Debug logging and various minor logging improvements (#1089)

This PR
- adds some logging to contract pruning
- updates the revision fetch logging to break up the errors to make the
log look a bit nicer. Also updates it to WARN instead ERROR since there
is nothing the user can do in most cases.
- adds some logging in the stores for when a sector is added but the
contract doesn't exist
- log a warning on startup when AVX2 isn't available similar to how
hostd does
- only log refill errors for contracts currently in the set

api/worker.go

@@ -49,8 +49,11 @@ type (
 
 	// ContractsResponse is the response type for the /rhp/contracts endpoint.
 	ContractsResponse struct {
-		Contracts []Contract `json:"contracts"`
-		Error     string     `json:"error,omitempty"`
+		Contracts []Contract                 `json:"contracts"`
+		Errors    map[types.PublicKey]string `json:"errors,omitempty"`
+
+		// deprecated
+		Error string `json:"error,omitempty"`
 	}
 
 	MemoryResponse struct {

autopilot/accounts.go

@@ -147,7 +147,11 @@ func (a *accounts) refillWorkerAccounts(ctx context.Context, w Worker) {
 						// register the alert if error is errMaxDriftExceeded
 						a.ap.RegisterAlert(ctx, newAccountRefillAlert(accountID, contract, *rerr))
 					}
-					a.l.Errorw(rerr.err.Error(), rerr.keysAndValues...)
+					if _, inSet := inContractSet[contract.ID]; inSet {
+						a.l.Errorw(rerr.err.Error(), rerr.keysAndValues...)
+					} else {
+						a.l.Debugw(rerr.err.Error(), rerr.keysAndValues...)
+					}
 				} else {
 					// dismiss alerts on success
 					a.ap.DismissAlert(ctx, alertIDForAccount(alertAccountRefillID, accountID))

autopilot/contractor.go

@@ -228,8 +228,10 @@ func (c *contractor) performContractMaintenance(ctx context.Context, w Worker) (
 	if err != nil {
 		return false, err
 	}
-	if resp.Error != "" {
-		c.logger.Error(resp.Error)
+	if resp.Errors != nil {
+		for pk, err := range resp.Errors {
+			c.logger.With("hostKey", pk).With("error", err).Warn("failed to fetch revision")
+		}
 	}
 	contracts := resp.Contracts
 	c.logger.Infof("fetched %d contracts from the worker, took %v", len(resp.Contracts), time.Since(start))

cmd/renterd/main.go

@@ -33,6 +33,7 @@ import (
 	"go.sia.tech/renterd/worker"
 	"go.sia.tech/web/renterd"
 	"go.uber.org/zap"
+	"golang.org/x/sys/cpu"
 	"golang.org/x/term"
 	"gopkg.in/yaml.v3"
 	"gorm.io/gorm/logger"
@@ -488,14 +489,17 @@ func main() {
 	defer closeFn(context.Background())
 
 	logger.Info("renterd", zap.String("version", build.Version()), zap.String("network", build.NetworkName()), zap.String("commit", build.Commit()), zap.Time("buildDate", build.BuildTime()))
+	if runtime.GOARCH == "amd64" && !cpu.X86.HasAVX2 {
+		logger.Warn("renterd is running on a system without AVX2 support, performance may be degraded")
+	}
 
 	// configure database logger
 	dbLogCfg := cfg.Log.Database
 	if cfg.Database.Log != (config.DatabaseLog{}) {
 		dbLogCfg = cfg.Database.Log
 	}
 	busCfg.DBLogger = zapgorm2.Logger{
-		ZapLogger:                 logger,
+		ZapLogger:                 logger.Named("SQL"),
 		LogLevel:                  level,
 		SlowThreshold:             dbLogCfg.SlowThreshold,
 		SkipCallerLookup:          false,

stores/metadata.go

@@ -2226,6 +2226,12 @@ func (s *SQLStore) createSlices(tx *gorm.DB, objID, multiPartID *uint, contractS
 							DBSectorID:   sectorID,
 							DBContractID: contracts[fcid].ID,
 						})
+					} else {
+						s.logger.Warn("missing contract for shard",
+							"contract", fcid,
+							"root", shard.Root,
+							"latest_host", shard.LatestHost,
+						)
 					}
 				}
 			}

worker/rhpv2.go

@@ -2,6 +2,7 @@ package worker
 
 import (
 	"context"
+	"encoding/hex"
 	"encoding/json"
 	"errors"
 	"fmt"
@@ -15,6 +16,7 @@ import (
 	"go.sia.tech/renterd/api"
 	"go.sia.tech/siad/build"
 	"go.sia.tech/siad/crypto"
+	"lukechampine.com/frand"
 )
 
 const (
@@ -339,7 +341,15 @@ func (w *worker) PruneContract(ctx context.Context, hostIP string, hostKey types
 }
 
 func (w *worker) deleteContractRoots(t *rhpv2.Transport, rev *rhpv2.ContractRevision, settings rhpv2.HostSettings, indices []uint64) (deleted uint64, err error) {
-	w.logger.Infow(fmt.Sprintf("deleting %d contract roots (%v)", len(indices), humanReadableSize(len(indices)*rhpv2.SectorSize)), "hk", rev.HostKey(), "fcid", rev.ID())
+	id := frand.Entropy128()
+	logger := w.logger.
+		With("id", hex.EncodeToString(id[:])).
+		With("hostKey", rev.HostKey()).
+		With("hostVersion", settings.Version).
+		With("fcid", rev.ID()).
+		With("revisionNumber", rev.Revision.RevisionNumber).
+		Named("deleteContractRoots")
+	logger.Infow(fmt.Sprintf("deleting %d contract roots (%v)", len(indices), humanReadableSize(len(indices)*rhpv2.SectorSize)), "hk", rev.HostKey(), "fcid", rev.ID())
 
 	// return early
 	if len(indices) == 0 {
@@ -380,9 +390,9 @@ func (w *worker) deleteContractRoots(t *rhpv2.Transport, rev *rhpv2.ContractRevi
 		if err = func() error {
 			var cost types.Currency
 			start := time.Now()
-			w.logger.Infow(fmt.Sprintf("starting batch %d/%d of size %d", i+1, len(batches), len(batch)))
+			logger.Infow(fmt.Sprintf("starting batch %d/%d of size %d", i+1, len(batches), len(batch)))
 			defer func() {
-				w.logger.Infow(fmt.Sprintf("processing batch %d/%d of size %d took %v", i+1, len(batches), len(batch), time.Since(start)), "cost", cost)
+				logger.Infow(fmt.Sprintf("processing batch %d/%d of size %d took %v", i+1, len(batches), len(batch), time.Since(start)), "cost", cost)
 			}()
 
 			numSectors := rev.NumSectors()
@@ -462,7 +472,7 @@ func (w *worker) deleteContractRoots(t *rhpv2.Transport, rev *rhpv2.ContractRevi
 				return err
 			} else if err := t.ReadResponse(&merkleResp, minMessageSize+responseSize); err != nil {
 				err := fmt.Errorf("couldn't read Merkle proof response, err: %v", err)
-				w.logger.Infow(fmt.Sprintf("processing batch %d/%d failed, err %v", i+1, len(batches), err))
+				logger.Infow(fmt.Sprintf("processing batch %d/%d failed, err %v", i+1, len(batches), err))
 				return err
 			}
 
@@ -472,7 +482,7 @@ func (w *worker) deleteContractRoots(t *rhpv2.Transport, rev *rhpv2.ContractRevi
 			oldRoot, newRoot := types.Hash256(rev.Revision.FileMerkleRoot), merkleResp.NewMerkleRoot
 			if rev.Revision.Filesize > 0 && !rhpv2.VerifyDiffProof(actions, numSectors, proofHashes, leafHashes, oldRoot, newRoot, nil) {
 				err := fmt.Errorf("couldn't verify delete proof, host %v, version %v; %w", rev.HostKey(), settings.Version, ErrInvalidMerkleProof)
-				w.logger.Infow(fmt.Sprintf("processing batch %d/%d failed, err %v", i+1, len(batches), err))
+				logger.Infow(fmt.Sprintf("processing batch %d/%d failed, err %v", i+1, len(batches), err))
 				t.WriteResponseErr(err)
 				return err
 			}

worker/worker.go

@@ -1298,6 +1298,10 @@ func (w *worker) rhpContractsHandlerGET(jc jape.Context) {
 	resp := api.ContractsResponse{Contracts: contracts}
 	if errs != nil {
 		resp.Error = errs.Error()
+		resp.Errors = make(map[types.PublicKey]string)
+		for pk, err := range errs {
+			resp.Errors[pk] = err.Error()
+		}
 	}
 	jc.Encode(resp)
 }