Description of problem:

neutron/server.log shows many times the following networking_odl ERROR while it is actually a warning. Please change this ERROR to WARN:

ERROR networking_odl.journal.periodic_task Failed during periodic task operation journal_recovery.: InvalidRequestError: Object '<OpenDaylightJournal at 0x7fadd4d3b450>' is already attached to session


Version-Release number of selected component (if applicable):
14   -p 2018-12-20.4

How reproducible:
Always

Steps to Reproduce:
1. Install OSP + ODL
2. Check neutron/server.log for ERRORs


Actual results:


*** controller-1: /var/log/containers/neutron/server.log ***

2018-12-24 10:02:09.871 38 INFO networking_odl.journal.periodic_task [req-682c5a23-6441-41e4-bf5d-0df3af33b87c - - - - -] Finished full_sync phase of maintenance task.
2018-12-24 10:02:09.872 38 INFO networking_odl.journal.periodic_task [req-682c5a23-6441-41e4-bf5d-0df3af33b87c - - - - -] Starting journal_recovery phase of periodic task maintenance.
2018-12-24 10:02:09.894 38 DEBUG networking_odl.journal.recovery [req-682c5a23-6441-41e4-bf5d-0df3af33b87c - - - - -] Attempting recovery of journal entry <networking_odl.db.models.OpenDaylightJournal[object at 7fadd4d86050] {seqnum=32, object_type=u'network', object_uuid=u'e845bd10-e12c-486a-bf0e-4f4fa3ca1234', operation=u'update', data={'provider:physical_network': None, 'ipv6_address_scope': None, 'revision_number': 4, 'port_security_enabled': True, 'mtu': 1500, 'id': u'e845bd10-e12c-486a-bf0e-4f4fa3ca1234', 'router:external': True, 'availability_zone_hints': [], 'availability_zones': [u'nova'], 'ipv4_address_scope': None, 'shared': False, 'project_id': u'70b82a4868bd42ccb36261613ac4d178', 'status': u'ACTIVE', 'subnets': [], 'description': u'', 'tags': [], 'updated_at': '2018-12-23T12:46:02Z', 'is_default': False, 'provider:segmentation_id': None, 'name': u'public', 'admin_state_up': True, 'tenant_id': u'70b82a4868bd42ccb36261613ac4d178', 'created_at': '2018-12-23T12:40:48Z', 'provider:network_type': None, 'vlan_transparent': None}, state='failed', retry_count=5, last_retried=datetime.datetime(2018, 12, 23, 12, 46, 3), version_id=13}>. journal_recovery /usr/lib/python2.7/site-packages/networking_odl/journal/recovery.py:39
2018-12-24 10:02:09.895 38 DEBUG networking_odl.common.client [req-682c5a23-6441-41e4-bf5d-0df3af33b87c - - - - -] Sending METHOD (get) URL (http://172.17.1.28:8081/controller/nb/v2/neutron/networks/e845bd10-e12c-486a-bf0e-4f4fa3ca1234) JSON (None) request /usr/lib/python2.7/site-packages/networking_odl/common/client.py:89
2018-12-24 10:02:09.930 38 ERROR networking_odl.journal.periodic_task     ectxt.value = e.inner_exc
2018-12-24 10:02:09.930 38 ERROR networking_odl.journal.periodic_task   File "/usr/lib/python2.7/site-packages/networking_odl/journal/periodic_task.py", line 65, in _execute_op
2018-12-24 10:02:09.930 38 ERROR networking_odl.journal.periodic_task   File "/usr/lib/python2.7/site-packages/neutron_lib/db/api.py", line 136, in wrapped
2018-12-24 10:02:09.930 38 ERROR networking_odl.journal.periodic_task   File "/usr/lib/python2.7/site-packages/neutron_lib/db/api.py", line 140, in wrapped
2018-12-24 10:02:09.930 38 ERROR networking_odl.journal.periodic_task   File "/usr/lib/python2.7/site-packages/neutron_lib/db/api.py", line 233, in wrapped
2018-12-24 10:02:09.930 38 ERROR networking_odl.journal.periodic_task   File "/usr/lib/python2.7/site-packages/oslo_db/api.py", line 142, in wrapper
2018-12-24 10:02:09.930 38 ERROR networking_odl.journal.periodic_task   File "/usr/lib/python2.7/site-packages/oslo_db/api.py", line 154, in wrapper
2018-12-24 10:02:09.930 38 ERROR networking_odl.journal.periodic_task   File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 196, in force_reraise
2018-12-24 10:02:09.930 38 ERROR networking_odl.journal.periodic_task   File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 220, in __exit__
2018-12-24 10:02:09.930 38 ERROR networking_odl.journal.periodic_task     operation(context)
2018-12-24 10:02:09.930 38 ERROR networking_odl.journal.periodic_task [req-682c5a23-6441-41e4-bf5d-0df3af33b87c - - - - -] Failed during periodic task operation journal_recovery.: InvalidRequestError: Object '<OpenDaylightJournal at 0x7fadd4d86050>' is already attached to session '17481' (this is '17490')
2018-12-24 10:02:09.930 38 ERROR networking_odl.journal.periodic_task     return f(*args, **kwargs)
2018-12-24 10:02:09.930 38 ERROR networking_odl.journal.periodic_task     return method(*args, **kwargs)
2018-12-24 10:02:09.930 38 ERROR networking_odl.journal.periodic_task     self.force_reraise()
2018-12-24 10:02:09.930 38 ERROR networking_odl.journal.periodic_task     setattr(e, '_RETRY_EXCEEDED', True)
2018-12-24 10:02:09.930 38 ERROR networking_odl.journal.periodic_task     six.reraise(self.type_, self.value, self.tb)
2018-12-24 10:02:09.930 38 ERROR networking_odl.journal.periodic_task Traceback (most recent call last):
2018-12-24 10:07:09.886 38 INFO networking_odl.journal.periodic_task [req-682c5a23-6441-41e4-bf5d-0df3af33b87c - - - - -] Finished full_sync phase of maintenance task.
2018-12-24 10:07:09.887 38 INFO networking_odl.journal.periodic_task [req-682c5a23-6441-41e4-bf5d-0df3af33b87c - - - - -] Starting journal_recovery phase of periodic task maintenance.
2018-12-24 10:07:09.905 38 DEBUG networking_odl.journal.recovery [req-682c5a23-6441-41e4-bf5d-0df3af33b87c - - - - -] Attempting recovery of journal entry <networking_odl.db.models.OpenDaylightJournal[object at 7fadd4ab8450] {seqnum=32, object_type=u'network', object_uuid=u'e845bd10-e12c-486a-bf0e-4f4fa3ca1234', operation=u'update', data={'provider:physical_network': None, 'ipv6_address_scope': None, 'revision_number': 4, 'port_security_enabled': True, 'mtu': 1500, 'id': u'e845bd10-e12c-486a-bf0e-4f4fa3ca1234', 'router:external': True, 'availability_zone_hints': [], 'availability_zones': [u'nova'], 'ipv4_address_scope': None, 'shared': False, 'project_id': u'70b82a4868bd42ccb36261613ac4d178', 'status': u'ACTIVE', 'subnets': [], 'description': u'', 'tags': [], 'updated_at': '2018-12-23T12:46:02Z', 'is_default': False, 'provider:segmentation_id': None, 'name': u'public', 'admin_state_up': True, 'tenant_id': u'70b82a4868bd42ccb36261613ac4d178', 'created_at': '2018-12-23T12:40:48Z', 'provider:network_type': None, 'vlan_transparent': None}, state='failed', retry_count=5, last_retried=datetime.datetime(2018, 12, 23, 12, 46, 3), version_id=13}>. journal_recovery /usr/lib/python2.7/site-packages/networking_odl/journal/recovery.py:39
2018-12-24 10:07:09.906 38 DEBUG networking_odl.common.client [req-682c5a23-6441-41e4-bf5d-0df3af33b87c - - - - -] Sending METHOD (get) URL (http://172.17.1.28:8081/controller/nb/v2/neutron/networks/e845bd10-e12c-486a-bf0e-4f4fa3ca1234) JSON (None) request /usr/lib/python2.7/site-packages/networking_odl/common/client.py:89
2018-12-24 10:07:09.938 38 ERROR networking_odl.journal.periodic_task     ectxt.value = e.inner_exc
2018-12-24 10:07:09.938 38 ERROR networking_odl.journal.periodic_task   File "/usr/lib/python2.7/site-packages/networking_odl/journal/periodic_task.py", line 65, in _execute_op
2018-12-24 10:07:09.938 38 ERROR networking_odl.journal.periodic_task   File "/usr/lib/python2.7/site-packages/neutron_lib/db/api.py", line 136, in wrapped
2018-12-24 10:07:09.938 38 ERROR networking_odl.journal.periodic_task   File "/usr/lib/python2.7/site-packages/neutron_lib/db/api.py", line 140, in wrapped
2018-12-24 10:07:09.938 38 ERROR networking_odl.journal.periodic_task   File "/usr/lib/python2.7/site-packages/neutron_lib/db/api.py", line 233, in wrapped
2018-12-24 10:07:09.938 38 ERROR networking_odl.journal.periodic_task   File "/usr/lib/python2.7/site-packages/oslo_db/api.py", line 142, in wrapper
2018-12-24 10:07:09.938 38 ERROR networking_odl.journal.periodic_task   File "/usr/lib/python2.7/site-packages/oslo_db/api.py", line 154, in wrapper
2018-12-24 10:07:09.938 38 ERROR networking_odl.journal.periodic_task   File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 196, in force_reraise
2018-12-24 10:07:09.938 38 ERROR networking_odl.journal.periodic_task   File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 220, in __exit__
2018-12-24 10:07:09.938 38 ERROR networking_odl.journal.periodic_task     operation(context)
2018-12-24 10:07:09.938 38 ERROR networking_odl.journal.periodic_task [req-682c5a23-6441-41e4-bf5d-0df3af33b87c - - - - -] Failed during periodic task operation journal_recovery.: InvalidRequestError: Object '<OpenDaylightJournal at 0x7fadd4ab8450>' is already attached to session '17552' (this is '17561')
2018-12-24 10:07:09.938 38 ERROR networking_odl.journal.periodic_task     return f(*args, **kwargs)
2018-12-24 10:07:09.938 38 ERROR networking_odl.journal.periodic_task     return method(*args, **kwargs)
2018-12-24 10:07:09.938 38 ERROR networking_odl.journal.periodic_task     self.force_reraise()
2018-12-24 10:07:09.938 38 ERROR networking_odl.journal.periodic_task     setattr(e, '_RETRY_EXCEEDED', True)
2018-12-24 10:07:09.938 38 ERROR networking_odl.journal.periodic_task     six.reraise(self.type_, self.value, self.tb)
2018-12-24 10:07:09.938 38 ERROR networking_odl.journal.periodic_task Traceback (most recent call last):
2018-12-24 10:12:09.891 38 INFO networking_odl.journal.periodic_task [req-682c5a23-6441-41e4-bf5d-0df3af33b87c - - - - -] Finished full_sync phase of maintenance task.
2018-12-24 10:12:09.892 38 INFO networking_odl.journal.periodic_task [req-682c5a23-6441-41e4-bf5d-0df3af33b87c - - - - -] Starting journal_recovery phase of periodic task maintenance.
2018-12-24 10:12:09.905 38 DEBUG networking_odl.journal.recovery [req-682c5a23-6441-41e4-bf5d-0df3af33b87c - - - - -] Attempting recovery of journal entry <networking_odl.db.models.OpenDaylightJournal[object at 7fadd4d3b450] {seqnum=32, object_type=u'network', object_uuid=u'e845bd10-e12c-486a-bf0e-4f4fa3ca1234', operation=u'update', data={'provider:physical_network': None, 'ipv6_address_scope': None, 'revision_number': 4, 'port_security_enabled': True, 'mtu': 1500, 'id': u'e845bd10-e12c-486a-bf0e-4f4fa3ca1234', 'router:external': True, 'availability_zone_hints': [], 'availability_zones': [u'nova'], 'ipv4_address_scope': None, 'shared': False, 'project_id': u'70b82a4868bd42ccb36261613ac4d178', 'status': u'ACTIVE', 'subnets': [], 'description': u'', 'tags': [], 'updated_at': '2018-12-23T12:46:02Z', 'is_default': False, 'provider:segmentation_id': None, 'name': u'public', 'admin_state_up': True, 'tenant_id': u'70b82a4868bd42ccb36261613ac4d178', 'created_at': '2018-12-23T12:40:48Z', 'provider:network_type': None, 'vlan_transparent': None}, state='failed', retry_count=5, last_retried=datetime.datetime(2018, 12, 23, 12, 46, 3), version_id=13}>. journal_recovery /usr/lib/python2.7/site-packages/networking_odl/journal/recovery.py:39
2018-12-24 10:12:09.906 38 DEBUG networking_odl.common.client [req-682c5a23-6441-41e4-bf5d-0df3af33b87c - - - - -] Sending METHOD (get) URL (http://172.17.1.28:8081/controller/nb/v2/neutron/networks/e845bd10-e12c-486a-bf0e-4f4fa3ca1234) JSON (None) request /usr/lib/python2.7/site-packages/networking_odl/common/client.py:89
2018-12-24 10:12:09.935 38 ERROR networking_odl.journal.periodic_task     ectxt.value = e.inner_exc
2018-12-24 10:12:09.935 38 ERROR networking_odl.journal.periodic_task   File "/usr/lib/python2.7/site-packages/networking_odl/journal/periodic_task.py", line 65, in _execute_op
2018-12-24 10:12:09.935 38 ERROR networking_odl.journal.periodic_task   File "/usr/lib/python2.7/site-packages/neutron_lib/db/api.py", line 136, in wrapped
2018-12-24 10:12:09.935 38 ERROR networking_odl.journal.periodic_task   File "/usr/lib/python2.7/site-packages/neutron_lib/db/api.py", line 140, in wrapped
2018-12-24 10:12:09.935 38 ERROR networking_odl.journal.periodic_task   File "/usr/lib/python2.7/site-packages/neutron_lib/db/api.py", line 233, in wrapped
2018-12-24 10:12:09.935 38 ERROR networking_odl.journal.periodic_task   File "/usr/lib/python2.7/site-packages/oslo_db/api.py", line 142, in wrapper
2018-12-24 10:12:09.935 38 ERROR networking_odl.journal.periodic_task   File "/usr/lib/python2.7/site-packages/oslo_db/api.py", line 154, in wrapper
2018-12-24 10:12:09.935 38 ERROR networking_odl.journal.periodic_task   File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 196, in force_reraise
2018-12-24 10:12:09.935 38 ERROR networking_odl.journal.periodic_task   File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 220, in __exit__
2018-12-24 10:12:09.935 38 ERROR networking_odl.journal.periodic_task     operation(context)
2018-12-24 10:12:09.935 38 ERROR networking_odl.journal.periodic_task [req-682c5a23-6441-41e4-bf5d-0df3af33b87c - - - - -] Failed during periodic task operation journal_recovery.: InvalidRequestError: Object '<OpenDaylightJournal at 0x7fadd4d3b450>' is already attached to session '17623' (this is '17632')
2018-12-24 10:12:09.935 38 ERROR networking_odl.journal.periodic_task     return f(*args, **kwargs)
2018-12-24 10:12:09.935 38 ERROR networking_odl.journal.periodic_task     return method(*args, **kwargs)
2018-12-24 10:12:09.935 38 ERROR networking_odl.journal.periodic_task     self.force_reraise()
2018-12-24 10:12:09.935 38 ERROR networking_odl.journal.periodic_task     setattr(e, '_RETRY_EXCEEDED', True)
2018-12-24 10:12:09.935 38 ERROR networking_odl.journal.periodic_task     six.reraise(self.type_, self.value, self.tb)
2018-12-24 10:12:09.935 38 ERROR networking_odl.journal.periodic_task Traceback (most recent call last):

Expected results:
If it's not a real ERROR, use WARN instead.

Additional info: