storagenode/pieces/lazyfilewalker: more logging to GC filewalker

Change-Id: I0103bde93a0a0a101fa413f06ae378da366dee46

cmd/storagenode/internalcmd/gc_filewalker.go

@@ -109,6 +109,7 @@ func gcCmdRun(g *RunOptions) (err error) {
 		}
 		err := json.NewEncoder(g.stdout).Encode(resp)
 		if err != nil {
+			log.Debug("failed to notify main process", zap.Error(err))
 			return err
 		}
 		numTrashed++
@@ -129,5 +130,10 @@ func gcCmdRun(g *RunOptions) (err error) {
 	log.Info("gc-filewalker completed", zap.Int64("piecesCount", piecesCount), zap.Int("trashPiecesCount", len(pieceIDs)), zap.Int("piecesTrashed", numTrashed), zap.Int64("piecesSkippedCount", piecesSkippedCount))
 
 	// encode the response struct and write it to stdout
-	return json.NewEncoder(g.stdout).Encode(resp)
+	err = json.NewEncoder(g.stdout).Encode(resp)
+	if err != nil {
+		log.Debug("failed to write to stdout", zap.Error(err))
+		return errs.New("Error writing response to stdout: %v", err)
+	}
+	return nil
 }

storagenode/pieces/lazyfilewalker/supervisor.go

@@ -153,7 +153,7 @@ func (fw *Supervisor) WalkSatellitePiecesToTrash(ctx context.Context, satelliteI
 
 	log := fw.log.Named(GCFilewalkerCmdName).With(zap.String("satelliteID", satelliteID.String()))
 
-	err = newProcess(fw.testingGCCmd, log, fw.executable, fw.gcArgs).setStdout(newTrashHandler(trashFunc)).run(ctx, req, &resp)
+	err = newProcess(fw.testingGCCmd, log, fw.executable, fw.gcArgs).setStdout(newTrashHandler(log, trashFunc)).run(ctx, req, &resp)
 	if err != nil {
 		return nil, 0, 0, err
 	}
@@ -184,18 +184,22 @@ func (fw *Supervisor) WalkCleanupTrash(ctx context.Context, satelliteID storj.No
 type trashHandler struct {
 	bytes.Buffer
 
+	log        *zap.Logger
 	lineBuffer []byte
 
 	trashFunc func(pieceID storj.PieceID) error
 }
 
-func newTrashHandler(trashFunc func(pieceID storj.PieceID) error) *trashHandler {
+func newTrashHandler(log *zap.Logger, trashFunc func(pieceID storj.PieceID) error) *trashHandler {
 	return &trashHandler{
+		log:       log.Named("trash-handler"),
 		trashFunc: trashFunc,
 	}
 }
 
 func (t *trashHandler) Write(b []byte) (n int, err error) {
+	t.log.Debug("received data from subprocess")
+
 	n = len(b)
 	t.lineBuffer = append(t.lineBuffer, b...)
 	for {
@@ -226,11 +230,13 @@ func (t *trashHandler) writeLine(b []byte) (remaining []byte, err error) {
 func (t *trashHandler) processTrashPiece(b []byte) error {
 	var resp GCFilewalkerResponse
 	if err := json.Unmarshal(b, &resp); err != nil {
+		t.log.Error("failed to unmarshal data from subprocess", zap.Error(err))
 		return err
 	}
 
 	if !resp.Completed {
 		for _, pieceID := range resp.PieceIDs {
+			t.log.Debug("trashing piece", zap.String("pieceID", pieceID.String()))
 			return t.trashFunc(pieceID)
 		}
 	}

storagenode/pieces/lazyfilewalker/supervisor_test.go

@@ -9,6 +9,7 @@ import (
 	"testing"
 
 	"github.com/stretchr/testify/require"
+	"go.uber.org/zap/zaptest"
 
 	"storj.io/common/storj"
 )
@@ -47,7 +48,7 @@ func TestTrashHandler_Write(t *testing.T) {
 			expectedFinalResponse,
 		}
 
-		trashHandler := newTrashHandler(trashFunc)
+		trashHandler := newTrashHandler(zaptest.NewLogger(t), trashFunc)
 
 		for _, output := range outputs {
 			err := json.NewEncoder(trashHandler).Encode(output)
@@ -78,7 +79,7 @@ func TestTrashHandler_Write(t *testing.T) {
 			return nil
 		}
 
-		trashHandler := newTrashHandler(trashFunc)
+		trashHandler := newTrashHandler(zaptest.NewLogger(t), trashFunc)
 
 		// The string slice below is a concatenation of multiple JSON outputs:
 		// {"pieceIDs":["<pieceID0>"]}\n