UPnP - Simple Service Discovery Protocol (SSDP) als Basismodul

Begonnen von klaus.schauer, 23 September 2020, 20:19:55

Vorheriges Thema - Nächstes Thema

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.

Zitat
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
RPi3/2 buster/stretch-SamsungAV_E/N-RFXTRX-IT-RSL-NC5462-Oregon-CUL433-GT-TMBBQ-01e-CUL868-FS20-EMGZ-1W(GPIO)-DS18B20-CO2-USBRS232-USBRS422-Betty_Boop-EchoDot-OBIS(Easymeter-Q3/EMH-KW8)-PCA301(S'duino)-Deebot(mqtt2)-zigbee2mqtt

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.  ;)
RPi3/2 buster/stretch-SamsungAV_E/N-RFXTRX-IT-RSL-NC5462-Oregon-CUL433-GT-TMBBQ-01e-CUL868-FS20-EMGZ-1W(GPIO)-DS18B20-CO2-USBRS232-USBRS422-Betty_Boop-EchoDot-OBIS(Easymeter-Q3/EMH-KW8)-PCA301(S'duino)-Deebot(mqtt2)-zigbee2mqtt

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

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

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:

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.



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

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 ?
ZitatUPNPDevice: 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 ?
RPi3/2 buster/stretch-SamsungAV_E/N-RFXTRX-IT-RSL-NC5462-Oregon-CUL433-GT-TMBBQ-01e-CUL868-FS20-EMGZ-1W(GPIO)-DS18B20-CO2-USBRS232-USBRS422-Betty_Boop-EchoDot-OBIS(Easymeter-Q3/EMH-KW8)-PCA301(S'duino)-Deebot(mqtt2)-zigbee2mqtt

klaus.schauer

Zitat von: KölnSolar am 05 Januar 2022, 18:27:57
Und Du rufst das von einem Gerät ungleich 192.168.6.46 auf?
Ja, von einem Windows Client mit Egde-Browser.
Zitat
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?
Zitat
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:

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.
Zitat
Ob das SEMP ist ?
Nein, Kostal hat wohl einen Energiezähler, der UPnP nutzt. Es fehlen aber die für SEMP notwendigen Sevicebeschreibungen:

<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

Zitatscheidet 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.
ZitatWelche 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)")

ZitatEs fehlen aber die für SEMP notwendigen Sevicebeschreibungen
Schon klar. Aber wozu sonst UPnP ohne Services ?  :-\
RPi3/2 buster/stretch-SamsungAV_E/N-RFXTRX-IT-RSL-NC5462-Oregon-CUL433-GT-TMBBQ-01e-CUL868-FS20-EMGZ-1W(GPIO)-DS18B20-CO2-USBRS232-USBRS422-Betty_Boop-EchoDot-OBIS(Easymeter-Q3/EMH-KW8)-PCA301(S'duino)-Deebot(mqtt2)-zigbee2mqtt

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
Zitat2022.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.
RPi3/2 buster/stretch-SamsungAV_E/N-RFXTRX-IT-RSL-NC5462-Oregon-CUL433-GT-TMBBQ-01e-CUL868-FS20-EMGZ-1W(GPIO)-DS18B20-CO2-USBRS232-USBRS422-Betty_Boop-EchoDot-OBIS(Easymeter-Q3/EMH-KW8)-PCA301(S'duino)-Deebot(mqtt2)-zigbee2mqtt

klaus.schauer

Zitat von: KölnSolar am 11 Januar 2022, 14:22:34
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

define UPNPSEMP UPNPDevice

und mit den Daten aus dem bekannten description.xml File vorsorgt.
Zitat
Mit welchem Browser arbeitest Du ? Ggfs. mal mit MS Edge probieren, damit ich das nachstellen kann.
MS Edge

KölnSolar

ZitatDiesen Serviceport habe ich - wissentlich - nicht aktiviert
Schon klar...
einfach nur delete UPNPSocket-UPNPSEMP-1900in FHEM

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

Zitatmit den Daten aus dem bekannten description.xml File vorsorgt.
Da kommt mir dann in den Sinn das mal wirklich abzugleichen. Ich starte mit

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

und SEMPdevice.xml
<?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<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>
RPi3/2 buster/stretch-SamsungAV_E/N-RFXTRX-IT-RSL-NC5462-Oregon-CUL433-GT-TMBBQ-01e-CUL868-FS20-EMGZ-1W(GPIO)-DS18B20-CO2-USBRS232-USBRS422-Betty_Boop-EchoDot-OBIS(Easymeter-Q3/EMH-KW8)-PCA301(S'duino)-Deebot(mqtt2)-zigbee2mqtt

klaus.schauer

#71
Ich hab die Konfiguration entsprechend eingestellt.

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.

KölnSolar

ZitatBeim 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.
RPi3/2 buster/stretch-SamsungAV_E/N-RFXTRX-IT-RSL-NC5462-Oregon-CUL433-GT-TMBBQ-01e-CUL868-FS20-EMGZ-1W(GPIO)-DS18B20-CO2-USBRS232-USBRS422-Betty_Boop-EchoDot-OBIS(Easymeter-Q3/EMH-KW8)-PCA301(S'duino)-Deebot(mqtt2)-zigbee2mqtt

klaus.schauer

#73
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.