Fedora Account System
Red Hat Associate
Red Hat Customer
Created attachment 870955 [details] Shell output Description of problem: Sometimes lpstat -p fail and report a broken pipe, while previous or subsequent calls succeed. Same with lpadmin. Version-Release number of selected component (if applicable): Fedora 20 cups-1.7.0-9.fc20.x86_64 How reproducible: Sometimes. About 25%. The fail raite seems to increase when adding more printers. Steps to Reproduce: 1. lpstat -p 2. lpstat -p Actual results: 1. printer rp01 is idle. enabled since ... 2. lpstat: Broken pipe Expected results: 1. printer rp01 is idle. enabled since ... 2. printer rp01 is idle. enabled since ... Additional info: At my site rp01 is a remote printer (IPP) on another cups server. My fedora 19 hosts (cups-1.6.4-2) do not show the erroneous behaviour. For debuging I set LogLevel to debug and after restarting cupsd calling lpstat -p every 30 seconds. I will attach the shell output, the cups access/error log, and cups config.
Created attachment 870956 [details] cups error log
Created attachment 870957 [details] cups access log
Created attachment 870958 [details] /etc/cups/cupsd.conf
Created attachment 870959 [details] /etc/cups/cups-files.conf
Created attachment 870960 [details] /etc/cups/printers.conf
It looks like the error is happening on the client side. The reason I say that is that the error_log looks like it's just missing bits when the error occurs. Here's the error_log that corresponds to the failure that occurred at 13:42:00: D [05/Mar/2014:13:42:00 +0100] cupsdAcceptClient: skipping getpeercon() D [05/Mar/2014:13:42:00 +0100] [Client 16] Accepted from localhost (Domain) D [05/Mar/2014:13:42:00 +0100] [Client 16] Waiting for request. D [05/Mar/2014:13:42:00 +0100] [Client 16] POST / HTTP/1.1 D [05/Mar/2014:13:42:00 +0100] cupsdSetBusyState: newbusy="Active clients", busy="Not busy" D [05/Mar/2014:13:42:00 +0100] [Client 16] No authentication data provided. D [05/Mar/2014:13:42:00 +0100] cupsdIsAuthorized: username="" D [05/Mar/2014:13:42:00 +0100] [Client 16] WWW-Authenticate: Basic realm="CUPS" D [05/Mar/2014:13:42:00 +0100] [Client 16] Closing connection. D [05/Mar/2014:13:42:00 +0100] cupsdSetBusyState: newbusy="Not busy", busy="Active clients" D [05/Mar/2014:13:42:00 +0100] cupsdAcceptClient: skipping getpeercon() D [05/Mar/2014:13:42:00 +0100] [Client 16] Accepted from localhost (Domain) D [05/Mar/2014:13:42:00 +0100] [Client 16] Waiting for request. D [05/Mar/2014:13:42:00 +0100] [Client 16] POST / HTTP/1.1 D [05/Mar/2014:13:42:00 +0100] cupsdSetBusyState: newbusy="Active clients", busy="Not busy" D [05/Mar/2014:13:42:00 +0100] [Client 16] No authentication data provided. D [05/Mar/2014:13:42:00 +0100] cupsdIsAuthorized: username="" D [05/Mar/2014:13:42:00 +0100] [Client 16] WWW-Authenticate: Basic realm="CUPS" D [05/Mar/2014:13:42:00 +0100] [Client 16] Closing connection. The next step should have been for the client to re-connect using PeerCred credentials, but for some reason it didn't. Could you please try running 'strace' on the lpstat process, and saving the strace output for a failed run?
Will attach output of a failed 'strace lpstat -p 2>strace.log'
Created attachment 870978 [details] output of 'strace lpstat -p'
Thanks. Reported upstream.
cups-1.7.1-6.fc20 has been submitted as an update for Fedora 20. https://admin.fedoraproject.org/updates/FEDORA-2014-3451/cups-1.7.1-6.fc20
Package cups-1.7.1-6.fc20: * should fix your issue, * was pushed to the Fedora 20 testing repository, * should be available at your local mirror within two days. Update it with: # su -c 'yum update --enablerepo=updates-testing cups-1.7.1-6.fc20' as soon as you are able to. Please go to the following url: https://admin.fedoraproject.org/updates/FEDORA-2014-3451/cups-1.7.1-6.fc20 then log in and leave karma (feedback).
Have tested cups-1.7.1-6.fc20. Error still comes up. I will append a new strace output from 'lpstat -p'. Also I will append another strace output from 'lpstat -p rp01' that also tend to fail with the error message 'Invalid destination name in list "rp01"'. I assume it's the result of the same bug. But maby the strace will help. Unfortunately I will be offline for about two weeks from now on. So until then I can not provide any assistance. But I will be back :) Thank you for your support so far.
Created attachment 871944 [details] cups-1.7.1-6.fc20: failed run of 'strace lpstat -p'
Created attachment 871946 [details] cups-1.7.1-6.fc20: failed run of 'strace lpstat -p rp01'
Created attachment 871948 [details] cups-1.7.1-6.fc20: successful run of 'strace lpstat -p rp01' (just for comparison)
cups-1.7.1-6.fc20 has been pushed to the Fedora 20 stable repository. If problems still persist, please make note of it in this bug report.
I've built a new release of cups pulling in a new upstream patch for this.
Are you able to test the packages directly from koji? http://koji.fedoraproject.org/koji/buildinfo?buildID=508931 (don't worry if not... I can arrange for another test update)
I have downloaded and installed - cups-1.7.1-9.fc20.x86_64.rpm - cups-libs-1.7.1-9.fc20.x86_64.rpm - cups-libs-1.7.1-9.fc20.i686.rpm - cups-filesystem-1.7.1-9.fc20.noarch.rpm from koji. Rebooted after that. But the error still occures. I would say the error comes up less often, but that may be illusion. I am still testing, maybe the error only comes up, if multiple clients are running simultaneous or shortly after each other.
OK, I see this too. How to reproduce: 1. Edit /etc/cups/cupsd.conf and change the 'Location /' stanza like this: <Location /> Order allow,deny AuthType Default Require valid-user </Location> 2. systemctl restart cups.service 3. Now run this: while :; do lpstat -p; done 2>&1 | grep roken and wait. It might take, say, a minute of continuous looping before 'lpstat: Broken pipe' is seen. I'm trying to run a slower test with CUPS debugging enabled on the server to find out what's going on.
Also for reproducing: the error occur more often if the system load is high.
Finally got a clean log for this. Here's the test script: while :; do date; lpstat -p >/dev/null || break; sleep 5; done 2>&1 It ended like this: Mon 14 Apr 16:36:26 BST 2014 Mon 14 Apr 16:36:31 BST 2014 lpstat: Broken pipe Here's the error_log that corresponds to it: D [14/Apr/2014:16:36:26 +0100] cupsdSetBusyState: newbusy="Not busy", busy="Not busy" D [14/Apr/2014:16:36:31 +0100] cupsdAcceptClient: skipping getpeercon() D [14/Apr/2014:16:36:31 +0100] [Client 14] Accepted from localhost (Domain) D [14/Apr/2014:16:36:31 +0100] [Client 14] Waiting for request. D [14/Apr/2014:16:36:31 +0100] [Client 14] POST / HTTP/1.1 D [14/Apr/2014:16:36:31 +0100] cupsdSetBusyState: newbusy="Active clients", busy ="Not busy" D [14/Apr/2014:16:36:31 +0100] [Client 14] No authentication data provided. D [14/Apr/2014:16:36:31 +0100] cupsdIsAuthorized: username="" D [14/Apr/2014:16:36:31 +0100] [Client 14] WWW-Authenticate: Basic realm="CUPS" D [14/Apr/2014:16:36:31 +0100] [Client 14] Closing connection. D [14/Apr/2014:16:36:31 +0100] cupsdSetBusyState: newbusy="Not busy", busy="Active clients" D [14/Apr/2014:16:36:31 +0100] cupsdAcceptClient: skipping getpeercon() D [14/Apr/2014:16:36:31 +0100] [Client 14] Accepted from localhost (Domain) D [14/Apr/2014:16:36:31 +0100] [Client 14] Waiting for request. D [14/Apr/2014:16:36:31 +0100] [Client 14] POST / HTTP/1.1 D [14/Apr/2014:16:36:31 +0100] cupsdSetBusyState: newbusy="Active clients", busy="Not busy" D [14/Apr/2014:16:36:31 +0100] [Client 14] No authentication data provided. D [14/Apr/2014:16:36:31 +0100] cupsdIsAuthorized: username="" D [14/Apr/2014:16:36:31 +0100] [Client 14] WWW-Authenticate: Basic realm="CUPS" D [14/Apr/2014:16:36:31 +0100] [Client 14] Closing connection. D [14/Apr/2014:16:36:31 +0100] cupsdSetBusyState: newbusy="Not busy", busy="Active clients" D [14/Apr/2014:16:37:44 +0100] cupsdAcceptClient: skipping getpeercon()
Here's how to reproduce it reliably: gdb --args lpstat -p b main r b request.c:747 c c i.e. put a breakpoint in cupsSendRequest() after httpPost() but before ippWrite().
Created attachment 886893 [details] cups-str4386.patch This patch fixes it for me.
I've added this new patch to STR #4386 for upstream comment.
This is now STR #4403.
cups-1.7.3-1.fc20 has been submitted as an update for Fedora 20. https://admin.fedoraproject.org/updates/cups-1.7.3-1.fc20
Package cups-1.7.3-1.fc20: * should fix your issue, * was pushed to the Fedora 20 testing repository, * should be available at your local mirror within two days. Update it with: # su -c 'yum update --enablerepo=updates-testing cups-1.7.3-1.fc20' as soon as you are able to. Please go to the following url: https://admin.fedoraproject.org/updates/FEDORA-2014-6798/cups-1.7.3-1.fc20 then log in and leave karma (feedback).
cups-1.7.3-1.fc20 has been pushed to the Fedora 20 stable repository. If problems still persist, please make note of it in this bug report.
Updates installed -> Bug fixed. Great. Thank you very, very much.