cURL cURL > Mailing List > Monthly Index > Single Mail

curl-tracker Archives

[curl:bugs] #1420 Pipelining + client-side timeouts lead to loss of synchronization with response stream and incorrect data delivery

From: Carlo Wood <libcw_at_users.sf.net>
Date: Thu, 30 Oct 2014 01:05:52 +0000

Hmm, if life was only this simple...

0x7fffe0a9d700 CURLIO 0x7fffc9173c80 * Connection cache is full, closing the oldest one.
0x7fffe0a9d700 CURLIO : 0x7fffc9173c80 Connection closed (#4); 0 connections remaining [0x7fffc8015110].
0x7fffe0a9d700 CURLIO 0x7fffc9173c80 * Closing connection 4
0x7fffe0a9d700 CURLIO 0x7fffc9173c80 * Removed connection 0x7fffd8484e18 to bundle at 0x7fffd849acb8, 0 connections left.
0x7fffe0a9d700 CURLIO 0x7fffc9173c80 * Destroying bundle at 0x7fffd849acb8
0x7fffe0a9d700 CURLIO 0x7fffc9173c80 * The cache now contains 9 members
...
0x7fffe0a9d700 CURLIO 0x7fffc916d0d0 * Created a new bundle at 0x7fffd876fd58
0x7fffe0a9d700 CURLIO 0x7fffc916d0d0 * Added connection 0x7fffd8484e18 to bundle at 0x7fffd876fd58, now 1 connections.
0x7fffe0a9d700 CURLIO 0x7fffc916d0d0 * Added connection 19. The cache now contains 10 members
...
and there we go again
0x7fffe0a9d700 CURLIO 0x7fffc9073d90 * Server doesn't support pipelining
...
0x7fffe0a9d700 CURLIO 0x7fffc916d0d0 * Added connection 0x7fffd8484e18 to bundle at 0x7fffd876fd58, now 1 connections.
0x7fffe0a9d700 CURLIO 0x7fffc9073d90 * Added connection 0x7fffd95f1848 to bundle at 0x7fffd876fd58, now 2 connections.
0x7fffe0a9d700 CURLIO 0x7fffc90574c0 * Added connection 0x7fffd959c2d8 to bundle at 0x7fffd876fd58, now 3 connections.
0x7fffe0a9d700 CURLIO 0x7fffc89ec6a0 * Added connection 0x7fffd95ef888 to bundle at 0x7fffd876fd58, now 4 connections.
0x7fffe0a9d700 CURLIO 0x7fffc89e9c10 * Added connection 0x7fffd93b2588 to bundle at 0x7fffd876fd58, now 5 connections.
0x7fffe0a9d700 CURLIO 0x7fffc8f634b0 * Added connection 0x7fffd9786a38 to bundle at 0x7fffd876fd58, now 6 connections.
0x7fffe0a9d700 CURLIO 0x7fffc8c703b0 * Added connection 0x7fffd93b1a68 to bundle at 0x7fffd876fd58, now 7 connections.
0x7fffe0a9d700 CURLIO 0x7fffc9042600 * Added connection 0x7fffd8f5c558 to bundle at 0x7fffd876fd58, now 8 connections.
0x7fffe0a9d700 CURLIO 0x7fffc916d850 * Added connection 0x7fffd8f5cc28 to bundle at 0x7fffd876fd58, now 9 connections.
0x7fffe0a9d700 CURLIO 0x7fffc903d4b0 * Added connection 0x7fffd8f46b18 to bundle at 0x7fffd876fd58, now 10 connections.
0x7fffe0a9d700 CURLIO 0x7fffc92629e0 * Added connection 0x7fffd9733428 to bundle at 0x7fffd876fd58, now 11 connections.
0x7fffe0a9d700 CURLIO 0x7fffc8cd4020 * Added connection 0x7fffd9733af8 to bundle at 0x7fffd876fd58, now 12 connections.
0x7fffe0a9d700 CURLIO 0x7fffc9174320 * Added connection 0x7fffd9615e78 to bundle at 0x7fffd876fd58, now 13 connections.
0x7fffe0a9d700 CURLIO 0x7fffc916c7c0 * Added connection 0x7fffd9616548 to bundle at 0x7fffd876fd58, now 14 connections.
0x7fffe0a9d700 CURLIO 0x7fffc91768f0 * Added connection 0x7fffd9616c18 to bundle at 0x7fffd876fd58, now 15 connections.
0x7fffe0a9d700 CURLIO 0x7fffc89e67e0 * Added connection 0x7fffd96172e8 to bundle at 0x7fffd876fd58, now 16 connections.
0x7fffe0a9d700 CURLIO 0x7fffc916e610 * Added connection 0x7fffd96179b8 to bundle at 0x7fffd876fd58, now 17 connections.
0x7fffe0a9d700 CURLIO 0x7fffc917d7b0 * Added connection 0x7fffd9599b38 to bundle at 0x7fffd876fd58, now 18 connections.
0x7fffe0a9d700 CURLIO 0x7fffc91b1930 * Added connection 0x7fffd959a208 to bundle at 0x7fffd876fd58, now 19 connections.
0x7fffe0a9d700 CURLIO 0x7fffc9186ac0 * Added connection 0x7fffd975e328 to bundle at 0x7fffd876fd58, now 20 connections.
0x7fffe0a9d700 CURLIO 0x7fffc813ee50 * Added connection 0x7fffd959a8d8 to bundle at 0x7fffd876fd58, now 21 connections.
0x7fffe0a9d700 CURLIO 0x7fffc9283c90 * Added connection 0x7fffd959afa8 to bundle at 0x7fffd876fd58, now 22 connections.
0x7fffe0a9d700 CURLIO 0x7fffc8e1ede0 * Added connection 0x7fffd959b678 to bundle at 0x7fffd876fd58, now 23 connections.
0x7fffe0a9d700 CURLIO 0x7fffc813fde0 * Added connection 0x7fffd8f59428 to bundle at 0x7fffd876fd58, now 24 connections.
0x7fffe0a9d700 CURLIO 0x7fffc916cf20 * Added connection 0x7fffd8f59af8 to bundle at 0x7fffd876fd58, now 25 connections.
0x7fffe0a9d700 CURLIO 0x7fffc8f62d00 * Added connection 0x7fffd8f5a1c8 to bundle at 0x7fffd876fd58, now 26 connections.
0x7fffe0a9d700 CURLIO 0x7fffc9282710 * Added connection 0x7fffd8f5a898 to bundle at 0x7fffd876fd58, now 27 connections.
0x7fffe0a9d700 CURLIO 0x7fffc8e1d8d0 * Added connection 0x7fffd8f5af68 to bundle at 0x7fffd876fd58, now 28 connections.
0x7fffe0a9d700 CURLIO 0x7fffc8abb270 * Added connection 0x7fffd8f5b638 to bundle at 0x7fffd876fd58, now 29 connections.
0x7fffe0a9d700 CURLIO 0x7fffc8c2c3e0 * Added connection 0x7fffd8f5bd08 to bundle at 0x7fffd876fd58, now 30 connections.
0x7fffe0a9d700 CURLIO 0x7fffc91a44f0 * Added connection 0x7fffd9583f88 to bundle at 0x7fffd876fd58, now 31 connections.

---
** [bugs:#1420] Pipelining + client-side timeouts lead to loss of synchronization with response stream and incorrect data delivery**
**Status:** open
**Labels:** pipelining 
**Created:** Tue Sep 02, 2014 10:36 PM UTC by Monty Brandenberg
**Last Updated:** Wed Oct 29, 2014 09:12 PM UTC
**Owner:** nobody
I've been tracking a data corruption/missing http status problem and I think I have enough data for a useful bug report.
The problem centers around the handling of queued requests in a pipeline when preceding requests are failed in libcurl after committing to a request/response transaction.  In the table below, I show six GET requests pipelined on one connection.  'Time' is relative seconds since the creation of the connection.  The first three requests are processed normally.  The fourth request times out while processing the response body.  The fifth request times out waiting for the response header.  The sixth request is allowed to proceed but appears to be out-of-sync with the response stream.  I haven't dumped the data in verbose mode but I'd guess that the sixth request is consuming the remainder of the fourth request's response body in some demented fashion.
Request | Time | Event
------- | ---- | -----
0 | 0 | HEADEROUT issued
0 | 1 | First HEADERIN data
0 | 13 | Request completed, 200 status
1 | 0 | HEADEROUT issued
1 | 13 | First HEADERIN data
1 | 15 | Request completed, 200 status
2 | 0 | HEADEROUT issued
2 | 15 | First HEADERIN data
2 | 20 | Request completed, 200 status
3 | 0 | HEADEROUT issued
3 | 20 | First HEADERIN data
3 | 30 | Timeout declared (easy error 28)
3 | 30 | Request failed, easy 28 status
4 | 0 | HEADEROUT issued
4 | 30 | Timeout declared (easy error 28), no HEADERIN data seen
4 | 30 | Request failed, easy 28 status
5 | 13 | HEADEROUT issued
5 | 30 | First DATAIN received, NO HEADERIN data for this request
5 | 43 | Connection closed.  This may be in response to server socket close.
5 | 43 | Request appears to succeed but CURLINFO_RESPONSE_CODE returns 0.
The sixth request appears to succeed as far as multi_perform and multi_info_read are concerned.  But fetching CURLINFO_RESPONSE_CODE returns 0 for status.  
As a workaround, checking the status as above appears to be useful.  I'm not certain that's 100% reliable or that the connection will be broken immediately at that point.  This has the potential of going very wrong as far as data integrity goes.
If I understand this correctly, solutions would include:
* Canceling/failing a request that's active on a pipeline results in failure to all requests farther down the pipeline.
* Canceling/failing a request results in 'passivation' of the request.  It no longer interacts with the caller but remains active sinking data from the response until satisfied.
---
Sent from sourceforge.net because curl-tracker@cool.haxx.se is subscribed to https://sourceforge.net/p/curl/bugs/
To unsubscribe from further messages, a project admin can change settings at https://sourceforge.net/p/curl/admin/bugs/options.  Or, if this is a mailing list, you can unsubscribe from the mailing list.
Received on 2014-10-30

These mail archives are generated by hypermail.