]> git.ipfire.org Git - thirdparty/cups.git/blobdiff - scheduler/log.c
Fix lpadmin error reporting for IPP Everywhere printers (Issue #5370)
[thirdparty/cups.git] / scheduler / log.c
index e72e4431b635900692bff8d1b2af0acfda200c68..cdb5437dcf712ace4d0cdcd203bbfef5af4924b6 100644 (file)
@@ -1,16 +1,11 @@
 /*
- * "$Id$"
- *
  * Log file routines for the CUPS scheduler.
  *
- * Copyright 2007-2013 by Apple Inc.
- * Copyright 1997-2007 by Easy Software Products, all rights reserved.
+ * Copyright © 2007-2018 by Apple Inc.
+ * Copyright © 1997-2007 by Easy Software Products, all rights reserved.
  *
- * These coded instructions, statements, and computer programs are the
- * property of Apple Inc. and are protected by Federal copyright
- * law.  Distribution and use rights are outlined in the file "LICENSE.txt"
- * which should have been included with this file.  If this file is
- * file is missing or damaged, see the license at "http://www.cups.org/".
+ * Licensed under Apache License v2.0.  See the file "LICENSE" for more
+ * information.
  */
 
 /*
 
 #include "cupsd.h"
 #include <stdarg.h>
+#ifdef HAVE_ASL_H
+#  include <asl.h>
+#elif defined(HAVE_SYSTEMD_SD_JOURNAL_H)
+#  define SD_JOURNAL_SUPPRESS_LOCATION
+#  include <systemd/sd-journal.h>
+#endif /* HAVE_ASL_H */
 #include <syslog.h>
 
 
+/*
+ * Constants for log keys from PWG 5110.3 (PWG Common Log Format)...
+ */
+
+#define PWG_DeviceUUID                 "DUU"
+#define PWG_Event                      "E"
+#define PWG_LogNaturalLanguage         "NL"
+#define PWG_Status                     "S"
+#define PWG_ServiceURI                 "URI"
+#define PWG_UserHost                   "UH"
+#define PWG_UserName                   "UN"
+#define PWG_UserURI                    "UU"
+#define PWG_ServiceIsAcceptingJobs     "IAJ"
+#define PWG_ServiceState               "ST"
+#define PWG_ServiceStateReasons                "SR"
+#define PWG_ServiceUUID                        "SUU"
+#define PWG_JobID                      "JID"
+#define PWG_JobUUID                    "JUU"
+#define PWG_JobImagesCompleted         "JIM"
+#define PWG_JobImpressionsCompleted    "JIC"
+#define PWG_JobDestinationURI          "JD"
+#define PWG_JobState                   "JS"
+#define PWG_JobStateReasons            "JR"
+#define PWG_JobAccountingID            "JA"
+#define PWG_JobAcountingUserName       "JAUN"
+#define PWG_JobAccountingUserURI       "JAUU"
+
+
 /*
  * Local globals...
  */
 
 static _cups_mutex_t log_mutex = _CUPS_MUTEX_INITIALIZER;
                                        /* Mutex for logging */
-static int     log_linesize = 0;       /* Size of line for output file */
+static size_t  log_linesize = 0;       /* Size of line for output file */
 static char    *log_line = NULL;       /* Line for output file */
 
-#ifdef HAVE_VSYSLOG
-static const int syslevels[] =         /* SYSLOG levels... */
+#ifdef HAVE_ASL_H
+static const int log_levels[] =                /* ASL levels... */
+               {
+                 ASL_LEVEL_EMERG,
+                 ASL_LEVEL_EMERG,
+                 ASL_LEVEL_ALERT,
+                 ASL_LEVEL_CRIT,
+                 ASL_LEVEL_ERR,
+                 ASL_LEVEL_WARNING,
+                 ASL_LEVEL_NOTICE,
+                 ASL_LEVEL_INFO,
+                 ASL_LEVEL_DEBUG,
+                 ASL_LEVEL_DEBUG
+               };
+#elif defined(HAVE_VSYSLOG) || defined(HAVE_SYSTEMD_SD_JOURNAL_H)
+static const int log_levels[] =                /* SYSLOG levels... */
                {
                  0,
                  LOG_EMERG,
@@ -45,7 +88,7 @@ static const int syslevels[] =                /* SYSLOG levels... */
                  LOG_DEBUG,
                  LOG_DEBUG
                };
-#endif /* HAVE_VSYSLOG */
+#endif /* HAVE_ASL_H */
 
 
 /*
@@ -76,6 +119,16 @@ cupsdCheckLogFile(cups_file_t **lf, /* IO - Log file */
   if (!lf || !logname || !logname[0])
     return (1);
 
+ /*
+  * Handle logging to stderr...
+  */
+
+  if (!strcmp(logname, "stderr"))
+  {
+    *lf = LogStderr;
+    return (1);
+  }
+
  /*
   * Format the filename as needed...
   */
@@ -114,7 +167,7 @@ cupsdCheckLogFile(cups_file_t **lf, /* IO - Log file */
          * Insert the server name...
          */
 
-         strlcpy(ptr, ServerName, sizeof(filename) - (ptr - filename));
+         strlcpy(ptr, ServerName, sizeof(filename) - (size_t)(ptr - filename));
          ptr += strlen(ptr);
        }
         else
@@ -155,23 +208,25 @@ cupsdCheckLogFile(cups_file_t **lf,       /* IO - Log file */
        * the log file permissions as a basis...
        */
 
-        int log_dir_perm = 0300 | LogFilePerm;
+        mode_t log_dir_perm = (mode_t)(0300 | LogFilePerm);
                                        /* LogFilePerm + owner write/search */
        if (log_dir_perm & 0040)
          log_dir_perm |= 0010;         /* Add group search */
        if (log_dir_perm & 0004)
          log_dir_perm |= 0001;         /* Add other search */
 
-        cupsdCheckPermissions(CUPS_LOGDIR, NULL, log_dir_perm, RunUser, Group,
-                             1, -1);
+        cupsdCheckPermissions(CUPS_LOGDIR, NULL, log_dir_perm, RunUser, Group, 1, -1);
 
         *lf = cupsFileOpen(filename, "a");
       }
 
       if (*lf == NULL)
       {
-       syslog(LOG_ERR, "Unable to open log file \"%s\" - %s", filename,
-              strerror(errno));
+#ifdef HAVE_SYSTEMD_SD_JOURNAL_H
+        sd_journal_print(LOG_ERR, "Unable to open log file \"%s\" - %s", filename, strerror(errno));
+#else
+       syslog(LOG_ERR, "Unable to open log file \"%s\" - %s", filename, strerror(errno));
+#endif /* HAVE_SYSTEMD_SD_JOURNAL_H */
 
         if (FatalErrors & CUPSD_FATAL_LOG)
          cupsdEndProcess(getpid(), 0);
@@ -212,8 +267,12 @@ cupsdCheckLogFile(cups_file_t **lf,        /* IO - Log file */
 
     if ((*lf = cupsFileOpen(filename, "a")) == NULL)
     {
-      syslog(LOG_ERR, "Unable to open log file \"%s\" - %s", filename,
-             strerror(errno));
+#ifdef HAVE_SYSTEMD_SD_JOURNAL_H
+      sd_journal_print(LOG_ERR, "Unable to open log file \"%s\" - %s", filename, strerror(errno));
+
+#else
+      syslog(LOG_ERR, "Unable to open log file \"%s\" - %s", filename, strerror(errno));
+#endif /* HAVE_SYSTEMD_SD_JOURNAL_H */
 
       if (FatalErrors & CUPSD_FATAL_LOG)
        cupsdEndProcess(getpid(), 0);
@@ -372,8 +431,8 @@ cupsdLogFCMessage(
 int                                    /* O - 1 on success, 0 on error */
 cupsdLogGSSMessage(
     int        level,                  /* I - Log level */
-    int               major_status,            /* I - Major GSSAPI status */
-    int               minor_status,            /* I - Minor GSSAPI status */
+    OM_uint32  major_status,           /* I - Major GSSAPI status */
+    OM_uint32  minor_status,           /* I - Minor GSSAPI status */
     const char *message,               /* I - printf-style message string */
     ...)                               /* I - Additional args as needed */
 {
@@ -503,16 +562,18 @@ cupsdLogJob(cupsd_job_t *job,             /* I - Job */
   if (TestConfigFile || !ErrorLog)
     return (1);
 
-  if ((level > LogLevel ||
-       (level == CUPSD_LOG_INFO && LogLevel < CUPSD_LOG_DEBUG)) &&
-      LogDebugHistory <= 0)
+  if (level > LogLevel && LogDebugHistory <= 0)
     return (1);
 
  /*
   * Format and write the log message...
   */
 
+#ifdef HAVE_SYSTEMD_SD_JOURNAL_H
+  if (job && strcmp(ErrorLog, "syslog"))
+#else
   if (job)
+#endif /* HAVE_SYSTEMD_SD_JOURNAL_H */
     snprintf(jobmsg, sizeof(jobmsg), "[Job %d] %s", job->id, message);
   else
     strlcpy(jobmsg, message, sizeof(jobmsg));
@@ -531,10 +592,7 @@ cupsdLogJob(cupsd_job_t *job,              /* I - Job */
 
   if (status > 0)
   {
-    if (job &&
-        (level > LogLevel ||
-         (level == CUPSD_LOG_INFO && LogLevel < CUPSD_LOG_DEBUG)) &&
-       LogDebugHistory > 0)
+    if (job && level > LogLevel && LogDebugHistory > 0)
     {
      /*
       * Add message to the job history...
@@ -573,9 +631,44 @@ cupsdLogJob(cupsd_job_t *job,              /* I - Job */
 
       return (1);
     }
-    else if (level <= LogLevel &&
-             (level != CUPSD_LOG_INFO || LogLevel >= CUPSD_LOG_DEBUG))
+    else if (level <= LogLevel)
+    {
+#ifdef HAVE_SYSTEMD_SD_JOURNAL_H
+      if (!strcmp(ErrorLog, "syslog"))
+      {
+       cupsd_printer_t *printer = job ? (job->printer ? job->printer : (job->dest ? cupsdFindDest(job->dest) : NULL)) : NULL;
+       static const char * const job_states[] =
+       {                                       /* job-state strings */
+         "Pending",
+         "PendingHeld",
+         "Processing",
+         "ProcessingStopped",
+         "Canceled",
+         "Aborted",
+         "Completed"
+       };
+
+       if (job)
+         sd_journal_send("MESSAGE=%s", log_line,
+                         "PRIORITY=%i", log_levels[level],
+                         PWG_Event"=JobStateChanged",
+                         PWG_ServiceURI"=%s", printer ? printer->uri : "",
+                         PWG_JobID"=%d", job->id,
+                         PWG_JobState"=%s", job->state_value < IPP_JSTATE_PENDING ? "" : job_states[job->state_value - IPP_JSTATE_PENDING],
+                         PWG_JobImpressionsCompleted"=%d", ippGetInteger(job->impressions, 0),
+                         NULL);
+       else
+         sd_journal_send("MESSAGE=%s", log_line,
+                         "PRIORITY=%i", log_levels[level],
+                         NULL);
+
+       return (1);
+      }
+      else
+#endif /* HAVE_SYSTEMD_SD_JOURNAL_H */
+
       return (cupsdWriteErrorLog(level, log_line));
+    }
     else
       return (1);
   }
@@ -602,22 +695,48 @@ cupsdLogMessage(int        level, /* I - Log level */
   * See if we want to log this message...
   */
 
-  if ((TestConfigFile || !ErrorLog) && level <= CUPSD_LOG_WARN)
+  if (TestConfigFile && level <= CUPSD_LOG_WARN)
   {
     va_start(ap, message);
-#ifdef HAVE_VSYSLOG
-    vsyslog(LOG_LPR | syslevels[level], message, ap);
+
+    vfprintf(stderr, message, ap);
+    putc('\n', stderr);
+
+    va_end(ap);
+
+    return (1);
+  }
+  else if (!ErrorLog && level <= CUPSD_LOG_WARN)
+  {
+    va_start(ap, message);
+
+#ifdef HAVE_SYSTEMD_SD_JOURNAL_H
+    sd_journal_printv(log_levels[level], message, ap);
+
+#elif defined(HAVE_VSYSLOG)
+    vsyslog(LOG_LPR | log_levels[level], message, ap);
+
 #else
     vfprintf(stderr, message, ap);
     putc('\n', stderr);
-#endif /* HAVE_VSYSLOG */
+#endif /* HAVE_SYSTEMD_SD_JOURNAL_H */
+
     va_end(ap);
 
     return (1);
   }
+  else if (level > LogLevel || !ErrorLog)
+    return (1);
 
-  if (level > LogLevel || !ErrorLog)
+#ifdef HAVE_SYSTEMD_SD_JOURNAL_H
+  else if (!strcmp(ErrorLog, "syslog"))
+  {
+    va_start(ap, message);
+    sd_journal_printv(log_levels[level], message, ap);
+    va_end(ap);
     return (1);
+  }
+#endif /* HAVE_SYSTEMD_SD_JOURNAL_H */
 
  /*
   * Format and write the log message...
@@ -687,53 +806,68 @@ cupsdLogPage(cupsd_job_t *job,            /* I - Job being printed */
            break;
 
         case 'p' :                     /* Printer name */
-           strlcpy(bufptr, job->printer->name,
-                   sizeof(buffer) - (bufptr - buffer));
+           strlcpy(bufptr, job->dest, sizeof(buffer) - (size_t)(bufptr - buffer));
            bufptr += strlen(bufptr);
            break;
 
         case 'j' :                     /* Job ID */
-           snprintf(bufptr, sizeof(buffer) - (bufptr - buffer), "%d", job->id);
+           snprintf(bufptr, sizeof(buffer) - (size_t)(bufptr - buffer), "%d", job->id);
            bufptr += strlen(bufptr);
            break;
 
         case 'u' :                     /* Username */
-           strlcpy(bufptr, job->username ? job->username : "-",
-                   sizeof(buffer) - (bufptr - buffer));
+           strlcpy(bufptr, job->username ? job->username : "-", sizeof(buffer) - (size_t)(bufptr - buffer));
            bufptr += strlen(bufptr);
            break;
 
         case 'T' :                     /* Date and time */
-           strlcpy(bufptr, cupsdGetDateTime(NULL, LogTimeFormat),
-                   sizeof(buffer) - (bufptr - buffer));
+           strlcpy(bufptr, cupsdGetDateTime(NULL, LogTimeFormat), sizeof(buffer) - (size_t)(bufptr - buffer));
            bufptr += strlen(bufptr);
            break;
 
         case 'P' :                     /* Page number */
-           strlcpy(bufptr, number, sizeof(buffer) - (bufptr - buffer));
+           strlcpy(bufptr, number, sizeof(buffer) - (size_t)(bufptr - buffer));
            bufptr += strlen(bufptr);
            break;
 
         case 'C' :                     /* Number of copies */
-           snprintf(bufptr, sizeof(buffer) - (bufptr - buffer), "%d", copies);
+           snprintf(bufptr, sizeof(buffer) - (size_t)(bufptr - buffer), "%d", copies);
            bufptr += strlen(bufptr);
            break;
 
         case '{' :                     /* {attribute} */
-           if ((nameend = strchr(format, '}')) != NULL &&
-               (nameend - format - 2) < (sizeof(name) - 1))
+           if ((nameend = strchr(format, '}')) != NULL && (size_t)(nameend - format - 2) < (sizeof(name) - 1))
            {
             /*
              * Pull the name from inside the brackets...
              */
 
-             memcpy(name, format + 1, nameend - format - 1);
+             memcpy(name, format + 1, (size_t)(nameend - format - 1));
              name[nameend - format - 1] = '\0';
 
              format = nameend;
 
-             if ((attr = ippFindAttribute(job->attrs, name,
-                                          IPP_TAG_ZERO)) != NULL)
+             attr = ippFindAttribute(job->attrs, name, IPP_TAG_ZERO);
+             if (!attr && !strcmp(name, "job-billing"))
+             {
+              /*
+               * Handle alias "job-account-id" (which was standardized after
+               * "job-billing" was defined for CUPS...
+               */
+
+               attr = ippFindAttribute(job->attrs, "job-account-id", IPP_TAG_ZERO);
+             }
+             else if (!attr && !strcmp(name, "media"))
+             {
+              /*
+               * Handle alias "media-col" which uses dimensions instead of
+               * names...
+               */
+
+               attr = ippFindAttribute(job->attrs, "media-col/media-size", IPP_TAG_BEGIN_COLLECTION);
+             }
+
+             if (attr)
              {
               /*
                * Add the attribute value...
@@ -751,14 +885,12 @@ cupsdLogPage(cupsd_job_t *job,            /* I - Job being printed */
                  {
                    case IPP_TAG_INTEGER :
                    case IPP_TAG_ENUM :
-                       snprintf(bufptr, sizeof(buffer) - (bufptr - buffer),
-                                "%d", attr->values[i].integer);
+                       snprintf(bufptr, sizeof(buffer) - (size_t)(bufptr - buffer), "%d", attr->values[i].integer);
                        bufptr += strlen(bufptr);
                        break;
 
                     case IPP_TAG_BOOLEAN :
-                       snprintf(bufptr, sizeof(buffer) - (bufptr - buffer),
-                                "%d", attr->values[i].boolean);
+                       snprintf(bufptr, sizeof(buffer) - (size_t)(bufptr - buffer), "%d", attr->values[i].boolean);
                        bufptr += strlen(bufptr);
                        break;
 
@@ -772,14 +904,28 @@ cupsdLogPage(cupsd_job_t *job,            /* I - Job being printed */
                    case IPP_TAG_CHARSET :
                    case IPP_TAG_LANGUAGE :
                    case IPP_TAG_MIMETYPE :
-                       strlcpy(bufptr, attr->values[i].string.text,
-                               sizeof(buffer) - (bufptr - buffer));
+                       strlcpy(bufptr, attr->values[i].string.text, sizeof(buffer) - (size_t)(bufptr - buffer));
                        bufptr += strlen(bufptr);
                        break;
 
+                    case IPP_TAG_BEGIN_COLLECTION :
+                       if (!strcmp(attr->name, "media-size"))
+                       {
+                         ipp_attribute_t *x_dimension = ippFindAttribute(ippGetCollection(attr, 0), "x-dimension", IPP_TAG_INTEGER);
+                         ipp_attribute_t *y_dimension = ippFindAttribute(ippGetCollection(attr, 0), "y-dimension", IPP_TAG_INTEGER);
+                                       /* Media dimensions */
+
+                         if (x_dimension && y_dimension)
+                         {
+                           pwg_media_t *pwg = pwgMediaForSize(ippGetInteger(x_dimension, 0), ippGetInteger(y_dimension, 0));
+                                       /* PWG media name */
+                           strlcpy(bufptr, pwg->pwg, sizeof(buffer) - (size_t)(bufptr - buffer));
+                           break;
+                         }
+                       }
+
                    default :
-                       strlcpy(bufptr, "???",
-                               sizeof(buffer) - (bufptr - buffer));
+                       strlcpy(bufptr, "???", sizeof(buffer) - (size_t)(bufptr - buffer));
                        bufptr += strlen(bufptr);
                        break;
                  }
@@ -805,7 +951,32 @@ cupsdLogPage(cupsd_job_t *job,             /* I - Job being printed */
 
   *bufptr = '\0';
 
-#ifdef HAVE_VSYSLOG
+#ifdef HAVE_SYSTEMD_SD_JOURNAL_H
+  if (!strcmp(PageLog, "syslog"))
+  {
+    static const char * const job_states[] =
+    {                                  /* job-state strings */
+      "Pending",
+      "PendingHeld",
+      "Processing",
+      "ProcessingStopped",
+      "Canceled",
+      "Aborted",
+      "Completed"
+    };
+
+    sd_journal_send("MESSAGE=%s", buffer,
+                    "PRIORITY=%i", LOG_INFO,
+                   PWG_Event"=JobStateChanged",
+                   PWG_ServiceURI"=%s", job->printer->uri,
+                   PWG_JobID"=%d", job->id,
+                   PWG_JobState"=%s", job_states[job->state_value - IPP_JSTATE_PENDING],
+                   PWG_JobImpressionsCompleted"=%d", ippGetInteger(job->impressions, 0),
+                   NULL);
+    return (1);
+  }
+
+#elif defined(HAVE_VSYSLOG)
  /*
   * See if we are logging pages via syslog...
   */
@@ -816,7 +987,7 @@ cupsdLogPage(cupsd_job_t *job,              /* I - Job being printed */
 
     return (1);
   }
-#endif /* HAVE_VSYSLOG */
+#endif /* HAVE_SYSTEMD_SD_JOURNAL_H */
 
  /*
   * Not using syslog; check the log file...
@@ -871,7 +1042,9 @@ cupsdLogRequest(cupsd_client_t *con,       /* I - Request to log */
   * Filter requests as needed...
   */
 
-  if (AccessLogLevel < CUPSD_ACCESSLOG_ALL)
+  if (AccessLogLevel == CUPSD_ACCESSLOG_NONE || !AccessLog)
+    return (1);
+  else if (AccessLogLevel < CUPSD_ACCESSLOG_ALL)
   {
    /*
     * Eliminate simple GET, POST, and PUT requests...
@@ -975,7 +1148,14 @@ cupsdLogRequest(cupsd_client_t *con,      /* I - Request to log */
     }
   }
 
-#ifdef HAVE_VSYSLOG
+#ifdef HAVE_SYSTEMD_SD_JOURNAL_H
+  if (!strcmp(AccessLog, "syslog"))
+  {
+    sd_journal_print(LOG_INFO, "REQUEST %s - %s \"%s %s HTTP/%d.%d\" %d " CUPS_LLFMT " %s %s", con->http->hostname, con->username[0] != '\0' ? con->username : "-", states[con->operation], _httpEncodeURI(temp, con->uri, sizeof(temp)), con->http->version / 100, con->http->version % 100, code, CUPS_LLCAST con->bytes, con->request ? ippOpString(con->request->request.op.operation_id) : "-", con->response ? ippErrorString(con->response->request.status.status_code) : "-");
+    return (1);
+  }
+
+#elif defined(HAVE_VSYSLOG)
  /*
   * See if we are logging accesses via syslog...
   */
@@ -995,7 +1175,7 @@ cupsdLogRequest(cupsd_client_t *con,       /* I - Request to log */
 
     return (1);
   }
-#endif /* HAVE_VSYSLOG */
+#endif /* HAVE_SYSTEMD_SD_JOURNAL_H */
 
  /*
   * Not using syslog; check the log file...
@@ -1053,17 +1233,24 @@ cupsdWriteErrorLog(int        level,    /* I - Log level */
                };
 
 
-#ifdef HAVE_VSYSLOG
+#ifdef HAVE_SYSTEMD_SD_JOURNAL_H
+  if (!strcmp(ErrorLog, "syslog"))
+  {
+    sd_journal_print(log_levels[level], "%s", message);
+    return (1);
+  }
+
+#elif defined(HAVE_VSYSLOG)
  /*
   * See if we are logging errors via syslog...
   */
 
   if (!strcmp(ErrorLog, "syslog"))
   {
-    syslog(syslevels[level], "%s", message);
+    syslog(log_levels[level], "%s", message);
     return (1);
   }
-#endif /* HAVE_VSYSLOG */
+#endif /* HAVE_SYSTEMD_SD_JOURNAL_H */
 
  /*
   * Not using syslog; check the log file...
@@ -1104,7 +1291,7 @@ static int                                /* O - -1 for fatal, 0 for retry, 1 for success */
 format_log_line(const char *message,   /* I - Printf-style format string */
                 va_list    ap)         /* I - Argument list */
 {
-  int          len;                    /* Length of formatted line */
+  ssize_t      len;                    /* Length of formatted line */
 
 
  /*
@@ -1124,17 +1311,16 @@ format_log_line(const char *message,    /* I - Printf-style format string */
   * Format the log message...
   */
 
-  len = vsnprintf(log_line, log_linesize, message, ap);
+  len = _cups_safe_vsnprintf(log_line, log_linesize, message, ap);
 
  /*
   * Resize the buffer as needed...
   */
 
-  if (len >= log_linesize && log_linesize < 65536)
+  if ((size_t)len >= log_linesize && log_linesize < 65536)
   {
     char       *temp;                  /* Temporary string pointer */
 
-
     len ++;
 
     if (len < 8192)
@@ -1142,12 +1328,12 @@ format_log_line(const char *message,    /* I - Printf-style format string */
     else if (len > 65536)
       len = 65536;
 
-    temp = realloc(log_line, len);
+    temp = realloc(log_line, (size_t)len);
 
     if (temp)
     {
       log_line     = temp;
-      log_linesize = len;
+      log_linesize = (size_t)len;
 
       return (0);
     }
@@ -1155,8 +1341,3 @@ format_log_line(const char *message,      /* I - Printf-style format string */
 
   return (1);
 }
-
-
-/*
- * End of "$Id$".
- */