Skip to content

Output logs on test failures

Sami Hiltunen requested to merge smh-record-log-output into master

Our tests are currently largely discarding all logs. This is done as we run our tests verbosely in the CI and the log output exceeded what the CI could at maximum display. Discarding the logs can make it more difficult to determine why the test exactly failed. This is especially true when concurrency is involved and a background worker not directly tied to the request fails. While the background worker would log the reason it failed, this is not visible in the tests.

Same goes for cases where the error metadata contains the stderr of a failing command but it's not output as part of the error. This would be visible in the logs but not necessarily in the assertion failure.

While most test logs are discarded, Gitaly and Praefect server logs are written into their own files. This requires one to know about this, and to go separately search for the log. On the CI, this requires download the artifacts to get the logs.

All in all, the logs in the test contain useful information when facing test failures but the logs are either discarded or difficult to access. This MR aims to solve this problem by printing the test cases logs if the test case fails. This avoids too many irrelevant logs which lead to CI discarding the logs but still giving easy access to the logs when they may be relevant.

Example output below with the test cases assertion modified to fail it:

--- FAIL: TestUserCreateBranch_failure (3.81s)
    --- FAIL: TestUserCreateBranch_failure/branch_exists (0.03s)
        user_create_branch_test.go:435: 
            	Error Trace:	/Users/sami/gitlab/gitlab-development-kit/gitaly/internal/testhelper/grpc.go:48
            	            				/Users/sami/gitlab/gitlab-development-kit/gitaly/internal/testhelper/grpc.go:76
            	            				/Users/sami/gitlab/gitlab-development-kit/gitaly/internal/gitaly/service/operations/user_create_branch_test.go:435
            	Error:      	Should be empty, but was   (*status.Status)(Inverse(protocmp.Transform, protocmp.Message{
            	            	  	"@type":   s"google.rpc.Status",
            	            	  	"code":    int32(9),
            	            	  	"details": []protocmp.Message{{"@type": s"google.protobuf.Any", "type_url": string("type.googleapis.com/testproto.ErrorMetadata"), "value": protocmp.Message{"@type": s"testproto.ErrorMetadata", "key": []uint8("stderr"), "value": []uint8("fatal: prepare: cannot lock ref 'refs/heads/master': reference a"...)}}},
            	            	  	"message": strings.Join({
            	            	  		"reference upda",
            	            	- 		"s",
            	            	  		`te: state update to "prepare" failed: EOF`,
            	            	  	}, ""),
            	            	  }))
            	Test:       	TestUserCreateBranch_failure/branch_exists
    logger.go:88: Recorded logs of "shared-logger":
        time="2023-08-22T17:07:39+03:00" level=warning msg="Git has not been properly configured, falling back to Git found on PATH" resolvedPath=/opt/homebrew/bin/git
        time="2023-08-22T17:07:39+03:00" level=warning msg="Git has not been properly configured, falling back to Git found on PATH" resolvedPath=/opt/homebrew/bin/git
        time="2023-08-22T17:07:39+03:00" level=warning msg="Git has not been properly configured, falling back to Git found on PATH" resolvedPath=/opt/homebrew/bin/git
        time="2023-08-22T17:07:39+03:00" level=warning msg="Git has not been properly configured, falling back to Git found on PATH" resolvedPath=/opt/homebrew/bin/git
        time="2023-08-22T17:07:39+03:00" level=warning msg="Git has not been properly configured, falling back to Git found on PATH" resolvedPath=/opt/homebrew/bin/git
        time="2023-08-22T17:07:39+03:00" level=warning msg="Git has not been properly configured, falling back to Git found on PATH" resolvedPath=/opt/homebrew/bin/git
        
    logger.go:88: Recorded logs of "gitaly":
        time="2023-08-22T17:07:39+03:00" level=info msg="All 0 tables opened in 0s\n" component=database storage=default
        time="2023-08-22T17:07:39+03:00" level=info msg="Discard stats nextEmptySlot: 0\n" component=database storage=default
        time="2023-08-22T17:07:39+03:00" level=info msg="Set nextTxnTs to 0" component=database storage=default
        time="2023-08-22T17:07:39+03:00" level=info msg="diskcache state change" component=gitaly.UnaryServerInterceptor correlation_id=01H8ES54AESQNBDQ4MY8WXR4X8 diskcache=7d468e16-64ea-42aa-ac98-0559c9fea27c grpc.meta.deadline_type=none grpc.meta.method_operation=mutator grpc.meta.method_scope=repository grpc.meta.method_type=unary grpc.method=CreateRepository grpc.request.fullMethod=/gitaly.RepositoryService/CreateRepository grpc.request.glProjectPath=gitlab-org/gitlab-test grpc.request.glRepository=project-1 grpc.request.repoPath=@hashed/be/ed/beede0274668dfc564c3b18cd889fa4369ebbbebceb2f4516131e20cbd7f056c.git grpc.request.repoStorage=default grpc.service=gitaly.RepositoryService grpc.start_time="2023-08-22T17:07:39.342" peer.address= span.kind=server system=grpc test=TestUserCreateBranch_failure
        time="2023-08-22T17:07:39+03:00" level=info msg="finished unary call with code OK" command.count=2 command.cpu_time_ms=8 command.inblock=0 command.majflt=17 command.maxrss=4997120 command.minflt=881 command.oublock=0 command.real_time_ms=18 command.spawn_token_fork_ms=2 command.spawn_token_wait_ms=0 command.system_time_ms=6 command.user_time_ms=2 component=gitaly.UnaryServerInterceptor correlation_id=01H8ES54AESQNBDQ4MY8WXR4X8 feature_flags=run_cmds_in_cgroup grpc.code=OK grpc.meta.deadline_type=none grpc.meta.method_operation=mutator grpc.meta.method_scope=repository grpc.meta.method_type=unary grpc.method=CreateRepository grpc.request.fullMethod=/gitaly.RepositoryService/CreateRepository grpc.request.glProjectPath=gitlab-org/gitlab-test grpc.request.glRepository=project-1 grpc.request.payload_bytes=133 grpc.request.repoPath=@hashed/be/ed/beede0274668dfc564c3b18cd889fa4369ebbbebceb2f4516131e20cbd7f056c.git grpc.request.repoStorage=default grpc.response.payload_bytes=0 grpc.service=gitaly.RepositoryService grpc.start_time="2023-08-22T17:07:39.342" grpc.time_ms=82.342 peer.address= span.kind=server system=grpc test=TestUserCreateBranch_failure
        time="2023-08-22T17:07:39+03:00" level=info msg="diskcache state change" component=gitaly.UnaryServerInterceptor correlation_id=01H8ES54EYTKWJTN7KBTSCFV1F diskcache=4b70fb48-ec78-46e9-8416-af08f18773d9 grpc.meta.deadline_type=none grpc.meta.method_operation=mutator grpc.meta.method_scope=repository grpc.meta.method_type=unary grpc.method=UserCreateBranch grpc.request.fullMethod=/gitaly.OperationService/UserCreateBranch grpc.request.glProjectPath=gitlab-org/gitlab-test grpc.request.glRepository=project-1 grpc.request.repoPath=@hashed/be/ed/beede0274668dfc564c3b18cd889fa4369ebbbebceb2f4516131e20cbd7f056c.git grpc.request.repoStorage=default grpc.service=gitaly.OperationService grpc.start_time="2023-08-22T17:07:39.486" peer.address= span.kind=server system=grpc test=TestUserCreateBranch_failure
        time="2023-08-22T17:07:39+03:00" level=warning msg="finished unary call with code FailedPrecondition" catfile.duration_ms=0 catfile.flush_count=1 catfile.flush_ms=0 catfile.read_object_count=1 catfile.read_object_ms=0 catfile.request_object_count=1 catfile.request_object_ms=0 command.count=4 command.cpu_time_ms=10 command.inblock=0 command.majflt=28 command.maxrss=5046272 command.minflt=1752 command.oublock=0 command.real_time_ms=23 command.spawn_token_fork_ms=3 command.spawn_token_wait_ms=0 command.system_time_ms=6 command.user_time_ms=4 component=gitaly.UnaryServerInterceptor correlation_id=01H8ES54EYTKWJTN7KBTSCFV1F error="reference update: state update to \"prepare\" failed: EOF" error_metadata="map[stderr:fatal: prepare: cannot lock ref 'refs/heads/master': reference already exists\n]" feature_flags=run_cmds_in_cgroup grpc.code=FailedPrecondition grpc.meta.deadline_type=none grpc.meta.method_operation=mutator grpc.meta.method_scope=repository grpc.meta.method_type=unary grpc.method=UserCreateBranch grpc.request.fullMethod=/gitaly.OperationService/UserCreateBranch grpc.request.glProjectPath=gitlab-org/gitlab-test grpc.request.glRepository=project-1 grpc.request.payload_bytes=213 grpc.request.repoPath=@hashed/be/ed/beede0274668dfc564c3b18cd889fa4369ebbbebceb2f4516131e20cbd7f056c.git grpc.request.repoStorage=default grpc.response.payload_bytes=0 grpc.service=gitaly.OperationService grpc.start_time="2023-08-22T17:07:39.486" grpc.time_ms=32.326 peer.address= span.kind=server system=grpc test=TestUserCreateBranch_failure
        time="2023-08-22T17:07:39+03:00" level=info msg="diskcache state change" component=gitaly.UnaryServerInterceptor correlation_id=01H8ES54G1PHN4R2VHGCVHRT29 diskcache=7e6c8e1e-4e0f-414a-a2ef-74daf3000a39 grpc.meta.deadline_type=none grpc.meta.method_operation=mutator grpc.meta.method_scope=repository grpc.meta.method_type=unary grpc.method=RemoveRepository grpc.request.fullMethod=/gitaly.RepositoryService/RemoveRepository grpc.request.glProjectPath=gitlab-org/gitlab-test grpc.request.glRepository=project-1 grpc.request.repoPath=@hashed/be/ed/beede0274668dfc564c3b18cd889fa4369ebbbebceb2f4516131e20cbd7f056c.git grpc.request.repoStorage=default grpc.service=gitaly.RepositoryService grpc.start_time="2023-08-22T17:07:39.521" peer.address= span.kind=server system=grpc test=TestUserCreateBranch_failure
        time="2023-08-22T17:07:39+03:00" level=info msg="finished unary call with code OK" component=gitaly.UnaryServerInterceptor correlation_id=01H8ES54G1PHN4R2VHGCVHRT29 grpc.code=OK grpc.meta.deadline_type=none grpc.meta.method_operation=mutator grpc.meta.method_scope=repository grpc.meta.method_type=unary grpc.method=RemoveRepository grpc.request.fullMethod=/gitaly.RepositoryService/RemoveRepository grpc.request.glProjectPath=gitlab-org/gitlab-test grpc.request.glRepository=project-1 grpc.request.payload_bytes=131 grpc.request.repoPath=@hashed/be/ed/beede0274668dfc564c3b18cd889fa4369ebbbebceb2f4516131e20cbd7f056c.git grpc.request.repoStorage=default grpc.response.payload_bytes=0 grpc.service=gitaly.RepositoryService grpc.start_time="2023-08-22T17:07:39.521" grpc.time_ms=13.348 peer.address= span.kind=server system=grpc test=TestUserCreateBranch_failure
        time="2023-08-22T17:07:39+03:00" level=info msg="Lifetime L0 stalled for: 0s\n" component=database storage=default
        time="2023-08-22T17:07:39+03:00" level=info msg="\nLevel 0 [ ]: NumTables: 00. Size: 0 B of 0 B. Score: 0.00->0.00 StaleData: 0 B Target FileSize: 64 MiB\nLevel 1 [ ]: NumTables: 00. Size: 0 B of 10 MiB. Score: 0.00->0.00 StaleData: 0 B Target FileSize: 2.0 MiB\nLevel 2 [ ]: NumTables: 00. Size: 0 B of 10 MiB. Score: 0.00->0.00 StaleData: 0 B Target FileSize: 2.0 MiB\nLevel 3 [ ]: NumTables: 00. Size: 0 B of 10 MiB. Score: 0.00->0.00 StaleData: 0 B Target FileSize: 2.0 MiB\nLevel 4 [ ]: NumTables: 00. Size: 0 B of 10 MiB. Score: 0.00->0.00 StaleData: 0 B Target FileSize: 2.0 MiB\nLevel 5 [ ]: NumTables: 00. Size: 0 B of 10 MiB. Score: 0.00->0.00 StaleData: 0 B Target FileSize: 2.0 MiB\nLevel 6 [B]: NumTables: 00. Size: 0 B of 10 MiB. Score: 0.00->0.00 StaleData: 0 B Target FileSize: 2.0 MiB\nLevel Done\n" component=database storage=default
        
FAIL
FAIL	gitlab.com/gitlab-org/gitaly/v16/internal/gitaly/service/operations	4.713s
FAIL

Verbose output of the test when it succeeds doesn't include the logs:

=== RUN   TestUserCreateBranch_failure
=== PAUSE TestUserCreateBranch_failure
=== CONT  TestUserCreateBranch_failure
=== RUN   TestUserCreateBranch_failure/branch_exists
=== PAUSE TestUserCreateBranch_failure/branch_exists
=== CONT  TestUserCreateBranch_failure/branch_exists
--- PASS: TestUserCreateBranch_failure (3.63s)
    --- PASS: TestUserCreateBranch_failure/branch_exists (0.04s)
PASS
ok  	gitlab.com/gitlab-org/gitaly/v16/internal/gitaly/service/operations	(cached)

As logs were generally discarded, many test are instantiating multiple loggers. This didn't previously matter as the logs were discarded but now they lead to multiple log record entries and the logs are not ordered. The SharedLogger functionality allows for easily plugging this in now and ordering the logs properly but is not really strictly needed. Eventually we should move towards only instantiating a single logger in most tests and pass it around.

There's still more improvements that can be done later. Some subtests use a shared server/logger in which case they also pollute each others logs. With the base functionality in place, we'll be in better position to refactor such setups cases by case as needed.

Edited by Sami Hiltunen

Merge request reports