SFTP Access Trouble After Update

I’ve been trying to figure out this ssh connection issue when using an SFTP source hosted locally. This was working perfectly until I did an update (hasn’t been done in over a year, but was moving things around after getting a new TV).

Context for the logs… SSH access from “my.host.com” to osmc (Pi 2) via forwarded port 22. The SSH client and host are the same machine.

I can access via ssh and sftp, without issues. I seems like the ssh connection that kodi is trying to establish uses different connection settings than /usr/bin/ssh?

20:49:03 osmc@osmc ~ $ sftp osmc@my.host.com
Connected to my.host.com.
sftp>

OK… on to the logs:

/home/osmc/.kodi/temp/kodi.log:
20:16:58.585 T:1423213536 ERROR: SFTPSession: Failed to connect ‘PRNG error’
20:16:58.586 T:1423213536 ERROR: SFTPSession: Not connected, can’t list directory ‘home/osmc/path/to/directory’
20:16:58.586 T:1423213536 ERROR: GetDirectory - Error getting sftp://USERNAME:PASSWORD@my.host.com:22/home/osmc/path/to/directory
20:16:58.601 T:1423213536 ERROR: SFTPSession: Not connected, can’t list directory 'home/osmc/path/to/directory
20:16:58.601 T:1423213536 ERROR: GetDirectory - Error getting sftp://USERNAME:PASSWORD@my.host.com:22/home/osmc/path/to/directory
20:16:58.608 T:1423213536 ERROR: SFTPSession: Not connected and can’t create file handle for 'home/osmc/path/to/directory/media.mp4
20:16:58.609 T:1423213536 ERROR: Open - failed to open source <sftp://USERNAME:PASSWORD@my.host.com:22/home/osmc/path/to/directory/media.mp4
20:16:58.609 T:1423213536 ERROR: CVideoPlayer::OpenInputStream - error opening [sftp://USERNAME:PASSWORD@my.host.com:22/home/osmc/path/to/directory/media.mp4]
20:16:58.609 T:1423213536 NOTICE: CVideoPlayer::OnExit()
20:16:58.610 T:1958875136 ERROR: PlayMedia could not play media: sftp://@my.host.com:22/home/osmc/path/to/directory/media.mp4
20:16:58.612 T:1958875136 NOTICE: CVideoPlayer::CloseFile()
20:16:58.612 T:1958875136 NOTICE: VideoPlayer: waiting for threads to exit
20:16:58.612 T:1958875136 NOTICE: VideoPlayer: finished waiting
20:16:58.613 T:1958875136 NOTICE: CVideoPlayer::CloseFile()
20:16:58.613 T:1958875136 NOTICE: VideoPlayer: waiting for threads to exit
20:16:58.613 T:1958875136 NOTICE: VideoPlayer: finished waiting

/var/sys/auth.log:
Sep 21 20:16:58 osmc sshd[897]: debug1: Forked child 6741.
Sep 21 20:16:58 osmc sshd[6741]: Set /proc/self/oom_score_adj to 0
Sep 21 20:16:58 osmc sshd[6741]: debug1: rexec start in 5 out 5 newsock 5 pipe 7 sock 8
Sep 21 20:16:58 osmc sshd[6741]: debug1: inetd sockets after dupping: 3, 3
Sep 21 20:16:58 osmc sshd[6741]: Connection from 192.168.1.1 port 33702 on 192.168.1.2 port 22
Sep 21 20:16:58 osmc sshd[6741]: debug1: Client protocol version 2.0; client software version libssh-0.6.3
Sep 21 20:16:58 osmc sshd[6741]: debug1: no match: libssh-0.6.3
Sep 21 20:16:58 osmc sshd[6741]: debug1: Enabling compatibility mode for protocol 2.0
Sep 21 20:16:58 osmc sshd[6741]: debug1: Local version string SSH-2.0-OpenSSH_6.7p1 Debian-5+deb8u3
Sep 21 20:16:58 osmc sshd[6741]: debug1: permanently_set_uid: 108/65534 [preauth]
Sep 21 20:16:58 osmc sshd[6741]: debug1: ssh_sandbox_child: prctl(PR_SET_SECCOMP): Invalid argument [preauth]
Sep 21 20:16:58 osmc sshd[6741]: debug1: list_hostkey_types: ssh-rsa,ecdsa-sha2-nistp256,ssh-ed25519 [preauth]
Sep 21 20:16:58 osmc sshd[6741]: debug1: SSH2_MSG_KEXINIT sent [preauth]
Sep 21 20:16:58 osmc sshd[6741]: debug1: SSH2_MSG_KEXINIT received [preauth]
Sep 21 20:16:58 osmc sshd[6741]: debug1: kex: client->server aes256-ctr hmac-sha1 none [preauth]
Sep 21 20:16:58 osmc sshd[6741]: debug1: kex: server->client aes256-ctr hmac-sha1 none [preauth]
Sep 21 20:16:58 osmc sshd[6741]: debug1: expecting SSH2_MSG_KEX_ECDH_INIT [preauth]
Sep 21 20:16:58 osmc sshd[6741]: Connection closed by 192.168.1.1 [preauth]
Sep 21 20:16:58 osmc sshd[6741]: debug1: do_cleanup [preauth]
Sep 21 20:16:58 osmc sshd[6741]: debug1: monitor_read_log: child log fd closed
Sep 21 20:16:58 osmc sshd[6741]: debug1: do_cleanup
Sep 21 20:16:58 osmc sshd[6741]: debug1: Killing privsep child 6742

Thanks for any insight! I’ve been digging through logs and trying to figure this for a couple days.

In march the weaker encryption modes were disabled, maybe that is your problem. If that is the case you would need to update your sftp client

This looks odd, did you change the log to “path/to/directory”? If not than that seems to be your problem.

Right, I’ve tried commenting the sshd_config lines specifying the encryption modes also, to attempt to workaround it temporarily. The thing I don’t get though is that the sftp client on the machine can login perfectly fine as shown by the clipped text in my first post. Is there a separate sftp client that kodi uses?

sudo apt-get install openssh-server openssh-sftp-server openssh-client -s
Reading package lists… Done
Building dependency tree
Reading state information… Done
openssh-client is already the newest version.
openssh-client set to manually installed.
openssh-server is already the newest version.
openssh-sftp-server is already the newest version.

You caught me me lol… just trying to make the logs more readable and get rid of the super long paths… figured it was irrelevant as I can’t even add the SFTP source without running into this.

This now confuses me, are you using Kodi on your client machine to access files via SFTP on your OSMC machine?

It’s a little unconventional but works really nicely, let me try to explain my setup:

                  Internet
                       |
osmc (pi2) --------- router ----- PC (win, kodi)
  -mysql db            |
              livingroom (pi3, running osmc)

The Pi with hostname osmc is both the client and server.

osmc is running a MySQL server to serve the media databases, it scans it’s local USB drive via SFTP, so that the MySQL database has the sftp paths instead of paths referenced locally.

PC and livingroom query the mysql db’s on osmc to get latest media & watched status and access it via the SFTP paths found by osmc.

Any reason why you don’t use SMB instead of SFTP?

So if I understand correctly the ‘shared’ files are located on the OSMC Pi2 with MySQL?

Just that I’d prefer not to open a samba port to the internet for remote access.

Yes, you understand it correctly.

So you are also sharing the files to another Kodi on the internet?

On occasion yes, but sort of getting on a tangent here and I already have an SSH port forwarded to login in remotely, so rather than open another port I’d prefer to just have the one.

I can’t sftp from osmc to itself within kodi, yet I can from a terminal.

I think I understand now. Your SFTP client is Kodi. And it’s scanning files on the local system (Pi2) using SFTP, correct?

Just a warning about how you are currently using it, if you are using Kodi on a system on the Internet, be warned that opening MySQL port 3306 is not the safest thing to do.

Have you updated all your OSMC devices successfully to the latest version?

Well to figure out if it is a algorithm problem you could temporarily add
diffie-hellman-group1-sha1 to KexAlgorithms and hmac-sha1 to MACs

I just tried an experiment on my Pi2 running the latest OSMC. And I was able to create a SFTP:// source and see the media.

What does your sources.xml look like?

you got it bmillham.

Thanks for the warning, but I use it a bit differently remotely with a separate kodi profile that scans by sftp directly.

~/.kodi/userdata/sources.xml:

  1 <sources>
  2     <programs>
  3         <default pathversion="1"></default>
  4     </programs>
  5     <video>
  6         <default pathversion="1"></default>
  7         <source>
  8             <name>Media</name>
  9             <path pathversion="1">sftp://USER:PASS@my.host.com:22/home/osmc/media/</path>
 10             <allowsharing>true</allowsharing>
 11         </source>
 12     </video>
 13     <music>
 14         <default pathversion="1"></default>
 15     </music>
 16     <pictures>
 17         <default pathversion="1"></default>
 18     </pictures>
 19     <files>
 20         <default pathversion="1"></default>
 21         <source>
 22             <name>osmc</name>
 23             <path pathversion="1">/home/osmc/</path>
 24             <allowsharing>true</allowsharing>
 25         </source>
 26     </files>
 27 </sources>

If you are using it without the DB remotely, then you could use SMB locally for the MySQL connected clients.

But as I said, using SFTP seems to work for me, so we need to find why it isn’t for you.

Ok, the source looks fine, assuming that the files are stored on your SD card, and not on a USB drive.

~/media is a symlink to a USB device.

Confirmed that I am able to play video from osmc via SFTP on my Linux laptop running Kodi 17.1.

What about from the the other OSMC Pi3?

I’m thinking that the upgrade was not complete, and you may want to do a fresh install.

Yeah… I was really trying to avoid that, but we’ll see…

Unfortunately the livingroom pi3, faced some USB file system corruption the other day, all the files are still recoverable by fsck, but the file system structure was lost and everything is in lost+found. So that one is getting a new SD card and a fresh install on Saturday.

Here is the sshd auth.log from the successful connection, which looks identical up to:
Sep 21 22:43:41 osmc sshd[15240]: debug1: SSH2_MSG_NEWKEYS sent [preauth]

auth.log:
Sep 21 22:43:40 osmc sshd[897]: debug1: Forked child 15240.
Sep 21 22:43:40 osmc sshd[15240]: Set /proc/self/oom_score_adj to 0
Sep 21 22:43:40 osmc sshd[15240]: debug1: rexec start in 5 out 5 newsock 5 pipe 7 sock 8
Sep 21 22:43:41 osmc sshd[15240]: debug1: inetd sockets after dupping: 3, 3
Sep 21 22:43:41 osmc sshd[15240]: Connection from 192.168.1.1 port 47272 on 192.168.1.2 port 22
Sep 21 22:43:41 osmc sshd[15240]: debug1: Client protocol version 2.0; client software version libssh-0.6.3
Sep 21 22:43:41 osmc sshd[15240]: debug1: no match: libssh-0.6.3
Sep 21 22:43:41 osmc sshd[15240]: debug1: Enabling compatibility mode for protocol 2.0
Sep 21 22:43:41 osmc sshd[15240]: debug1: Local version string SSH-2.0-OpenSSH_6.7p1 Debian-5+deb8u3
Sep 21 22:43:41 osmc sshd[15240]: debug1: permanently_set_uid: 108/65534 [preauth]
Sep 21 22:43:41 osmc sshd[15240]: debug1: ssh_sandbox_child: prctl(PR_SET_SECCOMP): Invalid argument [preauth]
Sep 21 22:43:41 osmc sshd[15240]: debug1: list_hostkey_types: ssh-rsa,ecdsa-sha2-nistp256,ssh-ed25519 [preauth]
Sep 21 22:43:41 osmc sshd[15240]: debug1: SSH2_MSG_KEXINIT sent [preauth]
Sep 21 22:43:41 osmc sshd[15240]: debug1: SSH2_MSG_KEXINIT received [preauth]
Sep 21 22:43:41 osmc sshd[15240]: debug1: kex: client->server aes256-ctr hmac-sha1 none [preauth]
Sep 21 22:43:41 osmc sshd[15240]: debug1: kex: server->client aes256-ctr hmac-sha1 none [preauth]
Sep 21 22:43:41 osmc sshd[15240]: debug1: expecting SSH2_MSG_KEX_ECDH_INIT [preauth]
Sep 21 22:43:41 osmc sshd[15240]: debug1: SSH2_MSG_NEWKEYS sent [preauth]
Sep 21 22:43:41 osmc sshd[15240]: debug1: expecting SSH2_MSG_NEWKEYS [preauth]
Sep 21 22:43:41 osmc sshd[15240]: debug1: SSH2_MSG_NEWKEYS received [preauth]
Sep 21 22:43:41 osmc sshd[15240]: debug1: KEX done [preauth]
Sep 21 22:43:41 osmc sshd[15240]: debug1: userauth-request for user osmc service ssh-connection method none [preauth]
Sep 21 22:43:41 osmc sshd[15240]: debug1: attempt 0 failures 0 [preauth]
Sep 21 22:43:41 osmc sshd[15240]: debug1: PAM: initializing for “osmc”
Sep 21 22:43:41 osmc sshd[15240]: debug1: PAM: setting PAM_RHOST to “192.168.1.1”
Sep 21 22:43:41 osmc sshd[15240]: debug1: PAM: setting PAM_TTY to “ssh”
Sep 21 22:43:41 osmc sshd[15240]: debug1: userauth-request for user osmc service ssh-connection method publickey [preauth]
Sep 21 22:43:41 osmc sshd[15240]: debug1: attempt 1 failures 0 [preauth]
Sep 21 22:43:41 osmc sshd[15240]: debug1: test whether pkalg/pkblob are acceptable [preauth]
Sep 21 22:43:41 osmc sshd[15240]: debug1: temporarily_use_uid: 1000/1000 (e=0/0)
Sep 21 22:43:41 osmc sshd[15240]: debug1: trying public key file /home/osmc/.ssh/authorized_keys
Sep 21 22:43:41 osmc sshd[15240]: debug1: fd 4 clearing O_NONBLOCK
Sep 21 22:43:41 osmc sshd[15240]: debug1: matching key found: file /home/osmc/.ssh/authorized_keys, line 6
Sep 21 22:43:41 osmc sshd[15240]: debug1: restore_uid: 0/0
Sep 21 22:43:41 osmc sshd[15240]: Postponed publickey for osmc from 192.168.1.1 port 47272 ssh2 [preauth]
Sep 21 22:43:41 osmc sshd[15240]: debug1: userauth-request for user osmc service ssh-connection method publickey [preauth]
Sep 21 22:43:41 osmc sshd[15240]: debug1: attempt 2 failures 0 [preauth]
Sep 21 22:43:41 osmc sshd[15240]: debug1: temporarily_use_uid: 1000/1000 (e=0/0)
Sep 21 22:43:41 osmc sshd[15240]: debug1: trying public key file /home/osmc/.ssh/authorized_keys
Sep 21 22:43:41 osmc sshd[15240]: debug1: fd 4 clearing O_NONBLOCK
Sep 21 22:43:41 osmc sshd[15240]: debug1: matching key found: file /home/osmc/.ssh/authorized_keys
Sep 21 22:43:41 osmc sshd[15240]: debug1: restore_uid: 0/0
Sep 21 22:43:41 osmc sshd[15240]: debug1: do_pam_account: called
Sep 21 22:43:41 osmc sshd[15240]: Accepted publickey for osmc from 192.168.1.1 port 47272 ssh2
Sep 21 22:43:41 osmc sshd[15240]: debug1: monitor_child_preauth: osmc has been authenticated by privileged process
Sep 21 22:43:41 osmc sshd[15240]: debug1: monitor_read_log: child log fd closed
Sep 21 22:43:41 osmc sshd[15240]: debug1: PAM: establishing credentials
Sep 21 22:43:41 osmc sshd[15240]: pam_unix(sshd:session): session opened for user osmc by (uid=0)

How about trying this on the Pi2. Rename /home/osmc/.ssh to /home/osmc/.ssh-save and reboot.

See if that helps.