in reply to Net::SFTP::Foreign works intermittently

Password authentication is failing.

Enable debugging, rerun your script and post here the output you get on a failed attempt: 

$Net::SFTP::Foreign::debug = -1;

[download]

Replies are listed 'Best First'.
Re^2: Net::SFTP::Foreign works intermittently
by Anonymous Monk on Jun 17, 2014 at 09:58 UTC

    Salva, I have replaced few paths with environment variables as per the company policies. Also, remote server IP, user name etc. have kept notations like sftp_user, remote_server etc. Please let me know if anything is not clear. I can elaborate on that. following is the output for the failed attempt :- 

    shell-init: error retrieving current directory: getcwd: cannot access 
+parent directories: No such file or directory
#5159 1402995021.00000 new: This is Net::SFTP::Foreign 1.77
#5159 1402995021.00000 new: Loaded from $PERL5LIB/Net/SFTP/Foreign.pm
#5159 1402995021.00000 new: Running on Perl v5.18.0 for linux
#5159 1402995021.00000 new: debug set to -1
#5159 1402995021.00000 new: ~0 is 18446744073709551615
#5159 1402995021.00000 new: Using backend Net::SFTP::Foreign::Backend:
+:Unix 1.76_03
#5159 1402995021.00000 _init_transport: ssh cmd: /usr/bin/ssh -p 22 -o
+ NumberOfPasswordPrompts=1 -o PreferredAuthentications=keyboard-inter
+active,password -l <sftp_user> -vvv -o StrictHostKeyChecking no <remo
+te_server> -s sftp

#5159 1402995021.00000 _init_transport: starting password authenticati
+on
#5159 1402995021.00000 _init_transport: checking timeout, max: 3600, e
+llapsed: 1.9073486328125e-05
#5159 1402995021.00000 _init_transport: waiting for data from the pty 
+to become available
OpenSSH_5.3p1, OpenSSL 1.0.0-fips 29 Mar 2010
debug1: Reading configuration data /etc/ssh/ssh_config
debug1: Applying options for *
debug2: ssh_connect: needpriv 0
debug1: Connecting to <remote_server> [<remote_server>] port 22.
debug1: Connection established.
debug1: identity file $HOME/.ssh/identity type -1
debug1: identity file $HOME/.ssh/id_rsa type -1
debug1: identity file $HOME/.ssh/id_dsa type -1
debug1: Remote protocol version 2.0, remote software version OpenSSH_5
+.3
debug1: match: OpenSSH_5.3 pat OpenSSH*
debug1: Enabling compatibility mode for protocol 2.0
debug1: Local version string SSH-2.0-OpenSSH_5.3
debug2: fd 3 setting O_NONBLOCK
debug1: SSH2_MSG_KEXINIT sent
debug3: Wrote 792 bytes for a total of 813
debug1: SSH2_MSG_KEXINIT received
debug2: kex_parse_kexinit: diffie-hellman-group-exchange-sha256,diffie
+-hellman-group-exchange-sha1,diffie-hellman-group14-sha1,diffie-hellm
+an-group1-sha1
debug2: kex_parse_kexinit: ssh-rsa,ssh-dss
debug2: kex_parse_kexinit: aes128-ctr,aes192-ctr,aes256-ctr,arcfour256
+,arcfour128,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,a
+es256-cbc,arcfour,rijndael-cbc@lysator.liu.se
debug2: kex_parse_kexinit: aes128-ctr,aes192-ctr,aes256-ctr,arcfour256
+,arcfour128,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,a
+es256-cbc,arcfour,rijndael-cbc@lysator.liu.se
debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,umac-64@openssh.com,hmac
+-ripemd160,hmac-ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96
debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,umac-64@openssh.com,hmac
+-ripemd160,hmac-ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96
debug2: kex_parse_kexinit: none,zlib@openssh.com,zlib
debug2: kex_parse_kexinit: none,zlib@openssh.com,zlib
debug2: kex_parse_kexinit:
debug2: kex_parse_kexinit:
debug2: kex_parse_kexinit: first_kex_follows 0
debug2: kex_parse_kexinit: reserved 0
debug2: kex_parse_kexinit: diffie-hellman-group-exchange-sha256,diffie
+-hellman-group-exchange-sha1,diffie-hellman-group14-sha1,diffie-hellm
+an-group1-sha1
debug2: kex_parse_kexinit: ssh-rsa,ssh-dss
debug2: kex_parse_kexinit: aes128-ctr,aes192-ctr,aes256-ctr,arcfour256
+,arcfour128,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,a
+es256-cbc,arcfour,rijndael-cbc@lysator.liu.se
debug2: kex_parse_kexinit: aes128-ctr,aes192-ctr,aes256-ctr,arcfour256
+,arcfour128,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,a
+es256-cbc,arcfour,rijndael-cbc@lysator.liu.se
debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,umac-64@openssh.com,hmac
+-ripemd160,hmac-ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96
debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,umac-64@openssh.com,hmac
+-ripemd160,hmac-ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96
debug2: kex_parse_kexinit: none,zlib@openssh.com
debug2: kex_parse_kexinit: none,zlib@openssh.com
debug2: kex_parse_kexinit:
debug2: kex_parse_kexinit:
debug2: kex_parse_kexinit: first_kex_follows 0
debug2: kex_parse_kexinit: reserved 0
debug2: mac_setup: found hmac-md5
debug1: kex: server->client aes128-ctr hmac-md5 none
debug2: mac_setup: found hmac-md5
debug1: kex: client->server aes128-ctr hmac-md5 none
debug1: SSH2_MSG_KEX_DH_GEX_REQUEST(1024<1024<8192) sent
debug1: expecting SSH2_MSG_KEX_DH_GEX_GROUP
debug3: Wrote 24 bytes for a total of 837
debug2: dh_gen_key: priv key bits set: 136/256
debug2: bits set: 503/1024
debug1: SSH2_MSG_KEX_DH_GEX_INIT sent
debug1: expecting SSH2_MSG_KEX_DH_GEX_REPLY
debug3: Wrote 144 bytes for a total of 981
debug3: check_host_in_hostfile: filename $HOME/.ssh/known_hosts
debug3: check_host_in_hostfile: match line 1
debug1: Host '<remote_server>' is known and matches the RSA host key.
debug1: Found key in <remote_server>/.ssh/known_hosts:1
debug2: bits set: 529/1024
debug1: ssh_rsa_verify: signature correct
debug2: kex_derive_keys
debug2: set_newkeys: mode 1
debug1: SSH2_MSG_NEWKEYS sent
debug1: expecting SSH2_MSG_NEWKEYS
debug3: Wrote 16 bytes for a total of 997
debug2: set_newkeys: mode 0
debug1: SSH2_MSG_NEWKEYS received
debug1: SSH2_MSG_SERVICE_REQUEST sent
debug3: Wrote 48 bytes for a total of 1045
debug2: service_accept: ssh-userauth
debug1: SSH2_MSG_SERVICE_ACCEPT received
debug2: key: $HOME/.ssh/identity ((nil))
debug2: key: $HOME/.ssh/id_rsa ((nil))
debug2: key: $HOME/.ssh/id_dsa ((nil))
debug3: Wrote 64 bytes for a total of 1109
debug3: input_userauth_banner
**********************************************************************
+*********
** WARNING ** WARNING ** WARNING ** WARNING ** WARNING ** WARNING ** W
+ARNING **
**********************************************************************
+*********
**                                                                    
+       **
**                   READ THIS BEFORE ATTEMPTING TO LOGON             
+       **
**                                                                    
+       **
**  ####company and user security policy stuff here####### **
**                                                                    
+       **
**********************************************************************
+*********
** WARNING ** WARNING ** WARNING ** WARNING ** WARNING ** WARNING ** W
+ARNING **
**********************************************************************
+*********

debug1: Authentications that can continue: publickey,gssapi-keyex,gssa
+pi-with-mic,password
debug3: start over, passed a different list publickey,gssapi-keyex,gss
+api-with-mic,password
debug3: preferred keyboard-interactive,password
debug3: authmethod_lookup password
debug3: remaining preferred: ,password
debug3: authmethod_is_enabled password
debug1: Next authentication method: password
#5159 1402995021.00000 _init_transport: 31 bytes readed from pty:
6c 6f 6b 69 40 31 30 2e 31 32 37 2e 33 34 2e 32 32 33 27 73 20 70 61 7
+3 73 77 6f 72 64 3a 20    | <sftp_user>@<remote_server>'s password:
#5159 1402995021.00000 _init_transport: looking for user/password prom
+pt
#5159 1402995021.00000 _init_transport: matching against (?^i:(user|na
+me|login)?[:?]\s*$)
#5159 1402995021.00000 _init_transport: sending password
#5159 1402995021.00000 _init_transport: checking timeout, max: 3600, e
+llapsed: 0.0849058628082275
#5159 1402995021.00000 _init_transport: waiting for data from the pty 
+to become available
#5159 1402995021.00000 _init_transport: 2 bytes readed from pty:
0d 0a                                                                 
+                          | ..
#5159 1402995021.00000 _init_transport: looking for password ok
#5159 1402995021.00000 _init_transport: password authentication done
#5159 1402995021.00000 _queue_msg: queueing msg len: 5, code:1, id:3 .
+.. [1]
00 00 00 05 01 00 00 00 03                                            
+                          | .........
#5159 1402995021.00000 _get_msg: waiting for message... [1]
#5159 1402995021.00000 _do_io: _do_io connected: 1
#5159 1402995021.00000 _do_io: _do_io select(-,-,-, 3600)
#5159 1402995021.00000 _do_io: _do_io write queue: 9, syswrite: 9, max
+: 65536, $!:
00 00 00 05 01 00 00 00 03                                            
+                          | .........
#5159 1402995021.00000 _do_io: _do_io select(-,-,-, 3600)
debug3: packet_send2: adding 32 (len 91 padlen 5 extra_pad 64)
debug2: we sent a password packet, wait for reply
debug3: Wrote 144 bytes for a total of 1253
debug1: Authentications that can continue: publickey,gssapi-keyex,gssa
+pi-with-mic,password
debug2: we did not send a packet, disable method
debug1: No more authentication methods to try.
Permission denied (publickey,gssapi-keyex,gssapi-with-mic,password).
#5159 1402995023.00000 _do_io: _do_io read sysread: 0, total read: 0, 
+$!:
#5159 1402995023.00000 _conn_lost: _conn_lost
#5159 1402995023.00000 _set_status: _set_status code: 7, str: Connecti
+on lost
#5159 1402995023.00000 _set_error: _set_err code: 37, str: Connection 
+to remote server is broken
#5159 1402995023.00000 _conn_lost: _conn_lost
#5159 1402995023.00000 DESTROY: Net::SFTP::Foreign=HASH(0x583d1f8)->DE
+STROY called (current pid: 5159, disconnect_by_pid: -1)

    [download]
[reply]
[d/l]
      Apparently, the password is being send at the right time. I can't see any problem there.

      Are you sure you are using the right password? could there be more than one server, with different configurations, listening at the same address?

      You can also try running the program with strace and checking that the password is written to the PTY from the Perl side and also read from the ssh slave process correctly.

[reply]
[d/l]
[select]

        The password is correct as it is the same password which works smoothly for all the successful attempts. Shouldn't it work for a failed attempt too? There is no such other server which is listening on the same address. Also, I am creating these sftp connection objects from a script, which runs as a daemon/background job. And am invoking 10 such jobs or gearman worker threads. These worker threads listen to a webservice call. Whenever, there is a webservice call, one of the available worker threads serves the request, downloads the file from the remote server and does some processing. do you see any issue with spawning such number of worker threads which create the sftp connection objects? Please let me know.

[reply]

In Section Seekers of Perl Wisdom