Skip to content

SSCursor does not handle timeouts properly #1032

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom
Closed
Nothing4You opened this issue Feb 5, 2022 · 6 comments · Fixed by #1035
Closed

SSCursor does not handle timeouts properly #1032

Nothing4You opened this issue Feb 5, 2022 · 6 comments · Fixed by #1035

Comments

@Nothing4You
Copy link
Contributor

Describe the bug
There's various cases where timeouts during queries can lead to surprising results.

To Reproduce
I'm currently working on tests cases for them and which outcomes I can observe.

Schema:

CREATE TABLE tbl (
id MEDIUMINT NOT NULL AUTO_INCREMENT,
name VARCHAR(255) NOT NULL,
PRIMARY KEY (id));

INSERT INTO tbl VALUES(1, 'a')
INSERT INTO tbl VALUES(2, 'b')
INSERT INTO tbl VALUES(3, 'c')

Code:

with connection.cursor(cursor=pymysql.cursors.SSCursor) as cur:
    sql = "SELECT /*+ MAX_EXECUTION_TIME(1) */ *,sleep(1) FROM tbl WHERE name='a'"
    cur.execute(sql)
    cur.fetchone()

This can lead to a ProgrammingError, I suspect it's this happens when the query is not cached.
I cannot reliably reproduce it yet, restarting the DB increases chance for this to happen, after the first query it won't happen for most attempts.

Traceback (most recent call last):
  File ".../PyMySQL/pmtest.py", line 72, in <module>
    r = cur.fetchone()
  File ".../PyMySQL/pymysql/cursors.py", line 442, in fetchone
    self._check_executed()
  File ".../PyMySQL/pymysql/cursors.py", line 70, in _check_executed
    raise err.ProgrammingError("execute() first")
pymysql.err.ProgrammingError: execute() first
debug output 
packet length: 7
call[1]: _read_packet (line 717)
call[2]: _roundtrip (line 120)
call[3]: caching_sha2_password_auth (line 266)
call[4]: _request_authentication (line 933)
call[5]: connect (line 636)
call[6]: __init__ (line 352)
------------------------------------------------------------------
00 00 00 02 00 00 00                             .......
------------------------------------------------------------------

Succeed to auth
packet length: 23
call[1]: _execute_command (line 820)
call[2]: _send_autocommit_mode (line 454)
call[3]: autocommit (line 436)
call[4]: connect (line 649)
call[5]: __init__ (line 352)
call[6]: <module> (line 7)
------------------------------------------------------------------
13 00 00 00 03 53 45 54 20 41 55 54 4F 43 4F 4D  .....SET AUTOCOM
4D 49 54 20 3D 20 30                             MIT = 0
------------------------------------------------------------------

packet length: 7
call[1]: _read_packet (line 717)
call[2]: _read_ok_packet (line 442)
call[3]: _send_autocommit_mode (line 457)
call[4]: autocommit (line 436)
call[5]: connect (line 649)
call[6]: __init__ (line 352)
------------------------------------------------------------------
00 00 00 00 00 00 00                             .......
------------------------------------------------------------------

packet length: 75
call[1]: _execute_command (line 820)
call[2]: query (line 548)
call[3]: _query (line 429)
call[4]: execute (line 158)
call[5]: <module> (line 63)
47 00 00 00 03 53 45 4C 45 43 54 20 2F 2A 2B 20  G....SELECT /*+
4D 41 58 5F 45 58 45 43 55 54 49 4F 4E 5F 54 49  MAX_EXECUTION_TI
4D 45 28 31 29 20 2A 2F 20 2A 2C 73 6C 65 65 70  ME(1) */ *,sleep
28 31 29 20 46 52 4F 4D 20 74 62 6C 20 57 48 45  (1) FROM tbl WHE
52 45 20 6E 61 6D 65 3D 27 62 27                 RE name='b'
------------------------------------------------------------------

packet length: 83
call[1]: _read_packet (line 717)
call[2]: init_unbuffered_query (line 1174)
call[3]: _read_query_result (line 772)
call[4]: query (line 549)
call[5]: _query (line 429)
call[6]: execute (line 158)
------------------------------------------------------------------
FF D0 0B 23 48 59 30 30 30 51 75 65 72 79 20 65  ...#HY000Query e
78 65 63 75 74 69 6F 6E 20 77 61 73 20 69 6E 74  xecution was int
65 72 72 75 70 74 65 64 2C 20 6D 61 78 69 6D 75  errupted, maximu
6D 20 73 74 61 74 65 6D 65 6E 74 20 65 78 65 63  m statement exec
75 74 69 6F 6E 20 74 69 6D 65 20 65 78 63 65 65  ution time excee
64 65 64                                         ded
------------------------------------------------------------------

fetching row 0
Traceback (most recent call last):
  File ".../PyMySQL/pmtest.py", line 72, in <module>
    r = cur.fetchone()
  File ".../PyMySQL/pymysql/cursors.py", line 442, in fetchone
    self._check_executed()
  File ".../PyMySQL/pymysql/cursors.py", line 70, in _check_executed
    raise err.ProgrammingError("execute() first")
pymysql.err.ProgrammingError: execute() first

This is just one of the problematic test cases, there's several more issues.
I'll add more info in additional comments.

Expected behavior
Query success or OperationalError.

Environment

  • OS: macOS 12
  • Server and version: MySQL 8.0.28 Homebrew
  • PyMySQL version: 3fb9dd9

Additional context
More to come...
@Nothing4You Nothing4You mentioned this issue Feb 5, 2022
Closed
@Nothing4You
Copy link
Contributor Author

For the ProgrammingError the problem is that in cursor.execute() we are only setting cursor._executed to the SQL query after the query was completed.
This leads to an OperationalError raised from cursor._query(query), bypassing setting cursor._executed and therefore leading to a ProgrammingError.

PyMySQL/pymysql/cursors.py

Lines 158 to 160 in 3fb9dd9

result = self._query(query)
self._executed = query
return result

I believe this was actually a flaw in my test code, which was slightly different from what I reported in the original issue, and I had cursor.execute() in a try block without also including cursor.fetchone().
This was indeed a correct ProgrammingError.

@Nothing4You
Copy link
Contributor Author

it may actually all have been issues in my test code, but at least i got some new tests out of them.
see #1033 for new tests.

@Nothing4You Nothing4You reopened this Feb 6, 2022
@Nothing4You
Copy link
Contributor Author

Nothing4You commented Feb 6, 2022 •
edited
Loading

still missing the following:

minimal test case against MySQL 8.0:

import pymysql

connection = pymysql.connect(
    host='127.0.0.1',
    port=3305,
    db='test_pymysql',
    charset='utf8mb4',
    user='root',
    password='root',
)

# table setup
with connection.cursor() as cur:
    cur.execute("DROP TABLE IF EXISTS tbl;")

    cur.execute("""
        CREATE TABLE tbl (
        id MEDIUMINT NOT NULL AUTO_INCREMENT,
        name VARCHAR(255) NOT NULL,
        PRIMARY KEY (id));
        """)

    for i in [(1, 'a'), (2, 'b'), (3, 'c')]:
        cur.execute("INSERT INTO tbl VALUES(%s, %s)", i)

    connection.commit()

with connection.cursor(cursor=pymysql.cursors.SSCursor) as cur:
    cur.execute("SELECT /*+ MAX_EXECUTION_TIME(1) */ *,sleep(1) FROM tbl")
    r = cur.fetchone()

    assert r is not None

    print("retrieved data within short timeout:")
    print(repr(r))

    cur.execute("SELECT 1")
    (r,) = cur.fetchone()

    assert r == 1

    print("selected 1")
Traceback (most recent call last):
  File ".../PyMySQL/pmtest.py", line 37, in <module>
    cur.execute("SELECT 1")
  File ".../PyMySQL/pymysql/cursors.py", line 158, in execute
    result = self._query(query)
  File ".../PyMySQL/pymysql/cursors.py", line 429, in _query
    conn.query(q, unbuffered=True)
  File ".../PyMySQL/pymysql/connections.py", line 548, in query
    self._execute_command(COMMAND.COM_QUERY, sql)
  File ".../PyMySQL/pymysql/connections.py", line 804, in _execute_command
    self._result._finish_unbuffered_query()
  File ".../PyMySQL/pymysql/connections.py", line 1265, in _finish_unbuffered_query
    packet = self.connection._read_packet()
  File ".../PyMySQL/pymysql/connections.py", line 729, in _read_packet
    packet.raise_for_error()
  File ".../PyMySQL/pymysql/protocol.py", line 221, in raise_for_error
    err.raise_mysql_exception(self._data)
  File ".../PyMySQL/pymysql/err.py", line 143, in raise_mysql_exception
    raise errorclass(errno, errval)
pymysql.err.OperationalError: (3024, 'Query execution was interrupted, maximum statement execution time exceeded')
debug output 
packet length: 60
call[1]: _execute_command (line 820)
call[2]: query (line 548)
call[3]: _query (line 429)
call[4]: execute (line 158)
call[5]: <module> (line 29)
38 00 00 00 03 53 45 4C 45 43 54 20 2F 2A 2B 20  8....SELECT /*+
4D 41 58 5F 45 58 45 43 55 54 49 4F 4E 5F 54 49  MAX_EXECUTION_TI
4D 45 28 31 29 20 2A 2F 20 2A 2C 73 6C 65 65 70  ME(1) */ *,sleep
28 31 29 20 46 52 4F 4D 20 74 62 6C              (1) FROM tbl
------------------------------------------------------------------

packet length: 1
call[1]: _read_packet (line 717)
call[2]: init_unbuffered_query (line 1174)
call[3]: _read_query_result (line 772)
call[4]: query (line 549)
call[5]: _query (line 429)
call[6]: execute (line 158)
------------------------------------------------------------------
03                                               .
------------------------------------------------------------------

packet length: 44
call[1]: _read_packet (line 717)
call[2]: _get_descriptions (line 1311)
call[3]: init_unbuffered_query (line 1186)
call[4]: _read_query_result (line 772)
call[5]: query (line 549)
call[6]: _query (line 429)
------------------------------------------------------------------
03 64 65 66 0C 74 65 73 74 5F 70 79 6D 79 73 71  .def.test_pymysq
6C 03 74 62 6C 03 74 62 6C 02 69 64 02 69 64 0C  l.tbl.tbl.id.id.
3F 00 09 00 00 00 09 03 42 00 00 00              ?.......B...
------------------------------------------------------------------

DEBUG: field=<class 'pymysql.protocol.FieldDescriptorPacket'> b'test_pymysql'.'tbl'.'id', type=9, flags=4203, converter=<class 'int'>
packet length: 48
call[1]: _read_packet (line 717)
call[2]: _get_descriptions (line 1311)
call[3]: init_unbuffered_query (line 1186)
call[4]: _read_query_result (line 772)
call[5]: query (line 549)
call[6]: _query (line 429)
------------------------------------------------------------------
03 64 65 66 0C 74 65 73 74 5F 70 79 6D 79 73 71  .def.test_pymysq
6C 03 74 62 6C 03 74 62 6C 04 6E 61 6D 65 04 6E  l.tbl.tbl.name.n
61 6D 65 0C 2D 00 FC 03 00 00 FD 01 10 00 00 00  ame.-...........
------------------------------------------------------------------

DEBUG: field=<class 'pymysql.protocol.FieldDescriptorPacket'> b'test_pymysql'.'tbl'.'name', type=253, flags=1001, converter=None
packet length: 30
call[1]: _read_packet (line 717)
call[2]: _get_descriptions (line 1311)
call[3]: init_unbuffered_query (line 1186)
call[4]: _read_query_result (line 772)
call[5]: query (line 549)
call[6]: _query (line 429)
------------------------------------------------------------------
03 64 65 66 00 00 00 08 73 6C 65 65 70 28 31 29  .def....sleep(1)
00 0C 3F 00 15 00 00 00 08 81 00 00 00 00        ..?...........
------------------------------------------------------------------

DEBUG: field=<class 'pymysql.protocol.FieldDescriptorPacket'> b''.''.'sleep(1)', type=8, flags=81, converter=<class 'int'>
packet length: 5
call[1]: _read_packet (line 717)
call[2]: _get_descriptions (line 1341)
call[3]: init_unbuffered_query (line 1186)
call[4]: _read_query_result (line 772)
call[5]: query (line 549)
call[6]: _query (line 429)
------------------------------------------------------------------
FE 00 00 21 00                                   ...!.
------------------------------------------------------------------

packet length: 6
call[1]: _read_packet (line 717)
call[2]: _read_rowdata_packet_unbuffered (line 1248)
call[3]: read_next (line 438)
call[4]: fetchone (line 443)
call[5]: <module> (line 30)
01 31 01 61 01 31                                .1.a.1
------------------------------------------------------------------

DEBUG: DATA =  1
DEBUG: DATA =  a
DEBUG: DATA =  1
retrieved data within short timeout:
(1, 'a', 1)
.../PyMySQL/pymysql/connections.py:803: UserWarning: Previous unbuffered result was left incomplete
  warnings.warn("Previous unbuffered result was left incomplete")
packet length: 83
call[1]: _read_packet (line 717)
call[2]: _finish_unbuffered_query (line 1265)
call[3]: _execute_command (line 804)
call[4]: query (line 548)
call[5]: _query (line 429)
call[6]: execute (line 158)
------------------------------------------------------------------
FF D0 0B 23 48 59 30 30 30 51 75 65 72 79 20 65  ...#HY000Query e
78 65 63 75 74 69 6F 6E 20 77 61 73 20 69 6E 74  xecution was int
65 72 72 75 70 74 65 64 2C 20 6D 61 78 69 6D 75  errupted, maximu
6D 20 73 74 61 74 65 6D 65 6E 74 20 65 78 65 63  m statement exec
75 74 69 6F 6E 20 74 69 6D 65 20 65 78 63 65 65  ution time excee
64 65 64                                         ded
------------------------------------------------------------------

Traceback (most recent call last):
  File ".../PyMySQL/pmtest.py", line 37, in <module>
    cur.execute("SELECT 1")
  File ".../PyMySQL/pymysql/cursors.py", line 158, in execute
    result = self._query(query)
  File ".../PyMySQL/pymysql/cursors.py", line 429, in _query
    conn.query(q, unbuffered=True)
  File ".../PyMySQL/pymysql/connections.py", line 548, in query
    self._execute_command(COMMAND.COM_QUERY, sql)
  File ".../PyMySQL/pymysql/connections.py", line 804, in _execute_command
    self._result._finish_unbuffered_query()
  File ".../PyMySQL/pymysql/connections.py", line 1265, in _finish_unbuffered_query
    packet = self.connection._read_packet()
  File ".../PyMySQL/pymysql/connections.py", line 729, in _read_packet
    packet.raise_for_error()
  File ".../PyMySQL/pymysql/protocol.py", line 221, in raise_for_error
    err.raise_mysql_exception(self._data)
  File ".../PyMySQL/pymysql/err.py", line 143, in raise_mysql_exception
    raise errorclass(errno, errval)
pymysql.err.OperationalError: (3024, 'Query execution was interrupted, maximum statement execution time exceeded')

I still need to test how reproducible this is, including across DB vendors.
For some reason MySQL 8.0 at least does not abort this query right away but still sends us a row, which to my understanding should not have happened in the first place.

https://dev.mysql.com/doc/refman/8.0/en/miscellaneous-functions.html#function_sleep

When SLEEP() is only part of a query that is interrupted, the query returns an error

I wouldn't expect this to fail on select 1.

@Nothing4You
Copy link
Contributor Author

Nothing4You commented Feb 6, 2022 •
edited
Loading

the problem with this test is that it seems to be related to whether MySQL has data cached, if I run this without table setup and restart my local database I don't get any rows returned and it will fail in the first execute(), if I then perform the same query again I will receive the behavior described above.

import pymysql

connection = pymysql.connect(
    host='127.0.0.1',
    port=3305,
    db='test_pymysql',
    charset='utf8mb4',
    user='root',
    password='root',
)

with connection.cursor(cursor=pymysql.cursors.SSCursor) as cur:
    cur.execute("SELECT /*+ MAX_EXECUTION_TIME(1) */ *,sleep(1) FROM tbl")
    r = cur.fetchone()

    assert r is not None

    print("retrieved data within short timeout:")
    print(repr(r))

    cur.execute("SELECT 1")
    (r,) = cur.fetchone()

    assert r == 1

    print("selected 1")
Traceback (most recent call last):
  File ".../PyMySQL/pmtest.py", line 13, in <module>
    cur.execute("SELECT /*+ MAX_EXECUTION_TIME(1) */ *,sleep(1) FROM tbl")
  File ".../PyMySQL/pymysql/cursors.py", line 158, in execute
    result = self._query(query)
  File ".../PyMySQL/pymysql/cursors.py", line 429, in _query
    conn.query(q, unbuffered=True)
  File ".../PyMySQL/pymysql/connections.py", line 549, in query
    self._affected_rows = self._read_query_result(unbuffered=unbuffered)
  File ".../PyMySQL/pymysql/connections.py", line 772, in _read_query_result
    result.init_unbuffered_query()
  File ".../PyMySQL/pymysql/connections.py", line 1174, in init_unbuffered_query
    first_packet = self.connection._read_packet()
  File ".../PyMySQL/pymysql/connections.py", line 729, in _read_packet
    packet.raise_for_error()
  File ".../PyMySQL/pymysql/protocol.py", line 221, in raise_for_error
    err.raise_mysql_exception(self._data)
  File ".../PyMySQL/pymysql/err.py", line 143, in raise_mysql_exception
    raise errorclass(errno, errval)
pymysql.err.OperationalError: (3024, 'Query execution was interrupted, maximum statement execution time exceeded')
debug output 
packet length: 60
call[1]: _execute_command (line 820)
call[2]: query (line 548)
call[3]: _query (line 429)
call[4]: execute (line 158)
call[5]: <module> (line 13)
38 00 00 00 03 53 45 4C 45 43 54 20 2F 2A 2B 20  8....SELECT /*+
4D 41 58 5F 45 58 45 43 55 54 49 4F 4E 5F 54 49  MAX_EXECUTION_TI
4D 45 28 31 29 20 2A 2F 20 2A 2C 73 6C 65 65 70  ME(1) */ *,sleep
28 31 29 20 46 52 4F 4D 20 74 62 6C              (1) FROM tbl
------------------------------------------------------------------

packet length: 83
call[1]: _read_packet (line 717)
call[2]: init_unbuffered_query (line 1174)
call[3]: _read_query_result (line 772)
call[4]: query (line 549)
call[5]: _query (line 429)
call[6]: execute (line 158)
------------------------------------------------------------------
FF D0 0B 23 48 59 30 30 30 51 75 65 72 79 20 65  ...#HY000Query e
78 65 63 75 74 69 6F 6E 20 77 61 73 20 69 6E 74  xecution was int
65 72 72 75 70 74 65 64 2C 20 6D 61 78 69 6D 75  errupted, maximu
6D 20 73 74 61 74 65 6D 65 6E 74 20 65 78 65 63  m statement exec
75 74 69 6F 6E 20 74 69 6D 65 20 65 78 63 65 65  ution time excee
64 65 64                                         ded
------------------------------------------------------------------

@Nothing4You
Copy link
Contributor Author

Nothing4You commented Feb 6, 2022 •
edited
Loading

this should fix the behavior, but the behavior doesn't seem to be entirely deterministic, at runtime it just "randomly" behaves one way or another, where most of the time it will send at least one row.

diff is based on #1033

diff --git a/pymysql/connections.py b/pymysql/connections.py
index 04e3c53..ce437c9 100644
--- a/pymysql/connections.py
+++ b/pymysql/connections.py
@@ -1262,7 +1262,20 @@ class MySQLResult:
         # in fact, no way to stop MySQL from sending all the data after
         # executing a query, so we just spin, and wait for an EOF packet.
         while self.unbuffered_active:
-            packet = self.connection._read_packet()
+            try:
+                packet = self.connection._read_packet()
+            except err.OperationalError as e:
+                if e.args[0] in (
+                    ER.QUERY_TIMEOUT,
+                    ER.STATEMENT_TIMEOUT,
+                ):
+                    # if the query timed out we can simply ignore this error
+                    self.unbuffered_active = False
+                    self.connection = None
+                    return
+
+                raise
+
             if self._check_packet_is_eof(packet):
                 self.unbuffered_active = False
                 self.connection = None  # release reference to kill cyclic reference.

@Nothing4You Nothing4You mentioned this issue Feb 6, 2022
Merged
@Nothing4You
Copy link
Contributor Author

in some manual tests against 5.5.5-10.7.1-MariaDB-1:10.7.1+maria~focal mariadb.org binary distribution the behavior is slightly different, but it seems to consistently not send the first row, letting the statement consistently fail on the first row read.

SET STATEMENT max_statement_time=0.001 FOR SELECT *,sleep(1) FROM tbl

I think I saw it skip the result structure once, but I can't repro that anymore.
For the majority of queries against this MariaDB instance I just get the result structure, EOF and then pymysql.err.OperationalError: (1969, 'Query execution was interrupted (max_statement_time exceeded)')

@Nothing4You Nothing4You mentioned this issue Apr 10, 2022
Merged
4 tasks
methane pushed a commit that referenced this issue May 23, 2023
@Nothing4You
Fix SSCursor raising query timeout error on wrong query on MySQL DB (#…
3cd76d7 
…1035)

Fixes #1032 (comment)
nicolestandifer3 added a commit to nicolestandifer3/MySQL-test-repos that referenced this issue Aug 6, 2023
@nicolestandifer3
Fix SSCursor raising query timeout error on wrong query on MySQL DB (…
c56d317 
…#1035)

Fixes PyMySQL/PyMySQL#1032 (comment)
@github-actions github-actions bot locked as resolved and limited conversation to collaborators May 27, 2024
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

Fix SSCursor raising query timeout error on wrong query on MySQL DB Nothing4You/PyMySQL
1 participant
@Nothing4You