From 96a98bc0716e920388402333af9972400ed826fe Mon Sep 17 00:00:00 2001 From: Olaoluwa Osuntokun Date: Mon, 5 Feb 2024 19:05:02 -0800 Subject: [PATCH] protofsm: add logging --- protofsm/state_machine.go | 76 ++++++++++++++++++++++++++++++++-- protofsm/state_machine_test.go | 6 ++- 2 files changed, 78 insertions(+), 4 deletions(-) diff --git a/protofsm/state_machine.go b/protofsm/state_machine.go index 2a62ac223..f922f536c 100644 --- a/protofsm/state_machine.go +++ b/protofsm/state_machine.go @@ -8,8 +8,10 @@ import ( "github.com/btcsuite/btcd/btcec/v2" "github.com/btcsuite/btcd/chaincfg/chainhash" "github.com/btcsuite/btcd/wire" + "github.com/davecgh/go-spew/spew" "github.com/lightningnetwork/lnd/chainntnfs" "github.com/lightningnetwork/lnd/fn" + "github.com/lightningnetwork/lnd/lnutils" "github.com/lightningnetwork/lnd/lnwire" ) @@ -204,6 +206,10 @@ func (s *StateMachine[Event, Env]) Stop() { // // TODO(roasbeef): bool if processed? func (s *StateMachine[Event, Env]) SendEvent(event Event) { + log.Debugf("FSM(%v): sending event: %v", s.cfg.Env.Name(), + lnutils.SpewLogClosure(event), + ) + select { case s.events <- event: case <-s.quit: @@ -236,6 +242,10 @@ func (s *StateMachine[Event, Env]) SendMessage(msg lnwire.Message) bool { return false } + log.Debugf("FSM(%v): sending msg: %v", s.cfg.Env.Name(), + lnutils.SpewLogClosure(msg), + ) + // Otherwise, try to map the message using the default message mapper. // If we can't extract an event, then we'll return false to indicate // that the message wasn't processed. @@ -295,12 +305,20 @@ func (s *StateMachine[Event, Env]) RemoveStateSub(sub StateSubscriber[ // executeDaemonEvent executes a daemon event, which is a special type of event // that can be emitted as part of the state transition function of the state // machine. An error is returned if the type of event is unknown. -func (s *StateMachine[Event, Env]) executeDaemonEvent(event DaemonEvent) error { +func (s *StateMachine[Event, Env]) executeDaemonEvent( //nolint:funlen + event DaemonEvent) error { + switch daemonEvent := event.(type) { // This is a send message event, so we'll send the event, and also mind // any preconditions as well as post-send events. case *SendMsgEvent[Event]: sendAndCleanUp := func() error { + log.Debugf("FSM(%v): sending message to target(%v): "+ + "%v", s.cfg.Env.Name(), + daemonEvent.TargetPeer.SerializeCompressed(), + lnutils.SpewLogClosure(daemonEvent.Msgs), + ) + err := s.cfg.Daemon.SendMessages( daemonEvent.TargetPeer, daemonEvent.Msgs, ) @@ -317,6 +335,12 @@ func (s *StateMachine[Event, Env]) executeDaemonEvent(event DaemonEvent) error { go func() { defer s.wg.Done() + log.Debugf("FSM(%v): sending "+ + "post-send event: %v", + s.cfg.Env.Name(), + lnutils.SpewLogClosure(event), + ) + s.SendEvent(event) }() }) @@ -340,6 +364,9 @@ func (s *StateMachine[Event, Env]) executeDaemonEvent(event DaemonEvent) error { predicateTicker := time.NewTicker(pollInterval) defer predicateTicker.Stop() + log.Infof("FSM(%v): waiting for send predicate to "+ + "be true", s.cfg.Env.Name()) + for { select { case <-predicateTicker.C: @@ -351,6 +378,10 @@ func (s *StateMachine[Event, Env]) executeDaemonEvent(event DaemonEvent) error { ) if canSend { + log.Infof("FSM(%v): send "+ + "active predicate", + s.cfg.Env.Name()) + err := sendAndCleanUp() if err != nil { //nolint:lll @@ -371,6 +402,9 @@ func (s *StateMachine[Event, Env]) executeDaemonEvent(event DaemonEvent) error { // If this is a broadcast transaction event, then we'll broadcast with // the label attached. case *BroadcastTxn: + log.Debugf("FSM(%v): broadcasting txn, txid=%v", + s.cfg.Env.Name(), daemonEvent.Tx.TxHash()) + err := s.cfg.Daemon.BroadcastTransaction( daemonEvent.Tx, daemonEvent.Label, ) @@ -383,6 +417,9 @@ func (s *StateMachine[Event, Env]) executeDaemonEvent(event DaemonEvent) error { // The state machine has requested a new event to be sent once a // transaction spending a specified outpoint has confirmed. case *RegisterSpend[Event]: + log.Debugf("FSM(%v): registering spend: %v", s.cfg.Env.Name(), + daemonEvent.OutPoint) + spendEvent, err := s.cfg.Daemon.RegisterSpendNtfn( &daemonEvent.OutPoint, daemonEvent.PkScript, daemonEvent.HeightHint, @@ -418,6 +455,9 @@ func (s *StateMachine[Event, Env]) executeDaemonEvent(event DaemonEvent) error { // The state machine has requested a new event to be sent once a // specified txid+pkScript pair has confirmed. case *RegisterConf[Event]: + log.Debugf("FSM(%v): registering conf: %v", s.cfg.Env.Name(), + daemonEvent.Txid) + numConfs := daemonEvent.NumConfs.UnwrapOr(1) confEvent, err := s.cfg.Daemon.RegisterConfirmationsNtfn( &daemonEvent.Txid, daemonEvent.PkScript, @@ -462,6 +502,12 @@ func (s *StateMachine[Event, Env]) executeDaemonEvent(event DaemonEvent) error { func (s *StateMachine[Event, Env]) applyEvents(currentState State[Event, Env], newEvent Event) (State[Event, Env], error) { + log.Debugf("FSM(%v): applying new event", s.cfg.Env.Name(), + lnutils.NewLogClosure(func() string { + return spew.Sdump(newEvent) + }), + ) + eventQueue := fn.NewQueue(newEvent) // Given the next event to handle, we'll process the event, then add @@ -472,6 +518,13 @@ func (s *StateMachine[Event, Env]) applyEvents(currentState State[Event, Env], //nolint:lll for nextEvent := eventQueue.Dequeue(); nextEvent.IsSome(); nextEvent = eventQueue.Dequeue() { err := fn.MapOptionZ(nextEvent, func(event Event) error { + log.Debugf("FSM(%v): processing event: %v", + s.cfg.Env.Name(), + lnutils.NewLogClosure(func() string { + return spew.Sdump(event) + }), + ) + // Apply the state transition function of the current // state given this new event and our existing env. transition, err := currentState.ProcessEvent( @@ -489,6 +542,10 @@ func (s *StateMachine[Event, Env]) applyEvents(currentState State[Event, Env], // //nolint:lll err := fn.MapOptionZ(events.ExternalEvents, func(dEvents DaemonEventSet) error { + log.Debugf("FSM(%v): processing "+ + "daemon %v daemon events", + s.cfg.Env.Name(), len(dEvents)) + for _, dEvent := range dEvents { err := s.executeDaemonEvent( dEvent, @@ -508,8 +565,19 @@ func (s *StateMachine[Event, Env]) applyEvents(currentState State[Event, Env], // our event queue. // //nolint:lll - events.InternalEvent.WhenSome(func(inEvent Event) { - eventQueue.Enqueue(inEvent) + events.InternalEvent.WhenSome(func(es Event) { + log.Debugf("FSM(%v): adding "+ + "new internal event "+ + "to queue: %v", + s.cfg.Env.Name(), + lnutils.NewLogClosure(func() string { //nolint:lll + return spew.Sdump( //nolint:lll + es, + ) + }), + ) + + eventQueue.Enqueue(es) }) return nil @@ -544,6 +612,8 @@ func (s *StateMachine[Event, Env]) applyEvents(currentState State[Event, Env], func (s *StateMachine[Event, Env]) driveMachine() { defer s.wg.Done() + log.Debugf("FSM(%v): starting state machine", s.cfg.Env.Name()) + currentState := s.cfg.InitialState // Before we start, if we have an init daemon event specified, then diff --git a/protofsm/state_machine_test.go b/protofsm/state_machine_test.go index bf7026f4e..0a09af60b 100644 --- a/protofsm/state_machine_test.go +++ b/protofsm/state_machine_test.go @@ -113,7 +113,11 @@ func (d *dummyStateStart) ProcessEvent(event dummyEvents, env *dummyEnv, }, NewEvents: fn.Some(EmittedEvent[dummyEvents]{ ExternalEvents: fn.Some(DaemonEventSet{ - sendEvent, &BroadcastTxn{}, sendEvent2, + sendEvent, sendEvent2, + &BroadcastTxn{ + Tx: &wire.MsgTx{}, + Label: "test", + }, }), }), }, nil