As a human, I find the output of the ansible-operator difficult to read

[djwhatle]

Summary

I think we can trim down and enhance the output from the ansible-operator such that users will have an easier time using and debugging ansible-operator. After gathering feedback here, I plan to submit a PR to operator-sdk.

Current and proposed log output

Here's what the current log output looks like running my sample operator user operator-sdk up local.

This is a draft of the proposed log output for the same events.

Goals in formatting the logs

• Add more visual separation between log messages
• Strip log messages down to minimize visual overload
• Give the user an easy way to access the full Ansible logs for a particular job (suggested by @alaypatel07 and @djzager)
• Balance human readability with machine readability by keeping log message content free of newline \n chars in the case that we ever want logs to be interpreted by another system (suggested by @fabianvf )

Changes suggested, as shown in the proposed log output:

• Add visual separation between log events by printing a line of ***** chars before each log, and a newline after each log

• Shorten the job identifier (at least in the logs) so that it takes up less space on-screen, and fits into short-term memory better when visually scanning across logs. We could consider switching to alphanumeric to compact while keeping large pool of IDs.

• Remove the component, and gvk fields from each log message, and combine Name and Kind to become Resource=<Kind>/<Name>. From my (limited) perspective, component and gvk are adequately represented by the Kind field. Please correct me if there is a good reason to have these in. If these are needed in special cases I'd like to suggest we have a DEBUG mode with additional logs.

• Add visual emphasis around the "log metadata" fields (job, resource, namespace) so that they can easily be picked out at the end of long log message lines. Also re-arrange meta fields in output so that job is first.

• Print a new log message when an ansible-runner job is started, as a matching pair to the exited successfully message. In this message, dynamically generate the kubectl/oc command that can be used to view the full logs for a particular ansible-runner job

Eager to hear thoughts on these changes.

[shawn-hurley]

First and foremost, thank you for getting this together! This is helpful, and I think a step in the right direction.

I am slightly worried about the implementation of some of these changes.

Add visual emphasis around the "log metadata" fields (job, resource, namespace) so that they can easily be picked out at the end of long log message lines. Also, re-arrange meta fields in output so that job is first.

I do not know of a way to change this currently with the default zap logger because it is hidden behind the logr interface. By default, controller-runtime uses this for the implementation of the interface but using the logr interface. All of this to say, if we wanted the ability to change the structure of the log, I think we would need to do something radically different. This is not a bad thing; I think that a logr implementation for logrus would be beneficial. But, we would need to implement that package. This would allow us to have "console" like logging as well as "structured" logging so that might help as well. The Operator-SDK has discussed doing this and has put it on the back burner, would this be something that someone would be interested in implmenting?

Print a new log message when an ansible-runner job is started, as a matching pair to the exited successfully message. In this message, dynamically generate the kubectl/oc command that can be used to view the full logs for a particular ansible-runner job

This feels fleeting, pods can die often, and if the command does not work for this reason or some other reason, I think it could be a challenge to help folks. I wonder what you think of better documentation in the developer guide, and giving an example command would suffice?

[djzager]

• Print a new log message when an ansible-runner job is started, as a matching pair to the exited successfully message. In this message, dynamically generate the kubectl/oc command that can be used to view the full logs for a particular ansible-runner job

I think this one is the highest value change that we could make. When we start a job, I believe, we have all of the information that we need to generate a kubectl exec -n ${namespace} ${pod_name} cat /path/to/job/stdout (probably not technically correct) command that would give you exactly what you want.

[djwhatle]

After further in-person discussion with Shawn, I think it makes most sense to work towards a modified subset of the originally suggested changes.

Revised list of changes

• Add visual separation between log messages with ****** chars and whitespace
• Add one or both of the following:
  • Helper command in operator-sdk that makes it easy to view logs for a particular ansible-runner job.
  • Additional documentation instructing users on how to manually access logs from an ansible-runner job ID
• Shorter ansible-runner job ID (~6 alphanumeric chars = 36^6 = 2,176,782,336 possibilities).
• Log when an ansible-runner job is started, as a matching pair to the exited successfully message.
• Look for opportunities to enhance ansible-operator output in some currently unhandled cases
• Initially at least, keep log metadata output the same to avoid extensive changes to logging infra in other projects
• Think a little more about the proper way to format output from ansible-operator vs ansible-runner
• Keep GVK field in the logs to clarify when multiple versions of the same group/kind are present

[cameronkerrnz]

Would using an environment variable such as ANSIBLE_STDOUT_CALLBACK=yaml fix a lot of these readability concerns? I know its made it a lot easier for my own Ansible work (looking forward to taking Ansible Operators for a spin).

Ref: https://docs.ansible.com/ansible/latest/plugins/callback.html

I see in https://github.com/water-hole/ansible-operator/blob/master/ansible.cfg it is set to 'debug'

Ah, but I guess much of this is caused by Ansible Runner, so setting ANSIBLE_STDOUT_CALLBACK may not be relevant.