yahoo-eng-team team mailing list archive

Thread
Date
[Bug 2008858] [NEW] Call the api and do not return for a long time

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: ZhouHeng <2008858@xxxxxxxxxxxxxxxxxx>
Date: Wed, 01 Mar 2023 06:21:06 -0000
Reply-to: Bug 2008858 <2008858@xxxxxxxxxxxxxxxxxx>
Sender: noreply@xxxxxxxxxxxxx
Public bug reported:

I have an environment for using ovn.

I found that sometimes when calling the api, it can return quickly, and sometimes it never returns.
This phenomenon also occurs when calling the same interface.
There is no error when the interface does not return.


After tracing the log, we found that some of the neutral-server processes reported errors when they were just started
from log, I found:
when we call post_fork_initialization and add_node to db failed. 
After analyzing the code, we can see that the error process did not connect to ovn-nb/sb and not set _post_fork_event.
However, the api process does not exit, and can receive api requests. When processing requests requires access to ovn-nb, it will always wait.
It is also difficult to troubleshoot problems. It can throw a wait timeout(=cfg.CONF.ovn.ovsdb_connection_timeout) to help troubleshoot problems.


error log:

2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines [None req-2537f423-6d58-48ef-995f-b6f1e1bac8d9 - - - - -] Database connection was found disconnected; reconnecting: oslo_db.exception.DBConnectionError: (pymysql.err.OperationalError) (2013, 'Lost connection to MySQL server during query') [SQL: 'SELECT 1'] (Background on this error at: http://sqlalche.me/e/e3q8)
2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines Traceback (most recent call last):
2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines   File "/var/lib/kolla/venv/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 1193, in _execute_context
2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines     context)
2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines   File "/var/lib/kolla/venv/lib/python3.6/site-packages/sqlalchemy/engine/default.py", line 509, in do_execute
2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines     cursor.execute(statement, parameters)
2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines   File "/var/lib/kolla/venv/lib/python3.6/site-packages/pymysql/cursors.py", line 170, in execute
2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines     result = self._query(query)
2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines   File "/var/lib/kolla/venv/lib/python3.6/site-packages/pymysql/cursors.py", line 328, in _query
2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines     conn.query(q)
2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines   File "/var/lib/kolla/venv/lib/python3.6/site-packages/pymysql/connections.py", line 516, in query
2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines     self._affected_rows = self._read_query_result(unbuffered=unbuffered)
2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines   File "/var/lib/kolla/venv/lib/python3.6/site-packages/pymysql/connections.py", line 727, in _read_query_result
2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines     result.read()
2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines   File "/var/lib/kolla/venv/lib/python3.6/site-packages/pymysql/connections.py", line 1066, in read
2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines     first_packet = self.connection._read_packet()
2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines   File "/var/lib/kolla/venv/lib/python3.6/site-packages/pymysql/connections.py", line 656, in _read_packet
2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines     packet_header = self._read_bytes(4)
2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines   File "/var/lib/kolla/venv/lib/python3.6/site-packages/pymysql/connections.py", line 702, in _read_bytes
2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines     CR.CR_SERVER_LOST, "Lost connection to MySQL server during query")
2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines pymysql.err.OperationalError: (2013, 'Lost connection to MySQL server during query')
2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines 
2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines The above exception was the direct cause of the following exception:
2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines 
2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines Traceback (most recent call last):
2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines   File "/var/lib/kolla/venv/lib/python3.6/site-packages/oslo_db/sqlalchemy/engines.py", line 73, in _connect_ping_listener
2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines     connection.scalar(select([1]))
2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines   File "/var/lib/kolla/venv/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 880, in scalar
2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines     return self.execute(object, *multiparams, **params).scalar()
2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines   File "/var/lib/kolla/venv/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 948, in execute
2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines     return meth(self, multiparams, params)
2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines   File "/var/lib/kolla/venv/lib/python3.6/site-packages/sqlalchemy/sql/elements.py", line 269, in _execute_on_connection
2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines     return connection._execute_clauseelement(self, multiparams, params)
2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines   File "/var/lib/kolla/venv/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 1060, in _execute_clauseelement
2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines     compiled_sql, distilled_params
2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines   File "/var/lib/kolla/venv/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 1200, in _execute_context
2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines     context)
2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines   File "/var/lib/kolla/venv/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 1409, in _handle_dbapi_exception
2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines     util.raise_from_cause(newraise, exc_info)
2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines   File "/var/lib/kolla/venv/lib/python3.6/site-packages/sqlalchemy/util/compat.py", line 265, in raise_from_cause
2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines     reraise(type(exception), exception, tb=exc_tb, cause=cause)
2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines   File "/var/lib/kolla/venv/lib/python3.6/site-packages/sqlalchemy/util/compat.py", line 248, in reraise
2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines     raise value.with_traceback(tb)
2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines   File "/var/lib/kolla/venv/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 1193, in _execute_context
2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines     context)
2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines   File "/var/lib/kolla/venv/lib/python3.6/site-packages/sqlalchemy/engine/default.py", line 509, in do_execute
2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines     cursor.execute(statement, parameters)
2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines   File "/var/lib/kolla/venv/lib/python3.6/site-packages/pymysql/cursors.py", line 170, in execute
2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines     result = self._query(query)
2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines   File "/var/lib/kolla/venv/lib/python3.6/site-packages/pymysql/cursors.py", line 328, in _query
2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines     conn.query(q)
2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines   File "/var/lib/kolla/venv/lib/python3.6/site-packages/pymysql/connections.py", line 516, in query
2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines     self._affected_rows = self._read_query_result(unbuffered=unbuffered)
2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines   File "/var/lib/kolla/venv/lib/python3.6/site-packages/pymysql/connections.py", line 727, in _read_query_result
2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines     result.read()
2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines   File "/var/lib/kolla/venv/lib/python3.6/site-packages/pymysql/connections.py", line 1066, in read
2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines     first_packet = self.connection._read_packet()
2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines   File "/var/lib/kolla/venv/lib/python3.6/site-packages/pymysql/connections.py", line 656, in _read_packet
2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines     packet_header = self._read_bytes(4)
2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines   File "/var/lib/kolla/venv/lib/python3.6/site-packages/pymysql/connections.py", line 702, in _read_bytes
2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines     CR.CR_SERVER_LOST, "Lost connection to MySQL server during query")
2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines oslo_db.exception.DBConnectionError: (pymysql.err.OperationalError) (2013, 'Lost connection to MySQL server during query') [SQL: 'SELECT 1'] (Background on this error at: http://sqlalche.me/e/e3q8)
2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines

** Affects: neutron
     Importance: Undecided
     Assignee: ZhouHeng (zhouhenglc)
         Status: In Progress

-- 
You received this bug notification because you are a member of Yahoo!
Engineering Team, which is subscribed to neutron.
https://bugs.launchpad.net/bugs/2008858

Title:
  Call the api and do not return for a long time

Status in neutron:
  In Progress

Bug description:
  I have an environment for using ovn.

  I found that sometimes when calling the api, it can return quickly, and sometimes it never returns.
  This phenomenon also occurs when calling the same interface.
  There is no error when the interface does not return.

  
  After tracing the log, we found that some of the neutral-server processes reported errors when they were just started
  from log, I found:
  when we call post_fork_initialization and add_node to db failed. 
  After analyzing the code, we can see that the error process did not connect to ovn-nb/sb and not set _post_fork_event.
  However, the api process does not exit, and can receive api requests. When processing requests requires access to ovn-nb, it will always wait.
  It is also difficult to troubleshoot problems. It can throw a wait timeout(=cfg.CONF.ovn.ovsdb_connection_timeout) to help troubleshoot problems.

  
  error log:

  2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines [None req-2537f423-6d58-48ef-995f-b6f1e1bac8d9 - - - - -] Database connection was found disconnected; reconnecting: oslo_db.exception.DBConnectionError: (pymysql.err.OperationalError) (2013, 'Lost connection to MySQL server during query') [SQL: 'SELECT 1'] (Background on this error at: http://sqlalche.me/e/e3q8)
  2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines Traceback (most recent call last):
  2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines   File "/var/lib/kolla/venv/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 1193, in _execute_context
  2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines     context)
  2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines   File "/var/lib/kolla/venv/lib/python3.6/site-packages/sqlalchemy/engine/default.py", line 509, in do_execute
  2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines     cursor.execute(statement, parameters)
  2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines   File "/var/lib/kolla/venv/lib/python3.6/site-packages/pymysql/cursors.py", line 170, in execute
  2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines     result = self._query(query)
  2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines   File "/var/lib/kolla/venv/lib/python3.6/site-packages/pymysql/cursors.py", line 328, in _query
  2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines     conn.query(q)
  2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines   File "/var/lib/kolla/venv/lib/python3.6/site-packages/pymysql/connections.py", line 516, in query
  2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines     self._affected_rows = self._read_query_result(unbuffered=unbuffered)
  2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines   File "/var/lib/kolla/venv/lib/python3.6/site-packages/pymysql/connections.py", line 727, in _read_query_result
  2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines     result.read()
  2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines   File "/var/lib/kolla/venv/lib/python3.6/site-packages/pymysql/connections.py", line 1066, in read
  2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines     first_packet = self.connection._read_packet()
  2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines   File "/var/lib/kolla/venv/lib/python3.6/site-packages/pymysql/connections.py", line 656, in _read_packet
  2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines     packet_header = self._read_bytes(4)
  2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines   File "/var/lib/kolla/venv/lib/python3.6/site-packages/pymysql/connections.py", line 702, in _read_bytes
  2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines     CR.CR_SERVER_LOST, "Lost connection to MySQL server during query")
  2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines pymysql.err.OperationalError: (2013, 'Lost connection to MySQL server during query')
  2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines 
  2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines The above exception was the direct cause of the following exception:
  2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines 
  2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines Traceback (most recent call last):
  2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines   File "/var/lib/kolla/venv/lib/python3.6/site-packages/oslo_db/sqlalchemy/engines.py", line 73, in _connect_ping_listener
  2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines     connection.scalar(select([1]))
  2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines   File "/var/lib/kolla/venv/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 880, in scalar
  2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines     return self.execute(object, *multiparams, **params).scalar()
  2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines   File "/var/lib/kolla/venv/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 948, in execute
  2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines     return meth(self, multiparams, params)
  2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines   File "/var/lib/kolla/venv/lib/python3.6/site-packages/sqlalchemy/sql/elements.py", line 269, in _execute_on_connection
  2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines     return connection._execute_clauseelement(self, multiparams, params)
  2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines   File "/var/lib/kolla/venv/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 1060, in _execute_clauseelement
  2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines     compiled_sql, distilled_params
  2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines   File "/var/lib/kolla/venv/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 1200, in _execute_context
  2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines     context)
  2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines   File "/var/lib/kolla/venv/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 1409, in _handle_dbapi_exception
  2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines     util.raise_from_cause(newraise, exc_info)
  2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines   File "/var/lib/kolla/venv/lib/python3.6/site-packages/sqlalchemy/util/compat.py", line 265, in raise_from_cause
  2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines     reraise(type(exception), exception, tb=exc_tb, cause=cause)
  2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines   File "/var/lib/kolla/venv/lib/python3.6/site-packages/sqlalchemy/util/compat.py", line 248, in reraise
  2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines     raise value.with_traceback(tb)
  2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines   File "/var/lib/kolla/venv/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 1193, in _execute_context
  2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines     context)
  2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines   File "/var/lib/kolla/venv/lib/python3.6/site-packages/sqlalchemy/engine/default.py", line 509, in do_execute
  2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines     cursor.execute(statement, parameters)
  2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines   File "/var/lib/kolla/venv/lib/python3.6/site-packages/pymysql/cursors.py", line 170, in execute
  2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines     result = self._query(query)
  2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines   File "/var/lib/kolla/venv/lib/python3.6/site-packages/pymysql/cursors.py", line 328, in _query
  2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines     conn.query(q)
  2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines   File "/var/lib/kolla/venv/lib/python3.6/site-packages/pymysql/connections.py", line 516, in query
  2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines     self._affected_rows = self._read_query_result(unbuffered=unbuffered)
  2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines   File "/var/lib/kolla/venv/lib/python3.6/site-packages/pymysql/connections.py", line 727, in _read_query_result
  2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines     result.read()
  2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines   File "/var/lib/kolla/venv/lib/python3.6/site-packages/pymysql/connections.py", line 1066, in read
  2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines     first_packet = self.connection._read_packet()
  2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines   File "/var/lib/kolla/venv/lib/python3.6/site-packages/pymysql/connections.py", line 656, in _read_packet
  2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines     packet_header = self._read_bytes(4)
  2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines   File "/var/lib/kolla/venv/lib/python3.6/site-packages/pymysql/connections.py", line 702, in _read_bytes
  2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines     CR.CR_SERVER_LOST, "Lost connection to MySQL server during query")
  2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines oslo_db.exception.DBConnectionError: (pymysql.err.OperationalError) (2013, 'Lost connection to MySQL server during query') [SQL: 'SELECT 1'] (Background on this error at: http://sqlalche.me/e/e3q8)
  2023-02-18 03:40:01.845 14 ERROR oslo_db.sqlalchemy.engines

To manage notifications about this bug go to:
https://bugs.launchpad.net/neutron/+bug/2008858/+subscriptions