Menu ▾ ▴

#1213 Wrong STARTTRANSFER timer for POST requests getting response code 100

closed-postponed
Daniel Stenberg
POST (2) CURLINFO_STARTTRANSFER_TIME (1)
4
2015-04-15
2013-04-06
Mezon
No

curl 7.28.1 (i686-pc-linux-gnu) libcurl/7.28.1 OpenSSL/0.9.8o zlib/1.2.3.4
Protocols: dict file ftp ftps gopher http https imap imaps pop3 pop3s rtsp smtp smtps telnet tftp
Features: IPv6 Largefile NTLM NTLM_WB SSL libz

There is an error in timing accounting at least for STARTTRANSFER timer during POST requests.

Timer works fine with GET requests, but while using POST the time for CURLINFO_STARTTRANSFER_TIME is wrong. While using POST CURLINFO_STARTTRANSFER_TIME minus CURLINFO_PRETRANSFER_TIME is near to zero every time.

Proof of concept:
I've prepared CGI script that sleeps 3 seconds on start, before it returns any data.
While making curl GET request to the script, (CURLINFO_STARTTRANSFER_TIME - CURLINFO_PRETRANSFER_TIME) is ok [~ 3 seconds]. Trying the same thing with POST request, cause the 3 seconds appears in CURLINFO_TOTAL_TIME instead of CURLINFO_STARTTRANSFER_TIME. So with POST it looks like the transfer took 3 seconds instead of waiting for server reply.

IMHO the problem is in ./lib/transfer.c in readwrite_upload() function, where Curl_pgrsTime(data, TIMER_STARTTRANSFER) is called in wrong place. Unfortunately I'm not sure where to replace it to fix the bug. I think it should go somewhere in Curl_readwrite() function, for example here:

/* We go ahead and do a read if we have a readable socket or if
     the stream was rewound (in which case we have data in a
     buffer) */
if((k->keepon & KEEP_RECV) &&
     ((select_res & CURL_CSELECT_IN) || conn->bits.stream_was_rewound)) {

    result = readwrite_data(data, conn, k, &didwhat, done);
    if(result || *done)
      return result;
  }
  else {
      Curl_pgrsTime(data, TIMER_STARTTRANSFER); // <-- here
  }

I'm not sure if any other timers are affected.

Best regards,
Mezon

Discussion

  • Daniel Stenberg

    Daniel Stenberg - 2013-06-17
    • labels: TIMER_STARTTRANSFER, Curl_pgrsTime, POST, CURLINFO_STARTTRANSFER_TIME --> POST, CURLINFO_STARTTRANSFER_TIME
    • status: open --> pending-invalid
    • assigned_to: Daniel Stenberg
     

  • Daniel Stenberg

    Daniel Stenberg - 2013-06-17

    I'm sorry but I read the code and I can't see the problem. I believe your test case is wrong. readwrite_upload() clearly sets the timer on its first invoke when nothing has been sent before. So, I think libcurl sends the data very early, it is just that your CGI waits so it doesn't receive it until later but your server did...

     

  • Mezon

    Mezon - 2013-06-20

    So, how will you explain different timing for POST and GET methods for the same CGI script?

    Mezon

     

  • Daniel Stenberg

    Daniel Stenberg - 2013-06-20

    Hm, right. No it may still be something there...

     

  • Daniel Stenberg

    Daniel Stenberg - 2013-09-12

    Hi again, any chance you can help us out with this and try making a patch for this problem?

     

  • Daniel Stenberg

    Daniel Stenberg - 2013-10-07
    • status: open --> pending
     

  • Daniel Stenberg

    Daniel Stenberg - 2013-10-07

    This is a low-prio problem for me and nobody else has stepped up. I'll document this as a known bug and close this report within shortly.

     

  • Daniel Stenberg

    Daniel Stenberg - 2013-11-05

    This problem is now mentioned as KNOWN_BUG #85 and is now marked for "later". Closing.

     

  • Daniel Stenberg

    Daniel Stenberg - 2013-11-05
    • status: pending --> closed-later
     

  • Fabian Frank

    Fabian Frank - 2014-01-19

    I had a mini heart attack when I read this, because I actually rely on CURLINFO_STARTTRANSFER_TIME for POST uploads in production. I tried to reproduce this with my own mock server, which is also capable of sleeping first and only then sending any data. I can not confirm this bug.

    Example output for POST:

    * STATE: INIT => CONNECT handle 0x7ffeb200cc08; line 1020 (connection #-5000)
* Hostname was NOT found in DNS cache
*   Trying 127.0.0.1...
* STATE: CONNECT => WAITCONNECT handle 0x7ffeb200cc08; line 1067 (connection #0)
* Connected to 127.0.0.1 (127.0.0.1) port 8000 (#0)
* STATE: WAITCONNECT => DO handle 0x7ffeb200cc08; line 1186 (connection #0)
> POST /sleep?t=1000 HTTP/1.1
Host: 127.0.0.1:8000
Accept: */*
Content-Length: 7
Content-Type: application/x-www-form-urlencoded

* upload completely sent off: 7 out of 7 bytes
* STATE: DO => DO_DONE handle 0x7ffeb200cc08; line 1272 (connection #0)
* STATE: DO_DONE => WAITPERFORM handle 0x7ffeb200cc08; line 1398 (connection #0)
* STATE: WAITPERFORM => PERFORM handle 0x7ffeb200cc08; line 1411 (connection #0)
* HTTP 1.1 or later with persistent connection, pipelining supported
< HTTP/1.1 200 OK
< Content-Type: text/plain
< Date: Sun, 19 Jan 2014 21:41:03 GMT
< Connection: keep-alive
< Transfer-Encoding: chunked
<
finished sleeping
* STATE: PERFORM => DONE handle 0x7ffeb200cc08; line 1581 (connection #0)
* Connection #0 to host 127.0.0.1 left intact
URL: http://127.0.0.1:8000/sleep?t=1000
CURLINFO_TOTAL_TIME: 1.00283900
CURLINFO_CONNECT_TIME: 0.00086900
CURLINFO_PRETRANSFER_TIME: 0.00095600
**CURLINFO_STARTTRANSFER_TIME: 1.00263300**

    Example output for GET:

    * STATE: INIT => CONNECT handle 0x7f8b6400cc08; line 1020 (connection #-5000)
* Hostname was NOT found in DNS cache
*   Trying 127.0.0.1...
* STATE: CONNECT => WAITCONNECT handle 0x7f8b6400cc08; line 1067 (connection #0)
* Connected to 127.0.0.1 (127.0.0.1) port 8000 (#0)
* STATE: WAITCONNECT => DO handle 0x7f8b6400cc08; line 1186 (connection #0)
> GET /sleep?t=1000 HTTP/1.1
Host: 127.0.0.1:8000
Accept: */*

* STATE: DO => DO_DONE handle 0x7f8b6400cc08; line 1272 (connection #0)
* STATE: DO_DONE => WAITPERFORM handle 0x7f8b6400cc08; line 1398 (connection #0)
* STATE: WAITPERFORM => PERFORM handle 0x7f8b6400cc08; line 1411 (connection #0)
* HTTP 1.1 or later with persistent connection, pipelining supported
< HTTP/1.1 200 OK
< Content-Type: text/plain
< Date: Sun, 19 Jan 2014 21:42:28 GMT
< Connection: keep-alive
< Transfer-Encoding: chunked
<
finished sleeping
* STATE: PERFORM => DONE handle 0x7f8b6400cc08; line 1581 (connection #0)
* Connection #0 to host 127.0.0.1 left intact
URL: http://127.0.0.1:8000/sleep?t=1000
CURLINFO_TOTAL_TIME: 1.00215800
CURLINFO_CONNECT_TIME: 0.00086800
CURLINFO_PRETRANSFER_TIME: 0.00095700
**CURLINFO_STARTTRANSFER_TIME: 1.00196000**

    In both cases the CURLINFO_STARTTRANSFER_TIME matches exactly the 1s sleep of the mock server.

     

  • Mezon

    Mezon - 2014-06-05

    Hi,
    we dig into this subject further and dicovered that the problem is only in case of sending http header: Expect: 100-continue

    Thats because the server will send reply: HTTP/1.1 100 Continue before the communication ends, and curl will assume that the server started sending data, which is false.

    When HTTP/1.1 100 Continue is sent by server, curl will continue to sending real POST data. The counter should start when curl finish sending data, but it has already been set while 100 Continue was recived.

    This is why the counter STARTTRANSFER is bugged - in this particular situation, when curl uses Expect: 100-continue

    We will try to handle his and send the patch.
    Best regards,
    Mezon

     

  • Daniel Stenberg

    Daniel Stenberg - 2014-06-05
    • status: closed-later --> open
     

  • Daniel Stenberg

    Daniel Stenberg - 2014-06-05

    Thanks, I'm re-opening this issue again then anticipating that we get some more data/code/reports on this.

     

  • Daniel Stenberg

    Daniel Stenberg - 2014-07-23
    • summary: Wrong STARTTRANSFER timer accounting for POST requests --> Wrong STARTTRANSFER timer for POST requests getting response code 100
     

  • Lucas Manuel Rodriguez

    Lucas Manuel Rodriguez - 2014-10-06

    Hello Daniel & Mezon,

    I have came across the same timing issue. That is, a wrong STARTTRANSFER time when POSTing data bigger than 1024 bytes (1024 is the value of TINY_INITIAL_POST_SIZE defined in lib/http.h). Mezon is right, it's using the 100-continue response to set the STARTTRANSFER time, instead of the time of the first byte of actual data received.

    I have attached a nodejs script to reproduce the issue:

    # Set up dummy server
$ nodejs index.js 8000

# Curl command that throws the STARTTRANSFER value to stdout
# data.txt should be a file with > 1024 bytes of data.
$ curl -v --data @data.txt --write-out ">>> Pre transfer time: %{time_pretransfer}\n>>> Start Transfer Time: %{time_starttransfer}\n>>> Total time: %{time_total}\n\n" http://127.0.0.1:8000/

    I have also attached a patch with a possible solution, a review would be really appreciated.

    Hope that helps.
    Thanks,
    Lucas Manuel Rodriguez.

     
    bug_1213.diff
    index.js

  • Daniel Stenberg

    Daniel Stenberg - 2015-04-15

    This issue is now instead tracked at https://github.com/bagder/curl/issues/218

     

  • Daniel Stenberg

    Daniel Stenberg - 2015-04-15
    • status: open --> closed-postponed