| /* |
| * Debugging functions for CUPS. |
| * |
| * Copyright © 2008-2018 by Apple Inc. |
| * |
| * Licensed under Apache License v2.0. See the file "LICENSE" for more |
| * information. |
| */ |
| |
| /* |
| * Include necessary headers... |
| */ |
| |
| #include "cups-private.h" |
| #include "debug-internal.h" |
| #include "thread-private.h" |
| #ifdef _WIN32 |
| # include <sys/timeb.h> |
| # include <time.h> |
| # include <io.h> |
| # define getpid (int)GetCurrentProcessId |
| int /* O - 0 on success, -1 on failure */ |
| _cups_gettimeofday(struct timeval *tv, /* I - Timeval struct */ |
| void *tz) /* I - Timezone */ |
| { |
| struct _timeb timebuffer; /* Time buffer struct */ |
| _ftime(&timebuffer); |
| tv->tv_sec = (long)timebuffer.time; |
| tv->tv_usec = timebuffer.millitm * 1000; |
| return 0; |
| } |
| #else |
| # include <sys/time.h> |
| # include <unistd.h> |
| #endif /* _WIN32 */ |
| #include <regex.h> |
| #include <fcntl.h> |
| |
| |
| #ifdef DEBUG |
| /* |
| * Globals... |
| */ |
| |
| int _cups_debug_fd = -1; |
| /* Debug log file descriptor */ |
| int _cups_debug_level = 1; |
| /* Log level (0 to 9) */ |
| |
| |
| /* |
| * Local globals... |
| */ |
| |
| static regex_t *debug_filter = NULL; |
| /* Filter expression for messages */ |
| static int debug_init = 0; /* Did we initialize debugging? */ |
| static _cups_mutex_t debug_init_mutex = _CUPS_MUTEX_INITIALIZER, |
| /* Mutex to control initialization */ |
| debug_log_mutex = _CUPS_MUTEX_INITIALIZER; |
| /* Mutex to serialize log entries */ |
| |
| |
| /* |
| * 'debug_thread_id()' - Return an integer representing the current thread. |
| */ |
| |
| static int /* O - Local thread ID */ |
| debug_thread_id(void) |
| { |
| _cups_globals_t *cg = _cupsGlobals(); /* Global data */ |
| |
| |
| return (cg->thread_id); |
| } |
| |
| |
| /* |
| * '_cups_debug_printf()' - Write a formatted line to the log. |
| */ |
| |
| void |
| _cups_debug_printf(const char *format, /* I - Printf-style format string */ |
| ...) /* I - Additional arguments as needed */ |
| { |
| va_list ap; /* Pointer to arguments */ |
| struct timeval curtime; /* Current time */ |
| char buffer[2048]; /* Output buffer */ |
| ssize_t bytes; /* Number of bytes in buffer */ |
| int level; /* Log level in message */ |
| |
| |
| /* |
| * See if we need to do any logging... |
| */ |
| |
| if (!debug_init) |
| _cups_debug_set(getenv("CUPS_DEBUG_LOG"), getenv("CUPS_DEBUG_LEVEL"), |
| getenv("CUPS_DEBUG_FILTER"), 0); |
| |
| if (_cups_debug_fd < 0) |
| return; |
| |
| /* |
| * Filter as needed... |
| */ |
| |
| if (isdigit(format[0])) |
| level = *format++ - '0'; |
| else |
| level = 0; |
| |
| if (level > _cups_debug_level) |
| return; |
| |
| if (debug_filter) |
| { |
| int result; /* Filter result */ |
| |
| _cupsMutexLock(&debug_init_mutex); |
| result = regexec(debug_filter, format, 0, NULL, 0); |
| _cupsMutexUnlock(&debug_init_mutex); |
| |
| if (result) |
| return; |
| } |
| |
| /* |
| * Format the message... |
| */ |
| |
| gettimeofday(&curtime, NULL); |
| snprintf(buffer, sizeof(buffer), "T%03d %02d:%02d:%02d.%03d ", |
| debug_thread_id(), (int)((curtime.tv_sec / 3600) % 24), |
| (int)((curtime.tv_sec / 60) % 60), |
| (int)(curtime.tv_sec % 60), (int)(curtime.tv_usec / 1000)); |
| |
| va_start(ap, format); |
| bytes = _cups_safe_vsnprintf(buffer + 19, sizeof(buffer) - 20, format, ap) + 19; |
| va_end(ap); |
| |
| if ((size_t)bytes >= (sizeof(buffer) - 1)) |
| { |
| buffer[sizeof(buffer) - 2] = '\n'; |
| bytes = sizeof(buffer) - 1; |
| } |
| else if (buffer[bytes - 1] != '\n') |
| { |
| buffer[bytes++] = '\n'; |
| buffer[bytes] = '\0'; |
| } |
| |
| /* |
| * Write it out... |
| */ |
| |
| _cupsMutexLock(&debug_log_mutex); |
| write(_cups_debug_fd, buffer, (size_t)bytes); |
| _cupsMutexUnlock(&debug_log_mutex); |
| } |
| |
| |
| /* |
| * '_cups_debug_puts()' - Write a single line to the log. |
| */ |
| |
| void |
| _cups_debug_puts(const char *s) /* I - String to output */ |
| { |
| struct timeval curtime; /* Current time */ |
| char buffer[2048]; /* Output buffer */ |
| ssize_t bytes; /* Number of bytes in buffer */ |
| int level; /* Log level in message */ |
| |
| |
| /* |
| * See if we need to do any logging... |
| */ |
| |
| if (!debug_init) |
| _cups_debug_set(getenv("CUPS_DEBUG_LOG"), getenv("CUPS_DEBUG_LEVEL"), |
| getenv("CUPS_DEBUG_FILTER"), 0); |
| |
| if (_cups_debug_fd < 0) |
| return; |
| |
| /* |
| * Filter as needed... |
| */ |
| |
| if (isdigit(s[0])) |
| level = *s++ - '0'; |
| else |
| level = 0; |
| |
| if (level > _cups_debug_level) |
| return; |
| |
| if (debug_filter) |
| { |
| int result; /* Filter result */ |
| |
| _cupsMutexLock(&debug_init_mutex); |
| result = regexec(debug_filter, s, 0, NULL, 0); |
| _cupsMutexUnlock(&debug_init_mutex); |
| |
| if (result) |
| return; |
| } |
| |
| /* |
| * Format the message... |
| */ |
| |
| gettimeofday(&curtime, NULL); |
| bytes = snprintf(buffer, sizeof(buffer), "T%03d %02d:%02d:%02d.%03d %s", |
| debug_thread_id(), (int)((curtime.tv_sec / 3600) % 24), |
| (int)((curtime.tv_sec / 60) % 60), |
| (int)(curtime.tv_sec % 60), (int)(curtime.tv_usec / 1000), |
| s); |
| |
| if ((size_t)bytes >= (sizeof(buffer) - 1)) |
| { |
| buffer[sizeof(buffer) - 2] = '\n'; |
| bytes = sizeof(buffer) - 1; |
| } |
| else if (buffer[bytes - 1] != '\n') |
| { |
| buffer[bytes++] = '\n'; |
| buffer[bytes] = '\0'; |
| } |
| |
| /* |
| * Write it out... |
| */ |
| |
| _cupsMutexLock(&debug_log_mutex); |
| write(_cups_debug_fd, buffer, (size_t)bytes); |
| _cupsMutexUnlock(&debug_log_mutex); |
| } |
| |
| |
| /* |
| * '_cups_debug_set()' - Enable or disable debug logging. |
| */ |
| |
| void |
| _cups_debug_set(const char *logfile, /* I - Log file or NULL */ |
| const char *level, /* I - Log level or NULL */ |
| const char *filter, /* I - Filter string or NULL */ |
| int force) /* I - Force initialization */ |
| { |
| _cupsMutexLock(&debug_init_mutex); |
| |
| if (!debug_init || force) |
| { |
| /* |
| * Restore debug settings to defaults... |
| */ |
| |
| if (_cups_debug_fd != -1) |
| { |
| close(_cups_debug_fd); |
| _cups_debug_fd = -1; |
| } |
| |
| if (debug_filter) |
| { |
| regfree((regex_t *)debug_filter); |
| debug_filter = NULL; |
| } |
| |
| _cups_debug_level = 1; |
| |
| /* |
| * Open logs, set log levels, etc. |
| */ |
| |
| if (!logfile) |
| _cups_debug_fd = -1; |
| else if (!strcmp(logfile, "-")) |
| _cups_debug_fd = 2; |
| else |
| { |
| char buffer[1024]; /* Filename buffer */ |
| |
| snprintf(buffer, sizeof(buffer), logfile, getpid()); |
| |
| if (buffer[0] == '+') |
| _cups_debug_fd = open(buffer + 1, O_WRONLY | O_APPEND | O_CREAT, 0644); |
| else |
| _cups_debug_fd = open(buffer, O_WRONLY | O_TRUNC | O_CREAT, 0644); |
| } |
| |
| if (level) |
| _cups_debug_level = atoi(level); |
| |
| if (filter) |
| { |
| if ((debug_filter = (regex_t *)calloc(1, sizeof(regex_t))) == NULL) |
| fputs("Unable to allocate memory for CUPS_DEBUG_FILTER - results not " |
| "filtered!\n", stderr); |
| else if (regcomp(debug_filter, filter, REG_EXTENDED)) |
| { |
| fputs("Bad regular expression in CUPS_DEBUG_FILTER - results not " |
| "filtered!\n", stderr); |
| free(debug_filter); |
| debug_filter = NULL; |
| } |
| } |
| |
| debug_init = 1; |
| } |
| |
| _cupsMutexUnlock(&debug_init_mutex); |
| } |
| |
| |
| #else |
| /* |
| * '_cups_debug_set()' - Enable or disable debug logging. |
| */ |
| |
| void |
| _cups_debug_set(const char *logfile, /* I - Log file or NULL */ |
| const char *level, /* I - Log level or NULL */ |
| const char *filter, /* I - Filter string or NULL */ |
| int force) /* I - Force initialization */ |
| { |
| (void)logfile; |
| (void)level; |
| (void)filter; |
| (void)force; |
| } |
| #endif /* DEBUG */ |
| |
| |
| /* |
| * '_cups_safe_vsnprintf()' - Format a string into a fixed size buffer, |
| * quoting special characters. |
| */ |
| |
| ssize_t /* O - Number of bytes formatted */ |
| _cups_safe_vsnprintf( |
| char *buffer, /* O - Output buffer */ |
| size_t bufsize, /* O - Size of output buffer */ |
| const char *format, /* I - printf-style format string */ |
| va_list ap) /* I - Pointer to additional arguments */ |
| { |
| char *bufptr, /* Pointer to position in buffer */ |
| *bufend, /* Pointer to end of buffer */ |
| size, /* Size character (h, l, L) */ |
| type; /* Format type character */ |
| int width, /* Width of field */ |
| prec; /* Number of characters of precision */ |
| char tformat[100], /* Temporary format string for snprintf() */ |
| *tptr, /* Pointer into temporary format */ |
| temp[1024]; /* Buffer for formatted numbers */ |
| char *s; /* Pointer to string */ |
| ssize_t bytes; /* Total number of bytes needed */ |
| |
| |
| if (!buffer || bufsize < 2 || !format) |
| return (-1); |
| |
| /* |
| * Loop through the format string, formatting as needed... |
| */ |
| |
| bufptr = buffer; |
| bufend = buffer + bufsize - 1; |
| bytes = 0; |
| |
| while (*format) |
| { |
| if (*format == '%') |
| { |
| tptr = tformat; |
| *tptr++ = *format++; |
| |
| if (*format == '%') |
| { |
| if (bufptr < bufend) |
| *bufptr++ = *format; |
| bytes ++; |
| format ++; |
| continue; |
| } |
| else if (strchr(" -+#\'", *format)) |
| *tptr++ = *format++; |
| |
| if (*format == '*') |
| { |
| /* |
| * Get width from argument... |
| */ |
| |
| format ++; |
| width = va_arg(ap, int); |
| |
| snprintf(tptr, sizeof(tformat) - (size_t)(tptr - tformat), "%d", width); |
| tptr += strlen(tptr); |
| } |
| else |
| { |
| width = 0; |
| |
| while (isdigit(*format & 255)) |
| { |
| if (tptr < (tformat + sizeof(tformat) - 1)) |
| *tptr++ = *format; |
| |
| width = width * 10 + *format++ - '0'; |
| } |
| } |
| |
| if (*format == '.') |
| { |
| if (tptr < (tformat + sizeof(tformat) - 1)) |
| *tptr++ = *format; |
| |
| format ++; |
| |
| if (*format == '*') |
| { |
| /* |
| * Get precision from argument... |
| */ |
| |
| format ++; |
| prec = va_arg(ap, int); |
| |
| snprintf(tptr, sizeof(tformat) - (size_t)(tptr - tformat), "%d", prec); |
| tptr += strlen(tptr); |
| } |
| else |
| { |
| prec = 0; |
| |
| while (isdigit(*format & 255)) |
| { |
| if (tptr < (tformat + sizeof(tformat) - 1)) |
| *tptr++ = *format; |
| |
| prec = prec * 10 + *format++ - '0'; |
| } |
| } |
| } |
| |
| if (*format == 'l' && format[1] == 'l') |
| { |
| size = 'L'; |
| |
| if (tptr < (tformat + sizeof(tformat) - 2)) |
| { |
| *tptr++ = 'l'; |
| *tptr++ = 'l'; |
| } |
| |
| format += 2; |
| } |
| else if (*format == 'h' || *format == 'l' || *format == 'L') |
| { |
| if (tptr < (tformat + sizeof(tformat) - 1)) |
| *tptr++ = *format; |
| |
| size = *format++; |
| } |
| else |
| size = 0; |
| |
| if (!*format) |
| break; |
| |
| if (tptr < (tformat + sizeof(tformat) - 1)) |
| *tptr++ = *format; |
| |
| type = *format++; |
| *tptr = '\0'; |
| |
| switch (type) |
| { |
| case 'E' : /* Floating point formats */ |
| case 'G' : |
| case 'e' : |
| case 'f' : |
| case 'g' : |
| if ((size_t)(width + 2) > sizeof(temp)) |
| break; |
| |
| snprintf(temp, sizeof(temp), tformat, va_arg(ap, double)); |
| |
| bytes += (int)strlen(temp); |
| |
| if (bufptr) |
| { |
| strlcpy(bufptr, temp, (size_t)(bufend - bufptr)); |
| bufptr += strlen(bufptr); |
| } |
| break; |
| |
| case 'B' : /* Integer formats */ |
| case 'X' : |
| case 'b' : |
| case 'd' : |
| case 'i' : |
| case 'o' : |
| case 'u' : |
| case 'x' : |
| if ((size_t)(width + 2) > sizeof(temp)) |
| break; |
| |
| # ifdef HAVE_LONG_LONG |
| if (size == 'L') |
| snprintf(temp, sizeof(temp), tformat, va_arg(ap, long long)); |
| else |
| # endif /* HAVE_LONG_LONG */ |
| if (size == 'l') |
| snprintf(temp, sizeof(temp), tformat, va_arg(ap, long)); |
| else |
| snprintf(temp, sizeof(temp), tformat, va_arg(ap, int)); |
| |
| bytes += (int)strlen(temp); |
| |
| if (bufptr) |
| { |
| strlcpy(bufptr, temp, (size_t)(bufend - bufptr)); |
| bufptr += strlen(bufptr); |
| } |
| break; |
| |
| case 'p' : /* Pointer value */ |
| if ((size_t)(width + 2) > sizeof(temp)) |
| break; |
| |
| snprintf(temp, sizeof(temp), tformat, va_arg(ap, void *)); |
| |
| bytes += (int)strlen(temp); |
| |
| if (bufptr) |
| { |
| strlcpy(bufptr, temp, (size_t)(bufend - bufptr)); |
| bufptr += strlen(bufptr); |
| } |
| break; |
| |
| case 'c' : /* Character or character array */ |
| bytes += width; |
| |
| if (bufptr) |
| { |
| if (width <= 1) |
| *bufptr++ = (char)va_arg(ap, int); |
| else |
| { |
| if ((bufptr + width) > bufend) |
| width = (int)(bufend - bufptr); |
| |
| memcpy(bufptr, va_arg(ap, char *), (size_t)width); |
| bufptr += width; |
| } |
| } |
| break; |
| |
| case 's' : /* String */ |
| if ((s = va_arg(ap, char *)) == NULL) |
| s = "(null)"; |
| |
| /* |
| * Copy the C string, replacing control chars and \ with |
| * C character escapes... |
| */ |
| |
| for (bufend --; *s && bufptr < bufend; s ++) |
| { |
| if (*s == '\n') |
| { |
| *bufptr++ = '\\'; |
| *bufptr++ = 'n'; |
| bytes += 2; |
| } |
| else if (*s == '\r') |
| { |
| *bufptr++ = '\\'; |
| *bufptr++ = 'r'; |
| bytes += 2; |
| } |
| else if (*s == '\t') |
| { |
| *bufptr++ = '\\'; |
| *bufptr++ = 't'; |
| bytes += 2; |
| } |
| else if (*s == '\\') |
| { |
| *bufptr++ = '\\'; |
| *bufptr++ = '\\'; |
| bytes += 2; |
| } |
| else if (*s == '\'') |
| { |
| *bufptr++ = '\\'; |
| *bufptr++ = '\''; |
| bytes += 2; |
| } |
| else if (*s == '\"') |
| { |
| *bufptr++ = '\\'; |
| *bufptr++ = '\"'; |
| bytes += 2; |
| } |
| else if ((*s & 255) < ' ') |
| { |
| if ((bufptr + 2) >= bufend) |
| break; |
| |
| *bufptr++ = '\\'; |
| *bufptr++ = '0'; |
| *bufptr++ = '0' + *s / 8; |
| *bufptr++ = '0' + (*s & 7); |
| bytes += 4; |
| } |
| else |
| { |
| *bufptr++ = *s; |
| bytes ++; |
| } |
| } |
| |
| bufend ++; |
| break; |
| |
| case 'n' : /* Output number of chars so far */ |
| *(va_arg(ap, int *)) = (int)bytes; |
| break; |
| } |
| } |
| else |
| { |
| bytes ++; |
| |
| if (bufptr < bufend) |
| *bufptr++ = *format; |
| |
| format ++; |
| } |
| } |
| |
| /* |
| * Nul-terminate the string and return the number of characters needed. |
| */ |
| |
| *bufptr = '\0'; |
| |
| return (bytes); |
| } |