kristapsdz / kcgi

minimal CGI and FastCGI library for C/C++
https://kristaps.bsd.lv/kcgi
ISC License
275 stars 40 forks source link

Default stderr logging output not line-buffered #75

Closed xwhatsit closed 4 years ago

xwhatsit commented 4 years ago

This is rather low-priority---it's one line to "fix" in an application, and I'm not really certain it's a kcgi issue or rather a quirk of slowcgi with httpd or Nginx.

stderr is normally unbuffered by default. This appears to cause problems with both Nginx and OpenBSD's httpd writing these logs with one character on each line. Example from httpd's log:

1234:5678:5e63:f101:8286:f2ff:feba:b1c5 account [Sat, 01 Feb 2020 02:15:24 GMT] INFO
m
o
d
i
f
y
_
p
a
g
e
:

s
u
c
c
e
s
s

This happens using kutil_* functions, but often seems to be triggered by an earlier "direct" write to stderr using fprintf() or perror() etc.

Using kutil_openlog() to log to a separate file does not show this behaviour; kutil_openlog() also enables line-buffered output. Using setvbuf(stderr, NULL, _IOLBF, 0) on the default stderr output appears to solve the issue entirely.

I haven't had time to dig into slowcgi's code, but I will guess that the cause is likely here and is related to how they read stderr before sending over TCP. The char-by-char fputc's in kutil_* logging functions are flushed immediately and being translated into entire log messages by the web servers.

Perhaps line-buffering for stderr could be enabled by default for the kutil_* logging functions; I can't think of any issues having buffered stderr in this context, other than the inefficiency of either calling setvbuf() on every log call, or lazily enabling it and keeping track of whether it was enabled on each call.

kristapsdz commented 4 years ago

I guess the simple fix for this is either to put a suitable note in the manpage either to setvbuf or to call the openlog function if any of the logging functions are used.

The more complicated fix is to convert the function to buffer the entire message before printing. I'm inclined to the latter as we already kinda do that for the varags part, although it's a fixed-size buffer. (Which should be made dynamic anyway.) So I think the best solution is to convert the function to heap-allocate the entire message, do its filtering, then push it out. This would also remove the need for line buffering at all.

xwhatsit commented 4 years ago

The more complicated fix is to convert the function to buffer the entire message before printing.

One could argue that libc is doing that for free when we setvbuf :)

I do like getting rid of fixed-size buffers however, although I can't picture writing 1 kB in a single log message (famous last words).

I'll try and find some time this weekend and put together a pull request.