Bug 977813 - 60s delay after reading IPP response
Summary: 60s delay after reading IPP response
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Fedora
Classification: Fedora
Component: cups
Version: 19
Hardware: Unspecified
OS: Unspecified
high
urgent
Target Milestone: ---
Assignee: Tim Waugh
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks: 978391
TreeView+ depends on / blocked
 
Reported: 2013-06-25 11:35 UTC by Tim Waugh
Modified: 2013-07-02 00:34 UTC (History)
2 users (show)

Fixed In Version: cups-1.6.2-12.fc19
Doc Type: Bug Fix
Doc Text:
Clone Of:
: 978391 (view as bug list)
Environment:
Last Closed: 2013-07-02 00:34:31 UTC


Attachments (Terms of Use)

Description Tim Waugh 2013-06-25 11:35:48 UTC
Description of problem:
When running against a CUPS-1.4.x server (e.g. Red Hat Enterprise Linux 6), the last IPP request for a particular connection causes a 60s delay after reading the response, as shown by strace:

connect(5, {sa_family=AF_INET, sin_port=htons(631), sin_addr=inet_addr("192.168.122.231")}, 16) = -1 EINPROGRESS (Operation now in progress)
fcntl(5, F_SETFL, O_RDWR)               = 0
poll([{fd=5, events=POLLIN|POLLOUT}], 1, 250) = 1 ([{fd=5, revents=POLLOUT}])
getpeername(5, {sa_family=AF_INET, sin_port=htons(631), sin_addr=inet_addr("192.168.122.231")}, [16]) = 0
uname({sys="Linux", node="rubik", ...}) = 0
sendto(5, "POST / HTTP/1.1\r\nContent-Length:"..., 190, 0, NULL, 0) = 190
sendto(5, "\2\0@\2\0\0\0\1\1G\0\22attributes-charset\0\5"..., 637, 0, NULL, 0) = 637
poll([{fd=5, events=POLLIN}], 1, 1000)  = 1 ([{fd=5, revents=POLLIN}])
poll([{fd=5, events=POLLIN}], 1, 60000) = 1 ([{fd=5, revents=POLLIN}])
recvfrom(5, "HTTP/1.1 100 Continue\r\n\r\nHTTP/1."..., 2048, 0, NULL, NULL) = 224
recvfrom(5, "\2\0\0\0\0\0\0\1\1G\0\22attributes-charset\0\5"..., 905, 0, NULL, NULL) = 905
recvfrom(5, 0x7fffd5f1b4f7, 1, 66, 0, 0) = -1 EAGAIN (Resource temporarily unavailable)
uname({sys="Linux", node="rubik", ...}) = 0
sendto(5, "POST / HTTP/1.1\r\nContent-Length:"..., 189, 0, NULL, 0) = 189
sendto(5, "\2\0@\1\0\0\0\2\1G\0\22attributes-charset\0\5"..., 75, 0, NULL, 0) = 75
poll([{fd=5, events=POLLIN}], 1, 1000)  = 1 ([{fd=5, revents=POLLIN}])
poll([{fd=5, events=POLLIN}], 1, 60000) = 1 ([{fd=5, revents=POLLIN}])
recvfrom(5, "HTTP/1.1 100 Continue\r\n\r\n", 2048, 0, NULL, NULL) = 25
poll([{fd=5, events=POLLIN}], 1, 60000) = 1 ([{fd=5, revents=POLLIN}])
recvfrom(5, "HTTP/1.1 200 OK\r\nDate: Tue, 25 J"..., 2048, 0, NULL, NULL) = 200
recvfrom(5, "\2\0\0\0\0\0\0\2\1G\0\22attributes-charset\0\5"..., 2048, 0, NULL, NULL) = 2030
recvfrom(5, "A\0\26printer-make-and-model\0\32Gener"..., 2048, 0, NULL, NULL) = 1916
recvfrom(5, "D\0\27notify-events-supported\0\rjob-"..., 1415, 0, NULL, NULL) = 1324
poll([{fd=5, events=POLLIN}], 1, 60000) = 0

Version-Release number of selected component (if applicable):
cups-1.6.2-9.fc19.x86_64
(cups-1.4.2-50.el6_4.4.x86_64)

How reproducible:
100%

Steps to Reproduce:
1. lpstat -h server -s

Actual results:
Takes a long time.

Expected results:
Very quick.

Additional info:
Works fine in Fedora 18.

Comment 2 Tim Waugh 2013-06-25 16:44:30 UTC
This seems to be triggered by svn revision 10102:

commit a92ea6976f174da7e20b3b40c226cdd8bf5afe25
Author: mike <mike@7a7537e8-13f0-0310-91df-b6672ffda945>
Date:   Wed Nov 2 23:52:39 2011 +0000

    Make default IPP version 2.0, and don't always use 1 for the request ID (STR #3929)

Comment 3 Tim Waugh 2013-06-26 14:01:32 UTC
The root cause of this is bug #978387 (STR #3521) on the server.

Meanwhile, we can default to IPP/1.1 in Fedora 19.

Comment 4 Fedora Update System 2013-06-26 15:15:25 UTC
cups-1.6.2-12.fc19 has been submitted as an update for Fedora 19.
https://admin.fedoraproject.org/updates/cups-1.6.2-12.fc19

Comment 5 Fedora Update System 2013-06-26 17:04:38 UTC
Package cups-1.6.2-12.fc19:
* should fix your issue,
* was pushed to the Fedora 19 testing repository,
* should be available at your local mirror within two days.
Update it with:
# su -c 'yum update --enablerepo=updates-testing cups-1.6.2-12.fc19'
as soon as you are able to.
Please go to the following url:
https://admin.fedoraproject.org/updates/FEDORA-2013-11691/cups-1.6.2-12.fc19
then log in and leave karma (feedback).

Comment 6 Fedora Update System 2013-07-02 00:34:31 UTC
cups-1.6.2-12.fc19 has been pushed to the Fedora 19 stable repository.  If problems still persist, please make note of it in this bug report.


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