User Logs & Feedback for issue 10788 #10907

TippyFlitsUK · 2023-05-22T17:13:44Z

TippyFlitsUK
May 22, 2023
Maintainer

User-provided logs and feedback for issue #10788 in the thread below.

Please also refer to the Slack thread for various @arajasek , @magik6k & @ZenGround0 responses 👍

TippyFlitsUK · 2023-05-22T17:19:17Z

TippyFlitsUK
May 22, 2023
Maintainer Author

@RobQuistNL

1 - #10788 (comment)

Lotus Version

1.23.0

Repro Steps

Run lotus
See chain sync stalls
See it continues after a node restart

Describe the Bug

$ lotus sync wait
Worker: 6975; Base: 2814173; Target: 2814175 (diff: 2)
State: persisting headers; Current Epoch: 2814175; Todo: 0
Validated 0 messages (0 per second)

Logging Information

$ lotus sync status
sync status:
worker 6968:
	Base:	[bafy2bzaceap5w6nqdh2r24vb34o63ooszwop2yoboi7riceasado6su27fheq bafy2bzacedth5orya7dhfmopudnp2keb7jyoo5lv3vmo5m2irsdqprian4f6c bafy2bzacecbu4yp4vea2qkhmi33imcfhf7pqeicso2eog5l7xf52i4ib64r6g]
	Target:	[bafy2bzacedndndgzgey2xdl5utjr5burejp3dlzqlq7ltitn6phyxdcwdkbo4] (2814172)
	Height diff:	1
	Stage: complete
	Height: 2814172
	Elapsed: 944.690545ms
worker 6969:
	Base:	[]
	Target:	[] (0)
	Height diff:	0
	Stage: idle
	Height: 0
worker 6970:
	Base:	[bafy2bzacecxcxaeabjjfbpizsrvbr3dkzmlskt4l6mhd3vhiorevcq5op5lmg bafy2bzacedoldldvzi52tv5a7zzvjjlkrky56m5kix5vaykpmkgx7ap7emex2 bafy2bzacea2u73js2ilfabfyn3etrmzhgwkn2t24ru4at3qfjby3um5lxdwta bafy2bzacedndndgzgey2xdl5utjr5burejp3dlzqlq7ltitn6phyxdcwdkbo4]
	Target:	[bafy2bzacecifdiqvsdw6zfocyy62jh3yqwjmfmjtmcb77yrl3t4e5eyjyslti] (2814173)
	Height diff:	1
	Stage: complete
	Height: 2814173
	Elapsed: 1m8.035874948s
worker 6971:
	Base:	[bafy2bzacecxcxaeabjjfbpizsrvbr3dkzmlskt4l6mhd3vhiorevcq5op5lmg bafy2bzacedoldldvzi52tv5a7zzvjjlkrky56m5kix5vaykpmkgx7ap7emex2 bafy2bzacea2u73js2ilfabfyn3etrmzhgwkn2t24ru4at3qfjby3um5lxdwta bafy2bzacedndndgzgey2xdl5utjr5burejp3dlzqlq7ltitn6phyxdcwdkbo4]
	Target:	[bafy2bzaceck2xp3ebqkmdp475ayfy27h42gc4ill2hlbtz74ircqrs4iykhry] (2814173)
	Height diff:	1
	Stage: message sync
	Height: 2814173
	Elapsed: 6h15m6.049031182s
worker 6972:
	Base:	[bafy2bzacecxcxaeabjjfbpizsrvbr3dkzmlskt4l6mhd3vhiorevcq5op5lmg bafy2bzacedoldldvzi52tv5a7zzvjjlkrky56m5kix5vaykpmkgx7ap7emex2 bafy2bzacea2u73js2ilfabfyn3etrmzhgwkn2t24ru4at3qfjby3um5lxdwta bafy2bzacedndndgzgey2xdl5utjr5burejp3dlzqlq7ltitn6phyxdcwdkbo4]
	Target:	[bafy2bzacecbaeyedm6ptysy33siqyvopes4zkzupjw4eh5g6tbegc53qfpi3w] (2814173)
	Height diff:	1
	Stage: message sync
	Height: 2814173
	Elapsed: 6h15m5.444462795s
worker 6973:
	Base:	[bafy2bzacecxcxaeabjjfbpizsrvbr3dkzmlskt4l6mhd3vhiorevcq5op5lmg bafy2bzacedoldldvzi52tv5a7zzvjjlkrky56m5kix5vaykpmkgx7ap7emex2 bafy2bzacea2u73js2ilfabfyn3etrmzhgwkn2t24ru4at3qfjby3um5lxdwta bafy2bzacedndndgzgey2xdl5utjr5burejp3dlzqlq7ltitn6phyxdcwdkbo4]
	Target:	[bafy2bzaceaxcyvk7dqlaikmx3nqkyk2c23hytamiukrdo3h5ivjqsvw2jodui] (2814173)
	Height diff:	1
	Stage: message sync
	Height: 2814173
	Elapsed: 6h15m5.309139366s
worker 6974:
	Base:	[bafy2bzacecxcxaeabjjfbpizsrvbr3dkzmlskt4l6mhd3vhiorevcq5op5lmg bafy2bzacedoldldvzi52tv5a7zzvjjlkrky56m5kix5vaykpmkgx7ap7emex2 bafy2bzacea2u73js2ilfabfyn3etrmzhgwkn2t24ru4at3qfjby3um5lxdwta bafy2bzacedndndgzgey2xdl5utjr5burejp3dlzqlq7ltitn6phyxdcwdkbo4]
	Target:	[bafy2bzaceddlz7l354dszfxtgjo76oy2xgkejewifrsnv5haua7h2m25zov2w] (2814173)
	Height diff:	1
	Stage: message sync
	Height: 2814173
	Elapsed: 6h15m4.082616156s
worker 6975:
	Base:	[bafy2bzacecifdiqvsdw6zfocyy62jh3yqwjmfmjtmcb77yrl3t4e5eyjyslti]
	Target:	[bafy2bzaceb3fx6swzg4lrgfrrytavano5xohsw4ophcxspopjstvpzovpeegi] (2814175)
	Height diff:	2
	Stage: persisting headers
	Height: 2814175
	Elapsed: 6h13m57.909469884s

2 - #10788 (comment)

Just happened again, looks like the last block sync happened 12:56. ( I see no "New heaviest tipset" in the logs after that)

Here's a bunch of logs;
Rob.txt

1 reply

TippyFlitsUK May 22, 2023
Maintainer Author

@RobQuistNL

Slack Posts - https://filecoinproject.slack.com/archives/CP50PPW2X/p1682716335088099

1

For the heck of it (Its not a solution but might be a workaround) - can you try importing a snapshot Nathanial? I've done that on a node that showed these problems but they seem to have disappeared after importing the snapshot. Might be because the GC won't not triggered for a while now..

Please note that the snapshots now are a lot smaller and they import way faster (also the block sync catchup is like 10x faster now, this cron change thing was heavy)

Magik quite sure its not net peers / connectivity - those are always healthy for me (meaning over 100), and killing the daemon process takes a lot of time, without any logs, so it does look like there's some stray routine or infinite loop somewhere

the daemon itself (on an API level) is also unreachable (basically what Casey is stating)

2

I do suspect its splitstore GC stuff yeah

3

Responding to a question regarding systemd memory limitations

I don't have those memory limitations and when it "froze" I didn't see anything out of the ordinary in memory usage

TippyFlitsUK · 2023-05-22T17:43:01Z

TippyFlitsUK
May 22, 2023
Maintainer Author

@marshyonline

1 - #10788 (comment)

See: https://filecoinproject.slack.com/archives/CP50PPW2X/p1682716335088099
Ive dumped logs and such here - this looks to be the same issue.

Out of 8 nodes - 3 keep getting stuck like this every few hours and require a reboot to get back into sync.

1 reply

TippyFlitsUK May 22, 2023
Maintainer Author

@marshyonline

Slack Posts - https://filecoinproject.slack.com/archives/CP50PPW2X/p1682716335088099

1

I copped this on 3 of our servers - Daemon went out of sync and lotus was not running the usual "completed mineOne"
Restarted all the things and synced back up no issues.

2

Here we go again

DOWNLOAD LINKS - goroutines.txt, peers.txt, scores.tx, daemon.log

3

3 More overnight 😞

4

Yeah Im seeing this more and more on a set of our daemon's - strangely enough not all of them tho

5

24hour snapshot

6

I had one (snapshot) re-imported lastnight and its no longer droping out of sync - but i am of the same mind thats its due to GC not running so its only 1 or two days away from tiggering again
All out daemon's have the same configs - so its weird that some are doing it and not all of them

7

Since I reimported a node I have not seen it again on that daemon
But in saying that, since I moved a miner away from another a different dameon it hasn't poped again either - today has been quite on this front :thinking_face:

8

Did this magicly go away for anyone else?

TippyFlitsUK · 2023-05-22T18:19:34Z

TippyFlitsUK
May 22, 2023
Maintainer Author

@scaseye

1 - #10788 (comment)

my lotus goes more than 5 epochs out of sync ~4 hours... most recent out of sync was 825am this morning. daemon log for 8am-9am is attached. also attaching 2 more logs for the prior to hour windows where lotus fell out of sync today.

prior to the 1.23.0 upgrade i was running splitstore without issue for over a month.

[Chainstore]
  EnableSplitstore = true

[Chainstore.Splitstore]
    ColdStoreType = "discard"
    HotStoreFullGCFrequency = 10

LOTUS_FVM_CONCURRENCY=24
LOTUS_SKIP_APPLY_TS_MESSAGE_CALL_WITH_GAS=1

Daemon:  1.23.0+mainnet+git.d1d4b35ad+api1.5.0
go version go1.20.3 linux/amd64

8am-daemon.txt
4am-daemon.txt
1am-daemon.txt

2 - #10788 (comment)

here are more logs pmap and -QUIT on the daemon
sig.txt
daemon-quit.txt
pmap-daemon-outpfsync.txt
pmap-daemon-running.txt

3 - #10788 (comment)

i also run my daemon service file with these set

MemoryAccounting=true
MemoryHigh=112G
MemoryMax=128G
LimitNOFILE=18192:102140

4 - #10788 (comment)

build settings

PATH="$PATH:/etc/alternatives/cuda/bin"
LD_LIBRARY_PATH="/etc/alternatives/cuda/lib64"
CUDA_HOME="/etc/alternatives/cuda"
RUSTFLAGS="-C target-cpu=native -g"
FFI_BUILD_FROM_SOURCE=1
FFI_USE_CUDA=1
RUST_GPU_TOOLS_CUSTOM_GPU="NVIDIA RTX A6000:10752"
RUST_BACKTRACE=full
RUST_LOG=info
FIL_PROOFS_USE_GPU_COLUMN_BUILDER=1
FIL_PROOFS_USE_GPU_TREE_BUILDER=1
FIL_PROOFS_MAXIMIZE_CACHING=1
FIL_PROOFS_USE_MULTICORE_SDR=1
FIL_PROOFS_VERIFY_CACHE=1

5 - #10788 (comment)

my last sync issue was May 3rd 12:20am pst. since then no issues. it is as if something changed on the network. as i have not changed anything on my node. been in sync since restarting lotus daemon at that time.

6 - #10788 (comment)

my current daemon systemd setup

[Unit]
Description=Lotus Daemon
After=network-online.target
Requires=network-online.target

[Service]
Environment=GOLOG_FILE='/home/scaseye/logs/daemon.log'
Environment=GOLOG_LOG_FMT='json'
EnvironmentFile=/home/scaseye/env/common.env
ExecStart=/usr/local/bin/lotus daemon
Restart=always
RestartSec=10
User=scaseye
Group=scaseye

#MemoryAccounting=true
#MemoryHigh=350G
#MemoryMax=384G
LimitNOFILE=18192:102140

#MemoryHigh=8G
#MemoryMax=10G
#LimitNOFILE=8192:10240
#LimitNOFILE=32000000:128000000

[Install]
WantedBy=multi-user.target

# common.env
# TOKENS
FULLNODE_API_INFO=ey...:/ip4/40.0.0.199/tcp/1234/http
MINER_API_INFO=...:/ip4/40.0.0.199/tcp/2345/http
MARKETS_API_INFO=...8:/ip4/40.0.0.199/tcp/8787/http
BOOST_API_INFO=...:/ip4/40.0.0.199/tcp/8787/http
#PATH
LOTUS_MARKETS_PATH=/data/mainnet32GiB/.boost
BOOST_PATH=/data/mainnet32GiB/.boost
LOTUS_MINER_PATH=/filecoin/mainnet32GiB/.lotusminer
LOTUS_PATH=/filecoin/mainnet32GiB/.lotus
FIL_PROOFS_PARAMETER_CACHE=/home/scaseye/.lotusproofs
FIL_PROOFS_PARENT_CACHE=/home/scaseye/.lotusproofs
LOTUS_BACKUP_BASE_PATH=/filecoin/mainnet32GiB/.lotusbackup
TMPDIR=/filecoin/mainnet32GiB/.lotustmpgpu
#Config/build/Performance
RUST_BACKTRACE=full
RUST_LOG=info
#LOTUS_FVM_CONCURRENCY=24
#LOTUS_SKIP_APPLY_TS_MESSAGE_CALL_WITH_GAS=1

7 - #10788 (comment)

yes on splitstore.

8 - #10788 (comment)

i already posted my working systemd config. would be interesting to see Stus non systemd settings and compare

2 replies

TippyFlitsUK May 22, 2023
Maintainer Author

@scaseye

Slack Posts - https://filecoinproject.slack.com/archives/CP50PPW2X/p1682716335088099

1

Posted 28th of April 2023

right at 1137am pst is when my lotus locked up. roughly when i saw a ton of those ignoring indexer messages

2

Just happened to me again

lotus locks up so the lotus status cmd just hangs

after this message all boost graphsync, bitswap activity stop.

{"level":"warn","ts":"2023-04-29T03:41:36.060-0700","logger":"chainxchg","caller":"exchange/client.go:118","msg":"could not send request to peer 12D3KooWMuPPsq8iym4TPNwz5eNyyBPaE6fczz9rNqYkJL7APky5: failed to read chainxchg response: i/o deadline reached"}

basically after that message lotus is offline.

logs for the hour it happened. i have noticed the sectors being reloaded?? usually only happens on startup.
2023-04-29T03:41:36.060-0700
3am-f01611097.txt

3

lotus is running but very little cpu 10-15%.

boost in the past had not impacted lotus... this is pretty major problem, its one thing to have boost lock up, but to have lotus lock up. too take the SP completely offline. i know im stating the obvious but just need to make clear the severity.

why with out a restart is the miner redeclaring sector storage??

4

yeah happend to me again, missed 2 posts. going into maintence mode till further notice

lotus responds but lotus-miner does not

$ lotus status
Sync Epoch: 2816590
Epochs Behind: 184
Peers to Publish Messages: 163
Peers to Publish Blocks: 164

lotus-miner cli cmds just hang no response

5

happens every 4 hours

6

seems not related to boost

so kept running boost

i have been running split store for a long time, was working perfect for me prior to 1.23... do i need to change any of these?

[Chainstore]
  EnableSplitstore = true

[Chainstore.Splitstore]
    ColdStoreType = "discard"
    HotStoreFullGCFrequency = 10

7

LOTUS_FVM_CONCURRENCY=24
LOTUS_SKIP_APPLY_TS_MESSAGE_CALL_WITH_GAS=1

has anyone tried running without the LOTUS_SKIP_APPLY_TS_MESSAGE_CALL_WITH_GAS set?

8

i changed
HotStoreFullGCFrequency = 20
and took these out

LOTUS_FVM_CONCURRENCY=24
LOTUS_SKIP_APPLY_TS_MESSAGE_CALL_WITH_GAS=1

same thing every ~4 hours it falls behind

will do a -3 in ~60 mins.

sig.txt

9

do these service settings need to be updated for lotus daemon?

MemoryAccounting=true
MemoryHigh=112G
MemoryMax=128G
LimitNOFILE=18192:102140

10

kill -3 gave me no output...

11

here is pmap before and after the event.
pmap-daemon-outpfsync.txt
pmap-daemon-running.txt

here is quit output
daemon-quit.txt

12

so either something is different on the network or changing these settings in my service file had the effect. daemon running on hour 7... prior would not make it past 3 hours.

#MemoryAccounting=true
#MemoryHigh=350G
#MemoryMax=384G

by changing i mean disabling

this is what top showed for lotus prior to the memory setting changes.

i think it was trying to GC every 3 hours....
either it got lucky and completed or those settings not been set helped. here is lotus this morning.

13

so without the systemd memory settings the hot gc completed. basically i think every 3 hours it was trying to do a hot gc but was locking up....
removed the settings, and ~3 hours after restarting the service the hot GC completed.

{"level":"info","ts":"2023-05-03T03:19:59.226-0700","logger":"badgerbs","caller":"v2@v2.2007.4/levels.go:1010","msg":"[Compactor: 1] Compaction for level: 2 DONE"}
{"level":"info","ts":"2023-05-03T03:20:00.357-0700","logger":"bs:sess","caller":"session/session.go:460","msg":"No peers - broadcasting","session":37,"want-count":52}
{"level":"info","ts":"2023-05-03T03:20:00.358-0700","logger":"bs:sess","caller":"session/session.go:460","msg":"No peers - broadcasting","session":39,"want-count":62}
{"level":"info","ts":"2023-05-03T03:20:00.358-0700","logger":"bs:sess","caller":"session/session.go:460","msg":"No peers - broadcasting","session":38,"want-count":57}
{"level":"warn","ts":"2023-05-03T03:20:03.213-0700","logger":"splitstore","caller":"splitstore/splitstore_compact.go:255","msg":"missing object reference bafy2bzacebtjvp7ohsatxxywopv2hdnpgkpgz4ktnkguragtoi4yocfy4ftdw in bafy2bzacecprzjm2auendih5folowy4adgzki63ekegabbkwsssn73ad77wjw"}
{"level":"warn","ts":"2023-05-03T03:20:03.213-0700","logger":"splitstore","caller":"splitstore/splitstore_compact.go:255","msg":"missing object reference bafy2bzacea5s45gf65htmytsjgjr4qhuyyhh2ssf43qrx2snvmvgzp5su7vdw in bafy2bzacecprzjm2auendih5folowy4adgzki63ekegabbkwsssn73ad77wjw"}
{"level":"warn","ts":"2023-05-03T03:20:03.380-0700","logger":"splitstore","caller":"splitstore/splitstore_compact.go:255","msg":"missing object reference bafy2bzacebtjvp7ohsatxxywopv2hdnpgkpgz4ktnkguragtoi4yocfy4ftdw in bafy2bzaceakecfddcl52ghzep5or4tcbdsggfk2djm32sx7aulst4zt4qfvsu"}
{"level":"warn","ts":"2023-05-03T03:20:03.380-0700","logger":"splitstore","caller":"splitstore/splitstore_compact.go:255","msg":"missing object reference bafy2bzacea5s45gf65htmytsjgjr4qhuyyhh2ssf43qrx2snvmvgzp5su7vdw in bafy2bzaceakecfddcl52ghzep5or4tcbdsggfk2djm32sx7aulst4zt4qfvsu"}
{"level":"warn","ts":"2023-05-03T03:20:03.551-0700","logger":"sub","caller":"sub/incoming.go:95","msg":"Slow msg fetch","cid":"bafy2bzacecxtu7mbn5z43vczlhnx2plsczk3ikm7e5jvuvsgczf7edrywzrry","source":"12D3KooWBo6f5riG1MDEbPr1prpMWiToWEZxLDFXw5cjcUhjMFBS","msgfetch":3.194764833}
{"level":"warn","ts":"2023-05-03T03:20:03.885-0700","logger":"splitstore","caller":"splitstore/splitstore_compact.go:255","msg":"missing object reference bafy2bzacebtjvp7ohsatxxywopv2hdnpgkpgz4ktnkguragtoi4yocfy4ftdw in bafy2bzacecxtu7mbn5z43vczlhnx2plsczk3ikm7e5jvuvsgczf7edrywzrry"}
{"level":"warn","ts":"2023-05-03T03:20:03.885-0700","logger":"splitstore","caller":"splitstore/splitstore_compact.go:255","msg":"missing object reference bafy2bzacea5s45gf65htmytsjgjr4qhuyyhh2ssf43qrx2snvmvgzp5su7vdw in bafy2bzacecxtu7mbn5z43vczlhnx2plsczk3ikm7e5jvuvsgczf7edrywzrry"}
{"level":"info","ts":"2023-05-03T03:20:06.323-0700","logger":"badgerbs","caller":"v2@v2.2007.4/levels.go:1000","msg":"[Compactor: 1] Running compaction: {level:2 score:1.0011577062308787 dropPrefixes:[]} for level: 2\n"}
{"level":"info","ts":"2023-05-03T03:20:06.456-0700","logger":"consensus-common","caller":"consensus/compute_state.go:300","msg":"ApplyBlocks stats","early":0.00000576,"earlyCronGas":0,"vmMsg":26.302627038,"msgGas":7601901045,"vmCron":65.201544922,"cronGas":25580863589,"vmFlush":1.873085965,"epoch":"2826757","tsk":
"{bafy2bzacea22vjhkkmbbt2rxkd6lq4d446mnvwoynj6u3gf64vegmavow6jdu}"}
{"level":"info","ts":"2023-05-03T03:20:06.564-0700","logger":"badgerbs","caller":"v2@v2.2007.4/levels.go:962","msg":"LOG Compact 1->2, del 27 tables, add 27 tables, took 8.589151379s\n"}
{"level":"info","ts":"2023-05-03T03:20:06.564-0700","logger":"badgerbs","caller":"v2@v2.2007.4/levels.go:1010","msg":"[Compactor: 0] Compaction for level: 1 DONE"}
{"level":"info","ts":"2023-05-03T03:20:07.421-0700","logger":"badgerbs","caller":"v2@v2.2007.4/db.go:1027","msg":"Storing value log head: {Fid:1038 Len:35 Offset:7780896}\n"}
{"level":"info","ts":"2023-05-03T03:20:08.034-0700","logger":"badgerbs","caller":"v2@v2.2007.4/levels.go:962","msg":"LOG Compact 2->3, del 6 tables, add 5 tables, took 1.71102995s\n"}
{"level":"info","ts":"2023-05-03T03:20:08.034-0700","logger":"badgerbs","caller":"v2@v2.2007.4/levels.go:1010","msg":"[Compactor: 1] Compaction for level: 2 DONE"}
{"level":"info","ts":"2023-05-03T03:20:11.624-0700","logger":"splitstore","caller":"splitstore/splitstore_compact.go:1358","msg":"purged cold objects","purged":10175949,"live":26}
{"level":"info","ts":"2023-05-03T03:20:11.624-0700","logger":"splitstore","caller":"splitstore/splitstore_compact.go:814","msg":"purging cold objects from hotstore done","took":101.42339793}
{"level":"info","ts":"2023-05-03T03:20:11.624-0700","logger":"splitstore","caller":"splitstore/splitstore_compact.go:950","msg":"ending critical section"}
{"level":"info","ts":"2023-05-03T03:20:11.624-0700","logger":"splitstore","caller":"splitstore/splitstore_compact.go:816","msg":"critical section done","total protected size":1937293891,"total marked live size":8617974}
{"level":"info","ts":"2023-05-03T03:20:11.632-0700","logger":"splitstore","caller":"splitstore/splitstore_gc.go:48","msg":"measured hot store size: 841591311386, approximate new size: 95432340268, should do full true, can do full false"}
{"level":"warn","ts":"2023-05-03T03:20:11.632-0700","logger":"splitstore","caller":"splitstore/splitstore_gc.go:54","msg":"Attention! Estimated moving GC size 95432340268 is not within safety buffer 50000000000 of target max 650000000000, performing aggressive online GC to attempt to bring hotstore size down safel
y"}
{"level":"warn","ts":"2023-05-03T03:20:11.632-0700","logger":"splitstore","caller":"splitstore/splitstore_gc.go:55","msg":"If problem continues you can 1) temporarily allocate more disk space to hotstore and 2) reflect in HotstoreMaxSpaceTarget OR trigger manual move with `lotus chain prune hot-moving`"}
{"level":"warn","ts":"2023-05-03T03:20:11.632-0700","logger":"splitstore","caller":"splitstore/splitstore_gc.go:56","msg":"If problem continues and you do not have any more disk space you can run continue to manually trigger online GC at aggressive thresholds (< 0.01) with `lotus chain prune hot`"}
{"level":"info","ts":"2023-05-03T03:20:11.632-0700","logger":"splitstore","caller":"splitstore/splitstore_gc.go:72","msg":"garbage collecting blockstore"}

14

my daemon never made it to this prior to the memory setting change.

$ grep "ending critical section" logs/daemon.log 
{"level":"info","ts":"2023-05-03T03:20:11.624-0700","logger":"splitstore","caller":"splitstore/splitstore_compact.go:950","msg":"ending critical section"}

15

Have to ride out the sync by restarting… something on the network eventually clears and it goes away magically

magik6k May 22, 2023
Maintainer

I see a bunch of goroutines blocked on splitstore, including the syncer

May 02 08:50:29 homemate-server01 lotus[1986322]: goroutine 313 [select, 9 minutes]:
May 02 08:50:29 homemate-server01 lotus[1986322]: runtime.gopark(0xc12a1ebf90?, 0x2?, 0x90?, 0xbe?, 0xc12a1ebf54?)
May 02 08:50:29 homemate-server01 lotus[1986322]:         /usr/local/go/src/runtime/proc.go:381 +0xd6 fp=0xc12a1ebdb8 sp=0xc12a1ebd98 pc=0x7d1976
May 02 08:50:29 homemate-server01 lotus[1986322]: runtime.selectgo(0xc12a1ebf90, 0xc12a1ebf50, 0x0?, 0x0, 0x0?, 0x1)
May 02 08:50:29 homemate-server01 lotus[1986322]:         /usr/local/go/src/runtime/select.go:327 +0x7be fp=0xc12a1ebef8 sp=0xc12a1ebdb8 pc=0x7e1c3e
May 02 08:50:29 homemate-server01 lotus[1986322]: github.com/ipfs/go-ds-badger2.(*Datastore).periodicGC(0xc00294d980)
May 02 08:50:29 homemate-server01 lotus[1986322]:         /home/scaseye/go/pkg/mod/github.com/ipfs/go-ds-badger2@v0.1.3/datastore.go:241 +0xe5 fp=0xc12a1ebfc8 sp=0xc12a1ebef8 pc=0x18a5fa5
May 02 08:50:29 homemate-server01 lotus[1986322]: github.com/ipfs/go-ds-badger2.NewDatastore.func3()
May 02 08:50:29 homemate-server01 lotus[1986322]:         /home/scaseye/go/pkg/mod/github.com/ipfs/go-ds-badger2@v0.1.3/datastore.go:229 +0x26 fp=0xc12a1ebfe0 sp=0xc12a1ebfc8 pc=0x18a5e46
May 02 08:50:29 homemate-server01 lotus[1986322]: runtime.goexit()
May 02 08:50:29 homemate-server01 lotus[1986322]:         /usr/local/go/src/runtime/asm_amd64.s:1598 +0x1 fp=0xc12a1ebfe8 sp=0xc12a1ebfe0 pc=0x8061a1
May 02 08:50:29 homemate-server01 lotus[1986322]: created by github.com/ipfs/go-ds-badger2.NewDatastore
May 02 08:50:29 homemate-server01 lotus[1986322]:         /home/scaseye/go/pkg/mod/github.com/ipfs/go-ds-badger2@v0.1.3/datastore.go:229 +0x5f0
May 02 08:50:29 homemate-server01 lotus[1986322]: goroutine 154040485 [sync.RWMutex.RLock, 4 minutes]:
May 02 08:50:29 homemate-server01 lotus[1986322]: runtime.gopark(0x0?, 0x0?, 0x68?, 0x5?, 0xc12c9905e0?)
May 02 08:50:29 homemate-server01 lotus[1986322]:         /usr/local/go/src/runtime/proc.go:381 +0xd6 fp=0xc12c990510 sp=0xc12c9904f0 pc=0x7d1976
May 02 08:50:29 homemate-server01 lotus[1986322]: runtime.goparkunlock(...)
May 02 08:50:29 homemate-server01 lotus[1986322]:         /usr/local/go/src/runtime/proc.go:387
May 02 08:50:29 homemate-server01 lotus[1986322]: runtime.semacquire1(0xc00182e41c, 0x20?, 0x3, 0x0, 0x0?)
May 02 08:50:29 homemate-server01 lotus[1986322]:         /usr/local/go/src/runtime/sema.go:160 +0x20f fp=0xc12c990578 sp=0xc12c990510 pc=0x7e2d2f
May 02 08:50:29 homemate-server01 lotus[1986322]: sync.runtime_SemacquireRWMutexR(0xc1344b0900?, 0x0?, 0xc12c9905d0?)
May 02 08:50:29 homemate-server01 lotus[1986322]:         /usr/local/go/src/runtime/sema.go:82 +0x26 fp=0xc12c9905b0 sp=0xc12c990578 pc=0x801ce6
May 02 08:50:29 homemate-server01 lotus[1986322]: sync.(*RWMutex).RLock(...)
May 02 08:50:29 homemate-server01 lotus[1986322]:         /usr/local/go/src/sync/rwmutex.go:71
May 02 08:50:29 homemate-server01 lotus[1986322]: github.com/filecoin-project/lotus/blockstore/splitstore.(*SplitStore).View(0xc00182e2c0, {0x72a4630, 0xc000054058}, {{0xc1344b0900?, 0x0?}}, 0xc116b93320)
May 02 08:50:29 homemate-server01 lotus[1986322]:         /home/scaseye/lotus/blockstore/splitstore/splitstore.go:634 +0xb7 fp=0xc12c990680 sp=0xc12c9905b0 pc=0x2735bb7
May 02 08:50:29 homemate-server01 lotus[1986322]: github.com/filecoin-project/lotus/chain/store.(*ChainStore).GetBlock(0xc001094000, {0x72a4630, 0xc000054058}, {{0xc1344b0900?, 0xc00980a400?}})
May 02 08:50:29 homemate-server01 lotus[1986322]:         /home/scaseye/lotus/chain/store/store.go:813 +0xb3 fp=0xc12c9906d8 sp=0xc12c990680 pc=0x1756f73
May 02 08:50:29 homemate-server01 lotus[1986322]: github.com/filecoin-project/lotus/chain/store.(*ChainStore).LoadTipSet.func1()
May 02 08:50:29 homemate-server01 lotus[1986322]:         /home/scaseye/lotus/chain/store/store.go:832 +0x65 fp=0xc12c990778 sp=0xc12c9906d8 pc=0x17573c5
May 02 08:50:29 homemate-server01 lotus[1986322]: golang.org/x/sync/errgroup.(*Group).Go.func1()
May 02 08:50:29 homemate-server01 lotus[1986322]:         /home/scaseye/go/pkg/mod/golang.org/x/sync@v0.1.0/errgroup/errgroup.go:75 +0x64 fp=0xc12c9907e0 sp=0xc12c990778 pc=0x159eb04
May 02 08:50:29 homemate-server01 lotus[1986322]: runtime.goexit()
May 02 08:50:29 homemate-server01 lotus[1986322]:         /usr/local/go/src/runtime/asm_amd64.s:1598 +0x1 fp=0xc12c9907e8 sp=0xc12c9907e0 pc=0x8061a1
May 02 08:50:29 homemate-server01 lotus[1986322]: created by golang.org/x/sync/errgroup.(*Group).Go
May 02 08:50:29 homemate-server01 lotus[1986322]:         /home/scaseye/go/pkg/mod/golang.org/x/sync@v0.1.0/errgroup/errgroup.go:72 +0xa5

Interestingly I see no references to anything in splitstore that could be holding the lock

TippyFlitsUK · 2023-05-22T19:15:29Z

TippyFlitsUK
May 22, 2023
Maintainer Author

@marco-storswift

1 - #10788 (comment)

#10791 , the same case

2 - #10788 (comment)

I found a special case, the chain sync block eight minutes

2023-05-06T00:40:13.198+0800 INFO consensus-common consensus/compute_state.go:301 ApplyBlocks stats {"early": 0.00000629, "earlyCronGas": 0, "vmMsg": 1.014845014, "msgGas": 13057662339, "vmCron": 0.889802878, "cronGas": 28795930927, "vmFlush": 0.130945503, "epoch": "2833277", "tsk": "{bafy2bzaceaytfjispquthorrvyrrezpi6r4cnuhk4dn5id7ey3mjbiyuzimsq,bafy2bzacebkty5ini2ujmdchrxuw2ygbd6pw6ou2puiq5ve245s3yfsyhg4lo,bafy2bzacecgoeiontx6w2sczrr335oxxjn2pkb734kmlhewqenjwfswxrodtw,bafy2bzacedc7ji5tulz2qlnxesusxmu2svf7htd37bxnaftfrl7cabeiualpy,bafy2bzaceb6ssk4sj7llkoj2jwh7f35jtu5vk7eiddhkpa7aomsu2qztrvi4m}"}
2023-05-06T00:42:00.260+0800 DEBUG chainxchg exchange/server.go:48 block sync request {"start": [{"/":"bafy2bzacedrowhcb3o3t4pwlr5uyy42t4hrb2gcpc46bm6wopijahimdzte2y"},{"/":"bafy2bzacecezpcor2govssd3dri7lbnsi6pksmwhgxhuiisw2epxno4ujsiys"},{"/":"bafy2bzacebz5kemektyq4g5hqvqw7grj2o2x5dqqogb2vmzlwim5vtyn645vo"},{"/":"bafy2bzaceburiwzkpc7u3n4dwf7ee6xwfsqjhmtx2lvc2ciihwfqablr5277u"}], "len": 1}
2023-05-06T00:42:00.261+0800 WARN chainxchg exchange/server.go:140 block sync request: collectChainSegment failed: failed loading tipset {bafy2bzacedrowhcb3o3t4pwlr5uyy42t4hrb2gcpc46bm6wopijahimdzte2y,bafy2bzacecezpcor2govssd3dri7lbnsi6pksmwhgxhuiisw2epxno4ujsiys,bafy2bzacebz5kemektyq4g5hqvqw7grj2o2x5dqqogb2vmzlwim5vtyn645vo,bafy2bzaceburiwzkpc7u3n4dwf7ee6xwfsqjhmtx2lvc2ciihwfqablr5277u}: get block bafy2bzaceburiwzkpc7u3n4dwf7ee6xwfsqjhmtx2lvc2ciihwfqablr5277u: ipld: could not find bafy2bzaceburiwzkpc7u3n4dwf7ee6xwfsqjhmtx2lvc2ciihwfqablr5277u
2023-05-06T00:46:00.092+0800 DEBUG chainxchg exchange/server.go:48 block sync request {"start": [{"/":"bafy2bzaceal7xaicsbx5cygnybhvnmlbrbzbbukxffgoyh3ekibpethluzmqy"},{"/":"bafy2bzaceachj77t2qgst6ctnrxn5efrmb4sjs4ejq5aqucpi47mcgbgfxfna"}], "len": 1}
2023-05-06T00:46:00.093+0800 WARN chainxchg exchange/server.go:140 block sync request: collectChainSegment failed: failed loading tipset {bafy2bzaceal7xaicsbx5cygnybhvnmlbrbzbbukxffgoyh3ekibpethluzmqy,bafy2bzaceachj77t2qgst6ctnrxn5efrmb4sjs4ejq5aqucpi47mcgbgfxfna}: get block bafy2bzaceachj77t2qgst6ctnrxn5efrmb4sjs4ejq5aqucpi47mcgbgfxfna: ipld: could not find bafy2bzaceachj77t2qgst6ctnrxn5efrmb4sjs4ejq5aqucpi47mcgbgfxfna
2023-05-06T00:48:56.670+0800 DEBUG hello hello/hello.go:155 Sending hello message: [bafy2bzaceaytfjispquthorrvyrrezpi6r4cnuhk4dn5id7ey3mjbiyuzimsq bafy2bzacebkty5ini2ujmdchrxuw2ygbd6pw6ou2puiq5ve245s3yfsyhg4lo bafy2bzacecgoeiontx6w2sczrr335oxxjn2pkb734kmlhewqenjwfswxrodtw bafy2bzacedc7ji5tulz2qlnxesusxmu2svf7htd37bxnaftfrl7cabeiualpy bafy2bzaceb6ssk4sj7llkoj2jwh7f35jtu5vk7eiddhkpa7aomsu2qztrvi4m] 2833277 bafy2bzacecnamqgqmifpluoeldx7zzglxcljo6oja4vrmtj7432rphldpdmm2
2023-05-06T00:48:56.670+0800 DEBUG hello hello/hello.go:80 genesis from hello {"tipset": [{"/":"bafy2bzaceascirtzzmxpm3vnu3kx25brpkopx7m3e66nvsi5xh4agcy5gb7su"},{"/":"bafy2bzaceairq74gavlnhzoo647f7p6egpyzxvk2nn37ny3mbajq7j36q7fru"},{"/":"bafy2bzacecey6jkecuhjh4bkwpc235neluag7ldkroattqpgdzpfilzcmip6g"},{"/":"bafy2bzaceb2v2za7xxo5gw2vzqtqwmkvh53tkmaeb45fby25awbtsuo5zriem"},{"/":"bafy2bzacebzlqfdgwpwl7nqtw5lmpmfr3qra5sr4eaidtzag523wlg3pi377e"},{"/":"bafy2bzaced2tzvtruommun5klbhz5lzaspkkkifrx4qwgguqs2vvm5iwdcrso"}], "peer": "12D3KooWBL1W2LCPfTWVYyDejMLvDPgooNDRT2VkcS1bCNWLBkS4", "hash": "bafy2bzacecnamqgqmifpluoeldx7zzglxcljo6oja4vrmtj7432rphldpdmm2"}
2023-05-06T00:48:56.699+0800 DEBUG hello hello/hello.go:127 Got new tipset through Hello: [bafy2bzaceascirtzzmxpm3vnu3kx25brpkopx7m3e66nvsi5xh4agcy5gb7su bafy2bzaceairq74gavlnhzoo647f7p6egpyzxvk2nn37ny3mbajq7j36q7fru bafy2bzacecey6jkecuhjh4bkwpc235neluag7ldkroattqpgdzpfilzcmip6g bafy2bzaceb2v2za7xxo5gw2vzqtqwmkvh53tkmaeb45fby25awbtsuo5zriem bafy2bzacebzlqfdgwpwl7nqtw5lmpmfr3qra5sr4eaidtzag523wlg3pi377e bafy2bzaced2tzvtruommun5klbhz5lzaspkkkifrx4qwgguqs2vvm5iwdcrso] from 12D3KooWBL1W2LCPfTWVYyDejMLvDPgooNDRT2VkcS1bCNWLBkS4
2023-05-06T00:48:56.721+0800 DEBUG chain chain/sync_manager.go:199 new peer head:

3 - #10788 (comment)

Having looked into this in some depth, I feel confident saying this is not a sync bug. That likely means that the cause is "lower" level (perhaps in the blockstore).

@ZenGround0 and I did a deep dive on the splitstore's locks, and have some concerns, but no concrete bug identified.

Question to reporters: Have all of you been running splitstore when you ran into this? Do we have any reports on such a problem NOT running splitstore?
I agree with you, it may be libp2p peers very few, when I meet this isssue. lotus net peers | wc -l it just 50

4 - #10788 (comment)

goroutines.zip
@arajasek this is lotus pprof goroutines log file

0 replies

TippyFlitsUK · 2023-05-22T19:22:41Z

TippyFlitsUK
May 22, 2023
Maintainer Author

@Trevor-K-Smith

1 - #10788 (comment)

My configuration is identical to that in Scaseye, including the Lotus version, Go version, and overall settings. There isn't much more to mention, aside from persistent issues that are causing significant damage.

I have attempted adjusting the settings using various configurations, but none have led to a stable fast Lotus. It syncs quickly, then gets stuck, and after restarting, the cycle repeats. This is quite unstable compared to earlier versions.

0 replies

TippyFlitsUK · 2023-05-22T19:30:52Z

TippyFlitsUK
May 22, 2023
Maintainer Author

@stuberman

1 - #10788 (comment)

I have also struggled with chain sync issues, even after upgrading to Lotus v1.23.0 and v1.23.1-rc1
I switched from using systemd last night to a command line instantiation of the daemon and I am not seeing sync issues today.

2 - #10788 (comment)

I run splitstore, but only seems to be an issue using systemd

3 - #10788 (comment)

Here are my splitstore settings and CLI command:

export LOTUS_FVM_CONCURRENCY=32
export LOTUS_SKIP_APPLY_TS_MESSAGE_CALL_WITH_GAS=1
export LOTUS_CHAINSTORE_SPLITSTORE_HOTSTOREFULLGCFREQUENCY=3

[Chainstore]
EnableSplitstore = true
[Chainstore.Splitstore]
ColdStoreType = "discard"
HotStoreFullGCFrequency = 3

nohup lotus daemon > /pool/logs/lotus.log 2>&1 &

0 replies

TippyFlitsUK · 2023-05-22T19:38:36Z

TippyFlitsUK
May 22, 2023
Maintainer Author

@piknikSteven2021

1 - #10788 (comment)

Our systemd settings:

LimitNOFILE=1024000:1024000
EnvironmentFile=/home/lotus%i/lotus%i.env

root@d1:~# cat /home/lotus1/lotus1.env 
RUST_LOG=info
LOTUS_FVM_CONCURRENCY=32

We are NOT running splitstore and seeing syncing issues as well. Block validations are quick, but the validations seem to be extremely delayed. It appears to me that this issue only occurs on daemons with an active boost node connected to it.

May 12 03:32:11 d1 lotus2[30618]: 2023-05-12T03:32:11.446Z        INFO        consensus-common        consensus/compute_state.go:300        ApplyBlocks stats        {"early": 0.00000355, "earlyCronGas": 0, "vmMsg": 0.272048049, "msgGas": 8007356451, "vmCron": 0.390802175, "cronGas": 20587118572, "vmFlush": 0.028936368, "epoch": "2851857", "tsk": "{bafy2bzacebm3qjgj5jilrnin4i7tzj6ae242nyusbcqqujkvdib3mo2kttrie}"}
May 12 03:32:11 d1 lotus2[30618]: 2023-05-12T03:32:11.459Z        INFO        chain        chain/sync.go:625        block validation        {"took": 0.709380193, "height": "2851858", "age": 191.459238467}
May 12 03:32:11 d1 lotus2[30618]: 2023-05-12T03:32:11.460Z        INFO        chain        chain/sync.go:625        block validation        {"took": 0.710140456, "height": "2851858", "age": 191.46003436}
May 12 03:32:11 d1 lotus2[30618]: 2023-05-12T03:32:11.463Z        INFO        chain        chain/sync.go:625        block validation        {"took": 0.713947212, "height": "2851858", "age": 191.463793126}
May 12 03:32:11 d1 lotus2[30618]: 2023-05-12T03:32:11.464Z        INFO        chain        chain/sync.go:625        block validation        {"took": 0.714734565, "height": "2851858", "age": 191.464614129}
May 12 03:32:11 d1 lotus2[30618]: 2023-05-12T03:32:11.464Z        INFO        chain        chain/sync.go:625        block validation        {"took": 0.714988313, "height": "2851858", "age": 191.464866527}

All Lotus nodes are v1.23.0 and Boost v1.7.2.

We'll apply #10855 and see how it goes with sync.

2 - #10788 (comment)

Cherry-picking commit f4a3207ede353f55e51204ac4ebfa2279a785003 to v1.23.0.

root@d1:~# lotus --version
lotus version 1.23.0+mainnet+git.720d50d09

I'll leave it going overnight and see how it goes.

3 - #10788 (comment)

Vanilla daemons on v1.23.0 are d1.las1-lotus1 and d1.las1-lotus2, these have been falling in and out of sync despite not active miners/boost nodes sending messages to them.
Cherry-picked daemons on custom v1.23.0 are d2.las1-lotus1 and d2.las-lotus2, these have been pretty good so far.

4 - #10788 (comment)

Left it going over night, looks like the patched version did not resolve sync issues.

5 - #10788 (comment)

Here is the lotus pprof goroutines output of an out of sync daemon with custom v1.23.0 Lotus version:
out-of-sync-goroutines.txt

6 - #10788 (comment)

out-of-sync-goroutines-2.txt
Here you go @arajasek

7 - #10788 (comment)

I can confirm that this is only prevalent on nodes connected to miners, and only if they are sealing. For us, it is impacting regardless if they are snap deals or not. All sealing causes sync issues.

1 reply

TippyFlitsUK May 22, 2023
Maintainer Author

@piknikSteven2021

Slack Posts - https://filecoinproject.slack.com/archives/CPFTWMY7N/p1683253610893109

1

I've cherry picked PR10857 into vanilla v1.23.0 and am currently running it on multiple daemons. Sync issues are not resolved, we are not using splitstore. I've posted logs and some graphs into the issue.

2

In response to:

can you please check if you have any instances of this 👇in your daemon logs of one of the nodes that is affected?
error in RPC call to 'Filecoin.StateSectorExpiration': failed to find sector

Between three affected nodes, only one has it in the last 5 days.

root@d1:~# journalctl -u lotus@1 --since "5 days ago" | grep "Filecoin.StateSectorExpiration"
root@d2:~# journalctl -u lotus@1 --since "5 days ago" | grep "Filecoin.StateSectorExpiration"
root@d2:~# journalctl -u lotus@2 --since "5 days ago" | grep "Filecoin.StateSectorExpiration"
May 18 06:01:32 d2 lotus2[3307705]: 2023-05-18T06:01:32.203Z        WARN        rpc        go-jsonrpc@v0.2.3/handler.go:406        error in RPC call to 'Filecoin.StateSectorExpiration': failed to find sector 35936:
May 18 07:54:32 d2 lotus2[3307705]: 2023-05-18T07:54:32.132Z        WARN        rpc        go-jsonrpc@v0.2.3/handler.go:406        error in RPC call to 'Filecoin.StateSectorExpiration': failed to find sector 34110:
May 18 07:54:32 d2 lotus2[3307705]: 2023-05-18T07:54:32.227Z        WARN        rpc        go-jsonrpc@v0.2.3/handler.go:406        error in RPC call to 'Filecoin.StateSectorExpiration': failed to find sector 34127:

3

In response to:

Thank you 🙏
I've been testing a few theories tonight and noticed the same message repeating occasionally for one sector. I terminated and removed it and the cyclical sync loss has completely stopped!!
Might be worth giving it a try?

This is affecting daemons with miners that have only been started up within the last two months (and old), so it's odd to me that Filecoin.StateSectorExpiration would be causing issues on the nodes we're seeing issues on.

I've removed the sectors indicated in the daemon logs with Filecoin.StateSectorExpiration

TippyFlitsUK · 2023-05-22T20:09:07Z

TippyFlitsUK
May 22, 2023
Maintainer Author

@donkabat

Conversation conducted in Slack 👇

1 reply

TippyFlitsUK May 22, 2023
Maintainer Author

@donkabat

Slack Posts - https://filecoinproject.slack.com/archives/CPFTWMY7N/p1684638398271809

1

Do you see more occurrences of "lateStart": true in the miner's logs? We got 7 orphans for the last 7 days which is over 17% of mined blocks.

grep -a -A9999999 '2023-05-01' ./lotus-miner0.log | grep 'lateStart": true' | cut -d'T' -f1 | sort | uniq -c
     14 2023-05-01
     10 2023-05-02
      4 2023-05-03
      1 2023-05-04
      5 2023-05-05
      3 2023-05-06
      1 2023-05-07
      4 2023-05-08
      9 2023-05-09
      8 2023-05-10
      6 2023-05-11
      9 2023-05-12
      3 2023-05-13
      6 2023-05-14
     12 2023-05-15
      3 2023-05-16
     20 2023-05-17
     49 2023-05-18
     54 2023-05-19
     39 2023-05-20

on the other hand there is no problem with time of block validation

grep -a -A9999999 '2023-05-01' ./lotus.log | grep 'block validation' | awk -F'{"took": ' '{print $2}' | awk -F', ' '{print $1}' | awk 'BEGIN {min=0; max=0; sum=0; count=0; c5=0; c10=0; c15=0; c20=0; c25=0; c30=0; c1=0} {if($1<min) min=$1; if($1>max) max=$1; sum+=$1; count+=1; if($1>5) c5+=1; if($1>10) c10+=1; if($1>15) c15+=1; if($1>20) c20+=1; if($1>25) c25+=1; if($1>30) c30+=1; if($1<1) c1+=1} END {printf("Min: %s\nAvg: %.2f\nMax: %s\n\nHow many time value was higher than\n5: %s\n10: %s\n15: %s\n20: %s\n25: %s\n30: %s\n\n 
How many time value was lower than\n1: %s\n", min, sum/count, max, c5, c10, c15, c20, c25, c30, c1)}'

Avg: 0.08
Max: 5.236999898

How many time value was higher than
5: 1
10: 0
15: 0
20: 0
25: 0
30: 0

 How many time value was lower than
1: 115328

2

any body could explain me what does it mean, miner logs:

2023-05-21T17:45:40.033Z        INFO    miner   miner/miner.go:477      completed mineOne       {"tookMilliseconds": 10, "forRound": 2879492, "baseEpoch": 2879490, "baseDeltaSeconds": 40, "nullRounds": 1, "lateStart": false, "beaconEpoch": 2975337, "lookbackEpochs": 900, "networkPowerAtLookback": "23751987466039001088", "minerPowerAtLookback": "9201568114081792", "isEligible": true, "isWinner": false, "error": null}
2023-05-21T17:46:10.037Z        INFO    miner   miner/miner.go:477      completed mineOne       {"tookMilliseconds": 10, "forRound": 2879493, "baseEpoch": 2879490, "baseDeltaSeconds": 70, "nullRounds": 2, "lateStart": false, "beaconEpoch": 2975338, "lookbackEpochs": 900, "networkPowerAtLookback": "23751984021123432448", "minerPowerAtLookback": "9201568114081792", "isEligible": true, "isWinner": false, "error": null}
2023-05-21T17:46:40.031Z        INFO    storageminer    storage/winning_prover.go:70    Computing WinningPoSt ;[{SealProof:8 SectorNumber:24795 SectorKey:bagboea4b5abcbdzvziuk5b67riqc7tolmqw57vawfh6ddtfsdlg75nwbai6ip5i2 SealedCID:bagboea4b5abcagxptylh3m4mdms6mk6m3wyb44e3ltihoibdtmi4gkmllniq4pk2}]; [174 153 98 24 196 230 243 201 52 233 172 86 179 100 35 44 211 94 115 18 92 239 196 89 76 206 147 199 254 204 145 93]
2023-05-21T17:46:40.031 INFO filecoin_proofs::api::post_util > generate_sector_challenges:start
2023-05-21T17:46:40.031 INFO filecoin_proofs::api::post_util > generate_sector_challenges:finish
2023-05-21T17:46:41.542Z        INFO    storageminer    storage/winning_prover.go:77    GenerateWinningPoSt took 1.510560848s
2023-05-21T17:46:41.643Z        INFO    miner   miner/miner.go:571      mined new block {"cid": "bafy2bzacedykbaq4s3kfhsgnba46gpwu3bqvrwxh2rj7k7boguyngn5tvtxoc", "height": 2879494, "miner": "f01127678", "parents": ["f01926914","f01926686","f01833576","f01135819","f01836766","f0144528"], "parentTipset": "{bafy2bzacebfv2hkxk6nik7c7cnpqm2bjqc5q5gi2s6rxrly5ciuxx3lr6txwi,bafy2bzaceamu6ilhkqfanrofh322el4rsdegf3j74srvq6nwoz6kchpyd2ada,bafy2bzacecuy2obesdwlhz3gu4zsey4lpfvdoc242ubd2bbbgvpd2r26minoq,bafy2bzaceats4ik7fcadttywraq6n3tm3pssywefvhphj6bwimgxpr3ungtnw,bafy2bzacea7lgbc4jc2ku7zajpbix4zjkyghoedojqantiandipmgdp7ynsye,bafy2bzacecnayd7jlw5cggg4w2yd5jpl32ankjqt45z37n5feuukdszknr3ai}", "took": 1.618398853}
2023-05-21T17:46:41.643Z        INFO    miner   miner/miner.go:477      completed mineOne       {"tookMilliseconds": 1618, "forRound": 2879494, "baseEpoch": 2879490, "baseDeltaSeconds": 100, "nullRounds": 3, "lateStart": false, "beaconEpoch": 2975339, "lookbackEpochs": 900, "networkPowerAtLookback": "23751983986763694080", "minerPowerAtLookback": "9201568114081792", "isEligible": true, "isWinner": true, "error": null}

there is not a single lateStart but baseDeltaSeconds shot into space...

3

we lost 11 mined blocks in the last 7 days... 27,5%

4

In response to:

How often are you seeing the baseDeltaSeconds rising Don and does it happen more when performing certain tasks such as C2?

5

If you would like to compare:
miners are connected to different nodes.

TippyFlitsUK · 2023-05-22T20:41:54Z

TippyFlitsUK
May 22, 2023
Maintainer Author

@TippyFlitsUK

Conversation conducted in Slack 👇

1 reply

TippyFlitsUK May 22, 2023
Maintainer Author

@TippyFlitsUK

Slack Posts - https://filecoinproject.slack.com/archives/CPFTWMY7N/p1684638398271809

1

I have been sealing CC sectors all week without any kind of repetition.
I started to import and snap deals a few hours ago and I'm starting to see similar sync loss.

lotus-boost.log, lotus-daemon.log, lotus-miner.log

hughjj · 2023-05-24T08:32:43Z

hughjj
May 24, 2023

@TippyFlitsUK hello, https://filecoinproject.slack.com/archives/CEGN061C5/p1684498564684429

lotus version 1.23.0+mainnet+git.0ffd04b3
not set env PROPAGATION_DELAY_SECS
EnableSplitstore = false

winningpost-logs-2023-05-22T05.log

lotus-log-2023-05-22T05.log

1 reply

TippyFlitsUK May 24, 2023
Maintainer Author

Many thanks Hugh!! 🙏

TippyFlitsUK · 2023-07-20T16:19:48Z

TippyFlitsUK
Jul 20, 2023
Maintainer Author

This issue has now been resolved in #10906

0 replies

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

User Logs & Feedback for issue 10788 #10907

{{title}}

{{editor}}'s edit

{{editor}}'s edit

Replies: 11 comments 8 replies

{{title}}

{{editor}}'s edit

{{editor}}'s edit

{{title}}

{{title}}

{{editor}}'s edit

{{editor}}'s edit

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

{{editor}}'s edit

{{editor}}'s edit

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

Select a reply

User Logs & Feedback for issue 10788 #10907

TippyFlitsUK May 22, 2023 Maintainer

User-provided logs and feedback for issue #10788 in the thread below.

Replies: 11 comments · 8 replies

TippyFlitsUK May 22, 2023 Maintainer Author

1 - #10788 (comment)

Lotus Version

Repro Steps

Describe the Bug

Logging Information

2 - #10788 (comment)

TippyFlitsUK May 22, 2023 Maintainer Author

Slack Posts - https://filecoinproject.slack.com/archives/CP50PPW2X/p1682716335088099

1

2

3

TippyFlitsUK May 22, 2023 Maintainer Author

1 - #10788 (comment)

TippyFlitsUK May 22, 2023 Maintainer Author

Slack Posts - https://filecoinproject.slack.com/archives/CP50PPW2X/p1682716335088099

1

2

3

4

5

6

7

8

TippyFlitsUK May 22, 2023 Maintainer Author

1 - #10788 (comment)

2 - #10788 (comment)

3 - #10788 (comment)

4 - #10788 (comment)

5 - #10788 (comment)

6 - #10788 (comment)

7 - #10788 (comment)

8 - #10788 (comment)

TippyFlitsUK May 22, 2023 Maintainer Author

Slack Posts - https://filecoinproject.slack.com/archives/CP50PPW2X/p1682716335088099

1

2

3

4

5

6

7

8

9

10

11

12

13

14

15

magik6k May 22, 2023 Maintainer

TippyFlitsUK May 22, 2023 Maintainer Author

1 - #10788 (comment)

2 - #10788 (comment)

3 - #10788 (comment)

4 - #10788 (comment)

TippyFlitsUK May 22, 2023 Maintainer Author

1 - #10788 (comment)

TippyFlitsUK May 22, 2023 Maintainer Author

1 - #10788 (comment)

2 - #10788 (comment)

3 - #10788 (comment)

TippyFlitsUK May 22, 2023 Maintainer Author

1 - #10788 (comment)

2 - #10788 (comment)

3 - #10788 (comment)

4 - #10788 (comment)

5 - #10788 (comment)

6 - #10788 (comment)

7 - #10788 (comment)

TippyFlitsUK May 22, 2023 Maintainer Author

Slack Posts - https://filecoinproject.slack.com/archives/CPFTWMY7N/p1683253610893109

1

2

3

TippyFlitsUK May 22, 2023 Maintainer Author

TippyFlitsUK
May 22, 2023
Maintainer

Replies: 11 comments 8 replies

TippyFlitsUK
May 22, 2023
Maintainer Author

TippyFlitsUK May 22, 2023
Maintainer Author

TippyFlitsUK
May 22, 2023
Maintainer Author

TippyFlitsUK May 22, 2023
Maintainer Author

TippyFlitsUK
May 22, 2023
Maintainer Author

TippyFlitsUK May 22, 2023
Maintainer Author

magik6k May 22, 2023
Maintainer

TippyFlitsUK
May 22, 2023
Maintainer Author

TippyFlitsUK
May 22, 2023
Maintainer Author

TippyFlitsUK
May 22, 2023
Maintainer Author

TippyFlitsUK
May 22, 2023
Maintainer Author

TippyFlitsUK May 22, 2023
Maintainer Author

TippyFlitsUK
May 22, 2023
Maintainer Author

TippyFlitsUK May 22, 2023
Maintainer Author

TippyFlitsUK
May 22, 2023
Maintainer Author

TippyFlitsUK May 22, 2023
Maintainer Author

TippyFlitsUK May 24, 2023
Maintainer Author

TippyFlitsUK
Jul 20, 2023
Maintainer Author