wsrep_sst_rsync fails in PXC 5.6

[Raghavendra D Prabhu]

Log:

==================================================
CURRENT_TEST: main.1st
2013-09-20 16:28:30 0 [Warning] WSREP: wsrep_sst_receive_address is set to '127.0.0.1:15007' which makes it impossible for another host to reach this one. Please set it to the address which this node can be connected at by other cluster members.
2013-09-20 16:28:30 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2013-09-20 16:28:30 15524 [Note] WSREP: Read nil XID from storage engines, skipping position init
2013-09-20 16:28:30 15524 [Note] WSREP: wsrep_load(): loading provider library '/home/jenkins/workspace/PXC-5.6-msysbench/BTYPE/release/Host/centos6-64/Percona-XtraDB-Cluster-5.6.13-24.0.433.Linux.x86_64/lib/libgalera_smm.so'
2013-09-20 16:28:30 15524 [Note] WSREP: wsrep_load(): Galera 3.0(r157) by Codership Oy <email address hidden> loaded successfully.
2013-09-20 16:28:30 15524 [Note] WSREP: CRC-32C: using "slicing-by-8" algorithm.
2013-09-20 16:28:30 15524 [Warning] WSREP: Could not open saved state file for reading: /home/jenkins/workspace/PXC-5.6-msysbench/BTYPE/release/Host/centos6-64/5/mysqldir/node1/mysqld.1/data//grastate.dat
2013-09-20 16:28:30 15524 [Note] WSREP: Found saved state: 00000000-0000-0000-0000-000000000000:-1
2013-09-20 16:28:30 15524 [Note] WSREP: Passing config to GCS: base_host = 127.0.0.1; base_port = 4567; cert.log_conflicts = no; gcache.dir = /home/jenkins/workspace/PXC-5.6-msysbench/BTYPE/release/Host/centos6-64/5/mysqldir/node1/mysqld.1/data/; gcache.keep_pages_size = 0; gcache.mem_size = 0; gcache.name = /home/jenkins/workspace/PXC-5.6-msysbench/BTYPE/release/Host/centos6-64/5/mysqldir/node1/mysqld.1/data//galera.cache; gcache.page_size = 128M; gcache.size = 128M; gcs.fc_debug = 0; gcs.fc_factor = 1; 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.listen_addr = tcp://127.0.0.1:15008; repl.causal_read_timeout = PT30S; repl.commit_order = 3; repl.key_format = FLAT8; repl.proto_max = 5
2013-09-20 16:28:30 15524 [Note] WSREP: Assign initial position for certification: -1, protocol version: -1
2013-09-20 16:28:30 15524 [Note] WSREP: wsrep_sst_grab()
2013-09-20 16:28:30 15524 [Note] WSREP: Start replication
2013-09-20 16:28:30 15524 [Note] WSREP: Setting initial position to 00000000-0000-0000-0000-000000000000:-1
2013-09-20 16:28:30 15524 [Note] WSREP: protonet asio version 0
2013-09-20 16:28:30 15524 [Note] WSREP: Using CRC-32C (optimized) for message checksums.
2013-09-20 16:28:30 15524 [Note] WSREP: backend: asio
2013-09-20 16:28:30 15524 [Note] WSREP: GMCast version 0
2013-09-20 16:28:30 15524 [Note] WSREP: (8a1ea6d2-21f8-11e3-8598-379aaae71021, 'tcp://127.0.0.1:15008') listening at tcp://127.0.0.1:15008
2013-09-20 16:28:30 15524 [Note] WSREP: (8a1ea6d2-21f8-11e3-8598-379aaae71021, 'tcp://127.0.0.1:15008') multicast: , ttl: 1
2013-09-20 16:28:30 15524 [Note] WSREP: EVS version 0
2013-09-20 16:28:30 15524 [Note] WSREP: PC version 0
2013-09-20 16:28:30 15524 [Note] WSREP: gcomm: connecting to group 'my_wsrep_cluster', peer ''
2013-09-20 16:28:30 15524 [Note] WSREP: Node 8a1ea6d2-21f8-11e3-8598-379aaae71021 state prim
2013-09-20 16:28:30 15524 [Note] WSREP: view(view_id(PRIM,8a1ea6d2-21f8-11e3-8598-379aaae71021,1) memb {
 8a1ea6d2-21f8-11e3-8598-379aaae71021,0
} joined {
} left {
} partitioned {
})
2013-09-20 16:28:30 15524 [Note] WSREP: gcomm: connected
2013-09-20 16:28:30 15524 [Note] WSREP: Changing maximum packet size to 64500, resulting msg size: 32636
2013-09-20 16:28:30 15524 [Note] WSREP: Shifting CLOSED -> OPEN (TO: 0)
2013-09-20 16:28:30 15524 [Note] WSREP: Opened channel 'my_wsrep_cluster'
2013-09-20 16:28:30 15524 [Note] WSREP: New COMPONENT: primary = yes, bootstrap = no, my_idx = 0, memb_num = 1
2013-09-20 16:28:30 15524 [Note] WSREP: Waiting for SST to complete.
2013-09-20 16:28:30 15524 [Note] WSREP: Starting new group from scratch: 8a1f3c02-21f8-11e3-bc54-caa260ba663c
2013-09-20 16:28:30 15524 [Note] WSREP: STATE_EXCHANGE: sent state UUID: 8a1f4d77-21f8-11e3-bf97-b2e02b5e5784
2013-09-20 16:28:30 15524 [Note] WSREP: STATE EXCHANGE: sent state msg: 8a1f4d77-21f8-11e3-bf97-b2e02b5e5784
2013-09-20 16:28:30 15524 [Note] WSREP: STATE EXCHANGE: got state msg: 8a1f4d77-21f8-11e3-bf97-b2e02b5e5784 from 0 (vps-centos6-x64-01.ci.percona.com)
2013-09-20 16:28:30 15524 [Note] WSREP: Quorum results:
 version = 3,
 component = PRIMARY,
 conf_id = 0,
 members = 1/1 (joined/total),
 act_id = 0,
 last_appl. = -1,
 protocols = 0/5/2 (gcs/repl/appl),
 group UUID = 8a1f3c02-21f8-11e3-bc54-caa260ba663c
2013-09-20 16:28:30 15524 [Note] WSREP: Flow-control interval: [16, 16]
2013-09-20 16:28:30 15524 [Note] WSREP: Restored state OPEN -> JOINED (0)
2013-09-20 16:28:30 15524 [Note] WSREP: Member 0 (vps-centos6-x64-01.ci.percona.com) synced with group.
2013-09-20 16:28:30 15524 [Note] WSREP: Shifting JOINED -> SYNCED (TO: 0)
2013-09-20 16:28:30 15524 [Note] WSREP: New cluster view: global state: 8a1f3c02-21f8-11e3-bc54-caa260ba663c:0, view# 1: Primary, number of nodes: 1, my index: 0, protocol version 2
2013-09-20 16:28:30 15524 [Note] WSREP: SST complete, seqno: 0
2013-09-20 16:28:30 15524 [Note] Plugin 'FEDERATED' is disabled.
2013-09-20 16:28:30 7f97cd7d67e0 InnoDB: Warning: Using innodb_additional_mem_pool_size is DEPRECATED. This option may be removed in future releases, together with the option innodb_use_sys_malloc and with the InnoDB's internal memory allocator.
2013-09-20 16:28:30 7f97cd7d67e0 InnoDB: Warning: Using innodb_locks_unsafe_for_binlog is DEPRECATED. This option may be removed in future releases. Please use READ COMMITTED transaction isolation level instead, see http://dev.mysql.com/doc/refman/5.6/en/set-transaction.html.
2013-09-20 16:28:30 15524 [Note] InnoDB: The InnoDB memory heap is disabled
2013-09-20 16:28:30 15524 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2013-09-20 16:28:30 15524 [Note] InnoDB: Compressed tables use zlib 1.2.3
2013-09-20 16:28:30 15524 [Note] InnoDB: Using Linux native AIO
2013-09-20 16:28:30 15524 [Note] InnoDB: Not using CPU crc32 instructions
2013-09-20 16:28:30 15524 [Note] InnoDB: Initializing buffer pool, size = 8.0M
2013-09-20 16:28:30 15524 [Note] InnoDB: Completed initialization of buffer pool
2013-09-20 16:28:30 15524 [Note] InnoDB: Highest supported file format is Barracuda.
2013-09-20 16:28:30 15524 [Note] InnoDB: 128 rollback segment(s) are active.
2013-09-20 16:28:30 15524 [Note] InnoDB: Waiting for purge to start
2013-09-20 16:28:30 15524 [Note] InnoDB: Percona XtraDB (http://www.percona.com) 5.6.13-rc60.5 started; log sequence number 1625977
2013-09-20 16:28:30 15524 [Warning] /home/jenkins/workspace/PXC-5.6-msysbench/BTYPE/release/Host/centos6-64/Percona-XtraDB-Cluster-5.6.13-24.0.433.Linux.x86_64/bin/mysqld: unknown variable 'loose-debug-sync-timeout=600'
2013-09-20 16:28:30 15524 [Warning] No existing UUID has been found, so we assume that this is the first time that this server has been started. Generating a new UUID: 8a3f482e-21f8-11e3-a7c6-e13c84e2e3ca.
2013-09-20 16:28:30 15524 [Note] RSA private key file not found: /home/jenkins/workspace/PXC-5.6-msysbench/BTYPE/release/Host/centos6-64/5/mysqldir/node1/mysqld.1/data//private_key.pem. Some authentication plugins will not work.
2013-09-20 16:28:30 15524 [Note] RSA public key file not found: /home/jenkins/workspace/PXC-5.6-msysbench/BTYPE/release/Host/centos6-64/5/mysqldir/node1/mysqld.1/data//public_key.pem. Some authentication plugins will not work.
2013-09-20 16:28:30 15524 [Note] Server hostname (bind-address): '*'; port: 15001
2013-09-20 16:28:30 15524 [Note] IPv6 is available.
2013-09-20 16:28:30 15524 [Note] - '::' resolves to '::';
2013-09-20 16:28:30 15524 [Note] Server socket created on IP: '::'.
2013-09-20 16:28:30 15524 [Warning] 'user' entry '<email address hidden>' ignored in --skip-name-resolve mode.
2013-09-20 16:28:30 15524 [Warning] 'proxies_priv' entry '@ <email address hidden>' ignored in --skip-name-resolve mode.
2013-09-20 16:28:30 15524 [Note] Event Scheduler: Loaded 0 events
2013-09-20 16:28:30 15524 [Note] WSREP: inited wsrep sidno 1
2013-09-20 16:28:30 15524 [Note] /home/jenkins/workspace/PXC-5.6-msysbench/BTYPE/release/Host/centos6-64/Percona-XtraDB-Cluster-5.6.13-24.0.433.Linux.x86_64/bin/mysqld: ready for connections.
Version: '5.6.13-24.0-log' socket: '/home/jenkins/workspace/PXC-5.6-msysbench/BTYPE/release/Host/centos6-64/5/mysqldir/node1/socket.sock' port: 15001 Percona XtraDB Cluster (GPL) 5.6.13-24.0, Revision 433, wsrep_24.0.r3928
2013-09-20 16:28:30 15524 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2013-09-20 16:28:30 15524 [Note] WSREP: REPL Protocols: 5 (3, 1)
2013-09-20 16:28:30 15524 [Note] WSREP: Assign initial position for certification: 0, protocol version: 3
2013-09-20 16:28:30 15524 [Note] WSREP: Service thread queue flushed.
2013-09-20 16:28:30 15524 [Note] WSREP: Synchronized with group, ready for connections
2013-09-20 16:28:30 15524 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2013-09-20 16:29:27 15524 [Note] WSREP: declaring abb8db09-21f8-11e3-805c-7fa0590b9f5e stable
2013-09-20 16:29:27 15524 [Note] WSREP: Node 8a1ea6d2-21f8-11e3-8598-379aaae71021 state prim
2013-09-20 16:29:27 15524 [Note] WSREP: view(view_id(PRIM,8a1ea6d2-21f8-11e3-8598-379aaae71021,2) memb {
 8a1ea6d2-21f8-11e3-8598-379aaae71021,0
 abb8db09-21f8-11e3-805c-7fa0590b9f5e,0
} joined {
} left {
} partitioned {
})
2013-09-20 16:29:27 15524 [Note] WSREP: New COMPONENT: primary = yes, bootstrap = no, my_idx = 0, memb_num = 2
2013-09-20 16:29:27 15524 [Note] WSREP: STATE_EXCHANGE: sent state UUID: ac05c298-21f8-11e3-b67b-87899464d903
2013-09-20 16:29:27 15524 [Note] WSREP: STATE EXCHANGE: sent state msg: ac05c298-21f8-11e3-b67b-87899464d903
2013-09-20 16:29:27 15524 [Note] WSREP: STATE EXCHANGE: got state msg: ac05c298-21f8-11e3-b67b-87899464d903 from 0 (vps-centos6-x64-01.ci.percona.com)
2013-09-20 16:29:27 15524 [Note] WSREP: STATE EXCHANGE: got state msg: ac05c298-21f8-11e3-b67b-87899464d903 from 1 (vps-centos6-x64-01.ci.percona.com)
2013-09-20 16:29:27 15524 [Note] WSREP: Quorum results:
 version = 3,
 component = PRIMARY,
 conf_id = 1,
 members = 1/2 (joined/total),
 act_id = 41,
 last_appl. = 39,
 protocols = 0/5/2 (gcs/repl/appl),
 group UUID = 8a1f3c02-21f8-11e3-bc54-caa260ba663c
2013-09-20 16:29:27 15524 [Note] WSREP: Flow-control interval: [23, 23]
2013-09-20 16:29:27 15524 [Note] WSREP: New cluster view: global state: 8a1f3c02-21f8-11e3-bc54-caa260ba663c:41, view# 2: Primary, number of nodes: 2, my index: 0, protocol version 2
2013-09-20 16:29:27 15524 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2013-09-20 16:29:27 15524 [Note] WSREP: REPL Protocols: 5 (3, 1)
2013-09-20 16:29:27 15524 [Note] WSREP: Assign initial position for certification: 41, protocol version: 3
2013-09-20 16:29:27 15524 [Note] WSREP: Service thread queue flushed.
2013-09-20 16:29:30 15524 [Note] WSREP: Node 1.0 (vps-centos6-x64-01.ci.percona.com) requested state transfer from '*any*'. Selected 0.0 (vps-centos6-x64-01.ci.percona.com)(SYNCED) as donor.
2013-09-20 16:29:30 15524 [Note] WSREP: Shifting SYNCED -> DONOR/DESYNCED (TO: 41)
2013-09-20 16:29:30 15524 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2013-09-20 16:29:30 15524 [Note] WSREP: Running: 'wsrep_sst_rsync --role 'donor' --address '127.0.0.1:18007/rsync_sst' --auth 'root:' --socket '/home/jenkins/workspace/PXC-5.6-msysbench/BTYPE/release/Host/centos6-64/5/mysqldir/node1/socket.sock' --datadir '/home/jenkins/workspace/PXC-5.6-msysbench/BTYPE/release/Host/centos6-64/5/mysqldir/node1/mysqld.1/data/' --defaults-file '/home/jenkins/workspace/PXC-5.6-msysbench/BTYPE/release/Host/centos6-64/5/mysqldir/node1/my.cnf' --binlog '0' --gtid '8a1f3c02-21f8-11e3-bc54-caa260ba663c:41''
2013-09-20 16:29:30 15524 [Note] WSREP: sst_donor_thread signaled with 0
2013-09-20 16:29:30 15524 [Note] WSREP: Flushing tables for SST...
2013-09-20 16:29:30 15524 [Note] WSREP: Provider paused at 8a1f3c02-21f8-11e3-bc54-caa260ba663c:41
2013-09-20 16:29:30 15524 [Note] WSREP: Tables flushed.
tail: cannot open `0.index' for reading: No such file or directory
2013-09-20 16:29:30 15524 [ERROR] WSREP: Failed to read from: wsrep_sst_rsync --role 'donor' --address '127.0.0.1:18007/rsync_sst' --auth 'root:' --socket '/home/jenkins/workspace/PXC-5.6-msysbench/BTYPE/release/Host/centos6-64/5/mysqldir/node1/socket.sock' --datadir '/home/jenkins/workspace/PXC-5.6-msysbench/BTYPE/release/Host/centos6-64/5/mysqldir/node1/mysqld.1/data/' --defaults-file '/home/jenkins/workspace/PXC-5.6-msysbench/BTYPE/release/Host/centos6-64/5/mysqldir/node1/my.cnf' --binlog '0' --gtid '8a1f3c02-21f8-11e3-bc54-caa260ba663c:41'
2013-09-20 16:29:30 15524 [Note] WSREP: Provider resumed.
2013-09-20 16:29:30 15524 [ERROR] WSREP: Process completed with error: wsrep_sst_rsync --role 'donor' --address '127.0.0.1:18007/rsync_sst' --auth 'root:' --socket '/home/jenkins/workspace/PXC-5.6-msysbench/BTYPE/release/Host/centos6-64/5/mysqldir/node1/socket.sock' --datadir '/home/jenkins/workspace/PXC-5.6-msysbench/BTYPE/release/Host/centos6-64/5/mysqldir/node1/mysqld.1/data/' --defaults-file '/home/jenkins/workspace/PXC-5.6-msysbench/BTYPE/release/Host/centos6-64/5/mysqldir/node1/my.cnf' --binlog '0' --gtid '8a1f3c02-21f8-11e3-bc54-caa260ba663c:41': 1 (Operation not permitted)
2013-09-20 16:29:30 15524 [Warning] WSREP: 0.0 (vps-centos6-x64-01.ci.percona.com): State transfer to 1.0 (vps-centos6-x64-01.ci.percona.com) failed: -1 (Operation not permitted)
2013-09-20 16:29:30 15524 [Note] WSREP: Shifting DONOR/DESYNCED -> JOINED (TO: 41)
2013-09-20 16:29:30 15524 [Note] WSREP: Member 0 (vps-centos6-x64-01.ci.percona.com) synced with group.
2013-09-20 16:29:30 15524 [Note] WSREP: Shifting JOINED -> SYNCED (TO: 41)
2013-09-20 16:29:30 15524 [Note] WSREP: Synchronized with group, ready for connections
2013-09-20 16:29:30 15524 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2013-09-20 16:29:56 15524 [Note] /home/jenkins/workspace/PXC-5.6-msysbench/BTYPE/release/Host/centos6-64/Percona-XtraDB-Cluster-5.6.13-24.0.433.Linux.x86_64/bin/mysqld: Normal shutdown

2013-09-20 16:29:56 15524 [Note] WSREP: Stop replication
2013-09-20 16:29:56 15524 [Note] WSREP: Closing send monitor...
2013-09-20 16:29:56 15524 [Note] WSREP: Closed send monitor.
2013-09-20 16:29:56 15524 [Note] WSREP: gcomm: terminating thread
2013-09-20 16:29:56 15524 [Note] WSREP: gcomm: joining thread
2013-09-20 16:29:56 15524 [Note] WSREP: gcomm: closing backend
2013-09-20 16:29:56 15524 [Note] WSREP: (8a1ea6d2-21f8-11e3-8598-379aaae71021, 'tcp://127.0.0.1:15008') turning message relay requesting on, nonlive peers: tcp://127.0.0.1:18008
2013-09-20 16:29:56 15524 [Note] WSREP: (8a1ea6d2-21f8-11e3-8598-379aaae71021, 'tcp://127.0.0.1:15008') reconnecting to abb8db09-21f8-11e3-805c-7fa0590b9f5e (tcp://127.0.0.1:18008), attempt 0
2013-09-20 16:29:56 15524 [Note] WSREP: Node 8a1ea6d2-21f8-11e3-8598-379aaae71021 state prim
2013-09-20 16:29:56 15524 [Note] WSREP: view(view_id(PRIM,8a1ea6d2-21f8-11e3-8598-379aaae71021,3) memb {
 8a1ea6d2-21f8-11e3-8598-379aaae71021,0
} joined {
} left {
} partitioned {
 abb8db09-21f8-11e3-805c-7fa0590b9f5e,0
})
2013-09-20 16:29:56 15524 [Note] WSREP: forgetting abb8db09-21f8-11e3-805c-7fa0590b9f5e (tcp://127.0.0.1:18008)
2013-09-20 16:29:56 15524 [Note] WSREP: deleting entry tcp://127.0.0.1:18008
2013-09-20 16:29:56 15524 [Note] WSREP: New COMPONENT: primary = yes, bootstrap = no, my_idx = 0, memb_num = 1
2013-09-20 16:29:56 15524 [Note] WSREP: (8a1ea6d2-21f8-11e3-8598-379aaae71021, 'tcp://127.0.0.1:15008') turning message relay requesting off
2013-09-20 16:29:56 15524 [Note] WSREP: view((empty))
2013-09-20 16:29:56 15524 [Note] WSREP: gcomm: closed
2013-09-20 16:29:56 15524 [Warning] WSREP: 0x276a670 down context(s) not set
2013-09-20 16:29:56 15524 [Warning] WSREP: Failed to send state UUID: -107 (Transport endpoint is not connected)
2013-09-20 16:29:56 15524 [Note] WSREP: Received self-leave message.
2013-09-20 16:29:56 15524 [Note] WSREP: Flow-control interval: [0, 0]
2013-09-20 16:29:56 15524 [Note] WSREP: Received SELF-LEAVE. Closing connection.
2013-09-20 16:29:56 15524 [Note] WSREP: Shifting SYNCED -> CLOSED (TO: 41)
2013-09-20 16:29:56 15524 [Note] WSREP: RECV thread exiting 0: Success
2013-09-20 16:29:56 15524 [Note] WSREP: New cluster view: global state: 8a1f3c02-21f8-11e3-bc54-caa260ba663c:41, view# -1: non-Primary, number of nodes: 0, my index: -1, protocol version 2
2013-09-20 16:29:56 15524 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2013-09-20 16:29:56 15524 [Note] WSREP: recv_thread() joined.
2013-09-20 16:29:56 15524 [Note] WSREP: Closing replication queue.
2013-09-20 16:29:56 15524 [Note] WSREP: applier thread exiting (code:0)
2013-09-20 16:29:56 15524 [Note] WSREP: Closing slave action queue.
2013-09-20 16:29:56 15524 [Note] WSREP: applier thread exiting (code:6)
2013-09-20 16:29:58 15524 [Note] WSREP: rollbacker thread exiting
2013-09-20 16:29:58 15524 [Note] Giving 0 client threads a chance to die gracefully
2013-09-20 16:29:58 15524 [Note] Event Scheduler: Purging the queue. 0 events
2013-09-20 16:29:58 15524 [Note] Shutting down slave threads
2013-09-20 16:29:58 15524 [Note] Forcefully disconnecting 0 remaining clients
2013-09-20 16:29:58 15524 [Note] WSREP: dtor state: CLOSED
2013-09-20 16:29:58 15524 [Note] WSREP: mon: entered 41 oooe fraction 0 oool fraction 0
2013-09-20 16:29:58 15524 [Note] WSREP: mon: entered 41 oooe fraction 0 oool fraction 0
2013-09-20 16:29:58 15524 [Note] WSREP: mon: entered 86 oooe fraction 0 oool fraction 0
2013-09-20 16:29:58 15524 [Note] WSREP: cert index usage at exit 0
2013-09-20 16:29:58 15524 [Note] WSREP: cert trx map usage at exit 0
2013-09-20 16:29:58 15524 [Note] WSREP: deps set usage at exit 0
2013-09-20 16:29:58 15524 [Note] WSREP: avg deps dist 0
2013-09-20 16:29:58 15524 [Note] WSREP: wsdb trx map usage 0 conn query map usage 0
2013-09-20 16:29:58 15524 [Note] WSREP: Shifting CLOSED -> DESTROYED (TO: 41)
2013-09-20 16:29:58 15524 [Note] WSREP: Flushing memory map to disk...
2013-09-20 16:29:58 15524 [Note] Binlog end
2013-09-20 16:29:58 15524 [Note] Shutting down plugin 'partition'
2013-09-20 16:29:58 15524 [Note] Shutting down plugin 'ARCHIVE'
2013-09-20 16:29:58 15524 [Note] Shutting down plugin 'PERFORMANCE_SCHEMA'
2013-09-20 16:29:58 15524 [Note] Shutting down plugin 'INNODB_CHANGED_PAGES'
2013-09-20 16:29:58 15524 [Note] Shutting down plugin 'INNODB_SYS_DATAFILES'
2013-09-20 16:29:58 15524 [Note] Shutting down plugin 'INNODB_SYS_TABLESPACES'
2013-09-20 16:29:58 15524 [Note] Shutting down plugin 'INNODB_SYS_FOREIGN_COLS'
2013-09-20 16:29:58 15524 [Note] Shutting down plugin 'INNODB_SYS_FOREIGN'
2013-09-20 16:29:58 15524 [Note] Shutting down plugin 'INNODB_SYS_FIELDS'
2013-09-20 16:29:58 15524 [Note] Shutting down plugin 'INNODB_SYS_COLUMNS'
2013-09-20 16:29:58 15524 [Note] Shutting down plugin 'INNODB_SYS_INDEXES'
2013-09-20 16:29:58 15524 [Note] Shutting down plugin 'INNODB_SYS_TABLESTATS'
2013-09-20 16:29:58 15524 [Note] Shutting down plugin 'INNODB_SYS_TABLES'
2013-09-20 16:29:58 15524 [Note] Shutting down plugin 'INNODB_FT_INDEX_TABLE'
2013-09-20 16:29:58 15524 [Note] Shutting down plugin 'INNODB_FT_INDEX_CACHE'
2013-09-20 16:29:58 15524 [Note] Shutting down plugin 'INNODB_FT_CONFIG'
2013-09-20 16:29:58 15524 [Note] Shutting down plugin 'INNODB_FT_BEING_DELETED'
2013-09-20 16:29:58 15524 [Note] Shutting down plugin 'INNODB_FT_DELETED'
2013-09-20 16:29:58 15524 [Note] Shutting down plugin 'INNODB_FT_DEFAULT_STOPWORD'
2013-09-20 16:29:58 15524 [Note] Shutting down plugin 'INNODB_METRICS'
2013-09-20 16:29:58 15524 [Note] Shutting down plugin 'INNODB_BUFFER_POOL_STATS'
2013-09-20 16:29:58 15524 [Note] Shutting down plugin 'INNODB_BUFFER_PAGE_LRU'
2013-09-20 16:29:58 15524 [Note] Shutting down plugin 'INNODB_BUFFER_PAGE'
2013-09-20 16:29:58 15524 [Note] Shutting down plugin 'INNODB_CMP_PER_INDEX_RESET'
2013-09-20 16:29:58 15524 [Note] Shutting down plugin 'INNODB_CMP_PER_INDEX'
2013-09-20 16:29:58 15524 [Note] Shutting down plugin 'INNODB_CMPMEM_RESET'
2013-09-20 16:29:58 15524 [Note] Shutting down plugin 'INNODB_CMPMEM'
2013-09-20 16:29:58 15524 [Note] Shutting down plugin 'INNODB_CMP_RESET'
2013-09-20 16:29:58 15524 [Note] Shutting down plugin 'INNODB_CMP'
2013-09-20 16:29:58 15524 [Note] Shutting down plugin 'INNODB_LOCK_WAITS'
2013-09-20 16:29:58 15524 [Note] Shutting down plugin 'INNODB_LOCKS'
2013-09-20 16:29:58 15524 [Note] Shutting down plugin 'INNODB_TRX'
2013-09-20 16:29:58 15524 [Note] Shutting down plugin 'XTRADB_RSEG'
2013-09-20 16:29:58 15524 [Note] Shutting down plugin 'XTRADB_INTERNAL_HASH_TABLES'
2013-09-20 16:29:58 15524 [Note] Shutting down plugin 'XTRADB_READ_VIEW'
2013-09-20 16:29:58 15524 [Note] Shutting down plugin 'InnoDB'
2013-09-20 16:29:58 15524 [Note] InnoDB: FTS optimize thread exiting.
2013-09-20 16:29:58 15524 [Note] InnoDB: Starting shutdown...
2013-09-20 16:29:59 15524 [Note] InnoDB: Shutdown completed; log sequence number 28502435
2013-09-20 16:29:59 15524 [Note] Shutting down plugin 'BLACKHOLE'
2013-09-20 16:29:59 15524 [Note] Shutting down plugin 'MRG_MYISAM'
2013-09-20 16:29:59 15524 [Note] Shutting down plugin 'MEMORY'
2013-09-20 16:29:59 15524 [Note] Shutting down plugin 'CSV'
2013-09-20 16:29:59 15524 [Note] Shutting down plugin 'MyISAM'
2013-09-20 16:29:59 15524 [Note] Shutting down plugin 'sha256_password'
2013-09-20 16:29:59 15524 [Note] Shutting down plugin 'mysql_old_password'
2013-09-20 16:29:59 15524 [Note] Shutting down plugin 'mysql_native_password'
2013-09-20 16:29:59 15524 [Note] Shutting down plugin 'wsrep'
2013-09-20 16:29:59 15524 [Note] Shutting down plugin 'binlog'
2013-09-20 16:29:59 15524 [Note] /home/jenkins/workspace/PXC-5.6-msysbench/BTYPE/release/Host/centos6-64/Percona-XtraDB-Cluster-5.6.13-24.0.433.Linux.x86_64/bin/mysqld: Shutdown complete

=========================================================

The script used is https://bazaar.launchpad.net/~percona-core/percona-qa/trunk/view/head:/pxc-bench.sh

Seems --binlog 0 is being passed even when binlogging is off.

[Alex Yurchenko (ayurchen)]

Raghu, are you sure that binlogging is OFF? Specifically log_bin option?

[Raghavendra D Prabhu (raghavendra-prabhu)]

@Alex,

I see that because of 2 observations:

a)
  perl mysql-test-run.pl \
    --start-and-exit \
    --port-base=$RBASE1 \
    --nowarnings \
    --vardir=$node1 \
    --mysqld=--innodb_file_per_table \
    --mysqld=--binlog-format=ROW \
    --mysqld=--wsrep-slave-threads=2 \
    --mysqld=--innodb_autoinc_lock_mode=2 \
    --mysqld=--innodb_locks_unsafe_for_binlog=1 \
    --mysqld=--wsrep-provider=${MYSQL_BASEDIR}/lib/libgalera_smm.so \
    --mysqld=--wsrep_cluster_address=gcomm://?pc.ignore_sb=true \
    --mysqld=--wsrep_sst_receive_address=$RADDR1 \
    --mysqld=--wsrep_node_incoming_address=$ADDR \
    --mysqld=--wsrep_provider_options="gmcast.listen_addr=tcp://$LADDR1" \
    --mysqld=--wsrep_sst_method=$sst_method \
    --mysqld=--wsrep_sst_auth=$SUSER:$SPASS \
    --mysqld=--wsrep_node_address=$ADDR \
    --mysqld=--innodb_flush_method=O_DIRECT \
    --mysqld=--core-file \
    --mysqld=--loose-new \
    --mysqld=--sql-mode=no_engine_substitution \
    --mysqld=--loose-innodb \
    --mysqld=--secure-file-priv= \
    --mysqld=--loose-innodb-status-file=1 \
    --mysqld=--skip-name-resolve \
    --mysqld=--socket=$node1/socket.sock \
    --mysqld=--log-output=none \
    1st

I used this command line for 5.5, using it for 5.6 as well, I
haven't passed binlogging here. (except binlog-format=ROW - can
that cause it to be on?)

b) The tail is failing because the binlog files - index/binlogs -
are missing themselves. I checked datadir and they are not there.

I will run this locally again and verify.

[Alex Yurchenko (ayurchen)]

The command line above does not say "no defaults" so there might be a default file loaded somewhere. The reason I'm asking is that --binlog option is generated only when opt_bin_logname global variable is set. And it does not happen here. Next thing to check is that you're running the latest 5.6.

--binlog option is 5.6 specific, it is to transfer the last binlog file that contains MySQL "gtids" to sync them between the nodes.

[Raghavendra D Prabhu (raghavendra-prabhu)]

@Alex,

From code it looks like:

  const char* binlog_opt= (opt_bin_logname ? WSREP_SST_OPT_BINLOG : "");
  const char* binlog_opt_val= (opt_bin_logname ? opt_bin_logname : "");

MySQL [(none)]> show global variables like '%log_bin%';
+---------------------------------+-------+
| Variable_name | Value |
+---------------------------------+-------+
| log_bin | OFF |
| log_bin_basename | |
| log_bin_index | |
| log_bin_trust_function_creators | ON |
| log_bin_use_v1_row_events | OFF |
| sql_log_bin | ON |
+---------------------------------+-------+
6 rows in set (0.00 sec)

===============================================================================

So, it is "OFF" by default if not set, https://dev.mysql.com/doc/refman/5.6/en/replication-options-binary-log.html#sysvar_log_bin also confirms it.

So, a different alternative needs to be used for ' const char* binlog_opt= (opt_bin_logname ? WSREP_SST_OPT_BINLOG : ""); '

  bool binlog_on= mysql_bin_log.is_open() && thd->variables.sql_log_bin;

from transaction.cc looks good.

[Raghavendra D Prabhu (raghavendra-prabhu)]

  const char* binlog_opt= (strcmp(opt_bin_logname, "OFF") ? WSREP_SST_OPT_BINLOG : "");

should do for now.
But, since binlogging can be turned on/off for a session, the thread specific variable may be required. (or may not be depending on how it effects SST)

[Raghavendra D Prabhu (raghavendra-prabhu)]

Fixed as:

bzr log -r437 -p
------------------------------------------------------------
revno: 437
fixes bug: https://launchpad.net/bugs/1228333
committer: Raghavendra D Prabhu <email address hidden>
branch nick: pxc-5.6-test
timestamp: Mon 2013-09-23 23:02:36 +0530
message:
  Bug#1228333: Fix the binlog issue during rsync SST
diff:
=== modified file 'Percona-Server/sql/wsrep_sst.cc'
--- Percona-Server/sql/wsrep_sst.cc 2013-09-20 21:34:32 +0000
+++ Percona-Server/sql/wsrep_sst.cc 2013-09-23 17:32:36 +0000
@@ -402,8 +402,8 @@
   ssize_t cmd_len= 1024;
   char cmd_str[cmd_len];
   const char* sst_dir= mysql_real_data_home;
- const char* binlog_opt= (opt_bin_logname ? WSREP_SST_OPT_BINLOG : "");
- const char* binlog_opt_val= (opt_bin_logname ? opt_bin_logname : "");
+ const char* binlog_opt= (strcmp(opt_bin_logname, "0") ? WSREP_SST_OPT_BINLOG : "");
+ const char* binlog_opt_val= (strcmp(opt_bin_logname, "0") ? opt_bin_logname : "");

   int ret= snprintf (cmd_str, cmd_len,
                      "wsrep_sst_%s "
@@ -929,8 +929,8 @@
 {
   ssize_t cmd_len = 4096;
   char cmd_str[cmd_len];
- const char* binlog_opt= (opt_bin_logname ? WSREP_SST_OPT_BINLOG : "");
- const char* binlog_opt_val= (opt_bin_logname ? opt_bin_logname : "");
+ const char* binlog_opt= (strcmp(opt_bin_logname, "0") ? WSREP_SST_OPT_BINLOG : "");
+ const char* binlog_opt_val= (strcmp(opt_bin_logname, "0") ? opt_bin_logname : "");

   int ret= snprintf (cmd_str, cmd_len,
                      "wsrep_sst_%s "

and tested with rsync SST + sysbench.

[Raghavendra D Prabhu (raghavendra-prabhu)]

The above fix segfaults the Xtrabackup SST though. Rsync SST works fine.

[Raghavendra D Prabhu (raghavendra-prabhu)]

Looks like opt_bin_logname is null sometimes, checking for it fixes that.

[Teemu Ollakka (teemu-ollakka)]

Fix to lp:codership-mysql/5.6 pushed in rev 3942.

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PXC-1442