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