1/* 2 * "$Id: debug.c 11560 2014-02-06 20:10:19Z msweet $" 3 * 4 * Debugging functions for CUPS. 5 * 6 * Copyright 2008-2014 by Apple Inc. 7 * 8 * These coded instructions, statements, and computer programs are the 9 * property of Apple Inc. and are protected by Federal copyright 10 * law. Distribution and use rights are outlined in the file "LICENSE.txt" 11 * which should have been included with this file. If this file is 12 * file is missing or damaged, see the license at "http://www.cups.org/". 13 * 14 * This file is subject to the Apple OS-Developed Software exception. 15 */ 16 17/* 18 * Include necessary headers... 19 */ 20 21#include "cups-private.h" 22#include "thread-private.h" 23#ifdef WIN32 24# include <sys/timeb.h> 25# include <time.h> 26# include <io.h> 27# define getpid (int)GetCurrentProcessId 28int /* O - 0 on success, -1 on failure */ 29_cups_gettimeofday(struct timeval *tv, /* I - Timeval struct */ 30 void *tz) /* I - Timezone */ 31{ 32 struct _timeb timebuffer; /* Time buffer struct */ 33 _ftime(&timebuffer); 34 tv->tv_sec = (long)timebuffer.time; 35 tv->tv_usec = timebuffer.millitm * 1000; 36 return 0; 37} 38#else 39# include <sys/time.h> 40# include <unistd.h> 41#endif /* WIN32 */ 42#include <regex.h> 43#include <fcntl.h> 44 45 46/* 47 * Globals... 48 */ 49 50int _cups_debug_fd = -1; 51 /* Debug log file descriptor */ 52int _cups_debug_level = 1; 53 /* Log level (0 to 9) */ 54 55 56#ifdef DEBUG 57/* 58 * Local globals... 59 */ 60 61static regex_t *debug_filter = NULL; 62 /* Filter expression for messages */ 63static int debug_init = 0; /* Did we initialize debugging? */ 64static _cups_mutex_t debug_init_mutex = _CUPS_MUTEX_INITIALIZER, 65 /* Mutex to control initialization */ 66 debug_log_mutex = _CUPS_MUTEX_INITIALIZER; 67 /* Mutex to serialize log entries */ 68 69 70/* 71 * 'debug_thread_id()' - Return an integer representing the current thread. 72 */ 73 74static int /* O - Local thread ID */ 75debug_thread_id(void) 76{ 77 _cups_globals_t *cg = _cupsGlobals(); /* Global data */ 78 79 80 return (cg->thread_id); 81} 82 83 84/* 85 * 'debug_vsnprintf()' - Format a string into a fixed size buffer. 86 */ 87 88static ssize_t /* O - Number of bytes formatted */ 89debug_vsnprintf(char *buffer, /* O - Output buffer */ 90 size_t bufsize, /* O - Size of output buffer */ 91 const char *format, /* I - printf-style format string */ 92 va_list ap) /* I - Pointer to additional arguments */ 93{ 94 char *bufptr, /* Pointer to position in buffer */ 95 *bufend, /* Pointer to end of buffer */ 96 size, /* Size character (h, l, L) */ 97 type; /* Format type character */ 98 int width, /* Width of field */ 99 prec; /* Number of characters of precision */ 100 char tformat[100], /* Temporary format string for sprintf() */ 101 *tptr, /* Pointer into temporary format */ 102 temp[1024]; /* Buffer for formatted numbers */ 103 char *s; /* Pointer to string */ 104 ssize_t bytes; /* Total number of bytes needed */ 105 106 107 if (!buffer || bufsize < 2 || !format) 108 return (-1); 109 110 /* 111 * Loop through the format string, formatting as needed... 112 */ 113 114 bufptr = buffer; 115 bufend = buffer + bufsize - 1; 116 bytes = 0; 117 118 while (*format) 119 { 120 if (*format == '%') 121 { 122 tptr = tformat; 123 *tptr++ = *format++; 124 125 if (*format == '%') 126 { 127 if (bufptr < bufend) 128 *bufptr++ = *format; 129 bytes ++; 130 format ++; 131 continue; 132 } 133 else if (strchr(" -+#\'", *format)) 134 *tptr++ = *format++; 135 136 if (*format == '*') 137 { 138 /* 139 * Get width from argument... 140 */ 141 142 format ++; 143 width = va_arg(ap, int); 144 145 snprintf(tptr, sizeof(tformat) - (size_t)(tptr - tformat), "%d", width); 146 tptr += strlen(tptr); 147 } 148 else 149 { 150 width = 0; 151 152 while (isdigit(*format & 255)) 153 { 154 if (tptr < (tformat + sizeof(tformat) - 1)) 155 *tptr++ = *format; 156 157 width = width * 10 + *format++ - '0'; 158 } 159 } 160 161 if (*format == '.') 162 { 163 if (tptr < (tformat + sizeof(tformat) - 1)) 164 *tptr++ = *format; 165 166 format ++; 167 168 if (*format == '*') 169 { 170 /* 171 * Get precision from argument... 172 */ 173 174 format ++; 175 prec = va_arg(ap, int); 176 177 snprintf(tptr, sizeof(tformat) - (size_t)(tptr - tformat), "%d", prec); 178 tptr += strlen(tptr); 179 } 180 else 181 { 182 prec = 0; 183 184 while (isdigit(*format & 255)) 185 { 186 if (tptr < (tformat + sizeof(tformat) - 1)) 187 *tptr++ = *format; 188 189 prec = prec * 10 + *format++ - '0'; 190 } 191 } 192 } 193 194 if (*format == 'l' && format[1] == 'l') 195 { 196 size = 'L'; 197 198 if (tptr < (tformat + sizeof(tformat) - 2)) 199 { 200 *tptr++ = 'l'; 201 *tptr++ = 'l'; 202 } 203 204 format += 2; 205 } 206 else if (*format == 'h' || *format == 'l' || *format == 'L') 207 { 208 if (tptr < (tformat + sizeof(tformat) - 1)) 209 *tptr++ = *format; 210 211 size = *format++; 212 } 213 else 214 size = 0; 215 216 if (!*format) 217 break; 218 219 if (tptr < (tformat + sizeof(tformat) - 1)) 220 *tptr++ = *format; 221 222 type = *format++; 223 *tptr = '\0'; 224 225 switch (type) 226 { 227 case 'E' : /* Floating point formats */ 228 case 'G' : 229 case 'e' : 230 case 'f' : 231 case 'g' : 232 if ((size_t)(width + 2) > sizeof(temp)) 233 break; 234 235 sprintf(temp, tformat, va_arg(ap, double)); 236 237 bytes += (int)strlen(temp); 238 239 if (bufptr) 240 { 241 strlcpy(bufptr, temp, (size_t)(bufend - bufptr)); 242 bufptr += strlen(bufptr); 243 } 244 break; 245 246 case 'B' : /* Integer formats */ 247 case 'X' : 248 case 'b' : 249 case 'd' : 250 case 'i' : 251 case 'o' : 252 case 'u' : 253 case 'x' : 254 if ((size_t)(width + 2) > sizeof(temp)) 255 break; 256 257# ifdef HAVE_LONG_LONG 258 if (size == 'L') 259 sprintf(temp, tformat, va_arg(ap, long long)); 260 else 261# endif /* HAVE_LONG_LONG */ 262 if (size == 'l') 263 sprintf(temp, tformat, va_arg(ap, long)); 264 else 265 sprintf(temp, tformat, va_arg(ap, int)); 266 267 bytes += (int)strlen(temp); 268 269 if (bufptr) 270 { 271 strlcpy(bufptr, temp, (size_t)(bufend - bufptr)); 272 bufptr += strlen(bufptr); 273 } 274 break; 275 276 case 'p' : /* Pointer value */ 277 if ((size_t)(width + 2) > sizeof(temp)) 278 break; 279 280 sprintf(temp, tformat, va_arg(ap, void *)); 281 282 bytes += (int)strlen(temp); 283 284 if (bufptr) 285 { 286 strlcpy(bufptr, temp, (size_t)(bufend - bufptr)); 287 bufptr += strlen(bufptr); 288 } 289 break; 290 291 case 'c' : /* Character or character array */ 292 bytes += width; 293 294 if (bufptr) 295 { 296 if (width <= 1) 297 *bufptr++ = (char)va_arg(ap, int); 298 else 299 { 300 if ((bufptr + width) > bufend) 301 width = (int)(bufend - bufptr); 302 303 memcpy(bufptr, va_arg(ap, char *), (size_t)width); 304 bufptr += width; 305 } 306 } 307 break; 308 309 case 's' : /* String */ 310 if ((s = va_arg(ap, char *)) == NULL) 311 s = "(null)"; 312 313 /* 314 * Copy the C string, replacing control chars and \ with 315 * C character escapes... 316 */ 317 318 for (bufend --; *s && bufptr < bufend; s ++) 319 { 320 if (*s == '\n') 321 { 322 *bufptr++ = '\\'; 323 *bufptr++ = 'n'; 324 bytes += 2; 325 } 326 else if (*s == '\r') 327 { 328 *bufptr++ = '\\'; 329 *bufptr++ = 'r'; 330 bytes += 2; 331 } 332 else if (*s == '\t') 333 { 334 *bufptr++ = '\\'; 335 *bufptr++ = 't'; 336 bytes += 2; 337 } 338 else if (*s == '\\') 339 { 340 *bufptr++ = '\\'; 341 *bufptr++ = '\\'; 342 bytes += 2; 343 } 344 else if (*s == '\'') 345 { 346 *bufptr++ = '\\'; 347 *bufptr++ = '\''; 348 bytes += 2; 349 } 350 else if (*s == '\"') 351 { 352 *bufptr++ = '\\'; 353 *bufptr++ = '\"'; 354 bytes += 2; 355 } 356 else if ((*s & 255) < ' ') 357 { 358 if ((bufptr + 2) >= bufend) 359 break; 360 361 *bufptr++ = '\\'; 362 *bufptr++ = '0'; 363 *bufptr++ = '0' + *s / 8; 364 *bufptr++ = '0' + (*s & 7); 365 bytes += 4; 366 } 367 else 368 { 369 *bufptr++ = *s; 370 bytes ++; 371 } 372 } 373 374 bufend ++; 375 break; 376 377 case 'n' : /* Output number of chars so far */ 378 *(va_arg(ap, int *)) = (int)bytes; 379 break; 380 } 381 } 382 else 383 { 384 bytes ++; 385 386 if (bufptr < bufend) 387 *bufptr++ = *format; 388 389 format ++; 390 } 391 } 392 393 /* 394 * Nul-terminate the string and return the number of characters needed. 395 */ 396 397 *bufptr = '\0'; 398 399 return (bytes); 400} 401 402 403/* 404 * '_cups_debug_printf()' - Write a formatted line to the log. 405 */ 406 407void DLLExport 408_cups_debug_printf(const char *format, /* I - Printf-style format string */ 409 ...) /* I - Additional arguments as needed */ 410{ 411 va_list ap; /* Pointer to arguments */ 412 struct timeval curtime; /* Current time */ 413 char buffer[2048]; /* Output buffer */ 414 ssize_t bytes; /* Number of bytes in buffer */ 415 int level; /* Log level in message */ 416 417 418 /* 419 * See if we need to do any logging... 420 */ 421 422 if (!debug_init) 423 _cups_debug_set(getenv("CUPS_DEBUG_LOG"), getenv("CUPS_DEBUG_LEVEL"), 424 getenv("CUPS_DEBUG_FILTER"), 0); 425 426 if (_cups_debug_fd < 0) 427 return; 428 429 /* 430 * Filter as needed... 431 */ 432 433 if (isdigit(format[0])) 434 level = *format++ - '0'; 435 else 436 level = 0; 437 438 if (level > _cups_debug_level) 439 return; 440 441 if (debug_filter) 442 { 443 int result; /* Filter result */ 444 445 _cupsMutexLock(&debug_init_mutex); 446 result = regexec(debug_filter, format, 0, NULL, 0); 447 _cupsMutexUnlock(&debug_init_mutex); 448 449 if (result) 450 return; 451 } 452 453 /* 454 * Format the message... 455 */ 456 457 gettimeofday(&curtime, NULL); 458 snprintf(buffer, sizeof(buffer), "T%03d %02d:%02d:%02d.%03d ", 459 debug_thread_id(), (int)((curtime.tv_sec / 3600) % 24), 460 (int)((curtime.tv_sec / 60) % 60), 461 (int)(curtime.tv_sec % 60), (int)(curtime.tv_usec / 1000)); 462 463 va_start(ap, format); 464 bytes = debug_vsnprintf(buffer + 19, sizeof(buffer) - 20, format, ap) + 19; 465 va_end(ap); 466 467 if ((size_t)bytes >= (sizeof(buffer) - 1)) 468 { 469 buffer[sizeof(buffer) - 2] = '\n'; 470 bytes = sizeof(buffer) - 1; 471 } 472 else if (buffer[bytes - 1] != '\n') 473 { 474 buffer[bytes++] = '\n'; 475 buffer[bytes] = '\0'; 476 } 477 478 /* 479 * Write it out... 480 */ 481 482 _cupsMutexLock(&debug_log_mutex); 483 write(_cups_debug_fd, buffer, (size_t)bytes); 484 _cupsMutexUnlock(&debug_log_mutex); 485} 486 487 488/* 489 * '_cups_debug_puts()' - Write a single line to the log. 490 */ 491 492void DLLExport 493_cups_debug_puts(const char *s) /* I - String to output */ 494{ 495 struct timeval curtime; /* Current time */ 496 char buffer[2048]; /* Output buffer */ 497 ssize_t bytes; /* Number of bytes in buffer */ 498 int level; /* Log level in message */ 499 500 501 /* 502 * See if we need to do any logging... 503 */ 504 505 if (!debug_init) 506 _cups_debug_set(getenv("CUPS_DEBUG_LOG"), getenv("CUPS_DEBUG_LEVEL"), 507 getenv("CUPS_DEBUG_FILTER"), 0); 508 509 if (_cups_debug_fd < 0) 510 return; 511 512 /* 513 * Filter as needed... 514 */ 515 516 if (isdigit(s[0])) 517 level = *s++ - '0'; 518 else 519 level = 0; 520 521 if (level > _cups_debug_level) 522 return; 523 524 if (debug_filter) 525 { 526 int result; /* Filter result */ 527 528 _cupsMutexLock(&debug_init_mutex); 529 result = regexec(debug_filter, s, 0, NULL, 0); 530 _cupsMutexUnlock(&debug_init_mutex); 531 532 if (result) 533 return; 534 } 535 536 /* 537 * Format the message... 538 */ 539 540 gettimeofday(&curtime, NULL); 541 bytes = snprintf(buffer, sizeof(buffer), "T%03d %02d:%02d:%02d.%03d %s", 542 debug_thread_id(), (int)((curtime.tv_sec / 3600) % 24), 543 (int)((curtime.tv_sec / 60) % 60), 544 (int)(curtime.tv_sec % 60), (int)(curtime.tv_usec / 1000), 545 s); 546 547 if ((size_t)bytes >= (sizeof(buffer) - 1)) 548 { 549 buffer[sizeof(buffer) - 2] = '\n'; 550 bytes = sizeof(buffer) - 1; 551 } 552 else if (buffer[bytes - 1] != '\n') 553 { 554 buffer[bytes++] = '\n'; 555 buffer[bytes] = '\0'; 556 } 557 558 /* 559 * Write it out... 560 */ 561 562 _cupsMutexLock(&debug_log_mutex); 563 write(_cups_debug_fd, buffer, (size_t)bytes); 564 _cupsMutexUnlock(&debug_log_mutex); 565} 566 567 568/* 569 * '_cups_debug_set()' - Enable or disable debug logging. 570 */ 571 572void DLLExport 573_cups_debug_set(const char *logfile, /* I - Log file or NULL */ 574 const char *level, /* I - Log level or NULL */ 575 const char *filter, /* I - Filter string or NULL */ 576 int force) /* I - Force initialization */ 577{ 578 _cupsMutexLock(&debug_init_mutex); 579 580 if (!debug_init || force) 581 { 582 /* 583 * Restore debug settings to defaults... 584 */ 585 586 if (_cups_debug_fd != -1) 587 { 588 close(_cups_debug_fd); 589 _cups_debug_fd = -1; 590 } 591 592 if (debug_filter) 593 { 594 regfree((regex_t *)debug_filter); 595 debug_filter = NULL; 596 } 597 598 _cups_debug_level = 1; 599 600 /* 601 * Open logs, set log levels, etc. 602 */ 603 604 if (!logfile) 605 _cups_debug_fd = -1; 606 else if (!strcmp(logfile, "-")) 607 _cups_debug_fd = 2; 608 else 609 { 610 char buffer[1024]; /* Filename buffer */ 611 612 snprintf(buffer, sizeof(buffer), logfile, getpid()); 613 614 if (buffer[0] == '+') 615 _cups_debug_fd = open(buffer + 1, O_WRONLY | O_APPEND | O_CREAT, 0644); 616 else 617 _cups_debug_fd = open(buffer, O_WRONLY | O_TRUNC | O_CREAT, 0644); 618 } 619 620 if (level) 621 _cups_debug_level = atoi(level); 622 623 if (filter) 624 { 625 if ((debug_filter = (regex_t *)calloc(1, sizeof(regex_t))) == NULL) 626 fputs("Unable to allocate memory for CUPS_DEBUG_FILTER - results not " 627 "filtered!\n", stderr); 628 else if (regcomp(debug_filter, filter, REG_EXTENDED)) 629 { 630 fputs("Bad regular expression in CUPS_DEBUG_FILTER - results not " 631 "filtered!\n", stderr); 632 free(debug_filter); 633 debug_filter = NULL; 634 } 635 } 636 637 debug_init = 1; 638 } 639 640 _cupsMutexUnlock(&debug_init_mutex); 641} 642#endif /* DEBUG */ 643 644 645/* 646 * End of "$Id: debug.c 11560 2014-02-06 20:10:19Z msweet $". 647 */ 648