Fix chatty loopWriter logs when log level config is empty
For #5658 (closed)
Problem statement
Recently, we noticed that Gitaly sometimes outputs verbose
transportation logs with info
severity. That causes a lot of confusion for our customers and our internal internal teams. We received a handful of questions regarding those logs in Slack and support tickets.
2023-10-12T20:30:18.883066580Z {"component": "gitaly","subcomponent":"gitaly","level":"error","level":"info","msg":"[transport] [client-transport 0xc00abb86c0] Closing: connection error: desc = \"error reading from server:EOF\"","pid":1,"system":"system","time":"2023-10-12T20:30:18.882Z"}
2023-10-12T20:30:18.883113776Z {"component": "gitaly","subcomponent":"gitaly","level":"error","level":"info","msg":"[transport] [client-transport 0xc00abb86c0] loopyWriter exiting with error: transport closed by client","pid":1,"system":"system","time":"2023-10-12T20:30:18.883Z"}
2023-10-12T20:30:18.883133413Z {"component": "gitaly","subcomponent":"gitaly","level":"error","level":"info","msg":"[transport] [server-transport 0xc005cdf520] loopyWriter exiting with error: transport closed by client","pid":1,"system":"system","time":"2023-10-12T20:30:18.883Z"}
The loopy writer stuff is gRPC-internal logic and likely doesn't indicate anything important. In fact, those logs are always output when the server/client closes the transportation regardless of the errors. The log printing statement can be found here: https://github.com/grpc/grpc-go/blob/8edfa1a17b3ff88cdb8cc9ec39fce22b812cf842/internal/transport/http2_server.go#L1232
We implemented a mechanism to replace grpc's default logger to make it less chatty. The replacement uplifts the minimum grpc logger level to "warning" when the configured Gitaly log level is "info". Unfortunately, it doesn't handle the case where Gitaly does not configure log level. As a result, grpc falls back to its "info". This commit handles that edge case.
Verify solution
Before
- Step 1: On the
master
branch, removelogging.level
from thetoml
file. GDK sets it by default. Folks who set that config will never observe this phenomenon.
[logging]
format = "json"
dir = "/path/to/log/gitaly"
- Step 2: Restart the Gitaly server. Perform some testing pulls and interrupt the connections early. The described logs show up:
After
Repeat the above steps. All the loopyWriter
logs disappeared. The warning
log still shows up as designed.