cups/debug.c

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