Bug#887495: cups-browsed: 'No destination host name supplied by cups-browsed for printer "name", is cups-browsed running?' for all queues
Package: cups-browsed
Version: 1.11.6-3
Severity: normal
We have a central cups print server (and one client offering a queue for a not network-connected printer) and about 50 identically configured clients running a current stable using it to print. On one specific client sometimes all printer queues stop working, giving the error message 'No destination host name supplied by cups-browsed for printer "name of the queue", is cups-browsed running?'.
Restarting the cups and cups-browsed services does not fix the behaviour; most of the times a reboot does, but not always.
Comparing the two browsed debug logs of the affected and and unaffected client I notice after printing (or trying to print) a test page, that the affected one is missing the lines, showing that the cups server contacted it. I'll attach the excerpt of the cups debug log showing the last connection attempts (of forty before cups gives up) below.
Changes to queues on the server get communicated through to cups by cups-browsed so communication in that direction seems to be working.
Both cups and cups-browsed on the client are currently running with the debug logs enabled, so if you need any more info I'll hopefully be able to provide it.
Probably just a coincidence but I'll mention it: The user of the affected client is the only one of ours that's running KDE as desktop.
-- System Information:
Debian Release: 9.3
APT prefers stable-updates
APT policy: (500, 'stable-updates'), (500, 'stable')
Architecture: amd64 (x86_64)
Kernel: Linux 4.9.0-5-amd64 (SMP w/4 CPU cores)
Locale: LANG=de_DE.UTF-8, LC_CTYPE=de_DE.UTF-8 (charmap=UTF-8), LANGUAGE=en_US:en (charmap=UTF-8)
Shell: /bin/sh linked to /bin/dash
Init: systemd (via /run/systemd/system)
Versions of packages cups-browsed depends on:
ii cups-daemon 2.2.1-8
ii init-system-helpers 1.48
ii libavahi-client3 0.6.32-2
ii libavahi-common3 0.6.32-2
ii libavahi-glib1 0.6.32-2
ii libc6 2.24-11+deb9u1
ii libcups2 2.2.1-8
ii libglib2.0-0 2.50.3-2
ii libldap-2.4-2 2.4.44+dfsg-5+deb9u1
ii lsb-base 9.20161125
Versions of packages cups-browsed recommends:
ii avahi-daemon 0.6.32-2
cups-browsed suggests no packages.
-- Configuration Files:
/etc/cups/cups-browsed.conf changed:
LogDir /var/log/cups
DebugLogging file
BrowseRemoteProtocols cups
BrowseAllow 141.66.176.24
BrowseAllow cups.zblmath.fiz-karlsruhe.de
BrowsePoll 141.66.176.24
BrowsePoll cups.zblmath.fiz-karlsruhe.de
-- debconf-show failed
/var/log/cups/error_log:
D [17/Jan/2018:12:56:41 +0100] [Client 52] Closing connection.
D [17/Jan/2018:12:56:41 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
d [17/Jan/2018:12:56:41 +0100] cupsdRemoveSelect(fd=21)
d [17/Jan/2018:12:56:41 +0100] cupsdRemoveSelect(fd=-1)
I [17/Jan/2018:12:56:41 +0100] Expiring subscriptions...
d [17/Jan/2018:12:56:41 +0100] select_timeout: JobHistoryUpdate=0
d [17/Jan/2018:12:56:41 +0100] cupsdAcceptClient(lis=0x559574abed90(3)) Clients=4
D [17/Jan/2018:12:56:41 +0100] [Client 53] Server address is "/var/run/cups/cups.sock".
D [17/Jan/2018:12:56:41 +0100] [Client 53] Accepted from localhost (Domain)
d [17/Jan/2018:12:56:41 +0100] cupsdAddSelect(fd=21, read_cb=0x55957473c370, write_cb=(nil), data=0x5595753122a0)
D [17/Jan/2018:12:56:41 +0100] [Client 53] Waiting for request.
d [17/Jan/2018:12:56:41 +0100] select_timeout: JobHistoryUpdate=0
d [17/Jan/2018:12:56:41 +0100] [Client 53] cupsdReadClient: error=0, used=0, state=HTTP_STATE_WAITING, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=0, request=(nil)(), file=-1
D [17/Jan/2018:12:56:41 +0100] [Client 53] POST / HTTP/1.1
D [17/Jan/2018:12:56:41 +0100] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Printing jobs and dirty files"
D [17/Jan/2018:12:56:41 +0100] [Client 53] Read: status=200
d [17/Jan/2018:12:56:41 +0100] cupsdFindBest: uri="/", limit=10...
d [17/Jan/2018:12:56:41 +0100] cupsdFindBest: Location /admin/conf(11) Limit 7f
d [17/Jan/2018:12:56:41 +0100] cupsdFindBest: Location /admin(6) Limit 7f
d [17/Jan/2018:12:56:41 +0100] cupsdFindBest: Location /(1) Limit 7f
d [17/Jan/2018:12:56:41 +0100] cupsdFindBest: best=/
d [17/Jan/2018:12:56:41 +0100] [Client 53] con->uri="/", con->best=0x559574abe120(/)
D [17/Jan/2018:12:56:41 +0100] [Client 53] No authentication data provided.
d [17/Jan/2018:12:56:41 +0100] cupsdIsAuthorized: con->uri="/", con->best=0x559574abe120(/)
d [17/Jan/2018:12:56:41 +0100] cupsdIsAuthorized: level=CUPSD_AUTH_ANON, type=None, satisfy=CUPSD_AUTH_SATISFY_ALL, num_names=0
d [17/Jan/2018:12:56:41 +0100] cupsdIsAuthorized: auth=CUPSD_AUTH_ALLOW...
D [17/Jan/2018:12:56:41 +0100] [Client 53] 2.0 Get-Printer-Attributes 39
d [17/Jan/2018:12:56:41 +0100] cupsdProcessIPPRequest(0x5595753122a0[53]): operation_id = 000b
D [17/Jan/2018:12:56:41 +0100] Get-Printer-Attributes ipp://localhost:631/printers/copier
d [17/Jan/2018:12:56:41 +0100] get_printer_attrs(0x5595753122a0[53], ipp://localhost:631/printers/copier)
d [17/Jan/2018:12:56:41 +0100] cupsdFindPolicyOp(p=0x559574abf450, op=b(Get-Printer-Attributes))
d [17/Jan/2018:12:56:41 +0100] cupsdFindPolicyOp: Found wildcard match...
d [17/Jan/2018:12:56:41 +0100] cupsdIsAuthorized: con->uri="/", con->best=0x559574ac2d70((null))
d [17/Jan/2018:12:56:41 +0100] cupsdIsAuthorized: level=CUPSD_AUTH_ANON, type=None, satisfy=CUPSD_AUTH_SATISFY_ALL, num_names=0
d [17/Jan/2018:12:56:41 +0100] cupsdIsAuthorized: op=0(0x0000)
d [17/Jan/2018:12:56:41 +0100] cupsdIsAuthorized: auth=CUPSD_AUTH_ALLOW...
d [17/Jan/2018:12:56:41 +0100] copy_attrs(to=0x55957530cef0, from=0x559574b803a0, ra=0x55957530cc10, group=0, quickcopy=0)
d [17/Jan/2018:12:56:41 +0100] copy_attrs(to=0x55957530cef0, from=0x559574b80650, ra=0x55957530cc10, group=0, quickcopy=0)
d [17/Jan/2018:12:56:41 +0100] copy_attrs(to=0x55957530cef0, from=0x559574ae2130, ra=0x55957530cc10, group=0, quickcopy=-2147483648)
D [17/Jan/2018:12:56:41 +0100] [Client 53] Returning IPP successful-ok for Get-Printer-Attributes (ipp://localhost:631/printers/copier) from localhost
D [17/Jan/2018:12:56:41 +0100] [Client 53] Content-Length: 680
D [17/Jan/2018:12:56:41 +0100] [Client 53] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
d [17/Jan/2018:12:56:41 +0100] cupsdAddSelect(fd=21, read_cb=0x55957473c370, write_cb=0x55957473ba50, data=0x5595753122a0)
d [17/Jan/2018:12:56:41 +0100] select_timeout: JobHistoryUpdate=0
D [17/Jan/2018:12:56:41 +0100] [Client 53] con->http=0x55957531d170
D [17/Jan/2018:12:56:41 +0100] [Client 53] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=680, response=0x55957530cef0(IPP_STATE_DATA),
pipe_pid=0, file=-1
D [17/Jan/2018:12:56:41 +0100] [Client 53] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [17/Jan/2018:12:56:41 +0100] [Client 53] bytes=0, http_state=0, data_remaining=680
D [17/Jan/2018:12:56:41 +0100] [Client 53] Flushing write buffer.
D [17/Jan/2018:12:56:41 +0100] [Client 53] New state is HTTP_STATE_WAITING
d [17/Jan/2018:12:56:41 +0100] cupsdAddSelect(fd=21, read_cb=0x55957473c370, write_cb=(nil), data=0x5595753122a0)
D [17/Jan/2018:12:56:41 +0100] [Client 53] Waiting for request.
D [17/Jan/2018:12:56:41 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files"
d [17/Jan/2018:12:56:41 +0100] select_timeout: JobHistoryUpdate=0
D [17/Jan/2018:12:56:41 +0100] [Job 578] Read cups-browsed-dest-printer option: (null)
d [17/Jan/2018:12:56:41 +0100] select_timeout: JobHistoryUpdate=0
d [17/Jan/2018:12:56:41 +0100] [Client 53] cupsdReadClient: error=0, used=0, state=HTTP_STATE_WAITING, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=0, request=(nil)(), file=-1
D [17/Jan/2018:12:56:41 +0100] [Client 53] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [17/Jan/2018:12:56:41 +0100] [Client 53] Closing connection.
D [17/Jan/2018:12:56:41 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
d [17/Jan/2018:12:56:41 +0100] cupsdRemoveSelect(fd=21)
d [17/Jan/2018:12:56:41 +0100] cupsdRemoveSelect(fd=-1)
d [17/Jan/2018:12:56:41 +0100] select_timeout: JobHistoryUpdate=0
d [17/Jan/2018:12:56:41 +0100] cupsdAcceptClient(lis=0x559574abed90(3)) Clients=4
D [17/Jan/2018:12:56:41 +0100] [Client 54] Server address is "/var/run/cups/cups.sock".
D [17/Jan/2018:12:56:41 +0100] [Client 54] Accepted from localhost (Domain)
d [17/Jan/2018:12:56:41 +0100] cupsdAddSelect(fd=21, read_cb=0x55957473c370, write_cb=(nil), data=0x5595753122a0)
D [17/Jan/2018:12:56:41 +0100] [Client 54] Waiting for request.
d [17/Jan/2018:12:56:41 +0100] select_timeout: JobHistoryUpdate=0
d [17/Jan/2018:12:56:41 +0100] [Client 54] cupsdReadClient: error=0, used=0, state=HTTP_STATE_WAITING, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=0, request=(nil)(), file=-1
D [17/Jan/2018:12:56:41 +0100] [Client 54] POST / HTTP/1.1
D [17/Jan/2018:12:56:41 +0100] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Printing jobs and dirty files"
D [17/Jan/2018:12:56:41 +0100] [Client 54] Read: status=200
d [17/Jan/2018:12:56:41 +0100] cupsdFindBest: uri="/", limit=10...
d [17/Jan/2018:12:56:41 +0100] cupsdFindBest: Location /admin/conf(11) Limit 7f
d [17/Jan/2018:12:56:41 +0100] cupsdFindBest: Location /admin(6) Limit 7f
d [17/Jan/2018:12:56:41 +0100] cupsdFindBest: Location /(1) Limit 7f
d [17/Jan/2018:12:56:41 +0100] cupsdFindBest: best=/
d [17/Jan/2018:12:56:41 +0100] [Client 54] con->uri="/", con->best=0x559574abe120(/)
D [17/Jan/2018:12:56:41 +0100] [Client 54] No authentication data provided.
d [17/Jan/2018:12:56:41 +0100] cupsdIsAuthorized: con->uri="/", con->best=0x559574abe120(/)
d [17/Jan/2018:12:56:41 +0100] cupsdIsAuthorized: level=CUPSD_AUTH_ANON, type=None, satisfy=CUPSD_AUTH_SATISFY_ALL, num_names=0
d [17/Jan/2018:12:56:41 +0100] cupsdIsAuthorized: auth=CUPSD_AUTH_ALLOW...
D [17/Jan/2018:12:56:41 +0100] [Client 54] 2.0 Get-Printer-Attributes 40
d [17/Jan/2018:12:56:41 +0100] cupsdProcessIPPRequest(0x5595753122a0[54]): operation_id = 000b
D [17/Jan/2018:12:56:41 +0100] Get-Printer-Attributes ipp://localhost:631/printers/copier
d [17/Jan/2018:12:56:41 +0100] get_printer_attrs(0x5595753122a0[54], ipp://localhost:631/printers/copier)
d [17/Jan/2018:12:56:41 +0100] cupsdFindPolicyOp(p=0x559574abf450, op=b(Get-Printer-Attributes))
d [17/Jan/2018:12:56:41 +0100] cupsdFindPolicyOp: Found wildcard match...
d [17/Jan/2018:12:56:41 +0100] cupsdIsAuthorized: con->uri="/", con->best=0x559574ac2d70((null))
d [17/Jan/2018:12:56:41 +0100] cupsdIsAuthorized: level=CUPSD_AUTH_ANON, type=None, satisfy=CUPSD_AUTH_SATISFY_ALL, num_names=0
d [17/Jan/2018:12:56:41 +0100] cupsdIsAuthorized: op=0(0x0000)
d [17/Jan/2018:12:56:41 +0100] cupsdIsAuthorized: auth=CUPSD_AUTH_ALLOW...
d [17/Jan/2018:12:56:41 +0100] copy_attrs(to=0x55957530cef0, from=0x559574b803a0, ra=0x55957530cc10, group=0, quickcopy=0)
d [17/Jan/2018:12:56:41 +0100] copy_attrs(to=0x55957530cef0, from=0x559574b80650, ra=0x55957530cc10, group=0, quickcopy=0)
d [17/Jan/2018:12:56:41 +0100] copy_attrs(to=0x55957530cef0, from=0x559574ae2130, ra=0x55957530cc10, group=0, quickcopy=-2147483648)
D [17/Jan/2018:12:56:41 +0100] [Client 54] Returning IPP successful-ok for Get-Printer-Attributes (ipp://localhost:631/printers/copier) from localhost
D [17/Jan/2018:12:56:41 +0100] [Client 54] Content-Length: 680
D [17/Jan/2018:12:56:41 +0100] [Client 54] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
d [17/Jan/2018:12:56:41 +0100] cupsdAddSelect(fd=21, read_cb=0x55957473c370, write_cb=0x55957473ba50, data=0x5595753122a0)
d [17/Jan/2018:12:56:41 +0100] select_timeout: JobHistoryUpdate=0
D [17/Jan/2018:12:56:41 +0100] [Client 54] con->http=0x55957531d170
D [17/Jan/2018:12:56:41 +0100] [Client 54] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=680, response=0x55957530cef0(IPP_STATE_DATA),
pipe_pid=0, file=-1
D [17/Jan/2018:12:56:41 +0100] [Client 54] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [17/Jan/2018:12:56:41 +0100] [Client 54] bytes=0, http_state=0, data_remaining=680
D [17/Jan/2018:12:56:41 +0100] [Client 54] Flushing write buffer.
D [17/Jan/2018:12:56:41 +0100] [Client 54] New state is HTTP_STATE_WAITING
d [17/Jan/2018:12:56:41 +0100] cupsdAddSelect(fd=21, read_cb=0x55957473c370, write_cb=(nil), data=0x5595753122a0)
D [17/Jan/2018:12:56:41 +0100] [Client 54] Waiting for request.
D [17/Jan/2018:12:56:41 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files"
d [17/Jan/2018:12:56:41 +0100] select_timeout: JobHistoryUpdate=0
D [17/Jan/2018:12:56:41 +0100] [Job 578] Read cups-browsed-dest-printer option: (null)
d [17/Jan/2018:12:56:41 +0100] select_timeout: JobHistoryUpdate=0
E [17/Jan/2018:12:56:42 +0100] [Job 578] No destination host name supplied by cups-browsed for printer \"copier\", is cups-browsed running?
D [17/Jan/2018:12:56:42 +0100] cupsdMarkDirty(---J-)
D [17/Jan/2018:12:56:42 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [17/Jan/2018:12:56:42 +0100] cupsdMarkDirty(---J-)
D [17/Jan/2018:12:56:42 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [17/Jan/2018:12:56:42 +0100] [Job 578] Set job-printer-state-message to "No destination host name supplied by cups-browsed for printer \"copier\", is cups-browsed running?", current level=ERROR
d [17/Jan/2018:12:56:42 +0100] cupsdAddEvent(event=job-progress, dest=0x559574af7eb0(copier), job=0x55957530d5b0(578), text="%s", ...)
d [17/Jan/2018:12:56:42 +0100] cupsd_send_notification(sub=0x559574ace620(183), event=0x559575300740(job-progress))
d [17/Jan/2018:12:56:42 +0100] sub->pipe=16
--
FIZ Karlsruhe - Leibniz-Institut für Informationsinfrastruktur GmbH.
Sitz der Gesellschaft: Eggenstein-Leopoldshafen, Amtsgericht Mannheim, HRB 101892.
Geschäftsführerin: Sabine Brünger-Weilandt.
Vorsitzender des Aufsichtsrats: MinDirig Dr. Stefan Luther.
Reply to: