NPE inside NetworkSanityChecker

[andreacioni]

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]

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

[andreacioni]

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

[doctor64]

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

[andreacioni]

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]

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

[doctor64]

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]

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]

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

[andreacioni]

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]

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

[andreacioni]

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