6.8.0 breaks FTP

[chainlinc]

After upgrading to OS6 6.8.0, scans from my Lexmark MX410de multi-function scanner fail if the .pdf file being written to is not altered within about 3 seconds. This is a new failure that did not exist with the past ReadyNAS firmwares. Let me explain...

The scanner starts a scan and creates a .pdf file at the beginning of the scan. As the scan progresses, the .pdf file is 'added to' by the additional pages as they are scanned. If there is a delay of more than three seconds, such as between pages if the auto-document-feeder is not used, or by very high resolution scans, the scanner responds with a connection error. There was no trouble with prior firmwares. There is no trouble if I use another FTP server.

My ReadyNAS and the scanner are both assigned reserved IP addresses by the DHCP server, and the FTP server is addressed by IP address.

This occurs whether or not anti-virus is turned on on the ReadyNAS. File search is turned off. There are terabytes of free space on the ReadyNAS.  Single pages (or multiple pages via the auto-document-feeder) at low or medium resolution work fine.

Any ideas? Has a timout or file-lock property been adjusted down in the current firmware?

[Skywalker · Accepted solution]

We traced the cause of the issue, and have posted our findings to the ProFTPD bugzilla report.  We should be able to get it fixed for the next 6.9.0 Beta.

[Marty_M]

Hello chainlinc,

 
I would like to verify the NAS and scanner is on the same local network? The 6.8.0 firmware did not made any changes on ftp access on the NAS. You have mentioned that if the resolution is set to low or medium it does work fine. There is a possibility that the NAS is lacking resources in scanning higher resolution files. Do you have ftp rate limit or ftp permission set on the shares that the scanner access. Can you provide the complete logs of the NAS, you may use file sharing website like wikisend and just PM the download link. 
 
Regards,
Marty_M 
NETGEAR Community Team

[chainlinc]

Both the NAS and the scanner are on the same local, wired network, both receiving a reserved IP address from the DHCP server.

Even low resolution scans fail when they are multiple page and the ADF is not used (the pause between placing the next page triggers the failure).

I set up a temporary FTP server on a Windows 10 Pro computer and the scanner scans to it just fine.

There is no FTP rate limit set. Permissions should not be an issue, as scans without a delay between pages work fine.

I will PM the logs.

[chainlinc]

PM sent

[chainlinc]

Below are three entries from the proftpd.log file just created:

Entry 1 shows a successful scan to the FTP server.

Entries 2 and 3 are a failed scan and the error.

Does anyone know what the last character (c or i) in the first two entries represents?

Mon Sep 18 09:38:50 2017 6 192.168.2.125 1166589 /var/ftp/shared_files/Documents/Online_Statements/_From_Scanner/Scanned_2017-09-18-103840.pdf b _ i r dtesluk ftp 0 * c

Mon Sep 18 09:39:11 2017 14 192.168.2.125 1048609 /var/ftp/shared_files/Documents/Online_Statements/_From_Scanner/Scanned_2017-09-18-103853.pdf b _ i r dtesluk ftp 0 * i

2017-09-18 09:39:15,690 rnpro proftpd[4729] 127.0.0.2 (192.168.2.125[192.168.2.125]): notice: user dtesluk: aborting transfer: Interrupted system call

[chainlinc]

Logs reveal that the OS on this ReadyNAS was updated to 6.8.0 on 2017-Aug-18.

Logs also reveal that the ProFTPD service on this ReadyNAS changed from 1.3.5b (maint) to 1.3.6 (stable) on 2017-08-18 (presumably by the firmware update).

It looks to me that the issue started from and is related to these linked updates.

[Marty_M]

Hello chainlinc,

 
It does appear that there is a bond set on the NIC cards what bonding/teaming is setup on the NAS? Have you try disconnecting the bond and just use a single ethernet port and then check the connection? Is the NAS connected to a Netgear switch?

I have notice there are  lot of logs listed below that I may need to check this with others who can probably assist us and get back to you as soon as possible.

Thanks for your cooperation!

Sep 18 09:52:08 rnpro proftpd[23603]: pam_unix(ftp:session): session opened for user admin by (uid=0)
Sep 18 09:52:08 rnpro proftpd[23603]: pam_unix(ftp:session): session closed for user admin
Sep 18 09:52:09 rnpro kernel: bond0: An illegal loopback occurred on adapter (eth0)

                                                 Check the configuration to verify that all adapters are connected to 802.3ad compliant switch ports
Sep 18 09:52:09 rnpro kernel: bond0: An illegal loopback occurred on adapter (eth1)

                                                 Check the configuration to verify that all adapters are connected to 802.3ad compliant switch ports 
 
Regards,
Marty_M 
NETGEAR Community Team

[chainlinc]

---

@Marty_M wrote:

Hello chainlinc,

 
It does appear that there is a bond set on the NIC cards what bonding/teaming is setup on the NAS? Have you try disconnecting the bond and just use a single ethernet port and then check the connection? Is the NAS connected to a Netgear switch?

I have notice there are  lot of logs listed below that I may need to check this with others who can probably assist us and get back to you as soon as possible.

Thanks for your cooperation!

Sep 18 09:52:08 rnpro proftpd[23603]: pam_unix(ftp:session): session opened for user admin by (uid=0)
Sep 18 09:52:08 rnpro proftpd[23603]: pam_unix(ftp:session): session closed for user admin
Sep 18 09:52:09 rnpro kernel: bond0: An illegal loopback occurred on adapter (eth0)

                                                 Check the configuration to verify that all adapters are connected to 802.3ad compliant switch ports
Sep 18 09:52:09 rnpro kernel: bond0: An illegal loopback occurred on adapter (eth1)

                                                 Check the configuration to verify that all adapters are connected to 802.3ad compliant switch ports 
 
Regards,
Marty_M 
NETGEAR Community Team

---

Marty_M,

I did try disconnecting the bond and just used a single ethernet port and then checked the connection - the problem persists.

Bond on ReadyNASBonding/teaming is setup on the NAS as a LACP team connected to a Netgear JGS524PE - 24-Port Gigabit ProSAFE Plus Switch through ports 13 and 15. The LAG was disabled on the switch and is now enabled. Switch has firmware 2.0.1.40. I am now going to try with the bond removed and use a single ethernet port on the switch (not 13 nor 15).

Bond on ReadyNASOn Netgear switch

[chainlinc]

The problem persists with the bond removed. I really think this is related to the 'upgrade' in OS 6.8.0 of the embedded ProFTPD service from 1.3.5b (maint) to 1.3.6 (stable).

Ethernet (not bonded) on port 21

[Marty_M]

Hello chainlinc,

Have you tried reflashing the firmware of the NAS? You may want to also try beta firmware 6.8.1 or 6.9.0 and check if it will make any difference. But I would recommend to have backup of the data save on the NAS before further troubleshooting. May I also ask for new copy of the logs.
 
Regards,
Marty_M 
NETGEAR Community Team

[chainlinc]

---

@Marty_M wrote:

Hello chainlinc,

Have you tried reflashing the firmware of the NAS? You may want to also try beta firmware 6.8.1 or 6.9.0 and check if it will make any difference. But I would recommend to have backup of the data save on the NAS before further troubleshooting. May I also ask for new copy of the logs.
 
Regards,
Marty_M 
NETGEAR Community Team

---

I have not re-flashed the firmware. Nor have I tried the beta firmware.

Logs send by PM link.

Right before downloading logs, I made a successful scan (by completing it within 3 seconds), followed by an unsuccessful scan (by trying a second hand-placed page).

The same sequence to a Win10 FTP server results in no errors.

The Bond was been removed earlier today to take that out of the equation.

[StephenB]

---

@chainlinc wrote:

I really think this is related to the 'upgrade' in OS 6.8.0 of the embedded ProFTPD service from 1.3.5b (maint) to 1.3.6 (stable).

I suspect you are right.  There is an open bug recently reported "Frequently breaks of FTP uploads - interrupted system call".  

http://bugs.proftpd.org/show_bug.cgi?id=4319

[chainlinc]

---

@StephenB wrote:

---

@chainlinc wrote:

I really think this is related to the 'upgrade' in OS 6.8.0 of the embedded ProFTPD service from 1.3.5b (maint) to 1.3.6 (stable).

I suspect you are right.  There is an open bug recently reported "Frequently breaks of FTP uploads - interrupted system call".  

http://bugs.proftpd.org/show_bug.cgi?id=4319

---

StephenB,

Thanks for that link. Possibly also related to this 'TimeoutLinger' report in ProFTDB 1.3.6:

http://bugs.proftpd.org/show_bug.cgi?id=4228

[chsu83]

did you found a fix for that problem?

[chainlinc]

---

@chsu83 wrote:

did you found a fix for that problem?

---

chsu83,

Sadly, I have not yet found a fix for the ReadyNAS.

[chsu83]

Puh.. can we contribute somewhere the logs or somewhat?

Unfortunately I don't see any correction in the Beta's.. how should they.. in the bugreport http://bugs.proftpd.org/show_bug.cgi?id=4319 is also no solution available.

If anybody (e.g. Netgear) has an account at proftpd, and I can contribute some files please inform me. (Perhaps I need to know how to start proftpd on readynas in verbose). Because there the os (where the failure is known) is only FreeBSD mentioned. Could be helpful to inform them about ReadyNAS Linux.

to specify things more precisely:

I'm using Readynas with 6.8.0

FTP works from Filezilla

But is broken from an OKI C5550 MFP

[Marty_M]

Hello chainlinc,

There is a big possibility that the bug from the proftpd 1.3.6 might be causing the problem. It does appear that it is being look onto right now and there is chance that fix might be available soon.

Regards,
Marty_M 
NETGEAR Community Team

[Skywalker · Accepted solution]

We traced the cause of the issue, and have posted our findings to the ProFTPD bugzilla report.  We should be able to get it fixed for the next 6.9.0 Beta.

[chsu83]

cool, Thank you

[chainlinc]

6.9.0-RC1 fixes the issue for me.