Skip to content

Enable log buffering #4061

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
steve-chavez opened this issue May 5, 2025 · 1 comment
Open

Enable log buffering #4061

steve-chavez opened this issue May 5, 2025 · 1 comment

Comments

@steve-chavez
Copy link
Member

steve-chavez commented May 5, 2025

Problem

Currently there's no log buffering, as noted in docs. This means that log levels higher than error cannot be enabled without reduced RPS.

Additionally, this might also cause other issues with the default log-level=error. For example on pool timeouts, the RPS will also suffer.

Solution

Enable log buffering, currently it's all set to line buffering on:

postgrest/main/Main.hs

Lines 15 to 21 in bf79766

setBuffering :: IO ()
setBuffering = do
-- LineBuffering: the entire output buffer is flushed whenever a newline is
-- output, the buffer overflows, a hFlush is issued or the handle is closed
hSetBuffering stdout LineBuffering
hSetBuffering stdin LineBuffering
hSetBuffering stderr LineBuffering

This concern should be centralized on the Logger.hs module and possibly receive a config option as input.

Notes

The logger middleware obfuscates this logic. Ideally we should reuse our Observation module as mentioned on:

-- TODO stop using this middleware to reuse the same "observer" pattern for all our logs
middleware :: LogLevel -> (Wai.Request -> Maybe BS.ByteString) -> Wai.Middleware
middleware logLevel getAuthRole =
unsafePerformIO $
Wai.mkRequestLogger Wai.defaultRequestLoggerSettings
{ Wai.outputFormat =
Wai.ApacheWithSettings $
Wai.defaultApacheSettings &
Wai.setApacheRequestFilter (\_ res -> shouldLogResponse logLevel $ Wai.responseStatus res) &
Wai.setApacheUserGetter getAuthRole
, Wai.autoFlush = True
, Wai.destination = Wai.Handle stdout
}

@steve-chavez
Copy link
Member Author

One way to test buffering is working as intended would be to enable log-level=info for the loadtests, in that case throughput should be more or less maintained.

steve-chavez added a commit to steve-chavez/postgrest that referenced this issue May 5, 2025
Benefits:

- Removes `unsafePerformIO` from Logger
- Reuses our cached time getter (`stateGetZTime`) instead of having another unnecessary one.
  See https://github.com/yesodweb/wai//blob/d50e1184600631a114e3d2ad119abdf0ef08834b/wai-extra/Network/Wai/Middleware/RequestLogger/Internal.hs#L22-L37.
- Reuses Observation module, simplified logic
- Will help with log buffering PostgREST#4061

TODO:

- [ ] Currently we vendor `apacheLogStr`, but might be possible to
  expose this function upstream. If not, it's not a big problem since
  the function is small.
- [ ] Time in logging differs a bit:
```
  Old: postgrest_test_anonymous [04/May/2025:14:43:06 -0500]
  New: postgrest_test_anonymous [2025-05-04 22:43:01.28098247 -05]
```
  + Otherwise all logging works the same.
- [ ] Auth error logging relies on old logger middleware
  + We might need to put `observer` in Auth.hs
  + Or otherwise try to combine this with PostgREST#4059
steve-chavez added a commit to steve-chavez/postgrest that referenced this issue May 5, 2025
Benefits:

- Removes `unsafePerformIO` from Logger
- Reuses our cached time getter (`stateGetZTime`) instead of having another unnecessary one.
  See https://github.com/yesodweb/wai//blob/d50e1184600631a114e3d2ad119abdf0ef08834b/wai-extra/Network/Wai/Middleware/RequestLogger/Internal.hs#L22-L37.
- Reuses Observation module, simplified logic
- Will help with log buffering PostgREST#4061

TODO:

- [ ] Currently we vendor `apacheLogStr`, but might be possible to
  expose this function upstream. If not, it's not a big problem since
  the function is small.
- [ ] Time in logging differs a bit:
```
  Old: postgrest_test_anonymous [04/May/2025:14:43:06 -0500]
  New: postgrest_test_anonymous [2025-05-04 22:43:01.28098247 -05]
```
  + Otherwise all logging works the same.
- [ ] Auth error logging relies on old logger middleware
  + We might need to put `observer` in Auth.hs
  + Or otherwise try to combine this with PostgREST#4059
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Development

No branches or pull requests

2 participants