Annotate all runner_on_* events with their start/stop/duration times

[wenottingham]

This is incredibly useful information to have for a variety of needs.

Stolen from https://github.com/ansible/ansible-baseline/.

[ansible-zuul]

Build failed.

• github-workflows : SUCCESS in 49s
• ansible-tox-py36 : SUCCESS in 9m 41s
• ansible-tox-py37 : SUCCESS in 10m 15s
• ansible-build-python-tarball : SUCCESS in 3m 23s
• ansible-tox-linters : FAILURE in 6m 19s
• ansible-tox-py27 : SUCCESS in 10m 02s

[ansible-zuul]

Build succeeded.

• github-workflows : SUCCESS in 1m 00s
• ansible-tox-py36 : SUCCESS in 9m 46s
• ansible-tox-py37 : SUCCESS in 10m 23s
• ansible-build-python-tarball : SUCCESS in 4m 16s
• ansible-tox-linters : SUCCESS in 5m 43s
• ansible-tox-py27 : SUCCESS in 9m 02s

[AlanCoding]

Right now I also have #404 open.

Some quick thoughts:

• if a client wants the duration, they can subtract the values on their own, no need to do it here
• the start timestamp is duplicated with the created timestamp, ideally we should only keep one
• this doesn't work for verbose events, and I don't know if it can be made to work

[wenottingham]

if a client wants the duration, they can subtract the values on their own, no need to do it here

I disagree - we want to avoid as much post-processing of the returned events as possible - if you're operating across one million events doing data processing, having to query all the events and then compute can be expensive.

the start timestamp is duplicated with the created timestamp, ideally we should only keep one

Will look.

[AlanCoding]

This is the other place this is done:

ansible-runner/ansible_runner/display_callback/events.py

Line 158 in e1f0d86

event_dict['created'] = event_data.get('created', datetime.datetime.utcnow().isoformat())

That also does isoformat

[wenottingham]

This is the other place this is done:

ansible-runner/ansible_runner/display_callback/events.py

Line 158 in e1f0d86

event_dict['created'] = event_data.get('created', datetime.datetime.utcnow().isoformat())

That also does isoformat

That's when it processes it from the disk, if I'm reading that right, which is already after the event has finished. That's sufficiently removed from the actual event generation in Ansible that I'd prefer to do that directly on the task start.

[AlanCoding]

That's when it processes it from the disk, if I'm reading that right, which is already after the event has finished.

I do see now how these are really different animals. Logic for created is in generation of the begin dict, but I think that also applies to all the timestamps saved in this PR too. Aside from time spent in the callback plugin itself, the start time should be the same as the created timestamp for the runner_on_start events and the end time should be the same as the created for the runner_on_ok/skipped/etc. events. So I do think that all of this should be reconstructable from the client's perspective.

[matburt]

This is probably the best place to put this information. I think I'm good with this.

[AlanCoding]

⚠️ D-D-D-DANGER ZONE ⚠️

This PR is targeting the master branch, but the default branch was changed to devel. If you can change your base branch, please do that now. Otherwise you may need to close and make a new PR.

[AlanCoding]

Apparently it let me, so I went ahead and changed the base

[ryanpetrello]

@matburt @wenottingham,

This doesn't work on Ansible pre-2.8, because runner_on_start was introduced in 2.8:

ansible/ansible#47684