From 9bfefa95ae10c245ab6b8fbe78cc09b2c33dd0e7 Mon Sep 17 00:00:00 2001 From: MassimilianoPinto Date: Tue, 8 Sep 2015 17:27:28 +0200 Subject: [PATCH] maxbinlogcheck update maxbinlogcheck update --- Documentation/Reference/MaxBinlogCheck.md | 327 ++++++++++++++++++ server/modules/routing/binlog/blr_file.c | 19 +- .../modules/routing/binlog/maxbinlogcheck.c | 7 +- 3 files changed, 343 insertions(+), 10 deletions(-) create mode 100644 Documentation/Reference/MaxBinlogCheck.md diff --git a/Documentation/Reference/MaxBinlogCheck.md b/Documentation/Reference/MaxBinlogCheck.md new file mode 100644 index 000000000..8a8c90c0a --- /dev/null +++ b/Documentation/Reference/MaxBinlogCheck.md @@ -0,0 +1,327 @@ +# Maxbinlogcheck + +# The MySQL/MariaDB binlog check utility + +Massimiliano Pinto + +Last Updated: 08th September 2015 + +# Overview + +Maxbinlogcheck is a command line utility for checkiing binlogfiles downloaded by MaxScale binlog router or the MySQL/MariaDB binlog files stored in a database server acting as a master in a replication environement. +It checks the binlog file against any corruption and incomplete transaction stored and reports a transaction summary after reading all the events. +It may optionally truncate binlog file. + +Maxbinlogcheck supports + +* MariaDB 5.5 and MySQL 5.6 + +* MariaDB 10.0 with a command line option + +# Running maxbinlogcheck +``` +# /usr/local/bin/maxbinlogcheck /path_to_file/bin.000002 +``` + +# Command Line Switches + +The maxbinlogcheck command accepts a number of switches + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + +
SwitchLong OptionDescription
-f--fixIf the option is set the binlog file will be truncated at last safe transaction pos in case of any error
-M--mariadb10Check the current binlog against MariaDB 10.0.x events
-d--debugSet the debug mode. If set the FD Events, Rotate events and opening/closing transactions are displayed.
-?--helpPrint usage information regarding maxbinlogcheck
-V--versionPrint the maxbinlogcheck version information
+ +## Example without debug: + +1) No transactions + +``` +[root@maxscale-02 build]# /usr/local/bin/maxbinlogcheck /servers/binlogs/new-trx/mar-bin.000002 +2015-09-08 09:38:03 maxbinlogcheck 1.0.0 +2015-09-08 09:38:03 Checking /servers/binlogs/new-trx/mar-bin.000002 (mar-bin.000002), size 290 bytes +2015-09-08 09:38:03 Transaction Summary: + Description Total Average Max + No. of Transactions 0 +2015-09-08 09:38:03 Check retcode: 0, Binlog Pos = 290 +``` + +2) With complete transactions + +``` +[root@maxscale-02 build]# /usr/local/bin/maxbinlogcheck /servers/binlogs/new-trx/mar-bin.000004 +2015-09-08 09:38:35 maxbinlogcheck 1.0.0 +2015-09-08 09:38:35 Checking /servers/binlogs/new-trx/mar-bin.000004 (mar-bin.000004), size 38738629 bytes +2015-09-08 09:38:36 Transaction Summary: + Description Total Average Max + No. of Transactions 21713 + No. of Events 186599 8.6 5082 + No. of Bytes 36M 1k 5M +2015-09-08 09:38:36 Check retcode: 0, Binlog Pos = 38738629 +``` + +## Example with debug: + +1) one complete transaction + +``` +[root@maxscale-02 build]# /usr/local/bin/maxbinlogcheck /servers/binlogs/new-trx/mar-bin.000001 -d +2015-09-08 09:36:49 maxbinlogcheck 1.0.0 +2015-09-08 09:36:49 Checking /servers/binlogs/new-trx/mar-bin.000001 (mar-bin.000001), size 590760698 bytes +2015-09-08 09:36:49 - Format Description event FDE @ 4, size 241 +2015-09-08 09:36:49 FDE ServerVersion [ 5.5.35-MariaDB-log] +2015-09-08 09:36:49 FDE Header EventLength 19, N. of supported MySQL/MariaDB events 160 +2015-09-08 09:36:49 FDE Checksum alg desc 1, alg type BINLOG_CHECKSUM_ALG_CRC32 +2015-09-08 09:36:49 > Transaction starts @ pos 572 +2015-09-08 09:36:49 Transaction XID @ pos 572, closing @ 590760644 +2015-09-08 09:36:49 < Transaction @ pos 572, is now closed @ 590760644. 18001 events seen +2015-09-08 09:36:49 End of binlog file [mar-bin.000001] at 590760698. +2015-09-08 09:36:49 Transaction Summary: + Description Total Average Max + No. of Transactions 1 + No. of Events 18001 18001.0 18001 + No. of Bytes 563M 563M 563M +2015-09-08 09:36:49 Check retcode: 0, Binlog Pos = 590760698 +``` + +2) some transactions + +``` +[root@maxscale-02 build]# /usr/local/bin/maxbinlogcheck /servers/binlogs/new-trx/mar-bin.000004 -d +2015-09-08 10:19:35 maxbinlogcheck 1.0.0 +2015-09-08 10:19:35 Checking /servers/binlogs/new-trx/mar-bin.000004 (mar-bin.000004), size 38738629 bytes +2015-09-08 10:19:35 - Format Description event FDE @ 4, size 241 +2015-09-08 10:19:35 FDE ServerVersion [ 5.5.35-MariaDB-log] +2015-09-08 10:19:35 FDE Header EventLength 19, N. of supported MySQL/MariaDB events 160 +2015-09-08 10:19:35 FDE Checksum alg desc 1, alg type BINLOG_CHECKSUM_ALG_CRC32 +2015-09-08 10:19:35 > Transaction starts @ pos 971 +2015-09-08 10:19:35 Transaction XID @ pos 971, closing @ 1128 +2015-09-08 10:19:35 < Transaction @ pos 971, is now closed @ 1128. 3 events seen +... +2015-09-08 10:19:51 > Transaction starts @ pos 33440561 +2015-09-08 10:19:51 Transaction XID @ pos 33440561, closing @ 33440763 +2015-09-08 10:19:51 < Transaction @ pos 33440561, is now closed @ 33440763. 3 events seen +2015-09-08 10:19:51 > Transaction starts @ pos 33440794 +2015-09-08 10:19:51 Transaction XID @ pos 33440794, closing @ 38738553 +2015-09-08 10:19:51 < Transaction @ pos 33440794, is now closed @ 38738553. 5082 events seen +2015-09-08 10:19:51 - Rotate event @ 38738584, next file is [mar-bin.000005] @ 4 +2015-09-08 10:19:51 End of binlog file [mar-bin.000004] at 38738629. +2015-09-08 10:19:51 Transaction Summary: + Description Total Average Max + No. of Transactions 21713 + No. of Events 186599 8.6 5082 + No. of Bytes 36M 1k 5M +2015-09-08 10:19:51 Check retcode: 0, Binlog Pos = 38738629 +``` + +3) No transactions + +``` +2015-09-08 09:41:02 Check retcode: 0, Binlog Pos = 290 +[root@maxscale-02 build]# /usr/local/bin/maxbinlogcheck /servers/binlogs/new-trx/mar-bin.000002 -d +2015-09-08 09:41:08 maxbinlogcheck 1.0.0 +2015-09-08 09:41:08 Checking /servers/binlogs/new-trx/mar-bin.000002 (mar-bin.000002), size 290 bytes +2015-09-08 09:41:08 - Format Description event FDE @ 4, size 241 +2015-09-08 09:41:08 FDE ServerVersion [ 5.5.35-MariaDB-log] +2015-09-08 09:41:08 FDE Header EventLength 19, N. of supported MySQL/MariaDB events 160 +2015-09-08 09:41:08 FDE Checksum alg desc 1, alg type BINLOG_CHECKSUM_ALG_CRC32 +2015-09-08 09:41:08 - Rotate event @ 245, next file is [mar-bin.000003] @ 4 +2015-09-08 09:41:08 End of binlog file [mar-bin.000002] at 290. +2015-09-08 09:41:08 Transaction Summary: + Description Total Average Max + No. of Transactions 0 +2015-09-08 09:41:08 Check retcode: 0, Binlog Pos = 290 +``` + +## Fixing a corrupted binlog file + +This file is corrupted, as reported by the utility: + +``` +2015-09-08 10:03:16 maxbinlogcheck 1.0.0 +2015-09-08 10:03:16 Checking /servers/binlogs/new-trx/bin.000002 (bin.000002), size 109498 bytes +2015-09-08 10:03:16 Event size error: size 0 at 290. +2015-09-08 10:03:16 warning : an error has been found. Setting safe pos to 245, current pos 290 +2015-09-08 10:03:16 Check retcode: 1, Binlog Pos = 245 +``` + +The suggested safe pos is 245 + +Use -f option for fix with debug: + +``` +[root@maxscale-02 build]# /usr/local/bin/maxbinlogcheck /servers/binlogs/new-trx/bin.000002 -d -f +2015-09-08 09:56:52 maxbinlogcheck 1.0.0 +2015-09-08 09:56:52 Checking /servers/binlogs/new-trx/bin.000002 (bin.000002), size 109498 bytes +2015-09-08 09:56:52 - Format Description event FDE @ 4, size 241 +2015-09-08 09:56:52 FDE ServerVersion [ 5.5.35-MariaDB-log] +2015-09-08 09:56:52 FDE Header EventLength 19, N. of supported MySQL/MariaDB events 160 +2015-09-08 09:56:52 FDE Checksum alg desc 1, alg type BINLOG_CHECKSUM_ALG_CRC32 +2015-09-08 09:56:52 - Rotate event @ 245, next file is [mar-bin.000003] @ 4 +2015-09-08 09:56:52 Event size error: size 0 at 290. +2015-09-08 09:56:52 warning : an error has been found. Setting safe pos to 245, current pos 290 +2015-09-08 09:56:52 Check retcode: 1, Binlog Pos = 245 +``` + +Check it again, last pos will be 245 and no errors will be reported: + +``` +[root@maxscale-02 build]# /usr/local/bin/maxbinlogcheck /servers/binlogs/new-trx/bin.000002 -d +2015-09-08 09:56:56 maxbinlogcheck 1.0.0 +2015-09-08 09:56:56 Checking /servers/binlogs/new-trx/bin.000002 (bin.000002), size 245 bytes +2015-09-08 09:56:56 - Format Description event FDE @ 4, size 241 +2015-09-08 09:56:56 FDE ServerVersion [ 5.5.35-MariaDB-log] +2015-09-08 09:56:56 FDE Header EventLength 19, N. of supported MySQL/MariaDB events 160 +2015-09-08 09:56:56 FDE Checksum alg desc 1, alg type BINLOG_CHECKSUM_ALG_CRC32 +2015-09-08 09:56:56 End of binlog file [bin.000002] at 245. +2015-09-08 09:56:56 Transaction Summary: + Description Total Average Max + No. of Transactions 0 +2015-09-08 09:56:56 Check retcode: 0, Binlog Pos = 245 +``` + +## Detection of an incomplete big transaction + +``` +[root@maxscale-02 build]# /usr/local/bin/maxbinlogcheck /servers/binlogs/new-trx/mar-bin.000003 +2015-09-08 10:10:21 maxbinlogcheck 1.0.0 +2015-09-08 10:10:21 Checking /servers/binlogs/new-trx/mar-bin.000003 (mar-bin.000003), size 16476284 bytes +2015-09-08 10:10:21 Warning : pending transaction has been found. Setting safe pos to 572, current pos 16476284 +2015-09-08 10:10:21 Transaction Summary: + Description Total Average Max + No. of Transactions 0 +2015-09-08 10:10:21 Check retcode: 0, Binlog Pos = 572 +``` + +with debug option: + +``` +[root@maxscale-02 build]# /usr/local/bin/maxbinlogcheck /servers/binlogs/new-trx/mar-bin.000003 -d +2015-09-08 10:11:08 maxbinlogcheck 1.0.0 +2015-09-08 10:11:08 Checking /servers/binlogs/new-trx/mar-bin.000003 (mar-bin.000003), size 16476284 bytes +2015-09-08 10:11:08 - Format Description event FDE @ 4, size 241 +2015-09-08 10:11:08 FDE ServerVersion [ 5.5.35-MariaDB-log] +2015-09-08 10:11:08 FDE Header EventLength 19, N. of supported MySQL/MariaDB events 160 +2015-09-08 10:11:08 FDE Checksum alg desc 1, alg type BINLOG_CHECKSUM_ALG_CRC32 +2015-09-08 10:11:08 > Transaction starts @ pos 572 +2015-09-08 10:11:08 Warning : pending transaction has been found. Setting safe pos to 572, current pos 16476284 +2015-09-08 10:11:08 End of binlog file [mar-bin.000003] at 16476284. +2015-09-08 10:11:08 Transaction Summary: + Description Total Average Max + No. of Transactions 0 +2015-09-08 10:11:08 Check retcode: 0, Binlog Pos = 572 +``` + +Retcode is 0 as the transaction may proceed over time, example: + +Another check ... + +``` +[root@maxscale-02 build]# /usr/local/bin/maxbinlogcheck /servers/binlogs/new-trx/mar-bin.000003 -d +2015-09-08 10:17:13 maxbinlogcheck 1.0.0 +2015-09-08 10:17:13 Checking /servers/binlogs/new-trx/mar-bin.000003 (mar-bin.000003), size 569296364 bytes +2015-09-08 10:17:13 - Format Description event FDE @ 4, size 241 +2015-09-08 10:17:13 FDE ServerVersion [ 5.5.35-MariaDB-log] +2015-09-08 10:17:13 FDE Header EventLength 19, N. of supported MySQL/MariaDB events 160 +2015-09-08 10:17:13 FDE Checksum alg desc 1, alg type BINLOG_CHECKSUM_ALG_CRC32 +2015-09-08 10:17:13 > Transaction starts @ pos 572 +2015-09-08 10:17:14 End of binlog file [mar-bin.000003] at 577567062. +2015-09-08 10:17:14 Transaction Summary: + Description Total Average Max + No. of Transactions 0 +2015-09-08 10:17:14 Warning : pending transaction has been found. Setting safe pos to 572, current pos 577567062 +2015-09-08 10:17:14 Check retcode: 0, Binlog Pos = 572 +``` + +And finally big transaction is now done. + +``` +[root@maxscale-02 build]# /usr/local/bin/maxbinlogcheck /servers/binlogs/new-trx/mar-bin.000003 -d +2015-09-08 10:17:15 maxbinlogcheck 1.0.0 +2015-09-08 10:17:15 Checking /servers/binlogs/new-trx/mar-bin.000003 (mar-bin.000003), size 590760698 bytes +2015-09-08 10:17:15 - Format Description event FDE @ 4, size 241 +2015-09-08 10:17:15 FDE ServerVersion [ 5.5.35-MariaDB-log] +2015-09-08 10:17:15 FDE Header EventLength 19, N. of supported MySQL/MariaDB events 160 +2015-09-08 10:17:15 FDE Checksum alg desc 1, alg type BINLOG_CHECKSUM_ALG_CRC32 +2015-09-08 10:17:15 > Transaction starts @ pos 572 +2015-09-08 10:17:16 Transaction XID @ pos 572, closing @ 590760644 +2015-09-08 10:17:16 < Transaction @ pos 572, is now closed @ 590760644. 18001 events seen +2015-09-08 10:17:16 End of binlog file [mar-bin.000003] at 590760698. +2015-09-08 10:17:16 Transaction Summary: + Description Total Average Max + No. of Transactions 1 + No. of Events 18001 18001.0 18001 + No. of Bytes 563M 563M 563M +2015-09-08 10:17:16 Check retcode: 0, Binlog Pos = 590760698 +``` + +**Note** +with current maxbinlogcheck it's not possible to fix a binlog with incomplete transaction and no other errors + +If that is really desired it will be possible with UNIX command line: + +``` +# truncate /servers/binlogs/new-trx/mar-bin.000003 --size=572 +``` + +In case of an error and incomplete transactions fix will work + +``` +[root@maxscale-02 build]# /usr/local/bin/maxbinlogcheck /servers/binlogs/new-trx/mar-bin.000003 -d -f +2015-09-08 10:35:57 maxbinlogcheck 1.0.0 +2015-09-08 10:35:57 Checking /servers/binlogs/new-trx/mar-bin.000003 (mar-bin.000003), size 282580902 bytes +2015-09-08 10:35:57 - Format Description event FDE @ 4, size 241 +2015-09-08 10:35:57 FDE ServerVersion [ 5.5.35-MariaDB-log] +2015-09-08 10:35:57 FDE Header EventLength 19, N. of supported MySQL/MariaDB events 160 +2015-09-08 10:35:57 FDE Checksum alg desc 1, alg type BINLOG_CHECKSUM_ALG_CRC32 +2015-09-08 10:35:57 > Transaction starts @ pos 572 +2015-09-08 10:35:57 Short read when reading the event at 304898502 in mar-bin.000003. Expected 65563 bytes got 15911 bytes. +2015-09-08 10:35:57 warning : an error has been found. Setting safe pos to 572, current pos 304898502 +2015-09-08 10:35:57 Check retcode: 1, Binlog Pos = 572 +``` + +Check result: + +``` +[root@maxscale-02 build]# /usr/local/bin/maxbinlogcheck /servers/binlogs/new-trx/mar-bin.000003 -d +2015-09-08 10:54:17 maxbinlogcheck 1.0.0 +2015-09-08 10:54:17 Checking /servers/binlogs/new-trx/mar-bin.000003 (mar-bin.000003), size 572 bytes +2015-09-08 10:54:17 - Format Description event FDE @ 4, size 241 +2015-09-08 10:54:17 FDE ServerVersion [ 5.5.35-MariaDB-log] +2015-09-08 10:54:17 FDE Header EventLength 19, N. of supported MySQL/MariaDB events 160 +2015-09-08 10:54:17 FDE Checksum alg desc 1, alg type BINLOG_CHECKSUM_ALG_CRC32 +2015-09-08 10:54:17 Transaction Summary: + Description Total Average Max + No. of Transactions 0 +2015-09-08 10:54:17 End of binlog file [mar-bin.000003] at 572. +2015-09-08 10:54:17 Check retcode: 0, Binlog Pos = 572 +``` + diff --git a/server/modules/routing/binlog/blr_file.c b/server/modules/routing/binlog/blr_file.c index 020838a83..5ad9f9a5d 100644 --- a/server/modules/routing/binlog/blr_file.c +++ b/server/modules/routing/binlog/blr_file.c @@ -76,7 +76,7 @@ int blr_file_new_binlog(ROUTER_INSTANCE *router, char *file); void blr_file_use_binlog(ROUTER_INSTANCE *router, char *file); int blr_file_write_master_config(ROUTER_INSTANCE *router, char *error); extern uint32_t extract_field(uint8_t *src, int bits); -static void blr_format_event_size(unsigned long *event_size, char *label); +static void blr_format_event_size(double *event_size, char *label); /** * Initialise the binlog file for this instance. MaxScale will look @@ -1008,22 +1008,23 @@ double average_bytes = 0; char total_label[2]=""; char average_label[2]=""; char max_label[2]=""; - unsigned long avg_bytes = (unsigned long) average_bytes; + double format_total_bytes = total_bytes; + double format_max_bytes = max_bytes; - blr_format_event_size(&total_bytes, total_label); - blr_format_event_size(&avg_bytes, average_label); - blr_format_event_size(&max_bytes, max_label); + blr_format_event_size(&format_total_bytes, total_label); + blr_format_event_size(&average_bytes, average_label); + blr_format_event_size(&format_max_bytes, max_label); LOGIF(LM, (skygw_log_write_flush(LOGFILE_MESSAGE, "Transaction Summary:\n" "\t\t\tDescription %17s%17s%17s\n\t\t\t" "No. of Transactions %16llu\n\t\t\t" "No. of Events %16llu %16.1f %16llu\n\t\t\t" - "No. of Bytes %16llu%s%16llu%s%16llu%s", + "No. of Bytes %16.1f%s%16.1f%s%16.1f%s", "Total", "Average", "Max", n_transactions, total_events, average_events, max_events, - total_bytes, total_label, avg_bytes, average_label, max_bytes, max_label))); + format_total_bytes, total_label, average_bytes, average_label, format_max_bytes, max_label))); } if (pending_transaction) { @@ -1270,7 +1271,7 @@ double average_bytes = 0; if(debug) LOGIF(LD, (skygw_log_write_flush(LOGFILE_DEBUG, "- Format Description event FDE @ %llu, size %lu", - pos, hdr.event_size))); + pos, (unsigned long)hdr.event_size))); event_header_length = ptr[2 + 50 + 4]; event_header_ntypes = hdr.event_size - event_header_length - (2 + 50 + 4 + 1); @@ -1573,7 +1574,7 @@ double average_bytes = 0; * @param label Label to use for display the formattted number */ static void -blr_format_event_size(unsigned long *event_size, char *label) +blr_format_event_size(double *event_size, char *label) { if (*event_size > (1024 * 1024 * 1024)) { *event_size = *event_size / (1024 * 1024 * 1024); diff --git a/server/modules/routing/binlog/maxbinlogcheck.c b/server/modules/routing/binlog/maxbinlogcheck.c index 2e7c65a14..7ff7c55fa 100644 --- a/server/modules/routing/binlog/maxbinlogcheck.c +++ b/server/modules/routing/binlog/maxbinlogcheck.c @@ -161,7 +161,12 @@ int main(int argc, char **argv) { strncpy(path, argv[num_args], PATH_MAX); - if ((fd = open(path, O_RDONLY, 0666)) == -1) + if (fix_file) + fd = open(path, O_RDWR, 0666); + else + fd = open(path, O_RDONLY, 0666); + + if (fd == -1) { LOGIF(LE, (skygw_log_write(LOGFILE_ERROR, "Failed to open binlog file %s: %s",