juniper_junos_software module failure: No handlers could be found for logger "ncclient.transport.session"

[jindu-okoli]

Issue Type

• Bug Report

Module Name

Juniper.Junos role and Python libraries version

~/Desktop/junos_upgrade$ pip freeze
ansible==2.7.5
apache-libcloud==2.2.1
asn1crypto==0.24.0
bcrypt==3.1.5
beautifulsoup4==4.6.0
certifi==2018.11.29
cffi==1.11.5
chardet==3.0.4
cryptography==2.4.2
enum34==1.1.6
html5lib==0.999999999
httplib2==0.9.2
idna==2.8
ipaddress==1.0.22
Jinja2==2.10
jmespath==0.9.3
junos-eznc==2.2.0
jxmlease==1.0.1
keyring==10.6.0
keyrings.alt==3.0
lockfile==0.12.2
lxml==4.2.5
MarkupSafe==1.1.0
ncclient==0.6.3
netaddr==0.7.19
paramiko==2.4.2
pyasn1==0.4.4
pycparser==2.19
pycrypto==2.6.1
pygobject==3.26.1
pykerberos==1.1.14
PyNaCl==1.3.0
pyOpenSSL==17.5.0
pyserial==3.4
pyxdg==0.25
PyYAML==3.13
requests==2.21.0
scp==0.13.0
SecretStorage==2.3.1
selectors2==2.0.1
simplejson==3.13.2
six==1.12.0
urllib3==1.24.1
webencodings==0.5
xmltodict==0.11.0

Juniper.junos-2.1.0

OS / Environment

Junos version: 14X53-D47, 17.2R1, 17.3R3
Model: EX4300

Summary

I get this error when upgrading a Junos device. The device reboots and the software is installed on the device but the script fails with this error :
No handlers could be found for logger "ncclient.transport.session"
Also, nothing is written to the log file. I have tried specifying the full path, creating the file with right permissions but it is still empty.

Steps to reproduce

---
- name: Software update
  hosts: devices
  roles:
  - Juniper.junos
  connection: local
  gather_facts: no

  vars:
    wait_time: 900
    log_dir: "log"
    netconf_port: 830
  vars_files:
  - vault-vars.yml

  tasks:
  - name: Install Junos Software
    juniper_junos_software:
      provider: "{{lab_credentials}}"
      local_package: /var/tmp/jinstall-ex-4300-17.2R1.13-signed.tgz
      reboot_pause: 65
      logfile: "{{ log_dir }}/{{ inventory_hostname }}.log"

Expected results

The script  upgrades/downgrades the device without failing

Actual results

fatal: [poc-ex4300-13]: FAILED! => {
"changed": false,
"rc": 1
}

MSG:

MODULE FAILURE
See stdout/stderr for the exact error

MODULE_STDERR:

No handlers could be found for logger "ncclient.transport.session"
Traceback (most recent call last):
File "/home/lab/.ansible/tmp/ansible-tmp-1546944251.76-50816382439807/AnsiballZ_juniper_junos_software.py", line 113, in
_ansiballz_main()
File "/home/lab/.ansible/tmp/ansible-tmp-1546944251.76-50816382439807/AnsiballZ_juniper_junos_software.py", line 105, in _ansiballz_main
invoke_module(zipped_mod, temp_path, ANSIBALLZ_PARAMS)
File "/home/lab/.ansible/tmp/ansible-tmp-1546944251.76-50816382439807/AnsiballZ_juniper_junos_software.py", line 48, in invoke_module
imp.load_module('main', mod, module, MOD_DESC)
File "/tmp/ansible_juniper_junos_software_payload_zOMHhH/main.py", line 747, in
File "/tmp/ansible_juniper_junos_software_payload_zOMHhH/main.py", line 743, in main
File "/tmp/ansible_juniper_junos_software_payload_zOMHhH/ansible_juniper_junos_software_payload.zip/ansible/module_utils/juniper_junos_common.py", line 792, in exit_json
File "/tmp/ansible_juniper_junos_software_payload_zOMHhH/ansible_juniper_junos_software_payload.zip/ansible/module_utils/juniper_junos_common.py", line 1327, in close
File "/home/lab/.local/lib/python2.7/site-packages/jnpr/junos/device.py", line 1328, in close
self._conn.close_session()
File "/home/lab/.local/lib/python2.7/site-packages/ncclient/manager.py", line 216, in execute
raise_mode=self._raise_mode).request(*args, **kwds)
File "/home/lab/.local/lib/python2.7/site-packages/ncclient/operations/session.py", line 28, in request
return self._request(new_ele("close-session"))
File "/home/lab/.local/lib/python2.7/site-packages/ncclient/operations/rpc.py", line 347, in _request
raise TimeoutExpiredError('ncclient timed out while waiting for an rpc reply.')
ncclient.operations.errors.TimeoutExpiredError: ncclient timed out while waiting for an rpc reply.

[tuhoanganh]

i'm facing the same problem when using juniper_junos_jsnapy.
Python 2.7.5
jsnapy 1.3.2
ansible 2.7.9

std_err:
fatal: [AGG01]: FAILED! => {
"changed": false,
"module_stderr": "No handlers could be found for logger "ncclient.transport.session"\n",
"module_stdout": "Taking snapshot of COMMAND: show interface xe-* \nTaking snapshot of COMMAND: show interface ge-* \n**************************** Device: 10.96.10.13 **\nTests Included: check_MTU_xe \n Command: show interface xe- \nPASS | All "mtu" is equal to "1514" [ 4 matched ]\nTests Included: check_MTU_ge \n Command: show interface ge- **********************\n[ERROR] Cong ge-0/2/0 MTU khac 1514, MTU hien tai la 9014 \nFAIL | All "mtu" is not equal to "1514" [ 0 matched / 1 failed ]\n------------------------------- Final Result!! -------------------------------\ncheck_MTU_ge : Failed\ncheck_MTU_xe : Passed\nTotal No of tests passed: 1\nTotal No of tests failed: 1 \nOverall Tests failed!!! \n\n{"final_result": "Failed", "total_failed": 1, "changed": false, "total_passed": 1, "test_results": {"show interface xe-": [{"xpath": "//physical-interface[normalize-space(oper-status)= \"up\"]", "count": {"fail": 0, "pass": 4}, "testoperation": "is-equal", "passed": [{"pre": {"mtu": "1514"}, "post": {"name": "xe-4/0/0", "mtu": "1514"}, "message": "[PASS] Cong xe-4/0/0 MTU la 1514 ", "actual_node_value": "1514", "id": {"name": "xe-4/0/0"}}, {"pre": {"mtu": "1514"}, "post": {"name": "xe-4/0/1", "mtu": "1514"}, "message": "[PASS] Cong xe-4/0/1 MTU la 1514 ", "actual_node_value": "1514", "id": {"name": "xe-4/0/1"}}, {"pre": {"mtu": "1514"}, "post": {"name": "xe-4/0/2", "mtu": "1514"}, "message": "[PASS] Cong xe-4/0/2 MTU la 1514 ", "actual_node_value": "1514", "id": {"name": "xe-4/0/2"}}, {"pre": {"mtu": "1514"}, "post": {"name": "xe-4/0/3", "mtu": "1514"}, "message": "[PASS] Cong xe-4/0/3 MTU la 1514 ", "actual_node_value": "1514", "id": {"name": "xe-4/0/3"}}], "node_name": "mtu", "failed": [], "result": true, "expected_node_value": "1514", "test_name": "check_MTU_xe"}], "show interface ge-": [{"xpath": "//physical-interface[normalize-space(oper-status)= \"up\"]", "count": {"fail": 1, "pass": 0}, "testoperation": "is-equal", "passed": [], "node_name": "mtu", "failed": [{"pre": {"mtu": "9014"}, "post": {"name": "ge-0/2/0", "mtu": "9014"}, "message": "[ERROR] Cong ge-0/2/0 MTU khac 1514, MTU hien tai la 9014 ", "actual_node_value": "9014", "id": {"name": "ge-0/2/0"}}], "result": false, "expected_node_value": "1514", "test_name": "check_MTU_ge"}]}, "failed": false, "total_tests": 2, "device": "10.96.10.13", "action": "snapcheck", "router": "10.96.10.13", "invocation": {"module_args": {"baud": null, "attempts": null, "ssh_private_key_file": null, "config_file": null, "level": null, "passwd": "VALUE_SPECIFIED_IN_NO_LOG_PARAMETER", "logdir": null, "ssh_config": null, "host": "10.96.10.13", "dir": "/etc/jsnapy/testfiles", "user": "juniper", "timeout": 30, "action": "snapcheck", "console": null, "logfile": null, "port": 830, "test_files": ["/home/juniper/METRO_HNI_JSNAPY/MBF_jsnapy.yml"], "mode": null}}, "pass_percentage": 50, "passPercentage": 50, "msg": "Test Failed: Passed 1, Failed 1"}\n",
"msg": "MODULE FAILURE\nSee stdout/stderr for the exact error",
"rc": 0
}

[dineshbaburam91]

@jindu-okoli Kindly use juniper.device ansible collection and validate the test case.

Playbook:

  vars:
    wait_time: 3600
    pkg_dir: /var/tmp/
    OS_version: 24.1 
    OS_package: junos-evo-install-ptx-x86-64-24.1I20240502185809-EVO.iso 
    log_dir: /var/log/

  tasks:
    - name: Checking NETCONF connectivity
      wait_for: host={{ ansible_ssh_host }} port=830 timeout=5
    - name: Install Junos OS package
      software:
        reboot: yes
        no_copy: True
        all_re: False
        version: "{{ OS_version }}"
        package: "{{ pkg_dir }}/{{ OS_package }}"
        logfile: "{{ log_dir }}/software.log"
      register: test1
      notify:
        - wait_reboot

    - name: Print response
      debug:
        var: test1

  handlers:
    - name: wait_reboot
      wait_for: host={{ ansible_ssh_host }} port=830 timeout={{ wait_time }}
      when: not test1.check_mode

Output:

(ansible-env)  % sudo ansible-playbook -i inventory pb.juniper_junos_software.yml

PLAY [Test juniper.device.software module] **************************************************************************************************************

TASK [Checking NETCONF connectivity] ********************************************************************************************************************
ok: [local_connection_testcases]

TASK [Install Junos OS package] *************************************************************************************************************************
changed: [local_connection_testcases]

TASK [Print response] ***********************************************************************************************************************************
ok: [local_connection_testcases] => {
    "test1": {
        "changed": true,
        "check_mode": false,
        "failed": false,
        "msg": "Package /var/tmp/junos-evo-install-ptx-x86-64-24.1R1-24.1I20240502185809-EVO successfully installed. Response from device is: \nAdding software images. This process can take several minutes. Please be patient...\n\nDownload and Validate in Progress\n\nre0: Running pre-checks for 'junos-evo-install-ptx-x86-64-24.1R1-202404032028.0-EVO'\n\nre0: Pre-checks pass successfully, copying files to software area\n\nre0: Starting upgrade : /var/tmp/junos-evo-install-ptx-x86-64-24.1R1-202404032028.0-EVO.iso\n\nre0: Upgrade version : junos-evo-install-ptx-x86-64-24.1R1-202404032028.0-EVO\n\nre0: Skipping Validation\n\nre1: Running pre-checks for 'junos-evo-install-ptx-x86-64-24.1R1-202404032028.0-EVO'\n\nre1: Pre-checks pass successfully, copying files to software area\n\nre0: Running post install commands...\n\nre1: Running post install commands...\n\nre0: Post install sequence was successful.\n\nre1: Post install sequence was successful.\n\nre0: Boot version is now 'junos-evo-install-ptx-x86-64-24.1R1-202404032028.0-EVO'\n\nre1: Boot version is now 'junos-evo-install-ptx-x86-64-24.1R1-202404032028.0-EVO'\n\nre0: Updating all nodes...\n\nre0: Other nodes have been updated successfully\n\nre0: Installation was successful\n\nImage validation and installation succeeded.\nWARNING: NOTE: A reboot is required to start using the new software.\nWARNING: Use the 'request system reboot' command when ready.\nWARNING: Configuration changes made after this point will not be validated.\nWARNING: Target image will be booted with the latest configuration. Changing configuration now may be risky. Reboot successfully initiated. Reboot message: \nreboot the system at Wed May  8 06:08:28 2024\n\n"
    }
}

RUNNING HANDLER [wait_reboot] ***************************************************************************************************************************
ok: [local_connection_testcases]

PLAY RECAP **********************************************************************************************************************************************
local_connection_testcases : ok=4    changed=1    unreachable=0    failed=0    skipped=0    rescued=0    ignored=0  

[dineshbaburam91]

Information provided. So, I'm closing the ticket.

If you have any issues with the latest Juniper Ansible collection, please don't hesitate to open a ticket.