scheduler/log.c

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