Skip to content

Implement subprocess logging via pipes

Sami Hiltunen requested to merge smh-log-server into master

Gitaly's subprocess logger receives logs from subprocesses over a pipe and outputs them with all the other logs in stdout. This makes log management easier when all logs are in a single location and not spread through different files.

This commit wires the subprocess logger into Gitaly. Gitaly passes a pipe into subprocesses when launching them if the feature flag is enabled. The subprocesses receive logging configuration over an environment variable and write their logs into the configured pipe instead of files.

When the feature flag is set, logs from gitaly-hooks for example are printed through Gitaly's stdout and look like

{"component":"gitaly_hooks.log","correlation_id":"01J30HGTP324HSWWFCB2YG02FT","level":"info","msg":"LOG OUTPUT FROM GITALY HOOKS","pid":89220,"time":"2024-07-17T14:28:42.654Z"}

In tests, if gitaly-hooks fails the output now gets printed as well with the other logs:

=== RUN   TestFetchInternalRemote_successful
=== PAUSE TestFetchInternalRemote_successful
=== CONT  TestFetchInternalRemote_successful
    replicate_test.go:635: 
        	Error Trace:	/Users/sami/gitlab/gitlab-development-kit/gitaly/internal/gitaly/service/repository/replicate_test.go:635
        	Error:      	Received unexpected error:
        	            	exit status 128
        	Test:       	TestFetchInternalRemote_successful
    command.go:78:  [-C /private/tmp/gitaly-1286342801/1402400427/storages.d/default/@hashed/0c/2a/0c2a8a45aa9459b4335ec810954bc794a896f6550f49b421d176bc15c2f0e95b.git show-ref --head]
    command.go:82: exit status 1
    logger.go:134: Recorded logs of "subprocess-logger":
        time="2024-07-18T08:40:02.720Z" level=error msg="SOME ERROR OCCURRED" component=gitaly_hooks.log correlation_id=01J32FZ3Z3F337WJRTPZ0Z3ANY pid=66206
        time="2024-07-18T08:40:02.987Z" level=error msg="SOME ERROR OCCURRED" component=gitaly_hooks.log correlation_id=01J32FZ3Z3F337WJRTPZ0Z3ANY pid=66386
        
    logger.go:134: Recorded logs of "gitaly":
        time="2024-07-18T11:40:02+03:00" level=info msg="request details" component=gitaly.UnaryServerInterceptor correlation_id=01J32FZ3Z3F337WJRTPZ0Z3ANY grpc.meta.deadline_type=none grpc.meta.method_operation=accessor grpc.meta.method_scope=repository grpc.meta.method_type=unary grpc.method=SSHUploadPackWithSidechannel grpc.request.fullMethod=/gitaly.SSHService/SSHUploadPackWithSidechannel grpc.request.glProjectPath=gitlab-org/gitlab-test grpc.request.glRepository=project-1 grpc.request.repoPath=@hashed/38/04/3804d3a182d5a3d8c55a6538627c9be0639815049add5e01293431d958339d91.git grpc.request.repoStorage=default grpc.service=gitaly.SSHService grpc.start_time="2024-07-18T11:40:02.026" response_bytes=395 span.kind=server system=grpc test=TestFetchInternalRemote_successful
        time="2024-07-18T11:40:02+03:00" level=info msg="finished unary call with code OK" command.count=3 command.cpu_time_ms=14 command.inblock=0 command.majflt=31 command.maxrss=6537216 command.minflt=2047 command.oublock=0 command.real_time_ms=25 command.spawn_token_fork_ms=3 command.spawn_token_wait_ms=0 command.system_time_ms=8 command.user_time_ms=6 component=gitaly.UnaryServerInterceptor correlation_id=01J32FZ3Z3F337WJRTPZ0Z3ANY feature_flags="log_server mailmap_options use_empty_tree_in_attr_tree_config" grpc.code=OK grpc.meta.deadline_type=none grpc.meta.method_operation=accessor grpc.meta.method_scope=repository grpc.meta.method_type=unary grpc.method=SSHUploadPackWithSidechannel grpc.request.fullMethod=/gitaly.SSHService/SSHUploadPackWithSidechannel grpc.request.glProjectPath=gitlab-org/gitlab-test grpc.request.glRepository=project-1 grpc.request.payload_bytes=203 grpc.request.repoPath=@hashed/38/04/3804d3a182d5a3d8c55a6538627c9be0639815049add5e01293431d958339d91.git grpc.request.repoStorage=default grpc.response.payload_bytes=9 grpc.service=gitaly.SSHService grpc.start_time="2024-07-18T11:40:02.026" grpc.time_ms=27.338 span.kind=server system=grpc test=TestFetchInternalRemote_successful
        
--- FAIL: TestFetchInternalRemote_successful (4.02s)
FAIL
FAIL	gitlab.com/gitlab-org/gitaly/v16/internal/gitaly/service/repository	5.213s
FAIL

Closes Centralize logging strategy to avoid individual... (#3275 - closed)

Edited by Sami Hiltunen

Merge request reports

Loading