scheduler/log.c

   1 /*
   2  * "$Id$"
   3  *
   4  *   Log file routines for the CUPS scheduler.
   5  *
   6  *   Copyright 2007-2012 by Apple Inc.
   7  *   Copyright 1997-2007 by Easy Software Products, all rights reserved.
   8  *
   9  *   These coded instructions, statements, and computer programs are the
  10  *   property of Apple Inc. and are protected by Federal copyright
  11  *   law.  Distribution and use rights are outlined in the file "LICENSE.txt"
  12  *   which should have been included with this file.  If this file is
  13  *   file is missing or damaged, see the license at "http://www.cups.org/".
  14  *
  15  * Contents:
  16  *
  17  *   cupsdCheckLogFile()     - Open/rotate a log file if it needs it.
  18  *   cupsdGetDateTime()   - Returns a pointer to a date/time string.
  19  *   cupsdLogGSSMessage() - Log a GSSAPI error...
  20  *   cupsdLogJob()        - Log a job message.
  21  *   cupsdLogMessage()    - Log a message to the error log file.
  22  *   cupsdLogPage()       - Log a page to the page log file.
  23  *   cupsdLogRequest()    - Log an HTTP request in Common Log Format.
  24  *   cupsdWriteErrorLog() - Write a line to the ErrorLog.
  25  *   format_log_line()    - Format a line for a log file.
  26  */
  27
  28 /*
  29  * Include necessary headers...
  30  */
  31
  32 #include "cupsd.h"
  33 #include <stdarg.h>
  34 #include <syslog.h>
  35
  36
  37 /*
  38  * Local globals...
  39  */
  40
  41 static _cups_mutex_t log_mutex = _CUPS_MUTEX_INITIALIZER;
  42                                         /* Mutex for logging */
  43 static int      log_linesize = 0;       /* Size of line for output file */
  44 static char     *log_line = NULL;       /* Line for output file */
  45
  46 #ifdef HAVE_VSYSLOG
  47 static const int syslevels[] =          /* SYSLOG levels... */
  48                 {
  49                   0,
  50                   LOG_EMERG,
  51                   LOG_ALERT,
  52                   LOG_CRIT,
  53                   LOG_ERR,
  54                   LOG_WARNING,
  55                   LOG_NOTICE,
  56                   LOG_INFO,
  57                   LOG_DEBUG,
  58                   LOG_DEBUG
  59                 };
  60 #endif /* HAVE_VSYSLOG */
  61
  62
  63 /*
  64  * Local functions...
  65  */
  66
  67 static int      format_log_line(const char *message, va_list ap);
  68
  69
  70 /*
  71  * 'cupsdCheckLogFile()' - Open/rotate a log file if it needs it.
  72  */
  73
  74 int                                     /* O  - 1 if log file open */
  75 cupsdCheckLogFile(cups_file_t **lf,     /* IO - Log file */
  76                   const char  *logname) /* I  - Log filename */
  77 {
  78   char          backname[1024],         /* Backup log filename */
  79                 filename[1024],         /* Formatted log filename */
  80                 *ptr;                   /* Pointer into filename */
  81   const char    *logptr;                /* Pointer into log filename */
  82
  83
  84  /*
  85   * See if we have a log file to check...
  86   */
  87
  88   if (!lf || !logname || !logname[0])
  89     return (1);
  90
  91  /*
  92   * Format the filename as needed...
  93   */
  94
  95   if (!*lf ||
  96       (strncmp(logname, "/dev/", 5) && cupsFileTell(*lf) > MaxLogSize &&
  97        MaxLogSize > 0))
  98   {
  99    /*
 100     * Handle format strings...
 101     */
 102
 103     filename[sizeof(filename) - 1] = '\0';
 104
 105     if (logname[0] != '/')
 106     {
 107       strlcpy(filename, ServerRoot, sizeof(filename));
 108       strlcat(filename, "/", sizeof(filename));
 109     }
 110     else
 111       filename[0] = '\0';
 112
 113     for (logptr = logname, ptr = filename + strlen(filename);
 114          *logptr && ptr < (filename + sizeof(filename) - 1);
 115          logptr ++)
 116       if (*logptr == '%')
 117       {
 118        /*
 119         * Format spec...
 120         */
 121
 122         logptr ++;
 123         if (*logptr == 's')
 124         {
 125          /*
 126           * Insert the server name...
 127           */
 128
 129           strlcpy(ptr, ServerName, sizeof(filename) - (ptr - filename));
 130           ptr += strlen(ptr);
 131         }
 132         else
 133         {
 134          /*
 135           * Otherwise just insert the character...
 136           */
 137
 138           *ptr++ = *logptr;
 139         }
 140       }
 141       else
 142         *ptr++ = *logptr;
 143
 144     *ptr = '\0';
 145   }
 146
 147  /*
 148   * See if the log file is open...
 149   */
 150
 151   if (!*lf)
 152   {
 153    /*
 154     * Nope, open the log file...
 155     */
 156
 157     if ((*lf = cupsFileOpen(filename, "a")) == NULL)
 158     {
 159      /*
 160       * If the file is in CUPS_LOGDIR then try to create a missing directory...
 161       */
 162
 163       if (!strncmp(filename, CUPS_LOGDIR, strlen(CUPS_LOGDIR)))
 164       {
 165        /*
 166         * Try updating the permissions of the containing log directory, using
 167         * the log file permissions as a basis...
 168         */
 169
 170         int log_dir_perm = 0300 | LogFilePerm;
 171                                         /* LogFilePerm + owner write/search */
 172         if (log_dir_perm & 0040)
 173           log_dir_perm |= 0010;         /* Add group search */
 174         if (log_dir_perm & 0004)
 175           log_dir_perm |= 0001;         /* Add other search */
 176
 177         cupsdCheckPermissions(CUPS_LOGDIR, NULL, log_dir_perm, RunUser, Group,
 178                               1, -1);
 179
 180         *lf = cupsFileOpen(filename, "a");
 181       }
 182
 183       if (*lf == NULL)
 184       {
 185         syslog(LOG_ERR, "Unable to open log file \"%s\" - %s", filename,
 186                strerror(errno));
 187
 188         if (FatalErrors & CUPSD_FATAL_LOG)
 189           cupsdEndProcess(getpid(), 0);
 190
 191         return (0);
 192       }
 193     }
 194
 195     if (strncmp(filename, "/dev/", 5))
 196     {
 197      /*
 198       * Change ownership and permissions of non-device logs...
 199       */
 200
 201       fchown(cupsFileNumber(*lf), RunUser, Group);
 202       fchmod(cupsFileNumber(*lf), LogFilePerm);
 203     }
 204   }
 205
 206  /*
 207   * Do we need to rotate the log?
 208   */
 209
 210   if (strncmp(logname, "/dev/", 5) && cupsFileTell(*lf) > MaxLogSize &&
 211       MaxLogSize > 0)
 212   {
 213    /*
 214     * Rotate log file...
 215     */
 216
 217     cupsFileClose(*lf);
 218
 219     strlcpy(backname, filename, sizeof(backname));
 220     strlcat(backname, ".O", sizeof(backname));
 221
 222     unlink(backname);
 223     rename(filename, backname);
 224
 225     if ((*lf = cupsFileOpen(filename, "a")) == NULL)
 226     {
 227       syslog(LOG_ERR, "Unable to open log file \"%s\" - %s", filename,
 228              strerror(errno));
 229
 230       if (FatalErrors & CUPSD_FATAL_LOG)
 231         cupsdEndProcess(getpid(), 0);
 232
 233       return (0);
 234     }
 235
 236    /*
 237     * Change ownership and permissions of non-device logs...
 238     */
 239
 240     fchown(cupsFileNumber(*lf), RunUser, Group);
 241     fchmod(cupsFileNumber(*lf), LogFilePerm);
 242   }
 243
 244   return (1);
 245 }
 246
 247
 248 /*
 249  * 'cupsdGetDateTime()' - Returns a pointer to a date/time string.
 250  */
 251
 252 char *                                  /* O - Date/time string */
 253 cupsdGetDateTime(struct timeval *t,     /* I - Time value or NULL for current */
 254                  cupsd_time_t   format) /* I - Format to use */
 255 {
 256   struct timeval        curtime;        /* Current time value */
 257   struct tm             *date;          /* Date/time value */
 258   static struct timeval last_time = { 0, 0 };
 259                                         /* Last time we formatted */
 260   static char           s[1024];        /* Date/time string */
 261   static const char * const months[12] =/* Months */
 262                 {
 263                   "Jan",
 264                   "Feb",
 265                   "Mar",
 266                   "Apr",
 267                   "May",
 268                   "Jun",
 269                   "Jul",
 270                   "Aug",
 271                   "Sep",
 272                   "Oct",
 273                   "Nov",
 274                   "Dec"
 275                 };
 276
 277
 278  /*
 279   * Make sure we have a valid time...
 280   */
 281
 282   if (!t)
 283   {
 284     gettimeofday(&curtime, NULL);
 285     t = &curtime;
 286   }
 287
 288   if (t->tv_sec != last_time.tv_sec ||
 289       (LogTimeFormat == CUPSD_TIME_USECS && t->tv_usec != last_time.tv_usec))
 290   {
 291     last_time = *t;
 292
 293    /*
 294     * Get the date and time from the UNIX time value, and then format it
 295     * into a string.  Note that we *can't* use the strftime() function since
 296     * it is localized and will seriously confuse automatic programs if the
 297     * month names are in the wrong language!
 298     *
 299     * Also, we use the "timezone" variable that contains the current timezone
 300     * offset from GMT in seconds so that we are reporting local time in the
 301     * log files.  If you want GMT, set the TZ environment variable accordingly
 302     * before starting the scheduler.
 303     *
 304     * (*BSD and Darwin store the timezone offset in the tm structure)
 305     */
 306
 307     date = localtime(&(t->tv_sec));
 308
 309     if (format == CUPSD_TIME_STANDARD)
 310       snprintf(s, sizeof(s), "[%02d/%s/%04d:%02d:%02d:%02d %+03ld%02ld]",
 311                date->tm_mday, months[date->tm_mon], 1900 + date->tm_year,
 312                date->tm_hour, date->tm_min, date->tm_sec,
 313 #ifdef HAVE_TM_GMTOFF
 314                date->tm_gmtoff / 3600, (date->tm_gmtoff / 60) % 60);
 315 #else
 316                timezone / 3600, (timezone / 60) % 60);
 317 #endif /* HAVE_TM_GMTOFF */
 318     else
 319       snprintf(s, sizeof(s), "[%02d/%s/%04d:%02d:%02d:%02d.%06d %+03ld%02ld]",
 320                date->tm_mday, months[date->tm_mon], 1900 + date->tm_year,
 321                date->tm_hour, date->tm_min, date->tm_sec, (int)t->tv_usec,
 322 #ifdef HAVE_TM_GMTOFF
 323                date->tm_gmtoff / 3600, (date->tm_gmtoff / 60) % 60);
 324 #else
 325                timezone / 3600, (timezone / 60) % 60);
 326 #endif /* HAVE_TM_GMTOFF */
 327   }
 328
 329   return (s);
 330 }
 331
 332
 333 /*
 334  * 'cupsdLogFCMessage()' - Log a file checking message.
 335  */
 336
 337 void
 338 cupsdLogFCMessage(
 339     void              *context,         /* I - Printer (if any) */
 340     _cups_fc_result_t result,           /* I - Check result */
 341     const char        *message)         /* I - Message to log */
 342 {
 343   cupsd_printer_t       *p = (cupsd_printer_t *)context;
 344                                         /* Printer */
 345   cupsd_loglevel_t      level;          /* Log level */
 346
 347
 348   if (result == _CUPS_FILE_CHECK_OK)
 349     level = CUPSD_LOG_DEBUG2;
 350   else
 351     level = CUPSD_LOG_ERROR;
 352
 353   if (p)
 354   {
 355     cupsdLogMessage(level, "%s: %s", p->name, message);
 356
 357     if (result == _CUPS_FILE_CHECK_MISSING ||
 358         result == _CUPS_FILE_CHECK_WRONG_TYPE)
 359     {
 360       strlcpy(p->state_message, message, sizeof(p->state_message));
 361
 362       if (cupsdSetPrinterReasons(p, "+cups-missing-filter-warning"))
 363         cupsdAddEvent(CUPSD_EVENT_PRINTER_STATE, p, NULL, "%s", message);
 364     }
 365     else if (result == _CUPS_FILE_CHECK_PERMISSIONS ||
 366              result == _CUPS_FILE_CHECK_RELATIVE_PATH)
 367     {
 368       strlcpy(p->state_message, message, sizeof(p->state_message));
 369
 370       if (cupsdSetPrinterReasons(p, "+cups-insecure-filter-warning"))
 371         cupsdAddEvent(CUPSD_EVENT_PRINTER_STATE, p, NULL, "%s", message);
 372     }
 373   }
 374   else
 375     cupsdLogMessage(level, "%s", message);
 376 }
 377
 378
 379 #ifdef HAVE_GSSAPI
 380 /*
 381  * 'cupsdLogGSSMessage()' - Log a GSSAPI error...
 382  */
 383
 384 int                                     /* O - 1 on success, 0 on error */
 385 cupsdLogGSSMessage(
 386     int        level,                   /* I - Log level */
 387     int        major_status,            /* I - Major GSSAPI status */
 388     int        minor_status,            /* I - Minor GSSAPI status */
 389     const char *message,                /* I - printf-style message string */
 390     ...)                                /* I - Additional args as needed */
 391 {
 392   OM_uint32     err_major_status,       /* Major status code for display */
 393                 err_minor_status;       /* Minor status code for display */
 394   OM_uint32     msg_ctx;                /* Message context */
 395   gss_buffer_desc major_status_string = GSS_C_EMPTY_BUFFER,
 396                                         /* Major status message */
 397                 minor_status_string = GSS_C_EMPTY_BUFFER;
 398                                         /* Minor status message */
 399   int           ret;                    /* Return value */
 400   char          buffer[8192];           /* Buffer for vsnprintf */
 401
 402
 403   if (strchr(message, '%'))
 404   {
 405    /*
 406     * Format the message string...
 407     */
 408
 409     va_list     ap;                     /* Pointer to arguments */
 410
 411     va_start(ap, message);
 412     vsnprintf(buffer, sizeof(buffer), message, ap);
 413     va_end(ap);
 414
 415     message = buffer;
 416   }
 417
 418   msg_ctx             = 0;
 419   err_major_status    = gss_display_status(&err_minor_status,
 420                                            major_status,
 421                                            GSS_C_GSS_CODE,
 422                                            GSS_C_NO_OID,
 423                                            &msg_ctx,
 424                                            &major_status_string);
 425
 426   if (!GSS_ERROR(err_major_status))
 427     gss_display_status(&err_minor_status, minor_status, GSS_C_MECH_CODE,
 428                        GSS_C_NULL_OID, &msg_ctx, &minor_status_string);
 429
 430   ret = cupsdLogMessage(level, "%s: %s, %s", message,
 431                         (char *)major_status_string.value,
 432                         (char *)minor_status_string.value);
 433   gss_release_buffer(&err_minor_status, &major_status_string);
 434   gss_release_buffer(&err_minor_status, &minor_status_string);
 435
 436   return (ret);
 437 }
 438 #endif /* HAVE_GSSAPI */
 439
 440
 441 /*
 442  * 'cupsdLogJob()' - Log a job message.
 443  */
 444
 445 int                                     /* O - 1 on success, 0 on error */
 446 cupsdLogJob(cupsd_job_t *job,           /* I - Job */
 447             int         level,          /* I - Log level */
 448             const char  *message,       /* I - Printf-style message string */
 449             ...)                        /* I - Additional arguments as needed */
 450 {
 451   va_list               ap, ap2;        /* Argument pointers */
 452   char                  jobmsg[1024];   /* Format string for job message */
 453   int                   status;         /* Formatting status */
 454
 455
 456  /*
 457   * See if we want to log this message...
 458   */
 459
 460   if (TestConfigFile || !ErrorLog)
 461     return (1);
 462
 463   if ((level > LogLevel ||
 464        (level == CUPSD_LOG_INFO && LogLevel < CUPSD_LOG_DEBUG)) &&
 465       LogDebugHistory <= 0)
 466     return (1);
 467
 468  /*
 469   * Format and write the log message...
 470   */
 471
 472   if (job)
 473     snprintf(jobmsg, sizeof(jobmsg), "[Job %d] %s", job->id, message);
 474   else
 475     strlcpy(jobmsg, message, sizeof(jobmsg));
 476
 477   va_start(ap, message);
 478
 479   do
 480   {
 481     va_copy(ap2, ap);
 482     status = format_log_line(jobmsg, ap2);
 483     va_end(ap2);
 484   }
 485   while (status == 0);
 486
 487   va_end(ap);
 488
 489   if (status > 0)
 490   {
 491     if (job &&
 492         (level > LogLevel ||
 493          (level == CUPSD_LOG_INFO && LogLevel < CUPSD_LOG_DEBUG)) &&
 494         LogDebugHistory > 0)
 495     {
 496      /*
 497       * Add message to the job history...
 498       */
 499
 500       cupsd_joblog_t *temp;             /* Copy of log message */
 501
 502
 503       if ((temp = malloc(sizeof(cupsd_joblog_t) + strlen(log_line))) != NULL)
 504       {
 505         temp->time = time(NULL);
 506         strlcpy(temp->message, log_line, sizeof(temp->message));
 507       }
 508
 509       if (!job->history)
 510         job->history = cupsArrayNew(NULL, NULL);
 511
 512       if (job->history && temp)
 513       {
 514         cupsArrayAdd(job->history, temp);
 515
 516         if (cupsArrayCount(job->history) > LogDebugHistory)
 517         {
 518          /*
 519           * Remove excess messages...
 520           */
 521
 522           temp = cupsArrayFirst(job->history);
 523           cupsArrayRemove(job->history, temp);
 524           free(temp);
 525         }
 526       }
 527       else if (temp)
 528         free(temp);
 529
 530       return (1);
 531     }
 532     else if (level <= LogLevel &&
 533              (level != CUPSD_LOG_INFO || LogLevel >= CUPSD_LOG_DEBUG))
 534       return (cupsdWriteErrorLog(level, log_line));
 535     else
 536       return (1);
 537   }
 538   else
 539     return (cupsdWriteErrorLog(CUPSD_LOG_ERROR,
 540                                "Unable to allocate memory for log line!"));
 541 }
 542
 543
 544 /*
 545  * 'cupsdLogMessage()' - Log a message to the error log file.
 546  */
 547
 548 int                                     /* O - 1 on success, 0 on error */
 549 cupsdLogMessage(int        level,       /* I - Log level */
 550                 const char *message,    /* I - printf-style message string */
 551                 ...)                    /* I - Additional args as needed */
 552 {
 553   va_list               ap, ap2;        /* Argument pointers */
 554   int                   status;         /* Formatting status */
 555
 556
 557  /*
 558   * See if we want to log this message...
 559   */
 560
 561   if ((TestConfigFile || !ErrorLog) && level <= CUPSD_LOG_WARN)
 562   {
 563     va_start(ap, message);
 564 #ifdef HAVE_VSYSLOG
 565     vsyslog(LOG_LPR | syslevels[level], message, ap);
 566 #else
 567     vfprintf(stderr, message, ap);
 568     putc('\n', stderr);
 569 #endif /* HAVE_VSYSLOG */
 570     va_end(ap);
 571
 572     return (1);
 573   }
 574
 575   if (level > LogLevel || !ErrorLog)
 576     return (1);
 577
 578  /*
 579   * Format and write the log message...
 580   */
 581
 582   va_start(ap, message);
 583
 584   do
 585   {
 586     va_copy(ap2, ap);
 587     status = format_log_line(message, ap2);
 588     va_end(ap2);
 589   }
 590   while (status == 0);
 591
 592   va_end(ap);
 593
 594   if (status > 0)
 595     return (cupsdWriteErrorLog(level, log_line));
 596   else
 597     return (cupsdWriteErrorLog(CUPSD_LOG_ERROR,
 598                                "Unable to allocate memory for log line!"));
 599 }
 600
 601
 602 /*
 603  * 'cupsdLogPage()' - Log a page to the page log file.
 604  */
 605
 606 int                                     /* O - 1 on success, 0 on error */
 607 cupsdLogPage(cupsd_job_t *job,          /* I - Job being printed */
 608              const char  *page)         /* I - Page being printed */
 609 {
 610   int                   i;              /* Looping var */
 611   char                  buffer[2048],   /* Buffer for page log */
 612                         *bufptr,        /* Pointer into buffer */
 613                         name[256];      /* Attribute name */
 614   const char            *format,        /* Pointer into PageLogFormat */
 615                         *nameend;       /* End of attribute name */
 616   ipp_attribute_t       *attr;          /* Current attribute */
 617   char                  number[256];    /* Page number */
 618   int                   copies;         /* Number of copies */
 619
 620
 621  /*
 622   * Format the line going into the page log...
 623   */
 624
 625   if (!PageLogFormat)
 626     return (1);
 627
 628   strlcpy(number, "1", sizeof(number));
 629   copies = 1;
 630   sscanf(page, "%255s%d", number, &copies);
 631
 632   for (format = PageLogFormat, bufptr = buffer; *format; format ++)
 633   {
 634     if (*format == '%')
 635     {
 636       format ++;
 637
 638       switch (*format)
 639       {
 640         case '%' :                      /* Literal % */
 641             if (bufptr < (buffer + sizeof(buffer) - 1))
 642               *bufptr++ = '%';
 643             break;
 644
 645         case 'p' :                      /* Printer name */
 646             strlcpy(bufptr, job->printer->name,
 647                     sizeof(buffer) - (bufptr - buffer));
 648             bufptr += strlen(bufptr);
 649             break;
 650
 651         case 'j' :                      /* Job ID */
 652             snprintf(bufptr, sizeof(buffer) - (bufptr - buffer), "%d", job->id);
 653             bufptr += strlen(bufptr);
 654             break;
 655
 656         case 'u' :                      /* Username */
 657             strlcpy(bufptr, job->username ? job->username : "-",
 658                     sizeof(buffer) - (bufptr - buffer));
 659             bufptr += strlen(bufptr);
 660             break;
 661
 662         case 'T' :                      /* Date and time */
 663             strlcpy(bufptr, cupsdGetDateTime(NULL, LogTimeFormat),
 664                     sizeof(buffer) - (bufptr - buffer));
 665             bufptr += strlen(bufptr);
 666             break;
 667
 668         case 'P' :                      /* Page number */
 669             strlcpy(bufptr, number, sizeof(buffer) - (bufptr - buffer));
 670             bufptr += strlen(bufptr);
 671             break;
 672
 673         case 'C' :                      /* Number of copies */
 674             snprintf(bufptr, sizeof(buffer) - (bufptr - buffer), "%d", copies);
 675             bufptr += strlen(bufptr);
 676             break;
 677
 678         case '{' :                      /* {attribute} */
 679             if ((nameend = strchr(format, '}')) != NULL &&
 680                 (nameend - format - 2) < (sizeof(name) - 1))
 681             {
 682              /*
 683               * Pull the name from inside the brackets...
 684               */
 685
 686               memcpy(name, format + 1, nameend - format - 1);
 687               name[nameend - format - 1] = '\0';
 688
 689               format = nameend;
 690
 691               if ((attr = ippFindAttribute(job->attrs, name,
 692                                            IPP_TAG_ZERO)) != NULL)
 693               {
 694                /*
 695                 * Add the attribute value...
 696                 */
 697
 698                 for (i = 0;
 699                      i < attr->num_values &&
 700                          bufptr < (buffer + sizeof(buffer) - 1);
 701                      i ++)
 702                 {
 703                   if (i)
 704                     *bufptr++ = ',';
 705
 706                   switch (attr->value_tag)
 707                   {
 708                     case IPP_TAG_INTEGER :
 709                     case IPP_TAG_ENUM :
 710                         snprintf(bufptr, sizeof(buffer) - (bufptr - buffer),
 711                                  "%d", attr->values[i].integer);
 712                         bufptr += strlen(bufptr);
 713                         break;
 714
 715                     case IPP_TAG_BOOLEAN :
 716                         snprintf(bufptr, sizeof(buffer) - (bufptr - buffer),
 717                                  "%d", attr->values[i].boolean);
 718                         bufptr += strlen(bufptr);
 719                         break;
 720
 721                     case IPP_TAG_TEXTLANG :
 722                     case IPP_TAG_NAMELANG :
 723                     case IPP_TAG_TEXT :
 724                     case IPP_TAG_NAME :
 725                     case IPP_TAG_KEYWORD :
 726                     case IPP_TAG_URI :
 727                     case IPP_TAG_URISCHEME :
 728                     case IPP_TAG_CHARSET :
 729                     case IPP_TAG_LANGUAGE :
 730                     case IPP_TAG_MIMETYPE :
 731                         strlcpy(bufptr, attr->values[i].string.text,
 732                                 sizeof(buffer) - (bufptr - buffer));
 733                         bufptr += strlen(bufptr);
 734                         break;
 735
 736                     default :
 737                         strlcpy(bufptr, "???",
 738                                 sizeof(buffer) - (bufptr - buffer));
 739                         bufptr += strlen(bufptr);
 740                         break;
 741                   }
 742                 }
 743               }
 744               else if (bufptr < (buffer + sizeof(buffer) - 1))
 745                 *bufptr++ = '-';
 746               break;
 747             }
 748
 749         default :
 750             if (bufptr < (buffer + sizeof(buffer) - 2))
 751             {
 752               *bufptr++ = '%';
 753               *bufptr++ = *format;
 754             }
 755             break;
 756       }
 757     }
 758     else if (bufptr < (buffer + sizeof(buffer) - 1))
 759       *bufptr++ = *format;
 760   }
 761
 762   *bufptr = '\0';
 763
 764 #ifdef HAVE_VSYSLOG
 765  /*
 766   * See if we are logging pages via syslog...
 767   */
 768
 769   if (!strcmp(PageLog, "syslog"))
 770   {
 771     syslog(LOG_INFO, "%s", buffer);
 772
 773     return (1);
 774   }
 775 #endif /* HAVE_VSYSLOG */
 776
 777  /*
 778   * Not using syslog; check the log file...
 779   */
 780
 781   if (!cupsdCheckLogFile(&PageFile, PageLog))
 782     return (0);
 783
 784  /*
 785   * Print a page log entry of the form:
 786   *
 787   *    printer user job-id [DD/MON/YYYY:HH:MM:SS +TTTT] page num-copies \
 788   *        billing hostname
 789   */
 790
 791   cupsFilePrintf(PageFile, "%s\n", buffer);
 792   cupsFileFlush(PageFile);
 793
 794   return (1);
 795 }
 796
 797
 798 /*
 799  * 'cupsdLogRequest()' - Log an HTTP request in Common Log Format.
 800  */
 801
 802 int                                     /* O - 1 on success, 0 on error */
 803 cupsdLogRequest(cupsd_client_t *con,    /* I - Request to log */
 804                 http_status_t  code)    /* I - Response code */
 805 {
 806   char  temp[2048];                     /* Temporary string for URI */
 807   static const char * const states[] =  /* HTTP client states... */
 808                 {
 809                   "WAITING",
 810                   "OPTIONS",
 811                   "GET",
 812                   "GET",
 813                   "HEAD",
 814                   "POST",
 815                   "POST",
 816                   "POST",
 817                   "PUT",
 818                   "PUT",
 819                   "DELETE",
 820                   "TRACE",
 821                   "CLOSE",
 822                   "STATUS"
 823                 };
 824
 825
 826  /*
 827   * Filter requests as needed...
 828   */
 829
 830   if (AccessLogLevel < CUPSD_ACCESSLOG_ALL)
 831   {
 832    /*
 833     * Eliminate simple GET, POST, and PUT requests...
 834     */
 835
 836     if ((con->operation == HTTP_GET &&
 837          strncmp(con->uri, "/admin/conf", 11) &&
 838          strncmp(con->uri, "/admin/log", 10)) ||
 839         (con->operation == HTTP_POST && !con->request &&
 840          strncmp(con->uri, "/admin", 6)) ||
 841         (con->operation != HTTP_GET && con->operation != HTTP_POST &&
 842          con->operation != HTTP_PUT))
 843       return (1);
 844
 845     if (con->request && con->response &&
 846         (con->response->request.status.status_code < IPP_REDIRECTION_OTHER_SITE ||
 847          con->response->request.status.status_code == IPP_NOT_FOUND))
 848     {
 849      /*
 850       * Check successful requests...
 851       */
 852
 853       ipp_op_t op = con->request->request.op.operation_id;
 854       static cupsd_accesslog_t standard_ops[] =
 855       {
 856         CUPSD_ACCESSLOG_ALL,    /* reserved */
 857         CUPSD_ACCESSLOG_ALL,    /* reserved */
 858         CUPSD_ACCESSLOG_ACTIONS,/* Print-Job */
 859         CUPSD_ACCESSLOG_ACTIONS,/* Print-URI */
 860         CUPSD_ACCESSLOG_ACTIONS,/* Validate-Job */
 861         CUPSD_ACCESSLOG_ACTIONS,/* Create-Job */
 862         CUPSD_ACCESSLOG_ACTIONS,/* Send-Document */
 863         CUPSD_ACCESSLOG_ACTIONS,/* Send-URI */
 864         CUPSD_ACCESSLOG_ACTIONS,/* Cancel-Job */
 865         CUPSD_ACCESSLOG_ALL,    /* Get-Job-Attributes */
 866         CUPSD_ACCESSLOG_ALL,    /* Get-Jobs */
 867         CUPSD_ACCESSLOG_ALL,    /* Get-Printer-Attributes */
 868         CUPSD_ACCESSLOG_ACTIONS,/* Hold-Job */
 869         CUPSD_ACCESSLOG_ACTIONS,/* Release-Job */
 870         CUPSD_ACCESSLOG_ACTIONS,/* Restart-Job */
 871         CUPSD_ACCESSLOG_ALL,    /* reserved */
 872         CUPSD_ACCESSLOG_CONFIG, /* Pause-Printer */
 873         CUPSD_ACCESSLOG_CONFIG, /* Resume-Printer */
 874         CUPSD_ACCESSLOG_CONFIG, /* Purge-Jobs */
 875         CUPSD_ACCESSLOG_CONFIG, /* Set-Printer-Attributes */
 876         CUPSD_ACCESSLOG_ACTIONS,/* Set-Job-Attributes */
 877         CUPSD_ACCESSLOG_CONFIG, /* Get-Printer-Supported-Values */
 878         CUPSD_ACCESSLOG_ACTIONS,/* Create-Printer-Subscription */
 879         CUPSD_ACCESSLOG_ACTIONS,/* Create-Job-Subscription */
 880         CUPSD_ACCESSLOG_ALL,    /* Get-Subscription-Attributes */
 881         CUPSD_ACCESSLOG_ALL,    /* Get-Subscriptions */
 882         CUPSD_ACCESSLOG_ACTIONS,/* Renew-Subscription */
 883         CUPSD_ACCESSLOG_ACTIONS,/* Cancel-Subscription */
 884         CUPSD_ACCESSLOG_ALL,    /* Get-Notifications */
 885         CUPSD_ACCESSLOG_ACTIONS,/* Send-Notifications */
 886         CUPSD_ACCESSLOG_ALL,    /* reserved */
 887         CUPSD_ACCESSLOG_ALL,    /* reserved */
 888         CUPSD_ACCESSLOG_ALL,    /* reserved */
 889         CUPSD_ACCESSLOG_ALL,    /* Get-Print-Support-Files */
 890         CUPSD_ACCESSLOG_CONFIG, /* Enable-Printer */
 891         CUPSD_ACCESSLOG_CONFIG, /* Disable-Printer */
 892         CUPSD_ACCESSLOG_CONFIG, /* Pause-Printer-After-Current-Job */
 893         CUPSD_ACCESSLOG_ACTIONS,/* Hold-New-Jobs */
 894         CUPSD_ACCESSLOG_ACTIONS,/* Release-Held-New-Jobs */
 895         CUPSD_ACCESSLOG_CONFIG, /* Deactivate-Printer */
 896         CUPSD_ACCESSLOG_CONFIG, /* Activate-Printer */
 897         CUPSD_ACCESSLOG_CONFIG, /* Restart-Printer */
 898         CUPSD_ACCESSLOG_CONFIG, /* Shutdown-Printer */
 899         CUPSD_ACCESSLOG_CONFIG, /* Startup-Printer */
 900         CUPSD_ACCESSLOG_ACTIONS,/* Reprocess-Job */
 901         CUPSD_ACCESSLOG_ACTIONS,/* Cancel-Current-Job */
 902         CUPSD_ACCESSLOG_ACTIONS,/* Suspend-Current-Job */
 903         CUPSD_ACCESSLOG_ACTIONS,/* Resume-Job */
 904         CUPSD_ACCESSLOG_ACTIONS,/* Promote-Job */
 905         CUPSD_ACCESSLOG_ACTIONS /* Schedule-Job-After */
 906       };
 907       static cupsd_accesslog_t cups_ops[] =
 908       {
 909         CUPSD_ACCESSLOG_ALL,    /* CUPS-Get-Default */
 910         CUPSD_ACCESSLOG_ALL,    /* CUPS-Get-Printers */
 911         CUPSD_ACCESSLOG_CONFIG, /* CUPS-Add-Modify-Printer */
 912         CUPSD_ACCESSLOG_CONFIG, /* CUPS-Delete-Printer */
 913         CUPSD_ACCESSLOG_ALL,    /* CUPS-Get-Classes */
 914         CUPSD_ACCESSLOG_CONFIG, /* CUPS-Add-Modify-Class */
 915         CUPSD_ACCESSLOG_CONFIG, /* CUPS-Delete-Class */
 916         CUPSD_ACCESSLOG_CONFIG, /* CUPS-Accept-Jobs */
 917         CUPSD_ACCESSLOG_CONFIG, /* CUPS-Reject-Jobs */
 918         CUPSD_ACCESSLOG_CONFIG, /* CUPS-Set-Default */
 919         CUPSD_ACCESSLOG_CONFIG, /* CUPS-Get-Devices */
 920         CUPSD_ACCESSLOG_CONFIG, /* CUPS-Get-PPDs */
 921         CUPSD_ACCESSLOG_ACTIONS,/* CUPS-Move-Job */
 922         CUPSD_ACCESSLOG_ACTIONS,/* CUPS-Authenticate-Job */
 923         CUPSD_ACCESSLOG_ALL     /* CUPS-Get-PPD */
 924       };
 925
 926
 927       if ((op <= IPP_SCHEDULE_JOB_AFTER && standard_ops[op] > AccessLogLevel) ||
 928           (op >= CUPS_GET_DEFAULT && op <= CUPS_GET_PPD &&
 929            cups_ops[op - CUPS_GET_DEFAULT] > AccessLogLevel))
 930         return (1);
 931     }
 932   }
 933
 934 #ifdef HAVE_VSYSLOG
 935  /*
 936   * See if we are logging accesses via syslog...
 937   */
 938
 939   if (!strcmp(AccessLog, "syslog"))
 940   {
 941     syslog(LOG_INFO,
 942            "REQUEST %s - %s \"%s %s HTTP/%d.%d\" %d " CUPS_LLFMT " %s %s\n",
 943            con->http.hostname, con->username[0] != '\0' ? con->username : "-",
 944            states[con->operation], _httpEncodeURI(temp, con->uri, sizeof(temp)),
 945            con->http.version / 100, con->http.version % 100,
 946            code, CUPS_LLCAST con->bytes,
 947            con->request ?
 948                ippOpString(con->request->request.op.operation_id) : "-",
 949            con->response ?
 950                ippErrorString(con->response->request.status.status_code) : "-");
 951
 952     return (1);
 953   }
 954 #endif /* HAVE_VSYSLOG */
 955
 956  /*
 957   * Not using syslog; check the log file...
 958   */
 959
 960   if (!cupsdCheckLogFile(&AccessFile, AccessLog))
 961     return (0);
 962
 963  /*
 964   * Write a log of the request in "common log format"...
 965   */
 966
 967   cupsFilePrintf(AccessFile,
 968                  "%s - %s %s \"%s %s HTTP/%d.%d\" %d " CUPS_LLFMT " %s %s\n",
 969                  con->http.hostname,
 970                  con->username[0] != '\0' ? con->username : "-",
 971                  cupsdGetDateTime(&(con->start), LogTimeFormat),
 972                  states[con->operation],
 973                  _httpEncodeURI(temp, con->uri, sizeof(temp)),
 974                  con->http.version / 100, con->http.version % 100,
 975                  code, CUPS_LLCAST con->bytes,
 976                  con->request ?
 977                      ippOpString(con->request->request.op.operation_id) : "-",
 978                  con->response ?
 979                      ippErrorString(con->response->request.status.status_code) :
 980                      "-");
 981
 982   cupsFileFlush(AccessFile);
 983
 984   return (1);
 985 }
 986
 987
 988 /*
 989  * 'cupsdWriteErrorLog()' - Write a line to the ErrorLog.
 990  */
 991
 992 int                                     /* O - 1 on success, 0 on failure */
 993 cupsdWriteErrorLog(int        level,    /* I - Log level */
 994                    const char *message) /* I - Message string */
 995 {
 996   int           ret = 1;                /* Return value */
 997   static const char     levels[] =      /* Log levels... */
 998                 {
 999                   ' ',
1000                   'X',
1001                   'A',
1002                   'C',
1003                   'E',
1004                   'W',
1005                   'N',
1006                   'I',
1007                   'D',
1008                   'd'
1009                 };
1010
1011
1012 #ifdef HAVE_VSYSLOG
1013  /*
1014   * See if we are logging errors via syslog...
1015   */
1016
1017   if (!strcmp(ErrorLog, "syslog"))
1018   {
1019     syslog(syslevels[level], "%s", message);
1020     return (1);
1021   }
1022 #endif /* HAVE_VSYSLOG */
1023
1024  /*
1025   * Not using syslog; check the log file...
1026   */
1027
1028   _cupsMutexLock(&log_mutex);
1029
1030   if (!cupsdCheckLogFile(&ErrorFile, ErrorLog))
1031   {
1032     ret = 0;
1033   }
1034   else
1035   {
1036    /*
1037     * Write the log message...
1038     */
1039
1040     cupsFilePrintf(ErrorFile, "%c %s %s\n", levels[level],
1041                    cupsdGetDateTime(NULL, LogTimeFormat), message);
1042     cupsFileFlush(ErrorFile);
1043   }
1044
1045   _cupsMutexUnlock(&log_mutex);
1046
1047   return (ret);
1048 }
1049
1050
1051 /*
1052  * 'format_log_line()' - Format a line for a log file.
1053  *
1054  * This function resizes a global string buffer as needed.  Each call returns
1055  * a pointer to this buffer, so the contents are only good until the next call
1056  * to format_log_line()...
1057  */
1058
1059 static int                              /* O - -1 for fatal, 0 for retry, 1 for success */
1060 format_log_line(const char *message,    /* I - Printf-style format string */
1061                 va_list    ap)          /* I - Argument list */
1062 {
1063   int           len;                    /* Length of formatted line */
1064
1065
1066  /*
1067   * Allocate the line buffer as needed...
1068   */
1069
1070   if (!log_linesize)
1071   {
1072     log_linesize = 8192;
1073     log_line     = malloc(log_linesize);
1074
1075     if (!log_line)
1076       return (-1);
1077   }
1078
1079  /*
1080   * Format the log message...
1081   */
1082
1083   len = vsnprintf(log_line, log_linesize, message, ap);
1084
1085  /*
1086   * Resize the buffer as needed...
1087   */
1088
1089   if (len >= log_linesize && log_linesize < 65536)
1090   {
1091     char        *temp;                  /* Temporary string pointer */
1092
1093
1094     len ++;
1095
1096     if (len < 8192)
1097       len = 8192;
1098     else if (len > 65536)
1099       len = 65536;
1100
1101     temp = realloc(log_line, len);
1102
1103     if (temp)
1104     {
1105       log_line     = temp;
1106       log_linesize = len;
1107
1108       return (0);
1109     }
1110   }
1111
1112   return (1);
1113 }
1114
1115
1116 /*
1117  * End of "$Id$".
1118  */