You can not select more than 25 topics Topics must start with a letter or number, can include dashes ('-') and can be up to 35 characters long.

657 lines
13 KiB

This file contains invisible Unicode characters!

This file contains invisible Unicode characters that may be processed differently from what appears below. If your use case is intentional and legitimate, you can safely ignore this warning. Use the Escape button to reveal hidden characters.

/*
* 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);
}