Crash after idling

[scaarup]

Description:
I have two webapp's in tomcat connected to a local proxysql. If I leave the one application without using it for some hours and then start using it, proxysql crashes.
log snippet from the crash:

2019-06-07 14:24:43 main.cpp:1634:main(): [ERROR] Watchdog: 1 threads missed a heartbeat
2019-06-07 14:24:46 main.cpp:1634:main(): [ERROR] Watchdog: 1 threads missed a heartbeat
2019-06-07 14:24:49 main.cpp:1634:main(): [ERROR] Watchdog: 1 threads missed a heartbeat
2019-06-07 14:24:52 main.cpp:1634:main(): [ERROR] Watchdog: 1 threads missed a heartbeat
2019-06-07 14:24:55 main.cpp:1634:main(): [ERROR] Watchdog: 1 threads missed a heartbeat
2019-06-07 14:24:58 main.cpp:1634:main(): [ERROR] Watchdog: 1 threads missed a heartbeat
2019-06-07 14:25:01 main.cpp:1634:main(): [ERROR] Watchdog: 1 threads missed a heartbeat
2019-06-07 14:25:04 main.cpp:1634:main(): [ERROR] Watchdog: 1 threads missed a heartbeat
2019-06-07 14:25:07 main.cpp:1634:main(): [ERROR] Watchdog: 1 threads missed a heartbeat
2019-06-07 14:25:10 main.cpp:1634:main(): [ERROR] Watchdog: 1 threads missed a heartbeat
2019-06-07 14:25:10 main.cpp:1638:main(): [ERROR] Watchdog: reached 10 missed heartbeats. Aborting!
proxysql: main.cpp:1639: int main(int, const char**): Assertion `0' failed.
Error: signal 6:
proxysql(_Z13crash_handleri+0x1a)[0x4a219a]
/lib64/libc.so.6(+0x36280)[0x7f525bfc1280]
/lib64/libc.so.6(gsignal+0x37)[0x7f525bfc1207]
/lib64/libc.so.6(abort+0x148)[0x7f525bfc28f8]
/lib64/libc.so.6(+0x2f026)[0x7f525bfba026]
/lib64/libc.so.6(+0x2f0d2)[0x7f525bfba0d2]
proxysql(main+0xb9d)[0x49e38d]
/lib64/libc.so.6(__libc_start_main+0xf5)[0x7f525bfad3d5]
proxysql[0x49e9f4]
2019-06-07 14:25:10 main.cpp:1371:ProxySQL_daemonize_phase3(): [ERROR] ProxySQL crashed. Restarting!

I have continuous monitoring of proxysql backend health and group membership. Everything is fine all the time, and my other application never fails.
Note: connections to backends is with ssl.
Version: 2.0.4
Installed from: https://repo.proxysql.com/ProxySQL/proxysql-2.0.x/centos/7/proxysql-2.0.4-1-centos7.x86_64.rpm
OS: Red Hat Enterprise Linux Server release 7.6 (Maipo)
Compressed error log: proxysql.log.gz
Coredump: core.2029.gz
Compressed binary: proxysql.gz

[altmannmarcelo]

Hi @scaarup and @renecannao .

By looking at the coredump, seems that a single thread is missing the heartbeat:

Core was generated by `proxysql -c /etc/proxysql.cnf -D /var/lib/proxysql'.
Program terminated with signal 6, Aborted.
#0  0x00007f525bfc1207 in raise () from /lib64/libc.so.6
Missing separate debuginfos, use: debuginfo-install glibc-2.17-260.el7_6.3.x86_64 libgcc-4.8.5-36.el7.x86_64 libstdc++-4.8.5-36.el7.x86_64 zlib-1.2.7-18.el7.x86_64
(gdb) frame 4
#4  0x000000000049e38d in main (argc=<optimized out>, argv=<optimized out>) at main.cpp:1639
1639	main.cpp: No such file or directory.
(gdb) p threads_missing_heartbeat
$1 = 1

pt-pmp show 3 worker threads are idle while 1 is stuck in pthread_getspecific:

3 poll(libc.so.6),MySQL_Thread::run,mysql_worker_thread_func,start_thread(libpthread.so.0),clone(libc.so.6)
2 pthread_cond_wait,remove,ConsumerThread::run,start_thread(libpthread.so.0),clone(libc.so.6)
1 raise(libc.so.6),abort(libc.so.6),__assert_fail_base(libc.so.6),__assert_fail(libc.so.6),main
1 raise(libc.so.6)
1 pthread_getspecific(libpthread.so.0),ERR_get_state,ERR_peek_error,SSL_get_error,ma_pvio_tls_read_async(ma_pvio.c:276),ma_pvio_read(ma_pvio.c:276),ma_pvio_cache_read(ma_pvio.c:360),ma_real_read(ma_net.c:376),ma_net_read(ma_net.c:430),ma_net_safe_read(mariadb_lib.c:193),mthd_my_read_rows(mariadb_lib.c:896),mthd_my_read_query_result(mariadb_lib.c:2164),mysql_real_query_start_internal(mariadb_async.c:381),my_context_spawn(ma_context.c:201)
1 pthread_cond_wait,remove,HGCU_thread_run,libstdc++::??(libstdc++.so.6),start_thread(libpthread.so.0),clone(libc.so.6)
1 poll(libc.so.6),poll_poll,ev_run,GTID_syncer_run,libstdc++::??(libstdc++.so.6),start_thread(libpthread.so.0),clone(libc.so.6)
1 poll(libc.so.6),admin_main_loop,start_thread(libpthread.so.0),clone(libc.so.6)
1 nanosleep(libc.so.6),usleep(libc.so.6),Query_Cache::purgeHash_thread,mysql_shared_query_cache_funct,start_thread(libpthread.so.0),clone(libc.so.6)
1 nanosleep(libc.so.6),usleep(libc.so.6),MySQL_Monitor::run,libstdc++::??(libstdc++.so.6),start_thread(libpthread.so.0),clone(libc.so.6)
1 nanosleep(libc.so.6),usleep(libc.so.6),MySQL_Monitor::monitor_replication_lag,monitor_replication_lag_pthread,start_thread(libpthread.so.0),clone(libc.so.6)
1 nanosleep(libc.so.6),usleep(libc.so.6),MySQL_Monitor::monitor_read_only,monitor_read_only_pthread,start_thread(libpthread.so.0),clone(libc.so.6)
1 nanosleep(libc.so.6),usleep(libc.so.6),MySQL_Monitor::monitor_ping,monitor_ping_pthread,start_thread(libpthread.so.0),clone(libc.so.6)
1 nanosleep(libc.so.6),usleep(libc.so.6),MySQL_Monitor::monitor_group_replication,monitor_group_replication_pthread,start_thread(libpthread.so.0),clone(libc.so.6)
1 nanosleep(libc.so.6),usleep(libc.so.6),MySQL_Monitor::monitor_galera,monitor_galera_pthread,start_thread(libpthread.so.0),clone(libc.so.6)
1 nanosleep(libc.so.6),usleep(libc.so.6),MySQL_Monitor::monitor_connect,monitor_connect_pthread,start_thread(libpthread.so.0),clone(libc.so.6)
1 nanosleep(libc.so.6),usleep(libc.so.6),MySQL_Monitor::monitor_aws_aurora,monitor_aws_aurora_pthread,start_thread(libpthread.so.0),clone(libc.so.6)

Looking the coredump again we can check the thread missing the heartbeats:

(gdb) info thread
  Id   Target Id         Frame
  19   Thread 0x7f52559f7700 (LWP 2047) 0x00007f525c04fe2d in nanosleep () from /lib64/libc.so.6
  18   Thread 0x7f5255df9700 (LWP 2045) 0x00007f525c04fe2d in nanosleep () from /lib64/libc.so.6
  17   Thread 0x7f52557f6700 (LWP 2048) 0x00007f525c04fe2d in nanosleep () from /lib64/libc.so.6
  16   Thread 0x7f5255bf8700 (LWP 2046) 0x00007f525c04fe2d in nanosleep () from /lib64/libc.so.6
  15   Thread 0x7f5256fff700 (LWP 2039) 0x00007f525c04fe2d in nanosleep () from /lib64/libc.so.6
  14   Thread 0x7f52561fb700 (LWP 2043) 0x00007f525c04fe2d in nanosleep () from /lib64/libc.so.6
  13   Thread 0x7f52587ff700 (LWP 2038) 0x00007f525c04fe2d in nanosleep () from /lib64/libc.so.6
  12   Thread 0x7f5255ffa700 (LWP 2044) 0x00007f525c04fe2d in nanosleep () from /lib64/libc.so.6
  11   Thread 0x7f52563fc700 (LWP 2042) 0x00007f525c04fe2d in nanosleep () from /lib64/libc.so.6
  10   Thread 0x7f52565fd700 (LWP 2041) 0x00007f525d1a4965 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
  9    Thread 0x7f52567fe700 (LWP 2040) 0x00007f525d1a4965 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
  8    Thread 0x7f5258f7e700 (LWP 2037) 0x00007f525c07e20d in poll () from /lib64/libc.so.6
  7    Thread 0x7f525d5c3700 (LWP 2034) 0x00007f525c07e20d in poll () from /lib64/libc.so.6
  6    Thread 0x7f525bf8a700 (LWP 2035) 0x00007f525c07e20d in poll () from /lib64/libc.so.6
  5    Thread 0x7f525977f700 (LWP 2033) 0x00007f525c07e20d in poll () from /lib64/libc.so.6
  4    Thread 0x7f525b3ec700 (LWP 2030) 0x00007f525d1a4965 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
  3    Thread 0x7f525abeb700 (LWP 2031) 0x00007f525c07e20d in poll () from /lib64/libc.so.6
  2    Thread 0x7f525a3ea700 (LWP 2036) 0x00007f525d1a57c1 in pthread_getspecific () from /lib64/libpthread.so.0
* 1    Thread 0x7f525d5c8380 (LWP 2029) 0x00007f525bfc1207 in raise () from /lib64/libc.so.6
(gdb) p 0x7f525a3ea700
$1 = 139991678101248
(gdb) frame 4
#4  0x000000000049e38d in main (argc=<optimized out>, argv=<optimized out>) at main.cpp:1639
1639	main.cpp: No such file or directory.
(gdb) p GloMTH->mysql_threads[0]
$2 = {worker = 0x7f5258a00000, thread_id = 139991730370304}
(gdb) p GloMTH->mysql_threads[1]
$3 = {worker = 0x7f5257800000, thread_id = 139991707068160}
(gdb) p GloMTH->mysql_threads[2]
$4 = {worker = 0x7f5257dff000, thread_id = 139991678101248}
(gdb) p GloMTH->mysql_threads[3]
$5 = {worker = 0x7f5257000000, thread_id = 139991656687360}
(gdb) p GloMTH->mysql_threads[0].worker->atomic_curtime->_M_i
$6 = 3630728638095
(gdb) p GloMTH->mysql_threads[1].worker->atomic_curtime->_M_i
$7 = 3630729943023
(gdb) p GloMTH->mysql_threads[2].worker->atomic_curtime->_M_i
$8 = 3630698797403
(gdb) p GloMTH->mysql_threads[3].worker->atomic_curtime->_M_i
$9 = 3630729950013

As shown above, worker 2 atomic_curtime is far behind than the others.

I've a different case with a total of 20 worker threads and 4 of them are also stuck and not updating atomic_curtime:

(gdb) info threads
  Id   Target Id         Frame
  26   Thread 0x7fbfd9dff700 (LWP 41) 0x00007fbfe4afee2d in nanosleep () at ../sysdeps/unix/syscall-template.S:81
  25   Thread 0x7fbfdcdff700 (LWP 40) 0x00007fbfe4afee2d in nanosleep () at ../sysdeps/unix/syscall-template.S:81
  24   Thread 0x7fbfdd8fe700 (LWP 39) 0x00007fbfe4b2d20d in poll () at ../sysdeps/unix/syscall-template.S:81
  23   Thread 0x7fbfdfdfd700 (LWP 29) 0x00007fbfe4b2d20d in poll () at ../sysdeps/unix/syscall-template.S:81
  22   Thread 0x7fbfdddfd700 (LWP 37) 0x00007fbfe4b2d20d in poll () at ../sysdeps/unix/syscall-template.S:81
  21   Thread 0x7fbfe0cff700 (LWP 24) 0x00007fbfe4b2d20d in poll () at ../sysdeps/unix/syscall-template.S:81
  20   Thread 0x7fbfe01ff700 (LWP 27) 0x00007fbfe4b2d20d in poll () at ../sysdeps/unix/syscall-template.S:81
  19   Thread 0x7fbfddefe700 (LWP 36) 0x00007fbfe4b2d20d in poll () at ../sysdeps/unix/syscall-template.S:81
  18   Thread 0x7fbfe05fd700 (LWP 26) 0x00007fbfe4b2d20d in poll () at ../sysdeps/unix/syscall-template.S:81
  17   Thread 0x7fbfde5ff700 (LWP 34) 0x00007fbfe4b2d20d in poll () at ../sysdeps/unix/syscall-template.S:81
  16   Thread 0x7fbfe1b7e700 (LWP 22) 0x00007fbfe4b2d20d in poll () at ../sysdeps/unix/syscall-template.S:81
  15   Thread 0x7fbfdedff700 (LWP 32) 0x00007fbfe4b2d20d in poll () at ../sysdeps/unix/syscall-template.S:81
  14   Thread 0x7fbfe237f700 (LWP 19) 0x00007fbfe4b2d20d in poll () at ../sysdeps/unix/syscall-template.S:81
  13   Thread 0x7fbfdd9ff700 (LWP 38) 0x00007fbfe4b2d20d in poll () at ../sysdeps/unix/syscall-template.S:81
  12   Thread 0x7fbfdf4fe700 (LWP 31) 0x00007fbfe4b2d20d in poll () at ../sysdeps/unix/syscall-template.S:81
  11   Thread 0x7fbfe0bfe700 (LWP 25) 0x00007fbfe4b2d20d in poll () at ../sysdeps/unix/syscall-template.S:81
  10   Thread 0x7fbfe13ff700 (LWP 23) 0x00007fbfe4b2d20d in poll () at ../sysdeps/unix/syscall-template.S:81
  9    Thread 0x7fbfe2fea700 (LWP 21) 0x00007fbfe4b2d20d in poll () at ../sysdeps/unix/syscall-template.S:81
  8    Thread 0x7fbfe6077700 (LWP 20) 0x00007fbfe4b2d20d in poll () at ../sysdeps/unix/syscall-template.S:81
  7    Thread 0x7fbfde1ff700 (LWP 35) 0x00007fbfe5c566fd in read () at ../sysdeps/unix/syscall-template.S:81
  6    Thread 0x7fbfe3fec700 (LWP 17) pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
  5    Thread 0x7fbfe37eb700 (LWP 18) 0x00007fbfe4b2d20d in poll () at ../sysdeps/unix/syscall-template.S:81
  4    Thread 0x7fbfdf5ff700 (LWP 30) 0x00007fbfe5c566fd in read () at ../sysdeps/unix/syscall-template.S:81
  3    Thread 0x7fbfdfefe700 (LWP 28) 0x00007fbfe5c566fd in read () at ../sysdeps/unix/syscall-template.S:81
  2    Thread 0x7fbfdf1fd700 (LWP 33) 0x00007fbfe5c566fd in read () at ../sysdeps/unix/syscall-template.S:81
* 1    Thread 0x7fbfe607c380 (LWP 15) 0x00007fbfe4a70207 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:55


(gdb) p 0x7fbfdf1fd700
$1 = 140462058886912 (worker 13)
(gdb) p GloMTH->mysql_threads[13]
$2 = {worker = 0x7fbfdba00000, thread_id = 140462058886912}
(gdb) p 0x7fbfdfefe700
$3 = 140462072522496 (worker 8)
(gdb) p GloMTH->mysql_threads[8]
$4 = {worker = 0x7fbfdf1fe000, thread_id = 140462072522496}
(gdb) p 0x7fbfdf5ff700
$5 = 140462063089408 (worker 10)
(gdb) p GloMTH->mysql_threads[10]
$6 = {worker = 0x7fbfdce00000, thread_id = 140462063089408}
(gdb) p 0x7fbfde1ff700
$7 = 140462042117888 (worker 15)
(gdb) p GloMTH->mysql_threads[15]
$8 = {worker = 0x7fbfdb200000, thread_id = 140462042117888}


(gdb) p GloMTH->mysql_threads[0].worker->atomic_curtime->_M_i
$36 = 980577914073
(gdb) p GloMTH->mysql_threads[1].worker->atomic_curtime->_M_i
$37 = 980577904789
(gdb) p GloMTH->mysql_threads[2].worker->atomic_curtime->_M_i
$38 = 980578108359
(gdb) p GloMTH->mysql_threads[3].worker->atomic_curtime->_M_i
$39 = 980578114097
(gdb) p GloMTH->mysql_threads[4].worker->atomic_curtime->_M_i
$40 = 980578911808
(gdb) p GloMTH->mysql_threads[5].worker->atomic_curtime->_M_i
$41 = 980577216055
(gdb) p GloMTH->mysql_threads[6].worker->atomic_curtime->_M_i
$42 = 980577205057
(gdb) p GloMTH->mysql_threads[7].worker->atomic_curtime->_M_i
$43 = 980577520141
(gdb) p GloMTH->mysql_threads[8].worker->atomic_curtime->_M_i
$44 = 980562012246
(gdb) p GloMTH->mysql_threads[9].worker->atomic_curtime->_M_i
$45 = 980578813595
(gdb) p GloMTH->mysql_threads[10].worker->atomic_curtime->_M_i
$46 = 980570205683
(gdb) p GloMTH->mysql_threads[11].worker->atomic_curtime->_M_i
$47 = 980579011967
(gdb) p GloMTH->mysql_threads[12].worker->atomic_curtime->_M_i
$48 = 980577202637
(gdb) p GloMTH->mysql_threads[13].worker->atomic_curtime->_M_i
$49 = 980562001507
(gdb) p GloMTH->mysql_threads[14].worker->atomic_curtime->_M_i
$50 = 980578209164
(gdb) p GloMTH->mysql_threads[15].worker->atomic_curtime->_M_i
$51 = 980568902443
(gdb) p GloMTH->mysql_threads[16].worker->atomic_curtime->_M_i
$52 = 980577406441
(gdb) p GloMTH->mysql_threads[17].worker->atomic_curtime->_M_i
$53 = 980577602113
(gdb) p GloMTH->mysql_threads[18].worker->atomic_curtime->_M_i
$54 = 980578300112
(gdb) p GloMTH->mysql_threads[19].worker->atomic_curtime->_M_i
$55 = 980578108030

While all the workers have a time higher than 980577202637, workers 8, 10, 13 and 15 have its timer set to 980562012246, 980570205683, 980562001507 and 980568902443 respectively.

pt-pmp:

16 poll,MySQL_Thread::run,mysql_worker_thread_func,start_thread,clone
 4 read,sock_read,bread_conv,BIO_read,ssl3_read_n,ssl3_get_record,ssl3_read_bytes,ssl3_read,ssl_read_internal,SSL_read,ma_tls_read(openssl.c:600),ma_pvio_tls_read(ma_tls.c:89),ma_pvio_tls_read_async(ma_pvio.c:272),ma_pvio_read(ma_pvio.c:272),ma_pvio_cache_read(ma_pvio.c:360),ma_real_read(ma_net.c:376),ma_net_read(ma_net.c:430),ma_net_safe_read(mariadb_lib.c:193),mthd_my_read_rows(mariadb_lib.c:896),mthd_my_read_query_result(mariadb_lib.c:2164),mysql_real_query_start_internal(mariadb_async.c:381),my_context_spawn(ma_context.c:201)
 1 pthread_cond_wait,remove,HGCU_thread_run,libstdc++::??(libstdc++.so.6),start_thread,clone
 1 poll,poll_poll,ev_run,GTID_syncer_run,libstdc++::??(libstdc++.so.6),start_thread,clone
 1 poll,admin_main_loop,start_thread,clone
 1 nanosleep,usleep,Query_Cache::purgeHash_thread,mysql_shared_query_cache_funct,start_thread,clone
 1 nanosleep,usleep,MySQL_Monitor::run,libstdc++::??(libstdc++.so.6),start_thread,clone
 1 __GI_raise,__GI_abort,__assert_fail_base,__GI___assert_fail,main
 1 __GI_raise

I'm yet working in trying to get a repeatable test case. They may be unrelated, but both cases SSL is in use.

[kvkunkel]

Hi, I have a small update on the original problem in this issue. We found that the crashing can be stopped by disabling SSL in ProxySQL. We have tried to disable on half the hosts experiencing the problem and crashes stopped.

Is there any way to see which database host the individual workers are connected to? We have a network issue between the application servers and some of the database hosts.

[nboscia]

Hi, I'm also experiencing this same issue and about to put in a ticket with Percona. We had it crash on two servers today with no prior issues, just coredump out of nowhere. We also have SSL from ProxySQL to the database, it's federally-mandated and we cannot disable it. This is a HUGE blocker for us. There's already an SSL bug where the session close isn't done encrypted so it creates endless Aborted Connections in the error logs.

[renecannao]

Closing, this issue is not relevant anymore as TLS handling has improved a lot.