node crashes and corrupts DB on heavy usage

[kuegi]

Summary

I am running multiple nodes on different servers. All get heavy usage of transactions (lots of TD and EVM txs, also native swaps).
Trying to update to 4.0.8 leads to a node crash with corrupted DB within a few hours.

It all works perfectly stable on 4.0.3

Environment

• Node Version: 4.0.8
• OS with version: debian

[Bushstar]

Can you build defid with debug enabled using MAKE_DEBUG=1 and get a core dump for this? Install coredumpctl and make sure that ulimit -c returns unlimited. This would be incredibly helpful.

[kuegi]

Can you build defid with debug enabled using MAKE_DEBUG=1 and get a core dump for this? Install coredumpctl and make sure that ulimit -c returns unlimited. This would be incredibly helpful.

I can try this. As these nodes should run 24/7 without interruption, I would prefer to only "force" such an interruption once. So to make sure it has everything prepared: I install coredumpctl (are there any known limitations/problems with having that on a production machine?).
compile with export MAKE_DEBUG=1 && ./make.sh release and run it. How do I make a core dump after the problem?

ulimit -c gives me 0 right now

[Bushstar]

I'd just build with the following and skip the release steps. Binaries will be in ./build/src/

MAKE_DEBUG=1 ./make.sh build

coredumpctl can be resource intensive at the point of capturing a core dump and the core dumps themselves can take up space. We do need to set the ulimit to be unlimited as otherwise the dump file will be truncated.

We can set the ulimit just for defid if you run it via systemd. Edit your service file, assuming it is /etc/systemd/system/defid.service'. Under [Service]` add the following line.

LimitCORE=infinity

Run the following command.

sudo systemctl daemon-reload

Then start or restart the defid service.

sudo systemctl restart defid.service

If you use systemd ignore the rest below, if however you run defid under a user account you would set ulimit -c unlimited. So if you ran your binary via cron you would have an entry like this.

@reboot ulimit -c unlimited; /path/to/your/script

Or add the line to your script, or create a wrapper script if cron ran a binary.

#!/bin/bash
ulimit -c unlimited
# Execute DeFiChain
/path/to/defid -daemon

Or you could set ulimit system wide by editing /etc/sysctl.conf or /etc/security/limits.conf and add the following lines. To limit it just to the user the binary is running under you can change the * to be the name of the user.

* soft core unlimited
* hard core unlimited

After reboot and see if ulimit is now set to unlimited.

[kuegi]

thx. Yes using systemd. Did the steps and its all running now. will report when i crashes again.
how do I get the coredump afterwards?

[Bushstar]

Run coredumpctl list to see all the core dumps, note the PID of the core dump you want to export and run the following command.

coredumpctl dump PID --output=defid.dump

Then GZIP the core dump and include the defid binary as well. I will then fire up gdb with the core dump and the executable and get the back trace.

However you could also just get the backtrace and post it here. Install gdb if not already installed and run the following replacing PID with the PID of the core dump.

coredumpctl gdb PID

Once at the GDB prompt type in bt and press enter. Copy and paste the result here. Probably easier to just run GDB and paste the result here than export, GZIP and send everything over.

[kuegi]

thx. I prefer to not install too much on the production machine. will see if I can do it locally.

One thing that I think might be the reason is a memory leak. Cause the logs on the crash fell a bit like an out of memory. Will try to watch the memory usage in the next hours

[kuegi]

update so far: it seems that the node is constantly increasing memory usage. started with 3g and is now at 5.7g
4.0.3 node is at 8g after weeks uptime.

[kuegi]

quick update: node is now at 7g memory. Its holding up longer than expected already (not sure if its due to the unlimited setting or debug build or just because there was less load).

[kuegi]

memory is still rising but slower than in previous tries. now 7.4g. I will go back to the release build of 4.0.8 where it got the problem within 12hours. lets see if thats the difference or the unlimited

[kuegi]

@Bushstar running it with the ./make.sh release build version, the error occured after 9 hours.

So it seems that there is a difference to MAKE_DEBUG=1 ./make.sh build that leads to the error.

result of gdb:

[New LWP 16778]
[New LWP 16758]
[New LWP 16930]
Cannot access memory at address 0x7ff201638168
Cannot access memory at address 0x7ff201638160
Failed to read a valid object file image from memory.
Core was generated by `/home/user/defichain/bin/defid'.
Program terminated with signal SIGSEGV, Segmentation fault.
#0  0x00007ff2013d2684 in ?? ()
[Current thread is 1 (LWP 16749)]
warning: Missing auto-load script at offset 0 in section .debug_gdb_scripts
of file /home/user/defichain-4.0.8k/bin/defid.
Use `info auto-load python-scripts [REGEXP]' to list them.
(gdb) bt
#0  0x00007ff2013d2684 in ?? ()
Backtrace stopped: Cannot access memory at address 0x7ff1ceffacc8
(gdb) 

(I guess it cannot read the data due to missing debug symbols, but since the error is not happening in debug build it will be hard to track down :/)

last logs before the crash doesn't really help either:

2024-02-07T16:56:45Z [evm_try_push_tx_in_template] failed, reason : [execute_tx] nonce check failed. Account nonce 19285, signed_tx nonce 19286
2024-02-07T16:56:50Z [evm_try_push_tx_in_template] failed, reason : [execute_tx] nonce check failed. Account nonce 190, signed_tx nonce 192
2024-02-07T16:56:50Z [evm_try_push_tx_in_template] failed, reason : [execute_tx] nonce check failed. Account nonce 19285, signed_tx nonce 19287
2024-02-07T16:56:52Z UpdateTip: new best=5e314b4ad6d6c31877dbeebdb2e59bfae0da5dbec01af12f42ba4e227c60c2bd height=3702580 version=0x20000000 log2_work=88.108927 tx=29276274 date='2024-02-07T16:57:17Z' progress=1.000000 cache=0.6MiB(4662txo)
2024-02-07T16:56:52Z UpdateTip: new best=5b5edc5f76c49cd039fafe0837d2f935bc0bb8b2316cccb667e65e600419fc84 height=3702581 version=0x20000000 log2_work=88.108928 tx=29276275 date='2024-02-07T16:56:34Z' progress=1.000000 cache=0.6MiB(4663txo)


2024-02-07T16:57:12Z DeFi Blockchain version v4.0.8.0-master-4d7e2ddd5b-dirty (debug build)
2024-02-07T16:57:12Z [ain_grpc] Init rs logging
2024-02-07T16:57:12Z conf: fd limit: req: 900, set 1024, max: 524288
2024-02-07T16:57:12Z conf: checkpoints enabled.

[kuegi]

running it on 4.0.9 with MAKE_DEBUG=1 ./make.sh release now. just for comparison.

[kuegi]

looks like its really the MAKE_DEBUG=1 cause this version runs without issue for 11 hours already. will switch to MAKE_DEBUG=0 in 10 hours to double check.

[kuegi]

held up longer, but also crashed now. But again with no symbols.

whats weird are those log messages, as they do not make sense imho. They come in massively right before it just stops.

2024-02-08T14:08:48Z [evm_try_push_tx_in_template] failed, reason : [execute_tx] nonce check failed. Account nonce 77, signed_tx nonce 78
2024-02-08T14:08:48Z [evm_try_push_tx_in_template] failed, reason : [execute_tx] nonce check failed. Account nonce 77, signed_tx nonce 79
2024-02-08T14:08:48Z [evm_try_push_tx_in_template] failed, reason : [execute_tx] nonce check failed. Account nonce 77, signed_tx nonce 80
2024-02-08T14:08:49Z [evm_try_push_tx_in_template] failed, reason : [execute_tx] nonce check failed. Account nonce 77, signed_tx nonce 81
2024-02-08T14:08:49Z [evm_try_push_tx_in_template] failed, reason : [execute_tx] nonce check failed. Account nonce 77, signed_tx nonce 82
2024-02-08T14:08:52Z [evm_try_push_tx_in_template] failed, reason : [execute_tx] nonce check failed. Account nonce 147, signed_tx nonce 148
2024-02-08T14:08:57Z [evm_try_push_tx_in_template] failed, reason : [execute_tx] nonce check failed. Account nonce 77, signed_tx nonce 78
2024-02-08T14:08:57Z [evm_try_push_tx_in_template] failed, reason : [execute_tx] nonce check failed. Account nonce 77, signed_tx nonce 79
2024-02-08T14:08:58Z [evm_try_push_tx_in_template] failed, reason : [execute_tx] nonce check failed. Account nonce 77, signed_tx nonce 80
2024-02-08T14:08:58Z [evm_try_push_tx_in_template] failed, reason : [execute_tx] nonce check failed. Account nonce 77, signed_tx nonce 81
2024-02-08T14:08:58Z [evm_try_push_tx_in_template] failed, reason : [execute_tx] nonce check failed. Account nonce 77, signed_tx nonce 82
2024-02-08T14:09:01Z [evm_try_push_tx_in_template] failed, reason : [execute_tx] nonce check failed. Account nonce 147, signed_tx nonce 148
2024-02-08T14:09:07Z [evm_try_push_tx_in_template] failed, reason : [execute_tx] nonce check failed. Account nonce 77, signed_tx nonce 78
2024-02-08T14:09:07Z [evm_try_push_tx_in_template] failed, reason : [execute_tx] nonce check failed. Account nonce 77, signed_tx nonce 79
2024-02-08T14:09:07Z [evm_try_push_tx_in_template] failed, reason : [execute_tx] nonce check failed. Account nonce 77, signed_tx nonce 80
2024-02-08T14:09:08Z [evm_try_push_tx_in_template] failed, reason : [execute_tx] nonce check failed. Account nonce 77, signed_tx nonce 81
2024-02-08T14:09:08Z [evm_try_push_tx_in_template] failed, reason : [execute_tx] nonce check failed. Account nonce 77, signed_tx nonce 82

this time gdb says:

Cannot access memory at address 0x7f1709473168
Cannot access memory at address 0x7f1709473160
Failed to read a valid object file image from memory.
Core was generated by `/home/user/defichain/bin/defid'.
Program terminated with signal SIGABRT, Aborted.
#0  0x00007f17090e88eb in ?? ()
[Current thread is 1 (LWP 24267)]
(gdb) bt
#0  0x00007f17090e88eb in ?? ()
Backtrace stopped: Cannot access memory at address 0x7f16f6ffb580

(not sure if the unlimited setting works in the systemd as the dump is truncated, will try setting ulimit directly)

[kuegi]

@Bushstar it finally also happened in a debug build. but seems the its still truncated and does not have debug symbols. will try a completely fresh build, maybe the build process is not cleaning up correctly.

this time it was a sig sev again

Program terminated with signal SIGSEGV, Segmentation fault.
#0  0x00007f9c60798684 in ?? ()
[Current thread is 1 (LWP 17358)]

[kuegi]

I managed to reproduce it locally with bot in dry-run mode (so not sending any transaction, basically only reading blockcount, pool data etc.). defid running directly in the console, it still just stops, but with the note about the kill:

2024-03-06T23:43:02Z UpdateTip: new best=cd1d9a0a9c0cd7f364bfd7863dc42a8664da939ae30170b77d7b9852c5f61cbf height=3783697 version=0x20000000 log2_work=88.161375 tx=30118281 date='2024-03-06T23:43:31Z' progress=1.000000 cache=0.3MiB(2066txo)
2024-03-06T23:43:02Z UpdateTip: new best=2cb8199400ed6b797e29ae435f0f4aab5f42a317401d645a0863c33624a3e369 height=3783698 version=0x20000000 log2_work=88.161375 tx=30118282 date='2024-03-06T23:42:43Z' progress=1.000000 cache=0.3MiB(2067txo)
zsh: segmentation fault (core dumped)  ./build/defichain-latest/bin/defid

core dump is 77.4GB ...

bt shows:

* thread #14, stop reason = ESR_EC_DABORT_EL0 (fault address: 0x0)
  * frame #0: 0x00000001003d66d8 defid`CFlushableStorageKV::GetSnapshotPair() [inlined] bool std::__1::__tree_is_left_child[abi:v160006]<std::__1::__tree_node_base<void*>*>(__x=0x00006000037837e0) at __tree:105:35 [opt]
    frame #1: 0x00000001003d66d4 defid`CFlushableStorageKV::GetSnapshotPair() [inlined] std::__1::__tree_end_node<std::__1::__tree_node_base<void*>*>* std::__1::__tree_next_iter[abi:v160006]<std::__1::__tree_end_node<std::__1::__tree_node_base<void*>*>*, std::__1::__tree_node_base<void*>*>(__x=0x00006000037837e0) at __tree:209:13 [opt]
    frame #2: 0x00000001003d66bc defid`CFlushableStorageKV::GetSnapshotPair() [inlined] std::__1::__tree_const_iterator<std::__1::__value_type<std::__1::vector<unsigned char, std::__1::allocator<unsigned char>>, std::__1::optional<std::__1::vector<unsigned char, std::__1::allocator<unsigned char>>>>, std::__1::__tree_node<std::__1::__value_type<std::__1::vector<unsigned char, std::__1::allocator<unsigned char>>, std::__1::optional<std::__1::vector<unsigned char, std::__1::allocator<unsigned char>>>>, void*>*, long>::operator++[abi:v160006](this=<unavailable>) at __tree:946:11 [opt]
    frame #3: 0x00000001003d66bc defid`CFlushableStorageKV::GetSnapshotPair() [inlined] std::__1::__map_const_iterator<std::__1::__tree_const_iterator<std::__1::__value_type<std::__1::vector<unsigned char, std::__1::allocator<unsigned char>>, std::__1::optional<std::__1::vector<unsigned char, std::__1::allocator<unsigned char>>>>, std::__1::__tree_node<std::__1::__value_type<std::__1::vector<unsigned char, std::__1::allocator<unsigned char>>, std::__1::optional<std::__1::vector<unsigned char, std::__1::allocator<unsigned char>>>>, void*>*, long>>::operator++[abi:v160006](this=<unavailable>) at map:936:41 [opt]
    frame #4: 0x00000001003d66bc defid`CFlushableStorageKV::GetSnapshotPair() at map:1272:59 [opt]
    frame #5: 0x00000001003d66a0 defid`CFlushableStorageKV::GetSnapshotPair() [inlined] std::__1::map<std::__1::vector<unsigned char, std::__1::allocator<unsigned char>>, std::__1::optional<std::__1::vector<unsigned char, std::__1::allocator<unsigned char>>>, std::__1::less<std::__1::vector<unsigned char, std::__1::allocator<unsigned char>>>, std::__1::allocator<std::__1::pair<std::__1::vector<unsigned char, std::__1::allocator<unsigned char>> const, std::__1::optional<std::__1::vector<unsigned char, std::__1::allocator<unsigned char>>>>>>::map[abi:v160006](this=0x00000001702aa508 size=12368, __m=<unavailable>) at map:1081:13 [opt]
    frame #6: 0x00000001003d66a0 defid`CFlushableStorageKV::GetSnapshotPair() [inlined] std::__1::map<std::__1::vector<unsigned char, std::__1::allocator<unsigned char>>, std::__1::optional<std::__1::vector<unsigned char, std::__1::allocator<unsigned char>>>, std::__1::less<std::__1::vector<unsigned char, std::__1::allocator<unsigned char>>>, std::__1::allocator<std::__1::pair<std::__1::vector<unsigned char, std::__1::allocator<unsigned char>> const, std::__1::optional<std::__1::vector<unsigned char, std::__1::allocator<unsigned char>>>>>>::map[abi:v160006](this=0x00000001702aa508 size=12368, __m=<unavailable>) at map:1080:9 [opt]
    frame #7: 0x00000001003d66a0 defid`CFlushableStorageKV::GetSnapshotPair() [inlined] std::__1::pair<std::__1::map<std::__1::vector<unsigned char, std::__1::allocator<unsigned char>>, std::__1::optional<std::__1::vector<unsigned char, std::__1::allocator<unsigned char>>>, std::__1::less<std::__1::vector<unsigned char, std::__1::allocator<unsigned char>>>, std::__1::allocator<std::__1::pair<std::__1::vector<unsigned char, std::__1::allocator<unsigned char>> const, std::__1::optional<std::__1::vector<unsigned char, std::__1::allocator<unsigned char>>>>>>, std::__1::unique_ptr<CStorageLevelDB, std::__1::default_delete<CStorageLevelDB>>>::pair[abi:v160006]<std::__1::map<std::__1::vector<unsigned char, std::__1::allocator<unsigned char>>, std::__1::optional<std::__1::vector<unsigned char, std::__1::allocator<unsigned char>>>, std::__1::less<std::__1::vector<unsigned char, std::__1::allocator<unsigned char>>>, std::__1::allocator<std::__1::pair<std::__1::vector<unsigned char, std::__1::allocator<unsigned char>> const, std::__1::optional<std::__1::vector<unsigned char, std::__1::allocator<unsigned char>>>>>>&, std::__1::unique_ptr<CStorageLevelDB, std::__1::default_delete<CStorageLevelDB>>, (void*)0>(this=0x00000001702aa508, __u1=<unavailable>, __u2=<unavailable>) at pair.h:222:11 [opt]
    frame #8: 0x00000001003d66a0 defid`CFlushableStorageKV::GetSnapshotPair() [inlined] std::__1::pair<std::__1::map<std::__1::vector<unsigned char, std::__1::allocator<unsigned char>>, std::__1::optional<std::__1::vector<unsigned char, std::__1::allocator<unsigned char>>>, std::__1::less<std::__1::vector<unsigned char, std::__1::allocator<unsigned char>>>, std::__1::allocator<std::__1::pair<std::__1::vector<unsigned char, std::__1::allocator<unsigned char>> const, std::__1::optional<std::__1::vector<unsigned char, std::__1::allocator<unsigned char>>>>>>, std::__1::unique_ptr<CStorageLevelDB, std::__1::default_delete<CStorageLevelDB>>>::pair[abi:v160006]<std::__1::map<std::__1::vector<unsigned char, std::__1::allocator<unsigned char>>, std::__1::optional<std::__1::vector<unsigned char, std::__1::allocator<unsigned char>>>, std::__1::less<std::__1::vector<unsigned char, std::__1::allocator<unsigned char>>>, std::__1::allocator<std::__1::pair<std::__1::vector<unsigned char, std::__1::allocator<unsigned char>> const, std::__1::optional<std::__1::vector<unsigned char, std::__1::allocator<unsigned char>>>>>>&, std::__1::unique_ptr<CStorageLevelDB, std::__1::default_delete<CStorageLevelDB>>, (void*)0>(this=0x00000001702aa508, __u1=<unavailable>, __u2=<unavailable>) at pair.h:222:79 [opt]
    frame #9: 0x00000001003d66a0 defid`CFlushableStorageKV::GetSnapshotPair(this=<unavailable>) at flushablestorage.h:385:16 [opt]
    frame #10: 0x00000001003d6488 defid`GetViewSnapshot() at masternodes.cpp:1405:62 [opt]
    frame #11: 0x000000010065b764 defid`getblockcount(request=<unavailable>) at blockchain.cpp:434:23 [opt]
    frame #12: 0x000000010042dba0 defid`CRPCCommand::CRPCCommand(this=<unavailable>, request=<unavailable>, result=0x00000001702aace0, (null)=<unavailable>)(JSONRPCRequest const&), std::initializer_list<char const*>)::'lambda'(JSONRPCRequest const&, UniValue&, bool)::operator()(JSONRPCRequest const&, UniValue&, bool) const at server.h:109:94 [opt]
    frame #13: 0x00000001006b9a74 defid`CRPCTable::execute(JSONRPCRequest const&) const [inlined] std::__1::__function::__value_func<bool (JSONRPCRequest const&, UniValue&, bool)>::operator()[abi:v160006](this=<unavailable>, __args=0x00000001702aabd0, __args=0x00000001702aace0, __args=0x00000001702aa9c8) const at function.h:510:16 [opt]
    frame #14: 0x00000001006b9a54 defid`CRPCTable::execute(JSONRPCRequest const&) const [inlined] std::__1::function<bool (JSONRPCRequest const&, UniValue&, bool)>::operator()(this=<unavailable>, __arg=0x00000001702aabd0, __arg=0x00000001702aace0, __arg=true) const at function.h:1156:12 [opt]
    frame #15: 0x00000001006b9a54 defid`CRPCTable::execute(JSONRPCRequest const&) const at server.cpp:456:20 [opt]
    frame #16: 0x00000001006b9a54 defid`CRPCTable::execute(this=<unavailable>, request=<unavailable>) const at server.cpp:439:17 [opt]
    frame #17: 0x00000001002928e0 defid`HTTPReq_JSONRPC(req=<unavailable>, (null)=<unavailable>) at httprpc.cpp:225:40 [opt]
    frame #18: 0x000000010029b4dc defid`HTTPWorkItem::operator()() [inlined] std::__1::__function::__value_func<bool (HTTPRequest*, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char>> const&)>::operator()[abi:v160006](this=<unavailable>, __args=0x00000001702aaed0, __args=<unavailable>) const at function.h:510:16 [opt]
    frame #19: 0x000000010029b4cc defid`HTTPWorkItem::operator()() [inlined] std::__1::function<bool (HTTPRequest*, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char>> const&)>::operator()(this=<unavailable>, __arg=0x0000600001ec20e0, __arg=<unavailable>) const at function.h:1156:12 [opt]
    frame #20: 0x000000010029b4cc defid`HTTPWorkItem::operator()(this=<unavailable>) at httpserver.cpp:56:9 [opt]
    frame #21: 0x000000010029c6f4 defid`WorkQueue<HTTPClosure>::Run(this=0x0000600002adc2c0) at httpserver.cpp:115:13 [opt]
    frame #22: 0x0000000100299588 defid`HTTPWorkQueueRun(queue=0x0000600002adc2c0, worker_num=1) at httpserver.cpp:346:12 [opt]
    frame #23: 0x000000010029ccb8 defid`void* std::__1::__thread_proxy[abi:v160006]<std::__1::tuple<std::__1::unique_ptr<std::__1::__thread_struct, std::__1::default_delete<std::__1::__thread_struct>>, void (*)(WorkQueue<HTTPClosure>*, int), WorkQueue<HTTPClosure>*, int>>(void*) [inlined] decltype(std::declval<void (*)(WorkQueue<HTTPClosure>*, int)>()(std::declval<WorkQueue<HTTPClosure>*>(), std::declval<int>())) std::__1::__invoke[abi:v160006]<void (*)(WorkQueue<HTTPClosure>*, int), WorkQueue<HTTPClosure>*, int>(__f=0x0000600001dc4028, __args=0x0000600001dc4030, __args=0x0000600001dc4038) at invoke.h:394:23 [opt]
    frame #24: 0x000000010029ccac defid`void* std::__1::__thread_proxy[abi:v160006]<std::__1::tuple<std::__1::unique_ptr<std::__1::__thread_struct, std::__1::default_delete<std::__1::__thread_struct>>, void (*)(WorkQueue<HTTPClosure>*, int), WorkQueue<HTTPClosure>*, int>>(void*) [inlined] void std::__1::__thread_execute[abi:v160006]<std::__1::unique_ptr<std::__1::__thread_struct, std::__1::default_delete<std::__1::__thread_struct>>, void (*)(WorkQueue<HTTPClosure>*, int), WorkQueue<HTTPClosure>*, int, 2ul, 3ul>(__t=size=4, (null)=<unavailable>) at thread:288:5 [opt]
    frame #25: 0x000000010029ccac defid`void* std::__1::__thread_proxy[abi:v160006]<std::__1::tuple<std::__1::unique_ptr<std::__1::__thread_struct, std::__1::default_delete<std::__1::__thread_struct>>, void (*)(WorkQueue<HTTPClosure>*, int), WorkQueue<HTTPClosure>*, int>>(__vp=0x0000600001dc4020) at thread:299:5 [opt]
    frame #26: 0x000000018b3ce034 libsystem_pthread.dylib`_pthread_start + 136

build was done from latest master:
DeFi Blockchain version v4.0.9.0-master-9bc9dd77d (debug build)

[prasannavl]

Thanks for the super detailed dig in and working with @Bushstar to get to the bottom of this @kuegi. Just taking account of this again, as we're just about ready to bring snapshots back in.

Could I confirm with you that the leaks were fixed after 4.0.x and doesn't occur in the latest 4.1.x?

[kuegi]

Could I confirm with you that the leaks were fixed after 4.0.x and doesn't occur in the latest 4.1.x?

yes, 4.1.0 is running without any issues here.