scheduler/log.c

   1 /*
   2  * "$Id: log.c 6875 2007-08-27 23:25:06Z mike $"
   3  *
   4  *   Log file routines for the Common UNIX Printing System (CUPS).
   5  *
   6  *   Copyright 2007-2008 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  *   cupsdGetDateTime()   - Returns a pointer to a date/time string.
  18  *   cupsdLogGSSMessage() - Log a GSSAPI error...
  19  *   cupsdLogMessage()    - Log a message to the error log file.
  20  *   cupsdLogPage()       - Log a page to the page log file.
  21  *   cupsdLogRequest()    - Log an HTTP request in Common Log Format.
  22  *   check_log_file()     - Open/rotate a log file if it needs it.
  23  */
  24
  25 /*
  26  * Include necessary headers...
  27  */
  28
  29 #include "cupsd.h"
  30 #include <stdarg.h>
  31 #include <syslog.h>
  32
  33
  34 /*
  35  * Local functions...
  36  */
  37
  38 static int      check_log_file(cups_file_t **, const char *);
  39
  40
  41 /*
  42  * 'cupsdGetDateTime()' - Returns a pointer to a date/time string.
  43  */
  44
  45 char *                                  /* O - Date/time string */
  46 cupsdGetDateTime(time_t t)              /* I - Time value */
  47 {
  48   struct tm     *date;                  /* Date/time value */
  49   static time_t last_time = -1;         /* Last time value */
  50   static char   s[1024];                /* Date/time string */
  51   static const char * const months[12] =/* Months */
  52                 {
  53                   "Jan",
  54                   "Feb",
  55                   "Mar",
  56                   "Apr",
  57                   "May",
  58                   "Jun",
  59                   "Jul",
  60                   "Aug",
  61                   "Sep",
  62                   "Oct",
  63                   "Nov",
  64                   "Dec"
  65                 };
  66
  67
  68  /*
  69   * Make sure we have a valid time...
  70   */
  71
  72   if (!t)
  73     t = time(NULL);
  74
  75   if (t != last_time)
  76   {
  77     last_time = t;
  78
  79    /*
  80     * Get the date and time from the UNIX time value, and then format it
  81     * into a string.  Note that we *can't* use the strftime() function since
  82     * it is localized and will seriously confuse automatic programs if the
  83     * month names are in the wrong language!
  84     *
  85     * Also, we use the "timezone" variable that contains the current timezone
  86     * offset from GMT in seconds so that we are reporting local time in the
  87     * log files.  If you want GMT, set the TZ environment variable accordingly
  88     * before starting the scheduler.
  89     *
  90     * (*BSD and Darwin store the timezone offset in the tm structure)
  91     */
  92
  93     date = localtime(&t);
  94
  95     snprintf(s, sizeof(s), "[%02d/%s/%04d:%02d:%02d:%02d %+03ld%02ld]",
  96              date->tm_mday, months[date->tm_mon], 1900 + date->tm_year,
  97              date->tm_hour, date->tm_min, date->tm_sec,
  98 #ifdef HAVE_TM_GMTOFF
  99              date->tm_gmtoff / 3600, (date->tm_gmtoff / 60) % 60);
 100 #else
 101              timezone / 3600, (timezone / 60) % 60);
 102 #endif /* HAVE_TM_GMTOFF */
 103   }
 104
 105   return (s);
 106 }
 107
 108
 109 #ifdef HAVE_GSSAPI
 110 /*
 111  * 'cupsdLogGSSMessage()' - Log a GSSAPI error...
 112  */
 113
 114 int                                     /* O - 1 on success, 0 on error */
 115 cupsdLogGSSMessage(
 116     int        level,                   /* I - Log level */
 117     int        major_status,            /* I - Major GSSAPI status */
 118     int        minor_status,            /* I - Minor GSSAPI status */
 119     const char *message,                /* I - printf-style message string */
 120     ...)                                /* I - Additional args as needed */
 121 {
 122   OM_uint32     err_major_status,       /* Major status code for display */
 123                 err_minor_status;       /* Minor status code for display */
 124   OM_uint32     msg_ctx;                /* Message context */
 125   gss_buffer_desc major_status_string = GSS_C_EMPTY_BUFFER,
 126                                         /* Major status message */
 127                 minor_status_string = GSS_C_EMPTY_BUFFER;
 128                                         /* Minor status message */
 129   int           ret;                    /* Return value */
 130
 131
 132   msg_ctx             = 0;
 133   err_major_status    = gss_display_status(&err_minor_status,
 134                                            major_status,
 135                                            GSS_C_GSS_CODE,
 136                                            GSS_C_NO_OID,
 137                                            &msg_ctx,
 138                                            &major_status_string);
 139
 140   if (!GSS_ERROR(err_major_status))
 141     err_major_status = gss_display_status(&err_minor_status,
 142                                           minor_status,
 143                                           GSS_C_MECH_CODE,
 144                                           GSS_C_NULL_OID,
 145                                           &msg_ctx,
 146                                           &minor_status_string);
 147
 148   ret = cupsdLogMessage(level, "%s: %s, %s", message,
 149                         (char *)major_status_string.value,
 150                         (char *)minor_status_string.value);
 151   gss_release_buffer(&err_minor_status, &major_status_string);
 152   gss_release_buffer(&err_minor_status, &minor_status_string);
 153
 154   return (ret);
 155 }
 156 #endif /* HAVE_GSSAPI */
 157
 158
 159 /*
 160  * 'cupsdLogMessage()' - Log a message to the error log file.
 161  */
 162
 163 int                                     /* O - 1 on success, 0 on error */
 164 cupsdLogMessage(int        level,       /* I - Log level */
 165                 const char *message,    /* I - printf-style message string */
 166                 ...)                    /* I - Additional args as needed */
 167 {
 168   int                   len;            /* Length of message */
 169   va_list               ap;             /* Argument pointer */
 170   static const char     levels[] =      /* Log levels... */
 171                 {
 172                   ' ',
 173                   'X',
 174                   'A',
 175                   'C',
 176                   'E',
 177                   'W',
 178                   'N',
 179                   'I',
 180                   'D',
 181                   'd'
 182                 };
 183 #ifdef HAVE_VSYSLOG
 184   static const int      syslevels[] =   /* SYSLOG levels... */
 185                 {
 186                   0,
 187                   LOG_EMERG,
 188                   LOG_ALERT,
 189                   LOG_CRIT,
 190                   LOG_ERR,
 191                   LOG_WARNING,
 192                   LOG_NOTICE,
 193                   LOG_INFO,
 194                   LOG_DEBUG,
 195                   LOG_DEBUG
 196                 };
 197 #endif /* HAVE_VSYSLOG */
 198   static int            linesize = 0;   /* Size of line for output file */
 199   static char           *line = NULL;   /* Line for output file */
 200
 201
 202  /*
 203   * See if we want to log this message...
 204   */
 205
 206   if (TestConfigFile)
 207   {
 208     if (level <= CUPSD_LOG_WARN)
 209     {
 210       va_start(ap, message);
 211       vfprintf(stderr, message, ap);
 212       putc('\n', stderr);
 213       va_end(ap);
 214     }
 215
 216     return (1);
 217   }
 218
 219   if (level > LogLevel || !ErrorLog)
 220     return (1);
 221
 222 #ifdef HAVE_VSYSLOG
 223  /*
 224   * See if we are logging errors via syslog...
 225   */
 226
 227   if (!strcmp(ErrorLog, "syslog"))
 228   {
 229     va_start(ap, message);
 230     vsyslog(syslevels[level], message, ap);
 231     va_end(ap);
 232
 233     return (1);
 234   }
 235 #endif /* HAVE_VSYSLOG */
 236
 237  /*
 238   * Not using syslog; check the log file...
 239   */
 240
 241   if (!check_log_file(&ErrorFile, ErrorLog))
 242     return (0);
 243
 244  /*
 245   * Print the log level and date/time...
 246   */
 247
 248   cupsFilePrintf(ErrorFile, "%c %s ", levels[level], cupsdGetDateTime(time(NULL)));
 249
 250  /*
 251   * Allocate the line buffer as needed...
 252   */
 253
 254   if (!linesize)
 255   {
 256     linesize = 8192;
 257     line     = malloc(linesize);
 258
 259     if (!line)
 260     {
 261       cupsFilePrintf(ErrorFile,
 262                      "ERROR: Unable to allocate memory for line - %s\n",
 263                      strerror(errno));
 264       cupsFileFlush(ErrorFile);
 265
 266       return (0);
 267     }
 268   }
 269
 270  /*
 271   * Format the log message...
 272   */
 273
 274   va_start(ap, message);
 275   len = vsnprintf(line, linesize, message, ap);
 276   va_end(ap);
 277
 278  /*
 279   * Resize the buffer as needed...
 280   */
 281
 282   if (len >= linesize)
 283   {
 284     char        *temp;                  /* Temporary string pointer */
 285
 286
 287     len ++;
 288
 289     if (len < 8192)
 290       len = 8192;
 291     else if (len > 65536)
 292       len = 65536;
 293
 294     temp = realloc(line, len);
 295
 296     if (temp)
 297     {
 298       line     = temp;
 299       linesize = len;
 300     }
 301
 302     va_start(ap, message);
 303     len = vsnprintf(line, linesize, message, ap);
 304     va_end(ap);
 305   }
 306
 307   if (len >= linesize)
 308     len = linesize - 1;
 309
 310  /*
 311   * Then the log message...
 312   */
 313
 314   cupsFilePuts(ErrorFile, line);
 315
 316  /*
 317   * Then a newline...
 318   */
 319
 320   if (len > 0 && line[len - 1] != '\n')
 321     cupsFilePutChar(ErrorFile, '\n');
 322
 323  /*
 324   * Flush the line to the file and return...
 325   */
 326
 327   cupsFileFlush(ErrorFile);
 328
 329   return (1);
 330 }
 331
 332
 333 /*
 334  * 'cupsdLogPage()' - Log a page to the page log file.
 335  */
 336
 337 int                                     /* O - 1 on success, 0 on error */
 338 cupsdLogPage(cupsd_job_t *job,          /* I - Job being printed */
 339              const char  *page)         /* I - Page being printed */
 340 {
 341   ipp_attribute_t *billing,             /* job-billing attribute */
 342                   *hostname;            /* job-originating-host-name attribute */
 343
 344
 345   billing  = ippFindAttribute(job->attrs, "job-billing", IPP_TAG_ZERO);
 346   hostname = ippFindAttribute(job->attrs, "job-originating-host-name",
 347                               IPP_TAG_ZERO);
 348
 349 #ifdef HAVE_VSYSLOG
 350  /*
 351   * See if we are logging pages via syslog...
 352   */
 353
 354   if (!strcmp(PageLog, "syslog"))
 355   {
 356     syslog(LOG_INFO, "PAGE %s %s %d %s %s %s", job->printer->name,
 357            job->username ? job->username : "-",
 358            job->id, page, billing ? billing->values[0].string.text : "-",
 359            hostname->values[0].string.text);
 360
 361     return (1);
 362   }
 363 #endif /* HAVE_VSYSLOG */
 364
 365  /*
 366   * Not using syslog; check the log file...
 367   */
 368
 369   if (!check_log_file(&PageFile, PageLog))
 370     return (0);
 371
 372  /*
 373   * Print a page log entry of the form:
 374   *
 375   *    printer user job-id [DD/MON/YYYY:HH:MM:SS +TTTT] page num-copies \
 376   *        billing hostname
 377   */
 378
 379   cupsFilePrintf(PageFile, "%s %s %d %s %s %s %s\n", job->printer->name,
 380                  job->username ? job->username : "-",
 381                  job->id, cupsdGetDateTime(time(NULL)), page,
 382                  billing ? billing->values[0].string.text : "-",
 383                  hostname->values[0].string.text);
 384   cupsFileFlush(PageFile);
 385
 386   return (1);
 387 }
 388
 389
 390 /*
 391  * 'cupsdLogRequest()' - Log an HTTP request in Common Log Format.
 392  */
 393
 394 int                                     /* O - 1 on success, 0 on error */
 395 cupsdLogRequest(cupsd_client_t *con,    /* I - Request to log */
 396                 http_status_t  code)    /* I - Response code */
 397 {
 398   char  temp[2048];                     /* Temporary string for URI */
 399   static const char * const states[] =  /* HTTP client states... */
 400                 {
 401                   "WAITING",
 402                   "OPTIONS",
 403                   "GET",
 404                   "GET",
 405                   "HEAD",
 406                   "POST",
 407                   "POST",
 408                   "POST",
 409                   "PUT",
 410                   "PUT",
 411                   "DELETE",
 412                   "TRACE",
 413                   "CLOSE",
 414                   "STATUS"
 415                 };
 416
 417
 418 #ifdef HAVE_VSYSLOG
 419  /*
 420   * See if we are logging accesses via syslog...
 421   */
 422
 423   if (!strcmp(AccessLog, "syslog"))
 424   {
 425     syslog(LOG_INFO,
 426            "REQUEST %s - %s \"%s %s HTTP/%d.%d\" %d " CUPS_LLFMT " %s %s\n",
 427            con->http.hostname, con->username[0] != '\0' ? con->username : "-",
 428            states[con->operation], _httpEncodeURI(temp, con->uri, sizeof(temp)),
 429            con->http.version / 100, con->http.version % 100,
 430            code, CUPS_LLCAST con->bytes,
 431            con->request ?
 432                ippOpString(con->request->request.op.operation_id) : "-",
 433            con->response ?
 434                ippErrorString(con->response->request.status.status_code) : "-");
 435
 436     return (1);
 437   }
 438 #endif /* HAVE_VSYSLOG */
 439
 440  /*
 441   * Not using syslog; check the log file...
 442   */
 443
 444   if (!check_log_file(&AccessFile, AccessLog))
 445     return (0);
 446
 447  /*
 448   * Write a log of the request in "common log format"...
 449   */
 450
 451   cupsFilePrintf(AccessFile,
 452                  "%s - %s %s \"%s %s HTTP/%d.%d\" %d " CUPS_LLFMT " %s %s\n",
 453                  con->http.hostname, con->username[0] != '\0' ? con->username : "-",
 454                  cupsdGetDateTime(con->start), states[con->operation],
 455                  _httpEncodeURI(temp, con->uri, sizeof(temp)),
 456                  con->http.version / 100, con->http.version % 100,
 457                  code, CUPS_LLCAST con->bytes,
 458                  con->request ?
 459                      ippOpString(con->request->request.op.operation_id) : "-",
 460                  con->response ?
 461                      ippErrorString(con->response->request.status.status_code) :
 462                      "-");
 463
 464   cupsFileFlush(AccessFile);
 465
 466   return (1);
 467 }
 468
 469
 470 /*
 471  * 'check_log_file()' - Open/rotate a log file if it needs it.
 472  */
 473
 474 static int                              /* O  - 1 if log file open */
 475 check_log_file(cups_file_t **lf,        /* IO - Log file */
 476                const char  *logname)    /* I  - Log filename */
 477 {
 478   char          backname[1024],         /* Backup log filename */
 479                 filename[1024],         /* Formatted log filename */
 480                 *ptr;                   /* Pointer into filename */
 481   const char    *logptr;                /* Pointer into log filename */
 482
 483
 484  /*
 485   * See if we have a log file to check...
 486   */
 487
 488   if (!lf || !logname || !logname[0])
 489     return (1);
 490
 491  /*
 492   * Format the filename as needed...
 493   */
 494
 495   if (!*lf ||
 496       (strncmp(logname, "/dev/", 5) && cupsFileTell(*lf) > MaxLogSize &&
 497        MaxLogSize > 0))
 498   {
 499    /*
 500     * Handle format strings...
 501     */
 502
 503     filename[sizeof(filename) - 1] = '\0';
 504
 505     if (logname[0] != '/')
 506     {
 507       strlcpy(filename, ServerRoot, sizeof(filename));
 508       strlcat(filename, "/", sizeof(filename));
 509     }
 510     else
 511       filename[0] = '\0';
 512
 513     for (logptr = logname, ptr = filename + strlen(filename);
 514          *logptr && ptr < (filename + sizeof(filename) - 1);
 515          logptr ++)
 516       if (*logptr == '%')
 517       {
 518        /*
 519         * Format spec...
 520         */
 521
 522         logptr ++;
 523         if (*logptr == 's')
 524         {
 525          /*
 526           * Insert the server name...
 527           */
 528
 529           strlcpy(ptr, ServerName, sizeof(filename) - (ptr - filename));
 530           ptr += strlen(ptr);
 531         }
 532         else
 533         {
 534          /*
 535           * Otherwise just insert the character...
 536           */
 537
 538           *ptr++ = *logptr;
 539         }
 540       }
 541       else
 542         *ptr++ = *logptr;
 543
 544     *ptr = '\0';
 545   }
 546
 547  /*
 548   * See if the log file is open...
 549   */
 550
 551   if (!*lf)
 552   {
 553    /*
 554     * Nope, open the log file...
 555     */
 556
 557     if ((*lf = cupsFileOpen(filename, "a")) == NULL)
 558     {
 559      /*
 560       * If the file is in CUPS_LOGDIR then try to create a missing directory...
 561       */
 562
 563       if (!strncmp(filename, CUPS_LOGDIR, strlen(CUPS_LOGDIR)))
 564       {
 565         cupsdCheckPermissions(CUPS_LOGDIR, NULL, 0755, RunUser, Group, 1, -1);
 566
 567         *lf = cupsFileOpen(filename, "a");
 568       }
 569
 570       if (*lf == NULL)
 571       {
 572         syslog(LOG_ERR, "Unable to open log file \"%s\" - %s", filename,
 573                strerror(errno));
 574         return (0);
 575       }
 576     }
 577
 578     if (strncmp(filename, "/dev/", 5))
 579     {
 580      /*
 581       * Change ownership and permissions of non-device logs...
 582       */
 583
 584       fchown(cupsFileNumber(*lf), RunUser, Group);
 585       fchmod(cupsFileNumber(*lf), LogFilePerm);
 586     }
 587   }
 588
 589  /*
 590   * Do we need to rotate the log?
 591   */
 592
 593   if (strncmp(logname, "/dev/", 5) && cupsFileTell(*lf) > MaxLogSize &&
 594       MaxLogSize > 0)
 595   {
 596    /*
 597     * Rotate log file...
 598     */
 599
 600     cupsFileClose(*lf);
 601
 602     strcpy(backname, filename);
 603     strlcat(backname, ".O", sizeof(backname));
 604
 605     unlink(backname);
 606     rename(filename, backname);
 607
 608     if ((*lf = cupsFileOpen(filename, "a")) == NULL)
 609     {
 610       syslog(LOG_ERR, "Unable to open log file \"%s\" - %s", filename,
 611              strerror(errno));
 612
 613       return (0);
 614     }
 615
 616    /*
 617     * Change ownership and permissions of non-device logs...
 618     */
 619
 620     fchown(cupsFileNumber(*lf), RunUser, Group);
 621     fchmod(cupsFileNumber(*lf), LogFilePerm);
 622   }
 623
 624   return (1);
 625 }
 626
 627
 628 /*
 629  * End of "$Id: log.c 6875 2007-08-27 23:25:06Z mike $".
 630  */