1.01 gives 425 Error reading from file: 5 but 0.96 works

[adynis]

Hello, may I please have some assistance on this issue? Thank You.

I spun up a FZ server 1.01 server on Windows Server 2019 to take scans from an older wide format plotter, a Ricoh Aficio MP W5100. I had not used FZ Server in a while and the new interface was quite a shock, and it took me a while to get around the whole path thing. This printer is onsite, with an IP of 10.6.0.60 and it is talking over an ipsec tunnel to a datacenter hosted server with an IP of 10.82.1.2. The ipsec tunnel is any:any:any stuff, wide open (don't judge). It'll get locked down when all the kinks are worked out. The firewall on-prem is pfSense+ 21.0.5 on Netgate SG3100. The datacenter firewall is virtual and pfSense CE 2.5.2.

I can screenconnect into the old server on-premises and fire up WinSCP and make an ftp connection and I can write a file just fine. When the plotter would do it, we would get the 425 Error reading from file: 5. When we put in 0.96, it immediately worked but I saw something that may explain its behavior.

Code: Select all

(000001)11/10/2021 14:41:07 PM - (not logged in) (10.6.0.60)> USER scans
(000001)11/10/2021 14:41:07 PM - (not logged in) (10.6.0.60)> 331 Password required for scans
(000001)11/10/2021 14:41:07 PM - (not logged in) (10.6.0.60)> PASS **********************
(000001)11/10/2021 14:41:07 PM - scans (10.6.0.60)> 230 Logged on
(000001)11/10/2021 14:41:07 PM - scans (10.6.0.60)> CWD /
(000001)11/10/2021 14:41:07 PM - scans (10.6.0.60)> 250 CWD successful. "/" is current directory.
(000001)11/10/2021 14:41:07 PM - scans (10.6.0.60)> TYPE I
(000001)11/10/2021 14:41:07 PM - scans (10.6.0.60)> 200 Type set to I
(000001)11/10/2021 14:41:07 PM - scans (10.6.0.60)> PORT 10,6,0,60,251,128
(000001)11/10/2021 14:41:07 PM - scans (10.6.0.60)> 200 Port command successful
(000001)11/10/2021 14:41:07 PM - scans (10.6.0.60)> RETR 20211110142417644.pdf
(000001)11/10/2021 14:41:07 PM - scans (10.6.0.60)> 550 File not found
(000001)11/10/2021 14:41:07 PM - scans (10.6.0.60)> TYPE I
(000001)11/10/2021 14:41:07 PM - scans (10.6.0.60)> 200 Type set to I
(000001)11/10/2021 14:41:07 PM - scans (10.6.0.60)> PORT 10,6,0,60,251,127
(000001)11/10/2021 14:41:07 PM - scans (10.6.0.60)> 200 Port command successful
(000001)11/10/2021 14:41:07 PM - scans (10.6.0.60)> STOR 20211110142417644.pdf
(000001)11/10/2021 14:41:07 PM - scans (10.6.0.60)> 150 Opening data channel for file upload to server of "/20211110142417644.pdf"
(000001)11/10/2021 14:41:08 PM - scans (10.6.0.60)> 226 Successfully transferred "/20211110142417644.pdf"
(000001)11/10/2021 14:41:08 PM - scans (10.6.0.60)> QUIT
(000001)11/10/2021 14:41:08 PM - scans (10.6.0.60)> 221 Goodbye
(000001)11/10/2021 14:41:08 PM - scans (10.6.0.60)> disconnected.

In what I am assuming is checking for a file that already has the same name it tries to do a RETREIVE before the STORE. On 0.96 this behavior works fine, on 1.01 this behavior fails.

On 1.01 I get this:

Code: Select all

2021-11-09T15:54:01.565Z >> [FTP Session 5 10.6.0.60] USER scans
2021-11-09T15:54:01.565Z << [FTP Session 5 10.6.0.60] 331 Please, specify the password.
2021-11-09T15:54:01.581Z >> [FTP Session 5 10.6.0.60] PASS ****
2021-11-09T15:54:01.675Z << [FTP Session 5 10.6.0.60 scans] 230 Login successful.
2021-11-09T15:54:01.706Z >> [FTP Session 5 10.6.0.60 scans] CWD /
2021-11-09T15:54:01.706Z << [FTP Session 5 10.6.0.60 scans] 250 CWD command successful
2021-11-09T15:54:01.721Z >> [FTP Session 5 10.6.0.60 scans] CWD Scans
2021-11-09T15:54:01.721Z << [FTP Session 5 10.6.0.60 scans] 250 CWD command successful
2021-11-09T15:54:01.893Z >> [FTP Session 5 10.6.0.60 scans] TYPE I
2021-11-09T15:54:01.893Z << [FTP Session 5 10.6.0.60 scans] 200 Type set to I
2021-11-09T15:54:01.925Z >> [FTP Session 5 10.6.0.60 scans] PORT 10,6,0,60,244,118
2021-11-09T15:54:01.925Z << [FTP Session 5 10.6.0.60 scans] 200 PORT command successful.
2021-11-09T15:54:01.940Z >> [FTP Session 5 10.6.0.60 scans] RETR 20211109103712008.pdf
2021-11-09T15:54:01.940Z << [FTP Session 5 10.6.0.60 scans] 150 Starting data transfer.
2021-11-09T15:54:01.987Z << [FTP Session 5 10.6.0.60 scans] 425 Error reading from file: 5
2021-11-09T15:54:02.018Z >> [FTP Session 5 10.6.0.60 scans] TYPE I
2021-11-09T15:54:02.018Z << [FTP Session 5 10.6.0.60 scans] 200 Type set to I
2021-11-09T15:54:02.034Z >> [FTP Session 5 10.6.0.60 scans] PORT 10,6,0,60,244,117
2021-11-09T15:54:02.034Z << [FTP Session 5 10.6.0.60 scans] 200 PORT command successful.
2021-11-09T15:54:02.065Z >> [FTP Session 5 10.6.0.60 scans] RETR 20211109103712008-1.pdf
2021-11-09T15:54:02.065Z << [FTP Session 5 10.6.0.60 scans] 150 Starting data transfer.
2021-11-09T15:54:02.081Z << [FTP Session 5 10.6.0.60 scans] 425 Error reading from file: 5
2021-11-09T15:54:02.112Z >> [FTP Session 5 10.6.0.60 scans] TYPE I
2021-11-09T15:54:02.112Z << [FTP Session 5 10.6.0.60 scans] 200 Type set to I
2021-11-09T15:54:02.128Z >> [FTP Session 5 10.6.0.60 scans] PORT 10,6,0,60,244,116
2021-11-09T15:54:02.128Z << [FTP Session 5 10.6.0.60 scans] 200 PORT command successful.
2021-11-09T15:54:02.159Z >> [FTP Session 5 10.6.0.60 scans] RETR 20211109103712008-2.pdf
2021-11-09T15:54:02.159Z << [FTP Session 5 10.6.0.60 scans] 150 Starting data transfer.
2021-11-09T15:54:02.175Z << [FTP Session 5 10.6.0.60 scans] 425 Error reading from file: 5

And that behavior repeats maybe 50-60 times before it gives up.

As for the path I set / to e:\Scans and yes "everyone" and "SYSTEM" had full control (again, I'll lock it down later, but that was my troubleshooting step 1). I even tried the path to /Scans/ and I set that as the path on the plotter to no avail.

Now, that plotter's days are numbered. The issue is these devices costs tens of thousands of dollars, so it takes a little while. But I would prefer being on 1.01 and not being on a server version from 2017.

It is important to point out that this server is not available to the outside internet only through the ipsec vpn tunnel. I am a network engineer an I was working with the a tech from the printer company as he just upgraded all the firmware on that plotter (it didn't work on the old firmware either).

Right now it is working on 0.96 and it does not work on 1.01.

Can someone please answer why that is? As well as a possible configuration fix? Thank You. I understand the plotter may be doing something "wrong" as you may see it but I do not have control on how it does things. I was dealing with the tech that was familiar with the printer but it is old and hasn't had new firmware made for it since 2017.

[adynis]

Forgot to add and I edited enough....

Controlled Folder Access is off. I can create, delete and rename files in the destination. The AV is Emsisoft and XDR is Cylance PROTECT and Cylance OPTICS but they are on monitor only, no blocking. Only emsisoft blocks and I have the md5 checksum for both server versions whitelisted in emsisoft.

[oibaf]

Hi,

1.1.0 has been out for a while now, would you please try with that one again? Just to be sure the problem still exists with the latest version.

If the problem persists, could you please show how you configured the two servers, regarding shared folders? I am asking, because of two oddities:

1) The lack of "CWD Scans" in the log from the old server
2) Then the "error 5", which implies that reading from the file failed, which in turn implies that the server was actually able to open the file for reading - or else it would have reported error 550.

Thanks.

[adynis]

I'm sorry, it is 1.1.0 I had the number wrong in my post. I had downloaded it only a few days ago from your website which was the latest version.

On 1.1.0, the alias was / mapped to e:\scans

on 0.9.6, The Home Directory of the user is e:\scans

I have no clue how to attach a imgur image.... but it just has e:\scans as the home directory.

The file does not exist in the directory. The filenames are date and time codes. The other printer is a Canon iR-ADV C3525 uses SMB to talk to the same directory but has a different naming scheme - that has no issues. That and they don't scan that often, maybe 2-3 times per day, so no scans had anywhere near the same name. I understand where you are coming from but someone else on this forum has this same issue, I responded to that post.

Why would 0.9.6 work and 1.1.0 not? Nothing is interfering with it. I disabled the AV and all of it.

[botg]

Code: Select all

(000001)11/10/2021 14:41:07 PM - scans (10.6.0.60)> RETR 20211110142417644.pdf
(000001)11/10/2021 14:41:07 PM - scans (10.6.0.60)> 550 File not found
...
(000001)11/10/2021 14:41:07 PM - scans (10.6.0.60)> STOR 20211110142417644.pdf

That is a very odd sequence of commands. There are far, far better way to check for existence of a file, such as presence in a standard directory listing. Clearly, the client is doing things it shouldn't really do to begin with. Have you reported this yet to your client vendor @adynis?

Code: Select all

2021-11-09T15:54:02.065Z >> [FTP Session 5 10.6.0.60 scans] RETR 20211109103712008-1.pdf
2021-11-09T15:54:02.065Z << [FTP Session 5 10.6.0.60 scans] 150 Starting data transfer.
2021-11-09T15:54:02.081Z << [FTP Session 5 10.6.0.60 scans] 425 Error reading from file: 5

The 4yz looks fishy. Non-existence of a file shouldn't result in a 4yz. If I'm not mistaken (correct me if I'm wrong @oibaf) this has already been fixed in the latest nightly builds.

[oibaf]

Indeed.

@adynis, can you please try the latest nightly build? You can download the "prefix_win64" one from here: https://filezilla-project.org/nightly.php?type=server

[chebik]

Hello. Same problem. After ugrading to nightly build 15/11/2021 error 425 changed to Unable to download file: 550 Invalid file name or path

[chebik]

After downgrading to 1.0.1 all works fine ((

[oibaf]

Hello. Same problem. After ugrading to nightly build 15/11/2021 error 425 changed to Unable to download file: 550 Invalid file name or path

Are you having this problem with the scanner, as the OP? "Invalid file name or path" hints at invalid characters in the file name or path, can you please post the full log?

[chebik]

Not with scanner. Just simple file download started by sheduler.
2021-11-15T17:50:13.890Z << [FTP Session 10 5.58.97.188 dataagent] 230 Login successful.
2021-11-15T17:50:13.911Z >> [FTP Session 10 5.58.97.188 dataagent] TYPE I
2021-11-15T17:50:13.911Z << [FTP Session 10 5.58.97.188 dataagent] 200 Type set to I
2021-11-15T17:50:13.931Z >> [FTP Session 10 5.58.97.188 dataagent] STRU F
2021-11-15T17:50:13.931Z << [FTP Session 10 5.58.97.188 dataagent] 200 Using file structure 'File'
2021-11-15T17:50:13.953Z >> [FTP Session 10 5.58.97.188 dataagent] MODE S
2021-11-15T17:50:13.953Z << [FTP Session 10 5.58.97.188 dataagent] 200 MODE set to S
2021-11-15T17:50:14.061Z >> [FTP Session 10 5.58.97.188 dataagent] REST 0
2021-11-15T17:50:14.061Z << [FTP Session 10 5.58.97.188 dataagent] 350 Restarting at 0
2021-11-15T17:50:14.090Z >> [FTP Session 10 5.58.97.188 dataagent] REST 1
2021-11-15T17:50:14.090Z << [FTP Session 10 5.58.97.188 dataagent] 350 Restarting at 1
2021-11-15T17:50:14.120Z >> [FTP Session 10 5.58.97.188 dataagent] REST 0
2021-11-15T17:50:14.120Z << [FTP Session 10 5.58.97.188 dataagent] 350 Restarting at 0
2021-11-15T17:50:14.152Z >> [FTP Session 10 5.58.97.188 dataagent] OPTS UTF8 ON
2021-11-15T17:50:14.152Z << [FTP Session 10 5.58.97.188 dataagent] 202 UTF8 mode is always enabled. No need to send this command
2021-11-15T17:50:14.180Z >> [FTP Session 10 5.58.97.188 dataagent] EPSV 1
2021-11-15T17:50:14.181Z << [FTP Session 10 5.58.97.188 dataagent] 229 Entering Extended Passive Mode (|||55551|)
2021-11-15T17:50:14.221Z >> [FTP Session 10 5.58.97.188 dataagent] TYPE A
2021-11-15T17:50:14.221Z << [FTP Session 10 5.58.97.188 dataagent] 200 Type set to A
2021-11-15T17:50:14.251Z >> [FTP Session 10 5.58.97.188 dataagent] RETR tabletki\yanovich\tabletki_export.sql
2021-11-15T17:50:14.251Z << [FTP Session 10 5.58.97.188 dataagent] 550 Invalid file name or path
2021-11-15T17:50:14.281Z >> [FTP Session 10 5.58.97.188 dataagent] QUIT
2021-11-15T17:50:14.281Z << [FTP Session 10 5.58.97.188 dataagent] 200 Goodbye.

[chebik]

Had to update to 1.1.0 again to receive error

[oibaf]

You are using backslashes in the filepath, they're not valid path separators for FTP and the fact the old server supports them is due to a bug that was closed by 1.1.0, which could actually be used to compromise the server.

Please, fix your scheduler and upgrade to 1.1.0.

[chebik]

Thanks. I'll try tomorrow.

[botg]

2021-11-15T17:50:14.061Z >> [FTP Session 10 5.58.97.188 dataagent] REST 0
2021-11-15T17:50:14.061Z << [FTP Session 10 5.58.97.188 dataagent] 350 Restarting at 0
2021-11-15T17:50:14.090Z >> [FTP Session 10 5.58.97.188 dataagent] REST 1
2021-11-15T17:50:14.090Z << [FTP Session 10 5.58.97.188 dataagent] 350 Restarting at 1
2021-11-15T17:50:14.120Z >> [FTP Session 10 5.58.97.188 dataagent] REST 0
2021-11-15T17:50:14.120Z << [FTP Session 10 5.58.97.188 dataagent] 350 Restarting at 0

New feature request: Punch the client in the face if it does such things.

[chebik]

You are using backslashes in the filepath, they're not valid path separators for FTP and the fact the old server supports them is due to a bug that was closed by 1.1.0, which could actually be used to compromise the server.

Please, fix your scheduler and upgrade to 1.1.0.

I can confirm that using path like /folder/folder/file in scheduler works fine with 1.1.0. Thank you very much.