Details
-
Bug
-
Status: Closed (View Workflow)
-
Major
-
Resolution: Fixed
-
10.1.10
-
None
-
Linux fm-first 3.16.0-4-amd64 #1 SMP Debian 3.16.7-ckt20-1+deb8u1 (2015-12-14) x86_64 GNU/Linux
-
10.1.15
Description
Looks like the master hasn't been shutdown properly and now the new node that tries to connect to this cluster tries to run a recovery , but the binlog file doesn't exist.
starting the daemon with
mysqld --wsrep_cluster_address=......
|
2016-01-15 9:33:23 140341928318912 [Note] mysqld (mysqld 10.1.10-MariaDB-1~jessie-log) starting as process 1 ...
|
2016-01-15 9:33:23 140341928318912 [Note] WSREP: Read nil XID from storage engines, skipping position init
|
2016-01-15 9:33:23 140341928318912 [Note] WSREP: wsrep_load(): loading provider library '/usr/lib/galera/libgalera_smm.so'
|
2016-01-15 9:33:23 140341928318912 [Note] WSREP: wsrep_load(): Galera 3.9(rXXXX) by Codership Oy <info@codership.com> loaded successfully.
|
2016-01-15 9:33:23 140341928318912 [Note] WSREP: CRC-32C: using hardware acceleration.
|
2016-01-15 9:33:23 140341928318912 [Note] WSREP: Found saved state: 00000000-0000-0000-0000-000000000000:-1
|
2016-01-15 9:33:23 140341928318912 [Note] WSREP: Passing config to GCS: base_host = 10.0.0.8; base_port = 4567; cert.log_conflicts = no; debug = no; evs.auto_evict = 0; evs.delay_margin = PT1S; evs.delayed_keep_period = PT30S; evs.inactive_check_period = PT0.5S; evs.inactive_timeout = PT15S; evs.join_retrans_period = PT1S; evs.max_install_timeouts = 3; evs.send_window = 4; evs.stats_report_period = PT1M; evs.suspect_timeout = PT5S; evs.user_send_window = 2; evs.view_forget_timeout = PT24H; gcache.dir = /var/lib/mysql/; gcache.keep_pages_size = 0; gcache.mem_size = 0; gcache.name = /var/lib/mysql//galera.cache; gcache.page_size = 128M; gcache.size = 3G; gcs.fc_debug = 0; gcs.fc_factor = 1.0; gcs.fc_limit = 16; gcs.fc_master_slave = no; gcs.max_packet_size = 64500; gcs.max_throttle = 0.25; gcs.recv_q_hard_limit = 9223372036854775807; gcs.recv_q_soft_limit = 0.25; gcs.sync_donor = no; gmcast.segment = 0; gmcast.version = 0; pc.announce_timeout = PT3S; pc.checksum = false; pc.ignore_quorum = false; pc.ignore_sb = false; pc.npvo = false; pc.recovery = 1;
|
2016-01-15 9:33:23 140338580059904 [Note] WSREP: Service thread queue flushed.
|
2016-01-15 9:33:23 140341928318912 [Note] WSREP: Assign initial position for certification: -1, protocol version: -1
|
2016-01-15 9:33:23 140341928318912 [Note] WSREP: wsrep_sst_grab()
|
2016-01-15 9:33:23 140341928318912 [Note] WSREP: Start replication
|
2016-01-15 9:33:23 140341928318912 [Note] WSREP: Setting initial position to 00000000-0000-0000-0000-000000000000:-1
|
2016-01-15 9:33:23 140341928318912 [Note] WSREP: protonet asio version 0
|
2016-01-15 9:33:23 140341928318912 [Note] WSREP: Using CRC-32C for message checksums.
|
2016-01-15 9:33:23 140341928318912 [Note] WSREP: backend: asio
|
2016-01-15 9:33:23 140341928318912 [Warning] WSREP: access file(gvwstate.dat) failed(No such file or directory)
|
2016-01-15 9:33:23 140341928318912 [Note] WSREP: restore pc from disk failed
|
2016-01-15 9:33:23 140341928318912 [Note] WSREP: GMCast version 0
|
2016-01-15 9:33:23 140341928318912 [Warning] WSREP: Failed to resolve tcp://compose_mariadb_1:4567
|
2016-01-15 9:33:23 140341928318912 [Note] WSREP: (05b59999, 'tcp://0.0.0.0:4567') listening at tcp://0.0.0.0:4567
|
2016-01-15 9:33:23 140341928318912 [Note] WSREP: (05b59999, 'tcp://0.0.0.0:4567') multicast: , ttl: 1
|
2016-01-15 9:33:23 140341928318912 [Note] WSREP: EVS version 0
|
2016-01-15 9:33:23 140341928318912 [Note] WSREP: gcomm: connecting to group 'my_wsrep_cluster', peer 'compose_garbd_1:4567,compose_mariadb_1:4567,second_mariadb_1:4567'
|
2016-01-15 9:33:23 140341928318912 [Note] WSREP: (05b59999, 'tcp://0.0.0.0:4567') turning message relay requesting on, nonlive peers:
|
2016-01-15 9:33:24 140341928318912 [Note] WSREP: declaring 1afe1669 at tcp://10.0.0.9:4567 stable
|
2016-01-15 9:33:24 140341928318912 [Note] WSREP: declaring 41c70c8c at tcp://10.0.0.12:4567 stable
|
2016-01-15 9:33:24 140341928318912 [Note] WSREP: Node 1afe1669 state prim
|
2016-01-15 9:33:25 140341928318912 [Note] WSREP: view(view_id(PRIM,05b59999,96) memb {
|
05b59999,0
|
1afe1669,0
|
41c70c8c,0
|
} joined {
|
} left {
|
} partitioned {
|
})
|
2016-01-15 9:33:25 140341928318912 [Note] WSREP: save pc into disk
|
2016-01-15 9:33:25 140341928318912 [Note] WSREP: gcomm: connected
|
2016-01-15 9:33:25 140341928318912 [Note] WSREP: Changing maximum packet size to 64500, resulting msg size: 32636
|
2016-01-15 9:33:25 140341928318912 [Note] WSREP: Shifting CLOSED -> OPEN (TO: 0)
|
2016-01-15 9:33:25 140341928318912 [Note] WSREP: Opened channel 'my_wsrep_cluster'
|
2016-01-15 9:33:25 140341928318912 [Note] WSREP: Waiting for SST to complete.
|
2016-01-15 9:33:25 140338517763840 [Note] WSREP: New COMPONENT: primary = yes, bootstrap = no, my_idx = 0, memb_num = 3
|
2016-01-15 9:33:25 140338517763840 [Note] WSREP: STATE_EXCHANGE: sent state UUID: 069bc67c-bb6b-11e5-a9b3-1ad7790ea186
|
2016-01-15 9:33:25 140338517763840 [Note] WSREP: STATE EXCHANGE: sent state msg: 069bc67c-bb6b-11e5-a9b3-1ad7790ea186
|
2016-01-15 9:33:25 140338517763840 [Note] WSREP: STATE EXCHANGE: got state msg: 069bc67c-bb6b-11e5-a9b3-1ad7790ea186 from 0 ()
|
2016-01-15 9:33:25 140338517763840 [Note] WSREP: STATE EXCHANGE: got state msg: 069bc67c-bb6b-11e5-a9b3-1ad7790ea186 from 1 (garb)
|
2016-01-15 9:33:25 140338517763840 [Note] WSREP: STATE EXCHANGE: got state msg: 069bc67c-bb6b-11e5-a9b3-1ad7790ea186 from 2 ()
|
2016-01-15 9:33:25 140338517763840 [Note] WSREP: Quorum results:
|
version = 3,
|
component = PRIMARY,
|
conf_id = 93,
|
members = 2/3 (joined/total),
|
act_id = 205387,
|
last_appl. = -1,
|
protocols = 0/7/3 (gcs/repl/appl),
|
group UUID = 0600869f-af4f-11e5-8c89-a35fa6cdd2ef
|
2016-01-15 9:33:25 140338517763840 [Note] WSREP: Flow-control interval: [28, 28]
|
2016-01-15 9:33:25 140338517763840 [Note] WSREP: Shifting OPEN -> PRIMARY (TO: 205387)
|
2016-01-15 9:33:25 140341928011520 [Note] WSREP: State transfer required:
|
Group state: 0600869f-af4f-11e5-8c89-a35fa6cdd2ef:205387
|
Local state: 00000000-0000-0000-0000-000000000000:-1
|
2016-01-15 9:33:25 140341928011520 [Note] WSREP: New cluster view: global state: 0600869f-af4f-11e5-8c89-a35fa6cdd2ef:205387, view# 94: Primary, number of nodes: 3, my index: 0, protocol version 3
|
2016-01-15 9:33:25 140341928011520 [Warning] WSREP: Gap in state sequence. Need state transfer.
|
2016-01-15 9:33:25 140338488407808 [Note] WSREP: Running: 'wsrep_sst_xtrabackup-v2 --role 'joiner' --address '10.0.0.8' --datadir '/var/lib/mysql/' --parent '1' --binlog '/var/log/mysql/mariadb-bin' '
|
WSREP_SST: [INFO] Logging all stderr of SST/Innobackupex to syslog (20160115 09:33:25.515)
|
2016-01-15 9:33:25 140341928011520 [Note] WSREP: Prepared SST request: xtrabackup-v2|10.0.0.8:4444/xtrabackup_sst//1
|
2016-01-15 9:33:25 140341928011520 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
|
2016-01-15 9:33:25 140341928011520 [Note] WSREP: REPL Protocols: 7 (3, 2)
|
2016-01-15 9:33:25 140338580059904 [Note] WSREP: Service thread queue flushed.
|
2016-01-15 9:33:25 140341928011520 [Note] WSREP: Assign initial position for certification: 205387, protocol version: 3
|
2016-01-15 9:33:25 140338580059904 [Note] WSREP: Service thread queue flushed.
|
2016-01-15 9:33:25 140341928011520 [Warning] WSREP: Failed to prepare for incremental state transfer: Local state UUID (00000000-0000-0000-0000-000000000000) does not match group state UUID (0600869f-af4f-11e5-8c89-a35fa6cdd2ef): 1 (Operation not permitted)
|
at galera/src/replicator_str.cpp:prepare_for_IST():456. IST will be unavailable.
|
2016-01-15 9:33:25 140338517763840 [Note] WSREP: Member 0.0 () requested state transfer from '*any*'. Selected 2.0 ()(SYNCED) as donor.
|
2016-01-15 9:33:25 140338517763840 [Note] WSREP: Shifting PRIMARY -> JOINER (TO: 205387)
|
2016-01-15 9:33:25 140341928011520 [Note] WSREP: Requesting state transfer: success, donor: 2
|
2016-01-15 9:33:27 140338526156544 [Note] WSREP: (05b59999, 'tcp://0.0.0.0:4567') turning message relay requesting off
|
2016-01-15 10:25:15 140338517763840 [Note] WSREP: 2.0 (): State transfer to 0.0 () complete.
|
2016-01-15 10:25:15 140338517763840 [Note] WSREP: Member 2.0 () synced with group.
|
2016-01-15 10:25:20 140341928318912 [Note] WSREP: SST complete, seqno: 205388
|
2016-01-15 10:25:21 140341928318912 [Note] InnoDB: Using mutexes to ref count buffer pool pages
|
2016-01-15 10:25:21 140341928318912 [Note] InnoDB: The InnoDB memory heap is disabled
|
2016-01-15 10:25:21 140341928318912 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
|
2016-01-15 10:25:21 140341928318912 [Note] InnoDB: Memory barrier is not used
|
2016-01-15 10:25:21 140341928318912 [Note] InnoDB: Compressed tables use zlib 1.2.8
|
2016-01-15 10:25:21 140341928318912 [Note] InnoDB: Using Linux native AIO
|
2016-01-15 10:25:21 140341928318912 [Note] InnoDB: Using SSE crc32 instructions
|
2016-01-15 10:25:21 140341928318912 [Note] InnoDB: Initializing buffer pool, size = 9.8G
|
2016-01-15 10:25:21 140341928318912 [Note] InnoDB: Completed initialization of buffer pool
|
2016-01-15 10:25:22 140341928318912 [Note] InnoDB: Highest supported file format is Barracuda.
|
2016-01-15 10:25:22 140341928318912 [Note] InnoDB: 128 rollback segment(s) are active.
|
2016-01-15 10:25:22 140341928318912 [Note] InnoDB: Waiting for purge to start
|
2016-01-15 10:25:22 140341928318912 [Note] InnoDB: Percona XtraDB (http://www.percona.com) 5.6.26-76.0 started; log sequence number 79527883504
|
2016-01-15 10:25:22 140318926145280 [Note] InnoDB: Dumping buffer pool(s) not yet started
|
2016-01-15 10:25:22 140341928318912 [Note] Plugin 'FEEDBACK' is disabled.
|
2016-01-15 10:25:22 140341928318912 [Note] Recovering after a crash using /var/log/mysql/mariadb-bin
|
2016-01-15 10:25:22 140341928318912 [ERROR] Binlog file '/var/log/mysql/mariadb-bin.000001' not found in binlog index, needed for recovery. Aborting.
|
2016-01-15 10:25:22 140341928318912 [ERROR] Crash recovery failed. Either correct the problem (if it's, for example, out of memory error) and restart, or delete (or rename) binary log and start mysqld with --tc-heuristic-recover={commit|rollback}
|
2016-01-15 10:25:22 140341928318912 [ERROR] Can't init tc log
|
2016-01-15 10:25:22 140341928318912 [ERROR] Aborting
|
Attachments
Issue Links
- duplicates
-
-
- Closed
-
- links to
Activity
Your data directory is apparently /var/lib/mysql. Did you also clean up /var/log/mysql, where your binary files are configured to reside?
The error log suggests that it found some broken remains of binary logs in there. Could you please check?
both dirs were empty
I think this reference comes from the main master I am trying to replicate.
I resolved the issue by running RESET MASTER ; on the main master and then added the node again.
So my logic is that the master didn't shutdown cleanly the last time and this affected the new node trying to run the recovery.
The error log looks strange for a message coming from another node, but I cannot rule it out right away. Assigning to nirbhay_c who can say for sure.
I can reproduce this reliably in my environment on MariaDB 10.1.13 / Percona XtraBackup 2.3.4 on Debian8 with wsrep_sst_method=xtrabackup-v2. I just create a simple innodb table and start a loop writing to the cluster from one node and force SST on another node and I get results similar to:
[Note] Recovering after a crash using /var/log/mysql/mysql-bin
|
[ERROR] Binlog file '/var/log/mysql/mysql-bin.000149' not found in binlog index, needed for recovery. Aborting.
|
[ERROR] Crash recovery failed. Either correct the problem (if it's, for example, out of memory error and restart, or delete (or rename) binary log and start mysqld with --tc-heuristic-recover={commit|rollback}
|
[ERROR] Can't init tc log
|
[ERROR] Aborting
|
Recovery started from an empty MySQL datadir and empty /var/log/mysql/.
I found that commenting out the lines in wsrep_sst_xtrabackup-v2 that copy Percona XtraBackup's archived binary log back to /var/log/mysql/ kept this from happening. I suppose that binlog recovery is initiated by the presence of the binary log which xtrabackup copies from the donor. I'm not sure of the ramifications of skipping that recovery.
I'm getting an exactly same problem. (also MariaDB 10.1.13)
2016-04-14 6:59:00 140693871286208 [Note] Recovering after a crash using /var/log/mysql/mariadb-bin
2016-04-14 6:59:00 140693871286208 [ERROR] Binlog file '/var/log/mysql/mariadb-bin.000036' not found in binlog index, needed for recovery. Aborting.
2016-04-14 6:59:00 140693871286208 [ERROR] Crash recovery failed. Either correct the problem (if it's, for example, out of memory error) and restart, or delete (or rename) binary log and start mysqld with --tc-heuristic-recover=
2016-04-14 6:59:00 140693871286208 [ERROR] Can't init tc log
2016-04-14 6:59:00 140693871286208 [ERROR] Aborting
There is list of log files on donor:
drwxr-xr-x 2 999 docker 4096 Apr 5 15:24 mariadb-bin
rw-rw--- 1 999 docker 81279761 Apr 13 10:41 mariadb-bin.000031
rw-rw--- 1 999 docker 104857796 Apr 13 17:51 mariadb-bin.000032
rw-rw--- 1 999 docker 94852709 Apr 13 21:51 mariadb-bin.000033
rw-rw--- 1 999 docker 104857677 Apr 14 02:05 mariadb-bin.000034
rw-rw--- 1 999 docker 96645794 Apr 14 06:52 mariadb-bin.000035
rw-rw--- 1 999 docker 1744580 Apr 14 06:58 mariadb-bin.000036
rw-rw--- 1 999 docker 22837123 Apr 14 08:17 mariadb-bin.000037
rw-rw--- 1 999 docker 13260939 Apr 14 08:45 mariadb-bin.000038
rw-rw--- 1 999 docker 442 Apr 14 08:17 mariadb-bin.index
And on new node:
drwxr-xr-x 2 999 docker 4096 Apr 14 06:33 mariadb-bin
rw-rw--- 1 999 docker 361 Apr 14 06:58 mariadb-bin.000037
rw-rw--- 1 999 docker 34 Apr 14 06:58 mariadb-bin.index
rw-rw--- 1 999 docker 7 Apr 14 06:33 mariadb-bin.state
For some reason during making SST donor rotated a log mariadb-bin.000036 and new log file mariadb-bin.000037 made and copied to new node.
May be an important observation:
I used:
wsrep_sst_method = xtrabackup-v2
After changing to:
wsrep_sst_method = xtrabackup
I've successfully added a node to cluster twice in a row.
Another datapoint is that I see the binary log bundled in the xtrabackup (v2.3.4) output has only a single binlog checkpoint:
# at 249 |
#160414 16:21:01 server id 168730634 end_log_pos 288 Gtid list [0-168730634-7392349] |
# at 288 |
#160414 16:21:01 server id 168730634 end_log_pos 327 Binlog checkpoint mysql-bin.000330 |
DELIMITER ;
|
# End of log file
|
ROLLBACK /* added by mysqlbinlog */; |
Where mysql-bin.000330 corresponds to the previous binary log and the backup image has mysql-bin.000331.
wsrep_sst_rsync generate a binary log with two checkpoints:
# at 249 |
#700101 0:00:00 server id 168730634 end_log_pos 288 Gtid list [0-168730634-6670147] |
# at 288 |
#700101 0:00:00 server id 168730634 end_log_pos 327 Binlog checkpoint mysql-bin.000282 |
# at 327 |
#700101 0:00:00 server id 168730634 end_log_pos 366 Binlog checkpoint mysql-bin.000283 |
DELIMITER ;
|
# End of log file
|
ROLLBACK /* added by mysqlbinlog */; |
Where this was a earlier run and 000283 corresponds to the current (copied) binlog and 000282 corresponds to the previous (uncopied) log.
I assume this is probably some bug in xtrabackup causing this - manually running FTWRL + FLUSH BINARY LOGS always gives me two checkpoints in the latest log. Maybe there's a race condition here that rsync doesn't trip over (maybe because it's holding the lock longer?)
Actually there is a race here that after all. In my environment, I see up to a second of delay between running FLUSH BINARY LOGS/SHOW MASTER STATUS and when the current binary log has its second binlog checkpoint written.
Given this python harness:
import os |
import time |
|
|
import MySQLdb |
|
|
def main(): |
|
|
c = MySQLdb.connect(read_default_group='client') |
z = c.cursor() |
|
|
z.execute('SELECT @@version, @@wsrep_patch_version, @@innodb_version') |
v_mariadb, v_wsrep, v_innodb = z.fetchone() |
print("MariaDB version: %s" % v_mariadb) |
print("WSREP version: %s" % v_wsrep) |
print("InnoDB version: %s" % v_innodb) |
|
|
start = time.time() |
print("FTWRL") |
z.execute('FLUSH TABLES WITH READ LOCK') |
print(" -> %.3f secs" % (time.time() - start)) |
|
|
start = time.time() |
print("FLUSH BINARY LOGS") |
z.execute('FLUSH BINARY LOGS') |
print(" -> %.3f secs" % (time.time() - start)) |
|
|
start = time.time() |
print('SHOW MASTER STATUS') |
z.execute('SHOW MASTER STATUS') |
print(" -> %.3f secs" % (time.time() - start)) |
|
|
|
|
file = z.fetchone()[0] |
st = os.stat('/var/log/mysql/' + file) |
print("[%s] %s : %s" % (time.time(), file, os.stat('/var/log/mysql/' + file).st_size)) |
start = time.time() |
while st.st_size < 366 and os.stat('/var/log/mysql/' + file).st_size == st.st_size: |
continue |
now = time.time() |
print("[%s] %s size changed after %.3f secs" % (now, file, now - start)) |
print("[%s] %s : %s" % (time.time(), file, os.stat('/var/log/mysql/' + file).st_size)) |
|
|
start = time.time() |
print("UNLOCK TABLES") |
z.execute('UNLOCK TABLES') |
print(" -> %.3f secs" % (time.time() - start)) |
|
|
main()
|
I see this output:
$ python mdev-9423_race.py
|
MariaDB version: 10.1.13-MariaDB-1~jessie
|
WSREP version: wsrep_25.13
|
InnoDB version: 5.6.28-76.1
|
FTWRL
|
-> 0.001 secs
|
FLUSH BINARY LOGS
|
-> 0.004 secs
|
SHOW MASTER STATUS
|
-> 0.000 secs
|
[1460653106.87] mysql-bin.000445 : 327
|
[1460653107.79] mysql-bin.000445 size changed after 0.916 secs
|
[1460653107.79] mysql-bin.000445 : 366
|
UNLOCK TABLES
|
-> 0.000 secs
|
So under FTWRL, the binary log size is changing after FLUSH BINARY LOGS returns and before we run UNLOCK TABLES but if we read the binary log too fast (even under the ftwrl lock) it is missing some data.
Adding FLUSH LOCAL ENGINE LOGS prior to copying the binary log seems to erase this problem. I'm not sure if this is bad MariaDB behavior or if xtrabackup should be expected to flush engine logs here.
I opened a bug with Percona against percona-xtrabackup that includes a minor patch against xtrabackup 2.3 that resolved this problem for me:
I just wanted to add that I'm also having this issue.
I'm using xtrabackup-v2
xtrabackup version 2.4
MariaDB 10.1.13
I just reverted back to xtrabackup version 2.2 and I was finally able to get the node to join without error.
I verified that xtrabackup 2.2 is also affected by this same issue (due to also not running flush engine logs prior to copying the binlog). This is racy so it will sometimes work in the right conditions (under any supported xtrabackup version).
vipconsult,
How exactly did you initialize the node? Did you copy the entire data directory from an existing node? If so, did you copy the binary logs and binary log index as well?