UPnP - Simple Service Discovery Protocol (SSDP) als Basismodul

[KölnSolar]

Hi Klaus,
habs jetzt wieder laufen.
UPNPController auf dem Produktivsystem
UPNPSEMP auf dem Testsystem

kein freeze, wenn ich die location-URL im Broser eines 3. Systems aufrufe.

1. Ruft man die SEMP URL "location" auf, so wird der Inhalt der xlm-Datei angezeigt, danach blockiert Fhem, auf dem das UPnP-Device läuft, 40 s oder mehr. Dann kommt die Fehlermeldung

Code: [Auswählen]

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

Kriegst Du das rekonstruiert ?
Grüße Markus

[klaus.schauer]

Welche Daten könnten bei der Analyse weiterhelfen? Soweit ich das beurteilen kann, steht der Perl-Prozess. Da sieht man natürlich nichts im Fhem-LOG.

[KölnSolar]

Ich müsste es ja nachgestellt bekommen. In der o.g. Konstellation gibt es keinen freeze bei mir. Folglich musst Du ja irgendeine andere Konstellation haben. Ich häng Dir mal meine  aktuelle Version an, damit wir auch hier "Gleichstand" haben. 

[klaus.schauer]

Erst einmal danke, dass Du dich der Sache wieder annimmst.

Ich hatte tatsächlich noch die Version 0.0.1. Der Fehler tritt aber auch bei der Version 0.0.2 auf. Folgende Meldungen erhalte ich im LOG:
-Fhem Start

Code: [Auswählen]

2022.01.05 12:09:46 3: UPNPDevice: device  UPNPSEMP registered with /opt/fhem/description.xml
2022.01.05 12:09:46 3: UPNPDevice: UPNPSEMP: socket device UPNPSocket-UPNPSEMP-1900.  Port: 1900 created.
2022.01.05 12:09:46 3: UPNPDevice: UPNPSEMP: socket device UPNPSocket-UPNPSEMP-4004.  Port: 4004 created.
2022.01.05 12:09:46 3: UPNPDevice: starting device UPNPSEMP
2022.01.05 12:09:46 1: PERL WARNING: Use of uninitialized value in concatenation (.) or string at ./FHEM/98_UPNPDevice.pm line 443, <FH> line 33.
Mit Aufruf von

Code: [Auswählen]

http://192.168.6.46:4004/opt/fhem/description.xml
wird die Datei ausgegeben und danach blockiert Fhem. Nach Ende der Blockade kommen Fehlermeldungen wie diese:

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.


Code: [Auswählen]

2022.01.05 12:39:57 1: PERL WARNING: Use of uninitialized value in concatenation (.) or string at ./FHEM/98_UPNPDevice.pm line 437.
2022.01.05 12:39:57 1: PERL WARNING: Use of uninitialized value in concatenation (.) or string at ./FHEM/98_UPNPDevice.pm line 443.
2022.01.05 12:42:02 3: UPNPDevice: handleOnce failed, Can't call method "uri" on an undefined value at FHEM/lib/UPnP/DeviceManager.pm line 782.

Die Blockaden dauern unterschiedlich lange, z. B. ca. 160 s oder 350 s. Während der Blockade von Fhem kann man weiterhin

Code: [Auswählen]

http://192.168.6.46:4004/opt/fhem/description.xml
aufrufen und erhält auch sofort eine Ausgabe. Ruft man diese Seite mehrfach während der Blockade auf, so scheint das WEB-Interface von Fhem nach drei bis fünf Aufrufen kurzeitig wieder zu reagieren. Blockiert danach aber sofort wieder.

Könnte es sein, dass der Prozess zur Ausgabe der html-Seite nicht zuverlässig schließt und später irgendein timeout zuschlägt?

[KölnSolar]

Und Du rufst das von einem Gerät ungleich 192.168.6.46 auf ?

UPNPDevice: handleOnce failed

Das sagt nur aus, dass irgendetwas auf den Ports angekommen ist und nun in der Blackbox des Perl-Pakets weiterverarbeitet wird. Dort können dann auch freezes entstehen, auf die ich keinen (direkten) Einfluss habe, weil es ja ein "fertiges" Perl-Paket ist. Bei einem freeze müssten da aber ganz andere Meldungen kommen.
Am einfachsten ist, wenn Du freezemon aktivierst. Dann sieht man wie lange(wahrscheinlich nicht wie Du beschrieben hast, sondern x*20s)einzelne freezes tatsächlich dauern und wahrscheinlich auch, ob das wirklich im Zusammenhang mit dem Browseraufruf steht und nicht vielleicht sogar generell auftritt. Freezemon hat den riesen Vorteil, dass man den verbose-level nicht extra setzen muss(wir haben ja 2 Socket-devices im Hintergrund und das UPNP-device) und man sieht im Freezemon-Log alle Log-Ausgaben eines devices zum Zeitpunkt(kurz davor und danach) des freezes.

Ob das SEMP ist ?

[klaus.schauer]

Und Du rufst das von einem Gerät ungleich 192.168.6.46 auf?

Ja, von einem Windows Client mit Egde-Browser.

Das sagt nur aus, dass irgendetwas auf den Ports angekommen ist und nun in der Blackbox des Perl-Pakets weiterverarbeitet wird. Dort können dann auch freezes entstehen, auf die ich keinen (direkten) Einfluss habe, weil es ja ein "fertiges" Perl-Paket ist. Bei einem freeze müssten da aber ganz andere Meldungen kommen.

Entscheidet ist, ob wir einen UPnP Dienst ans Laufen bringen, der insgesamt nicht blockiert. Der SMA Home Manager fragt in regelmäßigen Abständen von 60 s oder weniger an.

Welche Meldungen müssten denn bei einer Blockade z. B. kommen?

Am einfachsten ist, wenn Du freezemon aktivierst. Dann sieht man wie lange(wahrscheinlich nicht wie Du beschrieben hast, sondern x*20s)einzelne freezes tatsächlich dauern und wahrscheinlich auch, ob das wirklich im Zusammenhang mit dem Browseraufruf steht und nicht vielleicht sogar generell auftritt. Freezemon hat den riesen Vorteil, dass man den verbose-level nicht extra setzen muss(wir haben ja 2 Socket-devices im Hintergrund und das UPNP-device) und man sieht im Freezemon-Log alle Log-Ausgaben eines devices zum Zeitpunkt(kurz davor und danach) des freezes.

Ein list freezemon liefert:

Code: [Auswählen]

Internals:
   CFGFN     
   FUUID      61d72391-f33f-dda0-daa5-01a1dbc2ebf09a15
   NAME       freezemon
   NR         196
   NTFY_ORDER 99-freezemon
   STATE      s:18:17:57 e:18:19:03 f:66.594 d:tmr-CODE(0x55938f1cc0)(GetUpdate) tmr-CODE(0x5593892750)(ProcessRequestQueue) tmr-FW_closeInactiveClients(N/A) tmr-MQTT2_CLIENT_keepalive(MQTT_wald1_4) tmr-FHEM::Log2Syslog::calcTrate(syslog) tmr-TCM_msgCounter(TCM_ESP3_0)
   TYPE       freezemon
   VERSION    0.0.31
   .attraggr:
   .attrminint:
   READINGS:
     2022-01-06 18:19:03   .fm_freezes     2022-01-06: s:18:17:00 e:18:17:19 f:19.15 d:tmr-CODE(0x55938f1cc0)(GetUpdate) tmr-CODE(0x5593892750)(ProcessRequestQueue) ,2022-01-06: s:18:17:21 e:18:17:32 f:11.251 d:tmr-CODE(0x55938f1cc0)(GetUpdate) tmr-CODE(0x5593892750)(ProcessRequestQueue) ,2022-01-06: s:18:17:34 e:18:17:56 f:22.284 d:tmr-CODE(0x55938f1cc0)(GetUpdate) tmr-CODE(0x5593892750)(ProcessRequestQueue) ,2022-01-06: s:18:17:57 e:18:19:03 f:66.594 d:tmr-CODE(0x55938f1cc0)(GetUpdate) tmr-CODE(0x5593892750)(ProcessRequestQueue) tmr-FW_closeInactiveClients(N/A) tmr-MQTT2_CLIENT_keepalive(MQTT_wald1_4) tmr-FHEM::Log2Syslog::calcTrate(syslog) tmr-TCM_msgCounter(TCM_ESP3_0)
     2022-01-06 18:15:57   .lastDay        2022-01-06
     2022-01-06 18:19:03   fcDay           4
     2022-01-06 18:19:03   freezeDevice    tmr-CODE(0x55938f1cc0)(GetUpdate) tmr-CODE(0x5593892750)(ProcessRequestQueue) tmr-FW_closeInactiveClients(N/A) tmr-MQTT2_CLIENT_keepalive(MQTT_wald1_4) tmr-FHEM::Log2Syslog::calcTrate(syslog) tmr-TCM_msgCounter(TCM_ESP3_0)
     2022-01-06 18:19:03   freezeTime      66.594
     2022-01-06 18:19:03   ftDay           119.279
     2022-01-06 18:27:55   perfmon         not active
     2022-01-06 18:19:03   state           s:18:17:57 e:18:19:03 f:66.594 d:tmr-CODE(0x55938f1cc0)(GetUpdate) tmr-CODE(0x5593892750)(ProcessRequestQueue) tmr-FW_closeInactiveClients(N/A) tmr-MQTT2_CLIENT_keepalive(MQTT_wald1_4) tmr-FHEM::Log2Syslog::calcTrate(syslog) tmr-TCM_msgCounter(TCM_ESP3_0)
   helper:
     DISABLED   0
     TIMER      1641490118
     apptime   
     fn         
     freeze     66.5941679477692
     intCount   42
     msg        [Freezemon] freezemon: possible freeze starting at 18:17:57, delay is 66.594 possibly caused by: tmr-CODE(0x55938f1cc0)(GetUpdate) tmr-CODE(0x5593892750)(ProcessRequestQueue) tmr-FW_closeInactiveClients(N/A) tmr-MQTT2_CLIENT_keepalive(MQTT_wald1_4) tmr-FHEM::Log2Syslog::calcTrate(syslog) tmr-TCM_msgCounter(TCM_ESP3_0)
     now        1641489543.59417
     inAt:
       HASH(0x55946d9bf8)
       HASH(0x559485c460)
       HASH(0x55946fa540)
       HASH(0x559484c950)
       HASH(0x55948569e8)
       HASH(0x5594859fd8)
       HASH(0x55946e1360)
       HASH(0x559484e280)
       HASH(0x55946fa630)
       HASH(0x5594868e90)
       HASH(0x55949b0b90)
       HASH(0x5594859b40)
       HASH(0x5593226008)
     logfilequeue:
     logqueue:
Attributes:
 
Ich sehe auf Anhieb nicht, wie die Auflistung der Module, die als Verursacher in Frage kommen könnten, weiterhelfen könnte.

Ob das SEMP ist ?

Nein, Kostal hat wohl einen Energiezähler, der UPnP nutzt. Es fehlen aber die für SEMP notwendigen Sevicebeschreibungen:

Code: [Auswählen]

<semp:X_SEMPSERVICE xmlns:semp="urn:schemas-simple-energy-management-protocol:service-1-0">
<semp:server>http://192.168.x.y:4004</semp:server>
<semp:basePath>/opt/fhem/FHEM/lib/semp</semp:basePath>
<semp:transport>HTTP/Pull</semp:transport>
<semp:exchangeFormat>XML</semp:exchangeFormat>
<semp:wsVersion>1.1.5</semp:wsVersion>
</semp:X_SEMPSERVICE>


[KölnSolar]

scheidet ist, ob wir einen UPnP Dienst ans Laufen bringen, der insgesamt nicht blockiert

Da sind wir uns einig. 

Mit freezeemon hast Du mehrere Möglichkeiten der Überwachung/Analyse
- der aktuelle state zeigt den letzten freeze u. mögliche Verursacher
- mit verbose=3 werden die freezes im FHEMlog gelogged(lässt sich per attr freezemondevice fm_log ... verfeinern/individualisieren)
- mit get freezemondevice freezes bekommt man eine Liste der letzten 20 freezes
- Detailausgaben bekommt man durch  attr freezemondevice fm_logFile ....
  es wird ein separates file beschrieben, welches loglevel 5 zeigt
  lässt sich auch direkt über get freezemondevice log .... anzeigen

Aus Deinem list sehe ich auch nur die furchterregende freeze-Dauer. wir brauchen das freezelog.

Welche Meldungen müssten denn bei einer Blockade z. B. kommen?

Im FHEMlog z.B. UPNPDevice: handleOnce failed, $@  ($@ kommt aus perlupnp z.B. "Can't connect to IP:Port (No route to host)")

Es fehlen aber die für SEMP notwendigen Sevicebeschreibungen

Schon klar. Aber wozu sonst UPnP ohne Services ? 

[klaus.schauer]

Hier mal ein LOG-Versuch mit freezemon. Vielleicht ergeben sich daraus Anhaltspunkte für weitere Überlegungen.

[KölnSolar]

Lösch doch bitte mal das UPNPSocket-UPNPSEMP-1900. Das macht für unsere test ja erst einmal überhaupt keinen Sinn, da wir ja keinen echten Service anbieten.

Ich versuch dem

2022.01.11 08:14:02.535 4: UPNPDevice: UPNPSocket-UPNPSEMP-1900, received ssdp search or advertise event
--- log skips    94.954 secs.
2022.01.11 08:15:37.494 3: UPNPDevice: handleOnce failed, Can't call method "uri" on an undefined value at FHEM/lib/UPnP/DeviceManager.pm line 782.
2022.01.11 08:15:37.495 4: UPNPDevice: UPNPSocket-UPNPSEMP-4004, received message on HTTP handler port: 4004, Can't call method "uri" on an undefined value at FHEM/lib/UPnP/DeviceManager.pm line 782.
 

mal auf den Grund zu gehen.

Mit welchem Browser arbeitest Du ? Ggfs. mal mit MS Edge probieren, damit ich das nachstellen kann.

[klaus.schauer]

Lösch doch bitte mal das UPNPSocket-UPNPSEMP-1900. Das macht für unsere test ja erst einmal überhaupt keinen Sinn, da wir ja keinen echten Service anbieten.

Mir ist nicht klar, wie das erreicht werden kann. Diesen Serviceport habe ich - wissentlich - nicht aktiviert. Aktiviert habe ich das Modul mit

Code: [Auswählen]

define UPNPSEMP UPNPDevice
und mit den Daten aus dem bekannten description.xml File vorsorgt.

Mit welchem Browser arbeitest Du ? Ggfs. mal mit MS Edge probieren, damit ich das nachstellen kann.

MS Edge

[KölnSolar]

Diesen Serviceport habe ich - wissentlich - nicht aktiviert

Schon klar...
einfach nur

Code: [Auswählen]

delete UPNPSocket-UPNPSEMP-1900in FHEM

Solltest Du ein shutdown restart machen, dann immer danach dieses device löschen, weil es automatisch angelegt wird.

mit den Daten aus dem bekannten description.xml File vorsorgt.

Da kommt mir dann in den Sinn das mal wirklich abzugleichen. Ich starte mit

Code: [Auswählen]

define UPNPSEMP UPNPDevice
attr UPNPSEMP file /opt/fhem/SEMPdevice.xml
attr UPNPSEMP path /opt/fhem/
attr UPNPSEMP verbose 5und SEMPdevice.xml

Code: [Auswählen]

<?xml version="1.0"?>
<root xmlns="urn:schemas-upnp-org:device-1-0">
<specVersion>
<major>1</major>
<minor>0</minor>
</specVersion>
<device>
<deviceType>urn:domain-name:device:deviceType:ver</deviceType>
<friendlyName>this is just a test device</friendlyName>
<manufacturer>FHEM</manufacturer>
<modelName>FHEM UPNP SEMP device</modelName>
<UDN>uuid:fc655837-3054-4670-b1d2-4c7e8aeada08</UDN>
<serviceList>
</serviceList>
<deviceList>
</deviceList>
<semp:X_SEMPSERVICE
xmlns:semp="urn:schemas-simple-energy-management-protocol:service-1-0">
<semp:server>http://IP[:port]</semp:server>
<semp:basePath>/SEMP</semp:basePath>
<semp:transport>HTTP/Pull</semp:transport>
<semp:exchangeFormat>XML</semp:exchangeFormat>
<semp:wsVersion>x.y.z</semp:wsVersion>
</semp:X_SEMPSERVICE>
</device>
</root>Aufruf in MS Edge ergibt dann völlig freezefrei

Code: [Auswählen]

<root xmlns="urn:schemas-upnp-org:device-1-0">
<specVersion>
<major>1</major>
<minor>0</minor>
</specVersion>
<device>
<deviceType>urn:domain-name:device:deviceType:ver</deviceType>
<friendlyName>this is just a test device</friendlyName>
<manufacturer>FHEM</manufacturer>
<modelName>FHEM UPNP SEMP device</modelName>
<UDN>uuid:fc655837-3054-4670-b1d2-4c7e8aeada08</UDN>
<serviceList> </serviceList>
<deviceList> </deviceList>
<semp:X_SEMPSERVICE xmlns:semp="urn:schemas-simple-energy-management-protocol:service-1-0">
<semp:server>http://IP[:port]</semp:server>
<semp:basePath>/SEMP</semp:basePath>
<semp:transport>HTTP/Pull</semp:transport>
<semp:exchangeFormat>XML</semp:exchangeFormat>
<semp:wsVersion>x.y.z</semp:wsVersion>
</semp:X_SEMPSERVICE>
</device>
<URLBase>http://MeineFHEMIP:4004</URLBase>
</root>

[klaus.schauer]

Ich hab die Konfiguration entsprechend eingestellt.

Beim ersten Aufruf von

Code: [Auswählen]

http://192.168.6.46:4004/opt/fhem/SEMPdevice.xml
gab es auf den ersten Blick diesmal kein Problem. Ich habe dann ein paar Sekunden später nochmals einen Aufruf abgesetzt, der beantwortet wurde, aber dann blockierte. Wie schon letztlich beschrieben, scheint sich bei mehrmaligen Aufrufen - in Abständen von einigen Aufrufen - kurzzeitig die Blockade zu lösen.

[KölnSolar]

Beim ersten Aufruf von http://192.168.6.46:4004/opt/fhem/SEMPdevice.xml
gab es auf den ersten Blick diesmal kein Problem. Ich habe dann ein paar Sekunden später nochmals einen Aufruf abgesetzt, der beantwortet wurde, aber dann blockierte. Wie schon letztlich beschrieben, scheint sich bei mehrmaligen Aufrufen - in Abständen von einigen Aufrufen - kurzzeitig die Blockade zu lösen.

Das ist halt wieder subjektiv. Du kennst doch jetzt freezemon.  Ich ruf das zigmal hintereinander oder in größeren Abständen auf: kein freeze in freezemon sichtbar.

Mir gehen die Ideen aus, was in Deiner Umgebung anders als bei mir ist.

[klaus.schauer]

Vielleicht finden wir eine andere Möglichkeit, die Abläufe bei den Blockaden transparent zu machen. Freezemon scheint da wohl nicht weiterzuhelfen. Die letzte LOG-Datei umfasst den Zeitraum, indem ich die Beschreibungsdatei mehrfach abgerufen habe und das System blockiert war.

Auf meinen Systemen sind neben dem UPnP Prototyp insbesondere die Module TCM, EnOcean und PIFACE aktiv. In allen Modulen laufen an mehreren Stellen Timer über die Funktion InternalTimer; bei PIFACE z. B. im Sekundentakt. Timingprobleme oder Blockaden haben sich daraus aber bisher nie ergeben. Auch pendelt sich die CPU-Auslastung bei einem Raspberry 4B im stationären Betrieb auf 2 % bis 5 % ein, beim Raspberry der ersten Generation sind es ca. 20 % CPU-Last.

Ich frage mich allerdings, ob es da einen Zusammenhang geben kann. Nur habe ich keine Idee, wie man das verifizieren könnte. Klar erst einmal UPnP-Test ohne diese Module. Aber wie könnte es weitergehen, wenn sich die Vermutung bestätigt oder auch nicht?

[klaus.schauer]

Der Fehler tritt auch in einer Konfiguration auf, die ausschließlich UPNPDevice enthält. Fehlerursachen sind im freezelog nicht zu finden, siehe Anlage.