Boot messages in /var/log/syslog are out of order and with mostly "useless" timestamp

[Dave Chiluk]

On boot, early kernel boot messages get displayed out of order with userspace services starting. for example.

_____________________________________________________________
Aug 8 21:13:55 ubuntu systemd[1]: Started LVM2 metadata daemon.
Aug 8 21:13:55 ubuntu systemd[1]: Mounting FUSE Control File System...
Aug 8 21:13:55 ubuntu systemd[1]: Starting Apply Kernel Variables...
Aug 8 21:13:55 ubuntu systemd[1]: Starting Create Static Device Nodes in /dev...
Aug 8 21:13:55 ubuntu systemd[1]: Starting Load/Save Random Seed...
Aug 8 21:13:55 ubuntu systemd[1]: Activating swap /swap.img...
Aug 8 21:13:55 ubuntu systemd[1]: Starting Flush Journal to Persistent Storage...
Aug 8 21:13:55 ubuntu systemd[1]: Starting udev Coldplug all Devices...
Aug 8 21:13:55 ubuntu rsyslogd-2039: Could not open output pipe '/dev/xconsole':: No such file or directory [v8.16.0 try http://www.rsyslog.com/e/2039 ]
Aug 8 21:13:55 ubuntu systemd[1]: Mounted FUSE Control File System.
Aug 8 21:13:55 ubuntu systemd[1]: Started Apply Kernel Variables.
Aug 8 21:13:55 ubuntu systemd[1]: Started Load/Save Random Seed.
Aug 8 21:13:55 ubuntu rsyslogd-2007: action 'action 12' suspended, next retry is Mon Aug 8 21:14:25 2016 [v8.16.0 try http://www.rsyslog.com/e/2007 ]
Aug 8 21:13:55 ubuntu systemd[1]: Started Create Static Device Nodes in /dev.
Aug 8 21:13:55 ubuntu systemd[1]: Started Flush Journal to Persistent Storage.
Aug 8 21:13:55 ubuntu systemd[1]: Starting udev Kernel Device Manager...
Aug 8 21:13:55 ubuntu systemd[1]: Started udev Kernel Device Manager.
Aug 8 21:13:55 ubuntu systemd[1]: Started udev Coldplug all Devices.
Aug 8 21:13:55 ubuntu systemd[1]: Started Dispatch Password Requests to Console Directory Watch.
Aug 8 21:13:55 ubuntu systemd[1]: Activated swap /swap.img.
Aug 8 21:13:55 ubuntu systemd[1]: Reached target Swap.
Aug 8 21:13:55 ubuntu systemd-udevd[1507]: Process '/lib/udev/hdparm' failed with exit code 5.
Aug 8 21:13:55 ubuntu systemd-udevd[1456]: Error calling EVIOCSKEYCODE on device node '/dev/input/event2' (scan code 0x900f0, key code 152): Invalid argument
Aug 8 21:13:55 ubuntu systemd-udevd[1456]: Error calling EVIOCSKEYCODE on device node '/dev/input/event2' (scan code 0x900f1, key code 238): Invalid argument
Aug 8 21:13:55 ubuntu systemd-udevd[1456]: Error calling EVIOCSKEYCODE on device node '/dev/input/event2' (scan code 0x900f2, key code 227): Invalid argument
Aug 8 21:13:55 ubuntu systemd-udevd[1456]: Error calling EVIOCSKEYCODE on device node '/dev/input/event2' (scan code 0x900f3, key code 205): Invalid argument
Aug 8 21:13:55 ubuntu systemd-udevd[1456]: Error calling EVIOCSKEYCODE on device node '/dev/input/event2' (scan code 0x900f4, key code 225): Invalid argument
Aug 8 21:13:55 ubuntu systemd-udevd[1456]: Error calling EVIOCSKEYCODE on device node '/dev/input/event2' (scan code 0x900f5, key code 224): Invalid argument
Aug 8 21:13:55 ubuntu systemd-udevd[1456]: Error calling EVIOCSKEYCODE on device node '/dev/input/event2' (scan code 0x900f8, key code 372): Invalid argument
Aug 8 21:13:55 ubuntu systemd-udevd[1497]: Process '/lib/udev/hdparm' failed with exit code 5.
Aug 8 21:13:55 ubuntu kernel: [ 0.000000] Initializing cgroup subsys cpuset
Aug 8 21:13:55 ubuntu systemd[1]: Found device 82578DM Gigabit Network Connection.
Aug 8 21:13:55 ubuntu kernel: [ 0.000000] Initializing cgroup subsys cpu
Aug 8 21:13:55 ubuntu kernel: [ 0.000000] Initializing cgroup subsys cpuacct
Aug 8 21:13:55 ubuntu systemd-udevd[1506]: Process '/lib/udev/hdparm' failed with exit code 5.
Aug 8 21:13:55 ubuntu kernel: [ 0.000000] Linux version 4.4.0-34-generic (buildd@lgw01-20) (gcc version 5.3.1 20160413 (Ubuntu 5.3.1-14ubuntu2.1) ) #53-Ubuntu SMP Wed Jul 27 16:06:39 UTC 2016 (Ubuntu 4.4.0-34.53-generic 4.4.15)
Aug 8 21:13:55 ubuntu kernel: [ 0.000000] Command line: BOOT_IMAGE=/boot/vmlinuz-4.4.0-34-generic root=UUID=1931f21a-ee2e-4f02-abf6-6a0527f62df3 ro
Aug 8 21:13:55 ubuntu systemd[1]: Listening on Load/Save RF Kill Switch Status /dev/rfkill Watch.
Aug 8 21:13:55 ubuntu kernel: [ 0.000000] KERNEL supported cpus:
Aug 8 21:13:55 ubuntu kernel: [ 0.000000] Intel GenuineIntel
Aug 8 21:13:55 ubuntu systemd[1]: Reached target Sound Card.
Aug 8 21:13:55 ubuntu kernel: [ 0.000000] AMD AuthenticAMD
Aug 8 21:13:55 ubuntu kernel: [ 0.000000] Centaur CentaurHauls
Aug 8 21:13:55 ubuntu systemd[1]: Started Monitoring of LVM2 mirrors, snapshots etc. using dmeventd or progress polling.
Aug 8 21:13:55 ubuntu kernel: [ 0.000000] Disabled fast string operations
Aug 8 21:13:55 ubuntu systemd[1]: Reached target Local File Systems (Pre).
Aug 8 21:13:55 ubuntu kernel: [ 0.000000] x86/fpu: Legacy x87 FPU detected.
Aug 8 21:13:55 ubuntu kernel: [ 0.000000] x86/fpu: Using 'lazy' FPU context switches.
Aug 8 21:13:55 ubuntu kernel: [ 0.000000] e820: BIOS-provided physical RAM map:
Aug 8 21:13:55 ubuntu kernel: [ 0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000008fbff] usable
Aug 8 21:13:55 ubuntu kernel: [ 0.000000] BIOS-e820: [mem 0x000000000008fc00-0x000000000009ffff] reserved
Aug 8 21:13:55 ubuntu kernel: [ 0.000000] BIOS-e820: [mem 0x00000000000e0000-0x00000000000fffff] reserved
Aug 8 21:13:55 ubuntu kernel: [ 0.000000] BIOS-e820: [mem 0x0000000000100000-0x00000000bbc00fff] usable
Aug 8 21:13:55 ubuntu systemd[1]: Reached target Local File Systems.
Aug 8 21:13:55 ubuntu systemd[1]: Starting LSB: AppArmor initialization...
Aug 8 21:13:55 ubuntu systemd[1]: Starting Create Volatile Files and Directories...
_____________________________________________________________

As you can see from the above userspace services show they are started before the cpus have been initialized or the bios ram map has been processed. I'm sure this is due to systemd/journalctl, but I don't like it. Unfortunately I'm not sure if there's something that can be done about it either. Also notice that all the timestamps are Aug 8 21:13:55 which makes it additionally difficult to debug dependency problems.

Attaching full log for completeness.

[Dan Streetman (ddstreet)]

please reopen if this is still an issue