Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

NPE inside NetworkSanityChecker #97

Closed
andreacioni opened this issue Sep 23, 2017 · 11 comments

Comments

Projects
None yet
4 participants
@andreacioni
Copy link

commented Sep 23, 2017

Issue reported by: @doctor64 on MySensors Forum, here below the log:

22:41:33.015 [DEBUG] [rsAbstractConnection$MySensorsWriter] - Sending to MySensors: 0;0;3;0;2;
22:41:33.029 [DEBUG] [rsAbstractConnection$MySensorsReader] - Message from gateway received: 0;255;3;0;2;2.1.1
22:41:36.015 [DEBUG] [ateway.MySensorsNetworkSanityChecker] - Network sanity check: PASSED
22:41:36.015 [DEBUG] [ateway.MySensorsNetworkSanityChecker] - Sending I_HEARTBEAT_REQUESTs
22:41:36.016 [DEBUG] [rsAbstractConnection$MySensorsWriter] - Sending to MySensors: 0;255;3;0;18;
22:41:36.032 [DEBUG] [rsAbstractConnection$MySensorsReader] - Message from gateway received: 0;255;3;0;22;436674305
22:41:36.116 [DEBUG] [rsAbstractConnection$MySensorsWriter] - Sending to MySensors: 1;255;3;0;18;
22:41:36.217 [DEBUG] [rsAbstractConnection$MySensorsWriter] - Sending to MySensors: 2;255;3;0;18;
22:41:36.317 [DEBUG] [rsAbstractConnection$MySensorsWriter] - Sending to MySensors: 3;255;3;0;18;
22:41:36.398 [DEBUG] [rsAbstractConnection$MySensorsReader] - Message from gateway received: 3;255;3;0;22;717683
22:41:36.418 [DEBUG] [rsAbstractConnection$MySensorsWriter] - Sending to MySensors: 4;255;3;0;18;
22:41:36.518 [DEBUG] [rsAbstractConnection$MySensorsWriter] - Sending to MySensors: 5;255;3;0;18;
22:41:36.619 [DEBUG] [rsAbstractConnection$MySensorsWriter] - Sending to MySensors: 6;255;3;0;18;
22:41:36.652 [DEBUG] [rsAbstractConnection$MySensorsReader] - Message from gateway received: 5;255;3;0;22;9428217
22:41:36.683 [DEBUG] [rsAbstractConnection$MySensorsReader] - Message from gateway received: 6;255;3;0;22;3111897
22:41:39.016 [DEBUG] [ateway.MySensorsNetworkSanityChecker] - Node 1 request heartbreat answer, missing null of 10
22:41:39.016 [ERROR] [ateway.MySensorsNetworkSanityChecker] - Exception in network sanity thread checker
java.lang.NullPointerException
at org.openhab.binding.mysensors.internal.gateway.MySensorsNetworkSanityChecker.checkHeartbeatsResponse(MySensorsNetworkSanityChecker.java:178)[195:org.openhab.binding.mysensors:2.2.0.201708090807]
at org.openhab.binding.mysensors.internal.gateway.MySensorsNetworkSanityChecker.run(MySensorsNetworkSanityChecker.java:122)[195:org.openhab.binding.mysensors:2.2.0.201708090807]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)[:1.8.0_144]
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)[:1.8.0_144]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)[:1.8.0_144]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)[:1.8.0_144]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)[:1.8.0_144]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)[:1.8.0_144]
at java.lang.Thread.run(Thread.java:748)[:1.8.0_144]

I've already replicated the issue in my environment. Working on a solution.

@andreacioni

This comment has been minimized.

Copy link
Author

commented Sep 24, 2017

I found a possible cause. missingHearbeatsMap values are never initialized (and incremented). Solution should be easy to fix.

@andreacioni

This comment has been minimized.

Copy link
Author

commented Sep 26, 2017

I've released a temporary snapshot with the fix. If it solve the issue I'll open a PR.

@doctor64

This comment has been minimized.

Copy link

commented Sep 26, 2017

@andreacioni I can test if you wish - but please provide some instructions how to uninstall current binding and install snapshot.

@andreacioni

This comment has been minimized.

Copy link
Author

commented Sep 26, 2017

First you need to shutdown openhab. Then you can replace the previous version of the binding inside addons/ folder with the snapshot provided above. To avoid confusion you can delete the previous mysensors binding and then put the snapshot.
Now you can restart opehab and see if problem is gone. Let me know if you need more help ☺️

@gnalbandian

This comment has been minimized.

Copy link

commented Sep 27, 2017

I'll test it tonight. It would be wise to remove uninstall the binding through OH console, and to remove the mysensors folder from userdata...I will add some coments tonight. thanks

@tobof tobof added the bug label Sep 28, 2017

@doctor64

This comment has been minimized.

Copy link

commented Oct 2, 2017

Sorry for late reply, no free time :(
Seems like problem is fixed, thank you!
21:15:36.796 [DEBUG] [rsAbstractConnection$MySensorsWriter] - Sending to MySensors: 0;0;3;0;2; 21:15:36.805 [DEBUG] [rsAbstractConnection$MySensorsReader] - Message from gateway received: 0;255;3;0;2;2.1.1 21:15:39.797 [DEBUG] [ateway.MySensorsNetworkSanityChecker] - Network sanity check: PASSED 21:15:39.797 [DEBUG] [ateway.MySensorsNetworkSanityChecker] - Sending I_HEARTBEAT_REQUESTs 21:15:39.798 [DEBUG] [rsAbstractConnection$MySensorsWriter] - Sending to MySensors: 0;255;3;0;18; 21:15:39.814 [DEBUG] [rsAbstractConnection$MySensorsReader] - Message from gateway received: 0;255;3;0;22;1689642 21:15:39.899 [DEBUG] [rsAbstractConnection$MySensorsWriter] - Sending to MySensors: 1;255;3;0;18; 21:15:40.000 [DEBUG] [rsAbstractConnection$MySensorsWriter] - Sending to MySensors: 2;255;3;0;18; 21:15:40.100 [DEBUG] [rsAbstractConnection$MySensorsWriter] - Sending to MySensors: 3;255;3;0;18; 21:15:40.180 [DEBUG] [rsAbstractConnection$MySensorsReader] - Message from gateway received: 3;255;3;0;22;1602941 21:15:40.201 [DEBUG] [rsAbstractConnection$MySensorsWriter] - Sending to MySensors: 4;255;3;0;18; 21:15:40.302 [DEBUG] [rsAbstractConnection$MySensorsWriter] - Sending to MySensors: 5;255;3;0;18; 21:15:40.402 [DEBUG] [rsAbstractConnection$MySensorsWriter] - Sending to MySensors: 6;255;3;0;18; 21:15:40.436 [DEBUG] [rsAbstractConnection$MySensorsReader] - Message from gateway received: 5;255;3;0;22;80159209 21:15:40.457 [DEBUG] [rsAbstractConnection$MySensorsReader] - Message from gateway received: 6;255;3;0;22;258638 21:15:41.655 [INFO ] [marthome.event.ItemStateChangedEvent] - Temperature_Outside changed from 12.5 to 12.4 21:15:41.657 [INFO ] [marthome.event.ItemStateChangedEvent] - Humidity_Outside changed from 64 to 65 21:15:42.799 [DEBUG] [ateway.MySensorsNetworkSanityChecker] - Node 1 is not receiving hearbeat response (miss 1 of 10) 21:15:42.799 [DEBUG] [ateway.MySensorsNetworkSanityChecker] - Node 2 is not receiving hearbeat response (miss 1 of 10) 21:15:42.799 [DEBUG] [ateway.MySensorsNetworkSanityChecker] - Node 3 received heartbeat response, ok... 21:15:42.800 [DEBUG] [ateway.MySensorsNetworkSanityChecker] - Node 4 is not receiving hearbeat response (miss 1 of 10) 21:15:42.800 [DEBUG] [ateway.MySensorsNetworkSanityChecker] - Node 6 received heartbeat response, ok... 21:15:42.800 [WARN ] [ateway.MySensorsNetworkSanityChecker] - Check expected update can't be performed on node {} if request heartbeat is active. 21:15:42.800 [WARN ] [ateway.MySensorsNetworkSanityChecker] - Check expected update can't be performed on node {} if request heartbeat is active. 21:15:42.800 [WARN ] [ateway.MySensorsNetworkSanityChecker] - Check expected update can't be performed on node {} if request heartbeat is active. 21:15:42.800 [WARN ] [ateway.MySensorsNetworkSanityChecker] - Check expected update can't be performed on node {} if request heartbeat is active. 21:15:42.800 [WARN ] [ateway.MySensorsNetworkSanityChecker] - Check expected update can't be performed on node {} if request heartbeat is active.

@doctor64

This comment has been minimized.

Copy link

commented Oct 2, 2017

Unfortunately, another exception, not sure if it related to current.
How to reproduce:
1: made any change to bridge configuration.
2: restart sensor
'21:23:05.763 [DEBUG] [rsAbstractConnection$MySensorsReader] - Message from gateway received: 6;255;0;0;17;2.1.1
21:23:05.763 [DEBUG] [rs.internal.gateway.MySensorsGateway] - Presentation Message received
21:23:05.764 [DEBUG] [ensors.factory.MySensorsCacheFactory] - Writing on cache given_ids, content: [0,1,2,3,4,5,6]
21:23:05.765 [WARN ] [.discovery.MySensorsDiscoveryService] - Cannot automatic discover thing node: 6, child: 255 please insert it manually
21:23:05.775 [DEBUG] [rsAbstractConnection$MySensorsReader] - Message from gateway received: 6;255;3;0;6;0
21:23:05.776 [DEBUG] [rs.internal.gateway.MySensorsGateway] - I_CONFIG request received from M, answering: (is imperial?)false
21:23:05.776 [DEBUG] [rsAbstractConnection$MySensorsWriter] - Sending to MySensors: 6;255;3;0;6;M
21:23:05.807 [DEBUG] [rsAbstractConnection$MySensorsReader] - Message from gateway received: 6;255;3;0;11;Ikea Ansluta Light
21:23:05.817 [DEBUG] [rsAbstractConnection$MySensorsReader] - Message from gateway received: 6;255;3;0;12;1.0
21:23:05.828 [DEBUG] [rsAbstractConnection$MySensorsReader] - Message from gateway received: 6;0;0;0;4;
21:23:05.828 [DEBUG] [rs.internal.gateway.MySensorsGateway] - Presentation Message received
21:23:05.829 [DEBUG] [ensors.factory.MySensorsCacheFactory] - Writing on cache given_ids, content: [0,1,2,3,4,5,6]
21:23:05.830 [DEBUG] [.discovery.MySensorsDiscoveryService] - Preparing new thing for inbox: mysensors:dimmer
21:23:05.838 [DEBUG] [sensors.internal.event.EventRegister] - Listener org.openhab.binding.mysensors.handler.MySensorsThingHandler@4464578c not present, cannot remove it
21:23:05.838 [DEBUG] [ensors.handler.MySensorsThingHandler] - Configuration: MySensorsSensorConfiguration [nodeId=6, childId=0, requestAck=true, revertState=true, smartSleep=false, childUpdateTimeout=1, nodeUpdateTimeout=1, requestHeartbeatResponse=true]
21:23:05.839 [DEBUG] [rs.internal.gateway.MySensorsGateway] - Merging child map: {0=MySensorsChild [childId=0, nodeValue={V_VAR3=MySensorsVariableVVar3 [value=null], V_VAR4=MySensorsVariableVVar4 [value=null], V_STATUS=MySensorsVariableVStatus [value=null], V_VAR1=MySensorsVariableVVar1 [value=null], V_PERCENTAGE=MySensorsVariableVPercentage [value=null], V_VAR2=MySensorsVariableVVar2 [value=null], V_VAR5=MySensorsVariableVVar5 [value=null], V_WATT=MySensorsVariableVWatt [value=null]}], 255=MySensorsChild [childId=255, nodeValue={V_VAR3=MySensorsVariableVVar3 [value=null], V_VAR4=MySensorsVariableVVar4 [value=null], V_VAR1=MySensorsVariableVVar1 [value=null], V_VAR2=MySensorsVariableVVar2 [value=null], V_VAR5=MySensorsVariableVVar5 [value=null]}]} with: {0=MySensorsChild [childId=0, nodeValue={V_VAR3=MySensorsVariableVVar3 [value=null], V_VAR4=MySensorsVariableVVar4 [value=null], V_STATUS=MySensorsVariableVStatus [value=null], V_VAR1=MySensorsVariableVVar1 [value=null], V_PERCENTAGE=MySensorsVariableVPercentage [value=null], V_VAR2=MySensorsVariableVVar2 [value=null], V_VAR5=MySensorsVariableVVar5 [value=null], V_WATT=MySensorsVariableVWatt [value=null]}]}
21:23:10.842 [ERROR] [ome.core.thing.internal.ThingManager] - Exception occured while calling thing updated at ThingHandler 'org.openhab.binding.mysensors.handler.MySensorsThingHandler@4464578c': null
java.util.concurrent.TimeoutException
at java.util.concurrent.FutureTask.get(FutureTask.java:205)[:1.8.0_144]
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.thingUpdated(ThingManager.java:518)
at org.eclipse.smarthome.core.thing.internal.ThingRegistryImpl.notifyTrackers(ThingRegistryImpl.java:227)
at org.eclipse.smarthome.core.thing.internal.ThingRegistryImpl.notifyListenersAboutUpdatedElement(ThingRegistryImpl.java:150)
at org.eclipse.smarthome.core.thing.internal.ThingRegistryImpl.notifyListenersAboutUpdatedElement(ThingRegistryImpl.java:1)
at org.eclipse.smarthome.core.common.registry.AbstractRegistry.updated(AbstractRegistry.java:167)[98:org.eclipse.smarthome.core:0.9.0.b3]
at org.eclipse.smarthome.core.common.registry.AbstractProvider.notifyListeners(AbstractProvider.java:57)[98:org.eclipse.smarthome.core:0.9.0.b3]
at org.eclipse.smarthome.core.common.registry.AbstractProvider.notifyListenersAboutUpdatedElement(AbstractProvider.java:82)[98:org.eclipse.smarthome.core:0.9.0.b3]
at org.eclipse.smarthome.core.common.registry.AbstractManagedProvider.update(AbstractManagedProvider.java:134)[98:org.eclipse.smarthome.core:0.9.0.b3]
at org.eclipse.smarthome.config.discovery.internal.PersistentInbox.add(PersistentInbox.java:204)[95:org.eclipse.smarthome.config.discovery:0.9.0.b3]
at org.eclipse.smarthome.config.discovery.internal.PersistentInbox.thingDiscovered(PersistentInbox.java:293)[95:org.eclipse.smarthome.config.discovery:0.9.0.b3]
at org.eclipse.smarthome.config.discovery.internal.DiscoveryServiceRegistryImpl$2.run(DiscoveryServiceRegistryImpl.java:269)[95:org.eclipse.smarthome.config.discovery:0.9.0.b3]
at org.eclipse.smarthome.config.discovery.internal.DiscoveryServiceRegistryImpl$2.run(DiscoveryServiceRegistryImpl.java:1)[95:org.eclipse.smarthome.config.discovery:0.9.0.b3]
at java.security.AccessController.doPrivileged(Native Method)[:1.8.0_144]
at org.eclipse.smarthome.config.discovery.internal.DiscoveryServiceRegistryImpl.thingDiscovered(DiscoveryServiceRegistryImpl.java:266)
at org.eclipse.smarthome.config.discovery.AbstractDiscoveryService.thingDiscovered(AbstractDiscoveryService.java:253)
at org.openhab.binding.mysensors.discovery.MySensorsDiscoveryService.newDevicePresented(MySensorsDiscoveryService.java:95)
at org.openhab.binding.mysensors.discovery.MySensorsDiscoveryService.newNodeDiscovered(MySensorsDiscoveryService.java:107)
at org.openhab.binding.mysensors.internal.event.MySensorsEventRegister.lambda$2(MySensorsEventRegister.java:100)[198:org.openhab.binding.mysensors:2.2.0.201709261755]
at java.lang.Iterable.forEach(Iterable.java:75)[:1.8.0_144]
at org.openhab.binding.mysensors.internal.event.MySensorsEventRegister.notifyNewNodeDiscovered(MySensorsEventRegister.java:96)[198:org.openhab.binding.mysensors:2.2.0.201709261755]
at org.openhab.binding.mysensors.internal.gateway.MySensorsGateway.handlePresentationMessage(MySensorsGateway.java:535)[198:org.openhab.binding.mysensors:2.2.0.201709261755]
at org.openhab.binding.mysensors.internal.gateway.MySensorsGateway.handleIncomingMessage(MySensorsGateway.java:463)[198:org.openhab.binding.mysensors:2.2.0.201709261755]
at org.openhab.binding.mysensors.internal.gateway.MySensorsGateway.messageReceived(MySensorsGateway.java:372)[198:org.openhab.binding.mysensors:2.2.0.201709261755]
at org.openhab.binding.mysensors.internal.event.MySensorsEventRegister.lambda$1(MySensorsEventRegister.java:85)[198:org.openhab.binding.mysensors:2.2.0.201709261755]
at java.lang.Iterable.forEach(Iterable.java:75)[:1.8.0_144]
at org.openhab.binding.mysensors.internal.event.MySensorsEventRegister.notifyMessageReceived(MySensorsEventRegister.java:81)[198:org.openhab.binding.mysensors:2.2.0.201709261755]
at org.openhab.binding.mysensors.internal.protocol.MySensorsAbstractConnection$MySensorsReader.run(MySensorsAbstractConnection.java:365)[198:org.openhab.binding.mysensors:2.2.0.201709261755]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)[:1.8.0_144]
at java.util.concurrent.FutureTask.run(FutureTask.java:266)[:1.8.0_144]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)[:1.8.0_144]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)[:1.8.0_144]
at java.lang.Thread.run(Thread.java:748)[:1.8.0_144]
'

@doctor64

This comment has been minimized.

Copy link

commented Oct 2, 2017

Additional note - after restarting OH2 rebooting a sensor works as expected, no exceptions observed

@andreacioni

This comment has been minimized.

Copy link
Author

commented Oct 2, 2017

Last exception is probably not related to NetworkSanityChecker. Now I made a PR (#99) with heartbeat fixes and then I'll look into the last exception. Thank you for reporting all this issues 👍

@gnalbandian

This comment has been minimized.

Copy link

commented Oct 10, 2017

Latest snapshot is working fine for me. This issue can be closed.

@andreacioni

This comment has been minimized.

Copy link
Author

commented Oct 10, 2017

Waiting PR merge to close this issue👍🏼. Thank you!

@tobof tobof closed this Oct 12, 2017

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.