Как бороться с ошибкой: «sqlalchemy.exc.InterfaceError: (InterfaceError) 2013: Lost connection to MySQL»?

Question

[pcdesign]

Есть сайт на flask.
Изредка, примерно 1 раз в два дня возникают такие ошибки.

sqlalchemy.exc.InterfaceError: (InterfaceError) 2013: Lost connection to MySQL server during query 'SELECT

Происходит это, я так понимаю, когда MySQL рестартует по каким-то причинам.

В логе mysql:

150312 14:20:22 [Note] /usr/libexec/mysqld: Normal shutdown

150312 14:20:22 [Note] Event Scheduler: Purging the queue. 0 events
150312 14:20:22  InnoDB: Starting shutdown...
150312 14:20:23  InnoDB: Shutdown completed; log sequence number 13754751080
150312 14:20:23 [Note] /usr/libexec/mysqld: Shutdown complete

150312 14:20:23 mysqld_safe mysqld from pid file /var/run/mariadb/mariadb.pid ended
150312 14:20:41 mysqld_safe Starting mysqld daemon with databases from /var/lib/mysql
150312 14:20:41 InnoDB: The InnoDB memory heap is disabled
150312 14:20:41 InnoDB: Mutexes and rw_locks use GCC atomic builtins
150312 14:20:41 InnoDB: Compressed tables use zlib 1.2.7
150312 14:20:41 InnoDB: Using Linux native AIO
150312 14:20:41 InnoDB: Initializing buffer pool, size = 128.0M
150312 14:20:41 InnoDB: Completed initialization of buffer pool
150312 14:20:41 InnoDB: highest supported file format is Barracuda.
150312 14:20:42  InnoDB: Waiting for the background threads to start
150312 14:20:43 Percona XtraDB (http://www.percona.com) 5.5.40-MariaDB-36.1 started; log sequence number 13754751080
150312 14:20:43 [Note] Plugin 'FEEDBACK' is disabled.
150312 14:20:43 [Note] Server socket created on IP: '0.0.0.0'.
150312 14:20:43 [Note] Event Scheduler: Loaded 0 events
150312 14:20:43 [Note] /usr/libexec/mysqld: ready for connections.
Version: '5.5.40-MariaDB'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  MariaDB Server
150323 15:14:18 [Note] /usr/libexec/mysqld: Normal shutdown

150323 15:14:18 [Note] Event Scheduler: Purging the queue. 0 events
150323 15:14:18  InnoDB: Starting shutdown...
150323 15:14:18  InnoDB: Waiting for 16 pages to be flushed
150323 15:14:18  InnoDB: Shutdown completed; log sequence number 14011502490
150323 15:14:18 [Note] /usr/libexec/mysqld: Shutdown complete

150323 15:14:18 mysqld_safe mysqld from pid file /var/run/mariadb/mariadb.pid ended
150323 15:14:19 mysqld_safe Starting mysqld daemon with databases from /var/lib/mysql
150323 15:14:19 InnoDB: The InnoDB memory heap is disabled
150323 15:14:19 InnoDB: Mutexes and rw_locks use GCC atomic builtins
150323 15:14:19 InnoDB: Compressed tables use zlib 1.2.7
150323 15:14:19 InnoDB: Using Linux native AIO
150323 15:14:19 InnoDB: Initializing buffer pool, size = 128.0M
150323 15:14:19 InnoDB: Completed initialization of buffer pool
150323 15:14:19 InnoDB: highest supported file format is Barracuda.
150323 15:14:19  InnoDB: Waiting for the background threads to start
150323 15:14:20 Percona XtraDB (http://www.percona.com) 5.5.40-MariaDB-36.1 started; log sequence number 14011502490
150323 15:14:20 [Note] Plugin 'FEEDBACK' is disabled.
150323 15:14:20 [Note] Server socket created on IP: '0.0.0.0'.
150323 15:14:20 [Note] Event Scheduler: Loaded 0 events
150323 15:14:20 [Note] /usr/libexec/mysqld: ready for connections.
Version: '5.5.40-MariaDB'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  MariaDB Server
150414 15:47:49 [Note] /usr/libexec/mysqld: Normal shutdown

150414 15:47:49 [Note] Event Scheduler: Purging the queue. 0 events
150414 15:47:50  InnoDB: Starting shutdown...
150414 15:47:50  InnoDB: Shutdown completed; log sequence number 14440827849
150414 15:47:50 [Note] /usr/libexec/mysqld: Shutdown complete

150414 15:47:50 mysqld_safe mysqld from pid file /var/run/mariadb/mariadb.pid ended
150414 15:47:51 mysqld_safe Starting mysqld daemon with databases from /var/lib/mysql
150414 15:47:51 InnoDB: The InnoDB memory heap is disabled
150414 15:47:51 InnoDB: Mutexes and rw_locks use GCC atomic builtins
150414 15:47:51 InnoDB: Compressed tables use zlib 1.2.7
150414 15:47:51 InnoDB: Using Linux native AIO
150414 15:47:51 InnoDB: Initializing buffer pool, size = 128.0M
150414 15:47:51 InnoDB: Completed initialization of buffer pool
150414 15:47:51 InnoDB: highest supported file format is Barracuda.
150414 15:47:51  InnoDB: Waiting for the background threads to start
150414 15:47:52 Percona XtraDB (http://www.percona.com) 5.5.40-MariaDB-36.1 started; log sequence number 14440827849
150414 15:47:52 [Note] Plugin 'FEEDBACK' is disabled.
150414 15:47:52 [Note] Server socket created on IP: '0.0.0.0'.
150414 15:47:52 [Note] Event Scheduler: Loaded 0 events
150414 15:47:52 [Note] /usr/libexec/mysqld: ready for connections.
Version: '5.5.40-MariaDB'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  MariaDB Server

И вот что в my.cnf

cat /etc/my.cnf
[mysqld]
datadir=/var/lib/mysql
socket=/var/lib/mysql/mysql.sock
# Disabling symbolic-links is recommended to prevent assorted security risks
symbolic-links=0
net_read_timeout= 180
# Я дописал net_read_timeout= 180
# Settings user and group are ignored when systemd is used.
# If you need to run mysqld under a different user or group,
# customize your systemd unit file for mariadb according to the
# instructions in http://fedoraproject.org/wiki/Systemd

[mysqld_safe]
log-error=/var/log/mariadb/mariadb.log
pid-file=/var/run/mariadb/mariadb.pid

#
# include all files from the config directory
#
!includedir /etc/my.cnf.d

Answer 1

[sim3x]

В интернетах предполагают, что или кто-то рестатартит сервер, или кто-то получил привилегии и рестартит сервис, или что max_connections= может помочь

https://www.google.com/search?q=%2Fusr%2Flibexec%2...

Comments

[pcdesign]

Спасибо. Попробовал выставить:
set global max_connections = 300;
Было 151.
Осталось теперь понаблюдать будет клематься или нет.

[pcdesign]

Продержалось 4 дня, а потом выдало туже ошибку.

[sim3x]

pcdesign: текут коннекты
нужно курить docs.sqlalchemy.org/en/latest/core/pooling.html

[pcdesign]

sim3x: Спасибо за наводку.
Из этого мана:
https://pythonhosted.org/Flask-SQLAlchemy/config.html
Выставил значение
app.config['SQLALCHEMY_POOL_TIMEOUT'] = 2
По умолчанию 10 секунд было.
Осталось поглядеть, что будет.

[pcdesign]

И добавил:
app.config['SQLALCHEMY_POOL_SIZE'] = 10
До кучи.

[pcdesign]

Не помогает.
Заметил, что это происходит на тяжелых запросах с INNER JOIN.

[sim3x]

pcdesign: пили логирование в питон коде около таких мест
>app.config['SQLALCHEMY_POOL_TIMEOUT'] = 2
стоит таки вернуть в 10, а может даже и приподнять до 20-30

[sim3x]

pcdesign: но сперва, надо покурить ман по логированию БД https://mariadb.com/kb/en/mariadb/server-system-va...

[pcdesign]

sim3x: Да, спасибо. Я поднял это значение ['SQLALCHEMY_POOL_TIMEOUT'] до 20, практически сразу.
Так кол-во ошибок выросло при значении 2.

А на счет логирования. В чем суть? То есть чего нужно добиться?
Что мы хотим увидеть в логах?

[sim3x]

pcdesign: нужно зафиксировать, что происходит перед тем как БД идет на релоад

а идеально, просто прочитать причину перезагрузки в логах

[pcdesign]

sim3x: Спасибо.
Установил уровень логирования в дебаг.

Было:
MariaDB [(none)]> show global variables like '%warn%' ;
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| log_warnings | 1 |
| sql_warnings | OFF |
+---------------+-------+
2 rows in set (0.00 sec)

Стало:
MariaDB [(none)]> show global variables like '%warn%' ;
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| log_warnings | 2 |
| sql_warnings | OFF |
+---------------+-------+
2 rows in set (0.00 sec)
===============================

После того как установил новый левел, пришлось сделать рестарт mariadb.
За эти доли секунды пока рестартился mysql нападало тьма сообщений от flask.

sqlalchemy.exc.InterfaceError: (InterfaceError) 2003: Can't connect to MySQL

Но, что интересно код ошибки и сама ошибка немного другая.

[pcdesign]

Новый уровень логирования показал вот что:

В 2015-05-17 06:48:52 зафиксирована ошибка:
sqlalchemy.exc.InterfaceError: (InterfaceError) 2013: Lost connection

И в это же самое время в логах майсквеля:
150517 6:48:47 [Warning] Aborted connection 65 to db: 'db_name' user: 'db_user' host: 'localhost' (Unknown error)

[sim3x]

pcdesign:
похоже, что таймаут у алхимии больше чем у мускула
stackoverflow.com/questions/29755228/sqlalchemy-my...

нужно ждать "InnoDB: Starting shutdown..." для диагностики

[pcdesign]

sim3x: Благодарю за ответ.

150414 15:47:50 InnoDB: Starting shutdown...

было в момент рестарта.
А утром просто ошибка вида
[Warning] Aborted connection
И все.

От безысходности обновил машу.
Было:
mysql --version
mysql Ver 15.1 Distrib 5.5.40-MariaDB, for Linux (x86_64) using readline 5.1
yum update mariadb

Стало:
mysql --version
mysql Ver 15.1 Distrib 5.5.41-MariaDB, for Linux (x86_64) using readline 5.1

[pcdesign]

Семь дней продержалось. Семь дней "ни единого обрыва", а сегодня опять двадцать пять.
Все тоже самое в логах. Хотя 7 дней, конечно, прогресс. Раньше 2-3 дня было.

[sim3x]

pcdesign: stackoverflow.com/questions/29755228/sqlalchemy-my...

еще не попробовали pool_recycle

[pcdesign]

sim3x: Только что вставил:
app.config['SQLALCHEMY_POOL_RECYCLE'] = 1800
Понаблюдаем :)

[sim3x]

pcdesign: стоит посмотреть как вообще себя ведет приложение при нагрузке
сделай на себя нагрузку https://loadimpact.com/

[pcdesign]

sim3x: Сделал тест - все ок.
Но сайт и так достаточно нагружен, одних только зареганных юзеров 60к.
И там очень много в memcahed и в redis закешированно.

[sim3x]

pcdesign: ну тогда до встречи через неделю-месяц

[pcdesign]

Через неделю встретились )
sqlalchemy.exc.InterfaceError: (InterfaceError) 2013: Lost connection to MySQL server during

[pcdesign]

Небольшой прогресс есть. Раньше раз в 2 дня, теперь вот раз в неделю.

[sim3x]

pcdesign: так а что у юзера происходит в такой момент?
Заметно ли им вообще что-то

[pcdesign]

Им вылезает "ошибка 50x., что-то пошло не так." Еще как заметно.

[sim3x]

pcdesign: поищи зависимость между 50х и тем в каком вью происходит безобразие

есть вот такой баг например https://bugs.mysql.com/bug.php?id=74933

Почитай zen про саму ошибку dev.mysql.com/doc/refman/5.0/en/gone-away.html

[sim3x]

pcdesign:
в целях експеримента попробовать
app.config['SQLALCHEMY_POOL_RECYCLE'] = 300 # 1800

[pcdesign]

- Сделал: app.config['SQLALCHEMY_POOL_RECYCLE'] = 300

- Ошибка происходит во многих роутах. Но объединяет их одно: во всех их используется "INNER JOIN".

- Если это был бы один или два роута, то можно было бы обернуть в try, но в кучу роутов лезть совершенно не хочется.

- Был у меня еще один проект давно. Но он был мало нагружен и я там просто в жесткую засунул соединение с базой в before_request. А в teardown_request соединение с базой разрывал.

[sim3x]

pcdesign:
> используется "INNER JOIN"
а попробуй вручную сделать кучу таких запросов: напрямую через bash

> Если это был бы один или два роута, то можно было бы обернуть в try, но в кучу роутов лезть совершенно не хочется.

в конце исследования, может получится, что придется лезть не в питон-код, а в код мускула :)

[pcdesign]

- Запросы с "INNER JOIN" без проблем отрабатываются.
Выполняются десятки тысяч точно таких запросов, а потом чик, один раз
2013: Lost connection to MySQL
А потом опять все работает как ни в чем не бывало.

[pcdesign]

Сегодня опять двадцать пять:
2013: Lost connection to MySQL server during query
6 дней продержалось.

[sim3x]

pcdesign: переходи на постгрес лучше

те SQLALCHEMY_POOL_RECYCLE 300 не при чем

используется ли mysql-connector-python ?
какая версия?

апгрейдни его
pip install --upgrade mysql-connector-python

и кстати покажи конфиг алхимиии и сабконфиги марии - может там что-то такое веселое оверрайдится

есть стата по длительности запросов?

не отваливается ли изза короткого net_read_timeout ?

[pcdesign]

sim3x: Я использую вот эту штуку:
https://pythonhosted.org/Flask-SQLAlchemy/quicksta...

Name: mysql-connector-python
Version: 2.0.2
Но обновить не дает:
Could not find any downloads that satisfy the requirement mysql-connector-python

Конфиг алхимии всего несколько строк:

app.config['SQLALCHEMY_DATABASE_URI'] \
= 'mysql+mysqlconnector://user:pass@localhost/db?charset=utf8'
app.config['SQLALCHEMY_ECHO'] = True # Показывает sql запросы в дебаге
app.config['SQLALCHEMY_POOL_TIMEOUT'] = 20
app.config['SQLALCHEMY_POOL_SIZE'] = 20
app.config['SQLALCHEMY_POOL_RECYCLE'] = 300

Конфиги марии дефолтные. Я туда не лазил.

Замерил длительность запроса на котором было последнее падение:
1000 rows in set (0.02 sec)

Я уже добавлял строку в my.cnf
net_read_timeout= 180
Может имеет смысл еще увеличить этот параметр?

[sim3x]

тут стоит думать о том куда двигаться
- connection socket # даст буст по скорости, тк не будет использоваться ядро с его заморочками по поводу сети и тд

VS мучения с тюнингом мускуля + сетевой части

- max_allowed_packet
- net_read_timeout

сокет делается так

app.config['SQLALCHEMY_DATABASE_URI'] = ''mysql://dayenu:secret.word@localhost/dayenu?unix_socket=/usr/local/mysql5/mysqld.sock

только проверь по конфигу марии есть ли там путь /usr/local/mysql5/mysqld.sock и существует ли он в природе ls /usr/local/mysql5/mysqld.sock
там может что-то типа /var/run/mysql.sock быть

[pcdesign]

sim3x: Спасибо! Сокет вроде нашел в центосе:
ls -thall /var/lib/mysql/mysql.sock
srwxrwxrwx 1 mysql mysql 0 May 17 12:29 /var/lib/mysql/mysql.sock

А вот соединится с ним пока не получается.
А что это за прикол двух кавычек перед ''mysql?
Это так на самом деле надо или это опечатка?
Так при соединении пишет:
ImportError: No module named 'MySQLdb'

И как здесь воткнуть charset=utf8?

[sim3x]

pcdesign:
>опечатка

нужно как-то так

app.config['SQLALCHEMY_DATABASE_URI'] = \
"mysql+mysqlconnector://<user>:<password>@<host>[:<port>]/<dbname>" + \
"?charset=utf8&unix_socket=/var/lib/mysql/mysql.sock"

charset почитай в заметках что да как
docs.sqlalchemy.org/en/rel_0_6/dialects/mysql.html...

[sim3x]

pcdesign:
>ImportError: No module named 'MySQLdb'
в ответе на StackOverflow человек прогсто другой модуль дял коннекта к мускулу использовал

[pcdesign]

sim3x: Спасибо! Заработало через сокет.
Я еще для проверки сначала сделал так:
ngrep -W byline -d lo host localhost and port 3306
Поснифал трафик на порту 3306.
Убедился, что запросы идут через этот порт.
Ну потом включил через сокет.
И ngrep после включения через сокет уже больше ничего не показывал.
Так что работает подключение через сокет.

Осталось поглядеть сколько продержится :)

[pcdesign]

sim3x: Неделя прошла. Полет нормальный :)

[pcdesign]

sim3x: Продержалось две недели. Уже думал, что все. Трабл решен.
А сегодня опять:

sqlalchemy.exc.InterfaceError: (InterfaceError) 2013: Lost connection to MySQL server during query

[sim3x]

pcdesign: поставь у uWSGI

vacuum=True
max-requests=2500
harakiri=54

начни собирать все запросы, чтоб понять на каком запросе все падает

[pcdesign]

sim3x: У меня gunicorn деплоит проект.

Падает на многих запросах, то есть если был бы один какой-нибудь роут вида:
/user/go/
Я бы просто обернул в try, да и все.
Падает во многих роутах.
Единственное, что их всех объединяет это две вещи:
1) Запросы тяжелые на много строк при выдачи
2) Во всех них используется inner join.

[sim3x]

pcdesign: настрой гуникорн, так чтоб он пересоздавал процесс после Х ~ 2k-5k запросов
// не помню, а в предистории мускул-мария падала? или просто 50х?

Дело не в роутах - дело в запросе. Для того чтобю решить проблему нужно ее повторить
Грубо говоря, если у тебя есть предположение про inner join запили запрос с максимумом join-ов и увеличивай результат пока не упадет

[pcdesign]

Гуникорн можно в крон засунуть и рестарить, например в 4 утра.
Но разве это может помочь каким-то образом?

Мария-мускул не падает, она просто иногда рестартится иногда.
И именно в момент рестарта марии и происходят вот такие кульбиты.

На счет iner join да не проблема, сотни тысяч запросов нормально отрабатываются.
И лимиты я увеличивал. Все работает.

[sim3x]

pcdesign: ну вот когда рестартиться мария нужно 500 показывать и рестартить гуникорн

Answer 2

[Mikhail]

В принципе можно повесить перехват этой ошибки, что-бы он перезапускал сам сервер. Но как это сделать я пока не знаю...
Ещё есть supervisor.

Comments

[pcdesign]

MySQL - не падает сам по себе. Он живой.
Просто на какие-то доли секунды теряется соединение.
sqlalchemy делает реконнект и все работает как раньше.
Но именно в момент рестарта и реконекта бывают вот такие ошибки как я привел в своем вопросе.

[Mikhail]

pcdesign: у меня сайты на PHP висят и на Python. Когда падает соединение PHP продолжает работать... Python нет. Вероятно дело в самом Mysql только вот я в нём ничего не менял... В документации по Pyramid рекомендуют вешать супервизор, что-бы при падении сервера, он его перезапускал. И действительно перезапуск сервера решает проблему...

[pcdesign]

Mikhail: Тут все просто. Можно каждый раз при каждом запросе выполнять соединение с базой.
Соединились с базой, забрали через select что-нужно и закрыли соединение. Так в большинстве случаев работает PHP. Ясное дело такой ошибки в этом случае не будет.

В Python и sqlalchemy считают, что это накладно каждый раз соединятся и закрывать. И держат соединение до победного конца. А потом например mysql рестартанул. Соединение во flask перестало работать. Через какие-то секунды flask установил новое соединение.
Но именно в эти секунды и происходит та ошибка, которую я привел.

[Mikhail]

Самое интересное, что если есть аякс соединение каждые 2 минуты. Т.е. проверка новых записей, привилегий. То сервер не падает практически никогда. Т.е. оставил на 3 суток разработку такую и сервер работает. А если молчун - отдал результат и не работает то такая ошибка возникает примерно каждые несколько часов.