Zigbee - NullPointer Exceptions

Tveitane · May 3, 2023, 6:21pm

Platform information:
- OS: Windows 11
- Java Runtime Environment: zulu11.64.19-ca-jdk11.0.19-win_x64
- openHAB version: 3.4.3
  I am setting up a test system around a Sonoff Zigbee 3.0 USB Dongle Plus (E-type, firmware version 6.10.3.0) (Ember coordinator) . I have successfully added a couple of sviches/relay modules. Today I have tried to add this thermometer/hygromether module: https://www.amazon.it/dp/B0B87FNG7B?psc=1&ref=ppx_yo2ov_dt_b_product_details (an inexpensive combined thermoneter/hygrometer). It was detected and set up ok, and seems to work ok too. But I have started to get a large collection of warning and error messages and exceptions in openhab.log.

Warnings (a lot of these):
2023-05-03 18:13:48.440 [WARN ] [nding.zigbee.serial.ZigBeeSerialPort] - Processing DATA_AVAILABLE event: Serial buffer overrun

And exceptions (also quit a few):
2023-05-03 16:57:25.341 [ERROR] [st.antlr.ContentAssistContextFactory] - java.lang.RuntimeException: java.lang.NullPointerException java.util.concurrent.ExecutionException: java.lang.RuntimeException: java.lang.NullPointerException at java.util.concurrent.FutureTask.report(FutureTask.java:122) ~[?:?] at java.util.concurrent.FutureTask.get(FutureTask.java:191) ~[?:?] at org.eclipse.xtext.ide.editor.contentassist.antlr.ContentAssistContextFactory.doCreateContexts(ContentAssistContextFactory.java:181) ~[?:?] at org.eclipse.xtext.ide.editor.contentassist.antlr.ContentAssistContextFactory.create(ContentAssistContextFactory.java:131) ~[?:?] at org.eclipse.xtext.ide.server.contentassist.ContentAssistService.createProposals(ContentAssistService.java:104) ~[?:?] at org.eclipse.xtext.ide.server.contentassist.ContentAssistService.createCompletionList(ContentAssistService.java:78) ~[?:?] at org.eclipse.xtext.ide.server.LanguageServerImpl.lambda$completion$23(LanguageServerImpl.java:555) ~[?:?] at org.eclipse.xtext.ide.server.WorkspaceManager.doRead(WorkspaceManager.java:438) ~[?:?] at org.eclipse.xtext.ide.server.LanguageServerImpl.completion(LanguageServerImpl.java:554) ~[?:?] at org.eclipse.xtext.ide.server.LanguageServerImpl.lambda$completion$22(LanguageServerImpl.java:540) ~[?:?] at org.eclipse.xtext.ide.server.concurrent.ReadRequest.lambda$doRun$0(ReadRequest.java:66) ~[?:?] at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [?:?] at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?] at java.lang.Thread.run(Thread.java:829) [?:?] Caused by: java.lang.RuntimeException: java.lang.NullPointerException at org.eclipse.xtext.ide.editor.contentassist.antlr.BaseContentAssistParser.getFollowElements(BaseContentAssistParser.java:246) ~[?:?] at org.eclipse.xtext.ide.editor.contentassist.antlr.BaseContentAssistParser.getFollowElements(BaseContentAssistParser.java:237) ~[?:?] at org.eclipse.xtext.ide.editor.contentassist.antlr.BaseContentAssistParser.getFollowElements(BaseContentAssistParser.java:232) ~[?:?] at org.eclipse.xtext.ide.editor.contentassist.antlr.AbstractContentAssistParser.getFollowElements(AbstractContentAssistParser.java:49) ~[?:?] at org.eclipse.xtext.ide.editor.contentassist.antlr.AbstractContentAssistParser.getFollowElements(AbstractContentAssistParser.java:27) ~[?:?] at org.eclipse.xtext.ide.editor.contentassist.antlr.BaseContentAssistParser.getFollowElements(BaseContentAssistParser.java:264) ~[?:?] at org.eclipse.xtext.ide.editor.contentassist.antlr.ContentAssistContextFactory.createContextsForLastCompleteNode(ContentAssistContextFactory.java:299) ~[?:?] at org.eclipse.xtext.ide.editor.contentassist.antlr.ContentAssistContextFactory.handleLastCompleteNodeIsPartOfLookahead(ContentAssistContextFactory.java:220) ~[?:?] at org.eclipse.xtext.ide.editor.contentassist.antlr.ContentAssistContextFactory$3.call(ContentAssistContextFactory.java:172) ~[?:?] at org.eclipse.xtext.ide.editor.contentassist.antlr.ContentAssistContextFactory$3.call(ContentAssistContextFactory.java:169) ~[?:?] … 4 more Caused by: java.lang.NullPointerException at java.util.Objects.requireNonNull(Objects.java:221) ~[?:?] at java.lang.Class.getMethod(Class.java:2101) ~[?:?] at org.eclipse.xtext.ide.editor.contentassist.antlr.BaseContentAssistParser.getFollowElements(BaseContentAssistParser.java:169) ~[?:?] at org.eclipse.xtext.ide.editor.contentassist.antlr.BaseContentAssistParser.getFollowElements(BaseContentAssistParser.java:242) ~[?:?] at org.eclipse.xtext.ide.editor.contentassist.antlr.BaseContentAssistParser.getFollowElements(BaseContentAssistParser.java:237) ~[?:?] at org.eclipse.xtext.ide.editor.contentassist.antlr.BaseContentAssistParser.getFollowElements(BaseContentAssistParser.java:232) ~[?:?] at org.eclipse.xtext.ide.editor.contentassist.antlr.AbstractContentAssistParser.getFollowElements(AbstractContentAssistParser.java:49) ~[?:?] at org.eclipse.xtext.ide.editor.contentassist.antlr.AbstractContentAssistParser.getFollowElements(AbstractContentAssistParser.java:27) ~[?:?] at org.eclipse.xtext.ide.editor.contentassist.antlr.BaseContentAssistParser.getFollowElements(BaseContentAssistParser.java:264) ~[?:?] at org.eclipse.xtext.ide.editor.contentassist.antlr.ContentAssistContextFactory.createContextsForLastCompleteNode(ContentAssistContextFactory.java:299) ~[?:?] at org.eclipse.xtext.ide.editor.contentassist.antlr.ContentAssistContextFactory.handleLastCompleteNodeIsPartOfLookahead(ContentAssistContextFactory.java:220) ~[?:?] at org.eclipse.xtext.ide.editor.contentassist.antlr.ContentAssistContextFactory$3.call(ContentAssistContextFactory.java:172) ~[?:?] at org.eclipse.xtext.ide.editor.contentassist.antlr.ContentAssistContextFactory$3.call(ContentAssistContextFactory.java:169) ~[?:?] … 4 more

Is this related to the Thermometer/Hygrometer Thing or to the coordinator… or something else? Any advice on how tog get rid of the errors?

jswim788 · May 3, 2023, 8:34pm

Just a guess, but does your flow control match what is recommended for the controller in the documentation?: ZigBee - Bindings | openHAB (Look under “Supported Coordinators”).

Tveitane · May 4, 2023, 1:34pm

Thank you - it was an interesting place you took me. The doc I have seen before for my Ember coordinator just says baud rate 11520 or 57600, XON/XOFF or none handhake. Now I learnt that an Ember coordinator and an Ember coordinator are two different things (at least), with different baud rate and handshaking.
I tried some different combinations, and settled on 115200/NONE, it seems to reduce the number of errors significantly.
Probably it should also work with 115200/HW handshake, but I still got a few errors with that combination - will give it another try, though.

Ap15e · May 4, 2023, 3:35pm

Please note that there is a mismatch between specification (https://itead.cc/product/zigbee-3-0-usb-dongle/) and openHAB documentation (ZigBee - Bindings | openHAB):
SW flow control vs. HW flow control

Tveitane · May 5, 2023, 4:47am

Exactly. The doc says SW flow control, OpenHAB says HW - and I get the best results with NONE

NilsOF · May 5, 2023, 5:57pm

You can read this message as “computer did not process incoming messages, the que is overflowing”

Ibelive you must use SW flow control on this coordinator
The only other alternative is hardware flow control (for coordinators that do hardware control)

Setting it to None will cause problems sooner rather than later, it is really not an option.

Is USB OK on that computer?

jswim788 · May 5, 2023, 6:34pm

Surprisingly, Sonoff’s own documentation (How to Use SONOFF Dongle Plus on Home Assistant? How to Flash Firmware? - SONOFF Official) has a section on using this dongle with OH and it says either software or none.

NilsOF · May 6, 2023, 7:47pm

Heh, they really should try to put at least one of their fingers into the earth…
In real world it would never fly…

Tveitane · May 7, 2023, 6:46am

There has never been any problem with the USB port, so I believe it is OK, yes.

As predicted, I started getting a different kind of errors with no handshake: Truncated messages. I changed to SW handshake and then restatred everything. Seems to have resonably good stability, but now and then an odd NullPointerException still occurs. Seems like the system recovers each time, but NullPoinerExceptions are not a thing that I like. And the stack traces are cluttering up my logs…

NilsOF · May 9, 2023, 4:32pm

I have the “beta” version of that stick.
The Zigbee-binding loses contact with it sometimes, and reset it.
It did get better when I put it on a powered hub.
I also think there is something with the firmware on my stick.

Not sure what is happening here…
My logs do not look anything like posted here.
I will check my logs when I get back to the PC

NilsOF · May 9, 2023, 8:46pm

This is a snippet from my log:

2023-05-06 10:16:42.620 [WARN ] [e.ember.internal.ash.AshFrameHandler] - ASH: ERROR received (code 3). Disconnecting.
2023-05-06 10:16:43.627 [INFO ] [bee.handler.ZigBeeCoordinatorHandler] - ZigBee dongle inactivity timer. Reinitializing ZigBee
2023-05-06 10:16:43.882 [ERROR] [ng.zigbee.handler.ZigBeeThingHandler] - EC1BBDFFFE003744: Exception creating channels 
java.lang.NullPointerException: null
        at org.openhab.binding.zigbee.internal.converter.ZigBeeConverterSwitchLevel.updateConfiguration(ZigBeeConverterSwitchLevel.java:499) ~
[bundleFile:?]
        at org.openhab.binding.zigbee.handler.ZigBeeThingHandler.doNodeInitialisation(ZigBeeThingHandler.java:420) [bundleFile:?]
        at org.openhab.binding.zigbee.handler.ZigBeeThingHandler$1.call(ZigBeeThingHandler.java:244) [bundleFile:?]
        at org.openhab.binding.zigbee.handler.ZigBeeThingHandler$1.call(ZigBeeThingHandler.java:1) [bundleFile:?]
        at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) [?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
        at java.lang.Thread.run(Thread.java:829) [?:?]
2023-05-06 10:16:43.885 [ERROR] [ng.zigbee.handler.ZigBeeThingHandler] - EC1BBDFFFE003744: Exception creating channels 
java.lang.NullPointerException: null
        at org.openhab.binding.zigbee.internal.converter.ZigBeeConverterSwitchLevel.updateConfiguration(ZigBeeConverterSwitchLevel.java:499) ~
[bundleFile:?]
        at org.openhab.binding.zigbee.handler.ZigBeeThingHandler.doNodeInitialisation(ZigBeeThingHandler.java:420) [bundleFile:?]
        at org.openhab.binding.zigbee.handler.ZigBeeThingHandler$1.call(ZigBeeThingHandler.java:244) [bundleFile:?]
        at org.openhab.binding.zigbee.handler.ZigBeeThingHandler$1.call(ZigBeeThingHandler.java:1) [bundleFile:?]
        at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) [?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
        at java.lang.Thread.run(Thread.java:829) [?:?]
2023-05-06 10:16:59.395 [INFO ] [bee.discovery.ZigBeeDiscoveryService] - 00178801086C0DFD: Starting ZigBee device discovery

not that often, but irritating enough:

nils@bitfrost:~$ cat /var/log/openhab/openhab.log|grep "Reinitializing ZigBee"
2023-03-05 05:19:12.677 [INFO ] [bee.handler.ZigBeeCoordinatorHandler] - ZigBee dongle inactivity timer. Reinitializing ZigBee
2023-03-05 13:48:16.400 [INFO ] [bee.handler.ZigBeeCoordinatorHandler] - ZigBee dongle inactivity timer. Reinitializing ZigBee
2023-03-08 21:19:05.401 [INFO ] [bee.handler.ZigBeeCoordinatorHandler] - ZigBee dongle inactivity timer. Reinitializing ZigBee
2023-03-09 11:02:57.464 [INFO ] [bee.handler.ZigBeeCoordinatorHandler] - ZigBee dongle inactivity timer. Reinitializing ZigBee
2023-03-09 12:29:51.912 [INFO ] [bee.handler.ZigBeeCoordinatorHandler] - ZigBee dongle inactivity timer. Reinitializing ZigBee
2023-03-10 21:31:19.275 [INFO ] [bee.handler.ZigBeeCoordinatorHandler] - ZigBee dongle inactivity timer. Reinitializing ZigBee
2023-03-11 08:57:23.323 [INFO ] [bee.handler.ZigBeeCoordinatorHandler] - ZigBee dongle inactivity timer. Reinitializing ZigBee
2023-03-13 01:15:51.484 [INFO ] [bee.handler.ZigBeeCoordinatorHandler] - ZigBee dongle inactivity timer. Reinitializing ZigBee
2023-03-13 17:15:50.529 [INFO ] [bee.handler.ZigBeeCoordinatorHandler] - ZigBee dongle inactivity timer. Reinitializing ZigBee
2023-03-13 21:53:29.332 [INFO ] [bee.handler.ZigBeeCoordinatorHandler] - ZigBee dongle inactivity timer. Reinitializing ZigBee
2023-03-14 17:43:21.304 [INFO ] [bee.handler.ZigBeeCoordinatorHandler] - ZigBee dongle inactivity timer. Reinitializing ZigBee
2023-03-17 07:13:53.628 [INFO ] [bee.handler.ZigBeeCoordinatorHandler] - ZigBee dongle inactivity timer. Reinitializing ZigBee
2023-03-18 16:08:17.913 [INFO ] [bee.handler.ZigBeeCoordinatorHandler] - ZigBee dongle inactivity timer. Reinitializing ZigBee
2023-03-18 16:26:52.191 [INFO ] [bee.handler.ZigBeeCoordinatorHandler] - ZigBee dongle inactivity timer. Reinitializing ZigBee
2023-03-28 09:26:37.434 [INFO ] [bee.handler.ZigBeeCoordinatorHandler] - ZigBee dongle inactivity timer. Reinitializing ZigBee
2023-03-30 15:19:35.665 [INFO ] [bee.handler.ZigBeeCoordinatorHandler] - ZigBee dongle inactivity timer. Reinitializing ZigBee
2023-04-06 14:14:50.413 [INFO ] [bee.handler.ZigBeeCoordinatorHandler] - ZigBee dongle inactivity timer. Reinitializing ZigBee
2023-04-09 17:40:59.993 [INFO ] [bee.handler.ZigBeeCoordinatorHandler] - ZigBee dongle inactivity timer. Reinitializing ZigBee
2023-04-11 20:11:22.282 [INFO ] [bee.handler.ZigBeeCoordinatorHandler] - ZigBee dongle inactivity timer. Reinitializing ZigBee
2023-04-16 22:01:40.142 [INFO ] [bee.handler.ZigBeeCoordinatorHandler] - ZigBee dongle inactivity timer. Reinitializing ZigBee
2023-04-16 23:02:08.879 [INFO ] [bee.handler.ZigBeeCoordinatorHandler] - ZigBee dongle inactivity timer. Reinitializing ZigBee
2023-04-17 08:08:11.058 [INFO ] [bee.handler.ZigBeeCoordinatorHandler] - ZigBee dongle inactivity timer. Reinitializing ZigBee
2023-04-26 16:16:13.915 [INFO ] [bee.handler.ZigBeeCoordinatorHandler] - ZigBee dongle inactivity timer. Reinitializing ZigBee
2023-05-06 10:16:43.627 [INFO ] [bee.handler.ZigBeeCoordinatorHandler] - ZigBee dongle inactivity timer. Reinitializing ZigBee

Just to be clear:
I belive this is a fault in my Zigbee dongle.
@Tveitane : do this look familiar?

Tveitane · May 10, 2023, 7:05am

Yes, I have seen these messages. The inactivity timer is appearing regularly.
As I said, it seems like the system is restoring each time. But I agree, it is irritating enough.
Last night my computer rebooted, and new log files were created - my old logs are gone. And so long today, no errors… and no possibility to look at old events and exceptions. But they will probably be back.

Tveitane · May 10, 2023, 7:12am

Oh, I was looking in the wrong directory. The old logs were still there

NilsOF · May 11, 2023, 5:56am

Mybe new firmware can fix these problems.
I have not been following lately…