Primitive-ftpd shuts down unexpectedly with InterruptedIOException when listing specific files.

This report is for primitive-ftpd 6.11 code57, running on Samsung Galaxy Tab S7 (SM-T733), with Android 12. The tablet is rooted, and primitive-ftpd is using the Super User storage type.

When an SFTP client (Beyond Compare) scans the tablet's file system (either internal or extSD) and lists the files of an app called Mobile Sheets Pro (by Zubersoft), primitive-ftpd fails with the InterruptedIOException when a specific file is listed. From the point of view of the client, the server just stops responding.

I have enabled logging in primitive-ftpd, and present below the a portion of the logs where the client is recursively listing the server's file system and building a list of files to transfer. Here is the log of the last file name that before the failure:

"2022-06-18 03:14:48.0";"DEBUG";"org.apache.sshd.server.sftp.SftpSubsystem";"Received SSH_FXP_OPENDIR (path=/storage/emulated/0/Android/data/com.zubersoft.mobilesheetspro/fil...";"";
"2022-06-18 03:14:48.0";"TRACE";"org.primftpd.filesystem.RootSshFileSystemView";"getNormalizedView()";"";
"2022-06-18 03:14:48.0";"TRACE";"org.primftpd.filesystem.RootSshFileSystemView";"getFile(/storage/emulated/0/Android/data/com.zubersoft.mobilesheetspro/files/Your Love Never Fail...";"";
"2022-06-18 03:14:48.0";"TRACE";"org.primftpd.filesystem.RootSshFileSystemView";"  getFile(abs: /storage/emulated/0/Android/data/com.zubersoft.mobilesheetspro/files/Your Love Nev...";"";
"2022-06-18 03:14:48.0";"TRACE";"org.primftpd.filesystem.RootSshFileSystemView";"  running command: ls -lad "/storage/emulated/0/Android/data/com.zubersoft.mobilesheetspro/files/...";"";
"2022-06-18 03:14:48.0";"TRACE";"org.primftpd.filesystem.RootSshFile";"[Your Love Never Fails (B)] doesExist() -> false";"";
"2022-06-18 03:14:48.0";"DEBUG";"org.apache.sshd.server.sftp.SftpSubsystem";"Send SSH_FXP_STATUS (substatus=2, msg=/storage/emulated/0/Android/data/com.zubersoft.mobilesheets...";"";
"2022-06-18 03:14:48.0";"TRACE";"org.apache.sshd.server.channel.ChannelSession";"OUT: 00";"";
"2022-06-18 03:14:48.0";"ERROR";"org.primftpd.filesystem.RootSshFileSystemView";"could not run 'ls' command (exitCode: -2)";"";
"2022-06-18 03:14:48.0";"TRACE";"org.apache.sshd.server.channel.ChannelSession";"OUT: 00";"";
"2022-06-18 03:14:48.0";"TRACE";"org.apache.sshd.server.channel.ChannelSession";"OUT: 00";"";
"2022-06-18 03:14:48.0";"TRACE";"org.apache.sshd.server.channel.ChannelSession";"OUT: 6f";"";
"2022-06-18 03:14:48.0";"TRACE";"org.apache.sshd.server.channel.ChannelSession";"OUT: 65 00 00 01 6f 00 00 00 02 00 00 00 5e 2f 73 74 6f 72 61 67 65 2f 65 6d 75 6c 61 74 65 64 2f...";"";
"2022-06-18 03:14:48.0";"TRACE";"org.apache.sshd.common.channel.Window";"Consume server remote window by 115 down to 2038784";"";
"2022-06-18 03:14:48.0";"DEBUG";"org.apache.sshd.server.channel.ChannelSession";"Send SSH_MSG_CHANNEL_DATA on channel 0";"";
"2022-06-18 03:14:48.0";"TRACE";"org.apache.sshd.server.session.ServerSession";"Sending packet #376: 5e 00 00 00 01 00 00 00 73 00 00 00 6f 65 00 00 01 6f 00 00 00 02 00 00 00 5...";"";
"2022-06-18 03:14:48.0";"TRACE";"org.apache.sshd.server.session.ServerSession";"Received packet #379: 5e 00 00 00 00 00 00 00 6b 00 00 00 67 0b 00 00 01 70 00 00 00 5e 2f 73 74 ...";"";
"2022-06-18 03:14:48.0";"DEBUG";"org.apache.sshd.server.channel.ChannelSession";"Received SSH_MSG_CHANNEL_DATA on channel ChannelSession[id=0, recipient=1]";"";
"2022-06-18 03:14:48.0";"TRACE";"org.apache.sshd.server.channel.ChannelSession";"Received channel data: 00 00 00 67 0b 00 00 01 70 00 00 00 5e 2f 73 74 6f 72 61 67 65 2f 65 6d 75...";"";
"2022-06-18 03:14:48.0";"TRACE";"org.apache.sshd.server.channel.PipeDataReceiver";"IN:  00 00 00 67 0b 00 00 01 70 00 00 00 5e 2f 73 74 6f 72 61 67 65 2f 65 6d 75 6c 61 74 65 64 2f...";"";
"2022-06-18 03:14:48.0";"TRACE";"org.apache.sshd.common.channel.Window";"Consume server local  window by 4 down to 2058158";"";
"2022-06-18 03:14:48.0";"TRACE";"org.apache.sshd.common.channel.Window";"Consume server local  window by 103 down to 2058055";"";

Here's the continuation of the log, listing the file that causes the SFTP server to shut down:

"2022-06-18 03:14:48.0";"DEBUG";"org.apache.sshd.server.sftp.SftpSubsystem";"Received SSH_FXP_OPENDIR (path=/storage/emulated/0/Android/data/com.zubersoft.mobilesheetspro/fil...";"";
"2022-06-18 03:14:48.0";"TRACE";"org.primftpd.filesystem.RootSshFileSystemView";"getNormalizedView()";"";
"2022-06-18 03:14:48.0";"TRACE";"org.primftpd.filesystem.RootSshFileSystemView";"getFile(/storage/emulated/0/Android/data/com.zubersoft.mobilesheetspro/files/Your Love Never Fail...";"";
"2022-06-18 03:14:48.0";"TRACE";"org.primftpd.filesystem.RootSshFileSystemView";"  getFile(abs: /storage/emulated/0/Android/data/com.zubersoft.mobilesheetspro/files/Your Love Nev...";"";
"2022-06-18 03:14:48.0";"TRACE";"org.primftpd.filesystem.RootSshFileSystemView";"  running command: ls -lad "/storage/emulated/0/Android/data/com.zubersoft.mobilesheetspro/files/...";"";
"2022-06-18 03:14:48.0";"TRACE";"org.primftpd.filesystem.RootSshFile";"[Your Love Never Fails (C)] doesExist() -> false";"";
"2022-06-18 03:14:48.0";"DEBUG";"org.apache.sshd.server.sftp.SftpSubsystem";"Send SSH_FXP_STATUS (substatus=2, msg=/storage/emulated/0/Android/data/com.zubersoft.mobilesheets...";"";
"2022-06-18 03:14:48.0";"TRACE";"org.apache.sshd.server.channel.ChannelSession";"OUT: 00";"";
"2022-06-18 03:14:48.0";"TRACE";"org.apache.sshd.server.channel.ChannelSession";"OUT: 00";"";
"2022-06-18 03:14:48.0";"TRACE";"org.apache.sshd.server.channel.ChannelSession";"OUT: 00";"";
"2022-06-18 03:14:48.0";"TRACE";"org.apache.sshd.server.channel.ChannelSession";"OUT: 6f";"";
"2022-06-18 03:14:48.0";"ERROR";"org.primftpd.filesystem.RootSshFileSystemView";"could not run 'ls' command (exitCode: -2)";"";
"2022-06-18 03:14:48.0";"TRACE";"org.apache.sshd.server.channel.ChannelSession";"OUT: 65 00 00 01 70 00 00 00 02 00 00 00 5e 2f 73 74 6f 72 61 67 65 2f 65 6d 75 6c 61 74 65 64 2f...";"";
"2022-06-18 03:14:48.0";"TRACE";"org.apache.sshd.common.channel.Window";"Consume server remote window by 115 down to 2038669";"";
"2022-06-18 03:14:48.0";"DEBUG";"org.apache.sshd.server.channel.ChannelSession";"Send SSH_MSG_CHANNEL_DATA on channel 0";"";
"2022-06-18 03:14:48.0";"TRACE";"org.apache.sshd.server.session.ServerSession";"Sending packet #377: 5e 00 00 00 01 00 00 00 73 00 00 00 6f 65 00 00 01 70 00 00 00 02 00 00 00 5...";"";
"2022-06-18 03:15:36.9";"DEBUG";"org.primftpd.PrimitiveFtpdActivity";"onOptionsItemSelected()";"";
"2022-06-18 03:15:36.9";"TRACE";"org.primftpd.PrimitiveFtpdActivity";"handleStop()";"";
"2022-06-18 03:15:36.9";"TRACE";"org.primftpd.util.ServicesStartStopUtil";"stopServers()";"";
"2022-06-18 03:15:36.9";"DEBUG";"org.primftpd.services.SshServerService";"onDestroy()";"";
"2022-06-18 03:15:36.9";"DEBUG";"org.primftpd.PrimitiveFtpdActivity";"got ServerStateChangedEvent";"";
"2022-06-18 03:15:36.9";"DEBUG";"org.primftpd.PrimitiveFtpdActivity";"handling event 'org.primftpd.events.ServerStateChangedEvent', offset: 154880 ms";"";
"2022-06-18 03:15:36.9";"DEBUG";"org.primftpd.PrimitiveFtpdActivity";"displayServersState()";"";
"2022-06-18 03:15:36.9";"DEBUG";"org.primftpd.PrimitiveFtpdActivity";"checkServicesRunning()";"";
"2022-06-18 03:15:36.9";"DEBUG";"org.primftpd.services.ServerServiceHandler";"handleMessage()";"";
"2022-06-18 03:15:36.9";"DEBUG";"org.primftpd.PrimitiveFtpdActivity";"updateButtonStates()";"";
"2022-06-18 03:15:36.9";"DEBUG";"org.primftpd.services.ServerServiceHandler";"stopping sftp-ssh server";"";
"2022-06-18 03:15:36.9";"INFO";"org.apache.sshd.server.session.ServerSession";"Disconnecting: server close";"";
"2022-06-18 03:15:36.9";"TRACE";"org.apache.sshd.server.session.ServerSession";"Sending packet #378: 01 ff ff ff ff 00 00 00 0c 73 65 72 76 65 72 20 63 6c 6f 73 65 00 00 00 00";"";
"2022-06-18 03:15:36.9";"DEBUG";"org.apache.sshd.SshServer";"Closing SshServer[d2a148e] immediately";"";
"2022-06-18 03:15:36.9";"DEBUG";"org.apache.sshd.server.session.ServerSession";"Closing ServerSession[t*****@/192.168.***.***:38484] immediately";"";
"2022-06-18 03:15:36.9";"DEBUG";"org.apache.sshd.server.session.ServerConnectionService";"Closing ServerConnectionService[ServerSession[t*****@/192.168.***.***:38484]] immediately";"";
"2022-06-18 03:15:36.9";"DEBUG";"org.apache.sshd.common.forward.DefaultTcpipForwarder";"Closing DefaultTcpipForwarder[ServerSession[t*****@/192.168.***.***:38484]] immediately";"";
"2022-06-18 03:15:36.9";"DEBUG";"org.apache.sshd.common.forward.DefaultTcpipForwarder";"DefaultTcpipForwarder[ServerSession[t*****@/192.168.***.***:38484]] closed";"";
"2022-06-18 03:15:36.9";"DEBUG";"org.apache.sshd.agent.common.AgentForwardSupport";"Closing AgentForwardSupport[ServerSession[t*****@/192.168.***.***:38484]] immediately";"";
"2022-06-18 03:15:36.9";"DEBUG";"org.apache.sshd.agent.common.AgentForwardSupport";"AgentForwardSupport[ServerSession[t*****@/192.168.***.***:38484]] closed";"";
"2022-06-18 03:15:36.9";"DEBUG";"org.apache.sshd.server.x11.X11ForwardSupport";"Closing org.apache.sshd.server.x11.X11ForwardSupport@947f168 immediately";"";
"2022-06-18 03:15:36.9";"DEBUG";"org.apache.sshd.server.x11.X11ForwardSupport";"org.apache.sshd.server.x11.X11ForwardSupport@947f168 closed";"";
"2022-06-18 03:15:36.9";"DEBUG";"org.apache.sshd.server.channel.ChannelSession";"Closing ChannelSession[id=0, recipient=1] immediately";"";
"2022-06-18 03:15:36.9";"ERROR";"org.apache.sshd.server.sftp.SftpSubsystem";"Exception caught in SFTP subsystem";"java.io.InterruptedIOException: null
    org.apache.sshd.common.channel.ChannelPipedInputStream.read() line: 120
    java.io.DataInputStream.readFully() line: 198
    java.io.DataInputStream.readInt() line: 389
    org.apache.sshd.server.sftp.SftpSubsystem.run() line: 412
    java.util.concurrent.Executors$RunnableAdapter.call() line: 462
    java.util.concurrent.FutureTask.run() line: 266
    java.util.concurrent.ThreadPoolExecutor.runWorker() line: 1167
    java.util.concurrent.ThreadPoolExecutor$Worker.run() line: 641
    java.lang.Thread.run() line: 920
Caused by: java.lang.InterruptedException: null
    java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.reportInterruptAfterWait() line: 2042
    java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await() line: 2076
    org.apache.sshd.common.channel.ChannelPipedInputStream.read() line: 117
    java.io.DataInputStream.readFully() line: 198
    java.io.DataInputStream.readInt() line: 389
    org.apache.sshd.server.sftp.SftpSubsystem.run() line: 412
    java.util.concurrent.Executors$RunnableAdapter.call() line: 462
    java.util.concurrent.FutureTask.run() line: 266
    java.util.concurrent.ThreadPoolExecutor.runWorker() line: 1167
    java.util.concurrent.ThreadPoolExecutor$Worker.run() line: 641
    java.lang.Thread.run() line: 920";

The "could not run 'ls' command" error is throughout the log even when everything is working correctly, so it may be be spurious.

If I use Beyond Compare's "Exclude Folders" to exclude the path .\Android\data\com.zubersoft.mobilesheetspro, I am able to scan the file system on the tablet and successfully synchronize with Beyond Compare and primitive-ftpd as the server. Of course these files are important to access and back up, so ignoring them is not a solution.

Do these logs give any clue why these specific files might cause the primitive-ftpd server to fail?

I have installed an SSH server on the tablet and examining the files from a terminal, I do not see any differences in permissions between the file that fails, and the files that work normally. The Zubersoft Mobile Sheets Pro app is not running when the SFTP access is attempted.

@wolpi, bringing this discussion back to the original issue thread. I have installed primitiveFTPd-6.12-SNAPSHOT, and still see the same issue with specific files (maybe filenames with spaces or maybe spaces and other special characters) causing an exception and subsequent failure of primitive ftpd to respond to the client.

Here is another specific file that causes failure when the client attempts to copy it. /storage/emulated/0/Ring - Someone at Your Door (Bell).oga

I captured the logs for the attempt to copy this one file.

Here is the client (Beyond Compare) log:

7/4/2022 1:09:33 PM  Connecting to 192.168.27.144
7/4/2022 1:09:33 PM  Server key [RSA SHA256:pmTZ6lw9o1/GfkxE5Q2ki**********XYIXXGgKU]
7/4/2022 1:09:33 PM  Password authorization successful.
7/4/2022 1:09:33 PM  Server software: ${POM.ARTIFACTID}-${POM.VERSION}
7/4/2022 1:09:33 PM  Compression: none
7/4/2022 1:09:33 PM  Encryption: aes256-cbc
7/4/2022 1:09:33 PM  MAC algorithm: hmac-sha1
7/4/2022 1:09:33 PM  Connected to 192.168.27.144 port 1234
7/4/2022 1:09:33 PM  Using SFTP version 3.
7/4/2022 1:09:33 PM  Server information:
7/4/2022 1:09:33 PM  Current Folder: /
7/4/2022 1:09:33 PM  Unable to copy sftp://t*****@192.168.27.144:1234/storage/emulated/0/Notifications/Ring - Someone at Your Door (Bell).oga: No such file /storage/emulated/0/Notifications/Ring - Someone at Your Door (Bell).oga
7/4/2022 1:09:33 PM  Failed to copy 1 items.  Completed in 45.7 seconds.

Here is the log from primitive ftpd. (saved as prim-ftpd-log-2022-07-04-12-59-03.csv)

2022-07-04 01:10:02.8;"TRACE";"org.primftpd.filesystem.RootSshFileSystemView";"getNormalizedView()";"";
2022-07-04 01:10:02.8;"TRACE";"org.primftpd.filesystem.RootSshFileSystemView";"getFile(.)";"";
2022-07-04 01:10:02.8;"TRACE";"org.primftpd.filesystem.RootSshFileSystemView";"  getFile(abs: /)";"";
2022-07-04 01:10:02.8;"TRACE";"org.primftpd.filesystem.RootSshFileSystemView";"  running command: ls -lad /";"";
2022-07-04 01:10:02.8;"TRACE";"org.primftpd.filesystem.RootSshFile";"[] getAbsolutePath() -> '/'";"";
2022-07-04 01:10:02.8;"TRACE";"org.primftpd.filesystem.RootSshFileSystemView";"getNormalizedView()";"";
2022-07-04 01:10:02.8;"TRACE";"org.primftpd.filesystem.RootSshFileSystemView";"getFile(/)";"";
2022-07-04 01:10:02.8;"TRACE";"org.primftpd.filesystem.RootSshFileSystemView";"  getFile(abs: /)";"";
2022-07-04 01:10:02.8;"TRACE";"org.primftpd.filesystem.RootSshFileSystemView";"  running command: ls -lad /";"";
2022-07-04 01:10:02.8;"TRACE";"org.primftpd.filesystem.RootSshFile";"[] getName()";"";
2022-07-04 01:10:02.8;"ERROR";"org.primftpd.filesystem.RootSshFileSystemView";"could not run 'ls' command (exitCode: -2)";"";
2022-07-04 01:10:02.8;"TRACE";"org.primftpd.filesystem.RootSshFileSystemView";"getNormalizedView()";"";
2022-07-04 01:10:02.8;"TRACE";"org.primftpd.filesystem.RootSshFileSystemView";"getFile(.)";"";
2022-07-04 01:10:02.8;"ERROR";"org.primftpd.filesystem.RootSshFileSystemView";"could not run 'ls' command (exitCode: -2)";"";
2022-07-04 01:10:02.8;"TRACE";"org.primftpd.filesystem.RootSshFileSystemView";"  getFile(abs: /)";"";
2022-07-04 01:10:02.8;"TRACE";"org.primftpd.filesystem.RootSshFileSystemView";"  running command: ls -lad /";"";
2022-07-04 01:10:02.8;"ERROR";"org.primftpd.filesystem.RootSshFileSystemView";"could not run 'ls' command (exitCode: -2)";"";
2022-07-04 01:10:02.8;"TRACE";"org.primftpd.filesystem.RootSshFile";"[] getName()";"";
2022-07-04 01:10:02.8;"TRACE";"org.apache.sshd.server.channel.ChannelSession";"OUT: 00";"";
2022-07-04 01:10:02.8;"TRACE";"org.apache.sshd.server.channel.ChannelSession";"OUT: 00";"";
2022-07-04 01:10:02.8;"TRACE";"org.apache.sshd.server.channel.ChannelSession";"OUT: 00";"";
2022-07-04 01:10:02.8;"TRACE";"org.apache.sshd.server.channel.ChannelSession";"OUT: 4c";"";
2022-07-04 01:10:02.8;"TRACE";"org.apache.sshd.server.channel.ChannelSession";"OUT: 68 00 00 00 01 00 00 00 01 00 00 00 01 2f 00 00 00 36 2d 2d 2d 2d 2d 2d 2d 2d 2d 2d 20 20 31...";"";
2022-07-04 01:10:02.8;"TRACE";"org.apache.sshd.common.channel.Window";"Consume server remote window by 80 down to 32679";"";
2022-07-04 01:10:02.8;"DEBUG";"org.apache.sshd.server.channel.ChannelSession";"Send SSH_MSG_CHANNEL_DATA on channel 0";"";
2022-07-04 01:10:02.8;"TRACE";"org.apache.sshd.server.session.ServerSession";"Sending packet #10: 5e 00 00 00 01 00 00 00 50 00 00 00 4c 68 00 00 00 01 00 00 00 01 00 00 00 01...";"";
2022-07-04 01:10:02.8;"TRACE";"org.apache.sshd.server.session.ServerSession";"Received packet #12: 5e 00 00 00 00 00 00 00 55 00 00 00 51 11 00 00 00 02 00 00 00 48 2f 73 74 6...";"";
2022-07-04 01:10:02.8;"DEBUG";"org.apache.sshd.server.channel.ChannelSession";"Received SSH_MSG_CHANNEL_DATA on channel ChannelSession[id=0
2022-07-04 01:10:02.8;"TRACE";"org.apache.sshd.server.channel.ChannelSession";"Received channel data: 00 00 00 51 11 00 00 00 02 00 00 00 48 2f 73 74 6f 72 61 67 65 2f 65 6d 75...";"";
2022-07-04 01:10:02.8;"TRACE";"org.apache.sshd.server.channel.PipeDataReceiver";"IN:  00 00 00 51 11 00 00 00 02 00 00 00 48 2f 73 74 6f 72 61 67 65 2f 65 6d 75 6c 61 74 65 64 2f...";"";
2022-07-04 01:10:02.8;"TRACE";"org.apache.sshd.common.channel.Window";"Consume server local  window by 4 down to 2097125";"";
2022-07-04 01:10:02.8;"TRACE";"org.apache.sshd.common.channel.Window";"Consume server local  window by 81 down to 2097044";"";
2022-07-04 01:10:02.8;"DEBUG";"org.apache.sshd.server.sftp.SftpSubsystem";"Received SSH_FXP_STAT (path=/storage/emulated/0/Notifications/Ring - Someone at Your Door (Bell)....";"";
2022-07-04 01:10:02.8;"TRACE";"org.primftpd.filesystem.RootSshFileSystemView";"getNormalizedView()";"";
2022-07-04 01:10:02.8;"TRACE";"org.primftpd.filesystem.RootSshFileSystemView";"getFile(/storage/emulated/0/Notifications/Ring - Someone at Your Door (Bell).oga)";"";
2022-07-04 01:10:02.8;"TRACE";"org.primftpd.filesystem.RootSshFileSystemView";"  getFile(abs: /storage/emulated/0/Notifications/Ring - Someone at Your Door (Bell).oga)";"";
2022-07-04 01:10:02.8;"TRACE";"org.primftpd.filesystem.RootSshFileSystemView";"  running command: ls -lad /storage/emulated/0/Notifications/Ring\ -\ Someone\ at\ Your\ Door\ (B...";"";
2022-07-04 01:10:02.8;"TRACE";"org.primftpd.filesystem.RootSshFile";"[Ring - Someone at Your Door (Bell).oga] doesExist() -> false";"";
2022-07-04 01:10:02.8;"ERROR";"org.primftpd.filesystem.RootSshFileSystemView";"could not run 'ls' command (exitCode: -2)";"";
2022-07-04 01:10:02.8;"TRACE";"org.primftpd.filesystem.RootSshFile";"[Ring - Someone at Your Door (Bell).oga] getAbsolutePath() -> '/storage/emulated/0/Notifications/...";"";
2022-07-04 01:10:02.8;"DEBUG";"org.apache.sshd.server.sftp.SftpSubsystem";"Send SSH_FXP_STATUS (substatus=2
2022-07-04 01:10:02.8;"TRACE";"org.apache.sshd.server.channel.ChannelSession";"OUT: 00";"";
2022-07-04 01:10:02.8;"TRACE";"org.apache.sshd.server.channel.ChannelSession";"OUT: 00";"";
2022-07-04 01:10:02.8;"TRACE";"org.apache.sshd.server.channel.ChannelSession";"OUT: 00";"";
2022-07-04 01:10:02.8;"TRACE";"org.apache.sshd.server.channel.ChannelSession";"OUT: 59";"";
2022-07-04 01:10:02.8;"TRACE";"org.apache.sshd.server.channel.ChannelSession";"OUT: 65 00 00 00 02 00 00 00 02 00 00 00 48 2f 73 74 6f 72 61 67 65 2f 65 6d 75 6c 61 74 65 64 2f...";"";
2022-07-04 01:10:02.8;"TRACE";"org.apache.sshd.common.channel.Window";"Consume server remote window by 93 down to 32586";"";
2022-07-04 01:10:02.8;"DEBUG";"org.apache.sshd.server.channel.ChannelSession";"Send SSH_MSG_CHANNEL_DATA on channel 0";"";
2022-07-04 01:10:02.8;"TRACE";"org.apache.sshd.server.session.ServerSession";"Sending packet #11: 5e 00 00 00 01 00 00 00 5d 00 00 00 59 65 00 00 00 02 00 00 00 02 00 00 00 48...";"";
2022-07-04 01:10:02.8;"TRACE";"org.apache.sshd.server.session.ServerSession";"Received packet #13: 5e 00 00 00 00 00 00 00 5d 00 00 00 59 03 00 00 00 03 00 00 00 48 2f 73 74 6...";"";
2022-07-04 01:10:02.8;"DEBUG";"org.apache.sshd.server.channel.ChannelSession";"Received SSH_MSG_CHANNEL_DATA on channel ChannelSession[id=0
2022-07-04 01:10:02.8;"TRACE";"org.apache.sshd.server.channel.ChannelSession";"Received channel data: 00 00 00 59 03 00 00 00 03 00 00 00 48 2f 73 74 6f 72 61 67 65 2f 65 6d 75...";"";
2022-07-04 01:10:02.8;"TRACE";"org.apache.sshd.server.channel.PipeDataReceiver";"IN:  00 00 00 59 03 00 00 00 03 00 00 00 48 2f 73 74 6f 72 61 67 65 2f 65 6d 75 6c 61 74 65 64 2f...";"";
2022-07-04 01:10:02.8;"TRACE";"org.apache.sshd.common.channel.Window";"Consume server local  window by 4 down to 2097040";"";
2022-07-04 01:10:02.8;"TRACE";"org.apache.sshd.common.channel.Window";"Consume server local  window by 89 down to 2096951";"";
2022-07-04 01:10:02.8;"DEBUG";"org.apache.sshd.server.sftp.SftpSubsystem";"Received SSH_FXP_OPEN (path=/storage/emulated/0/Notifications/Ring - Someone at Your Door (Bell)....";"";
2022-07-04 01:10:02.8;"TRACE";"org.primftpd.filesystem.RootSshFileSystemView";"getNormalizedView()";"";
2022-07-04 01:10:02.8;"TRACE";"org.primftpd.filesystem.RootSshFileSystemView";"getFile(/storage/emulated/0/Notifications/Ring - Someone at Your Door (Bell).oga)";"";
2022-07-04 01:10:02.8;"TRACE";"org.primftpd.filesystem.RootSshFileSystemView";"  getFile(abs: /storage/emulated/0/Notifications/Ring - Someone at Your Door (Bell).oga)";"";
2022-07-04 01:10:02.8;"TRACE";"org.primftpd.filesystem.RootSshFileSystemView";"  running command: ls -lad /storage/emulated/0/Notifications/Ring\ -\ Someone\ at\ Your\ Door\ (B...";"";
2022-07-04 01:10:02.8;"TRACE";"org.primftpd.filesystem.RootSshFile";"[Ring - Someone at Your Door (Bell).oga] doesExist() -> false";"";
2022-07-04 01:10:02.8;"ERROR";"org.primftpd.filesystem.RootSshFileSystemView";"could not run 'ls' command (exitCode: -2)";"";
2022-07-04 01:10:02.8;"DEBUG";"org.apache.sshd.server.sftp.SftpSubsystem";"Send SSH_FXP_STATUS (substatus=2
2022-07-04 01:10:02.8;"TRACE";"org.apache.sshd.server.channel.ChannelSession";"OUT: 00";"";
2022-07-04 01:10:02.8;"TRACE";"org.apache.sshd.server.channel.ChannelSession";"OUT: 00";"";
2022-07-04 01:10:02.8;"TRACE";"org.apache.sshd.server.channel.ChannelSession";"OUT: 00";"";
2022-07-04 01:10:02.8;"TRACE";"org.apache.sshd.server.channel.ChannelSession";"OUT: 66";"";
2022-07-04 01:10:02.8;"TRACE";"org.apache.sshd.server.channel.ChannelSession";"OUT: 65 00 00 00 03 00 00 00 02 00 00 00 55 4e 6f 20 73 75 63 68 20 66 69 6c 65 20 2f 73 74 6f 72...";"";
2022-07-04 01:10:02.8;"TRACE";"org.apache.sshd.common.channel.Window";"Consume server remote window by 106 down to 32480";"";
2022-07-04 01:10:02.8;"DEBUG";"org.apache.sshd.server.channel.ChannelSession";"Send SSH_MSG_CHANNEL_DATA on channel 0";"";
2022-07-04 01:10:02.8;"TRACE";"org.apache.sshd.server.session.ServerSession";"Sending packet #12: 5e 00 00 00 01 00 00 00 6a 00 00 00 66 65 00 00 00 03 00 00 00 02 00 00 00 55...";"";
2022-07-04 01:10:38.4;"DEBUG";"org.primftpd.PrimitiveFtpdActivity";"onOptionsItemSelected()";"";
2022-07-04 01:10:38.4;"TRACE";"org.primftpd.PrimitiveFtpdActivity";"handleStop()";"";
2022-07-04 01:10:38.4;"TRACE";"org.primftpd.util.ServicesStartStopUtil";"stopServers()";"";
2022-07-04 01:10:38.4;"DEBUG";"org.primftpd.services.SshServerService";"onDestroy()";"";
2022-07-04 01:10:38.4;"DEBUG";"org.primftpd.PrimitiveFtpdActivity";"got ServerStateChangedEvent";"";
2022-07-04 01:10:38.4;"DEBUG";"org.primftpd.PrimitiveFtpdActivity";"handling event 'org.primftpd.events.ServerStateChangedEvent'
2022-07-04 01:10:38.4;"DEBUG";"org.primftpd.PrimitiveFtpdActivity";"displayServersState()";"";
2022-07-04 01:10:38.4;"DEBUG";"org.primftpd.PrimitiveFtpdActivity";"checkServicesRunning()";"";
2022-07-04 01:10:38.4;"DEBUG";"org.primftpd.services.ServerServiceHandler";"handleMessage()";"";
2022-07-04 01:10:38.4;"DEBUG";"org.primftpd.services.ServerServiceHandler";"stopping sftp-ssh server";"";
2022-07-04 01:10:38.4;"INFO";"org.apache.sshd.server.session.ServerSession";"Disconnecting: server close";"";
2022-07-04 01:10:38.4;"TRACE";"org.apache.sshd.server.session.ServerSession";"Sending packet #13: 01 ff ff ff ff 00 00 00 0c 73 65 72 76 65 72 20 63 6c 6f 73 65 00 00 00 00";"";
2022-07-04 01:10:38.4;"DEBUG";"org.primftpd.PrimitiveFtpdActivity";"updateButtonStates()";"";
2022-07-04 01:10:38.4;"DEBUG";"org.apache.sshd.SshServer";"Closing SshServer[b143ba0] immediately";"";
2022-07-04 01:10:38.4;"DEBUG";"org.apache.sshd.server.session.ServerSession";"Closing ServerSession[t*******@/192.168.27.106:6597] immediately";"";
2022-07-04 01:10:38.4;"DEBUG";"org.apache.sshd.server.session.ServerConnectionService";"Closing ServerConnectionService[ServerSession[t*******@/192.168.27.106:6597]] immediately";"";
2022-07-04 01:10:38.4;"DEBUG";"org.apache.sshd.common.forward.DefaultTcpipForwarder";"Closing DefaultTcpipForwarder[ServerSession[t*******@/192.168.27.106:6597]] immediately";"";
2022-07-04 01:10:38.4;"DEBUG";"org.apache.sshd.common.forward.DefaultTcpipForwarder";"DefaultTcpipForwarder[ServerSession[t*******@/192.168.27.106:6597]] closed";"";
2022-07-04 01:10:38.4;"DEBUG";"org.apache.sshd.agent.common.AgentForwardSupport";"Closing AgentForwardSupport[ServerSession[t*******@/192.168.27.106:6597]] immediately";"";
2022-07-04 01:10:38.4;"DEBUG";"org.apache.sshd.agent.common.AgentForwardSupport";"AgentForwardSupport[ServerSession[t*******@/192.168.27.106:6597]] closed";"";
2022-07-04 01:10:38.4;"DEBUG";"org.apache.sshd.server.x11.X11ForwardSupport";"Closing org.apache.sshd.server.x11.X11ForwardSupport@af3ca8c immediately";"";
2022-07-04 01:10:38.4;"DEBUG";"org.apache.sshd.server.x11.X11ForwardSupport";"org.apache.sshd.server.x11.X11ForwardSupport@af3ca8c closed";"";
2022-07-04 01:10:38.4;"DEBUG";"org.apache.sshd.server.channel.ChannelSession";"Closing ChannelSession[id=0
2022-07-04 01:10:38.4;"DEBUG";"org.apache.sshd.server.sftp.SftpSubsystem";"destroy() - cancel pending future=true";"";
2022-07-04 01:10:38.4;"DEBUG";"org.apache.sshd.server.sftp.SftpSubsystem";"destroy() - shutdown executor service - runners count=0";"";
2022-07-04 01:10:38.4;"DEBUG";"org.apache.sshd.server.sftp.SftpSubsystem";"destroy() - mark as closed";"";
2022-07-04 01:10:38.4;"DEBUG";"org.apache.sshd.server.channel.ChannelSession";"ChannelSession[id=0
2022-07-04 01:10:38.4;"DEBUG";"org.apache.sshd.server.session.ServerConnectionService";"ServerConnectionService[ServerSession[t*******@/192.168.27.106:6597]] closed";"";
2022-07-04 01:10:38.4;"DEBUG";"org.apache.sshd.common.io.mina.MinaSession";"Closing MinaSession[local=/192.168.27.144:1234
2022-07-04 01:10:38.4;"DEBUG";"org.apache.sshd.common.io.mina.MinaSession";"MinaSession[local=/192.168.27.144:1234
2022-07-04 01:10:38.4;"DEBUG";"org.apache.sshd.server.session.ServerSession";"ServerSession[t*******@/192.168.27.106:6597] closed";"";
2022-07-04 01:10:38.4;"DEBUG";"org.apache.sshd.server.session.ServerSession";"ServerSession[t*******@/192.168.27.106:6597] is already closed";"";
2022-07-04 01:10:38.4;"ERROR";"org.apache.sshd.server.sftp.SftpSubsystem";"Exception caught in SFTP subsystem";"java.io.InterruptedIOException: null
"   org.apache.sshd.common.channel.ChannelPipedInputStream.read() line: 120"
"   java.io.DataInputStream.readFully() line: 198"
"   java.io.DataInputStream.readInt() line: 389"
"   org.apache.sshd.server.sftp.SftpSubsystem.run() line: 412"
"   java.util.concurrent.Executors$RunnableAdapter.call() line: 462"
"   java.util.concurrent.FutureTask.run() line: 266"
"   java.util.concurrent.ThreadPoolExecutor.runWorker() line: 1167"
"   java.util.concurrent.ThreadPoolExecutor$Worker.run() line: 641"
"   java.lang.Thread.run() line: 920"
Caused by: java.lang.InterruptedException: null
"   java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.reportInterruptAfterWait() line: 2042"
"   java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await() line: 2076"
"   org.apache.sshd.common.channel.ChannelPipedInputStream.read() line: 117"
"   java.io.DataInputStream.readFully() line: 198"
"   java.io.DataInputStream.readInt() line: 389"
"   org.apache.sshd.server.sftp.SftpSubsystem.run() line: 412"
"   java.util.concurrent.Executors$RunnableAdapter.call() line: 462"
"   java.util.concurrent.FutureTask.run() line: 266"
"   java.util.concurrent.ThreadPoolExecutor.runWorker() line: 1167"
"   java.util.concurrent.ThreadPoolExecutor$Worker.run() line: 641"
"   java.lang.Thread.run() line: 920"";"
2022-07-04 01:10:38.4;"DEBUG";"org.apache.sshd.common.io.mina.MinaServiceFactory";"Closing org.apache.sshd.common.io.mina.MinaServiceFactory@7522a8d immediately";"";
2022-07-04 01:10:38.4;"DEBUG";"org.apache.sshd.common.io.mina.MinaServiceFactory";"org.apache.sshd.common.io.mina.MinaServiceFactory@7522a8d closed";"";
2022-07-04 01:10:38.4;"DEBUG";"org.apache.sshd.SshServer";"SshServer[b143ba0] closed";"";
2022-07-04 01:10:38.4;"DEBUG";"org.apache.sshd.SshServer";"SshServer[b143ba0] is already closed";"";
2022-07-04 01:10:38.4;"DEBUG";"org.primftpd.services.ServerServiceHandler";"releasing wake lock (sftp-ssh)";"";
2022-07-04 01:10:38.4;"DEBUG";"org.primftpd.services.ServerServiceHandler";"closing root shell (sftp-ssh)";"";
2022-07-04 01:10:38.4;"DEBUG";"org.primftpd.services.ServerServiceHandler";"stopSelf (sftp-ssh)";"";
2022-07-04 01:10:38.4;"TRACE";"org.primftpd.util.ServicesStartStopUtil";"updateNonActivityUI()";"";
2022-07-04 01:10:38.4;"DEBUG";"org.primftpd.util.ServicesStartStopUtil";"updateWidget()";"";
2022-07-04 01:10:38.4;"DEBUG";"org.primftpd.util.ServicesStartStopUtil";"removeStatusbarNotification()";"";
2022-07-04 01:10:38.4;"DEBUG";"org.primftpd.remotecontrol.TaskerReceiver";"sending tasker RequestQueryCondition";"";
2022-07-04 01:10:42.4;"DEBUG";"org.primftpd.PrimitiveFtpdActivity";"onOptionsItemSelected()";"";
2022-07-04 01:10:42.4;"TRACE";"org.primftpd.PrimitiveFtpdActivity";"handleClientAction()";"";
2022-07-04 01:10:42.4;"DEBUG";"org.primftpd.PrimitiveFtpdActivity";"onPause()";"";
2022-07-04 01:10:45.6;"DEBUG";"org.primftpd.PrimitiveFtpdActivity";"onStart()";"";
2022-07-04 01:10:45.6;"DEBUG";"org.primftpd.PrimitiveFtpdActivity";"loadPrefs()";"";
2022-07-04 01:10:45.6;"DEBUG";"org.primftpd.PrimitiveFtpdActivity";"got anonymousLogin: false";"";
2022-07-04 01:10:45.6;"DEBUG";"org.primftpd.PrimitiveFtpdActivity";"got userName: t*******";"";
2022-07-04 01:10:45.6;"DEBUG";"org.primftpd.PrimitiveFtpdActivity";"got password length: 88";"";
2022-07-04 01:10:45.6;"DEBUG";"org.primftpd.PrimitiveFtpdActivity";"got startDir: /";"";
2022-07-04 01:10:45.6;"DEBUG";"org.primftpd.PrimitiveFtpdActivity";"got announce: false";"";
2022-07-04 01:10:45.6;"DEBUG";"org.primftpd.PrimitiveFtpdActivity";"got announceName: primitive ftpd";"";
2022-07-04 01:10:45.6;"DEBUG";"org.primftpd.PrimitiveFtpdActivity";"got wakelock: true";"";
2022-07-04 01:10:45.6;"DEBUG";"org.primftpd.PrimitiveFtpdActivity";"got pubKeyAuth: false";"";
2022-07-04 01:10:45.6;"DEBUG";"org.primftpd.PrimitiveFtpdActivity";"got 'which server': SFTP";"";
2022-07-04 01:10:45.6;"DEBUG";"org.primftpd.PrimitiveFtpdActivity";"got ftpPassivePorts: 5678";"";
2022-07-04 01:10:45.6;"DEBUG";"org.primftpd.PrimitiveFtpdActivity";"got bindIp: null";"";
2022-07-04 01:10:45.6;"DEBUG";"org.primftpd.PrimitiveFtpdActivity";"got idleTimeout: 0";"";
2022-07-04 01:10:45.6;"DEBUG";"org.primftpd.PrimitiveFtpdActivity";"got 'port': 3777";"";
2022-07-04 01:10:45.6;"DEBUG";"org.primftpd.PrimitiveFtpdActivity";"got 'secure port': 1234";"";
2022-07-04 01:10:45.6;"DEBUG";"org.primftpd.PrimitiveFtpdActivity";"got showConnectionInfo: true";"";
2022-07-04 01:10:45.6;"DEBUG";"org.primftpd.PrimitiveFtpdActivity";"got 'StorageType': ROOT";"";
2022-07-04 01:10:45.6;"DEBUG";"org.primftpd.PrimitiveFtpdActivity";"got safUrl: ";"";
2022-07-04 01:10:45.6;"DEBUG";"org.primftpd.PrimitiveFtpdActivity";"got allowedIpsPattern: ";"";
2022-07-04 01:10:45.6;"DEBUG";"org.primftpd.PrimitiveFtpdActivity";"got rootCopyFiles: true";"";
2022-07-04 01:10:45.6;"DEBUG";"org.primftpd.PrimitiveFtpdActivity";"got 'logging': TEXT";"";
2022-07-04 01:10:45.6;"TRACE";"org.primftpd.PrimitiveFtpdActivity";"hasPermission()";"";
2022-07-04 01:10:45.6;"DEBUG";"org.primftpd.PrimitiveFtpdActivity";"onResume()";"";
2022-07-04 01:10:45.6;"DEBUG";"org.primftpd.PrimitiveFtpdActivity";"displayServersState()";"";
2022-07-04 01:10:45.6;"DEBUG";"org.primftpd.PrimitiveFtpdActivity";"checkServicesRunning()";"";
2022-07-04 01:10:45.6;"DEBUG";"org.primftpd.PrimitiveFtpdActivity";"updateButtonStates()";"";
2022-07-04 01:10:45.6;"DEBUG";"org.primftpd.PrimitiveFtpdActivity";"network connectivity changed
2022-07-04 01:10:49.0;"DEBUG";"org.primftpd.PrimitiveFtpdActivity";"onOptionsItemSelected()";"";
2022-07-04 01:10:49.0;"TRACE";"org.primftpd.PrimitiveFtpdActivity";"handleExit()";"";

I saw your request for running "ls" in the other issue. I'm not sure how to do that from primitive ftpd. I observe that the "ls" commands in the log report an error.

2022-07-04 01:10:02.8;"ERROR";"org.primftpd.filesystem.RootSshFileSystemView";"could not run 'ls' command (exitCode: -2)";"";
2022-07-04 01:10:02.8;"ERROR";"org.primftpd.filesystem.RootSshFileSystemView";"could not run 'ls' command (exitCode: -2)";"";
2022-07-04 01:10:02.8;"ERROR";"org.primftpd.filesystem.RootSshFileSystemView";"could not run 'ls' command (exitCode: -2)";"";
2022-07-04 01:10:02.8;"ERROR";"org.primftpd.filesystem.RootSshFileSystemView";"could not run 'ls' command (exitCode: -2)";"";
01:10:02.8;"ERROR";"org.primftpd.filesystem.RootSshFileSystemView";"could not run 'ls' command (exitCode: -2)";"";

From an SSH session on the same device, "ls -la" is successful:

:/storage/emulated/0/Notifications # ls -la
total 1872
-rw-rw---- 1 u0_a234 media_rw  85455 2022-05-28 09:11 Door\ Unlock\ Notifications.oga
-rw-rw---- 1 u0_a234 media_rw 184657 2022-05-28 09:10 Ring\ -\ Antique\ Ding\ Dong.oga
-rw-rw---- 1 u0_a234 media_rw  89572 2022-05-28 09:10 Ring\ -\ Default.oga
-rw-rw---- 1 u0_a234 media_rw 189754 2022-05-28 09:10 Ring\ -\ Ding\ Dong\ Neu.oga
-rw-rw---- 1 u0_a234 media_rw 105692 2022-05-28 09:10 Ring\ -\ Dogs.oga
-rw-rw---- 1 u0_a234 media_rw 454842 2022-05-28 09:10 Ring\ -\ Echo.oga
-rw-rw---- 1 u0_a234 media_rw  29940 2022-05-28 09:10 Ring\ -\ Motion\ at\ Front\ Door.oga
-rw-rw---- 1 u0_a234 media_rw  56041 2022-05-28 09:10 Ring\ -\ Navi.oga
-rw-rw---- 1 u0_a234 media_rw  52789 2022-05-28 09:10 Ring\ -\ Ring\ Theme\ Bells.oga
-rw-rw---- 1 u0_a234 media_rw   4327 2022-05-28 09:10 Ring\ -\ Silent.oga
-rwxrwx--- 1 u0_a234 media_rw  64228 2022-06-19 08:16 Ring\ -\ Someone\ at\ Your\ Door\ (Bell).oga
-rwxrwx--- 1 u0_a234 media_rw  20781 2022-06-19 08:16 Ring\ -\ Someone\ at\ Your\ Door.oga
-rw-rw---- 1 u0_a234 media_rw 152387 2022-05-28 09:10 Ring\ -\ Sonar.oga
-rw-rw---- 1 u0_a234 media_rw  90675 2022-05-28 09:10 Ring\ -\ Westminster\ Quarters.oga
-rw-rw---- 1 u0_a234 media_rw  85455 2022-05-28 09:10 Ring\ -\ Windchimes.oga
-rw-rw---- 1 u0_a234 media_rw 123028 2022-05-28 09:11 Ring\ Doorbell\ Notifications.oga
-rw-rw---- 1 u0_a234 media_rw  86238 2022-05-28 09:11 Ring\ Motion\ Notifications.oga
:/storage/emulated/0/Notifications #

I notice the failing file has the execute bit set - could that be an issue? I have no idea why that bit would be set. The files were all installed by the Ring app. I compared this name with the ones I reported above, and the common factor is the presence of spaces in the filename together with the use of parentheses in the filename.

wolpi / prim-ftpd

Primitive-ftpd shuts down unexpectedly with InterruptedIOException when listing specific files. #269