Note: This bug is displayed in read-only format because the product is no longer active in Red Hat Bugzilla.

Bug 1592823

Summary: Update logs should have timestamps to make debugging easier
Product: Red Hat OpenStack Reporter: Jiri Stransky <jstransk>
Component: openstack-tripleo-commonAssignee: Jiri Stransky <jstransk>
Status: CLOSED ERRATA QA Contact: Raviv Bar-Tal <rbartal>
Severity: low Docs Contact:
Priority: medium    
Version: 13.0 (Queens)CC: augol, ccamacho, jchhatba, jstransk, lmarsh, mburns, mcornea, morazi, slinaber, trozet
Target Milestone: z1Keywords: Triaged, ZStream
Target Release: 13.0 (Queens)   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: openstack-tripleo-common-8.6.1-23.el7ost Doc Type: Enhancement
Doc Text:
Logs from Ansible playbooks now include timestamps that provide information about the timing of actions during deployment, updates, and upgrades.
Story Points: ---
Clone Of: Environment:
Last Closed: 2018-07-19 14:27:12 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

Description Jiri Stransky 2018-06-19 11:47:34 UTC
With bugs where finding root cause is difficult, timestamps on activity logs are often useful clues. Currently we don't have timestamps on logs from updates and upgrades.

Comment 1 Jiri Stransky 2018-06-29 14:22:06 UTC
Merged to stable/queens.

Comment 8 Marius Cornea 2018-07-17 15:43:17 UTC
Snippet of stdout of openstack overcloud update run --nodes Controller --playbook all:

2018-07-15 14:40:47 |  u'TASK [Check if /var/lib/docker-puppet/docker-puppet-tasks5.json exists] ********',
2018-07-15 14:40:47 |  u'Sunday 15 July 2018  14:40:41 -0400 (0:00:01.967)       1:17:20.600 *********** ',
2018-07-15 14:40:47 |  u'ok: [192.168.24.13] => {"changed": false, "stat": {"exists": false}}',
2018-07-15 14:40:47 |  u'',
2018-07-15 14:40:47 |  u'TASK [Run docker-puppet tasks (bootstrap tasks) for step 5] ********************',
2018-07-15 14:40:47 |  u'Sunday 15 July 2018  14:40:43 -0400 (0:00:02.370)       1:17:22.971 *********** ',
2018-07-15 14:40:47 |  u'skipping: [192.168.24.13] => {"censored": "the output has been hidden due to the fact that \'no_log: true\' was specified for this result", "changed": false}',
2018-07-15 14:40:47 |  u'',
2018-07-15 14:40:47 |  u'TASK [Debug output for task which failed: Run docker-puppet tasks (bootstrap tasks) for step 5] ***',
2018-07-15 14:40:47 |  u'Sunday 15 July 2018  14:40:43 -0400 (0:00:00.047)       1:17:23.018 *********** ',
2018-07-15 14:40:47 |  u'skipping: [192.168.24.13] => {"changed": false, "skip_reason": "Conditional result was False"}',
2018-07-15 14:40:47 |  u'',
2018-07-15 14:40:47 |  u'PLAY RECAP *********************************************************************',
2018-07-15 14:40:47 |  u'192.168.24.13              : ok=221  changed=65   unreachable=0    failed=0   ',
2018-07-15 14:40:47 |  u'192.168.24.19              : ok=216  changed=64   unreachable=0    failed=0   ',
2018-07-15 14:40:47 |  u'192.168.24.8               : ok=216  changed=64   unreachable=0    failed=0   ',
2018-07-15 14:40:47 |  u'',
2018-07-15 14:40:47 |  u'Sunday 15 July 2018  14:40:43 -0400 (0:00:00.026)       1:17:23.045 *********** ',
2018-07-15 14:40:47 |  u'=============================================================================== ']
2018-07-15 14:40:47 | Success


Snippet of var/log/mistral/package_update.log

2018-07-15 15:05:48,003 p=16680 u=mistral |  TASK [Check if /var/lib/docker-puppet/docker-puppet-tasks5.json exists] ********
2018-07-15 15:05:48,004 p=16680 u=mistral |  Sunday 15 July 2018  15:05:48 -0400 (0:00:00.065)       0:11:47.433 *********** 
2018-07-15 15:05:50,211 p=16680 u=mistral |  ok: [192.168.24.17] => {"changed": false, "stat": {"exists": false}}
2018-07-15 15:05:50,230 p=16680 u=mistral |  TASK [Run docker-puppet tasks (bootstrap tasks) for step 5] ********************
2018-07-15 15:05:50,231 p=16680 u=mistral |  Sunday 15 July 2018  15:05:50 -0400 (0:00:02.227)       0:11:49.660 *********** 
2018-07-15 15:05:50,258 p=16680 u=mistral |  skipping: [192.168.24.17] => {"censored": "the output has been hidden due to the fact that 'no_log: true' was specified for this result", "changed": false}
2018-07-15 15:05:50,273 p=16680 u=mistral |  TASK [Debug output for task which failed: Run docker-puppet tasks (bootstrap tasks) for step 5] ***
2018-07-15 15:05:50,273 p=16680 u=mistral |  Sunday 15 July 2018  15:05:50 -0400 (0:00:00.041)       0:11:49.702 *********** 
2018-07-15 15:05:50,297 p=16680 u=mistral |  skipping: [192.168.24.17] => {"changed": false, "skip_reason": "Conditional result was False"}
2018-07-15 15:05:50,300 p=16680 u=mistral |  PLAY RECAP *********************************************************************
2018-07-15 15:05:50,300 p=16680 u=mistral |  192.168.24.14              : ok=83   changed=18   unreachable=0    failed=0   
2018-07-15 15:05:50,300 p=16680 u=mistral |  192.168.24.17              : ok=83   changed=18   unreachable=0    failed=0   
2018-07-15 15:05:50,301 p=16680 u=mistral |  192.168.24.7               : ok=83   changed=18   unreachable=0    failed=0   
2018-07-15 15:05:50,301 p=16680 u=mistral |  Sunday 15 July 2018  15:05:50 -0400 (0:00:00.027)       0:11:49.730 *********** 
2018-07-15 15:05:50,301 p=16680 u=mistral |  =============================================================================== 

Timestamps are present so we can move this bug to verified.

Comment 10 errata-xmlrpc 2018-07-19 14:27:12 UTC
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHSA-2018:2214