[cups-devel] IPP requests: Non-blocking or short timeout
Till Kamppeter
till.kamppeter at gmail.com
Wed Sep 14 15:31:46 PDT 2016
On 09/13/2016 01:10 PM, Michael Sweet wrote:
> Till,
>
>> On Sep 12, 2016, at 9:33 AM, Till Kamppeter <till.kamppeter at gmail.com> wrote:
>>
>> Thank you very much for the help.
>>
>> On 09/11/2016 03:22 PM, Michael Sweet wrote:
>>> The httpSetTimeout function can be used to manipulate the default read timeout for a given connection. But cupsDoRequest also attempts to reconnect on error (using a connection timeout of 30 seconds) so you might want to use cupsSendRequest and cupsGetResponse yourself to control the reconnect behavior...
>>>
>>
>> I have tried the cupsSendRequest()/cupsGetResponse() now and what happens is that cupsSendRequest() exits immediately with some OK status and cupsGetResponse() hangs for more than one minute with status 100 (HTTP_STATUS_CONTINUE). So the problem is that the server does not answer in time.
>
> Hmm, can you get a packet trace showing the traffic?
>
>> Calling "httpSetTimeout(http, 3, NULL, NULL);" before (3 sec timeout) does not help. Or do I have to define a callback here (which would for example kill the connection after the three seconds which I chosen as timeout). If I need a callback, how should it look like?
>
> The test/ipptool.c program has a fairly sophisticated one, but if you don't specify a callback it should timeout after the 3 seconds you specify.
>
> If you can compile and install CUPS with "--enable-debug-printfs", run cups-browsed (or a test program) against that libcups.so.2 with:
>
> CUPS_DEBUG_LOG=debug.log CUPS_DEBUG_LEVEL=6 CUPS_DEBUG_FILTER="^(http|ipp|cupsDo|cupsGet|cupsSend)" LD_LIBRARY_PATH=/path/to/cups/source/dir/cups cups-browsed-command
>
> then send me the "debug.log" file along with the packet trace. Something isn't right if the timeouts are not working - we depend on it for ipptool's timeout support, for example.
I have done this now. Setup is as follows:
Client is my real iron with IP 192.168.122.1
Server is a VM with IP 192.168.122.92
The server shares some CUPS queues (with PPDs), one of them is
wily-printer on which we will print from the client.
On the client there are some local queues which do not name-clash with
the server's queues. The client is running cups-browsed, automatically
creating local queues pointing to the server's queues, so one of them is
named wily-printer.
The local queue which cups-browsed creates uses the
/usr/lib/cups/backend/implicitclass backend, which is part of
cups-filters. cups-browsed subscribes to CUPS notifications on D-Bus and
as soon as a job on a printer with the implicitclass backend starts
processing, cups-browsed tell via IPP attribute on this queue to which
server to send the job. The implicitclass backend waits for this
attribute and sends the data on to the server as soon as it gets the
attribute.
This works perfectly well with a bug-free implicitclass backend as it is
now on the BZR repository of cups-filters. I cannot even reproduce my
problem with a bug-free implicitclass backend.
Now one could think that my problem is solved. I have fixed the bugs in
implicitclass and now all is working fine. But the problem is how
cups-browsed behaves. The servers's cupsd is not responding in time any
more, probably because it got bombed by the job and when trying to stop
cups-browsed with Ctrl+C or SIGTERM it takes more than a minute to shut
down, even with all HTTP and IPP timeouts shortened to 3 seconds
(default is 30 seconds AFAIK).
So to reproduce the problem I have put up a buggy version of the
implicitclass backend with the following two bugs:
- As soon as implicitclass knows the destination, it uses libcups'
functions to print a job and it prints the job on the remote server,
using cupsSetServer() but instead of using "host:631" as server string
it uses "host:631:631" (looking into CUPS' source code it seems that
CUPS takes the port 631 then and the hostname "host:631").
- Due to the first bug the implicitclass backend fails to print the job
and exits with CUPS_BACKEND_RETRY_CURRENT instead of correctly with
CUPS_BACKEND_RETRY. This makes the job being repeated immediately and
not after a delay of AFAIR 30 seconds.
It seems that these two bugs make the server being bombed (I do not get
an answer when entering the command "lpstat -o" in a terminal on the
server) and cups-browsed does not get answers from the server when
checking the server as destination for the next attempt of the job.
When one now tries to stop cups-browsed with Ctrl+C or SIGTERM,
cups-browsed needs more than one minute to stop, and that with each
request to the server correctly timing out after 3 seconds, so no part
of cups-browsed should be blocked for more than 3 seconds. And the CUPS
notification handler does only one IPP request to the server at a time,
it does not loop several times before returning.
So the problem is the time cups-browsed needs to stop when a server is
in a bad state.
For getting the logs you have asked for I have run Wireshark monitoring
the network interface between my real iron and the VM (virbr0), CUPS I
have running in debug logging mode and for cups-browsed I have used the
command line you mentioned, using libcups of a CUPS 2.2.0 (today's GIT)
built with --enable-debug-printfs. Here is the command line of cups-browsed:
sudo CUPS_DEBUG_LOG=cups-debug-2.log CUPS_DEBUG_LEVEL=6
CUPS_DEBUG_FILTER="^(http|ipp|cupsDo|cupsGet|cupsSend)"
LD_LIBRARY_PATH=/home/till/printing/cups/test/cups/cups ./cups-browsed
--debug 2>&1 | tee cups-browsed-2.log
The job I have started on the client via
lp -d wily-printer ~/.bashrc
It got the ID 2684 on the client. I do not know whether it got an ID on
the server.
I have made available a tarball with the following log files:
cups-browsed-2.log Log output of "cups-browsed --debug", see
my cups-browsed command line
cups-browsed-2.pcapng Wireshark's saved capture, needs Wireshark to
open
cups-browsed-2.txt Wireshark's capture as text file, no Wireshark
needed to open
cups-debug-2.log CUPS debug output of the libcups used by
cups-browsed, see my cups-browsed command line
error_log CUPS error_log on the client
error_log_server CUPS error_log on the server
Note for Wireshark's packet capture that packets 1-371 are for starting
cups-browsed and all packets afterwards are of the execution of the job.
Here is the tarball with all the logs for download:
http://www.openprinting.org/download/cups-browsed-logs.xz
I hope this helps.
Till
More information about the cups-devel
mailing list