Nochmal openHAB RPC Problem

Deutsche Foren Fehler
#1

Moin Zusammen,

nachdem der letzte Fehler im Zusammenhang mit openHAB so prima gelöst wurde, hat sich jetzt mit den neuesten openHAB Nightly ein neuer Fehler eingeschlichen. Da ich nicht in der Lage bin an der richtigen stelle zu suchen, stelle ich auch hier mal den Fehler ein, da dieser jetzt alle homematic Komponenten in openHAB lahmlegt.

Es scheint etwas mit dem RPC Protokoll zu tun zuhaben.

2018-01-24 10:40:06.544 [ERROR] [nicator.server.BinRpcResponseHandler] - No BinX signature
java.io.UnsupportedEncodingException: No BinX signature
        at org.openhab.binding.homematic.internal.communicator.message.BinRpcMessage.validateBinXSignature(BinRpcMessage.java:91) [214:org.openhab.binding.homematic:2.3.0.201801232258]
        at org.openhab.binding.homematic.internal.communicator.message.BinRpcMessage.<init>(BinRpcMessage.java:79) [214:org.openhab.binding.homematic:2.3.0.201801232258]
        at org.openhab.binding.homematic.internal.communicator.server.BinRpcResponseHandler.run(BinRpcResponseHandler.java:44) [214:org.openhab.binding.homematic:2.3.0.201801232258]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
        at java.lang.Thread.run(Thread.java:748) [?:?]

Wäre schön, wenn jemand das bestätigen könnte und dann natürlich auch reinschauen könnte.

Danke
Thomas

#2

Hallo @dibbler42,

da würde ein Hinweis von @gerrieg helfen, ob es ein Homegear-Problem ist. Könntest du das dazugehörige Homegear-Log auf Loglevel 4 posten? Vielleicht hilft das weiter, den Fehler etwas einzugrenzen.

Viele Grüße

Sathya

#3

Hier mal das Log. Ich hoffe, dass ich den richtigen Ausschnitt gefunden habe.

01/24/18 13:35:12.316 RPC Server (Port 2001): Info: Client number 105346 is calling RPC method: init (2) Parameters:
(String) binary://10.42.42.13:9126
01/24/18 13:35:12.318 Info: Client with IP ::ffff:10.42.42.13 is calling "init".
01/24/18 13:35:12.320 Info: Removing server "binary://10.42.42.13".
01/24/18 13:35:12.333 RPC Server (Port 2001): Info: Connection from ::ffff:10.42.42.13:47042 accepted. Client number: 105350
01/24/18 13:35:12.337 RPC Server (Port 2001): Info: RPC server client id for client number 105350 is: 2459
01/24/18 13:35:12.340 RPC Server (Port 2001): Info: Client number 105350 is calling RPC method: init (2) Parameters:
(String) binary://10.42.42.13:9126
(String) RF-895298B3-A5AA-26E6-54D1-4339B9E56827
(Integer) 32
01/24/18 13:35:12.342 Info: Client with IP ::ffff:10.42.42.13 is calling "init".
01/24/18 13:35:12.345 Info: Adding server "binary://10.42.42.13".
01/24/18 13:35:12.348 Info: Calling init methods on server "binary://10.42.42.13".
01/24/18 13:35:12.354 RPC Server (Port 2001): Info: Connection from ::ffff:10.42.42.13:47044 accepted. Client number: 105351
01/24/18 13:35:12.358 RPC Server (Port 2001): Info: RPC server client id for client number 105351 is: 2460
01/24/18 13:35:12.363 RPC Server (Port 2001): Info: Client number 105351 is calling RPC method: ping (2) Parameters:
(String) 895298B3-A5AA-26E6-54D1-4339B9E56827
01/24/18 13:35:12.375 Warning: Connection to client number 105352 closed (3): Connection reset by peer
01/24/18 13:35:12.387 Warning: Connection to client number 105353 closed (3): Connection reset by peer
01/24/18 13:35:12.399 Warning: Connection to client number 105354 closed (3): Connection reset by peer
01/24/18 13:35:12.402 Removing server "RF-895298B3-A5AA-26E6-54D1-4339B9E56827" after trying to send a packet 3 times. Server has to send "init" again.
#4

Hab das Thema natürlich auch im OH Forum gepostet.

Thomas

#5

Hmm, kannst du mir den Ausschnitt noch einmal auf Loglevel 5 posten?

#6

Logs:

01/25/18 09:28:51.720 RPC Server (Port 2001): Info: Client number 2508 is calling RPC method: init (2) Parameters:
(String) binary://192.168.1.121:9126
01/25/18 09:28:51.720 Info: Client with IP ::ffff:127.0.0.1 is calling "init".
01/25/18 09:28:51.720 Info: Removing server "binary://192.168.1.121".
01/25/18 09:28:51.721 RPC Server (Port 2001): Response:
(void)
01/25/18 09:28:51.721 RPC Server (Port 2001): Response binary:
42696E01000000080000000300000000
01/25/18 09:28:51.726 RPC Server (Port 2001): Debug: Connection to client number 2508 closed (3).
01/25/18 09:28:51.737 RPC Server (Port 2001): Info: Connection from ::ffff:127.0.0.1:50102 accepted. Client number: 2532
01/25/18 09:28:51.737 RPC Server (Port 2001): Info: RPC server client id for client number 2532 is: 157
01/25/18 09:28:51.737 RPC Server (Port 2001): Listening for incoming packets from client number 2532.
01/25/18 09:28:51.738 RPC Server (Port 2001): Debug: Packet received: 42696E000000004400000004696E697400000003000000030000001B62696E6172793A2F2F3139322E3136382E312E3132313A39313236000000030000000552462D68670000000100000020
01/25/18 09:28:51.738 RPC Server (Port 2001): Info: Client number 2532 is calling RPC method: init (2) Parameters:
(String) binary://192.168.1.121:9126
(String) RF-hg
(Integer) 32
01/25/18 09:28:51.738 Info: Client with IP ::ffff:127.0.0.1 is calling "init".
01/25/18 09:28:51.738 Info: Adding server "binary://192.168.1.121".
01/25/18 09:28:51.738 RPC Server (Port 2001): Response:
(void)
01/25/18 09:28:51.739 Info: Calling init methods on server "binary://192.168.1.121".
01/25/18 09:28:51.753 RPC Server (Port 2001): Response binary:
42696E01000000080000000300000000
01/25/18 09:28:51.756 RPC Server (Port 2001): Debug: Connection to client number 2532 closed (3).
01/25/18 09:28:51.757 RPC Server (Port 2001): Info: Connection from ::ffff:127.0.0.1:50104 accepted. Client number: 2533
01/25/18 09:28:51.757 RPC Server (Port 2001): Info: RPC server client id for client number 2533 is: 158
01/25/18 09:28:51.758 RPC Server (Port 2001): Listening for incoming packets from client number 2533.
01/25/18 09:28:51.758 RPC Server (Port 2001): Debug: Packet received: 42696E00000000160000000470696E670000000100000003000000026867
01/25/18 09:28:51.758 RPC Server (Port 2001): Info: Client number 2533 is calling RPC method: ping (2) Parameters:
(String) hg

... MQTT ...

01/25/18 09:28:51.774 RPC Server (Port 2001): Response:
(Boolean) 1
01/25/18 09:28:51.774 RPC Server (Port 2001): Response binary:
42696E01000000050000000201

... MQTT Einträge ...

01/25/18 09:28:52.253 RPC client: Debug: Calling RPC method "system.listMethods" on server 192.168.1.121.
01/25/18 09:28:52.254 RPC client: Parameters:
01/25/18 09:28:52.254 Debug: Calling getFileDescriptor...
01/25/18 09:28:52.254 Debug: Connecting to host 192.168.1.121 on port 9126...
01/25/18 09:28:52.254 Debug: Connected to host 192.168.1.121 on port 9126. Client number is: 2534
01/25/18 09:28:52.254 RPC client: Debug: Sending packet: POST /RPC2 HTTP/1.1
User-Agent: Homegear 0.7.12-1492
Host: 192.168.1.121:9126
Content-Type: text/xml
Content-Length: 101
Connection: close

<?xml version="1.0"?>
<methodCall><methodName>system.listMethods</methodName><params/></methodCall>

01/25/18 09:28:52.261 Warning: Connection to client number 2534 closed (3): Connection reset by peer
01/25/18 09:28:52.262 Debug: Calling getFileDescriptor...
01/25/18 09:28:52.262 Debug: Connecting to host 192.168.1.121 on port 9126...
01/25/18 09:28:52.262 Debug: Connected to host 192.168.1.121 on port 9126. Client number is: 2535
01/25/18 09:28:52.262 RPC client: Debug: Sending packet: POST /RPC2 HTTP/1.1
User-Agent: Homegear 0.7.12-1492
Host: 192.168.1.121:9126
Content-Type: text/xml
Content-Length: 101
Connection: close

<?xml version="1.0"?>
<methodCall><methodName>system.listMethods</methodName><params/></methodCall>

Erste Einschätzung

Homegear scheint eine XmlRpc Antwort auf den BinRpc Port zu senden. Dementsprechend passt die Signatur nicht. Ob das jetzt an einer Änderung in homegear oder openhab liegt, kann ich adhoc noch nicht sehen. Ich habe homegear auf die 0.7.12 zurückgesetzt, aber der Fehler ist geblieben.

Gruß,

Stephan

#7

Hallo @pauxus1,

der Fehler hat damit zu tun, das @gerrieg jetzt den Parameter flags auf 32 in init() setzt. Dort ist das Binary-Flag (2) nicht mitgesetzt. Das hat bis jetzt das binary:// überschrieben. Ich habe das Verhalten jetzt geändert, so dass entweder das Flag oder das Präfix verwendet werden kann. Im nächsten Homegear-Nightly sollte es wieder passen.

Viele Grüße

Sathya

#8

Hallo Sathya,

Das ging flott, danke.

Ist damit der init Request nicht eigentlich falsch? Sprich müsste es nicht eher in Openhab angepasst werden?

Mach wahrscheinlich Sinn, dass Homegear in diesem Fall zumindest eine fette Warnung in die Logs schreibt.

Gruß,

Stephan

#9

Hallo Stephan,

eigentlich ist das binary:// ja eindeutig. Ich wüsste keinen Fall, warum über das Binary-Flag Binär-RPC wieder abgeschaltet können werden sollte. Von daher passt die Lösung denke ich so.

Viele Grüße

Sathya

#10

Ich werde das Flag demnächst sicherheitshalber auch noch in Openhab hinzufügen.

Viele Grüße
Gerhard

#11

Moin Zusammen,

habe gerade mal die 1983 nightly installiert und bekommen den Fehler weiterhin.

Thomas

#12

Ist auch bisher nur für Debian Stretch amd64 und i386 online. Raspbian sollte spätestens morgen online sein.

#13

Ach und ich bin doch so ungeduldig :slight_smile:

Danke
Thomas

#14

Ich auch oft :-P. Doofe Kompilierwartezeit…

#15

1988 installiert und die aktuelle openHAB -> Fehler ist weg.

Danke

2 Likes
#16

@sathya
@gerrieg

Und hier kommt das nächste Problem :frowning: Ich habe (sorry for that) mal wieder ein update gefahren und bin jetzt bei homgear auf der 0.8.0-2000 und bei openHab auf der 2.3 1203.

Auf irgendeiner Seite wurde etwas verändert, was das Protokoll wieder zum straucheln bringt und zwar gründlich.

Hier mal das Log von openhab.

2018-02-03 08:51:06.839 [INFO ] [ommunicator.AbstractHomematicGateway] - HmGatewayInfo[id=HOMEGEAR,type=Homegear,firmware=0.8.0-2000,address=VBC1738129,wired=false,hmip=false,cuxd=false,group=false]
2018-02-03 08:51:07.433 [INFO ] [l.communicator.message.BinRpcMessage] - 42 B
2018-02-03 08:51:07.447 [INFO ] [l.communicator.message.BinRpcMessage] - 69 i
2018-02-03 08:51:07.476 [INFO ] [l.communicator.message.BinRpcMessage] - 6e n
2018-02-03 08:51:07.479 [INFO ] [l.communicator.message.BinRpcMessage] - 1
2018-02-03 08:51:07.482 [INFO ] [l.communicator.message.BinRpcMessage] - 0
2018-02-03 08:51:07.486 [INFO ] [l.communicator.message.BinRpcMessage] - 1
2018-02-03 08:51:07.488 [INFO ] [l.communicator.message.BinRpcMessage] - ffffffcb ￋ
2018-02-03 08:51:07.496 [INFO ] [l.communicator.message.BinRpcMessage] - 29 )
2018-02-03 08:51:07.508 [INFO ] [l.communicator.message.BinRpcMessage] - 0
2018-02-03 08:51:07.510 [INFO ] [l.communicator.message.BinRpcMessage] - 0
2018-02-03 08:51:07.513 [INFO ] [l.communicator.message.BinRpcMessage] - 1
2018-02-03 08:51:07.523 [INFO ] [l.communicator.message.BinRpcMessage] - 0
2018-02-03 08:51:07.544 [INFO ] [l.communicator.message.BinRpcMessage] - 0
2018-02-03 08:51:07.557 [INFO ] [l.communicator.message.BinRpcMessage] - 0
2018-02-03 08:51:07.570 [INFO ] [l.communicator.message.BinRpcMessage] - 1
2018-02-03 08:51:07.573 [INFO ] [l.communicator.message.BinRpcMessage] - b

2018-02-03 08:51:07.575 [INFO ] [l.communicator.message.BinRpcMessage] - 0
2018-02-03 08:51:07.577 [INFO ] [l.communicator.message.BinRpcMessage] - 0
2018-02-03 08:51:07.579 [INFO ] [l.communicator.message.BinRpcMessage] - 1
2018-02-03 08:51:07.597 [INFO ] [l.communicator.message.BinRpcMessage] - 1
2018-02-03 08:51:07.607 [INFO ] [l.communicator.message.BinRpcMessage] - 0
2018-02-03 08:51:07.610 [INFO ] [l.communicator.message.BinRpcMessage] - 0
2018-02-03 08:51:07.613 [INFO ] [l.communicator.message.BinRpcMessage] - 0
2018-02-03 08:51:07.615 [INFO ] [l.communicator.message.BinRpcMessage] - 12
2018-02-03 08:51:07.619 [INFO ] [l.communicator.message.BinRpcMessage] - 0
2018-02-03 08:51:07.624 [INFO ] [l.communicator.message.BinRpcMessage] - 0
2018-02-03 08:51:07.627 [INFO ] [l.communicator.message.BinRpcMessage] - 0
2018-02-03 08:51:07.639 [INFO ] [l.communicator.message.BinRpcMessage] - 7
2018-02-03 08:51:07.642 [INFO ] [l.communicator.message.BinRpcMessage] - 41 A
2018-02-03 08:51:07.644 [INFO ] [l.communicator.message.BinRpcMessage] - 44 D
2018-02-03 08:51:07.655 [INFO ] [l.communicator.message.BinRpcMessage] - 44 D
2018-02-03 08:51:07.657 [INFO ] [l.communicator.message.BinRpcMessage] - 52 R
2018-02-03 08:51:07.661 [INFO ] [l.communicator.message.BinRpcMessage] - 45 E
2018-02-03 08:51:07.663 [INFO ] [l.communicator.message.BinRpcMessage] - 53 S
2018-02-03 08:51:07.666 [INFO ] [l.communicator.message.BinRpcMessage] - 53 S
2018-02-03 08:51:07.669 [INFO ] [l.communicator.message.BinRpcMessage] - 0
2018-02-03 08:51:07.688 [INFO ] [l.communicator.message.BinRpcMessage] - 0
2018-02-03 08:51:07.691 [INFO ] [l.communicator.message.BinRpcMessage] - 0
2018-02-03 08:51:07.694 [INFO ] [l.communicator.message.BinRpcMessage] - 3
2018-02-03 08:51:07.697 [INFO ] [l.communicator.message.BinRpcMessage] - 0
2018-02-03 08:51:07.710 [INFO ] [l.communicator.message.BinRpcMessage] - 0
2018-02-03 08:51:07.713 [INFO ] [l.communicator.message.BinRpcMessage] - 0
2018-02-03 08:51:07.743 [INFO ] [l.communicator.message.BinRpcMessage] - a

Das läuft dann so durch, bis nix mehr kommt und später funktioniert natürlich keine Kommunikation.

auf der Homegear seite sehe ich nichts ungewöhnliches

#17

Jemand hat beim BinRpc Protokoll etwas geändert. Es gibt bereits einen Fix den ich auch getestet habe: https://github.com/openhab/openhab2-addons/pull/3202

#18

Ja, ist fixed in der 1204

Danke