Server under load fails to receive uploads

Need help with FileZilla Server? Something does not work as expected? In this forum you may find an answer.

Moderator: Project members

Post Reply
Message
Author
coderanger
500 Command not understood
Posts: 2
Joined: 2022-11-24 14:20

Server under load fails to receive uploads

#1 Post by coderanger » 2022-11-24 15:36

FileZilla: v1.5.1
OS: Windows Server
Settings: Ban IPs (disabled), Login Timeout (360), Activity Timeout (180), Performance: Threads (0), Custom Buffers (none set), Filters: Disallowed/Allowed IPs (none set)
User Accounts: Filters (none set), Speed Limits (none set, all set to unlimited), Permissions (Read+Write, Writeable Structure, Apply to SubDirs all set)

I have recently moved from Serv-U to FileZilla because the old version of Serv-U we used couldnt upload files with non-ascii accents/characters.

However, one thing I have noticed is when we are uploading 000's of files, which is quite common, we are getting intermittent failures with message "Couldn't open the file or directory". This never used to be a problem, but is now with FileZilla.

It even crashed the service after a while, so I have set the service to restart on failure which seems to have stopped the problem of the service staying down.

There shouldn't be any permissions issues because the user account we are using in FileZilla has "full control" access to the files and folders in the directory tree; and failed files do eventually work after retrying multiple times and when the load reduces.

Is there something I can try to help fix this as its becoming a bit of a major issue for me right now?

Below is a snippet of the log:

Code: Select all

2022-11-24T14:17:57.468Z == [FTP Server] Session 926 ended gracefully.
2022-11-24T14:17:57.468Z II [FTP Session 926 <ipredacted>] Session 0x1edcfd7c240 with ID 926 destroyed.
2022-11-24T14:17:57.468Z >> [FTP Session 927 <ipredacted> ftpuser] STOR /series/s275575.png
2022-11-24T14:17:57.546Z II [File-based Authenticator/impersonator client, user: ftpuser] on_can_recv: [fz::rmp::message<fz::tvfs::backend::info_response_tag (fz::result, bool, fz::local_filesys::type, long long, fz::datetime, int)>] processing.
2022-11-24T14:17:57.546Z II [File-based Authenticator/impersonator client, user: ftpuser] [fz::rmp::message<fz::tvfs::backend::info_response_tag (fz::result, bool, fz::local_filesys::type, long long, fz::datetime, int)>]: dispatching message
2022-11-24T14:17:57.546Z << [FTP Session 930 <ipredacted> ftpuser] 550 Couldn't open the file or directory
2022-11-24T14:17:57.546Z !! [File-based Authenticator/impersonator client, user: ftpuser/impersonator process] process::on_process_read: got premature EOF
2022-11-24T14:17:57.546Z !! [File-based Authenticator/impersonator client, user: ftpuser] Error: Unknown error (120). Closing channel.
2022-11-24T14:17:57.546Z << [FTP Session 927 <ipredacted> ftpuser] 550 Couldn't open the file or directory
2022-11-24T14:17:57.562Z >> [FTP Session 930 <ipredacted> ftpuser] TYPE I
2022-11-24T14:17:57.562Z << [FTP Session 930 <ipredacted> ftpuser] 200 Type set to I
2022-11-24T14:17:57.562Z >> [FTP Session 927 <ipredacted> ftpuser] QUIT
2022-11-24T14:17:57.562Z << [FTP Session 927 <ipredacted> ftpuser] 221 Goodbye.
2022-11-24T14:17:57.562Z == [FTP Server] Session 927 ended gracefully.
2022-11-24T14:17:57.562Z II [FTP Session 927 <ipredacted>] Session 0x1edcfe74f90 with ID 927 destroyed.
2022-11-24T14:17:57.562Z >> [FTP Session 930 <ipredacted> ftpuser] EPSV
2022-11-24T14:17:57.562Z << [FTP Session 930 <ipredacted> ftpuser] 229 Entering Extended Passive Mode (|||50005|)
2022-11-24T14:17:57.577Z >> [FTP Session 930 <ipredacted> ftpuser] NLST /brand
2022-11-24T14:17:57.577Z II [File-based Authenticator/impersonator client, user: ftpuser/impersonator process] Token is valid
2022-11-24T14:17:57.577Z II [File-based Authenticator/impersonator client, user: ftpuser/impersonator process] Process C:\Program Files\FileZilla Server\filezilla-server-impersonator.exe spawned.
2022-11-24T14:17:57.577Z >> [FTP Session 931 <ipredacted> ftpuser] SIZE /brand/p278074.png
2022-11-24T14:17:57.671Z II [File-based Authenticator/impersonator client, user: ftpuser] on_can_recv: [fz::rmp::message<fz::tvfs::backend::info_response_tag (fz::result, bool, fz::local_filesys::type, long long, fz::datetime, int)>] processing.
2022-11-24T14:17:57.671Z II [File-based Authenticator/impersonator client, user: ftpuser] [fz::rmp::message<fz::tvfs::backend::info_response_tag (fz::result, bool, fz::local_filesys::type, long long, fz::datetime, int)>]: dispatching message
2022-11-24T14:17:57.749Z >> [FTP Session 929 <ipredacted> ftpuser] SIZE /brand/p277706.png
2022-11-24T14:18:07.597Z !! [File-based Authenticator/impersonator client, user: ftpuser] Timeout expired.
2022-11-24T14:18:07.597Z !! [File-based Authenticator/impersonator client, user: ftpuser] Error: Unknown error (138). Closing channel.
2022-11-24T14:18:07.597Z << [FTP Session 931 <ipredacted> ftpuser] 550 Couldn't open the file or directory
2022-11-24T14:18:07.597Z << [FTP Session 930 <ipredacted> ftpuser] 550 Couldn't open the file or directory
2022-11-24T14:18:07.597Z << [FTP Session 929 <ipredacted> ftpuser] 550 Couldn't open the file or directory
2022-11-24T14:18:07.597Z >> [FTP Session 931 <ipredacted> ftpuser] MDTM /brand/p278074.png
2022-11-24T14:18:07.597Z II [File-based Authenticator/impersonator client, user: ftpuser/impersonator process] Token is valid
2022-11-24T14:18:07.613Z II [File-based Authenticator/impersonator client, user: ftpuser/impersonator process] Process C:\Program Files\FileZilla Server\filezilla-server-impersonator.exe spawned.
2022-11-24T14:18:07.613Z >> [FTP Session 929 <ipredacted> ftpuser] MDTM /brand/p277706.png
2022-11-24T14:18:07.613Z >> [FTP Session 930 <ipredacted> ftpuser] EPSV
2022-11-24T14:18:07.613Z << [FTP Session 930 <ipredacted> ftpuser] 229 Entering Extended Passive Mode (|||50015|)
2022-11-24T14:18:07.628Z >> [FTP Session 930 <ipredacted> ftpuser] STOR /brand/p276678.png
2022-11-24T14:18:07.628Z II [File-based Authenticator/impersonator client, user: ftpuser] on_can_send: couldn't send msg right now, waiting for next event.
2022-11-24T14:18:07.660Z II [File-based Authenticator/impersonator client, user: ftpuser] on_can_recv: [fz::rmp::message<fz::tvfs::backend::info_response_tag (fz::result, bool, fz::local_filesys::type, long long, fz::datetime, int)>] processing.
2022-11-24T14:18:07.660Z II [File-based Authenticator/impersonator client, user: ftpuser] [fz::rmp::message<fz::tvfs::backend::info_response_tag (fz::result, bool, fz::local_filesys::type, long long, fz::datetime, int)>]: dispatching message
2022-11-24T14:18:07.660Z << [FTP Session 931 <ipredacted> ftpuser] 213 20221124140916.548
2022-11-24T14:18:07.675Z !! [File-based Authenticator/impersonator client, user: ftpuser/impersonator process] process::on_process_read: got premature EOF
2022-11-24T14:18:07.675Z >> [FTP Session 931 <ipredacted> ftpuser] DELE /brand/p278074.png
2022-11-24T14:18:07.675Z !! [File-based Authenticator/impersonator client, user: ftpuser/impersonator process] process::on_process_write: process::write() returned error: 4, raw: 232
2022-11-24T14:18:07.675Z !! [File-based Authenticator/impersonator client, user: ftpuser] Error: Unknown error (120). Closing channel.
2022-11-24T14:18:07.675Z !! [File-based Authenticator/impersonator client, user: ftpuser] Error: Input/output error (5). Closing channel.
2022-11-24T14:18:07.675Z << [FTP Session 929 <ipredacted> ftpuser] 550 Couldn't open the file or directory
2022-11-24T14:18:07.675Z << [FTP Session 930 <ipredacted> ftpuser] 550 Couldn't open the file or directory
2022-11-24T14:18:07.675Z << [FTP Session 931 <ipredacted> ftpuser] 550 Couldn't open the file or directory
2022-11-24T14:18:07.691Z >> [FTP Session 931 <ipredacted> ftpuser] QUIT
2022-11-24T14:18:07.691Z << [FTP Session 931 <ipredacted> ftpuser] 221 Goodbye.
2022-11-24T14:18:07.691Z == [FTP Server] Session 931 ended gracefully.
2022-11-24T14:18:07.691Z II [FTP Session 931 <ipredacted>] Session 0x1edcfdceb90 with ID 931 destroyed.
2022-11-24T14:18:07.691Z >> [FTP Session 929 <ipredacted> ftpuser] TYPE I
2022-11-24T14:18:07.691Z << [FTP Session 929 <ipredacted> ftpuser] 200 Type set to I
2022-11-24T14:18:07.691Z >> [FTP Session 930 <ipredacted> ftpuser] QUIT
2022-11-24T14:18:07.691Z << [FTP Session 930 <ipredacted> ftpuser] 221 Goodbye.
2022-11-24T14:18:07.691Z == [FTP Server] Session 930 ended gracefully.
2022-11-24T14:18:07.691Z II [FTP Session 930 <ipredacted>] Session 0x1edcfd90930 with ID 930 destroyed.
2022-11-24T14:18:07.691Z >> [FTP Session 929 <ipredacted> ftpuser] EPSV
2022-11-24T14:18:07.691Z << [FTP Session 929 <ipredacted> ftpuser] 229 Entering Extended Passive Mode (|||50010|)
2022-11-24T14:18:07.707Z >> [FTP Session 929 <ipredacted> ftpuser] NLST /brand
2022-11-24T14:18:07.707Z II [File-based Authenticator/impersonator client, user: ftpuser/impersonator process] Token is valid
2022-11-24T14:18:07.707Z II [File-based Authenticator/impersonator client, user: ftpuser/impersonator process] Process C:\Program Files\FileZilla Server\filezilla-server-impersonator.exe spawned.
2022-11-24T14:18:07.769Z II [File-based Authenticator/impersonator client, user: ftpuser] on_can_recv: [fz::rmp::message<fz::tvfs::backend::info_response_tag (fz::result, bool, fz::local_filesys::type, long long, fz::datetime, int)>] processing.
2022-11-24T14:18:07.769Z II [File-based Authenticator/impersonator client, user: ftpuser] [fz::rmp::message<fz::tvfs::backend::info_response_tag (fz::result, bool, fz::local_filesys::type, long long, fz::datetime, int)>]: dispatching message
2022-11-24T14:18:07.769Z II [File-based Authenticator/impersonator client, user: ftpuser] on_can_recv: [fz::rmp::message<fz::tvfs::backend::open_response_tag (fz::result, fz::tvfs::fd_owner)>] processing.
2022-11-24T14:18:07.769Z II [File-based Authenticator/impersonator client, user: ftpuser] [fz::rmp::message<fz::tvfs::backend::open_response_tag (fz::result, fz::tvfs::fd_owner)>]: dispatching message
2022-11-24T14:18:07.785Z << [FTP Session 929 <ipredacted> ftpuser] 150 Starting data transfer.
2022-11-24T14:18:07.800Z << [FTP Session 929 <ipredacted> ftpuser] 226 Operation successful
On a side note, it would be nice if the error "Couldn't open the file or directory" actually stated which file or directory it was failing on :)

User avatar
oibaf
Contributor
Posts: 396
Joined: 2021-07-16 21:02
First name: Fabio
Last name: Alemagna

Re: Server under load fails to receive uploads

#2 Post by oibaf » 2022-11-24 18:44

This issue has been fixed already and is not present in the nightly builds. If you want to wait for the next candidate release, it's due in the next few hours.

As for "it would be nice if the error "Couldn't open the file or directory" actually stated which file or directory it was failing on", the message is the one sent to the ftp client and immeditely follows the command. You just need to go up in the log file until you find the corresponding command.

Code: Select all

2022-11-24T14:17:57.577Z >> [FTP Session 930 <ipredacted> ftpuser] NLST /brand
2022-11-24T14:18:07.597Z << [FTP Session 930 <ipredacted> ftpuser] 550 Couldn't open the file or directory

coderanger
500 Command not understood
Posts: 2
Joined: 2022-11-24 14:20

Re: Server under load fails to receive uploads

#3 Post by coderanger » 2022-11-24 19:18

Thats brilliant, and such a relief; thanks so much all. Great work!

Post Reply