#946 closed defect (wontfix)
Nginx that is logging into /dev/log cannot handle change of inode of the socket
| Reported by: | Owned by: | ||
|---|---|---|---|
| Priority: | minor | Milestone: | |
| Component: | nginx-core | Version: | 1.9.x |
| Keywords: | syslog logging | Cc: | |
| uname -a: | Linux osboxes 3.19.0-25-generic #26~14.04.1-Ubuntu SMP Fri Jul 24 21:16:20 UTC 2015 x86_64 x86_64 x86_64 GNU/Linux | ||
| nginx -V: |
nginx version: nginx/1.9.10
built with OpenSSL 1.0.1f 6 Jan 2014 TLS SNI support enabled configure arguments: --with-cc-opt='-g -O2 -fPIE -fstack-protector --param=ssp-buffer-size=4 -Wformat -Werror=format-security -D_FORTIFY_SOURCE=2' --with-ld-opt='-Wl,-Bsymbolic-functions -fPIE -pie -Wl,-z,relro -Wl,-z,now' --prefix=/usr/share/nginx --conf-path=/etc/nginx/nginx.conf --http-log-path=/var/log/nginx/access.log --error-log-path=/var/log/nginx/error.log --lock-path=/var/lock/nginx.lock --pid-path=/run/nginx.pid --http-client-body-temp-path=/var/lib/nginx/body --http-fastcgi-temp-path=/var/lib/nginx/fastcgi --http-proxy-temp-path=/var/lib/nginx/proxy --http-scgi-temp-path=/var/lib/nginx/scgi --http-uwsgi-temp-path=/var/lib/nginx/uwsgi --with-debug --with-pcre-jit --with-ipv6 --with-http_ssl_module --with-http_stub_status_module --with-http_realip_module --with-http_auth_request_module --add-module=/usr/local/lib/mod_security/nginx/modsecurity --with-http_addition_module --with-http_dav_module --with-http_geoip_module --with-http_gunzip_module --with-http_gzip_static_module --with-http_image_filter_module }}} |
||
Description
Hi,
I would like to report the following bug. We are using Nginx and Nginx is forwarding all logs into local syslog and local syslog is forwarding messages remotely.
Following configuration in Nginx is used
access_log syslog:server=unix:/dev/log,facility=local0,tag=nginx_accesslog,severity=info custom;
Everything works fine, until we change the configuration in rsyslog and restart the rsyslog service. Rsyslog service restart causes change of the inode of /dev/log.
#stat /dev/log File: ‘/dev/log’ Size: 0 Blocks: 0 IO Block: 4096 socket Device: 6h/6d Inode: 11124 Links: 1 Access: (0666/srw-rw-rw-) Uid: ( 0/ root) Gid: ( 0/ root) Access: 2016-04-01 09:30:02.841584888 +0100 Modify: 2016-04-01 09:30:02.705584891 +0100 Change: 2016-04-01 09:30:02.705584891 +0100 Birth: - #service rsyslog restart rsyslog stop/waiting rsyslog start/running, process 3116 #stat /dev/log File: ‘/dev/log’ Size: 0 Blocks: 0 IO Block: 4096 socket Device: 6h/6d Inode: 24709 Links: 1 Access: (0666/srw-rw-rw-) Uid: ( 0/ root) Gid: ( 0/ root) Access: 2016-04-01 09:46:56.531802641 +0100 Modify: 2016-04-01 09:46:56.531802641 +0100 Change: 2016-04-01 09:46:56.531802641 +0100 Birth: -
Now comes the part that I think is buggy in Nginx implementation. When the Nginx server tries to write first message to the /dev/log socket after rsyslog was restarted, it fails.
sendto(13, "<182>Apr 1 09:52:26 first access log message", 422, 0, NULL, 0) = -1 ECONNREFUSED (Connection refused) write(4, "2016/04/01 09:52:26 [error] 1479#0: send() failed (111: Connection refused)\n", 76) = 76 close(13) = 0
The second attempt to write to /dev/log is successful, because nginx closed the socket after first unsuccessful attempt and now it will open the new socket.
socket(PF_LOCAL, SOCK_DGRAM, 0) = 4
ioctl(4, FIONBIO, [1]) = 0
connect(4, {sa_family=AF_LOCAL, sun_path="/dev/log"}, 110) = 0
sendto(4, "<182>Apr 1 10:03:47 second access log message", 422, 0, NULL, 0) = 422
So the consequence of the improper implementation of socket handling is that the first message after restarting the syslog service will be lost.
Thanks.
Change History (2)
comment:1 by , 9 years ago
| Resolution: | → wontfix |
|---|---|
| Status: | new → closed |
comment:2 by , 9 years ago
Thanks for your quick reply.
I do agree with you. But one thing I see here that could be improved is that this is not happening only during restarting of rsyslog service. This happens also when you restarted rsyslog a while ago and thus /dev/log socket is in place and ready to receive the logs. But in a different inode. Nginx just tries to log message to the socket that has been opened for some time and if it fails (because the original inode does not exist anymore), there is no attempt to reopen the socket again (and it will be successful).
Syslog restarts are expected to cause message loss as there is a period of time when logging is not available at all. Current nginx syslog logging implementation assumes that it is safe to loss messages (as this is anyway expected to happen with syslog), but certainly not safe to block worker processes by waiting for syslog and/or doing in-place reconnects. Therefore if an error happens during logging, the logging socket is just closed and reopened on a next logging attempt.
If you aren't happy with this behaviour, consider using UDP sockets for logging instead of unix ones, it should minimize possible impact of syslog restarts. Alternatively, use logging to files - there should be no lost messages at all when logging to files.