Percona XtraDB Cluster moved to https://jira.percona.com/projects/PXC

service mysql restart; Node crashing after joining to cluster

Bug #1609801 reported by Mike on 2016-08-04

This bug affects 1 person

Affects		Status	Importance	Assigned to	Milestone
	Percona XtraDB Cluster moved to https://jira.percona.com/projects/PXC	New	Undecided	Unassigned

Bug Description

Error in my_thread_global_end(): 2 threads didn't exit
mysqld: /mnt/workspace/percona-xtradb-cluster-5.6-debian-binary-new/label_exp/debian-jessie-64bit/percona-xtradb-cluster-5.6-5.6.30-25.16/mysys/my_thr_init.c:207: m y_thread_global_end: Assertion `0' failed.
13:06:43 UTC - mysqld got signal 6 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
We will try our best to scrape up some info that will hopefully help
diagnose the problem, but since we have already crashed,
something is definitely wrong and this may fail.
Please help us make Percona XtraDB Cluster better by reporting any
bugs at https://bugs.launchpad.net/percona-xtradb-cluster

key_buffer_size=46212576
read_buffer_size=131072
max_used_connections=0
max_threads=302
thread_count=1
connection_count=0
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 165436 K bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x0
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 0 thread_stack 0x40000
/usr/sbin/mysqld(my_print_stacktrace+0x2c)[0x90aaec]
/usr/sbin/mysqld(handle_fatal_signal+0x469)[0x68ac69]
/lib/x86_64-linux-gnu/libpthread.so.0(+0xf8d0)[0x7f126454f8d0]
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0x37)[0x7f1262465067]
/lib/x86_64-linux-gnu/libc.so.6(abort+0x148)[0x7f1262466448]
/lib/x86_64-linux-gnu/libc.so.6(+0x2e266)[0x7f126245e266]
/lib/x86_64-linux-gnu/libc.so.6(+0x2e312)[0x7f126245e312]
/usr/sbin/mysqld[0x908999]
/usr/sbin/mysqld(my_end+0x70)[0x906030]
/usr/sbin/mysqld[0x5a7ead]
/usr/sbin/mysqld(unireg_abort+0x16f)[0x5af14f]
/usr/sbin/mysqld(_Z18wsrep_sst_receivedP5wsrepRK10wsrep_uuidlPKvm+0x23d)[0x5c3e7d]
/usr/sbin/mysqld(_Z18wsrep_sst_continuev+0xaa)[0x5c3f3a]
/usr/sbin/mysqld(_Z11mysqld_mainiPPc+0x146f)[0x5b642f]
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf5)[0x7f1262451b45]
/usr/sbin/mysqld[0x5a60bd]
You may download the Percona XtraDB Cluster operations manual by visiting
http://www.percona.com/software/percona-xtradb-cluster/. You may find information
in the manual which will help you identify the cause of the crash.
160804 15:06:43 mysqld_safe mysqld from pid file /var/run/mysql/mysql.pid ended

Revision history for this message

Krunal Bauskar (krunal-bauskar) wrote on 2016-08-08:

Can you share complete error log.

It seems like for some reason SST fails but galera doesn't ensure a clean shutdown.
(clean shutdown is existing issue and has been observed as part of other use-cases too
but may be what is interesting to findout is why SST failed ?)

Revision history for this message

Mike (h-biuro) wrote on 2016-08-08:

Download full text (30.8 KiB)

Hi! Thanks for reply,

another bug discovered:
server booted, mysql started, synced full transfer.

service mysql stop

netstat -ptan

------------

root@db03:~# head -400 /var/log/mysqld.log
2016-08-08 11:59:52 4009 [Note] /usr/sbin/mysqld: Normal shutdown

Hi! Thanks for reply,

another bug discovered: 
server booted, mysql started, synced full transfer.

service mysql stop

netstat -ptan

root@db03:~# netstat -ptan
Active Internet connections (servers and established)
Proto Recv-Q Send-Q Local Address           Foreign Address         State       PID/Program name
tcp        0      0 0.0.0.0:19381           0.0.0.0:*               LISTEN      2757/rpc.statd
tcp        0      0 0.0.0.0:22              0.0.0.0:*               LISTEN      2828/sshd
tcp        0      0 0.0.0.0:25              0.0.0.0:*               LISTEN      20105/master
tcp        0      0 0.0.0.0:5666            0.0.0.0:*               LISTEN      2881/nrpe
tcp        0      0 0.0.0.0:111             0.0.0.0:*               LISTEN      2746/rpcbind
tcp        0      0 0.0.0.0:9200            0.0.0.0:*               LISTEN      2898/xinetd

------------

root@db03:~# head -400 /var/log/mysqld.log
2016-08-08 11:59:52 4009 [Note] /usr/sbin/mysqld: Normal shutdown

2016-08-08 11:59:52 4009 [Note] WSREP: Stop replication
2016-08-08 11:59:52 4009 [Note] WSREP: Closing send monitor...
2016-08-08 11:59:52 4009 [Note] WSREP: Closed send monitor.
2016-08-08 11:59:52 4009 [Note] WSREP: gcomm: terminating thread
2016-08-08 11:59:52 4009 [Note] WSREP: gcomm: joining thread
2016-08-08 11:59:52 4009 [Note] WSREP: gcomm: closing backend
2016-08-08 11:59:52 4009 [Note] WSREP: view(view_id(NON_PRIM,0ca49fa1,27) memb {
        c8f2477c,0
} joined {
} left {
} partitioned {
        0ca49fa1,0
        c5a86da4,0
})
2016-08-08 11:59:52 4009 [Note] WSREP: New COMPONENT: primary = no, bootstrap = no, my_idx = 0, memb_num = 1
2016-08-08 11:59:52 4009 [Note] WSREP: view((empty))
2016-08-08 11:59:52 4009 [Note] WSREP: gcomm: closed
2016-08-08 11:59:52 4009 [Note] WSREP: Flow-control interval: [16, 16]
2016-08-08 11:59:52 4009 [Note] WSREP: Received NON-PRIMARY.
2016-08-08 11:59:52 4009 [Note] WSREP: Shifting SYNCED -> OPEN (TO: 256135853)
2016-08-08 11:59:52 4009 [Note] WSREP: Received self-leave message.
2016-08-08 11:59:52 4009 [Note] WSREP: New cluster view: global state: cad69e4f-c04d-11e5-ab50-efd4e2ebbb7c:256135853, view# -1: non-Primary, number of nodes: 1, my index: 0, protocol version 3
2016-08-08 11:59:52 4009 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2016-08-08 11:59:52 4009 [Note] WSREP: Flow-control interval: [0, 0]
2016-08-08 11:59:52 4009 [Note] WSREP: Received SELF-LEAVE. Closing connection.
2016-08-08 11:59:52 4009 [Note] WSREP: Shifting OPEN -> CLOSED (TO: 256135853)
2016-08-08 11:59:52 4009 [Note] WSREP: RECV thread exiting 0: Success
2016-08-08 11:59:52 4009 [Note] WSREP: New cluster view: global state: cad69e4f-c04d-11e5-ab50-efd4e2ebbb7c:256135853, view# -1: non-Primary, number of nodes: 0, my index: -1, protocol version 3
2016-08-08 11:59:52 4009 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2016-08-08 11:59:52 4009 [Note] WSREP: recv_thread() joined.
2016-08-08 11:59:52 4009 [Note] WSREP: applier thread exiting (code:0)
2016-08-08 11:59:52 4009 [Note] WSREP: Closing replication queue.
2016-08-08 11:59:52 4009 [Note] WSREP: Closing slave action queue.
2016-08-08 11:59:52 4009 [Note] WSREP: applier thread exiting (code:6)
2016-08-08 11:59:52 4009 [Note] WSREP: applier thread exiting (code:6)
2016-08-08 11:59:52 4009 [Note] WSREP: applier thread exiting (code:6)
2016-08-08 11:59:52 4009 [Note] WSREP: applier thread exiting (code:6)
2016-08-08 11:59:52 4009 [Note] WSREP: applier thread exiting (code:6)
2016-08-08 11:59:52 4009 [Note] WSREP: applier thread exiting (code:6)
2016-08-08 11:59:52 4009 [Note] WSREP: applier thread exiting (code:6)
2016-08-08 11:59:54 4009 [Note] WSREP: killing local connection: 9217825
2016-08-08 11:59:54 4009 [Note] WSREP: killing local connection: 9218318
2016-08-08 11:59:54 4009 [Note] WSREP: killing local connection: 9218316
2016-08-08 11:59:54 4009 [Note] WSREP: killing local connection: 9215981
2016-08-08 11:59:54 4009 [Note] WSREP: killing local connection: 9218484
2016-08-08 11:59:54 4009 [Note] WSREP: killing local connection: 9216897
2016-08-08 11:59:54 4009 [Note] WSREP: killing local connection: 9217705
2016-08-08 11:59:54 4009 [Note] WSREP: rollbacker thread exiting
2016-08-08 11:59:54 4009 [Note] Giving 2 client threads a chance to die gracefully
2016-08-08 11:59:54 4009 [Note] Event Scheduler: Purging the queue. 0 events
2016-08-08 11:59:54 4009 [Note] Shutting down slave threads
2016-08-08 11:59:56 4009 [Note] Forcefully disconnecting 1 remaining clients
2016-08-08 11:59:56 4009 [Warning] /usr/sbin/mysqld: Forcing close of thread 10  user: 'cmon'

2016-08-08 11:59:56 4009 [Note] WSREP: dtor state: CLOSED
2016-08-08 11:59:56 4009 [Note] WSREP: mon: entered 3909759 oooe fraction 0 oool fraction 2.5577e-07
2016-08-08 11:59:56 4009 [Note] WSREP: mon: entered 3909759 oooe fraction 0.00441562 oool fraction 0.000143999
2016-08-08 11:59:56 4009 [Note] WSREP: mon: entered 4014600 oooe fraction 0 oool fraction 2.49091e-07
2016-08-08 11:59:56 4009 [Note] WSREP: cert index usage at exit 0
2016-08-08 11:59:56 4009 [Note] WSREP: cert trx map usage at exit 52
2016-08-08 11:59:56 4009 [Note] WSREP: deps set usage at exit 0
2016-08-08 11:59:56 4009 [Note] WSREP: avg deps dist 117.228
2016-08-08 11:59:56 4009 [Note] WSREP: avg cert interval 0.022651
2016-08-08 11:59:56 4009 [Note] WSREP: cert index size 118
2016-08-08 11:59:56 4009 [Note] WSREP: Service thread queue flushed.
2016-08-08 11:59:56 4009 [Note] WSREP: wsdb trx map usage 0 conn query map usage 0
2016-08-08 11:59:56 4009 [Note] WSREP: MemPool(LocalTrxHandle): hit ratio: 0.999957, misses: 399, in use: 0, in pool: 399
2016-08-08 11:59:56 4009 [Note] WSREP: MemPool(SlaveTrxHandle): hit ratio: 0.419061, misses: 16519, in use: 0, in pool: 8839
2016-08-08 11:59:56 4009 [Note] WSREP: Shifting CLOSED -> DESTROYED (TO: 256135853)
2016-08-08 11:59:56 4009 [Note] WSREP: Flushing memory map to disk...
2016-08-08 11:59:56 4009 [Note] Binlog end
2016-08-08 11:59:57 4009 [Note] Shutting down plugin 'partition'
2016-08-08 11:59:57 4009 [Note] Shutting down plugin 'ARCHIVE'
2016-08-08 11:59:57 4009 [Note] Shutting down plugin 'BLACKHOLE'
2016-08-08 11:59:57 4009 [Note] Shutting down plugin 'INNODB_CHANGED_PAGES'
2016-08-08 11:59:57 4009 [Note] Shutting down plugin 'INNODB_SYS_DATAFILES'
2016-08-08 11:59:57 4009 [Note] Shutting down plugin 'INNODB_SYS_TABLESPACES'
2016-08-08 11:59:57 4009 [Note] Shutting down plugin 'INNODB_SYS_FOREIGN_COLS'
2016-08-08 11:59:57 4009 [Note] Shutting down plugin 'INNODB_SYS_FOREIGN'
2016-08-08 11:59:57 4009 [Note] Shutting down plugin 'INNODB_SYS_FIELDS'
2016-08-08 11:59:57 4009 [Note] Shutting down plugin 'INNODB_SYS_COLUMNS'
2016-08-08 11:59:57 4009 [Note] Shutting down plugin 'INNODB_SYS_INDEXES'
2016-08-08 11:59:57 4009 [Note] Shutting down plugin 'INNODB_SYS_TABLESTATS'
2016-08-08 11:59:57 4009 [Note] Shutting down plugin 'INNODB_SYS_TABLES'
2016-08-08 11:59:57 4009 [Note] Shutting down plugin 'INNODB_FT_INDEX_TABLE'
2016-08-08 11:59:57 4009 [Note] Shutting down plugin 'INNODB_FT_INDEX_CACHE'
2016-08-08 11:59:57 4009 [Note] Shutting down plugin 'INNODB_FT_CONFIG'
2016-08-08 11:59:57 4009 [Note] Shutting down plugin 'INNODB_FT_BEING_DELETED'
2016-08-08 11:59:57 4009 [Note] Shutting down plugin 'INNODB_FT_DELETED'
2016-08-08 11:59:57 4009 [Note] Shutting down plugin 'INNODB_FT_DEFAULT_STOPWORD'
2016-08-08 11:59:57 4009 [Note] Shutting down plugin 'INNODB_METRICS'
2016-08-08 11:59:57 4009 [Note] Shutting down plugin 'INNODB_BUFFER_POOL_STATS'
2016-08-08 11:59:57 4009 [Note] Shutting down plugin 'INNODB_BUFFER_PAGE_LRU'
2016-08-08 11:59:57 4009 [Note] Shutting down plugin 'INNODB_BUFFER_PAGE'
2016-08-08 11:59:57 4009 [Note] Shutting down plugin 'INNODB_CMP_PER_INDEX_RESET'
2016-08-08 11:59:57 4009 [Note] Shutting down plugin 'INNODB_CMP_PER_INDEX'
2016-08-08 11:59:57 4009 [Note] Shutting down plugin 'INNODB_CMPMEM_RESET'
2016-08-08 11:59:57 4009 [Note] Shutting down plugin 'INNODB_CMPMEM'
2016-08-08 11:59:57 4009 [Note] Shutting down plugin 'INNODB_CMP_RESET'
2016-08-08 11:59:57 4009 [Note] Shutting down plugin 'INNODB_CMP'
2016-08-08 11:59:57 4009 [Note] Shutting down plugin 'INNODB_LOCK_WAITS'
2016-08-08 11:59:57 4009 [Note] Shutting down plugin 'INNODB_LOCKS'
2016-08-08 11:59:57 4009 [Note] Shutting down plugin 'INNODB_TRX'
2016-08-08 11:59:57 4009 [Note] Shutting down plugin 'XTRADB_RSEG'
2016-08-08 11:59:57 4009 [Note] Shutting down plugin 'XTRADB_INTERNAL_HASH_TABLES'
2016-08-08 11:59:57 4009 [Note] Shutting down plugin 'XTRADB_READ_VIEW'
2016-08-08 11:59:57 4009 [Note] Shutting down plugin 'InnoDB'
2016-08-08 12:00:01 4009 [Note] InnoDB: FTS optimize thread exiting.
2016-08-08 12:00:01 4009 [Note] InnoDB: Starting shutdown...
2016-08-08 12:00:03 4009 [Note] InnoDB: Shutdown completed; log sequence number 724015545071
2016-08-08 12:00:03 4009 [Note] Shutting down plugin 'PERFORMANCE_SCHEMA'
2016-08-08 12:00:03 4009 [Note] Shutting down plugin 'MEMORY'
2016-08-08 12:00:03 4009 [Note] Shutting down plugin 'MRG_MYISAM'
2016-08-08 12:00:03 4009 [Note] Shutting down plugin 'MyISAM'
2016-08-08 12:00:03 4009 [Note] Shutting down plugin 'CSV'
2016-08-08 12:00:03 4009 [Note] Shutting down plugin 'sha256_password'
2016-08-08 12:00:03 4009 [Note] Shutting down plugin 'mysql_old_password'
2016-08-08 12:00:03 4009 [Note] Shutting down plugin 'mysql_native_password'
2016-08-08 12:00:03 4009 [Note] Shutting down plugin 'wsrep'
2016-08-08 12:00:03 4009 [Note] Shutting down plugin 'binlog'
2016-08-08 12:00:03 4009 [Note] /usr/sbin/mysqld: Shutdown complete

160808 12:00:03 mysqld_safe mysqld from pid file /var/run/mysql/mysql.pid ended
160808 12:00:04 mysqld_safe Starting mysqld daemon with databases from /var/lib/mysql
160808 12:00:04 mysqld_safe Skipping wsrep-recover for cad69e4f-c04d-11e5-ab50-efd4e2ebbb7c:256135853 pair
160808 12:00:04 mysqld_safe Assigning cad69e4f-c04d-11e5-ab50-efd4e2ebbb7c:256135853 to wsrep_start_position
2016-08-08 12:00:04 0 [Note] /usr/sbin/mysqld (mysqld 5.6.30-76.3-56) starting as process 17618 ...
2016-08-08 12:00:04 17618 [Note] WSREP: Read nil XID from storage engines, skipping position init
2016-08-08 12:00:04 17618 [Note] WSREP: wsrep_load(): loading provider library '/usr/lib/libgalera_smm.so'
2016-08-08 12:00:04 17618 [Note] WSREP: wsrep_load(): Galera 3.16(r5c765eb) by Codership Oy <info@codership.com> loaded successfully.
2016-08-08 12:00:04 17618 [Note] WSREP: CRC-32C: using hardware acceleration.
2016-08-08 12:00:04 17618 [Note] WSREP: Found saved state: cad69e4f-c04d-11e5-ab50-efd4e2ebbb7c:256135853
2016-08-08 12:00:04 17618 [Note] WSREP: Passing config to GCS: base_dir = /var/lib/mysql/; base_host = db03.mydomain.net; 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_count = 0; gcache.keep_pages_size = 0; gcache.mem_size = 0; gcache.name = /var/lib/mysql//galera.cache; gcache.page_size = 128M; gcache.size = 4G; gcomm.thread_prio = ; 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
2016-08-08 12:00:04 17618 [Note] WSREP: Service thread queue flushed.
2016-08-08 12:00:04 17618 [Note] WSREP: Assign initial position for certification: 256135853, protocol version: -1
2016-08-08 12:00:04 17618 [Note] WSREP: wsrep_sst_grab()
2016-08-08 12:00:04 17618 [Note] WSREP: Start replication
2016-08-08 12:00:04 17618 [Note] WSREP: Setting initial position to cad69e4f-c04d-11e5-ab50-efd4e2ebbb7c:256135853
2016-08-08 12:00:04 17618 [Note] WSREP: protonet asio version 0
2016-08-08 12:00:04 17618 [Note] WSREP: Using CRC-32C for message checksums.
2016-08-08 12:00:04 17618 [Note] WSREP: backend: asio
2016-08-08 12:00:04 17618 [Note] WSREP: gcomm thread scheduling priority set to other:0
2016-08-08 12:00:04 17618 [Warning] WSREP: access file(/var/lib/mysql//gvwstate.dat) failed(No such file or directory)
2016-08-08 12:00:04 17618 [Note] WSREP: restore pc from disk failed
2016-08-08 12:00:04 17618 [Note] WSREP: GMCast version 0
2016-08-08 12:00:04 17618 [Note] WSREP: (e142d053, 'tcp://0.0.0.0:4567') listening at tcp://0.0.0.0:4567
2016-08-08 12:00:04 17618 [Note] WSREP: (e142d053, 'tcp://0.0.0.0:4567') multicast: , ttl: 1
2016-08-08 12:00:04 17618 [Note] WSREP: EVS version 0
2016-08-08 12:00:04 17618 [Note] WSREP: gcomm: connecting to group 'my_wsrep_cluster', peer 'db03.mydomain.net:4567,db02.mydomain.net:4567,db01.mydomain.net:4567'
2016-08-08 12:00:04 17618 [Note] WSREP: (e142d053, 'tcp://0.0.0.0:4567') turning message relay requesting on, nonlive peers:
2016-08-08 12:00:06 17618 [Note] WSREP: declaring 0ca49fa1 at tcp://172.16.4.1:4567 stable
2016-08-08 12:00:06 17618 [Note] WSREP: declaring c5a86da4 at tcp://172.16.4.2:4567 stable
2016-08-08 12:00:07 17618 [Note] WSREP: Node 0ca49fa1 state prim
2016-08-08 12:00:07 17618 [Note] WSREP: view(view_id(PRIM,0ca49fa1,29) memb {
        0ca49fa1,0
        c5a86da4,0
        e142d053,0
} joined {
} left {
} partitioned {
})
2016-08-08 12:00:07 17618 [Note] WSREP: save pc into disk
2016-08-08 12:00:07 17618 [Note] WSREP: discarding pending addr without UUID: tcp://172.16.0.23:4567
2016-08-08 12:00:07 17618 [Note] WSREP: discarding pending addr proto entry 0x31623b0
2016-08-08 12:00:07 17618 [Note] WSREP: gcomm: connected
2016-08-08 12:00:07 17618 [Note] WSREP: Changing maximum packet size to 64500, resulting msg size: 32636
2016-08-08 12:00:07 17618 [Note] WSREP: Shifting CLOSED -> OPEN (TO: 0)
2016-08-08 12:00:07 17618 [Note] WSREP: Opened channel 'my_wsrep_cluster'
2016-08-08 12:00:07 17618 [Note] WSREP: New COMPONENT: primary = yes, bootstrap = no, my_idx = 2, memb_num = 3
2016-08-08 12:00:07 17618 [Note] WSREP: Waiting for SST to complete.
2016-08-08 12:00:07 17618 [Note] WSREP: STATE EXCHANGE: Waiting for state UUID.
2016-08-08 12:00:07 17618 [Note] WSREP: STATE EXCHANGE: sent state msg: e2b20723-5d4e-11e6-866f-d7f36dc5bb80
2016-08-08 12:00:07 17618 [Note] WSREP: STATE EXCHANGE: got state msg: e2b20723-5d4e-11e6-866f-d7f36dc5bb80 from 0 (db01.mydomain.net)
2016-08-08 12:00:07 17618 [Note] WSREP: STATE EXCHANGE: got state msg: e2b20723-5d4e-11e6-866f-d7f36dc5bb80 from 1 (db02.mydomain.net)
2016-08-08 12:00:07 17618 [Note] WSREP: STATE EXCHANGE: got state msg: e2b20723-5d4e-11e6-866f-d7f36dc5bb80 from 2 (db03.mydomain.net)
2016-08-08 12:00:07 17618 [Note] WSREP: Quorum results:
        version    = 4,
        component  = PRIMARY,
        conf_id    = 22,
        members    = 2/3 (joined/total),
        act_id     = 256135854,
        last_appl. = -1,
        protocols  = 0/7/3 (gcs/repl/appl),
        group UUID = cad69e4f-c04d-11e5-ab50-efd4e2ebbb7c
2016-08-08 12:00:07 17618 [Note] WSREP: Flow-control interval: [28, 28]
2016-08-08 12:00:07 17618 [Note] WSREP: Shifting OPEN -> PRIMARY (TO: 256135854)
2016-08-08 12:00:07 17618 [Note] WSREP: State transfer required:
        Group state: cad69e4f-c04d-11e5-ab50-efd4e2ebbb7c:256135854
        Local state: cad69e4f-c04d-11e5-ab50-efd4e2ebbb7c:256135853
2016-08-08 12:00:07 17618 [Note] WSREP: New cluster view: global state: cad69e4f-c04d-11e5-ab50-efd4e2ebbb7c:256135854, view# 23: Primary, number of nodes: 3, my index: 2, protocol version 3
2016-08-08 12:00:07 17618 [Warning] WSREP: Gap in state sequence. Need state transfer.
2016-08-08 12:00:07 17618 [Note] WSREP: Running: 'wsrep_sst_xtrabackup-v2 --role 'joiner' --address 'db03.mydomain.net' --datadir '/var/lib/mysql/' --defaults-file '/etc/mysql/my.cnf' --defaults-group-suffix '' --parent '17618'  '' '
WSREP_SST: [INFO] Streaming with xbstream (20160808 12:00:07.836)
WSREP_SST: [INFO] Using socat as streamer (20160808 12:00:07.837)
2016-08-08 12:00:07 17618 [Note] WSREP: Prepared SST request: xtrabackup-v2|db03.mydomain.net:4444/xtrabackup_sst//1
2016-08-08 12:00:07 17618 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2016-08-08 12:00:07 17618 [Note] WSREP: REPL Protocols: 7 (3, 2)
2016-08-08 12:00:07 17618 [Note] WSREP: Service thread queue flushed.
2016-08-08 12:00:07 17618 [Note] WSREP: Assign initial position for certification: 256135854, protocol version: 3
2016-08-08 12:00:07 17618 [Note] WSREP: Service thread queue flushed.
2016-08-08 12:00:07 17618 [Note] WSREP: IST receiver addr using tcp://db03.mydomain.net:4568
2016-08-08 12:00:07 17618 [Warning] WSREP: Failed to prepare for incremental state transfer: Failed to open IST listener at tcp://db03.mydomain.net:4568', asio error 'Cannot assign requested address': 99 (Cannot assign requested address)
         at galera/src/ist.cpp:prepare():326. IST will be unavailable.
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2016-08-08 12:00:07 17618 [Note] WSREP: Member 2.0 (db03.mydomain.net) requested state transfer from '*any*'. Selected 0.0 (db01.mydomain.net)(SYNCED) as donor.
2016-08-08 12:00:07 17618 [Note] WSREP: Shifting PRIMARY -> JOINER (TO: 256135861)
2016-08-08 12:00:07 17618 [Note] WSREP: Requesting state transfer: success, donor: 0
WSREP_SST: [INFO] Evaluating timeout -k 110 100 socat -u TCP-LISTEN:4444,reuseaddr stdio | pv -f  -i 10 -N joiner -F '%N => Rate:%r Avg:%a Elapsed:%t %e Bytes: %b %p'  | xbstream -x; RC=( ${PIPESTATUS[@]} ) (20160808 12:00:07.897)
   joiner: => Rate:[ 891 B/s] Avg:[ 891 B/s] Elapsed:0:00:00  Bytes:  139 B
WSREP_SST: [INFO] NOTE: Joiner-Recv-gtid took 1 seconds (20160808 12:00:08.056)
WSREP_SST: [INFO] Proceeding with SST (20160808 12:00:08.088)
WSREP_SST: [INFO] Evaluating socat -u TCP-LISTEN:4444,reuseaddr stdio | pv -f  -i 10 -N joiner -F '%N => Rate:%r Avg:%a Elapsed:%t %e Bytes: %b %p'  | xbstream -x; RC=( ${PIPESTATUS[@]} ) (20160808 12:00:08.089)
WSREP_SST: [INFO] Cleaning the existing datadir and innodb-data/log directories (20160808 12:00:08.090)
removed ‘/var/lib/mysql/z_sometable/sshop_products_groups_rel.ibd’
removed ‘/var/lib/mysql/z_sometable/FTS_000000000002f27d_BEING_DELETED_CACHE.ibd’
removed ‘/var/lib/mysql/z_sometable/FTS_000000000002f27d_000000000005b0da_INDEX_6.ibd’
removed ‘/var/lib/mysql/z_sometable/sshop_categories_products.frm’
removed ‘/var/lib/mysql/z_sometable/sshop_shipments.ibd’
removed ‘/var/lib/mysql/z_sometable/FTS_000000000002f27d_DELETED.ibd’

--------------------------------------------

2016-08-08 12:00:07 17618 [Warning] WSREP: Failed to prepare for incremental state transfer: Failed to open IST listener at tcp://db03.mydomain.net:4568', asio error 'Cannot assign requested address': 99 (Cannot assign requested address)
         at galera/src/ist.cpp:prepare():326. IST will be unavailable.

--------------------------------------------

Then, next service mysql start

--------------------------------------------

AAAAAAAAAAAAAAAAAAAnd finally:

2016-08-08 13:04:31 133363 [Note] WSREP: 0.0 (db01.mydomain.net): State transfer to 1.0 (db03.mydomain.net) complete.
2016-08-08 13:04:31 133363 [Note] WSREP: Member 0.0 (db01.mydomain.net) synced with group.
   joiner: => Rate:[37.4MiB/s] Avg:[37.4MiB/s] Elapsed:0:30:46  Bytes: 67.4GiB
WSREP_SST: [INFO] NOTE: Joiner-Recv-SST took 1847 seconds (20160808 13:04:37.351)
WSREP_SST: [INFO] Preparing the backup at /var/lib/mysql//.sst (20160808 13:04:37.355)
WSREP_SST: [INFO] Evaluating innobackupex --no-version-check --use-memory=6G --apply-log $rebuildcmd ${DATA} &>${DATA}/innobackup.prepare.log (20160808 13:04:37.357)

root@db03:/var/log#
root@db03:/var/log#
root@db03:/var/log#
root@db03:/var/log# WSREP_SST: [INFO] NOTE: Xtrabackup prepare stage took 30 seconds (20160808 13:05:07.802)
WSREP_SST: [INFO] Moving the backup to /var/lib/mysql/ (20160808 13:05:07.804)
WSREP_SST: [INFO] Evaluating innobackupex --defaults-file=/etc/mysql/my.cnf  --defaults-group=mysqld --no-version-check   --move-back --force-non-empty-directories ${DATA} &>${DATA}/innobackup.move.log (20160808 13:05:07.806)
WSREP_SST: [INFO] NOTE: Xtrabackup move stage took 2 seconds (20160808 13:05:09.616)
WSREP_SST: [INFO] Move successful, removing /var/lib/mysql//.sst (20160808 13:05:09.617)
WSREP_SST: [INFO] Galera co-ords from recovery: cad69e4f-c04d-11e5-ab50-efd4e2ebbb7c:256189451 (20160808 13:05:09.653)
WSREP_SST: [INFO] Total time on joiner: 32 seconds (20160808 13:05:09.655)
WSREP_SST: [INFO] Removing the sst_in_progress file (20160808 13:05:09.656)
2016-08-08 13:05:09 133363 [Note] WSREP: SST complete, seqno: 256189451
2016-08-08 13:05:09 133363 [Note] Plugin 'FEDERATED' is disabled.
2016-08-08 13:05:09 133363 [Warning] option 'innodb-buffer-pool-instances': signed value -1 adjusted to 0
2016-08-08 13:05:09 133363 [Note] InnoDB: Using atomics to ref count buffer pool pages
2016-08-08 13:05:09 133363 [Note] InnoDB: The InnoDB memory heap is disabled
2016-08-08 13:05:09 133363 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2016-08-08 13:05:09 133363 [Note] InnoDB: Memory barrier is not used
2016-08-08 13:05:09 133363 [Note] InnoDB: Compressed tables use zlib 1.2.8
2016-08-08 13:05:09 133363 [Note] InnoDB: Using Linux native AIO
2016-08-08 13:05:09 133363 [Note] InnoDB: Using CPU crc32 instructions
2016-08-08 13:05:09 133363 [Note] InnoDB: Initializing buffer pool, size = 1005.0M
2016-08-08 13:05:09 133363 [Note] InnoDB: Completed initialization of buffer pool
2016-08-08 13:05:09 133363 [Note] InnoDB: Highest supported file format is Barracuda.
2016-08-08 13:05:11 133363 [Note] InnoDB: 128 rollback segment(s) are active.
2016-08-08 13:05:11 133363 [Note] InnoDB: Waiting for purge to start
2016-08-08 13:05:11 133363 [Note] InnoDB:  Percona XtraDB (http://www.percona.com) 5.6.30-76.3 started; log sequence number 723793150595
2016-08-08 13:05:11 133363 [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: fa0b982f-5d57-11e6-801d-005056bc4d98.
2016-08-08 13:05:11 133363 [Note] RSA private key file not found: /var/lib/mysql//private_key.pem. Some authentication plugins will not work.
2016-08-08 13:05:11 133363 [Note] RSA public key file not found: /var/lib/mysql//public_key.pem. Some authentication plugins will not work.
2016-08-08 13:05:11 133363 [Note] Server hostname (bind-address): '0.0.0.0'; port: 3306
2016-08-08 13:05:11 133363 [Note]   - '0.0.0.0' resolves to '0.0.0.0';
2016-08-08 13:05:11 133363 [Note] Server socket created on IP: '0.0.0.0'.
2016-08-08 13:05:12 133363 [Note] Event Scheduler: Loaded 0 events
2016-08-08 13:05:12 133363 [Note] WSREP: Signalling provider to continue.
2016-08-08 13:05:12 133363 [Warning] WSREP: SST postion is in the past: 256189451, current: 256189454. Can't continue.
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2016-08-08 13:05:12 133363 [ERROR] Aborting

2016-08-08 13:05:12 133363 [Note] WSREP: Signalling cancellation of the SST request.
2016-08-08 13:05:12 133363 [Note] WSREP: SST request was cancelled
2016-08-08 13:05:12 133363 [Note] WSREP: Closing send monitor...
2016-08-08 13:05:12 133363 [Note] WSREP: Closed send monitor.
2016-08-08 13:05:12 133363 [Note] WSREP: gcomm: terminating thread
2016-08-08 13:05:12 133363 [Note] WSREP: gcomm: joining thread
2016-08-08 13:05:12 133363 [Note] WSREP: gcomm: closing backend
2016-08-08 13:05:12 133363 [Note] WSREP: view(view_id(NON_PRIM,0ca49fa1,31) memb {
        97cea26a,0
} joined {
} left {
} partitioned {
        0ca49fa1,0
        c5a86da4,0
})
2016-08-08 13:05:12 133363 [Note] WSREP: view((empty))
2016-08-08 13:05:12 133363 [Note] WSREP: New COMPONENT: primary = no, bootstrap = no, my_idx = 0, memb_num = 1
2016-08-08 13:05:12 133363 [Note] WSREP: gcomm: closed
2016-08-08 13:05:12 133363 [Note] WSREP: Flow-control interval: [16, 16]
2016-08-08 13:05:12 133363 [Note] WSREP: Received NON-PRIMARY.
2016-08-08 13:05:12 133363 [Note] WSREP: Shifting JOINER -> OPEN (TO: 256190352)
2016-08-08 13:05:12 133363 [Note] WSREP: Received self-leave message.
2016-08-08 13:05:12 133363 [Note] WSREP: Flow-control interval: [0, 0]
2016-08-08 13:05:12 133363 [Note] WSREP: Received SELF-LEAVE. Closing connection.
2016-08-08 13:05:12 133363 [Note] WSREP: Shifting OPEN -> CLOSED (TO: 256190352)
2016-08-08 13:05:12 133363 [Note] WSREP: RECV thread exiting 0: Success
2016-08-08 13:05:12 133363 [Note] WSREP: recv_thread() joined.
2016-08-08 13:05:12 133363 [Note] WSREP: Closing replication queue.
2016-08-08 13:05:12 133363 [Note] WSREP: Closing slave action queue.
2016-08-08 13:05:14 133363 [Note] WSREP: Service disconnected.
2016-08-08 13:05:14 133363 [Note] WSREP: rollbacker thread exiting
2016-08-08 13:05:15 133363 [Note] WSREP: Some threads may fail to exit.
2016-08-08 13:05:15 133363 [Note] Binlog end
2016-08-08 13:05:15 133363 [Note] Shutting down plugin 'partition'
2016-08-08 13:05:15 133363 [Note] Shutting down plugin 'ARCHIVE'
2016-08-08 13:05:15 133363 [Note] Shutting down plugin 'BLACKHOLE'
2016-08-08 13:05:15 133363 [Note] Shutting down plugin 'INNODB_CHANGED_PAGES'
2016-08-08 13:05:15 133363 [Note] Shutting down plugin 'INNODB_SYS_DATAFILES'
2016-08-08 13:05:15 133363 [Note] Shutting down plugin 'INNODB_SYS_TABLESPACES'
2016-08-08 13:05:15 133363 [Note] Shutting down plugin 'INNODB_SYS_FOREIGN_COLS'
2016-08-08 13:05:15 133363 [Note] Shutting down plugin 'INNODB_SYS_FOREIGN'
2016-08-08 13:05:15 133363 [Note] Shutting down plugin 'INNODB_SYS_FIELDS'
2016-08-08 13:05:15 133363 [Note] Shutting down plugin 'INNODB_SYS_COLUMNS'
2016-08-08 13:05:15 133363 [Note] Shutting down plugin 'INNODB_SYS_INDEXES'
2016-08-08 13:05:15 133363 [Note] Shutting down plugin 'INNODB_SYS_TABLESTATS'
2016-08-08 13:05:15 133363 [Note] Shutting down plugin 'INNODB_SYS_TABLES'
2016-08-08 13:05:15 133363 [Note] Shutting down plugin 'INNODB_FT_INDEX_TABLE'
2016-08-08 13:05:15 133363 [Note] Shutting down plugin 'INNODB_FT_INDEX_CACHE'
2016-08-08 13:05:15 133363 [Note] Shutting down plugin 'INNODB_FT_CONFIG'
2016-08-08 13:05:15 133363 [Note] Shutting down plugin 'INNODB_FT_BEING_DELETED'
2016-08-08 13:05:15 133363 [Note] Shutting down plugin 'INNODB_FT_DELETED'
2016-08-08 13:05:15 133363 [Note] Shutting down plugin 'INNODB_FT_DEFAULT_STOPWORD'
2016-08-08 13:05:15 133363 [Note] Shutting down plugin 'INNODB_METRICS'
2016-08-08 13:05:15 133363 [Note] Shutting down plugin 'INNODB_BUFFER_POOL_STATS'
2016-08-08 13:05:15 133363 [Note] Shutting down plugin 'INNODB_BUFFER_PAGE_LRU'
2016-08-08 13:05:15 133363 [Note] Shutting down plugin 'INNODB_BUFFER_PAGE'
2016-08-08 13:05:15 133363 [Note] Shutting down plugin 'INNODB_CMP_PER_INDEX_RESET'
2016-08-08 13:05:15 133363 [Note] Shutting down plugin 'INNODB_CMP_PER_INDEX'
2016-08-08 13:05:15 133363 [Note] Shutting down plugin 'INNODB_CMPMEM_RESET'
2016-08-08 13:05:15 133363 [Note] Shutting down plugin 'INNODB_CMPMEM'
2016-08-08 13:05:15 133363 [Note] Shutting down plugin 'INNODB_CMP_RESET'
2016-08-08 13:05:15 133363 [Note] Shutting down plugin 'INNODB_CMP'
2016-08-08 13:05:15 133363 [Note] Shutting down plugin 'INNODB_LOCK_WAITS'
2016-08-08 13:05:15 133363 [Note] Shutting down plugin 'INNODB_LOCKS'
2016-08-08 13:05:15 133363 [Note] Shutting down plugin 'INNODB_TRX'
2016-08-08 13:05:15 133363 [Note] Shutting down plugin 'XTRADB_RSEG'
2016-08-08 13:05:15 133363 [Note] Shutting down plugin 'XTRADB_INTERNAL_HASH_TABLES'
2016-08-08 13:05:15 133363 [Note] Shutting down plugin 'XTRADB_READ_VIEW'
2016-08-08 13:05:15 133363 [Note] Shutting down plugin 'InnoDB'
2016-08-08 13:05:15 133363 [Note] InnoDB: FTS optimize thread exiting.
2016-08-08 13:05:15 133363 [Note] InnoDB: Starting shutdown...
2016-08-08 13:05:17 133363 [Note] InnoDB: Shutdown completed; log sequence number 723793150605
2016-08-08 13:05:17 133363 [Note] Shutting down plugin 'PERFORMANCE_SCHEMA'
2016-08-08 13:05:17 133363 [Note] Shutting down plugin 'MEMORY'
2016-08-08 13:05:17 133363 [Note] Shutting down plugin 'MRG_MYISAM'
2016-08-08 13:05:17 133363 [Note] Shutting down plugin 'MyISAM'
2016-08-08 13:05:17 133363 [Note] Shutting down plugin 'CSV'
2016-08-08 13:05:17 133363 [Note] Shutting down plugin 'sha256_password'
2016-08-08 13:05:17 133363 [Note] Shutting down plugin 'mysql_old_password'
2016-08-08 13:05:17 133363 [Note] Shutting down plugin 'mysql_native_password'
2016-08-08 13:05:17 133363 [Note] Shutting down plugin 'wsrep'
2016-08-08 13:05:17 133363 [Note] Shutting down plugin 'binlog'
2016-08-08 13:05:17 133363 [Note] /usr/sbin/mysqld: Shutdown complete

Error in my_thread_global_end(): 2 threads didn't exit
mysqld: /mnt/workspace/percona-xtradb-cluster-5.6-debian-binary-new/label_exp/debian-jessie-64bit/percona-xtradb-cluster-5.6-5.6.30-25.16/mysys/my_thr_init.c:207: my_thread_global_end: Assertion `0' failed.
11:05:22 UTC - mysqld got signal 6 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
We will try our best to scrape up some info that will hopefully help
diagnose the problem, but since we have already crashed,
something is definitely wrong and this may fail.
Please help us make Percona XtraDB Cluster better by reporting any
bugs at https://bugs.launchpad.net/percona-xtradb-cluster

key_buffer_size=45897184
read_buffer_size=131072
max_used_connections=0
max_threads=302
thread_count=1
connection_count=0
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 165128 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x0
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 0 thread_stack 0x40000
/usr/sbin/mysqld(my_print_stacktrace+0x2c)[0x90aaec]
/usr/sbin/mysqld(handle_fatal_signal+0x469)[0x68ac69]
/lib/x86_64-linux-gnu/libpthread.so.0(+0xf8d0)[0x7f5f9991b8d0]
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0x37)[0x7f5f97831067]
/lib/x86_64-linux-gnu/libc.so.6(abort+0x148)[0x7f5f97832448]
/lib/x86_64-linux-gnu/libc.so.6(+0x2e266)[0x7f5f9782a266]
/lib/x86_64-linux-gnu/libc.so.6(+0x2e312)[0x7f5f9782a312]
/usr/sbin/mysqld[0x908999]
/usr/sbin/mysqld(my_end+0x70)[0x906030]
/usr/sbin/mysqld[0x5a7ead]
/usr/sbin/mysqld(unireg_abort+0x16f)[0x5af14f]
/usr/sbin/mysqld(_Z18wsrep_sst_receivedP5wsrepRK10wsrep_uuidlPKvm+0x23d)[0x5c3e7d]
/usr/sbin/mysqld(_Z18wsrep_sst_continuev+0xaa)[0x5c3f3a]
/usr/sbin/mysqld(_Z11mysqld_mainiPPc+0x146f)[0x5b642f]
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf5)[0x7f5f9781db45]
/usr/sbin/mysqld[0x5a60bd]
You may download the Percona XtraDB Cluster operations manual by visiting
http://www.percona.com/software/percona-xtradb-cluster/. You may find information
in the manual which will help you identify the cause of the crash.
160808 13:05:22 mysqld_safe mysqld from pid file /var/run/mysql/mysql.pid ended

-------------------------------------------------------

2016-08-08 13:05:12 133363 [Warning] WSREP: SST postion is in the past: 256189451, current: 256189454. Can't continue.

Revision history for this message

Shahriyar Rzayev (rzayev-sehriyar) wrote on 2018-01-18:

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

Report a bug

This report contains Public information

Everyone can see this information.

You are

Subscribing...

Edit bug mail

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.