Debug messages around the plan and plan response

nomad/plan_apply.go

@@ -59,6 +59,7 @@ func (s *Server) planApply() {
 		if err != nil {
 			return
 		}
+		s.logger.Printf("[DEBUG] plan_apply: dequeued plan: %#v", pending.plan)
 
 		// Verify the evaluation is outstanding, and that the tokens match.
 		if err := s.evalBroker.OutstandingReset(pending.plan.EvalID, pending.plan.EvalToken); err != nil {
@@ -89,6 +90,7 @@ func (s *Server) planApply() {
 
 		// Evaluate the plan
 		result, err := evaluatePlan(pool, snap, pending.plan)
+		s.logger.Printf("[DEBUG] plan_apply: plan result for eval %q: %#v", pending.plan.EvalID, result)
 		if err != nil {
 			s.logger.Printf("[ERR] nomad: failed to evaluate plan: %v", err)
 			pending.respond(nil, err)
@@ -234,6 +236,8 @@ func evaluatePlan(pool *EvaluatePool, snap *state.StateSnapshot, plan *structs.P
 			return true
 		}
 		if !fit {
+			log.Printf("[DEBUG] plan_apply: eval %q no fit on node %q", plan.EvalID, nodeID)
+
 			// Set that this is a partial commit
 			partialCommit = true
 

nomad/plan_endpoint.go

@@ -19,6 +19,8 @@ func (p *Plan) Submit(args *structs.PlanRequest, reply *structs.PlanResponse) er
 	}
 	defer metrics.MeasureSince([]string{"nomad", "plan", "submit"}, time.Now())
 
+	p.srv.logger.Printf("[DEBUG] plan_endpoint.Submit request: %#v", args.Plan)
+
 	// Submit the plan to the queue
 	future, err := p.srv.planQueue.Enqueue(args.Plan)
 	if err != nil {
@@ -34,5 +36,6 @@ func (p *Plan) Submit(args *structs.PlanRequest, reply *structs.PlanResponse) er
 	// Package the result
 	reply.Result = result
 	reply.Index = result.AllocIndex
+	p.srv.logger.Printf("[DEBUG] plan_endpoint.Submit eval %q response: %#v", args.Plan.EvalID, reply.Result)
 	return nil
 }

nomad/structs/structs.go

@@ -2457,6 +2457,18 @@ func (p *Plan) IsNoOp() bool {
 	return len(p.NodeUpdate) == 0 && len(p.NodeAllocation) == 0 && len(p.FailedAllocs) == 0
 }
 
+func (p *Plan) GoString() string {
+	planNodeUpdate := 0
+	planNodeAlloc := 0
+	for _, updates := range p.NodeUpdate {
+		planNodeUpdate += len(updates)
+	}
+	for _, allocs := range p.NodeAllocation {
+		planNodeAlloc += len(allocs)
+	}
+	return fmt.Sprintf("plan; eval %q; allocs %v; updates %v", p.EvalID, planNodeAlloc, planNodeUpdate)
+}
+
 // PlanResult is the result of a plan submitted to the leader.
 type PlanResult struct {
 	// NodeUpdate contains all the updates that were committed.
@@ -2500,6 +2512,19 @@ func (p *PlanResult) FullCommit(plan *Plan) (bool, int, int) {
 	return actual == expected, expected, actual
 }
 
+func (p *PlanResult) GoString() string {
+	planNodeUpdate := 0
+	planNodeAlloc := 0
+	for _, updates := range p.NodeUpdate {
+		planNodeUpdate += len(updates)
+	}
+	for _, allocs := range p.NodeAllocation {
+		planNodeAlloc += len(allocs)
+	}
+	return fmt.Sprintf("planresult allocs %v; updates %v; refresh %v; alloc index %v",
+		planNodeAlloc, planNodeUpdate, p.RefreshIndex, p.AllocIndex)
+}
+
 // msgpackHandle is a shared handle for encoding/decoding of structs
 var MsgpackHandle = func() *codec.MsgpackHandle {
 	h := &codec.MsgpackHandle{RawToString: true}

nomad/worker.go

@@ -282,6 +282,8 @@ func (w *Worker) SubmitPlan(plan *structs.Plan) (*structs.PlanResult, scheduler.
 	}
 	var resp structs.PlanResponse
 
+	w.logger.Printf("[DEBUG] worker.SubmitPlan request: %#v", plan)
+
 SUBMIT:
 	// Make the RPC call
 	if err := w.srv.RPC("Plan.Submit", &req, &resp); err != nil {
@@ -302,6 +304,8 @@ SUBMIT:
 		return nil, nil, fmt.Errorf("missing result")
 	}
 
+	w.logger.Printf("[DEBUG] worker.SubmitPlan eval %q result: %#v", plan.EvalID, result)
+
 	// Check if a state update is required. This could be required if we
 	// planning based on stale data, which is causing issues. For example, a
 	// node failure since the time we've started planning or conflicting task