DSC Binding - state updated to Disconnected!

Add-ons Bindings
1

I’m not sure how far back this goes in my binding usage but I after some item changes I noticed in the logs that the binding was repeatedly showing a state update of disconnected.

The debug says unable to make API connection, also shows a null item is being sent and shows a command with empty strings “” “” “” passed.

I would assume this is not normal behavior

Here is some of what I see in the DEBUG:

2015-09-27 12:36:19.138 [ERROR] [.o.b.d.i.DSCAlarmActiveBinding] - reconnect(): API reconnection failed!
2015-09-27 12:36:24.139 [DEBUG] [.o.b.d.i.DSCAlarmActiveBinding] - DSC Alarm Execute
2015-09-27 12:36:24.140 [DEBUG] [dscalarm.internal.protocol.API] - close(): Disconnecting from API Connection!
2015-09-27 12:36:24.141 [DEBUG] [o.b.d.i.connector.TCPConnector] - close(): Closed TCP Connection!
2015-09-27 12:36:24.141 [DEBUG] [.d.internal.DSCAlarmItemUpdate] - updateDeviceItem(): Item Name: PANEL_CONNECTION
2015-09-27 12:36:24.141 [DEBUG] [.d.internal.DSCAlarmItemUpdate] - updateDeviceProperties(): Item Name: PANEL_CONNECTION
2015-09-27 12:36:24.141 [DEBUG] [.dscalarm.internal.model.Panel] - updateProperties(): Panel Item Name: PANEL_CONNECTION
2015-09-27 12:36:24.141 [DEBUG] [.dscalarm.internal.model.Panel] - refreshItem(): Panel Item Name: PANEL_CONNECTION
2015-09-27 12:36:24.141 [DEBUG] [.o.b.d.i.DSCAlarmActiveBinding] - closeConnection(): TCP Connection Closed!
2015-09-27 12:36:24.141 [ERROR] [.o.b.d.i.DSCAlarmActiveBinding] - execute(): Not Connected to the DSC Alarm!
2015-09-27 12:36:24.141 [DEBUG] [.o.b.d.i.DSCAlarmActiveBinding] - reconnect(): API Reconnection!
2015-09-27 12:36:24.143 [DEBUG] [dscalarm.internal.protocol.API] - sendCommand(): ‘NetworkLogin’ Command Sent - 005user54

2015-09-27 12:36:24.143 [DEBUG] [dscalarm.internal.protocol.API] - open(): Connected = true, Connection Type: TCP
2015-09-27 12:36:24.143 [DEBUG] [.d.internal.DSCAlarmItemUpdate] - updateDeviceItem(): Item Name: PANEL_CONNECTION
2015-09-27 12:36:24.143 [DEBUG] [.d.internal.DSCAlarmItemUpdate] - updateDeviceProperties(): Item Name: PANEL_CONNECTION
2015-09-27 12:36:24.143 [DEBUG] [.dscalarm.internal.model.Panel] - updateProperties(): Panel Item Name: PANEL_CONNECTION
2015-09-27 12:36:24.143 [DEBUG] [.dscalarm.internal.model.Panel] - refreshItem(): Panel Item Name: PANEL_CONNECTION
2015-09-27 12:36:24.145 [ERROR] [o.b.d.i.connector.TCPConnector] - read(): IO Exception:
java.net.SocketException: Connection reset
at java.net.SocketInputStream.read(SocketInputStream.java:196) ~[na:1.7.0_79]
at java.net.SocketInputStream.read(SocketInputStream.java:122) ~[na:1.7.0_79]
at sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:283) ~[na:1.7.0_79]
at sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:325) ~[na:1.7.0_79]
at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:177) ~[na:1.7.0_79]
at java.io.InputStreamReader.read(InputStreamReader.java:184) ~[na:1.7.0_79]
at java.io.BufferedReader.fill(BufferedReader.java:154) ~[na:1.7.0_79]
at java.io.BufferedReader.readLine(BufferedReader.java:317) ~[na:1.7.0_79]
at java.io.BufferedReader.readLine(BufferedReader.java:382) ~[na:1.7.0_79]
at org.openhab.binding.dscalarm.internal.connector.TCPConnector.read(TCPConnector.java:89) ~[bundlefile:na]
at org.openhab.binding.dscalarm.internal.connector.TCPConnector$TCPListener.run(TCPConnector.java:231) [bundlefile:na]
2015-09-27 12:36:24.146 [DEBUG] [o.b.d.i.connector.TCPConnector] - handleIncomingMessage(): Message recieved: - Code: “”, Name: “”, Description: “”
2015-09-27 12:36:24.146 [DEBUG] [.d.internal.DSCAlarmItemUpdate] - updateDeviceItem(): Item Name: PANEL_MESSAGE
2015-09-27 12:36:24.146 [DEBUG] [.dscalarm.internal.model.Panel] - refreshItem(): Panel Item Name: PANEL_MESSAGE
2015-09-27 12:36:24.146 [DEBUG] [.o.b.d.i.DSCAlarmActiveBinding] - setTimeStampState(): Time Stamp:
2015-09-27 12:36:24.146 [DEBUG] [.d.internal.DSCAlarmItemUpdate] - updateDeviceProperties(): Item Name: PANEL_TIME_STAMP
2015-09-27 12:36:24.147 [DEBUG] [.o.b.d.i.DSCAlarmActiveBinding] - setTimeStampState(): Already Set!
2015-09-27 12:36:24.147 [DEBUG] [.o.b.d.i.DSCAlarmActiveBinding] - dscAlarmEventRecieved(): Event received! Looking for item: null
2015-09-27 12:36:29.144 [DEBUG] [.o.b.d.i.DSCAlarmActiveBinding] - DSC Alarm Execute
2015-09-27 12:36:29.145 [DEBUG] [dscalarm.internal.protocol.API] - close(): Disconnecting from API Connection!
2015-09-27 12:36:29.151 [DEBUG] [o.b.d.i.connector.TCPConnector] - close(): Closed TCP Connection!
2015-09-27 12:36:29.153 [DEBUG] [.d.internal.DSCAlarmItemUpdate] - updateDeviceItem(): Item Name: PANEL_CONNECTION
2015-09-27 12:36:29.155 [DEBUG] [.d.internal.DSCAlarmItemUpdate] - updateDeviceProperties(): Item Name: PANEL_CONNECTION
2015-09-27 12:36:29.156 [DEBUG] [.dscalarm.internal.model.Panel] - updateProperties(): Panel Item Name: PANEL_CONNECTION
2015-09-27 12:36:29.159 [DEBUG] [.dscalarm.internal.model.Panel] - refreshItem(): Panel Item Name: PANEL_CONNECTION
2015-09-27 12:36:29.167 [DEBUG] [.o.b.d.i.DSCAlarmActiveBinding] - closeConnection(): TCP Connection Closed!
2015-09-27 12:36:29.168 [ERROR] [.o.b.d.i.DSCAlarmActiveBinding] - execute(): Not Connected to the DSC Alarm!
2015-09-27 12:36:29.169 [DEBUG] [.o.b.d.i.DSCAlarmActiveBinding] - reconnect(): API Reconnection!
2015-09-27 12:36:29.175 [ERROR] [o.b.d.i.connector.TCPConnector] - write(): {}
java.net.SocketException: Connection reset
at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:118) ~[na:1.7.0_79]
at java.net.SocketOutputStream.write(SocketOutputStream.java:159) ~[na:1.7.0_79]
at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:221) ~[na:1.7.0_79]
at sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:291) ~[na:1.7.0_79]
at sun.nio.cs.StreamEncoder.implFlush(StreamEncoder.java:295) ~[na:1.7.0_79]
at sun.nio.cs.StreamEncoder.flush(StreamEncoder.java:141) ~[na:1.7.0_79]
at java.io.OutputStreamWriter.flush(OutputStreamWriter.java:229) ~[na:1.7.0_79]
at org.openhab.binding.dscalarm.internal.connector.TCPConnector.write(TCPConnector.java:72) ~[bundlefile:na]
at org.openhab.binding.dscalarm.internal.protocol.API.sendCommand(API.java:397) [bundlefile:na]
at org.openhab.binding.dscalarm.internal.protocol.API.open(API.java:204) [bundlefile:na]
at org.openhab.binding.dscalarm.internal.DSCAlarmActiveBinding.openConnection(DSCAlarmActiveBinding.java:531) [bundlefile:na]
at org.openhab.binding.dscalarm.internal.DSCAlarmActiveBinding.reconnect(DSCAlarmActiveBinding.java:545) [bundlefile:na]
at org.openhab.binding.dscalarm.internal.DSCAlarmActiveBinding.execute(DSCAlarmActiveBinding.java:139) [bundlefile:na]
at org.openhab.core.binding.AbstractActiveBinding$BindingActiveService.execute(AbstractActiveBinding.java:156) [org.openhab.core_1.7.1.jar:na]
at org.openhab.core.service.AbstractActiveService$RefreshThread.run(AbstractActiveService.java:173) [org.openhab.core_1.7.1.jar:na]
2015-09-27 12:36:29.177 [ERROR] [o.b.d.i.connector.TCPConnector] - read(): IO Exception:
java.net.SocketException: Connection reset
at java.net.SocketInputStream.read(SocketInputStream.java:196) ~[na:1.7.0_79]
at java.net.SocketInputStream.read(SocketInputStream.java:122) ~[na:1.7.0_79]
at sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:283) ~[na:1.7.0_79]
at sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:325) ~[na:1.7.0_79]
at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:177) ~[na:1.7.0_79]
at java.io.InputStreamReader.read(InputStreamReader.java:184) ~[na:1.7.0_79]
at java.io.BufferedReader.fill(BufferedReader.java:154) ~[na:1.7.0_79]
at java.io.BufferedReader.readLine(BufferedReader.java:317) ~[na:1.7.0_79]
at java.io.BufferedReader.readLine(BufferedReader.java:382) ~[na:1.7.0_79]
at org.openhab.binding.dscalarm.internal.connector.TCPConnector.read(TCPConnector.java:89) ~[bundlefile:na]
at org.openhab.binding.dscalarm.internal.connector.TCPConnector$TCPListener.run(TCPConnector.java:231) [bundlefile:na]
2015-09-27 12:36:29.189 [DEBUG] [dscalarm.internal.protocol.API] - sendCommand(): ‘NetworkLogin’ Command Sent - 005user54

2015-09-27 12:36:29.190 [ERROR] [dscalarm.internal.protocol.API] - open(): Unable to Make API Connection!
2015-09-27 12:36:29.191 [DEBUG] [dscalarm.internal.protocol.API] - open(): Connected = false, Connection Type: TCP
2015-09-27 12:36:29.193 [DEBUG] [.d.internal.DSCAlarmItemUpdate] - updateDeviceItem(): Item Name: PANEL_MESSAGE
2015-09-27 12:36:29.196 [DEBUG] [o.b.d.i.connector.TCPConnector] - handleIncomingMessage(): Message recieved: - Code: “”, Name: “”, Description: “”
2015-09-27 12:36:29.207 [DEBUG] [.d.internal.DSCAlarmItemUpdate] - updateDeviceProperties(): Item Name: PANEL_MESSAGE
2015-09-27 12:36:29.209 [DEBUG] [.dscalarm.internal.model.Panel] - updateProperties(): Panel Item Name: PANEL_MESSAGE
2015-09-27 12:36:29.210 [DEBUG] [.dscalarm.internal.model.Panel] - refreshItem(): Panel Item Name: PANEL_MESSAGE
2015-09-27 12:36:29.215 [ERROR] [.o.b.d.i.DSCAlarmActiveBinding] - reconnect(): API reconnection failed!
2015-09-27 12:36:29.216 [DEBUG] [.d.internal.DSCAlarmItemUpdate] - updateDeviceItem(): Item Name: ZONE3_IN_ALARM

I’m also seeing this where there is a network command sent “005user54” I do not know where that came from, but I think it might be possible that I erroneously programmed a section when trying to enable the output on the DSC system through the keypad:

at org.openhab.binding.dscalarm.internal.connector.TCPConnector$TCPListener.run(TCPConnector.java:231) [bundlefile:na]
2015-09-29 15:15:45.138 [DEBUG] [dscalarm.internal.protocol.API] - sendCommand(): ‘NetworkLogin’ Command Sent - 005user54

2015-09-29 15:15:45.141 [DEBUG] [o.b.d.i.connector.TCPConnector] - handleIncomingMessage(): Message recieved: - Code: “”, Name: “”, Description: “”
2015-09-29 15:15:45.142 [ERROR] [dscalarm.internal.protocol.API] - open(): Unable to Make API Connection!
2015-09-29 15:15:45.143 [DEBUG] [dscalarm.internal.protocol.API] - open(): Connected = false, Connection Type: TCP
2015-09-29 15:15:45.152 [DEBUG] [.d.internal.DSCAlarmItemUpdate] - updateDeviceItem(): Item Name: PANEL_MESSAGE
2015-09-29 15:15:45.152 [DEBUG] [.d.internal.DSCAlarmItemUpdate] - updateDeviceProperties(): Item Name: PANEL_MESSAGE
2015-09-29 15:15:45.153 [DEBUG] [.dscalarm.internal.model.Panel] - updateProperties(): Panel Item Name: PANEL_MESSAGE
2015-09-29 15:15:45.154 [DEBUG] [.dscalarm.internal.model.Panel] - refreshItem(): Panel Item Name: PANEL_MESSAGE
2015-09-29 15:15:45.154 [ERROR] [.o.b.d.i.DSCAlarmActiveBinding] - reconnect(): API reconnection failed!
2015-09-29 15:15:47.388 [DEBUG] [.o.b.d.i.DSCAlarmActiveBinding] - DSC Alarm Execute
2015-09-29 15:15:50.156 [DEBUG] [.o.b.d.i.DSCAlarmActiveBinding] - DSC Alarm Execute
2015-09-29 15:15:50.156 [DEBUG] [dscalarm.internal.protocol.API] - close(): Disconnecting from API Connection!
2015-09-29 15:15:50.158 [DEBUG] [o.b.d.i.connector.TCPConnector] - close(): Closed TCP Connection!
2015-09-29 15:15:50.159 [DEBUG] [.d.internal.DSCAlarmItemUpdate] - updateDeviceItem(): Item Name: PANEL_CONNECTION
2015-09-29 15:15:50.160 [DEBUG] [.d.internal.DSCAlarmItemUpdate] - updateDeviceProperties(): Item Name: PANEL_CONNECTION
2015-09-29 15:15:50.160 [DEBUG] [.dscalarm.internal.model.Panel] - updateProperties(): Panel Item Name: PANEL_CONNECTION
2015-09-29 15:15:50.161 [DEBUG] [.dscalarm.internal.model.Panel] - refreshItem(): Panel Item Name: PANEL_CONNECTION
2015-09-29 15:15:50.161 [DEBUG] [.o.b.d.i.DSCAlarmActiveBinding] - closeConnection(): TCP Connection Closed!
2015-09-29 15:15:50.162 [ERROR] [.o.b.d.i.DSCAlarmActiveBinding] - execute(): Not Connected to the DSC Alarm!
2015-09-29 15:15:50.162 [DEBUG] [.o.b.d.i.DSCAlarmActiveBinding] - reconnect(): API Reconnection!
2015-09-29 15:15:50.221 [ERROR] [o.b.d.i.connector.TCPConnector] - write(): {}
java.net.SocketException: Connection reset

Any ideas would be appreciated. The strange thing is, the commands still seem to be passed to the DSC system and I get responses and messages back so it must be connecting and disconnecting so quickly that I do not notice through the web interface other than occasional statuses.

2

Hello Adam,

A couple of things come to mind here. It looks like the Envisalink is refusing the connection. The first thing I would check is the network login password. The binding is sending the default, which is the ‘005user54’ command your seeing. If you have set the password to something else in the Envisalink then it will refuse the connection. This can be set in the ‘openhab.config’ file. The second thing is a long shot, but I would make sure nothing else is connected to the Envisalink. The Envisalink only allows one connection on port 4025. Hope this helps.

3

Thanks Russell,

I had only changed the password once in the envisalink when troubleshooting a failed connection at one point. The strange thing now is it seems to still be connecting to the point that commands and statuses are both reflected seemingly normal.

I did change the passwprd back then to “user” which I believed to be the default.

It may be possible my Vera is somehow still trying to contact it even though the Mios DSC plugin was turned off.

I will look at both of these closer again. Thanks for the fast reply and the info on “005user54”

EDIT: I did verify both default password is being used and even tried using “user” in openhab.cfg

Also ensure that the Vera DSC plugin is not being used…it was already removed from the device. Could any setting in the DSC system itself cause this?

I will keep poking arouund, bound to find something sooner or later

4

I am still wondering about the messages that say

DEBUG] [.o.b.d.i.DSCAlarmActiveBinding] - dscAlarmEventRecieved(): Event received! Looking for item: null

and

[DEBUG] [o.b.d.i.connector.TCPConnector] - handleIncomingMessage(): Message recieved: - Code: “”, Name: “”, Description: “”

5

It appears to be reading something from the connection, but the binding can’t interpret it so it defaults to an empty message.

6

Should I be seeing the binding execute every 5 seconds?

2015-10-04 23:51:58.800 [DEBUG] [.o.b.d.i.DSCAlarmActiveBinding] - DSC Alarm Execute
2015-10-04 23:52:03.801 [DEBUG] [.o.b.d.i.DSCAlarmActiveBinding] - DSC Alarm Execute
2015-10-04 23:52:08.801 [DEBUG] [.o.b.d.i.DSCAlarmActiveBinding] - DSC Alarm Execute
2015-10-04 23:52:13.802 [DEBUG] [.o.b.d.i.DSCAlarmActiveBinding] - DSC Alarm Execute
2015-10-04 23:52:18.803 [DEBUG] [.o.b.d.i.DSCAlarmActiveBinding] - DSC Alarm Execute
2015-10-04 23:52:23.803 [DEBUG] [.o.b.d.i.DSCAlarmActiveBinding] - DSC Alarm Execute
2015-10-04 23:52:28.804 [DEBUG] [.o.b.d.i.DSCAlarmActiveBinding] - DSC Alarm Execute

After restarding earlier I have not been able to get it to reconnect properly. In the logs it does say Panel state 1 but commands do not appear to be working again. Panel message says Disconnected though also.

I have tried power cycling the EVL3 also and restarting openhab to no avail.

7

found the problem…silly me. You were indeed correct saying that another device might have been competing for the connection.

I had an additional instance of openhab starting at boot that I had mistakenly thought was not running. Saw it when checking processes.

Thanks again for the direction.

8

Glad you got it working. To answer your question above about the ‘DSC Alarm Execute’ message; this is normal to see when in debug mode. It indicates that the binding is running correctly.