tripleo container update logs wrong timestamps

[Bogdan Dobrelya]

https://openstack.fortnebula.com:13808/v1/AUTH_e8fd161dc34c421a979a9e6421f823e9/zuul_opendev_logs_3a8/685175/8/check/tripleo-ci-centos-7-scenario000-multinode-oooq-container-upgrades/3a81468/logs/undercloud/var/log/tripleo-container-image-prepare.log.txt.gz

Logged http://paste.openstack.org/show/bZOlUZR4qN7fLsujotlh/:
2019-09-28 17:21:37,194 p=22890 u=root | TASK [tripleo-modify-image : Run yum_update.sh] ********************************
...
2019-09-28 17:21:37,823 p=22890 u=root | TASK [tripleo-modify-image : Remove temporary yum_update.sh script] ************

While the real time it took was 0:00:24.837:
2019-09-28 17:21:37,294 p=22890 u=root | Saturday 28 September 2019 17:21:37 +0000 (0:00:24.837) 0:00:28.767 ****

Another example https://storage.bhs1.cloud.ovh.net/v1/AUTH_dcaab5e32b234d56b626f72581e3644c/zuul_opendev_logs_c26/684835/9/check/tripleo-ci-centos-7-containers-multinode/c26ebd0/logs/undercloud/var/log/tripleo-container-image-prepare.log.txt.gz

http://paste.openstack.org/show/VSPIaYbvubhT7tHPyHQm/ :

More of that, in https://openstack.fortnebula.com:13808/v1/AUTH_e8fd161dc34c421a979a9e6421f823e9/zuul_opendev_logs_4cc/685378/2/check/tripleo-ci-centos-7-containers-multinode/4ccc1c6/logs/undercloud/var/log/tripleo-container-image-prepare.log.txt.gz

https://storage.bhs1.cloud.ovh.net/v1/AUTH_dcaab5e32b234d56b626f72581e3644c/zuul_opendev_logs_80a/685378/2/check/tripleo-ci-centos-7-scenario000-multinode-oooq-container-updates/80a6b86/logs/undercloud/var/log/tripleo-container-image-prepare.log.txt.gz

https://openstack.fortnebula.com:13808/v1/AUTH_e8fd161dc34c421a979a9e6421f823e9/zuul_opendev_logs_7ad/685378/2/check/tripleo-ci-centos-7-scenario000-multinode-oooq-container-upgrades/7ad7858/logs/undercloud/var/log/tripleo-container-image-prepare.log.txt.gz

This complicates profiling of the container images update optimizations have been submitted recently

[Bogdan Dobrelya (bogdando)]

Actually, I think that only affects the unmerged https://review.opendev.org/#/c/685175

[Bogdan Dobrelya (bogdando)]

The another unmerged change https://review.opendev.org/684411 is also affected by that issue

[Bogdan Dobrelya (bogdando)]

I confirm I can also observe it for the current master branch state https://storage.bhs1.cloud.ovh.net/v1/AUTH_dcaab5e32b234d56b626f72581e3644c/zuul_opendev_logs_80a/685378/2/check/tripleo-ci-centos-7-scenario000-multinode-oooq-container-updates/80a6b86/logs/undercloud/var/log/tripleo-container-image-prepare.log.txt.gz

[Bogdan Dobrelya (bogdando)]

Also note that that's ansible playbooks embedded timestamps, not the ones generated by the used python formatter as of https://review.opendev.org/#/c/684810/ (I think)

[Bogdan Dobrelya (bogdando)]

tl;dr http://paste.openstack.org/show/cVsQPvGhLzA2FXcYHkyO/

[Alex Schultz (alex-schultz)]

This is not a bug. The issue being shown is that since we now have timestamps in the logs, the ansible output shows up as bad timestamps. It's not really bad but rather how we print out ansible output. We print ansible output out in a single python LOG.debug(). You can see this because there's a timestamp dupe in the line that prints out the entire ansible items (that include timestamps). So this makes it look like the times are going backwards when the python timing is correct. The ansible output is not streamed so it shows up later.

2019-09-30 16:29:38.372 907906 DEBUG oslo_concurrency.processutils [ ] CMD "ansible-playbook-2 -v /tmp/tripleo-modify-image-playbook-hrR1s3/playbook.yaml" returned: 0 in 13.796s
2019-09-30 16:29:38.372 907906 INFO tripleo_common.image.image_uploader [ ] 2019-09-30 16:29:25,038 p=997113 u=root | Using /tmp/tripleo-modify-image-playbook-hrR1s3/ansible.cfg as config file
2019-09-30 16:29:25,052 p=997113 u=root | [WARNING]: provided hosts list is empty, only localhost is available. Note

[Alex Schultz (alex-schultz)]

We can improve this by logging the ansible output lines prefixed with the python timestamp.

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.opendev.org/685764

[Bogdan Dobrelya (bogdando)]

This issue should not be treated as a low-bug. It makes any decent profiling impossible. With https://review.opendev.org/#/c/684835/, users will have all type of events logged, like how long it took to process each data chunk and a layer of an image, or to fetch/yum update/upload it. But all that information turn completely useless when profiling it w/o proper timestamps.

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/685764
Committed: https://git.openstack.org/cgit/openstack/tripleo-common/commit/?id=6f92cb6685c75217606e74a3aaaf9702872513bf
Submitter: Zuul
Branch: master

commit 6f92cb6685c75217606e74a3aaaf9702872513bf
Author: Alex Schultz <email address hidden>
Date: Mon Sep 30 11:23:29 2019 -0600

    Prefix ansible output with timestamps

    We output the ansible output in a single log line which can lead to what
    appears to be out of sync timestamps. We can split the output by line
    and output that individually so the outter timestamps are in sync.

    Change-Id: I02723e0900a7490cb980fe84fbeebe83137e8554
    Closes-Bug: #1845930

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/stein
Review: https://review.opendev.org/686788

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/686788
Committed: https://git.openstack.org/cgit/openstack/tripleo-common/commit/?id=66f011325de9ed015e42eb0366e61d3846a9f649
Submitter: Zuul
Branch: stable/stein

commit 66f011325de9ed015e42eb0366e61d3846a9f649
Author: Alex Schultz <email address hidden>
Date: Mon Sep 30 11:23:29 2019 -0600

    Prefix ansible output with timestamps

    We output the ansible output in a single log line which can lead to what
    appears to be out of sync timestamps. We can split the output by line
    and output that individually so the outter timestamps are in sync.

    Change-Id: I02723e0900a7490cb980fe84fbeebe83137e8554
    Closes-Bug: #1845930
    (cherry picked from commit 6f92cb6685c75217606e74a3aaaf9702872513bf)

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/tripleo-common 11.3.0 release.

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/tripleo-common 10.8.2 release.