mjhjmtu

Background

I have a custom service file I created for running SSHD - used for SFTP. It doesn't change a whole lot from the default SSHD configuration, mainly just changing the port number and chroot'ing a specific user group.

I also have the native SSH service running, so I have two service files relating to SSH: The default one that provides SSH connectivity on port 22, and the custom one I made that provides SFTP connectivity on port 2222.

Contents of sftp-server.service:

[Unit]
Description=Local SFTP Server
Documentation=file://etc/ssh/sftp_config
Requires=network.target

[Service]
Type=forking
ExecStart=/usr/sbin/sshd -f /etc/ssh/sftp_config
ExecStop=/bin/kill -9 $MAINPID
SendSIGHUP=yes

[Install]
WantedBy=multi-user.target

Problem

Attempting to start this service using systemd fails due to a timeout systemctl start sftp-server gives me the following error:

Job for sftp-server.service failed because a timeout was exceeded. See "systemctl status sftp-server.service" and "journalctl -xe" for details.

Troubleshooting

SELinux

1. I have allowed ssh_port_t on port 2222 and 22


2. I do not see any SELinux/AVC denials for this service


3. I have ssh_chroot_rw_homedirs on


4. I performed sealert -a /var/log/audit/audit.log and it found 0 alerts

Logging

journalctl -u sftp-server output:

Jan 22 08:00:08 sftp1 systemd[1]: Starting Local SFTP Server...
Jan 22 08:00:08 sftp1 sshd[28112]: Server listening on 0.0.0.0 port 2222.
Jan 22 08:00:08 sftp1 sshd[28112]: Server listening on :: port 2222.
Jan 22 08:01:38 sftp1 systemd[1]: sftp-server.service start operation timed out. Terminating.
Jan 22 08:01:38 sftp1 sshd[28112]: Received signal 15; terminating.
Jan 22 08:01:38 sftp1 systemd[1]: Failed to start Local SFTP Server.
Jan 22 08:01:38 sftp1 systemd[1]: Unit sftp-server.service entered failed state.
Jan 22 08:01:38 sftp1 systemd[1]: sftp-server.service failed.

journalctl -xe output:

-- Unit sftp-server.service has begun starting up.
Jan 22 08:16:17 sftp1 sshd[28527]: Server listening on 0.0.0.0 port 2222.
Jan 22 08:16:17 sftp1 sshd[28527]: Server listening on :: port 2222.
Jan 22 08:17:01 sftp1 audispd[1059]: node=sftp1 type=USER_ACCT msg=audit(1516630621.631:151588): pid=28528 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:crond_t:s0-s0:c0.c1023 msg='op=PAM:accounting grantors=pam_access,
Jan 22 08:17:01 sftp1 audispd[1059]: node=sftp1 type=USER_ACCT msg=audit(1516630621.631:151587): pid=28529 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:crond_t:s0-s0:c0.c1023 msg='op=PAM:accounting grantors=pam_access,
Jan 22 08:17:01 sftp1 audispd[1059]: node=sftp1 type=CRED_ACQ msg=audit(1516630621.631:151589): pid=28528 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:crond_t:s0-s0:c0.c1023 msg='op=PAM:setcred grantors=pam_env,pam_uni
Jan 22 08:17:01 sftp1 audispd[1059]: node=sftp1 type=CRED_ACQ msg=audit(1516630621.631:151590): pid=28529 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:crond_t:s0-s0:c0.c1023 msg='op=PAM:setcred grantors=pam_env,pam_uni
Jan 22 08:17:01 sftp1 audispd[1059]: node=sftp1 type=LOGIN msg=audit(1516630621.632:151591): pid=28528 uid=0 subj=system_u:system_r:crond_t:s0-s0:c0.c1023 old-auid=4294967295 auid=0 tty=(none) old-ses=4294967295 ses=13414 res=1
Jan 22 08:17:01 sftp1 audispd[1059]: node=sftp1 type=LOGIN msg=audit(1516630621.632:151592): pid=28529 uid=0 subj=system_u:system_r:crond_t:s0-s0:c0.c1023 old-auid=4294967295 auid=0 tty=(none) old-ses=4294967295 ses=13415 res=1
Jan 22 08:17:01 sftp1 systemd[1]: Started Session 13415 of user root.
-- Subject: Unit session-13415.scope has finished start-up
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
--
-- Unit session-13415.scope has finished starting up.
--
-- The start-up result is done.
Jan 22 08:17:01 sftp1 systemd[1]: Starting Session 13415 of user root.
-- Subject: Unit session-13415.scope has begun start-up
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
--
-- Unit session-13415.scope has begun starting up.
Jan 22 08:17:01 sftp1 systemd[1]: Started Session 13414 of user root.
-- Subject: Unit session-13414.scope has finished start-up
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
--
-- Unit session-13414.scope has finished starting up.
--
-- The start-up result is done.
Jan 22 08:17:01 sftp1 systemd[1]: Starting Session 13414 of user root.
-- Subject: Unit session-13414.scope has begun start-up
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
--
-- Unit session-13414.scope has begun starting up.
Jan 22 08:17:01 sftp1 audispd[1059]: node=sftp1 type=USER_START msg=audit(1516630621.660:151593): pid=28528 uid=0 auid=0 ses=13414 subj=system_u:system_r:crond_t:s0-s0:c0.c1023 msg='op=PAM:session_open grantors=pam_loginuid,pam_keyin
Jan 22 08:17:01 sftp1 audispd[1059]: node=sftp1 type=USER_START msg=audit(1516630621.660:151594): pid=28529 uid=0 auid=0 ses=13415 subj=system_u:system_r:crond_t:s0-s0:c0.c1023 msg='op=PAM:session_open grantors=pam_loginuid,pam_keyin
Jan 22 08:17:01 sftp1 audispd[1059]: node=sftp1 type=CRED_REFR msg=audit(1516630621.661:151595): pid=28528 uid=0 auid=0 ses=13414 subj=system_u:system_r:crond_t:s0-s0:c0.c1023 msg='op=PAM:setcred grantors=pam_env,pam_unix acct="root"
Jan 22 08:17:01 sftp1 audispd[1059]: node=sftp1 type=CRED_REFR msg=audit(1516630621.661:151596): pid=28529 uid=0 auid=0 ses=13415 subj=system_u:system_r:crond_t:s0-s0:c0.c1023 msg='op=PAM:setcred grantors=pam_env,pam_unix acct="root"
Jan 22 08:17:01 sftp1 CROND[28533]: (root) CMD (/usr/lib64/sa/sa1 1 1)
Jan 22 08:17:01 sftp1 audispd[1059]: node=sftp1 type=CRED_DISP msg=audit(1516630621.691:151597): pid=28528 uid=0 auid=0 ses=13414 subj=system_u:system_r:crond_t:s0-s0:c0.c1023 msg='op=PAM:setcred grantors=pam_env,pam_unix acct="root"
Jan 22 08:17:01 sftp1 audispd[1059]: node=sftp1 type=USER_END msg=audit(1516630621.694:151598): pid=28528 uid=0 auid=0 ses=13414 subj=system_u:system_r:crond_t:s0-s0:c0.c1023 msg='op=PAM:session_close grantors=pam_loginuid,pam_keyini
Jan 22 08:17:03 sftp1 audispd[1059]: node=sftp1 type=CRED_DISP msg=audit(1516630623.091:151599): pid=28529 uid=0 auid=0 ses=13415 subj=system_u:system_r:crond_t:s0-s0:c0.c1023 msg='op=PAM:setcred grantors=pam_env,pam_unix acct="root"
Jan 22 08:17:03 sftp1 postfix/pickup[27708]: 16A7421C: uid=0 from=<root>
Jan 22 08:17:03 sftp1 postfix/cleanup[26382]: 16A7421C: message-id=<20180122141703.16A7421C@localhost>
Jan 22 08:17:03 sftp1 audispd[1059]: node=sftp1 type=USER_END msg=audit(1516630623.094:151600): pid=28529 uid=0 auid=0 ses=13415 subj=system_u:system_r:crond_t:s0-s0:c0.c1023 msg='op=PAM:session_close grantors=pam_loginuid,pam_keyini
Jan 22 08:17:03 sftp1 postfix/qmgr[1787]: 16A7421C: from=<root@localhost>, size=861, nrcpt=1 (queue active)
Jan 22 08:17:03 sftp1 postfix/local[26384]: 16A7421C: to=<root@localhost>, orig_to=<root>, relay=local, delay=1, delays=1/0/0/0.01, dsn=2.0.0, status=sent (delivered to mailbox)
Jan 22 08:17:03 sftp1 postfix/qmgr[1787]: 16A7421C: removed
Jan 22 08:17:47 sftp1 systemd[1]: sftp-server.service start operation timed out. Terminating.
Jan 22 08:17:47 sftp1 sshd[28527]: Received signal 15; terminating.
Jan 22 08:17:47 sftp1 audispd[1059]: node=sftp1 type=CRYPTO_KEY_USER msg=audit(1516630667.931:151601): pid=28527 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:sshd_t:s0-s0:c0.c1023 msg='op=destroy kind=server fp=SHA256:
Jan 22 08:17:47 sftp1 audispd[1059]: node=sftp1 type=CRYPTO_KEY_USER msg=audit(1516630667.931:151602): pid=28527 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:sshd_t:s0-s0:c0.c1023 msg='op=destroy kind=server fp=SHA256:
Jan 22 08:17:47 sftp1 audispd[1059]: node=sftp1 type=CRYPTO_KEY_USER msg=audit(1516630667.931:151603): pid=28527 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:sshd_t:s0-s0:c0.c1023 msg='op=destroy kind=server fp=SHA256:
Jan 22 08:17:47 sftp1 systemd[1]: Failed to start Local SFTP Server.
-- Subject: Unit sftp-server.service has failed
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
--
-- Unit sftp-server.service has failed.

Manual Testing

Running /usr/sbin/sshd -d -f /etc/ssh/sftp_config does not yield any errors:

debug1: sshd version OpenSSH_7.4, OpenSSL 1.0.2k-fips 26 Jan 2017
[output omitted]
debug1: rexec_argv[0]='/usr/sbin/sshd'
debug1: rexec_argv[1]='-df'
debug1: rexec_argv[2]='/etc/ssh/sftp_config'
debug1: Set /proc/self/oom_score_adj from 0 to -1000
debug1: Bind to port 2222 on 0.0.0.0.
Server listening on 0.0.0.0 port 2222.
debug1: Bind to port 2222 on ::.
Server listening on :: port 2222.