OWN CONNECTION ERROR

[fmalfatto]

I have several times in a day the following message:

2019-03-02 00:57:20.398 [WARN ] [org.openwebnet.bus.MyHomeConnection ] - ##gw-openwebnet-conn## ... STEP-2: HANDSHAKE FAILED response=*#9938080## 2019-03-02 00:57:20.704 [WARN ] [bnet.handler.OpenWebNetBridgeHandler] - ==OWN== CONNECTION ERROR: Connection error (IOException). Check network and gateway thing Configuration Parameters 2019-03-02 00:57:22.395 [WARN ] [org.openwebnet.bus.MyHomeConnection ] - ##gw-openwebnet-conn## ... handshake not completed but timeout expired, closing socket... 2019-03-02 00:57:23.214 [INFO ] [bnet.handler.OpenWebNetBridgeHandler] - ==OWN== ------------------- RE-CONNECTED to gateway! It happens with both gateways I have , MHS1 and a Touch 3.5 LN4890.

After these messages all is working again as usual, but sometime happens that a switch (and only this one) get opened: bus_on_off_switch Sez_garage "Sezionale garage" @ "Garage" [ where="25" ] This is my garage door, end when it is open with the alarm inserted, the alarm starts! This is very annoying! Thank you in advance for any help

[mvalla]

These seem two separate issues.

For the handshake failed seems that the gateway answers with a unexpected response (response=*#9938080##) after some disconnection. I will have to see the documentation (if there is one!) and check what that response from gateway means

The second issue about the switch being activated is very strange as of course the binding does not switch thing on or off if not done by the user. Do you have perhaps some rule or scenario that gets activated related to this switch? Can you post the log when this happens to see what has sent the command to the switch?

Bye M

[fmalfatto]

TY. I'm a little bit confused about the new settings of the log files. After last upgrades I lost the events file and I'm trying to recover it in karaf, but until now no success. I think I'll have to read the new documentation. This issue is a good reason to do it. The first issue is strange because I have nothing in openhab.log that could help:

2019-03-01 14:07:51.631 [ERROR] [penwebnet.message.OpenMessageFactory] - ##openwebnet## INVALID FRAME: *5*5*## 2019-03-01 14:07:55.923 [ERROR] [penwebnet.message.OpenMessageFactory] - ##openwebnet## INVALID FRAME: *5*1*## 2019-03-01 14:07:55.947 [ERROR] [penwebnet.message.OpenMessageFactory] - ##openwebnet## INVALID FRAME: *5*8*## 2019-03-01 14:07:55.954 [ERROR] [penwebnet.message.OpenMessageFactory] - ##openwebnet## INVALID FRAME: *5*5*## 2019-03-01 14:07:55.958 [ERROR] [penwebnet.message.OpenMessageFactory] - ##openwebnet## INVALID FRAME: *5*7*## 2019-03-01 14:08:12.286 [ERROR] [penwebnet.message.OpenMessageFactory] - ##openwebnet## INVALID FRAME: *5*5*## 2019-03-01 17:25:19.667 [WARN ] [org.openwebnet.bus.MyHomeConnection ] - ##gw-openwebnet-conn## ... STEP-2: HANDSHAKE FAILED response=*#8526672## 2019-03-01 17:25:19.975 [WARN ] [bnet.handler.OpenWebNetBridgeHandler] - ==OWN== CONNECTION ERROR: Connection error (IOException). Check network and gateway thing Configuration Parameters 2019-03-01 17:25:21.664 [WARN ] [org.openwebnet.bus.MyHomeConnection ] - ##gw-openwebnet-conn## ... handshake not completed but timeout expired, closing socket... 2019-03-01 17:25:22.482 [WARN ] [org.openwebnet.bus.MyHomeConnection ] - ##gw-openwebnet-conn## ... STEP-2: HANDSHAKE FAILED response=*#6687401## 2019-03-01 17:25:22.487 [WARN ] [org.openwebnet.OpenGatewayBus ] - ##gw-openwebnet-BUS## ...re-connect FAILED. Exception: Handshake failed, invalid response from GW at STEP-2 2019-03-01 17:25:24.479 [WARN ] [org.openwebnet.bus.MyHomeConnection ] - ##gw-openwebnet-conn## ... handshake not completed but timeout expired, closing socket... 2019-03-01 19:25:19.648 [WARN ] [org.openwebnet.bus.MyHomeConnection ] - ##gw-openwebnet-conn## ... STEP-2: HANDSHAKE FAILED response=*#7093760## 2019-03-01 19:25:19.956 [WARN ] [bnet.handler.OpenWebNetBridgeHandler] - ==OWN== CONNECTION ERROR: Connection error (IOException). Check network and gateway thing Configuration Parameters 2019-03-01 19:25:21.641 [WARN ] [org.openwebnet.bus.MyHomeConnection ] - ##gw-openwebnet-conn## ... handshake not completed but timeout expired, closing socket... 2019-03-01 19:25:22.465 [INFO ] [bnet.handler.OpenWebNetBridgeHandler] - ==OWN== ------------------- RE-CONNECTED to gateway! 2019-03-01 20:11:10.067 [ERROR] [penwebnet.message.OpenMessageFactory] - ##openwebnet## INVALID FRAME: *5*5*## 2019-03-01 20:11:14.375 [ERROR] [penwebnet.message.OpenMessageFactory] - ##openwebnet## INVALID FRAME: *5*1*## 2019-03-01 20:11:14.389 [ERROR] [penwebnet.message.OpenMessageFactory] - ##openwebnet## INVALID FRAME: *5*8*## 2019-03-01 20:11:14.392 [ERROR] [penwebnet.message.OpenMessageFactory] - ##openwebnet## INVALID FRAME: *5*5*## 2019-03-01 20:11:14.397 [ERROR] [penwebnet.message.OpenMessageFactory] - ##openwebnet## INVALID FRAME: *5*7*## 2019-03-01 20:12:11.871 [ERROR] [penwebnet.message.OpenMessageFactory] - ##openwebnet## INVALID FRAME: *5*3*## 2019-03-01 20:20:31.263 [ERROR] [penwebnet.message.OpenMessageFactory] - ##openwebnet## INVALID FRAME: *5*1*## 2019-03-01 20:20:31.275 [ERROR] [penwebnet.message.OpenMessageFactory] - ##openwebnet## INVALID FRAME: *5*8*## 2019-03-01 20:20:31.300 [ERROR] [penwebnet.message.OpenMessageFactory] - ##openwebnet## INVALID FRAME: *5*5*## 2019-03-01 20:20:31.316 [ERROR] [penwebnet.message.OpenMessageFactory] - ##openwebnet## INVALID FRAME: *5*7*## 2019-03-01 20:47:20.186 [WARN ] [org.openwebnet.bus.MyHomeConnection ] - ##gw-openwebnet-conn## ... STEP-2: HANDSHAKE FAILED response=*#585976## 2019-03-01 20:47:20.491 [WARN ] [bnet.handler.OpenWebNetBridgeHandler] - ==OWN== CONNECTION ERROR: Connection error (IOException). Check network and gateway thing Configuration Parameters 2019-03-01 20:47:22.182 [WARN ] [org.openwebnet.bus.MyHomeConnection ] - ##gw-openwebnet-conn## ... handshake not completed but timeout expired, closing socket... 2019-03-01 20:47:23.002 [INFO ] [bnet.handler.OpenWebNetBridgeHandler] - ==OWN== ------------------- RE-CONNECTED to gateway! 2019-03-01 22:52:26.189 [ERROR] [penwebnet.message.OpenMessageFactory] - ##openwebnet## INVALID FRAME: *5*5*## 2019-03-01 23:13:21.527 [ERROR] [penwebnet.message.OpenMessageFactory] - ##openwebnet## INVALID FRAME: *5*5*## 2019-03-01 23:13:25.845 [ERROR] [penwebnet.message.OpenMessageFactory] - ##openwebnet## INVALID FRAME: *5*1*## 2019-03-01 23:13:25.850 [ERROR] [penwebnet.message.OpenMessageFactory] - ##openwebnet## INVALID FRAME: *5*8*## 2019-03-01 23:13:25.853 [ERROR] [penwebnet.message.OpenMessageFactory] - ##openwebnet## INVALID FRAME: *5*5*## 2019-03-01 23:13:25.871 [ERROR] [penwebnet.message.OpenMessageFactory] - ##openwebnet## INVALID FRAME: *5*7*## 2019-03-01 23:14:23.870 [ERROR] [penwebnet.message.OpenMessageFactory] - ##openwebnet## INVALID FRAME: *5*3*## 2019-03-02 00:57:20.398 [WARN ] [org.openwebnet.bus.MyHomeConnection ] - ##gw-openwebnet-conn## ... STEP-2: HANDSHAKE FAILED response=*#9938080## 2019-03-02 00:57:20.704 [WARN ] [bnet.handler.OpenWebNetBridgeHandler] - ==OWN== CONNECTION ERROR: Connection error (IOException). Check network and gateway thing Configuration Parameters 2019-03-02 00:57:22.395 [WARN ] [org.openwebnet.bus.MyHomeConnection ] - ##gw-openwebnet-conn## ... handshake not completed but timeout expired, closing socket... 2019-03-02 00:57:23.214 [INFO ] [bnet.handler.OpenWebNetBridgeHandler] - ==OWN== ------------------- RE-CONNECTED to gateway!

I try te restart the event log to see what switches on the garage!

`

[mvalla]

For the connection error I would need:

• version of OH, version of the binding used
• model of the BTicino OpenWebNet gateway used
• set log level to debug (see README how)
• when in the log you see a HANDSHAKE FAILED, extract the log in a separate file from 10min before to some minutes after that log line, then post it here USING CODE FENCES, or event better send the log file as attachment with a private msg in the OH forum

Did you understand what switches on the garage?

[fmalfatto]

I did not succeeded in making a deep debug, but I think that the problem is not in the openhab side. I normally use the old My_Home suite to configure my devices and the MHS1, but I also have the official MyHomeUp application on smartphone. It happens that when I try to use it, for example to add a new device, the app corrupts my configuration, and I need to restore the correct configuration from MyHome_suite. If I do not reset everything after using the app, it may happens that devices are mixed and/or unusable. So I think that happened that the garage was opening at random. After resetting the whole configuration with MyhomeSuite, and avoiding the app, it works correctly. I decided to freeze experiments until the binding will support the AUX command, because the only think I really need is the way to control the burglar alarm from remote. I begin to be disappointed about the whole BTicino world: I had many official apps that mostly are unusable. So I decided to make my own portal with Domoticz and after few months I found that it is no more supporting OWN. So I moved to Openhab and I think it is a great software, but maybe the BTicino bus is too difficult to manage also for Openhab, so I think it's better to wait and think to a better solution. After 2 years from building a new brand domotic system I feel like I have an old and useless setup: most of devices are no more supported or not working well, and each time I call the support they tell me that I need to buy another piece to achieve what I thought I had already buy.

[mvalla]

Where is it said that Domoticz does not support BTicino anymore?

In the end: is this issue still valid? Can you reproduce the problem and provide a DEBUG level log, or shall I close this issue?

[fmalfatto]

1) The domoticz forum (openwebnet thread) is freezed since a year and I'm the last one who wrote there, just asking general info about the future of the project, and never had an answer.

2) I apologyze about not being able to follow your suggestions, but I'm a system engineer and not a developer, so I do not know how to follow the development flux of such a complex software. I try to read the suggestions but I miss the basic knowledge of the process. I programmed for 45 years in several languages but I never understood the path of building a Java application. Too far from my prehistoric skills. :-(

3) I had to completely restart from scratch my raspi environment because I cannot understand how manage upgrades and updates of packages, so I loose everything at each effort to change things. Maybe it's because I'm a unix man, and I cannot afford the way Debian manages the packages. I'm actually moving to another distribution. On my raspi I have both Domoticz, still working, and Openhab, and also DNS, DHCPD and other infrastructural services, maybe it's too much! For these reasons I think that the problem is in my environment and not in the package. Anyway, the connection problem is still there and this is the debug, but feel free to close the question.

I just upgraded manually o 2.5.0.M2-1 and I see no changes, here is part of the debug:

`> 2019-03-23 13:46:42.417 [INFO ] [g.openwebnet.bus.MyHomeJavaConnector] - COM SENDING ============>>>>>>>>>>>> *#13**15##

2019-03-23 13:46:42.421 [DEBUG] [g.openwebnet.bus.MyHomeSocketFactory] - ##gw-openwebnet-socket## CANNOT read from socket: read returned -1 2019-03-23 13:46:42.423 [DEBUG] [g.openwebnet.bus.MyHomeJavaConnector] - ##gw-openwebnet-connector## read returned -1 2019-03-23 13:46:42.426 [DEBUG] [g.openwebnet.bus.MyHomeJavaConnector] - ##gw-openwebnet-connector## let's try with a NEW SESSION... 2019-03-23 13:46:42.428 [INFO ] [g.openwebnet.bus.MyHomeSocketFactory] - ##gw-openwebnet-socket## Trying openCommandSession() socket.... (192.168.1.40:20000) 2019-03-23 13:46:42.432 [DEBUG] [org.openwebnet.bus.MyHomeConnection ] - ##gw-openwebnet-conn## ... starting HANDSHAKE ... 2019-03-23 13:46:42.435 [DEBUG] [org.openwebnet.bus.MyHomeConnection ] - COM RECEIVED <<<<<<====== #1## 2019-03-23 13:46:42.437 [DEBUG] [org.openwebnet.bus.MyHomeConnection ] - COM SENDING ======>>>>>> 990## 2019-03-23 13:46:42.442 [DEBUG] [org.openwebnet.bus.MyHomeConnection ] - COM RECEIVED <<<<<<====== 982## 2019-03-23 13:46:42.445 [DEBUG] [org.openwebnet.bus.MyHomeConnection ] - COM SENDING ======>>>>>> #1## 2019-03-23 13:46:42.450 [DEBUG] [org.openwebnet.bus.MyHomeConnection ] - COM RECEIVED <<<<<<====== #11100811140504141313021410141212041215030411100504151202031212131408100511031204051310070310050008051107130900071200011212140205## 2019-03-23 13:46:42.457 [DEBUG] [org.openwebnet.bus.MyHomeConnection ] - COM SENDING ======>>>>>> #0910131506030203091010111005081107041400080703151408140813051414101404080810010013120714091302011312031503120515130008120807151103141300021201130600070802091001071012120302150900120913020308080508110011050012050806140409090707071115010014030507080302070912## 2019-03-23 13:46:42.462 [DEBUG] [org.openwebnet.bus.MyHomeConnection ] - COM RECEIVED <<<<<<====== #13041102070515021507090701041213071111120013020202131408080511030111010511020008021305030815121307110506080008031307010714151202## 2019-03-23 13:46:42.467 [DEBUG] [org.openwebnet.bus.MyHomeConnection ] - COM SENDING ======>>>>>> #1## 2019-03-23 13:46:42.470 [INFO ] [g.openwebnet.bus.MyHomeSocketFactory] - ##gw-openwebnet-socket## ... CONNECTED command session 192.168.1.40:20000 2019-03-23 13:46:42.473 [INFO ] [g.openwebnet.bus.MyHomeJavaConnector] - COM SENDING ============>>>>>>>>>>>> *#1315## 2019-03-23 13:46:42.518 [INFO ] [g.openwebnet.bus.MyHomeSocketFactory] - COM RECEIVED <<<<<<<<<<<<============ *#1315200## 2019-03-23 13:46:42.562 [INFO ] [g.openwebnet.bus.MyHomeSocketFactory] - COM RECEIVED <<<<<<<<<<<<============ #1## 2019-03-23 13:46:42.865 [DEBUG] [org.openwebnet.OpenGatewayBus$a ] - ##gw-openwebnet-BUSReceiveThread## ^^^ ... gw is still reachable! 2019-03-23 13:46:42.866 [INFO ] [org.openwebnet.OpenGatewayBus$a ] - MON RECEIVED <<<<<<<<<<< #1315200## 2019-03-23 13:46:42.868 [DEBUG] [org.openwebnet.OpenGatewayBus ] - ##gw-openwebnet-BUS## server MODEL=MyHOMEServer1 / MH202 / F455 2019-03-23 13:46:42.870 [DEBUG] [bnet.handler.OpenWebNetBridgeHandler] - ==OWN== GatewayManagement WHAT = null 2019-03-23 13:47:56.757 [DEBUG] [org.openwebnet.bus.MyHomeConnection ] - ##gw-openwebnet-conn## sending MON keepalive ACK 2019-03-23 13:47:56.762 [DEBUG] [org.openwebnet.bus.MyHomeConnection ] - MON SENDING ======>>>>>> #1## 2019-03-23 13:48:42.963 [DEBUG] [g.openwebnet.bus.MyHomeJavaConnector] - ##gw-openwebnet-connector## readMonitoring() SocketTimeoutException: Read timed out 2019-03-23 13:48:42.967 [DEBUG] [org.openwebnet.OpenGatewayBus$a ] - ##gw-openwebnet-BusReceiveThread## SocketTimeoutException on readMonitoring: Read timed out 2019-03-23 13:48:42.970 [DEBUG] [org.openwebnet.OpenGatewayBus$a ] - ##gw-openwebnet-BusReceiveThread## ^^^ sending CMD message to see if gw is still reachable... 2019-03-23 13:48:42.973 [INFO ] [g.openwebnet.bus.MyHomeJavaConnector] - COM SENDING ============>>>>>>>>>>>> #13*15## 2019-03-23 13:48:42.978 [DEBUG] [g.openwebnet.bus.MyHomeSocketFactory] - ##gw-openwebnet-socket## CANNOT read from socket: read returned -1 2019-03-23 13:48:42.980 [DEBUG] [g.openwebnet.bus.MyHomeJavaConnector] - ##gw-openwebnet-connector## read returned -1 2019-03-23 13:48:42.984 [DEBUG] [g.openwebnet.bus.MyHomeJavaConnector] - ##gw-openwebnet-connector## let's try with a NEW SESSION... 2019-03-23 13:48:42.986 [INFO ] [g.openwebnet.bus.MyHomeSocketFactory] - ##gw-openwebnet-socket## Trying openCommandSession() socket.... (192.168.1.40:20000) 2019-03-23 13:48:42.993 [DEBUG] [org.openwebnet.bus.MyHomeConnection ] - ##gw-openwebnet-conn## ... starting HANDSHAKE ... 2019-03-23 13:48:42.997 [DEBUG] [org.openwebnet.bus.MyHomeConnection ] - COM RECEIVED <<<<<<====== #1## 2019-03-23 13:48:42.999 [DEBUG] [org.openwebnet.bus.MyHomeConnection ] - COM SENDING ======>>>>>> 990## 2019-03-23 13:48:43.005 [DEBUG] [org.openwebnet.bus.MyHomeConnection ] - COM RECEIVED <<<<<<====== 982## 2019-03-23 13:48:43.007 [DEBUG] [org.openwebnet.bus.MyHomeConnection ] - COM SENDING ======>>>>>> #1## 2019-03-23 13:48:43.013 [DEBUG] [org.openwebnet.bus.MyHomeConnection ] - COM RECEIVED <<<<<<====== #06000008020303080713080307011013051214050904061006151314070211130714030607091115070015131007030514000402041507100605141102051201## 2019-03-23 13:48:43.024 [DEBUG] [org.openwebnet.bus.MyHomeConnection ] - COM SENDING ======>>>>>> #0508131011001113130111090510061209091405090611130206030209140404140401150603111012130309151305010313120012110603060203030606120702130007100003090806090905120110050208010602030205020805121000090009080103051214130911130805150415100803011004140405051405020907## 2019-03-23 13:48:43.030 [DEBUG] [org.openwebnet.bus.MyHomeConnection ] - COM RECEIVED <<<<<<====== #00141305070508050501030302090510121215140813011006121203130201061306010708100510060405071107041102050913020605091113111104120810## 2019-03-23 13:48:43.041 [DEBUG] [org.openwebnet.bus.MyHomeConnection ] - COM SENDING ======>>>>>> #1## 2019-03-23 13:48:43.046 [INFO ] [g.openwebnet.bus.MyHomeSocketFactory] - ##gw-openwebnet-socket## ... CONNECTED command session 192.168.1.40:20000 2019-03-23 13:48:43.049 [INFO ] [g.openwebnet.bus.MyHomeJavaConnector] - COM SENDING ============>>>>>>>>>>>> #1315## 2019-03-23 13:48:43.094 [INFO ] [g.openwebnet.bus.MyHomeSocketFactory] - COM RECEIVED <<<<<<<<<<<<============ *#1315200## 2019-03-23 13:48:43.142 [INFO ] [g.openwebnet.bus.MyHomeSocketFactory] - COM RECEIVED <<<<<<<<<<<<============ #1## 2019-03-23 13:48:43.444 [DEBUG] [org.openwebnet.OpenGatewayBus$a ] - ##gw-openwebnet-BUSReceiveThread## ^^^ ... gw is still reachable! 2019-03-23 13:48:43.447 [INFO ] [org.openwebnet.OpenGatewayBus$a ] - MON RECEIVED <<<<<<<<<<< #1315*200## 2019-03-23 13:48:43.448 [DEBUG] [org.openwebnet.OpenGatewayBus ] - ##gw-openwebnet-BUS## server MODEL=MyHOMEServer1 / MH202 / F455`

[mvalla]

in the last logs (even if was not posted correctly, using code fences!!) i cannot see any problem at all with the connection to the gateway. There is no ERROR or WARN message. The lines;

2019-03-23 13:46:42.421 [DEBUG] [g.openwebnet.bus.MyHomeSocketFactory] - ##gw-openwebnet-socket## CANNOT read from socket: read returned -1
2019-03-23 13:46:42.423 [DEBUG] [g.openwebnet.bus.MyHomeJavaConnector] - ##gw-openwebnet-connector## read returned -1
2019-03-23 13:46:42.426 [DEBUG] [g.openwebnet.bus.MyHomeJavaConnector] - ##gw-openwebnet-connector## let's try with a NEW SESSION...

are perfectly normal because the command sessions is shutdown from the gateway after some inactivity, so the binding checks periodically if it can still reach the gateway, re-establishing a NEW SESSION each time.

Since I do not see any error with the connection, I will close this issue.