[Satel] Exceptions during connection

zacofunny · October 31, 2016, 11:08am

Hi,
I’m getting the following messages while trying to connect Satel. I have OH2 however the same issue I had with on 1.8.x. I’ve updated Satel mainboard to the latest firmware. ETHM-1 has 1.07 firmware. @druciak, what I can do with that?

java:
root@openhab:/home/openhab# java -version
java version "1.8.0_111"
Java™ SE Runtime Environment (build 1.8.0_111-b14)
Java HotSpot™ 64-Bit Server VM (build 25.111-b14, mixed mode)

config:
host=192.168.11.193
port=7094
timeout=5000
refresh=5000
user_code=XXXXXX
encryption_key=XXXXXXXXXXXX

error messages:
2016-10-31 12:12:50.225 [INFO ] [.satel.internal.protocol.Ethm1Module] - Connecting to ETHM-1 module at 192.168.11.193:7094
2016-10-31 12:12:50.239 [INFO ] [.satel.internal.protocol.Ethm1Module] - ETHM-1 module connected successfully
2016-10-31 12:12:50.264 [ERROR] [.satel.internal.protocol.SatelModule] - Unexpected exception occurred during reading a message
java.io.IOException: Invalid ‘id_s’ value. Got: 13, expected: -23
at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel.readMessage(Ethm1Module.java:202)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel.access$0(Ethm1Module.java:176)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel$1.read(Ethm1Module.java:141)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule.readMessage(SatelModule.java:221)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule.communicationLoop(SatelModule.java:369)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule.access$1(SatelModule.java:331)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule$CommunicationWatchdog$2.run(SatelModule.java:463)[206:org.openhab.binding.satel:1.9.0.b4]
at java.lang.Thread.run(Thread.java:745)[:1.8.0_111]
2016-10-31 12:12:50.269 [INFO ] [.satel.internal.protocol.Ethm1Module] - Closing connection to ETHM-1 module
2016-10-31 12:12:51.225 [INFO ] [.satel.internal.protocol.Ethm1Module] - Connecting to ETHM-1 module at 192.168.11.193:7094
2016-10-31 12:12:51.242 [INFO ] [.satel.internal.protocol.Ethm1Module] - ETHM-1 module connected successfully
2016-10-31 12:12:51.268 [ERROR] [.satel.internal.protocol.SatelModule] - Unexpected exception occurred during reading a message
java.io.IOException: Invalid ‘id_s’ value. Got: 13, expected: 11
at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel.readMessage(Ethm1Module.java:202)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel.access$0(Ethm1Module.java:176)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel$1.read(Ethm1Module.java:141)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule.readMessage(SatelModule.java:221)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule.communicationLoop(SatelModule.java:369)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule.access$1(SatelModule.java:331)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule$CommunicationWatchdog$2.run(SatelModule.java:463)[206:org.openhab.binding.satel:1.9.0.b4]
at java.lang.Thread.run(Thread.java:745)[:1.8.0_111]
2016-10-31 12:12:51.272 [INFO ] [.satel.internal.protocol.Ethm1Module] - Closing connection to ETHM-1 module

druciak · October 31, 2016, 1:29pm

Hi,
it seems you have some problems with encryption, at least this is what I can see in the log. I would double check your encryption configuration in DloadX. Also have you tried unencrypted connection? At least to check if the binding is properly working without encryption.

Cheers,
Krzysztof

zacofunny · October 31, 2016, 2:39pm

@druciak tried also with encryption (integration encryption) off and on, checked encryption_key is correct, doesn’t help.

Log with debug on:
2016-10-31 14:36:59.819 [INFO ] [.satel.internal.protocol.Ethm1Module] - Closing connection to ETHM-1 module
2016-10-31 14:36:59.822 [DEBUG] [satel.internal.event.EventDispatcher] - Distributing event: org.openhab.binding.satel.internal.event.ConnectionStatusEvent: connected = false
2016-10-31 14:36:59.824 [DEBUG] [.binding.satel.internal.SatelBinding] - Updating item state: item = AlarmConnection, state = OFF, event = org.openhab.binding.satel.internal.event.ConnectionStatusEvent: connected = false
2016-10-31 14:36:59.829 [DEBUG] [.binding.satel.internal.SatelBinding] - Updating item state: item = AlarmConnSince, state = Uninitialized, event = org.openhab.binding.satel.internal.event.ConnectionStatusEvent: connected = false
2016-10-31 14:36:59.832 [DEBUG] [.satel.internal.protocol.SatelModule] - Communication thread stopped
2016-10-31 14:37:00.758 [DEBUG] [.satel.internal.protocol.SatelModule] - Communication thread started
2016-10-31 14:37:00.760 [INFO ] [.satel.internal.protocol.Ethm1Module] - Connecting to ETHM-1 module at 192.168.11.193:7094
2016-10-31 14:37:00.774 [INFO ] [.satel.internal.protocol.Ethm1Module] - ETHM-1 module connected successfully
2016-10-31 14:37:00.778 [DEBUG] [.satel.internal.protocol.SatelModule] - Sending message: Message: command = 7E, payload =
2016-10-31 14:37:00.780 [DEBUG] [.satel.internal.protocol.Ethm1Module] - Encrypting data: 01 14 00 00 1F 00 FE FE 7E D8 60 FE 0D 00 00 00
2016-10-31 14:37:00.803 [DEBUG] [.satel.internal.protocol.Ethm1Module] - Decrypted data: 42 75 73 79 21 0D 0A 17 66 0C 86 83 BD ED 46 D0
2016-10-31 14:37:00.805 [ERROR] [.satel.internal.protocol.SatelModule] - Unexpected exception occurred during reading a message
java.io.IOException: Invalid ‘id_s’ value. Got: 13, expected: 31
at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel.readMessage(Ethm1Module.java:202)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel.access$0(Ethm1Module.java:176)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel$1.read(Ethm1Module.java:141)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule.readMessage(SatelModule.java:221)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule.communicationLoop(SatelModule.java:369)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule.access$1(SatelModule.java:331)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule$CommunicationWatchdog$2.run(SatelModule.java:463)[206:org.openhab.binding.satel:1.9.0.b4]
at java.lang.Thread.run(Thread.java:745)[:1.8.0_111]
2016-10-31 14:37:00.808 [INFO ] [.satel.internal.protocol.Ethm1Module] - Closing connection to ETHM-1 module
2016-10-31 14:37:00.810 [DEBUG] [satel.internal.event.EventDispatcher] - Distributing event: org.openhab.binding.satel.internal.event.ConnectionStatusEvent: connected = false
2016-10-31 14:37:00.812 [DEBUG] [.binding.satel.internal.SatelBinding] - Updating item state: item = AlarmConnection, state = OFF, event = org.openhab.binding.satel.internal.event.ConnectionStatusEvent: connected = false
2016-10-31 14:37:00.815 [DEBUG] [.binding.satel.internal.SatelBinding] - Updating item state: item = AlarmConnSince, state = Uninitialized, event = org.openhab.binding.satel.internal.event.ConnectionStatusEvent: connected = false
2016-10-31 14:37:00.817 [DEBUG] [.satel.internal.protocol.SatelModule] - Communication thread stopped
2016-10-31 14:37:01.759 [DEBUG] [.satel.internal.protocol.SatelModule] - Communication thread started
2016-10-31 14:37:01.761 [INFO ] [.satel.internal.protocol.Ethm1Module] - Connecting to ETHM-1 module at 192.168.11.193:7094
2016-10-31 14:37:01.775 [INFO ] [.satel.internal.protocol.Ethm1Module] - ETHM-1 module connected successfully
2016-10-31 14:37:01.779 [DEBUG] [.satel.internal.protocol.SatelModule] - Sending message: Message: command = 7E, payload =
2016-10-31 14:37:01.781 [DEBUG] [.satel.internal.protocol.Ethm1Module] - Encrypting data: E8 59 00 00 C9 00 FE FE 7E D8 60 FE 0D 00 00 00
2016-10-31 14:37:01.802 [DEBUG] [.satel.internal.protocol.Ethm1Module] - Decrypted data: 42 75 73 79 21 0D 0A C7 81 75 60 E1 2B 57 6A 9A
2016-10-31 14:37:01.804 [ERROR] [.satel.internal.protocol.SatelModule] - Unexpected exception occurred during reading a message
java.io.IOException: Invalid ‘id_s’ value. Got: 13, expected: -55
at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel.readMessage(Ethm1Module.java:202)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel.access$0(Ethm1Module.java:176)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel$1.read(Ethm1Module.java:141)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule.readMessage(SatelModule.java:221)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule.communicationLoop(SatelModule.java:369)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule.access$1(SatelModule.java:331)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule$CommunicationWatchdog$2.run(SatelModule.java:463)[206:org.openhab.binding.satel:1.9.0.b4]
at java.lang.Thread.run(Thread.java:745)[:1.8.0_111]
2016-10-31 14:37:01.806 [INFO ] [.satel.internal.protocol.Ethm1Module] - Closing connection to ETHM-1 module

druciak · October 31, 2016, 3:05pm

Ok, I’d like to clarify one thing: when you disable encryption for integration protocol in DloadX, you should comment out encryption_key entry in OH2 configuration. Otherwise the binding will be encrypting messages, while ETHM-1 doesn’t know it should decrypt them. Did you do that?

zacofunny · October 31, 2016, 7:38pm

@druciak, I’ve commented encryption_key by # and turned off encryption by DloadX:

zacofunny · October 31, 2016, 7:39pm

The log is:
2016-10-31 19:31:20.618 [DEBUG] [org.openhab.binding.satel ] - BundleEvent STARTING - org.openhab.binding.satel
2016-10-31 19:31:20.625 [DEBUG] [inding.satel.internal.SatelActivator] - Satel binding has been started.
2016-10-31 19:31:20.697 [DEBUG] [org.openhab.binding.satel ] - ServiceEvent REGISTERED - {org.openhab.model.item.binding.BindingConfigReader, org.openhab.binding.satel.SatelBindingProvider}={component.name=org.openhab.binding.satel.provider, component.id=202, service.id=337, service.bundleid=206, service.scope=bundle} - org.openhab.binding.satel
2016-10-31 19:31:20.801 [DEBUG] [org.openhab.binding.satel ] - ServiceEvent REGISTERED - {org.openhab.binding.satel.SatelCommModule, org.osgi.service.event.EventHandler, org.osgi.service.cm.ManagedService}={event.topics=openhab/*, service.pid=org.openhab.satel, component.name=org.openhab.binding.satel, component.id=201, service.id=338, service.bundleid=206, service.scope=bundle} - org.openhab.binding.satel
2016-10-31 19:31:20.905 [INFO ] [b.core.service.AbstractActiveService] - Satel Refresh Service has been started
2016-10-31 19:31:20.907 [DEBUG] [.binding.satel.internal.SatelBinding] - Module not initialized yet, skipping refresh
2016-10-31 19:31:20.937 [DEBUG] [.satel.internal.protocol.SatelModule] - Communication thread started
2016-10-31 19:31:20.942 [INFO ] [.satel.internal.protocol.Ethm1Module] - Connecting to ETHM-1 module at 192.168.11.193:7094
2016-10-31 19:31:20.967 [DEBUG] [org.openhab.binding.satel ] - BundleEvent STARTED - org.openhab.binding.satel
2016-10-31 19:31:20.973 [INFO ] [.satel.internal.protocol.Ethm1Module] - ETHM-1 module connected successfully
2016-10-31 19:31:21.018 [DEBUG] [.satel.internal.protocol.SatelModule] - Sending message: Message: command = 7E, payload =
2016-10-31 19:31:21.022 [DEBUG] [.satel.internal.protocol.Ethm1Module] - Encrypting data: F4 1E 00 00 9F 00 FE FE 7E D8 60 FE 0D 00 00 00
2016-10-31 19:31:21.049 [DEBUG] [.satel.internal.protocol.Ethm1Module] - Decrypted data: 6A 99 1C F4 DF A5 99 17 8B B3 FE E6 3D 09 C2 F9
2016-10-31 19:31:21.051 [ERROR] [.satel.internal.protocol.SatelModule] - Unexpected exception occurred during reading a message
java.io.IOException: Invalid ‘id_s’ value. Got: -91, expected: -97
at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel.readMessage(Ethm1Module.java:202)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel.access$0(Ethm1Module.java:176)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel$1.read(Ethm1Module.java:141)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule.readMessage(SatelModule.java:221)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule.communicationLoop(SatelModule.java:369)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule.access$1(SatelModule.java:331)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule$CommunicationWatchdog$2.run(SatelModule.java:463)[206:org.openhab.binding.satel:1.9.0.b4]
at java.lang.Thread.run(Thread.java:745)[:1.8.0_111]
2016-10-31 19:31:21.075 [INFO ] [.satel.internal.protocol.Ethm1Module] - Closing connection to ETHM-1 module
2016-10-31 19:31:21.079 [DEBUG] [satel.internal.event.EventDispatcher] - Distributing event: org.openhab.binding.satel.internal.event.ConnectionStatusEvent: connected = false
2016-10-31 19:31:21.109 [DEBUG] [.binding.satel.internal.SatelBinding] - Updating item state: item = AlarmConnection, state = OFF, event = org.openhab.binding.satel.internal.event.ConnectionStatusEvent: connected = false
2016-10-31 19:31:21.136 [DEBUG] [.binding.satel.internal.SatelBinding] - Updating item state: item = AlarmConnSince, state = Uninitialized, event = org.openhab.binding.satel.internal.event.ConnectionStatusEvent: connected = false
2016-10-31 19:31:21.165 [DEBUG] [.satel.internal.protocol.SatelModule] - Communication thread stopped
2016-10-31 19:31:21.189 [INFO ] [b.core.service.AbstractActiveService] - XBMC Refresh Service has been started
2016-10-31 19:31:21.904 [DEBUG] [.satel.internal.protocol.SatelModule] - Communication thread started
2016-10-31 19:31:21.906 [INFO ] [.satel.internal.protocol.Ethm1Module] - Connecting to ETHM-1 module at 192.168.11.193:7094
2016-10-31 19:31:21.921 [INFO ] [.satel.internal.protocol.Ethm1Module] - ETHM-1 module connected successfully
2016-10-31 19:31:21.924 [DEBUG] [.satel.internal.protocol.SatelModule] - Sending message: Message: command = 7E, payload =
2016-10-31 19:31:21.928 [DEBUG] [.satel.internal.protocol.Ethm1Module] - Encrypting data: 0F A1 00 00 77 00 FE FE 7E D8 60 FE 0D 00 00 00
2016-10-31 19:31:21.936 [DEBUG] [.satel.internal.protocol.Ethm1Module] - Decrypted data: BA 61 49 84 67 1C 2A B7 C4 F7 FC 61 DD 97 CB E0
2016-10-31 19:31:21.940 [ERROR] [.satel.internal.protocol.SatelModule] - Unexpected exception occurred during reading a message
java.io.IOException: Invalid ‘id_s’ value. Got: 28, expected: 119
at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel.readMessage(Ethm1Module.java:202)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel.access$0(Ethm1Module.java:176)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel$1.read(Ethm1Module.java:141)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule.readMessage(SatelModule.java:221)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule.communicationLoop(SatelModule.java:369)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule.access$1(SatelModule.java:331)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule$CommunicationWatchdog$2.run(SatelModule.java:463)[206:org.openhab.binding.satel:1.9.0.b4]
at java.lang.Thread.run(Thread.java:745)[:1.8.0_111]
2016-10-31 19:31:21.944 [INFO ] [.satel.internal.protocol.Ethm1Module] - Closing connection to ETHM-1 module
2016-10-31 19:31:21.948 [DEBUG] [satel.internal.event.EventDispatcher] - Distributing event: org.openhab.binding.satel.internal.event.ConnectionStatusEvent: connected = false
2016-10-31 19:31:21.951 [DEBUG] [.binding.satel.internal.SatelBinding] - Updating item state: item = AlarmConnection, state = OFF, event = org.openhab.binding.satel.internal.event.ConnectionStatusEvent: connected = false
2016-10-31 19:31:21.957 [DEBUG] [.binding.satel.internal.SatelBinding] - Updating item state: item = AlarmConnSince, state = Uninitialized, event = org.openhab.binding.satel.internal.event.ConnectionStatusEvent: connected = false
2016-10-31 19:31:21.975 [DEBUG] [.satel.internal.protocol.SatelModule] - Communication thread stopped
2016-10-31 19:31:22.823 [INFO ] [eather.internal.common.WeatherConfig] - ProviderConfig[providerName=WUNDERGROUND,apiKey=1220e04af0c1b26f]
2016-10-31 19:31:22.827 [INFO ] [eather.internal.common.WeatherConfig] - LocationConfig[providerName=WUNDERGROUND,language=pl,updateInterval=50,latitude=52.171,longitude=20.812,woeid=514263,locationId=home,name=Parzniew]
2016-10-31 19:31:22.904 [DEBUG] [.satel.internal.protocol.SatelModule] - Communication thread started
2016-10-31 19:31:22.922 [INFO ] [.satel.internal.protocol.Ethm1Module] - Connecting to ETHM-1 module at 192.168.11.193:7094
2016-10-31 19:31:22.944 [INFO ] [.satel.internal.protocol.Ethm1Module] - ETHM-1 module connected successfully
2016-10-31 19:31:22.947 [DEBUG] [.satel.internal.protocol.SatelModule] - Sending message: Message: command = 7E, payload =
2016-10-31 19:31:22.950 [DEBUG] [.satel.internal.protocol.Ethm1Module] - Encrypting data: 5D 63 00 00 F2 00 FE FE 7E D8 60 FE 0D 00 00 00
2016-10-31 19:31:22.975 [DEBUG] [.satel.internal.protocol.Ethm1Module] - Decrypted data: E2 2B B3 92 A4 AE 5E E5 26 D2 9C 75 BB 05 AF 86
2016-10-31 19:31:22.977 [ERROR] [.satel.internal.protocol.SatelModule] - Unexpected exception occurred during reading a message
java.io.IOException: Invalid ‘id_s’ value. Got: -82, expected: -14
at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel.readMessage(Ethm1Module.java:202)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel.access$0(Ethm1Module.java:176)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel$1.read(Ethm1Module.java:141)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule.readMessage(SatelModule.java:221)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule.communicationLoop(SatelModule.java:369)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule.access$1(SatelModule.java:331)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule$CommunicationWatchdog$2.run(SatelModule.java:463)[206:org.openhab.binding.satel:1.9.0.b4]
at java.lang.Thread.run(Thread.java:745)[:1.8.0_111]
2016-10-31 19:31:22.979 [INFO ] [.satel.internal.protocol.Ethm1Module] - Closing connection to ETHM-1 module
2016-10-31 19:31:22.981 [DEBUG] [satel.internal.event.EventDispatcher] - Distributing event: org.openhab.binding.satel.internal.event.ConnectionStatusEvent: connected = false
2016-10-31 19:31:22.983 [DEBUG] [.binding.satel.internal.SatelBinding] - Updating item state: item = AlarmConnection, state = OFF, event = org.openhab.binding.satel.internal.event.ConnectionStatusEvent: connected = false
2016-10-31 19:31:23.091 [DEBUG] [.binding.satel.internal.SatelBinding] - Updating item state: item = AlarmConnSince, state = Uninitialized, event = org.openhab.binding.satel.internal.event.ConnectionStatusEvent: connected = false
2016-10-31 19:31:23.094 [DEBUG] [.satel.internal.protocol.SatelModule] - Communication thread stopped
2016-10-31 19:31:23.518 [INFO ] [panel.internal.HABPanelDashboardTile] - Started HABPanel at /habpanel
2016-10-31 19:31:23.760 [INFO ] [ding.fatekplc.internal.FatekPLCSlave] - New Fatek PLC connectionUri=udp://192.168.1.195?plcId=1
2016-10-31 19:31:23.774 [INFO ] [b.core.service.AbstractActiveService] - Fatek PLC Refresh Service has been started
2016-10-31 19:31:23.774 [INFO ] [ng.fatekplc.internal.FatekPLCBinding] - Configuration has been updated, refresh=100
2016-10-31 19:31:23.895 [DEBUG] [.satel.internal.protocol.SatelModule] - Communication thread started
2016-10-31 19:31:23.899 [INFO ] [.satel.internal.protocol.Ethm1Module] - Connecting to ETHM-1 module at 192.168.11.193:7094
2016-10-31 19:31:23.914 [INFO ] [.satel.internal.protocol.Ethm1Module] - ETHM-1 module connected successfully
2016-10-31 19:31:23.947 [DEBUG] [.satel.internal.protocol.SatelModule] - Sending message: Message: command = 7E, payload =
2016-10-31 19:31:23.950 [DEBUG] [.satel.internal.protocol.Ethm1Module] - Encrypting data: B1 7E 00 00 AE 00 FE FE 7E D8 60 FE 0D 00 00 00
2016-10-31 19:31:23.995 [DEBUG] [.satel.internal.protocol.Ethm1Module] - Decrypted data: 5B 92 10 14 F6 7E 45 79 67 FF 40 AE A8 FB 4C 80
2016-10-31 19:31:23.996 [ERROR] [.satel.internal.protocol.SatelModule] - Unexpected exception occurred during reading a message
java.io.IOException: Invalid ‘id_s’ value. Got: 126, expected: -82
at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel.readMessage(Ethm1Module.java:202)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel.access$0(Ethm1Module.java:176)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel$1.read(Ethm1Module.java:141)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule.readMessage(SatelModule.java:221)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule.communicationLoop(SatelModule.java:369)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule.access$1(SatelModule.java:331)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule$CommunicationWatchdog$2.run(SatelModule.java:463)[206:org.openhab.binding.satel:1.9.0.b4]
at java.lang.Thread.run(Thread.java:745)[:1.8.0_111]
2016-10-31 19:31:23.999 [INFO ] [.satel.internal.protocol.Ethm1Module] - Closing connection to ETHM-1 module
2016-10-31 19:31:24.015 [DEBUG] [satel.internal.event.EventDispatcher] - Distributing event: org.openhab.binding.satel.internal.event.ConnectionStatusEvent: connected = false
2016-10-31 19:31:24.018 [DEBUG] [.binding.satel.internal.SatelBinding] - Updating item state: item = AlarmConnection, state = OFF, event = org.openhab.binding.satel.internal.event.ConnectionStatusEvent: connected = false
2016-10-31 19:31:24.022 [DEBUG] [.binding.satel.internal.SatelBinding] - Updating item state: item = AlarmConnSince, state = Uninitialized, event = org.openhab.binding.satel.internal.event.ConnectionStatusEvent: connected = false
2016-10-31 19:31:24.066 [DEBUG] [.satel.internal.protocol.SatelModule] - Communication thread stopped
2016-10-31 19:31:24.901 [DEBUG] [.satel.internal.protocol.SatelModule] - Communication thread started
2016-10-31 19:31:24.920 [INFO ] [.satel.internal.protocol.Ethm1Module] - Connecting to ETHM-1 module at 192.168.11.193:7094
2016-10-31 19:31:24.938 [INFO ] [.satel.internal.protocol.Ethm1Module] - ETHM-1 module connected successfully
2016-10-31 19:31:24.945 [DEBUG] [.satel.internal.protocol.SatelModule] - Sending message: Message: command = 7E, payload =
2016-10-31 19:31:24.950 [DEBUG] [.satel.internal.protocol.Ethm1Module] - Encrypting data: E7 F2 00 00 30 00 FE FE 7E D8 60 FE 0D 00 00 00
2016-10-31 19:31:24.974 [DEBUG] [.satel.internal.protocol.Ethm1Module] - Decrypted data: E2 2B B3 92 A4 AE 5E E5 26 D2 9C 75 BB 05 AF 86
2016-10-31 19:31:24.978 [ERROR] [.satel.internal.protocol.SatelModule] - Unexpected exception occurred during reading a message
java.io.IOException: Invalid ‘id_s’ value. Got: -82, expected: 48
at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel.readMessage(Ethm1Module.java:202)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel.access$0(Ethm1Module.java:176)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel$1.read(Ethm1Module.java:141)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule.readMessage(SatelModule.java:221)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule.communicationLoop(SatelModule.java:369)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule.access$1(SatelModule.java:331)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule$CommunicationWatchdog$2.run(SatelModule.java:463)[206:org.openhab.binding.satel:1.9.0.b4]
at java.lang.Thread.run(Thread.java:745)[:1.8.0_111]
2016-10-31 19:31:24.995 [INFO ] [.satel.internal.protocol.Ethm1Module] - Closing connection to ETHM-1 module
2016-10-31 19:31:25.000 [DEBUG] [satel.internal.event.EventDispatcher] - Distributing event: org.openhab.binding.satel.internal.event.ConnectionStatusEvent: connected = false
2016-10-31 19:31:25.005 [DEBUG] [.binding.satel.internal.SatelBinding] - Updating item state: item = AlarmConnection, state = OFF, event = org.openhab.binding.satel.internal.event.ConnectionStatusEvent: connected = false
2016-10-31 19:31:25.014 [DEBUG] [.binding.satel.internal.SatelBinding] - Updating item state: item = AlarmConnSince, state = Uninitialized, event = org.openhab.binding.satel.internal.event.ConnectionStatusEvent: connected = false
2016-10-31 19:31:25.034 [DEBUG] [.satel.internal.protocol.SatelModule] - Communication thread stopped
2016-10-31 19:31:25.843 [INFO ] [o.myopenhab.internal.MyOpenHABClient] - Connected to my.openHAB service (UUID = 608517d5-b5d4-4ce9-a340-5852fd246457, base URL = http://localhost:8080)
2016-10-31 19:31:25.908 [DEBUG] [.binding.satel.internal.SatelBinding] - Module not initialized yet, skipping refresh
2016-10-31 19:31:25.936 [DEBUG] [.satel.internal.protocol.SatelModule] - Communication thread started
2016-10-31 19:31:25.974 [INFO ] [.satel.internal.protocol.Ethm1Module] - Connecting to ETHM-1 module at 192.168.11.193:7094
2016-10-31 19:31:26.008 [INFO ] [.satel.internal.protocol.Ethm1Module] - ETHM-1 module connected successfully
2016-10-31 19:31:26.039 [DEBUG] [.satel.internal.protocol.SatelModule] - Sending message: Message: command = 7E, payload =
2016-10-31 19:31:26.052 [DEBUG] [.satel.internal.protocol.Ethm1Module] - Encrypting data: 04 F4 00 00 06 00 FE FE 7E D8 60 FE 0D 00 00 00
2016-10-31 19:31:26.083 [DEBUG] [.satel.internal.protocol.Ethm1Module] - Decrypted data: 33 CE FE F8 C8 54 1E F5 AD 55 6F C0 FF 1D 8F 98
2016-10-31 19:31:26.115 [ERROR] [.satel.internal.protocol.SatelModule] - Unexpected exception occurred during reading a message
java.io.IOException: Invalid ‘id_s’ value. Got: 84, expected: 6
at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel.readMessage(Ethm1Module.java:202)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel.access$0(Ethm1Module.java:176)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel$1.read(Ethm1Module.java:141)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule.readMessage(SatelModule.java:221)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule.communicationLoop(SatelModule.java:369)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule.access$1(SatelModule.java:331)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule$CommunicationWatchdog$2.run(SatelModule.java:463)[206:org.openhab.binding.satel:1.9.0.b4]
at java.lang.Thread.run(Thread.java:745)[:1.8.0_111]
2016-10-31 19:31:26.140 [INFO ] [.satel.internal.protocol.Ethm1Module] - Closing connection to ETHM-1 module
2016-10-31 19:31:26.146 [DEBUG] [satel.internal.event.EventDispatcher] - Distributing event: org.openhab.binding.satel.internal.event.ConnectionStatusEvent: connected = false
2016-10-31 19:31:26.155 [INFO ] [ternal.scheduler.WeatherJobScheduler] - Starting and scheduling weatherJob-home with interval of 50 minutes
2016-10-31 19:31:26.156 [DEBUG] [.binding.satel.internal.SatelBinding] - Updating item state: item = AlarmConnection, state = OFF, event = org.openhab.binding.satel.internal.event.ConnectionStatusEvent: connected = false
2016-10-31 19:31:26.174 [DEBUG] [.binding.satel.internal.SatelBinding] - Updating item state: item = AlarmConnSince, state = Uninitialized, event = org.openhab.binding.satel.internal.event.ConnectionStatusEvent: connected = false
2016-10-31 19:31:26.241 [DEBUG] [.satel.internal.protocol.SatelModule] - Communication thread stopped
2016-10-31 19:31:26.928 [DEBUG] [.satel.internal.protocol.SatelModule] - Communication thread started
2016-10-31 19:31:26.942 [INFO ] [.satel.internal.protocol.Ethm1Module] - Connecting to ETHM-1 module at 192.168.11.193:7094
2016-10-31 19:31:26.959 [INFO ] [.satel.internal.protocol.Ethm1Module] - ETHM-1 module connected successfully
2016-10-31 19:31:26.970 [DEBUG] [.satel.internal.protocol.SatelModule] - Sending message: Message: command = 7E, payload =
2016-10-31 19:31:26.986 [DEBUG] [.satel.internal.protocol.Ethm1Module] - Encrypting data: EB 7B 00 00 D8 00 FE FE 7E D8 60 FE 0D 00 00 00
2016-10-31 19:31:27.020 [DEBUG] [.satel.internal.protocol.Ethm1Module] - Decrypted data: C9 F3 3A 97 7A 89 10 47 23 BD 01 BA C6 72 7C EE
2016-10-31 19:31:27.056 [ERROR] [.satel.internal.protocol.SatelModule] - Unexpected exception occurred during reading a message
java.io.IOException: Invalid ‘id_s’ value. Got: -119, expected: -40
at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel.readMessage(Ethm1Module.java:202)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel.access$0(Ethm1Module.java:176)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel$1.read(Ethm1Module.java:141)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule.readMessage(SatelModule.java:221)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule.communicationLoop(SatelModule.java:369)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule.access$1(SatelModule.java:331)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule$CommunicationWatchdog$2.run(SatelModule.java:463)[206:org.openhab.binding.satel:1.9.0.b4]
at java.lang.Thread.run(Thread.java:745)[:1.8.0_111]
2016-10-31 19:31:27.061 [INFO ] [.satel.internal.protocol.Ethm1Module] - Closing connection to ETHM-1 module
2016-10-31 19:31:27.075 [DEBUG] [satel.internal.event.EventDispatcher] - Distributing event: org.openhab.binding.satel.internal.event.ConnectionStatusEvent: connected = false
2016-10-31 19:31:27.080 [DEBUG] [.binding.satel.internal.SatelBinding] - Updating item state: item = AlarmConnection, state = OFF, event = org.openhab.binding.satel.internal.event.ConnectionStatusEvent: connected = false
2016-10-31 19:31:27.120 [DEBUG] [.binding.satel.internal.SatelBinding] - Updating item state: item = AlarmConnSince, state = Uninitialized, event = org.openhab.binding.satel.internal.event.ConnectionStatusEvent: connected = false
2016-10-31 19:31:27.148 [DEBUG] [.satel.internal.protocol.SatelModule] - Communication thread stopped
2016-10-31 19:31:27.934 [DEBUG] [.satel.internal.protocol.SatelModule] - Communication thread started
2016-10-31 19:31:27.940 [INFO ] [.satel.internal.protocol.Ethm1Module] - Connecting to ETHM-1 module at 192.168.11.193:7094
2016-10-31 19:31:27.961 [INFO ] [.satel.internal.protocol.Ethm1Module] - ETHM-1 module connected successfully
2016-10-31 19:31:27.971 [DEBUG] [.satel.internal.protocol.SatelModule] - Sending message: Message: command = 7E, payload =
2016-10-31 19:31:27.981 [DEBUG] [.satel.internal.protocol.Ethm1Module] - Encrypting data: 5B A7 00 00 B7 00 FE FE 7E D8 60 FE 0D 00 00 00
2016-10-31 19:31:28.009 [DEBUG] [.satel.internal.protocol.Ethm1Module] - Decrypted data: 6F 53 A9 C9 C2 B0 F3 51 A2 F3 6D 57 77 67 3D F1
2016-10-31 19:31:28.017 [ERROR] [.satel.internal.protocol.SatelModule] - Unexpected exception occurred during reading a message
java.io.IOException: Invalid ‘id_s’ value. Got: -80, expected: -73
at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel.readMessage(Ethm1Module.java:202)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel.access$0(Ethm1Module.java:176)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel$1.read(Ethm1Module.java:141)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule.readMessage(SatelModule.java:221)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule.communicationLoop(SatelModule.java:369)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule.access$1(SatelModule.java:331)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule$CommunicationWatchdog$2.run(SatelModule.java:463)[206:org.openhab.binding.satel:1.9.0.b4]
at java.lang.Thread.run(Thread.java:745)[:1.8.0_111]
2016-10-31 19:31:28.025 [INFO ] [.satel.internal.protocol.Ethm1Module] - Closing connection to ETHM-1 module

zacofunny · October 31, 2016, 7:39pm

2016-10-31 19:31:28.032 [DEBUG] [satel.internal.event.EventDispatcher] - Distributing event: org.openhab.binding.satel.internal.event.ConnectionStatusEvent: connected = false
2016-10-31 19:31:28.037 [DEBUG] [.binding.satel.internal.SatelBinding] - Updating item state: item = AlarmConnection, state = OFF, event = org.openhab.binding.satel.internal.event.ConnectionStatusEvent: connected = false
2016-10-31 19:31:28.052 [DEBUG] [.binding.satel.internal.SatelBinding] - Updating item state: item = AlarmConnSince, state = Uninitialized, event = org.openhab.binding.satel.internal.event.ConnectionStatusEvent: connected = false
2016-10-31 19:31:28.064 [DEBUG] [.satel.internal.protocol.SatelModule] - Communication thread stopped
2016-10-31 19:31:28.934 [DEBUG] [.satel.internal.protocol.SatelModule] - Communication thread started
2016-10-31 19:31:28.950 [INFO ] [.satel.internal.protocol.Ethm1Module] - Connecting to ETHM-1 module at 192.168.11.193:7094
2016-10-31 19:31:28.967 [INFO ] [.satel.internal.protocol.Ethm1Module] - ETHM-1 module connected successfully
2016-10-31 19:31:28.977 [DEBUG] [.satel.internal.protocol.SatelModule] - Sending message: Message: command = 7E, payload =
2016-10-31 19:31:28.983 [DEBUG] [.satel.internal.protocol.Ethm1Module] - Encrypting data: F7 7C 00 00 2E 00 FE FE 7E D8 60 FE 0D 00 00 00
2016-10-31 19:31:28.992 [DEBUG] [.satel.internal.protocol.Ethm1Module] - Decrypted data: B7 ED C9 3A BD 64 BA 36 E7 D2 35 6E 3C D5 40 04
2016-10-31 19:31:28.998 [ERROR] [.satel.internal.protocol.SatelModule] - Unexpected exception occurred during reading a message
java.io.IOException: Invalid ‘id_s’ value. Got: 100, expected: 46
at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel.readMessage(Ethm1Module.java:202)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel.access$0(Ethm1Module.java:176)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel$1.read(Ethm1Module.java:141)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule.readMessage(SatelModule.java:221)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule.communicationLoop(SatelModule.java:369)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule.access$1(SatelModule.java:331)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule$CommunicationWatchdog$2.run(SatelModule.java:463)[206:org.openhab.binding.satel:1.9.0.b4]
at java.lang.Thread.run(Thread.java:745)[:1.8.0_111]
2016-10-31 19:31:29.005 [INFO ] [.satel.internal.protocol.Ethm1Module] - Closing connection to ETHM-1 module
2016-10-31 19:31:29.010 [DEBUG] [satel.internal.event.EventDispatcher] - Distributing event: org.openhab.binding.satel.internal.event.ConnectionStatusEvent: connected = false
2016-10-31 19:31:29.015 [DEBUG] [.binding.satel.internal.SatelBinding] - Updating item state: item = AlarmConnection, state = OFF, event = org.openhab.binding.satel.internal.event.ConnectionStatusEvent: connected = false
2016-10-31 19:31:29.031 [DEBUG] [.binding.satel.internal.SatelBinding] - Updating item state: item = AlarmConnSince, state = Uninitialized, event = org.openhab.binding.satel.internal.event.ConnectionStatusEvent: connected = false
2016-10-31 19:31:29.039 [DEBUG] [.satel.internal.protocol.SatelModule] - Communication thread stopped
2016-10-31 19:31:29.934 [DEBUG] [.satel.internal.protocol.SatelModule] - Communication thread started
2016-10-31 19:31:29.938 [INFO ] [.satel.internal.protocol.Ethm1Module] - Connecting to ETHM-1 module at 192.168.11.193:7094
2016-10-31 19:31:29.974 [INFO ] [.satel.internal.protocol.Ethm1Module] - ETHM-1 module connected successfully
2016-10-31 19:31:29.981 [DEBUG] [.satel.internal.protocol.SatelModule] - Sending message: Message: command = 7E, payload =
2016-10-31 19:31:30.007 [DEBUG] [.satel.internal.protocol.Ethm1Module] - Encrypting data: 95 7F 00 00 43 00 FE FE 7E D8 60 FE 0D 00 00 00
2016-10-31 19:31:30.911 [DEBUG] [.binding.satel.internal.SatelBinding] - Module not initialized yet, skipping refresh
2016-10-31 19:31:35.528 [WARN ] [mon.registry.AbstractManagedProvider] - Could not update element with key zwave:serial_zstick:board in ManagedThingProvider, because it does not exists.
2016-10-31 19:31:35.535 [WARN ] [.core.thing.binding.BaseThingHandler] - Error while applying configuration changes: ‘IllegalStateException: Could not update thing zwave:serial_zstick:board. Most likely because it is read-only.’ - reverting configuration changes on thing ‘zwave:serial_zstick:board’.
2016-10-31 19:31:35.557 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Connecting to serial port '/dev/ttyS2’
2016-10-31 19:31:35.875 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Stopped ZWave serial handler
2016-10-31 19:31:35.879 [WARN ] [mon.registry.AbstractManagedProvider] - Could not update element with key zwave:serial_zstick:board in ManagedThingProvider, because it does not exists.
2016-10-31 19:31:35.881 [WARN ] [.core.thing.binding.BaseThingHandler] - Error while applying configuration changes: ‘IllegalStateException: Could not update thing zwave:serial_zstick:board. Most likely because it is read-only.’ - reverting configuration changes on thing ‘zwave:serial_zstick:board’.
2016-10-31 19:31:35.888 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Connecting to serial port '/dev/ttyS2’
2016-10-31 19:31:35.915 [DEBUG] [.binding.satel.internal.SatelBinding] - Module not initialized yet, skipping refresh
2016-10-31 19:31:35.937 [ERROR] [.satel.internal.protocol.SatelModule] - Send/receive timeout, disconnecting module.
2016-10-31 19:31:36.064 [INFO ] [.satel.internal.protocol.Ethm1Module] - Closing connection to ETHM-1 module
2016-10-31 19:31:36.066 [DEBUG] [satel.internal.event.EventDispatcher] - Distributing event: org.openhab.binding.satel.internal.event.ConnectionStatusEvent: connected = false
2016-10-31 19:31:36.068 [DEBUG] [.binding.satel.internal.SatelBinding] - Updating item state: item = AlarmConnection, state = OFF, event = org.openhab.binding.satel.internal.event.ConnectionStatusEvent: connected = false
2016-10-31 19:31:36.071 [DEBUG] [.binding.satel.internal.SatelBinding] - Updating item state: item = AlarmConnSince, state = Uninitialized, event = org.openhab.binding.satel.internal.event.ConnectionStatusEvent: connected = false
2016-10-31 19:31:36.085 [DEBUG] [.satel.internal.protocol.SatelModule] - Communication thread stopped
2016-10-31 19:31:36.937 [DEBUG] [.satel.internal.protocol.SatelModule] - Communication thread started
2016-10-31 19:31:36.940 [INFO ] [.satel.internal.protocol.Ethm1Module] - Connecting to ETHM-1 module at 192.168.11.193:7094
2016-10-31 19:31:36.975 [INFO ] [.satel.internal.protocol.Ethm1Module] - ETHM-1 module connected successfully
2016-10-31 19:31:36.980 [DEBUG] [.satel.internal.protocol.SatelModule] - Sending message: Message: command = 7E, payload =
2016-10-31 19:31:36.983 [DEBUG] [.satel.internal.protocol.Ethm1Module] - Encrypting data: CC 3A 00 00 D9 00 FE FE 7E D8 60 FE 0D 00 00 00
2016-10-31 19:31:40.917 [DEBUG] [.binding.satel.internal.SatelBinding] - Module not initialized yet, skipping refresh
2016-10-31 19:31:42.512 [ERROR] [.script.engine.ScriptExecutionThread] - Rule ‘DoorLockTimer’: An error occured during the script execution: The name ‘DoorLockTimer’ cannot be resolved to an item or type.
2016-10-31 19:31:42.939 [ERROR] [.satel.internal.protocol.SatelModule] - Send/receive timeout, disconnecting module.
2016-10-31 19:31:43.040 [INFO ] [.satel.internal.protocol.Ethm1Module] - Closing connection to ETHM-1 module
2016-10-31 19:31:43.042 [DEBUG] [satel.internal.event.EventDispatcher] - Distributing event: org.openhab.binding.satel.internal.event.ConnectionStatusEvent: connected = false
2016-10-31 19:31:43.044 [DEBUG] [.binding.satel.internal.SatelBinding] - Updating item state: item = AlarmConnection, state = OFF, event = org.openhab.binding.satel.internal.event.ConnectionStatusEvent: connected = false
2016-10-31 19:31:43.046 [DEBUG] [.binding.satel.internal.SatelBinding] - Updating item state: item = AlarmConnSince, state = Uninitialized, event = org.openhab.binding.satel.internal.event.ConnectionStatusEvent: connected = false
2016-10-31 19:31:43.048 [DEBUG] [.satel.internal.protocol.SatelModule] - Communication thread stopped
2016-10-31 19:31:43.939 [DEBUG] [.satel.internal.protocol.SatelModule] - Communication thread started
2016-10-31 19:31:43.943 [INFO ] [.satel.internal.protocol.Ethm1Module] - Connecting to ETHM-1 module at 192.168.11.193:7094
2016-10-31 19:31:43.960 [INFO ] [.satel.internal.protocol.Ethm1Module] - ETHM-1 module connected successfully
2016-10-31 19:31:43.966 [DEBUG] [.satel.internal.protocol.SatelModule] - Sending message: Message: command = 7E, payload =
2016-10-31 19:31:43.972 [DEBUG] [.satel.internal.protocol.Ethm1Module] - Encrypting data: 18 B8 00 00 61 00 FE FE 7E D8 60 FE 0D 00 00 00
2016-10-31 19:31:46.017 [DEBUG] [.binding.satel.internal.SatelBinding] - Module not initialized yet, skipping refresh
2016-10-31 19:31:49.018 [ERROR] [.satel.internal.protocol.SatelModule] - Send/receive timeout, disconnecting module.
2016-10-31 19:31:49.119 [INFO ] [.satel.internal.protocol.Ethm1Module] - Closing connection to ETHM-1 module
2016-10-31 19:31:49.121 [DEBUG] [satel.internal.event.EventDispatcher] - Distributing event: org.openhab.binding.satel.internal.event.ConnectionStatusEvent: connected = false
2016-10-31 19:31:49.123 [DEBUG] [.binding.satel.internal.SatelBinding] - Updating item state: item = AlarmConnection, state = OFF, event = org.openhab.binding.satel.internal.event.ConnectionStatusEvent: connected = false
2016-10-31 19:31:49.127 [DEBUG] [.binding.satel.internal.SatelBinding] - Updating item state: item = AlarmConnSince, state = Uninitialized, event = org.openhab.binding.satel.internal.event.ConnectionStatusEvent: connected = false
2016-10-31 19:31:49.131 [DEBUG] [.satel.internal.protocol.SatelModule] - Communication thread stopped
2016-10-31 19:31:50.018 [DEBUG] [.satel.internal.protocol.SatelModule] - Communication thread started
2016-10-31 19:31:50.019 [INFO ] [.satel.internal.protocol.Ethm1Module] - Connecting to ETHM-1 module at 192.168.11.193:7094
2016-10-31 19:31:50.035 [INFO ] [.satel.internal.protocol.Ethm1Module] - ETHM-1 module connected successfully
2016-10-31 19:31:50.038 [DEBUG] [.satel.internal.protocol.SatelModule] - Sending message: Message: command = 7E, payload =
2016-10-31 19:31:50.040 [DEBUG] [.satel.internal.protocol.Ethm1Module] - Encrypting data: A0 CF 00 00 58 00 FE FE 7E D8 60 FE 0D 00 00 00
2016-10-31 19:31:50.048 [DEBUG] [.satel.internal.protocol.Ethm1Module] - Decrypted data: AE A8 DC F0 40 32 11 66 BA E0 C1 AB E8 3F CB EA
2016-10-31 19:31:50.051 [ERROR] [.satel.internal.protocol.SatelModule] - Unexpected exception occurred during reading a message
java.io.IOException: Invalid ‘id_s’ value. Got: 50, expected: 88
at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel.readMessage(Ethm1Module.java:202)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel.access$0(Ethm1Module.java:176)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel$1.read(Ethm1Module.java:141)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule.readMessage(SatelModule.java:221)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule.communicationLoop(SatelModule.java:369)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule.access$1(SatelModule.java:331)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule$CommunicationWatchdog$2.run(SatelModule.java:463)[206:org.openhab.binding.satel:1.9.0.b4]
at java.lang.Thread.run(Thread.java:745)[:1.8.0_111]
2016-10-31 19:31:50.055 [INFO ] [.satel.internal.protocol.Ethm1Module] - Closing connection to ETHM-1 module
2016-10-31 19:31:50.058 [DEBUG] [satel.internal.event.EventDispatcher] - Distributing event: org.openhab.binding.satel.internal.event.ConnectionStatusEvent: connected = false
2016-10-31 19:31:50.061 [DEBUG] [.binding.satel.internal.SatelBinding] - Updating item state: item = AlarmConnection, state = OFF, event = org.openhab.binding.satel.internal.event.ConnectionStatusEvent: connected = false
2016-10-31 19:31:50.066 [DEBUG] [.binding.satel.internal.SatelBinding] - Updating item state: item = AlarmConnSince, state = Uninitialized, event = org.openhab.binding.satel.internal.event.ConnectionStatusEvent: connected = false
2016-10-31 19:31:50.071 [DEBUG] [.satel.internal.protocol.SatelModule] - Communication thread stopped
2016-10-31 19:31:51.018 [DEBUG] [.satel.internal.protocol.SatelModule] - Communication thread started
2016-10-31 19:31:51.019 [DEBUG] [.binding.satel.internal.SatelBinding] - Module not initialized yet, skipping refresh
2016-10-31 19:31:51.023 [INFO ] [.satel.internal.protocol.Ethm1Module] - Connecting to ETHM-1 module at 192.168.11.193:7094
2016-10-31 19:31:51.043 [INFO ] [.satel.internal.protocol.Ethm1Module] - ETHM-1 module connected successfully
2016-10-31 19:31:51.048 [DEBUG] [.satel.internal.protocol.SatelModule] - Sending message: Message: command = 7E, payload =
2016-10-31 19:31:51.052 [DEBUG] [.satel.internal.protocol.Ethm1Module] - Encrypting data: 87 8F 00 00 EE 00 FE FE 7E D8 60 FE 0D 00 00 00
2016-10-31 19:31:51.062 [DEBUG] [.satel.internal.protocol.Ethm1Module] - Decrypted data: 84 79 43 6E 37 D3 F0 07 F2 F4 25 10 01 17 98 34
2016-10-31 19:31:51.067 [ERROR] [.satel.internal.protocol.SatelModule] - Unexpected exception occurred during reading a message
java.io.IOException: Invalid ‘id_s’ value. Got: -45, expected: -18
at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel.readMessage(Ethm1Module.java:202)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel.access$0(Ethm1Module.java:176)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel$1.read(Ethm1Module.java:141)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule.readMessage(SatelModule.java:221)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule.communicationLoop(SatelModule.java:369)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule.access$1(SatelModule.java:331)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule$CommunicationWatchdog$2.run(SatelModule.java:463)[206:org.openhab.binding.satel:1.9.0.b4]
at java.lang.Thread.run(Thread.java:745)[:1.8.0_111]
2016-10-31 19:31:51.074 [INFO ] [.satel.internal.protocol.Ethm1Module] - Closing connection to ETHM-1 module
2016-10-31 19:31:51.076 [DEBUG] [satel.internal.event.EventDispatcher] - Distributing event: org.openhab.binding.satel.internal.event.ConnectionStatusEvent: connected = false
2016-10-31 19:31:51.079 [DEBUG] [.binding.satel.internal.SatelBinding] - Updating item state: item = AlarmConnection, state = OFF, event = org.openhab.binding.satel.internal.event.ConnectionStatusEvent: connected = false
2016-10-31 19:31:51.083 [DEBUG] [.binding.satel.internal.SatelBinding] - Updating item state: item = AlarmConnSince, state = Uninitialized, event = org.openhab.binding.satel.internal.event.ConnectionStatusEvent: connected = false
2016-10-31 19:31:51.086 [DEBUG] [.satel.internal.protocol.SatelModule] - Communication thread stopped
2016-10-31 19:31:52.018 [DEBUG] [.satel.internal.protocol.SatelModule] - Communication thread started
2016-10-31 19:31:52.020 [INFO ] [.satel.internal.protocol.Ethm1Module] - Connecting to ETHM-1 module at 192.168.11.193:7094
2016-10-31 19:31:52.036 [INFO ] [.satel.internal.protocol.Ethm1Module] - ETHM-1 module connected successfully
2016-10-31 19:31:52.040 [DEBUG] [.satel.internal.protocol.SatelModule] - Sending message: Message: command = 7E, payload =
2016-10-31 19:31:52.043 [DEBUG] [.satel.internal.protocol.Ethm1Module] - Encrypting data: 64 2A 00 00 EB 00 FE FE 7E D8 60 FE 0D 00 00 00
2016-10-31 19:31:52.051 [DEBUG] [.satel.internal.protocol.Ethm1Module] - Decrypted data: 32 FC B7 1F 5F 35 81 20 D1 1E 39 46 BA B7 49 CB
2016-10-31 19:31:52.053 [ERROR] [.satel.internal.protocol.SatelModule] - Unexpected exception occurred during reading a message
java.io.IOException: Invalid ‘id_s’ value. Got: 53, expected: -21
at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel.readMessage(Ethm1Module.java:202)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel.access$0(Ethm1Module.java:176)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel$1.read(Ethm1Module.java:141)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule.readMessage(SatelModule.java:221)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule.communicationLoop(SatelModule.java:369)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule.access$1(SatelModule.java:331)[206:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule$CommunicationWatchdog$2.run(SatelModule.java:463)[206:org.openhab.binding.satel:1.9.0.b4]
at java.lang.Thread.run(Thread.java:745)[:1.8.0_111]
2016-10-31 19:31:52.057 [INFO ] [.satel.internal.protocol.Ethm1Module] - Closing connection to ETHM-1 module

druciak · November 1, 2016, 7:28am

As you can see in the logs, the binding is still encrypting data, so apparently you have not commented out encryption_key in the right place. Let’s focus on unencrypted communication, and when we solve it, then we will try to fix encrypted one. Please doble check if your config changes are done in the proper file/directory. Maybe you have more than one satel configuration files?

druciak · November 1, 2016, 7:30am

Also I assume you do OH restart after every configuration change?

zacofunny · November 1, 2016, 8:41am

I did restarted it plenty of times, I’ve also commented the correct line in conf file, so it’s kind of funny for me also what is happening. The binding was installed as extension through paper UI is there any other configuration file somewhere?

druciak · November 1, 2016, 9:02am

I am not OH2 expert, but AFAIK OH2 imports config files into its own database. Not sure what happens when they are all imported, whether or not it checks for modifications. You could remove this internal DB and check then. It is located in userdata/mapdb (at least it was some time ago, I don’t have most recent OH2 version).

druciak · November 1, 2016, 9:24am

Instead removing the database, you clould also try adding encryption_key with empty value. I think it imports values from the file, but if something is missing it leaves the previous value.

zacofunny · November 1, 2016, 6:03pm

Ok, I’ve reinstalled everything ( I used Kai’s latest build for Pine64). I’ve configured it without encryption_key enabled and I’ve got in log:
2016-11-01 17:17:53.147 [INFO ] [.satel.internal.protocol.Ethm1Module] - Connecting to ETHM-1 module at 192.168.1.191:7094
2016-11-01 17:17:53.163 [INFO ] [.satel.internal.protocol.Ethm1Module] - ETHM-1 module connected successfully
2016-11-01 17:17:53.179 [INFO ] [.satel.internal.protocol.Ethm1Module] - Closing connection to ETHM-1 module
2016-11-01 17:17:54.180 [INFO ] [.satel.internal.protocol.Ethm1Module] - Connecting to ETHM-1 module at 192.168.1.191:7094
2016-11-01 17:17:54.198 [INFO ] [.satel.internal.protocol.Ethm1Module] - ETHM-1 module connected successfully
2016-11-01 17:17:54.211 [INFO ] [.satel.internal.protocol.Ethm1Module] - Closing connection to ETHM-1 module
2016-11-01 17:17:55.173 [INFO ] [.satel.internal.protocol.Ethm1Module] - Connecting to ETHM-1 module at 192.168.1.191:7094
2016-11-01 17:17:55.187 [INFO ] [.satel.internal.protocol.Ethm1Module] - ETHM-1 module connected successfully
2016-11-01 17:17:55.203 [INFO ] [.satel.internal.protocol.Ethm1Module] - Closing connection to ETHM-1 module
2016-11-01 17:17:55.296 [INFO ] [ternal.scheduler.WeatherJobScheduler] - Starting and scheduling weatherJob-home with interval of 50 minutes
2016-11-01 17:17:56.179 [INFO ] [.satel.internal.protocol.Ethm1Module] - Connecting to ETHM-1 module at 192.168.1.191:7094
2016-11-01 17:17:56.209 [INFO ] [.satel.internal.protocol.Ethm1Module] - ETHM-1 module connected successfully
2016-11-01 17:17:56.222 [INFO ] [.satel.internal.protocol.Ethm1Module] - Closing connection to ETHM-1 module
2016-11-01 17:17:57.174 [INFO ] [.satel.internal.protocol.Ethm1Module] - Connecting to ETHM-1 module at 192.168.1.191:7094
2016-11-01 17:17:57.198 [INFO ] [.satel.internal.protocol.Ethm1Module] - ETHM-1 module connected successfully
2016-11-01 17:17:57.209 [INFO ] [.satel.internal.protocol.Ethm1Module] - Closing connection to ETHM-1 module
2016-11-01 17:17:58.174 [INFO ] [.satel.internal.protocol.Ethm1Module] - Connecting to ETHM-1 module at 192.168.1.191:7094
2016-11-01 17:17:58.195 [INFO ] [.satel.internal.protocol.Ethm1Module] - ETHM-1 module connected successfully
2016-11-01 17:17:58.209 [INFO ] [.satel.internal.protocol.Ethm1Module] - Closing connection to ETHM-1 module
2016-11-01 17:17:59.174 [INFO ] [.satel.internal.protocol.Ethm1Module] - Connecting to ETHM-1 module at 192.168.1.191:7094
2016-11-01 17:17:59.190 [INFO ] [.satel.internal.protocol.Ethm1Module] - ETHM-1 module connected successfully

later on I’ve got error:
2016-11-01 17:20:37.324 [ERROR] [nding.satel.command.SatelCommandBase] - Requesting user code not found

Is that ok?
After all I’ve turned on encryption I was stared to get the same issues as before

My java -version says:

java version "1.8.0_111"
Java™ SE Runtime Environment (build 1.8.0_111-b14)
Java HotSpot™ 64-Bit Server VM (build 25.111-b14, mixed mode)

I’ve also installed oracle-java8-unlimited-jce-policy. Before I installed it I was getting:

2016-11-01 17:42:03.222 [INFO ] [.satel.internal.protocol.Ethm1Module] - Connecting to ETHM-1 module at 192.168.1.191:7094
2016-11-01 17:42:03.236 [INFO ] [.satel.internal.protocol.Ethm1Module] - ETHM-1 module connected successfully
2016-11-01 17:42:03.238 [ERROR] [.satel.internal.protocol.Ethm1Module] - IO error occurred during connecting socket
java.io.IOException: General encryption failure
at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel.(Ethm1Module.java:127)[210:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.Ethm1Module.connect(Ethm1Module.java:73)[210:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule.communicationLoop(SatelModule.java:342)[210:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule.access$1(SatelModule.java:331)[210:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule$CommunicationWatchdog$2.run(SatelModule.java:463)[210:org.openhab.binding.satel:1.9.0.b4]
at java.lang.Thread.run(Thread.java:745)[:1.8.0_111]
Caused by: java.security.GeneralSecurityException: JCE does not support 192-bit keys
at org.openhab.binding.satel.internal.protocol.EncryptionHelper.(EncryptionHelper.java:38)[210:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel.(Ethm1Module.java:125)[210:org.openhab.binding.satel:1.9.0.b4]
… 5 more

However this time when I commented encryption_key I’ve got again:

2016-11-01 17:56:53.967 [INFO ] [.satel.internal.protocol.Ethm1Module] - Closing connection to ETHM-1 module
2016-11-01 17:56:54.933 [INFO ] [.satel.internal.protocol.Ethm1Module] - Connecting to ETHM-1 module at 192.168.1.191:7094
2016-11-01 17:56:54.959 [INFO ] [.satel.internal.protocol.Ethm1Module] - ETHM-1 module connected successfully
2016-11-01 17:57:00.932 [ERROR] [.satel.internal.protocol.SatelModule] - Send/receive timeout, disconnecting module.
2016-11-01 17:57:01.034 [INFO ] [.satel.internal.protocol.Ethm1Module] - Closing connection to ETHM-1 module
2016-11-01 17:57:01.934 [INFO ] [.satel.internal.protocol.Ethm1Module] - Connecting to ETHM-1 module at 192.168.1.191:7094
2016-11-01 17:57:01.955 [INFO ] [.satel.internal.protocol.Ethm1Module] - ETHM-1 module connected successfully
2016-11-01 17:57:07.932 [ERROR] [.satel.internal.protocol.SatelModule] - Send/receive timeout, disconnecting module.
2016-11-01 17:57:08.035 [INFO ] [.satel.internal.protocol.Ethm1Module] - Closing connection to ETHM-1 module
2016-11-01 17:57:08.933 [INFO ] [.satel.internal.protocol.Ethm1Module] - Connecting to ETHM-1 module at 192.168.1.191:7094
2016-11-01 17:57:08.948 [INFO ] [.satel.internal.protocol.Ethm1Module] - ETHM-1 module connected successfully
2016-11-01 17:57:14.933 [ERROR] [.satel.internal.protocol.SatelModule] - Send/receive timeout, disconnecting module.
2016-11-01 17:57:15.035 [INFO ] [.satel.internal.protocol.Ethm1Module] - Closing connection to ETHM-1 module
2016-11-01 17:57:15.934 [INFO ] [.satel.internal.protocol.Ethm1Module] - Connecting to ETHM-1 module at 192.168.1.191:7094
2016-11-01 17:57:15.957 [INFO ] [.satel.internal.protocol.Ethm1Module] - ETHM-1 module connected successfully
2016-11-01 17:57:21.934 [ERROR] [.satel.internal.protocol.SatelModule] - Send/receive timeout, disconnecting module.
2016-11-01 17:57:22.036 [INFO ] [.satel.internal.protocol.Ethm1Module] - Closing connection to ETHM-1 module
2016-11-01 17:57:22.935 [INFO ] [.satel.internal.protocol.Ethm1Module] - Connecting to ETHM-1 module at 192.168.1.191:7094
2016-11-01 17:57:22.955 [INFO ] [.satel.internal.protocol.Ethm1Module] - ETHM-1 module connected successfully
2016-11-01 17:57:28.935 [ERROR] [.satel.internal.protocol.SatelModule] - Send/receive timeout, disconnecting module.
2016-11-01 17:57:29.037 [INFO ] [.satel.internal.protocol.Ethm1Module] - Closing connection to ETHM-1 module
2016-11-01 17:57:29.935 [INFO ] [.satel.internal.protocol.Ethm1Module] - Connecting to ETHM-1 module at 192.168.1.191:7094
2016-11-01 17:57:29.951 [INFO ] [.satel.internal.protocol.Ethm1Module] - ETHM-1 module connected successfully
2016-11-01 17:57:29.974 [ERROR] [.satel.internal.protocol.SatelModule] - Unexpected exception occurred during reading a message
java.io.IOException: Invalid ‘id_s’ value. Got: 84, expected: 75
at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel.readMessage(Ethm1Module.java:202)[210:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel.access$0(Ethm1Module.java:176)[210:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel$1.read(Ethm1Module.java:141)[210:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule.readMessage(SatelModule.java:221)[210:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule.communicationLoop(SatelModule.java:369)[210:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule.access$1(SatelModule.java:331)[210:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule$CommunicationWatchdog$2.run(SatelModule.java:463)[210:org.openhab.binding.satel:1.9.0.b4]
at java.lang.Thread.run(Thread.java:745)[:1.8.0_111]
2016-11-01 17:57:29.976 [INFO ] [.satel.internal.protocol.Ethm1Module] - Closing connection to ETHM-1 module
2016-11-01 17:57:30.936 [INFO ] [.satel.internal.protocol.Ethm1Module] - Connecting to ETHM-1 module at 192.168.1.191:7094
2016-11-01 17:57:30.955 [INFO ] [.satel.internal.protocol.Ethm1Module] - ETHM-1 module connected successfully
2016-11-01 17:57:30.970 [ERROR] [.satel.internal.protocol.SatelModule] - Unexpected exception occurred during reading a message
java.io.IOException: Invalid ‘id_s’ value. Got: -119, expected: 44
at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel.readMessage(Ethm1Module.java:202)[210:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel.access$0(Ethm1Module.java:176)[210:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel$1.read(Ethm1Module.java:141)[210:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule.readMessage(SatelModule.java:221)[210:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule.communicationLoop(SatelModule.java:369)[210:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule.access$1(SatelModule.java:331)[210:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule$CommunicationWatchdog$2.run(SatelModule.java:463)[210:org.openhab.binding.satel:1.9.0.b4]
at java.lang.Thread.run(Thread.java:745)[:1.8.0_111]
2016-11-01 17:57:30.973 [INFO ] [.satel.internal.protocol.Ethm1Module] - Closing connection to ETHM-1 module
2016-11-01 17:57:31.936 [INFO ] [.satel.internal.protocol.Ethm1Module] - Connecting to ETHM-1 module at 192.168.1.191:7094
2016-11-01 17:57:31.959 [INFO ] [.satel.internal.protocol.Ethm1Module] - ETHM-1 module connected successfully
2016-11-01 17:57:31.974 [ERROR] [.satel.internal.protocol.SatelModule] - Unexpected exception occurred during reading a message
java.io.IOException: Invalid ‘id_s’ value. Got: -80, expected: 31
at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel.readMessage(Ethm1Module.java:202)[210:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel.access$0(Ethm1Module.java:176)[210:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel$1.read(Ethm1Module.java:141)[210:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule.readMessage(SatelModule.java:221)[210:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule.communicationLoop(SatelModule.java:369)[210:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule.access$1(SatelModule.java:331)[210:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule$CommunicationWatchdog$2.run(SatelModule.java:463)[210:org.openhab.binding.satel:1.9.0.b4]
at java.lang.Thread.run(Thread.java:745)[:1.8.0_111]
2016-11-01 17:57:31.979 [INFO ] [.satel.internal.protocol.Ethm1Module] - Closing connection to ETHM-1 module
2016-11-01 17:57:32.936 [INFO ] [.satel.internal.protocol.Ethm1Module] - Connecting to ETHM-1 module at 192.168.1.191:7094
2016-11-01 17:57:32.957 [INFO ] [.satel.internal.protocol.Ethm1Module] - ETHM-1 module connected successfully
2016-11-01 17:57:32.975 [ERROR] [.satel.internal.protocol.SatelModule] - Unexpected exception occurred during reading a message
java.io.IOException: Invalid ‘id_s’ value. Got: 100, expected: -61
at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel.readMessage(Ethm1Module.java:202)[210:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel.access$0(Ethm1Module.java:176)[210:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel$1.read(Ethm1Module.java:141)[210:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule.readMessage(SatelModule.java:221)[210:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule.communicationLoop(SatelModule.java:369)[210:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule.access$1(SatelModule.java:331)[210:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule$CommunicationWatchdog$2.run(SatelModule.java:463)[210:org.openhab.binding.satel:1.9.0.b4]
at java.lang.Thread.run(Thread.java:745)[:1.8.0_111]
2016-11-01 17:57:32.980 [INFO ] [.satel.internal.protocol.Ethm1Module] - Closing connection to ETHM-1 module
2016-11-01 17:57:33.936 [INFO ] [.satel.internal.protocol.Ethm1Module] - Connecting to ETHM-1 module at 192.168.1.191:7094
2016-11-01 17:57:33.966 [INFO ] [.satel.internal.protocol.Ethm1Module] - ETHM-1 module connected successfully
2016-11-01 17:57:33.981 [ERROR] [.satel.internal.protocol.SatelModule] - Unexpected exception occurred during reading a message
java.io.IOException: Invalid ‘id_s’ value. Got: -31, expected: 77
at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel.readMessage(Ethm1Module.java:202)[210:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel.access$0(Ethm1Module.java:176)[210:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel$1.read(Ethm1Module.java:141)[210:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule.readMessage(SatelModule.java:221)[210:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule.communicationLoop(SatelModule.java:369)[210:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule.access$1(SatelModule.java:331)[210:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule$CommunicationWatchdog$2.run(SatelModule.java:463)[210:org.openhab.binding.satel:1.9.0.b4]
at java.lang.Thread.run(Thread.java:745)[:1.8.0_111]
2016-11-01 17:57:33.986 [INFO ] [.satel.internal.protocol.Ethm1Module] - Closing connection to ETHM-1 module
2016-11-01 17:57:34.936 [INFO ] [.satel.internal.protocol.Ethm1Module] - Connecting to ETHM-1 module at 192.168.1.191:7094
2016-11-01 17:57:34.954 [INFO ] [.satel.internal.protocol.Ethm1Module] - ETHM-1 module connected successfully
2016-11-01 17:57:34.972 [ERROR] [.satel.internal.protocol.SatelModule] - Unexpected exception occurred during reading a message
java.io.IOException: Invalid ‘id_s’ value. Got: -64, expected: -21
at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel.readMessage(Ethm1Module.java:202)[210:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel.access$0(Ethm1Module.java:176)[210:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel$1.read(Ethm1Module.java:141)[210:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule.readMessage(SatelModule.java:221)[210:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule.communicationLoop(SatelModule.java:369)[210:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule.access$1(SatelModule.java:331)[210:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule$CommunicationWatchdog$2.run(SatelModule.java:463)[210:org.openhab.binding.satel:1.9.0.b4]
at java.lang.Thread.run(Thread.java:745)[:1.8.0_111]
2016-11-01 17:57:34.978 [INFO ] [.satel.internal.protocol.Ethm1Module] - Closing connection to ETHM-1 module
2016-11-01 17:57:35.936 [INFO ] [.satel.internal.protocol.Ethm1Module] - Connecting to ETHM-1 module at 192.168.1.191:7094
2016-11-01 17:57:35.960 [INFO ] [.satel.internal.protocol.Ethm1Module] - ETHM-1 module connected successfully
2016-11-01 17:57:35.978 [ERROR] [.satel.internal.protocol.SatelModule] - Unexpected exception occurred during reading a message
java.io.IOException: Invalid ‘id_s’ value. Got: -119, expected: 121
at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel.readMessage(Ethm1Module.java:202)[210:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel.access$0(Ethm1Module.java:176)[210:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel$1.read(Ethm1Module.java:141)[210:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule.readMessage(SatelModule.java:221)[210:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule.communicationLoop(SatelModule.java:369)[210:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule.access$1(SatelModule.java:331)[210:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule$CommunicationWatchdog$2.run(SatelModule.java:463)[210:org.openhab.binding.satel:1.9.0.b4]
at java.lang.Thread.run(Thread.java:745)[:1.8.0_111]
2016-11-01 17:57:35.985 [INFO ] [.satel.internal.protocol.Ethm1Module] - Closing connection to ETHM-1 module
2016-11-01 17:57:36.943 [INFO ] [.satel.internal.protocol.Ethm1Module] - Connecting to ETHM-1 module at 192.168.1.191:7094
2016-11-01 17:57:36.961 [INFO ] [.satel.internal.protocol.Ethm1Module] - ETHM-1 module connected successfully
2016-11-01 17:57:36.976 [ERROR] [.satel.internal.protocol.SatelModule] - Unexpected exception occurred during reading a message
java.io.IOException: Invalid ‘id_s’ value. Got: 38, expected: 120
at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel.readMessage(Ethm1Module.java:202)[210:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel.access$0(Ethm1Module.java:176)[210:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel$1.read(Ethm1Module.java:141)[210:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule.readMessage(SatelModule.java:221)[210:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule.communicationLoop(SatelModule.java:369)[210:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule.access$1(SatelModule.java:331)[210:org.openhab.binding.satel:1.9.0.b4]
at org.openhab.binding.satel.internal.protocol.SatelModule$CommunicationWatchdog$2.run(SatelModule.java:463)[210:org.openhab.binding.satel:1.9.0.b4]
at java.lang.Thread.run(Thread.java:745)[:1.8.0_111]
2016-11-01 17:57:36.980 [INFO ] [.satel.internal.protocol.Ethm1Module] - Closing connection to ETHM-1 module

So:

It worked for the 1st time when encryption was disabled
After enabling encryption I can’t turn it off by commenting encryption_key. It didn’t worked.
Setting encryption_key as empty value worked and brought back communication

@Kai what can be the reason of Ad 2 ?

druciak · November 2, 2016, 9:55pm

Your logs without encryption are definitely not OK. The connection should be stable, once it is established it lasts for days. Please switch back to unencrypted communication and enable debug in the logback config. Perhaps we will find something interesting there, because what I can see it just disconnects after few millis from the module without any reason/error. I would restart ETHM or the whole system if possible.

zacofunny · November 3, 2016, 5:45pm

Hi @druciak. At the moment I believe that the cause of the problems was beta4 of Openhab 2. Following @Kai’s recommendation I changed OH2 Beta 4 to the latest OH2 snapshot available at openhab.org/downloads. It looks like your binding works fine now in both settings i.e. with and without encryption.
However there is still an issue with commenting ‘encryption_key’ which simply doesn’t work. After commenting this variable and restarting OH2 the system still remembers recently set value. If I need to disable encryption_key I need to follow your advice and set this variable to empty value. I suppose it is also an OH2 issue and not your binding, but someone would need to check it anyway. Cheers and thanks for help.

druciak · November 3, 2016, 6:04pm

Im glad to hear everything worked finally.

Regarding commenting out values in config files: as I wrote in one of my previous messages OH2 imports the values into internal database. If you already have a setting it gets overwrited, but if you comment something out, it is just not processed, so the previous value is kept in the db. But I think once it worked you don’t need to change anything in the confing.

Cheers.

watou · November 3, 2016, 6:54pm

Does anyone know if an issue has been added to any repo about this? It has been causing problems for many users.

druciak · November 3, 2016, 8:43pm

I have no idea. I haven’t added such issue.

zacofunny · January 21, 2019, 12:54am

Hi druciak,
from few weeks with using Zulu jdk with ZuluJCEPolicies i had to disable coding since it stopped work properly. I have no idea what happend, I frequently update openhabian packages, so maybe it’s cased by some update. Any hints to solve it? I’m using openhabian on RPI3 with openhab testing.

2019-01-21 01:41:44.523 [ERROR] [.satel.internal.protocol.SatelModule] - Unexpected exception occurred during reading a message
java.io.IOException: Invalid 'idS' value. Got: 13, expected: -11
        at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel.readMessage(Ethm1Module.java:210) ~[243:org.openhab.binding.satel:2.4.0]
        at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel.access$0(Ethm1Module.java:177) ~[243:org.openhab.binding.satel:2.4.0]
        at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel$1.read(Ethm1Module.java:143) ~[243:org.openhab.binding.satel:2.4.0]
        at org.openhab.binding.satel.internal.protocol.SatelModule.readMessage(SatelModule.java:238) [243:org.openhab.binding.satel:2.4.0]
        at org.openhab.binding.satel.internal.protocol.SatelModule.communicationLoop(SatelModule.java:384) [243:org.openhab.binding.satel:2.4.0]
        at org.openhab.binding.satel.internal.protocol.SatelModule.access$1(SatelModule.java:344) [243:org.openhab.binding.satel:2.4.0]
        at org.openhab.binding.satel.internal.protocol.SatelModule$CommunicationWatchdog$2.run(SatelModule.java:479) [243:org.openhab.binding.satel:2.4.0]
        at java.lang.Thread.run(Thread.java:748) [?:?]
2019-01-21 01:41:44.525 [INFO ] [.satel.internal.protocol.Ethm1Module] - Closing connection to ETHM-1 module
2019-01-21 01:41:44.855 [WARN ] [ernal.handler.ModbusDataThingHandler] - Channel switch will not be updated since transformation was unsuccessful. Channel is expecting the following data types [OnOffType, UnDefType]. Input data: number value 0 (value type 'bit' taken into account) and bool value false. Transformation: Transformation@18c6a07[tranformation=JS(invertstate.js),transformationServiceName=JS,transformationServiceParam=invertstate.js]
2019-01-21 01:41:44.893 [WARN ] [ernal.handler.ModbusDataThingHandler] - Channel switch will not be updated since transformation was unsuccessful. Channel is expecting the following data types [OnOffType, UnDefType]. Input data: number value 0 (value type 'bit' taken into account) and bool value false. Transformation: Transformation@7d4220[tranformation=JS(invertstate.js),transformationServiceName=JS,transformationServiceParam=invertstate.js]
^O2019-01-21 01:41:45.487 [INFO ] [.satel.internal.protocol.Ethm1Module] - Connecting to ETHM-1 module at 192.168.1.191:7094
2019-01-21 01:41:45.502 [INFO ] [.satel.internal.protocol.Ethm1Module] - ETHM-1 module connected successfully
2019-01-21 01:41:45.572 [ERROR] [.satel.internal.protocol.SatelModule] - Unexpected exception occurred during reading a message
java.io.IOException: Invalid 'idS' value. Got: 13, expected: 120
        at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel.readMessage(Ethm1Module.java:210) ~[243:org.openhab.binding.satel:2.4.0]
        at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel.access$0(Ethm1Module.java:177) ~[243:org.openhab.binding.satel:2.4.0]
        at org.openhab.binding.satel.internal.protocol.Ethm1Module$EncryptedCommunicationChannel$1.read(Ethm1Module.java:143) ~[243:org.openhab.binding.satel:2.4.0]
        at org.openhab.binding.satel.internal.protocol.SatelModule.readMessage(SatelModule.java:238) [243:org.openhab.binding.satel:2.4.0]
        at org.openhab.binding.satel.internal.protocol.SatelModule.communicationLoop(SatelModule.java:384) [243:org.openhab.binding.satel:2.4.0]
        at org.openhab.binding.satel.internal.protocol.SatelModule.access$1(SatelModule.java:344) [243:org.openhab.binding.satel:2.4.0]
        at org.openhab.binding.satel.internal.protocol.SatelModule$CommunicationWatchdog$2.run(SatelModule.java:479) [243:org.openhab.binding.satel:2.4.0]
        at java.lang.Thread.run(Thread.java:748) [?:?]

druciak · January 21, 2019, 5:36am

I have no idea what is happening. I would try with a clean install of OH, it seems that some of your upgrades broke encryption mechanism. If it does not help, try to downgrade OH to previous version.