can you try using a git checkout instead of the pip install?
What version of python are you using? Also how did you install pip?
Did a checkout into /tank/ws/ansible
savant@vishnu:/tank/ws$ git clone https://github.com/ansible/ansible
Cloning into ‘ansible’…
remote: Counting objects: 80053, done.
remote: Compressing objects: 100% (72/72), done.
remote: Total 80053 (delta 29), reused 0 (delta 0), pack-reused 79975
Receiving objects: 100% (80053/80053), 24.66 MiB | 882.00 KiB/s, done.
Resolving deltas: 100% (50374/50374), done.
Checking connectivity… done.
But calling ansible from that directory yields the same results:
/tank/ws/ansible/bin/ansible testserver -m ping -v -v -v -v
<10.0.0.223> ESTABLISH CONNECTION FOR USER: vagrant
<10.0.0.223> REMOTE_MODULE ping
<10.0.0.223> EXEC ssh -C -tt -vvv -o Port=22 -o IdentityFile=“private_key” -o KbdInteractiveAuthentication=no -o PreferredAuthentications=gssapi-with-mic,gssapi-keyex,hostbased,publickey -o PasswordAuthentication=no -o User=vagrant -o ConnectTimeout=10 10.0.0.223 /bin/sh -c ‘mkdir -p /tmp/ansible-tmp-1430250178.79-155881019633771 && chmod a+rx /tmp/ansible-tmp-1430250178.79-155881019633771 && echo /tmp/ansible-tmp-1430250178.79-155881019633771’
testserver | FAILED => SSH Error: debug1: Calling cleanup 0x8078582(0x0)
while connecting to 10.0.0.223:22
It is sometimes useful to re-run the command using -vvvv, which prints SSH debug output to help diagnose the issue.
pfexec pkg install pip
pkg info pip
Name: library/python-2/pip
Summary: A tool for installing and managing Python packages
Category: Development/Python
State: Installed
Publisher: openindiana.org
Version: 1.4.1
Branch: 2015.0.0.0
Packaging Date: January 28, 2015 11:02:43 AM
Size: 0.00 B
FMRI: pkg://openindiana.org/library/python-2/pip@1.4.1-2015.0.0.0:20150128T110243Z
pkg list | grep python
library/python-2/cherrypy 3.1.2-2015.0.0.0 i–
library/python-2/cherrypy-26 3.1.2-2015.0.0.0 i–
library/python-2/coherence-26 0.6.6.2-0.151.1.8 i–
library/python-2/coverage 3.5-2015.0.0.0 i–
library/python-2/coverage-26 3.5-2015.0.0.0 i–
library/python-2/gnome-python-26 2.28.1-2015.0.0.0 i–
library/python-2/jsonrpclib 0.1.3-2015.0.0.0 i–
library/python-2/jsonrpclib-26 0.1.3-2015.0.0.0 i–
library/python-2/lcms-26 1.19-2015.0.1.0 i–
library/python-2/libxml2-26 2.9.2-2015.0.0.0 i–
library/python-2/libxsl-26 1.1.28-2015.0.0.0 i–
library/python-2/lxml 2.3.3-2015.0.0.1 i–
library/python-2/lxml-26 2.3.3-2015.0.0.1 i–
library/python-2/m2crypto 0.21.1-2015.0.0.1 i–
library/python-2/m2crypto-26 0.21.1-2015.0.0.1 i–
library/python-2/mako 0.4.1-2015.0.0.1 i–
library/python-2/mako-26 0.4.1-2015.0.0.1 i–
library/python-2/net-snmp-26 5.4.1.2-2015.0.0.3 i–
library/python-2/numpy-26 1.8.2-2015.0.0.0 i–
library/python-2/pip 1.4.1-2015.0.0.0 i–
library/python-2/pip-26 1.4.1-2015.0.0.0 i–
library/python-2/ply 3.1-2015.0.0.0 i–
library/python-2/ply-26 3.1-2015.0.0.0 i–
library/python-2/pyatspi-26 2.30.0-2015.0.0.0 i-r
library/python-2/pybonjour 1.1.1-2015.0.0.0 i–
library/python-2/pybonjour-26 1.1.1-2015.0.0.0 i–
library/python-2/pycairo-26 1.8.8-2015.0.0.1 i–
library/python-2/pycups 1.9.46-2015.0.0.0 i–
library/python-2/pycups-26 1.9.46-2015.0.0.0 i–
library/python-2/pycurl 7.19.0.1-2015.0.0.1 i–
library/python-2/pycurl-26 7.19.0.1-2015.0.0.1 i–
library/python-2/pygobject-26 2.21.5-2015.0.0.3 i–
library/python-2/pygtk2-26 2.17.0-2015.0.0.1 i–
library/python-2/pygtksourceview-26 2.10.1-2015.0.0.0 i–
library/python-2/pyopenssl 0.13-2015.0.0.1 i–
library/python-2/pyopenssl-26 0.13-2015.0.0.1 i–
library/python-2/pyorbit-26 2.24.0-2015.0.0.0 i–
library/python-2/pyrex 0.9.9-2015.0.0.0 i–
library/python-2/pyrex-26 0.9.9-2015.0.0.0 i–
library/python-2/python-compizconfig-26 0.8.4-2015.0.0.1 i–
library/python-2/python-dbus-26 0.84.0-2015.0.0.0 i–
library/python-2/python-extra-26 2.6.9-2014.0.1.0 i–
library/python-2/python-gnome-desktop-26 2.32.0-2015.0.0.2 i–
library/python-2/python-gnome-extras-26 2.25.3-2015.0.0.1 i–
library/python-2/python-gnome-libs-26 2.30.1-2014.0.1.0 i–
library/python-2/python-gst-26 0.10.22-2015.0.0.0 i–
library/python-2/python-notify-26 0.1.1-2015.0.1.0 i–
library/python-2/python-twisted 10.1.0-2015.0.0.0 i–
library/python-2/python-twisted-26 10.1.0-2015.0.0.0 i–
library/python-2/python-xdg-26 0.25-2015.0.0.0 i–
library/python-2/python-zope-interface 3.3.0-2015.0.0.0 i–
library/python-2/python-zope-interface-26 3.3.0-2015.0.0.0 i–
library/python-2/pyyaml-26 3.11-2015.0.0.0 i–
library/python-2/setuptools 0.6.11-2015.0.0.0 i–
library/python-2/setuptools-26 0.6.11-2015.0.0.0 i–
library/python-2/simplejson 2.1.2-2015.0.0.0 i–
library/python-2/simplejson-26 2.1.2-2015.0.0.0 i–
library/python-2/tkinter-26 2.6.9-2015.0.0.4 i–
runtime/python-26 2.6.9-2015.0.0.4 i–
python --version
Python 2.6.9
hmm, im running with 2.6.4, let me update the image.
Any luck reproducing the bug?
I had exactly the same bug only a bit different problem. Ubuntu 14.04, ansible installed from your repo via apt.
user@machine:~/ansible$ ansible --version
ansible 1.9.0.1
user@machine:~/ansible$ ansible -m ping machine2 -vvvv
SSH password:
SUDO password[defaults to SSH password]:
<192.168.35.81> ESTABLISH CONNECTION FOR USER: user
<192.168.35.81> REMOTE_MODULE ping
<192.168.35.81> EXEC sshpass -d6 ssh -C -tt -vvv -o ControlMaster=auto -o ControlPersist=60s -o ControlPath=“/home/user/.ansible/cp/ansible-ssh-%h-%p-%r” -o StrictHostKeyChecking=no -o Port=22 -o IdentityFile=“/home/user/.ssh/ansible” -o GSSAPIAuthentication=no -o PubkeyAuthentication=no -o ConnectTimeout=10 192.168.1.1 /bin/sh -c ‘mkdir -p $HOME/.ansible/tmp/ansible-tmp-1430303346.24-38061325826660 && chmod a+rx $HOME/.ansible/tmp/ansible-tmp-1430303346.24-38061325826660 && echo $HOME/.ansible/tmp/ansible-tmp-1430303346.24-38061325826660’
machine2.domain.com | FAILED => SSH Error: Permission denied (publickey,password).
while connecting to 192.168.1.1:22
It is sometimes useful to re-run the command using -vvvv, which prints SSH debug output to help diagnose the issue.
So no SSH debug output even when run with -vvvv.
But i guess i have found what was causing it in my case at least. I had an offending key (because that ip used to belong to other host) in known_hosts. I have removed the offending key using ssh-keygen -R and it now works as it should. I found my problem by going through SSH logs directly since Ansible didn’t output any of the ssh debug logs.
I understand that your problem is different as you have tried connecting using the ssh and host_key is not a problem but this still points to inconsistency in -vvvv behaviour.
Hope this helps a bit 
What -vvvv does for me is that it adds the lines starting with ESTABLISH CONNECTION, REMOTE_MODULE and EXEC to the output. I am not sure whether it is all it should do as this is my first encounter with Ansible.
I’ve run into the problem you describe as well, but corrected it by manually removing the offending line from the “~/.ssh/known_hosts” file.
/var/log/auth.log looks good to me (as expected).
Running sshd on another port with maximum debug level:
$ sudo /usr/sbin/sshd -d -d -d -p 2222 > /vagrant/sshd-log 2>&1
changeing testserver port to 2222 and then calling:
$ /ansible testserver -m ping -v -v -v -v
yields:
debug2: load_server_config: filename /etc/ssh/sshd_config
debug2: load_server_config: done config len = 763
debug2: parse_server_config: config /etc/ssh/sshd_config len 763
debug3: /etc/ssh/sshd_config:5 setting Port 22
debug3: /etc/ssh/sshd_config:9 setting Protocol 2
debug3: /etc/ssh/sshd_config:11 setting HostKey /etc/ssh/ssh_host_rsa_key
debug3: /etc/ssh/sshd_config:12 setting HostKey /etc/ssh/ssh_host_dsa_key
debug3: /etc/ssh/sshd_config:13 setting HostKey /etc/ssh/ssh_host_ecdsa_key
debug3: /etc/ssh/sshd_config:14 setting HostKey /etc/ssh/ssh_host_ed25519_key
debug3: /etc/ssh/sshd_config:16 setting UsePrivilegeSeparation yes
debug3: /etc/ssh/sshd_config:19 setting KeyRegenerationInterval 3600
debug3: /etc/ssh/sshd_config:20 setting ServerKeyBits 1024
debug3: /etc/ssh/sshd_config:23 setting SyslogFacility AUTH
debug3: /etc/ssh/sshd_config:24 setting LogLevel DEBUG3
debug3: /etc/ssh/sshd_config:27 setting LoginGraceTime 120
debug3: /etc/ssh/sshd_config:28 setting PermitRootLogin without-password
debug3: /etc/ssh/sshd_config:29 setting StrictModes yes
debug3: /etc/ssh/sshd_config:31 setting RSAAuthentication yes
debug3: /etc/ssh/sshd_config:32 setting PubkeyAuthentication yes
debug3: /etc/ssh/sshd_config:36 setting IgnoreRhosts yes
debug3: /etc/ssh/sshd_config:38 setting RhostsRSAAuthentication no
debug3: /etc/ssh/sshd_config:40 setting HostbasedAuthentication no
debug3: /etc/ssh/sshd_config:45 setting PermitEmptyPasswords no
debug3: /etc/ssh/sshd_config:49 setting ChallengeResponseAuthentication no
debug3: /etc/ssh/sshd_config:52 setting PasswordAuthentication yes
debug3: /etc/ssh/sshd_config:64 setting X11Forwarding yes
debug3: /etc/ssh/sshd_config:65 setting X11DisplayOffset 10
debug3: /etc/ssh/sshd_config:66 setting PrintMotd no
debug3: /etc/ssh/sshd_config:67 setting PrintLastLog yes
debug3: /etc/ssh/sshd_config:68 setting TCPKeepAlive yes
debug3: /etc/ssh/sshd_config:75 setting AcceptEnv LANG LC_*
debug3: /etc/ssh/sshd_config:77 setting Subsystem sftp /usr/lib/openssh/sftp-server
debug3: /etc/ssh/sshd_config:88 setting UsePAM yes
debug1: sshd version OpenSSH_6.6.1, OpenSSL 1.0.1f 6 Jan 2014
debug3: Incorrect RSA1 identifier
debug1: key_parse_private2: missing begin marker
debug1: read PEM private key done: type RSA
debug3: Incorrect RSA1 identifier
debug3: Could not load “/etc/ssh/ssh_host_rsa_key” as a RSA1 public key
debug1: private host key: #0 type 1 RSA
debug3: Incorrect RSA1 identifier
debug1: key_parse_private2: missing begin marker
debug1: read PEM private key done: type DSA
debug3: Incorrect RSA1 identifier
debug3: Could not load “/etc/ssh/ssh_host_dsa_key” as a RSA1 public key
debug1: private host key: #1 type 2 DSA
debug3: Incorrect RSA1 identifier
debug1: key_parse_private2: missing begin marker
debug1: read PEM private key done: type ECDSA
debug3: Incorrect RSA1 identifier
debug3: Could not load “/etc/ssh/ssh_host_ecdsa_key” as a RSA1 public key
debug1: private host key: #2 type 3 ECDSA
debug1: could not open key file ‘/etc/ssh/ssh_host_ed25519_key’: No such file or directory
Could not load host key: /etc/ssh/ssh_host_ed25519_key
debug1: rexec_argv[0]=‘/usr/sbin/sshd’
debug1: rexec_argv[1]=‘-d’
debug1: rexec_argv[2]=‘-d’
debug1: rexec_argv[3]=‘-d’
debug1: rexec_argv[4]=‘-p’
debug1: rexec_argv[5]=‘2222’
debug3: oom_adjust_setup
Set /proc/self/oom_score_adj from 0 to -1000
debug2: fd 3 setting O_NONBLOCK
debug1: Bind to port 2222 on 0.0.0.0.
Server listening on 0.0.0.0 port 2222.
debug2: fd 4 setting O_NONBLOCK
debug3: sock_set_v6only: set socket 4 IPV6_V6ONLY
debug1: Bind to port 2222 on ::.
Server listening on :: port 2222.
debug3: fd 5 is not O_NONBLOCK
debug1: Server will not fork when running in debugging mode.
debug3: send_rexec_state: entering fd = 8 config len 763
debug3: ssh_msg_send: type 0
debug3: send_rexec_state: done
debug1: rexec start in 5 out 5 newsock 5 pipe -1 sock 8
debug1: inetd sockets after dupping: 3, 3
Connection from 10.0.0.4 port 37252 on 10.0.0.223 port 2222
debug1: Client protocol version 2.0; client software version Sun_SSH_1.5
debug1: no match: Sun_SSH_1.5
debug1: Enabling compatibility mode for protocol 2.0
debug1: Local version string SSH-2.0-OpenSSH_6.6.1p1 Ubuntu-2ubuntu2
debug2: fd 3 setting O_NONBLOCK
debug2: Network child is on pid 10121
debug3: preauth child monitor started
debug3: privsep user:group 104:65534 [preauth]
debug1: permanently_set_uid: 104/65534 [preauth]
debug1: list_hostkey_types: ssh-rsa,ssh-dss,ecdsa-sha2-nistp256 [preauth]
debug1: SSH2_MSG_KEXINIT sent [preauth]
debug1: SSH2_MSG_KEXINIT received [preauth]
debug2: kex_parse_kexinit: curve25519-sha256@libssh.org,ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1 [preauth]
debug2: kex_parse_kexinit: ssh-rsa,ssh-dss,ecdsa-sha2-nistp256 [preauth]
debug2: kex_parse_kexinit: aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,aes128-gcm@openssh.com,aes256-gcm@openssh.com,chacha20-poly1305@openssh.com,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,rijndael-cbc@lysator.liu.se [preauth]
debug2: kex_parse_kexinit: aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,aes128-gcm@openssh.com,aes256-gcm@openssh.com,chacha20-poly1305@openssh.com,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,rijndael-cbc@lysator.liu.se [preauth]
debug2: kex_parse_kexinit: hmac-md5-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-ripemd160-etm@openssh.com,hmac-sha1-96-etm@openssh.com,hmac-md5-96-etm@openssh.com,hmac-md5,hmac-sha1,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-ripemd160,hmac-ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96 [preauth]
debug2: kex_parse_kexinit: hmac-md5-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-ripemd160-etm@openssh.com,hmac-sha1-96-etm@openssh.com,hmac-md5-96-etm@openssh.com,hmac-md5,hmac-sha1,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-ripemd160,hmac-ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96 [preauth]
debug2: kex_parse_kexinit: none,zlib@openssh.com [preauth]
debug2: kex_parse_kexinit: none,zlib@openssh.com [preauth]
debug2: kex_parse_kexinit: [preauth]
debug2: kex_parse_kexinit: [preauth]
debug2: kex_parse_kexinit: first_kex_follows 0 [preauth]
debug2: kex_parse_kexinit: reserved 0 [preauth]
debug2: kex_parse_kexinit: diffie-hellman-group-exchange-sha1,diffie-hellman-group1-sha1 [preauth]
debug2: kex_parse_kexinit: ssh-rsa,ssh-dss [preauth]
debug2: kex_parse_kexinit: aes128-ctr,aes192-ctr,aes256-ctr,arcfour128,arcfour256,arcfour,aes128-cbc,aes192-cbc,aes256-cbc,blowfish-cbc,3des-cbc [preauth]
debug2: kex_parse_kexinit: aes128-ctr,aes192-ctr,aes256-ctr,arcfour128,arcfour256,arcfour,aes128-cbc,aes192-cbc,aes256-cbc,blowfish-cbc,3des-cbc [preauth]
debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,hmac-sha1-96,hmac-md5-96 [preauth]
debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,hmac-sha1-96,hmac-md5-96 [preauth]
debug2: kex_parse_kexinit: zlib,none [preauth]
debug2: kex_parse_kexinit: zlib,none [preauth]
debug2: kex_parse_kexinit: en-US [preauth]
debug2: kex_parse_kexinit: en-US [preauth]
debug2: kex_parse_kexinit: first_kex_follows 0 [preauth]
debug2: kex_parse_kexinit: reserved 0 [preauth]
debug2: mac_setup: setup hmac-md5 [preauth]
debug1: kex: client->server aes128-ctr hmac-md5 none [preauth]
debug2: mac_setup: setup hmac-md5 [preauth]
debug1: kex: server->client aes128-ctr hmac-md5 none [preauth]
debug1: SSH2_MSG_KEX_DH_GEX_REQUEST received [preauth]
debug3: mm_request_send entering: type 0 [preauth]
debug3: mm_choose_dh: waiting for MONITOR_ANS_MODULI [preauth]
debug3: mm_request_receive_expect entering: type 1 [preauth]
debug3: mm_request_receive entering [preauth]
debug3: mm_request_receive entering
debug3: monitor_read: checking request 0
debug3: mm_answer_moduli: got parameters: 1024 2048 8192
debug3: mm_request_send entering: type 1
debug2: monitor_read: 0 used once, disabling now
debug3: mm_choose_dh: remaining 0 [preauth]
debug1: SSH2_MSG_KEX_DH_GEX_GROUP sent [preauth]
debug2: bits set: 1017/2048 [preauth]
debug1: expecting SSH2_MSG_KEX_DH_GEX_INIT [preauth]
debug2: bits set: 1026/2048 [preauth]
debug3: mm_key_sign entering [preauth]
debug3: mm_request_send entering: type 6 [preauth]
debug3: mm_key_sign: waiting for MONITOR_ANS_SIGN [preauth]
debug3: mm_request_receive_expect entering: type 7 [preauth]
debug3: mm_request_receive entering [preauth]
debug3: mm_request_receive entering
debug3: monitor_read: checking request 6
debug3: mm_answer_sign
debug3: mm_answer_sign: signature 0x7f506484eda0(271)
debug3: mm_request_send entering: type 7
debug2: monitor_read: 6 used once, disabling now
debug1: SSH2_MSG_KEX_DH_GEX_REPLY sent [preauth]
debug2: kex_derive_keys [preauth]
debug2: set_newkeys: mode 1 [preauth]
debug1: SSH2_MSG_NEWKEYS sent [preauth]
debug1: expecting SSH2_MSG_NEWKEYS [preauth]
debug2: set_newkeys: mode 0 [preauth]
debug1: SSH2_MSG_NEWKEYS received [preauth]
debug1: KEX done [preauth]
debug1: userauth-request for user vagrant service ssh-connection method none [preauth]
debug1: attempt 0 failures 0 [preauth]
debug3: mm_getpwnamallow entering [preauth]
debug3: mm_request_send entering: type 8 [preauth]
debug3: mm_getpwnamallow: waiting for MONITOR_ANS_PWNAM [preauth]
debug3: mm_request_receive_expect entering: type 9 [preauth]
debug3: mm_request_receive entering [preauth]
debug3: mm_request_receive entering
debug3: monitor_read: checking request 8
debug3: mm_answer_pwnamallow
debug3: Trying to reverse map address 10.0.0.4.
debug2: parse_server_config: config reprocess config len 763
debug3: mm_answer_pwnamallow: sending MONITOR_ANS_PWNAM: 1
debug3: mm_request_send entering: type 9
debug2: monitor_read: 8 used once, disabling now
debug2: input_userauth_request: setting up authctxt for vagrant [preauth]
debug3: mm_start_pam entering [preauth]
debug3: mm_request_send entering: type 100 [preauth]
debug3: mm_inform_authserv entering [preauth]
debug3: mm_request_send entering: type 4 [preauth]
debug2: input_userauth_request: try method none [preauth]
debug3: userauth_finish: failure partial=0 next methods=“publickey,password” [preauth]
Connection closed by 10.0.0.4 [preauth]
debug1: do_cleanup [preauth]
debug3: PAM: sshpam_thread_cleanup entering [preauth]
debug1: monitor_read_log: child log fd closed
debug3: mm_request_receive entering
debug3: monitor_read: checking request 100
debug1: PAM: initializing for “vagrant”
debug1: PAM: setting PAM_RHOST to “10.0.0.4”
debug1: PAM: setting PAM_TTY to “ssh”
debug2: monitor_read: 100 used once, disabling now
debug3: mm_request_receive entering
debug3: monitor_read: checking request 4
debug3: mm_answer_authserv: service=ssh-connection, style=, role=
debug2: monitor_read: 4 used once, disabling now
debug3: mm_request_receive entering
debug1: do_cleanup
debug1: PAM: cleanup
debug3: PAM: sshpam_thread_cleanup entering
debug1: Killing privsep child 10121
To contrast:
$ ssh -C -tt -vvv -o Port=2222 -o IdentityFile=“private_key” -o KbdInteractiveAuthentication=no -o PreferredAuthentications=gssapi-with-mic,gssapi-keyex,hostbased,publickey -o PasswordAuthentication=no -o User=vagrant -o ConnectTimeout=10 10.0.0.223 /bin/sh -c "‘mkdir -p /tmp/ansible-tmp-1430316462.2-160012430943180 && chmod a+rx /tmp/ansible-tmp-1430316462.2-160012430943180 && echo /tmp/ansible-tmp-1430316462.2-160012430943180’"
yields:
debug2: load_server_config: filename /etc/ssh/sshd_config
debug2: load_server_config: done config len = 763
debug2: parse_server_config: config /etc/ssh/sshd_config len 763
debug3: /etc/ssh/sshd_config:5 setting Port 22
debug3: /etc/ssh/sshd_config:9 setting Protocol 2
debug3: /etc/ssh/sshd_config:11 setting HostKey /etc/ssh/ssh_host_rsa_key
debug3: /etc/ssh/sshd_config:12 setting HostKey /etc/ssh/ssh_host_dsa_key
debug3: /etc/ssh/sshd_config:13 setting HostKey /etc/ssh/ssh_host_ecdsa_key
debug3: /etc/ssh/sshd_config:14 setting HostKey /etc/ssh/ssh_host_ed25519_key
debug3: /etc/ssh/sshd_config:16 setting UsePrivilegeSeparation yes
debug3: /etc/ssh/sshd_config:19 setting KeyRegenerationInterval 3600
debug3: /etc/ssh/sshd_config:20 setting ServerKeyBits 1024
debug3: /etc/ssh/sshd_config:23 setting SyslogFacility AUTH
debug3: /etc/ssh/sshd_config:24 setting LogLevel DEBUG3
debug3: /etc/ssh/sshd_config:27 setting LoginGraceTime 120
debug3: /etc/ssh/sshd_config:28 setting PermitRootLogin without-password
debug3: /etc/ssh/sshd_config:29 setting StrictModes yes
debug3: /etc/ssh/sshd_config:31 setting RSAAuthentication yes
debug3: /etc/ssh/sshd_config:32 setting PubkeyAuthentication yes
debug3: /etc/ssh/sshd_config:36 setting IgnoreRhosts yes
debug3: /etc/ssh/sshd_config:38 setting RhostsRSAAuthentication no
debug3: /etc/ssh/sshd_config:40 setting HostbasedAuthentication no
debug3: /etc/ssh/sshd_config:45 setting PermitEmptyPasswords no
debug3: /etc/ssh/sshd_config:49 setting ChallengeResponseAuthentication no
debug3: /etc/ssh/sshd_config:52 setting PasswordAuthentication yes
debug3: /etc/ssh/sshd_config:64 setting X11Forwarding yes
debug3: /etc/ssh/sshd_config:65 setting X11DisplayOffset 10
debug3: /etc/ssh/sshd_config:66 setting PrintMotd no
debug3: /etc/ssh/sshd_config:67 setting PrintLastLog yes
debug3: /etc/ssh/sshd_config:68 setting TCPKeepAlive yes
debug3: /etc/ssh/sshd_config:75 setting AcceptEnv LANG LC_*
debug3: /etc/ssh/sshd_config:77 setting Subsystem sftp /usr/lib/openssh/sftp-server
debug3: /etc/ssh/sshd_config:88 setting UsePAM yes
debug1: sshd version OpenSSH_6.6.1, OpenSSL 1.0.1f 6 Jan 2014
debug3: Incorrect RSA1 identifier
debug1: key_parse_private2: missing begin marker
debug1: read PEM private key done: type RSA
debug3: Incorrect RSA1 identifier
debug3: Could not load “/etc/ssh/ssh_host_rsa_key” as a RSA1 public key
debug1: private host key: #0 type 1 RSA
debug3: Incorrect RSA1 identifier
debug1: key_parse_private2: missing begin marker
debug1: read PEM private key done: type DSA
debug3: Incorrect RSA1 identifier
debug3: Could not load “/etc/ssh/ssh_host_dsa_key” as a RSA1 public key
debug1: private host key: #1 type 2 DSA
debug3: Incorrect RSA1 identifier
debug1: key_parse_private2: missing begin marker
debug1: read PEM private key done: type ECDSA
debug3: Incorrect RSA1 identifier
debug3: Could not load “/etc/ssh/ssh_host_ecdsa_key” as a RSA1 public key
debug1: private host key: #2 type 3 ECDSA
debug1: could not open key file ‘/etc/ssh/ssh_host_ed25519_key’: No such file or directory
Could not load host key: /etc/ssh/ssh_host_ed25519_key
debug1: rexec_argv[0]=‘/usr/sbin/sshd’
debug1: rexec_argv[1]=‘-d’
debug1: rexec_argv[2]=‘-d’
debug1: rexec_argv[3]=‘-d’
debug1: rexec_argv[4]=‘-p’
debug1: rexec_argv[5]=‘2222’
debug3: oom_adjust_setup
Set /proc/self/oom_score_adj from 0 to -1000
debug2: fd 3 setting O_NONBLOCK
debug1: Bind to port 2222 on 0.0.0.0.
Server listening on 0.0.0.0 port 2222.
debug2: fd 4 setting O_NONBLOCK
debug3: sock_set_v6only: set socket 4 IPV6_V6ONLY
debug1: Bind to port 2222 on ::.
Server listening on :: port 2222.
debug3: fd 5 is not O_NONBLOCK
debug1: Server will not fork when running in debugging mode.
debug3: send_rexec_state: entering fd = 8 config len 763
debug3: ssh_msg_send: type 0
debug3: send_rexec_state: done
debug1: rexec start in 5 out 5 newsock 5 pipe -1 sock 8
debug1: inetd sockets after dupping: 3, 3
Connection from 10.0.0.4 port 33847 on 10.0.0.223 port 2222
debug1: Client protocol version 2.0; client software version Sun_SSH_1.5
debug1: no match: Sun_SSH_1.5
debug1: Enabling compatibility mode for protocol 2.0
debug1: Local version string SSH-2.0-OpenSSH_6.6.1p1 Ubuntu-2ubuntu2
debug2: fd 3 setting O_NONBLOCK
debug2: Network child is on pid 10384
debug3: preauth child monitor started
debug3: privsep user:group 104:65534 [preauth]
debug1: permanently_set_uid: 104/65534 [preauth]
debug1: list_hostkey_types: ssh-rsa,ssh-dss,ecdsa-sha2-nistp256 [preauth]
debug1: SSH2_MSG_KEXINIT sent [preauth]
debug1: SSH2_MSG_KEXINIT received [preauth]
debug2: kex_parse_kexinit: curve25519-sha256@libssh.org,ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1 [preauth]
debug2: kex_parse_kexinit: ssh-rsa,ssh-dss,ecdsa-sha2-nistp256 [preauth]
debug2: kex_parse_kexinit: aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,aes128-gcm@openssh.com,aes256-gcm@openssh.com,chacha20-poly1305@openssh.com,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,rijndael-cbc@lysator.liu.se [preauth]
debug2: kex_parse_kexinit: aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,aes128-gcm@openssh.com,aes256-gcm@openssh.com,chacha20-poly1305@openssh.com,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,rijndael-cbc@lysator.liu.se [preauth]
debug2: kex_parse_kexinit: hmac-md5-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-ripemd160-etm@openssh.com,hmac-sha1-96-etm@openssh.com,hmac-md5-96-etm@openssh.com,hmac-md5,hmac-sha1,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-ripemd160,hmac-ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96 [preauth]
debug2: kex_parse_kexinit: hmac-md5-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-ripemd160-etm@openssh.com,hmac-sha1-96-etm@openssh.com,hmac-md5-96-etm@openssh.com,hmac-md5,hmac-sha1,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-ripemd160,hmac-ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96 [preauth]
debug2: kex_parse_kexinit: none,zlib@openssh.com [preauth]
debug2: kex_parse_kexinit: none,zlib@openssh.com [preauth]
debug2: kex_parse_kexinit: [preauth]
debug2: kex_parse_kexinit: [preauth]
debug2: kex_parse_kexinit: first_kex_follows 0 [preauth]
debug2: kex_parse_kexinit: reserved 0 [preauth]
debug2: kex_parse_kexinit: diffie-hellman-group-exchange-sha1,diffie-hellman-group1-sha1 [preauth]
debug2: kex_parse_kexinit: ssh-rsa,ssh-dss [preauth]
debug2: kex_parse_kexinit: aes128-ctr,aes192-ctr,aes256-ctr,arcfour128,arcfour256,arcfour,aes128-cbc,aes192-cbc,aes256-cbc,blowfish-cbc,3des-cbc [preauth]
debug2: kex_parse_kexinit: aes128-ctr,aes192-ctr,aes256-ctr,arcfour128,arcfour256,arcfour,aes128-cbc,aes192-cbc,aes256-cbc,blowfish-cbc,3des-cbc [preauth]
debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,hmac-sha1-96,hmac-md5-96 [preauth]
debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,hmac-sha1-96,hmac-md5-96 [preauth]
debug2: kex_parse_kexinit: zlib,none [preauth]
debug2: kex_parse_kexinit: zlib,none [preauth]
debug2: kex_parse_kexinit: en-US [preauth]
debug2: kex_parse_kexinit: en-US [preauth]
debug2: kex_parse_kexinit: first_kex_follows 0 [preauth]
debug2: kex_parse_kexinit: reserved 0 [preauth]
debug2: mac_setup: setup hmac-md5 [preauth]
debug1: kex: client->server aes128-ctr hmac-md5 none [preauth]
debug2: mac_setup: setup hmac-md5 [preauth]
debug1: kex: server->client aes128-ctr hmac-md5 none [preauth]
debug1: SSH2_MSG_KEX_DH_GEX_REQUEST received [preauth]
debug3: mm_request_send entering: type 0 [preauth]
debug3: mm_choose_dh: waiting for MONITOR_ANS_MODULI [preauth]
debug3: mm_request_receive_expect entering: type 1 [preauth]
debug3: mm_request_receive entering [preauth]
debug3: mm_request_receive entering
debug3: monitor_read: checking request 0
debug3: mm_answer_moduli: got parameters: 1024 2048 8192
debug3: mm_request_send entering: type 1
debug2: monitor_read: 0 used once, disabling now
debug3: mm_choose_dh: remaining 0 [preauth]
debug1: SSH2_MSG_KEX_DH_GEX_GROUP sent [preauth]
debug2: bits set: 1045/2048 [preauth]
debug1: expecting SSH2_MSG_KEX_DH_GEX_INIT [preauth]
debug2: bits set: 1006/2048 [preauth]
debug3: mm_key_sign entering [preauth]
debug3: mm_request_send entering: type 6 [preauth]
debug3: mm_key_sign: waiting for MONITOR_ANS_SIGN [preauth]
debug3: mm_request_receive_expect entering: type 7 [preauth]
debug3: mm_request_receive entering [preauth]
debug3: mm_request_receive entering
debug3: monitor_read: checking request 6
debug3: mm_answer_sign
debug3: mm_answer_sign: signature 0x7fae82385da0(271)
debug3: mm_request_send entering: type 7
debug2: monitor_read: 6 used once, disabling now
debug1: SSH2_MSG_KEX_DH_GEX_REPLY sent [preauth]
debug2: kex_derive_keys [preauth]
debug2: set_newkeys: mode 1 [preauth]
debug1: SSH2_MSG_NEWKEYS sent [preauth]
debug1: expecting SSH2_MSG_NEWKEYS [preauth]
debug2: set_newkeys: mode 0 [preauth]
debug1: SSH2_MSG_NEWKEYS received [preauth]
debug1: KEX done [preauth]
debug1: userauth-request for user vagrant service ssh-connection method none [preauth]
debug1: attempt 0 failures 0 [preauth]
debug3: mm_getpwnamallow entering [preauth]
debug3: mm_request_send entering: type 8 [preauth]
debug3: mm_getpwnamallow: waiting for MONITOR_ANS_PWNAM [preauth]
debug3: mm_request_receive_expect entering: type 9 [preauth]
debug3: mm_request_receive entering [preauth]
debug3: mm_request_receive entering
debug3: monitor_read: checking request 8
debug3: mm_answer_pwnamallow
debug3: Trying to reverse map address 10.0.0.4.
debug2: parse_server_config: config reprocess config len 763
debug3: mm_answer_pwnamallow: sending MONITOR_ANS_PWNAM: 1
debug3: mm_request_send entering: type 9
debug2: monitor_read: 8 used once, disabling now
debug2: input_userauth_request: setting up authctxt for vagrant [preauth]
debug3: mm_start_pam entering [preauth]
debug3: mm_request_send entering: type 100 [preauth]
debug3: mm_inform_authserv entering [preauth]
debug3: mm_request_send entering: type 4 [preauth]
debug2: input_userauth_request: try method none [preauth]
debug3: userauth_finish: failure partial=0 next methods=“publickey,password” [preauth]
debug3: mm_request_receive entering
debug3: monitor_read: checking request 100
debug1: PAM: initializing for “vagrant”
debug1: PAM: setting PAM_RHOST to “10.0.0.4”
debug1: PAM: setting PAM_TTY to “ssh”
debug2: monitor_read: 100 used once, disabling now
debug1: userauth-request for user vagrant service ssh-connection method publickey [preauth]
debug1: attempt 1 failures 0 [preauth]
debug2: input_userauth_request: try method publickey [preauth]
debug3: mm_key_allowed entering [preauth]
debug3: mm_request_send entering: type 22 [preauth]
debug3: mm_key_allowed: waiting for MONITOR_ANS_KEYALLOWED [preauth]
debug3: mm_request_receive_expect entering: type 23 [preauth]
debug3: mm_request_receive entering [preauth]
debug3: mm_request_receive entering
debug3: monitor_read: checking request 4
debug3: mm_answer_authserv: service=ssh-connection, style=, role=
debug2: monitor_read: 4 used once, disabling now
debug3: mm_request_receive entering
debug3: monitor_read: checking request 22
debug3: mm_answer_keyallowed entering
debug3: mm_answer_keyallowed: key_from_blob: 0x7fae8239e1e0
debug1: temporarily_use_uid: 1000/1000 (e=0/0)
debug1: trying public key file /home/vagrant/.ssh/authorized_keys
debug1: fd 4 clearing O_NONBLOCK
debug1: matching key found: file /home/vagrant/.ssh/authorized_keys, line 2 RSA 76:cb:db:1e:4a:ac:46:ca:c7:d5:8a:dc:86:41:50:ae
debug1: restore_uid: 0/0
debug3: mm_answer_keyallowed: key 0x7fae8239e1e0 is allowed
debug3: mm_request_send entering: type 23
debug3: mm_key_verify entering [preauth]
debug3: mm_request_send entering: type 24 [preauth]
debug3: mm_key_verify: waiting for MONITOR_ANS_KEYVERIFY [preauth]
debug3: mm_request_receive_expect entering: type 25 [preauth]
debug3: mm_request_receive entering [preauth]
debug3: mm_request_receive entering
debug3: monitor_read: checking request 24
debug1: ssh_rsa_verify: signature correct
debug3: mm_answer_keyverify: key 0x7fae8239e1e0 signature verified
debug3: mm_request_send entering: type 25
debug3: mm_request_receive_expect entering: type 102
debug3: mm_request_receive entering
debug1: do_pam_account: called
debug3: PAM: do_pam_account pam_acct_mgmt = 0 (Success)
debug3: mm_request_send entering: type 103
Accepted publickey for vagrant from 10.0.0.4 port 33847 ssh2: RSA 76:cb:db:1e:4a:ac:46:ca:c7:d5:8a:dc:86:41:50:ae
debug1: monitor_child_preauth: vagrant has been authenticated by privileged process
debug3: mm_get_keystate: Waiting for new keys
debug3: mm_request_receive_expect entering: type 26
debug3: mm_request_receive entering
debug3: mm_newkeys_from_blob: 0x7fae8239d230(122)
debug2: mac_setup: setup hmac-md5
debug3: mm_get_keystate: Waiting for second key
debug3: mm_newkeys_from_blob: 0x7fae8239d230(122)
debug2: mac_setup: setup hmac-md5
debug3: mm_get_keystate: Getting compression state
debug3: mm_get_keystate: Getting Network I/O buffers
debug2: userauth_pubkey: authenticated 1 pkalg ssh-rsa [preauth]
debug3: mm_do_pam_account entering [preauth]
debug3: mm_request_send entering: type 102 [preauth]
debug3: mm_request_receive_expect entering: type 103 [preauth]
debug3: mm_request_receive entering [preauth]
debug3: mm_do_pam_account returning 1 [preauth]
debug3: mm_send_keystate: Sending new keys: 0x7fae82386ef0 0x7fae82387730 [preauth]
debug3: mm_newkeys_to_blob: converting 0x7fae82386ef0 [preauth]
debug3: mm_newkeys_to_blob: converting 0x7fae82387730 [preauth]
debug3: mm_send_keystate: New keys have been sent [preauth]
debug3: mm_send_keystate: Sending compression state [preauth]
debug3: mm_request_send entering: type 26 [preauth]
debug3: mm_send_keystate: Finished sending state [preauth]
debug1: monitor_read_log: child log fd closed
debug3: mm_share_sync: Share sync
debug3: mm_share_sync: Share sync end
debug1: PAM: establishing credentials
debug3: PAM: opening session
debug3: PAM: sshpam_store_conv called with 1 messages
User child is on pid 10458
debug1: SELinux support disabled
debug1: PAM: establishing credentials
debug1: permanently_set_uid: 1000/1000
debug2: set_newkeys: mode 0
debug2: set_newkeys: mode 1
debug1: Entering interactive session for SSH2.
debug2: fd 6 setting O_NONBLOCK
debug2: fd 8 setting O_NONBLOCK
debug1: server_init_dispatch_20
debug1: server_input_channel_open: ctype session rchan 0 win 65536 max 16384
debug1: input_session_request
debug1: channel 0: new [server-session]
debug2: session_new: allocate (allocated 0 max 10)
debug3: session_unused: session id 0 unused
debug1: session_new: session 0
debug1: session_open: channel 0
debug1: session_open: session 0: link with channel 0
debug1: server_input_channel_open: confirm session
debug1: server_input_channel_req: channel 0 request env reply 0
debug1: session_by_channel: session 0 channel 0
debug1: session_input_channel_req: session 0 req env
debug2: Setting env 0: LANG=en_US.UTF-8
debug1: server_input_channel_req: channel 0 request pty-req reply 0
debug1: session_by_channel: session 0 channel 0
debug1: session_input_channel_req: session 0 req pty-req
debug1: Allocating pty.
debug3: mm_request_send entering: type 28
debug3: mm_request_receive entering
debug3: mm_pty_allocate: waiting for MONITOdebug3: mm_debug3: mm_request_receive_expect entering: type 29
llocated 0 max 10)
debug3: session_unused: session id 0 unused
debug3: mm_request_receive enterdebug1: SELinux support disabled
debug3: mm_request_send entering: type 29
debug3: mm_answer_pty: tty /dev/pts/1 ptyfd 5
debug1: session_pty_req: session 0 alloc /dev/pts/1
debug1: Ignoring unsupported tty mode opcode 11 (0xb)
debug1: Ignoring unsupported tty mode opcode 16 (0x10)
debug1: Ignoring unsupported tty mode opcode 17 (0x11)
debug1: server_input_channel_req: channel 0 request exec reply 0
debug1: session_by_channel: session 0 channel 0
debug1: session_input_channel_req: session 0 req exec
Starting session: command on pts/1 for vagrant from 10.0.0.4 port 33847
debug2: fd 3 setting TCP_NODELAY
debug3: packet_set_tos: set IP_TOS 0x10
debug2: channel 0: rfd 11 isatty
debug2: fd 11 setting O_NONBLOCK
debug3: fd 9 is O_NONBLOCK
debug1: Setting controlling tty using TIOCSCTTY.
debug3: mm_request_receive entering
debug3: monitor_read: checking request 156
debug3: mm_answer_consolekit_register entering
debug1: session_by_tty: session 0 tty /dev/pts/1
debug1: Unable to open session: The name org.freedesktop.ConsoleKit was not provided by any .service files
debug3: mm_request_send entering: type 157
debug2: channel 0: read<=0 rfd 11 len -1
debug2: channel 0: read failed
debug2: channel 0: close_read
debug2: channel 0: input open → drain
debug2: channel 0: ibuf empty
debug2: channel 0: send eof
debug2: channel 0: input drain → closed
debug2: notify_done: reading
debug1: Received SIGCHLD.
debug1: session_by_pid: pid 10459
debug1: session_exit_message: session 0 channel 0 pid 10459
debug2: channel 0: request exit-status confirm 0
debug1: session_exit_message: release channel 0
debug2: channel 0: write failed
debug2: channel 0: close_write
debug2: channel 0: send eow
debug2: channel 0: output open → closed
debug3: mm_request_send entering: type 30
debug3: mm_request_receive entering
debug3: monitor_read: checking request 30
debug2: channel 0: send close
ntering
debug1: session_by_tty: session 0 tty /dev/pts/1
debug3: mm_session_close: session 0 pid 10458
debug3: mm_session_close: tty /dev/pts/1 ptyfd 5
debug3: channel 0: will not send data after close
/pts/1
debug1: unregistering ConsoleKit session (null)
debug2: channel 0: rcvd close
debug3: channel 0: will not send data after close
debug2: channel 0: is dead
debug2: channel 0: gc: notify user
debug1: session_by_channel: session 0 channel 0
debug1: session_close_by_channel: channel 0 child 0
debug1: session_close: session 0 pid 0
debug3: session_unused: session id 0 unused
debug2: channel 0: gc: user detached
debug2: channel 0: is dead
debug2: channel 0: garbage collecting
debug1: channel 0: free: server-session, nchannels 1
debug3: channel 0: status: The following connections are open:
#0 server-session (t4 r0 i3/0 o3/0 fd -1/-1 cc -1)
Connection closed by 10.0.0.4
debug1: do_cleanup
debug3: PAM: sshpam_thread_cleanup entering
Transferred: sent 4008, received 2168 bytes
Closing connection to 10.0.0.4 port 33847
debug3: mm_request_send entering: type 50
debug3: mm_request_receive entering
debug3: monitor_read: checking request 50
debug3: mm_answer_term: tearing down sessions
debug1: PAM: cleanup
debug1: PAM: closing session
debug1: PAM: deleting credentials
I updated and I have not been able to reproduce, this is not an ssh
login problem as the debug shows this working. There seems to be a
truncation issue when the command is passed, no clue as to why this is
happening.
Can you please pinpoint the debug log lines that support your hypothesis?
debug1: Sending command: /bin/sh -c mkdir -p
$HOME/.ansible/tmp/ansible-tmp-1430038868.37-101280127720263 && chmod
a+rx $HOME/.ansible/tmp/ansible-tmp-1430038868.37-101280127720263 &&
echo $HOME/.ansible/tmp/ansible-tmp-1430038868.37-101280127720263
debug1: channel request 0: exec
debug1: fd 4 setting TCP_NODELAY
debug2: callback done
debug1: channel 0: open confirm rwindow 0 rmax 32768
debug2: channel 0: rcvd adjust 2097152
mkdir: missing operand
Try 'mkdir --help' for more information.
also that we do not get 'no authentication methods left' which would
signify an authentication failure.
But how do these support the truncation issue hypothesis? The command does not seem to be truncated in this log …
Also, can you please point me to the OpenIndiana image you have used as the basis for your bug reproduction test? I would like to try it myself and I want to make sure I am using the same starting point.
oi-dev-151a8-text-x86.iso downloaded from the site.
My host is gentoo, running this as a virtualbox vm
So I have created 2 Vagrant boxes for oi-server and oi-desktop and the bug is totally reproducible in both with exactly the same behavior described here.
Brian can you please suggest a server where I could upload the boxes for you??? They are 3.3GB and 5.1GB in size. (thus beyond githubs limits)
Please feel free to email me if necessary.
Regards,
=Dusan
I need to setup something, one question, what are you using as
underlying VM under vagrant?