protofsm: update GR Manager usage and start using structured logging #9342

ellemouton · 2024-12-10T05:46:08Z

This PR touches the protofsm package for 2 reasons:

update to use the latest GoroutineManager API introduced in: fn: Remove ctx from GoroutineManager constructor #9341
Update the StateMachine to thread a context through and to take a context via its API methods where it makes sense. With this update, logging can also be switched to the new structured logging pattern which allows us to avoid having to specify the FSM(%V) string for each log line

Depends on: btcsuite/btclog#20
Depends on: #9341

coderabbitai · 2024-12-10T05:46:15Z

Important

Review skipped

Auto reviews are limited to specific labels.

🏷️ Labels to auto review (1)

llm-review

Please check the settings in the CodeRabbit UI or the .coderabbit.yaml file in this repository. To trigger a single review, invoke the @coderabbitai review command.

You can disable this status message by setting the reviews.review_status to false in the CodeRabbit configuration file.

Thank you for using CodeRabbit. We offer it for free to the OSS community and would appreciate your support in helping us grow. If you find it useful, would you consider giving us a shout-out on your favorite social media?

❤️ Share

🪧 Tips

Chat

There are 3 ways to chat with CodeRabbit:

Review comments: Directly reply to a review comment made by CodeRabbit. Example:
- I pushed a fix in commit <commit_id>, please review it.
- Generate unit testing code for this file.
- Open a follow-up GitHub issue for this discussion.
Files and specific lines of code (under the "Files changed" tab): Tag @coderabbitai in a new review comment at the desired location with your query. Examples:
- @coderabbitai generate unit testing code for this file.
- @coderabbitai modularize this function.
PR comments: Tag @coderabbitai in a new PR comment to ask questions about the PR branch. For the best results, please provide a very specific query, as very limited context is provided in this mode. Examples:
- @coderabbitai gather interesting stats about this repository and render them as a table. Additionally, render a pie chart showing the language distribution in the codebase.
- @coderabbitai read src/utils.ts and generate unit testing code.
- @coderabbitai read the files in the src/scheduler package and generate a class diagram using mermaid and a README in the markdown format.
- @coderabbitai help me debug CodeRabbit configuration file.

Note: Be mindful of the bot's finite context window. It's strongly recommended to break down tasks such as reading entire modules into smaller chunks. For a focused discussion, use review comments to chat about specific files and their changes, instead of using the PR comments.

CodeRabbit Commands (Invoked using PR comments)

@coderabbitai pause to pause the reviews on a PR.
@coderabbitai resume to resume the paused reviews.
@coderabbitai review to trigger an incremental review. This is useful when automatic reviews are disabled for the repository.
@coderabbitai full review to do a full review from scratch and review all the files again.
@coderabbitai summary to regenerate the summary of the PR.
@coderabbitai generate docstrings to generate docstrings for this PR. (Experiment)
@coderabbitai resolve resolve all the CodeRabbit review comments.
@coderabbitai configuration to show the current CodeRabbit configuration for the repository.
@coderabbitai help to get help.

Other keywords and placeholders

Add @coderabbitai ignore anywhere in the PR description to prevent this PR from being reviewed.
Add @coderabbitai summary to generate the high-level summary at a specific location in the PR description.
Add @coderabbitai anywhere in the PR title to generate the title automatically.

CodeRabbit Configuration File (`.coderabbit.yaml`)

You can programmatically configure CodeRabbit by adding a .coderabbit.yaml file to the root of your repository.
Please see the configuration documentation for more information.
If your editor has YAML language server enabled, you can add the path at the top of this file to enable auto-completion and validation: # yaml-language-server: $schema=https://coderabbit.ai/integrations/schema.v2.json

Documentation and Community

Visit our Documentation for detailed information on how to use CodeRabbit.
Join our Discord Community to get help, request features, and share feedback.
Follow us on X/Twitter for updates and announcements.

Roasbeef · 2024-12-10T10:00:24Z

go.mod

@@ -213,3 +213,5 @@ replace google.golang.org/protobuf => github.com/lightninglabs/protobuf-go-hex-d
 go 1.22.6

 retract v0.0.2
+
+replace github.com/lightningnetwork/lnd/fn/v2 => github.com/ellemouton/lnd/fn/v2 v2.0.0-20241210050749-8c19ec06a189


FWIW in #8512 I've made the change to update to v2 just need to get CI grteen there (check commits failing IIRC) and it should be g2g there.

Roasbeef · 2024-12-10T10:02:03Z

protofsm/state_machine.go

 }

 // sendEvent sends a new event to the state machine.
-func (s *StateMachine[Event, Env]) sendEvent(event Event) {
+func (s *StateMachine[Event, Env]) sendEvent(ctx context.Context, event Event) {


What was the motivation re the change in the prior commit? To only have the private method be what selects on the context?

see the next commit which does the context decoration on any incoming ctx

Roasbeef · 2024-12-10T10:02:58Z

protofsm/state_machine.go

@@ -101,8 +102,8 @@ type DaemonAdapters interface {
 	// TODO(roasbeef): could abstract further?
 	RegisterConfirmationsNtfn(txid *chainhash.Hash, pkScript []byte,
 		numConfs, heightHint uint32,
-		opts ...chainntnfs.NotifierOption,


Prob the main stylistic diff in the codebase rn, but I prefer this option as it makes it clearer where the args end, and the return value starts.

Imo that only holds if the return values can in-fact fit on one line which is not always the case.
Personally I find the ) { on the unindented line strange

Roasbeef · 2024-12-10T10:03:57Z

protofsm/state_machine.go

-				daemonEvent.TargetPeer.SerializeCompressed(),
-				lnutils.SpewLogClosure(daemonEvent.Msgs),
-			)
+			log.DebugS(ctx, "Sending message",


Do you have a print sample of the before and after here re formatting?

yeah here is an example:

2024-12-10 13:08:43.637 [DBG]: Processing daemon events fsm_name=test num_events=3 2024-12-10 13:08:43.637 [DBG]: Sending message fsm_name=test target=0356167ba3e5 msgs=([]lnwire.Message) <nil> 2024-12-10 13:08:43.637 [INF]: Waiting for send predicate to be true fsm_name=test 2024-12-10 13:08:43.637 [DBG]: Broadcasting txn fsm_name=test txid=f702453dd03b0f055e5437d76128141803984fb10acb85fc3b2184fae2f3fa78 2024-12-10 13:08:43.638 [INF]: State transition fsm_name=test from_state=*protofsm.dummyStateStart to_state=*protofsm.dummyStateStart 2024-12-10 13:08:43.740 [INF]: Send active predicate fsm_name=test 2024-12-10 13:08:43.740 [DBG]: Sending message fsm_name=test target=02ec95e4e8ad msgs=([]lnwire.Message) <nil> 2024-12-10 13:08:43.740 [DBG]: Sending post-send event fsm_name=test event=(*protofsm.goToFin)(0x100cb5240)({ }) 2024-12-10 13:08:43.740 [DBG]: Sending event fsm_name=test event=(*protofsm.goToFin)(0x100cb5240)({ }) 2024-12-10 13:08:43.740 [DBG]: Applying new event fsm_name=test event=(*protofsm.goToFin)(0x100cb5240)({ }) 2024-12-10 13:08:43.740 [DBG]: Processing event fsm_name=test event=(*protofsm.goToFin)(0x100cb5240)({ }) 2024-12-10 13:08:43.740 [INF]: State transition fsm_name=test from_state=*protofsm.dummyStateStart to_state=*protofsm.dummyStateFin

see other comment re the prefix: with the prefixed logger, they now look like this:

2024-12-10 13:20:44.552 [DBG]: FSM(test) Starting state machine 2024-12-10 13:20:44.552 [DBG]: FSM(test) Sending event event=(*protofsm.emitInternal)(0x1045f1240)({ }) 2024-12-10 13:20:44.552 [DBG]: FSM(test) Applying new event event=(*protofsm.emitInternal)(0x1045f1240)({ }) 2024-12-10 13:20:44.552 [DBG]: FSM(test) Processing event event=(*protofsm.emitInternal)(0x1045f1240)({ }) 2024-12-10 13:20:44.552 [DBG]: FSM(test) Adding new internal event to queue event !BADKEY=(*protofsm.goToFin)(0x1045f1240)({ }) 2024-12-10 13:20:44.552 [INF]: FSM(test) State transition from_state=*protofsm.dummyStateStart to_state=*protofsm.dummyStateStart 2024-12-10 13:20:44.552 [DBG]: FSM(test) Processing event event=(*protofsm.goToFin)(0x1045f1240)({ }) 2024-12-10 13:20:44.552 [INF]: FSM(test) State transition from_state=*protofsm.dummyStateStart to_state=*protofsm.dummyStateFin

Roasbeef · 2024-12-10T10:04:57Z

protofsm/state_machine.go

-					log.Debugf("FSM(%v): processing "+
-						"daemon %v daemon events",
-						s.cfg.Env.Name(), len(dEvents))
+					log.DebugS(ctx, "Processing daemon events",


Is this upper case construct something new we're attempting to make standard with the new logging format?

I think in general we go for log lines that start with upper case? searching around the code base, i can see that most of our log lines start with an upper case letter

Roasbeef · 2024-12-10T10:06:00Z

protofsm/state_machine.go

+	ctx context.Context) context.Context {
+
+	return btclog.WithCtx(ctx,
+		btclog.Fmt("fsm_name", s.cfg.Env.Name())) //nolint:govet


Is there anyway we can keep the old prefix nature? At least when scanning, IMO it's useful for it to be at the very start as depending on the size of your editor/viewport, the end of the line may require moving the cursor to actually view.

as the library stands today, no. But what can be done is: to create a prefixed logger in NewStateMachine and then carry that around in the StateMachine struct. Then we just need to remember to do s.log.* for log lines.

shall we do that instead here?

ok i've added a temporary commit at the end that does it this way. Let me know if you think this is ok and i can squash in the change.

The logs now look like this:

2024-12-10 13:20:44.552 [DBG]: FSM(test) Starting state machine 2024-12-10 13:20:44.552 [DBG]: FSM(test) Sending event event=(*protofsm.emitInternal)(0x1045f1240)({ }) 2024-12-10 13:20:44.552 [DBG]: FSM(test) Applying new event event=(*protofsm.emitInternal)(0x1045f1240)({ }) 2024-12-10 13:20:44.552 [DBG]: FSM(test) Processing event event=(*protofsm.emitInternal)(0x1045f1240)({ }) 2024-12-10 13:20:44.552 [DBG]: FSM(test) Adding new internal event to queue event !BADKEY=(*protofsm.goToFin)(0x1045f1240)({ }) 2024-12-10 13:20:44.552 [INF]: FSM(test) State transition from_state=*protofsm.dummyStateStart to_state=*protofsm.dummyStateStart 2024-12-10 13:20:44.552 [DBG]: FSM(test) Processing event event=(*protofsm.goToFin)(0x1045f1240)({ }) 2024-12-10 13:20:44.552 [INF]: FSM(test) State transition from_state=*protofsm.dummyStateStart to_state=*protofsm.dummyStateFin

ellemouton

Thanks for taking a look @Roasbeef - responded to your comments

ellemouton · 2024-12-10T10:08:43Z

protofsm/state_machine.go

 }

 // sendEvent sends a new event to the state machine.
-func (s *StateMachine[Event, Env]) sendEvent(event Event) {
+func (s *StateMachine[Event, Env]) sendEvent(ctx context.Context, event Event) {


see the next commit which does the context decoration on any incoming ctx

ellemouton · 2024-12-10T10:12:21Z

protofsm/state_machine.go

-					log.Debugf("FSM(%v): processing "+
-						"daemon %v daemon events",
-						s.cfg.Env.Name(), len(dEvents))
+					log.DebugS(ctx, "Processing daemon events",


I think in general we go for log lines that start with upper case? searching around the code base, i can see that most of our log lines start with an upper case letter

ellemouton · 2024-12-10T10:13:59Z

protofsm/state_machine.go

+	ctx context.Context) context.Context {
+
+	return btclog.WithCtx(ctx,
+		btclog.Fmt("fsm_name", s.cfg.Env.Name())) //nolint:govet


as the library stands today, no. But what can be done is: to create a prefixed logger in NewStateMachine and then carry that around in the StateMachine struct. Then we just need to remember to do s.log.* for log lines.

shall we do that instead here?

In preparation for the next commit where we will do some context decorating of any incoming context that crosses the StateMachine's API boundary, we make sure to differentiate between exported and unexported methods here.

ellemouton force-pushed the slogProtofsm branch from 8c9dad2 to 2fefda4 Compare December 10, 2024 08:32

Roasbeef requested changes Dec 10, 2024

View reviewed changes

ellemouton commented Dec 10, 2024

View reviewed changes

ellemouton added 6 commits December 10, 2024 13:13

go.mod: update btclog dep

63a9bd7

protofsm: use updated GoroutineManager API

19abb76

protofsm: dont call exported API methods internally

ca96f70

In preparation for the next commit where we will do some context decorating of any incoming context that crosses the StateMachine's API boundary, we make sure to differentiate between exported and unexported methods here.

protofsm: thread a caller context through where appropriate

5396055

protofsm: update to take ctx and use structured logging

2805afc

docs: add release notes entry

a86da09

ellemouton force-pushed the slogProtofsm branch from 2fefda4 to a86da09 Compare December 10, 2024 11:15

protofsm: use prefixed logger instead

6526c62

ellemouton requested a review from Roasbeef December 10, 2024 11:23

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

protofsm: update GR Manager usage and start using structured logging #9342

protofsm: update GR Manager usage and start using structured logging #9342

ellemouton commented Dec 10, 2024 •

edited

Loading

coderabbitai bot commented Dec 10, 2024

Review skipped

Chat

CodeRabbit Commands (Invoked using PR comments)

Other keywords and placeholders

CodeRabbit Configuration File (`.coderabbit.yaml`)

Documentation and Community

Roasbeef Dec 10, 2024

Roasbeef Dec 10, 2024

ellemouton Dec 10, 2024

Roasbeef Dec 10, 2024

ellemouton Dec 10, 2024

Roasbeef Dec 10, 2024

ellemouton Dec 10, 2024

ellemouton Dec 10, 2024

Roasbeef Dec 10, 2024

ellemouton Dec 10, 2024

Roasbeef Dec 10, 2024

ellemouton Dec 10, 2024

ellemouton Dec 10, 2024

ellemouton left a comment

ellemouton Dec 10, 2024

ellemouton Dec 10, 2024

ellemouton Dec 10, 2024

protofsm: update GR Manager usage and start using structured logging #9342

Are you sure you want to change the base?

protofsm: update GR Manager usage and start using structured logging #9342

Conversation

ellemouton commented Dec 10, 2024 • edited Loading

coderabbitai bot commented Dec 10, 2024

Review skipped

Chat

CodeRabbit Commands (Invoked using PR comments)

Other keywords and placeholders

CodeRabbit Configuration File (.coderabbit.yaml)

Documentation and Community

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

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

ellemouton 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

ellemouton commented Dec 10, 2024 •

edited

Loading

CodeRabbit Configuration File (`.coderabbit.yaml`)