Skip to content
This repository has been archived by the owner on May 7, 2020. It is now read-only.

Child things missing handler when removing bridge #2757

Closed
mherwege opened this issue Jan 5, 2017 · 12 comments · Fixed by #2908
Closed

Child things missing handler when removing bridge #2757

mherwege opened this issue Jan 5, 2017 · 12 comments · Fixed by #2908

Comments

@mherwege
Copy link
Contributor

mherwege commented Jan 5, 2017

In developing my own binding (pull request #1589) I am hitting an issue when removing a bridge. When I remove the bridge, it gets removed correctly, but the child things are not removed. They go to an uninitialized state. Discovery results attached to the bridge are also removed. I am probably missing something in my coding, but was expecting child things to get removed before the bridge was removed. Note that the exception also appears for the bridge, but the bridge does get removed.

Any suggestions on what I need to do?

Here is the log:

2017-01-05 12:17:14.020 [DEBUG] [.c.thing.internal.ThingManager:929  ] - Removal handling of thing 'nikohomecontrol:bridge:0f2c6f05' completed. Going to remove it now.
2017-01-05 12:17:14.021 [DEBUG] [.core.common.ThreadPoolManager:145  ] - Created thread pool 'forceRemove' with size 5
2017-01-05 12:17:14.022 [INFO ] [nt.ThingStatusInfoChangedEvent:43   ] - 'nikohomecontrol:bridge:0f2c6f05' changed from ONLINE to REMOVING
2017-01-05 12:17:14.025 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:bridge:0f2c6f05' updated: REMOVED
2017-01-05 12:17:14.027 [INFO ] [nt.ThingStatusInfoChangedEvent:43   ] - 'nikohomecontrol:bridge:0f2c6f05' changed from REMOVING to REMOVED
2017-01-05 12:17:14.031 [INFO ] [rthome.event.InboxRemovedEvent:43   ] - Discovery Result with UID 'nikohomecontrol:onOff:0f2c6f05:4' has been removed.
2017-01-05 12:17:14.035 [INFO ] [rthome.event.InboxRemovedEvent:43   ] - Discovery Result with UID 'nikohomecontrol:onOff:0f2c6f05:7' has been removed.
...
2017-01-05 12:17:14.367 [INFO ] [rthome.event.InboxRemovedEvent:43   ] - Discovery Result with UID 'nikohomecontrol:onOff:0f2c6f05:31' has been removed.
2017-01-05 12:17:14.367 [DEBUG] [.c.thing.internal.ThingManager:473  ] - Thing 'nikohomecontrol:bridge:0f2c6f05' is no longer tracked by ThingManager.
2017-01-05 12:17:14.369 [DEBUG] [.c.thing.internal.ThingManager:823  ] - Unregister and dispose child 'nikohomecontrol:onOff:0f2c6f05:25' of bridge 'nikohomecontrol:bridge:0f2c6f05'.
2017-01-05 12:17:14.369 [DEBUG] [.c.thing.internal.ThingManager:768  ] - Calling unregisterHandler handler for thing 'nikohomecontrol:onOff:0f2c6f05:25' at 'org.openhab.binding.nikohomecontrol.internal.NikoHomeControlHandlerFactory@231c58e3'.
2017-01-05 12:17:14.371 [DEBUG] [.c.thing.internal.ThingManager:800  ] - Calling dispose handler for thing 'nikohomecontrol:onOff:0f2c6f05:25' at 'org.openhab.binding.nikohomecontrol.handler.NikoHomeControlHandler@3302dfb9'.
2017-01-05 12:17:14.372 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:onOff:0f2c6f05:25' updated: UNINITIALIZED (HANDLER_MISSING_ERROR)
2017-01-05 12:17:14.380 [ERROR] [.c.thing.internal.ThingManager:813  ] - Exception occured while disposing handler of thing 'nikohomecontrol:onOff:0f2c6f05:25': java.lang.IllegalStateException: Could not update status, because callback is missingjava.util.concurrent.ExecutionException: java.lang.IllegalStateException: Could not update status, because callback is missing
	at java.util.concurrent.FutureTask.report(Unknown Source)
	at java.util.concurrent.FutureTask.get(Unknown Source)
	at org.eclipse.smarthome.core.common.SafeMethodCaller.callAsynchronous(SafeMethodCaller.java:188)
	at org.eclipse.smarthome.core.common.SafeMethodCaller.call(SafeMethodCaller.java:81)
	at org.eclipse.smarthome.core.common.SafeMethodCaller.call(SafeMethodCaller.java:65)
	at org.eclipse.smarthome.core.thing.internal.ThingManager.doDisposeHandler(ThingManager.java:802)
	at org.eclipse.smarthome.core.thing.internal.ThingManager.disposeHandler(ThingManager.java:792)
	at org.eclipse.smarthome.core.thing.internal.ThingManager.unregisterChildHandlers(ThingManager.java:825)
	at org.eclipse.smarthome.core.thing.internal.ThingManager.unregisterHandler(ThingManager.java:760)
	at org.eclipse.smarthome.core.thing.internal.ThingManager.thingRemoved(ThingManager.java:479)
	at org.eclipse.smarthome.core.thing.internal.ThingRegistryImpl.notifyTrackers(ThingRegistryImpl.java:224)
Caused by: java.lang.IllegalStateException: Could not update status, because callback is missing
	at org.eclipse.smarthome.core.thing.binding.BaseThingHandler.updateStatus(BaseThingHandler.java:388)
	at org.eclipse.smarthome.core.thing.binding.BaseThingHandler.updateStatus(BaseThingHandler.java:415)
	at org.openhab.binding.nikohomecontrol.handler.NikoHomeControlHandler.dispose(NikoHomeControlHandler.java:122)
	at org.eclipse.smarthome.core.thing.internal.ThingManager$11.call(ThingManager.java:805)
	at org.eclipse.smarthome.core.thing.internal.ThingManager$11.call(ThingManager.java:1)
	at org.eclipse.smarthome.core.common.SafeMethodCaller$CallableWrapper.call(SafeMethodCaller.java:179)
	at java.util.concurrent.FutureTask.run(Unknown Source)
	... 3 common frames omitted

2017-01-05 12:17:14.381 [INFO ] [nt.ThingStatusInfoChangedEvent:43   ] - 'nikohomecontrol:onOff:0f2c6f05:25' changed from ONLINE to UNINITIALIZED (HANDLER_MISSING_ERROR)
2017-01-05 12:17:14.381 [DEBUG] [.c.thing.internal.ThingManager:768  ] - Calling unregisterHandler handler for thing 'nikohomecontrol:bridge:0f2c6f05' at 'org.openhab.binding.nikohomecontrol.internal.NikoHomeControlHandlerFactory@231c58e3'.
2017-01-05 12:17:14.385 [DEBUG] [.c.thing.internal.ThingManager:800  ] - Calling dispose handler for thing 'nikohomecontrol:bridge:0f2c6f05' at 'org.openhab.binding.nikohomecontrol.handler.NikoHomeControlBridgeHandler@274627cd'.
2017-01-05 12:17:14.386 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:bridge:0f2c6f05' updated: UNINITIALIZED (HANDLER_MISSING_ERROR)
2017-01-05 12:17:14.390 [ERROR] [.c.thing.internal.ThingManager:813  ] - Exception occured while disposing handler of thing 'nikohomecontrol:bridge:0f2c6f05': java.lang.IllegalStateException: Could not update status, because callback is missingjava.util.concurrent.ExecutionException: java.lang.IllegalStateException: Could not update status, because callback is missing
	at java.util.concurrent.FutureTask.report(Unknown Source)
	at java.util.concurrent.FutureTask.get(Unknown Source)
	at org.eclipse.smarthome.core.common.SafeMethodCaller.callAsynchronous(SafeMethodCaller.java:188)
	at org.eclipse.smarthome.core.common.SafeMethodCaller.call(SafeMethodCaller.java:81)
	at org.eclipse.smarthome.core.common.SafeMethodCaller.call(SafeMethodCaller.java:65)
	at org.eclipse.smarthome.core.thing.internal.ThingManager.doDisposeHandler(ThingManager.java:802)
	at org.eclipse.smarthome.core.thing.internal.ThingManager.disposeHandler(ThingManager.java:792)
	at org.eclipse.smarthome.core.thing.internal.ThingManager.thingRemoved(ThingManager.java:480)
	at org.eclipse.smarthome.core.thing.internal.ThingRegistryImpl.notifyTrackers(ThingRegistryImpl.java:224)
	at org.eclipse.smarthome.core.thing.internal.ThingRegistryImpl.notifyListenersAboutRemovedElement(ThingRegistryImpl.java:143)
	at org.eclipse.smarthome.core.thing.internal.ThingRegistryImpl.notifyListenersAboutRemovedElement(ThingRegistryImpl.java:1)
Caused by: java.lang.IllegalStateException: Could not update status, because callback is missing
	at org.eclipse.smarthome.core.thing.binding.BaseThingHandler.updateStatus(BaseThingHandler.java:388)
	at org.eclipse.smarthome.core.thing.binding.BaseThingHandler.updateStatus(BaseThingHandler.java:415)
	at org.openhab.binding.nikohomecontrol.handler.NikoHomeControlBridgeHandler.dispose(NikoHomeControlBridgeHandler.java:135)
	at org.eclipse.smarthome.core.thing.internal.ThingManager$11.call(ThingManager.java:805)
	at org.eclipse.smarthome.core.thing.internal.ThingManager$11.call(ThingManager.java:1)
	at org.eclipse.smarthome.core.common.SafeMethodCaller$CallableWrapper.call(SafeMethodCaller.java:179)
	at java.util.concurrent.FutureTask.run(Unknown Source)
	... 3 common frames omitted

2017-01-05 12:17:14.390 [INFO ] [nt.ThingStatusInfoChangedEvent:43   ] - 'nikohomecontrol:bridge:0f2c6f05' changed from REMOVED to UNINITIALIZED (HANDLER_MISSING_ERROR)
2017-01-05 12:17:14.391 [DEBUG] [.c.c.r.AbstractManagedProvider:115  ] - Removed element nikohomecontrol:bridge:0f2c6f05 from ManagedThingProvider.
2017-01-05 12:17:14.391 [INFO ] [rthome.event.ThingRemovedEvent:43   ] - Thing 'nikohomecontrol:bridge:0f2c6f05' has been removed.
@kaikreuzer
Copy link
Contributor

Any suggestions on what I need to do?

Looks like a bug in your implementation. Note that you must not call updateStatus from the dispose method.

@mherwege
Copy link
Contributor Author

mherwege commented Jan 5, 2017

@kaikreuzer Thank you for your quick reply. I have no updateStatus in my dispose methods. I only have a dispose method for the bridge, not for the connected things. I do expect this to be an implementation error on my side, but can't figure out what it could be. I was assuming that if there is no dispose method and my classes extend BaseBridgeHandler and BaseThingHandler respectively, removal should work.

@kaikreuzer
Copy link
Contributor

@mherwege
Copy link
Contributor Author

mherwege commented Jan 5, 2017

@kaikreuzer Correct for the pushed version, not anymore in my offline private copy. I removed that when solving another issue I discovered. It was just not ready for another push yet. Sorry for the misunderstanding.

@kaikreuzer
Copy link
Contributor

But you exception from above is clearly from that code.
So if you think you have updated it and you still have an issue, post a new log here.

@mherwege
Copy link
Contributor Author

mherwege commented Jan 6, 2017

@kaikreuzer Below is a new log file. Removal of the updateStatus call got rid of the exception. However, the child thing is still not removed when removing the bridge. So in the paperUI, the net result is the same. I have the bridge thing removed and a child thing is remaining in state uninitialized.

I appreciate all your effort on this.

2017-01-06 08:28:05.704 [DEBUG] [.c.thing.internal.ThingManager:929  ] - Removal handling of thing 'nikohomecontrol:bridge:031aa577' completed. Going to remove it now.
2017-01-06 08:28:05.708 [DEBUG] [.core.common.ThreadPoolManager:145  ] - Created thread pool 'forceRemove' with size 5
2017-01-06 08:28:05.712 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:bridge:031aa577' updated: REMOVING
2017-01-06 08:28:05.716 [INFO ] [nt.ThingStatusInfoChangedEvent:43   ] - 'nikohomecontrol:bridge:031aa577' changed from ONLINE to REMOVING
2017-01-06 08:28:05.718 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:bridge:031aa577' updated: REMOVED
2017-01-06 08:28:05.722 [INFO ] [nt.ThingStatusInfoChangedEvent:43   ] - 'nikohomecontrol:bridge:031aa577' changed from REMOVING to REMOVED
2017-01-06 08:28:05.746 [INFO ] [rthome.event.InboxRemovedEvent:43   ] - Discovery Result with UID 'nikohomecontrol:onOff:031aa577:17' has been removed.
2017-01-06 08:28:05.762 [INFO ] [rthome.event.InboxRemovedEvent:43   ] - Discovery Result with UID 'nikohomecontrol:onOff:031aa577:18' has been removed.
...
2017-01-06 08:28:06.221 [INFO ] [rthome.event.InboxRemovedEvent:43   ] - Discovery Result with UID 'nikohomecontrol:onOff:031aa577:41' has been removed.
2017-01-06 08:28:06.221 [DEBUG] [.c.thing.internal.ThingManager:473  ] - Thing 'nikohomecontrol:bridge:031aa577' is no longer tracked by ThingManager.
2017-01-06 08:28:06.222 [DEBUG] [.c.thing.internal.ThingManager:823  ] - Unregister and dispose child 'nikohomecontrol:dimmer:031aa577:35' of bridge 'nikohomecontrol:bridge:031aa577'.
2017-01-06 08:28:06.222 [DEBUG] [.c.thing.internal.ThingManager:768  ] - Calling unregisterHandler handler for thing 'nikohomecontrol:dimmer:031aa577:35' at 'org.openhab.binding.nikohomecontrol.internal.NikoHomeControlHandlerFactory@723c2032'.
2017-01-06 08:28:06.223 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:dimmer:031aa577:35' updated: UNINITIALIZED (HANDLER_MISSING_ERROR)
2017-01-06 08:28:06.223 [DEBUG] [.c.thing.internal.ThingManager:800  ] - Calling dispose handler for thing 'nikohomecontrol:dimmer:031aa577:35' at 'org.openhab.binding.nikohomecontrol.handler.NikoHomeControlHandler@43615e0c'.
2017-01-06 08:28:06.223 [INFO ] [nt.ThingStatusInfoChangedEvent:43   ] - 'nikohomecontrol:dimmer:031aa577:35' changed from ONLINE to UNINITIALIZED (HANDLER_MISSING_ERROR)
2017-01-06 08:28:06.223 [DEBUG] [.c.thing.internal.ThingManager:768  ] - Calling unregisterHandler handler for thing 'nikohomecontrol:bridge:031aa577' at 'org.openhab.binding.nikohomecontrol.internal.NikoHomeControlHandlerFactory@723c2032'.
2017-01-06 08:28:06.227 [DEBUG] [.c.thing.internal.ThingManager:800  ] - Calling dispose handler for thing 'nikohomecontrol:bridge:031aa577' at 'org.openhab.binding.nikohomecontrol.handler.NikoHomeControlBridgeHandler@2530a3b2'.
2017-01-06 08:28:06.227 [INFO ] [ome.event.ThingStatusInfoEvent:43   ] - 'nikohomecontrol:bridge:031aa577' updated: UNINITIALIZED (HANDLER_MISSING_ERROR)
2017-01-06 08:28:06.227 [DEBUG] [p.NikoHomeControlCommunication:300  ] - Niko Home Control: stopped listening for events
2017-01-06 08:28:06.227 [WARN ] [p.NikoHomeControlCommunication:289  ] - Niko Home Control: communication stopped
2017-01-06 08:28:06.227 [WARN ] [p.NikoHomeControlCommunication:263  ] - Niko Home Control: IO error
2017-01-06 08:28:06.227 [WARN ] [p.NikoHomeControlCommunication:289  ] - Niko Home Control: communication stopped
2017-01-06 08:28:06.227 [INFO ] [nt.ThingStatusInfoChangedEvent:43   ] - 'nikohomecontrol:bridge:031aa577' changed from REMOVED to UNINITIALIZED (HANDLER_MISSING_ERROR)
2017-01-06 08:28:06.227 [DEBUG] [.c.c.r.AbstractManagedProvider:115  ] - Removed element nikohomecontrol:bridge:031aa577 from ManagedThingProvider.
2017-01-06 08:28:06.231 [INFO ] [rthome.event.ThingRemovedEvent:43   ] - Thing 'nikohomecontrol:bridge:031aa577' has been removed.

@mherwege mherwege changed the title Things missing handler when removing Child things missing handler when removing bridge Jan 6, 2017
@mherwege
Copy link
Contributor Author

mherwege commented Jan 6, 2017

I have now updated the PR with my most recent code changes. The issue is still there.

@maggu2810
Copy link
Contributor

Why should a thing be removed if the bridge is removed at all?

@kaikreuzer
Copy link
Contributor

There is indeed no mechanism that would remove a thing in such a case.
It can be discussed whether such a feature should be introduced or not (see also #1763, which asks for the same), but it clearly is no bug in the current code.

@mherwege
Copy link
Contributor Author

mherwege commented Jan 8, 2017

I cannot judge all consequences. In my case, the child items are left without any meaning and in an unitialized state (see log, handler missing). That does not make sense in my specific case. The things stop having a meaning when the bridge gets removed. They cannot do anything on their own.
I could add code to remove the child things before removing the bridge, but that may create an inconsistent experience with the behaviour in other bindings.
If I don't add the code, I would have manually remove the child items, or reattach to a newly created bridge thing one by one, rather than using auto-discovery to rediscover all child things.
It could all work for me, but indeed open for debate and to be decided by all that have a longer experience and deeper knowledge on this topic than I have.

@J-N-K
Copy link
Contributor

J-N-K commented Jan 13, 2017

No, please don't remove things automatically (unless they where dynamically created by the bridge). The UNINITIALIZED state is fine. You can always assign a new bridge to the existing things and they start working again. Deleting them would require a lot of work to re-create them (especially for things that can't be auto-discovered).

Maybe (I didn't look in the code if something like this is already there) we could add a comment to the UNINITIALIZED state (like the OFFLINE state has), which states "bridge not available" to make it more clear why the thing is in uninitalized state.

@magcode
Copy link

magcode commented Jan 16, 2017

Anyone has a real code example on how to remove the things? (Assuming this is totally fine as the bridge would recreate the things immediately when it comes back)

sjsf pushed a commit to sjsf/smarthome that referenced this issue Jan 26, 2017
Initialization of ThingHandlers happens in the following order:
* Thing -> INITIALIZING
* BaseThingHandler gets the callback injected
* ThingHandler.initialize()
* Thing -> ONLINE/OFFLINE/UNKNOWN

The shudown however so far first removed the callback, and then called
ThingHandler.destroy(). As a result, the ThingHandler did not get the
chance to clean up first and could run into situations where it
tried to e.g. send events but the callback was already missing.

Hence the shudown process with this change becomes the exact reverse:
* Thing -> UNITIALIZED (so that it's not used anymore)
* ThingHandler.destroy()
* BaseThingHandler gets the callback "un"injected
* Thing -> UNINITIALIZED (HANDLER_MISSING)

fixes eclipse-archived#2757
fixes eclipse-archived#1338
Signed-off-by: Simon Kaufmann <[email protected]>
sjsf pushed a commit to sjsf/smarthome that referenced this issue Jan 27, 2017
Initialization of ThingHandlers happens in the following order:
* Thing -> INITIALIZING
* BaseThingHandler gets the callback injected
* ThingHandler.initialize()
* Thing -> ONLINE/OFFLINE/UNKNOWN

The shudown however so far first removed the callback, and then called
ThingHandler.destroy(). As a result, the ThingHandler did not get the
chance to clean up first and could run into situations where it
tried to e.g. send events but the callback was already missing.

Hence the shudown process with this change becomes the exact reverse:
* Thing -> UNITIALIZED (so that it's not used anymore)
* ThingHandler.destroy()
* BaseThingHandler gets the callback "un"injected
* Thing -> UNINITIALIZED (HANDLER_MISSING)

fixes eclipse-archived#2757
fixes eclipse-archived#1338
Signed-off-by: Simon Kaufmann <[email protected]>
sjsf pushed a commit to sjsf/smarthome that referenced this issue Jan 27, 2017
Initialization of ThingHandlers happens in the following order:
* Thing -> INITIALIZING
* BaseThingHandler gets the callback injected
* ThingHandler.initialize()
* Thing -> ONLINE/OFFLINE/UNKNOWN

The shudown however so far first removed the callback, and then called
ThingHandler.destroy(). As a result, the ThingHandler did not get the
chance to clean up first and could run into situations where it
tried to e.g. send events but the callback was already missing.

Hence the shudown process with this change becomes the exact reverse:
* Thing -> UNITIALIZED (so that it's not used anymore)
* ThingHandler.destroy()
* BaseThingHandler gets the callback "un"injected
* Thing -> UNINITIALIZED (HANDLER_MISSING)

fixes eclipse-archived#2757
fixes eclipse-archived#1338
Signed-off-by: Simon Kaufmann <[email protected]>
kaikreuzer pushed a commit that referenced this issue Jan 30, 2017
Initialization of ThingHandlers happens in the following order:
* Thing -> INITIALIZING
* BaseThingHandler gets the callback injected
* ThingHandler.initialize()
* Thing -> ONLINE/OFFLINE/UNKNOWN

The shudown however so far first removed the callback, and then called
ThingHandler.destroy(). As a result, the ThingHandler did not get the
chance to clean up first and could run into situations where it
tried to e.g. send events but the callback was already missing.

Hence the shudown process with this change becomes the exact reverse:
* Thing -> UNITIALIZED (so that it's not used anymore)
* ThingHandler.destroy()
* BaseThingHandler gets the callback "un"injected
* Thing -> UNINITIALIZED (HANDLER_MISSING)

fixes #2757
fixes #1338
Signed-off-by: Simon Kaufmann <[email protected]>
chaton78 pushed a commit to chaton78/smarthome that referenced this issue May 7, 2017
)

Initialization of ThingHandlers happens in the following order:
* Thing -> INITIALIZING
* BaseThingHandler gets the callback injected
* ThingHandler.initialize()
* Thing -> ONLINE/OFFLINE/UNKNOWN

The shudown however so far first removed the callback, and then called
ThingHandler.destroy(). As a result, the ThingHandler did not get the
chance to clean up first and could run into situations where it
tried to e.g. send events but the callback was already missing.

Hence the shudown process with this change becomes the exact reverse:
* Thing -> UNITIALIZED (so that it's not used anymore)
* ThingHandler.destroy()
* BaseThingHandler gets the callback "un"injected
* Thing -> UNINITIALIZED (HANDLER_MISSING)

fixes eclipse-archived#2757
fixes eclipse-archived#1338
Signed-off-by: Simon Kaufmann <[email protected]>
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
None yet
Projects
None yet
Development

Successfully merging a pull request may close this issue.

5 participants