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.

Sign up for GitHub

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

Jump to bottom

Dimmer not updated after openhab restart #36

Closed
martink2 opened this issue Dec 20, 2018 · 5 comments
Closed

Dimmer not updated after openhab restart #36

martink2 opened this issue Dec 20, 2018 · 5 comments

Comments

@martink2
Copy link

Hi @fruggy83

as mentioned in the community the is something problematic going on in the serial
transceiver on openhab startup:

I recently switched to the 2.4 release and found the issue to be present release as well as
at least m8, m7, m6 and the issue-10 version i am currently running.

On a clean openhabian installation i can create the bridge , dimmer thing and dimmer item
and everything works fine whenever the dimmer sends a status message the value is
reflected immediately. This is working until i restart the openhab process after which
the dimmer is still working in a sense that i can dimm it but if the dimmer is sending an
updated telegramm after manual dimming the new value is not updated in the item/thing.

I can solve the issue by removing the bridge and dimmer thing and adding it again afterward,
which makes it work until restart.

In the broken state i can still see the packet recieved for the thing in question but nothing is
published afterwards. As far as i can tell this behaviour is specific for the dimmer / command.

The other devices i have (classicDevices) are still reflecting the state via telegramms from associated
enocean id's. I have this behaviour consistently.

Below is a full startup log but i found the folowing:

2018-12-20 17:15:22.553 [WARN ] [erial.internal.SerialPortManagerImpl] - No SerialPortProvider found for: /dev/ttyUSB.Enocean
2018-12-20 17:15:22.557 [DEBUG] [org.openhab.binding.openocean       ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=383, service.bundleid=227, service.scope=singleton} - org.openhab.binding.openocean
2018-12-20 17:15:22.681 [hingStatusInfoChangedEvent] - 'enocean:classicDevice:01840526' changed from UNINITIALIZED to INITIALIZING
2018-12-20 17:15:22.610 [DEBUG] [nternal.handler.EnOceanBridgeHandler] - error during bridge init occured
java.io.IOException: Could not find a gateway on given path '/dev/ttyUSB.Enocean', 0 ports available.
	at org.openhab.binding.enocean.internal.transceiver.EnOceanSerialTransceiver.Initialize(EnOceanSerialTransceiver.java:54) ~[227:org.openhab.binding.openocean:2.4.0.201812142103]
	at org.openhab.binding.enocean.internal.handler.EnOceanBridgeHandler.initTransceiver(EnOceanBridgeHandler.java:197) [227:org.openhab.binding.openocean:2.4.0.201812142103]
	at org.openhab.binding.enocean.internal.handler.EnOceanBridgeHandler.access$2(EnOceanBridgeHandler.java:184) [227:org.openhab.binding.openocean:2.4.0.201812142103]
	at org.openhab.binding.enocean.internal.handler.EnOceanBridgeHandler$4.run(EnOceanBridgeHandler.java:176) [227:org.openhab.binding.openocean:2.4.0.201812142103]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:?]
	at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) [?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) [?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) [?:?]
	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) [?:?]

after a few minutes the bridge is reinitilized, which is working without a porblem:

2018-12-20 17:16:22.698 [DEBUG] [transceiver.EnOceanSerialTransceiver] - shutting down transceiver
2018-12-20 17:16:22.702 [DEBUG] [ernal.transceiver.EnOceanTransceiver] - Interrupt rx Thread
2018-12-20 17:16:22.705 [INFO ] [transceiver.EnOceanSerialTransceiver] - Transceiver shutdown
2018-12-20 17:16:22.712 [hingStatusInfoChangedEvent] - 'enocean:bridge:cd2c57b1' changed from OFFLINE (CONFIGURATION_ERROR): Port could not be found to OFFLINE (CONFIGURATION_PENDING): opening serial port...
2018-12-20 17:16:22.744 [INFO ] [transceiver.EnOceanSerialTransceiver] - EnOceanSerialTransceiver initialized
2018-12-20 17:16:22.751 [hingStatusInfoChangedEvent] - 'enocean:bridge:cd2c57b1' changed from OFFLINE (CONFIGURATION_PENDING): opening serial port... to OFFLINE (CONFIGURATION_PENDING): starting rx thread...
2018-12-20 17:16:22.755 [DEBUG] [nternal.handler.EnOceanBridgeHandler] - request base id
2018-12-20 17:16:22.758 [hingStatusInfoChangedEvent] - 'enocean:bridge:cd2c57b1' changed from OFFLINE (CONFIGURATION_PENDING): starting rx thread... to OFFLINE (CONFIGURATION_PENDING): trying to get bridge base id...
2018-12-20 17:16:22.774 [DEBUG] [ernal.transceiver.EnOceanTransceiver] - Enqueue new send request with ESP3 type COMMON_COMMAND with callback
2018-12-20 17:16:22.790 [DEBUG] [ernal.transceiver.EnOceanTransceiver] - Sending data, type COMMON_COMMAND, payload 08
2018-12-20 17:16:22.823 [DEBUG] [ernal.transceiver.EnOceanTransceiver] - Enqueue new send request with ESP3 type COMMON_COMMAND with callback
2018-12-20 17:16:23.074 [DEBUG] [ernal.transceiver.EnOceanTransceiver] - Sending data, type COMMON_COMMAND, payload 03

After which all things go into online state but at least dimmers are not updated.

I am a bit lost on how to debug this problem further, I assume there is some problem
in teh startup sequence or the sequence of loading things. The above error does
not appear when adding the bridge after startup.

As always very much gratefull for any advise how to debug further?

Thanks

Martin

2018-12-20 17:14:26.428 [DEBUG] [org.openhab.binding.openocean       ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.discovery.usbserial.UsbSerialDiscoveryParticipant}={service.id=120, service.bundleid=227, service.scope=bundle, component.name=org.openhab.binding.enocean.internal.discovery.EnOceanUsbSerialDiscoveryParticipant, component.id=13} - org.openhab.binding.openocean
2018-12-20 17:14:26.474 [DEBUG] [org.openhab.binding.openocean       ] - BundleEvent [unknown:512] - org.openhab.binding.openocean
2018-12-20 17:14:28.945 [DEBUG] [org.openhab.binding.openocean       ] - BundleEvent STARTING - org.openhab.binding.openocean
2018-12-20 17:14:28.952 [DEBUG] [org.openhab.binding.openocean       ] - BundleEvent STARTED - org.openhab.binding.openocean
2018-12-20 17:14:30.883 [INFO ] [panel.internal.HABPanelDashboardTile] - Started HABPanel at /habpanel
2018-12-20 17:14:31.003 [INFO ] [ebuilder.internal.HomeBuilderServlet] - Started Home Builder at /homebuilder
2018-12-20 17:14:49.860 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'kz.items'
2018-12-20 17:14:50.352 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'wz.items'
2018-12-20 17:14:50.484 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'ka.items'
2018-12-20 17:14:50.601 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'ba.items'
2018-12-20 17:14:50.738 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'fl.items'
2018-12-20 17:14:50.845 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'home.items'
2018-12-20 17:14:50.953 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'ku.items'
2018-12-20 17:14:51.104 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'az.items'
2018-12-20 17:14:51.215 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'sz.items'
2018-12-20 17:14:52.576 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'mapdb.persist'
2018-12-20 17:14:57.463 [INFO ] [thome.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
2018-12-20 17:15:02.803 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'ba.rules'
2018-12-20 17:15:03.698 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'ku.rules'
2018-12-20 17:15:05.050 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'home.sitemap'

2018-12-20 17:15:08.670 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Connecting to serial port '/dev/ttyACM.zwave'
2018-12-20 17:15:08.805 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Serial port is initialized

2018-12-20 17:15:08.912 [INFO ] [ve.internal.protocol.ZWaveController] - Starting ZWave controller
2018-12-20 17:15:08.916 [INFO ] [ve.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false.

2018-12-20 17:15:19.449 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at http://10.0.3.37:8080
2018-12-20 17:15:19.468 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at https://10.0.3.37:8443
2018-12-20 17:15:20.338 [INFO ] [.cc2531.network.ZigBeeNetworkManager] - Initialized ZigBee network with existing network state.
2018-12-20 17:15:20.546 [INFO ] [bee.discovery.ZigBeeDiscoveryService] - 7CB03EAA00ACE98E: Starting ZigBee device discovery

2018-12-20 17:15:20.556 [INFO ] [bee.discovery.ZigBeeDiscoveryService] - 7CB03EAA00ACB3CF: Starting ZigBee device discovery

2018-12-20 17:15:21.144 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Started Paper UI at /paperui

2018-12-20 17:15:22.197 [hingStatusInfoChangedEvent] - 'enocean:centralCommand:0183E856' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2018-12-20 17:15:22.211 [hingStatusInfoChangedEvent] - 'enocean:rockerSwitch:cd2c57b1:FEFF4BFE' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2018-12-20 17:15:22.229 [hingStatusInfoChangedEvent] - 'enocean:classicDevice:018614C7' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2018-12-20 17:15:22.233 [hingStatusInfoChangedEvent] - 'enocean:classicDevice:01860CD3' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2018-12-20 17:15:22.238 [hingStatusInfoChangedEvent] - 'enocean:rockerSwitch:cd2c57b1:FEFF4BB7' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2018-12-20 17:15:22.252 [hingStatusInfoChangedEvent] - 'enocean:centralCommand:0082254F' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)

2018-12-20 17:15:22.253 [DEBUG] [org.openhab.binding.openocean       ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.discovery.DiscoveryService}={service.id=381, service.bundleid=227, service.scope=singleton} - org.openhab.binding.openocean
2018-12-20 17:15:22.327 [DEBUG] [org.openhab.binding.openocean       ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=382, service.bundleid=227, service.scope=singleton} - org.openhab.binding.openocean

2018-12-20 17:15:22.433 [hingStatusInfoChangedEvent] - 'enocean:bridge:cd2c57b1' changed from UNINITIALIZED to INITIALIZING
2018-12-20 17:15:22.468 [hingStatusInfoChangedEvent] - 'enocean:bridge:cd2c57b1' changed from INITIALIZING to OFFLINE (CONFIGURATION_PENDING): trying to connect to gateway...
2018-12-20 17:15:22.536 [hingStatusInfoChangedEvent] - 'enocean:bridge:cd2c57b1' changed from OFFLINE (CONFIGURATION_PENDING): trying to connect to gateway... to OFFLINE (CONFIGURATION_PENDING): opening serial port...
2018-12-20 17:15:22.553 [WARN ] [erial.internal.SerialPortManagerImpl] - No SerialPortProvider found for: /dev/ttyUSB.Enocean
2018-12-20 17:15:22.557 [DEBUG] [org.openhab.binding.openocean       ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=383, service.bundleid=227, service.scope=singleton} - org.openhab.binding.openocean
2018-12-20 17:15:22.681 [hingStatusInfoChangedEvent] - 'enocean:classicDevice:01840526' changed from UNINITIALIZED to INITIALIZING
2018-12-20 17:15:22.610 [DEBUG] [nternal.handler.EnOceanBridgeHandler] - error during bridge init occured
java.io.IOException: Could not find a gateway on given path '/dev/ttyUSB.Enocean', 0 ports available.
	at org.openhab.binding.enocean.internal.transceiver.EnOceanSerialTransceiver.Initialize(EnOceanSerialTransceiver.java:54) ~[227:org.openhab.binding.openocean:2.4.0.201812142103]
	at org.openhab.binding.enocean.internal.handler.EnOceanBridgeHandler.initTransceiver(EnOceanBridgeHandler.java:197) [227:org.openhab.binding.openocean:2.4.0.201812142103]
	at org.openhab.binding.enocean.internal.handler.EnOceanBridgeHandler.access$2(EnOceanBridgeHandler.java:184) [227:org.openhab.binding.openocean:2.4.0.201812142103]
	at org.openhab.binding.enocean.internal.handler.EnOceanBridgeHandler$4.run(EnOceanBridgeHandler.java:176) [227:org.openhab.binding.openocean:2.4.0.201812142103]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:?]
	at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) [?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) [?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) [?:?]
	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) [?:?]
2018-12-20 17:15:22.680 [DEBUG] [rnal.handler.EnOceanBaseThingHandler] - Initializing enocean base thing handler.
2018-12-20 17:15:22.700 [DEBUG] [rnal.handler.EnOceanBaseThingHandler] - initializeThing thing enocean:classicDevice:01840526 bridge status OFFLINE
2018-12-20 17:15:22.702 [hingStatusInfoChangedEvent] - 'enocean:bridge:cd2c57b1' changed from OFFLINE (CONFIGURATION_PENDING): opening serial port... to OFFLINE (CONFIGURATION_ERROR): Port could not be found
2018-12-20 17:15:22.714 [hingStatusInfoChangedEvent] - 'enocean:classicDevice:01840526' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE)
2018-12-20 17:15:22.726 [DEBUG] [org.openhab.binding.openocean       ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=384, service.bundleid=227, service.scope=singleton} - org.openhab.binding.openocean
2018-12-20 17:15:22.752 [DEBUG] [ernal.transceiver.EnOceanTransceiver] - Listener added: 25429286
2018-12-20 17:15:22.805 [DEBUG] [rnal.handler.EnOceanBaseThingHandler] - Initializing enocean base thing handler.
2018-12-20 17:15:22.805 [hingStatusInfoChangedEvent] - 'enocean:centralCommand:00877367' changed from UNINITIALIZED to INITIALIZING
2018-12-20 17:15:22.807 [DEBUG] [rnal.handler.EnOceanBaseThingHandler] - initializeThing thing enocean:centralCommand:00877367 bridge status OFFLINE
2018-12-20 17:15:22.814 [hingStatusInfoChangedEvent] - 'enocean:centralCommand:00877367' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE)
2018-12-20 17:15:22.820 [DEBUG] [org.openhab.binding.openocean       ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=385, service.bundleid=227, service.scope=singleton} - org.openhab.binding.openocean
2018-12-20 17:15:22.855 [DEBUG] [rnal.handler.EnOceanBaseThingHandler] - Initializing enocean base thing handler.
2018-12-20 17:15:22.856 [hingStatusInfoChangedEvent] - 'enocean:classicDevice:0185F65C' changed from UNINITIALIZED to INITIALIZING
2018-12-20 17:15:22.859 [DEBUG] [rnal.handler.EnOceanBaseThingHandler] - initializeThing thing enocean:classicDevice:0185F65C bridge status OFFLINE
2018-12-20 17:15:22.873 [DEBUG] [ernal.transceiver.EnOceanTransceiver] - Listener added: 25556572
2018-12-20 17:15:22.877 [hingStatusInfoChangedEvent] - 'enocean:classicDevice:0185F65C' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE)
2018-12-20 17:15:22.875 [DEBUG] [org.openhab.binding.openocean       ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=386, service.bundleid=227, service.scope=singleton} - org.openhab.binding.openocean
2018-12-20 17:15:22.907 [DEBUG] [rnal.handler.EnOceanBaseThingHandler] - Initializing enocean base thing handler.
2018-12-20 17:15:22.909 [DEBUG] [rnal.handler.EnOceanBaseThingHandler] - initializeThing thing enocean:centralCommand:050A7B7D bridge status OFFLINE
2018-12-20 17:15:22.908 [hingStatusInfoChangedEvent] - 'enocean:centralCommand:050A7B7D' changed from UNINITIALIZED to INITIALIZING
2018-12-20 17:15:22.916 [hingStatusInfoChangedEvent] - 'enocean:centralCommand:050A7B7D' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE)
2018-12-20 17:15:22.922 [DEBUG] [org.openhab.binding.openocean       ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=387, service.bundleid=227, service.scope=singleton} - org.openhab.binding.openocean
2018-12-20 17:15:22.963 [hingStatusInfoChangedEvent] - 'enocean:rockerSwitch:cd2c57b1:018614C7' changed from UNINITIALIZED to INITIALIZING
2018-12-20 17:15:22.962 [DEBUG] [rnal.handler.EnOceanBaseThingHandler] - Initializing enocean base thing handler.
2018-12-20 17:15:22.969 [DEBUG] [rnal.handler.EnOceanBaseThingHandler] - initializeThing thing enocean:rockerSwitch:cd2c57b1:018614C7 bridge status OFFLINE
2018-12-20 17:15:22.980 [hingStatusInfoChangedEvent] - 'enocean:rockerSwitch:cd2c57b1:018614C7' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE)
2018-12-20 17:15:23.009 [DEBUG] [org.openhab.binding.openocean       ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=388, service.bundleid=227, service.scope=singleton} - org.openhab.binding.openocean
2018-12-20 17:15:23.012 [DEBUG] [org.openhab.binding.openocean       ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=392, service.bundleid=227, service.scope=singleton} - org.openhab.binding.openocean
2018-12-20 17:15:23.015 [DEBUG] [org.openhab.binding.openocean       ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=391, service.bundleid=227, service.scope=singleton} - org.openhab.binding.openocean
2018-12-20 17:15:23.020 [DEBUG] [org.openhab.binding.openocean       ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=390, service.bundleid=227, service.scope=singleton} - org.openhab.binding.openocean
2018-12-20 17:15:23.013 [DEBUG] [org.openhab.binding.openocean       ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=389, service.bundleid=227, service.scope=singleton} - org.openhab.binding.openocean
2018-12-20 17:15:23.087 [DEBUG] [org.openhab.binding.openocean       ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory}={service.id=380, service.bundleid=227, service.scope=bundle, component.name=org.openhab.binding.enocean.internal.EnOceanHandlerFactory, component.id=12} - org.openhab.binding.openocean
2018-12-20 17:15:23.103 [DEBUG] [rnal.handler.EnOceanBaseThingHandler] - Initializing enocean base thing handler.
2018-12-20 17:15:23.102 [hingStatusInfoChangedEvent] - 'enocean:rockerSwitch:cd2c57b1:FEFF4BFE' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2018-12-20 17:15:23.105 [DEBUG] [rnal.handler.EnOceanBaseThingHandler] - initializeThing thing enocean:rockerSwitch:cd2c57b1:FEFF4BB7 bridge status OFFLINE
2018-12-20 17:15:23.102 [DEBUG] [rnal.handler.EnOceanBaseThingHandler] - Initializing enocean base thing handler.
2018-12-20 17:15:23.117 [DEBUG] [rnal.handler.EnOceanBaseThingHandler] - Initializing enocean base thing handler.
2018-12-20 17:15:23.119 [DEBUG] [rnal.handler.EnOceanBaseThingHandler] - initializeThing thing enocean:classicDevice:018614C7 bridge status OFFLINE
2018-12-20 17:15:23.129 [DEBUG] [rnal.handler.EnOceanBaseThingHandler] - Initializing enocean base thing handler.
2018-12-20 17:15:23.132 [hingStatusInfoChangedEvent] - 'enocean:centralCommand:0082254F' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2018-12-20 17:15:23.131 [DEBUG] [rnal.handler.EnOceanBaseThingHandler] - Initializing enocean base thing handler.
2018-12-20 17:15:23.130 [DEBUG] [rnal.handler.EnOceanBaseThingHandler] - initializeThing thing enocean:rockerSwitch:cd2c57b1:FEFF4BFE bridge status OFFLINE
2018-12-20 17:15:23.127 [DEBUG] [org.openhab.binding.openocean       ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=393, service.bundleid=227, service.scope=singleton} - org.openhab.binding.openocean
2018-12-20 17:15:23.142 [DEBUG] [rnal.handler.EnOceanBaseThingHandler] - initializeThing thing enocean:centralCommand:0082254F bridge status OFFLINE
2018-12-20 17:15:23.140 [hingStatusInfoChangedEvent] - 'enocean:rockerSwitch:cd2c57b1:FEFF4BB7' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE)
2018-12-20 17:15:23.136 [DEBUG] [rnal.handler.EnOceanBaseThingHandler] - initializeThing thing enocean:classicDevice:01860CD3 bridge status OFFLINE
2018-12-20 17:15:23.149 [hingStatusInfoChangedEvent] - 'enocean:classicDevice:018614C7' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2018-12-20 17:15:23.155 [hingStatusInfoChangedEvent] - 'enocean:classicDevice:018614C7' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE)
2018-12-20 17:15:23.171 [DEBUG] [ernal.transceiver.EnOceanTransceiver] - Listener added: 25564359
2018-12-20 17:15:23.178 [hingStatusInfoChangedEvent] - 'enocean:classicDevice:01860CD3' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2018-12-20 17:15:23.187 [hingStatusInfoChangedEvent] - 'enocean:rockerSwitch:cd2c57b1:FEFF4BFE' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE)
2018-12-20 17:15:23.195 [hingStatusInfoChangedEvent] - 'enocean:classicDevice:01860CD3' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE)
2018-12-20 17:15:23.196 [DEBUG] [ernal.transceiver.EnOceanTransceiver] - Listener added: 25562323
2018-12-20 17:15:23.219 [hingStatusInfoChangedEvent] - 'enocean:centralCommand:0082254F' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE)
2018-12-20 17:15:23.231 [DEBUG] [rnal.handler.EnOceanBaseThingHandler] - Initializing enocean base thing handler.
2018-12-20 17:15:23.233 [hingStatusInfoChangedEvent] - 'enocean:centralCommand:0183E856' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2018-12-20 17:15:23.234 [DEBUG] [rnal.handler.EnOceanBaseThingHandler] - initializeThing thing enocean:centralCommand:0183E856 bridge status OFFLINE
2018-12-20 17:15:23.247 [hingStatusInfoChangedEvent] - 'enocean:centralCommand:0183E856' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE)
2018-12-20 17:15:30.774 [vent.ItemStateChangedEvent] - kuSchrank changed from NULL to OFF
2018-12-20 17:15:30.794 [vent.ItemStateChangedEvent] - kuHaube changed from NULL to OFF
2018-12-20 17:15:30.813 [vent.ItemStateChangedEvent] - baSpiegel changed from NULL to OFF
2018-12-20 17:15:30.823 [vent.ItemStateChangedEvent] - kuDecke changed from NULL to OFF
2018-12-20 17:15:34.162 [hingStatusInfoChangedEvent] - 'zwave:serial_zstick:445d9f4d' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE
2018-12-20 17:15:34.253 [hingStatusInfoChangedEvent] - 'zwave:device:445d9f4d:node2' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE
2018-12-20 17:15:34.311 [me.event.ThingUpdatedEvent] - Thing 'zwave:serial_zstick:445d9f4d' has been updated.
2018-12-20 17:15:35.503 [hingStatusInfoChangedEvent] - 'zwave:device:445d9f4d:node2' changed from ONLINE to ONLINE: Node initialising: PING
ONLINE
2018-12-20 17:16:22.698 [DEBUG] [transceiver.EnOceanSerialTransceiver] - shutting down transceiver
2018-12-20 17:16:22.702 [DEBUG] [ernal.transceiver.EnOceanTransceiver] - Interrupt rx Thread
2018-12-20 17:16:22.705 [INFO ] [transceiver.EnOceanSerialTransceiver] - Transceiver shutdown
2018-12-20 17:16:22.712 [hingStatusInfoChangedEvent] - 'enocean:bridge:cd2c57b1' changed from OFFLINE (CONFIGURATION_ERROR): Port could not be found to OFFLINE (CONFIGURATION_PENDING): opening serial port...
2018-12-20 17:16:22.744 [INFO ] [transceiver.EnOceanSerialTransceiver] - EnOceanSerialTransceiver initialized
2018-12-20 17:16:22.751 [hingStatusInfoChangedEvent] - 'enocean:bridge:cd2c57b1' changed from OFFLINE (CONFIGURATION_PENDING): opening serial port... to OFFLINE (CONFIGURATION_PENDING): starting rx thread...
2018-12-20 17:16:22.755 [DEBUG] [nternal.handler.EnOceanBridgeHandler] - request base id
2018-12-20 17:16:22.758 [hingStatusInfoChangedEvent] - 'enocean:bridge:cd2c57b1' changed from OFFLINE (CONFIGURATION_PENDING): starting rx thread... to OFFLINE (CONFIGURATION_PENDING): trying to get bridge base id...
2018-12-20 17:16:22.774 [DEBUG] [ernal.transceiver.EnOceanTransceiver] - Enqueue new send request with ESP3 type COMMON_COMMAND with callback
2018-12-20 17:16:22.790 [DEBUG] [ernal.transceiver.EnOceanTransceiver] - Sending data, type COMMON_COMMAND, payload 08
2018-12-20 17:16:22.823 [DEBUG] [ernal.transceiver.EnOceanTransceiver] - Enqueue new send request with ESP3 type COMMON_COMMAND with callback
2018-12-20 17:16:23.074 [DEBUG] [ernal.transceiver.EnOceanTransceiver] - Sending data, type COMMON_COMMAND, payload 03
2018-12-20 17:16:33.045 [hingStatusInfoChangedEvent] - 'zigbee:device:805460d3:7cb03eaa00acb3cf' changed from UNKNOWN to ONLINE
2018-12-20 17:16:33.057 [hingStatusInfoChangedEvent] - 'zigbee:device:805460d3:7cb03eaa00ace98e' changed from UNKNOWN to ONLINE
2018-12-20 17:16:33.108 [nt.FirmwareStatusInfoEvent] - Firmware status of thing zigbee:device:805460d3:7cb03eaa00acb3cf changed to UNKNOWN.
2018-12-20 17:16:33.114 [nt.FirmwareStatusInfoEvent] - Firmware status of thing zigbee:device:805460d3:7cb03eaa00ace98e changed to UNKNOWN.
2018-12-20 17:16:49.442 [vent.ItemStateChangedEvent] - kz_td_inside_temperature changed from 19.2 to 19.1
2018-12-20 17:16:49.463 [vent.ItemStateChangedEvent] - kz_td_humidity changed from 50.10 to 50.30
2018-12-20 17:17:22.826 [DEBUG] [transceiver.EnOceanSerialTransceiver] - shutting down transceiver
2018-12-20 17:17:22.829 [DEBUG] [ernal.transceiver.EnOceanTransceiver] - Interrupt rx Thread
2018-12-20 17:17:22.833 [DEBUG] [transceiver.EnOceanSerialTransceiver] - Closing serial output stream
2018-12-20 17:17:22.837 [DEBUG] [transceiver.EnOceanSerialTransceiver] - Closeing serial input stream
2018-12-20 17:17:22.840 [DEBUG] [transceiver.EnOceanSerialTransceiver] - Closing serial port
2018-12-20 17:17:22.882 [INFO ] [transceiver.EnOceanSerialTransceiver] - Transceiver shutdown
2018-12-20 17:17:22.894 [hingStatusInfoChangedEvent] - 'enocean:bridge:cd2c57b1' changed from OFFLINE (CONFIGURATION_PENDING): trying to get bridge base id... to OFFLINE (CONFIGURATION_PENDING): opening serial port...
2018-12-20 17:17:22.903 [INFO ] [transceiver.EnOceanSerialTransceiver] - EnOceanSerialTransceiver initialized
2018-12-20 17:17:22.911 [hingStatusInfoChangedEvent] - 'enocean:bridge:cd2c57b1' changed from OFFLINE (CONFIGURATION_PENDING): opening serial port... to OFFLINE (CONFIGURATION_PENDING): starting rx thread...
2018-12-20 17:17:22.913 [DEBUG] [nternal.handler.EnOceanBridgeHandler] - request base id
2018-12-20 17:17:22.916 [DEBUG] [ernal.transceiver.EnOceanTransceiver] - Enqueue new send request with ESP3 type COMMON_COMMAND with callback
2018-12-20 17:17:22.917 [hingStatusInfoChangedEvent] - 'enocean:bridge:cd2c57b1' changed from OFFLINE (CONFIGURATION_PENDING): starting rx thread... to OFFLINE (CONFIGURATION_PENDING): trying to get bridge base id...
2018-12-20 17:17:22.920 [DEBUG] [ernal.transceiver.EnOceanTransceiver] - Sending data, type COMMON_COMMAND, payload 08
2018-12-20 17:17:22.938 [DEBUG] [ernal.transceiver.EnOceanTransceiver] - Enqueue new send request with ESP3 type COMMON_COMMAND with callback
2018-12-20 17:17:22.942 [TRACE] [ernal.transceiver.EnOceanTransceiver] - Received Sync Byte
2018-12-20 17:17:22.948 [TRACE] [ernal.transceiver.EnOceanTransceiver] - >> Received header, data length 5 optional length 1 packet type 2
2018-12-20 17:17:22.958 [DEBUG] [ernal.transceiver.EnOceanTransceiver] - RESPONSE with code RET_OK payload 00FF826D000A received
2018-12-20 17:17:22.962 [DEBUG] [nternal.handler.EnOceanBridgeHandler] - received response for base id
2018-12-20 17:17:22.967 [hingStatusInfoChangedEvent] - 'enocean:bridge:cd2c57b1' changed from OFFLINE (CONFIGURATION_PENDING): trying to get bridge base id... to ONLINE
2018-12-20 17:17:22.966 [DEBUG] [rnal.handler.EnOceanBaseThingHandler] - initializeThing thing enocean:classicDevice:0185F65C bridge status ONLINE
2018-12-20 17:17:22.973 [DEBUG] [rnal.handler.EnOceanBaseThingHandler] - initializeThing thing enocean:rockerSwitch:cd2c57b1:018614C7 bridge status ONLINE
2018-12-20 17:17:22.973 [DEBUG] [rnal.handler.EnOceanBaseThingHandler] - initializeThing thing enocean:classicDevice:018614C7 bridge status ONLINE
2018-12-20 17:17:22.973 [DEBUG] [rnal.handler.EnOceanBaseThingHandler] - initializeThing thing enocean:classicDevice:01860CD3 bridge status ONLINE
2018-12-20 17:17:22.973 [DEBUG] [rnal.handler.EnOceanBaseThingHandler] - initializeThing thing enocean:centralCommand:0082254F bridge status ONLINE
2018-12-20 17:17:22.974 [TRACE] [ernal.transceiver.EnOceanTransceiver] - Response handled
2018-12-20 17:17:23.193 [DEBUG] [ernal.transceiver.EnOceanTransceiver] - Sending data, type COMMON_COMMAND, payload 03
2018-12-20 17:17:23.233 [DEBUG] [ernal.transceiver.EnOceanTransceiver] - Listener added: 25564359
2018-12-20 17:17:23.238 [DEBUG] [rnal.handler.EnOceanBaseThingHandler] - initializeThing thing enocean:centralCommand:050A7B7D bridge status ONLINE
2018-12-20 17:17:23.238 [hingStatusInfoChangedEvent] - 'enocean:classicDevice:018614C7' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2018-12-20 17:17:23.224 [TRACE] [ernal.transceiver.EnOceanTransceiver] - Received Sync Byte
2018-12-20 17:17:23.246 [DEBUG] [rnal.handler.EnOceanBaseThingHandler] - initializeThing thing enocean:rockerSwitch:cd2c57b1:FEFF4BFE bridge status ONLINE
2018-12-20 17:17:23.250 [DEBUG] [ernal.transceiver.EnOceanTransceiver] - Listener added: 8529231
2018-12-20 17:17:23.250 [TRACE] [ernal.transceiver.EnOceanTransceiver] - >> Received header, data length 33 optional length 0 packet type 2
2018-12-20 17:17:23.236 [DEBUG] [rnal.handler.EnOceanBaseThingHandler] - initializeThing thing enocean:classicDevice:01840526 bridge status ONLINE
2018-12-20 17:17:23.264 [DEBUG] [rnal.handler.EnOceanBaseThingHandler] - initializeThing thing enocean:rockerSwitch:cd2c57b1:FEFF4BB7 bridge status ONLINE
2018-12-20 17:17:23.264 [hingStatusInfoChangedEvent] - 'enocean:rockerSwitch:cd2c57b1:018614C7' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2018-12-20 17:17:23.272 [DEBUG] [rnal.handler.EnOceanBaseThingHandler] - initializeThing thing enocean:centralCommand:0183E856 bridge status ONLINE
2018-12-20 17:17:23.277 [DEBUG] [ernal.transceiver.EnOceanTransceiver] - Listener added: 4278143927
2018-12-20 17:17:23.279 [DEBUG] [ernal.transceiver.EnOceanTransceiver] - RESPONSE with code RET_OK payload 000207010002040201018404DA454F0103474154455741594354524C0000000000 received
2018-12-20 17:17:23.309 [DEBUG] [ernal.transceiver.EnOceanTransceiver] - Listener added: 84573053
2018-12-20 17:17:23.274 [DEBUG] [ernal.transceiver.EnOceanTransceiver] - Listener added: 4278143998
2018-12-20 17:17:23.317 [hingStatusInfoChangedEvent] - 'enocean:classicDevice:0185F65C' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2018-12-20 17:17:23.319 [DEBUG] [ernal.transceiver.EnOceanTransceiver] - Listener added: 25421910
2018-12-20 17:17:23.284 [DEBUG] [rnal.handler.EnOceanBaseThingHandler] - initializeThing thing enocean:centralCommand:00877367 bridge status ONLINE
2018-12-20 17:17:23.332 [TRACE] [ernal.transceiver.EnOceanTransceiver] - Response handled
2018-12-20 17:17:23.341 [hingStatusInfoChangedEvent] - 'enocean:classicDevice:01840526' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2018-12-20 17:17:23.354 [DEBUG] [ernal.transceiver.EnOceanTransceiver] - Listener added: 8876903
2018-12-20 17:17:23.346 [hingStatusInfoChangedEvent] - 'enocean:classicDevice:01860CD3' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2018-12-20 17:17:23.359 [hingStatusInfoChangedEvent] - 'enocean:centralCommand:0082254F' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2018-12-20 17:17:23.366 [hingStatusInfoChangedEvent] - 'enocean:rockerSwitch:cd2c57b1:FEFF4BB7' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2018-12-20 17:17:23.371 [hingStatusInfoChangedEvent] - 'enocean:rockerSwitch:cd2c57b1:FEFF4BFE' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2018-12-20 17:17:23.376 [hingStatusInfoChangedEvent] - 'enocean:centralCommand:050A7B7D' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2018-12-20 17:17:23.381 [hingStatusInfoChangedEvent] - 'enocean:centralCommand:0183E856' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2018-12-20 17:17:23.385 [hingStatusInfoChangedEvent] - 'enocean:centralCommand:00877367' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
@martink2
Copy link
Author

Short update, I might have been chasing a red herring with the tty errors
on startup.

I updated to the latest marketplace version and now the binding is started
later in the startup process and i do not see any errors in the log regarding
tty problems.

Unfortunately I still have the same problem with the dimmers:

ThingID: 00877367
EnoceanID: 00877367
SenderID: 5
EEP:Send Gateway Dimming A5_38_08
EEP:Receive Message with dimming Value A5_38_08

Button Pressed

2018-12-20 21:34:29.859 [TRACE] [ernal.transceiver.EnOceanTransceiver] - Received Sync Byte
2018-12-20 21:34:29.864 [TRACE] [ernal.transceiver.EnOceanTransceiver] - >> Received header, data length 7 optional length 7 packet type 1
2018-12-20 21:34:29.880 [DEBUG] [ernal.transceiver.EnOceanTransceiver] - RADIO_ERP1 with RORG RPS for FEFF3B48 payload F650FEFF3B483002FFFFFFFF5900 received

Button Released

2018-12-20 21:34:30.706 [TRACE] [ernal.transceiver.EnOceanTransceiver] - Received Sync Byte
2018-12-20 21:34:30.710 [TRACE] [ernal.transceiver.EnOceanTransceiver] - >> Received header, data length 7 optional length 7 packet type 1
2018-12-20 21:34:30.717 [DEBUG] [ernal.transceiver.EnOceanTransceiver] - RADIO_ERP1 with RORG RPS for FEFF3B48 payload F600FEFF3B482001FFFFFFFF5B00 received

State Telegram from Actor

2018-12-20 21:34:32.480 [TRACE] [ernal.transceiver.EnOceanTransceiver] - Received Sync Byte
2018-12-20 21:34:32.484 [TRACE] [ernal.transceiver.EnOceanTransceiver] - >> Received header, data length 10 optional length 7 packet type 1
2018-12-20 21:34:32.492 [DEBUG] [ernal.transceiver.EnOceanTransceiver] - RADIO_ERP1 with RORG _4BS for 00877367 payload A5024F0009008773670001FFFFFFFF5500 received
2018-12-20 21:34:32.496 [DEBUG] [rnal.handler.EnOceanBaseThingHandler] - ESP Packet payload A5024F00090087736700 for 00877367 received

But at this point the expected state change is not happening.

@martink2 martink2 changed the title Serial Transceiver initialisation error leading to dimmer not being updated Dimmer not updated after openhab restart Dec 22, 2018
@martink2
Copy link
Author

Hi @fruggy83,

i did some further debugging and i can narrow it down a little further:

I have a dimmer thing (wzDiBoden), which is not updating.

I remove the thing and re-create it with the exact same settings -> it starts working

2018-12-24 22:34:57.370 [DEBUG] [org.openhab.binding.openocean       ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=430, service.bundleid=254, service.scope=singleton} - org.openhab.binding.openocean
2018-12-24 22:34:57.422 [DEBUG] [rnal.handler.EnOceanBaseThingHandler] - Initializing enocean base thing handler.
2018-12-24 22:34:57.432 [DEBUG] [rnal.handler.EnOceanBaseThingHandler] - initializeThing thing enocean:centralCommand:050A7B7D bridge status ONLINE
2018-12-24 22:34:57.617 [DEBUG] [ernal.transceiver.EnOceanTransceiver] - Listener added: 84573053
2018-12-24 22:35:42.451 [TRACE] [ernal.transceiver.EnOceanTransceiver] - Received Sync Byte
2018-12-24 22:35:42.455 [TRACE] [ernal.transceiver.EnOceanTransceiver] - >> Received header, data length 10 optional length 7 packet type 1
2018-12-24 22:35:42.462 [DEBUG] [ernal.transceiver.EnOceanTransceiver] - RADIO_ERP1 with RORG _4BS for 050A7B7D payload A502380009050A7B7D0001FFFFFFFF5300 received
2018-12-24 22:35:42.466 [DEBUG] [rnal.handler.EnOceanBaseThingHandler] - ESP Packet payload A502380009050A7B7D00 for 050A7B7D received
2018-12-24 22:35:42.487 [vent.ItemStateChangedEvent] - wzBoden changed from 41 to 56

Now without restarting or any other changes i go in and change something on the
thing (ex. the name):

018-12-24 22:36:37.387 [DEBUG] [rnal.handler.EnOceanBaseThingHandler] - Initializing enocean base thing handler.
2018-12-24 22:36:37.392 [DEBUG] [rnal.handler.EnOceanBaseThingHandler] - initializeThing thing enocean:centralCommand:050A7B7D bridge status ONLINE
2018-12-24 22:36:37.424 [DEBUG] [ernal.transceiver.EnOceanTransceiver] - Listener added: 84573053
2018-12-24 22:36:37.480 [me.event.ThingUpdatedEvent] - Thing 'enocean:centralCommand:050A7B7D' has been updated.
2018-12-24 22:36:56.416 [TRACE] [ernal.transceiver.EnOceanTransceiver] - Received Sync Byte
2018-12-24 22:36:56.421 [TRACE] [ernal.transceiver.EnOceanTransceiver] - >> Received header, data length 10 optional length 7 packet type 1
2018-12-24 22:36:56.430 [DEBUG] [ernal.transceiver.EnOceanTransceiver] - RADIO_ERP1 with RORG _4BS for 050A7B7D payload A5023C0009050A7B7D0001FFFFFFFF5300 received
2018-12-24 22:36:56.434 [DEBUG] [rnal.handler.EnOceanBaseThingHandler] - ESP Packet payload A5023C0009050A7B7D00 for 050A7B7D received

At which point the dimmer value is no longer updated.

As far as i can see the resulting thing in the jsonDB is exactly the same.

Is there anything else you would suggest to do to further dig into the issue ?

Thanks

Martin

@fruggy83
Copy link
Owner

Hi @martink2,

thanks for your analysis. Found the bug and fixed it. Could you please test it? You find the fix in the issue branch. Thanks a lot.

@martink2
Copy link
Author

Hi @fruggy83 ,

thanks again for the quick support. Yes i can confirm with the build from the issue
branch the problem i resolved for me.

@fruggy83
Copy link
Owner

fruggy83 commented Jan 8, 2019

PR created 4542

@fruggy83 fruggy83 closed this as completed Jan 8, 2019
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@martink2 @fruggy83