ProxySQL Crash - create_new_session_and_client_data_stream

[ssgoburdhun]

Bug encountered:

• The angel process crashes at random times.
• We intervene and restarts the systemd (systemctl restart proxysql)

ProxySQL Version: 2.5.3 (Debian 11 - wget from github releases)

Reproduction:

• The angel process crashes at random

root@proxysql1 ~ # pssql -e '\s'|grep Uptime
Uptime:                 4 days 21 hours 28 min 46 sec

• The systemd service remains running:

     Active: active (running) since Thu 2023-07-20 02:12:21 UTC; 1 months 5 days ago

• (default location: /var/lib/proxysql/proxysql.log)
  Error frequently received during crash is:

2023-08-19 16:52:39 MySQL_Thread.cpp:2860:create_new_session_and_client_data_stream(): [ERROR] For FD -1 fcntl() returned -1 errno 9
proxysql: MySQL_Thread.cpp:2862: MySQL_Session* MySQL_Thread::create_new_session_and_client_data_stream(int): Assertion `prevflags != -1' failed.
Error: signal 6:
2023-08-19 16:52:39 MySQL_Thread.cpp:2860:create_new_session_and_client_data_stream(): [ERROR] For FD -1 fcntl() returned -1 errno 9
proxysql: MySQL_Thread.cpp:2862: MySQL_Session* MySQL_Thread::create_new_session_and_client_data_stream(int): Assertion `prevflags != -1' failed.
Error: signal 6:
/usr/bin/proxysql(_Z13crash_handleri+0x29)[0x557f30cc8809]
/usr/bin/proxysql(_Z13crash_handleri+0x29)[0x557f30cc8809]
/lib/x86_64-linux-gnu/libc.so.6(+0x38d60)[0x7f92d77edd60]
/lib/x86_64-linux-gnu/libc.so.6(+0x38d60)[0x7f92d77edd60]
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0x141)[0x7f92d77edce1]
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0x141)[0x7f92d77edce1]
/lib/x86_64-linux-gnu/libc.so.6(abort+0x123)[0x7f92d77d7537]
/lib/x86_64-linux-gnu/libc.so.6(abort+0x123)[0x7f92d77d7537]
2023-08-19 16:52:39 MySQL_Thread.cpp:2860:create_new_session_and_client_data_stream(): [ERROR] For FD -1 fcntl() returned -1 errno 9
/lib/x86_64-linux-gnu/libc.so.6(+0x2240f)[0x7f92d77d740f]
proxysql: MySQL_Thread.cpp:2862: MySQL_Session* MySQL_Thread::create_new_session_and_client_data_stream(int): Assertion `prevflags != -1' failed.
/lib/x86_64-linux-gnu/libc.so.6(+0x2240f)[0x7f92d77d740f]
/lib/x86_64-linux-gnu/libc.so.6(+0x31662)[0x7f92d77e6662]
/lib/x86_64-linux-gnu/libc.so.6(+0x31662)[0x7f92d77e6662]
Error: signal 6:
/usr/bin/proxysql(_ZN12MySQL_Thread41create_new_session_and_client_data_streamEi+0x439)[0x557f30d285d9]
/usr/bin/proxysql(_ZN12MySQL_Thread41create_new_session_and_client_data_streamEi+0x439)[0x557f30d285d9]
2023-08-19 16:52:39 MySQL_Thread.cpp:2860:create_new_session_and_client_data_stream(): [ERROR] For FD -1 fcntl() returned -1 errno 9
/usr/bin/proxysql(_Z13crash_handleri+0x29)[0x557f30cc8809]
proxysql: MySQL_Thread.cpp:2862: MySQL_Session* MySQL_Thread::create_new_session_and_client_data_stream(int): Assertion `prevflags != -1' failed.
Error: signal 6:
/usr/bin/proxysql(_Z11child_mysqlPv+0x124)[0x557f30d771c4]
/usr/bin/proxysql(_Z11child_mysqlPv+0x124)[0x557f30d771c4]
/lib/x86_64-linux-gnu/libc.so.6(+0x38d60)[0x7f92d77edd60]
/usr/bin/proxysql(_Z13crash_handleri+0x29)[0x557f30cc8809]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x7ea7)[0x7f92d7cccea7]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x7ea7)[0x7f92d7cccea7]
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0x141)[0x7f92d77edce1]
2023-08-19 16:52:39 MySQL_Thread.cpp:2860:create_new_session_and_client_data_stream(): [ERROR] For FD -1 fcntl() returned -1 errno 9
proxysql: MySQL_Thread.cpp:2862: MySQL_Session* MySQL_Thread::create_new_session_and_client_data_stream(int): Assertion `prevflags != -1' failed.
/lib/x86_64-linux-gnu/libc.so.6(+0x38d60)[0x7f92d77edd60]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x3f)[0x7f92d78b0a2f]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x3f)[0x7f92d78b0a2f]
/lib/x86_64-linux-gnu/libc.so.6(abort+0x123)[0x7f92d77d7537]
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0x141)[0x7f92d77edce1]
Error: signal 6:
2023-08-19 16:52:39 MySQL_Thread.cpp:2860:create_new_session_and_client_data_stream(): [ERROR] For FD -1 fcntl() returned -1 errno 9
proxysql: MySQL_Thread.cpp:2862: MySQL_Session* MySQL_Thread::create_new_session_and_client_data_stream(int): Assertion `prevflags != -1' failed.
/lib/x86_64-linux-gnu/libc.so.6(+0x2240f)[0x7f92d77d740f]
/lib/x86_64-linux-gnu/libc.so.6(abort+0x123)[0x7f92d77d7537]
 ---- /usr/bin/proxysql(_Z13crash_handleri+0x29) [0x557f30cc8809] : crash_handler(int)
Error: signal 6:
 ---- /usr/bin/proxysql(_ZN12MySQL_Thread41create_new_session_and_client_data_streamEi+0x439) [0x557f30d285d9] : MySQL_Thread::create_new_session_and_client_data_stream(int)
 ---- /usr/bin/proxysql(_Z11child_mysqlPv+0x124) [0x557f30d771c4] : child_mysql(void*)
To report a crashing bug visit: https://github.com/sysown/proxysql/issues
For support visit: https://proxysql.com/services/support/
/usr/bin/proxysql(_Z13crash_handleri+0x29)[0x557f30cc8809]
2023-08-19 16:52:41 main.cpp:1300:ProxySQL_daemonize_phase3(): [ERROR] ProxySQL crashed. Restarting!
2023-08-19 16:52:41 [INFO] ProxySQL version 2.5.3-89-g86ce115
2023-08-19 16:52:41 [INFO] ProxySQL SHA1 checksum: d318ad8b68590c65a0b69de84a0d7ecf42d038fd
2023-08-19 16:52:41 [INFO] Angel process started ProxySQL process 726625
2023-08-19 16:52:41 [INFO] SSL keys/certificates found in datadir (/var/lib/proxysql): loading them.
2023-08-19 16:52:41 [INFO] Loaded built-in SQLite3
Standard ProxySQL MySQL Logger rev. 2.5.0421 -- MySQL_Logger.cpp -- Mon Jun 19 19:55:05 2023
Standard ProxySQL Cluster rev. 0.4.0906 -- ProxySQL_Cluster.cpp -- Mon Jun 19 19:55:05 2023
Standard ProxySQL Statistics rev. 1.4.1027 -- ProxySQL_Statistics.cpp -- Mon Jun 19 19:55:05 2023
Standard ProxySQL HTTP Server Handler rev. 1.4.1031 -- ProxySQL_HTTP_Server.cpp -- Mon Jun 19 19:55:05 2023
2023-08-19 16:52:41 [INFO] Using UUID from database: 568b33cf-7688-4728-ba6c-7d0f376b022e
2023-08-19 16:52:41 [INFO] Computed checksum for 'LOAD ADMIN VARIABLES TO RUNTIME' was '0x32C14BBD52AEA7B1', with epoch '1692463961'
2023-08-19 16:52:41 ProxySQL_Admin.cpp:6956:flush_mysql_variables___database_to_runtime(): [WARNING] Impossible to set not existing variable client_multi_statements with value "true". Deleting. If the variable name is correct, this version doesn't support it
2023-08-19 16:52:41 ProxySQL_Admin.cpp:6956:flush_mysql_variables___database_to_runtime(): [WARNING] Impossible to set not existing variable client_found_rows with value "true". Deleting. If the variable name is correct, this version doesn't support it
2023-08-19 16:52:41 [INFO] Computed checksum for 'LOAD MYSQL VARIABLES TO RUNTIME' was '0x7AE303B6A09A18B0', with epoch '1692463961'
Standard ProxySQL Admin rev. 2.0.6.0805 -- ProxySQL_Admin.cpp -- Mon Jun 19 19:55:05 2023
2023-08-19 16:52:41 [INFO] ProxySQL SHA1 checksum: d318ad8b68590c65a0b69de84a0d7ecf42d038fd
Standard MySQL Threads Handler rev. 0.2.0902 -- MySQL_Thread.cpp -- Mon Jun 19 19:55:05 2023
[...]

Since the error log mentions FD, maybe it is related to file descriptors error.
In version 2.5.5, there seems to be a bug fix for this.
#4307

Can you comment on such file descriptor behaviour?

[renecannao]

Full log please

[ssgoburdhun]

Another crash has been seen recently with same information.
Sharing the full log.
I will make myself available if you require more information.
proxysql.log-20230829.gz

[renecannao]

There are two set of errors:

• SQLITE error: unable to open database file
• [ERROR] For FD -1 (-1 is not really a file descriptor)

You also have use_ssl=1.
All the above makes plausible that you are being affected by #4272 .
You should be able to verify if the number of file descriptors grow over time, and if yes than #4272 is confirmed.

[ssgoburdhun]

The file descriptors do grow over time:

root@sqlproxy-2 ~ # lsof -p 3279126 | grep "ca-certificate"  | wc -l
4101
# sleep 30
root@sqlproxy-2 ~ # lsof -p 3279126 | grep "ca-certificate"  | wc -l
4113

Thanks for your recommendations.
We'll plan the upgrade the 2.5.5

[JavierJF]

This issue looks like was correctly diagnosed, and likely motivated by #4272. So I'm closing it due to inactivity.

Thanks, Javier.