UPnP - Simple Service Discovery Protocol (SSDP) als Basismodul

[KölnSolar]

Hi Klaus,
das hab ich kaum anders erwartet.
Mittlerweile bin ich mir sicher, dass der Unterschied in unseren System viel "tiefer" liegt. Nämlich in den Perl-Paketen wie HTTP, SOAP.... Die lassen sich dann weder debuggen, noch werfen sie Logausgaben aus. Ich hab mir damals eigene Print-Ausgaben eingebaut, um "näher" an die freeze-Verursacher zu kommen. Es kann auch sein, dass ich dort etwas modifiziert habe. Sehe dort aber kein Eingreifen meinerseits. In meinen Aufzeichnungen habe ich nur gefunden, dass auch ich damals irgendwelche freeze-Problem hatte, die in einem System vorhanden waren, im anderen nicht.
Ich kann jetzt nur hingehen und erst einmal mein System(Rpi/buster) komplett auf einen "frischen" Auslieferungszustand bzgl. Perl(und perlupnp) zurücksetzen.

Was mich bei Deinen freezes wundert, ist das völlig undefinierte Zeitverhalten. Die freezes, die ich bisher im Zusammenhang mit perlupnp kenne, basieren immer auf irgendwelchen HTTP-Zugriffsproblemen, die wenigstens über "timeouts" regelmäßig waren. Z.B. immer 20s. Außerdem sind entsprechende Probleme immer in perlupnp mit carp/croak "abgefangen". Durch ein eval meinerseits lässt sich dann der Absturz verhindern und die Meldung loggen.

Mir scheint, dass Dein Problem ganz woanders liegt(sowas wie ne firewall ?). Du müsstest also mal ein bißchen mehr Statistik über das freeze-Verhalten machen, damit wir überhaupt mal eine Idee entwickeln können, wo es klemmt. Vielleicht auch mal den Datentraffic aufzeichnen(Wireshark/tcpdump) und analysieren.

Welche OS-Version und Releasestand hast Du ?

Grüße Markus

Edit: Gerade ist mir noch in den Sinn gekommen, dass der UPNPController seine Server ja auch nicht anders aufbaut. Im Gegensatz zu UPNPDevice ist es aber auf einigen Systemen problemlos. Läuft der UPNPController(mit freezemon) auf Deinem Testsystem problemlos ? Werden DLNA-devices automatisch angelegt, was dann bedeuten würde, dass auch der subscription process mit seinem Server problemlos läuft ?

[klaus.schauer]

Auf den Servern läuft Raspberry Pi OS Buster in der jeweils aktuellen Version, Raspi 1B mit 32 bit oder Raspi 4B mit 64 bit. Folgende Pakete sind installiert:

Code: [Auswählen]

perl libdevice-serialport-perl libio-socket-ssl-perl libwww-perl libdatetime-format-strptime-perl
liblist-moreutils-perl libxml-simple-perl libtext-csv-perl libarchive-extract-perl libcrypt-rijndael-perl
libcrypt-random-source-perl libstring-random-perl libdata-random-perl libyaml-perl sendemail libjson-perl
sqlite3 libdbd-sqlite3-perl libtext-diff-perl libdbi-perl libcgi-pm-perl libio-socket-multicast-perl libdigest-crc-perl
unattended-upgrades wiringpi libmodule-pluggable-perl git ser2net
libwww-perl libsoap-lite-perl libxml-parser-lite-perl

Der UPNPController auf dem Raspi 1B scheint problemlos zu laufen. Die UPnP-Devices im Netz werden alle gelistet.

Es gibt zwar viele freezemon-Meldungen, siehe Anlage. Das scheint mir aber auf das laufenden PIFACE-Modul zurückzuführen zu sein. Das startet im Sekundentakt mehrere Aufrufe auf Shell-Ebene über wiringpi zur Abfrage der GPIOs. Die durchschnittliche CPU-Last des Servers liegt bei ca. 20 % bis 25 %. Das Modul freezemon scheint auch zusätzlichen einen Anteil daran zu haben. Ein Raspi 1B ist nicht der schnellste.

Blockaden im Datentransfer sehe ich nicht. Die Geräte hängen alle an internen Switchen ohne Firewallfunktionen oder Portsperren.

[KölnSolar]

Code: [Auswählen]

[Freezemon] freezemon: possible freeze starting at 01:55:01, delay is 1.235 possibly caused by: tmr-PIFACE_GetUpdate(N/A) tmr-PIFACE_Watchdog(N/A)
2022.01.14 01:55:00.565 5: UPNPController: incoming message; will be processed by perlupnp handleOnce
2022.01.14 01:55:00.573 5: UPNPController: UPNPSocket-UPNP_Controller-1900, received ssdp event: was checked by discoverCallback for removed or added devices against pending search requests
2022.01.14 01:55:01.553 5: UPNPController: incoming message; will be processed by perlupnp handleOnce
2022.01.14 01:55:01.554 5: UPNPController: UPNPSocket-UPNP_Controller-1900, received ssdp event: was checked by discoverCallback for removed or added devices against pending search requests
2022.01.14 01:55:02.236 5: [Freezemon] freezemon: ----------- Starting Freeze handling at 2022.01.14 01:55:02.235 ---------------------
[Freezemon] freezemon: possible freeze starting at 01:55:01, delay is 1.235 possibly caused by: tmr-PIFACE_GetUpdate(N/A) tmr-PIFACE_Watchdog(N/A) Ich glaube fast, dass Du richtig liegst wegen der Einschätzung zu piface. Ich weiß leider auch nicht, wie freezemon auf die Idee kommt , dass der freeze von piface sein könnte. Aber wenn man auf die Log-Zeilen guckt, sieht man immer wieder ein ähnliches Muster: es kommt ein ssdp-event rein, wird blitzschnell verarbeitet und mit der "was checked" Meldung wird das Modul beendet. Danach tritt dann der freeze auf. Im obigen Log-Extrakt gut zu erkennen, dass nach Beendigung des Moduls 1s später erst die nächste message zur Verarbeitung startet, ohne dass ein FHEM-Logging dazwischen liegt.
Nur für meine Neugierde: Weißt Du, ob diese piface-Zugriffe per BlockingCall laufen ?

Die UPnP-Devices im Netz werden alle gelistet.

Und da sind auch devices mit DLNA dabei, die per autocreate angelegt und deren services subscribed wurden ?

[KölnSolar]

Seeeehr mühsam bin ich weiter. Ich denke es ist ein LAN/WLAN Problem. Ersetze mal die UPNPDevice_setupDevice mit

Code: [Auswählen]

sub UPNPDevice_setupDevice {
  my ($hash) = @_;
  my $name = $hash->{NAME};
  my $error;
  my $file = AttrVal($name,"file","/opt/fhem/description.xml"); #SEMPdevice.xml
  my $path = AttrVal($name,"path","/opt/fhem/");
  my $port = AttrVal($name,"port","4004");
 
  if (open(my $handle,"<",$file)) {
     close $handle;
  do {
$hash->{helper}{device} = $hash->{helper}{dm}->registerDevice(DevicePort => $port,
DescriptionFile => $file,   
DescriptionURI => $file,
ResourceDirectory => $path);
if($@) {
   $hash->{helper}{device} = undef;
   $error = "registration failed with error $@";
   Log3 $hash, 2, "UPNPDevice: device $name. $error";
   readingsSingleUpdate($hash,"state",$error,1);
   return $error;
}
else { 
   Log3 $hash, 3, "UPNPDevice: device $name returned handler-socket ".$hash->{helper}{device}{_handler}->socket." listening on port ".$hash->{helper}{device}->{_handler}->socket->sockport;
   Log3 $hash, 5, "UPNPDevice: device $name details: descriptionURI: ".$hash->{helper}{device}{_handler}->{_descriptionURI}.", DeviceDescription: ".$hash->{helper}{device}{_handler}->{_description}.", ResourceDirectory: ".$hash->{helper}{device}{_handler}->{_resourceDir}.", Server: ".$hash->{helper}{device}{_handler}->{_server};
   $hash->{helper}{device}{_handler}->socket->timeout(1); #avoid freezes longer than 1s
   UPNPDevice_addSocketDeviceToMainloop($hash);
}
   } # while($error);
  }
  else {
     Log3 $hash, 2, "UPNPDevice: device  $name failed to open $file $!";
  } 

  readingsSingleUpdate($hash,"state","registered",1);

  return undef;
}was den freeze auf 1s begrenzen sollte.

Der

Code: [Auswählen]

2022.01.05 12:22:37 3: UPNPDevice: handleOnce failed, Can't call method "uri" on an undefined value at FHEM/lib/UPnP/DeviceManager.pm line 782.
steht im Zusammenhang. Ist im FHEM/lib/UPnP/DeviceManager.pm nicht sauber programmiert, aber nicht so wichtig(Halten wir mal im Hinterkopf ggfs. das perlupnp zu modifizieren.)
Grüße Markus
PS: Das Ganze hatte aber wenigstens den positiven Lerneffekt, dass ich auf eine andere Modifikation in perlupnp verzichten kann und denselben Effekt im FHEM-Modul erreiche.

[klaus.schauer]

Danke für die weitere Fehleranalyse.

Ich denke es ist ein LAN/WLAN Problem.

Grundsätzlich oder u. U. bei meiner Netz- / oder Serverkonfiguration?

Nach dem Tausch des Routine UPNPDevice_setupDevice startet Fhem ständig neu. Die dort aufgerufene Routine UPNPDevice_addSocketDeviceToMainloop kann in UPNPDevice nicht gefunden werden. Ist diese identisch zur bisherigen Routine UPNPDevice_addSocketsToMainloop?

[KölnSolar]

Grundsätzlich oder u. U. bei meiner Netz- / oder Serverkonfiguration?

Ich denke grundsätzlich. Alles sehr ominös(für mich). Die freezedauer ist performance-abhängig, weshalb bei Deinem Rpi1 sehr lange freezes auftreten.

Die dort aufgerufene Routine UPNPDevice_addSocketDeviceToMainloop kann in UPNPDevice nicht gefunden werden

Sorry. Bei mir ist viel mehr geändert. Lass diese Zeile einfach weg.
Ich brauch noch etwas bis zur nächsten Version.

[klaus.schauer]

Bei den ersten Tests kann ich keine Blockaden mehr feststellen. freezemon liefert auch keine Meldungen mehr. Es kommen aber weiterhin Meldungen wie:

Code: [Auswählen]

2022.01.23 12:31:25 3: UPNPDevice: handleOnce failed, Can't call method "uri" on an undefined value at FHEM/lib/UPnP/DeviceManager.pm line 782.

Auch kann man das Attribut "file" nicht per Kommando ändern. Die WEB-Seite reagiert danach für einige Sekunden nicht mehr. Die Änderungen werden nicht übernommen. freezemon liefert aber keine Meldung. Falls man statt dessen das fhem.cfg manuell editiert, werden die Änderungen nach einem Restart übernommen. Wenn ich mich recht erinnere, ist das aber ein bereits bekannter Fehler.

[KölnSolar]

Bei den ersten Tests kann ich keine Blockaden mehr feststellen

sehr schön

2022.01.23 12:31:25 3: UPNPDevice: handleOnce failed, Can't call method "uri" on an undefined value at FHEM/lib/UPnP/DeviceManager.pm line 782.

Schrieb ich ja.Kannst Du ignorieren.

Auch kann man das Attribut "file" nicht per Kommando ändern

Gemach. daran arbeite ich aktuell.
Mach Du mal Deine SEMP-Konfiguration, dass wir feststellen, was das Modul noch können muss.

[KölnSolar]

Neue Version im Entwicklungsthread veröffentlicht. Fehlerbehebungen, keine neuen Funktionalitäten.

Grüße Markus

[klaus.schauer]

Danke für die Überarbeitungen. Bei der Ausgabe des XML-Datei treten jetzt manchmal Blockaden auf. In diesen Fällen wird eine Abfrage wie

Code: [Auswählen]

http://192.168.6.46:4004/opt/fhem/description.xml
erst nach Ende der Blockade beantwortet. Vorher meldet der Browser, die Seite sei nicht erreichbar. Im Fhem log kommt die Meldung:

Code: [Auswählen]

2022.02.06 09:27:39 3: UPNPDevice: UPNPSocket-UPNPSEMP-4004, message from 192.168.6.138:51260: handleOnce failed, Can't call method "uri" on an undefined value at FHEM/lib/UPnP/DeviceManager.pm line 782.

2022.02.06 09:27:42 1: PERL WARNING: Use of uninitialized value $client_port in concatenation (.) or string at ./FHEM/98_UPNPDevice.pm line 188.
2022.02.06 09:27:42 3: UPNPDevice: UPNPSocket-UPNPSEMP-4004, message from :: handleOnce failed, accept: timeout
2022.02.06 09:27:42 1: [Freezemon] freezemon: possible freeze starting at 09:27:41, delay is 1.407 possibly caused by: tmr-CODE(0x55b7ded338)(GetUpdate) tmr-CODE(0x55b7d8be28)(ProcessRequestQueue)
freezemon liefert:

Code: [Auswählen]

2022-02-06_09:27:42 freezemon s:09:27:41 e:09:27:42 f:1.407 d:tmr-CODE(0x55b7ded338)(GetUpdate) tmr-CODE(0x55b7d8be28)(ProcessRequestQueue)
2022-02-06_09:27:42 freezemon freezeTime: 1.407
2022-02-06_09:27:42 freezemon fcDay: 1
2022-02-06_09:27:42 freezemon ftDay: 1.407
2022-02-06_09:27:42 freezemon freezeDevice: tmr-CODE(0x55b7ded338)(GetUpdate) tmr-CODE(0x55b7d8be28)(ProcessRequestQueue)
Die Blockaden dauern - soweit ich das sehen kann - unter zwei Sekunden.

Bei den Anfragen, die unmittelbar ohne Blockaden beantwortet werden, werden keine log-Meldungen ausgegeben. Bisher war ja auch in diesen Fällen Meldungen wie

Code: [Auswählen]

... Can't call method "uri" on an undefined value ...
zu sehen.

[KölnSolar]

Hi Klaus,
ja, das ist die Modifikation, die ich vor ein paar Posts beschrieben hatte. Ausschließen lässt sich der freeze nicht. Nur reduzieren.

Mach Du mal Deine SEMP-Konfiguration, dass wir feststellen, was das Modul noch können muss.

Und dann kann man sich die Mühe machen das Ganze non-blocking zu realisieren(womit es immer noch eine unschöne Response time gäbe aber FHEM nicht mehr behindert wird).

[klaus.schauer]

Gut dann als nächsten Schritt ein Vorschlag zur Umstellung auf ein zweistufige Modulkommunikation.

• Verlagerung der Steuerung im UPNPDevice-Modul (set Kommandos) und Attribute file, path in die nachgelagerten Module z. B. SEMP
• Kommandos an UPNPDevice über IOWrite >> Returns über Dispatch an z. B. SEMP (Parameter im JSON-Format):
     -  set registerDevice
        - wird aus X_Define gesendet
        - IOWrite-Parameter: 'registerDevice', <DevicePort>, <descriptionURI>, <LeaseTime>, <Description>, <DescriptionFile>, <ResourceDirectory>
        - Return per Dispatch: 'registerDevice', <object-Kennzeichen>|<error>
     - set start
        - wird aus X_Define oder set-Kommando nach erfolgreichem registerDevice gesendet
        - IOWrite-Parameter: 'start', <object-Kennzeichen>
        - Return per Dispatch: 'start', <object-Kennzeichen>|<error>
     - set stop
        - wird aus X_Undef oder set-Kommando nach erfolgreichem start gesendet
        - IOWrite-Parameter: 'stop', <object-Kennzeichen>
        - Return per Dispatch: 'stop', <object-Kennzeichen>|<error>
     - set advertise
        - wird aus set-Kommando nach erfolgreichem start gesendet
        - IOWrite-Parameter: 'advertise', <object-Kennzeichen>
        - Return per Dispatch:  'advertise', <object-Kennzeichen>|<error>
  
• sonstige Statusmeldungen von UPNPDevice über Dispatch an SEMP und Co.
  - ?
  

Auch könnte man ggf. den Modul-Start von UPNPDevice noch automatisieren, indem man in den nachgelagerten Modulen prüft, ob das passende IODev (UPNPDevice) definiert ist.

Falls das grundsätzlich so machbar wäre, müssten wir festlegen, wie wir die notwendigen Anpassungen in UPNPDevice organisieren. Um das SEMP-Modul kümmere ich mich natürlich.

[KölnSolar]

Hallo Klaus,
kann man ja alles so machen. Bevor ich weiteren Aufwand investiere, möchte ich aber erst einmal Deine konkrete Anwendung/Konzept zu SEMP sehen.

Mach Du mal Deine SEMP-Konfiguration, dass wir feststellen, was das Modul noch können muss.

Ich entwickle daran ja nicht, weil ich Spaß an Perl habe, sondern weil ich notwendige/hilfreiche Funktionalität für FHEM bereitstellen möchte. Das erfüllt die jetzige Version ja jetzt bereits. Wenn Automatismen fehlen, lässt sich das zumindest halbmanuell durchspielen.
Den Umgang mit dem 2-stufigen Modulkonzept kriege ich problemlos hin, da ich das über UPNP-/DLNAController ganz gut gelernt habe. 
Grüße Markus

[justme1968]

nicht um hier etwas weg zu nehmen, sondern weil ich denke upnp/ssdp und mdns/dns-sd zusammen gehören: ich habe hier gerade eine erste version einer mdns/dns-sd implementierung für fhem gepostet: https://forum.fhem.de/index.php/topic,126262.0.html .

auch wenn ich gerade nicht besonders schnell mit dem thema und dem netdiscover modul bin gibt es einige berührungspunkte und es wäre schön wenn zumindest die dinge wie das automatische sammeln der daten im hintergrund und diese dann für andere module bereitstellen nicht komplett auseinander laufen.

ps: ihr scheint zumindest zum teil vorhandene perl upnp libs zu verwenden, mein ziel ist bisher vor allem so weit es geht ohne externe module auszukommen. ich hoffe auch das beisst sich nicht.

[klaus.schauer]

Nun kann ich die Funktionalität des Moduls UPNPDevice zusammen mit dem SEMP testen. Der Prototyp des SEMP Web-Service Dienstes in Fhem ist fertig, sodass alle Funktion für den Test der Kommunikation mit dem Home Manager vorhanden sind. Leider reagiert der Home Manager nicht auf die NOTIFY-Telegramme des UPNPDevice Modules. Folgendes ist mir aufgefallen:

1. Die UPnP Device Beschreibung (description.xml) wird von diesem nicht auf Fhem abgerufen. Die ssdp-Telegramme sehen auf den ersten Blick gut aus. Ungewöhnlich sind die Steuerzeichen an den Zeilenenden - \n statt \r\n -. Vielleicht hat der Home Manager damit ein Problem. Die mitgeschnittenen Telegramme sind in der angehängten Textdatei zu finden.

2. Die NOTIFY  ssdp:byebye-Telegramme werden beim FHEM shutdown nicht gesendet. Mit dem Kommando "stop" klappt es.

3. Der Home Manager sendet regelmäßig M-Search Requests. Das Modul UPNPDevice antwortet darauf aber nicht. Ein Beispiel für ein passendes M-Search Response ist ebenfalls in der Textdatei enthalten.

4. Im SEMP Kontext wird erwartet, dass die NOTIFY ssdp:alive Telegramme z. B. bei CACHE-CONTROL: max-age = 1800 in Abständen von ca. 900 s gesendet werden. Das Modul UPNPDevice sendet derzeit alle 1800 s. Ob das eine SEMP-Besonderheit ist oder so im ssdp-Standard vorgesehen ist, kann ich augenblicklich nicht beurteilen.

Um beim SEMP-Modul wirklich weiterzukommen, benötige ich erst einmal eine funktionsfähige Kommunikation mit dem Home Manager. Aus den Unterlagen ist für mich nicht eindeutig zu erkennen, wie das SEMP-Gateway in Fhem zur Steuerung mehrerer Devices gestaltet werden muss. Das sollte sich aber klären, sobald die Kommunikation mit einer Testkonfiguration klappt.

In der Datei description.xml gab es noch einen Fehler. Deshalb sende ich diese nochmals.