#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 \r. So basically all logging of HTTP stuff from nginx in systemd is useless. Maybe not a bug but feature request. Add support for lennart. All (most) linux distros are using systemd
Adding "workaround" for anyone banging his head:
- Build with
--error-log-path=/var/log/nginx/error.log
- 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 0, edited 5 years ago by (next)
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.