UPNPController, DLNAController und Multiroom

[KölnSolar]

Hi Michael,
dieser Thread nur für uns beide, um das ans Rennen zu kriegen.
Grüße
Markus

[MichaelT]

Fein,

Ich versuche gerade mit der munet app das zeugs wieder am laufen zu bekommen.
Problem war, das diese nur bis Android 6 läuft. Hab jetzt mein altes tablet wieder downgraded
Und kann wieder multiroom und stereo testen.

Ich versuche es nun nochmal zu sortieren.

[KölnSolar]

Ich kopier mal wesentliche alte Dinge der peaq munet. Geduld.

Du hast 3 Geräte
uuid:93b2abac-cb6a-4857-b891-Buero
uuid:93b2abac-cb6a-4857-b891-Schlafen
uuid:93b2abac-cb6a-4857-b891-Bad
(also offensichtlich 4 Gruppen fix und die letzte individuell für das physische device)

IPs sind fix, aber Ports wechseln im Betrieb.

Caskeid(aus event "Groups" von service SpeakerManagement)
<?xml version="1.0" ?><groups version="1.0"><group><id>4DAA44C0-8291-11E3-BAA7-0800200C9A66</id><name>Bluetooth</name></group></groups>
(und so wurde es im DLNARenderer geprüft: 4DAA44C0-8291-11E3-BAA7-0800200C9A66 Also zumindest bei peaq eine fixe id)

Code Auswählen Erweitern

services der Geräte
DLNA
- AVTransport
- RenderingControl
- SpeakerManagement
- SessionManagement
- ConnectionManager
unbekannt
- RTSPGateway
- NetworkManagement

SpeakerManagement http://IP:Port/xml/SpeakerManagement.xml

Code Auswählen Erweitern


<!-- ============================================================Title: UPnP SpeakerManagement Service TemplatePurpose:To identify the required/optional actions and state variablesand the required allowed values defined by this service type.This is a custom Pure Service designed to provide configurationmanagement options for Pure media renderer devices.Note:This file uses tabs (not spaces) for block indentation.Any updates to this file should maintain this convention.This includes disabling any automatic tab-to-space conversionfeature provided by your editor.================================================================ -->
<scpd xmlns="urn:schemas-upnp-org:service-1-0">
<specVersion>
<major>1</major>
<minor>0</minor>
</specVersion>
<serviceStateTable>
<stateVariable sendEvents="no">
<name>MCSType</name>
<dataType>string</dataType>
<allowedValueList>
<allowedValue>STEREO</allowedValue>
<allowedValue>STANDALONE</allowedValue>
</allowedValueList>
</stateVariable>
<stateVariable sendEvents="no">
<name>MCSID</name>
<dataType>string</dataType>
</stateVariable>
<stateVariable sendEvents="no">
<name>MCSFriendlyName</name>
<dataType>string</dataType>
</stateVariable>
<stateVariable sendEvents="no">
<name>SpeakerChannel</name>
<dataType>string</dataType>
<allowedValueList>
<allowedValue>LEFT_FRONT</allowedValue>
<allowedValue>RIGHT_FRONT</allowedValue>
<allowedValue>STANDALONE_SPEAKER</allowedValue>
</allowedValueList>
</stateVariable>
<stateVariable sendEvents="no">
<name>SpeakerOrientation</name>
<dataType>string</dataType>
<allowedValueList>
<allowedValue>HORIZONTAL</allowedValue>
<allowedValue>VERTICAL</allowedValue>
</allowedValueList>
</stateVariable>
<stateVariable sendEvents="no">
<name>A_ARG_TYPE_GroupID</name>
<dataType>string</dataType>
</stateVariable>
<stateVariable sendEvents="no">
<name>A_ARG_TYPE_GroupName</name>
<dataType>string</dataType>
</stateVariable>
<stateVariable sendEvents="no">
<name>A_ARG_TYPE_GroupMetadata</name>
<dataType>string</dataType>
</stateVariable>
<stateVariable sendEvents="yes">
<name>Groups</name>
<dataType>string</dataType>
</stateVariable>
<stateVariable sendEvents="no">
<name>A_ARG_Type_IdentifyPattern</name>
<dataType>string</dataType>
<allowedValueList>
<allowedValue>DEFAULT</allowedValue>
</allowedValueList>
</stateVariable>
<stateVariable sendEvents="yes">
<name>SessionID</name>
<dataType>string</dataType>
</stateVariable>
</serviceStateTable>
<actionList>
<action>
<name>SetMultiChannelSpeaker</name>
<argumentList>
<argument>
<name>NewMCSType</name>
<direction>in</direction>
<relatedStateVariable>MCSType</relatedStateVariable>
</argument>
<argument>
<name>NewMCSID</name>
<direction>in</direction>
<relatedStateVariable>MCSID</relatedStateVariable>
</argument>
<argument>
<name>NewMCSFriendlyName</name>
<direction>in</direction>
<relatedStateVariable>MCSFriendlyName</relatedStateVariable>
</argument>
<argument>
<name>NewSpeakerChannel</name>
<direction>in</direction>
<relatedStateVariable>SpeakerChannel</relatedStateVariable>
</argument>
</argumentList>
</action>
<action>
<name>GetMultiChannelSpeaker</name>
<argumentList>
<argument>
<name>CurrentMCSType</name>
<direction>out</direction>
<relatedStateVariable>MCSType</relatedStateVariable>
</argument>
<argument>
<name>CurrentMCSID</name>
<direction>out</direction>
<relatedStateVariable>MCSID</relatedStateVariable>
</argument>
<argument>
<name>CurrentMCSFriendlyName</name>
<direction>out</direction>
<relatedStateVariable>MCSFriendlyName</relatedStateVariable>
</argument>
<argument>
<name>CurrentSpeakerChannel</name>
<direction>out</direction>
<relatedStateVariable>SpeakerChannel</relatedStateVariable>
</argument>
</argumentList>
</action>
<action>
<name>SetSpeakerOrientation</name>
<argumentList>
<argument>
<name>NewSpeakerOrientation</name>
<direction>in</direction>
<relatedStateVariable>SpeakerOrientation</relatedStateVariable>
</argument>
</argumentList>
</action>
<action>
<name>GetSpeakerOrientation</name>
<argumentList>
<argument>
<name>CurrentSpeakerOrientation</name>
<direction>out</direction>
<relatedStateVariable>SpeakerOrientation</relatedStateVariable>
</argument>
</argumentList>
</action>
<action>
<name>IdentifyMe</name>
<argumentList>
<argument>
<name>IdentifyPattern</name>
<direction>in</direction>
<relatedStateVariable>A_ARG_Type_IdentifyPattern</relatedStateVariable>
</argument>
</argumentList>
</action>
<action>
<name>AddToGroup</name>
<argumentList>
<argument>
<name>ID</name>
<direction>in</direction>
<relatedStateVariable>A_ARG_TYPE_GroupID</relatedStateVariable>
</argument>
<argument>
<name>Name</name>
<direction>in</direction>
<relatedStateVariable>A_ARG_TYPE_GroupName</relatedStateVariable>
</argument>
<argument>
<name>Metadata</name>
<direction>in</direction>
<relatedStateVariable>A_ARG_TYPE_GroupMetadata</relatedStateVariable>
</argument>
</argumentList>
</action>
<action>
<name>RemoveFromGroup</name>
<argumentList>
<argument>
<name>ID</name>
<direction>in</direction>
<relatedStateVariable>A_ARG_TYPE_GroupID</relatedStateVariable>
</argument>
</argumentList>
</action>
<action>
<name>GetGroups</name>
<argumentList>
<argument>
<name>CurrentGroups</name>
<direction>out</direction>
<relatedStateVariable>Groups</relatedStateVariable>
</argument>
</argumentList>
</action>
<action>
<name>GetSession</name>
<argumentList>
<argument>
<name>SessionID</name>
<direction>out</direction>
<relatedStateVariable>SessionID</relatedStateVariable>
</argument>
</argumentList>
</action>
<action>
<name>SetSession</name>
<argumentList>
<argument>
<name>SessionID</name>
<direction>in</direction>
<relatedStateVariable>SessionID</relatedStateVariable>
</argument>
</argumentList>
</action>
<action>
<name>ClearSession</name>
<argumentList>
<argument>
<name>SessionID</name>
<direction>in</direction>
<relatedStateVariable>SessionID</relatedStateVariable>
</argument>
</argumentList>
</action>
</actionList>
</scpd>


events:
- <stateVariable sendEvents="yes"> <name>Groups</name> <dataType>string</dataType> </stateVariable>
- <stateVariable sendEvents="yes"> <name>SessionID</name> <dataType>string</dataType> </stateVariable>
actions:
- Set(Get)MultiChannelSpeaker, Set(Get)SpeakerOrientation, IdentifyMe, AddTo(RemoveFrom)Group,GetGroups,Set(Get,Clear)Session

SessionManagment  http://IP:Port/xml/SessionManagment.xml

Code Auswählen Erweitern


<!-- ============================================================Title: UPnP Session Management Service TemplatePurpose:To identify the required/optional actions and state variablesand the required allowed values defined by this service type.This is a custom Pure Service designed to allow Control Pointsto create/destroy a session and to add/remove UPnP media renderers toand from a session.Note:This file uses tabs (not spaces) for block indentation.Any updates to this file should maintain this convention.This includes disabling any automatic tab-to-space conversionfeature provided by your editor.================================================================ -->
<scpd xmlns="urn:schemas-upnp-org:service-1-0">
<specVersion>
<major>1</major>
<minor>0</minor>
</specVersion>
<serviceStateTable>
<stateVariable sendEvents="yes">
<name>SessionID</name>
<dataType>string</dataType>
</stateVariable>
<stateVariable sendEvents="no">
<name>SessionMetadata</name>
<dataType>string</dataType>
</stateVariable>
<stateVariable sendEvents="no">
<name>A_ARG_TYPE_UUID</name>
<dataType>string</dataType>
</stateVariable>
</serviceStateTable>
<actionList>
<action>
<name>CreateSession</name>
<argumentList>
<argument>
<name>SessionID</name>
<direction>out</direction>
<relatedStateVariable>SessionID</relatedStateVariable>
</argument>
<argument>
<name>Metadata</name>
<direction>in</direction>
<relatedStateVariable>SessionMetadata</relatedStateVariable>
</argument>
</argumentList>
</action>
<action>
<name>GetSession</name>
<argumentList>
<argument>
<name>SessionID</name>
<direction>out</direction>
<relatedStateVariable>SessionID</relatedStateVariable>
</argument>
<argument>
<name>Metadata</name>
<direction>out</direction>
<relatedStateVariable>SessionMetadata</relatedStateVariable>
</argument>
</argumentList>
</action>
<action>
<name>DestroySession</name>
<argumentList>
<argument>
<name>SessionID</name>
<direction>in</direction>
<relatedStateVariable>SessionID</relatedStateVariable>
</argument>
</argumentList>
</action>
<action>
<name>AddUnitToSession</name>
<argumentList>
<argument>
<name>SessionID</name>
<direction>in</direction>
<relatedStateVariable>SessionID</relatedStateVariable>
</argument>
<argument>
<name>UUID</name>
<direction>in</direction>
<relatedStateVariable>A_ARG_TYPE_UUID</relatedStateVariable>
</argument>
</argumentList>
</action>
<action>
<name>RemoveUnitFromSession</name>
<argumentList>
<argument>
<name>SessionID</name>
<direction>in</direction>
<relatedStateVariable>SessionID</relatedStateVariable>
</argument>
<argument>
<name>UUID</name>
<direction>in</direction>
<relatedStateVariable>A_ARG_TYPE_UUID</relatedStateVariable>
</argument>
</argumentList>
</action>
</actionList>
</scpd>


event: <stateVariable sendEvents="yes"> <name>SessionID</name><dataType>string</dataType></stateVariable>
actions: Create(Get,Destroy)Session,AddUnitTo(RemoveUnitFrom)Session

subscription u. events SessionManagement SpeakerManagement

Code Auswählen Erweitern

2021.03.10 19:16:23.660 4: UPNPController: subscribe: reading  IP_Port-zs-SessionManagement, uniquedevice IP_Port, service SessionManagement
2021.03.10 19:16:23.661 5: UPNPController: SessionManagement: urn:schemas-pure-com:service:SessionManagement:1 found. OK.
2021.03.10 19:16:23.661 5: UPNPController: SessionManagement: urn:schemas-pure-com:service:SessionManagement:1 found. OK.
2021.03.10 19:16:23.840 5: UPNPController: Received event: by IP_Port-zs-SessionManagement UPnP::ControlPoint::Service=HASH(0x74c7f94) $VAR1 = 'SessionID';
$VAR2 = '';

2021.03.10 19:16:23.840 5: UPNPController: Received event: by IP_Port-zs-SessionManagement original property:
2021.03.10 19:16:23.840 5: UPNPController: Received event: by IP_Port-zs-SessionManagement property:
2021.03.10 19:16:23.854 5: UPNPController: SYS_UPNP: event of service urn:schemas-upnp-org:metadata-1-0/RCS, message
2021.03.10 19:16:23.854 5: UPNPController: SYS_UPNP: event of service urn:schemas-upnp-org:metadata-1-0/AVT, message
2021.03.10 19:16:23.854 4: UPNPController: SYS_UPNP: service  event SessionID not yet implemented
2021.03.10 19:16:50.870 4: UPNPController: subscribe: reading  IP_Port-zs-SpeakerManagement, uniquedevice IP_Port, service SpeakerManagement
2021.03.10 19:16:50.870 5: UPNPController: SpeakerManagement: urn:schemas-pure-com:service:SpeakerManagement:1 found. OK.
2021.03.10 19:16:50.871 5: UPNPController: SpeakerManagement: urn:schemas-pure-com:service:SpeakerManagement:1 found. OK.
2021.03.10 19:16:51.112 5: UPNPController: Received event: by IP_Port-zs-SpeakerManagement UPnP::ControlPoint::Service=HASH(0x21debe0) $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>';

2021.03.10 19:16:51.113 5: UPNPController: Received event: by IP_Port-zs-SpeakerManagement original property:
2021.03.10 19:16:51.113 5: UPNPController: Received event: by IP_Port-zs-SpeakerManagement property:
2021.03.10 19:16:51.126 5: UPNPController: SYS_UPNP: event of service urn:schemas-upnp-org:metadata-1-0/RCS, message
2021.03.10 19:16:51.126 5: UPNPController: SYS_UPNP: event of service urn:schemas-upnp-org:metadata-1-0/AVT, message
2021.03.10 19:16:51.126 4: UPNPController: SYS_UPNP: service  event SessionID not yet implemented
2021.03.10 19:16:51.126 5: UPNPController: Received event: by IP_Port-zs-SpeakerManagement original property: <?xml version="1.0" ?><groups version="1.0"><group><id>4DAA44C0-8291-11E3-BAA7-0800200C9A66</id><name>Bluetooth</name></group></groups>
2021.03.10 19:16:51.127 5: UPNPController: Received event: by IP_Port-zs-SpeakerManagement property: <?xml version="1.0" ?><groups version="1.0"><group><id>4DAA44C0-8291-11E3-BAA7-0800200C9A66</id><name>Bluetooth</name></group></groups>
2021.03.10 19:16:51.127 5: UPNPController: SYS_UPNP: event of service urn:schemas-upnp-org:metadata-1-0/RCS, message <?xml version="1.0" ?><groups version="1.0"><group><id>4DAA44C0-8291-11E3-BAA7-0800200C9A66</id><name>Bluetooth</name></group></groups>
2021.03.10 19:16:51.127 5: UPNPController: SYS_UPNP: event of service urn:schemas-upnp-org:metadata-1-0/AVT, message <?xml version="1.0" ?><groups version="1.0"><group><id>4DAA44C0-8291-11E3-BAA7-0800200C9A66</id><name>Bluetooth</name></group></groups>
2021.03.10 19:16:51.127 4: UPNPController: SYS_UPNP: service <?xml version="1.0" ?><groups version="1.0"><group><id>4DAA44C0-8291-11E3-BAA7-0800200C9A66</id><name>Bluetooth</name></group></groups> event Groups not yet implemented

[KölnSolar]

Hi Michael,

so ganz verstehe ich Dominiks Ansatz nicht. Er nutzt caskeid als Multiroom-Indikator. Ich hab jetzt mal das event groups vom speakermanagement genommen.

Vielleicht bekommst Du ja mit der Äpp etwas mehr Klarheit, ob die speaker über Bluetooth verbunden sind oder nicht bzw. einer konkreteren Bedeutung von caskeid.

Attached die aktuellen  Testversionen. reload sollte genügen.

Grüße Markus

Edit: temporary modul versions removed

[MichaelT]

Morgen Markus,

danke für deine Erläuterung.

Zu den PMN300 und der Äpp:
Es gibt drei Feature bei diesen Dingern:

• Multiroom über app (hier wird die SessionID verwendet)
• Multiroom über BT (Caskeid, hier wird die Group verwendet)
• Stereo-Paare über app (man kann zwei devices als Stereo-Paar konfigurieren)

Zur MR BT:
In jedem Device kann man BT Caskeid aktivieren, dann wird die von dir bereits benannte GroupID eingetragen. Koppelt man nun eine
BT-Quelle mit einem Lautsprecher, spielt diese den Stream. Schaltet man bei einem weiteren Device BT-Caskeid ein, holt sich dieser anscheinend über die
GroupID mittels "rtsp://ip:8554/stream" den Stream und spielt in auch ab. Jedes weitere mach es auch so.

Zu MR App:
Man kann einen Stream von der App auf einem Device abspielen. Mit CheckBoxen kann ich weitere Devices hinzu schalten.
Hier ist es anscheinend so, dass die App beim ersten Stream eine SessionID im Device erzeugt und alle weiteren Devices den "Master" über die SessionID ermitteln und dann im Master das RTSPGateway enabled und im Salve mittels rtsp://ip-master der Stream geholt und abgespielt.

Zu Stereo-Paare:
In der App kann man von den verfügbaren devices ein oder mehrere Stereo-Paare bilden. Man wählt den Master, dann das Linke und Rechte device, wobei einer der Beiden der Master sein muss. Nun wird im Master das RTSPGateway enabled und im Salve mittels rtsp://ip-master der Stream geholt und abgespielt. Ich vermute, das die App links und rechts aufteilt und einen Kanal direkt an den Master und den zweiten Kanal über den Master (Gateway) zum Slave schickt. Balance wird und der App angeboten und regelt dies über Volume der devices.
Im SpeakerMgm kann man mit Set/GetMultiChannelSpeaker kann man den Mode (STEREO), den Name der Gruppe, die Aufgabe (Links/Rechts) und eine MultiChannelSpeakerSessionID setzen/ermitteln. Die normale SessionID ist auch gesetzt, unterscheidet sich aber von der MCSP-ID

Anmerkung:
- Alles nur Vermutungen nach der Analyse der UPnP-Abfragen, ggf. noch etwas falsch.
- mute funktioniert nun, danke

Weitere Infos auf Nachfrage, wie du bemerkt hast, habe ich immer ein wenig Reaktionszeit

Gruß Michael.

[KölnSolar]

wie du bemerkt hast, habe ich immer ein wenig Reaktionszeit

So ist das bei Hobbies.

Das verstehe ich dann so, dass wir Bt enable/disable können sollten und den entsprechenden state anzeigen.

Für 1./3. multiroom/stereo. Dafür sind dann die anderen Funktionen also. Die groups für eine allgemeine Definition(Kopplung von Speakern) und die session-id, wenn tatsächlich etwas abgespielt wird. Das erfolgt dann für alle speaker der group. Und stereo ist vermutlich der Sonderfall dazu.

Dann guck mal, ob Du jetzt etwas hinbekommst...

Ich ändere mal die Zuordnung der setter.

Sowas wie Jens bei den Teufeln(virtual devices) hast Du nicht, oder ? Immer nur 1 FHEM-device/physischem-speaker ?

Weiter sonnigen Sonntag
Markus

[MichaelT]

Code Auswählen Erweitern

Das verstehe ich dann so, dass wir Bt enable/disable können sollten und den entsprechenden state anzeigen.
Ja.

Code Auswählen Erweitern

Für 1./3. multiroom/stereo. Dafür sind dann die anderen Funktionen also. Die groups für eine allgemeine Definition(Kopplung von Speakern) und die session-id, wenn tatsächlich etwas abgespielt wird. Das erfolgt dann für alle speaker der group. Und stereo ist vermutlich der Sonderfall dazu.
Also bei MR und ST sind die groups im SpeakerMgm außen vor. Du meinst aber die "caskeidClients" im Module, oder? Das geht alles über die sessionId.

[KölnSolar]

Nein, ich meinte schon die groups.

Wenn alle speaker aus sind, dann gibt es doch vermutlich keine session-id. Erst, wenn etwas gestreamed wird. Und dann kann man erst einen weiteren speaker verknüpfen ? Ich hätte gedacht, dass das die Gruppen sind und man startet mit "stream auf Gruppe1".

[MichaelT]

Hallo Markus,

erster Zwischenstand:

+ Ich habe noch caskeid auf 1 gesetzt, damit auch addUnit und removeUnit usw. funktioniert.
+ also add und remove funktionieren dann
+ Ich habe noch "DLNAController_addUnit" erweitert, so dass die multiRoomUnits korrekt ergänzt werden. Bei playEverywherer wurde dies schon gemacht. Kann man wahrscheinlich dann besser in einer Funktion auslagern.

- multiRoomVolume macht noch seltsame Effekte (device kurz offline)
- die SessionID wird noch nicht in fhem übernommen, angezeigt

Diff gegen deiner letzten Version

Code Auswählen Erweitern

528,533c528
<
<       my $multiRoomUnits = ReadingsVal($hash->{NAME}, "multiRoomUnits", "");
<
<       $multiRoomUnits .= "," if($multiRoomUnits ne "");
<       $multiRoomUnits .= ReadingsVal($client->{NAME}, "friendlyName", "");
<       readingsSingleUpdate($hash, "multiRoomUnits", $multiRoomUnits, 1);
---
>       DLNAController_updateMultiRoomUnits($hash,$client);
558a554
>       DLNAController_updateMultiRoomUnits($hash,$client);
563a560,573
>
> sub DLNAController_updateMultiRoomUnits {
>
>   my ($hash, $client) = @_;
>
>   my $multiRoomUnits = ReadingsVal($hash->{NAME}, "multiRoomUnits", "");
>
>   $multiRoomUnits .= "," if($multiRoomUnits ne "");
>   $multiRoomUnits .= ReadingsVal($client->{NAME}, "friendlyName", "");
>   readingsSingleUpdate($hash, "multiRoomUnits", $multiRoomUnits, 1);
>
>   return undef;
> }
>
904a915
>     $hash->{helper}{caskeid} = 1;
1235a1247



Edit: Nachtrag log SessionID

Code Auswählen Erweitern

2022.02.13 17:55:01.877 5: UPNPController: Received event: by 192.168.4.31_46544-zs-SpeakerManagement UPnP::ControlPoint::Service=HASH(0x3006460) $VAR1 = 'Groups';
$VAR2 = '<?xml version="1.0" ?><groups version="1.0"></groups>';
$VAR3 = 'SessionID';
$VAR4 = '96791177-a26a-441b-887e-cb89dff636f2';

2022.02.13 17:55:01.878 5: UPNPController: SYS_UPNP: event of service SpeakerManagement, message <?xml version="1.0" ?><groups version="1.0"></groups>
2022.02.13 17:55:01.878 5: SYS_UPNP: dispatch SpeakerManagement|192.168.4.31_46544|Groups|<?xml version="1.0" ?><groups version="1.0"></groups>
2022.02.13 17:55:01.878 4: DLNAController: message from SYS_UPNP, message: SpeakerManagement|192.168.4.31_46544|Groups|<?xml version="1.0" ?><groups version="1.0"></groups>
2022.02.13 17:55:01.878 5: DLNAController: message parameters: SpeakerManagement, 192.168.4.31_46544, Groups, <?xml version="1.0" ?><groups version="1.0"></groups>
2022.02.13 17:55:01.879 5: DLNAController: OG_SZ_MR process property Groups, xml-event <?xml version="1.0" ?><groups version="1.0"></groups>
2022.02.13 17:55:01.879 4: DLNAController: OG_SZ_MR parsing did enter load_xml call: <?xml version="1.0" ?><groups version="1.0"></groups>
2022.02.13 17:55:01.880 4: DLNAController OG_SZ_MR: state update from SYS_UPNP, address 192.168.4.31_46544
2022.02.13 17:55:01.895 5: UPNPController: SYS_UPNP: event of service SpeakerManagement, message 96791177-a26a-441b-887e-cb89dff636f2
2022.02.13 17:55:01.895 5: UPNPController: SYS_UPNP: event of service RenderingControl, message 96791177-a26a-441b-887e-cb89dff636f2
2022.02.13 17:55:01.895 5: UPNPController: SYS_UPNP: event of service AVTransport, message 96791177-a26a-441b-887e-cb89dff636f2
2022.02.13 17:55:01.895 3: UPNPController: SYS_UPNP: uniqueDeviceName 192.168.4.31_46544 event SessionID not yet implemented
2022.02.13 17:55:01.895 4: UPNPController: SYS_UPNP: uniqueDeviceName 192.168.4.31_46544 event details: $VAR1 = '96791177-a26a-441b-887e-cb89dff636f2';

2022.02.13 17:55:01.940 5: UPNPController: Received event: by 192.168.4.31_46544-zs-SessionManagement UPnP::ControlPoint::Service=HASH(0x302f540) $VAR1 = 'SessionID';
$VAR2 = '';

2022.02.13 17:55:01.940 5: UPNPController: SYS_UPNP: empty event SessionID found
2022.02.13 17:55:01.943 5: SYS_UPNP: dispatch SessionManagement|192.168.4.31_46544|SessionID|
2022.02.13 17:55:01.943 4: DLNAController: message from SYS_UPNP, message: SessionManagement|192.168.4.31_46544|SessionID|
2022.02.13 17:55:01.944 5: DLNAController: message parameters: SessionManagement, 192.168.4.31_46544, SessionID,
2022.02.13 17:55:01.944 5: DLNAController: OG_SZ_MR process property SessionID, xml-event
2022.02.13 17:55:01.944 4: DLNAController OG_SZ_MR: state update from SYS_UPNP, address 192.168.4.31_46544



Edit2:
Hiermit geht nun auch multiRoomVolume

Code Auswählen Erweitern

455a456,465
> sub DLNAController_getHashByFriendlyName {
>   my ($hash, $friendlyName) = @_;
>
>   foreach my $fhem_dev (sort keys %main::defs) {
>     my $devHash = $main::defs{$fhem_dev};
>     return $devHash if($devHash->{TYPE} eq 'DLNAController' && ReadingsVal($devHash->{NAME}, "friendlyName", "") eq $friendlyName);
>   }
>
>   return undef;
> }

Sieht schon nicht schlecht aus
Gruß
Michael

[KölnSolar]

Hallo Michael,

ich hab jetzt noch einmal "Trockentests" gemacht.

Demnach ist "multiroom" wie folgt charakterisiert

Code Auswählen Erweitern

readings: multiRoomUnits - devices einer session(ihr friendlyName)
UPNP service: SessionManagement actions: GetSession, CreateSession, AddUnitToSession, RemoveUnitFromSession, DestroySession

zusätzl FHEM-Funktionen setMultiRoomVolume (reading multiRoomVolume) über service RenderingControl

- multiRoomVolume wird derzeit falsch gesetzt
- sinnvoll wäre dann auch eine setMultiRoomMute Funktion

und "Mono, Stereo" wie folgt

Code Auswählen Erweitern

UPNP service: SpeakerManagement actions: GetMultiChannelSpeaker, SetMultiChannelSpeaker
readings: stereoLeft, stereoRight - friendlyName des devices; stereoPairName - friendly name; stereoId; stereoSupport 0/1
               stereoPairName, stereoId, stereoSupport werden per internaltimer ausgelesen

- der internal timer wird derzeit nicht gestartet, also gibt es diese 3 readings auch nicht
- ich spekuliere, dass mute hier "irgendwie" per direkter Kommunikation funktioniert ? 

Zu groups hab ich jetzt noch nichts geprüft. Ist mir noch unklar.

Ich habe noch caskeid auf 1 gesetzt

Das verstehe ich, um die Funktionalität zu erreichen. Aber ich halte es für falsch. caskeid ist ja ungleich multiroom(und multiroom ohne Bt gibt's bestimmt auch).
Im Modul müsste also alles mögliche von caskeid in multiroom geändert werden. Verstehst Du, was ich meine ?

Grüße Markus

[MichaelT]

Hallo Markus,

Code Auswählen Erweitern

Das verstehe ich, um die Funktionalität zu erreichen. Aber ich halte es für falsch. caskeid ist ja ungleich multiroom(und multiroom ohne Bt gibt's bestimmt auch).
Im Modul müsste also alles mögliche von caskeid in multiroom geändert werden. Verstehst Du, was ich meine ?


Ja, bin ich bei dir. caskeid nur auf true, damit die restlichen set/get da sind.

Code Auswählen Erweitern


- multiRoomVolume wird derzeit falsch gesetzt
- sinnvoll wäre dann auch eine setMultiRoomMute Funktion

Ja, passt auch.

Code Auswählen Erweitern

- der internal timer wird derzeit nicht gestartet, also gibt es diese 3 readings auch nicht
- ich spekuliere, dass mute hier "irgendwie" per direkter Kommunikation funktioniert ?

- Timer hatte ich auch schon bemerkt, wusste aber nicht, wo man ihn am besten startet.
- mute hatte mit dem alten Mudul funktioniert (nur ein Hinweis)

Was auch noch unklar ist:
- Reading sessionId wird nicht gesetzt (blick nicht ganz durch, warum nicht). Das sorgt glaube ich dafür, dass z.B. ein set stream ... den multiplay beendet
weil bei AVT_play eine neue sessionId generiert wird.
- addUnit sollte normalerweise alle multiroom devices zur Auswahl anbieten, macht es aber nicht.

Gruß Michael

[KölnSolar]

Hallo Michael,

caskeid nur auf true, damit die restlichen set/get da sind

Dann hast Du mich doch nicht ganz verstanden. Nicht caskeid(die Bluetooth-group) ist der Indikator, sondern das Vorhandensein des service SessionManagment(oder SpeakerManagement; ich gehe davon aus, dass es beide services für multiroom entweder gibt oder eben nicht)
Ich würde dann einfach nur die Variablennamen etc. von caskeid in multiroom ändern, damit dass Modul "leserlicher" wird. caskeid würd ich dann nur noch für den Kontext benutzen, wie wir uns oben bereits geeinigt hatten.

Code Auswählen Erweitern


- multiRoomVolume wird derzeit falsch gesetzt
- sinnvoll wäre dann auch eine setMultiRoomMute Funktion
würde ich gleichzeitig einbauen.

Code Auswählen Erweitern

- Timer hatte ich auch schon bemerkt, wusste aber nicht, wo man ihn am besten startet.
- mute hatte mit dem alten Mudul funktioniert (nur ein Hinweis)ebenso.

auch

Reading sessionId wird nicht gesetzt (blick nicht ganz durch, warum nicht). Das sorgt glaube ich dafür, dass z.B. ein set stream ... den multiplay beendet
weil bei AVT_play eine neue sessionId generiert wird.
- addUnit sollte normalerweise alle multiroom devices zur Auswahl anbieten, macht es aber nicht.

Ich komm mit Deinen diffs nie so richtig klar, weil ich meist auch schon weiterentwickelt habe. Das obige ist mir insofern klar, dass Du aus ein paar Zeilen eine Funktion gemacht hast und durch den Funktionsaufruf ersetzt hast. Wo aber der neue zusätzliche Funktionsaufruf hin muss, ist mir unklar. Kannst Du mir das einfach als komplette sub einstellen. Und helper->caskeid ändere ich so natürlich nicht. 

Am We gibt's dann die neue Version für Dich und dann sollten wir schon recht gut vorangekommen sein und nachvollziehbareres Coding haben.

Grüße Markus

[MichaelT]

Hi,

updateMultiRoomUnits war quasi in playEverywhere drin, musste aber zusätzlich in addUnit auch rein.

Code Auswählen Erweitern

sub DLNAController_playEverywhere {
  my ($hash) = @_;
  my $multiRoomUnits = "";
  my @caskeidClients = DLNAController_caskeidClients($hash);
  foreach my $client (@caskeidClients) {
    if($client->{UDN} ne $hash->{UDN}) {
      DLNAController_addUnitToPlay($hash, substr($client->{UDN},5));
----->      DLNAController_updateMultiRoomUnits($hash,$client);
    }
  }
  return undef;
}

sub DLNAController_stopPlayEverywhere {
  my ($hash) = @_;
  DLNAController_destroyCurrentSession($hash);
  readingsSingleUpdate($hash, "multiRoomUnits", "", 1);
  return undef;
}

sub DLNAController_addUnit {
  my ($hash, $unitName) = @_;

  my @caskeidClients = DLNAController_caskeidClients($hash);
  foreach my $client (@caskeidClients) {
    if(ReadingsVal($client->{NAME}, "friendlyName", "") eq $unitName) {
      my @multiRoomUnits = split(",", ReadingsVal($hash->{NAME}, "multiRoomUnits", ""));
      foreach my $unit (@multiRoomUnits) {
        #skip if unit is already part of the session
        return undef if($unit eq $unitName);
      }
      #add unit to session
      DLNAController_addUnitToPlay($hash, substr($client->{UDN},5));
---->      DLNAController_updateMultiRoomUnits($hash,$client);
      return undef;
    }
  }
  return "DLNAController: No unit $unitName found.";
}

sub DLNAController_updateMultiRoomUnits {

  my ($hash, $client) = @_;

  my $multiRoomUnits = ReadingsVal($hash->{NAME}, "multiRoomUnits", "");

  $multiRoomUnits .= "," if($multiRoomUnits ne "");
  $multiRoomUnits .= ReadingsVal($client->{NAME}, "friendlyName", "");
  readingsSingleUpdate($hash, "multiRoomUnits", $multiRoomUnits, 1);

  return undef;
}


Dann hast Du mich doch nicht ganz verstanden

Glaube ich schon, habe mich bloß doof ausgedrückt.

Gruß Michael

[KölnSolar]

ich kämpfe noch mit den events 
nur zur Doku aus dem anderen Thread(bewusst ohne RenderingControl/AVTransport)

Code Auswählen Erweitern

2022.02.05 09:53:28.606 5: SYS_UPNP: dispatch SpeakerManagement|IP_Port|online|groups
2022.02.05 09:53:28.606 4: DLNAController: message from SYS_UPNP, message: SpeakerManagement|IP_Port|online|groups
2022.02.05 09:53:28.606 5: DLNAController: message parameters: SpeakerManagement, IP_Port, online, groups

2022.02.05 09:53:30.185 5: UPNPController: SYS_UPNP, IP_Port, SpeakerManagement, subscribe,
2022.02.05 09:53:30.185 5: UPNPController: SpeakerManagement: urn:pure-com:serviceId:SpeakerManagement found. OK.
2022.02.05 09:53:30.185 4: UPNPController: subscribe: reading  IP_Port-zs-SpeakerManagement, uniquedevice IP_Port, service SpeakerManagement
2022.02.05 09:53:30.186 5: UPNPController: SpeakerManagement: urn:pure-com:serviceId:SpeakerManagement found. OK.
2022.02.05 09:53:30.382 4: UPNPController: subscribe: reading  IP_Port-zs-SpeakerManagement, uniquedevice IP_Port, service SpeakerManagement timeout: 300

2022.02.05 09:53:30.400 5: UPNPController: SYS_UPNP, IP_Port, SessionManagement, subscribe,
2022.02.05 09:53:30.400 5: UPNPController: SessionManagement: urn:pure-com:serviceId:SessionManagement found. OK.
2022.02.05 09:53:30.400 4: UPNPController: subscribe: reading  IP_Port-zs-SessionManagement, uniquedevice IP_Port, service SessionManagement
2022.02.05 09:53:30.401 5: UPNPController: SessionManagement: urn:pure-com:serviceId:SessionManagement found. OK.
2022.02.05 09:53:30.506 4: UPNPController: subscribe: reading  IP_Port-zs-SessionManagement, uniquedevice IP_Port, service SessionManagement timeout: 300

2022.02.05 09:53:30.652 5: SYS_UPNP: dispatch SpeakerManagement|IP_Port|Groups|<?xml version="1.0" ?><groups version="1.0"></groups>
2022.02.05 09:53:30.652 4: DLNAController: message from SYS_UPNP, message: SpeakerManagement|IP_Port|Groups|<?xml version="1.0" ?><groups version="1.0"></groups>
2022.02.05 09:53:30.652 5: DLNAController: message parameters: SpeakerManagement, IP_Port, Groups, <?xml version="1.0" ?><groups version="1.0"></groups>

2022.02.05 09:53:30.655 5: UPNPController: SYS_UPNP: empty event SessionID found
2022.02.05 09:53:30.655 5: SYS_UPNP: dispatch SessionManagement|IP_Port|SessionID|
2022.02.05 09:53:30.655 4: DLNAController: message from SYS_UPNP, message: SessionManagement|IP_Port|SessionID|
2022.02.05 09:53:30.656 5: DLNAController: message parameters: SessionManagement, IP_Port, SessionID,

2022.02.05 09:53:30.696 5: UPNPController: Received event: by IP_Port-zs-SessionManagement UPnP::ControlPoint::Service=HASH(0x2a7e630) $VAR1 = 'SessionID';
$VAR2 = '';

2022.02.05 09:53:30.713 5: UPNPController: SYS_UPNP: empty event SessionID found
2022.02.05 09:53:30.714 5: SYS_UPNP: dispatch SessionManagement|IP_Port|SessionID|
2022.02.05 09:53:30.714 4: DLNAController: message from SYS_UPNP, message: SessionManagement|IP_Port|SessionID|
2022.02.05 09:53:30.714 5: DLNAController: message parameters: SessionManagement, IP_Port, SessionID,

Mich wundert

Sieht schon nicht schlecht aus

Der UPNPController dispatched bei meinen "Trockentests" doch gar keine SessionId(bzw. dispatched nur, wenn SessionId leer ist). 

Hast Du einen Log-Auszug, dass ich damit falsch liege ?

Grüße Markus

Edit: Jetzt bin ich gespannt, was die neuen Versionen bei Dir so machen. 

[MichaelT]

Hallo Markus,

Hast Du einen Log-Auszug, dass ich damit falsch liege ?

Meinst Du sowas?

Code Auswählen Erweitern

2022.02.19 11:06:58.725 5: UPNPController: Received event: by 192.168.4.32_48846-zs-SessionManagement UPnP::ControlPoint::Service=HASH(0x404b248) $VAR1 = 'SessionID';
$VAR2 = '6ea8f38b-bc3d-4920-b5fb-517d956c777d';

2022.02.19 11:06:58.726 5: UPNPController: SYS_UPNP: event of service SpeakerManagement, message 6ea8f38b-bc3d-4920-b5fb-517d956c777d
2022.02.19 11:06:58.726 5: UPNPController: SYS_UPNP: event of service AVTransport, message 6ea8f38b-bc3d-4920-b5fb-517d956c777d
2022.02.19 11:06:58.727 5: UPNPController: SYS_UPNP: event of service RenderingControl, message 6ea8f38b-bc3d-4920-b5fb-517d956c777d
2022.02.19 11:06:58.727 3: UPNPController: SYS_UPNP: uniqueDeviceName 192.168.4.32_48846 event SessionID not yet implemented
2022.02.19 11:06:58.728 4: UPNPController: SYS_UPNP: uniqueDeviceName 192.168.4.32_48846 event details: $VAR1 = '6ea8f38b-bc3d-4920-b5fb-517d956c777d';

2022.02.19 11:06:58.840 5: UPNPController: Received event: by 192.168.4.32_48846-zs-SpeakerManagement UPnP::ControlPoint::Service=HASH(0x400d1d8) $VAR1 = 'SessionID';
$VAR2 = '6ea8f38b-bc3d-4920-b5fb-517d956c777d';

2022.02.19 11:06:58.840 5: UPNPController: SYS_UPNP: event of service SpeakerManagement, message 6ea8f38b-bc3d-4920-b5fb-517d956c777d
2022.02.19 11:06:58.840 5: UPNPController: SYS_UPNP: event of service AVTransport, message 6ea8f38b-bc3d-4920-b5fb-517d956c777d
2022.02.19 11:06:58.841 5: UPNPController: SYS_UPNP: event of service RenderingControl, message 6ea8f38b-bc3d-4920-b5fb-517d956c777d
2022.02.19 11:06:58.841 3: UPNPController: SYS_UPNP: uniqueDeviceName 192.168.4.32_48846 event SessionID not yet implemented
2022.02.19 11:06:58.841 4: UPNPController: SYS_UPNP: uniqueDeviceName 192.168.4.32_48846 event details: $VAR1 = '6ea8f38b-bc3d-4920-b5fb-517d956c777d';

2022.02.19 11:06:59.101 5: UPNPController: Received event: by 192.168.4.32_48846-zs-AVTransport UPnP::ControlPoint::Service=HASH(0x404a8d8) $VAR1 = 'LastChange';
$VAR2 = '<Event xmlns="urn:schemas-upnp-org:metadata-1-0/AVT/"><InstanceID val="0"><TransportState val="TRANSITIONING"/></InstanceID></Event>';


[MichaelT]

Hallo.

neue Module im Einsatz:

für mich sieht es so aus, als wenn die SessionID nicht bis zum DLNAController durchkommt.
Multiroomsupport wird zwar gesetzt - aber wegen "Groups" nicht wegen "SessionID".

Code Auswählen Erweitern

2022.02.20 17:10:35.570 5: UPNPController: Received event: by 192.168.4.30_51053-zs-SpeakerManagement UPnP::ControlPoint::Service=HASH(0x32195fc) $VAR1 = 'Groups';
$VAR2 = '<?xml version="1.0" ?><groups version="1.0"></groups>';
$VAR3 = 'SessionID';
$VAR4 = '';

2022.02.20 17:10:35.595 5: SYS_UPNP: dispatch SpeakerManagement|192.168.4.30_51053|Groups|<?xml version="1.0" ?><groups version="1.0"></groups>
2022.02.20 17:10:35.595 4: DLNAController: message from SYS_UPNP, message: SpeakerManagement|192.168.4.30_51053|Groups|<?xml version="1.0" ?><groups version="1.0"></groups>
2022.02.20 17:10:35.595 5: DLNAController: message parameters: SpeakerManagement, 192.168.4.30_51053, Groups, <?xml version="1.0" ?><groups version="1.0"></groups>
2022.02.20 17:10:35.595 5: DLNAController: DG_BUE_MR process property Groups, xml-event <?xml version="1.0" ?><groups version="1.0"></groups>
2022.02.20 17:10:35.595 4: DLNAController: DG_BUE_MR parsing did enter load_xml call: <?xml version="1.0" ?><groups version="1.0"></groups>
2022.02.20 17:10:35.596 3: DLNAController: DG_BUE_MR property Groups, propertyval: <?xml version="1.0" ?><groups version="1.0"></groups>
2022.02.20 17:10:35.596 4: DLNAController DG_BUE_MR: state update from SYS_UPNP, address 192.168.4.30_51053
2022.02.20 17:10:35.633 3: UPNPController: SYS_UPNP: uniqueDeviceName 192.168.4.30_51053 event SessionID not yet implemented
2022.02.20 17:10:35.633 4: UPNPController: SYS_UPNP: uniqueDeviceName 192.168.4.30_51053 event details: $VAR1 = '';

2022.02.20 17:10:35.636 5: UPNPController: Received event: by 192.168.4.30_51053-zs-SessionManagement UPnP::ControlPoint::Service=HASH(0x32197b4) $VAR1 = 'SessionID';
$VAR2 = '';

2022.02.20 17:10:35.660 3: UPNPController: SYS_UPNP: uniqueDeviceName 192.168.4.30_51053 event SessionID not yet implemented
2022.02.20 17:10:35.660 4: UPNPController: SYS_UPNP: uniqueDeviceName 192.168.4.30_51053 event details: $VAR1 = '';

2022.02.20 17:11:35.117 5: UPNPController: try to renew subscriptions for services, device SYS_UPNP


Hier kommt er gar nicht vorbei:

Code Auswählen Erweitern

  } elsif($property eq "SessionID") {
    #TODO search for other speakers with same sessionId and add them to multiRoomUnits
Log3 $hash, 3, "DLNAController: $hash->{NAME} property SessionID, propertyval: $propertyval";
    $hash->{helper}{sessmgmt} = 1;
    readingsSingleUpdate($hash, "sessionId", $propertyval, 1);
    readingsSingleUpdate($hash, "multiRoomSupport", 1, 1);
  }



Oder ich verstehe es nicht richtig.

[KölnSolar]

Hi Michael,

Meinst Du sowas?

Genau. Man sieht das event und dann kommt:

2022.02.19 11:06:58.727 3: UPNPController: SYS_UPNP: uniqueDeviceName 192.168.4.32_48846 event SessionID not yet implemented

Aber wieso hat es dann funktioniert ?  Also ich meine in der Nutzung.

für mich sieht es so aus, als wenn die SessionID nicht bis zum DLNAController durchkommt.

Sag ich ja.

Hier kommt er gar nicht vorbei:

Klar. Bleibt bereits im UPNPController hängen. Ich dachte aber ich hätte das jetzt gelöst. 

Die Log-Zeile hast Du ja eingebaut. Was sagt denn das Log zu der Stelle, von wo Du es kopiert hast, also bei Groups ?

Funktionalität müsste klappen, wenn Du

Code Auswählen Erweitern

    $hash->{helper}{sessmgmt} = 1; in den "Groups-Block" packst.

Ich gucke....

Grüße Markus

[KölnSolar]

Bist Du sicher, dass Du ein reload für den UPNPController gemacht hast ? 

Ich hab mir ein test_dispatch eingebaut und das sieht gut aus

Code Auswählen Erweitern

2022.02.20 22:16:31 5: UPNP_Controller: dispatch SessionManagement|192.168.178.62_9197|SessionId|test
2022.02.20 22:16:31 4: DLNAController: message from UPNP_Controller, message: SessionManagement|192.x.y.z_9197|SessionId|test
2022.02.20 22:16:31 5: DLNAController: message parameters: SessionManagement, 192.x.y.z_9197, SessionId, test

Danach hab ich multiroomSupport.

Edit: Und dann funktionieren multiroomVolume und multiroomMute auf meinem Samsung 

[MichaelT]

Moin,

Aber wieso hat es dann funktioniert ?

Die Nutzung funktioniert, da bei einem Play immer eine neue Session erzeugt wird und addUnit diese nur nutzt.
Sobald man eine neuen Stream "played", wird wieder eine neue Session erzeugt und alle "geaddeten" sind wieder weg, da die "damalige" Session
nicht im Modul gespeichert wurde.

Die Log-Zeile hast Du ja eingebaut. Was sagt denn das Log zu der Stelle, von wo Du es kopiert hast, also bei Groups ?

Code Auswählen Erweitern

Multiroomsupport wird zwar gesetzt - aber wegen "Groups" nicht wegen "SessionID".
Logausgaben sind vorhanden

Code Auswählen Erweitern

2022.02.20 17:10:35.596 3: DLNAController: DG_BUE_MR property Groups, propertyval: <?xml version="1.0" ?><groups version="1.0"></groups>

Bist Du sicher, dass Du ein reload für den UPNPController gemacht hast ?

Ja, habe sogar nach dem Kopieren ein Restart fhem gemacht.

Gruß Michael, muss jetzt schaffen.

[KölnSolar]

Hi Michael,

das ist seltsam. Hab mir gerade die eingestellte Version angeguckt, ob ich vielleicht eine Falsche eingestellt hatte. Passt aber.

Entweder müsste richtigerweise dispatched werden oder die (noch falsche) Logmeldung

Code Auswählen Erweitern

        Log3 $hash, 5, "UPNPController: $hash->{NAME}: empty event $msgtype found" if ($msg);
müsste auftauchen. Kannst Du diese Zeile(in UPNPController_checkdispatch) mal so abändern

Code Auswählen Erweitern

Log3 $hash, 5, "UPNPController: $hash->{NAME}: checking event $msgtype against event_map";

Grüße Markus

[MichaelT]

Guten Abend,

geänderte Debugausgabe:

Code Auswählen Erweitern

2022.02.21 18:37:51.845 4: DLNAController: DG_BUE_MR Update reading nextAVTransportURI with
2022.02.21 18:37:51.845 4: DLNAController: DG_BUE_MR Update reading CurrentMediaDuration with 0:00:00
2022.02.21 18:37:51.845 4: DLNAController: DG_BUE_MR Update reading CurrentTrackDuration with 0:00:00
2022.02.21 18:37:51.846 4: DLNAController DG_BUE_MR: state update from SYS_UPNP, address 192.168.4.30_51053
2022.02.21 18:37:51.872 5: UPNPController: Received event: by 192.168.4.30_51053-zs-SpeakerManagement UPnP::ControlPoint::Service=HASH(0x32195fc) $VAR1 = 'Groups';
$VAR2 = '<?xml version="1.0" ?><groups version="1.0"></groups>';
$VAR3 = 'SessionID';
$VAR4 = '';

2022.02.21 18:37:51.896 5: SYS_UPNP: dispatch SpeakerManagement|192.168.4.30_51053|Groups|<?xml version="1.0" ?><groups version="1.0"></groups>
2022.02.21 18:37:51.896 4: DLNAController: message from SYS_UPNP, message: SpeakerManagement|192.168.4.30_51053|Groups|<?xml version="1.0" ?><groups version="1.0"></groups>
2022.02.21 18:37:51.896 5: DLNAController: message parameters: SpeakerManagement, 192.168.4.30_51053, Groups, <?xml version="1.0" ?><groups version="1.0"></groups>
2022.02.21 18:37:51.896 5: DLNAController: DG_BUE_MR process property Groups, xml-event <?xml version="1.0" ?><groups version="1.0"></groups>
2022.02.21 18:37:51.897 4: DLNAController: DG_BUE_MR parsing did enter load_xml call: <?xml version="1.0" ?><groups version="1.0"></groups>
2022.02.21 18:37:51.897 3: DLNAController: DG_BUE_MR property Groups, propertyval: <?xml version="1.0" ?><groups version="1.0"></groups>
2022.02.21 18:37:51.897 4: DLNAController DG_BUE_MR: state update from SYS_UPNP, address 192.168.4.30_51053
2022.02.21 18:37:51.933 5: UPNPController: SYS_UPNP: checking event SessionID against event_map
2022.02.21 18:37:51.933 3: UPNPController: SYS_UPNP: uniqueDeviceName 192.168.4.30_51053 event SessionID not yet implemented
2022.02.21 18:37:51.933 4: UPNPController: SYS_UPNP: uniqueDeviceName 192.168.4.30_51053 event details: $VAR1 = '';

2022.02.21 18:37:51.936 5: UPNPController: Received event: by 192.168.4.30_51053-zs-SessionManagement UPnP::ControlPoint::Service=HASH(0x32197b4) $VAR1 = 'SessionID';
$VAR2 = '';

2022.02.21 18:37:51.959 5: UPNPController: SYS_UPNP: checking event SessionID against event_map
2022.02.21 18:37:51.959 3: UPNPController: SYS_UPNP: uniqueDeviceName 192.168.4.30_51053 event SessionID not yet implemented
2022.02.21 18:37:51.959 4: UPNPController: SYS_UPNP: uniqueDeviceName 192.168.4.30_51053 event details: $VAR1 = '';

[KölnSolar]

Nun bin ich sicher, dass Du reloaded hast. 

Jetzt kann es eigentlich nur daran liegen, dass ich

SessionID

anders geschrieben habe, aber ich seh keinen Unterschied

zu

Code Auswählen Erweitern

  my $property_map = {
    Groups     => "SpeakerManagement",
    SessionId  => "SessionManagement"
und

Code Auswählen Erweitern

if (exists($property_map->{$msgtype})) {
sollte wahr sein.

Hahaha, das passiert, wenn man nicht mit eigener Hardware testen kann. Jetzt im direkten Vergleich sieht man es.

Mach doch mal in Zeile 74 ein D aus dem d 

[MichaelT]

Hi,

Genau das habe ich gerade auch gesehen.
Jetzt ist die SessionID in den reading!   

[MichaelT]

Hi,

ich bin begeistert. Mal grob getestet. Klappt alles soweit.

Danke Dir.

Gruß Michael

[MichaelT]

Nochmal Hi,

hast Du noch eine Idee, warum bei addUnit nicht die verfügbaren Devices (sessionmgm1==1) angezeigt werden?
Blick da nicht ganz durch, ob {helper}{sessionmgmtClients} hier die richtigen Werte hat ;-<

Code Auswählen Erweitern

addUnit           => {method => \&DLNAController_addUnit, args => 1, argdef => $hash->{helper}{sessmgmtClients}, sessmgmt => 1},

[KölnSolar]

ich bin begeistert. Mal grob getestet. Klappt alles soweit.

Da bin ich aber auch begeistert und erleichtert.

$hash->{helper}{sessmgmtClients}

haben wir wohl noch nie gehabt. Übersetzt aus dem DLNARenderer müssen wir

Code Auswählen Erweitern

      #update list of SessionManagement clients(multiroom devices)
      my @sessmgmtClients = DLNAController_sessmgmtClients($hash);
      $hash->{helper}{sessmgmtClients} = "";
      foreach my $client (@sessmgmtClients) {
        #do not add myself
        if($client->{UDN} ne $hash->{UDN}) {
          $hash->{helper}{sessmgmtClients} .= ",".ReadingsVal($client->{NAME}, "friendlyName", "");
        }
      }
      $hash->{helper}{sessmgmtClients} = substr($hash->{helper}{sessmgmtClients}, 1) if($hash->{helper}{sessmgmtClients} ne "");



in

Code Auswählen Erweitern

sub DLNAController_devicestate einfach am Ende der sub einbauen. Könnte klappen. 

Edit: das kleine Problem ist sicherlich, dass sich das "einschwingen" muss. Beim 1. device gibt es die anderen devices noch nicht. Also bleibt es leer. Das 2. findet das 1. ..... Bei jedem event wird die Liste neu aufgebaut, so dass dann irgendwann alle devices auch alle devices in der Liste haben. So die Theorie meines "Trockentests".

[MichaelT]

Schau ich morgen mal rein

[MichaelT]

Hallo Markus,

habe deinen Vorschlag mal eingebaut, funktioniert.

Versuche gerade mal das mit den Timer (StereoMode) unterzubringen.

[KölnSolar]

bau den Funktionsaufruf ins define als letzte Zeile. Dann sollte alles wie von selbst gehen. (nach reload und defmod)

Edit:  Aber wieso brauchten wir das noch ?  Sehe da gerade keinen Sinn drin(und scheinbar auch "Fehler" ? )
Edit2: opjepass(sacht der Kölsche): beim DLNArenderer gab es ja DAS master device. Nun haben wir x Einzeldevices !!! Da müssen wir uns konzeptionell Gedanken machen wann, wo(device) die Attribute multiRoomGroups(saveas,load) und  multiRoomUnits(session: stereo oder multiroom) definiert sind(Und mir gefällt nicht, dass das in Attributen steht). Müsste man nicht beim device, das man "bedient" diese Variablen(eher readings) maintainen und die anderen devices einer session bzw. alle(bei groups) bekommen eine Kopie ?
Oder wir definieren ein device als master ? per define oder attribute ?

[MichaelT]

Hi,
morgen hab ich wieder etwas Zeit.

Was hältst du von einem weiteren device, welches abhängig von multiroom angelegt wird und die Steuerung übernimmt.
Weiss selbst nicht, ob das gut ist. Wäre dann ähnlich z.B. der app. Die steuert einfach 1 bis x Devices.

[KölnSolar]

Was hältst du von einem weiteren device

Dann lieber nur ein master-Attribut. Wie wäre das bei z.B. 4 Speakern und man hätte die in 2 physischen Räumen und wollte dann in beiden Räumen stereo mit unterschiedlichen streams ?    Wären doch 2 master notwenig, oder ?

[MichaelT]

Hallo Markus,

ja, du hast Recht. Ich hatte eher MR im Kopf, da ich Stereo gerade nur zum Test verwende. Die Devices stehen bei
mir in getrennten Räumen.

Aktuell bekomme ich den StereoMode nicht mit fhem ans Laufen. Ist mir noch nicht klar, warum nicht. Ich meine, das hat mal funktioniert.
Irgendwie stehen alle Werte (RTSPGateway, SpeakerManagement) in den Devices korrekt - aber es kommt nichts.

Gruß Michael

[KölnSolar]

Hi Michael,
dann gib doch mal ein Log.

RTSPGateway

Den service hatten wir doch noch nie berücksichtigt. 

Zum master: Es ist doch so, dass eine session von einem device initiiert wird. Dann ist das doch der "master of session", oder ? Ich mach mal ne Übersicht der cmd's.

Grüße Markus

Edit: mir fehlt noch das Verständnis zu der Speicherung von den sessions und der Reihenfolge der Befehle(generell, also nicht FHEM)
- stream/play/speak/channel = abspielen mit neuer session-id oder für im device gespeicherte session(standalone,stereo,multiroom)
- bleibt die session-id auch nach offline/Stromausfall im physischen device erhalten ? Oder nur in der Äpp gespeichert ? Oder nirgends ?
- sind die den Umfang der session beeinflussenden Befehle(...Everywhere, addunit....) vor/während/beides abspielen eines streams ausführbar ?
- ist eine session in der Äpp eher wie ein eigenes device mit speakern als Attribut und gesteuert wird die session ?

Du siehst, jetzt, wo es grob funktioniert, denke ich in use cases. Machts nicht leichter. 

Edit2: Die "groups", zumal mit unterschiedlicher Bedeutung in FHEM vs. dem service SpeakerManagement, sind mir nach wie vor suspekt. Ist es nicht so, dass man Gruppen von Speakern benennen möchte, um dann eben die Gruppe(Bsp. Räume oder  Stereo im Raum)zu steuern ? Bisher haben wir die beiden Befehle LoadGroup und SaveGroupAs, die aber nur für den Stereomodus funktionieren. Ist die Idee nicht, Gruppen mit einem Namen zu definieren und jederzeit eine neue session mit den membern einer Gruppe aufzubauen(gleichzeitig die member ggfs. aus ihrer laufenden session zu entfernen) ?

Nun habe ich glaube ich verstanden, was da eigentlich die Bedeutungen sind: groups sind die "permanenten/gespeicherten" groups, die man laden kann. Die session ist das "temporäre" Geschehen.

Das würde bedeuten, dass im Modul noch einiges fehlt. Wir aber gar kein master device benötigen, da das reading multiroomunits und das Attribut multiroomgroups so gar nicht benötigt würden. Detsails dazu, wenn Du mir meine Annahmen bestätigt hast.

[MichaelT]

Hallo Markus,

spät, aber kommt

Ergebnisse aus der Beobachtung peaq-App und upnptester

- stream/play/speak/channel = abspielen mit neuer session-id oder für im device gespeicherte session(standalone,stereo,multiroom)

Sobald ich das erste Device in der App in einer Session aufnehme, wird die SessionID gesetzt und das RTSPGateway enabled. Alle weiteren Devices
bekommen beim hinzufügen die SessionID und der Stream wird auf rtsp://IP:port/stream gesetzt. Ich weiß aber nicht, ob z.B. das neue Device nur die SessionID
bekommt und hiermit die RTSP URI aus dem ersten Device ermittelt. Diese kann dort mit GetRTSPGatewayURI gelesen werden. Wird ein Device aus der Session entfernt
wird die SessionID gelöscht. Wird das erste Device aus der Session genommen, werden alle anderen Devices auch gestoppt und SessionID gelöscht.

bleibt die session-id auch nach offline/Stromausfall im physischen device erhalten ? Oder nur in der Äpp gespeichert ? Oder nirgends ?

Nach Offline/Stromausfall ist die SessionID == "".

- sind die den Umfang der session beeinflussenden Befehle(...Everywhere, addunit....) vor/während/beides abspielen eines streams ausführbar ?

Ja, man kann beliebig Devices hinzufügen und entfernen. Nur das Erste ist wohl der "master", wird dieses entfernt, sind alle aus.

- ist eine session in der Äpp eher wie ein eigenes device mit speakern als Attribut und gesteuert wird die session ?

Die peaq-App zeigt alle gefundenen Devices an und man kann dann mit Checkboxen den Stream der App lokal (kein Device aktiv) oder auf den aktivierten
Devices abspielen. Lautstärke kann man einzeln oder Gesamt steuern. Man kann zwei Devices als Stereopaar zusammenhängen, dann sieht man anstelle der Devices
ein neues mit frei wählbaren Name.

Edit2: Die "groups", zumal mit unterschiedlicher

Ich glaube, die Gruppen (SpeakerMgm) sind nur für "BT-caskeid" wichtig. Sobald BT aktiv ist, wird die Gruppe gesetzt. Alle Devices haben die gleiche Gruppe. Sobald ein Device
ein BT-Stream empfängt (gekoppelt ist), wird dort das RTSP-Gateway enabled. Alle Anderen (mit der gleichen Gruppe??) setzen spielen den Stream rtsp://IP:port/stream.

Nun habe ich glaube ich verstanden, was da eigentlich die Bedeutungen sind: groups sind die "permanenten/gespeicherten" groups, die man laden kann. Die session ist das "temporäre" Geschehen.

Ja, sehe ich auch so.

Das würde bedeuten, dass im Modul noch einiges fehlt. Wir aber gar kein master device benötigen, da das reading multiroomunits und das Attribut multiroomgroups so gar nicht benötigt würden. Detsails dazu, wenn Du mir meine Annahmen bestätigt hast.

Ja, das master-Device ist immer das, wo man addUnit macht. Wenn ich dann auf einem "nicht master" einen Stream startet, funktioniert das nicht, da die gleiche Session verwendet wird aber das RTSPGateway auf dem master aktiv ist. Erst wenn man ein stopPlayEveryWhere macht (alles SissionID sind dann gelöscht), kann wieder ein anderes Device ein Stream abspielen. removeUnit geht auch aktuell nicht korrekt, da dort der friendly name anstelle der UDN übergeben wird.

Ich hoffe ich verwirre nicht mehr als ich helfe.

Gruß Michael

[KölnSolar]

Hi Michael,

Ich hoffe ich verwirre nicht mehr als ich helfe.

Nein. Aber ist schon nicht leicht das "trocken" durchzuspielen.

SaveGroupAs und LoadGroup funktionieren doch im Grundsatz, oder ? Dann würd ich mal ne Zwischenversion machen, dass das nicht nur in FHEM, sondern in den speakern gespeichert wird. Und dann müssten wir einerseits events "groups" mit Inhalt bekommen und die Äpp zeigt dann(wo auch immer) diese Gruppe an. Und Strom off/on sollte nicht den Tod der group bedeuten.

D'accord ?

Markus

[MichaelT]

Ja, einverstanden.

Wovon wolltest Du denn ein Log haben, von dem Stereo-Thema?

Gruß

[KölnSolar]

Yes.

[KölnSolar]

Hallo Michael,

unabhängig der früheren Funktionsweise habe ich die Version wie folgt geändert:

mit

Code Auswählen Erweitern

saveGroupAs GroupNamewird im device die Gruppe GroupName mit der GroupID 4DAA44C0-8291-11E3-BAA7-0800200C9A65 angelegt

mit

Code Auswählen Erweitern

enableCaskeid wird im device unverändert die Gruppe Bluetooth mit der GroupID 4DAA44C0-8291-11E3-BAA7-0800200C9A66 angelegt

mit

Code Auswählen Erweitern

GetGroupswerden die vorhandenen(gespeicherten ?) Gruppen ausgelesen und in einem neuen reading groups abgelegt( wie auch immer der Inhalt aussehen wird)

bitte so testen:
nach reload
- saveGroupAs TestGroup    mit device_1
- GetGroups            Wie sieht nun das reading groups in diesem device aus ?
- enableCaskeid         mit device_1
- GetGroups            Wie sieht nun das reading groups in diesem device aus ?
- saveGroupAs TestGroup    mit device_2
- GetGroups            Wie sieht nun das reading groups in beiden devices aus ?
- enableCaskeid         mit demselben device_2
- GetGroups            Wie sieht nun das reading groups in beiden devices aus ?
- stromlos eines physischen devices
- GetGroups            Wie sieht nun das reading groups in beiden devices aus ? Die Groups in der Äpp ?


Da es keinen loadGroup upnp-Befehl im service SpeakerManagement gibt, gehe ich davon aus, dass Du über irgendetwas in der Äpp die session beeinflussen kannst
- kann man eine session zu einer Gruppe eröffnen ?
- wird möglicherweise bei start eines streams zu einem speaker automatisch eine neue session mit allen membern der Gruppe eröffnet ?


Und nach jedem Befehl bitte in die Äpp gucken, was dort evtl. verändert angezeigt wird. Und vermutlich hat es auch akkustische Auswirkungen. Welche ?

Und natürlich alles mit verbose 5 im DLNAController zur besseren Verfolgung Deiner Aktivitäten.

Grüße Markus

[MichaelT]

Hallo Markus

Ich musste noch ein Problem fixen, Funktionsaufruf falsch:

Code Auswählen Erweitern


622c622
<   DLNAController_upnpAddToGroup($hash, "4DAA44C0-8291-11E3-BAA7-0800200C9A65", $groupName);
---
>   DLNAController_AddToGroup($hash, "4DAA44C0-8291-11E3-BAA7-0800200C9A65", $groupName);


Test:

saveGroupAs TestGroup:

Code Auswählen Erweitern


Reading: <?xml version="1.0" ?><groups version="1.0"><group><id>4DAA44C0-8291-11E3-BAA7-0800200C9A65</id><name>TestGroup</name></group></groups>
Log:
2022.03.05 07:16:02.140 5:  DLNAController: DG_BUE_MR, 192.168.4.30_52976, SpeakerManagement, AddToGroup
2022.03.05 07:16:02.141 5:  UPNPController: SYS_UPNP, 192.168.4.30_52976, SpeakerManagement, AddToGroup, 4DAA44C0-8291-11E3-BAA7-0800200C9A65 TestGroup
2022.03.05 07:16:02.141 5:  UPNPController: SpeakerManagement: urn:pure-com:serviceId:SpeakerManagement found. OK.
2022.03.05 07:16:02.379 5:  UPNPController: Received event: by 192.168.4.30_52976-zs-SpeakerManagement UPnP::ControlPoint::Service=HASH(0x359b3d0) $VAR1 = 'Groups';
$VAR2 = '4DAA44C0-8291-11E3-BAA7-0800200C9A65TestGroup';

2022.03.05 07:16:02.391 5:  SYS_UPNP: dispatch SpeakerManagement|192.168.4.30_52976|Groups|4DAA44C0-8291-11E3-BAA7-0800200C9A65TestGroup
2022.03.05 07:16:02.391 4:  DLNAController: message from SYS_UPNP, message: SpeakerManagement|192.168.4.30_52976|Groups|4DAA44C0-8291-11E3-BAA7-0800200C9A65TestGroup
2022.03.05 07:16:02.391 5:  DLNAController: message parameters: SpeakerManagement, 192.168.4.30_52976, Groups, 4DAA44C0-8291-11E3-BAA7-0800200C9A65TestGroup
2022.03.05 07:16:02.391 5:  DLNAController: DG_BUE_MR process property Groups, xml-event 4DAA44C0-8291-11E3-BAA7-0800200C9A65TestGroup
2022.03.05 07:16:02.392 4:  DLNAController: DG_BUE_MR parsing did enter load_xml call: 4DAA44C0-8291-11E3-BAA7-0800200C9A65TestGroup
2022.03.05 07:16:02.392 3:  DLNAController: DG_BUE_MR property Groups, propertyval: 4DAA44C0-8291-11E3-BAA7-0800200C9A65TestGroup
2022.03.05 07:16:02.392 4:  DLNAController DG_BUE_MR: state update from SYS_UPNP, address 192.168.4.30_52976


enableBTCaskeid

Code Auswählen Erweitern


Reading: <?xml version="1.0" ?><groups version="1.0"><group><id>4DAA44C0-8291-11E3-BAA7-0800200C9A66</id><name>Bluetooth</name></group></groups>

Log:
2022.03.05 09:15:51.427 5:  DLNAController: DG_BUE_MR, 192.168.4.30_52976, SpeakerManagement, AddToGroup
2022.03.05 09:15:51.427 5:  UPNPController: SYS_UPNP, 192.168.4.30_52976, SpeakerManagement, AddToGroup, 4DAA44C0-8291-11E3-BAA7-0800200C9A66 Bluetooth
2022.03.05 09:15:51.427 5:  UPNPController: SpeakerManagement: urn:pure-com:serviceId:SpeakerManagement found. OK.
2022.03.05 09:15:51.680 5:  UPNPController: Received event: by 192.168.4.30_52976-zs-SpeakerManagement UPnP::ControlPoint::Service=HASH(0x359b3d0) $VAR1 = 'Groups';
$VAR2 = '4DAA44C0-8291-11E3-BAA7-0800200C9A66Bluetooth';

2022.03.05 09:15:51.696 5:  SYS_UPNP: dispatch SpeakerManagement|192.168.4.30_52976|Groups|4DAA44C0-8291-11E3-BAA7-0800200C9A66Bluetooth
2022.03.05 09:15:51.696 4:  DLNAController: message from SYS_UPNP, message: SpeakerManagement|192.168.4.30_52976|Groups|4DAA44C0-8291-11E3-BAA7-0800200C9A66Bluetooth
2022.03.05 09:15:51.697 5:  DLNAController: message parameters: SpeakerManagement, 192.168.4.30_52976, Groups, 4DAA44C0-8291-11E3-BAA7-0800200C9A66Bluetooth
2022.03.05 09:15:51.697 5:  DLNAController: DG_BUE_MR process property Groups, xml-event 4DAA44C0-8291-11E3-BAA7-0800200C9A66Bluetooth
2022.03.05 09:15:51.697 4:  DLNAController: DG_BUE_MR parsing did enter load_xml call: 4DAA44C0-8291-11E3-BAA7-0800200C9A66Bluetooth
2022.03.05 09:15:51.697 3:  DLNAController: DG_BUE_MR property Groups, propertyval: 4DAA44C0-8291-11E3-BAA7-0800200C9A66Bluetooth
2022.03.05 09:15:51.698 4:  DLNAController DG_BUE_MR: state update from SYS_UPNP, address 192.168.4.30_52976


Hier fällt schon auf, dass das enableBTCaskeid die TestGroup ersetzt! War bei beiden Devices so.
Aktuell wird das Reading "groups" nicht aktualisiert, nur ein browser reload zeigt die neuen Werte an.
Nach Restart device bleibt die jeweilige Group erhalten.
Überkreuz hatten die Aktionen keinen Einfluss.
In der App macht sich die TestGroup nicht bemerkbar. BTCaskeid wird korrekt angezeigt.
Ich habe immer mittels UPnPTest im Device geschaut. Aber dort war, wie zu erwarten, nichts anders als im Reading.


getGroups scheint aber keine Auswirkung zu haben

Code Auswählen Erweitern


2022.03.05 09:10:51.500 5:  UPNPController: renew subscription for service SpeakerManagement of device 192.168.4.31_38702 1646380964
2022.03.05 09:11:33.994 5:  DLNAController: DG_BUE_MR, 192.168.4.30_52976, SpeakerManagement, GetGroups
2022.03.05 09:11:33.995 5:  UPNPController: SYS_UPNP, 192.168.4.30_52976, SpeakerManagement, GetGroups,
2022.03.05 09:11:33.995 5:  UPNPController: SpeakerManagement: urn:pure-com:serviceId:SpeakerManagement found. OK.
2022.03.05 09:11:51.148 5:  UPNPController: try to renew subscriptions for services, device SYS_UPNP
2022.03.05 09:11:51.149 5:  UPNPController: renew subscription for service SessionManagement of device 192.168.4.32_57097 1646393811
2022.03.05 09:11:51.184 5:  UPNPController: renew subscription for service SpeakerManagement of device 192.168.4.32_57097 1646393810
2022.03.05 09:11:51.265 5:  UPNPController: renew subscription for service AVTransport of device 192.168.4.32_57097 16463938

UPnPTest zeigt aber bei GetGroups korrekt an.


In der App kann man "gefühlt" nichts mit den Gruppen machen, nur BTCaskeid ein/aus.
Ich glaube aber, die App war nur Minimalistisch und wird schon ewig nicht mehr weiter entwickelt. Deshalb auch Android 6.0 Ende.

Gruß Michael

[KölnSolar]

Hi Michael,
danke fürs testen(und bug beheben  )

Hmm, also gibt es nur eine Group je speaker. Warum dann Plural ? 

Was machen wir denn nun damit ?

Und, dass das so zusammengepappt ist. 

$VAR2 = '4DAA44C0-8291-11E3-BAA7-0800200C9A65TestGroup';

Mach doch mal aus der 5 wieder eine 6 im code und nochmal testen. Ob dann auch überschrieben wird oder die uuid der Schlüssel ist ? Aber wozu ?

Grüße Markus

[MichaelT]

Hallo Markus,

Hmm, also gibt es nur eine Group je speaker. Warum dann Plural ? 

Keine Ahnung, von der App kann man da keine Gruppen beeinflussen.

Und, dass das so zusammengepappt ist. 

Ich glaube, dass war nur ein Kopierfehler!

Code Auswählen Erweitern

2022.03.05 09:15:51.680 5: UPNPController: Received event: by 192.168.4.30_52976-zs-SpeakerManagement UPnP::ControlPoint::Service=HASH(0x359b3d0) $VAR1 = 'Groups';
$VAR2 = '<?xml version="1.0" ?><groups version="1.0"><group><id>4DAA44C0-8291-11E3-BAA7-0800200C9A66</id><name>Bluetooth</name></group></groups>';


habe 65 --> 66 geändert.
Sobald man dann saveGroupAs mit "TestGroup" macht, geht die App davon aus, dass Bluetooth enabled ist.
Also ist der Name der Group nicht relevant, sondern die UUID!

Was machen wir denn nun damit ?

Weiß auch nicht!?!

Was ich noch nicht verstehe ist, warum geht "mute" nicht.

17:40:39.379 SetMute aus FHEM.
17:42:07.507 mit UPnPTester siehe Bild.

Kann man sehen, was der UPNPController zum Device schickt? Sieht so aus, als wenn am Device immer eine 0 ankommt,

Code Auswählen Erweitern

2022.03.13 17:40:39.379 5: DLNAController: OG_SZ_MR, 192.168.4.31_55981, RenderingControl, SetMute
2022.03.13 17:40:39.379 5: UPNPController: SYS_UPNP, 192.168.4.31_55981, RenderingControl, SetMute, 0 Master 1
2022.03.13 17:40:39.380 5: UPNPController: RenderingControl: urn:upnp-org:serviceId:RenderingControl found. OK.
2022.03.13 17:40:39.892 5: UPNPController: Received event: by 192.168.4.31_55981-zs-RenderingControl UPnP::ControlPoint::Service=HASH(0x409daa4) $VAR1 = 'LastChange';
$VAR2 = '<Event xmlns="urn:schemas-upnp-org:metadata-1-0/RCS/"><InstanceID val="0"><Mute channel="Master" val="0"/></InstanceID></Event>';

2022.03.13 17:40:39.909 5: UPNPController: SYS_UPNP: checking event LastChange against event_map
2022.03.13 17:40:39.910 5: SYS_UPNP: dispatch RenderingControl|192.168.4.31_55981|LastChange|<Event xmlns="urn:schemas-upnp-org:metadata-1-0/RCS/"><InstanceID val="0"><Mute channel="Master" val="0"/></InstanceID></Event>
2022.03.13 17:40:39.910 4: DLNAController: message from SYS_UPNP, message: RenderingControl|192.168.4.31_55981|LastChange|<Event xmlns="urn:schemas-upnp-org:metadata-1-0/RCS/"><InstanceID val="0"><Mute channel="Master" val="0"/></InstanceID></Event>
2022.03.13 17:40:39.910 5: DLNAController: message parameters: RenderingControl, 192.168.4.31_55981, LastChange, <Event xmlns="urn:schemas-upnp-org:metadata-1-0/RCS/"><InstanceID val="0"><Mute channel="Master" val="0"/></InstanceID></Event>
2022.03.13 17:40:39.910 5: DLNAController: OG_SZ_MR process property LastChange, xml-event <Event xmlns="urn:schemas-upnp-org:metadata-1-0/RCS/"><InstanceID val="0"><Mute channel="Master" val="0"/></InstanceID></Event>
2022.03.13 17:40:39.910 4: DLNAController: OG_SZ_MR parsing did enter load_xml call: <Event xmlns="urn:schemas-upnp-org:metadata-1-0/RCS/"><InstanceID val="0"><Mute channel="Master" val="0"/></InstanceID></Event>
2022.03.13 17:40:39.911 4: DLNAController: OG_SZ_MR dom structure: <?xml version="1.0"?>
<Event xmlns="urn:schemas-upnp-org:metadata-1-0/RCS/">
  <InstanceID val="0">
    <Mute channel="Master" val="0"/>
  </InstanceID>
</Event>

2022.03.13 17:40:39.911 4: DLNAController: OG_SZ_MR LastChange xml event with root <Event xmlns="urn:schemas-upnp-org:metadata-1-0/RCS/"><InstanceID val="0"><Mute channel="Master" val="0"/></InstanceID></Event> found with name: Event
2022.03.13 17:40:39.911 5: DLNAController: OG_SZ_MR registered ns-uri is: urn:schemas-upnp-org:metadata-1-0/RCS/
2022.03.13 17:40:39.911 5: DLNAController: OG_SZ_MR node <InstanceID val="0"><Mute channel="Master" val="0"/></InstanceID>, node-name: InstanceID node-type: 1
2022.03.13 17:40:39.911 4: DLNAController: OG_SZ_MR Update reading mute with 0
2022.03.13 17:40:39.911 4: DLNAController: OG_SZ_MR Update reading mute with 0
2022.03.13 17:40:39.912 4: DLNAController: OG_SZ_MR Update reading mute with 0
2022.03.13 17:40:39.912 4: DLNAController: OG_SZ_MR Update reading mute with 0
2022.03.13 17:40:39.912 4: DLNAController OG_SZ_MR: state update from SYS_UPNP, address 192.168.4.31_55981
2022.03.13 17:40:52.434 5: UPNPController: try to renew subscriptions for services, device SYS_UPNP
2022.03.13 17:41:52.434 5: UPNPController: try to renew subscriptions for services, device SYS_UPNP
2022.03.13 17:41:52.436 5: UPNPController: renew subscription for service SpeakerManagement of device 192.168.4.31_55981 1646954141
2022.03.13 17:41:52.471 5: UPNPController: renew subscription for service SessionManagement of device 192.168.4.31_55981 1646954392
2022.03.13 17:41:52.509 5: UPNPController: renew subscription for service AVTransport of device 192.168.4.31_55981 1646954894
2022.03.13 17:41:52.557 5: UPNPController: renew subscription for service RenderingControl of device 192.168.4.31_55981 1646954643
2022.03.13 17:41:52.593 5: UPNPController: renew subscription for service AVTransport of device 192.168.4.30_52976 1646953389
2022.03.13 17:41:52.633 5: UPNPController: renew subscription for service RenderingControl of device 192.168.4.30_52976 1646953138
2022.03.13 17:41:52.678 5: UPNPController: renew subscription for service SessionManagement of device 192.168.4.30_52976 1646953640
2022.03.13 17:41:52.712 5: UPNPController: renew subscription for service SpeakerManagement of device 192.168.4.30_52976 1646952886
2022.03.13 17:41:52.746 5: UPNPController: renew subscription for service SessionManagement of device 192.168.4.32_47441 1646951885
2022.03.13 17:41:52.787 5: UPNPController: renew subscription for service SpeakerManagement of device 192.168.4.32_47441 1646951884
2022.03.13 17:41:52.821 5: UPNPController: renew subscription for service AVTransport of device 192.168.4.32_47441 1647165974
2022.03.13 17:41:52.853 5: UPNPController: renew subscription for service RenderingControl of device 192.168.4.32_47441 1646951884
2022.03.13 17:41:52.884 5: UPNPController: renew subscription for service RenderingControl of device 192.168.4.33_60063 1646952134
2022.03.13 17:41:52.936 5: UPNPController: renew subscription for service AVTransport of device 192.168.4.33_60063 1646951885
2022.03.13 17:41:52.971 5: UPNPController: renew subscription for service SessionManagement of device 192.168.4.33_60063 1646952636
2022.03.13 17:41:53.005 5: UPNPController: renew subscription for service SpeakerManagement of device 192.168.4.33_60063 1646952385
2022.03.13 17:42:07.507 5: UPNPController: Received event: by 192.168.4.31_55981-zs-RenderingControl UPnP::ControlPoint::Service=HASH(0x409daa4) $VAR1 = 'LastChange';
$VAR2 = '<Event xmlns="urn:schemas-upnp-org:metadata-1-0/RCS/"><InstanceID val="0"><Mute channel="Master" val="1"/></InstanceID></Event>';

2022.03.13 17:42:07.524 5: UPNPController: SYS_UPNP: checking event LastChange against event_map
2022.03.13 17:42:07.524 5: SYS_UPNP: dispatch RenderingControl|192.168.4.31_55981|LastChange|<Event xmlns="urn:schemas-upnp-org:metadata-1-0/RCS/"><InstanceID val="0"><Mute channel="Master" val="1"/></InstanceID></Event>
2022.03.13 17:42:07.525 4: DLNAController: message from SYS_UPNP, message: RenderingControl|192.168.4.31_55981|LastChange|<Event xmlns="urn:schemas-upnp-org:metadata-1-0/RCS/"><InstanceID val="0"><Mute channel="Master" val="1"/></InstanceID></Event>
2022.03.13 17:42:07.525 5: DLNAController: message parameters: RenderingControl, 192.168.4.31_55981, LastChange, <Event xmlns="urn:schemas-upnp-org:metadata-1-0/RCS/"><InstanceID val="0"><Mute channel="Master" val="1"/></InstanceID></Event>
2022.03.13 17:42:07.525 5: DLNAController: OG_SZ_MR process property LastChange, xml-event <Event xmlns="urn:schemas-upnp-org:metadata-1-0/RCS/"><InstanceID val="0"><Mute channel="Master" val="1"/></InstanceID></Event>
2022.03.13 17:42:07.525 4: DLNAController: OG_SZ_MR parsing did enter load_xml call: <Event xmlns="urn:schemas-upnp-org:metadata-1-0/RCS/"><InstanceID val="0"><Mute channel="Master" val="1"/></InstanceID></Event>
2022.03.13 17:42:07.525 4: DLNAController: OG_SZ_MR dom structure: <?xml version="1.0"?>
<Event xmlns="urn:schemas-upnp-org:metadata-1-0/RCS/">
  <InstanceID val="0">
    <Mute channel="Master" val="1"/>
  </InstanceID>
</Event>

2022.03.13 17:42:07.525 4: DLNAController: OG_SZ_MR LastChange xml event with root <Event xmlns="urn:schemas-upnp-org:metadata-1-0/RCS/"><InstanceID val="0"><Mute channel="Master" val="1"/></InstanceID></Event> found with name: Event
2022.03.13 17:42:07.526 5: DLNAController: OG_SZ_MR registered ns-uri is: urn:schemas-upnp-org:metadata-1-0/RCS/
2022.03.13 17:42:07.526 5: DLNAController: OG_SZ_MR node <InstanceID val="0"><Mute channel="Master" val="1"/></InstanceID>, node-name: InstanceID node-type: 1
2022.03.13 17:42:07.526 4: DLNAController: OG_SZ_MR Update reading mute with 1
2022.03.13 17:42:07.526 4: DLNAController: OG_SZ_MR Update reading mute with 1
2022.03.13 17:42:07.526 4: DLNAController: OG_SZ_MR Update reading mute with 1
2022.03.13 17:42:07.527 4: DLNAController: OG_SZ_MR Update reading mute with 1
2022.03.13 17:42:07.527 4: DLNAController OG_SZ_MR: state update from SYS_UPNP, address 192.168.4.31_55981


Gruß Michael

[KölnSolar]

Hi Michael,
mute funktioniert bei mir einwandfrei.

Kann man sehen, was der UPNPController zum Device schickt? Sieht so aus, als wenn am Device immer eine 0 ankommt,

Indirekt durch das folgende event(in der Regel  ).

Code Auswählen Erweitern

2022.03.13 17:40:39.892 5: UPNPController: Received event: by 192.168.4.31_55981-zs-RenderingControl UPnP::ControlPoint::Service=HASH(0x409daa4) $VAR1 = 'LastChange';
$VAR2 = '<Event xmlns="urn:schemas-upnp-org:metadata-1-0/RCS/"><InstanceID val="0"><Mute channel="Master" val="0"/></InstanceID></Event>';
bzw. im DLNAController

Code Auswählen Erweitern

2022.03.13 17:40:39.379 5: UPNPController: SYS_UPNP, 192.168.4.31_55981, RenderingControl, SetMute, 0 Master 1interpretiert über

Code Auswählen Erweitern

action>
<name>SetMute</name>
<argumentList>
<argument>
<name>InstanceID</name>
<direction>in</direction>
<relatedStateVariable>A_ARG_TYPE_InstanceID</relatedStateVariable>
</argument>
<argument>
<name>Channel</name>
<direction>in</direction>
<relatedStateVariable>A_ARG_TYPE_Channel</relatedStateVariable>
</argument>
<argument>
<name>DesiredMute</name>
<direction>in</direction>
<relatedStateVariable>Mute</relatedStateVariable>
</argument>
</argumentList>
</action> war es set mute on.

Und InstanceId und Channel sind gleich zum UPnPTester. Seltsam. Ist einer der Peaq's ? Und dass der Befehl "blockiert" wurde durch eine besondere Konstellation(stereo,multiroom...)? 

Grüße Markus

[MichaelT]

Hi,

Ist einer der Peaq's ? Und dass der Befehl "blockiert" wurde durch eine besondere Konstellation(stereo,multiroom...)?

Glaube ich eher nicht, da ja eine Reaktion aus SetMute kommt - bloß mit val="0"

[KölnSolar]

Naja, eben doch.
Der Befehl wird geschickt, empfangen und dann wird mit dem Status geantwortet. Quasi als Hinweis, habs aber nicht gemacht.

Da es ja problemlos bei mir funktioniert, kann es nicht irgendwie an dem Modul liegen. Und ich hab ja oben extra noch einmal mit Deinem Logauszug das Modul "trocken" durchlaufen. Das passt alles. Nach der Logausgabe

Code Auswählen Erweitern

RenderingControl, SetMute, 0 Master 1 kommen nur Standardfunktionen mit den Parametern: service, action, arguments, folglich waren die Argumente InstanceID=0, Channel=Master, und  DesiredMute=1.(Ein Schelm wer Böses bei dem Wörtchen desired denkt)

Du könntest die richtige Funktionsweise auch mit dem Windows Mediaplayer verifizieren.

Grüße Markus

[MichaelT]

Hallo Markus,

hab mal wieder ein wenig Zeit für's Hobby.

Mit dem Mute bin ich jetzt ein wenig weiter. Es funktioniert nur "set mute off".
Mir ist das nicht aufgefallen, da ich es nie probiert habe, am device zu "muten" und dann von fhem wieder
zu "entmuten".

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

Hast Du noch eine Idee?

Gruß Michael

[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)


[KölnSolar]

Wie gut Logs sind. Da war meine Spekulation falsch. Es ist wohl ein SSDP discovery event.

Guck Dir mal die Ports an.

Code Auswählen Erweitern

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.724 5: DLNAController: message parameters: RenderingControl, 192.168.4.32_49620, offline, urn:schemas-upnp-org:metadata-1-0/RCS
und dann

Code Auswählen Erweitern

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.Und weil nach Sichtung des Codes bei byebye kein Zugriff auf das device erfolgt, scheint es sich um eine alive-message mit neuem Port zu handeln. Aber das device hat vermutlich schnell seine Meinung geändert, startet den Server erst gar nicht(deshalb connect error bzw. max. timeout), sondern nimmt dann doch lieber einen dritten Port
und schließlich

Code Auswählen Erweitern

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

Ich muss mal ne Nacht drüber schlafen, ob ich sämtliche http-Zugriffe in der Controlpoint.pm auf FHEM httpnonblocking umbaue oder dort wenigstens jeweils vor den blockierenden Zugriffen einen nicht blockierenden Check mache oder ne ganz andere Lösung ? 

Grüße Markus