← Back to team overview

yahoo-eng-team team mailing list archive

  1. yahoo-eng-team team
  2. Mailing list archive
  3. Message #92550

[Bug 2025246] [NEW] [OVN] Improve log for the exception handling of ovn_l3/plugin.py

  Thread Previous • Date Previous • • Thread Next 
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

Follow ups

  Thread Previous • Date Previous • • Thread Next