#1815 closed defect (invalid)
Debug log of response is garbled in journald
| Reported by: | 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 , 5 years ago
| Resolution: | → invalid |
|---|---|
| Status: | new → closed |
comment:2 by , 5 years ago
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:
- Build with
--error-log-path=/var/log/nginx/error.log
- Use systemd logging
You can use journald normally and get the "hidden" "blob" stuff from the file if you need them
Note:
See TracTickets
for help on using tickets.
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.