protofsm: add logging

Author: Roasbeef

protofsm/log.go

@@ -27,3 +27,19 @@ func DisableLog() {
 func UseLogger(logger btclog.Logger) {
 	log = logger
 }
+
+// logClosure is used to provide a closure over expensive logging operations
+// so they aren't performed when the logging level doesn't warrant it.
+type logClosure func() string
+
+// String invokes the underlying function and returns the result.
+func (c logClosure) String() string {
+	return c()
+}
+
+// newLogClosure returns a new closure over a function that returns a string
+// which itself provides a Stringer interface so that it can be used with the
+// logging system.
+func newLogClosure(c func() string) logClosure {
+	return logClosure(c)
+}

protofsm/state_machine.go

@@ -8,6 +8,7 @@ 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/lnwire"
@@ -211,6 +212,12 @@ 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(),
+		newLogClosure(func() string {
+			return spew.Sdump(event)
+		}),
+	)
+
 	select {
 	case s.events <- event:
 	case <-s.quit:
@@ -243,6 +250,12 @@ func (s *StateMachine[Event, Env]) SendMessage(msg lnwire.Message) bool {
 		return false
 	}
 
+	log.Debugf("FSM(%v): sending msg: %v", s.cfg.Env.Name(),
+		newLogClosure(func() string {
+			return spew.Sdump(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.
@@ -302,12 +315,22 @@ 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,
+				newLogClosure(func() string {
+					return spew.Sdump(daemonEvent.Msgs)
+				}),
+			)
+
 			err := s.cfg.Daemon.SendMessages(
 				daemonEvent.TargetPeer, daemonEvent.Msgs,
 			)
@@ -324,6 +347,14 @@ 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(),
+						newLogClosure(func() string {
+							return spew.Sdump(event)
+						}),
+					)
+
 					s.SendEvent(event)
 				}()
 			})
@@ -347,6 +378,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:
@@ -358,6 +392,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
@@ -378,6 +416,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,
 		)
@@ -390,6 +431,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,
@@ -425,6 +469,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,
@@ -469,6 +516,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(),
+		newLogClosure(func() string {
+			return spew.Sdump(newEvent)
+		}),
+	)
+
 	eventQueue := fn.NewQueue(newEvent)
 
 	// Given the next event to handle, we'll process the event, then add
@@ -479,6 +532,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(),
+				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(
@@ -496,6 +556,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,
@@ -516,6 +580,16 @@ func (s *StateMachine[Event, Env]) applyEvents(currentState State[Event, Env],
 				//
 				//nolint:lll
 				events.InternalEvent.WhenSome(func(inEvent Event) {
+					log.Debugf("FSM(%v): adding new "+
+						"internal event to queue: %v",
+						s.cfg.Env.Name(),
+						newLogClosure(func() string {
+							return spew.Sdump(
+								inEvent,
+							)
+						}),
+					)
+
 					eventQueue.Enqueue(inEvent)
 				})
 
@@ -551,6 +625,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

protofsm/state_machine_test.go

@@ -119,7 +119,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