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

michaelrsweet · 2006-05-22T18:24:09Z

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 · 2006-05-22T19:11:55Z

CUPS.org User: mike

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

michaelrsweet · 2006-05-22T21:44:30Z

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 · 2006-05-22T21:52:37Z

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 · 2006-05-24T12:13:47Z

CUPS.org User: pieleric

Still present in version 1.2.1 ...

michaelrsweet · 2006-05-26T15:05:04Z

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 · 2006-05-30T19:07:28Z

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 · 2006-05-31T12:56:29Z

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 · 2006-05-31T13:52:03Z

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 · 2006-06-04T14:52:53Z

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 · 2006-06-04T15:59:18Z

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 · 2006-06-05T18:24:53Z

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 · 2006-06-07T12:40:58Z

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 · 2006-06-08T14:49:29Z

CUPS.org User: pieleric

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

michaelrsweet · 2006-06-09T07:06:09Z

CUPS.org User: tammo

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

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

michaelrsweet · 2006-06-09T12:37:19Z

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 · 2006-06-09T12:41:28Z

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 · 2006-06-17T15:51:28Z

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 · 2006-06-25T15:10:02Z

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 · 2006-06-26T12:46:48Z

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 · 2006-07-03T18:48:50Z

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 · 2006-07-11T20:39:22Z

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 · 2006-07-12T09:38:26Z

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 · 2006-07-14T03:14:10Z

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 · 2006-07-14T14:13:34Z

CUPS.org User: egk

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

michaelrsweet · 2006-07-17T17:12:38Z

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 · 2006-07-17T18:40:37Z

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 · 2006-07-18T06:01:01Z

CUPS.org User: arminb

test_armin_1.log was done using an unpatched 1.2.1 client.

michaelrsweet · 2006-07-18T08:55:17Z

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 · 2006-07-18T14:24:34Z

CUPS.org User: mike

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

michaelrsweet · 2006-07-18T14:57:42Z

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 · 2006-07-18T14:59:14Z

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 · 2006-07-18T15:31:44Z

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 · 2006-07-18T16:08:00Z

CUPS.org User: twaugh.redhat

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

michaelrsweet · 2006-07-18T17:57:12Z

CUPS.org User: mike

Fixed in Subversion repository.

michaelrsweet · 2006-07-18T17:57:12Z

"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)
{
/*

 \* Wait up to 1 second to get the 100-continue response...

 * Wait up to 0.8 seconds to get the 100-continue response...

*/

```
 if (httpWait(http, 1000))
```
```
 if (httpWait(http, 800))
 status = httpUpdate(http);
```
}
else if (httpCheck(http))
--- cups-1.2.1/cups/getputfile.c.str1717 2006-03-06 13:02:23.000000000 +0000
+++ cups-1.2.1/cups/getputfile.c 2006-07-18 15:43:57.000000000 +0100
@@ -318,10 +318,10 @@
}

/*
* Wait up to 1 second for a 100-continue response...
- Wait up to 0.8 seconds for a 100-continue response...
  */
if (httpWait(http, 1000))
if (httpWait(http, 800))
status = httpUpdate(http);
else
status = HTTP_CONTINUE;

michaelrsweet · 2006-07-18T17:57:12Z

"str1717.patch":

Index: http.c

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

/*

* Flush pending data, if any...
*/

if (http->wused)
{
if (httpFlushWrite(http) < 0)
```
 return (0);
```
}

/*
- If not, check the SSL/TLS buffers and do a select() on the connection...
  */

michaelrsweet closed this as completed Jul 18, 2006

michaelrsweet added the priority-low label Mar 17, 2016

michaelrsweet added this to the Stable milestone Mar 17, 2016

michaelrsweet mentioned this issue Mar 17, 2016

LaserJet 1320 always prompts for paper with CUPS 1.2.0 & manufacturer's PPD #1940

Closed

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

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

Comments

michaelrsweet commented May 22, 2006

This works fine!

michaelrsweet commented May 22, 2006

michaelrsweet commented May 22, 2006

michaelrsweet commented May 22, 2006

michaelrsweet commented May 24, 2006

michaelrsweet commented May 26, 2006

michaelrsweet commented May 30, 2006

michaelrsweet commented May 31, 2006

michaelrsweet commented May 31, 2006

michaelrsweet commented Jun 4, 2006

michaelrsweet commented Jun 4, 2006

michaelrsweet commented Jun 5, 2006

michaelrsweet commented Jun 7, 2006

michaelrsweet commented Jun 8, 2006

michaelrsweet commented Jun 9, 2006

michaelrsweet commented Jun 9, 2006

michaelrsweet commented Jun 9, 2006

michaelrsweet commented Jun 17, 2006

michaelrsweet commented Jun 25, 2006

michaelrsweet commented Jun 26, 2006

michaelrsweet commented Jul 3, 2006

michaelrsweet commented Jul 11, 2006

michaelrsweet commented Jul 12, 2006

michaelrsweet commented Jul 14, 2006

michaelrsweet commented Jul 14, 2006

michaelrsweet commented Jul 17, 2006

michaelrsweet commented Jul 17, 2006

michaelrsweet commented Jul 18, 2006

michaelrsweet commented Jul 18, 2006

michaelrsweet commented Jul 18, 2006

michaelrsweet commented Jul 18, 2006

michaelrsweet commented Jul 18, 2006

michaelrsweet commented Jul 18, 2006

michaelrsweet commented Jul 18, 2006

michaelrsweet commented Jul 18, 2006

michaelrsweet commented Jul 18, 2006

michaelrsweet commented Jul 18, 2006

Index: http.c