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