- Platform information:
- Hardware: Raspberry PI 3 B+, USB300
- OS: Raspbian Stretch Lite
- Java Runtime Environment: Java 8 Zulu Embedded
- openHAB version: 2.4, EnOcean Binding 2.5 (snapshot)
- Issue of the topic: After boot the enocean bindings sometimes takes several minutes to start up. At times it does not start up at all.
I have set up openHAB for the first time on the hardware mentioned above to set up to control NodOn roller shutter devices. I’m happy that I could add the thing via PaperUI, but looking at the logs I have some doubts if I have set up every correctly, because it seems that the binding takes several attempts and a few minutes to start up.
First here is the event log:
2019-01-18 22:31:36.570 [.ItemChannelLinkAddedEvent] - Link 'EnoceanUSB300DongleFT2VDCYB_RepeaterMode-enocean:bridge:FT2VDCYB:repeaterMode' has been added.
2019-01-18 22:31:36.592 [.ItemChannelLinkAddedEvent] - Link 'EnoceanUSB300DongleFT2VDCYB_SetBaseId-enocean:bridge:FT2VDCYB:setBaseId' has been added.
2019-01-18 22:31:38.598 [hingStatusInfoChangedEvent] - 'enocean:bridge:FT2VDCYB' changed from UNINITIALIZED to INITIALIZING
2019-01-18 22:31:38.628 [hingStatusInfoChangedEvent] - 'enocean:bridge:FT2VDCYB' changed from INITIALIZING to OFFLINE (CONFIGURATION_PENDING): trying to connect to gateway...
2019-01-18 22:31:38.671 [hingStatusInfoChangedEvent] - 'enocean:bridge:FT2VDCYB' changed from OFFLINE (CONFIGURATION_PENDING): trying to connect to gateway... to OFFLINE (CONFIGURATION_PENDING): opening serial port...
2019-01-18 22:31:38.677 [hingStatusInfoChangedEvent] - 'enocean:bridge:FT2VDCYB' changed from OFFLINE (CONFIGURATION_PENDING): opening serial port... to OFFLINE (CONFIGURATION_ERROR): Port could not be found
2019-01-18 22:32:38.690 [hingStatusInfoChangedEvent] - 'enocean:bridge:FT2VDCYB' changed from OFFLINE (CONFIGURATION_ERROR): Port could not be found to OFFLINE (CONFIGURATION_PENDING): opening serial port...
2019-01-18 22:32:38.817 [hingStatusInfoChangedEvent] - 'enocean:bridge:FT2VDCYB' changed from OFFLINE (CONFIGURATION_PENDING): opening serial port... to OFFLINE (CONFIGURATION_PENDING): starting rx thread...
2019-01-18 22:32:38.824 [hingStatusInfoChangedEvent] - 'enocean:bridge:FT2VDCYB' changed from OFFLINE (CONFIGURATION_PENDING): starting rx thread... to OFFLINE (CONFIGURATION_PENDING): trying to get bridge base id...
2019-01-18 22:33:38.882 [hingStatusInfoChangedEvent] - 'enocean:bridge:FT2VDCYB' changed from OFFLINE (CONFIGURATION_PENDING): trying to get bridge base id... to OFFLINE (CONFIGURATION_PENDING): opening serial port...
2019-01-18 22:33:38.904 [hingStatusInfoChangedEvent] - 'enocean:bridge:FT2VDCYB' changed from OFFLINE (CONFIGURATION_PENDING): opening serial port... to OFFLINE (CONFIGURATION_PENDING): starting rx thread...
2019-01-18 22:33:38.912 [hingStatusInfoChangedEvent] - 'enocean:bridge:FT2VDCYB' changed from OFFLINE (CONFIGURATION_PENDING): starting rx thread... to OFFLINE (CONFIGURATION_PENDING): trying to get bridge base id...
2019-01-18 22:33:38.938 [hingStatusInfoChangedEvent] - 'enocean:bridge:FT2VDCYB' changed from OFFLINE (CONFIGURATION_PENDING): trying to get bridge base id... to ONLINE
In this case the binding first tries to find a serial port, classifies this as a configuriation error and the resorts to an “rx thread”. Here the binding could successfully retrieve the base id after only two attempts and only two minutes. Sometimes a few more attempts are necessary.
The openhab.log somehow mirrors the above behaviour, but it also contains a stack trace:
2019-01-18 22:31:15.771 [INFO ] [ebuilder.internal.HomeBuilderServlet] - Started Home Builder at /homebuilder
2019-01-18 22:31:15.864 [INFO ] [panel.internal.HABPanelDashboardTile] - Started HABPanel at /habpanel
2019-01-18 22:31:35.684 [INFO ] [thome.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
2019-01-18 22:31:37.762 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at http://192.168.178.115:8080
2019-01-18 22:31:37.766 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at https://192.168.178.115:8443
2019-01-18 22:31:38.280 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Started Paper UI at /paperui
2019-01-18 22:31:38.632 [WARN ] [erial.internal.SerialPortManagerImpl] - No SerialPortProvider found for: /dev/ttyUSB0
2019-01-18 22:31:38.673 [ERROR] [ome.core.thing.link.ThingLinkManager] - Exception occurred while informing handler: null
java.lang.NullPointerException: null
at org.openhab.binding.enocean.internal.transceiver.EnOceanTransceiver$RequestQueue.send(EnOceanTransceiver.java:94) ~[?:?]
at org.openhab.binding.enocean.internal.transceiver.EnOceanTransceiver$RequestQueue.enqueRequest(EnOceanTransceiver.java:68) ~[?:?]
at org.openhab.binding.enocean.internal.transceiver.EnOceanTransceiver.sendESP3Packet(EnOceanTransceiver.java:382) ~[?:?]
at org.openhab.binding.enocean.internal.handler.EnOceanBridgeHandler.sendMessage(EnOceanBridgeHandler.java:336) ~[?:?]
at org.openhab.binding.enocean.internal.handler.EnOceanBridgeHandler.handleCommand(EnOceanBridgeHandler.java:95) ~[?:?]
at org.eclipse.smarthome.core.thing.binding.BaseThingHandler.channelLinked(BaseThingHandler.java:233) ~[?:?]
at org.eclipse.smarthome.core.thing.link.ThingLinkManager.lambda$0(ThingLinkManager.java:300) ~[?:?]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:?]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [?:?]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [?:?]
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) [?:?]
2019-01-18 22:31:38.831 [INFO ] [ui.habmin.internal.servlet.HABminApp] - Started HABmin servlet at /habmin
2019-01-18 22:32:38.673 [INFO ] [transceiver.EnOceanSerialTransceiver] - Transceiver shutdown
2019-01-18 22:32:38.809 [INFO ] [transceiver.EnOceanSerialTransceiver] - EnOceanSerialTransceiver initialized
2019-01-18 22:33:38.867 [INFO ] [transceiver.EnOceanSerialTransceiver] - Transceiver shutdown
2019-01-18 22:33:38.894 [INFO ] [transceiver.EnOceanSerialTransceiver] - EnOceanSerialTransceiver initialized
It would be great if somebody could confirm/deny that the described behaviour is either intended or at least to be expected, or point me in the right direction to further analyze my setup.