cups/debug.c

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