The NullHandler and StandardLogging test fixtures don't appear to be detecting formatting errors

[Matt Riedemann]

We have the NullHandler and StandardLogging fixtures here to detect formatting errors in the nova logs:

http://git.openstack.org/cgit/openstack/nova/tree/nova/tests/fixtures.py#n61

We've seen a few bugs recently where we weren't substituting variables in the log messages but didn't notice until after the fact:

https://review.openstack.org/#/c/220253/

https://review.openstack.org/#/c/221910/

It also appears we should be using the logging_error fixture from oslo.log:

http://git.openstack.org/cgit/openstack/oslo.log/tree/oslo_log/fixture/logging_error.py

[Matt Riedemann (mriedem)]

To test this, I made a change like this:

                        LOG.debug('Explicitly disassociating fixed IP %(test)s from '
                                  'instance.', address,
                                  instance_uuid=instance_uuid)

And then ran a unit test that I know hits that code and it failed:

nova.tests.unit.network.test_manager.NetworkManagerNoDBTestCase.test_deallocate_fixed_ip_explicit_disassociate
--------------------------------------------------------------------------------------------------------------

Captured traceback:
~~~~~~~~~~~~~~~~~~~
    Traceback (most recent call last):
      File "/home/mriedem/git/nova/.tox/py27/local/lib/python2.7/site-packages/mock/mock.py", line 1305, in patched
        return func(*args, **keywargs)
      File "nova/tests/unit/network/test_manager.py", line 3643, in test_deallocate_fixed_ip_explicit_disassociate
        do_test()
      File "/home/mriedem/git/nova/.tox/py27/local/lib/python2.7/site-packages/mock/mock.py", line 1305, in patched
        return func(*args, **keywargs)
      File "nova/tests/unit/network/test_manager.py", line 3635, in do_test
        self.context, fip['address'], instance=fake_inst)
      File "nova/network/manager.py", line 1090, in deallocate_fixed_ip
        instance=instance)
      File "/home/mriedem/git/nova/.tox/py27/local/lib/python2.7/site-packages/oslo_utils/excutils.py", line 195, in __exit__
        six.reraise(self.type_, self.value, self.tb)
      File "nova/network/manager.py", line 1078, in deallocate_fixed_ip
        instance_uuid=instance_uuid)
      File "/usr/lib/python2.7/logging/__init__.py", line 1425, in debug
        self.logger.debug(msg, *args, **kwargs)
      File "/usr/lib/python2.7/logging/__init__.py", line 1140, in debug
        self._log(DEBUG, msg, args, **kwargs)
      File "/usr/lib/python2.7/logging/__init__.py", line 1271, in _log
        self.handle(record)
      File "/usr/lib/python2.7/logging/__init__.py", line 1281, in handle
        self.callHandlers(record)
      File "/usr/lib/python2.7/logging/__init__.py", line 1321, in callHandlers
        hdlr.handle(record)
      File "nova/tests/fixtures.py", line 69, in handle
        self.format(record)
      File "/usr/lib/python2.7/logging/__init__.py", line 724, in format
        return fmt.format(record)
      File "/usr/lib/python2.7/logging/__init__.py", line 464, in format
        record.message = record.getMessage()
      File "/usr/lib/python2.7/logging/__init__.py", line 328, in getMessage
        msg = msg % self.args
    TypeError: format requires a mapping

[Matt Riedemann (mriedem)]

This doesn't fail, but it doesn't work in runtime either:

                        LOG.debug('Explicitly disassociating fixed IP %(address)s from '
                                  'instance.', address=address,
                                  instance_uuid=instance_uuid)

That's an example of what was wrong in https://review.openstack.org/#/c/221910/ .

[Matt Riedemann (mriedem)]

This is another one that doesn't fail, but it doesn't work either:

                        LOG.debug('Explicitly disassociating fixed IP %s from '
                                  'instance.', instance_uuid=instance_uuid)

That's like what was addressed here: https://review.openstack.org/#/c/220253/

[Matt Riedemann (mriedem)]

I'm guessing something was regressed when we moved to using oslo.log:

https://review.openstack.org/#/c/154260/

Since that changed how some of the logging fixtures worked.

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.openstack.org/221973

[melanie witt (melwitt)]

In oslo.log it uses something called the KeywordArgumentAdapter [1] which takes arbitrary keyword arguments and adds them to the "extra" keyword arg as a dict that's sent to the logger. That's why we don't see failures for things that are in "extra" but aren't accounted for in the format string -- they're simply ignored.

[1] https://github.com/openstack/oslo.log/blob/a0e50f8/oslo_log/log.py#L120-L125

[OpenStack Infra (hudson-openstack)]

Change abandoned by Matt Riedemann (<email address hidden>) on branch: master
Review: https://review.openstack.org/221973
Reason: I'm going to throw this fish back, since I never really caught it anyway.