Skip to content

Handling of MariaDB ER_CONNECTION_KILLED error packet #526

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
abg opened this issue Nov 9, 2016 · 1 comment · Fixed by #540
Closed

Handling of MariaDB ER_CONNECTION_KILLED error packet #526

abg opened this issue Nov 9, 2016 · 1 comment · Fixed by #540
Assignees
@methane

Comments

@abg
Copy link

abg commented Nov 9, 2016

This is a bit of quirky corner case. Under MariaDB during normal mysqld shutdown an error packet can be sent to the client of the form:

\x1e\x00\x00\x00\xff\x87\x07#70100Connection was killed

With a TCP connection this might be pending on the socket after a query was sent, resulting in pymysql failing with pymysql.err.InternalError: Packet sequence number wrong - got 0 expected 1

If the connection is not immediately closed this might result in further Packet sequence errors as the remaining bytes of this packet are read on subsequent queries but related to this same initial cause (e.g. Packet sequence number wrong - got 35 expected 1 mapping to the '#' character, got 48 expected 1 mapping to the '0' character, and so on as some applications were failing to discard and was subsequently reusing the connection after hitting an InternalError).

FWIW, I was unable to reproduce this under Oracle/MySQL 5.6+ so perhaps this is just a quirk of MariaDB. This error packet also does not get sent under normal KILL [CONNECTION] conditions on MariaDB - only after a normal shutdown. This case will also not manifest if a local unix socket connection (rather than TCP) is used - the socket io will error out before reading this error packet.

Expected Behavior

Expected: a dbapi error (ideally OperationalError) with the contents of the error packet. For comparison, MySQL-python, in contrast, always seems to fail with OperationalError: (2013, 'Lost connection to MySQL server during query').

Current Behavior

InternalError indicating a packet sequence error

Possible Solution

Read the error packet and follow the normal failure path - ideally mapping this 1927 error to an OperationalError exception. Dealing with this while retaining the check on packet sequence number is a bit awkward.

Executable script to reproduce (for bugs)

#!/usr/bin/env python

import os
import subprocess
import sys
import time

import pymysql
import pymysql.connections

pymysql.connections.DEBUG = True


def main():
    # Ensure MySQL is started
    subprocess.call("service mysql start", shell=True)
    connection = pymysql.connect(read_default_file=os.path.expanduser("~/.my.cnf"))
    cursor = connection.cursor()
    # Stop MySQL
    subprocess.call("service mysql stop", shell=True)
    # Wait a moment to be sure MySQL is offline
    time.sleep(2)

    # (Packet sequence number wrong - got 0 expected 1")
    cursor.execute('SELECT 1')

if __name__ == '__main__':
    sys.exit(main())

Tracebacks (for bugs)

Starting mysql (via systemctl):                            [  OK  ]
connected using socket
packet length: 4
call[1]: _read_packet (line 962)
call[2]: _get_server_information (line 1207)
call[3]: connect (line 905)
call[4]: __init__ (line 688)
call[5]: Connect (line 90)
------------------------------------------------------------------
59 00 00 00                                      Y...
------------------------------------------------------------------

packet length: 89
call[1]: _read_packet (line 972)
call[2]: _get_server_information (line 1207)
call[3]: connect (line 905)
call[4]: __init__ (line 688)
call[5]: Connect (line 90)
------------------------------------------------------------------
0A 35 2E 35 2E 35 2D 31 30 2E 31 2E 31 38 2D 4D  ...............M
61 72 69 61 44 42 00 03 00 00 00 63 5E 2D 64 32  ariaDB.....c^.d.
68 3A 28 00 FF F7 21 02 00 3F A0 15 00 00 00 00  h...............
00 00 00 00 00 00 57 5D 4C 47 5F 28 49 74 30 31  ......W]LG_.It..
44 40 00 6D 79 73 71 6C 5F 6E 61 74 69 76 65 5F  D..mysql_native_
70 61 73 73 77 6F 72 64 00                       password.
------------------------------------------------------------------

packet length: 89
call[1]: _get_server_information (line 1210)
call[2]: connect (line 905)
call[3]: __init__ (line 688)
call[4]: Connect (line 90)
call[5]: main (line 17)
------------------------------------------------------------------
0A 35 2E 35 2E 35 2D 31 30 2E 31 2E 31 38 2D 4D  ...............M
61 72 69 61 44 42 00 03 00 00 00 63 5E 2D 64 32  ariaDB.....c^.d.
68 3A 28 00 FF F7 21 02 00 3F A0 15 00 00 00 00  h...............
00 00 00 00 00 00 57 5D 4C 47 5F 28 49 74 30 31  ......W]LG_.It..
44 40 00 6D 79 73 71 6C 5F 6E 61 74 69 76 65 5F  D..mysql_native_
70 61 73 73 77 6F 72 64 00                       password.
------------------------------------------------------------------

server_status: 2
salt_len: 21
packet length: 64
call[1]: write_packet (line 951)
call[2]: _request_authentication (line 1113)
call[3]: connect (line 906)
call[4]: __init__ (line 688)
call[5]: Connect (line 90)
------------------------------------------------------------------
3C 00 00 01 05 A2 2B 00 01 00 00 00 08 00 00 00  ................
00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
00 00 00 00 72 6F 6F 74 00 00 6D 79 73 71 6C 5F  ....root..mysql_
6E 61 74 69 76 65 5F 70 61 73 73 77 6F 72 64 00  native_password.
------------------------------------------------------------------

packet length: 4
call[1]: _read_packet (line 962)
call[2]: _request_authentication (line 1114)
call[3]: connect (line 906)
call[4]: __init__ (line 688)
call[5]: Connect (line 90)
------------------------------------------------------------------
07 00 00 02                                      ....
------------------------------------------------------------------

packet length: 7
call[1]: _read_packet (line 972)
call[2]: _request_authentication (line 1114)
call[3]: connect (line 906)
call[4]: __init__ (line 688)
call[5]: Connect (line 90)
------------------------------------------------------------------
00 00 00 02 00 00 00                             .......
------------------------------------------------------------------

packet length: 23
call[1]: _execute_command (line 1055)
call[2]: _send_autocommit_mode (line 756)
call[3]: autocommit (line 739)
call[4]: connect (line 919)
call[5]: __init__ (line 688)
------------------------------------------------------------------
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....
------------------------------------------------------------------

packet length: 4
call[1]: _read_packet (line 962)
call[2]: _read_ok_packet (line 746)
call[3]: _send_autocommit_mode (line 757)
call[4]: autocommit (line 739)
call[5]: connect (line 919)
------------------------------------------------------------------
07 00 00 01                                      ....
------------------------------------------------------------------

packet length: 7
call[1]: _read_packet (line 972)
call[2]: _read_ok_packet (line 746)
call[3]: _send_autocommit_mode (line 757)
call[4]: autocommit (line 739)
call[5]: connect (line 919)
------------------------------------------------------------------
00 00 00 00 00 00 00                             .......
------------------------------------------------------------------

Stopping mysql (via systemctl):                            [  OK  ]
packet length: 13
call[1]: _execute_command (line 1055)
call[2]: query (line 834)
call[3]: _query (line 322)
call[4]: execute (line 166)
call[5]: main (line 25)
------------------------------------------------------------------
09 00 00 00 03 53 45 4C 45 43 54 20 31           .....SELECT..
------------------------------------------------------------------

packet length: 4
call[1]: _read_packet (line 962)
call[2]: read (line 1302)
call[3]: _read_query_result (line 1019)
call[4]: query (line 835)
call[5]: _query (line 322)
------------------------------------------------------------------
1E 00 00 00                                      ....
------------------------------------------------------------------

Traceback (most recent call last):
  File "test_er_conn_killed.py", line 28, in <module>
    sys.exit(main())
  File "test_er_conn_killed.py", line 25, in main
    cursor.execute('SELECT 1')
  File "/home/luser/PyMySQL/pymysql/cursors.py", line 166, in execute
    result = self._query(query)
  File "/home/luser/PyMySQL/pymysql/cursors.py", line 322, in _query
    conn.query(q)
  File "/home/luser/PyMySQL/pymysql/connections.py", line 835, in query
    self._affected_rows = self._read_query_result(unbuffered=unbuffered)
  File "/home/luser/PyMySQL/pymysql/connections.py", line 1019, in _read_query_result
    result.read()
  File "/home/luser/PyMySQL/pymysql/connections.py", line 1302, in read
    first_packet = self.connection._read_packet()
  File "/home/luser/PyMySQL/pymysql/connections.py", line 968, in _read_packet
    (packet_number, self._next_seq_id))
pymysql.err.InternalError: Packet sequence number wrong - got 0 expected 1

Context

I encountered this in a openstack test environment after restarting a MariaDB backend database - the existing (sqlalchemy pooled) connections all failed with "Packet sequence number wrong" errors. The error was confusing and I initially suspected a service of mishandling connections (which is usually the case), but this happened across every project with an open database connection on an idle test environment.

The internal error here with this message was not handled elegantly and the error packet messages makes it clear why things failed, at least. Remapping this error to an OperationalError exception leads to much more elegant default recovery behavior for some environments.

Your Environment

  • Operating System and version: Tested on CentOS 7 / Ubuntu 16.04 against MariaDB 10.0.27, 10.1.18, 10.1.19 from mariadb.org packages
  • Python version and build: python 2.7.12+Ubuntu 16.04.1 LTS and python 2.7.5+CentOS 7
  • PyMySQL Version used: 0.7.6 and 0.7.9 and PyMySQL/master
@jobrs
Copy link

jobrs commented Jan 11, 2017

+1

methane added a commit to methane/PyMySQL that referenced this issue Jan 12, 2017
@methane
Raise SERVER_LOST error for MariaDB's shutdown packet
6c888f5 
fixes PyMySQL#526
@methane methane mentioned this issue Jan 12, 2017
Merged
@methane methane self-assigned this Jan 12, 2017
methane added a commit to methane/PyMySQL that referenced this issue Jan 12, 2017
@methane
Raise SERVER_LOST error for MariaDB's shutdown packet
0540723 
fixes PyMySQL#526
methane added a commit to methane/PyMySQL that referenced this issue Jan 13, 2017
@methane
Raise SERVER_LOST error for MariaDB's shutdown packet
d9de7a9 
fixes PyMySQL#526
methane added a commit that referenced this issue Jan 13, 2017
@methane
Raise SERVER_LOST error for MariaDB's shutdown packet (#540)
a7e6d14 
Raise SERVER_LOST error for MariaDB's shutdown packet

fixes #526
@splashx splashx mentioned this issue Jan 13, 2017
Closed
@magnusjt magnusjt mentioned this issue Feb 20, 2017
Open
@kac- kac- mentioned this issue May 29, 2018
Open
@rspreen rspreen mentioned this issue Sep 14, 2018
Closed
@zzzeek zzzeek mentioned this issue Oct 24, 2019
Closed
@github-actions github-actions bot locked as resolved and limited conversation to collaborators Aug 3, 2021
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees

@methane methane

Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

Raise SERVER_LOST error for MariaDB's shutdown packet methane/PyMySQL
3 participants
@abg @methane @jobrs