make log outputs more readable

[dymurray]

This is GREAT. Previous logs were completely unreadable.

After this PR:

INFO[0060] dropping event that is not a JobEvent         component=eventapi job=8106210666315314979                                          
INFO[0061] [playbook debug]: var=_app_example_com_database  component=logging_event_handler event_type=runner_on_ok gvk="app.example.com/v1alpha1, Kind=Database" name=example namespace=default                                                                                          
INFO[0061] [playbook task]: busybox : start busybox      component=logging_event_handler event_type=playbook_on_task_start gvk="app.example.com/v1alpha1, Kind=Database" name=example namespace=default                                                                                   
INFO[0063] dropping event that is not a JobEvent         component=eventapi job=8106210666315314979                                          
INFO[0063] ansible-runner exited successfully            component=runner job=8106210666315314979 name=example namespace=default 

Before this PR:

INFO[72542] event: map[string]interface {}{"play_uuid":"64006a6f-b905-4c97-b814-000000000006", "task_action":"k8s", "role":"busybox", "play":"localhost", "task":"start busybox", "playbook":"/opt/ansible/playbook.yaml", "pid":28967, "playbook_uuid":"844d7ea0-6072-4e3b-aa9a-fc34fdece
b7b", "task_path":"/opt/ansible/roles/busybox/tasks/main.yml:3", "name":"busybox : start busybox", "is_conditional":false, "task_uuid":"64006a6f-b905-4c97-b814-00000000000e", "play_pattern":"localhost", "task_args":"definition={u'kind': u'Deployment', u'spec': {u'template': {u'spec
': {u'containers': [{u'image': u'busybox', u'args': [u'-c', u'while true; do echo {{ message|quote }}; sleep {{ echo_delay | int }} ;done'], u'command': [u'/bin/sh'], u'name': u'test'}]}, u'metadata': {u'labels': {u'app': u'test'}}}, u'selector': {u'matchLabels': {u'app': u'test'}}
}, u'apiVersion': u'apps/v1', u'metadata': {u'namespace': u'{{ meta.namespace }}', u'name': u'{{ meta.name }}-busybox'}}"}  component=logging_event_handler event_type=playbook_on_task_start gvk="app.example.com/v1alpha1, Kind=Database" name=example namespace=default task="start bus
ybox"                                                                                                                                        
INFO[72543] event: map[string]interface {}{"play_uuid":"64006a6f-b905-4c97-b814-000000000006", "task":"start busybox", "host":"localhost", "play_pattern":"localhost", "remote_addr":"localhost", "playbook_uuid":"844d7ea0-6072-4e3b-aa9a-fc34fdeceb7b", "task_action":"k8s", "task_args"
:"_ansible_version=2.6.3, definition={u'kind': u'Deployment', u'spec': {u'template': {u'spec': {u'containers': [{u'image': u'busybox', u'args': [u'-c', u\"while true; do echo 'hello world'; sleep 10 ;done\"], u'command': [u'/bin/sh'], u'name': u'test'}]}, u'metadata': {u'labels': {
u'app': u'test'}}}, u'selector': {u'matchLabels': {u'app': u'test'}}}, u'apiVersion': u'apps/v1', u'metadata': {u'namespace': u'default', u'name': u'example-busybox'}}, _ansible_selinux_special_fs=['fuse', 'nfs', 'vboxsf', 'ramfs', '9p'], _ansible_no_log=False, _ansible_module_name
=k8s, _ansible_debug=False, _ansible_verbosity=2, _ansible_keep_remote_files=False, _ansible_syslog_facility=LOG_USER, _ansible_socket=None, _ansible_diff=False, _ansible_remote_tmp=~/.ansible/tmp, _ansible_shell_executable=/bin/sh, _ansible_check_mode=False, _ansible_tmpdir=/home/
dymurray/.ansible/tmp/ansible-tmp-1537968955.5-75296223558483/", "task_uuid":"64006a6f-b905-4c97-b814-00000000000e", "role":"busybox", "play":"localhost", "event_loop":interface {}(nil), "playbook":"/opt/ansible/playbook.yaml", "task_path":"/opt/ansible/roles/busybox/tasks/main.yml
:3", "res":map[string]interface {}{"invocation":map[string]interface {}{"module_args":map[string]interface {}{"ssl_ca_cert":interface {}(nil), "force":false, "host":interface {}(nil), "kubeconfig":interface {}(nil), "verify_ssl":interface {}(nil), "context":interface {}(nil), "key_
file":interface {}(nil), "password":interface {}(nil), "username":interface {}(nil), "api_key":interface {}(nil), "state":"present", "cert_file":interface {}(nil)}}, "diff":[]interface {}{}, "method":"patch", "_ansible_parsed":true, "_ansible_no_log":false, "changed":false, "result
":map[string]interface {}{"status":map[string]interface {}{"conditions":[]interface {}{map[string]interface {}{"type":"Available", "status":"True", "lastUpdateTime":"2018-09-25T17:26:57Z", "lastTransitionTime":"2018-09-25T17:26:57Z", "reason":"MinimumReplicasAvailable", "message":"
Deployment has minimum availability."}, map[string]interface {}{"type":"Progressing", "status":"True", "lastUpdateTime":"2018-09-25T17:26:57Z", "lastTransitionTime":"2018-09-25T17:26:54Z", "reason":"NewReplicaSetAvailable", "message":"ReplicaSet \"example-busybox-5b5d4b7cdf\" has s
uccessfully progressed."}}, "replicas":1, "observedGeneration":1, "updatedReplicas":1, "availableReplicas":1, "readyReplicas":1}, "kind":"Deployment", "spec":map[string]interface {}{"strategy":map[string]interface {}{"rollingUpdate":map[string]interface {}{"maxUnavailable":"25%", "
maxSurge":"25%"}, "type":"RollingUpdate"}, "template":map[string]interface {}{"spec":map[string]interface {}{"containers":[]interface {}{map[string]interface {}{"command":[]interface {}{"/bin/sh"}, "imagePullPolicy":"Always", "resources":map[string]interface {}{}, "terminationMessa
gePath":"/dev/termination-log", "name":"test", "image":"busybox", "args":[]interface {}{"-c", "while true; do echo 'hello world'; sleep 10 ;done"}, "terminationMessagePolicy":"File"}}, "dnsPolicy":"ClusterFirst", "securityContext":map[string]interface {}{}, "schedulerName":"default
-scheduler", "terminationGracePeriodSeconds":30, "restartPolicy":"Always"}, "metadata":map[string]interface {}{"labels":map[string]interface {}{"app":"test"}, "creationTimestamp":interface {}(nil)}}, "revisionHistoryLimit":10, "progressDeadlineSeconds":600, "selector":map[string]in
terface {}{"matchLabels":map[string]interface {}{"app":"test"}}, "replicas":1}, "apiVersion":"apps/v1", "metadata":map[string]interface {}{"ownerReferences":[]interface {}{map[string]interface {}{"kind":"Database", "name":"example", "apiVersion":"app.example.com/v1alpha1", "uid":"a
8e980a8-c0e6-11e8-b631-5254003d3794"}}, "annotations":map[string]interface {}{"deployment.kubernetes.io/revision":"1"}, "uid":"329bd2de-c0e8-11e8-b631-5254003d3794", "name":"example-busybox", "generation":1, "namespace":"default", "resourceVersion":"117665", "creationTimestamp":"20
18-09-25T17:26:54Z", "selfLink":"/apis/apps/v1/namespaces/default/deployments/example-busybox"}}}, "pid":28967}  component=logging_event_handler event_type=runner_on_ok gvk="app.example.com/v1alpha1, Kind=Database" name=example namespace=default task="start busybox"
INFO[72543] event: map[string]interface {}{"play_uuid":"64006a6f-b905-4c97-b814-000000000006", "is_conditional":false, "playbook_uuid":"844d7ea0-6072-4e3b-aa9a-fc34fdeceb7b", "play_pattern":"localhost", "task":"debug", "task_args":"msg=sentinel value '{{ sentinel }}' detected, this
 is a finalizer", "name":"debug", "pid":28967, "task_action":"debug", "task_path":"/opt/ansible/playbook.yaml:9", "play":"localhost", "task_uuid":"64006a6f-b905-4c97-b814-000000000012", "playbook":"/opt/ansible/playbook.yaml"}  component=logging_event_handler event_type=playbook_on
_task_start gvk="app.example.com/v1alpha1, Kind=Database" name=example namespace=default task=debug
INFO[72543] event: map[string]interface {}{"task_args":"msg=sentinel value '{{ sentinel }}' detected, this is a finalizer", "pid":28967, "playbook_uuid":"844d7ea0-6072-4e3b-aa9a-fc34fdeceb7b", "play_pattern":"localhost", "task":"debug", "event_loop":interface {}(nil), "host":"local
host", "task_path":"/opt/ansible/playbook.yaml:9", "remote_addr":"localhost", "task_uuid":"64006a6f-b905-4c97-b814-000000000012", "play":"localhost", "task_action":"debug", "play_uuid":"64006a6f-b905-4c97-b814-000000000006", "playbook":"/opt/ansible/playbook.yaml"}  component=loggi
ng_event_handler event_type=runner_on_skipped gvk="app.example.com/v1alpha1, Kind=Database" name=example namespace=default task=debug
INFO[72543] event: map[string]interface {}{"verbosity":2, "play_uuid":"64006a6f-b905-4c97-b814-000000000006", "task_uuid":"64006a6f-b905-4c97-b814-000000000012", "playbook":"/opt/ansible/playbook.yaml", "task_action":"debug", "play":"localhost", "task_args":"msg=sentinel value '{{
sentinel }}' detected, this is a finalizer", "verbose":true, "pid":28967, "playbook_uuid":"844d7ea0-6072-4e3b-aa9a-fc34fdeceb7b", "task_path":"/opt/ansible/playbook.yaml:9", "play_pattern":"localhost", "task":"debug"}  component=logging_event_handler event_type=verbose gvk="app.exa
mple.com/v1alpha1, Kind=Database" name=example namespace=default task=debug
INFO[72543] event: map[string]interface {}{"playbook":"/opt/ansible/playbook.yaml", "task":"debug", "task_args":"msg=sentinel value '{{ sentinel }}' detected, this is a finalizer", "verbose":true, "pid":28967, "play_uuid":"64006a6f-b905-4c97-b814-000000000006", "task_uuid":"64006a6
f-b905-4c97-b814-000000000012", "playbook_uuid":"844d7ea0-6072-4e3b-aa9a-fc34fdeceb7b", "play_pattern":"localhost", "play":"localhost", "verbosity":2, "task_action":"debug", "task_path":"/opt/ansible/playbook.yaml:9"}  component=logging_event_handler event_type=verbose gvk="app.exa
mple.com/v1alpha1, Kind=Database" name=example namespace=default task=debug
INFO[72543] dropping event that is not a JobEvent         component=eventapi job=7143879604877439377
INFO[72543] ansible-runner exited successfully            component=runner job=7143879604877439377 name=example namespace=default

[mhrivnak]

Can you add fixes #45 to the commit message? That'll link it to the bug report and auto-close it when this gets merged.

[johnkim76]

@mhrivnak revised the comment on the commit as suggested

[mhrivnak]

LGTM!