UCS creation fails when restjavad timeout is exceeded

[aknot242]

ISSUE TYPE

• Bug Report

COMPONENT NAME

bigip_ucs_fetch

ANSIBLE VERSION

ansible 2.6.0
  config file = /home/snops/ansible-bigip-remote-backup/ansible.cfg
  configured module search path = [u'/root/.ansible/plugins/modules', u'/usr/share/ansible/plugins/modules']
  ansible python module location = /usr/lib/python2.7/site-packages/ansible
  executable location = /usr/bin/ansible
  python version = 2.7.15 (default, Aug 22 2018, 13:41:33) [GCC 6.2.1 20160822]

PYTHON VERSION

Python 2.7.15

BIGIP VERSION

Sys::Version
Main Package
  Product     BIG-IP
  Version     15.0.1
  Build       0.0.11
  Edition     Final
  Date        Fri Aug  2 21:38:03 PDT 2019

CONFIGURATION

deprecation_warnings = False retry_files_enabled = False host_key_checking=False

OS / ENVIRONMENT

N/A

SUMMARY

STEPS TO REPRODUCE

---
- name: Create UCS backup
  hosts: big-ips
  connection: local

  vars:
    backup_file: v15_backup.ucs
    local_path: ./
    provider:
      password: "{{ f5_password }}"
      server: "{{ inventory_hostname }}"
      user: "{{ f5_username }}"
      validate_certs: "{{ validate_certs }}"
      server_port: "{{ f5_server_port }}"

  tasks:
    - name: Create and Download a new UCS
      bigip_ucs_fetch:
        src: "{{ backup_file }}"
        dest: "{{ local_path }}{{ backup_file }}"
        create_on_missing: yes
        provider: "{{ provider }}"
      delegate_to: localhost

EXPECTED RESULTS

A backup is created

ACTUAL RESULTS

No UCS is created, and failure occurs at around 65 seconds. Presumably this is the point at which the restjavad call times out. If this is the case, issue reproduction may not be possible on a BIG-IP with a smaller backup workload, or a platform with greater control plane resources.

TASK [Gathering Facts] *********************************************************************************************************
ok: [mybigip]

TASK [Create and Download a new UCS] *******************************************************************************************
fatal: [mybigip -> localhost]: FAILED! => {"changed": false, "msg": "400 Unexpected Error: Bad 
Request for uri: https://mybigip:443/mgmt/tm/sys/ucs/\nText: u'{\"code\":400,\"message\":\"remo
teSender:1.1.1.1, method:POST \",\"originalRequestBody\":\"{\\\\\"command\\\\\": \\\\\"save\\\\\", \\\\\"name\\\\\": \\\\\
"v15_backup\\\\\"}\",\"referer\":\"1.1.1.1\",\"restOperationId\":50268851,\"kind\":\":resterrorrespon
se\"}'"}

PLAY RECAP *********************************************************************************************************************
mybigip : ok=1    changed=0    unreachable=0    failed=1   

The following is the restjavad log entry at the time of the failure:

==> /var/log/restjavad.0.log <==
[WARNING][586760][02 Oct 2019 02:05:24 UTC][8100/tm/auth/user PublicWorker] URI:http://localhost:8100/tm/sys/ucs/, Referrer:1.1.1.1, Method:POST, Exception:java.util.concurrent.TimeoutException: remoteSender:1.1.1.1, method:POST
    at com.f5.rest.common.RestWorker.logAndFailExpiredOperation(RestWorker.java:3168)
    at com.f5.rest.common.RestWorker.checkForExpiredOperations(RestWorker.java:3157)
    at com.f5.rest.common.RestServer.checkAndExpirePendingWorkerOperations(RestServer.java:1263)
    at com.f5.rest.common.RestServer.access$200(RestServer.java:44)
    at com.f5.rest.common.RestServer$3.run(RestServer.java:1236)
    at com.f5.rest.common.ScheduleTaskManager$2$1.run(ScheduleTaskManager.java:123)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:473)
    at java.util.concurrent.FutureTask.run(FutureTask.java:262)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:178)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:292)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1152)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:622)
    at java.lang.Thread.run(Thread.java:748)

[aknot242]

As I believe that the Ansible module cannot address changing the internal BIG-IP timeout value, I recommended using iControlREST asynchronous API transactions to accomplish the UCS archive.

[wojtek0806]

Please test with either Ansible development version or ansible 2.9 and report back @aknot242

[aknot242]

Yes, this is also occurring on 2.9.0rc1.

[wojtek0806]

Tentatively accepted: FMFA-409

Will be evaluated during development work

[MarkCon00]

Looks like this is BIG-IP ID797721 and not a bug on ansible. Try this on BIG-IP version 15.1.0 which I believed was already fixed.

[aknot242]

In 15.1.0, it appears that the BIG-IP REST API timeouts can be prevented by heeding the guidance in the release notes. However, The bigip_ucs_fetch Ansible module still appears to be timing out while waiting for the response. The provider timeout property appears to be 120 seconds, and can supposedly be overridden, but it does not appear that bigip_ucs_fetch is making use of the overridden timeout value. Here's the full exception:

An exception occurred during task execution. To see the full traceback, use -vvv. The error was: socket.timeout: The read operation timed out fatal: [mybigip.example.com -> localhost]: FAILED! => {"changed": false, "module_stderr": "Traceback (most recent call last):\n File \"/Users/user/.ansible/tmp/ansible-tmp-1579649776.13241-134533244415436/AnsiballZ_bigip_ucs_fetch.py\", line 102, in <module>\n _ansiballz_main()\n File \"/Users/user/.ansible/tmp/ansible-tmp-1579649776.13241-134533244415436/AnsiballZ_bigip_ucs_fetch.py\", line 94, in _ansiballz_main\n invoke_module(zipped_mod, temp_path, ANSIBALLZ_PARAMS)\n File \"/Users/user/.ansible/tmp/ansible-tmp-1579649776.13241-134533244415436/AnsiballZ_bigip_ucs_fetch.py\", line 40, in invoke_module\n runpy.run_module(mod_name='ansible.modules.network.f5.bigip_ucs_fetch', init_globals=None, run_name='__main__', alter_sys=True)\n File \"/usr/local/Cellar/python/3.7.5/Frameworks/Python.framework/Versions/3.7/lib/python3.7/runpy.py\", line 205, in run_module\n return _run_module_code(code, init_globals, run_name, mod_spec)\n File \"/usr/local/Cellar/python/3.7.5/Frameworks/Python.framework/Versions/3.7/lib/python3.7/runpy.py\", line 96, in _run_module_code\n mod_name, mod_spec, pkg_name, script_name)\n File \"/usr/local/Cellar/python/3.7.5/Frameworks/Python.framework/Versions/3.7/lib/python3.7/runpy.py\", line 85, in _run_code\n exec(code, run_globals)\n File \"/var/folders/yz/r44jvm3925l65zm1d81_gf51vz0hk7/T/ansible_bigip_ucs_fetch_payload_py_5yp3m/ansible_bigip_ucs_fetch_payload.zip/ansible/modules/network/f5/bigip_ucs_fetch.py\", line 612, in <module>\n File \"/var/folders/yz/r44jvm3925l65zm1d81_gf51vz0hk7/T/ansible_bigip_ucs_fetch_payload_py_5yp3m/ansible_bigip_ucs_fetch_payload.zip/ansible/modules/network/f5/bigip_ucs_fetch.py\", line 605, in main\n File \"/var/folders/yz/r44jvm3925l65zm1d81_gf51vz0hk7/T/ansible_bigip_ucs_fetch_payload_py_5yp3m/ansible_bigip_ucs_fetch_payload.zip/ansible/modules/network/f5/bigip_ucs_fetch.py\", line 265, in exec_module\n File \"/var/folders/yz/r44jvm3925l65zm1d81_gf51vz0hk7/T/ansible_bigip_ucs_fetch_payload_py_5yp3m/ansible_bigip_ucs_fetch_payload.zip/ansible/modules/network/f5/bigip_ucs_fetch.py\", line 300, in exec_module\n File \"/var/folders/yz/r44jvm3925l65zm1d81_gf51vz0hk7/T/ansible_bigip_ucs_fetch_payload_py_5yp3m/ansible_bigip_ucs_fetch_payload.zip/ansible/modules/network/f5/bigip_ucs_fetch.py\", line 312, in present\n File \"/var/folders/yz/r44jvm3925l65zm1d81_gf51vz0hk7/T/ansible_bigip_ucs_fetch_payload_py_5yp3m/ansible_bigip_ucs_fetch_payload.zip/ansible/modules/network/f5/bigip_ucs_fetch.py\", line 369, in create\n File \"/var/folders/yz/r44jvm3925l65zm1d81_gf51vz0hk7/T/ansible_bigip_ucs_fetch_payload_py_5yp3m/ansible_bigip_ucs_fetch_payload.zip/ansible/modules/network/f5/bigip_ucs_fetch.py\", line 390, in create_on_device\n File \"/var/folders/yz/r44jvm3925l65zm1d81_gf51vz0hk7/T/ansible_bigip_ucs_fetch_payload_py_5yp3m/ansible_bigip_ucs_fetch_payload.zip/ansible/module_utils/network/f5/icontrol.py\", line 238, in post\n File \"/var/folders/yz/r44jvm3925l65zm1d81_gf51vz0hk7/T/ansible_bigip_ucs_fetch_payload_py_5yp3m/ansible_bigip_ucs_fetch_payload.zip/ansible/module_utils/network/f5/icontrol.py\", line 193, in send\n File \"/var/folders/yz/r44jvm3925l65zm1d81_gf51vz0hk7/T/ansible_bigip_ucs_fetch_payload_py_5yp3m/ansible_bigip_ucs_fetch_payload.zip/ansible/module_utils/urls.py\", line 1294, in open\n File \"/usr/local/Cellar/python/3.7.5/Frameworks/Python.framework/Versions/3.7/lib/python3.7/urllib/request.py\", line 222, in urlopen\n return opener.open(url, data, timeout)\n File \"/usr/local/Cellar/python/3.7.5/Frameworks/Python.framework/Versions/3.7/lib/python3.7/urllib/request.py\", line 525, in open\n response = self._open(req, data)\n File \"/usr/local/Cellar/python/3.7.5/Frameworks/Python.framework/Versions/3.7/lib/python3.7/urllib/request.py\", line 543, in _open\n '_open', req)\n File \"/usr/local/Cellar/python/3.7.5/Frameworks/Python.framework/Versions/3.7/lib/python3.7/urllib/request.py\", line 503, in _call_chain\n result = func(*args)\n File \"/var/folders/yz/r44jvm3925l65zm1d81_gf51vz0hk7/T/ansible_bigip_ucs_fetch_payload_py_5yp3m/ansible_bigip_ucs_fetch_payload.zip/ansible/module_utils/urls.py\", line 467, in https_open\n File \"/usr/local/Cellar/python/3.7.5/Frameworks/Python.framework/Versions/3.7/lib/python3.7/urllib/request.py\", line 1320, in do_open\n r = h.getresponse()\n File \"/usr/local/Cellar/python/3.7.5/Frameworks/Python.framework/Versions/3.7/lib/python3.7/http/client.py\", line 1344, in getresponse\n response.begin()\n File \"/usr/local/Cellar/python/3.7.5/Frameworks/Python.framework/Versions/3.7/lib/python3.7/http/client.py\", line 306, in begin\n version, status, reason = self._read_status()\n File \"/usr/local/Cellar/python/3.7.5/Frameworks/Python.framework/Versions/3.7/lib/python3.7/http/client.py\", line 267, in _read_status\n line = str(self.fp.readline(_MAXLINE + 1), \"iso-8859-1\")\n File \"/usr/local/Cellar/python/3.7.5/Frameworks/Python.framework/Versions/3.7/lib/python3.7/socket.py\", line 589, in readinto\n return self._sock.recv_into(b)\n File \"/usr/local/Cellar/python/3.7.5/Frameworks/Python.framework/Versions/3.7/lib/python3.7/ssl.py\", line 1071, in recv_into\n return self.read(nbytes, buffer)\n File \"/usr/local/Cellar/python/3.7.5/Frameworks/Python.framework/Versions/3.7/lib/python3.7/ssl.py\", line 929, in read\n return self._sslobj.read(len, buffer)\nsocket.timeout: The read operation timed out\n", "module_stdout": "", "msg": "MODULE FAILURE\nSee stdout/stderr for the exact error", "rc": 1}

[focrensh]

Pending REST API endpoint to update timeout.

[AwwwwwYeah]

Hi, sorry, Is this fixed now and how/what version of Ansible or Ansible components was it fixed-in? I have the same problem.

[AwwwwwYeah]

The interesting thing about it my set up is it almost always times out first time but succeeds on second pass, so its like the UCS is still generating (and causing the delays) but when you run the UCS fetch the second time, the file has generated and now ready to be picked up without the need to generate again.

[focrensh]

The commit mentioned above will be in the next release.