search

HentschelT / openhab2-addons

The next-generation open Home Automation Bus (openHAB)
Eclipse Public License 1.0
9 stars 3 forks source link

[isy] Unhandled Error (closing connection) #17

Open jspeckman opened 5 years ago

jspeckman commented 5 years ago

Hi,

I'm getting an error in the log file anytime there is interaction the ISY. It looks like it causes the binding to disconnect from the ISY and eventually reconnect after a bunch of java error messages.

Below is the debug logging output that occurs anytime there is an update to a device or variable from the ISY side. In the below example I change the value of variable id 1 from the isy admin console. Debug output:

2018-12-07 07:27:31.982 [DEBUG] [binding.isy.handler.IsyBridgeHandler] - need to find variable handler, id is: 1, val: 1 2018-12-07 07:27:31.983 [DEBUG] [binding.isy.handler.IsyBridgeHandler] - find thing handler for id: 1, type: 1 2018-12-07 07:27:31.984 [WARN ] [.internal.IsyWebSocketSubscription$1] - Unhandled Error (closing connection) java.lang.ClassCastException: java.lang.String cannot be cast to java.math.BigDecimal at org.openhab.binding.isy.handler.IsyBridgeHandler.getVariableHandler(IsyBridgeHandler.java:114) [226:org.openhab.binding.isy:2.3.0.201806112243] at org.openhab.binding.isy.handler.IsyBridgeHandler.access$5(IsyBridgeHandler.java:110) [226:org.openhab.binding.isy:2.3.0.201806112243] at org.openhab.binding.isy.handler.IsyBridgeHandler$IsyListener.onVariableChanged(IsyBridgeHandler.java:461) [226:org.openhab.binding.isy:2.3.0.201806112243] at org.openhab.binding.isy.internal.IsyWebSocketSubscription.parseXml(IsyWebSocketSubscription.java:135) [226:org.openhab.binding.isy:2.3.0.201806112243] at org.openhab.binding.isy.internal.IsyWebSocketSubscription.access$0(IsyWebSocketSubscription.java:110) [226:org.openhab.binding.isy:2.3.0.201806112243] at org.openhab.binding.isy.internal.IsyWebSocketSubscription$1.onWebSocketText(IsyWebSocketSubscription.java:53) [226:org.openhab.binding.isy:2.3.0.201806112243] at org.eclipse.jetty.websocket.common.events.JettyListenerEventDriver.onTextMessage(JettyListenerEventDriver.java:189) [92:org.eclipse.jetty.websocket.common:9.3.21.v20170918] at org.eclipse.jetty.websocket.common.message.SimpleTextMessage.messageComplete(SimpleTextMessage.java:69) [92:org.eclipse.jetty.websocket.common:9.3.21.v20170918] at org.eclipse.jetty.websocket.common.events.AbstractEventDriver.appendMessage(AbstractEventDriver.java:66) [92:org.eclipse.jetty.websocket.common:9.3.21.v20170918] at org.eclipse.jetty.websocket.common.events.JettyListenerEventDriver.onTextFrame(JettyListenerEventDriver.java:158) [92:org.eclipse.jetty.websocket.common:9.3.21.v20170918] at org.eclipse.jetty.websocket.common.events.AbstractEventDriver.incomingFrame(AbstractEventDriver.java:162) [92:org.eclipse.jetty.websocket.common:9.3.21.v20170918] at org.eclipse.jetty.websocket.common.WebSocketSession.incomingFrame(WebSocketSession.java:376) [92:org.eclipse.jetty.websocket.common:9.3.21.v20170918] at org.eclipse.jetty.websocket.common.extensions.ExtensionStack.incomingFrame(ExtensionStack.java:220) [92:org.eclipse.jetty.websocket.common:9.3.21.v20170918] at org.eclipse.jetty.websocket.common.Parser.notifyFrame(Parser.java:220) [92:org.eclipse.jetty.websocket.common:9.3.21.v20170918] at org.eclipse.jetty.websocket.common.Parser.parse(Parser.java:256) [92:org.eclipse.jetty.websocket.common:9.3.21.v20170918] at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.readParse(AbstractWebSocketConnection.java:679) [92:org.eclipse.jetty.websocket.common:9.3.21.v20170918] at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.onFillable(AbstractWebSocketConnection.java:511) [92:org.eclipse.jetty.websocket.common:9.3.21.v20170918] at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:283) [76:org.eclipse.jetty.io:9.3.21.v20170918] at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:108) [76:org.eclipse.jetty.io:9.3.21.v20170918] at org.eclipse.jetty.io.SelectChannelEndPoint$2.run(SelectChannelEndPoint.java:93) [76:org.eclipse.jetty.io:9.3.21.v20170918] at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.executeProduceConsume(ExecuteProduceConsume.java:303) [87:org.eclipse.jetty.util:9.3.21.v20170918] at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.produceConsume(ExecuteProduceConsume.java:148) [87:org.eclipse.jetty.util:9.3.21.v20170918] at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.run(ExecuteProduceConsume.java:136) [87:org.eclipse.jetty.util:9.3.21.v20170918] at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:671) [87:org.eclipse.jetty.util:9.3.21.v20170918] at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:589) [87:org.eclipse.jetty.util:9.3.21.v20170918] at java.lang.Thread.run(Thread.java:748) [?:?] 2018-12-07 07:27:31.987 [ERROR] [sy.internal.IsyWebSocketSubscription] - Error with websocket communication java.lang.ClassCastException: java.lang.String cannot be cast to java.math.BigDecimal at org.openhab.binding.isy.handler.IsyBridgeHandler.getVariableHandler(IsyBridgeHandler.java:114) [226:org.openhab.binding.isy:2.3.0.201806112243] at org.openhab.binding.isy.handler.IsyBridgeHandler.access$5(IsyBridgeHandler.java:110) [226:org.openhab.binding.isy:2.3.0.201806112243] at org.openhab.binding.isy.handler.IsyBridgeHandler$IsyListener.onVariableChanged(IsyBridgeHandler.java:461) [226:org.openhab.binding.isy:2.3.0.201806112243] at org.openhab.binding.isy.internal.IsyWebSocketSubscription.parseXml(IsyWebSocketSubscription.java:135) [226:org.openhab.binding.isy:2.3.0.201806112243] at org.openhab.binding.isy.internal.IsyWebSocketSubscription.access$0(IsyWebSocketSubscription.java:110) [226:org.openhab.binding.isy:2.3.0.201806112243] at org.openhab.binding.isy.internal.IsyWebSocketSubscription$1.onWebSocketText(IsyWebSocketSubscription.java:53) [226:org.openhab.binding.isy:2.3.0.201806112243] at org.eclipse.jetty.websocket.common.events.JettyListenerEventDriver.onTextMessage(JettyListenerEventDriver.java:189) [92:org.eclipse.jetty.websocket.common:9.3.21.v20170918] at org.eclipse.jetty.websocket.common.message.SimpleTextMessage.messageComplete(SimpleTextMessage.java:69) [92:org.eclipse.jetty.websocket.common:9.3.21.v20170918] at org.eclipse.jetty.websocket.common.events.AbstractEventDriver.appendMessage(AbstractEventDriver.java:66) [92:org.eclipse.jetty.websocket.common:9.3.21.v20170918] at org.eclipse.jetty.websocket.common.events.JettyListenerEventDriver.onTextFrame(JettyListenerEventDriver.java:158) [92:org.eclipse.jetty.websocket.common:9.3.21.v20170918] at org.eclipse.jetty.websocket.common.events.AbstractEventDriver.incomingFrame(AbstractEventDriver.java:162) [92:org.eclipse.jetty.websocket.common:9.3.21.v20170918] at org.eclipse.jetty.websocket.common.WebSocketSession.incomingFrame(WebSocketSession.java:376) [92:org.eclipse.jetty.websocket.common:9.3.21.v20170918] at org.eclipse.jetty.websocket.common.extensions.ExtensionStack.incomingFrame(ExtensionStack.java:220) [92:org.eclipse.jetty.websocket.common:9.3.21.v20170918] at org.eclipse.jetty.websocket.common.Parser.notifyFrame(Parser.java:220) [92:org.eclipse.jetty.websocket.common:9.3.21.v20170918] at org.eclipse.jetty.websocket.common.Parser.parse(Parser.java:256) [92:org.eclipse.jetty.websocket.common:9.3.21.v20170918] at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.readParse(AbstractWebSocketConnection.java:679) [92:org.eclipse.jetty.websocket.common:9.3.21.v20170918] at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.onFillable(AbstractWebSocketConnection.java:511) [92:org.eclipse.jetty.websocket.common:9.3.21.v20170918] at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:283) [76:org.eclipse.jetty.io:9.3.21.v20170918] at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:108) [76:org.eclipse.jetty.io:9.3.21.v20170918] at org.eclipse.jetty.io.SelectChannelEndPoint$2.run(SelectChannelEndPoint.java:93) [76:org.eclipse.jetty.io:9.3.21.v20170918] at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.executeProduceConsume(ExecuteProduceConsume.java:303) [87:org.eclipse.jetty.util:9.3.21.v20170918] at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.produceConsume(ExecuteProduceConsume.java:148) [87:org.eclipse.jetty.util:9.3.21.v20170918] at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.run(ExecuteProduceConsume.java:136) [87:org.eclipse.jetty.util:9.3.21.v20170918] at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:671) [87:org.eclipse.jetty.util:9.3.21.v20170918] at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:589) [87:org.eclipse.jetty.util:9.3.21.v20170918] at java.lang.Thread.run(Thread.java:748) [?:?] 2018-12-07 07:27:31.990 [DEBUG] [binding.isy.handler.IsyBridgeHandler] - Received onDeviceOffLine message 2018-12-07 07:27:31.996 [DEBUG] [sy.internal.IsyWebSocketSubscription] - Node 'n/a' got control message '_0' action '120' 2018-12-07 07:27:32.104 [DEBUG] [sy.internal.IsyWebSocketSubscription] - Socket Closed: [1008]ClassCastException 2018-12-07 07:27:35.114 [INFO ] [sy.internal.IsyWebSocketSubscription] - Reconnecting via Websocket to Isy. 2018-12-07 07:27:35.128 [DEBUG] [sy.internal.IsyWebSocketSubscription] - Socket Connected: WebSocketSession[websocket=JettyListenerEventDriver[org.openhab.binding.isy.internal.IsyWebSocketSubscription$1],behavior=CLIENT,connection=WebSocketClientConnection@1513C297{endp=SelectChannelEndPoint@14ed7dc{isy994-ems.home/192.168.10.31:80<->39064,Open,in,out,-,-,1/300000,WebSocketClientConnection@1513c297}{io=1/0,kio=1,kro=1},ios=IOState@1714aad[CONNECTED,!in,out],f=Flusher[queueSize=0,aggregateSize=0,failure=null],g=Generator[CLIENT,validating],p=Parser@73dde7[ExtensionStack,s=START,c=0,len=0,f=null]},remote=WebSocketRemoteEndpoint@fe827d[batching=true],incoming=JettyListenerEventDriver[org.openhab.binding.isy.internal.IsyWebSocketSubscription$1],outgoing=ExtensionStack[queueSize=0,extensions=[],incoming=org.eclipse.jetty.websocket.common.WebSocketSession,outgoing=org.eclipse.jetty.websocket.client.io.WebSocketClientConnection]] 2018-12-07 07:27:35.136 [DEBUG] [binding.isy.handler.IsyBridgeHandler] - Received onDeviceOnLine message

Not sure if this is causing any usability issues, I am able to post updates to the ISY, and receive updates from the ISY. While I'm on the admin console, I do get messages about the subscriber not responding.

Thanks for your help. Jason

HentschelT commented 5 years ago

Hmm, interesting, some"thing" that is associated with the ISY bridge got a non-numeral id. I'll need to see how that would get there, no idea at the moment.

I'll plan on fixing/revamping the binding in the next few weeks, I'll take a look.

(Thanks for the extensive bug report, stuff like this helps)