fix localstore log messages (#202)

pkg/localstore/export.go

@@ -125,13 +125,13 @@ func (db *DB) Import(r io.Reader, legacy bool) (count int64, err error) {
 			}
 
 			if len(hdr.Name) != 64 {
-				db.logger.Warningf("ignoring non-chunk file, name : %s", hdr.Name)
+				db.logger.Warningf("localstore export: ignoring non-chunk file: %s", hdr.Name)
 				continue
 			}
 
 			keybytes, err := hex.DecodeString(hdr.Name)
 			if err != nil {
-				db.logger.Warningf("ignoring invalid chunk file. name : %s , Error : %s", hdr.Name, err)
+				db.logger.Warningf("localstore export: ignoring invalid chunk file %s: %v", hdr.Name, err)
 				continue
 			}
 

pkg/localstore/gc.go

@@ -18,6 +18,7 @@ package localstore
 
 import (
 	"errors"
+	"fmt"
 	"time"
 
 	"github.com/ethersphere/bee/pkg/shed"
@@ -54,7 +55,7 @@ func (db *DB) collectGarbageWorker() {
 			// another collect garbage run is needed
 			collectedCount, done, err := db.collectGarbage()
 			if err != nil {
-				db.logger.Errorf("localstore collect garbage. Error : %s", err.Error())
+				db.logger.Errorf("localstore: collect garbage: %v", err)
 			}
 			// check if another gc run is needed
 			if !done {
@@ -96,8 +97,7 @@ func (db *DB) collectGarbage() (collectedCount uint64, done bool, err error) {
 	// remove them from the gcIndex before iterating through gcIndex
 	err = db.removeChunksInExcludeIndexFromGC()
 	if err != nil {
-		db.logger.Errorf("localstore exclude pinned chunks. Error : %s", err)
-		return 0, true, err
+		return 0, true, fmt.Errorf("remove chunks in exclude index: %v", err)
 	}
 
 	gcSize, err := db.gcSize.Get()

pkg/localstore/migration.go

@@ -46,7 +46,7 @@ func (db *DB) migrate(schemaName string) error {
 		return nil
 	}
 
-	db.logger.Infof("need to run data migrations on localstore. numMigrations : %s, schemaName : %s ", len(migrations), schemaName)
+	db.logger.Infof("localstore migration: need to run %v data migrations on localstore to schema %s", len(migrations), schemaName)
 	for i := 0; i < len(migrations); i++ {
 		err := migrations[i].fn(db)
 		if err != nil {
@@ -60,7 +60,7 @@ func (db *DB) migrate(schemaName string) error {
 		if err != nil {
 			return err
 		}
-		db.logger.Infof("successfully ran migration. migrationId : %s, currentSchema : %s", i, schemaName)
+		db.logger.Infof("localstore migration: successfully ran migration: id %v current schema: %s", i, schemaName)
 	}
 	return nil
 }
@@ -81,7 +81,7 @@ func getMigrations(currentSchema, targetSchema string, allSchemeMigrations []mig
 				return nil, errors.New("found schema name for the second time when looking for migrations")
 			}
 			foundCurrent = true
-			db.logger.Infof("found current localstore schema. currentSchema : %s , migrateTo : %s, total migrations : %d", currentSchema, DbSchemaCurrent, len(allSchemeMigrations)-i)
+			db.logger.Infof("localstore migration: found current localstore schema %s, migrate to %s, total migrations %d", currentSchema, DbSchemaCurrent, len(allSchemeMigrations)-i)
 			continue // current schema migration should not be executed (already has been when schema was migrated to)
 		case targetSchema:
 			foundTarget = true

pkg/localstore/mode_get.go

@@ -107,7 +107,7 @@ func (db *DB) updateGCItems(items ...shed.Item) {
 			err := db.updateGC(item)
 			if err != nil {
 				db.metrics.GCUpdateError.Inc()
-				db.logger.Errorf("localstore update gc. Error : %s", err.Error())
+				db.logger.Errorf("localstore update gc: %v", err)
 			}
 		}
 		// if gc update hook is defined, call it

pkg/localstore/mode_set.go

@@ -233,7 +233,7 @@ func (db *DB) setSync(batch *leveldb.Batch, addr swarm.Address, mode storage.Mod
 				// if we return the error here - it means that for example, in stream protocol peers which we sync
 				// to would be dropped. this is possible when the chunk is put with ModePutRequest and ModeSetSyncPull is
 				// called on the same chunk (which should not happen)
-				db.logger.Errorf("chunk not found in pull index. addr: %s", addr.String())
+				db.logger.Debugf("localstore: chunk with address %s not found in pull index", addr)
 				break
 			}
 			return 0, err
@@ -267,7 +267,7 @@ func (db *DB) setSync(batch *leveldb.Batch, addr swarm.Address, mode storage.Mod
 				// we handle this error internally, since this is an internal inconsistency of the indices
 				// this error can happen if the chunk is put with ModePutRequest or ModePutSync
 				// but this function is called with ModeSetSyncPush
-				db.logger.Errorf("chunk not found in push index. addr : %s", addr.String())
+				db.logger.Debugf("localstore: chunk with address %s not found in push index", addr)
 				break
 			}
 			return 0, err
@@ -277,7 +277,7 @@ func (db *DB) setSync(batch *leveldb.Batch, addr swarm.Address, mode storage.Mod
 			if err != nil {
 				// we cannot break or return here since the function needs to
 				// run to end from db.pushIndex.DeleteInBatch
-				db.logger.Errorf("error getting tags on push sync set. uid : %d", i.Tag)
+				db.logger.Errorf("localstore: get tags on push sync set uid %d: %v", i.Tag, err)
 			} else {
 				// setting a chunk for push sync assumes the tag is not anonymous
 				if t.Anonymous {

pkg/localstore/subscription_pull.go

@@ -136,7 +136,7 @@ func (db *DB) SubscribePull(ctx context.Context, bin uint8, since, until uint64)
 						return
 					}
 					db.metrics.SubscribePullIterationFailure.Inc()
-					db.logger.Errorf("localstore pull subscription iteration. bin: %d, since: %d, until: %d. Error : %s", bin, since, until, err.Error())
+					db.logger.Debugf("localstore pull subscription iteration: bin: %d, since: %d, until: %d: %v", bin, since, until, err)
 					return
 				}
 				if count > 0 {
@@ -153,7 +153,7 @@ func (db *DB) SubscribePull(ctx context.Context, bin uint8, since, until uint64)
 			case <-ctx.Done():
 				err := ctx.Err()
 				if err != nil {
-					db.logger.Errorf("localstore pull subscription. bin: %d, since: %d, until: %d. Error : %s", bin, since, until, err.Error())
+					db.logger.Debugf("localstore pull subscription iteration: bin: %d, since: %d, until: %d: %v", bin, since, until, err)
 				}
 				return
 			}

pkg/localstore/subscription_push.go

@@ -18,7 +18,6 @@ package localstore
 
 import (
 	"context"
-	"fmt"
 	"sync"
 	"time"
 
@@ -80,7 +79,6 @@ func (db *DB) SubscribePush(ctx context.Context) (c <-chan swarm.Chunk, stop fun
 						// set next iteration start item
 						// when its chunk is successfully sent to channel
 						sinceItem = &item
-						db.logger.Tracef("subscribe.push. ref : %s, binId : %d", fmt.Sprintf("%x", sinceItem.Address), sinceItem.BinID)
 						return false, nil
 					case <-stopChan:
 						// gracefully stop the iteration
@@ -104,7 +102,7 @@ func (db *DB) SubscribePush(ctx context.Context) (c <-chan swarm.Chunk, stop fun
 
 				if err != nil {
 					db.metrics.SubscribePushIterationFailure.Inc()
-					db.logger.Errorf("localstore push subscription iteration. Error : %s", err.Error())
+					db.logger.Debugf("localstore push subscription iteration: %v", err)
 					return
 				}
 			case <-stopChan:
@@ -118,7 +116,7 @@ func (db *DB) SubscribePush(ctx context.Context) (c <-chan swarm.Chunk, stop fun
 			case <-ctx.Done():
 				err := ctx.Err()
 				if err != nil {
-					db.logger.Errorf("localstore push subscription. Error : %s", err.Error())
+					db.logger.Debugf("localstore push subscription iteration: %v", err)
 				}
 				return
 			}