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