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