wait_c does not gracefully handle EINTR errors (PEP-475)

[Jawshua]

Hello there,

The custom wait_c implementation does not implement EINTR handling in the same way that the standard library does as of Python 3.5 / PEP-475 (automatic retries).

This is at the root of a problem we've seen pop up seemingly at random, and rather upsettingly it was obfuscated behind a completely different error when combined with SQLAlchemy sessions and connection pooling.

Eventually we worked out that the signals from our wall profiler were manifesting as an EINTR error, and that psycopg's wait implementation wasn't retrying when they occur. Swapping to the native Python implementation with PSYCOPG_WAIT_FUNC=wait_poll solves the problem.

The result is an Exception that looks something like this

  File "/app/.venv/lib/python3.11/site-packages/sqlalchemy/orm/session.py", line 2232, in execute
    return self._execute_internal(
           ^^^^^^^^^^^^^^^^^^^^^^^
  File "/app/.venv/lib/python3.11/site-packages/sqlalchemy/orm/session.py", line 2127, in _execute_internal
    result: Result[Any] = compile_state_cls.orm_execute_statement(
                          ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/app/.venv/lib/python3.11/site-packages/sqlalchemy/orm/context.py", line 293, in orm_execute_statement
    result = conn.execute(
             ^^^^^^^^^^^^^
  File "/app/.venv/lib/python3.11/site-packages/sqlalchemy/engine/base.py", line 1413, in execute
    return meth(
           ^^^^^
  File "/app/.venv/lib/python3.11/site-packages/sqlalchemy/sql/elements.py", line 483, in _execute_on_connection
    return connection._execute_clauseelement(
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/app/.venv/lib/python3.11/site-packages/sqlalchemy/engine/base.py", line 1637, in _execute_clauseelement
    ret = self._execute_context(
          ^^^^^^^^^^^^^^^^^^^^^^
  File "/app/.venv/lib/python3.11/site-packages/sqlalchemy/engine/base.py", line 1846, in _execute_context
    return self._exec_single_context(
           ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/app/.venv/lib/python3.11/site-packages/sqlalchemy/engine/base.py", line 1987, in _exec_single_context
    self._handle_dbapi_exception(
  File "/app/.venv/lib/python3.11/site-packages/sqlalchemy/engine/base.py", line 2347, in _handle_dbapi_exception
    raise exc_info[1].with_traceback(exc_info[2])
  File "/app/.venv/lib/python3.11/site-packages/sqlalchemy/engine/base.py", line 1968, in _exec_single_context
    self.dialect.do_execute(
  File "/app/.venv/lib/python3.11/site-packages/sqlalchemy/engine/default.py", line 920, in do_execute
    cursor.execute(statement, parameters)
  File "/app/.venv/lib/python3.11/site-packages/psycopg/cursor.py", line 719, in execute
    self._conn.wait(
  File "/app/.venv/lib/python3.11/site-packages/psycopg/connection.py", line 957, in wait
    return waiting.wait(gen, self.pgconn.socket, timeout=timeout)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "psycopg_binary/_psycopg/waiting.pyx", line 179, in psycopg_binary._psycopg.wait_c
InterruptedError: [Errno 4] Interrupted system call

For posterity, the default FastAPI/SQLAlchemy pattern will result in an Exception that swallows the one above:

    session.close()
  File "/app/.venv/lib/python3.11/site-packages/sqlalchemy/orm/session.py", line 2383, in close
    self._close_impl(invalidate=False)
  File "/app/.venv/lib/python3.11/site-packages/sqlalchemy/orm/session.py", line 2425, in _close_impl
    transaction.close(invalidate)
  File "<string>", line 2, in close
  File "/app/.venv/lib/python3.11/site-packages/sqlalchemy/orm/state_changes.py", line 137, in _go
    ret_value = fn(self, *arg, **kw)
                ^^^^^^^^^^^^^^^^^^^^
  File "/app/.venv/lib/python3.11/site-packages/sqlalchemy/orm/session.py", line 1330, in close
    transaction.close()
  File "/app/.venv/lib/python3.11/site-packages/sqlalchemy/engine/base.py", line 2577, in close
    self._do_close()
  File "/app/.venv/lib/python3.11/site-packages/sqlalchemy/engine/base.py", line 2715, in _do_close
    self._close_impl()
  File "/app/.venv/lib/python3.11/site-packages/sqlalchemy/engine/base.py", line 2701, in _close_impl
    self._connection_rollback_impl()
  File "/app/.venv/lib/python3.11/site-packages/sqlalchemy/engine/base.py", line 2693, in _connection_rollback_impl
    self.connection._rollback_impl()
  File "/app/.venv/lib/python3.11/site-packages/sqlalchemy/engine/base.py", line 1117, in _rollback_impl
    self._handle_dbapi_exception(e, None, None, None, None)
  File "/app/.venv/lib/python3.11/site-packages/sqlalchemy/engine/base.py", line 2344, in _handle_dbapi_exception
    raise sqlalchemy_exception.with_traceback(exc_info[2]) from e
  File "/app/.venv/lib/python3.11/site-packages/sqlalchemy/engine/base.py", line 1115, in _rollback_impl
    self.engine.dialect.do_rollback(self.connection)
  File "/app/.venv/lib/python3.11/site-packages/sqlalchemy/engine/default.py", line 693, in do_rollback
    dbapi_connection.rollback()
  File "/app/.venv/lib/python3.11/site-packages/psycopg/connection.py", line 889, in rollback
    self.wait(self._rollback_gen())
  File "/app/.venv/lib/python3.11/site-packages/psycopg/connection.py", line 957, in wait
    return waiting.wait(gen, self.pgconn.socket, timeout=timeout)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "psycopg_binary/_psycopg/waiting.pyx", line 176, in psycopg_binary._psycopg.wait_c
  File "/app/.venv/lib/python3.11/site-packages/psycopg/connection.py", line 557, in _rollback_gen
    yield from self._exec_command(b"ROLLBACK")
  File "/app/.venv/lib/python3.11/site-packages/psycopg/connection.py", line 461, in _exec_command
    self.pgconn.send_query_params(command, None, result_format=result_format)
  File "psycopg_binary/pq/pgconn.pyx", line 276, in psycopg_binary.pq.PGconn.send_query_params
sqlalchemy.exc.OperationalError: (psycopg.OperationalError) sending query and params failed: another command is already in progress
(Background on this error at: https://sqlalche.me/e/20/e3q8)

Using an SQLAlchemy session contextually produces a similar stack:

    with Session() as session:
  File "/app/.venv/lib/python3.11/site-packages/sqlalchemy/orm/session.py", line 1687, in __exit__
    self.close()
  File "/app/.venv/lib/python3.11/site-packages/sqlalchemy/orm/session.py", line 2383, in close
    self._close_impl(invalidate=False)
  ... <snipped>

[dvarrazzo]

Thank you, great finding.

Are you able to create a repro script to be sure to fix the issue, and that it stays fixed?

[dvarrazzo]

the signals from our wall profiler were manifesting as an EINTR error

Which signal are you sending to your app?

I am testing with the following test in tests/test_concurrency.py:

@pytest.mark.slow
@pytest.mark.subprocess
@pytest.mark.skipif(sys.platform == "win32", reason="signal test")
@pytest.mark.parametrize(
    "signame", ["SIGINT", "SIGALRM", "SIGWINCH", "SIGTERM", "SIGCHLD"]
)
def test_eintr(dsn, signame):
    try:
        sig = int(getattr(signal, signame))
    except AttributeError:
        pytest.skip(f"unknown signal: {signame}")

    script = f"""\
import os
import time
import psycopg
from threading import Thread

def message_to_meself():
    time.sleep(0.25)
    os.kill(os.getpid(), {sig!r})

with psycopg.connect({dsn!r}) as conn:

    cur = conn.cursor()

    t = Thread(target=message_to_meself, daemon=True)
    t.start()
    cur.execute("select 'ok' from pg_sleep(0.5)")
    assert cur.fetchone() == ("ok",)
"""
    cp = sp.run([sys.executable, "-s"], input=script, text=True)
    assert (
        cp.returncode == 0
    ), f"script terminated with {signal.Signals(abs(cp.returncode)).name}"

but I can't reproduce the issue: the script passes with "SIGWINCH", "SIGCHLD", terminates with the other signals:

FAILED tests/test_concurrency.py::test_eintr[SIGTERM] - AssertionError: script terminated with SIGTERM
FAILED tests/test_concurrency.py::test_eintr[SIGINT] - AssertionError: script terminated with SIGINT
FAILED tests/test_concurrency.py::test_eintr[SIGALRM] - AssertionError: script terminated with SIGALRM

and I can't reproduce an InterruptedError. Getting the same results using PSYCOPG_WAIT_FUNC=wait_poll.

List of alarms taken from the test in python/cpython#67806.

[dvarrazzo]

My shot at fixing the issue is in 30daa2d. However I would be keen to reproduce the issue. Have you got suggestions about how to do it?

[Jawshua]

Thanks for the attentive response.

Our profiler uses interrupt timers, and there's some special signal sauce that needs to happen on the main thread to make it work. Here's a stripped down test that is essentially how it works:

@pytest.mark.slow
@pytest.mark.subprocess
@pytest.mark.parametrize(
    "itimername", ["ITIMER_REAL"],
)
def test_itimer(dsn, itimername):
    itimer_signals = {
        "ITIMER_REAL": signal.SIGALRM,
    }

    try:
        itimer = int(getattr(signal, itimername))
        sig = int(itimer_signals[itimername])
    except (AttributeError, KeyError):
        pytest.skip(f"unknown interrupt timer: {itimername}")

    script = f"""\
import os
import signal
import time
import psycopg
from threading import Thread

def signal_handler(signum, frame):
    assert signum == {sig!r}

# Install a handler for the signal
signal.signal({sig!r}, signal_handler)

# Restart system calls interrupted by the signal
signal.siginterrupt({sig!r}, False)


with psycopg.connect({dsn!r}) as conn:
    # Fire an interrupt signal every 0.25 seconds
    signal.setitimer({itimer!r}, 0.25, 0.25)

    cur = conn.cursor()
    cur.execute("select 'ok' from pg_sleep(0.5)")
    assert cur.fetchone() == ("ok",)
"""
    cp = sp.run([sys.executable, "-s"], input=script, text=True)
    assert (
        cp.returncode == 0
    ), f"script terminated with {signal.Signals(abs(cp.returncode)).name}"

I've also adapted the test you posted above to cut out the setitimer middleman, but I'm not 100% sure we can expect all of these to pass even if the problem is fixed:

@pytest.mark.slow
@pytest.mark.subprocess
@pytest.mark.skipif(sys.platform == "win32", reason="signal test")
@pytest.mark.parametrize(
    "signame", ["SIGINT", "SIGALRM", "SIGVTALRM", "SIGPROF", "SIGWINCH", "SIGTERM", "SIGCHLD"]
)
def test_eintr(dsn, signame):
    try:
        sig = int(getattr(signal, signame))
    except AttributeError:
        pytest.skip(f"unknown signal: {signame}")

    script = f"""\
import os
import signal
import time
import psycopg
from threading import Thread

def signal_handler(signum, frame):
    assert signum == {sig!r}

# Install a handler for the signal
signal.signal({sig!r}, signal_handler)

# Restart system calls interrupted by the signal
signal.siginterrupt({sig!r}, False)

def message_to_meself():
    time.sleep(0.25)
    os.kill(os.getpid(), {sig!r})

with psycopg.connect({dsn!r}) as conn:

    cur = conn.cursor()

    t = Thread(target=message_to_meself, daemon=True)
    t.start()
    cur.execute("select 'ok' from pg_sleep(0.5)")
    assert cur.fetchone() == ("ok",)
"""
    cp = sp.run([sys.executable, "-s"], input=script, text=True)
    assert (
        cp.returncode == 0
    ), f"script terminated with {signal.Signals(abs(cp.returncode)).name}"

[Jawshua]

I can also sadly confirm your fix hasn't fix it, but I'm assuming that's because macOS uses the select path which doesn't have the fix.

[dvarrazzo]

Thank you for your repro, I will try it.

I can also sadly confirm your fix hasn't fix it, but I'm assuming that's because macOS uses the select path which doesn't have the fix.

Oh, I misread the #IFs and thought that the non-poll branch was for windows. Can you try 60c5d32 please?

[Jawshua]

No bueno. My C is very rusty, but I think a continue in a while(0) will probably exit the loop, so that EINTR handler is effectively a no-op.

[dvarrazzo]

Your test to reproduce is good, thank you! So mine wasn't working probably because of the thread tampering with the state we will try to achieve

And yes, my fix didn't fix anything. Let's see if a good old GOTO fixes...

[dvarrazzo]

Added test to reproduce the issue, and added fix.

My C is very rusty, but I think a continue in a while(0) will probably exit the loop

Darn, I thought I was being clever and managed to not upset Djikstra's spirit...