Author Topic: CentOS7 w/ ProFTPd 1.3.5d hangs on dispatching CMD command 'AUTH SSL' to mod_tls  (Read 271 times)

Offline EwaldvanGeffen

  • New user
  • *
  • Posts: 2
    • View Profile
Code: [Select]
Apr 21 13:20:13 grid3 proftpd[43788]: using TCP receive buffer size of 87380 bytes
Apr 21 13:20:13 grid3 proftpd[43788]: using TCP send buffer size of 16384 bytes
Apr 21 13:20:13 grid3 proftpd[43788]: mod_tls/2.6: using OpenSSL 1.0.1e-fips 11 Feb 2013
Apr 21 13:20:13 grid3 proftpd[43788]: using 'UTF-8' as local charset for UTF-8 conversion
Apr 21 13:20:13 grid3 proftpd[43788]: <IfModule>: using 'mod_tls.c' section at line 19
Apr 21 13:20:13 grid3 proftpd[43788]: ROOT PRIVS at mod_tls.c:9064
Apr 21 13:20:13 grid3 proftpd[43788]: RELINQUISH PRIVS at mod_tls.c:9066
Apr 21 13:20:13 grid3 proftpd[43788]: ROOT PRIVS at mod_tls.c:9088
Apr 21 13:20:13 grid3 proftpd[43788]: RELINQUISH PRIVS at mod_tls.c:9090
Apr 21 13:20:13 grid3 proftpd[43788]: <Directory /var/www/vhosts>: adding section for resolved path '/var/www/vhosts'
Apr 21 13:20:13 grid3 proftpd[43788]: ROOT PRIVS at mod_core.c:341
Apr 21 13:20:13 grid3 proftpd[43788]: processing configuration directory '/etc/proftpd.d'
Apr 21 13:20:13 grid3 proftpd[43788]: ROOT PRIVS at dirtree.c:3368
Apr 21 13:20:13 grid3 proftpd[43788]: <IfModule>: using 'mod_tls.c' section at line 8
Apr 21 13:20:13 grid3 proftpd[43788]: RELINQUISH PRIVS at dirtree.c:3371
Apr 21 13:20:13 grid3 proftpd[43788]: ROOT PRIVS at dirtree.c:3368
Apr 21 13:20:13 grid3 proftpd[43788]: RELINQUISH PRIVS at dirtree.c:3371
Apr 21 13:20:13 grid3 proftpd[43788]: ROOT PRIVS at dirtree.c:3368
Apr 21 13:20:13 grid3 proftpd[43788]: <IfModule>: using 'mod_tls.c' section at line 1
Apr 21 13:20:13 grid3 proftpd[43788]: <IfModule>: using 'mod_tls.c' section at line 4
Apr 21 13:20:13 grid3 proftpd[43788]: RELINQUISH PRIVS at dirtree.c:3371
Apr 21 13:20:13 grid3 proftpd[43788]: RELINQUISH PRIVS at mod_core.c:365
Apr 21 13:20:13 grid3 proftpd[43788]: UseReverseDNS off, returning IP address instead of DNS name
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 - 0.0.0.0:21 masquerading as <server-ip>
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 -
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 - Config for ProFTPD:
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 - /var/www/vhosts
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 -  GroupOwner
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 -  UseFtpUsers
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 -  TimesGMT
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 -  Umask
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 -  TransferLog
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 -  TLSRequired
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 -  AllowOverwrite
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 - DefaultServer
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 - DefaultTransferMode
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 - UseFtpUsers
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 - TimesGMT
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 - SetEnv
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 - Umask
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 - TransferLog
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 - AuthPAM
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 - AuthPAMConfig
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 - IdentLookups
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 - AuthGroupFile
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 - MasqueradeAddress
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 - PassivePorts
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 - TLSCipherSuite
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 - TLSProtocol
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 - TLSEngine
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 - TLSRequired
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 - DefaultRoot
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 - AllowOverwrite
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 - TLSEngine
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 - TLSRequired
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 - TLSLog
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 - TLSRSACertificateFile
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 - TLSRSACertificateKeyFile
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 - TLSVerifyClient
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 - TLSRenegotiate
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 - TLSOptions
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 - mod_lang/1.0: unable to bind to text domain 'proftpd', lacking libintl support
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 - ROOT PRIVS at mod_tls.c:2142
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 - RELINQUISH PRIVS at mod_tls.c:2145
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 - ROOT PRIVS at mod_tls.c:2240
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 - mod_tls/2.6: passphrase locked into memory
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 - RELINQUISH PRIVS at mod_tls.c:2248
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 - ROOT PRIVS at mod_delay.c:441
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 - RELINQUISH PRIVS at mod_delay.c:444
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 - ROOT PRIVS at mod_rlimit.c:541
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 - RELINQUISH PRIVS at mod_rlimit.c:544
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 - set core resource limits for daemon
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 - SETUP PRIVS at main.c:3067
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 - ROOT PRIVS at main.c:2345
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 - opening scoreboard '/var/run/proftpd.scoreboard'
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 - RELINQUISH PRIVS at main.c:2374
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 - ROOT PRIVS at main.c:1227
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 - RELINQUISH PRIVS at main.c:1231
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 - no matching vhost found for <server-ip>#21, using 'ProFTPD' listening on wildcard address
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 (<client-ip>[<client-ip>]) - session requested from client in unknown class
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 (<client-ip>[<client-ip>]) - performing module session initializations
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 (<client-ip>[<client-ip>]) - mod_cap/1.1: adding CAP_AUDIT_WRITE capability
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 (<client-ip>[<client-ip>]) - ROOT PRIVS at mod_tls.c:7641
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 (<client-ip>[<client-ip>]) - RELINQUISH PRIVS at mod_tls.c:7644
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 (<client-ip>[<client-ip>]) - ROOT PRIVS at mod_tls.c:2271
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 (<client-ip>[<client-ip>]) - RELINQUISH PRIVS at mod_tls.c:2297
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 (<client-ip>[<client-ip>]) - mod_tls/2.6: supporting TLSv1, TLSv1.1, TLSv1.2 protocols
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 (<client-ip>[<client-ip>]) - ROOT PRIVS at mod_tls.c:3203
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 (<client-ip>[<client-ip>]) - RELINQUISH PRIVS at mod_tls.c:3722
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 (<client-ip>[<client-ip>]) - mod_ident/1.0: ident lookup disabled
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 (<client-ip>[<client-ip>]) - ROOT PRIVS at mod_delay.c:1756
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 (<client-ip>[<client-ip>]) - RELINQUISH PRIVS at mod_delay.c:1759
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 (<client-ip>[<client-ip>]) - ROOT PRIVS at mod_auth.c:140
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 (<client-ip>[<client-ip>]) - opening scoreboard '/var/run/proftpd.scoreboard'
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 (<client-ip>[<client-ip>]) - RELINQUISH PRIVS at mod_auth.c:142
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 (<client-ip>[<client-ip>]) - connected - local  : <server-ip>:21
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 (<client-ip>[<client-ip>]) - connected - remote : <client-ip>:25303
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 (<client-ip>[<client-ip>]) - FTP session opened.
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 (<client-ip>[<client-ip>]) - dispatching PRE_CMD command 'AUTH SSL' to mod_tls
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 (<client-ip>[<client-ip>]) - dispatching PRE_CMD command 'AUTH SSL' to mod_core
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 (<client-ip>[<client-ip>]) - dispatching PRE_CMD command 'AUTH SSL' to mod_core
Apr 21 13:20:13 grid3 proftpd[43788]: 0.0.0.0 (<client-ip>[<client-ip>]) - dispatching CMD command 'AUTH SSL' to mod_tls

Any ideas why the connection would stall there?

Offline castaglia

  • Administrator
  • Support Hero
  • *****
  • Posts: 5373
    • View Profile
    • http://www.castaglia.org/
As part of the handling of the AUTH SSL command, the mod_tls module performs the SSL handshake.  To help test what might be happening there, you might use this:

  $ openssl s_client -connect server:21 -starttls -debug

Also, what do you see on the FTPS client end, when this hang occurs?  What does the TLSLog file show?

Offline EwaldvanGeffen

  • New user
  • *
  • Posts: 2
    • View Profile
Thought I should follow up. I figured out there's a TLS log-file and this shows the EOF error mentioned in your FAQ. I could only reproduce the problem behind client NAT. Is there any way to workaround this, like disabling the client NAT FTP helper modules?

Offline castaglia

  • Administrator
  • Support Hero
  • *****
  • Posts: 5373
    • View Profile
    • http://www.castaglia.org/
Sounds like the NAT device is interfering with the "start TLS" functionality; I think that disabling that NAT "helper" functionality will depend much on the specific NAT device (and software versions) in question.

 

sighted planning