Proxysql: Proxysql v2.0.0 crashes due to database (sqlite) locked errors

[acampoh]

Hello!

I'm trying to run the latest code for version v2.0.0 and i'm having a lot of crashes, all of them with this trace

2019-01-15 10:31:19 sqlite3db.cpp:61:execute(): [ERROR] SQLITE error: database is locked --- DELETE FROM runtime_global_variables
2019-01-15 10:31:19 sqlite3db.cpp:61:execute(): [ERROR] SQLITE error: database is locked --- DELETE FROM main.runtime_mysql_servers
proxysql: ProxySQL_Admin.cpp:7521: void ProxySQL_Admin::save_mysql_servers_runtime_to_database(bool): Assertion `rc==0' failed.

I'm running it with valgrind to try to find memory leaks, shouldn't be related but just in case...

Thanks a lot!

[renecannao]

@acampoh ,
Can you share your configuration?
Specifically I want to know:

• how many servers/hostgroups you have in mysql_servers
• what other servers related tables you have configured (Galera? Group Replication, Replication hostgroups?)
• what are the various timers related to Monitor module
• do you have Scheduler script? If yes, what they do?
• do you have any external script/monitoring that pool data from Admin?
• do you have ProxySQL Cluster enabled? If yes, how many nodes, and what timers do you use?

All commands executed from Admin interface use a global mutex (sql_query_global_mutex) so they are serialized. But they could still interfere with internal reconfiguration due to Monitor or Cluster.

If you have a core dump it would be possible to check which thread is currently locking that table

[acampoh]

after playing a bit with this, it seems that is related to the use of valgrind to run proxysql. Probably something is initialised in a different way and make it behave in a unexpected way.

I'll keep having a look to this and try to find out where the issue comes from.

[renecannao]

not sure if relevant to this, but I found this on a live system:

2019-01-27 10:41:52 sqlite3db.cpp:61:execute(): [ERROR] SQLITE error: database is locked --- DELETE FROM system_cpu_hour WHERE timestamp < 1517049712
2019-01-27 10:44:52 sqlite3db.cpp:61:execute(): [ERROR] SQLITE error: database is locked --- DELETE FROM system_cpu_hour WHERE timestamp < 1517049892
2019-01-27 10:47:52 sqlite3db.cpp:61:execute(): [ERROR] SQLITE error: database is locked --- DELETE FROM stats_mysql_global
2019-01-27 10:47:52 sqlite3db.cpp:61:execute(): [ERROR] SQLITE error: UNIQUE constraint failed: stats_mysql_global.Variable_Name --- INSERT INTO stats_mysql_global VALUES ("ProxySQL_Uptime","1560")
2019-01-27 10:47:52 sqlite3db.cpp:61:execute(): [ERROR] SQLITE error: UNIQUE constraint failed: stats_mysql_global.Variable_Name --- INSERT INTO stats_mysql_global VALUES ("Active_Transactions","10")
2019-01-27 10:47:52 sqlite3db.cpp:61:execute(): [ERROR] SQLITE error: UNIQUE constraint failed: stats_mysql_global.Variable_Name --- INSERT INTO stats_mysql_global VALUES ("Client_Connections_aborted","0")
2019-01-27 10:47:52 sqlite3db.cpp:61:execute(): [ERROR] SQLITE error: UNIQUE constraint failed: stats_mysql_global.Variable_Name --- INSERT INTO stats_mysql_global VALUES ("Client_Connections_connected","28")
2019-01-27 10:47:52 sqlite3db.cpp:61:execute(): [ERROR] SQLITE error: UNIQUE constraint failed: stats_mysql_global.Variable_Name --- INSERT INTO stats_mysql_global VALUES ("Client_Connections_created","293")

It is likely this is the result of collecting historical data

[hydeperion]

Excuse me for jumping in.

I got the same error in PrixySQL v2.0.2.

```2019-03-07 12:29:42 sqlite3db.cpp:61:execute(): [ERROR] SQLITE error: database is locked --- DELETE FROM system_memory WHERE timestamp < 1551324582
2019-03-07 12:38:42 sqlite3db.cpp:61:execute(): [ERROR] SQLITE error: database is locked --- DELETE FROM system_cpu WHERE timestamp < 1551325122
2019-03-07 12:42:42 sqlite3db.cpp:61:execute(): [ERROR] SQLITE error: database is locked --- INSERT INTO system_memory_hour SELECT timestamp/3600*3600 , AVG(allocated), AVG(resident), AVG(active), AVG(mapped), AVG(metadata), AVG(retained) FROM system_memory WHERE timestamp >= 1551927600 AND timestamp < 1551927600 GROUP BY timestamp/3600
2019-03-07 12:42:42 sqlite3db.cpp:61:execute(): [ERROR] SQLITE error: database is locked --- DELETE FROM system_memory WHERE timestamp < 1551325362
2019-03-07 12:44:42 sqlite3db.cpp:61:execute(): [ERROR] SQLITE error: database is locked --- DELETE FROM system_cpu WHERE timestamp < 1551325482
2019-03-07 12:44:42 sqlite3db.cpp:61:execute(): [ERROR] SQLITE error: database is locked --- DELETE FROM system_cpu_hour WHERE timestamp < 1520394282
.
.

The errors seems to correspond to `SQLITE_BUSY` error of SQLite.
https://www.sqlite.org/c3ref/c_abort.html

define SQLITE_BUSY 5 /* The database file is locked */

define SQLITE_LOCKED 6 /* A table in the database is locked */

```

@renecannao
https://github.com/sysown/proxysql/issues/549
https://github.com/sysown/proxysql/commit/84606e241075a26912b98272749f467494a05f1f
Previously, as you avoided by sleeping when SQLITE_LOCKED occurs,
can we avoid it by sleeping even when SQLITE_BUSY occurs?

FYI, https://groups.google.com/forum/#!topic/proxysql/UoN8T38QLAc
This is a report in relation to this issue.

[hydeperion]

I think we will be able to fix this issue by the following pull request.
https://github.com/sysown/proxysql/pull/2000

Thanks.

[nicolasgarfinkiel]

Hello, while not crashing proxysql, I'm seeing these types of errors on both instances I have running, ProxySQL version 2.0.3.

Relevant log traces example:

2019-04-26 15:46:42 sqlite3db.cpp:61:execute(): [ERROR] SQLITE error: database is locked --- INSERT INTO myhgm_connections_hour SELECT timestamp/3600*3600 , MAX(MyHGM_myconnpoll_destroy), MAX(MyHGM_myconnpoll_get), MAX(MyHGM_myconnpoll_get_ok), MAX(MyHGM_myconnpoll_push), MAX(MyHGM_myconnpoll_reset) FROM myhgm_connections WHERE timestamp >= 1556290800 AND timestamp < 1556290800 GROUP BY timestamp/3600
2019-04-26 15:46:42 sqlite3db.cpp:61:execute(): [ERROR] SQLITE error: database is locked --- DELETE FROM myhgm_connections WHERE timestamp < 1555688802
2019-04-26 15:46:42 sqlite3db.cpp:61:execute(): [ERROR] SQLITE error: database is locked --- DELETE FROM myhgm_connections_hour WHERE timestamp < 1524757602
2019-04-26 15:47:42 sqlite3db.cpp:61:execute(): [ERROR] SQLITE error: database is locked --- INSERT INTO myhgm_connections_hour SELECT timestamp/3600*3600 , MAX(MyHGM_myconnpoll_destroy), MAX(MyHGM_myconnpoll_get), MAX(MyHGM_myconnpoll_get_ok), MAX(MyHGM_myconnpoll_push), MAX(MyHGM_myconnpoll_reset) FROM myhgm_connections WHERE timestamp >= 1556290800 AND timestamp < 1556290800 GROUP BY timestamp/3600
2019-04-26 15:47:42 sqlite3db.cpp:61:execute(): [ERROR] SQLITE error: database is locked --- DELETE FROM myhgm_connections WHERE timestamp < 1555688862
2019-04-26 15:47:42 sqlite3db.cpp:61:execute(): [ERROR] SQLITE error: database is locked --- DELETE FROM myhgm_connections_hour WHERE timestamp < 1524757662
2019-04-26 15:49:42 sqlite3db.cpp:61:execute(): [ERROR] SQLITE error: database is locked --- DELETE FROM stats_mysql_global
2019-04-26 15:49:42 sqlite3db.cpp:61:execute(): [ERROR] SQLITE error: database is locked --- INSERT INTO myhgm_connections_hour SELECT timestamp/3600*3600 , MAX(MyHGM_myconnpoll_destroy), MAX(MyHGM_myconnpoll_get), MAX(MyHGM_myconnpoll_get_ok), MAX(MyHGM_myconnpoll_push), MAX(MyHGM_myconnpoll_reset) FROM myhgm_connections WHERE timestamp >= 1556290800 AND timestamp < 1556290800 GROUP BY timestamp/3600
2019-04-26 15:49:42 sqlite3db.cpp:61:execute(): [ERROR] SQLITE error: database is locked --- DELETE FROM myhgm_connections WHERE timestamp < 1555688982
2019-04-26 15:49:42 sqlite3db.cpp:61:execute(): [ERROR] SQLITE error: database is locked --- DELETE FROM myhgm_connections_hour WHERE timestamp < 1524757782

Thanks

[nicolasgarfinkiel]

Furthermore, I see this kind of error as well that don't crash ProxySQL but make it unresponsive.

2019-04-26 16:18:42 sqlite3db.cpp:61:execute(): [ERROR] SQLITE error: database is locked --- INSERT INTO myhgm_connections_hour SELECT timestamp/3600*3600 , MAX(MyHGM_myconnpoll_destroy), MAX(MyHGM_myconnpoll_get), MAX(MyHGM_myconnpoll_get_ok), MAX(MyHGM_myconnpoll_push), MAX(MyHGM_myconnpoll_reset) FROM myhgm_connections WHERE timestamp >= 1556294400 AND timestamp < 1556294400 GROUP BY timestamp/3600
2019-04-26 16:18:42 sqlite3db.cpp:61:execute(): [ERROR] SQLITE error: database is locked --- DELETE FROM myhgm_connections WHERE timestamp < 1555690722
2019-04-26 16:18:42 sqlite3db.cpp:61:execute(): [ERROR] SQLITE error: database is locked --- DELETE FROM myhgm_connections_hour WHERE timestamp < 1524759522
2019-04-26 16:19:42 sqlite3db.cpp:61:execute(): [ERROR] SQLITE error: database is locked --- DELETE FROM mysql_connections WHERE timestamp < 1555690782
2019-04-26 16:19:42 sqlite3db.cpp:61:execute(): [ERROR] SQLITE error: database is locked --- DELETE FROM mysql_connections_hour WHERE timestamp < 1524759582
2019-04-26 16:22:42 sqlite3db.cpp:61:execute(): [ERROR] SQLITE error: database is locked --- INSERT INTO myhgm_connections_hour SELECT timestamp/3600*3600 , MAX(MyHGM_myconnpoll_destroy), MAX(MyHGM_myconnpoll_get), MAX(MyHGM_myconnpoll_get_ok), MAX(MyHGM_myconnpoll_push), MAX(MyHGM_myconnpoll_reset) FROM myhgm_connections WHERE timestamp >= 1556294400 AND timestamp < 1556294400 GROUP BY timestamp/3600
2019-04-26 16:22:42 sqlite3db.cpp:61:execute(): [ERROR] SQLITE error: database is locked --- DELETE FROM myhgm_connections WHERE timestamp < 1555690962
2019-04-26 16:22:42 sqlite3db.cpp:61:execute(): [ERROR] SQLITE error: database is locked --- DELETE FROM myhgm_connections_hour WHERE timestamp < 1524759762
2019-04-26 16:25:42 sqlite3db.cpp:61:execute(): [ERROR] SQLITE error: database is locked --- DELETE FROM stats_mysql_global
2019-04-26 16:25:42 sqlite3db.cpp:61:execute(): [ERROR] SQLITE error: database is locked --- INSERT INTO myhgm_connections_hour SELECT timestamp/3600*3600 , MAX(MyHGM_myconnpoll_destroy), MAX(MyHGM_myconnpoll_get), MAX(MyHGM_myconnpoll_get_ok), MAX(MyHGM_myconnpoll_push), MAX(MyHGM_myconnpoll_reset) FROM myhgm_connections WHERE timestamp >= 1556294400 AND timestamp < 1556294400 GROUP BY timestamp/3600
2019-04-26 16:25:42 sqlite3db.cpp:61:execute(): [ERROR] SQLITE error: database is locked --- DELETE FROM myhgm_connections WHERE timestamp < 1555691142
2019-04-26 16:25:42 sqlite3db.cpp:61:execute(): [ERROR] SQLITE error: database is locked --- DELETE FROM myhgm_connections_hour WHERE timestamp < 1524759942

Thanks

[gilahacker]

I think we are also having the issue resolved by https://github.com/sysown/proxysql/pull/2000.

2019-05-06 07:05:16 sqlite3db.cpp:61:execute(): [ERROR] SQLITE error: database is locked --- DELETE FROM main.runtime_mysql_servers
proxysql: ProxySQL_Admin.cpp:7576: void ProxySQL_Admin::save_mysql_servers_runtime_to_database(bool): Assertion `rc==6' failed.
Error: signal 6:
proxysql(_Z13crash_handleri+0x1a)[0x48ff6a]
/lib64/libc.so.6(+0x36280)[0x7fb5dc426280]
/lib64/libc.so.6(gsignal+0x37)[0x7fb5dc426207]
/lib64/libc.so.6(abort+0x148)[0x7fb5dc4278f8]
/lib64/libc.so.6(+0x2f026)[0x7fb5dc41f026]
/lib64/libc.so.6(+0x2f0d2)[0x7fb5dc41f0d2]
proxysql(_ZN14ProxySQL_Admin38save_mysql_servers_runtime_to_databaseEb+0x100d)[0x4fffad]
proxysql(_ZN14ProxySQL_Admin24GenericRefreshStatisticsEPKcjb+0xae0)[0x509a20]
proxysql(_Z21admin_session_handlerP13MySQL_SessionPvP10_PtrSize_t+0x134)[0x515734]
proxysql(_ZN13MySQL_Session7handlerEv+0x192a)[0x4de43a]
proxysql(_Z11child_mysqlPv+0x251)[0x4f1ff1]
/lib64/libpthread.so.0(+0x7dd5)[0x7fb5dd605dd5]
/lib64/libc.so.6(clone+0x6d)[0x7fb5dc4edead]
2019-05-06 07:05:16 main.cpp:1371:ProxySQL_daemonize_phase3(): [ERROR] ProxySQL crashed. Restarting!

Is there an ETA for the 2.0.4 release, or should I try compiling it myself from that branch?