Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-13950

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

    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

        1. jessie.log
          69 kB
          Andrii Nikitin

          Issue Links

            Activity

              People

              • Assignee:
                sachin.setiya.007 Sachin Setiya
                Reporter:
                sysdljr sysdljr
              • Votes:
                4 Vote for this issue
                Watchers:
                14 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved: