server: fix grep_log not finding string logged immediately before

.github/workflows/package_test.yml

@@ -19,7 +19,7 @@ jobs:
           - dist: fedora
             version: 36
 
-    runs-on: ubuntu-20.04
+    runs-on: ubuntu-latest
 
     steps:
       - name: Check out repo

.github/workflows/test_on_push.yaml

@@ -11,9 +11,9 @@ jobs:
       github.event_name == 'pull_request' && github.event.pull_request.head.repo.owner.login != 'tarantool'
     strategy:
       matrix:
-        tarantool: ["1.10", "2.6", "2.7", "2.8", "2.10", "2.11", "3.0"]
+        tarantool: ["2.11", "3.0", "3.1", "3.2", "3.3", "3.4"]
       fail-fast: false
-    runs-on: [ubuntu-20.04]
+    runs-on: [ubuntu-latest]
     steps:
       - uses: actions/checkout@master
       - uses: tarantool/setup-tarantool@v3

CHANGELOG.md

@@ -1,5 +1,10 @@
 # Changelog
 
+## Unreleased
+
+- Fixed a bug when `server:grep_log()` failed to find a string logged in
+  `server:exec()` called immediately before it (gh-421).
+
 ## 1.1.0
 
 - Added logging to unified file (gh-324).

luatest/server.lua

@@ -896,8 +896,19 @@ function Server:grep_log(pattern, bytes_num, opts)
         fail('Failed to open log file')
     end
 
-    io.flush() -- attempt to flush stdout == log fd
+    -- Logs written by a test server go through a pipe and are processed
+    -- by a luatest fiber before they make it to the log file. Let's write
+    -- a unique marker string to the server log via server:exec() and retry
+    -- until we find the marker.
+    local marker
+    if self ~= nil and self.net_box ~= nil and self.net_box:ping() then
+        marker = ('LUATEST_GREP_LOG_MARKER:%d'):format(math.random(1e9))
+        self:exec(function(s) require('log').info(s) end, {marker})
+    end
+
+    local retries = 0
 
+    ::retry::
     local filesize = file:seek(0, 'SEEK_END')
     if filesize == nil then
         fail('Failed to get log file size')
@@ -938,11 +949,21 @@ function Server:grep_log(pattern, bytes_num, opts)
                 else
                     found = string.match(line, pattern) or found
                 end
+                if marker ~= nil and string.match(line, marker) then
+                    marker = nil
+                end
             end
             pos = endpos and endpos + 2 -- jump to char after \n
         until pos == nil
     until s == ''
 
+    if found == nil and marker ~= nil and retries < 10 then
+        log.info('Retrying grep because marker was not found')
+        retries = retries + 1
+        fiber.sleep(0.1)
+        goto retry
+    end
+
     file:close()
 
     return found

test/luaunit/assertions_error_test.lua

@@ -235,13 +235,13 @@ function g.test_assert_errorCovers()
     t.assert_error_covers({type = 'ClientError', code = 0}, box.error, 0)
     local err = box.error.new(box.error.UNKNOWN)
     if err.set_prev ~= nil then
-        err:set_prev(box.error.new(box.error.ILLEGAL_PARAMS, 'foo'))
+        err:set_prev(box.error.new(box.error.UNSUPPORTED, 'foo', 'bar'))
         expected = {
             type = 'ClientError',
             code = box.error.UNKNOWN,
-            prev = {code = box.error.ILLEGAL_PARAMS}
+            prev = {type = 'ClientError', code = box.error.UNSUPPORTED}
         }
-        t.assert_error_covers(expected, err.raise, err)
+        t.assert_error_covers(expected, box.error, err)
     end
 
     -- test assert failure due to unexpected error trace