_exec_once_mutex_lock.md

Traceback (most recent call first):                                                                                                                                                                     [44/1997]
  <built-in method __enter__ of _thread.lock object at remote 0x7f8e021156c0>
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/event/attr.py", line 284, in exec_once
    with self._exec_once_mutex:
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/pool/base.py", line 649, in __connect
    ).exec_once(self.connection, self)
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/pool/base.py", line 437, in __init__
    self.__connect(first_connect_check=True)
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/pool/base.py", line 308, in _create_connection
    return _ConnectionRecord(self)
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/pool/impl.py", line 238, in _do_get
    return self._create_connection()
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/pool/base.py", line 492, in checkout
    rec = pool._do_get()
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/pool/base.py", line 760, in _checkout
    fairy = _ConnectionRecord.checkout(pool)
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/pool/base.py", line 303, in unique_connection
    return _ConnectionFairy._checkout(self)
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/engine/base.py", line 2265, in _wrap_pool_connect
    return fn()
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/engine/base.py", line 2296, in raw_connection
    self.pool.unique_connection, _connection
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/engine/base.py", line 466, in _revalidate_connection
    self.__connection = self.engine.raw_connection(_connection=self)
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/engine/base.py", line 388, in connection
    return self._revalidate_connection()
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/engine/default.py", line 347, in check_unicode
    cursor = connection.connection.cursor()
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/engine/default.py", line 379, in <setcomp>
    results = {check_unicode(test) for test in tests}
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/engine/default.py", line 379, in _check_unicode_returns
    results = {check_unicode(test) for test in tests}
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/dialects/mysql/mysqldb.py", line 163, in _check_unicode_returns
    connection, additional_tests
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/engine/default.py", line 309, in initialize
    self.returns_unicode_strings = self._check_unicode_returns(connection)
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/dialects/mysql/base.py", line 2383, in initialize
    default.DefaultDialect.initialize(self, connection)
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/engine/strategies.py", line 199, in first_connect
    dialect.initialize(c)
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/util/langhelpers.py", line 1443, in go
    return once_fn(*arg, **kw)
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/event/attr.py", line 297, in __call__
    fn(*args, **kw)
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/event/attr.py", line 287, in exec_once
    self(*args, **kw)
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/pool/base.py", line 649, in __connect
    ).exec_once(self.connection, self)
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/pool/base.py", line 437, in __init__
    self.__connect(first_connect_check=True)
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/pool/base.py", line 308, in _create_connection
    return _ConnectionRecord(self)
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/pool/impl.py", line 238, in _do_get
    return self._create_connection()
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/pool/base.py", line 492, in checkout
    rec = pool._do_get()
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/pool/base.py", line 760, in _checkout
    fairy = _ConnectionRecord.checkout(pool)
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/pool/base.py", line 363, in connect
    return _ConnectionFairy._checkout(self)
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/engine/base.py", line 2265, in _wrap_pool_connect
    return fn()
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/engine/base.py", line 2229, in _contextual_connect
    self._wrap_pool_connect(self.pool.connect, None),
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/orm/session.py", line 431, in _connection_for_bind
    conn = bind._contextual_connect()
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/orm/session.py", line 1130, in _connection_for_bind
    engine, execution_options
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/orm/session.py", line 1124, in connection
    execution_options=execution_options,
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/orm/query.py", line 3345, in _connection_from_session
    conn = self.session.connection(**kw)
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/orm/query.py", line 3367, in _get_bind_args
    mapper=self._bind_mapper(), clause=querycontext.statement, **kw
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/orm/query.py", line 3352, in _execute_and_instances
    querycontext, self._connection_from_session, close_with_result=True
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/orm/query.py", line 3330, in __iter__
    return self._execute_and_instances(context)
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/orm/query.py", line 3018, in __getitem__
    return list(res)
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/orm/query.py", line 3228, in first
    ret = list(self[0:1])
  File "/usr/local/lib/python3.7/site-packages/airflow/models/taskinstance.py", line 549, in refresh_from_db
    ti = qry.first()

This process S 97 99 Thu Jan 26 04:07:05 2023 /usr/local/bin/python3.7 /usr/local/bin/airflow run dag_id task_id date --raw -sd /tmp/test.py is stuck with the above stacktrace

STAT  PPID   PID                  STARTED COMMAND
Ss       0     1 Thu Jan 26 04:06:58 2023 dumb-init -- entrypoint airflow run dag_id task_id date --local -sd /tmp/test.py
Ss       1     7 Thu Jan 26 04:06:58 2023 sudo -E -H -u airflow_sudoable PYTHONPATH=/srv/airflow/pythonpath  airflow run dag_id task_id date --local -sd /tmp/test.py
Sl       7    44 Thu Jan 26 04:07:03 2023 /usr/local/bin/python3.7 /usr/local/bin/airflow run dag_id task_id date --local -sd /tmp/test.py
Ss      44    97 Thu Jan 26 04:07:05 2023 sudo -E -H -u user PYTHONPATH=/srv/airflow/pythonpath airflow run dag_id task_id date --raw -sd /tmp/test.py -
S       97    99 Thu Jan 26 04:07:05 2023 /usr/local/bin/python3.7 /usr/local/bin/airflow run dag_id task_id date --raw -sd /tmp/test.py

The stuck process /usr/local/bin/python3.7 /usr/local/bin/airflow run dag_id task_id date --raw -sd /tmp/test.py with pid as 99 is spawned by sudo -E -H -u user PYTHONPATH=/srv/airflow/pythonpath airflow run dag_id task_id date --raw -sd /tmp/test.py with pid as 97 via: subprocess.Popen:

    def _read_task_logs(self, stream):
        while True:
            line = stream.readline()
            if isinstance(line, bytes):
                line = line.decode('utf-8')
            if len(line) == 0:
                break
            self.log.info('Job %s: Subtask %s %s',
                          self._task_instance.job_id, self._task_instance.task_id,
                          line.rstrip('\n'))

def start(self, full_cmd):
        proc = subprocess.Popen(
            full_cmd,
            stdout=subprocess.PIPE,
            stderr=subprocess.STDOUT,
            universal_newlines=True,
            close_fds=True,
            env=os.environ.copy(),
            preexec_fn=os.setsid
        )

        # Start daemon thread to read subprocess logging output
        log_reader = threading.Thread(
            target=self._read_task_logs,
            args=(proc.stdout,),
        )
        log_reader.daemon = True
        log_reader.start()

info threads:

running: thread apply all bt, for that blas_thread_server, i am not sure whether it comes from:

Case where there is only 1 thread:

(gdb)
(gdb) info threads
  Id   Target Id         Frame
* 1    Thread 0x7fb36d483080 (LWP 99) "/usr/local/bin/" 0x00007fb36d0587c6 in do_futex_wait.constprop () from target:/lib/x86_64-linux-gnu/libpthread.so.0
(gdb)

py-bt output:

Traceback (most recent call first):
  <built-in method __enter__ of _thread.lock object at remote 0x7fb35c706390>
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/event/attr.py", line 284, in exec_once
    with self._exec_once_mutex:
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/pool/base.py", line 649, in __connect
    ).exec_once(self.connection, self)
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/pool/base.py", line 437, in __init__
    self.__connect(first_connect_check=True)
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/pool/base.py", line 308, in _create_connection
    return _ConnectionRecord(self)
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/pool/impl.py", line 238, in _do_get
    return self._create_connection()
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/pool/base.py", line 492, in checkout
    rec = pool._do_get()
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/pool/base.py", line 760, in _checkout
    fairy = _ConnectionRecord.checkout(pool)
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/pool/base.py", line 303, in unique_connection
    return _ConnectionFairy._checkout(self)
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/engine/base.py", line 2265, in _wrap_pool_connect
    return fn()
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/engine/base.py", line 2296, in raw_connection
    self.pool.unique_connection, _connection
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/engine/base.py", line 466, in _revalidate_connection
    self.__connection = self.engine.raw_connection(_connection=self)
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/engine/base.py", line 388, in connection
    return self._revalidate_connection()
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/engine/default.py", line 347, in check_unicode
    cursor = connection.connection.cursor()
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/engine/default.py", line 379, in <setcomp>
    results = {check_unicode(test) for test in tests}
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/engine/default.py", line 379, in _check_unicode_returns
    results = {check_unicode(test) for test in tests}
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/dialects/mysql/mysqldb.py", line 163, in _check_unicode_returns
    connection, additional_tests
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/engine/default.py", line 309, in initialize
    self.returns_unicode_strings = self._check_unicode_returns(connection)
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/dialects/mysql/base.py", line 2383, in initialize
    default.DefaultDialect.initialize(self, connection)
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/engine/strategies.py", line 199, in first_connect
    dialect.initialize(c)
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/util/langhelpers.py", line 1443, in go
    return once_fn(*arg, **kw)
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/event/attr.py", line 297, in __call__
    fn(*args, **kw)
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/event/attr.py", line 287, in exec_once
    self(*args, **kw)
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/pool/base.py", line 649, in __connect
    ).exec_once(self.connection, self)
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/pool/base.py", line 437, in __init__
    self.__connect(first_connect_check=True)
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/pool/base.py", line 308, in _create_connection
    return _ConnectionRecord(self)
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/pool/impl.py", line 238, in _do_get
    return self._create_connection()
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/pool/base.py", line 492, in checkout
    rec = pool._do_get()
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/pool/base.py", line 760, in _checkout
    fairy = _ConnectionRecord.checkout(pool)
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/pool/base.py", line 363, in connect
    return _ConnectionFairy._checkout(self)
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/engine/base.py", line 2265, in _wrap_pool_connect
    return fn()
  File "/usr/local/lib/python3.7/site-packages/sqlalchemy/engine/base.py", line 2229, in _contextual_connect
    self._wrap_pool_connect(self.pool.connect, None),