smarthome Tradfri binding does not reestablish connection to gateway after connection loss

Tradfri binding does not reestablish connection to gateway after connection loss

Open roben opened this issue 5 years ago • 83 comments

Short version: If the gateway gets physically dis- and reconnected the binding does not automatically reconnect to it. To reestablish the connection manually, the IP can be changed to something else and back to the correct value again.

Long version with screenshots and logs: https://community.openhab.org/t/tradfri-binding-loses-connection-after-power-failure-gateway-reboot/47833

Aug 16 '18 14:08 roben

Have you tried to set the Security Code only?

Aug 16 '18 14:08 lukicsl

No, because I never had an issue with the code. Maybe you setting the code again also only caused a reconnect. It is intended to not being set after the first connection.

Aug 16 '18 14:08 roben

Do I read it correct: you go to Configuration > Things > Edit >TRÅDFRI Gateway and just change/change back the ip address. Question: Do you have anything visible indication (*******) that Security Code has value. I have always a blank field there.

Aug 16 '18 15:08 lukicsl

you go to Configuration > Things > Edit >TRÅDFRI Gateway and just change/change back the ip address.

Yes.

Question: Do you have anything visible indication (*******) that Security Code has value. I have always a blank field there.

No. It's empty after it has been processed. The real security credentials are shown when setting tools > show advanced settings (or something like this, it's in German for me).

Aug 16 '18 19:08 roben

But let's stick to the connection issue here. If you have further questions, we can continue in the OH forums.

Aug 16 '18 19:08 roben

The Bridge handler overwrites the "Security Code" with null after successfully establishing a connection to the gateway. Why? I will remove that line of code and do some tests.

https://github.com/eclipse/smarthome/blob/b39fe45be22b7290269f1959803e49fda91cdb6a/extensions/binding/org.eclipse.smarthome.binding.tradfri/src/main/java/org/eclipse/smarthome/binding/tradfri/handler/TradfriGatewayHandler.java#L220-L224

Aug 17 '18 16:08 cweitkamp

@cweitkamp This is by design as @roben referenced here already. Afair, the Tradfri developer docs stated that systems must not persist the security code, only the PSK.

Aug 17 '18 17:08 kaikreuzer

I got it. Did not read carefully enough. Nonetheless I did some more research. After restarting the bundle we ran into some timeout errors which seem to stop the handler from coming ONLINE again:

2018-08-19 14:18:33.803 [DEBUG] [tradfri.internal.TradfriCoapEndpoint] - Destroying CoAP endpoint.
java.lang.RuntimeException: Endpoint destroyed
        at org.eclipse.smarthome.binding.tradfri.internal.TradfriCoapEndpoint.destroy(TradfriCoapEndpoint.java:39) [234:org.eclipse.smarthome.binding.tradfri:0.10.0.201808191135]
        at org.eclipse.smarthome.binding.tradfri.handler.TradfriGatewayHandler.dispose(TradfriGatewayHandler.java:263) [234:org.eclipse.smarthome.binding.tradfri:0.10.0.201808191135]
        at org.eclipse.smarthome.core.thing.binding.BaseThingHandler.thingUpdated(BaseThingHandler.java:206) [101:org.eclipse.smarthome.core.thing:0.10.0.201808011124]
        at org.eclipse.smarthome.binding.tradfri.handler.TradfriGatewayHandler.thingUpdated(TradfriGatewayHandler.java:371) [234:org.eclipse.smarthome.binding.tradfri:0.10.0.201808191135]
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
        at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
        at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:153) [94:org.eclipse.smarthome.core:0.10.0.201808011124]
        at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:53) [94:org.eclipse.smarthome.core:0.10.0.201808011124]
        at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
        at java.lang.Thread.run(Thread.java:748) [?:?]
2018-08-19 14:18:33.822 [INFO ] [radfri.handler.TradfriGatewayHandler] - Bridge configuration updated. Updating paired things (if any).
2018-08-19 14:18:37.842 [DEBUG] [.tradfri.internal.TradfriCoapHandler] - CoAP onError
2018-08-19 14:18:47.484 [DEBUG] [.tradfri.internal.TradfriCoapHandler] - CoAP onError
2018-08-19 14:18:50.242 [DEBUG] [.tradfri.internal.TradfriCoapHandler] - CoAP onError

I changed the order of destroying the endpoint before shutting down the client in #6079. This maybe is a fix for our issue, but I am not sure. We need some more testing.

Aug 19 '18 13:08 cweitkamp

@roben @lukicsl

New ESH 291 and OH2 1340 snapshots have been release. May I ask you to do some more tests with the new version? I am curios if it works...

Aug 25 '18 09:08 cweitkamp

Thanks! Can I use just the new binding jar with the current OH stable? Or is there even a way to tell OH to install the snapshot version of the binding?

Aug 25 '18 09:08 roben

Both options are possible. Lets continue our discussion in the community forum.

Aug 25 '18 09:08 cweitkamp

Sady it did not seem to help. I am running 234 │ Active │ 80 │ 0.10.0.201808242044 │ org.eclipse.smarthome.binding.tradfri but still had to do the manual IP change workaround to get the gateway back online.

Even more it seems that OH is now taking much longer to detect the gateway being offline. It logged 12:09:24.240 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'tradfri:gateway:gwdcefcaba8d2b' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR) some minutes after I unplugged it and reconnected it.

Aug 25 '18 10:08 roben

I'll leave it in this state for now and see if it just takes some time to come back online automatically.

Aug 25 '18 10:08 roben

Oh and I tried to access the binding while it was already gone but still marked as online: 12:08:55.340 [INFO ] [smarthome.event.ItemCommandEvent ] - Item 'Tradfri_Bulb_WZ_Stehlampe_gr' received command 39 12:08:55.342 [INFO ] [smarthome.event.ItemStateChangedEvent] - Tradfri_Bulb_WZ_Stehlampe_gr changed from 76 to 39

Aug 25 '18 10:08 roben

15 Minutes later and still no luck. So it seems still broken to me, sorry.

Aug 25 '18 10:08 roben

My I ask you to enable DEBUG or TRACE logging while testing?

Aug 25 '18 10:08 cweitkamp

Of course. For which logging facility? Only org.eclipse.smarthome.binding.tradfri?

Aug 25 '18 10:08 roben

Yes.

Aug 25 '18 10:08 cweitkamp

First thing I noticed: 12:54:01.703 [DEBUG] [nal.discovery.TradfriDiscoveryService] - Adding device tradfri:0100:gwdcefcaba8d2b:65543 to inbox, even though it is already configured and currently online:

Update: Maybe not that important. Those are just the devices, not the gateway.

Aug 25 '18 10:08 roben

Unplugged the gateway - no update.

Switched lamp with unplugged gateway:

13:00:42.024 [DEBUG] [g.tradfri.handler.TradfriThingHandler] - Sending payload: {"3311":[{"5850":0}],"3":{}}
13:00:42.025 [DEBUG] [ng.tradfri.internal.TradfriCoapClient] - Proccessing payload: {"3311":[{"5850":0}],"3":{}}
13:00:43.946 [DEBUG] [g.tradfri.handler.TradfriThingHandler] - Sending payload: {"3311":[{"5850":1}],"3":{}}
13:00:43.947 [DEBUG] [ng.tradfri.internal.TradfriCoapClient] - Proccessing payload: {"3311":[{"5850":1}],"3":{}}

Two minutes later, gateway is marked offline in Habmin:

13:01:55.902 [DEBUG] [g.tradfri.internal.TradfriCoapHandler] - CoAP onError
13:02:05.967 [DEBUG] [g.tradfri.internal.TradfriCoapHandler] - CoAP onError
13:02:16.392 [DEBUG] [g.tradfri.internal.TradfriCoapHandler] - CoAP onError
[...]

Plugged gateway back in, gateway is discovered but still marked offline:

13:03:24.018 [DEBUG] [discovery.TradfriDiscoveryParticipant] - Discovered Tradfri gateway: [ServiceInfoImpl@321876347 name: 'gw-dcefcaba8d2b._coap._udp.local.' address: '/10.0.1.167:5684 ' status: 'DNS: JmDNS-IP-1 [/10.0.1.2] state: probing 1 task: null' is persistent, has data
	version: 1.4.15]
13:03:27.617 [DEBUG] [discovery.TradfriDiscoveryParticipant] - Discovered Tradfri gateway: [ServiceInfoImpl@321876347 name: 'gw-dcefcaba8d2b._coap._udp.local.' address: '/10.0.1.167:5684 /fe80:0:0:0:deef:caff:feba:8d2b:5684 ' status: 'DNS: JmDNS-IP-1 [/10.0.1.2] state: probing 1 task: null' is persistent, has data
	version: 1.4.15]
13:03:33.991 [DEBUG] [g.tradfri.internal.TradfriCoapHandler] - CoAP onError

Setting wrong IP:

java.lang.RuntimeException: Endpoint destroyed
	at org.eclipse.smarthome.binding.tradfri.internal.TradfriCoapEndpoint.destroy(TradfriCoapEndpoint.java:39) [234:org.eclipse.smarthome.binding.tradfri:0.10.0.201808242044]
	at org.eclipse.smarthome.binding.tradfri.handler.TradfriGatewayHandler.dispose(TradfriGatewayHandler.java:259) [234:org.eclipse.smarthome.binding.tradfri:0.10.0.201808242044]
	at org.eclipse.smarthome.core.thing.binding.BaseThingHandler.handleConfigurationUpdate(BaseThingHandler.java:196) [108:org.eclipse.smarthome.core.thing:0.10.0.oh230]
	at org.eclipse.smarthome.core.thing.internal.ThingRegistryImpl.updateConfiguration(ThingRegistryImpl.java:92) [108:org.eclipse.smarthome.core.thing:0.10.0.oh230]
	at org.eclipse.smarthome.io.rest.core.internal.thing.ThingResource.updateConfiguration(ThingResource.java:425) [118:org.eclipse.smarthome.io.rest.core:0.10.0.oh230]
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
	at org.glassfish.jersey.server.model.internal.ResourceMethodInvocationHandlerFactory$1.invoke(ResourceMethodInvocationHandlerFactory.java:81) [170:org.glassfish.jersey.core.jersey-server:2.22.2]
	at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher$1.run(AbstractJavaResourceMethodDispatcher.java:144) [170:org.glassfish.jersey.core.jersey-server:2.22.2]
	at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.invoke(AbstractJavaResourceMethodDispatcher.java:161) [170:org.glassfish.jersey.core.jersey-server:2.22.2]
	at org.glassfish.jersey.server.model.internal.JavaResourceMethodDispatcherProvider$ResponseOutInvoker.doDispatch(JavaResourceMethodDispatcherProvider.java:160) [170:org.glassfish.jersey.core.jersey-server:2.22.2]
	at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.dispatch(AbstractJavaResourceMethodDispatcher.java:99) [170:org.glassfish.jersey.core.jersey-server:2.22.2]
	at org.glassfish.jersey.server.model.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:389) [170:org.glassfish.jersey.core.jersey-server:2.22.2]
	at org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:347) [170:org.glassfish.jersey.core.jersey-server:2.22.2]
	at org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:102) [170:org.glassfish.jersey.core.jersey-server:2.22.2]
	at org.glassfish.jersey.server.ServerRuntime$2.run(ServerRuntime.java:326) [170:org.glassfish.jersey.core.jersey-server:2.22.2]
	at org.glassfish.jersey.internal.Errors$1.call(Errors.java:271) [169:org.glassfish.jersey.core.jersey-common:2.22.2]
	at org.glassfish.jersey.internal.Errors$1.call(Errors.java:267) [169:org.glassfish.jersey.core.jersey-common:2.22.2]
	at org.glassfish.jersey.internal.Errors.process(Errors.java:315) [169:org.glassfish.jersey.core.jersey-common:2.22.2]
	at org.glassfish.jersey.internal.Errors.process(Errors.java:297) [169:org.glassfish.jersey.core.jersey-common:2.22.2]
	at org.glassfish.jersey.internal.Errors.process(Errors.java:267) [169:org.glassfish.jersey.core.jersey-common:2.22.2]
	at org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:317) [169:org.glassfish.jersey.core.jersey-common:2.22.2]
	at org.glassfish.jersey.server.ServerRuntime.process(ServerRuntime.java:305) [170:org.glassfish.jersey.core.jersey-server:2.22.2]
	at org.glassfish.jersey.server.ApplicationHandler.handle(ApplicationHandler.java:1154) [170:org.glassfish.jersey.core.jersey-server:2.22.2]
	at org.glassfish.jersey.servlet.WebComponent.serviceImpl(WebComponent.java:473) [167:org.glassfish.jersey.containers.jersey-container-servlet-core:2.22.2]
	at org.glassfish.jersey.servlet.WebComponent.service(WebComponent.java:427) [167:org.glassfish.jersey.containers.jersey-container-servlet-core:2.22.2]
	at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:388) [167:org.glassfish.jersey.containers.jersey-container-servlet-core:2.22.2]
	at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:341) [167:org.glassfish.jersey.containers.jersey-container-servlet-core:2.22.2]
	at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:228) [167:org.glassfish.jersey.containers.jersey-container-servlet-core:2.22.2]
	at com.eclipsesource.jaxrs.publisher.internal.ServletContainerBridge.service(ServletContainerBridge.java:76) [15:com.eclipsesource.jaxrs.publisher:5.3.1.201602281253]
	at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:848) [85:org.eclipse.jetty.servlet:9.3.21.v20170918]
	at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:584) [85:org.eclipse.jetty.servlet:9.3.21.v20170918]
	at org.ops4j.pax.web.service.jetty.internal.HttpServiceServletHandler.doHandle(HttpServiceServletHandler.java:71) [183:org.ops4j.pax.web.pax-web-jetty:6.0.9]
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143) [84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:548) [82:org.eclipse.jetty.security:9.3.21.v20170918]
	at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:226) [84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1180) [84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.ops4j.pax.web.service.jetty.internal.HttpServiceContext.doHandle(HttpServiceContext.java:284) [183:org.ops4j.pax.web.pax-web-jetty:6.0.9]
	at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:512) [85:org.eclipse.jetty.servlet:9.3.21.v20170918]
	at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:185) [84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1112) [84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) [84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.ops4j.pax.web.service.jetty.internal.JettyServerHandlerCollection.handle(JettyServerHandlerCollection.java:80) [183:org.ops4j.pax.web.pax-web-jetty:6.0.9]
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:134) [84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.eclipse.jetty.server.Server.handle(Server.java:534) [84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:333) [84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:251) [84:org.eclipse.jetty.server: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) [?:?]
13:04:41.695 [DEBUG] [.tradfri.internal.TradfriCoapEndpoint] - Destroying CoAP endpoint.
java.lang.RuntimeException: Endpoint destroyed
	at org.eclipse.smarthome.binding.tradfri.internal.TradfriCoapEndpoint.destroy(TradfriCoapEndpoint.java:39) [234:org.eclipse.smarthome.binding.tradfri:0.10.0.201808242044]
	at org.eclipse.smarthome.binding.tradfri.handler.TradfriGatewayHandler.dispose(TradfriGatewayHandler.java:259) [234:org.eclipse.smarthome.binding.tradfri:0.10.0.201808242044]
	at org.eclipse.smarthome.core.thing.binding.BaseThingHandler.handleConfigurationUpdate(BaseThingHandler.java:196) [108:org.eclipse.smarthome.core.thing:0.10.0.oh230]
	at org.eclipse.smarthome.core.thing.internal.ThingRegistryImpl.updateConfiguration(ThingRegistryImpl.java:92) [108:org.eclipse.smarthome.core.thing:0.10.0.oh230]
	at org.eclipse.smarthome.io.rest.core.internal.thing.ThingResource.updateConfiguration(ThingResource.java:425) [118:org.eclipse.smarthome.io.rest.core:0.10.0.oh230]
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
	at org.glassfish.jersey.server.model.internal.ResourceMethodInvocationHandlerFactory$1.invoke(ResourceMethodInvocationHandlerFactory.java:81) [170:org.glassfish.jersey.core.jersey-server:2.22.2]
	at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher$1.run(AbstractJavaResourceMethodDispatcher.java:144) [170:org.glassfish.jersey.core.jersey-server:2.22.2]
	at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.invoke(AbstractJavaResourceMethodDispatcher.java:161) [170:org.glassfish.jersey.core.jersey-server:2.22.2]
	at org.glassfish.jersey.server.model.internal.JavaResourceMethodDispatcherProvider$ResponseOutInvoker.doDispatch(JavaResourceMethodDispatcherProvider.java:160) [170:org.glassfish.jersey.core.jersey-server:2.22.2]
	at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.dispatch(AbstractJavaResourceMethodDispatcher.java:99) [170:org.glassfish.jersey.core.jersey-server:2.22.2]
	at org.glassfish.jersey.server.model.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:389) [170:org.glassfish.jersey.core.jersey-server:2.22.2]
	at org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:347) [170:org.glassfish.jersey.core.jersey-server:2.22.2]
	at org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:102) [170:org.glassfish.jersey.core.jersey-server:2.22.2]
	at org.glassfish.jersey.server.ServerRuntime$2.run(ServerRuntime.java:326) [170:org.glassfish.jersey.core.jersey-server:2.22.2]
	at org.glassfish.jersey.internal.Errors$1.call(Errors.java:271) [169:org.glassfish.jersey.core.jersey-common:2.22.2]
	at org.glassfish.jersey.internal.Errors$1.call(Errors.java:267) [169:org.glassfish.jersey.core.jersey-common:2.22.2]
	at org.glassfish.jersey.internal.Errors.process(Errors.java:315) [169:org.glassfish.jersey.core.jersey-common:2.22.2]
	at org.glassfish.jersey.internal.Errors.process(Errors.java:297) [169:org.glassfish.jersey.core.jersey-common:2.22.2]
	at org.glassfish.jersey.internal.Errors.process(Errors.java:267) [169:org.glassfish.jersey.core.jersey-common:2.22.2]
	at org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:317) [169:org.glassfish.jersey.core.jersey-common:2.22.2]
	at org.glassfish.jersey.server.ServerRuntime.process(ServerRuntime.java:305) [170:org.glassfish.jersey.core.jersey-server:2.22.2]
	at org.glassfish.jersey.server.ApplicationHandler.handle(ApplicationHandler.java:1154) [170:org.glassfish.jersey.core.jersey-server:2.22.2]
	at org.glassfish.jersey.servlet.WebComponent.serviceImpl(WebComponent.java:473) [167:org.glassfish.jersey.containers.jersey-container-servlet-core:2.22.2]
	at org.glassfish.jersey.servlet.WebComponent.service(WebComponent.java:427) [167:org.glassfish.jersey.containers.jersey-container-servlet-core:2.22.2]
	at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:388) [167:org.glassfish.jersey.containers.jersey-container-servlet-core:2.22.2]
	at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:341) [167:org.glassfish.jersey.containers.jersey-container-servlet-core:2.22.2]
	at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:228) [167:org.glassfish.jersey.containers.jersey-container-servlet-core:2.22.2]
	at com.eclipsesource.jaxrs.publisher.internal.ServletContainerBridge.service(ServletContainerBridge.java:76) [15:com.eclipsesource.jaxrs.publisher:5.3.1.201602281253]
	at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:848) [85:org.eclipse.jetty.servlet:9.3.21.v20170918]
	at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:584) [85:org.eclipse.jetty.servlet:9.3.21.v20170918]
	at org.ops4j.pax.web.service.jetty.internal.HttpServiceServletHandler.doHandle(HttpServiceServletHandler.java:71) [183:org.ops4j.pax.web.pax-web-jetty:6.0.9]
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143) [84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:548) [82:org.eclipse.jetty.security:9.3.21.v20170918]
	at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:226) [84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1180) [84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.ops4j.pax.web.service.jetty.internal.HttpServiceContext.doHandle(HttpServiceContext.java:284) [183:org.ops4j.pax.web.pax-web-jetty:6.0.9]
	at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:512) [85:org.eclipse.jetty.servlet:9.3.21.v20170918]
	at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:185) [84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1112) [84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) [84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.ops4j.pax.web.service.jetty.internal.JettyServerHandlerCollection.handle(JettyServerHandlerCollection.java:80) [183:org.ops4j.pax.web.pax-web-jetty:6.0.9]
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:134) [84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.eclipse.jetty.server.Server.handle(Server.java:534) [84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:333) [84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:251) [84:org.eclipse.jetty.server: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) [?:?]

Setting correct IP:

13:04:43.784 [DEBUG] [g.tradfri.internal.TradfriCoapHandler] - CoAP response
options: {"Content-Format":"application/json", "Max-Age":604800}
payload: {"9023":"1.tradfri.pool.ntp.org","9029":"1.4.15","9059":1535195083,"9060":"2018-08-25T11:04:43.041104Z","9062":0,"9061":0,"9081":"7e191d52044000e8","9082":true,"9093":0,"9083":"862-73-258","9054":0,"9073":13,"9055":0,"9200":"537e7ce9-e42e-4eb4-80eb-93319c1c8f30","9066":5,"9069":1530532122,"9107":1,"9106":0,"9077":28,"9071":1,"9072":8,"9074":17,"9080":60,"9075":28,"9076":10,"9078":1,"9079":0,"9092":0,"9105":0}
13:04:44.229 [DEBUG] [g.tradfri.internal.TradfriCoapHandler] - CoAP response
options: {"Content-Format":"application/json", "Max-Age":604800}
payload: [65541,65536,65542,65540,65538,65537,65544,65543]
13:04:44.232 [DEBUG] [tradfri.handler.TradfriGatewayHandler] - onUpdate response: [65541,65536,65542,65540,65538,65537,65544,65543]
13:04:44.237 [DEBUG] [g.tradfri.internal.TradfriCoapHandler] - CoAP response
options: {"Content-Format":"application/json", "Max-Age":604800}
payload: {"15009":[{"9003":0}],"9001":"TRADFRI remote control 2","9002":1511897934,"9020":1534305112,"9003":65541,"5750":0,"9054":0,"9019":1,"3":{"3":"1.2.214","0":"IKEA of Sweden","1":"TRADFRI remote control","2":"","6":3,"9":60}}
13:04:44.239 [DEBUG] [tradfri.handler.TradfriGatewayHandler] - requestDeviceDetails response: {"15009":[{"9003":0}],"9001":"TRADFRI remote control 2","9002":1511897934,"9020":1534305112,"9003":65541,"5750":0,"9054":0,"9019":1,"3":{"3":"1.2.214","0":"IKEA of Sweden","1":"TRADFRI remote control","2":"","6":3,"9":60}}
13:04:44.240 [DEBUG] [nal.discovery.TradfriDiscoveryService] - Adding device tradfri:0830:gwdcefcaba8d2b:65541 to inbox
13:04:44.242 [DEBUG] [g.tradfri.internal.TradfriCoapHandler] - CoAP response

GW is back online.

Aug 25 '18 11:08 roben

Just to add, I have the same issue. Gateway is set to a fixed ip via dhcp reservation. I use the DNS fqdn in the binding. If i change the fqdn to something else in the binding and revert back to the proper fqdn of the gateway it comes back online.

Sep 11 '18 17:09 chriscolden

I was also just rebooting the openhab server serveral times yesterday and had to set/reset the ip address of gateway in order to get connected. The gateway was not touched at all (power all time on).

Sep 12 '18 08:09 lukicsl

I think this needs to be reopened. I'm still having this issue. The address has been updated for the ip when I was using the fqdn which I assume is due to this commit, but its still loosing connection a staying lost until i manually change the address, save, edit the up back a save. Thanks.

Sep 23 '18 14:09 chriscolden

@chriscolden Are you sure that you have used the latest code that includes the fix? In case you are using an openHAB snapshot, please note that this fix is only contained in it since build 1370.

Sep 24 '18 06:09 kaikreuzer

Thanks @kaikreuzer. Im on snapshot but one behind that. I'll updated an see how I get on.

Sep 24 '18 06:09 chriscolden

@kaikreuzer are you able to tell me how I can find out when fixes which are merged make it into the builds please? Save me logging issues which I think should be fix but I'm not running them yet. Thanks

Sep 24 '18 06:09 chriscolden

https://github.com/eclipse/smarthome/wiki/ESH-used-in-openHAB

Sep 24 '18 06:09 kaikreuzer

I had a power outage yesterday (OH on UPS but Tradfri down) and can report that Tradfri recovered just fine in my case. Thanks!

Sep 24 '18 07:09 roben

I had it loose the gateway last night. Changing the ip to a false ip and back again, brought the gateway back online, therefore I dont think this has resolved the issue I'm having. Running openhab build 1376.

Sep 30 '18 15:09 chriscolden

Reopening for @chriscolden's request in #6305:

I'm facing an issue where the Tradfri binding looses connection to the gateway after a period of time, usually within a 12 hour period.

I can solve the problem temporarily by changing the ip on the gateway and change it back to the original ip. I believe this is session issue. The session becomes stale and doesn't re initiate.

My tradfri gateway is on a static ip via dhcp reservation.

Gateway version 1.4.15

Additional note: The tradfri mobile app now has notes around this issue. They say if the app cannot connect to the gateway, swipe the app away and reopen. I believe I'm doing the equivalent by changing the ip, forcing the binding to re initiate the session with the gateway.

Please let me know if you need further information. This only started happening recently, possibly because the gateway was updated.

Oct 04 '18 06:10 htreu

smarthome smarthome copied to clipboard

Tradfri binding does not reestablish connection to gateway after connection loss

smarthome
smarthome copied to clipboard