[MXS-2298] Maxscale crashed after binlog service was enabled Created: 2019-01-28  Updated: 2019-07-05  Resolved: 2019-07-05

Status: Closed
Project: MariaDB MaxScale
Component/s: binlogrouter
Affects Version/s: 2.3.2
Fix Version/s: N/A

Type: Bug Priority: Critical
Reporter: Maikel Punie Assignee: markus makela
Resolution: Incomplete Votes: 0
Labels: None
Environment:

CentOS Linux release 7.6.1810 (Core)
kernel: 3.10.0-693.11.1.el7.x86_64



 Description   

When enabling the binlog router, maxscale starts to crash.

2019-01-28 14:06:57   notice : (22977) BinLogSVC: 'CHANGE MASTER TO executed'. Previous state MASTER_HOST='_none_', MASTER_PORT=3306, MASTER_LOG_FILE='', MASTER_LOG_POS=0, MASTER_USER='repl'. New state is MASTER_HOST='10.255.10.32', MASTER_PORT=3306, MASTER_LOG_FILE='', MASTER_LOG_POS=4, MASTER_USER='repl', MASTER_USE_GTID=Slave_pos, MASTER_HEARTBEAT_PERIOD=300, MASTER_CONNECT_RETRY=60
2019-01-28 14:07:14   notice : (22977) BinLogSVC: START SLAVE executed by repl@::ffff:138.203.240.20. Trying connection to master [10.255.10.32]:3306, binlog , pos 4, transaction safe pos 4
2019-01-28 14:07:14   warning: Protocol module 'mysqlbackend' has been deprecated, use 'mariadbbackend' instead.
2019-01-28 14:07:14   notice : BinLogSVC: attempting to connect to master server [10.255.10.32]:3306, binlog='', pos=4, GTID=0-1-31441169129
2019-01-28 14:07:14   notice : (22977) [BinLogSVC] No users were loaded but 'inject_service_user' is enabled. Enabling service credentials for authentication until database users have been successfully loaded.
2019-01-28 14:07:14   notice : (23580) BinLogSVC: identity seen by the master: Server_id: 9, Slave_UUID: fa40d93a-22f8-11e9-a374-002590137cfc, Host: harvey
2019-01-28 14:07:14   notice : (23580) BinLogSVC: identity seen by the slaves: server_id: 10, hostname: harvey, MySQL version: 10.3.11-MariaDB-log
 
 
2019-01-28 14:08:10   alert  : (23580) Fatal: MaxScale 2.3.2 received fatal signal 6. Attempting backtrace.
2019-01-28 14:08:10   alert  : (23580) Commit ID: 1126c687a4570f60ee26a163520198a3263ccbbd System name: Linux Release string: CentOS Linux release 7.6.1810 (Core) 
2019-01-28 14:08:10   alert  : (23580)   /usr/bin/maxscale(_ZN7maxbase15dump_stacktraceESt8functionIFvPKcS2_EE+0x2b) [0x40cbeb]: /home/vagrant/MaxScale/maxutils/maxbase/src/stacktrace.cc:130
2019-01-28 14:08:10   alert  : (23580)   /usr/bin/maxscale(_ZN7maxbase15dump_stacktraceEPFvPKcS1_E+0x4e) [0x40cf4e]: /usr/include/c++/4.8.2/functional:2029
2019-01-28 14:08:10   alert  : (23580)   /usr/bin/maxscale() [0x4095c9]: ??:0
2019-01-28 14:08:10   alert  : (23580)   /lib64/libpthread.so.0(+0xf5d0) [0x7ff85937c5d0]: sigaction.c:?
2019-01-28 14:08:10   alert  : (23580)   /lib64/libpthread.so.0(fsync+0x2d) [0x7ff85937bd1d]: :?
2019-01-28 14:08:10   alert  : (23580)   /lib64/libsqlite3.so.0(+0x3288c) [0x7ff85863488c]: ??:?
2019-01-28 14:08:10   alert  : (23580)   /lib64/libsqlite3.so.0(+0x26ae7) [0x7ff858628ae7]: ??:?
2019-01-28 14:08:10   alert  : (23580)   /lib64/libsqlite3.so.0(+0x4a9e5) [0x7ff85864c9e5]: ??:?
2019-01-28 14:08:10   alert  : (23580)   /lib64/libsqlite3.so.0(+0x4ac0a) [0x7ff85864cc0a]: ??:?
2019-01-28 14:08:10   alert  : (23580)   /lib64/libsqlite3.so.0(+0x5abeb) [0x7ff85865cbeb]: ??:?
2019-01-28 14:08:10   alert  : (23580)   /lib64/libsqlite3.so.0(+0x7342c) [0x7ff85867542c]: ??:?
nm: /lib64/libsqlite3.so.0: no symbols
2019-01-28 14:08:10   alert  : (23580)   /lib64/libsqlite3.so.0(sqlite3_step+0x2bf) [0x7ff858675d1f]: ??:0
nm: /lib64/libsqlite3.so.0: no symbols
2019-01-28 14:08:10   alert  : (23580)   /lib64/libsqlite3.so.0(sqlite3_exec+0x10a) [0x7ff85866b81a]: ??:0
2019-01-28 14:08:10   alert  : (23580)   /usr/lib64/maxscale/libbinlogrouter.so(_Z21blr_save_mariadb_gtidP15ROUTER_INSTANCE+0x217) [0x7ff84f27ad57]: /home/vagrant/MaxScale/server/modules/routing/binlogrouter/blr_file.cc:4382
2019-01-28 14:08:10   alert  : (23580)   /usr/lib64/maxscale/libbinlogrouter.so(_Z20blr_handle_one_eventP10mxs_routerR10rep_headerPhji+0x733) [0x7ff84f280c63]: /home/vagrant/MaxScale/server/modules/routing/binlogrouter/blr_event.cc:383
2019-01-28 14:08:10   alert  : (23580)   /usr/lib64/maxscale/libbinlogrouter.so(_Z24blr_handle_binlog_recordP15ROUTER_INSTANCEP5gwbuf+0x118) [0x7ff84f260da8]: /home/vagrant/MaxScale/server/modules/routing/binlogrouter/blr_master.cc:1064
2019-01-28 14:08:10   alert  : (23580)   /usr/lib64/maxscale/libbinlogrouter.so(+0x129e5) [0x7ff84f2629e5]: /home/vagrant/MaxScale/server/modules/routing/binlogrouter/blr_master.cc:2835
2019-01-28 14:08:10   alert  : (23580)   /usr/lib64/maxscale/libbinlogrouter.so(_Z19blr_master_responseP15ROUTER_INSTANCEP5gwbuf+0x19b) [0x7ff84f26385b]: /home/vagrant/MaxScale/server/modules/routing/binlogrouter/blr_master.cc:595
2019-01-28 14:08:10   alert  : (23580)   /usr/lib64/maxscale/libbinlogrouter.so(+0xa1f9) [0x7ff84f25a1f9]: /home/vagrant/MaxScale/server/modules/routing/binlogrouter/blr.cc:2338
2019-01-28 14:08:10   alert  : (23580)   /usr/lib64/maxscale/libmariadbbackend.so(+0x433b) [0x7ff84e7da33b]: /home/vagrant/MaxScale/server/modules/protocol/MySQL/mariadbbackend/mysql_backend.cc:1038
2019-01-28 14:08:10   alert  : (23580)   /usr/lib64/maxscale/libmaxscale-common.so.1.0.0(+0x7a907) [0x7ff859aa6907]: /home/vagrant/MaxScale/server/core/dcb.cc:3127
2019-01-28 14:08:10   alert  : (23580)   /usr/lib64/maxscale/libmaxscale-common.so.1.0.0(+0x7aaab) [0x7ff859aa6aab]: /home/vagrant/MaxScale/server/core/dcb.cc:3219
2019-01-28 14:08:10   alert  : (23580)   /usr/lib64/maxscale/libmaxscale-common.so.1.0.0(_ZN7maxbase6Worker15poll_waiteventsEv+0x1b5) [0x7ff859b02505]: /home/vagrant/MaxScale/maxutils/maxbase/src/worker.cc:844
2019-01-28 14:08:11   alert  : (23580)   /usr/lib64/maxscale/libmaxscale-common.so.1.0.0(_ZN7maxbase6Worker3runEPNS_9SemaphoreE+0x51) [0x7ff859b02701]: /home/vagrant/MaxScale/maxutils/maxbase/src/worker.cc:545
2019-01-28 14:08:11   alert  : (23580)   /usr/bin/maxscale(main+0x2019) [0x4087f9]: /home/vagrant/MaxScale/server/core/gateway.cc:2260
2019-01-28 14:08:11   alert  : (23580)   /lib64/libc.so.6(__libc_start_main+0xf5) [0x7ff8572793d5]: ??:?
2019-01-28 14:08:11   alert  : (23580)   /usr/bin/maxscale() [0x409022]: ??:0



 Comments   
Comment by markus makela [ 2019-01-28 ]

Were there any errors before the crash? It looks like it was trying to use the SQLite database that holds the GTID information when the crash occurred.

Comment by Maikel Punie [ 2019-01-28 ]

here are the lines between a restart and the crash

2019-01-28 13:33:58   notice : Started REST API on [127.0.0.1]:8989
2019-01-28 13:33:58   notice : MaxScale started with 8 worker threads, each with a stack size of 8388608 bytes.
2019-01-28 13:59:29   warning: [MySQLAuth] ReadWriteSVC: login attempt for user 'maxscale'@[138.203.240.20]:48296, authentication failed. User not f
ound.
2019-01-28 13:59:42   warning: [MySQLAuth] ReadWriteSVC: login attempt for user 'repl'@[138.203.240.20]:48360, authentication failed. User not found
.
2019-01-28 14:02:16   warning: (20449) Slave server 'maric': response (0xff) differs from master's response (0x00) to COM_QUERY: `SET @@global.gtid_
slave_pos='0-1-31441169129'`. Closing slave connection due to inconsistent session state.
2019-01-28 14:02:16   warning: (20449) Slave server 'hans': response (0xff) differs from master's response (0x00) to COM_QUERY: `SET @@global.gtid_s
lave_pos='0-1-31441169129'`. Closing slave connection due to inconsistent session state.
2019-01-28 14:02:16   warning: (20449) Slave server 'eduard': response (0xff) differs from master's response (0x00) to COM_QUERY: `SET @@global.gtid
_slave_pos='0-1-31441169129'`. Closing slave connection due to inconsistent session state.
2019-01-28 14:02:16   warning: (20449) Slave server 'albert': response (0xff) differs from master's response (0x00) to COM_QUERY: `SET @@global.gtid
_slave_pos='0-1-31441169129'`. Closing slave connection due to inconsistent session state.
2019-01-28 14:06:57   notice : (22977) BinLogSVC: 'CHANGE MASTER TO executed'. Previous state MASTER_HOST='_none_', MASTER_PORT=3306, MASTER_LOG_FIL
E='', MASTER_LOG_POS=0, MASTER_USER='repl'. New state is MASTER_HOST='10.255.10.32', MASTER_PORT=3306, MASTER_LOG_FILE='', MASTER_LOG_POS=4, MASTER_
USER='repl', MASTER_USE_GTID=Slave_pos, MASTER_HEARTBEAT_PERIOD=300, MASTER_CONNECT_RETRY=60
2019-01-28 14:07:14   notice : (22977) BinLogSVC: START SLAVE executed by repl@::ffff:138.203.240.20. Trying connection to master [10.255.10.32]:330
6, binlog , pos 4, transaction safe pos 4
2019-01-28 14:07:14   warning: (22977) The user for service 'BinLogSVC' might be missing the SELECT grant on `mysql.roles_mapping` or `mysql.user`. 
Use of default roles is disabled until the missing privileges are added. Error was: SELECT command denied to user 'repl'@'10.255.10.39' for table 'r
oles_mapping'
2019-01-28 14:07:14   error  : (22977) Failed to load users from server 'binlog_router_master_host': Access denied for user 'repl'@'%' to database '
mysql'
2019-01-28 14:07:14   warning: Protocol module 'mysqlbackend' has been deprecated, use 'mariadbbackend' instead.
2019-01-28 14:07:14   notice : BinLogSVC: attempting to connect to master server [10.255.10.32]:3306, binlog='', pos=4, GTID=0-1-31441169129
2019-01-28 14:07:14   notice : (22977) [BinLogSVC] No users were loaded but 'inject_service_user' is enabled. Enabling service credentials for authe
ntication until database users have been successfully loaded.
2019-01-28 14:07:14   notice : (23580) BinLogSVC: identity seen by the master: Server_id: 9, Slave_UUID: fa40d93a-22f8-11e9-a374-002590137cfc, Host:
 harvey
2019-01-28 14:07:14   notice : (23580) BinLogSVC: identity seen by the slaves: server_id: 10, hostname: harvey, MySQL version: 10.3.11-MariaDB-log
2019-01-28 14:08:10   alert  : (23580) Fatal: MaxScale 2.3.2 received fatal signal 6. Attempting backtrace.
2019-01-28 14:08:10   alert  : (23580) Commit ID: 1126c687a4570f60ee26a163520198a3263ccbbd System name: Linux Release string: CentOS Linux release 7

Comment by Maikel Punie [ 2019-01-30 ]

Today it happend again, and all the binlog items are commented out in the config file, so it has nothing todo with the binlog router

2019-01-30 11:40:55   error  : (685923) Unexpected internal state: received response 0x00 from server 'eduard' when no response was expected. Command: 0x00 Query: <not available>
2019-01-30 11:40:55   error  : (685923) Unexpected internal state: received response 0x00 from server 'eduard' when no response was expected. Command: 0x00 Query: <not available>
2019-01-30 11:40:55   error  : (685923) Unexpected internal state: received response 0x00 from server 'eduard' when no response was expected. Command: 0x00 Query: <not available>
2019-01-30 11:40:55   error  : (685923) Unexpected internal state: received response 0x00 from server 'eduard' when no response was expected. Command: 0x00 Query: <not available>
2019-01-30 11:40:55   error  : (685923) Unexpected internal state: received response 0x00 from server 'eduard' when no response was expected. Command: 0x00 Query: <not available>
2019-01-30 11:40:55   error  : (685923) Unexpected internal state: received response 0x00 from server 'eduard' when no response was expected. Command: 0x00 Query: <not available>
2019-01-30 11:40:55   error  : (685923) Unexpected internal state: received response 0x00 from server 'eduard' when no response was expected. Command: 0x00 Query: <not available>
2019-01-30 11:40:55   error  : (685923) Unexpected internal state: received response 0x00 from server 'eduard' when no response was expected. Command: 0x00 Query: <not available>
2019-01-30 15:13:16   alert  : Fatal: MaxScale 2.3.2 received fatal signal 11. Attempting backtrace.
2019-01-30 15:13:16   alert  : Commit ID: 1126c687a4570f60ee26a163520198a3263ccbbd System name: Linux Release string: CentOS Linux release 7.6.1810 (Core)
2019-01-30 15:13:16   alert  :   /usr/bin/maxscale(_ZN7maxbase15dump_stacktraceESt8functionIFvPKcS2_EE+0x2b) [0x40cbeb]: /home/vagrant/MaxScale/maxutils/maxbase/src/stacktrace.cc:130
2019-01-30 15:13:16   alert  :   /usr/bin/maxscale(_ZN7maxbase15dump_stacktraceEPFvPKcS1_E+0x4e) [0x40cf4e]: /usr/include/c++/4.8.2/functional:2029
2019-01-30 15:13:16   alert  :   /usr/bin/maxscale() [0x4095c9]: ??:0
2019-01-30 15:13:16   alert  :   /lib64/libpthread.so.0(+0xf5d0) [0x7f2c3775b5d0]: sigaction.c:?
2019-01-30 15:13:16   alert  :   /usr/lib64/maxscale/libmysqlcommon.so.2.0.0(mysql_protocol_done+0x12) [0x7f2c2d876c72]: /home/vagrant/MaxScale/server/modules/protocol/MySQL/mysql_common.cc:79
2019-01-30 15:13:16   alert  :   /usr/lib64/maxscale/libmariadbclient.so(+0x3371) [0x7f2c2da83371]: /home/vagrant/MaxScale/server/modules/protocol/MySQL/mariadbclient/mysql_client.cc:1497
2019-01-30 15:13:16   alert  :   /usr/lib64/maxscale/libmaxscale-common.so.1.0.0(dcb_final_close+0x488) [0x7f2c37e86e08]: /home/vagrant/MaxScale/server/core/dcb.cc:1237
2019-01-30 15:13:16   alert  :   /usr/lib64/maxscale/libmaxscale-common.so.1.0.0(_ZN8maxscale13RoutingWorker14delete_zombiesEv+0x34) [0x7f2c37ebf7a4]: /usr/include/c++/4.8.2/bits/stl_vector.h:734
2019-01-30 15:13:16   alert  :   /usr/lib64/maxscale/libmaxscale-common.so.1.0.0(_ZN8maxscale13RoutingWorker10epoll_tickEv+0x26) [0x7f2c37ec0016]: /home/vagrant/MaxScale/server/core/routingworker.cc:641
2019-01-30 15:13:16   alert  :   /usr/lib64/maxscale/libmaxscale-common.so.1.0.0(_ZN7maxbase6Worker15poll_waiteventsEv+0x326) [0x7f2c37ee1676]: /home/vagrant/MaxScale/maxutils/maxbase/src/worker.cc:762
2019-01-30 15:13:16   alert  :   /usr/lib64/maxscale/libmaxscale-common.so.1.0.0(_ZN7maxbase6Worker3runEPNS_9SemaphoreE+0x51) [0x7f2c37ee1701]: /home/vagrant/MaxScale/maxutils/maxbase/src/worker.cc:545
2019-01-30 15:13:16   alert  :   /lib64/libstdc++.so.6(+0xb5070) [0x7f2c3678f070]: ??:?
2019-01-30 15:13:16   alert  :   /lib64/libpthread.so.0(+0x7dd5) [0x7f2c37753dd5]: pthread_create.c:?
2019-01-30 15:13:16   alert  :   /lib64/libc.so.6(clone+0x6d) [0x7f2c35733ead]: ??:?

Comment by markus makela [ 2019-01-30 ]

That looks like MXS-2217 which was fixed in 2.3.3.

Comment by Maikel Punie [ 2019-01-30 ]

indeed, this one seems unrelated

Comment by Maikel Punie [ 2019-02-04 ]

i was just able to reproduce the original bug with 2.3.3, notice the timestamps, there was a 1.5 minuts gap in the logging ...
During this log gap maxctrl is not responding at all, the cpuload goes through the roof and the disk where we write the binlog to is almost idle

The timestmap GAP:

2019-02-04 06:41:02   notice : (2428) BinLogSVC: identity seen by the slaves: server_id: 10, hostname: harvey, MySQL version: 10.3.11-MariaDB-log
2019-02-04 06:43:37   alert  : (2428) Fatal: MaxScale 2.3.3 received fatal signal 6. Attempting backtrace.

The log:

MariaDB MaxScale  /var/log/maxscale/maxscale.log  Mon Feb  4 06:36:56 2019
----------------------------------------------------------------------------
2019-02-04 06:36:56   notice : syslog logging is enabled.
2019-02-04 06:36:56   notice : maxlog logging is enabled.
2019-02-04 06:36:56   notice : Using up to 9.35GiB of memory for query classifier cache
2019-02-04 06:36:56   notice : Working directory: /var/log/maxscale
2019-02-04 06:36:56   notice : The collection of SQLite memory allocation statistics turned off.
2019-02-04 06:36:56   notice : Threading mode of SQLite set to Multi-thread.
2019-02-04 06:36:56   notice : MariaDB MaxScale 2.3.3 started (Commit: 28644e9626ad16cb30a2f715b8fa9e3a8df5583b)
2019-02-04 06:36:56   notice : MaxScale is running in process 2047
2019-02-04 06:36:56   notice : Configuration file: /etc/maxscale.cnf
2019-02-04 06:36:56   notice : Log directory: /var/log/maxscale
2019-02-04 06:36:56   notice : Data directory: /var/lib/maxscale
2019-02-04 06:36:56   notice : Module directory: /usr/lib64/maxscale
2019-02-04 06:36:56   notice : Service cache: /var/cache/maxscale
2019-02-04 06:36:56   notice : No query classifier specified, using default 'qc_sqlite'.
2019-02-04 06:36:56   notice : Loaded module qc_sqlite: V1.0.0 from /usr/lib64/maxscale/libqc_sqlite.so
2019-02-04 06:36:56   notice : Query classification results are cached and reused. Memory used per thread: 1.17GiB
2019-02-04 06:36:56   notice : The systemd watchdog is Enabled. Internal timeout = 30s
2019-02-04 06:36:56   notice : Loading /etc/maxscale.cnf.
2019-02-04 06:36:56   notice : /etc/maxscale.cnf.d does not exist, not reading.
2019-02-04 06:36:56   notice : Loaded module mariadbclient: V1.1.0 from /usr/lib64/maxscale/libmariadbclient.so
2019-02-04 06:36:56   notice : Initialise binlog router module.
2019-02-04 06:36:56   notice : Loaded module binlogrouter: V2.1.0 from /usr/lib64/maxscale/libbinlogrouter.so
2019-02-04 06:36:56   notice : Initializing statement-based read/write split router module.
2019-02-04 06:36:56   notice : Loaded module readwritesplit: V1.1.0 from /usr/lib64/maxscale/libreadwritesplit.so
2019-02-04 06:36:56   notice : Initialise readconnroute router module.
2019-02-04 06:36:56   notice : Loaded module readconnroute: V2.0.0 from /usr/lib64/maxscale/libreadconnroute.so
2019-02-04 06:36:56   notice : Initialise the MariaDB Monitor module.
2019-02-04 06:36:56   notice : Loaded module mariadbmon: V1.5.0 from /usr/lib64/maxscale/libmariadbmon.so
2019-02-04 06:36:56   notice : Loaded module mariadbbackend: V2.0.0 from /usr/lib64/maxscale/libmariadbbackend.so
2019-02-04 06:36:56   notice : Loaded module MySQLBackendAuth: V1.0.0 from /usr/lib64/maxscale/libmysqlbackendauth.so
2019-02-04 06:36:56   notice : BinLogSVC: storing binlog files in 'tree' mode using GTID domain_id and server_id
2019-02-04 06:36:56   notice : BinLogSVC: Service has MariaDB GTID otion set to ON
2019-02-04 06:36:56   notice : BinLogSVC: Service has transaction safety option set to ON
2019-02-04 06:36:56   notice : Validating last binlog file '0/1/mysql-bin.002718' ...
2019-02-04 06:36:57   notice : 1548652763 @ 256, GTID List Event, (Mon Jan 28 06:19:23 2019), First EventTime
2019-02-04 06:36:57   notice : 1548680417 @ 748468963, Transaction ID Event (2 Phase Commit), (Mon Jan 28 14:00:17 2019), Last EventTime
2019-02-04 06:36:57   notice : Transaction Summary for binlog 'mysql-bin.002718'
                        Description                    Total          Average              Max
                        No. of Transactions              412
                        No. of Events                    867              2.1                3
                        No. of Bytes                  104.6k           259.9B           378.0B
2019-02-04 06:36:57   notice : Loaded module MySQLAuth: V1.1.0 from /usr/lib64/maxscale/libmysqlauth.so
2019-02-04 06:36:57   notice : Housekeeper thread started.
2019-02-04 06:36:57   notice : Encrypted password file /var/lib/maxscale/.secrets can't be accessed (No such file or directory). Password encryption is not used.
2019-02-04 06:36:57   notice : Loaded server states from journal file: /var/lib/maxscale/Antwerp/monitor.dat
2019-02-04 06:36:57   notice : Starting a total of 4 services...
2019-02-04 06:36:57   notice : [BinLogSVC] Loaded 155 MySQL users for listener ReplLST.
2019-02-04 06:36:57   notice : Listening for connections at [::]:6605 with protocol MySQL
2019-02-04 06:36:57   notice : Service 'BinLogSVC' started (1/4)
2019-02-04 06:36:58   notice : [ReadWriteSVC] Loaded 157 MySQL users for listener WriteLST-242.
2019-02-04 06:36:58   notice : Listening for connections at [138.203.16.242]:3306 with protocol MySQL
2019-02-04 06:36:58   notice : [ReadWriteSVC] Loaded 157 MySQL users for listener WriteLST-130.
2019-02-04 06:36:58   notice : Listening for connections at [138.203.16.130]:3306 with protocol MySQL
2019-02-04 06:36:58   notice : Service 'ReadWriteSVC' started (2/4)
2019-02-04 06:36:58   notice : [WriteSVC] Loaded 157 MySQL users for listener BWriteLST.
2019-02-04 06:36:58   notice : Listening for connections at [10.255.10.39]:3306 with protocol MySQL
2019-02-04 06:36:58   notice : Service 'WriteSVC' started (3/4)
2019-02-04 06:36:58   notice : [ReadSVC] Loaded 157 MySQL users for listener BReadLST.
2019-02-04 06:36:58   notice : Listening for connections at [10.255.10.38]:3306 with protocol MySQL
2019-02-04 06:36:59   notice : [ReadSVC] Loaded 157 MySQL users for listener ReadLST-129.
2019-02-04 06:36:59   notice : Listening for connections at [138.203.16.129]:3306 with protocol MySQL
2019-02-04 06:36:59   notice : Service 'ReadSVC' started (4/4)
2019-02-04 06:37:01   notice : Started REST API on [127.0.0.1]:8989
2019-02-04 06:37:01   notice : MaxScale started with 8 worker threads, each with a stack size of 8388608 bytes.
2019-02-04 06:37:02   warning: Protocol module 'mysqlbackend' has been deprecated, use 'mariadbbackend' instead.
2019-02-04 06:37:02   notice : BinLogSVC: attempting to connect to master server [10.255.10.32]:3306, binlog='mysql-bin.002718', pos=748468994, GTID=0-1-1376560919
2019-02-04 06:37:02   notice : (10) BinLogSVC: Request binlog records from mysql-bin.002718 at position 748468994 from master server [10.255.10.32]:3306
2019-02-04 06:37:02   notice : (10) BinLogSVC: identity seen by the master: Server_id: 9, Slave_UUID: e2cc217e-283e-11e9-bbe8-002590137cfc, Host: harvey
2019-02-04 06:37:02   notice : (10) BinLogSVC: identity seen by the slaves: server_id: 10, hostname: harvey, MySQL version: 10.3.11-MariaDB-log
2019-02-04 06:37:02   error  : (10) Error packet in binlog stream (mysql-bin.002718@748468994): Could not find GTID state requested by slave in any 
binlog files. Probably the slave state is too old and required binlog files have been purged.
2019-02-04 06:37:02   notice : (10) BinLogSVC: Master 10.255.10.32 disconnected after 0 seconds. 1 events read.
2019-02-04 06:37:41   warning: [MySQLAuth] WriteSVC: login attempt for user 'root'@[10.255.10.39]:42368, authentication failed. User not found.
2019-02-04 06:38:54   notice : BinLogSVC: Slave ::ffff:127.0.0.1, server id 0, disconnected after 35 seconds. 2 SQL commands
2019-02-04 06:39:38   notice : BinLogSVC: Slave ::ffff:127.0.0.1, server id 0, disconnected after 15 seconds. 1 SQL commands
2019-02-04 06:39:47   warning: [MySQLAuth] BinLogSVC: login attempt for user 'repl'@[::ffff:127.0.0.1]:50996, authentication failed. User not found.
2019-02-04 06:41:01   notice : (2167) BinLogSVC: START SLAVE executed by repl@::ffff:127.0.0.1. Trying connection to master [10.255.10.32]:3306, binlog mysql-bin.002718, pos 748468994, transaction safe pos 748468994
2019-02-04 06:41:01   notice : BinLogSVC: attempting to connect to master server [10.255.10.32]:3306, binlog='mysql-bin.002718', pos=748468994, GTID=0-1-31590485797
2019-02-04 06:41:02   notice : (2428) BinLogSVC: Request binlog records from mysql-bin.002718 at position 748468994 from master server [10.255.10.32]:3306
2019-02-04 06:41:02   notice : (2428) BinLogSVC: identity seen by the master: Server_id: 9, Slave_UUID: e2cc217e-283e-11e9-bbe8-002590137cfc, Host: harvey
2019-02-04 06:41:02   notice : (2428) BinLogSVC: identity seen by the slaves: server_id: 10, hostname: harvey, MySQL version: 10.3.11-MariaDB-log
2019-02-04 06:43:37   alert  : (2428) Fatal: MaxScale 2.3.3 received fatal signal 6. Attempting backtrace.
2019-02-04 06:43:37   alert  : (2428) Commit ID: 28644e9626ad16cb30a2f715b8fa9e3a8df5583b System name: Linux Release string: CentOS Linux release 7.6.1810 (Core) 
2019-02-04 06:43:37   alert  : (2428)   /usr/bin/maxscale(_ZN7maxbase15dump_stacktraceESt8functionIFvPKcS2_EE+0x2b) [0x40cbab]: /home/vagrant/MaxScale/maxutils/maxbase/src/stacktrace.cc:130
2019-02-04 06:43:37   alert  : (2428)   /usr/bin/maxscale(_ZN7maxbase15dump_stacktraceEPFvPKcS1_E+0x4e) [0x40cf0e]: /usr/include/c++/4.8.2/functional:2029
2019-02-04 06:43:37   alert  : (2428)   /usr/bin/maxscale() [0x4095b9]: ??:0
2019-02-04 06:43:37   alert  : (2428)   /lib64/libpthread.so.0(+0xf5d0) [0x7fb5f31b25d0]: sigaction.c:?
2019-02-04 06:43:37   alert  : (2428)   /lib64/libpthread.so.0(fsync+0x2d) [0x7fb5f31b1d1d]: :?
2019-02-04 06:43:37   alert  : (2428)   /lib64/libsqlite3.so.0(+0x3288c) [0x7fb5f246a88c]: ??:?
2019-02-04 06:43:37   alert  : (2428)   /lib64/libsqlite3.so.0(+0x4aa5d) [0x7fb5f2482a5d]: ??:?
2019-02-04 06:43:37   alert  : (2428)   /lib64/libsqlite3.so.0(+0x4ac0a) [0x7fb5f2482c0a]: ??:?
2019-02-04 06:43:37   alert  : (2428)   /lib64/libsqlite3.so.0(+0x5abeb) [0x7fb5f2492beb]: ??:?
2019-02-04 06:43:37   alert  : (2428)   /lib64/libsqlite3.so.0(+0x7342c) [0x7fb5f24ab42c]: ??:?
nm: /lib64/libsqlite3.so.0: no symbols
2019-02-04 06:43:37   alert  : (2428)   /lib64/libsqlite3.so.0(sqlite3_step+0x2bf) [0x7fb5f24abd1f]: ??:0
nm: /lib64/libsqlite3.so.0: no symbols
2019-02-04 06:43:37   alert  : (2428)   /lib64/libsqlite3.so.0(sqlite3_exec+0x10a) [0x7fb5f24a181a]: ??:0
2019-02-04 06:43:37   alert  : (2428)   /usr/lib64/maxscale/libbinlogrouter.so(_Z21blr_save_mariadb_gtidP15ROUTER_INSTANCE+0x217) [0x7fb5e9095d57]: /home/vagrant/MaxScale/server/modules/routing/binlogrouter/blr_file.cc:4382
2019-02-04 06:43:37   alert  : (2428)   /usr/lib64/maxscale/libbinlogrouter.so(_Z20blr_handle_one_eventP10mxs_routerR10rep_headerPhji+0x733) [0x7fb5e909bc63]: /home/vagrant/MaxScale/server/modules/routing/binlogrouter/blr_event.cc:383
2019-02-04 06:43:37   alert  : (2428)   /usr/lib64/maxscale/libbinlogrouter.so(_Z24blr_handle_binlog_recordP15ROUTER_INSTANCEP5gwbuf+0x118) [0x7fb5e907bda8]: /home/vagrant/MaxScale/server/modules/routing/binlogrouter/blr_master.cc:1064
2019-02-04 06:43:37   alert  : (2428)   /usr/lib64/maxscale/libbinlogrouter.so(+0x129e5) [0x7fb5e907d9e5]: /home/vagrant/MaxScale/server/modules/routing/binlogrouter/blr_master.cc:2835
2019-02-04 06:43:37   alert  : (2428)   /usr/lib64/maxscale/libbinlogrouter.so(_Z19blr_master_responseP15ROUTER_INSTANCEP5gwbuf+0x19b) [0x7fb5e907e85b]: /home/vagrant/MaxScale/server/modules/routing/binlogrouter/blr_master.cc:595
2019-02-04 06:43:37   alert  : (2428)   /usr/lib64/maxscale/libbinlogrouter.so(+0xa1f9) [0x7fb5e90751f9]: /home/vagrant/MaxScale/server/modules/routing/binlogrouter/blr.cc:2338
2019-02-04 06:43:37   alert  : (2428)   /usr/lib64/maxscale/libmariadbbackend.so(+0x438b) [0x7fb5e85f438b]: /home/vagrant/MaxScale/server/modules/protocol/MySQL/mariadbbackend/mysql_backend.cc:1039
2019-02-04 06:43:37   alert  : (2428)   /usr/lib64/maxscale/libmaxscale-common.so.1.0.0(+0x7b9f7) [0x7fb5f38dd9f7]: /home/vagrant/MaxScale/server/core/dcb.cc:3136
2019-02-04 06:43:37   alert  : (2428)   /usr/lib64/maxscale/libmaxscale-common.so.1.0.0(+0x7bb9b) [0x7fb5f38ddb9b]: /home/vagrant/MaxScale/server/core/dcb.cc:3228
2019-02-04 06:43:37   alert  : (2428)   /usr/lib64/maxscale/libmaxscale-common.so.1.0.0(_ZN7maxbase6Worker15poll_waiteventsEv+0x1b5) [0x7fb5f3939885]: /home/vagrant/MaxScale/maxutils/maxbase/src/worker.cc:844
2019-02-04 06:43:37   alert  : (2428)   /usr/lib64/maxscale/libmaxscale-common.so.1.0.0(_ZN7maxbase6Worker3runEPNS_9SemaphoreE+0x51) [0x7fb5f3939a81]: /home/vagrant/MaxScale/maxutils/maxbase/src/worker.cc:545
2019-02-04 06:43:37   alert  : (2428)   /usr/bin/maxscale(main+0x2019) [0x4087f9]: /home/vagrant/MaxScale/server/core/gateway.cc:2259
2019-02-04 06:43:38   alert  : (2428)   /lib64/libc.so.6(__libc_start_main+0xf5) [0x7fb5f10af3d5]: ??:?
2019-02-04 06:43:38   alert  : (2428)   /usr/bin/maxscale() [0x409022]: ??:0
 
 
MariaDB MaxScale  /var/log/maxscale/maxscale.log  Mon Feb  4 06:43:38 2019

Comment by markus makela [ 2019-02-05 ]

Can you reproduce this with a clean /var/lib/maxscale/ and clean binlogdir?

Comment by Maikel Punie [ 2019-02-05 ]

that scenario from yesterday was on a clean server, a fresh install...
i only copied over the maxscale.cnf file in /etc

Comment by Maikel Punie [ 2019-02-06 ]

i tried the scenario this morning, removing all files from maxscale on the disk.
and the same crash happend.

This is the content of the binlogs dir

[root@harvey binlogs]# ls
0  cache  gtid_maps.db  gtid_maps.db-journal  master.ini

And i can open the sallite gtids_maps.db

[root@harvey binlogs]# sqlite3 gtid_maps.db
SQLite version 3.7.17 2013-05-20 00:56:22
Enter ".help" for instructions
Enter SQL statements terminated with a ";"
sqlite> select * from gtid_maps;
1|0|1|0||mysql-bin.002764|4|4
2|0|1|1535574207||mysql-bin.002764|674951779|674952191
3|0|1|1535574215||mysql-bin.002764|674954953|674955363
.....
55|0|1|1535574631||mysql-bin.002764|675117619|675117899
56|0|1|1535574639||mysql-bin.002764|675117899|675118358
sqlite> 

Comment by markus makela [ 2019-03-25 ]

I believe we met at MariaDB OpenWorks and discussed (even debugged ) this issue. Is this still a problem?

Comment by Maikel Punie [ 2019-03-25 ]

indeed, of we keep the gtid disabled it all works as expected

Comment by markus makela [ 2019-07-05 ]

I'll close this now: if it still appears with the latest issue, please reopen this.

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