[MDEV-13950] mysqld_safe could not start Galera node after upgrade to 10.1.28 or 10.2.9 - Jira

Details

Type: Bug
Status: Closed (View Workflow)
Priority: Blocker
Resolution: Fixed
Affects Version/s: 10.1.28, 10.2.9
Fix Version/s: 10.1.29, 10.2.10
Component/s: Galera
Labels:
None
Environment:
CentOS 6.7

Sprint:
10.2.10

Description

Hi,
Today , We upgrade a node of three nodes galera from MariaDB 10.1.26 to 10.1.28 in test machines. after upgrade, start MariaDB server failed, but not error info in error log.

170929 11:10:25 mysqld_safe Starting mysqld daemon with databases from /data/gc/data

170929 11:10:25 mysqld_safe WSREP: Running position recovery with --disable-log-error  --pid-file='/data/gc/data/OG5300-FM

41-252-recover.pid'

2017-09-29 11:10:25 140515836905504 [Note] /usr/sbin/mysqld (mysqld 10.1.28-MariaDB) starting as process 13773 ...

2017-09-29 11:10:26 140515836905504 [Note] InnoDB: Using mutexes to ref count buffer pool pages

2017-09-29 11:10:26 140515836905504 [Note] InnoDB: The InnoDB memory heap is disabled

2017-09-29 11:10:26 140515836905504 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins

2017-09-29 11:10:26 140515836905504 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier

2017-09-29 11:10:26 140515836905504 [Note] InnoDB: Compressed tables use zlib 1.2.3

2017-09-29 11:10:26 140515836905504 [Note] InnoDB: Using Linux native AIO

2017-09-29 11:10:26 140515836905504 [Note] InnoDB: Using SSE crc32 instructions

2017-09-29 11:10:26 140515836905504 [Note] InnoDB: Initializing buffer pool, size = 8.0G

2017-09-29 11:10:26 140515836905504 [Note] InnoDB: Completed initialization of buffer pool

2017-09-29 11:10:26 140515836905504 [Note] InnoDB: Opened 4 undo tablespaces

2017-09-29 11:10:26 140515836905504 [Note] InnoDB: Highest supported file format is Barracuda.

2017-09-29 11:10:27 140515836905504 [Note] InnoDB: 128 rollback segment(s) are active.

2017-09-29 11:10:27 140515836905504 [Note] InnoDB:  Percona XtraDB (http://www.percona.com) 5.6.36-82.2 started; log seque

nce number 26100895442

2017-09-29 11:10:27 140515836905504 [Warning] InnoDB: Skipping buffer pool dump/restore during wsrep recovery.

2017-09-29 11:10:27 140515836905504 [Note] Plugin 'FEEDBACK' is disabled.

2017-09-29 11:10:27 140515836905504 [Warning] Failed to create a socket for IPv6 '::': errno: 97.

2017-09-29 11:10:27 140515836905504 [Note] Server socket created on IP: '0.0.0.0'.

2017-09-29 11:10:27 140515836905504 [Note] WSREP: Recovered position: d1b940ba-608d-11e7-a924-ba9a2478cac0:10282408

if set wsrep_on=off, MariaDB server could start normal.
if downgrade to 10.1.26, set wsrep=on , MariaDB server could start normal too.

On other 10.1.26 node, start MariaDB service info at below, it look different as 10.1.28 node.
Why it has only very seldom wsrep info in 10.1.28 error log? please help confirm , thanks.

170929 11:12:19 mysqld_safe Starting mysqld daemon with databases from /data/gc/data

170929 11:12:19 mysqld_safe WSREP: Running position recovery with --log_error='/data/gc/data/wsrep_recovery.bxCldj' --pid-

file='/data/gc/data/OG5309-FM41-253-recover.pid'

2017-09-29 11:12:19 140448920930336 [Note] /usr/sbin/mysqld (mysqld 10.1.26-MariaDB) starting as process 28057 ...

170929 11:12:31 mysqld_safe WSREP: Recovered position d1b940ba-608d-11e7-a924-ba9a2478cac0:10282408

2017-09-29 11:12:31 140472818767904 [Note] /usr/sbin/mysqld (mysqld 10.1.26-MariaDB) starting as process 28107 ...

2017-09-29 11:12:31 140472818767904 [Note] WSREP: Read nil XID from storage engines, skipping position init

2017-09-29 11:12:31 140472818767904 [Note] WSREP: wsrep_load(): loading provider library '/usr/lib64/galera/libgalera_smm.

so'

2017-09-29 11:12:31 140472818767904 [Note] WSREP: wsrep_load(): Galera 25.3.20(r3703) by Codership Oy <info@codership.com>

 loaded successfully.

2017-09-29 11:12:31 140472818767904 [Note] WSREP: CRC-32C: using hardware acceleration.

2017-09-29 11:12:31 140472818767904 [Note] WSREP: Found saved state: d1b940ba-608d-11e7-a924-ba9a2478cac0:10282408, safe_t

o_bootsrap: 0

2017-09-29 11:12:31 140472818767904 [Note] WSREP: Recovering GCache ring buffer: version: 1, UUID: d1b940ba-608d-11e7-a924

-ba9a2478cac0, offset: 1428487245

2017-09-29 11:12:31 140472818767904 [Note] WSREP: GCache::RingBuffer initial scan (2147483688 bytes)... 0.0% (0 bytes) com

plete.

2017-09-29 11:12:32 140472818767904 [Note] WSREP: GCache::RingBuffer initial scan (2147483688 bytes)... 100.0% (2147483688

 bytes) complete.

2017-09-29 11:12:32 140472818767904 [Note] WSREP: Recovering GCache ring buffer: found gapless sequence 9309448-10282408

2017-09-29 11:12:32 140472818767904 [Note] WSREP: GCache::RingBuffer unused buffers scan (2147481783 bytes)... 0.0% (0 byt

es) complete.

2017-09-29 11:12:32 140472818767904 [Note] WSREP: GCache::RingBuffer unused buffers scan (2147481783 bytes)... 100.0% (214

7481783 bytes) complete.

2017-09-29 11:12:32 140472818767904 [Note] WSREP: GCache DEBUG: RingBuffer::recover(): found 0/972961 locked buffers

2017-09-29 11:12:32 140472818767904 [Note] WSREP: GCache DEBUG: RingBuffer::recover(): used space: 2147481783/2147483648

[root@OG5309-FM41-253 11:13:06 log]# vi log.err

2017-09-27 11:57:05 140561910589184 [Note] WSREP: declaring 7478d999 at tcp://172.28.41.254:4567 stable

2017-09-27 11:57:05 140561910589184 [Note] WSREP: forgetting cf2f5d62 (tcp://172.28.41.252:4567)

2017-09-27 11:57:05 140561910589184 [Note] WSREP: Node 7478d999 state prim

2017-09-27 11:57:05 140561910589184 [Note] WSREP: view(view_id(PRIM,7478d999,26) memb {

        7478d999,0

        ca02a904,0

} joined {

} left {

} partitioned {

        cf2f5d62,0

})

2017-09-27 11:57:05 140561910589184 [Note] WSREP: save pc into disk

2017-09-27 11:57:05 140561910589184 [Note] WSREP: forgetting cf2f5d62 (tcp://172.28.41.252:4567)

2017-09-27 11:57:05 140561900099328 [Note] WSREP: New COMPONENT: primary = yes, bootstrap = no, my_idx = 1, memb_num = 2

2017-09-27 11:57:05 140561900099328 [Note] WSREP: STATE EXCHANGE: Waiting for state UUID.

2017-09-27 11:57:05 140561900099328 [Note] WSREP: STATE EXCHANGE: sent state msg: eceffe3e-a337-11e7-a36a-2f00347d9bdc

2017-09-27 11:57:05 140561900099328 [Note] WSREP: STATE EXCHANGE: got state msg: eceffe3e-a337-11e7-a36a-2f00347d9bdc from

 0 (node254)

2017-09-27 11:57:05 140561900099328 [Note] WSREP: STATE EXCHANGE: got state msg: eceffe3e-a337-11e7-a36a-2f00347d9bdc from

 1 (node253)

2017-09-27 11:57:05 140561900099328 [Note] WSREP: Quorum results:

        version    = 4,

        component  = PRIMARY,

        conf_id    = 25,

        members    = 2/2 (joined/total),

        act_id     = 10282408,

        last_appl. = 0,

        protocols  = 0/7/3 (gcs/repl/appl),

        group UUID = d1b940ba-608d-11e7-a924-ba9a2478cac0

2017-09-27 11:57:05 140561900099328 [Note] WSREP: Flow-control interval: [256, 256]

2017-09-27 11:57:05 140564255800064 [Note] WSREP: New cluster view: global state: d1b940ba-608d-11e7-a924-ba9a2478cac0:102

82408, view# 26: Primary, number of nodes: 2, my index: 1, protocol version 3

2017-09-27 11:57:05 140564255800064 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.

2017-09-27 11:57:05 140564255800064 [Note] WSREP: REPL Protocols: 7 (3, 2)

2017-09-27 11:57:05 140564255800064 [Note] WSREP: Assign initial position for certification: 10282408, protocol version: 3

2017-09-27 11:57:05 140561960924928 [Note] WSREP: Service thread queue flushed.

"log.err" 293L, 24946C

2017-09-29 11:12:47 140472818767904 [Note] WSREP: SST complete, seqno: 10282408

2017-09-29 11:12:47 140470464276224 [Note] WSREP: Member 0.0 (node253) synced with group.

2017-09-29 11:12:47 140470464276224 [Note] WSREP: Shifting JOINED -> SYNCED (TO: 10282408)

2017-09-29 11:12:47 140472818767904 [Note] InnoDB: Using mutexes to ref count buffer pool pages

2017-09-29 11:12:47 140472818767904 [Note] InnoDB: The InnoDB memory heap is disabled

2017-09-29 11:12:47 140472818767904 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins

2017-09-29 11:12:47 140472818767904 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier

2017-09-29 11:12:47 140472818767904 [Note] InnoDB: Compressed tables use zlib 1.2.3

2017-09-29 11:12:47 140472818767904 [Note] InnoDB: Using Linux native AIO

2017-09-29 11:12:47 140472818767904 [Note] InnoDB: Using SSE crc32 instructions

2017-09-29 11:12:47 140472818767904 [Note] InnoDB: Initializing buffer pool, size = 32.0G

2017-09-29 11:12:48 140472818767904 [Note] InnoDB: Completed initialization of buffer pool

2017-09-29 11:12:49 140472818767904 [Note] InnoDB: Opened 4 undo tablespaces

2017-09-29 11:12:49 140472818767904 [Note] InnoDB: Highest supported file format is Barracuda.

2017-09-29 11:12:50 140472818767904 [Note] InnoDB: 128 rollback segment(s) are active.

2017-09-29 11:12:50 140472818767904 [Note] InnoDB:  Percona XtraDB (http://www.percona.com) 5.6.36-82.1 started; log seque

nce number 26160484326

2017-09-29 11:12:50 140470474766080 [Note] WSREP: (1146e144, 'tcp://0.0.0.0:4567') connection to peer 1146e144 with addr t

cp://172.28.41.253:4567 timed out, no messages seen in PT3S

2017-09-29 11:12:50 140470474766080 [Note] WSREP: (1146e144, 'tcp://0.0.0.0:4567') turning message relay requesting off

2017-09-29 11:12:50 140472818767904 [Note] Plugin 'FEEDBACK' is disabled.

2017-09-29 11:12:50 140432369514240 [Note] InnoDB: Dumping buffer pool(s) not yet started

2017-09-29 11:12:50 7fb8f57ff700 InnoDB: Loading buffer pool(s) from /data/gc/data/ib_buffer_pool

2017-09-29 11:12:50 140472818767904 [Warning] Failed to create a socket for IPv6 '::': errno: 97.

2017-09-29 11:12:50 140472818767904 [Note] Server socket created on IP: '0.0.0.0'.

2017-09-29 11:12:50 140432232532736 [Note] Event Scheduler: scheduler thread started with id 4

2017-09-29 11:12:50 140472818767904 [Note] /usr/sbin/mysqld: ready for connections.

Version: '10.1.26-MariaDB'  socket: '/data/gc/data/mysql.sock'  port: 3309  MariaDB Server

2017-09-29 11:12:50 140470441208576 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.

2017-09-29 11:12:50 140470441208576 [Note] WSREP: REPL Protocols: 7 (3, 2)

2017-09-29 11:12:50 140470441208576 [Note] WSREP: Assign initial position for certification: 10282408, protocol version: 3

2017-09-29 11:12:50 140470525097728 [Note] WSREP: Service thread queue flushed.

2017-09-29 11:12:50 140470441208576 [Note] WSREP: Synchronized with group, ready for connections

2017-09-29 11:12:50 140470441208576 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.

2017-09-29 11:13:14 7fb8f57ff700 InnoDB: Buffer pool(s) load completed at 170929 11:13:14

Attachments

- Sort By Name
- Sort By Date
- Ascending
- Descending
- Thumbnails
- List
- Download All

jessie.log
69 kB
2017-09-29 10:27

Issue Links

is caused by

MDEV-10767 /tmp/wsrep_recovery.${RANDOM} file created in unallowed SELinux context

Closed

is duplicated by

MDEV-14061 SElinuix preventing MariaDB + Galera trying to create temporary file on /usr

Closed

MDEV-14063 mariadb102-server 10.2.9 cannot startup with galera

Closed

MDEV-14136 Cannot start a new galera cluster on systemd: Broken galera_recovery script

Closed

Activity

Ascending order - Click to sort in descending order

sysdljr created issue - 2017-09-29 03:39

sysdljr made changes - 2017-09-29 03:46

Field	Original Value	New Value
Description	Hi, Today , We upgrade a node of three nodes galera from MariaDB 10.1.26 to 10.1.28 in test machines. after upgrade, start MariaDB server failed, but not error info in error log. 170929 11:10:25 mysqld_safe Starting mysqld daemon with databases from /data/gc/data 170929 11:10:25 mysqld_safe WSREP: Running position recovery with --disable-log-error --pid-file='/data/gc/data/OG5300-FM 41-252-recover.pid' 2017-09-29 11:10:25 140515836905504 [Note] /usr/sbin/mysqld (mysqld 10.1.28-MariaDB) starting as process 13773 ... 2017-09-29 11:10:26 140515836905504 [Note] InnoDB: Using mutexes to ref count buffer pool pages 2017-09-29 11:10:26 140515836905504 [Note] InnoDB: The InnoDB memory heap is disabled 2017-09-29 11:10:26 140515836905504 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins 2017-09-29 11:10:26 140515836905504 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier 2017-09-29 11:10:26 140515836905504 [Note] InnoDB: Compressed tables use zlib 1.2.3 2017-09-29 11:10:26 140515836905504 [Note] InnoDB: Using Linux native AIO 2017-09-29 11:10:26 140515836905504 [Note] InnoDB: Using SSE crc32 instructions 2017-09-29 11:10:26 140515836905504 [Note] InnoDB: Initializing buffer pool, size = 8.0G 2017-09-29 11:10:26 140515836905504 [Note] InnoDB: Completed initialization of buffer pool 2017-09-29 11:10:26 140515836905504 [Note] InnoDB: Opened 4 undo tablespaces 2017-09-29 11:10:26 140515836905504 [Note] InnoDB: Highest supported file format is Barracuda. 2017-09-29 11:10:27 140515836905504 [Note] InnoDB: 128 rollback segment(s) are active. 2017-09-29 11:10:27 140515836905504 [Note] InnoDB: Percona XtraDB (http://www.percona.com) 5.6.36-82.2 started; log seque nce number 26100895442 2017-09-29 11:10:27 140515836905504 [Warning] InnoDB: Skipping buffer pool dump/restore during wsrep recovery. 2017-09-29 11:10:27 140515836905504 [Note] Plugin 'FEEDBACK' is disabled. 2017-09-29 11:10:27 140515836905504 [Warning] Failed to create a socket for IPv6 '::': errno: 97. 2017-09-29 11:10:27 140515836905504 [Note] Server socket created on IP: '0.0.0.0'. 2017-09-29 11:10:27 140515836905504 [Note] WSREP: Recovered position: d1b940ba-608d-11e7-a924-ba9a2478cac0:10282408 if set wsrep_on=off, MariaDB server could start normal. if downgrade to 10.1.26, set wsrep=on , MariaDB server could start normal too. On other 10.1.26 node, start MariaDB service info at below, it look different as 10.1.28 node. please help confirm , thanks. 170929 11:12:19 mysqld_safe Starting mysqld daemon with databases from /data/gc/data 170929 11:12:19 mysqld_safe WSREP: Running position recovery with --log_error='/data/gc/data/wsrep_recovery.bxCldj' --pid- file='/data/gc/data/OG5309-FM41-253-recover.pid' 2017-09-29 11:12:19 140448920930336 [Note] /usr/sbin/mysqld (mysqld 10.1.26-MariaDB) starting as process 28057 ... 170929 11:12:31 mysqld_safe WSREP: Recovered position d1b940ba-608d-11e7-a924-ba9a2478cac0:10282408 2017-09-29 11:12:31 140472818767904 [Note] /usr/sbin/mysqld (mysqld 10.1.26-MariaDB) starting as process 28107 ... 2017-09-29 11:12:31 140472818767904 [Note] WSREP: Read nil XID from storage engines, skipping position init 2017-09-29 11:12:31 140472818767904 [Note] WSREP: wsrep_load(): loading provider library '/usr/lib64/galera/libgalera_smm. so' 2017-09-29 11:12:31 140472818767904 [Note] WSREP: wsrep_load(): Galera 25.3.20(r3703) by Codership Oy <info@codership.com> loaded successfully. 2017-09-29 11:12:31 140472818767904 [Note] WSREP: CRC-32C: using hardware acceleration. 2017-09-29 11:12:31 140472818767904 [Note] WSREP: Found saved state: d1b940ba-608d-11e7-a924-ba9a2478cac0:10282408, safe_t o_bootsrap: 0 2017-09-29 11:12:31 140472818767904 [Note] WSREP: Recovering GCache ring buffer: version: 1, UUID: d1b940ba-608d-11e7-a924 -ba9a2478cac0, offset: 1428487245 2017-09-29 11:12:31 140472818767904 [Note] WSREP: GCache::RingBuffer initial scan (2147483688 bytes)... 0.0% (0 bytes) com plete. 2017-09-29 11:12:32 140472818767904 [Note] WSREP: GCache::RingBuffer initial scan (2147483688 bytes)... 100.0% (2147483688 bytes) complete. 2017-09-29 11:12:32 140472818767904 [Note] WSREP: Recovering GCache ring buffer: found gapless sequence 9309448-10282408 2017-09-29 11:12:32 140472818767904 [Note] WSREP: GCache::RingBuffer unused buffers scan (2147481783 bytes)... 0.0% (0 byt es) complete. 2017-09-29 11:12:32 140472818767904 [Note] WSREP: GCache::RingBuffer unused buffers scan (2147481783 bytes)... 100.0% (214 7481783 bytes) complete. 2017-09-29 11:12:32 140472818767904 [Note] WSREP: GCache DEBUG: RingBuffer::recover(): found 0/972961 locked buffers 2017-09-29 11:12:32 140472818767904 [Note] WSREP: GCache DEBUG: RingBuffer::recover(): used space: 2147481783/2147483648 [root@OG5309-FM41-253 11:13:06 log]# vi log.err 2017-09-27 11:57:05 140561910589184 [Note] WSREP: declaring 7478d999 at tcp://172.28.41.254:4567 stable 2017-09-27 11:57:05 140561910589184 [Note] WSREP: forgetting cf2f5d62 (tcp://172.28.41.252:4567) 2017-09-27 11:57:05 140561910589184 [Note] WSREP: Node 7478d999 state prim 2017-09-27 11:57:05 140561910589184 [Note] WSREP: view(view_id(PRIM,7478d999,26) memb { 7478d999,0 ca02a904,0 } joined { } left { } partitioned { cf2f5d62,0 }) 2017-09-27 11:57:05 140561910589184 [Note] WSREP: save pc into disk 2017-09-27 11:57:05 140561910589184 [Note] WSREP: forgetting cf2f5d62 (tcp://172.28.41.252:4567) 2017-09-27 11:57:05 140561900099328 [Note] WSREP: New COMPONENT: primary = yes, bootstrap = no, my_idx = 1, memb_num = 2 2017-09-27 11:57:05 140561900099328 [Note] WSREP: STATE EXCHANGE: Waiting for state UUID. 2017-09-27 11:57:05 140561900099328 [Note] WSREP: STATE EXCHANGE: sent state msg: eceffe3e-a337-11e7-a36a-2f00347d9bdc 2017-09-27 11:57:05 140561900099328 [Note] WSREP: STATE EXCHANGE: got state msg: eceffe3e-a337-11e7-a36a-2f00347d9bdc from 0 (node254) 2017-09-27 11:57:05 140561900099328 [Note] WSREP: STATE EXCHANGE: got state msg: eceffe3e-a337-11e7-a36a-2f00347d9bdc from 1 (node253) 2017-09-27 11:57:05 140561900099328 [Note] WSREP: Quorum results: version = 4, component = PRIMARY, conf_id = 25, members = 2/2 (joined/total), act_id = 10282408, last_appl. = 0, protocols = 0/7/3 (gcs/repl/appl), group UUID = d1b940ba-608d-11e7-a924-ba9a2478cac0 2017-09-27 11:57:05 140561900099328 [Note] WSREP: Flow-control interval: [256, 256] 2017-09-27 11:57:05 140564255800064 [Note] WSREP: New cluster view: global state: d1b940ba-608d-11e7-a924-ba9a2478cac0:102 82408, view# 26: Primary, number of nodes: 2, my index: 1, protocol version 3 2017-09-27 11:57:05 140564255800064 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification. 2017-09-27 11:57:05 140564255800064 [Note] WSREP: REPL Protocols: 7 (3, 2) 2017-09-27 11:57:05 140564255800064 [Note] WSREP: Assign initial position for certification: 10282408, protocol version: 3 2017-09-27 11:57:05 140561960924928 [Note] WSREP: Service thread queue flushed. "log.err" 293L, 24946C 2017-09-29 11:12:47 140472818767904 [Note] WSREP: SST complete, seqno: 10282408 2017-09-29 11:12:47 140470464276224 [Note] WSREP: Member 0.0 (node253) synced with group. 2017-09-29 11:12:47 140470464276224 [Note] WSREP: Shifting JOINED -> SYNCED (TO: 10282408) 2017-09-29 11:12:47 140472818767904 [Note] InnoDB: Using mutexes to ref count buffer pool pages 2017-09-29 11:12:47 140472818767904 [Note] InnoDB: The InnoDB memory heap is disabled 2017-09-29 11:12:47 140472818767904 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins 2017-09-29 11:12:47 140472818767904 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier 2017-09-29 11:12:47 140472818767904 [Note] InnoDB: Compressed tables use zlib 1.2.3 2017-09-29 11:12:47 140472818767904 [Note] InnoDB: Using Linux native AIO 2017-09-29 11:12:47 140472818767904 [Note] InnoDB: Using SSE crc32 instructions 2017-09-29 11:12:47 140472818767904 [Note] InnoDB: Initializing buffer pool, size = 32.0G 2017-09-29 11:12:48 140472818767904 [Note] InnoDB: Completed initialization of buffer pool 2017-09-29 11:12:49 140472818767904 [Note] InnoDB: Opened 4 undo tablespaces 2017-09-29 11:12:49 140472818767904 [Note] InnoDB: Highest supported file format is Barracuda. 2017-09-29 11:12:50 140472818767904 [Note] InnoDB: 128 rollback segment(s) are active. 2017-09-29 11:12:50 140472818767904 [Note] InnoDB: Percona XtraDB (http://www.percona.com) 5.6.36-82.1 started; log seque nce number 26160484326 2017-09-29 11:12:50 140470474766080 [Note] WSREP: (1146e144, 'tcp://0.0.0.0:4567') connection to peer 1146e144 with addr t cp://172.28.41.253:4567 timed out, no messages seen in PT3S 2017-09-29 11:12:50 140470474766080 [Note] WSREP: (1146e144, 'tcp://0.0.0.0:4567') turning message relay requesting off 2017-09-29 11:12:50 140472818767904 [Note] Plugin 'FEEDBACK' is disabled. 2017-09-29 11:12:50 140432369514240 [Note] InnoDB: Dumping buffer pool(s) not yet started 2017-09-29 11:12:50 7fb8f57ff700 InnoDB: Loading buffer pool(s) from /data/gc/data/ib_buffer_pool 2017-09-29 11:12:50 140472818767904 [Warning] Failed to create a socket for IPv6 '::': errno: 97. 2017-09-29 11:12:50 140472818767904 [Note] Server socket created on IP: '0.0.0.0'. 2017-09-29 11:12:50 140432232532736 [Note] Event Scheduler: scheduler thread started with id 4 2017-09-29 11:12:50 140472818767904 [Note] /usr/sbin/mysqld: ready for connections. Version: '10.1.26-MariaDB' socket: '/data/gc/data/mysql.sock' port: 3309 MariaDB Server 2017-09-29 11:12:50 140470441208576 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification. 2017-09-29 11:12:50 140470441208576 [Note] WSREP: REPL Protocols: 7 (3, 2) 2017-09-29 11:12:50 140470441208576 [Note] WSREP: Assign initial position for certification: 10282408, protocol version: 3 2017-09-29 11:12:50 140470525097728 [Note] WSREP: Service thread queue flushed. 2017-09-29 11:12:50 140470441208576 [Note] WSREP: Synchronized with group, ready for connections 2017-09-29 11:12:50 140470441208576 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification. 2017-09-29 11:13:14 7fb8f57ff700 InnoDB: Buffer pool(s) load completed at 170929 11:13:14	Hi, Today , We upgrade a node of three nodes galera from MariaDB 10.1.26 to 10.1.28 in test machines. after upgrade, start MariaDB server failed, but not error info in error log. 170929 11:10:25 mysqld_safe Starting mysqld daemon with databases from /data/gc/data 170929 11:10:25 mysqld_safe WSREP: Running position recovery with --disable-log-error --pid-file='/data/gc/data/OG5300-FM 41-252-recover.pid' 2017-09-29 11:10:25 140515836905504 [Note] /usr/sbin/mysqld (mysqld 10.1.28-MariaDB) starting as process 13773 ... 2017-09-29 11:10:26 140515836905504 [Note] InnoDB: Using mutexes to ref count buffer pool pages 2017-09-29 11:10:26 140515836905504 [Note] InnoDB: The InnoDB memory heap is disabled 2017-09-29 11:10:26 140515836905504 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins 2017-09-29 11:10:26 140515836905504 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier 2017-09-29 11:10:26 140515836905504 [Note] InnoDB: Compressed tables use zlib 1.2.3 2017-09-29 11:10:26 140515836905504 [Note] InnoDB: Using Linux native AIO 2017-09-29 11:10:26 140515836905504 [Note] InnoDB: Using SSE crc32 instructions 2017-09-29 11:10:26 140515836905504 [Note] InnoDB: Initializing buffer pool, size = 8.0G 2017-09-29 11:10:26 140515836905504 [Note] InnoDB: Completed initialization of buffer pool 2017-09-29 11:10:26 140515836905504 [Note] InnoDB: Opened 4 undo tablespaces 2017-09-29 11:10:26 140515836905504 [Note] InnoDB: Highest supported file format is Barracuda. 2017-09-29 11:10:27 140515836905504 [Note] InnoDB: 128 rollback segment(s) are active. 2017-09-29 11:10:27 140515836905504 [Note] InnoDB: Percona XtraDB (http://www.percona.com) 5.6.36-82.2 started; log seque nce number 26100895442 2017-09-29 11:10:27 140515836905504 [Warning] InnoDB: Skipping buffer pool dump/restore during wsrep recovery. 2017-09-29 11:10:27 140515836905504 [Note] Plugin 'FEEDBACK' is disabled. 2017-09-29 11:10:27 140515836905504 [Warning] Failed to create a socket for IPv6 '::': errno: 97. 2017-09-29 11:10:27 140515836905504 [Note] Server socket created on IP: '0.0.0.0'. 2017-09-29 11:10:27 140515836905504 [Note] WSREP: Recovered position: d1b940ba-608d-11e7-a924-ba9a2478cac0:10282408 if set wsrep_on=off, MariaDB server could start normal. if downgrade to 10.1.26, set wsrep=on , MariaDB server could start normal too. On other 10.1.26 node, start MariaDB service info at below, it look different as 10.1.28 node. Why it has only very seldom wsrep info in 10.1.28 error log? please help confirm , thanks. 170929 11:12:19 mysqld_safe Starting mysqld daemon with databases from /data/gc/data 170929 11:12:19 mysqld_safe WSREP: Running position recovery with --log_error='/data/gc/data/wsrep_recovery.bxCldj' --pid- file='/data/gc/data/OG5309-FM41-253-recover.pid' 2017-09-29 11:12:19 140448920930336 [Note] /usr/sbin/mysqld (mysqld 10.1.26-MariaDB) starting as process 28057 ... 170929 11:12:31 mysqld_safe WSREP: Recovered position d1b940ba-608d-11e7-a924-ba9a2478cac0:10282408 2017-09-29 11:12:31 140472818767904 [Note] /usr/sbin/mysqld (mysqld 10.1.26-MariaDB) starting as process 28107 ... 2017-09-29 11:12:31 140472818767904 [Note] WSREP: Read nil XID from storage engines, skipping position init 2017-09-29 11:12:31 140472818767904 [Note] WSREP: wsrep_load(): loading provider library '/usr/lib64/galera/libgalera_smm. so' 2017-09-29 11:12:31 140472818767904 [Note] WSREP: wsrep_load(): Galera 25.3.20(r3703) by Codership Oy <info@codership.com> loaded successfully. 2017-09-29 11:12:31 140472818767904 [Note] WSREP: CRC-32C: using hardware acceleration. 2017-09-29 11:12:31 140472818767904 [Note] WSREP: Found saved state: d1b940ba-608d-11e7-a924-ba9a2478cac0:10282408, safe_t o_bootsrap: 0 2017-09-29 11:12:31 140472818767904 [Note] WSREP: Recovering GCache ring buffer: version: 1, UUID: d1b940ba-608d-11e7-a924 -ba9a2478cac0, offset: 1428487245 2017-09-29 11:12:31 140472818767904 [Note] WSREP: GCache::RingBuffer initial scan (2147483688 bytes)... 0.0% (0 bytes) com plete. 2017-09-29 11:12:32 140472818767904 [Note] WSREP: GCache::RingBuffer initial scan (2147483688 bytes)... 100.0% (2147483688 bytes) complete. 2017-09-29 11:12:32 140472818767904 [Note] WSREP: Recovering GCache ring buffer: found gapless sequence 9309448-10282408 2017-09-29 11:12:32 140472818767904 [Note] WSREP: GCache::RingBuffer unused buffers scan (2147481783 bytes)... 0.0% (0 byt es) complete. 2017-09-29 11:12:32 140472818767904 [Note] WSREP: GCache::RingBuffer unused buffers scan (2147481783 bytes)... 100.0% (214 7481783 bytes) complete. 2017-09-29 11:12:32 140472818767904 [Note] WSREP: GCache DEBUG: RingBuffer::recover(): found 0/972961 locked buffers 2017-09-29 11:12:32 140472818767904 [Note] WSREP: GCache DEBUG: RingBuffer::recover(): used space: 2147481783/2147483648 [root@OG5309-FM41-253 11:13:06 log]# vi log.err 2017-09-27 11:57:05 140561910589184 [Note] WSREP: declaring 7478d999 at tcp://172.28.41.254:4567 stable 2017-09-27 11:57:05 140561910589184 [Note] WSREP: forgetting cf2f5d62 (tcp://172.28.41.252:4567) 2017-09-27 11:57:05 140561910589184 [Note] WSREP: Node 7478d999 state prim 2017-09-27 11:57:05 140561910589184 [Note] WSREP: view(view_id(PRIM,7478d999,26) memb { 7478d999,0 ca02a904,0 } joined { } left { } partitioned { cf2f5d62,0 }) 2017-09-27 11:57:05 140561910589184 [Note] WSREP: save pc into disk 2017-09-27 11:57:05 140561910589184 [Note] WSREP: forgetting cf2f5d62 (tcp://172.28.41.252:4567) 2017-09-27 11:57:05 140561900099328 [Note] WSREP: New COMPONENT: primary = yes, bootstrap = no, my_idx = 1, memb_num = 2 2017-09-27 11:57:05 140561900099328 [Note] WSREP: STATE EXCHANGE: Waiting for state UUID. 2017-09-27 11:57:05 140561900099328 [Note] WSREP: STATE EXCHANGE: sent state msg: eceffe3e-a337-11e7-a36a-2f00347d9bdc 2017-09-27 11:57:05 140561900099328 [Note] WSREP: STATE EXCHANGE: got state msg: eceffe3e-a337-11e7-a36a-2f00347d9bdc from 0 (node254) 2017-09-27 11:57:05 140561900099328 [Note] WSREP: STATE EXCHANGE: got state msg: eceffe3e-a337-11e7-a36a-2f00347d9bdc from 1 (node253) 2017-09-27 11:57:05 140561900099328 [Note] WSREP: Quorum results: version = 4, component = PRIMARY, conf_id = 25, members = 2/2 (joined/total), act_id = 10282408, last_appl. = 0, protocols = 0/7/3 (gcs/repl/appl), group UUID = d1b940ba-608d-11e7-a924-ba9a2478cac0 2017-09-27 11:57:05 140561900099328 [Note] WSREP: Flow-control interval: [256, 256] 2017-09-27 11:57:05 140564255800064 [Note] WSREP: New cluster view: global state: d1b940ba-608d-11e7-a924-ba9a2478cac0:102 82408, view# 26: Primary, number of nodes: 2, my index: 1, protocol version 3 2017-09-27 11:57:05 140564255800064 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification. 2017-09-27 11:57:05 140564255800064 [Note] WSREP: REPL Protocols: 7 (3, 2) 2017-09-27 11:57:05 140564255800064 [Note] WSREP: Assign initial position for certification: 10282408, protocol version: 3 2017-09-27 11:57:05 140561960924928 [Note] WSREP: Service thread queue flushed. "log.err" 293L, 24946C 2017-09-29 11:12:47 140472818767904 [Note] WSREP: SST complete, seqno: 10282408 2017-09-29 11:12:47 140470464276224 [Note] WSREP: Member 0.0 (node253) synced with group. 2017-09-29 11:12:47 140470464276224 [Note] WSREP: Shifting JOINED -> SYNCED (TO: 10282408) 2017-09-29 11:12:47 140472818767904 [Note] InnoDB: Using mutexes to ref count buffer pool pages 2017-09-29 11:12:47 140472818767904 [Note] InnoDB: The InnoDB memory heap is disabled 2017-09-29 11:12:47 140472818767904 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins 2017-09-29 11:12:47 140472818767904 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier 2017-09-29 11:12:47 140472818767904 [Note] InnoDB: Compressed tables use zlib 1.2.3 2017-09-29 11:12:47 140472818767904 [Note] InnoDB: Using Linux native AIO 2017-09-29 11:12:47 140472818767904 [Note] InnoDB: Using SSE crc32 instructions 2017-09-29 11:12:47 140472818767904 [Note] InnoDB: Initializing buffer pool, size = 32.0G 2017-09-29 11:12:48 140472818767904 [Note] InnoDB: Completed initialization of buffer pool 2017-09-29 11:12:49 140472818767904 [Note] InnoDB: Opened 4 undo tablespaces 2017-09-29 11:12:49 140472818767904 [Note] InnoDB: Highest supported file format is Barracuda. 2017-09-29 11:12:50 140472818767904 [Note] InnoDB: 128 rollback segment(s) are active. 2017-09-29 11:12:50 140472818767904 [Note] InnoDB: Percona XtraDB (http://www.percona.com) 5.6.36-82.1 started; log seque nce number 26160484326 2017-09-29 11:12:50 140470474766080 [Note] WSREP: (1146e144, 'tcp://0.0.0.0:4567') connection to peer 1146e144 with addr t cp://172.28.41.253:4567 timed out, no messages seen in PT3S 2017-09-29 11:12:50 140470474766080 [Note] WSREP: (1146e144, 'tcp://0.0.0.0:4567') turning message relay requesting off 2017-09-29 11:12:50 140472818767904 [Note] Plugin 'FEEDBACK' is disabled. 2017-09-29 11:12:50 140432369514240 [Note] InnoDB: Dumping buffer pool(s) not yet started 2017-09-29 11:12:50 7fb8f57ff700 InnoDB: Loading buffer pool(s) from /data/gc/data/ib_buffer_pool 2017-09-29 11:12:50 140472818767904 [Warning] Failed to create a socket for IPv6 '::': errno: 97. 2017-09-29 11:12:50 140472818767904 [Note] Server socket created on IP: '0.0.0.0'. 2017-09-29 11:12:50 140432232532736 [Note] Event Scheduler: scheduler thread started with id 4 2017-09-29 11:12:50 140472818767904 [Note] /usr/sbin/mysqld: ready for connections. Version: '10.1.26-MariaDB' socket: '/data/gc/data/mysql.sock' port: 3309 MariaDB Server 2017-09-29 11:12:50 140470441208576 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification. 2017-09-29 11:12:50 140470441208576 [Note] WSREP: REPL Protocols: 7 (3, 2) 2017-09-29 11:12:50 140470441208576 [Note] WSREP: Assign initial position for certification: 10282408, protocol version: 3 2017-09-29 11:12:50 140470525097728 [Note] WSREP: Service thread queue flushed. 2017-09-29 11:12:50 140470441208576 [Note] WSREP: Synchronized with group, ready for connections 2017-09-29 11:12:50 140470441208576 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification. 2017-09-29 11:13:14 7fb8f57ff700 InnoDB: Buffer pool(s) load completed at 170929 11:13:14

Sergei Golubchik made changes - 2017-09-29 06:04

Description

Hi,
      Today , We upgrade a node of three nodes galera from MariaDB 10.1.26 to 10.1.28 in test machines. after upgrade, start MariaDB server failed, but not error info in error log.
170929 11:10:25 mysqld_safe Starting mysqld daemon with databases from /data/gc/data
170929 11:10:25 mysqld_safe WSREP: Running position recovery with --disable-log-error --pid-file='/data/gc/data/OG5300-FM
41-252-recover.pid'
2017-09-29 11:10:25 140515836905504 [Note] /usr/sbin/mysqld (mysqld 10.1.28-MariaDB) starting as process 13773 ...
2017-09-29 11:10:26 140515836905504 [Note] InnoDB: Using mutexes to ref count buffer pool pages
2017-09-29 11:10:26 140515836905504 [Note] InnoDB: The InnoDB memory heap is disabled
2017-09-29 11:10:26 140515836905504 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2017-09-29 11:10:26 140515836905504 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
2017-09-29 11:10:26 140515836905504 [Note] InnoDB: Compressed tables use zlib 1.2.3
2017-09-29 11:10:26 140515836905504 [Note] InnoDB: Using Linux native AIO
2017-09-29 11:10:26 140515836905504 [Note] InnoDB: Using SSE crc32 instructions
2017-09-29 11:10:26 140515836905504 [Note] InnoDB: Initializing buffer pool, size = 8.0G
2017-09-29 11:10:26 140515836905504 [Note] InnoDB: Completed initialization of buffer pool
2017-09-29 11:10:26 140515836905504 [Note] InnoDB: Opened 4 undo tablespaces
2017-09-29 11:10:26 140515836905504 [Note] InnoDB: Highest supported file format is Barracuda.
2017-09-29 11:10:27 140515836905504 [Note] InnoDB: 128 rollback segment(s) are active.
2017-09-29 11:10:27 140515836905504 [Note] InnoDB: Percona XtraDB (http://www.percona.com) 5.6.36-82.2 started; log seque
nce number 26100895442
2017-09-29 11:10:27 140515836905504 [Warning] InnoDB: Skipping buffer pool dump/restore during wsrep recovery.
2017-09-29 11:10:27 140515836905504 [Note] Plugin 'FEEDBACK' is disabled.
2017-09-29 11:10:27 140515836905504 [Warning] Failed to create a socket for IPv6 '::': errno: 97.
2017-09-29 11:10:27 140515836905504 [Note] Server socket created on IP: '0.0.0.0'.
2017-09-29 11:10:27 140515836905504 [Note] WSREP: Recovered position: d1b940ba-608d-11e7-a924-ba9a2478cac0:10282408

if set wsrep_on=off, MariaDB server could start normal.
if downgrade to 10.1.26, set wsrep=on , MariaDB server could start normal too.

On other 10.1.26 node, start MariaDB service info at below, it look different as 10.1.28 node.
Why it has only very seldom wsrep info in 10.1.28 error log? please help confirm , thanks.
170929 11:12:19 mysqld_safe Starting mysqld daemon with databases from /data/gc/data
170929 11:12:19 mysqld_safe WSREP: Running position recovery with --log_error='/data/gc/data/wsrep_recovery.bxCldj' --pid-
file='/data/gc/data/OG5309-FM41-253-recover.pid'
2017-09-29 11:12:19 140448920930336 [Note] /usr/sbin/mysqld (mysqld 10.1.26-MariaDB) starting as process 28057 ...
170929 11:12:31 mysqld_safe WSREP: Recovered position d1b940ba-608d-11e7-a924-ba9a2478cac0:10282408
2017-09-29 11:12:31 140472818767904 [Note] /usr/sbin/mysqld (mysqld 10.1.26-MariaDB) starting as process 28107 ...
2017-09-29 11:12:31 140472818767904 [Note] WSREP: Read nil XID from storage engines, skipping position init
2017-09-29 11:12:31 140472818767904 [Note] WSREP: wsrep_load(): loading provider library '/usr/lib64/galera/libgalera_smm.
so'
2017-09-29 11:12:31 140472818767904 [Note] WSREP: wsrep_load(): Galera 25.3.20(r3703) by Codership Oy <info@codership.com>
loaded successfully.
2017-09-29 11:12:31 140472818767904 [Note] WSREP: CRC-32C: using hardware acceleration.
2017-09-29 11:12:31 140472818767904 [Note] WSREP: Found saved state: d1b940ba-608d-11e7-a924-ba9a2478cac0:10282408, safe_t
o_bootsrap: 0
2017-09-29 11:12:31 140472818767904 [Note] WSREP: Recovering GCache ring buffer: version: 1, UUID: d1b940ba-608d-11e7-a924
-ba9a2478cac0, offset: 1428487245
2017-09-29 11:12:31 140472818767904 [Note] WSREP: GCache::RingBuffer initial scan (2147483688 bytes)... 0.0% (0 bytes) com
plete.
2017-09-29 11:12:32 140472818767904 [Note] WSREP: GCache::RingBuffer initial scan (2147483688 bytes)... 100.0% (2147483688
bytes) complete.
2017-09-29 11:12:32 140472818767904 [Note] WSREP: Recovering GCache ring buffer: found gapless sequence 9309448-10282408
2017-09-29 11:12:32 140472818767904 [Note] WSREP: GCache::RingBuffer unused buffers scan (2147481783 bytes)... 0.0% (0 byt
es) complete.
2017-09-29 11:12:32 140472818767904 [Note] WSREP: GCache::RingBuffer unused buffers scan (2147481783 bytes)... 100.0% (214
7481783 bytes) complete.
2017-09-29 11:12:32 140472818767904 [Note] WSREP: GCache DEBUG: RingBuffer::recover(): found 0/972961 locked buffers
2017-09-29 11:12:32 140472818767904 [Note] WSREP: GCache DEBUG: RingBuffer::recover(): used space: 2147481783/2147483648
[root@OG5309-FM41-253 11:13:06 log]# vi log.err
2017-09-27 11:57:05 140561910589184 [Note] WSREP: declaring 7478d999 at tcp://172.28.41.254:4567 stable
2017-09-27 11:57:05 140561910589184 [Note] WSREP: forgetting cf2f5d62 (tcp://172.28.41.252:4567)
2017-09-27 11:57:05 140561910589184 [Note] WSREP: Node 7478d999 state prim
2017-09-27 11:57:05 140561910589184 [Note] WSREP: view(view_id(PRIM,7478d999,26) memb {
        7478d999,0
        ca02a904,0
} joined {
} left {
} partitioned {
        cf2f5d62,0
})
2017-09-27 11:57:05 140561910589184 [Note] WSREP: save pc into disk
2017-09-27 11:57:05 140561910589184 [Note] WSREP: forgetting cf2f5d62 (tcp://172.28.41.252:4567)
2017-09-27 11:57:05 140561900099328 [Note] WSREP: New COMPONENT: primary = yes, bootstrap = no, my_idx = 1, memb_num = 2
2017-09-27 11:57:05 140561900099328 [Note] WSREP: STATE EXCHANGE: Waiting for state UUID.
2017-09-27 11:57:05 140561900099328 [Note] WSREP: STATE EXCHANGE: sent state msg: eceffe3e-a337-11e7-a36a-2f00347d9bdc
2017-09-27 11:57:05 140561900099328 [Note] WSREP: STATE EXCHANGE: got state msg: eceffe3e-a337-11e7-a36a-2f00347d9bdc from
0 (node254)
2017-09-27 11:57:05 140561900099328 [Note] WSREP: STATE EXCHANGE: got state msg: eceffe3e-a337-11e7-a36a-2f00347d9bdc from
1 (node253)
2017-09-27 11:57:05 140561900099328 [Note] WSREP: Quorum results:
        version = 4,
        component = PRIMARY,
        conf_id = 25,
        members = 2/2 (joined/total),
        act_id = 10282408,
        last_appl. = 0,
        protocols = 0/7/3 (gcs/repl/appl),
        group UUID = d1b940ba-608d-11e7-a924-ba9a2478cac0
2017-09-27 11:57:05 140561900099328 [Note] WSREP: Flow-control interval: [256, 256]
2017-09-27 11:57:05 140564255800064 [Note] WSREP: New cluster view: global state: d1b940ba-608d-11e7-a924-ba9a2478cac0:102
82408, view# 26: Primary, number of nodes: 2, my index: 1, protocol version 3
2017-09-27 11:57:05 140564255800064 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2017-09-27 11:57:05 140564255800064 [Note] WSREP: REPL Protocols: 7 (3, 2)
2017-09-27 11:57:05 140564255800064 [Note] WSREP: Assign initial position for certification: 10282408, protocol version: 3
2017-09-27 11:57:05 140561960924928 [Note] WSREP: Service thread queue flushed.
"log.err" 293L, 24946C
2017-09-29 11:12:47 140472818767904 [Note] WSREP: SST complete, seqno: 10282408
2017-09-29 11:12:47 140470464276224 [Note] WSREP: Member 0.0 (node253) synced with group.
2017-09-29 11:12:47 140470464276224 [Note] WSREP: Shifting JOINED -> SYNCED (TO: 10282408)
2017-09-29 11:12:47 140472818767904 [Note] InnoDB: Using mutexes to ref count buffer pool pages
2017-09-29 11:12:47 140472818767904 [Note] InnoDB: The InnoDB memory heap is disabled
2017-09-29 11:12:47 140472818767904 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2017-09-29 11:12:47 140472818767904 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
2017-09-29 11:12:47 140472818767904 [Note] InnoDB: Compressed tables use zlib 1.2.3
2017-09-29 11:12:47 140472818767904 [Note] InnoDB: Using Linux native AIO
2017-09-29 11:12:47 140472818767904 [Note] InnoDB: Using SSE crc32 instructions
2017-09-29 11:12:47 140472818767904 [Note] InnoDB: Initializing buffer pool, size = 32.0G
2017-09-29 11:12:48 140472818767904 [Note] InnoDB: Completed initialization of buffer pool
2017-09-29 11:12:49 140472818767904 [Note] InnoDB: Opened 4 undo tablespaces
2017-09-29 11:12:49 140472818767904 [Note] InnoDB: Highest supported file format is Barracuda.
2017-09-29 11:12:50 140472818767904 [Note] InnoDB: 128 rollback segment(s) are active.
2017-09-29 11:12:50 140472818767904 [Note] InnoDB: Percona XtraDB (http://www.percona.com) 5.6.36-82.1 started; log seque
nce number 26160484326
2017-09-29 11:12:50 140470474766080 [Note] WSREP: (1146e144, 'tcp://0.0.0.0:4567') connection to peer 1146e144 with addr t
cp://172.28.41.253:4567 timed out, no messages seen in PT3S
2017-09-29 11:12:50 140470474766080 [Note] WSREP: (1146e144, 'tcp://0.0.0.0:4567') turning message relay requesting off
2017-09-29 11:12:50 140472818767904 [Note] Plugin 'FEEDBACK' is disabled.
2017-09-29 11:12:50 140432369514240 [Note] InnoDB: Dumping buffer pool(s) not yet started
2017-09-29 11:12:50 7fb8f57ff700 InnoDB: Loading buffer pool(s) from /data/gc/data/ib_buffer_pool
2017-09-29 11:12:50 140472818767904 [Warning] Failed to create a socket for IPv6 '::': errno: 97.
2017-09-29 11:12:50 140472818767904 [Note] Server socket created on IP: '0.0.0.0'.
2017-09-29 11:12:50 140432232532736 [Note] Event Scheduler: scheduler thread started with id 4
2017-09-29 11:12:50 140472818767904 [Note] /usr/sbin/mysqld: ready for connections.
Version: '10.1.26-MariaDB' socket: '/data/gc/data/mysql.sock' port: 3309 MariaDB Server
2017-09-29 11:12:50 140470441208576 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2017-09-29 11:12:50 140470441208576 [Note] WSREP: REPL Protocols: 7 (3, 2)
2017-09-29 11:12:50 140470441208576 [Note] WSREP: Assign initial position for certification: 10282408, protocol version: 3
2017-09-29 11:12:50 140470525097728 [Note] WSREP: Service thread queue flushed.
2017-09-29 11:12:50 140470441208576 [Note] WSREP: Synchronized with group, ready for connections
2017-09-29 11:12:50 140470441208576 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2017-09-29 11:13:14 7fb8f57ff700 InnoDB: Buffer pool(s) load completed at 170929 11:13:14

Hi,
      Today , We upgrade a node of three nodes galera from MariaDB 10.1.26 to 10.1.28 in test machines. after upgrade, start MariaDB server failed, but not error info in error log.
{noformat}
170929 11:10:25 mysqld_safe Starting mysqld daemon with databases from /data/gc/data
170929 11:10:25 mysqld_safe WSREP: Running position recovery with --disable-log-error --pid-file='/data/gc/data/OG5300-FM
41-252-recover.pid'
2017-09-29 11:10:25 140515836905504 [Note] /usr/sbin/mysqld (mysqld 10.1.28-MariaDB) starting as process 13773 ...
2017-09-29 11:10:26 140515836905504 [Note] InnoDB: Using mutexes to ref count buffer pool pages
2017-09-29 11:10:26 140515836905504 [Note] InnoDB: The InnoDB memory heap is disabled
2017-09-29 11:10:26 140515836905504 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2017-09-29 11:10:26 140515836905504 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
2017-09-29 11:10:26 140515836905504 [Note] InnoDB: Compressed tables use zlib 1.2.3
2017-09-29 11:10:26 140515836905504 [Note] InnoDB: Using Linux native AIO
2017-09-29 11:10:26 140515836905504 [Note] InnoDB: Using SSE crc32 instructions
2017-09-29 11:10:26 140515836905504 [Note] InnoDB: Initializing buffer pool, size = 8.0G
2017-09-29 11:10:26 140515836905504 [Note] InnoDB: Completed initialization of buffer pool
2017-09-29 11:10:26 140515836905504 [Note] InnoDB: Opened 4 undo tablespaces
2017-09-29 11:10:26 140515836905504 [Note] InnoDB: Highest supported file format is Barracuda.
2017-09-29 11:10:27 140515836905504 [Note] InnoDB: 128 rollback segment(s) are active.
2017-09-29 11:10:27 140515836905504 [Note] InnoDB: Percona XtraDB (http://www.percona.com) 5.6.36-82.2 started; log seque
nce number 26100895442
2017-09-29 11:10:27 140515836905504 [Warning] InnoDB: Skipping buffer pool dump/restore during wsrep recovery.
2017-09-29 11:10:27 140515836905504 [Note] Plugin 'FEEDBACK' is disabled.
2017-09-29 11:10:27 140515836905504 [Warning] Failed to create a socket for IPv6 '::': errno: 97.
2017-09-29 11:10:27 140515836905504 [Note] Server socket created on IP: '0.0.0.0'.
2017-09-29 11:10:27 140515836905504 [Note] WSREP: Recovered position: d1b940ba-608d-11e7-a924-ba9a2478cac0:10282408
{noformat}
if set wsrep_on=off, MariaDB server could start normal.
if downgrade to 10.1.26, set wsrep=on , MariaDB server could start normal too.

On other 10.1.26 node, start MariaDB service info at below, it look different as 10.1.28 node.
Why it has only very seldom wsrep info in 10.1.28 error log? please help confirm , thanks.
{noformat}
170929 11:12:19 mysqld_safe Starting mysqld daemon with databases from /data/gc/data
170929 11:12:19 mysqld_safe WSREP: Running position recovery with --log_error='/data/gc/data/wsrep_recovery.bxCldj' --pid-
file='/data/gc/data/OG5309-FM41-253-recover.pid'
2017-09-29 11:12:19 140448920930336 [Note] /usr/sbin/mysqld (mysqld 10.1.26-MariaDB) starting as process 28057 ...
170929 11:12:31 mysqld_safe WSREP: Recovered position d1b940ba-608d-11e7-a924-ba9a2478cac0:10282408
2017-09-29 11:12:31 140472818767904 [Note] /usr/sbin/mysqld (mysqld 10.1.26-MariaDB) starting as process 28107 ...
2017-09-29 11:12:31 140472818767904 [Note] WSREP: Read nil XID from storage engines, skipping position init
2017-09-29 11:12:31 140472818767904 [Note] WSREP: wsrep_load(): loading provider library '/usr/lib64/galera/libgalera_smm.
so'
2017-09-29 11:12:31 140472818767904 [Note] WSREP: wsrep_load(): Galera 25.3.20(r3703) by Codership Oy <info@codership.com>
loaded successfully.
2017-09-29 11:12:31 140472818767904 [Note] WSREP: CRC-32C: using hardware acceleration.
2017-09-29 11:12:31 140472818767904 [Note] WSREP: Found saved state: d1b940ba-608d-11e7-a924-ba9a2478cac0:10282408, safe_t
o_bootsrap: 0
2017-09-29 11:12:31 140472818767904 [Note] WSREP: Recovering GCache ring buffer: version: 1, UUID: d1b940ba-608d-11e7-a924
-ba9a2478cac0, offset: 1428487245
2017-09-29 11:12:31 140472818767904 [Note] WSREP: GCache::RingBuffer initial scan (2147483688 bytes)... 0.0% (0 bytes) com
plete.
2017-09-29 11:12:32 140472818767904 [Note] WSREP: GCache::RingBuffer initial scan (2147483688 bytes)... 100.0% (2147483688
bytes) complete.
2017-09-29 11:12:32 140472818767904 [Note] WSREP: Recovering GCache ring buffer: found gapless sequence 9309448-10282408
2017-09-29 11:12:32 140472818767904 [Note] WSREP: GCache::RingBuffer unused buffers scan (2147481783 bytes)... 0.0% (0 byt
es) complete.
2017-09-29 11:12:32 140472818767904 [Note] WSREP: GCache::RingBuffer unused buffers scan (2147481783 bytes)... 100.0% (214
7481783 bytes) complete.
2017-09-29 11:12:32 140472818767904 [Note] WSREP: GCache DEBUG: RingBuffer::recover(): found 0/972961 locked buffers
2017-09-29 11:12:32 140472818767904 [Note] WSREP: GCache DEBUG: RingBuffer::recover(): used space: 2147481783/2147483648
[root@OG5309-FM41-253 11:13:06 log]# vi log.err
2017-09-27 11:57:05 140561910589184 [Note] WSREP: declaring 7478d999 at tcp://172.28.41.254:4567 stable
2017-09-27 11:57:05 140561910589184 [Note] WSREP: forgetting cf2f5d62 (tcp://172.28.41.252:4567)
2017-09-27 11:57:05 140561910589184 [Note] WSREP: Node 7478d999 state prim
2017-09-27 11:57:05 140561910589184 [Note] WSREP: view(view_id(PRIM,7478d999,26) memb {
        7478d999,0
        ca02a904,0
} joined {
} left {
} partitioned {
        cf2f5d62,0
})
2017-09-27 11:57:05 140561910589184 [Note] WSREP: save pc into disk
2017-09-27 11:57:05 140561910589184 [Note] WSREP: forgetting cf2f5d62 (tcp://172.28.41.252:4567)
2017-09-27 11:57:05 140561900099328 [Note] WSREP: New COMPONENT: primary = yes, bootstrap = no, my_idx = 1, memb_num = 2
2017-09-27 11:57:05 140561900099328 [Note] WSREP: STATE EXCHANGE: Waiting for state UUID.
2017-09-27 11:57:05 140561900099328 [Note] WSREP: STATE EXCHANGE: sent state msg: eceffe3e-a337-11e7-a36a-2f00347d9bdc
2017-09-27 11:57:05 140561900099328 [Note] WSREP: STATE EXCHANGE: got state msg: eceffe3e-a337-11e7-a36a-2f00347d9bdc from
0 (node254)
2017-09-27 11:57:05 140561900099328 [Note] WSREP: STATE EXCHANGE: got state msg: eceffe3e-a337-11e7-a36a-2f00347d9bdc from
1 (node253)
2017-09-27 11:57:05 140561900099328 [Note] WSREP: Quorum results:
        version = 4,
        component = PRIMARY,
        conf_id = 25,
        members = 2/2 (joined/total),
        act_id = 10282408,
        last_appl. = 0,
        protocols = 0/7/3 (gcs/repl/appl),
        group UUID = d1b940ba-608d-11e7-a924-ba9a2478cac0
2017-09-27 11:57:05 140561900099328 [Note] WSREP: Flow-control interval: [256, 256]
2017-09-27 11:57:05 140564255800064 [Note] WSREP: New cluster view: global state: d1b940ba-608d-11e7-a924-ba9a2478cac0:102
82408, view# 26: Primary, number of nodes: 2, my index: 1, protocol version 3
2017-09-27 11:57:05 140564255800064 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2017-09-27 11:57:05 140564255800064 [Note] WSREP: REPL Protocols: 7 (3, 2)
2017-09-27 11:57:05 140564255800064 [Note] WSREP: Assign initial position for certification: 10282408, protocol version: 3
2017-09-27 11:57:05 140561960924928 [Note] WSREP: Service thread queue flushed.
"log.err" 293L, 24946C
2017-09-29 11:12:47 140472818767904 [Note] WSREP: SST complete, seqno: 10282408
2017-09-29 11:12:47 140470464276224 [Note] WSREP: Member 0.0 (node253) synced with group.
2017-09-29 11:12:47 140470464276224 [Note] WSREP: Shifting JOINED -> SYNCED (TO: 10282408)
2017-09-29 11:12:47 140472818767904 [Note] InnoDB: Using mutexes to ref count buffer pool pages
2017-09-29 11:12:47 140472818767904 [Note] InnoDB: The InnoDB memory heap is disabled
2017-09-29 11:12:47 140472818767904 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2017-09-29 11:12:47 140472818767904 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
2017-09-29 11:12:47 140472818767904 [Note] InnoDB: Compressed tables use zlib 1.2.3
2017-09-29 11:12:47 140472818767904 [Note] InnoDB: Using Linux native AIO
2017-09-29 11:12:47 140472818767904 [Note] InnoDB: Using SSE crc32 instructions
2017-09-29 11:12:47 140472818767904 [Note] InnoDB: Initializing buffer pool, size = 32.0G
2017-09-29 11:12:48 140472818767904 [Note] InnoDB: Completed initialization of buffer pool
2017-09-29 11:12:49 140472818767904 [Note] InnoDB: Opened 4 undo tablespaces
2017-09-29 11:12:49 140472818767904 [Note] InnoDB: Highest supported file format is Barracuda.
2017-09-29 11:12:50 140472818767904 [Note] InnoDB: 128 rollback segment(s) are active.
2017-09-29 11:12:50 140472818767904 [Note] InnoDB: Percona XtraDB (http://www.percona.com) 5.6.36-82.1 started; log seque
nce number 26160484326
2017-09-29 11:12:50 140470474766080 [Note] WSREP: (1146e144, 'tcp://0.0.0.0:4567') connection to peer 1146e144 with addr t
cp://172.28.41.253:4567 timed out, no messages seen in PT3S
2017-09-29 11:12:50 140470474766080 [Note] WSREP: (1146e144, 'tcp://0.0.0.0:4567') turning message relay requesting off
2017-09-29 11:12:50 140472818767904 [Note] Plugin 'FEEDBACK' is disabled.
2017-09-29 11:12:50 140432369514240 [Note] InnoDB: Dumping buffer pool(s) not yet started
2017-09-29 11:12:50 7fb8f57ff700 InnoDB: Loading buffer pool(s) from /data/gc/data/ib_buffer_pool
2017-09-29 11:12:50 140472818767904 [Warning] Failed to create a socket for IPv6 '::': errno: 97.
2017-09-29 11:12:50 140472818767904 [Note] Server socket created on IP: '0.0.0.0'.
2017-09-29 11:12:50 140432232532736 [Note] Event Scheduler: scheduler thread started with id 4
2017-09-29 11:12:50 140472818767904 [Note] /usr/sbin/mysqld: ready for connections.
Version: '10.1.26-MariaDB' socket: '/data/gc/data/mysql.sock' port: 3309 MariaDB Server
2017-09-29 11:12:50 140470441208576 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2017-09-29 11:12:50 140470441208576 [Note] WSREP: REPL Protocols: 7 (3, 2)
2017-09-29 11:12:50 140470441208576 [Note] WSREP: Assign initial position for certification: 10282408, protocol version: 3
2017-09-29 11:12:50 140470525097728 [Note] WSREP: Service thread queue flushed.
2017-09-29 11:12:50 140470441208576 [Note] WSREP: Synchronized with group, ready for connections
2017-09-29 11:12:50 140470441208576 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
2017-09-29 11:13:14 7fb8f57ff700 InnoDB: Buffer pool(s) load completed at 170929 11:13:14
{noformat}

Sachin Setiya (Inactive) made changes - 2017-09-29 07:34

Assignee

Sachin Setiya [ sachin.setiya.007 ]

Sachin Setiya (Inactive) made changes - 2017-09-29 07:44

Link

This issue is caused by ~~MDEV-10767~~ [ ~~MDEV-10767~~ ]

Sachin Setiya (Inactive) made changes - 2017-09-29 08:09

Comment

[ This is caused by fix of 10767. I forgot to add /tmp in front of wsrep.recovery.XXXXX in mysqld_safe ]

Andrii Nikitin (Inactive) made changes - 2017-09-29 10:27

Attachment

jessie.log [ 44267 ]

Andrii Nikitin (Inactive) made changes - 2017-09-29 14:27

Status

Open [ 1 ]

Confirmed [ 10101 ]

Andrii Nikitin (Inactive) made changes - 2017-09-29 19:13

Priority

Major [ 3 ]

Blocker [ 1 ]

Andrii Nikitin (Inactive) made changes - 2017-10-01 05:28

Affects Version/s

10.2.9 [ 22611 ]

Andrii Nikitin (Inactive) made changes - 2017-10-01 05:29

Fix Version/s		10.1 [ 16100 ]
Fix Version/s		10.2 [ 14601 ]

Andrii Nikitin (Inactive) made changes - 2017-10-01 05:29

Summary

MariaDB Galera could not start after upgrade to 10.1.28?

mysqld_safe could not start Galera node after upgrade to 10.1.28 or 10.2.9

Sergei Golubchik made changes - 2017-10-04 10:39

Fix Version/s		10.1.29 [ 22636 ]
Fix Version/s		10.2.10 [ 22615 ]
Fix Version/s	10.2 [ 14601 ]
Fix Version/s	10.1 [ 16100 ]

Sergei Golubchik made changes - 2017-10-04 10:39

Resolution		Fixed [ 1 ]
Status	Confirmed [ 10101 ]	Closed [ 6 ]

Sergei Golubchik made changes - 2017-10-04 14:39

Sprint

10.2.10 [ 183 ]

Andrii Nikitin (Inactive) made changes - 2017-10-13 13:43

Link

This issue is duplicated by ~~MDEV-14061~~ [ ~~MDEV-14061~~ ]

Andrii Nikitin (Inactive) made changes - 2017-10-28 00:20

Link

This issue is duplicated by ~~MDEV-14136~~ [ ~~MDEV-14136~~ ]

Andrii Nikitin (Inactive) made changes - 2017-10-31 11:34

Link

This issue is duplicated by ~~MDEV-14063~~ [ ~~MDEV-14063~~ ]

Otto Kekäläinen made changes - 2017-11-21 11:22

Summary

mysqld_safe could not start Galera node after upgrade to 10.1.28 or 10.2.9

mysqld_safe could not start Galera node after upgrade to 10.1.28 or 10.1.29

Otto Kekäläinen made changes - 2017-11-21 11:23

Summary

mysqld_safe could not start Galera node after upgrade to 10.1.28 or 10.1.29

mysqld_safe could not start Galera node after upgrade to 10.1.28 or 10.2.9

Sergei Golubchik made changes - 2021-12-06 21:45

Workflow

MariaDB v3 [ 82848 ]

MariaDB v4 [ 152916 ]

Jira Automation (IT) made changes - 2024-07-04 08:10

Zendesk Related Tickets

198739

People

Assignee:: Sachin Setiya (Inactive)

Reporter:: sysdljr

Votes:: 4 Vote for this issue

Watchers:: 14 Start watching this issue

Dates

Created:: 2017-09-29 03:39

Updated:: 2024-07-08 00:37

Resolved:: 2017-10-04 10:39

Git Integration

Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.