I'm setting up SFTP for a group of users I want to only have SFTP access, for the purposes of uploading files to the server. I already have them jailed to their own home directories, and have blocked shell logins. Each home directory has a subfolder for receiving uploads. I would like SFTP connections to automatically change to this upload folder on login. Pretty standard.
I am using the ForceCommand
directive to achieve this successfully on an old server. However, on the new server I'm currently preparing, this is not working. Why?
/etc/ssh/sshd_config.d/sftpgroup.conf
Match Group ftpgroup
# The following two directives force ftpgroup to become chrooted
# and only have SFTP available. No other chroot setup is required.
ChrootDirectory /home/ftp_users/%u
ForceCommand internal-sftp -u 0002
# For additional paranoia, disallow all types of port forwardings.
AllowTcpForwarding no
GatewayPorts no
X11Forwarding no
# Force local logging
ForceCommand /usr/lib/openssh/sftp-server -l VERBOSE
# Change default directory to ~/upload
ForceCommand cd /upload
/var/log/auth.log with LogLevel DEBUG3
Mar 9 15:18:03 MyServer sshd[393644]: debug1: userauth-request for user myuser service ssh-connection method none [preauth]
Mar 9 15:18:03 MyServer sshd[393644]: debug1: attempt 0 failures 0 [preauth]
Mar 9 15:18:03 MyServer sshd[393644]: debug3: mm_getpwnamallow entering [preauth]
Mar 9 15:18:03 MyServer sshd[393644]: debug3: mm_request_send entering: type 8 [preauth]
Mar 9 15:18:03 MyServer sshd[393644]: debug3: mm_getpwnamallow: waiting for MONITOR_ANS_PWNAM [preauth]
Mar 9 15:18:03 MyServer sshd[393644]: debug3: mm_request_receive_expect entering: type 9 [preauth]
Mar 9 15:18:03 MyServer sshd[393644]: debug3: mm_request_receive entering [preauth]
Mar 9 15:18:03 MyServer sshd[393644]: debug3: mm_request_receive entering
Mar 9 15:18:03 MyServer sshd[393644]: debug3: monitor_read: checking request 8
Mar 9 15:18:03 MyServer sshd[393644]: debug3: mm_answer_pwnamallow
Mar 9 15:18:03 MyServer sshd[393644]: debug2: parse_server_config_depth: config reprocess config len 383
Mar 9 15:18:03 MyServer sshd[393644]: debug2: parse_server_config_depth: config /etc/ssh/sshd_config.d/sftpgroup.conf len 228
Mar 9 15:18:03 MyServer sshd[393644]: debug3: checking match for 'Group ftpgroup,!sftpgroup' user myuser host 1.2.3.4 addr 1.2.3.4 laddr 10.0.0.4 lport 22
Mar 9 15:18:03 MyServer sshd[393644]: debug1: user myuser does not match group list ftpgroup,!sftpgroup at line 4
Mar 9 15:18:03 MyServer sshd[393644]: debug3: match not found
Mar 9 15:18:03 MyServer sshd[393644]: debug3: checking match for 'Group ftpgroup' user myuser host 1.2.3.4 addr 1.2.3.4 laddr 10.0.0.4 lport 22
Mar 9 15:18:03 MyServer sshd[393644]: debug1: user myuser matched group list ftpgroup at line 9
Mar 9 15:18:03 MyServer sshd[393644]: debug3: match found
Mar 9 15:18:03 MyServer sshd[393644]: debug3: /etc/ssh/sshd_config.d/sftpgroup.conf:12 setting ChrootDirectory /home/ftp_users/%u
Mar 9 15:18:03 MyServer sshd[393644]: debug3: /etc/ssh/sshd_config.d/sftpgroup.conf:13 setting ForceCommand internal-sftp -u 0002
Mar 9 15:18:03 MyServer sshd[393644]: debug3: /etc/ssh/sshd_config.d/sftpgroup.conf:15 setting AllowTcpForwarding no
Mar 9 15:18:03 MyServer sshd[393644]: debug3: /etc/ssh/sshd_config.d/sftpgroup.conf:16 setting GatewayPorts no
Mar 9 15:18:03 MyServer sshd[393644]: debug3: /etc/ssh/sshd_config.d/sftpgroup.conf:17 setting X11Forwarding no
Mar 9 15:18:03 MyServer sshd[393644]: debug3: /etc/ssh/sshd_config.d/sftpgroup.conf:21 setting ForceCommand cd /upload
Mar 9 15:18:03 MyServer sshd[393644]: debug3: mm_answer_pwnamallow: sending MONITOR_ANS_PWNAM: 1
Mar 9 15:18:03 MyServer sshd[393644]: debug3: mm_request_send entering: type 9
Mar 9 15:18:03 MyServer sshd[393644]: debug2: monitor_read: 8 used once, disabling now
Mar 9 15:18:03 MyServer sshd[393644]: debug2: input_userauth_request: setting up authctxt for myuser [preauth]
Mar 9 15:18:03 MyServer sshd[393644]: debug3: mm_start_pam entering [preauth]
Mar 9 15:18:03 MyServer sshd[393644]: debug3: mm_request_send entering: type 100 [preauth]
Mar 9 15:18:03 MyServer sshd[393644]: debug3: mm_inform_authserv entering [preauth]
Mar 9 15:18:03 MyServer sshd[393644]: debug3: mm_request_send entering: type 4 [preauth]
Mar 9 15:18:03 MyServer sshd[393644]: debug2: input_userauth_request: try method none [preauth]
Mar 9 15:18:03 MyServer sshd[393644]: debug3: user_specific_delay: user specific delay 0.000ms [preauth]
Mar 9 15:18:03 MyServer sshd[393644]: debug3: ensure_minimum_time_since: elapsed 2.862ms, delaying 4.136ms (requested 6.998ms) [preauth]
Mar 9 15:18:03 MyServer sshd[393644]: debug3: mm_request_receive entering
Mar 9 15:18:03 MyServer sshd[393644]: debug3: monitor_read: checking request 100
Mar 9 15:18:03 MyServer sshd[393644]: debug1: PAM: initializing for "myuser"
Mar 9 15:18:03 MyServer sshd[393644]: debug1: PAM: setting PAM_RHOST to "1.2.3.4"
Mar 9 15:18:03 MyServer sshd[393644]: debug1: PAM: setting PAM_TTY to "ssh"
Mar 9 15:18:03 MyServer sshd[393644]: debug2: monitor_read: 100 used once, disabling now
Mar 9 15:18:03 MyServer sshd[393644]: debug3: mm_request_receive entering
Mar 9 15:18:03 MyServer sshd[393644]: debug3: monitor_read: checking request 4
Mar 9 15:18:03 MyServer sshd[393644]: debug3: mm_answer_authserv: service=ssh-connection, style=, role=
Mar 9 15:18:03 MyServer sshd[393644]: debug2: monitor_read: 4 used once, disabling now
Mar 9 15:18:03 MyServer sshd[393644]: debug3: userauth_finish: failure partial=0 next methods="publickey,password" [preauth]
Mar 9 15:18:03 MyServer sshd[393644]: debug3: send packet: type 51 [preauth]
Mar 9 15:18:03 MyServer sshd[393644]: debug3: receive packet: type 2 [preauth]
Mar 9 15:18:03 MyServer sshd[393644]: debug3: Received SSH2_MSG_IGNORE [preauth]
Mar 9 15:18:03 MyServer sshd[393644]: debug3: receive packet: type 50 [preauth]
Mar 9 15:18:03 MyServer sshd[393644]: debug1: userauth-request for user myuser service ssh-connection method password [preauth]
Mar 9 15:18:03 MyServer sshd[393644]: debug1: attempt 1 failures 0 [preauth]
Mar 9 15:18:03 MyServer sshd[393644]: debug2: input_userauth_request: try method password [preauth]
Mar 9 15:18:03 MyServer sshd[393644]: debug3: mm_auth_password entering [preauth]
Mar 9 15:18:03 MyServer sshd[393644]: debug3: mm_request_send entering: type 12 [preauth]
Mar 9 15:18:03 MyServer sshd[393644]: debug3: mm_auth_password: waiting for MONITOR_ANS_AUTHPASSWORD [preauth]
Mar 9 15:18:03 MyServer sshd[393644]: debug3: mm_request_receive_expect entering: type 13 [preauth]
Mar 9 15:18:03 MyServer sshd[393644]: debug3: mm_request_receive entering [preauth]
Mar 9 15:18:03 MyServer sshd[393644]: debug3: mm_request_receive entering
Mar 9 15:18:03 MyServer sshd[393644]: debug3: monitor_read: checking request 12
Mar 9 15:18:03 MyServer sshd[393644]: debug3: PAM: sshpam_passwd_conv called with 1 messages
Mar 9 15:18:03 MyServer sshd[393644]: debug1: PAM: password authentication accepted for myuser
Mar 9 15:18:03 MyServer sshd[393644]: debug3: mm_answer_authpassword: sending result 1
Mar 9 15:18:03 MyServer sshd[393644]: debug3: mm_request_send entering: type 13
Mar 9 15:18:03 MyServer sshd[393644]: debug3: mm_request_receive_expect entering: type 102
Mar 9 15:18:03 MyServer sshd[393644]: debug3: mm_request_receive entering
Mar 9 15:18:03 MyServer sshd[393644]: debug1: do_pam_account: called
Mar 9 15:18:03 MyServer sshd[393644]: debug2: do_pam_account: auth information in SSH_AUTH_INFO_0
Mar 9 15:18:03 MyServer sshd[393644]: debug3: PAM: do_pam_account pam_acct_mgmt = 0 (Success)
Mar 9 15:18:03 MyServer sshd[393644]: debug3: mm_request_send entering: type 103
Mar 9 15:18:03 MyServer sshd[393644]: Accepted password for myuser from 1.2.3.4 port 55095 ssh2
Mar 9 15:18:03 MyServer sshd[393644]: debug1: monitor_child_preauth: myuser has been authenticated by privileged process
Mar 9 15:18:03 MyServer sshd[393644]: debug3: mm_get_keystate: Waiting for new keys
Mar 9 15:18:03 MyServer sshd[393644]: debug3: mm_request_receive_expect entering: type 26
Mar 9 15:18:03 MyServer sshd[393644]: debug3: mm_request_receive entering
Mar 9 15:18:03 MyServer sshd[393644]: debug3: mm_get_keystate: GOT new keys
Mar 9 15:18:03 MyServer sshd[393644]: debug3: mm_auth_password: user authenticated [preauth]
Mar 9 15:18:03 MyServer sshd[393644]: debug3: user_specific_delay: user specific delay 0.000ms [preauth]
Mar 9 15:18:03 MyServer sshd[393644]: debug3: ensure_minimum_time_since: elapsed 7.172ms, delaying 6.825ms (requested 6.998ms) [preauth]
Mar 9 15:18:03 MyServer sshd[393644]: debug3: mm_do_pam_account entering [preauth]
Mar 9 15:18:03 MyServer sshd[393644]: debug3: mm_request_send entering: type 102 [preauth]
Mar 9 15:18:03 MyServer sshd[393644]: debug3: mm_request_receive_expect entering: type 103 [preauth]
Mar 9 15:18:03 MyServer sshd[393644]: debug3: mm_request_receive entering [preauth]
Mar 9 15:18:03 MyServer sshd[393644]: debug3: mm_do_pam_account returning 1 [preauth]
Mar 9 15:18:03 MyServer sshd[393644]: debug3: send packet: type 52 [preauth]
Mar 9 15:18:03 MyServer sshd[393644]: debug3: mm_request_send entering: type 26 [preauth]
Mar 9 15:18:03 MyServer sshd[393644]: debug3: mm_send_keystate: Finished sending state [preauth]
Mar 9 15:18:03 MyServer sshd[393644]: debug1: monitor_read_log: child log fd closed
Mar 9 15:18:03 MyServer sshd[393644]: debug3: ssh_sandbox_parent_finish: finished
Mar 9 15:18:03 MyServer sshd[393644]: debug1: PAM: establishing credentials
Mar 9 15:18:03 MyServer sshd[393644]: debug3: PAM: opening session
Mar 9 15:18:03 MyServer sshd[393644]: debug2: do_pam_session: auth information in SSH_AUTH_INFO_0
Mar 9 15:18:03 MyServer sshd[393644]: pam_unix(sshd:session): session opened for user myuser(uid=1001) by (uid=0)
Mar 9 15:18:03 MyServer systemd-logind[607]: New session 530 of user myuser.
Mar 9 15:18:03 MyServer systemd: pam_unix(systemd-user:session): session opened for user myuser(uid=1001) by (uid=0)
Mar 9 15:18:03 MyServer sshd[393644]: debug3: PAM: sshpam_store_conv called with 1 messages
Mar 9 15:18:03 MyServer sshd[393644]: debug3: PAM: sshpam_store_conv called with 1 messages
Mar 9 15:18:03 MyServer sshd[393644]: User child is on pid 393672
Mar 9 15:18:03 MyServer sshd[393672]: debug1: SELinux support disabled
Mar 9 15:18:03 MyServer sshd[393672]: debug1: PAM: establishing credentials
Mar 9 15:18:03 MyServer sshd[393672]: debug3: safely_chroot: checking '/'
Mar 9 15:18:03 MyServer sshd[393672]: debug3: safely_chroot: checking '/home/'
Mar 9 15:18:03 MyServer sshd[393672]: debug3: safely_chroot: checking '/home/ftp_users/'
Mar 9 15:18:03 MyServer sshd[393672]: debug3: safely_chroot: checking '/home/ftp_users/myuser'
Mar 9 15:18:04 MyServer sshd[393644]: debug3: mm_request_receive entering
Mar 9 15:18:04 MyServer sshd[393644]: debug3: monitor_read: checking request 113
Mar 9 15:18:04 MyServer sshd[393644]: debug3: mm_answer_audit_command entering
ssh -V
Old server:
- OpenSSH_7.9p1 Debian-10+deb10u2, OpenSSL 1.1.1d 10 Sep 2019
New Server:
- OpenSSH_8.4p1 Debian-5, OpenSSL 1.1.1k 25 Mar 2021
Update
It turns out on the old system this was actually working because of manipulated home folders and symlinks, rather than because of the ForceCommand
directive on that system (even though that directive exists).
ln -s /home/ftp_users/myuser /home/myuser
usermod -d /home/myuser myuser
ln -s ../upload /home/ftp_users/myuser/home/myuser
So when a user logs in and changes to ~
it goes to /home/myuser
which is a symlink for /upload
. When matching the home folder setup with the old system, the new system now routes properly on login. Bit hackish, and definitely suboptimal (was trying to avoid it tbh), but it "works."
So then the question becomes, why doesn't ForceCommand
override this? Is it executing at all? How can I tell?