cups-filters
cups-filters copied to clipboard
OpenPrinting
No destination host name supplied by cups-browsed for printer
Today I cannot print from my Ubuntu 20.10 laptop. The printer is detected, a print job gets created, stays active for 60 seconds, then goes into waiting. /var/log/cups/errorr_log has
E [24/Nov/2021:14:34:36 +0200] [Job 69] Bad value (0) for orientation-requested, using 0 degrees
at the time when the job is first created, then
E [24/Nov/2021:14:35:36 +0200] [Job 69] No destination host name supplied by cups-browsed for printer \"HP_Color_LaserJet_MFP_M477fdw_15A597_\", is cups-browsed running?
W [24/Nov/2021:14:35:36 +0200] [Job 69] Backend returned status 4 (stop printer)
Printing worked fine just a few days ago, with the same Ubuntu version and the same printers. I'm not sure what changed.
https://github.com/OpenPrinting/cups-filters/issues/97#issuecomment-729612669 suggests creating an issue here.
Please check whether at the time of printing cups-browsed is actually running, as cups-browsed tells the job to which destination to go
cups-browsed is running. restarting cups-browsed doesn't make the problem go away.
Which version of cups-filters do you have
1.28.10-2
How many print queues does cups-browsed generate on your system (the ones with implicitclass:/... in the output of lpstat -v).
Two, which is correct: the printer advertises itself over DNS-SD, and there's a local server (fridge.lan) with a CUPS queue for the same printer. Printing to either queue fails in (almost) the same way; the only difference is that only one of the two queues produces the "Bad value (0) for orientation-requested" error.
lpstat -v shows
$ lpstat -v
device for HP_Color_LaserJet_MFP_M477fdw_15A597_: implicitclass://HP_Color_LaserJet_MFP_M477fdw_15A597_/
device for HP_Color_LaserJet_MFP_M477fdw_fridge: implicitclass://HP_Color_LaserJet_MFP_M477fdw_fridge/
device for ML-1640-Series: usb://Samsung/ML-1640%20Series?serial=144QBAAS601512F.
(the USB printer is currently disconnected and is irrelevant to this bug report)
Please create an issue report here with /etc/cups/cupsd.conf and /etc/cups/cups-browsed.conf attached.
(I've made two changes to cups-browsed.conf, compared to stock ubuntu config: removed cups from BrowseLocalProtocols, and uncommented DebugLogging file stderr.)
Also, here's /var/log/cups/cups-browsed_log after I enabled debug logging and restarted cups-browsed, then tried printing.
Other bug reports had questions about Avahi version, so
avahi-resolve --version
avahi-resolve 0.8
I can ping both fridge.local and cream.local, i.e. DNS-SD name resolution works fine on the system. (Besides, cups-browserd detects the printers fine, so it must be seeing mDNS packets).
I'm not sure how to interpret the cups-browsed_log. The "Remote printer overview" section is interesting, particularly where it says things like cream.local, IP not determined. The only things logged during the actual print job execution and failure are printer state change notifications that don't seem to be saying anything.
I wish I had debug logging enabled from when printing worked fine, so I could see what differs between now and then...
Got my printout after printing again, then manually running cupsenable HP_Color_LaserJet_MFP_M477fdw_15A597_.
Note that cups-browsed skips paused printers when looking for the destination for a job, so if the destination printer of a cups-browsed-generated print queue is paused, cups-browsed does not find a destination and gives the error. So keep an eye that your printers are not paused/disabled when printing.
Also somehow your cups-browsed_log file did not catch the handling of a job.
So should we close this now as you are able to print again?
But wasn't the printer originally paused because of this bug?
And doesn't restarting cups-browserd unpause the printer? (I ask because I see the job getting retried and failing again in error_log after I do systemctl restart cups-browsed.service, and don't touch anything else.)
I've experienced the bug once before, in Ubuntu 21.04, with cups-filters 1.28.8. At the time the workaround mentioned in #321 (restarting cups-browsed) sufficed. This time it didn't.
Also somehow your cups-browsed_log file did not catch the handling of a job.
Yes, that was weird.
I wish I made better notes of what exactly I did; I was sometimes testing by keeping a queued print job and seeing it be retried automatically when I restarted cups-browsed; at other times I deleted the job and printed the file again.
The successful print was after I (1) restarted cups-browsed with debugging enabled, (2) saw an existing print job get retried with no success and scant logging from cups-browsed, (3) deleted the job, (4) printed the file again, then finally (5) ran cupsenable.
The cups-browsed_log attached here was captured after step 2. After step 5 I have a lot of log entries of the successful handling of the job. I could attach the new log, but I'm not sure it's useful.
So should we close this now as you are able to print again?
I don't mind closing the bug, but I have no confidence that it won't come back.
I'm going to keep debug logging enabled so I can provide better logs if this happens again.
I keep hitting a similar bug with Brother network printers on a local network. Printing is extremely unreliable due to it, and I'm not sure what makes it succeed (I generally try to restart cups, cups-browsed and the printer, sometimes to no avail). I'd be happy to provide more information or try debugging things.
See also https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=990331 (I suspected app-armor at some point but I don't think it's the culprit anymore).
One additional idea to try (you need to compile C code for that, also mainly for cases where printing sometimes works and sometimes not):
- First, make sure you have debug logging active as described in the beginning of this thread.
- in the source file
backend/implicitclass.cis a lineusleep(500000);. Double the number in this line, compile (make), copy.libs/implicitclassto/usr/lib/cups/backend(or domake install), try printing again. - Is it more reliable now? If not, or not much more reliable, try doubling the number again. If you arrive at a reliable state, tell us the number at which you have arrived.
- Check the log files for any clues, attach them if in doubt.
- Tell us also how many printers your
cups-browsedis handling (lpstat -v | grep implicitclass: | wc -l).
Today I cannot print again. Excerpts from log files in /var/log/cups:
==> access_log <==
localhost - root [01/Dec/2021:10:35:13 +0200] "POST / HTTP/1.1" 200 349 Create-Printer-Subscriptions successful-ok
localhost - root [01/Dec/2021:10:35:17 +0200] "POST /admin/ HTTP/1.1" 200 181 CUPS-Delete-Printer client-error-not-found
localhost - root [01/Dec/2021:10:35:17 +0200] "POST /admin/ HTTP/1.1" 200 14921 CUPS-Add-Modify-Printer successful-ok
localhost - - [01/Dec/2021:10:37:56 +0200] "POST / HTTP/1.1" 200 181 Renew-Subscription client-error-not-found
localhost - - [01/Dec/2021:11:36:16 +0200] "POST / HTTP/1.1" 200 181 Renew-Subscription client-error-not-found
localhost - - [01/Dec/2021:12:34:36 +0200] "POST / HTTP/1.1" 200 181 Renew-Subscription client-error-not-found
localhost - - [01/Dec/2021:13:32:56 +0200] "POST / HTTP/1.1" 200 181 Renew-Subscription client-error-not-found
localhost - - [01/Dec/2021:14:27:02 +0200] "POST /printers/HP_Color_LaserJet_MFP_M477fdw_15A597_ HTTP/1.1" 200 1581876 Print-Job successful-ok
localhost - - [01/Dec/2021:14:31:16 +0200] "POST / HTTP/1.1" 200 181 Renew-Subscription client-error-not-found
localhost - - [01/Dec/2021:14:31:20 +0200] "POST /admin/ HTTP/1.1" 401 180 Resume-Printer successful-ok
localhost - mg [01/Dec/2021:14:31:20 +0200] "POST /admin/ HTTP/1.1" 200 180 Resume-Printer successful-ok
10:35 is when I woke up the laptop in the office network, 14:27 is when I printed a job, 14:31 is when I ran cupsenable HP_Color_LaserJet_MFP_M477fdw_15A597_
==> error_log <==
W [01/Dec/2021:10:35:17 +0200] CreateProfile failed: org.freedesktop.ColorManager.AlreadyExists:profile id \'HP_Color_LaserJet_MFP_M477fdw_fridge-Gray..\' already exists
W [01/Dec/2021:10:35:17 +0200] CreateProfile failed: org.freedesktop.ColorManager.AlreadyExists:profile id \'HP_Color_LaserJet_MFP_M477fdw_fridge-DeviceN..\' already exists
E [01/Dec/2021:14:27:02 +0200] [Job 71] Bad value (0) for orientation-requested, using 0 degrees
E [01/Dec/2021:14:28:02 +0200] [Job 71] No destination host name supplied by cups-browsed for printer \"HP_Color_LaserJet_MFP_M477fdw_15A597_\", is cups-browsed running?
W [01/Dec/2021:14:28:02 +0200] [Job 71] Backend returned status 4 (stop printer)
E [01/Dec/2021:14:31:20 +0200] [Job 71] Bad value (0) for orientation-requested, using 0 degrees
E [01/Dec/2021:14:32:20 +0200] [Job 71] No destination host name supplied by cups-browsed for printer \"HP_Color_LaserJet_MFP_M477fdw_15A597_\", is cups-browsed running?
W [01/Dec/2021:14:32:20 +0200] [Job 71] Backend returned status 4 (stop printer)
Same as last time: a CreateProfile error on printer discovery, a Bad value error whenever a job is being processed, and a No destination host name supplied error from cups-browsed.
Now the interesting bit: cups-browsed_log.dec1.txt
Printer discovery at 10:35 shows up there. Print jobs at 14:27 or 14:31, however, do not. The only thing that appears are those repeated
nm_properties_changed() in THREAD 139756731443904
messages.
Does this provide any clues to anyone?
I'm also attaching the logrotated cups-browsed_log.1, just in case there might be clues how cups-browsed got into this situation where it ignores jobs: cups-browsed_log.nov29-30.txt
cups-browsed_log.2.gz ends with
Mon Nov 29 12:28:38 2021 NetworkManager ActiveConnections changed
Mon Nov 29 12:28:38 2021 Caught signal 15, shutting down ...
Mon Nov 29 12:28:38 2021 main loop exited
Mon Nov 29 12:28:38 2021 Processing printer list ...
Mon Nov 29 12:28:38 2021 === Remote printer overview ===
Mon Nov 29 12:28:38 2021 ===============================
Mon Nov 29 12:28:38 2021 === Remote printer overview ===
Mon Nov 29 12:28:38 2021 ===============================
Mon Nov 29 12:28:38 2021 Error subscribing to CUPS notifications: Subscription #1751 does not exist.
Mon Nov 29 12:28:38 2021 cups-browsed [BrowsePoll /run/cups/cups.sock:0]: IPP-Cancel-Subscription
Mon Nov 29 12:28:38 2021 cupsd-browsed [BrowsePoll /run/cups/cups.sock:0]: failed: Subscription #1750 does not exist.
Mon Nov 29 12:28:38 2021 free_local_printer() in THREAD 140102439914176
so I think older logrotated files aren't relevant.
Since I had to print, I did a sudo systemctl restart cups-browsed.log, a bunch of cupsenables that didn't do anything, one cupsdisable + cupsenable pair ditto, and then I figured out the job itself was paused and so I found the GUI button to resume it. Twice (1st failed with the same error, 2nd worked fine).
Additional logs:
==> access_log <==
localhost - root [01/Dec/2021:14:46:09 +0200] "POST /admin/ HTTP/1.1" 200 223 Pause-Printer successful-ok
localhost - root [01/Dec/2021:14:46:09 +0200] "POST /admin/ HTTP/1.1" 200 181 CUPS-Delete-Printer successful-ok
localhost - root [01/Dec/2021:14:46:09 +0200] "POST / HTTP/1.1" 200 123 Cancel-Subscription client-error-not-found
localhost - - [01/Dec/2021:14:46:09 +0200] "POST / HTTP/1.1" 200 152 Cancel-Subscription successful-ok
localhost - - [01/Dec/2021:14:46:09 +0200] "POST / HTTP/1.1" 200 349 Create-Printer-Subscriptions successful-ok
localhost - - [01/Dec/2021:14:46:09 +0200] "POST / HTTP/1.1" 200 176 Create-Printer-Subscriptions successful-ok
localhost - - [01/Dec/2021:14:46:11 +0200] "POST /admin/ HTTP/1.1" 401 180 Resume-Printer successful-ok
localhost - mg [01/Dec/2021:14:46:11 +0200] "POST /admin/ HTTP/1.1" 200 180 Resume-Printer successful-ok
localhost - - [01/Dec/2021:14:46:13 +0200] "POST /admin/ HTTP/1.1" 401 239 CUPS-Add-Modify-Printer successful-ok
localhost - root [01/Dec/2021:14:46:13 +0200] "POST /admin/ HTTP/1.1" 200 239 CUPS-Add-Modify-Printer successful-ok
localhost - root [01/Dec/2021:14:46:13 +0200] "POST /admin/ HTTP/1.1" 200 232 CUPS-Add-Modify-Printer successful-ok
localhost - root [01/Dec/2021:14:46:13 +0200] "POST /admin/ HTTP/1.1" 200 232 CUPS-Add-Modify-Printer successful-ok
localhost - root [01/Dec/2021:14:46:16 +0200] "POST /admin/ HTTP/1.1" 200 15996 CUPS-Add-Modify-Printer successful-ok
localhost - root [01/Dec/2021:14:46:16 +0200] "POST /admin/ HTTP/1.1" 200 206 CUPS-Add-Modify-Printer successful-ok
localhost - root [01/Dec/2021:14:46:16 +0200] "POST /admin/ HTTP/1.1" 200 181 CUPS-Delete-Printer client-error-not-found
localhost - root [01/Dec/2021:14:46:16 +0200] "POST /admin/ HTTP/1.1" 200 14921 CUPS-Add-Modify-Printer successful-ok
localhost - - [01/Dec/2021:14:47:08 +0200] "POST /admin/ HTTP/1.1" 401 180 Resume-Printer successful-ok
localhost - mg [01/Dec/2021:14:47:08 +0200] "POST /admin/ HTTP/1.1" 200 180 Resume-Printer successful-ok
localhost - - [01/Dec/2021:14:47:15 +0200] "POST /admin/ HTTP/1.1" 401 180 Pause-Printer successful-ok
localhost - mg [01/Dec/2021:14:47:15 +0200] "POST /admin/ HTTP/1.1" 200 180 Pause-Printer successful-ok
localhost - - [01/Dec/2021:14:47:17 +0200] "POST /admin/ HTTP/1.1" 401 180 Resume-Printer successful-ok
localhost - mg [01/Dec/2021:14:47:17 +0200] "POST /admin/ HTTP/1.1" 200 180 Resume-Printer successful-ok
localhost - - [01/Dec/2021:14:47:29 +0200] "POST / HTTP/1.1" 200 342 Create-Printer-Subscriptions successful-ok
localhost - - [01/Dec/2021:14:47:29 +0200] "POST / HTTP/1.1" 200 5236835 CUPS-Get-PPDs -
localhost - - [01/Dec/2021:14:47:38 +0200] "POST /jobs/ HTTP/1.1" 200 164 Set-Job-Attributes successful-ok
localhost - root [01/Dec/2021:14:47:39 +0200] "POST /admin/ HTTP/1.1" 200 310 CUPS-Add-Modify-Printer successful-ok
localhost - - [01/Dec/2021:14:48:05 +0200] "POST /jobs/ HTTP/1.1" 200 164 Set-Job-Attributes successful-ok
localhost - root [01/Dec/2021:14:48:07 +0200] "POST /admin/ HTTP/1.1" 200 310 CUPS-Add-Modify-Printer successful-ok
localhost - - [01/Dec/2021:14:49:02 +0200] "POST / HTTP/1.1" 200 150 Cancel-Subscription successful-ok
localhost - - [01/Dec/2021:14:49:02 +0200] "POST / HTTP/1.1" 200 150 Cancel-Subscription client-error-not-found
==> error_log <==
E [01/Dec/2021:14:46:11 +0200] [Job 71] Bad value (0) for orientation-requested, using 0 degrees
E [01/Dec/2021:14:46:13 +0200] [Job 71] No suitable destination host found by cups-browsed.
W [01/Dec/2021:14:46:13 +0200] [Job 71] Backend returned status 6 (retry job later)
W [01/Dec/2021:14:46:16 +0200] CreateProfile failed: org.freedesktop.ColorManager.AlreadyExists:profile id \'HP_Color_LaserJet_MFP_M477fdw_15A597_-Gray..\' already exists
W [01/Dec/2021:14:46:16 +0200] CreateProfile failed: org.freedesktop.ColorManager.AlreadyExists:profile id \'HP_Color_LaserJet_MFP_M477fdw_15A597_-DeviceN..\' already exists
W [01/Dec/2021:14:46:16 +0200] CreateProfile failed: org.freedesktop.ColorManager.AlreadyExists:profile id \'HP_Color_LaserJet_MFP_M477fdw_fridge-Gray..\' already exists
W [01/Dec/2021:14:46:16 +0200] CreateProfile failed: org.freedesktop.ColorManager.AlreadyExists:profile id \'HP_Color_LaserJet_MFP_M477fdw_fridge-DeviceN..\' already exists
E [01/Dec/2021:14:47:38 +0200] [Job 71] No suitable destination host found by cups-browsed.
E [01/Dec/2021:14:47:38 +0200] [Job 71] Bad value (0) for orientation-requested, using 0 degrees
W [01/Dec/2021:14:47:38 +0200] [Job 71] Backend returned status 6 (retry job later)
E [01/Dec/2021:14:48:05 +0200] [Job 71] Bad value (0) for orientation-requested, using 0 degrees
cups-browsed_log is too big for excerpts, so here's a full version: cups-browsed_log.dec1.success.txt
Curiously I see that it ends with the same
Mon Nov 29 12:28:38 2021 Caught signal 15, shutting down ...
Mon Nov 29 12:28:38 2021 main loop exited
Mon Nov 29 12:28:38 2021 Processing printer list ...
Mon Nov 29 12:28:38 2021 === Remote printer overview ===
Mon Nov 29 12:28:38 2021 ===============================
Mon Nov 29 12:28:38 2021 === Remote printer overview ===
Mon Nov 29 12:28:38 2021 ===============================
Mon Nov 29 12:28:38 2021 Error subscribing to CUPS notifications: Subscription #1751 does not exist.
Mon Nov 29 12:28:38 2021 cups-browsed [BrowsePoll /run/cups/cups.sock:0]: IPP-Cancel-Subscription
Mon Nov 29 12:28:38 2021 cupsd-browsed [BrowsePoll /run/cups/cups.sock:0]: failed: Subscription #1750 does not exist.
Mon Nov 29 12:28:38 2021 free_local_printer() in THREAD 140102439914176
bit that I earlier assumed the service was shutting down, what with the "shutting down ..." and "main loop exited", but ps shows that the process is still running:
$ ps -o pid,lstart,etime,cmd $(pgrep cups-browsed)
PID STARTED ELAPSED CMD
1934848 Wed Dec 1 14:46:09 2021 06:47 /usr/sbin/cups-browsed
~~Could this be a clue? main loop exits, so cups-browsed stops responding to hostname and whatnot queries issued by cupsd? Some other threads keep the cups-browsed process itself alive, so systemd doesn't restart it.~~
I just printed a test page and it came out fine, so no, that's a red herring.
@mgedmin Could it be that you had 2 cups-browsed processes running? The log output of the shutdown sequence would be then from one and the process you have seen afterwards from the other. And while there were two cups-browsed processes running, competing somehow with each other you were not able to print and as soon as one got shut down you could print, controlled by the other.
So check whether there is more than one cups-browsed running if you cannot print again.
Do a sudo killall cups-browsed to terminate all cups-browsed processes. If your system uses systemd then systemd will start one single cups-browsed (watch dog/automatic crash recovery). Now printing should work again.
I have the atop daemon running in the background, which records system snapshots (such as PIDs and command lines) every 10 minutes. Looking at the log file for Nov 29 and Nov 30, I see that only one cups-browsed process is running at one time, but the PID changes after each main loop exited message. By some coincidence atop's own log files are rotated at the exact same time, so I think this is anacron running daily jobs on my laptop.
Looking at these cups-browsed restart timestamps, I think I got mixed up between terminal tabs and log files in my earlier comment -- there was no restart on Dec 1:
mg@blynas: /var/log/cups $ zgrep 'main loop exi' cups-browsed_log*
cups-browsed_log.1:Wed Dec 8 12:32:22 2021 main loop exited
cups-browsed_log.2.gz:Tue Dec 7 13:57:52 2021 main loop exited
cups-browsed_log.3.gz:Mon Dec 6 15:23:41 2021 main loop exited
cups-browsed_log.4.gz:Sat Dec 4 10:54:54 2021 main loop exited
cups-browsed_log.5.gz:Tue Nov 30 10:23:10 2021 main loop exited
cups-browsed_log.6.gz:Mon Nov 29 12:28:38 2021 main loop exited
cups-browsed_log.7.gz:Sat Nov 27 07:33:47 2021 main loop exited
cups-browsed_log.7.gz:Sun Nov 28 10:22:12 2021 main loop exited
There are two different issues for the same bug, #357 and #429. What is the difference between them, because I have not been able to find one. Maybe one should be closed and marked as duplicate of the other.
I am running into the same issue on several machines running Ubuntu 20.04, I might be able to help out if any more information is needed. Is that the case, is there something to test out?
@mgedmin Could you please enable CUPS debugging and attach all the log files here again after an unsuccessful print job?
To enable CUPS debugging, run:
cupsctl --debug-logging
and then restart CUPS.
@makuser If you are running into the same issue, could you attach your CUPS error_log and cups-browsed_log (with debugging enabled) here after handling an unsuccessful print job? Enable CUPS debugging as shown above. cups-browsed debugging can be enabled by editing /etc/cups/cups-browsed.conf and adding this line:
DebugLogging file
and then restarting cups-browsed.
Perhaps the problem is caused by AppArmor settings.
See:
https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=990331
So look for messages containing audit in the syslog.
Is there a way of testing whether cupsd can talk to cups-browsed and get a valid IP, without wasting paper? I've been delaying additional testing on this issue because I don't have anything I want to print (and I irrationally believe that printing would work if the only reason I did it was to reproduce a bug).
The apparmor allegations have been mentioned before, in an earlier comment, and don't quite explain why the bug would be non-deterministic and go away after restarting/unpausing/retrying things without adjusting AppArmor profiles or enforcement rules...