Loading...

Type: Bug
Resolution: Done
Priority: P2: Important
Fix Version/s: 4.8.2
Affects Version/s: 4.8.0
Component/s: Network
Labels:
None
Environment:
Mac OS X 10.6

Commits:
b754deb055db1b3d74f4ecaed38fa7e59fdcd877; 2cfc2a2e9af97a2799e76868e4c6b302d55266e0

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.

relates to

QTBUG-25675 Connection closed before finish processing an URL

Closed

- Issue Only
- Show All Reviews
- Show Open Reviews
- Show All Issues
- Show Open Issues

No reviews matched the request. Check your Options in the drop-down menu of this sections header.

Details

Description

Attachments

Issue Links

Gerrit Reviews

Activity

People

Dates

Gerrit Reviews