Swap logger (#1754)

* api,debug,log,main,swap,swarm: adds swap specific logger and saves to disk if --swap-audit-logpath is specified

Author: santicomp2014

api/config.go

@@ -57,6 +57,7 @@ type Config struct {
 	SwapEnabled             bool           // whether SWAP incentives are enabled
 	SwapPaymentThreshold    uint64         // honey amount at which a payment is triggered
 	SwapDisconnectThreshold uint64         // honey amount at which a peer disconnects
+	SwapLogPath             string         // dir to swap related audit logs
 	Contract                common.Address // address of the chequebook contract
 	// end of Swap configs
 
@@ -94,6 +95,7 @@ func NewConfig() (c *Config) {
 		SwapEnabled:             false,
 		SwapPaymentThreshold:    swap.DefaultPaymentThreshold,
 		SwapDisconnectThreshold: swap.DefaultDisconnectThreshold,
+		SwapLogPath:             "",
 		HiveParams:              network.NewHiveParams(),
 		Pss:                     pss.NewParams(),
 		EnsRoot:                 ens.TestNetAddress,

cmd/swarm/config.go

@@ -69,6 +69,7 @@ const (
 	SwarmEnvSwapBackendURL          = "SWARM_SWAP_BACKEND_URL"
 	SwarmEnvSwapPaymentThreshold    = "SWARM_SWAP_PAYMENT_THRESHOLD"
 	SwarmEnvSwapDisconnectThreshold = "SWARM_SWAP_DISCONNECT_THRESHOLD"
+	SwarmEnvSwapLogPath             = "SWARM_SWAP_LOG_PATH"
 	SwarmEnvSyncDisable             = "SWARM_SYNC_DISABLE"
 	SwarmEnvSyncUpdateDelay         = "SWARM_ENV_SYNC_UPDATE_DELAY"
 	SwarmEnvMaxStreamPeerServers    = "SWARM_ENV_MAX_STREAM_PEER_SERVERS"
@@ -204,6 +205,9 @@ func flagsOverride(currentConfig *bzzapi.Config, ctx *cli.Context) *bzzapi.Confi
 	if swapBackendURL := ctx.GlobalString(SwarmSwapBackendURLFlag.Name); swapBackendURL != "" {
 		currentConfig.SwapBackendURL = swapBackendURL
 	}
+	if swapLogPath := ctx.GlobalString(SwarmSwapLogPathFlag.Name); currentConfig.SwapEnabled && swapLogPath != "" {
+		currentConfig.SwapLogPath = swapLogPath
+	}
 	if paymentThreshold := ctx.GlobalUint64(SwarmSwapPaymentThresholdFlag.Name); paymentThreshold != 0 {
 		currentConfig.SwapPaymentThreshold = paymentThreshold
 	}

cmd/swarm/flags.go

@@ -79,6 +79,11 @@ var (
 		Usage:  "honey amount at which a peer disconnects",
 		EnvVar: SwarmEnvSwapDisconnectThreshold,
 	}
+	SwarmSwapLogPathFlag = cli.StringFlag{
+		Name:   "swap-audit-logpath",
+		Usage:  "Write execution logs of swap audit to the given directory",
+		EnvVar: SwarmEnvSwapLogPath,
+	}
 	SwarmSyncDisabledFlag = cli.BoolTFlag{
 		Name:   "nosync",
 		Usage:  "Disable swarm syncing",

cmd/swarm/main.go

@@ -181,6 +181,7 @@ func init() {
 		SwarmSwapBackendURLFlag,
 		SwarmSwapDisconnectThresholdFlag,
 		SwarmSwapPaymentThresholdFlag,
+		SwarmSwapLogPathFlag,
 		SwarmSwapChequebookAddrFlag,
 		// end of swap flags
 		SwarmSyncDisabledFlag,

internal/debug/flags.go

@@ -110,17 +110,23 @@ func init() {
 	glogger = log.NewGlogHandler(ostream)
 }
 
+// rotatingFileHandler returns a RotatingFileHandler this will split the logs into multiple files.
+// the files are split based on the limit parameter expressed in bytes
+func rotatingFileHandler(logdir string) (log.Handler, error) {
+	return log.RotatingFileHandler(
+		logdir,
+		262144,
+		log.JSONFormatOrderedEx(false, true),
+	)
+}
+
 // Setup initializes profiling and logging based on the CLI flags.
 // It should be called as early as possible in the program.
 func Setup(ctx *cli.Context, logdir string) error {
 	// logging
 	log.PrintOrigins(ctx.GlobalBool(debugFlag.Name))
 	if logdir != "" {
-		rfh, err := log.RotatingFileHandler(
-			logdir,
-			262144,
-			log.JSONFormatOrderedEx(false, true),
-		)
+		rfh, err := rotatingFileHandler(logdir)
 		if err != nil {
 			return err
 		}

log/log.go

@@ -46,3 +46,8 @@ func Trace(msg string, ctx ...interface{}) {
 	metrics.GetOrRegisterCounter("trace", nil).Inc(1)
 	l.Output(msg, l.LvlTrace, CallDepth, ctx...)
 }
+
+// GetHandler return the Handler assigned to root
+func GetHandler() l.Handler {
+	return l.Root().GetHandler()
+}

swap/peer.go

@@ -24,7 +24,6 @@ import (
 	"sync"
 
 	"github.com/ethereum/go-ethereum/common"
-	"github.com/ethersphere/swarm/log"
 	"github.com/ethersphere/swarm/p2p/protocols"
 )
 
@@ -109,7 +108,7 @@ func (p *Peer) updateBalance(amount int64) error {
 	if err := p.setBalance(newBalance); err != nil {
 		return err
 	}
-	log.Debug("balance for peer after accounting", "peer", p.ID().String(), "balance", strconv.FormatInt(newBalance, 10))
+	auditLog.Debug("balance for peer after accounting", "peer", p.ID().String(), "balance", strconv.FormatInt(newBalance, 10))
 	return nil
 }
 
@@ -165,7 +164,7 @@ func (p *Peer) sendCheque() error {
 		return err
 	}
 
-	log.Info("sending cheque", "honey", cheque.Honey, "cumulativePayout", cheque.ChequeParams.CumulativePayout, "beneficiary", cheque.Beneficiary, "contract", cheque.Contract)
+	auditLog.Info("sending cheque", "honey", cheque.Honey, "cumulativePayout", cheque.ChequeParams.CumulativePayout, "beneficiary", cheque.Beneficiary, "contract", cheque.Contract)
 	return p.Send(context.Background(), &EmitChequeMsg{
 		Cheque: cheque,
 	})

swap/protocol.go

@@ -21,12 +21,12 @@ import (
 	"errors"
 
 	"github.com/ethereum/go-ethereum/common"
+	"github.com/ethereum/go-ethereum/log"
 	"github.com/ethereum/go-ethereum/p2p/enode"
 
 	"github.com/ethereum/go-ethereum/p2p"
 	"github.com/ethereum/go-ethereum/rpc"
 	contract "github.com/ethersphere/swarm/contracts/swap"
-	"github.com/ethersphere/swarm/log"
 	"github.com/ethersphere/swarm/p2p/protocols"
 )
 

swap/protocol_test.go

@@ -36,8 +36,14 @@ import (
 	contract "github.com/ethersphere/swarm/contracts/swap"
 	"github.com/ethersphere/swarm/p2p/protocols"
 	p2ptest "github.com/ethersphere/swarm/p2p/testing"
+	colorable "github.com/mattn/go-colorable"
 )
 
+func init() {
+	log.PrintOrigins(true)
+	log.Root().SetHandler(log.LvlFilterHandler(log.Lvl(*loglevel), log.StreamHandler(colorable.NewColorableStderr(), log.TerminalFormat(true))))
+}
+
 /*
 TestHandshake creates two mock nodes and initiates an exchange;
 it expects a handshake to take place between the two nodes

swap/swap.go

@@ -32,17 +32,22 @@ import (
 	"github.com/ethereum/go-ethereum/core/types"
 	"github.com/ethereum/go-ethereum/crypto"
 	"github.com/ethereum/go-ethereum/ethclient"
+	"github.com/ethereum/go-ethereum/log"
 	"github.com/ethereum/go-ethereum/p2p/enode"
 	"github.com/ethersphere/swarm/contracts/swap"
 	contract "github.com/ethersphere/swarm/contracts/swap"
-	"github.com/ethersphere/swarm/log"
 	"github.com/ethersphere/swarm/p2p/protocols"
 	"github.com/ethersphere/swarm/state"
 )
 
 // ErrInvalidChequeSignature indicates the signature on the cheque was invalid
 var ErrInvalidChequeSignature = errors.New("invalid cheque signature")
 
+var auditLog log.Logger // logger for Swap related messages and audit trail
+
+// swapLogLevel indicates filter level of log messages
+const swapLogLevel = 3
+
 // Swap represents the Swarm Accounting Protocol
 // a peer to peer micropayment system
 // A node maintains an individual balance with every peer
@@ -80,8 +85,42 @@ func NewParams() *Params {
 	}
 }
 
+// newLogger returns a new logger
+func newLogger(logpath string) log.Logger {
+	swapLogger := log.New("swaplog", "*")
+
+	lh := log.Root().GetHandler()
+	rfh, err := swapRotatingFileHandler(logpath)
+
+	if err != nil {
+		log.Warn("RotatingFileHandler was not initialized", "logdir", logpath, "err", err)
+		//sets a fallback logger, it will use the swarm logger.
+		swapLogger.SetHandler(lh)
+		return swapLogger
+	}
+
+	//Filters messages with the correct logLevel for swap
+	rfh = log.LvlFilterHandler(log.Lvl(swapLogLevel), rfh)
+
+	//Dispatches the logs to the default swarm log and also the filtered swap file logger.
+	swapLogger.SetHandler(log.MultiHandler(lh, rfh))
+
+	return swapLogger
+}
+
+// swapRotatingFileHandler returns a RotatingFileHandler this will split the logs into multiple files.
+// the files are split based on the limit parameter expressed in bytes
+func swapRotatingFileHandler(logdir string) (log.Handler, error) {
+	return log.RotatingFileHandler(
+		logdir,
+		262144,
+		log.JSONFormatOrderedEx(false, true),
+	)
+}
+
 // new - swap constructor without integrity check
-func new(stateStore state.Store, prvkey *ecdsa.PrivateKey, backend contract.Backend, disconnectThreshold uint64, paymentThreshold uint64) *Swap {
+func new(logpath string, stateStore state.Store, prvkey *ecdsa.PrivateKey, backend contract.Backend, disconnectThreshold uint64, paymentThreshold uint64) *Swap {
+	auditLog = newLogger(logpath)
 	return &Swap{
 		store:               stateStore,
 		peers:               make(map[enode.ID]*Peer),
@@ -95,7 +134,7 @@ func new(stateStore state.Store, prvkey *ecdsa.PrivateKey, backend contract.Back
 }
 
 // New - swap constructor with integrity checks
-func New(dbPath string, prvkey *ecdsa.PrivateKey, backendURL string, disconnectThreshold uint64, paymentThreshold uint64) (*Swap, error) {
+func New(logpath string, dbPath string, prvkey *ecdsa.PrivateKey, backendURL string, disconnectThreshold uint64, paymentThreshold uint64) (*Swap, error) {
 	// we MUST have a backend
 	if backendURL == "" {
 		return nil, errors.New("swap init error: no backend URL given")
@@ -114,6 +153,7 @@ func New(dbPath string, prvkey *ecdsa.PrivateKey, backendURL string, disconnectT
 		return nil, fmt.Errorf("swap init error: error connecting to Ethereum API %s: %s", backendURL, err)
 	}
 	return new(
+		logpath,
 		stateStore,
 		prvkey,
 		backend,
@@ -185,7 +225,7 @@ func (s *Swap) Add(amount int64, peer *protocols.Peer) (err error) {
 	// It is the peer with a negative balance who sends a cheque, thus we check
 	// that the balance is *below* the threshold
 	if swapPeer.getBalance() <= -s.paymentThreshold {
-		log.Warn("balance for peer went over the payment threshold, sending cheque", "peer", peer.ID().String(), "payment threshold", s.paymentThreshold)
+		auditLog.Info("balance for peer went over the payment threshold, sending cheque", "peer", peer.ID().String(), "payment threshold", s.paymentThreshold)
 		return swapPeer.sendCheque()
 	}
 
@@ -212,13 +252,13 @@ func (s *Swap) handleEmitChequeMsg(ctx context.Context, p *Peer, msg *EmitCheque
 	defer p.lock.Unlock()
 
 	cheque := msg.Cheque
-	log.Info("received cheque from peer", "peer", p.ID().String(), "honey", cheque.Honey)
+	auditLog.Info("received cheque from peer", "peer", p.ID().String(), "honey", cheque.Honey)
 	_, err := s.processAndVerifyCheque(cheque, p)
 	if err != nil {
 		return err
 	}
 
-	log.Debug("received cheque processed and verified", "peer", p.ID().String())
+	auditLog.Debug("received cheque processed and verified", "peer", p.ID().String())
 
 	// reset balance by amount
 	// as this is done by the creditor, receiving the cheque, the amount should be negative,
@@ -249,17 +289,17 @@ func cashCheque(s *Swap, otherSwap contract.Contract, opts *bind.TransactOpts, c
 	if err != nil {
 		// TODO: do something with the error
 		// and we actually need to log this error as we are in an async routine; nobody is handling this error for now
-		log.Error("error cashing cheque", "err", err)
+		auditLog.Error("error cashing cheque", "err", err)
 		return
 	}
 
 	if result.Bounced {
-		log.Error("cheque bounced", "tx", receipt.TxHash)
+		auditLog.Warn("cheque bounced", "tx", receipt.TxHash)
 		return
 		// TODO: do something here
 	}
 
-	log.Debug("cash tx mined", "receipt", receipt)
+	auditLog.Debug("cash tx mined", "receipt", receipt)
 }
 
 // processAndVerifyCheque verifies the cheque and compares it with the last received cheque
@@ -283,7 +323,7 @@ func (s *Swap) processAndVerifyCheque(cheque *Cheque, p *Peer) (uint64, error) {
 	}
 
 	if err := p.setLastReceivedCheque(cheque); err != nil {
-		log.Error("error while saving last received cheque", "peer", p.ID().String(), "err", err.Error())
+		auditLog.Error("error while saving last received cheque", "peer", p.ID().String(), "err", err.Error())
 		// TODO: what do we do here? Related issue: https://github.com/ethersphere/swarm/issues/1515
 	}
 
@@ -432,13 +472,13 @@ func (s *Swap) Deploy(ctx context.Context) error {
 	opts.Value = big.NewInt(int64(s.params.InitialDepositAmount))
 	opts.Context = ctx
 
-	log.Info("deploying new swap", "owner", opts.From.Hex())
+	auditLog.Info("deploying new swap", "owner", opts.From.Hex())
 	address, err := s.deployLoop(opts, s.owner.address, defaultHarddepositTimeoutDuration)
 	if err != nil {
-		log.Error("unable to deploy swap", "error", err)
+		auditLog.Error("unable to deploy swap", "error", err)
 		return err
 	}
-	log.Info("swap deployed", "address", address.Hex(), "owner", opts.From.Hex())
+	auditLog.Info("swap deployed", "address", address.Hex(), "owner", opts.From.Hex())
 
 	return err
 }
@@ -452,11 +492,11 @@ func (s *Swap) deployLoop(opts *bind.TransactOpts, owner common.Address, default
 		}
 
 		if s.contract, tx, err = contract.Deploy(opts, s.backend, owner, defaultHarddepositTimeoutDuration); err != nil {
-			log.Warn("can't send chequebook deploy tx", "try", try, "error", err)
+			auditLog.Warn("can't send chequebook deploy tx", "try", try, "error", err)
 			continue
 		}
 		if addr, err = bind.WaitDeployed(opts.Context, s.backend, tx); err != nil {
-			log.Warn("chequebook deploy error", "try", try, "error", err)
+			auditLog.Warn("chequebook deploy error", "try", try, "error", err)
 			continue
 		}
 		return addr, nil