make journal pluggable; record deals, sealing, wdpost, mempool events #2455

raulk · 2020-07-17T13:23:12Z

Please merge with a squash

Addresses part of #2441; the other part (in-memory journal implementation) is hosted in Project Oni: filecoin-project/oni#226.

What has been done here

New journal events

Sealing state transition events are now recorded in the journal.
- Required a change in storage-fsm to emit notifications.
Deal state transitions are now recorded in the journal.
Windowed PoSt events (run, abort, faults_processed, recoveries_processed, proofs_processed) are now recorded in the journal.
Mempool events (add, remove, repub) are now recorded in the journal. Add and remove are disabled by default.

Journal framework

Make the Journal not global; instead, use fx to inject it where needed.
Support typed journal events.
By default, Lotus constructs the filesystem-based journal, but it can be overridden with another implementation through a constructor option.
Ability to suppress/disable certain types of events, such as those known to be noisy and not relevant during production use, but important for testing (e.g. mempool add/drop).
In order to avoid runtime costs, suppressed event types need to be disabled during construction, by overriding the DisabledEvents fx key.
By default, we suppress the noisy mempool events. Oni tests will pass in an empty disabled set, so we get access to everything.
Sugar API function MaybeRecordEvent that lazily creates the event only if the EventType is enabled.

Example journal events

Sealing state machine transitions

{"System":"storage","Event":"sealing_states","Timestamp":"2020-08-11T15:05:00.556940387Z","Data":{"SectorNumber":19,"SectorType":2,"From":"WaitSeed","After":"Committing","Error":""}}
{"System":"storage","Event":"sealing_states","Timestamp":"2020-08-11T15:07:46.797337768Z","Data":{"SectorNumber":19,"SectorType":2,"From":"Committing","After":"CommitWait","Error":""}}
{"System":"storage","Event":"sealing_states","Timestamp":"2020-08-11T15:11:59.258008229Z","Data":{"SectorNumber":19,"SectorType":2,"From":"CommitWait","After":"FinalizeSector","Error":""}}
{"System":"storage","Event":"sealing_states","Timestamp":"2020-08-11T15:11:59.655317986Z","Data":{"SectorNumber":19,"SectorType":2,"From":"FinalizeSector","After":"Proving","Error":""}}
{"System":"storage","Event":"sealing_states","Timestamp":"2020-08-11T15:44:00.581866465Z","Data":{"SectorNumber":20,"SectorType":2,"From":"WaitDeals","After":"Packing","Error":""}}
{"System":"storage","Event":"sealing_states","Timestamp":"2020-08-11T15:44:13.940864008Z","Data":{"SectorNumber":20,"SectorType":2,"From":"Packing","After":"PreCommit1","Error":""}}
{"System":"storage","Event":"sealing_states","Timestamp":"2020-08-11T15:45:03.216173326Z","Data":{"SectorNumber":20,"SectorType":2,"From":"PreCommit1","After":"PreCommit2","Error":""}}
{"System":"storage","Event":"sealing_states","Timestamp":"2020-08-11T15:46:30.365776445Z","Data":{"SectorNumber":0,"SectorType":0,"From":"","After":"Empty","Error":""}}

Windowed PoSt

{"System":"storage","Event":"wdpost","Timestamp":"2020-08-11T15:20:30.401238096Z","Data":{"State":"abort","Deadline":{"CurrentEpoch":10099,"PeriodStart":8419,"Index":28,"Open":10099,"Close":10159,"Challenge":10079,"FaultCutoff":10029},"Height":10158,"TipSet":[{"/":"bafy2bzacecv7qpj2o4i3wqiv2sia6sbuwiicequvvfwofybhownpdxjjll5d4"}]}}
{"System":"storage","Event":"wdpost","Timestamp":"2020-08-11T15:20:30.401491228Z","Data":{"State":"started","Deadline":{"CurrentEpoch":10159,"PeriodStart":8419,"Index":29,"Open":10159,"Close":10219,"Challenge":10139,"FaultCutoff":10089},"Height":10158,"TipSet":[{"/":"bafy2bzacecv7qpj2o4i3wqiv2sia6sbuwiicequvvfwofybhownpdxjjll5d4"}]}}
{"System":"storage","Event":"wdpost","Timestamp":"2020-08-11T15:20:30.403296622Z","Data":{"State":"recoveries_processed","Deadline":{"CurrentEpoch":10159,"PeriodStart":8419,"Index":29,"Open":10159,"Close":10219,"Challenge":10139,"FaultCutoff":10089},"Height":10158,"TipSet":[{"/":"bafy2bzacecv7qpj2o4i3wqiv2sia6sbuwiicequvvfwofybhownpdxjjll5d4"}],"Recoveries":{"Declarations":[],"MessageCID":null}}}
{"System":"storage","Event":"wdpost","Timestamp":"2020-08-11T15:20:30.403301022Z","Data":{"State":"faults_processed","Deadline":{"CurrentEpoch":10159,"PeriodStart":8419,"Index":29,"Open":10159,"Close":10219,"Challenge":10139,"FaultCutoff":10089},"Height":10158,"TipSet":[{"/":"bafy2bzacecv7qpj2o4i3wqiv2sia6sbuwiicequvvfwofybhownpdxjjll5d4"}],"Faults":{"Declarations":[],"MessageCID":null}}}

mpool

Add and remove events are disabled by default, but this is how add events look.

{"System":"mpool","Event":"add","Timestamp":"2020-08-11T15:35:42.640242628Z","Data":{"Action":"add","Messages":[{"Version":0,"To":"t01464","From":"t3q2sc3zvdhcwhuttajyv6zhlfmqfffan736fc552zu5m6vofneecmsbs5b3clrpgexklaqn75fgztim5y6rgq","Nonce":12673,"Value":"3727422619627069401","GasLimit":21651646,"GasFeeCap":"1064652776302","GasPremium":"4","Method":6,"Params":"igMZ1EjYKlgpAAGC4gOB6AIge/eO8WleRP1CBG7vb588+wOuByEifkZXavzVsjicJDEZH7uAGgAIu6P0AAAA","CID":{"/":"bafy2bzacebq3qfiynqc5oopqwmlhljsleybimkofuek5efthmfa7ang2hfa6i"}}]}}
{"System":"mpool","Event":"add","Timestamp":"2020-08-11T15:35:43.220132993Z","Data":{"Action":"add","Messages":[{"Version":0,"To":"t05","From":"t3qtgrsjee4tubfpzf2hjdmeqonkoz4c3llracv2lnwtanmkrexbtvcln7zvjwmptdblq67lkle66npbbnvbnq","Nonce":3351,"Value":"0","GasLimit":60881214,"GasFeeCap":"1088471905894","GasPremium":"2","Method":4,"Params":"gYGCi9gqWCgAAYHiA5IgIA/Jg0iXqR68K/HsuKblVjnlXjJzGmfzDFZ8XfYX5Hg4GgAEAAD0WDEDhM0ZJITk6BK/JdHSNhIOap2eC2tcQCrpbbTA1iokuGdRLb/NU2Y+Ywrh761LJ7zXQwC0DnhkewoJInBjaWRzIjogWwoJCXsKCQkJIi8iOiAiYmFmazJiemFjZWM1aWRuempxZHNubjM0ZmVnZnAzNGhlaHhyeXBmbmFmbHAycGxzeWplNGM1a2N3YnhsY3EiCgkJfQoJXQp9ChkzDRoACZ4ARQBQd12AQEBYYQKorCx9eeMPROqSS3EBVOkpB+D8ED3F9BFhdy/zLuENKoM5wpVzsczB3BqebR+LWIcScjNM4bDlT///WH/qlvkMTD5ac6E3gz1FzjmK9EhipOCZD0Qz146C1fmYq4DDNbg=","CID":{"/":"bafy2bzacebxx7hk7t6wpmehvo7ociw7tadntksjfwdyjnniygtqmulh7pamqo"}}]}}
{"System":"mpool","Event":"add","Timestamp":"2020-08-11T15:35:44.044902337Z","Data":{"Action":"add","Messages":[{"Version":0,"To":"t01045","From":"t3spbjekuheshmqj6gsz3fbrzozejq5aiyntqtaxuhptnemc5k4bolfgtyc76efrkwj4j6nz5vhlhf765i3fda","Nonce":26757,"Value":"3727361587939049590","GasLimit":14942648,"GasFeeCap":"335131587179","GasPremium":"2","Method":6,"Params":"igMZM23YKlgpAAGC4gOB6AIgf5Uw+fvcv1mECsio0Zoaqh44mYmGhagTyLH3TVIhzxUZH6mAGgAX0aL0AAAA","CID":{"/":"bafy2bzacecprq5z43bfucpg2hwh2faak7pjicz7jb6k74vaskqio5qjr5p5o6"}}]}}
{"System":"mpool","Event":"add","Timestamp":"2020-08-11T15:35:44.319591507Z","Data":{"Action":"add","Messages":[{"Version":0,"To":"t02220","From":"t3snngyn6annziz5heowxfkkd6jcpn5bizr2xkgptxxbatq2ttbuo56hl2xwnxsuqv3uj7nn6nzrxh73ufisha","Nonce":34002,"Value":"3727361587939049590","GasLimit":23323009,"GasFeeCap":"1","GasPremium":"1","Method":6,"Params":"igMaAASgqNgqWCkAAYLiA4HoAiCbrcfJNcDgfR5x8EXLAxkbPKhz0e+O427yQ0dFq8VQGhkiEYAaABfan/QAAAA=","CID":{"/":"bafy2bzacedzl7tmdqbvdct7ionck3ct5pibnxrrvt2cfocyvi7qcr65pqlarq"}}]}

Deals

{"System":"markets:storage:provider","Event":"deal_complete","Timestamp":"2020-08-11T15:43:00.600472498Z","Data":{"ID":18281,"Deal":{"Proposal":{"PieceCID":{"/":"baga6ea4seaqemba7nfrn6r2rv7x7q5uaaqrzdhyux3jpa2vvas4qqu7x2fae4hq"},"PieceSize":131072,"VerifiedDeal":false,"Client":"t3ulfykd6qimw63fbk6lcdjqnw6b7jqxwt2h7omwfdrawbssizutamjfax5g6iiqbkx22pt2yl2dtgk7vnj67a","Provider":"t03212","Label":"{\n\t\"pcids\": [\n\t\t{\n\t\t\t\"/\": \"bafk2bzacedmlz6vhpcemizgcax5almemh5o2f76vnnyk3r3dsofehi375rre2\"\n\t\t}\n\t]\n}\n","StartEpoch":13075,"EndEpoch":593058,"StoragePricePerEpoch":"2000000","ProviderCollateral":"0","ClientCollateral":"0"},"ClientSignature":{"Type":0,"Data":null},"ProposalCid":{"/":"bafyreicm35wkw6vrzbtpf3mj4zcquhi4h7qs6cmrfxatqagqcrqnm6hngy"},"AddFundsCid":null,"PublishCid":null,"Miner":"","Client":"12D3KooWJU6qqDH4DJtYfZrqiqb2dyNtgW2HNjhPmr6whSU6MgNb","State":4,"PiecePath":"","MetadataPath":"","SlashEpoch":0,"FastRetrieval":true,"Message":"","StoreID":null,"FundsReserved":"\u003cnil\u003e","Ref":{"TransferType":"graphsync","Root":{"/":"bafk2bzacedmlz6vhpcemizgcax5almemh5o2f76vnnyk3r3dsofehi375rre2"},"PieceCid":null,"PieceSize":0},"AvailableForRetrieval":false,"DealID":18281},"State":{"SectorStartEpoch":0,"LastUpdatedEpoch":0,"SlashEpoch":0},"Height":0}}

journal/memory.go

journal/types.go

raulk · 2020-08-11T12:07:47Z

journal/fs.go

@@ -0,0 +1,131 @@
+package journal


Most of this was copied as-is.

node/modules/storageminer.go

raulk · 2020-08-11T12:11:59Z

storage/wdpost_sched.go

+	Proofs     *WindowPoStEvt_Proofs     `json:",omitempty"`
+	Recoveries *WindowPoStEvt_Recoveries `json:",omitempty"`
+	Faults     *WindowPoStEvt_Faults     `json:",omitempty"`


These could actually be splintered into separate event types.

Probably worth doing, window post journal will likely be the one of the most looked at

Makes sense, will do.

raulk · 2020-08-11T12:14:04Z

markets/storageadapter/provider.go

@@ -45,14 +46,25 @@ type ProviderNodeAdapter struct {

 	secb *sectorblocks.SectorBlocks
 	ev   *events.Events
+
+	jrnl     journal.Journal
+	evtTypes [4]journal.EventType


For performance reasons, an array of journal.EventTypes is what I settled on as the lowest overhead, nicely encapsulated technique to initialize and store EventTypes during construction time, and index into them during runtime.

Code which is called here triggers codepaths which take minutes/hours on real networks, I don't think we need to worry about making this super fast too much.

…ost.

magik6k

Sorry for taking so long on this.

Looks pretty good, just a couple of comments

magik6k · 2020-08-31T08:41:40Z

journal/nil.go

+
+func (n *nilJournal) RegisterEventType(_, _ string) EventType { return EventType{} }
+
+func (n *nilJournal) RecordEvent(_ EventType, _ func() interface{}) {}


Should we scream loudly in logs when something calls this?

I don't think so. This journal is designed for testing or for running stuff outside the lotus daemon (e.g. CLI tools). Things will call it all the time; this journal just no-ops. Maybe we can scream loudly when registering events, but I think it adds no value.

magik6k · 2020-08-31T08:51:00Z

markets/storageadapter/provider.go

@@ -45,14 +46,25 @@ type ProviderNodeAdapter struct {

 	secb *sectorblocks.SectorBlocks
 	ev   *events.Events
+
+	jrnl     journal.Journal
+	evtTypes [4]journal.EventType


Code which is called here triggers codepaths which take minutes/hours on real networks, I don't think we need to worry about making this super fast too much.

node/builder.go

node/modules/storageminer.go

magik6k · 2020-08-31T09:01:18Z

storage/miner.go

+}
+
+// SealingStateEvt is a journal event that records a sector state transition.
+type SealingStateEvt struct {


Ideally this would live inside the sealing package. We want to move sealing.New construction to DI, but it's somewhat entangled with the Miner struct here. We should try to not make this worse

You mean the journalling itself, or just the struct? If it's the first, we could do that, but that means that the theoretically external sealing package would now depend on Lotus' journal interface, unless we re-declare it there. This would be a very simple refactor to do going forward, when compared to all the detangling that needs to happen anyway, so I wouldn't wanna stall on this right here right now.

storage/wdpost_run.go

magik6k · 2020-08-31T09:16:34Z

storage/wdpost_sched.go

+	Proofs     *WindowPoStEvt_Proofs     `json:",omitempty"`
+	Recoveries *WindowPoStEvt_Recoveries `json:",omitempty"`
+	Faults     *WindowPoStEvt_Faults     `json:",omitempty"`


Probably worth doing, window post journal will likely be the one of the most looked at

raulk · 2020-09-02T18:55:29Z

Note that I don’t have a miner, so I haven’t tested this to the degree I'd be satisfied. Please test with a miner of yours before merging! There may be hidden bugs that weren’t caught by tests.

whyrusleeping

lets doooo ittttt

RobQuistNL · 2020-09-18T07:37:04Z

This is freaking awesome <3

wip in-memory journal.

695f6cf

raulk force-pushed the inmem-journal branch from a8fc4a6 to 695f6cf Compare July 17, 2020 13:34

Kubuxu reviewed Jul 17, 2020

View reviewed changes

journal/memory.go Outdated Show resolved Hide resolved

yusefnapora reviewed Jul 17, 2020

View reviewed changes

journal/types.go Outdated Show resolved Hide resolved

raulk added 3 commits July 17, 2020 18:35

refactor EventType construction.

bef7d64

use new journal from chain/store pkg.

4bcf019

add NilJournal; fix call sites to ChainStore constructor.

becbff0

raulk force-pushed the inmem-journal branch from b28e48d to becbff0 Compare July 17, 2020 18:10

raulk added 2 commits July 20, 2020 10:38

Merge branch 'next' into inmem-journal

4d2d8b2

wip

226786c

raulk mentioned this pull request Jul 20, 2020

[test request] tipset assembly in real-world network conditions (monte carlo simulation) filecoin-project/oni#14

Open

raulk added 12 commits July 20, 2020 16:37

add mpool journal events; fix dependency injection.

7459ec6

pipe sealing events to the journal.

d6e6eed

message pool: write message(s) in journal entries.

3bd9d55

journal: disable noisy message pool events.

cb8e209

record deals events in journal.

d547c25

rename journal entries to journal events.

4e82cf3

fix tests.

443473f

Merge branch 'next' into inmem-journal

b847511

move in-mem journal to Project Oni.

5074ce5

Merge branch 'next' into inmem-journal

9259823

Merge remote-tracking branch 'origin/next' into inmem-journal

bca516b

add comment.

5e2c28d

raulk commented Aug 11, 2020

View reviewed changes

raulk changed the title ~~wip in-memory journal.~~ make journal pluggable; record deals, sealing, wdpost, mempool events Aug 11, 2020

raulk mentioned this pull request Aug 11, 2020

introduce notifications for sector state transitions. filecoin-project/storage-fsm#54

Closed

storage-fsm: emit sealing state transition notifications.

d53c6f2

raulk force-pushed the inmem-journal branch from 47bfcd1 to d53c6f2 Compare August 11, 2020 12:24

raulk added 2 commits August 11, 2020 13:48

wire journal into miner.

2ea5abd

panic recovery in MaybeRecordEvent; handle nil current tipsets in wdp…

b534ab9

…ost.

Base automatically changed from next to master August 19, 2020 00:14

raulk added 3 commits August 26, 2020 16:09

make journal a global var.

4e1ef09

Merge branch 'master' into inmem-journal

efdfd3e

reduce diff noise.

cb8e105

magik6k reviewed Aug 31, 2020

View reviewed changes

raulk added 3 commits September 2, 2020 19:15

move InitJournalKey to the top; add godcs on invoke order.

0b6a182

shuffle code to journal wdpost events.

ac152ab

split wdpost event into finer-grained ones.

f046af3

raulk requested a review from magik6k September 2, 2020 18:46

raulk added 3 commits September 2, 2020 19:46

go mod tidy.

fd04a19

Merge branch 'master' into inmem-journal

3206f92

fix lotus-bench stale import.

4554c4b

raulk added 7 commits September 3, 2020 15:51

fix imports.

97ff90f

fix test following merge.

d46f684

fix lint errors.

905168e

Merge branch 'master' into inmem-journal

1ec534d

fix dangling import.

0a4c473

Merge branch 'master' into inmem-journal

35a8f7e

Merge branch 'master' into inmem-journal

6d29d75

raulk requested a review from whyrusleeping as a code owner September 14, 2020 11:17

raulk added 4 commits September 14, 2020 13:01

allow customizing disabled journal events + tests.

05aa5f2

deal journal events: wire into markets subscriptions.

09e9d6d

Merge branch 'master' into inmem-journal

7c13fa9

fix transitive api dependency on ffi.

954ff32

whyrusleeping approved these changes Sep 14, 2020

View reviewed changes

whyrusleeping merged commit b212368 into master Sep 14, 2020

whyrusleeping deleted the inmem-journal branch September 14, 2020 18:17

raulk mentioned this pull request Jan 18, 2021

journal the world! #2441

Closed

10 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

make journal pluggable; record deals, sealing, wdpost, mempool events #2455

make journal pluggable; record deals, sealing, wdpost, mempool events #2455

raulk commented Jul 17, 2020 •

edited

raulk Aug 11, 2020

raulk Aug 11, 2020

magik6k Aug 31, 2020

raulk Sep 2, 2020

raulk Sep 2, 2020

raulk Aug 11, 2020

magik6k Aug 31, 2020

magik6k left a comment

magik6k Aug 31, 2020

raulk Sep 2, 2020

magik6k Aug 31, 2020

magik6k Aug 31, 2020

raulk Sep 2, 2020

magik6k Aug 31, 2020

raulk commented Sep 2, 2020

whyrusleeping left a comment

RobQuistNL commented Sep 18, 2020


		func (n *nilJournal) RegisterEventType(_, _ string) EventType { return EventType{} }

		func (n *nilJournal) RecordEvent(_ EventType, _ func() interface{}) {}

make journal pluggable; record deals, sealing, wdpost, mempool events #2455

make journal pluggable; record deals, sealing, wdpost, mempool events #2455

Conversation

raulk commented Jul 17, 2020 • edited

What has been done here

New journal events

Journal framework

Example journal events

Sealing state machine transitions

Windowed PoSt

mpool

Deals

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

magik6k left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

raulk commented Sep 2, 2020

whyrusleeping left a comment

Choose a reason for hiding this comment

RobQuistNL commented Sep 18, 2020

raulk commented Jul 17, 2020 •

edited