Line data Source code
1 : /*
2 : * SPDX-License-Identifier: MPL-2.0
3 : *
4 : * This Source Code Form is subject to the terms of the Mozilla Public
5 : * License, v. 2.0. If a copy of the MPL was not distributed with this
6 : * file, You can obtain one at http://mozilla.org/MPL/2.0/.
7 : *
8 : * Copyright 2024 MonetDB Foundation;
9 : * Copyright August 2008 - 2023 MonetDB B.V.;
10 : * Copyright 1997 - July 2008 CWI.
11 : */
12 :
13 : #include "monetdb_config.h"
14 : #include "gdk.h"
15 : #include "gdk_tracer.h"
16 : #include "gdk_private.h"
17 : #include "mutils.h"
18 :
19 : #define DEFAULT_ADAPTER BASIC
20 : #define DEFAULT_LOG_LEVEL M_ERROR
21 : #define DEFAULT_FLUSH_LEVEL M_DEBUG
22 :
23 : #define FILE_NAME "mdbtrace.log"
24 :
25 : #define AS_STR(x) #x
26 : #define STR(x) AS_STR(x)
27 :
28 : #define GENERATE_STRING(STRING) #STRING,
29 :
30 : static FILE *active_tracer;
31 : MT_Lock GDKtracer_lock = MT_LOCK_INITIALIZER(GDKtracer_lock);
32 :
33 : static char *file_name;
34 :
35 : static ATOMIC_TYPE cur_adapter = ATOMIC_VAR_INIT(DEFAULT_ADAPTER);
36 :
37 : static log_level_t cur_flush_level = DEFAULT_FLUSH_LEVEL;
38 :
39 : static bool write_to_tracer = false;
40 :
41 : #define GENERATE_LOG_LEVEL(COMP) ATOMIC_VAR_INIT((ATOMIC_BASE_TYPE) DEFAULT_LOG_LEVEL),
42 : ATOMIC_TYPE lvl_per_component[] = {
43 : FOREACH_COMP(GENERATE_LOG_LEVEL)
44 : };
45 :
46 : static const char *adapter_str[] = {
47 : FOREACH_ADPTR(GENERATE_STRING)
48 : };
49 :
50 : static const char *layer_str[] = {
51 : FOREACH_LAYER(GENERATE_STRING)
52 : };
53 :
54 : static const char *component_str[] = {
55 : FOREACH_COMP(GENERATE_STRING)
56 : };
57 :
58 : static const char *level_str[] = {
59 : FOREACH_LEVEL(GENERATE_STRING)
60 : };
61 :
62 :
63 : #define MXW "20"
64 :
65 : #define TS_SIZE ((size_t) 20) /* buffer size needed for timestamp */
66 :
67 :
68 : /*
69 : * GDKtracer Stream Macros
70 : */
71 : // Exception
72 : #define GDK_TRACER_EXCEPTION(MSG, ...) \
73 : fprintf(stderr, \
74 : "%s " \
75 : "%-"MXW"s " \
76 : "%"MXW"s:%d " \
77 : "%"MXW"s " \
78 : "%-"MXW"s " \
79 : "%-"MXW"s # "MSG, \
80 : get_timestamp((char[TS_SIZE]){0}, TS_SIZE), \
81 : __FILE__, \
82 : __func__, \
83 : __LINE__, \
84 : STR(M_CRITICAL), \
85 : STR(GDK_TRACER), \
86 : MT_thread_getname(), \
87 : ## __VA_ARGS__);
88 :
89 :
90 : #define GDK_TRACER_RESET_OUTPUT() \
91 : do { \
92 : write_to_tracer = false; \
93 : for (int i = 0; !write_to_tracer && i < (int) COMPONENTS_COUNT; i++) { \
94 : write_to_tracer = (log_level_t) ATOMIC_GET(&lvl_per_component[i]) > DEFAULT_LOG_LEVEL; \
95 : } \
96 : } while(0)
97 :
98 : static inline char *
99 287384 : get_timestamp(char *datetime, size_t dtsz)
100 : {
101 287384 : time_t now = time(NULL);
102 287382 : struct tm tmp;
103 287382 : (void) localtime_r(&now, &tmp);
104 287398 : strftime(datetime, dtsz, "%Y-%m-%d %H:%M:%S", &tmp);
105 :
106 287398 : return datetime;
107 : }
108 :
109 :
110 : // When BASIC adapter is active, all the log messages are getting printed to a file.
111 : // This function prepares a file in order to write the contents of the buffer when necessary.
112 : static gdk_return
113 649 : GDKtracer_init_trace_file(const char *dbpath, const char *dbtrace)
114 : {
115 649 : char *fn;
116 :
117 : /* we use malloc/free instead of GDKmalloc/GDKfree to avoid
118 : * possible recursion */
119 : #undef malloc
120 : #undef free
121 649 : if (dbtrace == NULL) {
122 649 : write_to_tracer = false;
123 649 : if (dbpath == NULL) {
124 320 : active_tracer = stderr;
125 320 : return GDK_SUCCEED;
126 : }
127 329 : size_t fnl = strlen(dbpath) + strlen(DIR_SEP_STR) + strlen(FILE_NAME) + 1;
128 329 : fn = malloc(fnl);
129 329 : if (fn == NULL) {
130 0 : GDK_TRACER_EXCEPTION("malloc failure\n");
131 0 : active_tracer = stderr;
132 0 : return GDK_FAIL;
133 : }
134 329 : if (strconcat_len(fn, fnl, dbpath, DIR_SEP_STR, FILE_NAME, NULL)
135 : >= fnl) {
136 : /* cannot happen */
137 0 : goto too_long;
138 : }
139 : } else {
140 0 : write_to_tracer = true;
141 0 : size_t fnl = strlen(dbtrace) + 1;
142 0 : fn = malloc(fnl);
143 0 : if (fn == NULL) {
144 0 : GDK_TRACER_EXCEPTION("malloc failure\n");
145 0 : active_tracer = stderr;
146 0 : return GDK_FAIL;
147 : }
148 0 : if (strcpy_len(fn, dbtrace, fnl)
149 : >= fnl) {
150 : /* cannot happen */
151 0 : goto too_long;
152 : }
153 : }
154 329 : free(file_name);
155 329 : file_name = fn;
156 :
157 329 : active_tracer = MT_fopen(file_name, "a");
158 :
159 329 : if (active_tracer == NULL) {
160 0 : GDK_TRACER_EXCEPTION("Failed to open %s: %s\n", file_name,
161 0 : GDKstrerror(errno, (char[64]){0}, 64));
162 : /* uninitialize */
163 0 : free(file_name);
164 0 : file_name = NULL;
165 0 : active_tracer = stderr;
166 0 : return GDK_FAIL;
167 : }
168 :
169 : return GDK_SUCCEED;
170 :
171 0 : too_long:
172 0 : GDK_TRACER_EXCEPTION("path name for dbtrace file too long\n");
173 : /* uninitialize */
174 0 : free(fn);
175 0 : free(file_name);
176 0 : file_name = NULL;
177 0 : active_tracer = stderr;
178 0 : return GDK_FAIL;
179 : }
180 :
181 : static gdk_return
182 319 : _GDKtracer_init_basic_adptr(void)
183 : {
184 319 : return GDKtracer_init_trace_file(GDKgetenv("gdk_dbpath"),
185 : GDKgetenv("gdk_dbtrace"));
186 : }
187 :
188 : static void
189 326 : set_level_for_layer(int layer, log_level_t level)
190 : {
191 326 : const char *tok = NULL;
192 :
193 : // make sure we initialize before changing the component level
194 326 : MT_lock_set(&GDKtracer_lock);
195 326 : if (file_name == NULL) {
196 1 : _GDKtracer_init_basic_adptr();
197 : }
198 326 : MT_lock_unset(&GDKtracer_lock);
199 :
200 8802 : for (int i = 0; i < COMPONENTS_COUNT; i++) {
201 8476 : if (layer == MDB_ALL) {
202 8476 : ATOMIC_SET(&lvl_per_component[i], (ATOMIC_BASE_TYPE) level);
203 : } else {
204 0 : tok = component_str[i];
205 :
206 0 : switch (layer) {
207 0 : case SQL_ALL:
208 0 : if (strncmp(tok, "SQL_", 4) == 0)
209 0 : ATOMIC_SET(&lvl_per_component[i], (ATOMIC_BASE_TYPE) level);
210 : break;
211 0 : case MAL_ALL:
212 0 : if (strncmp(tok, "MAL_", 4) == 0)
213 0 : ATOMIC_SET(&lvl_per_component[i], (ATOMIC_BASE_TYPE) level);
214 : break;
215 0 : case GDK_ALL:
216 0 : if (strncmp(tok, "GDK", 3) == 0)
217 0 : ATOMIC_SET(&lvl_per_component[i], (ATOMIC_BASE_TYPE) level);
218 : break;
219 : default:
220 : break;
221 : }
222 : }
223 : }
224 326 : MT_lock_set(&GDKtracer_lock);
225 8802 : GDK_TRACER_RESET_OUTPUT();
226 326 : MT_lock_unset(&GDKtracer_lock);
227 326 : }
228 :
229 : static inline adapter_t
230 1 : find_adapter(const char *adptr)
231 : {
232 1 : if (adptr == NULL)
233 : return ADAPTERS_COUNT;
234 :
235 3 : for (int i = 0; i < (int) ADAPTERS_COUNT; i++) {
236 3 : if (strcasecmp(adapter_str[i], adptr) == 0) {
237 1 : return (adapter_t) i;
238 : }
239 : }
240 : return ADAPTERS_COUNT;
241 : }
242 :
243 : static inline log_level_t
244 441 : find_level(const char *lvl)
245 : {
246 441 : if (lvl == NULL)
247 : return LOG_LEVELS_COUNT;
248 :
249 2089 : for (int i = 0; i < (int) LOG_LEVELS_COUNT; i++) {
250 2089 : if (strcasecmp(level_str[i] + 2, lvl) == 0) {
251 441 : return (log_level_t) i;
252 : }
253 : }
254 : return LOG_LEVELS_COUNT;
255 : }
256 :
257 : static inline layer_t
258 0 : find_layer(const char *layer)
259 : {
260 0 : if (layer == NULL)
261 : return LAYERS_COUNT;
262 0 : for (int i = 0; i < (int) LAYERS_COUNT; i++) {
263 0 : if (strcasecmp(layer_str[i], layer) == 0) {
264 0 : return (layer_t) i;
265 : }
266 : }
267 : return LAYERS_COUNT;
268 : }
269 :
270 : static inline component_t
271 4412 : find_component(const char *comp)
272 : {
273 : /* special case for the (currently) three components that end in _ */
274 4412 : if (comp == NULL || *comp == 0 || comp[strlen(comp) - 1] == '_')
275 : return COMPONENTS_COUNT;
276 4412 : if (strcasecmp(comp, "io") == 0)
277 : comp = "io_";
278 4054 : else if (strcasecmp(comp, "bat") == 0)
279 : comp = "bat_";
280 3696 : else if (strcasecmp(comp, "check") == 0)
281 358 : comp = "check_";
282 :
283 31676 : for (int i = 0; i < (int) COMPONENTS_COUNT; i++) {
284 31676 : if (strcasecmp(component_str[i], comp) == 0) {
285 4412 : return (component_t) i;
286 : }
287 : }
288 : return COMPONENTS_COUNT;
289 : }
290 :
291 :
292 :
293 : /**
294 : *
295 : * API CALLS
296 : *
297 : */
298 : static volatile sig_atomic_t interrupted = 0;
299 :
300 : void
301 0 : GDKtracer_reinit_basic(int sig)
302 : {
303 0 : (void) sig;
304 0 : interrupted = 1;
305 0 : }
306 :
307 : static void
308 0 : reinit(void)
309 : {
310 : /* called locked */
311 :
312 0 : interrupted = 0;
313 :
314 : // GDKtracer needs to reopen the file only in
315 : // case the adapter is BASIC
316 0 : if ((adapter_t) ATOMIC_GET(&cur_adapter) != BASIC)
317 : return;
318 :
319 0 : if (active_tracer) {
320 0 : if (active_tracer != stderr)
321 0 : fclose(active_tracer);
322 : else
323 0 : fflush(active_tracer);
324 0 : active_tracer = NULL;
325 : }
326 0 : _GDKtracer_init_basic_adptr();
327 : }
328 :
329 :
330 : gdk_return
331 326 : GDKtracer_stop(void)
332 : {
333 326 : set_level_for_layer(MDB_ALL, DEFAULT_LOG_LEVEL);
334 326 : if (active_tracer) {
335 326 : if (active_tracer != stderr)
336 325 : fclose(active_tracer);
337 : else
338 1 : fflush(active_tracer);
339 326 : active_tracer = NULL;
340 : }
341 326 : return GDK_SUCCEED;
342 : }
343 :
344 : gdk_return
345 441 : GDKtracer_set_component_level(const char *comp, const char *lvl)
346 : {
347 441 : log_level_t level = find_level(lvl);
348 441 : component_t component = find_component(comp);
349 :
350 441 : if (level == LOG_LEVELS_COUNT) {
351 0 : GDKerror("unknown level\n");
352 0 : return GDK_FAIL;
353 : }
354 441 : if (component == COMPONENTS_COUNT) {
355 0 : GDKerror("unknown component\n");
356 0 : return GDK_FAIL;
357 : }
358 :
359 : // make sure we initialize before changing the component level
360 441 : MT_lock_set(&GDKtracer_lock);
361 441 : if (file_name == NULL) {
362 318 : _GDKtracer_init_basic_adptr();
363 : }
364 441 : write_to_tracer |= level > DEFAULT_LOG_LEVEL;
365 441 : MT_lock_unset(&GDKtracer_lock);
366 :
367 441 : ATOMIC_SET(&lvl_per_component[component], (ATOMIC_BASE_TYPE) level);
368 :
369 441 : return GDK_SUCCEED;
370 : }
371 :
372 : const char *
373 240 : GDKtracer_get_component_level(const char *comp)
374 : {
375 240 : component_t component = find_component(comp);
376 :
377 240 : if (component == COMPONENTS_COUNT) {
378 0 : GDKerror("unknown component\n");
379 0 : return NULL;
380 : }
381 240 : return level_str[ATOMIC_GET(&lvl_per_component[component])];
382 : }
383 :
384 :
385 : gdk_return
386 3731 : GDKtracer_reset_component_level(const char *comp)
387 : {
388 3731 : component_t component = find_component(comp);
389 :
390 3731 : if (component == COMPONENTS_COUNT) {
391 0 : GDKerror("unknown component\n");
392 0 : return GDK_FAIL;
393 : }
394 3731 : ATOMIC_SET(&lvl_per_component[component], (ATOMIC_BASE_TYPE) DEFAULT_LOG_LEVEL);
395 3731 : MT_lock_set(&GDKtracer_lock);
396 51258 : GDK_TRACER_RESET_OUTPUT();
397 3731 : MT_lock_unset(&GDKtracer_lock);
398 :
399 3731 : return GDK_SUCCEED;
400 : }
401 :
402 :
403 : gdk_return
404 0 : GDKtracer_set_layer_level(const char *layer, const char *lvl)
405 : {
406 0 : layer_t lyr = find_layer(layer);
407 0 : log_level_t level = find_level(lvl);
408 0 : if (level == LOG_LEVELS_COUNT) {
409 0 : GDKerror("unknown level\n");
410 0 : return GDK_FAIL;
411 : }
412 0 : if (lyr == LAYERS_COUNT) {
413 0 : GDKerror("unknown layer\n");
414 0 : return GDK_FAIL;
415 : }
416 :
417 0 : set_level_for_layer(lyr, level);
418 0 : return GDK_SUCCEED;
419 : }
420 :
421 :
422 : gdk_return
423 0 : GDKtracer_reset_layer_level(const char *layer)
424 : {
425 0 : layer_t lyr = find_layer(layer);
426 0 : if (lyr == LAYERS_COUNT) {
427 0 : GDKerror("unknown layer\n");
428 0 : return GDK_FAIL;
429 : }
430 :
431 0 : set_level_for_layer(lyr, DEFAULT_LOG_LEVEL);
432 0 : return GDK_SUCCEED;
433 : }
434 :
435 :
436 : gdk_return
437 0 : GDKtracer_set_flush_level(const char *lvl)
438 : {
439 0 : log_level_t level = find_level(lvl);
440 0 : if (level == LOG_LEVELS_COUNT) {
441 0 : GDKerror("unknown level\n");
442 0 : return GDK_FAIL;
443 : }
444 :
445 0 : cur_flush_level = level;
446 0 : return GDK_SUCCEED;
447 : }
448 :
449 :
450 : gdk_return
451 0 : GDKtracer_reset_flush_level(void)
452 : {
453 0 : cur_flush_level = DEFAULT_FLUSH_LEVEL;
454 0 : return GDK_SUCCEED;
455 : }
456 :
457 :
458 : gdk_return
459 1 : GDKtracer_set_adapter(const char *adapter)
460 : {
461 1 : adapter_t adptr = find_adapter(adapter);
462 1 : if (adptr == ADAPTERS_COUNT) {
463 0 : GDKerror("unknown adapter\n");
464 0 : return GDK_FAIL;
465 : }
466 :
467 : // Here when switching between adapters we can open/close the file
468 : // But it is not so important to keep it open in case the adapter switches
469 : // From BASIC to other => close the file
470 : // From other to BASIC => open the file
471 :
472 1 : ATOMIC_SET(&cur_adapter, adptr);
473 :
474 1 : return GDK_SUCCEED;
475 : }
476 :
477 :
478 : gdk_return
479 0 : GDKtracer_reset_adapter(void)
480 : {
481 0 : ATOMIC_SET(&cur_adapter, DEFAULT_ADAPTER);
482 0 : return GDK_SUCCEED;
483 : }
484 :
485 : static bool add_ts; /* add timestamp to error message to stderr */
486 :
487 : gdk_return
488 330 : GDKtracer_init(const char *dbpath, const char *dbtrace)
489 : {
490 330 : MT_lock_set(&GDKtracer_lock);
491 : #ifdef _MSC_VER
492 : add_ts = GetFileType(GetStdHandle(STD_ERROR_HANDLE)) != FILE_TYPE_PIPE;
493 : #else
494 330 : add_ts = isatty(2) || lseek(2, 0, SEEK_CUR) != (off_t) -1 || errno != ESPIPE;
495 : #endif
496 330 : gdk_return rc = GDKtracer_init_trace_file(dbpath, dbtrace);
497 330 : MT_lock_unset(&GDKtracer_lock);
498 330 : return rc;
499 : }
500 :
501 : gdk_return
502 0 : GDKtracer_set_tracefile(const char *tracefile)
503 : {
504 0 : return GDKtracer_init(NULL, tracefile);
505 : }
506 :
507 : void
508 287391 : GDKtracer_log(const char *file, const char *func, int lineno,
509 : log_level_t level, component_t comp,
510 : const char *syserr,
511 : const char *fmt, ...)
512 : {
513 287391 : int bytes_written;
514 287391 : char buffer[512]; /* should be plenty big enough for a message */
515 287391 : va_list va;
516 287391 : char ts[TS_SIZE];
517 287391 : char *msg = NULL;
518 287391 : bool isexit;
519 287391 : static char file_prefix[] = __FILE__;
520 287391 : static size_t prefix_length = (size_t) -1;
521 :
522 287391 : if (prefix_length == (size_t) -1) {
523 : /* first time, calculate prefix of file name */
524 173 : msg = strstr(file_prefix, "gdk" DIR_SEP_STR "gdk_tracer.c");
525 173 : if (msg == NULL)
526 0 : prefix_length = 0;
527 : else
528 173 : prefix_length = (size_t) (msg - file_prefix);
529 : }
530 287391 : if (prefix_length != 0 &&
531 287391 : strncmp(file, file_prefix, prefix_length) == 0)
532 287380 : file += prefix_length;
533 :
534 287391 : va_start(va, fmt);
535 287391 : int pad = (int) strlen(file);
536 287391 : pad = (pad > 40) ? 0 : 40 - pad;
537 287391 : bytes_written = snprintf(buffer, sizeof(buffer),
538 : "%s " /* timestamp */
539 : "%10s " /* level */
540 : "%-8s " /* component */
541 : "%-20s " /* thread name */
542 : "%s:%-5d %*s" /* file, lineno, pad */
543 : "%-20s ", /* function */
544 : get_timestamp(ts, sizeof(ts)),
545 : level_str[level],
546 : component_str[comp],
547 : MT_thread_getname(),
548 : file, lineno, pad, "",
549 : func);
550 287398 : if (bytes_written > 0 && bytes_written < (int) sizeof(buffer)) {
551 287394 : msg = buffer + bytes_written;
552 : } else {
553 : /* exceedingly unlikely that we ever come here */
554 : msg = buffer;
555 : bytes_written = 0;
556 : }
557 287398 : bytes_written = vsnprintf(msg,
558 : sizeof(buffer) - bytes_written,
559 : fmt, va);
560 287398 : isexit = strstr(msg, EXITING_MSG) != NULL;
561 287398 : va_end(va);
562 287398 : if (bytes_written < 0) {
563 0 : if ((adapter_t) ATOMIC_GET(&cur_adapter) != MBEDDED)
564 0 : GDK_TRACER_EXCEPTION("Failed to write logs\n");
565 2176 : return;
566 : }
567 287398 : char *p;
568 287398 : if ((p = strchr(buffer, '\n')) != NULL)
569 150918 : *p = '\0';
570 :
571 287398 : if (comp == GDK && level <= M_ERROR) {
572 : /* append message to GDKerrbuf (if set) */
573 1576 : char *buf = GDKerrbuf;
574 1576 : if (buf) {
575 1574 : size_t n = strlen(buf);
576 4722 : snprintf(buf + n, GDKMAXERRLEN - n,
577 : "%s%s: %s%s%s\n",
578 : isexit ? "" : GDKERROR,
579 : func, msg,
580 : syserr ? ": " : "",
581 : syserr ? syserr : "");
582 : }
583 : }
584 :
585 : /* don't write to file in embedded case, but set the GDK error buffer */
586 287398 : if ((adapter_t) ATOMIC_GET(&cur_adapter) == MBEDDED)
587 : return;
588 :
589 287389 : MT_lock_set(&GDKtracer_lock);
590 287398 : if (interrupted)
591 0 : reinit();
592 :
593 287398 : if (level <= M_WARNING || (ATOMIC_GET(&GDKdebug) & TESTINGMASK)) {
594 574393 : fprintf(level <= M_ERROR && !isexit ? stderr : stdout,
595 : "#%s%s%s: %s: %s: %s%s%s\n",
596 : add_ts ? ts : "",
597 286834 : add_ts ? ": " : "",
598 286834 : MT_thread_getname(), func, level_str[level] + 2,
599 : msg, syserr ? ": " : "",
600 : syserr ? syserr : "");
601 286834 : if (active_tracer == NULL || active_tracer == stderr || !write_to_tracer) {
602 2167 : MT_lock_unset(&GDKtracer_lock);
603 2167 : return;
604 : }
605 : }
606 285231 : if (active_tracer == NULL) {
607 0 : MT_lock_unset(&GDKtracer_lock);
608 0 : return;
609 : }
610 285231 : if (syserr)
611 0 : fprintf(active_tracer, "%s: %s\n", buffer, syserr);
612 : else
613 285231 : fprintf(active_tracer, "%s\n", buffer);
614 :
615 : // Flush the current buffer in case the event is
616 : // important depending on the flush-level
617 : // Always flush CRITICAL and ERROR messages - prevent cases
618 : // like mserver5 refusing to start due to allocated port
619 : // and the error is never reported to the user because it
620 : // is still in the buffer which it never gets flushed.
621 285231 : if (level == cur_flush_level || level <= M_ERROR)
622 41140 : fflush(active_tracer);
623 285231 : MT_lock_unset(&GDKtracer_lock);
624 : }
625 :
626 :
627 : gdk_return
628 0 : GDKtracer_flush_buffer(void)
629 : {
630 0 : if (active_tracer)
631 0 : fflush(active_tracer);
632 0 : return GDK_SUCCEED;
633 : }
634 :
635 :
636 : gdk_return
637 0 : GDKtracer_fill_comp_info(BAT *id, BAT *component, BAT *log_level)
638 : {
639 0 : for (int i = 0; i < COMPONENTS_COUNT; i++) {
640 0 : if (BUNappend(id, &i, false) != GDK_SUCCEED)
641 0 : return GDK_FAIL;
642 :
643 0 : if (BUNappend(component, component_str[i], false) != GDK_SUCCEED)
644 : return GDK_FAIL;
645 :
646 0 : if (BUNappend(log_level, level_str[ATOMIC_GET(&lvl_per_component[i])], false) != GDK_SUCCEED)
647 : return GDK_FAIL;
648 : }
649 :
650 0 : return GDK_SUCCEED;
651 : }
|
