This could be related to MXS-1191.
Right, I also generated avsc file with the script (not the one written in Go).
I've build packages from commit a418387d0a8fa2372f78eb2fe351122c6b3ab024: http://max-tst-01.mariadb.com/ci-repository/2.0-apr20/mariadb-maxscale/
These packages contain the fixes for the handling of ALTER TABLE statements that can cause crashes.
Ok it seems to go a little further but I have a new stack :
2017-04-21 15:40:48 info : Processed 1 transactions and 0 row events.
|
2017-04-21 15:40:48 notice : End of binlog file [mariadb-bin.000032] at 1074063067. Rotating to file [mariadb-bin.000033].
|
2017-04-21 15:40:48 error : Failed to read field value 'code_account_externe', type 'string' at file offset 228993, record numer 0.
|
2017-04-21 15:40:48 error : Failed to read field value 'hash_code', type 'string' at file offset 82640, record numer 0.
|
2017-04-21 15:40:48 notice : Schema version 1 already exists: /var/lib/maxscale/avro/symwis.bank_mandate.000001.avsc
|
2017-04-21 15:40:48 error : Fatal: MaxScale 2.0.5 received fatal signal 11. Attempting backtrace.
|
2017-04-21 15:40:48 error : Commit ID: a418387d0a8fa2372f78eb2fe351122c6b3ab024 System name: Linux Release string: CentOS release 6.8 (Final)
|
2017-04-21 15:40:48 error : /usr/bin/maxscale() [0x403b9c]
|
2017-04-21 15:40:48 error : /lib64/libpthread.so.0(+0xf7e0) [0x7f9beb9757e0]
|
2017-04-21 15:40:48 error : /usr/lib64/maxscale/libavrorouter.so(+0x44678) [0x7f9be6520678]
|
2017-04-21 15:40:48 error : /usr/lib64/maxscale/libavrorouter.so(+0x43a40) [0x7f9be651fa40]
|
2017-04-21 15:40:49 error : /usr/lib64/maxscale/libavrorouter.so(avro_schema_record_field_get_index+0x2b) [0x7f9be651c156]
|
2017-04-21 15:40:49 error : /usr/lib64/maxscale/libavrorouter.so(+0x2d158) [0x7f9be6509158]
|
2017-04-21 15:40:49 error : /usr/lib64/maxscale/libavrorouter.so(process_row_event_data+0x12f) [0x7f9be64f34f3]
|
2017-04-21 15:40:49 error : /usr/lib64/maxscale/libavrorouter.so(handle_row_event+0x3e6) [0x7f9be64f2c94]
|
2017-04-21 15:40:49 error : /usr/lib64/maxscale/libavrorouter.so(avro_read_all_events+0x88d) [0x7f9be64f57b3]
|
2017-04-21 15:40:49 error : /usr/lib64/maxscale/libavrorouter.so(converter_func+0x8f) [0x7f9be64ece3a]
|
2017-04-21 15:40:49 error : /usr/lib64/maxscale/libmaxscale-common.so.1.0.0(+0x40bbe) [0x7f9bec286bbe]
|
2017-04-21 15:40:49 error : /lib64/libpthread.so.0(+0x7aa1) [0x7f9beb96daa1]
|
2017-04-21 15:40:49 error : /lib64/libc.so.6(clone+0x6d) [0x7f9bea4f3aad]
|
2017-04-21 15:40:49 info : Starting log flushing to disk.
|
The packages that were previously built didn't have the avrorouter module in the packages. I apologize for this inconvenience and I would like to ask you to test with these new packages and report if the crash still occurs.
The packages can be found here: http://max-tst-01.mariadb.com/ci-repository/2.0-may8/mariadb-maxscale/
No problems don't worry 
I flushed *.avro files, avro-conversion.ini and avro.index to start conversion from the begining. I tried again with this new build and here is a new stack :
2017-05-08 10:47:42 notice : replication-service: Request binlog records from mariadb-bin.000078 at position 151931758 from master server 192.168.80.48:3306
|
2017-05-08 10:47:42 notice : replication-service: identity seen by the master: server_id: 4000, uuid: fdb32ae2-33ca-11e7-a71c-0050569bd68b
|
2017-05-08 10:47:42 notice : replication-service: identity seen by the slaves: server_id: 3000, hostname: PP-DB-04, MySQL version: 10.0.25-MariaDB-wsrep
|
2017-05-08 10:47:42 [7] info : > Autocommit: [enabled], trx is [not open], cmd: UNKNOWN MYSQL PACKET TYPE, type: N/A, stmt: nK
|
2017-05-08 10:47:42 [7] info : Route query to master 192.168.80.38:3306 <
|
2017-05-08 10:47:42 error : Error packet in binlog stream.mariadb-bin.000078 @ 151931758.
|
2017-05-08 10:47:42 info : qc_sqlite: In-memory sqlite database successfully opened for thread 139755272529664.
|
2017-05-08 10:47:43 notice : Schema version 1 already exists: /var/lib/maxscale/avro/bbdb._partition.000001.avsc
|
2017-05-08 10:47:43 notice : Schema version 1 already exists: /var/lib/maxscale/avro/bbdb.mediator_execution.000001.avsc
|
2017-05-08 10:47:43 error : debug assert /home/vagrant/workspace/server/modules/routing/avro/avro_rbr.c:559
|
2017-05-08 10:47:43 info : Starting log flushing to disk.
|
2017-05-08 10:47:43 error : Fatal: MaxScale 2.0.5 received fatal signal 6. Attempting backtrace.
|
2017-05-08 10:47:43 error : Commit ID: ade2cef8527406b8591fdf2c014422383fb4efc3 System name: Linux Release string: CentOS release 6.8 (Final)
|
2017-05-08 10:47:43 error : /usr/bin/maxscale() [0x403f85]
|
2017-05-08 10:47:43 error : /lib64/libpthread.so.0(+0xf7e0) [0x7f1b5c6947e0]
|
2017-05-08 10:47:43 error : /lib64/libc.so.6(gsignal+0x35) [0x7f1b5b15c5e5]
|
2017-05-08 10:47:43 error : /lib64/libc.so.6(abort+0x175) [0x7f1b5b15ddc5]
|
2017-05-08 10:47:43 error : /lib64/libc.so.6(+0x2b70e) [0x7f1b5b15570e]
|
2017-05-08 10:47:43 error : /lib64/libc.so.6(__assert_perror_fail+0) [0x7f1b5b1557d0]
|
2017-05-08 10:47:43 error : /usr/lib64/maxscale/libavrorouter.so(process_row_event_data+0x754) [0x7f1b571eb59f]
|
2017-05-08 10:47:43 error : /usr/lib64/maxscale/libavrorouter.so(handle_row_event+0x470) [0x7f1b571ea6d4]
|
2017-05-08 10:47:43 error : /usr/lib64/maxscale/libavrorouter.so(avro_read_all_events+0x92b) [0x7f1b571edb23]
|
2017-05-08 10:47:43 error : /usr/lib64/maxscale/libavrorouter.so(converter_func+0xc0) [0x7f1b571e3756]
|
2017-05-08 10:47:43 error : /usr/lib64/maxscale/libmaxscale-common.so.1.0.0(+0x43e39) [0x7f1b5cfa8e39]
|
2017-05-08 10:47:43 error : /lib64/libpthread.so.0(+0x7aa1) [0x7f1b5c68caa1]
|
2017-05-08 10:47:43 error : /lib64/libc.so.6(clone+0x6d) [0x7f1b5b212aad]
|
2017-05-08 10:47:43 info : Starting log flushing to disk.
|
2017-05-08 10:47:43 info : Starting log flushing to disk.
|
Thanks for the swift response! This stack trace will really help as it triggered a debug assertion which tells us exactly where things went wrong.
I found a bug in the fixed length string processing in the avrorouter wher I was pointed to by the debug assertion in that stack trace. It could possibly cause a crash if long fixed length strings were used. This bug is not present with variable length strings so an immediate fix to this is to change the types from CHAR to VARCHAR.
The fix is quite simple and later I can provide packages for testing and verification so that we can be sure that the bug is fixed on your end.
I've built packages from commit 898bc3444eadae7a72d9c19a741ec678bcfe18cc which you can find here: http://max-tst-01.mariadb.com/ci-repository/2.0-may9/mariadb-maxscale/
These packages should fix the problems with fixed length strings and I'm cautiously optimistic that the root cause of these crashes is fixed. I thank you for reporting these problems and taking the time to test our fixes.
I'm glad to help ! And thank you too for being so reactive.
I just install this new package and I've got a new debug assertion a little further from the last one :
2017-05-10 10:31:19 error : Error packet in binlog stream.mariadb-bin.000078 @ 151931758.
|
2017-05-10 10:31:19 info : qc_sqlite: In-memory sqlite database successfully opened for thread 140261820724992.
|
2017-05-10 10:31:20 notice : Schema version 1 already exists: /var/lib/maxscale/avro/bbdb._partition.000001.avsc
|
2017-05-10 10:31:20 notice : Schema version 1 already exists: /var/lib/maxscale/avro/bbdb.mediator_execution.000001.avsc
|
2017-05-10 10:31:20 error : debug assert /home/vagrant/workspace/server/modules/routing/avro/avro_rbr.c:578
|
2017-05-10 10:31:20 info : Starting log flushing to disk.
|
2017-05-10 10:31:20 error : Fatal: MaxScale 2.0.5 received fatal signal 6. Attempting backtrace.
|
2017-05-10 10:31:20 error : Commit ID: 898bc3444eadae7a72d9c19a741ec678bcfe18cc System name: Linux Release string: CentOS release 6.8 (Final)
|
2017-05-10 10:31:20 error : /usr/bin/maxscale() [0x403f85]
|
2017-05-10 10:31:20 error : /lib64/libpthread.so.0(+0xf7e0) [0x7f914ea1e7e0]
|
2017-05-10 10:31:20 error : /lib64/libc.so.6(gsignal+0x35) [0x7f914d4e65e5]
|
2017-05-10 10:31:20 error : /lib64/libc.so.6(abort+0x175) [0x7f914d4e7dc5]
|
2017-05-10 10:31:20 error : /lib64/libc.so.6(+0x2b70e) [0x7f914d4df70e]
|
2017-05-10 10:31:20 error : /lib64/libc.so.6(__assert_perror_fail+0) [0x7f914d4df7d0]
|
2017-05-10 10:31:20 error : /usr/lib64/maxscale/libavrorouter.so(process_row_event_data+0x7a9) [0x7f91495755f4]
|
2017-05-10 10:31:20 error : /usr/lib64/maxscale/libavrorouter.so(handle_row_event+0x470) [0x7f91495746d4]
|
2017-05-10 10:31:20 error : /usr/lib64/maxscale/libavrorouter.so(avro_read_all_events+0x92b) [0x7f9149577b7b]
|
2017-05-10 10:31:20 error : /usr/lib64/maxscale/libavrorouter.so(converter_func+0xc0) [0x7f914956d756]
|
2017-05-10 10:31:20 error : /usr/lib64/maxscale/libmaxscale-common.so.1.0.0(+0x43e39) [0x7f914f332e39]
|
2017-05-10 10:31:20 error : /lib64/libpthread.so.0(+0x7aa1) [0x7f914ea16aa1]
|
2017-05-10 10:31:20 error : /lib64/libc.so.6(clone+0x6d) [0x7f914d59caad]
|
2017-05-10 10:31:20 info : Starting log flushing to disk.
|
Hmm, it still seems to be the same part of code. Would you happen to have a way to reproduce this crash without providing the exact binlogs?
If you don't have a simple way of reproducing this, you could upload the binlog files confidentially to ftp://ftp.mariadb.com/uploads where can look at them.
I don't really know how to reproduce it and I can't manage to connect to the ftp, I'm using FileZilla on ftp.mariadb.com port 21 with anonymous authentication (tried with my JIRA credentials too) and default folder to /uploads/ but it doesn't work, am I doing something wrong ?
If you have curl installed, the following should work.
curl -T <file> ftp://ftp.mariadb.com/uploads/
|
where <file> is the file to upload.
For FileZilla, connect to ftp.mariadb.com and then navigate to the private subdirectory. There you can upload the files.
My bad, it was a network restriction on my side. I uploaded a file named "MXS-1216.tar.gz" containing the binlog into private folder.
I've managed to reproduce the crash with the binlog and I'm proceeding with my investigation. I will post an update once I've figured out why it crashes.
Which version of the server were these binlogs created with?
MariaDB [(none)]> show global variables like 'version%';
| Variable_name | Value |
| version | 10.0.25-MariaDB-wsrep |
| version_comment | MariaDB Server, wsrep_25.13.raf7f02e |
| version_compile_machine | x86_64 |
| version_compile_os | Linux |
Upon further investigation, the problem seems to be the DATETIME type processing for events created by a MariaDB 10.0 server. This can be reproduced with the following test case on a 10.0 server.
create table t1(d datetime(3)); |
insert into t1 values (now()); |
There doesn't seem to be an immediate workaround for this apart from using a MariaDB 10.1 server. The replication events generated by the 10.1 server use a newer format which is processed correctly. I'll continue my investigations into finding a way to resolve this issue.
I've created packages from commit 5a0d2c54bd564688af44695067953ac16a09ee85 which fixes the crash on 10.0 DATETIME(1..6). The packages can be found here: http://max-tst-01.mariadb.com/ci-repository/2.0-may15/mariadb-maxscale/
Tried this new build :
2017-05-15 16:43:17 notice : Schema version 1 already exists: /var/lib/maxscale/avro/bbdb._partition.000001.avsc
|
2017-05-15 16:43:17 info : Table Map for 'bbdb._partition' at 407
|
2017-05-15 16:43:17 info : Row Event for 'bbdb._partition' at 460
|
2017-05-15 16:43:17 info : Row 1
|
2017-05-15 16:43:17 notice : Schema version 1 already exists: /var/lib/maxscale/avro/bbdb.mediator_execution.000001.avsc
|
2017-05-15 16:43:17 info : Table Map for 'bbdb.mediator_execution' at 591
|
2017-05-15 16:43:17 info : Row Event for 'bbdb.mediator_execution' at 666
|
2017-05-15 16:43:17 info : Row 2
|
2017-05-15 16:43:17 info : [3] VARCHAR: field: 765 bytes, data: 20 bytes
|
2017-05-15 16:43:17 info : [4] TEMPORAL: 588112-91-51 25:06:88
|
2017-05-15 16:43:17 info : [5] TEMPORAL: 55713-83-27 23:66:73
|
2017-05-15 16:43:17 info : [7] NULL
|
2017-05-15 16:43:17 info : [8] NULL
|
2017-05-15 16:43:17 info : [9] CHAR: field: 87 bytes, data: 48 bytes
|
2017-05-15 16:43:17 error : debug assert /home/vagrant/workspace/server/modules/routing/avro/avro_rbr.c:597
|
2017-05-15 16:43:17 info : Starting log flushing to disk.
|
2017-05-15 16:43:17 error : Fatal: MaxScale 2.0.5 received fatal signal 6. Attempting backtrace.
|
2017-05-15 16:43:17 error : Commit ID: 5a0d2c54bd564688af44695067953ac16a09ee85 System name: Linux Release string: CentOS release 6.8 (Final)
|
2017-05-15 16:43:17 error : /usr/bin/maxscale() [0x403f85]
|
2017-05-15 16:43:17 error : /lib64/libpthread.so.0(+0xf7e0) [0x7ff70a1947e0]
|
2017-05-15 16:43:17 error : /lib64/libc.so.6(gsignal+0x35) [0x7ff708c5c5e5]
|
2017-05-15 16:43:17 error : /lib64/libc.so.6(abort+0x175) [0x7ff708c5ddc5]
|
2017-05-15 16:43:17 error : /lib64/libc.so.6(+0x2b70e) [0x7ff708c5570e]
|
2017-05-15 16:43:17 error : /lib64/libc.so.6(__assert_perror_fail+0) [0x7ff708c557d0]
|
2017-05-15 16:43:17 error : /usr/lib64/maxscale/libavrorouter.so(process_row_event_data+0x957) [0x7ff704ceaf62]
|
2017-05-15 16:43:17 error : /usr/lib64/maxscale/libavrorouter.so(handle_row_event+0x4f6) [0x7ff704ce9e94]
|
2017-05-15 16:43:17 error : /usr/lib64/maxscale/libavrorouter.so(avro_read_all_events+0x94b) [0x7ff704ced6f6]
|
2017-05-15 16:43:17 error : /usr/lib64/maxscale/libavrorouter.so(converter_func+0xc0) [0x7ff704ce28a6]
|
2017-05-15 16:43:17 error : /usr/lib64/maxscale/libmaxscale-common.so.1.0.0(+0x43ec9) [0x7ff70aaa8ec9]
|
2017-05-15 16:43:17 error : /lib64/libpthread.so.0(+0x7aa1) [0x7ff70a18caa1]
|
2017-05-15 16:43:17 error : /lib64/libc.so.6(clone+0x6d) [0x7ff708d12aad]
|
2017-05-15 16:43:17 info : Starting log flushing to disk.
|
Could it be possible to get the table definition for the table which was being processed? I believe the table in question is mediator_execution.
I suspect that a DATETIME value with sub-second precision might be causing these problems. I have encountered some problems when defining the DATETIME values with 10.0 as DATETIME(0).
I don't have DATETIME(0) in this table, only DATETIME(3) :
MariaDB [bbdb]> desc mediator_execution;
|
+---------------------------+------------------+------+-----+---------+-------+
|
| Field | Type | Null | Key | Default | Extra |
|
+---------------------------+------------------+------+-----+---------+-------+
|
| id | int(11) unsigned | NO | PRI | NULL | |
|
| mediator_configuration_fk | int(11) unsigned | YES | MUL | NULL | |
|
| mediator_entity_fk | int(11) unsigned | YES | MUL | NULL | |
|
| local_bean | varchar(255) | NO | | NULL | |
|
| start_date | datetime(3) | NO | | NULL | |
|
| end_date | datetime(3) | NO | | NULL | |
|
| status | smallint(5) | YES | | NULL | |
|
| exception | text | YES | | NULL | |
|
| message | varchar(255) | YES | | NULL | |
|
| tx_uid | char(29) | NO | | NULL | |
|
| manual | tinyint(1) | NO | | 0 | |
|
+---------------------------+------------------+------+-----+---------+-------+
|
11 rows in set (0.00 sec)
|
Thanks for the table definition, I'll continue my investigations. I'll post updates when I have more information.
Would it be possible for you to upload the binlog in question that is causing the crash? I haven't been able to reproduce the crash locally.
I think it's still the same binlog as before, do you want me to reupload it ?
Curious, I was able to convert the whole binlog without a crash. I'll take a closer look at the binlog again.
Here is the avro-conversion.ini content :
[avro-conversion]
|
position=526
|
gtid=0-38-45225:2
|
file=mariadb-bin.000032
|
Ah, this is due to the fact that I lack the .avsc schema files for those tables. I'll be able to create them using the table definition you provided.
Oh yes I had to create them with a script, I thought that it would be able to create them itself as it was a fresh load on the db but for some reasons create statements where missing from the binlog position I set (it wasn't a fresh mariadb database).
I managed to reproduce the crash by defining the schema for the table. I had to add two extra fields to the Avro schema to store the real type and the length of each field.
If the field doesn't define the two new fields, real_type and length, then the conversion process crashes due to a debug assertion. By adding the extra information to the DATETIME fields I'm able to convert the binlog corretly:
...
|
{
|
"name": "start_date", |
"type": "string", |
"real_type": "datetime", |
"length": 3 |
},
|
...
|
You can manually add the fields to the schema or use this Python script to generate them: https://github.com/mariadb-corporation/MaxScale/blob/2.0-avro-datetime/server/modules/protocol/examples/cdc_schema.py
I will regenerate all avsc schema files to be sure to have the correct format for each table.
Finally I had to edit the file (I can't run the script as I'm on CentOs 6 and it seems that there is no python3/mysql connector for CentOs 6) and it seems to run smoothly I will probably have to edit other file if I understand well (every datetime field right ?).
Yes, all DATETIME fields that have a precision definition e.g. DATETIME(3). This is only for 10.0 and 10.1 should generate correct events regardless of the DATETIME precision.
I'll regenerate avsc files from a CentOs 7 VM and put them on my CentOs 6 VM and try to convert the whole binlogs.
Closing as fixed. Please reopen this if you find any problems.