Opened 5 months ago

Closed 5 months ago

Last modified 5 months 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 Changed 5 months ago by mdounin

  • Resolution set to invalid
  • Status changed from new to closed

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 Changed 5 months ago by kosmas.valianos@…

Apparently journald does not like some characters and deems it as blob. So basically all logging of HTTP stuff from nginx in systemd is useless. 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. Use systemd logging

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

Last edited 5 months ago by kosmas.valianos@… (previous) (diff)
Note: See TracTickets for help on using tickets.