Sonos Player disappeared

[juemuc]

Alle SONOS-Geräte sind mit allen Methoden reachable, unbekanntes Gerät ist not reachable

Kann ich bestätigen 

Viele Grüße
Jürgen

[mumpitzstuff]

Ich habe bei mir im SONOS-Modul zusätzliche Loggings eingebaut, z.B. wird die Zeit ausgegeben, die zwischen den Keep-Alives abgelaufen ist Da ist mir dann aufgefallen, dass wenn ein SONOS-Gerät abgeschaltet ist folgende Ausgabe alle 30 Minuten kommtund bei 240 Sekunden wäre dann die Meldung "... way too old ..." gekommen und Sonos hätte sich aufgehängt. Was passiert dort alle 30 Minuten?

Es wird ein RenewSubscription durchgeführt, das sind bei den bei mir vorhandenen Geräten zwischen 2 und 9 einzelne Renews für die jeweils ein Timeout von 20 Sekunden eingestellt ist und die Keepalives hängen in der Bearbeitungsqueue hinter den Renews und werden dadurch verzögert.

Was ich jetzt nicht verstehe ist, warum in SONOS_ProcessRenew der Timeout-Fall nicht erkannt wird und der Player nicht entfernt wird (obwohl das, soweit ich die Kommentare dort verstehe, passieren sollte)?

Also soweit ich das bisher sehen konnte, wird in dem Reading LastProcessAnswer festgehalten, wann as letzte Mal erfolgreich kommuniziert werden konnte und zwar nicht mit einem Player (wenn ich das richtig verstanden habe), sondrn mit einem anderen Prozess. In der Funktion SONOS_IsSubprocessAliveChecker() wird dann folgende Überprüfung gemacht:

Code Auswählen Erweitern

  # Wenn die letzte Antwort zu lange her ist, dann den SubProzess neustarten...
  if (($lastProcessAnswer != 0) && ($lastProcessAnswer < time() - (4 * $hash->{INTERVAL}))) {

Hier steckt genau die 4 x 60 = 240s drin. Danach wird der Subprocess gestoppt und neu gestartet. Genau diesen Punkt hoffe ich bereits gefixt zu haben, denn in der originalen Version wurde hier der Prozess lediglich abgeschossen, konnte aber nicht neu gestartet werden. Die Renews hängen höchstwahrscheinlich mit dem Neustart des Subprocess zusammen.

Wenn ich jetzt richtig verstanden habe ist deine Frage außerdem, weshalb SONOS nicht bei einem Renew eines ausgeschalteten Players nach disappeared wechselt. Wenn ich den Code überfliege, war das wohl eigentlich auch so gedacht. Die ControlPoint.pm müsste in diesem Fall eigentlich eine Logmessage hinterlassen:

Code Auswählen Erweitern

"Renewal of subscription failed with error: ..."

Und dann sollte der Player als disappeared angezeigt werden. Irgendwas wie das Folgende sollte dann im Logfile auftauchen (nur ab Verbose 3!):

Code Auswählen Erweitern

SONOS_Log $udn, 3, 'Error! '.$subscriptionName.'-Subscription for ZonePlayer "'.$udn.'" has expired and could not be renewed: '.$@;

Falls der Mechanismus nicht funktioniert, sollte für den betreffenden Player sowas im Logfile auftauchen:

Code Auswählen Erweitern

SONOS_Log $udn, 3, $subscriptionName.'-Subscription for ZonePlayer "'.$udn.'" has expired and is now renewed.';

Kannst du bitte das beschriebene Verhalten noch einmal mit Verbose 3 nachstellen und ausschau nach diesen Meldungen im Logfile halten? Ich hätte gern gewusst an welcher Stelle etwas nicht funktioniert. Meldet die ControlPoint was falsches, oder funktioniert die Logik im SONOS Modul an der Stelle nicht oder aber der Player wird aus disappeared gesetzt, aber irgendwas anderes setzt den Status zurück.

PS: Du wolltest auch wissen was alle halbe Stunde passiert. Alle halbe Stunde wird ein SONOS_ProcessRenew() ausgelöst, falls alle Player vorhanden sind. Falls irgendwo Probleme auftreten, wird das vermutlich öfter stattfinden, weil dann teilweise Prozesse abgeschossen und neu gestartet werden.

[mumpitzstuff]

Die Erkenntnise zu den Pings habe ich inzwischen eingebaut. Die neue Version liegt im Github:

Code Auswählen Erweitern

https://github.com/mumpitzstuff/fhem-SONOS

[det.]

Bist ein Held! Soeben Update gemacht am Pc, dabei über den angeschlossenen ZP Musik gehört, PC abgeschaltet, am iPad nachgesehen - ZP ist disabled. Das gab es so noch nie! Danke!!!

Auch nach den eben gemachten SONOS App und Systemupdates nach dem heutigen Stand (S1) - gehen alle eingeschalteten Player sofort auf appeared und nach ausschalten auf disappeared

[87insane]

Bin gespannt. Kann leider erst später testen aber es lässt sich ja in wenigen Minuten testen ob es geht.

Gesendet von meinem LM-G810 mit Tapatalk

[Nobby1805]

Hallo mumpitzstuff,

im Prinzip sehe ich es genau so ... den Grund für das Verhalten alle 30 Minuten hatte ich ja ausch schon erwähnt 

Die Meldung

"Renewal of subscription failed with error: ..."

aus dem ControlPoint kommt nicht, und genau das ist es, was ich nicht verstehe!

Folglich kommt

SONOS_Log $udn, 3, 'Error! '.$subscriptionName.'-Subscription for ZonePlayer "'.$udn.'" has expired and could not be renewed: '.$@;

auch nicht und der Player geht nicht auf disappeared

Gruß Nobby

PS Ich habe den Verbose-Level der Meldungen im SONOS_ProcessRenew() auf 2 (statt 3) gesetzt um nicht alle sonstigen Meldungen auf Level 3 zu bekommen ...

[mumpitzstuff]

Hallo mumpitzstuff,

im Prinzip sehe ich es genau so ... den Grund für das Verhalten alle 30 Minuten hatte ich ja ausch schon erwähnt 

Die Meldung  aus dem ControlPoint kommt nicht, und genau das ist es, was ich nicht verstehe!

Folglich kommt  auch nicht und der Player geht nicht auf disappeared

Gruß Nobby

PS Ich habe den Verbose-Level der Meldungen im SONOS_ProcessRenew() auf 2 (statt 3) gesetzt um nicht alle sonstigen Meldungen auf Level 3 zu bekommen ...

Könntest du bitte mal die in der ControlPoint die renew Funktion durch folgendes ersetzen und mir dann die Ausgabe des abgeschalteten Gerätes geben?

Code Auswählen Erweitern

sub renew {
my $self = shift;
my $timeout = shift;

my $url = $self->{_eventSubURL};
my $request = HTTP::Request->new('SUBSCRIBE',
"$url");
$request->header('SID', $self->{_sid});
$request->header('Timeout',
'Second-' . defined($timeout) ? $timeout : 'infinite');

my $ua = LWP::UserAgent->new(timeout => 20);
my $response = $ua->request($request);

carp("response code: " . $response->code . "\n" .
         "response message: " . $response->message . "\n" .
         "response error: " . $response->is_error . "\n" .
         "response success: " . $response->is_success . "\n" .
         "response header: " . $response->headers_as_string . "\n");
   
    if ($response->is_success) {
$timeout = $response->header('Timeout');
if ($timeout =~ /^Second-(\d+)$/) {
$timeout = $1;
}

$self->{_timeout} = $timeout;
$self->{_startTime} = Time::HiRes::time();
}
else {
carp("Renewal of subscription failed with error: " .
$response->code . " " . $response->message);
}

return $self;
}

Ich hoffe damit sehe ich mal, was da wirklich zurück kommt. Zum Vergleich vielleicht auch mal den Gut Fall mitschicken, damit ich direkt den Unterschied sehen kann. Vielen Dank.

PS: Ich habe gesehen das in dem ControlPoint Modul mehrfach mit einem Timeout von 20s gearbeitet wird. Unter anderem bei Subscribe und Unsubscribe. Das könnte irgendwie ungesund sein, bei einem ausgeschaltetem Device. Warum man ein derart langes Timeout benötigt ist mir noch schleierhaft.

PSS: Habe auch noch folgendes gefunden, was wahrscheinlich die Ursache ist:

When a request times out, a response object is still returned. The response will have a standard HTTP Status Code (500). This response will have the "Client-Warning" header set to the value of "Internal response".

PSSS: Ich habe mal einen Versuch dran gehangen das zu beheben. Das ist aber ein Schuss ins Blaue. DIe anderen Infos wären trotzdem sehr hilfreich. Bei dieser Version wurde das Timeout bei subscribe, unsubscribe und renew von 20s auf 5s reduziert und bei renew hoffentlich das Problem abgefangen.

[Nobby1805]

Könntest du bitte mal die in der ControlPoint die renew Funktion durch folgendes ersetzen und mir dann die Ausgabe des abgeschalteten Gerätes geben?
...
Das ist aber ein Schuss ins Blaue. DIe anderen Infos wären trotzdem sehr hilfreich.

Ich habe es eingebaut, aber wo finde ich denn die von carp ausgegebenen Werte?

Ich habe jetzt die Fehlerabfrage etwas verändert und messe die Laufzeit des renew(). Wenn diese größer als 10 Sekunden ist behandele ich das wie eine Fehlerrückmeldung.

Ergebnis: Player geht sofort auf disappeared

[mumpitzstuff]

Hmm das nützt mir alles nix. Ich brauche den Errorcode. Die Meldungen sollten eigentlich im Logfile auftauchen.

Code Auswählen Erweitern

sub renew {
my $self = shift;
my $timeout = shift;

my $url = $self->{_eventSubURL};
my $request = HTTP::Request->new('SUBSCRIBE',
"$url");
$request->header('SID', $self->{_sid});
$request->header('Timeout',
'Second-' . defined($timeout) ? $timeout : 'infinite');

my $ua = LWP::UserAgent->new(timeout => 20);
my $response = $ua->request($request);

croak("response code: " . $response->code . "\n" .
         "response message: " . $response->message . "\n" .
         "response error: " . $response->is_error . "\n" .
         "response success: " . $response->is_success . "\n" .
         "response header: " . $response->headers_as_string . "\n");
   
    if ($response->is_success) {
$timeout = $response->header('Timeout');
if ($timeout =~ /^Second-(\d+)$/) {
$timeout = $1;
}

$self->{_timeout} = $timeout;
$self->{_startTime} = Time::HiRes::time();
}
else {
croak("Renewal of subscription failed with error: " .
$response->code . " " . $response->message);
}

return $self;
}

Kannst du es bitte damit versuchen? Ich habe carp durch croak ersetzt.

[mumpitzstuff]

Wenn damit auch nix im Logfile auftaucht, dann benutz mal bitte die ControlPoint aus Post #231. Hier habe ich den Zusatz eingebaut, der bereits in subscribe verwendet wird. Der sollte ja bei renew genauso funktionieren. Hier wird nämlich anders als bei renew auf 200 als code abgefragt und ansonsten ein Fehler zurück gegeben.

[Nobby1805]

OK, ich teste jetzt erst einmal croak

Irgendwie habe ich im Hinterkopf irgendwo mal gelesen zu haben, dass FHEM eine Spezialbehandlung von Carp und Croak eingebaut hat ?

Edit: schau dir mal den Kommentar in Zeile 182 ff von 00_SONOS an ... kann das etwas mit dem fehlenden Logging zu tun  haben?

[Nobby1805]

So, ich habe jetzt etwas ...

Code Auswählen Erweitern

response code: 200
response message: OK
response error:
response success: 1
response header: Connection: close
Server: Linux UPnP/1.0 Sonos/57.3-77280 (ZPS1)
Client-Date: Mon, 08 Jun 2020 20:46:33 GMT
Client-Peer: 192.168.1.55:1400
Client-Response-Num: 1
SID: uuid:RINCON_000E58C1DE0A01400_sub0000000061
TIMEOUT: Second-86400

jetzt schalte ich einen Player mal aus ...

Edit: Player ist aus

Code Auswählen Erweitern

response code: 500
response message: Can't connect to 192.168.1.56:1400
response error: 1
response success:
response header: Content-Type: text/plain
Client-Date: Mon, 08 Jun 2020 21:16:54 GMT
Client-Warning: Internal response

[mumpitzstuff]

Ahh super. 200 kommt im Gutfall zurück und 500 wird kommen wenn der request in den Timeout läuft. Dann sollte die oben angehangene ControlPoint funktionieren.

[mumpitzstuff]

Hmm komisch ist aber das bei success eigentlich nichts drin steht und die ControlPoint dann auch in den Fehlerfall rein laufen sollte. Ich muss noch mal nachdenken...

[mumpitzstuff]

Okay die renew Funktion gibt nur carp zurück, aber hier greift dann die eval catch Funktion im SONOS Modul nicht und der entsprechende Codeteil weird nicht ausgeführt. Im Fehlerfall muss ich jetzt einfach croak verwenden, dann wird auch im SONOS Modul das Richtige aufgerufen. Ich probiere es mal.

PS: Danke für den Hinweis im SONOS Modul, das hat meinen Verdacht bestätigt.