FileZilla "request ID mismatch"

[karatekaneen]

First of all, thank you for this, it has most of what we need and is really helpful.

When testing this out with FileZilla I get a fatal error as "request ID mismatch". It does however work with cyberduck without any problems. Unfortunately my logs are partly in Swedish so below are my translated logs:

Status:         Ansluter till 12.123.123.123:9022...
Status:         Using username "username". 
Status:         Further authentication required 
Status:         Connected to 12.123.123.123
Status:         Listing directory...
Status:         Listing directory /
Error:              FATAL ERROR: unable to understand SFTP response packet from server: request ID mismatch
Error:              Listing Directory failed
Status:         Disconnected from server

And on the server side:

2021-03-26T13:32:46.354Z debug: [sftp-gcs] Client connected!
2021-03-26T13:32:46.497Z debug: [sftp-gcs] authentication: method=none
2021-03-26T13:32:46.497Z debug: [sftp-gcs] We have at least a user to match
2021-03-26T13:32:46.549Z debug: [sftp-gcs] authentication: method=password
2021-03-26T13:32:46.550Z debug: [sftp-gcs] Client authenticated!
2021-03-26T13:32:46.655Z debug: [sftp-gcs] Client SFTP session
2021-03-26T13:32:46.745Z debug: [sftp-gcs] REALPATH<256>: path: "."
2021-03-26T13:32:46.745Z debug: [sftp-gcs] Returning "/"
2021-03-26T13:32:46.792Z debug: [sftp-gcs] REALPATH<256>: path: "/."
2021-03-26T13:32:46.792Z debug: [sftp-gcs] Returning "/"
2021-03-26T13:32:46.838Z debug: [sftp-gcs] OPENDIR<256> path: "/"
2021-03-26T13:32:46.839Z debug: [sftp-gcs] Converted "/" to ""
2021-03-26T13:32:46.884Z debug: [sftp-gcs] READDIR<256>: handle: 0, path: ""
2021-03-26T13:32:46.885Z debug: [sftp-gcs] READDIR<257>: handle: 0, path: ""
2021-03-26T13:32:46.885Z debug: [sftp-gcs] READDIR<258>: handle: 0, path: ""
2021-03-26T13:32:46.885Z debug: [sftp-gcs] READDIR<259>: handle: 0, path: ""
2021-03-26T13:32:46.930Z debug: [sftp-gcs] Client disconnected

PS. Not using filezilla is not a problem for us, just wanted to let you know

[JeffryCA]

Having the same issue.

[jogoldberg]

@kolban-google - I don't know if this is helpful https://forum.filezilla-project.org/viewtopic.php?t=49236

[kmeljko]

Is there any news about this problem?

[kolban-google]

All right chums ... looking at it now.

See also #2

What the SFTP specification says is that an SFTP client (eg. Filezilla) can send in multiple requests concurrently without requiring a response from the server. This then seems to say "If I send a response, how will it know which request the response is for?"

For example, if a client says:

List directory /xyz List directory /abc

and then a while later the SFTP server sends back a list of files ... how do we know whether these are form /xyz or /abc?

And answer is that each request should send in (as part of the request) a "request id". This is an integer. When a response is returned, the response will also return the corresponding request id.

So the protocol flow will be:

List directory /xyz, reqid: 1 List directory /abc, reqid: 2

and the response would be a:

List of files for reqid: 1 List of files for reqid: 2

and all is well.

However, what the reports seem to be saying is that when we use Filezilla, even though it may be sending in multiple requests, it assumes that the requests are processed serially with the corresponding response. This is not what the underlying SSH2 library is designed to do ... and arguably ... not what it should do.

[hec10r]

Any updates on how to solve this?

[karatekaneen]

@hec10r I think my fork might have solved this issue but can't remember. We have since dropped the use of (my fork of) this package and are now using this server instead to use ftp backed by GCS.

[hec10r]

Hi @karatekaneen, thanks for your response. I tried and got the same error 😞.

FileZilla output:

Status:         Disconnected from server
Status:         Connecting to x.x.x.x:9022...
Status:         Using username "prod". 
Status:         Further authentication required 
Status:         Further authentication required 
Status:         Connected to x.x.x.x
Status:         Retrieving directory listing...
Status:         Listing directory /
Error:          FATAL ERROR: unable to understand SFTP response packet from server: request ID mismatch
Error:          Failed to retrieve directory listing
Status:         Disconnected from server
Status:         Connecting to  x.x.x.x:9022...
Status:         Using username "prod". 
Status:         Further authentication required 
Status:         Further authentication required 
Status:         Connected to  x.x.x.x
Status:         Retrieving directory listing...
Status:         Listing directory /
Error:          FATAL ERROR: unable to understand SFTP response packet from server: request ID mismatch
Error:          Failed to retrieve directory listing

Console output:

2023-03-27T19:04:03.087Z debug: [sftp-gcs] No PubKey or no key provided in request
2023-03-27T19:04:03.287Z debug: [sftp-gcs] authentication: method=password
2023-03-27T19:04:03.287Z debug: [sftp-gcs] Client authenticated!
2023-03-27T19:04:04.082Z debug: [sftp-gcs] Client SFTP session initiated
2023-03-27T19:04:04.569Z debug: [sftp-gcs] REALPATH<256>: path: "."
2023-03-27T19:04:04.569Z debug: [sftp-gcs] Returning "/"
2023-03-27T19:04:04.815Z debug: [sftp-gcs] REALPATH<256>: path: "/."
2023-03-27T19:04:04.815Z debug: [sftp-gcs] Returning "/"
2023-03-27T19:04:05.212Z debug: [sftp-gcs] OPENDIR<256> path: "/"
2023-03-27T19:04:05.212Z debug: [sftp-gcs] Converted "/" to ""
2023-03-27T19:04:05.411Z debug: [sftp-gcs] READDIR<256>: handle: 0, path: ""
2023-03-27T19:04:05.412Z debug: [sftp-gcs] READDIR<257>: handle: 0, path: ""
2023-03-27T19:04:05.412Z debug: [sftp-gcs] READDIR<258>: handle: 0, path: ""
2023-03-27T19:04:05.412Z debug: [sftp-gcs] READDIR<259>: handle: 0, path: ""
2023-03-27T19:04:05.715Z debug: [sftp-gcs] Client disconnected