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