profile_tasks bogus time with multiple playbooks

[dseven]

SUMMARY

When ansible-playbook is invoked with two playbooks, the profile_tasks reports a bogus time for the last task in the first playbook in the summary at the end. Instead of the actual time taken by that task, it reports the time since the epoch.

ISSUE TYPE

• Bug Report

COMPONENT NAME

profile_tasks

ANSIBLE VERSION

  config file = /tmp/atest/ansible.cfg
  configured module search path = [u'/root/.ansible/plugins/modules', u'/usr/share/ansible/plugins/modules']
  ansible python module location = /usr/lib/python2.7/site-packages/ansible
  executable location = /usr/bin/ansible
  python version = 2.7.5 (default, Nov  1 2018, 03:12:47) [GCC 4.8.5 20150623 (Red Hat 4.8.5-36.0.1)]

CONFIGURATION

OS / ENVIRONMENT

EL7

STEPS TO REPRODUCE

$ cat pb1.yml 
- hosts: localhost
  tasks:
    - name: "sleep 1a"
      command: "sleep 1"
    - name: "sleep 1b"
      command: "sleep 1"
    - name: "sleep 1c"
      command: "sleep 1"
$ cat pb2.yml 
- hosts: localhost
  tasks:
    - name: "sleep 2a"
      command: "sleep 1"
    - name: "sleep 2b"
      command: "sleep 1"
    - name: "sleep 2c"
      command: "sleep 1"
$ 

EXPECTED RESULTS

"sleep 1c" in the summary should show approx 1 second (actual "1.21s" in the example below)

ACTUAL RESULTS

"sleep 1c" in the summary shows time since epoch ("1550785925.32s")

1550785919.47
$ ansible-playbook pb1.yml pb2.yml
 [WARNING]: provided hosts list is empty, only localhost is available. Note that the implicit
localhost does not match 'all'


PLAY [localhost] *********************************************************************************

TASK [Gathering Facts] ***************************************************************************
Thursday 21 February 2019  21:52:01 +0000 (0:00:00.104)       0:00:00.104 ***** 
ok: [localhost]

TASK [sleep 1a] **********************************************************************************
Thursday 21 February 2019  21:52:02 +0000 (0:00:01.110)       0:00:01.215 ***** 
changed: [localhost]

TASK [sleep 1b] **********************************************************************************
Thursday 21 February 2019  21:52:04 +0000 (0:00:01.423)       0:00:02.639 ***** 
changed: [localhost]

TASK [sleep 1c] **********************************************************************************
Thursday 21 February 2019  21:52:05 +0000 (0:00:01.236)       0:00:03.875 ***** 
changed: [localhost]

PLAY RECAP ***************************************************************************************
localhost                  : ok=4    changed=3    unreachable=0    failed=0   

Thursday 21 February 2019  21:52:06 +0000 (0:00:01.205)       0:00:05.080 ***** 
=============================================================================== 
sleep 1a ---------------------------------------------------------------------------------- 1.42s
sleep 1b ---------------------------------------------------------------------------------- 1.24s
sleep 1c ---------------------------------------------------------------------------------- 1.21s
Gathering Facts --------------------------------------------------------------------------- 1.11s

PLAY [localhost] *********************************************************************************

TASK [Gathering Facts] ***************************************************************************
Thursday 21 February 2019  21:52:06 +0000 (0:00:00.065)       0:00:05.145 ***** 
ok: [localhost]

TASK [sleep 2a] **********************************************************************************
Thursday 21 February 2019  21:52:07 +0000 (0:00:00.629)       0:00:05.775 ***** 
changed: [localhost]

TASK [sleep 2b] **********************************************************************************
Thursday 21 February 2019  21:52:08 +0000 (0:00:01.237)       0:00:07.013 ***** 
changed: [localhost]

TASK [sleep 2c] **********************************************************************************
Thursday 21 February 2019  21:52:09 +0000 (0:00:01.235)       0:00:08.248 ***** 
changed: [localhost]

PLAY RECAP ***************************************************************************************
localhost                  : ok=8    changed=6    unreachable=0    failed=0   

Thursday 21 February 2019  21:52:10 +0000 (0:00:01.203)       0:00:09.452 ***** 
=============================================================================== 
sleep 1c ------------------------------------------------------------------------------- 1550785925.32s
sleep 1a ---------------------------------------------------------------------------------- 1.42s
sleep 2a ---------------------------------------------------------------------------------- 1.24s
sleep 1b ---------------------------------------------------------------------------------- 1.24s
sleep 2b ---------------------------------------------------------------------------------- 1.24s
sleep 2c ---------------------------------------------------------------------------------- 1.20s
Gathering Facts --------------------------------------------------------------------------- 1.11s
Gathering Facts --------------------------------------------------------------------------- 0.63s
$ 

[ansibot]

Files identified in the description:

• lib/ansible/plugins/callback/profile_tasks.py

If these files are inaccurate, please update the component name section of the description or use the !component bot command.

click here for bot help

[samdoran]

Verified this is still the case in devel.