TestEyeballs::test_06_13_timers - AssertionError on ppc64el

[charles2910]

I did this

Hi, 8.21.0 is currently failing the timers happy eyeballs test on ppc64el (for both ssl backends, openssl and gnutls). I tried to take a look but couldn't come up with an answer so it's time to ask the experts. I have access to a ppc64el porterbox where I can reproduce the problem and can provide further information and testing to assist finding/fixing the problem. The failure logs are below.

FAILED tests/http/test_06_eyeballs.py::TestEyeballs::test_06_13_timers - AssertionError: found: 17:40:27.656742 [0-0] * [TIMER] [HAPPY_EYEBALLS] set for 123000ns
  17:40:27.781388 [0-0] * [TIMER] [HAPPY_EYEBALLS] set for 123000ns
  17:40:27.783053 [0-0] * [TIMER] [HAPPY_EYEBALLS] set for 121000ns

  >>--stdout ----------------------------------------------
  {"certs":"","conn_id":0,"content_type":null,"errormsg":"Connection timed out after 1003 milliseconds","exitcode":28,"filename_effective":"download_#1.data","ftp_entry_path":null,"http_code
":0,"http_connect":0,"http_version":"0","local_ip":"","local_port":-1,"method":"GET","num_certs":0,"num_connects":0,"num_headers":0,"num_redirects":0,"num_retries":0,"proxy_ssl_verify_result
":0,"proxy_used":0,"redirect_url":null,"referer":null,"remote_ip":"","remote_port":-1,"response_code":0,"scheme":"https","size_delivered":0,"size_download":0,"size_header":0,"size_request":0
,"size_upload":0,"speed_download":0,"speed_upload":0,"ssl_verify_result":0,"time_appconnect":0.000000,"time_connect":0.000000,"time_namelookup":0.000122,"time_posttransfer":1.003389,"time_pr
etransfer":1.003388,"time_queue":0.000065,"time_redirect":0.000000,"time_starttransfer":1.003389,"time_total":1.003393,"tls_earlydata":0,"url":"https://xxx.invalid/","url.fragment":null,"url
.host":"xxx.invalid","url.options":null,"url.password":null,"url.path":"/","url.port":"443","url.query":null,"url.scheme":"https","url.user":null,"url.zoneid":null,"url_effective":"https://x
xx.invalid/","urle.fragment":null,"urle.host":"xxx.invalid","urle.options":null,"urle.password":null,"urle.path":"/","urle.port":"443","urle.query":null,"urle.scheme":"https","urle.user":nul
l,"urle.zoneid":null,"urlnum":0,"xfer_id":0,"curl_version":"libcurl/8.21.0 OpenSSL/3.6.3 zlib/1.3.2 brotli/1.2.0 zstd/1.5.7 libidn2/2.3.8 libpsl/0.23.0 libssh2/1.11.1 nghttp2/1.69.0 ngtcp2/1
.24.0 nghttp3/1.17.0 mit-krb5/1.22.1 OpenLDAP/2.6.13"}
  >>--stderr ----------------------------------------------
  17:40:27.655969 [0-x] * Added xxx.invalid:443:0100::1,0100::2,0100::3 to DNS cache
  17:40:27.656047 [0-x] * [TIMER] [CONNECTTIMEOUT] set for 999999ns
  17:40:27.656123 [0-0] * Hostname xxx.invalid was found in DNS cache
  17:40:27.656168 [0-0] * Host xxx.invalid:443 was resolved.
  17:40:27.656212 [0-0] * IPv6: 100::1, 100::2, 100::3
  17:40:27.656254 [0-0] * IPv4: (none)
  17:40:27.656299 [0-0] * [HAPPY-EYEBALLS] init ip ballers for transport 3
  17:40:27.656342 [0-0] * [HAPPY-EYEBALLS] want to do more
  17:40:27.656384 [0-0] * [HAPPY-EYEBALLS] check for next AAAA address: found
  17:40:27.656427 [0-0] * [HAPPY-EYEBALLS] starting first attempt for ipv6 -> 0
  17:40:27.656476 [0-0] *   Trying [100::1]:443...
  17:40:27.656525 [0-0] * [TCP] cf_socket_open() -> 0, fd=4
  17:40:27.656613 [0-0] * [TCP] local address 2605:bc80:3010:b00:0:deb:166:201 port 49940...
  17:40:27.656657 [0-0] * [HAPPY-EYEBALLS] checked connect attempts: 1 ongoing, 0 inconclusive
  17:40:27.656700 [0-0] * [HAPPY-EYEBALLS] next HAPPY_EYEBALLS timeout in 123ms
  17:40:27.656742 [0-0] * [TIMER] [HAPPY_EYEBALLS] set for 123000ns
  17:40:27.656789 [0-0] * [TCP] adjust_pollset, !connected, POLLOUT fd=4
  17:40:27.656831 [0-0] * [HAPPY-EYEBALLS] adjust_pollset -> 0, 1 socks
  17:40:27.656874 [0-0] * [TIMER] [HAPPY_EYEBALLS] gives multi timeout in 123ms
  17:40:27.780577 [0-0] * [TCP] not connected yet on fd=4
  17:40:27.780643 [0-0] * [HAPPY-EYEBALLS] checked connect attempts: 1 ongoing, 0 inconclusive
  17:40:27.780705 [0-0] * [HAPPY-EYEBALLS] happy eyeballs timeout expired, start next attempt
  17:40:27.780765 [0-0] * [HAPPY-EYEBALLS] want to do more
  17:40:27.780826 [0-0] * [HAPPY-EYEBALLS] check for next AAAA address: found
  17:40:27.780890 [0-0] * [HAPPY-EYEBALLS] starting next attempt for ipv6 -> 0
  17:40:27.780952 [0-0] * [TCP] not connected yet on fd=4
  17:40:27.781023 [0-0] *   Trying [100::2]:443...
  17:40:27.781093 [0-0] * [TCP] cf_socket_open() -> 0, fd=5
  17:40:27.781201 [0-0] * [TCP] local address 2605:bc80:3010:b00:0:deb:166:201 port 60154...
  17:40:27.781264 [0-0] * [HAPPY-EYEBALLS] checked connect attempts: 2 ongoing, 0 inconclusive
  17:40:27.781327 [0-0] * [HAPPY-EYEBALLS] next HAPPY_EYEBALLS timeout in 123ms
  17:40:27.781388 [0-0] * [TIMER] [HAPPY_EYEBALLS] set for 123000ns
  17:40:27.781455 [0-0] * [TCP] adjust_pollset, !connected, POLLOUT fd=4
  17:40:27.781517 [0-0] * [TCP] adjust_pollset, !connected, POLLOUT fd=5
  17:40:27.781578 [0-0] * [HAPPY-EYEBALLS] adjust_pollset -> 0, 2 socks
  17:40:27.781640 [0-0] * [TIMER] [HAPPY_EYEBALLS] gives multi timeout in 123ms
  17:40:27.782594 [0-0] * [TCP] not connected yet on fd=4
  17:40:27.782660 [0-0] * [TCP] poll/select error on fd=5
  17:40:27.782807 [0-0] * connect to 100::2 port 443 from 2605:bc80:3010:b00:0:deb:166:201 port 60154 failed: Network is unreachable
  17:40:27.782869 [0-0] * [TCP] destroy
  17:40:27.782930 [0-0] * [HAPPY-EYEBALLS] checked connect attempts: 1 ongoing, 0 inconclusive
  17:40:27.782992 [0-0] * [HAPPY-EYEBALLS] next HAPPY_EYEBALLS timeout in 121ms
  17:40:27.783053 [0-0] * [TIMER] [HAPPY_EYEBALLS] set for 121000ns
  17:40:27.783119 [0-0] * [TCP] adjust_pollset, !connected, POLLOUT fd=4
  17:40:27.783181 [0-0] * [HAPPY-EYEBALLS] adjust_pollset -> 0, 1 socks
  17:40:27.783243 [0-0] * [TIMER] [HAPPY_EYEBALLS] gives multi timeout in 121ms
  17:40:27.904958 [0-0] * [TCP] not connected yet on fd=4
  17:40:27.905023 [0-0] * [HAPPY-EYEBALLS] checked connect attempts: 1 ongoing, 0 inconclusive
  17:40:27.905085 [0-0] * [HAPPY-EYEBALLS] happy eyeballs timeout expired, start next attempt
  17:40:27.905146 [0-0] * [HAPPY-EYEBALLS] want to do more
  17:40:27.905208 [0-0] * [HAPPY-EYEBALLS] check for next AAAA address: found
  17:40:27.905272 [0-0] * [HAPPY-EYEBALLS] starting next attempt for ipv6 -> 0
  17:40:27.905335 [0-0] * [TCP] not connected yet on fd=4
  17:40:27.905405 [0-0] *   Trying [100::3]:443...
  17:40:27.905473 [0-0] * [TCP] cf_socket_open() -> 0, fd=5
  17:40:27.905575 [0-0] * [TCP] local address 2605:bc80:3010:b00:0:deb:166:201 port 49144...
  17:40:27.905638 [0-0] * [HAPPY-EYEBALLS] checked connect attempts: 2 ongoing, 0 inconclusive
  17:40:27.905706 [0-0] * [TCP] adjust_pollset, !connected, POLLOUT fd=4
  17:40:27.905773 [0-0] * [TCP] adjust_pollset, !connected, POLLOUT fd=5
  17:40:27.905836 [0-0] * [HAPPY-EYEBALLS] adjust_pollset -> 0, 2 socks
  17:40:27.905899 [0-0] * [TIMER] [CONNECTTIMEOUT] gives multi timeout in 752ms
  17:40:27.907430 [0-0] * [TCP] not connected yet on fd=4
  17:40:27.907498 [0-0] * [TCP] poll/select error on fd=5
  17:40:27.907582 [0-0] * connect to 100::3 port 443 from 2605:bc80:3010:b00:0:deb:166:201 port 49144 failed: Network is unreachable
  17:40:27.907644 [0-0] * [TCP] destroy
  17:40:27.907706 [0-0] * [HAPPY-EYEBALLS] checked connect attempts: 1 ongoing, 0 inconclusive
  17:40:27.907773 [0-0] * [TCP] adjust_pollset, !connected, POLLOUT fd=4
  17:40:27.907835 [0-0] * [HAPPY-EYEBALLS] adjust_pollset -> 0, 1 socks
  17:40:27.907897 [0-0] * [TIMER] [CONNECTTIMEOUT] gives multi timeout in 750ms
  17:40:28.659230 [0-0] * Connection timed out after 1003 milliseconds
  17:40:28.659308 [0-0] * closing connection #0
  <<-------------------------------------------------------

assert 3 == 2
 +  where 3 = len(['17:40:27.656742 [0-0] * [TIMER] [HAPPY_EYEBALLS] set for 123000ns\n', '17:40:27.781388 [0-0] * [TIMER] [HAPPY_EYEBALLS] set for 123000ns\n', '17:40:27.783053 [0-0] * [TIMER] [HAPPY_EYEBALLS] set for 121000ns\n'])

And:

_______________________________________________________________________________ TestEyeballs.test_06_13_timers ______________________________________________________________________________$

self = <test_06_eyeballs.TestEyeballs object at 0x3fff95754950>, env = <testenv.env.Env object at 0x3fff957987d0>

    @pytest.mark.skipif(condition=not Env.curl_has_feature('IPv6'),
                        reason='curl lacks ipv6 support')
    @pytest.mark.skipif(condition=not Env.curl_has_feature('AsynchDNS'),
                        reason='curl lacks async DNS support')
    @pytest.mark.skipif(condition=not Env.curl_is_verbose(), reason="needs curl verbose strings")
    def test_06_13_timers(self, env: Env):
        curl = CurlClient(env=env)
        # ipv6 0100::/64 is supposed to go into the void (rfc6666)
        r = curl.http_download(urls=['https://xxx.invalid/'], extra_args=[
            '--resolve', 'xxx.invalid:443:0100::1,0100::2,0100::3',
            '--connect-timeout', '1',
            '--happy-eyeballs-timeout-ms', '123',
            '--trace-config', 'timer,happy-eyeballs,tcp'
        ])
        r.check_response(count=1, http_status=None, exitcode=False)
        assert r.stats[0]['time_connect'] == 0     # no one connected
        # check that we indeed started attempts on all 3 addresses
        tcp_attempts = [line for line in r.trace_lines
                         if re.match(r'.*Trying \[100::[123]]:443', line)]
        assert len(tcp_attempts) == 3, f'fond: {"".join(tcp_attempts)}\n{r.dump_logs()}'
        # if the 0100::/64 really goes into the void, we should see 2 HAPPY_EYEBALLS
        # timeouts being set here
        failed_attempts = [line for line in r.trace_lines
                           if re.match(r'.*checked connect attempts: 0 ongoing', line)]
        if len(failed_attempts):
            # github CI fails right away with "Network is unreachable", slackers...
            assert len(failed_attempts) == 3, f'found: {"".join(failed_attempts)}\n{r.dump_logs()}'
        else:
            # no immediately failed attempts, as should be
            he_timers_set = [line for line in r.trace_lines
                             if re.match(r'.*\[TIMER] \[HAPPY_EYEBALLS] set for', line)]
>           assert len(he_timers_set) == 2, f'found: {"".join(he_timers_set)}\n{r.dump_logs()}'
E           AssertionError: found: 17:40:27.656742 [0-0] * [TIMER] [HAPPY_EYEBALLS] set for 123000ns
E             17:40:27.781388 [0-0] * [TIMER] [HAPPY_EYEBALLS] set for 123000ns
E             17:40:27.783053 [0-0] * [TIMER] [HAPPY_EYEBALLS] set for 121000ns
E
E             >>--stdout ----------------------------------------------
E             {"certs":"","conn_id":0,"content_type":null,"errormsg":"Connection timed out after 1003 milliseconds","exitcode":28,"filename_effective":"download_#1.data","17:40:28 [128/1960]
l,"http_code":0,"http_connect":0,"http_version":"0","local_ip":"","local_port":-1,"method":"GET","num_certs":0,"num_connects":0,"num_headers":0,"num_redirects":0,"num_retries":0,"proxy_ssl_v
erify_result":0,"proxy_used":0,"redirect_url":null,"referer":null,"remote_ip":"","remote_port":-1,"response_code":0,"scheme":"https","size_delivered":0,"size_download":0,"size_header":0,"siz
e_request":0,"size_upload":0,"speed_download":0,"speed_upload":0,"ssl_verify_result":0,"time_appconnect":0.000000,"time_connect":0.000000,"time_namelookup":0.000122,"time_posttransfer":1.003
389,"time_pretransfer":1.003388,"time_queue":0.000065,"time_redirect":0.000000,"time_starttransfer":1.003389,"time_total":1.003393,"tls_earlydata":0,"url":"https://xxx.invalid/","url.fragmen
t":null,"url.host":"xxx.invalid","url.options":null,"url.password":null,"url.path":"/","url.port":"443","url.query":null,"url.scheme":"https","url.user":null,"url.zoneid":null,"url_effective
":"https://xxx.invalid/","urle.fragment":null,"urle.host":"xxx.invalid","urle.options":null,"urle.password":null,"urle.path":"/","urle.port":"443","urle.query":null,"urle.scheme":"https","ur
le.user":null,"urle.zoneid":null,"urlnum":0,"xfer_id":0,"curl_version":"libcurl/8.21.0 OpenSSL/3.6.3 zlib/1.3.2 brotli/1.2.0 zstd/1.5.7 libidn2/2.3.8 libpsl/0.23.0 libssh2/1.11.1 nghttp2/1.6
9.0 ngtcp2/1.24.0 nghttp3/1.17.0 mit-krb5/1.22.1 OpenLDAP/2.6.13"}
E             >>--stderr ----------------------------------------------
E             17:40:27.655969 [0-x] * Added xxx.invalid:443:0100::1,0100::2,0100::3 to DNS cache
E             17:40:27.656047 [0-x] * [TIMER] [CONNECTTIMEOUT] set for 999999ns
E             17:40:27.656123 [0-0] * Hostname xxx.invalid was found in DNS cache
E             17:40:27.656168 [0-0] * Host xxx.invalid:443 was resolved.
E             17:40:27.656212 [0-0] * IPv6: 100::1, 100::2, 100::3
E             17:40:27.656254 [0-0] * IPv4: (none)
E             17:40:27.656299 [0-0] * [HAPPY-EYEBALLS] init ip ballers for transport 3
E             17:40:27.656342 [0-0] * [HAPPY-EYEBALLS] want to do more
E             17:40:27.656384 [0-0] * [HAPPY-EYEBALLS] check for next AAAA address: found
E             17:40:27.656427 [0-0] * [HAPPY-EYEBALLS] starting first attempt for ipv6 -> 0
E             17:40:27.656476 [0-0] *   Trying [100::1]:443...
E             17:40:27.656525 [0-0] * [TCP] cf_socket_open() -> 0, fd=4
E             17:40:27.656613 [0-0] * [TCP] local address 2605:bc80:3010:b00:0:deb:166:201 port 49940...
E             17:40:27.656657 [0-0] * [HAPPY-EYEBALLS] checked connect attempts: 1 ongoing, 0 inconclusive
E             17:40:27.656700 [0-0] * [HAPPY-EYEBALLS] next HAPPY_EYEBALLS timeout in 123ms
E             17:40:27.656742 [0-0] * [TIMER] [HAPPY_EYEBALLS] set for 123000ns
E             17:40:27.656789 [0-0] * [TCP] adjust_pollset, !connected, POLLOUT fd=4
E             17:40:27.656831 [0-0] * [HAPPY-EYEBALLS] adjust_pollset -> 0, 1 socks
E             17:40:27.656874 [0-0] * [TIMER] [HAPPY_EYEBALLS] gives multi timeout in 123ms
E             17:40:27.780577 [0-0] * [TCP] not connected yet on fd=4
E             17:40:27.780643 [0-0] * [HAPPY-EYEBALLS] checked connect attempts: 1 ongoing, 0 inconclusive
E             17:40:27.780705 [0-0] * [HAPPY-EYEBALLS] happy eyeballs timeout expired, start next attempt
E             17:40:27.780765 [0-0] * [HAPPY-EYEBALLS] want to do more
E             17:40:27.780826 [0-0] * [HAPPY-EYEBALLS] check for next AAAA address: found
E             17:40:27.780890 [0-0] * [HAPPY-EYEBALLS] starting next attempt for ipv6 -> 0
E             17:40:27.780952 [0-0] * [TCP] not connected yet on fd=4
E             17:40:27.781023 [0-0] *   Trying [100::2]:443...
E             17:40:27.781093 [0-0] * [TCP] cf_socket_open() -> 0, fd=5
E             17:40:27.781201 [0-0] * [TCP] local address 2605:bc80:3010:b00:0:deb:166:201 port 60154...
E             17:40:27.781264 [0-0] * [HAPPY-EYEBALLS] checked connect attempts: 2 ongoing, 0 inconclusive
E             17:40:27.781327 [0-0] * [HAPPY-EYEBALLS] next HAPPY_EYEBALLS timeout in 123ms
E             17:40:27.781388 [0-0] * [TIMER] [HAPPY_EYEBALLS] set for 123000ns
E             17:40:27.781455 [0-0] * [TCP] adjust_pollset, !connected, POLLOUT fd=4
E             17:40:27.781517 [0-0] * [TCP] adjust_pollset, !connected, POLLOUT fd=5
E             17:40:27.781578 [0-0] * [HAPPY-EYEBALLS] adjust_pollset -> 0, 2 socks
E             17:40:27.781640 [0-0] * [TIMER] [HAPPY_EYEBALLS] gives multi timeout in 123ms
E             17:40:27.782594 [0-0] * [TCP] not connected yet on fd=4
E             17:40:27.782660 [0-0] * [TCP] poll/select error on fd=5
E             17:40:27.782807 [0-0] * connect to 100::2 port 443 from 2605:bc80:3010:b00:0:deb:166:201 port 60154 failed: Network is unreachable
E             17:40:27.782869 [0-0] * [TCP] destroy
E             17:40:27.782930 [0-0] * [HAPPY-EYEBALLS] checked connect attempts: 1 ongoing, 0 inconclusive
E             17:40:27.782992 [0-0] * [HAPPY-EYEBALLS] next HAPPY_EYEBALLS timeout in 121ms
E             17:40:27.783053 [0-0] * [TIMER] [HAPPY_EYEBALLS] set for 121000ns
E             17:40:27.783119 [0-0] * [TCP] adjust_pollset, !connected, POLLOUT fd=4
E             17:40:27.783181 [0-0] * [HAPPY-EYEBALLS] adjust_pollset -> 0, 1 socks
E             17:40:27.783243 [0-0] * [TIMER] [HAPPY_EYEBALLS] gives multi timeout in 121ms
E             17:40:27.904958 [0-0] * [TCP] not connected yet on fd=4
E             17:40:27.905023 [0-0] * [HAPPY-EYEBALLS] checked connect attempts: 1 ongoing, 0 inconclusive
E             17:40:27.905085 [0-0] * [HAPPY-EYEBALLS] happy eyeballs timeout expired, start next attempt
E             17:40:27.905146 [0-0] * [HAPPY-EYEBALLS] want to do more
E             17:40:27.905208 [0-0] * [HAPPY-EYEBALLS] check for next AAAA address: found
E             17:40:27.905272 [0-0] * [HAPPY-EYEBALLS] starting next attempt for ipv6 -> 0
E             17:40:27.905335 [0-0] * [TCP] not connected yet on fd=4
E             17:40:27.905405 [0-0] *   Trying [100::3]:443...
E             17:40:27.905473 [0-0] * [TCP] cf_socket_open() -> 0, fd=5
E             17:40:27.905575 [0-0] * [TCP] local address 2605:bc80:3010:b00:0:deb:166:201 port 49144...
E             17:40:27.905638 [0-0] * [HAPPY-EYEBALLS] checked connect attempts: 2 ongoing, 0 inconclusive
E             17:40:27.905706 [0-0] * [TCP] adjust_pollset, !connected, POLLOUT fd=4
E             17:40:27.905773 [0-0] * [TCP] adjust_pollset, !connected, POLLOUT fd=5
E             17:40:27.905836 [0-0] * [HAPPY-EYEBALLS] adjust_pollset -> 0, 2 socks
E             17:40:27.905899 [0-0] * [TIMER] [CONNECTTIMEOUT] gives multi timeout in 752ms
E             17:40:27.907430 [0-0] * [TCP] not connected yet on fd=4
E             17:40:27.907498 [0-0] * [TCP] poll/select error on fd=5
E             17:40:27.907582 [0-0] * connect to 100::3 port 443 from 2605:bc80:3010:b00:0:deb:166:201 port 49144 failed: Network is unreachable
E             17:40:27.907644 [0-0] * [TCP] destroy
E             17:40:27.907706 [0-0] * [HAPPY-EYEBALLS] checked connect attempts: 1 ongoing, 0 inconclusive
E             17:40:27.907773 [0-0] * [TCP] adjust_pollset, !connected, POLLOUT fd=4
E             17:40:27.907835 [0-0] * [HAPPY-EYEBALLS] adjust_pollset -> 0, 1 socks
E             17:40:27.907897 [0-0] * [TIMER] [CONNECTTIMEOUT] gives multi timeout in 750ms
E             17:40:28.659230 [0-0] * Connection timed out after 1003 milliseconds
E             17:40:28.659308 [0-0] * closing connection #0
E             <<-------------------------------------------------------
E
E           assert 3 == 2
E            +  where 3 = len(['17:40:27.656742 [0-0] * [TIMER] [HAPPY_EYEBALLS] set for 123000ns\n', '17:40:27.781388 [0-0] * [TIMER] [HAPPY_EYEBALLS] set for 123000ns\n', '17:40:27.783053
[0-0] * [TIMER] [HAPPY_EYEBALLS] set for 121000ns\n'])

I expected the following

No response

curl/libcurl version

curl 8.21.0 (powerpc64le-unknown-linux-gnu) libcurl/8.21.0 OpenSSL/3.6.3 zlib/1.3.2 brotli/1.2.0 zstd/1.5.7 libidn2/2.3.8 libpsl/0.23.0 libssh2/1.11.1 nghttp2/1.69.0 ngtcp2/1.24.0 nghttp3/1.17.0 mit-krb5/1.22.1 OpenLDAP/2.6.13

operating system

Debian unstable (sid)

[icing]

@charles2910 thanks for the report. The test uses ipv6 addresses that are supposed to be blackholed (https://www.rfc-editor.org/info/rfc6666/), e.g. being dropped into the void. That should give no reply to curl and allow the timers to trigger.

As the logs show, the system you run this on immediately returns "network unreachable", so the IP connect attempt fails and the timers never come into effect.

Ideally, we would detect such a system and skip the tests. I am not sure how to do that reliably, though.

[icing]

@charles2910 could you verify if #22355 solves the problem for you? Thanks!

[charles2910]

@icing thanks for looking at it. I tested it now and I believe it does not:

_______________________________________________________________________________ TestEyeballs.test_06_13_timers ______________________________________________________________________________$

self = <test_06_eyeballs.TestEyeballs object at 0x3fff9ff82450>, env = <testenv.env.Env object at 0x3fff9ff26350>

    @pytest.mark.skipif(condition=not Env.curl_has_feature('IPv6'),
                        reason='curl lacks ipv6 support')
    @pytest.mark.skipif(condition=not Env.curl_has_feature('AsynchDNS'),
                        reason='curl lacks async DNS support')
    @pytest.mark.skipif(condition=not Env.curl_is_verbose(), reason="needs curl verbose strings")
    def test_06_13_timers(self, env: Env):
        curl = CurlClient(env=env)
        # IPv6 0100::/64 is supposed to go into the void (rfc6666), but in
        # some implementations, this is broken. Try to detect this
        r = curl.http_download(urls=['https://xxx.invalid/'], extra_args=[
            '--resolve', 'xxx.invalid:443:0100::1',
            '--connect-timeout', '0.5',
        ])
        # this should error with CURLE_OPERATION_TIMEDOUT
        if r.exit_code != 28:
            pytest.skip(f'system does not blackhole 0100::/64')

        r = curl.http_download(urls=['https://xxx.invalid/'], extra_args=[
            '--resolve', 'xxx.invalid:443:0100::1,0100::2,0100::3',
            '--connect-timeout', '1',
            '--happy-eyeballs-timeout-ms', '123',
            '--trace-config', 'timer,happy-eyeballs,tcp'
        ])
        r.check_response(count=1, http_status=None, exitcode=False)
        assert r.stats[0]['time_connect'] == 0     # no one connected
        # check that we indeed started attempts on all 3 addresses
        tcp_attempts = [line for line in r.trace_lines
                         if re.match(r'.*Trying \[100::[123]]:443', line)]
        assert len(tcp_attempts) == 3, f'fond: {"".join(tcp_attempts)}\n{r.dump_logs()}'
        # if the 0100::/64 really goes into the void, we should see 2 HAPPY_EYEBALLS
        # timeouts being set here
        failed_attempts = [line for line in r.trace_lines
                           if re.match(r'.*checked connect attempts: 0 ongoing', line)]
        if len(failed_attempts):
            # github CI fails right away with "Network is unreachable", slackers...
            assert len(failed_attempts) == 3, f'found: {"".join(failed_attempts)}\n{r.dump_logs()}'
        else:
            # no immediately failed attempts, as should be
            he_timers_set = [line for line in r.trace_lines
                             if re.match(r'.*\[TIMER] \[HAPPY_EYEBALLS] set for', line)]
>           assert len(he_timers_set) == 2, f'found: {"".join(he_timers_set)}\n{r.dump_logs()}'
E           AssertionError: found: 01:18:36.199353 [0-0] * [TIMER] [HAPPY_EYEBALLS] set for 123000ns
E             01:18:36.324178 [0-0] * [TIMER] [HAPPY_EYEBALLS] set for 123000ns
E             01:18:36.327222 [0-0] * [TIMER] [HAPPY_EYEBALLS] set for 120000ns
E
E             >>--stdout ----------------------------------------------
E             {"certs":"","conn_id":0,"content_type":null,"errormsg":"Connection timed out after 1003 milliseconds","exitcode":28,"filename_effective":"download_#1.data","f01:18:37 [47/1884]
l,"http_code":0,"http_connect":0,"http_version":"0","local_ip":"","local_port":-1,"method":"GET","num_certs":0,"num_connects":0,"num_headers":0,"num_redirects":0,"num_retries":0,"proxy_ssl_v
erify_result":0,"proxy_used":0,"redirect_url":null,"referer":null,"remote_ip":"","remote_port":-1,"response_code":0,"scheme":"https","size_delivered":0,"size_download":0,"size_header":0,"siz
e_request":0,"size_upload":0,"speed_download":0,"speed_upload":0,"ssl_verify_result":0,"time_appconnect":0.000000,"time_connect":0.000000,"time_namelookup":0.000144,"time_posttransfer":1.003
354,"time_pretransfer":1.003354,"time_queue":0.000081,"time_redirect":0.000000,"time_starttransfer":1.003354,"time_total":1.003358,"tls_earlydata":0,"url":"https://xxx.invalid/","url.fragmen
t":null,"url.host":"xxx.invalid","url.options":null,"url.password":null,"url.path":"/","url.port":"443","url.query":null,"url.scheme":"https","url.user":null,"url.zoneid":null,"url_effective
":"https://xxx.invalid/","urle.fragment":null,"urle.host":"xxx.invalid","urle.options":null,"urle.password":null,"urle.path":"/","urle.port":"443","urle.query":null,"urle.scheme":"https","ur
le.user":null,"urle.zoneid":null,"urlnum":0,"xfer_id":0,"curl_version":"libcurl/8.21.0 GnuTLS/3.8.13 zlib/1.3.2 brotli/1.2.0 zstd/1.5.7 libidn2/2.3.8 libpsl/0.23.0 libssh2/1.11.1 nghttp2/1.6
9.0 ngtcp2/1.24.0 nghttp3/1.17.0 mit-krb5/1.22.1 OpenLDAP/2.6.13"}
E             >>--stderr ----------------------------------------------
E             01:18:36.198419 [0-x] * Added xxx.invalid:443:0100::1,0100::2,0100::3 to DNS cache
E             01:18:36.198521 [0-x] * [TIMER] [CONNECTTIMEOUT] set for 1000000ns
E             01:18:36.198614 [0-0] * Hostname xxx.invalid was found in DNS cache
E             01:18:36.198663 [0-0] * Host xxx.invalid:443 was resolved.
E             01:18:36.198735 [0-0] * IPv6: 100::1, 100::2, 100::3
E             01:18:36.198782 [0-0] * IPv4: (none)
E             01:18:36.198833 [0-0] * [HAPPY-EYEBALLS] init ip ballers for transport 3
E             01:18:36.198883 [0-0] * [HAPPY-EYEBALLS] want to do more
E             01:18:36.198951 [0-0] * [HAPPY-EYEBALLS] check for next AAAA address: found
E             01:18:36.199001 [0-0] * [HAPPY-EYEBALLS] starting first attempt for ipv6 -> 0
E             01:18:36.199056 [0-0] *   Trying [100::1]:443...
E             01:18:36.199111 [0-0] * [TCP] cf_socket_open() -> 0, fd=4
E             01:18:36.199210 [0-0] * [TCP] local address 2605:bc80:3010:b00:0:deb:166:201 port 36142...
E             01:18:36.199258 [0-0] * [HAPPY-EYEBALLS] checked connect attempts: 1 ongoing, 0 inconclusive
E             01:18:36.199306 [0-0] * [HAPPY-EYEBALLS] next HAPPY_EYEBALLS timeout in 123ms
E             01:18:36.199353 [0-0] * [TIMER] [HAPPY_EYEBALLS] set for 123000ns
E             01:18:36.199415 [0-0] * [TCP] adjust_pollset, !connected, POLLOUT fd=4
E             01:18:36.199463 [0-0] * [HAPPY-EYEBALLS] adjust_pollset -> 0, 1 socks
E             01:18:36.199511 [0-0] * [TIMER] [HAPPY_EYEBALLS] gives multi timeout in 123ms
E             01:18:36.323216 [0-0] * [TCP] not connected yet on fd=4
E             01:18:36.323301 [0-0] * [HAPPY-EYEBALLS] checked connect attempts: 1 ongoing, 0 inconclusive
E             01:18:36.323386 [0-0] * [HAPPY-EYEBALLS] happy eyeballs timeout expired, start next attempt
E             01:18:36.323459 [0-0] * [HAPPY-EYEBALLS] want to do more
E             01:18:36.323531 [0-0] * [HAPPY-EYEBALLS] check for next AAAA address: found
E             01:18:36.323606 [0-0] * [HAPPY-EYEBALLS] starting next attempt for ipv6 -> 0
E             01:18:36.323680 [0-0] * [TCP] not connected yet on fd=4
E             01:18:36.323762 [0-0] *   Trying [100::2]:443...
E             01:18:36.323842 [0-0] * [TCP] cf_socket_open() -> 0, fd=5
E             01:18:36.323955 [0-0] * [TCP] local address 2605:bc80:3010:b00:0:deb:166:201 port 51234...
E             01:18:36.324030 [0-0] * [HAPPY-EYEBALLS] checked connect attempts: 2 ongoing, 0 inconclusive
E             01:18:36.324105 [0-0] * [HAPPY-EYEBALLS] next HAPPY_EYEBALLS timeout in 123ms
E             01:18:36.324178 [0-0] * [TIMER] [HAPPY_EYEBALLS] set for 123000ns
E             01:18:36.324256 [0-0] * [TCP] adjust_pollset, !connected, POLLOUT fd=4
E             01:18:36.324329 [0-0] * [TCP] adjust_pollset, !connected, POLLOUT fd=5
E             01:18:36.324402 [0-0] * [HAPPY-EYEBALLS] adjust_pollset -> 0, 2 socks
E             01:18:36.324476 [0-0] * [TIMER] [HAPPY_EYEBALLS] gives multi timeout in 123ms
E             01:18:36.326735 [0-0] * [TCP] not connected yet on fd=4
E             01:18:36.326819 [0-0] * [TCP] poll/select error on fd=5
E             01:18:36.326928 [0-0] * connect to 100::2 port 443 from 2605:bc80:3010:b00:0:deb:166:201 port 51234 failed: Network is unreachable
E             01:18:36.327001 [0-0] * [TCP] destroy
E             01:18:36.327074 [0-0] * [HAPPY-EYEBALLS] checked connect attempts: 1 ongoing, 0 inconclusive
E             01:18:36.327148 [0-0] * [HAPPY-EYEBALLS] next HAPPY_EYEBALLS timeout in 120ms
E             01:18:36.327222 [0-0] * [TIMER] [HAPPY_EYEBALLS] set for 120000ns
E             01:18:36.327299 [0-0] * [TCP] adjust_pollset, !connected, POLLOUT fd=4
E             01:18:36.327386 [0-0] * [HAPPY-EYEBALLS] adjust_pollset -> 0, 1 socks
E             01:18:36.327461 [0-0] * [TIMER] [HAPPY_EYEBALLS] gives multi timeout in 120ms
E             01:18:36.448215 [0-0] * [TCP] not connected yet on fd=4
E             01:18:36.448315 [0-0] * [HAPPY-EYEBALLS] checked connect attempts: 1 ongoing, 0 inconclusive
E             01:18:36.448390 [0-0] * [HAPPY-EYEBALLS] happy eyeballs timeout expired, start next attempt
E             01:18:36.448462 [0-0] * [HAPPY-EYEBALLS] want to do more
E             01:18:36.448535 [0-0] * [HAPPY-EYEBALLS] check for next AAAA address: found
E             01:18:36.448612 [0-0] * [HAPPY-EYEBALLS] starting next attempt for ipv6 -> 0
E             01:18:36.448687 [0-0] * [TCP] not connected yet on fd=4
E             01:18:36.448777 [0-0] *   Trying [100::3]:443...
E             01:18:36.448861 [0-0] * [TCP] cf_socket_open() -> 0, fd=5
E             01:18:36.449003 [0-0] * [TCP] local address 2605:bc80:3010:b00:0:deb:166:201 port 53330...
E             01:18:36.449077 [0-0] * [HAPPY-EYEBALLS] checked connect attempts: 2 ongoing, 0 inconclusive
E             01:18:36.449160 [0-0] * [TCP] adjust_pollset, !connected, POLLOUT fd=4
E             01:18:36.449250 [0-0] * [TCP] adjust_pollset, !connected, POLLOUT fd=5
E             01:18:36.449324 [0-0] * [HAPPY-EYEBALLS] adjust_pollset -> 0, 2 socks
E             01:18:36.449399 [0-0] * [TIMER] [CONNECTTIMEOUT] gives multi timeout in 751ms
E             01:18:36.451452 [0-0] * [TCP] not connected yet on fd=4
E             01:18:36.451550 [0-0] * [TCP] poll/select error on fd=5
E             01:18:36.451675 [0-0] * connect to 100::3 port 443 from 2605:bc80:3010:b00:0:deb:166:201 port 53330 failed: Network is unreachable
E             01:18:36.451767 [0-0] * [TCP] destroy
E             01:18:36.451880 [0-0] * [HAPPY-EYEBALLS] checked connect attempts: 1 ongoing, 0 inconclusive
E             01:18:36.451990 [0-0] * [TCP] adjust_pollset, !connected, POLLOUT fd=4
E             01:18:36.452064 [0-0] * [HAPPY-EYEBALLS] adjust_pollset -> 0, 1 socks
E             01:18:36.452139 [0-0] * [TIMER] [CONNECTTIMEOUT] gives multi timeout in 748ms
E             01:18:37.201608 [0-0] * Connection timed out after 1003 milliseconds
E             01:18:37.201727 [0-0] * closing connection #0
E             <<-------------------------------------------------------
E
E           assert 3 == 2
E            +  where 3 = len(['01:18:36.199353 [0-0] * [TIMER] [HAPPY_EYEBALLS] set for 123000ns\n', '01:18:36.324178 [0-0] * [TIMER] [HAPPY_EYEBALLS] set for 123000ns\n', '01:18:36.327222
[0-0] * [TIMER] [HAPPY_EYEBALLS] set for 120000ns\n'])

tests/http/test_06_eyeballs.py:145: AssertionError
------------------------------------------------------------------------------------- Captured log setup -------------------------------------------------------------------------------------
DEBUG    filelock:_api.py:572 Attempting to acquire lock 70367143689392 on /tmp/autopkgtest.5OcImM/build.0bS/real-tree/debian/build-gnutls/tests/http/gen/ca/ca.lock
DEBUG    filelock:_api.py:575 Lock 70367143689392 acquired on /tmp/autopkgtest.5OcImM/build.0bS/real-tree/debian/build-gnutls/tests/http/gen/ca/ca.lock
DEBUG    filelock:_api.py:604 Attempting to release lock 70367143689392 on /tmp/autopkgtest.5OcImM/build.0bS/real-tree/debian/build-gnutls/tests/http/gen/ca/ca.lock
DEBUG    filelock:_api.py:608 Lock 70367143689392 released on /tmp/autopkgtest.5OcImM/build.0bS/real-tree/debian/build-gnutls/tests/http/gen/ca/ca.lock
DEBUG    filelock:_api.py:572 Attempting to acquire lock 70367131796496 on /tmp/autopkgtest.5OcImM/build.0bS/real-tree/debian/build-gnutls/tests/http/gen/ports.lock
DEBUG    filelock:_api.py:575 Lock 70367131796496 acquired on /tmp/autopkgtest.5OcImM/build.0bS/real-tree/debian/build-gnutls/tests/http/gen/ports.lock
DEBUG    filelock:_api.py:604 Attempting to release lock 70367131796496 on /tmp/autopkgtest.5OcImM/build.0bS/real-tree/debian/build-gnutls/tests/http/gen/ports.lock
DEBUG    filelock:_api.py:608 Lock 70367131796496 released on /tmp/autopkgtest.5OcImM/build.0bS/real-tree/debian/build-gnutls/tests/http/gen/ports.lock
================================================================================== short test summary info ===================================================================================
FAILED tests/http/test_06_eyeballs.py::TestEyeballs::test_06_13_timers - AssertionError: found: 01:18:36.199353 [0-0] * [TIMER] [HAPPY_EYEBALLS] set for 123000ns
===================================================================================== 1 failed in 4.16s ======================================================================================

Maybe an option is I just skip that test though in ppc64el

[icing]

Weird system. Blackholes 2 of the 3 addresses and fails right away on 0100::2...

I changed the assert in test_06_13 to also accept more than 2 timer sets.

[charles2910]

I changed the assert in test_06_13 to also accept more than 2 timer sets.

Yeah, now I can confirm it's passing.

The test uses ipv6 addresses that are supposed to be blackholed (https://www.rfc-editor.org/info/rfc6666/), e.g. being dropped into the void. That should give no reply to curl and allow the timers to trigger.

Weird system. Blackholes 2 of the 3 addresses and fails right away on 0100::2...

I'll forward this to the ppc64el porters mailing list, maybe they can find and fix the problem

Thanks @icing!