Lowess/ansible-issue-14426-debug-log.log

## ansible-issue-14426-debug-log.log
root@ip-w-x-y-z:/opt/ops/ansible# ANSIBLE_DEBUG=y ansible-playbook test.yaml -t configure -l <EC2_ID> -vvvvv
  1039 1459767500.53173: starting run
Using /etc/ansible/ansible.cfg as config file
  1039 1459767517.21890: in VariableManager get_vars()
  1039 1459767517.23086: done with get_vars()
  1039 1459767517.23098: in VariableManager get_vars()
  1039 1459767517.23495: done with get_vars()
  1039 1459767517.25708: in VariableManager get_vars()
  1039 1459767517.26139: done with get_vars()
  1039 1459767517.26150: in VariableManager get_vars()
  1039 1459767517.26604: done with get_vars()
  1039 1459767517.28302: in VariableManager get_vars()
  1039 1459767517.28315: done with get_vars()
  1039 1459767517.28326: in VariableManager get_vars()
  1039 1459767517.28337: done with get_vars()
  1039 1459767517.28376: in VariableManager get_vars()
  1039 1459767517.28388: done with get_vars()
  1039 1459767517.28398: in VariableManager get_vars()
  1039 1459767517.28409: done with get_vars()
  1039 1459767517.28448: in VariableManager get_vars()
  1039 1459767517.28459: done with get_vars()
  1039 1459767517.28468: in VariableManager get_vars()
  1039 1459767517.28479: done with get_vars()
  1039 1459767517.28517: in VariableManager get_vars()
  1039 1459767517.28527: done with get_vars()
  1039 1459767517.28537: in VariableManager get_vars()
  1039 1459767517.28548: done with get_vars()
  1039 1459767517.28588: in VariableManager get_vars()
  1039 1459767517.28599: done with get_vars()
  1039 1459767517.28609: in VariableManager get_vars()
  1039 1459767517.28620: done with get_vars()
  1039 1459767517.28658: in VariableManager get_vars()
  1039 1459767517.28669: done with get_vars()
  1039 1459767517.28680: in VariableManager get_vars()
  1039 1459767517.28691: done with get_vars()
  1039 1459767517.28730: in VariableManager get_vars()
  1039 1459767517.28742: done with get_vars()
  1039 1459767517.28753: in VariableManager get_vars()
  1039 1459767517.28764: done with get_vars()
  1039 1459767517.28803: in VariableManager get_vars()
  1039 1459767517.28814: done with get_vars()
  1039 1459767517.28825: in VariableManager get_vars()
  1039 1459767517.28836: done with get_vars()
  1039 1459767517.28875: in VariableManager get_vars()
  1039 1459767517.28887: done with get_vars()
  1039 1459767517.28916: in VariableManager get_vars()
  1039 1459767517.28927: done with get_vars()
  1039 1459767517.29077: in VariableManager get_vars()
  1039 1459767517.29089: done with get_vars()
  1039 1459767517.29099: in VariableManager get_vars()
  1039 1459767517.29110: done with get_vars()
  1039 1459767517.31383: in VariableManager get_vars()
  1039 1459767517.31396: done with get_vars()
  1039 1459767517.31407: in VariableManager get_vars()
  1039 1459767517.31418: done with get_vars()
  1039 1459767517.32762: in VariableManager get_vars()
  1039 1459767517.32775: done with get_vars()
  1039 1459767517.32787: in VariableManager get_vars()
  1039 1459767517.32798: done with get_vars()
  1039 1459767517.33875: in VariableManager get_vars()
  1039 1459767517.33887: done with get_vars()
  1039 1459767517.33899: in VariableManager get_vars()
  1039 1459767517.33910: done with get_vars()
  1039 1459767517.35059: in VariableManager get_vars()
  1039 1459767517.35072: done with get_vars()
  1039 1459767517.35083: in VariableManager get_vars()
  1039 1459767517.35095: done with get_vars()
  1039 1459767517.36251: in VariableManager get_vars()
  1039 1459767517.36264: done with get_vars()
  1039 1459767517.36275: in VariableManager get_vars()
  1039 1459767517.36286: done with get_vars()
  1039 1459767517.37542: in VariableManager get_vars()
  1039 1459767517.37555: done with get_vars()
  1039 1459767517.37566: in VariableManager get_vars()
  1039 1459767517.37577: done with get_vars()
Loaded callback default of type stdout, v2.0
Loaded callback timer of type aggregate, v2.0
1 plays in test.yaml
  1039 1459767517.85612: in VariableManager get_vars()
  1039 1459767517.86092: done with get_vars()

PLAY [Installation and configuration] *************************************
  1039 1459767517.93644: getting the remaining hosts for this loop
  1039 1459767517.93665: done getting the remaining hosts for this loop
  1039 1459767517.93692: building list of next tasks for hosts
  1039 1459767517.93706: getting the next task for host ip-10-142-244-154.ec2.internal
  1039 1459767517.93722: done getting next task for host ip-10-142-244-154.ec2.internal
  1039 1459767517.93737:  ^ task is: TASK: setup
  1039 1459767517.93751:  ^ state is: HOST STATE: block=0, task=0, rescue=0, always=0, role=None, run_state=ITERATING_SETUP, fail_state=FAILED_NONE, pending_setup=True, tasks child state? None, rescue child state? None, always child state? None
  1039 1459767517.93763: done building task lists
  1039 1459767517.93777: counting tasks in each state of execution
  1039 1459767517.93789: done counting tasks in each state of execution
  1039 1459767517.93800: advancing hosts in ITERATING_SETUP
  1039 1459767517.93812: starting to advance hosts
  1039 1459767517.93823: getting the next task for host ip-10-142-244-154.ec2.internal
  1039 1459767517.93837: done getting next task for host ip-10-142-244-154.ec2.internal
  1039 1459767517.93849:  ^ task is: TASK: setup
  1039 1459767517.93861:  ^ state is: HOST STATE: block=0, task=0, rescue=0, always=0, role=None, run_state=ITERATING_SETUP, fail_state=FAILED_NONE, pending_setup=True, tasks child state? None, rescue child state? None, always child state? None
  1039 1459767517.93872: done advancing hosts to next task
  1039 1459767517.94055: getting variables
  1039 1459767517.94069: in VariableManager get_vars()
  1039 1459767517.94429: done with get_vars()
  1039 1459767517.94444: done getting variables
  1039 1459767517.94461: sending task start callback, copying the task so we can template it temporarily
  1039 1459767517.94474: done copying, going to template now
  1039 1459767517.94487: done templating
  1039 1459767517.94498: here goes the callback...

TASK [setup] *******************************************************************
  1039 1459767517.94525: sending task start callback
  1039 1459767517.94538: entering _queue_task() for ip-10-142-244-154.ec2.internal/TASK: setup
  1039 1459767517.94550: ip-10-142-244-154.ec2.internal - putting task (TASK: setup) in queue
  1039 1459767517.94562: worker is 1 (out of 1 available)
  1039 1459767517.94712: exiting _queue_task() for ip-10-142-244-154.ec2.internal/TASK: setup
  1039 1459767517.94766: done queuing things up, now waiting for results queue to drain
  1039 1459767517.94779: waiting for pending results...
  1052 1459767517.94994: running TaskExecutor() for ip-10-142-244-154.ec2.internal/TASK: setup
  1052 1459767517.95006: in run()
  1052 1459767517.95114: calling self._execute()
  1052 1459767517.96234: starting attempt loop
  1052 1459767517.96258: running the handler
  1052 1459767517.96439: _low_level_execute_command(): starting
  1052 1459767517.96454: _low_level_execute_command(): using become for this command
  1052 1459767517.96484: _low_level_execute_command(): executing: /bin/sh -c 'sudo -H -S -n -u root /bin/sh -c '"'"'echo BECOME-SUCCESS-poicmzrregwbpdqegnyixgufasrmbhxm; /bin/sh -c '"'"'"'"'"'"'"'"'LANG=en_US.UTF-8 LC_ALL=en_US.UTF-8 LC_MESSAGES=en_US.UTF-8 /usr/bin/python'"'"'"'"'"'"'"'"''"'"''
<ip-10-142-244-154.ec2.internal> ESTABLISH SSH CONNECTION FOR USER: ubuntu
<ip-10-142-244-154.ec2.internal> SSH: ansible.cfg set ssh_args: (-o)(ControlMaster=auto)(-o)(ControlPersist=30m)
<ip-10-142-244-154.ec2.internal> SSH: ANSIBLE_PRIVATE_KEY_FILE/private_key_file/ansible_ssh_private_key_file set: (-o)(IdentityFile="/root/.ssh/id_rskeypair")
<ip-10-142-244-154.ec2.internal> SSH: ansible_password/ansible_ssh_pass not set: (-o)(KbdInteractiveAuthentication=no)(-o)(PreferredAuthentications=gssapi-with-mic,gssapi-keyex,hostbased,publickey)(-o)(PasswordAuthentication=no)
<ip-10-142-244-154.ec2.internal> SSH: ANSIBLE_REMOTE_USER/remote_user/ansible_user/user/-u set: (-o)(User=ubuntu)
<ip-10-142-244-154.ec2.internal> SSH: ANSIBLE_TIMEOUT/timeout set: (-o)(ConnectTimeout=10)
<ip-10-142-244-154.ec2.internal> SSH: PlayContext set ssh_common_args: ()
<ip-10-142-244-154.ec2.internal> SSH: PlayContext set ssh_extra_args: ()
<ip-10-142-244-154.ec2.internal> SSH: found only ControlPersist; added ControlPath: (-o)(ControlPath=/root/.ansible/cp/ansible-ssh-%h-%p-%r)
<ip-10-142-244-154.ec2.internal> SSH: EXEC ssh -C -vvv -o ControlMaster=auto -o ControlPersist=30m -o 'IdentityFile="/root/.ssh/id_rskeypair"' -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 ip-10-142-244-154.ec2.internal '/bin/sh -c '"'"'sudo -H -S -n -u root /bin/sh -c '"'"'"'"'"'"'"'"'echo BECOME-SUCCESS-poycmzrregwbpzqegnyixgufzsrmbhxm; /bin/sh -c '"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'LANG=en_US.UTF-8 LC_ALL=en_US.UTF-8 LC_MESSAGES=en_US.UTF-8 /usr/bin/python'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"''"'"'"'"'"'"'"'"''"'"''
  1052 1459767517.96868: Initial state: awaiting_escalation: BECOME-SUCCESS-poycmzrregwbpzqegnyixgufzsrmbhxm
  1052 1459767517.97126: 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 *
<<<

  1052 1459767517.97247: 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-ip-10-142-244-154.ec2.internal-22-ubuntu" does not exist
<<<

  1052 1459767517.97394: stderr chunk (state=1):
>>>debug2: ssh_connect: needpriv 0
debug1: Connecting to ip-10-142-244-154.ec2.internal [10.142.244.154] port 22.
debug2: fd 3 setting O_NONBLOCK
<<<

  1052 1459767517.97495: stderr chunk (state=1):
>>>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/id_rskeypair" as a RSA1 public key
debug1: identity file /root/.ssh/id_rskeypair type -1
debug1: identity file /root/.ssh/id_rskeypair-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
<<<

  1052 1459767517.98893: 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 "ip-10-142-244-154.ec2.internal" from file "/root/.ssh/known_hosts"
<<<

  1052 1459767517.99245: stderr chunk (state=1):
>>>debug3: load_hostkeys: loaded 0 keys
<<<

  1052 1459767517.99294: 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
<<<

  1052 1459767518.00080: stderr chunk (state=1):
>>>debug1: sending SSH2_MSG_KEX_ECDH_INIT
debug1: expecting SSH2_MSG_KEX_ECDH_REPLY
debug1: Server host key: ECDSA 5e:75:8f:31:f9:c1:bb:34:e8:c8:3c:be:70:d6:02:4b
debug3: load_hostkeys: loading entries for host "ip-10-142-244-154.ec2.internal" from file "/root/.ssh/known_hosts"
<<<

  1052 1459767518.00328: stderr chunk (state=1):
>>>debug3: load_hostkeys: loaded 0 keys
debug3: load_hostkeys: loading entries for host "10.142.244.154" from file "/root/.ssh/known_hosts"
<<<

  1052 1459767518.00671: stderr chunk (state=1):
>>>debug3: load_hostkeys: loaded 0 keys
<<<

  1052 1459767518.00716: stderr chunk (state=1):
>>>Warning: Permanently added 'ip-10-142-244-154.ec2.internal,10.142.244.154' (ECDSA) to the list of known hosts.
<<<

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

  1052 1459767518.01107: 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
<<<

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

  1052 1459767518.05220: 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/id_rskeypair
<<<

  1052 1459767518.05444: stderr chunk (state=1):
>>>debug1: key_parse_private2: missing begin marker
debug1: read PEM private key done: type RSA
debug3: sign_and_send_pubkey: RSA f1:25:75:2c:ec:78:06:73:b2:ad:48:d8:bc:75:7f:42
<<<

  1052 1459767518.05537: stderr chunk (state=1):
>>>debug2: we sent a publickey packet, wait for reply
<<<

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

  1052 1459767518.06550: stderr chunk (state=1):
>>>debug1: Authentication succeeded (publickey).
Authenticated to ip-10-142-244-154.ec2.internal ([10.142.244.154]:22).
debug1: setting up multiplex master socket
debug3: muxserver_listen: temporary control path /root/.ansible/cp/ansible-ssh-ip-10-142-244-154.ec2.internal-22-ubuntu.0AlHzRnRocj4DGX4
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-ip-10-142-244-154.ec2.internal-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 1055
debug2: fd 4 setting O_NONBLOCK
debug1: forking to background
debug1: Entering interactive session.
<<<

  1052 1459767518.06984: stderr chunk (state=1):
>>>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 = 1057
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-poycmzrregwbpzqegnyixgufzsrmbhxm; /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
<<<

  1052 1459767530.08833: done running TaskExecutor() for ip-10-142-244-154.ec2.internal/TASK: setup
  1052 1459767530.08845: sending task result
  1052 1459767530.08889: done sending task result
  1052 1459767530.09234: WORKER PROCESS EXITING
  1051 1459767530.09254: worker 0 has data to read
  1051 1459767530.09424: got a result from worker 0: <ansible.executor.task_result.TaskResult object at 0x7f809ce6d3d0>
  1051 1459767530.09437: sending result: [u'host_task_failed', u'<ansible.executor.task_result.TaskResult object at 0x7f809ce6d3d0>']
  1051 1459767530.09475: done sending result
  1039 1459767530.09641: got result from result worker: [u'host_task_failed', u'<ansible.executor.task_result.TaskResult object at 0x7f8098dca0d0>']
  1039 1459767530.09667: marking ip-10-142-244-154.ec2.internal as failed
fatal: [ip-10-142-244-154.ec2.internal]: FAILED! => {"failed": true, "msg": "Timeout (12s) waiting for privilege escalation prompt: "}
  1039 1459767530.09744: no more pending results, returning what we have
  1039 1459767530.09760: results queue empty
  1039 1459767530.09775: checking for any_errors_fatal
  1039 1459767530.09788: done checking for any_errors_fatal
  1039 1459767530.09799: getting the remaining hosts for this loop
  1039 1459767530.09817: done getting the remaining hosts for this loop
  1039 1459767530.09843: building list of next tasks for hosts
  1039 1459767530.09857: done building task lists
  1039 1459767530.09869: counting tasks in each state of execution
  1039 1459767530.09880: done counting tasks in each state of execution
  1039 1459767530.09892: all hosts are done, so returning None's for all hosts
  1039 1459767530.09904: done queuing things up, now waiting for results queue to drain
  1039 1459767530.09915: waiting for pending results...
  1039 1459767530.09926: no more pending results, returning what we have
  1039 1459767530.09938: out of hosts to run on

NO MORE HOSTS LEFT *************************************************************
  1039 1459767530.09963: running handlers
  to retry, use: --limit @test.retry

PLAY RECAP *********************************************************************
ip-10-142-244-154.ec2.internal : ok=0    changed=0    unreachable=0    failed=1

Playbook run took 0 days, 0 hours, 0 minutes, 12 seconds
  1039 1459767530.10065: RUNNING CLEANUP