Public bug reported:
While debugging an internal issue, the create_router() from the
ovn_l3/plugin.py was raising an exception and as part of the handling of
this exception it was logging an ERROR but, there was no traceback which
makes it really hard to figure out where this error is being raised even
in with debug mode enabled. For example, that's the logs:
['neutron.services.ovn_l3.plugin.RouterAvailabilityZoneMixin._process_az_request-13770945',
'neutron.services.ovn_l3.plugin.OVNL3RouterPlugin.create_router_precommit-181103']
for router, precommit_create _notify_loop
/usr/lib/python3.9/site-packages/neutron_lib/callbacks/manager.py:192
2023-06-26 10:11:39.037 30 DEBUG neutron.db.ovn_revision_numbers_db
[req-18ddc15b-8b4e-4c3c-a360-1d6c10680b39 46d4bcf86b0a4de691d824308920146c
b867c3a5edc8442c946948014a351985 - default default] create_initial_revision
uuid=9969c69e-ca2f-4f6d-bdfd-74cf1febda83, type=routers, rev=-1
create_initial_revision
/usr/lib/python3.9/site-packages/neutron/db/ovn_revision_numbers_db.py:104
2023-06-26 10:11:39.159 30 DEBUG neutron_lib.callbacks.manager
[req-18ddc15b-8b4e-4c3c-a360-1d6c10680b39 46d4bcf86b0a4de691d824308920146c
b867c3a5edc8442c946948014a351985 - default default] Notify callbacks [] for
router, after_create _notify_loop
/usr/lib/python3.9/site-packages/neutron_lib/callbacks/manager.py:192
2023-06-26 10:11:39.160 30 INFO
neutron.plugins.ml2.drivers.ovn.mech_driver.ovsdb.extensions.qos
[req-18ddc15b-8b4e-4c3c-a360-1d6c10680b39 46d4bcf86b0a4de691d824308920146c
b867c3a5edc8442c946948014a351985 - default default] Starting
OVNClientQosExtension
2023-06-26 10:11:39.210 30 ERROR neutron.services.ovn_l3.plugin
[req-18ddc15b-8b4e-4c3c-a360-1d6c10680b39 46d4bcf86b0a4de691d824308920146c
b867c3a5edc8442c946948014a351985 - default default] Unable to create lrouter
for 9969c69e-ca2f-4f6d-bdfd-74cf1febda83:
neutron_lib.exceptions.l3.RouterNotFound: Router
9969c69e-ca2f-4f6d-bdfd-74cf1febda83 could not be found
2023-06-26 10:11:39.219 30 DEBUG neutron_lib.callbacks.manager
[req-18ddc15b-8b4e-4c3c-a360-1d6c10680b39 46d4bcf86b0a4de691d824308920146c
b867c3a5edc8442c946948014a351985 - default default] Notify callbacks [] for
router, before_delete _notify_loop
/usr/lib/python3.9/site-packages/neutron_lib/callbacks/manager.py:192
2023-06-26 10:11:39.386 32 DEBUG neutron.wsgi [-] (32) accepted
('fd00:fd00:fd00:2000::399', 33076, 0, 0) server
/usr/lib/python3.9/site-packages/eventlet/wsgi.py:992
2023-06-26 10:11:39.389 32 INFO neutron.wsgi [-] fd00:fd00:fd00:2000::399 "GET
/ HTTP/1.1" status: 200 len: 244 time: 0.0014989
2023-06-26 10:11:39.406 30 DEBUG neutron_lib.callbacks.manager
[req-18ddc15b-8b4e-4c3c-a360-1d6c10680b39 46d4bcf86b0a4de691d824308920146c
b867c3a5edc8442c946948014a351985 - default default] Notify callbacks [] for
router, precommit_delete _notify_loop
/usr/lib/python3.9/site-packages/neutron_lib/callbacks/manager.py:192
2023-06-26 10:11:39.471 30 DEBUG neutron_lib.callbacks.manager
[req-18ddc15b-8b4e-4c3c-a360-1d6c10680b39 46d4bcf86b0a4de691d824308920146c
b867c3a5edc8442c946948014a351985 - default default] Notify callbacks [] for
router, after_delete _notify_loop
/usr/lib/python3.9/site-packages/neutron_lib/callbacks/manager.py:192
2023-06-26 10:11:39.472 30 DEBUG
neutron.api.rpc.agentnotifiers.l3_rpc_agent_api
[req-18ddc15b-8b4e-4c3c-a360-1d6c10680b39 46d4bcf86b0a4de691d824308920146c
b867c3a5edc8442c946948014a351985 - default default] Fanout notify agent at
l3_agent the message router_deleted on router
9969c69e-ca2f-4f6d-bdfd-74cf1febda83 _notification_fanout
/usr/lib/python3.9/site-packages/neutron/api/rpc/agentnotifiers/l3_rpc_agent_api.py:118
2023-06-26 10:11:39.549 30 INFO neutron.api.v2.resource
[req-18ddc15b-8b4e-4c3c-a360-1d6c10680b39 46d4bcf86b0a4de691d824308920146c
b867c3a5edc8442c946948014a351985 - default default] create failed (client
error): The resource could not be found.
As you can see the error is:
46d4bcf86b0a4de691d824308920146c b867c3a5edc8442c946948014a351985 -
default default] Unable to create lrouter for
9969c69e-ca2f-4f6d-bdfd-74cf1febda83:
neutron_lib.exceptions.l3.RouterNotFound: Router
9969c69e-ca2f-4f6d-bdfd-74cf1febda83 could not be found
But there's no traceback to know where this error has originally being
raised. The create_router() method does a many things and it's very
difficult to figure this out without the traceback.
This LP is about improving the logs for that module in general as I see
other parts where nothing is being logged when things goes bad.
** Affects: neutron
Importance: Undecided
Status: New
--
You received this bug notification because you are a member of Yahoo!
Engineering Team, which is subscribed to neutron.
https://bugs.launchpad.net/bugs/2025246
Title:
[OVN] Improve log for the exception handling of ovn_l3/plugin.py
Status in neutron:
New
Bug description:
While debugging an internal issue, the create_router() from the
ovn_l3/plugin.py was raising an exception and as part of the handling
of this exception it was logging an ERROR but, there was no traceback
which makes it really hard to figure out where this error is being
raised even in with debug mode enabled. For example, that's the logs:
['neutron.services.ovn_l3.plugin.RouterAvailabilityZoneMixin._process_az_request-13770945',
'neutron.services.ovn_l3.plugin.OVNL3RouterPlugin.create_router_precommit-181103']
for router, precommit_create _notify_loop
/usr/lib/python3.9/site-packages/neutron_lib/callbacks/manager.py:192
2023-06-26 10:11:39.037 30 DEBUG neutron.db.ovn_revision_numbers_db
[req-18ddc15b-8b4e-4c3c-a360-1d6c10680b39 46d4bcf86b0a4de691d824308920146c
b867c3a5edc8442c946948014a351985 - default default] create_initial_revision
uuid=9969c69e-ca2f-4f6d-bdfd-74cf1febda83, type=routers, rev=-1
create_initial_revision
/usr/lib/python3.9/site-packages/neutron/db/ovn_revision_numbers_db.py:104
2023-06-26 10:11:39.159 30 DEBUG neutron_lib.callbacks.manager
[req-18ddc15b-8b4e-4c3c-a360-1d6c10680b39 46d4bcf86b0a4de691d824308920146c
b867c3a5edc8442c946948014a351985 - default default] Notify callbacks [] for
router, after_create _notify_loop
/usr/lib/python3.9/site-packages/neutron_lib/callbacks/manager.py:192
2023-06-26 10:11:39.160 30 INFO
neutron.plugins.ml2.drivers.ovn.mech_driver.ovsdb.extensions.qos
[req-18ddc15b-8b4e-4c3c-a360-1d6c10680b39 46d4bcf86b0a4de691d824308920146c
b867c3a5edc8442c946948014a351985 - default default] Starting
OVNClientQosExtension
2023-06-26 10:11:39.210 30 ERROR neutron.services.ovn_l3.plugin
[req-18ddc15b-8b4e-4c3c-a360-1d6c10680b39 46d4bcf86b0a4de691d824308920146c
b867c3a5edc8442c946948014a351985 - default default] Unable to create lrouter
for 9969c69e-ca2f-4f6d-bdfd-74cf1febda83:
neutron_lib.exceptions.l3.RouterNotFound: Router
9969c69e-ca2f-4f6d-bdfd-74cf1febda83 could not be found
2023-06-26 10:11:39.219 30 DEBUG neutron_lib.callbacks.manager
[req-18ddc15b-8b4e-4c3c-a360-1d6c10680b39 46d4bcf86b0a4de691d824308920146c
b867c3a5edc8442c946948014a351985 - default default] Notify callbacks [] for
router, before_delete _notify_loop
/usr/lib/python3.9/site-packages/neutron_lib/callbacks/manager.py:192
2023-06-26 10:11:39.386 32 DEBUG neutron.wsgi [-] (32) accepted
('fd00:fd00:fd00:2000::399', 33076, 0, 0) server
/usr/lib/python3.9/site-packages/eventlet/wsgi.py:992
2023-06-26 10:11:39.389 32 INFO neutron.wsgi [-] fd00:fd00:fd00:2000::399
"GET / HTTP/1.1" status: 200 len: 244 time: 0.0014989
2023-06-26 10:11:39.406 30 DEBUG neutron_lib.callbacks.manager
[req-18ddc15b-8b4e-4c3c-a360-1d6c10680b39 46d4bcf86b0a4de691d824308920146c
b867c3a5edc8442c946948014a351985 - default default] Notify callbacks [] for
router, precommit_delete _notify_loop
/usr/lib/python3.9/site-packages/neutron_lib/callbacks/manager.py:192
2023-06-26 10:11:39.471 30 DEBUG neutron_lib.callbacks.manager
[req-18ddc15b-8b4e-4c3c-a360-1d6c10680b39 46d4bcf86b0a4de691d824308920146c
b867c3a5edc8442c946948014a351985 - default default] Notify callbacks [] for
router, after_delete _notify_loop
/usr/lib/python3.9/site-packages/neutron_lib/callbacks/manager.py:192
2023-06-26 10:11:39.472 30 DEBUG
neutron.api.rpc.agentnotifiers.l3_rpc_agent_api
[req-18ddc15b-8b4e-4c3c-a360-1d6c10680b39 46d4bcf86b0a4de691d824308920146c
b867c3a5edc8442c946948014a351985 - default default] Fanout notify agent at
l3_agent the message router_deleted on router
9969c69e-ca2f-4f6d-bdfd-74cf1febda83 _notification_fanout
/usr/lib/python3.9/site-packages/neutron/api/rpc/agentnotifiers/l3_rpc_agent_api.py:118
2023-06-26 10:11:39.549 30 INFO neutron.api.v2.resource
[req-18ddc15b-8b4e-4c3c-a360-1d6c10680b39 46d4bcf86b0a4de691d824308920146c
b867c3a5edc8442c946948014a351985 - default default] create failed (client
error): The resource could not be found.
As you can see the error is:
46d4bcf86b0a4de691d824308920146c b867c3a5edc8442c946948014a351985 -
default default] Unable to create lrouter for
9969c69e-ca2f-4f6d-bdfd-74cf1febda83:
neutron_lib.exceptions.l3.RouterNotFound: Router
9969c69e-ca2f-4f6d-bdfd-74cf1febda83 could not be found
But there's no traceback to know where this error has originally being
raised. The create_router() method does a many things and it's very
difficult to figure this out without the traceback.
This LP is about improving the logs for that module in general as I
see other parts where nothing is being logged when things goes bad.
To manage notifications about this bug go to:
https://bugs.launchpad.net/neutron/+bug/2025246/+subscriptions
--
Mailing list: https://launchpad.net/~yahoo-eng-team
Post to : [email protected]
Unsubscribe : https://launchpad.net/~yahoo-eng-team
More help : https://help.launchpad.net/ListHelp
