Bug 499687 - client fails to get information from cups server
Summary: client fails to get information from cups server
Keywords:
Status: CLOSED NOTABUG
Alias: None
Product: Fedora
Classification: Fedora
Component: cups
Version: 10
Hardware: All
OS: Linux
low
high
Target Milestone: ---
Assignee: Tim Waugh
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2009-05-07 16:43 UTC by Matthew Caron
Modified: 2009-10-23 15:54 UTC (History)
4 users (show)

Fixed In Version:
Clone Of:
Environment:
Last Closed: 2009-10-23 15:36:10 UTC
Type: ---
Embargoed:


Attachments (Terms of Use)
lpoptions.txt (74.75 KB, text/plain)
2009-10-13 10:38 UTC, Alexey Kuznetsov
no flags Details
lpoptions.txt from Matt Caron (91.51 KB, text/plain)
2009-10-21 20:31 UTC, Matthew Caron
no flags Details
cupsd.conf from misbehaving server (1.78 KB, application/octet-stream)
2009-10-23 12:38 UTC, Matthew Caron
no flags Details
ifconfig output from misbehaving server (1.47 KB, text/plain)
2009-10-23 14:06 UTC, Matthew Caron
no flags Details
Packet capture of cups messages (465 bytes, application/octet-stream)
2009-10-23 14:15 UTC, Matthew Caron
no flags Details

Description Matthew Caron 2009-05-07 16:43:17 UTC
Description of problem:

Client machines can no longer get "extra" information from the cups server (printer features, etc.). This causes applications using the standard GTK dialog boxes to become unresponsive when trying to print. Standard lp/lpr print requests still work.

When in system-config-printer on the client, if you click "Properties" you get "There was a problem connecting to the CUPS server".

When in an application (openoffice), and you try to print, the dialog is very slow and the print button never becomes active. Server error/access log shows nothing. Client error log shows "cupsdReadClient: 12 IPP Read Error!"


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

Server and client both running Fedora 10, updated with all updates at time of writing.


How reproducible:

Happens for me all the time, though I have not tried fresh installs or anything.

Steps to Reproduce:
1. Set up a printer connected to a server, shared.
2. Set up a client using these shared printers.
3. Try to print something, or open system-config-printer and click "Properties"
  
Actual results:

Hangs and doesn't let you print or issues an error.

Expected results:

Should print.

Additional info:

This used to work when I first set it up. The server has always been Fedora 10, and the client was Fedora 9, upgraded to Fedora 10. As of about the beginning of April, it worked. I first noticed it was broken this week (beginning of May). Somewhere in there, something broke it.

I've tried turning off the firewall and SELinux on both the client and server. It had no effect.

Comment 1 Tim Waugh 2009-05-07 16:55:57 UTC
Please update the server to this cups package:

http://koji.fedoraproject.org/koji/buildinfo?buildID=101015

Download the RPMs for your architecture and use (e.g.) 'rpm -Fvh cups-*.rpm' to update them.

Does this have any effect on the problem?

Comment 2 Matthew Caron 2009-05-07 17:08:58 UTC
The new RPMs had no effect.

Comment 3 Tim Waugh 2009-05-11 10:27:33 UTC
What does 'lpstat -s' say on the client?

Comment 4 Matthew Caron 2009-05-11 19:33:12 UTC
(MattC@ENG26A) ~$ lpstat -s
system default destination: e2ljp3005
device for e2ljp3005: ///dev/null
device for e2ljp3005-letterhead: ///dev/null


Which doesn't seem right...

I should also note that an Ubuntu machine has the same issue attempting to print to this printserver, implying that it is something messed up on the server side.

Comment 5 Tim Waugh 2009-05-12 11:30:24 UTC
What does 'lpstat -c' say?  I think you might have implicit classes there.

Presumably e2ljp3005 is the queue that's failing for you.  So the next step is to try to fetch its PPD.  On the client, do this:

lpoptions -p e2ljp3005 -l

What output do you get?

Comment 6 Matthew Caron 2009-05-13 13:04:54 UTC
Actually, both queues fail, which is not surprising, because they're on the same machine.

Answers to your questions:

(MattC@ENG26A) ~$ lpstat -c
(MattC@ENG26A) ~$ lpoptions -p e2ljp3005 -l
lpoptions: Unable to get PPD file for e2ljp3005: successful-ok

Thanks for the help, btw.

Comment 7 Tim Waugh 2009-05-13 13:32:40 UTC
Great, now run 'cupsctl --debug-logging' as root to turn on debugging output, and run lpoptions again.

Do you get anything logged in /var/log/cups/error_log about what failed?

Comment 8 Matthew Caron 2009-05-13 13:44:10 UTC
Well, there's a whole bunch of this repeated at about 1s intervals even when not doing anything:

D [13/May/2009:09:39:34 -0400] cupsdReadClient: 11 POST / HTTP/1.1
D [13/May/2009:09:39:34 -0400] cupsdAuthorize: No authentication data provided.
D [13/May/2009:09:39:34 -0400] CUPS-Get-Default
D [13/May/2009:09:39:34 -0400] cupsdProcessIPPRequest: 11 status_code=0 (success
ful-ok)
D [13/May/2009:09:39:34 -0400] cupsdCloseClient: 11
D [13/May/2009:09:39:34 -0400] cupsdAcceptClient: skipping getpeercon()
D [13/May/2009:09:39:34 -0400] cupsdAcceptClient: 11 from localhost (Domain)
D [13/May/2009:09:39:34 -0400] cupsdReadClient: 11 POST / HTTP/1.1
D [13/May/2009:09:39:34 -0400] cupsdAuthorize: No authentication data provided.
D [13/May/2009:09:39:34 -0400] Get-Printer-Attributes ipp://localhost/printers/e
2ljp3005
D [13/May/2009:09:39:34 -0400] cupsdProcessIPPRequest: 11 status_code=0 (success
ful-ok)

and then this is the bit which happens when I do the lpoptions again:

D [13/May/2009:09:39:35 -0400] cupsdAcceptClient: skipping getpeercon()
D [13/May/2009:09:39:35 -0400] cupsdAcceptClient: 13 from localhost (Domain)
D [13/May/2009:09:39:35 -0400] cupsdCloseClient: 12
D [13/May/2009:09:39:35 -0400] cupsdReadClient: 13 POST / HTTP/1.1
D [13/May/2009:09:39:35 -0400] cupsdAuthorize: No authentication data provided.
D [13/May/2009:09:39:36 -0400] CUPS-Get-Printers
D [13/May/2009:09:39:36 -0400] cupsdProcessIPPRequest: 13 status_code=0 (success
ful-ok)
D [13/May/2009:09:39:37 -0400] cupsdCloseClient: 13
D [13/May/2009:09:39:37 -0400] cupsdCloseClient: 11


I don't know why it is complaining about authentication. The printer allows everyone to print, and the server lets anyone connect.

Comment 9 Tim Waugh 2009-05-13 14:03:28 UTC
Ignore that -- just concentrate on what happens at the point that you try to fetch the PPD.

Comment 10 Matthew Caron 2009-05-14 15:30:18 UTC
That's what this bit is:

D [13/May/2009:09:39:35 -0400] cupsdAcceptClient: skipping getpeercon()
D [13/May/2009:09:39:35 -0400] cupsdAcceptClient: 13 from localhost (Domain)
D [13/May/2009:09:39:35 -0400] cupsdCloseClient: 12
D [13/May/2009:09:39:35 -0400] cupsdReadClient: 13 POST / HTTP/1.1
D [13/May/2009:09:39:35 -0400] cupsdAuthorize: No authentication data provided.
D [13/May/2009:09:39:36 -0400] CUPS-Get-Printers
D [13/May/2009:09:39:36 -0400] cupsdProcessIPPRequest: 13 status_code=0
(success
ful-ok)
D [13/May/2009:09:39:37 -0400] cupsdCloseClient: 13
D [13/May/2009:09:39:37 -0400] cupsdCloseClient: 11

Comment 11 Tim Waugh 2009-05-14 15:57:28 UTC
Looks like it isn't getting to talk to the server at all when it fetches the PPD.

Please run 'strace -s1000 lpoptions -p e2ljp3005 -l 2>lpoptions.txt' and attach lpoptions.txt.

Comment 12 Alexey Kuznetsov 2009-10-13 10:38:08 UTC
Created attachment 364570 [details]
lpoptions.txt

Same issue on my machines. I do attach this file, with same arguments (bad idea?).

Comment 13 Alexey Kuznetsov 2009-10-21 20:09:57 UTC
it fixed for me with last updates of cups.

i suggest to close the bug

Comment 14 Matthew Caron 2009-10-21 20:30:27 UTC
It is still broken for me.

Sorry Tim, I missed the earlier message from back in May. I've run and will attach the file, but I think I see the problem - it can't connect to 10.3.24.1... and it can't connect to that because that is the IP of that machine's private network interface (which doesn't reach outside the server room)... So, I'm going to hazard a guess, but it looks like the CUPS broadcast messages have the wrong IP address in them.

Comment 15 Matthew Caron 2009-10-21 20:31:03 UTC
Created attachment 365600 [details]
lpoptions.txt from Matt Caron

Comment 16 Alexey Kuznetsov 2009-10-21 20:43:02 UTC
i told about f12 beta. do you tried it?

Comment 17 Matthew Caron 2009-10-21 20:50:08 UTC
No, I'm still on f10.

Also, I see the problem in a packet capture. 2 messages come in from that machine for that printer - one on each IP address. So, it's sending a broadcast for every printer and port combination it has.

That said, if it is fixed for you in F12, then I'm okay with closing it. I don't know if I'm ever going to go to F12, so I will never be able to confirm it.

Comment 18 Alexey Kuznetsov 2009-10-21 23:28:36 UTC
you can try f12 as guest under your virtual machine and post results here. i use f12 as desktop without any issues (small problems like suspend/or 3d issues).

so i think you wait too long, 5 month. and here to many changes already done in f11-f12 packages. you probably better to move to f11 or f12beta.

so checkout package changes here:
http://koji.fedoraproject.org/koji/packageinfo?packageID=54

Comment 19 Alexey Kuznetsov 2009-10-21 23:30:57 UTC
...or livecd...

Comment 20 Tim Waugh 2009-10-22 10:45:51 UTC
Matthew, could you please attach the /etc/cups/cupsd.conf file from the server?  Thanks.

Comment 21 Matthew Caron 2009-10-23 12:38:42 UTC
Created attachment 365843 [details]
cupsd.conf from misbehaving server

Per Tim's request, cupsd.conf from the server hosting the queues.

Note that this was never hand-edited, all changes were made through system-config-printer.

Comment 22 Tim Waugh 2009-10-23 14:02:11 UTC
> Also, I see the problem in a packet capture. 2 messages come in from that
> machine for that printer - one on each IP address. So, it's sending a broadcast
> for every printer and port combination it has.

Can you elaborate on this with more specifics please?  Which UDP packets reach the client, and what are their contents?

It sounds like a problem on the server end with determining which interfaces are available.  Can you describe them please, or provide the output of '/sbin/ifconfig'?  Thanks.

Comment 23 Matthew Caron 2009-10-23 14:06:10 UTC
Created attachment 365853 [details]
ifconfig output from misbehaving server

ifconfig output from server. eth0 is 10.128.1.9, eth1 is 10.3.24.1.

Comment 24 Matthew Caron 2009-10-23 14:15:41 UTC
Created attachment 365855 [details]
Packet capture of cups messages

Messages from misbehaving server.

Comment 25 Matthew Caron 2009-10-23 15:08:31 UTC
Okay, so if we look at the ifconfig output, we see that eth0 is 10.128.1.9 (eng06....) and eth1 is 10.3.24.1, right?

Now, the packet capture shows 2 packets - the first uses the IP from eth0, and the second from eth1.

Comment 26 Tim Waugh 2009-10-23 15:30:20 UTC
So, what's weird about the ifconfig output, and it explains what's going on really, is that both interfaces have exactly the same broadcast address: 10.255.255.255.

That looks wrong to me...

Comment 27 Matthew Caron 2009-10-23 15:36:10 UTC
*headdesk*

I am such an idiot.

Sorry to waste your time like that.

Comment 28 Tim Waugh 2009-10-23 15:54:02 UTC
Don't worry, wasn't an obvious problem. ;-)


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