Created attachment 1130224 [details]
Fix

This issue is present also in Fedora (I tested at least F23).

+++ This bug was initially created as a clone of Bug #1175071 +++

Description of problem:

From the man page,
---
"When syslog is enabled, any log output which would have gone to /var/log/vsftpd.log goes to the system log instead."
---
But,

"User is not in the allow user list." message is logged to /var/log/vsftpd.log when syslog_enable=no

"User is not in the allow user list." message is NOT logged to syslog when syslog_enable=yes

Version-Release number of selected component (if applicable):
vsftpd-2.2.2-13.el6_6.1.x86_64

How reproducible:

Steps to Reproduce:

Enviornment,
Red Hat Enterprise Linux Server release 6.6 (Santiago)
vsftpd-2.2.2-13.el6_6.1.x86_64

1: Enable syslog and add userlist settings to vsftpd.conf configuration file :
cat >>/etc/vsftpd/vsftpd.conf <<EOF

userlist_log=yes
userlist_deny=NO
syslog_enable=yes
EOF

2: Disable wu-ftpd style transfer log :
sed -i 's/^xferlog_std_format=YES/xferlog_std_format=NO/' /etc/vsftpd/vsftpd.conf

3: Add ftp facility to /etc/rsyslog.conf configuration file :
sed -i '/local7/a\\nftp.*    \/var\/log\/vsftpd.log' /etc/rsyslog.conf

4: service rsyslog restart ; service vsftpd restart

5: Verify that user "toto" is not in /etc/vsftpd/user_list

grep -c toto /etc/vsftpd/user_list
0

6: Check test login:
ftp localhost
Trying ::1...
Connected to localhost (127.0.0.1).
220 (vsFTPd 2.2.2)
Name (localhost:root): toto
530 Permission denied.
Login failed.
ftp> bye

7: verify that nothing has been logged in /var/log/vsftpd.log

grep -c toto /var/log/vsftpd.log

0


8:  Revert syslog_enable to default value (NO) :

sed -i 's/^syslog_enable/#&/' /etc/vsftpd/vsftpd.conf
service vsftpd restart

ftp localhost
Trying 127.0.0.1...
Connected to localhost (127.0.0.1).
220 (vsFTPd 2.2.2)
Name (localhost:root): toto
530 Permission denied.
Login failed.
ftp> bye

verify that "User is not in the allow user list." message is logged 

cat /var/log/vsftpd.log

[toto] FAIL LOGIN: Client "127.0.0.1", "User is not in the allow user list."

Conclusion :
When syslog is enabled, a message which would have gone to /var/log/vsftpd.log doesn’t go to the system log instead

Note:Also setting xferlog_std_format to YES, "User is not in the allow user list." message is not logged to /var/log/xferlog.

--- Additional comment from Tomas Hozza on 2016-02-24 12:36:25 CET ---

The issue is with syslog in general, so no log messages are print from the child process which handles the client.

When new client connects, new child process is forked to handle it. The child process opens necessary files (like user_list, ...) initializes logging (in case of other means than syslog it opens the files), then it drops privileges and calls setrlimit(RLIMIT_NOFILE, {rlim_cur=0, rlim_max=0}) = 0. This means that the process will not be able to open any new file descriptors.

When syslog is used, during the logging initialization in child process, the openlog() is called. However the LOG_NDELAY is not set as option, which means that the /dev/log socket will be opened with first call to syslog() to log some message. openlog() is called before the setrlimit() call, but the first syslog() call is done after the setrlimit() call.

In the source, the syslog() function is called correctly, however inside the function the opening of new socket fails due to previously set LIMIT_NOFILE.

This can be investigated by using the ltrace and strace tools. The snippet from strace when following the child process:

...
[pid  2668] chroot(".")                 = 0
[pid  2668] setrlimit(RLIMIT_NOFILE, {rlim_cur=0, rlim_max=0}) = 0
[pid  2668] setgid(99)                  = 0
[pid  2668] setuid(99)                  = 0
[pid  2668] setrlimit(RLIMIT_NPROC, {rlim_cur=0, rlim_max=0}) = 0
[pid  2668] rt_sigaction(SIGALRM, {0x7f8a421d8490, ~[RTMIN RT_1], SA_RESTORER, 0x7f8a40f93660}, NULL, 8) = 0
[pid  2668] alarm(300)                  = 0
[pid  2668] gettimeofday({1456313069, 206740}, NULL) = 0
[pid  2668] socket(PF_LOCAL, SOCK_DGRAM|SOCK_CLOEXEC, 0) = -1 EMFILE (Too many open files)
[pid  2668] write(0, "220 (vsFTPd 2.2.2)\r\n", 20) = 20
...

You can see that the creation of the socket used for logging fails with EMFILE.

The solution is to call openlog() with option LOG_NDELAY. This will assure, that the socket is opened before the call to setrlimit() and the logging then works just fine.