openssh-5.0p1: sftp transfer logging doesn't appear to work with chroot environment

[john]

Hi all,

I am running Debian Etch. I've compiled openssh-5.0p1 with pam
support. I'd like to use a chrooted sftp environment for my users and
also log their sftp file transfers. Currently file transfer logging
stops working when I implement a jail.  Logging from within the chroot
seems like a useful feature. I hope it makes it in sooner rather than
later.

Here's the contents of my sshd_config:

Protocol 2
SyslogFacility AUTH
LogLevel VERBOSE
PermitRootLogin no
MaxAuthTries 3
UsePAM yes
ChrootDirectory /home
Subsystem       sftp    internal-sftp -l VERBOSE -f AUTH


When I run sshd without the ChrootDirectory declaration sftp logging
in /var/log/AUTH looks like:

May  1 14:26:59 slocker sshd[7502]: Server listening on :: port 22.
May  1 14:26:59 slocker sshd[7502]: Server listening on 0.0.0.0 port 22.
May  1 14:27:05 slocker sshd[7503]: Connection from 10.1.3.233 port 60419
May  1 14:27:05 slocker sshd[7503]: Failed none for flyboy2 from
10.1.3.233 port 60419 ssh2
May  1 14:27:05 slocker sshd[7503]: Failed publickey for flyboy2 from
10.1.3.233 port 60419 ssh2
May  1 14:27:06 slocker pam_winbind[7505]: user 'flyboy2' granted access
May  1 14:27:06 slocker pam_winbind[7505]: user 'flyboy2' OK
May  1 14:27:06 slocker pam_winbind[7505]: user 'flyboy2' granted access
May  1 14:27:06 slocker sshd[7503]: Accepted keyboard-interactive/pam
for flyboy2 from 10.1.3.233 port 60419 ssh2
May  1 14:27:06 slocker sshd[7503]: (pam_unix) session opened for user
flyboy2 by (uid=0)
May  1 14:27:06 slocker sshd[7506]: subsystem request for sftp
May  1 14:27:06 slocker internal-sftp[7507]: session opened for local
user flyboy2 from [10.1.3.233]
May  1 14:27:06 slocker internal-sftp[7507]: received client version 3
May  1 14:27:23 slocker internal-sftp[7507]: realpath "/home/flyboy2"
May  1 14:27:23 slocker internal-sftp[7507]: stat name "/home/flyboy2"
May  1 14:27:27 slocker internal-sftp[7507]: lstat name "/home/flyboy2/z.ico"
May  1 14:27:27 slocker internal-sftp[7507]: stat name "/home/flyboy2/z.ico"
May  1 14:27:27 slocker internal-sftp[7507]: open
"/home/flyboy2/z.ico" flags READ mode 0666
May  1 14:27:27 slocker internal-sftp[7507]: close
"/home/flyboy2/z.ico" bytes read 7110 written 0
May  1 14:27:31 slocker internal-sftp[7507]: open
"/home/flyboy2/z.ico" flags WRITE,CREATE,TRUNCATE mode 0700
May  1 14:27:31 slocker internal-sftp[7507]: close
"/home/flyboy2/z.ico" bytes read 0 written 7110



When I add the ChrootDirectory  stanza the logs fail to note the same
sort of file transfers:

May  1 14:23:00 slocker sshd[7464]: Server listening on :: port 22.
May  1 14:23:00 slocker sshd[7464]: Server listening on 0.0.0.0 port 22.
May  1 14:23:12 slocker sshd[7322]: (pam_unix) session closed for user flyboy2
May  1 14:23:14 slocker sshd[7465]: Connection from 10.1.3.233 port 60819
May  1 14:23:14 slocker sshd[7465]: Failed none for flyboy2 from
10.1.3.233 port 60819 ssh2
May  1 14:23:14 slocker sshd[7465]: Failed publickey for flyboy2 from
10.1.3.233 port 60819 ssh2
May  1 14:23:16 slocker pam_winbind[7467]: user 'flyboy2' granted access
May  1 14:23:16 slocker pam_winbind[7467]: user 'flyboy2' OK
May  1 14:23:16 slocker pam_winbind[7467]: user 'flyboy2' granted access
May  1 14:23:16 slocker sshd[7465]: Accepted keyboard-interactive/pam
for flyboy2 from 10.1.3.233 port 60819 ssh2
May  1 14:23:16 slocker sshd[7465]: (pam_unix) session opened for user
flyboy2 by (uid=0)
May  1 14:23:16 slocker sshd[7468]: Changed root directory to "/home"

Thanks!

John