CentOS - Sep 2015 - rsyslog for chrooted sftp users has stopped working -- Centos 6.6

Hello everyone,

We have some chrooted sftp-only users on a CentOS release 6.6 server. The
server had been logging their actions, but after recent updates the logs
have stopped.

The server correctly logs non-chrooted users:

    Sep 14 17:47:24 vsecure4 sshd[1981]: Accepted publickey for jcours from
192.168.10.166 port 42545 ssh2
    Sep 14 17:47:24 vsecure4 sshd[1981]: pam_unix(sshd:session): session
opened for user jcours by (uid=0)
    Sep 14 17:47:24 vsecure4 sshd[1983]: subsystem request for sftp
    Sep 14 17:47:24 vsecure4 internal-sftp[1984]: session opened for local
user jcours from [192.168.10.166]
    Sep 14 17:47:24 vsecure4 internal-sftp[1984]: opendir
"/home/jcours"
    Sep 14 17:47:24 vsecure4 internal-sftp[1984]: closedir
"/home/jcours"
    Sep 14 17:47:49 vsecure4 internal-sftp[1984]: session closed for local
user jcours from [192.168.10.166]
    Sep 14 17:47:19 vsecure4 sshd[1977]: pam_unix(sshd:session): session
closed for user jcours

but log messages for chrooted users do not appear:

    Sep 14 17:08:11 vsecure4 sshd[1730]: Accepted publickey for
test-sftp-only from 192.168.10.166 port 41723 ssh2
    Sep 14 17:08:11 vsecure4 sshd[1730]: pam_unix(sshd:session): session
opened for user test-sftp-only by (uid=0)
    Sep 14 17:08:11 vsecure4 sshd[1734]: subsystem request for sftp
    Sep 14 17:08:22 vsecure4 sshd[1730]: pam_unix(sshd:session): session
closed for user test-sftp-only

Notice that there are no "opendir" or "closedir" messages
for the chrooted
user, or anything else from the internal-sftp system, for that matter.

/etc/sshd_config contains these settings:

    Subsystem sftp internal-sftp -f AUTHPRIV -l INFO

    Match User test-sftp-only
          ChrootDirectory /home/sftp/mcsosftp
          ForceCommand internal-sftp
          PasswordAuthentication no
          AuthorizedKeysCommand /usr/local/bin/get_sftp_key

We've been setting up chrooted logging using this sequence:

    sudo mkdir /home/sftp/mcsosftp/dev
    sudo touch /home/sftp/mcsosftp/dev/log
    sudo chattr +i /home/sftp/mcsosftp/dev
    sudo mount --bind /dev/log /home/sftp/mcsosftp/dev/log

/etc/rsyslog.conf includes the standard stuff for authpriv:

    # The authpriv file has restricted access.
    authpriv.*                                              /var/log/secure

I've tried forcing rsyslog.conf to listen to /dev/log:

    # We should be listening here.
    $SystemLogSocketName /dev/log

I've also tried removing the hard-mounted /home/sftp/mcsosftp/dev/log and
instead using this in /etc/rsyslog.conf:

    # For chrooted users, generally sftp-only users.
    $AddUnixListenSocket /home/sftp/mcsosftp/dev/log

Neither approach seemed to help the problem, though rsyslogd does appear to
be listening to the sockets:

    $ sudo lsof -c rsyslogd | grep dev/log
    lsof: WARNING: can't stat() devtmpfs file system /home/sftp/dev/log
(deleted)
          Output information may be incomplete.
    rsyslogd 1963 root    0u  unix 0xdc100040      0t0      15419 /dev/log
    rsyslogd 1963 root    3u  unix 0xdbd27dc0      0t0      15421
/home/sftp/mcsosftp/dev/log

and file identifies both as sockets:

    $ file /dev/log
    /dev/log: socket

    $ sudo file /home/sftp/mcsosftp/dev/log
    /home/sftp/mcsosftp/dev/log: socket

Here's additional system info for the development server I'm using to
debug
the problem:

    $ ls -l /dev/log
    srw-rw-rw- 1 root root 0 Sep 14 17:43 /dev/log

    $ sudo ls -l /home/sftp/mcsosftp/dev/log
    srw-rw-rw- 1 root root 0 Sep 14 17:43 /home/sftp/mcsosftp/dev/log

    $ ls -l /dev | grep log
    srw-rw-rw- 1 root root           0 Sep 14 17:43 log
    crw-rw---- 1 root root     10, 227 Sep 14 15:23 mcelog

    $ sudo ls -l /home/sftp/mcsosftp/dev | grep log
    srw-rw-rw- 1 root root 0 Sep 14 17:43 log

    $ cat /etc/redhat-release
    CentOS release 6.6 (Final)

    $ sestatus
    SELinux status:                 disabled

    $ grep test-sftp-only /etc/passwd
    test-sftp-only:x:507:507:Test SFTP
Only:/home/sftp/mcsosftp:/sbin/nologin

    $ sudo yum list installed | egrep -E 'rsyslog|ssh|sftp'
    libssh2.i686           1.4.2-1.el6_6.1    @updates
    openssh.i686           5.3p1-104.el6_6.1  @updates
    openssh-clients.i686   5.3p1-104.el6_6.1  @updates
    openssh-server.i686    5.3p1-104.el6_6.1  @updates
    rsyslog.i686           5.8.10-10.el6_6    @updates
    vsftpd.i686            2.2.2-14.el6       @base

Corresponding packages on the production server showing the same problem:

    $ sudo yum list installed | egrep -E 'rsyslog|ssh|sftp'
    libssh2.x86_64                         1.4.2-1.el6_6.1
@system-updates
    openssh.x86_64                         5.3p1-112.el6_7
@system-updates
    openssh-clients.x86_64                 5.3p1-112.el6_7
@system-updates
    openssh-server.x86_64                  5.3p1-112.el6_7
@system-updates
    rsyslog.x86_64                         5.8.10-10.el6_6
@system-updates
    rsyslog-gnutls.x86_64                  5.8.10-10.el6_6
@system-updates


Does anyone have any ideas what the problem could be or how to diagnose it?

Thanks very much in advance,
Jeff

And no sooner do I send the email than I spot the problem. Oops! Sorry
about that.

The sshd_config needed to contain a different internal-sftp line:

    Match User test-sftp-only
          ChrootDirectory /home/sftp/mcsosftp
          ForceCommand internal-sftp -f AUTHPRIV -l INFO
          PasswordAuthentication no
          AuthorizedKeysCommand /usr/local/bin/get_sftp_key

That's gotten the test server working.

Unfortunately, the production server already has that setting, so it's back
to eliminating differences.

Jeff


On Mon, Sep 14, 2015 at 6:32 PM, Jeff Cours <jtcours.bulk at gmail.com>
wrote:
> Hello everyone,
>
> We have some chrooted sftp-only users on a CentOS release 6.6 server. The
> server had been logging their actions, but after recent updates the logs
> have stopped.
>
> The server correctly logs non-chrooted users:
>
>     Sep 14 17:47:24 vsecure4 sshd[1981]: Accepted publickey for jcours
> from 192.168.10.166 port 42545 ssh2
>     Sep 14 17:47:24 vsecure4 sshd[1981]: pam_unix(sshd:session): session
> opened for user jcours by (uid=0)
>     Sep 14 17:47:24 vsecure4 sshd[1983]: subsystem request for sftp
>     Sep 14 17:47:24 vsecure4 internal-sftp[1984]: session opened for local
> user jcours from [192.168.10.166]
>     Sep 14 17:47:24 vsecure4 internal-sftp[1984]: opendir
"/home/jcours"
>     Sep 14 17:47:24 vsecure4 internal-sftp[1984]: closedir
"/home/jcours"
>     Sep 14 17:47:49 vsecure4 internal-sftp[1984]: session closed for local
> user jcours from [192.168.10.166]
>     Sep 14 17:47:19 vsecure4 sshd[1977]: pam_unix(sshd:session): session
> closed for user jcours
>
> but log messages for chrooted users do not appear:
>
>     Sep 14 17:08:11 vsecure4 sshd[1730]: Accepted publickey for
> test-sftp-only from 192.168.10.166 port 41723 ssh2
>     Sep 14 17:08:11 vsecure4 sshd[1730]: pam_unix(sshd:session): session
> opened for user test-sftp-only by (uid=0)
>     Sep 14 17:08:11 vsecure4 sshd[1734]: subsystem request for sftp
>     Sep 14 17:08:22 vsecure4 sshd[1730]: pam_unix(sshd:session): session
> closed for user test-sftp-only
>
> Notice that there are no "opendir" or "closedir"
messages for the chrooted
> user, or anything else from the internal-sftp system, for that matter.
>
> /etc/sshd_config contains these settings:
>
>     Subsystem sftp internal-sftp -f AUTHPRIV -l INFO
>
>     Match User test-sftp-only
>           ChrootDirectory /home/sftp/mcsosftp
>           ForceCommand internal-sftp
>           PasswordAuthentication no
>           AuthorizedKeysCommand /usr/local/bin/get_sftp_key
>
> We've been setting up chrooted logging using this sequence:
>
>     sudo mkdir /home/sftp/mcsosftp/dev
>     sudo touch /home/sftp/mcsosftp/dev/log
>     sudo chattr +i /home/sftp/mcsosftp/dev
>     sudo mount --bind /dev/log /home/sftp/mcsosftp/dev/log
>
> /etc/rsyslog.conf includes the standard stuff for authpriv:
>
>     # The authpriv file has restricted access.
>     authpriv.*                                              /var/log/secure
>
> I've tried forcing rsyslog.conf to listen to /dev/log:
>
>     # We should be listening here.
>     $SystemLogSocketName /dev/log
>
> I've also tried removing the hard-mounted /home/sftp/mcsosftp/dev/log
and
> instead using this in /etc/rsyslog.conf:
>
>     # For chrooted users, generally sftp-only users.
>     $AddUnixListenSocket /home/sftp/mcsosftp/dev/log
>
> Neither approach seemed to help the problem, though rsyslogd does appear
> to be listening to the sockets:
>
>     $ sudo lsof -c rsyslogd | grep dev/log
>     lsof: WARNING: can't stat() devtmpfs file system /home/sftp/dev/log
> (deleted)
>           Output information may be incomplete.
>     rsyslogd 1963 root    0u  unix 0xdc100040      0t0      15419 /dev/log
>     rsyslogd 1963 root    3u  unix 0xdbd27dc0      0t0      15421
> /home/sftp/mcsosftp/dev/log
>
> and file identifies both as sockets:
>
>     $ file /dev/log
>     /dev/log: socket
>
>     $ sudo file /home/sftp/mcsosftp/dev/log
>     /home/sftp/mcsosftp/dev/log: socket
>
> Here's additional system info for the development server I'm using
to
> debug the problem:
>
>     $ ls -l /dev/log
>     srw-rw-rw- 1 root root 0 Sep 14 17:43 /dev/log
>
>     $ sudo ls -l /home/sftp/mcsosftp/dev/log
>     srw-rw-rw- 1 root root 0 Sep 14 17:43 /home/sftp/mcsosftp/dev/log
>
>     $ ls -l /dev | grep log
>     srw-rw-rw- 1 root root           0 Sep 14 17:43 log
>     crw-rw---- 1 root root     10, 227 Sep 14 15:23 mcelog
>
>     $ sudo ls -l /home/sftp/mcsosftp/dev | grep log
>     srw-rw-rw- 1 root root 0 Sep 14 17:43 log
>
>     $ cat /etc/redhat-release
>     CentOS release 6.6 (Final)
>
>     $ sestatus
>     SELinux status:                 disabled
>
>     $ grep test-sftp-only /etc/passwd
>     test-sftp-only:x:507:507:Test SFTP
> Only:/home/sftp/mcsosftp:/sbin/nologin
>
>     $ sudo yum list installed | egrep -E 'rsyslog|ssh|sftp'
>     libssh2.i686           1.4.2-1.el6_6.1    @updates
>     openssh.i686           5.3p1-104.el6_6.1  @updates
>     openssh-clients.i686   5.3p1-104.el6_6.1  @updates
>     openssh-server.i686    5.3p1-104.el6_6.1  @updates
>     rsyslog.i686           5.8.10-10.el6_6    @updates
>     vsftpd.i686            2.2.2-14.el6       @base
>
> Corresponding packages on the production server showing the same problem:
>
>     $ sudo yum list installed | egrep -E 'rsyslog|ssh|sftp'
>     libssh2.x86_64                         1.4.2-1.el6_6.1
> @system-updates
>     openssh.x86_64                         5.3p1-112.el6_7
> @system-updates
>     openssh-clients.x86_64                 5.3p1-112.el6_7
> @system-updates
>     openssh-server.x86_64                  5.3p1-112.el6_7
> @system-updates
>     rsyslog.x86_64                         5.8.10-10.el6_6
> @system-updates
>     rsyslog-gnutls.x86_64                  5.8.10-10.el6_6
> @system-updates
>
>
> Does anyone have any ideas what the problem could be or how to diagnose it?
>
> Thanks very much in advance,
> Jeff
>
>

On 09/14/2015 06:49 PM, Jeff Cours wrote:
> Unfortunately, the production server already has that setting, so it's
back
> to eliminating differences.
Log in to one of the chroot accounts, and while that session is open, 
check all of that user's processes in /proc.  Specifically, I'd check 
/proc/<pid>/{root,cwd,fd}

Also check selinux enforcing on both hosts, and the SELinux attributes 
of the chroot dir, its dev directory and its log socket.