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 -- Mailing list: https://launchpad.net/~yahoo-eng-team Post to : yahoo-eng-team@lists.launchpad.net Unsubscribe : https://launchpad.net/~yahoo-eng-team More help : https://help.launchpad.net/ListHelp
