_cupsConnect() can return cached http connection which is already unusable #4187

Closed
michaelrsweet opened this Issue Sep 12, 2012 · 7 comments

Comments

Projects
None yet
1 participant
Collaborator

michaelrsweet commented Sep 12, 2012

Version: 1.6-current
CUPS.org User: cvachoucek

Hi all,
we have CUPS clients configured to print directly to remote CUPS server - ie. we have /etc/cups/client.conf with ServerName pointing to our CUPS server. And we see such unpleasant behavior:

  1. first time the app does some request to libcups.so, the HTTP connection is
    created and used - all works ok. The HTTP connection is not closed but cached
    in _cupsGlobals.

  2. The CUPS server has its timeout - if the connection is idle for some time
    (the default is 5 minutes), it closes it. This can be verified for example
    by netstat output on clients - the TCP connection state changes from
    ESTABLISHED to CLOSE_WAIT.

  3. Next time the app does some request to libcups.so, the cached HTTP connection
    is directly used - returned by _cupsConnect(). Request is sent (no error
    produced) and when reading response, the recv() call gets ECONNRESET and
    the request fails.

This is easy to reproduce. Start OpenOffice or LibreOffice,
open "File -> Printer Settings" dialog, close it and wait 5 minutes.
Then try to open it again - and the list of printers is empty.

The idea for fix is to check the TCP connection state in _cupsConnect()
and verify the connection is still in ESTABLISHED state. If its not then
close it - the _cupsConnect() will then re-create it.

I'm attaching the patch with the fix for Solaris - checking the TCP connection
state is system-specific, so the real fix for upstream would have to add
the code for other supported platforms as well.

I understand the fix is not perfect - there's still chance for request to fail
if the server closes the connection just after the client checks it. But it is
not very invasive and improves the users experience a lot in this scenario,
because otherwise this bug is hit always and is very annoying for users.

Collaborator

michaelrsweet commented Oct 1, 2012

CUPS.org User: mike

Petr,

When we try to send the next request on a closed connection we will get an error back from send(), which will trigger a reconnect. Can you compile and install CUPS with debug logging (./configure --enable-debug-printfs ...), and then run an affected application with the following environment variables set:

CUPS_DEBUG_LOG=filename.log CUPS_DEBUG_LEVEL=6 CUPS_DEBUG_FILTER='^(http|ipp|_http|_ipp|cupsDo|cupsSend|cupsGetResponse).*$' command

and then attach the log file to this bug?

Thanks!

Collaborator

michaelrsweet commented Oct 1, 2012

CUPS.org User: cvachoucek

Requested log file attached. Interesting parts are at its end - failed request starts at line 9659. The log was created on Solaris 11, where we ship CUPS version 1.4.5. Its not so easy for me to try latest CUPS on Solaris, but before submitting the bug report I've reproduced it on SUSE Linux 12.2 (CUPS 1.5.3) and Arch Linux (CUPS 1.6.1).

Thanks!
Petr

Collaborator

michaelrsweet commented Oct 2, 2012

CUPS.org User: cvachoucek

I was able to reproduce the problem with CUPS 1.6.1 on Solaris. Debug log attached as cups-1.6.1-debug.zip.

Collaborator

michaelrsweet commented Dec 13, 2012

CUPS.org User: mike

Proposed change attached; basically I added a recv() call to peek at the incoming side of the connection - if it fails (other than for "would block") then we reset the connection.

Collaborator

michaelrsweet commented Mar 20, 2013

CUPS.org User: till.kamppeter

Ubuntu bug report

https://bugs.launchpad.net/ubuntu/+source/cups/+bug/1020048

seems to be about the same problem.

Collaborator

michaelrsweet commented Mar 20, 2013

"cupsconnect.patch":

diff -Naur cups-1.6svn-r10486.orig/cups/request.c cups-1.6svn-r10486/cups/request.c
--- cups-1.6svn-r10486.orig/cups/request.c 2012-05-12 02:07:16.000000000 +0200
+++ cups-1.6svn-r10486/cups/request.c 2012-09-12 09:16:21.888777664 +0200
@@ -46,7 +46,9 @@
#ifndef O_BINARY

define O_BINARY 0

#endif /* O_BINARY */

+#if defined(__sun)
+#include <inet/tcp.h> /* need this for TCPS_ESTABLISHED ... */
+#endif

/*

  • 'cupsDoFileRequest()' - Do an IPP request with a file.
    @@ -1000,6 +1002,38 @@
    }
    }

+#if defined(__sun)

  • /*
  • * Check the connection state.
  • * If the connection wasn't used for some time, the server could close it.
  • * The socket state would change to CLOSE_WAIT in such case.
  • */
  • if (cg->http)
  • {
  • struct tcp_info tcpi;
  • socklen_t len = sizeof(tcpi);
  • memset(&tcpi, 0, sizeof(tcpi));
  • /*
  • * Get TCP connection info.
  • */
  • if (getsockopt(cg->http->fd, IPPROTO_TCP, TCP_INFO, &tcpi, &len) == 0)
  • {
  • /*
    
  •  \* Successfully got TCP connection state. Check it.
    
  •  */
    
  •  if (tcpi.tcpi_state != TCPS_ESTABLISHED)
    
  •  {
    
  •   /*
    
  •    \* Need to close the current connection.
    
  •    */
    
  •    httpClose(cg->http);
    
  •    cg->http = NULL;
    
  •  }
    
  • }
  • }
    +#endif

/*

  • (Re)connect as needed...
    */
Collaborator

michaelrsweet commented Mar 20, 2013

"str4187.patch":

Index: cups/request.c

--- cups/request.c (revision 10756)
+++ cups/request.c (working copy)
@@ -1007,6 +1007,25 @@
httpClose(cg->http);
cg->http = NULL;
}

  • else
  • {
  • /*
    
  •  \* Same server, see if the connection is still established...
    
  •  */
    
  •  char ch;             /\* Connection check byte */
    
  •  if (recv(cg->http->fd, &ch, 1, MSG_PEEK | MSG_DONTWAIT) < 0 &&
    
  •      errno != EWOULDBLOCK)
    
  •  {
    
  •   /*
    
  •    \* Nope, close the connection...
    
  •    */
    
  • httpClose(cg->http);
  • cg->http = NULL;
  •  }
    
  • }
    }

/*

michaelrsweet added this to the Stable milestone Mar 17, 2016

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment