Public bug reported:
Hi,
The timestamps displayed in /var/log/cloud-init.log are different from
the timestamps displayed in "journactl -u cloud-init".
For example :
$ head -n1 /var/log/cloud-init.log ; tail -n 1 /var/log/cloud-init.log
Jan 17 23:22:58 foo [CLOUDINIT] util.py[DEBUG]: Cloud-init v. 0.7.8 running
'init-local' at Tue, 17 Jan 2017 23:22:36 +0000. Up 6.24 seconds.
Jan 17 23:23:01 foo [CLOUDINIT] handlers.py[DEBUG]: finish: modules-final:
SUCCESS: running modules for final
Here, by looking at the timestamp at the beginning of the 2 lines, you
could believe that cloud-init took 3 seconds to complete.
However, there are several pieces of information that contradicts this.
First, there is a discrepancy in the first line pasted above : the first
timestamp says "Jan 17 23:22:58" but on the same line, you also have "at
Tue, 17 Jan 2017 23:22:36 +0000."
Then, there is the console log (this is an OpenStack VM), which shows :
cloud-init[1050]: Cloud-init v. 0.7.8 running 'init' at Tue, 17 Jan 2017
23:22:38 +0000. Up 7.55 seconds.
[...]
cloud-init[1690]: Cloud-init v. 0.7.8 running 'modules:final' at Tue, 17 Jan
2017 23:23:00 +0000. Up 30.32 seconds.
which hints that the run took ~23 seconds.
Then, there are the various "duration" messages in /var/log/cloud-init.log :
$ grep ' took ' /var/log/cloud-init.log
Jan 17 23:22:58 foo [CLOUDINIT] util.py[DEBUG]: cloud-init mode 'init' took
0.530 seconds (0.53)
Jan 17 23:22:58 foo [CLOUDINIT] util.py[DEBUG]: Crawl of openstack metadata
service took 18.093 seconds
Jan 17 23:22:58 foo [CLOUDINIT] util.py[DEBUG]: resize_devices took 0.082
seconds
Jan 17 23:22:58 foo [CLOUDINIT] util.py[DEBUG]: Resizing took 0.048 seconds
Jan 17 23:23:00 foo [CLOUDINIT] util.py[DEBUG]: cloud-init mode 'modules' took
1.764 seconds (1.77)
Jan 17 23:23:01 foo [CLOUDINIT] util.py[DEBUG]: cloud-init mode 'modules' took
0.240 seconds (0.24)
The metadata discovery alone took 18s !
And finally, it looks like the proper information is produced by "journactl -u
cloud-init" :
$ journalctl -u cloud-init |head -n2
-- Logs begin at Tue 2017-01-17 23:22:35 UTC, end at Wed 2017-01-18 12:28:22
UTC. --
Jan 17 23:22:37 ubuntu systemd[1]: Starting Initial cloud-init job (metadata
service crawler)...
$ journalctl -u cloud-init |tail -n1
Jan 17 23:22:57 foo systemd[1]: Started Initial cloud-init job (metadata
service crawler).
Could we please get the correct timestamps in /var/log/cloud-init.log ?
Thanks
** Affects: cloud-init
Importance: Undecided
Status: New
--
You received this bug notification because you are a member of Yahoo!
Engineering Team, which is subscribed to cloud-init.
https://bugs.launchpad.net/bugs/1657446
Title:
Wrong timestamps in /var/log/cloud-init.log
Status in cloud-init:
New
Bug description:
Hi,
The timestamps displayed in /var/log/cloud-init.log are different from
the timestamps displayed in "journactl -u cloud-init".
For example :
$ head -n1 /var/log/cloud-init.log ; tail -n 1 /var/log/cloud-init.log
Jan 17 23:22:58 foo [CLOUDINIT] util.py[DEBUG]: Cloud-init v. 0.7.8 running
'init-local' at Tue, 17 Jan 2017 23:22:36 +0000. Up 6.24 seconds.
Jan 17 23:23:01 foo [CLOUDINIT] handlers.py[DEBUG]: finish: modules-final:
SUCCESS: running modules for final
Here, by looking at the timestamp at the beginning of the 2 lines, you
could believe that cloud-init took 3 seconds to complete.
However, there are several pieces of information that contradicts
this.
First, there is a discrepancy in the first line pasted above : the
first timestamp says "Jan 17 23:22:58" but on the same line, you also
have "at Tue, 17 Jan 2017 23:22:36 +0000."
Then, there is the console log (this is an OpenStack VM), which shows
:
cloud-init[1050]: Cloud-init v. 0.7.8 running 'init' at Tue, 17 Jan 2017
23:22:38 +0000. Up 7.55 seconds.
[...]
cloud-init[1690]: Cloud-init v. 0.7.8 running 'modules:final' at Tue, 17 Jan
2017 23:23:00 +0000. Up 30.32 seconds.
which hints that the run took ~23 seconds.
Then, there are the various "duration" messages in /var/log/cloud-init.log :
$ grep ' took ' /var/log/cloud-init.log
Jan 17 23:22:58 foo [CLOUDINIT] util.py[DEBUG]: cloud-init mode 'init' took
0.530 seconds (0.53)
Jan 17 23:22:58 foo [CLOUDINIT] util.py[DEBUG]: Crawl of openstack metadata
service took 18.093 seconds
Jan 17 23:22:58 foo [CLOUDINIT] util.py[DEBUG]: resize_devices took 0.082
seconds
Jan 17 23:22:58 foo [CLOUDINIT] util.py[DEBUG]: Resizing took 0.048 seconds
Jan 17 23:23:00 foo [CLOUDINIT] util.py[DEBUG]: cloud-init mode 'modules'
took 1.764 seconds (1.77)
Jan 17 23:23:01 foo [CLOUDINIT] util.py[DEBUG]: cloud-init mode 'modules'
took 0.240 seconds (0.24)
The metadata discovery alone took 18s !
And finally, it looks like the proper information is produced by "journactl
-u cloud-init" :
$ journalctl -u cloud-init |head -n2
-- Logs begin at Tue 2017-01-17 23:22:35 UTC, end at Wed 2017-01-18 12:28:22
UTC. --
Jan 17 23:22:37 ubuntu systemd[1]: Starting Initial cloud-init job (metadata
service crawler)...
$ journalctl -u cloud-init |tail -n1
Jan 17 23:22:57 foo systemd[1]: Started Initial cloud-init job (metadata
service crawler).
Could we please get the correct timestamps in /var/log/cloud-init.log
?
Thanks
To manage notifications about this bug go to:
https://bugs.launchpad.net/cloud-init/+bug/1657446/+subscriptions
--
Mailing list: https://launchpad.net/~yahoo-eng-team
Post to : yahoo-eng-team@lists.launchpad.net
Unsubscribe : https://launchpad.net/~yahoo-eng-team
More help : https://help.launchpad.net/ListHelp
