← Back to team overview

yahoo-eng-team team mailing list archive

  1. yahoo-eng-team team
  2. Mailing list archive
  3. Message #60606

[Bug 1657446] [NEW] Wrong timestamps in /var/log/cloud-init.log

  Thread Previous • Date Previous • • Thread Next 
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

Follow ups

  Thread Previous • Date Previous • • Thread Next