[gelöst] smartSleep friert Fhem ein

[alru]

Moin,

da nach dem Update (https://forum.fhem.de/index.php/topic,95298.0.html) i.S. "alive" action required ist, wollte ich das heute mal testen.

So wie ich das verstanden habe, gibt es zwei Möglichkeiten ein alive zu generieren:

• sendHeartbeat() oder
• smartSleep(<ms>)

Die erste Variante mit sendHeartbeat() funktioniert wie erwartet. Die readings für heartbeat und state werden entsprechend aktualisiert.

Beim Einsatz von smartSleep erscheint nach dem Start des Nodes oder nach dem Reset häufig (nicht immer, aber man kann es provozieren) im state "received presentation".
Danach ist Fhem sofort komplett eingefroren (im Log ist dazu nichts zu finden). Auf der Konsole wird beim Prozess 100% CPU Auslastung angezeigt. Ein Stop/Start von Fhem ist nicht möglich, der Prozess muss gekilled werden.
So lange asleep, alive oder dead im state erscheint, funktioniert alles.

Getestet hab ich das mit einem quasi "leeren" Sketch, auf einem Uno:

Code Auswählen Erweitern

void loop()
{
// so geht es:
     sendHeartbeat();
     sleep(5000);

// und so nicht:
//   smartSleep(5000);
}

Meine Konfigurationen:
fhem.pl                                        18317 2019-01-18
10_MYSENSORS_DEVICE.pm 18211 2019-01-11
Mysensors API                           2.2.0
Arduino IDE                                1.8.5

Wenn ich die Wahl hätte, wäre smartSleep mein Favorit, da dort auch der Status "asleep" zu sehen ist.

[Beta-User]

Hallo alru,
Danke für's reporten.

Leider habe ich im Moment noch keine durchgreifende Idee, was das auslöst, aber die Funktionalität sollte so sein wie vor dir beschrieben.

Kannst du mal den Abschnitt ab Zeile 767 gegen das hier tauschen und dann nochmal versuchen, den Fehler zu provozieren:

Code Auswählen Erweitern

    $type == I_SKETCH_NAME and do {
        #$hash->{$typeStr} = $msg->{payload};
        readingsSingleUpdate($hash, "state", "received presentation", 1) unless ($hash->{STATE} eq "received presentation");
        readingsSingleUpdate($hash, "SKETCH_NAME", $msg->{payload}, 1);
        Log3 $name, 3, "Sketch Name updated";
        #undef $hash->{FW_DATA}; # enable this to free memory?
        delete $hash->{FW_DATA} if (defined $hash->{FW_DATA});
        Log3 $name, 3, "FW_data successfully deleted";
        if (defined $hash->{getCommentReadings}){
          if ($hash->{getCommentReadings} eq "1") {
            $hash->{getCommentReadings} = 2 ;
            Log3 $name, 3, "getCommentReadings set to 2";
          }elsif ($hash->{getCommentReadings} eq "2") {
            Log3 $name, 3, "deleting getCommentReadings";
            delete $hash->{getCommentReadings};
          }
        }
        Log3 $name, 3, "leaving Sketch Name update";
        last;
    };

Dann wäre noch gut zu wissen, wie die Node konfiguriert ist und ob du versucht hast, was an die zu versenden. Bzw. wie du den Absturz provozieren kannst.

Tendenziell würde ich smartSleep aber eher für nodes nutzen, die zwar schlafen, aber Infos erhalten sollen oder OTA-fähig sein (und bei denen man schlecht an den Knopf für einen Reboot kommt). Bei smartSleep wird nämlich der Prozessor samt Transceiver nicht gleich schlafen gelegt, das kostet also ggf. Batterielebensdauer.

(Aber das Problem sollten wir natürlich fixen).

[alru]

Moin,

ich hab mal die Zeile gegen ausgetauscht. Danach ging leider gar nix mehr mit den Mysensor Nodes, aber reichlich Text im Log:

Code Auswählen Erweitern

2019.01.26 16:19:25 1: PERL WARNING: Subroutine MYSENSORS_DEVICE_Initialize redefined at ./FHEM/10_MYSENSORS_DEVICE.pm line 30.
2019.01.26 16:19:25 1: PERL WARNING: Subroutine Define redefined at ./FHEM/10_MYSENSORS_DEVICE.pm line 215.
2019.01.26 16:19:25 1: PERL WARNING: Subroutine UnDefine redefined at ./FHEM/10_MYSENSORS_DEVICE.pm line 235.
2019.01.26 16:19:25 1: PERL WARNING: Subroutine Set redefined at ./FHEM/10_MYSENSORS_DEVICE.pm line 244.
2019.01.26 16:19:25 1: PERL WARNING: Subroutine Get redefined at ./FHEM/10_MYSENSORS_DEVICE.pm line 325.
2019.01.26 16:19:25 1: PERL WARNING: Subroutine onStreamMessage redefined at ./FHEM/10_MYSENSORS_DEVICE.pm line 369.
2019.01.26 16:19:25 1: PERL WARNING: Subroutine Attr redefined at ./FHEM/10_MYSENSORS_DEVICE.pm line 444.
2019.01.26 16:19:25 1: PERL WARNING: Subroutine onGatewayStarted redefined at ./FHEM/10_MYSENSORS_DEVICE.pm line 585.
2019.01.26 16:19:25 1: PERL WARNING: Subroutine onPresentationMessage redefined at ./FHEM/10_MYSENSORS_DEVICE.pm line 590.
2019.01.26 16:19:25 1: PERL WARNING: Subroutine onSetMessage redefined at ./FHEM/10_MYSENSORS_DEVICE.pm line 671.
2019.01.26 16:19:25 1: PERL WARNING: Subroutine onRequestMessage redefined at ./FHEM/10_MYSENSORS_DEVICE.pm line 686.
2019.01.26 16:19:25 1: PERL WARNING: Subroutine onInternalMessage redefined at ./FHEM/10_MYSENSORS_DEVICE.pm line 701.
2019.01.26 16:19:25 1: PERL WARNING: Subroutine sendClientMessage redefined at ./FHEM/10_MYSENSORS_DEVICE.pm line 922.
2019.01.26 16:19:25 1: PERL WARNING: Subroutine rawToMappedReading redefined at ./FHEM/10_MYSENSORS_DEVICE.pm line 954.
2019.01.26 16:19:25 1: PERL WARNING: Subroutine mappedReadingToRaw redefined at ./FHEM/10_MYSENSORS_DEVICE.pm line 964.
2019.01.26 16:19:25 1: PERL WARNING: Subroutine short2Hex redefined at ./FHEM/10_MYSENSORS_DEVICE.pm line 983.
2019.01.26 16:19:25 1: PERL WARNING: Subroutine hex2Short redefined at ./FHEM/10_MYSENSORS_DEVICE.pm line 989.
2019.01.26 16:19:25 1: PERL WARNING: Subroutine flashFirmware redefined at ./FHEM/10_MYSENSORS_DEVICE.pm line 994.
2019.01.26 16:19:25 1: PERL WARNING: Subroutine refreshInternalMySTimer redefined at ./FHEM/10_MYSENSORS_DEVICE.pm line 1081.
2019.01.26 16:19:25 1: PERL WARNING: Subroutine timeoutMySTimer redefined at ./FHEM/10_MYSENSORS_DEVICE.pm line 1107.
2019.01.26 16:20:58 3: Sketch Name updated
2019.01.26 16:20:58 3: FW_data successfully deleted
2019.01.26 16:20:58 3: leaving Sketch Name update
2019.01.26 16:22:35 1: PERL WARNING: Subroutine sendClientMessage redefined at ./FHEM/10_MYSENSORS_DEVICE.pm line 917.
2019.01.26 16:22:35 1: PERL WARNING: Subroutine rawToMappedReading redefined at ./FHEM/10_MYSENSORS_DEVICE.pm line 949.
2019.01.26 16:22:35 1: PERL WARNING: Subroutine mappedReadingToRaw redefined at ./FHEM/10_MYSENSORS_DEVICE.pm line 959.
2019.01.26 16:22:35 1: PERL WARNING: Subroutine short2Hex redefined at ./FHEM/10_MYSENSORS_DEVICE.pm line 978.
2019.01.26 16:22:35 1: PERL WARNING: Subroutine hex2Short redefined at ./FHEM/10_MYSENSORS_DEVICE.pm line 984.
2019.01.26 16:22:35 1: PERL WARNING: Subroutine flashFirmware redefined at ./FHEM/10_MYSENSORS_DEVICE.pm line 989.
2019.01.26 16:22:35 1: PERL WARNING: Subroutine refreshInternalMySTimer redefined at ./FHEM/10_MYSENSORS_DEVICE.pm line 1076.
2019.01.26 16:22:35 1: PERL WARNING: Subroutine timeoutMySTimer redefined at ./FHEM/10_MYSENSORS_DEVICE.pm line 1102.

Zur Konfiguration des Node, hier das List:

Code Auswählen Erweitern

Internals:
   CFGFN     
   DEF        199
   FUUID      5c4c7d1e-f33f-f58a-7cf3-6a7db27a73ed95f1
   IODev      MSG1
   NAME       MYSENSOR_199
   NR         1211
   STATE      alive
   TYPE       MYSENSORS_DEVICE
   ack        0
   radioId    199
   repeater   0
   timeoutAlive 10
   version    2.2.0
   READINGS:
     2019-01-26 16:34:04   heartbeat       last
     2019-01-26 16:34:04   state           alive

Attributes:
   IODev      MSG1
   mode       node
   room       Test
   timeoutAlive 10

Und hier der komplette Sketch:

Code Auswählen Erweitern

// Test Sktech um "Heartbeat" zu prüfen

// Enable debug prints to serial monitor
#define MY_DEBUG

// Enable and select radio type attached
#define MY_RADIO_NRF24
// MSG1 (Frequenz 2496 MHz)
#define MY_RF24_CHANNEL 96

// Optional: Define Node ID
#define MY_NODE_ID 199
#define MY_PARENT_NODE_ID 0
#define MY_PARENT_NODE_IS_STATIC

#include <MySensors.h>

void before()
{
}

void setup()
{
}

void presentation()
{
  // Send the sketch version information to the gateway and Controller
  sendSketchInfo("uno_test_heartbeat", "0.2");
}

void loop()
{
sendHeartbeat();
sleep(5000);
// smartSleep(5000);
}


Provoziert hab ich den Absturz einfach mit der Reset Taste auf dem Uno. Gesendet hab ich aus Fhem nichts

[Beta-User]

Hmm,
ok, Danke, passiert auch bei mir "zuverlässig", wenn ich die schlafende Node reboote...

Mache grade ein paar Tests mit mehr logausgaben, ich denke, ich kann den Fehler soweit eingrenzen, dass das bald gefixt sein wird.

[Beta-User]

So, Fehler hoffentlich identifiziert und behoben, update ist im svn.

Die log-Ausgaben können wieder raus, nach "$hash->{FW_DATA} if (defined $hash->{FW_DATA});"
sollte folgendes rein:

Code Auswählen Erweitern

$hash->{nowSleeping} = 0 if $hash->{nowSleeping};

Wenn es danach noch Probleme gibt, bitte melden.

[alru]

Das ging ja fix....

Ich hab noch ein paar Warnings im Log gefunden:

Code Auswählen Erweitern

2019.01.26 18:11:44 1: PERL WARNING: Subroutine sendClientMessage redefined at ./FHEM/10_MYSENSORS_DEVICE.pm line 916.
2019.01.26 18:11:44 1: PERL WARNING: Subroutine rawToMappedReading redefined at ./FHEM/10_MYSENSORS_DEVICE.pm line 948.
2019.01.26 18:11:44 1: PERL WARNING: Subroutine mappedReadingToRaw redefined at ./FHEM/10_MYSENSORS_DEVICE.pm line 958.
2019.01.26 18:11:44 1: PERL WARNING: Subroutine short2Hex redefined at ./FHEM/10_MYSENSORS_DEVICE.pm line 977.
2019.01.26 18:11:44 1: PERL WARNING: Subroutine hex2Short redefined at ./FHEM/10_MYSENSORS_DEVICE.pm line 983.
2019.01.26 18:11:44 1: PERL WARNING: Subroutine flashFirmware redefined at ./FHEM/10_MYSENSORS_DEVICE.pm line 988.
2019.01.26 18:11:44 1: PERL WARNING: Subroutine refreshInternalMySTimer redefined at ./FHEM/10_MYSENSORS_DEVICE.pm line 1075.
2019.01.26 18:11:44 1: PERL WARNING: Subroutine timeoutMySTimer redefined at ./FHEM/10_MYSENSORS_DEVICE.pm line 1101.
2019.01.26 18:12:26 3: leaving Sketch Name update

Besonders die letzte Zeile "leaving Sketch Name update" wird nach jedem Reset geschrieben, aber ...
...die smartSleep Funktion ist jetzt gegeben. Mein Kurztest hat keine Abbrüche mehr feststellen können.

Sieht also gut aus. Ich lasse die Tests noch weiter laufen. Aber soweit erst mal Danke!

Noch eine Frage zur Nutzung der beiden Funktionen:
Ich bin mir jetzt echt unsicher welche der Varianten ich nutzen soll. "Wartet" smartSleep denn entscheidend lange, so dass der Batteriebetrieb wirklich merklich belastet wird?

[alru]

Moin,

ich hab noch ein paar Tests durchgeführt, aber keine weiteren Fehler gefunden.
Es bleibt nur bei der für mich nicht nachvollziehbaren Meldung im Log, die nach jedem Neustart des Nodes dort zu finden ist. Und zwar für beide alive-Varianten (heartbeat oder smartSleep):

Code Auswählen Erweitern

2019.01.27 14:34:15 3: leaving Sketch Name update
Ein evtl. Update des Sketch Names wird natürlich trotzdem ausgeführt.

[Beta-User]

Moin,
hast du ein update gemacht oder alle log-Zeilen von der gestrigen Erweiterung wieder rausgeworfen?
Dann sollte das weg sein.

Die übrigen "redefined"-Zeilen kamen übrigens vom reload des Moduls, das ist immer so, wenn man (irgend-) ein Modul manuell neu lädt.

Ergänzend noch zur Frage, was da sinnvoll ist: Es gibt auch noch eine Timer-Erneuerung bei Sendung eines battery-internals. Ansonsten nimmt smartSleep per dafault 500UL, also bei einer 1MHz-Node 500ms (was ein sinnvoller Wert ist).

Will man nicht zwingend was senden (oder kommt an die Node nicht für OTA ran), finde ich die battery-Variante eigentlich am besten (reicht ja ggf. nur alle paar Sendungen). Das mit dem state "asleep" ist zwar nett, aber m.E. reicht es, wenn man weiß, dass die Node regelmäßig sendet.
Muß aber natürlich jeder selber wissen, aus meiner Warte war das vor allem dazu da, um die Funktionsfähigkeit voll auszutesten... Bei "kitzeligen" Funkverbindungen kann das m.E. sogar kontraproduktiv sein (wenn die "gehe-jetzt-Schlafen"-Info unterwegs verloren geht).

[alru]

Moin,
ich hab gestern das Modul aus dem SVN installiert. Danach kamen dann nur noch die Meldung mit "leaving Sketch Name update" im Log, keine weiteren Meldungen.
Also waren die anderen Meldungen tatsächlich vom Reload des Moduls.

Danke für die Erklärung zu den Unterschieden. Ich werde jetzt erst mal die sendHeartbeat() Variante benutzen. Der Sketch der jetzt damit ausgestattet wird darf ohnehin kein sleep benutzen, das hab ich jetzt beim Blick in den Code erst wieder gesehen.

[Beta-User]

Thx, da hatte ich beim update noch einen Level übersehen. update ist eingecheckt.

[alru]

... update ist eingecheckt.

? Ich sehe im SVN nur die Version von gestern...

[achim771]

Hallo,

leider hängt mein FHEM auch fest. Seit Anfang des Monats steht der FHEM-Prozess
mit nahezu 100%. Mit 'service fhem stop' und viel Wartezeit bekomme ich den Server
gestoppt. Im Moment läuft der Server nur, wenn ich die MYSENSORS_DEVICE.pm vom 24.10.2018
downgrade.

Habe heute mal ein nagelneuen FHEM-Server mit Serial-Gateway und den gleichen Nodes aufgesetzt.
Gleiches Ergebniss

Die meisten meiner Nodes sind Sleep-Nodes mit smartSleep().

[Beta-User]

Hallo zusammen,
@achim771: bitte um Rückmeldung, ob das mit version 18432 auch noch passiert (von gestern nachmittag 14:37:06 UTC). Wenn ja: steht was im log? Bzw. kannst du auf dem testsystem mal den verbose-level der Node, die du neu startest auf 5 stellen (dann recht schnell stoppen, bei mir war es mit der alten Version auch unendlich dieselbe Fehlermeldung)...?

@alru: K.A., warum die gestern nicht direkt verfügbar war, hat evtl. ein paar Minuten gedauert, bis das sichtbar war...

[achim771]

@Beta-User: ja, ist die Version 18432. Hab mal ein Testnode(100) zusätzlich eingebunden.
Ausgelöst hat es allerdings ein getriggerter Bewegungsmelder(107)

Code Auswählen Erweitern

2019.01.28 18:07:57 5: MYSENSOR_100: refreshInternalMySTimer called (Asleep)
2019.01.28 18:07:57 5: MYSENSOR_100: Awake timeout timer set at 1548695277.86823
2019.01.28 18:07:57 5: MYSENSOR_100: timeoutMySTimer called (timeoutAwake)
2019.01.28 18:08:03 5: MYSENSOR_100: refreshInternalMySTimer called (Asleep)
2019.01.28 18:08:03 5: MYSENSOR_100: Awake timeout timer set at 1548695283.70622
2019.01.28 18:08:03 5: MYSENSOR_100: timeoutMySTimer called (timeoutAwake)
2019.01.28 18:08:09 5: MYSENSOR_100: refreshInternalMySTimer called (Asleep)
2019.01.28 18:08:09 5: MYSENSOR_100: Awake timeout timer set at 1548695289.54492
2019.01.28 18:08:09 5: MYSENSOR_100: timeoutMySTimer called (timeoutAwake)
2019.01.28 18:08:12 5: MYSENSOR_107 is sleeping, enqueueing message!
2019.01.28 18:08:12 5: MYSENSOR_107 is sleeping, enqueueing message!
2019.01.28 18:08:13 4: MYSENSORS_DEVICE MYSENSOR_107: batteryPercent 71
2019.01.28 18:08:14 5: MYSENSOR_107: refreshInternalMySTimer called (Asleep)
2019.01.28 18:08:14 5: MYSENSOR_107: Awake timeout timer set at 1548695294.45189
2019.01.28 18:08:14 5: MYSENSOR_107 is sleeping, enqueueing message!
2019.01.28 18:08:14 5: MYSENSOR_107 is sleeping, enqueueing message!
2019.01.28 18:08:14 5: MYSENSOR_107 is sleeping, enqueueing message!
2019.01.28 18:08:14 5: MYSENSOR_107 is sleeping, enqueueing message!
2019.01.28 18:08:14 5: MYSENSOR_107 is sleeping, enqueueing message!
2019.01.28 18:08:14 5: MYSENSOR_107 is sleeping, enqueueing message!
2019.01.28 18:08:14 5: MYSENSOR_107 is sleeping, enqueueing message!

PS: es hängen noch Gateways am Pi (RPI-HM-MOD, Signalduino, BT LE) die allerdings nicht im FHEM registriert sind!

[alru]

Moin,

ich hab jetzt auch die Version 18432 kurz getestet.
Bei mir sieht jetzt alles OK aus. Die Meldungen im Log sind auch weg. Der Fhem Prozess zeigt eine unauffällige CPU Last.