Skip to content

Fix chatty loopWriter logs when log level config is empty

Quang-Minh Nguyen requested to merge qmnguyen0711/fix-loopy-logger-issue into master

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, remove logging.level from the toml 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:

Screenshot_2023-11-08_at_17.06.02

After

Repeat the above steps. All the loopyWriter logs disappeared. The warning log still shows up as designed.

Screenshot_2023-11-08_at_17.07.07

Merge request reports