Node start and stop errors - Algorand
Node start and stop errors
post by cusma on Aug 6, 2020
Hi guys,
recently I started having some issues with my node installed on a Raspberry Pi 4.
I’m running both Main Net and Test Net in parallel. From time to time I lose connection with the Main Net and when I try to restart the node on the Main Net I get the following error:
$ goal node start
Algorand node failed to start: node exited before we could contact it
Moreover, I cannot stop the node:
$ goal node stop
Cannot kill node: operation not permitted
Any idea about what is going on?
post by fabrice on Aug 6, 2020
Can you look at $ALGORAND_DATA/algod-err.log and $ALGORAND_DATA/algod-out.log?
where $ALGORAND_DATA is your data folder, which is /var/lib/algorand by default in case you used the Debian package.
post by cusma on Aug 6, 2020
algod-err.log is empty, maybe because I’ve just restarted the Raspberry Pi.
algod-out.log content:
Logging to: /home/pi/node/data/node.log
Deadlock detection is set to: disabled (Default state is 'disable')
Initializing the Algorand node... Success!
⇨ http server started on 127.0.0.1:8080
Node running and accepting RPC requests over HTTP on port 127.0.0.1:8080. Press Ctrl-C to exit
Once I restart the Raspberry Pi the node starts, but I’m still unable to stop it:
$ goal node stop
Cannot kill node: operation not permitted
post by fabrice on Aug 6, 2020
Most likely the issue is a permission issue.
If you’re using the Debian package, the node is started under the algorand user, rather than your user.
It is best to use systemctl to manage it in that case.
If you want to use the goal command, you need to can use sudo -E -u algorand goal node stop.
post by ryanRfox on Aug 6, 2020
I am also experiencing a deadlock on my MainNet archival node. I built from source and periodically stop/start my nodes. Today I noticed my MainNet node was stopped and both TestNet and BetaNet nodes were operational. No worries, it will catch up, I thought. I built master and stopped the other two nodes. They both restarted fine and are operational (however, those are not archival). The MainNet node produced the following (truncated) node.log file:
{"file":"fetcher.go","function":"github.com/algorand/go-algorand/catchup.(*NetworkFetcher).FetchBlock","level":"info","line":219,"msg":"networkFetcher.FetchBlock: asking client r-si.algorand-mainnet.network:4160 for block 8191384","time":"2020-08-06T18:17:04.733513Z"}
{"file":"fetcher.go","function":"github.com/algorand/go-algorand/catchup.(*NetworkFetcher).FetchBlock","level":"info","line":219,"msg":"networkFetcher.FetchBlock: asking client r-cs.algorand-mainnet.network:4160 for block 8191385","time":"2020-08-06T18:17:05.271563Z"}
{"Context":"Agreement","Hash":"","ObjectPeriod":0,"ObjectRound":0,"ObjectStep":0,"Period":0,"Round":8191369,"Sender":"","Step":0,"Type":"RoundInterrupted","Weight":0,"WeightTotal":0,"file":"demux.go","function":"github.com/algorand/go-algorand/agreement.(*demux).next","level":"info","line":285,"msg":"agreement: round 8191369 ended early due to concurrent write;$
{"file":"fetcher.go","function":"github.com/algorand/go-algorand/catchup.(*NetworkFetcher).FetchBlock","level":"info","line":219,"msg":"networkFetcher.FetchBlock: asking client r-fr.algorand-mainnet.network:4160 for block 8191386","time":"2020-08-06T18:17:05.522169Z"}
{"Context":"Agreement","Hash":"","ObjectPeriod":0,"ObjectRound":0,"ObjectStep":0,"Period":0,"Round":8191370,"Sender":"","Step":0,"Type":"RoundInterrupted","Weight":0,"WeightTotal":0,"file":"demux.go","function":"github.com/algorand/go-algorand/agreement.(*demux).next","level":"info","line":285,"msg":"agreement: round 8191370 ended early due to concurrent write;$
{"file":"fetcher.go","function":"github.com/algorand/go-algorand/catchup.(*NetworkFetcher).FetchBlock","level":"info","line":219,"msg":"networkFetcher.FetchBlock: asking client r13.algorand-mainnet.network:80 for block 8191387","time":"2020-08-06T18:17:05.545599Z"}
{"file":"deadlockLogger.go","function":"github.com/algorand/go-algorand/daemon/algod.(*dumpLogger).dump","level":"error","line":36,"msg":"[Stack] goroutine 66 [running]:\nruntime/debug.Stack(0xc000080820, 0xc000010570, 0xc00a940780)\n\truntime/debug/stack.go:24 +0x9f\ngithub.com/algorand/go-algorand/logging.logger.Error(0xc000080820, 0xc000010570, 0xc00a8cfc70,$
{"file":"deadlockLogger.go","function":"github.com/algorand/go-algorand/daemon/algod.(*dumpLogger).dump","level":"error","line":36,"msg":"POTENTIAL DEADLOCK:\nPrevious place where the lock was grabbed\ngoroutine 86 lock 0xc000259788\ngithub.com/algorand/go-algorand/ledger/ledger.go:333 ledger.(*Ledger).notifyCommit ??? ⟨⟨⟨⟨⟨
github.com$
{"file":"deadlockLogger.go","function":"github.com/algorand/go-algorand/daemon/algod.setupDeadlockLogger.func1","level":"error","line":57,"msg":"[Stack] goroutine 66 [running]:\nruntime/debug.Stack(0xc000080820, 0xc000010570)\n\truntime/debug/stack.go:24 +0x9f\ngithub.com/algorand/go-algorand/logging.logger.Panic(0xc000080820, 0xc000010570, 0xc00a$
post by cusma on Aug 6, 2020
Until now I didn’t need to restart the node, I’m just managing an autonomous start of the node on my Raspberry Pi bootstrap, but I’m experiencing something similar to you: I go out of sync only on the Main Net while Test Net keeps running smoothly.
post by cusma on Aug 7, 2020
It happened again, I lost connection with the MainNet.
Here is the algod-err.log:
runtime: out of memory: cannot allocate 4202496-byte block (2622619648 in use)
fatal error: out of memory
...
post by tsachi on Aug 7, 2020
Hi @cusma,
You have not specified which version you’re running. A new version was released today which reduces the memory utilization. Would you mind trying this one out?
( in this case, it’s more than just a good idea to keep your node updated… )
Also, how much memory is available on your Raspberry PI? The above indicates that 2GB are in use. Is that the case?
post by cusma on Aug 8, 2020
Hi @tsachi,
my node just updated (the process is scheduled through crontab), this is current version:
8589934601
2.0.9.stable [rel/stable] (commit #a7718244)
go-algorand is licensed with AGPLv3.0
source code available at https://github.com/algorand/go-algorand
I run a node on a RaspberryPi 4, it has 4 GB of RAM totally, nothing but the node runs on it (both TestNet and MainNet run in parallel).
The node is currently synchronizing, I’ll show up here in case something goes wrong again.
post by cusma on Aug 17, 2020
Hi, today I lost sync with the MainNet again. I’m running this node version on Raspberry Pi 4 (with 4 GB RAM):
2.0.9.stable [rel/stable] (commit #a7718244)
go-algorand is licensed with AGPLv3.0
source code available at https://github.com/algorand/go-algorand
This is the algod-err.log:
runtime: out of memory: cannot allocate 16384-byte block (2489974784 in use)
fatal error: out of memory
post by tsachi on Aug 17, 2020
Could you please confirm whether prior to the node running out of memory it was able to sync up with mainnet or not ? Is that an archival node, relay node, indexer node or none of the above ?
post by cusma on Aug 17, 2020
Hi @tsachi,
the node is a simple Participation Node (nor Archival, nor Relay, nor Indexer).
From the recently transactions volume growth the node is experimenting an increased Time since last block on the MainNet for some rounds of the protocol. Before the transactions volume growth the Time since last block was always lower than 5 seconds.
I noticed that the node is currently accumulating delay sometime, then it catches up again, so I’m not 100% it was fully synced before the memory error.
post by tsachi on Aug 17, 2020
Hmm. I’m not sure why the node was accumulating delays.
It could be, as you suggested, due to the higher congestion we’ve seen on mainnet.
If that it truly the case, then maybe the upcoming Wednesday release would improve the situation, as it has several performance optimizations.
One other issue that could negatively affect the node performance is slow storage.
On RaspberryPI it’s an SSD card, but I have never tested its relative performance compared to a x86 platform equipped with SSD HDD. I know that some low-end network storage devices, which typically have higher latency, won’t be able to sustain the full block load ( i.e. ~1200 txn/sec).
Last, I suspect that the reason it ran out of memory is that you were running both testnet and mainnet on the device. As mainnet grows in volume, the temporary per-round changes are also growing, which eventually might run out of device space.
post by cusma on Aug 18, 2020
Yes, I was talking to @fabrice about the issue and he suggested exactly the same too! I’m using a SanDisk 64GB Extreme microSDXC UHS-I A2 (Read 4000 IOPS, Write 2000 IOPS) as storage on the Raspberry Pi 4, so roughly 30 MB/s (minimum sequential writing speed).
Yes, the only two processes running in parallel on the Raspberry Pi 4 are the MainNet and TestNet nodes. These are two snapshots of hardware load in different moments:
post by rmb on Aug 19, 2020
I also ran into a similar problem a few days back for the mainnet instance (archival Debian node). It was only a couple of hundred thousand blocks away from being fully sync’d. (I was gutted!)
My first thought was that my ancient machine had just run out of resources to cope with the size of the mainnet. On closer inspection the problem looked more like something was wrong with the Algorand code or configuration.
The symptoms were that the machine became unresponsive to the point that I had to power off the machine to be able to intervene and stop algod immediately after booting up otherwise I would be locked out of the console.
After shifting node.log out of the way and restarting the mainnet instance node.log showed:
Logging Starting
Telemetry Enabled: 54ab6020-52cf-444d-be74-155cc5450220
Session:
++++++++++++++++++++++++++++++++++++++++
{"callee": "github.com/algorand/go-algorand/ledger.(*blockQueue).getBlock.func1","caller":"/root/go/src/github.com/algorand/go-algorand/ledger/blockqueue.go:247","file":"dbutil.go","function":"github.com/algorand/go-algorand/util/db.(*Accessor).Atomic","level":"warning","line":272,"msg":"dbatomic: tx took 4.284393143s","name":"","readonly":true,"time":"2020-08-18T09:33:28.068428+01:00"}
{"callee": "github.com/algorand/go-algorand/ledger.(*blockQueue).getBlock.func1","caller":"/root/go/src/github.com/algorand/go-algorand/ledger/blockqueue.go:247","file":"dbutil.go","function":"github.com/algorand/go-algorand/util/db.(*Accessor).Atomic","level":"warning","line":272,"msg":"dbatomic: tx took 4.86935983s","name":"","readonly":true,"time":"2020-08-18T09:34:35.065294+01:00"}
{"callee": "github.com/algorand/go-algorand/ledger.(*blockQueue).getBlock.func1","caller":"/root/go/src/github.com/algorand/go-algorand/ledger/blockqueue.go:247","file":"dbutil.go","function":"github.com/algorand/go-algorand/util/db.(*Accessor).Atomic","level":"warning","line":272,"msg":"dbatomic: tx took 2.603299742s","name":"","readonly":true,"time":"2020-08-18T09:35:25.537086+01:00"}
I’m currently experimenting with the speed of synchronisation I decided to trash my installation and start again.