ansible 2.0.1.0 // target: solaris 11.3 x86 // client: OS X 10.11.3

ansible.cfg

[defaults]
pipelining = True
deprecation_warnings = True
forks=10

debug.log

~/git/s11-test ▸ ANSIBLE_DEBUG=y ansible-playbook -i inventory.ini test.yml --ask-become-pass -vvvvv
 38330 1458312673.31012: starting run
Using /Users/user/git/s11-test/ansible.cfg as config file
SUDO password: 
Loaded callback default of type stdout, v2.0
1 plays in test.yml
 38330 1458312676.98988: in VariableManager get_vars()
 38330 1458312676.99002: done with get_vars()
 38330 1458312676.99140: in VariableManager get_vars()
 38330 1458312676.99155: done with get_vars()

PLAY ***************************************************************************
 38330 1458312677.03484: getting the remaining hosts for this loop
 38330 1458312677.03533: done getting the remaining hosts for this loop
 38330 1458312677.03678: building list of next tasks for hosts
 38330 1458312677.03702: getting the next task for host host.example.com
 38330 1458312677.03758: done getting next task for host host.example.com
 38330 1458312677.03799:  ^ task is: TASK: meta
 38330 1458312677.03840:  ^ 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
 38330 1458312677.03859: done building task lists
 38330 1458312677.03867: counting tasks in each state of execution
 38330 1458312677.03877: done counting tasks in each state of execution
 38330 1458312677.03882: advancing hosts in ITERATING_TASKS
 38330 1458312677.03887: starting to advance hosts
 38330 1458312677.03892: getting the next task for host host.example.com
 38330 1458312677.03899: done getting next task for host host.example.com
 38330 1458312677.03905:  ^ task is: TASK: meta
 38330 1458312677.03911:  ^ 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
 38330 1458312677.03915: done advancing hosts to next task
 38330 1458312677.04071: done queuing things up, now waiting for results queue to drain
 38330 1458312677.04078: waiting for pending results...
 38330 1458312677.04083: no more pending results, returning what we have
 38330 1458312677.04087: results queue empty
 38330 1458312677.04092: checking for any_errors_fatal
 38330 1458312677.04095: done checking for any_errors_fatal
 38330 1458312677.04099: getting the remaining hosts for this loop
 38330 1458312677.04107: done getting the remaining hosts for this loop
 38330 1458312677.04127: building list of next tasks for hosts
 38330 1458312677.04133: getting the next task for host host.example.com
 38330 1458312677.04140: done getting next task for host host.example.com
 38330 1458312677.04146:  ^ task is: TASK: command
 38330 1458312677.04152:  ^ 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
 38330 1458312677.04157: done building task lists
 38330 1458312677.04161: counting tasks in each state of execution
 38330 1458312677.04166: done counting tasks in each state of execution
 38330 1458312677.04170: advancing hosts in ITERATING_TASKS
 38330 1458312677.04173: starting to advance hosts
 38330 1458312677.04177: getting the next task for host host.example.com
 38330 1458312677.04184: done getting next task for host host.example.com
 38330 1458312677.04189:  ^ task is: TASK: command
 38330 1458312677.04193:  ^ 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
 38330 1458312677.04198: done advancing hosts to next task
 38330 1458312677.04206: getting variables
 38330 1458312677.04211: in VariableManager get_vars()
 38330 1458312677.04253: done with get_vars()
 38330 1458312677.04264: done getting variables
 38330 1458312677.04272: sending task start callback, copying the task so we can template it temporarily
 38330 1458312677.04277: done copying, going to template now
 38330 1458312677.04282: done templating
 38330 1458312677.04286: here goes the callback...

TASK [command] *****************************************************************
task path: /Users/user/git/s11-test/test.yml:10
 38330 1458312677.04302: sending task start callback
 38330 1458312677.04308: entering _queue_task() for host.example.com/TASK: command
 38330 1458312677.04313: host.example.com - putting task (TASK: command) in queue
 38330 1458312677.04318: worker is 1 (out of 1 available)
 38330 1458312677.04454: exiting _queue_task() for host.example.com/TASK: command
 38330 1458312677.04495: done queuing things up, now waiting for results queue to drain
 38330 1458312677.04503: waiting for pending results...
 38332 1458312677.04921: running TaskExecutor() for host.example.com/TASK: command
 38332 1458312677.04936: in run()
 38332 1458312677.05024: calling self._execute()
 38332 1458312677.06923: starting attempt loop
 38332 1458312677.06933: running the handler
 38332 1458312677.07069: _low_level_execute_command(): starting
 38332 1458312677.07076: _low_level_execute_command(): executing: /bin/sh -c '( umask 22 && mkdir -p "` echo $HOME/.ansible/tmp/ansible-tmp-1458312677.07-145981842056304 `" && echo "` echo $HOME/.ansible/tmp/ansible-tmp-1458312677.07-145981842056304 `" )'
<host.example.com> ESTABLISH SSH CONNECTION FOR USER: admin
<host.example.com> SSH: ansible.cfg set ssh_args: (-o)(ControlMaster=auto)(-o)(ControlPersist=60s)
<host.example.com> SSH: ansible_password/ansible_ssh_pass not set: (-o)(KbdInteractiveAuthentication=no)(-o)(PreferredAuthentications=gssapi-with-mic,gssapi-keyex,hostbased,publickey)(-o)(PasswordAuthentication=no)
<host.example.com> SSH: ANSIBLE_REMOTE_USER/remote_user/ansible_user/user/-u set: (-o)(User=admin)
<host.example.com> SSH: ANSIBLE_TIMEOUT/timeout set: (-o)(ConnectTimeout=10)
<host.example.com> SSH: PlayContext set ssh_common_args: ()
<host.example.com> SSH: PlayContext set ssh_extra_args: ()
<host.example.com> SSH: found only ControlPersist; added ControlPath: (-o)(ControlPath=/Users/user/.ansible/cp/ansible-ssh-%h-%p-%r)
<host.example.com> SSH: EXEC ssh -C -vvv -o ControlMaster=auto -o ControlPersist=60s -o KbdInteractiveAuthentication=no -o PreferredAuthentications=gssapi-with-mic,gssapi-keyex,hostbased,publickey -o PasswordAuthentication=no -o User=admin -o ConnectTimeout=10 -o ControlPath=/Users/user/.ansible/cp/ansible-ssh-%h-%p-%r -tt host.example.com '/bin/sh -c '"'"'( umask 22 && mkdir -p "` echo $HOME/.ansible/tmp/ansible-tmp-1458312677.07-145981842056304 `" && echo "` echo $HOME/.ansible/tmp/ansible-tmp-1458312677.07-145981842056304 `" )'"'"''
 38332 1458312677.07998: stderr chunk (state=2):
>>>OpenSSH_6.9p1, LibreSSL 2.1.8
debug1: Reading configuration data /Users/user/.ssh/config
<<<

 38332 1458312677.08016: stderr chunk (state=3):
>>>debug1: Reading configuration data /etc/ssh/ssh_config
debug1: /etc/ssh/ssh_config line 21: Applying options for *
<<<

 38332 1458312677.08029: stderr chunk (state=3):
>>>debug1: auto-mux: Trying existing master
<<<

 38332 1458312677.08036: stderr chunk (state=3):
>>>debug2: fd 3 setting O_NONBLOCK
<<<

 38332 1458312677.08047: stderr chunk (state=3):
>>>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
<<<

 38332 1458312677.08057: stderr chunk (state=3):
>>>debug3: mux_client_request_alive: done pid = 37945
debug3: mux_client_request_session: session request sent
<<<

 38332 1458312677.12748: stderr chunk (state=3):
>>>debug1: mux_client_request_session: master session id: 3
<<<

 38332 1458312677.27965: stdout chunk (state=3):
>>>/export/home/admin/.ansible/tmp/ansible-tmp-1458312677.07-145981842056304
<<<

 38332 1458312677.29654: stderr chunk (state=3):
>>>debug3: mux_client_read_packet: read header failed: Broken pipe
debug2: Received exit status from master 0
Shared connection to host.example.com closed.
<<<

 38332 1458312677.29710: stdout chunk (state=3):
>>><<<

 38332 1458312677.29729: stderr chunk (state=3):
>>><<<

 38332 1458312677.29760: _low_level_execute_command() done: rc=0, stdout=/export/home/admin/.ansible/tmp/ansible-tmp-1458312677.07-145981842056304
, stderr=OpenSSH_6.9p1, LibreSSL 2.1.8
debug1: Reading configuration data /Users/user/.ssh/config
debug1: Reading configuration data /etc/ssh/ssh_config
debug1: /etc/ssh/ssh_config line 21: 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 = 37945
debug3: mux_client_request_session: session request sent
debug1: mux_client_request_session: master session id: 3
debug3: mux_client_read_packet: read header failed: Broken pipe
debug2: Received exit status from master 0
Shared connection to host.example.com closed.

 38332 1458312677.29780: transferring module to remote
<host.example.com> PUT /var/folders/ns/n74snjr53kz_8kvjk7ckcqd40000gn/T/tmpGcjmGc TO /export/home/admin/.ansible/tmp/ansible-tmp-1458312677.07-145981842056304/command
<host.example.com> SSH: ansible.cfg set ssh_args: (-o)(ControlMaster=auto)(-o)(ControlPersist=60s)
<host.example.com> SSH: ansible_password/ansible_ssh_pass not set: (-o)(KbdInteractiveAuthentication=no)(-o)(PreferredAuthentications=gssapi-with-mic,gssapi-keyex,hostbased,publickey)(-o)(PasswordAuthentication=no)
<host.example.com> SSH: ANSIBLE_REMOTE_USER/remote_user/ansible_user/user/-u set: (-o)(User=admin)
<host.example.com> SSH: ANSIBLE_TIMEOUT/timeout set: (-o)(ConnectTimeout=10)
<host.example.com> SSH: PlayContext set ssh_common_args: ()
<host.example.com> SSH: PlayContext set sftp_extra_args: ()
<host.example.com> SSH: found only ControlPersist; added ControlPath: (-o)(ControlPath=/Users/user/.ansible/cp/ansible-ssh-%h-%p-%r)
<host.example.com> SSH: EXEC sftp -b - -C -vvv -o ControlMaster=auto -o ControlPersist=60s -o KbdInteractiveAuthentication=no -o PreferredAuthentications=gssapi-with-mic,gssapi-keyex,hostbased,publickey -o PasswordAuthentication=no -o User=admin -o ConnectTimeout=10 -o ControlPath=/Users/user/.ansible/cp/ansible-ssh-%h-%p-%r '[host.example.com]'
 38332 1458312677.30403: Sending initial data
 38332 1458312677.30421: Sent initial data (145 bytes)
 38332 1458312677.31588: stderr chunk (state=3):
>>>OpenSSH_6.9p1, LibreSSL 2.1.8
debug1: Reading configuration data /Users/user/.ssh/config
<<<

 38332 1458312677.31608: stderr chunk (state=3):
>>>debug1: Reading configuration data /etc/ssh/ssh_config
debug1: /etc/ssh/ssh_config line 21: Applying options for *
<<<

 38332 1458312677.31636: stderr chunk (state=3):
>>>debug1: auto-mux: Trying existing master
<<<

 38332 1458312677.31650: stderr chunk (state=3):
>>>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
<<<

 38332 1458312677.31662: stderr chunk (state=3):
>>>debug3: mux_client_request_alive: done pid = 37945
debug3: mux_client_request_session: session request sent
<<<

 38332 1458312677.31708: stderr chunk (state=3):
>>>debug1: mux_client_request_session: master session id: 2
<<<

 38332 1458312677.33000: stderr chunk (state=3):
>>>debug2: Remote version: 3
debug3: Sent message fd 9 T:16 I:1
<<<

 38332 1458312677.33053: stderr chunk (state=3):
>>>debug3: SSH_FXP_REALPATH . -> /export/home/admin size 0
<<<

 38332 1458312677.33068: stdout chunk (state=3):
>>>sftp> put /var/folders/ns/n74snjr53kz_8kvjk7ckcqd40000gn/T/tmpGcjmGc /export/home/admin/.ansible/tmp/ansible-tmp-1458312677.07-145981842056304/command
<<<

 38332 1458312677.33077: stderr chunk (state=3):
>>>debug3: Looking up /var/folders/ns/n74snjr53kz_8kvjk7ckcqd40000gn/T/tmpGcjmGc
debug3: Sent message fd 9 T:17 I:2
<<<

 38332 1458312677.33114: stderr chunk (state=3):
>>>debug3: Received stat reply T:101 I:2
debug1: Couldn't stat remote file: No such file or directory
<<<

 38332 1458312677.33130: stderr chunk (state=3):
>>>debug3: Sent message SSH2_FXP_OPEN I:3 P:/export/home/admin/.ansible/tmp/ansible-tmp-1458312677.07-145981842056304/command
<<<

 38332 1458312677.33355: stderr chunk (state=3):
>>>debug3: Sent message SSH2_FXP_WRITE I:4 O:0 S:32768
<<<

 38332 1458312677.33476: stderr chunk (state=3):
>>>debug3: SSH2_FXP_STATUS 0
debug3: In write loop, ack for 4 32768 bytes at 0
<<<

 38332 1458312677.33583: stderr chunk (state=3):
>>>debug3: Sent message SSH2_FXP_WRITE I:5 O:32768 S:32768
<<<

 38332 1458312677.33760: stderr chunk (state=3):
>>>debug3: Sent message SSH2_FXP_WRITE I:6 O:65536 S:25110
<<<

 38332 1458312677.33809: stderr chunk (state=3):
>>>debug3: SSH2_FXP_STATUS 0
debug3: In write loop, ack for 5 32768 bytes at 32768
<<<

 38332 1458312677.33868: stderr chunk (state=3):
>>>debug3: SSH2_FXP_STATUS 0
debug3: In write loop, ack for 6 25110 bytes at 65536
debug3: Sent message SSH2_FXP_CLOSE I:4
<<<

 38332 1458312677.33904: stderr chunk (state=3):
>>>debug3: SSH2_FXP_STATUS 0
<<<

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

 38332 1458312677.34087: stdout chunk (state=3):
>>><<<

 38332 1458312677.34094: stderr chunk (state=3):
>>><<<

 38332 1458312677.34116: done transferring module to remote
 38332 1458312677.34147: _low_level_execute_command(): starting
 38332 1458312677.34154: _low_level_execute_command(): using become for this command
 38332 1458312677.34175: _low_level_execute_command(): executing: /bin/sh -c 'su  root -c /bin/sh -c '"'"'echo BECOME-SUCCESS-rvajtyhgcqtodequifwsdrooxaxrgwzp; /bin/sh -c '"'"'"'"'"'"'"'"'LANG=de_DE.UTF-8 LC_ALL=de_DE.UTF-8 LC_MESSAGES=de_DE.UTF-8 /usr/bin/python /export/home/admin/.ansible/tmp/ansible-tmp-1458312677.07-145981842056304/command; rm -rf "/export/home/admin/.ansible/tmp/ansible-tmp-1458312677.07-145981842056304/" > /dev/null 2>&1'"'"'"'"'"'"'"'"''"'"''
<host.example.com> ESTABLISH SSH CONNECTION FOR USER: admin
<host.example.com> SSH: ansible.cfg set ssh_args: (-o)(ControlMaster=auto)(-o)(ControlPersist=60s)
<host.example.com> SSH: ansible_password/ansible_ssh_pass not set: (-o)(KbdInteractiveAuthentication=no)(-o)(PreferredAuthentications=gssapi-with-mic,gssapi-keyex,hostbased,publickey)(-o)(PasswordAuthentication=no)
<host.example.com> SSH: ANSIBLE_REMOTE_USER/remote_user/ansible_user/user/-u set: (-o)(User=admin)
<host.example.com> SSH: ANSIBLE_TIMEOUT/timeout set: (-o)(ConnectTimeout=10)
<host.example.com> SSH: PlayContext set ssh_common_args: ()
<host.example.com> SSH: PlayContext set ssh_extra_args: ()
<host.example.com> SSH: found only ControlPersist; added ControlPath: (-o)(ControlPath=/Users/user/.ansible/cp/ansible-ssh-%h-%p-%r)
<host.example.com> SSH: EXEC ssh -C -vvv -o ControlMaster=auto -o ControlPersist=60s -o KbdInteractiveAuthentication=no -o PreferredAuthentications=gssapi-with-mic,gssapi-keyex,hostbased,publickey -o PasswordAuthentication=no -o User=admin -o ConnectTimeout=10 -o ControlPath=/Users/user/.ansible/cp/ansible-ssh-%h-%p-%r -tt host.example.com '/bin/sh -c '"'"'su  root -c /bin/sh -c '"'"'"'"'"'"'"'"'echo BECOME-SUCCESS-rvajtyhgcqtodequifwsdrooxaxrgwzp; /bin/sh -c '"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'LANG=de_DE.UTF-8 LC_ALL=de_DE.UTF-8 LC_MESSAGES=de_DE.UTF-8 /usr/bin/python /export/home/admin/.ansible/tmp/ansible-tmp-1458312677.07-145981842056304/command; rm -rf "/export/home/admin/.ansible/tmp/ansible-tmp-1458312677.07-145981842056304/" > /dev/null 2>&1'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"'"''"'"'"'"'"'"'"'"''"'"''
 38332 1458312677.34519: Initial state: awaiting_prompt: <function detect_su_prompt at 0x108f42b90>
 38332 1458312677.35092: stderr chunk (state=0):
>>>OpenSSH_6.9p1, LibreSSL 2.1.8
debug1: Reading configuration data /Users/user/.ssh/config
<<<

 38332 1458312677.35624: stderr chunk (state=0):
>>>debug1: Reading configuration data /etc/ssh/ssh_config
debug1: /etc/ssh/ssh_config line 21: 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 = 37945
debug3: mux_client_request_session: session request sent
debug1: mux_client_request_session: master session id: 2
<<<

 38332 1458312677.41075: stdout chunk (state=0):
>>>Password: <<<

 38332 1458312677.41093: become_prompt: (source=stdout, state=awaiting_prompt): 'Password: '
 38332 1458312677.41115: Sending become_pass in response to prompt
 38332 1458312677.41177: stdout chunk (state=1):
>>>
<<<

 38332 1458312677.53112: stdout chunk (state=1):
admin@host:~$ <<<

 38332 1458312689.53200: done running TaskExecutor() for host.example.com/TASK: command
 38332 1458312689.53207: sending task result
 38332 1458312689.53263: done sending task result
 38332 1458312689.53368: WORKER PROCESS EXITING
 38331 1458312689.53386: worker 0 has data to read
 38331 1458312689.53574: got a result from worker 0: <ansible.executor.task_result.TaskResult object at 0x109f3e4d0>
 38331 1458312689.53585: sending result: [u'host_task_failed', u'<ansible.executor.task_result.TaskResult object at 0x109f3e4d0>']
 38331 1458312689.53626: done sending result
 38330 1458312689.53844: got result from result worker: [u'host_task_failed', u'<ansible.executor.task_result.TaskResult object at 0x10a0fd4d0>']
 38330 1458312689.53857: marking host.example.com as failed
fatal: [host.example.com]: FAILED! => {"failed": true, "msg": "Timeout (12s) waiting for privilege escalation prompt: \r\n\r"}
 38330 1458312689.53911: no more pending results, returning what we have
 38330 1458312689.53919: results queue empty
 38330 1458312689.53923: checking for any_errors_fatal
 38330 1458312689.53930: done checking for any_errors_fatal
 38330 1458312689.53934: getting the remaining hosts for this loop
 38330 1458312689.53945: done getting the remaining hosts for this loop
 38330 1458312689.53969: building list of next tasks for hosts
 38330 1458312689.53975: done building task lists
 38330 1458312689.53979: counting tasks in each state of execution
 38330 1458312689.53984: done counting tasks in each state of execution
 38330 1458312689.53989: all hosts are done, so returning None's for all hosts
 38330 1458312689.53995: done queuing things up, now waiting for results queue to drain
 38330 1458312689.54000: waiting for pending results...
 38330 1458312689.54005: no more pending results, returning what we have
 38330 1458312689.54013: out of hosts to run on

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

PLAY RECAP *********************************************************************
host.example.com : ok=0    changed=0    unreachable=0    failed=1   

 38330 1458312689.54095: RUNNING CLEANUP

test.yml

---

- hosts: all
  gather_facts: no
  become: yes
  become_user: root
  become_method: su

  tasks:
    - shell: /bin/true