Source: curl Version: 8.21.0-2 Severity: serious X-Debbugs-Cc: [email protected] User: [email protected] Usertags: ppc64el
https://ci.debian.net/packages/c/curl/testing/ppc64el/ shows that the latest version of curl consistently fails its autopkgtests on ppc64el, when the version currently in testing passed. The test log seems to pretty consistently look like this: =================================== FAILURES =================================== ________________________ TestEyeballs.test_06_13_timers ________________________ self = <test_06_eyeballs.TestEyeballs object at 0x3fffad08c350> env = <testenv.env.Env object at 0x3fffad246d50> @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: 11:35:58.211780 [0-0] * [TIMER] [HAPPY_EYEBALLS] set for 123000ns E 11:35:58.336539 [0-0] * [TIMER] [HAPPY_EYEBALLS] set for 122999ns E 11:35:58.337195 [0-0] * [TIMER] [HAPPY_EYEBALLS] set for 123000ns E E >>--stdout ---------------------------------------------- E {"certs":"","conn_id":0,"content_type":null,"errormsg":"Connection timed out after 1001 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.000069,"time_posttransfer":1.001221,"time_pretransfer":1.001220,"time_queue":0.000042,"time_redirect":0.000000,"time_starttransfer":1.001221,"time_total":1.001224,"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://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","urle.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.22.0 libssh2/1.11.1 nghttp2/1.69.0 ngtcp2/1.22.1 nghttp3/1.15.0 mit-krb5/1.22.1 OpenLDAP/2.6.10"} E >>--stderr ---------------------------------------------- E 11:35:58.211166 [0-x] * Added xxx.invalid:443:0100::1,0100::2,0100::3 to DNS cache E 11:35:58.211227 [0-x] * [TIMER] [CONNECTTIMEOUT] set for 1000000ns E 11:35:58.211277 [0-0] * Hostname xxx.invalid was found in DNS cache E 11:35:58.211295 [0-0] * Host xxx.invalid:443 was resolved. E 11:35:58.211317 [0-0] * IPv6: 100::1, 100::2, 100::3 E 11:35:58.211334 [0-0] * IPv4: (none) E 11:35:58.211354 [0-0] * [HAPPY-EYEBALLS] init ip ballers for transport 3 E 11:35:58.211372 [0-0] * [HAPPY-EYEBALLS] want to do more E 11:35:58.211390 [0-0] * [HAPPY-EYEBALLS] check for next AAAA address: found E 11:35:58.211409 [0-0] * [HAPPY-EYEBALLS] starting first attempt for ipv6 -> 0 E 11:35:58.211433 [0-0] * Trying [100::1]:443... E 11:35:58.211458 [0-0] * [TCP] cf_socket_open() -> 0, fd=4 E 11:35:58.211725 [0-0] * [TCP] local address fc42:5009:ba4b:5ab0:b7b2:9e1a:c428:9a6c port 37694... E 11:35:58.211744 [0-0] * [HAPPY-EYEBALLS] checked connect attempts: 1 ongoing, 0 inconclusive E 11:35:58.211762 [0-0] * [HAPPY-EYEBALLS] next HAPPY_EYEBALLS timeout in 123ms E 11:35:58.211780 [0-0] * [TIMER] [HAPPY_EYEBALLS] set for 123000ns E 11:35:58.211802 [0-0] * [TCP] adjust_pollset, !connected, POLLOUT fd=4 E 11:35:58.211819 [0-0] * [HAPPY-EYEBALLS] adjust_pollset -> 0, 1 socks E 11:35:58.211837 [0-0] * [TIMER] [HAPPY_EYEBALLS] gives multi timeout in 124ms E 11:35:58.336065 [0-0] * [TCP] not connected yet on fd=4 E 11:35:58.336105 [0-0] * [HAPPY-EYEBALLS] checked connect attempts: 1 ongoing, 0 inconclusive E 11:35:58.336125 [0-0] * [HAPPY-EYEBALLS] happy eyeballs timeout expired, start next attempt E 11:35:58.336142 [0-0] * [HAPPY-EYEBALLS] want to do more E 11:35:58.336159 [0-0] * [HAPPY-EYEBALLS] check for next AAAA address: found E 11:35:58.336183 [0-0] * [HAPPY-EYEBALLS] starting next attempt for ipv6 -> 0 E 11:35:58.336201 [0-0] * [TCP] not connected yet on fd=4 E 11:35:58.336255 [0-0] * Trying [100::2]:443... E 11:35:58.336282 [0-0] * [TCP] cf_socket_open() -> 0, fd=5 E 11:35:58.336483 [0-0] * [TCP] local address fc42:5009:ba4b:5ab0:b7b2:9e1a:c428:9a6c port 43470... E 11:35:58.336502 [0-0] * [HAPPY-EYEBALLS] checked connect attempts: 2 ongoing, 0 inconclusive E 11:35:58.336521 [0-0] * [HAPPY-EYEBALLS] next HAPPY_EYEBALLS timeout in 123ms E 11:35:58.336539 [0-0] * [TIMER] [HAPPY_EYEBALLS] set for 122999ns E 11:35:58.336564 [0-0] * [TCP] adjust_pollset, !connected, POLLOUT fd=4 E 11:35:58.336582 [0-0] * [TCP] adjust_pollset, !connected, POLLOUT fd=5 E 11:35:58.336599 [0-0] * [HAPPY-EYEBALLS] adjust_pollset -> 0, 2 socks E 11:35:58.336617 [0-0] * [TIMER] [HAPPY_EYEBALLS] gives multi timeout in 123ms E 11:35:58.337023 [0-0] * [TCP] not connected yet on fd=4 E 11:35:58.337044 [0-0] * [TCP] poll/select error on fd=5 E 11:35:58.337124 [0-0] * connect to 100::2 port 443 from fc42:5009:ba4b:5ab0:b7b2:9e1a:c428:9a6c port 43470 failed: Network is unreachable E 11:35:58.337142 [0-0] * [TCP] destroy E 11:35:58.337160 [0-0] * [HAPPY-EYEBALLS] checked connect attempts: 1 ongoing, 0 inconclusive E 11:35:58.337178 [0-0] * [HAPPY-EYEBALLS] next HAPPY_EYEBALLS timeout in 123ms E 11:35:58.337195 [0-0] * [TIMER] [HAPPY_EYEBALLS] set for 123000ns E 11:35:58.337214 [0-0] * [TCP] adjust_pollset, !connected, POLLOUT fd=4 E 11:35:58.337232 [0-0] * [HAPPY-EYEBALLS] adjust_pollset -> 0, 1 socks E 11:35:58.337250 [0-0] * [TIMER] [HAPPY_EYEBALLS] gives multi timeout in 123ms E 11:35:58.460468 [0-0] * [TCP] not connected yet on fd=4 E 11:35:58.460510 [0-0] * [HAPPY-EYEBALLS] checked connect attempts: 1 ongoing, 0 inconclusive E 11:35:58.460529 [0-0] * [HAPPY-EYEBALLS] happy eyeballs timeout expired, start next attempt E 11:35:58.460546 [0-0] * [HAPPY-EYEBALLS] want to do more E 11:35:58.460564 [0-0] * [HAPPY-EYEBALLS] check for next AAAA address: found E 11:35:58.460586 [0-0] * [HAPPY-EYEBALLS] starting next attempt for ipv6 -> 0 E 11:35:58.460605 [0-0] * [TCP] not connected yet on fd=4 E 11:35:58.460651 [0-0] * Trying [100::3]:443... E 11:35:58.460679 [0-0] * [TCP] cf_socket_open() -> 0, fd=5 E 11:35:58.460911 [0-0] * [TCP] local address fc42:5009:ba4b:5ab0:b7b2:9e1a:c428:9a6c port 48088... E 11:35:58.460930 [0-0] * [HAPPY-EYEBALLS] checked connect attempts: 2 ongoing, 0 inconclusive E 11:35:58.460977 [0-0] * [TCP] adjust_pollset, !connected, POLLOUT fd=4 E 11:35:58.460995 [0-0] * [TCP] adjust_pollset, !connected, POLLOUT fd=5 E 11:35:58.461013 [0-0] * [HAPPY-EYEBALLS] adjust_pollset -> 0, 2 socks E 11:35:58.461033 [0-0] * [TIMER] [CONNECTTIMEOUT] gives multi timeout in 751ms E 11:35:58.461271 [0-0] * [TCP] not connected yet on fd=4 E 11:35:58.461290 [0-0] * [TCP] poll/select error on fd=5 E 11:35:58.461343 [0-0] * connect to 100::3 port 443 from fc42:5009:ba4b:5ab0:b7b2:9e1a:c428:9a6c port 48088 failed: Network is unreachable E 11:35:58.461361 [0-0] * [TCP] destroy E 11:35:58.461378 [0-0] * [HAPPY-EYEBALLS] checked connect attempts: 1 ongoing, 0 inconclusive E 11:35:58.461398 [0-0] * [TCP] adjust_pollset, !connected, POLLOUT fd=4 E 11:35:58.461416 [0-0] * [HAPPY-EYEBALLS] adjust_pollset -> 0, 1 socks E 11:35:58.461434 [0-0] * [TIMER] [CONNECTTIMEOUT] gives multi timeout in 750ms E 11:35:59.212283 [0-0] * Connection timed out after 1001 milliseconds E 11:35:59.212354 [0-0] * closing connection #0 E <<------------------------------------------------------- E E assert 3 == 2 E + where 3 = len(['11:35:58.211780 [0-0] * [TIMER] [HAPPY_EYEBALLS] set for 123000ns\n', '11:35:58.336539 [0-0] * [TIMER] [HAPPY_EYEBALLS] set for 122999ns\n', '11:35:58.337195 [0-0] * [TIMER] [HAPPY_EYEBALLS] set for 123000ns\n']) tests/http/test_06_eyeballs.py:136: AssertionError Thanks, -- Colin Watson (he/him) [[email protected]]
