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
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
# 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?
Let me start from fresh and collect new data. But before that I want to make sure that I have the correct setting to collect DEBUG information. Can you take a look at the post above and tell me
The debug settings you posted looked ok, so that’s why I think the lack of debug information must be due to an exception (ie stopping the logging, rather than the logging not being enabled).
I don’t use start_debug normally - this enables something else that is not related to logging (it provides a debug interface for Eclipse). I’m not sure how you have moved all ZWave logging into another file - I guess you’ve edited the logback.xml file - I don’t tend to do that - I tend to just log everything into a single file. That way everything is roughly in chronological order and we’re not trying to tie up dates from different files and getting into the confusion we have above.
I wouldn’t however enable debug for “everything” - you’ll end up swamping the system with all sorts of stuff from libraries like Jetty. Just enable debug for ZWave, and any other bindings you want - if it’s a reasonable amount, then in my opinion it’s best to have everything together so we see any other strange things happening in the system that might be linked.
Ok, the redirection to different file comes from the file org.ops4j.pax.logging.cfg (see above). I will unite openhab.log, events.log, zwave.log into a single file.
This means that the controller thinks the device is offline. There’s a long discussion about this hidden in the long security thread.
Hi chris, i noticed something strange, the “Node is not communicating with controller” thing only happens to the EZMotion Express sensor, not to my other battery operated devices.
When this happens it blocks my entire z-wave network.
Could it be that it has something to do with the device-list entry in the database or perhaps something else?
@Avner do you also have such behaviour?
thanks all,
br,
Raymond
I was not able to reproduce the problem so far. I think that the events stopping after some time, was just an artifact of using the command tail -f /var/log/openhab2/events.log the and the log rotating.
@RayBe I think I saw the temporary Node is not communicating with the Controller message, but I did not experience any problem as a result. I didn’t find enough time to experiment with the EZMotion Express sensor extensively since it was fixed. I’ll keep my eyes open when I get a chance to play with it more.
It’s nothing to do with the database - this information only comes from the controller. I’ll likely change the logic around DEAD devices again before this is released…
Hi all,
I just managed to reproduce this issue. Please check attached log and tell me if you notice anything special. Exception happened around 12:19:851.
Sorry - just to be clear, what is “this issue”? This thread is very long and discusses many issues…
it is about the zwave serial handler with queue full, causing the zwave controller to stop communicating with the network. Someone mentioned that this might be caused by dead nodes that can not be removed from the network. In my case node 35 is one of those. Only a reboot can restore normal operation.
I’m not sure this is related - but Chris - you may remember the issues I had with the new binding, where no devices would be identified, and that I restored a backup of the stick to get it going. The ONLY difference, that I am aware of, between the backup and the problematic stick was that I had also included the HSM100 in the non-working stick.
I have not yet re-added the hsm100 to the now working network, due to not having had the time.
This may not be related at all, but, I thought I should highlight. However, this does not explain why my system worked fine with the mainline 2.0 binding.
@chris
Hi Chris, since there are no reports anymore that indicate the hsm100 sensor isn’t working for somebody, I assume it’s working perfectly for everybody 
Could you please send back the device and wrap it as I did? Thanks a million for all your hard work.
Best regards,
Raymond
Hi Raymond,
Sure - I think I can find the device 
Can you PM me your address - I think you’ve probably sent it in the past, but let’s be sure
Cheers
Chris
PM send
Did you get it?
Br,
Raymond
I just wanted to confirm that now, the HSM100 works perfectly for me.
@RayBe thanks for sending the device
@chris, thanks for putting all the work into fixing the problem.
Hi Chris,
Sinds its been over a year that nobody is reporting any issues, we can safely say, its working 
Could you please send me the device back?
Thanks for your work.
Best regards,
Raymond
