test(refactor): make debug output testing more robust

This change introduces a match_log function, that implements lenient matching of log output lines. Tests of log output are retrofited to use the function.

test/io/test_io.py

@@ -21,6 +21,19 @@ from postgrest import (
 )
 
 
+def match_log(output, matchers):
+    ito = iter(output)
+    itm = iter(matchers)
+    nextMatcher = next(itm, None)
+    while nextMatcher is not None and (line := next(ito, None)) is not None:
+        if re.match(nextMatcher, line) is not None:
+            nextMatcher = next(itm, None)
+    if nextMatcher is not None:
+        raise AssertionError(
+            f"Expected log line matching {nextMatcher} not found in output"
+        )
+
+
 def test_connect_with_dburi(dburi, defaultenv):
     "Connecting with db-uri instead of LIPQ* environment variables should work."
     defaultenv_without_libpq = {
@@ -679,54 +692,44 @@ def test_log_level(level, defaultenv):
         response = postgrest.session.get("/")
         assert response.status_code == 200
 
-        output = sorted(postgrest.read_stdout(nlines=7))
+        output = postgrest.read_stdout(nlines=7)
 
         if level == "crit":
             assert len(output) == 0
         elif level == "error":
-            assert re.match(
+            match_log(
-                r'- - - \[.+\] "GET / HTTP/1.1" 500 \d+ "" "python-requests/.+"',
+                output,
-                output[0],
+                [r'- - - \[.+\] "GET / HTTP/1.1" 500 \d+ "" "python-requests/.+"'],
             )
             assert len(output) == 1
         elif level == "warn":
-            assert re.match(
+            match_log(
-                r'- - - \[.+\] "GET / HTTP/1.1" 500 \d+ "" "python-requests/.+"',
+                output,
-                output[0],
+                [
-            )
+                    r'- - - \[.+\] "GET / HTTP/1.1" 500 \d+ "" "python-requests/.+"',
-            assert re.match(
+                    r'- - postgrest_test_anonymous \[.+\] "GET /unknown HTTP/1.1" 404 \d+ "" "python-requests/.+"',
-                r'- - postgrest_test_anonymous \[.+\] "GET /unknown HTTP/1.1" 404 \d+ "" "python-requests/.+"',
+                ],
-                output[1],
             )
             assert len(output) == 2
         elif level == "info":
-            assert re.match(
+            match_log(
-                r'- - - \[.+\] "GET / HTTP/1.1" 500 \d+ "" "python-requests/.+"',
+                output,
-                output[0],
+                [
-            )
+                    r'- - - \[.+\] "GET / HTTP/1.1" 500 \d+ "" "python-requests/.+"',
-            assert re.match(
+                    r'- - postgrest_test_anonymous \[.+\] "GET /unknown HTTP/1.1" 404 \d+ "" "python-requests/.+"',
-                r'- - postgrest_test_anonymous \[.+\] "GET / HTTP/1.1" 200 \d+ "" "python-requests/.+"',
+                    r'- - postgrest_test_anonymous \[.+\] "GET / HTTP/1.1" 200 \d+ "" "python-requests/.+"',
-                output[1],
+                ],
-            )
-            assert re.match(
-                r'- - postgrest_test_anonymous \[.+\] "GET /unknown HTTP/1.1" 404 \d+ "" "python-requests/.+"',
-                output[2],
             )
             assert len(output) == 3
         elif level == "debug":
-            assert re.match(
+            match_log(
-                r'- - - \[.+\] "GET / HTTP/1.1" 500 \d+ "" "python-requests/.+"',
+                output,
-                output[0],
+                [
+                    r'- - - \[.+\] "GET / HTTP/1.1" 500 \d+ "" "python-requests/.+"',
+                    r'- - postgrest_test_anonymous \[.+\] "GET /unknown HTTP/1.1" 404 \d+ "" "python-requests/.+"',
+                    r'- - postgrest_test_anonymous \[.+\] "GET / HTTP/1.1" 200 \d+ "" "python-requests/.+"',
+                ],
             )
-            assert re.match(
-                r'- - postgrest_test_anonymous \[.+\] "GET / HTTP/1.1" 200 \d+ "" "python-requests/.+"',
-                output[1],
-            )
-            assert re.match(
-                r'- - postgrest_test_anonymous \[.+\] "GET /unknown HTTP/1.1" 404 \d+ "" "python-requests/.+"',
-                output[2],
-            )
-
             assert len(output) == 7
             assert any("Connection" and "is available" in line for line in output)
             assert any("Connection" and "is used" in line for line in output)
@@ -1364,16 +1367,21 @@ def test_db_error_logging_to_stderr(level, defaultenv, metapostgrest):
         assert response.status_code == 500
 
         # ensure the message appears on the logs
-        output = sorted(postgrest.read_stdout(nlines=6))
+        output = postgrest.read_stdout(nlines=6)
 
         if level == "crit":
             assert len(output) == 0
         elif level == "debug":
-            assert " 500 " in output[0]
+            match_log(
-            assert "canceling statement due to statement timeout" in output[5]
+                output,
+                [
+                    r".*canceling statement due to statement timeout.*",
+                    r".*500.*",
+                ],
+            )
         else:
-            assert " 500 " in output[0]
+            assert " 500 " in output[1]
-            assert "canceling statement due to statement timeout" in output[1]
+            assert "canceling statement due to statement timeout" in output[0]
 
     reset_statement_timeout(metapostgrest, role)
 
@@ -1567,18 +1575,17 @@ def test_log_pool_req_observation(level, defaultenv):
 
     headers = jwtauthheader({"role": "postgrest_test_author"}, SECRET)
 
-    pool_req = "Trying to borrow a connection from pool"
+    pool_req = r".*Trying to borrow a connection from pool.*"
-    pool_req_fullfill = "Borrowed a connection from the pool"
+    pool_req_fullfill = r".*Borrowed a connection from the pool.*"
 
     with run(env=env) as postgrest:
 
         postgrest.session.get("/authors_only", headers=headers)
 
         if level == "debug":
-            output = postgrest.read_stdout(nlines=5)
+            output = postgrest.read_stdout(nlines=7)
-            assert pool_req in output[1]
+            assert len(output) == 6
-            assert pool_req_fullfill in output[4]
+            match_log(output, [pool_req, pool_req_fullfill])
-            assert len(output) == 5
         elif level == "info":
             output = postgrest.read_stdout(nlines=4)
             assert len(output) == 1