Merge pull request #59 from JackalLabs/improve-logging

add more logging for better diagnostics

api/file_handler.go

@@ -29,7 +29,7 @@ func handleErr(err error, w http.ResponseWriter, code int) {
 	w.WriteHeader(code)
 	err = json.NewEncoder(w).Encode(v)
 	if err != nil {
-		log.Error().Err(err)
+		log.Error().Err(err).Msg("json encoder failed to write error response to http response writer")
 	}
 }
 

api/log.go

@@ -0,0 +1,19 @@
+package api
+
+import (
+	"net/http"
+
+	"github.com/rs/zerolog/log"
+)
+
+func loggingMiddleware(next http.Handler) http.Handler {
+	return http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) {
+		log.Info().
+			Str("method", req.Method).
+			Str("url", req.URL.RequestURI()).
+			Str("user_agent", req.UserAgent()).
+			Str("remote_addr", req.RemoteAddr).
+			Msg("incoming http request")
+		next.ServeHTTP(w, req)
+	})
+}

api/server.go

@@ -36,6 +36,7 @@ func (a *API) Close() error {
 }
 
 func (a *API) Serve(f *file_system.FileSystem, p *proofs.Prover, wallet *wallet.Wallet, chunkSize int64) error {
+	defer log.Info().Msg("API module stopped")
 	r := mux.NewRouter()
 	r.HandleFunc("/", IndexHandler(wallet.AccAddress()))
 	r.HandleFunc("/upload", PostFileHandler(f, p, wallet, chunkSize))
@@ -52,6 +53,7 @@ func (a *API) Serve(f *file_system.FileSystem, p *proofs.Prover, wallet *wallet.
 	r.HandleFunc("/version", VersionHandler(wallet))
 
 	r.Handle("/metrics", promhttp.Handler())
+	r.Use(loggingMiddleware)
 
 	a.srv = &http.Server{
 		Handler: r,

config/types.go

@@ -1,6 +1,9 @@
 package config
 
-import "github.com/desmos-labs/cosmos-go-wallet/types"
+import (
+	"github.com/desmos-labs/cosmos-go-wallet/types"
+	"github.com/rs/zerolog"
+)
 
 type Seed struct {
 	SeedPhrase     string `json:"seed_phrase"`
@@ -66,3 +69,22 @@ func DefaultConfig() *Config {
 		ProofThreads: 1000,
 	}
 }
+
+func (c Config) MarshalZerologObject(e *zerolog.Event) {
+	e.Int64("QueueInterval", c.QueueInterval).
+		Int64("ProofInterval", c.ProofInterval).
+		Int64("StrayCheckInterval", c.StrayManagerCfg.CheckInterval).
+		Int64("StrayRefreshInterval", c.StrayManagerCfg.RefreshInterval).
+		Int("StrayHandCount", c.StrayManagerCfg.HandCount).
+		Str("ChainRPCAddr", c.ChainCfg.RPCAddr).
+		Str("ChainGRPCAddr", c.ChainCfg.GRPCAddr).
+		Str("ChainGasPrice", c.ChainCfg.GasPrice).
+		Float64("ChainGasAdjustment", c.ChainCfg.GasAdjustment).
+		Str("IP", c.Ip).
+		Int64("TotalSpace", c.TotalSpace).
+		Str("DataDirectory", c.DataDirectory).
+		Int64("APIPort", c.APICfg.Port).
+		Int("APIIPFSPort", c.APICfg.IPFSPort).
+		Str("APIIPFSDomain", c.APICfg.IPFSDomain).
+		Int64("ProofThreads", c.ProofThreads)
+}

core/app.go

@@ -160,11 +160,13 @@ func (a *App) Start() error {
 	if err != nil {
 		return err
 	}
+	log.Debug().Object("config", cfg).Msg("sequoia config")
 
 	w, err := config.InitWallet(a.home)
 	if err != nil {
 		return err
 	}
+	log.Info().Str("provider_address", w.AccAddress()).Send()
 
 	myAddress := w.AccAddress()
 
@@ -178,12 +180,19 @@ func (a *App) Start() error {
 
 	res, err := cl.Provider(context.Background(), queryParams)
 	if err != nil {
-		log.Info().Msg("Provider does not exist on network or is not connected...")
+		log.Info().Err(err).Msg("Provider does not exist on network or is not connected...")
 		err := initProviderOnChain(w, cfg.Ip, cfg.TotalSpace)
 		if err != nil {
 			return err
 		}
 	} else {
+		log.Debug().
+			Str("address", res.Provider.Address).
+			Str("ip", res.Provider.Ip).
+			Str("totalspace", res.Provider.Totalspace).
+			Str("burned_contracts", res.Provider.BurnedContracts).
+			Str("keybase_identity", res.Provider.KeybaseIdentity).
+			Msg("provider query result")
 		claimers = res.Provider.AuthClaimers
 
 		totalSpace, err := strconv.ParseInt(res.Provider.Totalspace, 10, 64)

file_system/types.go

@@ -8,6 +8,7 @@ import (
 	ipfs2 "github.com/JackalLabs/sequoia/ipfs"
 	"github.com/dgraph-io/badger/v4"
 	ipfslite "github.com/hsanjuan/ipfs-lite"
+	"github.com/rs/zerolog/log"
 )
 
 type FileSystem struct {
@@ -25,5 +26,12 @@ func NewFileSystem(ctx context.Context, db *badger.DB, ipfsPort int, ipfsDomain
 }
 
 func (f *FileSystem) Close() {
-	f.db.Close()
+	err := f.db.Close()
+	if err != nil {
+		log.Error().Err(err).Msg("error occurred while closing database")
+	}
+	err = f.ipfsHost.Close()
+	if err != nil {
+		log.Error().Err(err).Msg("error occurred while stopping ipfs host")
+	}
 }

monitoring/monitor.go

@@ -7,6 +7,7 @@ import (
 
 	bankTypes "github.com/cosmos/cosmos-sdk/x/bank/types"
 	"github.com/jackalLabs/canine-chain/v3/x/storage/types"
+	"github.com/rs/zerolog/log"
 )
 
 func (m *Monitor) updateBurns() {
@@ -48,6 +49,7 @@ func (m *Monitor) updateBalance() {
 }
 
 func (m *Monitor) Start() {
+	defer log.Info().Msg("Monitor moduel stopped")
 	m.running = true
 
 	for m.running {

proofs/proofs.go

@@ -209,8 +209,8 @@ func (p *Prover) PostProof(merkle []byte, owner string, start int64, blockHeight
 
 func (p *Prover) Start() {
 	p.running = true
-	for {
-		if !p.running { // stop when running is false
+	for p.running {
+		if !p.running {
 			return
 		}
 
@@ -245,24 +245,50 @@ func (p *Prover) Start() {
 
 		p.processed = time.Now()
 	}
+	log.Info().Msg("Prover module stopped")
 }
 
 func (p *Prover) wrapPostProof(merkle []byte, owner string, start int64, height int64, startedAt time.Time) {
 	defer filesProving.Dec()
 	defer p.Dec()
 	err := p.PostProof(merkle, owner, start, height, startedAt)
 	if err != nil {
-		log.Warn().Err(err)
+		log.Warn().
+			Err(err).
+			Hex("merkle", merkle).
+			Str("owner", owner).
+			Int64("start", start).
+			Int64("height", height).
+			Msg("proof error")
+
 		if err.Error() == "rpc error: code = NotFound desc = not found" { // if the file is not found on the network, delete it
+			log.Info().
+				Hex("merkle", merkle).
+				Str("owner", owner).
+				Int64("start", start).
+				Msg("deleting the file that no longer exists on the network")
+
 			err := p.io.DeleteFile(merkle, owner, start)
 			if err != nil {
-				log.Error().Err(err)
+				log.Error().
+					Err(err).
+					Hex("merkle", merkle).
+					Msg("failed to delete file that no longer exist on the network")
 			}
 		}
 		if err.Error() == ErrNotOurs { // if the file is not ours, delete it
+			log.Info().
+				Hex("merkle", merkle).
+				Str("owner", owner).
+				Int64("start", start).
+				Msg("deleting the file that does not belong to this provider")
+
 			err := p.io.DeleteFile(merkle, owner, start)
 			if err != nil {
-				log.Error().Err(err)
+				log.Error().
+					Hex("merkle", merkle).
+					Err(err).
+					Msg("failed to delete file that does not belong to this provider")
 			}
 		}
 	}

queue/queue.go

@@ -48,6 +48,9 @@ func (q *Queue) Stop() {
 
 func (q *Queue) Listen() {
 	q.running = true
+	defer log.Info().Msg("Queue module stopped")
+
+	log.Info().Msg("Queue module started")
 	for q.running {
 		time.Sleep(time.Millisecond * 333)                                                // pauses for one third of a second
 		if !q.processed.Add(time.Second * time.Duration(q.interval)).Before(time.Now()) { // check every ten seconds
@@ -89,7 +92,7 @@ func (q *Queue) Listen() {
 
 		res, err := q.wallet.BroadcastTxCommit(data)
 		if err != nil {
-			log.Info().Msg(fmt.Sprintf("Failed to post from queue: %s", err.Error()))
+			log.Warn().Err(err).Msg("tx broadcast failed from queue")
 		}
 
 		for i, process := range toProcess {

strays/hands.go

@@ -23,7 +23,11 @@ func (h *Hand) Stop() {
 
 func (h *Hand) Start(f *file_system.FileSystem, wallet *wallet.Wallet, myUrl string, chunkSize int64) {
 	h.running = true
-	for h.running {
+	defer log.Info().Msg("Hand stopped")
+	for !h.running {
+		if h.running {
+			return
+		}
 
 		if h.stray == nil {
 			time.Sleep(time.Millisecond * 333)

strays/manager.go

@@ -90,12 +90,17 @@ func NewStrayManager(w *wallet.Wallet, q *queue.Queue, interval int64, refreshIn
 
 func (s *StrayManager) Start(f *file_system.FileSystem, myUrl string, chunkSize int64) {
 	s.running = true
+	defer log.Info().Msg("StrayManager stopped")
 
 	for _, hand := range s.hands {
 		go hand.Start(f, s.wallet, myUrl, chunkSize)
 	}
 
 	for s.running {
+		if !s.running {
+			return
+		}
+
 		time.Sleep(time.Millisecond * 333)
 		if s.refreshed.Add(time.Second * s.refreshInterval).Before(time.Now()) {
 			err := s.RefreshList()