Oct 04 10:46:07 [99354] : signals blocked Oct 04 10:46:07 [99354] : signals already blocked (block count = 1) Oct 04 10:46:07 [99354] : signals already unblocked (block count = 2) Oct 04 10:46:07 [99354] : signals already blocked (block count = 1) Oct 04 10:46:07 [99354] : signals already unblocked (block count = 2) Oct 04 10:46:07 [99354] : signals unblocked Oct 04 10:46:07 [99354] : no IP address found in netaddr cache for name '10.0.2.17' Oct 04 10:46:07 [99354] : verifying DNS name for IP address 10.0.2.17 via reverse DNS lookup Oct 04 10:46:07 [99354] : checking addresses associated with host 'Swordfish.ply.claimlynx.com' Oct 04 10:46:07 [99354] : using DNS name 'Swordfish.ply.claimlynx.com' for IP address '10.0.2.17' Oct 04 10:46:07 [99354] : stashed IP address '10.0.2.17' for name 'Swordfish.ply.claimlynx.com' in the netaddr cache Oct 04 10:46:07 [99354] : stashed IP address '10.0.2.17' for name '10.0.2.17' in the netaddr cache Oct 04 10:46:07 [99354] : added 'mod_auth_pam.c' to auth-only module list Oct 04 10:46:07 [99354] : signals blocked Oct 04 10:46:07 [99354] : signals already blocked (block count = 1) Oct 04 10:46:07 [99354] : signals already unblocked (block count = 2) Oct 04 10:46:07 [99354] : signals already blocked (block count = 1) Oct 04 10:46:07 [99354] : signals already unblocked (block count = 2) Oct 04 10:46:07 [99354] : signals unblocked Oct 04 10:46:07 [99354] : signals blocked Oct 04 10:46:07 [99354] : signals unblocked Oct 04 10:46:07 [99354] : signals blocked Oct 04 10:46:07 [99354] : signals unblocked Oct 04 10:46:07 [99354] : converting UTF-8 to local character set 'US-ASCII' Oct 04 10:46:07 [99354] : module 'tls' (0x5eb6c0) unregistering handler for event 'core.exit' Oct 04 10:46:07 [99354] : module 'dso' (0x5eb240) unregistering handler for event 'core.restart' Oct 04 10:46:07 [99354] : module 'delay' (0x5eade0) unregistering handler for event 'core.exit' Oct 04 10:46:07 [99354] : opening DelayTable '/var/run/proftpd.delay' Oct 04 10:46:07 [99354] : signals blocked Oct 04 10:46:07 [99354] : signals unblocked Oct 04 10:46:07 [99354] : using system open() for path '/var/run/proftpd.delay' Oct 04 10:46:07 [99354] : signals blocked Oct 04 10:46:07 [99354] : signals unblocked Oct 04 10:46:07 [99354] : added timer ID 1 ('TimeoutLogin', for module 'auth'), triggering in 300 seconds Oct 04 10:46:07 [99354] : signals blocked Oct 04 10:46:07 [99354] : signals unblocked Oct 04 10:46:07 [99354] : signals blocked Oct 04 10:46:07 [99354] : signals unblocked Oct 04 10:46:07 [99354] : module 'auth' (0x5e9e00) registering handler for event 'core.exit' (at 0x45bf50) Oct 04 10:46:07 [99354] : attempting to write-lock scoreboard fd 4 Oct 04 10:46:07 [99354] : write-lock of scoreboard fd 4 successful Oct 04 10:46:07 [99354] : signals blocked Oct 04 10:46:07 [99354] : signals unblocked Oct 04 10:46:07 [99354] : attempting to unlock scoreboard fd 4 Oct 04 10:46:07 [99354] : unlock of scoreboard fd 4 successful Oct 04 10:46:07 [99354] : attempting to write-lock scoreboard fd 4 entry, offset 32 Oct 04 10:46:07 [99354] : write-lock of scoreboard fd 4 entry, offset 32 succeeded Oct 04 10:46:07 [99354] : attempting to unlock scoreboard fd 4 entry, offset 32 Oct 04 10:46:07 [99354] : unlock of scoreboard fd 4 entry, offset 32 succeeded Oct 04 10:46:07 [99354] : attempting to read-lock scoreboard fd 4 Oct 04 10:46:07 [99354] : read-lock of scoreboard fd 4 successful Oct 04 10:46:07 [99354] : attempting to unlock scoreboard fd 4 Oct 04 10:46:07 [99354] : unlock of scoreboard fd 4 successful Oct 04 10:46:07 [99354] : attempting to read-lock scoreboard fd 4 Oct 04 10:46:07 [99354] : read-lock of scoreboard fd 4 successful Oct 04 10:46:07 [99354] : attempting to unlock scoreboard fd 4 Oct 04 10:46:07 [99354] : unlock of scoreboard fd 4 successful Oct 04 10:46:07 [99354] : module 'auth_unix' (0x5e97e0) registering handler for event 'core.exit' (at 0x453f60) Oct 04 10:46:07 [99354] : module 'xfer' (0x5e9080) registering handler for event 'core.exit' (at 0x44eb20) Oct 04 10:46:07 [99354] : module 'xfer' (0x5e9080) registering handler for event 'core.timeout-stalled' (at 0x44eab0) Oct 04 10:46:07 [99354] : module 'xfer' (0x5e9080) registering handler for event 'core.signal.USR2' (at 0x452d60) Oct 04 10:46:07 [99354] : added timer ID 2 ('TimeoutIdle', for module '[none]'), triggering in 600 seconds Oct 04 10:46:07 [99354] : setting SO_OOBINLINE for listening socket -1 Oct 04 10:46:07 [99354] : setting SO_OOBINLINE for reading socket 0 Oct 04 10:46:07 [99354] : setting SO_OOBINLINE for writing socket 1 Oct 04 10:46:07 [99354] : attempting to write-lock scoreboard fd 4 entry, offset 32 Oct 04 10:46:07 [99354] : write-lock of scoreboard fd 4 entry, offset 32 succeeded Oct 04 10:46:07 [99354] : attempting to unlock scoreboard fd 4 entry, offset 32 Oct 04 10:46:07 [99354] : unlock of scoreboard fd 4 entry, offset 32 succeeded Oct 04 10:46:07 [99354] : handling connection from SSH2 client 'OpenSSH_5.2' Oct 04 10:46:07 [99354] : checking client version 'OpenSSH_5.2' against regex '^OpenSSH-2\.0.*|^OpenSSH-2\.1.*|^OpenSSH_2\.1.*|^OpenSSH_2\.2.*|^OpenSSH_2\.3\.0.*' Oct 04 10:46:07 [99354] : client version 'OpenSSH_5.2' did not match regex '^OpenSSH-2\.0.*|^OpenSSH-2\.1.*|^OpenSSH_2\.1.*|^OpenSSH_2\.2.*|^OpenSSH_2\.3\.0.*' Oct 04 10:46:07 [99354] : checking client version 'OpenSSH_5.2' against regex '^OpenSSH_2\.3\..*|^OpenSSH_2\.5\.0p1.*|^OpenSSH_2\.5\.1p1.*|^OpenSSH_2\.5\.0.*|^OpenSSH_2\.5\.1.*|^OpenSSH_2\.5\.2.*|^OpenSSH_2\.5\.3.*' Oct 04 10:46:07 [99354] : client version 'OpenSSH_5.2' did not match regex '^OpenSSH_2\.3\..*|^OpenSSH_2\.5\.0p1.*|^OpenSSH_2\.5\.1p1.*|^OpenSSH_2\.5\.0.*|^OpenSSH_2\.5\.1.*|^OpenSSH_2\.5\.2.*|^OpenSSH_2\.5\.3.*' Oct 04 10:46:07 [99354] : checking client version 'OpenSSH_5.2' against regex '^OpenSSH.*' Oct 04 10:46:07 [99354] : client version 'OpenSSH_5.2' matched against regex '^OpenSSH.*' Oct 04 10:46:07 [99354] : checking client version 'OpenSSH_5.2' against SFTPClientMatch regex 'WS_FTP|edtFTPjPRO|WeOnlyDo' Oct 04 10:46:07 [99354] : client version 'OpenSSH_5.2' did not match SFTPClientMatch regex 'WS_FTP|edtFTPjPRO|WeOnlyDo' Oct 04 10:46:07 [99354] : unable to use 'none' cipher: Must be explicitly requested via SFTPCiphers Oct 04 10:46:07 [99354] : unable to use 'none' digest: Must be explicitly requested via SFTPDigests Oct 04 10:46:07 [99354] : sending KEXINIT message to client Oct 04 10:46:07 [99354] : sent SSH_MSG_KEXINIT (20) packet Oct 04 10:46:07 [99354] : attempting to write-lock scoreboard fd 4 entry, offset 32 Oct 04 10:46:07 [99354] : write-lock of scoreboard fd 4 entry, offset 32 succeeded Oct 04 10:46:07 [99354] : attempting to unlock scoreboard fd 4 entry, offset 32 Oct 04 10:46:07 [99354] : unlock of scoreboard fd 4 entry, offset 32 succeeded Oct 04 10:46:07 [99354] : attempting to write-lock scoreboard fd 4 entry, offset 32 Oct 04 10:46:07 [99354] : write-lock of scoreboard fd 4 entry, offset 32 succeeded Oct 04 10:46:07 [99354] : attempting to unlock scoreboard fd 4 entry, offset 32 Oct 04 10:46:07 [99354] : unlock of scoreboard fd 4 entry, offset 32 succeeded Oct 04 10:46:07 [99354] : SSH2 packet len = 788 bytes Oct 04 10:46:07 [99354] : SSH2 packet padding len = 8 bytes Oct 04 10:46:07 [99354] : SSH2 packet payload len = 779 bytes Oct 04 10:46:07 [99354] : SSH2 packet MAC len = 0 bytes Oct 04 10:46:07 [99354] : reset timer ID 2 ('TimeoutIdle', for module '[none]') Oct 04 10:46:07 [99354] : received SSH_MSG_KEXINIT (20) packet Oct 04 10:46:07 [99354] : reading KEXINIT message from client Oct 04 10:46:07 [99354] : first kex packet follows = false Oct 04 10:46:07 [99354] : decoded 'KEXINIT' into 'KEXINIT' Oct 04 10:46:07 [99354] : dispatching LOG_CMD command 'KEXINIT' to mod_log.c Oct 04 10:46:07 [99354] : determining shared algorithms for SSH session Oct 04 10:46:07 [99354] : client-sent key exchange algorithms: diffie-hellman-group-exchange-sha256,diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1 Oct 04 10:46:07 [99354] : client-sent host key algorithms: ssh-rsa,ssh-dss Oct 04 10:46:07 [99354] : client-sent client encryption algorithms: aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,rijndael-cbc@lysator.liu.se Oct 04 10:46:07 [99354] : client-sent server encryption algorithms: aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,rijndael-cbc@lysator.liu.se Oct 04 10:46:07 [99354] : client-sent client MAC algorithms: hmac-md5,hmac-sha1,umac-64@openssh.com,hmac-ripemd160,hmac-ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96 Oct 04 10:46:07 [99354] : client-sent server MAC algorithms: hmac-md5,hmac-sha1,umac-64@openssh.com,hmac-ripemd160,hmac-ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96 Oct 04 10:46:07 [99354] : client-sent client compression algorithms: none,zlib@openssh.com,zlib Oct 04 10:46:07 [99354] : client-sent server compression algorithms: none,zlib@openssh.com,zlib Oct 04 10:46:07 [99354] : client-sent client languages: Oct 04 10:46:07 [99354] : client-sent server languages: Oct 04 10:46:07 [99354] : attempting to write-lock scoreboard fd 4 entry, offset 32 Oct 04 10:46:07 [99354] : write-lock of scoreboard fd 4 entry, offset 32 succeeded Oct 04 10:46:07 [99354] : attempting to unlock scoreboard fd 4 entry, offset 32 Oct 04 10:46:07 [99354] : unlock of scoreboard fd 4 entry, offset 32 succeeded Oct 04 10:46:07 [99354] : attempting to write-lock scoreboard fd 4 entry, offset 32 Oct 04 10:46:07 [99354] : write-lock of scoreboard fd 4 entry, offset 32 succeeded Oct 04 10:46:07 [99354] : attempting to unlock scoreboard fd 4 entry, offset 32 Oct 04 10:46:07 [99354] : unlock of scoreboard fd 4 entry, offset 32 succeeded Oct 04 10:46:07 [99354] : SSH2 packet len = 20 bytes Oct 04 10:46:07 [99354] : SSH2 packet padding len = 6 bytes Oct 04 10:46:07 [99354] : SSH2 packet payload len = 13 bytes Oct 04 10:46:07 [99354] : SSH2 packet MAC len = 0 bytes Oct 04 10:46:07 [99354] : reset timer ID 2 ('TimeoutIdle', for module '[none]') Oct 04 10:46:07 [99354] : received SSH_MSG_KEX_DH_GEX_REQUEST (34) packet Oct 04 10:46:07 [99354] : reading DH_GEX_REQUEST message from client Oct 04 10:46:07 [99354] : decoded 'DH_GEX_REQUEST' into 'DH_GEX_REQUEST' Oct 04 10:46:07 [99354] : dispatching LOG_CMD command 'DH_GEX_REQUEST' to mod_log.c Oct 04 10:46:07 [99354] : using DH parameters from SFTPDHParamFile '/usr/local/etc/dhparams.pem' for group exchange Oct 04 10:46:07 [99354] : client requested min 1024, pref 1024, max 8192 sizes for DH group exchange, selected DH of 1024 bits Oct 04 10:46:07 [99354] : writing DH_GEX_GROUP message to client Oct 04 10:46:07 [99354] : sent SSH_MSG_KEX_DH_REPLY (31) packet Oct 04 10:46:07 [99354] : attempting to write-lock scoreboard fd 4 entry, offset 32 Oct 04 10:46:07 [99354] : write-lock of scoreboard fd 4 entry, offset 32 succeeded Oct 04 10:46:07 [99354] : attempting to unlock scoreboard fd 4 entry, offset 32 Oct 04 10:46:07 [99354] : unlock of scoreboard fd 4 entry, offset 32 succeeded Oct 04 10:46:07 [99354] : attempting to write-lock scoreboard fd 4 entry, offset 32 Oct 04 10:46:07 [99354] : write-lock of scoreboard fd 4 entry, offset 32 succeeded Oct 04 10:46:07 [99354] : attempting to unlock scoreboard fd 4 entry, offset 32 Oct 04 10:46:07 [99354] : unlock of scoreboard fd 4 entry, offset 32 succeeded Oct 04 10:46:07 [99354] : SSH2 packet len = 140 bytes Oct 04 10:46:07 [99354] : SSH2 packet padding len = 6 bytes Oct 04 10:46:07 [99354] : SSH2 packet payload len = 133 bytes Oct 04 10:46:07 [99354] : SSH2 packet MAC len = 0 bytes Oct 04 10:46:07 [99354] : reset timer ID 2 ('TimeoutIdle', for module '[none]') Oct 04 10:46:07 [99354] : received SSH_MSG_KEX_DH_GEX_INIT (32) packet Oct 04 10:46:07 [99354] : reading DH_GEX_INIT message from client Oct 04 10:46:07 [99354] : decoded 'DH_GEX_INIT' into 'DH_GEX_INIT' Oct 04 10:46:07 [99354] : dispatching LOG_CMD command 'DH_GEX_INIT' to mod_log.c Oct 04 10:46:07 [99354] : attempt #1 to create a good DH key Oct 04 10:46:07 [99354] : generating DH key Oct 04 10:46:07 [99354] : good DH public key: 526 bits set Oct 04 10:46:07 [99354] : computing DH key Oct 04 10:46:07 [99354] : writing DH_GEX_REPLY message to client Oct 04 10:46:07 [99354] : sent SSH_MSG_KEX_DH_GEX_REPLY (33) packet Oct 04 10:46:07 [99354] : sending NEWKEYS message to client Oct 04 10:46:07 [99354] : sent SSH_MSG_NEWKEYS (21) packet Oct 04 10:46:07 [99354] : reading NEWKEYS message from client Oct 04 10:46:07 [99354] : attempting to write-lock scoreboard fd 4 entry, offset 32 Oct 04 10:46:07 [99354] : write-lock of scoreboard fd 4 entry, offset 32 succeeded Oct 04 10:46:07 [99354] : attempting to unlock scoreboard fd 4 entry, offset 32 Oct 04 10:46:07 [99354] : unlock of scoreboard fd 4 entry, offset 32 succeeded Oct 04 10:46:07 [99354] : attempting to write-lock scoreboard fd 4 entry, offset 32 Oct 04 10:46:07 [99354] : write-lock of scoreboard fd 4 entry, offset 32 succeeded Oct 04 10:46:07 [99354] : attempting to unlock scoreboard fd 4 entry, offset 32 Oct 04 10:46:07 [99354] : unlock of scoreboard fd 4 entry, offset 32 succeeded Oct 04 10:46:07 [99354] : SSH2 packet len = 12 bytes Oct 04 10:46:07 [99354] : SSH2 packet padding len = 10 bytes Oct 04 10:46:07 [99354] : SSH2 packet payload len = 1 bytes Oct 04 10:46:07 [99354] : SSH2 packet MAC len = 0 bytes Oct 04 10:46:07 [99354] : reset timer ID 2 ('TimeoutIdle', for module '[none]') Oct 04 10:46:07 [99354] : received SSH_MSG_NEWKEYS (21) packet Oct 04 10:46:07 [99354] : decoded 'NEWKEYS' into 'NEWKEYS' Oct 04 10:46:07 [99354] : dispatching LOG_CMD command 'NEWKEYS' to mod_log.c Oct 04 10:46:07 [99354] : setting session keys Oct 04 10:46:07 [99354] : added timer ID 1025 ('SFTP KEX Rekey timer', for module 'sftp'), triggering in 3600 seconds Oct 04 10:46:07 [99354] : attempting to write-lock scoreboard fd 4 entry, offset 32 Oct 04 10:46:07 [99354] : write-lock of scoreboard fd 4 entry, offset 32 succeeded Oct 04 10:46:07 [99354] : attempting to unlock scoreboard fd 4 entry, offset 32 Oct 04 10:46:07 [99354] : unlock of scoreboard fd 4 entry, offset 32 succeeded Oct 04 10:46:07 [99354] : attempting to write-lock scoreboard fd 4 entry, offset 32 Oct 04 10:46:07 [99354] : write-lock of scoreboard fd 4 entry, offset 32 succeeded Oct 04 10:46:07 [99354] : attempting to unlock scoreboard fd 4 entry, offset 32 Oct 04 10:46:07 [99354] : unlock of scoreboard fd 4 entry, offset 32 succeeded Oct 04 10:46:08 [99354] : SSH2 packet len = 28 bytes Oct 04 10:46:08 [99354] : SSH2 packet padding len = 10 bytes Oct 04 10:46:08 [99354] : SSH2 packet payload len = 17 bytes Oct 04 10:46:08 [99354] : SSH2 packet MAC len = 16 bytes Oct 04 10:46:08 [99354] : reset timer ID 2 ('TimeoutIdle', for module '[none]') Oct 04 10:46:08 [99354] : received SSH_MSG_SERVICE_REQUEST (5) packet Oct 04 10:46:08 [99354] : 'ssh-userauth' service requested Oct 04 10:46:08 [99354] : decoded 'SERVICE_REQUEST' into 'SERVICE_REQUEST' Oct 04 10:46:08 [99354] : dispatching LOG_CMD command 'SERVICE_REQUEST' to mod_log.c Oct 04 10:46:08 [99354] : sent SSH_MSG_SERVICE_ACCEPT (6) packet Oct 04 10:46:08 [99354] : attempting to write-lock scoreboard fd 4 entry, offset 32 Oct 04 10:46:08 [99354] : write-lock of scoreboard fd 4 entry, offset 32 succeeded Oct 04 10:46:08 [99354] : attempting to unlock scoreboard fd 4 entry, offset 32 Oct 04 10:46:08 [99354] : unlock of scoreboard fd 4 entry, offset 32 succeeded Oct 04 10:46:08 [99354] : attempting to write-lock scoreboard fd 4 entry, offset 32 Oct 04 10:46:08 [99354] : write-lock of scoreboard fd 4 entry, offset 32 succeeded Oct 04 10:46:08 [99354] : attempting to unlock scoreboard fd 4 entry, offset 32 Oct 04 10:46:08 [99354] : unlock of scoreboard fd 4 entry, offset 32 succeeded Oct 04 10:46:08 [99354] : SSH2 packet len = 44 bytes Oct 04 10:46:08 [99354] : SSH2 packet padding len = 4 bytes Oct 04 10:46:08 [99354] : SSH2 packet payload len = 39 bytes Oct 04 10:46:08 [99354] : SSH2 packet MAC len = 16 bytes Oct 04 10:46:08 [99354] : reset timer ID 2 ('TimeoutIdle', for module '[none]') Oct 04 10:46:08 [99354] : received SSH_MSG_USER_AUTH_REQUEST (50) packet Oct 04 10:46:08 [99354] : decoded 'USER' into 'USER' Oct 04 10:46:08 [99354] : decoded 'testuser' into 'testuser' Oct 04 10:46:08 [99354] : dispatching PRE_CMD command 'USER testuser' to mod_tls.c Oct 04 10:46:08 [99354] : dispatching PRE_CMD command 'USER testuser' to mod_rewrite.c Oct 04 10:46:08 [99354] : dispatching PRE_CMD command 'USER testuser' to mod_core.c Oct 04 10:46:08 [99354] : dispatching PRE_CMD command 'USER testuser' to mod_core.c Oct 04 10:46:08 [99354] : dispatching PRE_CMD command 'USER testuser' to mod_delay.c Oct 04 10:46:08 [99354] : dispatching PRE_CMD command 'USER testuser' to mod_auth.c Oct 04 10:46:08 [99354] : dispatching auth request "endpwent" to module mod_ldap Oct 04 10:46:08 [99354] : dispatching auth request "endgrent" to module mod_ldap Oct 04 10:46:08 [99354] : dispatching POST_CMD command 'USER testuser' to mod_delay.c Oct 04 10:46:08 [99354] : mapping DelayTable '/var/run/proftpd.delay' (63040 bytes, fd 3) into memory Oct 04 10:46:08 [99354] : write-locking DelayTable '/var/run/proftpd.delay', row 5 Oct 04 10:46:08 [99354] : interval between connect and USER command: 92 usecs Oct 04 10:46:08 [99354] : selecting median interval from 256 values Oct 04 10:46:08 [99354] : selected median interval of 113 usecs Oct 04 10:46:08 [99354] : adding 92 usecs to USER row Oct 04 10:46:08 [99354] : unlocking DelayTable '/var/run/proftpd.delay', row 5 Oct 04 10:46:08 [99354] : unmapping DelayTable '/var/run/proftpd.delay' from memory Oct 04 10:46:08 [99354] : interval (92 usecs) less than selected median (113 usecs), delaying Oct 04 10:46:08 [99354] : additional random delay of 1 usecs added Oct 04 10:46:08 [99354] : delaying for 22 usecs Oct 04 10:46:08 [99354] : dispatching LOG_CMD command 'USER testuser' to mod_log.c Oct 04 10:46:08 [99354] : auth requested for user 'testuser', service 'ssh-connection', using method 'none' Oct 04 10:46:08 [99354] : no SFTPAuthorizedUserKeys configured, not offering 'publickey' authentication Oct 04 10:46:08 [99354] : no SFTPAuthorizedHostKeys configured, not offering 'hostbased' authentication Oct 04 10:46:08 [99354] : no kbdint drivers present, not offering 'keyboard-interactive' authentication Oct 04 10:46:08 [99354] : offering authentication methods: password Oct 04 10:46:08 [99354] : decoded 'PASS' into 'PASS' Oct 04 10:46:08 [99354] : decoded '(hidden)' into '(hidden)' Oct 04 10:46:08 [99354] : dispatching PRE_CMD command 'PASS (hidden)' to mod_tls.c Oct 04 10:46:08 [99354] : dispatching PRE_CMD command 'PASS (hidden)' to mod_rewrite.c Oct 04 10:46:08 [99354] : dispatching PRE_CMD command 'PASS (hidden)' to mod_core.c Oct 04 10:46:08 [99354] : dispatching PRE_CMD command 'PASS (hidden)' to mod_core.c Oct 04 10:46:08 [99354] : dispatching PRE_CMD command 'PASS (hidden)' to mod_radius.c Oct 04 10:46:08 [99354] : dispatching PRE_CMD command 'PASS (hidden)' to mod_wrap2.c Oct 04 10:46:08 [99354] : dispatching PRE_CMD command 'PASS (hidden)' to mod_delay.c Oct 04 10:46:08 [99354] : dispatching PRE_CMD command 'PASS (hidden)' to mod_auth.c Oct 04 10:46:08 [99354] : dispatching auth request "endpwent" to module mod_ldap Oct 04 10:46:08 [99354] : dispatching auth request "endgrent" to module mod_ldap Oct 04 10:46:08 [99354] : sent SSH_MSG_USER_AUTH_FAILURE (51) packet Oct 04 10:46:08 [99354] : decoded 'USERAUTH_REQUEST' into 'USERAUTH_REQUEST' Oct 04 10:46:08 [99354] : dispatching LOG_CMD command 'USERAUTH_REQUEST' to mod_log.c Oct 04 10:46:08 [99354] : attempting to write-lock scoreboard fd 4 entry, offset 32 Oct 04 10:46:08 [99354] : write-lock of scoreboard fd 4 entry, offset 32 succeeded Oct 04 10:46:08 [99354] : attempting to unlock scoreboard fd 4 entry, offset 32 Oct 04 10:46:08 [99354] : unlock of scoreboard fd 4 entry, offset 32 succeeded Oct 04 10:46:08 [99354] : attempting to write-lock scoreboard fd 4 entry, offset 32 Oct 04 10:46:08 [99354] : write-lock of scoreboard fd 4 entry, offset 32 succeeded Oct 04 10:46:08 [99354] : attempting to unlock scoreboard fd 4 entry, offset 32 Oct 04 10:46:08 [99354] : unlock of scoreboard fd 4 entry, offset 32 succeeded Oct 04 10:46:10 [99354] : SSH2 packet len = 124 bytes Oct 04 10:46:10 [99354] : SSH2 packet padding len = 69 bytes Oct 04 10:46:10 [99354] : SSH2 packet payload len = 54 bytes Oct 04 10:46:10 [99354] : SSH2 packet MAC len = 16 bytes Oct 04 10:46:10 [99354] : reset timer ID 2 ('TimeoutIdle', for module '[none]') Oct 04 10:46:10 [99354] : received SSH_MSG_USER_AUTH_REQUEST (50) packet Oct 04 10:46:10 [99354] : decoded 'USER' into 'USER' Oct 04 10:46:10 [99354] : decoded 'testuser' into 'testuser' Oct 04 10:46:10 [99354] : dispatching PRE_CMD command 'USER testuser' to mod_tls.c Oct 04 10:46:10 [99354] : dispatching PRE_CMD command 'USER testuser' to mod_rewrite.c Oct 04 10:46:10 [99354] : dispatching PRE_CMD command 'USER testuser' to mod_core.c Oct 04 10:46:10 [99354] : dispatching PRE_CMD command 'USER testuser' to mod_core.c Oct 04 10:46:10 [99354] : dispatching PRE_CMD command 'USER testuser' to mod_delay.c Oct 04 10:46:10 [99354] : dispatching PRE_CMD command 'USER testuser' to mod_auth.c Oct 04 10:46:10 [99354] : dispatching auth request "endpwent" to module mod_ldap Oct 04 10:46:10 [99354] : dispatching auth request "endgrent" to module mod_ldap Oct 04 10:46:10 [99354] : dispatching POST_CMD command 'USER testuser' to mod_delay.c Oct 04 10:46:10 [99354] : mapping DelayTable '/var/run/proftpd.delay' (63040 bytes, fd 3) into memory Oct 04 10:46:10 [99354] : write-locking DelayTable '/var/run/proftpd.delay', row 5 Oct 04 10:46:10 [99354] : interval between connect and USER command: 94 usecs Oct 04 10:46:10 [99354] : selecting median interval from 256 values Oct 04 10:46:10 [99354] : selected median interval of 95 usecs Oct 04 10:46:10 [99354] : adding 94 usecs to USER row Oct 04 10:46:10 [99354] : unlocking DelayTable '/var/run/proftpd.delay', row 5 Oct 04 10:46:10 [99354] : unmapping DelayTable '/var/run/proftpd.delay' from memory Oct 04 10:46:10 [99354] : interval (94 usecs) less than selected median (95 usecs), delaying Oct 04 10:46:10 [99354] : additional random delay of 0 usecs added Oct 04 10:46:10 [99354] : delaying for 1 usecs Oct 04 10:46:10 [99354] : dispatching LOG_CMD command 'USER testuser' to mod_log.c Oct 04 10:46:10 [99354] : auth requested for user 'testuser', service 'ssh-connection', using method 'password' Oct 04 10:46:10 [99354] : decoded 'PASS' into 'PASS' Oct 04 10:46:10 [99354] : decoded '(hidden)' into '(hidden)' Oct 04 10:46:10 [99354] : dispatching PRE_CMD command 'PASS (hidden)' to mod_tls.c Oct 04 10:46:10 [99354] : dispatching PRE_CMD command 'PASS (hidden)' to mod_rewrite.c Oct 04 10:46:10 [99354] : dispatching PRE_CMD command 'PASS (hidden)' to mod_core.c Oct 04 10:46:10 [99354] : dispatching PRE_CMD command 'PASS (hidden)' to mod_core.c Oct 04 10:46:10 [99354] : dispatching PRE_CMD command 'PASS (hidden)' to mod_radius.c Oct 04 10:46:10 [99354] : dispatching PRE_CMD command 'PASS (hidden)' to mod_wrap2.c Oct 04 10:46:10 [99354] : dispatching PRE_CMD command 'PASS (hidden)' to mod_delay.c Oct 04 10:46:10 [99354] : dispatching PRE_CMD command 'PASS (hidden)' to mod_auth.c Oct 04 10:46:10 [99354] : dispatching auth request "endpwent" to module mod_ldap Oct 04 10:46:10 [99354] : dispatching auth request "endgrent" to module mod_ldap Oct 04 10:46:10 [99354] : dispatching auth request "getpwnam" to module mod_ldap Oct 04 10:46:11 [99354] : stashed module 'mod_ldap.c' for user 'testuser' in the authcache Oct 04 10:46:11 [99354] : stashed name 'testuser' for UID 700 in the uidcache Oct 04 10:46:11 [99354] : checking with auth-only module 'mod_auth_pam.c' Oct 04 10:46:11 [99354] : using module 'mod_ldap.c' from authcache to authenticate user 'testuser' Oct 04 10:46:11 [99354] : dispatching auth request "auth" to module mod_ldap Oct 04 10:46:11 [99354] : using module 'mod_ldap.c' from authcache to authenticate user 'testuser' Oct 04 10:46:11 [99354] : dispatching auth request "check" to module mod_ldap Oct 04 10:46:11 [99354] : dispatching auth request "getpwnam" to module mod_ldap Oct 04 10:46:11 [99354] : stashed module 'mod_ldap.c' for user 'testuser' in the authcache Oct 04 10:46:11 [99354] : signals blocked Oct 04 10:46:11 [99354] : signals unblocked Oct 04 10:46:11 [99354] : signals blocked Oct 04 10:46:11 [99354] : signals unblocked Oct 04 10:46:11 [99354] : no value found in gidcache for GID 700: No such file or directory Oct 04 10:46:11 [99354] : dispatching auth request "gid2name" to module mod_ldap Oct 04 10:46:11 [99354] : dispatching auth request "getgroups" to module mod_ldap Oct 04 10:46:11 [99354] : signals blocked Oct 04 10:46:11 [99354] : signals unblocked Oct 04 10:46:11 [99354] : signals blocked Oct 04 10:46:11 [99354] : signals unblocked Oct 04 10:46:11 [99354] : signals blocked Oct 04 10:46:11 [99354] : signals unblocked Oct 04 10:46:11 [99354] : using system stat() for path '/home/testuser' Oct 04 10:46:11 [99354] : signals blocked Oct 04 10:46:11 [99354] : signals unblocked Oct 04 10:46:11 [99354] : signals blocked Oct 04 10:46:11 [99354] : signals unblocked Oct 04 10:46:11 [99354] : signals blocked Oct 04 10:46:11 [99354] : signals unblocked Oct 04 10:46:11 [99354] : signals blocked Oct 04 10:46:11 [99354] : signals unblocked Oct 04 10:46:11 [99354] : dispatching auth request "getpwnam" to module mod_ldap Oct 04 10:46:11 [99354] : stashed module 'mod_ldap.c' for user 'testuser' in the authcache Oct 04 10:46:11 [99354] : signals blocked Oct 04 10:46:11 [99354] : signals unblocked Oct 04 10:46:11 [99354] : dispatching auth request "setpwent" to module mod_ldap Oct 04 10:46:11 [99354] : dispatching auth request "setgrent" to module mod_ldap Oct 04 10:46:11 [99354] : signals blocked Oct 04 10:46:11 [99354] : signals unblocked Oct 04 10:46:11 [99354] : using system chroot() for path '/home/testuser' Oct 04 10:46:11 [99354] : signals blocked Oct 04 10:46:11 [99354] : signals unblocked Oct 04 10:46:11 [99354] : signals blocked Oct 04 10:46:11 [99354] : signals already blocked (block count = 1) Oct 04 10:46:11 [99354] : signals already unblocked (block count = 2) Oct 04 10:46:11 [99354] : signals already blocked (block count = 1) Oct 04 10:46:11 [99354] : signals already unblocked (block count = 2) Oct 04 10:46:11 [99354] : signals unblocked Oct 04 10:46:11 [99354] : signals blocked Oct 04 10:46:11 [99354] : signals unblocked Oct 04 10:46:11 [99354] : using system chdir() for path '/' Oct 04 10:46:11 [99354] : using system stat() for path '/' Oct 04 10:46:11 [99354] : using system stat() for path '/.ftpaccess' Oct 04 10:46:11 [99354] : using system stat() for path '/.ftpaccess' Oct 04 10:46:11 [99354] : using system stat() for path '/' Oct 04 10:46:11 [99354] : using system stat() for path '/.ftpaccess' Oct 04 10:46:11 [99354] : using system stat() for path '/.ftpaccess' Oct 04 10:46:11 [99354] : attempting to write-lock scoreboard fd 4 entry, offset 32 Oct 04 10:46:11 [99354] : write-lock of scoreboard fd 4 entry, offset 32 succeeded Oct 04 10:46:11 [99354] : attempting to unlock scoreboard fd 4 entry, offset 32 Oct 04 10:46:11 [99354] : unlock of scoreboard fd 4 entry, offset 32 succeeded Oct 04 10:46:11 [99354] : removed timer ID 1 ('TimeoutLogin', for module 'auth') Oct 04 10:46:11 [99354] : sent SSH_MSG_USER_AUTH_SUCCESS (52) packet Oct 04 10:46:11 [99354] : decoded 'USERAUTH_REQUEST' into 'USERAUTH_REQUEST' Oct 04 10:46:11 [99354] : dispatching LOG_CMD command 'USERAUTH_REQUEST' to mod_log.c Oct 04 10:46:11 [99354] : dispatching POST_CMD command 'PASS (hidden)' to mod_ifsession.c Oct 04 10:46:11 [99354] : dispatching POST_CMD command 'PASS (hidden)' to mod_tls.c Oct 04 10:46:11 [99354] : dispatching POST_CMD command 'PASS (hidden)' to mod_radius.c Oct 04 10:46:11 [99354] : dispatching POST_CMD command 'PASS (hidden)' to mod_wrap2.c Oct 04 10:46:11 [99354] : dispatching POST_CMD command 'PASS (hidden)' to mod_readme.c Oct 04 10:46:11 [99354] : dispatching POST_CMD command 'PASS (hidden)' to mod_ratio.c Oct 04 10:46:11 [99354] : dispatching POST_CMD command 'PASS (hidden)' to mod_delay.c Oct 04 10:46:11 [99354] : mapping DelayTable '/var/run/proftpd.delay' (63040 bytes, fd 3) into memory Oct 04 10:46:11 [99354] : write-locking DelayTable '/var/run/proftpd.delay', row 6 Oct 04 10:46:11 [99354] : interval between USER and PASS commands: 30304 usecs Oct 04 10:46:11 [99354] : selecting median interval from 67 values Oct 04 10:46:11 [99354] : selected median interval of 29216 usecs Oct 04 10:46:11 [99354] : adding 30304 usecs to PASS row Oct 04 10:46:11 [99354] : unlocking DelayTable '/var/run/proftpd.delay', row 6 Oct 04 10:46:11 [99354] : unmapping DelayTable '/var/run/proftpd.delay' from memory Oct 04 10:46:11 [99354] : dispatching POST_CMD command 'PASS (hidden)' to mod_log.c Oct 04 10:46:11 [99354] : dispatching POST_CMD command 'PASS (hidden)' to mod_ls.c Oct 04 10:46:11 [99354] : dispatching POST_CMD command 'PASS (hidden)' to mod_auth.c Oct 04 10:46:11 [99354] : cleared auth-only module list Oct 04 10:46:11 [99354] : attempting to read-lock scoreboard fd 4 Oct 04 10:46:11 [99354] : read-lock of scoreboard fd 4 successful Oct 04 10:46:11 [99354] : attempting to unlock scoreboard fd 4 Oct 04 10:46:11 [99354] : unlock of scoreboard fd 4 successful Oct 04 10:46:11 [99354] : attempting to read-lock scoreboard fd 4 Oct 04 10:46:11 [99354] : read-lock of scoreboard fd 4 successful Oct 04 10:46:11 [99354] : attempting to unlock scoreboard fd 4 Oct 04 10:46:11 [99354] : unlock of scoreboard fd 4 successful Oct 04 10:46:11 [99354] : using system stat() for path '/' Oct 04 10:46:11 [99354] : using system stat() for path '/.ftpaccess' Oct 04 10:46:11 [99354] : using system stat() for path '/.ftpaccess' Oct 04 10:46:11 [99354] : dispatching POST_CMD command 'PASS (hidden)' to mod_xfer.c Oct 04 10:46:11 [99354] : dispatching POST_CMD command 'PASS (hidden)' to mod_core.c Oct 04 10:46:11 [99354] : clearing response lists before dispatching command 'PASS' Oct 04 10:46:11 [99354] : dispatching LOG_CMD command 'PASS (hidden)' to mod_log.c Oct 04 10:46:11 [99354] : dispatching LOG_CMD command 'PASS (hidden)' to mod_ratio.c Oct 04 10:46:11 [99354] : dispatching LOG_CMD command 'PASS (hidden)' to mod_auth.c Oct 04 10:46:11 [99354] : attempting to write-lock scoreboard fd 4 entry, offset 32 Oct 04 10:46:11 [99354] : write-lock of scoreboard fd 4 entry, offset 32 succeeded Oct 04 10:46:11 [99354] : attempting to unlock scoreboard fd 4 entry, offset 32 Oct 04 10:46:11 [99354] : unlock of scoreboard fd 4 entry, offset 32 succeeded Oct 04 10:46:11 [99354] : attempting to write-lock scoreboard fd 4 entry, offset 32 Oct 04 10:46:11 [99354] : write-lock of scoreboard fd 4 entry, offset 32 succeeded Oct 04 10:46:11 [99354] : attempting to unlock scoreboard fd 4 entry, offset 32 Oct 04 10:46:11 [99354] : unlock of scoreboard fd 4 entry, offset 32 succeeded Oct 04 10:46:11 [99354] : SSH2 packet len = 44 bytes Oct 04 10:46:11 [99354] : SSH2 packet padding len = 19 bytes Oct 04 10:46:11 [99354] : SSH2 packet payload len = 24 bytes Oct 04 10:46:11 [99354] : SSH2 packet MAC len = 16 bytes Oct 04 10:46:11 [99354] : reset timer ID 2 ('TimeoutIdle', for module '[none]') Oct 04 10:46:11 [99354] : received SSH_MSG_CHANNEL_OPEN (90) packet Oct 04 10:46:11 [99354] : open of 'session' channel using remote ID 0 requested: initial client window len = 1048576 bytes, client max packet size = 16384 bytes Oct 04 10:46:11 [99354] : decoded 'CHANNEL_OPEN' into 'CHANNEL_OPEN' Oct 04 10:46:11 [99354] : dispatching LOG_CMD command 'CHANNEL_OPEN' to mod_log.c Oct 04 10:46:11 [99354] : confirm open channel remote ID 0, local ID 0: initial server window len = 4294967295 bytes, server max packet size = 32768 bytes Oct 04 10:46:11 [99354] : sent SSH_MSG_CHANNEL_OPEN_CONFIRMATION (91) packet Oct 04 10:46:11 [99354] : attempting to write-lock scoreboard fd 4 entry, offset 32 Oct 04 10:46:11 [99354] : write-lock of scoreboard fd 4 entry, offset 32 succeeded Oct 04 10:46:11 [99354] : attempting to unlock scoreboard fd 4 entry, offset 32 Oct 04 10:46:11 [99354] : unlock of scoreboard fd 4 entry, offset 32 succeeded Oct 04 10:46:11 [99354] : attempting to write-lock scoreboard fd 4 entry, offset 32 Oct 04 10:46:11 [99354] : write-lock of scoreboard fd 4 entry, offset 32 succeeded Oct 04 10:46:11 [99354] : attempting to unlock scoreboard fd 4 entry, offset 32 Oct 04 10:46:11 [99354] : unlock of scoreboard fd 4 entry, offset 32 succeeded Oct 04 10:46:11 [99354] : SSH2 packet len = 44 bytes Oct 04 10:46:11 [99354] : SSH2 packet padding len = 7 bytes Oct 04 10:46:11 [99354] : SSH2 packet payload len = 36 bytes Oct 04 10:46:11 [99354] : SSH2 packet MAC len = 16 bytes Oct 04 10:46:11 [99354] : reset timer ID 2 ('TimeoutIdle', for module '[none]') Oct 04 10:46:11 [99354] : received SSH_MSG_CHANNEL_REQUEST (98) packet Oct 04 10:46:11 [99354] : received 'auth-agent-req@openssh.com' request for channel ID 0, want reply = false Oct 04 10:46:11 [99354] : decoded 'CHANNEL_REQUEST' into 'CHANNEL_REQUEST' Oct 04 10:46:11 [99354] : dispatching LOG_CMD command 'CHANNEL_REQUEST' to mod_log.c Oct 04 10:46:11 [99354] : attempting to write-lock scoreboard fd 4 entry, offset 32 Oct 04 10:46:11 [99354] : write-lock of scoreboard fd 4 entry, offset 32 succeeded Oct 04 10:46:11 [99354] : attempting to unlock scoreboard fd 4 entry, offset 32 Oct 04 10:46:11 [99354] : unlock of scoreboard fd 4 entry, offset 32 succeeded Oct 04 10:46:11 [99354] : attempting to write-lock scoreboard fd 4 entry, offset 32 Oct 04 10:46:11 [99354] : write-lock of scoreboard fd 4 entry, offset 32 succeeded Oct 04 10:46:11 [99354] : attempting to unlock scoreboard fd 4 entry, offset 32 Oct 04 10:46:11 [99354] : unlock of scoreboard fd 4 entry, offset 32 succeeded Oct 04 10:46:11 [99354] : SSH2 packet len = 316 bytes Oct 04 10:46:11 [99354] : SSH2 packet padding len = 12 bytes Oct 04 10:46:11 [99354] : SSH2 packet payload len = 303 bytes Oct 04 10:46:11 [99354] : SSH2 packet MAC len = 16 bytes Oct 04 10:46:11 [99354] : reset timer ID 2 ('TimeoutIdle', for module '[none]') Oct 04 10:46:11 [99354] : received SSH_MSG_CHANNEL_REQUEST (98) packet Oct 04 10:46:11 [99354] : received 'pty-req' request for channel ID 0, want reply = true Oct 04 10:46:11 [99354] : sent SSH_MSG_CHANNEL_FAILURE (100) packet Oct 04 10:46:11 [99354] : decoded 'CHANNEL_REQUEST' into 'CHANNEL_REQUEST' Oct 04 10:46:11 [99354] : dispatching LOG_CMD command 'CHANNEL_REQUEST' to mod_log.c Oct 04 10:46:11 [99354] : attempting to write-lock scoreboard fd 4 entry, offset 32 Oct 04 10:46:11 [99354] : write-lock of scoreboard fd 4 entry, offset 32 succeeded Oct 04 10:46:11 [99354] : attempting to unlock scoreboard fd 4 entry, offset 32 Oct 04 10:46:11 [99354] : unlock of scoreboard fd 4 entry, offset 32 succeeded Oct 04 10:46:11 [99354] : attempting to write-lock scoreboard fd 4 entry, offset 32 Oct 04 10:46:11 [99354] : write-lock of scoreboard fd 4 entry, offset 32 succeeded Oct 04 10:46:11 [99354] : attempting to unlock scoreboard fd 4 entry, offset 32 Oct 04 10:46:11 [99354] : unlock of scoreboard fd 4 entry, offset 32 succeeded Oct 04 10:46:11 [99354] : SSH2 packet len = 28 bytes Oct 04 10:46:11 [99354] : SSH2 packet padding len = 12 bytes Oct 04 10:46:11 [99354] : SSH2 packet payload len = 15 bytes Oct 04 10:46:11 [99354] : SSH2 packet MAC len = 16 bytes Oct 04 10:46:11 [99354] : reset timer ID 2 ('TimeoutIdle', for module '[none]') Oct 04 10:46:11 [99354] : received SSH_MSG_CHANNEL_REQUEST (98) packet Oct 04 10:46:11 [99354] : received 'shell' request for channel ID 0, want reply = true Oct 04 10:46:11 [99354] : sent SSH_MSG_CHANNEL_FAILURE (100) packet Oct 04 10:46:11 [99354] : decoded 'CHANNEL_REQUEST' into 'CHANNEL_REQUEST' Oct 04 10:46:11 [99354] : dispatching LOG_CMD command 'CHANNEL_REQUEST' to mod_log.c Oct 04 10:46:11 [99354] : attempting to write-lock scoreboard fd 4 entry, offset 32 Oct 04 10:46:11 [99354] : write-lock of scoreboard fd 4 entry, offset 32 succeeded Oct 04 10:46:11 [99354] : attempting to unlock scoreboard fd 4 entry, offset 32 Oct 04 10:46:11 [99354] : unlock of scoreboard fd 4 entry, offset 32 succeeded Oct 04 10:46:11 [99354] : attempting to write-lock scoreboard fd 4 entry, offset 32 Oct 04 10:46:11 [99354] : write-lock of scoreboard fd 4 entry, offset 32 succeeded Oct 04 10:46:11 [99354] : attempting to unlock scoreboard fd 4 entry, offset 32 Oct 04 10:46:11 [99354] : unlock of scoreboard fd 4 entry, offset 32 succeeded Oct 04 10:46:11 [99354] : attempting to write-lock scoreboard fd 4 entry, offset 32 Oct 04 10:46:11 [99354] : write-lock of scoreboard fd 4 entry, offset 32 succeeded Oct 04 10:46:11 [99354] : attempting to unlock scoreboard fd 4 entry, offset 32 Oct 04 10:46:11 [99354] : unlock of scoreboard fd 4 entry, offset 32 succeeded Oct 04 10:46:11 [99354] : dispatching event 'core.exit' to core (at 0x41e470) Oct 04 10:46:11 [99354] : dispatching event 'core.exit' to mod_sftp (at 0x48d330) Oct 04 10:46:11 [99354] : destroying unclosed channel ID 0 (0 bytes pending) Oct 04 10:46:11 [99354] : dispatching event 'core.exit' to mod_auth (at 0x45bf50) Oct 04 10:46:11 [99354] : dispatching event 'core.exit' to mod_auth_unix (at 0x453f60) Oct 04 10:46:11 [99354] : dispatching auth request "endpwent" to module mod_ldap Oct 04 10:46:11 [99354] : emptying authcache Oct 04 10:46:11 [99354] : dispatching auth request "endgrent" to module mod_ldap Oct 04 10:46:11 [99354] : dispatching event 'core.exit' to mod_xfer (at 0x44eb20)