Fehler in linknx-Log : [ WARN] TimerManager: TimerTask skipped ...

[netfriend]

Hallo,

ich nutze seit knapp einem Jahr linknx (Version 0.0.1.30) und habe ein paar rules definiert. Grob gesagt sind es actions die ich zum Tages-/Wochen- und Monatswechsel ausführen lassen möchte. Das hat bisher auch zuverlässig funktioniert. Gestern habe ich festgestellt, dass es hiermit Probleme gibt. Nach einigem suchen und probieren bin ich darauf gestoßen, dass es wohl an diesen rules liegen muss. Genauer gesagt an der "Monatswechsel"-rule:

<rule id="Tageswechsel">
    <condition type="timer" trigger="true">
        <at hour="0" min="0" exception="no"/>
    </condition>
    <actionlist type="if-true">
        ...
    </actionlist>  
</rule>

<rule id="Wochenwechsel">
    <condition type="timer" trigger="true">
        <at hour="0" min="0" wdays="1" exception="no" />
    </condition>
    <actionlist type="if-true">
        ...
    </actionlist>
</rule>

<rule id="Monatswechsel">
    <condition type="timer" trigger="true">
        <at hour="0" min="0" day="1" exception="no"/>
    </condition>
    <actionlist type="if-true">
        ...
    </actionlist>
</rule>

Wenn ich bei der Monatswechsel-rule das day="1" entferne, läuft alles (zwar nicht wie gewünscht, dafür aber ohne Fehlermeldungen). Füge ich es wieder ein, so steht in der linknx-log folgendes:

2018-10-07 10:46:27 [ INFO] Rule: Rule: Configuring Tageswechsel (active=1)
2018-10-07 10:46:27 [ INFO] TimeSpec: 1899-0--1 0:0:0 (wdays=0; exception=0)
2018-10-07 10:46:27 [ INFO] PeriodicTask: Rescheduled at 2018-10-8 0:0:0 (1538949600)
2018-10-07 10:46:27 [ INFO] Rule: ActionList: Configuring 'if-true' action list
-> Aktions entfernt
2018-10-07 10:46:27 [ INFO] Rule: Rule: Configuration done

2018-10-07 10:46:27 [ INFO] Rule: Rule: Configuring Wochenwechsel (active=1)
2018-10-07 10:46:27 [ INFO] TimeSpec: 1899-0--1 0:0:0 (wdays=1; exception=0)
2018-10-07 10:46:27 [ INFO] PeriodicTask: Rescheduled at 2018-10-8 0:0:0 (1538949600)
2018-10-07 10:46:27 [ INFO] Rule: ActionList: Configuring 'if-true' action list
-> Aktions entfernt
2018-10-07 10:46:27 [ INFO] Rule: Rule: Configuration done

2018-10-07 10:46:27 [ INFO] Rule: Rule: Configuring Monatswechsel (active=1)
2018-10-07 10:46:27 [ INFO] TimeSpec: 1899-0-1 0:0:0 (wdays=0; exception=0)
2018-10-07 10:46:27 [ INFO] PeriodicTask: Rescheduled at 2018-10-2 0:0:0 (1538431200)
2018-10-07 10:46:27 [ INFO] Rule: ActionList: Configuring 'if-true' action list
2018-1-> Aktions entfernt
2018-10-07 10:46:27 [ INFO] Rule: Rule: Configuration done
2018-10-07 10:46:27 [ INFO] main: Config file loaded: /var/lib/linknx/linknx.xml

2018-10-07 10:46:27 [ WARN] TimerManager: TimerTask skipped due to clock skew or heavy load. 1538431200
2018-10-07 10:46:27 [ INFO] PeriodicTask: Rescheduled at 2018-10-2 0:0:0 (1538431200)
-> Diese Warnungen kommen im ms-Rhythmus

Es sieht wohl so aus, als ob der nächste "Monatswechsel" nicht am 01.11.18 ist, sondern in der Vergangenheit liegt.

Hat jemand ne Idee, wie das sein kann? Die letzten 10 Monate hat das funktioniert.
Danke für Eure Hilfe, bin im Moment etwas ratlos.

[netfriend]

Keiner ne Idee?

[Tru]

Keiner ne Idee?

Vielleicht bekommst du mehr Echo in dieser Google Group: https://groups.google.com/forum/#!fo...-linknx-knxweb

[netfriend]

Danke Tru, ich dachte, hier gibts auch Experten, die linknx einsetzen. Vor allem in Verbindung mit der CometVisu auf dem Raspi.
Deshalb habe ich es hier versucht.

Zwischenzeitlich habe ich etwas weiter getestet. Das Verhalten (Fehlermeldung im ms-Rhythmus und damit wird das komplette System lahmgelegt) konnte ich abstellen: ich habe von der linknx 0.0.1.30 auf die aktuelle 0.0.1.36 upgedated.
Damit wird zwar das System nicht mehr lahmgelegt, aber das nicht nachvollziehbare Verhalten wie der nächste Task festgelegt wird, bleibt.

Testweise habe ich folgende linknx.xml erstellt.

<?xml version="1.0" ?>
<config>
    <services>
        <knxconnection url="ip:127.0.0.1" />
         <persistence type="file" path="/var/lib/linknx" logpath="/var/lib/linknx/log" />
    </services>
    <objects>
        <object type="5.xxx" id="linknx_Test" gad="0/0/2" flags="cwtu" init="persist" log="true">linknx_Test</object>
    </objects>
    <rules>    
        <rule id="Tageswechsel">
            <condition type="timer" trigger="true">
                <at hour="0" min="0"/>
            </condition>    
            <actionlist type="if-true">   
                <action type="set-value" id="linknx_Test" value="0"/>
            </actionlist>
        </rule>     

        <rule id="Wochenwechsel">
            <condition type="timer" trigger="true">
                <at hour="0" min="0" wdays="1"/>
            </condition>    
            <actionlist type="if-true">   
                <action type="set-value" id="linknx_Test" value="1"/>
            </actionlist>
        </rule>     
         
        <rule id="Monatswechsel_1">
            <condition type="timer" trigger="true">
                <at hour="0" min="0" day="1"/>
            </condition>    
            <actionlist type="if-true">   
                <action type="set-value" id="linknx_Test" value="2"/>
            </actionlist>
        </rule>    
        <rule id="Monatswechsel_2">
            <condition type="timer" trigger="true">
                <at hour="0" min="0" day="2"/>
            </condition>    
            <actionlist type="if-true">   
                <action type="set-value" id="linknx_Test" value="3"/>
            </actionlist>
        </rule>    
        <rule id="Monatswechsel_3">
            <condition type="timer" trigger="true">
                <at hour="0" min="0" day="20"/>
            </condition>    
            <actionlist type="if-true">   
                <action type="set-value" id="linknx_Test" value="4"/>
            </actionlist>
        </rule>    
        <rule id="Monatswechsel_4">
            <condition type="timer" trigger="true">
                <at hour="0" min="0" day="31"/>
            </condition>    
            <actionlist type="if-true">   
                <action type="set-value" id="linknx_Test" value="5"/>
            </actionlist>
        </rule>            
    </rules>
    <logging output="/var/log/linknx.log" format="%d{%Y-%m-%d %H:%M:%S,%l} %5p > %c %x - %m%n" level="DEBUG" maxfilesize="100" maxfileindex="2" />
</config>

Heute ist Freitag, der 12.10.18, damit erwarte ich folgendes Verhalten bzgl. der nächsten Ausführtermine der rules:

2018-10-12 12:14:58 [ INFO] Rule: Rule: Configuring Tageswechsel (active=1)
2018-10-12 12:14:58 [ INFO] TimeSpec: 1899-0--1 00:00:0 (wdays=0; exception=2)
2018-10-12 12:14:58 [ INFO] PeriodicTask: Rescheduled at 2018-10-13 00:00:00 (1539381600) -> stimmt

2018-10-12 12:14:58 [ INFO] Rule: Rule: Configuring Wochenwechsel (active=1)
2018-10-12 12:14:58 [ INFO] TimeSpec: 1899-0--1 00:00:0 (wdays=1; exception=2)
2018-10-12 12:14:58 [ INFO] PeriodicTask: Rescheduled at 2018-10-15 00:00:00 (1539554400) -> stimmt

2018-10-12 12:14:58 [ INFO] Rule: Rule: Configuring Monatswechsel_1 (active=1)
2018-10-12 12:14:58 [ INFO] TimeSpec: 1899-0-01 00:00:0 (wdays=0; exception=2)
2018-10-12 12:14:58 [ INFO] PeriodicTask: PeriodicTask: DST change detected
2018-10-12 12:14:58 [ERROR] PeriodicTask: Timer error, nextExecTime(1538427600) is before startTime(1539339298) -> FEHLER, hier sollte 2018-11-01 00:00:00 stehen.

2018-10-12 12:14:58 [ INFO] Rule: Rule: Configuring Monatswechsel_2 (active=1)
2018-10-12 12:14:58 [ INFO] TimeSpec: 1899-0-02 00:00:0 (wdays=0; exception=2)
2018-10-12 12:14:58 [ INFO] PeriodicTask: Rescheduled at 2018-11-2 23:00:00 (1541196000) -> stimmt, warum klappt es mit dem 02.11. aber nicht mit dem 01.11. ?

2018-10-12 12:14:58 [ INFO] Rule: Rule: Configuring Monatswechsel_3 (active=1)
2018-10-12 12:14:58 [ INFO] TimeSpec: 1899-0-20 00:00:0 (wdays=0; exception=2)
2018-10-12 12:14:58 [ INFO] PeriodicTask: Rescheduled at 2018-10-20 00:00:00 (1539986400) -> stimmt

2018-10-12 12:14:58 [ INFO] Rule: Rule: Configuring Monatswechsel_4 (active=1)
2018-10-12 12:14:58 [ INFO] TimeSpec: 1899-0-31 00:00:0 (wdays=0; exception=2)
2018-10-12 12:14:58 [ INFO] PeriodicTask: Rescheduled at 2018-10-31 23:00:00 (1541023200) -> FEHLER: Tag stimmt, aber weshalb 23:00 und nicht 00:00 ?

Kann das jemand nachvollziehen bzw. bitte einmal ausprobieren? Würde mir sehr helfen.
Ich kann es echt nicht verstehen. Hab auch diesbezüglich bei google nichts gefunden, was mir weiterhelfen könnte.

[Tru]

Kann das jemand nachvollziehen bzw. bitte einmal ausprobieren? Würde mir sehr helfen.

Ich bekomme mit deiner Konfig die gleichen Resultate. Ich vermute einen Programmfehler. Wir könnten ja mal versuchen den zu finden. Ich bin aber nicht besonders fit in Coding.
Für 23:00:00 gibt es eine Erklärung: wenn es um die gleiche (Tages-)Zeit sein soll, dann stimmt es, es findet am 28.10 die Umstellung auf Winterzeit statt.

[netfriend]

Ich bekomme mit deiner Konfig die gleichen Resultate. Ich vermute einen Programmfehler. Wir könnten ja mal versuchen den zu finden. Ich bin aber nicht besonders fit in Coding.

Ich leider auch nicht. Sieht fast so aus, als ob es ein Problem mit genau dem 01.11. gibt. Daher ist es mir auch bisher nicht aufgefallen, da meine Konfiguration seit Anfang des Jahres so läuft - bisher ohne Probleme.Aufgefallen wäre es mir sicherlich, da jetzt das komplette System zu tot war.

Für 23:00:00 gibt es eine Erklärung: wenn es um die gleiche (Tages-)Zeit sein soll, dann stimmt es, es findet am 28.10 die Umstellung auf Winterzeit statt.

Das hatte ich auch schon im Sinn. Ich hätte nun vermutet, dass trotzdem 00:00 Uhr dort steht, weil zwischenzeitlich zwar die Zeit umgestellt wird, aber zu dem Ausführzeitpunkt in der Winterzeit es 00:00 sein wird. Offenbar wird es aber aus jetziger Sicht angezeigt, dann würde 23:00 Uhr stimmen. Wenn ich mir das dann am 29.10. - wenn schon Winterzeit ist - anschaue, müsste 00:00 Uhr dort stehen. Dann würde es passen.


Trotzdem danke fürs Probieren. Dann weiß ich wenigstens, dass es weder an meiner Konfig noch an meinem Verständnis der Parameter liegt.

[netfriend]

Interessant auch: Stellt man beim Monatswechsel nicht 00:00 ein, sondern 01:00, dann passt's auch am 01.11.. Jedenfalls vom Datum her, Uhrzeit ist aber um 00:00.

<rule id="Monatswechsel">
   <condition type="timer" trigger="true">
      <at hour="1" min="0" day="1"/>
   </condition>
   <actionlist type="if-true">
      <action type="set-value" id="linknx_Test" value="0"/>
   </actionlist>
</rule>

2018-10-12 21:33:02 [ INFO] Rule: Rule: Configuring Monatswechsel (active=1)
2018-10-12 21:33:02 [ INFO] TimeSpec: 1899-0-01 01:00:0 (wdays=0; exception=0)
2018-10-12 21:33:02 [ INFO] PeriodicTask: Rescheduled at 2018-11-1 00:00:00 (1541026800)

[Tru]

Ich leider auch nicht. Sieht fast so aus, als ob es ein Problem mit genau dem 01.11. gibt.

So ist es. Ich habe den Fehler gefunden. Allerdings reicht meine Auffassungsgabe noch nicht aus um den Fehler zu korrigieren. Aber das wird mich wohl die nächsten Tage verfolgen.

Vereinfacht gesagt geht der Code nach meinem bescheidenen Verständnis in Zeilen 562-564 in timermanager.cpp so: die Zeitparameter sind gesetzt als min=0, hour=0, mon=11, mday=1, also 1.11. 00:00. Dann wird davon der Timestamp berechnet. Weil aus Sicht des Startzeitpunkts die Sommerzeit zurückgesetzt wird, ergibt das dann wohl 31.10. 23:00. Dann wird nochmals mday=1 gesetzt, was 1.10. 23:00 ergibt. Zum Schluss wird dann der Timestamp genau so gesetzt und ist dann natürlich falsch. Das passiert für jeden Startzeitpunkt im diesem Oktober vor dem 28.10. 03:00.
Ohne Einbezug der Sommer-/Winterzeit passiert nichts dergleichen. Ich habe das verifiziert, indem ich die gleiche Konfig für die Zeitzone UTC habe laufen lassen.
Es gibt eine Korrekturfunktion mktimeNoDst, welche den Zeitwechsel berücksichtigt - vielleicht kann sie hier eingesetzt werden. Das müsste man zuerst richtig durchdenken.

[netfriend]

Das klingt interessant. Geht mir auch so, dass mich das nicht in Ruhe lässt.

[Tru]

Ich bin unterdessen ziemlich sicher, dass dieser Code von Zeilen 562-564 geändert werden sollte

timeinfo->tm_mday = mday;
mktime(timeinfo);
timeinfo->tm_mday = mday;

und zwar so

timeinfo->tm_mday = mday;
mktimeNoDst(timeinfo);

Jedenfalls läuft dann deine Konfig korrekt. So wird die Stunde kompensiert, welche beim Wechsel zur Winterzeit abgezogen wird.

[MGK]

Wenn das dann funktioniert bitte auch auf https://github.com/linknx/linknx/issues melden, dann haben alle was davon!

[Tru]

Wenn das dann funktioniert bitte auch auf https://github.com/linknx/linknx/issues melden, dann haben alle was davon!

Ich habe jetzt noch eine Nacht darüber (nicht) geschlafen und bin jetzt überzeugt die richtige Korrektur gefunden zu haben und habe einen Pull Request abgesetzt

[netfriend]

Super, danke fürs kümmern! Echt klasse

[cyrille]

Hi everyone,

I am the french developer who decided to take the linknx project over a few years ago, after discussing with Jean-François who did explicitly tell that he was no more willing to spend time on it. As it has already been mentioned earlier in this thread, the source code is now on github: https://github.com/linknx/linknx and my username is 2franix.

First, let me thank netfriend for the outstanding bug report. This is really helpful. I also would like to thank Tru for his time in investigating this issue.

But I also would like to mention that this forum is definitely not the best place to report issues regarding linknx. The main reason is I do not visit this forum very often. My German is quite rusty (to the least). So the odds are very high that I would miss an important report, as I would have for this thread if Tru did not let me know. The best way to report problems is to submit an issue on github (https://github.com/linknx/linknx/issues). Alternatively, you can post to https://groups.google.com/forum/#!fo...-linknx-knxweb which I subscribed to. The forum is mostly in French but feel free to post in English or even in German. That would at least draw my attention. You can even drop me a line by email - my address being easy to find in the AUTHORS file.

Coming back to Tru 's PR: I believe his last version is correct but by reviewing the whole section of code dealing with periodic tasks I have found a few other bugs... I would like to have everything fixed while I am at it. I'll let this thread know once everything is fixed. Thank you for your patience!

Best regards,
Cyrille

[MGK]

Thanks cyrille, your work is appreciated!!!