cups/debug.c

   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 }