MySQL Forums
Forum List  »  NDB clusters

Re: Node 6: Forced node shutdown completed. Occurred during startphase 5. Caused by error 2341
Posted by: Pradeep Manickam
Date: March 05, 2021 03:54PM

out.log
=======
2021-03-05 21:17:49 [ndbd] INFO -- Angel pid: 1492 started child: 1493
2021-03-05 21:17:49 [ndbd] INFO -- Initial start of data node, ignoring any info on disk
2021-03-05 21:17:49 [ndbd] INFO -- Configuration fetched from '172.20.10.50:1186', generation: 3
2021-03-05 21:17:49 [ndbd] INFO -- Changing directory to '/var/lib/mysql-cluster'
2021-03-05 21:17:49 [ndbd] INFO -- SchedulerSpinTimer = 0
2021-03-05 21:17:49 [ndbd] INFO -- AutomaticThreadConfig = 0, NumCPUs = 0
2021-03-05 21:17:49 [ndbd] INFO -- MaxNoOfTriggers set to 1400
NDBMT: non-mt
2021-03-05 21:17:49 [ndbd] INFO -- NDB Cluster -- DB node 6
2021-03-05 21:17:49 [ndbd] INFO -- mysql-8.0.23 ndb-8.0.23 --
2021-03-05 21:17:49 [ndbd] INFO -- Memory Allocation for global memory pools Starting
2021-03-05 21:17:49 [ndbd] INFO -- numa_set_interleave_mask(numa_all_nodes) : no numa support
2021-03-05 21:17:49 [ndbd] INFO -- SharedGlobalMemory set to 128 MB
2021-03-05 21:17:49 [ndbd] INFO -- DataMemory set to 100 MB
2021-03-05 21:17:49 [ndbd] INFO -- RedoLogBuffer uses 132 MB
2021-03-05 21:17:49 [ndbd] INFO -- DiskPageBuffer uses 70 MB
2021-03-05 21:17:49 [ndbd] INFO -- SchemaTransactionMemory uses 2 MB
2021-03-05 21:17:49 [ndbd] INFO -- TransactionMemory calculated to 148 MB
2021-03-05 21:17:49 [ndbd] INFO -- Reserved part of TransactionMemory is 28 MB
2021-03-05 21:17:49 [ndbd] INFO -- No Undo log buffer used, will be allocated from TransactionMemory if later defined by command
2021-03-05 21:17:49 [ndbd] INFO -- TransactionMemory can expand and use SharedGlobalMemory if required
2021-03-05 21:17:49 [ndbd] INFO -- QueryMemory can use memory from SharedGlobalMemory until 90% used
2021-03-05 21:17:49 [ndbd] INFO -- Ndbd_mem_manager::init(1) min: 452Mb initial: 580Mb
2021-03-05 21:17:49 [ndbd] INFO -- Touch Memory Starting, 4224 pages, page size = 32768
2021-03-05 21:17:49 [ndbd] INFO -- Touch Memory Completed
2021-03-05 21:17:49 [ndbd] INFO -- Adding 132Mb to ZONE_19 (1, 4223)
2021-03-05 21:17:49 [ndbd] INFO -- Memory Allocation for global memory pools Completed
Started thread, index = 0, id = 1494, type = NdbfsThread
2021-03-05 21:17:49 [ndbd] INFO -- Loading blocks for data node run-time environment
2021-03-05 21:17:49 [ndbd] INFO -- Starting Sending and Receiving services
Started thread, index = 1, id = 1504, type = SocketClientThread
Started thread, index = 2, id = 1495, type = WatchDogThread
Started thread, index = 3, id = 1505, type = SocketServerThread
2021-03-05 21:17:49 [ndbd] INFO -- Starting the data node run-time environment
2021-03-05 21:17:49 [ndbd] INFO -- First START_ORD executed to connect MGM servers
2021-03-05 21:17:49 [ndbd] INFO -- Received second START_ORD as part of normal start
2021-03-05 21:17:49 [ndbd] INFO -- Disconnect all non-MGM servers
2021-03-05 21:17:49 [ndbd] INFO -- Start excuting the start phases
2021-03-05 21:17:49 [ndbd] INFO -- Sending READ_CONFIG_REQ to index = 0, name = CMVMI
2021-03-05 21:17:49 [ndbd] INFO -- Start initiated (mysql-8.0.23 ndb-8.0.23)
NDBFS/AsyncFile: Allocating 275256 for In/Deflate buffer
Started thread, index = 5, id = 1506, type = NdbfsThread
2021-03-05 21:17:49 [ndbd] INFO -- Touch Memory Starting, 14354 pages, page size = 32768
2021-03-05 21:17:49 [ndbd] INFO -- Touch Memory Completed
2021-03-05 21:17:49 [ndbd] INFO -- Adding 449Mb to ZONE_19 (4224, 14354)
2021-03-05 21:17:49 [ndbd] INFO -- Sending READ_CONFIG_REQ to index = 1, name = NDBFS


Started thread, index = 6, id = 1515, type = NdbfsThread
NDBFS/AsyncFile: Allocating 275256 for In/Deflate buffer
Started thread, index = 7, id = 1516, type = NdbfsThread
NDBFS/AsyncFile: Allocating 275256 for In/Deflate buffer
Started thread, index = 8, id = 1517, type = NdbfsThread
NDBFS/AsyncFile: Allocating 275256 for In/Deflate buffer
Started thread, index = 9, id = 1518, type = NdbfsThread
NDBFS/AsyncFile: Allocating 275256 for In/Deflate buffer
Started thread, index = 10, id = 1519, type = NdbfsThread
NDBFS/AsyncFile: Allocating 275256 for In/Deflate buffer
Started thread, index = 11, id = 1520, type = NdbfsThread
NDBFS/AsyncFile: Allocating 275256 for In/Deflate buffer
Started thread, index = 12, id = 1521, type = NdbfsThread
NDBFS/AsyncFile: Allocating 275256 for In/Deflate buffer
Started thread, index = 13, id = 1522, type = NdbfsThread
NDBFS/AsyncFile: Allocating 275256 for In/Deflate buffer
Started thread, index = 14, id = 1523, type = NdbfsThread
NDBFS/AsyncFile: Allocating 275256 for In/Deflate buffer
Started thread, index = 15, id = 1524, type = NdbfsThread
NDBFS/AsyncFile: Allocating 275256 for In/Deflate buffer
Started thread, index = 16, id = 1525, type = NdbfsThread
NDBFS/AsyncFile: Allocating 275256 for In/Deflate buffer
Started thread, index = 17, id = 1526, type = NdbfsThread
NDBFS/AsyncFile: Allocating 275256 for In/Deflate buffer
Started thread, index = 18, id = 1527, type = NdbfsThread
NDBFS/AsyncFile: Allocating 275256 for In/Deflate buffer
Started thread, index = 19, id = 1528, type = NdbfsThread
NDBFS/AsyncFile: Allocating 275256 for In/Deflate buffer
Started thread, index = 20, id = 1529, type = NdbfsThread
NDBFS/AsyncFile: Allocating 275256 for In/Deflate buffer
:
:
Started thread, index = 40, id = 1549, type = NdbfsThread
NDBFS/AsyncFile: Allocating 275256 for In/Deflate buffer
Started thread, index = 41, id = 1550, type = NdbfsThread
NDBFS/AsyncFile: Allocating 275256 for In/Deflate buffer
Started thread, index = 42, id = 1551, type = NdbfsThread
Started thread, index = 43, id = 1552, type = NdbfsThread
Started thread, index = 44, id = 1553, type = NdbfsThread
2021-03-05 21:17:49 [ndbd] INFO -- Sending READ_CONFIG_REQ to index = 2, name = DBINFO
2021-03-05 21:17:49 [ndbd] INFO -- Sending READ_CONFIG_REQ to index = 3, name = DBTUP
2021-03-05 21:17:49 [ndbd] INFO -- Sending READ_CONFIG_REQ to index = 4, name = DBACC
2021-03-05 21:17:49 [ndbd] INFO -- Sending READ_CONFIG_REQ to index = 5, name = DBTC
2021-03-05 21:17:49 [ndbd] INFO -- Sending READ_CONFIG_REQ to index = 6, name = DBLQH
LCPFragWatchdog : WarnElapsed : 60000(ms) MaxElapsed 180000(ms) : period millis : 1000
2021-03-05 21:17:50 [ndbd] INFO -- Sending READ_CONFIG_REQ to index = 7, name = DBTUX
2021-03-05 21:17:50 [ndbd] INFO -- Sending READ_CONFIG_REQ to index = 8, name = DBDICT
2021-03-05 21:17:50 [ndbd] INFO -- Sending READ_CONFIG_REQ to index = 9, name = DBDIH
2021-03-05 21:17:50 [ndbd] INFO -- Sending READ_CONFIG_REQ to index = 10, name = NDBCNTR
2021-03-05 21:17:50 [ndbd] INFO -- Sending READ_CONFIG_REQ to index = 11, name = QMGR
2021-03-05 21:17:50 [ndbd] INFO -- Sending READ_CONFIG_REQ to index = 12, name = TRIX
2021-03-05 21:17:50 [ndbd] INFO -- Sending READ_CONFIG_REQ to index = 13, name = BACKUP
2021-03-05 21:17:50 [ndbd] INFO -- Sending READ_CONFIG_REQ to index = 14, name = DBUTIL
2021-03-05 21:17:50 [ndbd] INFO -- Sending READ_CONFIG_REQ to index = 15, name = SUMA
2021-03-05 21:17:50 [ndbd] INFO -- Sending READ_CONFIG_REQ to index = 16, name = TSMAN
2021-03-05 21:17:50 [ndbd] INFO -- Sending READ_CONFIG_REQ to index = 17, name = LGMAN
2021-03-05 21:17:50 [ndbd] INFO -- Sending READ_CONFIG_REQ to index = 18, name = PGMAN
pgman: page buffer entries = 10
2021-03-05 21:17:50 [ndbd] INFO -- Sending READ_CONFIG_REQ to index = 19, name = RESTORE
2021-03-05 21:17:50 [ndbd] INFO -- Sending READ_CONFIG_REQ to index = 20, name = DBSPJ
2021-03-05 21:17:50 [ndbd] INFO -- Sending READ_CONFIG_REQ to index = 21, name = THRMAN
2021-03-05 21:17:50 [ndbd] INFO -- Sending READ_CONFIG_REQ to index = 22, name = DBQLQH
2021-03-05 21:17:50 [ndbd] INFO -- Sending READ_CONFIG_REQ to index = 23, name = DBQACC
2021-03-05 21:17:50 [ndbd] INFO -- Sending READ_CONFIG_REQ to index = 24, name = DBQTUP
2021-03-05 21:17:50 [ndbd] INFO -- Sending READ_CONFIG_REQ to index = 25, name = QBACKUP
2021-03-05 21:17:50 [ndbd] INFO -- Sending READ_CONFIG_REQ to index = 26, name = DBQTUX
2021-03-05 21:17:50 [ndbd] INFO -- Sending READ_CONFIG_REQ to index = 27, name = QRESTORE
2021-03-05 21:17:50 [ndbd] INFO -- READ_CONFIG_REQ phase completed, this phase is used to read configuration and to calculate various sizes and allocate almost all memory needed by the data node in i>
2021-03-05 21:17:50 [ndbd] INFO -- Clearing filesystem in initial start
2021-03-05 21:17:50 [ndbd] INFO -- Start phase 0 completed
2021-03-05 21:17:50 [ndbd] INFO -- Phase 0 has made some file system initialisations
2021-03-05 21:17:50 [ndbd] INFO -- We are running with 0 LDM workers and 4 REDO log parts. This means that we can avoid using a mutex to access REDO log parts
2021-03-05 21:17:50 [ndbd] INFO -- Watchdog KillSwitch off.
2021-03-05 21:17:50 [ndbd] INFO -- Starting QMGR phase 1
2021-03-05 21:17:50 [ndbd] INFO -- DIH reported initial start, now starting the Node Inclusion Protocol
2021-03-05 21:17:50 [ndbd] INFO -- findNeighbours from: 2988 old (left: 65535 right: 65535) new (5 4)
2021-03-05 21:17:50 [ndbd] INFO -- Include node protocol completed, phase 1 in QMGR completed
2021-03-05 21:17:50 [ndbd] INFO -- Start phase 1 completed
2021-03-05 21:17:50 [ndbd] INFO -- Phase 1 initialised some variables and included node in cluster, locked memory if configured to do so
2021-03-05 21:17:50 [ndbd] INFO -- Asking main node to accept our start (nodeId = 4 is main), GCI = 0
2021-03-05 21:17:50 [ndbd] INFO -- NDBCNTR main accepted us into cluster, start NDB start phase 1
2021-03-05 21:17:50 [ndbd] INFO -- We are performing initial node restart
2021-03-05 21:17:50 [ndbd] INFO -- LDM(0): Starting REDO log initialisation
2021-03-05 21:17:50 [ndbd] INFO -- Receive arbitrator node 1 [ticket=055b000900b60ad0]
2021-03-05 21:17:51 [ndbd] INFO -- Adjusting disk write speed bounds due to : Node restart ongoing
2021-03-05 21:17:55 [ndbd] INFO -- LDM(0): Completed REDO log initialisation of logPart = 1
2021-03-05 21:17:55 [ndbd] INFO -- LDM(0): Completed REDO log initialisation of logPart = 0
2021-03-05 21:17:55 [ndbd] INFO -- LDM(0): Completed REDO log initialisation of logPart = 3
2021-03-05 21:17:55 [ndbd] INFO -- LDM(0): Completed REDO log initialisation of logPart = 2
2021-03-05 21:17:55 [ndbd] INFO -- LDM(0): Completed REDO initialisation
2021-03-05 21:17:55 [ndbd] INFO -- Schema file initialisation Starting
2021-03-05 21:17:55 [ndbd] INFO -- Schema file initialisation Completed
2021-03-05 21:17:55 [ndbd] INFO -- NDB start phase 1 completed
2021-03-05 21:17:55 [ndbd] INFO -- Start phase 2 completed
2021-03-05 21:17:55 [ndbd] INFO -- Phase 2 did more initialisations, main accepted our start, we initialised the REDO log
2021-03-05 21:17:55 [ndbd] INFO -- Start NDB start phase 2
2021-03-05 21:17:55 [ndbd] INFO -- Starting with m_restart_seq set to 1
2021-03-05 21:17:55 [ndbd] INFO -- Request permission to start our node from main Starting
2021-03-05 21:17:55 [ndbd] INFO -- Request permission to start our node from main Completed
2021-03-05 21:17:55 [ndbd] INFO -- NDB start phase 2 completed
2021-03-05 21:17:55 [ndbd] INFO -- Start phase 3 completed
2021-03-05 21:17:55 [ndbd] INFO -- Phase 3 locked the data dictionary, performed local connection setups, we asked for permission to start our node
2021-03-05 21:17:55 [ndbd] INFO -- Start NDB start phase 3
2021-03-05 21:17:55 [ndbd] INFO -- Start invalidating: Part 0, Head: file: 0, page: 1, Invalidation start: file: 0, page: 1, actual start invalidate: file: 0 page: 1
2021-03-05 21:17:55 [ndbd] INFO -- Start invalidating: Part 2, Head: file: 0, page: 1, Invalidation start: file: 0, page: 1, actual start invalidate: file: 0 page: 1
2021-03-05 21:17:55 [ndbd] INFO -- Start invalidating: Part 3, Head: file: 0, page: 1, Invalidation start: file: 0, page: 1, actual start invalidate: file: 0 page: 1
2021-03-05 21:17:55 [ndbd] INFO -- Start invalidating: Part 1, Head: file: 0, page: 1, Invalidation start: file: 0, page: 1, actual start invalidate: file: 0 page: 1
2021-03-05 21:17:56 [ndbd] INFO -- LDM(0): Completed old Redo head invalidation on log part 2
2021-03-05 21:17:56 [ndbd] INFO -- LDM(0): Completed old Redo head invalidation on log part 0
2021-03-05 21:17:56 [ndbd] INFO -- LDM(0): Completed old Redo head invalidation on log part 1
2021-03-05 21:17:56 [ndbd] INFO -- LDM(0): Completed old Redo head invalidation on log part 3
2021-03-05 21:17:56 [ndbd] INFO -- LDM(0): All redo actions complete (apply, invalidate)
2021-03-05 21:17:56 [ndbd] INFO -- NDB start phase 3 completed
2021-03-05 21:17:56 [ndbd] INFO -- Start phase 4 completed
2021-03-05 21:17:56 [ndbd] INFO -- Phase 4 continued preparations of the REDO log
2021-03-05 21:17:56 [ndbd] INFO -- Start NDB start phase 4
2021-03-05 21:17:56 [ndbd] INFO -- Request copying of distribution and dictionary information from main Starting
2021-03-05 21:17:56 [ndbd] INFO -- Completed setting up multiple transporters to nodes in the same node group
2021-03-05 21:17:56 [ndbd] INFO -- Adjusting disk write speed bounds due to : Node restart finished
2021-03-05 21:17:56 [ndbd] INFO -- Copying of dictionary information from main Starting
2021-03-05 21:17:57 [ndbd] INFO -- Copying of dictionary information from main Completed
2021-03-05 21:17:57 [ndbd] INFO -- Request copying of distribution and dictionary information from main Completed
2021-03-05 21:17:57 [ndbd] INFO -- NDB start phase 4 completed
2021-03-05 21:17:57 [ndbd] INFO -- Start NDB start phase 5 (only to DBDIH)
2021-03-05 21:17:57 [ndbd] INFO -- Restore Database Off-line Starting
2021-03-05 21:17:57 [ndbd] INFO -- GSN_START_RECREQ keepGci: 0 (5249)
2021-03-05 21:17:57 [ndbd] INFO -- All start fragments sent, requesting LDM to restore all fragments and to execute the REDO log to bring the database to an off-line but consistent state
execSTART_RECREQ changing srnodes from 0000000000000000000000000000000000000070 to 0000000000000000000000000000000000000040
2021-03-05 21:17:57 [ndbd] INFO -- LDM instance 0: Restored LCP : 0 fragments, 0 rows, 0 millis, 0 rows/s
2021-03-05 21:17:57 [ndbd] INFO -- LDM(0): Completed fuzzy restore 0 fragments (0 from LCP, 0 by non-trans copy)
2021-03-05 21:17:57 [ndbd] INFO -- LDM(0): Starting DD Undo log application
2021-03-05 21:17:57 [ndbd] INFO -- LDM(0): Completed DD Undo log application
2021-03-05 21:17:57 [ndbd] INFO -- LDM(0): Starting to rebuild ordered indexes
2021-03-05 21:17:57 [ndbd] INFO -- LDM(0): index id 9 rebuild done
2021-03-05 21:17:57 [ndbd] INFO -- LDM(0): index id 12 rebuild done
2021-03-05 21:17:57 [ndbd] INFO -- LDM(0): index id 14 rebuild done
2021-03-05 21:17:57 [ndbd] INFO -- LDM(0): We have completed restoring our fragments and executed REDO log and rebuilt ordered indexes
2021-03-05 21:17:57 [ndbd] INFO -- Restore Database Off-line Completed
2021-03-05 21:17:57 [ndbd] INFO -- Bring Database On-line Starting
2021-03-05 21:17:57 [ndbd] INFO -- Bring Database On-line Completed
2021-03-05 21:17:57 [ndbd] INFO -- Starting REDO logging
2021-03-05 21:17:57 [ndbd] INFO -- Make On-line Database recoverable by waiting for LCP Starting, all parallel threads have now ceased their activity and we have a single wait state here
For help with below stacktrace consult:
https://dev.mysql.com/doc/refman/en/using-stack-trace.html
Also note that stack_bottom and thread_stack will always show up as zero.
Base address/slide: 0x55dfb86b3000
With use of addr2line, llvm-symbolizer, or, atos, subtract the addresses in
stacktrace with the base address before passing them to tool.
For tools that have options for slide use that, e.g.:
llvm-symbolizer --adjust-vma=0x55dfb86b3000 ...
atos -s 0x55dfb86b3000 ...
stack_bottom = 0 thread_stack 0x0
ndbd(my_print_stacktrace(unsigned char const*, unsigned long)+0x41) [0x55dfb8f421c1]
ndbd(ndb_print_stacktrace()+0x56) [0x55dfb8f41606]
ndbd(ErrorReporter::handleError(int, char const*, char const*, NdbShutdownType)+0x33) [0x55dfb8edd023]
ndbd(SimulatedBlock::progError(int, int, char const*, char const*) const+0xfd) [0x55dfb8f6954d]

ndbd(Tsman::execEND_LCPREQ(Signal*)+0x156) [0x55dfb8ed6066]
ndbd(FastScheduler::doJob(unsigned int)+0x1d5) [0x55dfb8f656e5]
ndbd(ThreadConfig::ipControlLoop(NdbThread*)+0x6a8) [0x55dfb8f75a28]
ndbd(ndbd_run(bool, int, char const*, int, char const*, bool, bool, bool, unsigned int, int, int, unsigned long)+0x769) [0x55dfb8ba2ef9]
ndbd(real_main(int, char**)+0x37f) [0x55dfb8ba0f2f]
ndbd(angel_run(char const*, Vector<BaseString> const&, char const*, int, char const*, bool, bool, bool, int, int)+0xf48) [0x55dfb8ba0958]
ndbd(real_main(int, char**)+0x2e3) [0x55dfb8ba0e93]
ndbd(main+0x3e) [0x55dfb8ba0a5e]
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf3) [0x7f865f1720b3]
ndbd(_start+0x2e) [0x55dfb8b9e38e]
2021-03-05 21:18:01 [ndbd] INFO -- /var/lib/pb2/sb_1-1373275-1607727651.83/release/mysql-cluster-gpl-8.0.23/storage/ndb/src/kernel/blocks/tsman.cpp
2021-03-05 21:18:01 [ndbd] INFO -- TSMAN (Line: 2984) 0x00000006 Check m_lcp_ongoing failed
2021-03-05 21:18:01 [ndbd] INFO -- Error handler shutting down system
2021-03-05 21:18:01 [ndbd] INFO -- Error handler shutdown completed - exiting
2021-03-05 21:18:01 [ndbd] ALERT -- Node 6: Forced node shutdown completed. Occurred during startphase 5. Caused by error 2341: 'Internal program error (failed ndbrequire)(Internal error, programming >

Options: ReplyQuote


Subject
Views
Written By
Posted
Re: Node 6: Forced node shutdown completed. Occurred during startphase 5. Caused by error 2341
231
March 05, 2021 03:54PM


Sorry, only registered users may post in this forum.

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.