Sonos Player disappeared

Reinerlein · 19 Juni 2020, 10:44:43

Hi Nobby,

Zitatund deshalb kam es pro nicht erreichbarem SONOS-Devices bis zu 9 mal zum 20 Sekunden Timeout und danach trat immer mal wieder ein "way too old" auf

Du meinst beim Absetzen eines Befehls an einen Player, der schon weg war, aber vom Modul noch nicht als "disappeared" markiert war?

Ok, das ist noch ein Hinweis. Aber eine Änderung war ja auch der Timeout auf 5 Sekunden in der ControlPoint...

Grüße
Reinerlein

Nobby1805 · 19 Juni 2020, 11:44:35

Hallo Reinerlein,

der "abgesetzte Befehl" ist das alle 30 Minuten durchgeführte "RenewSubscription" für alle SONOS-Geräte.

Wenn du weiter vorne hier im Thread schaust, dann findest du Loggings von mir, wo ich den Logtext durch den "Rückgabewert" in $@ erweitert habe, man sieht in den einzelnen Logzeilen jeweils den 20 Sekunden Timeout und $@ ist immer leer.
Die Reduzierung des Timeouts von 20 auf 5 Sekunden verhindert/reduziert zwar die Wahrscheinlichkeit von "way too old", aber das eigentliche Problem ist ja die Rückgabe des Fehlercodes aus ControilPoint.

btw. in 00_SONOS gibt es einen Hinweis zur Behandlung von croak/catp in ControlPoint, aber alles nur Kommentar

Code Auswählen

  ########################################################
  # Change all carp-calls in the UPnP-Module to croak-calls
  # This will ensure you can "catch" carp with an enclosing
  # "eval{}"-Block
  ########################################################
  #*UPnP::ControlPoint::carp = \&UPnP::ControlPoint::croak;

Gruß Nobby

Reinerlein · 19 Juni 2020, 12:15:45

Hi Nobby,

danke für die Aufklärung.. ich habe den Thread, wie gesagt, nur überflogen

Das ausmarkierte von mir hatte meiner Meinung nach zu Problemen geführt, da es dann auch die anderen Module, die die ControlPoint verwenden, beeinflusst hatte...
Deswegen muss man mit Änderungen in der Datei auch immer etwas zurückhaltend sein $:-\$

Aber wie gesagt, sind wir ja noch auf der Fehlersuche...

Grüße
Reinerlein

aski71 · 19 Juni 2020, 12:36:10

Zitat von: Reinerlein am 19 Juni 2020, 12:15:45
Hi Nobby,

danke für die Aufklärung.. ich habe den Thread, wie gesagt, nur überflogen

Das ausmarkierte von mir hatte meiner Meinung nach zu Problemen geführt, da es dann auch die anderen Module, die die ControlPoint verwenden, beeinflusst hatte...
Deswegen muss man mit Änderungen in der Datei auch immer etwas zurückhaltend sein $:-\$

Aber wie gesagt, sind wir ja noch auf der Fehlersuche...

Grüße
Reinerlein

Hallo Leute,

cool, dass hier wieder Bewegung drin ist.
Ich hatte heute früh wieder das Problem, dass Lautsprecher, die ich per AddMember automatisch und bewegungsgesteuert einer Hauptquelle zuschalten lasse, nichts getan haben, obwohl sie nicht auf disappeared standen.
Vorgestern hatte ich den Fall, dass morgens das Hauptmodul wieder auf disable stand.
Und scheinbar "verschwinden" Lautsprecher hin und wieder und können auch durch ReScanNetwork nicht mehr gefunden werden.

Das alles tritt bei mir erst wieder auf, seit Umstieg auf S2.

Letzter Stand war: Ich habe von mumpitzstuff verstanden, ich soll seine Version installieren. des Loggings wegen.

Nachdem ja jetzt auch wieder am Originalmodul geschraubt wird: Was empfehlt Ihr? mumpitzstuff-Version installieren? Oder anhand des Originalmoduls bei der Diagnose helfen?
Und wenn ja, wie?

Kann leider nicht zuverlässig jeden Tag hier sein, aber: happy to help!

mumpitzstuff · 19 Juni 2020, 18:23:50

Zitat von: Reinerlein am 18 Juni 2020, 23:52:56
Und natürlich lasse ich den SubProzess erstmal nur absterben. Um den Neustart kümmert sich dann Zeitversetzt ein anderer Teil:
Code Auswählen Erweitern
. . # Stoppen... InternalTimer(gettimeofday() + 1, 'SONOS_StopSubProcess', $hash, 0); # Starten... InternalTimer(gettimeofday() + 30, 'SONOS_DelayStart', $hash, 0); . .
Das ist das, was ausgeführt wird, wenn die letzte SubProzess-Antwort zu lange her ist... Beides wird Zeitversetzt ausgeführt, damit Fhem nicht blockiert wird...

Ja das versuchst du an der Stelle, das ist richtig. Es funktioniert meiner Meinung nach nur nicht so wie du dir das vorstellst. Du stoppst erst den Subprocess und versuchst ihn dann mit SONOS_DelayStart neu zu starten. Dabei vergisst du aber, das die Verbindung noch existiert. Selbst wenn du den Socket schliesst, braucht dieser unter Umständen viele Sekunden bis er wirklich abgebaut ist. Das dauert länger als die von dir vorgesehenen 30s! Das siehst du in deinem Originalmodul sehr schön nach einem shutdown restart von FHEM. Dein Modul braucht 3-4 Anläufe bis der Port wieder frei ist, obwohl du zwischen den Versuchen 30s wartest. Das führt dann dazu, das in der Funktion SONOS_StartClientProcessIfNeccessary() die Bedingung if (!$socket) nicht true sondern false ist. Dadurch schiesst du den Server komplett ab. Du hast hier kein retry eingebaut, der später erneut versuchen würde den UPnP-Server noch einmal zu starten. Aus diesem Grund habe ich filgendes gemacht:

Code Auswählen

eval {
      $socket->sockopt(SO_LINGER, pack("ii", 1, 0));
      $socket->sockopt(SO_REUSEADDR, 1);
      $socket->sockopt(SO_REUSEPORT, 1) if (defined(&SO_REUSEPORT));
    };
eval {
      $socket->shutdown(2);
      $socket->close();
    };

SO_LINGER sorgt dafür das der Socket sofort freigegeben wird (ohne wait). Danach wird das Ding abgeschossen und ist sofort weg. Danach starte ich den Server wieder. Da jetzt der Socket frei sein sollte, braucht es an der Stelle auch kein Retry mehr und alles sollte gehen.

Beim Ping habe ich folgendes geändert:

Code Auswählen

    $ping->port_number($port) if ((lc($pingType) eq 'tcp') || (lc($pingType) eq 'syn')); # Wenn TCP oder SYN verwendet werden soll, dann auf HTTP-Port des Location-Documents (Standard: 1400) des Player verbinden
    $ping->ping($host) if (lc($pingType) eq 'syn');

    if (((lc($pingType) eq 'syn') && $ping->ack($host)) ||
        ((lc($pingType) ne 'syn') && $ping->ping($host))) {

DIe Änderungen sind hier, das bei syn der Port gesetzt werden muss, genauso wie bei tcp. Außerdem muss man bei syn zuerst ein ping() aufrufen (das gibts immer true zurück) und erst ack() liefert das Ergebnis true oder false. Bei allen anderen Pings muss man nur ping() aufrufen, um das Ergebnis zu erhalten. Mit anderen Worten, der syn Ping liefert in deinem Modul immer true.

In den Funktionen SONOS_RestartControlPoint und SONOS_StopControlPoint setze ich ebenfalls SO_LINGER und close dann die Sockets, was bewirkt, das die Sockets SOFORT frei werden. Danach setzt dein SONOS Modul die ControlPoint neu auf, was allerdings nicht funktioniert und zum Absturz führt, wenn die Ports noch belegt sind. Wenn die Dinger aber mit SO_LINGER und close geschlossen wurden, geht das.

Reinerlein · 19 Juni 2020, 20:59:37

Hi mumpitzstuff,

das mit dem Ping habe ich übernommen, danke für die Hinweise...

Bei dem "StartClientProcessIfNeccessary" muss allerdings noch berücksichtigt werden, dass der Anwender den SubProzess vielleicht schon selber gestartet hat, vielleicht auch auf einer anderen Maschine... Deswegen passt deine Änderung da nicht ganz... ich schrieb ja, dass ich mir das gerade genauer anschaue, da es nicht ganz so einfach ist...

Die eigentliche Verbindung wird dann ja auch von Fhem gemacht, sodass ich da nicht einfach so_linger angeben kann. In der Prozedur wird ja nur geschaut, ob ich selber was starten müsste...
Der Verbindungsaufbau passiert initial nach dem define in "SONOS_DelayOpenDev". Kann ich dieses so_linger irgendwie mitgeben oder danach setzen?
Und wird das bei einem Re-Connect durch Fhem wieder gesetzt?
Oder muss das nur auf der Socket-Serverseite erfolgen? Dann wäre deine Stelle ja nicht korrekt, sondern müsste in den SubProzess (wo es aber auch schon steht, und die 9-fache Wiederholung eingebaut ist)...
Oder reicht es, es an irgendeiner Seite zu setzen?

Das ist mir einfach alles noch etwas unklar...

Grüße
Reinerlein

mumpitzstuff · 19 Juni 2020, 21:17:35

Ich habe es immer da gemacht (erst SO_LINGER gesetzt und dann den Socket abgeschossen) wo das Modul irgendwie den Socket ohnehin abgeschossen hat. Auch an der besagten Stelle ist dein Originalmodul immer in den Zweig rein, wo der Socket mit close geschlossen wurde. An der Logik selbst habe ich nichts geändert und den Sonderfall den du ansprichst, der kann meines Erachtens nie funktioniert haben. Wenn du den Prozess außerhalb von FHEM selbst startest, dann schießt meines Erachtens dein Modul beim Start das Ding wieder ab und baut einen eigenen Server auf. Aber probier das doch noch mal aus, es würde mich interessieren, ob meine Theorie stimmt.

Wenn man SO_LINGER kurz davor setzt, wird der Socket meines Wissens sofort geschlossen, ohne rund 2 Minuten im wait zu verharren und die Verbindung ordentlich abzubauen. Das ist wie den Stecker ziehen. Ich würde die Option übrigens nicht sofort setzen, sondern nur, kurz bevor du den Socket ohnehin schließt oder wie bei der Controlpoint die Verbindungen neu aufbauen möchtest.

Reinerlein · 19 Juni 2020, 22:47:47

Hi mumpitzstuff,

das mit dem bereits gestarteten SubProzess funktioniert. Einige benutzen das, wenn Fhem nicht im selben Multicast-Netz wie die Sonosplayer liegt...

Der Check prüft ja nur, und trennt die Verbindung ordnungsgemäß wieder. Abgeschossen wird da gar nichts.

Ich habe mal ein paar so_linger-Optionen verteilt... mal sehen, wie das jetzt so läuft...

Grüße
Reinerlein

mumpitzstuff · 21 Juni 2020, 00:09:52

Okay. Du könntest übrigens testweise einfach mal einen Timer setzen und dann z.b. 2min nach dem Start interne Variablen umbiegen oder Funktionen aufrufen und so die neuralgischen Punkte triggern, die irgendwelche restarts von Prozessen oder der ControlPoint machen. Dann kannst du direkt sehen was passiert bzw. ob du in irgendwelche Probleme rein läufst. Das warten auf einen zufälligen Fehler würde sich dann zumindest teilweise erübrigen.

Reinerlein · 23 Juni 2020, 09:53:37

Hallo,

kurzer Zwischenstand:
Ich habe für die Fehler aus der ControlPoint (carp-Aufrufe) mich nun für die unter Perlvar (https://perldoc.perl.org/perlvar.html#Error-Variables) empfohlene Schreibweise entschieden:

Code Auswählen

local $SIG{__WARN__} = sub { die $_[0] };
Damit wird meine bereits eingebaute Methode (das Prüfen von "$@") funktionsfähig gemacht...
Das funktioniert auch, ich habe in der ControlPoint bei Renew mal Fehler provoziert, und diese wurden korrekt gemeldet und behandelt.

Auch hat das Einbauen der so_linger-Optionen Wirkung gezeigt, und es gibt bei einem Neustart des SubProzesses keine Port-ist-noch-blockiert-Meldungen.

@mumpitzstuff: Ich habe in deinem Code eine Anpassung bei "setCurrentTrackPosition" gefunden. Ich habe nur nicht verstanden, warum... es scheint so zu sein, dass du dachtest man könnte keine Sekunden angeben...
Das klappt aber alles...
Was war denn der Grund für diese Änderung?

Grüße
Reinerlein

aski71 · 23 Juni 2020, 12:25:50

Ich habe jetzt mumpitzstuff's Modul installiert.
Heutiges Phänomen: Playbase spielt was ab, aber das Modul bekommt es nicht mit.
Alles steht auf appeared. Sonos ist opened.
Behebung: Sonos Device neu starten.

Trotz Verbose 3 sehe ich leider nichts im Logging.

mumpitzstuff · 23 Juni 2020, 19:41:48

Zitat von: Reinerlein am 23 Juni 2020, 09:53:37
Hallo,

kurzer Zwischenstand:
Ich habe für die Fehler aus der ControlPoint (carp-Aufrufe) mich nun für die unter Perlvar (https://perldoc.perl.org/perlvar.html#Error-Variables) empfohlene Schreibweise entschieden:
Code Auswählen Erweitern
local $SIG{__WARN__} = sub { die $_[0] };
Damit wird meine bereits eingebaute Methode (das Prüfen von "$@") funktionsfähig gemacht...
Das funktioniert auch, ich habe in der ControlPoint bei Renew mal Fehler provoziert, und diese wurden korrekt gemeldet und behandelt.

Auch hat das Einbauen der so_linger-Optionen Wirkung gezeigt, und es gibt bei einem Neustart des SubProzesses keine Port-ist-noch-blockiert-Meldungen.

@mumpitzstuff: Ich habe in deinem Code eine Anpassung bei "setCurrentTrackPosition" gefunden. Ich habe nur nicht verstanden, warum... es scheint so zu sein, dass du dachtest man könnte keine Sekunden angeben...
Das klappt aber alles...
Was war denn der Grund für diese Änderung?

Grüße
Reinerlein

Ich kann dir nicht folgen. Der einzige Punkt an der ich das finde ist hier (Z. 2574):

Code Auswählen

    } elsif ($workType eq 'setCurrentTrackPosition') {

An der Stelle habe ich laut meinem Git keine Änderungen vorgenommen. Da wurden höchstens Tabs in Leerzeichen konvertiert oder ich habe eine Einrückung angepasst.

mumpitzstuff · 23 Juni 2020, 19:43:16

Zitat von: aski71 am 23 Juni 2020, 12:25:50
Ich habe jetzt mumpitzstuff's Modul installiert.
Heutiges Phänomen: Playbase spielt was ab, aber das Modul bekommt es nicht mit.
Alles steht auf appeared. Sonos ist opened.
Behebung: Sonos Device neu starten.

Trotz Verbose 3 sehe ich leider nichts im Logging.

Warte am besten noch etwas bis Reinerlein seine Version angepasst hat, dann sind vielleicht auch diese Probleme behoben.

aski71 · 23 Juni 2020, 19:44:12

Zitat von: mumpitzstuff am 23 Juni 2020, 19:43:16
Warte am besten noch etwas bis Reinerlein seine Version angepasst hat, dann sind vielleicht auch diese Probleme behoben.

Alles klar. Ich warte ab.

Reinerlein · 23 Juni 2020, 20:24:46

Hi mumpitzstuff,

ja, du hast Recht... mein Vergleichstool hat eine sehr unübersichtliche Ausgabe, und es war meine eigene Änderung, die nur noch nicht im Subversion drin ist

Ich hatte ja noch ein bißchen Hoffnung, dass diese SubProzess-Stillstand mal bei mir auftritt... aber der ist bei mir ja sowieso sehr selten gewesen (so alle 2-3Monate mal), sodass hier natürlich in der kurzen Zeit nix passiert...
Ich werde im Laufe des Wochenendes wohl mal meinen letzten Stand einchecken, und dann mal sehen, ob es allgemein besser wird...

Grüße
Reinerlein