EnOcean binding taking several minutes to start up

  • 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.

Hi Matthias @ohle,

this behaviour is definitely not intended :wink: This sems to be the reason for the problem No SerialPortProvider found for: /dev/ttyUSB0. Will see what I can do.

Best regards
Daniel

Hi Daniel

thanks a lot for all the effort you put in into answering so many questions concerning EnOcean in this forums! Just let me know if I can support the analysis somehow.
A little more info wrt my setup:

  • I did not use openhabian, but a plain Raspian Stretch Lite image
  • Installed Zulu Java and openHAB according to the documentation and set up openHAB as a service
  • Enabled the serial port hardware with raspi-config, but not the login shell over serial
  • Added the openhab user to groups dialout and tty
  • Added the following line to /etc/default/openhab2: EXTRA_JAVA_OPTS="-Dgnu.io.rxtx.SerialPorts=/dev/ttyUSB0:/dev/ttyS0:/dev/ttyAMA0"

Regards
Matthias

Hi there,

I’m expecting the same behavior since I’m using the latest zwave snapshot. I’m using a raspberrypi 2 with razpberry module.

2019-04-13 14:30:40.786 [WARN ] [erial.internal.SerialPortManagerImpl] - No SerialPortProvider found for: /dev/ttyAMA0

Maybe the new snapshots do use some new framework features that are using the unreleased upcoming openhab version?