[MXS-2024] Crash in reauthenticate_client Created: 2018-08-24  Updated: 2018-08-29  Resolved: 2018-08-29

Status: Closed
Project: MariaDB MaxScale
Component/s: Protocol
Affects Version/s: 2.2.13
Fix Version/s: 2.2.14

Type: Bug Priority: Critical
Reporter: markus makela Assignee: markus makela
Resolution: Fixed Votes: 0
Labels: None


 Description   

This was reported by assen.totin in MXS-1760.

[maxscale@CGDSQLMAX1 ~]$ ==23197== Thread 6:
 
==23197== Invalid write of size 1
 
==23197==    at 0x4C2CAB0: strcpy (vg_replace_strmem.c:510)
 
==23197==    by 0xBB3FCDA: reauthenticate_client(session*, gwbuf*) (mysql_client.cc:1550)
 
==23197==    by 0xBB40209: route_by_statement(session*, unsigned long, gwbuf**) (mysql_client.cc:1691)
 
==23197==    by 0xBB3E38A: gw_read_finish_processing(dcb*, gwbuf*, unsigned long) (mysql_client.cc:1122)
 
==23197==    by 0xBB3E12C: gw_read_normal_data(dcb*, gwbuf*, int) (mysql_client.cc:1064)
 
==23197==    by 0xBB3C749: gw_read_client_event(dcb*) (mysql_client.cc:516)
 
==23197==    by 0x4EDBC3D: dcb_process_poll_events(dcb*, unsigned int) (dcb.cc:3084)
 
==23197==    by 0x4EDBFFB: dcb_handler(dcb*, unsigned int) (dcb.cc:3169)
 
==23197==    by 0x4EDC0A8: dcb_poll_handler(mxs_poll_data*, int, unsigned int) (dcb.cc:3205)
 
==23197==    by 0x4F3D3F2: maxscale::Worker::poll_waitevents() (worker.cc:1212)
 
==23197==    by 0x4F3C53B: maxscale::Worker::run() (worker.cc:892)
 
==23197==    by 0x4F3CF9B: maxscale::Worker::thread_main(void*) (worker.cc:1113)
 
==23197==  Address 0xf9af610 is 0 bytes after a block of size 304 alloc'd
 
==23197==    at 0x4C2B955: calloc (vg_replace_malloc.c:711)
 
==23197==    by 0x4EB7511: mxs_calloc (alloc.cc:58)
 
==23197==    by 0xB0FC64A: mysql_session_alloc (mysql_common.cc:42)
 
==23197==    by 0xBB3CF08: gw_read_do_authentication(dcb*, gwbuf*, int) (mysql_client.cc:666)
 
==23197==    by 0xBB3C72E: gw_read_client_event(dcb*) (mysql_client.cc:503)
 
==23197==    by 0x4EDBC3D: dcb_process_poll_events(dcb*, unsigned int) (dcb.cc:3084)
 
==23197==    by 0x4EDBFFB: dcb_handler(dcb*, unsigned int) (dcb.cc:3169)
 
==23197==    by 0x4EDC0A8: dcb_poll_handler(mxs_poll_data*, int, unsigned int) (dcb.cc:3205)
 
==23197==    by 0x4F3D3F2: maxscale::Worker::poll_waitevents() (worker.cc:1212)
 
==23197==    by 0x4F3C53B: maxscale::Worker::run() (worker.cc:892)
 
==23197==    by 0x4F3CF9B: maxscale::Worker::thread_main(void*) (worker.cc:1113)
 
==23197==    by 0x54EADD4: start_thread (in /usr/lib64/libpthread-2.17.so)
 
==23197== 
==23197== Invalid write of size 1
 
==23197==    at 0x4C2CAC3: strcpy (vg_replace_strmem.c:510)
 
==23197==    by 0xBB3FCDA: reauthenticate_client(session*, gwbuf*) (mysql_client.cc:1550)
 
==23197==    by 0xBB40209: route_by_statement(session*, unsigned long, gwbuf**) (mysql_client.cc:1691)
 
==23197==    by 0xBB3E38A: gw_read_finish_processing(dcb*, gwbuf*, unsigned long) (mysql_client.cc:1122)
 
==23197==    by 0xBB3E12C: gw_read_normal_data(dcb*, gwbuf*, int) (mysql_client.cc:1064)
 
==23197==    by 0xBB3C749: gw_read_client_event(dcb*) (mysql_client.cc:516)
 
==23197==    by 0x4EDBC3D: dcb_process_poll_events(dcb*, unsigned int) (dcb.cc:3084)
 
==23197==    by 0x4EDBFFB: dcb_handler(dcb*, unsigned int) (dcb.cc:3169)
 
==23197==    by 0x4EDC0A8: dcb_poll_handler(mxs_poll_data*, int, unsigned int) (dcb.cc:3205)
 
==23197==    by 0x4F3D3F2: maxscale::Worker::poll_waitevents() (worker.cc:1212)
 
==23197==    by 0x4F3C53B: maxscale::Worker::run() (worker.cc:892)
 
==23197==    by 0x4F3CF9B: maxscale::Worker::thread_main(void*) (worker.cc:1113)
 
==23197==  Address 0xf9af6d2 is 34 bytes inside a block of size 672 free'd
 
==23197==    at 0x4C2ACBD: free (vg_replace_malloc.c:530)
 
==23197==    by 0x621E0E5: ??? (in /usr/lib64/libsqlite3.so.0.8.6)
 
==23197==    by 0x621E424: ??? (in /usr/lib64/libsqlite3.so.0.8.6)
 
==23197==    by 0x621E6C7: sqlite3_prepare_v2 (in /usr/lib64/libsqlite3.so.0.8.6)
 
==23197==    by 0x621E784: sqlite3_exec (in /usr/lib64/libsqlite3.so.0.8.6)
 
==23197==    by 0xB72E8E4: validate_mysql_user (dbusers.c:272)
 
==23197==    by 0xB72CFE9: mysql_auth_authenticate (mysql_auth.c:288)
 
==23197==    by 0xBB3CFED: gw_read_do_authentication(dcb*, gwbuf*, int) (mysql_client.cc:702)
 
==23197==    by 0xBB3C72E: gw_read_client_event(dcb*) (mysql_client.cc:503)
 
==23197==    by 0x4EDBC3D: dcb_process_poll_events(dcb*, unsigned int) (dcb.cc:3084)
 
==23197==    by 0x4EDBFFB: dcb_handler(dcb*, unsigned int) (dcb.cc:3169)
 
==23197==    by 0x4EDC0A8: dcb_poll_handler(mxs_poll_data*, int, unsigned int) (dcb.cc:3205)
 
==23197==  Block was alloc'd at
 
==23197==    at 0x4C29BC3: malloc (vg_replace_malloc.c:299)
 
==23197==    by 0x61E92A6: ??? (in /usr/lib64/libsqlite3.so.0.8.6)
 
==23197==    by 0x61CC9D1: ??? (in /usr/lib64/libsqlite3.so.0.8.6)
 
==23197==    by 0x61CCB40: ??? (in /usr/lib64/libsqlite3.so.0.8.6)
 
==23197==    by 0x61CCBBC: ??? (in /usr/lib64/libsqlite3.so.0.8.6)
 
==23197==    by 0x621DED5: ??? (in /usr/lib64/libsqlite3.so.0.8.6)
 
==23197==    by 0x621E424: ??? (in /usr/lib64/libsqlite3.so.0.8.6)
 
==23197==    by 0x621E6C7: sqlite3_prepare_v2 (in /usr/lib64/libsqlite3.so.0.8.6)
 
==23197==    by 0x621E784: sqlite3_exec (in /usr/lib64/libsqlite3.so.0.8.6)
 
==23197==    by 0xB72E8E4: validate_mysql_user (dbusers.c:272)
 
==23197==    by 0xB72CFE9: mysql_auth_authenticate (mysql_auth.c:288)
 
==23197==    by 0xBB3CFED: gw_read_do_authentication(dcb*, gwbuf*, int) (mysql_client.cc:702)
 
==23197== 
==23197== Invalid read of size 1
 
==23197==    at 0x4C2CAB4: strcpy (vg_replace_strmem.c:510)
 
==23197==    by 0xB72DC6F: mysql_auth_reauthenticate (mysql_auth.c:669)
 
==23197==    by 0xBB3FD2F: reauthenticate_client(session*, gwbuf*) (mysql_client.cc:1555)
 
==23197==    by 0xBB40209: route_by_statement(session*, unsigned long, gwbuf**) (mysql_client.cc:1691)
 
==23197==    by 0xBB3E38A: gw_read_finish_processing(dcb*, gwbuf*, unsigned long) (mysql_client.cc:1122)
 
==23197==    by 0xBB3E12C: gw_read_normal_data(dcb*, gwbuf*, int) (mysql_client.cc:1064)
 
==23197==    by 0xBB3C749: gw_read_client_event(dcb*) (mysql_client.cc:516)
 
==23197==    by 0x4EDBC3D: dcb_process_poll_events(dcb*, unsigned int) (dcb.cc:3084)
 
==23197==    by 0x4EDBFFB: dcb_handler(dcb*, unsigned int) (dcb.cc:3169)
 
==23197==    by 0x4EDC0A8: dcb_poll_handler(mxs_poll_data*, int, unsigned int) (dcb.cc:3205)
 
==23197==    by 0x4F3D3F2: maxscale::Worker::poll_waitevents() (worker.cc:1212)
 
==23197==    by 0x4F3C53B: maxscale::Worker::run() (worker.cc:892)
 
==23197==  Address 0xf9af610 is 0 bytes after a block of size 304 alloc'd
 
==23197==    at 0x4C2B955: calloc (vg_replace_malloc.c:711)
 
==23197==    by 0x4EB7511: mxs_calloc (alloc.cc:58)
 
==23197==    by 0xB0FC64A: mysql_session_alloc (mysql_common.cc:42)
 
==23197==    by 0xBB3CF08: gw_read_do_authentication(dcb*, gwbuf*, int) (mysql_client.cc:666)
 
==23197==    by 0xBB3C72E: gw_read_client_event(dcb*) (mysql_client.cc:503)
 
==23197==    by 0x4EDBC3D: dcb_process_poll_events(dcb*, unsigned int) (dcb.cc:3084)
 
==23197==    by 0x4EDBFFB: dcb_handler(dcb*, unsigned int) (dcb.cc:3169)
 
==23197==    by 0x4EDC0A8: dcb_poll_handler(mxs_poll_data*, int, unsigned int) (dcb.cc:3205)
 
==23197==    by 0x4F3D3F2: maxscale::Worker::poll_waitevents() (worker.cc:1212)
 
==23197==    by 0x4F3C53B: maxscale::Worker::run() (worker.cc:892)
 
==23197==    by 0x4F3CF9B: maxscale::Worker::thread_main(void*) (worker.cc:1113)
 
==23197==    by 0x54EADD4: start_thread (in /usr/lib64/libpthread-2.17.so)
 
==23197== 
 
 
valgrind: m_mallocfree.c:307 (get_bszB_as_is): Assertion 'bszB_lo == bszB_hi' failed.
 
valgrind: Heap block lo/hi size mismatch: lo = 368, hi = 2048201833770919119.
 
This is probably caused by your program erroneously writing past the
 
end of a heap block and corrupting heap metadata.  If you fix any
 
invalid writes reported by Memcheck, this assertion failure will
 
probably go away.  Please try that before reporting this as a bug.
 
 
 
 
 
host stacktrace:
 
==23197==    at 0x5803FC3D: ??? (in /usr/lib64/valgrind/memcheck-amd64-linux)
 
==23197==    by 0x5803FD54: ??? (in /usr/lib64/valgrind/memcheck-amd64-linux)
 
==23197==    by 0x5803FEE1: ??? (in /usr/lib64/valgrind/memcheck-amd64-linux)
 
==23197==    by 0x5804D9F3: ??? (in /usr/lib64/valgrind/memcheck-amd64-linux)
 
==23197==    by 0x580390AB: ??? (in /usr/lib64/valgrind/memcheck-amd64-linux)
 
==23197==    by 0x58037923: ??? (in /usr/lib64/valgrind/memcheck-amd64-linux)
 
==23197==    by 0x5803BB1B: ??? (in /usr/lib64/valgrind/memcheck-amd64-linux)
 
==23197==    by 0x58036D3B: ??? (in /usr/lib64/valgrind/memcheck-amd64-linux)
 
==23197==    by 0x5801427C: ??? (in /usr/lib64/valgrind/memcheck-amd64-linux)
 
==23197==    by 0x1002D42845: ???
 
==23197==    by 0x1005F86F1F: ???
 
==23197==    by 0x1002010F7F: ???
 
==23197==    by 0xB72DC52: mysql_auth_reauthenticate (mysql_auth.c:668)
 
==23197==    by 0xA85F: ???
 
==23197==    by 0x1002010F7F: ???
 
 
 
sched status:
 
  running_tid=6
 
 
 
Thread 1: status = VgTs_WaitSys (lwpid 23197)
 
==23197==    at 0x7547113: ??? (in /usr/lib64/libc-2.17.so)
 
==23197==    by 0x4F3D149: maxscale::Worker::poll_waitevents() (worker.cc:1160)
 
==23197==    by 0x4F3C53B: maxscale::Worker::run() (worker.cc:892)
 
==23197==    by 0x409530: main (gateway.cc:2276)
 
 
 
Thread 2: status = VgTs_WaitSys (lwpid 23198)
 
==23197==    at 0x54EE945: pthread_cond_wait@@GLIBC_2.3.2 (in /usr/lib64/libpthread-2.17.so)
 
==23197==    by 0x4F31671: skygw_message_wait (skygw_utils.cc:640)
 
==23197==    by 0x4EF2A8D: thr_filewriter_fun(void*) (log_manager.cc:2328)
 
==23197==    by 0x54EADD4: start_thread (in /usr/lib64/libpthread-2.17.so)
 
==23197==    by 0x7546B3C: clone (in /usr/lib64/libc-2.17.so)
 
 
 
Thread 3: status = VgTs_WaitSys (lwpid 23199)
 
==23197==    at 0x54F1EED: ??? (in /usr/lib64/libpthread-2.17.so)
 
==23197==    by 0x4F33B12: thread_millisleep (thread.cc:70)
 
==23197==    by 0xAC7E28C: monitorMain(void*) (mariadbmon.cc:2202)
 
==23197==    by 0x54EADD4: start_thread (in /usr/lib64/libpthread-2.17.so)
 
==23197==    by 0x7546B3C: clone (in /usr/lib64/libc-2.17.so)
 
 
 
Thread 4: status = VgTs_WaitSys (lwpid 23200)
 
==23197==    at 0x54F1EED: ??? (in /usr/lib64/libpthread-2.17.so)
 
==23197==    by 0x409907: log_flush_cb(void*) (gateway.cc:2415)
 
==23197==    by 0x54EADD4: start_thread (in /usr/lib64/libpthread-2.17.so)
 
==23197==    by 0x7546B3C: clone (in /usr/lib64/libc-2.17.so)
 
 
 
Thread 5: status = VgTs_WaitSys (lwpid 23201)
 
==23197==    at 0x54F1EED: ??? (in /usr/lib64/libpthread-2.17.so)
 
==23197==    by 0x4F33B12: thread_millisleep (thread.cc:70)
 
==23197==    by 0x4EE273C: hkthread(void*) (housekeeper.cc:242)
 
==23197==    by 0x54EADD4: start_thread (in /usr/lib64/libpthread-2.17.so)
 
==23197==    by 0x7546B3C: clone (in /usr/lib64/libc-2.17.so)
 
 
 
Thread 6: status = VgTs_Runnable (lwpid 23202)
 
==23197==    at 0x4C2CAB4: strcpy (vg_replace_strmem.c:510)
 
==23197==    by 0xB72DC6F: mysql_auth_reauthenticate (mysql_auth.c:669)
 
==23197==    by 0xBB3FD2F: reauthenticate_client(session*, gwbuf*) (mysql_client.cc:1555)
 
 
 
Thread 7: status = VgTs_WaitSys (lwpid 23203)
 
==23197==    at 0x7547113: ??? (in /usr/lib64/libc-2.17.so)
 
==23197==    by 0x4FE4AB9: MHD_epoll (daemon.c:4267)
 
==23197==    by 0x4FE5F91: MHD_select_thread (daemon.c:4544)
 
==23197==    by 0x54EADD4: start_thread (in /usr/lib64/libpthread-2.17.so)
 
==23197==    by 0x7546B3C: clone (in /usr/lib64/libc-2.17.so)
 
 
 
 
 
Note: see also the FAQ in the source distribution.
 
It contains workarounds to several common problems.
 
In particular, if Valgrind aborted or crashed after
 
identifying problems in your program, there's a good chance
 
that fixing those problems will prevent Valgrind aborting or
 
crashing, especially if it happened in m_mallocfree.c.
 
 
 
If that doesn't help, please report this bug to: www.valgrind.org
 
 
 
In the bug report, send all the above text, the valgrind
 
version, and what OS and version you are using.  Thanks.



 Comments   
Comment by Assen Totin (Inactive) [ 2018-08-26 ]

DB dump uploaded on FTP as MXS-2024.sql.gz.

Restore to any DB name (name it's set in the client's config).

The client side is Matomo (formerly Piwik), the client uses their latest 3.5.1 release available for download here: https://builds.matomo.org/piwik.zip . DB access is configured in config/config.ini.php

Matomo uses PHP, the client has 7.0.27, but any 7.0 should do it. As the MaxScale crash is triggered by cron job, PHP CLI is needed.

To run the aggregation job that leads to MaxScale crash, execute:

php /path/to/piwik/console core:archive --url=https://piwik.curaprox.com

Alternatively, I have a TCP dump taken on the MaxScale node which includes the complete run up to crash. I can upload it if needed.

Comment by markus makela [ 2018-08-27 ]

This does appear to be caused by a misinterpretation of a LOAD DATA LOCAL INFILE. This time, it's the client protocol module that misinterprets the data. The crash is easily preventable but the root cause is harder to deal with. I've created MXS-2027 that relates to the aforementioned problem.

Generated at Thu Feb 08 04:11:08 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.