Uploaded image for project: 'Qt'
  1. Qt
  2. QTBUG-20924

Threaded HTTP Backend in QNetworkAccessManager does not handle remote socket closes correctly

    XMLWordPrintable

Details

    • Bug
    • Resolution: Done
    • P2: Important
    • 4.8.2
    • 4.8.0
    • Network
    • None
    • Mac OS X 10.6
    • b754deb055db1b3d74f4ecaed38fa7e59fdcd877; 2cfc2a2e9af97a2799e76868e4c6b302d55266e0

    Description

      With the introduction of the threaded http backend code the keep alive handling does not seem to work properly any longer (at least on Mac OS X).

      I've done a direct comparison of the event flow between 4.7 and 4.8 by activating the debug macros in the Qt network code.

      The problem in 4.8 seems to be that the new implementation tries to write data to a socket that's already been closed.

      The server used to reproduce this is configured not to do keep alive connections. However similar problems arise when turning keep alive on, it's only later when the server begins to close the connections (due to timeout or usage count).

      ---------------------------------------------------------------------------------------------------------------------------------
4.7 (good)
---------------------------------------------------------------------------------------------------------------------------------

4.7 -- 1. request

HandlerManager::postRequest "http://localhost:9090/tksuite/login" 
QTcpSocket::QTcpSocket()
QTcpSocket::QTcpSocket()
QTcpSocket::QTcpSocket()
QTcpSocket::QTcpSocket()
QTcpSocket::QTcpSocket()
QTcpSocket::QTcpSocket()
QNativeSocketEnginePrivate::nativeConnect() : 14 
QNativeSocketEnginePrivate::nativeConnect(127.0.0.1, 9090) == false (Connection in progress)
QNativeSocketEnginePrivate::nativeConnect() : 14 
QNativeSocketEnginePrivate::nativeConnect(127.0.0.1, 9090) == true
QNativeSocketEnginePrivate::fetchConnectionParameters() local == 127.0.0.1:64555, peer == 127.0.0.1:9090, socket == TcpSocket - IPv4Protocol
QNativeSocketEnginePrivate::nativeWrite(0x11900ca18 "POST /tksuite/lo...", 253) == 253
QNativeSocketEnginePrivate::nativeBytesAvailable() == 523
QNativeSocketEnginePrivate::nativeRead(0x11900ca18 "HTTP/1.1 200 OK\r...", 523) == 523
QNativeSocketEngine::nativeClose()
HEADER:  "Cache-Control" : "no-cache" 
HEADER:  "Connection" : "Close" 
HEADER:  "Content-Length" : "245" 
HEADER:  "Content-Type" : "application/json" 
HEADER:  "Date" : "Mon, 15 Aug 2011 14:21:41 GMT" 
HEADER:  "Server" : "HTTP/1.1" 
HEADER:  "Set-Cookie" : "sessionid=456cd9c4-f51f-4f88-9f9d-bc7fa388e5fc; path=/" 
HEADER:  "Transfer-Encoding" : "chunked" 
RequestHandlerManager::requestFinished(): code: 200 0  
                                          
4.7 -- first request has finished, everything is fine
4.7 -- 2. and 3. request (simultaneously)

HandlerManager::postRequest "http://localhost:9090/tksuite/user/list" 
HandlerManager::postRequest "http://localhost:9090/tksuite/favouritelist/list" 

4.7 -- opening a new connection for each request because the old one has been correctly detected as closed

QNativeSocketEnginePrivate::nativeConnect() : 17 
QNativeSocketEnginePrivate::nativeConnect(127.0.0.1, 9090) == false (Connection in progress)
QNativeSocketEnginePrivate::nativeConnect() : 18 
QNativeSocketEnginePrivate::nativeConnect(127.0.0.1, 9090) == false (Connection in progress)
QNativeSocketEnginePrivate::nativeConnect() : 17 
QNativeSocketEnginePrivate::nativeConnect(127.0.0.1, 9090) == true
QNativeSocketEnginePrivate::fetchConnectionParameters() local == 127.0.0.1:64556, peer == 127.0.0.1:9090, socket == TcpSocket - IPv4Protocol
QNativeSocketEnginePrivate::nativeWrite(0x11900ca18 "POST /tksuite/us...", 357) == 357
QNativeSocketEnginePrivate::nativeConnect() : 18 
QNativeSocketEnginePrivate::nativeConnect(127.0.0.1, 9090) == true
QNativeSocketEnginePrivate::fetchConnectionParameters() local == 127.0.0.1:64557, peer == 127.0.0.1:9090, socket == TcpSocket - IPv4Protocol
QNativeSocketEnginePrivate::nativeWrite(0x11900ca18 "POST /tksuite/fa...", 380) == 380
QNativeSocketEnginePrivate::nativeBytesAvailable() == 199
QNativeSocketEnginePrivate::nativeRead(0x11900ca18 "HTTP/1.1 200 OK\r...", 199) == 199
QNativeSocketEnginePrivate::nativeBytesAvailable() == 5139
QNativeSocketEnginePrivate::nativeRead(0x11900ca18 "HTTP/1.1 200 OK\r...", 5139) == 5139
QNativeSocketEnginePrivate::nativeBytesAvailable() == 5
QNativeSocketEnginePrivate::nativeRead(0x11900ca18 "0\r\n\r\n", 5) == 5
QNativeSocketEngine::nativeClose()
HEADER:  "Cache-Control" : "no-cache" 
HEADER:  "Connection" : "Close" 
HEADER:  "Content-Length" : "4924" 
HEADER:  "Content-Type" : "application/json" 
HEADER:  "Date" : "Mon, 15 Aug 2011 14:21:41 GMT" 
HEADER:  "Server" : "HTTP/1.1" 
HEADER:  "Transfer-Encoding" : "chunked" 
RequestHandlerManager::requestFinished(): code: 200 0  
QNativeSocketEnginePrivate::nativeBytesAvailable() == 600
QNativeSocketEnginePrivate::nativeRead(0x119009218 "24C\r\n{\n   "data"...", 600) == 600
QNativeSocketEngine::nativeClose()
HEADER:  "Cache-Control" : "no-cache" 
HEADER:  "Connection" : "Close" 
HEADER:  "Content-Length" : "588" 
HEADER:  "Content-Type" : "application/json" 
HEADER:  "Date" : "Mon, 15 Aug 2011 14:21:41 GMT" 
HEADER:  "Server" : "HTTP/1.1" 
HEADER:  "Transfer-Encoding" : "chunked" 
RequestHandlerManager::requestFinished(): code: 200 0  

---------------------------------------------------------------------------------------------------------------------------------
4.8 (bad)
---------------------------------------------------------------------------------------------------------------------------------

4.8 -- 1. request

HandlerManager::postRequest "http://localhost:9090/tksuite/login" 
QHttpThreadDelegate::startRequest() thread= 0x11ada5000 
QTcpSocket::QTcpSocket()
QTcpSocket::QTcpSocket()
QTcpSocket::QTcpSocket()
QTcpSocket::QTcpSocket()
QTcpSocket::QTcpSocket()
QTcpSocket::QTcpSocket()
QNativeSocketEnginePrivate::nativeConnect() : 16 
QNativeSocketEnginePrivate::nativeConnect(127.0.0.1, 9090) == false (Connection in progress)
QNativeSocketEnginePrivate::nativeConnect() : 16 
QNativeSocketEnginePrivate::nativeConnect(127.0.0.1, 9090) == true
QNativeSocketEnginePrivate::fetchConnectionParameters() local == 127.0.0.1:64591, peer == 127.0.0.1:9090, socket == TcpSocket - IPv4Protocol
QNativeSocketEnginePrivate::nativeWrite(0x1065f9078 "POST /tksuite/lo...", 207) == 207 SD 16
QNativeSocketEnginePrivate::nativeWrite(0x1125675c8 "{"data":{"login"...", 46) == 46 SD 16
QNativeSocketEnginePrivate::nativeBytesAvailable() == 0
QNativeSocketEnginePrivate::nativeBytesAvailable() == 267
QNativeSocketEnginePrivate::nativeBytesAvailable() == 523
QNativeSocketEnginePrivate::nativeRead(0x105051418 "HTTP/1.1 200 OK\r...", 523) == 523
QHttpThreadDelegate::headerChangedSlot() thread= 0x11ada5000 
QNativeSocketEnginePrivate::nativeBytesAvailable() == 0
QNativeSocketEnginePrivate::nativeBytesAvailable() == 0
QNativeSocketEnginePrivate::nativeBytesAvailable() == 0
QNativeSocketEnginePrivate::nativeBytesAvailable() == 0
QNativeSocketEnginePrivate::nativeBytesAvailable() == 0
QNativeSocketEnginePrivate::nativeBytesAvailable() == 0
QNativeSocketEnginePrivate::nativeBytesAvailable() == 0
QHttpThreadDelegate::finishedSlot() thread= 0x11ada5000 result= 200 
QNativeSocketEnginePrivate::nativeBytesAvailable() == 0
HEADER:  "Cache-Control" : "no-cache" 
HEADER:  "Connection" : "Close" 
HEADER:  "Content-Length" : "245" 
HEADER:  "Content-Type" : "application/json" 
HEADER:  "Date" : "Mon, 15 Aug 2011 14:25:05 GMT" 
HEADER:  "Server" : "HTTP/1.1" 
HEADER:  "Set-Cookie" : "sessionid=dd5322ce-856d-4664-ae58-c2d8d7185822; path=/" 
HEADER:  "Transfer-Encoding" : "chunked" 
RequestHandlerManager::requestFinished(): code: 200 0  


4.8 -- done, fine
4.8 -- 2. and 3. request (simultaneously)

HandlerManager::postRequest "http://localhost:9090/tksuite/user/list" 
HandlerManager::postRequest "http://localhost:9090/tksuite/favouritelist/list" 
QHttpThreadDelegate::startRequest() thread= 0x11ada5000 

4.8 -- why trying to write to socket descriptor 16? (should be already closed, see "connection: close" above)

QNativeSocketEnginePrivate::nativeWrite(0x1065f97b8 "POST /tksuite/us...", 267) == 267 SD 16

4.8 -- correctly trying to open a second connection for the second request

QHttpThreadDelegate::startRequest() thread= 0x11ada5000 
QNativeSocketEnginePrivate::nativeConnect() : 18 
QNativeSocketEnginePrivate::nativeConnect(127.0.0.1, 9090) == false (Connection in progress)
QNativeSocketEngine::nativeClose()

4.8 -- boom => now it's detected that socket descriptor 16 is closed, we get an error now!

QNativeSocketEnginePrivate::nativeWrite(0x115bee2f8 "{"data":null,"pr...", 90) == -1 SD -1
QHttpThreadDelegate::finishedWithErrorSlot() thread= 0x11ada5000 error= 99 "" 

4.8 -- this is where we get informed about the "error"

http error! 99 "" 
QNativeSocketEnginePrivate::nativeConnect() : 18 
QNativeSocketEnginePrivate::nativeConnect(127.0.0.1, 9090) == true
RequestHandlerManager::requestFinished(): code: 0 99  
QNativeSocketEnginePrivate::fetchConnectionParameters() local == 127.0.0.1:64592, peer == 127.0.0.1:9090, socket == TcpSocket - IPv4Protocol

4.8 -- while the second request is written to the new socket...

QNativeSocketEnginePrivate::nativeWrite(0x1065fa048 "POST /tksuite/fa...", 277) == 277 SD 18
QHttpThreadDelegate::abortRequest() thread= 0x11ada5000 sync= false 
QNativeSocketEnginePrivate::nativeWrite(0x112568cb8 "{"data":null,"pr...", 103) == 103 SD 18
QNativeSocketEnginePrivate::nativeBytesAvailable() == 0
QNativeSocketEnginePrivate::nativeBytesAvailable() == 199
QNativeSocketEnginePrivate::nativeBytesAvailable() == 799
QNativeSocketEnginePrivate::nativeRead(0x112816218 "HTTP/1.1 200 OK\r...", 799) == 799
QHttpThreadDelegate::headerChangedSlot() thread= 0x11ada5000 
QNativeSocketEnginePrivate::nativeBytesAvailable() == 0
QNativeSocketEnginePrivate::nativeBytesAvailable() == 0
QNativeSocketEnginePrivate::nativeBytesAvailable() == 0
QNativeSocketEnginePrivate::nativeBytesAvailable() == 0
QNativeSocketEnginePrivate::nativeBytesAvailable() == 0
QNativeSocketEnginePrivate::nativeBytesAvailable() == 0
QNativeSocketEnginePrivate::nativeBytesAvailable() == 0
QHttpThreadDelegate::finishedSlot() thread= 0x11ada5000 result= 200 
QNativeSocketEnginePrivate::nativeBytesAvailable() == 0
HEADER:  "Cache-Control" : "no-cache" 
HEADER:  "Connection" : "Close" 
HEADER:  "Content-Length" : "588" 
HEADER:  "Content-Type" : "application/json" 
HEADER:  "Date" : "Mon, 15 Aug 2011 14:25:05 GMT" 
HEADER:  "Server" : "HTTP/1.1" 
HEADER:  "Transfer-Encoding" : "chunked" 
RequestHandlerManager::requestFinished(): code: 200 0  

etc.

      Attachments

        Issue Links

          relates to

          Bug - A problem which impairs or prevents the functions of the product. QTBUG-25675 Connection closed before finish processing an URL

          • P2: Important - Urgent, should be fixed, but will not stop the release.
          • Closed
          No reviews matched the request. Check your Options in the drop-down menu of this sections header.

          Activity

            People

              xcm Martin Petersson (Inactive)
              njeisecke Nils Jeisecke
              Votes:
              6 Vote for this issue
              Watchers:
              8 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved:

                Gerrit Reviews

                  There are no open Gerrit changes