Hey again.
As a workaround, I have now decided to force Ansible to use Paramiko instead of OpenSSH, and my playbooks work. Paavo On Monday, 10 November 2014 09:34:01 UTC+9, Paavo wrote: > > Hi, Everyone. > > > I'm trying to run an Ansible playbook on two servers, and occasionally > either one or both of them fail a task with the error "/usr/bin/python: > can't open file 'command': [Errno 13] Permission denied". I started looking > into why this was happening (and why it was only happening some of the > time). I traced the error to the temporary directory where Ansible copies > its command file sometimes being empty instead of the normal random > directory created in /tmp (runner/__init__.py:Runner._make_tmp_path()). > Looking into it further, it looks like sometimes the mkdir && echo command > used to create the temporary directory is assumed to be successful, but the > output, which should be the created directory, is empty > (runner/connection_plugins/ssh.py:Connection._communicate()). > > The mkdir && echo commands looks identical to me: > > <server1> EXEC ssh -C -tt -vvv -o ControlMaster=auto -o ControlPersist=60s > -o ControlPath="/home/user/.ansible/cp/ansible-ssh-%h-%p-%r" -o > KbdInteractiveAuthentication=no -o > PreferredAuthentications=gssapi-with-mic,gssapi-keyex,hostbased,publickey > -o PasswordAuthentication=no -o ConnectTimeout=30 server1 /bin/sh -c 'mkdir > -p /tmp/ansible-tmp-1415576481.52-184054006705534 && chmod a+rx > /tmp/ansible-tmp-1415576481.52-184054006705534 && echo > /tmp/ansible-tmp-1415576481.52-18405400670 > > <server2> EXEC ssh -C -tt -vvv -o ControlMaster=auto -o ControlPersist=60s > -o ControlPath="/home/user/.ansible/cp/ansible-ssh-%h-%p-%r" -o > KbdInteractiveAuthentication=no -o > PreferredAuthentications=gssapi-with-mic,gssapi-keyex,hostbased,publickey > -o PasswordAuthentication=no -o ConnectTimeout=30 server2 /bin/sh -c 'mkdir > -p /tmp/ansible-tmp-1415576481.52-82470479460561 && chmod a+rx > /tmp/ansible-tmp-1415576481.52-82470479460561 && echo > /tmp/ansible-tmp-1415576481.52-82470479460561' > > But when I print out the stderr output from the commands, they are very > different: > > Server 1 (failed): > > OpenSSH_5.3p1, OpenSSL 1.0.1e-fips 11 Feb 2013 > debug1: Reading configuration data /etc/ssh/ssh_config > debug1: Applying options for * > debug1: auto-mux: Trying existing master > debug1: Control socket > "/home/user/.ansible/cp/ansible-ssh-server1-22-user" does not exist > debug2: ssh_connect: needpriv 0 > debug1: Connecting to server1 [[server1 IP]] port 22. > debug2: fd 3 setting O_NONBLOCK > debug1: fd 3 clearing O_NONBLOCK > debug1: Connection established. > debug3: timeout: 30000 ms remain after connect > debug1: identity file /home/user/.ssh/identity type -1 > debug1: identity file /home/user/.ssh/identity-cert type -1 > debug3: Not a RSA1 key file /home/user/.ssh/id_rsa. > debug2: key_type_from_name: unknown key type '-----BEGIN' > debug3: key_read: missing keytype > debug3: key_read: missing whitespace > debug3: key_read: missing whitespace > debug3: key_read: missing whitespace > debug3: key_read: missing whitespace > debug3: key_read: missing whitespace > debug3: key_read: missing whitespace > debug3: key_read: missing whitespace > debug3: key_read: missing whitespace > debug3: key_read: missing whitespace > debug3: key_read: missing whitespace > debug3: key_read: missing whitespace > debug3: key_read: missing whitespace > debug3: key_read: missing whitespace > debug3: key_read: missing whitespace > debug3: key_read: missing whitespace > debug3: key_read: missing whitespace > debug3: key_read: missing whitespace > debug3: key_read: missing whitespace > debug3: key_read: missing whitespace > debug3: key_read: missing whitespace > debug3: key_read: missing whitespace > debug3: key_read: missing whitespace > debug3: key_read: missing whitespace > debug3: key_read: missing whitespace > debug3: key_read: missing whitespace > debug2: key_type_from_name: unknown key type '-----END' > debug3: key_read: missing keytype > debug1: identity file /home/user/.ssh/id_rsa type 1 > debug1: identity file /home/user/.ssh/id_rsa-cert type -1 > debug1: identity file /home/user/.ssh/id_dsa type -1 > debug1: identity file /home/user/.ssh/id_dsa-cert type -1 > debug1: identity file /home/user/.ssh/id_ecdsa type -1 > debug1: identity file /home/user/.ssh/id_ecdsa-cert 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 960 bytes for a total of 981 > debug1: SSH2_MSG_KEXINIT received > debug2: kex_parse_kexinit: > diffie-hellman-group-exchange-sha256,diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1 > debug2: kex_parse_kexinit: [email protected], > [email protected],[email protected], > [email protected],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,aes256-cbc,arcfour, > [email protected] > debug2: kex_parse_kexinit: > aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour, > [email protected] > debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,[email protected] > ,hmac-sha2-256,hmac-sha2-512,hmac-ripemd160,[email protected] > ,hmac-sha1-96,hmac-md5-96 > debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,[email protected] > ,hmac-sha2-256,hmac-sha2-512,hmac-ripemd160,[email protected] > ,hmac-sha1-96,hmac-md5-96 > debug2: kex_parse_kexinit: [email protected],zlib,none > debug2: kex_parse_kexinit: [email protected],zlib,none > 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-hellman-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,aes256-cbc,arcfour, > [email protected] > debug2: kex_parse_kexinit: > aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour, > [email protected] > debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,[email protected] > ,hmac-ripemd160,[email protected],hmac-sha1-96,hmac-md5-96 > debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,[email protected] > ,hmac-ripemd160,[email protected],hmac-sha1-96,hmac-md5-96 > debug2: kex_parse_kexinit: none,[email protected] > debug2: kex_parse_kexinit: none,[email protected] > 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 [email protected] > debug2: mac_setup: found hmac-md5 > debug1: kex: client->server aes128-ctr hmac-md5 [email protected] > 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 1005 > debug2: dh_gen_key: priv key bits set: 146/256 > debug2: bits set: 521/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 1149 > debug3: check_host_in_hostfile: host server1 filename > /home/user/.ssh/known_hosts > debug3: check_host_in_hostfile: host server1 filename > /home/user/.ssh/known_hosts > debug3: check_host_in_hostfile: match line 9 > debug3: check_host_in_hostfile: host [server1 IP] filename > /home/user/.ssh/known_hosts > debug3: check_host_in_hostfile: host [server1 IP] filename > /home/user/.ssh/known_hosts > debug3: check_host_in_hostfile: match line 10 > debug1: Host 'server1' is known and matches the RSA host key. > debug1: Found key in /home/user/.ssh/known_hosts:9 > debug2: bits set: 501/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 1165 > debug2: set_newkeys: mode 0 > debug1: SSH2_MSG_NEWKEYS received > debug1: SSH2_MSG_SERVICE_REQUEST sent > debug3: Wrote 48 bytes for a total of 1213 > debug2: service_accept: ssh-userauth > debug1: SSH2_MSG_SERVICE_ACCEPT received > debug2: key: /home/user/.ssh/identity ((nil)) > debug2: key: /home/user/.ssh/id_rsa (0x7f4dc338f2d0) > debug2: key: /home/user/.ssh/id_dsa ((nil)) > debug2: key: /home/user/.ssh/id_ecdsa ((nil)) > debug3: Wrote 64 bytes for a total of 1277 > debug1: Authentications that can continue: > publickey,gssapi-keyex,gssapi-with-mic,password > debug3: start over, passed a different list > publickey,gssapi-keyex,gssapi-with-mic,password > debug3: preferred gssapi-with-mic,gssapi-keyex,hostbased,publickey > debug3: authmethod_lookup gssapi-with-mic > debug3: remaining preferred: gssapi-keyex,hostbased,publickey > debug3: authmethod_is_enabled gssapi-with-mic > debug1: Next authentication method: gssapi-with-mic > debug3: Trying to reverse map address [server1 IP]. > debug1: Unspecified GSS failure. Minor code may provide more information > Credentials cache file '/tmp/krb5cc_12444' not found > > debug1: Unspecified GSS failure. Minor code may provide more information > Credentials cache file '/tmp/krb5cc_12444' not found > > debug1: Unspecified GSS failure. Minor code may provide more information > > > debug1: Unspecified GSS failure. Minor code may provide more information > Credentials cache file '/tmp/krb5cc_12444' not found > > debug2: we did not send a packet, disable method > debug3: authmethod_lookup gssapi-keyex > debug3: remaining preferred: hostbased,publickey > debug3: authmethod_is_enabled gssapi-keyex > debug1: Next authentication method: gssapi-keyex > debug1: No valid Key exchange context > debug2: we did not send a packet, disable method > debug3: authmethod_lookup publickey > debug3: remaining preferred: ,publickey > debug3: authmethod_is_enabled publickey > debug1: Next authentication method: publickey > debug1: Trying private key: /home/user/.ssh/identity > debug3: no such identity: /home/user/.ssh/identity > debug1: Offering public key: /home/user/.ssh/id_rsa > debug3: send_pubkey_test > debug2: we sent a publickey packet, wait for reply > debug3: Wrote 368 bytes for a total of 1645 > debug1: Server accepts key: pkalg ssh-rsa blen 277 > debug2: input_userauth_pk_ok: SHA1 fp > d3:31:a6:e5:17:09:6c:cb:aa:f1:02:85:5f:fc:e9:94:56:e5:3e:d1 > debug3: sign_and_send_pubkey: RSA > d3:31:a6:e5:17:09:6c:cb:aa:f1:02:85:5f:fc:e9:94:56:e5:3e:d1 > debug1: read PEM private key done: type RSA > debug3: Wrote 640 bytes for a total of 2285 > debug1: Enabling compression at level 6. > debug1: Authentication succeeded (publickey). > debug1: setting up multiplex master socket > debug3: muxserver_listen: temporary control path > /home/user/.ansible/cp/ansible-ssh-server1-22-user.FZ7QTgXgs6oGvNas > debug2: fd 4 setting O_NONBLOCK > debug3: fd 4 is O_NONBLOCK > debug3: fd 4 is O_NONBLOCK > debug1: channel 0: new > [/home/user/.ansible/cp/ansible-ssh-server1-22-user.FZ7QTgXgs6oGvNas] > debug3: muxserver_listen: mux listener channel 0 fd 4 > debug1: Entering interactive session. > debug2: set_control_persist_exit_time: schedule exit in 60 seconds > > Server 2 (ok): > > OpenSSH_5.3p1, OpenSSL 1.0.1e-fips 11 Feb 2013 > debug1: Reading configuration data /etc/ssh/ssh_config > debug1: Applying options for * > debug1: auto-mux: Trying existing master > debug2: fd 3 setting O_NONBLOCK > debug2: mux_client_hello_exchange: master version 4 > debug3: mux_client_request_forwards: requesting forwardings: 0 local, 0 > remote > debug3: mux_client_request_session: entering > debug3: mux_client_request_alive: entering > debug3: mux_client_request_alive: done pid = 18226 > debug3: mux_client_request_session: session request sent > debug1: mux_client_request_session: master session id: 2 > debug1: mux_client_request_session: master session id: 2 > debug3: mux_client_read_packet: read header failed: Broken pipe > debug2: Received exit status from master 0 > Shared connection to server2 closed. > > > I'm not familiar with SSH, so I don't understand much what's going on in > the failing case. It looks to me like it's trying out different > authentication methods, and eventually is successful. (For authentication, > I have keys set up in authorized_keys in both servers.) > > Version info: > > control: > CentOS release 6.6 (Final) > Python 2.7.3 > openssh.x86_64 5.3p1-104.el6 > > server1: > CentOS release 6.2 (Final) > Python 2.6.6 > openssh.x86_64 5.3p1-70.el6 > > server2: > CentOS release 6.2 (Final) > Python 2.6.6 > openssh.x86_64 5.3p1-70.el6 > > > I hope someone could shed some light on this, or at least be able to > propose a workaround, so I could get it to work. > > > Paavo > > -- You received this message because you are subscribed to the Google Groups "Ansible Project" group. To unsubscribe from this group and stop receiving emails from it, send an email to [email protected]. To post to this group, send email to [email protected]. To view this discussion on the web visit https://groups.google.com/d/msgid/ansible-project/bd7c0fe6-f00d-41bf-81c7-48d161c22c90%40googlegroups.com. For more options, visit https://groups.google.com/d/optout.
