X-Git-Url: https://arthur.barton.de/cgi-bin/gitweb.cgi?p=netatalk.git;a=blobdiff_plain;f=libatalk%2Futil%2Flogger.c;h=c8a2a0a8acd2845c43bfbd088e81b7a496855a1b;hp=bebc26660c7417dffbd4425e5c2a59b77f969dcb;hb=4111aba41c36a99bfd7eb7e987b24314735cdd10;hpb=95f8603b4a655d6335d97cb472092e80099162f2 diff --git a/libatalk/util/logger.c b/libatalk/util/logger.c index bebc2666..c8a2a0a8 100644 --- a/libatalk/util/logger.c +++ b/libatalk/util/logger.c @@ -1,3 +1,4 @@ + #ifdef HAVE_CONFIG_H #include "config.h" #endif @@ -27,120 +28,116 @@ Netatalk 2001 (c) #include #include #include +#include -#include #include - -#define LOGGER_C #include -#undef LOGGER_C - -#define OPEN_LOGS_AS_UID 0 +#include #define COUNT_ARRAY(array) (sizeof((array))/sizeof((array)[0])) +#define MAXLOGSIZE 512 + +#define LOGLEVEL_STRING_IDENTIFIERS { \ + "NOTHING", \ + "SEVERE", \ + "ERROR", \ + "WARN", \ + "NOTE", \ + "INFO", \ + "DEBUG", \ + "DEBUG6", \ + "DEBUG7", \ + "DEBUG8", \ + "DEBUG9", \ + "MAXDEBUG"} + +/* these are the string identifiers corresponding to each logtype */ +#define LOGTYPE_STRING_IDENTIFIERS { \ + "Default", \ + "Logger", \ + "CNID", \ + "AFPDaemon", \ + "DSI", \ + "ATalkDaemon", \ + "PAPDaemon", \ + "UAMS", \ + "end_of_list_marker"} \ + /* ========================================================================= Config ========================================================================= */ -/* Main log config container, must be globally visible */ -log_config_t log_config = { - 0, /* Initialized ? 0 = no */ - 0, /* No filelogging setup yet */ - {0}, /* processname */ - 0, /* syslog opened ? */ - logfacility_daemon, /* syslog facility to use */ - logoption_ndelay|logoption_pid, /* logging options for syslog */ - 0 /* log level for syslog */ -}; +/* Main log config container */ +log_config_t log_config = { 0 }; /* Default log config: log nothing to files. - 0: not set individually - NULL: Name of file - -1: logfiles fd - 0: Log Level - 0: Display options */ -#define DEFAULT_LOG_CONFIG {0, NULL, -1, 0, 0} - -filelog_conf_t file_configs[logtype_end_of_list_marker] = { + 0: set ? + 0: syslog ? + -1: logfiles fd + log_none: no logging by default + 0: Display options */ +#define DEFAULT_LOG_CONFIG {0, 0, -1, log_none, 0} + +UAM_MODULE_EXPORT logtype_conf_t type_configs[logtype_end_of_list_marker] = { DEFAULT_LOG_CONFIG, /* logtype_default */ - DEFAULT_LOG_CONFIG, /* logtype_core */ DEFAULT_LOG_CONFIG, /* logtype_logger */ DEFAULT_LOG_CONFIG, /* logtype_cnid */ DEFAULT_LOG_CONFIG, /* logtype_afpd */ + DEFAULT_LOG_CONFIG, /* logtype_dsi */ DEFAULT_LOG_CONFIG, /* logtype_atalkd */ DEFAULT_LOG_CONFIG, /* logtype_papd */ - DEFAULT_LOG_CONFIG /* logtype_uams */ + DEFAULT_LOG_CONFIG /* logtype_uams */ +}; + +static void syslog_setup(int loglevel, enum logtypes logtype, int display_options, int facility); + +/* We use this in order to track the last n log messages in order to prevent flooding */ +#define LOG_FLOODING_MINCOUNT 5 /* this controls after how many consecutive messages must be detected + before we start to hide them */ +#define LOG_FLOODING_MAXCOUNT 1000 /* this controls after how many consecutive messages we force a + "repeated x times" message */ +#define LOG_FLOODING_ARRAY_SIZE 3 /* this contols how many messages in flow we track */ + +struct log_flood_entry { + int count; + unsigned int hash; }; +static struct log_flood_entry log_flood_array[LOG_FLOODING_ARRAY_SIZE]; +static int log_flood_entries; + /* These are used by the LOG macro to store __FILE__ and __LINE__ */ -char *log_src_filename; -int log_src_linenumber; +static const char *log_src_filename; +static int log_src_linenumber; /* Array to store text to list given a log type */ static const char *arr_logtype_strings[] = LOGTYPE_STRING_IDENTIFIERS; -static const int num_logtype_strings = COUNT_ARRAY(arr_logtype_strings); +static const unsigned int num_logtype_strings = COUNT_ARRAY(arr_logtype_strings); /* Array for charachters representing log severity in the log file */ static const char arr_loglevel_chars[] = {'-','S', 'E', 'W', 'N', 'I', 'D'}; -static const int num_loglevel_chars = COUNT_ARRAY(arr_loglevel_chars); +static const unsigned int num_loglevel_chars = COUNT_ARRAY(arr_loglevel_chars); static const char *arr_loglevel_strings[] = LOGLEVEL_STRING_IDENTIFIERS; -static const int num_loglevel_strings = COUNT_ARRAY(arr_loglevel_strings); +static const unsigned int num_loglevel_strings = COUNT_ARRAY(arr_loglevel_strings); /* ========================================================================= Internal function definitions ========================================================================= */ -/* - * If filename == NULL its for syslog logging, otherwise its for file-logging. - * "unsetuplog" calls with loglevel == NULL. - * loglevel == NULL means: - * if logtype == default - * disable logging - * else - * set to default logging - */ - -/* -[un]setuplog []*/ -static void setuplog_internal(const char *loglevel, const char *logtype, const char *filename) +/* Hash a log message */ +static unsigned int hash_message(const char *message) { - int typenum, levelnum; + const char *p = message; + unsigned int hash = 0, i = 7; - /* Parse logtype */ - for( typenum=0; typenum < num_logtype_strings; typenum++) { - if (strcasecmp(logtype, arr_logtype_strings[typenum]) == 0) - break; - } - if (typenum >= num_logtype_strings) { - return; - } - - /* Parse loglevel */ - if (loglevel == NULL) { - levelnum = 0; - } else { - for(levelnum=1; levelnum < num_loglevel_strings; levelnum++) { - if (strcasecmp(loglevel, arr_loglevel_strings[levelnum]) == 0) - break; - } - if (levelnum >= num_loglevel_strings) { - return; - } - } - - /* is this a syslog setup or a filelog setup ? */ - if (filename == NULL) { - /* must be syslog */ - syslog_setup(levelnum, 0, - log_config.syslog_display_options, - log_config.facility); - } else { - /* this must be a filelog */ - log_setup(filename, levelnum, typenum); + while (*p) { + hash += *p * i; + i++; + p++; } - - return; + return hash; } static void generate_message_details(char *message_details_buffer, @@ -236,43 +233,47 @@ static int get_syslog_equivalent(enum loglevels loglevel) } } -/* ========================================================================= - Global function definitions - ========================================================================= */ - -void log_init(void) +/* Called by the LOG macro for syslog messages */ +static void make_syslog_entry(enum loglevels loglevel, enum logtypes logtype _U_, char *message) { - syslog_setup(log_note, 0, - log_config.syslog_display_options, - log_config.facility); + if ( !log_config.syslog_opened ) { + openlog(log_config.processname, + log_config.syslog_display_options, + log_config.syslog_facility); + log_config.syslog_opened = true; + } + + syslog(get_syslog_equivalent(loglevel), "%s", message); } -void log_setup(const char *filename, enum loglevels loglevel, enum logtypes logtype) +static void log_init(void) { - uid_t process_uid; + syslog_setup(log_info, + logtype_default, + logoption_ndelay | logoption_pid, + logfacility_daemon); +} +static void log_setup(const char *filename, enum loglevels loglevel, enum logtypes logtype) +{ if (loglevel == 0) { /* Disable */ - if (file_configs[logtype].set) { - if (file_configs[logtype].filename) { - free(file_configs[logtype].filename); - file_configs[logtype].filename = NULL; - } - close(file_configs[logtype].fd); - file_configs[logtype].fd = -1; - file_configs[logtype].level = 0; - file_configs[logtype].set = 0; + if (type_configs[logtype].set) { + if (type_configs[logtype].fd != -1) + close(type_configs[logtype].fd); + type_configs[logtype].fd = -1; + type_configs[logtype].level = -1; + type_configs[logtype].set = false; /* if disabling default also set all "default using" levels to 0 */ if (logtype == logtype_default) { while (logtype != logtype_end_of_list_marker) { - if ( ! (file_configs[logtype].set)) - file_configs[logtype].level = 0; + if ( ! (type_configs[logtype].set)) + type_configs[logtype].level = -1; logtype++; } } } - return; } @@ -281,51 +282,60 @@ void log_setup(const char *filename, enum loglevels loglevel, enum logtypes logt return; /* Resetting existing config ? */ - if (file_configs[logtype].set && file_configs[logtype].filename) { - free(file_configs[logtype].filename); - file_configs[logtype].filename = NULL; - close(file_configs[logtype].fd); - file_configs[logtype].fd = -1; - file_configs[logtype].level = 0; - file_configs[logtype].set = 0; + if (type_configs[logtype].set) { + if (type_configs[logtype].fd != -1) + close(type_configs[logtype].fd); + type_configs[logtype].fd = -1; + type_configs[logtype].level = -1; + type_configs[logtype].set = false; + type_configs[logtype].syslog = false; + + /* Reset configs using default */ + if (logtype == logtype_default) { + int typeiter = 0; + while (typeiter != logtype_end_of_list_marker) { + if (type_configs[typeiter].set == false) { + type_configs[typeiter].level = -1; + type_configs[typeiter].syslog = false; + } + typeiter++; + } + } } /* Set new values */ - file_configs[logtype].filename = strdup(filename); - file_configs[logtype].level = loglevel; - + type_configs[logtype].level = loglevel; /* Open log file as OPEN_LOGS_AS_UID*/ - process_uid = geteuid(); - if (process_uid) { - if (seteuid(OPEN_LOGS_AS_UID) == -1) { - /* XXX failing silently */ - return; - } - } - file_configs[logtype].fd = open( file_configs[logtype].filename, - O_CREAT | O_WRONLY | O_APPEND, - S_IRUSR | S_IWUSR | S_IRGRP | S_IROTH); - if (process_uid) { - if (seteuid(process_uid) == -1) { - LOG(log_error, logtype_logger, "can't seteuid back %s", strerror(errno)); - exit(EXITERR_SYS); - } + + /* Is it /dev/tty ? */ + if (strcmp(filename, "/dev/tty") == 0) { + type_configs[logtype].fd = 1; /* stdout */ + + /* Does it end in "XXXXXX" ? debug reguest via SIGINT */ + } else if (strcmp(filename + strlen(filename) - 6, "XXXXXX") == 0) { + char *tmp = strdup(filename); + type_configs[logtype].fd = mkstemp(tmp); + free(tmp); + + } else { + become_root(); + type_configs[logtype].fd = open(filename, + O_CREAT | O_WRONLY | O_APPEND, + S_IRUSR | S_IWUSR | S_IRGRP | S_IROTH); + become_root(); } /* Check for error opening/creating logfile */ - if (-1 == file_configs[logtype].fd) { - free(file_configs[logtype].filename); - file_configs[logtype].filename = NULL; - file_configs[logtype].level = -1; - file_configs[logtype].set = 0; + if (type_configs[logtype].fd == -1) { + type_configs[logtype].level = -1; + type_configs[logtype].set = false; return; } - fcntl(file_configs[logtype].fd, F_SETFD, FD_CLOEXEC); - file_configs[logtype].set = 1; - log_config.filelogging = 1; - log_config.inited = 1; + fcntl(type_configs[logtype].fd, F_SETFD, FD_CLOEXEC); + type_configs[logtype].set = true; + log_config.inited = true; /* Here's how we make it possible to LOG to a logtype like "logtype_afpd" */ /* which then uses the default logtype setup if it isn't setup itself: */ @@ -335,36 +345,106 @@ void log_setup(const char *filename, enum loglevels loglevel, enum logtypes logt /* in order to make it easy and fast to check the loglevels in the LOG macro! */ if (logtype == logtype_default) { - while (logtype != logtype_end_of_list_marker) { - if ( ! (file_configs[logtype].set)) - file_configs[logtype].level = loglevel; - logtype++; + int typeiter = 0; + while (typeiter != logtype_end_of_list_marker) { + if ( ! (type_configs[typeiter].set)) + type_configs[typeiter].level = loglevel; + typeiter++; } - logtype = logtype_default; } LOG(log_debug, logtype_logger, "Setup file logging: type: %s, level: %s, file: %s", - arr_logtype_strings[logtype], arr_loglevel_strings[loglevel], file_configs[logtype].filename); + arr_logtype_strings[logtype], arr_loglevel_strings[loglevel], filename); } -/* logtype is ignored, it's just one for all */ -void syslog_setup(int loglevel, enum logtypes logtype _U_, - int display_options, int facility) +/* Setup syslog logging */ +static void syslog_setup(int loglevel, enum logtypes logtype, int display_options, int facility) { - log_config.syslog_level = loglevel; + /* + * FIXME: + * this currently doesn't care if logtype is already logging to a file. + * Fortunately currently there's no way a user could trigger this as afpd.conf + * is not re-read on SIGHUP. + */ + + type_configs[logtype].level = loglevel; + type_configs[logtype].set = true; + type_configs[logtype].syslog = true; log_config.syslog_display_options = display_options; - log_config.facility = facility; + log_config.syslog_facility = facility; + + /* Setting default logging? Then set all logtype not set individually */ + if (logtype == logtype_default) { + int typeiter = 0; + while (typeiter != logtype_end_of_list_marker) { + if ( ! (type_configs[typeiter].set)) { + type_configs[typeiter].level = loglevel; + type_configs[typeiter].syslog = true; + } + typeiter++; + } + } log_config.inited = 1; - LOG(log_note, logtype_logger, "Set syslog logging to level: %s", + LOG(log_info, logtype_logger, "Set syslog logging to level: %s", arr_loglevel_strings[loglevel]); } -void log_close(void) +/* + * If filename == NULL its for syslog logging, otherwise its for file-logging. + * "unsetuplog" calls with loglevel == NULL. + * loglevel == NULL means: + * if logtype == default + * disable logging + * else + * set to default logging + */ +static void setuplog_internal(const char *loglevel, const char *logtype, const char *filename) { + unsigned int typenum, levelnum; + + /* Parse logtype */ + for( typenum=0; typenum < num_logtype_strings; typenum++) { + if (strcasecmp(logtype, arr_logtype_strings[typenum]) == 0) + break; + } + if (typenum >= num_logtype_strings) { + return; + } + + /* Parse loglevel */ + if (loglevel == NULL) { + levelnum = 0; + } else { + for(levelnum=1; levelnum < num_loglevel_strings; levelnum++) { + if (strcasecmp(loglevel, arr_loglevel_strings[levelnum]) == 0) + break; + } + if (levelnum >= num_loglevel_strings) { + return; + } + } + + /* is this a syslog setup or a filelog setup ? */ + if (filename == NULL) { + /* must be syslog */ + syslog_setup(levelnum, + typenum, + logoption_ndelay | logoption_pid, + logfacility_daemon); + } else { + /* this must be a filelog */ + log_setup(filename, levelnum, typenum); + } + + return; } +/* ========================================================================= + Global function definitions + ========================================================================= */ + /* This function sets up the processname */ void set_processname(const char *processname) { @@ -378,7 +458,7 @@ void set_processname(const char *processname) So it must be shorter than MAXLOGSIZE ------------------------------------------------------------------------- */ void make_log_entry(enum loglevels loglevel, enum logtypes logtype, - char *message, ...) + const char *file, int line, char *message, ...) { /* fn is not reentrant but is used in signal handler * with LOGGER it's a little late source name and line number @@ -393,20 +473,43 @@ void make_log_entry(enum loglevels loglevel, enum logtypes logtype, if (inlog) return; + inlog = 1; + + if (!log_config.inited) { + log_init(); + } + + if (type_configs[logtype].syslog) { + if (type_configs[logtype].level >= loglevel) { + /* Initialise the Messages and send it to syslog */ + va_start(args, message); + vsnprintf(temp_buffer, MAXLOGSIZE -1, message, args); + va_end(args); + temp_buffer[MAXLOGSIZE -1] = 0; + make_syslog_entry(loglevel, logtype, temp_buffer); + } + inlog = 0; + return; + } + + /* logging to a file */ + + log_src_filename = file; + log_src_linenumber = line; + /* Check if requested logtype is setup */ - if (file_configs[logtype].set) + if (type_configs[logtype].set) /* Yes */ - fd = file_configs[logtype].fd; + fd = type_configs[logtype].fd; else /* No: use default */ - fd = file_configs[logtype_default].fd; + fd = type_configs[logtype_default].fd; if (fd < 0) { /* no where to send the output, give up */ - return; + goto exit; } - inlog = 1; /* Initialise the Messages */ va_start(args, message); len = vsnprintf(temp_buffer, MAXLOGSIZE -1, message, args); @@ -423,102 +526,120 @@ void make_log_entry(enum loglevels loglevel, enum logtypes logtype, temp_buffer[len+1] = 0; } - generate_message_details(log_details_buffer, sizeof(log_details_buffer), - file_configs[logtype].set ? - file_configs[logtype].display_options : - file_configs[logtype_default].display_options, - loglevel, logtype); + if (type_configs[logtype].level >= log_debug) + goto log; /* bypass flooding checks */ + /* Prevent flooding: hash the message and check if we got the same one recently */ + int hash = hash_message(temp_buffer) + log_src_linenumber; - /* If default wasnt setup its fd is -1 */ - iov[0].iov_base = log_details_buffer; - iov[0].iov_len = strlen(log_details_buffer); - iov[1].iov_base = temp_buffer; - iov[1].iov_len = strlen(temp_buffer); - writev( fd, iov, 2); + /* Search for the same message by hash */ + for (int i = log_flood_entries - 1; i >= 0; i--) { + if (log_flood_array[i].hash == hash) { - inlog = 0; -} + /* found same message */ + log_flood_array[i].count++; -/* Called by the LOG macro for syslog messages */ -void make_syslog_entry(enum loglevels loglevel, enum logtypes logtype _U_, char *message, ...) -{ - va_list args; - char log_buffer[MAXLOGSIZE]; - /* fn is not reentrant but is used in signal handler - * with LOGGER it's a little late source name and line number - * are already changed. - */ - static int inlog = 0; + /* Check if that message has reached LOG_FLOODING_MAXCOUNT */ + if (log_flood_array[i].count >= LOG_FLOODING_MAXCOUNT) { + /* yes, log it and remove from array */ - if (inlog) - return; - inlog = 1; + /* reusing log_details_buffer */ + sprintf(log_details_buffer, "message repeated %i times\n", + LOG_FLOODING_MAXCOUNT - 1); + write(fd, log_details_buffer, strlen(log_details_buffer)); - if ( ! (log_config.syslog_opened) ) { - openlog(log_config.processname, log_config.syslog_display_options, - log_config.facility); - log_config.syslog_opened = 1; - } + if ((i + 1) == LOG_FLOODING_ARRAY_SIZE) { + /* last array element, just decrement count */ + log_flood_entries--; + goto exit; + } + /* move array elements down */ + for (int j = i + 1; j != LOG_FLOODING_ARRAY_SIZE ; j++) + log_flood_array[j-1] = log_flood_array[j]; + log_flood_entries--; + } - /* Initialise the Messages */ - va_start(args, message); - vsnprintf(log_buffer, sizeof(log_buffer), message, args); - va_end(args); - log_buffer[MAXLOGSIZE -1] = 0; - syslog(get_syslog_equivalent(loglevel), "%s", log_buffer); + if (log_flood_array[i].count < LOG_FLOODING_MINCOUNT) + /* log it */ + goto log; + /* discard it */ + goto exit; + } /* if */ + } /* for */ + + /* No matching message found, add this message to array*/ + if (log_flood_entries == LOG_FLOODING_ARRAY_SIZE) { + /* array is full, discard oldest entry printing "message repeated..." if count > 1 */ + if (log_flood_array[0].count >= LOG_FLOODING_MINCOUNT) { + /* reusing log_details_buffer */ + sprintf(log_details_buffer, "message repeated %i times\n", + log_flood_array[0].count - LOG_FLOODING_MINCOUNT + 1); + write(fd, log_details_buffer, strlen(log_details_buffer)); + } + for (int i = 1; i < LOG_FLOODING_ARRAY_SIZE; i++) { + log_flood_array[i-1] = log_flood_array[i]; + } + log_flood_entries--; + } + log_flood_array[log_flood_entries].count = 1; + log_flood_array[log_flood_entries].hash = hash; + log_flood_entries++; + +log: + if ( ! log_config.console) { + generate_message_details(log_details_buffer, sizeof(log_details_buffer), + type_configs[logtype].set ? + type_configs[logtype].display_options : + type_configs[logtype_default].display_options, + loglevel, logtype); + + /* If default wasnt setup its fd is -1 */ + iov[0].iov_base = log_details_buffer; + iov[0].iov_len = strlen(log_details_buffer); + iov[1].iov_base = temp_buffer; + iov[1].iov_len = strlen(temp_buffer); + writev( fd, iov, 2); + } else { + write(fd, temp_buffer, strlen(temp_buffer)); + } +exit: inlog = 0; } -void setuplog(const char *logstr) +void setuplog(const char *logstr, const char *logfile) { - char *ptr, *ptrbak, *logtype, *loglevel, *filename; - ptr = strdup(logstr); - ptrbak = ptr; - - /* logtype */ - logtype = ptr; - - /* get loglevel */ - ptr = strpbrk(ptr, " \t"); - if (ptr) { - *ptr++ = 0; - while (*ptr && isspace(*ptr)) - ptr++; - loglevel = ptr; + char *ptr, *save; + char *logtype, *loglevel; + char c; + + save = ptr = strdup(logstr); + + ptr = strtok(ptr, ", "); - /* get filename */ - ptr = strpbrk(ptr, " \t"); - if (ptr) { - *ptr++ = 0; + while (ptr) { + while (*ptr) { while (*ptr && isspace(*ptr)) ptr++; + + logtype = ptr; + ptr = strpbrk(ptr, ":"); + if (!ptr) + break; + *ptr = 0; + + ptr++; + loglevel = ptr; + while (*ptr && !isspace(*ptr)) + ptr++; + c = *ptr; + *ptr = 0; + setuplog_internal(loglevel, logtype, logfile); + *ptr = c; } - filename = ptr; + ptr = strtok(NULL, ", "); } - /* finally call setuplog, filename can be NULL */ - setuplog_internal(loglevel, logtype, filename); - - free(ptrbak); + free(save); } -void unsetuplog(const char *logstr) -{ - char *str, *logtype, *filename; - - str = strdup(logstr); - - /* logtype */ - logtype = str; - - /* get filename, can be NULL */ - strtok(str, " \t"); - filename = strtok(NULL, " \t"); - - /* finally call setuplog, filename can be NULL */ - setuplog_internal(NULL, str, filename); - - free(str); -}