Motion sensor hsm100 fail to initialise

@Avner So this is working ok now?

On both my sensors i get motion detected and values for lumi and temp.
I think its safe to say that everything is working as it should, what do you guys think @chris, @Avner?

As a note: i just updated the device parameter descriptions so they show up nicely and do not trow a error on the database site :slight_smile:

I think so. I still have this problem, where after a while zwave events stop coming up, and then I get a Queue Full exception error.
I connected another device and when this happened, I stopped seeing events from the other device as well, so I think this is a more general problem that is related to the zwave thread and not specifically to the HSM100.
I opened another thread for this issue here. @chris do you know what could cause the exception?

Not off the top of my head - I’d need to look, but I can probably be pretty sure it’s nothing to do with this device.

Just to be sure, I restarted openhab with the other device only (took the batteries from the HSM100), to see if the Queue Full assertion error still happens, when the HSM100 is not active. So far openhab runs without problem. I’ll keep monitoring…
@chris I read that if other dead nodes (of devices that no longer exist) on the zwave stick can create side effects. Is there a way to remove them without resetting the stick?

I doubt that this is related to the HSM100, but if it is, then you’d be better to put the batteries back in and get a log showing the problem. Getting a log that doesn’t show the problem isn’t going to be useful.

Ok, I put the batteries back on. Attached are the log files:
zwave.log (with DEBUG enabled)
openhab.log
events.log

This time, there is no Queue Full exception error, but the events still stop after some time.
The flow of events is in note1.
I’m working with a stable build, and the development zwave binding on top. I added the development binding using the steps in note2 (Should I do it differently?)


note1 - flow of events

  • Started openhab at around 2017-05-06 08:54

  • OFF/ON events coming from the HASM100 and Fibaro devices at e.g.
    – node6 (Fibaro): 2017-05-06 09:01:06.496, 2017-05-06 09:12:10.579
    – node3 (HSM100): 2017-05-06 09:01:46.219, 2017-05-06 09:12:10.270

  • Communication error events
    – node3 (HSM100): 2017-05-06 13:14:44.666
    – node6 (Fibaro): 2017-05-06 14:48:28.029


note2 - installed bundles

uninstall zwave binding from http://localhost:8080/paperui/index.html#/extensions
cd /usr/share/openhab2/addons
sudo wget http://www.cd-jackson.com/downloads/openhab2/org.openhab.binding.zwave-2.1.0-SNAPSHOT.jar
sudo chown openhab:openhab org.openhab.binding.zwave-2.1.0-SNAPSHOT.jar

openhab> bundle:list -s | grep zwave
200 | Active    |  80 | 2.1.0.201704162057    | ZWave Binding                                          | org.openhab.binding.zwave
202 | Installed |  80 | 2.0.0                 | ZWave Binding                                          | org.openhab.binding.zwave

Sorry - but unless it’s a debug log, it’s really of no use.

Also, there are other errors in your file - you are trying to load two zwave bundles so you should also resolve this so you know what version is actually running.

It is a debug log. Can you please take a look?

I described in here how the development binding was loaded on top of the stable version. Doesn’t status Active for the development binding (2.1.0.201704162057) indicate that this is the version that is running. please let me know how to install the development version on top of a stable OpenHab2, if my development installation steps are not correct.

Sorry - my point was that it isn’t a debug log (unless you updated it today?).

It is a debug log

Ok - so you updated it today then?

Sorry - but I just checked again and it’s not a debug log.

wait, I’ll check again…
It was always a debug log. I think you may have responded before I completed the post (and added the link to the log file)

Sorry - I just realised that you split the ZWave and OH logs into separate files and I was looking at the OH log only.

Yes, there is a dedicated file for zwave (zwave.log)

There is information on installing the binding in the other thread. I’m not sure what is up, but I don’t think you should normally end up with these exceptions in the log. Anyway, that’s not the issue you want to look at.

This log has limited information and is unfortunately unusable. There is no logging of any zwave messages for example and without this it’s impossible to say what is happening.

@chris, in what way the information is limited in the log?
I configured it to DEBUG and captured the entire time from restarting oh2 until zwave events stopped coming in.
Also, the snapshots note1, and note2 line up with this.
If needed, I’ll capture more log information. Let me know.


note1 - Starting of oh2

08:54:30.276 TX REQ SerialApiGetCapabilities

note2 OFF/ON events coming from the HASM100 and Fibaro devices

09:00:15.563	6	STATE UPDATE zwave:device:baa75210:node6:alarm_motion ON [OnOffType]
09:01:06.495	6	STATE UPDATE zwave:device:baa75210:node6:alarm_motion OFF [OnOffType]
09:01:46.216	3	RX REQ ApplicationCommandHandler BASIC_SET

As said earlier, the log you posted has no logging of ZWave messages. There are only logs from a couple of classes (no command classes, no ZWave messages).

Maybe there’s another exception somewhere that is bumping out the receive thread. This could then cause the receive buffer overflow and also the lack of logging. It would be well before the log full exception though.

In the past when running oh2 from the command line I did get messages with the DEBUG annotation, e.g.

2017-01-28 00:14:10.067 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 20: foo

This time I’m running openhab2 as a service. I have set the log level to DEBUG (note1) (the logging config is in note2).

sudo /etc/init.d/openhab2 restart

Should I be running oh2 from the command line instead using start_debug.sh like so?

sudo /usr/share/openhab2/start_debug.sh

note1

openhab> log:list
Logger                                                      | Level
-------------------------------------------------------------------
ROOT                                                        | WARN
javax.jmdns                                                 | ERROR
org.apache.aries.spifly                                     | ERROR
org.apache.karaf.kar.internal.KarServiceImpl                | ERROR
org.eclipse.smarthome                                       | INFO
org.jupnp                                                   | ERROR
org.openhab                                                 | INFO
org.openhab.binding.zwave                                   | DEBUG
org.ops4j.pax.web.service.jetty.internal.JettyServerWrapper | ERROR
smarthome.event                                             | INFO
smarthome.event.InboxUpdatedEvent                           | ERROR
smarthome.event.ItemStateEvent                              | ERROR
smarthome.event.ThingStatusInfoEvent                        | ERROR

note2 - logging config file

# Root logger
log4j.rootLogger = WARN, out, osgi:*
log4j.throwableRenderer=org.apache.log4j.OsgiThrowableRenderer

# openHAB specific logger configuration
log4j.logger.smarthome.event = INFO, event, osgi:*
log4j.logger.smarthome.event.ItemStateEvent = ERROR
log4j.logger.smarthome.event.ThingStatusInfoEvent = ERROR
log4j.logger.smarthome.event.InboxUpdatedEvent = ERROR
log4j.additivity.smarthome.event = false

log4j.logger.org.openhab = INFO
log4j.logger.org.eclipse.smarthome = INFO
log4j.logger.org.jupnp = ERROR
log4j.logger.javax.jmdns = ERROR
log4j.logger.org.ops4j.pax.web.service.jetty.internal.JettyServerWrapper = ERROR
log4j.logger.org.apache.karaf.kar.internal.KarServiceImpl = ERROR
log4j.logger.org.apache.aries.spifly = ERROR

# CONSOLE appender not used by default
log4j.appender.stdout=org.apache.log4j.ConsoleAppender
log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
log4j.appender.stdout.layout.ConversionPattern=%d{HH:mm:ss.SSS} [%-5.5p] [%-36.36c] - %m%n

# File appender - openhab.log
log4j.appender.out=org.apache.log4j.RollingFileAppender
log4j.appender.out.layout=org.apache.log4j.PatternLayout
log4j.appender.out.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss.SSS} [%-5.5p] [%-36.36c] - %m%n
log4j.appender.out.file=${openhab.logdir}/openhab.log
log4j.appender.out.append=true
log4j.appender.out.maxFileSize=10MB
log4j.appender.out.maxBackupIndex=10

# File appender - events.log
log4j.appender.event=org.apache.log4j.RollingFileAppender
log4j.appender.event.layout=org.apache.log4j.PatternLayout
log4j.appender.event.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss.SSS} [%-26.26c{1}] - %m%n
log4j.appender.event.file=${openhab.logdir}/events.log
log4j.appender.event.append=true
log4j.appender.event.maxFileSize=10MB
log4j.appender.event.maxBackupIndex=10

# Sift appender
log4j.appender.sift=org.apache.log4j.sift.MDCSiftingAppender
log4j.appender.sift.key=bundle.name
log4j.appender.sift.default=openhab
log4j.appender.sift.appender=org.apache.log4j.FileAppender
log4j.appender.sift.appender.layout=org.apache.log4j.PatternLayout
log4j.appender.sift.appender.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss.SSS} [%-5.5p] [%-36.36c] - %m%n
log4j.appender.sift.appender.file=${openhab.logdir}/$\\{bundle.name\\}.log
log4j.appender.sift.appender.append=true

# zwave appender
log4j.logger.org.openhab.binding.zwave = DEBUG, zwave, osgi:*
log4j.additivity.org.openhab.binding.zwave = false
log4j.appender.zwave=org.apache.log4j.RollingFileAppender
log4j.appender.zwave.layout=org.apache.log4j.PatternLayout
log4j.appender.zwave.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss.SSS} [%-26.26c{1}] - %m%n
log4j.appender.zwave.file=${openhab.logdir}/zwave.log
log4j.appender.zwave.append=true
log4j.appender.zwave.maxFileSize=10MB
log4j.appender.zwave.maxBackupIndex=10

Ok, so maybe the lack of messages is something else. As I suggested, I wonder if there’s another exception somewhere that is causing the receive thread to exit. Another suggestion is that something bad is happening earlier so that the binding stops processing received data, and then at some point later, you get the queue full.

I can’t tie up the exceptions with errors in the logs as the different logs don’t tie up for me.

The error you show above at 09:00:15 is this one -:

2017-05-06 09:00:15.560 [Handler$ZWaveReceiveThread] - Receive Message = 01 13 00 04 00 06 0D 56 01 71 05 00 00 00 FF 07 08 00 E8 89 51 

This is on the 6 May. If I look in the OH2 log, there is no error at this time on the 6th May. There are 3 exceptions in the OH2 log -:

2017-04-17 05:43:28.805 [ERROR] [WaveSerialHandler$ZWaveReceiveThread] - Exception during ZWave thread. 
2017-04-29 02:02:28.219 [ERROR] [WaveSerialHandler$ZWaveReceiveThread] - Exception during ZWave thread. 
2017-05-04 06:36:31.001 [ERROR] [WaveSerialHandler$ZWaveReceiveThread] - Exception during ZWave thread. 

None of these tie up with either of the logs that you show in note1 or note2 (I’m assuming that’s what you are trying to say when you said it ties up with “this” - “this” being the exceptions?).

Is that what you are trying to show with the log images above?