Re: Node 6: Forced node shutdown completed. Occurred during startphase 5. Caused by error 2341
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 KllSwitch 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 >