Tests: wait_for_record() introduced.

6 files changed, 59 insertions, 85 deletions

diff --git a/test/test_access_log.py b/test/test_access_log.py
index 1c8c29d7..b5bfff7a 100644
--- a/test/test_access_log.py
+++ b/test/test_access_log.py
@@ -13,9 +13,8 @@ class TestAccessLog(TestApplicationPython):
 
         self.conf('"' + self.testdir + '/access.log"', 'access_log')
 
-    def search_in_log(self, pattern, name='access.log'):
-        with open(self.testdir + '/' + name, 'r') as f:
-            return re.search(pattern, f.read())
+    def wait_for_record(self, pattern, name='access.log'):
+        return super().wait_for_record(pattern, name)
 
     def test_access_log_keepalive(self):
         self.load('mirror')
@@ -30,10 +29,8 @@ class TestAccessLog(TestApplicationPython):
             body='01234',
         )
 
-        time.sleep(0.2)
-
         self.assertIsNotNone(
-            self.search_in_log(r'"POST / HTTP/1.1" 200 5'), 'keepalive 1'
+            self.wait_for_record(r'"POST / HTTP/1.1" 200 5'), 'keepalive 1'
         )
 
         resp = self.post(
@@ -46,12 +43,10 @@ class TestAccessLog(TestApplicationPython):
             body='0123456789',
         )
 
-        time.sleep(0.2)
-
         self.stop()
 
         self.assertIsNotNone(
-            self.search_in_log(r'"POST / HTTP/1.1" 200 10'), 'keepalive 2'
+            self.wait_for_record(r'"POST / HTTP/1.1" 200 10'), 'keepalive 2'
         )
 
     def test_access_log_pipeline(self):
@@ -76,20 +71,18 @@ Connection: close
             raw=True,
         )
 
-        time.sleep(0.2)
-
         self.stop()
 
         self.assertIsNotNone(
-            self.search_in_log(r'"GET / HTTP/1.1" 200 0 "Referer-1" "-"'),
+            self.wait_for_record(r'"GET / HTTP/1.1" 200 0 "Referer-1" "-"'),
             'pipeline 1',
         )
         self.assertIsNotNone(
-            self.search_in_log(r'"GET / HTTP/1.1" 200 0 "Referer-2" "-"'),
+            self.wait_for_record(r'"GET / HTTP/1.1" 200 0 "Referer-2" "-"'),
             'pipeline 2',
         )
         self.assertIsNotNone(
-            self.search_in_log(r'"GET / HTTP/1.1" 200 0 "Referer-3" "-"'),
+            self.wait_for_record(r'"GET / HTTP/1.1" 200 0 "Referer-3" "-"'),
             'pipeline 3',
         )
 
@@ -100,12 +93,10 @@ Connection: close
 
         self.get(sock_type='ipv6')
 
-        time.sleep(0.2)
-
         self.stop()
 
         self.assertIsNotNone(
-            self.search_in_log(
+            self.wait_for_record(
                 r'::1 - - \[.+\] "GET / HTTP/1.1" 200 0 "-" "-"'
             ),
             'ipv6',
@@ -120,12 +111,10 @@ Connection: close
 
         self.get(sock_type='unix', addr=addr)
 
-        time.sleep(0.2)
-
         self.stop()
 
         self.assertIsNotNone(
-            self.search_in_log(
+            self.wait_for_record(
                 r'unix: - - \[.+\] "GET / HTTP/1.1" 200 0 "-" "-"'
             ),
             'unix',
@@ -142,12 +131,12 @@ Connection: close
             }
         )
 
-        time.sleep(0.2)
-
         self.stop()
 
         self.assertIsNotNone(
-            self.search_in_log(r'"GET / HTTP/1.1" 200 0 "referer-value" "-"'),
+            self.wait_for_record(
+                r'"GET / HTTP/1.1" 200 0 "referer-value" "-"'
+            ),
             'referer',
         )
 
@@ -162,12 +151,10 @@ Connection: close
             }
         )
 
-        time.sleep(0.2)
-
         self.stop()
 
         self.assertIsNotNone(
-            self.search_in_log(
+            self.wait_for_record(
                 r'"GET / HTTP/1.1" 200 0 "-" "user-agent-value"'
             ),
             'user agent',
@@ -178,12 +165,10 @@ Connection: close
 
         self.get(http_10=True)
 
-        time.sleep(0.2)
-
         self.stop()
 
         self.assertIsNotNone(
-            self.search_in_log(r'"GET / HTTP/1.0" 200 0 "-" "-"'), 'http 1.0'
+            self.wait_for_record(r'"GET / HTTP/1.0" 200 0 "-" "-"'), 'http 1.0'
         )
 
     def test_access_log_partial(self):
@@ -191,12 +176,10 @@ Connection: close
 
         self.http(b"""GE""", raw=True)
 
-        time.sleep(0.2)
-
         self.stop()
 
         self.assertIsNotNone(
-            self.search_in_log(r'"GE" 400 0 "-" "-"'), 'partial'
+            self.wait_for_record(r'"GE" 400 0 "-" "-"'), 'partial'
         )
 
     def test_access_log_partial_2(self):
@@ -204,12 +187,10 @@ Connection: close
 
         self.http(b"""GET /\n""", raw=True)
 
-        time.sleep(0.2)
-
         self.stop()
 
         self.assertIsNotNone(
-            self.search_in_log(r'"GET /" 400 \d+ "-" "-"'), 'partial 2'
+            self.wait_for_record(r'"GET /" 400 \d+ "-" "-"'), 'partial 2'
         )
 
     def test_access_log_partial_3(self):
@@ -217,12 +198,10 @@ Connection: close
 
         self.http(b"""GET / HTTP/1.1""", raw=True)
 
-        time.sleep(0.2)
-
         self.stop()
 
         self.assertIsNotNone(
-            self.search_in_log(r'"GET /" 400 0 "-" "-"'), 'partial 3'
+            self.wait_for_record(r'"GET /" 400 0 "-" "-"'), 'partial 3'
         )
 
     def test_access_log_partial_4(self):
@@ -230,12 +209,11 @@ Connection: close
 
         resp = self.http(b"""GET / HTTP/1.1\n""", raw=True)
 
-        time.sleep(0.2)
-
         self.stop()
 
         self.assertIsNotNone(
-            self.search_in_log(r'"GET / HTTP/1.1" 400 0 "-" "-"'), 'partial 4'
+            self.wait_for_record(r'"GET / HTTP/1.1" 400 0 "-" "-"'),
+            'partial 4',
         )
 
     def test_access_log_partial_5(self):
@@ -246,7 +224,8 @@ Connection: close
         self.stop()
 
         self.assertIsNotNone(
-            self.search_in_log(r'"GET / HTTP/1.1" 200 0 "-" "-"'), 'partial 5'
+            self.wait_for_record(r'"GET / HTTP/1.1" 200 0 "-" "-"'),
+            'partial 5',
         )
 
     def test_access_log_get_parameters(self):
@@ -254,12 +233,10 @@ Connection: close
 
         self.get(url='/?blah&var=val')
 
-        time.sleep(0.2)
-
         self.stop()
 
         self.assertIsNotNone(
-            self.search_in_log(
+            self.wait_for_record(
                 r'"GET /\?blah&var=val HTTP/1.1" 200 0 "-" "-"'
             ),
             'get parameters',
@@ -272,11 +249,11 @@ Connection: close
 
         self.get(url='/delete')
 
-        time.sleep(0.2)
-
         self.stop()
 
-        self.assertIsNone(self.search_in_log(r'/delete'), 'delete')
+        self.assertIsNone(
+            self.search_in_log(r'/delete', 'access.log'), 'delete'
+        )
 
     def test_access_log_change(self):
         self.load('empty')
@@ -287,12 +264,10 @@ Connection: close
 
         self.get()
 
-        time.sleep(0.2)
-
         self.stop()
 
         self.assertIsNotNone(
-            self.search_in_log(r'"GET / HTTP/1.1" 200 0 "-" "-"', 'new.log'),
+            self.wait_for_record(r'"GET / HTTP/1.1" 200 0 "-" "-"', 'new.log'),
             'change',
         )
 
@@ -309,10 +284,8 @@ Connection: close
 
         self.get()
 
-        time.sleep(0.2)
-
         self.assertIsNotNone(
-            self.search_in_log(r'"GET / HTTP/1.1" 200 0 "-" "-"', 'new.log'),
+            self.wait_for_record(r'"GET / HTTP/1.1" 200 0 "-" "-"', 'new.log'),
             'rename new',
         )
         self.assertFalse(os.path.isfile(log_path), 'rename old')
@@ -326,15 +299,13 @@ Connection: close
 
         self.get(url='/usr1')
 
-        time.sleep(0.2)
-
-        self.assertIsNone(
-            self.search_in_log(r'/usr1', 'new.log'), 'rename new 2'
-        )
         self.assertIsNotNone(
-            self.search_in_log(r'"GET /usr1 HTTP/1.1" 200 0 "-" "-"'),
+            self.wait_for_record(r'"GET /usr1 HTTP/1.1" 200 0 "-" "-"'),
             'reopen 2',
         )
+        self.assertIsNone(
+            self.search_in_log(r'/usr1', 'new.log'), 'rename new 2'
+        )
 
 
 if __name__ == '__main__':
diff --git a/test/test_perl_application.py b/test/test_perl_application.py
index 00d4a3e5..df037155 100644
--- a/test/test_perl_application.py
+++ b/test/test_perl_application.py
@@ -137,7 +137,7 @@ class TestPerlApplication(TestApplicationPerl):
         self.stop()
 
         self.assertIsNotNone(
-            self.search_in_log(r'\[error\].+Error in application'),
+            self.wait_for_record(r'\[error\].+Error in application'),
             'errors print',
         )
 
@@ -226,12 +226,12 @@ class TestPerlApplication(TestApplicationPerl):
         self.assertEqual(self.get()['body'], '21', 'body io fake')
 
         self.assertIsNotNone(
-            self.search_in_log(r'\[error\].+IOFake getline\(\) \$\/ is \d+'),
+            self.wait_for_record(r'\[error\].+IOFake getline\(\) \$\/ is \d+'),
             'body io fake $/ value',
         )
 
         self.assertIsNotNone(
-            self.search_in_log(r'\[error\].+IOFake close\(\) called'),
+            self.wait_for_record(r'\[error\].+IOFake close\(\) called'),
             'body io fake close',
         )
 
diff --git a/test/test_python_application.py b/test/test_python_application.py
index 0b153d77..d66a6555 100644
--- a/test/test_python_application.py
+++ b/test/test_python_application.py
@@ -127,10 +127,8 @@ class TestPythonApplication(TestApplicationPython):
 
         self.stop()
 
-        time.sleep(0.2)
-
         self.assertIsNotNone(
-            self.search_in_log(r'RuntimeError'), 'ctx iter atexit'
+            self.wait_for_record(r'RuntimeError'), 'ctx iter atexit'
         )
 
     def test_python_keepalive_body(self):
@@ -310,7 +308,9 @@ Connection: close
 
         self.stop()
 
-        self.assertIsNotNone(self.search_in_log(r'At exit called\.'), 'atexit')
+        self.assertIsNotNone(
+            self.wait_for_record(r'At exit called\.'), 'atexit'
+        )
 
     @unittest.expectedFailure
     def test_python_application_start_response_exit(self):
@@ -384,7 +384,7 @@ Connection: close
         self.stop()
 
         self.assertIsNotNone(
-            self.search_in_log(r'\[error\].+Error in application\.'),
+            self.wait_for_record(r'\[error\].+Error in application\.'),
             'errors write',
         )
 
@@ -417,7 +417,7 @@ Connection: close
 
         self.stop()
 
-        self.assertIsNotNone(self.search_in_log(r'Close called\.'), 'close')
+        self.assertIsNotNone(self.wait_for_record(r'Close called\.'), 'close')
 
     def test_python_application_close_error(self):
         self.load('close_error')
@@ -427,7 +427,7 @@ Connection: close
         self.stop()
 
         self.assertIsNotNone(
-            self.search_in_log(r'Close called\.'), 'close error'
+            self.wait_for_record(r'Close called\.'), 'close error'
         )
 
     def test_python_application_not_iterable(self):
@@ -438,7 +438,7 @@ Connection: close
         self.stop()
 
         self.assertIsNotNone(
-            self.search_in_log(
+            self.wait_for_record(
                 r'\[error\].+the application returned not an iterable object'
             ),
             'not iterable',
diff --git a/test/test_ruby_application.py b/test/test_ruby_application.py
index e119127f..924fe1ee 100644
--- a/test/test_ruby_application.py
+++ b/test/test_ruby_application.py
@@ -197,7 +197,7 @@ class TestRubyApplication(TestApplicationRuby):
         self.stop()
 
         self.assertIsNotNone(
-            self.search_in_log(r'\[error\].+Error in application'),
+            self.wait_for_record(r'\[error\].+Error in application'),
             'errors puts',
         )
 
@@ -209,7 +209,7 @@ class TestRubyApplication(TestApplicationRuby):
         self.stop()
 
         self.assertIsNotNone(
-            self.search_in_log(r'\[error\].+1234567890'), 'errors puts int'
+            self.wait_for_record(r'\[error\].+1234567890'), 'errors puts int'
         )
 
     def test_ruby_application_errors_write(self):
@@ -220,7 +220,7 @@ class TestRubyApplication(TestApplicationRuby):
         self.stop()
 
         self.assertIsNotNone(
-            self.search_in_log(r'\[error\].+Error in application'),
+            self.wait_for_record(r'\[error\].+Error in application'),
             'errors write',
         )
 
@@ -237,7 +237,7 @@ class TestRubyApplication(TestApplicationRuby):
         self.stop()
 
         self.assertIsNotNone(
-            self.search_in_log(r'\[error\].+1234567890'), 'errors write int'
+            self.wait_for_record(r'\[error\].+1234567890'), 'errors write int'
         )
 
     def test_ruby_application_at_exit(self):
@@ -250,7 +250,7 @@ class TestRubyApplication(TestApplicationRuby):
         self.stop()
 
         self.assertIsNotNone(
-            self.search_in_log(r'\[error\].+At exit called\.'), 'at exit'
+            self.wait_for_record(r'\[error\].+At exit called\.'), 'at exit'
         )
 
     def test_ruby_application_header_custom(self):
@@ -309,7 +309,7 @@ class TestRubyApplication(TestApplicationRuby):
         self.stop()
 
         self.assertIsNotNone(
-            self.search_in_log(r'\[error\].+Failed to run ruby script'),
+            self.wait_for_record(r'\[error\].+Failed to run ruby script'),
             'body each error',
         )
 
diff --git a/test/test_tls.py b/test/test_tls.py
index f9b0a978..dc570c34 100644
--- a/test/test_tls.py
+++ b/test/test_tls.py
@@ -13,14 +13,6 @@ class TestTLS(TestApplicationTLS):
         with open(self.testdir + '/unit.log', 'r', errors='ignore') as f:
             return re.findall(pattern, f.read())
 
-    def wait_for_record(self, pattern):
-        for i in range(50):
-            with open(self.testdir + '/unit.log', 'r', errors='ignore') as f:
-                if re.search(pattern, f.read()) is not None:
-                    break
-
-            time.sleep(0.1)
-
     def openssl_date_to_sec_epoch(self, date):
         return self.date_to_sec_epoch(date, '%b %d %H:%M:%S %Y %Z')
 
diff --git a/test/unit/applications/proto.py b/test/unit/applications/proto.py
index 16007757..2b865695 100644
--- a/test/unit/applications/proto.py
+++ b/test/unit/applications/proto.py
@@ -13,3 +13,14 @@ class TestApplicationProto(TestControl):
     def search_in_log(self, pattern, name='unit.log'):
         with open(self.testdir + '/' + name, 'r', errors='ignore') as f:
             return re.search(pattern, f.read())
+
+    def wait_for_record(self, pattern, name='unit.log'):
+        for i in range(50):
+            found = self.search_in_log(pattern, name)
+
+            if found is not None:
+                break
+
+            time.sleep(0.1)
+
+        return found