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