Homematic via LAN-GW: lesen geht noch, schreiben führt zu "Ignoring too small packet"

[rbott]

Seit einiger Zeit habe ich mit meinem homegear Setup das Problem, dass homegear zwar noch von den Geräten lesen kann (Status-Updates der Devices kommen über das LAN-Gateay rein), aber ich kann keine Einstellungen mehr ändern. Hier mal der Versuch, bei einem Thermostat die Temperatur zu setzen:

05/27/19 20:06:51.042 RPC Server (Port 2001): Info: Client number 11 is calling RPC method: setValue (1) Parameters:
(Integer) 2
(Integer) 4
(String) SET_TEMPERATURE
(String) 22
(Boolean) 1
05/27/19 20:06:51.043 Module HomeMatic BidCoS: Debug: SET_TEMPERATURE of peer 2 with serial number LEQ0780016:4 was set to 2C.
05/27/19 20:06:51.044 Module HomeMatic BidCoS: LAN-Konfigurationsadapter “My-HM-CFG-LAN”: Info: Sending (My-HM-CFG-LAN): 0AF9B01100AFFE2DD41280
05/27/19 20:06:51.044 Module HomeMatic BidCoS: LAN-Konfigurationsadapter “My-HM-CFG-LAN”: Debug: Sending (encrypted): SFA793EA4,00,00000000,01,FFFFFFFFA5C71591,F9B01100AFFE2DD41280
05/27/19 20:06:51.693 Module HomeMatic BidCoS: LAN-Konfigurationsadapter “My-HM-CFG-LAN”: Debug: Packet received from HM-CFG-LAN (encrypted): RFA793EA4,0008,00000000,FF,7FFF,59
05/27/19 20:06:51.693 Module HomeMatic BidCoS: LAN-Konfigurationsadapter “My-HM-CFG-LAN”: Info: Ignoring too small packet: 59
05/27/19 20:06:53.076 RPC Server (Port 2001): Debug: Joining read thread of client 0
05/27/19 20:06:53.077 RPC Server (Port 2001): Debug: Client 0 removed.
05/27/19 20:06:53.077 RPC Server (Port 2001): Debug: Joining read thread of client 1
05/27/19 20:06:53.077 RPC Server (Port 2001): Debug: Client 1 removed.
05/27/19 20:06:53.599 RPC Server (Port 2001): Response:
(Struct length=2)
{
[faultCode] (Integer) -100
[faultString] (String) No answer from device.
}
05/27/19 20:06:53.600 RPC Server (Port 2001): Response packet: HTTP/1.1 200 OK
Connection: Keep-Alive
Content-Type: text/xml
Content-Length: 248

<?xml version="1.0"?><member faultCode-100<member faultStringNo answer from device.</value

05/27/19 20:06:53.624 RPC Server (Port 2001): Debug: Connection to client number 11 closed (3).
05/27/19 20:06:53.630 Info: Script with id 1 finished with exit code 0
05/27/19 20:06:54.051 Module HomeMatic BidCoS: Debug: Deleting queue 0 for BidCoS peer with address 0x2DD412
05/27/19 20:06:54.051 Module HomeMatic BidCoS: Info: Setting peer to unreachable, because the queue processing was interrupted.
05/27/19 20:06:54.051 Module HomeMatic BidCoS: Info: Queue is not finished (peer: 2). Retrying…
05/27/19 20:06:54.151 Module HomeMatic BidCoS: LAN-Konfigurationsadapter “My-HM-CFG-LAN”: Info: Sending (My-HM-CFG-LAN): 0AF9B01100AFFE2DD41280
05/27/19 20:06:54.152 Module HomeMatic BidCoS: LAN-Konfigurationsadapter “My-HM-CFG-LAN”: Debug: Sending (encrypted): SFA794AC7,00,00000000,01,FFFFFFFFA5C721B4,F9B01100AFFE2DD41280
05/27/19 20:06:54.794 Module HomeMatic BidCoS: LAN-Konfigurationsadapter “My-HM-CFG-LAN”: Debug: Packet received from HM-CFG-LAN (encrypted): RFA794AC7,0008,00000000,FF,7FFF,1B
05/27/19 20:06:54.795 Module HomeMatic BidCoS: LAN-Konfigurationsadapter “My-HM-CFG-LAN”: Info: Ignoring too small packet: 1B
05/27/19 20:06:57.159 Module HomeMatic BidCoS: Debug: Deleting queue 1 for BidCoS peer with address 0x2DD412
05/27/19 20:06:57.159 Module HomeMatic BidCoS: Info: Setting peer to unreachable, because the queue processing was interrupted.
05/27/19 20:06:57.177 Module HomeMatic BidCoS: Info: Queue is not finished (peer: 2). Retrying…
05/27/19 20:06:57.260 Module HomeMatic BidCoS: LAN-Konfigurationsadapter “My-HM-CFG-LAN”: Info: Sending (My-HM-CFG-LAN): 0AF9B01100AFFE2DD41280
05/27/19 20:06:57.260 Module HomeMatic BidCoS: LAN-Konfigurationsadapter “My-HM-CFG-LAN”: Debug: Sending (encrypted): SFA7956EC,00,00000000,01,FFFFFFFFA5C72DD9,F9B01100AFFE2DD41280
05/27/19 20:06:57.903 Module HomeMatic BidCoS: LAN-Konfigurationsadapter “My-HM-CFG-LAN”: Debug: Packet received from HM-CFG-LAN (encrypted): RFA7956EC,0008,00000000,FF,7FFF,DD
05/27/19 20:06:57.903 Module HomeMatic BidCoS: LAN-Konfigurationsadapter “My-HM-CFG-LAN”: Info: Ignoring too small packet: DD

Hat jemand eine Idee, was das Problem sein könnte? Ich habe homegear auf einem raspbian (9.9) in Version 0.7.39-2773 installiert. Ich glaube, das Problem kam mit einem Update von homegear vor einiger Zeit, aber ganz sicher kann ich das nicht sagen. Bis dahin hat das Setup sehr stabil für über zwei Jahre funktioniert (inklusive Updates). Wenn man sich in der homegear CLI die homegear Geräte anschaut, steht dort für alle bei “Config Pending” und “Unreachable” jeweils “No”.

Ich habe bisher noch kein Gerät entfernt/zurückgesetzt und komplett neu gepaired. Ich hoffe, dass das unterm Strich nicht die Lösung sein wird, die Arbeit würde ich mir gerne sparen

Grüße, Rudi

[rbott]

Achso und noch als kleiner Nachtrag: man sieht die Meldungen erst ab “Info”-Level aufwärts. Bin ich der einzige, der das auch als “Warning” einstufen würde? Falls nicht, würde ich da mal einen Feature Request bzw. ein Issue zu aufmachen. Normalerweise läuft homegear bei mir mit Log Level 3 (Warning), um nicht unnötig auf der SD Karte herumzuschreiben.

[rbott]

Hat niemand eine Idee? Dann muss ich wohl alles mal zurücksetzen und neu anlernen
Ich berichte dann hier, was dabei herausgekommen ist.

[rbott]

Es klingt grundsätzlich nach diesem Problem:
https://forum.homegear.eu/t/homegearopenhab-24-%E2%80%9Cno-answer-from-device-sending-setvalue%E2%80%9D/2723/28

@sathya könnte es das gleiche Thema sein? Du verweist da auf eine “max.conf” - die Datei gibt es bei mir allerdings nirgends unterhalb von /etc/homegear. Kannst du die Lösung bzw. Ursache ggf. noch ein wenig weiter ausführen?

[pmayer]

Sorry, dass dir bis jetzt keiner helfen konnte. Ich leider auch nicht.

Die max.conf ist Teil von homegear-max für die Max!-Geräte - hat also mit Homematic nichts zu tun.
Schlussendlich muss sich das aber @sathya mal angucken…

[rbott]

Hier nochmal ein Nachtrag. Hab Pairing aktiviert und versucht, eine Remote (HM-RC-8) anzulernen. Hat auch nicht funktioniert mit folgendem Ergebnis:

06/03/19 19:29:10.007 IPC Server: Info: Client number 0 is calling RPC method: cliFamilyCommand
(Integer64) 0
(String) pon
06/03/19 19:29:10.008 IPC Server: Debug: CLI client 0 is executing family command: pon
06/03/19 19:29:10.009 IPC Server: Response:
(String) Pairing mode enabled for 60 seconds.

06/03/19 19:29:14.005 Module HomeMatic BidCoS: LAN-Konfigurationsadapter “My-HM-CFG-LAN”: Debug: Packet received from HM-CFG-LAN (encrypted): E283C90,0000,C9B2A0EB,FF,FFC4,938670283C9000000000E144
06/03/19 19:29:14.005 Debug (My-HM-CFG-LAN): Packet 0C938670283C9000000000E144 enters raisePacketReceived.
06/03/19 19:29:14.006 Debug (My-HM-CFG-LAN): Packet 0C938670283C9000000000E144 is now passed to the EventHandler.
06/03/19 19:29:14.005 HomeMatic BidCoS packet received (My-HM-CFG-LAN, RSSI: -60 dBm): 0C938670283C9000000000E144
06/03/19 19:29:14.006 Devlog (My-HM-CFG-LAN): Getting peer for packet 0C938670283C9000000000E144.
06/03/19 19:29:14.006 Devlog (My-HM-CFG-LAN): Packet 0C938670283C9000000000E144 is now passed to checkForBestInterface.
06/03/19 19:29:14.006 Devlog (My-HM-CFG-LAN): checkForBestInterface finished.
06/03/19 19:29:14.006 Devlog (My-HM-CFG-LAN): Packet 0C938670283C9000000000E144 is now passed to _receivedPackets.set.
06/03/19 19:29:14.006 Devlog (My-HM-CFG-LAN): _receivedPackets.set finished.
06/03/19 19:29:14.006 Devlog (My-HM-CFG-LAN): Packet 0C938670283C9000000000E144 is now passed to the peer.
06/03/19 19:29:14.008 Module HomeMatic BidCoS: Info: HUMIDITY on channel 1 of HomeMatic BidCoS peer 7 with serial number LEQ0122852 was set to 0x44.
06/03/19 19:29:14.008 Module HomeMatic BidCoS: Info: TEMPERATURE on channel 1 of HomeMatic BidCoS peer 7 with serial number LEQ0122852 was set to 0x00E1.
06/03/19 19:29:14.009 Debug (My-HM-CFG-LAN): Packet processing of packet 0C938670283C9000000000E144 took 3 ms.
06/03/19 19:29:17.596 Module HomeMatic BidCoS: LAN-Konfigurationsadapter “My-HM-CFG-LAN”: Debug: Packet received from HM-CFG-LAN (encrypted): E6C115D,0000,C9B2AEEC,FF,FFD4,0684006C115D0000001100DA5045513139313837373440080000
06/03/19 19:29:17.596 Debug (My-HM-CFG-LAN): Packet 1A0684006C115D0000001100DA5045513139313837373440080000 enters raisePacketReceived.
06/03/19 19:29:17.596 Debug (My-HM-CFG-LAN): Packet 1A0684006C115D0000001100DA5045513139313837373440080000 is now passed to the EventHandler.
06/03/19 19:29:17.596 HomeMatic BidCoS packet received (My-HM-CFG-LAN, RSSI: -44 dBm): 1A0684006C115D0000001100DA5045513139313837373440080000
06/03/19 19:29:17.596 Devlog (My-HM-CFG-LAN): Getting peer for packet 1A0684006C115D0000001100DA5045513139313837373440080000.
06/03/19 19:29:17.597 Devlog (My-HM-CFG-LAN): Packet 1A0684006C115D0000001100DA5045513139313837373440080000 is now passed to _receivedPackets.set.
06/03/19 19:29:17.597 Module HomeMatic BidCoS: LAN-Konfigurationsadapter “My-HM-CFG-LAN”: Debug: Sending (encrypted): -6C115D
06/03/19 19:29:17.598 Module HomeMatic BidCoS: LAN-Konfigurationsadapter “My-HM-CFG-LAN”: Debug: Sending (encrypted): +6C115D,00,00,
06/03/19 19:29:17.598 Module HomeMatic BidCoS: Debug: Setting physical device’s wake up flag.
06/03/19 19:29:17.598 Module HomeMatic BidCoS: LAN-Konfigurationsadapter “My-HM-CFG-LAN”: Debug: Sending (encrypted): -6C115D
06/03/19 19:29:17.598 Module HomeMatic BidCoS: LAN-Konfigurationsadapter “My-HM-CFG-LAN”: Debug: Sending (encrypted): +6C115D,02,00,
06/03/19 19:29:17.599 Module HomeMatic BidCoS: Info: Pushing pending queues.
06/03/19 19:29:17.599 Devlog (My-HM-CFG-LAN): _receivedPackets.set finished.
06/03/19 19:29:17.599 Debug (My-HM-CFG-LAN): Packet processing of packet 1A0684006C115D0000001100DA5045513139313837373440080000 took 3 ms.
06/03/19 19:29:17.655 Module HomeMatic BidCoS: LAN-Konfigurationsadapter “My-HM-CFG-LAN”: Info: Sending (My-HM-CFG-LAN): 1025A00100AFFE6C115D00050000000000
06/03/19 19:29:17.655 Module HomeMatic BidCoS: LAN-Konfigurationsadapter “My-HM-CFG-LAN”: Debug: Sending (encrypted): S1E636057,00,00000000,01,FFFFFFFFC9B2AF3C,25A00100AFFE6C115D00050000000000
06/03/19 19:29:17.718 Module HomeMatic BidCoS: LAN-Konfigurationsadapter “My-HM-CFG-LAN”: Debug: Packet received from HM-CFG-LAN (encrypted): R1E636057,0002,00000000,FF,7FFF,F3
06/03/19 19:29:17.718 Module HomeMatic BidCoS: LAN-Konfigurationsadapter “My-HM-CFG-LAN”: Info: Ignoring too small packet: F3
06/03/19 19:29:20.602 Module HomeMatic BidCoS: Debug: Deleting queue 6 for BidCoS peer with address 0x6C115D
06/03/19 19:29:22.723 Module HomeMatic BidCoS: LAN-Konfigurationsadapter “My-HM-CFG-LAN”: Debug: Sending (encrypted): K
06/03/19 19:29:22.752 Module HomeMatic BidCoS: LAN-Konfigurationsadapter “My-HM-CFG-LAN”: Debug: Packet received from HM-CFG-LAN (encrypted): HHM-LAN-IF,03C4,LEQ0384800,29A090,00AFFE,C9B2C322,000C,02

Vielleicht trägt das noch irgendwie zur Auflösung bei

[sathya]

Hallo @rbott,

da stimmt irgendetwas nicht. Jedenfalls sind die empfangenen Antworten nicht die üblichen (z. B. R1E636057,0002,00000000,FF,7FFF,F3). Normalerweise sollte der letzte Teil (mit dem F3) mindestens 18 Zeichen lang sein. Hast du neben HomeMatic BidCoS noch andere 868-MHz-Geräte im Einsatz (außer MAX!)?

Viele Grüße

Sathya

[rbott]

Hallo @sathya,

Danke für Deine Antwort. Ich habe allerdings keine sonstigen Gerätefamilien an meiner homegear Instanz in Betrieb (und auch sonst nichts in meiner Wohnung). Ich bin mir relativ sicher, dass das Verhalten mit einem homegear Update vor einiger Zeit (ich kann leider kein genaues Datum mehr angeben) angefangen hat. Neue Geräte lassen sich derzeit auch nicht mehr anmelden. Ich könnte allerdings mal die komplette Datenbank wegschieben und mit einem “Clean State” anfangen und neue Geräte versuchen anzulernen. Aber nach dem was Du schreibst habe ich nicht das Gefühl, dass das etwas ändern würde

Grüße, Rudi

[sathya]

Hallo @rbott,

ich habe jetzt endlich testeshalber wieder einen HM-CFG-LAN in Betrieb genommen. Hier klappt alles einwandfrei. Von daher bin ich jetzt etwas ratlos, was das Problem bei dir sein könnte. Ich kann dir anbieten, mir den HM-CFG-LAN zuzusenden, dann kann ich mir das Ganze einmal im “Labor” ansehen.

Viele Grüße

Sathya

[Kukamee]

Habe gestern auch mal das Update (version 0.7.40-2948) ausgeführt.
Hab nun das gleiche Problem das ich keine Aktoren mehr steuern kann.

Anbei mal die Log Datei:

08/12/19 21:27:36.120 RPC Server (Port 2001): Info: Client number 483 is calling RPC method: setValue (2) Parameters:

(String) LEQ1317833:1

(String) LEVEL

(Float) 0.44

08/12/19 21:27:36.121 Module HomeMatic BidCoS: LAN-Konfigurationsadapter “My-HM-CFG-LAN”: Info: Sending (My-HM-CFG-LAN): 0E99A0112CD62133E50A02015800A0

08/12/19 21:27:36.726 Module HomeMatic BidCoS: LAN-Konfigurationsadapter “My-HM-CFG-LAN”: Info: Ignoring too small packet: 02

08/12/19 21:27:38.695 RPC Server (Port 2001): Info: Connection from ::ffff:192.168.2.68:57114 accepted. Client number: 534

08/12/19 21:27:38.695 RPC Server (Port 2001): Info: RPC server client id for client number 534 is: 18

08/12/19 21:27:38.697 RPC Server (Port 2001): Info: Client number 534 is calling RPC method: setValue (2) Parameters:

(String) LEQ1317833:1

(String) LEVEL

(Float) 0.44

08/12/19 21:27:41.280 RPC Server (Port 2001): Info: Client number 534 is calling RPC method: ping (2) Parameters:

(String) 7278994b

08/12/19 21:27:41.284 RPC Server (Port 2001): Info: Client number 534 is calling RPC method: listBidcosInterfaces (2) Parameters:

08/12/19 21:27:41.755 Module HomeMatic BidCoS: Info: Setting peer to unreachable, because the queue processing was interrupted.

08/12/19 21:27:41.755 Module HomeMatic BidCoS: Info: Queue is not finished (peer: 3). Retrying…

08/12/19 21:27:41.856 Module HomeMatic BidCoS: LAN-Konfigurationsadapter “My-HM-CFG-LAN”: Info: Sending (My-HM-CFG-LAN): 0E9AA0112CD62133E50A02015800A0

08/12/19 21:27:41.876 Module HomeMatic BidCoS: LAN-Konfigurationsadapter “My-HM-CFG-LAN”: Info: Ignoring too small packet: 68

08/12/19 21:27:44.874 Module HomeMatic BidCoS: Info: Setting peer to unreachable, because the queue processing was interrupted.

08/12/19 21:27:44.875 Module HomeMatic BidCoS: Info: Queue is not finished (peer: 3). Retrying…

08/12/19 21:27:44.975 Module HomeMatic BidCoS: LAN-Konfigurationsadapter “My-HM-CFG-LAN”: Info: Sending (My-HM-CFG-LAN): 0E9AA0112CD62133E50A02015800A0

08/12/19 21:27:44.996 Module HomeMatic BidCoS: LAN-Konfigurationsadapter “My-HM-CFG-LAN”: Info: Ignoring too small packet: 2B

08/12/19 21:27:47.992 Module HomeMatic BidCoS: Info: Setting peer to unreachable, because the queue processing was interrupted.

08/12/19 21:27:47.992 Module HomeMatic BidCoS: Info: Queue is not finished (peer: 3). Retrying…

08/12/19 21:27:48.093 Module HomeMatic BidCoS: LAN-Konfigurationsadapter “My-HM-CFG-LAN”: Info: Sending (My-HM-CFG-LAN): 0E9AA0112CD62133E50A02015800A0

08/12/19 21:27:48.114 Module HomeMatic BidCoS: LAN-Konfigurationsadapter “My-HM-CFG-LAN”: Info: Ignoring too small packet: EE

08/12/19 21:27:51.109 Module HomeMatic BidCoS: Info: Setting peer to unreachable, because the queue processing was interrupted.

08/12/19 21:27:51.110 Info: Peer 3 is unreachable.

08/12/19 21:27:51.861 Info: Peer 3 is reachable again.

irgendwie ist seit dem Update das (ich nenne es mal) Sendepaket zu klein.

[sathya]

Hallo @Kukamee,

da kommen die Antwortbytes nur sehr sporadisch rein. Wie ist deine Systemauslastung (top)? Wird USB durch irgendetwas belegt? Auf den ersten Blick sieht es so aus, dass entweder das System oder die Interrupthandler stark ausgelastet sind. An der Kommunikation mit dem HM-CFG-LAN hat sich seit langem im Quelltext nichts mehr verändert. Es gab zwischen den letzten Stable-Versionen also keine Unterschiede an dieser Stelle.

Was läuft bei dir neben Homegear noch auf dem System? Welches System nutzt du?

Ich habe es auch gerade noch einmal getestet: Bei mir funktioniert der HM-CFG-LAN in der aktuellen Version.

Viele Grüße

Sathya

[Kukamee]

Hi @sathya,

danke für die schnelle Antwort!
USBs sind alle Frei.
Die Kommunikation mit den Homematic Komponenten läuft mit Homegear über einen HM-CFG-LAN.
Sonst läuft auf dem System (Intel Nuc) noch ein Mosquitto-MQTT server, Openhab2 und Node-RED.
Denke das hier noch Reserven vorhanden sind…

Anbei die Systemauslastung:

top - 22:04:11 up 13 min, 1 user, load average: 0,18, 0,56, 0,81
Tasks: 118 total, 1 running, 75 sleeping, 0 stopped, 0 zombie
%Cpu(s): 5,9 us, 0,7 sy, 0,2 ni, 93,0 id, 0,0 wa, 0,0 hi, 0,3 si, 0,0 st
KiB Mem : 3958448 total, 2518640 free, 928004 used, 511804 buff/cache
KiB Swap: 3957756 total, 3957756 free, 0 used. 2795772 avail Mem

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
862 openhab 20 0 3074144 653948 20476 S 11,9 16,5 3:28.26 java
1048 homegear 20 0 1973428 71536 24416 S 1,0 1,8 0:10.58 homegear
351 nucmast+ 20 0 42804 4072 3452 R 0,7 0,1 0:01.34 top
874 root 20 0 110412 1932 1716 S 0,3 0,0 0:00.18 irqbalance
880 nucmast+ 25 5 936924 85432 28424 S 0,3 2,2 0:08.34 node-red
31151 nucmast+ 20 0 108172 5616 4512 S 0,3 0,1 0:00.21 sshd
1 root 20 0 77876 9028 6712 S 0,0 0,2 0:03.14 systemd
2 root 20 0 0 0 0 S 0,0 0,0 0:00.01 kthreadd
4 root 0 -20 0 0 0 I 0,0 0,0 0:00.00 kworker/0:0H
5 root 20 0 0 0 0 I 0,0 0,0 0:00.09 kworker/u4:0
6 root 0 -20 0 0 0 I 0,0 0,0 0:00.00 mm_percpu_wq
7 root 20 0 0 0 0 S 0,0 0,0 0:00.16 ksoftirqd/0
8 root 20 0 0 0 0 I 0,0 0,0 0:01.09 rcu_sched
9 root 20 0 0 0 0 I 0,0 0,0 0:00.00 rcu_bh
10 root rt 0 0 0 0 S 0,0 0,0 0:00.00 migration/0
11 root rt 0 0 0 0 S 0,0 0,0 0:00.00 watchdog/0

[sathya]

Hi @Kukamee,

gut, der NUC als System sollte mehr als schnell genug sein. Könntest du einmal debugLevel = 6 in der main.conf einschalten? Dann sollten Zeilen mit Debug: Packet received from HM-CFG-LAN. Raw data: im Log auftauchen und wir sehen, was roh über den Socket eingeht und vor allem wann.

Viele Grüße

Sathya

[Kukamee]

Hey @sathya, danke nochmal.

Hab mal den Wert 83% an einen Dimmaktor gesendet (16:57:23)
Hoffe mal das passt so:

08/14/19 16:57:19.272 RPC client: Response was:

(Array length=1)

[

(String) event

]

08/14/19 16:57:19.274 RPC Server (Port 2001): Debug: Packet received: 42696E000000001C000000146C697374426964636F73496E746572666163657300000000

08/14/19 16:57:19.274 RPC Server (Port 2001): Info: Client number 16713 is calling RPC method: listBidcosInterfaces (2) Parameters:

08/14/19 16:57:19.275 RPC Server (Port 2001): Response:

(Array length=1)

[

(Struct length=4)

{

[ADDRESS] (String) VBC9911585

[CONNECTED] (Boolean) 1

[DEFAULT] (Boolean) 1

[DESCRIPTION] (String) Homegear default BidCoS interface

}

]

08/14/19 16:57:19.275 RPC Server (Port 2001): Response binary:

42696E0100000087000001000000000100000101000000040000000741444452455353000000030000000A5642433939313135383500000009434F4E4E454354454400000002010000000744454641554C5400000002010000000B4445534352495054494F4E0000000300000021486F6D65676561722064656661756C7420426964436F5320696E74657266616365

08/14/19 16:57:21.134 Module HomeMatic BidCoS: LAN-Konfigurationsadapter “My-HM-CFG-LAN”: Debug: Sending: K

08/14/19 16:57:21.137 Module HomeMatic BidCoS: LAN-Konfigurationsadapter “My-HM-CFG-LAN”: Debug: Packet received from HM-CFG-LAN. Raw data:

48484D2D4C414E2D49462C303343342C4C4551303634313638362C3243443632312C3243443632312C39303846384543432C303032332C30330D0A

08/14/19 16:57:21.137 Module HomeMatic BidCoS: LAN-Konfigurationsadapter “My-HM-CFG-LAN”: Debug: Packet received from HM-CFG-LAN: HHM-LAN-IF,03C4,LEQ0641686,2CD621,2CD621,908F8ECC,0023,03

08/14/19 16:57:23.175 RPC Server (Port 2001): Debug: Packet received: 42696E000000003D0000000873657456616C756500000003000000030000000C4C4551303539303730363A3100000003000000054C4556454C00000004351EB85200000000

08/14/19 16:57:23.175 RPC Server (Port 2001): Info: Client number 16713 is calling RPC method: setValue (2) Parameters:

(String) LEQ0590706:1

(String) LEVEL

(Float) 0.83

08/14/19 16:57:23.175 Module HomeMatic BidCoS: Debug: LEVEL of peer 11 with serial number LEQ0590706:1 was set to A6.

08/14/19 16:57:23.176 Module HomeMatic BidCoS: LAN-Konfigurationsadapter “My-HM-CFG-LAN”: Info: Sending (My-HM-CFG-LAN): 0ED7A0112CD6212B67200201A600A0

08/14/19 16:57:23.176 Module HomeMatic BidCoS: LAN-Konfigurationsadapter “My-HM-CFG-LAN”: Debug: Sending: S90A22CE8,00,00000000,01,FFFFFFFF908F96C3,D7A0112CD6212B67200201A600A0

08/14/19 16:57:23.196 Module HomeMatic BidCoS: LAN-Konfigurationsadapter “My-HM-CFG-LAN”: Debug: Packet received from HM-CFG-LAN. Raw data:

5239304132324345382C303030322C30303030303030302C46462C374646462C36430D0A

08/14/19 16:57:23.196 Module HomeMatic BidCoS: LAN-Konfigurationsadapter “My-HM-CFG-LAN”: Debug: Packet received from HM-CFG-LAN: R90A22CE8,0002,00000000,FF,7FFF,6C

08/14/19 16:57:23.196 Module HomeMatic BidCoS: LAN-Konfigurationsadapter “My-HM-CFG-LAN”: Info: Ignoring too small packet: 6C

08/14/19 16:57:25.747 RPC Server (Port 2001): Response:

(Struct length=2)

{

[faultCode] (Integer) -100

[faultString] (String) No answer from device.

}

08/14/19 16:57:25.747 RPC Server (Port 2001): Response binary:

42696EFF0000004A0000010100000002000000096661756C74436F646500000001FFFFFF9C0000000B6661756C74537472696E6700000003000000164E6F20616E737765722066726F6D206465766963652E

08/14/19 16:57:25.754 RPC Server (Port 2001): Debug: Connection to client number 16713 closed (3).

08/14/19 16:57:25.756 RPC Server (Port 2001): Info: Connection from ::ffff:192.168.2.68:47620 accepted. Client number: 16738

08/14/19 16:57:25.756 RPC Server (Port 2001): Info: RPC server client id for client number 16738 is: 100

08/14/19 16:57:25.757 RPC Server (Port 2001): Listening for incoming packets from client number 16738.

08/14/19 16:57:25.758 RPC Server (Port 2001): Debug: Packet received: 42696E000000003D0000000873657456616C756500000003000000030000000C4C4551303539303730363A3100000003000000054C4556454C00000004351EB85200000000

08/14/19 16:57:25.758 RPC Server (Port 2001): Info: Client number 16738 is calling RPC method: setValue (2) Parameters:

(String) LEQ0590706:1

(String) LEVEL

(Float) 0.83

08/14/19 16:57:25.758 Module HomeMatic BidCoS: Debug: LEVEL of peer 11 with serial number LEQ0590706:1 was set to A6.

08/14/19 16:57:28.328 RPC Server (Port 2001): Response:

(Struct length=2)

{

[faultCode] (Integer) -100

[faultString] (String) No answer from device.

}

08/14/19 16:57:28.328 RPC Server (Port 2001): Response binary:

42696EFF0000004A0000010100000002000000096661756C74436F646500000001FFFFFF9C0000000B6661756C74537472696E6700000003000000164E6F20616E737765722066726F6D206465766963652E

08/14/19 16:57:28.809 Module HomeMatic BidCoS: Debug: Deleting queue 60 for BidCoS peer with address 0x2B6720

08/14/19 16:57:28.809 Module HomeMatic BidCoS: Info: Setting peer to unreachable, because the queue processing was interrupted.

08/14/19 16:57:28.809 Module HomeMatic BidCoS: Info: Queue is not finished (peer: 11). Retrying…

08/14/19 16:57:28.910 Module HomeMatic BidCoS: LAN-Konfigurationsadapter “My-HM-CFG-LAN”: Info: Sending (My-HM-CFG-LAN): 0ED8A0112CD6212B67200201A600A0

08/14/19 16:57:28.910 Module HomeMatic BidCoS: LAN-Konfigurationsadapter “My-HM-CFG-LAN”: Debug: Sending: S90A2434D,00,00000000,01,FFFFFFFF908FAD28,D8A0112CD6212B67200201A600A0

08/14/19 16:57:28.930 Module HomeMatic BidCoS: LAN-Konfigurationsadapter “My-HM-CFG-LAN”: Debug: Packet received from HM-CFG-LAN. Raw data:

5239304132343334442C303030322C30303030303030302C46462C374646462C44320D0A

08/14/19 16:57:28.930 Module HomeMatic BidCoS: LAN-Konfigurationsadapter “My-HM-CFG-LAN”: Debug: Packet received from HM-CFG-LAN: R90A2434D,0002,00000000,FF,7FFF,D2

08/14/19 16:57:28.930 Module HomeMatic BidCoS: LAN-Konfigurationsadapter “My-HM-CFG-LAN”: Info: Ignoring too small packet: D2

08/14/19 16:57:31.927 Module HomeMatic BidCoS: Debug: Deleting queue 61 for BidCoS peer with address 0x2B6720

08/14/19 16:57:31.927 Module HomeMatic BidCoS: Info: Setting peer to unreachable, because the queue processing was interrupted.

08/14/19 16:57:31.928 Module HomeMatic BidCoS: Info: Queue is not finished (peer: 11). Retrying…

08/14/19 16:57:32.028 Module HomeMatic BidCoS: LAN-Konfigurationsadapter “My-HM-CFG-LAN”: Info: Sending (My-HM-CFG-LAN): 0ED8A0112CD6212B67200201A600A0

08/14/19 16:57:32.028 Module HomeMatic BidCoS: LAN-Konfigurationsadapter “My-HM-CFG-LAN”: Debug: Sending: S90A24F7C,00,00000000,01,FFFFFFFF908FB957,D8A0112CD6212B67200201A600A0

08/14/19 16:57:32.049 Module HomeMatic BidCoS: LAN-Konfigurationsadapter “My-HM-CFG-LAN”: Debug: Packet received from HM-CFG-LAN. Raw data:

5239304132344637432C303030322C30303030303030302C46462C374646462C39350D0A

08/14/19 16:57:32.049 Module HomeMatic BidCoS: LAN-Konfigurationsadapter “My-HM-CFG-LAN”: Debug: Packet received from HM-CFG-LAN: R90A24F7C,0002,00000000,FF,7FFF,95

08/14/19 16:57:32.049 Module HomeMatic BidCoS: LAN-Konfigurationsadapter “My-HM-CFG-LAN”: Info: Ignoring too small packet: 95

08/14/19 16:57:34.282 RPC Server (Port 2001): Debug: Packet received: 42696E000000001C0000000470696E670000000100000003000000083732373839393462

08/14/19 16:57:34.282 RPC Server (Port 2001): Info: Client number 16738 is calling RPC method: ping (2) Parameters:

(String) 7278994b

08/14/19 16:57:34.282 RPC Server (Port 2001): Response:

(Boolean) 1

08/14/19 16:57:34.283 RPC Server (Port 2001): Response binary:

42696E01000000050000000201

08/14/19 16:57:34.283 RPC client: Debug: Calling RPC method “system.multicall” on server 192.168.2.68.

08/14/19 16:57:34.283 RPC client: Parameters:

(Array length=1)

[

(Struct length=2)

{

[methodName] (String) event

[params] (Array length=4)

[

(String) RF-7278994b

(String) CENTRAL

(String) PONG

(String) 7278994b

]

}

]

08/14/19 16:57:34.283 Debug: Calling getFileDescriptor…

08/14/19 16:57:34.283 Debug: Connecting to host 192.168.2.68 on port 9126…

08/14/19 16:57:34.284 Debug: Connected to host 192.168.2.68 on port 9126. Client number is: 16739

08/14/19 16:57:34.284 RPC client: Debug: Sending packet: 42696E00000000930000001073797374656D2E6D756C746963616C6C00000001000001000000000100000101000000020000000A6D6574686F644E616D6500000003000000056576656E7400000006706172616D730000010000000004000000030000000B52462D3732373839393462000000030000000743454E5452414C0000000300000004504F4E4700000003000000083732373839393462

08/14/19 16:57:34.285 RPC client: Debug: Packet received: 42696E0100000015000001000000000100000003000000056576656E74

08/14/19 16:57:34.286 RPC client: Debug: Received packet from server 192.168.2.68: 42696E0100000015000001000000000100000003000000056576656E74

08/14/19 16:57:34.286 RPC client: Response was:

(Array length=1)

[

(String) event

]

08/14/19 16:57:34.286 RPC Server (Port 2001): Debug: Packet received: 42696E000000001C000000146C697374426964636F73496E746572666163657300000000

08/14/19 16:57:34.286 RPC Server (Port 2001): Info: Client number 16738 is calling RPC method: listBidcosInterfaces (2) Parameters:

08/14/19 16:57:34.286 RPC Server (Port 2001): Response:

(Array length=1)

[

(Struct length=4)

{

[ADDRESS] (String) VBC9911585

[CONNECTED] (Boolean) 1

[DEFAULT] (Boolean) 1

[DESCRIPTION] (String) Homegear default BidCoS interface

}

]

08/14/19 16:57:34.287 RPC Server (Port 2001): Response binary:

42696E0100000087000001000000000100000101000000040000000741444452455353000000030000000A5642433939313135383500000009434F4E4E454354454400000002010000000744454641554C5400000002010000000B4445534352495054494F4E0000000300000021486F6D65676561722064656661756C7420426964436F5320696E74657266616365

08/14/19 16:57:35.045 Module HomeMatic BidCoS: Debug: Deleting queue 62 for BidCoS peer with address 0x2B6720

08/14/19 16:57:35.045 Module HomeMatic BidCoS: Info: Setting peer to unreachable, because the queue processing was interrupted.

08/14/19 16:57:35.045 Module HomeMatic BidCoS: Info: Queue is not finished (peer: 11). Retrying…

08/14/19 16:57:35.146 Module HomeMatic BidCoS: LAN-Konfigurationsadapter “My-HM-CFG-LAN”: Info: Sending (My-HM-CFG-LAN): 0ED8A0112CD6212B67200201A600A0

08/14/19 16:57:35.146 Module HomeMatic BidCoS: LAN-Konfigurationsadapter “My-HM-CFG-LAN”: Debug: Sending: S90A25BAA,00,00000000,01,FFFFFFFF908FC585,D8A0112CD6212B67200201A600A0

08/14/19 16:57:35.166 Module HomeMatic BidCoS: LAN-Konfigurationsadapter “My-HM-CFG-LAN”: Debug: Packet received from HM-CFG-LAN. Raw data:

5239304132354241412C303030322C30303030303030302C46462C374646462C35380D0A

08/14/19 16:57:35.166 Module HomeMatic BidCoS: LAN-Konfigurationsadapter “My-HM-CFG-LAN”: Debug: Packet received from HM-CFG-LAN: R90A25BAA,0002,00000000,FF,7FFF,58

08/14/19 16:57:35.166 Module HomeMatic BidCoS: LAN-Konfigurationsadapter “My-HM-CFG-LAN”: Info: Ignoring too small packet: 58

[sathya]

Hallo @Kukamee,

Fehler gefunden: Z. B. FFFFFFFF908FC585 darf nicht im Paket stehen. Das Problem ist nur auf 64-Bit-Systemen symptomatisch, daher ist es wohl noch nicht aufgefallen. Es tritt auch nur auf, wenn der 32-Bit-Anteil des aktuellen Unixzeitstempels in Millisekunden größer als 0x7FFFFFFF ist, da die Zahl dann in eine negative konvertiert wurde. Ab dem 5. September hätte es wieder für 4 Milliarden Millisekunden (ungefähr 50 Tage) funktioniert (1567663063040).

Der Fehler sollte im nächsten Nightly gefixt sein.

Viele Grüße

Sathya

[Kukamee]

Hey @sathya,

du bist die beste!
Vielen Dank!

Melde mich wenn es funktioniert hat.

[Kukamee]

@sathya
so, konnte nun endlich mal auf das nightly updaten.
Es funktioniert wieder alles.

Vielen Dank nochmal!

[rbott]

Hey @sathya,

wann kommt das denn im stable Release an?

Grüße, Rudi

[rbott]

Ich habe jetzt ein neues Problem. Ich kann wieder sendend mit den Homematic Geräten kommunizieren (da der Fehler ja datumsbezogen war, sollte es aktuell funktionieren), allerdings komme ich trotzdem nicht weiter. Wenn ich ein SET_TEMPERATURE auslöse per RPC Call ist vermeintlich alles in Ordnung, das Thermostat wechselt aber dann in den State “OFF” am Display. Ich habe hier vier Stück und alle verhalten sich identisch. Hier mal ein Beispiel:

10/02/19 09:30:06.286 RPC Server (Port 2001): Info: Client number 9 is calling RPC method: setValue (1) Parameters:
(Integer) 3
(Integer) 4
(String) SET_TEMPERATURE
(String) 19
(Boolean) 1
10/02/19 09:30:06.286 Module HomeMatic BidCoS: Debug: SET_TEMPERATURE of peer 3 with serial number LEQ0782364:4 was set to 09.
10/02/19 09:30:06.287 Module HomeMatic BidCoS: LAN-Konfigurationsadapter "My-HM-CFG-LAN": Info: Sending (My-HM-CFG-LAN): 0CFCB01100AFFE2E1E41860409
10/02/19 09:30:06.287 Module HomeMatic BidCoS: LAN-Konfigurationsadapter "My-HM-CFG-LAN": Debug: Sending (encrypted): S8B60494F,00,00000000,01,502AA173,FCB01100AFFE2E1E41860409
10/02/19 09:30:06.397 Module HomeMatic BidCoS: Debug: Deleting queue 0 for BidCoS peer with address 0x2DD412
10/02/19 09:30:06.850 Module HomeMatic BidCoS: LAN-Konfigurationsadapter "My-HM-CFG-LAN": Debug: Packet received from HM-CFG-LAN (encrypted): R8B60494F,0001,502AA39C,FF,FFCF,FC80022E1E4100AFFE010409202E40
10/02/19 09:30:06.850 HomeMatic BidCoS packet received (My-HM-CFG-LAN, RSSI: -49 dBm): 0FFC80022E1E4100AFFE010409202E40
10/02/19 09:30:06.850 Module HomeMatic BidCoS: Popping from BidCoSQueue: 1
10/02/19 09:30:06.850 Module HomeMatic BidCoS: Message now at front: Message type: 0x2
10/02/19 09:30:06.850 Module HomeMatic BidCoS: Popping from BidCoSQueue: 1
10/02/19 09:30:06.851 Module HomeMatic BidCoS: Info: Queue 1 is empty and there are no pending queues.
10/02/19 09:30:06.852 Module HomeMatic BidCoS: Info: BOOST_STATE on channel 4 of HomeMatic BidCoS peer 3 with serial number LEQ0782364 was set to 0x00.
10/02/19 09:30:06.852 Module HomeMatic BidCoS: Info: CONTROL_MODE on channel 4 of HomeMatic BidCoS peer 3 with serial number LEQ0782364 was set to 0x01.
10/02/19 09:30:06.852 Module HomeMatic BidCoS: Info: FAULT_REPORTING on channel 4 of HomeMatic BidCoS peer 3 with serial number LEQ0782364 was set to 0x00.
10/02/19 09:30:06.852 Module HomeMatic BidCoS: Info: PARTY_START_TIME on channel 4 of HomeMatic BidCoS peer 3 with serial number LEQ0782364 was set to 0x00.
10/02/19 09:30:06.853 Module HomeMatic BidCoS: Info: SET_TEMPERATURE on channel 4 of HomeMatic BidCoS peer 3 with serial number LEQ0782364 was set to 0x09.
10/02/19 09:30:06.888 RPC Server (Port 2001): Response: 
(void)
10/02/19 09:30:06.889 RPC Server (Port 2001): Response packet: HTTP/1.1 200 OK
Connection: Keep-Alive
Content-Type: text/xml
Content-Length: 96

<?xml version="1.0"?><methodResponse><params><param><value/></param></params></methodResponse>

Hat jemand eine Idee, was das nun wieder ist? Ich befinde mich noch im aktuellen stable release (0.7.40-2948) von homegear.

Grüße, Rudi

[rbott]

Uhm…nevermind. Das war mein Problem: mein PHP RPC Code hat den Temperatur-Wert als String reingereicht. Ein floatval() drumherum hat das Problem gelöst. Da hat sich vermutlich das homegear Verhalten irgendwann geändert und ich habs nicht gemerkt weil a) Sommer war und b) dann irgendwann der 64-Bit-Zeitstempel-Bug alles weitere verhindert hat.