libatalk/util/logger.c

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