Improves output available for troubleshooting ansible

* When a specific task fails, the path and line number are logged.
* When ansible fails to run any tasks, such as if a syntax error exists in a role, ansible's stdout gets logged.
* log messages from the reconciler now include the job ID.
* The message "dropping event that is not a JobEvent" is now logged at debug level instead of info, since it isn't normally helpful.

Author: mhrivnak

pkg/ansible/controller/reconcile.go

@@ -18,7 +18,9 @@ import (
 	"context"
 	"encoding/json"
 	"errors"
+	"math/rand"
 	"os"
+	"strconv"
 	"strings"
 	"time"
 
@@ -65,6 +67,15 @@ func (r *AnsibleOperatorReconciler) Reconcile(request reconcile.Request) (reconc
 	if err != nil {
 		return reconcile.Result{}, err
 	}
+
+	ident := strconv.Itoa(rand.Int())
+	logger := logrus.WithFields(logrus.Fields{
+		"component": "reconciler",
+		"job":       ident,
+		"name":      u.GetName(),
+		"namespace": u.GetNamespace(),
+	})
+
 	reconcileResult := reconcile.Result{RequeueAfter: r.ReconcilePeriod}
 	if ds, ok := u.GetAnnotations()[ReconcilePeriodAnnotation]; ok {
 		duration, err := time.ParseDuration(ds)
@@ -79,7 +90,7 @@ func (r *AnsibleOperatorReconciler) Reconcile(request reconcile.Request) (reconc
 	pendingFinalizers := u.GetFinalizers()
 	// If the resource is being deleted we don't want to add the finalizer again
 	if finalizerExists && !deleted && !contains(pendingFinalizers, finalizer) {
-		logrus.Debugf("Adding finalizer %s to resource", finalizer)
+		logger.Debugf("Adding finalizer %s to resource", finalizer)
 		finalizers := append(pendingFinalizers, finalizer)
 		u.SetFinalizers(finalizers)
 		err := r.Client.Update(context.TODO(), u)
@@ -88,14 +99,14 @@ func (r *AnsibleOperatorReconciler) Reconcile(request reconcile.Request) (reconc
 		}
 	}
 	if !contains(pendingFinalizers, finalizer) && deleted {
-		logrus.Info("Resource is terminated, skipping reconcilation")
+		logger.Info("Resource is terminated, skipping reconcilation")
 		return reconcileResult, nil
 	}
 
 	spec := u.Object["spec"]
 	_, ok := spec.(map[string]interface{})
 	if !ok {
-		logrus.Debugf("spec was not found")
+		logger.Debugf("spec was not found")
 		u.Object["spec"] = map[string]interface{}{}
 		err = r.Client.Update(context.TODO(), u)
 		if err != nil {
@@ -141,15 +152,15 @@ func (r *AnsibleOperatorReconciler) Reconcile(request reconcile.Request) (reconc
 		return reconcileResult, err
 	}
 	defer os.Remove(kc.Name())
-	eventChan, err := r.Runner.Run(u, kc.Name())
+	result, err := r.Runner.Run(ident, u, kc.Name())
 	if err != nil {
 		return reconcileResult, err
 	}
 
 	// iterate events from ansible, looking for the final one
 	statusEvent := eventapi.StatusJobEvent{}
 	failureMessages := eventapi.FailureMessages{}
-	for event := range eventChan {
+	for event := range result.Events {
 		for _, eHandler := range r.EventHandlers {
 			go eHandler.Handle(u, event)
 		}
@@ -165,13 +176,23 @@ func (r *AnsibleOperatorReconciler) Reconcile(request reconcile.Request) (reconc
 			}
 		}
 		if event.Event == eventapi.EventRunnerOnFailed {
+			taskPath, ok := event.EventData["task_path"]
+			if ok {
+				logger.Errorf("failed task: %s\n", taskPath)
+			}
 			failureMessages = append(failureMessages, event.GetFailedPlaybookMessage())
 		}
 	}
 	if statusEvent.Event == "" {
-		err := errors.New("did not receive playbook_on_stats event")
-		logrus.Error(err.Error())
-		return reconcileResult, err
+		msg := "did not receive playbook_on_stats event"
+		logger.Error(msg)
+		stdout, err := result.Stdout()
+		if err != nil {
+			logger.Infof("failed to get ansible-runner stdout: %s\n", err.Error())
+		} else {
+			logger.Error(stdout)
+		}
+		return reconcileResult, errors.New(msg)
 	}
 
 	// We only want to update the CustomResource once, so we'll track changes and do it at the end

pkg/ansible/runner/eventapi/eventapi.go

@@ -165,7 +165,7 @@ func (e *EventReceiver) handleEvents(w http.ResponseWriter, r *http.Request) {
 	// we're not currently interested in.
 	// https://ansible-runner.readthedocs.io/en/latest/external_interface.html#event-structure
 	if event.UUID == "" {
-		e.logger.Info("dropping event that is not a JobEvent")
+		e.logger.Debug("dropping event that is not a JobEvent")
 	} else {
 		// timeout if the channel blocks for too long
 		timeout := time.NewTimer(10 * time.Second)

pkg/ansible/runner/internal/inputdir/inputdir.go

@@ -56,6 +56,14 @@ func (i *InputDir) addFile(path string, content []byte) error {
 	return err
 }
 
+// Stdout reads the stdout from the ansible artifact that corresponds to the
+// given ident and returns it as a string.
+func (i *InputDir) Stdout(ident string) (string, error) {
+	errorPath := filepath.Join(i.Path, "artifacts", ident, "stdout")
+	errorText, err := ioutil.ReadFile(errorPath)
+	return string(errorText), err
+}
+
 // Write commits the object's state to the filesystem at i.Path.
 func (i *InputDir) Write() error {
 	paramBytes, err := json.Marshal(i.Parameters)

pkg/ansible/runner/runner.go

@@ -18,12 +18,10 @@ import (
 	"errors"
 	"fmt"
 	"io/ioutil"
-	"math/rand"
 	"net/http"
 	"os"
 	"os/exec"
 	"path/filepath"
-	"strconv"
 	"strings"
 	"time"
 
@@ -39,7 +37,7 @@ import (
 // Runner - a runnable that should take the parameters and name and namespace
 // and run the correct code.
 type Runner interface {
-	Run(*unstructured.Unstructured, string) (chan eventapi.JobEvent, error)
+	Run(string, *unstructured.Unstructured, string) (*RunResult, error)
 	GetFinalizer() (string, bool)
 	GetReconcilePeriod() (time.Duration, bool)
 }
@@ -176,11 +174,10 @@ type runner struct {
 	reconcilePeriod  time.Duration
 }
 
-func (r *runner) Run(u *unstructured.Unstructured, kubeconfig string) (chan eventapi.JobEvent, error) {
+func (r *runner) Run(ident string, u *unstructured.Unstructured, kubeconfig string) (*RunResult, error) {
 	if u.GetDeletionTimestamp() != nil && !r.isFinalizerRun(u) {
 		return nil, errors.New("resource has been deleted, but no finalizer was matched, skipping reconciliation")
 	}
-	ident := strconv.Itoa(rand.Int())
 	logger := logrus.WithFields(logrus.Fields{
 		"component": "runner",
 		"job":       ident,
@@ -242,7 +239,11 @@ func (r *runner) Run(u *unstructured.Unstructured, kubeconfig string) (chan even
 			logger.Errorf("error from event api: %s", err.Error())
 		}
 	}()
-	return receiver.Events, nil
+	return &RunResult{
+		Events:   receiver.Events,
+		inputDir: &inputDir,
+		ident:    ident,
+	}, nil
 }
 
 // GetReconcilePeriod - new reconcile period.
@@ -330,3 +331,18 @@ func (r *runner) makeParameters(u *unstructured.Unstructured) map[string]interfa
 	}
 	return parameters
 }
+
+// RunResult facilitates access to information about a run of ansible.
+type RunResult struct {
+	// Events is a channel of events from ansible that contain state related
+	// to a run of ansible.
+	Events <-chan eventapi.JobEvent
+
+	ident    string
+	inputDir *inputdir.InputDir
+}
+
+// Stdout returns the stdout from ansible-runner if it is available, else an error.
+func (r *RunResult) Stdout() (string, error) {
+	return r.inputDir.Stdout(r.ident)
+}