Opened 4 years ago

Closed 4 years ago

Last modified 4 years ago

#946 closed defect (wontfix)

Nginx that is logging into /dev/log cannot handle change of inode of the socket

Reported by: gulycka@… 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 Maxim Dounin, 4 years ago

Resolution: wontfix
Status: newclosed

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.

comment:2 by gulycka@…, 4 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).

Note: See TracTickets for help on using tickets.