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