proftpd-mod_proxy icon indicating copy to clipboard operation
proftpd-mod_proxy copied to clipboard
verified publisher icon Castaglia

mod_proxy not respecting "AllowForeignAddress on" setting

Open PAamac opened this issue 1 year ago • 18 comments

Using proftpd v1.3.8b with mod_proxy on Fedora 39 and trying to set up a DMZ-based FTPS proxy in private network space that will be used to access to a third party internet-based FTPS server that requires explicit TLS and passive mode transfers. The internet-based server uses separate data and control servers, so it is expected to receive a different public IP than the control server public IP in response to a PASV command.

mod_proxy is logging the following even when the "AllowForeignAddress on" option has been configured for proftpd, which is also the case if also adding this setting to a proxy-specific settings block in the conf file:

mod_proxy/0.9.4[3810226]: Refused PASV address 5.6.7.8 (address mismatch with 1.2.3.4)

I am not clear on whether this is a bug or not. If not, how can the option to accept FTPS data server IPs that differ from the control server IP be configured in mod_proxy?

Thank you for the project and your time

PAamac avatar Jun 26 '24 01:06 PAamac

Could you provide the full ProFTPD configuration you're using, please?

Castaglia avatar Jun 26 '24 15:06 Castaglia

Sure. Some settings have been in and out of config, such as "ProxyDataTransferPolicy PASV" --

ServerName "Server Name"
ServerType standalone
DefaultServer on

UseIPv6 off

Port 1234

PassivePorts 64700 64800

LogFormat default "%h %l %u %t \"%r\" %s %b"

TransferLog /var/log/proftpd/transfer.log

AllowStoreRestart on

AllowForeignAddress on

LoadModule mod_proxy.c

<IfModule mod_tls.c>
  TLSEngine on
  TLSLog /var/log/proftpd/tls.log
  TLSProtocol TLSv1.2
  TLSRSACertificateFile /etc/proftpd/ssl/ourcert.pem
  TLSRSACertificateKeyFile /etc/proftpd/ssl/ourcert.key.pem
  TLSVerifyClient off
  TLSRequired on
</IfModule>

<IfModule mod_proxy.c>
  ProxyEngine on
  ProxyTables /var/ftp/proxy

  MasqueradeAddress 11.22.33.44
  AllowForeignAddress on

  ProxyDataTransferPolicy PASV
  
  ProxyRole forward
  ProxyForwardMethod user@host

  # Log for proxy operations
  ProxyLog /var/log/proftpd/proxy.log

</IfModule>

PAamac avatar Jun 26 '24 16:06 PAamac

Thanks! So you're using forward proxying, of FTPS connections, correct? I don't see anything immediately obviously wrong/missing in the provided config.

While I work to reproduce this issue locally, could you configure/provide the ProxyLog (and ProFTPD debugging logging) for one of the sessions that runs into this problem? I'm hoping that the logs can provide more useful context/tidbits about what might be going on.

Castaglia avatar Jun 27 '24 00:06 Castaglia

Sure thing. Here is the debug ouput generated by using DebugLevel 10 in the conf file:

2024-06-27 14:37:06,919 our.server.internal proftpd[4025945] our.server.internal: 10.5.6.7:1234 masquerading as 11.22.33.44
2024-06-27 14:37:06,992 our.server.internal proftpd[4025945] our.server.internal: ProFTPD 1.3.8b (maint) (built Sun Mar 31 2024 00:00:00 UTC) standalone mode STARTUP
2024-06-27 14:37:10,505 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): connected - local  : 10.5.6.7:1234
2024-06-27 14:37:10,505 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): connected - remote : 10.1.2.3:62131
2024-06-27 14:37:10,505 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): FTP session opened.
2024-06-27 14:37:10,530 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'AUTH TLS' to mod_tls
2024-06-27 14:37:10,530 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'AUTH TLS' to mod_core
2024-06-27 14:37:10,530 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'AUTH TLS' to mod_core
2024-06-27 14:37:10,530 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching CMD command 'AUTH TLS' to mod_proxy
2024-06-27 14:37:10,530 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching CMD command 'AUTH TLS' to mod_tls
2024-06-27 14:37:10,584 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching POST_CMD command 'AUTH TLS' to mod_tls
2024-06-27 14:37:10,584 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching LOG_CMD command 'AUTH TLS' to mod_log
2024-06-27 14:37:10,584 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching LOG_CMD command 'AUTH TLS' to mod_tls
2024-06-27 14:37:13,826 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'USER [email protected]@remote.server.com' to mod_tls
2024-06-27 14:37:13,826 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'USER [email protected]@remote.server.com' to mod_core
2024-06-27 14:37:13,826 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'USER [email protected]@remote.server.com' to mod_core
2024-06-27 14:37:13,826 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'USER [email protected]@remote.server.com' to mod_delay
2024-06-27 14:37:13,826 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'USER [email protected]@remote.server.com' to mod_auth
2024-06-27 14:37:13,826 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching CMD command 'USER [email protected]@remote.server.com' to mod_proxy
2024-06-27 14:37:14,088 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching POST_CMD command 'USER [email protected]@remote.server.com' to mod_delay
2024-06-27 14:37:14,089 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching LOG_CMD command 'USER [email protected]@remote.server.com' to mod_log
2024-06-27 14:37:14,089 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching LOG_CMD command 'USER [email protected]@remote.server.com' to mod_delay
2024-06-27 14:37:14,112 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'PASS (hidden)' to mod_tls
2024-06-27 14:37:14,112 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'PASS (hidden)' to mod_core
2024-06-27 14:37:14,112 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'PASS (hidden)' to mod_core
2024-06-27 14:37:14,112 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'PASS (hidden)' to mod_delay
2024-06-27 14:37:14,112 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'PASS (hidden)' to mod_auth
2024-06-27 14:37:14,112 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching CMD command 'PASS (hidden)' to mod_proxy
2024-06-27 14:37:14,272 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]):
2024-06-27 14:37:14,272 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): Config for Server Name:
2024-06-27 14:37:14,272 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): DefaultServer
2024-06-27 14:37:14,272 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): DebugLevel
2024-06-27 14:37:14,272 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): Port
2024-06-27 14:37:14,272 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): LogFormat
2024-06-27 14:37:14,272 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): TransferLog
2024-06-27 14:37:14,272 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): PassivePorts
2024-06-27 14:37:14,272 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): AllowStoreRestart
2024-06-27 14:37:14,272 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): AllowForeignAddress
2024-06-27 14:37:14,272 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): TLSEngine
2024-06-27 14:37:14,272 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): TLSLog
2024-06-27 14:37:14,272 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): TLSProtocol
2024-06-27 14:37:14,272 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): TLSRSACertificateFile
2024-06-27 14:37:14,272 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): TLSRSACertificateKeyFile
2024-06-27 14:37:14,272 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): TLSVerifyClient
2024-06-27 14:37:14,272 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): TLSRequired
2024-06-27 14:37:14,272 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): ProxyEngine
2024-06-27 14:37:14,272 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): ProxyTables
2024-06-27 14:37:14,272 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): MasqueradeAddress
2024-06-27 14:37:14,272 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): AllowForeignAddress
2024-06-27 14:37:14,272 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): ProxyDataTransferPolicy
2024-06-27 14:37:14,272 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): ProxyRole
2024-06-27 14:37:14,272 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): ProxyForwardMethod
2024-06-27 14:37:14,272 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): ProxyLog
2024-06-27 14:37:14,272 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): AllowOverwrite
2024-06-27 14:37:14,272 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): ROOT PRIVS at mod_proxy.c:440
2024-06-27 14:37:14,272 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): opening TransferLog '/var/log/proftpd/transfer.log'
2024-06-27 14:37:14,273 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): REVOKE PRIVS at mod_proxy.c:486
2024-06-27 14:37:14,273 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching POST_CMD command 'PASS (hidden)' to mod_lang
2024-06-27 14:37:14,273 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching POST_CMD command 'PASS (hidden)' to mod_cap
2024-06-27 14:37:14,273 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): mod_cap/1.1: uid = 0, euid = 0, gid = 0, egid = 0
2024-06-27 14:37:14,273 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): mod_cap/1.1: capabilities 'cap_chown,cap_setgid,cap_setuid,cap_net_bind_service,cap_audit_write=ep'
2024-06-27 14:37:14,273 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching POST_CMD command 'PASS (hidden)' to mod_tls
2024-06-27 14:37:14,273 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching POST_CMD command 'PASS (hidden)' to mod_delay
2024-06-27 14:37:14,273 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching POST_CMD command 'PASS (hidden)' to mod_log
2024-06-27 14:37:14,273 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching POST_CMD command 'PASS (hidden)' to mod_ls
2024-06-27 14:37:14,273 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching POST_CMD command 'PASS (hidden)' to mod_auth
2024-06-27 14:37:14,273 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): ROOT PRIVS at mod_auth.c:727
2024-06-27 14:37:14,273 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): ROOT PRIVS: ID switching disabled
2024-06-27 14:37:14,273 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): REVOKE PRIVS at mod_auth.c:728
2024-06-27 14:37:14,273 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): RootRevoke in effect, dropped root privs
2024-06-27 14:37:14,273 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching POST_CMD command 'PASS (hidden)' to mod_rlimit
2024-06-27 14:37:14,273 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching POST_CMD command 'PASS (hidden)' to mod_xfer
2024-06-27 14:37:14,273 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching POST_CMD command 'PASS (hidden)' to mod_core
2024-06-27 14:37:14,273 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching LOG_CMD command 'PASS (hidden)' to mod_log
2024-06-27 14:37:14,273 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching LOG_CMD command 'PASS (hidden)' to mod_readme
2024-06-27 14:37:14,273 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching LOG_CMD command 'PASS (hidden)' to mod_delay
2024-06-27 14:37:14,273 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching LOG_CMD command 'PASS (hidden)' to mod_auth
2024-06-27 14:37:14,273 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): USER [email protected]@remote.server.com: Login successful.
2024-06-27 14:37:14,296 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'SYST' to mod_tls
2024-06-27 14:37:14,296 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'SYST' to mod_core
2024-06-27 14:37:14,296 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'SYST' to mod_core
2024-06-27 14:37:14,297 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching CMD command 'SYST' to mod_proxy
2024-06-27 14:37:14,325 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching LOG_CMD command 'SYST' to mod_log
2024-06-27 14:37:14,349 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'FEAT' to mod_tls
2024-06-27 14:37:14,349 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'FEAT' to mod_core
2024-06-27 14:37:14,349 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'FEAT' to mod_core
2024-06-27 14:37:14,349 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching CMD command 'FEAT' to mod_proxy
2024-06-27 14:37:14,376 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching LOG_CMD command 'FEAT' to mod_log
2024-06-27 14:37:14,401 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'OPTS UTF8 ON' to mod_tls
2024-06-27 14:37:14,401 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'OPTS UTF8 ON' to mod_core
2024-06-27 14:37:14,401 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'OPTS UTF8 ON' to mod_core
2024-06-27 14:37:14,401 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching CMD command 'OPTS UTF8 ON' to mod_proxy
2024-06-27 14:37:14,426 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching LOG_CMD command 'OPTS UTF8 ON' to mod_log
2024-06-27 14:37:14,450 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'PBSZ 0' to mod_tls
2024-06-27 14:37:14,450 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'PBSZ 0' to mod_core
2024-06-27 14:37:14,450 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'PBSZ 0' to mod_core
2024-06-27 14:37:14,450 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching CMD command 'PBSZ 0' to mod_proxy
2024-06-27 14:37:14,450 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching CMD command 'PBSZ 0' to mod_tls
2024-06-27 14:37:14,450 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching LOG_CMD command 'PBSZ 0' to mod_log
2024-06-27 14:37:14,474 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'PROT P' to mod_tls
2024-06-27 14:37:14,474 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'PROT P' to mod_core
2024-06-27 14:37:14,474 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'PROT P' to mod_core
2024-06-27 14:37:14,474 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching CMD command 'PROT P' to mod_proxy
2024-06-27 14:37:14,474 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching CMD command 'PROT P' to mod_tls
2024-06-27 14:37:14,474 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching POST_CMD command 'PROT P' to mod_proxy
2024-06-27 14:37:14,474 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching POST_CMD command 'PROT P' to mod_xfer
2024-06-27 14:37:14,474 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching LOG_CMD command 'PROT P' to mod_log
2024-06-27 14:37:14,498 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'OPTS MLST type;perm;size;modify;unix.mode;unix.uid;unix.gid;' to mod_tls
2024-06-27 14:37:14,498 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'OPTS MLST type;perm;size;modify;unix.mode;unix.uid;unix.gid;' to mod_core
2024-06-27 14:37:14,498 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'OPTS MLST type;perm;size;modify;unix.mode;unix.uid;unix.gid;' to mod_core
2024-06-27 14:37:14,498 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching CMD command 'OPTS MLST type;perm;size;modify;unix.mode;unix.uid;unix.gid;' to mod_proxy
2024-06-27 14:37:14,523 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching LOG_CMD command 'OPTS MLST type;perm;size;modify;unix.mode;unix.uid;unix.gid;' to mod_log
2024-06-27 14:37:14,550 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'PWD' to mod_tls
2024-06-27 14:37:14,550 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'PWD' to mod_core
2024-06-27 14:37:14,550 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'PWD' to mod_core
2024-06-27 14:37:14,550 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching CMD command 'PWD' to mod_proxy
2024-06-27 14:37:14,575 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching LOG_CMD command 'PWD' to mod_log
2024-06-27 14:37:14,600 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'TYPE I' to mod_tls
2024-06-27 14:37:14,600 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'TYPE I' to mod_core
2024-06-27 14:37:14,600 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'TYPE I' to mod_core
2024-06-27 14:37:14,600 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching CMD command 'TYPE I' to mod_proxy
2024-06-27 14:37:14,625 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching LOG_CMD command 'TYPE I' to mod_log
2024-06-27 14:37:14,649 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'PASV' to mod_tls
2024-06-27 14:37:14,649 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'PASV' to mod_core
2024-06-27 14:37:14,649 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'PASV' to mod_core
2024-06-27 14:37:14,649 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching CMD command 'PASV' to mod_proxy
2024-06-27 14:37:14,681 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching LOG_CMD_ERR command 'PASV' to mod_log
2024-06-27 14:37:14,705 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'PORT 10,1,2,3,242,181' to mod_tls
2024-06-27 14:37:14,705 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'PORT 10,1,2,3,242,181' to mod_core
2024-06-27 14:37:14,705 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'PORT 10,1,2,3,242,181' to mod_core
2024-06-27 14:37:14,705 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching CMD command 'PORT 10,1,2,3,242,181' to mod_proxy
2024-06-27 14:37:14,741 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): dispatching LOG_CMD_ERR command 'PORT 10,1,2,3,242,181' to mod_log
2024-06-27 14:37:23,419 our.server.internal proftpd[4025946] our.server.internal (10.1.2.3[10.1.2.3]): FTP session closed.
^C2024-06-27 14:38:54,473 our.server.internal proftpd[4025945] our.server.internal: ProFTPD terminating (signal 2)
2024-06-27 14:38:54,874 our.server.internal proftpd[4025945] our.server.internal: ProFTPD killed (signal 2)
2024-06-27 14:38:54,875 our.server.internal proftpd[4025945] our.server.internal: ProFTPD 1.3.8b standalone mode SHUTDOWN

Here are the proxy logs from the same time period:

2024-06-27 14:37:13,878 mod_proxy/0.9.4[4025946]: received banner from backend 1.2.3.4:21: 220 Welcome to Remote Server!
2024-06-27 14:37:13,929 mod_proxy/0.9.4[4025946]: starting TLS negotiation on control connection
2024-06-27 14:37:13,963 mod_proxy/0.9.4[4025946]: [tls.tlsext] TLS server extension "supported versions" (ID 43, 2 bytes)
2024-06-27 14:37:13,963 mod_proxy/0.9.4[4025946]: [tls.tlsext] TLS server extension "(unknown)" (ID 51, 36 bytes)
2024-06-27 14:37:13,966 mod_proxy/0.9.4[4025946]: Server: CN = *.server.com
2024-06-27 14:37:13,966 mod_proxy/0.9.4[4025946]: TLSv1.3 connection created, using cipher TLS_AES_256_GCM_SHA384 (256 bits)
2024-06-27 14:37:14,273 mod_proxy/0.9.4[4025946]: proxy session running as UID 0, GID 0, restricted to '/var/ftp/proxy/empty'
2024-06-27 14:37:14,680 mod_proxy/0.9.4[4025946]: Refused PASV address 5.6.7.8 (address mismatch with 1.2.3.4)
2024-06-27 14:37:14,741 mod_proxy/0.9.4[4025946]: Refused PASV address 5.6.7.8 (address mismatch with 1.2.3.4)

Additionally, here is the -vv output with loaded module information:

2024-06-27 14:56:30,923 our.server.internal proftpd[4027645] our.server.internal: 10.5.6.7:1234 masquerading as 11.22.33.44
ProFTPD Version: 1.3.8b (maint)
  Scoreboard Version: 01040003
  Built: Sun Mar 31 2024 00:00:00 UTC

Loaded modules:
  mod_proxy/0.9.4
  mod_lang/1.1
  mod_ctrls/0.9.5
  mod_cap/1.1
  mod_memcache/0.1
  mod_tls/2.9.2
  mod_auth_pam/1.2
  mod_readme/1.0
  mod_dso/0.5
  mod_facts/0.7
  mod_delay/0.8
  mod_site.c
  mod_log/1.0
  mod_ls.c
  mod_auth.c
  mod_auth_file/1.0
  mod_auth_unix.c
  mod_rlimit/1.0
  mod_xfer.c
  mod_core.c

PAamac avatar Jun 27 '24 19:06 PAamac

Ah, I see what's happening here -- it's the same as Issue #193. Namely, that the "address mismatch" in question is occurring between mod_proxy, and the backend server: mod_proxy resolved the requested backend server to an IP address, and then sent a PASV command to that backend server. In the PASV response from the backend server, the backend server sent an IP address that does not match the IP address to which mod_proxy resolved/connected. Hence the error message.

The AllowForeignAddress directive manages frontend data transfers (i.e. to the connecting client); mod_proxy does not reuse that directive to manage backend data transfers. It could -- but there might be reasons to allow "foreign address" transfers for backend transfers, but not frontend transfers, and using one directive for both situations would make that harder.

I'll see about implementing such ProxyOptions AllowForeignAddress functionality, per Issue #193, as well as determining how to document this better.

Castaglia avatar Jun 29 '24 20:06 Castaglia

I've just merged my patch to master. If you can download and compile the latest mod_proxy, then you should be able to add ProxyOptions AllowForeignAddress to your <IfModule mod_proxy.c> section, and this should hopefully address this behavior.

Castaglia avatar Jun 29 '24 20:06 Castaglia

Thank you for the update. Unfortunately, I'm now running into a different error.

For reference, I have been using the Fedora packaged version of proftpd.

To generate the updated mod_proxy I downloaded the tar.gz of the 1.3.8b source from the main project and git cloned proftpd-mod_proxy. I did a "make" of the main project to create dependency files needed by mod_proxy, then issued a "make" for mod_proxy, which created a "mod_proxy.so" file.

At the default Fedora module path of "/usr/libexec/proftpd/mod_proxy.so" I removed the existing "mod_proxy.so" file and substituted in the newly made version.

I first tried the new option (I wasn't clear if I still needed to add syntax such as "on" to the end of ProxyOptions AllowForeignAddress or not), but while the daemon does start for me, when I try to connect from an FTPS client as before, the client advises that the server closed the connection and the server side logging is as follows:

proxy.log -- 2024-06-30 17:25:44,168 mod_proxy/0.9.5[111485]: error stashing proxy session note: Invalid argument

daemon output -- 2024-06-30 17:25:44,168 our.server.internal proftpd[111485] our.server.internal (10.1.2.3[10.1.2.3]): mod_proxy.c: error initializing session: Operation not permitted

I removed the new ProxyOptions AllowForeignAddress option and also the original AllowForeignAddress config lines from the <IfModule mod_proxy.c> section, but the same error was generated.

I'm not sure if this is related to continued use of the main proftpd bin from Fedora package, or if perhaps the "make" of mod_proxy on the Fedora server wasn't perfect.

Here is the -vv output for reference, showing the updated mod_proxy version number --

ProFTPD Version: 1.3.8b (maint)
  Scoreboard Version: 01040003
  Built: Sun Mar 31 2024 00:00:00 UTC

Loaded modules:
  mod_proxy/0.9.5
  mod_lang/1.1
  mod_ctrls/0.9.5
  mod_cap/1.1
  mod_memcache/0.1
  mod_tls/2.9.2
  mod_auth_pam/1.2
  mod_readme/1.0
  mod_dso/0.5
  mod_facts/0.7
  mod_delay/0.8
  mod_site.c
  mod_log/1.0
  mod_ls.c
  mod_auth.c
  mod_auth_file/1.0
  mod_auth_unix.c
  mod_rlimit/1.0
  mod_xfer.c
  mod_core.c

PAamac avatar Jun 30 '24 22:06 PAamac

Hmm. I'm not sure if building the latest mod_proxy, as a shared module, would work that way. I suspect there might be some compilation differences between the package-installed ProFTPD you're using, and doing a "make" with the ProFTPD 1.3.8b source code.

Do you see any logging in the ProxyLog, and or debug logging at debug level 10, that might provide more details/clues?

Castaglia avatar Jul 04 '24 17:07 Castaglia

Even without the option, the "operation not permitted" shows up. Here are the debug and proxy log values:

Proxy log: 2024-07-04 13:07:20,285 mod_proxy/0.9.5[602799]: error stashing proxy session note: Invalid argument

Debug log:

2024-07-04 13:07:20,280 our.server.internal proftpd[602799] our.server.internal: ROOT PRIVS at main.c:1327
2024-07-04 13:07:20,280 our.server.internal proftpd[602799] our.server.internal: RELINQUISH PRIVS at main.c:1331
2024-07-04 13:07:20,280 our.server.internal proftpd[602799] our.server.internal: no matching vhost found for 10.5.6.7#1234, using 'Our Proxy Server' listening on wildcard address
2024-07-04 13:07:20,285 our.server.internal proftpd[602799] our.server.internal (10.1.2.3[10.1.2.3]): session requested from client in unknown class
2024-07-04 13:07:20,285 our.server.internal proftpd[602799] our.server.internal (10.1.2.3[10.1.2.3]): performing module session initializations
2024-07-04 13:07:20,285 our.server.internal proftpd[602799] our.server.internal (10.1.2.3[10.1.2.3]): ROOT PRIVS at mod_proxy.c:5514
2024-07-04 13:07:20,285 our.server.internal proftpd[602799] our.server.internal (10.1.2.3[10.1.2.3]): RELINQUISH PRIVS at mod_proxy.c:5517
2024-07-04 13:07:20,286 our.server.internal proftpd[602799] our.server.internal (10.1.2.3[10.1.2.3]): mod_proxy.c: error initializing session: Operation not permitted
^C2024-07-04 13:07:26,334 our.server.internal proftpd[602707] our.server.internal: ProFTPD terminating (signal 2)
2024-07-04 13:07:26,735 our.server.internal proftpd[602707] our.server.internal: ProFTPD killed (signal 2)
2024-07-04 13:07:26,735 our.server.internal proftpd[602707] our.server.internal: ROOT PRIVS at signals.c:59
2024-07-04 13:07:26,735 our.server.internal proftpd[602707] our.server.internal: ROOT PRIVS at mod_tls.c:6604
2024-07-04 13:07:26,735 our.server.internal proftpd[602707] our.server.internal: RELINQUISH PRIVS at mod_tls.c:6607
2024-07-04 13:07:26,735 our.server.internal proftpd[602707] our.server.internal: ROOT PRIVS at mod_delay.c:1943
2024-07-04 13:07:26,735 our.server.internal proftpd[602707] our.server.internal: RELINQUISH PRIVS at mod_delay.c:1946
2024-07-04 13:07:26,735 our.server.internal proftpd[602707] our.server.internal: RELINQUISH PRIVS at signals.c:85
2024-07-04 13:07:26,735 our.server.internal proftpd[602707] our.server.internal: ProFTPD 1.3.8b standalone mode SHUTDOWN
2024-07-04 13:07:26,735 our.server.internal proftpd[602707] our.server.internal: ROOT PRIVS at signals.c:92
2024-07-04 13:07:26,735 our.server.internal proftpd[602707] our.server.internal: deleting existing scoreboard '/run/proftpd/proftpd.scoreboard'
2024-07-04 13:07:26,736 our.server.internal proftpd[602707] our.server.internal: RELINQUISH PRIVS at signals.c:94

Does a self-compilation of the updated "mod_proxy" source need to be run with the latest proftpd version (acquired via git clone of project folder), or will it run with self-compiled 1.3.8b?

PAamac avatar Jul 04 '24 18:07 PAamac

Even without the option, the "operation not permitted" shows up. Here are the debug and proxy log values:

Proxy log: 2024-07-04 13:07:20,285 mod_proxy/0.9.5[602799]: error stashing proxy session note: Invalid argument

OK, I think this particular log message might be the main indicator of trouble. Let's see if we can obtain a little more info, using trace logging. Could you add the following to your ProFTPD config on the proxy host, and provide the generated (and verbose!) trace log?

TraceLog /path/to/proftpd-trace.log
Trace proxy:30 \
  proxy.conn:30 \
  proxy.db:30 \
  proxy.dns:30 \
  proxy.forward:30 \
  proxy.session:30 \
  proxy.uri:30

Does a self-compilation of the updated "mod_proxy" source need to be run with the latest proftpd version (acquired via git clone of project folder), or will it run with self-compiled 1.3.8b?

In theory, no, this shouldn't be required. Occasionally I need to make tweaks to the core ProFTPD code base in order to accommodate some of the mod_proxy operations, but I don't recall anything major needing to be done, along those lines, recently.

That said, it's rarely a bad idea to use the latest ProFTPD source code from GitHub; I strive to ensure that the latest in the master branch there always builds and runs properly. If you choose to go that route, I recommend using the "Built With: configure" flags that you'll see from your package-installed ProFTPD via proftpd -V -- that's why I added that to the -V output, i.e. so you can build from source using all the same options as done in a package. (Note that you may find yourself needing to install some library packages as dependencies, too.)

Once we get past these compilation issues, to use the fix for the "Refused PASV address" is to have the following in your config:

<IfModule mod_proxy.c>
  ...
  ProxyOptions AllowForeignAddress
</IfModule>

Just that, no "on" or "off" following the option name.

Castaglia avatar Jul 04 '24 18:07 Castaglia

For building mod_proxy, you may also want/need to install the ProFTPD "devel" package on Fedora 39, e.g. yum install -y proftpd-devel. (I'm currently trying to reproduce this build issue locally, using a Fedora 39 Docker image.) Why? This package installs a lot of the library dependencies for building ProFTPD from source. In addition, it installs some of the necessary header files in /usr/include/proftpd/, including a Make.rules file. This Make.rules file contains variables (paths, locations, flags, etc) that the mod_proxy Makefile will try to reference.

I know that this isn't a great process. I do have feature request tickets, to make it much easier to build multi-file modules (such as mod_proxy) using prxs -- just haven't had time to focus on them yet:

Castaglia avatar Jul 04 '24 19:07 Castaglia

Having built a custom bin for proftpd v1.3.8b for use with the new mod_proxy 0.9.5, here are the log files. The same error appears to be logged. Masquerading to the client is not necessary, so masquerading address was removed.

proftpd debug output:

2024-07-29 18:02:27,873 our.server.internal proftpd[4142997]: using TCP receive buffer size of 131072 bytes
2024-07-29 18:02:27,873 our.server.internal proftpd[4142997]: using TCP send buffer size of 16384 bytes
2024-07-29 18:02:27,874 our.server.internal proftpd[4142997]: using 'en_US.UTF-8' locale based on LANG=en_US.UTF-8 environment variable
2024-07-29 18:02:27,874 our.server.internal proftpd[4142997]: using 'UTF-8' as local charset for UTF-8 conversion
2024-07-29 18:02:27,874 our.server.internal proftpd[4142997]: mod_tls/2.9.2: using OpenSSL 3.1.1 30 May 2023
2024-07-29 18:02:27,874 our.server.internal proftpd[4142997]: mod_memcache/0.1: using libmemcached-1.1.4
2024-07-29 18:02:27,874 our.server.internal proftpd[4142997]: disabling runtime support for IPv6 connections
2024-07-29 18:02:27,874 our.server.internal proftpd[4142997]: ROOT PRIVS at trace.c:377
2024-07-29 18:02:27,875 our.server.internal proftpd[4142997]: RELINQUISH PRIVS at trace.c:380
2024-07-29 18:02:27,875 our.server.internal proftpd[4142997]: mod_dso/0.5: loading 'mod_proxy.c'
2024-07-29 18:02:27,876 our.server.internal proftpd[4142997]: mod_dso/0.5: loaded module 'mod_proxy' (from '/usr/libexec/proftpd/mod_proxy.so', last modified on Thu Jul 04 18:15:49 2024)
2024-07-29 18:02:27,876 our.server.internal proftpd[4142997]: <IfModule>: using 'mod_tls.c' section at line 37
2024-07-29 18:02:27,876 our.server.internal proftpd[4142997]: ROOT PRIVS at mod_tls.c:14976
2024-07-29 18:02:27,879 our.server.internal proftpd[4142997]: RELINQUISH PRIVS at mod_tls.c:14979
2024-07-29 18:02:27,879 our.server.internal proftpd[4142997]: ROOT PRIVS at mod_tls.c:15001
2024-07-29 18:02:27,880 our.server.internal proftpd[4142997]: RELINQUISH PRIVS at mod_tls.c:15045
2024-07-29 18:02:27,880 our.server.internal proftpd[4142997]: <IfModule>: using 'mod_proxy.c' section at line 47
2024-07-29 18:02:27,881 our.server.internal proftpd[4142997] our.server.internal:
2024-07-29 18:02:27,882 our.server.internal proftpd[4142997] our.server.internal: Config for Our FTPS Proxy Server:
2024-07-29 18:02:27,882 our.server.internal proftpd[4142997] our.server.internal: DefaultServer
2024-07-29 18:02:27,882 our.server.internal proftpd[4142997] our.server.internal: DebugLevel
2024-07-29 18:02:27,882 our.server.internal proftpd[4142997] our.server.internal: Port
2024-07-29 18:02:27,882 our.server.internal proftpd[4142997] our.server.internal: LogFormat
2024-07-29 18:02:27,882 our.server.internal proftpd[4142997] our.server.internal: TransferLog
2024-07-29 18:02:27,882 our.server.internal proftpd[4142997] our.server.internal: PassivePorts
2024-07-29 18:02:27,882 our.server.internal proftpd[4142997] our.server.internal: AllowStoreRestart
2024-07-29 18:02:27,882 our.server.internal proftpd[4142997] our.server.internal: TLSEngine
2024-07-29 18:02:27,882 our.server.internal proftpd[4142997] our.server.internal: TLSLog
2024-07-29 18:02:27,882 our.server.internal proftpd[4142997] our.server.internal: TLSProtocol
2024-07-29 18:02:27,882 our.server.internal proftpd[4142997] our.server.internal: TLSRSACertificateFile
2024-07-29 18:02:27,882 our.server.internal proftpd[4142997] our.server.internal: TLSRSACertificateKeyFile
2024-07-29 18:02:27,882 our.server.internal proftpd[4142997] our.server.internal: TLSVerifyClient
2024-07-29 18:02:27,882 our.server.internal proftpd[4142997] our.server.internal: TLSRequired
2024-07-29 18:02:27,882 our.server.internal proftpd[4142997] our.server.internal: ProxyEngine
2024-07-29 18:02:27,882 our.server.internal proftpd[4142997] our.server.internal: ProxyTables
2024-07-29 18:02:27,882 our.server.internal proftpd[4142997] our.server.internal: ProxyOptions
2024-07-29 18:02:27,882 our.server.internal proftpd[4142997] our.server.internal: ProxyRole
2024-07-29 18:02:27,882 our.server.internal proftpd[4142997] our.server.internal: ProxyForwardMethod
2024-07-29 18:02:27,882 our.server.internal proftpd[4142997] our.server.internal: ProxyLog
2024-07-29 18:02:27,882 our.server.internal proftpd[4142997] our.server.internal: ROOT PRIVS at lib/proxy/reverse/db.c:1758
2024-07-29 18:02:27,886 our.server.internal proftpd[4142997] our.server.internal: RELINQUISH PRIVS at lib/proxy/reverse/db.c:1762
2024-07-29 18:02:27,901 our.server.internal proftpd[4142997] our.server.internal: ROOT PRIVS at lib/proxy/ssh/db.c:328
2024-07-29 18:02:27,903 our.server.internal proftpd[4142997] our.server.internal: RELINQUISH PRIVS at lib/proxy/ssh/db.c:332
2024-07-29 18:02:27,908 our.server.internal proftpd[4142997] our.server.internal: ROOT PRIVS at lib/proxy/tls/db.c:393
2024-07-29 18:02:27,910 our.server.internal proftpd[4142997] our.server.internal: RELINQUISH PRIVS at lib/proxy/tls/db.c:397
2024-07-29 18:02:27,913 our.server.internal proftpd[4142997] our.server.internal: mod_lang/1.1: binding to text domain 'proftpd' using locale path '/usr/share/locale'
2024-07-29 18:02:27,913 our.server.internal proftpd[4142997] our.server.internal: mod_lang/1.1: using locale files in '/usr/share/locale'
2024-07-29 18:02:27,917 our.server.internal proftpd[4142997] our.server.internal: mod_lang/1.1: added the following supported languages: zh_CN, zh_TW, bg_BG, es_ES, fr_FR, it_IT, ja_JP, ko_KR, ru_RU
2024-07-29 18:02:27,917 our.server.internal proftpd[4142997] our.server.internal: ROOT PRIVS at mod_ctrls.c:1233
2024-07-29 18:02:27,917 our.server.internal proftpd[4142997] our.server.internal: RELINQUISH PRIVS at mod_ctrls.c:1235
2024-07-29 18:02:27,917 our.server.internal proftpd[4142997] our.server.internal: mod_tls/2.9.2: generating initial TLS session ticket key
2024-07-29 18:02:27,917 our.server.internal proftpd[4142997] our.server.internal: ROOT PRIVS at mod_tls.c:6562
2024-07-29 18:02:27,917 our.server.internal proftpd[4142997] our.server.internal: RELINQUISH PRIVS at mod_tls.c:6565
2024-07-29 18:02:27,917 our.server.internal proftpd[4142997] our.server.internal: mod_tls/2.9.2: scheduling new TLS session ticket key every 3600 secs
2024-07-29 18:02:27,917 our.server.internal proftpd[4142997] our.server.internal: ROOT PRIVS at mod_tls.c:3643
2024-07-29 18:02:27,917 our.server.internal proftpd[4142997] our.server.internal: RELINQUISH PRIVS at mod_tls.c:3646
2024-07-29 18:02:27,919 our.server.internal proftpd[4142997] our.server.internal: ROOT PRIVS at mod_delay.c:583
2024-07-29 18:02:27,919 our.server.internal proftpd[4142997] our.server.internal: RELINQUISH PRIVS at mod_delay.c:586
2024-07-29 18:02:27,920 our.server.internal proftpd[4142997] our.server.internal: ROOT PRIVS at mod_rlimit.c:554
2024-07-29 18:02:27,920 our.server.internal proftpd[4142997] our.server.internal: RELINQUISH PRIVS at mod_rlimit.c:557
2024-07-29 18:02:27,920 our.server.internal proftpd[4142997] our.server.internal: set core resource limits for daemon
2024-07-29 18:02:27,920 our.server.internal proftpd[4142997] our.server.internal: SETUP PRIVS at main.c:2796
2024-07-29 18:02:27,920 our.server.internal proftpd[4142997] our.server.internal: ROOT PRIVS at main.c:1952
2024-07-29 18:02:27,920 our.server.internal proftpd[4142997] our.server.internal: opening scoreboard '/run/proftpd/proftpd.scoreboard'
2024-07-29 18:02:27,920 our.server.internal proftpd[4142997] our.server.internal: RELINQUISH PRIVS at main.c:1979
2024-07-29 18:02:27,920 our.server.internal proftpd[4142997] our.server.internal: ROOT PRIVS at pidfile.c:56
2024-07-29 18:02:27,920 our.server.internal proftpd[4142997] our.server.internal: RELINQUISH PRIVS at pidfile.c:59
2024-07-29 18:02:27,920 our.server.internal proftpd[4142997] our.server.internal: ROOT PRIVS at pidfile.c:67
2024-07-29 18:02:27,920 our.server.internal proftpd[4142997] our.server.internal: RELINQUISH PRIVS at pidfile.c:70
2024-07-29 18:02:27,920 our.server.internal proftpd[4142997] our.server.internal: ProFTPD 1.3.8b (maint) (built Sun Mar 31 2024 00:00:00 UTC) standalone mode STARTUP
2024-07-29 18:02:31,252 our.server.internal proftpd[4142998] our.server.internal: ROOT PRIVS at main.c:1327
2024-07-29 18:02:31,252 our.server.internal proftpd[4142998] our.server.internal: RELINQUISH PRIVS at main.c:1331
2024-07-29 18:02:31,252 our.server.internal proftpd[4142998] our.server.internal: no matching vhost found for 10.5.6.7#4001, using 'Our FTPS Proxy Server' listening on wildcard address
2024-07-29 18:02:31,254 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): session requested from client in unknown class
2024-07-29 18:02:31,254 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): performing module session initializations
2024-07-29 18:02:31,254 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): ROOT PRIVS at mod_proxy.c:5514
2024-07-29 18:02:31,254 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): RELINQUISH PRIVS at mod_proxy.c:5517
2024-07-29 18:02:31,255 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): ROOT PRIVS at lib/proxy/tls.c:4456
2024-07-29 18:02:31,255 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): ROOT PRIVS at lib/proxy/tls/db.c:463
2024-07-29 18:02:31,255 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): RELINQUISH PRIVS at lib/proxy/tls/db.c:467
2024-07-29 18:02:31,255 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): RELINQUISH PRIVS at lib/proxy/tls.c:4459
2024-07-29 18:02:31,255 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): mod_proxy/0.9.5: supporting TLSv1, TLSv1.1, TLSv1.2 protocols
2024-07-29 18:02:31,274 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): mod_cap/1.1: adding CAP_AUDIT_WRITE capability
2024-07-29 18:02:31,274 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): ROOT PRIVS at mod_tls.c:6752
2024-07-29 18:02:31,274 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): RELINQUISH PRIVS at mod_tls.c:6755
2024-07-29 18:02:31,274 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): ROOT PRIVS at mod_tls.c:12749
2024-07-29 18:02:31,274 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): RELINQUISH PRIVS at mod_tls.c:12752
2024-07-29 18:02:31,274 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): ROOT PRIVS at mod_tls.c:3834
2024-07-29 18:02:31,274 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): RELINQUISH PRIVS at mod_tls.c:3864
2024-07-29 18:02:31,293 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): ROOT PRIVS at mod_tls.c:17953
2024-07-29 18:02:31,295 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): RELINQUISH PRIVS at mod_tls.c:18038
2024-07-29 18:02:31,296 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): mod_tls/2.9.2: supporting TLSv1.2 protocol only
2024-07-29 18:02:31,296 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): ROOT PRIVS at mod_delay.c:2111
2024-07-29 18:02:31,296 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): RELINQUISH PRIVS at mod_delay.c:2114
2024-07-29 18:02:31,296 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): ROOT PRIVS at mod_auth.c:215
2024-07-29 18:02:31,296 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): opening scoreboard '/run/proftpd/proftpd.scoreboard'
2024-07-29 18:02:31,296 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): RELINQUISH PRIVS at mod_auth.c:217
2024-07-29 18:02:31,296 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): connected - local  : 10.5.6.7:4001
2024-07-29 18:02:31,296 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): connected - remote : 10.1.2.3:63023
2024-07-29 18:02:31,296 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): FTP session opened.
2024-07-29 18:02:31,321 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'AUTH TLS' to mod_tls
2024-07-29 18:02:31,321 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'AUTH TLS' to mod_core
2024-07-29 18:02:31,321 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'AUTH TLS' to mod_core
2024-07-29 18:02:31,321 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching CMD command 'AUTH TLS' to mod_proxy
2024-07-29 18:02:31,321 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching CMD command 'AUTH TLS' to mod_tls
2024-07-29 18:02:31,372 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching POST_CMD command 'AUTH TLS' to mod_tls
2024-07-29 18:02:31,372 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching LOG_CMD command 'AUTH TLS' to mod_log
2024-07-29 18:02:31,372 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching LOG_CMD command 'AUTH TLS' to mod_tls
2024-07-29 18:02:31,408 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'USER [email protected]@remote.server.com' to mod_tls
2024-07-29 18:02:31,408 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'USER [email protected]@remote.server.com' to mod_core
2024-07-29 18:02:31,408 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'USER [email protected]@remote.server.com' to mod_core
2024-07-29 18:02:31,408 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'USER [email protected]@remote.server.com' to mod_delay
2024-07-29 18:02:31,408 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'USER [email protected]@remote.server.com' to mod_auth
2024-07-29 18:02:31,408 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching CMD command 'USER [email protected]@remote.server.com' to mod_proxy
2024-07-29 18:02:31,622 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching POST_CMD command 'USER [email protected]@remote.server.com' to mod_delay
2024-07-29 18:02:31,752 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching LOG_CMD command 'USER [email protected]@remote.server.com' to mod_log
2024-07-29 18:02:31,752 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching LOG_CMD command 'USER [email protected]@remote.server.com' to mod_delay
2024-07-29 18:02:31,752 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'PASS (hidden)' to mod_tls
2024-07-29 18:02:31,752 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'PASS (hidden)' to mod_core
2024-07-29 18:02:31,752 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'PASS (hidden)' to mod_core
2024-07-29 18:02:31,752 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'PASS (hidden)' to mod_delay
2024-07-29 18:02:31,752 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'PASS (hidden)' to mod_auth
2024-07-29 18:02:31,752 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching CMD command 'PASS (hidden)' to mod_proxy
2024-07-29 18:02:31,879 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]):
2024-07-29 18:02:31,879 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): Config for Our FTPS Proxy Server:
2024-07-29 18:02:31,879 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): DefaultServer
2024-07-29 18:02:31,879 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): DebugLevel
2024-07-29 18:02:31,879 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): Port
2024-07-29 18:02:31,879 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): LogFormat
2024-07-29 18:02:31,879 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): TransferLog
2024-07-29 18:02:31,879 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): PassivePorts
2024-07-29 18:02:31,879 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): AllowStoreRestart
2024-07-29 18:02:31,879 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): TLSEngine
2024-07-29 18:02:31,879 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): TLSLog
2024-07-29 18:02:31,879 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): TLSProtocol
2024-07-29 18:02:31,879 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): TLSRSACertificateFile
2024-07-29 18:02:31,879 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): TLSRSACertificateKeyFile
2024-07-29 18:02:31,879 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): TLSVerifyClient
2024-07-29 18:02:31,879 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): TLSRequired
2024-07-29 18:02:31,879 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): ProxyEngine
2024-07-29 18:02:31,879 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): ProxyTables
2024-07-29 18:02:31,879 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): ProxyOptions
2024-07-29 18:02:31,879 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): ProxyRole
2024-07-29 18:02:31,879 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): ProxyForwardMethod
2024-07-29 18:02:31,879 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): ProxyLog
2024-07-29 18:02:31,879 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): AllowOverwrite
2024-07-29 18:02:31,879 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): ROOT PRIVS at mod_proxy.c:440
2024-07-29 18:02:31,879 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): opening TransferLog '/var/log/proftpd/transfer.log'
2024-07-29 18:02:31,879 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): REVOKE PRIVS at mod_proxy.c:486
2024-07-29 18:02:31,879 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching POST_CMD command 'PASS (hidden)' to mod_lang
2024-07-29 18:02:31,879 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching POST_CMD command 'PASS (hidden)' to mod_cap
2024-07-29 18:02:31,879 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): mod_cap/1.1: uid = 0, euid = 0, gid = 0, egid = 0
2024-07-29 18:02:31,879 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): mod_cap/1.1: capabilities 'cap_chown,cap_setgid,cap_setuid,cap_net_bind_service,cap_audit_write=ep'
2024-07-29 18:02:31,879 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching POST_CMD command 'PASS (hidden)' to mod_tls
2024-07-29 18:02:31,879 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching POST_CMD command 'PASS (hidden)' to mod_delay
2024-07-29 18:02:31,907 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching POST_CMD command 'PASS (hidden)' to mod_log
2024-07-29 18:02:31,907 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching POST_CMD command 'PASS (hidden)' to mod_ls
2024-07-29 18:02:31,907 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching POST_CMD command 'PASS (hidden)' to mod_auth
2024-07-29 18:02:31,907 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): ROOT PRIVS at mod_auth.c:727
2024-07-29 18:02:31,907 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): ROOT PRIVS: ID switching disabled
2024-07-29 18:02:31,907 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): REVOKE PRIVS at mod_auth.c:728
2024-07-29 18:02:31,907 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): RootRevoke in effect, dropped root privs
2024-07-29 18:02:31,907 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching POST_CMD command 'PASS (hidden)' to mod_rlimit
2024-07-29 18:02:31,907 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching POST_CMD command 'PASS (hidden)' to mod_xfer
2024-07-29 18:02:31,907 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching POST_CMD command 'PASS (hidden)' to mod_core
2024-07-29 18:02:31,907 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching LOG_CMD command 'PASS (hidden)' to mod_log
2024-07-29 18:02:31,907 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching LOG_CMD command 'PASS (hidden)' to mod_readme
2024-07-29 18:02:31,907 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching LOG_CMD command 'PASS (hidden)' to mod_delay
2024-07-29 18:02:31,907 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching LOG_CMD command 'PASS (hidden)' to mod_auth
2024-07-29 18:02:31,907 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): USER [email protected]@remote.server.com: Login successful.
2024-07-29 18:02:31,907 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'OPTS UTF8 ON' to mod_tls
2024-07-29 18:02:31,907 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'OPTS UTF8 ON' to mod_core
2024-07-29 18:02:31,907 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'OPTS UTF8 ON' to mod_core
2024-07-29 18:02:31,908 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching CMD command 'OPTS UTF8 ON' to mod_proxy
2024-07-29 18:02:31,931 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching LOG_CMD command 'OPTS UTF8 ON' to mod_log
2024-07-29 18:02:31,955 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'PBSZ 0' to mod_tls
2024-07-29 18:02:31,955 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'PBSZ 0' to mod_core
2024-07-29 18:02:31,955 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'PBSZ 0' to mod_core
2024-07-29 18:02:31,955 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching CMD command 'PBSZ 0' to mod_proxy
2024-07-29 18:02:31,956 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching CMD command 'PBSZ 0' to mod_tls
2024-07-29 18:02:31,956 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching LOG_CMD command 'PBSZ 0' to mod_log
2024-07-29 18:02:31,980 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'PROT P' to mod_tls
2024-07-29 18:02:31,980 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'PROT P' to mod_core
2024-07-29 18:02:31,980 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'PROT P' to mod_core
2024-07-29 18:02:31,980 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching CMD command 'PROT P' to mod_proxy
2024-07-29 18:02:31,980 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching CMD command 'PROT P' to mod_tls
2024-07-29 18:02:31,980 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching POST_CMD command 'PROT P' to mod_proxy
2024-07-29 18:02:31,980 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching POST_CMD command 'PROT P' to mod_xfer
2024-07-29 18:02:31,980 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching LOG_CMD command 'PROT P' to mod_log
2024-07-29 18:02:32,004 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'OPTS MLST type;perm;size;modify;unix.mode;unix.uid;unix.gid;' to mod_tls
2024-07-29 18:02:32,004 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'OPTS MLST type;perm;size;modify;unix.mode;unix.uid;unix.gid;' to mod_core
2024-07-29 18:02:32,004 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'OPTS MLST type;perm;size;modify;unix.mode;unix.uid;unix.gid;' to mod_core
2024-07-29 18:02:32,004 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching CMD command 'OPTS MLST type;perm;size;modify;unix.mode;unix.uid;unix.gid;' to mod_proxy
2024-07-29 18:02:32,028 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching LOG_CMD command 'OPTS MLST type;perm;size;modify;unix.mode;unix.uid;unix.gid;' to mod_log
2024-07-29 18:02:32,069 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'PWD' to mod_tls
2024-07-29 18:02:32,069 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'PWD' to mod_core
2024-07-29 18:02:32,069 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'PWD' to mod_core
2024-07-29 18:02:32,069 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching CMD command 'PWD' to mod_proxy
2024-07-29 18:02:32,093 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching LOG_CMD command 'PWD' to mod_log
2024-07-29 18:02:32,117 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'TYPE I' to mod_tls
2024-07-29 18:02:32,117 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'TYPE I' to mod_core
2024-07-29 18:02:32,117 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'TYPE I' to mod_core
2024-07-29 18:02:32,117 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching CMD command 'TYPE I' to mod_proxy
2024-07-29 18:02:32,140 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching LOG_CMD command 'TYPE I' to mod_log
2024-07-29 18:02:32,165 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'PASV' to mod_tls
2024-07-29 18:02:32,165 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'PASV' to mod_core
2024-07-29 18:02:32,165 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'PASV' to mod_core
2024-07-29 18:02:32,165 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching CMD command 'PASV' to mod_proxy
2024-07-29 18:02:32,189 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching LOG_CMD_ERR command 'PASV' to mod_log
2024-07-29 18:02:32,213 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'PORT 10,1,2,3,246,48' to mod_tls
2024-07-29 18:02:32,213 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'PORT 10,1,2,3,246,48' to mod_core
2024-07-29 18:02:32,213 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'PORT 10,1,2,3,246,48' to mod_core
2024-07-29 18:02:32,213 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): dispatching CMD command 'PORT 10,1,2,3,246,48' to mod_proxy
2024-07-29 18:02:37,321 our.server.internal proftpd[4142997] our.server.internal: ROOT PRIVS at mod_ctrls.c:747
2024-07-29 18:02:37,321 our.server.internal proftpd[4142997] our.server.internal: RELINQUISH PRIVS at mod_ctrls.c:753
^C2024-07-29 18:02:43,454 our.server.internal proftpd[4142997] our.server.internal: ROOT PRIVS at signals.c:152
2024-07-29 18:02:43,454 our.server.internal proftpd[4142997] our.server.internal: RELINQUISH PRIVS at signals.c:154
2024-07-29 18:02:43,454 our.server.internal proftpd[4142997] our.server.internal: ProFTPD killed (signal 2)
2024-07-29 18:02:43,454 our.server.internal proftpd[4142997] our.server.internal: ROOT PRIVS at signals.c:59
2024-07-29 18:02:43,455 our.server.internal proftpd[4142997] our.server.internal: ROOT PRIVS at mod_tls.c:6604
2024-07-29 18:02:43,455 our.server.internal proftpd[4142997] our.server.internal: RELINQUISH PRIVS at mod_tls.c:6607
2024-07-29 18:02:43,455 our.server.internal proftpd[4142997] our.server.internal: ROOT PRIVS at mod_delay.c:1943
2024-07-29 18:02:43,455 our.server.internal proftpd[4142997] our.server.internal: RELINQUISH PRIVS at mod_delay.c:1946
2024-07-29 18:02:43,456 our.server.internal proftpd[4142997] our.server.internal: RELINQUISH PRIVS at signals.c:85
2024-07-29 18:02:43,456 our.server.internal proftpd[4142997] our.server.internal: ProFTPD 1.3.8b standalone mode SHUTDOWN
2024-07-29 18:02:43,456 our.server.internal proftpd[4142997] our.server.internal: ROOT PRIVS at signals.c:92
2024-07-29 18:02:43,456 our.server.internal proftpd[4142997] our.server.internal: deleting existing scoreboard '/run/proftpd/proftpd.scoreboard'
2024-07-29 18:02:43,456 our.server.internal proftpd[4142997] our.server.internal: RELINQUISH PRIVS at signals.c:94
2024-07-29 18:02:43,457 our.server.internal proftpd[4142998] our.server.internal (10.1.2.3[10.1.2.3]): FTP session closed.

proftpdv -vv output:

  Scoreboard Version: 01040003
  Built: Sun Mar 31 2024 00:00:00 UTC

Loaded modules:
  mod_proxy/0.9.5
  mod_lang/1.1
  mod_ctrls/0.9.5
  mod_cap/1.1
  mod_memcache/0.1
  mod_tls/2.9.2
  mod_auth_pam/1.2
  mod_readme/1.0
  mod_dso/0.5
  mod_facts/0.7
  mod_delay/0.8
  mod_site.c
  mod_log/1.0
  mod_ls.c
  mod_auth.c
  mod_auth_file/1.0
  mod_auth_unix.c
  mod_rlimit/1.0
  mod_xfer.c
  mod_core.c

proxy.log content:

2024-07-29 18:02:31,504 mod_proxy/0.9.5[4142998]: starting TLS negotiation on control connection
2024-07-29 18:02:31,529 mod_proxy/0.9.5[4142998]: [tls.tlsext] TLS server extension "supported versions" (ID 43, 2 bytes)
2024-07-29 18:02:31,529 mod_proxy/0.9.5[4142998]: [tls.tlsext] TLS server extension "(unknown)" (ID 51, 36 bytes)
2024-07-29 18:02:31,529 mod_proxy/0.9.5[4142998]: [tls.tlsext] TLS server extension "PSK" (ID 41, 2 bytes)
2024-07-29 18:02:31,529 mod_proxy/0.9.5[4142998]: Server: CN = *.remoteserver.com
2024-07-29 18:02:31,529 mod_proxy/0.9.5[4142998]: TLSv1.3 connection created, using cipher TLS_AES_256_GCM_SHA384 (256 bits)
2024-07-29 18:02:31,879 mod_proxy/0.9.5[4142998]: proxy session running as UID 0, GID 0, restricted to '/var/ftp/proxy/empty'
2024-07-29 18:02:32,189 mod_proxy/0.9.5[4142998]: Refused PASV address 5.6.7.8 (address mismatch with 1.2.3.4)

proftpd-trace.log content:

2024-07-29 18:02:27,882 [4142997] <proxy.db:19>: attempting to open proxy_reverse tables at path '/var/ftp/proxy/proxy-reverse.db'
2024-07-29 18:02:27,882 [4142997] <proxy.db:10>: schema 'proxy_reverse': executing statement 'PRAGMA temp_store = MEMORY;'
2024-07-29 18:02:27,882 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': executing stmt 'PRAGMA temp_store = MEMORY;'
2024-07-29 18:02:27,882 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': stmt 'PRAGMA temp_store = MEMORY;' ran for 0 nanosecs
2024-07-29 18:02:27,882 [4142997] <proxy.db:13>: successfully executed 'PRAGMA temp_store = MEMORY;'
2024-07-29 18:02:27,882 [4142997] <proxy.db:10>: schema 'proxy_reverse': executing statement 'PRAGMA journal_mode = MEMORY;'
2024-07-29 18:02:27,882 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': returning result row for stmt '(null)'
2024-07-29 18:02:27,882 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': returning result row for stmt '(null)'
2024-07-29 18:02:27,882 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': returning result row for stmt '(null)'
2024-07-29 18:02:27,882 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': returning result row for stmt '(null)'
2024-07-29 18:02:27,882 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': returning result row for stmt '(null)'
2024-07-29 18:02:27,882 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': returning result row for stmt '(null)'
2024-07-29 18:02:27,882 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': returning result row for stmt '(null)'
2024-07-29 18:02:27,882 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': returning result row for stmt '(null)'
2024-07-29 18:02:27,882 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': returning result row for stmt '(null)'
2024-07-29 18:02:27,882 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': returning result row for stmt '(null)'
2024-07-29 18:02:27,882 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': returning result row for stmt '(null)'
2024-07-29 18:02:27,882 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': returning result row for stmt '(null)'
2024-07-29 18:02:27,882 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': returning result row for stmt '(null)'
2024-07-29 18:02:27,882 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': returning result row for stmt '(null)'
2024-07-29 18:02:27,882 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': returning result row for stmt '(null)'
2024-07-29 18:02:27,882 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': returning result row for stmt '(null)'
2024-07-29 18:02:27,882 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': executing stmt 'PRAGMA journal_mode = MEMORY;'
2024-07-29 18:02:27,882 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': returning result row for stmt 'PRAGMA journal_mode = MEMORY;'
2024-07-29 18:02:27,882 [4142997] <proxy.db:9>: results for 'PRAGMA journal_mode = MEMORY;':
2024-07-29 18:02:27,882 [4142997] <proxy.db:9>: col #1 [journal_mode]: memory
2024-07-29 18:02:27,882 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': stmt 'PRAGMA journal_mode = MEMORY;' ran for 0 nanosecs
2024-07-29 18:02:27,882 [4142997] <proxy.db:13>: successfully executed 'PRAGMA journal_mode = MEMORY;'
2024-07-29 18:02:27,882 [4142997] <proxy.db:9>: opened SQLite table '/var/ftp/proxy/proxy-reverse.db'
2024-07-29 18:02:27,882 [4142997] <proxy.db:19>: ensuring that schema at path '/var/ftp/proxy/proxy-reverse.db' has at least schema version 6
2024-07-29 18:02:27,882 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': executing stmt 'SELECT version FROM schema_version WHERE schema = ?;'
2024-07-29 18:02:27,883 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': returning result row for stmt 'SELECT version FROM schema_version WHERE schema = 'proxy_reverse';'
2024-07-29 18:02:27,883 [4142997] <proxy.db:12>: schema 'proxy_reverse': executing prepared statement 'SELECT version FROM schema_version WHERE schema = ?;' returned row (columns: 1)
2024-07-29 18:02:27,883 [4142997] <proxy.db:17>: column version [0]: 6
2024-07-29 18:02:27,883 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': stmt 'SELECT version FROM schema_version WHERE schema = 'proxy_reverse';' ran for 1000000 nanosecs
2024-07-29 18:02:27,883 [4142997] <proxy.db:13>: successfully executed 'SELECT version FROM schema_version WHERE schema = ?;'
2024-07-29 18:02:27,883 [4142997] <proxy.db:11>: schema version 6 >= desired version 6 for path '/var/ftp/proxy/proxy-reverse.db'
2024-07-29 18:02:27,883 [4142997] <proxy.db:10>: schema 'proxy_reverse': executing statement 'PRAGMA integrity_check;'
2024-07-29 18:02:27,883 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': executing stmt 'PRAGMA integrity_check;'
2024-07-29 18:02:27,883 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': returning result row for stmt 'PRAGMA integrity_check;'
2024-07-29 18:02:27,883 [4142997] <proxy.db:9>: results for 'PRAGMA integrity_check;':
2024-07-29 18:02:27,883 [4142997] <proxy.db:9>: col #1 [integrity_check]: ok
2024-07-29 18:02:27,883 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': stmt 'PRAGMA integrity_check;' ran for 0 nanosecs
2024-07-29 18:02:27,883 [4142997] <proxy.db:13>: successfully executed 'PRAGMA integrity_check;'
2024-07-29 18:02:27,883 [4142997] <proxy.db:10>: schema 'proxy_reverse': executing statement 'VACUUM;'
2024-07-29 18:02:27,883 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': executing stmt 'VACUUM;'
2024-07-29 18:02:27,886 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': stmt 'VACUUM;' ran for 3000000 nanosecs
2024-07-29 18:02:27,886 [4142997] <proxy.db:13>: successfully executed 'VACUUM;'
2024-07-29 18:02:27,886 [4142997] <proxy.db:10>: schema 'proxy_reverse': executing statement 'CREATE TABLE IF NOT EXISTS proxy_vhosts (vhost_id INTEGER NOT NULL PRIMARY KEY, vhost_name TEXT NOT NULL);'
2024-07-29 18:02:27,886 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': returning result row for stmt '(null)'
2024-07-29 18:02:27,886 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': returning result row for stmt '(null)'
2024-07-29 18:02:27,886 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': returning result row for stmt '(null)'
2024-07-29 18:02:27,886 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': returning result row for stmt '(null)'
2024-07-29 18:02:27,886 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': returning result row for stmt '(null)'
2024-07-29 18:02:27,886 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': returning result row for stmt '(null)'
2024-07-29 18:02:27,886 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': returning result row for stmt '(null)'
2024-07-29 18:02:27,886 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': returning result row for stmt '(null)'
2024-07-29 18:02:27,886 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': returning result row for stmt '(null)'
2024-07-29 18:02:27,886 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': returning result row for stmt '(null)'
2024-07-29 18:02:27,886 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': returning result row for stmt '(null)'
2024-07-29 18:02:27,886 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': returning result row for stmt '(null)'
2024-07-29 18:02:27,886 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': returning result row for stmt '(null)'
2024-07-29 18:02:27,886 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': returning result row for stmt '(null)'
2024-07-29 18:02:27,886 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': returning result row for stmt '(null)'
2024-07-29 18:02:27,886 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': returning result row for stmt '(null)'
2024-07-29 18:02:27,886 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': executing stmt 'CREATE TABLE IF NOT EXISTS proxy_vhosts (vhost_id INTEGER NOT NULL PRIMARY KEY, vhost_name TEXT NOT NULL);'
2024-07-29 18:02:27,886 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': stmt 'CREATE TABLE IF NOT EXISTS proxy_vhosts (vhost_id INTEGER NOT NULL PRIMARY KEY, vhost_name TEXT NOT NULL);' ran for 0 nanosecs
2024-07-29 18:02:27,886 [4142997] <proxy.db:13>: successfully executed 'CREATE TABLE IF NOT EXISTS proxy_vhosts (vhost_id INTEGER NOT NULL PRIMARY KEY, vhost_name TEXT NOT NULL);'
2024-07-29 18:02:27,886 [4142997] <proxy.db:10>: schema 'proxy_reverse': executing statement 'CREATE TABLE IF NOT EXISTS proxy_vhost_backends (vhost_id INTEGER NOT NULL, backend_id INTEGER NOT NULL, backend_uri TEXT NOT NULL, conn_count INTEGER NOT NULL, connect_ms INTEGER);'
2024-07-29 18:02:27,886 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': executing stmt 'CREATE TABLE IF NOT EXISTS proxy_vhost_backends (vhost_id INTEGER NOT NULL, backend_id INTEGER NOT NULL, backend_uri TEXT NOT NULL, conn_count INTEGER NOT NULL, connect_ms INTEGER);'
2024-07-29 18:02:27,886 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': stmt 'CREATE TABLE IF NOT EXISTS proxy_vhost_backends (vhost_id INTEGER NOT NULL, backend_id INTEGER NOT NULL, backend_uri TEXT NOT NULL, conn_count INTEGER NOT NULL, connect_ms INTEGER);' ran for 0 nanosecs
2024-07-29 18:02:27,886 [4142997] <proxy.db:13>: successfully executed 'CREATE TABLE IF NOT EXISTS proxy_vhost_backends (vhost_id INTEGER NOT NULL, backend_id INTEGER NOT NULL, backend_uri TEXT NOT NULL, conn_count INTEGER NOT NULL, connect_ms INTEGER);'
2024-07-29 18:02:27,886 [4142997] <proxy.db:10>: schema 'proxy_reverse': executing statement 'CREATE INDEX IF NOT EXISTS proxy_vhost_backends_vhost_id_idx ON proxy_vhost_backends (vhost_id);'
2024-07-29 18:02:27,886 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': executing stmt 'CREATE INDEX IF NOT EXISTS proxy_vhost_backends_vhost_id_idx ON proxy_vhost_backends (vhost_id);'
2024-07-29 18:02:27,886 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': stmt 'CREATE INDEX IF NOT EXISTS proxy_vhost_backends_vhost_id_idx ON proxy_vhost_backends (vhost_id);' ran for 0 nanosecs
2024-07-29 18:02:27,886 [4142997] <proxy.db:13>: successfully executed 'CREATE INDEX IF NOT EXISTS proxy_vhost_backends_vhost_id_idx ON proxy_vhost_backends (vhost_id);'
2024-07-29 18:02:27,886 [4142997] <proxy.db:10>: schema 'proxy_reverse': executing statement 'CREATE TABLE IF NOT EXISTS proxy_vhost_reverse_roundrobin (vhost_id INTEGER NOT NULL, current_backend_id INTEGER NOT NULL, FOREIGN KEY (vhost_id) REFERENCES proxy_vhosts (vhost_id), FOREIGN KEY (current_backend_id) REFERENCES proxy_vhost_backends (backend_id));'
2024-07-29 18:02:27,886 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': executing stmt 'CREATE TABLE IF NOT EXISTS proxy_vhost_reverse_roundrobin (vhost_id INTEGER NOT NULL, current_backend_id INTEGER NOT NULL, FOREIGN KEY (vhost_id) REFERENCES proxy_vhosts (vhost_id), FOREIGN KEY (current_backend_id) REFERENCES proxy_vhost_backends (backend_id));'
2024-07-29 18:02:27,886 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': stmt 'CREATE TABLE IF NOT EXISTS proxy_vhost_reverse_roundrobin (vhost_id INTEGER NOT NULL, current_backend_id INTEGER NOT NULL, FOREIGN KEY (vhost_id) REFERENCES proxy_vhosts (vhost_id), FOREIGN KEY (current_backend_id) REFERENCES proxy_vhost_backends (backend_id));' ran for 0 nanosecs
2024-07-29 18:02:27,886 [4142997] <proxy.db:13>: successfully executed 'CREATE TABLE IF NOT EXISTS proxy_vhost_reverse_roundrobin (vhost_id INTEGER NOT NULL, current_backend_id INTEGER NOT NULL, FOREIGN KEY (vhost_id) REFERENCES proxy_vhosts (vhost_id), FOREIGN KEY (current_backend_id) REFERENCES proxy_vhost_backends (backend_id));'
2024-07-29 18:02:27,886 [4142997] <proxy.db:10>: schema 'proxy_reverse': executing statement 'CREATE TABLE IF NOT EXISTS proxy_vhost_reverse_shuffle (vhost_id INTEGER NOT NULL, avail_backend_id INTEGER NOT NULL, FOREIGN KEY (vhost_id) REFERENCES proxy_vhosts (vhost_id), FOREIGN KEY (avail_backend_id) REFERENCES proxy_vhost_backends (backend_id));'
2024-07-29 18:02:27,886 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': executing stmt 'CREATE TABLE IF NOT EXISTS proxy_vhost_reverse_shuffle (vhost_id INTEGER NOT NULL, avail_backend_id INTEGER NOT NULL, FOREIGN KEY (vhost_id) REFERENCES proxy_vhosts (vhost_id), FOREIGN KEY (avail_backend_id) REFERENCES proxy_vhost_backends (backend_id));'
2024-07-29 18:02:27,886 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': stmt 'CREATE TABLE IF NOT EXISTS proxy_vhost_reverse_shuffle (vhost_id INTEGER NOT NULL, avail_backend_id INTEGER NOT NULL, FOREIGN KEY (vhost_id) REFERENCES proxy_vhosts (vhost_id), FOREIGN KEY (avail_backend_id) REFERENCES proxy_vhost_backends (backend_id));' ran for 0 nanosecs
2024-07-29 18:02:27,886 [4142997] <proxy.db:13>: successfully executed 'CREATE TABLE IF NOT EXISTS proxy_vhost_reverse_shuffle (vhost_id INTEGER NOT NULL, avail_backend_id INTEGER NOT NULL, FOREIGN KEY (vhost_id) REFERENCES proxy_vhosts (vhost_id), FOREIGN KEY (avail_backend_id) REFERENCES proxy_vhost_backends (backend_id));'
2024-07-29 18:02:27,886 [4142997] <proxy.db:10>: schema 'proxy_reverse': executing statement 'CREATE TABLE IF NOT EXISTS proxy_vhost_reverse_per_user (vhost_id INTEGER NOT NULL, user_name TEXT NOT NULL, backend_uri TEXT, FOREIGN KEY (vhost_id) REFERENCES proxy_vhosts (vhost_id), UNIQUE (vhost_id, user_name));'
2024-07-29 18:02:27,886 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': executing stmt 'CREATE TABLE IF NOT EXISTS proxy_vhost_reverse_per_user (vhost_id INTEGER NOT NULL, user_name TEXT NOT NULL, backend_uri TEXT, FOREIGN KEY (vhost_id) REFERENCES proxy_vhosts (vhost_id), UNIQUE (vhost_id, user_name));'
2024-07-29 18:02:27,886 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': stmt 'CREATE TABLE IF NOT EXISTS proxy_vhost_reverse_per_user (vhost_id INTEGER NOT NULL, user_name TEXT NOT NULL, backend_uri TEXT, FOREIGN KEY (vhost_id) REFERENCES proxy_vhosts (vhost_id), UNIQUE (vhost_id, user_name));' ran for 0 nanosecs
2024-07-29 18:02:27,886 [4142997] <proxy.db:13>: successfully executed 'CREATE TABLE IF NOT EXISTS proxy_vhost_reverse_per_user (vhost_id INTEGER NOT NULL, user_name TEXT NOT NULL, backend_uri TEXT, FOREIGN KEY (vhost_id) REFERENCES proxy_vhosts (vhost_id), UNIQUE (vhost_id, user_name));'
2024-07-29 18:02:27,886 [4142997] <proxy.db:10>: schema 'proxy_reverse': executing statement 'CREATE INDEX IF NOT EXISTS proxy_vhost_reverse_per_user_name_idx ON proxy_vhost_reverse_per_user (user_name);'
2024-07-29 18:02:27,886 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': executing stmt 'CREATE INDEX IF NOT EXISTS proxy_vhost_reverse_per_user_name_idx ON proxy_vhost_reverse_per_user (user_name);'
2024-07-29 18:02:27,886 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': stmt 'CREATE INDEX IF NOT EXISTS proxy_vhost_reverse_per_user_name_idx ON proxy_vhost_reverse_per_user (user_name);' ran for 0 nanosecs
2024-07-29 18:02:27,886 [4142997] <proxy.db:13>: successfully executed 'CREATE INDEX IF NOT EXISTS proxy_vhost_reverse_per_user_name_idx ON proxy_vhost_reverse_per_user (user_name);'
2024-07-29 18:02:27,886 [4142997] <proxy.db:10>: schema 'proxy_reverse': executing statement 'CREATE TABLE IF NOT EXISTS proxy_vhost_reverse_per_group (vhost_id INTEGER NOT NULL, group_name TEXT NOT NULL, backend_uri TEXT, FOREIGN KEY (vhost_id) REFERENCES proxy_vhosts (vhost_id), UNIQUE (vhost_id, group_name));'
2024-07-29 18:02:27,886 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': executing stmt 'CREATE TABLE IF NOT EXISTS proxy_vhost_reverse_per_group (vhost_id INTEGER NOT NULL, group_name TEXT NOT NULL, backend_uri TEXT, FOREIGN KEY (vhost_id) REFERENCES proxy_vhosts (vhost_id), UNIQUE (vhost_id, group_name));'
2024-07-29 18:02:27,886 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': stmt 'CREATE TABLE IF NOT EXISTS proxy_vhost_reverse_per_group (vhost_id INTEGER NOT NULL, group_name TEXT NOT NULL, backend_uri TEXT, FOREIGN KEY (vhost_id) REFERENCES proxy_vhosts (vhost_id), UNIQUE (vhost_id, group_name));' ran for 0 nanosecs
2024-07-29 18:02:27,886 [4142997] <proxy.db:13>: successfully executed 'CREATE TABLE IF NOT EXISTS proxy_vhost_reverse_per_group (vhost_id INTEGER NOT NULL, group_name TEXT NOT NULL, backend_uri TEXT, FOREIGN KEY (vhost_id) REFERENCES proxy_vhosts (vhost_id), UNIQUE (vhost_id, group_name));'
2024-07-29 18:02:27,886 [4142997] <proxy.db:10>: schema 'proxy_reverse': executing statement 'CREATE INDEX IF NOT EXISTS proxy_vhost_reverse_per_group_name_idx ON proxy_vhost_reverse_per_group (group_name);'
2024-07-29 18:02:27,886 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': executing stmt 'CREATE INDEX IF NOT EXISTS proxy_vhost_reverse_per_group_name_idx ON proxy_vhost_reverse_per_group (group_name);'
2024-07-29 18:02:27,886 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': stmt 'CREATE INDEX IF NOT EXISTS proxy_vhost_reverse_per_group_name_idx ON proxy_vhost_reverse_per_group (group_name);' ran for 0 nanosecs
2024-07-29 18:02:27,886 [4142997] <proxy.db:13>: successfully executed 'CREATE INDEX IF NOT EXISTS proxy_vhost_reverse_per_group_name_idx ON proxy_vhost_reverse_per_group (group_name);'
2024-07-29 18:02:27,886 [4142997] <proxy.db:10>: schema 'proxy_reverse': executing statement 'CREATE TABLE IF NOT EXISTS proxy_vhost_reverse_per_host (vhost_id INTEGER NOT NULL, ip_addr TEXT NOT NULL, backend_uri TEXT, FOREIGN KEY (vhost_id) REFERENCES proxy_vhosts (vhost_id), UNIQUE (vhost_id, ip_addr));'
2024-07-29 18:02:27,886 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': executing stmt 'CREATE TABLE IF NOT EXISTS proxy_vhost_reverse_per_host (vhost_id INTEGER NOT NULL, ip_addr TEXT NOT NULL, backend_uri TEXT, FOREIGN KEY (vhost_id) REFERENCES proxy_vhosts (vhost_id), UNIQUE (vhost_id, ip_addr));'
2024-07-29 18:02:27,886 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': stmt 'CREATE TABLE IF NOT EXISTS proxy_vhost_reverse_per_host (vhost_id INTEGER NOT NULL, ip_addr TEXT NOT NULL, backend_uri TEXT, FOREIGN KEY (vhost_id) REFERENCES proxy_vhosts (vhost_id), UNIQUE (vhost_id, ip_addr));' ran for 0 nanosecs
2024-07-29 18:02:27,886 [4142997] <proxy.db:13>: successfully executed 'CREATE TABLE IF NOT EXISTS proxy_vhost_reverse_per_host (vhost_id INTEGER NOT NULL, ip_addr TEXT NOT NULL, backend_uri TEXT, FOREIGN KEY (vhost_id) REFERENCES proxy_vhosts (vhost_id), UNIQUE (vhost_id, ip_addr));'
2024-07-29 18:02:27,886 [4142997] <proxy.db:10>: schema 'proxy_reverse': executing statement 'CREATE INDEX IF NOT EXISTS proxy_vhost_reverse_per_host_ipaddr_idx ON proxy_vhost_reverse_per_host (ip_addr);'
2024-07-29 18:02:27,886 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': executing stmt 'CREATE INDEX IF NOT EXISTS proxy_vhost_reverse_per_host_ipaddr_idx ON proxy_vhost_reverse_per_host (ip_addr);'
2024-07-29 18:02:27,886 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': stmt 'CREATE INDEX IF NOT EXISTS proxy_vhost_reverse_per_host_ipaddr_idx ON proxy_vhost_reverse_per_host (ip_addr);' ran for 0 nanosecs
2024-07-29 18:02:27,886 [4142997] <proxy.db:13>: successfully executed 'CREATE INDEX IF NOT EXISTS proxy_vhost_reverse_per_host_ipaddr_idx ON proxy_vhost_reverse_per_host (ip_addr);'
2024-07-29 18:02:27,886 [4142997] <proxy.db:10>: schema 'proxy_reverse': executing statement 'DELETE FROM proxy_vhosts;'
2024-07-29 18:02:27,886 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': executing stmt 'DELETE FROM proxy_vhosts;'
2024-07-29 18:02:27,887 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': stmt 'DELETE FROM proxy_vhosts;' ran for 1000000 nanosecs
2024-07-29 18:02:27,887 [4142997] <proxy.db:13>: successfully executed 'DELETE FROM proxy_vhosts;'
2024-07-29 18:02:27,887 [4142997] <proxy.db:10>: schema 'proxy_reverse': executing statement 'DELETE FROM proxy_vhost_backends;'
2024-07-29 18:02:27,887 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': executing stmt 'DELETE FROM proxy_vhost_backends;'
2024-07-29 18:02:27,889 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': stmt 'DELETE FROM proxy_vhost_backends;' ran for 2000000 nanosecs
2024-07-29 18:02:27,889 [4142997] <proxy.db:13>: successfully executed 'DELETE FROM proxy_vhost_backends;'
2024-07-29 18:02:27,889 [4142997] <proxy.db:10>: schema 'proxy_reverse': executing statement 'DELETE FROM proxy_vhost_reverse_roundrobin;'
2024-07-29 18:02:27,889 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': executing stmt 'DELETE FROM proxy_vhost_reverse_roundrobin;'
2024-07-29 18:02:27,890 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': stmt 'DELETE FROM proxy_vhost_reverse_roundrobin;' ran for 1000000 nanosecs
2024-07-29 18:02:27,890 [4142997] <proxy.db:13>: successfully executed 'DELETE FROM proxy_vhost_reverse_roundrobin;'
2024-07-29 18:02:27,890 [4142997] <proxy.db:10>: schema 'proxy_reverse': executing statement 'DELETE FROM proxy_vhost_reverse_shuffle;'
2024-07-29 18:02:27,890 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': executing stmt 'DELETE FROM proxy_vhost_reverse_shuffle;'
2024-07-29 18:02:27,891 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': stmt 'DELETE FROM proxy_vhost_reverse_shuffle;' ran for 1000000 nanosecs
2024-07-29 18:02:27,891 [4142997] <proxy.db:13>: successfully executed 'DELETE FROM proxy_vhost_reverse_shuffle;'
2024-07-29 18:02:27,891 [4142997] <proxy.db:10>: schema 'proxy_reverse': executing statement 'DELETE FROM proxy_vhost_reverse_per_user;'
2024-07-29 18:02:27,891 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': executing stmt 'DELETE FROM proxy_vhost_reverse_per_user;'
2024-07-29 18:02:27,892 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': stmt 'DELETE FROM proxy_vhost_reverse_per_user;' ran for 1000000 nanosecs
2024-07-29 18:02:27,892 [4142997] <proxy.db:13>: successfully executed 'DELETE FROM proxy_vhost_reverse_per_user;'
2024-07-29 18:02:27,892 [4142997] <proxy.db:10>: schema 'proxy_reverse': executing statement 'DELETE FROM proxy_vhost_reverse_per_group;'
2024-07-29 18:02:27,892 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': executing stmt 'DELETE FROM proxy_vhost_reverse_per_group;'
2024-07-29 18:02:27,894 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': stmt 'DELETE FROM proxy_vhost_reverse_per_group;' ran for 2000000 nanosecs
2024-07-29 18:02:27,894 [4142997] <proxy.db:13>: successfully executed 'DELETE FROM proxy_vhost_reverse_per_group;'
2024-07-29 18:02:27,894 [4142997] <proxy.db:10>: schema 'proxy_reverse': executing statement 'DELETE FROM proxy_vhost_reverse_per_host;'
2024-07-29 18:02:27,894 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': executing stmt 'DELETE FROM proxy_vhost_reverse_per_host;'
2024-07-29 18:02:27,895 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': stmt 'DELETE FROM proxy_vhost_reverse_per_host;' ran for 1000000 nanosecs
2024-07-29 18:02:27,895 [4142997] <proxy.db:13>: successfully executed 'DELETE FROM proxy_vhost_reverse_per_host;'
2024-07-29 18:02:27,895 [4142997] <proxy.db:10>: schema 'proxy_reverse': executing statement 'REINDEX proxy_vhost_backends_vhost_id_idx;'
2024-07-29 18:02:27,895 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': executing stmt 'REINDEX proxy_vhost_backends_vhost_id_idx;'
2024-07-29 18:02:27,896 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': stmt 'REINDEX proxy_vhost_backends_vhost_id_idx;' ran for 1000000 nanosecs
2024-07-29 18:02:27,896 [4142997] <proxy.db:13>: successfully executed 'REINDEX proxy_vhost_backends_vhost_id_idx;'
2024-07-29 18:02:27,896 [4142997] <proxy.db:10>: schema 'proxy_reverse': executing statement 'REINDEX proxy_vhost_reverse_per_user_name_idx;'
2024-07-29 18:02:27,896 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': executing stmt 'REINDEX proxy_vhost_reverse_per_user_name_idx;'
2024-07-29 18:02:27,897 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': stmt 'REINDEX proxy_vhost_reverse_per_user_name_idx;' ran for 1000000 nanosecs
2024-07-29 18:02:27,897 [4142997] <proxy.db:13>: successfully executed 'REINDEX proxy_vhost_reverse_per_user_name_idx;'
2024-07-29 18:02:27,897 [4142997] <proxy.db:10>: schema 'proxy_reverse': executing statement 'REINDEX proxy_vhost_reverse_per_group_name_idx;'
2024-07-29 18:02:27,897 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': executing stmt 'REINDEX proxy_vhost_reverse_per_group_name_idx;'
2024-07-29 18:02:27,898 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': stmt 'REINDEX proxy_vhost_reverse_per_group_name_idx;' ran for 1000000 nanosecs
2024-07-29 18:02:27,898 [4142997] <proxy.db:13>: successfully executed 'REINDEX proxy_vhost_reverse_per_group_name_idx;'
2024-07-29 18:02:27,898 [4142997] <proxy.db:10>: schema 'proxy_reverse': executing statement 'REINDEX proxy_vhost_reverse_per_host_ipaddr_idx;'
2024-07-29 18:02:27,898 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': executing stmt 'REINDEX proxy_vhost_reverse_per_host_ipaddr_idx;'
2024-07-29 18:02:27,899 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': stmt 'REINDEX proxy_vhost_reverse_per_host_ipaddr_idx;' ran for 1000000 nanosecs
2024-07-29 18:02:27,899 [4142997] <proxy.db:13>: successfully executed 'REINDEX proxy_vhost_reverse_per_host_ipaddr_idx;'
2024-07-29 18:02:27,899 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': executing stmt 'INSERT INTO proxy_vhosts (vhost_id, vhost_name) VALUES (?, ?);'
2024-07-29 18:02:27,900 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': stmt 'INSERT INTO proxy_vhosts (vhost_id, vhost_name) VALUES (1, 'Our FTPS Proxy Server');' ran for 1000000 nanosecs
2024-07-29 18:02:27,900 [4142997] <proxy.db:13>: successfully executed 'INSERT INTO proxy_vhosts (vhost_id, vhost_name) VALUES (?, ?);'
2024-07-29 18:02:27,900 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': executing stmt 'INSERT INTO proxy_vhost_reverse_roundrobin (vhost_id, current_backend_id) VALUES (?, ?);'
2024-07-29 18:02:27,901 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': stmt 'INSERT INTO proxy_vhost_reverse_roundrobin (vhost_id, current_backend_id) VALUES (1, 0);' ran for 1000000 nanosecs
2024-07-29 18:02:27,901 [4142997] <proxy.db:13>: successfully executed 'INSERT INTO proxy_vhost_reverse_roundrobin (vhost_id, current_backend_id) VALUES (?, ?);'
2024-07-29 18:02:27,901 [4142997] <proxy.db:19>: closing 'proxy_reverse' database handle
2024-07-29 18:02:27,901 [4142997] <proxy.db:18>: finished prepared statement 'INSERT INTO proxy_vhost_reverse_roundrobin (vhost_id, current_backend_id) VALUES (?, ?);'
2024-07-29 18:02:27,901 [4142997] <proxy.db:18>: finished prepared statement 'INSERT INTO proxy_vhosts (vhost_id, vhost_name) VALUES (?, ?);'
2024-07-29 18:02:27,901 [4142997] <proxy.db:18>: finished prepared statement 'SELECT version FROM schema_version WHERE schema = ?;'
2024-07-29 18:02:27,901 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': closing database connection to /var/ftp/proxy/proxy-reverse.db
2024-07-29 18:02:27,901 [4142997] <proxy.db:18>: closed SQLite database
2024-07-29 18:02:27,901 [4142997] <proxy.db:19>: attempting to open proxy_ssh tables at path '/var/ftp/proxy/proxy-ssh.db'
2024-07-29 18:02:27,901 [4142997] <proxy.db:10>: schema 'proxy_ssh': executing statement 'PRAGMA temp_store = MEMORY;'
2024-07-29 18:02:27,901 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_ssh': executing stmt 'PRAGMA temp_store = MEMORY;'
2024-07-29 18:02:27,901 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_ssh': stmt 'PRAGMA temp_store = MEMORY;' ran for 0 nanosecs
2024-07-29 18:02:27,901 [4142997] <proxy.db:13>: successfully executed 'PRAGMA temp_store = MEMORY;'
2024-07-29 18:02:27,901 [4142997] <proxy.db:10>: schema 'proxy_ssh': executing statement 'PRAGMA journal_mode = MEMORY;'
2024-07-29 18:02:27,901 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_ssh': returning result row for stmt '(null)'
2024-07-29 18:02:27,901 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_ssh': returning result row for stmt '(null)'
2024-07-29 18:02:27,901 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_ssh': returning result row for stmt '(null)'
2024-07-29 18:02:27,901 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_ssh': returning result row for stmt '(null)'
2024-07-29 18:02:27,902 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_ssh': returning result row for stmt '(null)'
2024-07-29 18:02:27,902 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_ssh': executing stmt 'PRAGMA journal_mode = MEMORY;'
2024-07-29 18:02:27,902 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_ssh': returning result row for stmt 'PRAGMA journal_mode = MEMORY;'
2024-07-29 18:02:27,902 [4142997] <proxy.db:9>: results for 'PRAGMA journal_mode = MEMORY;':
2024-07-29 18:02:27,902 [4142997] <proxy.db:9>: col #1 [journal_mode]: memory
2024-07-29 18:02:27,902 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_ssh': stmt 'PRAGMA journal_mode = MEMORY;' ran for 0 nanosecs
2024-07-29 18:02:27,902 [4142997] <proxy.db:13>: successfully executed 'PRAGMA journal_mode = MEMORY;'
2024-07-29 18:02:27,902 [4142997] <proxy.db:9>: opened SQLite table '/var/ftp/proxy/proxy-ssh.db'
2024-07-29 18:02:27,902 [4142997] <proxy.db:19>: ensuring that schema at path '/var/ftp/proxy/proxy-ssh.db' has at least schema version 1
2024-07-29 18:02:27,902 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_ssh': executing stmt 'SELECT version FROM schema_version WHERE schema = ?;'
2024-07-29 18:02:27,902 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_ssh': returning result row for stmt 'SELECT version FROM schema_version WHERE schema = 'proxy_ssh';'
2024-07-29 18:02:27,902 [4142997] <proxy.db:12>: schema 'proxy_ssh': executing prepared statement 'SELECT version FROM schema_version WHERE schema = ?;' returned row (columns: 1)
2024-07-29 18:02:27,902 [4142997] <proxy.db:17>: column version [0]: 1
2024-07-29 18:02:27,902 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_ssh': stmt 'SELECT version FROM schema_version WHERE schema = 'proxy_ssh';' ran for 0 nanosecs
2024-07-29 18:02:27,902 [4142997] <proxy.db:13>: successfully executed 'SELECT version FROM schema_version WHERE schema = ?;'
2024-07-29 18:02:27,902 [4142997] <proxy.db:11>: schema version 1 >= desired version 1 for path '/var/ftp/proxy/proxy-ssh.db'
2024-07-29 18:02:27,902 [4142997] <proxy.db:10>: schema 'proxy_ssh': executing statement 'PRAGMA integrity_check;'
2024-07-29 18:02:27,902 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_ssh': executing stmt 'PRAGMA integrity_check;'
2024-07-29 18:02:27,902 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_ssh': returning result row for stmt 'PRAGMA integrity_check;'
2024-07-29 18:02:27,902 [4142997] <proxy.db:9>: results for 'PRAGMA integrity_check;':
2024-07-29 18:02:27,902 [4142997] <proxy.db:9>: col #1 [integrity_check]: ok
2024-07-29 18:02:27,902 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_ssh': stmt 'PRAGMA integrity_check;' ran for 0 nanosecs
2024-07-29 18:02:27,902 [4142997] <proxy.db:13>: successfully executed 'PRAGMA integrity_check;'
2024-07-29 18:02:27,902 [4142997] <proxy.db:10>: schema 'proxy_ssh': executing statement 'VACUUM;'
2024-07-29 18:02:27,902 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_ssh': executing stmt 'VACUUM;'
2024-07-29 18:02:27,903 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_ssh': stmt 'VACUUM;' ran for 1000000 nanosecs
2024-07-29 18:02:27,903 [4142997] <proxy.db:13>: successfully executed 'VACUUM;'
2024-07-29 18:02:27,903 [4142997] <proxy.db:10>: schema 'proxy_ssh': executing statement 'CREATE TABLE IF NOT EXISTS proxy_ssh_vhosts (vhost_id INTEGER NOT NULL PRIMARY KEY, vhost_name TEXT NOT NULL);'
2024-07-29 18:02:27,903 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_ssh': returning result row for stmt '(null)'
2024-07-29 18:02:27,903 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_ssh': returning result row for stmt '(null)'
2024-07-29 18:02:27,903 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_ssh': returning result row for stmt '(null)'
2024-07-29 18:02:27,903 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_ssh': returning result row for stmt '(null)'
2024-07-29 18:02:27,903 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_ssh': returning result row for stmt '(null)'
2024-07-29 18:02:27,903 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_ssh': executing stmt 'CREATE TABLE IF NOT EXISTS proxy_ssh_vhosts (vhost_id INTEGER NOT NULL PRIMARY KEY, vhost_name TEXT NOT NULL);'
2024-07-29 18:02:27,903 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_ssh': stmt 'CREATE TABLE IF NOT EXISTS proxy_ssh_vhosts (vhost_id INTEGER NOT NULL PRIMARY KEY, vhost_name TEXT NOT NULL);' ran for 0 nanosecs
2024-07-29 18:02:27,903 [4142997] <proxy.db:13>: successfully executed 'CREATE TABLE IF NOT EXISTS proxy_ssh_vhosts (vhost_id INTEGER NOT NULL PRIMARY KEY, vhost_name TEXT NOT NULL);'
2024-07-29 18:02:27,903 [4142997] <proxy.db:10>: schema 'proxy_ssh': executing statement 'CREATE TABLE IF NOT EXISTS proxy_ssh_hostkeys (backend_uri STRING NOT NULL PRIMARY KEY, vhost_id INTEGER NOT NULL, algo TEXT NOT NULL, hostkey BLOB NOT NULL, FOREIGN KEY (vhost_id) REFERENCES proxy_ssh_hosts (vhost_id));'
2024-07-29 18:02:27,903 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_ssh': executing stmt 'CREATE TABLE IF NOT EXISTS proxy_ssh_hostkeys (backend_uri STRING NOT NULL PRIMARY KEY, vhost_id INTEGER NOT NULL, algo TEXT NOT NULL, hostkey BLOB NOT NULL, FOREIGN KEY (vhost_id) REFERENCES proxy_ssh_hosts (vhost_id));'
2024-07-29 18:02:27,903 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_ssh': stmt 'CREATE TABLE IF NOT EXISTS proxy_ssh_hostkeys (backend_uri STRING NOT NULL PRIMARY KEY, vhost_id INTEGER NOT NULL, algo TEXT NOT NULL, hostkey BLOB NOT NULL, FOREIGN KEY (vhost_id) REFERENCES proxy_ssh_hosts (vhost_id));' ran for 0 nanosecs
2024-07-29 18:02:27,903 [4142997] <proxy.db:13>: successfully executed 'CREATE TABLE IF NOT EXISTS proxy_ssh_hostkeys (backend_uri STRING NOT NULL PRIMARY KEY, vhost_id INTEGER NOT NULL, algo TEXT NOT NULL, hostkey BLOB NOT NULL, FOREIGN KEY (vhost_id) REFERENCES proxy_ssh_hosts (vhost_id));'
2024-07-29 18:02:27,903 [4142997] <proxy.db:10>: schema 'proxy_ssh': executing statement 'DELETE FROM proxy_ssh_vhosts;'
2024-07-29 18:02:27,903 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_ssh': executing stmt 'DELETE FROM proxy_ssh_vhosts;'
2024-07-29 18:02:27,905 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_ssh': stmt 'DELETE FROM proxy_ssh_vhosts;' ran for 2000000 nanosecs
2024-07-29 18:02:27,905 [4142997] <proxy.db:13>: successfully executed 'DELETE FROM proxy_ssh_vhosts;'
2024-07-29 18:02:27,905 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_ssh': executing stmt 'INSERT INTO proxy_ssh_vhosts (vhost_id, vhost_name) VALUES (?, ?);'
2024-07-29 18:02:27,908 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_ssh': stmt 'INSERT INTO proxy_ssh_vhosts (vhost_id, vhost_name) VALUES (1, 'Our FTPS Proxy Server');' ran for 3000000 nanosecs
2024-07-29 18:02:27,908 [4142997] <proxy.db:13>: successfully executed 'INSERT INTO proxy_ssh_vhosts (vhost_id, vhost_name) VALUES (?, ?);'
2024-07-29 18:02:27,908 [4142997] <proxy.db:19>: closing 'proxy_ssh' database handle
2024-07-29 18:02:27,908 [4142997] <proxy.db:18>: finished prepared statement 'INSERT INTO proxy_ssh_vhosts (vhost_id, vhost_name) VALUES (?, ?);'
2024-07-29 18:02:27,908 [4142997] <proxy.db:18>: finished prepared statement 'SELECT version FROM schema_version WHERE schema = ?;'
2024-07-29 18:02:27,908 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_ssh': closing database connection to /var/ftp/proxy/proxy-ssh.db
2024-07-29 18:02:27,908 [4142997] <proxy.db:18>: closed SQLite database
2024-07-29 18:02:27,908 [4142997] <proxy.db:19>: attempting to open proxy_tls tables at path '/var/ftp/proxy/proxy-tls.db'
2024-07-29 18:02:27,909 [4142997] <proxy.db:10>: schema 'proxy_tls': executing statement 'PRAGMA temp_store = MEMORY;'
2024-07-29 18:02:27,909 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_tls': executing stmt 'PRAGMA temp_store = MEMORY;'
2024-07-29 18:02:27,909 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_tls': stmt 'PRAGMA temp_store = MEMORY;' ran for 0 nanosecs
2024-07-29 18:02:27,909 [4142997] <proxy.db:13>: successfully executed 'PRAGMA temp_store = MEMORY;'
2024-07-29 18:02:27,909 [4142997] <proxy.db:10>: schema 'proxy_tls': executing statement 'PRAGMA journal_mode = MEMORY;'
2024-07-29 18:02:27,909 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_tls': returning result row for stmt '(null)'
2024-07-29 18:02:27,909 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_tls': returning result row for stmt '(null)'
2024-07-29 18:02:27,909 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_tls': returning result row for stmt '(null)'
2024-07-29 18:02:27,909 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_tls': returning result row for stmt '(null)'
2024-07-29 18:02:27,909 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_tls': returning result row for stmt '(null)'
2024-07-29 18:02:27,909 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_tls': executing stmt 'PRAGMA journal_mode = MEMORY;'
2024-07-29 18:02:27,909 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_tls': returning result row for stmt 'PRAGMA journal_mode = MEMORY;'
2024-07-29 18:02:27,909 [4142997] <proxy.db:9>: results for 'PRAGMA journal_mode = MEMORY;':
2024-07-29 18:02:27,909 [4142997] <proxy.db:9>: col #1 [journal_mode]: memory
2024-07-29 18:02:27,909 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_tls': stmt 'PRAGMA journal_mode = MEMORY;' ran for 0 nanosecs
2024-07-29 18:02:27,909 [4142997] <proxy.db:13>: successfully executed 'PRAGMA journal_mode = MEMORY;'
2024-07-29 18:02:27,909 [4142997] <proxy.db:9>: opened SQLite table '/var/ftp/proxy/proxy-tls.db'
2024-07-29 18:02:27,909 [4142997] <proxy.db:19>: ensuring that schema at path '/var/ftp/proxy/proxy-tls.db' has at least schema version 3
2024-07-29 18:02:27,909 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_tls': executing stmt 'SELECT version FROM schema_version WHERE schema = ?;'
2024-07-29 18:02:27,909 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_tls': returning result row for stmt 'SELECT version FROM schema_version WHERE schema = 'proxy_tls';'
2024-07-29 18:02:27,909 [4142997] <proxy.db:12>: schema 'proxy_tls': executing prepared statement 'SELECT version FROM schema_version WHERE schema = ?;' returned row (columns: 1)
2024-07-29 18:02:27,909 [4142997] <proxy.db:17>: column version [0]: 3
2024-07-29 18:02:27,909 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_tls': stmt 'SELECT version FROM schema_version WHERE schema = 'proxy_tls';' ran for 0 nanosecs
2024-07-29 18:02:27,909 [4142997] <proxy.db:13>: successfully executed 'SELECT version FROM schema_version WHERE schema = ?;'
2024-07-29 18:02:27,909 [4142997] <proxy.db:11>: schema version 3 >= desired version 3 for path '/var/ftp/proxy/proxy-tls.db'
2024-07-29 18:02:27,909 [4142997] <proxy.db:10>: schema 'proxy_tls': executing statement 'PRAGMA integrity_check;'
2024-07-29 18:02:27,909 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_tls': executing stmt 'PRAGMA integrity_check;'
2024-07-29 18:02:27,909 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_tls': returning result row for stmt 'PRAGMA integrity_check;'
2024-07-29 18:02:27,909 [4142997] <proxy.db:9>: results for 'PRAGMA integrity_check;':
2024-07-29 18:02:27,909 [4142997] <proxy.db:9>: col #1 [integrity_check]: ok
2024-07-29 18:02:27,909 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_tls': stmt 'PRAGMA integrity_check;' ran for 0 nanosecs
2024-07-29 18:02:27,909 [4142997] <proxy.db:13>: successfully executed 'PRAGMA integrity_check;'
2024-07-29 18:02:27,909 [4142997] <proxy.db:10>: schema 'proxy_tls': executing statement 'VACUUM;'
2024-07-29 18:02:27,909 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_tls': executing stmt 'VACUUM;'
2024-07-29 18:02:27,910 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_tls': stmt 'VACUUM;' ran for 1000000 nanosecs
2024-07-29 18:02:27,910 [4142997] <proxy.db:13>: successfully executed 'VACUUM;'
2024-07-29 18:02:27,910 [4142997] <proxy.db:10>: schema 'proxy_tls': executing statement 'CREATE TABLE IF NOT EXISTS proxy_tls_vhosts (vhost_id INTEGER NOT NULL PRIMARY KEY, vhost_name TEXT NOT NULL);'
2024-07-29 18:02:27,910 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_tls': returning result row for stmt '(null)'
2024-07-29 18:02:27,910 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_tls': returning result row for stmt '(null)'
2024-07-29 18:02:27,910 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_tls': returning result row for stmt '(null)'
2024-07-29 18:02:27,910 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_tls': returning result row for stmt '(null)'
2024-07-29 18:02:27,910 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_tls': returning result row for stmt '(null)'
2024-07-29 18:02:27,910 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_tls': executing stmt 'CREATE TABLE IF NOT EXISTS proxy_tls_vhosts (vhost_id INTEGER NOT NULL PRIMARY KEY, vhost_name TEXT NOT NULL);'
2024-07-29 18:02:27,911 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_tls': stmt 'CREATE TABLE IF NOT EXISTS proxy_tls_vhosts (vhost_id INTEGER NOT NULL PRIMARY KEY, vhost_name TEXT NOT NULL);' ran for 0 nanosecs
2024-07-29 18:02:27,911 [4142997] <proxy.db:13>: successfully executed 'CREATE TABLE IF NOT EXISTS proxy_tls_vhosts (vhost_id INTEGER NOT NULL PRIMARY KEY, vhost_name TEXT NOT NULL);'
2024-07-29 18:02:27,911 [4142997] <proxy.db:10>: schema 'proxy_tls': executing statement 'CREATE TABLE IF NOT EXISTS proxy_tls_sessions (backend_uri STRING NOT NULL PRIMARY KEY, vhost_id INTEGER NOT NULL, session TEXT NOT NULL, FOREIGN KEY (vhost_id) REFERENCES proxy_tls_hosts (vhost_id));'
2024-07-29 18:02:27,911 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_tls': executing stmt 'CREATE TABLE IF NOT EXISTS proxy_tls_sessions (backend_uri STRING NOT NULL PRIMARY KEY, vhost_id INTEGER NOT NULL, session TEXT NOT NULL, FOREIGN KEY (vhost_id) REFERENCES proxy_tls_hosts (vhost_id));'
2024-07-29 18:02:27,911 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_tls': stmt 'CREATE TABLE IF NOT EXISTS proxy_tls_sessions (backend_uri STRING NOT NULL PRIMARY KEY, vhost_id INTEGER NOT NULL, session TEXT NOT NULL, FOREIGN KEY (vhost_id) REFERENCES proxy_tls_hosts (vhost_id));' ran for 0 nanosecs
2024-07-29 18:02:27,911 [4142997] <proxy.db:13>: successfully executed 'CREATE TABLE IF NOT EXISTS proxy_tls_sessions (backend_uri STRING NOT NULL PRIMARY KEY, vhost_id INTEGER NOT NULL, session TEXT NOT NULL, FOREIGN KEY (vhost_id) REFERENCES proxy_tls_hosts (vhost_id));'
2024-07-29 18:02:27,911 [4142997] <proxy.db:10>: schema 'proxy_tls': executing statement 'DELETE FROM proxy_tls_vhosts;'
2024-07-29 18:02:27,911 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_tls': executing stmt 'DELETE FROM proxy_tls_vhosts;'
2024-07-29 18:02:27,912 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_tls': stmt 'DELETE FROM proxy_tls_vhosts;' ran for 1000000 nanosecs
2024-07-29 18:02:27,912 [4142997] <proxy.db:13>: successfully executed 'DELETE FROM proxy_tls_vhosts;'
2024-07-29 18:02:27,912 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_tls': executing stmt 'INSERT INTO proxy_tls_vhosts (vhost_id, vhost_name) VALUES (?, ?);'
2024-07-29 18:02:27,913 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_tls': stmt 'INSERT INTO proxy_tls_vhosts (vhost_id, vhost_name) VALUES (1, 'Our FTPS Proxy Server');' ran for 1000000 nanosecs
2024-07-29 18:02:27,913 [4142997] <proxy.db:13>: successfully executed 'INSERT INTO proxy_tls_vhosts (vhost_id, vhost_name) VALUES (?, ?);'
2024-07-29 18:02:27,913 [4142997] <proxy.db:19>: closing 'proxy_tls' database handle
2024-07-29 18:02:27,913 [4142997] <proxy.db:18>: finished prepared statement 'INSERT INTO proxy_tls_vhosts (vhost_id, vhost_name) VALUES (?, ?);'
2024-07-29 18:02:27,913 [4142997] <proxy.db:18>: finished prepared statement 'SELECT version FROM schema_version WHERE schema = ?;'
2024-07-29 18:02:27,913 [4142997] <proxy.db:17>: (sqlite3): schema 'proxy_tls': closing database connection to /var/ftp/proxy/proxy-tls.db
2024-07-29 18:02:27,913 [4142997] <proxy.db:18>: closed SQLite database
2024-07-29 18:02:31,255 [4142998] <proxy.db:19>: attempting to open proxy_tls tables at path '/var/ftp/proxy/proxy-tls.db'
2024-07-29 18:02:31,255 [4142998] <proxy.db:10>: schema 'proxy_tls': executing statement 'PRAGMA temp_store = MEMORY;'
2024-07-29 18:02:31,255 [4142998] <proxy.db:17>: (sqlite3): schema 'proxy_tls': executing stmt 'PRAGMA temp_store = MEMORY;'
2024-07-29 18:02:31,255 [4142998] <proxy.db:17>: (sqlite3): schema 'proxy_tls': stmt 'PRAGMA temp_store = MEMORY;' ran for 0 nanosecs
2024-07-29 18:02:31,255 [4142998] <proxy.db:13>: successfully executed 'PRAGMA temp_store = MEMORY;'
2024-07-29 18:02:31,255 [4142998] <proxy.db:10>: schema 'proxy_tls': executing statement 'PRAGMA journal_mode = MEMORY;'
2024-07-29 18:02:31,255 [4142998] <proxy.db:17>: (sqlite3): schema 'proxy_tls': returning result row for stmt '(null)'
2024-07-29 18:02:31,255 [4142998] <proxy.db:17>: (sqlite3): schema 'proxy_tls': returning result row for stmt '(null)'
2024-07-29 18:02:31,255 [4142998] <proxy.db:17>: (sqlite3): schema 'proxy_tls': returning result row for stmt '(null)'
2024-07-29 18:02:31,255 [4142998] <proxy.db:17>: (sqlite3): schema 'proxy_tls': returning result row for stmt '(null)'
2024-07-29 18:02:31,255 [4142998] <proxy.db:17>: (sqlite3): schema 'proxy_tls': returning result row for stmt '(null)'
2024-07-29 18:02:31,255 [4142998] <proxy.db:17>: (sqlite3): schema 'proxy_tls': executing stmt 'PRAGMA journal_mode = MEMORY;'
2024-07-29 18:02:31,255 [4142998] <proxy.db:17>: (sqlite3): schema 'proxy_tls': returning result row for stmt 'PRAGMA journal_mode = MEMORY;'
2024-07-29 18:02:31,255 [4142998] <proxy.db:9>: results for 'PRAGMA journal_mode = MEMORY;':
2024-07-29 18:02:31,255 [4142998] <proxy.db:9>: col #1 [journal_mode]: memory
2024-07-29 18:02:31,255 [4142998] <proxy.db:17>: (sqlite3): schema 'proxy_tls': stmt 'PRAGMA journal_mode = MEMORY;' ran for 0 nanosecs
2024-07-29 18:02:31,255 [4142998] <proxy.db:13>: successfully executed 'PRAGMA journal_mode = MEMORY;'
2024-07-29 18:02:31,255 [4142998] <proxy.db:9>: opened SQLite table '/var/ftp/proxy/proxy-tls.db'
2024-07-29 18:02:31,274 [4142998] <proxy:9>: removed PRE_CMD APPE mod_xfer handlers
2024-07-29 18:02:31,274 [4142998] <proxy:9>: removed PRE_CMD RETR mod_xfer handlers
2024-07-29 18:02:31,274 [4142998] <proxy:9>: removed PRE_CMD STOR mod_xfer handlers
2024-07-29 18:02:31,274 [4142998] <proxy:9>: removed PRE_CMD STOU mod_xfer handlers
2024-07-29 18:02:31,321 [4142998] <proxy:15>: found group 'NONE' for command 'AUTH'
2024-07-29 18:02:31,408 [4142998] <proxy.uri:17>: parsed host 'ftp.remoteserver.com' out of URI 'ftp://ftp.remoteserver.com:21'
2024-07-29 18:02:31,409 [4142998] <proxy.conn:12>: connecting to backend address 1.2.3.4#21 from 10.5.6.7#33989
2024-07-29 18:02:31,457 [4142998] <proxy.conn:5>: successfully connected to 1.2.3.4#21 from 10.5.6.7#33989
2024-07-29 18:02:31,504 [4142998] <proxy.db:17>: (sqlite3): schema 'proxy_tls': executing stmt 'SELECT session FROM proxy_tls_sessions WHERE vhost_id = ? AND backend_uri = ?;'
2024-07-29 18:02:31,504 [4142998] <proxy.db:17>: (sqlite3): schema 'proxy_tls': returning result row for stmt 'SELECT session FROM proxy_tls_sessions WHERE vhost_id = 1 AND backend_uri = 'ftp://ftp.remoteserver.com:21';'
2024-07-29 18:02:31,504 [4142998] <proxy.db:12>: schema 'proxy_tls': executing prepared statement 'SELECT session FROM proxy_tls_sessions WHERE vhost_id = ? AND backend_uri = ?;' returned row (columns: 1)
2024-07-29 18:02:31,504 [4142998] <proxy.db:17>: column session [0]: -----BEGIN SSL SESSION PARAMETERS-----
MIIHkg[etc]==
-----END SSL SESSION PARAMETERS-----
2024-07-29 18:02:31,504 [4142998] <proxy.db:17>: (sqlite3): schema 'proxy_tls': stmt 'SELECT session FROM proxy_tls_sessions WHERE vhost_id = 1 AND backend_uri = 'ftp://ftp.remoteserver.com:21';' ran for 0 nanosecs
2024-07-29 18:02:31,504 [4142998] <proxy.db:13>: successfully executed 'SELECT session FROM proxy_tls_sessions WHERE vhost_id = ? AND backend_uri = ?;'
2024-07-29 18:02:31,879 [4142998] <proxy:9>: chrooted session to '/var/ftp/proxy/empty'
2024-07-29 18:02:31,908 [4142998] <proxy:15>: found group 'NONE' for command 'OPTS'
2024-07-29 18:02:31,955 [4142998] <proxy:15>: found group 'NONE' for command 'PBSZ'
2024-07-29 18:02:31,980 [4142998] <proxy:15>: found group 'NONE' for command 'PROT'
2024-07-29 18:02:32,004 [4142998] <proxy:15>: found group 'NONE' for command 'OPTS'
2024-07-29 18:02:32,117 [4142998] <proxy:15>: found group 'NONE' for command 'TYPE'
2024-07-29 18:02:43,455 [4142998] <proxy.db:17>: (sqlite3): schema 'proxy_tls': executing stmt 'SELECT COUNT(*) FROM proxy_tls_sessions;'
2024-07-29 18:02:43,455 [4142998] <proxy.db:17>: (sqlite3): schema 'proxy_tls': returning result row for stmt 'SELECT COUNT(*) FROM proxy_tls_sessions;'
2024-07-29 18:02:43,455 [4142998] <proxy.db:12>: schema 'proxy_tls': executing prepared statement 'SELECT COUNT(*) FROM proxy_tls_sessions;' returned row (columns: 1)
2024-07-29 18:02:43,455 [4142998] <proxy.db:17>: column COUNT(*) [0]: 2
2024-07-29 18:02:43,455 [4142998] <proxy.db:17>: (sqlite3): schema 'proxy_tls': stmt 'SELECT COUNT(*) FROM proxy_tls_sessions;' ran for 0 nanosecs
2024-07-29 18:02:43,455 [4142998] <proxy.db:13>: successfully executed 'SELECT COUNT(*) FROM proxy_tls_sessions;'
2024-07-29 18:02:43,455 [4142998] <proxy.db:17>: (sqlite3): schema 'proxy_tls': executing stmt 'INSERT OR REPLACE INTO proxy_tls_sessions (vhost_id, backend_uri, session) VALUES (?, ?, ?);'
2024-07-29 18:02:43,456 [4142998] <proxy.db:17>: (sqlite3): schema 'proxy_tls': stmt '(full SQL statement redacted)' ran for 1000000 nanosecs
2024-07-29 18:02:43,456 [4142998] <proxy.db:13>: successfully executed 'INSERT OR REPLACE INTO proxy_tls_sessions (vhost_id, backend_uri, session) VALUES (?, ?, ?);'
2024-07-29 18:03:32,309 [4143104] <proxy.db:9>: using SQLite 3.42.0
2024-07-29 18:03:32,314 [4143104] <proxy.db:19>: attempting to open proxy_reverse tables at path '/var/ftp/proxy/proxy-reverse.db'
2024-07-29 18:03:32,314 [4143104] <proxy.db:10>: schema 'proxy_reverse': executing statement 'PRAGMA temp_store = MEMORY;'
2024-07-29 18:03:32,314 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': executing stmt 'PRAGMA temp_store = MEMORY;'
2024-07-29 18:03:32,314 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': stmt 'PRAGMA temp_store = MEMORY;' ran for 0 nanosecs
2024-07-29 18:03:32,314 [4143104] <proxy.db:13>: successfully executed 'PRAGMA temp_store = MEMORY;'
2024-07-29 18:03:32,314 [4143104] <proxy.db:10>: schema 'proxy_reverse': executing statement 'PRAGMA journal_mode = MEMORY;'
2024-07-29 18:03:32,314 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': returning result row for stmt '(null)'
2024-07-29 18:03:32,314 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': returning result row for stmt '(null)'
2024-07-29 18:03:32,314 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': returning result row for stmt '(null)'
2024-07-29 18:03:32,314 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': returning result row for stmt '(null)'
2024-07-29 18:03:32,314 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': returning result row for stmt '(null)'
2024-07-29 18:03:32,314 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': returning result row for stmt '(null)'
2024-07-29 18:03:32,314 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': returning result row for stmt '(null)'
2024-07-29 18:03:32,314 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': returning result row for stmt '(null)'
2024-07-29 18:03:32,314 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': returning result row for stmt '(null)'
2024-07-29 18:03:32,314 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': returning result row for stmt '(null)'
2024-07-29 18:03:32,314 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': returning result row for stmt '(null)'
2024-07-29 18:03:32,314 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': returning result row for stmt '(null)'
2024-07-29 18:03:32,314 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': returning result row for stmt '(null)'
2024-07-29 18:03:32,314 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': returning result row for stmt '(null)'
2024-07-29 18:03:32,314 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': returning result row for stmt '(null)'
2024-07-29 18:03:32,314 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': returning result row for stmt '(null)'
2024-07-29 18:03:32,314 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': executing stmt 'PRAGMA journal_mode = MEMORY;'
2024-07-29 18:03:32,314 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': returning result row for stmt 'PRAGMA journal_mode = MEMORY;'
2024-07-29 18:03:32,314 [4143104] <proxy.db:9>: results for 'PRAGMA journal_mode = MEMORY;':
2024-07-29 18:03:32,314 [4143104] <proxy.db:9>: col #1 [journal_mode]: memory
2024-07-29 18:03:32,314 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': stmt 'PRAGMA journal_mode = MEMORY;' ran for 0 nanosecs
2024-07-29 18:03:32,314 [4143104] <proxy.db:13>: successfully executed 'PRAGMA journal_mode = MEMORY;'
2024-07-29 18:03:32,314 [4143104] <proxy.db:9>: opened SQLite table '/var/ftp/proxy/proxy-reverse.db'
2024-07-29 18:03:32,314 [4143104] <proxy.db:19>: ensuring that schema at path '/var/ftp/proxy/proxy-reverse.db' has at least schema version 6
2024-07-29 18:03:32,314 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': executing stmt 'SELECT version FROM schema_version WHERE schema = ?;'
2024-07-29 18:03:32,314 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': returning result row for stmt 'SELECT version FROM schema_version WHERE schema = 'proxy_reverse';'
2024-07-29 18:03:32,314 [4143104] <proxy.db:12>: schema 'proxy_reverse': executing prepared statement 'SELECT version FROM schema_version WHERE schema = ?;' returned row (columns: 1)
2024-07-29 18:03:32,314 [4143104] <proxy.db:17>: column version [0]: 6
2024-07-29 18:03:32,314 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': stmt 'SELECT version FROM schema_version WHERE schema = 'proxy_reverse';' ran for 0 nanosecs
2024-07-29 18:03:32,314 [4143104] <proxy.db:13>: successfully executed 'SELECT version FROM schema_version WHERE schema = ?;'
2024-07-29 18:03:32,314 [4143104] <proxy.db:11>: schema version 6 >= desired version 6 for path '/var/ftp/proxy/proxy-reverse.db'
2024-07-29 18:03:32,314 [4143104] <proxy.db:10>: schema 'proxy_reverse': executing statement 'PRAGMA integrity_check;'
2024-07-29 18:03:32,314 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': executing stmt 'PRAGMA integrity_check;'
2024-07-29 18:03:32,314 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': returning result row for stmt 'PRAGMA integrity_check;'
2024-07-29 18:03:32,314 [4143104] <proxy.db:9>: results for 'PRAGMA integrity_check;':
2024-07-29 18:03:32,314 [4143104] <proxy.db:9>: col #1 [integrity_check]: ok
2024-07-29 18:03:32,314 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': stmt 'PRAGMA integrity_check;' ran for 0 nanosecs
2024-07-29 18:03:32,314 [4143104] <proxy.db:13>: successfully executed 'PRAGMA integrity_check;'
2024-07-29 18:03:32,314 [4143104] <proxy.db:10>: schema 'proxy_reverse': executing statement 'VACUUM;'
2024-07-29 18:03:32,314 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': executing stmt 'VACUUM;'
2024-07-29 18:03:32,317 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': stmt 'VACUUM;' ran for 3000000 nanosecs
2024-07-29 18:03:32,317 [4143104] <proxy.db:13>: successfully executed 'VACUUM;'
2024-07-29 18:03:32,317 [4143104] <proxy.db:10>: schema 'proxy_reverse': executing statement 'CREATE TABLE IF NOT EXISTS proxy_vhosts (vhost_id INTEGER NOT NULL PRIMARY KEY, vhost_name TEXT NOT NULL);'
2024-07-29 18:03:32,317 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': returning result row for stmt '(null)'
2024-07-29 18:03:32,317 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': returning result row for stmt '(null)'
2024-07-29 18:03:32,317 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': returning result row for stmt '(null)'
2024-07-29 18:03:32,317 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': returning result row for stmt '(null)'
2024-07-29 18:03:32,317 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': returning result row for stmt '(null)'
2024-07-29 18:03:32,317 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': returning result row for stmt '(null)'
2024-07-29 18:03:32,317 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': returning result row for stmt '(null)'
2024-07-29 18:03:32,317 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': returning result row for stmt '(null)'
2024-07-29 18:03:32,317 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': returning result row for stmt '(null)'
2024-07-29 18:03:32,317 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': returning result row for stmt '(null)'
2024-07-29 18:03:32,317 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': returning result row for stmt '(null)'
2024-07-29 18:03:32,317 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': returning result row for stmt '(null)'
2024-07-29 18:03:32,317 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': returning result row for stmt '(null)'
2024-07-29 18:03:32,317 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': returning result row for stmt '(null)'
2024-07-29 18:03:32,317 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': returning result row for stmt '(null)'
2024-07-29 18:03:32,317 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': returning result row for stmt '(null)'
2024-07-29 18:03:32,317 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': executing stmt 'CREATE TABLE IF NOT EXISTS proxy_vhosts (vhost_id INTEGER NOT NULL PRIMARY KEY, vhost_name TEXT NOT NULL);'
2024-07-29 18:03:32,317 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': stmt 'CREATE TABLE IF NOT EXISTS proxy_vhosts (vhost_id INTEGER NOT NULL PRIMARY KEY, vhost_name TEXT NOT NULL);' ran for 0 nanosecs
2024-07-29 18:03:32,317 [4143104] <proxy.db:13>: successfully executed 'CREATE TABLE IF NOT EXISTS proxy_vhosts (vhost_id INTEGER NOT NULL PRIMARY KEY, vhost_name TEXT NOT NULL);'
2024-07-29 18:03:32,317 [4143104] <proxy.db:10>: schema 'proxy_reverse': executing statement 'CREATE TABLE IF NOT EXISTS proxy_vhost_backends (vhost_id INTEGER NOT NULL, backend_id INTEGER NOT NULL, backend_uri TEXT NOT NULL, conn_count INTEGER NOT NULL, connect_ms INTEGER);'
2024-07-29 18:03:32,317 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': executing stmt 'CREATE TABLE IF NOT EXISTS proxy_vhost_backends (vhost_id INTEGER NOT NULL, backend_id INTEGER NOT NULL, backend_uri TEXT NOT NULL, conn_count INTEGER NOT NULL, connect_ms INTEGER);'
2024-07-29 18:03:32,317 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': stmt 'CREATE TABLE IF NOT EXISTS proxy_vhost_backends (vhost_id INTEGER NOT NULL, backend_id INTEGER NOT NULL, backend_uri TEXT NOT NULL, conn_count INTEGER NOT NULL, connect_ms INTEGER);' ran for 0 nanosecs
2024-07-29 18:03:32,317 [4143104] <proxy.db:13>: successfully executed 'CREATE TABLE IF NOT EXISTS proxy_vhost_backends (vhost_id INTEGER NOT NULL, backend_id INTEGER NOT NULL, backend_uri TEXT NOT NULL, conn_count INTEGER NOT NULL, connect_ms INTEGER);'
2024-07-29 18:03:32,317 [4143104] <proxy.db:10>: schema 'proxy_reverse': executing statement 'CREATE INDEX IF NOT EXISTS proxy_vhost_backends_vhost_id_idx ON proxy_vhost_backends (vhost_id);'
2024-07-29 18:03:32,317 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': executing stmt 'CREATE INDEX IF NOT EXISTS proxy_vhost_backends_vhost_id_idx ON proxy_vhost_backends (vhost_id);'
2024-07-29 18:03:32,317 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': stmt 'CREATE INDEX IF NOT EXISTS proxy_vhost_backends_vhost_id_idx ON proxy_vhost_backends (vhost_id);' ran for 0 nanosecs
2024-07-29 18:03:32,317 [4143104] <proxy.db:13>: successfully executed 'CREATE INDEX IF NOT EXISTS proxy_vhost_backends_vhost_id_idx ON proxy_vhost_backends (vhost_id);'
2024-07-29 18:03:32,317 [4143104] <proxy.db:10>: schema 'proxy_reverse': executing statement 'CREATE TABLE IF NOT EXISTS proxy_vhost_reverse_roundrobin (vhost_id INTEGER NOT NULL, current_backend_id INTEGER NOT NULL, FOREIGN KEY (vhost_id) REFERENCES proxy_vhosts (vhost_id), FOREIGN KEY (current_backend_id) REFERENCES proxy_vhost_backends (backend_id));'
2024-07-29 18:03:32,317 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': executing stmt 'CREATE TABLE IF NOT EXISTS proxy_vhost_reverse_roundrobin (vhost_id INTEGER NOT NULL, current_backend_id INTEGER NOT NULL, FOREIGN KEY (vhost_id) REFERENCES proxy_vhosts (vhost_id), FOREIGN KEY (current_backend_id) REFERENCES proxy_vhost_backends (backend_id));'
2024-07-29 18:03:32,317 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': stmt 'CREATE TABLE IF NOT EXISTS proxy_vhost_reverse_roundrobin (vhost_id INTEGER NOT NULL, current_backend_id INTEGER NOT NULL, FOREIGN KEY (vhost_id) REFERENCES proxy_vhosts (vhost_id), FOREIGN KEY (current_backend_id) REFERENCES proxy_vhost_backends (backend_id));' ran for 0 nanosecs
2024-07-29 18:03:32,317 [4143104] <proxy.db:13>: successfully executed 'CREATE TABLE IF NOT EXISTS proxy_vhost_reverse_roundrobin (vhost_id INTEGER NOT NULL, current_backend_id INTEGER NOT NULL, FOREIGN KEY (vhost_id) REFERENCES proxy_vhosts (vhost_id), FOREIGN KEY (current_backend_id) REFERENCES proxy_vhost_backends (backend_id));'
2024-07-29 18:03:32,317 [4143104] <proxy.db:10>: schema 'proxy_reverse': executing statement 'CREATE TABLE IF NOT EXISTS proxy_vhost_reverse_shuffle (vhost_id INTEGER NOT NULL, avail_backend_id INTEGER NOT NULL, FOREIGN KEY (vhost_id) REFERENCES proxy_vhosts (vhost_id), FOREIGN KEY (avail_backend_id) REFERENCES proxy_vhost_backends (backend_id));'
2024-07-29 18:03:32,317 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': executing stmt 'CREATE TABLE IF NOT EXISTS proxy_vhost_reverse_shuffle (vhost_id INTEGER NOT NULL, avail_backend_id INTEGER NOT NULL, FOREIGN KEY (vhost_id) REFERENCES proxy_vhosts (vhost_id), FOREIGN KEY (avail_backend_id) REFERENCES proxy_vhost_backends (backend_id));'
2024-07-29 18:03:32,317 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': stmt 'CREATE TABLE IF NOT EXISTS proxy_vhost_reverse_shuffle (vhost_id INTEGER NOT NULL, avail_backend_id INTEGER NOT NULL, FOREIGN KEY (vhost_id) REFERENCES proxy_vhosts (vhost_id), FOREIGN KEY (avail_backend_id) REFERENCES proxy_vhost_backends (backend_id));' ran for 0 nanosecs
2024-07-29 18:03:32,317 [4143104] <proxy.db:13>: successfully executed 'CREATE TABLE IF NOT EXISTS proxy_vhost_reverse_shuffle (vhost_id INTEGER NOT NULL, avail_backend_id INTEGER NOT NULL, FOREIGN KEY (vhost_id) REFERENCES proxy_vhosts (vhost_id), FOREIGN KEY (avail_backend_id) REFERENCES proxy_vhost_backends (backend_id));'
2024-07-29 18:03:32,317 [4143104] <proxy.db:10>: schema 'proxy_reverse': executing statement 'CREATE TABLE IF NOT EXISTS proxy_vhost_reverse_per_user (vhost_id INTEGER NOT NULL, user_name TEXT NOT NULL, backend_uri TEXT, FOREIGN KEY (vhost_id) REFERENCES proxy_vhosts (vhost_id), UNIQUE (vhost_id, user_name));'
2024-07-29 18:03:32,317 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': executing stmt 'CREATE TABLE IF NOT EXISTS proxy_vhost_reverse_per_user (vhost_id INTEGER NOT NULL, user_name TEXT NOT NULL, backend_uri TEXT, FOREIGN KEY (vhost_id) REFERENCES proxy_vhosts (vhost_id), UNIQUE (vhost_id, user_name));'
2024-07-29 18:03:32,317 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': stmt 'CREATE TABLE IF NOT EXISTS proxy_vhost_reverse_per_user (vhost_id INTEGER NOT NULL, user_name TEXT NOT NULL, backend_uri TEXT, FOREIGN KEY (vhost_id) REFERENCES proxy_vhosts (vhost_id), UNIQUE (vhost_id, user_name));' ran for 0 nanosecs
2024-07-29 18:03:32,317 [4143104] <proxy.db:13>: successfully executed 'CREATE TABLE IF NOT EXISTS proxy_vhost_reverse_per_user (vhost_id INTEGER NOT NULL, user_name TEXT NOT NULL, backend_uri TEXT, FOREIGN KEY (vhost_id) REFERENCES proxy_vhosts (vhost_id), UNIQUE (vhost_id, user_name));'
2024-07-29 18:03:32,317 [4143104] <proxy.db:10>: schema 'proxy_reverse': executing statement 'CREATE INDEX IF NOT EXISTS proxy_vhost_reverse_per_user_name_idx ON proxy_vhost_reverse_per_user (user_name);'
2024-07-29 18:03:32,318 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': executing stmt 'CREATE INDEX IF NOT EXISTS proxy_vhost_reverse_per_user_name_idx ON proxy_vhost_reverse_per_user (user_name);'
2024-07-29 18:03:32,318 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': stmt 'CREATE INDEX IF NOT EXISTS proxy_vhost_reverse_per_user_name_idx ON proxy_vhost_reverse_per_user (user_name);' ran for 0 nanosecs
2024-07-29 18:03:32,318 [4143104] <proxy.db:13>: successfully executed 'CREATE INDEX IF NOT EXISTS proxy_vhost_reverse_per_user_name_idx ON proxy_vhost_reverse_per_user (user_name);'
2024-07-29 18:03:32,318 [4143104] <proxy.db:10>: schema 'proxy_reverse': executing statement 'CREATE TABLE IF NOT EXISTS proxy_vhost_reverse_per_group (vhost_id INTEGER NOT NULL, group_name TEXT NOT NULL, backend_uri TEXT, FOREIGN KEY (vhost_id) REFERENCES proxy_vhosts (vhost_id), UNIQUE (vhost_id, group_name));'
2024-07-29 18:03:32,318 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': executing stmt 'CREATE TABLE IF NOT EXISTS proxy_vhost_reverse_per_group (vhost_id INTEGER NOT NULL, group_name TEXT NOT NULL, backend_uri TEXT, FOREIGN KEY (vhost_id) REFERENCES proxy_vhosts (vhost_id), UNIQUE (vhost_id, group_name));'
2024-07-29 18:03:32,318 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': stmt 'CREATE TABLE IF NOT EXISTS proxy_vhost_reverse_per_group (vhost_id INTEGER NOT NULL, group_name TEXT NOT NULL, backend_uri TEXT, FOREIGN KEY (vhost_id) REFERENCES proxy_vhosts (vhost_id), UNIQUE (vhost_id, group_name));' ran for 0 nanosecs
2024-07-29 18:03:32,318 [4143104] <proxy.db:13>: successfully executed 'CREATE TABLE IF NOT EXISTS proxy_vhost_reverse_per_group (vhost_id INTEGER NOT NULL, group_name TEXT NOT NULL, backend_uri TEXT, FOREIGN KEY (vhost_id) REFERENCES proxy_vhosts (vhost_id), UNIQUE (vhost_id, group_name));'
2024-07-29 18:03:32,318 [4143104] <proxy.db:10>: schema 'proxy_reverse': executing statement 'CREATE INDEX IF NOT EXISTS proxy_vhost_reverse_per_group_name_idx ON proxy_vhost_reverse_per_group (group_name);'
2024-07-29 18:03:32,318 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': executing stmt 'CREATE INDEX IF NOT EXISTS proxy_vhost_reverse_per_group_name_idx ON proxy_vhost_reverse_per_group (group_name);'
2024-07-29 18:03:32,318 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': stmt 'CREATE INDEX IF NOT EXISTS proxy_vhost_reverse_per_group_name_idx ON proxy_vhost_reverse_per_group (group_name);' ran for 0 nanosecs
2024-07-29 18:03:32,318 [4143104] <proxy.db:13>: successfully executed 'CREATE INDEX IF NOT EXISTS proxy_vhost_reverse_per_group_name_idx ON proxy_vhost_reverse_per_group (group_name);'
2024-07-29 18:03:32,318 [4143104] <proxy.db:10>: schema 'proxy_reverse': executing statement 'CREATE TABLE IF NOT EXISTS proxy_vhost_reverse_per_host (vhost_id INTEGER NOT NULL, ip_addr TEXT NOT NULL, backend_uri TEXT, FOREIGN KEY (vhost_id) REFERENCES proxy_vhosts (vhost_id), UNIQUE (vhost_id, ip_addr));'
2024-07-29 18:03:32,318 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': executing stmt 'CREATE TABLE IF NOT EXISTS proxy_vhost_reverse_per_host (vhost_id INTEGER NOT NULL, ip_addr TEXT NOT NULL, backend_uri TEXT, FOREIGN KEY (vhost_id) REFERENCES proxy_vhosts (vhost_id), UNIQUE (vhost_id, ip_addr));'
2024-07-29 18:03:32,318 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': stmt 'CREATE TABLE IF NOT EXISTS proxy_vhost_reverse_per_host (vhost_id INTEGER NOT NULL, ip_addr TEXT NOT NULL, backend_uri TEXT, FOREIGN KEY (vhost_id) REFERENCES proxy_vhosts (vhost_id), UNIQUE (vhost_id, ip_addr));' ran for 0 nanosecs
2024-07-29 18:03:32,318 [4143104] <proxy.db:13>: successfully executed 'CREATE TABLE IF NOT EXISTS proxy_vhost_reverse_per_host (vhost_id INTEGER NOT NULL, ip_addr TEXT NOT NULL, backend_uri TEXT, FOREIGN KEY (vhost_id) REFERENCES proxy_vhosts (vhost_id), UNIQUE (vhost_id, ip_addr));'
2024-07-29 18:03:32,318 [4143104] <proxy.db:10>: schema 'proxy_reverse': executing statement 'CREATE INDEX IF NOT EXISTS proxy_vhost_reverse_per_host_ipaddr_idx ON proxy_vhost_reverse_per_host (ip_addr);'
2024-07-29 18:03:32,318 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': executing stmt 'CREATE INDEX IF NOT EXISTS proxy_vhost_reverse_per_host_ipaddr_idx ON proxy_vhost_reverse_per_host (ip_addr);'
2024-07-29 18:03:32,318 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': stmt 'CREATE INDEX IF NOT EXISTS proxy_vhost_reverse_per_host_ipaddr_idx ON proxy_vhost_reverse_per_host (ip_addr);' ran for 0 nanosecs
2024-07-29 18:03:32,318 [4143104] <proxy.db:13>: successfully executed 'CREATE INDEX IF NOT EXISTS proxy_vhost_reverse_per_host_ipaddr_idx ON proxy_vhost_reverse_per_host (ip_addr);'
2024-07-29 18:03:32,318 [4143104] <proxy.db:10>: schema 'proxy_reverse': executing statement 'DELETE FROM proxy_vhosts;'
2024-07-29 18:03:32,318 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': executing stmt 'DELETE FROM proxy_vhosts;'
2024-07-29 18:03:32,319 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': stmt 'DELETE FROM proxy_vhosts;' ran for 1000000 nanosecs
2024-07-29 18:03:32,319 [4143104] <proxy.db:13>: successfully executed 'DELETE FROM proxy_vhosts;'
2024-07-29 18:03:32,319 [4143104] <proxy.db:10>: schema 'proxy_reverse': executing statement 'DELETE FROM proxy_vhost_backends;'
2024-07-29 18:03:32,319 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': executing stmt 'DELETE FROM proxy_vhost_backends;'
2024-07-29 18:03:32,320 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': stmt 'DELETE FROM proxy_vhost_backends;' ran for 1000000 nanosecs
2024-07-29 18:03:32,320 [4143104] <proxy.db:13>: successfully executed 'DELETE FROM proxy_vhost_backends;'
2024-07-29 18:03:32,320 [4143104] <proxy.db:10>: schema 'proxy_reverse': executing statement 'DELETE FROM proxy_vhost_reverse_roundrobin;'
2024-07-29 18:03:32,320 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': executing stmt 'DELETE FROM proxy_vhost_reverse_roundrobin;'
2024-07-29 18:03:32,321 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': stmt 'DELETE FROM proxy_vhost_reverse_roundrobin;' ran for 1000000 nanosecs
2024-07-29 18:03:32,321 [4143104] <proxy.db:13>: successfully executed 'DELETE FROM proxy_vhost_reverse_roundrobin;'
2024-07-29 18:03:32,321 [4143104] <proxy.db:10>: schema 'proxy_reverse': executing statement 'DELETE FROM proxy_vhost_reverse_shuffle;'
2024-07-29 18:03:32,321 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': executing stmt 'DELETE FROM proxy_vhost_reverse_shuffle;'
2024-07-29 18:03:32,322 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': stmt 'DELETE FROM proxy_vhost_reverse_shuffle;' ran for 1000000 nanosecs
2024-07-29 18:03:32,322 [4143104] <proxy.db:13>: successfully executed 'DELETE FROM proxy_vhost_reverse_shuffle;'
2024-07-29 18:03:32,322 [4143104] <proxy.db:10>: schema 'proxy_reverse': executing statement 'DELETE FROM proxy_vhost_reverse_per_user;'
2024-07-29 18:03:32,322 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': executing stmt 'DELETE FROM proxy_vhost_reverse_per_user;'
2024-07-29 18:03:32,323 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': stmt 'DELETE FROM proxy_vhost_reverse_per_user;' ran for 1000000 nanosecs
2024-07-29 18:03:32,323 [4143104] <proxy.db:13>: successfully executed 'DELETE FROM proxy_vhost_reverse_per_user;'
2024-07-29 18:03:32,323 [4143104] <proxy.db:10>: schema 'proxy_reverse': executing statement 'DELETE FROM proxy_vhost_reverse_per_group;'
2024-07-29 18:03:32,323 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': executing stmt 'DELETE FROM proxy_vhost_reverse_per_group;'
2024-07-29 18:03:32,324 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': stmt 'DELETE FROM proxy_vhost_reverse_per_group;' ran for 1000000 nanosecs
2024-07-29 18:03:32,324 [4143104] <proxy.db:13>: successfully executed 'DELETE FROM proxy_vhost_reverse_per_group;'
2024-07-29 18:03:32,324 [4143104] <proxy.db:10>: schema 'proxy_reverse': executing statement 'DELETE FROM proxy_vhost_reverse_per_host;'
2024-07-29 18:03:32,324 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': executing stmt 'DELETE FROM proxy_vhost_reverse_per_host;'
2024-07-29 18:03:32,325 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': stmt 'DELETE FROM proxy_vhost_reverse_per_host;' ran for 1000000 nanosecs
2024-07-29 18:03:32,325 [4143104] <proxy.db:13>: successfully executed 'DELETE FROM proxy_vhost_reverse_per_host;'
2024-07-29 18:03:32,325 [4143104] <proxy.db:10>: schema 'proxy_reverse': executing statement 'REINDEX proxy_vhost_backends_vhost_id_idx;'
2024-07-29 18:03:32,325 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': executing stmt 'REINDEX proxy_vhost_backends_vhost_id_idx;'
2024-07-29 18:03:32,326 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': stmt 'REINDEX proxy_vhost_backends_vhost_id_idx;' ran for 1000000 nanosecs
2024-07-29 18:03:32,326 [4143104] <proxy.db:13>: successfully executed 'REINDEX proxy_vhost_backends_vhost_id_idx;'
2024-07-29 18:03:32,326 [4143104] <proxy.db:10>: schema 'proxy_reverse': executing statement 'REINDEX proxy_vhost_reverse_per_user_name_idx;'
2024-07-29 18:03:32,326 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': executing stmt 'REINDEX proxy_vhost_reverse_per_user_name_idx;'
2024-07-29 18:03:32,327 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': stmt 'REINDEX proxy_vhost_reverse_per_user_name_idx;' ran for 1000000 nanosecs
2024-07-29 18:03:32,327 [4143104] <proxy.db:13>: successfully executed 'REINDEX proxy_vhost_reverse_per_user_name_idx;'
2024-07-29 18:03:32,327 [4143104] <proxy.db:10>: schema 'proxy_reverse': executing statement 'REINDEX proxy_vhost_reverse_per_group_name_idx;'
2024-07-29 18:03:32,327 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': executing stmt 'REINDEX proxy_vhost_reverse_per_group_name_idx;'
2024-07-29 18:03:32,328 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': stmt 'REINDEX proxy_vhost_reverse_per_group_name_idx;' ran for 1000000 nanosecs
2024-07-29 18:03:32,328 [4143104] <proxy.db:13>: successfully executed 'REINDEX proxy_vhost_reverse_per_group_name_idx;'
2024-07-29 18:03:32,328 [4143104] <proxy.db:10>: schema 'proxy_reverse': executing statement 'REINDEX proxy_vhost_reverse_per_host_ipaddr_idx;'
2024-07-29 18:03:32,328 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': executing stmt 'REINDEX proxy_vhost_reverse_per_host_ipaddr_idx;'
2024-07-29 18:03:32,329 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': stmt 'REINDEX proxy_vhost_reverse_per_host_ipaddr_idx;' ran for 1000000 nanosecs
2024-07-29 18:03:32,329 [4143104] <proxy.db:13>: successfully executed 'REINDEX proxy_vhost_reverse_per_host_ipaddr_idx;'
2024-07-29 18:03:32,329 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': executing stmt 'INSERT INTO proxy_vhosts (vhost_id, vhost_name) VALUES (?, ?);'
2024-07-29 18:03:32,330 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': stmt 'INSERT INTO proxy_vhosts (vhost_id, vhost_name) VALUES (1, 'Our FTPS Proxy Server');' ran for 1000000 nanosecs
2024-07-29 18:03:32,330 [4143104] <proxy.db:13>: successfully executed 'INSERT INTO proxy_vhosts (vhost_id, vhost_name) VALUES (?, ?);'
2024-07-29 18:03:32,330 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': executing stmt 'INSERT INTO proxy_vhost_reverse_roundrobin (vhost_id, current_backend_id) VALUES (?, ?);'
2024-07-29 18:03:32,331 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': stmt 'INSERT INTO proxy_vhost_reverse_roundrobin (vhost_id, current_backend_id) VALUES (1, 0);' ran for 1000000 nanosecs
2024-07-29 18:03:32,331 [4143104] <proxy.db:13>: successfully executed 'INSERT INTO proxy_vhost_reverse_roundrobin (vhost_id, current_backend_id) VALUES (?, ?);'
2024-07-29 18:03:32,331 [4143104] <proxy.db:19>: closing 'proxy_reverse' database handle
2024-07-29 18:03:32,331 [4143104] <proxy.db:18>: finished prepared statement 'INSERT INTO proxy_vhost_reverse_roundrobin (vhost_id, current_backend_id) VALUES (?, ?);'
2024-07-29 18:03:32,331 [4143104] <proxy.db:18>: finished prepared statement 'INSERT INTO proxy_vhosts (vhost_id, vhost_name) VALUES (?, ?);'
2024-07-29 18:03:32,331 [4143104] <proxy.db:18>: finished prepared statement 'SELECT version FROM schema_version WHERE schema = ?;'
2024-07-29 18:03:32,331 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_reverse': closing database connection to /var/ftp/proxy/proxy-reverse.db
2024-07-29 18:03:32,331 [4143104] <proxy.db:18>: closed SQLite database
2024-07-29 18:03:32,331 [4143104] <proxy.db:19>: attempting to open proxy_ssh tables at path '/var/ftp/proxy/proxy-ssh.db'
2024-07-29 18:03:32,331 [4143104] <proxy.db:10>: schema 'proxy_ssh': executing statement 'PRAGMA temp_store = MEMORY;'
2024-07-29 18:03:32,331 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_ssh': executing stmt 'PRAGMA temp_store = MEMORY;'
2024-07-29 18:03:32,331 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_ssh': stmt 'PRAGMA temp_store = MEMORY;' ran for 0 nanosecs
2024-07-29 18:03:32,331 [4143104] <proxy.db:13>: successfully executed 'PRAGMA temp_store = MEMORY;'
2024-07-29 18:03:32,331 [4143104] <proxy.db:10>: schema 'proxy_ssh': executing statement 'PRAGMA journal_mode = MEMORY;'
2024-07-29 18:03:32,331 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_ssh': returning result row for stmt '(null)'
2024-07-29 18:03:32,331 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_ssh': returning result row for stmt '(null)'
2024-07-29 18:03:32,331 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_ssh': returning result row for stmt '(null)'
2024-07-29 18:03:32,331 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_ssh': returning result row for stmt '(null)'
2024-07-29 18:03:32,331 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_ssh': returning result row for stmt '(null)'
2024-07-29 18:03:32,331 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_ssh': executing stmt 'PRAGMA journal_mode = MEMORY;'
2024-07-29 18:03:32,331 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_ssh': returning result row for stmt 'PRAGMA journal_mode = MEMORY;'
2024-07-29 18:03:32,331 [4143104] <proxy.db:9>: results for 'PRAGMA journal_mode = MEMORY;':
2024-07-29 18:03:32,331 [4143104] <proxy.db:9>: col #1 [journal_mode]: memory
2024-07-29 18:03:32,331 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_ssh': stmt 'PRAGMA journal_mode = MEMORY;' ran for 0 nanosecs
2024-07-29 18:03:32,331 [4143104] <proxy.db:13>: successfully executed 'PRAGMA journal_mode = MEMORY;'
2024-07-29 18:03:32,331 [4143104] <proxy.db:9>: opened SQLite table '/var/ftp/proxy/proxy-ssh.db'
2024-07-29 18:03:32,331 [4143104] <proxy.db:19>: ensuring that schema at path '/var/ftp/proxy/proxy-ssh.db' has at least schema version 1
2024-07-29 18:03:32,331 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_ssh': executing stmt 'SELECT version FROM schema_version WHERE schema = ?;'
2024-07-29 18:03:32,331 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_ssh': returning result row for stmt 'SELECT version FROM schema_version WHERE schema = 'proxy_ssh';'
2024-07-29 18:03:32,332 [4143104] <proxy.db:12>: schema 'proxy_ssh': executing prepared statement 'SELECT version FROM schema_version WHERE schema = ?;' returned row (columns: 1)
2024-07-29 18:03:32,332 [4143104] <proxy.db:17>: column version [0]: 1
2024-07-29 18:03:32,332 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_ssh': stmt 'SELECT version FROM schema_version WHERE schema = 'proxy_ssh';' ran for 1000000 nanosecs
2024-07-29 18:03:32,332 [4143104] <proxy.db:13>: successfully executed 'SELECT version FROM schema_version WHERE schema = ?;'
2024-07-29 18:03:32,332 [4143104] <proxy.db:11>: schema version 1 >= desired version 1 for path '/var/ftp/proxy/proxy-ssh.db'
2024-07-29 18:03:32,332 [4143104] <proxy.db:10>: schema 'proxy_ssh': executing statement 'PRAGMA integrity_check;'
2024-07-29 18:03:32,332 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_ssh': executing stmt 'PRAGMA integrity_check;'
2024-07-29 18:03:32,332 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_ssh': returning result row for stmt 'PRAGMA integrity_check;'
2024-07-29 18:03:32,332 [4143104] <proxy.db:9>: results for 'PRAGMA integrity_check;':
2024-07-29 18:03:32,332 [4143104] <proxy.db:9>: col #1 [integrity_check]: ok
2024-07-29 18:03:32,332 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_ssh': stmt 'PRAGMA integrity_check;' ran for 0 nanosecs
2024-07-29 18:03:32,332 [4143104] <proxy.db:13>: successfully executed 'PRAGMA integrity_check;'
2024-07-29 18:03:32,332 [4143104] <proxy.db:10>: schema 'proxy_ssh': executing statement 'VACUUM;'
2024-07-29 18:03:32,332 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_ssh': executing stmt 'VACUUM;'
2024-07-29 18:03:32,333 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_ssh': stmt 'VACUUM;' ran for 1000000 nanosecs
2024-07-29 18:03:32,333 [4143104] <proxy.db:13>: successfully executed 'VACUUM;'
2024-07-29 18:03:32,333 [4143104] <proxy.db:10>: schema 'proxy_ssh': executing statement 'CREATE TABLE IF NOT EXISTS proxy_ssh_vhosts (vhost_id INTEGER NOT NULL PRIMARY KEY, vhost_name TEXT NOT NULL);'
2024-07-29 18:03:32,333 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_ssh': returning result row for stmt '(null)'
2024-07-29 18:03:32,333 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_ssh': returning result row for stmt '(null)'
2024-07-29 18:03:32,333 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_ssh': returning result row for stmt '(null)'
2024-07-29 18:03:32,333 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_ssh': returning result row for stmt '(null)'
2024-07-29 18:03:32,333 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_ssh': returning result row for stmt '(null)'
2024-07-29 18:03:32,333 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_ssh': executing stmt 'CREATE TABLE IF NOT EXISTS proxy_ssh_vhosts (vhost_id INTEGER NOT NULL PRIMARY KEY, vhost_name TEXT NOT NULL);'
2024-07-29 18:03:32,333 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_ssh': stmt 'CREATE TABLE IF NOT EXISTS proxy_ssh_vhosts (vhost_id INTEGER NOT NULL PRIMARY KEY, vhost_name TEXT NOT NULL);' ran for 0 nanosecs
2024-07-29 18:03:32,333 [4143104] <proxy.db:13>: successfully executed 'CREATE TABLE IF NOT EXISTS proxy_ssh_vhosts (vhost_id INTEGER NOT NULL PRIMARY KEY, vhost_name TEXT NOT NULL);'
2024-07-29 18:03:32,333 [4143104] <proxy.db:10>: schema 'proxy_ssh': executing statement 'CREATE TABLE IF NOT EXISTS proxy_ssh_hostkeys (backend_uri STRING NOT NULL PRIMARY KEY, vhost_id INTEGER NOT NULL, algo TEXT NOT NULL, hostkey BLOB NOT NULL, FOREIGN KEY (vhost_id) REFERENCES proxy_ssh_hosts (vhost_id));'
2024-07-29 18:03:32,333 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_ssh': executing stmt 'CREATE TABLE IF NOT EXISTS proxy_ssh_hostkeys (backend_uri STRING NOT NULL PRIMARY KEY, vhost_id INTEGER NOT NULL, algo TEXT NOT NULL, hostkey BLOB NOT NULL, FOREIGN KEY (vhost_id) REFERENCES proxy_ssh_hosts (vhost_id));'
2024-07-29 18:03:32,333 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_ssh': stmt 'CREATE TABLE IF NOT EXISTS proxy_ssh_hostkeys (backend_uri STRING NOT NULL PRIMARY KEY, vhost_id INTEGER NOT NULL, algo TEXT NOT NULL, hostkey BLOB NOT NULL, FOREIGN KEY (vhost_id) REFERENCES proxy_ssh_hosts (vhost_id));' ran for 0 nanosecs
2024-07-29 18:03:32,333 [4143104] <proxy.db:13>: successfully executed 'CREATE TABLE IF NOT EXISTS proxy_ssh_hostkeys (backend_uri STRING NOT NULL PRIMARY KEY, vhost_id INTEGER NOT NULL, algo TEXT NOT NULL, hostkey BLOB NOT NULL, FOREIGN KEY (vhost_id) REFERENCES proxy_ssh_hosts (vhost_id));'
2024-07-29 18:03:32,333 [4143104] <proxy.db:10>: schema 'proxy_ssh': executing statement 'DELETE FROM proxy_ssh_vhosts;'
2024-07-29 18:03:32,333 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_ssh': executing stmt 'DELETE FROM proxy_ssh_vhosts;'
2024-07-29 18:03:32,334 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_ssh': stmt 'DELETE FROM proxy_ssh_vhosts;' ran for 1000000 nanosecs
2024-07-29 18:03:32,334 [4143104] <proxy.db:13>: successfully executed 'DELETE FROM proxy_ssh_vhosts;'
2024-07-29 18:03:32,334 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_ssh': executing stmt 'INSERT INTO proxy_ssh_vhosts (vhost_id, vhost_name) VALUES (?, ?);'
2024-07-29 18:03:32,335 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_ssh': stmt 'INSERT INTO proxy_ssh_vhosts (vhost_id, vhost_name) VALUES (1, 'Our FTPS Proxy Server');' ran for 1000000 nanosecs
2024-07-29 18:03:32,335 [4143104] <proxy.db:13>: successfully executed 'INSERT INTO proxy_ssh_vhosts (vhost_id, vhost_name) VALUES (?, ?);'
2024-07-29 18:03:32,335 [4143104] <proxy.db:19>: closing 'proxy_ssh' database handle
2024-07-29 18:03:32,335 [4143104] <proxy.db:18>: finished prepared statement 'INSERT INTO proxy_ssh_vhosts (vhost_id, vhost_name) VALUES (?, ?);'
2024-07-29 18:03:32,335 [4143104] <proxy.db:18>: finished prepared statement 'SELECT version FROM schema_version WHERE schema = ?;'
2024-07-29 18:03:32,335 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_ssh': closing database connection to /var/ftp/proxy/proxy-ssh.db
2024-07-29 18:03:32,335 [4143104] <proxy.db:18>: closed SQLite database
2024-07-29 18:03:32,336 [4143104] <proxy.db:19>: attempting to open proxy_tls tables at path '/var/ftp/proxy/proxy-tls.db'
2024-07-29 18:03:32,336 [4143104] <proxy.db:10>: schema 'proxy_tls': executing statement 'PRAGMA temp_store = MEMORY;'
2024-07-29 18:03:32,336 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_tls': executing stmt 'PRAGMA temp_store = MEMORY;'
2024-07-29 18:03:32,336 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_tls': stmt 'PRAGMA temp_store = MEMORY;' ran for 0 nanosecs
2024-07-29 18:03:32,336 [4143104] <proxy.db:13>: successfully executed 'PRAGMA temp_store = MEMORY;'
2024-07-29 18:03:32,336 [4143104] <proxy.db:10>: schema 'proxy_tls': executing statement 'PRAGMA journal_mode = MEMORY;'
2024-07-29 18:03:32,336 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_tls': returning result row for stmt '(null)'
2024-07-29 18:03:32,336 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_tls': returning result row for stmt '(null)'
2024-07-29 18:03:32,336 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_tls': returning result row for stmt '(null)'
2024-07-29 18:03:32,336 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_tls': returning result row for stmt '(null)'
2024-07-29 18:03:32,336 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_tls': returning result row for stmt '(null)'
2024-07-29 18:03:32,336 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_tls': executing stmt 'PRAGMA journal_mode = MEMORY;'
2024-07-29 18:03:32,336 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_tls': returning result row for stmt 'PRAGMA journal_mode = MEMORY;'
2024-07-29 18:03:32,336 [4143104] <proxy.db:9>: results for 'PRAGMA journal_mode = MEMORY;':
2024-07-29 18:03:32,336 [4143104] <proxy.db:9>: col #1 [journal_mode]: memory
2024-07-29 18:03:32,336 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_tls': stmt 'PRAGMA journal_mode = MEMORY;' ran for 0 nanosecs
2024-07-29 18:03:32,336 [4143104] <proxy.db:13>: successfully executed 'PRAGMA journal_mode = MEMORY;'
2024-07-29 18:03:32,336 [4143104] <proxy.db:9>: opened SQLite table '/var/ftp/proxy/proxy-tls.db'
2024-07-29 18:03:32,336 [4143104] <proxy.db:19>: ensuring that schema at path '/var/ftp/proxy/proxy-tls.db' has at least schema version 3
2024-07-29 18:03:32,336 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_tls': executing stmt 'SELECT version FROM schema_version WHERE schema = ?;'
2024-07-29 18:03:32,336 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_tls': returning result row for stmt 'SELECT version FROM schema_version WHERE schema = 'proxy_tls';'
2024-07-29 18:03:32,336 [4143104] <proxy.db:12>: schema 'proxy_tls': executing prepared statement 'SELECT version FROM schema_version WHERE schema = ?;' returned row (columns: 1)
2024-07-29 18:03:32,336 [4143104] <proxy.db:17>: column version [0]: 3
2024-07-29 18:03:32,336 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_tls': stmt 'SELECT version FROM schema_version WHERE schema = 'proxy_tls';' ran for 0 nanosecs
2024-07-29 18:03:32,336 [4143104] <proxy.db:13>: successfully executed 'SELECT version FROM schema_version WHERE schema = ?;'
2024-07-29 18:03:32,336 [4143104] <proxy.db:11>: schema version 3 >= desired version 3 for path '/var/ftp/proxy/proxy-tls.db'
2024-07-29 18:03:32,336 [4143104] <proxy.db:10>: schema 'proxy_tls': executing statement 'PRAGMA integrity_check;'
2024-07-29 18:03:32,336 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_tls': executing stmt 'PRAGMA integrity_check;'
2024-07-29 18:03:32,336 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_tls': returning result row for stmt 'PRAGMA integrity_check;'
2024-07-29 18:03:32,336 [4143104] <proxy.db:9>: results for 'PRAGMA integrity_check;':
2024-07-29 18:03:32,336 [4143104] <proxy.db:9>: col #1 [integrity_check]: ok
2024-07-29 18:03:32,336 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_tls': stmt 'PRAGMA integrity_check;' ran for 0 nanosecs
2024-07-29 18:03:32,336 [4143104] <proxy.db:13>: successfully executed 'PRAGMA integrity_check;'
2024-07-29 18:03:32,336 [4143104] <proxy.db:10>: schema 'proxy_tls': executing statement 'VACUUM;'
2024-07-29 18:03:32,336 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_tls': executing stmt 'VACUUM;'
2024-07-29 18:03:32,338 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_tls': stmt 'VACUUM;' ran for 2000000 nanosecs
2024-07-29 18:03:32,338 [4143104] <proxy.db:13>: successfully executed 'VACUUM;'
2024-07-29 18:03:32,338 [4143104] <proxy.db:10>: schema 'proxy_tls': executing statement 'CREATE TABLE IF NOT EXISTS proxy_tls_vhosts (vhost_id INTEGER NOT NULL PRIMARY KEY, vhost_name TEXT NOT NULL);'
2024-07-29 18:03:32,338 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_tls': returning result row for stmt '(null)'
2024-07-29 18:03:32,338 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_tls': returning result row for stmt '(null)'
2024-07-29 18:03:32,338 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_tls': returning result row for stmt '(null)'
2024-07-29 18:03:32,338 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_tls': returning result row for stmt '(null)'
2024-07-29 18:03:32,338 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_tls': returning result row for stmt '(null)'
2024-07-29 18:03:32,338 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_tls': executing stmt 'CREATE TABLE IF NOT EXISTS proxy_tls_vhosts (vhost_id INTEGER NOT NULL PRIMARY KEY, vhost_name TEXT NOT NULL);'
2024-07-29 18:03:32,338 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_tls': stmt 'CREATE TABLE IF NOT EXISTS proxy_tls_vhosts (vhost_id INTEGER NOT NULL PRIMARY KEY, vhost_name TEXT NOT NULL);' ran for 0 nanosecs
2024-07-29 18:03:32,338 [4143104] <proxy.db:13>: successfully executed 'CREATE TABLE IF NOT EXISTS proxy_tls_vhosts (vhost_id INTEGER NOT NULL PRIMARY KEY, vhost_name TEXT NOT NULL);'
2024-07-29 18:03:32,338 [4143104] <proxy.db:10>: schema 'proxy_tls': executing statement 'CREATE TABLE IF NOT EXISTS proxy_tls_sessions (backend_uri STRING NOT NULL PRIMARY KEY, vhost_id INTEGER NOT NULL, session TEXT NOT NULL, FOREIGN KEY (vhost_id) REFERENCES proxy_tls_hosts (vhost_id));'
2024-07-29 18:03:32,338 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_tls': executing stmt 'CREATE TABLE IF NOT EXISTS proxy_tls_sessions (backend_uri STRING NOT NULL PRIMARY KEY, vhost_id INTEGER NOT NULL, session TEXT NOT NULL, FOREIGN KEY (vhost_id) REFERENCES proxy_tls_hosts (vhost_id));'
2024-07-29 18:03:32,338 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_tls': stmt 'CREATE TABLE IF NOT EXISTS proxy_tls_sessions (backend_uri STRING NOT NULL PRIMARY KEY, vhost_id INTEGER NOT NULL, session TEXT NOT NULL, FOREIGN KEY (vhost_id) REFERENCES proxy_tls_hosts (vhost_id));' ran for 0 nanosecs
2024-07-29 18:03:32,338 [4143104] <proxy.db:13>: successfully executed 'CREATE TABLE IF NOT EXISTS proxy_tls_sessions (backend_uri STRING NOT NULL PRIMARY KEY, vhost_id INTEGER NOT NULL, session TEXT NOT NULL, FOREIGN KEY (vhost_id) REFERENCES proxy_tls_hosts (vhost_id));'
2024-07-29 18:03:32,338 [4143104] <proxy.db:10>: schema 'proxy_tls': executing statement 'DELETE FROM proxy_tls_vhosts;'
2024-07-29 18:03:32,338 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_tls': executing stmt 'DELETE FROM proxy_tls_vhosts;'
2024-07-29 18:03:32,339 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_tls': stmt 'DELETE FROM proxy_tls_vhosts;' ran for 1000000 nanosecs
2024-07-29 18:03:32,339 [4143104] <proxy.db:13>: successfully executed 'DELETE FROM proxy_tls_vhosts;'
2024-07-29 18:03:32,339 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_tls': executing stmt 'INSERT INTO proxy_tls_vhosts (vhost_id, vhost_name) VALUES (?, ?);'
2024-07-29 18:03:32,340 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_tls': stmt 'INSERT INTO proxy_tls_vhosts (vhost_id, vhost_name) VALUES (1, 'Our FTPS Proxy Server');' ran for 1000000 nanosecs
2024-07-29 18:03:32,340 [4143104] <proxy.db:13>: successfully executed 'INSERT INTO proxy_tls_vhosts (vhost_id, vhost_name) VALUES (?, ?);'
2024-07-29 18:03:32,340 [4143104] <proxy.db:19>: closing 'proxy_tls' database handle
2024-07-29 18:03:32,340 [4143104] <proxy.db:18>: finished prepared statement 'INSERT INTO proxy_tls_vhosts (vhost_id, vhost_name) VALUES (?, ?);'
2024-07-29 18:03:32,340 [4143104] <proxy.db:18>: finished prepared statement 'SELECT version FROM schema_version WHERE schema = ?;'
2024-07-29 18:03:32,340 [4143104] <proxy.db:17>: (sqlite3): schema 'proxy_tls': closing database connection to /var/ftp/proxy/proxy-tls.db
2024-07-29 18:03:32,340 [4143104] <proxy.db:18>: closed SQLite database

PAamac avatar Jul 29 '24 23:07 PAamac

Thanks for the logs! And I'm glad you were able to get a working build with the latest mod_proxy.

I think I found the next issue -- and it's completely my fault. My previous commit for this issue included parsing of the new ProxyOption value, and documentation for it. However, the commit completely missed the code changes needed to actually implement the behavior. Sigh. I'm terribly sorry about that.

This should now be addressed in the master branch of this repo, with https://github.com/Castaglia/proftpd-mod_proxy/commit/ab77f714ddb7f7f1fd2e0f085ed3d86655bf3741

Maybe you could re-build mod_proxy with that commit, and test again?

Castaglia avatar Jul 30 '24 01:07 Castaglia

Thank you for the update!

On the good news front, replacing the xfer.c file, performing a clean make, and updating the mod_proxy.so file for ProFTPD v1.3.8b does now allow for the original remote address, and the remote address provided in responses from that server, to be different.

Delving into what is likely off-topic to the original issue - apologies; this may be relevant to compatibility in some situations as it appears to be for ours - our FTPS ProFTPD-proxied connection to internet that uses PASSIVE mode (required by remote server) will fail once a PORT command is issued to begin passive mode transfer.

Given a set-up where:

  1. proxy server has only a private RFC1918 IPv4 address (for non-loopback traffic) -and-
  2. there is an internet-edge NAT which takes place for traffic between the proxy server and remote FTPS server -and-
  3. there is no SSL/TLS inspection in place (or possible in this case)

there is a disconnect between ports communicated by ProFTPD to the internet FTPS server and the actual NAT ports assigned for ProFTPD server traffic on the internet edge. There may also be an issue with the IP address communicated by ProFTPD to the internet FTPS server (private IP instead of public IP).

To resolve the NAT port issue, is there a way to have mod_proxy always use a specific port/range for FTPS PASSIVE mode to the destination server? This would allow 1:1 port translations to be configured at the NAT edge. The PassivePorts configuration directive in ProFTPD only appears to apply to ports used to communicate with the proxy client and not those used to communicate with the destination server.

There may also be an issue with the IPv4 address that the private IP proxy server provides to the public IP destination FTPS server when entering passive mode. In the set-up described above, the ProFTPD masquerade option is seemingly not desirable as the proxy client still needs to communicate with the proxy server at its private IP address. Is there an option to make ProFTPD, or just mod_proxy, aware of an IP address (in this case a public one used for NAT) that should only be used to identify itself when communicating with a remote FTPS server, while continuing to identify itself to proxy clients with an actual local listening IP address?

Thank you again!

PAamac avatar Jul 30 '24 18:07 PAamac

On the good news front, replacing the xfer.c file, performing a clean make, and updating the mod_proxy.so file for ProFTPD v1.3.8b does now allow for the original remote address, and the remote address provided in responses from that server, to be different.

Excellent! Did the rest of the FTP session (directory listings, file transfers, etc) succeed as well?

Delving into what is likely off-topic to the original issue - apologies; this may be relevant to compatibility in some situations as it appears to be for ours - our FTPS ProFTPD-proxied connection to internet that uses PASSIVE mode (required by remote server) will fail once a PORT command is issued to begin passive mode transfer.

The PORT (and EPRT) FTP commands are used to initiate active transfers, not passive mode transfers. "Passive", in this case, means that the server (the backend server) will "passively" listen for and accept the separate TCP connection for the data transfer, at an address/port indicated in the PASV (or EPSV) response. If instead the client sends PORT (or EPRT), then the server will "actively" connect back to the client, at the address/port indicated in the PORT command.

there is a disconnect between ports communicated by ProFTPD to the internet FTPS server and the actual NAT ports assigned for ProFTPD server traffic on the internet edge. There may also be an issue with the IP address communicated by ProFTPD to the internet FTPS server (private IP instead of public IP).

Yes, this is currently possible, and at present, mod_proxy does not expose a way to configure the external address (or port range) used in PORT (or EPRT) commands that it may send to the backend server. It hasn't been an issue (or requested feature) so far, since most FTP data transfers do use passive (client connecting to server for data transfer), not active, mode.

To resolve the NAT port issue, is there a way to have mod_proxy always use a specific port/range for FTPS PASSIVE mode to the destination server? This would allow 1:1 port translations to be configured at the NAT edge. The PassivePorts configuration directive in ProFTPD only appears to apply to ports used to communicate with the proxy client and not those used to communicate with the destination server.

Correct. If your use case does need such configurability, for your proxied FTP sessions, would you mind filing that in a separate ticket? Remember that, for these proxied FTP sessions, mod_proxy is acting as an FTP client. FTP clients do not specify any address/ports for passive data transfers; FTP clients only specify address/ports in PORT/EPRT commands for active data transfers. This is why the PassivePorts configuration directive is not used by mod_proxy for active data transfers.

Castaglia avatar Jul 31 '24 14:07 Castaglia

Thank you for the comments/update.

With the different foreign address allowed in the latest mod_proxy update, the proxy client can log on for FTPS in ProxyForwardMethod "user@host" mode via the proxy server, but the new issue is now that the proxy client stops receiving data once it issues the MLSD command to retrieve a directory listing for the default directory of the remote FTPS server.

The client trace shows that it issues a PASV command, the proxy server provides a 227 response with its private IP and port information, the client issues the MLSD command to the proxy server, the proxy server provides a "150 File status okay. About to open data connection." response, but then the client stops receiving data. Here is the protftpd debug level 10 output for the MLSD command:

2024-07-31 12:42:12,993 our.server.internal proftpd[175401] our.server.internal (10.1.2.3[10.1.2.3]): dispatching CMD command 'PASV' to mod_proxy
2024-07-31 12:42:13,017 our.server.internal proftpd[175401] our.server.internal (10.1.2.3[10.1.2.3]): dispatching LOG_CMD command 'PASV' to mod_log
2024-07-31 12:42:13,041 our.server.internal proftpd[175401] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'MLSD' to mod_tls
2024-07-31 12:42:13,042 our.server.internal proftpd[175401] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'MLSD' to mod_core
2024-07-31 12:42:13,042 our.server.internal proftpd[175401] our.server.internal (10.1.2.3[10.1.2.3]): dispatching PRE_CMD command 'MLSD' to mod_core
2024-07-31 12:42:13,042 our.server.internal proftpd[175401] our.server.internal (10.1.2.3[10.1.2.3]): dispatching CMD command 'MLSD' to mod_proxy
2024-07-31 12:42:18,891 our.server.internal proftpd[175400] our.server.internal: ROOT PRIVS at mod_ctrls.c:747
2024-07-31 12:42:18,891 our.server.internal proftpd[175400] our.server.internal: RELINQUISH PRIVS at mod_ctrls.c:753
^C2024-07-31 12:42:32,567 our.server.internal proftpd[175400] our.server.internal: ROOT PRIVS at signals.c:152
2024-07-31 12:42:32,567 our.server.internal proftpd[175400] our.server.internal: RELINQUISH PRIVS at signals.c:154
2024-07-31 12:42:32,568 our.server.internal proftpd[175401] our.server.internal (10.1.2.3[10.1.2.3]): -----BEGIN STACK TRACE-----
2024-07-31 12:42:32,568 our.server.internal proftpd[175400] our.server.internal: ProFTPD killed (signal 2)
2024-07-31 12:42:32,568 our.server.internal proftpd[175400] our.server.internal: ROOT PRIVS at signals.c:59
2024-07-31 12:42:32,568 our.server.internal proftpd[175400] our.server.internal: ROOT PRIVS at mod_tls.c:6604
2024-07-31 12:42:32,568 our.server.internal proftpd[175400] our.server.internal: RELINQUISH PRIVS at mod_tls.c:6607
2024-07-31 12:42:32,568 our.server.internal proftpd[175401] our.server.internal (10.1.2.3[10.1.2.3]): [0] proftpd: [email protected]@ftps.remoteserver.com - (connecting): MLSD() [0x4218e2]
2024-07-31 12:42:32,568 our.server.internal proftpd[175401] our.server.internal (10.1.2.3[10.1.2.3]): [1] proftpd: [email protected]@ftps.remoteserver.com - (connecting): MLSD() [0x4218e2]
2024-07-31 12:42:32,568 our.server.internal proftpd[175401] our.server.internal (10.1.2.3[10.1.2.3]): [2] proftpd: [email protected]@ftps.remoteserver.com - (connecting): MLSD(pr_netio_close+0x12f) [0x44199f]
2024-07-31 12:42:32,568 our.server.internal proftpd[175401] our.server.internal (10.1.2.3[10.1.2.3]): [3] proftpd: [email protected]@ftps.remoteserver.com - (connecting): MLSD() [0x433e0a]
2024-07-31 12:42:32,568 our.server.internal proftpd[175401] our.server.internal (10.1.2.3[10.1.2.3]): [4] proftpd: [email protected]@ftps.remoteserver.com - (connecting): MLSD() [0x42191e]
2024-07-31 12:42:32,568 our.server.internal proftpd[175401] our.server.internal (10.1.2.3[10.1.2.3]): [5] proftpd: [email protected]@ftps.remoteserver.com - (connecting): MLSD() [0x45dde9]
2024-07-31 12:42:32,568 our.server.internal proftpd[175401] our.server.internal (10.1.2.3[10.1.2.3]): [6] proftpd: [email protected]@ftps.remoteserver.com - (connecting): MLSD(pr_session_disconnect+0x45) [0x45dfc5]
2024-07-31 12:42:32,568 our.server.internal proftpd[175401] our.server.internal (10.1.2.3[10.1.2.3]): [7] proftpd: [email protected]@ftps.remoteserver.com - (connecting): MLSD(pr_signals_handle+0x323) [0x42e263]
2024-07-31 12:42:32,568 our.server.internal proftpd[175401] our.server.internal (10.1.2.3[10.1.2.3]): [8] proftpd: [email protected]@ftps.remoteserver.com - (connecting): MLSD() [0x4b14be]
2024-07-31 12:42:32,568 our.server.internal proftpd[175401] our.server.internal (10.1.2.3[10.1.2.3]): [9] /lib64/libssl.so.3(+0x23608) [0x7f930d920608]
2024-07-31 12:42:32,568 our.server.internal proftpd[175401] our.server.internal (10.1.2.3[10.1.2.3]): [10] /lib64/libssl.so.3(+0x2e0a5) [0x7f930d92b0a5]
2024-07-31 12:42:32,568 our.server.internal proftpd[175401] our.server.internal (10.1.2.3[10.1.2.3]): [11] proftpd: [email protected]@ftps.remoteserver.com - (connecting): MLSD() [0x4b0989]
2024-07-31 12:42:32,568 our.server.internal proftpd[175401] our.server.internal (10.1.2.3[10.1.2.3]): [12] proftpd: [email protected]@ftps.remoteserver.com - (connecting): MLSD() [0x4b11ad]
2024-07-31 12:42:32,568 our.server.internal proftpd[175401] our.server.internal (10.1.2.3[10.1.2.3]): [13] proftpd: [email protected]@ftps.remoteserver.com - (connecting): MLSD(pr_netio_close+0x8a) [0x4418fa]
2024-07-31 12:42:32,568 our.server.internal proftpd[175400] our.server.internal: ROOT PRIVS at mod_delay.c:1943
2024-07-31 12:42:32,568 our.server.internal proftpd[175401] our.server.internal (10.1.2.3[10.1.2.3]): [14] proftpd: [email protected]@ftps.remoteserver.com - (connecting): MLSD() [0x433e76]
2024-07-31 12:42:32,568 our.server.internal proftpd[175401] our.server.internal (10.1.2.3[10.1.2.3]): [15] proftpd: [email protected]@ftps.remoteserver.com - (connecting): MLSD() [0x42191e]
2024-07-31 12:42:32,568 our.server.internal proftpd[175401] our.server.internal (10.1.2.3[10.1.2.3]): [16] proftpd: [email protected]@ftps.remoteserver.com - (connecting): MLSD() [0x45dde9]
2024-07-31 12:42:32,568 our.server.internal proftpd[175401] our.server.internal (10.1.2.3[10.1.2.3]): [17] proftpd: [email protected]@ftps.remoteserver.com - (connecting): MLSD(pr_session_disconnect+0x45) [0x45dfc5]
2024-07-31 12:42:32,568 our.server.internal proftpd[175401] our.server.internal (10.1.2.3[10.1.2.3]): [18] proftpd: [email protected]@ftps.remoteserver.com - (connecting): MLSD(pr_signals_handle+0x323) [0x42e263]
2024-07-31 12:42:32,568 our.server.internal proftpd[175400] our.server.internal: RELINQUISH PRIVS at mod_delay.c:1946
2024-07-31 12:42:32,568 our.server.internal proftpd[175401] our.server.internal (10.1.2.3[10.1.2.3]): [19] proftpd: [email protected]@ftps.remoteserver.com - (connecting): MLSD() [0x4254e4]
2024-07-31 12:42:32,568 our.server.internal proftpd[175401] our.server.internal (10.1.2.3[10.1.2.3]): [20] proftpd: [email protected]@ftps.remoteserver.com - (connecting): MLSD(pr_table_kget+0x3d) [0x4259bd]
2024-07-31 12:42:32,568 our.server.internal proftpd[175401] our.server.internal (10.1.2.3[10.1.2.3]): [21] proftpd: [email protected]@ftps.remoteserver.com - (connecting): MLSD(pr_trace_vmsg+0x8c) [0x45ed7c]
2024-07-31 12:42:32,568 our.server.internal proftpd[175401] our.server.internal (10.1.2.3[10.1.2.3]): [22] proftpd: [email protected]@ftps.remoteserver.com - (connecting): MLSD(pr_trace_msg+0xbe) [0x45f2ae]
2024-07-31 12:42:32,568 our.server.internal proftpd[175401] our.server.internal (10.1.2.3[10.1.2.3]): [23] proftpd: [email protected]@ftps.remoteserver.com - (connecting): MLSD() [0x42dafe]
2024-07-31 12:42:32,568 our.server.internal proftpd[175401] our.server.internal (10.1.2.3[10.1.2.3]): [24] /lib64/libc.so.6(+0x3e9a0) [0x7f930d25c9a0]
2024-07-31 12:42:32,568 our.server.internal proftpd[175401] our.server.internal (10.1.2.3[10.1.2.3]): [25] /lib64/libc.so.6(__connect+0x12) [0x7f930d3356f2]
2024-07-31 12:42:32,568 our.server.internal proftpd[175401] our.server.internal (10.1.2.3[10.1.2.3]): [26] proftpd: [email protected]@ftps.remoteserver.com - (connecting): MLSD(pr_inet_connect+0x89) [0x436079]
2024-07-31 12:42:32,568 our.server.internal proftpd[175401] our.server.internal (10.1.2.3[10.1.2.3]): [27] /usr/libexec/proftpd/mod_proxy.so(proxy_inet_connect+0x14a) [0x7f92ff79ebba]
2024-07-31 12:42:32,568 our.server.internal proftpd[175401] our.server.internal (10.1.2.3[10.1.2.3]): [28] /usr/libexec/proftpd/mod_proxy.so(proxy_ftp_conn_connect+0x178) [0x7f92ff7b2bc8]
2024-07-31 12:42:32,568 our.server.internal proftpd[175401] our.server.internal (10.1.2.3[10.1.2.3]): [29] /usr/libexec/proftpd/mod_proxy.so(+0x1f3d8) [0x7f92ff7953d8]
2024-07-31 12:42:32,568 our.server.internal proftpd[175401] our.server.internal (10.1.2.3[10.1.2.3]): [30] /usr/libexec/proftpd/mod_proxy.so(+0x208d9) [0x7f92ff7968d9]
2024-07-31 12:42:32,568 our.server.internal proftpd[175401] our.server.internal (10.1.2.3[10.1.2.3]): -----END STACK TRACE-----
2024-07-31 12:42:32,568 our.server.internal proftpd[175401] our.server.internal (10.1.2.3[10.1.2.3]): ProFTPD terminating (signal 11)
2024-07-31 12:42:32,568 our.server.internal proftpd[175401] our.server.internal (10.1.2.3[10.1.2.3]): FTP session closed.
2024-07-31 12:42:32,569 our.server.internal proftpd[175400] our.server.internal: RELINQUISH PRIVS at signals.c:85
2024-07-31 12:42:32,569 our.server.internal proftpd[175400] our.server.internal: ProFTPD 1.3.8b standalone mode SHUTDOWN
2024-07-31 12:42:32,569 our.server.internal proftpd[175400] our.server.internal: ROOT PRIVS at signals.c:92
2024-07-31 12:42:32,569 our.server.internal proftpd[175400] our.server.internal: deleting existing scoreboard '/run/proftpd/proftpd.scoreboard'
2024-07-31 12:42:32,569 our.server.internal proftpd[175401] our.server.internal (10.1.2.3[10.1.2.3]): ProFTPD terminating (signal 11)
2024-07-31 12:42:32,569 our.server.internal proftpd[175400] our.server.internal: RELINQUISH PRIVS at signals.c:94
2024-07-31 12:42:32,573 our.server.internal proftpd[175401] our.server.internal (10.1.2.3[10.1.2.3]): FTP session closed.

The timeout/hang results are the same whether using the default MLSD or configuring the proxy server to use LIST with the mod_proxy "ProxyDirectoryListPolicy LIST" option set.

PAamac avatar Jul 31 '24 19:07 PAamac

I see. Well, the segfault/backtrace there is certainly unexpected.

Would it be possible to see the full PASV response that the backend server is sending? In particular, I'd like to see the address/ports it is telling the client (mod_proxy, in this case) to connect to, for that MLSD directory listing data transfer?

Castaglia avatar Aug 01 '24 15:08 Castaglia

Would it be possible to see the full PASV response that the backend server is sending? In particular, I'd like to see the address/ports it is telling the client (mod_proxy, in this case) to connect to, for that MLSD directory listing data transfer?

For purposes of debugging this data transfer issue, I'd need to see the full/real PASV response from the backend server, and would need to know the IP address of the proxy. I realize that you may not want to provide that information in this GitHub ticket; feel free to just send it to me directly via email if that'd be better for you.

Castaglia avatar Aug 06 '24 00:08 Castaglia