Implement subprocess logging via pipes
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)