After updating no printing: Jobs withheld in Queue.

This is on tumbleweed with a Brother HL-2040 (black and white laserprinter), using driver Brother HL-2060 Foomatic/hl1250 (grayscale) connected via USB. “lsusb” sees it too. I know that there is a driver and wrapperdriver on the brother site, but installing those I get a message that they are deprecated and will not be supported at some time in the future, so I don’t use them. My setup worked for years until about the beginning of August 2019 (I don’t print often, so I am not quite sure, when the problem started).

pending since Fri 16 Aug 2019 03:28:49 PM CEST  
processing since Fri 16 Aug 2019 04:21:15 PM CEST *"Sending Data to Printer."*

What? How?? Where??? I don’t even know where to look, and google disappointed me severely :(.

A starting point would probably be to take a look at any log files at:

/var/log/cups/

Maybe some clues in those…

Okay, this is the /var/log/cups/error_log of today:

E [16/Aug/2019:16:20:51 +0200] Missing value on line 563 of /var/cache/cups/job.cache.
E [16/Aug/2019:16:20:51 +0200] Missing value on line 576 of /var/cache/cups/job.cache.
E [16/Aug/2019:16:20:51 +0200] Missing value on line 770 of /var/cache/cups/job.cache.
E [16/Aug/2019:16:20:51 +0200] Missing value on line 783 of /var/cache/cups/job.cache.
E [16/Aug/2019:16:20:51 +0200] Missing value on line 923 of /var/cache/cups/job.cache.
E [16/Aug/2019:16:20:51 +0200] Missing value on line 936 of /var/cache/cups/job.cache.
E [16/Aug/2019:16:20:51 +0200] Missing value on line 1027 of /var/cache/cups/job.cache.
E [16/Aug/2019:16:20:51 +0200] Missing value on line 1312 of /var/cache/cups/job.cache.
E [16/Aug/2019:16:20:51 +0200] Missing value on line 1325 of /var/cache/cups/job.cache.
E [16/Aug/2019:16:20:51 +0200] Missing value on line 1364 of /var/cache/cups/job.cache.
E [16/Aug/2019:16:20:51 +0200] Missing value on line 1390 of /var/cache/cups/job.cache.
E [16/Aug/2019:16:20:51 +0200] Unknown Servicecenter directive on line 1391 of /var/cache/cups/job.cache.
E [16/Aug/2019:16:20:51 +0200] Missing value on line 1404 of /var/cache/cups/job.cache.
E [16/Aug/2019:16:20:51 +0200] Unknown Servicecenter directive on line 1405 of /var/cache/cups/job.cache.
E [16/Aug/2019:16:20:51 +0200] Missing value on line 1665 of /var/cache/cups/job.cache.
E [16/Aug/2019:16:20:51 +0200] Missing value on line 1782 of /var/cache/cups/job.cache.
E [16/Aug/2019:16:20:51 +0200] Missing value on line 1795 of /var/cache/cups/job.cache.
E [16/Aug/2019:16:20:51 +0200] Missing value on line 1808 of /var/cache/cups/job.cache.
E [16/Aug/2019:16:20:51 +0200] Missing value on line 2444 of /var/cache/cups/job.cache.
E [16/Aug/2019:16:20:51 +0200] Missing value on line 2522 of /var/cache/cups/job.cache.
E [16/Aug/2019:16:20:51 +0200] Missing value on line 2535 of /var/cache/cups/job.cache.
E [16/Aug/2019:16:20:51 +0200] Missing value on line 2548 of /var/cache/cups/job.cache.
E [16/Aug/2019:16:20:51 +0200] Missing value on line 2560 of /var/cache/cups/job.cache.
W [16/Aug/2019:16:20:51 +0200] CreateProfile failed: org.freedesktop.DBus.Error.ServiceUnknown:The name org.freedesktop.ColorManager was not provided by any .service files
W [16/Aug/2019:16:20:51 +0200] CreateDevice failed: org.freedesktop.DBus.Error.ServiceUnknown:The name org.freedesktop.ColorManager was not provided by any .service files
W [16/Aug/2019:16:20:51 +0200] CreateProfile failed: org.freedesktop.DBus.Error.ServiceUnknown:The name org.freedesktop.ColorManager was not provided by any .service files
W [16/Aug/2019:16:20:51 +0200] CreateDevice failed: org.freedesktop.DBus.Error.ServiceUnknown:The name org.freedesktop.ColorManager was not provided by any .service files
E [16/Aug/2019:15:28:43 +0200] [CGI] cups-brf must be called as root
E [16/Aug/2019:15:28:43 +0200] [cups-deviced] PID 6501 (cups-brf) stopped with status 1!
E [16/Aug/2019:15:28:43 +0200] [cups-deviced] PID 6505 (gutenprint52+usb) stopped with status 1!
E [16/Aug/2019:15:31:47 +0200] [CGI] cups-brf must be called as root
E [16/Aug/2019:15:31:47 +0200] [cups-deviced] PID 6701 (cups-brf) stopped with status 1!
E [16/Aug/2019:15:31:47 +0200] [cups-deviced] PID 6707 (gutenprint52+usb) stopped with status 1!
E [16/Aug/2019:15:36:32 +0200] [CGI] cups-brf must be called as root
E [16/Aug/2019:15:36:32 +0200] [cups-deviced] PID 6897 (cups-brf) stopped with status 1!
E [16/Aug/2019:15:36:32 +0200] [cups-deviced] PID 6903 (gutenprint52+usb) stopped with status 1!
E [16/Aug/2019:15:37:08 +0200] [cups-driverd] Bad driver information file \"/usr/share/cups/drv/sample.drv\"!
E [16/Aug/2019:15:37:08 +0200] [cups-driverd] Bad driver information file \"/usr/share/cups/drv/cupsfilters.drv\"!
E [16/Aug/2019:15:37:08 +0200] [cups-driverd] Bad driver information file \"/usr/share/cups/drv/generic-brf.drv\"!
E [16/Aug/2019:15:37:08 +0200] [cups-driverd] Bad driver information file \"/usr/share/cups/drv/generic-ubrl.drv\"!
E [16/Aug/2019:15:37:08 +0200] [cups-driverd] Bad driver information file \"/usr/share/cups/drv/indexv3.drv\"!
E [16/Aug/2019:15:37:08 +0200] [cups-driverd] Bad driver information file \"/usr/share/cups/drv/indexv4.drv\"!

I regret to say, that I don’t understand it…

Unfortunately, the log snippet you have shared is incomplete. To start with put CUPS into debug mode for more verbose output.

sudo cupsctl --debug-logging

then clear any existing/stale jobs

sudo cancel -a

Now watch the error_log with

sudo tail -f /var/log/cups/error_log|egrep -iA4 "filter|error"

and generate another print job. Observe/capture the output.

If the output is lengthy consider uploading to https://paste.opensuse.org/ and post the link that it generates here. If you have susepaste installed, you can do

susepaste /var/log/cups/error_log

and share the link to it here.

Uarghhh, I hate machines sniping at me. I entered your commands and now it is printing. This is the output:

me@PC:~> sudo cupsctl --debug-logging
me@PC:~> sudo cancel -a
me@PC:~> sudo tail -f /var/log/cups/error_log|egrep -iA4 "filter|error"
D [17/Aug/2019:14:59:01 +0200] [Client 5] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [17/Aug/2019:14:59:01 +0200] [Client 5] Closing connection.
D [17/Aug/2019:14:59:01 +0200] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
I [17/Aug/2019:14:59:02 +0200] Expiring subscriptions...
I [17/Aug/2019:14:59:12 +0200] Saving printers.conf...
--
D [17/Aug/2019:15:00:15 +0200] [Client 6] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [17/Aug/2019:15:00:15 +0200] [Client 6] Closing connection.
D [17/Aug/2019:15:00:15 +0200] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [17/Aug/2019:15:00:15 +0200] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [17/Aug/2019:15:00:15 +0200] [Client 7] Server address is "/run/cups/cups.sock".
--
D [17/Aug/2019:15:00:15 +0200] [Client 7] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [17/Aug/2019:15:00:15 +0200] [Client 7] Closing connection.
D [17/Aug/2019:15:00:15 +0200] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [17/Aug/2019:15:00:15 +0200] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [17/Aug/2019:15:00:15 +0200] [Client 9] Server address is "/run/cups/cups.sock".
--
D [17/Aug/2019:15:00:15 +0200] [Client 8] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [17/Aug/2019:15:00:15 +0200] [Client 8] Closing connection.
D [17/Aug/2019:15:00:15 +0200] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [17/Aug/2019:15:00:15 +0200] [Client 9] POST / HTTP/1.1
D [17/Aug/2019:15:00:15 +0200] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
--
D [17/Aug/2019:15:00:15 +0200] [CGI] envp[9] = "PATH=/usr/lib/cups/filter:/usr/bin:/usr/sbin:/bin:/usr/bin"
D [17/Aug/2019:15:00:15 +0200] [CGI] envp[10] = "SERVER_ADMIN=root@PC"
D [17/Aug/2019:15:00:15 +0200] [CGI] envp[11] = "SOFTWARE=CUPS/2.3b6"
D [17/Aug/2019:15:00:15 +0200] [CGI] envp[12] = "TMPDIR=/var/spool/cups/tmp"
D [17/Aug/2019:15:00:15 +0200] [CGI] envp[13] = "USER=root"
--
D [17/Aug/2019:15:00:15 +0200] [cups-deviced] PID 4120 (serial) exited with no errors.
D [17/Aug/2019:15:00:15 +0200] [Client 9] con->http=0x55b3c4d7a360
D [17/Aug/2019:15:00:15 +0200] [Client 9] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=2147483647, response=(nil)(), pipe_pid=4113, file=17
D [17/Aug/2019:15:00:15 +0200] [Client 9] Waiting for CGI data.
D [17/Aug/2019:15:00:15 +0200] [Client 9] Script header: Content-Type: application/ipp
D [17/Aug/2019:15:00:15 +0200] [Client 9] Script header: 
D [17/Aug/2019:15:00:15 +0200] [Client 9] Sending status 200 for CGI.
--
D [17/Aug/2019:15:00:15 +0200] [Client 9] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=4113, file=17
D [17/Aug/2019:15:00:15 +0200] [Client 9] Waiting for CGI data.
D [17/Aug/2019:15:00:15 +0200] [CGI] Started ippfind (PID 4123)
D [17/Aug/2019:15:00:15 +0200] [cups-deviced] PID 4119 (implicitclass) exited with no errors.
D [17/Aug/2019:15:00:15 +0200] [CGI] Started post-processing (PID 4124)
D [17/Aug/2019:15:00:15 +0200] [CGI] Loading USB quirks from \"/usr/share/cups/usb\".
D [17/Aug/2019:15:00:15 +0200] [CGI] Multi-Call Dye-sublimation CUPS Backend version 0.75G
D [17/Aug/2019:15:00:15 +0200] [CGI] Loaded 164 quirks.
--
D [17/Aug/2019:15:00:15 +0200]  -e ]           # Query error log
D [17/Aug/2019:15:00:15 +0200]  -f ]           # Use fast return mode
D [17/Aug/2019:15:00:15 +0200]  -F ]           # Flash Printer LED
D [17/Aug/2019:15:00:15 +0200]  -i ]           # Query printer info
D [17/Aug/2019:15:00:15 +0200]  -l filename ]  # Get current tone curve
--
D [17/Aug/2019:15:00:15 +0200]  -e ]           # Query error log
D [17/Aug/2019:15:00:15 +0200]  -F ]           # Flash Printer LED
D [17/Aug/2019:15:00:15 +0200]  -i ]           # Query printer info
D [17/Aug/2019:15:00:15 +0200]  -k num ]       # Set sleep time (5-240 minutes)
D [17/Aug/2019:15:00:15 +0200]  -l filename ]  # Get current tone curve
--
D [17/Aug/2019:15:00:15 +0200]  -e ]           # Query error log
D [17/Aug/2019:15:00:15 +0200]  -F ]           # Flash Printer LED
D [17/Aug/2019:15:00:15 +0200]  -i ]           # Query printer info
D [17/Aug/2019:15:00:15 +0200]  -k num ]       # Set sleep time (5-240 minutes)
D [17/Aug/2019:15:00:15 +0200]  -l filename ]  # Get current tone curve
--
D [17/Aug/2019:15:00:15 +0200] [Client 9] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=4113, file=17
D [17/Aug/2019:15:00:15 +0200] [Client 9] Waiting for CGI data.
D [17/Aug/2019:15:00:15 +0200] [Client 9] con->http=0x55b3c4d7a360
D [17/Aug/2019:15:00:15 +0200] [Client 9] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=4113, file=17
D [17/Aug/2019:15:00:15 +0200] [Client 9] Waiting for CGI data.
D [17/Aug/2019:15:00:15 +0200] [Client 9] CGI data ready to be sent.
D [17/Aug/2019:15:00:15 +0200] [CGI] Flushed attributes...
D [17/Aug/2019:15:00:15 +0200] [cups-deviced] Found device \"hp\"...
--
D [17/Aug/2019:15:00:15 +0200] [Client 9] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=4113, file=17
D [17/Aug/2019:15:00:15 +0200] [Client 9] Waiting for CGI data.
D [17/Aug/2019:15:00:15 +0200] [Client 9] con->http=0x55b3c4d7a360
D [17/Aug/2019:15:00:15 +0200] [Client 9] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=4113, file=17
D [17/Aug/2019:15:00:15 +0200] [Client 9] Waiting for CGI data.
D [17/Aug/2019:15:00:15 +0200] [cups-deviced] PID 4122 (hp) exited with no errors.
D [17/Aug/2019:15:00:15 +0200] [Client 9] CGI data ready to be sent.
D [17/Aug/2019:15:00:15 +0200] [CGI] Flushed attributes...
D [17/Aug/2019:15:00:15 +0200] [cups-deviced] Found device \"ipps\"...
D [17/Aug/2019:15:00:15 +0200] [cups-deviced] PID 4116 (usb) exited with no errors.
D [17/Aug/2019:15:00:15 +0200] [Client 9] con->http=0x55b3c4d7a360
D [17/Aug/2019:15:00:15 +0200] [Client 9] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=4113, file=17
D [17/Aug/2019:15:00:15 +0200] [Client 9] Waiting for CGI data.
D [17/Aug/2019:15:00:15 +0200] [Client 9] con->http=0x55b3c4d7a360
D [17/Aug/2019:15:00:15 +0200] [Client 9] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=4113, file=17

After this the last four lines are repeated at least 50+ times and the job terminates normally. What happened?

Btw. what would be the command to reset logging to normal, something like “sudo cupsctl --logging-normal”?

Oh, and thank you very much :).

That’s great news and of course the log output reflected that. :wink:

After this the last four lines are repeated at least 50+ times and the job terminates normally. What happened?

Clearing the stuck print jobs probably helped with returning the printer status to ‘Idle’ and ‘Accepting Requests’, and the ‘cupsctl’ command will have restarted cups anyway. The printer status would confirm that

lpstat -t

Btw. what would be the command to reset logging to normal, something like “sudo cupsctl --logging-normal”?

Oh, and thank you very much :).

This will return logging to the normal level

sudo cupsctl --no-debug-logging

Glad to have been of help.

Printer / Cups reset to normal logging level and tried out lpstat -t. Thread bookmarked just in case … ;).

Thanks again and have a nice (rest of the) weekend.

Nooooo – it is doing it again and your commands don’t help anymore:

me@PC:~> sudo cupsctl --debug-logging
me@PC:~> sudo cancel -a              
me@PC:~> sudo tail -f /var/log/cups/error_log|egrep -iA4 "filter|error"
D [19/Aug/2019:15:59:49 +0200] [Client 5] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [19/Aug/2019:15:59:49 +0200] [Client 5] Closing connection.
D [19/Aug/2019:15:59:49 +0200] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
I [19/Aug/2019:15:59:50 +0200] Expiring subscriptions...
D [19/Aug/2019:16:00:11 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
--
D [19/Aug/2019:16:00:11 +0200] [Client 6] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=9726, response=0x56438e470c70(IPP_STATE_DATA), pipe_pid=0, file=-1
D [19/Aug/2019:16:00:11 +0200] [Client 6] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [19/Aug/2019:16:00:11 +0200] [Client 6] bytes=0, http_state=0, data_remaining=9726
D [19/Aug/2019:16:00:11 +0200] [Client 6] Flushing write buffer.
D [19/Aug/2019:16:00:11 +0200] [Client 6] New state is HTTP_STATE_WAITING
--
D [19/Aug/2019:16:00:11 +0200] [Client 6] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=2139, response=0x56438e43c370(IPP_STATE_DATA), pipe_pid=0, file=-1
D [19/Aug/2019:16:00:11 +0200] [Client 6] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [19/Aug/2019:16:00:11 +0200] [Client 6] bytes=0, http_state=0, data_remaining=2139
D [19/Aug/2019:16:00:11 +0200] [Client 6] Flushing write buffer.
D [19/Aug/2019:16:00:11 +0200] [Client 6] New state is HTTP_STATE_WAITING
--
...

… and so forth many times. This is 3 pages .pdf printed from Okular, ahm at least trying to print…

First, you should know that the commands were given as part of a debug process to help identify the underlying issue here. There should be more to your log output than what is shown here upon trying to print a document. The output may be lengthy, so you’re best advised to use susepaste, pastebin, (or similar), to share that output.

Post the current printer status…

lpstat -t

I am aware that you aimed at debugging, but assumed from your previous post that “sudo cancel -a” cleared the way. Just to be on the secure side I repeated the entire procedure…

Latest “lpstat -t”:

me@PC:~> lpstat -t
Zeitplandienst läuft
systemvoreingestelltes Ziel: HL-2040-series
Gerät für HL-2040: ///dev/null
Gerät für HL-2040-series: usb://Brother/HL-2040%20series?serial=B5J419303
HL-2040 akzeptiert keine Anfragen seit Mi 14 Aug 2019 17:30:57 CEST -
        reason unknown
HL-2040-series akzeptiert Anfragen seit Di 20 Aug 2019 13:00:23 CEST
Drucker HL-2040 ist deaktiviert seit Mi 14 Aug 2019 17:30:57 CEST
        unbekannter Grund
Drucker HL-2040-series druckt jetzt HL-2040-series-297.  Aktiviert seit Di 20 Aug 2019 13:00:23 CEST
        Sende Daten zum Drucker.
HL-2040-series-297      matthias        370688   Di 20 Aug 2019 13:00:23 CEST

And here is the output of logging: https://paste.opensuse.org/22138659

HTH.

Can you please run that to provide english output?

LC_ALL=C lpstat -t

Certainly, sorry:

me@PC:~> LC_ALL=C lpstat -t
scheduler is running
system default destination: HL-2040-series
device for HL-2040: ///dev/null
device for HL-2040-series: usb://Brother/HL-2040%20series?serial=B5J419303
HL-2040 not accepting requests since Wed Aug 14 17:30:57 2019 -
        reason unknown
HL-2040-series accepting requests since Thu Aug 22 12:17:09 2019
printer HL-2040 disabled since Wed Aug 14 17:30:57 2019 -
        reason unknown
printer HL-2040-series now printing HL-2040-series-297.  enabled since Thu Aug 22 12:17:09 2019
        Warte darauf dass der Drucker verfügbar wird.
HL-2040-series-297      me        370688   Tue Aug 20 13:00:23 2019

The one sentence still in German means “Waiting for the printer to become available”. HTH.

Okay, so at last I dug up my old notes (Precambrian probably). They said to go to YAST / security & users / Firewall – and then all is new. BUT: I opened ports 54925 plus 54926 in the external zone as well as in the DMZ (Scan and Fax ports). Printer is printing again. I hate it, when this happens. But I also feel better now. Hope this helps some other poor stranded soul some day…

Good to read that printing is now working for you, but since it was working prior to your firewall changes, it’s not clear why you believe these ports are involved for printing. The Brother documentation suggests these are pertinent for network scanning communication…

https://support.brother.com/g/s/id/htmldoc/mfc/cv_mfc8370dn/gb/html/sug/chapter7.html

This is a misunderstanding. It works again, after I re-opened these ports. I never touched the firewall during and prior to the time printing broke down. My old notes read that these ports are to be opened for functioning of Cups. Else, what do you think, why printing works again after I re-opened them but did not change anything else on the system (same session, first printing blocked, then ports opened and re-boot and everything back to normal…)?

Firewalls control access/behaviour in network environments - nothing to do with USB-connected devices.

Sensible. Then now it is your turn: Why is the printer working after I opened these ports? :\

Out of curiosity, and to eliminate the possibility of a weird coincidence, if you close those ports, does the printer then fail to work again?

Arghhh. I hate errors like this one. I closed the ports and the printer still works. At least that, but for how long? Grrrr

Thank you for this excellent suggestion. And I admit that deano_ferrari was right. Any more hints anyone?

Don’t know if this could be the same issue, but I had weird issues with a ( Samsung ) printer over USB. Had to stop the tlp for it by adding it to /etc/default/tlp . Without it the printer queue would stop after every single print job.
This part IIRC:

# Exclude listed devices from USB autosuspend (separate with spaces).# Use lsusb to get the ids.
# Note: input devices (usbhid) are excluded automatically
# Default: <none>
#USB_BLACKLIST="1111:2222 3333:4444"