search

victronenergy / venus

Victron Energy Unix/Linux OS
https://github.com/victronenergy/venus/wiki
577 stars 72 forks source link

bbb: clock issue #77

Closed mpvader closed 7 years ago

mpvader commented 7 years ago

Tests were done on a beagleboneblack, not connected to internet / ntp.

After setting the hwclock to some time in the past, the time is miraculously restored again during boot.

Which is normally not such a big issue, ie. why would someone want to set the hwclock many years back?, but it is now: setting the hwclock and then powering the device down for a few seconds before starting it up again is part of the rtc & backup battery test.

A few things I noticed in below log.

1) the hwclock is restoring the correct time: 

[    1.887398] rtc-pcf8523 1-0068: setting system clock to 2003-01-01 00:00:18 UTC (1041379218)

2) somewhere at the end, the wrong time shows up again:

Populating dev cache
Mon Oct 24 00:00:17 UTC 2016

This 2016-10-24 is the time the system had before setting it back to 2003-1-1.

Full log:

root@beaglebone:~# date 2003-1-1
Wed Jan  1 00:00:00 UTC 2003
root@beaglebone:~# date
Wed Jan  1 00:00:01 UTC 2003
root@beaglebone:~# hwclock -w
root@beaglebone:~# hwclock
Wed Jan  1 00:00:05 2003  0.000000 seconds 

(here the device is rebooted)

U-Boot SPL 2015.07-venus (Oct 13 2016 - 21:50:39) reading u-boot.img reading u-boot.img

U-Boot 2015.07-venus (Oct 13 2016 - 21:50:39 +0200)

       Watchdog enabled
I2C:   ready
DRAM:  512 MiB
MMC:   OMAP SD/MMC: 0, OMAP SD/MMC: 1
Net:   <ethaddr> not set. Validating first E-fuse MAC
cpsw, usb_ether
Hit any key to stop autoboot:  0
Card did not respond to voltage select!
Card did not respond to voltage select!
switch to partitions #0, OK
mmc1(part 0) is current device
SD/MMC found on device 1
reading boot.scr
** Unable to read file boot.scr **
reading uEnv.txt
918 bytes read in 3 ms (298.8 KiB/s)
Loaded environment from uEnv.txt
Importing environment from mmc ...
Running uenvcmd ...
30731 bytes read in 28 ms (1 MiB/s)
Loaded bbb-venus.dtb
3659280 bytes read in 229 ms (15.2 MiB/s) Kernel image @ 0x82000000 [ 0x000000 - 0x37d610 ] ## Flattened Device Tree blob at 88000000
   Booting using the fdt blob at 0x88000000
   Loading Device Tree to 8fff5000, end 8ffff80a ... OK

Starting kernel ...

[    0.000000] Booting Linux on physical CPU 0x0
[    0.000000] Linux version 4.1.15-venus (matthijs@matthijs-VirtualBox) (gcc version 5.2.0 (GCC) ) #1 Fri Oct 14 09:50:13 CEST 2016
[    0.000000] CPU: ARMv7 Processor [413fc082] revision 2 (ARMv7), cr=10c5387d
[    0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache
[    0.000000] Machine model: TI AM335x BeagleBone Black
[    0.000000] cma: Reserved 16 MiB at 0x9f000000
[    0.000000] Memory policy: Data cache writeback
[    0.000000] CPU: All CPU(s) started in SVC mode.
[    0.000000] AM335X ES2.1 (sgx neon )
[    0.000000] Built 1 zonelists in Zone order, mobility grouping on.  Total pages: 130048
[    0.000000] Kernel command line: console=ttyO0,115200n8 consoleblank=0 root=/dev/mmcblk1p3 rw rootfstype=ext4 rootwait
[    0.000000] PID hash table entries: 2048 (order: 1, 8192 bytes)
[    0.000000] Dentry cache hash table entries: 65536 (order: 6, 262144 bytes)
[    0.000000] Inode-cache hash table entries: 32768 (order: 5, 131072 bytes)
[    0.000000] Memory: 487616K/524288K available (4993K kernel code, 322K rwdata, 1752K rodata, 276K init, 8172K bss, 20288K reserved, 16384K cma-reserved, 0K highmem)
[    0.000000] Virtual kernel memory layout:
[    0.000000]     vector  : 0xffff0000 - 0xffff1000   (   4 kB)
[    0.000000]     fixmap  : 0xffc00000 - 0xfff00000   (3072 kB)
[    0.000000]     vmalloc : 0xe0800000 - 0xff000000   ( 488 MB)
[    0.000000]     lowmem  : 0xc0000000 - 0xe0000000   ( 512 MB)
[    0.000000]     pkmap   : 0xbfe00000 - 0xc0000000   (   2 MB)
[    0.000000]     modules : 0xbf000000 - 0xbfe00000   (  14 MB)
[    0.000000]       .text : 0xc0008000 - 0xc069e928   (6747 kB)
[    0.000000]       .init : 0xc069f000 - 0xc06e4000   ( 276 kB)
[    0.000000]       .data : 0xc06e4000 - 0xc0734a38   ( 323 kB)
[    0.000000]        .bss : 0xc0734a38 - 0xc0f2fc18   (8173 kB)
[    0.000000] Running RCU self tests
[    0.000000] NR_IRQS:16 nr_irqs:16 16
[    0.000000] IRQ: Found an INTC at 0xfa200000 (revision 5.0) with 128 interrupts
[    0.000000] OMAP clockevent source: timer2 at 24000000 Hz
[    0.000012] sched_clock: 32 bits at 24MHz, resolution 41ns, wraps every 89478484971ns
[    0.000033] clocksource timer1: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 79635851949 ns
[    0.000077] OMAP clocksource: timer1 at 24000000 Hz
[    0.000728] Console: colour dummy device 80x30
[    0.000780] Lock dependency validator: Copyright (c) 2006 Red Hat, Inc., Ingo Molnar
[    0.000788] ... MAX_LOCKDEP_SUBCLASSES:  8
[    0.000794] ... MAX_LOCK_DEPTH:          48
[    0.000799] ... MAX_LOCKDEP_KEYS:        8191
[    0.000805] ... CLASSHASH_SIZE:          4096
[    0.000811] ... MAX_LOCKDEP_ENTRIES:     32768
[    0.000817] ... MAX_LOCKDEP_CHAINS:      65536
[    0.000823] ... CHAINHASH_SIZE:          32768
[    0.000829]  memory used by lock dependency info: 5167 kB
[    0.000835]  per task-struct memory footprint: 1152 bytes
[    0.000858] Calibrating delay loop... 996.14 BogoMIPS (lpj=4980736)
[    0.078948] pid_max: default: 32768 minimum: 301
[    0.079153] Mount-cache hash table entries: 1024 (order: 0, 4096 bytes)
[    0.079164] Mountpoint-cache hash table entries: 1024 (order: 0, 4096 bytes)
[    0.081378] CPU: Testing write buffer coherency: ok
[    0.082575] Setting up static identity map for 0x80008200 - 0x80008258
[    0.086580] devtmpfs: initialized
[    0.111907] VFP support v0.3: implementor 41 architecture 3 part 30 variant c rev 3
[    0.147541] omap_hwmod: tptc0 using broken dt data from edma
[    0.147947] omap_hwmod: tptc1 using broken dt data from edma
[    0.148329] omap_hwmod: tptc2 using broken dt data from edma
[    0.156117] omap_hwmod: debugss: _wait_target_disable failed
[    0.211179] clocksource jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
[    0.213640] pinctrl core: initialized pinctrl subsystem
[    0.218261] NET: Registered protocol family 16
[    0.225379] DMA: preallocated 256 KiB pool for atomic coherent allocations
[    0.228175] cpuidle: using governor ladder
[    0.228214] cpuidle: using governor menu
[    0.235803] OMAP GPIO hardware version 0.1
[    0.253662] No ATAGs?
[    0.253693] hw-breakpoint: debug architecture 0x4 unsupported.
[    0.323994] edma-dma-engine edma-dma-engine.0: TI EDMA DMA engine driver
[    0.328436] usbcore: registered new interface driver usbfs
[    0.328598] usbcore: registered new interface driver hub
[    0.328753] usbcore: registered new device driver usb
[    0.329765] omap_i2c 44e0b000.i2c: could not find pctldev for node /ocp/l4_wkup@44c00000/scm@210000/pinmux@800/pinmux_i2c0_pins, deferring probe
[    0.329865] omap_i2c 4802a000.i2c: could not find pctldev for node /ocp/l4_wkup@44c00000/scm@210000/pinmux@800/pinmux_i2c1_pins, deferring probe
[    0.333230] Switched to clocksource timer1
[    0.471166] NET: Registered protocol family 2
[    0.472838] TCP established hash table entries: 4096 (order: 2, 16384 bytes)
[    0.473001] TCP bind hash table entries: 4096 (order: 5, 147456 bytes)
[    0.474292] TCP: Hash tables configured (established 4096 bind 4096)
[    0.474477] UDP hash table entries: 256 (order: 2, 20480 bytes)
[    0.474647] UDP-Lite hash table entries: 256 (order: 2, 20480 bytes)
[    0.475389] NET: Registered protocol family 1
[    0.477253] CPU PMU: Failed to parse /pmu/interrupt-affinity[0]
[    0.477325] hw perfevents: enabled with armv7_cortex_a8 PMU driver, 5 counters available
[    0.481078] futex hash table entries: 256 (order: 1, 11264 bytes)
[    0.490138] VFS: Disk quotas dquot_6.6.0
[    0.490237] VFS: Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
[    0.496098] io scheduler noop registered
[    0.496131] io scheduler deadline registered
[    0.496166] io scheduler cfq registered (default)
[    0.499390] pinctrl-single 44e10800.pinmux: 142 pins at pa f9e10800 size 568
[    0.502870] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled
[    0.509457] omap_uart 44e09000.serial: no wakeirq for uart0
[    0.510033] 44e09000.serial: ttyO0 at MMIO 0x44e09000 (irq = 154, base_baud = 3000000) is a OMAP UART0
[    1.082393] console [ttyO0] enabled
[    1.089163] omap_uart 48024000.serial: no wakeirq for uart2
[    1.095367] 48024000.serial: ttyO2 at MMIO 0x48024000 (irq = 155, base_baud = 3000000) is a OMAP UART2
[    1.106736] omap_uart 481a8000.serial: no wakeirq for uart4
[    1.112847] 481a8000.serial: ttyO4 at MMIO 0x481a8000 (irq = 156, base_baud = 3000000) is a OMAP UART4
[    1.124191] omap_uart 481aa000.serial: no wakeirq for uart5
[    1.130296] 481aa000.serial: ttyO5 at MMIO 0x481aa000 (irq = 157, base_baud = 3000000) is a OMAP UART5
[    1.143183] omap_rng 48310000.rng: OMAP Random Number Generator ver. 20
[    1.182362] brd: module loaded
[    1.203626] loop: module loaded
[    1.208728] vcan: Virtual CAN interface driver
[    1.213456] slcan: serial line CAN interface driver
[    1.218569] slcan: 10 dynamic interface channels.
[    1.223526] CAN device driver interface
[    1.230058] c_can_platform 481cc000.can: c_can_platform device registered (regs=fa1cc000, irq=163)
[    1.241314] c_can_platform 481d0000.can: c_can_platform device registered (regs=fa1d0000, irq=164)
[    1.252241] usbcore: registered new interface driver asix
[    1.258093] usbcore: registered new interface driver ax88179_178a
[    1.264614] usbcore: registered new interface driver cdc_ether
[    1.270870] usbcore: registered new interface driver smsc95xx
[    1.277020] usbcore: registered new interface driver net1080
[    1.283055] usbcore: registered new interface driver cdc_subset
[    1.289382] usbcore: registered new interface driver zaurus
[    1.295439] usbcore: registered new interface driver cdc_ncm
[    1.311621] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
[    1.318568] ehci-omap: OMAP-EHCI Host Controller driver
[    1.324414] ohci_hcd: USB 1.1 'Open' Host Controller (OHCI) Driver
[    1.331093] usbcore: registered new interface driver cdc_wdm
[    1.337245] usbcore: registered new interface driver usbtest
[    1.345879] 47401300.usb-phy supply vcc not found, using dummy regulator
[    1.362294] 47401b00.usb-phy supply vcc not found, using dummy regulator
[    1.374574] musb-hdrc musb-hdrc.1.auto: MUSB HDRC host driver
[    1.383860] musb-hdrc musb-hdrc.1.auto: new USB bus registered, assigned bus number 1
[    1.393933] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002
[    1.401063] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    1.408666] usb usb1: Product: MUSB HDRC host driver
[    1.413886] usb usb1: Manufacturer: Linux 4.1.15-venus musb-hcd
[    1.420092] usb usb1: SerialNumber: musb-hdrc.1.auto
[    1.429430] hub 1-0:1.0: USB hub found
[    1.434289] hub 1-0:1.0: 1 port detected
[    1.445191] mousedev: PS/2 mouse device common for all mice
[    1.454300] i2c /dev entries driver
[    1.458057] Driver for 1-wire Dallas network protocol.
[    1.468573] omap_wdt: OMAP Watchdog Timer Rev 0x01: initial timeout 60 sec
[    1.478278] omap_hsmmc 48060000.mmc: Got CD GPIO
[    1.566616] ledtrig-cpu: registered to indicate activity on CPUs
[    1.573519] usbcore: registered new interface driver usbhid
[    1.579364] usbhid: USB HID core driver
[    1.584421] oprofile: using arm/armv7
[    1.588868] Initializing XFRM netlink socket
[    1.593744] NET: Registered protocol family 10
[    1.608661] sit: IPv6 over IPv4 tunneling driver
[    1.615719] NET: Registered protocol family 17
[    1.620461] NET: Registered protocol family 15
[    1.625209] can: controller area network core (rev 20120528 abi 9)
[    1.631813] NET: Registered protocol family 29
[    1.636591] can: raw protocol (rev 20120528)
[    1.641205] can: broadcast manager protocol (rev 20120528 t)
[    1.647632] Key type dns_resolver registered
[    1.652283] omap_voltage_late_init: Voltage driver support not added
[    1.659978] ThumbEE CPU extension supported.
[    1.709345] tps65217 0-0024: TPS65217 ID 0xe version 1.2
[    1.715166] omap_i2c 44e0b000.i2c: bus 0 rev0.11 at 400 kHz
[    1.722127] mmc1: MAN_BKOPS_EN bit is not set
[    1.735395] mmc1: new high speed MMC card at address 0001
[    1.744424] mmcblk1: mmc1:0001 S10004 3.56 GiB
[    1.749868] mmcblk1boot0: mmc1:0001 S10004 partition 1 4.00 MiB
[    1.756531] mmcblk1boot1: mmc1:0001 S10004 partition 2 4.00 MiB
[    1.767354] rtc-pcf8523 1-0068: rtc core: registered rtc-pcf8523 as rtc0
[    1.774547] omap_i2c 4802a000.i2c: bus 1 rev0.11 at 400 kHz
[    1.801477]  mmcblk1: p1 p2 p3 p4 < p5 p6 >
[    1.844098] davinci_mdio 4a101000.mdio: davinci mdio revision 1.6
[    1.850512] davinci_mdio 4a101000.mdio: detected phy mask fffffffe
[    1.859847] libphy: 4a101000.mdio: probed
[    1.864150] davinci_mdio 4a101000.mdio: phy[0]: device 4a101000.mdio:00, driver SMSC LAN8710/LAN8720
[    1.874870] cpsw 4a100000.ethernet: Detected MACID = b0:d5:cc:ff:e6:e0
[    1.887398] rtc-pcf8523 1-0068: setting system clock to 2003-01-01 00:00:18 UTC (1041379218)
[    1.943643] usb 1-1: new high-speed USB device number 2 using musb-hdrc
[    1.990019] EXT4-fs (mmcblk1p3): recovery complete
[    1.996921] EXT4-fs (mmcblk1p3): mounted filesystem with ordered data mode. Opts: (null)
[    2.005615] VFS: Mounted root (ext4 filesystem) on device 179:11.
[    2.016375] devtmpfs: mounted
[    2.019995] Freeing unused kernel memory: 276K (c069f000 - c06e4000)
INIT: [    2.099554] usb 1-1: New USB device found, idVendor=05e3, idProduct=0610
[    2.107036] usb 1-1: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[    2.114545] usb 1-1: Product: USB2.0 Hub
[    2.118658] usb 1-1: Manufacturer: GenesysLogic
version 2.88 booting[    2.127671] hub 1-1:1.0: USB hub found
[    2.132849] hub 1-1:1.0: 4 ports detected

[    2.383028] EXT4-fs (mmcblk1p5): recovery complete
[    2.389222] EXT4-fs (mmcblk1p5): mounted filesystem with ordered data mode. Opts: (null)
[    2.404221] EXT4-fs (mmcblk1p6): recovery complete
[    2.409290] EXT4-fs (mmcblk1p6): mounted filesystem with ordered data mode. Opts: (null)
[    2.417929] usb 1-1.2: new full-speed USB device number 3 using musb-hdrc
Starting udev
[    2.533002] usb 1-1.2: New USB device found, idVendor=0403, idProduct=6015
[    2.540314] usb 1-1.2: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[    2.547998] usb 1-1.2: Product: VE Direct cable
[    2.552748] usb 1-1.2: Manufacturer: VictronEnergy BV
[    2.558058] usb 1-1.2: SerialNumber: HQ16265K1FV
udev: Not using udev cache because of changes detected in the following files:
udev:     /proc/version /proc/cmdline /proc/devices
udev:     lib/udev/rules.d/* etc/udev/rules.d/*
udev: The udev cache will be regenerated. To identify the detected changes,
udev: compare the cached sysconf at   /etc/udev/cache.data
udev: against the current sysconf at  /dev/shm/udev.cache
[    2.673351] usb 1-1.4: new full-speed USB device number 4 using musb-hdrc
[    2.697850] udevd[674]: starting version 182
[    2.793225] usb 1-1.4: New USB device found, idVendor=0403, idProduct=6015
[    2.800551] usb 1-1.4: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[    2.808236] usb 1-1.4: Product: VE Direct cable
[    2.812984] usb 1-1.4: Manufacturer: VictronEnergy BV
[    2.818294] usb 1-1.4: SerialNumber: HQ16262VB1N
[    2.913440] usbcore: registered new interface driver usbserial
[    2.919725] usbcore: registered new interface driver usbserial_generic
[    2.927464] usbserial: USB Serial support registered for generic
[    2.993048] usbcore: registered new interface driver ftdi_sio
[    2.999392] usbserial: USB Serial support registered for FTDI USB Serial Device
[    3.007429] ftdi_sio 1-1.2:1.0: FTDI USB Serial Device converter detected
[    3.015227] usb 1-1.2: Detected FT-X
[    3.085014] usb 1-1.2: FTDI USB Serial Device converter now attached to ttyUSB0
[    3.093439] ftdi_sio 1-1.4:1.0: FTDI USB Serial Device converter detected
[    3.100955] usb 1-1.4: Detected FT-X
[    3.187992] usb 1-1.4: FTDI USB Serial Device converter now attached to ttyUSB1
[    7.086496] EXT4-fs (mmcblk1p3): re-mounted. Opts: data=ordered
bootlogd: cannot allocate pseudo tty: No such file or directory
[    7.238757] random: dd urandom read with 45 bits of entropy available
Populating dev cache
Mon Oct 24 00:00:17 UTC 2016
Starting watchdog
[    8.320741] watchdog watchdog0: watchdog did not stop!
INIT: Entering runlevel: 4
Configuring network interfaces... [   10.519429] net eth0: initializing cpsw version 1.12 (0)
[   10.527521] net eth0: phy found : id is : 0x7c0f1
[   10.532585] libphy: PHY 4a101000.mdio:01 not found
[   10.537641] net eth0: phy 4a101000.mdio:01 not found on slave 1
[   10.549718] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
udhcpc (v1.23.2) started
Sending discover...
Sending discover...
Sending discover...
No lease, forking to background
[   19.783594] c_can_platform 481d0000.can can1: setting BTR=1c05 BRPE=0000
done.
Starting syslogd/klogd: done
Starting php-fpm  done
Starting Hiawatha Web Server: hiawatha.
Starting crond: OK

Victron Energy v1.80~17 beaglebone /dev/ttyO0

beaglebone login: root
Last login: Mon Oct 24 00:00:45 +0000 2016 on /dev/ttyO0.
root@beaglebone:~# date
Mon Oct 24 00:00:33 UTC 2016
root@beaglebone:~# hwclock
Mon Oct 24 00:00:35 2016  0.000000 seconds
mpvader commented 7 years ago

And found the cause (thanks @jhofstee), see: https://github.com/victronenergy/openembedded-core/blob/danny_venus/meta/recipes-core/initscripts/initscripts-1.0/bootmisc.sh#L65

mpvader commented 7 years ago

fix is underway: test will be done by setting clock forward instead of backward.

Also, after setting the current date/time as the last step, I'll add a call to initscripts/save-rtc.sh.