cups/debug.c

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