ftp server disconnects during upload

knireis · May 26th 2020

I have enabled the ftp server and till about a week ago everything worked fine.

Now i have issues with connections being disconnected.

When restarting my omv server i get 3 email system notifications (in sequence of appearing)

1.

Host: \openmediavault.local

Date: Tue, 26 May 2020 15:09:13

Service: proftpd

Event: Does not exist

Description: process is not running

This triggered the monitoring system to: restart

2.

Host: \openmediavault.local

Date: Tue, 26 May 2020 15:09:44

Service: proftpd

Event: Exists

Description: process is running with pid 3530

This triggered the monitoring system to: alert

3.

Host: \openmediavault.local

Date: Tue, 26 May 2020 15:10:44

Service: proftpd

Event: Connection failed

Description: failed protocol test [FTP] at [localhost]:21 [TCP/IP] -- FTP: error receiving data -- Resource temporarily unavailable

This triggered the monitoring system to: restart

Then no notifications, the indicators are green but as i said connections are interrupted. In the log files is hardly any information:

Tue May 26 15:16:53 2020 23 185.94.230.101 645463840 /neostrada/www.leukgevonden.com/www.leukgevonden.com-20200526-131135-4c4ojt.wpress b _ i r ftpuser ftp 1 * i

Tue May 26 15:17:28 2020 26 185.94.230.101 726804016 /neostrada/www.leukgevonden.com/www.leukgevonden.com-20200526-131135-4c4ojt.wpress b _ i r ftpuser ftp 1 * i

Tue May 26 15:17:57 2020 25 185.94.230.101 756887848 /neostrada/www.leukgevonden.com/www.leukgevonden.com-20200526-131135-4c4ojt.wpress b _ i r ftpuser ftp 1 * i

Tue May 26 15:18:29 2020 26 185.94.230.101 740735640 /neostrada/www.leukgevonden.com/www.leukgevonden.com-20200526-131135-4c4ojt.wpress b _ i r ftpuser ftp 1 * i

knireis · Jun 2nd 2020

Noboby else has this issue? It looks like connetion is disconnect after certain amount of time. Then the client tries again. Smaller files are transferred ok.

knireis · Jun 7th 2020

I switched to the pve kernel and the issue has gone. When restarting the omv server i now get only the first 2 email system notifications.

knireis · Jun 9th 2020

Unfortunately the error returned. I updated OMV to 5.5.2, but i do not know if that caused it.

Here is a part of the filezilla log maybe someone can give advice? It is in Dutch but i translated the most important parts

2020-06-09 09:02:34 6036 4 Antwoord: 227 Entering Passive Mode (192,168,1,4,168,69).

2020-06-09 09:02:34 6036 4 Opdracht: STOR leukgevonden.com-20200511-140033-h5tg2u.wpress

2020-06-09 09:02:34 6036 4 Antwoord: 150 Opening BINARY mode data connection for leukgevonden.com-20200511-140033-h5tg2u.wpress

2020-06-09 09:03:00 6036 3 Status: Connection closed by server

2020-06-09 09:03:02 6036 4 Fout: Could not write to transfer socket: ECONNRESET - Connection reset by server

2020-06-09 09:03:02 6036 4 Fout: Connection closed by server

2020-06-09 09:03:02 6036 4 Fout: File transfer fails after the transfer of 434,7 MB inr 28 seconden

2020-06-09 09:03:02 6036 4 Status: Connection with server lost

2020-06-09 09:03:02 6036 4 Status: Verbinden met 192.168.1.4:21...

2020-06-09 09:03:02 6036 4 Status: Verbinding gemaakt, welkomstbericht afwachten...

2020-06-09 09:03:02 6036 4 Antwoord: 220 ProFTPD Server ready.

2020-06-09 09:03:02 6036 4 Opdracht: AUTH TLS

2020-06-09 09:03:02 6036 4 Antwoord: 500 AUTH not understood

2020-06-09 09:03:02 6036 4 Opdracht: AUTH SSL

2020-06-09 09:03:02 6036 4 Antwoord: 500 AUTH not understood

2020-06-09 09:03:02 6036 4 Status: Onveilige server, die geen FTP over TLS ondersteunt.

pcreadycl · Oct 16th 2020

same here ovm v5.5.12

yarvv · Jan 9th 2021

The same problem!

FTP service is ON, TLS/SSL is ON, TLS/SSL is required, passive mode ON, no masqerade

Deep investigation results:

1 - proftpd binded on port 21 or the any other - no effect, error exist

2 - only if "Implicit SSL" in SSL/TLS settings is ON error exist, but without this parameter not works my FTPS uploads by CURL (?)

3 - "monit" service checks proftpd`s state every 30 sec and cause this error

/var/log/proftpd/tls.log fragment:

......

>>2021-01-08 23:00:06,612 mod_tls/2.7[30134]: TLSOption UseImplicitSSL in effect, starting SSL/TLS handshake

>>2021-01-08 23:00:11,613 mod_tls/2.7[30134]: unable to accept TLS connection: system call error: [0] Р’С‹РїРѕР»РЅРµРЅРѕ

4 - if disable port check in "monit" config, all works fine

/etc/monit/conf.d/openmediavault-proftpd.conf string:

.....

>> # if failed port 21 protocol ftp for 3 cycles then restart

It is no true solution, but is acceptable in this moment

mi-hol · Jan 9th 2021

votdev could you please have a look to validate the suspected root cause " "monit" service checks proftpd`s state every 30 sec and cause this error"?

yarvv · Jan 9th 2021

Quote from mi-hol

votdev could you please have a look to validate the suspected root cause " "monit" service checks proftpd`s state every 30 sec and cause this error"?

Deep inspection configs and logs!

1 - Simulating problem re-enabling port 21 check in monit config...

Time in logs is corresponding

every 30 sec monit detects error and restarts proftpd

/var/log/syslog:

Jan 9 20:01:09 slavaya-omv monit[27662]: Monit daemon with pid [27662] stopped

Jan 9 20:01:09 slavaya-omv monit[27662]: '\slavaya-omv.local' Monit 5.26.0 stopped

Jan 9 20:01:09 slavaya-omv monit[10898]: Stopping daemon monitor: monit.

Jan 9 20:01:09 slavaya-omv systemd[1]: monit.service: Succeeded.

Jan 9 20:01:09 slavaya-omv systemd[1]: Stopped LSB: service and resource monitoring daemon.

Jan 9 20:01:29 slavaya-omv systemd[1]: Starting LSB: service and resource monitoring daemon...

Jan 9 20:01:29 slavaya-omv monit[10990]: Starting Monit 5.26.0 daemon with http interface at /run/monit.sock

Jan 9 20:01:29 slavaya-omv monit[10987]: Starting daemon monitor: monit.

Jan 9 20:01:29 slavaya-omv systemd[1]: Started LSB: service and resource monitoring daemon.

Jan 9 20:01:29 slavaya-omv monit[10992]: '\slavaya-omv.local' Monit 5.26.0 started

Jan 9 20:01:34 slavaya-omv monit[10992]: 'proftpd' failed protocol test [FTP] at [localhost]:21 [TCP/IP] -- FTP: error receiving data -- Resource temporarily unavailable

Jan 9 20:01:34 slavaya-omv proftpd[10994]: 192.168.254.112 (127.0.0.1[127.0.0.1]) - mod_tls.c: error initializing session: РћС‚РєР°Р·Р°РЅРѕ РІ РґРѕСЃС‚СѓРїРµ

Jan 9 20:02:09 slavaya-omv monit[10992]: 'proftpd' failed protocol test [FTP] at [localhost]:21 [TCP/IP] -- FTP: error receiving data -- Resource temporarily unavailable

Jan 9 20:02:09 slavaya-omv proftpd[11049]: 192.168.254.112 (127.0.0.1[127.0.0.1]) - mod_tls.c: error initializing session: РћС‚РєР°Р·Р°РЅРѕ РІ РґРѕСЃС‚СѓРїРµ

Jan 9 20:02:45 slavaya-omv monit[10992]: 'proftpd' failed protocol test [FTP] at [localhost]:21 [TCP/IP] -- FTP: error receiving data -- Resource temporarily unavailable

Jan 9 20:02:45 slavaya-omv monit[10992]: 'proftpd' trying to restart

Jan 9 20:02:45 slavaya-omv monit[10992]: 'proftpd' stop: '/etc/init.d/proftpd stop'

Jan 9 20:02:45 slavaya-omv proftpd[11103]: 192.168.254.112 (127.0.0.1[127.0.0.1]) - mod_tls.c: error initializing session: РћС‚РєР°Р·Р°РЅРѕ РІ РґРѕСЃС‚СѓРїРµ

Jan 9 20:02:45 slavaya-omv systemd[1]: Stopping LSB: Starts ProFTPD daemon...

Jan 9 20:02:45 slavaya-omv proftpd[31802]: 192.168.254.112 - ProFTPD killed (signal 15)

Jan 9 20:02:45 slavaya-omv proftpd[31802]: 192.168.254.112 - ProFTPD 1.3.6 standalone mode SHUTDOWN

Jan 9 20:02:45 slavaya-omv proftpd[11121]: Stopping ftp server: proftpd.

Jan 9 20:02:45 slavaya-omv systemd[1]: proftpd.service: Succeeded.

Jan 9 20:02:45 slavaya-omv systemd[1]: Stopped LSB: Starts ProFTPD daemon.

Jan 9 20:02:45 slavaya-omv monit[10992]: 'proftpd' start: '/etc/init.d/proftpd restart'

Jan 9 20:02:45 slavaya-omv systemd[1]: Starting LSB: Starts ProFTPD daemon...

Jan 9 20:02:45 slavaya-omv proftpd[11150]: 192.168.254.112 - ProFTPD 1.3.6 (stable) (built Tue Mar 10 2020 23:03:08 UTC) standalone mode STARTUP

Jan 9 20:02:45 slavaya-omv proftpd[11140]: Starting ftp server: proftpd.

Jan 9 20:02:45 slavaya-omv systemd[1]: Started LSB: Starts ProFTPD daemon.

Jan 9 20:03:21 slavaya-omv monit[10992]: 'proftpd' failed protocol test [FTP] at [localhost]:21 [TCP/IP] -- FTP: error receiving data -- Resource temporarily unavailable

Jan 9 20:03:21 slavaya-omv monit[10992]: 'proftpd' trying to restart

Jan 9 20:03:21 slavaya-omv monit[10992]: 'proftpd' stop: '/etc/init.d/proftpd stop'

Jan 9 20:03:21 slavaya-omv proftpd[11196]: 192.168.254.112 (127.0.0.1[127.0.0.1]) - mod_tls.c: error initializing session: РћС‚РєР°Р·Р°РЅРѕ РІ РґРѕСЃС‚СѓРїРµ

Jan 9 20:03:21 slavaya-omv systemd[1]: Stopping LSB: Starts ProFTPD daemon...

Jan 9 20:03:21 slavaya-omv proftpd[11150]: 192.168.254.112 - ProFTPD killed (signal 15)

Jan 9 20:03:21 slavaya-omv proftpd[11150]: 192.168.254.112 - ProFTPD 1.3.6 standalone mode SHUTDOWN

Jan 9 20:03:21 slavaya-omv proftpd[11214]: Stopping ftp server: proftpd.

Jan 9 20:03:21 slavaya-omv systemd[1]: proftpd.service: Succeeded.

Jan 9 20:03:21 slavaya-omv systemd[1]: Stopped LSB: Starts ProFTPD daemon.

Jan 9 20:03:21 slavaya-omv monit[10992]: 'proftpd' start: '/etc/init.d/proftpd restart'

Jan 9 20:03:21 slavaya-omv systemd[1]: Starting LSB: Starts ProFTPD daemon...

Jan 9 20:03:21 slavaya-omv proftpd[11242]: 192.168.254.112 - ProFTPD 1.3.6 (stable) (built Tue Mar 10 2020 23:03:08 UTC) standalone mode STARTUP

Jan 9 20:03:21 slavaya-omv proftpd[11234]: Starting ftp server: proftpd.

Jan 9 20:03:21 slavaya-omv systemd[1]: Started LSB: Starts ProFTPD daemon.

Jan 9 20:03:57 slavaya-omv monit[10992]: 'proftpd' failed protocol test [FTP] at [localhost]:21 [TCP/IP] -- FTP: error receiving data -- Resource temporarily unavailable

Jan 9 20:03:57 slavaya-omv monit[10992]: 'proftpd' trying to restart

Jan 9 20:03:57 slavaya-omv monit[10992]: 'proftpd' stop: '/etc/init.d/proftpd stop'

Jan 9 20:03:57 slavaya-omv proftpd[11289]: 192.168.254.112 (127.0.0.1[127.0.0.1]) - mod_tls.c: error initializing session: РћС‚РєР°Р·Р°РЅРѕ РІ РґРѕСЃС‚СѓРїРµ

Jan 9 20:03:57 slavaya-omv systemd[1]: Stopping LSB: Starts ProFTPD daemon...

Jan 9 20:03:57 slavaya-omv proftpd[11242]: 192.168.254.112 - ProFTPD killed (signal 15)

Jan 9 20:03:57 slavaya-omv proftpd[11242]: 192.168.254.112 - ProFTPD 1.3.6 standalone mode SHUTDOWN

Jan 9 20:03:57 slavaya-omv proftpd[11307]: Stopping ftp server: proftpd.

Jan 9 20:03:57 slavaya-omv systemd[1]: proftpd.service: Succeeded.

Jan 9 20:03:57 slavaya-omv systemd[1]: Stopped LSB: Starts ProFTPD daemon.

Jan 9 20:03:57 slavaya-omv monit[10992]: 'proftpd' start: '/etc/init.d/proftpd restart'

Jan 9 20:03:57 slavaya-omv systemd[1]: Starting LSB: Starts ProFTPD daemon...

Jan 9 20:03:57 slavaya-omv proftpd[11334]: 192.168.254.112 - ProFTPD 1.3.6 (stable) (built Tue Mar 10 2020 23:03:08 UTC) standalone mode STARTUP

Jan 9 20:03:57 slavaya-omv proftpd[11326]: Starting ftp server: proftpd.

Jan 9 20:03:57 slavaya-omv systemd[1]: Started LSB: Starts ProFTPD daemon.

Jan 9 20:04:33 slavaya-omv monit[10992]: 'proftpd' failed protocol test [FTP] at [localhost]:21 [TCP/IP] -- FTP: error receiving data -- Resource temporarily unavailable

Jan 9 20:04:33 slavaya-omv monit[10992]: 'proftpd' trying to restart

Jan 9 20:04:33 slavaya-omv monit[10992]: 'proftpd' stop: '/etc/init.d/proftpd stop'

Jan 9 20:04:33 slavaya-omv proftpd[11381]: 192.168.254.112 (127.0.0.1[127.0.0.1]) - mod_tls.c: error initializing session: РћС‚РєР°Р·Р°РЅРѕ РІ РґРѕСЃС‚СѓРїРµ

Jan 9 20:04:33 slavaya-omv systemd[1]: Stopping LSB: Starts ProFTPD daemon.......

see attach - 10000 char limit

votdev · Jan 11th 2021

Quote from mi-hol

votdev could you please have a look to validate the suspected root cause " "monit" service checks proftpd`s state every 30 sec and cause this error"?

I can not do everything. But based on the information that are available it seems that monit and/or proftpd has some issues with checking port 21 when implicit SSL is used. IMO this is a good starting point for digging into this issue. I'm happy to see ideas for useful improvements.

votdev · Jan 11th 2021

According to https://mmonit.com/monit/docum…nit.html#CONNECTION-TESTS, could you please do some tests using the configuration line if failed port 21 for 3 cycles then restart? The docs mention that the protocol should not be set if it is not in the list of supported protocols. Maybe monit is clever enough and it will fix the issue.

Please open a bug report in this case, tracking such issues in the forum is impossible.

votdev · Jan 11th 2021

The issue is addressed by https://github.com/openmediavault/openmediavault/pull/931. Adding with ssl will fix the issue.

Code

if failed port 21 protocol ftp with ssl for 3 cycles then restart

mi-hol · Jan 11th 2021

Thanks votdev dev it sounded like an issue requiring a developer to look into

cubemin · Feb 3rd 2021

Can we expect an update to OMV soon that will include the fix for this issue? (Hope I'm not coming across as impatient, but just trying to get an idea.)

Or can one manually apply it, and if so, how? I'm looking at the commit on Github but it's a bit too complex for my humble mind... although I gather that it entails replacing a few specific config files.

ftp server disconnects during upload

Participate now!

Tags