Menu ▾ ▴

#1224 CONNECTTIMEOUT_MS functionality has been broken since 7.29

closed-fixed
Daniel Stenberg
None
5
2014-08-16
2013-05-15
stkasm92
No

I found that 7.29 and 7.30 libcurl versions have partly broken CONNECTTIMEOUT_MS functionality. These versions do not respect subseconds and use full-second resolution for timeouts even if compiled against c-ares.

OS: CentOS 6.3 x86_64

Broken: curl 7.30.0 (x86_64-unknown-linux-gnu) libcurl/7.30.0 OpenSSL/1.0.0 zlib/1.2.3 c-ares/1.9.1 libidn/1.18 libssh2/1.4.3 (the same goes for 7.29)

Good: curl 7.28.1 (x86_64-unknown-linux-gnu) libcurl/7.28.1 OpenSSL/1.0.0 zlib/1.2.3 c-ares/1.9.1 libidn/1.18 libssh2/1.4.3

Configuration options are exactly the same.

Simple php script to reproduce this:

::php

Trace for 7.28.1 (the good one):

socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 3
fcntl(3, F_GETFL) = 0x2 (flags O_RDWR)
fcntl(3, F_SETFL, O_RDWR|O_NONBLOCK) = 0
connect(3, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("8.9.8.9")}, 16) = -1 EINPROGRESS (Operation now in progress)
clock_gettime(CLOCK_MONOTONIC, {681218, 818857874}) = 0
clock_gettime(CLOCK_MONOTONIC, {681218, 819188128}) = 0
poll([{fd=3, events=POLLOUT|POLLWRNORM}], 1, 39) = 0 (Timeout)

Trace for 7.30.0 (the bad one):

socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 3
fcntl(3, F_GETFL) = 0x2 (flags O_RDWR)
fcntl(3, F_SETFL, O_RDWR|O_NONBLOCK) = 0
clock_gettime(CLOCK_MONOTONIC, {681540, 350585044}) = 0
connect(3, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("8.9.8.9")}, 16) = -1 EINPROGRESS (Operation now in progress)
clock_gettime(CLOCK_MONOTONIC, {681540, 351323315}) = 0
clock_gettime(CLOCK_MONOTONIC, {681540, 351379339}) = 0
clock_gettime(CLOCK_MONOTONIC, {681540, 351437113}) = 0
clock_gettime(CLOCK_MONOTONIC, {681540, 351493897}) = 0
poll([{fd=3, events=POLLOUT|POLLWRNORM}], 1, 0) = 0 (Timeout)
clock_gettime(CLOCK_MONOTONIC, {681540, 351618878}) = 0
clock_gettime(CLOCK_MONOTONIC, {681540, 351676111}) = 0
poll([{fd=3, events=POLLOUT}], 1, 1000) = 0 (Timeout)

Let me know if you need any additional info.

Thanks.

1 Attachments
debugit.c

Discussion

  • Daniel Stenberg

    Daniel Stenberg - 2013-05-21
    • status: open --> pending-invalid
    • assigned_to: Daniel Stenberg
     

  • Daniel Stenberg

    Daniel Stenberg - 2013-05-21

    Works for me. I just tried the latest dev version (I have no reason to beleive it works any differently than 7.30.0 in this aspect) and it worked fine:

    $ time ./debugit

    • STATE: INIT => CONNECT handle 0x1d8b7d8; line 1010 (connection #-5000)
    • About to connect() to IP port 80 (#0)
    • Trying IP...
    • Adding handle: conn: 0x1da6da8
    • Adding handle: send: 0
    • Adding handle: recv: 0
    • Curl_addHandleToPipeline: length: 1
    • 0x1d70128 is at send pipe head!
      • Conn 0 (0x1da6da8) send_pipe: 1, recv_pipe: 0
    • STATE: CONNECT => WAITCONNECT handle 0x1d8b7d8; line 1057 (connection #0)
    • Connection timed out after 2 milliseconds
    • Closing connection 0
    • The cache now contains 0 members
      curl_easy_perform() failed: Timeout was reached

    I attached my test program. My libcurl has version set:

    curl 7.31.0-DEV (x86_64-unknown-linux-gnu) libcurl/7.31.0-DEV OpenSSL/1.0.1e zlib/1.2.8 c-ares/1.10.1-DEV libidn/1.25 libssh2/1.4.4_DEV librtmp/2.3

    So, please help us repeat your claim!

     

  • stkasm92

    stkasm92 - 2013-05-22

    Hi Daniel,

    I forgot to mention 1 important part... The host:port you are trying to connect to must be completely unreachable from your network. Pick any unreachable external host (better outside of your network to prevent any ICMP replies from your router) which will timeout your request. It works fine if host refuses the connection or send any reply back. I can reproduce the same behavior for DNS resolvers connections. Probably it can be OS related, but CentOS / RedHat are de facto enterprise standard, so I'll appreciate any clues.

    Libcurl 7.28.1 is the latest version which handles such timeouts properly.

    Sure, here is the output:

    Latest daily build:

    curl -V

    curl 7.31.0-20130522 (x86_64-unknown-linux-gnu) libcurl/7.31.0-20130522 OpenSSL/1.0.0 zlib/1.2.3 c-ares/1.9.1 libidn/1.18 libssh2/1.4.3
    Protocols: dict file ftp ftps gopher http https imap imaps ldap ldaps pop3 pop3s rtsp scp sftp smtp smtps telnet tftp
    Features: AsynchDNS GSS-Negotiate IDN IPv6 Largefile NTLM NTLM_WB SSL libz

    ./debugit

    • About to connect() to 8.9.8.9 port 80 (#0)
    • Trying 8.9.8.9...
    • Adding handle: conn: 0x1527360
    • Adding handle: send: 0
    • Adding handle: recv: 0
    • Curl_addHandleToPipeline: length: 1
      • Conn 0 (0x1527360) send_pipe: 1, recv_pipe: 0
    • Connection timed out after 1001 milliseconds
    • Closing connection 0
      curl_easy_perform() failed: Timeout was reached

    But if you try to connect to any host within your network which will refuse the connection really fast or send any reply back it will just work:

    ./debugit

    • About to connect() to IP port 80 (#0)
    • Trying IP...
    • Adding handle: conn: 0x1cea360
    • Adding handle: send: 0
    • Adding handle: recv: 0
    • Curl_addHandleToPipeline: length: 1
      • Conn 0 (0x1cea360) send_pipe: 1, recv_pipe: 0
    • Connection timed out after 2 milliseconds
    • Closing connection 0
      curl_easy_perform() failed: Timeout was reached

    curl -V

    curl 7.30.0 (x86_64-unknown-linux-gnu) libcurl/7.30.0 OpenSSL/1.0.0 zlib/1.2.3 c-ares/1.9.1 libidn/1.18 libssh2/1.4.3
    Protocols: dict file ftp ftps gopher http https imap imaps ldap ldaps pop3 pop3s rtsp scp sftp smtp smtps telnet tftp
    Features: AsynchDNS GSS-Negotiate IDN IPv6 Largefile NTLM NTLM_WB SSL libz

    time ./debugit

    • About to connect() to 8.9.8.9 port 80 (#0)
    • Trying 8.9.8.9...
    • Adding handle: conn: 0x106aef0
    • Adding handle: send: 0
    • Adding handle: recv: 0
    • Curl_addHandleToPipeline: length: 1
      • Conn 0 (0x106aef0) send_pipe: 1, recv_pipe: 0
    • Connection timed out after 1001 milliseconds
    • Closing connection 0
      curl_easy_perform() failed: Timeout was reached

    real 0m1.026s
    user 0m0.010s
    sys 0m0.015s

    and for 7.28.1 (which works):

    curl -V

    curl 7.28.1 (x86_64-unknown-linux-gnu) libcurl/7.28.1 OpenSSL/1.0.0 zlib/1.2.3 c-ares/1.9.1 libidn/1.18 libssh2/1.4.3
    Protocols: dict file ftp ftps gopher http https imap imaps ldap ldaps pop3 pop3s rtsp scp sftp smtp smtps telnet tftp
    Features: AsynchDNS GSS-Negotiate IDN IPv6 Largefile NTLM NTLM_WB SSL libz

    time ./debugit

    • About to connect() to 8.9.8.9 port 80 (#0)
    • Trying 8.9.8.9...
    • Timeout
    • couldn't connect to host at 8.9.8.9:80
    • Closing connection #0
    • Couldn't connect to server
      curl_easy_perform() failed: Couldn't connect to server

    real 0m0.024s
    user 0m0.006s
    sys 0m0.016s

    The interesting part is that there is no "* Connection timed out after XX milliseconds" message generated but the timeout mechanism works as it should.

    Thanks.

     

  • stkasm92

    stkasm92 - 2013-05-22

    and the other thing I just noticed.. in 7.28.1 error message is different for this particular case.

    it just says: Couldn't connect to server and not "Timeout was reached". But as you can see from strace I provided it respects CONNECTIONTIMEOUT_MS value: poll([{fd=3, events=POLLOUT|POLLWRNORM}], 1, 39) = 0 (Timeout). In my initial example timeout was set to '40' ms

     

  • Daniel Stenberg

    Daniel Stenberg - 2013-05-24
    • status: pending-invalid --> open-confirmed
     

  • Daniel Stenberg

    Daniel Stenberg - 2013-05-24

    yeps, with an unreachable IP it seems to happen for me as well. Should give me something to debug...

     

  • Daniel Stenberg

    Daniel Stenberg - 2013-06-17
    • status: open-confirmed --> closed-fixed
     
MongoDB Logo MongoDB