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
 318
 319 #else
 320 /*
 321  * '_cups_debug_set()' - Enable or disable debug logging.
 322  */
 323
 324 void
 325 _cups_debug_set(const char *logfile,    /* I - Log file or NULL */
 326                 const char *level,      /* I - Log level or NULL */
 327                 const char *filter,     /* I - Filter string or NULL */
 328                 int        force)       /* I - Force initialization */
 329 {
 330   (void)logfile;
 331   (void)level;
 332   (void)filter;
 333   (void)force;
 334 }
 335 #endif /* DEBUG */
 336
 337
 338 /*
 339  * '_cups_safe_vsnprintf()' - Format a string into a fixed size buffer,
 340  *                            quoting special characters.
 341  */
 342
 343 ssize_t                                 /* O - Number of bytes formatted */
 344 _cups_safe_vsnprintf(
 345     char       *buffer,                 /* O - Output buffer */
 346     size_t     bufsize,                 /* O - Size of output buffer */
 347     const char *format,                 /* I - printf-style format string */
 348     va_list    ap)                      /* I - Pointer to additional arguments */
 349 {
 350   char          *bufptr,                /* Pointer to position in buffer */
 351                 *bufend,                /* Pointer to end of buffer */
 352                 size,                   /* Size character (h, l, L) */
 353                 type;                   /* Format type character */
 354   int           width,                  /* Width of field */
 355                 prec;                   /* Number of characters of precision */
 356   char          tformat[100],           /* Temporary format string for snprintf() */
 357                 *tptr,                  /* Pointer into temporary format */
 358                 temp[1024];             /* Buffer for formatted numbers */
 359   char          *s;                     /* Pointer to string */
 360   ssize_t       bytes;                  /* Total number of bytes needed */
 361
 362
 363   if (!buffer || bufsize < 2 || !format)
 364     return (-1);
 365
 366  /*
 367   * Loop through the format string, formatting as needed...
 368   */
 369
 370   bufptr = buffer;
 371   bufend = buffer + bufsize - 1;
 372   bytes  = 0;
 373
 374   while (*format)
 375   {
 376     if (*format == '%')
 377     {
 378       tptr = tformat;
 379       *tptr++ = *format++;
 380
 381       if (*format == '%')
 382       {
 383         if (bufptr < bufend)
 384           *bufptr++ = *format;
 385         bytes ++;
 386         format ++;
 387         continue;
 388       }
 389       else if (strchr(" -+#\'", *format))
 390         *tptr++ = *format++;
 391
 392       if (*format == '*')
 393       {
 394        /*
 395         * Get width from argument...
 396         */
 397
 398         format ++;
 399         width = va_arg(ap, int);
 400
 401         snprintf(tptr, sizeof(tformat) - (size_t)(tptr - tformat), "%d", width);
 402         tptr += strlen(tptr);
 403       }
 404       else
 405       {
 406         width = 0;
 407
 408         while (isdigit(*format & 255))
 409         {
 410           if (tptr < (tformat + sizeof(tformat) - 1))
 411             *tptr++ = *format;
 412
 413           width = width * 10 + *format++ - '0';
 414         }
 415       }
 416
 417       if (*format == '.')
 418       {
 419         if (tptr < (tformat + sizeof(tformat) - 1))
 420           *tptr++ = *format;
 421
 422         format ++;
 423
 424         if (*format == '*')
 425         {
 426          /*
 427           * Get precision from argument...
 428           */
 429
 430           format ++;
 431           prec = va_arg(ap, int);
 432
 433           snprintf(tptr, sizeof(tformat) - (size_t)(tptr - tformat), "%d", prec);
 434           tptr += strlen(tptr);
 435         }
 436         else
 437         {
 438           prec = 0;
 439
 440           while (isdigit(*format & 255))
 441           {
 442             if (tptr < (tformat + sizeof(tformat) - 1))
 443               *tptr++ = *format;
 444
 445             prec = prec * 10 + *format++ - '0';
 446           }
 447         }
 448       }
 449
 450       if (*format == 'l' && format[1] == 'l')
 451       {
 452         size = 'L';
 453
 454         if (tptr < (tformat + sizeof(tformat) - 2))
 455         {
 456           *tptr++ = 'l';
 457           *tptr++ = 'l';
 458         }
 459
 460         format += 2;
 461       }
 462       else if (*format == 'h' || *format == 'l' || *format == 'L')
 463       {
 464         if (tptr < (tformat + sizeof(tformat) - 1))
 465           *tptr++ = *format;
 466
 467         size = *format++;
 468       }
 469       else
 470         size = 0;
 471
 472       if (!*format)
 473         break;
 474
 475       if (tptr < (tformat + sizeof(tformat) - 1))
 476         *tptr++ = *format;
 477
 478       type  = *format++;
 479       *tptr = '\0';
 480
 481       switch (type)
 482       {
 483         case 'E' : /* Floating point formats */
 484         case 'G' :
 485         case 'e' :
 486         case 'f' :
 487         case 'g' :
 488             if ((size_t)(width + 2) > sizeof(temp))
 489               break;
 490
 491             snprintf(temp, sizeof(temp), tformat, va_arg(ap, double));
 492
 493             bytes += (int)strlen(temp);
 494
 495             if (bufptr)
 496             {
 497               strlcpy(bufptr, temp, (size_t)(bufend - bufptr));
 498               bufptr += strlen(bufptr);
 499             }
 500             break;
 501
 502         case 'B' : /* Integer formats */
 503         case 'X' :
 504         case 'b' :
 505         case 'd' :
 506         case 'i' :
 507         case 'o' :
 508         case 'u' :
 509         case 'x' :
 510             if ((size_t)(width + 2) > sizeof(temp))
 511               break;
 512
 513 #  ifdef HAVE_LONG_LONG
 514             if (size == 'L')
 515               snprintf(temp, sizeof(temp), tformat, va_arg(ap, long long));
 516             else
 517 #  endif /* HAVE_LONG_LONG */
 518             if (size == 'l')
 519               snprintf(temp, sizeof(temp), tformat, va_arg(ap, long));
 520             else
 521               snprintf(temp, sizeof(temp), tformat, va_arg(ap, int));
 522
 523             bytes += (int)strlen(temp);
 524
 525             if (bufptr)
 526             {
 527               strlcpy(bufptr, temp, (size_t)(bufend - bufptr));
 528               bufptr += strlen(bufptr);
 529             }
 530             break;
 531
 532         case 'p' : /* Pointer value */
 533             if ((size_t)(width + 2) > sizeof(temp))
 534               break;
 535
 536             snprintf(temp, sizeof(temp), tformat, va_arg(ap, void *));
 537
 538             bytes += (int)strlen(temp);
 539
 540             if (bufptr)
 541             {
 542               strlcpy(bufptr, temp, (size_t)(bufend - bufptr));
 543               bufptr += strlen(bufptr);
 544             }
 545             break;
 546
 547         case 'c' : /* Character or character array */
 548             bytes += width;
 549
 550             if (bufptr)
 551             {
 552               if (width <= 1)
 553                 *bufptr++ = (char)va_arg(ap, int);
 554               else
 555               {
 556                 if ((bufptr + width) > bufend)
 557                   width = (int)(bufend - bufptr);
 558
 559                 memcpy(bufptr, va_arg(ap, char *), (size_t)width);
 560                 bufptr += width;
 561               }
 562             }
 563             break;
 564
 565         case 's' : /* String */
 566             if ((s = va_arg(ap, char *)) == NULL)
 567               s = "(null)";
 568
 569            /*
 570             * Copy the C string, replacing control chars and \ with
 571             * C character escapes...
 572             */
 573
 574             for (bufend --; *s && bufptr < bufend; s ++)
 575             {
 576               if (*s == '\n')
 577               {
 578                 *bufptr++ = '\\';
 579                 *bufptr++ = 'n';
 580                 bytes += 2;
 581               }
 582               else if (*s == '\r')
 583               {
 584                 *bufptr++ = '\\';
 585                 *bufptr++ = 'r';
 586                 bytes += 2;
 587               }
 588               else if (*s == '\t')
 589               {
 590                 *bufptr++ = '\\';
 591                 *bufptr++ = 't';
 592                 bytes += 2;
 593               }
 594               else if (*s == '\\')
 595               {
 596                 *bufptr++ = '\\';
 597                 *bufptr++ = '\\';
 598                 bytes += 2;
 599               }
 600               else if (*s == '\'')
 601               {
 602                 *bufptr++ = '\\';
 603                 *bufptr++ = '\'';
 604                 bytes += 2;
 605               }
 606               else if (*s == '\"')
 607               {
 608                 *bufptr++ = '\\';
 609                 *bufptr++ = '\"';
 610                 bytes += 2;
 611               }
 612               else if ((*s & 255) < ' ')
 613               {
 614                 if ((bufptr + 2) >= bufend)
 615                   break;
 616
 617                 *bufptr++ = '\\';
 618                 *bufptr++ = '0';
 619                 *bufptr++ = '0' + *s / 8;
 620                 *bufptr++ = '0' + (*s & 7);
 621                 bytes += 4;
 622               }
 623               else
 624               {
 625                 *bufptr++ = *s;
 626                 bytes ++;
 627               }
 628             }
 629
 630             bufend ++;
 631             break;
 632
 633         case 'n' : /* Output number of chars so far */
 634             *(va_arg(ap, int *)) = (int)bytes;
 635             break;
 636       }
 637     }
 638     else
 639     {
 640       bytes ++;
 641
 642       if (bufptr < bufend)
 643         *bufptr++ = *format;
 644
 645       format ++;
 646     }
 647   }
 648
 649  /*
 650   * Nul-terminate the string and return the number of characters needed.
 651   */
 652
 653   *bufptr = '\0';
 654
 655   return (bytes);
 656 }