Opened 3 years ago

Closed 3 years ago

Last modified 3 years ago

#1815 closed defect (invalid)

Debug log of response is garbled in journald

Reported by: kosmas.valianos@… Owned by:
Priority: minor Milestone:
Component: nginx-core Version: 1.16.x
Keywords: journald, stdout Cc:
uname -a: Linux envy-172-17-146-2.devops 4.15.0-54-generic #58-Ubuntu SMP Mon Jun 24 10:55:24 UTC 2019 x86_64 x86_64 x86_64 GNU/Linux
nginx -V: nginx version: nginx/1.16.0
built by gcc 8.3.0 (Ubuntu 8.3.0-6ubuntu1~18.04.1)
built with OpenSSL 1.1.1 11 Sep 2018
TLS SNI support enabled
configure arguments: --with-cc-opt='-g -Wall -Wextra -fshort-enums -fPIE -fstack-protector-all -fstack-clash-protection -D_FORTIFY_SOURCE=2 -Wformat -Wformat-security -std=gnu11 --param=ssp-buffer-size=4 -mtune=intel -O3 -fno-omit-frame-pointer -flto -DNDEBUG' --with-ld-opt='-Wl,-z,now -Wl,-z,relro -Wl,-Bsymbolic-functions -pie' --add-module=ngx-devel-kit --add-module=lua-nginx-module --with-threads --add-module=../url_access --without-http_gzip_module --with-http_ssl_module --with-http_auth_request_module --with-ipv6 --with-debug --prefix=/usr --sbin-path=/usr/sbin/nginx --conf-path=/etc/nginx/nginx.conf --error-log-path=/var/log/nginx/error.log --http-log-path=/var/log/nginx/access.log --pid-path=/run/nginx.pid --with-http_v2_module

Description

It is quite easy to reproduce. In your nginx.conf set the error_log to stdout. Create a body handler so that you can send your own response to an HTTP request. Do a curl or something to trigger your response. In the logs to stdout you will nicely see:

2019/07/17 08:54:38 [debug] 18863#18863: *1 http request body content length filter
2019/07/17 08:54:38 [debug] 18863#18863: *1 lua capture header filter, uri "/url_access/remove_all"
2019/07/17 08:54:38 [debug] 18863#18863: *1 HTTP/1.1 200 OK
Server: nginx
Date: Wed, 17 Jul 2019 08:54:38 GMT
Content-Length: 128
Connection: keep-alive
X-Nginx-Module: url_access

2019/07/17 08:54:38 [debug] 18863#18863: *1 write new buf t:1 f:0 000055FCB4E0D2B0, pos 000055FCB4E0D2B0, size: 144 file: 0, size: 0
2019/07/17 08:54:38 [debug] 18863#18863: *1 http write filter: l:0 f:0 s:144
2019/07/17 08:54:38 [debug] 18863#18863: *1 http output filter "/url_access/remove_all?"
2019/07/17 08:54:38 [debug] 18863#18863: *1 http copy filter: "/url_access/remove_all?"
2019/07/17 08:54:38 [debug] 18863#18863: *1 lua capture body filter, uri "/url_access/remove_all"
2019/07/17 08:54:38 [debug] 18863#18863: *1 http postpone filter "/url_access/remove_all?" 00007FFE03A91AD0
2019/07/17 08:54:38 [debug] 18863#18863: *1 write old buf t:1 f:0 000055FCB4E0D2B0, pos 000055FCB4E0D2B0, size: 144 file: 0, size: 0
2019/07/17 08:54:38 [debug] 18863#18863: *1 write new buf t:0 f:0 00007FFE03A91B50, pos 00007FFE03A91B50, size: 128 file: 0, size: 0
2019/07/17 08:54:38 [debug] 18863#18863: *1 http write filter: l:1 f:0 s:272
2019/07/17 08:54:38 [debug] 18863#18863: *1 http write filter limit 0
2019/07/17 08:54:38 [debug] 18863#18863: *1 writev: 272 of 272
2019/07/17 08:54:38 [debug] 18863#18863: *1 http write filter 0000000000000000
2019/07/17 08:54:38 [debug] 18863#18863: *1 http copy filter: 0 "/url_access/remove_all?"
2019/07/17 08:54:38 [debug] 18863#18863: *1 http finalize request: 0, "/url_access/remove_all?" a:1, c:2
2019/07/17 08:54:38 [debug] 18863#18863: *1 http request count:2 blk:0
2019/07/17 08:54:38 [debug] 18863#18863: *1 http finalize request: -4, "/url_access/remove_all?" a:1, c:1
2019/07/17 08:54:38 [debug] 18863#18863: *1 set http keepalive handler
2019/07/17 08:54:38 [debug] 18863#18863: *1 http close request
2019/07/17 08:54:38 [debug] 18863#18863: *1 http log handler

Change now your nginx.conf to use journald. I use error_log syslog:server=unix:/dev/log,nohostname debug;. Do the same thing to trigger your response. Check journald logs and you will see garbled output instead:

Jul 17 08:52:44 envy-172-17-146-2.devops nginx[12890]: 2019/07/17 08:52:44 [debug] 12890#12890: *2 http request body content length filter
nginx[12890]: 2019/07/17 08:52:44 [debug] 12890#12890: *2 lua capture header filter, uri "/url_access/remove_all"
nginx[12890]: [184B blob data]
nginx[12890]: 2019/07/17 08:52:44 [debug] 12890#12890: *2 write new buf t:1 f:0 00005571CAEA22B0, pos 00005571CAEA22B0, size: 144 file: 0, size: 0
nginx[12890]: 2019/07/17 08:52:44 [debug] 12890#12890: *2 http write filter: l:0 f:0 s:144
nginx[12890]: 2019/07/17 08:52:44 [debug] 12890#12890: *2 http output filter "/url_access/remove_all?"
nginx[12890]: 2019/07/17 08:52:44 [debug] 12890#12890: *2 http copy filter: "/url_access/remove_all?"
nginx[12890]: 2019/07/17 08:52:44 [debug] 12890#12890: *2 lua capture body filter, uri "/url_access/remove_all"
nginx[12890]: 2019/07/17 08:52:44 [debug] 12890#12890: *2 http postpone filter "/url_access/remove_all?" 00007FFE0A649170
nginx[12890]: 2019/07/17 08:52:44 [debug] 12890#12890: *2 write old buf t:1 f:0 00005571CAEA22B0, pos 00005571CAEA22B0, size: 144 file: 0, size: 0
nginx[12890]: 2019/07/17 08:52:44 [debug] 12890#12890: *2 write new buf t:0 f:0 00007FFE0A6491F0, pos 00007FFE0A6491F0, size: 128 file: 0, size: 0
nginx[12890]: 2019/07/17 08:52:44 [debug] 12890#12890: *2 http write filter: l:1 f:0 s:272
nginx[12890]: 2019/07/17 08:52:44 [debug] 12890#12890: *2 http write filter limit 0
nginx[12890]: 2019/07/17 08:52:44 [debug] 12890#12890: *2 writev: 272 of 272
nginx[12890]: 2019/07/17 08:52:44 [debug] 12890#12890: *2 http write filter 0000000000000000
nginx[12890]: 2019/07/17 08:52:44 [debug] 12890#12890: *2 http copy filter: 0 "/url_access/remove_all?"
nginx[12890]: 2019/07/17 08:52:44 [debug] 12890#12890: *2 http finalize request: 0, "/url_access/remove_all?" a:1, c:2
nginx[12890]: 2019/07/17 08:52:44 [debug] 12890#12890: *2 http request count:2 blk:0
nginx[12890]: 2019/07/17 08:52:44 [debug] 12890#12890: *2 http finalize request: -4, "/url_access/remove_all?" a:1, c:1
nginx[12890]: 2019/07/17 08:52:44 [debug] 12890#12890: *2 set http keepalive handler
nginx[12890]: 2019/07/17 08:52:44 [debug] 12890#12890: *2 http close request
nginx[12890]: 2019/07/17 08:52:44 [debug] 12890#12890: *2 http log handler

Notice it now shows nginx[12890]: [184B blob data] instead of the headers etc like above in the stdout case

Change History (2)

comment:1 by Maxim Dounin, 3 years ago

Resolution: invalid
Status: newclosed

It looks like your syslog daemon doesn't like multi-line messages and hides them, saying it's "blob data". This is to be addressed in your syslog daemon.

comment:2 by kosmas.valianos@…, 3 years ago

Apparently journald does not like \r. So basically all logging of HTTP stuff from nginx in systemd is useless. Maybe not a bug but feature request. Add support for systemd. All (most) linux distros are using systemd

Adding "workaround" for anyone banging his head:

  1. Build with
    --error-log-path=/var/log/nginx/error.log
    
  2. In your nginx conf use systemd logging

You can use journald normally and get the "hidden" "blob" stuff from the file if you need them

Version 1, edited 3 years ago by kosmas.valianos@… (previous) (next) (diff)
Note: See TracTickets for help on using tickets.