search

psi-4ward / AskSinAnalyzerXS

Analyzer for radio telegrams in a HomeMatic environment
Other
48 stars 7 forks source link

Server-Betrieb: nach einiger Zeit werden keine Telegramme mehr erkannt #7

Closed demel42 closed 4 years ago

demel42 commented 4 years ago

Problem: der als service eingetragene analyzer-Prozess läuft und erkennt Telegramme, nach etwas 2-3h werden keine Telegramme mehr erkannt, was sich darin äussert, das es in der Web-GUI nichts zu sehen ist aber auch die CSV-Datei nicht mehr wächst.

Wenn man dann im Web-Konfigurationsdialog auf "Speichern" drückt, läuft der Prozess wieder an, es werden wieder Telegramme erkannt.

Umgebung:

USB-Stick wird erkannt

admin@ips-prod:/opt/analyzer$ dmesg
[42248.242088] usb 1-3: new full-speed USB device number 6 using xhci_hcd
[42248.400775] usb 1-3: New USB device found, idVendor=0403, idProduct=6001
[42248.400782] usb 1-3: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[42248.400786] usb 1-3: Product: FT232R USB UART
[42248.400789] usb 1-3: Manufacturer: FTDI
[42248.400792] usb 1-3: SerialNumber: A911B8S3
[42248.404602] ftdi_sio 1-3:1.0: FTDI USB Serial Device converter detected

admin@ips-prod:/opt/analyzer$ lsusb -t
/:  Bus 02.Port 1: Dev 1, Class=root_hub, Driver=xhci_hcd/6p, 5000M
/:  Bus 01.Port 1: Dev 1, Class=root_hub, Driver=xhci_hcd/12p, 480M
    |__ Port 3: Dev 6, If 0, Class=Vendor Specific Class, Driver=ftdi_sio, 12M
    |__ Port 6: Dev 3, If 0, Class=Vendor Specific Class, Driver=rtsx_usb, 480M
    |__ Port 7: Dev 4, If 0, Class=Mass Storage, Driver=usb-storage, 480M

Nach meiner Verständnis ist der USB-Port immer aktiv (auch überprüft mit PowerTool)

admin@ips-prod:/opt/analyzer$ cat /sys/bus/usb/devices/1-3/power/level
on

Logfile bei typischem Verhalten 

admin@ips-prod:/opt/analyzer$ sudo journalctl -u analyzer
Mär 20 21:43:15 ips-prod asksin-analyzer-xs[15486]: Connected to /dev/ttyUSB0
Mär 20 21:43:15 ips-prod asksin-analyzer-xs[15486]: Opening /opt/analyzer/TelegramsXS_2020-03-20.csv for persistent storage.
Mär 20 21:43:16 ips-prod asksin-analyzer-xs[15486]: I: AskSin++ V4.1.2 (Mar 19 2020 06:50:15)
Mär 20 21:43:16 ips-prod asksin-analyzer-xs[15486]: I: CC init1
Mär 20 21:43:16 ips-prod asksin-analyzer-xs[15486]: I: CC Version: 14
Mär 20 21:43:16 ips-prod asksin-analyzer-xs[15486]: I:  - ready
Mär 21 00:45:51 ips-prod asksin-analyzer-xs[15486]: Opening /opt/analyzer/TelegramsXS_2020-03-21.csv for persistent storage.
Mär 21 07:56:34 ips-prod asksin-analyzer-xs[15486]: Detected SerialPort: /dev/ttyUSB0 (FTDI)
Mär 21 07:56:34 ips-prod asksin-analyzer-xs[15486]: Detected SerialPort: /dev/ttyS1 (unknown manufacturer)
Mär 21 07:56:34 ips-prod asksin-analyzer-xs[15486]: Detected SerialPort: /dev/ttyS10 (unknown manufacturer)
Mär 21 07:56:34 ips-prod asksin-analyzer-xs[15486]: Detected SerialPort: /dev/ttyS11 (unknown manufacturer)
Mär 21 07:56:34 ips-prod asksin-analyzer-xs[15486]: Detected SerialPort: /dev/ttyS12 (unknown manufacturer)
Mär 21 07:56:34 ips-prod asksin-analyzer-xs[15486]: Detected SerialPort: /dev/ttyS13 (unknown manufacturer)
Mär 21 07:56:34 ips-prod asksin-analyzer-xs[15486]: Detected SerialPort: /dev/ttyS14 (unknown manufacturer)
Mär 21 07:56:34 ips-prod asksin-analyzer-xs[15486]: Detected SerialPort: /dev/ttyS15 (unknown manufacturer)
Mär 21 07:56:34 ips-prod asksin-analyzer-xs[15486]: Detected SerialPort: /dev/ttyS16 (unknown manufacturer)
Mär 21 07:56:34 ips-prod asksin-analyzer-xs[15486]: Detected SerialPort: /dev/ttyS17 (unknown manufacturer)
Mär 21 07:56:34 ips-prod asksin-analyzer-xs[15486]: Detected SerialPort: /dev/ttyS18 (unknown manufacturer)
Mär 21 07:56:34 ips-prod asksin-analyzer-xs[15486]: Detected SerialPort: /dev/ttyS19 (unknown manufacturer)
Mär 21 07:56:34 ips-prod asksin-analyzer-xs[15486]: Detected SerialPort: /dev/ttyS2 (unknown manufacturer)
Mär 21 07:56:34 ips-prod asksin-analyzer-xs[15486]: Detected SerialPort: /dev/ttyS20 (unknown manufacturer)
Mär 21 07:56:34 ips-prod asksin-analyzer-xs[15486]: Detected SerialPort: /dev/ttyS21 (unknown manufacturer)
Mär 21 07:56:34 ips-prod asksin-analyzer-xs[15486]: Detected SerialPort: /dev/ttyS22 (unknown manufacturer)
Mär 21 07:56:34 ips-prod asksin-analyzer-xs[15486]: Detected SerialPort: /dev/ttyS23 (unknown manufacturer)
Mär 21 07:56:34 ips-prod asksin-analyzer-xs[15486]: Detected SerialPort: /dev/ttyS24 (unknown manufacturer)
Mär 21 07:56:34 ips-prod asksin-analyzer-xs[15486]: Detected SerialPort: /dev/ttyS25 (unknown manufacturer)
Mär 21 07:56:34 ips-prod asksin-analyzer-xs[15486]: Detected SerialPort: /dev/ttyS26 (unknown manufacturer)
Mär 21 07:56:34 ips-prod asksin-analyzer-xs[15486]: Detected SerialPort: /dev/ttyS27 (unknown manufacturer)
Mär 21 07:56:34 ips-prod asksin-analyzer-xs[15486]: Detected SerialPort: /dev/ttyS28 (unknown manufacturer)
Mär 21 07:56:34 ips-prod asksin-analyzer-xs[15486]: Detected SerialPort: /dev/ttyS29 (unknown manufacturer)
Mär 21 07:56:34 ips-prod asksin-analyzer-xs[15486]: Detected SerialPort: /dev/ttyS3 (unknown manufacturer)
Mär 21 07:56:34 ips-prod asksin-analyzer-xs[15486]: Detected SerialPort: /dev/ttyS30 (unknown manufacturer)
Mär 21 07:56:34 ips-prod asksin-analyzer-xs[15486]: Detected SerialPort: /dev/ttyS31 (unknown manufacturer)
Mär 21 07:56:34 ips-prod asksin-analyzer-xs[15486]: Detected SerialPort: /dev/ttyS4 (unknown manufacturer)
Mär 21 07:56:34 ips-prod asksin-analyzer-xs[15486]: Detected SerialPort: /dev/ttyS5 (unknown manufacturer)
Mär 21 07:56:34 ips-prod asksin-analyzer-xs[15486]: Detected SerialPort: /dev/ttyS6 (unknown manufacturer)
Mär 21 07:56:34 ips-prod asksin-analyzer-xs[15486]: Detected SerialPort: /dev/ttyS7 (unknown manufacturer)
Mär 21 07:56:34 ips-prod asksin-analyzer-xs[15486]: Detected SerialPort: /dev/ttyS8 (unknown manufacturer)
Mär 21 07:56:34 ips-prod asksin-analyzer-xs[15486]: Detected SerialPort: /dev/ttyS9 (unknown manufacturer)
Mär 21 07:56:34 ips-prod asksin-analyzer-xs[15486]: Detected SerialPort: /dev/ttyS0 (unknown manufacturer)
Mär 21 07:56:46 ips-prod asksin-analyzer-xs[15486]: Fetched Device List from homematic-ccu.damsky.home
Mär 21 07:56:46 ips-prod asksin-analyzer-xs[15486]: Connected to /dev/ttyUSB0
Mär 21 07:56:46 ips-prod asksin-analyzer-xs[15486]: Opening /opt/analyzer/TelegramsXS_2020-03-21.csv for persistent storage.
Mär 21 07:56:48 ips-prod asksin-analyzer-xs[15486]: I: AskSin++ V4.1.2 (Mar 19 2020 06:50:15)
Mär 21 07:56:48 ips-prod asksin-analyzer-xs[15486]: I: CC init1
Mär 21 07:56:48 ips-prod asksin-analyzer-xs[15486]: I: CC Version: 14
Mär 21 07:56:48 ips-prod asksin-analyzer-xs[15486]: I:  - ready

Auszug aus CSV-Datei

1584749630447;2020-03-21 01:13:50.447;-78;13;154;BCAST,BIDI,RPTEN,WKMEUP;INFO;4630533;6026570;Vorplatz.Bewegungsmelder;CCU.HM;NEQ0320541;BidCoS-RF;false;false;06014100
1584749630719;2020-03-21 01:13:50.719;-78;25;154;BIDI,RPTEN;RESPONSE_AES;4630533;6026570;Vorplatz.Bewegungsmelder;CCU.HM;NEQ0320541;BidCoS-RF;false;false;BE6E18582B651CE50300B53CDE231A17
1584749632799;2020-03-21 01:13:52.799;-88;37;16;HMIP_UNKNOWN;HMIP_TYPE;2649974;12507592;Terrasse.Lichtsensor;CCU.HmIP;000D58A9915BBE;HmIP-RF;true;true;00064B734F67F2F279D08720BF38D926B5DAA2D42F1AC1B94CD5FFDF
1584773812076;2020-03-21 07:56:52.076;-68;37;16;HMIP_UNKNOWN;HMIP_TYPE;2361524;12507592;Jaana-BZ.Thermostat;CCU.HmIP;000C9A4999F299;HmIP-RF;true;true;00004BDE9192678ACBBF098D6AC7BE160E36459130B10127E37823A8
1584773813564;2020-03-21 07:56:53.564;-68;30;16;HMIP_UNKNOWN;HMIP_TYPE;2361524;12507592;Jaana-BZ.Thermostat;CCU.HmIP;000C9A4999F299;HmIP-RF;true;true;00004BDFD8D90746CC4479F85B6DF156D84DECD821
1584773820780;2020-03-21 07:57:00.780;-73;39;16;HMIP_UNKNOWN;HMIP_TYPE;9694532;12507592;Gewächshaus.Heizung;CCU.HmIP;000895699E5C07;HmIP-RF;true;true;0B2D0398E5782F50116C9C14159DA6010DC02120ECCC2FDE9BA48566D8E3
1584773844295;2020-03-21 07:57:24.295;-73;33;80;HMIP_UNKNOWN;HMIP_TYPE;11224315;12507592;Tomatenhaus.Raumklima;CCU.HmIP;000ED709B28322;HmIP-RF;true;true;00078C680D2203D1D98A2D7D87057E2A1BAEEA0CB6D49E3F

Ich hatte um 21:43 den Prozess das letzte mal durch "Speichern" getigert, Telegramme wurden bis 01:13 erkannt und dann wieder nach dem nächsten "Reset" um 7:56. Das eine sol lange Zeit keine Telegramme kommen ist nicht nur unwahrscheinlich, ich habe auch morgens einige zeitgesteuerte Schaltbefehle.

Gruß demel

psi-4ward commented 4 years ago

Hi, zuerst solltest du die aktuelle Dev-Version (Tag 0.0.0) installieren, hier hab ich das Error-Logging ausgebaut.

Dann prüfe bitte ob du cat /sys/bus/usb/devices/1-3/power/autosuspend hast, ggf existiert das auch für den Hub selbst. Siehe https://www.kernel.org/doc/html/v4.16/driver-api/usb/power-management.html und https://thinkwiki.de/Linux_Stromsparen#USB_Autosuspend

Ansonsten hab ich gerade leider keine Idee warum das bei dir auftritt

demel42 commented 4 years ago

Hallo,

ich finde das mit dem USB-Powermanagment etwas verwirrend, so richtig bin ich da gestern nicht durchgestiegen

admin@ips-prod:/opt/analyzer$ cat /sys/bus/usb/devices/1-3/power/autosuspend
2

aber wenn ich das jetzt richtig verstehe sorgt ein Wert von 0 für einen Dauerbetrieb, gemacht getan.

root@ips-prod:~# echo 0 > /sys/bus/usb/devices/1-3/power/autosuspend

Die Dev-Version ist auch installiert, ich beobachte ...

danke

psi-4ward commented 4 years ago

Travis ist gerade leider down und baut nicht. Du solltest mindestes die Ausgabe von "Memory" im Info-Tab sehen.

demel42 commented 4 years ago

im Web-GUI unter "(i)" sehe ich Memory-RSS und Memory-Heap, in /var/log/syslog sehe ich bisher nur den normalen output vom Start (so wie in journalctl

demel42 commented 4 years ago

Situation ist zur Zeit so: grundsätzlich werden immer noch Telegramme empfangen (also schon länger als bisher), aber es gab eine Pause con 32m, in der keine Telegramme verzeichnet wurden. Das scheint mir unmöglich richtug zu sein, auch ohne das etwas los ist, habe ich ca. 10 Telegramme/min.

wo wäre im Fehlerfall denn etwas zu sehen? in /var/log/syslog bzw journalclt ist nur zweimal zu sehen, das er die USB-Ports scannt.

demel42 commented 4 years ago

der Status ist wie folgt

Ich werden den Stick jetzt an einem Raspberry testen (#8) ...

psi-4ward commented 4 years ago

Du kannst ja mal minicom laufen lassen und sehen ob hier Lücken entstehen. weiß nur nich wie man das dann sinnig erkennen kann

psi-4ward commented 4 years ago

Entgegen meiner Annahme hab ich gesehen, dass beim "connect" des Devices (was ja bei jedem SPEICHERN UND VERBINDEN ausgelöst wird) der DTR Pin getriggert wird, also wird dein NanoCul hier resettet.

Dies widerspricht aber wiederum deinem anderen Ticket, hier scheint ja die RSSI-Noise weiter zu laufen.

demel42 commented 4 years ago

ja, das ist ziemlich merkwürdig, aber das bedeutet, das der Stick ja grundsätzlich funktioniert und da der Noise ja weiter ausgewiesen wird, muss doch vermutlich das Funkmodul noch funktionieren.

ich besorge ich mir mal einen weiteren nanoCUL um zu sehen, ob sich der anders verhält.

psi-4ward commented 4 years ago

Oder Pro mini mit cc1101 und ftdi oder Konsorten.

demel42 commented 4 years ago

es war ganz offensichtlich der Stick. Der Lieferant (der sich sehr engagiert hat und sich auch den AskSinSniffer-Code reingearbeitet hat), vermutet, das sich die Frequenz im Betrieb verstellt hat. Er hat ein solches Phänomen wohl schon mal bei einem 433MHz-Modul beobachtet.

Der neue Stick ist jetzt seit 24h ohne Aussetzer aktiv.

Daher ist der Issue aus meiner Sicht erledigt.

danke