Bug 1276918 - cups-browsed stops working after suspend/resume
cups-browsed stops working after suspend/resume
Status: CLOSED CURRENTRELEASE
Product: Fedora
Classification: Fedora
Component: cups-filters (Show other bugs)
27
Unspecified Unspecified
unspecified Severity unspecified
: ---
: ---
Assigned To: Zdenek Dohnal
Fedora Extras Quality Assurance
: Reopened
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2015-11-01 05:03 EST by Tore Anderson
Modified: 2018-02-01 11:11 EST (History)
5 users (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2018-02-01 11:11:39 EST
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)
cups-browsed debug log (12.79 KB, text/plain)
2015-11-02 15:48 EST, Tore Anderson
no flags Details
cups-browsed 1.8.3-1 debug log when reproducing (13.32 KB, text/plain)
2016-04-03 05:09 EDT, Tore Anderson
no flags Details

  None (edit)
Description Tore Anderson 2015-11-01 05:03:36 EST
Description of problem:

After bootup (or restart of the cups-browsed service), cups discovers the remote printer found on the print server specified by BrowsePoll, and it can be printed to just fine. However, after suspending/resuming, the discovered printered vanishes, and stays gone until cups-browsed is restarted.

Version-Release number of selected component (if applicable):

cups-filters-1.0.71-1.fc22.x86_64

How reproducible:

100% (on multiple systems)

Steps to Reproduce:
1. (Re)start cups-browsed, observe how remote printers on the RemotePoll service shows up and are available for printing
2. Suspend
3. Wait a while (not exactly how sure how long is necessary, but "overnight" is the usual case for me)
4. Resume

Actual results:

The printer discovered in step #1 is removed from the system. No printing can occur.

Expected results:

The printer discovered in step #1 would stay available

Additional info:

The only change to the default cups-browsed.conf is the addition of the BrowsePoll directive.

When the printer is discovered, the following is shown in /var/log/cups/access_log:

localhost - - [31/Oct/2015:12:15:30 +0100] "POST / HTTP/1.1" 200 152 Cancel-Subscription successful-ok
localhost - - [31/Oct/2015:12:15:30 +0100] "POST / HTTP/1.1" 200 349 Create-Printer-Subscriptions successful-ok
localhost - - [31/Oct/2015:12:15:33 +0100] "POST /admin/ HTTP/1.1" 401 370 CUPS-Add-Modify-Printer successful-ok
localhost - root [31/Oct/2015:12:15:33 +0100] "POST /admin/ HTTP/1.1" 200 370 CUPS-Add-Modify-Printer successful-ok

When the system is resumed from suspend, the following log lines appear:

localhost - - [01/Nov/2015:10:48:45 +0100] "POST /admin/ HTTP/1.1" 401 149 CUPS-Delete-Printer successful-ok
localhost - root [01/Nov/2015:10:48:45 +0100] "POST /admin/ HTTP/1.1" 200 149 CUPS-Delete-Printer successful-ok

So it would apear that the deletion is something that happens explicitly. The question is why.
Comment 1 Tim Waugh 2015-11-02 04:42:01 EST
I would expect it to delete the printer in between resuming from suspend and receiving the first browse packet from it since resuming. But doesn't it add the printer back when it receives a browse packet from it? (It might take 60s or so.)
Comment 2 Tore Anderson 2015-11-02 04:54:41 EST
No, it doesn't get added back.

I might have misunderstood what you meant with "receiving the first browse packet", but I don't see how the client running cups-browsed can receive any packets from the print server unless it explicitly has asked for them?

I guess that after a sufficiently long suspend/resume cycle, cups-browsed will have likely lost contact with the print server, and would need to actively reconnect to it in order to determine which printers are available, but it doesn't do that (unless I restart the process).
Comment 3 Tim Waugh 2015-11-02 07:45:40 EST
Oh, that's right, you're using BrowsePoll. However, it doesn't keep an active connection but instead creates a new connection each time it polls.

Could you please enable debug logging for cups-browsed? You can do so like this:

(sudo su -)
# cat <<"EOF" >/etc/systemd/system/cups-browsed.service
[Unit]
Description=Make remote CUPS printers available locally
After=cups.service avahi-daemon.service
Wants=cups.service avahi-daemon.service

[Service]
ExecStart=/usr/sbin/cups-browsed --debug

[Install]
WantedBy=multi-user.target
EOF
# systemctl daemon-reload
# systemctl restart cups-browsed.service

Afterwards you can see its debugging output by running 'journalctl -u cups-browsed.service'.

To turn off debugging after you've caught it failing:

# rm /etc/systemd/system/cups-browsed.service
# systemctl daemon-reload
# systemctl restart cups-browsed.service

What debugging output do you get after a resume causes it to fail again?
Comment 4 Tore Anderson 2015-11-02 15:48 EST
Created attachment 1088717 [details]
cups-browsed debug log

I've attached the requested logs.

The system was suspended at 21:07 and resumed at 21:38. I confirmed that the printer was visible before the suspend and that it did not re-appear after the resume (even after waiting a while).

It would appear that cups-browsed does continue polling the print server after the resume, and that it does re-discover the printer. In spite of that, no "Creating/Updating CUPS queue" message appears after the resume, which does strike me as very suspect.
Comment 5 Tore Anderson 2015-11-03 02:29:47 EST
FYI, I found an easy way to reproduce the problem without requiring a suspend/resume cycle:

$ kill -STOP $(pidof cups-browsed); sleep 310; kill -CONT $(pidof cups-browsed)
Comment 6 Tore Anderson 2016-04-03 05:09 EDT
Created attachment 1142950 [details]
cups-browsed 1.8.3-1 debug log when reproducing

I just re-verified that the problem exists as of cups-filters-1.8.3-1.fc23.x86_64.rpm. The behaviour has however changed somewhat, as I can no longer reproduce it with the simple method described in comment #5.

It seems that it now essential that the network is disconnected/unavailable when cups-browsed is waking up, so that the initial browse poll fails. If that happens, it will not recover - even though subsequent browse polls succeeds and the remote printer is discovered, the print queue is not recreated and applications can not print to it.

To reproduce the problem:

* Start cups-browsed (the remote printer should show up in applications)
* Send cups-browsed SIGSTOP
* Wait a while (five minutes)
* Disconnect/disable networking
* Send cups-browsed SIGCONT
* Wait a few seconds to let cups-browsed attempt (and fail) a browse poll
* Reconnect networking and wait wait for cups-browsed to attempt another periodic browse poll

At this point, it is evident from reading the debug logs that cups-browsed has successfully reconnected to the remote print server and found the remote print queue. However, as I mentioned earlier, it is not available for printing to in applications.

I am attaching an updated cups-browsed debug log. I've also annotated it to illustrate when cups-browsed was sent the various signals and when the network connectivity was changed.

Tore
Comment 7 Fedora Admin XMLRPC Client 2016-06-24 06:32:30 EDT
This package has changed ownership in the Fedora Package Database.  Reassigning to the new owner of this component.
Comment 8 Fedora End Of Life 2016-11-24 08:00:42 EST
This message is a reminder that Fedora 23 is nearing its end of life.
Approximately 4 (four) weeks from now Fedora will stop maintaining
and issuing updates for Fedora 23. It is Fedora's policy to close all
bug reports from releases that are no longer maintained. At that time
this bug will be closed as EOL if it remains open with a Fedora  'version'
of '23'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, simply change the 'version' 
to a later Fedora version.

Thank you for reporting this issue and we are sorry that we were not 
able to fix it before Fedora 23 is end of life. If you would still like 
to see this bug fixed and are able to reproduce it against a later version 
of Fedora, you are encouraged  change the 'version' to a later Fedora 
version prior this bug is closed as described in the policy above.

Although we aim to fix as many bugs as possible during every release's 
lifetime, sometimes those efforts are overtaken by events. Often a 
more recent Fedora release includes newer upstream software that fixes 
bugs or makes them obsolete.
Comment 9 Fedora End Of Life 2016-12-20 10:17:23 EST
Fedora 23 changed to end-of-life (EOL) status on 2016-12-20. Fedora 23 is
no longer maintained, which means that it will not receive any further
security or bug fix updates. As a result we are closing this bug.

If you can reproduce this bug against a currently maintained version of
Fedora please feel free to reopen this bug against that version. If you
are unable to reopen this bug, please file a new report against the
current release. If you experience problems, please add a comment to this
bug.

Thank you for reporting this bug and we are sorry it could not be fixed.
Comment 10 Fedora End Of Life 2017-11-16 14:05:41 EST
This message is a reminder that Fedora 25 is nearing its end of life.
Approximately 4 (four) weeks from now Fedora will stop maintaining
and issuing updates for Fedora 25. It is Fedora's policy to close all
bug reports from releases that are no longer maintained. At that time
this bug will be closed as EOL if it remains open with a Fedora  'version'
of '25'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, simply change the 'version'
to a later Fedora version.

Thank you for reporting this issue and we are sorry that we were not
able to fix it before Fedora 25 is end of life. If you would still like
to see this bug fixed and are able to reproduce it against a later version
of Fedora, you are encouraged  change the 'version' to a later Fedora
version prior this bug is closed as described in the policy above.

Although we aim to fix as many bugs as possible during every release's
lifetime, sometimes those efforts are overtaken by events. Often a
more recent Fedora release includes newer upstream software that fixes
bugs or makes them obsolete.
Comment 11 Zdenek Dohnal 2018-02-01 11:11:39 EST
I tried to reproduce this issue with Tore's steps from comment #6 in Fedora 26, but with no luck. But this issue or similar exists still in cups-browsed - I have reports from people who are seeing printers, but cannot print with message:

ERROR: No destination host name supplied by cups-browsed for printer <name>, is cups-browsed running?

They can print again only after restarting cups-browsed or whole PC.

I'll create separate bugzilla for it, because IMO it is slightly different issue - Tore didn't see print queues at all after suspend, this time we can see queues, but you cannot print anything.
Closing this bug as CURRENTRELEASE, if someone won't be able to reproduce it.

Note You need to log in before you can comment on or make changes to this bug.