]> git.ipfire.org Git - thirdparty/cups.git/blobdiff - scheduler/job.c
Merge changes from CUPS 1.4svn-r8628.
[thirdparty/cups.git] / scheduler / job.c
index b947d58ca9561432484183d42d86586fea4d6beb..7f3fa355fe21bbe15b84edc5ffcdfa3ea106a6ca 100644 (file)
@@ -45,6 +45,8 @@
  *   compare_active_jobs()      - Compare the job IDs and priorities of two
  *                                jobs.
  *   compare_jobs()             - Compare the job IDs of two jobs.
+ *   dump_job_history()         - Dump any debug messages for a job.
+ *   free_job_history()         - Free any log history.
  *   finalize_job()             - Cleanup after job filter processes and support
  *                                data.
  *   get_options()              - Get a string containing the job options.
@@ -165,7 +167,9 @@ static mime_filter_t        gziptoany_filter =
 
 static int     compare_active_jobs(void *first, void *second, void *data);
 static int     compare_jobs(void *first, void *second, void *data);
+static void    dump_job_history(cupsd_job_t *job);
 static void    finalize_job(cupsd_job_t *job);
+static void    free_job_history(cupsd_job_t *job);
 static char    *get_options(cupsd_job_t *job, int banner_page, char *copies,
                             size_t copies_size, char *title,
                             size_t title_size);
@@ -271,23 +275,36 @@ cupsdCheckJobs(void)
   cupsd_printer_t      *printer,       /* Printer destination */
                        *pclass;        /* Printer class destination */
   ipp_attribute_t      *attr;          /* Job attribute */
+  time_t               curtime;        /* Current time */
 
 
   cupsdLogMessage(CUPSD_LOG_DEBUG2,
                   "cupsdCheckJobs: %d active jobs, sleeping=%d, reload=%d",
                   cupsArrayCount(ActiveJobs), Sleeping, NeedReload);
 
+  curtime = time(NULL);
+
   for (job = (cupsd_job_t *)cupsArrayFirst(ActiveJobs);
        job;
        job = (cupsd_job_t *)cupsArrayNext(ActiveJobs))
   {
+   /*
+    * Kill jobs if they are unresponsive...
+    */
+
+    if (job->kill_time && job->kill_time <= curtime)
+    {
+      stop_job(job, CUPSD_JOB_FORCE);
+      continue;
+    }
+
    /*
     * Start held jobs if they are ready...
     */
 
     if (job->state_value == IPP_JOB_HELD &&
         job->hold_until &&
-       job->hold_until < time(NULL))
+       job->hold_until < curtime)
     {
       if (job->pending_timeout)
       {
@@ -318,6 +335,14 @@ cupsdCheckJobs(void)
                        "Job submission timed out.");
     }
 
+   /*
+    * Continue jobs that are waiting on the FilterLimit...
+    */
+
+    if (job->pending_cost > 0 &&
+       ((FilterLevel + job->pending_cost) < FilterLimit || FilterLevel == 0))
+      cupsdContinueJob(job);
+
    /*
     * Start pending jobs if the destination is available...
     */
@@ -428,7 +453,7 @@ cupsdContinueJob(cupsd_job_t *job)  /* I - Job */
 {
   int                  i;              /* Looping var */
   int                  slot;           /* Pipe slot */
-  cups_array_t         *filters,       /* Filters for job */
+  cups_array_t         *filters = NULL,/* Filters for job */
                        *prefilters;    /* Filters with prefilters */
   mime_filter_t                *filter,        /* Current filter */
                        *prefilter,     /* Prefilter */
@@ -437,13 +462,16 @@ cupsdContinueJob(cupsd_job_t *job)        /* I - Job */
   ipp_attribute_t      *attr;          /* Current attribute */
   const char           *ptr,           /* Pointer into value */
                        *abort_message; /* Abort message */
+  ipp_jstate_t         abort_state = IPP_JOB_STOPPED;
+                                       /* New job state on abort */
   struct stat          backinfo;       /* Backend file information */
   int                  backroot;       /* Run backend as root? */
   int                  pid;            /* Process ID of new filter process */
   int                  banner_page;    /* 1 if banner page, 0 otherwise */
-  int                  filterfds[2][2];/* Pipes used between filters */
+  int                  filterfds[2][2] = { { -1, -1 }, { -1, -1 } };
+                                       /* Pipes used between filters */
   int                  envc;           /* Number of environment variables */
-  char                 **argv,         /* Filter command-line arguments */
+  char                 **argv = NULL,  /* Filter command-line arguments */
                        filename[1024], /* Job filename */
                        command[1024],  /* Full path to command */
                        jobid[255],     /* Job ID string */
@@ -490,7 +518,11 @@ cupsdContinueJob(cupsd_job_t *job) /* I - Job */
 
   FilterLevel -= job->cost;
 
-  filters = NULL;
+  job->cost         = 0;
+  job->pending_cost = 0;
+
+  memset(job->filters, 0, sizeof(job->filters));
+
 
   if (job->printer->raw)
   {
@@ -500,8 +532,6 @@ cupsdContinueJob(cupsd_job_t *job)  /* I - Job */
     */
 
     cupsdLogJob(job, CUPSD_LOG_DEBUG, "Sending job to queue tagged as raw...");
-
-    filters = NULL;
   }
   else
   {
@@ -518,13 +548,10 @@ cupsdContinueJob(cupsd_job_t *job)        /* I - Job */
                  "Unable to convert file %d to printable format!",
                  job->current_file);
 
-      job->current_file ++;
+      abort_message = "Aborting job because it cannot be printed.";
+      abort_state   = IPP_JOB_ABORTED;
 
-      if (job->current_file == job->num_files)
-        cupsdSetJobState(job, IPP_JOB_ABORTED, CUPSD_JOB_DEFAULT,
-                        "Aborting job because it cannot be printed.");
-
-      return;
+      goto abort_job;
     }
 
    /*
@@ -598,6 +625,9 @@ cupsdContinueJob(cupsd_job_t *job)  /* I - Job */
                "cupsdContinueJob: file=%d, cost=%d, level=%d, limit=%d",
                job->current_file, job->cost, FilterLevel,
                FilterLimit);
+
+    job->pending_cost = job->cost;
+    job->cost         = 0;
     return;
   }
 
@@ -625,12 +655,9 @@ cupsdContinueJob(cupsd_job_t *job) /* I - Job */
 
       cupsArrayDelete(filters);
 
-      cupsdSetJobState(job, IPP_JOB_STOPPED, CUPSD_JOB_DEFAULT,
-                      "Stopping job because the scheduler ran out of "
-                      "memory.");
+      abort_message = "Stopping job because the scheduler ran out of memory.";
 
-      FilterLevel -= job->cost;
-      return;
+      goto abort_job;
     }
   }
 
@@ -659,14 +686,9 @@ cupsdContinueJob(cupsd_job_t *job) /* I - Job */
       cupsdLogJob(job, CUPSD_LOG_DEBUG,
                  "Unable to add port monitor - %s", strerror(errno));
 
-      cupsArrayDelete(filters);
-
-      cupsdSetJobState(job, IPP_JOB_STOPPED, CUPSD_JOB_DEFAULT,
-                      "Stopping job because the scheduler ran out of "
-                      "memory.");
+      abort_message = "Stopping job because the scheduler ran out of memory.";
 
-      FilterLevel -= job->cost;
-      return;
+      goto abort_job;
     }
   }
 
@@ -680,13 +702,10 @@ cupsdContinueJob(cupsd_job_t *job)        /* I - Job */
                "Too many filters (%d > %d), unable to print!",
                cupsArrayCount(filters), MAX_FILTERS);
 
-    cupsArrayDelete(filters);
-    cupsdSetJobState(job, IPP_JOB_STOPPED, CUPSD_JOB_DEFAULT,
-                    "Stopping job because it needs too many filters to "
-                    "print.");
+    abort_message = "Aborting job because it needs too many filters to print.";
+    abort_state   = IPP_JOB_ABORTED;
 
-    FilterLevel -= job->cost;
-    return;
+    goto abort_job;
   }
 
  /*
@@ -726,12 +745,9 @@ cupsdContinueJob(cupsd_job_t *job) /* I - Job */
   if ((options = get_options(job, banner_page, copies, sizeof(copies), title,
                              sizeof(title))) == NULL)
   {
-    cupsdSetJobState(job, IPP_JOB_STOPPED, CUPSD_JOB_DEFAULT,
-                    "Stopping job because the scheduler ran out of memory.");
-    cupsArrayDelete(filters);
+    abort_message = "Stopping job because the scheduler ran out of memory.";
 
-    FilterLevel -= job->cost;
-    return;
+    goto abort_job;
   }
 
  /*
@@ -761,12 +777,10 @@ cupsdContinueJob(cupsd_job_t *job)        /* I - Job */
   {
     cupsdLogMessage(CUPSD_LOG_DEBUG, "Unable to allocate argument array - %s",
                     strerror(errno));
-    cupsdSetJobState(job, IPP_JOB_STOPPED, CUPSD_JOB_DEFAULT,
-                    "Stopping job because the scheduler ran out of memory.");
-    cupsArrayDelete(filters);
 
-    FilterLevel -= job->cost;
-    return;
+    abort_message = "Stopping job because the scheduler ran out of memory.";
+
+    goto abort_job;
   }
 
   sprintf(jobid, "%d", job->id);
@@ -953,13 +967,6 @@ cupsdContinueJob(cupsd_job_t *job) /* I - Job */
   * Now create processes for all of the filters...
   */
 
-  filterfds[0][0] = -1;
-  filterfds[0][1] = -1;
-  filterfds[1][0] = -1;
-  filterfds[1][1] = -1;
-
-  memset(job->filters, 0, sizeof(job->filters));
-
   for (i = 0, slot = 0, filter = (mime_filter_t *)cupsArrayFirst(filters);
        filter;
        i ++, filter = (mime_filter_t *)cupsArrayNext(filters))
@@ -1036,7 +1043,7 @@ cupsdContinueJob(cupsd_job_t *job)        /* I - Job */
     pid = cupsdStartProcess(command, argv, envp, filterfds[!slot][0],
                             filterfds[slot][1], job->status_pipes[1],
                            job->back_pipes[0], job->side_pipes[0], 0,
-                           job->profile, job->id, job->filters + i);
+                           job->profile, job, job->filters + i);
 
     cupsdClosePipe(filterfds[!slot]);
 
@@ -1045,7 +1052,7 @@ cupsdContinueJob(cupsd_job_t *job)        /* I - Job */
       cupsdLogJob(job, CUPSD_LOG_ERROR, "Unable to start filter \"%s\" - %s.",
                  filter->filter, strerror(errno));
 
-      abort_message = "Stopped job because the scheduler could not execute a "
+      abort_message = "Stopping job because the scheduler could not execute a "
                      "filter.";
 
       goto abort_job;
@@ -1091,7 +1098,7 @@ cupsdContinueJob(cupsd_job_t *job)        /* I - Job */
       pid = cupsdStartProcess(command, argv, envp, filterfds[!slot][0],
                              filterfds[slot][1], job->status_pipes[1],
                              job->back_pipes[1], job->side_pipes[1],
-                             backroot, job->profile, job->id, &(job->backend));
+                             backroot, job->profile, job, &(job->backend));
 
       if (pid == 0)
       {
@@ -1147,6 +1154,16 @@ cupsdContinueJob(cupsd_job_t *job)       /* I - Job */
   cupsdAddEvent(CUPSD_EVENT_JOB_STATE, job->printer, job, "Job #%d started.",
                 job->id);
 
+ /*
+  * If we get here than we are able to run the printer driver filters, so clear
+  * the missing and insecure warnings...
+  */
+
+  if (cupsdSetPrinterReasons(job->printer, "-cups-missing-filter-warning,"
+                                          "cups-insecure-filter-warning"))
+    cupsdAddEvent(CUPSD_EVENT_PRINTER_STATE, job->printer, NULL,
+                  "Printer drivers now functional.");
+
   return;
 
 
@@ -1157,25 +1174,53 @@ cupsdContinueJob(cupsd_job_t *job)      /* I - Job */
 
   abort_job:
 
+  FilterLevel -= job->cost;
+  job->cost = 0;
+
   for (slot = 0; slot < 2; slot ++)
     cupsdClosePipe(filterfds[slot]);
 
+  cupsArrayDelete(filters);
+
+  if (argv)
+  {
+    if (job->printer->remote && job->num_files > 1)
+    {
+      for (i = 0; i < job->num_files; i ++)
+       free(argv[i + 6]);
+    }
+
+    free(argv);
+  }
+
+  cupsdClosePipe(job->print_pipes);
+  cupsdClosePipe(job->back_pipes);
+  cupsdClosePipe(job->side_pipes);
+
+  cupsdRemoveSelect(job->status_pipes[0]);
   cupsdClosePipe(job->status_pipes);
   cupsdStatBufDelete(job->status_buffer);
   job->status_buffer = NULL;
 
-  cupsArrayDelete(filters);
+ /*
+  * Update the printer and job state.
+  */
 
-  if (job->printer->remote && job->num_files > 1)
-  {
-    for (i = 0; i < job->num_files; i ++)
-      free(argv[i + 6]);
-  }
+  cupsdSetJobState(job, abort_state, CUPSD_JOB_DEFAULT, "%s", abort_message);
+  cupsdSetPrinterState(job->printer, IPP_PRINTER_IDLE, 0);
+  update_job_attrs(job, 0);
 
-  free(argv);
+  if (job->history)
+    free_job_history(job);
 
-  cupsdSetJobState(job, IPP_JOB_STOPPED, CUPSD_JOB_DEFAULT, "%s",
-                   abort_message);
+  cupsArrayRemove(PrintingJobs, job);
+
+ /*
+  * Clear the printer <-> job association...
+  */
+
+  job->printer->job = NULL;
+  job->printer      = NULL;
 }
 
 
@@ -1231,6 +1276,9 @@ cupsdDeleteJob(cupsd_job_t       *job,    /* I - Job */
     job->num_files = 0;
   }
 
+  if (job->history)
+    free_job_history(job);
+
   unload_job(job);
 
   cupsArrayRemove(Jobs, job);
@@ -1256,7 +1304,7 @@ cupsdFreeAllJobs(void)
 
   cupsdHoldSignals();
 
-  cupsdStopAllJobs(1);
+  cupsdStopAllJobs(CUPSD_JOB_FORCE, 0);
   cupsdSaveAllJobs();
 
   for (job = (cupsd_job_t *)cupsArrayFirst(Jobs);
@@ -2338,6 +2386,13 @@ cupsdSetJobState(
        break;
   }
 
+ /*
+  * Finalize the job immediately if we forced things...
+  */
+
+  if (action == CUPSD_JOB_FORCE)
+    finalize_job(job);
+
  /*
   * Update the server "busy" state...
   */
@@ -2352,7 +2407,8 @@ cupsdSetJobState(
 
 void
 cupsdStopAllJobs(
-    cupsd_jobaction_t action)          /* I - Action */
+    cupsd_jobaction_t action,          /* I - Action */
+    int               kill_delay)      /* I - Number of seconds before we kill */
 {
   cupsd_job_t  *job;                   /* Current job */
 
@@ -2362,7 +2418,12 @@ cupsdStopAllJobs(
   for (job = (cupsd_job_t *)cupsArrayFirst(PrintingJobs);
        job;
        job = (cupsd_job_t *)cupsArrayNext(PrintingJobs))
+  {
+    if (kill_delay)
+      job->kill_time = time(NULL) + kill_delay;
+
     cupsdSetJobState(job, IPP_JOB_PENDING, action, NULL);
+  }
 }
 
 
@@ -2426,6 +2487,140 @@ compare_jobs(void *first,               /* I - First job */
 }
 
 
+/*
+ * 'dump_job_history()' - Dump any debug messages for a job.
+ */
+
+static void
+dump_job_history(cupsd_job_t *job)     /* I - Job */
+{
+  int                  i,              /* Looping var */
+                       oldsize;        /* Current MaxLogSize */
+  struct tm            *date;          /* Date/time value */
+  cupsd_joblog_t       *message;       /* Current message */
+  char                 temp[2048],     /* Log message */
+                       *ptr,           /* Pointer into log message */
+                       start[256],     /* Start time */
+                       end[256];       /* End time */
+  cupsd_printer_t      *printer;       /* Printer for job */
+
+
+ /*
+  * See if we have anything to dump...
+  */
+
+  if (!job->history)
+    return;
+
+ /*
+  * Disable log rotation temporarily...
+  */
+
+  oldsize    = MaxLogSize;
+  MaxLogSize = 0;
+
+ /*
+  * Copy the debug messages to the log...
+  */
+
+  message = (cupsd_joblog_t *)cupsArrayFirst(job->history);
+  date = localtime(&(message->time));
+  strftime(start, sizeof(start), "%X", date);
+
+  message = (cupsd_joblog_t *)cupsArrayLast(job->history);
+  date = localtime(&(message->time));
+  strftime(end, sizeof(end), "%X", date);
+
+  snprintf(temp, sizeof(temp),
+           "[Job %d] The following messages were recorded from %s to %s",
+           job->id, start, end);
+  cupsdWriteErrorLog(CUPSD_LOG_DEBUG, temp);
+
+  for (message = (cupsd_joblog_t *)cupsArrayFirst(job->history);
+       message;
+       message = (cupsd_joblog_t *)cupsArrayNext(job->history))
+    cupsdWriteErrorLog(CUPSD_LOG_DEBUG, message->message);
+
+  snprintf(temp, sizeof(temp), "[Job %d] End of messages", job->id);
+  cupsdWriteErrorLog(CUPSD_LOG_DEBUG, temp);
+
+ /*
+  * Log the printer state values...
+  */
+
+  if ((printer = job->printer) == NULL)
+    printer = cupsdFindDest(job->dest);
+
+  if (printer)
+  {
+    snprintf(temp, sizeof(temp), "[Job %d] printer-state=%d(%s)", job->id,
+             printer->state,
+            printer->state == IPP_PRINTER_IDLE ? "idle" :
+                printer->state == IPP_PRINTER_PROCESSING ? "processing" :
+                "stopped");
+    cupsdWriteErrorLog(CUPSD_LOG_DEBUG, temp);
+
+    snprintf(temp, sizeof(temp), "[Job %d] printer-state-message=\"%s\"",
+             job->id, printer->state_message);
+    cupsdWriteErrorLog(CUPSD_LOG_DEBUG, temp);
+
+    snprintf(temp, sizeof(temp), "[Job %d] printer-state-reasons=", job->id);
+    ptr = temp + strlen(temp);
+    if (printer->num_reasons == 0)
+      strlcpy(ptr, "none", sizeof(temp) - (ptr - temp));
+    else
+    {
+      for (i = 0;
+           i < printer->num_reasons && ptr < (temp + sizeof(temp) - 2);
+           i ++)
+      {
+        if (i)
+         *ptr++ = ',';
+
+       strlcpy(ptr, printer->reasons[i], sizeof(temp) - (ptr - temp));
+       ptr += strlen(ptr);
+      }
+    }
+    cupsdWriteErrorLog(CUPSD_LOG_DEBUG, temp);
+  }
+
+ /*
+  * Restore log file rotation...
+  */
+
+  MaxLogSize = oldsize;
+
+ /*
+  * Free all messages...
+  */
+
+  free_job_history(job);
+}
+
+
+/*
+ * 'free_job_history()' - Free any log history.
+ */
+
+static void
+free_job_history(cupsd_job_t *job)     /* I - Job */
+{
+  char *message;                       /* Current message */
+
+
+  if (!job->history)
+    return;
+
+  for (message = (char *)cupsArrayFirst(job->history);
+       message;
+       message = (char *)cupsArrayNext(job->history))
+    free(message);
+
+  cupsArrayDelete(job->history);
+  job->history = NULL;
+}
+
+
 /*
  * 'finalize_job()' - Cleanup after job filter processes and support data.
  */
@@ -2467,13 +2662,12 @@ finalize_job(cupsd_job_t *job)          /* I - Job */
   * Close pipes and status buffer...
   */
 
-  cupsdRemoveSelect(job->status_buffer->fd);
-
   cupsdClosePipe(job->print_pipes);
   cupsdClosePipe(job->back_pipes);
   cupsdClosePipe(job->side_pipes);
-  cupsdClosePipe(job->status_pipes);
 
+  cupsdRemoveSelect(job->status_pipes[0]);
+  cupsdClosePipe(job->status_pipes);
   cupsdStatBufDelete(job->status_buffer);
   job->status_buffer = NULL;
 
@@ -2499,8 +2693,8 @@ finalize_job(cupsd_job_t *job)            /* I - Job */
     default :
     case IPP_JOB_PROCESSING :
     case IPP_JOB_COMPLETED :
-       job_state     = IPP_JOB_COMPLETED;
-       message       = "Job completed.";
+       job_state = IPP_JOB_COMPLETED;
+       message   = "Job completed.";
         break;
 
     case IPP_JOB_STOPPED :
@@ -2634,14 +2828,12 @@ finalize_job(cupsd_job_t *job)          /* I - Job */
            message   = "Job aborted due to backend errors; please consult "
                        "the error_log file for details.";
          }
-         else
+         else if (job->state_value == IPP_JOB_PROCESSING)
           {
+            job_state     = IPP_JOB_PENDING;
            printer_state = IPP_PRINTER_STOPPED;
            message       = "Printer stopped due to backend errors; please "
                            "consult the error_log file for details.";
-
-            if (job_state == IPP_JOB_COMPLETED)
-             job_state = IPP_JOB_PENDING;
          }
           break;
 
@@ -2724,6 +2916,14 @@ finalize_job(cupsd_job_t *job)           /* I - Job */
                        printer_state == IPP_PRINTER_STOPPED);
   update_job_attrs(job, 0);
 
+  if (job->history)
+  {
+    if (job->status)
+      dump_job_history(job);
+    else
+      free_job_history(job);
+  }
+
   cupsArrayRemove(PrintingJobs, job);
 
  /*
@@ -3589,6 +3789,9 @@ start_job(cupsd_job_t     *job,           /* I - Job ID */
   job->status_buffer = cupsdStatBufNew(job->status_pipes[0], NULL);
   job->status_level  = CUPSD_LOG_INFO;
 
+  if (job->printer_message)
+    cupsdSetString(&(job->printer_message->values[0].string.text), "");
+
  /*
   * Create the backchannel pipes and make them non-blocking...
   */
@@ -3670,6 +3873,11 @@ stop_job(cupsd_job_t       *job, /* I - Job */
   FilterLevel -= job->cost;
   job->cost   = 0;
 
+  if (action == CUPSD_JOB_DEFAULT && !job->kill_time)
+    job->kill_time = time(NULL) + JobKillDelay;
+  else if (action == CUPSD_JOB_FORCE)
+    job->kill_time = 0;
+
   for (i = 0; job->filters[i]; i ++)
     if (job->filters[i] > 0)
       cupsdEndProcess(job->filters[i], action == CUPSD_JOB_FORCE);
@@ -3711,7 +3919,8 @@ update_job(cupsd_job_t *job)              /* I - Job to check */
 {
   int          i;                      /* Looping var */
   int          copies;                 /* Number of copies printed */
-  char         message[1024],          /* Message text */
+  char         message[CUPSD_SB_BUFFER_SIZE],
+                                       /* Message text */
                *ptr;                   /* Pointer update... */
   int          loglevel,               /* Log level for message */
                event = 0;              /* Events? */
@@ -3983,8 +4192,7 @@ update_job(cupsd_job_t *job)              /* I - Job to check */
 #endif /* __APPLE__ */
     else
     {
-      if (loglevel != CUPSD_LOG_INFO && loglevel > LogLevel)
-       cupsdLogJob(job, loglevel, "%s", message);
+      cupsdLogJob(job, loglevel, "%s", message);
 
       if (loglevel < CUPSD_LOG_DEBUG)
       {
@@ -3994,7 +4202,7 @@ update_job(cupsd_job_t *job)              /* I - Job to check */
 
        event |= CUPSD_EVENT_PRINTER_STATE | CUPSD_EVENT_JOB_PROGRESS;
 
-       if (loglevel <= job->status_level)
+       if (loglevel < job->status_level)
        {
         /*
          * Some messages show in the job-printer-state-message attribute...