Debug output related to the Ansible issue #13278. Running Ansible 2.0.1.0 against Ubuntu 14.04 Ec2 server. When Ansible initiate the first shell command it fails with the timeout error, when the command runs for a second time it just works.

0-ansible-issue-13278-cmd.log

ANSIBLE_DEBUG=y ansible <EC2_ID> -s -m shell -a '/bin/true' -vvvvv

1-ansible-issue-13278-debug-failue-log.log

20852 1459837712.80784: starting run
Using /etc/ansible/ansible.cfg as config file
Loaded callback minimal of type stdout, v2.0
 20852 1459837715.85448: in VariableManager get_vars()
 20852 1459837715.85485: done with get_vars()
 20852 1459837715.86447: getting the remaining hosts for this loop
 20852 1459837715.86486: done getting the remaining hosts for this loop
 20852 1459837715.86513: building list of next tasks for hosts
 20852 1459837715.86527: getting the next task for host 10.5.161.14
 20852 1459837715.86543: done getting next task for host 10.5.161.14
 20852 1459837715.86556:  ^ task is: TASK: meta
 20852 1459837715.86572:  ^ state is: HOST STATE: block=1, task=1, rescue=0, always=0, role=None, run_state=ITERATING_TASKS, fail_state=FAILED_NONE, pending_setup=False, tasks child state? None, rescue child state? None, always child state? None
 20852 1459837715.86584: done building task lists
 20852 1459837715.86595: counting tasks in each state of execution
 20852 1459837715.86606: done counting tasks in each state of execution
 20852 1459837715.86617: advancing hosts in ITERATING_TASKS
 20852 1459837715.86628: starting to advance hosts
 20852 1459837715.86639: getting the next task for host 10.5.161.14
 20852 1459837715.86652: done getting next task for host 10.5.161.14
 20852 1459837715.86664:  ^ task is: TASK: meta
 20852 1459837715.86675:  ^ state is: HOST STATE: block=1, task=1, rescue=0, always=0, role=None, run_state=ITERATING_TASKS, fail_state=FAILED_NONE, pending_setup=False, tasks child state? None, rescue child state? None, always child state? None
 20852 1459837715.86686: done advancing hosts to next task
 20852 1459837715.86847: done queuing things up, now waiting for results queue to drain
 20852 1459837715.86861: waiting for pending results...
 20852 1459837715.86873: no more pending results, returning what we have
 20852 1459837715.86885: results queue empty
 20852 1459837715.86896: checking for any_errors_fatal
 20852 1459837715.86908: done checking for any_errors_fatal
 20852 1459837715.86918: getting the remaining hosts for this loop
 20852 1459837715.86931: done getting the remaining hosts for this loop
 20852 1459837715.86957: building list of next tasks for hosts
 20852 1459837715.86974: getting the next task for host 10.5.161.14
 20852 1459837715.86988: done getting next task for host 10.5.161.14
 20852 1459837715.87000:  ^ task is: TASK: command
 20852 1459837715.87012:  ^ state is: HOST STATE: block=2, task=1, rescue=0, always=0, role=None, run_state=ITERATING_TASKS, fail_state=FAILED_NONE, pending_setup=False, tasks child state? None, rescue child state? None, always child state? None
 20852 1459837715.87024: done building task lists
 20852 1459837715.87034: counting tasks in each state of execution
 20852 1459837715.87045: done counting tasks in each state of execution
 20852 1459837715.87056: advancing hosts in ITERATING_TASKS
 20852 1459837715.87066: starting to advance hosts
 20852 1459837715.87077: getting the next task for host 10.5.161.14
 20852 1459837715.87091: done getting next task for host 10.5.161.14
 20852 1459837715.87102:  ^ task is: TASK: command
 20852 1459837715.87113:  ^ state is: HOST STATE: block=2, task=1, rescue=0, always=0, role=None, run_state=ITERATING_TASKS, fail_state=FAILED_NONE, pending_setup=False, tasks child state? None, rescue child state? None, always child state? None
 20852 1459837715.87124: done advancing hosts to next task
 20852 1459837715.87139: getting variables
 20852 1459837715.87151: in VariableManager get_vars()
 20852 1459837715.87454: done with get_vars()
 20852 1459837715.87467: done getting variables
 20852 1459837715.87483: sending task start callback, copying the task so we can template it temporarily
 20852 1459837715.87496: done copying, going to template now
 20852 1459837715.87509: done templating
 20852 1459837715.87520: here goes the callback...
 20852 1459837715.87533: sending task start callback
 20852 1459837715.87546: entering _queue_task() for 10.5.161.14/TASK: command
 20852 1459837715.87560: 10.5.161.14 - putting task (TASK: command) in queue
 20852 1459837715.87572: worker is 1 (out of 1 available)
 20852 1459837715.87701: exiting _queue_task() for 10.5.161.14/TASK: command
 20852 1459837715.87749: done queuing things up, now waiting for results queue to drain
 20852 1459837715.87762: waiting for pending results...
 20865 1459837715.87965: running TaskExecutor() for 10.5.161.14/TASK: command
 20865 1459837715.87975: in run()
 20865 1459837715.88055: calling self._execute()
 20865 1459837715.89054: starting attempt loop
 20865 1459837715.89078: running the handler
 20865 1459837715.89211: _low_level_execute_command(): starting
 20865 1459837715.89228: _low_level_execute_command(): using become for this command
 20865 1459837715.89254: _low_level_execute_command(): executing: /bin/sh -c 'sudo -H -S -n -u root /bin/sh -c '"'"'echo BECOME-SUCCESS-yffexzkoeiqeoaehdhjwkdfhvefytidq; /bin/sh -c '"'"'"'"'"'"'"'"'LANG=en_US.UTF-8 LC_ALL=en_US.UTF-8 LC_MESSAGES=en_US.UTF-8 /usr/bin/python'"'"'"'"'"'"'"'"''"'"''
<10.5.161.14> ESTABLISH SSH CONNECTION FOR USER: ubuntu
<10.5.161.14> SSH: ansible.cfg set ssh_args: (-o)(ControlMaster=auto)(-o)(ControlPersist=30m)
<10.5.161.14> SSH: ANSIBLE_PRIVATE_KEY_FILE/private_key_file/ansible_ssh_private_key_file set: (-o)(IdentityFile="/root/.ssh/ops.key")
<10.5.161.14> SSH: ansible_password/ansible_ssh_pass not set: (-o)(KbdInteractiveAuthentication=no)(-o)(PreferredAuthentications=gssapi-with-mic,gssapi-keyex,hostbased,publickey)(-o)(PasswordAuthentication=no)
<10.5.161.14> SSH: ANSIBLE_REMOTE_USER/remote_user/ansible_user/user/-u set: (-o)(User=ubuntu)
<10.5.161.14> SSH: ANSIBLE_TIMEOUT/timeout set: (-o)(ConnectTimeout=10)
<10.5.161.14> SSH: PlayContext set ssh_common_args: ()
<10.5.161.14> SSH: PlayContext set ssh_extra_args: ()
<10.5.161.14> SSH: found only ControlPersist; added ControlPath: (-o)(ControlPath=/root/.ansible/cp/ansible-ssh-%h-%p-%r)
<10.5.161.14> SSH: EXEC ssh -C -vvv -o ControlMaster=auto -o ControlPersist=30m -o 'IdentityFile="/root/.ssh/ops.key"' -o KbdInteractiveAuthentication=no -o PreferredAuthentications=gssapi-with-mic,gssapi-keyex,hostbased,publickey -o PasswordAuthentication=no -o User=ubuntu -o ConnectTimeout=10 -o ControlPath=/root/.ansible/cp/ansible-ssh-%h-%p-%r 10.5.161.14 '/bin/sh -c '"'"'sudo -H -S -n -u root /bin/sh -c '"'"'"'"'"'"'"'"'echo BECOME-SUCCESS-yfeexzkoeiqeoaehahjwkdfhvefytidq; /bin/sh -c '"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'LANG=en_US.UTF-8 LC_ALL=en_US.UTF-8 LC_MESSAGES=en_US.UTF-8 /usr/bin/python'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"''"'"'"'"'"'"'"'"''"'"''
 20865 1459837715.89609: Initial state: awaiting_escalation: BECOME-SUCCESS-yfeexzkoeiqeoaehahjwkdfhvefytidq
 20865 1459837715.89874: stderr chunk (state=1):
>>>OpenSSH_6.6.1, OpenSSL 1.0.1f 6 Jan 2014
debug1: Reading configuration data /root/.ssh/config
debug1: /root/.ssh/config line 2: Applying options for *
<<<

 20865 1459837715.90013: stderr chunk (state=1):
>>>debug1: Reading configuration data /etc/ssh/ssh_config
debug1: /etc/ssh/ssh_config line 19: Applying options for *
debug1: auto-mux: Trying existing master
debug1: Control socket "/root/.ansible/cp/ansible-ssh-10.5.161.14-22-ubuntu" does not exist
debug2: ssh_connect: needpriv 0
debug1: Connecting to 10.5.161.14 [10.5.161.14] port 22.
debug2: fd 3 setting O_NONBLOCK
debug1: fd 3 clearing O_NONBLOCK
debug1: Connection established.
debug3: timeout: 10000 ms remain after connect
debug1: permanently_set_uid: 0/0
debug3: Incorrect RSA1 identifier
debug3: Could not load "/root/.ssh/ops.key" as a RSA1 public key
debug1: identity file /root/.ssh/ops.key type -1
debug1: identity file /root/.ssh/ops.key-cert type -1
debug1: Enabling compatibility mode for protocol 2.0
debug1: Local version string SSH-2.0-OpenSSH_6.6.1p1 Ubuntu-2ubuntu2.4
<<<

 20865 1459837715.90440: stderr chunk (state=1):
>>>debug1: Remote protocol version 2.0, remote software version OpenSSH_6.6.1p1 Ubuntu-2ubuntu2.6
debug1: match: OpenSSH_6.6.1p1 Ubuntu-2ubuntu2.6 pat OpenSSH_6.6.1* compat 0x04000000
debug2: fd 3 setting O_NONBLOCK
debug3: load_hostkeys: loading entries for host "10.5.161.14" from file "/root/.ssh/known_hosts"
<<<

 20865 1459837715.90823: stderr chunk (state=1):
>>>debug3: load_hostkeys: loaded 0 keys
<<<

 20865 1459837715.90875: stderr chunk (state=1):
>>>debug1: SSH2_MSG_KEXINIT sent
debug1: SSH2_MSG_KEXINIT received
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
debug2: kex_parse_kexinit: ecdsa-sha2-nistp256-cert-v01@openssh.com,ecdsa-sha2-nistp384-cert-v01@openssh.com,ecdsa-sha2-nistp521-cert-v01@openssh.com,ssh-ed25519-cert-v01@openssh.com,ssh-rsa-cert-v01@openssh.com,ssh-dss-cert-v01@openssh.com,ssh-rsa-cert-v00@openssh.com,ssh-dss-cert-v00@openssh.com,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,ssh-ed25519,ssh-rsa,ssh-dss
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
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
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
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
debug2: kex_parse_kexinit: zlib@openssh.com,zlib,none
debug2: kex_parse_kexinit: zlib@openssh.com,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: 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
debug2: kex_parse_kexinit: ssh-rsa,ssh-dss,ecdsa-sha2-nistp256,ssh-ed25519
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
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
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
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
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: setup hmac-md5-etm@openssh.com
debug1: kex: server->client aes128-ctr hmac-md5-etm@openssh.com zlib@openssh.com
debug2: mac_setup: setup hmac-md5-etm@openssh.com
debug1: kex: client->server aes128-ctr hmac-md5-etm@openssh.com zlib@openssh.com
<<<

 20865 1459837715.91635: stderr chunk (state=1):
>>>debug1: sending SSH2_MSG_KEX_ECDH_INIT
debug1: expecting SSH2_MSG_KEX_ECDH_REPLY
debug1: Server host key: ECDSA ea:59:55:a6:28:bf:3a:80:ca:b5:e1:d8:32:7d:0e:78
debug3: load_hostkeys: loading entries for host "10.5.161.14" from file "/root/.ssh/known_hosts"
<<<

 20865 1459837715.91909: stderr chunk (state=1):
>>>debug3: load_hostkeys: loaded 0 keys
<<<

 20865 1459837715.91955: stderr chunk (state=1):
>>>Warning: Permanently added '10.5.161.14' (ECDSA) to the list of known hosts.
<<<

 20865 1459837715.92242: stderr chunk (state=1):
>>>debug1: ssh_ecdsa_verify: signature correct
debug2: kex_derive_keys
debug2: set_newkeys: mode 1
<<<

 20865 1459837715.92339: stderr chunk (state=1):
>>>debug1: SSH2_MSG_NEWKEYS sent
debug1: expecting SSH2_MSG_NEWKEYS
debug2: set_newkeys: mode 0
debug1: SSH2_MSG_NEWKEYS received
debug1: SSH2_MSG_SERVICE_REQUEST sent
<<<

 20865 1459837715.95987: stderr chunk (state=1):
>>>debug2: service_accept: ssh-userauth
debug1: SSH2_MSG_SERVICE_ACCEPT received
debug2: key: /root/.ssh/ops.key ((nil)), explicit
<<<

 20865 1459837715.96306: stderr chunk (state=1):
>>>debug1: Authentications that can continue: publickey
debug3: start over, passed a different list publickey
debug3: preferred gssapi-with-mic,gssapi-keyex,hostbased,publickey
debug3: authmethod_lookup publickey
debug3: remaining preferred: ,gssapi-keyex,hostbased,publickey
debug3: authmethod_is_enabled publickey
debug1: Next authentication method: publickey
debug1: Trying private key: /root/.ssh/ops.key
debug1: key_parse_private2: missing begin marker
<<<

 20865 1459837715.96546: stderr chunk (state=1):
>>>debug1: read PEM private key done: type RSA
debug3: sign_and_send_pubkey: RSA 68:df:b8:13:1d:b1:b6:9b:4d:be:5b:13:fc:09:06:88
debug2: we sent a publickey packet, wait for reply
<<<

 20865 1459837716.01393: stderr chunk (state=1):
>>>debug1: Enabling compression at level 6.
<<<

 20865 1459837716.01454: stderr chunk (state=1):
>>>debug1: Authentication succeeded (publickey).
Authenticated to 10.5.161.14 ([10.5.161.14]:22).
debug1: setting up multiplex master socket
debug3: muxserver_listen: temporary control path /root/.ansible/cp/ansible-ssh-10.5.161.14-22-ubuntu.VNT2Gj0ijYEWsNg6
debug2: fd 4 setting O_NONBLOCK
debug3: fd 4 is O_NONBLOCK
debug3: fd 4 is O_NONBLOCK
debug1: channel 0: new [/root/.ansible/cp/ansible-ssh-10.5.161.14-22-ubuntu]
debug3: muxserver_listen: mux listener channel 0 fd 4
debug2: fd 3 setting TCP_NODELAY
debug3: packet_set_tos: set IP_TOS 0x08
debug1: control_persist_detach: backgrounding master process
debug2: control_persist_detach: background process is 20868
debug2: fd 4 setting O_NONBLOCK
debug1: forking to background
<<<

 20865 1459837716.01857: stderr chunk (state=1):
>>>debug1: Entering interactive session.
debug2: set_control_persist_exit_time: schedule exit in 1800 seconds
debug1: multiplexing control connection
debug2: fd 5 setting O_NONBLOCK
debug3: fd 5 is O_NONBLOCK
debug1: channel 1: new [mux-control]
debug3: channel_post_mux_listener: new mux channel 1 fd 5
debug3: mux_master_read_cb: channel 1: hello sent
debug2: set_control_persist_exit_time: cancel scheduled exit
debug3: mux_master_read_cb: channel 1 packet type 0x00000001 len 4
debug2: process_mux_master_hello: channel 1 slave version 4
debug2: mux_client_hello_exchange: master version 4
debug3: mux_client_forwards: request forwardings: 0 local, 0 remote
debug3: mux_client_request_session: entering
debug3: mux_client_request_alive: entering
debug3: mux_master_read_cb: channel 1 packet type 0x10000004 len 4
debug2: process_mux_alive_check: channel 1: alive check
debug3: mux_client_request_alive: done pid = 20870
debug3: mux_client_request_session: session request sent
debug3: mux_master_read_cb: channel 1 packet type 0x10000002 len 291
debug2: process_mux_new_session: channel 1: request tty 0, X 0, agent 0, subsys 0, term "xterm", cmd "/bin/sh -c 'sudo -H -S -n -u root /bin/sh -c '"'"'echo BECOME-SUCCESS-yfeexzkoeiqeoaehahjwkdfhvefytidq; /bin/sh -c '"'"'"'"'"'"'"'"'LANG=en_US.UTF-8 LC_ALL=en_US.UTF-8 LC_MESSAGES=en_US.UTF-8 /usr/bin/python'"'"'"'"'"'"'"'"''"'"''", env 1
debug3: process_mux_new_session: got fds stdin 6, stdout 7, stderr 8
debug2: fd 6 setting O_NONBLOCK
debug2: fd 7 setting O_NONBLOCK
debug2: fd 8 setting O_NONBLOCK
debug1: channel 2: new [client-session]
debug2: process_mux_new_session: channel_new: 2 linked to control channel 1
debug2: channel 2: send open
<<<

 20865 1459837728.02607: done running TaskExecutor() for 10.5.161.14/TASK: command
 20865 1459837728.02617: sending task result
 20865 1459837728.02657: done sending task result
 20865 1459837728.02750: WORKER PROCESS EXITING
 20864 1459837728.02762: worker 0 has data to read
 20864 1459837728.02878: got a result from worker 0: <ansible.executor.task_result.TaskResult object at 0x7f5eec815a10>
 20864 1459837728.02890: sending result: [u'host_task_failed', u'<ansible.executor.task_result.TaskResult object at 0x7f5eec815a10>']
 20864 1459837728.02932: done sending result
 20852 1459837728.03090: got result from result worker: [u'host_task_failed', u'<ansible.executor.task_result.TaskResult object at 0x7f5eed8f1cd0>']
 20852 1459837728.03117: marking 10.5.161.14 as failed
10.5.161.14 | FAILED | rc=0 >>
Timeout (12s) waiting for privilege escalation prompt: 

 20852 1459837728.03181: no more pending results, returning what we have
 20852 1459837728.03199: results queue empty
 20852 1459837728.03211: checking for any_errors_fatal
 20852 1459837728.03226: done checking for any_errors_fatal
 20852 1459837728.03238: getting the remaining hosts for this loop
 20852 1459837728.03255: done getting the remaining hosts for this loop
 20852 1459837728.03282: building list of next tasks for hosts
 20852 1459837728.03297: done building task lists
 20852 1459837728.03309: counting tasks in each state of execution
 20852 1459837728.03322: done counting tasks in each state of execution
 20852 1459837728.03333: all hosts are done, so returning None's for all hosts
 20852 1459837728.03347: done queuing things up, now waiting for results queue to drain
 20852 1459837728.03358: waiting for pending results...
 20852 1459837728.03374: no more pending results, returning what we have
 20852 1459837728.03388: out of hosts to run on
 20852 1459837728.03402: running handlers
 20852 1459837728.03429: RUNNING CLEANUP

2-ansible-issue-13278-debug-success-log.log

 21244 1459838233.62192: starting run
Using /etc/ansible/ansible.cfg as config file
Loaded callback minimal of type stdout, v2.0
 21244 1459838236.86854: in VariableManager get_vars()
 21244 1459838236.86891: done with get_vars()
 21244 1459838236.87851: getting the remaining hosts for this loop
 21244 1459838236.87890: done getting the remaining hosts for this loop
 21244 1459838236.87916: building list of next tasks for hosts
 21244 1459838236.87930: getting the next task for host 10.5.161.14
 21244 1459838236.87946: done getting next task for host 10.5.161.14
 21244 1459838236.87960:  ^ task is: TASK: meta
 21244 1459838236.87973:  ^ state is: HOST STATE: block=1, task=1, rescue=0, always=0, role=None, run_state=ITERATING_TASKS, fail_state=FAILED_NONE, pending_setup=False, tasks child state? None, rescue child state? None, always child state? None
 21244 1459838236.87985: done building task lists
 21244 1459838236.87996: counting tasks in each state of execution
 21244 1459838236.88008: done counting tasks in each state of execution
 21244 1459838236.88019: advancing hosts in ITERATING_TASKS
 21244 1459838236.88029: starting to advance hosts
 21244 1459838236.88040: getting the next task for host 10.5.161.14
 21244 1459838236.88053: done getting next task for host 10.5.161.14
 21244 1459838236.88065:  ^ task is: TASK: meta
 21244 1459838236.88076:  ^ state is: HOST STATE: block=1, task=1, rescue=0, always=0, role=None, run_state=ITERATING_TASKS, fail_state=FAILED_NONE, pending_setup=False, tasks child state? None, rescue child state? None, always child state? None
 21244 1459838236.88087: done advancing hosts to next task
 21244 1459838236.88255: done queuing things up, now waiting for results queue to drain
 21244 1459838236.88269: waiting for pending results...
 21244 1459838236.88282: no more pending results, returning what we have
 21244 1459838236.88294: results queue empty
 21244 1459838236.88305: checking for any_errors_fatal
 21244 1459838236.88316: done checking for any_errors_fatal
 21244 1459838236.88328: getting the remaining hosts for this loop
 21244 1459838236.88341: done getting the remaining hosts for this loop
 21244 1459838236.88366: building list of next tasks for hosts
 21244 1459838236.88379: getting the next task for host 10.5.161.14
 21244 1459838236.88392: done getting next task for host 10.5.161.14
 21244 1459838236.88404:  ^ task is: TASK: command
 21244 1459838236.88417:  ^ state is: HOST STATE: block=2, task=1, rescue=0, always=0, role=None, run_state=ITERATING_TASKS, fail_state=FAILED_NONE, pending_setup=False, tasks child state? None, rescue child state? None, always child state? None
 21244 1459838236.88428: done building task lists
 21244 1459838236.88438: counting tasks in each state of execution
 21244 1459838236.88449: done counting tasks in each state of execution
 21244 1459838236.88461: advancing hosts in ITERATING_TASKS
 21244 1459838236.88472: starting to advance hosts
 21244 1459838236.88483: getting the next task for host 10.5.161.14
 21244 1459838236.88496: done getting next task for host 10.5.161.14
 21244 1459838236.88508:  ^ task is: TASK: command
 21244 1459838236.88520:  ^ state is: HOST STATE: block=2, task=1, rescue=0, always=0, role=None, run_state=ITERATING_TASKS, fail_state=FAILED_NONE, pending_setup=False, tasks child state? None, rescue child state? None, always child state? None
 21244 1459838236.88532: done advancing hosts to next task
 21244 1459838236.88547: getting variables
 21244 1459838236.88559: in VariableManager get_vars()
 21244 1459838236.88868: done with get_vars()
 21244 1459838236.88882: done getting variables
 21244 1459838236.88897: sending task start callback, copying the task so we can template it temporarily
 21244 1459838236.88911: done copying, going to template now
 21244 1459838236.88924: done templating
 21244 1459838236.88936: here goes the callback...
 21244 1459838236.88949: sending task start callback
 21244 1459838236.88962: entering _queue_task() for 10.5.161.14/TASK: command
 21244 1459838236.88978: 10.5.161.14 - putting task (TASK: command) in queue
 21244 1459838236.88990: worker is 1 (out of 1 available)
 21244 1459838236.89114: exiting _queue_task() for 10.5.161.14/TASK: command
 21244 1459838236.89164: done queuing things up, now waiting for results queue to drain
 21244 1459838236.89178: waiting for pending results...
 21259 1459838236.89363: running TaskExecutor() for 10.5.161.14/TASK: command
 21259 1459838236.89375: in run()
 21259 1459838236.89456: calling self._execute()
 21259 1459838236.90508: starting attempt loop
 21259 1459838236.90531: running the handler
 21259 1459838236.90683: _low_level_execute_command(): starting
 21259 1459838236.90699: _low_level_execute_command(): using become for this command
 21259 1459838236.90726: _low_level_execute_command(): executing: /bin/sh -c 'sudo -H -S -n -u root /bin/sh -c '"'"'echo BECOME-SUCCESS-whdkxatcdwgguljlghdawdmtshnphrnn; /bin/sh -c '"'"'"'"'"'"'"'"'LANG=en_US.UTF-8 LC_ALL=en_US.UTF-8 LC_MESSAGES=en_US.UTF-8 /usr/bin/python'"'"'"'"'"'"'"'"''"'"''
<10.5.161.14> ESTABLISH SSH CONNECTION FOR USER: ubuntu
<10.5.161.14> SSH: ansible.cfg set ssh_args: (-o)(ControlMaster=auto)(-o)(ControlPersist=30m)
<10.5.161.14> SSH: ANSIBLE_PRIVATE_KEY_FILE/private_key_file/ansible_ssh_private_key_file set: (-o)(IdentityFile="/root/.ssh/ops.key")
<10.5.161.14> SSH: ansible_password/ansible_ssh_pass not set: (-o)(KbdInteractiveAuthentication=no)(-o)(PreferredAuthentications=gssapi-with-mic,gssapi-keyex,hostbased,publickey)(-o)(PasswordAuthentication=no)
<10.5.161.14> SSH: ANSIBLE_REMOTE_USER/remote_user/ansible_user/user/-u set: (-o)(User=ubuntu)
<10.5.161.14> SSH: ANSIBLE_TIMEOUT/timeout set: (-o)(ConnectTimeout=10)
<10.5.161.14> SSH: PlayContext set ssh_common_args: ()
<10.5.161.14> SSH: PlayContext set ssh_extra_args: ()
<10.5.161.14> SSH: found only ControlPersist; added ControlPath: (-o)(ControlPath=/root/.ansible/cp/ansible-ssh-%h-%p-%r)
<10.5.161.14> SSH: EXEC ssh -C -vvv -o ControlMaster=auto -o ControlPersist=30m -o 'IdentityFile="/root/.ssh/ops.key"' -o KbdInteractiveAuthentication=no -o PreferredAuthentications=gssapi-with-mic,gssapi-keyex,hostbased,publickey -o PasswordAuthentication=no -o User=ubuntu -o ConnectTimeout=10 -o ControlPath=/root/.ansible/cp/ansible-ssh-%h-%p-%r 10.5.161.14 '/bin/sh -c '"'"'sudo -H -S -n -u root /bin/sh -c '"'"'"'"'"'"'"'"'echo BECOME-SUCCESS-whdkxatcjwgguljlghdawdmtshnphrnn; /bin/sh -c '"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'LANG=en_US.UTF-8 LC_ALL=en_US.UTF-8 LC_MESSAGES=en_US.UTF-8 /usr/bin/python'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"''"'"'"'"'"'"'"'"''"'"''
 21259 1459838236.91064: Initial state: awaiting_escalation: BECOME-SUCCESS-whdkxatcjwgguljlghdawdmtshnphrnn
 21259 1459838236.91338: stderr chunk (state=1):
>>>OpenSSH_6.6.1, OpenSSL 1.0.1f 6 Jan 2014
debug1: Reading configuration data /root/.ssh/config
debug1: /root/.ssh/config line 2: Applying options for *
<<<

 21259 1459838236.91460: stderr chunk (state=1):
>>>debug1: Reading configuration data /etc/ssh/ssh_config
debug1: /etc/ssh/ssh_config line 19: 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_forwards: request forwardings: 0 local, 0 remote
debug3: mux_client_request_session: entering
debug3: mux_client_request_alive: entering
debug3: mux_client_request_alive: done pid = 20870
debug3: mux_client_request_session: session request sent
<<<

 21259 1459838236.91708: stderr chunk (state=1):
>>>debug1: mux_client_request_session: master session id: 2
<<<

 21259 1459838236.93578: stdout chunk (state=1):
>>>BECOME-SUCCESS-whdkxatcjwgguljlghdawdmtshnphrnn
<<<

 21259 1459838236.93595: become_success: (source=stdout, state=awaiting_escalation): 'BECOME-SUCCESS-whdkxatcjwgguljlghdawdmtshnphrnn'
 21259 1459838236.93608: Escalation succeeded
 21259 1459838236.93621: Sending initial data
 21259 1459838236.93703: Sent initial data (90646 bytes)
 21259 1459838237.01147: stdout chunk (state=3):
>>>{"changed": true, "end": "2016-04-05 06:37:16.947387", "stdout": "", "cmd": "/bin/true", "rc": 0, "start": "2016-04-05 06:37:16.944292", "stderr": "", "delta": "0:00:00.003095", "invocation": {"module_args": {"warn": true, "executable": null, "_uses_shell": true, "_raw_params": "/bin/true", "removes": null, "creates": null, "chdir": null, "_ansible_debug": true}}, "warnings": []}
<<<

 21259 1459838237.02344: stderr chunk (state=3):
>>>debug3: mux_client_read_packet: read header failed: Broken pipe
debug2: Received exit status from master 0
<<<

 21259 1459838237.02369: stdout chunk (state=3):
>>><<<

 21259 1459838237.02382: stderr chunk (state=3):
>>><<<

 21259 1459838237.02399: _low_level_execute_command() done: rc=0, stdout={"changed": true, "end": "2016-04-05 06:37:16.947387", "stdout": "", "cmd": "/bin/true", "rc": 0, "start": "2016-04-05 06:37:16.944292", "stderr": "", "delta": "0:00:00.003095", "invocation": {"module_args": {"warn": true, "executable": null, "_uses_shell": true, "_raw_params": "/bin/true", "removes": null, "creates": null, "chdir": null, "_ansible_debug": true}}, "warnings": []}
, stderr=OpenSSH_6.6.1, OpenSSL 1.0.1f 6 Jan 2014
debug1: Reading configuration data /root/.ssh/config
debug1: /root/.ssh/config line 2: Applying options for *
debug1: Reading configuration data /etc/ssh/ssh_config
debug1: /etc/ssh/ssh_config line 19: 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_forwards: request forwardings: 0 local, 0 remote
debug3: mux_client_request_session: entering
debug3: mux_client_request_alive: entering
debug3: mux_client_request_alive: done pid = 20870
debug3: mux_client_request_session: session request sent
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

 21259 1459838237.02430: done with _execute_module (command, {u'_raw_params': u'/bin/true', '_uses_shell': True, '_ansible_debug': True})
 21259 1459838237.02449: handler run complete
 21259 1459838237.02469: attempt loop complete, returning result
 21259 1459838237.02483: _execute() done
 21259 1459838237.02495: dumping result to json
 21259 1459838237.02509: done dumping result, returning
 21259 1459838237.02525: done running TaskExecutor() for 10.5.161.14/TASK: command
 21259 1459838237.02533: sending task result
 21259 1459838237.02570: done sending task result
 21259 1459838237.02574: WORKER PROCESS EXITING
 21258 1459838237.02668: worker 0 has data to read
 21258 1459838237.02764: got a result from worker 0: <ansible.executor.task_result.TaskResult object at 0x7f11d31c58d0>
 21258 1459838237.02776: sending result: [u'host_task_ok', u'<ansible.executor.task_result.TaskResult object at 0x7f11d31c58d0>']
 21258 1459838237.02811: done sending result
 21244 1459838237.02956: got result from result worker: [u'host_task_ok', u'<ansible.executor.task_result.TaskResult object at 0x7f11d315cdd0>']
10.5.161.14 | SUCCESS | rc=0 >>


 21244 1459838237.03023: no more pending results, returning what we have
 21244 1459838237.03040: results queue empty
 21244 1459838237.03054: checking for any_errors_fatal
 21244 1459838237.03069: done checking for any_errors_fatal
 21244 1459838237.03082: getting the remaining hosts for this loop
 21244 1459838237.03100: done getting the remaining hosts for this loop
 21244 1459838237.03128: building list of next tasks for hosts
 21244 1459838237.03144: getting the next task for host 10.5.161.14
 21244 1459838237.03161: done getting next task for host 10.5.161.14
 21244 1459838237.03175:  ^ task is: TASK: meta
 21244 1459838237.03190:  ^ state is: HOST STATE: block=3, task=1, rescue=0, always=0, role=None, run_state=ITERATING_TASKS, fail_state=FAILED_NONE, pending_setup=False, tasks child state? None, rescue child state? None, always child state? None
 21244 1459838237.03204: done building task lists
 21244 1459838237.03217: counting tasks in each state of execution
 21244 1459838237.03231: done counting tasks in each state of execution
 21244 1459838237.03244: advancing hosts in ITERATING_TASKS
 21244 1459838237.03256: starting to advance hosts
 21244 1459838237.03270: getting the next task for host 10.5.161.14
 21244 1459838237.03285: done getting next task for host 10.5.161.14
 21244 1459838237.03299:  ^ task is: TASK: meta
 21244 1459838237.03313:  ^ state is: HOST STATE: block=3, task=1, rescue=0, always=0, role=None, run_state=ITERATING_TASKS, fail_state=FAILED_NONE, pending_setup=False, tasks child state? None, rescue child state? None, always child state? None
 21244 1459838237.03328: done advancing hosts to next task
 21244 1459838237.03349: done queuing things up, now waiting for results queue to drain
 21244 1459838237.03363: waiting for pending results...
 21244 1459838237.03378: no more pending results, returning what we have
 21244 1459838237.03391: results queue empty
 21244 1459838237.03405: checking for any_errors_fatal
 21244 1459838237.03417: done checking for any_errors_fatal
 21244 1459838237.03430: getting the remaining hosts for this loop
 21244 1459838237.03445: done getting the remaining hosts for this loop
 21244 1459838237.03472: building list of next tasks for hosts
 21244 1459838237.03487: getting the next task for host 10.5.161.14
 21244 1459838237.03502: done getting next task for host 10.5.161.14
 21244 1459838237.03516:  ^ task is: TASK: meta
 21244 1459838237.03530:  ^ state is: HOST STATE: block=4, task=1, rescue=0, always=0, role=None, run_state=ITERATING_TASKS, fail_state=FAILED_NONE, pending_setup=False, tasks child state? None, rescue child state? None, always child state? None
 21244 1459838237.03544: done building task lists
 21244 1459838237.03557: counting tasks in each state of execution
 21244 1459838237.03571: done counting tasks in each state of execution
 21244 1459838237.03583: advancing hosts in ITERATING_TASKS
 21244 1459838237.03596: starting to advance hosts
 21244 1459838237.03609: getting the next task for host 10.5.161.14
 21244 1459838237.03624: done getting next task for host 10.5.161.14
 21244 1459838237.03638:  ^ task is: TASK: meta
 21244 1459838237.03651:  ^ state is: HOST STATE: block=4, task=1, rescue=0, always=0, role=None, run_state=ITERATING_TASKS, fail_state=FAILED_NONE, pending_setup=False, tasks child state? None, rescue child state? None, always child state? None
 21244 1459838237.03665: done advancing hosts to next task
 21244 1459838237.03684: done queuing things up, now waiting for results queue to drain
 21244 1459838237.03698: waiting for pending results...
 21244 1459838237.03710: no more pending results, returning what we have
 21244 1459838237.03723: results queue empty
 21244 1459838237.03736: checking for any_errors_fatal
 21244 1459838237.03748: done checking for any_errors_fatal
 21244 1459838237.03760: getting the remaining hosts for this loop
 21244 1459838237.03777: done getting the remaining hosts for this loop
 21244 1459838237.03803: building list of next tasks for hosts
 21244 1459838237.03818: getting the next task for host 10.5.161.14
 21244 1459838237.03835: done getting next task for host 10.5.161.14
 21244 1459838237.03848:  ^ task is: None
 21244 1459838237.03861:  ^ state is: HOST STATE: block=5, task=0, rescue=0, always=0, role=None, run_state=ITERATING_COMPLETE, fail_state=FAILED_NONE, pending_setup=False, tasks child state? None, rescue child state? None, always child state? None
 21244 1459838237.03875: done building task lists
 21244 1459838237.03887: counting tasks in each state of execution
 21244 1459838237.03899: done counting tasks in each state of execution
 21244 1459838237.03912: all hosts are done, so returning None's for all hosts
 21244 1459838237.03925: done queuing things up, now waiting for results queue to drain
 21244 1459838237.03937: waiting for pending results...
 21244 1459838237.03949: no more pending results, returning what we have
 21244 1459838237.03963: results queue empty
 21244 1459838237.03976: checking for any_errors_fatal
 21244 1459838237.03988: done checking for any_errors_fatal
 21244 1459838237.04001: running handlers
 21244 1459838237.04025: RUNNING CLEANUP