MySQL Forums
Forum List  »  NDB clusters

[NDB Cluster 7.4.15] ndb cluster doesn't restart after initial {Last completed phase 3}
Posted by: Sergey Ivankov
Date: May 23, 2017 11:10AM

[ndbd(NDB)] 4 node(s)
id=3 @10.0.240.94 (mysql-5.6.36 ndb-7.4.15, starting, Nodegroup: 0, *)
id=4 @10.0.241.94 (mysql-5.6.36 ndb-7.4.15, starting, Nodegroup: 0)
id=5 @10.0.240.95 (mysql-5.6.36 ndb-7.4.15, starting, Nodegroup: 0)
id=6 @10.0.241.95 (mysql-5.6.36 ndb-7.4.15, starting, Nodegroup: 0)

[ndb_mgmd(MGM)] 2 node(s)
id=1 @10.0.240.241 (mysql-5.6.36 ndb-7.4.15)
id=2 @10.0.241.241 (mysql-5.6.36 ndb-7.4.15)

ndb_mgm -e "all status"
Connected to Management Server at: localhost:1186
Node 3: starting (Last completed phase 3) (mysql-5.6.36 ndb-7.4.15)
Node 4: starting (Last completed phase 3) (mysql-5.6.36 ndb-7.4.15)
Node 5: starting (Last completed phase 3) (mysql-5.6.36 ndb-7.4.15)
Node 6: starting (Last completed phase 3) (mysql-5.6.36 ndb-7.4.15)


The DATA-Nodes X_out.log contain some records:
2017-05-23 19:09:23 [ndbd] INFO -- Restart recreating table with id = 1
2017-05-23 19:09:23 [ndbd] INFO -- Restart recreating table with id = 2
2017-05-23 19:09:23 [ndbd] INFO -- Restart recreating table with id = 3
2017-05-23 19:09:23 [ndbd] INFO -- LDM(6):Ready to start execute REDO log phase, prepare REDO log phase completed
2017-05-23 19:09:23 [ndbd] INFO -- LDM(3):Ready to start execute REDO log phase, prepare REDO log phase completed
2017-05-23 19:09:23 [ndbd] INFO -- LDM(5):Ready to start execute REDO log phase, prepare REDO log phase completed
2017-05-23 19:09:23 [ndbd] INFO -- LDM(9):Ready to start execute REDO log phase, prepare REDO log phase completed
2017-05-23 19:09:23 [ndbd] INFO -- LDM(4):Ready to start execute REDO log phase, prepare REDO log phase completed
2017-05-23 19:09:23 [ndbd] INFO -- LDM(8):Ready to start execute REDO log phase, prepare REDO log phase completed
2017-05-23 19:09:23 [ndbd] INFO -- LDM(10):Ready to start execute REDO log phase, prepare REDO log phase completed
2017-05-23 19:09:24 [ndbd] INFO -- LDM(7):Ready to start execute REDO log phase, prepare REDO log phase completed
2017-05-23 19:09:24 [ndbd] INFO -- LDM(2):Ready to start execute REDO log phase, prepare REDO log phase completed
2017-05-23 19:09:24 [ndbd] INFO -- LDM(11):Ready to start execute REDO log phase, prepare REDO log phase completed
2017-05-23 19:09:24 [ndbd] INFO -- LDM(1):Ready to start execute REDO log phase, prepare REDO log phase completed
2017-05-23 19:09:24 [ndbd] INFO -- LDM(12):Ready to start execute REDO log phase, prepare REDO log phase completed

2017-05-23 19:32:33 [ndbd] WARNING -- Ndb kernel thread 7 is stuck in: Job Handling elapsed=100
2017-05-23 19:32:33 [ndbd] INFO -- Watchdog: User time: 2146 System time: 5980
2017-05-23 19:32:33 [ndbd] WARNING -- Ndb kernel thread 9 is stuck in: Job Handling elapsed=100
2017-05-23 19:32:33 [ndbd] INFO -- Watchdog: User time: 2146 System time: 5980
2017-05-23 19:32:33 [ndbd] WARNING -- Ndb kernel thread 22 is stuck in: Job Handling elapsed=100
2017-05-23 19:32:33 [ndbd] INFO -- Watchdog: User time: 2150 System time: 5992
2017-05-23 19:32:34 [ndbd] WARNING -- Ndb kernel thread 6 is stuck in: Job Handling elapsed=100
2017-05-23 19:32:34 [ndbd] INFO -- Watchdog: User time: 2156 System time: 6007
2017-05-23 19:34:00 [ndbd] WARNING -- Ndb kernel thread 13 is stuck in: Job Handling elapsed=100
2017-05-23 19:34:00 [ndbd] INFO -- Watchdog: User time: 2235 System time: 6140
2017-05-23 19:34:00 [ndbd] WARNING -- Ndb kernel thread 15 is stuck in: Job Handling elapsed=100
2017-05-23 19:34:00 [ndbd] INFO -- Watchdog: User time: 2235 System time: 6140



The cluster.log
2017-05-23 19:06:40 [MgmtSrvr] INFO -- Stopping this node
2017-05-23 19:06:41 [MgmtSrvr] INFO -- Shutting down server...
2017-05-23 19:06:46 [MgmtSrvr] INFO -- Shutdown complete
2017-05-23 19:06:59 [MgmtSrvr] INFO -- Loaded config from '/etc//ndb_2_config.bin.1'
2017-05-23 19:06:59 [MgmtSrvr] INFO -- Id: 2, Command port: *:1186
2017-05-23 19:06:59 [MgmtSrvr] INFO -- Node 2: Node 2 Connected
2017-05-23 19:06:59 [MgmtSrvr] INFO -- MySQL Cluster Management Server mysql-5.6.36 ndb-7.4.15 started
2017-05-23 19:06:59 [MgmtSrvr] INFO -- Node 2: Node 1 Connected
2017-05-23 19:06:59 [MgmtSrvr] INFO -- Node 2 connected
2017-05-23 19:06:59 [MgmtSrvr] INFO -- Node 1 connected
2017-05-23 19:07:30 [MgmtSrvr] INFO -- Node 2: Node 3 Connected
2017-05-23 19:07:33 [MgmtSrvr] INFO -- Node 2: Node 4 Connected
2017-05-23 19:07:38 [MgmtSrvr] INFO -- Node 2: Node 5 Connected
2017-05-23 19:07:41 [MgmtSrvr] INFO -- Node 2: Node 6 Connected
2017-05-23 19:09:04 [MgmtSrvr] INFO -- Node 3: Start initiated (mysql-5.6.36 ndb-7.4.15)
2017-05-23 19:09:04 [MgmtSrvr] INFO -- Node 4: Start initiated (mysql-5.6.36 ndb-7.4.15)
2017-05-23 19:09:04 [MgmtSrvr] INFO -- Node 5: Start initiated (mysql-5.6.36 ndb-7.4.15)
2017-05-23 19:09:04 [MgmtSrvr] INFO -- Node 6: Start initiated (mysql-5.6.36 ndb-7.4.15)
2017-05-23 19:09:19 [MgmtSrvr] INFO -- Node 5: Buffering maximum epochs 90
2017-05-23 19:09:19 [MgmtSrvr] INFO -- Node 3: Buffering maximum epochs 90
2017-05-23 19:09:19 [MgmtSrvr] INFO -- Node 5: Start phase 0 completed
2017-05-23 19:09:19 [MgmtSrvr] INFO -- Node 3: Start phase 0 completed
2017-05-23 19:09:19 [MgmtSrvr] INFO -- Node 5: Waiting 30 sec for nodes 3, 4 and 6 to connect, nodes [ all: 3, 4, 5 and 6 connected: 5 no-wait: ]
2017-05-23 19:09:19 [MgmtSrvr] INFO -- Node 5: Communication to Node 6 opened
2017-05-23 19:09:19 [MgmtSrvr] INFO -- Node 5: Communication to Node 3 opened
2017-05-23 19:09:19 [MgmtSrvr] INFO -- Node 5: Communication to Node 4 opened
2017-05-23 19:09:19 [MgmtSrvr] INFO -- Node 6: Buffering maximum epochs 90
2017-05-23 19:09:19 [MgmtSrvr] INFO -- Node 3: Waiting 30 sec for nodes 4, 5 and 6 to connect, nodes [ all: 3, 4, 5 and 6 connected: 3 no-wait: ]
2017-05-23 19:09:19 [MgmtSrvr] INFO -- Node 3: Communication to Node 6 opened
2017-05-23 19:09:19 [MgmtSrvr] INFO -- Node 3: Communication to Node 5 opened
2017-05-23 19:09:19 [MgmtSrvr] INFO -- Node 3: Communication to Node 4 opened
2017-05-23 19:09:19 [MgmtSrvr] INFO -- Node 4: Buffering maximum epochs 90
2017-05-23 19:09:20 [MgmtSrvr] INFO -- Node 6: Start phase 0 completed
2017-05-23 19:09:20 [MgmtSrvr] INFO -- Node 3: Node 5 Connected
2017-05-23 19:09:20 [MgmtSrvr] INFO -- Node 4: Start phase 0 completed
2017-05-23 19:09:20 [MgmtSrvr] INFO -- Node 3: Waiting 30 sec for nodes 4 and 6 to connect, nodes [ all: 3, 4, 5 and 6 connected: 3 and 5 no-wait: ]
2017-05-23 19:09:20 [MgmtSrvr] INFO -- Node 5: Node 3 Connected
2017-05-23 19:09:20 [MgmtSrvr] INFO -- Node 6: Waiting 30 sec for nodes 3, 4 and 5 to connect, nodes [ all: 3, 4, 5 and 6 connected: 6 no-wait: ]
2017-05-23 19:09:20 [MgmtSrvr] INFO -- Node 6: Communication to Node 5 opened
2017-05-23 19:09:20 [MgmtSrvr] INFO -- Node 6: Communication to Node 3 opened
2017-05-23 19:09:20 [MgmtSrvr] INFO -- Node 6: Communication to Node 4 opened
2017-05-23 19:09:20 [MgmtSrvr] INFO -- Node 3: Node 6 Connected
2017-05-23 19:09:20 [MgmtSrvr] INFO -- Node 6: Node 5 Connected
2017-05-23 19:09:20 [MgmtSrvr] INFO -- Node 5: Node 6 Connected
2017-05-23 19:09:20 [MgmtSrvr] INFO -- Node 6: Node 3 Connected
2017-05-23 19:09:20 [MgmtSrvr] INFO -- Node 3: Waiting 30 sec for nodes 4 to connect, nodes [ all: 3, 4, 5 and 6 connected: 3, 5 and 6 no-wait: ]
2017-05-23 19:09:20 [MgmtSrvr] INFO -- Node 4: Waiting 30 sec for nodes 3, 5 and 6 to connect, nodes [ all: 3, 4, 5 and 6 connected: 4 no-wait: ]
2017-05-23 19:09:20 [MgmtSrvr] INFO -- Node 4: Communication to Node 3 opened
2017-05-23 19:09:20 [MgmtSrvr] INFO -- Node 4: Communication to Node 5 opened
2017-05-23 19:09:20 [MgmtSrvr] INFO -- Node 4: Communication to Node 6 opened
2017-05-23 19:09:20 [MgmtSrvr] INFO -- Node 3: Node 4 Connected
2017-05-23 19:09:20 [MgmtSrvr] INFO -- Node 4: Node 3 Connected
2017-05-23 19:09:20 [MgmtSrvr] INFO -- Node 3: Start with all nodes 3, 4, 5 and 6
2017-05-23 19:09:20 [MgmtSrvr] INFO -- Node 3: CM_REGCONF president = 3, own Node = 3, our dynamic id = 0/1
2017-05-23 19:09:20 [MgmtSrvr] INFO -- Node 4: Node 5 Connected
2017-05-23 19:09:20 [MgmtSrvr] INFO -- Node 5: Node 4 Connected
2017-05-23 19:09:20 [MgmtSrvr] INFO -- Node 6: Node 4 Connected
2017-05-23 19:09:20 [MgmtSrvr] INFO -- Node 4: Node 6 Connected
2017-05-23 19:09:22 [MgmtSrvr] INFO -- Node 5: CM_REGCONF president = 3, own Node = 5, our dynamic id = 0/2
2017-05-23 19:09:22 [MgmtSrvr] INFO -- Node 3: Node 5: API mysql-5.6.36 ndb-7.4.15
2017-05-23 19:09:22 [MgmtSrvr] INFO -- Node 5: Node 3: API mysql-5.6.36 ndb-7.4.15
2017-05-23 19:09:22 [MgmtSrvr] INFO -- Node 5: Start phase 1 completed
2017-05-23 19:09:23 [MgmtSrvr] INFO -- Node 6: CM_REGCONF president = 3, own Node = 6, our dynamic id = 0/3
2017-05-23 19:09:23 [MgmtSrvr] INFO -- Node 5: Node 6: API mysql-5.6.36 ndb-7.4.15
2017-05-23 19:09:23 [MgmtSrvr] INFO -- Node 3: Node 6: API mysql-5.6.36 ndb-7.4.15
2017-05-23 19:09:23 [MgmtSrvr] INFO -- Node 6: Node 5: API mysql-5.6.36 ndb-7.4.15
2017-05-23 19:09:23 [MgmtSrvr] INFO -- Node 6: Node 3: API mysql-5.6.36 ndb-7.4.15
2017-05-23 19:09:23 [MgmtSrvr] INFO -- Node 6: Start phase 1 completed
2017-05-23 19:09:23 [MgmtSrvr] INFO -- Node 4: CM_REGCONF president = 3, own Node = 4, our dynamic id = 0/4
2017-05-23 19:09:23 [MgmtSrvr] INFO -- Node 5: Node 4: API mysql-5.6.36 ndb-7.4.15
2017-05-23 19:09:23 [MgmtSrvr] INFO -- Node 6: Node 4: API mysql-5.6.36 ndb-7.4.15
2017-05-23 19:09:23 [MgmtSrvr] INFO -- Node 3: Node 4: API mysql-5.6.36 ndb-7.4.15
2017-05-23 19:09:23 [MgmtSrvr] INFO -- Node 4: Node 6: API mysql-5.6.36 ndb-7.4.15
2017-05-23 19:09:23 [MgmtSrvr] INFO -- Node 4: Node 5: API mysql-5.6.36 ndb-7.4.15
2017-05-23 19:09:23 [MgmtSrvr] INFO -- Node 4: Node 3: API mysql-5.6.36 ndb-7.4.15
2017-05-23 19:09:23 [MgmtSrvr] INFO -- Node 4: Start phase 1 completed
2017-05-23 19:09:23 [MgmtSrvr] INFO -- Node 3: Start phase 1 completed
2017-05-23 19:09:23 [MgmtSrvr] INFO -- Node 3: System Restart: master node: 4, num starting: 3, gci: 70
2017-05-23 19:09:23 [MgmtSrvr] INFO -- Node 3: CNTR_START_CONF: started: 0000000000000000
2017-05-23 19:09:23 [MgmtSrvr] INFO -- Node 3: CNTR_START_CONF: starting: 0000000000000078
2017-05-23 19:09:23 [MgmtSrvr] INFO -- Node 3: Start phase 2 completed (system restart)
2017-05-23 19:09:23 [MgmtSrvr] INFO -- Node 6: Start phase 2 completed (system restart)
2017-05-23 19:09:23 [MgmtSrvr] INFO -- Node 4: Start phase 2 completed (system restart)
2017-05-23 19:09:23 [MgmtSrvr] INFO -- Node 5: Start phase 2 completed (system restart)
2017-05-23 19:09:23 [MgmtSrvr] INFO -- Node 6: Start phase 3 completed (system restart)
2017-05-23 19:09:23 [MgmtSrvr] INFO -- Node 5: Start phase 3 completed (system restart)
2017-05-23 19:09:23 [MgmtSrvr] INFO -- Node 4: Start phase 3 completed (system restart)
2017-05-23 19:09:23 [MgmtSrvr] INFO -- Node 3: Start phase 3 completed (system restart)
2017-05-23 19:09:23 [MgmtSrvr] INFO -- Node 3: Restarting cluster to GCI: 70
2017-05-23 19:09:23 [MgmtSrvr] INFO -- Node 3: Restore dictionary information from disk Starting
2017-05-23 19:09:23 [MgmtSrvr] INFO -- Node 3: Starting to restore schema
2017-05-23 19:09:48 [MgmtSrvr] INFO -- Node 5: Data usage is 0%(0 32K pages of total 4960512)
2017-05-23 19:09:48 [MgmtSrvr] INFO -- Node 5: Index usage is 0%(0 8K pages of total 3146112)
2017-05-23 19:09:48 [MgmtSrvr] INFO -- Node 3: Data usage is 0%(0 32K pages of total 4960512)
2017-05-23 19:09:48 [MgmtSrvr] INFO -- Node 3: Index usage is 0%(0 8K pages of total 3146112)
2017-05-23 19:09:49 [MgmtSrvr] INFO -- Node 6: Data usage is 0%(0 32K pages of total 4960512)
2017-05-23 19:09:49 [MgmtSrvr] INFO -- Node 6: Index usage is 0%(0 8K pages of total 3146112)
2017-05-23 19:09:49 [MgmtSrvr] INFO -- Node 4: Data usage is 0%(0 32K pages of total 4960512)
2017-05-23 19:09:49 [MgmtSrvr] INFO -- Node 4: Index usage is 0%(0 8K pages of total 3146112)
.... zZzzzzzz
....
2017-05-23 20:07:31 [MgmtSrvr] INFO -- Node 5: Data usage is 0%(0 32K pages of total 4960512)
2017-05-23 20:07:31 [MgmtSrvr] INFO -- Node 5: Index usage is 0%(0 8K pages of total 3146112)
2017-05-23 20:07:32 [MgmtSrvr] INFO -- Node 6: Data usage is 0%(0 32K pages of total 4960512)
2017-05-23 20:07:32 [MgmtSrvr] INFO -- Node 6: Index usage is 0%(0 8K pages of total 3146112)
2017-05-23 20:07:32 [MgmtSrvr] INFO -- Node 3: Data usage is 0%(0 32K pages of total 4960512)
2017-05-23 20:07:32 [MgmtSrvr] INFO -- Node 3: Index usage is 0%(0 8K pages of total 3146112)
2017-05-23 20:07:32 [MgmtSrvr] INFO -- Node 4: Data usage is 0%(0 32K pages of total 4960512)
2017-05-23 20:07:32 [MgmtSrvr] INFO -- Node 4: Index usage is 0%(0 8K pages of total 3146112)
....
2017-05-23 19:34:00 [ndbd] INFO -- Watchdog: User time: 2235 System time: 6140
2017-05-23 22:01:08 [ndbd] WARNING -- Ndb kernel thread 28 is stuck in: Job Handling elapsed=100
2017-05-23 22:01:08 [ndbd] INFO -- Watchdog: User time: 9153 System time: 12956
2017-05-23 23:49:09 [ndbd] WARNING -- Ndb kernel thread 6 is stuck in: Job Handling elapsed=100
2017-05-23 23:49:09 [ndbd] INFO -- Watchdog: User time: 13571 System time: 18538
2017-05-24 00:10:08 [ndbd] INFO -- Node failure during restart
2017-05-24 00:10:08 [ndbd] INFO -- QMGR (Line: 4232) 0x00000002
2017-05-24 00:10:08 [ndbd] INFO -- Error handler shutting down system
2017-05-24 00:10:08 [ndbd] INFO -- Error handler shutdown completed - exiting
2017-05-24 00:10:09 [ndbd] ALERT -- Node 3: Forced node shutdown completed. Occured during startphase 4. Caused by error 2308: 'Another node failed during system restart, please investigate error(s) on other node(s)(Restart error). Temporary error, restart node'.


Someone can help me ?

Red Hat Enterprise Linux Server release 7.3 (Maipo)



Edited 2 time(s). Last edit at 05/24/2017 12:45AM by Sergey Ivankov.

Options: ReplyQuote


Subject
Views
Written By
Posted
[NDB Cluster 7.4.15] ndb cluster doesn't restart after initial {Last completed phase 3}
291
May 23, 2017 11:10AM


Sorry, you can't reply to this topic. It has been closed.

Content reproduced on this site is the property of the respective copyright holders. It is not reviewed in advance by Oracle and does not necessarily represent the opinion of Oracle or any other party.