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