[Master] tripleoclient does not play well with cliff-3.4.0

[yatin]

Jobs failing while running openstack baremetal node list with cliff-3.4.0:-

2020-08-05 05:51:21.643746 | primary | TASK [overcloud-prep-images : Wait until nodes will be manageable] *************
2020-08-05 05:51:21.643875 | primary | Wednesday 05 August 2020 05:51:21 +0000 (0:00:00.043) 0:30:18.884 ******
2020-08-05 05:51:28.122927 | primary | FAILED - RETRYING: Wait until nodes will be manageable (10 retries left).
2020-08-05 05:52:01.247231 | primary | FAILED - RETRYING: Wait until nodes will be manageable (9 retries left).
2020-08-05 05:52:34.901402 | primary | FAILED - RETRYING: Wait until nodes will be manageable (8 retries left).
2020-08-05 05:53:08.168990 | primary | FAILED - RETRYING: Wait until nodes will be manageable (7 retries left).
2020-08-05 05:53:41.332388 | primary | FAILED - RETRYING: Wait until nodes will be manageable (6 retries left).
2020-08-05 05:54:14.187384 | primary | FAILED - RETRYING: Wait until nodes will be manageable (5 retries left).
2020-08-05 05:54:47.252761 | primary | FAILED - RETRYING: Wait until nodes will be manageable (4 retries left).
2020-08-05 05:55:20.869404 | primary | FAILED - RETRYING: Wait until nodes will be manageable (3 retries left).
2020-08-05 05:55:54.463138 | primary | FAILED - RETRYING: Wait until nodes will be manageable (2 retries left).
2020-08-05 05:56:28.003778 | primary | FAILED - RETRYING: Wait until nodes will be manageable (1 retries left).
2020-08-05 05:57:01.057502 | primary | fatal: [undercloud]: FAILED! => {
2020-08-05 05:57:01.057662 | primary | "attempts": 10,
2020-08-05 05:57:01.057682 | primary | "changed": false,
2020-08-05 05:57:01.057694 | primary | "cmd": "set -o pipefail && openstack --os-cloud undercloud baremetal node list -f value -c \"Provisioning State\" | grep -v -e manageable -e available",
2020-08-05 05:57:01.057706 | primary | "delta": "0:00:02.497370",
2020-08-05 05:57:01.057717 | primary | "end": "2020-08-05 05:57:01.024299",
2020-08-05 05:57:01.057729 | primary | "failed_when_result": true,
2020-08-05 05:57:01.057740 | primary | "rc": 0,
2020-08-05 05:57:01.057751 | primary | "start": "2020-08-05 05:56:58.526929"
2020-08-05 05:57:01.057762 | primary | }
2020-08-05 05:57:01.057793 | primary |
2020-08-05 05:57:01.057807 | primary | STDOUT:
2020-08-05 05:57:01.057819 | primary |
2020-08-05 05:57:01.057830 | primary | 2020-08-05 05:57:00.306 119070 INFO osc_lib.shell [-] command: baremetal node list -> ironicclient.osc.v1.baremetal_node.ListBaremetalNode (auth=True)
2020-08-05 05:57:01.057859 | primary | 2020-08-05 05:57:00.308 119070 INFO osc_lib.clientmanager [-] Using auth plugin: password
2020-08-05 05:57:01.057871 | primary | 2020-08-05 05:57:00.737 119070 INFO osc_lib.shell [-] END return value: 0
2020-08-05 05:57:01.057882 | primary |
2020-08-05 05:57:01.057892 | primary |
2020-08-05 05:57:01.057903 | primary | STDERR:
2020-08-05 05:57:01.057914 | primary |
2020-08-05 05:57:01.057925 | primary | /usr/lib64/python3.6/importlib/_bootstrap.py:219: ImportWarning: can't resolve package from __spec__ or __package__, falling back on __name__ and __path__
2020-08-05 05:57:01.057935 | primary | return f(*args, **kwds)

Issue is happening happening as return code is 0 now and stdout is not null with new cliff as seen in above snippet.
Conditions on failing task:-
  until: result.stdout == ''
  failed_when: result.rc == 0

Detected while bumping cliff following uppper-constraints with
Logs:- https://review.rdoproject.org/r/#/c/28837/2/tags/victoria-uc.yml@84
https://logserver.rdoproject.org/37/28837/2/experimental/distgit-tripleo-master-testing-centos-8-multinode-1ctlr-featureset010/d0e0c05/job-output.txt

Small reproducer(On a undercloud node):-
virtualenv clifftest
source clifftest/bin/activate
pip install python-openstackclient python-ironicclient
openstack --os-cloud undercloud baremetal node list -f value -c "Provisioning State"

# Install python-tripleoclient
pip install python-tripleoclient
# Now output changes for command, some INFO messages are dumped:-
openstack --os-cloud undercloud baremetal node list -f value -c "Provisioning State"
2020-08-05 06:43:10.788 776951 INFO osc_lib.shell [-] command: baremetal node list -> ironicclient.osc.v1.baremetal_node.ListBaremetalNode (auth=True)
2020-08-05 06:43:10.790 776951 INFO osc_lib.clientmanager [-] Using auth plugin: password
2020-08-05 06:43:11.264 776951 INFO osc_lib.shell [-] END return value: 0

# Issue not specific to baremetal, all commands are impacted like
openstack --os-cloud undercloud network list
2020-08-05 06:45:28.404 780181 INFO osc_lib.shell [-] command: network list -> openstackclient.network.v2.network.ListNetwork (auth=True)
2020-08-05 06:45:28.405 780181 INFO osc_lib.clientmanager [-] Using auth plugin: password
/home/zuul/clifftest/lib/python3.6/site-packages/openstack/resource.py:351: DeprecationWarning: inspect.getargspec() is deprecated since Python 3.0, use inspect.signature() or inspect.getfullargspec()
  len(inspect.getargspec(type_).args) > 1)
+--------------------------------------+----------+--------------------------------------+
| ID | Name | Subnets |
+--------------------------------------+----------+--------------------------------------+
| 5cfe57fb-6520-429a-844a-06d57a835259 | ctlplane | dc35e3e7-713a-46fb-b792-3bd003ffda02 |
+--------------------------------------+----------+--------------------------------------+
2020-08-05 06:45:29.002 780181 INFO osc_lib.shell [-] END return value: 0

# If tripleoclient is removed from venv or cliff is downgraded to 3.3.0, issue no longer happens, so something is going wrong with tripleoclient. There is only 1 commit in 3.4.0 which switches to importlib-metadata:- https://github.com/openstack/cliff/compare/3.3.0...3.4.0

[OpenStack Infra (hudson-openstack)]

Related fix proposed to branch: master
Review: https://review.opendev.org/752931

[yatin (yatinkarel)]

Posting here so it's not lost(from #openstack-oslo):-
<ykarel> dhellmann, bnemec hi
<ykarel> can u check https://bugs.launchpad.net/tripleo/+bug/1890389
<openstack> Launchpad bug 1890389 in tripleo "[Master] tripleoclient does not play well with cliff-3.4.0" [High,Triaged] - Assigned to chandan kumar (chkumar246)
<ykarel> with cliff switch to stevedore with https://github.com/openstack/cliff/commit/6ac510d0cd25c8c3c76d56dd8e100ca2a6f8b962, we are seeing ^
<ykarel> can u check if it's some regression in cliff or tripleocient is not doing something right
<ykarel> on debugging i found that issue happens when logging.setup is called https://review.opendev.org/#/c/752931/2/tripleoclient/v1/overcloud_update.py
<ykarel> please check and suggest what would be good to clear this
<dhellmann> ykarel : You need to wait to use the config object to set up logging until oslo.config has parsed all of the arguments and read the config file. I think that means moving that call from the module scope to somewhere in a main function for the app.
<dhellmann> ykarel : you would want to move the logging.register_options() call to the same place
ykarel> dhellmann, Thanks, i would try that out and get back to you
<ykarel> but would try tomorrow

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/752931
Committed: https://git.openstack.org/cgit/openstack/python-tripleoclient/commit/?id=a8831c600080ba3a25993cac497da2a0c8210661
Submitter: Zuul
Branch: master

commit a8831c600080ba3a25993cac497da2a0c8210661
Author: yatinkarel <email address hidden>
Date: Mon Sep 21 18:00:40 2020 +0530

    Make tripleoclient compatible with cliff-3.4.0

    cliff with 3.4.0[1] release moved to stevedore for
    loading entry points, with this logging get's setup
    too early before config options are loaded.

    Move Config register and logging setup to app's main
    function.

    Also after moving logging.setup to app's main function
    a time.time call is removed so adjust test for it.

    [1] https://github.com/openstack/cliff/commit/6ac510

    Suggested-By: Doug Hellmann <email address hidden>
    Closes-Bug: #1890389
    Change-Id: Ia9a2146a0ad3156c80f8cdffe33280380319e3d6

[OpenStack Infra (hudson-openstack)]

Related fix proposed to branch: master
Review: https://review.opendev.org/760922

[OpenStack Infra (hudson-openstack)]

Related fix proposed to branch: master
Review: https://review.opendev.org/760980

[OpenStack Infra (hudson-openstack)]

Change abandoned by Sergii Golovatiuk (<email address hidden>) on branch: master
Review: https://review.opendev.org/760922

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/760980
Committed: https://git.openstack.org/cgit/openstack/python-tripleoclient/commit/?id=b139da3995a0033d6bb724c4e53ba4df1168f16c
Submitter: Zuul
Branch: master

commit b139da3995a0033d6bb724c4e53ba4df1168f16c
Author: Sergii Golovatiuk <email address hidden>
Date: Thu Oct 1 14:37:06 2020 +0200

    Logging refactor

    - Replace logging with logging from oslo_log
      In order to have timestamps as well as other features this patch
      replaces python logging to extended logging from oslo_log. This allows
      to produce timestamps in output messages
    - Replace some prints with log.info to have timing information in logs

    Change-Id: I3569272795a52bb25f3de502fdfd5006ff6b8be1
    Related-Bug: #1890389

[OpenStack Infra (hudson-openstack)]

Related fix proposed to branch: stable/victoria
Review: https://review.opendev.org/761788

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/761788
Committed: https://git.openstack.org/cgit/openstack/python-tripleoclient/commit/?id=3a6354edb2718f4dc0a1edcb76afde536131d3a7
Submitter: Zuul
Branch: stable/victoria

commit 3a6354edb2718f4dc0a1edcb76afde536131d3a7
Author: Sergii Golovatiuk <email address hidden>
Date: Thu Oct 1 14:37:06 2020 +0200

    Logging refactor

    - Replace logging with logging from oslo_log
      In order to have timestamps as well as other features this patch
      replaces python logging to extended logging from oslo_log. This allows
      to produce timestamps in output messages
    - Replace some prints with log.info to have timing information in logs

    Change-Id: I3569272795a52bb25f3de502fdfd5006ff6b8be1
    Related-Bug: #1890389
    (cherry picked from commit b139da3995a0033d6bb724c4e53ba4df1168f16c)