search

apple / cups

Apple CUPS Sources
https://www.cups.org
Apache License 2.0
1.95k stars 464 forks source link

lpr returns "Bad Request" when connecting to a ipp based cups server #1717

Closed michaelrsweet closed 18 years ago

michaelrsweet commented 18 years ago

Version: 1.2.0 CUPS.org User: pieleric

Hello,

When trying to print via an ipp cups server (version 1.1), a "Bad Request" error is displayed (and nothing printed): $ lpr test.ps lpr: Bad Request

Otherwise, everything seems working fine (lpr, lpstat, lprm...)! A very detail bug report is available there https://launchpad.net/distros/ubuntu/+source/cupsys/+bug/42513 .

Basically, the most interesting part is that cupsdoprint works depending on the arguments order: $ cupsdoprint -H scutum -P nrg-nb test.ps client-error-bad-request

$ cupsdoprint -P nrg-nb -H scutum test.ps

This works fine!

For information, my distrib is Mandriva cooker (cups 1.2.0). This used to work with cups 1.1, and it seems to be broken from the very beginning I've upgraded to 1.2-developement (somewhere around March, but there were other bugs at this time ;-) ).

michaelrsweet commented 18 years ago

CUPS.org User: mike

Please attach your /var/log/cups/error_log file...

michaelrsweet commented 18 years ago

CUPS.org User: pieleric

I forgot to mention I run cups only as a client, so no error_log . I could still try to provide you the error_log of the 1.1 cups server (but I'm not the administrator so it'll take some time).

In the mean time I've noticed a mistake in the bug description: It's actually "cupsdoprint -P nrg-nb -H scutum test.ps" which fails and "cupsdoprint -H scutum -P nrg-nb test.ps" which works.

Attached are the two strace logs associated.

michaelrsweet commented 18 years ago

CUPS.org User: pieleric

Sorry, actually, it just seems that the argument order doesn't have such a strong role. cupsdoprint simply works sometimes and sometimes doesn't. The same command might fail or succed with not clue beforehand (it seems the difference comes from the timeout during the HTTP request?).

michaelrsweet commented 18 years ago

CUPS.org User: pieleric

Still present in version 1.2.1 ...

michaelrsweet commented 18 years ago

CUPS.org User: luc.lalonde.polymtl

Where having the same problem:

Cups server version 1.1.23 (Message: ReadClient: 7 IPP Read Error) Cups clients version 1.2.1 (Message: Bad Request)

On the clientside, the cups server is deactivated and access the above server with the ServerName directive in client.conf

Downgrading the clients to 1.1.23 solves the problem (Bad Request messages, IPP Read Error).

michaelrsweet commented 18 years ago

CUPS.org User: mike

We'll need the error_log file from the server to make any headway, along with a complete description of how things are setup, e.g. is the server on the LAN or are you accessing via WAN/Internet, what operating systems/distributions are you using, etc?

Also, if you can come up with the lp/lpr commands needed to reproduce the problem every time, that will be very useful. "cupsdoprint" is not a CUPS command, so that doesn't help.

michaelrsweet commented 18 years ago

CUPS.org User: pieleric

Ok, I'll try to get an error_log from the server, I've got to talk with the admin. In the mean, I think you can get something very similar, already posted at the ubuntu bug report (which address is in the bug description).

Sorry concerning cupsdoprint... I used it specifically because I thought it was a CUPS program! Anyway, the lpr command (the CUPS one) does exactly the same behaviour. Basically, it works randomly every 10th times (9 times it says "lpr : Bad request" and then it works) : "lpr -P printername file.ps"

The configuration: My machine (client) is mandriva cooker with cups 1.2.1 . The server is an older Mandriva (10.2 I think) with cups 1.1 (I'll be able to give precise information latter on). Both are x86 machines. They are connected via 1Gb ethernet.

michaelrsweet commented 18 years ago

CUPS.org User: pieleric

Here are the logs with debug turned on. Those are logs for when the client did: "lpr -P nrg-nb rib-soge.ps"

The first one is when it failed and the second one is 11 trials later, when it succeded.

The cups server exact version is 1.1.21 .

michaelrsweet commented 18 years ago

CUPS.org User: Tuxi

I've posted my CUPS server error log. I'm running Ubuntu Dapper on the client and CUPS v 1.1 on Fedora Core 4. There are several unsuccessful tries printing from Evolution on the client followed by cupsdoprint -H -P from the Dapper client (gives IPP Read Error!). The last entry was the successful printing using cupsdoprint -P -H from the Dapper client. I've also posted this information on Ubuntu's bug tracking under Bug #45099.

michaelrsweet commented 18 years ago

CUPS.org User: Tuxi

My problem seems to be related to browsing. I pointed my printer to the RAW printer on the server and it prints just fine.

michaelrsweet commented 18 years ago

CUPS.org User: mike

The logs still don't show enough information to be useful - in the failure case, the server gets (what appears to be) a bad CUPS_GET_PRINTERS request.

Perhaps if you do a network capture with tcpdump or ethereal and then post a failure case when using lp or lpr?

michaelrsweet commented 18 years ago

CUPS.org User: tammo

Hello !

I can confirm this bug. I tcpdumped the traffic between client (ubuntu dapper) and server (debian sarge) with -w option.

http://www/~tammo/cups.log

Kind regards

Tammo

michaelrsweet commented 18 years ago

CUPS.org User: pieleric

Hello Tammo, could you repost your link, you forgot to put the server address, thanks!

michaelrsweet commented 18 years ago

CUPS.org User: tammo

Sorry! I should not use cut and paste here ....

http://www.fkp.uni-hannover.de/~tammo/cups.log

michaelrsweet commented 18 years ago

CUPS.org User: oll

I have exactly the same problem with cups 1.2.1 clients (Fedora Core 5) and cups 1.1.22 server. I don't think it has something to do with browsing since the simple command : lp -d MyPrinter MyTestFile once works, once gives me a Bad Request. It's around 1 success for 3 failures.

michaelrsweet commented 18 years ago

CUPS.org User: oll

I just posted 2 backtraces from exactly the same command : one is a failure ("strace lp -d pdf .cshrc"), the other a success.

michaelrsweet commented 18 years ago

CUPS.org User: sinder

I'm wondering somewhat that this issue only has low priority as there probably are quite a number of people (like me ;-) around who have Redhat Linux servers running with a cups 1.1.x ipp print server and trying to use Ubuntu 6.06 (in my case about 50) clients with cups 1.2.x software... So I'd (and my institute) would be very grateful if the priority could be raised to 'important'...

But anyway, thanks for providing such a widespread software for this important service!

michaelrsweet commented 18 years ago

CUPS.org User: egk

I have the same issue with cups 1.2 on Fedora Core 5 printing to an FC4 server.

I will post an ethereal dump containing one failed attemps at printing a simple text file, and one successful attemps. The failure starts at frame 1 until frame 99, and the rest is the successful printing.

Emmanuel
michaelrsweet commented 18 years ago

CUPS.org User: martinxyz

I have the same problem after upgrading debian testing. I upgraded the client where I run lpr, not the server running ubuntu.

Client: cupsys-client 1.2.1-3 # lpr bug as described Server: cupsys-client 1.1.23-10ubunt # lpr seems to work fine

michaelrsweet commented 18 years ago

CUPS.org User: DanielLinux

The same problem is happening here too. The configuration:

Server (debian stable) with cups 1.1.23-10sarge Clients (debian testing) with cups 1.2.1-2

michaelrsweet commented 18 years ago

CUPS.org User: mike

OK, everyone please stop posting strace and error_log files. They are useless for tracking this problem down.

What we need are Ethereal/tcpdump files showing good and bad prints. Thus far we don't have enough information to track this problem down. If you want to post files, post dumps from either program. We are only interested in TCP traffic to/from port 631...

Sinder, WRT to the priority being "2", it isn't something we've been able to reproduce and isn't affecting all users of CUPS, even users with mixed 1.1.x and 1.2.x installations.

michaelrsweet commented 18 years ago

CUPS.org User: tammo

Hello !

I captured a "good.dump" and a "bad.dump" of the command "cupsdoprint -H caesium -P pdf /etc/motd". The dump was taken via "tcpdump 'tcp port 631' -w foo.dump". The server is caesium (130.75.48.55 - cups 1.1.23) and the client is xenon ( 130.75.48.54 - cups 1.2.1 )

michaelrsweet commented 18 years ago

CUPS.org User: dreamdreams

I posted another set of good and bad dump files. They look a little different than tammo's.

Capture command was: tcpdump -w bad port 631

and print command was: lpr sig_card.pdf

michaelrsweet commented 18 years ago

CUPS.org User: egk

I've just noticed that it seems the ethereal dump I mentioned failed to upload.
I will try again...

michaelrsweet commented 18 years ago

CUPS.org User: twaugh.redhat

Here is another tcpdump capture of what appears to be the same problem:

https://bugzilla.redhat.com/bugzilla/show_bug.cgi?id=198987#c2

CUPS_GET_PRINTERS works fine CUPS_GET_CLASSES works fine CUPS_GET_DEFAULT works fine Actually printing the job: fails with bad request

michaelrsweet commented 18 years ago

CUPS.org User: mike

OK, I'm attaching a test file for the CUPS ipptest program (in the "test" subdirectory of the source tarball) to test this problem. Please save the str1717.test file to the "test" subdirectory, go there, and then run the following command on one of the affected 1.2.x systems:

./ipptest -v ipp://servername/printers/printername str1717.test 2>&1 >test.log

and then send the results.

At the moment, I still can't reproduce this problem with the current 1.2.x or trunk code - either the timeout changes we made for 1.2.2 have fixed the problem, or it is something that can't be easily reproduced...

michaelrsweet commented 18 years ago

CUPS.org User: arminb

test_armin_1.log was done using an unpatched 1.2.1 client.

michaelrsweet commented 18 years ago

CUPS.org User: arminb

Hm, sorry, I used a not existing printer in test_armin_1.log. ipptest does not show an error with here (tried 30 times).

michaelrsweet commented 18 years ago

CUPS.org User: mike

It seems to be important to test with a remote server, so please test from another system...

michaelrsweet commented 18 years ago

CUPS.org User: twaugh.redhat

This is a timing race. The 1.2.x client is sending 'Expect: 100-continue' and waiting for 1s for the reply, but the 1.1.x server is also 1s before it times out waiting for the IPP request.

I have a trace of a successful request and a failed request for exactly the same set-up, and the only difference is the timing between the 'Expect:' header and the IPP data. The failed case had a delay of 1.001863s; the succeeding case only waited 1.000063s.

I think the 1.2.x client code should lower its timeout to (say) 0.8s.

michaelrsweet commented 18 years ago

CUPS.org User: twaugh.redhat

I have been unable to reproduce the problem after applying cups-0.8s.patch (attached). Before applying the patch, I could reproduce the problem about one time in ten.

michaelrsweet commented 18 years ago

CUPS.org User: mike

While the timing might be an issue, I don't think this is the ultimate cause of the problem - we write the IPP request before the httpWait(), but I suspect the issue is that the requests are fitting in the write buffer and are not getting flushed out.

Try inserting httpFlushWrite(http) before the httpWait() call and see if that yields the desired results. If so, I'll update httpWait() to do a flush as needed...

michaelrsweet commented 18 years ago

CUPS.org User: twaugh.redhat

Yes, making that change instead of adjusting the timeout seems to fix the problem here.

michaelrsweet commented 18 years ago

CUPS.org User: mike

Fixed in Subversion repository.

michaelrsweet commented 18 years ago

"cups-0.8s.patch":

--- cups-1.2.1/cups/request.c.str1717 2006-07-18 15:50:47.000000000 +0100 +++ cups-1.2.1/cups/request.c 2006-07-18 15:51:09.000000000 +0100 @@ -210,10 +210,10 @@ if (!got_status) { /*

michaelrsweet commented 18 years ago

"str1717.patch":

Index: http.c

--- http.c (revision 5743) +++ http.c (working copy) @@ -1809,6 +1809,16 @@ return (1);

/*