SONOS Player Disappeared ... immer und immer wieder

Begonnen von KalleBlomquist, 01 Dezember 2017, 08:48:45

Vorheriges Thema - Nächstes Thema

Reinerlein

Hi Kalle,

ok, er verarbeitet also die ReceiveQueue (bei dir ja noch ComObjectQueue :) ) irgendwann nicht mehr.

hmm... Das ist ja blöd...
Versuch doch mal die Wartezeit etwas hochzusetzen. Damit wird die Reaktionszeit etwas höher, aber vielleicht liegt es irgendwie daran.

Also in der Zeile, wo du das if drumrum gebaut hast:

if (my @sockets = $select->can_read(0.1)) {
mal die zehnfache Wartezeit (oder gerne auch mal mehr probieren)...

Alternativ kannst du auch mal aus der folgenden While-Schleife für die Verarbeitung ein if machen. Dann wird pro Zyklus nur noch ein Element verarbeitet...

Da habe ich gerade leider keine Zielführende, direkte Idee...

Grüße
Reiner

Nobby1805

Hallo Reiner,

wenn ich mich recht erinnere haben wir vor ca. 1 Jahr ebenfalls Probleme im Umfeld der Main-/Sub-Prozess-Kommunikation diskutiert und dabei komisches Verhalten im Umfeld von can_read festgestellt ... letztlich hat das dann dazu geführt, dass du die Synchronisation zwischen Main und Sub umgebaut hast.

Seitdem funktioniert bei mir alles wunderbar, die "too old" Meldung taucht bei mir sehr, sehr selten mal auf ... hat dann aber keine negativen Auswirkungen.

Ich hatte immer den Eindruck, dass zwischen den Ergebnissen von can_read und dem Lesen etwas nicht stimmt, aber da haben wir ja letztlich nichts genaues finden können weil das Problem nicht gezielt reproduzierbar war ... wenn das bei Kalle jetzt 100% reproduzierbar ist dann könnte man doch noch zusätzliche Logs direkt beim can_read/dequeue einbauen

Gruß Nobby
FHEM-Featurelevel: 6.2   (fhem.pl:28227/2023-11-29) auf Windows 10 Pro mit Strawberry Perl 5.32.1.1-32bit
TabletUI: 2.7.15
IO: 2xHMLAN(0.965)|HMUSB2(0.967)

Reinerlein

Hi Nobby,

genau, und deswegen ist der Bereich auch sehr übersichtlich:

while (!$SONOS_RestartControlPoint) {
# UPnP-Sockets abfragen...
if (my @sockets = $select->can_read(0.01)) {
for my $sock (@sockets) {
$SONOS_Controlpoint->handleOnce($sock);
}
}

# Befehlsqueue abfragen...
while ($SONOS_Client_ReceiveQueue->pending()) {
SONOS_Discover_DoQueue($SONOS_Client_ReceiveQueue->dequeue());
}
}

Er kommt hier irgendwann nicht mehr dazu, die Queue auf pending zu überprüfen, bzw. das DoQueue auszuführen.
Man könnte noch eine Logausgabe dazwischen einbauen (bei dem Kommentar "Befehlsqueue abfragen"). Das wird aber seeeehhhhr lang, da der Thread ja mehrmals pro Sekunde da vorbeikommen sollte...
Dann könnte man erkennen, ob es an der Überprüfung von pending() liegt, oder ob er gar nicht mehr aus dem can_read() herauskommt...
Letzteres glaube ich aber eher nicht, da er ja sauber den Prozess beenden kann, was ja über die äußerste While-Schleife erfolgt (allerdings durch Aufrufen eines Sig-INTs, was ja can_read auch beendet).

Wenn es also Probleme mit dem pending geben sollte... da habe ich mir schon die Augen wundgegoogelt, und nichts zu gefunden.
Wenn can_read nicht mehr aus dem timeout wiederkommt, weiß ich auch nicht, wie das sein kann...

Echt schwierig ???

Grüße
Reiner

Nobby1805

Zitat von: Reinerlein am 15 Januar 2018, 18:26:35
Man könnte noch eine Logausgabe dazwischen einbauen (bei dem Kommentar "Befehlsqueue abfragen"). Das wird aber seeeehhhhr lang, da der Thread ja mehrmals pro Sekunde da vorbeikommen sollte...
Wenn Kalle die Wartezeit auf 1 Sekunden oder sogar 5 Sekunden erhöht und der Fehler dann bei ihm immer noch gut reproduzierbar auftritt, dann sollte die Größe des Logs doch im noch vertretbaren Rahmen liegen. Ich hatte allerdings immer so ein Bauchgefühl als ob das Problem etwas mit der for-Schleife über die sockets zu tun hat

Gruß Nobby
FHEM-Featurelevel: 6.2   (fhem.pl:28227/2023-11-29) auf Windows 10 Pro mit Strawberry Perl 5.32.1.1-32bit
TabletUI: 2.7.15
IO: 2xHMLAN(0.965)|HMUSB2(0.967)

KalleBlomquist

Hallo,

OK wir können gerne testen ...
Was schlagt ihr vor soll ich anpassen ?

Gruß Kalle



Nobby1805

Ohne Reiner jetzt vorzugreifen kann ich ja mal einen Vorschlag machen ...

while (!$SONOS_RestartControlPoint) {
# UPnP-Sockets abfragen...
if (my @sockets = $select->can_read(1.0)) {                                       ## nicht zu häufig
for my $sock (@sockets) {
                SONOS_Log undef, 5, "Angekommen vor handleOnce...";      ## es gibt also etwas zum Lesen
$SONOS_Controlpoint->handleOnce($sock);
}
}

# Befehlsqueue abfragen...
        SONOS_Log undef, 5, "Angekommen vor pending...";                            ## dann sollte auch etwas pending sein             
while ($SONOS_Client_ReceiveQueue->pending()) {
SONOS_Discover_DoQueue($SONOS_Client_ReceiveQueue->dequeue());
        SONOS_Log undef, 5, "Angekommen nach dequeue...";                 ## und das Gelesene istb earbeitet
}
}

Die 4 Änderungen habe ich mit ## kommentiert ...
Um nicht zu viel Logs zu erzeugen wird das Timeout auf 1 Sekunde gesetzt ... mit der Hoffnung, dass das Problem dann trotzdem noch auftritt, normale Bearbeitungen können etwas verzögert werden
FHEM-Featurelevel: 6.2   (fhem.pl:28227/2023-11-29) auf Windows 10 Pro mit Strawberry Perl 5.32.1.1-32bit
TabletUI: 2.7.15
IO: 2xHMLAN(0.965)|HMUSB2(0.967)

KalleBlomquist

Hallo Nobby,

ich habe die Änderungen eingefügt und es gab wieder den Shutdown (das wollten wir ja  :D)
Die Logfiles im Anhang.

DANKE EUCH !!!

VG
Kalle

P.S.: "$SONOS_Client_ReceiveQueue" ist in meinem Modul "$SONOS_ComObjectTransportQueue"  ?!
Habe ich nicht das aktuelle Modul ?

Nobby1805

Bist du sic her, dass du es genau so eingebaut hast wie ich es vorgeschlagen habe?

eine dequeue-Logeintrga finde ich gar nicht :(

eine Sequenz 2018.01.17 10:14:34 5: SONOS1: Angekommen vor pending...
2018.01.17 10:14:34 5: SONOS1: Angekommen vor handleOnce...
2018.01.17 10:14:34 5: SONOS1: Angekommen vor pending...
2018.01.17 10:14:34 5: SONOS1: Angekommen vor handleOnce...
2018.01.17 10:14:34 5: SONOS1: Angekommen vor pending...
2018.01.17 10:14:34 5: SONOS1: Angekommen vor handleOnce...

zeigt, dass can_read immer sofort "fertig" war ... also kein Timeout passiert ist ... also immer etwas zum Lesen an stand

Irgendetwas passt da nicht ... ich verstehe aber leider nicht was da nicht passiert :(

FHEM-Featurelevel: 6.2   (fhem.pl:28227/2023-11-29) auf Windows 10 Pro mit Strawberry Perl 5.32.1.1-32bit
TabletUI: 2.7.15
IO: 2xHMLAN(0.965)|HMUSB2(0.967)

nils_

Zitat von: Nobby1805 am 16 Januar 2018, 13:15:57

if (my @sockets = $select->can_read(1.0)) {  ## nicht zu häufig
...
}

...
Um nicht zu viel Logs zu erzeugen wird das Timeout auf 1 Sekunde gesetzt ... mit der Hoffnung, dass das Problem dann trotzdem noch auftritt, normale Bearbeitungen können etwas verzögert werden

dazu habe das hier gefunden: http://www.perlmonks.org/bare/?node_id=427056
nicht das evtl. andere signale stören?!

ansonsten lese ich nur mit :)
viele Wege in FHEM es gibt!

KalleBlomquist

#39
Hi,

Zitat von: Nobby1805 am 17 Januar 2018, 11:33:26
Bist du sicher, dass du es genau so eingebaut hast wie ich es vorgeschlagen habe?

Hier ist der Code wie ich ihn eingefügt habe:

while (!$SONOS_RestartControlPoint) {
# UPnP-Sockets abfragen...
if (my @sockets = $select->can_read(1.0)) {
for my $sock (@sockets) {
SONOS_Log undef, 5, "Angekommen vor handleOnce...";
$SONOS_Controlpoint->handleOnce($sock);
}
}
# Befehlsqueue abfragen...
SONOS_Log undef, 5, "Angekommen vor pending...";
while ($SONOS_ComObjectTransportQueue->pending()) {
SONOS_Discover_DoQueue($SONOS_ComObjectTransportQueue->dequeue());
SONOS_Log undef, 5, "Angekommen nach dequeue...";
}
}


Gruß
Kalle


KalleBlomquist

Hab nochmal ein Log (Sonos_SubProcess.log) gezogen, FHEM neu gestartet und wieder ein Log (Sonos_SubProcess_2.log) gezogen ...

bis dann im FHEM-Log erscheint: "SONOS0: LastProcessAnswer way too old (Lastanswer: 1516199200.16529 ~ 2018-01-17 15:26:40)... try to restart the process and connection..."





nils_

Zitat von: KalleBlomquist am 17 Januar 2018, 10:23:06
P.S.: "$SONOS_Client_ReceiveQueue" ist in meinem Modul "$SONOS_ComObjectTransportQueue"  ?!
Habe ich nicht das aktuelle Modul ?

du hast die aus dem svn...
https://svn.fhem.de/trac/browser/trunk/fhem/FHEM/00_SONOS.pm#L2402


hat reiner evtl. eine neue in dem thread gepostet??
viele Wege in FHEM es gibt!

KalleBlomquist

Mir ist gerade aufgefallen, dass die Sonos über FHEM auch nicht mehr ansteuerbar sind, z.B. "set Sonos_xxx Volume 25" wird nicht angenommen, obwohl das Device appeared zeigt.

Irgendwas ist komisch ...

@Nils_
Kannst Du mir bitte mal Deine Version zur Verfügung stellen, dann würde ich die mal einbinden und testen.

nils_

Zitat von: KalleBlomquist am 17 Januar 2018, 16:23:26
@Nils_
Kannst Du mir bitte mal Deine Version zur Verfügung stellen, dann würde ich die mal einbinden und testen.

sorry, ich hab leider auch keine hier.

also laut https://forum.fhem.de/index.php/topic,82390.msg744642.html
ist die aktuelle von ihm wohl im svn  ::)
viele Wege in FHEM es gibt!

Nobby1805

#44
@Kalle: der Code sieht OK aus ... und jetzt findet man im Log sogar einen dequeue-Eintrag ... aber ich verstehe immer noch nicht was da passiert

@Nils: den Monk-Artikel kannte ich ... und ich meine Reiner und ich haben den vor ca. 1 Jahr auch diskutiert ... aber geholfen hat das auch nicht :(

Edit: kann es am Eval liegen, dass dequeue so selten im Log erscheint? Es passiert ein Fehler im SONOS_Discover_DoQueue und der Ablauf wird hinter dem Eval-Block fortgesetzt?
FHEM-Featurelevel: 6.2   (fhem.pl:28227/2023-11-29) auf Windows 10 Pro mit Strawberry Perl 5.32.1.1-32bit
TabletUI: 2.7.15
IO: 2xHMLAN(0.965)|HMUSB2(0.967)