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

[KölnSolar]

Hi Dieter,
jetzt wird s klar, es ist die FritzBox und nicht ein Repeater, der die dieses MüllSonderzeichen liefert. 
set subscribe

Code Auswählen Erweitern

2022.03.10 17:20:24 4: UPNPController: subscribe: reading  192.168.178.1_49000_1-zz-zz-zs-WANIPConn1, uniquedevice 192.168.178.1_49000_1-zz-zz, service WANIPConn1
2022.03.10 17:20:24 5: UPNPController: WANIPConn1: urn:upnp-org:serviceId:WANIPConn1 found. OK.
2022.03.10 17:20:24 4: UPNPController: subscribe: reading  192.168.178.1_49000_1-zz-zz-zs-WANIPConn1, uniquedevice 192.168.178.1_49000_1-zz-zz, service WANIPConn1 timeout: 1800und nun kommt das event

Code Auswählen Erweitern


2022.03.10 17:20:25 3: UPNPController:DEBUG UPNPSocket-UPNP_Controller-45899, received subscription message IP: 192.168.178.1 on port 45899 will be checked now
2022.03.10 17:20:25 3: UPNPController:DEBUG UPNPSocket-UPNP_Controller-45899, received subscription message IP: 192.168.178.1 on port 45899 will be processed now
junk '
' after XML element

Dann mach doch mal bitte die Modifikation, die ich vorgestern vorgeschlagen hatte. Du wirst sehen, es funktioniert.

(wobei für mich das Phänomen mit usedonlyIPs bleibt;hab heute das Ganze noch einmal detaillierter getestet. Funktioniert problemlos bei mir.  )

Grüße Markus

Edit: Aber eine Absturzursache ist das nicht. Kann es sein, dass Dein Watchdog auf freezes reagiert hat ? Oder gar kein Neustart, sondern nur seeeehr lange freezes haben Dich irritiert ?

[RockFan]

Hi Markus,
die Codeänderung scheint sich positiv ausgewirkt zu haben 

Schon vor dem Aktivieren des Debug-Modus finde ich Informationen zur Fritte:

Code Auswählen Erweitern


gelöscht


Hier nun auch noch die Ausgabe während der guten Minute im Debug inkl. Subscribe und v.a. ohne Neustart von FHEM:

Code Auswählen Erweitern


gelöscht


Ist das nun das erwartete Ergebnis?

Warum nun in den beiden vorigen Versuchen FHEM Neugestartet wurde bleibt unklar. Ich glaube ein Neustart wird durch den HW Watchdog vom Raspi initiiert, wenn FHEM einige Zeit (30 Minuten) sich nicht mehr meldet (Schreiben von fhem.save). Es passierte ja auch unmittelbar (ca. eine halbe Minute nach dem Setzen von Debug plus Subscribe).

Viele Grüße
Dieter

[RockFan]

Guten Morgen Markus,

Jetzt kommen auch Einträge für die Zwangstrennung:

Code Auswählen Erweitern


gelöscht


Viele Grüße
Dieter

[KölnSolar]

Guten Morgen Dieter,
hatte ich nicht anders erwartet.

Ist das nun das erwartete Ergebnis?

Jawoll.

Aber es ist nur eine vorübergehende Lösung, denn das Editieren und Modifizieren von perl-Paketen sollte nicht die Lösung bleiben. Mal sehen...

Warum nun in den beiden vorigen Versuchen FHEM  Neugestartet wurde bleibt unklar.

Wenn es ein Absturz durch/von FHEM war, müsstest Du ja im Log vor den markanten Zeilen für einen Neustart einen Hinweis auf den Verursacher finden können. Ansonsten bleibt mein Verdacht, dass freezes den Neustart über den watchdog ausgelöst haben. freezemon hast Du installiert ?

Kannst jetzt all Deine Log-Auszüge löschen, wenn Du magst. Insbesondere aber den Letzten, denn dort hast Du jetzt Deine aktuelle v4- u. v6-Adresse veröffentlicht. Oder Du machst einen reconnect an der Fritzbox. Ist sonst ein nettes Angriffsziel. 

Grüße Markus

[RockFan]

Danke Markus!!

Aber es ist nur eine vorübergehende Lösung, denn das Editieren und Modifizieren von perl-Paketen sollte nicht die Lösung bleiben. Mal sehen...
Wenn es ein Absturz durch/von FHEM war, müsstest Du ja im Log vor den markanten Zeilen für einen Neustart einen Hinweis auf den Verursacher finden können. Ansonsten bleibt mein Verdacht, dass freezes den Neustart über den watchdog ausgelöst haben. freezemon hast Du installiert ?

Ja, ich verwende freezmon schon sehr lange und habe recht viele Einträge im Log, seit ich es aktiviert habe.
Ich muss mir am WE die Logs nochmal genauer anschauen, aber für mich sah es so aus wie immer. Direkt vor dem Neustart waren auch nur die geposteten Logs. Ich habe allerdings auch das Phänomen, dass ich meistens nach einem "shutdown restart" einen doppelten Restart habe, obwohl ich seit einiger Zeit restartDelay in global auf 5 gesetzt habe. Keine Ahnung warum das passiert.

Kannst jetzt all Deine Log-Auszüge löschen, wenn Du magst. Insbesondere aber den Letzten, denn dort hast Du jetzt Deine aktuelle v4- u. v6-Adresse veröffentlicht. Oder Du machst einen reconnect an der Fritzbox. Ist sonst ein nettes Angriffsziel. 

Ich hoffe ich habe alle relevanten Logs erwischt 

Viele Grüße
Dieter

[KölnSolar]

@all
mir wurde per PN ein Fall gemeldet, dass das device keinen "echten" service bietet. Das xml (location) sieht dann so aus 

Code Auswählen Erweitern

<root xmlns="urn:schemas-upnp-org:device-1-0">
<specVersion>
<major>1</major>
<minor>0</minor>
</specVersion>
<device>
<deviceType>urn:schemas-upnp-org:device:VBus/LAN:1</deviceType>
<friendlyName>VBus LAN-Adapter (IP)</friendlyName>
<manufacturer>Hersteller GmbH</manufacturer>
<manufacturerURL>http://www.hersteller.com</manufacturerURL>
<modelDescription>VBus/LAN Module</modelDescription>
<modelName>VBus/LAN</modelName>
<modelNumber>VBus/LAN</modelNumber>
<UDN>uuid:upnp_VBus/LAN-spezifischeNr.</UDN>
<serviceList>
<service>
<serviceType>(null)</serviceType>
<serviceId>(null)</serviceId>
<controlURL>(null)</controlURL>
<eventSubURL>(null)</eventSubURL>
<SCPDURL>(null)</SCPDURL>
</service>
</serviceList>
<presentationURL>http://IP:Port</presentationURL>
</device>
</root> Das ist natürlich Unfug. Ein service, der keiner ist, und eine SCPDURL, die keine URL ist. 
Zum einen erzeugt das unnötige freezes, aber auch Probleme beim reading, da die Klammern eigentlich unzulässig sind.

Code Auswählen Erweitern

setstate UPNPController 2022-03-13 20:11:25 IP_Port-zs-(null) (null)

Ich werde also diesen Unfug abfangen. Jetzt stellt sich die Frage, ob jemand ähnlichen Unfug in seinem LAN hat, der möglicherweise etwas anders geartet ist und auch abgefangen werden sollte.

@Dieter: Und, wie läufts nun ? Möglicherweise jetzt auch die Medion's vernünftig integriert ? Keine ominösen Log-Meldungen und, viel wichtiger, keine freezes ?

@all: Apropos freezes. Irgendwo hatte ich glaub ich bereits auf die APIPA-Thematik(ggfs. wird zumindest kurzzeitig eine IP aus einem festen Nummernkreis z.B. 169.254.x.y anstatt DHCP vergeben) hingewiesen. Es kann auch sein, dass ein device eine (unsinnige) fest vorgegebene statische IP kurz nutzt. Im Log machen sich beide Fälle mit "old .... found...deleted" Einträge bemerkbar, z.B. mein Repeater

Code Auswählen Erweitern

2022.03.13 06:35:06 3: UPNPController: old definition of device uuid:fa095ecc-e13e-40e7-8e6c-BC0543512C9A found with statische_unsinnige_IP_49200. readings deleted.
und logischerweise auch freezes(weil es das device irgendwann ja nicht mehr im Netzwerk gibt) bemerkbar.

Die unerwünschten IP's lassen sich per regexp ausschließen. Wichtig sind die umschließenden /regexp/, wenn es ein regexp und keine einzelne IP ist

Code Auswählen Erweitern

attr UPNPController ignoredIPs /169\.254\..*$/ Dadurch werden dann freezes vermieden, die nur darauf zurückzuführen sind, dass ein device sich kurz mit einer APIPA-IP meldet, dann aber selber auf DHCP-IP ändert und logischerweise der URL-Zugriff in die Hose geht.

Grüße Markus

[mumpitzstuff]

Besteht vielleicht die Möglichkeit die Module irgendwie über github verfügbar zu machen und per Update einzubinden? Das manuelle umkopieren ist irgendwie maximal aufwendig.

[RockFan]

@Dieter: Und, wie läufts nun ? Möglicherweise jetzt auch die Medion's vernünftig integriert ? Keine ominösen Log-Meldungen und, viel wichtiger, keine freezes ?

Hi Markus,

sorry, hatte mich nicht zurückgemeldet. Am Wochenende hatte ich mal versucht etwas ungewöhnliches an den beiden Neustarts von FHEM zu finden, als ich DEBUG+Subscribe gesetzt hatte. Allerdings habe ich nichts außergewöhnliches (außer den Logs, die ich gepostet hatte) gefunden. Ich bin dann dadurch etwas in den Freezes versumpft. Ich habe ja schon immer Freezes (seit ich sie durch das Modul logge). Damals noch auf einem RPi 3. Mit dem Umstieg auf den RPi 4 hatte es sich leider nicht groß geändert. Die Freezes beeinträchtigten aber auch nie wirklich.

Logeinträge:
Es gibt es keine Junks mehr. Beui der Zwangstrennung kommt dann immer

Code Auswählen Erweitern


2022.03.14 03:29:45 3: UPNPController: UPNP_Controller: uniqueDeviceName 192.168.178.1_49000_1-zz-zz event ConnectionStatus not yet implemented
2022.03.14 03:29:45 3: UPNPController: UPNP_Controller: uniqueDeviceName 192.168.178.1_49000_1-zz-zz event ConnectionStatus not yet implemented
2022.03.14 03:29:45 3: UPNPController: UPNP_Controller: uniqueDeviceName 192.168.178.1_49000_1-zz-zz event ExternalIPv6Address not yet implemented
2022.03.14 03:29:48 3: UPNPController: UPNP_Controller: uniqueDeviceName 192.168.178.1_49000_1-zz-zz event ConnectionStatus not yet implemented
2022.03.14 03:29:48 3: UPNPController: UPNP_Controller: uniqueDeviceName 192.168.178.1_49000_1-zz-zz event ExternalIPAddress not yet implemented
2022.03.14 03:29:49 3: UPNPController: UPNP_Controller: uniqueDeviceName 192.168.178.1_49000_1-zz-zz event ExternalIPv6Address not yet implemented


Bzgl. der Medion Devices hatte ich vor einem Jahr verstanden, dass da nicht viel zu machen ist, da sie nicht wie erwartet antworten. Das Radio habe ich ja über SIRD eingebunden und der Fernseher lässt sich ohnehin nicht über IP einschalten, da er im Standby nicht mehr "hören" will.

Wenn du noch Ideen hast, gerne. Ich probiere gerne aus (wenn es mit überschaubarem Aufwand möglich ist), da ich immer neugierig bin 
Wahrscheinlich habe ich auch deshalb viel zu viele Devices in FHEM laufen

Viele Grüße
Dieter

[KölnSolar]

Besteht vielleicht die Möglichkeit die Module irgendwie über github verfügbar zu machen und per Update einzubinden? Das manuelle umkopieren ist irgendwie maximal aufwendig.

Nein, weil ich keinen github-account habe und ich github maximal aufwendig empfinde. Die immer weiter wachsende Zahl der individuellen githubs finde ich persönlich extrem unübersichtlich. Einen Zusammenhang zum Forum gibt es nicht.
Die nächste Version dürfte offiziell werden und dann wird per update easy verteilt.

@Dieter
Sieht ja alles gut aus.

Bzgl. der Medion Devices hatte ich vor einem Jahr verstanden, dass da nicht viel zu machen ist, da sie nicht wie erwartet antworten

Ah, so war das. Ich kann mir nicht jedes Problem bzw. jeden device typ merken. Könnte ja sein, dass durch die Weiterentwicklung das ein oder andere issue doch gelöst wurde.

Ich habe ja schon immer Freezes (seit ich sie durch das Modul logge)

Gar nicht gut.  Das alleine kann ja auch zu Problemen in anderen Modulen führen. Da ich recht viel Erfahrung mit freezemon und der Analyse dessen Logs habe, kannst Du Dich auch gerne per PN oder separatem Thread an mich wenden.

Im Augenblick scheinen wir die freezes beim UPNPController durch verschiedene Maßnahmen in den Griff zu bekommen. Bei mir gibt es die nur in 2 Fällen:
- das powerline-LAN spielt verrückt und lässt die Kommunikation nur in eine Richtung durch 
- Abschalten von subscribed devices/services durch "Stecker ziehen"--> keine bye-bye-message--> das nächste subscription renewal versucht wartend(=freeze) auf das device zuzugreifen
  --> ich denke, dass ich das gelöst bekomme, indem ich einfach VOR dem renewal einen ping auf das device auf Erfolg prüfe und bei Nichterfolg das device in den offline-state setze. In den readings der
        services dann dokumentiert mit "subscription failed, maybe offline"

Grüße Markus

[mumpitzstuff]

Code Auswählen Erweitern

2022.03.15 12:18:58 3: UPNPController: renewal of subscription for service AVTransport of device 192.168.178.102_8080 failed: , try to subscribe
2022.03.15 12:18:58 3: UPNPController: renewal of subscription for service RenderingControl of device 192.168.178.102_8080 failed: , try to subscribe
2022.03.15 12:20:08 3: UPNPController: renewal of subscription for service RenderingControl of device 192.168.178.115_8080 failed: , try to subscribe
2022.03.15 12:20:08 3: UPNPController: renewal of subscription for service AVTransport of device 192.168.178.115_8080 failed: , try to subscribe
2022.03.15 12:23:19 3: UPNPController: renewal of subscription for service RenderingControl of device 192.168.178.102_8080 failed: , try to subscribe
2022.03.15 12:23:19 3: UPNPController: renewal of subscription for service AVTransport of device 192.168.178.102_8080 failed: , try to subscribe
2022.03.15 12:24:29 3: UPNPController: renewal of subscription for service RenderingControl of device 192.168.178.115_8080 failed: , try to subscribe
2022.03.15 12:24:29 3: UPNPController: renewal of subscription for service AVTransport of device 192.168.178.115_8080 failed: , try to subscribe
2022.03.15 12:26:13 3: UPNPController: UPNPSocket-UPNP_Controller-1900, handleOnce failed, mismatched tag 'head'


Sind solche Nachrichten im Log normal? Bei den beiden Geräten handelt es sich um Boxen mit Multiroom Support (SMRS18A1).

[KölnSolar]

Jein. Die Unregelmäßigkeit der Meldungen sagt mir, dass vermutlich kurzzeitig keine (WLAN)Netzwerkverbindung bestand, das device nicht erreichbar war. Wie die Meldung schon sagt, wird die subscription dann erneut versucht neu aufzubauen, was dann vermutlich auch geklappt hat. Wenn die Meldungen fortwährend kämen, würde das den Hinweis liefern, dass das device(oder das Modul  ) nicht richtig arbeitet . Dann müsste man etwas tiefer in die Analyse einsteigen.

2022.03.15 12:26:13 3: UPNPController: UPNPSocket-UPNP_Controller-1900, handleOnce failed, mismatched tag 'head'

Einmalig ? Hier könnte die neue Debugging option zumindest den Hinweis liefern um welches device(IP) es sich handelt.

Boxen mit Multiroom Support (SMRS18A1)

Hier fahre ich ja kompletten Blindflug. Scheinbar ist das aber kein per DLNA(UPNP) unterstütztes "Multiroom", sonst dürften ja auch für diese services subscription Fehler auftauchen. Siehst Du im UPNPController die services GroupManagement/SpeakerManagement ? 

Wenn ja hätten wir neben Michaels munet endlich ein weiteres Testobjekt für DLNA-Multiroom.

Grüße Markus

[mumpitzstuff]

Es handelt sich hierbei um https://www.manualslib.de/manual/461384/Silvercrest-Smrs-18-A1.html.

Diese beiden Lautsprecher sind über mein SIRD Modul eingebunden. Die Meldungen erscheinen regelmäßig (alle 4-5 Minuten mehrere dieser Log Nachrichten) und nicht sporadisch. Der kopierte Ausschnitt war lediglich ein kleiner Teil. Dieser Lautsprecher gehen in einen Standby Modus und schalten dort glaube ich bestimmte Services ab. Ich habe mehrere dieser SIRD Devices und habe in jedem Fall festgestellt, das ich bei ihnen in einem Moment viele DInge machen kann wie z.B. play, stream, speak usw. und im nächsten Moment nur noch volume und mute angeboten werden.
Ich habe eben sogar bei laufenden Internetradio ein shutdown restart gemacht und vor dem restart wurden Dinge wie Speak angeboten. nach dem restart eine ganze Zeit nur noch volume und mute und nach ein paar Minuten dann wieder speak und alles andere. Irgendwie toggeln die Geräte zwischen voller Funktionalität und einer eingeschränkten Variante hin und her. Vorhin hatte ich auch den Fall, das eine der Boxen (beides die Gleichen) die volle Funktionalität angezeigt hat und die andere dauerhaft nur mote und volume (beide waren an und haben per Multiroom einen Internet Radiosender abgespielt).
Näher ansehen kann ich das jetzt aktuell nicht, da das Netzteil meines Rechners kaputt ist und eingeschickt werden muss. Am Tablet macht sich das alles nicht so gut. Ich melde mich noch mal, wenn alles repariert ist, stelle dann sicher, das die aktuellsten Versionen installiert sind und reiche dann ausführliche Logfiles nach. Das kann aber leider noch ein paar Tage dauern.

[KölnSolar]

Ich habe eben sogar bei laufenden Internetradio ein shutdown restart gemacht und vor dem restart wurden Dinge wie Speak angeboten. nach dem restart eine ganze Zeit nur noch volume und mute und nach ein paar Minuten dann wieder speak und alles andere.

Das ist klar. Es dauert eben, bis nach einem restart/Attributänderung/define/modify alle devices sich wieder gemeldet haben. Hab ich schon häufig hingewiesen, dass da Geduld gefragt ist.

Diese beiden Lautsprecher sind über mein SIRD Modul eingebunden.

Das erklärt es ja vermutlich. SIRD(siehe letzter Post von Rockfan). Ich glaub ich hatte sogar einen eigenen Thread für SIRD eröffnet(ich suche mal und wenn nicht, macht es Sinn einen zu eröffnen)

Die Meldungen erscheinen regelmäßig (alle 4-5 Minuten mehrere dieser Log Nachrichten) und nicht sporadisch. Der kopierte Ausschnitt war lediglich ein kleiner Teil. Dieser Lautsprecher gehen in einen Standby Modus und schalten dort glaube ich bestimmte Services ab. Ich habe mehrere dieser SIRD Devices und habe in jedem Fall festgestellt, das ich bei ihnen in einem Moment viele DInge machen kann wie z.B. play, stream, speak usw. und im nächsten Moment nur noch volume und mute angeboten werden.

Offensichtlich läuft dann das renewal der subscription immer gegen die Wand. Will heißen, obwohl vorher selber die Zeitdauer(vergleichbar lease time bei DHCP) bei der subscription vorgegeben wird, wird das renewal nicht akzeptiert. Danach erfolgt dann eine erneute subscription und der Prozess wiederholt sich.

Ich nehm aber Dein Angebot gerne an, demnächst noch einmal tiefer in die SIRD-Problematik einzusteigen. Mit Dir lässt sich dann auch leichter und schneller eine kleine Veränderung am Code vornehmen, um dem Grund dieses ominösen Verhaltens näher zu kommen. Und es wär natürlich prima, wenn Du bei Funktionsfähigkeit das SIRD-Modul auf UPNP-/DLNAController anpassen würdest. Hättest dann ja event-Funktionalität vs. polling(sofern meine Unterstellung richtig ist) und müsstest Dich im Modul um diesen ganzen Kram nicht mehr kümmern, sondern nur noch um "Sonderfunktionalitäten" außerhalb von UPNP/DLNA.

Grüße Markus   

[RockFan]

Hallo Markus,

@Dieter
Sieht ja alles gut aus. Ah, so war das. Ich kann mir nicht jedes Problem bzw. jeden device typ merken. Könnte ja sein, dass durch die Weiterentwicklung das ein oder andere issue doch gelöst wurde.

Kein Problem. Ist ja auch schon ein ganz schönes Weilchen her. Da kann ich mich nur vage erinnern
Mit dem Radio gab's Probleme, weshalb ich die IP dann ausgeschlossen hatte. Beim TV könnte ich nochmal probieren. Das blöde ist aber eigentlich, dass man den Fernseher - so wie es aussieht "By Design" - nicht einschalten kann.

Gar nicht gut.  Das alleine kann ja auch zu Problemen in anderen Modulen führen. Da ich recht viel Erfahrung mit freezemon und der Analyse dessen Logs habe, kannst Du Dich auch gerne per PN oder separatem Thread an mich wenden.

Danke, das ist ein sehr verlockendes Angebot von Dir. Ich lese von Beginn an bei freezemon mit. Aber einen Griff habe ich bei mir nie an die Freezes bekommen. Der Umstieg auf den RPi 4 hatte, wie geschrieben, auch nichts bewirkt. Da ja alles eigentlich gut läuft, dachte ich mir, dass es vielleicht an der viel zu Großen Menge an unterschiedlichsten Devices bei mir liegt und habe es nicht mehr weiter verfolgt (außer natürlich die Posts zu lesen).

Ich würde vielleicht am Besten einen neuen Thread anfangen, aber in welchem Unterforum? "FHEM - Hausautomations-Systeme » Unterstützende Dienste" vielleicht? Welche Logs helfen denn dann? Freezemon verrät mir, dass ich täglich knapp 2.000 Freezes mit über 5.000 Sekunden habe.

Viele Grüße
Dieter

[KölnSolar]

Ich würde vielleicht am Besten einen neuen Thread anfangen, aber in welchem Unterforum? "FHEM - Hausautomations-Systeme » Unterstützende Dienste" vielleicht?

egal. Anfänger, weil so unspezifisch ? Ich finde ihn schon....

Freezemon verrät mir, dass ich täglich knapp 2.000 Freezes mit über 5.000 Sekunden habe.

Hölle. Ich hab so 10. Meistens Plots.

Welche Logs helfen denn dann?

Du musst das Attribut setzen

Code Auswählen Erweitern

attr Deinfreezemondevice fm_logFile ./log/freeze-%Y%m%d.logDann bekommt man tägliche files für die Analyse. Obacht, die werden bei Dir groß. Nicht, dass die Platte platzt.
Grüße Markus