pytest: fix and improve reliability

Address issues listed in #19770:
- allow for ngttpx to successfully shut down on last attempt that might
  extend beyond the finish timestamp
- timeline checks: allos `time_starttransfer` to appear anywhere in
  the timeline as a slow client might seen response data before setting
  the other counters
- dump logs on test_05_02 as it was not reproduced locally

Fixes #19970
Closes #19783

tests/http/test_01_basic.py

@@ -308,13 +308,14 @@ class TestBasic:
         url = f'https://{env.authority_for(env.domain1, proto)}/curltest/echo'
         r = curl.http_download(urls=[url], alpn_proto=proto, with_stats=True,
                                extra_args=['-X', method])
-        assert len(r.stats) == 1
         if proto == 'h2' or proto == 'h3':
-            r.check_response(http_status=0)
+            # h2+3 may close the connection for such invalid requests
             re_m = re.compile(r'.*\[:method: ([^\]]+)\].*')
             lines = [line for line in r.trace_lines if re_m.match(line)]
             assert len(lines) == 1, f'{r.dump_logs()}'
             m = re_m.match(lines[0])
             assert m.group(1) == method, f'{r.dump_logs()}'
         else:
+            # h1 should give us a real response
+            assert len(r.stats) == 1
             r.check_response(http_status=400)

tests/http/test_05_errors.py

@@ -73,8 +73,8 @@ class TestErrors:
         invalid_stats = []
         for idx, s in enumerate(r.stats):
             if 'exitcode' not in s or s['exitcode'] not in [18, 55, 56, 92, 95]:
-                invalid_stats.append(f'request {idx} exit with {s["exitcode"]}\n{s}')
-        assert len(invalid_stats) == 0, f'failed: {invalid_stats}'
+                invalid_stats.append(f'request {idx} exit with {s["exitcode"]}\n{r.dump_logs()}')
+        assert len(invalid_stats) == 0, f'failed: {invalid_stats}\n{r.dump_logs()}'
 
     # access a resource that, on h2, RST the stream with HTTP_1_1_REQUIRED
     @pytest.mark.skipif(condition=not Env.have_h2_curl(), reason="curl without h2")

tests/http/testenv/curl.py

@@ -525,6 +525,7 @@ class ExecResult:
         }
         # stat keys where we expect a positive value
         ref_tl = []
+        somewhere_keys = []
         exact_match = True
         # redirects mess up the queue time, only count without
         if s['time_redirect'] == 0:
@@ -542,10 +543,13 @@ class ExecResult:
         # what kind of transfer was it?
         if s['size_upload'] == 0 and s['size_download'] > 0:
             # this is a download
-            dl_tl = ['time_pretransfer', 'time_starttransfer']
+            dl_tl = ['time_pretransfer']
             if s['size_request'] > 0:
                 dl_tl = ['time_posttransfer'] + dl_tl
             ref_tl += dl_tl
+            # the first byte of the response may arrive before we
+            # track the other times when the client is slow (CI).
+            somewhere_keys = ['time_starttransfer']
         elif s['size_upload'] > 0 and s['size_download'] == 0:
             # this is an upload
             ul_tl = ['time_pretransfer', 'time_posttransfer']
@@ -561,11 +565,14 @@ class ExecResult:
             self.check_stat_positive(s, idx, key)
         if exact_match:
             # assert all events not in reference timeline are 0
-            for key in [key for key in all_keys if key not in ref_tl]:
+            for key in [key for key in all_keys if key not in ref_tl and key not in somewhere_keys]:
                 self.check_stat_zero(s, key)
         # calculate the timeline that did happen
         seen_tl = sorted(ref_tl, key=lambda ts: s[ts])
         assert seen_tl == ref_tl, f'{[f"{ts}: {s[ts]}" for ts in seen_tl]}'
+        for key in somewhere_keys:
+            self.check_stat_positive(s, idx, key)
+            assert s[key] <= s['time_total']
 
     def dump_logs(self):
         lines = ['>>--stdout ----------------------------------------------\n']

tests/http/testenv/nghttpx.py

@@ -138,7 +138,7 @@ class Nghttpx:
                 except subprocess.TimeoutExpired:
                     log.warning(f'nghttpx({running.pid}), not shut down yet.')
                     os.kill(running.pid, signal.SIGQUIT)
-            if datetime.now() >= end_wait:
+            if running and datetime.now() >= end_wait:
                 log.error(f'nghttpx({running.pid}), terminate forcefully.')
                 os.kill(running.pid, signal.SIGKILL)
                 running.terminate()