Due to a typo in the log message of the exception handler of the policy_driver_manager the handler will throw an erorr when trying to log a message (see below).
The code is found here: https://github.com/openstack/group-based-policy/blob/master/gbpservice/neutron/services/grouppolicy/policy_driver_manager.py#L153
There is an erroneous comma (,) in the LOG.exception call:
This should be:
LOG.exception(
"Policy driver '%(name)s' failed in %(method)s ",
"with sqlalchemy.exc.InvalidRequestError",
{'name': driver.name, 'method': method_name})
LOG.exception(
"Policy driver '%(name)s' failed in %(method)s "
"with sqlalchemy.exc.InvalidRequestError",
{'name': driver.name, 'method': method_name})
2019-03-11 17:18:56,407.407 126742 INFO neutron.wsgi [req-b1c7da4d-f28d-4e2d-b9b0-21167f23befc f4d04555dd314fd09206fea7b6a553eb a76afd71063f474f9e9374f4eb9d919b - default default] 10.200.25.10 "POST /v2.0/grouppolicy/policy_target_groups HTTP/1.1" status: 201 len: 1059 time: 7.2169480
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource [req-29e03214-321a-4860-995d-4b5cb48f0770 f4d04555dd314fd09206fea7b6a553eb a76afd71063f474f9e9374f4eb9d919b - default default] create failed: No details.: TypeError: not all arguments converted during string formatting
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource Traceback (most recent call last):
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource File "/usr/lib/python2.7/site-packages/neutron/api/v2/resource.py", line 98, in resource
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource result = method(request=request, **args)
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource File "/usr/lib/python2.7/site-packages/neutron/api/v2/base.py", line 435, in create
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource return self._create(request, body, **kwargs)
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource File "/usr/lib/python2.7/site-packages/neutron/db/api.py", line 93, in wrapped
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource setattr(e, '_RETRY_EXCEEDED', True)
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 220, in __exit__
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource self.force_reraise()
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 196, in force_reraise
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource six.reraise(self.type_, self.value, self.tb)
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource File "/usr/lib/python2.7/site-packages/neutron/db/api.py", line 89, in wrapped
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource return f(*args, **kwargs)
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource File "/usr/lib/python2.7/site-packages/oslo_db/api.py", line 150, in wrapper
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource ectxt.value = e.inner_exc
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 220, in __exit__
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource self.force_reraise()
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 196, in force_reraise
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource six.reraise(self.type_, self.value, self.tb)
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource File "/usr/lib/python2.7/site-packages/oslo_db/api.py", line 138, in wrapper
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource return f(*args, **kwargs)
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource File "/usr/lib/python2.7/site-packages/neutron/db/api.py", line 128, in wrapped
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource LOG.debug("Retry wrapper got retriable exception: %s", e)
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 220, in __exit__
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource self.force_reraise()
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 196, in force_reraise
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource six.reraise(self.type_, self.value, self.tb)
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource File "/usr/lib/python2.7/site-packages/neutron/db/api.py", line 124, in wrapped
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource return f(*dup_args, **dup_kwargs)
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource File "/usr/lib/python2.7/site-packages/neutron/api/v2/base.py", line 548, in _create
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource obj = do_create(body)
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource File "/usr/lib/python2.7/site-packages/neutron/api/v2/base.py", line 530, in do_create
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource request.context, reservation.reservation_id)
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 220, in __exit__
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource self.force_reraise()
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 196, in force_reraise
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource six.reraise(self.type_, self.value, self.tb)
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource File "/usr/lib/python2.7/site-packages/neutron/api/v2/base.py", line 523, in do_create
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource return obj_creator(request.context, **kwargs)
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource File "/usr/lib/python2.7/site-packages/oslo_log/helpers.py", line 67, in wrapper
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource return method(*args, **kwargs)
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource File "/usr/lib/python2.7/site-packages/neutron/db/api.py", line 163, in wrapped
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource return method(*args, **kwargs)
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource File "/usr/lib/python2.7/site-packages/neutron/db/api.py", line 93, in wrapped
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource setattr(e, '_RETRY_EXCEEDED', True)
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 220, in __exit__
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource self.force_reraise()
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 196, in force_reraise
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource six.reraise(self.type_, self.value, self.tb)
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource File "/usr/lib/python2.7/site-packages/neutron/db/api.py", line 89, in wrapped
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource return f(*args, **kwargs)
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource File "/usr/lib/python2.7/site-packages/oslo_db/api.py", line 150, in wrapper
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource ectxt.value = e.inner_exc
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 220, in __exit__
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource self.force_reraise()
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 196, in force_reraise
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource six.reraise(self.type_, self.value, self.tb)
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource File "/usr/lib/python2.7/site-packages/oslo_db/api.py", line 138, in wrapper
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource return f(*args, **kwargs)
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource File "/usr/lib/python2.7/site-packages/neutron/db/api.py", line 128, in wrapped
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource LOG.debug("Retry wrapper got retriable exception: %s", e)
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 220, in __exit__
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource self.force_reraise()
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 196, in force_reraise
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource six.reraise(self.type_, self.value, self.tb)
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource File "/usr/lib/python2.7/site-packages/neutron/db/api.py", line 124, in wrapped
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource return f(*dup_args, **dup_kwargs)
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource File "/usr/lib/python2.7/site-packages/gbpservice/neutron/extensions/__init__.py", line 34, in inner
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource return f(self, context, *args, **kwargs)
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource File "/usr/lib/python2.7/site-packages/gbpservice/neutron/services/grouppolicy/plugin.py", line 483, in create_policy_target
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource policy_context)
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource File "/usr/lib/python2.7/site-packages/gbpservice/neutron/services/grouppolicy/policy_driver_manager.py", line 193, in create_policy_target_precommit
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource self._call_on_drivers("create_policy_target_precommit", context)
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource File "/usr/lib/python2.7/site-packages/gbpservice/neutron/services/grouppolicy/policy_driver_manager.py", line 159, in _call_on_drivers
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource {'name': driver.name, 'method': method_name})
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource File "/usr/lib64/python2.7/logging/__init__.py", line 1446, in error
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource self.logger.error(msg, *args, **kwargs)
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource File "/usr/lib64/python2.7/logging/__init__.py", line 1175, in error
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource self._log(ERROR, msg, args, **kwargs)
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource File "/usr/lib64/python2.7/logging/__init__.py", line 1268, in _log
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource self.handle(record)
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource File "/usr/lib64/python2.7/logging/__init__.py", line 1278, in handle
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource self.callHandlers(record)
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource File "/usr/lib64/python2.7/logging/__init__.py", line 1318, in callHandlers
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource hdlr.handle(record)
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource File "/usr/lib64/python2.7/logging/__init__.py", line 749, in handle
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource self.emit(record)
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource File "build/bdist.linux-x86_64/egg/fluent/handler.py", line 237, in emit
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource data = self.format(record)
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource File "/usr/lib64/python2.7/logging/__init__.py", line 724, in format
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource return fmt.format(record)
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource File "/usr/lib/python2.7/site-packages/oslo_log/formatters.py", line 279, in format
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource message = {'message': record.getMessage(),
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource File "/usr/lib64/python2.7/logging/__init__.py", line 328, in getMessage
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource msg = msg % self.args
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource TypeError: not all arguments converted during string formatting
2019-03-11 17:18:56,902.902 126742 ERROR neutron.api.v2.resource
2019-03-11 17:18:56,905.905 126742 INFO neutron.wsgi [req-29e03214-321a-4860-995d-4b5cb48f0770 f4d04555dd314fd09206fea7b6a553eb a76afd71063f474f9e9374f4eb9d919b - default default] 10.200.25.10 "POST /v2.0/grouppolicy/policy_targets HTTP/1.1" status: 500 len: 363 time: 0.4880722
