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

@@ -19,6 +19,7 @@ package swap
 import (
 	"context"
 	"crypto/ecdsa"
+	"encoding/hex"
 	"encoding/json"
 	"errors"
 	"fmt"
@@ -45,8 +46,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
 
@@ -63,6 +62,7 @@ type Swap struct {
 	params           *Params            // economic and operational parameters
 	contract         swap.Contract      // reference to the smart contract
 	honeyPriceOracle HoneyOracle        // oracle which resolves the price of honey (in Wei)
+	logger           log.Logger         // logger for swap related messages and audit trail
 }
 
 // Owner encapsulates information related to accessing the contract
@@ -72,39 +72,52 @@ type Owner struct {
 	publicKey  *ecdsa.PublicKey  // public key
 }
 
-// Params encapsulates param
+// Params encapsulates economic and operational parameters
 type Params struct {
+	OverlayAddr         []byte // this node's base address
 	LogPath             string // optional audit log path
 	PaymentThreshold    int64  // honey amount at which a payment is triggered
 	DisconnectThreshold int64  // honey amount at which a peer disconnects
 }
 
-// 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(logPath string, overlayAddr []byte) log.Logger {
+	swapLogger := log.New("swaplog", "*", "base", hex.EncodeToString(overlayAddr)[:16])
+	setLoggerHandler(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", "*", "base", hex.EncodeToString(s.params.OverlayAddr)[:16], "peer", peerID.String()[:16])
+	setLoggerHandler(s.params.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()
 
 	if logpath == "" {
-		swapLogger.SetHandler(lh)
-		return swapLogger
+		logger.SetHandler(lh)
+		return
 	}
 
 	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
+		// use the default swarm logger as a fallback
+		logger.SetHandler(lh)
+		return
 	}
 
-	//Filters messages with the correct logLevel for swap
+	// filter messages with the correct log level 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
+	// 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.
@@ -118,14 +131,15 @@ func swapRotatingFileHandler(logdir string) (log.Handler, error) {
 }
 
 // new - swap constructor without integrity check
-func new(stateStore state.Store, owner *Owner, backend contract.Backend, params *Params) *Swap {
+func new(stateStore state.Store, owner *Owner, backend contract.Backend, params *Params, logger log.Logger) *Swap {
 	return &Swap{
 		store:            stateStore,
 		peers:            make(map[enode.ID]*Peer),
 		backend:          backend,
 		owner:            owner,
 		params:           params,
 		honeyPriceOracle: NewHoneyPriceOracle(),
+		logger:           logger,
 	}
 }
 
@@ -136,13 +150,13 @@ func new(stateStore state.Store, owner *Owner, backend contract.Backend, params
 // - verifies that we have not connected SWAP before on a different blockchain backend;
 // - starts the chequebook; creates the swap instance
 func New(dbPath string, prvkey *ecdsa.PrivateKey, backendURL string, params *Params, chequebookAddressFlag common.Address, initialDepositAmountFlag uint64) (swap *Swap, err error) {
-	// auditLog for swap-logging purposes
-	auditLog = newLogger(params.LogPath)
+	// swap log for auditing purposes
+	swapLogger := newSwapLogger(params.LogPath, params.OverlayAddr)
 	// verify that backendURL is not empty
 	if backendURL == "" {
 		return nil, errors.New("no backend URL given")
 	}
-	auditLog.Info("connecting to SWAP API", "url", backendURL)
+	swapLogger.Info("connecting to SWAP API", "url", backendURL)
 	// initialize the balances store
 	var stateStore state.Store
 	if stateStore, err = state.NewDBStore(filepath.Join(dbPath, "swap.db")); err != nil {
@@ -162,10 +176,10 @@ func New(dbPath string, prvkey *ecdsa.PrivateKey, backendURL string, params *Par
 		return nil, fmt.Errorf("error retrieving chainID from backendURL: %v", err)
 	}
 	// verify that we have not used SWAP before on a different chainID
-	if err := checkChainID(chainID.Uint64(), stateStore); err != nil {
+	if err := checkChainID(chainID.Uint64(), stateStore, swapLogger); err != nil {
 		return nil, err
 	}
-	auditLog.Info("Using backend network ID", "ID", chainID.Uint64())
+	swapLogger.Info("Using backend network ID", "ID", chainID.Uint64())
 	// create the owner of SWAP
 	owner := createOwner(prvkey)
 	// create the swap instance
@@ -174,6 +188,7 @@ func New(dbPath string, prvkey *ecdsa.PrivateKey, backendURL string, params *Par
 		owner,
 		backend,
 		params,
+		swapLogger,
 	)
 	// start the chequebook
 	if swap.contract, err = swap.StartChequebook(chequebookAddressFlag, initialDepositAmountFlag); err != nil {
@@ -191,7 +206,7 @@ const (
 )
 
 // checkChainID verifies whether we have initialized SWAP before and ensures that we are on the same backendNetworkID if this is the case
-func checkChainID(currentChainID uint64, s state.Store) (err error) {
+func checkChainID(currentChainID uint64, s state.Store, logger log.Logger) (err error) {
 	var connectedBlockchain uint64
 	err = s.Get(connectedBlockchainKey, &connectedBlockchain)
 	// error reading from database
@@ -203,7 +218,7 @@ func checkChainID(currentChainID uint64, s state.Store) (err error) {
 		return fmt.Errorf("statestore previously used on different backend network. Used before on network: %d, Attempting to connect on network %d", connectedBlockchain, currentChainID)
 	}
 	if err == state.ErrNotFound {
-		auditLog.Info("First time connected to SWAP. Storing chain ID", "ID", currentChainID)
+		logger.Info("First time connected to SWAP. Storing chain ID", "ID", currentChainID)
 		return s.Put(connectedBlockchainKey, currentChainID)
 	}
 	return nil
@@ -262,7 +277,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.params.PaymentThreshold {
-		auditLog.Info("balance for peer went over the payment threshold, sending cheque", "peer", peer.ID().String(), "payment threshold", s.params.PaymentThreshold)
+		swapPeer.logger.Info("balance for peer went over the payment threshold, sending cheque", "payment threshold", s.params.PaymentThreshold)
 		return swapPeer.sendCheque()
 	}
 
@@ -289,13 +304,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("processed and verified received cheque", "beneficiary", cheque.Beneficiary, "cumulative payout", cheque.CumulativePayout)
 
 	// reset balance by amount
 	// as this is done by the creditor, receiving the cheque, the amount should be negative,
@@ -337,17 +352,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
@@ -371,7 +386,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
 	}
 
@@ -611,27 +626,27 @@ func (s *Swap) StartChequebook(chequebookAddrFlag common.Address, initialDeposit
 		if err := s.saveChequebook(contract.ContractParams().ContractAddress); err != nil {
 			return nil, err
 		}
-		auditLog.Info("Deployed chequebook", "contract address", contract.ContractParams().ContractAddress.Hex(), "deposit", toDeposit, "owner", s.owner.address)
+		s.logger.Info("Deployed chequebook", "contract address", contract.ContractParams().ContractAddress.Hex(), "deposit", toDeposit, "owner", s.owner.address)
 		// first time connecting by deploying a new chequebook
 		return contract, nil
 	}
 	// first time connecting with a chequebookAddress passed in
 	if chequebookAddrFlag != (common.Address{}) {
-		return bindToContractAt(chequebookAddrFlag, s.backend)
+		return s.bindToContractAt(chequebookAddrFlag)
 	}
 	// reconnecting with contract read from statestore
-	return bindToContractAt(previouslyUsedChequebook, s.backend)
+	return s.bindToContractAt(previouslyUsedChequebook)
 }
 
 // BindToContractAt binds to an instance of an already existing chequebook contract at address
-func bindToContractAt(address common.Address, backend contract.Backend) (contract.Contract, error) {
+func (s *Swap) bindToContractAt(address common.Address) (contract.Contract, error) {
 	// validate whether address is a chequebook
-	if err := contract.ValidateCode(context.Background(), backend, address); err != nil {
+	if err := contract.ValidateCode(context.Background(), s.backend, address); err != nil {
 		return nil, fmt.Errorf("contract validation for %v failed: %v", address.Hex(), err)
 	}
-	auditLog.Info("bound to chequebook", "chequebookAddr", address)
+	s.logger.Info("bound to chequebook", "chequebookAddr", address)
 	// get the instance
-	return contract.InstanceAt(address, backend)
+	return contract.InstanceAt(address, s.backend)
 }
 
 // Deploy deploys the Swap contract
@@ -640,7 +655,7 @@ func (s *Swap) Deploy(ctx context.Context, initialDepositAmount uint64) (contrac
 	// initial topup value
 	opts.Value = big.NewInt(int64(initialDepositAmount))
 	opts.Context = ctx
-	auditLog.Info("Deploying new swap", "owner", opts.From.Hex(), "deposit", opts.Value)
+	s.logger.Info("Deploying new swap", "owner", opts.From.Hex(), "deposit", opts.Value)
 	return s.deployLoop(opts, defaultHarddepositTimeoutDuration)
 }
 
@@ -652,11 +667,11 @@ func (s *Swap) deployLoop(opts *bind.TransactOpts, defaultHarddepositTimeoutDura
 			time.Sleep(deployDelay)
 		}
 		if instance, tx, err = contract.Deploy(opts, s.backend, s.owner.address, defaultHarddepositTimeoutDuration); err != nil {
-			auditLog.Warn("can't send chequebook deploy tx", "try", try, "error", err)
+			s.logger.Warn("can't send chequebook deploy tx, retrying...", "try", try, "error", err)
 			continue
 		}
 		if _, 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, retrying...", "try", try, "error", err)
 			continue
 		}
 		return instance, nil

swap/swap_test.go

@@ -621,7 +621,7 @@ func TestNewSwapFailure(t *testing.T) {
 		t.Error(err)
 	}
 
-	params := newDefaultParams()
+	params := newDefaultParams(t)
 	chequebookAddress := testChequeContract
 	InitialDeposit := uint64(1)
 
@@ -1103,8 +1103,14 @@ func testCashCheque(s *Swap, otherSwap cswap.Contract, opts *bind.TransactOpts,
 }
 
 // newDefaultParams creates a set of default params for tests
-func newDefaultParams() *Params {
+func newDefaultParams(t *testing.T) *Params {
+	baseKey := make([]byte, 32)
+	_, err := rand.Read(baseKey)
+	if err != nil {
+		t.Fatal(err)
+	}
 	return &Params{
+		OverlayAddr:         baseKey,
 		LogPath:             "",
 		PaymentThreshold:    int64(DefaultPaymentThreshold),
 		DisconnectThreshold: int64(DefaultDisconnectThreshold),
@@ -1124,15 +1130,15 @@ func newBaseTestSwapWithParams(t *testing.T, key *ecdsa.PrivateKey, params *Para
 	}
 	log.Debug("creating simulated backend")
 	owner := createOwner(key)
-	auditLog = newLogger(params.LogPath)
-	swap := new(stateStore, owner, testBackend, params)
+	swapLogger := newSwapLogger(params.LogPath, params.OverlayAddr)
+	swap := new(stateStore, owner, testBackend, params, swapLogger)
 	return swap, dir
 }
 
 // create a test swap account with a backend
 // creates a stateStore for persistence and a Swap account
 func newBaseTestSwap(t *testing.T, key *ecdsa.PrivateKey) (*Swap, string) {
-	params := newDefaultParams()
+	params := newDefaultParams(t)
 	return newBaseTestSwapWithParams(t, key, params)
 }
 
@@ -1686,7 +1692,7 @@ func TestSwapLogToFile(t *testing.T) {
 	defer os.RemoveAll(logDirDebitor)
 
 	// set the log dir to the params
-	params := newDefaultParams()
+	params := newDefaultParams(t)
 	params.LogPath = logDirDebitor
 
 	// create both test swap accounts
@@ -1743,9 +1749,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())
 

swarm.go

@@ -122,6 +122,7 @@ func NewSwarm(config *api.Config, mockStore *mock.NodeStore) (self *Swarm, err e
 			return nil, fmt.Errorf("swap can only be enabled under BZZ Network ID %d, found Network ID %d instead", swap.AllowedNetworkID, self.config.NetworkID)
 		}
 		swapParams := &swap.Params{
+			OverlayAddr:         common.FromHex(self.config.BzzKey),
 			LogPath:             self.config.SwapLogPath,
 			DisconnectThreshold: int64(self.config.SwapDisconnectThreshold),
 			PaymentThreshold:    int64(self.config.SwapPaymentThreshold),