Commands sent in wrong order when uploading directories, resulting in files not uploaded

[teo8976]

Steps to reproduce:

• connect to a server
• on the local side (left), select a few folders
• right-click and upload

Expected result:

• for each folder, it should OBVIOUSLY first create the folder, then upload the files.

Observed results:

• for each folder, systematically, the "put" command to upload the first file in the folder is sent BEFORE the mkdir command to create the folder. So, unless the folder already existed on the server, that file upload gives an error and is not uploaded.

ALSO, whenever a file gives an error it should be kept in the queue so that you can retry!!!

This level of unreliability make FileZilla completely unusable. You have to check all the files one by one, because there may have been any such random error and you wouldn't even know.

I think this is a regression. I have used FileZilla for ages and had never seen such a thing before.

Example log when uploading a folder called "runtime" within one called "protected":

Status: Starting upload of /home/teo/Documents/xxxxx/protected/runtime/application.log.4
Error: Directory /srv/www/xxxxx/protected/runtime: no such file or directory
Command: cd "/srv/www/xxxxx/protected"
Response: New directory is: "/srv/www/xxxxx/protected"
Command: mkdir "runtime"

[teo8976]

Please somebody tell me to which version I should downgrade to get rid of this bug until it's fixed. This is a disaster.

Also, I need to know whether the same happens on download because then I may have lost random files while doing a backup on a server and I need to redo it.

[Tim Kosse]

This is not a critical issue as it is neither a security vulnerability nor renders FileZilla completely useless.

[Tim Kosse]

Which version of FileZilla are you using?

If it's the latest version as stated on the FileZilla website, please attach a complete log showing the issue.

[teo8976]

It's 3.7.3, the latest available as a package for Ubuntu (assuming that automatic updates are working properly).

By log do you mean the one I can copy and paste from the topmost panel, or some log file?

Do you realize that this means that you may upload several GB worth on data and almost certainly there will be some random missing file in almost each folder? Don't you consider that critical for an ftp client? An ftp client that is not reliable _is_ useless.

If at least failed uploads/downloads remained in the queue or there was a final message with a summary of all failed uploads/downloads (not buried among thousands of other lines of log for all succsesfull actions), then one could know exactly which files need to be transferred again.
But perhaps that should be treated as a separate (also critical) issue.

[teo8976]

I've just noticed that this happens systematically with a given server, and not on another. I still don't see a way this could possibly not be a bug in the client, whatever is going on on the server. The client is performing operations in the wrong order, attempting to upload a file before creating the folder that is coing to cointain it.

Here's a complete log.
Obviously I'll strip out the server name:

Status: Connecting to xxxxxxxx.net...
Response: fzSftp started
Command: open "xxxxxxxx@…" 22
Command: Pass: *
Status: Connected to xxxxxxxx.net
Status: Retrieving directory listing...
Command: cd "/srv/www/xxxxxxxx.net/public_html"
Response: New directory is: "/srv/www/xxxxxxxx.net/public_html"
Command: ls
Status: Listing directory /srv/www/xxxxxxxx.net/public_html
Status: Calculating timezone offset of server...
Command: mtime "images"
Response: 1413850639
Status: Timezone offsets: Server: 0 seconds. Local: 7200 seconds. Difference: 7200 seconds.
Status: Directory listing successful
Status: Connecting to xxxxxxxx.net...
Status: Connecting to xxxxxxxx.net...
Response: fzSftp started
Command: open "xxxxxxxx@…" 22
Response: fzSftp started
Command: open "xxxxxxxx@…" 22
Command: Pass: *
Command: Pass: *
Status: Connected to xxxxxxxx.net
Status: Connected to xxxxxxxx.net
Status: Starting upload of /home/teo/Documents/servers/xxxxxxxxxxxxx/public_html/test_upload/test1.txt~
Command: cd "/srv/www/xxxxxxxx.net/public_html/test_upload"
Status: Starting upload of /home/teo/Documents/servers/xxxxxxxxxxxxx/public_html/test_upload/test5.txt
Error: Directory /srv/www/xxxxxxxx.net/public_html/test_upload: no such file or directory
Command: cd "/srv/www/xxxxxxxx.net/public_html"
Response: New directory is: "/srv/www/xxxxxxxx.net/public_html"
Command: mkdir "test_upload"
Response: mkdir /srv/www/xxxxxxxx.net/public_html/test_upload: OK
Command: cd "/srv/www/xxxxxxxx.net/public_html/test_upload"
Response: New directory is: "/srv/www/xxxxxxxx.net/public_html/test_upload"
Status: Retrieving directory listing...
Command: ls
Command: cd "/srv/www/xxxxxxxx.net/public_html/test_upload"
Status: Listing directory /srv/www/xxxxxxxx.net/public_html/test_upload
Response: New directory is: "/srv/www/xxxxxxxx.net/public_html/test_upload"
Status: Retrieving directory listing...
Command: put "/home/teo/Documents/servers/xxxxxxxxxxxxx/public_html/test_upload/test1.txt~" "test1.txt~"
Error: File transfer failed
Status: Starting upload of /home/teo/Documents/servers/xxxxxxxxxxxxx/public_html/test_upload/test5.txt
Command: put "/home/teo/Documents/servers/xxxxxxxxxxxxx/public_html/test_upload/test5.txt" "test5.txt"
Status: local:/home/teo/Documents/servers/xxxxxxxxxxxxx/public_html/test_upload/test1.txt~ => remote:/srv/www/xxxxxxxx.net/public_html/test_upload/test1.txt~
Status: local:/home/teo/Documents/servers/xxxxxxxxxxxxx/public_html/test_upload/test5.txt => remote:/srv/www/xxxxxxxx.net/public_html/test_upload/test5.txt
Status: File transfer successful, transferred 0 B in 1 second
Status: Starting upload of /home/teo/Documents/servers/xxxxxxxxxxxxx/public_html/test_upload/test4.txt
Command: put "/home/teo/Documents/servers/xxxxxxxxxxxxx/public_html/test_upload/test4.txt" "test4.txt"
Status: File transfer successful, transferred 73 B in 1 second
Status: Starting upload of /home/teo/Documents/servers/xxxxxxxxxxxxx/public_html/test_upload/test1.txt
Command: put "/home/teo/Documents/servers/xxxxxxxxxxxxx/public_html/test_upload/test1.txt" "test1.txt"
Status: local:/home/teo/Documents/servers/xxxxxxxxxxxxx/public_html/test_upload/test4.txt => remote:/srv/www/xxxxxxxx.net/public_html/test_upload/test4.txt
Status: local:/home/teo/Documents/servers/xxxxxxxxxxxxx/public_html/test_upload/test1.txt => remote:/srv/www/xxxxxxxx.net/public_html/test_upload/test1.txt
Status: File transfer successful, transferred 73 B in 1 second
Status: Starting upload of /home/teo/Documents/servers/xxxxxxxxxxxxx/public_html/test_upload/test3.txt
Command: put "/home/teo/Documents/servers/xxxxxxxxxxxxx/public_html/test_upload/test3.txt" "test3.txt"
Status: File transfer successful, transferred 73 B in 1 second
Status: Starting upload of /home/teo/Documents/servers/xxxxxxxxxxxxx/public_html/test_upload/test2.txt
Command: put "/home/teo/Documents/servers/xxxxxxxxxxxxx/public_html/test_upload/test2.txt" "test2.txt"
Status: local:/home/teo/Documents/servers/xxxxxxxxxxxxx/public_html/test_upload/test3.txt => remote:/srv/www/xxxxxxxx.net/public_html/test_upload/test3.txt
Status: local:/home/teo/Documents/servers/xxxxxxxxxxxxx/public_html/test_upload/test2.txt => remote:/srv/www/xxxxxxxx.net/public_html/test_upload/test2.txt
Status: File transfer successful, transferred 73 B in 1 second
Status: File transfer successful, transferred 73 B in 1 second
Status: Retrieving directory listing...
Command: cd "/srv/www/xxxxxxxx.net/public_html"
Response: New directory is: "/srv/www/xxxxxxxx.net/public_html"
Command: ls
Status: Listing directory /srv/www/xxxxxxxx.net/public_html
Status: Directory listing successful

[teo8976]

Oh, one difference between the server where I observe the issue and that where I don't, is that where I observe the issue i'm using SFTP, while the case that works I'm using plain FTP.

[Tim Kosse]

Unfortunately two files are being transferred at the same time.

Please post another log with debug level set to 3 in the settings dialog of FileZilla and while transferring no more than one file at a time.

[teo8976]

I've reduced the number of maximum simultaneous uploads to 1. The issue persists (which was quite predictable, given the logs I posted).
Note that this MUST be guaranteed to work correctly regardless of how many transfers are done simultaneously.

I attach the log you asked. This is uploading a folder with 5 txt files inside.

By the way, did _you_ make any test? Because I find this to be 100% reproducible with SFTP (and pretty easy to test), and I confirmed this with two completely different servers, so I wonder whether you tested it and couldn't reproduce, or if you didn't try at all, as in "users who report the bug are supposed to do the debugging work, not developers".

I haven't observed this on plain FTP. This may be an issue specific to SFTP. Which doesn't make it less of an issue; actually it makes it worse, because this obliges people to use FTP, which is insecure.

From the log it seems obvious that the first file in the folder is sent before the folder is created.

Again, could you please explain how an issue that renders secure file transfer unreliable, hence unusable (it actually GUARANTEES that one random file per folder will be lost if the folder doesn't previously exist) is not critical?

Status: Connecting to XXXXX.net...
Trace: Going to execute /usr/bin/fzsftp
Response: fzSftp started
Trace: CSftpControlSocket::ConnectParseResponse(fzSftp started)
Trace: CSftpControlSocket::SendNextCommand()
Trace: CSftpControlSocket::ConnectSend()
Command: open "XXXXX@…" 22
Trace: Server version: SSH-2.0-OpenSSH_6.0p1 Debian-4+deb7u2
Trace: Using SSH protocol version 2
Trace: We claim version: SSH-2.0-PuTTY_Local:_Sep_14_2013_01:12:43
Trace: Doing Diffie-Hellman group exchange
Trace: Doing Diffie-Hellman key exchange with hash SHA-256
Trace: Host key fingerprint is:
Trace: ssh-rsa 2048
Trace: Initialised AES-256 SDCTR client->server encryption
Trace: Initialised HMAC-SHA1 client->server MAC algorithm
Trace: Initialised AES-256 SDCTR server->client encryption
Trace: Initialised HMAC-SHA1 server->client MAC algorithm
Trace: Pageant is running. Requesting keys.
Trace: Pageant has 1 SSH-2 keys
Trace: Trying Pageant key #0
Trace: Server refused public key
Command: Pass: *
Trace: Sent password
Trace: Access granted
Trace: Opened channel for session
Trace: Started a shell/command
Status: Connected to XXXXX.net
Trace: CSftpControlSocket::ConnectParseResponse()
Trace: CSftpControlSocket::ResetOperation(0)
Trace: CControlSocket::ResetOperation(0)
Trace: CSftpControlSocket::FileTransfer(...)
Status: Starting upload of /home/teo/Documents/lavoro/XXXXX/httpdocs/test_upload/test5.txt
Trace: CSftpControlSocket::SendNextCommand()
Trace: CSftpControlSocket::ChangeDirSend()
Command: cd "/srv/www/XXXXX.net/public_html/test_upload"
Error: Directory /srv/www/XXXXX.net/public_html/test_upload: no such file or directory
Trace: CSftpControlSocket::SendNextCommand()
Trace: CSftpControlSocket::MkdirSend
Command: cd "/srv/www/XXXXX.net/public_html"
Response: New directory is: "/srv/www/XXXXX.net/public_html"
Trace: CSftpControlSocket::MkdirParseResonse
Trace: CSftpControlSocket::MkdirSend
Command: mkdir "test_upload"
Response: mkdir /srv/www/XXXXX.net/public_html/test_upload: OK
Trace: CSftpControlSocket::MkdirParseResonse
Trace: CSftpControlSocket::ResetOperation(0)
Trace: CControlSocket::ResetOperation(0)
Trace: CSftpControlSocket::ParseSubcommandResult(0)
Trace: CSftpControlSocket::ChangeDirSubcommandResult()
Trace: CSftpControlSocket::SendNextCommand()
Trace: CSftpControlSocket::ChangeDirSend()
Command: cd "/srv/www/XXXXX.net/public_html/test_upload"
Response: New directory is: "/srv/www/XXXXX.net/public_html/test_upload"
Trace: CSftpControlSocket::ResetOperation(0)
Trace: CControlSocket::ResetOperation(0)
Trace: CSftpControlSocket::ParseSubcommandResult(0)
Trace: CSftpControlSocket::FileTransferSubcommandResult()
Status: Retrieving directory listing...
Trace: sftpcontrolsocket.cpp(960): List called from other command caller=0x20ac440
Trace: CSftpControlSocket::ParseSubcommandResult(0)
Trace: CSftpControlSocket::ListSubcommandResult()
Trace: CSftpControlSocket::SendNextCommand()
Trace: CSftpControlSocket::ListSend()
Command: ls
Status: Listing directory /srv/www/XXXXX.net/public_html/test_upload
Trace: CSftpControlSocket::ListParseResponse()
Trace: CSftpControlSocket::ResetOperation(0)
Trace: CControlSocket::ResetOperation(0)
Trace: CSftpControlSocket::ParseSubcommandResult(0)
Trace: CSftpControlSocket::FileTransferSubcommandResult()
Trace: CSftpControlSocket::SendNextCommand()
Trace: FileTransferSend()
Command: put "/home/teo/Documents/lavoro/XXXXX/httpdocs/test_upload/test5.txt" "test5.txt"
Status: local:/home/teo/Documents/lavoro/XXXXX/httpdocs/test_upload/test5.txt => remote:/srv/www/XXXXX.net/public_html/test_upload/test5.txt
Trace: FileTransferParseResponse()
Trace: CSftpControlSocket::ResetOperation(0)
Trace: CControlSocket::ResetOperation(0)
Status: File transfer successful, transferred 73 B in 1 second
Trace: CSftpControlSocket::FileTransfer(...)
Status: Starting upload of /home/teo/Documents/lavoro/XXXXX/httpdocs/test_upload/test4.txt
Trace: CSftpControlSocket::ParseSubcommandResult(0)
Trace: CSftpControlSocket::FileTransferSubcommandResult()
Trace: CSftpControlSocket::SendNextCommand()
Trace: FileTransferSend()
Command: put "/home/teo/Documents/lavoro/XXXXX/httpdocs/test_upload/test4.txt" "test4.txt"
Status: local:/home/teo/Documents/lavoro/XXXXX/httpdocs/test_upload/test4.txt => remote:/srv/www/XXXXX.net/public_html/test_upload/test4.txt
Trace: FileTransferParseResponse()
Trace: CSftpControlSocket::ResetOperation(0)
Trace: CControlSocket::ResetOperation(0)
Status: File transfer successful, transferred 73 B in 1 second
Trace: CSftpControlSocket::FileTransfer(...)
Status: Starting upload of /home/teo/Documents/lavoro/XXXXX/httpdocs/test_upload/test1.txt
Trace: CSftpControlSocket::ParseSubcommandResult(0)
Trace: CSftpControlSocket::FileTransferSubcommandResult()
Trace: CSftpControlSocket::SendNextCommand()
Trace: FileTransferSend()
Command: put "/home/teo/Documents/lavoro/XXXXX/httpdocs/test_upload/test1.txt" "test1.txt"
Status: local:/home/teo/Documents/lavoro/XXXXX/httpdocs/test_upload/test1.txt => remote:/srv/www/XXXXX.net/public_html/test_upload/test1.txt
Trace: FileTransferParseResponse()
Trace: CSftpControlSocket::ResetOperation(0)
Trace: CControlSocket::ResetOperation(0)
Status: File transfer successful, transferred 73 B in 1 second
Trace: CSftpControlSocket::FileTransfer(...)
Status: Starting upload of /home/teo/Documents/lavoro/XXXXX/httpdocs/test_upload/test3.txt
Trace: CSftpControlSocket::ParseSubcommandResult(0)
Trace: CSftpControlSocket::FileTransferSubcommandResult()
Trace: CSftpControlSocket::SendNextCommand()
Trace: FileTransferSend()
Command: put "/home/teo/Documents/lavoro/XXXXX/httpdocs/test_upload/test3.txt" "test3.txt"
Status: local:/home/teo/Documents/lavoro/XXXXX/httpdocs/test_upload/test3.txt => remote:/srv/www/XXXXX.net/public_html/test_upload/test3.txt
Trace: FileTransferParseResponse()
Trace: CSftpControlSocket::ResetOperation(0)
Trace: CControlSocket::ResetOperation(0)
Status: File transfer successful, transferred 73 B in 1 second
Trace: CSftpControlSocket::FileTransfer(...)
Status: Starting upload of /home/teo/Documents/lavoro/XXXXX/httpdocs/test_upload/test2.txt
Trace: CSftpControlSocket::ParseSubcommandResult(0)
Trace: CSftpControlSocket::FileTransferSubcommandResult()
Trace: CSftpControlSocket::SendNextCommand()
Trace: FileTransferSend()
Command: put "/home/teo/Documents/lavoro/XXXXX/httpdocs/test_upload/test2.txt" "test2.txt"
Status: local:/home/teo/Documents/lavoro/XXXXX/httpdocs/test_upload/test2.txt => remote:/srv/www/XXXXX.net/public_html/test_upload/test2.txt
Trace: FileTransferParseResponse()
Trace: CSftpControlSocket::ResetOperation(0)
Trace: CControlSocket::ResetOperation(0)
Status: File transfer successful, transferred 73 B in 1 second
Status: Retrieving directory listing...
Trace: CSftpControlSocket::SendNextCommand()
Trace: CSftpControlSocket::ChangeDirSend()
Command: cd "/srv/www/XXXXX.net/public_html"
Response: New directory is: "/srv/www/XXXXX.net/public_html"
Trace: CSftpControlSocket::ResetOperation(0)
Trace: CControlSocket::ResetOperation(0)
Trace: CSftpControlSocket::ParseSubcommandResult(0)
Trace: CSftpControlSocket::ListSubcommandResult()
Trace: CSftpControlSocket::SendNextCommand()
Trace: CSftpControlSocket::ListSend()
Command: ls
Status: Listing directory /srv/www/XXXXX.net/public_html
Trace: CSftpControlSocket::ListParseResponse()
Trace: CSftpControlSocket::ResetOperation(0)
Trace: CControlSocket::ResetOperation(0)
Status: Directory listing successful

[Tim Kosse]

As your log clearly shows, the directory is being created prior to the actual upload of the first file:

Status: Starting upload of /home/teo/Documents/lavoro/XXXXX/httpdocs/test_upload/test5.txt
Command: cd "/srv/www/XXXXX.net/public_html/test_upload"
Error: Directory /srv/www/XXXXX.net/public_html/test_upload: no such file or directory
Command: cd "/srv/www/XXXXX.net/public_html"
Response: New directory is: "/srv/www/XXXXX.net/public_html"
Command: mkdir "test_upload"
Response: mkdir /srv/www/XXXXX.net/public_html/test_upload: OK
Command: cd "/srv/www/XXXXX.net/public_html/test_upload"
Response: New directory is: "/srv/www/XXXXX.net/public_html/test_upload"
Status: Retrieving directory listing...
Command: ls
Status: Listing directory /srv/www/XXXXX.net/public_html/test_upload
Command: put "/home/teo/Documents/lavoro/XXXXX/httpdocs/test_upload/test5.txt" "test5.txt"
Status: local:/home/teo/Documents/lavoro/XXXXX/httpdocs/test_upload/test5.txt => remote:/srv/www/XXXXX.net/public_html/test_upload/test5.txt
Status: File transfer successful, transferred 73 B in 1 second

Status: Starting upload of /home/teo/Documents/lavoro/XXXXX/httpdocs/test_upload/test4.txt
Command: put "/home/teo/Documents/lavoro/XXXXX/httpdocs/test_upload/test4.txt" "test4.txt"
Status: local:/home/teo/Documents/lavoro/XXXXX/httpdocs/test_upload/test4.txt => remote:/srv/www/XXXXX.net/public_html/test_upload/test4.txt
Status: File transfer successful, transferred 73 B in 1 second

Status: Starting upload of /home/teo/Documents/lavoro/XXXXX/httpdocs/test_upload/test1.txt
Command: put "/home/teo/Documents/lavoro/XXXXX/httpdocs/test_upload/test1.txt" "test1.txt"
Status: local:/home/teo/Documents/lavoro/XXXXX/httpdocs/test_upload/test1.txt => remote:/srv/www/XXXXX.net/public_html/test_upload/test1.txt
Status: File transfer successful, transferred 73 B in 1 second

Status: Starting upload of /home/teo/Documents/lavoro/XXXXX/httpdocs/test_upload/test3.txt
Command: put "/home/teo/Documents/lavoro/XXXXX/httpdocs/test_upload/test3.txt" "test3.txt"
Status: local:/home/teo/Documents/lavoro/XXXXX/httpdocs/test_upload/test3.txt => remote:/srv/www/XXXXX.net/public_html/test_upload/test3.txt
Status: File transfer successful, transferred 73 B in 1 second

Status: Starting upload of /home/teo/Documents/lavoro/XXXXX/httpdocs/test_upload/test2.txt
Command: put "/home/teo/Documents/lavoro/XXXXX/httpdocs/test_upload/test2.txt" "test2.txt"
Status: local:/home/teo/Documents/lavoro/XXXXX/httpdocs/test_upload/test2.txt => remote:/srv/www/XXXXX.net/public_html/test_upload/test2.txt
Status: File transfer successful, transferred 73 B in 1 second

According to your own log, all commands were sent in the right order and all five files were successfully uploaded.

[teo8976]

Sorry, I didn't notice that this log didn't actually show the issue, and that it is not indeed 100% reproducible (I was seeing the errors and didn't notice that the operations are then re-done in expected order).

I definitely did observe missing files, though, when I reported the bug in the first place (I didn't notice because I saw the error, I noticed because there was a file missing). Perhaps it only happens when mutiple transfers are allowed simultaneously, and i guess it is intermittent (as I can't reproduce it right now even with multiple file transfers allowed).

I understand you being skeptical, so I'll reopen when I observe this again, and hope I'll have the log then. In the meantime I'll have to double check every folder I transfer, or transfer them twice each time.