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?
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
- should I run oh2 from the command line with start_debug, or is it ok to run oh2 as a service with the logging settings that I mentioned?
- should I collect debug info from zwave binding only or from other bindings / modules too (and if yes, what is the easiest way to turn DEBUG for everything)?
- should I change the ConverssionPattern format in the file org.ops4j.pax.logging.cfg, so that it is easier to see the DEBUG messages?
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.