Claiming Job Completed when GhostScript Runs out of Memory, Causing Print Failed

[SadaleNet]

Environment:

• Debian Wheezy
• CUPS 1.5.3
• Gutenprint v5.2.9

Steps to reproduce:

1. (Optional)Disable swap
2. Somehow fill the RAM of the machine until it has somewhere like 50MB free RAM left.
3. Print anything(e.g. test page)

Result:

It printed nothing, nor the printer received any print command. However, in /var/log/cups/access_log:

localhost - - [10/May/2016:14:37:12 +0800] "POST /printers/Canon_MG2400_series HTTP/1.1" 200 422 Print-Job successful-ok

In addition, in /var/log/cups/error_log:

D [10/May/2016:14:37:20 +0800] [Job 136] Last OS error: Cannot allocate memory
D [10/May/2016:14:37:20 +0800] [Job 136] GPL Ghostscript 9.05: Unrecoverable error, exit code 1

Expected result:

1. The print should not be shown as "Completed" or "Successful"
2. The log level of the error should not be "error" instead of "debug".

It wasted me a few hours to figure out what's wrong. :(

[michaelrsweet]

It is up to Ghostscript (or the wrapper around it) to report errors as errors. CUPS sees the stderr output as a debug message and logs accordingly.

[SadaleNet]

True. But the exit code of Ghostscript is 1 instead of 0. I think, if possible, CUPS should report the message as an "error" message instead of "debug" message. That would make debugging this issue much easier.

Or is Ghostscript called by GutenPrint, causing the exit code of Ghostscript not accessible by CUPS?

[michaelrsweet]

The wrapper script may be consuming the Ghostscript exit status - please report that upstream to the Ghostscript folks.

Similarly, it is up to Ghostscript to tell CUPS its message is an error (via an ERROR: prefix), otherwise CUPS will assume it is a debug message (which has been the documented interface with CUPS since 1998...)

[SadaleNet]

Ah. Got it. Thank you very much for quick reply. That's very helpful. :)

[jsmeix]

I think such issues should not be reported to Ghostscript
because Ghostscript upstream usually rejects such
reports as "invalid" for Ghostscript which is right
because Ghostscript cannot know what program
has called it and what its caller does with its output.

I suggest to report such issues to the matching upstream
project of the caller of Ghostscript (i.e. the "wrapper script")
because in the end the caller pf a program is responsible
to do "the right things" when calling the program in a
particular environment (here in the environment of how
the CUPS print job processing works).

The caller of Ghostscript could be something like foomatic-rip
(check your PPD file what "cupsFilter" entries there are).

If your PPD file /etc/cups/ppd/<queue_name>.ppd contains

cupsFilter ... foomatic-rip

the Ghostscript caller is foomatic-rip which is nowadays
provided by the cups-filters software (which is not from CUPS).

The cups-filters software is from OpenPrinting.org, see
http://www.linuxfoundation.org/collaborate/workgroups/openprinting/cups-filters

Otherwise inspect you /var/log/cups/error_log
what the caller of Ghsotscript is in your case.

For example if you /var/log/cups/error_log contains

Started filter /usr/lib/cups/filter/gstoraster
...
Ghostscript command line: /usr/bin/gs ... -sDEVICE=cups ...

then /usr/lib/cups/filter/gstoraster is the caller of Ghostscript
and this one also belongs to cups-filters.

[jsmeix]

This is the matching report at Ghostscript
http://bugs.ghostscript.com/show_bug.cgi?id=696767

Because
https://sadale.net/40/solution-to-cups-claiming-print-job-completed-despite-printing-nothing
contains "Raspberry Pi" see also the related issue
http://bugs.ghostscript.com/show_bug.cgi?id=696348
which is also about a system with too little memory.

[SadaleNet]

I've found the following in the log:

Started filter /usr/lib/cups/filter/bannertopdf
Started filter /usr/lib/cups/filter/pdftopdf
Started filter /usr/lib/cups/filter/gstoraster
...
Ghostscript command line: /usr/bin/gs ... -sDEVICE=cups ...

Does that mean that /usr/lib/cups/filter/gstoraster is the caller?

EDIT: There is no cupsFilter ... foomatic-rip in the PPD file

[jsmeix]

Yes, /usr/lib/cups/filter/gstoraster is the caller.

See "Bug reports" at
http://www.linuxfoundation.org/collaborate/workgroups/openprinting/cups-filters

[SadaleNet]

Thanks for making it clear. I'll file a bug report to them soon!

[jsmeix]

For completeness:
This is the matching report at cups-filters:
https://bugs.linuxfoundation.org/show_bug.cgi?id=1354