oslo.log

Misleading TRACE level when printing exception

Bug #1434851 reported by Davanum Srinivas (DIMS) on 2015-03-21

This bug affects 1 person

Affects		Status	Importance	Assigned to	Milestone
	oslo.log	Fix Released	Undecided	Davanum Srinivas (DIMS)	oslo.log 1.4.0 "1.4.0"

Bug Description

Let's take this example:
http://logs.openstack.org/53/166453/1/gate/gate-tempest-dsvm-neutron-src-oslo.i18n/86b6ba8/logs/screen-q-agt.txt.gz?level=TRACE#_2015-03-21_16_33_28_351

The Traceback is printed from the following line:
LOG.exception(_LE("Error while processing VIF ports"))

Which means the log level is ERROR, but because the oslo.log config option (logging_exception_prefix) defaults to:

    cfg.StrOpt('logging_exception_prefix',
               default='%(asctime)s.%(msecs)03d %(process)d TRACE %(name)s '
               '%(instance)s',
               help='Prefix each line of exception output with this format.'),

The traceback in the log looks like this

2015-03-21 16:33:28.351 ERROR neutron.plugins.openvswitch.agent.ovs_neutron_agent [req-b55e69ba-e9b9-4cd2-a267-8c296dd79db6 None None] Error while processing VIF ports
2015-03-21 16:33:28.351 18984 TRACE neutron.plugins.openvswitch.agent.ovs_neutron_agent Traceback (most recent call last):
2015-03-21 16:33:28.351 18984 TRACE neutron.plugins.openvswitch.agent.ovs_neutron_agent File "/opt/stack/new/neutron/neutron/plugins/openvswitch/agent/ovs_neutron_agent.py", line 1479, in rpc_loop
2015-03-21 16:33:28.351 18984 TRACE neutron.plugins.openvswitch.agent.ovs_neutron_agent port_info = self.scan_ports(reg_ports, updated_ports_copy)
2015-03-21 16:33:28.351 18984 TRACE neutron.plugins.openvswitch.agent.ovs_neutron_agent File "/opt/stack/new/neutron/neutron/plugins/openvswitch/agent/ovs_neutron_agent.py", line 1001, in scan_ports
2015-03-21 16:33:28.351 18984 TRACE neutron.plugins.openvswitch.agent.ovs_neutron_agent updated_ports.update(self.check_changed_vlans(registered_ports))
2015-03-21 16:33:28.351 18984 TRACE neutron.plugins.openvswitch.agent.ovs_neutron_agent File "/opt/stack/new/neutron/neutron/plugins/openvswitch/agent/ovs_neutron_agent.py", line 1028, in check_changed_vlans
2015-03-21 16:33:28.351 18984 TRACE neutron.plugins.openvswitch.agent.ovs_neutron_agent port_tags = self.int_br.get_port_tag_dict()
2015-03-21 16:33:28.351 18984 TRACE neutron.plugins.openvswitch.agent.ovs_neutron_agent File "/opt/stack/new/neutron/neutron/agent/linux/ovs_lib.py", line 375, in get_port_tag_dict
2015-03-21 16:33:28.351 18984 TRACE neutron.plugins.openvswitch.agent.ovs_neutron_agent results = cmd.execute(check_error=True)
2015-03-21 16:33:28.351 18984 TRACE neutron.plugins.openvswitch.agent.ovs_neutron_agent File "/opt/stack/new/neutron/neutron/agent/ovsdb/impl_vsctl.py", line 83, in execute
2015-03-21 16:33:28.351 18984 TRACE neutron.plugins.openvswitch.agent.ovs_neutron_agent txn.add(self)
2015-03-21 16:33:28.351 18984 TRACE neutron.plugins.openvswitch.agent.ovs_neutron_agent File "/opt/stack/new/neutron/neutron/agent/ovsdb/api.py", line 68, in __exit__
2015-03-21 16:33:28.351 18984 TRACE neutron.plugins.openvswitch.agent.ovs_neutron_agent self.result = self.commit()
2015-03-21 16:33:28.351 18984 TRACE neutron.plugins.openvswitch.agent.ovs_neutron_agent File "/opt/stack/new/neutron/neutron/agent/ovsdb/impl_vsctl.py", line 50, in commit
2015-03-21 16:33:28.351 18984 TRACE neutron.plugins.openvswitch.agent.ovs_neutron_agent res = self.run_vsctl(args)
2015-03-21 16:33:28.351 18984 TRACE neutron.plugins.openvswitch.agent.ovs_neutron_agent File "/opt/stack/new/neutron/neutron/agent/ovsdb/impl_vsctl.py", line 70, in run_vsctl
2015-03-21 16:33:28.351 18984 TRACE neutron.plugins.openvswitch.agent.ovs_neutron_agent ctxt.reraise = False
2015-03-21 16:33:28.351 18984 TRACE neutron.plugins.openvswitch.agent.ovs_neutron_agent File "/usr/local/lib/python2.7/dist-packages/oslo_utils/excutils.py", line 85, in __exit__
2015-03-21 16:33:28.351 18984 TRACE neutron.plugins.openvswitch.agent.ovs_neutron_agent six.reraise(self.type_, self.value, self.tb)
2015-03-21 16:33:28.351 18984 TRACE neutron.plugins.openvswitch.agent.ovs_neutron_agent File "/opt/stack/new/neutron/neutron/agent/ovsdb/impl_vsctl.py", line 63, in run_vsctl
2015-03-21 16:33:28.351 18984 TRACE neutron.plugins.openvswitch.agent.ovs_neutron_agent log_fail_as_error=False).rstrip()
2015-03-21 16:33:28.351 18984 TRACE neutron.plugins.openvswitch.agent.ovs_neutron_agent File "/opt/stack/new/neutron/neutron/agent/linux/utils.py", line 135, in execute
2015-03-21 16:33:28.351 18984 TRACE neutron.plugins.openvswitch.agent.ovs_neutron_agent raise RuntimeError(m)
2015-03-21 16:33:28.351 18984 TRACE neutron.plugins.openvswitch.agent.ovs_neutron_agent RuntimeError:
2015-03-21 16:33:28.351 18984 TRACE neutron.plugins.openvswitch.agent.ovs_neutron_agent Command: ['ovs-vsctl', '--timeout=10', '--oneline', '--format=json', '--', '--columns=name,tag', 'list', 'Port', u'patch-tun', u'qr-5b2567eb-b1', u'qr-7f65dad0-7e', u'tap3441ac83-f8', u'tap4d1f6f89-57', u'tap64de22fc-d7', u'tapbeb6fc74-d0']
2015-03-21 16:33:28.351 18984 TRACE neutron.plugins.openvswitch.agent.ovs_neutron_agent Exit code: 1
2015-03-21 16:33:28.351 18984 TRACE neutron.plugins.openvswitch.agent.ovs_neutron_agent Stdin:
2015-03-21 16:33:28.351 18984 TRACE neutron.plugins.openvswitch.agent.ovs_neutron_agent Stdout:
2015-03-21 16:33:28.351 18984 TRACE neutron.plugins.openvswitch.agent.ovs_neutron_agent Stderr: ovs-vsctl: no row "tap4d1f6f89-57" in table Port
2015-03-21 16:33:28.351 18984 TRACE neutron.plugins.openvswitch.agent.ovs_neutron_agent
2015-03-21 16:33:28.351 18984 TRACE neutron.plugins.openvswitch.agent.ovs_neutron_agent

Revision history for this message

Davanum Srinivas (DIMS) (dims-v) wrote on 2015-03-21:

We need to switch TRACE to ERROR in the default config option as we use this only when printing error/exceptions

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2015-03-21: Fix proposed to oslo.log (master)

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

Changed in oslo.log:
assignee:	nobody → Davanum Srinivas (DIMS) (dims-v)
status:	New → In Progress

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2015-05-06: Fix merged to oslo.log (master)

Reviewed: https://review.openstack.org/166537
Committed: https://git.openstack.org/cgit/openstack/oslo.log/commit/?id=27f7fe52fefcb81c5fe01736841d7a20149caf02
Submitter: Jenkins
Branch: master

commit 27f7fe52fefcb81c5fe01736841d7a20149caf02
Author: Davanum Srinivas <email address hidden>
Date: Sat Mar 21 12:56:26 2015 -0400

Change misleading TRACE to ERROR

Tracebacks in logs should be prefixed with the correct log level.

Closes-Bug: #1434851
Change-Id: I8c618e7b8523bcc0e19a9b77c4d2d5984369a04a

Changed in oslo.log:
status:	In Progress → Fix Committed

Doug Hellmann (doug-hellmann) on 2015-06-09

Changed in oslo.log:
milestone:	none → 1.4.0
status:	Fix Committed → Fix Released

Report a bug

This report contains Public information

Everyone can see this information.

You are

Subscribing...

Edit bug mail

Other bug subscribers

Remote bug watches

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