Bug 1552073 - configure ovsdbapp logging to use ovirt-provider-ovn.log
Summary: configure ovsdbapp logging to use ovirt-provider-ovn.log
Keywords:
Status: CLOSED CURRENTRELEASE
Alias: None
Product: ovirt-provider-ovn
Classification: oVirt
Component: provider
Version: unspecified
Hardware: Unspecified
OS: Unspecified
medium
medium
Target Milestone: ovirt-4.2.2
: ---
Assignee: Marcin Mirecki
QA Contact: Mor
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2018-03-06 12:58 UTC by Mor
Modified: 2018-03-29 11:06 UTC (History)
5 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2018-03-29 11:06:46 UTC
oVirt Team: Network
Embargoed:
rule-engine: ovirt-4.2+


Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
oVirt gerrit 88539 0 master MERGED Configure logging for ovsdbapp 2018-03-13 08:28:17 UTC

Description Mor 2018-03-06 12:58:08 UTC
Description of problem:
If ovsdbapp throws errors/exceptions, they are logged in journalctl/syslog. There should be an option configure ovsdbapp logging to ovirt-provider-ovn.log, so we won't miss important errors/exceptions when looking at this log.

Version-Release number of selected component (if applicable):
RHV 4.2.2.2-0.1.el7

Comment 1 Dan Kenigsberg 2018-03-06 21:01:09 UTC
Can you share an example of a syslogged exception?

Comment 2 Marcin Mirecki 2018-03-07 07:42:01 UTC
An example would be a failed ovs db transaction (as in the case of the unicode bug). Ovsdbapp retrieves the error from ovsdb and wraps it in its own exception, but without ovsdbapp logging enabled we loose some of the original information.

By default we will only log the error messages.

Comment 3 Mor 2018-03-07 08:33:21 UTC
Sure.

This is an example taken from the journalctl of ovirt-provider-ovn service:

# systemctl status ovirt-provider-ovn

Jan 22 13:12:42 network-ge-2.scl.lab.tlv.redhat.com python[25021]: self.__target(*self.__args, **self.__kwargs)
Jan 22 13:12:42 network-ge-2.scl.lab.tlv.redhat.com python[25021]: File "/usr/lib/python2.7/site-packages/ovsdbapp/backend/ovs_idl/connection.py", line 96, in run
Jan 22 13:12:42 network-ge-2.scl.lab.tlv.redhat.com python[25021]: self.idl.run()
Jan 22 13:12:42 network-ge-2.scl.lab.tlv.redhat.com python[25021]: File "/usr/lib/python2.7/site-packages/ovs/db/idl.py", line 173, in run
Jan 22 13:12:42 network-ge-2.scl.lab.tlv.redhat.com python[25021]: assert not self.txn
Jan 22 13:12:42 network-ge-2.scl.lab.tlv.redhat.com python[25021]: AssertionError

Comment 4 Marcin Mirecki 2018-03-15 11:48:29 UTC
Available in provider 1.2.9

Comment 5 Mor 2018-03-18 07:29:50 UTC
Checked on:
ovirt-provider-ovn-1.2.9-1.el7ev.noarch
RHV 4.2.2-6

Provider restarts its service when detecting exception on ovsdbapp:
2018-03-18 09:24:11,011 requests.packages.urllib3.connectionpool Starting new HTTPS connection (1): network-ge-1.scl.lab.tlv.redhat.com
2018-03-18 09:24:11,286 root Uncaught exception
Traceback (most recent call last):
  File "/usr/share/ovirt-provider-ovn/ovirt_provider_ovn.py", line 62, in run_with_except_hook
    run_original(*args2, **kwargs2)
  File "/usr/lib64/python2.7/threading.py", line 765, in run
    self.__target(*self.__args, **self.__kwargs)
  File "/usr/lib/python2.7/site-packages/ovsdbapp/backend/ovs_idl/connection.py", line 96, in run
    assert False ## DELETE
AssertionError
2018-03-18 09:24:11,288 root Irrecoverable error. Exiting!
2018-03-18 09:24:13,247 root Starting server
2018-03-18 09:24:13,248 root Version: 1.2.9-1
2018-03-18 09:24:13,248 root Build date: 20180313095726
2018-03-18 09:24:13,248 root Githash: 135935e

In logger.conf we supply 'qualname'. I don't see it in the exception log. Does it make sense?

logger.conf:
[logger_ovsdbapp]
level=ERROR
handlers=logfile
propagate=0
qualname=ovsdbapp

Comment 6 Marcin Mirecki 2018-03-19 08:31:23 UTC
This is an exception in ovsdbapp code, but it is not logged by ovsdbapp code.
Ovsdbapp does not catch it, so it crashes the ovsdbapp transaction thread, making ovsdbapp unusable. To prevent this have a hook in the provider code that detects and reports such situations, so this exception is logged by the provider.
The same hook will shutdown the provider, which will then be restarted by systemd. This is prefered to trying to fix ovsdbapp.

Comment 7 Mor 2018-03-19 08:53:06 UTC
Just noting: 
'root' is the default logger which ovirt-provider-ovn uses, just in case we find messages/errors from this source.

Comment 8 Sandro Bonazzola 2018-03-29 11:06:46 UTC
This bugzilla is included in oVirt 4.2.2 release, published on March 28th 2018.

Since the problem described in this bug report should be
resolved in oVirt 4.2.2 release, it has been closed with a resolution of CURRENT RELEASE.

If the solution does not work for you, please open a new bug report.


Note You need to log in before you can comment on or make changes to this bug.