Timeouts on LISTing

[e-fik123]

Hi @Castaglia i am now experiencing this issue, i have compiled ProFTPd:

proftpd -V
Compile-time Settings:
Version: 1.3.9rc1 (devel)
Platform: LINUX [Linux 5.15.0-89-generic x86_64]
OS/Release:
PRETTY_NAME="Ubuntu 22.04.3 LTS"
NAME="Ubuntu"
VERSION_ID="22.04"
VERSION="22.04.3 LTS (Jammy Jellyfish)"
VERSION_CODENAME=jammy
ID=ubuntu
ID_LIKE=debian
UBUNTU_CODENAME=jammy
Built: Tue Dec 5 2023 14:01:30 CET
Built With:
configure '--with-includes=/usr/include/openssl:/usr/include:/usr/local/src/proftpd/contrib:/usr/local/src/proftpd/contrib/mod_proxy/include:/usr/include/mysql' '--sysconfdir=/etc/proftpd' '--with-libraries=/usr/lib/ssl:/usr/lib/x86_64-linux-gnu/:/usr/local/src/proftpd/contrib/mod_proxy/lib' '--enable-openssl' '--with-modules=mod_sql:mod_sql_mysql:mod_tls:mod_sftp:mod_proxy:mod_rewrite:mod_ban:mod_dynmasq:mod_wrap:mod_wrap2:mod_wrap2_file:mod_wrap2_sql:mod_ifsession:mod_shaper:mod_ctrls_admin:mod_unique_id:mod_site_misc:mod_load:mod_sftp_sql' '--enable-dso' '--enable-ctrls'

CFLAGS: -g2 -O2 -Wall -fno-omit-frame-pointer -fno-strict-aliasing
LDFLAGS: -Wl,-L$(top_srcdir)/lib,-L$(top_builddir)/lib -rdynamic -L/usr/local/src/proftpd/contrib/mod_proxy/lib -L/usr/lib/x86_64-linux-gnu/ -L/usr/lib/ssl -L/usr/lib/x86_64-linux-gnu
LIBS: -lssl -lcrypto -lwrap -lnsl -lsqlite3 -lssl -lm -lmysqlclient -lz -lcrypto -lcrypt -pthread

Files:
Configuration File:
/etc/proftpd/proftpd.conf
Pid File:
/usr/local/var/proftpd.pid
Scoreboard File:
/usr/local/var/proftpd.scoreboard
Header Directory:
/usr/local/include/proftpd
Shared Module Directory:
/usr/local/libexec

Info:
+ Max supported UID: 4294967295
+ Max supported GID: 4294967295

Features:
- Autoshadow support
+ Controls support
- curses support
- Developer support
+ DSO support
+ IPv6 support
+ Largefile support
- Lastlog support
- Memcache support
- ncurses support
- NLS support
+ OpenSSL support (OpenSSL 3.0.2 15 Mar 2022)
- PCRE support
- PCRE2 support
- POSIX ACL support
- Redis support
+ Sendfile support
+ Shadow file support
- Sodium support
+ Trace support
+ xattr support

Tunable Options:
PR_TUNABLE_BUFFER_SIZE = 1024
PR_TUNABLE_DEFAULT_RCVBUFSZ = 65536
PR_TUNABLE_DEFAULT_SNDBUFSZ = 65536
PR_TUNABLE_ENV_MAX = 2048
PR_TUNABLE_GLOBBING_MAX_MATCHES = 100000
PR_TUNABLE_GLOBBING_MAX_RECURSION = 8
PR_TUNABLE_HASH_TABLE_SIZE = 40
PR_TUNABLE_LOGIN_MAX = 256
PR_TUNABLE_NEW_POOL_SIZE = 512
PR_TUNABLE_PATH_MAX = 4096
PR_TUNABLE_SCOREBOARD_BUFFER_SIZE = 80
PR_TUNABLE_SCOREBOARD_SCRUB_TIMER = 30
PR_TUNABLE_SELECT_TIMEOUT = 30
PR_TUNABLE_TIMEOUTIDENT = 10
PR_TUNABLE_TIMEOUTIDLE = 600
PR_TUNABLE_TIMEOUTLINGER = 10
PR_TUNABLE_TIMEOUTLOGIN = 300
PR_TUNABLE_TIMEOUTNOXFER = 300
PR_TUNABLE_TIMEOUTSTALLED = 3600
PR_TUNABLE_XFER_SCOREBOARD_UPDATES = 10

with the latest mod_proxy. The backend FTP servers are: ProFTPd: 1.3.5 and also 1.3.9rc1.

Command: MLSD
Answer: 150 Opening BINARY mode data connection for MLSD
Error: Can not connect: ETIMEDOUT - Connection try exceeded timout limit

Any help is more then welcome.

Thank you

[e-fik123]

Also attaching paranooid log:

xxxxxxxxxxxxxxxx UNKNOWN - [05/Dec/2023:18:28:10 +0100] "USER admin@xxxxxxxxxxxxxxxx" 530 -
xxxxxxxxxxxxxxxx UNKNOWN admin@xxxxxxxxxxxxxxxx [05/Dec/2023:18:28:12 +0100] "PASS (hidden)" 230 -
xxxxxxxxxxxxxxxx UNKNOWN admin@xxxxxxxxxxxxxxxx [05/Dec/2023:18:28:12 +0100] "PBSZ 0" 200 -
xxxxxxxxxxxxxxxx UNKNOWN admin@xxxxxxxxxxxxxxxx [05/Dec/2023:18:28:12 +0100] "PROT P" 200 -
xxxxxxxxxxxxxxxx UNKNOWN admin@xxxxxxxxxxxxxxxx [05/Dec/2023:18:28:12 +0100] "CWD /webpage/subdomains" 250 -
xxxxxxxxxxxxxxxx UNKNOWN admin@xxxxxxxxxxxxxxxx [05/Dec/2023:18:28:13 +0100] "TYPE I" 200 -
xxxxxxxxxxxxxxxx UNKNOWN admin@xxxxxxxxxxxxxxxx [05/Dec/2023:18:28:13 +0100] "PASV" 227 -
xxxxxxxxxxxxxxxx UNKNOWN admin@xxxxxxxxxxxxxxxx [05/Dec/2023:18:28:13 +0100] "MLSD" - 509
xxxxxxxxxxxxxxxx UNKNOWN admin@xxxxxxxxxxxxxxxx [05/Dec/2023:18:28:16 +0100] "CWD dev" 250 -
xxxxxxxxxxxxxxxx UNKNOWN admin@xxxxxxxxxxxxxxxx [05/Dec/2023:18:28:16 +0100] "PWD" 257 -
xxxxxxxxxxxxxxxx UNKNOWN admin@xxxxxxxxxxxxxxxx [05/Dec/2023:18:28:16 +0100] "PASV" 227 -
xxxxxxxxxxxxxxxx UNKNOWN admin@xxxxxxxxxxxxxxxx [05/Dec/2023:18:28:16 +0100] "MLSD" - 4031
xxxxxxxxxxxxxxxx UNKNOWN admin@xxxxxxxxxxxxxxxx [05/Dec/2023:18:28:21 +0100] "CWD modules" 250 -
xxxxxxxxxxxxxxxx UNKNOWN admin@xxxxxxxxxxxxxxxx [05/Dec/2023:18:28:21 +0100] "PWD" 257 -
xxxxxxxxxxxxxxxx UNKNOWN admin@xxxxxxxxxxxxxxxx [05/Dec/2023:18:28:21 +0100] "PASV" 227 -

[Castaglia]

Can you configure a ProxyLog, and provide the messages from that log file, for a session which encounters these issues, please?

[e-fik123]

@Castaglia pls see below:

2023-12-05 18:28:10,432 mod_proxy/0.9.2[2812]: selected backend server 'ftp://192.168.50.154:21'
2023-12-05 18:28:10,438 mod_proxy/0.9.2[2812]: received banner from backend 192.168.50.154:21: 220 ProFTPD Server (Debian) [::ffff:192.168.50.154]
2023-12-05 18:28:10,440 mod_proxy/0.9.2[2812]: proxy session running as UID 65534, GID 65534, restricted to '/usr/local/var/proxy/empty'
2023-12-05 18:28:13,058 mod_proxy/0.9.2[2812]: Entering Passive Mode (xx,xx,xx,xx,194,243).
2023-12-05 18:28:13,109 mod_proxy/0.9.2[2812]: passive backend data connection opened - local  : 192.168.50.105:40363
2023-12-05 18:28:13,109 mod_proxy/0.9.2[2812]: passive backend data connection opened - remote : 192.168.50.154:45901
2023-12-05 18:28:13,189 mod_proxy/0.9.2[2812]: passive frontend data connection opened - local  : 192.168.50.105:49907
2023-12-05 18:28:13,189 mod_proxy/0.9.2[2812]: passive frontend data connection opened - remote : xx.xx.xx.xx:57969
2023-12-05 18:28:16,487 mod_proxy/0.9.2[2812]: Entering Passive Mode (xx,xx,xx,xx,193,53).
2023-12-05 18:28:16,526 mod_proxy/0.9.2[2812]: passive backend data connection opened - local  : 192.168.50.105:37175
2023-12-05 18:28:16,526 mod_proxy/0.9.2[2812]: passive backend data connection opened - remote : 192.168.50.154:32799
2023-12-05 18:28:16,596 mod_proxy/0.9.2[2812]: passive frontend data connection opened - local  : 192.168.50.105:49461
2023-12-05 18:28:16,596 mod_proxy/0.9.2[2812]: passive frontend data connection opened - remote : xx.xx.xx.xx:57970
2023-12-05 18:28:21,381 mod_proxy/0.9.2[2812]: Entering Passive Mode (xx,xx,xx,xx,196,238).
2023-12-05 18:28:21,428 mod_proxy/0.9.2[2812]: passive backend data connection opened - local  : 192.168.50.105:42617
2023-12-05 18:28:21,448 mod_proxy/0.9.2[2812]: passive backend data connection opened - remote : 192.168.50.154:44465

[Castaglia]

Thanks. Would it be possible to also get the ProFTPD debug logging, debug level 10, from the proxy, when this happens? I have a suspicion of what's happening, and am hoping that the debug logging (in combination with the ProxyLog) can provide more details.

[e-fik123]

Hi @Castaglia,
pls find attached debug log from PROFTPD with Proxy. Logs are not from backend.

The problem happened when reading folder: /httpdocs/admin/webfonts
The second attempt was then successful.

Below extract of the log with error
proftpd_debug.log

2023-12-13 14:58:43,471 elgvsrv129 proftpd[1807693] localhost (XX-XXX-XXX-XXX.iinternet.xx[XX.XXX.XXX.XXX]): ROOT PRIVS at mod_proxy.c:473
2023-12-13 14:58:43,471 elgvsrv129 proftpd[1807693] localhost (XX-XXX-XXX-XXX.iinternet.xx[XX.XXX.XXX.XXX]): opening TransferLog '/var/log/proftpd/xfer.log'
2023-12-13 14:58:43,471 elgvsrv129 proftpd[1807693] localhost (XX-XXX-XXX-XXX.iinternet.xx[XX.XXX.XXX.XXX]): REVOKE PRIVS at mod_proxy.c:519
2023-12-13 14:58:43,471 elgvsrv129 proftpd[1807693] localhost (XX-XXX-XXX-XXX.iinternet.xx[XX.XXX.XXX.XXX]): dispatching POST_CMD command 'USER admin@ftp.webpage.com' to mod_sql
2023-12-13 14:58:43,471 elgvsrv129 proftpd[1807693] localhost (XX-XXX-XXX-XXX.iinternet.xx[XX.XXX.XXX.XXX]): dispatching POST_CMD command 'USER admin@ftp.webpage.com' to mod_delay
2023-12-13 14:58:43,472 elgvsrv129 proftpd[1807693] localhost (XX-XXX-XXX-XXX.iinternet.xx[XX.XXX.XXX.XXX]): dispatching LOG_CMD command 'USER admin@ftp.webpage.com' to mod_sql
2023-12-13 14:58:43,472 elgvsrv129 proftpd[1807693] localhost (XX-XXX-XXX-XXX.iinternet.xx[XX.XXX.XXX.XXX]): dispatching LOG_CMD command 'USER admin@ftp.webpage.com' to mod_log
2023-12-13 14:58:43,472 elgvsrv129 proftpd[1807693] localhost (XX-XXX-XXX-XXX.iinternet.xx[XX.XXX.XXX.XXX]): dispatching LOG_CMD command 'USER admin@ftp.webpage.com' to mod_delay
2023-12-13 14:58:43,896 elgvsrv129 proftpd[1807693] localhost (XX-XXX-XXX-XXX.iinternet.xx[XX.XXX.XXX.XXX]): dispatching PRE_CMD command 'PASS (hidden)' to mod_rewrite
2023-12-13 14:58:43,896 elgvsrv129 proftpd[1807693] localhost (XX-XXX-XXX-XXX.iinternet.xx[XX.XXX.XXX.XXX]): dispatching PRE_CMD command 'PASS (hidden)' to mod_tls
2023-12-13 14:58:43,896 elgvsrv129 proftpd[1807693] localhost (XX-XXX-XXX-XXX.iinternet.xx[XX.XXX.XXX.XXX]): dispatching PRE_CMD command 'PASS (hidden)' to mod_core
2023-12-13 14:58:43,896 elgvsrv129 proftpd[1807693] localhost (XX-XXX-XXX-XXX.iinternet.xx[XX.XXX.XXX.XXX]): dispatching PRE_CMD command 'PASS (hidden)' to mod_core
2023-12-13 14:58:43,896 elgvsrv129 proftpd[1807693] localhost (XX-XXX-XXX-XXX.iinternet.xx[XX.XXX.XXX.XXX]): dispatching PRE_CMD command 'PASS (hidden)' to mod_ifsession
2023-12-13 14:58:43,896 elgvsrv129 proftpd[1807693] localhost (XX-XXX-XXX-XXX.iinternet.xx[XX.XXX.XXX.XXX]): dispatching PRE_CMD command 'PASS (hidden)' to mod_shaper
2023-12-13 14:58:43,896 elgvsrv129 proftpd[1807693] localhost (XX-XXX-XXX-XXX.iinternet.xx[XX.XXX.XXX.XXX]): ROOT PRIVS at mod_shaper.c:2064
2023-12-13 14:58:43,896 elgvsrv129 proftpd[1807693] localhost (XX-XXX-XXX-XXX.iinternet.xx[XX.XXX.XXX.XXX]): ROOT PRIVS: unable to seteuid(): Operation not permitted
2023-12-13 14:58:43,896 elgvsrv129 proftpd[1807693] localhost (XX-XXX-XXX-XXX.iinternet.xx[XX.XXX.XXX.XXX]): ROOT PRIVS: unable to setegid(): Operation not permitted
2023-12-13 14:58:43,896 elgvsrv129 proftpd[1807693] localhost (XX-XXX-XXX-XXX.iinternet.xx[XX.XXX.XXX.XXX]): RELINQUISH PRIVS at mod_shaper.c:2066
2023-12-13 14:58:43,896 elgvsrv129 proftpd[1807693] localhost (XX-XXX-XXX-XXX.iinternet.xx[XX.XXX.XXX.XXX]): RELINQUISH PRIVS: unable to seteuid(PR_ROOT_UID): Operation not permitted
2023-12-13 14:58:43,896 elgvsrv129 proftpd[1807693] localhost (XX-XXX-XXX-XXX.iinternet.xx[XX.XXX.XXX.XXX]): dispatching PRE_CMD command 'PASS (hidden)' to mod_wrap2
2023-12-13 14:58:43,896 elgvsrv129 proftpd[1807693] localhost (XX-XXX-XXX-XXX.iinternet.xx[XX.XXX.XXX.XXX]): dispatching PRE_CMD command 'PASS (hidden)' to mod_wrap
2023-12-13 14:58:43,896 elgvsrv129 proftpd[1807693] localhost (XX-XXX-XXX-XXX.iinternet.xx[XX.XXX.XXX.XXX]): dispatching PRE_CMD command 'PASS (hidden)' to mod_ban
2023-12-13 14:58:43,896 elgvsrv129 proftpd[1807693] localhost (XX-XXX-XXX-XXX.iinternet.xx[XX.XXX.XXX.XXX]): dispatching PRE_CMD command 'PASS (hidden)' to mod_sql
2023-12-13 14:58:43,896 elgvsrv129 proftpd[1807693] localhost (XX-XXX-XXX-XXX.iinternet.xx[XX.XXX.XXX.XXX]): dispatching PRE_CMD command 'PASS (hidden)' to mod_delay
2023-12-13 14:58:43,896 elgvsrv129 proftpd[1807693] localhost (XX-XXX-XXX-XXX.iinternet.xx[XX.XXX.XXX.XXX]): dispatching PRE_CMD command 'PASS (hidden)' to mod_auth
2023-12-13 14:58:43,897 elgvsrv129 proftpd[1807693] localhost (XX-XXX-XXX-XXX.iinternet.xx[XX.XXX.XXX.XXX]): dispatching CMD command 'PASS (hidden)' to mod_proxy
2023-12-13 14:58:45,630 elgvsrv129 proftpd[1807693] localhost (XX-XXX-XXX-XXX.iinternet.xx[XX.XXX.XXX.XXX]): ROOT PRIVS at lib/proxy/session.c:258
2023-12-13 14:58:45,630 elgvsrv129 proftpd[1807693] localhost (XX-XXX-XXX-XXX.iinternet.xx[XX.XXX.XXX.XXX]): RELINQUISH PRIVS at lib/proxy/session.c:274
2023-12-13 14:58:45,630 elgvsrv129 proftpd[1807693] localhost (XX-XXX-XXX-XXX.iinternet.xx[XX.XXX.XXX.XXX]): RELINQUISH PRIVS: unable to seteuid(PR_ROOT_UID): Operation not permitted

And below are logs from proxy from the same time as logs above:

2023-12-13 14:58:11,270 mod_proxy/0.8[1807692]: selected backend server 'ftp://192.168.50.152:21'
2023-12-13 14:58:11,355 mod_proxy/0.8[1807692]: received banner from backend 192.168.50.152:21: 220 ProFTPD 1.3.5 Server (Debian) [::ffff:192.168.50.152]
2023-12-13 14:58:11,358 mod_proxy/0.8[1807692]: proxy session running as UID 65534, GID 65534, restricted to '/usr/local/var/proxy/empty'
2023-12-13 14:58:18,937 mod_proxy/0.8[1807692]: Entering Passive Mode (XX,XXX,XX,XXX,193,191).
2023-12-13 14:58:19,005 mod_proxy/0.8[1807692]: passive backend data connection opened - local  : 192.168.50.105:38777
2023-12-13 14:58:19,005 mod_proxy/0.8[1807692]: passive backend data connection opened - remote : 192.168.50.152:50280
2023-12-13 14:58:19,110 mod_proxy/0.8[1807692]: passive frontend data connection opened - local  : 192.168.50.105:49599
2023-12-13 14:58:19,110 mod_proxy/0.8[1807692]: passive frontend data connection opened - remote : 37.188.179.181:37619
2023-12-13 14:58:22,668 mod_proxy/0.8[1807692]: Entering Passive Mode (XX,XXX,XX,XXX,199,144).
2023-12-13 14:58:22,724 mod_proxy/0.8[1807692]: passive backend data connection opened - local  : 192.168.50.105:42931
2023-12-13 14:58:22,724 mod_proxy/0.8[1807692]: passive backend data connection opened - remote : 192.168.50.152:47417
2023-12-13 14:58:43,465 mod_proxy/0.8[1807693]: selected backend server 'ftp://192.168.50.152:21'
2023-12-13 14:58:43,469 mod_proxy/0.8[1807693]: received banner from backend 192.168.50.152:21: 220 ProFTPD 1.3.5 Server (Debian) [::ffff:192.168.50.152]
2023-12-13 14:58:43,471 mod_proxy/0.8[1807693]: proxy session running as UID 65534, GID 65534, restricted to '/usr/local/var/proxy/empty'
2023-12-13 14:58:46,105 mod_proxy/0.8[1807693]: Entering Passive Mode (XX,XXX,XX,XXX,198,132).
2023-12-13 14:58:46,197 mod_proxy/0.8[1807693]: passive backend data connection opened - local  : 192.168.50.105:43555
2023-12-13 14:58:46,197 mod_proxy/0.8[1807693]: passive backend data connection opened - remote : 192.168.50.152:39368

[e-fik123]

Hi @Castaglia ,
requested logs are now provided. Can you pls help me to solve this issue, or can you help me with a workaround?

Thank you

[e-fik123]

adding also logs from latests PROFTPD version with the latest PROXY version logs
The error seams to be the same is in previous post. But just to make sure i did not miss anything
proftpd_proxy.log
proftpd_debug.log

[Castaglia]

From the logs, we see that the backend FTP server is using a private IP address (192.168.50.152).

We also see, in the logs, that the proxy is using a private IP address for frontend data transfers (192.168.50.105).

The question is: what's the IP address of the client? (Currently it's sanitized from the logs.).

Why does this matter? If the client is connecting to the proxy using a public IP address, and if the proxy is telling the client to connect to a private IP address for data transfers, then it would explain the timeouts you see when doing directory listings (which are a type of data transfer). The client would be trying to connect to a private IP address, and would not be able to do so.

We've not seen the full ProFTPD configuration being used for the proxy. But if the above is the case, then configuring the proxy to provide a public IP address for data transfers, using the MasqueradeAddress directive, might help.

Reference:

• https://slacksite.com/other/ftp.html

[e-fik123]

Hi @Castaglia,
as per comment above i do not connect from local network. But i connect from WAN.
I use masqueradeAddress.
Pls see attached partially sanitized logs. You can see the client connecting from 88.102.1XX.XX
The WAN address: MasqueradeAddress 84.242.XX.XXX

Adding debug loggin and configuration file
proftpd_debug.txt
proftpd_config.txt

If you need any more information pls let me know.

Regards

[Castaglia]

In the provided configuration, I see MasqueradeAddress, but not PassivePorts. Is there a firewall or NAT in front of the proxy? If so, is it configured to allow the entire port range for passive data transfers? Or, is it one of those firewalls/NATs which expects to be able to inspect the control connection FTP traffic, and dynamically open the necessary port for a passive data transfer? I see, from the provided debug log, that the client is using FTPS, which means the control connection is encrypted -- a firewall/NAT would not be able to inspect/snoop on the control connection traffic in this case.

[Castaglia]

Would it also be possible to get the ProFTPD debug logging of the backend FTP server as well?

For debugging issues like this, there are multiple places and multiple factors involved:

client -- (ftps) -- (firewall/NAT?) --> proxy -- ftps --> backend

Right now, I am looking for data to help indicate whether the main factors are closer to the proxy (and any possible firewall/NAT/router in front of it), or whether the main factors are closer to the backend FTP server.

[e-fik123]

HI @Castaglia
There is NAT to the internal address. Passive ports worked before this problem and therefore no changes in natting and in firewall. Also behind the proxy there is only FTP not FTPS.
PassivePorts are in the configuration
PassivePorts 49152 51151
Also in my previous comment

Below all logs. From frontend, proxy, backend

proftpd_frontend_debug.txt
proftpd_debug_proxy.txt
proftpd_debug_backend.txt

Thank you

[Castaglia]

Hmm. Nothing in the provided logs is showing any signs of errors. Are you still seeing the error reported by your FTPS client (which app is that)?

What's interesting is that these sessions appear to end after 2-3 data transfers (via MLSD directory listings), but nothing on the server side is showing any issues. So if you are still seeing this ETIMEDOUT error reported by your FTPS client, it seems like it would be caused by something between the client, and the proxy server.