cups/debug.c

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