LinHES Forums :: View topic - Weird Clock Changes

Oct 2 11:01:19 mythtv -- MARK --
Oct 2 11:02:55 mythtv shutdown[4849]: shutting down for system halt
Oct 2 11:03:03 mythtv kernel: Kernel logging (proc) stopped.
Oct 2 11:03:03 mythtv kernel: Kernel log daemon terminating.
Oct 2 11:03:04 mythtv exiting on signal 15
Jan 1 11:10:00 mythtv syslogd 1.4.1#20: restart.
Jan 1 11:10:00 mythtv kernel: klogd 1.4.1#20, log source = /proc/kmsg started.
Jan 1 11:10:00 mythtv kernel: Linux version 2.6.18-chw-13 (root@mythtv) (gcc version 4.1.2 20061115 (prerelease) (Debian 4.1.1-21)) #1 SM
P PREEMPT Sat Jun 2 21:06:06 PDT 2007
Jan 1 11:10:00 mythtv kernel: BIOS-provided physical RAM map:

Jan 1 11:10:16 mythtv kernel: ACPI: PCI Interrupt 0000:00:05.0[A] -> Link [APC7] -> GSI 16 (level, low) -> IRQ 21
Jan 1 11:10:16 mythtv kernel: NVRM: loading NVIDIA UNIX x86 Kernel Module 1.0-9755 Mon Feb 26 23:21:15 PST 2007
Jan 1 11:10:22 mythtv gconfd (mythtv-8780): starting (version 2.16.1), pid 8780 user 'mythtv'
Jan 1 11:10:22 mythtv gconfd (mythtv-8780): Resolved address "xml:readonly:/etc/gconf/gconf.xml.mandatory" to a read-only configuration s
ource at position 0
Jan 1 11:10:22 mythtv gconfd (mythtv-8780): Resolved address "xml:readwrite:/home/mythtv/.gconf" to a writable configuration source at po
sition 1
Jan 1 11:10:22 mythtv gconfd (mythtv-8780): Resolved address "xml:readonly:/etc/gconf/gconf.xml.defaults" to a read-only configuration so
urce at position 2
Jan 1 11:10:22 mythtv gconfd (mythtv-8780): Resolved address "xml:readonly:/var/lib/gconf/debian.defaults" to a read-only configuration s
ource at position 3
Jan 1 11:10:22 mythtv gconfd (mythtv-8780): Resolved address "xml:readonly:/var/lib/gconf/defaults" to a read-only configuration source a
t position 4
Oct 3 18:47:19 mythtv gconfd (mythtv-8780): GConf server is not in use, shutting down.
Oct 3 18:47:19 mythtv gconfd (mythtv-8780): Exiting
Oct 3 19:06:27 mythtv -- MARK --

Jan 1 11:10:02 mythtv kernel: lirc_dev: lirc_register_plugin: sample_rate: 0
Jan 1 11:10:08 mythtv kernel: eth0: no IPv6 routers present
Jan 1 11:10:15 mythtv kernel: nvidia: module license 'NVIDIA' taints kernel.
Jan 1 11:10:16 mythtv kernel: ACPI: PCI Interrupt Link [APC7] enabled at IRQ 16
Jan 1 11:10:16 mythtv kernel: ACPI: PCI Interrupt 0000:00:05.0[A] -> Link [APC7] -> GSI 16 (level, low) -> IRQ 21
Jan 1 11:10:16 mythtv kernel: PCI: Setting latency timer of device 0000:00:05.0 to 64
Jan 1 11:10:16 mythtv kernel: NVRM: loading NVIDIA UNIX x86 Kernel Module 1.0-9755 Mon Feb 26 23:21:15 PST 2007
Oct 3 18:50:54 mythtv kernel: vp7045: USB control message 'in' went wrong.
Oct 3 19:00:40 mythtv kernel: vp7045: USB control message 'in' went wrong.
Oct 3 19:00:43 mythtv kernel: vp7045: USB control message 'in' went wrong.
Oct 3 20:09:56 mythtv kernel: vp7045: USB control message 'in' went wrong.

Oct 2 10:41:29 mythtv /etc/mysql/debian-start[3589]: Checking for crashed MySQL tables.
Oct 2 10:41:33 mythtv ntpd[3605]: ntpd 4.2.2p4@1.1585-o Sun Mar 4 13:21:35 UTC 2007 (1)
Oct 2 10:41:33 mythtv ntpd[3606]: precision = 2.000 usec
Oct 2 10:41:33 mythtv ntpd[3606]: Listening on interface wildcard, 0.0.0.0#123 Disabled
Oct 2 10:41:33 mythtv ntpd[3606]: Listening on interface wildcard, ::#123 Disabled
Oct 2 10:41:33 mythtv ntpd[3606]: Listening on interface lo, ::1#123 Enabled
Oct 2 10:41:33 mythtv ntpd[3606]: Listening on interface eth0, fe80::217:31ff:fe80:8b4d#123 Enabled
Oct 2 10:41:33 mythtv ntpd[3606]: Listening on interface lo, 127.0.0.1#123 Enabled
Oct 2 10:41:33 mythtv ntpd[3606]: Listening on interface eth0, 10.0.0.20#123 Enabled
Oct 2 10:41:33 mythtv ntpd[3606]: kernel time sync status 0040
Oct 2 10:41:33 mythtv ntpd[3606]: frequency initialized -18.830 PPM from /var/lib/ntp/ntp.drift
Oct 2 10:41:44 mythtv lircd-0.8.2-CVS-pvr150[3346]: accepted new client on /dev/lircd
Oct 2 10:41:44 mythtv ntpd[3606]: synchronized to 59.167.252.133, stratum 2
Oct 2 10:41:44 mythtv ntpd[3606]: time reset -0.840738 s
Oct 2 10:41:44 mythtv ntpd[3606]: kernel time sync enabled 0001
Oct 2 10:45:50 mythtv ntpd[3606]: synchronized to 130.102.128.23, stratum 2
Oct 2 10:55:40 mythtv lircd-0.8.2-CVS-pvr150[3346]: accepted new client on /dev/lircd
Oct 2 10:59:51 mythtv lircd-0.8.2-CVS-pvr150[3346]: removed client
Oct 2 11:02:55 mythtv init: Switching to runlevel: 0
Oct 2 11:02:56 mythtv lircd-0.8.2-CVS-pvr150[3346]: caught signal
Oct 2 11:02:56 mythtv mysqld[3415]: 071002 11:02:56 [Note] /usr/sbin/mysqld: Normal shutdown
Oct 2 11:02:56 mythtv mysqld[3415]:
Oct 2 11:02:56 mythtv mysqld[3415]: 071002 11:02:56 InnoDB: Starting shutdown...
Oct 2 11:02:58 mythtv mysqld[3415]: 071002 11:02:58 InnoDB: Shutdown completed; log sequence number 0 43665
Oct 2 11:02:58 mythtv mysqld[3415]: 071002 11:02:58 [Note] /usr/sbin/mysqld: Shutdown complete
Oct 2 11:02:58 mythtv mysqld[3415]:
Oct 2 11:02:58 mythtv mysqld_safe[4927]: ended
Oct 2 11:03:03 mythtv ntpd[3606]: ntpd exiting on signal 15
Jan 1 11:10:02 mythtv lircd-0.8.2-CVS-pvr150[8314]: lircd(all) ready
Jan 1 11:10:03 mythtv mysqld_safe[8380]: started
Jan 1 11:10:03 mythtv mysqld[8383]: 060101 11:10:03 InnoDB: Started; log sequence number 0 43665
Jan 1 11:10:03 mythtv mysqld[8383]: 060101 11:10:03 [Note] /usr/sbin/mysqld: ready for connections.
Jan 1 11:10:03 mythtv mysqld[8383]: Version: '5.0.32-Debian_7etch1' socket: '/var/run/mysqld/mysqld.sock' port: 3306 Debian etch distr
ibution
Jan 1 11:10:04 mythtv /etc/mysql/debian-start[8420]: Upgrading MySQL tables if necessary.
Jan 1 11:10:09 mythtv /etc/mysql/debian-start[8558]: Checking for crashed MySQL tables.
Jan 1 11:10:13 mythtv ntpd[8574]: ntpd 4.2.2p4@1.1585-o Sun Mar 4 13:21:35 UTC 2007 (1)
Jan 1 11:10:13 mythtv ntpd[8575]: precision = 2.000 usec
Jan 1 11:10:13 mythtv ntpd[8575]: Listening on interface wildcard, 0.0.0.0#123 Disabled
Jan 1 11:10:13 mythtv ntpd[8575]: Listening on interface wildcard, ::#123 Disabled
Jan 1 11:10:13 mythtv ntpd[8575]: Listening on interface lo, ::1#123 Enabled
Jan 1 11:10:13 mythtv ntpd[8575]: Listening on interface eth0, fe80::217:31ff:fe80:8b4d#123 Enabled
Jan 1 11:10:13 mythtv ntpd[8575]: Listening on interface lo, 127.0.0.1#123 Enabled
Jan 1 11:10:13 mythtv ntpd[8575]: Listening on interface eth0, 10.0.0.20#123 Enabled
Jan 1 11:10:13 mythtv ntpd[8575]: kernel time sync status 0040
Jan 1 11:10:13 mythtv ntpd[8575]: frequency initialized -18.505 PPM from /var/lib/ntp/ntp.drift
Jan 1 11:10:21 mythtv lircd-0.8.2-CVS-pvr150[8314]: accepted new client on /dev/lircd
Oct 3 18:46:51 mythtv ntpd[8575]: synchronized to 60.240.81.28, stratum 2
Oct 3 18:46:51 mythtv ntpd[8575]: time reset +55326987.392169 s
Oct 3 18:46:51 mythtv ntpd[8575]: kernel time sync enabled 0001
Oct 3 18:50:01 mythtv lircd-0.8.2-CVS-pvr150[8314]: accepted new client on /dev/lircd
Oct 3 18:51:24 mythtv ntpd[8575]: synchronized to 60.240.81.28, stratum 2
Oct 3 18:55:14 mythtv ntpd[8575]: synchronized to 121.0.1.1, stratum 2
Oct 3 19:59:55 mythtv ntpd[8575]: synchronized to 60.240.81.28, stratum 2
Oct 3 20:25:35 mythtv ntpd[8575]: synchronized to 121.0.1.1, stratum 2

#!/bin/bash
stamp_file=/home/mythtv/timestamp

#just log what we get as command line parameters
echo $1 $2 $3> $stamp_file

#i setted mythtv to output the number of seconds since epoch
#so i calculate the number of hours, minutes and seconds from
#now the computer has to wakeup:
sfn=$(($2 - `date +"%s"`))

#and then send it to /proc/acpi/wakeup in the format we saw above
y=`(echo $(($sfn - 3600))|awk '{print strftime("+00-00-00 %H:%M:%S", $1)}')`

echo "$y">/proc/acpi/alarm
echo "$y">>$stamp_file
echo "executed at `date`" >> $stamp_file
exit

ntpdate -u 0.debian.pool.ntp.org

Author:	turpie [ Wed Oct 03, 2007 4:39 am ]
Post subject:	Weird Clock Changes
My system has had a couple of weird clock changes lately. Since upgrading to R5F27 the clock in my KM machine has occasionally gone back in time, then returned to normal again later. A couple of times when I've turned the machine on it has had to do a fsck scan because it think that hundreds of days have passed since the check. I'm not really sure where to start so does anyone have any idea of what is happening? Here are some snippets of /var/log/messages Code: Oct 2 11:01:19 mythtv -- MARK -- Oct 2 11:02:55 mythtv shutdown[4849]: shutting down for system halt Oct 2 11:03:03 mythtv kernel: Kernel logging (proc) stopped. Oct 2 11:03:03 mythtv kernel: Kernel log daemon terminating. Oct 2 11:03:04 mythtv exiting on signal 15 Jan 1 11:10:00 mythtv syslogd 1.4.1#20: restart. Jan 1 11:10:00 mythtv kernel: klogd 1.4.1#20, log source = /proc/kmsg started. Jan 1 11:10:00 mythtv kernel: Linux version 2.6.18-chw-13 (root@mythtv) (gcc version 4.1.2 20061115 (prerelease) (Debian 4.1.1-21)) #1 SM P PREEMPT Sat Jun 2 21:06:06 PDT 2007 Jan 1 11:10:00 mythtv kernel: BIOS-provided physical RAM map: Code: Jan 1 11:10:16 mythtv kernel: ACPI: PCI Interrupt 0000:00:05.0[A] -> Link [APC7] -> GSI 16 (level, low) -> IRQ 21 Jan 1 11:10:16 mythtv kernel: NVRM: loading NVIDIA UNIX x86 Kernel Module 1.0-9755 Mon Feb 26 23:21:15 PST 2007 Jan 1 11:10:22 mythtv gconfd (mythtv-8780): starting (version 2.16.1), pid 8780 user 'mythtv' Jan 1 11:10:22 mythtv gconfd (mythtv-8780): Resolved address "xml:readonly:/etc/gconf/gconf.xml.mandatory" to a read-only configuration s ource at position 0 Jan 1 11:10:22 mythtv gconfd (mythtv-8780): Resolved address "xml:readwrite:/home/mythtv/.gconf" to a writable configuration source at po sition 1 Jan 1 11:10:22 mythtv gconfd (mythtv-8780): Resolved address "xml:readonly:/etc/gconf/gconf.xml.defaults" to a read-only configuration so urce at position 2 Jan 1 11:10:22 mythtv gconfd (mythtv-8780): Resolved address "xml:readonly:/var/lib/gconf/debian.defaults" to a read-only configuration s ource at position 3 Jan 1 11:10:22 mythtv gconfd (mythtv-8780): Resolved address "xml:readonly:/var/lib/gconf/defaults" to a read-only configuration source a t position 4 Oct 3 18:47:19 mythtv gconfd (mythtv-8780): GConf server is not in use, shutting down. Oct 3 18:47:19 mythtv gconfd (mythtv-8780): Exiting Oct 3 19:06:27 mythtv -- MARK -- /var/log/kern.log Code: Jan 1 11:10:02 mythtv kernel: lirc_dev: lirc_register_plugin: sample_rate: 0 Jan 1 11:10:08 mythtv kernel: eth0: no IPv6 routers present Jan 1 11:10:15 mythtv kernel: nvidia: module license 'NVIDIA' taints kernel. Jan 1 11:10:16 mythtv kernel: ACPI: PCI Interrupt Link [APC7] enabled at IRQ 16 Jan 1 11:10:16 mythtv kernel: ACPI: PCI Interrupt 0000:00:05.0[A] -> Link [APC7] -> GSI 16 (level, low) -> IRQ 21 Jan 1 11:10:16 mythtv kernel: PCI: Setting latency timer of device 0000:00:05.0 to 64 Jan 1 11:10:16 mythtv kernel: NVRM: loading NVIDIA UNIX x86 Kernel Module 1.0-9755 Mon Feb 26 23:21:15 PST 2007 Oct 3 18:50:54 mythtv kernel: vp7045: USB control message 'in' went wrong. Oct 3 19:00:40 mythtv kernel: vp7045: USB control message 'in' went wrong. Oct 3 19:00:43 mythtv kernel: vp7045: USB control message 'in' went wrong. Oct 3 20:09:56 mythtv kernel: vp7045: USB control message 'in' went wrong. For some reason it seems to have booted up thinking it is Jan 1 2006 then somehow corrected itself to the right time. Might using ACPI wakeups be affecting it.

Author:	turpie [ Wed Oct 03, 2007 4:49 am ]
Post subject:
This log seems to suggest that ntpd was responsible for fixing the time, but why is it going out of whack in the first place? /var/log/daemon.log Code: Oct 2 10:41:29 mythtv /etc/mysql/debian-start[3589]: Checking for crashed MySQL tables. Oct 2 10:41:33 mythtv ntpd[3605]: ntpd 4.2.2p4@1.1585-o Sun Mar 4 13:21:35 UTC 2007 (1) Oct 2 10:41:33 mythtv ntpd[3606]: precision = 2.000 usec Oct 2 10:41:33 mythtv ntpd[3606]: Listening on interface wildcard, 0.0.0.0#123 Disabled Oct 2 10:41:33 mythtv ntpd[3606]: Listening on interface wildcard, ::#123 Disabled Oct 2 10:41:33 mythtv ntpd[3606]: Listening on interface lo, ::1#123 Enabled Oct 2 10:41:33 mythtv ntpd[3606]: Listening on interface eth0, fe80::217:31ff:fe80:8b4d#123 Enabled Oct 2 10:41:33 mythtv ntpd[3606]: Listening on interface lo, 127.0.0.1#123 Enabled Oct 2 10:41:33 mythtv ntpd[3606]: Listening on interface eth0, 10.0.0.20#123 Enabled Oct 2 10:41:33 mythtv ntpd[3606]: kernel time sync status 0040 Oct 2 10:41:33 mythtv ntpd[3606]: frequency initialized -18.830 PPM from /var/lib/ntp/ntp.drift Oct 2 10:41:44 mythtv lircd-0.8.2-CVS-pvr150[3346]: accepted new client on /dev/lircd Oct 2 10:41:44 mythtv ntpd[3606]: synchronized to 59.167.252.133, stratum 2 Oct 2 10:41:44 mythtv ntpd[3606]: time reset -0.840738 s Oct 2 10:41:44 mythtv ntpd[3606]: kernel time sync enabled 0001 Oct 2 10:45:50 mythtv ntpd[3606]: synchronized to 130.102.128.23, stratum 2 Oct 2 10:55:40 mythtv lircd-0.8.2-CVS-pvr150[3346]: accepted new client on /dev/lircd Oct 2 10:59:51 mythtv lircd-0.8.2-CVS-pvr150[3346]: removed client Oct 2 11:02:55 mythtv init: Switching to runlevel: 0 Oct 2 11:02:56 mythtv lircd-0.8.2-CVS-pvr150[3346]: caught signal Oct 2 11:02:56 mythtv mysqld[3415]: 071002 11:02:56 [Note] /usr/sbin/mysqld: Normal shutdown Oct 2 11:02:56 mythtv mysqld[3415]: Oct 2 11:02:56 mythtv mysqld[3415]: 071002 11:02:56 InnoDB: Starting shutdown... Oct 2 11:02:58 mythtv mysqld[3415]: 071002 11:02:58 InnoDB: Shutdown completed; log sequence number 0 43665 Oct 2 11:02:58 mythtv mysqld[3415]: 071002 11:02:58 [Note] /usr/sbin/mysqld: Shutdown complete Oct 2 11:02:58 mythtv mysqld[3415]: Oct 2 11:02:58 mythtv mysqld_safe[4927]: ended Oct 2 11:03:03 mythtv ntpd[3606]: ntpd exiting on signal 15 Jan 1 11:10:02 mythtv lircd-0.8.2-CVS-pvr150[8314]: lircd(all) ready Jan 1 11:10:03 mythtv mysqld_safe[8380]: started Jan 1 11:10:03 mythtv mysqld[8383]: 060101 11:10:03 InnoDB: Started; log sequence number 0 43665 Jan 1 11:10:03 mythtv mysqld[8383]: 060101 11:10:03 [Note] /usr/sbin/mysqld: ready for connections. Jan 1 11:10:03 mythtv mysqld[8383]: Version: '5.0.32-Debian_7etch1' socket: '/var/run/mysqld/mysqld.sock' port: 3306 Debian etch distr ibution Jan 1 11:10:04 mythtv /etc/mysql/debian-start[8420]: Upgrading MySQL tables if necessary. Jan 1 11:10:09 mythtv /etc/mysql/debian-start[8558]: Checking for crashed MySQL tables. Jan 1 11:10:13 mythtv ntpd[8574]: ntpd 4.2.2p4@1.1585-o Sun Mar 4 13:21:35 UTC 2007 (1) Jan 1 11:10:13 mythtv ntpd[8575]: precision = 2.000 usec Jan 1 11:10:13 mythtv ntpd[8575]: Listening on interface wildcard, 0.0.0.0#123 Disabled Jan 1 11:10:13 mythtv ntpd[8575]: Listening on interface wildcard, ::#123 Disabled Jan 1 11:10:13 mythtv ntpd[8575]: Listening on interface lo, ::1#123 Enabled Jan 1 11:10:13 mythtv ntpd[8575]: Listening on interface eth0, fe80::217:31ff:fe80:8b4d#123 Enabled Jan 1 11:10:13 mythtv ntpd[8575]: Listening on interface lo, 127.0.0.1#123 Enabled Jan 1 11:10:13 mythtv ntpd[8575]: Listening on interface eth0, 10.0.0.20#123 Enabled Jan 1 11:10:13 mythtv ntpd[8575]: kernel time sync status 0040 Jan 1 11:10:13 mythtv ntpd[8575]: frequency initialized -18.505 PPM from /var/lib/ntp/ntp.drift Jan 1 11:10:21 mythtv lircd-0.8.2-CVS-pvr150[8314]: accepted new client on /dev/lircd Oct 3 18:46:51 mythtv ntpd[8575]: synchronized to 60.240.81.28, stratum 2 Oct 3 18:46:51 mythtv ntpd[8575]: time reset +55326987.392169 s Oct 3 18:46:51 mythtv ntpd[8575]: kernel time sync enabled 0001 Oct 3 18:50:01 mythtv lircd-0.8.2-CVS-pvr150[8314]: accepted new client on /dev/lircd Oct 3 18:51:24 mythtv ntpd[8575]: synchronized to 60.240.81.28, stratum 2 Oct 3 18:55:14 mythtv ntpd[8575]: synchronized to 121.0.1.1, stratum 2 Oct 3 19:59:55 mythtv ntpd[8575]: synchronized to 60.240.81.28, stratum 2 Oct 3 20:25:35 mythtv ntpd[8575]: synchronized to 121.0.1.1, stratum 2

Author:	turpie [ Wed Oct 03, 2007 5:14 pm ]
Post subject:
Would my modification to /etc/init.d/hwclock.sh be to blame? Quote: stop\|restart\|reload\|force-reload) # # Updates the Hardware Clock with the System Clock time. # This will override any changes made to the Hardware Clock. # # WARNING: If you disable this, any changes to the system # clock will not be carried across reboots. # ACPITIME=`cat /proc/acpi/alarm` if [ "$HWCLOCKACCESS" != no ]; then log_action_msg "Saving the system clock." if [ "$GMT" = "-u" ]; then GMT="--utc" fi /sbin/hwclock --systohc $GMT $HWCLOCKPARS $BADYEAR verbose_log_action_msg "Hardware Clock updated to `date`" echo "$ACPITIME" > /proc/acpi/alarm else verbose_log_action_msg "Not saving System Clock" fi ;; The red lines are the ones I added for ACPI wakeups.

Author:	Verbetex [ Wed Oct 17, 2007 2:05 pm ]
Post subject:
I'm getting the exact same thing! I've set up mythwelcome and using ACPI to do the wakeup. However, I've not made the fussy bios change you have (modification of hwclock.sh) so I would rule that out for the problem. This is resulting in my machine waking up, but not actually recording anything. I'm using the following script to set the time: Code: #!/bin/bash stamp_file=/home/mythtv/timestamp #just log what we get as command line parameters echo $1 $2 $3> $stamp_file #i setted mythtv to output the number of seconds since epoch #so i calculate the number of hours, minutes and seconds from #now the computer has to wakeup: sfn=$(($2 - `date +"%s"`)) #and then send it to /proc/acpi/wakeup in the format we saw above y=`(echo $(($sfn - 3600))\|awk '{print strftime("+00-00-00 %H:%M:%S", $1)}')` echo "$y">/proc/acpi/alarm echo "$y">>$stamp_file echo "executed at `date`" >> $stamp_file exit Anyone have any ideas??

Author:	Verbetex [ Wed Oct 17, 2007 3:40 pm ]
Post subject:
Not a proper fix, but I'm hoping that it may partially help... I've basically installed ntpdate and added Code: ntpdate -u 0.debian.pool.ntp.org to /etc/init.d/bootmisc.sh Hopefully it'll update the time when the machine starts so it doesn't have to wait for the ntp deamon to kick in. However, this won't get round the disk checking on startup, but might help with starting a recording.

LinHES Forums http://forum.linhes.org/

Weird Clock Changes http://forum.linhes.org/viewtopic.php?f=6&t=16834	Page 1 of 1

Page 1 of 1	All times are UTC - 6 hours
Powered by phpBB® Forum Software © phpBB Group http://www.phpbb.com/