sftp chroot RELENG_14 vs RELENG_13 broken?

From: mike tancsa <mike_at_sentex.net>
Date: Tue, 05 Mar 2024 21:03:35 UTC
Hi all,

     Trying to stand up a new vm with RELENG_14 and cant for some reason 
get chrooted logging working with the sftp server built into the base 
openssh.

On a RELENG_13 box, the following config works


Match user testuser1
    ChrootDirectory %h
    ForceCommand internal-sftp -f local1 -l verbose
    AllowTcpForwarding no
    PermitTunnel no
    X11Forwarding no
    PermitTTY no

and I have full logging of what the client sends as commands to the server.

e.g.

Mar  5 15:30:03 vm1c sshd[70518]: Received disconnect from 127.0.0.1 
port 18574:11: disconnected by user
Mar  5 15:30:03 vm1c sshd[70518]: Disconnected from user testuser1 
127.0.0.1 port 18574
Mar  5 15:32:33 vm1c sshd[70459]: Received signal 15; terminating.
Mar  5 15:32:33 vm1c sshd[70659]: Server listening on 127.0.0.1 port 22.
Mar  5 15:32:33 vm1c sshd[70659]: Server listening on 10.187.2.97 port 22.
Mar  5 15:32:35 vm1c sshd[70662]: Connection from 127.0.0.1 port 14265 
on 127.0.0.1 port 22
Mar  5 15:32:35 vm1c sshd[70662]: Accepted key RSA SHA256:nh.. found at 
/home/testuser1/.ssh/authorized_keys:2
Mar  5 15:32:35 vm1c sshd[70662]: Postponed publickey for testuser1 from 
127.0.0.1 port 14265 ssh2 [preauth]
Mar  5 15:32:36 vm1c sshd[70662]: Accepted key RSA SHA256:nh.. found at 
/home/testuser1/.ssh/authorized_keys:2
Mar  5 15:32:36 vm1c sshd[70662]: Accepted publickey for testuser1 from 
127.0.0.1 port 14265 ssh2: RSA SHA256:nh....
Mar  5 15:32:36 vm1c sshd[70662]: User child is on pid 70664
Mar  5 15:32:36 vm1c sshd[70664]: Starting session: forced-command 
(config) 'internal-sftp -f local1 -l verbose' for testuser1 from 
127.0.0.1 port 14265 id 0
Mar  5 15:32:36 vm1c internal-sftp[70665]: session opened for local user 
testuser1 from [127.0.0.1]
Mar  5 15:32:36 vm1c internal-sftp[70665]: received client version 3
Mar  5 15:32:36 vm1c internal-sftp[70665]: realpath "."
Mar  5 15:32:37 vm1c internal-sftp[70665]: opendir "/home/testuser1"
Mar  5 15:32:37 vm1c internal-sftp[70665]: closedir "/home/testuser1"
Mar  5 15:32:37 vm1c internal-sftp[70665]: users-groups-by-id: 4 users, 
0 groups
Mar  5 15:32:37 vm1c internal-sftp[70665]: session closed for local user 
testuser1 from [127.0.0.1]

In /home/testuser1, I have /dev/ and a hard link to the log socket on 
the same partition

# pwd
/home/testuser1/dev

# ln /home/var/run/log .

and syslog was started as so

syslogd -s -p /var/run/log -p /home/var/run/log


However, on RELENG14 I cant get any sftp commands to log if I chroot the 
daemon

The last messages I see are

Mar  5 15:37:55 vm1c sshd[71034]: Accepted key RSA SHA256:nh.. found at 
/home/testuser1/.ssh/authorized_keys:2
Mar  5 15:37:55 vm1c sshd[71034]: Accepted publickey for testuser1 from 
127.0.0.1 port 30728 ssh2: RSA SHA256:nhi..

I dont see the "Starting session: forced-command" line ever logged.

I tried creating a simple RELENG_13 jail on the RELENG14 box and I see 
the same behaviour. So I am guessing its not something in userland ?  If 
so, any ideas what it might be ?

     ---Mike