Re: [cups-devel] IPP requests: Non-blocking or short timeout

On 09/13/2016 01:10 PM, Michael Sweet wrote:
> Till,
>
>> On Sep 12, 2016, at 9:33 AM, Till Kamppeter <[email protected]> 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