Page 1 of 3 123 LastLast
Results 1 to 10 of 26

Thread: After updating no printing: Jobs withheld in Queue.

  1. #1

    Default 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).

    The Cups interface says concerning the jobs e.g.:
    Code:
    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 .

  2. #2
    Join Date
    Sep 2013
    Location
    Norfolk, UK
    Posts
    1,257

    Default Re: After updating no printing: Jobs withheld in Queue.

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

    /var/log/cups/

    Maybe some clues in those...
    Regards, Paul

    2x Tumbleweed (Snapshot: 20191011) KDE Plasma 5
    2x Leap 15.1 KDE Plasma 5

  3. #3

    Default Re: After updating no printing: Jobs withheld in Queue.

    Okay, this is the /var/log/cups/error_log of today:
    Code:
    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...

  4. #4
    Join Date
    Jun 2008
    Location
    Auckland, NZ
    Posts
    20,375
    Blog Entries
    1

    Default Re: After updating no printing: Jobs withheld in Queue.

    Unfortunately, the log snippet you have shared is incomplete. To start with put CUPS into debug mode for more verbose output.
    Code:
    sudo cupsctl --debug-logging
    then clear any existing/stale jobs
    Code:
    sudo cancel -a
    Now watch the error_log with
    Code:
    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
    Code:
    susepaste /var/log/cups/error_log
    and share the link to it here.
    openSUSE Leap 15.0; KDE Plasma 5

  5. #5

    Default Re: After updating no printing: Jobs withheld in Queue.

    Uarghhh, I hate machines sniping at me. I entered your commands and now it is printing. This is the output:
    Code:
    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 .

  6. #6
    Join Date
    Jun 2008
    Location
    Auckland, NZ
    Posts
    20,375
    Blog Entries
    1

    Default Re: After updating no printing: Jobs withheld in Queue.

    Quote Originally Posted by wodenhof View Post
    Uarghhh, I hate machines sniping at me. I entered your commands and now it is printing. This is the output:
    That's great news and of course the log output reflected that.

    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
    Code:
    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
    Code:
    sudo cupsctl --no-debug-logging
    Glad to have been of help.
    openSUSE Leap 15.0; KDE Plasma 5

  7. #7

    Default Re: After updating no printing: Jobs withheld in Queue.

    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.

  8. #8

    Default Re: After updating no printing: Jobs withheld in Queue.

    Nooooo -- it is doing it again and your commands don't help anymore:

    Code:
    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...

  9. #9
    Join Date
    Jun 2008
    Location
    Auckland, NZ
    Posts
    20,375
    Blog Entries
    1

    Default Re: After updating no printing: Jobs withheld in Queue.

    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....
    Code:
    lpstat -t
    openSUSE Leap 15.0; KDE Plasma 5

  10. #10

    Default Re: After updating no printing: Jobs withheld in Queue.

    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":

    Code:
    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.

Page 1 of 3 123 LastLast

Posting Permissions

  • You may not post new threads
  • You may not post replies
  • You may not post attachments
  • You may not edit your posts
  •