Linknx did not survive time change...

[Damago]

This night is the night when the time changes to summer time in Poland. Unfortunately it seams that Linknx did not survive it. Shortly after 1:00 am it started throwing zillions of identical warnings into the log file filing it up to 80megs very quickly.

After restarting it did the initial object and rules initialisation and immediately after entering KNX communication it loops throwing this warings again:

... normal stuff here, object initialisation etc...
20110327 01:19:40,672  INFO Rule : Rule: Configuring zmierzch (active=1)
20110327 01:19:40,672  INFO TimeSpec : 1899-0--1 -1:-1:0 (wdays=0; exception=2)
20110327 01:19:40,672  INFO SolarTimeSpec : sun_rise_set date 2011-3-27
20110327 01:19:40,672  INFO SolarTimeSpec : sun_rise_set returned 17:54
20110327 01:19:40,673  INFO SolarTimeSpec : adjustTime date 2011-3-27
20110327 01:19:40,673  INFO SolarTimeSpec : adjustTime returned 18:54
20110327 01:19:40,673  INFO PeriodicTask : Rescheduled at 2011-3-27 18:54:0 (1301244840)
20110327 01:19:40,673  INFO Rule : ActionList: Configuring 'on-true' action list
20110327 01:19:40,673  INFO Action : SetValueAction: Configured for object elewacja_ganek_sluzbowy with value on
20110327 01:19:40,673  INFO Action : SetValueAction: Configured for object ogrod_front_furtka with value on
20110327 01:19:40,673  INFO Rule : Rule: Configuration done
20110327 01:19:40,673  INFO Rule : Rule: Configuring pozna_noc (active=1)
20110327 01:19:40,674  INFO TimeSpec : 1899-0--1 2:0:0 (wdays=0; exception=2)
20110327 01:19:40,674  INFO PeriodicTask : Rescheduled at 2011-3-27 1:0:0 (1301184000)
20110327 01:19:40,674  INFO Rule : ActionList: Configuring 'on-true' action list
20110327 01:19:40,674  INFO Action : SetValueAction: Configured for object elewacja_ganek_sluzbowy with value off
20110327 01:19:40,674  INFO Rule : Rule: Configuration done
20110327 01:19:40,674  INFO main : Config file loaded: /var/lib/linknx/linknx.xml
20110327 01:19:40,689  WARN TimerManager : TimerTask skipped due to clock skew or heavy load. 1301184000
20110327 01:19:40,689  INFO PeriodicTask : Rescheduled at 2011-3-27 1:0:0 (1301184000)
20110327 01:19:40,689  WARN TimerManager : TimerTask skipped due to clock skew or heavy load. 1301184000
20110327 01:19:40,689  INFO PeriodicTask : Rescheduled at 2011-3-27 1:0:0 (1301184000)
20110327 01:19:40,689  WARN TimerManager : TimerTask skipped due to clock skew or heavy load. 1301184000
20110327 01:19:40,689  INFO PeriodicTask : Rescheduled at 2011-3-27 1:0:0 (1301184000)
20110327 01:19:40,690  WARN TimerManager : TimerTask skipped due to clock skew or heavy load. 1301184000
20110327 01:19:40,690  INFO PeriodicTask : Rescheduled at 2011-3-27 1:0:0 (1301184000)
20110327 01:19:40,690  WARN TimerManager : TimerTask skipped due to clock skew or heavy load. 1301184000
20110327 01:19:40,690  INFO PeriodicTask : Rescheduled at 2011-3-27 1:0:0 (1301184000)
20110327 01:19:40,690  WARN TimerManager : TimerTask skipped due to clock skew or heavy load. 1301184000
20110327 01:19:40,691  INFO PeriodicTask : Rescheduled at 2011-3-27 1:0:0 (1301184000)
20110327 01:19:40,691  WARN TimerManager : TimerTask skipped due to clock skew or heavy load. 1301184000
20110327 01:19:40,691  INFO PeriodicTask : Rescheduled at 2011-3-27 1:0:0 (1301184000)
20110327 01:19:40,691  WARN TimerManager : TimerTask skipped due to clock skew or heavy load. 1301184000
....and the abofe warnings repeated infinitely

After another restart of Linknx it throws only an instance of 'int' error:

20110327 01:24:32,402  INFO XmlInetServer : Starting on port 1028
terminate called after throwing an instance of 'int'

and exits.

[Damago]

It seams that such rule could be the reason:

  <rule id="pozna_noc">
   <condition type="timer" trigger="true">
     <at hour="2" min="0"/>
   </condition>
   <actionlist>
     <action type="set-value" id="elewacja_ganek_sluzbowy" value="off"/>
   </actionlist>
  </rule>

I have digged into the log to the place where the strange behaviour began. It was something like this:

20110327 00:43:13,487  INFO Object : New value off for object sluzbowka_centr1 (type: 1.001)
20110327 00:43:13,717  INFO Object : New value off for object sluzbowka_centr1_S (type: 1.001)
20110327 01:00:00,299  INFO TimerManager : TimerTask execution. 1301184000
20110327 01:00:00,300  INFO Rule : Evaluate rule pozna_noc
20110327 01:00:00,300  INFO Condition : TimerCondition evaluated as '1'
20110327 01:00:00,301  INFO Rule : Rule pozna_noc evaluated as 1, prev value was 0
20110327 01:00:00,301  INFO Rule : Evaluate rule pozna_noc
20110327 01:00:00,301  INFO Condition : TimerCondition evaluated as '0'
20110327 01:00:00,301  INFO Rule : Rule pozna_noc evaluated as 0, prev value was 1
20110327 01:00:00,303  INFO PeriodicTask : Rescheduled at 2011-3-27 1:0:0 (1301184000)
20110327 01:00:00,303  INFO TimerManager : TimerTask execution. 1301184000
20110327 01:00:00,304  INFO Rule : Evaluate rule pozna_noc
20110327 01:00:00,304  INFO Condition : TimerCondition evaluated as '1'
20110327 01:00:00,304  INFO Rule : Rule pozna_noc evaluated as 1, prev value was 0
20110327 01:00:00,305  INFO Rule : Evaluate rule pozna_noc
20110327 01:00:00,305  INFO Condition : TimerCondition evaluated as '0'
20110327 01:00:00,305  INFO Rule : Rule pozna_noc evaluated as 0, prev value was 1
20110327 01:00:00,305  INFO PeriodicTask : Rescheduled at 2011-3-27 1:0:0 (1301184000)
20110327 01:00:00,306  INFO TimerManager : TimerTask execution. 1301184000
20110327 01:00:00,306  INFO Rule : Evaluate rule pozna_noc
20110327 01:00:00,306  INFO Condition : TimerCondition evaluated as '1'
20110327 01:00:00,307  INFO Rule : Rule pozna_noc evaluated as 1, prev value was 0
....
and then infinite loop of repetitions between 0 and 1 for rule pozna_noc until the place i did restart Linknx

After I did restart Linknx the above INFO and WARN loop showed up (as in my first message),

After I did restart it once again an exception 'throwing an instance of 'int' did show up.

After I have re-set this rule to be activated at 0:59 instead of 2:00 I could succesfully reboot the machine and Linknx started to work properly.

At 2:00 the time changed to 3:00 without any noticable problems, no trace of it in the logs.

It seams that any event falling into the non-existing hour during time change (that is between 2:00 and 3:00 on the day of time change) was causing problems of either infinite rule re-evaluation or warnings/infos of re-schedules.

Yours

Damago1