LCOV - code coverage report
Current view: top level - gdk - gdk_tracer.c (source / functions) Hit Total Coverage
Test: coverage.info Lines: 115 212 54.2 %
Date: 2021-09-14 19:48:19 Functions: 14 24 58.3 %

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

Generated by: LCOV version 1.14