UPNPController, DLNAController und Multiroom

[KölnSolar]

Hallo Michael,

Ich verstehe aber nicht, warum man von fhem nicht muten kann, da vom UPnP-Tester es ja nachweislich mehrfach (quasi immer) funktioniert.

Verstehe ich auch nicht. FHEM(das Modul) kann da nicht Schuld sein. Ich kann mir nur unterschiedliche Ausgangssituationen vorstellen(Peter kann z.B. bei einem device nur mute, volume ändern, während ein stream abgespielt wird.) Oder die auslösende Hardware ?  Aber was sollte da ein solches Detail verhindern ? 

Und mit dem Mediaplayer kannst Du FHEM prüfen. Dann wirst Du die Unsicherheit los, es könne an FHEM liegen. 

In welchen Situationen hattest Du eigentlich bedeutende freezes ? Ich hab da ne ganze Menge neue Ansätze. Vielleicht veröffentliche ich morgen hier mal eine Zwischenversion.

Grüße Markus

[MichaelT]

Hallo nochmal,

habe mal mit tcpdump und wireshark fhem und UPnPTester verglichen:

fhem (tcpdump):

Code Auswählen Erweitern

<?xml version="1.0" encoding="UTF-8"?>
<soap:Envelope soap:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/" xmlns:namesp65="u" xmlns:namesp66="urn:schemas-upnp-org:service:RenderingControl:3" xmlns:soap="http://schemas.xmlsoap.org/soap/envelope/" xmlns:soapenc="http://schemas.xmlsoap.org/soap/encoding/" xmlns:xsd="http://www.w3.org/2001/XMLSchema" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance">
  <soap:Body>
    <namesp66:SetMute>
      <InstanceID xsi:type="xsd:int">0</InstanceID>
      <Channel xsi:type="xsd:string">Master</Channel>
      <DesiredMute xsi:type="xsd:boolean">true</DesiredMute>
    </namesp66:SetMute>
  </soap:Body>
</soap:Envelope>

UPnPTester (wireshark):

Code Auswählen Erweitern


<SOAP-ENV:Envelope xmlns:SOAP-ENV="http://schemas.xmlsoap.org/soap/envelope/" SOAP-ENV:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/">
  <SOAP-ENV:Body>
    <m:SetMute xmlns:m="urn:schemas-upnp-org:service:RenderingControl:3">
      <InstanceID xmlns:dt="urn:schemas-microsoft-com:datatypes" dt:dt="ui4">0</InstanceID>
      <Channel xmlns:dt="urn:schemas-microsoft-com:datatypes" dt:dt="string">Master</Channel>
      <DesiredMute xmlns:dt="urn:schemas-microsoft-com:datatypes" dt:dt="boolean">1</DesiredMute>
    </m:SetMute>
  </SOAP-ENV:Body>
</SOAP-ENV:Envelope>

Auffällig ist, dass fhem ein "true" sendet und UPnPTester eine "1" bei DesiredMute.
Kommt das von den unterschiedlichen namespaces oder Datentypen?
Kannst Du das erklären?

Gruß Michael

[KölnSolar]

keine Ahnung. So tief hab ich vor Jahren rein geguckt. Und bei mute off ? Das funktionierte doch, oder ?

Wie sehen die Attribute envNamespace und envPrefix bei Dir aus ?
Für die Samsung's ist es so erforderlich

Code Auswählen Erweitern

attr UPNP_Controller envNamespace <undef>
attr UPNP_Controller envPrefix sDie hat Reinerlein damals eingeführt, weil die Befehle mit dem DLNARenderer nicht funktionierten.
Grüße Markus
Edit: Das Verhalten kommt aus dem Deserializer von SOAP:Lite. Scheinbar lassen sich verschiedene SOAP Versionen ansteuern Ich gucke...

[KölnSolar]

Hi Michael,
ohne die Attribute rufst Du SOAP so auf

Code Auswählen Erweitern

            return bless {
                    _service => $service,
                    _proxy => SOAP::Lite->envprefix("soap")
                     ->ns("u")
                     ->uri($service->serviceType)->proxy($service->controlURL),
            }, $class;
für die Samsungs so

Code Auswählen Erweitern

            return bless {
                    _service => $service,
                    _proxy => SOAP::Lite->envprefix("s")
                     ->uri($service->serviceType)->proxy($service->controlURL),
            }, $class;

Du könntest es mal mit

Code Auswählen Erweitern

attr UPNP_Controller envNamespace <undef>
attr UPNP_Controller envPrefix SOAP-ENV probieren. Ansonsten sehe ich kaum eine Chance. Vielleicht noch globale Variablen verändern. 

Grüße Markus

[MichaelT]

Hallo Markus,

mal "dreckig" getestet:

In UPnP/Common.pm den typeMap Zeile 100 auf 'boolean' => 'int' umgestellt, dann funktioniert es.
Ist natürlich die Frage, was passiert dann z.B. bei SONOS?

Code Auswählen Erweitern

<?xml version="1.0" encoding="UTF-8"?><soap:Envelope soap:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/" xmlns:namesp25="u" xmlns:namesp26="urn:schemas-upnp-org:service:RenderingControl:3" xmlns:soap="http://schemas.xmlsoap.org/soap/envelope/" xmlns:soapenc="http://schemas.xmlsoap.org/soap/encoding/" xmlns:xsd="http://www.w3.org/2001/XMLSchema" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"><soap:Body><namesp26:SetMute><InstanceID xsi:type="xsd:int">0</InstanceID><Channel xsi:type="xsd:string">Master</Channel><DesiredMute xsi:type="xsd:int">1</DesiredMute></namesp26:SetMute></soap:Body></soap:Envelope>


Edit: Deine Vorschläge von oben haben keine Lösung gebracht.

Gruß Michael

[MichaelT]

Ach so,

In welchen Situationen hattest Du eigentlich bedeutende freezes ?

Bei mir tauchen die Freezes fast immer in diesem Zusammenhang auf:

Code Auswählen Erweitern

2022.03.30 18:08:20.479 5: UPNPController: UPNPSocket-SYS_UPNP-1900, received message on port 1900 starting handleOnce
2022.03.30 18:08:20.707 4: UPNPController: discovery message of Werkstatt with UDN: uuid:93b2abac-cb6a-4857-b891-002261914054 action: deviceAdded
2022.03.30 18:08:20.708 5: UPNPController: SYS_UPNP: alive-notify message device uuid:93b2abac-cb6a-4857-b891-002261914054 received
2022.03.30 18:08:20.708 5: UPNPController: SYS_UPNP: device uuid:93b2abac-cb6a-4857-b891-002261914054 found. Check for processing
2022.03.30 18:08:20.708 5: UPNPController: SYS_UPNP: device uuid:93b2abac-cb6a-4857-b891-002261914054 will be controlled with 192.168.4.32_37123
2022.03.30 18:08:20.708 5: UPNPController: warning: main, Use of uninitialized value $value in string eq at fhem.pl line 4962.

2022.03.30 18:08:20.709 5: UPNPController: SYS_UPNP: device uuid:93b2abac-cb6a-4857-b891-002261914054 has service with serviceId: ConnectionManager
2022.03.30 18:08:20.709 5: UPNPController: SYS_UPNP: device uuid:93b2abac-cb6a-4857-b891-002261914054 has service with serviceId: AVTransport
2022.03.30 18:08:20.709 4: UPNPController: subscribe: reading  192.168.4.32_37123-zs-AVTransport, uniquedevice 192.168.4.32_37123, service AVTransport
2022.03.30 18:08:20.709 5: UPNPController: AVTransport: urn:upnp-org:serviceId:AVTransport found. OK.
--- log skips     1.008 secs.
2022.03.30 18:08:21.717 5: UPNPController: warning: Carp, Subscription request failed with error: 500 read timeout at ./FHEM/98_UPNPController.pm line 760.

2022.03.30 18:08:21.717 5: UPNPController: SYS_UPNP: checking event offline against event_map
2022.03.30 18:08:21.718 5: SYS_UPNP: dispatch AVTransport|192.168.4.32_37123|offline|urn:schemas-upnp-org:metadata-1-0/AVT
2022.03.30 18:08:21.718 4: DLNAController: message from SYS_UPNP, message: AVTransport|192.168.4.32_37123|offline|urn:schemas-upnp-org:metadata-1-0/AVT
2022.03.30 18:08:21.718 5: DLNAController: message parameters: AVTransport, 192.168.4.32_37123, offline, urn:schemas-upnp-org:metadata-1-0/AVT
2022.03.30 18:08:21.718 4: DLNAController GA_WS_MR: state update from SYS_UPNP, address 192.168.4.32_37123
2022.03.30 18:08:21.735 5: End notify loop for GA_WS_MR
2022.03.30 18:08:21.735 3: UPNPController: subscription for service AVTransport of device 192.168.4.32_37123 failed:
2022.03.30 18:08:21.735 5: UPNPController: SYS_UPNP: device uuid:93b2abac-cb6a-4857-b891-002261914054 has service with serviceId: RenderingControl
2022.03.30 18:08:21.735 4: UPNPController: subscribe: reading  192.168.4.32_37123-zs-RenderingControl, uniquedevice 192.168.4.32_37123, service RenderingControl
2022.03.30 18:08:21.736 5: UPNPController: RenderingControl: urn:upnp-org:serviceId:RenderingControl found. OK.
--- log skips     1.008 secs.
2022.03.30 18:08:22.743 5: UPNPController: warning: Carp, Subscription request failed with error: 500 read timeout at ./FHEM/98_UPNPController.pm line 760.


Ich weiß nicht, warum es dort keine Daten gibt. Passiert so 1 bis 5 mal in Folge, dann wieder gut. Ggf. liegt es aber eher an den PEAQs.
Wenn ich die timeout-Änderung in ContolPoint.pm nicht mache, habe ich Zustände in denen fhem vollständig einfriert.

[KölnSolar]

Hi Michael,

mal "dreckig" getestet:

sehr dreckig. 
Also nicht die namespaces, sondern true/false bei boolean vs. 1/0.
Ich vermute, dass es auch funktioniert, wenn in /usr/share/perl5/Lite.pm in as_boolean in package SOAP::XMLSchema2001::Serializer

Code Auswählen Erweitern

            ? 'true'
            : 'false'in

Code Auswählen Erweitern

            ? 1
            : 0geändert wird. Hab noch keine Idee, ob wir das Schema für den Serializer in Controlpoint.pm oder gar im UPNPController beeinflusst bekommen. 

Bei mir tauchen die Freezes fast immer in diesem Zusammenhang auf:

Regelmäßig, wenn sie online(physisch) sind oder nur beim Einschalten ? Und bleiben permanent offline(state DLNA) oder irgendwann dann doch online(dann hat die subscription funktioniert) ?

Grüße Markus

[MichaelT]

Hallo Markus,

Regelmäßig, wenn sie online(physisch) sind oder nur beim Einschalten ? Und bleiben permanent offline(state DLNA) oder irgendwann dann doch online(dann hat die subscription funktioniert) ?

Die Dinger gehen im laufenden Betrieb offline und dann irgendwann wieder online.

Hier mal von Gestern :

Code Auswählen Erweitern

2022.04.02 00:28:09.549 5: SYS_UPNP: dispatch AVTransport|192.168.4.32_42050|offline|urn:schemas-upnp-org:metadata-1-0/AVT
2022.04.02 00:28:09.797 5: SYS_UPNP: dispatch RenderingControl|192.168.4.32_36913|online|urn:schemas-upnp-org:metadata-1-0/RCS
2022.04.02 00:28:12.825 5: SYS_UPNP: dispatch AVTransport|192.168.4.32_36913|offline|urn:schemas-upnp-org:metadata-1-0/AVT
2022.04.02 00:28:13.851 5: SYS_UPNP: dispatch RenderingControl|192.168.4.32_36913|offline|urn:schemas-upnp-org:metadata-1-0/RCS
2022.04.02 00:28:15.433 5: SYS_UPNP: dispatch RenderingControl|192.168.4.32_36913|online|urn:schemas-upnp-org:metadata-1-0/RCS
2022.04.02 00:28:17.234 5: SYS_UPNP: dispatch RenderingControl|192.168.4.32_36913|online|urn:schemas-upnp-org:metadata-1-0/RCS
2022.04.02 02:30:25.562 5: SYS_UPNP: dispatch AVTransport|192.168.4.30_60534|offline|urn:schemas-upnp-org:metadata-1-0/AVT
2022.04.02 02:31:07.509 5: SYS_UPNP: dispatch RenderingControl|192.168.4.30_60534|online|urn:schemas-upnp-org:metadata-1-0/RCS
2022.04.02 11:13:44.256 5: SYS_UPNP: dispatch AVTransport|192.168.4.32_36913|offline|urn:schemas-upnp-org:metadata-1-0/AVT
2022.04.02 11:13:59.912 5: SYS_UPNP: dispatch RenderingControl|192.168.4.32_41790|online|urn:schemas-upnp-org:metadata-1-0/RCS
2022.04.02 11:14:01.542 5: SYS_UPNP: dispatch RenderingControl|192.168.4.32_41790|offline|urn:schemas-upnp-org:metadata-1-0/RCS
2022.04.02 11:14:06.706 5: SYS_UPNP: dispatch RenderingControl|192.168.4.32_41790|offline|urn:schemas-upnp-org:metadata-1-0/RCS
2022.04.02 11:14:06.724 5: SYS_UPNP: dispatch RenderingControl|192.168.4.32_41790|online|urn:schemas-upnp-org:metadata-1-0/RCS
2022.04.02 11:14:09.242 5: SYS_UPNP: dispatch RenderingControl|192.168.4.32_41790|offline|urn:schemas-upnp-org:metadata-1-0/RCS
2022.04.02 11:14:09.261 5: SYS_UPNP: dispatch RenderingControl|192.168.4.32_41790|online|urn:schemas-upnp-org:metadata-1-0/RCS
2022.04.02 11:14:14.604 5: SYS_UPNP: dispatch RenderingControl|192.168.4.32_41790|offline|urn:schemas-upnp-org:metadata-1-0/RCS
2022.04.02 11:14:14.619 5: SYS_UPNP: dispatch RenderingControl|192.168.4.32_41790|online|urn:schemas-upnp-org:metadata-1-0/RCS
2022.04.02 11:15:32.834 5: SYS_UPNP: dispatch RenderingControl|192.168.4.32_41790|offline|urn:schemas-upnp-org:metadata-1-0/RCS
2022.04.02 11:15:32.849 5: SYS_UPNP: dispatch RenderingControl|192.168.4.32_41790|online|urn:schemas-upnp-org:metadata-1-0/RCS
2022.04.02 11:21:38.327 5: SYS_UPNP: dispatch RenderingControl|192.168.4.32_41790|online|urn:schemas-upnp-org:metadata-1-0/RCS
2022.04.02 11:33:17.441 5: SYS_UPNP: dispatch RenderingControl|192.168.4.32_41790|offline|urn:schemas-upnp-org:metadata-1-0/RCS
2022.04.02 11:33:17.701 5: SYS_UPNP: dispatch RenderingControl|192.168.4.32_36210|online|urn:schemas-upnp-org:metadata-1-0/RCS
2022.04.02 11:33:21.553 5: SYS_UPNP: dispatch RenderingControl|192.168.4.32_36210|offline|urn:schemas-upnp-org:metadata-1-0/RCS
2022.04.02 11:33:22.186 5: SYS_UPNP: dispatch RenderingControl|192.168.4.32_36210|online|urn:schemas-upnp-org:metadata-1-0/RCS
2022.04.02 11:33:24.580 5: SYS_UPNP: dispatch RenderingControl|192.168.4.32_36210|online|urn:schemas-upnp-org:metadata-1-0/RCS



Hier mal ein Log von offline bis nach online

Code Auswählen Erweitern


2022.04.02 02:26:20.078 5: UPNPController: try to renew subscriptions for services, device SYS_UPNP
2022.04.02 02:26:20.079 5: UPNPController: renew subscription for service RenderingControl of device 192.168.4.30_60534 1648734772
2022.04.02 02:26:20.114 5: UPNPController: renew subscription for service AVTransport of device 192.168.4.30_60534 1648734772
2022.04.02 02:26:20.163 5: UPNPController: renew subscription for service SpeakerManagement of device 192.168.4.30_60534 1648734772
2022.04.02 02:26:20.198 5: UPNPController: renew subscription for service SessionManagement of device 192.168.4.30_60534 1648734772
2022.04.02 02:26:20.228 5: UPNPController: renew subscription for service AVTransport of device 192.168.4.33_40781 1648734789
2022.04.02 02:26:20.266 5: UPNPController: renew subscription for service RenderingControl of device 192.168.4.33_40781 1648734789
2022.04.02 02:26:20.300 5: UPNPController: renew subscription for service SpeakerManagement of device 192.168.4.33_40781 1648734789
2022.04.02 02:26:20.374 5: UPNPController: renew subscription for service SessionManagement of device 192.168.4.33_40781 1648734790
2022.04.02 02:26:20.412 5: UPNPController: renew subscription for service RenderingControl of device 192.168.4.31_57510 1648734808
2022.04.02 02:26:20.447 5: UPNPController: renew subscription for service AVTransport of device 192.168.4.31_57510 1648734808
2022.04.02 02:26:20.482 5: UPNPController: renew subscription for service SpeakerManagement of device 192.168.4.31_57510 1648734808
2022.04.02 02:26:20.557 5: UPNPController: renew subscription for service SessionManagement of device 192.168.4.31_57510 1648734808
2022.04.02 02:27:20.075 5: UPNPController: try to renew subscriptions for services, device SYS_UPNP
2022.04.02 02:28:20.078 5: UPNPController: try to renew subscriptions for services, device SYS_UPNP
2022.04.02 02:28:20.079 5: UPNPController: renew subscription for service RenderingControl of device 192.168.4.32_36913 1648852398
2022.04.02 02:28:20.110 5: UPNPController: renew subscription for service AVTransport of device 192.168.4.32_36913 1648852398
2022.04.02 02:28:20.141 5: UPNPController: renew subscription for service SpeakerManagement of device 192.168.4.32_36913 1648852398
2022.04.02 02:28:20.174 5: UPNPController: renew subscription for service SessionManagement of device 192.168.4.32_36913 1648852398
2022.04.02 02:29:20.074 5: UPNPController: try to renew subscriptions for services, device SYS_UPNP
2022.04.02 02:30:20.074 5: UPNPController: try to renew subscriptions for services, device SYS_UPNP
2022.04.02 02:30:20.074 5: UPNPController: renew subscription for service RenderingControl of device 192.168.4.30_60534 1648734772
2022.04.02 02:30:21.082 5: UPNPController: warning: Carp, Renewal of subscription failed with error: 500 Can't connect to 192.168.4.30:60534 (Connection timed out) at ./FHEM/98_UPNPController.pm line 834.
2022.04.02 02:30:21.083 3: UPNPController: renewal of subscription for service RenderingControl of device 192.168.4.30_60534 failed: , try to subscribe
2022.04.02 02:30:21.083 5: UPNPController: renew subscription for service AVTransport of device 192.168.4.30_60534 1648734772
2022.04.02 02:30:22.093 5: UPNPController: warning: Carp, Renewal of subscription failed with error: 500 Can't connect to 192.168.4.30:60534 (Connection timed out) at ./FHEM/98_UPNPController.pm line 834.
2022.04.02 02:30:22.094 3: UPNPController: renewal of subscription for service AVTransport of device 192.168.4.30_60534 failed: , try to subscribe
2022.04.02 02:30:22.095 5: UPNPController: renew subscription for service SpeakerManagement of device 192.168.4.30_60534 1648734772
2022.04.02 02:30:23.105 5: UPNPController: warning: Carp, Renewal of subscription failed with error: 500 Can't connect to 192.168.4.30:60534 (Connection timed out) at ./FHEM/98_UPNPController.pm line 834.
2022.04.02 02:30:23.105 3: UPNPController: renewal of subscription for service SpeakerManagement of device 192.168.4.30_60534 failed: , try to subscribe
2022.04.02 02:30:23.106 5: UPNPController: renew subscription for service SessionManagement of device 192.168.4.30_60534 1648734772
2022.04.02 02:30:24.115 5: UPNPController: warning: Carp, Renewal of subscription failed with error: 500 Can't connect to 192.168.4.30:60534 (Connection timed out) at ./FHEM/98_UPNPController.pm line 834.
2022.04.02 02:30:24.115 3: UPNPController: renewal of subscription for service SessionManagement of device 192.168.4.30_60534 failed: , try to subscribe
2022.04.02 02:30:24.116 5: UPNPController: renew subscription for service AVTransport of device 192.168.4.33_40781 1648734789
2022.04.02 02:30:24.185 5: UPNPController: renew subscription for service RenderingControl of device 192.168.4.33_40781 1648734789
2022.04.02 02:30:24.251 5: UPNPController: renew subscription for service SpeakerManagement of device 192.168.4.33_40781 1648734789
2022.04.02 02:30:24.296 5: UPNPController: renew subscription for service SessionManagement of device 192.168.4.33_40781 1648734790
2022.04.02 02:30:24.333 5: UPNPController: renew subscription for service RenderingControl of device 192.168.4.31_57510 1648734808
2022.04.02 02:30:24.371 5: UPNPController: renew subscription for service AVTransport of device 192.168.4.31_57510 1648734808
2022.04.02 02:30:24.406 5: UPNPController: renew subscription for service SpeakerManagement of device 192.168.4.31_57510 1648734808
2022.04.02 02:30:24.436 5: UPNPController: renew subscription for service SessionManagement of device 192.168.4.31_57510 1648734808
2022.04.02 02:30:24.479 5: UPNPController: renewSubscriptionsfinished name SYS_UPNP, readingname 192.168.4.30_60534-zs-SessionManagement
2022.04.02 02:30:24.495 4: UPNPController: subscribe: reading  192.168.4.30_60534-zs-SessionManagement, uniquedevice 192.168.4.30_60534, service SessionManagement
2022.04.02 02:30:24.495 5: UPNPController: SessionManagement: urn:pure-com:serviceId:SessionManagement found. OK.
2022.04.02 02:30:25.511 5: UPNPController: warning: Carp, Subscription request failed with error: 500 read timeout at ./FHEM/98_UPNPController.pm line 760.
2022.04.02 02:30:25.511 4: UPNPController: discovery message of Buero with UDN: uuid:93b2abac-cb6a-4857-b891-00226190ead6 action: deviceRemoved
2022.04.02 02:30:25.512 5: UPNPController: SYS_UPNP: byebye-notify message device 192.168.4.30_60534 received
2022.04.02 02:30:25.527 5: UPNPController: earlier subscribed service RenderingControl of device 192.168.4.30_60534 went offline
2022.04.02 02:30:25.539 5: UPNPController: earlier subscribed service AVTransport of device 192.168.4.30_60534 went offline
2022.04.02 02:30:25.550 5: UPNPController: earlier subscribed service SpeakerManagement of device 192.168.4.30_60534 went offline
2022.04.02 02:30:25.562 5: UPNPController: SYS_UPNP: checking event offline against event_map
2022.04.02 02:30:25.562 5: SYS_UPNP: dispatch AVTransport|192.168.4.30_60534|offline|urn:schemas-upnp-org:metadata-1-0/AVT
2022.04.02 02:30:25.563 4: DLNAController: message from SYS_UPNP, message: AVTransport|192.168.4.30_60534|offline|urn:schemas-upnp-org:metadata-1-0/AVT
2022.04.02 02:30:25.563 5: DLNAController: message parameters: AVTransport, 192.168.4.30_60534, offline, urn:schemas-upnp-org:metadata-1-0/AVT
2022.04.02 02:30:25.563 4: DLNAController DG_BUE_MR: state update from SYS_UPNP, address 192.168.4.30_60534
2022.04.02 02:30:25.576 5: UPNPController: SYS_UPNP: checking event offline against event_map
2022.04.02 02:30:25.576 5: UPNPController: warning: main, Use of uninitialized value $msg in index at ./FHEM/98_UPNPController.pm line 915.
2022.04.02 02:30:25.576 5: UPNPController: warning: main, Use of uninitialized value $msg in index at ./FHEM/98_UPNPController.pm line 915.
2022.04.02 02:30:25.576 3: UPNPController: SYS_UPNP: uniqueDeviceName 192.168.4.30_60534 event offline not yet implemented
2022.04.02 02:30:25.576 4: UPNPController: SYS_UPNP: uniqueDeviceName 192.168.4.30_60534 event details: $VAR1 = undef;
2022.04.02 02:30:25.577 3: UPNPController: subscription for service SessionManagement of device 192.168.4.30_60534 failed:
2022.04.02 02:31:06.446 4: UPNPController: discovery message of Buero with UDN: uuid:93b2abac-cb6a-4857-b891-00226190ead6 action: deviceAdded
2022.04.02 02:31:06.446 5: UPNPController: SYS_UPNP: alive-notify message device uuid:93b2abac-cb6a-4857-b891-00226190ead6 received
2022.04.02 02:31:06.449 5: UPNPController: SYS_UPNP: device uuid:93b2abac-cb6a-4857-b891-00226190ead6 found. Check for processing
2022.04.02 02:31:06.449 5: UPNPController: SYS_UPNP: device uuid:93b2abac-cb6a-4857-b891-00226190ead6 will be controlled with 192.168.4.30_60534
2022.04.02 02:31:06.449 5: UPNPController: warning: main, Use of uninitialized value $value in string eq at fhem.pl line 4962.
2022.04.02 02:31:06.449 5: UPNPController: SYS_UPNP: device uuid:93b2abac-cb6a-4857-b891-00226190ead6 has service with serviceId: ConnectionManager
2022.04.02 02:31:06.449 5: UPNPController: SYS_UPNP: device uuid:93b2abac-cb6a-4857-b891-00226190ead6 has service with serviceId: AVTransport
2022.04.02 02:31:06.450 4: UPNPController: subscribe: reading  192.168.4.30_60534-zs-AVTransport, uniquedevice 192.168.4.30_60534, service AVTransport
2022.04.02 02:31:06.450 5: UPNPController: AVTransport: urn:upnp-org:serviceId:AVTransport found. OK.
2022.04.02 02:31:07.043 4: UPNPController: subscribe: reading  192.168.4.30_60534-zs-AVTransport, uniquedevice 192.168.4.30_60534, service AVTransport timeout: 300
2022.04.02 02:31:07.043 5: UPNPController: SYS_UPNP: device uuid:93b2abac-cb6a-4857-b891-00226190ead6 has service with serviceId: RenderingControl
2022.04.02 02:31:07.044 4: UPNPController: subscribe: reading  192.168.4.30_60534-zs-RenderingControl, uniquedevice 192.168.4.30_60534, service RenderingControl
2022.04.02 02:31:07.045 5: UPNPController: RenderingControl: urn:upnp-org:serviceId:RenderingControl found. OK.
2022.04.02 02:31:07.324 4: UPNPController: subscribe: reading  192.168.4.30_60534-zs-RenderingControl, uniquedevice 192.168.4.30_60534, service RenderingControl timeout: 300
2022.04.02 02:31:07.325 5: UPNPController: SYS_UPNP: device uuid:93b2abac-cb6a-4857-b891-00226190ead6 has service with serviceId: RTSPGateway
2022.04.02 02:31:07.326 5: UPNPController: SYS_UPNP: device uuid:93b2abac-cb6a-4857-b891-00226190ead6 has service with serviceId: SpeakerManagement
2022.04.02 02:31:07.327 4: UPNPController: subscribe: reading  192.168.4.30_60534-zs-SpeakerManagement, uniquedevice 192.168.4.30_60534, service SpeakerManagement
2022.04.02 02:31:07.328 5: UPNPController: SpeakerManagement: urn:pure-com:serviceId:SpeakerManagement found. OK.
2022.04.02 02:31:07.444 4: UPNPController: subscribe: reading  192.168.4.30_60534-zs-SpeakerManagement, uniquedevice 192.168.4.30_60534, service SpeakerManagement timeout: 300
2022.04.02 02:31:07.445 5: UPNPController: SYS_UPNP: device uuid:93b2abac-cb6a-4857-b891-00226190ead6 has service with serviceId: NetworkManagement
2022.04.02 02:31:07.445 5: UPNPController: SYS_UPNP: device uuid:93b2abac-cb6a-4857-b891-00226190ead6 has service with serviceId: SessionManagement
2022.04.02 02:31:07.446 4: UPNPController: subscribe: reading  192.168.4.30_60534-zs-SessionManagement, uniquedevice 192.168.4.30_60534, service SessionManagement
2022.04.02 02:31:07.447 5: UPNPController: SessionManagement: urn:pure-com:serviceId:SessionManagement found. OK.
2022.04.02 02:31:07.506 4: UPNPController: subscribe: reading  192.168.4.30_60534-zs-SessionManagement, uniquedevice 192.168.4.30_60534, service SessionManagement timeout: 300
2022.04.02 02:31:07.507 5: UPNPController: SYS_UPNP: checking event online against event_map
2022.04.02 02:31:07.509 5: SYS_UPNP: dispatch RenderingControl|192.168.4.30_60534|online|urn:schemas-upnp-org:metadata-1-0/RCS
2022.04.02 02:31:07.509 4: DLNAController: message from SYS_UPNP, message: RenderingControl|192.168.4.30_60534|online|urn:schemas-upnp-org:metadata-1-0/RCS
2022.04.02 02:31:07.510 5: DLNAController: message parameters: RenderingControl, 192.168.4.30_60534, online, urn:schemas-upnp-org:metadata-1-0/RCS
2022.04.02 02:31:07.510 4: DLNAController DG_BUE_MR: state update from SYS_UPNP, address 192.168.4.30_60534


Hab noch keine Idee, ob wir das Schema für den Serializer in Controlpoint.pm oder gar im UPNPController beeinflusst bekommen.

Da kenne ich mich nicht aus.  Laut SOAP kann boolean 1, 0 oder true, false sein.

Michael

[KölnSolar]

Hi Michael,

Laut SOAP kann boolean 1, 0 oder true, false sein.

Ja, aber die peaq scheinen das nicht zu mögen.

Da kenne ich mich nicht aus.

Frag mich mal.  Das ist schon ganz schön komplex. Ich hab aber "das Gefühl", dass wir das beeinflusst bekommen. Testen ist halt blöd, weil shutdown/restart nach jeder kleinsten Änderung zu deren Aktivierung erforderlich ist.

Den freeze erkennt man gut

2022.04.02 02:30:20.074 5: UPNPController: try to renew subscriptions for services, device SYS_UPNP
2022.04.02 02:30:20.074 5: UPNPController: renew subscription for service RenderingControl of device 192.168.4.30_60534 1648734772
2022.04.02 02:30:21.082 5: UPNPController: warning: Carp, Renewal of subscription failed with error: 500 Can't connect to 192.168.4.30:60534 (Connection timed out) at ./FHEM/98_UPNPController.pm line 834.

Dann geht die "Selbstheilung" (logischerweise) in die Hose

2022.04.02 02:30:24.495 4: UPNPController: subscribe: reading  192.168.4.30_60534-zs-SessionManagement, uniquedevice 192.168.4.30_60534, service SessionManagement

und schließlich nach zig 1s freezes meldet sich das device

2022.04.02 02:31:06.446 4: UPNPController: discovery message of Buero with UDN: uuid:93b2abac-cb6a-4857-b891-00226190ead6 action: deviceAdded

Ich hab dazu schon was vorbereitet, muss aber erst noch trocken testen. Ich will non-blocking VORHER auf das device zugreifen. Schlägt das fehl, dann muss Wohl oder Übel das device in fhem offline gesetzt werden. Mal schauen wann ich Dir hier eine Testversion zur Verfügung stellen kann. Ich werde noch ein Attribut für die Dauer des timeouts einbauen müssen, damit der User für seine Installation entscheiden kann, wie lange gewartet wird, bis dieses Verhalten auch als Fehler erkannt wird. Denn je nach Netzwerk oder device gibt es vielleicht auch einfach nur lange Antwortzeiten, die natürlich nicht zu einem "offline" führen dürfen.

Grüße Markus

[KölnSolar]

Hallo Michael,
anbei die Version, die die beschriebenen freezes beheben sollten(und Du dann die Modifikation in Controlpoint.pm wieder rückgängig machen könntest).

Es gibt ein neues Attribut timeout. Default ist 1. Ansonsten kannst Du es auf jeden beliebigen Wert setzen.

Der Ablauf ist so: wenn das subscription renewal fehlschlägt, wird ja ein erneutes Subscription ausgeführt. VORHER greife ich per http_non_blocking auf das device zu. Der service wird auf subscribed gesetzt. Wird das definierte timeout überschritten, wird die subscription nicht ausgeführt. Das wird mit verbose level 3 gelogged.
Ich denke, dass sich das jede Minute wiederholt, da ich den presence Status des devices NICHT verändere(bleibt online). Und irgendwann meldet sich das device wieder per "alive" und es wird verfahren, als wäre das device eingeschaltet worden.

So die Theorie.  Bin gespannt...

Grüße Markus

[MichaelT]

Hi Markus,

habe das Modul in Verwendung. ControlPoint wieder original.
Erstmal keine Auffälligkeiten.

Device (192.168.4.30) offline (Netzteil aus):

Code Auswählen Erweitern

2022.04.07 19:21:38.121 5: UPNPController: try to renew subscriptions for services, device SYS_UPNP
2022.04.07 19:22:38.121 5: UPNPController: try to renew subscriptions for services, device SYS_UPNP
2022.04.07 19:23:38.123 5: UPNPController: try to renew subscriptions for services, device SYS_UPNP
2022.04.07 19:23:38.123 5: UPNPController: renew subscription for service AVTransport of device 192.168.4.30_42046 1649346282
2022.04.07 19:23:43.135 5: UPNPController: warning: Carp, Renewal of subscription failed with error: 500 Can't connect to 192.168.4.30:42046 (Connection timed out) at ./FHEM/98_UPNPController.pm line 971.

2022.04.07 19:23:43.137 3: UPNPController: renewal of subscription for service AVTransport of device 192.168.4.30_42046 failed: , try to subscribe
2022.04.07 19:23:43.137 5: UPNPController: renew subscription for service SessionManagement of device 192.168.4.30_42046 1649346282
2022.04.07 19:23:48.147 5: UPNPController: warning: Carp, Renewal of subscription failed with error: 500 Can't connect to 192.168.4.30:42046 (Connection timed out) at ./FHEM/98_UPNPController.pm line 971.

2022.04.07 19:23:48.147 3: UPNPController: renewal of subscription for service SessionManagement of device 192.168.4.30_42046 failed: , try to subscribe
2022.04.07 19:23:48.149 5: UPNPController: renew subscription for service RenderingControl of device 192.168.4.30_42046 1649346282
2022.04.07 19:23:51.203 5: UPNPController: warning: Carp, Renewal of subscription failed with error: 500 Can't connect to 192.168.4.30:42046 (No route to host) at ./FHEM/98_UPNPController.pm line 971.

2022.04.07 19:23:51.204 3: UPNPController: renewal of subscription for service RenderingControl of device 192.168.4.30_42046 failed: , try to subscribe
2022.04.07 19:23:51.205 5: UPNPController: renew subscription for service SpeakerManagement of device 192.168.4.30_42046 1649346282
2022.04.07 19:23:54.275 5: UPNPController: warning: Carp, Renewal of subscription failed with error: 500 Can't connect to 192.168.4.30:42046 (No route to host) at ./FHEM/98_UPNPController.pm line 971.

2022.04.07 19:23:54.276 3: UPNPController: renewal of subscription for service SpeakerManagement of device 192.168.4.30_42046 failed: , try to subscribe
2022.04.07 19:23:54.276 5: UPNPController: renew subscription for service SpeakerManagement of device 192.168.4.33_42729 1649346285
2022.04.07 19:23:54.332 5: UPNPController: renew subscription for service RenderingControl of device 192.168.4.33_42729 1649346285
2022.04.07 19:23:54.360 5: UPNPController: renew subscription for service SessionManagement of device 192.168.4.33_42729 1649346285
2022.04.07 19:23:54.391 5: UPNPController: renew subscription for service AVTransport of device 192.168.4.33_42729 1649346285
2022.04.07 19:23:54.430 5: UPNPController: renewSubscriptionsfinished name SYS_UPNP, readingname 192.168.4.30_42046-zs-SpeakerManagement
2022.04.07 19:23:54.448 4: UPNPController: subscribe: reading  192.168.4.30_42046-zs-SpeakerManagement, uniquedevice 192.168.4.30_42046, service SpeakerManagement
2022.04.07 19:23:55.451 3: UPNPController: Subscription_Callback: subscription of 192.168.4.30_42046-zs-SpeakerManagement failed; error while requesting http://192.168.4.30:42046/93b2abac-cb6a-4857-b891-00226190ead6.xml - connect to http://192.168.4.30:42046 timed out
2022.04.07 19:24:38.120 5: UPNPController: try to renew subscriptions for services, device SYS_UPNP
2022.04.07 19:24:38.120 5: UPNPController: renew subscription for service SessionManagement of device 192.168.4.31_57510 1649346335
2022.04.07 19:24:38.148 5: UPNPController: renew subscription for service RenderingControl of device 192.168.4.31_57510 1649346336
2022.04.07 19:24:38.176 5: UPNPController: renew subscription for service AVTransport of device 192.168.4.31_57510 1649346336
2022.04.07 19:24:38.219 5: UPNPController: renew subscription for service SpeakerManagement of device 192.168.4.31_57510 1649346335
2022.04.07 19:24:38.248 5: UPNPController: renew subscription for service SpeakerManagement of device 192.168.4.32_51147 1649346331
2022.04.07 19:24:38.279 5: UPNPController: renew subscription for service SessionManagement of device 192.168.4.32_51147 1649346330
2022.04.07 19:24:38.309 5: UPNPController: renew subscription for service RenderingControl of device 192.168.4.32_51147 1649346330
2022.04.07 19:24:38.344 5: UPNPController: renew subscription for service AVTransport of device 192.168.4.32_51147 1649346330
2022.04.07 19:25:38.122 5: UPNPController: try to renew subscriptions for services, device SYS_UPNP

renew nach einigen Minuten:

Code Auswählen Erweitern

2022.04.07 19:27:38.123 5: UPNPController: try to renew subscriptions for services, device SYS_UPNP
2022.04.07 19:28:38.126 5: UPNPController: try to renew subscriptions for services, device SYS_UPNP
2022.04.07 19:28:38.127 5: UPNPController: renew subscription for service AVTransport of device 192.168.4.30_42046 1649346282
2022.04.07 19:28:41.185 5: UPNPController: warning: Carp, Renewal of subscription failed with error: 500 Can't connect to 192.168.4.30:42046 (No route to host) at ./FHEM/98_UPNPController.pm line 971.

2022.04.07 19:28:41.185 3: UPNPController: renewal of subscription for service AVTransport of device 192.168.4.30_42046 failed: , try to subscribe
2022.04.07 19:28:41.185 5: UPNPController: renew subscription for service SessionManagement of device 192.168.4.30_42046 1649346282
2022.04.07 19:28:44.257 5: UPNPController: warning: Carp, Renewal of subscription failed with error: 500 Can't connect to 192.168.4.30:42046 (No route to host) at ./FHEM/98_UPNPController.pm line 971.

2022.04.07 19:28:44.257 3: UPNPController: renewal of subscription for service SessionManagement of device 192.168.4.30_42046 failed: , try to subscribe
2022.04.07 19:28:44.258 5: UPNPController: renew subscription for service RenderingControl of device 192.168.4.30_42046 1649346282
2022.04.07 19:28:47.330 5: UPNPController: warning: Carp, Renewal of subscription failed with error: 500 Can't connect to 192.168.4.30:42046 (No route to host) at ./FHEM/98_UPNPController.pm line 971.

2022.04.07 19:28:47.330 3: UPNPController: renewal of subscription for service RenderingControl of device 192.168.4.30_42046 failed: , try to subscribe
2022.04.07 19:28:47.330 5: UPNPController: renew subscription for service SpeakerManagement of device 192.168.4.30_42046 1649346282
2022.04.07 19:28:50.401 5: UPNPController: warning: Carp, Renewal of subscription failed with error: 500 Can't connect to 192.168.4.30:42046 (No route to host) at ./FHEM/98_UPNPController.pm line 971.

2022.04.07 19:28:50.402 3: UPNPController: renewal of subscription for service SpeakerManagement of device 192.168.4.30_42046 failed: , try to subscribe
2022.04.07 19:28:50.402 5: UPNPController: renew subscription for service SpeakerManagement of device 192.168.4.33_42729 1649346285
2022.04.07 19:28:50.432 5: UPNPController: renew subscription for service RenderingControl of device 192.168.4.33_42729 1649346285
2022.04.07 19:28:50.463 5: UPNPController: renew subscription for service SessionManagement of device 192.168.4.33_42729 1649346285
2022.04.07 19:28:50.507 5: UPNPController: renew subscription for service AVTransport of device 192.168.4.33_42729 1649346285
2022.04.07 19:28:50.539 5: UPNPController: renew subscription for service SessionManagement of device 192.168.4.31_57510 1649346335
2022.04.07 19:28:50.580 5: UPNPController: renew subscription for service RenderingControl of device 192.168.4.31_57510 1649346336
2022.04.07 19:28:50.618 5: UPNPController: renew subscription for service AVTransport of device 192.168.4.31_57510 1649346336
2022.04.07 19:28:50.656 5: UPNPController: renew subscription for service SpeakerManagement of device 192.168.4.31_57510 1649346335
2022.04.07 19:28:50.692 5: UPNPController: renew subscription for service SpeakerManagement of device 192.168.4.32_51147 1649346331
2022.04.07 19:28:50.726 5: UPNPController: renew subscription for service SessionManagement of device 192.168.4.32_51147 1649346330
2022.04.07 19:28:50.760 5: UPNPController: renew subscription for service RenderingControl of device 192.168.4.32_51147 1649346330
2022.04.07 19:28:50.791 5: UPNPController: renew subscription for service AVTransport of device 192.168.4.32_51147 1649346330
2022.04.07 19:28:50.841 5: UPNPController: renewSubscriptionsfinished name SYS_UPNP, readingname 192.168.4.30_42046-zs-SpeakerManagement
2022.04.07 19:28:50.858 4: UPNPController: subscribe: reading  192.168.4.30_42046-zs-SpeakerManagement, uniquedevice 192.168.4.30_42046, service SpeakerManagement
2022.04.07 19:28:51.860 3: UPNPController: Subscription_Callback: subscription of 192.168.4.30_42046-zs-SpeakerManagement failed; error while requesting http://192.168.4.30:42046/93b2abac-cb6a-4857-b891-00226190ead6.xml - connect to http://192.168.4.30:42046 timed out
2022.04.07 19:29:38.127 5: UPNPController: try to renew subscriptions for services, device SYS_UPNP
2022.04.07 19:30:38.124 5: UPNPController: try to renew subscriptions for services, device SYS_UPNP
2022.04.07 19:31:38.124 5: UPNPController: try to renew subscriptions for services, device SYS_UPNP

Spannung ein:

Code Auswählen Erweitern

2022.04.07 19:34:26.427 5: DLNAController: message parameters: AVTransport, 192.168.4.131_8080, offline, urn:schemas-upnp-org:metadata-1-0/AVT
2022.04.07 19:34:26.439 3: UPNPController: subscription for service AVTransport of device 192.168.4.131_8080 failed:
2022.04.07 19:35:01.463 5: UPNPController: try to renew subscriptions for services, device SYS_UPNP
2022.04.07 19:35:13.167 4: UPNPController: discovery message of Buero with UDN: uuid:93b2abac-cb6a-4857-b891-00226190ead6 action: deviceRemoved
2022.04.07 19:35:13.168 5: UPNPController: SYS_UPNP: byebye-notify message device 192.168.4.30_42046 received
2022.04.07 19:35:13.184 5: UPNPController: earlier subscribed service AVTransport of device 192.168.4.30_42046 went offline
2022.04.07 19:35:13.196 5: UPNPController: earlier subscribed service SessionManagement of device 192.168.4.30_42046 went offline
2022.04.07 19:35:13.208 5: UPNPController: earlier subscribed service RenderingControl of device 192.168.4.30_42046 went offline
2022.04.07 19:35:13.220 5: UPNPController: earlier subscribed service SpeakerManagement of device 192.168.4.30_42046 went offline
2022.04.07 19:35:13.232 5: SYS_UPNP: dispatch RenderingControl|192.168.4.30_42046|offline|urn:schemas-upnp-org:metadata-1-0/RCS
2022.04.07 19:35:13.232 4: DLNAController: message from SYS_UPNP, message: RenderingControl|192.168.4.30_42046|offline|urn:schemas-upnp-org:metadata-1-0/RCS
2022.04.07 19:35:13.232 5: DLNAController: message parameters: RenderingControl, 192.168.4.30_42046, offline, urn:schemas-upnp-org:metadata-1-0/RCS
2022.04.07 19:35:13.232 4: DLNAController DG_BUE_MR: state update from SYS_UPNP, address 192.168.4.30_42046
2022.04.07 19:35:13.467 4: UPNPController: discovery message of Buero with UDN: uuid:93b2abac-cb6a-4857-b891-00226190ead6 action: deviceAdded
2022.04.07 19:35:13.467 5: UPNPController: SYS_UPNP: alive-notify message device uuid:93b2abac-cb6a-4857-b891-00226190ead6 received
2022.04.07 19:35:13.469 5: UPNPController: SYS_UPNP: device uuid:93b2abac-cb6a-4857-b891-00226190ead6 found. Check for processing
2022.04.07 19:35:13.470 5: UPNPController: SYS_UPNP: device uuid:93b2abac-cb6a-4857-b891-00226190ead6 will be controlled with 192.168.4.30_42046
2022.04.07 19:35:13.470 5: UPNPController: SYS_UPNP: device uuid:93b2abac-cb6a-4857-b891-00226190ead6 has service with serviceId: ConnectionManager
2022.04.07 19:35:13.470 5: UPNPController: SYS_UPNP: device uuid:93b2abac-cb6a-4857-b891-00226190ead6 has service with serviceId: AVTransport
2022.04.07 19:35:13.470 4: UPNPController: subscribe: reading  192.168.4.30_42046-zs-AVTransport, uniquedevice 192.168.4.30_42046, service AVTransport
2022.04.07 19:35:13.471 5: UPNPController: SYS_UPNP: device uuid:93b2abac-cb6a-4857-b891-00226190ead6 has service with serviceId: RenderingControl
2022.04.07 19:35:13.472 4: UPNPController: subscribe: reading  192.168.4.30_42046-zs-RenderingControl, uniquedevice 192.168.4.30_42046, service RenderingControl
2022.04.07 19:35:13.472 5: UPNPController: SYS_UPNP: device uuid:93b2abac-cb6a-4857-b891-00226190ead6 has service with serviceId: RTSPGateway
2022.04.07 19:35:13.473 5: UPNPController: SYS_UPNP: device uuid:93b2abac-cb6a-4857-b891-00226190ead6 has service with serviceId: SpeakerManagement
2022.04.07 19:35:13.473 4: UPNPController: subscribe: reading  192.168.4.30_42046-zs-SpeakerManagement, uniquedevice 192.168.4.30_42046, service SpeakerManagement
2022.04.07 19:35:13.474 5: UPNPController: SYS_UPNP: device uuid:93b2abac-cb6a-4857-b891-00226190ead6 has service with serviceId: NetworkManagement
2022.04.07 19:35:13.474 5: UPNPController: SYS_UPNP: device uuid:93b2abac-cb6a-4857-b891-00226190ead6 has service with serviceId: SessionManagement
2022.04.07 19:35:13.474 4: UPNPController: subscribe: reading  192.168.4.30_42046-zs-SessionManagement, uniquedevice 192.168.4.30_42046, service SessionManagement
2022.04.07 19:35:13.475 5: SYS_UPNP: dispatch RenderingControl|192.168.4.30_42046|online|urn:schemas-upnp-org:metadata-1-0/RCS
2022.04.07 19:35:13.475 4: DLNAController: message from SYS_UPNP, message: RenderingControl|192.168.4.30_42046|online|urn:schemas-upnp-org:metadata-1-0/RCS
2022.04.07 19:35:13.475 5: DLNAController: message parameters: RenderingControl, 192.168.4.30_42046, online, urn:schemas-upnp-org:metadata-1-0/RCS
2022.04.07 19:35:13.476 4: DLNAController DG_BUE_MR: state update from SYS_UPNP, address 192.168.4.30_42046
2022.04.07 19:35:13.575 5: UPNPController: AVTransport: urn:upnp-org:serviceId:AVTransport found. OK.
2022.04.07 19:35:13.790 4: UPNPController: subscribe: reading  192.168.4.30_42046-zs-AVTransport, uniquedevice 192.168.4.30_42046, service AVTransport timeout: 300
2022.04.07 19:35:13.808 5: UPNPController: SessionManagement: urn:pure-com:serviceId:SessionManagement found. OK.
2022.04.07 19:35:13.998 4: UPNPController: subscribe: reading  192.168.4.30_42046-zs-SessionManagement, uniquedevice 192.168.4.30_42046, service SessionManagement timeout: 300
2022.04.07 19:35:14.016 5: UPNPController: SpeakerManagement: urn:pure-com:serviceId:SpeakerManagement found. OK.
2022.04.07 19:35:15.131 4: UPNPController: subscribe: reading  192.168.4.30_42046-zs-SpeakerManagement, uniquedevice 192.168.4.30_42046, service SpeakerManagement timeout: 300
2022.04.07 19:35:15.147 5: UPNPController: RenderingControl: urn:upnp-org:serviceId:RenderingControl found. OK.
2022.04.07 19:35:15.251 4: UPNPController: subscribe: reading  192.168.4.30_42046-zs-RenderingControl, uniquedevice 192.168.4.30_42046, service RenderingControl timeout: 300
2022.04.07 19:35:16.094 5: UPNPController: Received event: by 192.168.4.30_42046-zs-AVTransport UPnP::ControlPoint::Service=HASH(0x43add84) $VAR1 = 'LastChange';
$VAR2 = '<Event xmlns="urn:schemas-upnp-org:metadata-1-0/AVT/"><InstanceID val="0"><TransportPlaySpeed val="1"/><RecordStorageMedium val="NOT_IMPLEMENTED"/><CurrentPlayMode val="NORMAL"/><TransportState val="STOPPED"/><RecordMediumWriteStatus val="NOT_IMPLEMENTED"/><CurrentRecordQualityMode val="NOT_IMPLEMENTED"/><SyncOffset val="P00:00:00.000"/><CurrentTrackURI val=""/><PlaybackStorageMedium val="NOT_IMPLEMENTED"/><NumberOfTracks val="0"/><CurrentMediaDuration val="0:00:00"/><NextAVTransportURIMetaData val=""/><AVTransportURI val=""/><PossiblePlaybackStorageMedia val="None,Network"/><PossibleRecordStorageMedia val="NOT_IMPLEMENTED"/><NextAVTransportURI val=""/><TransportStatus val="OK"/><CurrentTrackMetaData val=""/><AVTransportURIMetaData val=""/><CurrentTrackDuration val="0:00:00"/><PossibleRecordQualityMode val="NOT_IMPLEMENTED"/><CurrentTrack val="0"/></InstanceID></Event>';

2022.04.07 19:35:16.152 5: SYS_UPNP: dispatch AVTransport|192.168.4.30_42046|LastChange|<Event xmlns="urn:schemas-upnp-org:metadata-1-0/AVT/"><InstanceID val="0"><TransportPlaySpeed val="1"/><RecordStorageMedium val="NOT_IMPLEMENTED"/><CurrentPlayMode val="NORMAL"/><TransportState val="STOPPED"/><RecordMediumWriteStatus val="NOT_IMPLEMENTED"/><CurrentRecordQualityMode val="NOT_IMPLEMENTED"/><SyncOffset val="P00:00:00.000"/><CurrentTrackURI val=""/><PlaybackStorageMedium val="NOT_IMPLEMENTED"/><NumberOfTracks val="0"/><CurrentMediaDuration val="0:00:00"/><NextAVTransportURIMetaData val=""/><AVTransportURI val=""/><PossiblePlaybackStorageMedia val="None,Network"/><PossibleRecordStorageMedia val="NOT_IMPLEMENTED"/><NextAVTransportURI val=""/><TransportStatus val="OK"/><CurrentTrackMetaData val=""/><AVTransportURIMetaData val=""/><CurrentTrackDuration val="0:00:00"/><PossibleRecordQualityMode val="NOT_IMPLEMENTED"/><CurrentTrack val="0"/></InstanceID></Event>
2022.04.07 19:35:16.152 4: DLNAController: message from SYS_UPNP, message: AVTransport|192.168.4.30_42046|LastChange|<Event xmlns="urn:schemas-upnp-org:metadata-1-0/AVT/"><InstanceID val="0"><TransportPlaySpeed val="1"/><RecordStorageMedium val="NOT_IMPLEMENTED"/><CurrentPlayMode val="NORMAL"/><TransportState val="STOPPED"/><RecordMediumWriteStatus val="NOT_IMPLEMENTED"/><CurrentRecordQualityMode val="NOT_IMPLEMENTED"/><SyncOffset val="P00:00:00.000"/><CurrentTrackURI val=""/><PlaybackStorageMedium val="NOT_IMPLEMENTED"/><NumberOfTracks val="0"/><CurrentMediaDuration val="0:00:00"/><NextAVTransportURIMetaData val=""/><AVTransportURI val=""/><PossiblePlaybackStorageMedia val="None,Network"/><PossibleRecordStorageMedia val="NOT_IMPLEMENTED"/><NextAVTransportURI val=""/><TransportStatus val="OK"/><CurrentTrackMetaData val=""/><AVTransportURIMetaData val=""/><CurrentTrackDuration val="0:00:00"/><PossibleRecordQualityMode val="NOT_IMPLEMENTED"/><CurrentTrack val="0"/></InstanceID></Event>
2022.04.07 19:35:16.153 5: DLNAController: message parameters: AVTransport, 192.168.4.30_42046, LastChange, <Event xmlns="urn:schemas-upnp-org:metadata-1-0/AVT/"><InstanceID val="0"><TransportPlaySpeed val="1"/><RecordStorageMedium val="NOT_IMPLEMENTED"/><CurrentPlayMode val="NORMAL"/><TransportState val="STOPPED"/><RecordMediumWriteStatus val="NOT_IMPLEMENTED"/><CurrentRecordQualityMode val="NOT_IMPLEMENTED"/><SyncOffset val="P00:00:00.000"/><CurrentTrackURI val=""/><PlaybackStorageMedium val="NOT_IMPLEMENTED"/><NumberOfTracks val="0"/><CurrentMediaDuration val="0:00:00"/><NextAVTransportURIMetaData val=""/><AVTransportURI val=""/><PossiblePlaybackStorageMedia val="None,Network"/><PossibleRecordStorageMedia val="NOT_IMPLEMENTED"/><NextAVTransportURI val=""/><TransportStatus val="OK"/><CurrentTrackMetaData val=""/><AVTransportURIMetaData val=""/><CurrentTrackDuration val="0:00:00"/><PossibleRecordQualityMode val="NOT_IMPLEMENTED"/><CurrentTrack val="0"/></InstanceID></Event>
2022.04.07 19:35:16.153 5: DLNAController: DG_BUE_MR process property LastChange, xml-event <Event xmlns="urn:schemas-upnp-org:metadata-1-0/AVT/"><InstanceID val="0"><TransportPlaySpeed val="1"/><RecordStorageMedium val="NOT_IMPLEMENTED"/><CurrentPlayMode val="NORMAL"/><TransportState val="STOPPED"/><RecordMediumWriteStatus val="NOT_IMPLEMENTED"/><CurrentRecordQualityMode val="NOT_IMPLEMENTED"/><SyncOffset val="P00:00:00.000"/><CurrentTrackURI val=""/><PlaybackStorageMedium val="NOT_IMPLEMENTED"/><NumberOfTracks val="0"/><CurrentMediaDuration val="0:00:00"/><NextAVTransportURIMetaData val=""/><AVTransportURI val=""/><PossiblePlaybackStorageMedia val="None,Network"/><PossibleRecordStorageMedia val="NOT_IMPLEMENTED"/><NextAVTransportURI val=""/><TransportStatus val="OK"/><CurrentTrackMetaData val=""/><AVTransportURIMetaData val=""/><CurrentTrackDuration val="0:00:00"/><PossibleRecordQualityMode val="NOT_IMPLEMENTED"/><CurrentTrack val="0"/></InstanceID></Event>
2022.04.07 19:35:16.153 4: DLNAController: DG_BUE_MR parsing did enter load_xml call: <Event xmlns="urn:schemas-upnp-org:metadata-1-0/AVT/"><InstanceID val="0"><TransportPlaySpeed val="1"/><RecordStorageMedium val="NOT_IMPLEMENTED"/><CurrentPlayMode val="NORMAL"/><TransportState val="STOPPED"/><RecordMediumWriteStatus val="NOT_IMPLEMENTED"/><CurrentRecordQualityMode val="NOT_IMPLEMENTED"/><SyncOffset val="P00:00:00.000"/><CurrentTrackURI val=""/><PlaybackStorageMedium val="NOT_IMPLEMENTED"/><NumberOfTracks val="0"/><CurrentMediaDuration val="0:00:00"/><NextAVTransportURIMetaData val=""/><AVTransportURI val=""/><PossiblePlaybackStorageMedia val="None,Network"/><PossibleRecordStorageMedia val="NOT_IMPLEMENTED"/><NextAVTransportURI val=""/><TransportStatus val="OK"/><CurrentTrackMetaData val=""/><AVTransportURIMetaData val=""/><CurrentTrackDuration val="0:00:00"/><PossibleRecordQualityMode val="NOT_IMPLEMENTED"/><CurrentTrack val="0"/></InstanceID></Event>
2022.04.07 19:35:16.153 4: DLNAController: DG_BUE_MR dom structure: <?xml version="1.0"?>
<Event xmlns="urn:schemas-upnp-org:metadata-1-0/AVT/">
  <InstanceID val="0">
    <TransportPlaySpeed val="1"/>
    <RecordStorageMedium val="NOT_IMPLEMENTED"/>
    <CurrentPlayMode val="NORMAL"/>
    <TransportState val="STOPPED"/>
    <RecordMediumWriteStatus val="NOT_IMPLEMENTED"/>
    <CurrentRecordQualityMode val="NOT_IMPLEMENTED"/>
    <SyncOffset val="P00:00:00.000"/>
    <CurrentTrackURI val=""/>
    <PlaybackStorageMedium val="NOT_IMPLEMENTED"/>
    <NumberOfTracks val="0"/>
    <CurrentMediaDuration val="0:00:00"/>
    <NextAVTransportURIMetaData val=""/>
    <AVTransportURI val=""/>
    <PossiblePlaybackStorageMedia val="None,Network"/>
    <PossibleRecordStorageMedia val="NOT_IMPLEMENTED"/>
    <NextAVTransportURI val=""/>
    <TransportStatus val="OK"/>
    <CurrentTrackMetaData val=""/>
    <AVTransportURIMetaData val=""/>
    <CurrentTrackDuration val="0:00:00"/>
    <PossibleRecordQualityMode val="NOT_IMPLEMENTED"/>
    <CurrentTrack val="0"/>
  </InstanceID>
</Event>

2022.04.07 19:35:16.153 4: DLNAController: DG_BUE_MR LastChange xml event with root <Event xmlns="urn:schemas-upnp-org:metadata-1-0/AVT/"><InstanceID val="0"><TransportPlaySpeed val="1"/><RecordStorageMedium val="NOT_IMPLEMENTED"/><CurrentPlayMode val="NORMAL"/><TransportState val="STOPPED"/><RecordMediumWriteStatus val="NOT_IMPLEMENTED"/><CurrentRecordQualityMode val="NOT_IMPLEMENTED"/><SyncOffset val="P00:00:00.000"/><CurrentTrackURI val=""/><PlaybackStorageMedium val="NOT_IMPLEMENTED"/><NumberOfTracks val="0"/><CurrentMediaDuration val="0:00:00"/><NextAVTransportURIMetaData val=""/><AVTransportURI val=""/><PossiblePlaybackStorageMedia val="None,Network"/><PossibleRecordStorageMedia val="NOT_IMPLEMENTED"/><NextAVTransportURI val=""/><TransportStatus val="OK"/><CurrentTrackMetaData val=""/><AVTransportURIMetaData val=""/><CurrentTrackDuration val="0:00:00"/><PossibleRecordQualityMode val="NOT_IMPLEMENTED"/><CurrentTrack val="0"/></InstanceID></Event> found with name: Event
2022.04.07 19:35:16.154 5: DLNAController: DG_BUE_MR registered ns-uri is: urn:schemas-upnp-org:metadata-1-0/AVT/
2022.04.07 19:35:16.154 5: DLNAController: DG_BUE_MR node <InstanceID val="0"><TransportPlaySpeed val="1"/><RecordStorageMedium val="NOT_IMPLEMENTED"/><CurrentPlayMode val="NORMAL"/><TransportState val="STOPPED"/><RecordMediumWriteStatus val="NOT_IMPLEMENTED"/><CurrentRecordQualityMode val="NOT_IMPLEMENTED"/><SyncOffset val="P00:00:00.000"/><CurrentTrackURI val=""/><PlaybackStorageMedium val="NOT_IMPLEMENTED"/><NumberOfTracks val="0"/><CurrentMediaDuration val="0:00:00"/><NextAVTransportURIMetaData val=""/><AVTransportURI val=""/><PossiblePlaybackStorageMedia val="None,Network"/><PossibleRecordStorageMedia val="NOT_IMPLEMENTED"/><NextAVTransportURI val=""/><TransportStatus val="OK"/><CurrentTrackMetaData val=""/><AVTransportURIMetaData val=""/><CurrentTrackDuration val="0:00:00"/><PossibleRecordQualityMode val="NOT_IMPLEMENTED"/><CurrentTrack val="0"/></InstanceID>, node-name: InstanceID node-type: 1
2022.04.07 19:35:16.154 4: DLNAController: DG_BUE_MR Update reading transportState with STOPPED
2022.04.07 19:35:16.155 4: DLNAController: DG_BUE_MR Update reading transportStatus with OK
2022.04.07 19:35:16.155 4: DLNAController: DG_BUE_MR Update reading currentTrackURI with
2022.04.07 19:35:16.155 4: DLNAController: DG_BUE_MR Update reading nextAVTransportURI with
2022.04.07 19:35:16.155 4: DLNAController: DG_BUE_MR Update reading CurrentMediaDuration with 0:00:00
2022.04.07 19:35:16.155 4: DLNAController: DG_BUE_MR Update reading CurrentTrackDuration with 0:00:00
2022.04.07 19:35:16.156 4: DLNAController DG_BUE_MR: state update from SYS_UPNP, address 192.168.4.30_42046
2022.04.07 19:35:16.508 5: UPNPController: Received event: by 192.168.4.30_42046-zs-SpeakerManagement UPnP::ControlPoint::Service=HASH(0x497c634) $VAR1 = 'SessionID';
$VAR2 = '';
$VAR3 = 'Groups';
$VAR4 = '<?xml version="1.0" ?><groups version="1.0"><group><id>4DAA44C0-8291-11E3-BAA7-0800200C9A66</id><name>Bluetooth</name></group></groups>';

2022.04.07 19:35:16.535 5: SYS_UPNP: dispatch SessionManagement|192.168.4.30_42046|SessionID|
2022.04.07 19:35:16.535 4: DLNAController: message from SYS_UPNP, message: SessionManagement|192.168.4.30_42046|SessionID|
2022.04.07 19:35:16.535 5: DLNAController: message parameters: SessionManagement, 192.168.4.30_42046, SessionID,
2022.04.07 19:35:16.535 5: DLNAController: DG_BUE_MR process property SessionID, xml-event
2022.04.07 19:35:16.536 4: DLNAController DG_BUE_MR: state update from SYS_UPNP, address 192.168.4.30_42046
2022.04.07 19:35:16.562 5: SYS_UPNP: dispatch SpeakerManagement|192.168.4.30_42046|Groups|<?xml version="1.0" ?><groups version="1.0"><group><id>4DAA44C0-8291-11E3-BAA7-0800200C9A66</id><name>Bluetooth</name></group></groups>
2022.04.07 19:35:16.562 4: DLNAController: message from SYS_UPNP, message: SpeakerManagement|192.168.4.30_42046|Groups|<?xml version="1.0" ?><groups version="1.0"><group><id>4DAA44C0-8291-11E3-BAA7-0800200C9A66</id><name>Bluetooth</name></group></groups>
2022.04.07 19:35:16.562 5: DLNAController: message parameters: SpeakerManagement, 192.168.4.30_42046, Groups, <?xml version="1.0" ?><groups version="1.0"><group><id>4DAA44C0-8291-11E3-BAA7-0800200C9A66</id><name>Bluetooth</name></group></groups>
2022.04.07 19:35:16.562 5: DLNAController: DG_BUE_MR process property Groups, xml-event <?xml version="1.0" ?><groups version="1.0"><group><id>4DAA44C0-8291-11E3-BAA7-0800200C9A66</id><name>Bluetooth</name></group></groups>
2022.04.07 19:35:16.562 4: DLNAController: DG_BUE_MR parsing did enter load_xml call: <?xml version="1.0" ?><groups version="1.0"><group><id>4DAA44C0-8291-11E3-BAA7-0800200C9A66</id><name>Bluetooth</name></group></groups>
2022.04.07 19:35:16.563 3: DLNAController: DG_BUE_MR property Groups, propertyval: <?xml version="1.0" ?><groups version="1.0"><group><id>4DAA44C0-8291-11E3-BAA7-0800200C9A66</id><name>Bluetooth</name></group></groups>
2022.04.07 19:35:16.563 4: DLNAController DG_BUE_MR: state update from SYS_UPNP, address 192.168.4.30_42046
2022.04.07 19:35:16.580 5: UPNPController: Received event: by 192.168.4.30_42046-zs-RenderingControl UPnP::ControlPoint::Service=HASH(0x4a7d82c) $VAR1 = 'LastChange';
$VAR2 = '<Event xmlns="urn:schemas-upnp-org:metadata-1-0/RCS/"><InstanceID val="0"><AllowedTransformSettings val="&lt;?xml version=&quot;1.0&quot; encoding=&quot;UTF-8&quot;?&gt;&lt;TransformList xmlns=&quot;urn:schemas-upnp-org:av:AllowedTransformSettings&quot; xmlns:xsi=&quot;http://www.w3.org/2001/XMLSchema-instance&quot; xsi:schemaLocation=&quot;urn:schemas-upnp-org:av:AllowedTransformSettings http://www.upnp.org/schemas/av/AllowedTransformSettings.xsd&quot;&gt;&lt;transform name=&quot;BandEq_65_1040&quot; shared=&quot;1&quot;&gt;&lt;friendlyName&gt;Bass&lt;/friendlyName&gt;&lt;allowedValueRange scale=&quot;Linear&quot;&gt;&lt;minimum&gt;0&lt;/minimum&gt;&lt;maximum&gt;10&lt;/maximum&gt;&lt;step&gt;1&lt;/step&gt;&lt;/allowedValueRange&gt;&lt;/transform&gt;&lt;transform name=&quot;BandEq_1250_20000&quot; shared=&quot;1&quot;&gt;&lt;friendlyName&gt;Treble&lt;/friendlyName&gt;&lt;allowedValueRange scale=&quot;Linear&quot;&gt;&lt;minimum&gt;0&lt;/minimum&gt;&lt;maximum&gt;10&lt;/maximum&gt;&lt;step&gt;1&lt;/step&gt;&lt;/allowedValueRange&gt;&lt;/transform&gt;&lt;/TransformList&gt;"/><TransformSettings val="&lt;?xml version=&quot;1.0&quot; encoding=&quot;UTF-8&quot;?&gt;&lt;TransformSettings xmlns=&quot;urn:schemas-upnp-org:av:TransformSettings&quot; xmlns:xsi=&quot;http://www.w3.org/2001/XMLSchema-instance&quot; xsi:schemaLocation=&quot;urn:schemas-upnp-org:av:TransformSettings http://www.upnp.org/schemas/av/TransformSettings.xsd&quot;&gt;&lt;transform name=&quot;BandEq_65_1040&quot;&gt;&lt;Value&gt;5&lt;/Value&gt;&lt;/transform&gt;&lt;transform name=&quot;BandEq_1250_20000&quot;&gt;&lt;Value&gt;5&lt;/Value&gt;&lt;/transform&gt;&lt;/TransformSettings&gt;"/><PresetNameList val="FactoryDefaults, InstallationDefaults"/><Mute channel="Master" val="0"/><Volume channel="Master" val="24"/></InstanceID></Event>';

2022.04.07 19:35:16.724 5: SYS_UPNP: dispatch RenderingControl|192.168.4.30_42046|LastChange|<Event xmlns="urn:schemas-upnp-org:metadata-1-0/RCS/"><InstanceID val="0"><AllowedTransformSettings val="&lt;?xml version=&quot;1.0&quot; encoding=&quot;UTF-8&quot;?&gt;&lt;TransformList xmlns=&quot;urn:schemas-upnp-org:av:AllowedTransformSettings&quot; xmlns:xsi=&quot;http://www.w3.org/2001/XMLSchema-instance&quot; xsi:schemaLocation=&quot;urn:schemas-upnp-org:av:AllowedTransformSettings http://www.upnp.org/schemas/av/AllowedTransformSettings.xsd&quot;&gt;&lt;transform name=&quot;BandEq_65_1040&quot; shared=&quot;1&quot;&gt;&lt;friendlyName&gt;Bass&lt;/friendlyName&gt;&lt;allowedValueRange scale=&quot;Linear&quot;&gt;&lt;minimum&gt;0&lt;/minimum&gt;&lt;maximum&gt;10&lt;/maximum&gt;&lt;step&gt;1&lt;/step&gt;&lt;/allowedValueRange&gt;&lt;/transform&gt;&lt;transform name=&quot;BandEq_1250_20000&quot; shared=&quot;1&quot;&gt;&lt;friendlyName&gt;Treble&lt;/friendlyName&gt;&lt;allowedValueRange scale=&quot;Linear&quot;&gt;&lt;minimum&gt;0&lt;/minimum&gt;&lt;maximum&gt;10&lt;/maximum&gt;&lt;step&gt;1&lt;/step&gt;&lt;/allowedValueRange&gt;&lt;/transform&gt;&lt;/TransformList&gt;"/><TransformSettings val="&lt;?xml version=&quot;1.0&quot; encoding=&quot;UTF-8&quot;?&gt;&lt;TransformSettings xmlns=&quot;urn:schemas-upnp-org:av:TransformSettings&quot; xmlns:xsi=&quot;http://www.w3.org/2001/XMLSchema-instance&quot; xsi:schemaLocation=&quot;urn:schemas-upnp-org:av:TransformSettings http://www.upnp.org/schemas/av/TransformSettings.xsd&quot;&gt;&lt;transform name=&quot;BandEq_65_1040&quot;&gt;&lt;Value&gt;5&lt;/Value&gt;&lt;/transform&gt;&lt;transform name=&quot;BandEq_1250_20000&quot;&gt;&lt;Value&gt;5&lt;/Value&gt;&lt;/transform&gt;&lt;/TransformSettings&gt;"/><PresetNameList val="FactoryDefaults, InstallationDefaults"/><Mute channel="Master" val="0"/><Volume channel="Master" val="24"/></InstanceID></Event>
2022.04.07 19:35:16.724 4: DLNAController: message from SYS_UPNP, message: RenderingControl|192.168.4.30_42046|LastChange|<Event xmlns="urn:schemas-upnp-org:metadata-1-0/RCS/"><InstanceID val="0"><AllowedTransformSettings val="&lt;?xml version=&quot;1.0&quot; encoding=&quot;UTF-8&quot;?&gt;&lt;TransformList xmlns=&quot;urn:schemas-upnp-org:av:AllowedTransformSettings&quot; xmlns:xsi=&quot;http://www.w3.org/2001/XMLSchema-instance&quot; xsi:schemaLocation=&quot;urn:schemas-upnp-org:av:AllowedTransformSettings http://www.upnp.org/schemas/av/AllowedTransformSettings.xsd&quot;&gt;&lt;transform name=&quot;BandEq_65_1040&quot; shared=&quot;1&quot;&gt;&lt;friendlyName&gt;Bass&lt;/friendlyName&gt;&lt;allowedValueRange scale=&quot;Linear&quot;&gt;&lt;minimum&gt;0&lt;/minimum&gt;&lt;maximum&gt;10&lt;/maximum&gt;&lt;step&gt;1&lt;/step&gt;&lt;/allowedValueRange&gt;&lt;/transform&gt;&lt;transform name=&quot;BandEq_1250_20000&quot; shared=&quot;1&quot;&gt;&lt;friendlyName&gt;Treble&lt;/friendlyName&gt;&lt;allowedValueRange scale=&quot;Linear&quot;&gt;&lt;minimum&gt;0&lt;/minimum&gt;&lt;maximum&gt;10&lt;/maximum&gt;&lt;step&gt;1&lt;/step&gt;&lt;/allowedValueRange&gt;&lt;/transform&gt;&lt;/TransformList&gt;"/><TransformSettings val="&lt;?xml version=&quot;1.0&quot; encoding=&quot;UTF-8&quot;?&gt;&lt;TransformSettings xmlns=&quot;urn:schemas-upnp-org:av:TransformSettings&quot; xmlns:xsi=&quot;http://www.w3.org/2001/XMLSchema-instance&quot; xsi:schemaLocation=&quot;urn:schemas-upnp-org:av:TransformSettings http://www.upnp.org/schemas/av/TransformSettings.xsd&quot;&gt;&lt;transform name=&quot;BandEq_65_1040&quot;&gt;&lt;Value&gt;5&lt;/Value&gt;&lt;/transform&gt;&lt;transform name=&quot;BandEq_1250_20000&quot;&gt;&lt;Value&gt;5&lt;/Value&gt;&lt;/transform&gt;&lt;/TransformSettings&gt;"/><PresetNameList val="FactoryDefaults, InstallationDefaults"/><Mute channel="Master" val="0"/><Volume channel="Master" val="24"/></InstanceID></Event>
2022.04.07 19:35:16.724 5: DLNAController: message parameters: RenderingControl, 192.168.4.30_42046, LastChange, <Event xmlns="urn:schemas-upnp-org:metadata-1-0/RCS/"><InstanceID val="0"><AllowedTransformSettings val="&lt;?xml version=&quot;1.0&quot; encoding=&quot;UTF-8&quot;?&gt;&lt;TransformList xmlns=&quot;urn:schemas-upnp-org:av:AllowedTransformSettings&quot; xmlns:xsi=&quot;http://www.w3.org/2001/XMLSchema-instance&quot; xsi:schemaLocation=&quot;urn:schemas-upnp-org:av:AllowedTransformSettings http://www.upnp.org/schemas/av/AllowedTransformSettings.xsd&quot;&gt;&lt;transform name=&quot;BandEq_65_1040&quot; shared=&quot;1&quot;&gt;&lt;friendlyName&gt;Bass&lt;/friendlyName&gt;&lt;allowedValueRange scale=&quot;Linear&quot;&gt;&lt;minimum&gt;0&lt;/minimum&gt;&lt;maximum&gt;10&lt;/maximum&gt;&lt;step&gt;1&lt;/step&gt;&lt;/allowedValueRange&gt;&lt;/transform&gt;&lt;transform name=&quot;BandEq_1250_20000&quot; shared=&quot;1&quot;&gt;&lt;friendlyName&gt;Treble&lt;/friendlyName&gt;&lt;allowedValueRange scale=&quot;Linear&quot;&gt;&lt;minimum&gt;0&lt;/minimum&gt;&lt;maximum&gt;10&lt;/maximum&gt;&lt;step&gt;1&lt;/step&gt;&lt;/allowedValueRange&gt;&lt;/transform&gt;&lt;/TransformList&gt;"/><TransformSettings val="&lt;?xml version=&quot;1.0&quot; encoding=&quot;UTF-8&quot;?&gt;&lt;TransformSettings xmlns=&quot;urn:schemas-upnp-org:av:TransformSettings&quot; xmlns:xsi=&quot;http://www.w3.org/2001/XMLSchema-instance&quot; xsi:schemaLocation=&quot;urn:schemas-upnp-org:av:TransformSettings http://www.upnp.org/schemas/av/TransformSettings.xsd&quot;&gt;&lt;transform name=&quot;BandEq_65_1040&quot;&gt;&lt;Value&gt;5&lt;/Value&gt;&lt;/transform&gt;&lt;transform name=&quot;BandEq_1250_20000&quot;&gt;&lt;Value&gt;5&lt;/Value&gt;&lt;/transform&gt;&lt;/TransformSettings&gt;"/><PresetNameList val="FactoryDefaults, InstallationDefaults"/><Mute channel="Master" val="0"/><Volume channel="Master" val="24"/></InstanceID></Event>
2022.04.07 19:35:16.724 5: DLNAController: DG_BUE_MR process property LastChange, xml-event <Event xmlns="urn:schemas-upnp-org:metadata-1-0/RCS/"><InstanceID val="0"><AllowedTransformSettings val="<?xml version="1.0" encoding="UTF-8"?><TransformList xmlns="urn:schemas-upnp-org:av:AllowedTransformSettings" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:schemaLocation="urn:schemas-upnp-org:av:AllowedTransformSettings http://www.upnp.org/schemas/av/AllowedTransformSettings.xsd"><transform name="BandEq_65_1040" shared="1"><friendlyName>Bass</friendlyName><allowedValueRange scale="Linear"><minimum>0</minimum><maximum>10</maximum><step>1</step></allowedValueRange></transform><transform name="BandEq_1250_20000" shared="1"><friendlyName>Treble</friendlyName><allowedValueRange scale="Linear"><minimum>0</minimum><maximum>10</maximum><step>1</step></allowedValueRange></transform></TransformList>"/><TransformSettings val="<?xml version="1.0" encoding="UTF-8"?><TransformSettings xmlns="urn:schemas-upnp-org:av:TransformSettings" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:schemaLocation="urn:schemas-upnp-org:av:TransformSettings http://www.upnp.org/schemas/av/TransformSettings.xsd"><transform name="BandEq_65_1040"><Value>5</Value></transform><transform name="BandEq_1250_20000"><Value>5</Value></transform></TransformSettings>"/><PresetNameList val="FactoryDefaults, InstallationDefaults"/><Mute channel="Master" val="0"/><Volume channel="Master" val="24"/></InstanceID></Event>
2022.04.07 19:35:16.724 4: DLNAController: DG_BUE_MR parsing did enter load_xml call: <Event xmlns="urn:schemas-upnp-org:metadata-1-0/RCS/"><InstanceID val="0"><AllowedTransformSettings val="<?xml version="1.0" encoding="UTF-8"?><TransformList xmlns="urn:schemas-upnp-org:av:AllowedTransformSettings" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:schemaLocation="urn:schemas-upnp-org:av:AllowedTransformSettings http://www.upnp.org/schemas/av/AllowedTransformSettings.xsd"><transform name="BandEq_65_1040" shared="1"><friendlyName>Bass</friendlyName><allowedValueRange scale="Linear"><minimum>0</minimum><maximum>10</maximum><step>1</step></allowedValueRange></transform><transform name="BandEq_1250_20000" shared="1"><friendlyName>Treble</friendlyName><allowedValueRange scale="Linear"><minimum>0</minimum><maximum>10</maximum><step>1</step></allowedValueRange></transform></TransformList>"/><TransformSettings val="<?xml version="1.0" encoding="UTF-8"?><TransformSettings xmlns="urn:schemas-upnp-org:av:TransformSettings" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:schemaLocation="urn:schemas-upnp-org:av:TransformSettings http://www.upnp.org/schemas/av/TransformSettings.xsd"><transform name="BandEq_65_1040"><Value>5</Value></transform><transform name="BandEq_1250_20000"><Value>5</Value></transform></TransformSettings>"/><PresetNameList val="FactoryDefaults, InstallationDefaults"/><Mute channel="Master" val="0"/><Volume channel="Master" val="24"/></InstanceID></Event>
2022.04.07 19:35:16.725 4: DLNAController: DG_BUE_MR dom structure: <?xml version="1.0"?>
<Event xmlns="urn:schemas-upnp-org:metadata-1-0/RCS/">
  <InstanceID val="0">
    <AllowedTransformSettings val="<?xml version="1.0" encoding="UTF-8"?><TransformList xmlns="urn:schemas-upnp-org:av:AllowedTransformSettings" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:schemaLocation="urn:schemas-upnp-org:av:AllowedTransformSettings http://www.upnp.org/schemas/av/AllowedTransformSettings.xsd"><transform name="BandEq_65_1040" shared="1"><friendlyName>Bass</friendlyName><allowedValueRange scale="Linear"><minimum>0</minimum><maximum>10</maximum><step>1</step></allowedValueRange></transform><transform name="BandEq_1250_20000" shared="1"><friendlyName>Treble</friendlyName><allowedValueRange scale="Linear"><minimum>0</minimum><maximum>10</maximum><step>1</step></allowedValueRange></transform></TransformList>"/>
    <TransformSettings val="<?xml version="1.0" encoding="UTF-8"?><TransformSettings xmlns="urn:schemas-upnp-org:av:TransformSettings" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:schemaLocation="urn:schemas-upnp-org:av:TransformSettings http://www.upnp.org/schemas/av/TransformSettings.xsd"><transform name="BandEq_65_1040"><Value>5</Value></transform><transform name="BandEq_1250_20000"><Value>5</Value></transform></TransformSettings>"/>
    <PresetNameList val="FactoryDefaults, InstallationDefaults"/>
    <Mute channel="Master" val="0"/>
    <Volume channel="Master" val="24"/>
  </InstanceID>
</Event>

2022.04.07 19:35:16.725 4: DLNAController: DG_BUE_MR LastChange xml event with root <Event xmlns="urn:schemas-upnp-org:metadata-1-0/RCS/"><InstanceID val="0"><AllowedTransformSettings val="<?xml version="1.0" encoding="UTF-8"?><TransformList xmlns="urn:schemas-upnp-org:av:AllowedTransformSettings" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:schemaLocation="urn:schemas-upnp-org:av:AllowedTransformSettings http://www.upnp.org/schemas/av/AllowedTransformSettings.xsd"><transform name="BandEq_65_1040" shared="1"><friendlyName>Bass</friendlyName><allowedValueRange scale="Linear"><minimum>0</minimum><maximum>10</maximum><step>1</step></allowedValueRange></transform><transform name="BandEq_1250_20000" shared="1"><friendlyName>Treble</friendlyName><allowedValueRange scale="Linear"><minimum>0</minimum><maximum>10</maximum><step>1</step></allowedValueRange></transform></TransformList>"/><TransformSettings val="<?xml version="1.0" encoding="UTF-8"?><TransformSettings xmlns="urn:schemas-upnp-org:av:TransformSettings" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:schemaLocation="urn:schemas-upnp-org:av:TransformSettings http://www.upnp.org/schemas/av/TransformSettings.xsd"><transform name="BandEq_65_1040"><Value>5</Value></transform><transform name="BandEq_1250_20000"><Value>5</Value></transform></TransformSettings>"/><PresetNameList val="FactoryDefaults, InstallationDefaults"/><Mute channel="Master" val="0"/><Volume channel="Master" val="24"/></InstanceID></Event> found with name: Event
2022.04.07 19:35:16.725 5: DLNAController: DG_BUE_MR registered ns-uri is: urn:schemas-upnp-org:metadata-1-0/RCS/
2022.04.07 19:35:16.725 5: DLNAController: DG_BUE_MR node <InstanceID val="0"><AllowedTransformSettings val="<?xml version="1.0" encoding="UTF-8"?><TransformList xmlns="urn:schemas-upnp-org:av:AllowedTransformSettings" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:schemaLocation="urn:schemas-upnp-org:av:AllowedTransformSettings http://www.upnp.org/schemas/av/AllowedTransformSettings.xsd"><transform name="BandEq_65_1040" shared="1"><friendlyName>Bass</friendlyName><allowedValueRange scale="Linear"><minimum>0</minimum><maximum>10</maximum><step>1</step></allowedValueRange></transform><transform name="BandEq_1250_20000" shared="1"><friendlyName>Treble</friendlyName><allowedValueRange scale="Linear"><minimum>0</minimum><maximum>10</maximum><step>1</step></allowedValueRange></transform></TransformList>"/><TransformSettings val="<?xml version="1.0" encoding="UTF-8"?><TransformSettings xmlns="urn:schemas-upnp-org:av:TransformSettings" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:schemaLocation="urn:schemas-upnp-org:av:TransformSettings http://www.upnp.org/schemas/av/TransformSettings.xsd"><transform name="BandEq_65_1040"><Value>5</Value></transform><transform name="BandEq_1250_20000"><Value>5</Value></transform></TransformSettings>"/><PresetNameList val="FactoryDefaults, InstallationDefaults"/><Mute channel="Master" val="0"/><Volume channel="Master" val="24"/></InstanceID>, node-name: InstanceID node-type: 1
2022.04.07 19:35:16.726 4: DLNAController: DG_BUE_MR Update reading mute with 0
2022.04.07 19:35:16.726 4: DLNAController: DG_BUE_MR Update reading mute with 0
2022.04.07 19:35:16.726 4: DLNAController: DG_BUE_MR Update reading mute with 0
2022.04.07 19:35:16.726 4: DLNAController: DG_BUE_MR Update reading mute with 0
2022.04.07 19:35:16.726 4: DLNAController: DG_BUE_MR Update reading mute with 0
2022.04.07 19:35:16.726 4: DLNAController: DG_BUE_MR Update reading mute with 0
2022.04.07 19:35:16.726 4: DLNAController: DG_BUE_MR Update reading mute with 0
2022.04.07 19:35:16.727 4: DLNAController: DG_BUE_MR Update reading mute with 0
2022.04.07 19:35:16.727 4: DLNAController: DG_BUE_MR Update reading mute with 0
2022.04.07 19:35:16.727 4: DLNAController: DG_BUE_MR Update reading mute with 0
2022.04.07 19:35:16.727 4: DLNAController: DG_BUE_MR Update reading mute with 0
2022.04.07 19:35:16.727 4: DLNAController: DG_BUE_MR Update reading mute with 0
2022.04.07 19:35:16.727 4: DLNAController DG_BUE_MR: state update from SYS_UPNP, address 192.168.4.30_42046
2022.04.07 19:35:16.749 5: UPNPController: Received event: by 192.168.4.30_42046-zs-SessionManagement UPnP::ControlPoint::Service=HASH(0x4a31cf4) $VAR1 = 'SessionID';
$VAR2 = '';

2022.04.07 19:35:16.774 5: SYS_UPNP: dispatch SessionManagement|192.168.4.30_42046|SessionID|
2022.04.07 19:35:16.775 4: DLNAController: message from SYS_UPNP, message: SessionManagement|192.168.4.30_42046|SessionID|
2022.04.07 19:35:16.775 5: DLNAController: message parameters: SessionManagement, 192.168.4.30_42046, SessionID,
2022.04.07 19:35:16.775 5: DLNAController: DG_BUE_MR process property SessionID, xml-event
2022.04.07 19:35:16.776 4: DLNAController DG_BUE_MR: state update from SYS_UPNP, address 192.168.4.30_42046
2022.04.07 19:35:23.839 5: UPNPController: try to renew subscriptions for services, device SYS_UPNP

Ich glaube, das sieht sehr gut aus. Keine Freezes 
Ich lass es jetzt mal laufen und schaue, was bei den ungewollten Aussetzern passsiert.


Gruß Michael.

[KölnSolar]

Hi Michael,
klingt gut.
Aber nur die

den ungewollten Aussetzern

gilt es im Augenblick zu "bekämpfen".
Bin gespannt...
Grüße Markus
PS: Ich selber habe durchaus kleinere freezes beim discovery und den actions. Das liegt an lahmen devices. 
Mir ist wichtig, dass die "unnötigen" freezes bei subscription und dessen renewal ausgemerzt sind, wenn der Stecker am device gezogen oder wie bei Dir ein seltsamer off/on Effekt auftritt, oder  IP/Port sich ändern.... zumal die x*20s  dauern.

[MichaelT]

Moin,

schade. Um 08:13 hat es die 192.168.4.32 wieder erwischt, danach wieder lange Freezes:

Code Auswählen Erweitern

2022.04.08 08:07:06.261 5: SYS_UPNP: dispatch AVTransport|192.168.4.131_8080|offline|urn:schemas-upnp-org:metadata-1-0/AVT
2022.04.08 08:07:06.261 4: DLNAController: message from SYS_UPNP, message: AVTransport|192.168.4.131_8080|offline|urn:schemas-upnp-org:metadata-1-0/AVT
2022.04.08 08:07:06.261 5: DLNAController: message parameters: AVTransport, 192.168.4.131_8080, offline, urn:schemas-upnp-org:metadata-1-0/AVT
2022.04.08 08:07:06.262 3: UPNPController: subscription for service AVTransport of device 192.168.4.131_8080 failed:
2022.04.08 08:07:56.278 5: UPNPController: try to renew subscriptions for services, device SYS_UPNP
2022.04.08 08:07:56.279 5: UPNPController: renew subscription for service SessionManagement of device 192.168.4.31_57510 1649346335
2022.04.08 08:07:56.316 5: UPNPController: renew subscription for service RenderingControl of device 192.168.4.31_57510 1649346336
2022.04.08 08:07:56.344 5: UPNPController: renew subscription for service AVTransport of device 192.168.4.31_57510 1649346336
2022.04.08 08:07:56.372 5: UPNPController: renew subscription for service SpeakerManagement of device 192.168.4.31_57510 1649346335
2022.04.08 08:07:56.408 5: UPNPController: renew subscription for service SpeakerManagement of device 192.168.4.32_49620 1649365498
2022.04.08 08:07:56.443 5: UPNPController: renew subscription for service AVTransport of device 192.168.4.32_49620 1649365497
2022.04.08 08:07:56.474 5: UPNPController: renew subscription for service SessionManagement of device 192.168.4.32_49620 1649365498
2022.04.08 08:07:56.510 5: UPNPController: renew subscription for service RenderingControl of device 192.168.4.32_49620 1649365497
2022.04.08 08:07:56.543 5: UPNPController: renew subscription for service SpeakerManagement of device 192.168.4.33_42729 1649346285
2022.04.08 08:07:56.579 5: UPNPController: renew subscription for service SessionManagement of device 192.168.4.33_42729 1649346285
2022.04.08 08:07:56.610 5: UPNPController: renew subscription for service RenderingControl of device 192.168.4.33_42729 1649346285
2022.04.08 08:07:56.643 5: UPNPController: renew subscription for service AVTransport of device 192.168.4.33_42729 1649354157
2022.04.08 08:08:56.265 5: UPNPController: try to renew subscriptions for services, device SYS_UPNP
2022.04.08 08:08:56.266 5: UPNPController: renew subscription for service SpeakerManagement of device 192.168.4.30_42046 1649353216
2022.04.08 08:08:56.299 5: UPNPController: renew subscription for service SessionManagement of device 192.168.4.30_42046 1649353216
2022.04.08 08:08:56.331 5: UPNPController: renew subscription for service RenderingControl of device 192.168.4.30_42046 1649353216
2022.04.08 08:08:56.364 5: UPNPController: renew subscription for service AVTransport of device 192.168.4.30_42046 1649353216
2022.04.08 08:09:56.269 5: UPNPController: try to renew subscriptions for services, device SYS_UPNP
2022.04.08 08:10:56.270 5: UPNPController: try to renew subscriptions for services, device SYS_UPNP
2022.04.08 08:11:56.270 5: UPNPController: try to renew subscriptions for services, device SYS_UPNP
2022.04.08 08:11:56.271 5: UPNPController: renew subscription for service SessionManagement of device 192.168.4.31_57510 1649346335
2022.04.08 08:11:56.298 5: UPNPController: renew subscription for service RenderingControl of device 192.168.4.31_57510 1649346336
2022.04.08 08:11:56.330 5: UPNPController: renew subscription for service AVTransport of device 192.168.4.31_57510 1649346336
2022.04.08 08:11:56.364 5: UPNPController: renew subscription for service SpeakerManagement of device 192.168.4.31_57510 1649346335
2022.04.08 08:11:56.396 5: UPNPController: renew subscription for service SpeakerManagement of device 192.168.4.32_49620 1649365498
2022.04.08 08:11:56.429 5: UPNPController: renew subscription for service AVTransport of device 192.168.4.32_49620 1649365497
2022.04.08 08:11:56.460 5: UPNPController: renew subscription for service SessionManagement of device 192.168.4.32_49620 1649365498
2022.04.08 08:11:56.494 5: UPNPController: renew subscription for service RenderingControl of device 192.168.4.32_49620 1649365497
2022.04.08 08:11:56.528 5: UPNPController: renew subscription for service SpeakerManagement of device 192.168.4.33_42729 1649346285
2022.04.08 08:11:56.563 5: UPNPController: renew subscription for service SessionManagement of device 192.168.4.33_42729 1649346285
2022.04.08 08:11:56.596 5: UPNPController: renew subscription for service RenderingControl of device 192.168.4.33_42729 1649346285
2022.04.08 08:11:56.628 5: UPNPController: renew subscription for service AVTransport of device 192.168.4.33_42729 1649354157
2022.04.08 08:12:56.265 5: UPNPController: try to renew subscriptions for services, device SYS_UPNP
2022.04.08 08:12:56.266 5: UPNPController: renew subscription for service SpeakerManagement of device 192.168.4.30_42046 1649353216
2022.04.08 08:12:56.311 5: UPNPController: renew subscription for service SessionManagement of device 192.168.4.30_42046 1649353216
2022.04.08 08:12:56.347 5: UPNPController: renew subscription for service RenderingControl of device 192.168.4.30_42046 1649353216
2022.04.08 08:12:56.379 5: UPNPController: renew subscription for service AVTransport of device 192.168.4.30_42046 1649353216
2022.04.08 08:13:29.654 4: UPNPController: discovery message of Werkstatt with UDN: uuid:93b2abac-cb6a-4857-b891-002261914054 action: deviceRemoved
2022.04.08 08:13:29.655 5: UPNPController: SYS_UPNP: byebye-notify message device 192.168.4.32_49620 received
2022.04.08 08:13:29.677 5: UPNPController: earlier subscribed service SpeakerManagement of device 192.168.4.32_49620 went offline
2022.04.08 08:13:29.689 5: UPNPController: earlier subscribed service AVTransport of device 192.168.4.32_49620 went offline
2022.04.08 08:13:29.700 5: UPNPController: earlier subscribed service SessionManagement of device 192.168.4.32_49620 went offline
2022.04.08 08:13:29.712 5: UPNPController: earlier subscribed service RenderingControl of device 192.168.4.32_49620 went offline
2022.04.08 08:13:29.724 5: SYS_UPNP: dispatch RenderingControl|192.168.4.32_49620|offline|urn:schemas-upnp-org:metadata-1-0/RCS
2022.04.08 08:13:29.724 4: DLNAController: message from SYS_UPNP, message: RenderingControl|192.168.4.32_49620|offline|urn:schemas-upnp-org:metadata-1-0/RCS
2022.04.08 08:13:29.724 5: DLNAController: message parameters: RenderingControl, 192.168.4.32_49620, offline, urn:schemas-upnp-org:metadata-1-0/RCS
2022.04.08 08:13:50.071 5: UPNPController: warning: Carp, Loading device description failed with error: 500 Can't connect to 192.168.4.32:36566 (Connection timed out) (Location: http://192.168.4.32:36566/93b2abac-cb6a-4857-b891-002261914054.xml) at ./FHEM/98_UPNPController.pm line 403.

2022.04.08 08:13:50.073 1: [Freezemon] myFreezemon: possible freeze starting at 08:13:31, delay is 19.072 possibly caused by: no bad guy found :-(
2022.04.08 08:14:10.128 5: UPNPController: warning: Carp, Loading device description failed with error: 500 Can't connect to 192.168.4.32:36566 (Connection timed out) (Location: http://192.168.4.32:36566/93b2abac-cb6a-4857-b891-002261914054.xml) at ./FHEM/98_UPNPController.pm line 403.

2022.04.08 08:14:10.130 1: [Freezemon] myFreezemon: possible freeze starting at 08:13:51, delay is 19.129 possibly caused by: tmr-FW_closeInactiveClients(N/A)
2022.04.08 08:14:10.165 5: UPNPController: try to renew subscriptions for services, device SYS_UPNP
2022.04.08 08:14:30.189 5: UPNPController: warning: Carp, Loading device description failed with error: 500 Can't connect to 192.168.4.32:36566 (Connection timed out) (Location: http://192.168.4.32:36566/93b2abac-cb6a-4857-b891-002261914054.xml) at ./FHEM/98_UPNPController.pm line 403.

2022.04.08 08:14:30.191 1: [Freezemon] myFreezemon: possible freeze starting at 08:14:11, delay is 19.19 possibly caused by: tmr-UPNPController_renewSubscriptions(SYS_UPNP)
2022.04.08 08:14:50.226 5: UPNPController: warning: Carp, Loading device description failed with error: 500 Can't connect to 192.168.4.32:36566 (Connection timed out) (Location: http://192.168.4.32:36566/93b2abac-cb6a-4857-b891-002261914054.xml) at ./FHEM/98_UPNPController.pm line 403.

2022.04.08 08:14:50.233 1: [Freezemon] myFreezemon: possible freeze starting at 08:14:31, delay is 19.231 possibly caused by: no bad guy found :-(
2022.04.08 08:15:10.265 5: UPNPController: warning: Carp, Loading device description failed with error: 500 Can't connect to 192.168.4.32:36566 (Connection timed out) (Location: http://192.168.4.32:36566/93b2abac-cb6a-4857-b891-002261914054.xml) at ./FHEM/98_UPNPController.pm line 403.

2022.04.08 08:15:10.272 1: [Freezemon] myFreezemon: possible freeze starting at 08:14:51, delay is 19.271 possibly caused by: tmr-CODE(0x430824c)(GetUpdate) tmr-FW_closeInactiveClients(N/A)
2022.04.08 08:15:10.303 5: UPNPController: try to renew subscriptions for services, device SYS_UPNP
2022.04.08 08:15:30.329 5: UPNPController: warning: Carp, Loading device description failed with error: 500 Can't connect to 192.168.4.32:36566 (Connection timed out) (Location: http://192.168.4.32:36566/93b2abac-cb6a-4857-b891-002261914054.xml) at ./FHEM/98_UPNPController.pm line 403.

2022.04.08 08:15:30.330 1: [Freezemon] myFreezemon: possible freeze starting at 08:15:11, delay is 19.33 possibly caused by: tmr-UPNPController_renewSubscriptions(SYS_UPNP) tmr-CODE(0x2fb1d8c)(dnsQuery)
2022.04.08 08:15:50.392 5: UPNPController: warning: Carp, Loading device description failed with error: 500 Can't connect to 192.168.4.32:36566 (Connection timed out) (Location: http://192.168.4.32:36566/93b2abac-cb6a-4857-b891-002261914054.xml) at ./FHEM/98_UPNPController.pm line 403.

2022.04.08 08:15:50.405 1: [Freezemon] myFreezemon: possible freeze starting at 08:15:31, delay is 19.405 possibly caused by: tmr-HttpUtils_TimeoutErr(N/A)
2022.04.08 08:16:10.436 5: UPNPController: warning: Carp, Loading device description failed with error: 500 Can't connect to 192.168.4.32:36566 (Connection timed out) (Location: http://192.168.4.32:36566/93b2abac-cb6a-4857-b891-002261914054.xml) at ./FHEM/98_UPNPController.pm line 403.

2022.04.08 08:16:10.443 1: [Freezemon] myFreezemon: possible freeze starting at 08:15:51, delay is 19.441 possibly caused by: tmr-FW_closeInactiveClients(N/A)
2022.04.08 08:16:10.471 5: UPNPController: try to renew subscriptions for services, device SYS_UPNP
2022.04.08 08:16:30.502 5: UPNPController: warning: Carp, Loading device description failed with error: 500 Can't connect to 192.168.4.32:36566 (Connection timed out) (Location: http://192.168.4.32:36566/93b2abac-cb6a-4857-b891-002261914054.xml) at ./FHEM/98_UPNPController.pm line 403.

2022.04.08 08:16:30.505 1: [Freezemon] myFreezemon: possible freeze starting at 08:16:11, delay is 19.503 possibly caused by: tmr-UPNPController_renewSubscriptions(SYS_UPNP)
2022.04.08 08:16:50.523 5: UPNPController: warning: Carp, Loading device description failed with error: 500 Can't connect to 192.168.4.32:36566 (Connection timed out) (Location: http://192.168.4.32:36566/93b2abac-cb6a-4857-b891-002261914054.xml) at ./FHEM/98_UPNPController.pm line 403.

2022.04.08 08:16:50.525 1: [Freezemon] myFreezemon: possible freeze starting at 08:16:31, delay is 19.524 possibly caused by: no bad guy found :-(
2022.04.08 08:17:10.560 5: UPNPController: warning: Carp, Loading device description failed with error: 500 Can't connect to 192.168.4.32:36566 (Connection timed out) (Location: http://192.168.4.32:36566/93b2abac-cb6a-4857-b891-002261914054.xml) at ./FHEM/98_UPNPController.pm line 403.

2022.04.08 08:17:10.563 1: [Freezemon] myFreezemon: possible freeze starting at 08:16:51, delay is 19.562 possibly caused by: tmr-FW_closeInactiveClients(N/A)
2022.04.08 08:17:10.619 5: UPNPController: try to renew subscriptions for services, device SYS_UPNP
2022.04.08 08:17:30.647 5: UPNPController: warning: Carp, Loading device description failed with error: 500 Can't connect to 192.168.4.32:36566 (Connection timed out) (Location: http://192.168.4.32:36566/93b2abac-cb6a-4857-b891-002261914054.xml) at ./FHEM/98_UPNPController.pm line 403.

2022.04.08 08:17:30.652 1: [Freezemon] myFreezemon: possible freeze starting at 08:17:11, delay is 19.65 possibly caused by: tmr-UPNPController_renewSubscriptions(SYS_UPNP)
2022.04.08 08:17:50.675 5: UPNPController: warning: Carp, Loading device description failed with error: 500 Can't connect to 192.168.4.32:36566 (Connection timed out) (Location: http://192.168.4.32:36566/93b2abac-cb6a-4857-b891-002261914054.xml) at ./FHEM/98_UPNPController.pm line 403.

2022.04.08 08:17:50.682 1: [Freezemon] myFreezemon: possible freeze starting at 08:17:31, delay is 19.68 possibly caused by: no bad guy found :-(
2022.04.08 08:18:10.711 5: UPNPController: warning: Carp, Loading device description failed with error: 500 Can't connect to 192.168.4.32:36566 (Connection timed out) (Location: http://192.168.4.32:36566/93b2abac-cb6a-4857-b891-002261914054.xml) at ./FHEM/98_UPNPController.pm line 403.

2022.04.08 08:18:10.720 1: [Freezemon] myFreezemon: possible freeze starting at 08:17:51, delay is 19.718 possibly caused by: tmr-FW_closeInactiveClients(N/A)
2022.04.08 08:18:10.748 5: UPNPController: try to renew subscriptions for services, device SYS_UPNP
2022.04.08 08:18:30.757 5: UPNPController: warning: Carp, Loading device description failed with error: 500 Can't connect to 192.168.4.32:36566 (Connection timed out) (Location: http://192.168.4.32:36566/93b2abac-cb6a-4857-b891-002261914054.xml) at ./FHEM/98_UPNPController.pm line 403.

2022.04.08 08:18:30.759 1: [Freezemon] myFreezemon: possible freeze starting at 08:18:11, delay is 19.759 possibly caused by: tmr-UPNPController_renewSubscriptions(SYS_UPNP)
2022.04.08 08:18:50.792 5: UPNPController: warning: Carp, Loading device description failed with error: 500 Can't connect to 192.168.4.32:36566 (Connection timed out) (Location: http://192.168.4.32:36566/93b2abac-cb6a-4857-b891-002261914054.xml) at ./FHEM/98_UPNPController.pm line 403.

2022.04.08 08:18:50.797 1: [Freezemon] myFreezemon: possible freeze starting at 08:18:31, delay is 19.795 possibly caused by: no bad guy found :-(
2022.04.08 08:19:10.848 5: UPNPController: warning: Carp, Loading device description failed with error: 500 Can't connect to 192.168.4.32:36566 (Connection timed out) (Location: http://192.168.4.32:36566/93b2abac-cb6a-4857-b891-002261914054.xml) at ./FHEM/98_UPNPController.pm line 403.

2022.04.08 08:19:10.853 1: [Freezemon] myFreezemon: possible freeze starting at 08:18:51, delay is 19.852 possibly caused by: tmr-FW_closeInactiveClients(N/A)
2022.04.08 08:19:10.887 5: UPNPController: try to renew subscriptions for services, device SYS_UPNP
2022.04.08 08:19:30.912 5: UPNPController: warning: Carp, Loading device description failed with error: 500 Can't connect to 192.168.4.32:36566 (Connection timed out) (Location: http://192.168.4.32:36566/93b2abac-cb6a-4857-b891-002261914054.xml) at ./FHEM/98_UPNPController.pm line 403.

2022.04.08 08:19:30.914 1: [Freezemon] myFreezemon: possible freeze starting at 08:19:11, delay is 19.914 possibly caused by: tmr-UPNPController_renewSubscriptions(SYS_UPNP)
2022.04.08 08:19:50.947 5: UPNPController: warning: Carp, Loading device description failed with error: 500 Can't connect to 192.168.4.32:36566 (Connection timed out) (Location: http://192.168.4.32:36566/93b2abac-cb6a-4857-b891-002261914054.xml) at ./FHEM/98_UPNPController.pm line 403.

2022.04.08 08:19:50.950 1: [Freezemon] myFreezemon: possible freeze starting at 08:19:31, delay is 19.948 possibly caused by: no bad guy found :-(
2022.04.08 08:20:10.984 5: UPNPController: warning: Carp, Loading device description failed with error: 500 Can't connect to 192.168.4.32:36566 (Connection timed out) (Location: http://192.168.4.32:36566/93b2abac-cb6a-4857-b891-002261914054.xml) at ./FHEM/98_UPNPController.pm line 403.

2022.04.08 08:20:10.993 1: [Freezemon] myFreezemon: possible freeze starting at 08:19:51, delay is 19.992 possibly caused by: tmr-FW_closeInactiveClients(N/A) tmr-CODE(0x430824c)(GetUpdate)
2022.04.08 08:20:11.021 5: UPNPController: try to renew subscriptions for services, device SYS_UPNP
2022.04.08 08:20:31.047 5: UPNPController: warning: Carp, Loading device description failed with error: 500 Can't connect to 192.168.4.32:36566 (Connection timed out) (Location: http://192.168.4.32:36566/93b2abac-cb6a-4857-b891-002261914054.xml) at ./FHEM/98_UPNPController.pm line 403.

2022.04.08 08:20:31.053 1: [Freezemon] myFreezemon: possible freeze starting at 08:20:11, delay is 20.052 possibly caused by: tmr-CODE(0x2fb1d8c)(dnsQuery) tmr-UPNPController_renewSubscriptions(SYS_UPNP)
2022.04.08 08:20:46.409 5: UPNPController: warning: Carp, Loading device description failed with error: 500 Can't connect to 192.168.4.32:36566 (Connection refused) (Location: http://192.168.4.32:36566/93b2abac-cb6a-4857-b891-002261914054.xml) at ./FHEM/98_UPNPController.pm line 403.

2022.04.08 08:20:46.413 1: [Freezemon] myFreezemon: possible freeze starting at 08:20:32, delay is 14.412 possibly caused by: tmr-HttpUtils_TimeoutErr(N/A)
2022.04.08 08:20:46.426 5: UPNPController: warning: Carp, Loading device description failed with error: 500 Can't connect to 192.168.4.32:36566 (Connection refused) (Location: http://192.168.4.32:36566/93b2abac-cb6a-4857-b891-002261914054.xml) at ./FHEM/98_UPNPController.pm line 403.

2022.04.08 08:20:46.451 5: UPNPController: warning: Carp, Loading device description failed with error: 500 Can't connect to 192.168.4.32:36566 (Connection refused) (Location: http://192.168.4.32:36566/93b2abac-cb6a-4857-b891-002261914054.xml) at ./FHEM/98_UPNPController.pm line 403.

2022.04.08 08:20:46.457 5: UPNPController: warning: Carp, Loading device description failed with error: 500 Can't connect to 192.168.4.32:36566 (Connection refused) (Location: http://192.168.4.32:36566/93b2abac-cb6a-4857-b891-002261914054.xml) at ./FHEM/98_UPNPController.pm line 403.

2022.04.08 08:20:46.463 5: UPNPController: warning: Carp, Loading device description failed with error: 500 Can't connect to 192.168.4.32:36566 (Connection refused) (Location: http://192.168.4.32:36566/93b2abac-cb6a-4857-b891-002261914054.xml) at ./FHEM/98_UPNPController.pm line 403.

2022.04.08 08:20:46.471 5: UPNPController: warning: Carp, Loading device description failed with error: 500 Can't connect to 192.168.4.32:36566 (Connection refused) (Location: http://192.168.4.32:36566/93b2abac-cb6a-4857-b891-002261914054.xml) at ./FHEM/98_UPNPController.pm line 403.

2022.04.08 08:20:48.922 4: UPNPController: discovery message of Werkstatt with UDN: uuid:93b2abac-cb6a-4857-b891-002261914054 action: deviceAdded
2022.04.08 08:20:48.922 5: UPNPController: SYS_UPNP: alive-notify message device uuid:93b2abac-cb6a-4857-b891-002261914054 received
2022.04.08 08:20:48.923 3: UPNPController: old definition of device uuid:93b2abac-cb6a-4857-b891-002261914054 found with 192.168.4.32_49620. readings deleted.
2022.04.08 08:20:48.923 5: UPNPController: SYS_UPNP: device uuid:93b2abac-cb6a-4857-b891-002261914054 found. Check for processing
2022.04.08 08:20:48.923 5: UPNPController: SYS_UPNP: device uuid:93b2abac-cb6a-4857-b891-002261914054 will be controlled with 192.168.4.32_49030
2022.04.08 08:20:48.924 5: UPNPController: SYS_UPNP: device uuid:93b2abac-cb6a-4857-b891-002261914054 has service with serviceId: ConnectionManager
2022.04.08 08:20:48.924 5: UPNPController: SYS_UPNP: device uuid:93b2abac-cb6a-4857-b891-002261914054 has service with serviceId: AVTransport
2022.04.08 08:20:48.924 5: UPNPController: SYS_UPNP: device uuid:93b2abac-cb6a-4857-b891-002261914054 has service with serviceId: RenderingControl
2022.04.08 08:20:48.924 5: UPNPController: SYS_UPNP: device uuid:93b2abac-cb6a-4857-b891-002261914054 has service with serviceId: RTSPGateway
2022.04.08 08:20:48.925 5: UPNPController: SYS_UPNP: device uuid:93b2abac-cb6a-4857-b891-002261914054 has service with serviceId: SpeakerManagement
2022.04.08 08:20:48.925 5: UPNPController: SYS_UPNP: device uuid:93b2abac-cb6a-4857-b891-002261914054 has service with serviceId: NetworkManagement
2022.04.08 08:20:48.925 5: UPNPController: SYS_UPNP: device uuid:93b2abac-cb6a-4857-b891-002261914054 has service with serviceId: SessionManagement
2022.04.08 08:20:48.925 5: SYS_UPNP: dispatch RenderingControl|192.168.4.32_49030|online|urn:schemas-upnp-org:metadata-1-0/RCS
2022.04.08 08:20:48.926 4: DLNAController: message from SYS_UPNP, message: RenderingControl|192.168.4.32_49030|online|urn:schemas-upnp-org:metadata-1-0/RCS
2022.04.08 08:20:48.926 5: DLNAController: message parameters: RenderingControl, 192.168.4.32_49030, online, urn:schemas-upnp-org:metadata-1-0/RCS
2022.04.08 08:20:48.926 5: UPNPController: SYS_UPNP, 192.168.4.32_49030, RenderingControl, subscribe,
2022.04.08 08:20:48.926 5: UPNPController: RenderingControl: urn:upnp-org:serviceId:RenderingControl found. OK.
2022.04.08 08:20:48.926 4: UPNPController: subscribe: reading  192.168.4.32_49030-zs-RenderingControl, uniquedevice 192.168.4.32_49030, service RenderingControl
2022.04.08 08:20:48.927 5: UPNPController: SYS_UPNP, 192.168.4.32_49030, AVTransport, subscribe,
2022.04.08 08:20:48.928 5: UPNPController: AVTransport: urn:upnp-org:serviceId:AVTransport found. OK.
2022.04.08 08:20:48.928 4: UPNPController: subscribe: reading  192.168.4.32_49030-zs-AVTransport, uniquedevice 192.168.4.32_49030, service AVTransport
2022.04.08 08:20:48.929 5: UPNPController: SYS_UPNP, 192.168.4.32_49030, SpeakerManagement, subscribe,
2022.04.08 08:20:48.929 5: UPNPController: SpeakerManagement: urn:pure-com:serviceId:SpeakerManagement found. OK.
2022.04.08 08:20:48.930 4: UPNPController: subscribe: reading  192.168.4.32_49030-zs-SpeakerManagement, uniquedevice 192.168.4.32_49030, service SpeakerManagement
2022.04.08 08:20:48.931 5: UPNPController: SYS_UPNP, 192.168.4.32_49030, SessionManagement, subscribe,
2022.04.08 08:20:48.931 5: UPNPController: SessionManagement: urn:pure-com:serviceId:SessionManagement found. OK.
2022.04.08 08:20:48.932 4: UPNPController: subscribe: reading  192.168.4.32_49030-zs-SessionManagement, uniquedevice 192.168.4.32_49030, service SessionManagement
2022.04.08 08:20:49.061 5: UPNPController: AVTransport: urn:upnp-org:serviceId:AVTransport found. OK.
2022.04.08 08:20:50.301 4: UPNPController: subscribe: reading  192.168.4.32_49030-zs-AVTransport, uniquedevice 192.168.4.32_49030, service AVTransport timeout: 300
2022.04.08 08:20:50.319 3: UPNPController: Subscription_Callback: subscription of 192.168.4.32_49030-zs-SpeakerManagement failed; error while requesting http://192.168.4.32:49030/93b2abac-cb6a-4857-b891-002261914054.xml - read from http://192.168.4.32:49030 timed out
2022.04.08 08:20:50.319 3: UPNPController: Subscription_Callback: subscription of 192.168.4.32_49030-zs-SessionManagement failed; error while requesting http://192.168.4.32:49030/93b2abac-cb6a-4857-b891-002261914054.xml - read from http://192.168.4.32:49030 timed out
2022.04.08 08:20:50.320 3: UPNPController: Subscription_Callback: subscription of 192.168.4.32_49030-zs-RenderingControl failed; error while requesting http://192.168.4.32:49030/93b2abac-cb6a-4857-b891-002261914054.xml - read from http://192.168.4.32:49030 timed out
2022.04.08 08:20:50.417 5: UPNPController: Received event: by 192.168.4.32_49030-zs-AVTransport UPnP::ControlPoint::Service=HASH(0x4a9e08c) $VAR1 = 'LastChange';
$VAR2 = '<Event xmlns="urn:schemas-upnp-org:metadata-1-0/AVT/"><InstanceID val="0"><TransportPlaySpeed val="1"/><RecordStorageMedium val="NOT_IMPLEMENTED"/><CurrentPlayMode val="NORMAL"/><TransportState val="STOPPED"/><RecordMediumWriteStatus val="NOT_IMPLEMENTED"/><CurrentRecordQualityMode val="NOT_IMPLEMENTED"/><SyncOffset val="P00:00:00.000"/><CurrentTrackURI val=""/><PlaybackStorageMedium val="NOT_IMPLEMENTED"/><NumberOfTracks val="0"/><CurrentMediaDuration val="0:00:00"/><NextAVTransportURIMetaData val=""/><AVTransportURI val=""/><PossiblePlaybackStorageMedia val="None,Network"/><PossibleRecordStorageMedia val="NOT_IMPLEMENTED"/><NextAVTransportURI val=""/><TransportStatus val="OK"/><CurrentTrackMetaData val=""/><AVTransportURIMetaData val=""/><CurrentTrackDuration val="0:00:00"/><PossibleRecordQualityMode val="NOT_IMPLEMENTED"/><CurrentTrack val="0"/></InstanceID></Event>';

2022.04.08 08:20:50.475 5: SYS_UPNP: dispatch AVTransport|192.168.4.32_49030|LastChange|<Event xmlns="urn:schemas-upnp-org:metadata-1-0/AVT/"><InstanceID val="0"><TransportPlaySpeed val="1"/><RecordStorageMedium val="NOT_IMPLEMENTED"/><CurrentPlayMode val="NORMAL"/><TransportState val="STOPPED"/><RecordMediumWriteStatus val="NOT_IMPLEMENTED"/><CurrentRecordQualityMode val="NOT_IMPLEMENTED"/><SyncOffset val="P00:00:00.000"/><CurrentTrackURI val=""/><PlaybackStorageMedium val="NOT_IMPLEMENTED"/><NumberOfTracks val="0"/><CurrentMediaDuration val="0:00:00"/><NextAVTransportURIMetaData val=""/><AVTransportURI val=""/><PossiblePlaybackStorageMedia val="None,Network"/><PossibleRecordStorageMedia val="NOT_IMPLEMENTED"/><NextAVTransportURI val=""/><TransportStatus val="OK"/><CurrentTrackMetaData val=""/><AVTransportURIMetaData val=""/><CurrentTrackDuration val="0:00:00"/><PossibleRecordQualityMode val="NOT_IMPLEMENTED"/><CurrentTrack val="0"/></InstanceID></Event>
2022.04.08 08:20:50.475 4: DLNAController: message from SYS_UPNP, message: AVTransport|192.168.4.32_49030|LastChange|<Event xmlns="urn:schemas-upnp-org:metadata-1-0/AVT/"><InstanceID val="0"><TransportPlaySpeed val="1"/><RecordStorageMedium val="NOT_IMPLEMENTED"/><CurrentPlayMode val="NORMAL"/><TransportState val="STOPPED"/><RecordMediumWriteStatus val="NOT_IMPLEMENTED"/><CurrentRecordQualityMode val="NOT_IMPLEMENTED"/><SyncOffset val="P00:00:00.000"/><CurrentTrackURI val=""/><PlaybackStorageMedium val="NOT_IMPLEMENTED"/><NumberOfTracks val="0"/><CurrentMediaDuration val="0:00:00"/><NextAVTransportURIMetaData val=""/><AVTransportURI val=""/><PossiblePlaybackStorageMedia val="None,Network"/><PossibleRecordStorageMedia val="NOT_IMPLEMENTED"/><NextAVTransportURI val=""/><TransportStatus val="OK"/><CurrentTrackMetaData val=""/><AVTransportURIMetaData val=""/><CurrentTrackDuration val="0:00:00"/><PossibleRecordQualityMode val="NOT_IMPLEMENTED"/><CurrentTrack val="0"/></InstanceID></Event>
2022.04.08 08:20:50.475 5: DLNAController: message parameters: AVTransport, 192.168.4.32_49030, LastChange, <Event xmlns="urn:schemas-upnp-org:metadata-1-0/AVT/"><InstanceID val="0"><TransportPlaySpeed val="1"/><RecordStorageMedium val="NOT_IMPLEMENTED"/><CurrentPlayMode val="NORMAL"/><TransportState val="STOPPED"/><RecordMediumWriteStatus val="NOT_IMPLEMENTED"/><CurrentRecordQualityMode val="NOT_IMPLEMENTED"/><SyncOffset val="P00:00:00.000"/><CurrentTrackURI val=""/><PlaybackStorageMedium val="NOT_IMPLEMENTED"/><NumberOfTracks val="0"/><CurrentMediaDuration val="0:00:00"/><NextAVTransportURIMetaData val=""/><AVTransportURI val=""/><PossiblePlaybackStorageMedia val="None,Network"/><PossibleRecordStorageMedia val="NOT_IMPLEMENTED"/><NextAVTransportURI val=""/><TransportStatus val="OK"/><CurrentTrackMetaData val=""/><AVTransportURIMetaData val=""/><CurrentTrackDuration val="0:00:00"/><PossibleRecordQualityMode val="NOT_IMPLEMENTED"/><CurrentTrack val="0"/></InstanceID></Event>
2022.04.08 08:21:00.353 5: UPNPController: try to renew subscriptions for services, device SYS_UPNP
2022.04.08 08:22:00.349 5: UPNPController: try to renew subscriptions for services, device SYS_UPNP
2022.04.08 08:23:00.351 5: UPNPController: try to renew subscriptions for services, device SYS_UPNP
2022.04.08 08:24:00.355 5: UPNPController: try to renew subscriptions for services, device SYS_UPNP

Ist das denn korrekt, dass nach dem byebye noch versucht wird, eine Verbindung aufzubauen 08:13:50?

Code Auswählen Erweitern

2022.04.08 08:13:29.654 4: UPNPController: discovery message of Werkstatt with UDN: uuid:93b2abac-cb6a-4857-b891-002261914054 action: deviceRemoved
2022.04.08 08:13:29.655 5: UPNPController: SYS_UPNP: byebye-notify message device 192.168.4.32_49620 received
2022.04.08 08:13:29.677 5: UPNPController: earlier subscribed service SpeakerManagement of device 192.168.4.32_49620 went offline
2022.04.08 08:13:29.689 5: UPNPController: earlier subscribed service AVTransport of device 192.168.4.32_49620 went offline
2022.04.08 08:13:29.700 5: UPNPController: earlier subscribed service SessionManagement of device 192.168.4.32_49620 went offline
2022.04.08 08:13:29.712 5: UPNPController: earlier subscribed service RenderingControl of device 192.168.4.32_49620 went offline
2022.04.08 08:13:29.724 5: SYS_UPNP: dispatch RenderingControl|192.168.4.32_49620|offline|urn:schemas-upnp-org:metadata-1-0/RCS
2022.04.08 08:13:29.724 4: DLNAController: message from SYS_UPNP, message: RenderingControl|192.168.4.32_49620|offline|urn:schemas-upnp-org:metadata-1-0/RCS
2022.04.08 08:13:29.724 5: DLNAController: message parameters: RenderingControl, 192.168.4.32_49620, offline, urn:schemas-upnp-org:metadata-1-0/RCS
2022.04.08 08:13:50.071 5: UPNPController: warning: Carp, Loading device description failed with error: 500 Can't connect to 192.168.4.32:36566 (Connection timed out) (Location: http://192.168.4.32:36566/93b2abac-cb6a-4857-b891-002261914054.xml) at ./FHEM/98_UPNPController.pm line 403.

2022.04.08 08:13:50.073 1: [Freezemon] myFreezemon: possible freeze starting at 08:13:31, delay is 19.072 possibly caused by: no bad guy found :-(
Falls Du mehr Infos benötigst, einfach melde 

Schönes Wochenende

Michael

[KölnSolar]

Hi Michael,

ist aber was anderes, als der vermeintliche off/on ohne byebye. 

Ist das denn korrekt, dass nach dem byebye noch versucht wird, eine Verbindung aufzubauen 08:13:50?

Aus Modulsicht ja, aus logischer Sicht natürlich nicht. 

Hast Du auch das freezemonlog dazu ? Ich spekuliere, dass da noch ein event nach dem byebye reingekommen ist.   

Ich muss mal alle Loggings überarbeiten, damit  man einfacher sieht, aus welchem der 3 devices die Meldungen kommen.  Krieg ich bestimmt bis heute Abend hin und attache dann hier mal eine überarbeitete Version.

Grüße Markus

[MichaelT]

Hier die freeze-Logs:
Falls Du mehr brauchst, meld dich.

Code Auswählen Erweitern

=========================================================
[Freezemon] myFreezemon: possible freeze starting at 08:13:31, delay is 19.072 possibly caused by: no bad guy found :-(
2022.04.08 08:13:30.002 5: UPNPController: UPNPSocket-SYS_UPNP-1900, received message on port 1900 starting handleOnce
2022.04.08 08:13:30.002 4: UPNPController: UPNPSocket-SYS_UPNP-1900, received ssdp event: was checked by discoverCallback for removed or added devices against pending search requests
2022.04.08 08:13:30.003 5: UPNPController: UPNPSocket-SYS_UPNP-1900, received message on port 1900 starting handleOnce
2022.04.08 08:13:30.003 4: UPNPController: UPNPSocket-SYS_UPNP-1900, received ssdp event: was checked by discoverCallback for removed or added devices against pending search requests
2022.04.08 08:13:30.005 5: UPNPController: UPNPSocket-SYS_UPNP-1900, received message on port 1900 starting handleOnce
2022.04.08 08:13:30.005 4: UPNPController: UPNPSocket-SYS_UPNP-1900, received ssdp event: was checked by discoverCallback for removed or added devices against pending search requests
2022.04.08 08:13:30.006 5: UPNPController: UPNPSocket-SYS_UPNP-1900, received message on port 1900 starting handleOnce
2022.04.08 08:13:30.006 4: UPNPController: UPNPSocket-SYS_UPNP-1900, received ssdp event: was checked by discoverCallback for removed or added devices against pending search requests
2022.04.08 08:13:30.007 5: UPNPController: UPNPSocket-SYS_UPNP-1900, received message on port 1900 starting handleOnce
2022.04.08 08:13:30.007 4: UPNPController: UPNPSocket-SYS_UPNP-1900, received ssdp event: was checked by discoverCallback for removed or added devices against pending search requests
2022.04.08 08:13:30.049 5: UPNPController: UPNPSocket-SYS_UPNP-1900, received message on port 1900 starting handleOnce
--- log skips    20.022 secs.
2022.04.08 08:13:50.071 5: UPNPController: warning: Carp, Loading device description failed with error: 500 Can't connect to 192.168.4.32:36566 (Connection timed out) (Location: http://192.168.4.32:36566/93b2abac-cb6a-4857-b891-002261914054.xml) at ./FHEM/98_UPNPController.pm line 403.

2022.04.08 08:13:50.072 4: UPNPController: UPNPSocket-SYS_UPNP-1900, received ssdp event: was checked by discoverCallback for removed or added devices against pending search requests
2022.04.08 08:13:50.072 5: [Freezemon] myFreezemon: ----------- Starting Freeze handling at 2022.04.08 08:13:50.072 ---------------------
[Freezemon] myFreezemon: possible freeze starting at 08:13:31, delay is 19.072 possibly caused by: no bad guy found :-(


Code Auswählen Erweitern

[Freezemon] myFreezemon: possible freeze starting at 08:13:51, delay is 19.129 possibly caused by: tmr-FW_closeInactiveClients(N/A)
2022.04.08 08:13:50.097 4: BlockingCall (freezemon_processBlocking): created child (31778), uses telnetPort to connect back
2022.04.08 08:13:50.099 5: [Freezemon] myFreezemon: Blocking Call started with PID 31778
2022.04.08 08:13:50.102 5: UPNPController: UPNPSocket-SYS_UPNP-1900, received message on port 1900 starting handleOnce
--- log skips    20.027 secs.
2022.04.08 08:14:10.128 5: UPNPController: warning: Carp, Loading device description failed with error: 500 Can't connect to 192.168.4.32:36566 (Connection timed out) (Location: http://192.168.4.32:36566/93b2abac-cb6a-4857-b891-002261914054.xml) at ./FHEM/98_UPNPController.pm line 403.

2022.04.08 08:14:10.129 4: UPNPController: UPNPSocket-SYS_UPNP-1900, received ssdp event: was checked by discoverCallback for removed or added devices against pending search requests
2022.04.08 08:14:10.129 5: [Freezemon] myFreezemon: ----------- Starting Freeze handling at 2022.04.08 08:14:10.129 ---------------------
2022.04.08 08:14:10.130 5: Freezemon: something went wrong FW_closeInactiveClients
[Freezemon] myFreezemon: possible freeze starting at 08:13:51, delay is 19.129 possibly caused by: tmr-FW_closeInactiveClients(N/A)


Code Auswählen Erweitern

=========================================================
[Freezemon] myFreezemon: possible freeze starting at 08:14:11, delay is 19.19 possibly caused by: tmr-UPNPController_renewSubscriptions(SYS_UPNP)
2022.04.08 08:14:10.161 4: BlockingCall (UPNPController_renewSubscriptionBlocking): created child (31787), uses telnetPort to connect back
2022.04.08 08:14:10.165 4: Connection accepted from telnetPort_127.0.0.1_34888
2022.04.08 08:14:10.165 5: UPNPController: UPNPSocket-SYS_UPNP-1900, received message on port 1900 starting handleOnce
--- log skips    20.024 secs.
2022.04.08 08:14:30.189 5: UPNPController: warning: Carp, Loading device description failed with error: 500 Can't connect to 192.168.4.32:36566 (Connection timed out) (Location: http://192.168.4.32:36566/93b2abac-cb6a-4857-b891-002261914054.xml) at ./FHEM/98_UPNPController.pm line 403.

2022.04.08 08:14:30.190 4: UPNPController: UPNPSocket-SYS_UPNP-1900, received ssdp event: was checked by discoverCallback for removed or added devices against pending search requests
2022.04.08 08:14:30.190 5: [Freezemon] myFreezemon: ----------- Starting Freeze handling at 2022.04.08 08:14:30.190 ---------------------
[Freezemon] myFreezemon: possible freeze starting at 08:14:11, delay is 19.19 possibly caused by: tmr-UPNPController_renewSubscriptions(SYS_UPNP)


Code Auswählen Erweitern

[Freezemon] myFreezemon: possible freeze starting at 08:14:31, delay is 19.231 possibly caused by: no bad guy found :-(
2022.04.08 08:14:30.199 5: UPNPController: UPNPSocket-SYS_UPNP-1900, received message on port 1900 starting handleOnce
2022.04.08 08:14:30.199 4: UPNPController: UPNPSocket-SYS_UPNP-1900, received ssdp event: was checked by discoverCallback for removed or added devices against pending search requests
2022.04.08 08:14:30.199 4: Connection accepted from telnetPort_127.0.0.1_34952
2022.04.08 08:14:30.200 5: Cmd: >{BlockingRegisterTelnet($cl,902)}<
2022.04.08 08:14:30.200 5: UPNPController: UPNPSocket-SYS_UPNP-1900, received message on port 1900 starting handleOnce
--- log skips    20.026 secs.
2022.04.08 08:14:50.226 5: UPNPController: warning: Carp, Loading device description failed with error: 500 Can't connect to 192.168.4.32:36566 (Connection timed out) (Location: http://192.168.4.32:36566/93b2abac-cb6a-4857-b891-002261914054.xml) at ./FHEM/98_UPNPController.pm line 403.

2022.04.08 08:14:50.227 4: UPNPController: UPNPSocket-SYS_UPNP-1900, received ssdp event: was checked by discoverCallback for removed or added devices against pending search requests
2022.04.08 08:14:50.227 5: Cmd: >{BlockingStart('903')}<
2022.04.08 08:14:50.229 5: Cmd: >{UPNPController_renewSubscriptionsfinished('SYS_UPNP')}<
2022.04.08 08:14:50.232 5: [Freezemon] myFreezemon: ----------- Starting Freeze handling at 2022.04.08 08:14:50.232 ---------------------
[Freezemon] myFreezemon: possible freeze starting at 08:14:31, delay is 19.231 possibly caused by: no bad guy found :-(


Code Auswählen Erweitern

=========================================================
[Freezemon] myFreezemon: possible freeze starting at 08:14:51, delay is 19.271 possibly caused by: tmr-CODE(0x430824c)(GetUpdate) tmr-FW_closeInactiveClients(N/A)
2022.04.08 08:14:50.238 4: Wetter: GetUpdate called (update)
2022.04.08 08:14:50.238 4: Wetter: UpdateTimer called from GetUpdate with cmd next sets timer to call update function in 300.0 sec at 08:19:50.238, interval 300
2022.04.08 08:14:50.238 5: Wetter: AddToQueue adds type update to URL https://www.wunderground.com/dashboard/pws/IMARL111, no data, no headers, retry 0, initial queue len: 0
2022.04.08 08:14:50.238 5: Wetter: HandleSendQueue called from AddToSendQueue, qlen = 1
2022.04.08 08:14:50.238 5: Wetter: HandleSendQueue is using Cookie ci=TWC-Locale-Group=US&X-Origin-Hint=wu-next-prod&TWC-GeoIP-Country=DE&TWC-Privacy with path / and Value gdpr (key ci=TWC-Locale-Group=US&X-Origin-Hint=wu-next-prod&TWC-GeoIP-Country=DE&TWC-Privacy;/, destination path is /dashboard/pws/IMARL111)
2022.04.08 08:14:50.238 5: Wetter: HandleSendQueue is using Cookie speedpin with path / and Value 4G (key speedpin;/, destination path is /dashboard/pws/IMARL111)
2022.04.08 08:14:50.238 5: Wetter: DoCookies is adding Cookie header: ci=TWC-Locale-Group=US&X-Origin-Hint=wu-next-prod&TWC-GeoIP-Country=DE&TWC-Privacy=gdpr; speedpin=4G
2022.04.08 08:14:50.238 4: Wetter: HandleSendQueue sends update with timeout 10 to https://www.wunderground.com/dashboard/pws/IMARL111, No Data, ^M
header: Cookie: ci=TWC-Locale-Group=US&X-Origin-Hint=wu-next-prod&TWC-GeoIP-Country=DE&TWC-Privacy=gdpr; speedpin=4G
2022.04.08 08:14:50.238 5: HttpUtils url=https://www.wunderground.com/dashboard/pws/IMARL111 NonBlocking via https
2022.04.08 08:14:50.239 5: DNS QUERY 707201000001000000000000037777770c77756e64657267726f756e6403636f6d0000010001
2022.04.08 08:14:50.239 5: UPNPController: UPNPSocket-SYS_UPNP-1900, received message on port 1900 starting handleOnce
--- log skips    20.025 secs.
2022.04.08 08:15:10.265 5: UPNPController: warning: Carp, Loading device description failed with error: 500 Can't connect to 192.168.4.32:36566 (Connection timed out) (Location: http://192.168.4.32:36566/93b2abac-cb6a-4857-b891-002261914054.xml) at ./FHEM/98_UPNPController.pm line 403.

2022.04.08 08:15:10.266 4: UPNPController: UPNPSocket-SYS_UPNP-1900, received ssdp event: was checked by discoverCallback for removed or added devices against pending search requests
2022.04.08 08:15:10.266 5: Cmd: >{BlockingStart('902')}<
2022.04.08 08:15:10.268 5: Cmd: >{freezemon_freezeDone('myFreezemon')}<
2022.04.08 08:15:10.269 5: [Freezemon] myFreezemon: Blocking Call with PID 31778 ended
2022.04.08 08:15:10.271 5: [Freezemon] myFreezemon: ----------- Starting Freeze handling at 2022.04.08 08:15:10.271 ---------------------
2022.04.08 08:15:10.272 5: Freezemon: something went wrong FW_closeInactiveClients
[Freezemon] myFreezemon: possible freeze starting at 08:14:51, delay is 19.271 possibly caused by: tmr-CODE(0x430824c)(GetUpdate) tmr-FW_closeInactiveClients(N/A)


Code Auswählen Erweitern

=========================================================
[Freezemon] myFreezemon: possible freeze starting at 08:15:11, delay is 19.33 possibly caused by: tmr-UPNPController_renewSubscriptions(SYS_UPNP) tmr-CODE(0x2fb1d8c)(dnsQuery)
2022.04.08 08:15:10.297 4: BlockingCall (UPNPController_renewSubscriptionBlocking): created child (31832), uses telnetPort to connect back
2022.04.08 08:15:10.303 5: DNS ANSWER 137:707281800001000300000000037777770c77756e64657267726f756e6403636f6d0000010001c00c000500010000003c0022037777770c77756e64657267726f756e6403636f6d07656467656b6579036e657400c03200050001000013ba001906653131373739046473636a0a616b616d616965646765c04fc06000010001000000140004173910aa
2022.04.08 08:15:10.303 4: DNS result for www.wunderground.com: 23.57.16.170, ttl:20
2022.04.08 08:15:10.303 4: IP: www.wunderground.com -> 23.57.16.170
2022.04.08 08:15:10.304 5: UPNPController: UPNPSocket-SYS_UPNP-1900, received message on port 1900 starting handleOnce
--- log skips    20.025 secs.
2022.04.08 08:15:30.329 5: UPNPController: warning: Carp, Loading device description failed with error: 500 Can't connect to 192.168.4.32:36566 (Connection timed out) (Location: http://192.168.4.32:36566/93b2abac-cb6a-4857-b891-002261914054.xml) at ./FHEM/98_UPNPController.pm line 403.

2022.04.08 08:15:30.329 4: UPNPController: UPNPSocket-SYS_UPNP-1900, received ssdp event: was checked by discoverCallback for removed or added devices against pending search requests
2022.04.08 08:15:30.330 5: [Freezemon] myFreezemon: ----------- Starting Freeze handling at 2022.04.08 08:15:30.330 ---------------------
[Freezemon] myFreezemon: possible freeze starting at 08:15:11, delay is 19.33 possibly caused by: tmr-UPNPController_renewSubscriptions(SYS_UPNP) tmr-CODE(0x2fb1d8c)(dnsQuery)


Code Auswählen Erweitern

=========================================================
[Freezemon] myFreezemon: possible freeze starting at 08:15:31, delay is 19.405 possibly caused by: tmr-HttpUtils_TimeoutErr(N/A)
2022.04.08 08:15:30.361 4: BlockingCall (freezemon_processBlocking): created child (31838), uses telnetPort to connect back
2022.04.08 08:15:30.363 5: [Freezemon] myFreezemon: Blocking Call started with PID 31838
2022.04.08 08:15:30.365 4: extending 'connect to https://www.wunderground.com:443' timeout due to busy loop
2022.04.08 08:15:30.366 5: UPNPController: UPNPSocket-SYS_UPNP-1900, received message on port 1900 starting handleOnce
--- log skips    20.026 secs.
2022.04.08 08:15:50.392 5: UPNPController: warning: Carp, Loading device description failed with error: 500 Can't connect to 192.168.4.32:36566 (Connection timed out) (Location: http://192.168.4.32:36566/93b2abac-cb6a-4857-b891-002261914054.xml) at ./FHEM/98_UPNPController.pm line 403.

2022.04.08 08:15:50.393 4: UPNPController: UPNPSocket-SYS_UPNP-1900, received ssdp event: was checked by discoverCallback for removed or added devices against pending search requests
2022.04.08 08:15:50.395 4: Connection accepted from telnetPort_127.0.0.1_35136
2022.04.08 08:15:50.399 5: Wetter: ReadCallback called from HttpUtils_Connect2NonblockingSSL
2022.04.08 08:15:50.399 5: Wetter: Read callback Error LogLvl set to 3, regex
2022.04.08 08:15:50.399 3: Wetter: Read callback: Error:  SSL connect attempt failed
2022.04.08 08:15:50.399 4: Wetter: Read callback: request type was update retry 0, no headers, no body
2022.04.08 08:15:50.399 5: Wetter: Read callback: body empty
2022.04.08 08:15:50.399 4: Wetter: BodyDecode is not decoding the response body (charset not found, bodyDecode defaults to none)
2022.04.08 08:15:50.399 5: Wetter: GetCookies is looking for Cookies
2022.04.08 08:15:50.399 5: Wetter: ExtractSid called, context reading, num unknown
2022.04.08 08:15:50.399 4: Wetter: no header to look for redirects
2022.04.08 08:15:50.399 5: Wetter: Read callback sets LAST_REQUEST to update
2022.04.08 08:15:50.399 5: Wetter: CheckAuth decided no authentication required
2022.04.08 08:15:50.403 5: End notify loop for Wetter
2022.04.08 08:15:50.405 5: [Freezemon] myFreezemon: ----------- Starting Freeze handling at 2022.04.08 08:15:50.405 ---------------------
[Freezemon] myFreezemon: possible freeze starting at 08:15:31, delay is 19.405 possibly caused by: tmr-HttpUtils_TimeoutErr(N/A)