cups/debug.c

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