3
votes

I set up an SSH Server as an SFTP Server with Apache Mina SSHD. I implemented my own FileSystemFactory, so that specific directories are created for the user that logs in. When I open a connection to the server with FileZilla, the directory structure is displayed wrong.

enter image description here

In the root directory view, an empty folder is displayed. This one does not exist. There should only be two directories. "Upload" and "Download".

enter image description here

When I open the upload directory, I once again see an empty directory which should not be shown because it does not exist. Furthermore, another upload directory is shown. I can't open it, because it says /upload/upload does not exist, which is true, but I can't figure out why it is shown.

When I connect with WinSCP, I don't get this display error. Does anyone know why it happens or how to solve it?

EDIT:

FileSystemFactory implementation:

public class CustomFileSystemFactory implements FileSystemFactory {
  private String defaultHomeDir;
  private FileSystem fileSystem;

  public CustomFileSystemFactory(String defaultHomeDir){
    this.defaultHomeDir = defaultHomeDir;
  }

  public String getDefaultHome(){
    return defaultHomeDir;
  }

  public FileSystem getFileSystem(){
    return fileSystem;
  }

  @Override
  public FileSystem createFileSystem(Session session) throws IOException {
    Path dir = computeRootDir(session.getUsername());
    if (dir == null) {
      throw new InvalidPathException(session.getUsername(), "Cannot resolve home directory");
    }

    if(!Files.exists(dir)){
      Files.createDirectory(dir);
    }
    setupFolders(session.getUsername());
    FileSystem fileSystem = new RootedFileSystemProvider().newFileSystem(dir, Collections.emptyMap());
    return fileSystem;
  }

  protected Path computeRootDir(String username){
    Path path = Paths.get(defaultHomeDir + Utils.getPrincipalExtId(username) + "/");
    return path;
  }

  protected void setupFolders(String username) throws IOException {
    Path homeDir = computeRootDir(username);
    File uploadFolder = new File(homeDir + "/upload/");
    File downloadFolder = new File(homeDir + "/download/");
    if(!uploadFolder.exists()){
      uploadFolder.mkdirs();
    }
    if(!downloadFolder.exists()){
      downloadFolder.mkdirs();
    }
  }
}

This is the WinSCP Log on Debug Level 2:

. 2016-01-07 14:46:46.909 Listing directory "/".
> 2016-01-07 14:46:46.909 Type: SSH_FXP_OPENDIR, Size: 10, Number: 4107
> 2016-01-07 14:46:46.909 0B,00,00,10,0B,00,00,00,01,2F,
. 2016-01-07 14:46:46.909 Sent 14 bytes
. 2016-01-07 14:46:46.909 There are 0 bytes remaining in the send buffer
. 2016-01-07 14:46:46.909 Looking for network events
. 2016-01-07 14:46:46.909 Timeout waiting for network events
. 2016-01-07 14:46:46.909 Waiting for another 4 bytes
. 2016-01-07 14:46:46.909 Looking for incoming data
. 2016-01-07 14:46:46.909 Looking for network events
. 2016-01-07 14:46:46.913 Detected network event
. 2016-01-07 14:46:46.913 Enumerating network events for socket 1084
. 2016-01-07 14:46:46.913 Enumerated 1 network events making 1 cumulative events for socket 1084
. 2016-01-07 14:46:46.913 Handling network read event on socket 1084 with error 0
. 2016-01-07 14:46:46.913 Received 45 bytes (0)
. 2016-01-07 14:46:46.913 Read 4 bytes (41 pending)
. 2016-01-07 14:46:46.913 Read 41 bytes (0 pending)
< 2016-01-07 14:46:46.913 Type: SSH_FXP_HANDLE, Size: 41, Number: 4107
< 2016-01-07 14:46:46.913 66,00,00,10,0B,00,00,00,20,34,34,30,63,33,34,36,32,62,30,34,65,39,37,32,61,
< 2016-01-07 14:46:46.913 34,39,34,62,62,31,30,64,36,65,62,61,35,65,61,33,
> 2016-01-07 14:46:46.913 Type: SSH_FXP_READDIR, Size: 41, Number: 4364
> 2016-01-07 14:46:46.913 0C,00,00,11,0C,00,00,00,20,34,34,30,63,33,34,36,32,62,30,34,65,39,37,32,61,
> 2016-01-07 14:46:46.913 34,39,34,62,62,31,30,64,36,65,62,61,35,65,61,33,
. 2016-01-07 14:46:46.913 Sent 45 bytes
. 2016-01-07 14:46:46.914 There are 0 bytes remaining in the send buffer
. 2016-01-07 14:46:46.914 Looking for network events
. 2016-01-07 14:46:46.914 Timeout waiting for network events
. 2016-01-07 14:46:46.914 Waiting for another 4 bytes
. 2016-01-07 14:46:46.914 Looking for incoming data
. 2016-01-07 14:46:46.914 Looking for network events
. 2016-01-07 14:46:46.924 Detected network event
. 2016-01-07 14:46:46.924 Enumerating network events for socket 1084
. 2016-01-07 14:46:46.924 Enumerated 1 network events making 1 cumulative events for socket 1084
. 2016-01-07 14:46:46.924 Handling network read event on socket 1084 with error 0
. 2016-01-07 14:46:46.925 Received 1113 bytes (0)
. 2016-01-07 14:46:46.925 Read 4 bytes (1109 pending)
. 2016-01-07 14:46:46.925 Read 1109 bytes (0 pending)
< 2016-01-07 14:46:46.925 Type: SSH_FXP_NAME, Size: 1109, Number: 4364
< 2016-01-07 14:46:46.925 68,00,00,11,0C,00,00,00,03,00,00,00,01,2E,00,00,00,7C,02,00,00,41,B6,00,00,
< 2016-01-07 14:46:46.925 00,00,56,79,11,96,00,00,00,00,56,79,11,96,00,00,00,00,56,79,11,96,00,00,01,
< 2016-01-07 14:46:46.925 37,00,00,00,07,00,00,00,00,00,00,00,00,00,1F,01,FF,00,00,00,1C,56,4F,52,44,
< 2016-01-07 14:46:46.925 45,46,49,4E,49,45,52,54,5C,41,64,6D,69,6E,69,73,74,72,61,74,6F,72,65,6E,00,
< 2016-01-07 14:46:46.925 00,00,00,00,00,00,0B,00,00,00,00,00,00,00,1C,56,4F,52,44,45,46,49,4E,49,45,
< 2016-01-07 14:46:46.925 52,54,5C,41,64,6D,69,6E,69,73,74,72,61,74,6F,72,65,6E,00,00,00,00,00,00,00,
< 2016-01-07 14:46:46.925 00,00,1F,01,FF,00,00,00,14,4E,54,2D,41,55,54,4F,52,49,54,C3,84,54,5C,53,59,
< 2016-01-07 14:46:46.925 53,54,45,4D,00,00,00,00,00,00,00,0B,00,00,00,00,00,00,00,14,4E,54,2D,41,55,
< 2016-01-07 14:46:46.925 54,4F,52,49,54,C3,84,54,5C,53,59,53,54,45,4D,00,00,00,00,00,00,00,03,00,12,
< 2016-01-07 14:46:46.925 00,A9,00,00,00,15,56,4F,52,44,45,46,49,4E,49,45,52,54,5C,42,65,6E,75,74,7A,
< 2016-01-07 14:46:46.925 65,72,00,00,00,00,00,00,00,00,00,13,01,BF,00,00,00,27,4E,54,2D,41,55,54,4F,
< 2016-01-07 14:46:46.925 52,49,54,C3,84,54,5C,41,75,74,68,65,6E,74,69,66,69,7A,69,65,72,74,65,20,42,
< 2016-01-07 14:46:46.925 65,6E,75,74,7A,65,72,00,00,00,00,00,00,00,0B,00,01,00,00,00,00,00,27,4E,54,
< 2016-01-07 14:46:46.925 2D,41,55,54,4F,52,49,54,C3,84,54,5C,41,75,74,68,65,6E,74,69,66,69,7A,69,65,
< 2016-01-07 14:46:46.925 72,74,65,20,42,65,6E,75,74,7A,65,72,00,00,00,08,64,6F,77,6E,6C,6F,61,64,00,
< 2016-01-07 14:46:46.925 00,00,7C,02,00,00,41,B6,00,00,00,00,56,8E,52,55,00,00,00,00,56,8E,52,55,00,
< 2016-01-07 14:46:46.925 00,00,00,56,8E,52,55,00,00,01,54,00,00,00,08,00,00,00,00,00,00,00,03,00,1F,
< 2016-01-07 14:46:46.925 01,FF,00,00,00,0D,44,55,53,5C,6E,6D,65,63,6B,6D,61,6E,6E,00,00,00,00,00,00,
< 2016-01-07 14:46:46.925 00,00,00,1F,01,FF,00,00,00,1C,56,4F,52,44,45,46,49,4E,49,45,52,54,5C,41,64,
< 2016-01-07 14:46:46.925 6D,69,6E,69,73,74,72,61,74,6F,72,65,6E,00,00,00,00,00,00,00,0B,00,00,00,00,
< 2016-01-07 14:46:46.925 00,00,00,1C,56,4F,52,44,45,46,49,4E,49,45,52,54,5C,41,64,6D,69,6E,69,73,74,
< 2016-01-07 14:46:46.925 72,61,74,6F,72,65,6E,00,00,00,00,00,00,00,00,00,1F,01,FF,00,00,00,14,4E,54,
< 2016-01-07 14:46:46.925 2D,41,55,54,4F,52,49,54,C3,84,54,5C,53,59,53,54,45,4D,00,00,00,00,00,00,00,
< 2016-01-07 14:46:46.925 0B,00,00,00,00,00,00,00,14,4E,54,2D,41,55,54,4F,52,49,54,C3,84,54,5C,53,59,
< 2016-01-07 14:46:46.925 53,54,45,4D,00,00,00,00,00,00,00,03,00,12,00,A9,00,00,00,15,56,4F,52,44,45,
< 2016-01-07 14:46:46.925 46,49,4E,49,45,52,54,5C,42,65,6E,75,74,7A,65,72,00,00,00,00,00,00,00,00,00,
< 2016-01-07 14:46:46.925 13,01,BF,00,00,00,27,4E,54,2D,41,55,54,4F,52,49,54,C3,84,54,5C,41,75,74,68,
< 2016-01-07 14:46:46.925 65,6E,74,69,66,69,7A,69,65,72,74,65,20,42,65,6E,75,74,7A,65,72,00,00,00,00,
< 2016-01-07 14:46:46.925 00,00,00,0B,00,01,00,00,00,00,00,27,4E,54,2D,41,55,54,4F,52,49,54,C3,84,54,
< 2016-01-07 14:46:46.925 5C,41,75,74,68,65,6E,74,69,66,69,7A,69,65,72,74,65,20,42,65,6E,75,74,7A,65,
< 2016-01-07 14:46:46.925 72,00,00,00,06,75,70,6C,6F,61,64,00,00,00,7C,02,00,00,41,B6,00,00,00,00,56,
< 2016-01-07 14:46:46.925 8E,51,ED,00,00,00,00,56,8E,51,ED,00,00,00,00,56,8E,51,ED,00,00,01,37,00,00,
< 2016-01-07 14:46:46.925 00,07,00,00,00,00,00,00,00,00,00,1F,01,FF,00,00,00,1C,56,4F,52,44,45,46,49,
< 2016-01-07 14:46:46.925 4E,49,45,52,54,5C,41,64,6D,69,6E,69,73,74,72,61,74,6F,72,65,6E,00,00,00,00,
< 2016-01-07 14:46:46.925 00,00,00,0B,00,00,00,00,00,00,00,1C,56,4F,52,44,45,46,49,4E,49,45,52,54,5C,
< 2016-01-07 14:46:46.925 41,64,6D,69,6E,69,73,74,72,61,74,6F,72,65,6E,00,00,00,00,00,00,00,00,00,1F,
< 2016-01-07 14:46:46.925 01,FF,00,00,00,14,4E,54,2D,41,55,54,4F,52,49,54,C3,84,54,5C,53,59,53,54,45,
< 2016-01-07 14:46:46.925 4D,00,00,00,00,00,00,00,0B,00,00,00,00,00,00,00,14,4E,54,2D,41,55,54,4F,52,
< 2016-01-07 14:46:46.925 49,54,C3,84,54,5C,53,59,53,54,45,4D,00,00,00,00,00,00,00,03,00,12,00,A9,00,
< 2016-01-07 14:46:46.925 00,00,15,56,4F,52,44,45,46,49,4E,49,45,52,54,5C,42,65,6E,75,74,7A,65,72,00,
< 2016-01-07 14:46:46.925 00,00,00,00,00,00,00,00,13,01,BF,00,00,00,27,4E,54,2D,41,55,54,4F,52,49,54,
< 2016-01-07 14:46:46.925 C3,84,54,5C,41,75,74,68,65,6E,74,69,66,69,7A,69,65,72,74,65,20,42,65,6E,75,
< 2016-01-07 14:46:46.925 74,7A,65,72,00,00,00,00,00,00,00,0B,00,01,00,00,00,00,00,27,4E,54,2D,41,55,
< 2016-01-07 14:46:46.926 54,4F,52,49,54,C3,84,54,5C,41,75,74,68,65,6E,74,69,66,69,7A,69,65,72,74,65,
< 2016-01-07 14:46:46.926 20,42,65,6E,75,74,7A,65,72,
> 2016-01-07 14:46:46.926 Type: SSH_FXP_READDIR, Size: 41, Number: 4620
> 2016-01-07 14:46:46.926 0C,00,00,12,0C,00,00,00,20,34,34,30,63,33,34,36,32,62,30,34,65,39,37,32,61,
> 2016-01-07 14:46:46.926 34,39,34,62,62,31,30,64,36,65,62,61,35,65,61,33,
. 2016-01-07 14:46:46.926 Sent 45 bytes
. 2016-01-07 14:46:46.926 There are 0 bytes remaining in the send buffer
. 2016-01-07 14:46:46.926 Looking for network events
. 2016-01-07 14:46:46.926 Timeout waiting for network events
. 2016-01-07 14:46:46.926 Read file '.' from listing
. 2016-01-07 14:46:46.926 Read file 'download' from listing
. 2016-01-07 14:46:46.926 Read file 'upload' from listing
. 2016-01-07 14:46:46.926 Waiting for another 4 bytes
. 2016-01-07 14:46:46.926 Looking for incoming data
. 2016-01-07 14:46:46.926 Looking for network events
. 2016-01-07 14:46:46.926 Detected network event
. 2016-01-07 14:46:46.926 Enumerating network events for socket 1084
. 2016-01-07 14:46:46.926 Enumerated 1 network events making 1 cumulative events for socket 1084
. 2016-01-07 14:46:46.926 Handling network read event on socket 1084 with error 0
. 2016-01-07 14:46:46.926 Received 46 bytes (0)
. 2016-01-07 14:46:46.926 Read 4 bytes (42 pending)
. 2016-01-07 14:46:46.926 Read 42 bytes (0 pending)
< 2016-01-07 14:46:46.926 Type: SSH_FXP_STATUS, Size: 42, Number: 4620
< 2016-01-07 14:46:46.926 65,00,00,12,0C,00,00,00,01,00,00,00,19,44,69,72,65,63,74,6F,72,79,20,72,65,
< 2016-01-07 14:46:46.926 61,64,69,6E,67,20,69,73,20,64,6F,6E,65,00,00,00,00,
< 2016-01-07 14:46:46.926 Status code: 1
> 2016-01-07 14:46:46.926 Type: SSH_FXP_CLOSE, Size: 41, Number: 4868
> 2016-01-07 14:46:46.926 04,00,00,13,04,00,00,00,20,34,34,30,63,33,34,36,32,62,30,34,65,39,37,32,61,
> 2016-01-07 14:46:46.926 34,39,34,62,62,31,30,64,36,65,62,61,35,65,61,33,
. 2016-01-07 14:46:46.926 Sent 45 bytes
. 2016-01-07 14:46:46.926 There are 0 bytes remaining in the send buffer
. 2016-01-07 14:46:46.926 Looking for network events
. 2016-01-07 14:46:46.926 Timeout waiting for network events
. 2016-01-07 14:46:46.927 download;D;0;2016-01-07T11:56:05.000Z;"" [0];"" [0];rw-rw-rw-;1
. 2016-01-07 14:46:46.927 upload;D;0;2016-01-07T11:54:21.000Z;"" [0];"" [0];rw-rw-rw-;1
. 2016-01-07 14:46:47.009 Startup conversation with host finished.
. 2016-01-07 14:46:47.122 Session upkeep
. 2016-01-07 14:46:47.122 Looking for network events
. 2016-01-07 14:46:47.122 Detected network event
. 2016-01-07 14:46:47.122 Enumerating network events for socket 1084
. 2016-01-07 14:46:47.122 Enumerated 1 network events making 1 cumulative events for socket 1084
. 2016-01-07 14:46:47.122 Handling network read event on socket 1084 with error 0
. 2016-01-07 14:46:47.122 Received 21 bytes (0)
. 2016-01-07 14:46:47.124 Session upkeep
. 2016-01-07 14:46:47.124 Looking for network events
. 2016-01-07 14:46:47.124 Timeout waiting for network events
. 2016-01-07 14:46:47.257 Session upkeep
. 2016-01-07 14:46:47.257 Looking for network events
. 2016-01-07 14:46:47.257 Timeout waiting for network events
. 2016-01-07 14:46:47.768 Session upkeep
. 2016-01-07 14:46:47.768 Looking for network events
. 2016-01-07 14:46:47.768 Timeout waiting for network events
. 2016-01-07 14:46:48.267 Session upkeep
. 2016-01-07 14:46:48.267 Looking for network events
. 2016-01-07 14:46:48.267 Timeout waiting for network events
. 2016-01-07 14:46:48.781 Session upkeep
. 2016-01-07 14:46:48.782 Looking for network events
. 2016-01-07 14:46:48.782 Timeout waiting for network events
. 2016-01-07 14:46:48.832 Cached directory change via "download" to "/download".
. 2016-01-07 14:46:48.832 Getting current directory name.
. 2016-01-07 14:46:48.832 Listing directory "/download".
> 2016-01-07 14:46:48.832 Type: SSH_FXP_OPENDIR, Size: 18, Number: 5131
> 2016-01-07 14:46:48.832 0B,00,00,14,0B,00,00,00,09,2F,64,6F,77,6E,6C,6F,61,64,
. 2016-01-07 14:46:48.832 Sent 22 bytes
. 2016-01-07 14:46:48.832 There are 0 bytes remaining in the send buffer
. 2016-01-07 14:46:48.832 Looking for network events
. 2016-01-07 14:46:48.834 Timeout waiting for network events
. 2016-01-07 14:46:48.834 Read 4 bytes (17 pending)
. 2016-01-07 14:46:48.834 Read 17 bytes (0 pending)
< 2016-01-07 14:46:48.834 Type: SSH_FXP_STATUS, Size: 17, Number: 4868
< 2016-01-07 14:46:48.834 65,00,00,13,04,00,00,00,00,00,00,00,00,00,00,00,00,
. 2016-01-07 14:46:48.834 Discarding reserved response
. 2016-01-07 14:46:48.834 Waiting for another 4 bytes
. 2016-01-07 14:46:48.834 Looking for incoming data
. 2016-01-07 14:46:48.834 Looking for network events
. 2016-01-07 14:46:48.834 Detected network event
. 2016-01-07 14:46:48.834 Enumerating network events for socket 1084
. 2016-01-07 14:46:48.834 Enumerated 1 network events making 1 cumulative events for socket 1084
. 2016-01-07 14:46:48.834 Handling network read event on socket 1084 with error 0
. 2016-01-07 14:46:48.834 Received 45 bytes (0)
. 2016-01-07 14:46:48.834 Read 4 bytes (41 pending)
. 2016-01-07 14:46:48.834 Read 41 bytes (0 pending)
< 2016-01-07 14:46:48.834 Type: SSH_FXP_HANDLE, Size: 41, Number: 5131
< 2016-01-07 14:46:48.834 66,00,00,14,0B,00,00,00,20,30,61,33,38,32,30,37,31,37,64,61,65,34,34,39,61,
< 2016-01-07 14:46:48.834 30,31,66,36,32,65,35,61,33,34,65,34,30,33,39,34,
> 2016-01-07 14:46:48.834 Type: SSH_FXP_READDIR, Size: 41, Number: 5388
> 2016-01-07 14:46:48.834 0C,00,00,15,0C,00,00,00,20,30,61,33,38,32,30,37,31,37,64,61,65,34,34,39,61,
> 2016-01-07 14:46:48.834 30,31,66,36,32,65,35,61,33,34,65,34,30,33,39,34,
. 2016-01-07 14:46:48.835 Sent 45 bytes
. 2016-01-07 14:46:48.835 There are 0 bytes remaining in the send buffer
. 2016-01-07 14:46:48.835 Looking for network events
. 2016-01-07 14:46:48.835 Timeout waiting for network events
. 2016-01-07 14:46:48.835 Waiting for another 4 bytes
. 2016-01-07 14:46:48.835 Looking for incoming data
. 2016-01-07 14:46:48.835 Looking for network events
. 2016-01-07 14:46:48.840 Detected network event
. 2016-01-07 14:46:48.840 Enumerating network events for socket 1084
. 2016-01-07 14:46:48.840 Enumerated 1 network events making 1 cumulative events for socket 1084
. 2016-01-07 14:46:48.840 Handling network read event on socket 1084 with error 0
. 2016-01-07 14:46:48.840 Received 749 bytes (0)
. 2016-01-07 14:46:48.840 Read 4 bytes (745 pending)
. 2016-01-07 14:46:48.840 Read 745 bytes (0 pending)
< 2016-01-07 14:46:48.840 Type: SSH_FXP_NAME, Size: 745, Number: 5388
< 2016-01-07 14:46:48.840 68,00,00,15,0C,00,00,00,02,00,00,00,01,2E,00,00,00,7C,02,00,00,41,B6,00,00,
< 2016-01-07 14:46:48.840 00,00,56,8E,52,55,00,00,00,00,56,8E,52,55,00,00,00,00,56,8E,52,55,00,00,01,
< 2016-01-07 14:46:48.840 54,00,00,00,08,00,00,00,00,00,00,00,03,00,1F,01,FF,00,00,00,0D,44,55,53,5C,
< 2016-01-07 14:46:48.840 6E,6D,65,63,6B,6D,61,6E,6E,00,00,00,00,00,00,00,00,00,1F,01,FF,00,00,00,1C,
< 2016-01-07 14:46:48.840 56,4F,52,44,45,46,49,4E,49,45,52,54,5C,41,64,6D,69,6E,69,73,74,72,61,74,6F,
< 2016-01-07 14:46:48.840 72,65,6E,00,00,00,00,00,00,00,0B,00,00,00,00,00,00,00,1C,56,4F,52,44,45,46,
< 2016-01-07 14:46:48.840 49,4E,49,45,52,54,5C,41,64,6D,69,6E,69,73,74,72,61,74,6F,72,65,6E,00,00,00,
< 2016-01-07 14:46:48.840 00,00,00,00,00,00,1F,01,FF,00,00,00,14,4E,54,2D,41,55,54,4F,52,49,54,C3,84,
< 2016-01-07 14:46:48.840 54,5C,53,59,53,54,45,4D,00,00,00,00,00,00,00,0B,00,00,00,00,00,00,00,14,4E,
< 2016-01-07 14:46:48.840 54,2D,41,55,54,4F,52,49,54,C3,84,54,5C,53,59,53,54,45,4D,00,00,00,00,00,00,
< 2016-01-07 14:46:48.840 00,03,00,12,00,A9,00,00,00,15,56,4F,52,44,45,46,49,4E,49,45,52,54,5C,42,65,
< 2016-01-07 14:46:48.840 6E,75,74,7A,65,72,00,00,00,00,00,00,00,00,00,13,01,BF,00,00,00,27,4E,54,2D,
< 2016-01-07 14:46:48.840 41,55,54,4F,52,49,54,C3,84,54,5C,41,75,74,68,65,6E,74,69,66,69,7A,69,65,72,
< 2016-01-07 14:46:48.840 74,65,20,42,65,6E,75,74,7A,65,72,00,00,00,00,00,00,00,0B,00,01,00,00,00,00,
< 2016-01-07 14:46:48.840 00,27,4E,54,2D,41,55,54,4F,52,49,54,C3,84,54,5C,41,75,74,68,65,6E,74,69,66,
< 2016-01-07 14:46:48.840 69,7A,69,65,72,74,65,20,42,65,6E,75,74,7A,65,72,00,00,00,02,2E,2E,00,00,00,
< 2016-01-07 14:46:48.840 7C,02,00,00,41,B6,00,00,00,00,56,79,11,96,00,00,00,00,56,79,11,96,00,00,00,
< 2016-01-07 14:46:48.840 00,56,79,11,96,00,00,01,37,00,00,00,07,00,00,00,00,00,00,00,00,00,1F,01,FF,
< 2016-01-07 14:46:48.840 00,00,00,1C,56,4F,52,44,45,46,49,4E,49,45,52,54,5C,41,64,6D,69,6E,69,73,74,
< 2016-01-07 14:46:48.840 72,61,74,6F,72,65,6E,00,00,00,00,00,00,00,0B,00,00,00,00,00,00,00,1C,56,4F,
< 2016-01-07 14:46:48.840 52,44,45,46,49,4E,49,45,52,54,5C,41,64,6D,69,6E,69,73,74,72,61,74,6F,72,65,
< 2016-01-07 14:46:48.840 6E,00,00,00,00,00,00,00,00,00,1F,01,FF,00,00,00,14,4E,54,2D,41,55,54,4F,52,
< 2016-01-07 14:46:48.840 49,54,C3,84,54,5C,53,59,53,54,45,4D,00,00,00,00,00,00,00,0B,00,00,00,00,00,
< 2016-01-07 14:46:48.840 00,00,14,4E,54,2D,41,55,54,4F,52,49,54,C3,84,54,5C,53,59,53,54,45,4D,00,00,
< 2016-01-07 14:46:48.840 00,00,00,00,00,03,00,12,00,A9,00,00,00,15,56,4F,52,44,45,46,49,4E,49,45,52,
< 2016-01-07 14:46:48.840 54,5C,42,65,6E,75,74,7A,65,72,00,00,00,00,00,00,00,00,00,13,01,BF,00,00,00,
< 2016-01-07 14:46:48.840 27,4E,54,2D,41,55,54,4F,52,49,54,C3,84,54,5C,41,75,74,68,65,6E,74,69,66,69,
< 2016-01-07 14:46:48.840 7A,69,65,72,74,65,20,42,65,6E,75,74,7A,65,72,00,00,00,00,00,00,00,0B,00,01,
< 2016-01-07 14:46:48.840 00,00,00,00,00,27,4E,54,2D,41,55,54,4F,52,49,54,C3,84,54,5C,41,75,74,68,65,
< 2016-01-07 14:46:48.841 6E,74,69,66,69,7A,69,65,72,74,65,20,42,65,6E,75,74,7A,65,72,
> 2016-01-07 14:46:48.841 Type: SSH_FXP_READDIR, Size: 41, Number: 5644
> 2016-01-07 14:46:48.841 0C,00,00,16,0C,00,00,00,20,30,61,33,38,32,30,37,31,37,64,61,65,34,34,39,61,
> 2016-01-07 14:46:48.841 30,31,66,36,32,65,35,61,33,34,65,34,30,33,39,34,
. 2016-01-07 14:46:48.841 Sent 45 bytes
. 2016-01-07 14:46:48.841 There are 0 bytes remaining in the send buffer
. 2016-01-07 14:46:48.841 Looking for network events
. 2016-01-07 14:46:48.841 Timeout waiting for network events
. 2016-01-07 14:46:48.841 Read file '.' from listing
. 2016-01-07 14:46:48.841 Read file '..' from listing
. 2016-01-07 14:46:48.841 Waiting for another 4 bytes
. 2016-01-07 14:46:48.841 Looking for incoming data
. 2016-01-07 14:46:48.841 Looking for network events
. 2016-01-07 14:46:48.841 Detected network event
. 2016-01-07 14:46:48.841 Enumerating network events for socket 1084
. 2016-01-07 14:46:48.841 Enumerated 1 network events making 1 cumulative events for socket 1084
. 2016-01-07 14:46:48.841 Handling network read event on socket 1084 with error 0
. 2016-01-07 14:46:48.841 Received 46 bytes (0)
. 2016-01-07 14:46:48.841 Read 4 bytes (42 pending)
. 2016-01-07 14:46:48.841 Read 42 bytes (0 pending)
< 2016-01-07 14:46:48.841 Type: SSH_FXP_STATUS, Size: 42, Number: 5644
< 2016-01-07 14:46:48.841 65,00,00,16,0C,00,00,00,01,00,00,00,19,44,69,72,65,63,74,6F,72,79,20,72,65,
< 2016-01-07 14:46:48.841 61,64,69,6E,67,20,69,73,20,64,6F,6E,65,00,00,00,00,
< 2016-01-07 14:46:48.842 Status code: 1
> 2016-01-07 14:46:48.842 Type: SSH_FXP_CLOSE, Size: 41, Number: 5892
> 2016-01-07 14:46:48.842 04,00,00,17,04,00,00,00,20,30,61,33,38,32,30,37,31,37,64,61,65,34,34,39,61,
> 2016-01-07 14:46:48.842 30,31,66,36,32,65,35,61,33,34,65,34,30,33,39,34,
. 2016-01-07 14:46:48.842 Sent 45 bytes
. 2016-01-07 14:46:48.842 There are 0 bytes remaining in the send buffer
. 2016-01-07 14:46:48.842 Looking for network events
. 2016-01-07 14:46:48.842 Timeout waiting for network events
. 2016-01-07 14:46:48.842 ..;D;0;2015-12-22T09:02:14.000Z;"" [0];"" [0];rw-rw-rw-;1
. 2016-01-07 14:46:49.283 Session upkeep
. 2016-01-07 14:46:49.283 Looking for network events
. 2016-01-07 14:46:49.283 Detected network event
. 2016-01-07 14:46:49.283 Enumerating network events for socket 1084
. 2016-01-07 14:46:49.283 Enumerated 1 network events making 1 cumulative events for socket 1084
. 2016-01-07 14:46:49.283 Handling network read event on socket 1084 with error 0
. 2016-01-07 14:46:49.283 Received 21 bytes (0)
. 2016-01-07 14:46:49.472 Cached directory change via ".." to "/".
. 2016-01-07 14:46:49.472 Getting current directory name.
. 2016-01-07 14:46:49.473 Directory content loaded from cache.
. 2016-01-07 14:46:49.795 Session upkeep
. 2016-01-07 14:46:49.795 Looking for network events
. 2016-01-07 14:46:49.795 Timeout waiting for network events
. 2016-01-07 14:46:49.880 Cached directory change via "upload" to "/upload".
. 2016-01-07 14:46:49.880 Getting current directory name.
. 2016-01-07 14:46:49.881 Listing directory "/upload".
> 2016-01-07 14:46:49.881 Type: SSH_FXP_OPENDIR, Size: 16, Number: 6155
> 2016-01-07 14:46:49.881 0B,00,00,18,0B,00,00,00,07,2F,75,70,6C,6F,61,64,
. 2016-01-07 14:46:49.881 Sent 20 bytes
. 2016-01-07 14:46:49.881 There are 0 bytes remaining in the send buffer
. 2016-01-07 14:46:49.881 Looking for network events
. 2016-01-07 14:46:49.882 Timeout waiting for network events
. 2016-01-07 14:46:49.882 Read 4 bytes (17 pending)
. 2016-01-07 14:46:49.882 Read 17 bytes (0 pending)
< 2016-01-07 14:46:49.882 Type: SSH_FXP_STATUS, Size: 17, Number: 5892
< 2016-01-07 14:46:49.882 65,00,00,17,04,00,00,00,00,00,00,00,00,00,00,00,00,
. 2016-01-07 14:46:49.882 Discarding reserved response
. 2016-01-07 14:46:49.882 Waiting for another 4 bytes
. 2016-01-07 14:46:49.882 Looking for incoming data
. 2016-01-07 14:46:49.882 Looking for network events
. 2016-01-07 14:46:49.882 Detected network event
. 2016-01-07 14:46:49.882 Enumerating network events for socket 1084
. 2016-01-07 14:46:49.883 Enumerated 1 network events making 1 cumulative events for socket 1084
. 2016-01-07 14:46:49.883 Handling network read event on socket 1084 with error 0
. 2016-01-07 14:46:49.883 Received 45 bytes (0)
. 2016-01-07 14:46:49.883 Read 4 bytes (41 pending)
. 2016-01-07 14:46:49.883 Read 41 bytes (0 pending)
< 2016-01-07 14:46:49.883 Type: SSH_FXP_HANDLE, Size: 41, Number: 6155
< 2016-01-07 14:46:49.883 66,00,00,18,0B,00,00,00,20,30,38,61,36,35,34,38,66,61,36,39,63,66,31,64,37,
< 2016-01-07 14:46:49.883 65,31,33,34,32,33,63,32,61,30,32,30,35,33,63,37,
> 2016-01-07 14:46:49.883 Type: SSH_FXP_READDIR, Size: 41, Number: 6412
> 2016-01-07 14:46:49.883 0C,00,00,19,0C,00,00,00,20,30,38,61,36,35,34,38,66,61,36,39,63,66,31,64,37,
> 2016-01-07 14:46:49.883 65,31,33,34,32,33,63,32,61,30,32,30,35,33,63,37,
. 2016-01-07 14:46:49.883 Sent 45 bytes
. 2016-01-07 14:46:49.883 There are 0 bytes remaining in the send buffer
. 2016-01-07 14:46:49.883 Looking for network events
. 2016-01-07 14:46:49.883 Timeout waiting for network events
. 2016-01-07 14:46:49.883 Waiting for another 4 bytes
. 2016-01-07 14:46:49.883 Looking for incoming data
. 2016-01-07 14:46:49.883 Looking for network events
. 2016-01-07 14:46:49.889 Detected network event
. 2016-01-07 14:46:49.890 Enumerating network events for socket 1084
. 2016-01-07 14:46:49.890 Enumerated 1 network events making 1 cumulative events for socket 1084
. 2016-01-07 14:46:49.890 Handling network read event on socket 1084 with error 0
. 2016-01-07 14:46:49.890 Received 720 bytes (0)
. 2016-01-07 14:46:49.890 Read 4 bytes (716 pending)
. 2016-01-07 14:46:49.890 Read 716 bytes (0 pending)

Greetings

1
Show us a session log file from both WinSCP and FileZilla (a real log file, not the message log from GUI).Martin Prikryl
I added both log files. Hope that is what you wanted to see?nlsn
Sorry, I didn't realize it's SFTP, so that the listing won't be seen in the plain log. Can you add "Debug 2"-level log from WinSCP? Also show us your file system code.Martin Prikryl
I added my implementation for the FileSystemFactory. Is it actually necessary to add the "Debug 2" level of the WinSCP log? WinSCP is working as intended.nlsn
From the Debug 2 log, we can see the listing that your server is sending to WinSCP.Martin Prikryl

1 Answers

1
votes

The problem is solved in Apache Mina SSHD 1.1.0, see


Keeping the solution for earlier versions:

The problem is partly on both sides, the Mina SSHD server and the FileZilla client.

In the SFTP version 3 (that FileZilla uses), an entry for each file contains both a structured metadata and a display-only string (aka longname field) with a similar format as in the *nix ls -l command. That display-only string should not be parsed.

But FileZilla does parse it, instead of using the structured metadata (except for a file timestamp). An internal psftp process that FileZilla uses to implement the SFTP protocol provides only this information to a parent FileZilla process (an sftp_cmd_ls function):

if (ournames[i]->attrs.flags & SSH_FILEXFER_ATTR_ACMODTIME) {
    mtime = ournames[i]->attrs.mtime;
}
fzprintf(sftpListentry, "%lu %s", mtime, ournames[i]->longname);

The Mina SSHD/SFTP (the SftpSubsystem class), when listing the . and .. meta-directories, incorrectly uses a current folder name and a parent folder name in the display-only string, instead of the . and ... It correctly uses the . and .. in the structured medata (a shortname field).


FileZilla reads the wrong names from the listing and gets confused, treating the entries as actual subdirectory entries, instead of the meta-directories.

In the root directory, both the . and .. are probably listed as /. The FileZilla trims everything until the last /, leading to the empty entry (and the two same-named [empty-named] entries are probably merged into one).

So instead of

.
..
upload
download

the FileZilla sees

/ [treated as an empty string]
/ [treated as an empty string and ignored as duplicate]
upload
download   

In the upload directory, the . is listed as upload and the .. as / (leading to the empty entry).

So instead of

.
..

the FileZilla sees

upload
/ [treated as an empty string]

WinSCP, on the contrary, never uses the display-only string to resolve the file/directory name. And mainly (if the server supports that, what Mina SSHD does) uses the SFTP version 4, that does not even include the display-only string.


To fix the problem, you need pass a shortName parameter of SftpSubsystem.writeDirEntry method to the called .getLongName method. And modify the .getLongName to use shortName in the string it returns instead of getShortName(f).

See below a modified code of SftpSubsystem with comments describing the changes. The code is from Mina SSHD version 1.0

protected void writeDirEntry(int id, DirectoryHandle dir, Buffer buffer, int index, Path f, String shortName, LinkOption... options) throws IOException {
   ...
    if (version == SFTP_V3) {
        // added shortName argument
        String longName = getLongName(f, options, shortName);
    } else {
    ...
}

// added shortName parameter
protected String getLongName(Path f, LinkOption... options, String shortName) throws IOException {
    // added shortName argument
    return getLongName(f, true, options, shortName);
}

// added shortName parameter
private String getLongName(Path f, boolean sendAttrs, LinkOption... options, String shortName) throws IOException {
    ...
    // added shortName argument
    return getLongName(f, attributes, shortName);
}

// added shortName parameter
private String getLongName(Path f, Map<String, ?> attributes, String shortName) throws IOException {
    ...
    return (SftpHelper.getBool(isDirectory) ? "d" : (SftpHelper.getBool(isLink) ? "l" : "-"))
            + PosixFilePermissions.toString(perms) + "  "
            + (attributes.containsKey("nlink") ? attributes.get("nlink") : "1")
            + " " + username + " " + group + " " + lengthString + " "
            + UnixDateFormat.getUnixDate((FileTime) attributes.get("lastModifiedTime"))
            // using shortName instead of getShortName(f) 
            + " " + shortName;
}

// + you need to modify sendPath to pass getShortName(f) 
//   to its call to getLongName

I do not do Java, so excuse any broken code.


Consider reporting the bug to the Mina SSHD project. Link the issue here, if you do.