swarm, swap: add addresses to logs

swap/peer.go

@@ -24,6 +24,7 @@ import (
 	"sync"
 
 	"github.com/ethereum/go-ethereum/common"
+	"github.com/ethereum/go-ethereum/log"
 	"github.com/ethersphere/swarm/p2p/protocols"
 )
 
@@ -40,6 +41,7 @@ type Peer struct {
 	lastReceivedCheque *Cheque
 	lastSentCheque     *Cheque
 	balance            int64
+	logger             log.Logger // logger for swap related messages and audit trail with peer identifier
 }
 
 // NewPeer creates a new swap Peer instance
@@ -49,6 +51,7 @@ func NewPeer(p *protocols.Peer, s *Swap, beneficiary common.Address, contractAdd
 		swap:            s,
 		beneficiary:     beneficiary,
 		contractAddress: contractAddress,
+		logger:          newPeerLogger(s, p.ID()),
 	}
 
 	if peer.lastReceivedCheque, err = s.loadLastReceivedCheque(p.ID()); err != nil {
@@ -108,7 +111,7 @@ func (p *Peer) updateBalance(amount int64) error {
 	if err := p.setBalance(newBalance); err != nil {
 		return err
 	}
-	auditLog.Debug("balance for peer after accounting", "peer", p.ID().String(), "balance", strconv.FormatInt(newBalance, 10))
+	p.logger.Debug("updated balance", "balance", strconv.FormatInt(newBalance, 10))
 	return nil
 }
 
@@ -164,7 +167,7 @@ func (p *Peer) sendCheque() error {
 		return err
 	}
 
-	auditLog.Info("sending cheque", "honey", cheque.Honey, "cumulativePayout", cheque.ChequeParams.CumulativePayout, "beneficiary", cheque.Beneficiary, "contract", cheque.Contract)
+	p.logger.Info("sending cheque to peer", "honey", cheque.Honey, "cumulativePayout", cheque.ChequeParams.CumulativePayout, "beneficiary", cheque.Beneficiary, "contract", cheque.Contract)
 	return p.Send(context.Background(), &EmitChequeMsg{
 		Cheque: cheque,
 	})

swap/swap.go

@@ -43,8 +43,6 @@ import (
 // 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
 
@@ -64,6 +62,8 @@ type Swap struct {
 	honeyPriceOracle    HoneyOracle        // oracle which resolves the price of honey (in Wei)
 	paymentThreshold    int64              // honey amount at which a payment is triggered
 	disconnectThreshold int64              // honey amount at which a peer disconnects
+	logpath             string             // path to log files in case they are persisted to disk
+	logger              log.Logger         // logger for swap related messages and audit trail
 }
 
 // Owner encapsulates information related to accessing the contract
@@ -85,27 +85,37 @@ func NewParams() *Params {
 	}
 }
 
-// newLogger returns a new logger
-func newLogger(logpath string) log.Logger {
-	swapLogger := log.New("swaplog", "*")
+// newSwapLogger returns a new logger for standard swap logs
+func newSwapLogger(s *Swap) log.Logger {
+	swapLogger := log.New("swaplog", "*", "selfAddress", s.owner.address)
+	setLoggerHandler(s.logpath, swapLogger)
+	return swapLogger
+}
+
+// newPeerLogger returns a new logger for swap logs with peer info
+func newPeerLogger(s *Swap, peerID enode.ID) log.Logger {
+	peerLogger := log.New("swaplog", "*", "selfAddress", s.owner.address, "peer", peerID)
+	setLoggerHandler(s.logpath, peerLogger)
+	return peerLogger
+}
 
+// setLoggerHandler will set the logger handle to write logs to the specified path
+// or use the default swarm logger in case this isn't specified or an error occurs
+func setLoggerHandler(logpath string, logger log.Logger) {
 	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))
+		// use the default swarm logger as a fallback
+		logger.SetHandler(lh)
+	} else {
+		// filter messages with the correct log level for swap
+		rfh = log.LvlFilterHandler(log.Lvl(swapLogLevel), rfh)
 
-	return swapLogger
+		// dispatch the logs to the default swarm log and also the filtered swap logger
+		logger.SetHandler(log.MultiHandler(lh, rfh))
+	}
 }
 
 // swapRotatingFileHandler returns a RotatingFileHandler this will split the logs into multiple files.
@@ -120,8 +130,7 @@ func swapRotatingFileHandler(logdir string) (log.Handler, error) {
 
 // new - swap constructor without integrity check
 func new(logpath string, stateStore state.Store, prvkey *ecdsa.PrivateKey, backend contract.Backend, disconnectThreshold uint64, paymentThreshold uint64) *Swap {
-	auditLog = newLogger(logpath)
-	return &Swap{
+	s := &Swap{
 		store:               stateStore,
 		peers:               make(map[enode.ID]*Peer),
 		backend:             backend,
@@ -130,7 +139,10 @@ func new(logpath string, stateStore state.Store, prvkey *ecdsa.PrivateKey, backe
 		disconnectThreshold: int64(disconnectThreshold),
 		paymentThreshold:    int64(paymentThreshold),
 		honeyPriceOracle:    NewHoneyPriceOracle(),
+		logpath:             logpath,
 	}
+	s.logger = newSwapLogger(s)
+	return s
 }
 
 // New - swap constructor with integrity checks
@@ -225,7 +237,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 {
-		auditLog.Info("balance for peer went over the payment threshold, sending cheque", "peer", peer.ID().String(), "payment threshold", s.paymentThreshold)
+		swapPeer.logger.Info("balance for peer went over the payment threshold, sending cheque", "payment threshold", s.paymentThreshold)
 		return swapPeer.sendCheque()
 	}
 
@@ -252,13 +264,13 @@ func (s *Swap) handleEmitChequeMsg(ctx context.Context, p *Peer, msg *EmitCheque
 	defer p.lock.Unlock()
 
 	cheque := msg.Cheque
-	auditLog.Info("received cheque from peer", "peer", p.ID().String(), "honey", cheque.Honey)
+	p.logger.Info("received cheque from peer", "honey", cheque.Honey)
 	_, err := s.processAndVerifyCheque(cheque, p)
 	if err != nil {
 		return err
 	}
 
-	auditLog.Debug("received cheque processed and verified", "peer", p.ID().String())
+	p.logger.Debug("received cheque, processed and verified")
 
 	// reset balance by amount
 	// as this is done by the creditor, receiving the cheque, the amount should be negative,
@@ -289,17 +301,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
-		auditLog.Error("error cashing cheque", "err", err)
+		s.logger.Error("error cashing cheque", "err", err)
 		return
 	}
 
 	if result.Bounced {
-		auditLog.Warn("cheque bounced", "tx", receipt.TxHash)
+		s.logger.Warn("cheque bounced", "tx", receipt.TxHash)
 		return
 		// TODO: do something here
 	}
 
-	auditLog.Debug("cash tx mined", "receipt", receipt)
+	s.logger.Debug("cash tx mined", "receipt", receipt)
 }
 
 // processAndVerifyCheque verifies the cheque and compares it with the last received cheque
@@ -323,7 +335,7 @@ func (s *Swap) processAndVerifyCheque(cheque *Cheque, p *Peer) (uint64, error) {
 	}
 
 	if err := p.setLastReceivedCheque(cheque); err != nil {
-		auditLog.Error("error while saving last received cheque", "peer", p.ID().String(), "err", err.Error())
+		p.logger.Error("error while saving last received cheque", "err", err.Error())
 		// TODO: what do we do here? Related issue: https://github.com/ethersphere/swarm/issues/1515
 	}
 
@@ -472,13 +484,13 @@ func (s *Swap) Deploy(ctx context.Context) error {
 	opts.Value = big.NewInt(int64(s.params.InitialDepositAmount))
 	opts.Context = ctx
 
-	auditLog.Info("deploying new swap", "owner", opts.From.Hex())
+	s.logger.Info("deploying new swap", "owner", opts.From.Hex())
 	address, err := s.deployLoop(opts, s.owner.address, defaultHarddepositTimeoutDuration)
 	if err != nil {
-		auditLog.Error("unable to deploy swap", "error", err)
+		s.logger.Error("unable to deploy swap", "error", err)
 		return err
 	}
-	auditLog.Info("swap deployed", "address", address.Hex(), "owner", opts.From.Hex())
+	s.logger.Info("swap deployed", "address", address.Hex(), "owner", opts.From.Hex())
 
 	return err
 }
@@ -492,11 +504,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 {
-			auditLog.Warn("can't send chequebook deploy tx", "try", try, "error", err)
+			s.logger.Warn("can't send chequebook deploy tx", "try", try, "error", err)
 			continue
 		}
 		if addr, err = bind.WaitDeployed(opts.Context, s.backend, tx); err != nil {
-			auditLog.Warn("chequebook deploy error", "try", try, "error", err)
+			s.logger.Warn("chequebook deploy error", "try", try, "error", err)
 			continue
 		}
 		return addr, nil

swap/swap_test.go

@@ -1286,7 +1286,7 @@ func TestSwapLogToFile(t *testing.T) {
 	// so creditor is the model of the remote mode for the debitor! (and vice versa)
 	cPeer := newDummyPeerWithSpec(Spec)
 	dPeer := newDummyPeerWithSpec(Spec)
-	fmt.Println(1)
+
 	creditor, err := debitorSwap.addPeer(cPeer.Peer, creditorSwap.owner.address, debitorSwap.GetParams().ContractAddress)
 	if err != nil {
 		t.Fatal(err)
@@ -1313,9 +1313,12 @@ func TestSwapLogToFile(t *testing.T) {
 	}
 
 	files, err := ioutil.ReadDir(logDirDebitor)
-	if err != nil || len(files) == 0 {
+	if err != nil {
 		t.Fatal(err)
 	}
+	if len(files) == 0 {
+		t.Fatalf("expected at least 1 file in the log directory, found none")
+	}
 
 	logFile := path.Join(logDirDebitor, files[0].Name())