Neuentw. Modulpaket zu UPnP: Controller, Device, DLNA(Renderer-Ersatz)

[eki]

Ich habe jetzt auch noch mal ein bisschen rumgespielt, um auch besser zu verstehen, wie ich das mit dem Vestel Modul "verheiraten" kann. Habe aber noch einige Punkte, die ich nicht so ganz verstehe.

Grundsätzlich ist mein halbwissendes Verständnis (aus Beobachtung abgeleitet, also möglicherweise Blödsinn  ) so, dass immer dann, wenn ein AVTransport service per UPNP gefunden wird, dann wird ein DLNAController Device erzeugt und versucht zu subscriben.
Das klappt auch immer erst mal und ich erhalte für die Geräte, wenn sie an sind, einige Readings, die teilweise auch den am Gerät gemachten Einstellungen (z.B. für Volume) folgen bzw. mit denen ich aus FHEM die Geräte steuern kann.
Leider geht das, zumindest bisher, immer nur temporär. Nach einer gewissen Zeit (habe nicht wirklich etwas gefunden, was das Verhalten triggert) verliert der DLNAController immer die Verbindung und bekommt sie dann auch nicht wieder zurück. Eventuelll wird das durch das Ausschalten des Gerätes hervorgerufen.
Falls ich noch Inputs liefern soll, meldet Euch.

[KölnSolar]

Hi Eki,

ein AVTransport service per UPNP gefunden wird, dann wird ein DLNAController Device erzeugt und versucht zu subscriben.

Fast. Auch bei den anderen DLNA-services RenderingControl, SpeakerManagement u. SessionManagement.

Leider geht das, zumindest bisher, immer nur temporär. Nach einer gewissen Zeit (habe nicht wirklich etwas gefunden, was das Verhalten triggert) verliert der DLNAController immer die Verbindung und bekommt sie dann auch nicht wieder zurück. Eventuelll wird das durch das Ausschalten des Gerätes hervorgerufen.

Es wird über die subscription getriggered. FHEM meldet dem device, dass es "mit events versorgt werden möchte"(subscription). Dabei vergibt das device eine lease time. Diese siehst Du im UPNPController unter dem servicereading mit "timeout: xxxx". Am timestamp siehst Du, wann es war. Nun wird innerhalb der leasetime ein renewal der subscription ausgeführt. Fehler oder wenn eine subscription wg. "offline" nicht möglich war, sieht man ebenfalls in diesem reading. Ohne subscription--->keine events(Änderungen werden FHEM nicht mitgeteilt). Im Grundsatz läuft das automatisch und funktioniert trotz zwischenzeitlichem Ausschalten des physischen devices oder Netzwerkproblemen oder..... Klappt es gar nicht oder die Wiederaufnahme der Verarbeitung, dann haben wir ein Problem und müssen es analysieren.

Ich nehme an Du hast das jetzt mit einem "Vestel"-device ausprobiert ? Dann schreib bitte in dem separaten Thread weiter. Scheinbar gibt es bei "Vestel" Probleme mit dem subscription-Prozess, die ich noch nicht verstanden hab. Da hatte ich bereits eine Frage an Dich Da spekulierte ich, dass das sehr seltsame Medion-Radio den gesamten renewal-Prozess des UPNP-Controller stört.

Grüße Markus

[eki]

Ich nehme an Du hast das jetzt mit einem "Vestel"-device ausprobiert ?

Ich habe das eigentlich mit allem, was der UPNP_Controller so sieht und erzählt probiert. Konkret werden aktuell bei mir folgende Devices als DLNAController Devices erstellt:

Radio mit SIRD Chipsatz (ist von Aldi und damit auch von Medion, glaube ich)
ein LG TV
der Vestel (Telefunken) TV (der meldet aber einen subscription Fehler)

Bei allen ist eingentlich das beschriebene Verhalten aufgetreten. Mit Deinen Inputs kann ich mir das noch mal genauer anschauen.

Alles Andere (die Frtzbox, ein FritzRepeater, ein EPSON Drucker, meine NAS, ein Humax (Sky) Receiver) wird zwar von UPNP_Controller erkannt, führt aber nicht zu Subscriptions.

Die Frage im anderen Thread war echt gut versteckt, hatte ich übersehen. Das schaue ich mir auch noch mal an.

[KölnSolar]

Radio mit SIRD Chipsatz

Ist glaub ich der device-typ, den Dieter auch hat und der kann schon von Hause aus kein volume-/mute-event  und macht nur Probleme.

Nimm mal den Windows-Mediaplayer. Der funktioniert eigentlich perfekt. Und wenn man das Prinzip dann etwas mehr verstanden hat, kann man dem Fehlverhalten von anderen devices auf den Grund gehen.

[MichaelT]

Hat sich da die IP geändert ?

Hallo Markus,

nein, die IP hat sich nicht geändert. Sind mit statischer IP konfiguriert.

Gruß
Michael

[KölnSolar]

Hallo Michael,
ich hab jetzt noch einmal Stunden verbracht, um Deine freezes u. den Absturz zu analysieren u. das Modul korrigieren. Aber es findet sich sich erst einmal nichts. Da ich auch immere wieder Kleinigkeiten korrigiere, ist es möglicherweise bereits behoben. 

Erläuterungen zu Deinen Meldungen:
- der Absturz war dann wohl doch nicht beim UPNP-Controller zu suchen.
- der 20s freeze ist durch die timeouts je service bedingt. Warum es diese timeouts gibt, ist erst einmal nicht nachvollziehbar. Da müssten wir dann schauen, dass wir es reproduziert bekommen. Vielleicht auch nur eine einmalige Geschichte, da Du ja anfänglich auch von funktionierendem Multiroom sprachst(Deine vorgschlagenen Änderungen sind in der akt. Version enthalten).
- der 3s freeze ist erst einmal nicht erheblich. Ähnliches beobachte ich auch aufgrund der "transition". Das ist dann ein Thema, wenn mal alles funktionell rund läuft. Dann werde ich das technisch lösen, dass es keine freezes mehr in FHEM geben kann.

@all: bitte mit der aktuellen Version testen.

@Jens: bei den Teufels müssten wir gucken, dass wir das mit den wechselnden IPs/Ports/devices in den Griff bekommen.

Grüße Markus

[MichaelT]

Hallo Markus,

reicht erstmal vollkommen aus. Der 20s Freeze ist nicht so tragisch, da das echt ein Sonderfall war/ist.
Die 3 Sekunden stören erstmal nicht wirklich.

Ich werden deine neuen Stand testen, danke für die Übernahme.

Gruß
Michael

[Newbie]

Hallo Markus,

@Jens: bei den Teufels müssten wir gucken, dass wir das mit den wechselnden IPs/Ports/devices in den Griff bekommen

also mit der aktuellen Version hat sich am Verhalten noch nichts geändert.

Was ich sagen kann:

- die drei Lautsprecher haben immer den gleichen Port
- "Raumfeld MediaServer" und "Raumfeld ConfigDevice" ebenfalls
- schalte ich die Räume "Küche" und "Schlafzimmer" in den Multiroom-Modus (Teufel spricht von Gruppieren) entscheidet die Reihenfolge der Zusammenschaltung was im UPNP-
   und DLNA-Controller passiert, d. h. Küche + Schlafzimmer = Küche, Schlafzimmer mit der UUID und dem Port des Einzelraumes Küche, Schlafzimmer geht offline
                                                            Schlafzimmer + Küche = Schlafzimmer, Küche mit der UUID und dem Port des Einzelraumes Schlafzimmer, Küche geht offline
  beim zurück auf Einzelraum das gleiche, der Raum der aus der Gruppe entfernt wird bekommt einen neuen Port/UUID

und das sind nur zwei Räume. Wie willst du das abfangen? UUID und Ports ignorieren?

viele Grüße und noch ein schönes Osterfest
Jens

[KölnSolar]

Hi Jens,

UUID und Ports ignorieren?

keineswegs.  Wenn die per Zufall generiert werden, können wir aber maximal drauf reagieren.
Nur um ein eindeutiges Verhalten zu beschreiben:

- die drei Lautsprecher haben immer den gleichen Port
- "Raumfeld MediaServer" und "Raumfeld ConfigDevice" ebenfalls

d.h. diese Aussage

nur der Port nach WLAN-Restart

ist falsch ?

Die 3 devices sind online, die services subscribed u. Änderungen kommen auch an, oder nur je nach Betriebsart bei Raum- u./o. Gruppendevice ? Kannst Du egal in welcher Betriebsart Befehle über das Lautspecherdevice senden u. wie wirkt sich das ggfs. auf Räume/Gruppen aus ?

Grüße Markus

[MichaelT]

Hallo Markus,

kurzes Feedback:
1. Ich bin auf einem separaten FHEM umgezogen, da ich wieder 2 mal die Freezes mit den alten Stand hatte. Es sah so aus, als wenn
der Renderer nicht mehr erreichbar war. Doofer Weise habe ich die log versehentlich gelöscht .

2. Neue Module jetzt im Einsatz, läuft erstmal reibungslos.
Ich habe verbose vollständig auf 5 gesetzt, so das man im Fehlerfall mehr sieht.

Ich berichte.

Danke und schöne Ostern

Gruß Michael

[Newbie]

Hallo Markus,

Die 3 devices sind online, die services subscribed u. Änderungen kommen auch an, oder nur je nach Betriebsart bei Raum- u./o. Gruppendevice ? Kannst Du egal in welcher Betriebsart Befehle über das Lautspecherdevice senden u. wie wirkt sich das ggfs. auf Räume/Gruppen aus ?

Das geht in allen Modi, wirkt sich aber immer nur auf den zugeordneten Raum aus.

d.h. diese Aussage
nur der Port nach WLAN-Restart
ist falsch ?

denke schon, wenn du die drei devices meinst bleiben die Ports bis zum Werks-Reset bzw. Änderungen innerhalb der APP gleich.
Aber wie ich schon sagte, zeigen diese devices nur wenige Readings an (keine Titel oder Sendernamen).


mfg Jens

[MichaelT]

Hallo Markus,

hier mal wieder ein Feedack von meiner Seite.

1. Die Erkennung, ob multiRoomSupport existiert, habe ich nochmal angepasst. Es kann passieren, dass die SessionID nicht empty ist! Dann wird nach einem Neustart
der Support nicht gesetzt.

Code Auswählen Erweitern

2021.04.11 08:46:04.186 5: UPNPController: Received event: by 192.168.4.31_54277-zs-SpeakerManagement UPnP::ControlPoint::Service=HASH(0x48b51b4) $VAR1 = 'SessionID';
$VAR2 = '89f4b029-2236-4adf-b606-5df6fb7acd37';
Anpassung UPNPController.pm:

Code Auswählen Erweitern


< Deins
> meins
860,872c860
<     if ($msg ne "") {
<               foreach my $key (keys %$event_map) {
< #               Log3 $hash, 5, "UPNPController: $hash->{NAME}: event of service $key, message ".$msg;
<                 if (index($msg,$event_map->{$key}) >= 0) {
<                        $message = $key;
<                        $valid = 1;
<                        # no further processing if dispatched
<                        last;
<                  }
<               }
<     }
<     else {
<        if ($msgtype eq "SessionID") {     # indicates SessionManagement; might by an event of SpeakerManagement or SessionManagement
---
>     if ($msgtype eq "SessionID") {     # indicates SessionManagement; might by an event of SpeakerManagement or SessionManagement
875c863,875
<        }
---
>     }
>     elsif ($msg ne "") {
>       foreach my $key (keys %$event_map) {
>         Log3 $hash, 5, "UPNPController: $hash->{NAME}: event of service $key, message ".$msg;
>         if (index($msg,$event_map->{$key}) >= 0) {
>                  $message = $key;
>                $valid = 1;
>                # no further processing if dispatched
>                last;
>          }
>       }
>     }
>     else {

2. Weiterhin habe ich das Problem, dass ab und zu die freezes passieren.
Offensichtlich kommt es bei mir vor, dass die Renderer nicht erreichbar sind (Warum - kann ich nicht sagen!).

Code Auswählen Erweitern


OG_BAD_MR-2021.log:2021-04-07_19:54:48 OG_BAD_MR online
OG_BAD_MR-2021.log:2021-04-08_02:06:33 OG_BAD_MR presence: offline
OG_BAD_MR-2021.log:2021-04-08_02:06:33 OG_BAD_MR offline
OG_BAD_MR-2021.log:2021-04-08_02:06:34 OG_BAD_MR presence: online
OG_BAD_MR-2021.log:2021-04-08_02:06:34 OG_BAD_MR online
OG_BAD_MR-2021.log:2021-04-11_15:57:18 OG_BAD_MR presence: offline
OG_BAD_MR-2021.log:2021-04-11_15:57:18 OG_BAD_MR offline
OG_BAD_MR-2021.log:2021-04-11_15:57:20 OG_BAD_MR presence: online
OG_BAD_MR-2021.log:2021-04-11_15:57:20 OG_BAD_MR online

...

DG_BUE_MR-2021.log:2021-04-07_20:35:47 DG_BUE_MR online
DG_BUE_MR-2021.log:2021-04-08_02:06:35 DG_BUE_MR presence: offline
DG_BUE_MR-2021.log:2021-04-08_02:06:35 DG_BUE_MR offline
DG_BUE_MR-2021.log:2021-04-08_09:22:31 DG_BUE_MR presence: online
DG_BUE_MR-2021.log:2021-04-08_09:22:31 DG_BUE_MR online
DG_BUE_MR-2021.log:2021-04-10_14:32:01 DG_BUE_MR presence: offline
DG_BUE_MR-2021.log:2021-04-10_14:32:01 DG_BUE_MR offline
DG_BUE_MR-2021.log:2021-04-10_14:32:02 DG_BUE_MR presence: online


Als Folge z.B. des OG_BAD_MR Offlines kamen auch nach dem "online" keine Events mehr vom Renderer.
Erst ein modify hat die Events wieder aktiviert.

Die offlines sind wahrscheinlich mein Problem, aber das erst ein modify gemacht werden muss, ist glaube ich nicht richtig.

Ich habe Dir mal logs angehangen (Ausschnitte). Wenn Du die Muße hast, kannst Du ja mal drüber schauen.

Ggf. hast Du ja noch eine Idee, was ich weiter testen kann.

Das multiroom-Zeugs geht irgendwie. Anscheinend holt sich ein zusätzliches Device mit der gleichen SessionID mittels
"currentTrackURI rtsp://192.168.4.33:8554/stream"
den Stream des masters und folgt diesem dann.

Bin aber noch weiter am Testen, da die peaq App nicht mehr unter Android > 7.0 läuft muss ich ein Telefon zurück drehen.

Gruß Michael

[KölnSolar]

Hallo Michael,

Als Folge z.B. des OG_BAD_MR Offlines kamen auch nach dem "online" keine Events mehr vom Renderer.
Erst ein modify hat die Events wieder aktiviert.

Schau Dir in solchen Fällen bitte mal das DLNAController-device vor dem modify näher an. Stimmen das Internal address(IP_Port) mit den entsprechenden Readings im UPNPController überein ? Kann IP_Port sich geändert haben ? Mehrere IP_Port-Readings ? Allerdings müsste sich ein address-change auch bei verbose=3 im Log melden. Ich hab da meinen FritzRepeater, der sich auch komisch/ähnlich verhält. Er meldet sich mit einer (eigentlich falschen  ) IP per UPnP, wenn ich ihn morgens aus dem Nachtschlaf erwachen lasse. Das ist dann aber nur kurz u. UPnPController/DLNAController passen sich entsprechend an.
Tatsächlich geht dann die subscription verloren. Das lässt sich sicherlich durch eine Modifikation lösen. Edit: Ich bin dem mal näher auf den Grund gegangen. Es dürfte mit der IP_Port-Änderung zusammenhängen, was nicht richtig implementiert war(u. auch die x mal 5s freezes ließen sich so erklären). Ersetze bitte mal die Parse_Sub im DLNAControllermit

Code Auswählen Erweitern

sub DLNAController_Parse($$)
{
my ( $io_hash, $message) = @_;

        my ($modulekey,$address,$property,$propertyval) = split("\\|",$message);
      Log3 $io_hash, 5, "DLNAController: message from $io_hash->{NAME}, message: $message";
my $udn = ReadingsVal($io_hash->{NAME}, $address."-UDN", "not found");

my $def = "$udn $address";
        Log3 $io_hash, 4, "DLNAController: message parameters: $modulekey, $address, $property, $propertyval";
# wenn bereits eine Gerätedefinition existiert (via Definition Pointer aus Define-Funktion)
if(my $hash = $modules{DLNAController}{defptr}{$udn}) {
#           has address changed ?
        if ($hash->{address} ne $address) {
           $hash->{address} = $address;
         $hash->{helper}{subscribed} = 0;
    }
    $hash->{DEF} = $def;
    if($property ne "online" && $property ne "offline") {
DLNAController_processEventXml($hash, $property, $propertyval);
DLNAController_devicestate($hash, "online");        
    }
    else {
               if ($hash->{helper}{subscribed} != 1 &&
                   $property ne "offline") {
    DLNAController_upnpAction($hash, 'RenderingControl', 'subscribe');
  DLNAController_upnpAction($hash, 'AVTransport', 'subscribe');
    DLNAController_upnpAction($hash, 'SpeakerManagement', 'subscribe');
    DLNAController_upnpAction($hash, 'SessionManagement', 'subscribe');
    Log3 $hash, 3, "DLNAController: $hash->{NAME} address changed; services initially subscribed";   
    $hash->{helper}{subscribed} = 1;
       }
DLNAController_devicestate($hash, $property);
    }
    return $hash->{NAME};
        }
else {
            my @temp = split(":",$udn);
            $temp[1] =~ tr/-/_/;
    return "UNDEFINED DLNA_".$temp[1]." DLNAController ".$def;
}
}

Ich lass das bei mir auch laufen u. morgen früh sollte ich das (positive) Ergebnis sehen.

Warum - kann ich nicht sagen!

Nur um es zu verstehen(ich vermute, dass nicht um 2 nachts Musik gehört wurde  ): Die Teile sind im Normalfall 24/7 online ? Könnte da evtl. was mit dem WLAN sein ? Bei einer FritzBox würde man die An-/Abmeldung in den Systemereignissen sehen können. Selbst, wenn gerade ein stream läuft, dürfte man das nicht akkustisch merken, weil die streams ja eine gewisse Zeit gepuffert sind u. der Zeitraum offline-online immer nur sehr kurz scheint.

Die anderen Dinge gucke ich mir in Ruhe an. Bin im Augenblick leider zeitlich durch einen Festplattencrash gehandicaped u. das Umstellen auf eine neue xml-parser-Lib bereitet mir auch mehr Probleme als erwartet.

Grüße Markus

Edit: Es scheint funktioniert zu haben.  Mal für Dich zum Vergleich, welcher Unsinn da bei mir passiert. Ich hab mal versucht durch Absetzungen die wesentlichen von den eher unwesentlichen Log-Meldungen zu trennen. Im groben siehst Du, dass es KEINE Abmeldung gestern Abend gab, durch das subscription renewal[mit 500ern(mögliche freezes)] der offline-status erkannt u. korrigiert wurde. Dann meldet sich heute Morgen das device mit der "falschen"(keine Ahnung warum  ) IP. UPNPController u. DLNAController reagieren auf die IP-Änderung. Obwohl sich das device gerade selber mit dieser IP gemeldet hat, schlagen die subscriptions fehl mit 500ern(mögliche freezes), was wieder zu "offline" in FHEM führt. Dann kommt die korrekte IP in einer weiteren alive-message. Das Spiel beginnt von vorn. Nur dass diesmal alles so verläuft, wie es sich gehört:

Code Auswählen Erweitern

-----> event für 192.x.y.37  <----- successful (typical event;normally every 12')
2021.04.12 23:25:39 4: DLNAController: message parameters: AVTransport, 192.x.y.37_49200, LastChange, <Event xmlns = "urn:schemas-upnp-org:metadata-1-0/AVT/"> <InstanceID val="0"> <TransportState val="STOPPED"/><TransportStatus val="OK"/><PlaybackStorageMedium val="NETWORK"/><RecordStorageMedium val="NOT_IMPLEMENTED"/><CurrentPlayMode val="NORMAL"/><RecordMediumWriteStatus val="NOT_IMPLEMENTED"/><CurrentRecordQualityMode val="NOT_IMPLEMENTED"/><CurrentTrackDuration val="00:00:00"/><CurrentMediaDuration val="00:00:00"/><CurrentTrackMetaData val=""/><CurrentTrackURI val="http://translate.google.com/translate_tts?tl=en&client=tw-ob&q=Test"/><AVTransportURI val="http://translate.google.com/translate_tts?tl=en&client=tw-ob&q=Test"/><NextAVTransportURI val=""/><CurrentTransportActions val="Play,Stop,Seek"/><PossiblePlaybackStorageMedia val="NONE,NETWORK,USB-MASS"/><PossibleRecordStorageMedia val="NOT_IMPLEMENTED"/><PossibleRecordQualityModes val="NOT_IMPLEMENTED"/><TransportPlaySpeed val="1"/><NumberOfTracks val="1"/><CurrentTrack val="1"/> </InstanceID> </Event>


-----> last renewal für 192.x.y.37  <----- successful
2021.04.12 23:33:01 5: UPNPController: renew subscription for service AVTransport of device 192.x.y.37_49200

-----> last event für 192.x.y.37  before sleep <----- successful
2021.04.12 23:37:39 4: DLNAController DLNA_fa095ecc_e13e_40e7_8e6c_BC0543512C9A: state update from UPNP_Controller, address 192.x.y.37_49200

-----> 23:45 go to sleep für 192.x.y.37  <----- no byebye-message sent; not DLNA compliant !!!!

-----> periodic renewal of subscriptions 192.x.y.37  <----- failure; device no longer available(no byebye event sent before !!!!)
2021.04.13 00:02:02 4: UPNPController: try to renew subscriptions for services, device UPNP_Controller with timeout: 1800
2021.04.13 00:02:02 5: UPNPController: renew subscription for service AVTransport of device 192.x.y.37_49200
2021.04.13 00:02:07 5: UPNPController: warning: Carp, Renewal of subscription failed with error: 500 Can't connect to 192.x.y.37:49200 (Connection timed out) at ./FHEM/98_UPNPController.pm line 790.
2021.04.13 00:02:07 3: UPNPController: renewal of subscription for service AVTransport of device 192.x.y.37_49200 failed: , try to subscribe
2021.04.13 00:02:07 5: UPNPController: renew subscription for service RenderingControl of device 192.x.y.37_49200
2021.04.13 00:02:12 5: UPNPController: warning: Carp, Renewal of subscription failed with error: 500 Can't connect to 192.x.y.37:49200 (Connection timed out) at ./FHEM/98_UPNPController.pm line 790.
2021.04.13 00:02:12 3: UPNPController: renewal of subscription for service RenderingControl of device 192.x.y.37_49200 failed: , try to subscribe
2021.04.13 00:02:12 5: UPNPController: renewSubscriptionsfinished name UPNP_Controller, readingname 192.x.y.37_49200-zs-RenderingControl
2021.04.13 00:02:12 4: UPNPController: subscribe: reading  192.x.y.37_49200-zs-RenderingControl, uniquedevice 192.x.y.37_49200, service RenderingControl
2021.04.13 00:02:12 5: UPNPController: RenderingControl: urn:schemas-upnp-org:service:RenderingControl:1 found. OK.
2021.04.13 00:02:12 5: UPNPController: RenderingControl: urn:schemas-upnp-org:service:RenderingControl:1 found. OK.
2021.04.13 00:02:13 5: UPNPController: warning: Carp, Subscription request failed with error: 500 Can't connect to 192.x.y.37:49200 (No route to host) at ./FHEM/98_UPNPController.pm line 719.
2021.04.13 00:02:13 4: UPNPController: discovery message of AVM FRITZ!MediaRenderer with UDN: uuid:fa095ecc-e13e-40e7-8e6c-BC0543512C9A action: deviceRemoved
2021.04.13 00:02:13 5: UPNPController: UPNP_Controller: byebye-notify message device 192.x.y.37_49200 received
2021.04.13 00:02:13 5: UPNPController: earlier subscribed service AVTransport of device 192.x.y.37_49200 went offline
2021.04.13 00:02:13 5: UPNP_Controller: dispatch AVTransport|192.x.y.37_49200|offline|urn:schemas-upnp-org:metadata-1-0/AVT
2021.04.13 00:02:13 5: DLNAController: message from UPNP_Controller, message: AVTransport|192.x.y.37_49200|offline|urn:schemas-upnp-org:metadata-1-0/AVT
2021.04.13 00:02:13 4: DLNAController: message parameters: AVTransport, 192.x.y.37_49200, offline, urn:schemas-upnp-org:metadata-1-0/AVT
2021.04.13 00:02:13 4: DLNAController DLNA_fa095ecc_e13e_40e7_8e6c_BC0543512C9A: state update from UPNP_Controller, address 192.x.y.37_49200
2021.04.13 00:02:13 5: UPNP_Controller: dispatch RenderingControl|192.x.y.37_49200|offline|urn:schemas-upnp-org:metadata-1-0/RCS
2021.04.13 00:02:13 5: DLNAController: message from UPNP_Controller, message: RenderingControl|192.x.y.37_49200|offline|urn:schemas-upnp-org:metadata-1-0/RCS
2021.04.13 00:02:13 4: DLNAController: message parameters: RenderingControl, 192.x.y.37_49200, offline, urn:schemas-upnp-org:metadata-1-0/RCS
2021.04.13 00:02:13 4: DLNAController DLNA_fa095ecc_e13e_40e7_8e6c_BC0543512C9A: state update from UPNP_Controller, address 192.x.y.37_49200
2021.04.13 00:02:13 3: UPNPController: subscription for service RenderingControl of device 192.x.y.37_49200 failed:

-----> 06:00 awakes from sleep für 192.x.y.37  <----- alive message with fault IP 192.x.y.2 for ALL services
2021.04.13 06:00:39 4: UPNPController: discovery message of AVM FRITZ!MediaRenderer with UDN: uuid:fa095ecc-e13e-40e7-8e6c-BC0543512C9A action: deviceAdded
2021.04.13 06:00:39 5: UPNPController: UPNP_Controller: alive-notify message device uuid:fa095ecc-e13e-40e7-8e6c-BC0543512C9A received

-----> different IP(address) recognized for 192.x.y.37  <----- old readings deleted; DLNAController with new address; new subscriptions
2021.04.13 06:00:39 3: UPNPController: old definition of device uuid:fa095ecc-e13e-40e7-8e6c-BC0543512C9A found with 192.x.y.37_49200. readings deleted.

2021.04.13 06:00:39 5: UPNPController: UPNP_Controller: device uuid:fa095ecc-e13e-40e7-8e6c-BC0543512C9A found. Check for processing
2021.04.13 06:00:39 5: UPNPController: UPNP_Controller: device uuid:fa095ecc-e13e-40e7-8e6c-BC0543512C9A will be controlled with 192.x.y.2_49200
2021.04.13 06:00:39 5: UPNPController: UPNP_Controller: device uuid:fa095ecc-e13e-40e7-8e6c-BC0543512C9A has service with serviceId: RenderingControl
2021.04.13 06:00:39 5: UPNPController: UPNP_Controller: device uuid:fa095ecc-e13e-40e7-8e6c-BC0543512C9A has service with serviceId: ConnectionManager
2021.04.13 06:00:39 5: UPNPController: UPNP_Controller: device uuid:fa095ecc-e13e-40e7-8e6c-BC0543512C9A has service with serviceId: AVTransport
2021.04.13 06:00:39 5: UPNP_Controller: dispatch AVTransport|192.x.y.2_49200|online|urn:schemas-upnp-org:metadata-1-0/AVT
2021.04.13 06:00:39 5: DLNAController: message from UPNP_Controller, message: AVTransport|192.x.y.2_49200|online|urn:schemas-upnp-org:metadata-1-0/AVT

2021.04.13 06:00:39 4: DLNAController: message parameters: AVTransport, 192.x.y.2_49200, online, urn:schemas-upnp-org:metadata-1-0/AVT

2021.04.13 06:00:39 5: UPNPController: UPNP_Controller, 192.x.y.2_49200, RenderingControl, subscribe,
2021.04.13 06:00:39 5: UPNPController: RenderingControl: urn:schemas-upnp-org:service:RenderingControl:1 found. OK.
2021.04.13 06:00:39 4: UPNPController: subscribe: reading  192.x.y.2_49200-zs-RenderingControl, uniquedevice 192.x.y.2_49200, service RenderingControl
2021.04.13 06:00:39 5: UPNPController: RenderingControl: urn:schemas-upnp-org:service:RenderingControl:1 found. OK.
2021.04.13 06:00:39 5: UPNPController: RenderingControl: urn:schemas-upnp-org:service:RenderingControl:1 found. OK.
2021.04.13 06:00:39 4: UPNPController: subscribe: reading  192.x.y.2_49200-zs-RenderingControl, uniquedevice 192.x.y.2_49200, service RenderingControl timeout: 1800
2021.04.13 06:00:39 5: UPNPController: UPNP_Controller, 192.x.y.2_49200, AVTransport, subscribe,
2021.04.13 06:00:39 5: UPNPController: AVTransport: urn:schemas-upnp-org:service:AVTransport:1 found. OK.
2021.04.13 06:00:39 4: UPNPController: subscribe: reading  192.x.y.2_49200-zs-AVTransport, uniquedevice 192.x.y.2_49200, service AVTransport
2021.04.13 06:00:39 5: UPNPController: AVTransport: urn:schemas-upnp-org:service:AVTransport:1 found. OK.
2021.04.13 06:00:39 5: UPNPController: AVTransport: urn:schemas-upnp-org:service:AVTransport:1 found. OK.

2021.04.13 06:00:42 5: UPNPController: warning: Carp, Subscription request failed with error: 500 Can't connect to 192.x.y.2:49200 (No route to host) at ./FHEM/98_UPNPController.pm line 719.

2021.04.13 06:00:42 5: UPNP_Controller: dispatch AVTransport|192.x.y.2_49200|offline|urn:schemas-upnp-org:metadata-1-0/AVT
2021.04.13 06:00:42 5: DLNAController: message from UPNP_Controller, message: AVTransport|192.x.y.2_49200|offline|urn:schemas-upnp-org:metadata-1-0/AVT

2021.04.13 06:00:42 4: DLNAController: message parameters: AVTransport, 192.x.y.2_49200, offline, urn:schemas-upnp-org:metadata-1-0/AVT
2021.04.13 06:00:42 4: DLNAController DLNA_fa095ecc_e13e_40e7_8e6c_BC0543512C9A: state update from UPNP_Controller, address 192.x.y.2_49200

2021.04.13 06:00:42 3: UPNPController: subscription for service AVTransport of device 192.x.y.2_49200 failed:

2021.04.13 06:00:42 3: DLNAController: DLNA_fa095ecc_e13e_40e7_8e6c_BC0543512C9A address changed; services initially subscribed
2021.04.13 06:00:42 4: DLNAController DLNA_fa095ecc_e13e_40e7_8e6c_BC0543512C9A: state update from UPNP_Controller, address 192.x.y.2_49200

2021.04.13 06:00:43 5: UPNPController: Received event: by 192.x.y.2_49200-zs-RenderingControl UPnP::ControlPoint::Service=HASH(0x45f0508) $VAR1 = 'LastChange';
2021.04.13 06:00:43 5: UPNPController: Received event: by 192.x.y.2_49200-zs-RenderingControl property: <Event xmlns = "urn:schemas-upnp-org:metadata-1-0/AVT_RCS"> <InstanceID val="0"> <PresetNameList val="FactoryDefaults"/> </InstanceID> </Event>
2021.04.13 06:00:43 5: UPNP_Controller: dispatch AVTransport|192.x.y.2_49200|LastChange|<Event xmlns = "urn:schemas-upnp-org:metadata-1-0/AVT_RCS"> <InstanceID val="0"> <PresetNameList val="FactoryDefaults"/> </InstanceID> </Event>
2021.04.13 06:00:43 5: DLNAController: message from UPNP_Controller, message: AVTransport|192.x.y.2_49200|LastChange|<Event xmlns = "urn:schemas-upnp-org:metadata-1-0/AVT_RCS"> <InstanceID val="0"> <PresetNameList val="FactoryDefaults"/> </InstanceID> </Event>
2021.04.13 06:00:43 4: DLNAController: message parameters: AVTransport, 192.x.y.2_49200, LastChange, <Event xmlns = "urn:schemas-upnp-org:metadata-1-0/AVT_RCS"> <InstanceID val="0"> <PresetNameList val="FactoryDefaults"/> </InstanceID> </Event>
2021.04.13 06:00:43 4: DLNAController DLNA_fa095ecc_e13e_40e7_8e6c_BC0543512C9A: state update from UPNP_Controller, address 192.x.y.2_49200

2021.04.13 06:00:45 5: UPNPController: warning: Carp, Loading device description failed with error: 500 Can't connect to 192.x.y.2:49200 (No route to host) (Location: http://192.x.y.2:49200/MediaRendererDevDesc.xml) at ./FHEM/98_UPNPController.pm line 217.

2021.04.13 06:00:46 5: UPNPController: Received event: by 192.x.y.2_49200-zs-RenderingControl UPnP::ControlPoint::Service=HASH(0x45f0508) $VAR1 = 'LastChange';
$VAR2 = '&lt;Event xmlns = &quot;urn:schemas-upnp-org:metadata-1-0/AVT_RCS&quot;&gt; &lt;InstanceID val=&quot;0&quot;&gt; &lt;PresetNameList val=&quot;FactoryDefaults&quot;/&gt; &lt;/InstanceID&gt; &lt;/Event&gt;';
2021.04.13 06:00:46 5: UPNPController: Received event: by 192.x.y.2_49200-zs-RenderingControl property: <Event xmlns = "urn:schemas-upnp-org:metadata-1-0/AVT_RCS"> <InstanceID val="0"> <PresetNameList val="FactoryDefaults"/> </InstanceID> </Event>
2021.04.13 06:00:46 5: UPNP_Controller: dispatch AVTransport|192.x.y.2_49200|LastChange|<Event xmlns = "urn:schemas-upnp-org:metadata-1-0/AVT_RCS"> <InstanceID val="0"> <PresetNameList val="FactoryDefaults"/> </InstanceID> </Event>
2021.04.13 06:00:46 5: DLNAController: message from UPNP_Controller, message: AVTransport|192.x.y.2_49200|LastChange|<Event xmlns = "urn:schemas-upnp-org:metadata-1-0/AVT_RCS"> <InstanceID val="0"> <PresetNameList val="FactoryDefaults"/> </InstanceID> </Event>
2021.04.13 06:00:46 4: DLNAController: message parameters: AVTransport, 192.x.y.2_49200, LastChange, <Event xmlns = "urn:schemas-upnp-org:metadata-1-0/AVT_RCS"> <InstanceID val="0"> <PresetNameList val="FactoryDefaults"/> </InstanceID> </Event>
2021.04.13 06:00:46 4: DLNAController DLNA_fa095ecc_e13e_40e7_8e6c_BC0543512C9A: state update from UPNP_Controller, address 192.x.y.2_49200

2021.04.13 06:00:48 5: UPNPController: warning: Carp, Loading device description failed with error: 500 Can't connect to 192.x.y.2:49200 (No route to host) (Location: http://192.x.y.2:49200/MediaRendererDevDesc.xml) at ./FHEM/98_UPNPController.pm line 217.
2021.04.13 06:00:51 5: UPNPController: warning: Carp, Loading device description failed with error: 500 Can't connect to 192.x.y.2:49200 (No route to host) (Location: http://192.x.y.2:49200/MediaRendererDevDesc.xml) at ./FHEM/98_UPNPController.pm line 217.

2021.04.13 06:00:52 4: UPNPController: try to renew subscriptions for services, device UPNP_Controller with timeout: 1800
2021.04.13 06:00:52 5: UPNPController: Received event: by 192.x.y.2_49200-zs-RenderingControl UPnP::ControlPoint::Service=HASH(0x45f0508) $VAR1 = 'LastChange';
$VAR2 = '&lt;Event xmlns = &quot;urn:schemas-upnp-org:metadata-1-0/AVT_RCS&quot;&gt; &lt;InstanceID val=&quot;0&quot;&gt; &lt;PresetNameList val=&quot;FactoryDefaults&quot;/&gt; &lt;/InstanceID&gt; &lt;/Event&gt;';
2021.04.13 06:00:52 5: UPNPController: Received event: by 192.x.y.2_49200-zs-RenderingControl property: <Event xmlns = "urn:schemas-upnp-org:metadata-1-0/AVT_RCS"> <InstanceID val="0"> <PresetNameList val="FactoryDefaults"/> </InstanceID> </Event>
2021.04.13 06:00:52 5: UPNP_Controller: dispatch AVTransport|192.x.y.2_49200|LastChange|<Event xmlns = "urn:schemas-upnp-org:metadata-1-0/AVT_RCS"> <InstanceID val="0"> <PresetNameList val="FactoryDefaults"/> </InstanceID> </Event>
2021.04.13 06:00:52 5: DLNAController: message from UPNP_Controller, message: AVTransport|192.x.y.2_49200|LastChange|<Event xmlns = "urn:schemas-upnp-org:metadata-1-0/AVT_RCS"> <InstanceID val="0"> <PresetNameList val="FactoryDefaults"/> </InstanceID> </Event>
2021.04.13 06:00:52 4: DLNAController: message parameters: AVTransport, 192.x.y.2_49200, LastChange, <Event xmlns = "urn:schemas-upnp-org:metadata-1-0/AVT_RCS"> <InstanceID val="0"> <PresetNameList val="FactoryDefaults"/> </InstanceID> </Event>
2021.04.13 06:00:52 4: DLNAController DLNA_fa095ecc_e13e_40e7_8e6c_BC0543512C9A: state update from UPNP_Controller, address 192.x.y.2_49200

2021.04.13 06:00:54 5: UPNPController: warning: Carp, Loading device description failed with error: 500 Can't connect to 192.x.y.2:49200 (No route to host) (Location: http://192.x.y.2:49200/MediaRendererDevDesc.xml) at ./FHEM/98_UPNPController.pm line 217.
2021.04.13 06:00:57 5: UPNPController: warning: Carp, Loading device description failed with error: 500 Can't connect to 192.x.y.2:49200 (No route to host) (Location: http://192.x.y.2:49200/MediaRendererDevDesc.xml) at ./FHEM/98_UPNPController.pm line 217.

-----> correct IP(address) recognized for 192.x.y.37  <----- old readings(192.x.y.2) deleted; DLNAController with new (correct) address; new subscriptions
2021.04.13 06:00:58 5: UPNPController: UPNP_Controller: alive-notify message device uuid:fa095ecc-e13e-40e7-8e6c-BC0543512C9A received

2021.04.13 06:00:58 3: UPNPController: old definition of device uuid:fa095ecc-e13e-40e7-8e6c-BC0543512C9A found with 192.x.y.2_49200. readings deleted.

2021.04.13 06:00:58 5: UPNPController: UPNP_Controller: device uuid:fa095ecc-e13e-40e7-8e6c-BC0543512C9A found. Check for processing
2021.04.13 06:00:58 5: UPNPController: UPNP_Controller: device uuid:fa095ecc-e13e-40e7-8e6c-BC0543512C9A will be controlled with 192.x.y.37_49200
2021.04.13 06:00:58 5: UPNPController: UPNP_Controller: device uuid:fa095ecc-e13e-40e7-8e6c-BC0543512C9A has service with serviceId: RenderingControl
2021.04.13 06:00:58 5: UPNPController: UPNP_Controller: device uuid:fa095ecc-e13e-40e7-8e6c-BC0543512C9A has service with serviceId: ConnectionManager
2021.04.13 06:00:58 5: UPNPController: UPNP_Controller: device uuid:fa095ecc-e13e-40e7-8e6c-BC0543512C9A has service with serviceId: AVTransport
2021.04.13 06:00:58 5: UPNP_Controller: dispatch AVTransport|192.x.y.37_49200|online|urn:schemas-upnp-org:metadata-1-0/AVT
2021.04.13 06:00:58 5: DLNAController: message from UPNP_Controller, message: AVTransport|192.x.y.37_49200|online|urn:schemas-upnp-org:metadata-1-0/AVT

2021.04.13 06:00:58 4: DLNAController: message parameters: AVTransport, 192.x.y.37_49200, online, urn:schemas-upnp-org:metadata-1-0/AVT

2021.04.13 06:00:58 5: UPNPController: UPNP_Controller, 192.x.y.37_49200, RenderingControl, subscribe,
2021.04.13 06:00:58 5: UPNPController: RenderingControl: urn:schemas-upnp-org:service:RenderingControl:1 found. OK.
2021.04.13 06:00:58 4: UPNPController: subscribe: reading  192.x.y.37_49200-zs-RenderingControl, uniquedevice 192.x.y.37_49200, service RenderingControl
2021.04.13 06:00:58 5: UPNPController: RenderingControl: urn:schemas-upnp-org:service:RenderingControl:1 found. OK.
2021.04.13 06:00:58 5: UPNPController: RenderingControl: urn:schemas-upnp-org:service:RenderingControl:1 found. OK.
2021.04.13 06:00:58 4: UPNPController: subscribe: reading  192.x.y.37_49200-zs-RenderingControl, uniquedevice 192.x.y.37_49200, service RenderingControl timeout: 1800
2021.04.13 06:00:58 5: UPNPController: UPNP_Controller, 192.x.y.37_49200, AVTransport, subscribe,
2021.04.13 06:00:58 5: UPNPController: AVTransport: urn:schemas-upnp-org:service:AVTransport:1 found. OK.
2021.04.13 06:00:58 4: UPNPController: subscribe: reading  192.x.y.37_49200-zs-AVTransport, uniquedevice 192.x.y.37_49200, service AVTransport
2021.04.13 06:00:58 5: UPNPController: AVTransport: urn:schemas-upnp-org:service:AVTransport:1 found. OK.
2021.04.13 06:00:58 5: UPNPController: AVTransport: urn:schemas-upnp-org:service:AVTransport:1 found. OK.
2021.04.13 06:00:58 4: UPNPController: subscribe: reading  192.x.y.37_49200-zs-AVTransport, uniquedevice 192.x.y.37_49200, service AVTransport timeout: 1800

2021.04.13 06:00:58 3: DLNAController: DLNA_fa095ecc_e13e_40e7_8e6c_BC0543512C9A address changed; services initially subscribed

2021.04.13 06:00:58 4: DLNAController DLNA_fa095ecc_e13e_40e7_8e6c_BC0543512C9A: state update from UPNP_Controller, address 192.x.y.37_49200
.....
Edit2: Auch an Tag2 sieht es gut aus. Im UPNPController sind die services um 6:00 neu subscribed u. das DLNAController-device verarbeitet brav die eintreffenden events.

[enno]

Moin Markus,

ich habe "The Frame" von Samsung am Start und du hattest den Tip (https://forum.fhem.de/index.php/topic,109498.25.html) gegeben es hier zu testen. Ich habe schnell mal UPNPController nach Anleitung auf meinem Raspi 3 installiert. Die Readings werden angelegt, aber ich bekomme im Log im 9 Sekunden Takt folgende Fehlermeldung. Was könnte fehlen? Was hilft bei der Fehlersuche?

Code Auswählen Erweitern

2021.04.16 18:35:36 3: UPNPController: handleOnce failed, not properly closed tag 'root'

Gruss
  Enno

[KölnSolar]

Hi Enno,

Was hilft bei der Fehlersuche?

Ein Log mit verbose=4 sollte genügen. Dann sehen wir den Bösewicht.

Ob die Fehlermeldung wahr ist, lässt sich dann in einem weiteren Schritt prüfen. Ich hab auch ein Gerät, welches ein vermeintlich fehlerhaftes XML meldet. Ich arbeite derzeit daran einen anderen xml-parser einzusetzen. Dauert aber noch.

Grüße Markus
Edit: wenn der Bösewicht gefunden ist, lässt er sich über die Attribute ausschließen.