Improve operator logs by adding the possibility to get the full Ansible logs on it

CHANGELOG.md

@@ -10,6 +10,7 @@
 - Scaffold code in `cmd/manager/main.go` for Go operators and add logic to Ansible/Helm operators to handle [multinamespace caching](https://godoc.org/github.com/kubernetes-sigs/controller-runtime/pkg/cache#MultiNamespacedCacheBuilder) if `WATCH_NAMESPACE` contains multiple namespaces. ([#2522](https://github.com/operator-framework/operator-sdk/pull/2522))
 - Add a new flag option (`--skip-cleanup-error`) to the test framework to allow skip the function which will remove all artefacts when an error be faced to perform this operation.   ([#2512](https://github.com/operator-framework/operator-sdk/pull/2512))
 - Add event stats output to the operator logs for Ansible based-operators. ([2580](https://github.com/operator-framework/operator-sdk/pull/2580))   
+- Improve Ansible logs by allowing output the full Ansible result for Ansible based-operators configurable by environment variable. ([2589](https://github.com/operator-framework/operator-sdk/pull/2589))   
 
 ### Changed
 - Ansible scaffolding has been rewritten to be simpler and make use of newer features of Ansible and Molecule.

doc/ansible/dev/developer_guide.md

@@ -321,6 +321,18 @@ kubectl logs deployment/foo-operator
 The logs contain the information about the Ansible run and will make it much easier to debug issues within your Ansible tasks. 
 Note that the logs will contain much more detailed information about the Ansible Operator's internals and interface with Kubernetes as well.
 
+Also, you can use the environment variable `ANSIBLE_DEBUG_LOGS` set as `True` to check the full Ansible result in the logs in order to be able to debug it. 
+
+**Example**
+
+In the `deploy/operator.yaml`:
+```yaml
+...
+- name: ANSIBLE_DEBUG_LOGS
+  value: "True"
+...
+```
+
 ## Custom Resource Status Management
 The operator will automatically update the CR's `status` subresource with
 generic information about the previous Ansible run. This includes the number of

doc/ansible/user-guide.md

@@ -67,7 +67,7 @@ be monitored for updates and cached.
   role/playbook is run, for a given CR.
 * **manageStatus** (optional): When true (default), the operator will manage
   the status of the CR generically. Set to false, the status of the CR is
-  managed elsewhere, by the specified role/playbook or in a separate controller.
+  managed elsewhere, by the specified role/playbook or in a separate controller. 
 * **blacklist**: A list of child resources (by GVK) that will not be watched or cached.
 
 An example Watches file:
@@ -94,7 +94,7 @@ An example Watches file:
   kind: Baz
   playbook: baz.yml
   reconcilePeriod: 0
-  manageStatus: false
+  manageStatus: False
   vars:
     foo: bar
 
@@ -363,6 +363,18 @@ kubectl logs deployment/memcached-operator
 The logs contain the information about the Ansible run and will make it much easier to debug issues within your Ansible tasks. 
 Note that the logs will contain much more detailed information about the Ansible Operator's internals and interface with Kubernetes as well.
 
+Also, you can use the environment variable `ANSIBLE_DEBUG_LOGS` set as `True` to check the full Ansible result in the logs in order to be able to debug it. 
+
+**Example**
+
+In the `deploy/operator.yaml`:
+```yaml
+...
+- name: ANSIBLE_DEBUG_LOGS
+  value: "True"
+...
+```
+
 ### Additional Ansible Debug
 
 Occasionally while developing additional debug in the Operator logs is nice to have.

pkg/ansible/controller/controller.go

@@ -45,6 +45,7 @@ type Options struct {
 	GVK                         schema.GroupVersionKind
 	ReconcilePeriod             time.Duration
 	ManageStatus                bool
+	AnsibleDebugLogs            bool
 	WatchDependentResources     bool
 	WatchClusterScopedResources bool
 	MaxWorkers                  int
@@ -60,13 +61,14 @@ func Add(mgr manager.Manager, options Options) *controller.Controller {
 	eventHandlers := append(options.EventHandlers, events.NewLoggingEventHandler(options.LoggingLevel))
 
 	aor := &AnsibleOperatorReconciler{
-		Client:          mgr.GetClient(),
-		GVK:             options.GVK,
-		Runner:          options.Runner,
-		EventHandlers:   eventHandlers,
-		ReconcilePeriod: options.ReconcilePeriod,
-		ManageStatus:    options.ManageStatus,
-		APIReader:       mgr.GetAPIReader(),
+		Client:           mgr.GetClient(),
+		GVK:              options.GVK,
+		Runner:           options.Runner,
+		EventHandlers:    eventHandlers,
+		ReconcilePeriod:  options.ReconcilePeriod,
+		ManageStatus:     options.ManageStatus,
+		AnsibleDebugLogs: options.AnsibleDebugLogs,
+		APIReader:        mgr.GetAPIReader(),
 	}
 
 	scheme := mgr.GetScheme()

pkg/ansible/controller/reconcile.go

@@ -52,13 +52,14 @@ const (
 
 // AnsibleOperatorReconciler - object to reconcile runner requests
 type AnsibleOperatorReconciler struct {
-	GVK             schema.GroupVersionKind
-	Runner          runner.Runner
-	Client          client.Client
-	APIReader       client.Reader
-	EventHandlers   []events.EventHandler
-	ReconcilePeriod time.Duration
-	ManageStatus    bool
+	GVK              schema.GroupVersionKind
+	Runner           runner.Runner
+	Client           client.Client
+	APIReader        client.Reader
+	EventHandlers    []events.EventHandler
+	ReconcilePeriod  time.Duration
+	ManageStatus     bool
+	AnsibleDebugLogs bool
 }
 
 // Reconcile - handle the event.
@@ -193,6 +194,9 @@ func (r *AnsibleOperatorReconciler) Reconcile(request reconcile.Request) (reconc
 	// To print the stats of the task
 	printEventStats(statusEvent)
 
+	// To print the full ansible result
+	r.printAnsibleResult(result)
+
 	if statusEvent.Event == "" {
 		eventErr := errors.New("did not receive playbook_on_stats event")
 		stdout, err := result.Stdout()
@@ -256,13 +260,26 @@ func (r *AnsibleOperatorReconciler) Reconcile(request reconcile.Request) (reconc
 }
 
 func printEventStats(statusEvent eventapi.StatusJobEvent) {
-	fmt.Printf("\n--------------------------- Ansible Task Status Event StdOut  -----------------\n")
-	fmt.Println(statusEvent.StdOut)
-	fmt.Printf("\n-------------------------------------------------------------------------------\n")
+	if len(statusEvent.StdOut) > 0 {
+		fmt.Printf("\n--------------------------- Ansible Task Status Event StdOut  -----------------\n")
+		fmt.Println(statusEvent.StdOut)
+		fmt.Printf("\n-------------------------------------------------------------------------------\n")
+	}
+}
+
+func (r *AnsibleOperatorReconciler) printAnsibleResult(result runner.RunResult) {
+	if r.AnsibleDebugLogs {
+		if res, err := result.Stdout(); err == nil && len(res) > 0 {
+			fmt.Printf("\n--------------------------- Ansible Debug Result -----------------------------\n")
+			fmt.Println(res)
+			fmt.Printf("\n-------------------------------------------------------------------------------\n")
+		}
+	}
 }
 
 func (r *AnsibleOperatorReconciler) markRunning(u *unstructured.Unstructured,
 	namespacedName types.NamespacedName) error {
+
 	// Get the latest resource to prevent updating a stale status.
 	if err := r.APIReader.Get(context.TODO(), namespacedName, u); err != nil {
 		return err

pkg/ansible/events/log_events.go

@@ -93,17 +93,20 @@ func (l loggingEventHandler) Handle(ident string, u *unstructured.Unstructured,
 	// log everything else for the 'Everything' LogLevel
 	if l.LogLevel == Everything {
 		logger.Info("", "EventData", e.EventData)
+		l.logAnsibleStdOut(e)
 	}
 }
 
 // logAnsibleStdOut will print in the logs the Ansible Task Output formatted
 func (l loggingEventHandler) logAnsibleStdOut(e eventapi.JobEvent) {
-	fmt.Printf("\n--------------------------- Ansible Task StdOut -------------------------------\n")
-	if e.Event != eventapi.EventPlaybookOnTaskStart {
-		fmt.Printf("\n TASK [%v] ******************************** \n", e.EventData["task"])
+	if len(e.StdOut) > 0 {
+		fmt.Printf("\n--------------------------- Ansible Task StdOut -------------------------------\n")
+		if e.Event != eventapi.EventPlaybookOnTaskStart {
+			fmt.Printf("\n TASK [%v] ******************************** \n", e.EventData["task"])
+		}
+		fmt.Println(e.StdOut)
+		fmt.Printf("\n-------------------------------------------------------------------------------\n")
 	}
-	fmt.Println(e.StdOut)
-	fmt.Printf("\n-------------------------------------------------------------------------------\n")
 }
 
 // NewLoggingEventHandler - Creates a Logging Event Handler to log events.

pkg/ansible/run.go

@@ -20,6 +20,7 @@ import (
 	"fmt"
 	"os"
 	"runtime"
+	"strconv"
 	"strings"
 
 	"github.com/operator-framework/operator-sdk/pkg/ansible/controller"
@@ -131,11 +132,12 @@ func Run(flags *aoflags.AnsibleOperatorFlags) error {
 		}
 
 		ctr := controller.Add(mgr, controller.Options{
-			GVK:             w.GroupVersionKind,
-			Runner:          runner,
-			ManageStatus:    w.ManageStatus,
-			MaxWorkers:      w.MaxWorkers,
-			ReconcilePeriod: w.ReconcilePeriod,
+			GVK:              w.GroupVersionKind,
+			Runner:           runner,
+			ManageStatus:     w.ManageStatus,
+			AnsibleDebugLogs: getAnsibleDebugLog(),
+			MaxWorkers:       w.MaxWorkers,
+			ReconcilePeriod:  w.ReconcilePeriod,
 		})
 		if ctr == nil {
 			return fmt.Errorf("failed to add controller for GVK %v", w.GroupVersionKind.String())
@@ -255,3 +257,22 @@ func serveCRMetrics(cfg *rest.Config, gvks []schema.GroupVersionKind) error {
 	}
 	return nil
 }
+
+// getAnsibleDebugLog return the value from the ANSIBLE_DEBUG_LOGS it order to
+// print the full Ansible logs
+func getAnsibleDebugLog() bool {
+	const envVar = "ANSIBLE_DEBUG_LOGS"
+	val := false
+	if envVal, ok := os.LookupEnv(envVar); ok {
+		if i, err := strconv.ParseBool(envVal); err != nil {
+			log.Info("Could not parse environment variable as an boolean; using default value",
+				"envVar", envVar, "default", val)
+		} else {
+			val = i
+		}
+	} else if !ok {
+		log.Info("Environment variable not set; using default value", "envVar", envVar,
+			envVar, val)
+	}
+	return val
+}