logging for harmonytask test failures

itests/harmonytask_test.go

@@ -9,6 +9,7 @@ import (
 	"testing"
 	"time"
 
+	logging "github.com/ipfs/go-log/v2"
 	"github.com/stretchr/testify/require"
 
 	"github.com/filecoin-project/lotus/itests/kit"
@@ -30,6 +31,7 @@ func withDbSetup(t *testing.T, f func(*kit.TestMiner)) {
 		kit.LatestActorsAt(-1),
 		kit.MockProofs(),
 	)
+	logging.SetLogLevel("harmonytask", "debug")
 
 	f(miner)
 }

lib/harmony/harmonytask/task_type_handler.go

@@ -32,7 +32,7 @@ func (h *taskTypeHandler) AddTask(extra func(TaskID, *harmonydb.Tx) (bool, error
 		_, err := tx.Exec(`INSERT INTO harmony_task (name, added_by, posted_time) 
 			VALUES ($1, $2, CURRENT_TIMESTAMP) `, h.Name, h.TaskEngine.ownerID)
 		if err != nil {
-			return false, fmt.Errorf("Could not insert into harmonyTask: %w", err)
+			return false, fmt.Errorf("could not insert into harmonyTask: %w", err)
 		}
 		err = tx.QueryRow("SELECT id FROM harmony_task ORDER BY update_time DESC LIMIT 1").Scan(&tID)
 		if err != nil {
@@ -60,7 +60,7 @@ top:
 
 	// 1. Can we do any more of this task type?
 	if h.Max > -1 && int(h.Count.Load()) == h.Max {
-		log.Infow("did not accept task", "name", h.Name, "reason", "at max already")
+		log.Debugw("did not accept task", "name", h.Name, "reason", "at max already")
 		return false
 	}
 
@@ -70,7 +70,7 @@ top:
 	// 2. Can we do any more work?
 	err := h.AssertMachineHasCapacity()
 	if err != nil {
-		log.Info(err)
+		log.Debugw("did not accept task", "name", h.Name, "reason", "at capacity already: "+err.Error())
 		return false
 	}
 
@@ -81,7 +81,7 @@ top:
 		return false
 	}
 	if tID == nil {
-		log.Infow("did not accept task", "task_id", ids[0], "reason", "CanAccept() refused")
+		log.Infow("did not accept task", "task_id", ids[0], "reason", "CanAccept() refused", "name", h.Name)
 		return false
 	}
 
@@ -92,7 +92,7 @@ top:
 		return false
 	}
 	if ct == 0 {
-		log.Infow("did not accept task", "task_id", strconv.Itoa(int(*tID)), "reason", "already Taken")
+		log.Infow("did not accept task", "task_id", strconv.Itoa(int(*tID)), "reason", "already Taken", "name", h.Name)
 		var tryAgain = make([]TaskID, 0, len(ids)-1)
 		for _, id := range ids {
 			if id != *tID {
@@ -105,7 +105,7 @@ top:
 
 	go func() {
 		h.Count.Add(1)
-		log.Infow("Beginning work on Task", "id", *tID, "from", from, "type", h.Name)
+		log.Infow("Beginning work on Task", "id", *tID, "from", from, "name", h.Name)
 
 		var done bool
 		var doErr error
@@ -151,14 +151,14 @@ func (h *taskTypeHandler) recordCompletion(tID TaskID, workStart time.Time, done
 		var postedTime time.Time
 		err := tx.QueryRow(`SELECT posted_time FROM harmony_task WHERE id=$1`, tID).Scan(&postedTime)
 		if err != nil {
-			return false, fmt.Errorf("Could not log completion: %w ", err)
+			return false, fmt.Errorf("could not log completion: %w ", err)
 		}
 		result := "unspecified error"
 		if done {
 			_, err = tx.Exec("DELETE FROM harmony_task WHERE id=$1", tID)
 			if err != nil {
 
-				return false, fmt.Errorf("Could not log completion: %w", err)
+				return false, fmt.Errorf("could not log completion: %w", err)
 			}
 			result = ""
 		} else {
@@ -171,7 +171,7 @@ func (h *taskTypeHandler) recordCompletion(tID TaskID, workStart time.Time, done
 				err = tx.QueryRow(`SELECT count(*) FROM harmony_task_history 
 				WHERE task_id=$1 AND result=FALSE`, tID).Scan(&ct)
 				if err != nil {
-					return false, fmt.Errorf("Could not read task history: %w", err)
+					return false, fmt.Errorf("could not read task history: %w", err)
 				}
 				if ct >= h.MaxFailures {
 					deleteTask = true
@@ -180,13 +180,13 @@ func (h *taskTypeHandler) recordCompletion(tID TaskID, workStart time.Time, done
 			if deleteTask {
 				_, err = tx.Exec("DELETE FROM harmony_task WHERE id=$1", tID)
 				if err != nil {
-					return false, fmt.Errorf("Could not delete failed job: %w", err)
+					return false, fmt.Errorf("could not delete failed job: %w", err)
 				}
 				// Note: Extra Info is left laying around for later review & clean-up
 			} else {
 				_, err := tx.Exec(`UPDATE harmony_task SET owner_id=NULL WHERE id=$1`, tID)
 				if err != nil {
-					return false, fmt.Errorf("Could not disown failed task: %v %v", tID, err)
+					return false, fmt.Errorf("could not disown failed task: %v %v", tID, err)
 				}
 			}
 		}
@@ -194,7 +194,7 @@ func (h *taskTypeHandler) recordCompletion(tID TaskID, workStart time.Time, done
 												(task_id, name, posted,    work_start, work_end, result, err)
 			 VALUES ($1, $2, $3, $4, $5, $6, $7)`, tID, h.Name, postedTime, workStart, workEnd, done, result)
 		if err != nil {
-			return false, fmt.Errorf("Could not write history: %w", err)
+			return false, fmt.Errorf("could not write history: %w", err)
 		}
 		return true, nil
 	})