[SOLVED] Z-Wave dongle makes openhab crash

ulfwin · August 16, 2017, 1:32pm

Hi,

I’m trying to enable my aeon z-stick gen5 for use with openhab2, but whenever the dongle is plugged in, openhab crashes. If I restart the service with

sudo service openhab2 start

or restart the computer, the webgui starts and is accessible at first, but disappears after some seconds.

If I unplug the dongle, openhab starts normally.

I’ve tried to find some clue in the log file, and have changed to “TRACE” level for log4j.logger.org.ops4j.pax.web.service.jetty.internal.JettyServerWrapper in file /var/lib/openhab2/etc/org.ops4j.pax.logging.cfg, but it simply stops with:

2017-08-16 14:58:32.031 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Connecting to serial port '/dev/ttyACM0'

Some notes:

There is no reported error before the above row
I’m using debian on an arm single board computer (wandboard)
the openhab user has been added to tty and dialout groups
ttyACM0 has been added to the extra java options

Is this problem known to anyone, or does anybody have any tip on how diagnose this problem?

Any help is much appreciated!

namraccr · August 17, 2017, 5:27am

If it’s a zwave-related dongle, you should try setting the zwave binding into TRACE mode.

ulfwin · August 17, 2017, 6:46am

Hi namraccr,

Thanks for the tip. I now did that, but cannot see any error, or other additional information:

openhab> log:get org.openhab.binding.zwave
Logger                    | Level
---------------------------------
org.openhab.binding.zwave | TRACE
openhab> log:tail org.openhab.binding.zwave
17:21:58.427 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Connecting to serial port '/dev/ttyACM0'
17:27:06.828 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Stopped ZWave serial handler
17:28:33.546 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Connecting to serial port '/dev/ttyACM0'
08:31:15.240 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Stopped ZWave serial handler
08:32:01.912 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Initializing ZWave serial controller.
08:32:01.921 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Initializing ZWave Controller.
08:32:06.935 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Connecting to serial port '/dev/ttyACM0'
Connection to localhost closed by remote host.
Connection to localhost closed.

For the above log, the entries of interest are from 08:31 and later, where I first plugged in the dongle, removed the thing and tried tried to add it again in PaperUI.

5iver · August 17, 2017, 7:21am

To quickly rule out a bad stick, I suggest putting it in another computer and trying to use the Aeon software to see if it responds properly. Although, if you are unplugging/plugging in the stick, you may be getting a different serial port. You may want to look into a udev rule to keep the port configuration static in OH. Anything odd come up for the zstick with dmesg -T | grep tty?

Another thought… what version of the binding are you running, did you compile it, and how did you install it? Is the serial binding installed (bundle:list)? Try tailing openhab.log file to see if there are any other errors coming up.

ulfwin · August 17, 2017, 9:48am

Hi Scott,

Thanks, I’ve tried some of your suggestions.

Aeon doesn’t provide software to use the dongle, besides a backup software. I tried that one, and I’m able to turn the LED blinking off and download the entire Eeprom. So hardware wise it seems to work.

The serial port stays the same. I conclude this since dmesg only list ttyACM0, and because openhab does not crash when the dongle is not connected.

There is nothing odd in dmesg regarding tty, just listings of ttyACM0, seemlingly corresponding to the amount of times I’ve plugged it (let me know if you want me to post it, I’m on another computer right now)

I installed the binding from paperUI (binding-zwave - 2.1.0). I did not install the serial binding. The only thing i found using bundle:list was “nrjavaserial” which has version 3.12.0.OH. Do I need the serial binding as well?

Thanks in advance!

ulfwin · August 17, 2017, 9:50am

Oh, and I also checked the openhab.log file as one of my first steps, but there are no errors listed before the crash

5iver · August 17, 2017, 10:40am

Yes, that was what I was thinking of. They used to provide a download of Zensys Tools too. Cool, it sounds like it’s not hardware!

I thought installing the zwave binding through PaperUI also put down the serial binding… must be wrong on that. But yes, you do need the serial binding! You can find it in PaperUI. Without the serial binding, you should have a bunch of errors in the log too… maybe they were during startup. Anyway, this will hopefully get you going!

ulfwin · August 17, 2017, 2:56pm

Hi again,

I installed the serial binding, but sadly that did not solve the problem. Exact same symptom as before. I tried restarting openhab and reinstalling the z-wave binding without luck…

I see there is also a “z-way” binding. Is that an alternative I could try perhaps?

5iver · August 17, 2017, 3:31pm

I am not familiar with zway, but if you’d like some more help with zwave, it would be very helpful if you would post some logs of the OH startup while the zstick is plugged in and the zwave binding in DEBUG. You may have examples of this in /var/lib/openhab2/logs/openhab.log.

chris · August 17, 2017, 3:36pm

My 2c worth is that this is more likely to be a hardware/driver sort of problem - it shouldn’t really be possible for the binding itself to crash OH - any errors there would just throw an exception. If things are really crashing out, then it’s more likely to be something in the JVM or low level routines.

Probably not - it requires the ZWave.me dongle and their software license.

ulfwin · August 17, 2017, 5:12pm

@5iver: I’ve pasted the output from my openhab.log file for one failed startup. Would be great if you could take a look!

2017-08-17 18:36:29.646 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - Creating new ServletContextHandler for HTTP context [DefaultHttpContext [bundle=org.eclipse.smarthome.core.audio_0.9.0.b5 [99], contextID=default]] and model [ContextModel{id=org.ops4j.pax.web.service.spi.model.ContextModel-1,name=,httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.core.audio_0.9.0.b5 [99], contextID=default],contextParams={},virtualHosts={},connectors={}}]
2017-08-17 18:36:29.787 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - configureSessionManager for context [HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.core.audio_0.9.0.b5 [99], contextID=default]}] using - timeout:10, cookie:JSESSIONID, url:jsessionid, cookieHttpOnly:false, workerName:null, lazyLoad:false, storeDirectory: null
2017-08-17 18:36:29.789 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - Session timeout set to 10 minutes for context [HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.core.audio_0.9.0.b5 [99], contextID=default]}]
2017-08-17 18:36:29.792 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - Session cookie set to JSESSIONID for context [HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.core.audio_0.9.0.b5 [99], contextID=default]}]
2017-08-17 18:36:29.793 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - Session cookieHttpOnly set to false for context [HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.core.audio_0.9.0.b5 [99], contextID=default]}]
2017-08-17 18:36:29.794 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - Session cookie secure set to false for context [HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.core.audio_0.9.0.b5 [99], contextID=default]}]
2017-08-17 18:36:29.795 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - Session URL set to jsessionid for context [HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.core.audio_0.9.0.b5 [99], contextID=default]}]
2017-08-17 18:36:29.796 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - is LazyLoad active? false
2017-08-17 18:36:29.797 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - Added servlet context: HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.core.audio_0.9.0.b5 [99], contextID=default]}
2017-08-17 18:36:30.340 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - ServletContextHandler for HTTP context [DefaultHttpContext [bundle=org.eclipse.smarthome.core.audio_0.9.0.b5 [99], contextID=default]] referenced [1] times.
2017-08-17 18:36:30.965 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - Creating new ServletContextHandler for HTTP context [DefaultHttpContext [bundle=com.eclipsesource.jaxrs.publisher_5.3.1.201602281253 [9], contextID=default]] and model [ContextModel{id=org.ops4j.pax.web.service.spi.model.ContextModel-3,name=,httpContext=DefaultHttpContext [bundle=com.eclipsesource.jaxrs.publisher_5.3.1.201602281253 [9], contextID=default],contextParams={},virtualHosts={},connectors={}}]
2017-08-17 18:36:30.995 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - configureSessionManager for context [HttpServiceContext{httpContext=DefaultHttpContext [bundle=com.eclipsesource.jaxrs.publisher_5.3.1.201602281253 [9], contextID=default]}] using - timeout:10, cookie:JSESSIONID, url:jsessionid, cookieHttpOnly:false, workerName:null, lazyLoad:false, storeDirectory: null
2017-08-17 18:36:30.997 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - Session timeout set to 10 minutes for context [HttpServiceContext{httpContext=DefaultHttpContext [bundle=com.eclipsesource.jaxrs.publisher_5.3.1.201602281253 [9], contextID=default]}]
2017-08-17 18:36:30.997 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - Session cookie set to JSESSIONID for context [HttpServiceContext{httpContext=DefaultHttpContext [bundle=com.eclipsesource.jaxrs.publisher_5.3.1.201602281253 [9], contextID=default]}]
2017-08-17 18:36:30.998 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - Session cookieHttpOnly set to false for context [HttpServiceContext{httpContext=DefaultHttpContext [bundle=com.eclipsesource.jaxrs.publisher_5.3.1.201602281253 [9], contextID=default]}]
2017-08-17 18:36:30.999 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - Session cookie secure set to false for context [HttpServiceContext{httpContext=DefaultHttpContext [bundle=com.eclipsesource.jaxrs.publisher_5.3.1.201602281253 [9], contextID=default]}]
2017-08-17 18:36:31.000 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - Session URL set to jsessionid for context [HttpServiceContext{httpContext=DefaultHttpContext [bundle=com.eclipsesource.jaxrs.publisher_5.3.1.201602281253 [9], contextID=default]}]
2017-08-17 18:36:31.001 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - is LazyLoad active? false
2017-08-17 18:36:31.001 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - Added servlet context: HttpServiceContext{httpContext=DefaultHttpContext [bundle=com.eclipsesource.jaxrs.publisher_5.3.1.201602281253 [9], contextID=default]}
2017-08-17 18:36:31.002 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - (Re)starting servlet contexts...
2017-08-17 18:36:40.008 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'mysql.persist'
2017-08-17 18:36:46.155 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - Creating new ServletContextHandler for HTTP context [DefaultHttpContext [bundle=org.eclipse.smarthome.ui_0.9.0.b5 [136], contextID=default]] and model [ContextModel{id=org.ops4j.pax.web.service.spi.model.ContextModel-6,name=,httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui_0.9.0.b5 [136], contextID=default],contextParams={},virtualHosts={},connectors={}}]
2017-08-17 18:36:46.186 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - configureSessionManager for context [HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui_0.9.0.b5 [136], contextID=default]}] using - timeout:10, cookie:JSESSIONID, url:jsessionid, cookieHttpOnly:false, workerName:null, lazyLoad:false, storeDirectory: null
2017-08-17 18:36:46.187 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - Session timeout set to 10 minutes for context [HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui_0.9.0.b5 [136], contextID=default]}]
2017-08-17 18:36:46.188 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - Session cookie set to JSESSIONID for context [HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui_0.9.0.b5 [136], contextID=default]}]
2017-08-17 18:36:46.189 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - Session cookieHttpOnly set to false for context [HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui_0.9.0.b5 [136], contextID=default]}]
2017-08-17 18:36:46.189 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - Session cookie secure set to false for context [HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui_0.9.0.b5 [136], contextID=default]}]
2017-08-17 18:36:46.190 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - Session URL set to jsessionid for context [HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui_0.9.0.b5 [136], contextID=default]}]
2017-08-17 18:36:46.191 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - is LazyLoad active? false
2017-08-17 18:36:46.192 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - Added servlet context: HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui_0.9.0.b5 [136], contextID=default]}
2017-08-17 18:36:46.192 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - (Re)starting servlet contexts...
2017-08-17 18:36:46.413 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - Creating new ServletContextHandler for HTTP context [DefaultHttpContext [bundle=org.eclipse.smarthome.ui.icon_0.9.0.b5 [137], contextID=default]] and model [ContextModel{id=org.ops4j.pax.web.service.spi.model.ContextModel-9,name=,httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui.icon_0.9.0.b5 [137], contextID=default],contextParams={},virtualHosts={},connectors={}}]
2017-08-17 18:36:46.438 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - configureSessionManager for context [HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui.icon_0.9.0.b5 [137], contextID=default]}] using - timeout:10, cookie:JSESSIONID, url:jsessionid, cookieHttpOnly:false, workerName:null, lazyLoad:false, storeDirectory: null
2017-08-17 18:36:46.440 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - Session timeout set to 10 minutes for context [HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui.icon_0.9.0.b5 [137], contextID=default]}]
2017-08-17 18:36:46.442 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - Session cookie set to JSESSIONID for context [HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui.icon_0.9.0.b5 [137], contextID=default]}]
2017-08-17 18:36:46.443 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - Session cookieHttpOnly set to false for context [HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui.icon_0.9.0.b5 [137], contextID=default]}]
2017-08-17 18:36:46.445 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - Session cookie secure set to false for context [HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui.icon_0.9.0.b5 [137], contextID=default]}]
2017-08-17 18:36:46.447 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - Session URL set to jsessionid for context [HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui.icon_0.9.0.b5 [137], contextID=default]}]
2017-08-17 18:36:46.449 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - is LazyLoad active? false
2017-08-17 18:36:46.451 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - Added servlet context: HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui.icon_0.9.0.b5 [137], contextID=default]}
2017-08-17 18:36:46.453 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - (Re)starting servlet contexts...
2017-08-17 18:36:47.837 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - Creating new ServletContextHandler for HTTP context [org.jupnp.transport.impl.osgi.DisableAuthenticationHttpContext@8bf37f] and model [ContextModel{id=org.ops4j.pax.web.service.spi.model.ContextModel-11,name=,httpContext=org.jupnp.transport.impl.osgi.DisableAuthenticationHttpContext@8bf37f,contextParams={},virtualHosts={},connectors={}}]
2017-08-17 18:36:47.866 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - configureSessionManager for context [HttpServiceContext{httpContext=org.jupnp.transport.impl.osgi.DisableAuthenticationHttpContext@8bf37f}] using - timeout:10, cookie:JSESSIONID, url:jsessionid, cookieHttpOnly:false, workerName:null, lazyLoad:false, storeDirectory: null
2017-08-17 18:36:47.868 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - Session timeout set to 10 minutes for context [HttpServiceContext{httpContext=org.jupnp.transport.impl.osgi.DisableAuthenticationHttpContext@8bf37f}]
2017-08-17 18:36:47.869 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - Session cookie set to JSESSIONID for context [HttpServiceContext{httpContext=org.jupnp.transport.impl.osgi.DisableAuthenticationHttpContext@8bf37f}]
2017-08-17 18:36:47.870 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - Session cookieHttpOnly set to false for context [HttpServiceContext{httpContext=org.jupnp.transport.impl.osgi.DisableAuthenticationHttpContext@8bf37f}]
2017-08-17 18:36:47.872 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - Session cookie secure set to false for context [HttpServiceContext{httpContext=org.jupnp.transport.impl.osgi.DisableAuthenticationHttpContext@8bf37f}]
2017-08-17 18:36:47.873 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - Session URL set to jsessionid for context [HttpServiceContext{httpContext=org.jupnp.transport.impl.osgi.DisableAuthenticationHttpContext@8bf37f}]
2017-08-17 18:36:47.874 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - is LazyLoad active? false
2017-08-17 18:36:47.876 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - Added servlet context: HttpServiceContext{httpContext=org.jupnp.transport.impl.osgi.DisableAuthenticationHttpContext@8bf37f}
2017-08-17 18:36:47.877 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - (Re)starting servlet contexts...
2017-08-17 18:36:48.421 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - Creating new ServletContextHandler for HTTP context [DefaultHttpContext [bundle=org.openhab.ui.dashboard_2.1.0 [170], contextID=default]] and model [ContextModel{id=org.ops4j.pax.web.service.spi.model.ContextModel-13,name=,httpContext=DefaultHttpContext [bundle=org.openhab.ui.dashboard_2.1.0 [170], contextID=default],contextParams={},virtualHosts={},connectors={}}]
2017-08-17 18:36:48.462 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - configureSessionManager for context [HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.openhab.ui.dashboard_2.1.0 [170], contextID=default]}] using - timeout:10, cookie:JSESSIONID, url:jsessionid, cookieHttpOnly:false, workerName:null, lazyLoad:false, storeDirectory: null
2017-08-17 18:36:48.464 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - Session timeout set to 10 minutes for context [HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.openhab.ui.dashboard_2.1.0 [170], contextID=default]}]
2017-08-17 18:36:48.467 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - Session cookie set to JSESSIONID for context [HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.openhab.ui.dashboard_2.1.0 [170], contextID=default]}]
2017-08-17 18:36:48.470 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - Session cookieHttpOnly set to false for context [HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.openhab.ui.dashboard_2.1.0 [170], contextID=default]}]
2017-08-17 18:36:48.472 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - Session cookie secure set to false for context [HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.openhab.ui.dashboard_2.1.0 [170], contextID=default]}]
2017-08-17 18:36:48.475 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - Session URL set to jsessionid for context [HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.openhab.ui.dashboard_2.1.0 [170], contextID=default]}]
2017-08-17 18:36:48.477 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - is LazyLoad active? false
2017-08-17 18:36:48.480 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - Added servlet context: HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.openhab.ui.dashboard_2.1.0 [170], contextID=default]}
2017-08-17 18:36:48.482 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - (Re)starting servlet contexts...
2017-08-17 18:36:48.535 [WARN ] [g.eclipse.smarthome.core.net.NetUtil] - Found multiple local interfaces - ignoring 192.168.0.6
2017-08-17 18:36:48.537 [INFO ] [.dashboard.internal.DashboardService] - Started dashboard at http://10.8.0.1:8080
2017-08-17 18:36:48.540 [WARN ] [g.eclipse.smarthome.core.net.NetUtil] - Found multiple local interfaces - ignoring 192.168.0.6
2017-08-17 18:36:48.542 [INFO ] [.dashboard.internal.DashboardService] - Started dashboard at https://10.8.0.1:8443
2017-08-17 18:36:48.873 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - Creating new ServletContextHandler for HTTP context [DefaultHttpContext [bundle=org.eclipse.smarthome.ui.basic_0.9.0.b5 [176], contextID=default]] and model [ContextModel{id=org.ops4j.pax.web.service.spi.model.ContextModel-16,name=,httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui.basic_0.9.0.b5 [176], contextID=default],contextParams={},virtualHosts={},connectors={}}]
2017-08-17 18:36:48.920 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - configureSessionManager for context [HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui.basic_0.9.0.b5 [176], contextID=default]}] using - timeout:10, cookie:JSESSIONID, url:jsessionid, cookieHttpOnly:false, workerName:null, lazyLoad:false, storeDirectory: null
2017-08-17 18:36:48.921 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - Session timeout set to 10 minutes for context [HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui.basic_0.9.0.b5 [176], contextID=default]}]
2017-08-17 18:36:48.922 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - Session cookie set to JSESSIONID for context [HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui.basic_0.9.0.b5 [176], contextID=default]}]
2017-08-17 18:36:48.924 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - Session cookieHttpOnly set to false for context [HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui.basic_0.9.0.b5 [176], contextID=default]}]
2017-08-17 18:36:48.951 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - Session cookie secure set to false for context [HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui.basic_0.9.0.b5 [176], contextID=default]}]
2017-08-17 18:36:48.953 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - Session URL set to jsessionid for context [HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui.basic_0.9.0.b5 [176], contextID=default]}]
2017-08-17 18:36:48.954 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - is LazyLoad active? false
2017-08-17 18:36:48.955 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - Added servlet context: HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui.basic_0.9.0.b5 [176], contextID=default]}
2017-08-17 18:36:48.956 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - (Re)starting servlet contexts...
2017-08-17 18:36:49.407 [INFO ] [basic.internal.servlet.WebAppServlet] - Started Basic UI at /basicui/app
2017-08-17 18:36:49.489 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - Creating new ServletContextHandler for HTTP context [DefaultHttpContext [bundle=org.eclipse.smarthome.ui.paper_0.9.0.b5 [177], contextID=default]] and model [ContextModel{id=org.ops4j.pax.web.service.spi.model.ContextModel-20,name=,httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui.paper_0.9.0.b5 [177], contextID=default],contextParams={},virtualHosts={},connectors={}}]
2017-08-17 18:36:49.526 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - configureSessionManager for context [HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui.paper_0.9.0.b5 [177], contextID=default]}] using - timeout:10, cookie:JSESSIONID, url:jsessionid, cookieHttpOnly:false, workerName:null, lazyLoad:false, storeDirectory: null
2017-08-17 18:36:49.528 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - Session timeout set to 10 minutes for context [HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui.paper_0.9.0.b5 [177], contextID=default]}]
2017-08-17 18:36:49.529 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - Session cookie set to JSESSIONID for context [HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui.paper_0.9.0.b5 [177], contextID=default]}]
2017-08-17 18:36:49.531 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - Session cookieHttpOnly set to false for context [HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui.paper_0.9.0.b5 [177], contextID=default]}]
2017-08-17 18:36:49.532 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - Session cookie secure set to false for context [HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui.paper_0.9.0.b5 [177], contextID=default]}]
2017-08-17 18:36:49.533 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - Session URL set to jsessionid for context [HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui.paper_0.9.0.b5 [177], contextID=default]}]
2017-08-17 18:36:49.534 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - is LazyLoad active? false
2017-08-17 18:36:49.536 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - Added servlet context: HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.eclipse.smarthome.ui.paper_0.9.0.b5 [177], contextID=default]}
2017-08-17 18:36:49.537 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - (Re)starting servlet contexts...
2017-08-17 18:36:49.549 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Started Paper UI at /paperui
2017-08-17 18:36:49.635 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - Creating new ServletContextHandler for HTTP context [DefaultHttpContext [bundle=org.openhab.ui.habpanel_2.1.0 [179], contextID=default]] and model [ContextModel{id=org.ops4j.pax.web.service.spi.model.ContextModel-22,name=,httpContext=DefaultHttpContext [bundle=org.openhab.ui.habpanel_2.1.0 [179], contextID=default],contextParams={},virtualHosts={},connectors={}}]
2017-08-17 18:36:49.674 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - configureSessionManager for context [HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.openhab.ui.habpanel_2.1.0 [179], contextID=default]}] using - timeout:10, cookie:JSESSIONID, url:jsessionid, cookieHttpOnly:false, workerName:null, lazyLoad:false, storeDirectory: null
2017-08-17 18:36:49.675 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - Session timeout set to 10 minutes for context [HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.openhab.ui.habpanel_2.1.0 [179], contextID=default]}]
2017-08-17 18:36:49.676 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - Session cookie set to JSESSIONID for context [HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.openhab.ui.habpanel_2.1.0 [179], contextID=default]}]
2017-08-17 18:36:49.677 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - Session cookieHttpOnly set to false for context [HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.openhab.ui.habpanel_2.1.0 [179], contextID=default]}]
2017-08-17 18:36:49.679 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - Session cookie secure set to false for context [HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.openhab.ui.habpanel_2.1.0 [179], contextID=default]}]
2017-08-17 18:36:49.680 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - Session URL set to jsessionid for context [HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.openhab.ui.habpanel_2.1.0 [179], contextID=default]}]
2017-08-17 18:36:49.681 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - is LazyLoad active? false
2017-08-17 18:36:49.682 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - Added servlet context: HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.openhab.ui.habpanel_2.1.0 [179], contextID=default]}
2017-08-17 18:36:49.683 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - (Re)starting servlet contexts...
2017-08-17 18:36:49.694 [INFO ] [panel.internal.HABPanelDashboardTile] - Started HABPanel at /habpanel
2017-08-17 18:36:51.784 [DEBUG] [org.openhab.binding.zwave           ] - BundleEvent STARTING - org.openhab.binding.zwave
2017-08-17 18:36:51.793 [DEBUG] [inding.zwave.internal.ZWaveActivator] - Z-Wave binding started. Version 2.1.0
2017-08-17 18:36:52.032 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.ConfigOptionProvider, org.eclipse.smarthome.config.core.ConfigDescriptionProvider}={component.name=org.openhab.binding.zwave.ConfigDescription, component.id=180, service.id=303, service.bundleid=192, service.scope=bundle} - org.openhab.binding.zwave
2017-08-17 18:36:52.045 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.events.EventFactory}={component.name=org.openhab.binding.zwave.event.BindingEventFactory, component.id=181, service.id=304, service.bundleid=192, service.scope=bundle} - org.openhab.binding.zwave
2017-08-17 18:36:52.090 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory}={component.name=org.openhab.binding.zwave.internal.ZWaveHandlerFactory, component.id=184, service.id=305, service.bundleid=192, service.scope=bundle} - org.openhab.binding.zwave
2017-08-17 18:36:52.092 [DEBUG] [org.openhab.binding.zwave           ] - BundleEvent STARTED - org.openhab.binding.zwave
2017-08-17 18:36:52.163 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - Creating new ServletContextHandler for HTTP context [DefaultHttpContext [bundle=org.openhab.core_2.1.0 [166], contextID=default]] and model [ContextModel{id=org.ops4j.pax.web.service.spi.model.ContextModel-24,name=,httpContext=DefaultHttpContext [bundle=org.openhab.core_2.1.0 [166], contextID=default],contextParams={},virtualHosts={},connectors={}}]
2017-08-17 18:36:52.196 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - configureSessionManager for context [HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.openhab.core_2.1.0 [166], contextID=default]}] using - timeout:10, cookie:JSESSIONID, url:jsessionid, cookieHttpOnly:false, workerName:null, lazyLoad:false, storeDirectory: null
2017-08-17 18:36:52.197 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - Session timeout set to 10 minutes for context [HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.openhab.core_2.1.0 [166], contextID=default]}]
2017-08-17 18:36:52.198 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - Session cookie set to JSESSIONID for context [HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.openhab.core_2.1.0 [166], contextID=default]}]
2017-08-17 18:36:52.199 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - Session cookieHttpOnly set to false for context [HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.openhab.core_2.1.0 [166], contextID=default]}]
2017-08-17 18:36:52.201 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - Session cookie secure set to false for context [HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.openhab.core_2.1.0 [166], contextID=default]}]
2017-08-17 18:36:52.202 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - Session URL set to jsessionid for context [HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.openhab.core_2.1.0 [166], contextID=default]}]
2017-08-17 18:36:52.203 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - is LazyLoad active? false
2017-08-17 18:36:52.204 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - Added servlet context: HttpServiceContext{httpContext=DefaultHttpContext [bundle=org.openhab.core_2.1.0 [166], contextID=default]}
2017-08-17 18:36:52.205 [DEBUG] [ce.jetty.internal.JettyServerWrapper] - (Re)starting servlet contexts...
2017-08-17 18:36:56.776 [WARN ] [ore.internal.events.OSGiEventManager] - Dispatching event to subscriber 'org.eclipse.smarthome.core.thing.link.ThingLinkManager@b53227' takes more than 5000ms.
2017-08-17 18:36:56.958 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Initializing ZWave serial controller.
2017-08-17 18:36:56.961 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Initializing ZWave Controller.
2017-08-17 18:36:56.965 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Connecting to serial port '/dev/ttyACM0'

@chris: I fear you’re right… would you have any tip for me to continue if this i the case? I’ve been searching for a tool to debug the z-stick but not found any. I’m using zulu since that was recommended. Is it an idea to try openJDK instead? Do you have any other idea how I can dig deeper?

chris · August 17, 2017, 5:24pm

Based on the log, if this is all there is, then the binding isn’t even talking to the stick. It’s trying to open the serial port, and then it seems to crash out. I’m pretty sure this is going to be a low level issue - drivers or something like that.

You could try any serial port software to see if the port opens or not - that might at least provide some information since the binding isn’t even getting that far.

5iver · August 17, 2017, 6:12pm

Just to get this out of the way… turn off the trace logging for jetty.

You confirmed dmesg | grep tty only returned ttyACM0. This command will provide some device details (including driver).

udevadm info --a -p $(udevadm info -q path -n /dev/ttyACM0)

ulfwin · August 17, 2017, 6:33pm

Ah, that reduced the messages quite a bit :). Here it is:

2017-08-17 20:26:39.935 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'mysql.persist'
2017-08-17 20:26:48.271 [WARN ] [g.eclipse.smarthome.core.net.NetUtil] - Found multiple local interfaces - ignoring 192.168.0.6
2017-08-17 20:26:48.275 [INFO ] [.dashboard.internal.DashboardService] - Started dashboard at http://10.8.0.1:8080
2017-08-17 20:26:48.279 [WARN ] [g.eclipse.smarthome.core.net.NetUtil] - Found multiple local interfaces - ignoring 192.168.0.6
2017-08-17 20:26:48.282 [INFO ] [.dashboard.internal.DashboardService] - Started dashboard at https://10.8.0.1:8443
2017-08-17 20:26:49.047 [INFO ] [basic.internal.servlet.WebAppServlet] - Started Basic UI at /basicui/app
2017-08-17 20:26:49.226 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Started Paper UI at /paperui
2017-08-17 20:26:49.482 [INFO ] [panel.internal.HABPanelDashboardTile] - Started HABPanel at /habpanel
2017-08-17 20:26:56.829 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Connecting to serial port '/dev/ttyACM0'

It appears I don’t have udevadm installed, and it doesn’t exist using apt-get. I’ll look into it to see if I can get it installed…

5iver · August 17, 2017, 6:47pm

How about stty -F /dev/ttyACM0? If it gets a response, the port should be working.

ulfwin · August 18, 2017, 9:44am

Hi @5iver,

There appears to be a response:

debian@debian-armhf:/usr/lib/jvm$ sudo stty -F /dev/ttyACM0
speed 9600 baud; line = 0;
min = 0; time = 0;
-brkint -icrnl -imaxbel
-opost -onlcr
-isig -icanon -iexten -echo -echoe -echok -echoctl -echoke

I read in the openhab installation instructions that java for ARM 64 bit specifically fails for serial communication. I am using 32 bit, but It made me start fiddling with java.

I’ve tried openjdk 6 and 7 (which are not supposed to work anyway I guess), and zulu version 1.8.0_131 and 1.8.0_121, but none of them make any difference.

I also tried to communicate with the dongle using minicom, but I have not figured out exactly what config I need, so no result there.

Do you guys have any other idea of what I might try?

5iver · August 18, 2017, 11:37am

Can you run stty with the account running OH, to make sure it has the permissions it needs? Does anything change if you run OH as root?

ulfwin · August 18, 2017, 1:51pm

Tried your suggestion but no hit I’m afraid:

debian@debian-armhf:/usr/lib/jvm$ sudo -u openhab stty -F /dev/ttyACM0
[sudo] password for debian: 
speed 9600 baud; line = 0;
min = 0; time = 0;
-brkint -icrnl -imaxbel
-opost -onlcr
-isig -icanon -iexten -echo -echoe -echok -echoctl -echoke

I also temporarily changed the init.d script to run as root, but I see the same symptom. Appears to be a tricky issue, this one…

5iver · August 18, 2017, 2:46pm

Here is the stty result from my zstick:

[root@fedora01 rules]# stty -F /dev/ttyACM0
speed 115200 baud; line = 0;
eof = ^A; min = 1; time = 0;
-brkint -icrnl -imaxbel
-opost -onlcr
-isig -icanon -iexten -echo -echoe -echok -echoctl -echoke

The baud rate stands out to me, but the eof might come into play too. The binding may set the baud rate for you (@chris would know). If not, that might be something to try (stty -F /dev/ttyACM0 115200).

Yes… but there has to be a log somewhere with some details . Here are some more things I would try…

Is Java core dumping?
Maybe running OH in debug mode would show something new.
I’m not sure how you are viewing the log, but it looks like you may be sshing into the Karaf console and viewing the log. Can you use ssh into the Wandboard and manually launch OH to see if there’s more being reported after the ssh session ends?
Have you looked into the actual log file and does it literally just stop after connecting to the serial port, or is there more in the file? If you’re manually running OH, you could also then use strace to dig deeper.
To possibly rule out Java as the issue, you could try another app and see if it can communicate with the port. It’s a little old, but maybe something like Java Serial Port Terminal download | SourceForge.net.

chris · August 18, 2017, 2:54pm

Yes - the baud rate is set by the binding (I don’t think it’s possible to open a serial port without specifying the baud rate).