win_update: WinRM failed to connect post reboot #143

Udayendu · 2020-12-03T15:53:09Z

SUMMARY

win_update module is not responding properly to reboot_timeout and throwing the traceback even if the update & system reboot is successful.

ISSUE TYPE

Bug Report

COMPONENT NAME

win_update

ANSIBLE VERSION

pip3 show ansible
Name: ansible
Version: 2.10.1
Summary: Radically simple IT automation
Home-page: https://ansible.com/
Author: Ansible, Inc.
Author-email: [email protected]
License: GPLv3+
Location: /usr/local/lib/python3.8/dist-packages
Requires: ansible-base
Required-by:

OS / ENVIRONMENT

Ubuntu 20.04 LTS [Ansible Provision Server]
Windows 2016 Server [Guest OS]

STEPS TO REPRODUCE

- name: Install all security, critical, and rollup updates
  win_updates:
    category_names:
      - SecurityUpdates
      - CriticalUpdates
      - UpdateRollups
    reboot: yes
    state: installed
    reboot_timeout: 3600

EXPECTED RESULTS

Should complete the update successfully

ACTUAL RESULTS

Failed with the following traceback:

win_updates: attempting to get system boot time
<192.168.9.251> ESTABLISH WINRM CONNECTION FOR USER: redhatcloud\redhatadmin on PORT 5986 TO 192.168.9.251
EXEC (via pipeline wrapper)
win_updates: attempting to get system boot time
<192.168.9.251> ESTABLISH WINRM CONNECTION FOR USER: redhatcloud\redhatadmin on PORT 5986 TO 192.168.9.251
<192.168.9.251> ESTABLISH WINRM CONNECTION FOR USER: redhatcloud\redhatadmin on PORT 5986 TO 192.168.9.251
win_updates: attempting to get system boot time
<192.168.9.251> ESTABLISH WINRM CONNECTION FOR USER: redhatcloud\redhatadmin on PORT 5986 TO 192.168.9.251
EXEC (via pipeline wrapper)
<192.168.9.251> ESTABLISH WINRM CONNECTION FOR USER: redhatcloud\redhatadmin on PORT 5986 TO 192.168.9.251
win_updates: attempting post-reboot test command
EXEC (via pipeline wrapper)
win_updates: system successfully rebooted
win_updates: checking WUA is not busy with win_shell command
Using module file /usr/local/lib/python3.8/dist-packages/ansible_collections/ansible/windows/plugins/modules/win_shell.ps1
Pipelining is enabled.
EXEC (via pipeline wrapper)
win_updates: shell wait results: {"start": "2020-12-03 03:18:20.698627", "stdout": "False\r\n", "cmd": "(New-Object -ComObject Microsoft.Update.Session).CreateUpdateInstaller().IsBusy", "stderr": "", "changed": true, "rc": 0, "delta": "0:00:46.711452", "end": "2020-12-03 03:19:07.410080", "_ansible_parsed": true, "stdout_lines": ["False"], "stderr_lines": []}
win_updates: ensure the connection is up and running
wait_for_connection: attempting ping module test
<192.168.9.251> ESTABLISH WINRM CONNECTION FOR USER: redhatcloud\redhatadmin on PORT 5986 TO 192.168.9.251
Using module file /usr/local/lib/python3.8/dist-packages/ansible_collections/ansible/windows/plugins/modules/win_ping.ps1
Pipelining is enabled.
EXEC (via pipeline wrapper)
win_updates: running win_updates module
Using module file /usr/local/lib/python3.8/dist-packages/ansible_collections/ansible/windows/plugins/modules/win_updates.ps1
Pipelining is enabled.
EXEC (via pipeline wrapper)
The full traceback is:
Traceback (most recent call last):
  File "/usr/lib/python3/dist-packages/urllib3/connectionpool.py", line 665, in urlopen
    httplib_response = self._make_request(
  File "/usr/lib/python3/dist-packages/urllib3/connectionpool.py", line 421, in _make_request
    six.raise_from(e, None)
  File "<string>", line 3, in raise_from
  File "/usr/lib/python3/dist-packages/urllib3/connectionpool.py", line 416, in _make_request
    httplib_response = conn.getresponse()
  File "/usr/lib/python3.8/http/client.py", line 1347, in getresponse
    response.begin()
  File "/usr/lib/python3.8/http/client.py", line 307, in begin
    version, status, reason = self._read_status()
  File "/usr/lib/python3.8/http/client.py", line 268, in _read_status
    line = str(self.fp.readline(_MAXLINE + 1), "iso-8859-1")
  File "/usr/lib/python3.8/socket.py", line 669, in readinto
    return self._sock.recv_into(b)
  File "/usr/lib/python3/dist-packages/urllib3/contrib/pyopenssl.py", line 328, in recv_into
    return self.recv_into(*args, **kwargs)
  File "/usr/lib/python3/dist-packages/urllib3/contrib/pyopenssl.py", line 318, in recv_into
    raise SocketError(str(e))
OSError: (104, 'ECONNRESET')

During handling of the above exception, another exception occurred:

[.........]

Traceback (most recent call last):
  File "/usr/lib/python3/dist-packages/urllib3/connectionpool.py", line 665, in urlopen
    httplib_response = self._make_request(
  File "/usr/lib/python3/dist-packages/urllib3/connectionpool.py", line 376, in _make_request
    self._validate_conn(conn)
  File "/usr/lib/python3/dist-packages/urllib3/connectionpool.py", line 996, in _validate_conn
    conn.connect()
  File "/usr/lib/python3/dist-packages/urllib3/connection.py", line 314, in connect
    conn = self._new_conn()
  File "/usr/lib/python3/dist-packages/urllib3/connection.py", line 171, in _new_conn
    raise NewConnectionError(
urllib3.exceptions.NewConnectionError: <urllib3.connection.VerifiedHTTPSConnection object at 0x7f2f14db9820>: Failed to establish a new connection: [Errno 111] Connection refused

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/lib/python3/dist-packages/requests/adapters.py", line 439, in send
    resp = conn.urlopen(
  File "/usr/lib/python3/dist-packages/urllib3/connectionpool.py", line 719, in urlopen
    retries = retries.increment(
  File "/usr/lib/python3/dist-packages/urllib3/util/retry.py", line 436, in increment
    raise MaxRetryError(_pool, url, error or ResponseError(cause))
urllib3.exceptions.MaxRetryError: HTTPSConnectionPool(host='192.168.9.251', port=5986): Max retries exceeded with url: /wsman (Caused by NewConnectionError('<urllib3.connection.VerifiedHTTPSConnection object at 0x7f2f14db9820>: Failed to establish a new connection: [Errno 111] Connection refused'))

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.8/dist-packages/ansible/executor/task_executor.py", line 158, in run
    res = self._execute()
  File "/usr/local/lib/python3.8/dist-packages/ansible/executor/task_executor.py", line 663, in _execute
    result = self._handler.run(task_vars=variables)
  File "/usr/local/lib/python3.8/dist-packages/ansible_collections/ansible/windows/plugins/action/win_updates.py", line 223, in run
    result = self._run_win_updates(new_module_args, task_vars,
  File "/usr/local/lib/python3.8/dist-packages/ansible_collections/ansible/windows/plugins/action/win_updates.py", line 24, in _run_win_updates
    result = self._execute_module_with_become(module_name='ansible.windows.win_updates',
  File "/usr/local/lib/python3.8/dist-packages/ansible_collections/ansible/windows/plugins/action/win_updates.py", line 114, in _execute_module_with_become
    module_res = self._execute_module(module_name=module_name,
  File "/usr/local/lib/python3.8/dist-packages/ansible/plugins/action/__init__.py", line 969, in _execute_module
    res = self._low_level_execute_command(cmd, sudoable=sudoable, in_data=in_data)
  File "/usr/local/lib/python3.8/dist-packages/ansible/plugins/action/__init__.py", line 1121, in _low_level_execute_command
    rc, stdout, stderr = self._connection.exec_command(cmd, in_data=in_data, sudoable=sudoable)
  File "/usr/local/lib/python3.8/dist-packages/ansible/plugins/connection/winrm.py", line 545, in exec_command
    result = self._winrm_exec(cmd_parts[0], cmd_parts[1:], from_exec=True, stdin_iterator=stdin_iterator)
  File "/usr/local/lib/python3.8/dist-packages/ansible/plugins/connection/winrm.py", line 506, in _winrm_exec
    self.protocol.cleanup_command(self.shell_id, command_id)
  File "/usr/local/lib/python3.8/dist-packages/winrm/protocol.py", line 390, in cleanup_command
    res = self.send_message(xmltodict.unparse(req))
  File "/usr/local/lib/python3.8/dist-packages/winrm/protocol.py", line 243, in send_message
    resp = self.transport.send_message(message)
  File "/usr/local/lib/python3.8/dist-packages/winrm/transport.py", line 323, in send_message
    response = self._send_message_request(prepared_request, message)
  File "/usr/local/lib/python3.8/dist-packages/winrm/transport.py", line 328, in _send_message_request
    response = self.session.send(prepared_request, timeout=self.read_timeout_sec)
  File "/usr/lib/python3/dist-packages/requests/sessions.py", line 646, in send
    r = adapter.send(request, **kwargs)
  File "/usr/lib/python3/dist-packages/requests/adapters.py", line 516, in send
    raise ConnectionError(e, request=request)
requests.exceptions.ConnectionError: HTTPSConnectionPool(host='192.168.9.251', port=5986): Max retries exceeded with url: /wsman (Caused by NewConnectionError('<urllib3.connection.VerifiedHTTPSConnection object at 0x7f2f14db9820>: Failed to establish a new connection: [Errno 111] Connection refused'))
fatal: [192.168.9.251]: FAILED! => {
    "msg": "Unexpected failure during module execution.",
    "stdout": ""
}

The text was updated successfully, but these errors were encountered:

Udayendu · 2020-12-03T16:04:17Z

The playbook is working well and total time takes to reach the above stage is:

real    36m35.699s
user    1m44.810s
sys     0m8.901s

Seems like the main issue is here:

win_updates: attempting post-reboot test command

And this command is exiting with just few tries. Because the system reboot is complete and its just checking all the policies. So that also has to be considered. Because as per my observation, after this failure, with in 30-40 secs system is back to login screen.

killuminiiiou · 2021-03-04T10:55:45Z

Hello there!
Are you still facing this issue?

I believe I'm experiencing some kind of similar problem using win_updates module, trying to install updates on a fresh Windows 2016 server...

My feeling is that the module could have an issue managing multiple reboots required by the updates installation. This is the log I'm getting (obfuscating sensitive data):

<xxx.mydomain.com> ESTABLISH WINRM CONNECTION FOR USER: admin on PORT 5986 TO xxx.mydomain.com
EXEC (via pipeline wrapper)
<xxx.mydomain.com> ESTABLISH WINRM CONNECTION FOR USER: admin on PORT 5986 TO xxx.mydomain.com
win_updates: attempting post-reboot test command
EXEC (via pipeline wrapper)
win_updates: system successfully rebooted
win_updates: checking WUA is not busy with win_shell command
Using module file /usr/lib/python2.7/site-packages/ansible/modules/windows/win_shell.ps1
Pipelining is enabled.
EXEC (via pipeline wrapper)
win_updates: shell wait results: {"_ansible_parsed": true, "stderr_lines": [], "changed": true, "end": "2021-03-04 09:08:52.896365", "stdout": "False\r\n", "cmd": "(New-Object -ComObject Microsoft.Update.Session).CreateUpdateInstaller().IsBusy", "start": "2021-03-04 09:08:47.453732", "delta": "0:00:05.442633", "stderr": "", "rc": 0, "stdout_lines": ["False"]}
win_updates: ensure the connection is up and running
wait_for_connection: attempting ping module test
<xxx.mydomain.com> ESTABLISH WINRM CONNECTION FOR USER: admin on PORT 5986 TO xxx.mydomain.com
Using module file /usr/lib/python2.7/site-packages/ansible/modules/windows/win_ping.ps1
Pipelining is enabled.
EXEC (via pipeline wrapper)
win_updates: running win_updates module
Using module file /usr/lib/python2.7/site-packages/ansible/modules/windows/win_updates.ps1
Pipelining is enabled.
EXEC (via pipeline wrapper)
The full traceback is:
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/ansible/executor/task_executor.py", line 145, in run
    res = self._execute()
  File "/usr/lib/python2.7/site-packages/ansible/executor/task_executor.py", line 664, in _execute
    result = self._handler.run(task_vars=variables)
  File "/usr/lib/python2.7/site-packages/ansible/plugins/action/win_updates.py", line 231, in run
    use_task)
  File "/usr/lib/python2.7/site-packages/ansible/plugins/action/win_updates.py", line 27, in _run_win_updates
    use_task=use_task)
  File "/usr/lib/python2.7/site-packages/ansible/plugins/action/win_updates.py", line 122, in _execute_module_with_become
    wrap_async=wrap_async)
  File "/usr/lib/python2.7/site-packages/ansible/plugins/action/__init__.py", line 917, in _execute_module
    res = self._low_level_exec…

What I understand:

post reboot test command is OK
"checking WUA is not busy with win_shell command" is OK
"ensure the connection is up and running" is OK (using ping test)
"running win_updates module" is KO, trying to run the module one more time to check newly available updates

The precise error raised on this step is:

Max retries exceeded with url: /wsman (Caused by NewConnectionError('<urllib3.connection.VerifiedHTTPSConnection object at 0x7fcee24bd650>: Failed to establish a new connection: [Errno 111] Connection refused',))

Monitoring aside the server itself, I can see it rebooting multiple times during the update process. Could it be possible the module believes the server is up and running fine, but a reboot takes place just after that (caused by an update just installed)?

I don't see any easy fix for that, any help welcome!

Thanks a lot!

Udayendu · 2021-03-07T10:02:56Z

Hello there!
Are you still facing this issue?

I believe I'm experiencing some kind of similar problem using win_updates module, trying to install updates on a fresh Windows 2016 server...

My feeling is that the module could have an issue managing multiple reboots required by the updates installation. This is the log I'm getting (obfuscating sensitive data):

<xxx.mydomain.com> ESTABLISH WINRM CONNECTION FOR USER: admin on PORT 5986 TO xxx.mydomain.com
EXEC (via pipeline wrapper)
<xxx.mydomain.com> ESTABLISH WINRM CONNECTION FOR USER: admin on PORT 5986 TO xxx.mydomain.com
win_updates: attempting post-reboot test command
EXEC (via pipeline wrapper)
win_updates: system successfully rebooted
win_updates: checking WUA is not busy with win_shell command
Using module file /usr/lib/python2.7/site-packages/ansible/modules/windows/win_shell.ps1
Pipelining is enabled.
EXEC (via pipeline wrapper)
win_updates: shell wait results: {"_ansible_parsed": true, "stderr_lines": [], "changed": true, "end": "2021-03-04 09:08:52.896365", "stdout": "False\r\n", "cmd": "(New-Object -ComObject Microsoft.Update.Session).CreateUpdateInstaller().IsBusy", "start": "2021-03-04 09:08:47.453732", "delta": "0:00:05.442633", "stderr": "", "rc": 0, "stdout_lines": ["False"]}
win_updates: ensure the connection is up and running
wait_for_connection: attempting ping module test
<xxx.mydomain.com> ESTABLISH WINRM CONNECTION FOR USER: admin on PORT 5986 TO xxx.mydomain.com
Using module file /usr/lib/python2.7/site-packages/ansible/modules/windows/win_ping.ps1
Pipelining is enabled.
EXEC (via pipeline wrapper)
win_updates: running win_updates module
Using module file /usr/lib/python2.7/site-packages/ansible/modules/windows/win_updates.ps1
Pipelining is enabled.
EXEC (via pipeline wrapper)
The full traceback is:
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/ansible/executor/task_executor.py", line 145, in run
    res = self._execute()
  File "/usr/lib/python2.7/site-packages/ansible/executor/task_executor.py", line 664, in _execute
    result = self._handler.run(task_vars=variables)
  File "/usr/lib/python2.7/site-packages/ansible/plugins/action/win_updates.py", line 231, in run
    use_task)
  File "/usr/lib/python2.7/site-packages/ansible/plugins/action/win_updates.py", line 27, in _run_win_updates
    use_task=use_task)
  File "/usr/lib/python2.7/site-packages/ansible/plugins/action/win_updates.py", line 122, in _execute_module_with_become
    wrap_async=wrap_async)
  File "/usr/lib/python2.7/site-packages/ansible/plugins/action/__init__.py", line 917, in _execute_module
    res = self._low_level_exec…

What I understand:

post reboot test command is OK
"checking WUA is not busy with win_shell command" is OK
"ensure the connection is up and running" is OK (using ping test)
"running win_updates module" is KO, trying to run the module one more time to check newly available updates

The precise error raised on this step is:

Max retries exceeded with url: /wsman (Caused by NewConnectionError('<urllib3.connection.VerifiedHTTPSConnection object at 0x7fcee24bd650>: Failed to establish a new connection: [Errno 111] Connection refused',))

Monitoring aside the server itself, I can see it rebooting multiple times during the update process. Could it be possible the module believes the server is up and running fine, but a reboot takes place just after that (caused by an update just installed)?

I don't see any easy fix for that, any help welcome!

Thanks a lot!

Agree with you. Fix is not easy but a fix has to be applied. Currently win_update module is not atall able to handle the system updates due to multiple reboot. May be some system validation logic has to be implemented in it.

jborean93 mentioned this issue May 21, 2021

Refactor win_updates #225

Merged

4 tasks

jborean93 closed this as completed in #225 Jun 19, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

win_update: WinRM failed to connect post reboot #143

win_update: WinRM failed to connect post reboot #143

Udayendu commented Dec 3, 2020

Udayendu commented Dec 3, 2020

killuminiiiou commented Mar 4, 2021

Udayendu commented Mar 7, 2021

win_update: WinRM failed to connect post reboot #143

win_update: WinRM failed to connect post reboot #143

Comments

Udayendu commented Dec 3, 2020

SUMMARY

ISSUE TYPE

COMPONENT NAME

ANSIBLE VERSION

OS / ENVIRONMENT

STEPS TO REPRODUCE

EXPECTED RESULTS

ACTUAL RESULTS

Udayendu commented Dec 3, 2020

killuminiiiou commented Mar 4, 2021

Udayendu commented Mar 7, 2021