SFTP close connection after authorisation

HWSW_eng · July 31, 2018, 3:59pm

Hi,

I’m new to rockstor and fight the hole day to keep the sftp connection running but without luck…

To my setup:

Rockstor is running on an Intel Machine (nativly without VM) and fixed IP address
on my firewall appliance / router (OpnSense) I have configured two port forwardings from two custom ports on the WAN side to 443 for the GUI and 22 for SSH / SFTP
access was tested from remote side with windows machines using the clients WinSCP, MobaXterm and Cyberduck (all with the same result)

What is working:

Access of the Rockstor GUI
establishing a SSH session with putty, but unfortunately I haven’t the root passwort present (only from the second admin account on the GUI) therefore I can only verify until the password promt

What was done for user creation:

setting up a user with his one group
create a share within the pool created during instalation (rockstor_rockstor)
setting the user as owner of the share
add a sftp share to the obove created share and enable the SFTP Service

The result:
Win SCP connect to the server, checking the password and username garant access and than the server disconnects the connection.

Following an part from the ftp client log file:

. 2018-07-31 14:29:05.521 Opening session as main channel
. 2018-07-31 14:29:05.521 Waiting for the server to continue with the initialization
. 2018-07-31 14:29:05.521 Looking for incoming data
. 2018-07-31 14:29:05.521 Looking for network events
. 2018-07-31 14:29:05.540 Detected network event
. 2018-07-31 14:29:05.540 Enumerating network events for socket 1844
. 2018-07-31 14:29:05.540 Enumerated 1 network events making 1 cumulative events for socket 1844
. 2018-07-31 14:29:05.540 Handling network read event on socket 1844 with error 0
. 2018-07-31 14:29:05.540 Opened main channel
. 2018-07-31 14:29:05.541 Waiting for the server to continue with the initialization
. 2018-07-31 14:29:05.541 Looking for incoming data
. 2018-07-31 14:29:05.541 Looking for network events
. 2018-07-31 14:29:05.621 Detected network event
. 2018-07-31 14:29:05.621 Enumerating network events for socket 1844
. 2018-07-31 14:29:05.621 Enumerated 1 network events making 1 cumulative events for socket 1844
. 2018-07-31 14:29:05.621 Handling network read event on socket 1844 with error 0
. 2018-07-31 14:29:05.621 Started a shell/command
. 2018-07-31 14:29:05.651 --------------------------------------------------------------------------
. 2018-07-31 14:29:05.651 Using SFTP protocol.
. 2018-07-31 14:29:05.651 Doing startup conversation with host.
. 2018-07-31 14:29:05.652 Session upkeep
. 2018-07-31 14:29:05.652 Looking for network events
. 2018-07-31 14:29:05.652 Detected network event
. 2018-07-31 14:29:05.652 Enumerating network events for socket 1844
. 2018-07-31 14:29:05.652 Enumerated 1 network events making 1 cumulative events for socket 1844
. 2018-07-31 14:29:05.652 Handling network read event on socket 1844 with error 0
. 2018-07-31 14:29:05.652 Server sent command exit status 127
. 2018-07-31 14:29:05.652 Selecting events 0 for socket 1844
. 2018-07-31 14:29:05.652 Disconnected: All channels closed

2018-07-31 14:29:05.783 (EFatal)

I have found that some persons had a solution by changing the SFTP server protocoll options but that has no effect for the issue.

Did I miss something?
From my understanding SFTP only uses the port 22 or is there any other port required?

Any help would be appreciate.

Best regards,
Philipp

HWSW_eng · August 9, 2018, 9:20pm

I have test to access the sftp share on the local LAN in order to check if the firewall or the port forwarding cause the problem. But the problem presist

What the hell could cause that issue?

vesper1978 · August 9, 2018, 11:42pm

@HWSW_eng,

Can you run the following from the shell on your RockStor sever after making another SFTP connection attempt:

grep -i sftp /var/log/audit/audit.log

Then paste the results in a response here.

Thanks,

Jason

HWSW_eng · August 13, 2018, 9:03am

Hi Jason,

the log file contains the following:

type=DAEMON_START msg=audit(1534150227.500:3355): op=start ver=2.6.5 format=raw kernel=4.10.6-1.el7.elrepo.x86_64 auid=4294967295 pid=3516 res=success
type=SERVICE_START msg=audit(1534150227.577:4): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=dbus comm=“systemd” exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? $
type=SERVICE_START msg=audit(1534150227.580:5): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=irqbalance comm=“systemd” exe="/usr/lib/systemd/systemd" hostname=? addr=? termi$
type=SERVICE_START msg=audit(1534150227.581:6): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=smartd comm=“systemd” exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=$
type=SERVICE_START msg=audit(1534150227.593:7): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=yum-cron comm=“systemd” exe="/usr/lib/systemd/systemd" hostname=? addr=? termina$
type=SERVICE_START msg=audit(1534150227.612:8): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=rhel-dmesg comm=“systemd” exe="/usr/lib/systemd/systemd" hostname=? addr=? termi$
type=SERVICE_START msg=audit(1534150227.648:9): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-logind comm=“systemd” exe="/usr/lib/systemd/systemd" hostname=? addr=? t$
type=SERVICE_START msg=audit(1534150227.724:10): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=chronyd comm=“systemd” exe="/usr/lib/systemd/systemd" hostname=? addr=? termina$
type=SERVICE_START msg=audit(1534150227.757:11): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=avahi-daemon comm=“systemd” exe="/usr/lib/systemd/systemd" hostname=? addr=? te$
type=SERVICE_START msg=audit(1534150227.857:12): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=gssproxy comm=“systemd” exe="/usr/lib/systemd/systemd" hostname=? addr=? termin$
type=SERVICE_START msg=audit(1534150227.864:13): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-user-sessions comm=“systemd” exe="/usr/lib/systemd/systemd" hostname=? $
type=SERVICE_START msg=audit(1534150227.866:14): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=crond comm=“systemd” exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=$
type=SERVICE_START msg=audit(1534150227.872:15): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=atd comm=“systemd” exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? $
type=SERVICE_START msg=audit(1534150227.940:16): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=plymouth-quit-wait comm=“systemd” exe="/usr/lib/systemd/systemd" hostname=? add$
type=SERVICE_STOP msg=audit(1534150227.940:17): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=plymouth-quit-wait comm=“systemd” exe="/usr/lib/systemd/systemd" hostname=? addr$
type=SERVICE_START msg=audit(1534150227.941:18): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=plymouth-quit comm=“systemd” exe="/usr/lib/systemd/systemd" hostname=? addr=? t$
type=SERVICE_STOP msg=audit(1534150227.941:19): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=plymouth-quit comm=“systemd” exe="/usr/lib/systemd/systemd" hostname=? addr=? te$
type=SERVICE_START msg=audit(1534150227.942:20): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=plymouth-start comm=“systemd” exe="/usr/lib/systemd/systemd" hostname=? addr=? $
type=SERVICE_STOP msg=audit(1534150227.942:21): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=plymouth-start comm=“systemd” exe="/usr/lib/systemd/systemd" hostname=? addr=? t$
type=SERVICE_START msg=audit(1534150227.945:22): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=getty@tty1 comm=“systemd” exe="/usr/lib/systemd/systemd" hostname=? addr=? term$
type=SERVICE_START msg=audit(1534150227.963:23): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=NetworkManager comm=“systemd” exe="/usr/lib/systemd/systemd" hostname=? addr=? $
type=SERVICE_START msg=audit(1534150227.982:24): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=NetworkManager-dispatcher comm=“systemd” exe="/usr/lib/systemd/systemd" hostnam$
type=SERVICE_START msg=audit(1534150228.029:25): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-hostnamed comm=“systemd” exe="/usr/lib/systemd/systemd" hostname=? addr$
type=SERVICE_START msg=audit(1534150228.207:26): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=polkit comm=“systemd” exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal$
type=SERVICE_START msg=audit(1534150228.293:27): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=sshd-keygen comm=“systemd” exe="/usr/lib/systemd/systemd" hostname=? addr=? ter$
type=SERVICE_STOP msg=audit(1534150231.085:28): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=sshd-keygen comm=“systemd” exe="/usr/lib/systemd/systemd" hostname=? addr=? term$
type=SERVICE_START msg=audit(1534150236.662:29): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=NetworkManager-wait-online comm=“systemd” exe="/usr/lib/systemd/systemd" hostna$
type=SERVICE_START msg=audit(1534150237.168:30): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=network comm=“systemd” exe="/usr/lib/systemd/systemd" hostname=? addr=? termina$
type=SERVICE_START msg=audit(1534150237.203:31): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=sshd comm=“systemd” exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=?$
type=SERVICE_START msg=audit(1534150237.207:32): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=rpc-statd-notify comm=“systemd” exe="/usr/lib/systemd/systemd" hostname=? addr=$
type=SERVICE_STOP msg=audit(1534150237.207:33): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=rpc-statd-notify comm=“systemd” exe="/usr/lib/systemd/systemd" hostname=? addr=?$
type=CRED_ACQ msg=audit(1534150237.347:34): pid=3911 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:setcred grantors=pam_rootok acct=“postgres” exe="/usr/sbin/runuser" hostname=? $
type=USER_START msg=audit(1534150237.368:35): pid=3911 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:session_open grantors=pam_keyinit,pam_systemd,pam_keyinit,pam_limits,pam_unix$
type=SERVICE_START msg=audit(1534150237.625:36): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=postfix comm=“systemd” exe="/usr/lib/systemd/systemd" hostname=? addr=? termina$
$ermina$type=DAEMON_START msg=audit(1534150227.500:3355): op=start ver=2.6.5 format=raw kernel=4.10.6-1.el7.elrepo.x86_64 auid=4294967295 pid=3516 res=success

Thank you for your help!

vesper1978 · August 13, 2018, 11:06am

I don’t see any login attempts at all. Are you sure you did this right after an sftp login attempt?

Try your sftp connection again, and this time run:

grep -i user /var/log/audit/audit.log

This time replace “user” with the user you are trying to connect as.

HWSW_eng · August 27, 2018, 11:26am

Sorry for the late reply, I was on a business trip the last weeks.
Indeed I have posted the old logfile and missed to save the right one

But I have just for testing turned on and off the sftp service, and since than it works just fine. The intresting thing is that rebooting the hole server doesn’t solve the issue… (and yes the sftp service was active…)

Maybe I have the chance later to figure out what caused the first issue.

scob7 · March 12, 2019, 1:46am

I just ran into this same issue after a fresh install and following the guide for setting up sftp shares. I was pulling my hair out until I read this and then stopped and restarted the sftp service. Connections went from EOF errors using cyberduck and “Connection closed” using Duplicati to magically working. Definitely a bug in adding new sftp shares.

Rockstor version 3.9.1-0