Line data Source code
1 : #ifndef FD_LOG_STYLE
2 : #if FD_HAS_HOSTED
3 : #define FD_LOG_STYLE 0
4 : #else
5 : #error "Define FD_LOG_STYLE for this platform"
6 : #endif
7 : #endif
8 :
9 : #if FD_LOG_STYLE==0 /* POSIX style */
10 :
11 : #ifndef FD_HAS_BACKTRACE
12 : #if __has_include( <execinfo.h> )
13 : #define FD_HAS_BACKTRACE 1
14 : #else
15 : #define FD_HAS_BACKTRACE 0
16 : #endif
17 : #endif
18 :
19 : /* FIXME: SANITIZE VARIOUS USER SET STRINGS */
20 :
21 : #define _GNU_SOURCE
22 :
23 : #include "fd_log.h"
24 : #include "fd_backtrace.h"
25 :
26 : #include <stdio.h>
27 : #include <stdlib.h>
28 : #include <stdarg.h>
29 : #include <ctype.h>
30 : #include <errno.h>
31 : #include <fcntl.h>
32 : #include <unistd.h>
33 : #include <signal.h>
34 : #include <sched.h>
35 : #include <time.h>
36 : #if defined(__linux__)
37 : #include <syscall.h>
38 : #endif
39 : #include <sys/mman.h>
40 :
41 : #if FD_HAS_BACKTRACE
42 : #include <execinfo.h>
43 : #endif
44 :
45 : #if defined(__FreeBSD__)
46 : #include <sys/stat.h> /* S_IRUSR */
47 : #endif /* defined(__FreeBSD__) */
48 :
49 : #include "../tile/fd_tile_private.h"
50 :
51 : #ifdef __has_include
52 : #if __has_include("../../app/fdctl/version.h")
53 : #include "../../app/fdctl/version.h"
54 : #endif
55 : #endif
56 :
57 : #ifndef FDCTL_MAJOR_VERSION
58 : #define FDCTL_MAJOR_VERSION 0
59 : #endif
60 : #ifndef FDCTL_MINOR_VERSION
61 : #define FDCTL_MINOR_VERSION 0
62 : #endif
63 : #ifndef FDCTL_PATCH_VERSION
64 : #define FDCTL_PATCH_VERSION 0
65 : #endif
66 :
67 : #ifdef FD_BUILD_INFO
68 : FD_IMPORT_CSTR( fd_log_build_info, FD_BUILD_INFO );
69 : #else
70 : char const fd_log_build_info[1] __attribute__((aligned(1))) = { '\0' };
71 : ulong const fd_log_build_info_sz = 1UL;
72 : #endif
73 :
74 : /* TEXT_* are quick-and-dirty color terminal hacks. Probably should
75 : do something more robust longer term. */
76 :
77 80592 : #define TEXT_NORMAL "\033[0m"
78 : #define TEXT_BOLD "\033[1m"
79 : #define TEXT_UNDERLINE "\033[4m"
80 : #define TEXT_BLINK "\033[5m"
81 :
82 10074 : #define TEXT_BLUE "\033[34m"
83 10074 : #define TEXT_GREEN "\033[32m"
84 10074 : #define TEXT_YELLOW "\033[93m"
85 40296 : #define TEXT_RED "\033[31m"
86 :
87 : /* APPLICATION LOGICAL ID APIS ****************************************/
88 :
89 : /* App id */
90 :
91 : static ulong fd_log_private_app_id; /* 0 outside boot/halt, init on boot */
92 :
93 2491 : void fd_log_private_app_id_set( ulong app_id ) { fd_log_private_app_id = app_id; }
94 :
95 18005054 : ulong fd_log_app_id( void ) { return fd_log_private_app_id; }
96 :
97 : /* App */
98 :
99 : static char fd_log_private_app[ FD_LOG_NAME_MAX ]; /* "" outside boot/halt, init on boot */
100 :
101 : void
102 2491 : fd_log_private_app_set( char const * app ) {
103 2491 : if( FD_UNLIKELY( !app ) ) app = "[app]";
104 2491 : if( FD_LIKELY( app!=fd_log_private_app ) )
105 2491 : fd_cstr_fini( fd_cstr_append_cstr_safe( fd_cstr_init( fd_log_private_app ), app, FD_LOG_NAME_MAX-1UL ) );
106 2491 : }
107 :
108 2394300 : char const * fd_log_app( void ) { return fd_log_private_app; }
109 :
110 : /* Thread ID */
111 :
112 : #if FD_HAS_THREADS
113 : static ulong fd_log_private_thread_id_ctr; /* 0 outside boot/halt, init on boot */
114 :
115 : static ulong
116 2527 : fd_log_private_thread_id_next( void ) {
117 2527 : return FD_ATOMIC_FETCH_AND_ADD( &fd_log_private_thread_id_ctr, 1UL );
118 2527 : }
119 : #endif
120 :
121 : static FD_TL ulong fd_log_private_thread_id; /* 0 at thread start */
122 : static FD_TL int fd_log_private_thread_id_init; /* 0 at thread start */
123 :
124 : void
125 2527 : fd_log_private_thread_id_set( ulong thread_id ) {
126 2527 : fd_log_private_thread_id = thread_id;
127 2527 : fd_log_private_thread_id_init = 1;
128 2527 : }
129 :
130 : ulong
131 36007608 : fd_log_thread_id( void ) {
132 36007608 : # if FD_HAS_THREADS
133 36007608 : if( FD_UNLIKELY( !fd_log_private_thread_id_init ) ) fd_log_private_thread_id_set( fd_log_private_thread_id_next() );
134 : # else
135 : FD_COMPILER_MFENCE(); /* Work around FD_FN_CONST */
136 : # endif
137 36007608 : return fd_log_private_thread_id;
138 36007608 : }
139 :
140 : /* Thread */
141 :
142 : /* Initialize name to a reasonable default thread description (FIXME:
143 : WEEN THIS OFF STDLIB) */
144 :
145 : static void
146 2536 : fd_log_private_thread_default( char * name ) { /* FD_LOG_NAME_MAX bytes */
147 2536 : sprintf( name, "%lu", fd_log_thread_id() );
148 2536 : }
149 :
150 : static FD_TL char fd_log_private_thread[ FD_LOG_NAME_MAX ]; /* "" at thread start */
151 : static FD_TL int fd_log_private_thread_init; /* 0 at thread start */
152 :
153 : void
154 2536 : fd_log_thread_set( char const * thread ) {
155 2536 : if( FD_UNLIKELY( !thread ) || FD_UNLIKELY( thread[0]=='\0') ) {
156 2536 : fd_log_private_thread_default( fd_log_private_thread );
157 2536 : fd_log_private_thread_init = 1;
158 2536 : } else if( FD_LIKELY( thread!=fd_log_private_thread ) ) {
159 0 : fd_cstr_fini( fd_cstr_append_cstr_safe( fd_cstr_init( fd_log_private_thread ), thread, FD_LOG_NAME_MAX-1UL ) );
160 0 : fd_log_private_thread_init = 1;
161 0 : }
162 2536 : }
163 :
164 : char const *
165 3555426 : fd_log_thread( void ) {
166 3555426 : if( FD_UNLIKELY( !fd_log_private_thread_init ) ) fd_log_thread_set( NULL );
167 3555426 : return fd_log_private_thread;
168 3555426 : }
169 :
170 : /* APPLICATION PHYSICAL ID APIS ***************************************/
171 :
172 : /* Host ID */
173 :
174 : static ulong fd_log_private_host_id; /* 0 outside boot/halt, initialized on boot */
175 :
176 2491 : void fd_log_private_host_id_set( ulong host_id ) { fd_log_private_host_id = host_id; }
177 :
178 5018 : ulong fd_log_host_id( void ) { return fd_log_private_host_id; }
179 :
180 : /* Host */
181 :
182 : static char fd_log_private_host[ FD_LOG_NAME_MAX ]; /* "" outside boot/halt, initialized on boot */
183 :
184 2394299 : char const * fd_log_host( void ) { return fd_log_private_host; }
185 :
186 : void
187 2491 : fd_log_private_host_set( char const * host ) {
188 2491 : if( FD_UNLIKELY( !host ) || FD_UNLIKELY( host[0]=='\0') ) host = "[host]";
189 2491 : if( FD_LIKELY( host!=fd_log_private_host ) )
190 2491 : fd_cstr_fini( fd_cstr_append_cstr_safe( fd_cstr_init( fd_log_private_host ), host, FD_LOG_NAME_MAX-1UL ) );
191 2491 : }
192 :
193 : /* CPU ID */
194 :
195 : /* First CPU scheduled to run on or ULONG_MAX on failure */
196 :
197 : ulong
198 2491 : fd_log_private_cpu_id_default( void ) {
199 2491 : FD_CPUSET_DECL( cpu_set );
200 2491 : if( FD_UNLIKELY( fd_cpuset_getaffinity( (pid_t)0, cpu_set ) ) ) return ULONG_MAX;
201 2491 : ulong idx = fd_cpuset_first( cpu_set );
202 2491 : idx = fd_ulong_if( idx<FD_TILE_MAX, idx, ULONG_MAX );
203 2491 : return idx;
204 2491 : }
205 :
206 : static FD_TL ulong fd_log_private_cpu_id; /* 0 at thread start */
207 : static FD_TL int fd_log_private_cpu_id_init; /* 0 at thread start */
208 :
209 : void
210 2500 : fd_log_private_cpu_id_set( ulong cpu_id ) {
211 2500 : fd_log_private_cpu_id = cpu_id;
212 2500 : fd_log_private_cpu_id_init = 1;
213 2500 : }
214 :
215 : ulong
216 18002560 : fd_log_cpu_id( void ) {
217 18002560 : if( FD_UNLIKELY( !fd_log_private_cpu_id_init ) ) fd_log_private_cpu_id_set( fd_log_private_cpu_id_default() );
218 18002560 : return fd_log_private_cpu_id;
219 18002560 : }
220 :
221 : /* CPU */
222 :
223 : /* Initialize name to a reasonable default CPU description (FIXME: WEEN
224 : THIS OFF STDLIB) */
225 :
226 : static void
227 2536 : fd_log_private_cpu_default( char * name ) { /* FD_LOG_NAME_MAX bytes */
228 2536 : FD_CPUSET_DECL( set );
229 :
230 2536 : int err = fd_cpuset_getaffinity( (pid_t)0, set );
231 2536 : if( FD_UNLIKELY( err ) ) { sprintf( name, "e%i", err ); return; }
232 :
233 2536 : ulong cnt = fd_cpuset_cnt( set );
234 2536 : if( FD_UNLIKELY( !((0UL<cnt) & (cnt<=FD_TILE_MAX)) ) ) { sprintf( name, "ec" ); return; }
235 :
236 2536 : ulong idx = fd_cpuset_first( set );
237 2536 : sprintf( name, (cnt>1) ? "f%lu" : "%lu", idx );
238 2536 : }
239 :
240 : static FD_TL char fd_log_private_cpu[ FD_LOG_NAME_MAX ]; /* "" at thread start */
241 : static FD_TL int fd_log_private_cpu_init; /* 0 at thread start */
242 :
243 : void
244 2536 : fd_log_cpu_set( char const * cpu ) {
245 2536 : if( FD_UNLIKELY( !cpu ) || FD_UNLIKELY( cpu[0]=='\0') ) {
246 2536 : fd_log_private_cpu_default( fd_log_private_cpu );
247 2536 : fd_log_private_cpu_init = 1;
248 2536 : } else if( FD_LIKELY( cpu!=fd_log_private_cpu ) ) {
249 0 : fd_cstr_fini( fd_cstr_append_cstr_safe( fd_cstr_init( fd_log_private_cpu ), cpu, FD_LOG_NAME_MAX-1UL ) );
250 0 : fd_log_private_cpu_init = 1;
251 0 : }
252 2536 : }
253 :
254 : char const *
255 3555426 : fd_log_cpu( void ) {
256 3555426 : if( FD_UNLIKELY( !fd_log_private_cpu_init ) ) fd_log_cpu_set( NULL );
257 3555426 : return fd_log_private_cpu;
258 3555426 : }
259 :
260 : /* THREAD GROUP ID APIS ***********************************************/
261 :
262 : /* Group id */
263 :
264 : static ulong fd_log_private_group_id; /* 0 outside boot/halt, init on boot */
265 :
266 2491 : void fd_log_private_group_id_set( ulong group_id ) { fd_log_private_group_id = group_id; }
267 :
268 313706214 : ulong fd_log_group_id( void ) { return fd_log_private_group_id; }
269 :
270 : /* Group */
271 :
272 : static char fd_log_private_group[ FD_LOG_NAME_MAX ]; /* "" outside boot/halt, init on boot */
273 :
274 2394298 : char const * fd_log_group( void ) { return fd_log_private_group; }
275 :
276 : void
277 2491 : fd_log_private_group_set( char const * group ) {
278 2491 : if( FD_UNLIKELY( !group ) || FD_UNLIKELY( group[0]=='\0') ) group = "[group]";
279 2491 : if( FD_LIKELY( group!=fd_log_private_group ) )
280 2491 : fd_cstr_fini( fd_cstr_append_cstr_safe( fd_cstr_init( fd_log_private_group ), group, FD_LOG_NAME_MAX-1UL ) );
281 2491 : }
282 :
283 : /* System TID or ULONG_MAX on failure */
284 :
285 : ulong
286 2527 : fd_log_private_tid_default( void ) {
287 2527 : # if defined(__linux__)
288 2527 : long tid = syscall( SYS_gettid );
289 : # else
290 : long tid = getpid();
291 : # endif
292 2527 : return fd_ulong_if( tid>0L, (ulong)tid, ULONG_MAX );
293 2527 : }
294 :
295 : static FD_TL ulong fd_log_private_tid; /* 0 at thread start */
296 : static FD_TL int fd_log_private_tid_init; /* 0 at thread start */
297 :
298 : void
299 2527 : fd_log_private_tid_set( ulong tid ) {
300 2527 : fd_log_private_tid = tid;
301 2527 : fd_log_private_tid_init = 1;
302 2527 : }
303 :
304 : ulong
305 3557881 : fd_log_tid( void ) {
306 3557881 : if( FD_UNLIKELY( !fd_log_private_tid_init ) ) fd_log_private_tid_set( fd_log_private_tid_default() );
307 3557881 : return fd_log_private_tid;
308 3557881 : }
309 :
310 : /* User id */
311 :
312 : static ulong
313 2491 : fd_log_private_user_id_default( void ) {
314 2491 : return (ulong)getuid(); /* POSIX spec seems ambiguous as to whether or not this is a signed type */
315 2491 : }
316 :
317 : static ulong fd_log_private_user_id; /* 0 outside boot/halt, init on boot */
318 : static int fd_log_private_user_id_init;
319 :
320 : void
321 2491 : fd_log_private_user_id_set( ulong user_id ) {
322 2491 : fd_log_private_user_id = user_id;
323 2491 : fd_log_private_user_id_init = 1;
324 2491 : }
325 :
326 : ulong
327 2527 : fd_log_user_id( void ) {
328 2527 : if( FD_UNLIKELY( !fd_log_private_user_id_init ) ) {
329 0 : fd_log_private_user_id = fd_log_private_user_id_default();
330 0 : fd_log_private_user_id_init = 1;
331 0 : }
332 2527 : return fd_log_private_user_id;
333 2527 : }
334 :
335 : /* User */
336 :
337 : static char fd_log_private_user[ FD_LOG_NAME_MAX ]; /* "" outside boot/halt, init on boot */
338 :
339 2394299 : char const * fd_log_user( void ) { return fd_log_private_user; }
340 :
341 : void
342 2491 : fd_log_private_user_set( char const * user ) {
343 2491 : if( FD_UNLIKELY( !user ) || FD_UNLIKELY( user[0]=='\0') ) user = "[user]";
344 2491 : if( FD_LIKELY( user!=fd_log_private_user ) )
345 2491 : fd_cstr_fini( fd_cstr_append_cstr_safe( fd_cstr_init( fd_log_private_user ), user, FD_LOG_NAME_MAX-1UL ) );
346 2491 : }
347 :
348 : int
349 0 : fd_log_group_id_query( ulong group_id ) {
350 0 : if( group_id==fd_log_group_id() ) return FD_LOG_GROUP_ID_QUERY_LIVE; /* Avoid O/S call for self queries */
351 0 : pid_t pid = (pid_t)group_id;
352 0 : if( FD_UNLIKELY( ((group_id!=(ulong)pid) | (pid<=(pid_t)0)) ) ) return FD_LOG_GROUP_ID_QUERY_INVAL;
353 0 : if( !kill( (pid_t)group_id, 0 ) ) return FD_LOG_GROUP_ID_QUERY_LIVE;
354 0 : if( FD_LIKELY( errno==ESRCH ) ) return FD_LOG_GROUP_ID_QUERY_DEAD;
355 0 : if( FD_LIKELY( errno==EPERM ) ) return FD_LOG_GROUP_ID_QUERY_PERM;
356 0 : return FD_LOG_GROUP_ID_QUERY_FAIL;
357 0 : }
358 :
359 : /* WALLCLOCK APIS *****************************************************/
360 :
361 : long
362 122887973 : fd_log_wallclock_host( void const * _ ) {
363 122887973 : (void)_;
364 122887973 : struct timespec ts[1];
365 122887973 : clock_gettime( CLOCK_REALTIME, ts );
366 122887973 : return ((long)1e9)*((long)ts->tv_sec) + (long)ts->tv_nsec;
367 122887973 : }
368 :
369 : static fd_clock_func_t fd_log_private_clock_func = fd_log_wallclock_host;
370 : static void const * fd_log_private_clock_args = NULL;
371 :
372 : long
373 121667176 : fd_log_wallclock( void ) {
374 121667176 : return fd_log_private_clock_func( fd_log_private_clock_args );
375 121667176 : }
376 :
377 : void
378 : fd_log_wallclock_set( fd_clock_func_t clock,
379 0 : void const * args ) {
380 0 : fd_log_private_clock_func = clock;
381 0 : fd_log_private_clock_args = args;
382 0 : }
383 :
384 : char *
385 : fd_log_wallclock_cstr( long now,
386 2398756 : char * buf ) {
387 2398756 : uint YYYY;
388 2398756 : uint MM;
389 2398756 : uint DD;
390 2398756 : uint hh;
391 2398756 : uint mm;
392 2398756 : ulong ns;
393 2398756 : int tz;
394 :
395 2398756 : static long const ns_per_m = 60000000000L;
396 2398756 : static long const ns_per_s = 1000000000L;
397 :
398 2398756 : static FD_TL long now_ref = 1262325600000000000L; /* 2010-01-01 00:00:00.000000000 GMT-06 */
399 2398756 : static FD_TL uint YYYY_ref = 2010U; /* Initialized to what now0 corresponds to */
400 2398756 : static FD_TL uint MM_ref = 1U; /* " */
401 2398756 : static FD_TL uint DD_ref = 1U; /* " */
402 2398756 : static FD_TL uint hh_ref = 0U; /* " */
403 2398756 : static FD_TL uint mm_ref = 0U; /* " */
404 2398756 : static FD_TL int tz_ref = -6; /* " */
405 :
406 2398756 : if( FD_LIKELY( (now_ref<=now) & (now<(now_ref+ns_per_m)) ) ) {
407 :
408 : /* now is near the reference timestamp so we reuse the reference
409 : calculation timestamp. */
410 :
411 2396236 : YYYY = YYYY_ref;
412 2396236 : MM = MM_ref;
413 2396236 : DD = DD_ref;
414 2396236 : hh = hh_ref;
415 2396236 : mm = mm_ref;
416 2396236 : ns = (ulong)(now - now_ref);
417 2396236 : tz = tz_ref;
418 :
419 2396236 : } else {
420 :
421 2520 : long _t = now / ns_per_s;
422 2520 : long _ns = now - ns_per_s*_t;
423 2520 : if( _ns<0L ) _ns += ns_per_s, _t--;
424 2520 : time_t t = (time_t)_t;
425 :
426 2520 : struct tm tm[1];
427 2520 : static FD_TL int localtime_broken = 0;
428 2520 : if( FD_UNLIKELY( !localtime_broken && !localtime_r( &t, tm ) ) ) localtime_broken = 1;
429 2520 : if( FD_UNLIKELY( localtime_broken ) ) { /* If localtime_r doesn't work, pretty print as a raw UNIX time */
430 : /* Note: These can all run in parallel */
431 0 : fd_cstr_append_fxp10_as_text( buf, ' ', fd_char_if( now<0L, '-', '\0' ), 9UL, fd_long_abs( now ), 29UL );
432 0 : fd_cstr_append_text ( buf+29, " s UNIX", 7UL );
433 0 : fd_cstr_append_char ( buf+36, '\0' );
434 0 : return buf;
435 0 : }
436 :
437 2520 : YYYY = (uint)(1900+tm->tm_year);
438 2520 : MM = (uint)( 1+tm->tm_mon );
439 2520 : DD = (uint)tm->tm_mday;
440 2520 : hh = (uint)tm->tm_hour;
441 2520 : mm = (uint)tm->tm_min;
442 2520 : ns = ((ulong)((uint)tm->tm_sec))*((ulong)ns_per_s) + ((ulong)_ns);
443 2520 : # if defined(__linux__)
444 2520 : tz = (int)(-timezone/3600L+(long)tm->tm_isdst);
445 : # else
446 : tz = 0;
447 : # endif
448 :
449 2520 : now_ref = now - (long)ns;
450 2520 : YYYY_ref = YYYY;
451 2520 : MM_ref = MM;
452 2520 : DD_ref = DD;
453 2520 : hh_ref = hh;
454 2520 : mm_ref = mm;
455 2520 : tz_ref = tz;
456 :
457 2520 : }
458 :
459 : /* Note: These can all run in parallel! */
460 2398756 : fd_cstr_append_uint_as_text ( buf, '0', '\0', YYYY, 4UL );
461 2398756 : fd_cstr_append_char ( buf+ 4, '-' );
462 2398756 : fd_cstr_append_uint_as_text ( buf+ 5, '0', '\0', MM, 2UL );
463 2398756 : fd_cstr_append_char ( buf+ 7, '-' );
464 2398756 : fd_cstr_append_uint_as_text ( buf+ 8, '0', '\0', DD, 2UL );
465 2398756 : fd_cstr_append_char ( buf+10, ' ' );
466 2398756 : fd_cstr_append_uint_as_text ( buf+11, '0', '\0', hh, 2UL );
467 2398756 : fd_cstr_append_char ( buf+13, ':' );
468 2398756 : fd_cstr_append_uint_as_text ( buf+14, '0', '\0', mm, 2UL );
469 2398756 : fd_cstr_append_char ( buf+16, ':' );
470 2398756 : fd_cstr_append_fxp10_as_text( buf+17, '0', '\0', 9UL, ns, 12UL );
471 2398756 : fd_cstr_append_text ( buf+29, " GMT", 4UL );
472 2398756 : fd_cstr_append_char ( buf+33, fd_char_if( tz<0, '-', '+' ) );
473 2398756 : fd_cstr_append_uint_as_text ( buf+34, '0', '\0', fd_int_abs( tz ), 2UL );
474 2398756 : fd_cstr_append_char ( buf+36, '\0' );
475 2398756 : return buf;
476 2398756 : }
477 :
478 : long
479 606 : fd_log_sleep( long dt ) {
480 606 : if( FD_UNLIKELY( dt < 1L ) ) {
481 0 : sched_yield();
482 0 : return 0L;
483 0 : }
484 :
485 : /* dt is in [1,LONG_MAX] at this point */
486 606 : long ns_dt = fd_long_min( dt, (((long)1e9)<<31)-1L ); /* in [1,2^31*1e9) and <= dt at this point */
487 606 : dt -= ns_dt;
488 :
489 606 : struct timespec req[1];
490 606 : struct timespec rem[1];
491 606 : req->tv_sec = (time_t)( ((ulong)ns_dt) / ((ulong)1e9) ); /* in [0,2^31-1] */
492 606 : req->tv_nsec = (long) ( ((ulong)ns_dt) % ((ulong)1e9) ); /* in [0,1e9) */
493 606 : int sleep_res;
494 606 : #if defined(__linux__)
495 : /* Always use clock_nanosleep on Linux to be predictable */
496 606 : sleep_res = clock_nanosleep( CLOCK_REALTIME, 0, req, rem );
497 : #else
498 : sleep_res = nanosleep( req, rem );
499 : #endif
500 606 : if( FD_UNLIKELY( sleep_res ) && FD_LIKELY( errno==EINTR ) ) dt += ((long)1e9)*((long)rem->tv_sec) + rem->tv_nsec;
501 606 : return dt;
502 606 : }
503 :
504 : long
505 3 : fd_log_wait_until( long then ) {
506 3 : long now;
507 3 : for(;;) {
508 3 : now = fd_log_wallclock();
509 3 : long rem = then - now;
510 3 : if( FD_LIKELY( rem<=0L ) ) break; /* we've waited long enough */
511 0 : if( FD_UNLIKELY( rem>(long)1e9 ) ) { /* long wait (over ~1 s) ... sleep until medium long */
512 0 : fd_log_sleep( rem-(long)0.1e9 );
513 0 : continue;
514 0 : }
515 0 : if( FD_UNLIKELY( rem>(long)0.1e9 ) ) { /* medium long wait (over ~0.1 s) ... yield */
516 0 : FD_YIELD();
517 0 : continue;
518 0 : }
519 0 : if( FD_UNLIKELY( rem>(long)1e3 ) ) { /* medium short wait (over ~1 us) ... hyperthreading friendly spin */
520 0 : FD_SPIN_PAUSE();
521 0 : continue;
522 0 : }
523 : /* short wait ... spin on fd_log_wallclock */
524 0 : }
525 3 : return now;
526 3 : }
527 :
528 : /* LOG APIS ***********************************************************/
529 :
530 : char fd_log_private_path[ 1024 ]; /* "" outside boot/halt, init at boot */
531 : static int fd_log_private_fileno = -1; /* -1 outside boot/halt, init at boot */
532 : static int fd_log_private_dedup; /* 0 outside boot/halt, init at boot */
533 :
534 : void
535 4443 : fd_log_flush( void ) {
536 4443 : int log_fileno = FD_VOLATILE_CONST( fd_log_private_fileno );
537 4443 : if( FD_LIKELY( log_fileno!=-1 ) ) fsync( log_fileno );
538 4443 : }
539 :
540 : static int fd_log_private_colorize; /* 0 outside boot/halt, init at boot */
541 : static int fd_log_private_level_logfile; /* 0 outside boot/halt, init at boot */
542 : static int fd_log_private_level_stderr; /* 0 outside boot/halt, init at boot */
543 : static int fd_log_private_level_flush; /* 0 outside boot/halt, init at boot */
544 : static int fd_log_private_level_core; /* 0 outside boot/halt, init at boot */
545 : static int fd_log_private_unclean_exit;
546 : static int fd_log_private_signal_handler;
547 :
548 2491 : int fd_log_colorize ( void ) { return FD_VOLATILE_CONST( fd_log_private_colorize ); }
549 3689943 : int fd_log_level_logfile( void ) { return FD_VOLATILE_CONST( fd_log_private_level_logfile ); }
550 3555819 : int fd_log_level_stderr ( void ) { return FD_VOLATILE_CONST( fd_log_private_level_stderr ); }
551 2400768 : int fd_log_level_flush ( void ) { return FD_VOLATILE_CONST( fd_log_private_level_flush ); }
552 4741 : int fd_log_level_core ( void ) { return FD_VOLATILE_CONST( fd_log_private_level_core ); }
553 :
554 2491 : void fd_log_colorize_set ( int mode ) { FD_VOLATILE( fd_log_private_colorize ) = mode; }
555 2500 : void fd_log_level_logfile_set( int level ) { FD_VOLATILE( fd_log_private_level_logfile ) = level; }
556 2503 : void fd_log_level_stderr_set ( int level ) { FD_VOLATILE( fd_log_private_level_stderr ) = level; }
557 2491 : void fd_log_level_flush_set ( int level ) { FD_VOLATILE( fd_log_private_level_flush ) = level; }
558 2503 : void fd_log_level_core_set ( int level ) { FD_VOLATILE( fd_log_private_level_core ) = level; }
559 :
560 12 : int fd_log_private_logfile_fd( void ) { return FD_VOLATILE_CONST( fd_log_private_fileno ); }
561 :
562 0 : void fd_log_enable_signal_handler( void ) { fd_log_private_signal_handler = 1; }
563 0 : void fd_log_enable_unclean_exit( void ) { fd_log_private_unclean_exit = 1; }
564 :
565 : /* Buffer size used for vsnprintf calls (this is also one more than the
566 : maximum size that this can passed to fd_io_write) */
567 :
568 12175442 : #define FD_LOG_BUF_SZ (32UL*4096UL)
569 :
570 : /* Lock to used by fd_log_private_fprintf_0 to sequence calls writes
571 : between different _processes_ that share the same fd. */
572 :
573 : static int fd_log_private_shared_lock_local[1] __attribute__((aligned(128))); /* location of lock if boot mmap fails */
574 : int * fd_log_private_shared_lock = fd_log_private_shared_lock_local; /* Local lock outside boot/halt, init at boot */
575 :
576 : /* File descriptor to restore when logging a message that will terminate
577 : the application, incase it was redirected to some other consumer in
578 : the process which will not be able to process it in time */
579 : static int fd_log_private_stderr_fileno = STDERR_FILENO;
580 : int fd_log_private_restore_stderr = STDERR_FILENO;
581 :
582 : void
583 : fd_log_private_fprintf_0( int fd,
584 2407042 : char const * fmt, ... ) {
585 :
586 : /* Note: while this function superficially looks vdprintf-ish, we don't
587 : use that as it can do all sorts of unpleasantness under the hood
588 : (fflush, mutex / futex on fd, non-AS-safe buffering, ...) that this
589 : function deliberately avoids. Also, the function uses the shared
590 : lock to help keep messages generated from processes that share the
591 : same log fd sane. */
592 :
593 : /* TODO:
594 : - Consider moving to util/io as fd_io_printf or renaming to
595 : fd_log_printf?
596 : - Is msg better to have on stack or in thread local storage?
597 : - Is msg even necessary given shared lock? (probably still useful to
598 : keep the message write to be a single-system-call best effort)
599 : - Allow partial write to fd_io_write? (e.g. src_min=0 such that
600 : the fd_io_write below is guaranteed to be a single system call) */
601 :
602 2407042 : char msg[ FD_LOG_BUF_SZ ];
603 :
604 2407042 : va_list ap;
605 2407042 : va_start( ap, fmt );
606 2407042 : int len = vsnprintf( msg, FD_LOG_BUF_SZ, fmt, ap );
607 2407042 : if( len<0 ) len = 0; /* cmov */
608 2407042 : if( len>(int)(FD_LOG_BUF_SZ-1UL) ) len = (int)(FD_LOG_BUF_SZ-1UL); /* cmov */
609 2407042 : msg[ len ] = '\0';
610 2407042 : va_end( ap );
611 :
612 2407042 : # if FD_HAS_ATOMIC
613 2407042 : FD_COMPILER_MFENCE();
614 2409262 : while(( FD_LIKELY( FD_ATOMIC_CAS( fd_log_private_shared_lock, 0, 1 ) ) )) ;
615 2407042 : FD_COMPILER_MFENCE();
616 2407042 : # endif
617 :
618 2407042 : ulong wsz;
619 2407042 : fd_io_write( fd, msg, (ulong)len, (ulong)len, &wsz ); /* Note: we ignore errors because what are we doing to do? log them? */
620 :
621 2407042 : # if FD_HAS_ATOMIC
622 2407042 : FD_COMPILER_MFENCE();
623 2407042 : FD_VOLATILE( *fd_log_private_shared_lock ) = 0;
624 2407042 : FD_COMPILER_MFENCE();
625 2407042 : # endif
626 :
627 2407042 : }
628 :
629 : /* This is the same as fd_log_private_fprintf_0 except that it does not try to
630 : take a lock when writing to the log file. This should almost never be used
631 : except in exceptional cases when logging while the process is shutting down.
632 :
633 : It exists because if a child process dies while holding the lock, we may
634 : want to log some diagnostic messages when tearing down the process tree. */
635 : void
636 : fd_log_private_fprintf_nolock_0( int fd,
637 0 : char const * fmt, ... ) {
638 :
639 : /* Note: while this function superficially looks vdprintf-ish, we don't
640 : use that as it can do all sorts of unpleasantness under the hood
641 : (fflush, mutex / futex on fd, non-AS-safe buffering, ...) that this
642 : function deliberately avoids. Also, the function uses the shared
643 : lock to help keep messages generated from processes that share the
644 : same log fd sane. */
645 :
646 : /* TODO:
647 : - Consider moving to util/io as fd_io_printf or renaming to
648 : fd_log_printf?
649 : - Is msg better to have on stack or in thread local storage?
650 : - Is msg even necessary given shared lock? (probably still useful to
651 : keep the message write to be a single-system-call best effort)
652 : - Allow partial write to fd_io_write? (e.g. src_min=0 such that
653 : the fd_io_write below is guaranteed to be a single system call) */
654 :
655 0 : char msg[ FD_LOG_BUF_SZ ];
656 :
657 0 : va_list ap;
658 0 : va_start( ap, fmt );
659 0 : int len = vsnprintf( msg, FD_LOG_BUF_SZ, fmt, ap );
660 0 : if( len<0 ) len = 0; /* cmov */
661 0 : if( len>(int)(FD_LOG_BUF_SZ-1UL) ) len = (int)(FD_LOG_BUF_SZ-1UL); /* cmov */
662 0 : msg[ len ] = '\0';
663 0 : va_end( ap );
664 :
665 0 : ulong wsz;
666 0 : fd_io_write( fd, msg, (ulong)len, (ulong)len, &wsz ); /* Note: we ignore errors because what are we doing to do? log them? */
667 0 : }
668 :
669 : /* Log buffer used by fd_log_private_0 and fd_log_private_hexdump_msg */
670 :
671 : static FD_TL char fd_log_private_log_msg[ FD_LOG_BUF_SZ ];
672 :
673 : char const *
674 3680679 : fd_log_private_0( char const * fmt, ... ) {
675 3680679 : va_list ap;
676 3680679 : va_start( ap, fmt );
677 3680679 : int len = vsnprintf( fd_log_private_log_msg, FD_LOG_BUF_SZ, fmt, ap );
678 3680679 : if( len<0 ) len = 0; /* cmov */
679 3680679 : if( len>(int)(FD_LOG_BUF_SZ-1UL) ) len = (int)(FD_LOG_BUF_SZ-1UL); /* cmov */
680 3680679 : fd_log_private_log_msg[ len ] = '\0';
681 3680679 : va_end( ap );
682 3680679 : return fd_log_private_log_msg;
683 3680679 : }
684 :
685 : char const *
686 : fd_log_private_hexdump_msg( char const * descr,
687 : void const * mem,
688 6300 : ulong sz ) {
689 :
690 3159756 : # define FD_LOG_HEXDUMP_BYTES_PER_LINE (16UL)
691 6300 : # define FD_LOG_HEXDUMP_BLOB_DESCRIPTION_MAX_LEN (32UL)
692 6300 : # define FD_LOG_HEXDUMP_MAX_INPUT_BLOB_SZ (1664UL) /* multiple of 128 >= 1542 */
693 :
694 3560238 : # define FD_LOG_HEXDUMP_ADD_TO_LOG_BUF(...) do { log_buf_ptr += fd_int_max( sprintf( log_buf_ptr, __VA_ARGS__ ), 0 ); } while(0)
695 6300 : char * log_buf_ptr = fd_log_private_log_msg; /* used by FD_LOG_HEXDUMP_ADD_TO_LOG_BUF macro */
696 :
697 : /* Print the hexdump header */
698 : /* FIXME: consider additional sanitization of descr or using compiler
699 : tricks to prevent user from passing a non-const-char string (i.e.
700 : data they got from somewhere else that might not be sanitized). */
701 :
702 6300 : if( FD_UNLIKELY( !descr ) ) {
703 :
704 0 : FD_LOG_HEXDUMP_ADD_TO_LOG_BUF( "HEXDUMP - (%lu bytes at 0x%lx)", sz, (ulong)mem );
705 :
706 6300 : } else if( FD_UNLIKELY( strlen( descr )>FD_LOG_HEXDUMP_BLOB_DESCRIPTION_MAX_LEN ) ) {
707 :
708 3 : char tmp[ FD_LOG_HEXDUMP_BLOB_DESCRIPTION_MAX_LEN + 1UL ];
709 3 : fd_cstr_fini( fd_cstr_append_text( fd_cstr_init( tmp ), descr, FD_LOG_HEXDUMP_BLOB_DESCRIPTION_MAX_LEN ) );
710 3 : FD_LOG_HEXDUMP_ADD_TO_LOG_BUF( "HEXDUMP \"%s\"... (%lu bytes at 0x%lx)", tmp, sz, (ulong)mem );
711 :
712 6297 : } else {
713 :
714 6297 : FD_LOG_HEXDUMP_ADD_TO_LOG_BUF( "HEXDUMP \"%s\" (%lu bytes at 0x%lx)", descr, sz, (ulong)mem );
715 :
716 6297 : }
717 :
718 6300 : if( FD_UNLIKELY( !sz ) ) return fd_log_private_log_msg;
719 :
720 6300 : FD_LOG_HEXDUMP_ADD_TO_LOG_BUF( "\n" );
721 :
722 6300 : if( FD_UNLIKELY( !mem ) ) {
723 0 : FD_LOG_HEXDUMP_ADD_TO_LOG_BUF( "\t... snip (unreadable memory) ..." );
724 0 : return fd_log_private_log_msg;
725 0 : }
726 :
727 6300 : char line_buf[ FD_LOG_HEXDUMP_BYTES_PER_LINE+1 ];
728 6300 : char const * blob = (char const *)mem;
729 6300 : ulong blob_off = 0UL;
730 6300 : ulong blob_sz = fd_ulong_min( sz, FD_LOG_HEXDUMP_MAX_INPUT_BLOB_SZ );
731 :
732 3158370 : for( ; blob_off<blob_sz; blob_off++ ) {
733 3152070 : ulong col_idx = blob_off % FD_LOG_HEXDUMP_BYTES_PER_LINE;
734 :
735 : /* New line. Print previous line's ASCII representation and then print the offset. */
736 3152070 : if( FD_UNLIKELY( !col_idx ) ) {
737 197091 : if( FD_LIKELY( blob_off ) ) FD_LOG_HEXDUMP_ADD_TO_LOG_BUF( " %s\n", line_buf );
738 197091 : FD_LOG_HEXDUMP_ADD_TO_LOG_BUF( "\t%04lx: ", blob_off );
739 197091 : }
740 : /* FIXME: consider extra space between col 7 and 8 to make easier
741 : for visual inspection */
742 :
743 3152070 : char c = blob[blob_off];
744 3152070 : FD_LOG_HEXDUMP_ADD_TO_LOG_BUF( " %02x", (uint)(uchar)c );
745 :
746 : /* If not a printable ASCII character, output a dot. */
747 3152070 : line_buf[ col_idx ] = fd_char_if( fd_isalnum( (int)c ) | fd_ispunct( (int)c ) | (c==' '), c, '.' );
748 3152070 : line_buf[ col_idx+1UL ] = '\0';
749 3152070 : }
750 :
751 : /* Print the 2nd column of last blob line */
752 7686 : while( blob_off % FD_LOG_HEXDUMP_BYTES_PER_LINE ) {
753 1386 : FD_LOG_HEXDUMP_ADD_TO_LOG_BUF( " " );
754 1386 : blob_off++;
755 1386 : }
756 6300 : FD_LOG_HEXDUMP_ADD_TO_LOG_BUF( " %s", line_buf );
757 :
758 6300 : if( FD_UNLIKELY( blob_sz < sz ) )
759 0 : FD_LOG_HEXDUMP_ADD_TO_LOG_BUF( "\n\t... snip (printed %lu bytes, omitted %lu bytes) ...", blob_sz, sz-blob_sz );
760 :
761 6300 : return fd_log_private_log_msg;
762 :
763 6300 : # undef FD_LOG_HEXDUMP_BYTES_PER_LINE
764 6300 : # undef FD_LOG_HEXDUMP_BLOB_DESCRIPTION_MAX_LEN
765 6300 : # undef FD_LOG_HEXDUMP_MAX_INPUT_BLOB_SZ
766 6300 : # undef FD_LOG_HEXDUMP_ADD_TO_LOG_BUF
767 6300 : }
768 :
769 : void
770 : fd_log_private_1( int level,
771 : long now,
772 : char const * file,
773 : int line,
774 : char const * func,
775 3686987 : char const * msg ) {
776 :
777 3686987 : if( level<fd_log_level_logfile() ) return;
778 :
779 : /* These are thread init so we call them regardless of permanent log
780 : enabled to their initialization time is guaranteed independent of
781 : whether the permanent log is enabled. */
782 :
783 3552863 : char const * thread = fd_log_thread();
784 3552863 : char const * cpu = fd_log_cpu();
785 3552863 : ulong tid = fd_log_tid();
786 :
787 3552863 : int log_fileno = FD_VOLATILE_CONST( fd_log_private_fileno );
788 3552863 : int to_logfile = (log_fileno!=-1);
789 3552863 : int to_stderr = (level>=fd_log_level_stderr());
790 3552863 : if( !(to_logfile | to_stderr) ) return;
791 :
792 : /* Deduplicate the log if requested */
793 :
794 3487610 : if( fd_log_private_dedup ) {
795 :
796 : /* Compute if this message appears to be a recent duplicate of
797 : a previous log message */
798 :
799 3487608 : ulong hash = fd_cstr_hash_append( fd_cstr_hash_append( fd_cstr_hash_append( fd_ulong_hash(
800 3487608 : (ulong)(8L*(long)line+(long)level) ), file ), func ), msg );
801 :
802 3487608 : static long const dedup_interval = 20000000L; /* 1/50 s */
803 :
804 3487608 : static FD_TL int init; /* 0 on thread start */
805 3487608 : static FD_TL ulong last_hash; /* 0UL on thread start */
806 3487608 : static FD_TL long then; /* 0L on thread start */
807 :
808 3487608 : int is_dup = init & (hash==last_hash) & ((now-then)<dedup_interval);
809 3487608 : init = 1;
810 :
811 : /* Update how many messages from this thread in row have been
812 : duplicates */
813 :
814 3487608 : static FD_TL ulong dedup_cnt; /* 0UL on thread start */
815 3487608 : static FD_TL int in_dedup; /* 0 on thread start */
816 :
817 3487608 : if( is_dup ) dedup_cnt++;
818 2397529 : else {
819 2397529 : if( in_dedup ) {
820 :
821 : /* This message appears to end a long string of duplicates.
822 : Log the end of the deduplication. */
823 :
824 284 : char then_cstr[ FD_LOG_WALLCLOCK_CSTR_BUF_SZ ];
825 284 : fd_log_wallclock_cstr( then, then_cstr );
826 :
827 284 : if( to_logfile )
828 284 : fd_log_private_fprintf_0( log_fileno, "SNIP %s %6lu:%-6lu %s:%s:%-4s %s:%s:%-4s "
829 284 : "stopped repeating (%lu identical messages)\n",
830 284 : then_cstr, fd_log_group_id(),tid, fd_log_user(),fd_log_host(),cpu,
831 284 : fd_log_app(),fd_log_group(),thread, dedup_cnt+1UL );
832 :
833 284 : if( to_stderr ) {
834 216 : char * then_short_cstr = then_cstr+5; then_short_cstr[21] = '\0'; /* Lop off the year, ns resolution and timezone */
835 216 : fd_log_private_fprintf_0( fd_log_private_stderr_fileno, "SNIP %s %-6lu %-4s %-4s stopped repeating (%lu identical messages)\n",
836 216 : then_short_cstr, tid,cpu,thread, dedup_cnt+1UL );
837 216 : }
838 :
839 284 : in_dedup = 0;
840 284 : }
841 :
842 2397529 : dedup_cnt = 0UL;
843 2397529 : }
844 :
845 : /* dedup_cnt previous messages from this thread appear to be
846 : duplicates. Decide whether to let the raw message print or
847 : deduplicate to the log. FIXME: CONSIDER RANDOMIZING THE
848 : THROTTLE. */
849 :
850 3487608 : static ulong const dedup_thresh = 3UL; /* let initial dedup_thresh duplicates go out the door */
851 3487608 : static long const dedup_throttle = 1000000000L; /* ~1s, how often to update status on current duplication */
852 :
853 3487608 : static FD_TL long dedup_last; /* 0L on thread start */
854 :
855 3487608 : if( dedup_cnt < dedup_thresh ) dedup_last = now;
856 1089341 : else {
857 1089341 : if( (now-dedup_last) >= dedup_throttle ) {
858 36 : char now_cstr[ FD_LOG_WALLCLOCK_CSTR_BUF_SZ ];
859 36 : fd_log_wallclock_cstr( now, now_cstr );
860 36 : if( to_logfile )
861 36 : fd_log_private_fprintf_0( log_fileno, "SNIP %s %6lu:%-6lu %s:%s:%-4s %s:%s:%-4s repeating (%lu identical messages)\n",
862 36 : now_cstr, fd_log_group_id(),tid, fd_log_user(),fd_log_host(),cpu,
863 36 : fd_log_app(),fd_log_group(),thread, dedup_cnt+1UL );
864 36 : if( to_stderr ) {
865 36 : char * now_short_cstr = now_cstr+5; now_short_cstr[21] = '\0'; /* Lop off the year, ns resolution and timezone */
866 36 : fd_log_private_fprintf_0( fd_log_private_stderr_fileno, "SNIP %s %-6lu %-4s %-4s repeating (%lu identical messages)\n",
867 36 : now_short_cstr, tid,cpu,thread, dedup_cnt+1UL );
868 36 : }
869 36 : dedup_last = now;
870 36 : }
871 1089341 : in_dedup = 1;
872 1089341 : }
873 :
874 3487608 : last_hash = hash;
875 3487608 : then = now;
876 :
877 3487608 : if( in_dedup ) return;
878 3487608 : }
879 :
880 2398277 : char now_cstr[ FD_LOG_WALLCLOCK_CSTR_BUF_SZ ];
881 2398277 : fd_log_wallclock_cstr( now, now_cstr );
882 :
883 2398277 : static char const * level_cstr[] = {
884 2398277 : /* 0 */ "DEBUG ",
885 2398277 : /* 1 */ "INFO ",
886 2398277 : /* 2 */ "NOTICE ",
887 2398277 : /* 3 */ "WARNING",
888 2398277 : /* 4 */ "ERR ",
889 2398277 : /* 5 */ "CRIT ",
890 2398277 : /* 6 */ "ALERT ",
891 2398277 : /* 7 */ "EMERG "
892 2398277 : };
893 :
894 2398277 : if( to_logfile )
895 2391417 : fd_log_private_fprintf_0( log_fileno, "%s %s %6lu:%-6lu %s:%s:%-4s %s:%s:%-4s %s(%i)[%s]: %s\n",
896 2391417 : level_cstr[level], now_cstr, fd_log_group_id(),tid, fd_log_user(),fd_log_host(),cpu,
897 2391417 : fd_log_app(),fd_log_group(),thread, file,line,func, msg );
898 :
899 2398277 : if( to_stderr ) {
900 10074 : static char const * color_level_cstr[] = {
901 10074 : /* 0 */ TEXT_NORMAL "DEBUG ",
902 10074 : /* 1 */ TEXT_BLUE "INFO " TEXT_NORMAL,
903 10074 : /* 2 */ TEXT_GREEN "NOTICE " TEXT_NORMAL,
904 10074 : /* 3 */ TEXT_YELLOW "WARNING" TEXT_NORMAL,
905 10074 : /* 4 */ TEXT_RED "ERR " TEXT_NORMAL,
906 10074 : /* 5 */ TEXT_RED TEXT_BOLD "CRIT " TEXT_NORMAL,
907 10074 : /* 6 */ TEXT_RED TEXT_BOLD TEXT_UNDERLINE "ALERT " TEXT_NORMAL,
908 10074 : /* 7 */ TEXT_RED TEXT_BOLD TEXT_UNDERLINE TEXT_BLINK "EMERG " TEXT_NORMAL
909 10074 : };
910 10074 : char * now_short_cstr = now_cstr+5; now_short_cstr[21] = '\0'; /* Lop off the year, ns resolution and timezone */
911 10074 : fd_log_private_fprintf_0( fd_log_private_stderr_fileno, "%s %s %-6lu %-4s %-4s %s(%i): %s\n",
912 10074 : fd_log_private_colorize ? color_level_cstr[level] : level_cstr[level],
913 10074 : now_short_cstr, tid,cpu,thread, file, line, msg );
914 10074 : }
915 :
916 2398277 : if( level<fd_log_level_flush() ) return;
917 :
918 4410 : fd_log_flush();
919 4410 : }
920 :
921 : void
922 : fd_log_private_2( int level,
923 : long now,
924 : char const * file,
925 : int line,
926 : char const * func,
927 1125 : char const * msg ) {
928 1125 : if( level<fd_log_level_core() && fd_log_private_restore_stderr!=-1 ) {
929 : /* Restore stderr to original fd in case it was redirected to
930 : something that won't be able to process the fatal message */
931 :
932 1125 : fd_log_private_stderr_fileno = fd_log_private_restore_stderr;
933 1125 : fd_log_private_restore_stderr = -1;
934 :
935 1125 : }
936 :
937 1125 : fd_log_private_1( level, now, file, line, func, msg );
938 :
939 1125 : if( level<fd_log_level_core() ) {
940 1125 : # if defined(__linux__)
941 1125 : if( fd_log_private_unclean_exit ) {
942 0 : syscall( SYS_exit_group, 1 );
943 0 : }
944 1125 : # endif /* defined(__linux__) */
945 1125 : exit(1); /* atexit will call fd_log_private_cleanup implicitly */
946 1125 : }
947 :
948 0 : abort();
949 1125 : }
950 :
951 : void
952 : fd_log_private_raw_2( char const * file,
953 : int line,
954 : char const * func,
955 0 : char const * msg ) {
956 0 : fd_log_private_fprintf_nolock_0( fd_log_private_stderr_fileno, "%s(%i)[%s]: %s\n", file, line, func, msg );
957 0 : # if defined(__linux__)
958 0 : syscall( SYS_exit_group, 1 );
959 : # else
960 : exit(1);
961 : # endif
962 0 : abort();
963 0 : }
964 :
965 : /* BOOT/HALT APIS *****************************************************/
966 :
967 : static void
968 3830 : fd_log_private_cleanup( void ) {
969 :
970 : /* The atexit below means that all calls to "exit();" implicitly
971 : become "fd_log_private_cleanup(); exit();". It also implies that
972 : programs that terminate via a top level return from main implicitly
973 : call fd_log_private_cleanup().
974 :
975 : As such it is possible that a thread other than the booter will
976 : trigger cleanup either by triggering this directly (e.g. calling
977 : exit) or indirectly (e.g. by logging a message with an exit
978 : triggering priority) and that the booter itself might call this
979 : more than once sequentially (e.g. fd_halt() calling cleanup
980 : explicitly followed by return from main triggering it again.
981 :
982 : Accordingly we protect this with a ONCE block so it only will
983 : execute once per program. Further, if cleanup gets triggered by
984 : multiple threads concurrently, the ONCE block will prevent them
985 : from progressing until the first thread that hits the once block
986 : has completed cleanup. */
987 :
988 12642 : FD_ONCE_BEGIN {
989 2491 : int log_fileno = FD_VOLATILE_CONST( fd_log_private_fileno );
990 2491 : if( log_fileno==-1 ) fd_log_private_fprintf_0( STDERR_FILENO, "No log\n" );
991 667 : else if( !strcmp( fd_log_private_path, "-" ) ) fd_log_private_fprintf_0( STDERR_FILENO, "Log to stdout\n" );
992 655 : else {
993 655 : # if FD_HAS_THREADS
994 655 : if( fd_log_private_thread_id_ctr>1UL ) { /* There are potentially other log users running */
995 : /* Just closing the permanent log file is not multithreading
996 : safe in the case where other threads are still running
997 : normally and thus potentially logging to the permanent log.
998 : Such should not happen in a correctly written and functioning
999 : application but logging exists in large part to help
1000 : understand when applications misbehave. So we try to be as
1001 : robust and informative as we can here. FIXME: THE SECOND
1002 : USLEEP IS AN UGLY HACK TO REDUCE (BUT NOT FULLY ELIMINATE)
1003 : THE RISK OF USE AFTER CLOSE BY THOSE OTHER THREADS. IT IS
1004 : POSSIBLE WITH A MORE INVASIVE CHANGES TO FULLY ELIMINATE THIS
1005 : RISK. */
1006 0 : usleep( (useconds_t)40000 ); /* Give potentially concurrent users a chance to get their dying messages out */
1007 0 : FD_COMPILER_MFENCE();
1008 0 : FD_VOLATILE( fd_log_private_fileno ) = -1; /* Turn off the permanent log for concurrent users */
1009 0 : FD_COMPILER_MFENCE();
1010 0 : usleep( (useconds_t)40000 ); /* Give any concurrent log operations progress at turn off a chance to wrap */
1011 0 : }
1012 : # else
1013 : FD_VOLATILE( fd_log_private_fileno ) = -1;
1014 : # endif
1015 :
1016 655 : fsync( log_fileno );
1017 655 : sync();
1018 655 : fd_log_private_fprintf_0( STDERR_FILENO, "Log at \"%s\"\n", fd_log_private_path );
1019 655 : }
1020 2491 : } FD_ONCE_END;
1021 3830 : }
1022 :
1023 : static void
1024 : fd_log_private_sig_abort( int sig,
1025 : siginfo_t * info,
1026 0 : void * context ) {
1027 0 : (void)sig; (void)info; (void)context;
1028 :
1029 : /* Thread could have caught signal while holding a lock.
1030 : Hack around this re-entrancy problem by pointing the log lock to
1031 : a dummy buffer. */
1032 0 : int lock = 0;
1033 0 : fd_log_private_shared_lock = &lock;
1034 :
1035 0 : #define FD_LOG_ERR_NOEXIT(a) do { long _fd_log_msg_now = fd_log_wallclock(); fd_log_private_1( 4, _fd_log_msg_now, __FILE__, __LINE__, __func__, fd_log_private_0 a ); } while(0)
1036 0 : FD_LOG_ERR_NOEXIT(( "Received signal %s", fd_io_strsignal( sig ) ));
1037 0 : #undef FD_LOG_ERR_NOEXIT
1038 :
1039 0 : # if FD_HAS_BACKTRACE
1040 :
1041 0 : void * btrace[ 128UL ];
1042 0 : int btrace_cnt = backtrace( btrace, 128 );
1043 :
1044 0 : fd_backtrace_log( btrace, (ulong)btrace_cnt );
1045 :
1046 0 : # endif
1047 :
1048 : /* Returning is going to cause SIGSYS since it's probably not allowed
1049 : in the sandbox, which is OK. The parent process will terminate
1050 : everything anyway. If we allow rt_sigreturn to be called in the
1051 : sandbox, then we will get a correct signal. */
1052 0 : return;
1053 0 : }
1054 :
1055 : static void
1056 44568 : fd_log_private_sig_trap( int sig ) {
1057 44568 : struct sigaction act[1];
1058 : /* FIXME: CONSIDER NOT OVERRIDING IF THE SIGNAL HANDLER HAS ALREADY
1059 : BEEN SET BY THE USER. */
1060 44568 : act->sa_sigaction = fd_log_private_sig_abort;
1061 44568 : if( sigemptyset( &act->sa_mask ) ) FD_LOG_ERR(( "sigempty set failed" ));
1062 44568 : act->sa_flags = (int)(SA_SIGINFO | SA_RESETHAND);
1063 44568 : if( sigaction( sig, act, NULL ) ) FD_LOG_ERR(( "unable to override signal %i", sig ));
1064 44568 : }
1065 :
1066 : static int
1067 : fd_log_private_open_path( int cmdline,
1068 2491 : char const * log_path ) {
1069 2491 : ulong log_path_sz = log_path ? (strlen( log_path )+1UL) : 0UL;
1070 :
1071 2491 : if( !log_path_sz ) { /* Use default log path */
1072 0 : char tag[ FD_LOG_WALLCLOCK_CSTR_BUF_SZ ];
1073 0 : fd_log_wallclock_cstr( fd_log_wallclock(), tag );
1074 0 : for( ulong b=0UL; tag[b]; b++ ) if( tag[b]==' ' || tag[b]=='-' || tag[b]=='.' || tag[b]==':' ) tag[b] = '_';
1075 0 : ulong len; fd_cstr_printf( fd_log_private_path, 1024UL, &len, "/tmp/fd-%i.%i.%i_%lu_%s_%s_%s",
1076 0 : FDCTL_MAJOR_VERSION, FDCTL_MINOR_VERSION, FDCTL_PATCH_VERSION,
1077 0 : fd_log_group_id(), fd_log_user(), fd_log_host(), tag );
1078 0 : if( len==1023UL ) { fd_log_private_fprintf_0( STDERR_FILENO, "default log path too long; unable to boot\n" ); exit(1); }
1079 0 : }
1080 2491 : else if( log_path_sz==1UL ) fd_log_private_path[0] = '\0'; /* User disabled */
1081 667 : else if( log_path_sz<=1024UL ) fd_memcpy( fd_log_private_path, log_path, log_path_sz ); /* User specified */
1082 0 : else { fd_log_private_fprintf_0( STDERR_FILENO, "log path too long; unable to boot\n" ); exit(1); } /* Invalid */
1083 :
1084 2491 : int log_fileno;
1085 2491 : if( fd_log_private_path[0]=='\0' ) {
1086 1824 : if( cmdline ) fd_log_private_fprintf_0( STDERR_FILENO, "--log-path \"\"\nNo log\n" );
1087 0 : else fd_log_private_fprintf_0( STDERR_FILENO, "No log\n" );
1088 1824 : log_fileno = -1;
1089 1824 : } else if( !strcmp( fd_log_private_path, "-" ) ) {
1090 12 : if( cmdline ) fd_log_private_fprintf_0( STDERR_FILENO, "--log-path \"-\"\nLog to stdout\n" );
1091 0 : else fd_log_private_fprintf_0( STDERR_FILENO, "Log to stdout\n" );
1092 12 : log_fileno = STDOUT_FILENO;
1093 655 : } else {
1094 655 : if( cmdline && !log_path_sz ) fd_log_private_fprintf_0( STDERR_FILENO, "--log-path not specified; using autogenerated path\n" );
1095 655 : log_fileno = open( fd_log_private_path, O_WRONLY | O_CREAT | O_APPEND, S_IRUSR | S_IWUSR | S_IRGRP | S_IWGRP | S_IROTH | S_IWOTH );
1096 655 : if( log_fileno==-1 ) {
1097 0 : fd_log_private_fprintf_0( STDERR_FILENO, "open failed (--log-path \"%s\"); unable to boot (%d-%s)\n", fd_log_private_path, errno, fd_io_strerror( errno ) );
1098 0 : exit(1);
1099 0 : }
1100 655 : fd_log_private_fprintf_0( STDERR_FILENO, "Log at \"%s\"\n", fd_log_private_path );
1101 655 : }
1102 2491 : return log_fileno;
1103 2491 : }
1104 :
1105 : void
1106 : fd_log_private_boot( int * pargc,
1107 2491 : char *** pargv ) {
1108 : //FD_LOG_INFO(( "fd_log: booting" )); /* Log not online yet */
1109 :
1110 2491 : char buf[ FD_LOG_NAME_MAX ];
1111 :
1112 2491 : fd_log_private_shared_lock = fd_log_private_shared_lock_local;
1113 :
1114 : /* Init our our application logical ids */
1115 : /* FIXME: CONSIDER EXPLICIT SPECIFICATION OF RANGE OF THREADS
1116 : INSTEAD OF ATOMIC COUNTER FROM BASE */
1117 :
1118 2491 : fd_log_private_app_id_set( fd_env_strip_cmdline_ulong( pargc, pargv, "--log-app-id", "FD_LOG_APP_ID", 0UL ) );
1119 :
1120 2491 : fd_log_private_app_set( fd_env_strip_cmdline_cstr( pargc, pargv, "--log-app", "FD_LOG_APP", NULL ) );
1121 :
1122 2491 : # if FD_HAS_THREADS
1123 2491 : fd_log_private_thread_id_ctr = fd_env_strip_cmdline_ulong( pargc, pargv, "--log-thread-id", "FD_LOG_THREAD_ID", 0UL );
1124 2491 : ulong thread_id = fd_log_private_thread_id_next();
1125 : # else
1126 : ulong thread_id = fd_env_strip_cmdline_ulong( pargc, pargv, "--log-thread-id", "FD_LOG_THREAD_ID", 0UL );
1127 : # endif
1128 2491 : fd_log_private_thread_id_set( thread_id );
1129 :
1130 2491 : fd_log_thread_set( fd_env_strip_cmdline_cstr( pargc, pargv, "--log-thread", "FD_LOG_THREAD", NULL ) );
1131 :
1132 : /* Init our application physical ids */
1133 : /* We ignore any user specified cpu-id in favor of the actual core
1134 : assigned by the host OS. We strip it from the command line so
1135 : downstream command line handling is identical from user's point of
1136 : view. */
1137 :
1138 2491 : fd_log_private_host_id_set( fd_env_strip_cmdline_ulong( pargc, pargv, "--log-host-id", "FD_LOG_HOST_ID", 0UL ) );
1139 :
1140 2491 : char const * host = fd_env_strip_cmdline_cstr( pargc, pargv, "--log-host", "FD_LOG_HOST", NULL );
1141 2491 : if( !host ) { if( !gethostname( buf, FD_LOG_NAME_MAX ) ) buf[ FD_LOG_NAME_MAX-1UL ] = '\0', host = buf; }
1142 2491 : fd_msan_unpoison( (void *)host, FD_LOG_NAME_MAX );
1143 2491 : fd_log_private_host_set( host );
1144 :
1145 2491 : fd_env_strip_cmdline_ulong( pargc, pargv, "--log-cpu-id", "FD_LOG_CPU_ID", 0UL ); /* FIXME: LOG IGNORING? */
1146 2491 : fd_log_private_cpu_id_set( fd_log_private_cpu_id_default() );
1147 :
1148 2491 : fd_log_cpu_set( fd_env_strip_cmdline_cstr( pargc, pargv, "--log-cpu", "FD_LOG_CPU", NULL ) );
1149 :
1150 : /* Init our thread group ids */
1151 : /* We ignore any user specified group id and tid in favor of the actual
1152 : group id and tid assigned by the host OS. We strip it from the
1153 : command line so downstream command line handling is identical from
1154 : user's point of view. */
1155 :
1156 2491 : fd_env_strip_cmdline_ulong( pargc, pargv, "--log-group-id", "FD_LOG_GROUP_ID", 0UL ); /* FIXME: LOG IGNORING? */
1157 2491 : pid_t pid = getpid();
1158 2491 : fd_log_private_group_id_set( fd_ulong_if( pid>(pid_t)0, (ulong)pid, ULONG_MAX ) );
1159 :
1160 2491 : char const * group = fd_env_strip_cmdline_cstr( pargc, pargv, "--log-group", "FD_LOG_GROUP", NULL );
1161 2491 : # if defined(__linux__)
1162 2491 : if( !group ) group = program_invocation_short_name;
1163 : # elif defined(__FreeBSD__)
1164 : if( !group ) group = getprogname();
1165 : # endif
1166 2491 : if( !group ) group = (pargc && pargv && (*pargc)>0) ? (*pargv)[0] : NULL;
1167 2491 : fd_log_private_group_set( group );
1168 :
1169 2491 : fd_env_strip_cmdline_ulong( pargc, pargv, "--log-tid", "FD_LOG_TID", 0UL ); /* FIXME: LOG IGNORING? */
1170 2491 : fd_log_private_tid_set( fd_log_private_tid_default() );
1171 :
1172 2491 : fd_env_strip_cmdline_ulong( pargc, pargv, "--log-user-id", "FD_LOG_USER_ID", 0UL ); /* FIXME: LOG IGNORING? */
1173 2491 : fd_log_private_user_id_set( fd_log_private_user_id_default() );
1174 :
1175 2491 : char const * user = fd_env_strip_cmdline_cstr( pargc, pargv, "--log-user", "FD_LOG_USER", NULL );
1176 2491 : if( !user ) user = getenv( "LOGNAME" );
1177 2491 : if( !user ) user = getlogin();
1178 2491 : fd_log_private_user_set( user );
1179 :
1180 : /* Configure the log */
1181 :
1182 2491 : fd_log_private_dedup = fd_env_strip_cmdline_int( pargc, pargv, "--log-dedup", "FD_LOG_DEDUP", 1 );
1183 :
1184 2491 : int colorize = 0;
1185 2491 : do {
1186 2491 : char const * cstr = fd_env_strip_cmdline_cstr( pargc, pargv, "--log-colorize", "FD_LOG_COLORIZE", NULL );
1187 2491 : if( cstr ) { colorize = fd_cstr_to_int( cstr ); break; }
1188 :
1189 2491 : cstr = fd_env_strip_cmdline_cstr( NULL, NULL, NULL, "COLORTERM", NULL );
1190 2491 : if( cstr && !strcmp( cstr, "truecolor" ) ) { colorize = 1; break; }
1191 :
1192 2491 : cstr = fd_env_strip_cmdline_cstr( NULL, NULL, NULL, "TERM", NULL );
1193 2491 : if( cstr && strstr( cstr, "256color" ) ) { colorize = 1; break; }
1194 :
1195 2491 : } while(0);
1196 0 : fd_log_colorize_set( colorize );
1197 :
1198 2491 : fd_log_level_logfile_set( fd_env_strip_cmdline_int( pargc, pargv, "--log-level-logfile", "FD_LOG_LEVEL_LOGFILE", 1 ) );
1199 2491 : fd_log_level_stderr_set ( fd_env_strip_cmdline_int( pargc, pargv, "--log-level-stderr", "FD_LOG_LEVEL_STDERR", 2 ) );
1200 2491 : fd_log_level_flush_set ( fd_env_strip_cmdline_int( pargc, pargv, "--log-level-flush", "FD_LOG_LEVEL_FLUSH", 3 ) );
1201 2491 : fd_log_level_core_set ( fd_env_strip_cmdline_int( pargc, pargv, "--log-level-core", "FD_LOG_LEVEL_CORE", 5 ) );
1202 :
1203 : /* Hook up signal handlers */
1204 :
1205 2491 : int log_backtrace = fd_env_strip_cmdline_int( pargc, pargv, "--log-backtrace", "FD_LOG_BACKTRACE", 1 );
1206 2491 : if( log_backtrace || fd_log_private_signal_handler ) {
1207 :
1208 2476 : # if FD_HAS_BACKTRACE
1209 : /* If libgcc isn't already linked into the program when a trapped
1210 : signal is received by an application, calls to backtrace and
1211 : backtrace_symbols_fd within the signal handler can silently
1212 : invoke the dynamic linker, which in turn can do silent async
1213 : signal unsafe behavior behind our back. We do dummy calls to
1214 : backtrace and backtrace_symbols_fd here to avoid dynamic linking
1215 : surprises in the signal handler. (Hat tip to runtimeverification
1216 : for finding this.) */
1217 :
1218 2476 : void * btrace[128];
1219 2476 : (void)backtrace( btrace, 128 );
1220 2476 : # endif /* FD_HAS_BACKTRACE */
1221 :
1222 : /* This is all overridable POSIX sigs whose default behavior is to
1223 : abort the program. It will backtrace and then fallback to the
1224 : default behavior. */
1225 2476 : fd_log_private_sig_trap( SIGABRT );
1226 2476 : fd_log_private_sig_trap( SIGALRM );
1227 2476 : fd_log_private_sig_trap( SIGFPE );
1228 2476 : fd_log_private_sig_trap( SIGHUP );
1229 2476 : fd_log_private_sig_trap( SIGILL );
1230 2476 : fd_log_private_sig_trap( SIGQUIT );
1231 2476 : fd_log_private_sig_trap( SIGPIPE );
1232 2476 : fd_log_private_sig_trap( SIGSEGV );
1233 2476 : fd_log_private_sig_trap( SIGUSR1 );
1234 2476 : fd_log_private_sig_trap( SIGUSR2 );
1235 2476 : fd_log_private_sig_trap( SIGBUS );
1236 2476 : fd_log_private_sig_trap( SIGPOLL );
1237 2476 : fd_log_private_sig_trap( SIGPROF );
1238 2476 : fd_log_private_sig_trap( SIGSYS );
1239 2476 : fd_log_private_sig_trap( SIGTRAP );
1240 2476 : fd_log_private_sig_trap( SIGVTALRM );
1241 2476 : fd_log_private_sig_trap( SIGXCPU );
1242 2476 : fd_log_private_sig_trap( SIGXFSZ );
1243 2476 : }
1244 :
1245 : /* Hook up the permanent log */
1246 2491 : char const * log_path = fd_env_strip_cmdline_cstr( pargc, pargv, "--log-path", "FD_LOG_PATH", NULL );
1247 2491 : FD_VOLATILE( fd_log_private_fileno ) = fd_log_private_open_path( 1, log_path );
1248 :
1249 2491 : if( !fd_log_private_unclean_exit ) {
1250 2491 : if( atexit( fd_log_private_cleanup ) ) { fd_log_private_fprintf_0( STDERR_FILENO, "atexit failed; unable to boot\n" ); exit(1); }
1251 2491 : }
1252 :
1253 : /* At this point, logging online */
1254 2491 : if( fd_log_build_info_sz>1UL ) FD_LOG_INFO(( "fd_log: build info:\n%s", fd_log_build_info ));
1255 0 : else FD_LOG_INFO(( "fd_log: build info not available" ));
1256 2491 : FD_LOG_INFO(( "fd_log: --log-path %s", fd_log_private_path ));
1257 2491 : FD_LOG_INFO(( "fd_log: --log-dedup %i", fd_log_private_dedup ));
1258 2491 : FD_LOG_INFO(( "fd_log: --log-colorize %i", fd_log_colorize() ));
1259 2491 : FD_LOG_INFO(( "fd_log: --log-level-logfile %i", fd_log_level_logfile() ));
1260 2491 : FD_LOG_INFO(( "fd_log: --log-level-stderr %i", fd_log_level_stderr() ));
1261 2491 : FD_LOG_INFO(( "fd_log: --log-level-flush %i", fd_log_level_flush() ));
1262 2491 : FD_LOG_INFO(( "fd_log: --log-level-core %i", fd_log_level_core() ));
1263 2491 : FD_LOG_INFO(( "fd_log: --log-app-id %lu", fd_log_app_id() ));
1264 2491 : FD_LOG_INFO(( "fd_log: --log-app %s", fd_log_app() ));
1265 2491 : FD_LOG_INFO(( "fd_log: --log-thread-id %lu", fd_log_thread_id() ));
1266 2491 : FD_LOG_INFO(( "fd_log: --log-thread %s", fd_log_thread() ));
1267 2491 : FD_LOG_INFO(( "fd_log: --log-host-id %lu", fd_log_host_id() ));
1268 2491 : FD_LOG_INFO(( "fd_log: --log-host %s", fd_log_host() ));
1269 2491 : FD_LOG_INFO(( "fd_log: --log-cpu-id %lu", fd_log_cpu_id() ));
1270 2491 : FD_LOG_INFO(( "fd_log: --log-cpu %s", fd_log_cpu() ));
1271 2491 : FD_LOG_INFO(( "fd_log: --log-group-id %lu", fd_log_group_id() ));
1272 2491 : FD_LOG_INFO(( "fd_log: --log-group %s", fd_log_group() ));
1273 2491 : FD_LOG_INFO(( "fd_log: --log-tid %lu", fd_log_tid() ));
1274 2491 : FD_LOG_INFO(( "fd_log: --log-user-id %lu", fd_log_user_id() ));
1275 2491 : FD_LOG_INFO(( "fd_log: --log-user %s", fd_log_user() ));
1276 :
1277 2491 : FD_LOG_INFO(( "fd_log: boot success" ));
1278 2491 : }
1279 :
1280 : void
1281 : fd_log_private_boot_custom( int * lock,
1282 : ulong app_id,
1283 : char const * app,
1284 : ulong thread_id,
1285 : char const * thread,
1286 : ulong host_id,
1287 : char const * host,
1288 : ulong cpu_id,
1289 : char const * cpu,
1290 : ulong group_id,
1291 : char const * group,
1292 : ulong tid,
1293 : ulong user_id,
1294 : char const * user,
1295 : int dedup,
1296 : int colorize,
1297 : int level_logfile,
1298 : int level_stderr,
1299 : int level_flush,
1300 : int level_core,
1301 : int log_fd,
1302 0 : char const * log_path ) {
1303 0 : fd_log_private_shared_lock = lock;
1304 :
1305 0 : fd_log_private_app_id_set( app_id );
1306 0 : fd_log_private_app_set( app );
1307 0 : fd_log_private_thread_id_set( thread_id );
1308 0 : fd_log_thread_set( thread );
1309 0 : fd_log_private_host_id_set( host_id );
1310 0 : fd_log_private_host_set( host );
1311 0 : fd_log_private_cpu_id_set( cpu_id );
1312 0 : fd_log_cpu_set( cpu );
1313 0 : fd_log_private_group_id_set( group_id );
1314 0 : fd_log_private_group_set( group );
1315 0 : fd_log_private_tid_set( tid );
1316 0 : fd_log_private_user_id_set( user_id );
1317 0 : fd_log_private_user_set( user );
1318 :
1319 0 : fd_log_private_dedup = dedup;
1320 0 : fd_log_colorize_set( colorize );
1321 :
1322 0 : fd_log_level_logfile_set( level_logfile );
1323 0 : fd_log_level_stderr_set ( level_stderr );
1324 0 : fd_log_level_flush_set ( level_flush );
1325 0 : fd_log_level_core_set ( level_core );
1326 :
1327 : /* Hook up the permanent log */
1328 0 : if( -1!=log_fd ) {
1329 : /* Log file descriptor was set up before boot, user wishes to log there directly. */
1330 0 : fd_log_private_path[0] = '\0';
1331 0 : FD_VOLATILE( fd_log_private_fileno ) = log_fd;
1332 0 : } else {
1333 0 : FD_VOLATILE( fd_log_private_fileno ) = fd_log_private_open_path( 0, log_path );
1334 0 : }
1335 :
1336 0 : if( FD_UNLIKELY( fd_log_private_signal_handler ) ) {
1337 : /* See note above about needing to prime backtrace */
1338 0 : void * btrace[128];
1339 0 : (void)backtrace( btrace, 128 );
1340 :
1341 : /* This is all overridable POSIX sigs whose default behavior is to
1342 : abort the program. It will backtrace and then fallback to the
1343 : default behavior. */
1344 0 : fd_log_private_sig_trap( SIGABRT );
1345 0 : fd_log_private_sig_trap( SIGALRM );
1346 0 : fd_log_private_sig_trap( SIGFPE );
1347 0 : fd_log_private_sig_trap( SIGHUP );
1348 0 : fd_log_private_sig_trap( SIGILL );
1349 0 : fd_log_private_sig_trap( SIGQUIT );
1350 0 : fd_log_private_sig_trap( SIGPIPE );
1351 0 : fd_log_private_sig_trap( SIGSEGV );
1352 0 : fd_log_private_sig_trap( SIGUSR1 );
1353 0 : fd_log_private_sig_trap( SIGUSR2 );
1354 0 : fd_log_private_sig_trap( SIGBUS );
1355 0 : fd_log_private_sig_trap( SIGPOLL );
1356 0 : fd_log_private_sig_trap( SIGPROF );
1357 0 : fd_log_private_sig_trap( SIGSYS );
1358 0 : fd_log_private_sig_trap( SIGTRAP );
1359 0 : fd_log_private_sig_trap( SIGVTALRM );
1360 0 : fd_log_private_sig_trap( SIGXCPU );
1361 0 : fd_log_private_sig_trap( SIGXFSZ );
1362 0 : }
1363 :
1364 : /* At this point, logging online */
1365 0 : if( fd_log_build_info_sz>1UL ) FD_LOG_INFO(( "fd_log: build info:\n%s", fd_log_build_info ));
1366 0 : else FD_LOG_INFO(( "fd_log: build info not available" ));
1367 0 : FD_LOG_INFO(( "fd_log: --log-path %s", fd_log_private_path ));
1368 0 : FD_LOG_INFO(( "fd_log: --log-dedup %i", fd_log_private_dedup ));
1369 0 : FD_LOG_INFO(( "fd_log: --log-colorize %i", fd_log_colorize() ));
1370 0 : FD_LOG_INFO(( "fd_log: --log-level-logfile %i", fd_log_level_logfile() ));
1371 0 : FD_LOG_INFO(( "fd_log: --log-level-logfile %i", fd_log_level_logfile() ));
1372 0 : FD_LOG_INFO(( "fd_log: --log-level-stderr %i", fd_log_level_stderr() ));
1373 0 : FD_LOG_INFO(( "fd_log: --log-level-flush %i", fd_log_level_flush() ));
1374 0 : FD_LOG_INFO(( "fd_log: --log-level-core %i", fd_log_level_core() ));
1375 0 : FD_LOG_INFO(( "fd_log: --log-app-id %lu", fd_log_app_id() ));
1376 0 : FD_LOG_INFO(( "fd_log: --log-app %s", fd_log_app() ));
1377 0 : FD_LOG_INFO(( "fd_log: --log-thread-id %lu", fd_log_thread_id() ));
1378 0 : FD_LOG_INFO(( "fd_log: --log-thread %s", fd_log_thread() ));
1379 0 : FD_LOG_INFO(( "fd_log: --log-host-id %lu", fd_log_host_id() ));
1380 0 : FD_LOG_INFO(( "fd_log: --log-host %s", fd_log_host() ));
1381 0 : FD_LOG_INFO(( "fd_log: --log-cpu-id %lu", fd_log_cpu_id() ));
1382 0 : FD_LOG_INFO(( "fd_log: --log-cpu %s", fd_log_cpu() ));
1383 0 : FD_LOG_INFO(( "fd_log: --log-group-id %lu", fd_log_group_id() ));
1384 0 : FD_LOG_INFO(( "fd_log: --log-group %s", fd_log_group() ));
1385 0 : FD_LOG_INFO(( "fd_log: --log-tid %lu", fd_log_tid() ));
1386 0 : FD_LOG_INFO(( "fd_log: --log-user-id %lu", fd_log_user_id() ));
1387 0 : FD_LOG_INFO(( "fd_log: --log-user %s", fd_log_user() ));
1388 :
1389 0 : FD_LOG_INFO(( "fd_log: boot success" ));
1390 0 : }
1391 :
1392 : void
1393 1339 : fd_log_private_halt( void ) {
1394 1339 : FD_LOG_INFO(( "fd_log: halting" ));
1395 :
1396 1339 : fd_log_private_cleanup();
1397 :
1398 : /* At this point, log is offline */
1399 :
1400 1339 : fd_log_private_path[0] = '\0';
1401 : //fd_log_private_fileno = -1; /* Already handled by cleanup */
1402 1339 : fd_log_private_dedup = 0;
1403 :
1404 1339 : fd_log_private_level_core = 0;
1405 1339 : fd_log_private_level_flush = 0;
1406 1339 : fd_log_private_level_stderr = 0;
1407 1339 : fd_log_private_level_logfile = 0;
1408 1339 : fd_log_private_colorize = 0;
1409 :
1410 1339 : fd_log_private_clock_func = fd_log_wallclock_host;
1411 1339 : fd_log_private_clock_args = NULL;
1412 :
1413 1339 : fd_log_private_user[0] = '\0';
1414 1339 : fd_log_private_user_id_init = 0;
1415 1339 : fd_log_private_user_id = 0UL;
1416 1339 : fd_log_private_tid_init = 0;
1417 1339 : fd_log_private_tid = 0UL;
1418 1339 : fd_log_private_group[0] = '\0';
1419 1339 : fd_log_private_group_id = 0UL;
1420 :
1421 1339 : fd_log_private_cpu_init = 0;
1422 1339 : fd_log_private_cpu[0] = '\0';
1423 1339 : fd_log_private_cpu_id_init = 0;
1424 1339 : fd_log_private_cpu_id = 0UL;
1425 1339 : fd_log_private_host[0] = '\0';
1426 1339 : fd_log_private_host_id = 0UL;
1427 :
1428 1339 : fd_log_private_thread_init = 0;
1429 1339 : fd_log_private_thread[0] = '\0';
1430 1339 : fd_log_private_thread_id_init = 0;
1431 1339 : fd_log_private_thread_id = 0UL;
1432 1339 : # if FD_HAS_THREADS
1433 1339 : fd_log_private_thread_id_ctr = 0UL;
1434 1339 : # endif
1435 1339 : fd_log_private_app[0] = '\0';
1436 1339 : fd_log_private_app_id = 0UL;
1437 :
1438 1339 : if( FD_LIKELY( fd_log_private_shared_lock!=fd_log_private_shared_lock_local ) ) {
1439 : /* Note: the below will not unmap this in any clones that also
1440 : inherited this mapping unless they were cloned with CLONE_VM. In
1441 : cases like this, the caller is expected to handle the cleanup
1442 : semantics sanely (e.g. only have the parent do boot/halt and then
1443 : children only use log while parent has log booted). */
1444 0 : if( FD_UNLIKELY( munmap( fd_log_private_shared_lock, sizeof(int) ) ) )
1445 0 : fd_log_private_fprintf_0( STDERR_FILENO,
1446 0 : "munmap( fd_log_private_shared_lock, sizeof(int) ) failed (%i-%s); attempting to continue",
1447 0 : errno, fd_io_strerror( errno ) );
1448 0 : }
1449 1339 : fd_log_private_shared_lock = NULL;
1450 :
1451 : //FD_LOG_INFO(( "fd_log: halt success" )); /* Log not online anymore */
1452 1339 : }
1453 :
1454 : #include <sys/resource.h>
1455 :
1456 : ulong
1457 2491 : fd_log_private_main_stack_sz( void ) {
1458 :
1459 : /* We are extra paranoid about what rlimit returns and we don't trust
1460 : environments that claim an unlimited stack size (because it just
1461 : isn't unlimited ... even if rlimit says otherwise ... which it will
1462 : if a user tries to be clever with a "ulimit -s unlimited" ... e.g.
1463 : tile0's stack highest address is at 128 TiB-4KiB typically on
1464 : modern Linux and grows down while the text / data / heap grow up
1465 : from 0B ... so stack size is practically always going to be << 128
1466 : TiB irrespective of any getrlimit claim). TODO: It looks like
1467 : pthead_attr_getstack might be getrlimit based under the hood, so
1468 : maybe just use pthread_attr_getstack here too? */
1469 :
1470 2491 : struct rlimit rlim[1];
1471 2491 : int err = getrlimit( RLIMIT_STACK, rlim );
1472 2491 : if( FD_UNLIKELY( err ) ) {
1473 0 : FD_LOG_WARNING(( "fd_log: getrlimit failed (%i-%s)", errno, fd_io_strerror( errno ) ));
1474 0 : return 0UL;
1475 0 : }
1476 :
1477 2491 : ulong stack_sz = (ulong)rlim->rlim_cur;
1478 2491 : if( FD_UNLIKELY( (rlim->rlim_cur>rlim->rlim_max) | (rlim->rlim_max>RLIM_INFINITY ) |
1479 2491 : (rlim->rlim_cur==RLIM_INFINITY) | (rlim->rlim_cur!=(rlim_t)stack_sz) ) ) {
1480 0 : FD_LOG_WARNING(( "fd_log: unexpected stack limits (rlim_cur %lu, rlim_max %lu)",
1481 0 : (ulong)rlim->rlim_cur, (ulong)rlim->rlim_max ));
1482 0 : return 0UL;
1483 0 : }
1484 :
1485 2491 : return stack_sz;
1486 2491 : }
1487 :
1488 : /* When pthread_setstack is not used to explicitly set the memory region
1489 : for a new thread's stack, pthread_create will create a memory region
1490 : (using either the requested size or a default size). And, while
1491 : pthread allows us to set and get the size of the stack region it
1492 : creates and we can get a pointer into a thread's stack by just
1493 : declaring a stack variable in that thread and we obviously know where
1494 : a thread's stack is when we explicitly specify it to pthread create,
1495 : pthreads does not seem to provide a simple way to get the extents of
1496 : the stacks it creates.
1497 :
1498 : But the relationship between a pointer in the stack and the stack
1499 : extents is non-trival because pthreads will use some of the stack for
1500 : things like thread local storage (and it will not tell us how much
1501 : stack was used by that and this is practically only known after
1502 : linking is complete and then it is not simply exposed to the
1503 : application).
1504 :
1505 : Similar uncertainty applies to the first thread's stack. We can
1506 : learn how large the stack is and get a pointer into the stack via a
1507 : stack variable but we have no simple way to get the extents. And, in
1508 : this case on recent Linux, things like command line strings and
1509 : environment strings are typically allowed to consume up to 1/4 of
1510 : main's thread stack ... these are only known at application load
1511 : time. (There is the additional caveat that the main stack might be
1512 : dynamically allocated such that the address space reserved for it
1513 : might not be backed by memory yet.)
1514 :
1515 : But, if we want to do useful run-time stack diagnostics (e.g. alloca
1516 : bounds checking / stack overflow prevention / etc), having explicit
1517 : knowledge of a thread's stack extents is very useful. Hence the
1518 : below. It would be nice if there was portable and non-horrific way
1519 : to do this (an even more horrific way is trigger seg faults by
1520 : scanning for the guard pages and then recover from the seg fault via
1521 : a longjmp ... shivers). */
1522 :
1523 : void
1524 : fd_log_private_stack_discover( ulong stack_sz,
1525 : ulong * _stack0,
1526 2491 : ulong * _stack1 ) {
1527 :
1528 2491 : if( FD_UNLIKELY( !stack_sz ) ) {
1529 0 : *_stack0 = 0UL;
1530 0 : *_stack1 = 0UL;
1531 0 : return;
1532 0 : }
1533 :
1534 2491 : ulong stack0 = 0UL;
1535 2491 : ulong stack1 = 0UL;
1536 :
1537 : /* Create a variable on the caller's stack and scan the thread group's
1538 : memory map for the memory region holding the variable. That should
1539 : be the caller's stack. */
1540 :
1541 2491 : uchar stack_mem[1];
1542 2491 : FD_VOLATILE( stack_mem[0] ) = (uchar)1; /* Paranoia to make sure compiler puts this in stack */
1543 2491 : ulong stack_addr = (ulong)stack_mem;
1544 :
1545 2491 : int filefd;
1546 2491 : if( FD_UNLIKELY( ( filefd = open( "/proc/self/maps", O_RDONLY ) ) < 0 ) ) {
1547 0 : FD_LOG_WARNING(( "open( \"/proc/self/maps\" ) failed (%i-%s)", errno, fd_io_strerror( errno ) ));
1548 0 : *_stack0 = 0UL;
1549 0 : *_stack1 = 0UL;
1550 0 : return;
1551 0 : }
1552 :
1553 2491 : char filebuf[1<<12];
1554 2491 : ulong filelen = 0;
1555 2491 : char * p = filebuf;
1556 2491 : int found = 0;
1557 95079 : while( !found ) {
1558 :
1559 : /* Scan a line */
1560 :
1561 95079 : int full_line = 0;
1562 95079 : char * nextp;
1563 9784765 : for( nextp = p; nextp < filebuf + filelen; ) {
1564 9782264 : if( *(nextp++) == '\n' ) {
1565 92578 : full_line = 1;
1566 92578 : break;
1567 92578 : }
1568 9782264 : }
1569 95079 : if( !full_line ) {
1570 : /* We need to read more data. First shift the old data down. */
1571 2501 : filelen = (ulong)((filebuf + filelen) - p);
1572 2501 : if( filelen )
1573 0 : memmove( filebuf, p, filelen );
1574 2501 : p = filebuf;
1575 : /* Now read data */
1576 2501 : ssize_t tlen;
1577 2501 : if( FD_UNLIKELY( ( tlen = read( filefd, filebuf + filelen, sizeof(filebuf)-1U-filelen ) ) < 0 ) ) {
1578 0 : FD_LOG_WARNING(( "read( \"/proc/self/maps\" ) failed (%i-%s)", errno, fd_io_strerror( errno ) ));
1579 0 : break;
1580 0 : }
1581 2501 : if( tlen == 0 ) break; /* End of file */
1582 2501 : filelen += (ulong)tlen;
1583 2501 : filebuf[filelen] = '\0'; /* For sscanf */
1584 2501 : continue;
1585 2501 : }
1586 :
1587 92578 : ulong m0;
1588 92578 : ulong m1;
1589 92578 : int r = sscanf( p, "%lx-%lx", &m0, &m1 );
1590 92578 : p = nextp;
1591 92578 : if( FD_UNLIKELY( r !=2 ) ) continue;
1592 :
1593 : /* Test if the stack allocation is in the discovered region */
1594 :
1595 92578 : if( FD_UNLIKELY( (m0<=stack_addr) & (stack_addr<m1) ) ) {
1596 2491 : found = 1;
1597 2491 : ulong msz = m1 - m0;
1598 2491 : if( msz==stack_sz ) { /* Memory region matches expectations */
1599 0 : stack0 = m0;
1600 0 : stack1 = m1;
1601 2491 : } else if( ((fd_log_group_id()==fd_log_tid()) & (msz<stack_sz)) ) {
1602 : /* This is the main thread, which, on recent Linux, seems to
1603 : just reserve address space for main's stack at program
1604 : start up to the application stack size limits then uses
1605 : page faults to dynamically back the stack with DRAM as the
1606 : stack grows (which is awful for performance, jitter and
1607 : reliability ... sigh). This assumes stack grows down such
1608 : that m1 is the fixed value in this process. */
1609 2491 : stack0 = m1 - stack_sz;
1610 2491 : stack1 = m1;
1611 2491 : } else {
1612 0 : FD_LOG_WARNING(( "unexpected caller stack memory region size (got %lu bytes, expected %lu bytes)", msz, stack_sz ));
1613 : /* don't trust the discovered region */
1614 0 : }
1615 2491 : break;
1616 2491 : }
1617 :
1618 92578 : }
1619 2491 : if( !found )
1620 0 : FD_LOG_WARNING(( "unable to find stack size around address 0x%lx", stack_addr ));
1621 :
1622 2491 : close(filefd);
1623 :
1624 2491 : *_stack0 = stack0;
1625 2491 : *_stack1 = stack1;
1626 2491 : }
1627 :
1628 : #else
1629 : #error "Unknown FD_LOG_STYLE"
1630 : #endif
|
