Block height fallback problem report #7630

MatrixStorage · 2021-11-05T06:15:21Z

MatrixStorage
Nov 5, 2021

Lotus Version

Daemon:  1.13.0+mainnet+git.7a55e8e89.dirty+api1.4.0
Local: lotus version 1.13.0+mainnet+git.7a55e8e89.dirty

Describe the Bug

Error：

failed to set up called handler: called check error (h: 1256818): failed to look up deal on chain: deal 2711201 not found - deal may not have completed sealing before deal proposal start epoch, or deal may have been slashed

Add a block height log to chain/events/events_called.go # 122 to print the block height to be applied:
2021-11-02T17:16:00.919Z INFO events events/events_called.go:123 启动events callled apply,from 1252231 to 1252232
2021-11-02T17:16:00.920Z INFO events events/events_called.go:161 启动events callled revert,from 1252232 to 1252231
2021-11-02T17:16:00.920Z INFO events events/events_called.go:123 启动events callled apply,from 1252231 to 1252232
2021-11-02T17:16:30.637Z INFO events events/events_called.go:123 启动events callled apply,from 1252232 to 1252233
2021-11-02T17:16:30.637Z INFO events events/events_called.go:161 启动events callled revert,from 1252233 to 1252232
2021-11-02T17:16:30.637Z INFO events events/events_called.go:123 启动events callled apply,from 1252232 to 1252233
2021-11-02T17:16:30.637Z INFO events events/events_called.go:161 启动events callled revert,from 1252233 to 1252232
2021-11-02T17:16:30.637Z INFO events events/events_called.go:123 启动events callled apply,from 1252232 to 1252233
2021-11-03T01:32:21.950Z INFO events events/events_called.go:123 启动events callled apply,from 1252231 to 1252232
2021-11-03T01:32:21.950Z INFO events events/events_called.go:161 启动events callled revert,from 1252232 to 1252231
2021-11-03T01:32:36.738Z INFO events events/events_called.go:123 启动events callled apply,from 1252231 to 1252232
2021-11-03T01:32:51.569Z INFO events events/events_called.go:123 启动events callled apply,from 1252232 to 1252233
2021-11-03T01:32:51.569Z INFO events events/events_called.go:161 启动events callled revert,from 1252233 to 1252232
2021-11-03T01:33:06.098Z INFO events events/events_called.go:123 启动events callled apply,from 1252232 to 1252233
2021-11-03T01:33:06.098Z INFO events events/events_called.go:161 启动events callled revert,from 1252233 to 1252232
2021-11-03T01:33:20.606Z INFO events events/events_called.go:123 启动events callled apply,from 1252232 to 1252233

This causes the block height at the current time to go back in time, and when Lotus Client checks whether the deal is consistent, it uses the block height of the past to query the deal, and the deal cannot be found

Answered by MatrixStorage

Nov 18, 2021

上一次提issue的时候我们进行了排查，进行了如下的代码变更，用于输出上次的提交日志：
/lotus/chain/events/events_called.go#Apply

defer func() { e.lastTs = to }()

change code

	defer func() {
		log.Infof("启动events callled apply,from %d to %d,old lastTs=>%d,address=>%p", from.Height(), to.Height(), e.lastTs.Height(), e)
		e.lastTs = to
	}()

/lotus/chain/events/events_called.go#Revert

defer func() { e.lastTs = to }()

change code

	defer func() {
        log.Infof("启动events callled revert,from %d to %d,old lastTs=>%d,address=>%p", from.Height(), to.Height(), e.lastTs.Height(), e)
		e.lastTs = to
	}()

根据我们最新排查的情况，是区块高度在同步apply的时候会出现处理时间较长的情况（默认30s/组）。此情况会导致后续的区块同步apply处理延时。
目前矩阵存储基于官方底层代码的运行情况为每次同步5-6个消息，每个消息7s以上（处理时长超过30s/组），长期处理延时…

View full answer

jennijuju · 2021-11-16T03:21:52Z

jennijuju
Nov 16, 2021
Maintainer

What do you mean by This causes the block height at the current time to go back in time, what’s this?
the log shown doesn’t seems like to be in default lotus so gonna transfer this to discussion.
Also, the error message seems clear to me on why the deal cannot be found.

0 replies

MatrixStorage · 2021-11-18T03:02:27Z

MatrixStorage
Nov 18, 2021
Author

上一次提issue的时候我们进行了排查，进行了如下的代码变更，用于输出上次的提交日志：
/lotus/chain/events/events_called.go#Apply

defer func() { e.lastTs = to }()

change code

	defer func() {
		log.Infof("启动events callled apply,from %d to %d,old lastTs=>%d,address=>%p", from.Height(), to.Height(), e.lastTs.Height(), e)
		e.lastTs = to
	}()

/lotus/chain/events/events_called.go#Revert

defer func() { e.lastTs = to }()

change code

	defer func() {
        log.Infof("启动events callled revert,from %d to %d,old lastTs=>%d,address=>%p", from.Height(), to.Height(), e.lastTs.Height(), e)
		e.lastTs = to
	}()

根据我们最新排查的情况，是区块高度在同步apply的时候会出现处理时间较长的情况（默认30s/组）。此情况会导致后续的区块同步apply处理延时。
目前矩阵存储基于官方底层代码的运行情况为每次同步5-6个消息，每个消息7s以上（处理时长超过30s/组），长期处理延时的堆积导致矩阵存储用户近170w+的文件停留在归档中，或无法获悉目前真实归档状态。

最新排查增加的日志输出代码
/lotus/chain/events/observer/events_called.go#listenHeadChangesOnce

	for changes := range notifs {
		if err := o.applyChanges(ctx, changes); err != nil {
			return err
		}
	}

change code

	for changes := range notifs {
		a := time.Now()
		if err := o.applyChanges(ctx, changes); err != nil {
			return err
		}
		b := time.Now()
		log.Infof("spend time:%f,address=>%p", b.Sub(a).Seconds(), o)
	}

printLog

Nov 17 15:50:43 YAYD01-FF-JZCC-G01-ODP-52.109 lotus[1978801]: 2021-11-17T15:50:43.680+0800        INFO        events        events/observer.go:133        spend time:7.055177,address=>0xc01894a500
Nov 17 15:50:43 YAYD01-FF-JZCC-G01-ODP-52.109 lotus[1978801]: 2021-11-17T15:50:43.680+0800        ERROR        events        events/observer.go:149        tip set revert 1294298,address=>0xc01894a500
Nov 17 15:50:43 YAYD01-FF-JZCC-G01-ODP-52.109 lotus[1978801]: 2021-11-17T15:50:43.680+0800        ERROR        events        events/observer.go:152        tip set apply 1294298,address=>0xc01894a500
Nov 17 15:50:50 YAYD01-FF-JZCC-G01-ODP-52.109 lotus[1978801]: 2021-11-17T15:50:50.728+0800        INFO        events        events/observer.go:133        spend time:7.047916,address=>0xc01894a500
Nov 17 15:50:50 YAYD01-FF-JZCC-G01-ODP-52.109 lotus[1978801]: 2021-11-17T15:50:50.728+0800        ERROR        events        events/observer.go:152        tip set apply 1294299,address=>0xc01894a500
Nov 17 15:50:58 YAYD01-FF-JZCC-G01-ODP-52.109 lotus[1978801]: 2021-11-17T15:50:58.608+0800        INFO        events        events/observer.go:133        spend time:7.880149,address=>0xc01894a500
Nov 17 15:50:58 YAYD01-FF-JZCC-G01-ODP-52.109 lotus[1978801]: 2021-11-17T15:50:58.608+0800        ERROR        events        events/observer.go:149        tip set revert 1294299,address=>0xc01894a500
Nov 17 15:50:58 YAYD01-FF-JZCC-G01-ODP-52.109 lotus[1978801]: 2021-11-17T15:50:58.608+0800        ERROR        events        events/observer.go:152        tip set apply 1294299,address=>0xc01894a500
Nov 17 15:51:09 YAYD01-FF-JZCC-G01-ODP-52.109 lotus[1978801]: 2021-11-17T15:51:09.595+0800        INFO        events        events/observer.go:133        spend time:10.986525,address=>0xc01894a500
Nov 17 15:51:09 YAYD01-FF-JZCC-G01-ODP-52.109 lotus[1978801]: 2021-11-17T15:51:09.595+0800        ERROR        events        events/observer.go:149        tip set revert 1294299,address=>0xc01894a500
Nov 17 15:51:09 YAYD01-FF-JZCC-G01-ODP-52.109 lotus[1978801]: 2021-11-17T15:51:09.595+0800        ERROR        events        events/observer.go:152        tip set apply 1294299,address=>0xc01894a500
Nov 17 15:51:16 YAYD01-FF-JZCC-G01-ODP-52.109 lotus[1978801]: 2021-11-17T15:51:16.660+0800        INFO        events        events/observer.go:133        spend time:7.065194,address=>0xc01894a500
Nov 17 15:51:16 YAYD01-FF-JZCC-G01-ODP-52.109 lotus[1978801]: 2021-11-17T15:51:16.660+0800        ERROR        events        events/observer.go:149        tip set revert 1294299,address=>0xc01894a500
Nov 17 15:51:16 YAYD01-FF-JZCC-G01-ODP-52.109 lotus[1978801]: 2021-11-17T15:51:16.660+0800        ERROR        events        events/observer.go:152        tip set apply 1294299,address=>0xc01894a500
Nov 17 15:51:23 YAYD01-FF-JZCC-G01-ODP-52.109 lotus[1978801]: 2021-11-17T15:51:23.729+0800        INFO        events        events/observer.go:133        spend time:7.068511,address=>0xc01894a500
Nov 17 15:51:23 YAYD01-FF-JZCC-G01-ODP-52.109 lotus[1978801]: 2021-11-17T15:51:23.729+0800        ERROR        events        events/observer.go:152        tip set apply 1294300,address=>0xc01894a500
Nov 17 15:51:36 YAYD01-FF-JZCC-G01-ODP-52.109 lotus[1978801]: 2021-11-17T15:51:36.132+0800        INFO        events        events/observer.go:133        spend time:12.403854,address=>0xc01894a500
Nov 17 15:51:36 YAYD01-FF-JZCC-G01-ODP-52.109 lotus[1978801]: 2021-11-17T15:51:36.132+0800        ERROR        events        events/observer.go:149        tip set revert 1294300,address=>0xc01894a500
Nov 17 15:51:36 YAYD01-FF-JZCC-G01-ODP-52.109 lotus[1978801]: 2021-11-17T15:51:36.132+0800        ERROR        events        events/observer.go:152        tip set apply 1294300,address=>0xc01894a500
Nov 17 15:51:43 YAYD01-FF-JZCC-G01-ODP-52.109 lotus[1978801]: 2021-11-17T15:51:43.177+0800        INFO        events        events/observer.go:133        spend time:7.044372,address=>0xc01894a500
Nov 17 15:51:43 YAYD01-FF-JZCC-G01-ODP-52.109 lotus[1978801]: 2021-11-17T15:51:43.177+0800        ERROR        events        events/observer.go:152        tip set apply 1294301,address=>0xc01894a500
Nov 17 15:51:50 YAYD01-FF-JZCC-G01-ODP-52.109 lotus[1978801]: 2021-11-17T15:51:50.968+0800        INFO        events        events/observer.go:133        spend time:7.790889,address=>0xc01894a500
Nov 17 15:51:50 YAYD01-FF-JZCC-G01-ODP-52.109 lotus[1978801]: 2021-11-17T15:51:50.968+0800        ERROR        events        events/observer.go:149        tip set revert 1294301,address=>0xc01894a500
Nov 17 15:51:50 YAYD01-FF-JZCC-G01-ODP-52.109 lotus[1978801]: 2021-11-17T15:51:50.968+0800        ERROR        events        events/observer.go:152        tip set apply 1294301,address=>0xc01894a500
Nov 17 15:51:58 YAYD01-FF-JZCC-G01-ODP-52.109 lotus[1978801]: 2021-11-17T15:51:58.004+0800        INFO        events        events/observer.go:133        spend time:7.036069,address=>0xc01894a500
Nov 17 15:51:58 YAYD01-FF-JZCC-G01-ODP-52.109 lotus[1978801]: 2021-11-17T15:51:58.004+0800        ERROR        events        events/observer.go:149        tip set revert 1294301,address=>0xc01894a500
Nov 17 15:51:58 YAYD01-FF-JZCC-G01-ODP-52.109 lotus[1978801]: 2021-11-17T15:51:58.004+0800        ERROR        events        events/observer.go:152        tip set apply 1294301,address=>0xc01894a500
Nov 17 15:52:06 YAYD01-FF-JZCC-G01-ODP-52.109 lotus[1978801]: 2021-11-17T15:52:06.394+0800        INFO        events        events/observer.go:133        spend time:8.389735,address=>0xc01894a500
Nov 17 15:52:06 YAYD01-FF-JZCC-G01-ODP-52.109 lotus[1978801]: 2021-11-17T15:52:06.394+0800        ERROR        events        events/observer.go:149        tip set revert 1294301,address=>0xc01894a500
Nov 17 15:52:06 YAYD01-FF-JZCC-G01-ODP-52.109 lotus[1978801]: 2021-11-17T15:52:06.394+0800        ERROR        events        events/observer.go:152        tip set apply 1294301,address=>0xc01894a500
Nov 17 15:52:13 YAYD01-FF-JZCC-G01-ODP-52.109 lotus[1978801]: 2021-11-17T15:52:13.442+0800        INFO        events        events/observer.go:133        spend time:7.048198,address=>0xc01894a500
Nov 17 15:52:13 YAYD01-FF-JZCC-G01-ODP-52.109 lotus[1978801]: 2021-11-17T15:52:13.442+0800        ERROR        events        events/observer.go:149        tip set revert 1294301,address=>0xc01894a500
Nov 17 15:52:13 YAYD01-FF-JZCC-G01-ODP-52.109 lotus[1978801]: 2021-11-17T15:52:13.442+0800        ERROR        events        events/observer.go:152        tip set apply 1294301,address=>0xc01894a500

2 replies

LexLuthr Nov 30, 2021
Collaborator

@MatrixStorage Do you require any further help on this? If no, would it be possible for you to help me summarize your answer in English so this discussion can be helpful to more community members.

MatrixStorage Dec 6, 2021
Author

@LexLuthr I will translate the above dialogue into English for our discussion. Thank you for your feedback

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

Block height fallback problem report #7630

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{editor}}'s edit

{{editor}}'s edit

Uh oh!

Replies: 2 comments 2 replies

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{title}}

Uh oh!

Select a reply

Uh oh!

Block height fallback problem report #7630

Uh oh!

Uh oh!

MatrixStorage Nov 5, 2021

Lotus Version

Describe the Bug

Replies: 2 comments · 2 replies

Uh oh!

jennijuju Nov 16, 2021 Maintainer

Uh oh!

MatrixStorage Nov 18, 2021 Author

printLog

Uh oh!

LexLuthr Nov 30, 2021 Collaborator

Uh oh!

MatrixStorage Dec 6, 2021 Author

MatrixStorage
Nov 5, 2021

Replies: 2 comments 2 replies

jennijuju
Nov 16, 2021
Maintainer

MatrixStorage
Nov 18, 2021
Author

LexLuthr Nov 30, 2021
Collaborator

MatrixStorage Dec 6, 2021
Author