Error reading SSH protocol banner timeout when using network_cli connection #69267

seansabour · 2020-04-30T23:19:29Z

SUMMARY

When using the network_cli we are seeing issues with ssh protocol banner timeout coming from paramiko. When running the SSH proxy command manually from the server it has no problems connecting.

ISSUE TYPE

Bug Report

COMPONENT NAME

network_cli connection plugin

ANSIBLE VERSION

ansible 2.9.7
  config file = /etc/ansible/ansible.cfg
  configured module search path = ['/root/.ansible/plugins/modules', '/usr/share/ansible/plugins/modules']
  ansible python module location = /usr/local/lib/python3.6/site-packages/ansible
  executable location = /usr/local/bin/ansible
  python version = 3.6.8 (default, Aug  7 2019, 17:28:10) [GCC 4.8.5 20150623 (Red Hat 4.8.5-39)]

I've also tested this with ansible2.8.4 with python2.7.5 and same issue occurs

CONFIGURATION

DEFAULT_FORKS(/etc/ansible/ansible.cfg) = 500
HOST_KEY_CHECKING(/etc/ansible/ansible.cfg) = False
PARAMIKO_HOST_KEY_AUTO_ADD(/etc/ansible/ansible.cfg) = True
PARAMIKO_LOOK_FOR_KEYS(/etc/ansible/ansible.cfg) = False
PERSISTENT_COMMAND_TIMEOUT(/etc/ansible/ansible.cfg) = 600
RETRY_FILES_ENABLED(/etc/ansible/ansible.cfg) = False

OS / ENVIRONMENT

2.6.32-754.17.1.el6.x86_64 on centos-6.10 on ProLiant DL360p Gen8 bastion server

Name        : openssh
Arch        : x86_64
Version     : 5.3p1
Release     : 124.el6_10

Cisco:
Software
  BIOS: version 07.59
  NXOS: version 7.0(3)I7(4)
  BIOS compile time:  08/26/2016
  NXOS image file is: bootflash:///nxos.7.0.3.I7.4.bin
  NXOS compile time:  6/14/2018 2:00:00 [06/14/2018 09:49:04]
Hardware
  cisco Nexus9000 C9372TX chassis

STEPS TO REPRODUCE

Create playbook below
Create inventory containing cisco device with the following group_vars:

ansible_connection: network_cli
ansible_network_os: nxos
ansible_ssh_common_args: '-o ProxyCommand="ssh -W %h:%p -q bastionhost.1234"'

Run your playbook

- name: "Uploading file: {{ image_file }}"
  hosts: all
  connection: network_cli
  # This is how many parallel tasks are launched at the same time.
  # We don't want to clog the network. Set to 4 due to "MaxAuthTries" on sshd config on server.
  serial: 4
  gather_facts: no
  ignore_errors: yes
  vars:
    ansible_command_timeout: 600
    ansible_network_os: nxos
    _image_file: "{{ image_file }}"
    _remote_scp_server: "{{ remote_scp_server }}"
    # Free space required is different if image was already uploaded or not.
    # For 9ks this is not a problem, but the 3k device I've been working on,
    # has 1.8GB total. Previous image could be 700MB, next image another 700...
    # Will set this to the 700 for an image + some extra space for the upgrade.
    _free_space_required: "{{ free_space_required | default(1073741824) }}"
  tasks:
    - nxos_facts:
        gather_subset:
          - config

EXPECTED RESULTS

To be able to successfully connect to the box and pull facts

ACTUAL RESULTS

SSH protocol banner timeout

2020-04-30 04:18:30,135 p=53 u=root n=ansible |     53 1588220310.13553: starting run
2020-04-30 04:18:30,283 p=53 u=root n=ansible | ansible-playbook 2.9.7
  config file = /etc/ansible/ansible.cfg
  configured module search path = ['/root/.ansible/plugins/modules', '/usr/share/ansible/plugins/modules']
  ansible python module location = /usr/local/lib/python3.6/site-packages/ansible
  executable location = /usr/local/bin/ansible-playbook
  python version = 3.6.8 (default, Aug  7 2019, 17:28:10) [GCC 4.8.5 20150623 (Red Hat 4.8.5-39)]
2020-04-30 04:18:30,283 p=53 u=root n=ansible | Using /etc/ansible/ansible.cfg as config file
2020-04-30 04:18:34,999 p=53 u=root n=ansible |     53 1588220314.99948: Added group all to inventory
2020-04-30 04:18:34,999 p=53 u=root n=ansible |     53 1588220314.99977: Added group ungrouped to inventory
2020-04-30 04:18:34,999 p=53 u=root n=ansible |     53 1588220314.99991: Group all now contains ungrouped
2020-04-30 04:18:35,000 p=53 u=root n=ansible |     53 1588220315.00001: Examining possible inventory source: /root/inventory
2020-04-30 04:18:35,000 p=53 u=root n=ansible | setting up inventory plugins
2020-04-30 04:18:35,001 p=53 u=root n=ansible |     53 1588220315.00185: trying /usr/local/lib/python3.6/site-packages/ansible/plugins/cache
2020-04-30 04:18:35,003 p=53 u=root n=ansible |     53 1588220315.00380: Loading CacheModule 'memory' from /usr/local/lib/python3.6/site-packages/ansible/plugins/cache/memory.py
2020-04-30 04:18:35,004 p=53 u=root n=ansible |     53 1588220315.00419: trying /usr/local/lib/python3.6/site-packages/ansible/plugins/inventory
2020-04-30 04:18:35,006 p=53 u=root n=ansible |     53 1588220315.00596: Loading InventoryModule 'host_list' from /usr/local/lib/python3.6/site-packages/ansible/plugins/inventory/host_list.py
2020-04-30 04:18:35,010 p=53 u=root n=ansible |     53 1588220315.01074: Loaded config def from plugin (inventory/script)
2020-04-30 04:18:35,010 p=53 u=root n=ansible |     53 1588220315.01087: Loading InventoryModule 'script' from /usr/local/lib/python3.6/site-packages/ansible/plugins/inventory/script.py
2020-04-30 04:18:35,012 p=53 u=root n=ansible |     53 1588220315.01273: Loading InventoryModule 'auto' from /usr/local/lib/python3.6/site-packages/ansible/plugins/inventory/auto.py
2020-04-30 04:18:35,017 p=53 u=root n=ansible |     53 1588220315.01701: Loaded config def from plugin (inventory/yaml)
2020-04-30 04:18:35,017 p=53 u=root n=ansible |     53 1588220315.01713: Loading InventoryModule 'yaml' from /usr/local/lib/python3.6/site-packages/ansible/plugins/inventory/yaml.py
2020-04-30 04:18:35,022 p=53 u=root n=ansible |     53 1588220315.02199: Loading InventoryModule 'ini' from /usr/local/lib/python3.6/site-packages/ansible/plugins/inventory/ini.py
2020-04-30 04:18:35,023 p=53 u=root n=ansible |     53 1588220315.02358: Loading InventoryModule 'toml' from /usr/local/lib/python3.6/site-packages/ansible/plugins/inventory/toml.py
2020-04-30 04:18:35,023 p=53 u=root n=ansible |     53 1588220315.02373: Attempting to use plugin host_list (/usr/local/lib/python3.6/site-packages/ansible/plugins/inventory/host_list.py)
2020-04-30 04:18:35,023 p=53 u=root n=ansible | host_list declined parsing /root/inventory as it did not pass its verify_file() method
2020-04-30 04:18:35,023 p=53 u=root n=ansible |     53 1588220315.02388: Attempting to use plugin script (/usr/local/lib/python3.6/site-packages/ansible/plugins/inventory/script.py)
2020-04-30 04:18:35,024 p=53 u=root n=ansible | script declined parsing /root/inventory as it did not pass its verify_file() method
2020-04-30 04:18:35,024 p=53 u=root n=ansible |     53 1588220315.02405: Attempting to use plugin auto (/usr/local/lib/python3.6/site-packages/ansible/plugins/inventory/auto.py)
2020-04-30 04:18:35,024 p=53 u=root n=ansible | auto declined parsing /root/inventory as it did not pass its verify_file() method
2020-04-30 04:18:35,024 p=53 u=root n=ansible |     53 1588220315.02417: Attempting to use plugin yaml (/usr/local/lib/python3.6/site-packages/ansible/plugins/inventory/yaml.py)
2020-04-30 04:18:35,025 p=53 u=root n=ansible |     53 1588220315.02507: Loading data from /root/inventory
2020-04-30 04:18:35,025 p=53 u=root n=ansible |     53 1588220315.02567: /root/inventory was not parsable by yaml
2020-04-30 04:18:35,026 p=53 u=root n=ansible |     53 1588220315.02619: Attempting to use plugin ini (/usr/local/lib/python3.6/site-packages/ansible/plugins/inventory/ini.py)
2020-04-30 04:18:35,027 p=53 u=root n=ansible |     53 1588220315.02744: set inventory_file for tordevice.REDACTED
2020-04-30 04:18:35,027 p=53 u=root n=ansible |     53 1588220315.02757: set inventory_dir for tordevice.REDACTED
2020-04-30 04:18:35,027 p=53 u=root n=ansible |     53 1588220315.02764: Added host tordevice.REDACTED to inventory
2020-04-30 04:18:35,027 p=53 u=root n=ansible |     53 1588220315.02775: Added host tordevice.REDACTED to group ungrouped
2020-04-30 04:18:35,028 p=53 u=root n=ansible | Parsed /root/inventory inventory source with ini plugin
2020-04-30 04:18:35,028 p=53 u=root n=ansible |     53 1588220315.02819: Reconcile groups and hosts in inventory.
2020-04-30 04:18:35,028 p=53 u=root n=ansible |     53 1588220315.02843: Loading CacheModule 'memory' from /usr/local/lib/python3.6/site-packages/ansible/plugins/cache/memory.py (found_in_cache=True, class_only=False)
2020-04-30 04:18:35,043 p=53 u=root n=ansible |     53 1588220315.04362: Loaded config def from plugin (connection/buildah)
2020-04-30 04:18:35,043 p=53 u=root n=ansible |     53 1588220315.04389: Loading Connection 'buildah' from /usr/local/lib/python3.6/site-packages/ansible/plugins/connection/buildah.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,049 p=53 u=root n=ansible |     53 1588220315.04910: Loaded config def from plugin (connection/chroot)
2020-04-30 04:18:35,049 p=53 u=root n=ansible |     53 1588220315.04925: Loading Connection 'chroot' from /usr/local/lib/python3.6/site-packages/ansible/plugins/connection/chroot.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,056 p=53 u=root n=ansible |     53 1588220315.05659: Loaded config def from plugin (connection/docker)
2020-04-30 04:18:35,056 p=53 u=root n=ansible |     53 1588220315.05676: Loading Connection 'docker' from /usr/local/lib/python3.6/site-packages/ansible/plugins/connection/docker.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,059 p=53 u=root n=ansible |     53 1588220315.05963: Loaded config def from plugin (connection/funcd)
2020-04-30 04:18:35,099 p=53 u=root n=ansible |     53 1588220315.09948: Loaded config def from plugin (connection/httpapi)
2020-04-30 04:18:35,099 p=53 u=root n=ansible |     53 1588220315.09972: Loading Connection 'httpapi' from /usr/local/lib/python3.6/site-packages/ansible/plugins/connection/httpapi.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,103 p=53 u=root n=ansible |     53 1588220315.10319: Loaded config def from plugin (connection/iocage)
2020-04-30 04:18:35,103 p=53 u=root n=ansible |     53 1588220315.10334: Loading Connection 'iocage' from /usr/local/lib/python3.6/site-packages/ansible/plugins/connection/iocage.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,106 p=53 u=root n=ansible |     53 1588220315.10624: Loaded config def from plugin (connection/jail)
2020-04-30 04:18:35,106 p=53 u=root n=ansible |     53 1588220315.10638: Loading Connection 'jail' from /usr/local/lib/python3.6/site-packages/ansible/plugins/connection/jail.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,127 p=53 u=root n=ansible |     53 1588220315.12694: Loaded config def from plugin (connection/kubectl)
2020-04-30 04:18:35,127 p=53 u=root n=ansible |     53 1588220315.12709: Loading Connection 'kubectl' from /usr/local/lib/python3.6/site-packages/ansible/plugins/connection/kubectl.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,129 p=53 u=root n=ansible |     53 1588220315.12948: Loaded config def from plugin (connection/libvirt_lxc)
2020-04-30 04:18:35,129 p=53 u=root n=ansible |     53 1588220315.12962: Loading Connection 'libvirt_lxc' from /usr/local/lib/python3.6/site-packages/ansible/plugins/connection/libvirt_lxc.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,131 p=53 u=root n=ansible |     53 1588220315.13125: Loading Connection 'local' from /usr/local/lib/python3.6/site-packages/ansible/plugins/connection/local.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,134 p=53 u=root n=ansible |     53 1588220315.13463: Loaded config def from plugin (connection/lxc)
2020-04-30 04:18:35,134 p=53 u=root n=ansible |     53 1588220315.13478: Loading Connection 'lxc' from /usr/local/lib/python3.6/site-packages/ansible/plugins/connection/lxc.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,138 p=53 u=root n=ansible |     53 1588220315.13801: Loaded config def from plugin (connection/lxd)
2020-04-30 04:18:35,138 p=53 u=root n=ansible |     53 1588220315.13815: Loading Connection 'lxd' from /usr/local/lib/python3.6/site-packages/ansible/plugins/connection/lxd.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,154 p=53 u=root n=ansible |     53 1588220315.15462: Loaded config def from plugin (connection/napalm)
2020-04-30 04:18:35,154 p=53 u=root n=ansible |     53 1588220315.15480: Loading Connection 'napalm' from /usr/local/lib/python3.6/site-packages/ansible/plugins/connection/napalm.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,177 p=53 u=root n=ansible |     53 1588220315.17776: Loaded config def from plugin (connection/netconf)
2020-04-30 04:18:35,177 p=53 u=root n=ansible |     53 1588220315.17793: Loading Connection 'netconf' from /usr/local/lib/python3.6/site-packages/ansible/plugins/connection/netconf.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,214 p=53 u=root n=ansible |     53 1588220315.21441: Loaded config def from plugin (connection/network_cli)
2020-04-30 04:18:35,214 p=53 u=root n=ansible |     53 1588220315.21458: Loading Connection 'network_cli' from /usr/local/lib/python3.6/site-packages/ansible/plugins/connection/network_cli.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,231 p=53 u=root n=ansible |     53 1588220315.23104: Loaded config def from plugin (connection/oc)
2020-04-30 04:18:35,231 p=53 u=root n=ansible |     53 1588220315.23120: Loading Connection 'oc' from /usr/local/lib/python3.6/site-packages/ansible/plugins/connection/oc.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,253 p=53 u=root n=ansible |     53 1588220315.25331: Loaded config def from plugin (connection/paramiko_ssh)
2020-04-30 04:18:35,253 p=53 u=root n=ansible |     53 1588220315.25348: Loading Connection 'paramiko_ssh' from /usr/local/lib/python3.6/site-packages/ansible/plugins/connection/paramiko_ssh.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,282 p=53 u=root n=ansible |     53 1588220315.28243: Loaded config def from plugin (connection/persistent)
2020-04-30 04:18:35,282 p=53 u=root n=ansible |     53 1588220315.28275: Loading Connection 'persistent' from /usr/local/lib/python3.6/site-packages/ansible/plugins/connection/persistent.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,286 p=53 u=root n=ansible |     53 1588220315.28663: Loaded config def from plugin (connection/podman)
2020-04-30 04:18:35,286 p=53 u=root n=ansible |     53 1588220315.28678: Loading Connection 'podman' from /usr/local/lib/python3.6/site-packages/ansible/plugins/connection/podman.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,325 p=53 u=root n=ansible |     53 1588220315.32570: Loaded config def from plugin (connection/psrp)
2020-04-30 04:18:35,325 p=53 u=root n=ansible |     53 1588220315.32588: Loading Connection 'psrp' from /usr/local/lib/python3.6/site-packages/ansible/plugins/connection/psrp.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,329 p=53 u=root n=ansible |     53 1588220315.32895: Loaded config def from plugin (connection/qubes)
2020-04-30 04:18:35,329 p=53 u=root n=ansible |     53 1588220315.32910: Loading Connection 'qubes' from /usr/local/lib/python3.6/site-packages/ansible/plugins/connection/qubes.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,330 p=53 u=root n=ansible |     53 1588220315.33058: Loading Connection 'saltstack' from /usr/local/lib/python3.6/site-packages/ansible/plugins/connection/saltstack.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,370 p=53 u=root n=ansible |     53 1588220315.37048: Loaded config def from plugin (connection/ssh)
2020-04-30 04:18:35,370 p=53 u=root n=ansible |     53 1588220315.37065: Loading Connection 'ssh' from /usr/local/lib/python3.6/site-packages/ansible/plugins/connection/ssh.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,387 p=53 u=root n=ansible |     53 1588220315.38750: Loaded config def from plugin (connection/vmware_tools)
2020-04-30 04:18:35,387 p=53 u=root n=ansible |     53 1588220315.38765: Loading Connection 'vmware_tools' from /usr/local/lib/python3.6/site-packages/ansible/plugins/connection/vmware_tools.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,405 p=53 u=root n=ansible |     53 1588220315.40552: Loaded config def from plugin (connection/winrm)
2020-04-30 04:18:35,405 p=53 u=root n=ansible |     53 1588220315.40569: Loading Connection 'winrm' from /usr/local/lib/python3.6/site-packages/ansible/plugins/connection/winrm.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,407 p=53 u=root n=ansible |     53 1588220315.40790: Loaded config def from plugin (connection/zone)
2020-04-30 04:18:35,408 p=53 u=root n=ansible |     53 1588220315.40804: Loading Connection 'zone' from /usr/local/lib/python3.6/site-packages/ansible/plugins/connection/zone.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,410 p=53 u=root n=ansible |     53 1588220315.41076: trying /usr/local/lib/python3.6/site-packages/ansible/plugins/doc_fragments
2020-04-30 04:18:35,412 p=53 u=root n=ansible |     53 1588220315.41254: Loading ModuleDocFragment 'shell_windows' from /usr/local/lib/python3.6/site-packages/ansible/plugins/doc_fragments/shell_windows.py
2020-04-30 04:18:35,417 p=53 u=root n=ansible |     53 1588220315.41707: Loaded config def from plugin (shell/cmd)
2020-04-30 04:18:35,417 p=53 u=root n=ansible |     53 1588220315.41720: Loading ShellModule 'cmd' from /usr/local/lib/python3.6/site-packages/ansible/plugins/shell/cmd.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,418 p=53 u=root n=ansible |     53 1588220315.41861: Loading ModuleDocFragment 'shell_common' from /usr/local/lib/python3.6/site-packages/ansible/plugins/doc_fragments/shell_common.py
2020-04-30 04:18:35,426 p=53 u=root n=ansible |     53 1588220315.42625: Loaded config def from plugin (shell/csh)
2020-04-30 04:18:35,426 p=53 u=root n=ansible |     53 1588220315.42638: Loading ShellModule 'csh' from /usr/local/lib/python3.6/site-packages/ansible/plugins/shell/csh.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,427 p=53 u=root n=ansible |     53 1588220315.42789: Loading ModuleDocFragment 'shell_common' from /usr/local/lib/python3.6/site-packages/ansible/plugins/doc_fragments/shell_common.py (found_in_cache=True, class_only=False)
2020-04-30 04:18:35,435 p=53 u=root n=ansible |     53 1588220315.43545: Loaded config def from plugin (shell/fish)
2020-04-30 04:18:35,435 p=53 u=root n=ansible |     53 1588220315.43560: Loading ShellModule 'fish' from /usr/local/lib/python3.6/site-packages/ansible/plugins/shell/fish.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,437 p=53 u=root n=ansible |     53 1588220315.43696: Loading ModuleDocFragment 'shell_windows' from /usr/local/lib/python3.6/site-packages/ansible/plugins/doc_fragments/shell_windows.py (found_in_cache=True, class_only=False)
2020-04-30 04:18:35,441 p=53 u=root n=ansible |     53 1588220315.44125: Loaded config def from plugin (shell/powershell)
2020-04-30 04:18:35,441 p=53 u=root n=ansible |     53 1588220315.44137: Loading ShellModule 'powershell' from /usr/local/lib/python3.6/site-packages/ansible/plugins/shell/powershell.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,442 p=53 u=root n=ansible |     53 1588220315.44258: Loading ModuleDocFragment 'shell_common' from /usr/local/lib/python3.6/site-packages/ansible/plugins/doc_fragments/shell_common.py (found_in_cache=True, class_only=False)
2020-04-30 04:18:35,450 p=53 u=root n=ansible |     53 1588220315.45083: Loaded config def from plugin (shell/sh)
2020-04-30 04:18:35,450 p=53 u=root n=ansible |     53 1588220315.45096: Loading ShellModule 'sh' from /usr/local/lib/python3.6/site-packages/ansible/plugins/shell/sh.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,462 p=53 u=root n=ansible |     53 1588220315.46282: Loaded config def from plugin (become/doas)
2020-04-30 04:18:35,462 p=53 u=root n=ansible |     53 1588220315.46295: Loading BecomeModule 'doas' from /usr/local/lib/python3.6/site-packages/ansible/plugins/become/doas.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,472 p=53 u=root n=ansible |     53 1588220315.47234: Loaded config def from plugin (become/dzdo)
2020-04-30 04:18:35,472 p=53 u=root n=ansible |     53 1588220315.47247: Loading BecomeModule 'dzdo' from /usr/local/lib/python3.6/site-packages/ansible/plugins/become/dzdo.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,476 p=53 u=root n=ansible |     53 1588220315.47611: Loaded config def from plugin (become/enable)
2020-04-30 04:18:35,476 p=53 u=root n=ansible |     53 1588220315.47624: Loading BecomeModule 'enable' from /usr/local/lib/python3.6/site-packages/ansible/plugins/become/enable.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,487 p=53 u=root n=ansible |     53 1588220315.48751: Loaded config def from plugin (become/ksu)
2020-04-30 04:18:35,487 p=53 u=root n=ansible |     53 1588220315.48764: Loading BecomeModule 'ksu' from /usr/local/lib/python3.6/site-packages/ansible/plugins/become/ksu.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,497 p=53 u=root n=ansible |     53 1588220315.49731: Loaded config def from plugin (become/machinectl)
2020-04-30 04:18:35,497 p=53 u=root n=ansible |     53 1588220315.49744: Loading BecomeModule 'machinectl' from /usr/local/lib/python3.6/site-packages/ansible/plugins/become/machinectl.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,508 p=53 u=root n=ansible |     53 1588220315.50838: Loaded config def from plugin (become/pbrun)
2020-04-30 04:18:35,508 p=53 u=root n=ansible |     53 1588220315.50852: Loading BecomeModule 'pbrun' from /usr/local/lib/python3.6/site-packages/ansible/plugins/become/pbrun.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,520 p=53 u=root n=ansible |     53 1588220315.52075: Loaded config def from plugin (become/pfexec)
2020-04-30 04:18:35,520 p=53 u=root n=ansible |     53 1588220315.52089: Loading BecomeModule 'pfexec' from /usr/local/lib/python3.6/site-packages/ansible/plugins/become/pfexec.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,528 p=53 u=root n=ansible |     53 1588220315.52864: Loaded config def from plugin (become/pmrun)
2020-04-30 04:18:35,528 p=53 u=root n=ansible |     53 1588220315.52879: Loading BecomeModule 'pmrun' from /usr/local/lib/python3.6/site-packages/ansible/plugins/become/pmrun.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,537 p=53 u=root n=ansible |     53 1588220315.53716: Loaded config def from plugin (become/runas)
2020-04-30 04:18:35,537 p=53 u=root n=ansible |     53 1588220315.53730: Loading BecomeModule 'runas' from /usr/local/lib/python3.6/site-packages/ansible/plugins/become/runas.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,546 p=53 u=root n=ansible |     53 1588220315.54680: Loaded config def from plugin (become/sesu)
2020-04-30 04:18:35,546 p=53 u=root n=ansible |     53 1588220315.54694: Loading BecomeModule 'sesu' from /usr/local/lib/python3.6/site-packages/ansible/plugins/become/sesu.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,558 p=53 u=root n=ansible |     53 1588220315.55827: Loaded config def from plugin (become/su)
2020-04-30 04:18:35,558 p=53 u=root n=ansible |     53 1588220315.55843: Loading BecomeModule 'su' from /usr/local/lib/python3.6/site-packages/ansible/plugins/become/su.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,567 p=53 u=root n=ansible |     53 1588220315.56790: Loaded config def from plugin (become/sudo)
2020-04-30 04:18:35,568 p=53 u=root n=ansible |     53 1588220315.56804: Loading BecomeModule 'sudo' from /usr/local/lib/python3.6/site-packages/ansible/plugins/become/sudo.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,568 p=53 u=root n=ansible |     53 1588220315.56839: Loading data from /root/test.yaml
2020-04-30 04:18:35,576 p=53 u=root n=ansible |     53 1588220315.57599: trying /usr/local/lib/python3.6/site-packages/ansible/plugins/action
2020-04-30 04:18:35,577 p=53 u=root n=ansible |     53 1588220315.57722: trying /usr/local/lib/python3.6/site-packages/ansible/plugins/action/__pycache__
2020-04-30 04:18:35,598 p=53 u=root n=ansible |     53 1588220315.59877: trying /usr/local/lib/python3.6/site-packages/ansible/modules
2020-04-30 04:18:35,599 p=53 u=root n=ansible |     53 1588220315.59908: trying /usr/local/lib/python3.6/site-packages/ansible/modules/identity
2020-04-30 04:18:35,599 p=53 u=root n=ansible |     53 1588220315.59929: trying /usr/local/lib/python3.6/site-packages/ansible/modules/source_control
2020-04-30 04:18:35,599 p=53 u=root n=ansible |     53 1588220315.59969: trying /usr/local/lib/python3.6/site-packages/ansible/modules/remote_management
2020-04-30 04:18:35,599 p=53 u=root n=ansible |     53 1588220315.59992: trying /usr/local/lib/python3.6/site-packages/ansible/modules/network
2020-04-30 04:18:35,600 p=53 u=root n=ansible |     53 1588220315.60044: trying /usr/local/lib/python3.6/site-packages/ansible/modules/storage
2020-04-30 04:18:35,600 p=53 u=root n=ansible |     53 1588220315.60060: trying /usr/local/lib/python3.6/site-packages/ansible/modules/utilities
2020-04-30 04:18:35,600 p=53 u=root n=ansible |     53 1588220315.60074: trying /usr/local/lib/python3.6/site-packages/ansible/modules/clustering
2020-04-30 04:18:35,600 p=53 u=root n=ansible |     53 1588220315.60095: trying /usr/local/lib/python3.6/site-packages/ansible/modules/net_tools
2020-04-30 04:18:35,601 p=53 u=root n=ansible |     53 1588220315.60129: trying /usr/local/lib/python3.6/site-packages/ansible/modules/system
2020-04-30 04:18:35,602 p=53 u=root n=ansible |     53 1588220315.60232: trying /usr/local/lib/python3.6/site-packages/ansible/modules/commands
2020-04-30 04:18:35,602 p=53 u=root n=ansible |     53 1588220315.60254: trying /usr/local/lib/python3.6/site-packages/ansible/modules/monitoring
2020-04-30 04:18:35,603 p=53 u=root n=ansible |     53 1588220315.60305: trying /usr/local/lib/python3.6/site-packages/ansible/modules/files
2020-04-30 04:18:35,603 p=53 u=root n=ansible |     53 1588220315.60343: trying /usr/local/lib/python3.6/site-packages/ansible/modules/messaging
2020-04-30 04:18:35,603 p=53 u=root n=ansible |     53 1588220315.60354: trying /usr/local/lib/python3.6/site-packages/ansible/modules/web_infrastructure
2020-04-30 04:18:35,603 p=53 u=root n=ansible |     53 1588220315.60392: trying /usr/local/lib/python3.6/site-packages/ansible/modules/notification
2020-04-30 04:18:35,604 p=53 u=root n=ansible |     53 1588220315.60440: trying /usr/local/lib/python3.6/site-packages/ansible/modules/packaging
2020-04-30 04:18:35,604 p=53 u=root n=ansible |     53 1588220315.60452: trying /usr/local/lib/python3.6/site-packages/ansible/modules/inventory
2020-04-30 04:18:35,604 p=53 u=root n=ansible |     53 1588220315.60465: trying /usr/local/lib/python3.6/site-packages/ansible/modules/crypto
2020-04-30 04:18:35,605 p=53 u=root n=ansible |     53 1588220315.60499: trying /usr/local/lib/python3.6/site-packages/ansible/modules/database
2020-04-30 04:18:35,605 p=53 u=root n=ansible |     53 1588220315.60515: trying /usr/local/lib/python3.6/site-packages/ansible/modules/cloud
2020-04-30 04:18:35,605 p=53 u=root n=ansible |     53 1588220315.60551: trying /usr/local/lib/python3.6/site-packages/ansible/modules/__pycache__
2020-04-30 04:18:35,605 p=53 u=root n=ansible |     53 1588220315.60561: trying /usr/local/lib/python3.6/site-packages/ansible/modules/identity/ipa
2020-04-30 04:18:35,605 p=53 u=root n=ansible |     53 1588220315.60592: trying /usr/local/lib/python3.6/site-packages/ansible/modules/identity/cyberark
2020-04-30 04:18:35,606 p=53 u=root n=ansible |     53 1588220315.60606: trying /usr/local/lib/python3.6/site-packages/ansible/modules/identity/keycloak
2020-04-30 04:18:35,606 p=53 u=root n=ansible |     53 1588220315.60622: trying /usr/local/lib/python3.6/site-packages/ansible/modules/identity/opendj
2020-04-30 04:18:35,606 p=53 u=root n=ansible |     53 1588220315.60634: trying /usr/local/lib/python3.6/site-packages/ansible/modules/identity/__pycache__
2020-04-30 04:18:35,606 p=53 u=root n=ansible |     53 1588220315.60646: trying /usr/local/lib/python3.6/site-packages/ansible/modules/identity/ipa/__pycache__
2020-04-30 04:18:35,606 p=53 u=root n=ansible |     53 1588220315.60669: trying /usr/local/lib/python3.6/site-packages/ansible/modules/identity/cyberark/__pycache__
2020-04-30 04:18:35,606 p=53 u=root n=ansible |     53 1588220315.60682: trying /usr/local/lib/python3.6/site-packages/ansible/modules/identity/keycloak/__pycache__
2020-04-30 04:18:35,606 p=53 u=root n=ansible |     53 1588220315.60694: trying /usr/local/lib/python3.6/site-packages/ansible/modules/identity/opendj/__pycache__
2020-04-30 04:18:35,607 p=53 u=root n=ansible |     53 1588220315.60705: trying /usr/local/lib/python3.6/site-packages/ansible/modules/source_control/bitbucket
2020-04-30 04:18:35,607 p=53 u=root n=ansible |     53 1588220315.60721: trying /usr/local/lib/python3.6/site-packages/ansible/modules/source_control/__pycache__
2020-04-30 04:18:35,607 p=53 u=root n=ansible |     53 1588220315.60750: trying /usr/local/lib/python3.6/site-packages/ansible/modules/source_control/bitbucket/__pycache__
2020-04-30 04:18:35,607 p=53 u=root n=ansible |     53 1588220315.60764: trying /usr/local/lib/python3.6/site-packages/ansible/modules/remote_management/manageiq
2020-04-30 04:18:35,607 p=53 u=root n=ansible |     53 1588220315.60788: trying /usr/local/lib/python3.6/site-packages/ansible/modules/remote_management/ipmi
2020-04-30 04:18:35,608 p=53 u=root n=ansible |     53 1588220315.60803: trying /usr/local/lib/python3.6/site-packages/ansible/modules/remote_management/stacki
2020-04-30 04:18:35,608 p=53 u=root n=ansible |     53 1588220315.60815: trying /usr/local/lib/python3.6/site-packages/ansible/modules/remote_management/cobbler
2020-04-30 04:18:35,608 p=53 u=root n=ansible |     53 1588220315.60829: trying /usr/local/lib/python3.6/site-packages/ansible/modules/remote_management/cpm
2020-04-30 04:18:35,608 p=53 u=root n=ansible |     53 1588220315.60846: trying /usr/local/lib/python3.6/site-packages/ansible/modules/remote_management/intersight
2020-04-30 04:18:35,608 p=53 u=root n=ansible |     53 1588220315.60863: trying /usr/local/lib/python3.6/site-packages/ansible/modules/remote_management/foreman
2020-04-30 04:18:35,608 p=53 u=root n=ansible |     53 1588220315.60878: trying /usr/local/lib/python3.6/site-packages/ansible/modules/remote_management/redfish
2020-04-30 04:18:35,609 p=53 u=root n=ansible |     53 1588220315.60901: trying /usr/local/lib/python3.6/site-packages/ansible/modules/remote_management/dellemc
2020-04-30 04:18:35,609 p=53 u=root n=ansible |     53 1588220315.60915: trying /usr/local/lib/python3.6/site-packages/ansible/modules/remote_management/oneview
2020-04-30 04:18:35,609 p=53 u=root n=ansible |     53 1588220315.60957: trying /usr/local/lib/python3.6/site-packages/ansible/modules/remote_management/ucs
2020-04-30 04:18:35,610 p=53 u=root n=ansible |     53 1588220315.60998: trying /usr/local/lib/python3.6/site-packages/ansible/modules/remote_management/imc
2020-04-30 04:18:35,610 p=53 u=root n=ansible |     53 1588220315.61012: trying /usr/local/lib/python3.6/site-packages/ansible/modules/remote_management/hpilo
2020-04-30 04:18:35,610 p=53 u=root n=ansible |     53 1588220315.61029: trying /usr/local/lib/python3.6/site-packages/ansible/modules/remote_management/lxca
2020-04-30 04:18:35,610 p=53 u=root n=ansible |     53 1588220315.61044: trying /usr/local/lib/python3.6/site-packages/ansible/modules/remote_management/__pycache__
2020-04-30 04:18:35,610 p=53 u=root n=ansible |     53 1588220315.61057: trying /usr/local/lib/python3.6/site-packages/ansible/modules/remote_management/manageiq/__pycache__
2020-04-30 04:18:35,610 p=53 u=root n=ansible |     53 1588220315.61075: trying /usr/local/lib/python3.6/site-packages/ansible/modules/remote_management/ipmi/__pycache__
2020-04-30 04:18:35,610 p=53 u=root n=ansible |     53 1588220315.61089: trying /usr/local/lib/python3.6/site-packages/ansible/modules/remote_management/stacki/__pycache__
2020-04-30 04:18:35,611 p=53 u=root n=ansible |     53 1588220315.61099: trying /usr/local/lib/python3.6/site-packages/ansible/modules/remote_management/cobbler/__pycache__
2020-04-30 04:18:35,611 p=53 u=root n=ansible |     53 1588220315.61111: trying /usr/local/lib/python3.6/site-packages/ansible/modules/remote_management/cpm/__pycache__
2020-04-30 04:18:35,611 p=53 u=root n=ansible |     53 1588220315.61126: trying /usr/local/lib/python3.6/site-packages/ansible/modules/remote_management/intersight/__pycache__
2020-04-30 04:18:35,611 p=53 u=root n=ansible |     53 1588220315.61138: trying /usr/local/lib/python3.6/site-packages/ansible/modules/remote_management/foreman/__pycache__
2020-04-30 04:18:35,611 p=53 u=root n=ansible |     53 1588220315.61150: trying /usr/local/lib/python3.6/site-packages/ansible/modules/remote_management/redfish/__pycache__
2020-04-30 04:18:35,611 p=53 u=root n=ansible |     53 1588220315.61166: trying /usr/local/lib/python3.6/site-packages/ansible/modules/remote_management/dellemc/__pycache__
2020-04-30 04:18:35,611 p=53 u=root n=ansible |     53 1588220315.61180: trying /usr/local/lib/python3.6/site-packages/ansible/modules/remote_management/oneview/__pycache__
2020-04-30 04:18:35,612 p=53 u=root n=ansible |     53 1588220315.61210: trying /usr/local/lib/python3.6/site-packages/ansible/modules/remote_management/ucs/__pycache__
2020-04-30 04:18:35,612 p=53 u=root n=ansible |     53 1588220315.61237: trying /usr/local/lib/python3.6/site-packages/ansible/modules/remote_management/imc/__pycache__
2020-04-30 04:18:35,612 p=53 u=root n=ansible |     53 1588220315.61248: trying /usr/local/lib/python3.6/site-packages/ansible/modules/remote_management/hpilo/__pycache__
2020-04-30 04:18:35,612 p=53 u=root n=ansible |     53 1588220315.61261: trying /usr/local/lib/python3.6/site-packages/ansible/modules/remote_management/lxca/__pycache__
2020-04-30 04:18:35,612 p=53 u=root n=ansible |     53 1588220315.61274: trying /usr/local/lib/python3.6/site-packages/ansible/modules/network/netscaler
2020-04-30 04:18:35,613 p=53 u=root n=ansible |     53 1588220315.61303: trying /usr/local/lib/python3.6/site-packages/ansible/modules/network/avi
2020-04-30 04:18:35,614 p=53 u=root n=ansible |     53 1588220315.61411: trying /usr/local/lib/python3.6/site-packages/ansible/modules/network/vyos
2020-04-30 04:18:35,614 p=53 u=root n=ansible |     53 1588220315.61455: trying /usr/local/lib/python3.6/site-packages/ansible/modules/network/netact
2020-04-30 04:18:35,614 p=53 u=root n=ansible |     53 1588220315.61470: trying /usr/local/lib/python3.6/site-packages/ansible/modules/network/meraki
2020-04-30 04:18:35,615 p=53 u=root n=ansible |     53 1588220315.61505: trying /usr/local/lib/python3.6/site-packages/ansible/modules/network/interface
2020-04-30 04:18:35,615 p=53 u=root n=ansible |     53 1588220315.61522: trying /usr/local/lib/python3.6/site-packages/ansible/modules/network/aruba
2020-04-30 04:18:35,615 p=53 u=root n=ansible |     53 1588220315.61536: trying /usr/local/lib/python3.6/site-packages/ansible/modules/network/routing
2020-04-30 04:18:35,615 p=53 u=root n=ansible |     53 1588220315.61548: trying /usr/local/lib/python3.6/site-packages/ansible/modules/network/aireos
2020-04-30 04:18:35,615 p=53 u=root n=ansible |     53 1588220315.61561: trying /usr/local/lib/python3.6/site-packages/ansible/modules/network/bigswitch
2020-04-30 04:18:35,615 p=53 u=root n=ansible |     53 1588220315.61580: trying /usr/local/lib/python3.6/site-packages/ansible/modules/network/aci
2020-04-30 04:18:35,617 p=53 u=root n=ansible |     53 1588220315.61729: trying /usr/local/lib/python3.6/site-packages/ansible/modules/network/panos
2020-04-30 04:18:35,617 p=53 u=root n=ansible |     53 1588220315.61773: trying /usr/local/lib/python3.6/site-packages/ansible/modules/network/cloudengine
2020-04-30 04:18:35,618 p=53 u=root n=ansible |     53 1588220315.61868: trying /usr/local/lib/python3.6/site-packages/ansible/modules/network/dellos6
2020-04-30 04:18:35,618 p=53 u=root n=ansible |     53 1588220315.61884: trying /usr/local/lib/python3.6/site-packages/ansible/modules/network/layer3
2020-04-30 04:18:35,619 p=53 u=root n=ansible |     53 1588220315.61909: trying /usr/local/lib/python3.6/site-packages/ansible/modules/network/junos
2020-04-30 04:18:35,619 p=53 u=root n=ansible |     53 1588220315.61959: trying /usr/local/lib/python3.6/site-packages/ansible/modules/network/eric_eccli
2020-04-30 04:18:35,619 p=53 u=root n=ansible |     53 1588220315.61973: trying /usr/local/lib/python3.6/site-packages/ansible/modules/network/nso
2020-04-30 04:18:35,619 p=53 u=root n=ansible |     53 1588220315.61991: trying /usr/local/lib/python3.6/site-packages/ansible/modules/network/f5
2020-04-30 04:18:35,622 p=53 u=root n=ansible |     53 1588220315.62219: trying /usr/local/lib/python3.6/site-packages/ansible/modules/network/skydive
2020-04-30 04:18:35,622 p=53 u=root n=ansible |     53 1588220315.62238: trying /usr/local/lib/python3.6/site-packages/ansible/modules/network/fortimanager
2020-04-30 04:18:35,622 p=53 u=root n=ansible |     53 1588220315.62286: trying /usr/local/lib/python3.6/site-packages/ansible/modules/network/check_point
2020-04-30 04:18:35,624 p=53 u=root n=ansible |     53 1588220315.62424: trying /usr/local/lib/python3.6/site-packages/ansible/modules/network/icx
2020-04-30 04:18:35,624 p=53 u=root n=ansible |     53 1588220315.62457: trying /usr/local/lib/python3.6/site-packages/ansible/modules/network/opx
2020-04-30 04:18:35,624 p=53 u=root n=ansible |     53 1588220315.62471: trying /usr/local/lib/python3.6/site-packages/ansible/modules/network/citrix
2020-04-30 04:18:35,624 p=53 u=root n=ansible |     53 1588220315.62483: trying /usr/local/lib/python3.6/site-packages/ansible/modules/network/fortios
2020-04-30 04:18:35,630 p=53 u=root n=ansible |     53 1588220315.63065: trying /usr/local/lib/python3.6/site-packages/ansible/modules/network/dellos9
2020-04-30 04:18:35,630 p=53 u=root n=ansible |     53 1588220315.63088: trying /usr/local/lib/python3.6/site-packages/ansible/modules/network/voss
2020-04-30 04:18:35,631 p=53 u=root n=ansible |     53 1588220315.63104: trying /usr/local/lib/python3.6/site-packages/ansible/modules/network/ordnance
2020-04-30 04:18:35,631 p=53 u=root n=ansible |     53 1588220315.63119: trying /usr/local/lib/python3.6/site-packages/ansible/modules/network/nos
2020-04-30 04:18:35,631 p=53 u=root n=ansible |     53 1588220315.63134: trying /usr/local/lib/python3.6/site-packages/ansible/modules/network/ingate
2020-04-30 04:18:35,631 p=53 u=root n=ansible |     53 1588220315.63147: trying /usr/local/lib/python3.6/site-packages/ansible/modules/network/frr
2020-04-30 04:18:35,631 p=53 u=root n=ansible |     53 1588220315.63160: trying /usr/local/lib/python3.6/site-packages/ansible/modules/network/fortianalyzer
2020-04-30 04:18:35,631 p=53 u=root n=ansible |     53 1588220315.63174: trying /usr/local/lib/python3.6/site-packages/ansible/modules/network/cnos
2020-04-30 04:18:35,632 p=53 u=root n=ansible |     53 1588220315.63232: trying /usr/local/lib/python3.6/site-packages/ansible/modules/network/illumos
2020-04-30 04:18:35,632 p=53 u=root n=ansible |     53 1588220315.63260: trying /usr/local/lib/python3.6/site-packages/ansible/modules/network/enos
2020-04-30 04:18:35,632 p=53 u=root n=ansible |     53 1588220315.63277: trying /usr/local/lib/python3.6/site-packages/ansible/modules/network/protocol
2020-04-30 04:18:35,632 p=53 u=root n=ansible |     53 1588220315.63289: trying /usr/local/lib/python3.6/site-packages/ansible/modules/network/system
2020-04-30 04:18:35,633 p=53 u=root n=ansible |     53 1588220315.63306: trying /usr/local/lib/python3.6/site-packages/ansible/modules/network/ftd
2020-04-30 04:18:35,633 p=53 u=root n=ansible |     53 1588220315.63323: trying /usr/local/lib/python3.6/site-packages/ansible/modules/network/cumulus
2020-04-30 04:18:35,633 p=53 u=root n=ansible |     53 1588220315.63344: trying /usr/local/lib/python3.6/site-packages/ansible/modules/network/onyx
2020-04-30 04:18:35,633 p=53 u=root n=ansible |     53 1588220315.63390: trying /usr/local/lib/python3.6/site-packages/ansible/modules/network/cloudvision
2020-04-30 04:18:35,634 p=53 u=root n=ansible |     53 1588220315.63403: trying /usr/local/lib/python3.6/site-packages/ansible/modules/network/ironware
2020-04-30 04:18:35,634 p=53 u=root n=ansible |     53 1588220315.63419: trying /usr/local/lib/python3.6/site-packages/ansible/modules/network/eos
2020-04-30 04:18:35,634 p=53 u=root n=ansible |     53 1588220315.63462: trying /usr/local/lib/python3.6/site-packages/ansible/modules/network/nuage
2020-04-30 04:18:35,634 p=53 u=root n=ansible |     53 1588220315.63477: trying /usr/local/lib/python3.6/site-packages/ansible/modules/network/files
2020-04-30 04:18:35,634 p=53 u=root n=ansible |     53 1588220315.63490: trying /usr/local/lib/python3.6/site-packages/ansible/modules/network/edgeswitch
2020-04-30 04:18:35,635 p=53 u=root n=ansible |     53 1588220315.63503: trying /usr/local/lib/python3.6/site-packages/ansible/modules/network/aos
2020-04-30 04:18:35,635 p=53 u=root n=ansible |     53 1588220315.63528: trying /usr/local/lib/python3.6/site-packages/ansible/modules/network/routeros
2020-04-30 04:18:35,635 p=53 u=root n=ansible |     53 1588220315.63542: trying /usr/local/lib/python3.6/site-packages/ansible/modules/network/cli
2020-04-30 04:18:35,635 p=53 u=root n=ansible |     53 1588220315.63555: trying /usr/local/lib/python3.6/site-packages/ansible/modules/network/restconf
2020-04-30 04:18:35,635 p=53 u=root n=ansible |     53 1588220315.63569: trying /usr/local/lib/python3.6/site-packages/ansible/modules/network/edgeos
2020-04-30 04:18:35,635 p=53 u=root n=ansible |     53 1588220315.63584: trying /usr/local/lib/python3.6/site-packages/ansible/modules/network/netvisor
2020-04-30 04:18:35,636 p=53 u=root n=ansible |     53 1588220315.63659: trying /usr/local/lib/python3.6/site-packages/ansible/modules/network/dellos10
2020-04-30 04:18:35,636 p=53 u=root n=ansible |     53 1588220315.63678: trying /usr/local/lib/python3.6/site-packages/ansible/modules/network/ios
2020-04-30 04:18:35,637 p=53 u=root n=ansible |     53 1588220315.63725: trying /usr/local/lib/python3.6/site-packages/ansible/modules/network/asa
2020-04-30 04:18:35,637 p=53 u=root n=ansible |     53 1588220315.63742: trying /usr/local/lib/python3.6/site-packages/ansible/modules/network/ovs
2020-04-30 04:18:35,637 p=53 u=root n=ansible |     53 1588220315.63758: trying /usr/local/lib/python3.6/site-packages/ansible/modules/network/iosxr
2020-04-30 04:18:35,637 p=53 u=root n=ansible |     53 1588220315.63792: trying /usr/local/lib/python3.6/site-packages/ansible/modules/network/sros
2020-04-30 04:18:35,638 p=53 u=root n=ansible |     53 1588220315.63814: trying /usr/local/lib/python3.6/site-packages/ansible/modules/network/a10
2020-04-30 04:18:35,638 p=53 u=root n=ansible |     53 1588220315.63835: trying /usr/local/lib/python3.6/site-packages/ansible/modules/network/layer2
2020-04-30 04:18:35,638 p=53 u=root n=ansible |     53 1588220315.63852: trying /usr/local/lib/python3.6/site-packages/ansible/modules/network/netconf
2020-04-30 04:18:35,638 p=53 u=root n=ansible |     53 1588220315.63870: trying /usr/local/lib/python3.6/site-packages/ansible/modules/network/nxos
2020-04-30 04:18:35,640 p=53 u=root n=ansible |     53 1588220315.64074: trying /usr/local/lib/python3.6/site-packages/ansible/plugins/callback
2020-04-30 04:18:35,645 p=53 u=root n=ansible |     53 1588220315.64550: Loading ModuleDocFragment 'default_callback' from /usr/local/lib/python3.6/site-packages/ansible/plugins/doc_fragments/default_callback.py
2020-04-30 04:18:35,654 p=53 u=root n=ansible |     53 1588220315.65406: Loaded config def from plugin (callback/default)
2020-04-30 04:18:35,654 p=53 u=root n=ansible |     53 1588220315.65421: Loading CallbackModule 'default' from /usr/local/lib/python3.6/site-packages/ansible/plugins/callback/default.py
2020-04-30 04:18:35,654 p=53 u=root n=ansible | Loading callback plugin default of type stdout, v2.0 from /usr/local/lib/python3.6/site-packages/ansible/plugins/callback/default.py
2020-04-30 04:18:35,661 p=53 u=root n=ansible |     53 1588220315.66111: Loading ModuleDocFragment 'default_callback' from /usr/local/lib/python3.6/site-packages/ansible/plugins/doc_fragments/default_callback.py (found_in_cache=True, class_only=False)
2020-04-30 04:18:35,670 p=53 u=root n=ansible |     53 1588220315.67001: Loaded config def from plugin (callback/actionable)
2020-04-30 04:18:35,670 p=53 u=root n=ansible |     53 1588220315.67018: Loading CallbackModule 'actionable' from /usr/local/lib/python3.6/site-packages/ansible/plugins/callback/actionable.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,672 p=53 u=root n=ansible |     53 1588220315.67205: Loading CallbackModule 'aws_resource_actions' from /usr/local/lib/python3.6/site-packages/ansible/plugins/callback/aws_resource_actions.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,677 p=53 u=root n=ansible |     53 1588220315.67698: Loaded config def from plugin (callback/cgroup_memory_recap)
2020-04-30 04:18:35,677 p=53 u=root n=ansible |     53 1588220315.67711: Loading CallbackModule 'cgroup_memory_recap' from /usr/local/lib/python3.6/site-packages/ansible/plugins/callback/cgroup_memory_recap.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,697 p=53 u=root n=ansible |     53 1588220315.69754: Loaded config def from plugin (callback/cgroup_perf_recap)
2020-04-30 04:18:35,697 p=53 u=root n=ansible |     53 1588220315.69772: Loading CallbackModule 'cgroup_perf_recap' from /usr/local/lib/python3.6/site-packages/ansible/plugins/callback/cgroup_perf_recap.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,699 p=53 u=root n=ansible |     53 1588220315.69935: Loading CallbackModule 'context_demo' from /usr/local/lib/python3.6/site-packages/ansible/plugins/callback/context_demo.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,701 p=53 u=root n=ansible |     53 1588220315.70160: Loading ModuleDocFragment 'default_callback' from /usr/local/lib/python3.6/site-packages/ansible/plugins/doc_fragments/default_callback.py (found_in_cache=True, class_only=False)
2020-04-30 04:18:35,712 p=53 u=root n=ansible |     53 1588220315.71193: Loaded config def from plugin (callback/counter_enabled)
2020-04-30 04:18:35,712 p=53 u=root n=ansible |     53 1588220315.71213: Loading CallbackModule 'counter_enabled' from /usr/local/lib/python3.6/site-packages/ansible/plugins/callback/counter_enabled.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,714 p=53 u=root n=ansible |     53 1588220315.71412: Loading ModuleDocFragment 'default_callback' from /usr/local/lib/python3.6/site-packages/ansible/plugins/doc_fragments/default_callback.py (found_in_cache=True, class_only=False)
2020-04-30 04:18:35,723 p=53 u=root n=ansible |     53 1588220315.72311: Loaded config def from plugin (callback/debug)
2020-04-30 04:18:35,723 p=53 u=root n=ansible |     53 1588220315.72328: Loading CallbackModule 'debug' from /usr/local/lib/python3.6/site-packages/ansible/plugins/callback/debug.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,723 p=53 u=root n=ansible |     53 1588220315.72338: Loading CallbackModule 'default' from /usr/local/lib/python3.6/site-packages/ansible/plugins/callback/default.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,725 p=53 u=root n=ansible |     53 1588220315.72528: Loading ModuleDocFragment 'default_callback' from /usr/local/lib/python3.6/site-packages/ansible/plugins/doc_fragments/default_callback.py (found_in_cache=True, class_only=False)
2020-04-30 04:18:35,733 p=53 u=root n=ansible |     53 1588220315.73390: Loaded config def from plugin (callback/dense)
2020-04-30 04:18:35,734 p=53 u=root n=ansible |     53 1588220315.73403: Loading CallbackModule 'dense' from /usr/local/lib/python3.6/site-packages/ansible/plugins/callback/dense.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,742 p=53 u=root n=ansible |     53 1588220315.74232: Loaded config def from plugin (callback/foreman)
2020-04-30 04:18:35,742 p=53 u=root n=ansible |     53 1588220315.74246: Loading CallbackModule 'foreman' from /usr/local/lib/python3.6/site-packages/ansible/plugins/callback/foreman.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,745 p=53 u=root n=ansible |     53 1588220315.74494: Loading ModuleDocFragment 'default_callback' from /usr/local/lib/python3.6/site-packages/ansible/plugins/doc_fragments/default_callback.py (found_in_cache=True, class_only=False)
2020-04-30 04:18:35,753 p=53 u=root n=ansible |     53 1588220315.75377: Loaded config def from plugin (callback/full_skip)
2020-04-30 04:18:35,753 p=53 u=root n=ansible |     53 1588220315.75393: Loading CallbackModule 'full_skip' from /usr/local/lib/python3.6/site-packages/ansible/plugins/callback/full_skip.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,765 p=53 u=root n=ansible |     53 1588220315.76571: Loaded config def from plugin (callback/grafana_annotations)
2020-04-30 04:18:35,765 p=53 u=root n=ansible |     53 1588220315.76589: Loading CallbackModule 'grafana_annotations' from /usr/local/lib/python3.6/site-packages/ansible/plugins/callback/grafana_annotations.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,773 p=53 u=root n=ansible |     53 1588220315.77361: Loaded config def from plugin (callback/hipchat)
2020-04-30 04:18:35,773 p=53 u=root n=ansible |     53 1588220315.77381: Loading CallbackModule 'hipchat' from /usr/local/lib/python3.6/site-packages/ansible/plugins/callback/hipchat.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,778 p=53 u=root n=ansible |     53 1588220315.77859: Loaded config def from plugin (callback/jabber)
2020-04-30 04:18:35,779 p=53 u=root n=ansible |     53 1588220315.77889: Loading CallbackModule 'jabber' from /usr/local/lib/python3.6/site-packages/ansible/plugins/callback/jabber.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,782 p=53 u=root n=ansible |     53 1588220315.78221: Loaded config def from plugin (callback/json)
2020-04-30 04:18:35,782 p=53 u=root n=ansible |     53 1588220315.78235: Loading CallbackModule 'json' from /usr/local/lib/python3.6/site-packages/ansible/plugins/callback/json.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,792 p=53 u=root n=ansible |     53 1588220315.79278: Loaded config def from plugin (callback/junit)
2020-04-30 04:18:35,792 p=53 u=root n=ansible |     53 1588220315.79296: Loading CallbackModule 'junit' from /usr/local/lib/python3.6/site-packages/ansible/plugins/callback/junit.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,796 p=53 u=root n=ansible |     53 1588220315.79600: Loaded config def from plugin (callback/log_plays)
2020-04-30 04:18:35,796 p=53 u=root n=ansible |     53 1588220315.79614: Loading CallbackModule 'log_plays' from /usr/local/lib/python3.6/site-packages/ansible/plugins/callback/log_plays.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,803 p=53 u=root n=ansible |     53 1588220315.80313: Loaded config def from plugin (callback/logdna)
2020-04-30 04:18:35,803 p=53 u=root n=ansible |     53 1588220315.80328: Loading CallbackModule 'logdna' from /usr/local/lib/python3.6/site-packages/ansible/plugins/callback/logdna.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,813 p=53 u=root n=ansible |     53 1588220315.81334: Loaded config def from plugin (callback/logentries)
2020-04-30 04:18:35,813 p=53 u=root n=ansible |     53 1588220315.81349: Loading CallbackModule 'logentries' from /usr/local/lib/python3.6/site-packages/ansible/plugins/callback/logentries.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,817 p=53 u=root n=ansible |     53 1588220315.81734: Loaded config def from plugin (callback/logstash)
2020-04-30 04:18:35,817 p=53 u=root n=ansible |     53 1588220315.81747: Loading CallbackModule 'logstash' from /usr/local/lib/python3.6/site-packages/ansible/plugins/callback/logstash.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,843 p=53 u=root n=ansible |     53 1588220315.84363: Loaded config def from plugin (callback/mail)
2020-04-30 04:18:35,843 p=53 u=root n=ansible |     53 1588220315.84386: Loading CallbackModule 'mail' from /usr/local/lib/python3.6/site-packages/ansible/plugins/callback/mail.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,845 p=53 u=root n=ansible |     53 1588220315.84522: Loading CallbackModule 'minimal' from /usr/local/lib/python3.6/site-packages/ansible/plugins/callback/minimal.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,853 p=53 u=root n=ansible |     53 1588220315.85330: Loaded config def from plugin (callback/nrdp)
2020-04-30 04:18:35,853 p=53 u=root n=ansible |     53 1588220315.85345: Loading CallbackModule 'nrdp' from /usr/local/lib/python3.6/site-packages/ansible/plugins/callback/nrdp.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,854 p=53 u=root n=ansible |     53 1588220315.85479: Loading CallbackModule 'null' from /usr/local/lib/python3.6/site-packages/ansible/plugins/callback/null.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,856 p=53 u=root n=ansible |     53 1588220315.85602: Loading CallbackModule 'oneline' from /usr/local/lib/python3.6/site-packages/ansible/plugins/callback/oneline.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,858 p=53 u=root n=ansible |     53 1588220315.85797: Loading CallbackModule 'osx_say' from /usr/local/lib/python3.6/site-packages/ansible/plugins/callback/osx_say.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,859 p=53 u=root n=ansible |     53 1588220315.85941: Loading CallbackModule 'profile_roles' from /usr/local/lib/python3.6/site-packages/ansible/plugins/callback/profile_roles.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,864 p=53 u=root n=ansible |     53 1588220315.86454: Loaded config def from plugin (callback/profile_tasks)
2020-04-30 04:18:35,864 p=53 u=root n=ansible |     53 1588220315.86468: Loading CallbackModule 'profile_tasks' from /usr/local/lib/python3.6/site-packages/ansible/plugins/callback/profile_tasks.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,866 p=53 u=root n=ansible |     53 1588220315.86659: Loading CallbackModule 'say' from /usr/local/lib/python3.6/site-packages/ansible/plugins/callback/say.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,870 p=53 u=root n=ansible |     53 1588220315.87031: Loaded config def from plugin (callback/selective)
2020-04-30 04:18:35,870 p=53 u=root n=ansible |     53 1588220315.87048: Loading CallbackModule 'selective' from /usr/local/lib/python3.6/site-packages/ansible/plugins/callback/selective.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,872 p=53 u=root n=ansible |     53 1588220315.87282: Loading ModuleDocFragment 'default_callback' from /usr/local/lib/python3.6/site-packages/ansible/plugins/doc_fragments/default_callback.py (found_in_cache=True, class_only=False)
2020-04-30 04:18:35,881 p=53 u=root n=ansible |     53 1588220315.88141: Loaded config def from plugin (callback/skippy)
2020-04-30 04:18:35,881 p=53 u=root n=ansible |     53 1588220315.88155: Loading CallbackModule 'skippy' from /usr/local/lib/python3.6/site-packages/ansible/plugins/callback/skippy.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,888 p=53 u=root n=ansible |     53 1588220315.88815: Loaded config def from plugin (callback/slack)
2020-04-30 04:18:35,888 p=53 u=root n=ansible |     53 1588220315.88829: Loading CallbackModule 'slack' from /usr/local/lib/python3.6/site-packages/ansible/plugins/callback/slack.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,892 p=53 u=root n=ansible |     53 1588220315.89280: Loaded config def from plugin (callback/splunk)
2020-04-30 04:18:35,892 p=53 u=root n=ansible |     53 1588220315.89294: Loading CallbackModule 'splunk' from /usr/local/lib/python3.6/site-packages/ansible/plugins/callback/splunk.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,895 p=53 u=root n=ansible |     53 1588220315.89574: Loading ModuleDocFragment 'default_callback' from /usr/local/lib/python3.6/site-packages/ansible/plugins/doc_fragments/default_callback.py (found_in_cache=True, class_only=False)
2020-04-30 04:18:35,904 p=53 u=root n=ansible |     53 1588220315.90470: Loaded config def from plugin (callback/stderr)
2020-04-30 04:18:35,904 p=53 u=root n=ansible |     53 1588220315.90486: Loading CallbackModule 'stderr' from /usr/local/lib/python3.6/site-packages/ansible/plugins/callback/stderr.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,907 p=53 u=root n=ansible |     53 1588220315.90785: Loaded config def from plugin (callback/sumologic)
2020-04-30 04:18:35,908 p=53 u=root n=ansible |     53 1588220315.90798: Loading CallbackModule 'sumologic' from /usr/local/lib/python3.6/site-packages/ansible/plugins/callback/sumologic.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,914 p=53 u=root n=ansible |     53 1588220315.91398: Loaded config def from plugin (callback/syslog_json)
2020-04-30 04:18:35,914 p=53 u=root n=ansible |     53 1588220315.91412: Loading CallbackModule 'syslog_json' from /usr/local/lib/python3.6/site-packages/ansible/plugins/callback/syslog_json.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,915 p=53 u=root n=ansible |     53 1588220315.91556: Loading CallbackModule 'timer' from /usr/local/lib/python3.6/site-packages/ansible/plugins/callback/timer.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,917 p=53 u=root n=ansible |     53 1588220315.91730: Loading CallbackModule 'tree' from /usr/local/lib/python3.6/site-packages/ansible/plugins/callback/tree.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,919 p=53 u=root n=ansible |     53 1588220315.91912: Loading ModuleDocFragment 'default_callback' from /usr/local/lib/python3.6/site-packages/ansible/plugins/doc_fragments/default_callback.py (found_in_cache=True, class_only=False)
2020-04-30 04:18:35,927 p=53 u=root n=ansible |     53 1588220315.92773: Loaded config def from plugin (callback/unixy)
2020-04-30 04:18:35,927 p=53 u=root n=ansible |     53 1588220315.92788: Loading CallbackModule 'unixy' from /usr/local/lib/python3.6/site-packages/ansible/plugins/callback/unixy.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,930 p=53 u=root n=ansible |     53 1588220315.93001: Loading ModuleDocFragment 'default_callback' from /usr/local/lib/python3.6/site-packages/ansible/plugins/doc_fragments/default_callback.py (found_in_cache=True, class_only=False)
2020-04-30 04:18:35,938 p=53 u=root n=ansible |     53 1588220315.93870: Loaded config def from plugin (callback/yaml)
2020-04-30 04:18:35,938 p=53 u=root n=ansible |     53 1588220315.93883: Loading CallbackModule 'yaml' from /usr/local/lib/python3.6/site-packages/ansible/plugins/callback/yaml.py (found_in_cache=False, class_only=True)
2020-04-30 04:18:35,938 p=53 u=root n=ansible | PLAYBOOK: test.yaml *****************************************************************************************************************************************
2020-04-30 04:18:35,939 p=53 u=root n=ansible | 1 plays in test.yaml
2020-04-30 04:18:35,939 p=53 u=root n=ansible |     53 1588220315.93932: in VariableManager get_vars()
2020-04-30 04:18:35,940 p=53 u=root n=ansible |     53 1588220315.94070: done with get_vars()
2020-04-30 04:18:35,940 p=53 u=root n=ansible |     53 1588220315.94089: in VariableManager get_vars()
2020-04-30 04:18:35,941 p=53 u=root n=ansible |     53 1588220315.94107: done with get_vars()
2020-04-30 04:18:35,955 p=53 u=root n=ansible |     53 1588220315.95575: Loading FilterModule 'core' from /usr/local/lib/python3.6/site-packages/ansible/plugins/filter/core.py
2020-04-30 04:18:35,956 p=53 u=root n=ansible |     53 1588220315.95661: Loading FilterModule 'gcp_kms_filters' from /usr/local/lib/python3.6/site-packages/ansible/plugins/filter/gcp_kms_filters.py
2020-04-30 04:18:35,957 p=53 u=root n=ansible |     53 1588220315.95722: Loading FilterModule 'ipaddr' from /usr/local/lib/python3.6/site-packages/ansible/plugins/filter/ipaddr.py
2020-04-30 04:18:35,957 p=53 u=root n=ansible |     53 1588220315.95759: Loading FilterModule 'json_query' from /usr/local/lib/python3.6/site-packages/ansible/plugins/filter/json_query.py
2020-04-30 04:18:35,958 p=53 u=root n=ansible |     53 1588220315.95798: Loading FilterModule 'k8s' from /usr/local/lib/python3.6/site-packages/ansible/plugins/filter/k8s.py
2020-04-30 04:18:35,958 p=53 u=root n=ansible |     53 1588220315.95831: Loading FilterModule 'mathstuff' from /usr/local/lib/python3.6/site-packages/ansible/plugins/filter/mathstuff.py
2020-04-30 04:18:35,959 p=53 u=root n=ansible |     53 1588220315.95894: Loading FilterModule 'network' from /usr/local/lib/python3.6/site-packages/ansible/plugins/filter/network.py
2020-04-30 04:18:35,959 p=53 u=root n=ansible |     53 1588220315.95925: Loading FilterModule 'urls' from /usr/local/lib/python3.6/site-packages/ansible/plugins/filter/urls.py
2020-04-30 04:18:35,959 p=53 u=root n=ansible |     53 1588220315.95952: Loading FilterModule 'urlsplit' from /usr/local/lib/python3.6/site-packages/ansible/plugins/filter/urlsplit.py
2020-04-30 04:18:35,960 p=53 u=root n=ansible |     53 1588220315.96046: Loading TestModule 'core' from /usr/local/lib/python3.6/site-packages/ansible/plugins/test/core.py
2020-04-30 04:18:35,960 p=53 u=root n=ansible |     53 1588220315.96072: Loading TestModule 'files' from /usr/local/lib/python3.6/site-packages/ansible/plugins/test/files.py
2020-04-30 04:18:35,960 p=53 u=root n=ansible |     53 1588220315.96095: Loading TestModule 'mathstuff' from /usr/local/lib/python3.6/site-packages/ansible/plugins/test/mathstuff.py
2020-04-30 04:18:35,961 p=53 u=root n=ansible |     53 1588220315.96188: in VariableManager get_vars()
2020-04-30 04:18:35,962 p=53 u=root n=ansible |     53 1588220315.96220: done with get_vars()
2020-04-30 04:18:35,962 p=53 u=root n=ansible |     53 1588220315.96279: Loading FilterModule 'core' from /usr/local/lib/python3.6/site-packages/ansible/plugins/filter/core.py (found_in_cache=True, class_only=False)
2020-04-30 04:18:35,962 p=53 u=root n=ansible |     53 1588220315.96290: Loading FilterModule 'gcp_kms_filters' from /usr/local/lib/python3.6/site-packages/ansible/plugins/filter/gcp_kms_filters.py (found_in_cache=True, class_only=False)
2020-04-30 04:18:35,963 p=53 u=root n=ansible |     53 1588220315.96299: Loading FilterModule 'ipaddr' from /usr/local/lib/python3.6/site-packages/ansible/plugins/filter/ipaddr.py (found_in_cache=True, class_only=False)
2020-04-30 04:18:35,963 p=53 u=root n=ansible |     53 1588220315.96306: Loading FilterModule 'json_query' from /usr/local/lib/python3.6/site-packages/ansible/plugins/filter/json_query.py (found_in_cache=True, class_only=False)
2020-04-30 04:18:35,963 p=53 u=root n=ansible |     53 1588220315.96312: Loading FilterModule 'k8s' from /usr/local/lib/python3.6/site-packages/ansible/plugins/filter/k8s.py (found_in_cache=True, class_only=False)
2020-04-30 04:18:35,963 p=53 u=root n=ansible |     53 1588220315.96320: Loading FilterModule 'mathstuff' from /usr/local/lib/python3.6/site-packages/ansible/plugins/filter/mathstuff.py (found_in_cache=True, class_only=False)
2020-04-30 04:18:35,963 p=53 u=root n=ansible |     53 1588220315.96327: Loading FilterModule 'network' from /usr/local/lib/python3.6/site-packages/ansible/plugins/filter/network.py (found_in_cache=True, class_only=False)
2020-04-30 04:18:35,963 p=53 u=root n=ansible |     53 1588220315.96333: Loading FilterModule 'urls' from /usr/local/lib/python3.6/site-packages/ansible/plugins/filter/urls.py (found_in_cache=True, class_only=False)
2020-04-30 04:18:35,963 p=53 u=root n=ansible |     53 1588220315.96339: Loading FilterModule 'urlsplit' from /usr/local/lib/python3.6/site-packages/ansible/plugins/filter/urlsplit.py (found_in_cache=True, class_only=False)
2020-04-30 04:18:35,963 p=53 u=root n=ansible |     53 1588220315.96369: Loading TestModule 'core' from /usr/local/lib/python3.6/site-packages/ansible/plugins/test/core.py (found_in_cache=True, class_only=False)
2020-04-30 04:18:35,963 p=53 u=root n=ansible |     53 1588220315.96379: Loading TestModule 'files' from /usr/local/lib/python3.6/site-packages/ansible/plugins/test/files.py (found_in_cache=True, class_only=False)
2020-04-30 04:18:35,963 p=53 u=root n=ansible |     53 1588220315.96386: Loading TestModule 'mathstuff' from /usr/local/lib/python3.6/site-packages/ansible/plugins/test/mathstuff.py (found_in_cache=True, class_only=False)
2020-04-30 04:18:35,964 p=53 u=root n=ansible | PLAY [Uploading file: {{ image_file }}] *********************************************************************************************************************
2020-04-30 04:18:35,968 p=53 u=root n=ansible |     53 1588220315.96864: trying /usr/local/lib/python3.6/site-packages/ansible/plugins/strategy
2020-04-30 04:18:35,969 p=53 u=root n=ansible |     53 1588220315.96914: Loading StrategyModule 'linear' from /usr/local/lib/python3.6/site-packages/ansible/plugins/strategy/linear.py
2020-04-30 04:18:35,969 p=53 u=root n=ansible |     53 1588220315.96962: getting the remaining hosts for this loop
2020-04-30 04:18:35,969 p=53 u=root n=ansible |     53 1588220315.96976: done getting the remaining hosts for this loop
2020-04-30 04:18:35,969 p=53 u=root n=ansible |     53 1588220315.96993: building list of next tasks for hosts
2020-04-30 04:18:35,970 p=53 u=root n=ansible |     53 1588220315.97001: getting the next task for host tordevice.REDACTED
2020-04-30 04:18:35,970 p=53 u=root n=ansible |     53 1588220315.97009: done getting next task for host tordevice.REDACTED
2020-04-30 04:18:35,970 p=53 u=root n=ansible |     53 1588220315.97018:  ^ task is: TASK: meta (flush_handlers)
2020-04-30 04:18:35,970 p=53 u=root n=ansible |     53 1588220315.97025:  ^ state is: HOST STATE: block=1, task=1, rescue=0, always=0, run_state=ITERATING_TASKS, fail_state=FAILED_NONE, pending_setup=False, tasks child state? (None), rescue child state? (None), always child state? (None), did rescue? False, did start at task? False
2020-04-30 04:18:35,970 p=53 u=root n=ansible |     53 1588220315.97031: done building task lists
2020-04-30 04:18:35,970 p=53 u=root n=ansible |     53 1588220315.97037: counting tasks in each state of execution
2020-04-30 04:18:35,970 p=53 u=root n=ansible |     53 1588220315.97043: done counting tasks in each state of execution:
	num_setups: 0
	num_tasks: 1
	num_rescue: 0
	num_always: 0
2020-04-30 04:18:35,970 p=53 u=root n=ansible |     53 1588220315.97050: advancing hosts in ITERATING_TASKS
2020-04-30 04:18:35,970 p=53 u=root n=ansible |     53 1588220315.97056: starting to advance hosts
2020-04-30 04:18:35,970 p=53 u=root n=ansible |     53 1588220315.97062: getting the next task for host tordevice.REDACTED
2020-04-30 04:18:35,970 p=53 u=root n=ansible |     53 1588220315.97070: done getting next task for host tordevice.REDACTED
2020-04-30 04:18:35,970 p=53 u=root n=ansible |     53 1588220315.97078:  ^ task is: TASK: meta (flush_handlers)
2020-04-30 04:18:35,970 p=53 u=root n=ansible |     53 1588220315.97084:  ^ state is: HOST STATE: block=1, task=1, rescue=0, always=0, run_state=ITERATING_TASKS, fail_state=FAILED_NONE, pending_setup=False, tasks child state? (None), rescue child state? (None), always child state? (None), did rescue? False, did start at task? False
2020-04-30 04:18:35,970 p=53 u=root n=ansible |     53 1588220315.97090: done advancing hosts to next task
2020-04-30 04:18:35,971 p=53 u=root n=ansible | META: ran handlers
2020-04-30 04:18:35,971 p=53 u=root n=ansible |     53 1588220315.97111: done queuing things up, now waiting for results queue to drain
2020-04-30 04:18:35,971 p=53 u=root n=ansible |     53 1588220315.97119: results queue empty
2020-04-30 04:18:35,971 p=53 u=root n=ansible |     53 1588220315.97125: checking for any_errors_fatal
2020-04-30 04:18:35,971 p=53 u=root n=ansible |     53 1588220315.97132: done checking for any_errors_fatal
2020-04-30 04:18:35,971 p=53 u=root n=ansible |     53 1588220315.97138: checking for max_fail_percentage
2020-04-30 04:18:35,971 p=53 u=root n=ansible |     53 1588220315.97143: done checking for max_fail_percentage
2020-04-30 04:18:35,971 p=53 u=root n=ansible |     53 1588220315.97149: checking to see if all hosts have failed and the running result is not ok
2020-04-30 04:18:35,971 p=53 u=root n=ansible |     53 1588220315.97154: done checking to see if all hosts have failed
2020-04-30 04:18:35,971 p=53 u=root n=ansible |     53 1588220315.97159: getting the remaining hosts for this loop
2020-04-30 04:18:35,971 p=53 u=root n=ansible |     53 1588220315.97165: done getting the remaining hosts for this loop
2020-04-30 04:18:35,971 p=53 u=root n=ansible |     53 1588220315.97176: building list of next tasks for hosts
2020-04-30 04:18:35,971 p=53 u=root n=ansible |     53 1588220315.97182: getting the next task for host tordevice.REDACTED
2020-04-30 04:18:35,971 p=53 u=root n=ansible |     53 1588220315.97189: done getting next task for host tordevice.REDACTED
2020-04-30 04:18:35,971 p=53 u=root n=ansible |     53 1588220315.97196:  ^ task is: TASK: nxos_facts
2020-04-30 04:18:35,972 p=53 u=root n=ansible |     53 1588220315.97203:  ^ state is: HOST STATE: block=2, task=1, rescue=0, always=0, run_state=ITERATING_TASKS, fail_state=FAILED_NONE, pending_setup=False, tasks child state? (None), rescue child state? (None), always child state? (None), did rescue? False, did start at task? False
2020-04-30 04:18:35,972 p=53 u=root n=ansible |     53 1588220315.97209: done building task lists
2020-04-30 04:18:35,972 p=53 u=root n=ansible |     53 1588220315.97214: counting tasks in each state of execution
2020-04-30 04:18:35,972 p=53 u=root n=ansible |     53 1588220315.97221: done counting tasks in each state of execution:
	num_setups: 0
	num_tasks: 1
	num_rescue: 0
	num_always: 0
2020-04-30 04:18:35,972 p=53 u=root n=ansible |     53 1588220315.97228: advancing hosts in ITERATING_TASKS
2020-04-30 04:18:35,972 p=53 u=root n=ansible |     53 1588220315.97233: starting to advance hosts
2020-04-30 04:18:35,972 p=53 u=root n=ansible |     53 1588220315.97239: getting the next task for host tordevice.REDACTED
2020-04-30 04:18:35,972 p=53 u=root n=ansible |     53 1588220315.97245: done getting next task for host tordevice.REDACTED
2020-04-30 04:18:35,972 p=53 u=root n=ansible |     53 1588220315.97252:  ^ task is: TASK: nxos_facts
2020-04-30 04:18:35,972 p=53 u=root n=ansible |     53 1588220315.97259:  ^ state is: HOST STATE: block=2, task=1, rescue=0, always=0, run_state=ITERATING_TASKS, fail_state=FAILED_NONE, pending_setup=False, tasks child state? (None), rescue child state? (None), always child state? (None), did rescue? False, did start at task? False
2020-04-30 04:18:35,972 p=53 u=root n=ansible |     53 1588220315.97266: done advancing hosts to next task
2020-04-30 04:18:35,972 p=53 u=root n=ansible |     53 1588220315.97277: getting variables
2020-04-30 04:18:35,972 p=53 u=root n=ansible |     53 1588220315.97283: in VariableManager get_vars()
2020-04-30 04:18:35,973 p=53 u=root n=ansible |     53 1588220315.97301: Calling all_inventory to load vars for tordevice.REDACTED
2020-04-30 04:18:35,973 p=53 u=root n=ansible |     53 1588220315.97309: Calling groups_inventory to load vars for tordevice.REDACTED
2020-04-30 04:18:35,973 p=53 u=root n=ansible |     53 1588220315.97316: Calling all_plugins_inventory to load vars for tordevice.REDACTED
2020-04-30 04:18:35,973 p=53 u=root n=ansible |     53 1588220315.97394: Loading VarsModule 'host_group_vars' from /usr/local/lib/python3.6/site-packages/ansible/plugins/vars/host_group_vars.py
2020-04-30 04:18:35,974 p=53 u=root n=ansible |     53 1588220315.97411: Calling all_plugins_play to load vars for tordevice.REDACTED
2020-04-30 04:18:35,974 p=53 u=root n=ansible |     53 1588220315.97433: Loading VarsModule 'host_group_vars' from /usr/local/lib/python3.6/site-packages/ansible/plugins/vars/host_group_vars.py (found_in_cache=True, class_only=False)
2020-04-30 04:18:35,974 p=53 u=root n=ansible |     53 1588220315.97450: Calling groups_plugins_inventory to load vars for tordevice.REDACTED
2020-04-30 04:18:35,974 p=53 u=root n=ansible |     53 1588220315.97474: Loading VarsModule 'host_group_vars' from /usr/local/lib/python3.6/site-packages/ansible/plugins/vars/host_group_vars.py (found_in_cache=True, class_only=False)
2020-04-30 04:18:35,974 p=53 u=root n=ansible |     53 1588220315.97487: Calling groups_plugins_play to load vars for tordevice.REDACTED
2020-04-30 04:18:35,975 p=53 u=root n=ansible |     53 1588220315.97507: Loading VarsModule 'host_group_vars' from /usr/local/lib/python3.6/site-packages/ansible/plugins/vars/host_group_vars.py (found_in_cache=True, class_only=False)
2020-04-30 04:18:35,975 p=53 u=root n=ansible |     53 1588220315.97534: Loading VarsModule 'host_group_vars' from /usr/local/lib/python3.6/site-packages/ansible/plugins/vars/host_group_vars.py (found_in_cache=True, class_only=False)
2020-04-30 04:18:35,975 p=53 u=root n=ansible |     53 1588220315.97563: Loading VarsModule 'host_group_vars' from /usr/local/lib/python3.6/site-packages/ansible/plugins/vars/host_group_vars.py (found_in_cache=True, class_only=False)
2020-04-30 04:18:35,977 p=53 u=root n=ansible |     53 1588220315.97760: done with get_vars()
2020-04-30 04:18:35,977 p=53 u=root n=ansible |     53 1588220315.97777: done getting variables
2020-04-30 04:18:35,977 p=53 u=root n=ansible |     53 1588220315.97788: sending task start callback, copying the task so we can template it temporarily
2020-04-30 04:18:35,977 p=53 u=root n=ansible |     53 1588220315.97795: done copying, going to template now
2020-04-30 04:18:35,978 p=53 u=root n=ansible |     53 1588220315.97802: done templating
2020-04-30 04:18:35,978 p=53 u=root n=ansible |     53 1588220315.97807: here goes the callback...
2020-04-30 04:18:35,978 p=53 u=root n=ansible | TASK [nxos_facts] *******************************************************************************************************************************************
2020-04-30 04:18:35,978 p=53 u=root n=ansible | task path: /root/test.yaml:20
2020-04-30 04:18:35,978 p=53 u=root n=ansible |     53 1588220315.97830: sending task start callback
2020-04-30 04:18:35,978 p=53 u=root n=ansible |     53 1588220315.97836: entering _queue_task() for tordevice.REDACTED/nxos_facts
2020-04-30 04:18:35,978 p=53 u=root n=ansible |     53 1588220315.97843: Creating lock for nxos_facts
2020-04-30 04:18:35,980 p=53 u=root n=ansible |     53 1588220315.98048: worker is 1 (out of 1 available)
2020-04-30 04:18:35,981 p=53 u=root n=ansible |     53 1588220315.98142: exiting _queue_task() for tordevice.REDACTED/nxos_facts
2020-04-30 04:18:35,982 p=53 u=root n=ansible |     53 1588220315.98214: done queuing things up, now waiting for results queue to drain
2020-04-30 04:18:35,982 p=59 u=root n=ansible |     59 1588220315.98184: running TaskExecutor() for tordevice.REDACTED/TASK: nxos_facts
2020-04-30 04:18:35,982 p=53 u=root n=ansible |     53 1588220315.98228: waiting for pending results...
2020-04-30 04:18:35,982 p=59 u=root n=ansible |     59 1588220315.98268: in run() - task 0242ac11-0002-bf5d-b365-000000000008
2020-04-30 04:18:35,983 p=59 u=root n=ansible |     59 1588220315.98328: calling self._execute()
2020-04-30 04:18:35,986 p=59 u=root n=ansible |     59 1588220315.98614: trying /usr/local/lib/python3.6/site-packages/ansible/plugins/connection
2020-04-30 04:18:35,987 p=59 u=root n=ansible |     59 1588220315.98695: Loading Connection 'network_cli' from /usr/local/lib/python3.6/site-packages/ansible/plugins/connection/network_cli.py (found_in_cache=True, class_only=False)
2020-04-30 04:18:35,987 p=59 u=root n=ansible |     59 1588220315.98728: trying /usr/local/lib/python3.6/site-packages/ansible/plugins/shell
2020-04-30 04:18:35,987 p=59 u=root n=ansible |     59 1588220315.98751: Loading ShellModule 'sh' from /usr/local/lib/python3.6/site-packages/ansible/plugins/shell/sh.py (found_in_cache=True, class_only=False)
2020-04-30 04:18:35,987 p=59 u=root n=ansible |     59 1588220315.98765: Loading ShellModule 'sh' from /usr/local/lib/python3.6/site-packages/ansible/plugins/shell/sh.py (found_in_cache=True, class_only=False)
2020-04-30 04:18:35,987 p=59 u=root n=ansible |     59 1588220315.98791: Loading Connection 'local' from /usr/local/lib/python3.6/site-packages/ansible/plugins/connection/local.py (found_in_cache=True, class_only=False)
2020-04-30 04:18:35,988 p=59 u=root n=ansible |     59 1588220315.98807: Loading ShellModule 'sh' from /usr/local/lib/python3.6/site-packages/ansible/plugins/shell/sh.py (found_in_cache=True, class_only=False)
2020-04-30 04:18:35,988 p=59 u=root n=ansible |     59 1588220315.98816: Loading ShellModule 'sh' from /usr/local/lib/python3.6/site-packages/ansible/plugins/shell/sh.py (found_in_cache=True, class_only=False)
2020-04-30 04:18:35,988 p=59 u=root n=ansible |     59 1588220315.98836: Loading Connection 'ssh' from /usr/local/lib/python3.6/site-packages/ansible/plugins/connection/ssh.py (found_in_cache=True, class_only=True)
2020-04-30 04:18:35,990 p=59 u=root n=ansible |     59 1588220315.99033: trying /usr/local/lib/python3.6/site-packages/ansible/plugins/terminal
2020-04-30 04:18:35,993 p=59 u=root n=ansible |     59 1588220315.99338: Loading TerminalModule 'nxos' from /usr/local/lib/python3.6/site-packages/ansible/plugins/terminal/nxos.py
2020-04-30 04:18:35,995 p=59 u=root n=ansible |     59 1588220315.99504: trying /usr/local/lib/python3.6/site-packages/ansible/plugins/cliconf
2020-04-30 04:18:35,998 p=59 u=root n=ansible |     59 1588220315.99839: Loading Cliconf 'nxos' from /usr/local/lib/python3.6/site-packages/ansible/plugins/cliconf/nxos.py
2020-04-30 04:18:35,998 p=59 u=root n=ansible | <tordevice.REDACTED> attempting to start connection
2020-04-30 04:18:35,998 p=59 u=root n=ansible | <tordevice.REDACTED> using connection plugin network_cli
2020-04-30 04:18:36,597 p=60 u=root n=ansible |     60 1588220316.59779: trying /usr/local/lib/python3.6/site-packages/ansible/plugins/connection/__pycache__
2020-04-30 04:18:36,598 p=60 u=root n=ansible |     60 1588220316.59825: trying /usr/local/lib/python3.6/site-packages/ansible/plugins/connection
2020-04-30 04:18:36,642 p=60 u=root n=ansible |     60 1588220316.64269: Loaded config def from plugin (connection/ssh)
2020-04-30 04:18:36,642 p=60 u=root n=ansible |     60 1588220316.64290: Loading Connection 'ssh' from /usr/local/lib/python3.6/site-packages/ansible/plugins/connection/ssh.py (searched paths: /usr/local/lib/python3.6/site-packages/ansible/plugins/connection:/usr/local/lib/python3.6/site-packages/ansible/plugins/connection/__pycache__) (found_in_cache=False, class_only=True)
2020-04-30 04:18:36,687 p=64 u=root n=ansible |     64 1588220316.68689: Loaded config def from plugin (connection/network_cli)
2020-04-30 04:18:36,687 p=64 u=root n=ansible |     64 1588220316.68743: Loading Connection 'network_cli' from /usr/local/lib/python3.6/site-packages/ansible/plugins/connection/network_cli.py (searched paths: /usr/local/lib/python3.6/site-packages/ansible/plugins/connection:/usr/local/lib/python3.6/site-packages/ansible/plugins/connection/__pycache__)
2020-04-30 04:18:36,687 p=64 u=root n=ansible |     64 1588220316.68794: trying /usr/local/lib/python3.6/site-packages/ansible/plugins/shell
2020-04-30 04:18:36,690 p=64 u=root n=ansible |     64 1588220316.69034: trying /usr/local/lib/python3.6/site-packages/ansible/plugins/doc_fragments
2020-04-30 04:18:36,692 p=64 u=root n=ansible |     64 1588220316.69213: Loading ModuleDocFragment 'shell_common' from /usr/local/lib/python3.6/site-packages/ansible/plugins/doc_fragments/shell_common.py
2020-04-30 04:18:36,699 p=64 u=root n=ansible |     64 1588220316.69987: Loaded config def from plugin (shell/sh)
2020-04-30 04:18:36,700 p=64 u=root n=ansible |     64 1588220316.69998: Loading ShellModule 'sh' from /usr/local/lib/python3.6/site-packages/ansible/plugins/shell/sh.py
2020-04-30 04:18:36,700 p=64 u=root n=ansible |     64 1588220316.70008: Loading ShellModule 'sh' from /usr/local/lib/python3.6/site-packages/ansible/plugins/shell/sh.py (found_in_cache=True, class_only=False)
2020-04-30 04:18:36,701 p=64 u=root n=ansible |     64 1588220316.70183: Loading Connection 'local' from /usr/local/lib/python3.6/site-packages/ansible/plugins/connection/local.py (searched paths: /usr/local/lib/python3.6/site-packages/ansible/plugins/connection:/usr/local/lib/python3.6/site-packages/ansible/plugins/connection/__pycache__)
2020-04-30 04:18:36,701 p=64 u=root n=ansible |     64 1588220316.70196: Loading ShellModule 'sh' from /usr/local/lib/python3.6/site-packages/ansible/plugins/shell/sh.py (found_in_cache=True, class_only=False)
2020-04-30 04:18:36,702 p=64 u=root n=ansible |     64 1588220316.70204: Loading ShellModule 'sh' from /usr/local/lib/python3.6/site-packages/ansible/plugins/shell/sh.py (found_in_cache=True, class_only=False)
2020-04-30 04:18:36,702 p=64 u=root n=ansible |     64 1588220316.70215: Loading Connection 'ssh' from /usr/local/lib/python3.6/site-packages/ansible/plugins/connection/ssh.py (searched paths: /usr/local/lib/python3.6/site-packages/ansible/plugins/connection:/usr/local/lib/python3.6/site-packages/ansible/plugins/connection/__pycache__) (found_in_cache=True, class_only=True)
2020-04-30 04:18:36,704 p=64 u=root n=ansible |     64 1588220316.70452: trying /usr/local/lib/python3.6/site-packages/ansible/plugins/terminal/__pycache__
2020-04-30 04:18:36,704 p=64 u=root n=ansible |     64 1588220316.70494: trying /usr/local/lib/python3.6/site-packages/ansible/plugins/terminal
2020-04-30 04:18:36,707 p=64 u=root n=ansible |     64 1588220316.70780: Loading TerminalModule 'nxos' from /usr/local/lib/python3.6/site-packages/ansible/plugins/terminal/nxos.py (searched paths: /usr/local/lib/python3.6/site-packages/ansible/plugins/terminal/__pycache__:/usr/local/lib/python3.6/site-packages/ansible/plugins/terminal)
2020-04-30 04:18:36,710 p=64 u=root n=ansible |     64 1588220316.71008: trying /usr/local/lib/python3.6/site-packages/ansible/plugins/cliconf/__pycache__
2020-04-30 04:18:36,710 p=64 u=root n=ansible |     64 1588220316.71046: trying /usr/local/lib/python3.6/site-packages/ansible/plugins/cliconf
2020-04-30 04:18:36,713 p=64 u=root n=ansible |     64 1588220316.71304: Loading Cliconf 'nxos' from /usr/local/lib/python3.6/site-packages/ansible/plugins/cliconf/nxos.py (searched paths: /usr/local/lib/python3.6/site-packages/ansible/plugins/cliconf/__pycache__:/usr/local/lib/python3.6/site-packages/ansible/plugins/cliconf)
2020-04-30 04:18:36,755 p=59 u=root n=ansible | <tordevice.REDACTED> local domain socket does not exist, starting it
2020-04-30 04:18:36,755 p=59 u=root n=ansible | <tordevice.REDACTED> control socket path is /root/.ansible/pc/951c79052a
2020-04-30 04:18:36,755 p=59 u=root n=ansible | <tordevice.REDACTED>     60 1588220316.59779: trying /usr/local/lib/python3.6/site-packages/ansible/plugins/connection/__pycache__
2020-04-30 04:18:36,755 p=59 u=root n=ansible | <tordevice.REDACTED>     60 1588220316.59825: trying /usr/local/lib/python3.6/site-packages/ansible/plugins/connection
2020-04-30 04:18:36,755 p=59 u=root n=ansible | <tordevice.REDACTED>     60 1588220316.64269: Loaded config def from plugin (connection/ssh)
2020-04-30 04:18:36,755 p=59 u=root n=ansible | <tordevice.REDACTED>     60 1588220316.64290: Loading Connection 'ssh' from /usr/local/lib/python3.6/site-packages/ansible/plugins/connection/ssh.py (searched paths: /usr/local/lib/python3.6/site-packages/ansible/plugins/connection:/usr/local/lib/python3.6/site-packages/ansible/plugins/connection/__pycache__) (found_in_cache=False, class_only=True)
2020-04-30 04:18:36,755 p=59 u=root n=ansible | <tordevice.REDACTED>     64 1588220316.68689: Loaded config def from plugin (connection/network_cli)
2020-04-30 04:18:36,755 p=59 u=root n=ansible | <tordevice.REDACTED>     64 1588220316.68743: Loading Connection 'network_cli' from /usr/local/lib/python3.6/site-packages/ansible/plugins/connection/network_cli.py (searched paths: /usr/local/lib/python3.6/site-packages/ansible/plugins/connection:/usr/local/lib/python3.6/site-packages/ansible/plugins/connection/__pycache__)
2020-04-30 04:18:36,755 p=59 u=root n=ansible | <tordevice.REDACTED>     64 1588220316.68794: trying /usr/local/lib/python3.6/site-packages/ansible/plugins/shell
2020-04-30 04:18:36,755 p=59 u=root n=ansible | <tordevice.REDACTED>     64 1588220316.69034: trying /usr/local/lib/python3.6/site-packages/ansible/plugins/doc_fragments
2020-04-30 04:18:36,755 p=59 u=root n=ansible | <tordevice.REDACTED>     64 1588220316.69213: Loading ModuleDocFragment 'shell_common' from /usr/local/lib/python3.6/site-packages/ansible/plugins/doc_fragments/shell_common.py
2020-04-30 04:18:36,755 p=59 u=root n=ansible | <tordevice.REDACTED>     64 1588220316.69987: Loaded config def from plugin (shell/sh)
2020-04-30 04:18:36,756 p=59 u=root n=ansible | <tordevice.REDACTED>     64 1588220316.69998: Loading ShellModule 'sh' from /usr/local/lib/python3.6/site-packages/ansible/plugins/shell/sh.py
2020-04-30 04:18:36,756 p=59 u=root n=ansible | <tordevice.REDACTED>     64 1588220316.70008: Loading ShellModule 'sh' from /usr/local/lib/python3.6/site-packages/ansible/plugins/shell/sh.py (found_in_cache=True, class_only=False)
2020-04-30 04:18:36,756 p=59 u=root n=ansible | <tordevice.REDACTED>     64 1588220316.70183: Loading Connection 'local' from /usr/local/lib/python3.6/site-packages/ansible/plugins/connection/local.py (searched paths: /usr/local/lib/python3.6/site-packages/ansible/plugins/connection:/usr/local/lib/python3.6/site-packages/ansible/plugins/connection/__pycache__)
2020-04-30 04:18:36,756 p=59 u=root n=ansible | <tordevice.REDACTED>     64 1588220316.70196: Loading ShellModule 'sh' from /usr/local/lib/python3.6/site-packages/ansible/plugins/shell/sh.py (found_in_cache=True, class_only=False)
2020-04-30 04:18:36,756 p=59 u=root n=ansible | <tordevice.REDACTED>     64 1588220316.70204: Loading ShellModule 'sh' from /usr/local/lib/python3.6/site-packages/ansible/plugins/shell/sh.py (found_in_cache=True, class_only=False)
2020-04-30 04:18:36,756 p=59 u=root n=ansible | <tordevice.REDACTED>     64 1588220316.70215: Loading Connection 'ssh' from /usr/local/lib/python3.6/site-packages/ansible/plugins/connection/ssh.py (searched paths: /usr/local/lib/python3.6/site-packages/ansible/plugins/connection:/usr/local/lib/python3.6/site-packages/ansible/plugins/connection/__pycache__) (found_in_cache=True, class_only=True)
2020-04-30 04:18:36,756 p=59 u=root n=ansible | <tordevice.REDACTED>     64 1588220316.70452: trying /usr/local/lib/python3.6/site-packages/ansible/plugins/terminal/__pycache__
2020-04-30 04:18:36,756 p=59 u=root n=ansible | <tordevice.REDACTED>     64 1588220316.70494: trying /usr/local/lib/python3.6/site-packages/ansible/plugins/terminal
2020-04-30 04:18:36,756 p=59 u=root n=ansible | <tordevice.REDACTED>     64 1588220316.70780: Loading TerminalModule 'nxos' from /usr/local/lib/python3.6/site-packages/ansible/plugins/terminal/nxos.py (searched paths: /usr/local/lib/python3.6/site-packages/ansible/plugins/terminal/__pycache__:/usr/local/lib/python3.6/site-packages/ansible/plugins/terminal)
2020-04-30 04:18:36,756 p=59 u=root n=ansible | <tordevice.REDACTED>     64 1588220316.71008: trying /usr/local/lib/python3.6/site-packages/ansible/plugins/cliconf/__pycache__
2020-04-30 04:18:36,756 p=59 u=root n=ansible | <tordevice.REDACTED>     64 1588220316.71046: trying /usr/local/lib/python3.6/site-packages/ansible/plugins/cliconf
2020-04-30 04:18:36,756 p=59 u=root n=ansible | <tordevice.REDACTED>     64 1588220316.71304: Loading Cliconf 'nxos' from /usr/local/lib/python3.6/site-packages/ansible/plugins/cliconf/nxos.py (searched paths: /usr/local/lib/python3.6/site-packages/ansible/plugins/cliconf/__pycache__:/usr/local/lib/python3.6/site-packages/ansible/plugins/cliconf)
2020-04-30 04:18:36,756 p=59 u=root n=ansible | <tordevice.REDACTED> local domain socket listeners started successfully
2020-04-30 04:18:36,756 p=59 u=root n=ansible | <tordevice.REDACTED> loaded cliconf plugin nxos from path /usr/local/lib/python3.6/site-packages/ansible/plugins/cliconf/nxos.py for network_os nxos
2020-04-30 04:18:36,756 p=59 u=root n=ansible | network_os is set to nxos
2020-04-30 04:18:36,756 p=59 u=root n=ansible | <tordevice.REDACTED>     60 1588220316.59779: trying /usr/local/lib/python3.6/site-packages/ansible/plugins/connection/__pycache__
    60 1588220316.59825: trying /usr/local/lib/python3.6/site-packages/ansible/plugins/connection
    60 1588220316.64269: Loaded config def from plugin (connection/ssh)
    60 1588220316.64290: Loading Connection 'ssh' from /usr/local/lib/python3.6/site-packages/ansible/plugins/connection/ssh.py (searched paths: /usr/local/lib/python3.6/site-packages/ansible/plugins/connection:/usr/local/lib/python3.6/site-packages/ansible/plugins/connection/__pycache__) (found_in_cache=False, class_only=True)

2020-04-30 04:18:36,757 p=59 u=root n=ansible | <tordevice.REDACTED> local domain socket path is /root/.ansible/pc/951c79052a
2020-04-30 04:18:36,761 p=59 u=root n=ansible |     59 1588220316.76106: Loading ActionModule 'nxos' from /usr/local/lib/python3.6/site-packages/ansible/plugins/action/nxos.py (searched paths: /usr/local/lib/python3.6/site-packages/ansible/plugins/action/__pycache__:/usr/local/lib/python3.6/site-packages/ansible/plugins/action)
2020-04-30 04:18:36,761 p=59 u=root n=ansible |     59 1588220316.76134: starting attempt loop
2020-04-30 04:18:36,761 p=59 u=root n=ansible |     59 1588220316.76143: running the handler
2020-04-30 04:18:36,782 p=64 u=root n=ansible |     64 1588220316.78256: Loaded config def from plugin (connection/paramiko_ssh)
2020-04-30 04:18:36,782 p=64 u=root n=ansible |     64 1588220316.78278: Loading Connection 'paramiko_ssh' from /usr/local/lib/python3.6/site-packages/ansible/plugins/connection/paramiko_ssh.py (searched paths: /usr/local/lib/python3.6/site-packages/ansible/plugins/connection:/usr/local/lib/python3.6/site-packages/ansible/plugins/connection/__pycache__)
2020-04-30 04:18:36,782 p=64 u=root n=ansible |     64 1588220316.78289: Loading ShellModule 'sh' from /usr/local/lib/python3.6/site-packages/ansible/plugins/shell/sh.py (found_in_cache=True, class_only=False)
2020-04-30 04:18:36,783 p=64 u=root n=ansible |     64 1588220316.78298: Loading ShellModule 'sh' from /usr/local/lib/python3.6/site-packages/ansible/plugins/shell/sh.py (found_in_cache=True, class_only=False)
2020-04-30 04:18:36,783 p=64 u=root n=ansible | <tordevice.REDACTED> ESTABLISH PARAMIKO SSH CONNECTION FOR USER: username_REDACTED on PORT 22 TO tordevice.REDACTED
2020-04-30 04:18:36,785 p=64 u=root n=ansible | <tordevice.REDACTED> CONFIGURE PROXY COMMAND FOR CONNECTION: ssh -W tordevice.REDACTED:22 -q username_REDACTED@BASTION_SERVER_REDACTED_IP
2020-04-30 04:18:36,786 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] | starting thread (client mode): 0x8e9c44e0
2020-04-30 04:18:36,787 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] | Local version/idstring: SSH-2.0-paramiko_2.7.1
2020-04-30 04:18:51,788 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] | Exception: Error reading SSH protocol banner
2020-04-30 04:18:51,789 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] | Traceback (most recent call last):
2020-04-30 04:18:51,789 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] |   File "/usr/local/lib/python3.6/site-packages/paramiko/transport.py", line 2211, in _check_banner
2020-04-30 04:18:51,789 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] |     buf = self.packetizer.readline(timeout)
2020-04-30 04:18:51,789 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] |   File "/usr/local/lib/python3.6/site-packages/paramiko/packet.py", line 380, in readline
2020-04-30 04:18:51,789 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] |     buf += self._read_timeout(timeout)
2020-04-30 04:18:51,789 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] |   File "/usr/local/lib/python3.6/site-packages/paramiko/packet.py", line 622, in _read_timeout
2020-04-30 04:18:51,789 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] |     raise socket.timeout()
2020-04-30 04:18:51,789 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] | socket.timeout
2020-04-30 04:18:51,789 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] | 
2020-04-30 04:18:51,789 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] | During handling of the above exception, another exception occurred:
2020-04-30 04:18:51,789 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] | 
2020-04-30 04:18:51,789 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] | Traceback (most recent call last):
2020-04-30 04:18:51,789 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] |   File "/usr/local/lib/python3.6/site-packages/paramiko/transport.py", line 2039, in run
2020-04-30 04:18:51,789 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] |     self._check_banner()
2020-04-30 04:18:51,790 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] |   File "/usr/local/lib/python3.6/site-packages/paramiko/transport.py", line 2216, in _check_banner
2020-04-30 04:18:51,790 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] |     "Error reading SSH protocol banner" + str(e)
2020-04-30 04:18:51,790 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] | paramiko.ssh_exception.SSHException: Error reading SSH protocol banner
2020-04-30 04:18:51,790 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] | 
2020-04-30 04:18:53,792 p=64 u=root n=ansible | <tordevice.REDACTED> ESTABLISH PARAMIKO SSH CONNECTION FOR USER: username_REDACTED on PORT 22 TO tordevice.REDACTED
2020-04-30 04:18:53,795 p=64 u=root n=ansible | <tordevice.REDACTED> CONFIGURE PROXY COMMAND FOR CONNECTION: ssh -W tordevice.REDACTED:22 -q username_REDACTED@BASTION_SERVER_REDACTED_IP
2020-04-30 04:18:53,796 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] | starting thread (client mode): 0x8e9c4c50
2020-04-30 04:18:53,796 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] | Local version/idstring: SSH-2.0-paramiko_2.7.1
2020-04-30 04:19:08,798 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] | Exception: Error reading SSH protocol banner
2020-04-30 04:19:08,798 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] | Traceback (most recent call last):
2020-04-30 04:19:08,798 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] |   File "/usr/local/lib/python3.6/site-packages/paramiko/transport.py", line 2211, in _check_banner
2020-04-30 04:19:08,798 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] |     buf = self.packetizer.readline(timeout)
2020-04-30 04:19:08,798 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] |   File "/usr/local/lib/python3.6/site-packages/paramiko/packet.py", line 380, in readline
2020-04-30 04:19:08,798 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] |     buf += self._read_timeout(timeout)
2020-04-30 04:19:08,798 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] |   File "/usr/local/lib/python3.6/site-packages/paramiko/packet.py", line 622, in _read_timeout
2020-04-30 04:19:08,798 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] |     raise socket.timeout()
2020-04-30 04:19:08,798 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] | socket.timeout
2020-04-30 04:19:08,799 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] | 
2020-04-30 04:19:08,799 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] | During handling of the above exception, another exception occurred:
2020-04-30 04:19:08,799 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] | 
2020-04-30 04:19:08,799 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] | Traceback (most recent call last):
2020-04-30 04:19:08,799 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] |   File "/usr/local/lib/python3.6/site-packages/paramiko/transport.py", line 2039, in run
2020-04-30 04:19:08,799 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] |     self._check_banner()
2020-04-30 04:19:08,799 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] |   File "/usr/local/lib/python3.6/site-packages/paramiko/transport.py", line 2216, in _check_banner
2020-04-30 04:19:08,799 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] |     "Error reading SSH protocol banner" + str(e)
2020-04-30 04:19:08,799 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] | paramiko.ssh_exception.SSHException: Error reading SSH protocol banner
2020-04-30 04:19:08,799 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] | 
2020-04-30 04:19:12,803 p=64 u=root n=ansible | <tordevice.REDACTED> ESTABLISH PARAMIKO SSH CONNECTION FOR USER: username_REDACTED on PORT 22 TO tordevice.REDACTED
2020-04-30 04:19:12,806 p=64 u=root n=ansible | <tordevice.REDACTED> CONFIGURE PROXY COMMAND FOR CONNECTION: ssh -W tordevice.REDACTED:22 -q username_REDACTED@BASTION_SERVER_REDACTED_IP
2020-04-30 04:19:12,807 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] | starting thread (client mode): 0x8e94bc50
2020-04-30 04:19:12,807 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] | Local version/idstring: SSH-2.0-paramiko_2.7.1
2020-04-30 04:19:27,809 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] | Exception: Error reading SSH protocol banner
2020-04-30 04:19:27,809 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] | Traceback (most recent call last):
2020-04-30 04:19:27,809 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] |   File "/usr/local/lib/python3.6/site-packages/paramiko/transport.py", line 2211, in _check_banner
2020-04-30 04:19:27,809 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] |     buf = self.packetizer.readline(timeout)
2020-04-30 04:19:27,809 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] |   File "/usr/local/lib/python3.6/site-packages/paramiko/packet.py", line 380, in readline
2020-04-30 04:19:27,809 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] |     buf += self._read_timeout(timeout)
2020-04-30 04:19:27,809 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] |   File "/usr/local/lib/python3.6/site-packages/paramiko/packet.py", line 622, in _read_timeout
2020-04-30 04:19:27,809 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] |     raise socket.timeout()
2020-04-30 04:19:27,809 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] | socket.timeout
2020-04-30 04:19:27,809 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] | 
2020-04-30 04:19:27,809 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] | During handling of the above exception, another exception occurred:
2020-04-30 04:19:27,810 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] | 
2020-04-30 04:19:27,810 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] | Traceback (most recent call last):
2020-04-30 04:19:27,810 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] |   File "/usr/local/lib/python3.6/site-packages/paramiko/transport.py", line 2039, in run
2020-04-30 04:19:27,810 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] |     self._check_banner()
2020-04-30 04:19:27,810 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] |   File "/usr/local/lib/python3.6/site-packages/paramiko/transport.py", line 2216, in _check_banner
2020-04-30 04:19:27,810 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] |     "Error reading SSH protocol banner" + str(e)
2020-04-30 04:19:27,810 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] | paramiko.ssh_exception.SSHException: Error reading SSH protocol banner
2020-04-30 04:19:27,810 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] | 
2020-04-30 04:19:35,818 p=64 u=root n=ansible | <tordevice.REDACTED> ESTABLISH PARAMIKO SSH CONNECTION FOR USER: username_REDACTED on PORT 22 TO tordevice.REDACTED
2020-04-30 04:19:35,821 p=64 u=root n=ansible | <tordevice.REDACTED> CONFIGURE PROXY COMMAND FOR CONNECTION: ssh -W tordevice.REDACTED:22 -q username_REDACTED@BASTION_SERVER_REDACTED_IP
2020-04-30 04:19:35,822 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] | starting thread (client mode): 0x8e912470
2020-04-30 04:19:35,822 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] | Local version/idstring: SSH-2.0-paramiko_2.7.1
2020-04-30 04:19:50,824 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] | Exception: Error reading SSH protocol banner
2020-04-30 04:19:50,825 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] | Traceback (most recent call last):
2020-04-30 04:19:50,825 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] |   File "/usr/local/lib/python3.6/site-packages/paramiko/transport.py", line 2211, in _check_banner
2020-04-30 04:19:50,825 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] |     buf = self.packetizer.readline(timeout)
2020-04-30 04:19:50,825 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] |   File "/usr/local/lib/python3.6/site-packages/paramiko/packet.py", line 380, in readline
2020-04-30 04:19:50,825 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] |     buf += self._read_timeout(timeout)
2020-04-30 04:19:50,825 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] |   File "/usr/local/lib/python3.6/site-packages/paramiko/packet.py", line 622, in _read_timeout
2020-04-30 04:19:50,825 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] |     raise socket.timeout()
2020-04-30 04:19:50,825 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] | socket.timeout
2020-04-30 04:19:50,825 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] | 
2020-04-30 04:19:50,825 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] | During handling of the above exception, another exception occurred:
2020-04-30 04:19:50,825 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] | 
2020-04-30 04:19:50,826 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] | Traceback (most recent call last):
2020-04-30 04:19:50,826 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] |   File "/usr/local/lib/python3.6/site-packages/paramiko/transport.py", line 2039, in run
2020-04-30 04:19:50,826 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] |     self._check_banner()
2020-04-30 04:19:50,826 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] |   File "/usr/local/lib/python3.6/site-packages/paramiko/transport.py", line 2216, in _check_banner
2020-04-30 04:19:50,826 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] |     "Error reading SSH protocol banner" + str(e)
2020-04-30 04:19:50,826 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] | paramiko.ssh_exception.SSHException: Error reading SSH protocol banner
2020-04-30 04:19:50,826 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] | 
2020-04-30 04:19:50,827 p=64 u=root n=ansible | Traceback (most recent call last):
  File "/usr/local/lib/python3.6/site-packages/paramiko/transport.py", line 2211, in _check_banner
    buf = self.packetizer.readline(timeout)
  File "/usr/local/lib/python3.6/site-packages/paramiko/packet.py", line 380, in readline
    buf += self._read_timeout(timeout)
  File "/usr/local/lib/python3.6/site-packages/paramiko/packet.py", line 622, in _read_timeout
    raise socket.timeout()
socket.timeout

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.6/site-packages/ansible/plugins/connection/paramiko_ssh.py", line 352, in _connect_uncached
    **ssh_connect_kwargs
  File "/usr/local/lib/python3.6/site-packages/paramiko/client.py", line 406, in connect
    t.start_client(timeout=timeout)
  File "/usr/local/lib/python3.6/site-packages/paramiko/transport.py", line 660, in start_client
    raise e
  File "/usr/local/lib/python3.6/site-packages/paramiko/transport.py", line 2039, in run
    self._check_banner()
  File "/usr/local/lib/python3.6/site-packages/paramiko/transport.py", line 2216, in _check_banner
    "Error reading SSH protocol banner" + str(e)
paramiko.ssh_exception.SSHException: Error reading SSH protocol banner

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.6/site-packages/ansible/plugins/connection/network_cli.py", line 421, in _connect
    ssh = self.paramiko_conn._connect()
  File "/usr/local/lib/python3.6/site-packages/ansible/plugins/connection/paramiko_ssh.py", line 245, in _connect
    self.ssh = SSH_CONNECTION_CACHE[cache_key] = self._connect_uncached()
  File "/usr/local/lib/python3.6/site-packages/ansible/plugins/connection/paramiko_ssh.py", line 368, in _connect_uncached
    raise AnsibleConnectionFailure(msg)
ansible.errors.AnsibleConnectionFailure: Error reading SSH protocol banner

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.6/site-packages/ansible/utils/jsonrpc.py", line 45, in handle_request
    result = rpc_method(*args, **kwargs)
  File "/usr/local/lib/python3.6/site-packages/ansible/plugins/connection/__init__.py", line 34, in wrapped
    self._connect()
  File "/usr/local/lib/python3.6/site-packages/ansible/plugins/connection/network_cli.py", line 426, in _connect
    raise AnsibleConnectionFailure(to_text(e, errors='surrogate_or_strict'))
ansible.errors.AnsibleConnectionFailure: Error reading SSH protocol banner

2020-04-30 04:19:50,827 p=64 u=root n=ansible | network_cli_retry: attempt: 1, caught exception(Error reading SSH protocol banner), pausing for 2 seconds
2020-04-30 04:19:50,827 p=64 u=root n=ansible | network_cli_retry: attempt: 2, caught exception(Error reading SSH protocol banner), pausing for 4 seconds
2020-04-30 04:19:50,827 p=64 u=root n=ansible | network_cli_retry: attempt: 3, caught exception(Error reading SSH protocol banner), pausing for 8 seconds
2020-04-30 04:19:50,829 p=59 u=root n=ansible |     59 1588220390.82909: done running TaskExecutor() for tordevice.REDACTED/TASK: nxos_facts [0242ac11-0002-bf5d-b365-000000000008]
2020-04-30 04:19:50,829 p=59 u=root n=ansible |     59 1588220390.82940: sending task result for task 0242ac11-0002-bf5d-b365-000000000008
2020-04-30 04:19:50,829 p=59 u=root n=ansible |     59 1588220390.82987: done sending task result for task 0242ac11-0002-bf5d-b365-000000000008
2020-04-30 04:19:50,830 p=59 u=root n=ansible |     59 1588220390.83008: WORKER PROCESS EXITING
2020-04-30 04:19:50,832 p=53 u=root n=ansible | The full traceback is:
Traceback (most recent call last):
  File "/usr/local/lib/python3.6/site-packages/ansible/executor/task_executor.py", line 146, in run
    res = self._execute()
  File "/usr/local/lib/python3.6/site-packages/ansible/executor/task_executor.py", line 645, in _execute
    result = self._handler.run(task_vars=variables)
  File "/usr/local/lib/python3.6/site-packages/ansible/plugins/action/nxos.py", line 137, in run
    out = conn.get_prompt()
  File "/usr/local/lib/python3.6/site-packages/ansible/module_utils/connection.py", line 185, in __rpc__
    raise ConnectionError(to_text(msg, errors='surrogate_then_replace'), code=code)
ansible.module_utils.connection.ConnectionError: Error reading SSH protocol banner

2020-04-30 04:19:50,832 p=53 u=root n=ansible | fatal: [tordevice.REDACTED]: FAILED! => {
    "msg": "Unexpected failure during module execution.",
    "stdout": ""
}
2020-04-30 04:19:50,832 p=53 u=root n=ansible | ...ignoring
2020-04-30 04:19:50,832 p=53 u=root n=ansible |     53 1588220390.83253: no more pending results, returning what we have
2020-04-30 04:19:50,832 p=53 u=root n=ansible |     53 1588220390.83263: results queue empty
2020-04-30 04:19:50,832 p=53 u=root n=ansible |     53 1588220390.83271: checking for any_errors_fatal
2020-04-30 04:19:50,832 p=53 u=root n=ansible |     53 1588220390.83280: done checking for any_errors_fatal
2020-04-30 04:19:50,832 p=53 u=root n=ansible |     53 1588220390.83287: checking for max_fail_percentage
2020-04-30 04:19:50,832 p=53 u=root n=ansible |     53 1588220390.83293: done checking for max_fail_percentage
2020-04-30 04:19:50,833 p=53 u=root n=ansible |     53 1588220390.83299: checking to see if all hosts have failed and the running result is not ok
2020-04-30 04:19:50,833 p=53 u=root n=ansible |     53 1588220390.83305: done checking to see if all hosts have failed
2020-04-30 04:19:50,833 p=53 u=root n=ansible |     53 1588220390.83311: getting the remaining hosts for this loop
2020-04-30 04:19:50,833 p=53 u=root n=ansible |     53 1588220390.83318: done getting the remaining hosts for this loop
2020-04-30 04:19:50,833 p=53 u=root n=ansible |     53 1588220390.83329: building list of next tasks for hosts
2020-04-30 04:19:50,833 p=53 u=root n=ansible |     53 1588220390.83336: getting the next task for host tordevice.REDACTED
2020-04-30 04:19:50,833 p=53 u=root n=ansible |     53 1588220390.83344: done getting next task for host tordevice.REDACTED
2020-04-30 04:19:50,833 p=53 u=root n=ansible |     53 1588220390.83351:  ^ task is: TASK: meta (flush_handlers)
2020-04-30 04:19:50,833 p=53 u=root n=ansible |     53 1588220390.83359:  ^ state is: HOST STATE: block=3, task=1, rescue=0, always=0, run_state=ITERATING_TASKS, fail_state=FAILED_NONE, pending_setup=False, tasks child state? (None), rescue child state? (None), always child state? (None), did rescue? False, did start at task? False
2020-04-30 04:19:50,833 p=53 u=root n=ansible |     53 1588220390.83366: done building task lists
2020-04-30 04:19:50,833 p=53 u=root n=ansible |     53 1588220390.83373: counting tasks in each state of execution
2020-04-30 04:19:50,833 p=53 u=root n=ansible |     53 1588220390.83380: done counting tasks in each state of execution:
	num_setups: 0
	num_tasks: 1
	num_rescue: 0
	num_always: 0
2020-04-30 04:19:50,833 p=53 u=root n=ansible |     53 1588220390.83387: advancing hosts in ITERATING_TASKS
2020-04-30 04:19:50,833 p=53 u=root n=ansible |     53 1588220390.83393: starting to advance hosts
2020-04-30 04:19:50,834 p=53 u=root n=ansible |     53 1588220390.83399: getting the next task for host tordevice.REDACTED
2020-04-30 04:19:50,834 p=53 u=root n=ansible |     53 1588220390.83406: done getting next task for host tordevice.REDACTED
2020-04-30 04:19:50,834 p=53 u=root n=ansible |     53 1588220390.83414:  ^ task is: TASK: meta (flush_handlers)
2020-04-30 04:19:50,834 p=53 u=root n=ansible |     53 1588220390.83420:  ^ state is: HOST STATE: block=3, task=1, rescue=0, always=0, run_state=ITERATING_TASKS, fail_state=FAILED_NONE, pending_setup=False, tasks child state? (None), rescue child state? (None), always child state? (None), did rescue? False, did start at task? False
2020-04-30 04:19:50,834 p=53 u=root n=ansible |     53 1588220390.83426: done advancing hosts to next task
2020-04-30 04:19:50,834 p=53 u=root n=ansible | META: ran handlers
2020-04-30 04:19:50,834 p=53 u=root n=ansible |     53 1588220390.83459: done queuing things up, now waiting for results queue to drain
2020-04-30 04:19:50,834 p=53 u=root n=ansible |     53 1588220390.83468: results queue empty
2020-04-30 04:19:50,834 p=53 u=root n=ansible |     53 1588220390.83474: checking for any_errors_fatal
2020-04-30 04:19:50,834 p=53 u=root n=ansible |     53 1588220390.83482: done checking for any_errors_fatal
2020-04-30 04:19:50,834 p=53 u=root n=ansible |     53 1588220390.83487: checking for max_fail_percentage
2020-04-30 04:19:50,834 p=53 u=root n=ansible |     53 1588220390.83493: done checking for max_fail_percentage
2020-04-30 04:19:50,835 p=53 u=root n=ansible |     53 1588220390.83499: checking to see if all hosts have failed and the running result is not ok
2020-04-30 04:19:50,835 p=53 u=root n=ansible |     53 1588220390.83504: done checking to see if all hosts have failed
2020-04-30 04:19:50,835 p=53 u=root n=ansible |     53 1588220390.83510: getting the remaining hosts for this loop
2020-04-30 04:19:50,835 p=53 u=root n=ansible |     53 1588220390.83517: done getting the remaining hosts for this loop
2020-04-30 04:19:50,835 p=53 u=root n=ansible |     53 1588220390.83526: building list of next tasks for hosts
2020-04-30 04:19:50,835 p=53 u=root n=ansible |     53 1588220390.83533: getting the next task for host tordevice.REDACTED
2020-04-30 04:19:50,835 p=53 u=root n=ansible |     53 1588220390.83540: done getting next task for host tordevice.REDACTED
2020-04-30 04:19:50,835 p=53 u=root n=ansible |     53 1588220390.83546:  ^ task is: TASK: meta (flush_handlers)
2020-04-30 04:19:50,835 p=53 u=root n=ansible |     53 1588220390.83553:  ^ state is: HOST STATE: block=4, task=1, rescue=0, always=0, run_state=ITERATING_TASKS, fail_state=FAILED_NONE, pending_setup=False, tasks child state? (None), rescue child state? (None), always child state? (None), did rescue? False, did start at task? False
2020-04-30 04:19:50,835 p=53 u=root n=ansible |     53 1588220390.83560: done building task lists
2020-04-30 04:19:50,835 p=53 u=root n=ansible |     53 1588220390.83565: counting tasks in each state of execution
2020-04-30 04:19:50,835 p=53 u=root n=ansible |     53 1588220390.83575: done counting tasks in each state of execution:
	num_setups: 0
	num_tasks: 1
	num_rescue: 0
	num_always: 0
2020-04-30 04:19:50,835 p=53 u=root n=ansible |     53 1588220390.83583: advancing hosts in ITERATING_TASKS
2020-04-30 04:19:50,835 p=53 u=root n=ansible |     53 1588220390.83588: starting to advance hosts
2020-04-30 04:19:50,835 p=53 u=root n=ansible |     53 1588220390.83595: getting the next task for host tordevice.REDACTED
2020-04-30 04:19:50,836 p=53 u=root n=ansible |     53 1588220390.83602: done getting next task for host tordevice.REDACTED
2020-04-30 04:19:50,836 p=53 u=root n=ansible |     53 1588220390.83609:  ^ task is: TASK: meta (flush_handlers)
2020-04-30 04:19:50,836 p=53 u=root n=ansible |     53 1588220390.83616:  ^ state is: HOST STATE: block=4, task=1, rescue=0, always=0, run_state=ITERATING_TASKS, fail_state=FAILED_NONE, pending_setup=False, tasks child state? (None), rescue child state? (None), always child state? (None), did rescue? False, did start at task? False
2020-04-30 04:19:50,836 p=53 u=root n=ansible |     53 1588220390.83622: done advancing hosts to next task
2020-04-30 04:19:50,836 p=53 u=root n=ansible | META: ran handlers
2020-04-30 04:19:50,836 p=53 u=root n=ansible |     53 1588220390.83642: done queuing things up, now waiting for results queue to drain
2020-04-30 04:19:50,836 p=53 u=root n=ansible |     53 1588220390.83649: results queue empty
2020-04-30 04:19:50,836 p=53 u=root n=ansible |     53 1588220390.83654: checking for any_errors_fatal
2020-04-30 04:19:50,836 p=53 u=root n=ansible |     53 1588220390.83661: done checking for any_errors_fatal
2020-04-30 04:19:50,836 p=53 u=root n=ansible |     53 1588220390.83667: checking for max_fail_percentage
2020-04-30 04:19:50,836 p=53 u=root n=ansible |     53 1588220390.83676: done checking for max_fail_percentage
2020-04-30 04:19:50,836 p=53 u=root n=ansible |     53 1588220390.83682: checking to see if all hosts have failed and the running result is not ok
2020-04-30 04:19:50,836 p=53 u=root n=ansible |     53 1588220390.83687: done checking to see if all hosts have failed
2020-04-30 04:19:50,836 p=53 u=root n=ansible |     53 1588220390.83693: getting the remaining hosts for this loop
2020-04-30 04:19:50,837 p=53 u=root n=ansible |     53 1588220390.83699: done getting the remaining hosts for this loop
2020-04-30 04:19:50,837 p=53 u=root n=ansible |     53 1588220390.83708: building list of next tasks for hosts
2020-04-30 04:19:50,837 p=53 u=root n=ansible |     53 1588220390.83716: getting the next task for host tordevice.REDACTED
2020-04-30 04:19:50,837 p=53 u=root n=ansible |     53 1588220390.83723: done getting next task for host tordevice.REDACTED
2020-04-30 04:19:50,837 p=53 u=root n=ansible |     53 1588220390.83729:  ^ task is: None
2020-04-30 04:19:50,837 p=53 u=root n=ansible |     53 1588220390.83735:  ^ state is: HOST STATE: block=5, task=0, rescue=0, always=0, run_state=ITERATING_COMPLETE, fail_state=FAILED_NONE, pending_setup=False, tasks child state? (None), rescue child state? (None), always child state? (None), did rescue? False, did start at task? False
2020-04-30 04:19:50,837 p=53 u=root n=ansible |     53 1588220390.83742: done building task lists
2020-04-30 04:19:50,837 p=53 u=root n=ansible |     53 1588220390.83748: counting tasks in each state of execution
2020-04-30 04:19:50,837 p=53 u=root n=ansible |     53 1588220390.83755: done counting tasks in each state of execution:
	num_setups: 0
	num_tasks: 0
	num_rescue: 0
	num_always: 0
2020-04-30 04:19:50,837 p=53 u=root n=ansible |     53 1588220390.83762: all hosts are done, so returning None's for all hosts
2020-04-30 04:19:50,837 p=53 u=root n=ansible |     53 1588220390.83769: done queuing things up, now waiting for results queue to drain
2020-04-30 04:19:50,837 p=53 u=root n=ansible |     53 1588220390.83775: results queue empty
2020-04-30 04:19:50,837 p=53 u=root n=ansible |     53 1588220390.83781: checking for any_errors_fatal
2020-04-30 04:19:50,837 p=53 u=root n=ansible |     53 1588220390.83786: done checking for any_errors_fatal
2020-04-30 04:19:50,837 p=53 u=root n=ansible |     53 1588220390.83792: checking for max_fail_percentage
2020-04-30 04:19:50,838 p=53 u=root n=ansible |     53 1588220390.83797: done checking for max_fail_percentage
2020-04-30 04:19:50,838 p=53 u=root n=ansible |     53 1588220390.83803: checking to see if all hosts have failed and the running result is not ok
2020-04-30 04:19:50,838 p=53 u=root n=ansible |     53 1588220390.83809: done checking to see if all hosts have failed
2020-04-30 04:19:50,838 p=53 u=root n=ansible |     53 1588220390.83816: getting the next task for host tordevice.REDACTED
2020-04-30 04:19:50,838 p=53 u=root n=ansible |     53 1588220390.83823: done getting next task for host tordevice.REDACTED
2020-04-30 04:19:50,838 p=53 u=root n=ansible |     53 1588220390.83828:  ^ task is: None
2020-04-30 04:19:50,838 p=53 u=root n=ansible |     53 1588220390.83834:  ^ state is: HOST STATE: block=5, task=0, rescue=0, always=0, run_state=ITERATING_COMPLETE, fail_state=FAILED_NONE, pending_setup=False, tasks child state? (None), rescue child state? (None), always child state? (None), did rescue? False, did start at task? False
2020-04-30 04:19:50,838 p=53 u=root n=ansible |     53 1588220390.83841: running handlers
2020-04-30 04:19:50,839 p=53 u=root n=ansible | PLAY RECAP **************************************************************************************************************************************************
2020-04-30 04:19:50,839 p=53 u=root n=ansible | tordevice.REDACTED : ok=1    changed=0    unreachable=0    failed=0    skipped=0    rescued=0    ignored=1   
2020-04-30 04:19:50,839 p=53 u=root n=ansible |     53 1588220390.83948: RUNNING CLEANUP
2020-04-30 04:20:20,829 p=64 u=root n=ansible | persistent connection idle timeout triggered, timeout value is 30 secs.
See the timeout setting options in the Network Debug and Troubleshooting Guide.
2020-04-30 04:20:20,930 p=64 u=root n=ansible | shutdown complete

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

ansibot · 2020-04-30T23:23:51Z

Files identified in the description:

lib/ansible/plugins/connection

If these files are incorrect, please update the component name section of the description or use the !component bot command.

click here for bot help

ganeshrn · 2020-05-01T05:45:01Z

The issue should be fixed by PR #68184
Can you test the changes in PR and confirm if it works for you?

needs_info

dragon0087 · 2020-05-02T06:39:50Z

@ganeshrn we've tried to modify the banner timeout, but still have the same issue. The timeout only delay the error from 15s to 30s. The problem is the bastion server doesn't seem to start the proxycommand at all. We did tcpdump and see the connection from client to bastion server can be established. However right after the handshake the connection is closed by a FIN from client. When test directly using ssh command from the client it works as expected so the network connectivity is fine. Only when running from ansible-playbook we have this issue

dragon0087 · 2020-05-03T21:12:00Z

2020-04-30 04:19:35,822 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] | starting thread (client mode): 0x8e912470
2020-04-30 04:19:35,822 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] | Local version/idstring: SSH-2.0-paramiko_2.7.1
2020-04-30 04:19:50,824 p=64 u=root n=p=64 u=root | paramiko [tordevice.REDACTED] | Exception: Error reading SSH protocol banner
Here we can see clearly the 15s timeout. It actually retry 3 times, each time it hit the 15s. However from tcpdump we see the connection established then ended with FIN within 1s on bastion server.

ganeshrn · 2020-05-04T06:07:55Z

@dragon0087
Based on the logs you shared it seems there is a connection timeout triggered

2020-04-30 04:20:20,829 p=64 u=root n=ansible | persistent connection idle timeout triggered, timeout value is 30 secs.

Try increasing the connect_timeout Refer: https://docs.ansible.com/ansible/devel/network/user_guide/network_debug_troubleshooting.html#persistent-connection-idle-timeout

Even after that if you are seeing the issue enable the persistent device logging to identify which command is failing (gerp for jsonrpc request and jsonrpc response). However, since the connection is closed immediately I doubt it will have any logs but still can try it out.
Refer https://docs.ansible.com/ansible/devel/network/user_guide/network_debug_troubleshooting.html#persistent-connection-idle-timeout

dragon0087 · 2020-05-04T21:45:00Z

@ganeshrn change persistent timeout didn't help. persistent logging give only one more line that pretty much saying the same thing
2020-05-04 21:38:52,714 p=32 u=root n=ansible | jsonrpc response: {"jsonrpc": "2.0", "id": "3fc97156-4b2c-404b-8fa6-b1c8a2c64fcd", "error": {"code": -32603, "message": "Internal error", "data": "Error reading SSH protocol banner"}}

The issue is tcp connection can be established to bastion server but close immediately after GEX.

this is what it looks like in tcpdump on bastion server.
The interesting thing here is that Ansible sent the FIN to close the connection.

dragon0087 · 2020-05-04T22:16:53Z

btw this is our ansible.cfg

[defaults]
# log_path=/path/to/logfile
host_key_checking = False
forks = 500
retry_files_enabled = False


[persistent_connection]
command_timeout=600

[paramiko_connection]
host_key_auto_add = True
look_for_keys = False

ganeshrn · 2020-05-05T06:32:17Z

@dragon0087 In your ansible.cfg file I can't see any values for connect_timeout. Is it set somewhere else?

[persistent_connection]
command_timeout=600
connect_timeout=300

dragon0087 · 2020-05-05T21:16:47Z

@ganeshrn yes, I tried that by export env variable.

termlen0 · 2020-06-02T15:05:37Z

+1

ansibot · 2020-06-03T08:08:02Z

@seansabour This issue is waiting for your response. Please respond or the issue will be closed.

click here for bot help

seansabour · 2020-06-03T08:11:40Z

Hi @ganeshrn - can you remove the needs_info label, i don't want this issue to be closed ^

ganeshrn · 2020-06-03T08:26:37Z

@seansabour The network_cli plugin is now moved out of the core to https://github.com/ansible-collections/ansible.netcommon collection. Hence this issue will be closed anyways in future. Please raise a new issue https://github.com/ansible-collections/ansible.netcommon/issues with reference to this issue.

seansabour · 2020-06-03T08:39:04Z

@ganeshrn Cool, thanks for the heads up! I've opened the issue in the new repo

mkrizek · 2020-06-03T09:57:37Z

Closing per above.

ansibot added the needs_info This issue requires further information. Please answer any outstanding questions. label May 1, 2020

sivel removed the needs_triage Needs a first human triage before being processed. label May 1, 2020

ganeshrn self-assigned this May 4, 2020

sivel mentioned this issue May 8, 2020

Error reading SSH protocol banner on using ProxyCommand with ios_command #69389

Closed

seansabour mentioned this issue Jun 3, 2020

Error reading SSH protocol banner timeout when using network_cli connection ansible-collections/ansible.netcommon#46

Open

ansibot removed the needs_info This issue requires further information. Please answer any outstanding questions. label Jun 3, 2020

mkrizek closed this as completed Jun 3, 2020

ansible locked and limited conversation to collaborators Jul 1, 2020

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Error reading SSH protocol banner timeout when using network_cli connection #69267

Error reading SSH protocol banner timeout when using network_cli connection #69267

seansabour commented Apr 30, 2020 •

edited

Loading

ansibot commented Apr 30, 2020

ganeshrn commented May 1, 2020

dragon0087 commented May 2, 2020

dragon0087 commented May 3, 2020 •

edited

Loading

ganeshrn commented May 4, 2020

dragon0087 commented May 4, 2020

dragon0087 commented May 4, 2020

ganeshrn commented May 5, 2020 •

edited

Loading

dragon0087 commented May 5, 2020

termlen0 commented Jun 2, 2020

ansibot commented Jun 3, 2020

seansabour commented Jun 3, 2020

ganeshrn commented Jun 3, 2020

seansabour commented Jun 3, 2020

mkrizek commented Jun 3, 2020

Error reading SSH protocol banner timeout when using network_cli connection #69267

Error reading SSH protocol banner timeout when using network_cli connection #69267

Comments

seansabour commented Apr 30, 2020 • edited Loading

SUMMARY

ISSUE TYPE

COMPONENT NAME

ANSIBLE VERSION

CONFIGURATION

OS / ENVIRONMENT

STEPS TO REPRODUCE

EXPECTED RESULTS

ACTUAL RESULTS

ansibot commented Apr 30, 2020

ganeshrn commented May 1, 2020

dragon0087 commented May 2, 2020

dragon0087 commented May 3, 2020 • edited Loading

ganeshrn commented May 4, 2020

dragon0087 commented May 4, 2020

dragon0087 commented May 4, 2020

ganeshrn commented May 5, 2020 • edited Loading

dragon0087 commented May 5, 2020

termlen0 commented Jun 2, 2020

ansibot commented Jun 3, 2020

seansabour commented Jun 3, 2020

ganeshrn commented Jun 3, 2020

seansabour commented Jun 3, 2020

mkrizek commented Jun 3, 2020

seansabour commented Apr 30, 2020 •

edited

Loading

dragon0087 commented May 3, 2020 •

edited

Loading

ganeshrn commented May 5, 2020 •

edited

Loading