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