5

I'm looking for causes of a particular problem in kern.log. There are many entries with a 00:00:00 timestamp:

Jun 11 00:00:00 mymachine kernel: [    0.000000] Initializing cgroup subsys cpusetJun 11 00:00:00 mymachine kernel: [    0.000000] Initializing cgroup subsys cpu
Jun 11 00:00:00 mymachine kernel: [    0.000000] Linux version 3.2.0-33-virtual (buildd@batsu) (gcc version 4.6.3 (Ubuntu/Linaro 4.6.3-1ubuntu5) ) #52-Ubuntu SMP Thu Oct 18 16:48:3
7 UTC 2012 (Ubuntu 3.2.0-33.52-virtual 3.2.31)
Jun 11 00:00:00 mymachine kernel: [    0.000000] Command line: BOOT_IMAGE=/boot/vmlinuz-3.2.0-33-virtual root=LABEL=cloudimg-rootfs ro console=ttyS0

Assuming I didn't actually boot the machine up at midnight - does the 00:00:00 timestamp mean a particular phase of the bootup process? Any particular reason they do this?

(It's an Ubuntu Precise VM hosted on OpenStack, if that matters. I think this boot up was immediately after being cloned from another image.)

EDIT More information:

As far as I can tell (pgrep ntp, ls /etc/ntp* ) ntp is not running.

The time seems to (correctly) be set to UTC, with (incorrectly) no local timezone set.

EDIT2 The last log entries at 00:00:00 looks like this:

Jun 11 00:00:00 mymachine kernel: [    6.324599] type=1400 audit(1370908796.761:11): apparmor="STATUS" operation="profile_load" name="/usr/sbin/tcpdump" pid=875 comm="apparmor_parser"
Jun 11 00:00:02 mymachine kernel: [   12.259133] postgres (1033): /proc/1033/oom_adj is deprecated, please use /proc/1033/oom_score_adj instead.
Jun 11 00:00:05 mymachine kernel: [   13.592385] eth0: no IPv6 routers present
Jun 11 06:22:15 mymachine kernel: [22942.768233] init: tilemill main process (3167) killed by TERM signal
Jun 11 06:40:14 mymachine kernel: [24022.599001] init: tilemill main process (5640) killed by TERM signal
  • Is the box running NTP of any sort? What time does the box report when these messages are showing up? Also what timezone is the box set to? A simple date will tell you the timezone. – slm Jun 13 '13 at 8:39
  • @sim See extra information. – Steve Bennett Jun 13 '13 at 13:17
  • Thanks. What time was the server at when you noticed these logs? Or are new msgs. still showing up with the 00:00:00 time? – slm Jun 13 '13 at 13:22
  • Does this VM ever suspend? – slm Jun 13 '13 at 21:09
  • Not so far (apart from the snapshot/clone process). – Steve Bennett Jun 13 '13 at 21:36
1

Take a look at this other Unix & Linux question titled: Correlating /var/log/* timestamps.

The timing details/resolution are controlled by the settings that get passed to the kernel during boot:

$ grep PRINTK /boot/config-`uname -r`
CONFIG_PRINTK=y
CONFIG_SND_VERBOSE_PRINTK=y
CONFIG_PRINTK_TIME=y
CONFIG_BOOT_PRINTK_DELAY=y
CONFIG_EARLY_PRINTK=y
CONFIG_EARLY_PRINTK_DBGP=y

You can read more about these options here in the kernel.org git repo.

excerpt from the page above

config PRINTK_TIME

bool "Show timing information on printks"
depends on PRINTK
help

Selecting this option causes time stamps of the printk() messages to be added to the output of the syslog() system call and at the console.

The timestamp is always recorded internally, and exported to /dev/kmsg. This flag just specifies if the timestamp should be included, not that the timestamp is recorded.

The behavior is also controlled by the kernel command line parameter printk.time=1. See Documentation/kernel-parameters.txt

The timestamps [ 0.000000] are in terms of seconds since the system booted.

  • 1
    While correct, I think that OP is referring to the 0 hours, 0 minutes, 0 seconds, not the printk time. – Lekensteyn Jun 13 '13 at 8:34
  • @Lekensteyn - thanks I mis-read the time there. We'll need to follow up with him to see if he has NTP running and also what timezone the box is in to determine what's up with the 00:00:00 time. – slm Jun 13 '13 at 8:37

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.