SONOS-Subprocess geht in den Endlos-Loop

[Nobby1805]

Hallo,

seit einiger Zeit habe ich das Problem, dass der SONOS-Subprocess in einen Endlos-Loop geht, der einen Processor-Kern vollständig auslastet. Fhem bekommt dann auch keine Änderungen durch die Sonos-App mehr mit und Kommandos Von Fhem/Sonos erreichen die Sonos-Player nicht. Wenn man dann Sonos im Fhem neu startet, dann funktioniert alles wieder für eine gewisse Zeit und dann passiert es wieder. Ich habe aber bisher noch nicht feststellen können, wann und warum er in diesen Loop geht.

Ich habe dann verbose für Sonos hoch gesetzt, inzwischen bin ich bei 5. Das Modul m Haupt-Prozess bekommt das sofort mit, aber der Sub nicht. Der verwendet das neue verbose erst nach dem nächsten Restart.

Seit verbose 5 ist kommt in Log (Hauptprozess) im Minutenabstand

Code Auswählen Erweitern

2021.01.31 16:25:33.589 5: SONOS0: Long time, no hear from SubProcess... sending ping-request
2021.01.31 16:25:33.589 5: SW: DoWork:undef:refreshProcessAnswer:

2021.01.31 16:26:33.620 5: SONOS0: Long time, no hear from SubProcess... sending ping-request
2021.01.31 16:26:33.621 5: SW: DoWork:undef:refreshProcessAnswer:

Im Log des Subprozesse kommt bereits seit verbose = 3 ebenfalls etwa jede Minute

Code Auswählen Erweitern

2021.01.31 16:32:25.460 4: SONOS3: ╓── IsAlive-Event-Anfang UDN=RINCON_000E58A376D201400_MR
2021.01.31 16:32:25.462 4: SONOS3: ║ 192.168.1.102 is alive
2021.01.31 16:32:25.464 4: SONOS3: ╙── IsAlive-Event-Ende UDN=RINCON_000E58A376D201400_MR
2021.01.31 16:32:25.465 4: SONOS3: ╓── IsAlive-Event-Anfang UDN=RINCON_000E58C1DE0A01400_MR
2021.01.31 16:32:25.471 4: SONOS3: ║ 192.168.1.104 is alive
2021.01.31 16:32:25.472 4: SONOS3: ╙── IsAlive-Event-Ende UDN=RINCON_000E58C1DE0A01400_MR
2021.01.31 16:32:25.474 4: SONOS3: ╓── IsAlive-Event-Anfang UDN=RINCON_7828CA255F0A01400_MR
2021.01.31 16:32:25.480 4: SONOS3: ║ 192.168.1.105 is alive
2021.01.31 16:32:25.482 4: SONOS3: ╙── IsAlive-Event-Ende UDN=RINCON_7828CA255F0A01400_MR
2021.01.31 16:32:25.483 4: SONOS3: ╓── IsAlive-Event-Anfang UDN=RINCON_000E58E3988A01400_MR
2021.01.31 16:32:25.488 4: SONOS3: ║ 192.168.1.101 is alive
2021.01.31 16:32:25.490 4: SONOS3: ╙── IsAlive-Event-Ende UDN=RINCON_000E58E3988A01400_MR
Die letzten anderslautenden Einträge kamen heute Morgen um 3:56 und ich vermute, seitdem loopt der Subprocess

Code Auswählen Erweitern

2021.01.31 03:56:00.966 4: SONOS1: SONOS_Client_Notifier(PropagateTitleInformationsToSlaves:Sonos_Schlafzimmer)
2021.01.31 03:56:00.968 3: SONOS1: Event: End of Transport-Event for Zone "Sonos_Schlafzimmer".
2021.01.31 03:56:00.970 4: SONOS1: ProxyObject exists: UPnP::ControlPoint::ControlProxy=HASH(0x67a679c)
2021.01.31 03:56:00.971 4: SONOS1: ProxyObject exists: UPnP::ControlPoint::ControlProxy=HASH(0x67a679c)


Idealerweise sagt jetzt jemand: kenne ich, liegt an ... 
Aber ich freue mich schon über jeden Tipp, wie man das Problem weiter einkreisen könnte

Gruß Nobby

PS jetzt werde ich mal mit verbose 5 den Restart machen ... wird dann ein etwas größerer Logfile

[Nobby1805]

Jetzt hat es nicht lange gedauert bis der Subprocess wieder loopt

Ich habe nach dem Restart erst ein Start Kommando und dann eine Pause an einen Player geschickt ... das hat beim Player auch funktioniert, aber anscheinend hat er sich unmittelbar danach verabschiedet

jetzt mit verbose 5 gibt es etwas mehr logging

Code Auswählen Erweitern

2021.01.31 17:10:17.530 5: SW: DoWork:RINCON_000E58A376D201400_MR:pause:

2021.01.31 17:10:18.326 4: SONOS0: ReadingsBeginUpdate from Module for "Sonos_Wohnzimmer"
2021.01.31 17:10:18.347 4: SONOS0: ReadingsEndUpdate from Module for "Sonos_Wohnzimmer"
2021.01.31 17:10:19.357 4: SONOS0: ReadingsBeginUpdate from Module for "Sonos_Wohnzimmer"
2021.01.31 17:10:19.379 4: SONOS0: ReadingsEndUpdate from Module for "Sonos_Wohnzimmer"
2021.01.31 17:10:20.388 4: SONOS0: ReadingsBeginUpdate from Module for "Sonos_Wohnzimmer"
2021.01.31 17:10:20.411 4: SONOS0: ReadingsEndUpdate from Module for "Sonos_Wohnzimmer"
...
2021.01.31 17:11:14.107 4: SONOS0: ReadingsBeginUpdate from Module for "Sonos_Wohnzimmer"
2021.01.31 17:11:14.127 4: SONOS0: ReadingsEndUpdate from Module for "Sonos_Wohnzimmer"
2021.01.31 17:11:15.122 5: SONOS0: Long time, no hear from SubProcess... sending ping-request
2021.01.31 17:11:15.123 5: SW: DoWork:undef:refreshProcessAnswer:

2021.01.31 17:11:15.138 4: SONOS0: ReadingsBeginUpdate from Module for "Sonos_Wohnzimmer"
2021.01.31 17:11:15.159 4: SONOS0: ReadingsEndUpdate from Module for "Sonos_Wohnzimmer"
im Sekundenrhythmus ein Readings-Update und alle Minute das "Long time no hear ..."

Code Auswählen Erweitern

2021.01.31 17:10:17.528 5: SONOS0: Received: 'DoWork:RINCON_000E58A376D201400_MR:pause:'
2021.01.31 17:10:48.012 4: SONOS3: ╓── IsAlive-Event-Anfang UDN=RINCON_000E58A376D201400_MR
2021.01.31 17:10:48.012 5: SONOS3: SONOS_Client_Data_Retreive(RINCON_000E58A376D201400_MR, reading, location, ) -> http://192.168.1.102:1400/xml/device_description.xml
2021.01.31 17:10:48.014 5: SONOS3: ║ Location: http://192.168.1.102:1400/xml/device_description.xml
2021.01.31 17:10:48.015 5: SONOS3: ║ PingType: syn
2021.01.31 17:10:48.018 5: SONOS3: ║ IsAlive: After Ping->new
2021.01.31 17:10:48.019 5: SONOS3: ║ IsAlive: After Ping->source_verify
2021.01.31 17:10:48.020 5: SONOS3: ║ IsAlive: After Ping->service_check
2021.01.31 17:10:48.022 5: SONOS3: ║ IsAlive: After Ping->port_number
2021.01.31 17:10:48.024 5: SONOS3: ║ IsAlive: After Ping->ping(1) for syn
2021.01.31 17:10:48.026 4: SONOS3: ║ 192.168.1.102 is alive
2021.01.31 17:10:48.027 5: SONOS3: ║ IsAlive: After Ping->close
2021.01.31 17:10:48.028 4: SONOS3: ╙── IsAlive-Event-Ende UDN=RINCON_000E58A376D201400_MR
2021.01.31 17:10:48.029 4: SONOS3: ╓── IsAlive-Event-Anfang UDN=RINCON_000E58C1DE0A01400_MR
2021.01.31 17:10:48.030 5: SONOS3: SONOS_Client_Data_Retreive(RINCON_000E58C1DE0A01400_MR, reading, location, ) -> http://192.168.1.104:1400/xml/device_description.xml
2021.01.31 17:10:48.031 5: SONOS3: ║ Location: http://192.168.1.104:1400/xml/device_description.xml
2021.01.31 17:10:48.033 5: SONOS3: ║ PingType: syn
2021.01.31 17:10:48.035 5: SONOS3: ║ IsAlive: After Ping->new
2021.01.31 17:10:48.036 5: SONOS3: ║ IsAlive: After Ping->source_verify
2021.01.31 17:10:48.038 5: SONOS3: ║ IsAlive: After Ping->service_check
2021.01.31 17:10:48.039 5: SONOS3: ║ IsAlive: After Ping->port_number
2021.01.31 17:10:48.041 5: SONOS3: ║ IsAlive: After Ping->ping(1) for syn
2021.01.31 17:10:48.047 4: SONOS3: ║ 192.168.1.104 is alive
2021.01.31 17:10:48.049 5: SONOS3: ║ IsAlive: After Ping->close
2021.01.31 17:10:48.050 4: SONOS3: ╙── IsAlive-Event-Ende UDN=RINCON_000E58C1DE0A01400_MR
2021.01.31 17:11:15.122 5: SONOS0: Received: 'DoWork:undef:refreshProcessAnswer:'
Etwas mehr logging, wie gehabt im Minutenrhytmus IsAlive .. aber jetzt nur für die IP .102 und .104 und nicht wie vor dem letzten Restart für .101, .102, .104 und .105

Jetzt eben ist mir noch folgendes aufgefallen, das erklärt die ReadingsUpdates

Code Auswählen Erweitern


currentTrackPositionSimulated              1:53:55             2021-01-31 19:02:54
currentTrackPositionSimulatedPercent        3193.9             2021-01-31 19:02:54
currentTrackPositionSimulatedSec              6835             2021-01-31 19:02:54


ihr seht mich ratlos ...

[tfriedrich85]

Ich habe genau das gleiche Problem ca. 5 Tage nach dem Neustart.
Finde ich folgendes im Log

Code Auswählen Erweitern

2021.06.14 22:36:50 5: SW: DoWork:undef:refreshProcessAnswer:
2021.06.14 22:36:50 5: SONOS0: Long time, no hear from SubProcess... sending ping-request

Man kann nicht mehr mit Sonos interagieren und Ein Fhem neustart behebt das ganze....

[Nobby1805]

kurze Antwort von mir als "Thread-Ersteller"

Bei mir läuft im Moment alles normal ... was habe ich geändert? Fhem läuft jetzt unter Windows 10 auf einem schnelleren Rechner ... aber ob es daran liegt?