libatalk/util/logger.c

   1
   2 #ifdef HAVE_CONFIG_H
   3 #include "config.h"
   4 #endif
   5
   6 /* =========================================================================
   7
   8 logger.c was written by Simon Bazley (sibaz@sibaz.com)
   9
  10 I believe libatalk is released under the L/GPL licence.
  11 Just incase, it is, thats the licence I'm applying to this file.
  12 Netatalk 2001 (c)
  13
  14 ========================================================================= */
  15
  16 #include <stdio.h>
  17 #include <limits.h>
  18 #include <stdarg.h>
  19 #include <string.h>
  20 #include <stdlib.h>
  21 #include <syslog.h>
  22 #include <sys/types.h>
  23 #include <sys/stat.h>
  24 #include <fcntl.h>
  25 #include <sys/uio.h>
  26 #include <unistd.h>
  27 #include <sys/time.h>
  28 #include <time.h>
  29 #include <ctype.h>
  30 #include <errno.h>
  31 #include <stdbool.h>
  32
  33 #include <atalk/util.h>
  34 #include <atalk/logger.h>
  35 #include <atalk/unix.h>
  36
  37 #define COUNT_ARRAY(array) (sizeof((array))/sizeof((array)[0]))
  38
  39 #define MAXLOGSIZE 512
  40
  41 #define LOGLEVEL_STRING_IDENTIFIERS { \
  42   "NOTHING",                      \
  43   "SEVERE",                       \
  44   "ERROR",                        \
  45   "WARN",                         \
  46   "NOTE",                         \
  47   "INFO",                         \
  48   "DEBUG",                        \
  49   "DEBUG6",                       \
  50   "DEBUG7",                       \
  51   "DEBUG8",                       \
  52   "DEBUG9",                       \
  53   "MAXDEBUG"}
  54
  55 /* these are the string identifiers corresponding to each logtype */
  56 #define LOGTYPE_STRING_IDENTIFIERS { \
  57   "Default",                         \
  58   "Logger",                          \
  59   "CNID",                            \
  60   "AFPDaemon",                       \
  61   "DSI",                             \
  62   "UAMS",                            \
  63   "FCE",                             \
  64   "end_of_list_marker"}
  65
  66 /* =========================================================================
  67    Config
  68    ========================================================================= */
  69
  70 /* Main log config container */
  71 log_config_t log_config = { 0 };
  72
  73 /* Default log config: log nothing to files.
  74    0:               set ?
  75    0:               syslog ?
  76    -1:              logfiles fd
  77    log_none:        no logging by default
  78    0:               Display options */
  79 #define DEFAULT_LOG_CONFIG {0, 0, -1, log_none, 0}
  80
  81 UAM_MODULE_EXPORT logtype_conf_t type_configs[logtype_end_of_list_marker] = {
  82     DEFAULT_LOG_CONFIG, /* logtype_default */
  83     DEFAULT_LOG_CONFIG, /* logtype_logger */
  84     DEFAULT_LOG_CONFIG, /* logtype_cnid */
  85     DEFAULT_LOG_CONFIG, /* logtype_afpd */
  86     DEFAULT_LOG_CONFIG, /* logtype_dsi */
  87     DEFAULT_LOG_CONFIG, /* logtype_uams */
  88     DEFAULT_LOG_CONFIG  /* logtype_fce */
  89 };
  90
  91 static void syslog_setup(int loglevel, enum logtypes logtype, int display_options, int facility);
  92
  93 /* We use this in order to track the last n log messages in order to prevent flooding */
  94 #define LOG_FLOODING_MINCOUNT 5 /* this controls after how many consecutive messages must be detected
  95                                    before we start to hide them */
  96 #define LOG_FLOODING_MAXCOUNT 1000 /* this controls after how many consecutive messages we force a
  97                                       "repeated x times" message */
  98 #define LOG_FLOODING_ARRAY_SIZE 3 /* this contols how many messages in flow we track */
  99
 100 struct log_flood_entry {
 101     int count;
 102     unsigned int hash;
 103 };
 104
 105 static struct log_flood_entry log_flood_array[LOG_FLOODING_ARRAY_SIZE];
 106 static int log_flood_entries;
 107
 108 /* These are used by the LOG macro to store __FILE__ and __LINE__ */
 109 static const char *log_src_filename;
 110 static int  log_src_linenumber;
 111
 112 /* Array to store text to list given a log type */
 113 static const char *arr_logtype_strings[] =  LOGTYPE_STRING_IDENTIFIERS;
 114 static const unsigned int num_logtype_strings = COUNT_ARRAY(arr_logtype_strings);
 115
 116 /* Array for charachters representing log severity in the log file */
 117 static const char arr_loglevel_chars[] = {'-','S', 'E', 'W', 'N', 'I', 'D'};
 118 static const unsigned int num_loglevel_chars = COUNT_ARRAY(arr_loglevel_chars);
 119
 120 static const char *arr_loglevel_strings[] = LOGLEVEL_STRING_IDENTIFIERS;
 121 static const unsigned int num_loglevel_strings = COUNT_ARRAY(arr_loglevel_strings);
 122
 123 /* =========================================================================
 124    Internal function definitions
 125    ========================================================================= */
 126
 127 /* Hash a log message */
 128 static unsigned int hash_message(const char *message)
 129 {
 130     const char *p = message;
 131     unsigned int hash = 0, i = 7;
 132
 133     while (*p) {
 134         hash += *p * i;
 135         i++;
 136         p++;
 137     }
 138     return hash;
 139 }
 140
 141 static void generate_message_details(char *message_details_buffer,
 142                                      int message_details_buffer_length,
 143                                      int display_options,
 144                                      enum loglevels loglevel, enum logtypes logtype)
 145 {
 146     char   *ptr = message_details_buffer;
 147     int    templen;
 148     int    len = message_details_buffer_length;
 149     struct timeval tv;
 150     pid_t  pid;
 151
 152     *ptr = 0;
 153
 154     /* Print time */
 155     gettimeofday(&tv, NULL);
 156     strftime(ptr, len, "%b %d %H:%M:%S.", localtime(&tv.tv_sec));
 157     templen = strlen(ptr);
 158     len -= templen;
 159     ptr += templen;
 160
 161     templen = snprintf(ptr, len, "%06u ", (int)tv.tv_usec);
 162     if (templen == -1 || templen >= len)
 163         return;
 164
 165     len -= templen;
 166     ptr += templen;
 167
 168     /* Process name &&  PID */
 169     pid = getpid();
 170     templen = snprintf(ptr, len, "%s[%d]", log_config.processname, pid);
 171     if (templen == -1 || templen >= len)
 172         return;
 173     len -= templen;
 174     ptr += templen;
 175
 176     /* Source info ? */
 177     if ( ! (display_options & logoption_nsrcinfo)) {
 178         char *basename = strrchr(log_src_filename, '/');
 179         if (basename)
 180             templen = snprintf(ptr, len, " {%s:%d}", basename + 1, log_src_linenumber);
 181         else
 182             templen = snprintf(ptr, len, " {%s:%d}", log_src_filename, log_src_linenumber);
 183         if (templen == -1 || templen >= len)
 184             return;
 185         len -= templen;
 186         ptr += templen;
 187     }
 188
 189     /* Errorlevel */
 190     if (loglevel >= (num_loglevel_chars - 1))
 191         templen = snprintf(ptr, len,  " (D%d:", loglevel - 1);
 192     else
 193         templen = snprintf(ptr, len, " (%c:", arr_loglevel_chars[loglevel]);
 194
 195     if (templen == -1 || templen >= len)
 196         return;
 197     len -= templen;
 198     ptr += templen;
 199
 200     /* Errortype */
 201     if (logtype<num_logtype_strings) {
 202         templen = snprintf(ptr, len, "%s", arr_logtype_strings[logtype]);
 203         if (templen == -1 || templen >= len)
 204             return;
 205         len -= templen;
 206         ptr += templen;
 207     }
 208
 209     strncat(ptr, "): ", len);
 210     ptr[len -1] = 0;
 211 }
 212
 213 static int get_syslog_equivalent(enum loglevels loglevel)
 214 {
 215     switch (loglevel)
 216     {
 217         /* The question is we know how bad it is for us,
 218            but how should that translate in the syslogs?  */
 219     case 1: /* severe */
 220         return LOG_ERR;
 221     case 2: /* error */
 222         return LOG_ERR;
 223     case 3: /* warning */
 224         return LOG_WARNING;
 225     case 4: /* note */
 226         return LOG_NOTICE;
 227     case 5: /* information */
 228         return LOG_INFO;
 229     default: /* debug */
 230         return LOG_DEBUG;
 231     }
 232 }
 233
 234 /* Called by the LOG macro for syslog messages */
 235 static void make_syslog_entry(enum loglevels loglevel, enum logtypes logtype _U_, char *message)
 236 {
 237     if ( !log_config.syslog_opened ) {
 238         openlog(log_config.processname,
 239                 log_config.syslog_display_options,
 240                 log_config.syslog_facility);
 241         log_config.syslog_opened = true;
 242     }
 243
 244     syslog(get_syslog_equivalent(loglevel), "%s", message);
 245 }
 246
 247 static void log_init(void)
 248 {
 249     syslog_setup(log_info,
 250                  logtype_default,
 251                  logoption_ndelay | logoption_pid,
 252                  logfacility_daemon);
 253 }
 254
 255 static void log_setup(const char *filename, enum loglevels loglevel, enum logtypes logtype)
 256 {
 257     if (loglevel == 0) {
 258         /* Disable */
 259         if (type_configs[logtype].set) {
 260             if (type_configs[logtype].fd != -1)
 261                 close(type_configs[logtype].fd);
 262             type_configs[logtype].fd = -1;
 263             type_configs[logtype].level = -1;
 264             type_configs[logtype].set = false;
 265
 266             /* if disabling default also set all "default using" levels to 0 */
 267             if (logtype == logtype_default) {
 268                 while (logtype != logtype_end_of_list_marker) {
 269                     if ( ! (type_configs[logtype].set))
 270                         type_configs[logtype].level = -1;
 271                     logtype++;
 272                 }
 273             }
 274         }
 275         return;
 276     }
 277
 278     /* Safety check */
 279     if (NULL == filename)
 280         return;
 281
 282     /* Resetting existing config ? */
 283     if (type_configs[logtype].set) {
 284         if (type_configs[logtype].fd != -1)
 285             close(type_configs[logtype].fd);
 286         type_configs[logtype].fd = -1;
 287         type_configs[logtype].level = -1;
 288         type_configs[logtype].set = false;
 289         type_configs[logtype].syslog = false;
 290
 291         /* Reset configs using default */
 292         if (logtype == logtype_default) {
 293             int typeiter = 0;
 294             while (typeiter != logtype_end_of_list_marker) {
 295                 if (type_configs[typeiter].set == false) {
 296                     type_configs[typeiter].level = -1;
 297                     type_configs[typeiter].syslog = false;
 298                 }
 299                 typeiter++;
 300             }
 301         }
 302     }
 303
 304     /* Set new values */
 305     type_configs[logtype].level = loglevel;
 306
 307     /* Open log file as OPEN_LOGS_AS_UID*/
 308
 309     /* Is it /dev/tty ? */
 310     if (strcmp(filename, "/dev/tty") == 0) {
 311         type_configs[logtype].fd = 1; /* stdout */
 312
 313     /* Does it end in "XXXXXX" ? debug reguest via SIGINT */
 314     } else if (strcmp(filename + strlen(filename) - 6, "XXXXXX") == 0) {
 315         char *tmp = strdup(filename);
 316         type_configs[logtype].fd = mkstemp(tmp);
 317         free(tmp);
 318
 319     } else {
 320         become_root();
 321         type_configs[logtype].fd = open(filename,
 322                                         O_CREAT | O_WRONLY | O_APPEND,
 323                                         S_IRUSR | S_IWUSR | S_IRGRP | S_IROTH);
 324         become_root();
 325     }
 326
 327     /* Check for error opening/creating logfile */
 328     if (type_configs[logtype].fd == -1) {
 329         type_configs[logtype].level = -1;
 330         type_configs[logtype].set = false;
 331         return;
 332     }
 333
 334     fcntl(type_configs[logtype].fd, F_SETFD, FD_CLOEXEC);
 335     type_configs[logtype].set = true;
 336     log_config.inited = true;
 337
 338     /* Here's how we make it possible to LOG to a logtype like "logtype_afpd" */
 339     /* which then uses the default logtype setup if it isn't setup itself: */
 340     /* we just copy the loglevel from default to all logtypes that are not setup. */
 341     /* In "make_log_entry" we then check for the logtypes if they arent setup */
 342     /* and use default then. We must provide accessible values for all logtypes */
 343     /* in order to make it easy and fast to check the loglevels in the LOG macro! */
 344
 345     if (logtype == logtype_default) {
 346         int typeiter = 0;
 347         while (typeiter != logtype_end_of_list_marker) {
 348             if ( ! (type_configs[typeiter].set))
 349                 type_configs[typeiter].level = loglevel;
 350             typeiter++;
 351         }
 352     }
 353
 354     LOG(log_debug, logtype_logger, "Setup file logging: type: %s, level: %s, file: %s",
 355         arr_logtype_strings[logtype], arr_loglevel_strings[loglevel], filename);
 356 }
 357
 358 /* Setup syslog logging */
 359 static void syslog_setup(int loglevel, enum logtypes logtype, int display_options, int facility)
 360 {
 361     /*
 362      * FIXME:
 363      * this currently doesn't care if logtype is already logging to a file.
 364      * Fortunately currently there's no way a user could trigger this as afpd.conf
 365      * is not re-read on SIGHUP.
 366      */
 367
 368     type_configs[logtype].level = loglevel;
 369     type_configs[logtype].set = true;
 370     type_configs[logtype].syslog = true;
 371     log_config.syslog_display_options = display_options;
 372     log_config.syslog_facility = facility;
 373
 374     /* Setting default logging? Then set all logtype not set individually */
 375     if (logtype == logtype_default) {
 376         int typeiter = 0;
 377         while (typeiter != logtype_end_of_list_marker) {
 378             if ( ! (type_configs[typeiter].set)) {
 379                 type_configs[typeiter].level = loglevel;
 380                 type_configs[typeiter].syslog = true;
 381             }
 382             typeiter++;
 383         }
 384     }
 385
 386     log_config.inited = 1;
 387
 388     LOG(log_info, logtype_logger, "Set syslog logging to level: %s",
 389         arr_loglevel_strings[loglevel]);
 390 }
 391
 392 /*
 393  * If filename == NULL its for syslog logging, otherwise its for file-logging.
 394  * "unsetuplog" calls with loglevel == NULL.
 395  * loglevel == NULL means:
 396  *    if logtype == default
 397  *       disable logging
 398  *    else
 399  *       set to default logging
 400  */
 401 static void setuplog_internal(const char *loglevel, const char *logtype, const char *filename)
 402 {
 403     unsigned int typenum, levelnum;
 404
 405     /* Parse logtype */
 406     for( typenum=0; typenum < num_logtype_strings; typenum++) {
 407         if (strcasecmp(logtype, arr_logtype_strings[typenum]) == 0)
 408             break;
 409     }
 410     if (typenum >= num_logtype_strings) {
 411         return;
 412     }
 413
 414     /* Parse loglevel */
 415     if (loglevel == NULL) {
 416         levelnum = 0;
 417     } else {
 418         for(levelnum=1; levelnum < num_loglevel_strings; levelnum++) {
 419             if (strcasecmp(loglevel, arr_loglevel_strings[levelnum]) == 0)
 420                 break;
 421         }
 422         if (levelnum >= num_loglevel_strings) {
 423             return;
 424         }
 425     }
 426
 427     /* is this a syslog setup or a filelog setup ? */
 428     if (filename == NULL) {
 429         /* must be syslog */
 430         syslog_setup(levelnum,
 431                      typenum,
 432                      logoption_ndelay | logoption_pid,
 433                      logfacility_daemon);
 434     } else {
 435         /* this must be a filelog */
 436         log_setup(filename, levelnum, typenum);
 437     }
 438
 439     return;
 440 }
 441
 442 /* =========================================================================
 443    Global function definitions
 444    ========================================================================= */
 445
 446 /* This function sets up the processname */
 447 void set_processname(const char *processname)
 448 {
 449     strncpy(log_config.processname, processname, 15);
 450     log_config.processname[15] = 0;
 451 }
 452
 453 /* -------------------------------------------------------------------------
 454    make_log_entry has 1 main flaws:
 455    The message in its entirity, must fit into the tempbuffer.
 456    So it must be shorter than MAXLOGSIZE
 457    ------------------------------------------------------------------------- */
 458 void make_log_entry(enum loglevels loglevel, enum logtypes logtype,
 459                     const char *file, int line, char *message, ...)
 460 {
 461     /* fn is not reentrant but is used in signal handler
 462      * with LOGGER it's a little late source name and line number
 463      * are already changed. */
 464     static int inlog = 0;
 465     int fd, len;
 466     char temp_buffer[MAXLOGSIZE];
 467     char log_details_buffer[MAXLOGSIZE];
 468     va_list args;
 469     struct iovec iov[2];
 470
 471     if (inlog)
 472         return;
 473
 474     inlog = 1;
 475
 476     if (!log_config.inited) {
 477       log_init();
 478     }
 479
 480     if (type_configs[logtype].syslog) {
 481         if (type_configs[logtype].level >= loglevel) {
 482             /* Initialise the Messages and send it to syslog */
 483             va_start(args, message);
 484             vsnprintf(temp_buffer, MAXLOGSIZE -1, message, args);
 485             va_end(args);
 486             temp_buffer[MAXLOGSIZE -1] = 0;
 487             make_syslog_entry(loglevel, logtype, temp_buffer);
 488         }
 489         inlog = 0;
 490         return;
 491     }
 492
 493     /* logging to a file */
 494
 495     log_src_filename = file;
 496     log_src_linenumber = line;
 497
 498     /* Check if requested logtype is setup */
 499     if (type_configs[logtype].set)
 500         /* Yes */
 501         fd = type_configs[logtype].fd;
 502     else
 503         /* No: use default */
 504         fd = type_configs[logtype_default].fd;
 505
 506     if (fd < 0) {
 507         /* no where to send the output, give up */
 508         goto exit;
 509     }
 510
 511     /* Initialise the Messages */
 512     va_start(args, message);
 513     len = vsnprintf(temp_buffer, MAXLOGSIZE -1, message, args);
 514     va_end(args);
 515
 516     /* Append \n */
 517     if (len ==-1 || len >= MAXLOGSIZE -1) {
 518         /* vsnprintf hit the buffer size*/
 519         temp_buffer[MAXLOGSIZE-2] = '\n';
 520         temp_buffer[MAXLOGSIZE-1] = 0;
 521     }
 522     else {
 523         temp_buffer[len] = '\n';
 524         temp_buffer[len+1] = 0;
 525     }
 526
 527     if (type_configs[logtype].level >= log_debug)
 528         goto log; /* bypass flooding checks */
 529
 530     /* Prevent flooding: hash the message and check if we got the same one recently */
 531     int hash = hash_message(temp_buffer) + log_src_linenumber;
 532
 533     /* Search for the same message by hash */
 534     for (int i = log_flood_entries - 1; i >= 0; i--) {
 535         if (log_flood_array[i].hash == hash) {
 536
 537             /* found same message */
 538             log_flood_array[i].count++;
 539
 540             /* Check if that message has reached LOG_FLOODING_MAXCOUNT */
 541             if (log_flood_array[i].count >= LOG_FLOODING_MAXCOUNT) {
 542                 /* yes, log it and remove from array */
 543
 544                 /* reusing log_details_buffer */
 545                 sprintf(log_details_buffer, "message repeated %i times\n",
 546                         LOG_FLOODING_MAXCOUNT - 1);
 547                 write(fd, log_details_buffer, strlen(log_details_buffer));
 548
 549                 if ((i + 1) == LOG_FLOODING_ARRAY_SIZE) {
 550                     /* last array element, just decrement count */
 551                     log_flood_entries--;
 552                     goto exit;
 553                 }
 554                 /* move array elements down */
 555                 for (int j = i + 1; j != LOG_FLOODING_ARRAY_SIZE ; j++)
 556                     log_flood_array[j-1] = log_flood_array[j];
 557                 log_flood_entries--;
 558             }
 559
 560             if (log_flood_array[i].count < LOG_FLOODING_MINCOUNT)
 561                 /* log it */
 562                 goto log;
 563             /* discard it */
 564             goto exit;
 565         } /* if */
 566     }  /* for */
 567
 568     /* No matching message found, add this message to array*/
 569     if (log_flood_entries == LOG_FLOODING_ARRAY_SIZE) {
 570         /* array is full, discard oldest entry printing "message repeated..." if count > 1 */
 571         if (log_flood_array[0].count >= LOG_FLOODING_MINCOUNT) {
 572             /* reusing log_details_buffer */
 573             sprintf(log_details_buffer, "message repeated %i times\n",
 574                     log_flood_array[0].count - LOG_FLOODING_MINCOUNT + 1);
 575             write(fd, log_details_buffer, strlen(log_details_buffer));
 576         }
 577         for (int i = 1; i < LOG_FLOODING_ARRAY_SIZE; i++) {
 578             log_flood_array[i-1] = log_flood_array[i];
 579         }
 580         log_flood_entries--;
 581     }
 582     log_flood_array[log_flood_entries].count = 1;
 583     log_flood_array[log_flood_entries].hash = hash;
 584     log_flood_entries++;
 585
 586 log:
 587     if ( ! log_config.console) {
 588         generate_message_details(log_details_buffer, sizeof(log_details_buffer),
 589                                  type_configs[logtype].set ?
 590                                      type_configs[logtype].display_options :
 591                                      type_configs[logtype_default].display_options,
 592                                  loglevel, logtype);
 593
 594         /* If default wasnt setup its fd is -1 */
 595         iov[0].iov_base = log_details_buffer;
 596         iov[0].iov_len = strlen(log_details_buffer);
 597         iov[1].iov_base = temp_buffer;
 598         iov[1].iov_len = strlen(temp_buffer);
 599         writev( fd,  iov, 2);
 600     } else {
 601         write(fd, temp_buffer, strlen(temp_buffer));
 602     }
 603
 604 exit:
 605     inlog = 0;
 606 }
 607
 608 void setuplog(const char *logstr, const char *logfile)
 609 {
 610     char *ptr, *save;
 611     char *logtype, *loglevel;
 612     char c;
 613
 614     save = ptr = strdup(logstr);
 615
 616     ptr = strtok(ptr, ", ");
 617
 618     while (ptr) {
 619         while (*ptr) {
 620             while (*ptr && isspace(*ptr))
 621                 ptr++;
 622
 623             logtype = ptr;
 624             ptr = strpbrk(ptr, ":");
 625             if (!ptr)
 626                 break;
 627             *ptr = 0;
 628
 629             ptr++;
 630             loglevel = ptr;
 631             while (*ptr && !isspace(*ptr))
 632                 ptr++;
 633             c = *ptr;
 634             *ptr = 0;
 635             setuplog_internal(loglevel, logtype, logfile);
 636             *ptr = c;
 637         }
 638         ptr = strtok(NULL, ", ");
 639     }
 640
 641     free(save);
 642 }
 643