Py3.7 test failure MismatchError: 'info\nwarn\n' != 'warn\n'

Bug #1783630 reported by Corey Bryant
18
This bug affects 3 people
Affects Status Importance Assigned to Milestone
oslo.log
Fix Released
High
Ben Nemec

Bug Description

The following test is failing with Py3.7:

FAIL: oslo_log.tests.unit.test_log.MutateTestCase.test_remove_logger
--------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/corey/pkg/rocky2/upstream/oslo.log/oslo_log/tests/unit/test_log.py", line 1544, in test_remove_logger
    self.assertEqual("info\nwarn\n", stream.getvalue())
  File "/home/corey/pkg/rocky2/upstream/oslo.log/.tox/py37/lib/python3.7/site-packages/testtools/testcase.py", line 411, in assertEqual
    self.assertThat(observed, matcher, message)
  File "/home/corey/pkg/rocky2/upstream/oslo.log/.tox/py37/lib/python3.7/site-packages/testtools/testcase.py", line 498, in assertThat
    raise mismatch_error
testtools.matchers._impl.MismatchError: 'info\nwarn\n' != 'warn\n'
Ran 178 tests in 7.423s
FAILED (id=0, failures=3, skips=1)

Ben Nemec (bnemec)
Changed in oslo.log:
status: New → Confirmed
importance: Undecided → High
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix proposed to oslo.log (master)

Fix proposed to branch: master
Review: https://review.opendev.org/676450

Changed in oslo.log:
assignee: nobody → Ben Nemec (bnemec)
status: Confirmed → In Progress
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix merged to oslo.log (master)

Reviewed: https://review.opendev.org/676450
Committed: https://git.openstack.org/cgit/openstack/oslo.log/commit/?id=500788981e1abcd5a495badac350285e39f993a4
Submitter: Zuul
Branch: master

commit 500788981e1abcd5a495badac350285e39f993a4
Author: Ben Nemec <email address hidden>
Date: Wed Aug 14 16:02:23 2019 +0000

    Use setLevel instead of setting logger.level directly

    Python 3.7 added caching of the log level for calls to isEnabledFor
    on a logger[0]. As a result, modifying the logger level directly
    can cause a mismatch in behavior if a log call was made prior to
    that modification. In our case, we were calling logger.info before
    the info level was enabled, which meant the logger cached the fact
    that it was not enabled for info-level logging. Even after setting
    the level to NOTSET, it was still remembering that it shouldn't log
    info messages and that breaks our unit tests on py37. There is a
    related issue open against Python[1], but basically the answer there
    was "don't mess with logger internals".

    The simple fix is to use logger.setLevel for resetting the log level
    instead of modifying the attribute directly.

    Change-Id: Ifd1300d8e4280df1913f632e964f9458dbb2db55
    0: https://github.com/python/cpython/commit/78c18a9b9a1445f7c755929917a790ba02b4a5e0#diff-5bd69232a06838f179312d3e48ccf506
    1: https://bugs.python.org/issue34269
    Closes-Bug: 1783630

Changed in oslo.log:
status: In Progress → Fix Released
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix included in openstack/oslo.log 3.44.1

This issue was fixed in the openstack/oslo.log 3.44.1 release.

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Duplicates of this bug

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.