[cups] CUPS sometimes losing jobs upon restart

[Michael Sweet]

Nick,

AppSocket doesn't provide any means of determining the disposition of the job after it is sent...  Since you didn't pause (disable) the queue and the backend didn't return an error, cupsd assumes that the job did get printed.


> On Aug 26, 2015, at 1:58 PM, Nick <darknovanick at gmail.com> wrote:
> 
> On Tue, Aug 25, 2015 at 6:53 AM, Michael Sweet <msweet at apple.com> wrote:
> 
>> Nick,
>> 
>> I'm guessing that there is a job in the printer when it gets shut off, and
>> that CUPS thinks that the job has been successfully accepted by the
>> printer.  Depending on the protocol being used to talk to the printer, we
>> may or may not be able to know whether the job has been completely printed.
>> 
>> The proper way to manage this sort of thing is to run the "cupsdisable"
>> command on the print queue before turning the printer off - that will stop
>> processing of the current job.  If you are running CUPS 2.0 or later you
>> can also use the --hold option to allow the current job to complete.
>> 
>> Similarly, in the morning you want to run the "cupsenable" command to
>> start job processing again, after the printer has been turned on.
>> 
>> If you allow the printer to go into its sleep state (vs. physically
>> powering it off) then all you need it to add the cupsdisable/enable
>> commands to cron jobs that run at the appropriate times.  The printer will
>> go to sleep overnight automatically...
>> 
>> 
>> 
> 
> Yes, it looks like this is what is happening -- the print job is in the
> process of being spooled when the printer is shut off (with a physical
> power switch), and the spooling is interrupted, and the job is lost the
> next morning. We are open to changing our procedures, and I think your
> suggestion of using cupsdisable/cupsenable makes sense, but I'm still
> unclear on why exactly the job is being lost. Here's some more log output
> from when one of these jobs is first printed:
> 
> 
> I [20/Aug/2015:17:13:17 -0500] [Job 517105] Adding start banner page "none".
> I [20/Aug/2015:17:13:17 -0500] [Job 517105] Queued on "picking" by "root".
> D [20/Aug/2015:17:13:17 -0500] [Job 517105] Auto-typing file...
> D [20/Aug/2015:17:13:17 -0500] [Job 517105] Request file type is
> application/postscript.
> I [20/Aug/2015:17:13:17 -0500] [Job 517105] File of type
> application/postscript queued by "root".
> I [20/Aug/2015:17:13:17 -0500] [Job 517105] Adding end banner page "none".
> D [20/Aug/2015:17:13:17 -0500] [Job 517105] job-sheets=none,none
> D [20/Aug/2015:17:13:17 -0500] [Job 517105] argv[0]="picking"
> D [20/Aug/2015:17:13:17 -0500] [Job 517105] argv[1]="517105"
> ....
> I [20/Aug/2015:17:13:17 -0500] [Job 517105] Start rendering...
> D [20/Aug/2015:17:13:17 -0500] [Job 517105] Set job-printer-state-message
> to "Start rendering...", current level=INFO
> I [20/Aug/2015:17:13:17 -0500] [Job 517105] Processing page 1...
> D [20/Aug/2015:17:13:17 -0500] [Job 517105] Set job-printer-state-message
> to "Processing page 1...", current level=INFO
> D [20/Aug/2015:17:13:17 -0500] [Job 517105] Gutenprint: About to start
> printing loop.
> D [20/Aug/2015:17:13:17 -0500] [Job 517105] Gutenprint: ================
> Printing page 1      ================
> ....
> I [20/Aug/2015:17:13:17 -0500] [Job 517105] Printing page 1, 1%
> D [20/Aug/2015:17:13:17 -0500] [Job 517105] Set job-printer-state-message
> to "Printing page 1, 1%", current level=INFO
> D [20/Aug/2015:17:13:17 -0500] [Job 517105] ATTR: job-media-progress=1
> I [20/Aug/2015:17:13:17 -0500] [Job 517105] Printing page 1, 2%
> D [20/Aug/2015:17:13:17 -0500] [Job 517105] Set job-printer-state-message
> to "Printing page 1, 2%", current level=INFO
> ....
> I [20/Aug/2015:17:13:17 -0500] [Job 517105] Printing page 1, 20%
> D [20/Aug/2015:17:13:17 -0500] [Job 517105] Set job-printer-state-message
> to "Printing page 1, 20%", current level=INFO
> D [20/Aug/2015:17:13:17 -0500] [Job 517105] ATTR: job-media-progress=20
> I [20/Aug/2015:17:13:17 -0500] [Job 517105] Printing page 1, 21%
> D [20/Aug/2015:17:13:17 -0500] [Job 517105] Set job-printer-state-message
> to "Printing page 1, 21%", current level=INFO
> D [20/Aug/2015:17:13:17 -0500] [Job 517105] ATTR: job-media-progress=21
> D [20/Aug/2015:17:13:21 -0500] [Job 517105] prtGeneralCurrentLocalization
> type is 0, expected 2!
> D [20/Aug/2015:17:13:21 -0500] [Job 517105] backendWaitLoop(snmp_fd=5,
> addr=0x7ffed447ca28, side_cb=0x7ffed3ab9460)
> D [20/Aug/2015:17:13:21 -0500] [Job 517105] Connecting to 192.168.0.113:9100
> I [20/Aug/2015:17:13:21 -0500] [Job 517105] Connecting to printer.
> D [20/Aug/2015:17:13:21 -0500] [Job 517105] Set job-printer-state-message
> to "Connecting to printer.", current level=INFO
> D [20/Aug/2015:17:13:24 -0500] [Job 517105] Connection error: No route to
> host
> W [20/Aug/2015:17:13:24 -0500] [Job 517105] The printer is unreachable at
> this time.
> D [20/Aug/2015:17:13:24 -0500] [Job 517105] Set job-printer-state-message
> to "The printer is unreachable at this time.", current level=WARN
> D [20/Aug/2015:17:13:32 -0500] [Job 517105] Connection error: No route to
> host
> W [20/Aug/2015:17:13:32 -0500] [Job 517105] The printer is unreachable at
> this time.
> D [20/Aug/2015:17:13:45 -0500] [Job 517105] Connection error: No route to
> host
> W [20/Aug/2015:17:13:45 -0500] [Job 517105] The printer is unreachable at
> this time.
> .... (repeats all night) ....
> 
> and then the next morning after CUPS has been reloaded, but the printer has
> not been turned on again:
> 
> I [21/Aug/2015:06:35:52 -0500] [Job 517105] Job completed.
> D [21/Aug/2015:06:35:52 -0500] [Job 517105] Unloading...
> D [21/Aug/2015:06:35:53 -0500] [Job 517105] Loading from cache...
> I [21/Aug/2015:06:35:53 -0500] [Job 517105] Data files have gone away!
> D [21/Aug/2015:06:35:53 -0500] [Job 517105] Loading attributes...
> E [21/Aug/2015:06:35:55 -0500] [Job 517105] Aborting job because it has no
> files.
> D [21/Aug/2015:06:37:04 -0500] [Job 517105] Unloading...
> 
> 
> 
> So, to my understanding, the job is in the process of being printed, and
> makes it to 21% of "printing". During this process it looks like it
> attempts to connect to the printer (192.168.0.113) at which point it fails
> with a connection error: No route to host. It continually retries. As I
> read this, since it never says it has "connected", I'm unclear on if it
> actually managed to talk to the printer at all? But regardless, it did not
> finish the "printing" process so I'm not sure why CUPS thinks the job has
> been completed and the "data files have gone away!"
> 
> Like I said, I am totally willing to have them change how we do things to
> avoid this situation as I agree that it is kind of bad policy to shut the
> printer off when it could be in the middle of spooling a job. But I also
> want to make sure I do my part, if CUPS isn't supposed to be working this
> way that I can assist in providing the logs, as it seems to me like CUPS
> shouldn't be deleting the job file until it has successfully completed the
> print, and if it is interrupted halfway I would think it would retry from
> the beginning (better to risk 2 copies than none). Thanks,
> 
> Nick
> _______________________________________________
> cups mailing list
> cups at cups.org
> https://www.cups.org/mailman/listinfo/cups

_________________________________________________________
Michael Sweet, Senior Printing System Engineer, PWG Chair