Z-wave things lose their Lifeline Association Group

chris · October 28, 2018, 11:45am

I know I “bang on” about logs a lot, but they tell me exactly what happened at the protocol and binding level, and it what order, timing, etc. Often peoples descriptions of what they did are either too high level, incomplete, or even inaccurate. The logs may not always be perfect - there’s a limit to how much logging can be done, but it will help a LOT to work out where to look, and we can always add more logging in specific areas if needed.

Without the detailed debug logging, it’s really hard, or impossible even, to work out what is happening. I know creating the logs has drawbacks and people don’t like to do it sometimes, but without them, I’m not sure I can really help, and believe me, I would REALLY like to resolve this issue.

OMR · October 28, 2018, 11:48am

I hear you both, problem is that I do not usually have log:set to DEBUG and the INFO level log probably won’t cut it? I remember I set up log4?? (cplus/java) a year back with my settings of log rotations etc, but an OH upgrade wiped it all, Should probably have done it using an override of some sort if that even exists.
As it is now, I only get one openhab.log, no rotation, so I don’t know how much debug logging it will hold.
I will try setting up rotation again, and keep it on during the night.

Back to the matter at hand:

when I tried to set AG1 to Controller -> still nothing heard when pressing S1
an a whim, I set AG2 (Basic set) to controller -> dimmer_switch1 triggered my rule
Coming to think of it, I did set that one last night as well. You know how it is burning the midnight oil …

I will throw out e DEBUG net tonight to see if we can catch anything.

On a side note Chris, HABMIN is acting up a bit. I had to set the AG in PaperUi. After attempting to do it in HABMIN, HABMIN showed the device with no active channels. Killing my Chrome browser tab and reloading HABMIN it appears OK again until trying to manipulate an AG.

sihui · October 28, 2018, 11:52am

mhilbush · October 28, 2018, 11:53am

Definitely won’t cut it for this problem.

It sometimes helps to log zwave to its own log file with its own rotation. If you want, I’ll post a logging config that I use.

OMR · October 28, 2018, 11:55am

Please do! (In a new post, so others may benefit as well?)

mhilbush · October 28, 2018, 12:02pm

Put this in your userdata/etc/org.ops4j.pax.logging.cfg file.

### Zwave custom logger
log4j2.logger.Zwave.name = org.openhab.binding.zwave
log4j2.logger.Zwave.level = DEBUG
log4j2.logger.Zwave.additivity = false
log4j2.logger.Zwave.appenderRefs = Zwave
log4j2.logger.Zwave.appenderRef.Zwave.ref = ZWAVE

### Zwave custom appender
log4j2.appender.Zwave.name = ZWAVE
log4j2.appender.Zwave.type = RollingRandomAccessFile
log4j2.appender.Zwave.fileName = /opt/openhab2/userdata/logs/zwave.log
log4j2.appender.Zwave.filePattern = /opt/openhab2/userdata/logs/zwave.log.%i
log4j2.appender.Zwave.immediateFlush = true
log4j2.appender.Zwave.append = true
log4j2.appender.Zwave.layout.type = PatternLayout
log4j2.appender.Zwave.layout.pattern = %d{yyyy-MM-dd HH:mm:ss.SSS} [%-5.5p] [%-50.50c] - %m%n
log4j2.appender.Zwave.policies.type = Policies
log4j2.appender.Zwave.policies.size.type = SizeBasedTriggeringPolicy
log4j2.appender.Zwave.policies.size.size = 10MB
log4j2.appender.Zwave.strategy.type = DefaultRolloverStrategy
log4j2.appender.Zwave.strategy.max = 20

chris · October 28, 2018, 1:27pm

Thanks Mark. I’ve added this to the docs -:

Let me know if you have any comments before I merge.

jwiseman · October 28, 2018, 1:42pm

Hi Chris,

Running your latest M4 release of the binding. Great job in ALL the work you do for OH!

In my zWave logs I get these sometimes; what does this mean and how do I fix it?

2018-10-27 02:41:48.482 [ERROR] [age.AssignSucReturnRouteMessageClass] - NODE 8: Assign SUC return routes failed.
2018-10-28 02:41:48.773 [ERROR] [age.AssignSucReturnRouteMessageClass] - NODE 4: Assign SUC return routes failed.
2018-10-28 02:41:48.889 [ERROR] [age.AssignSucReturnRouteMessageClass] - NODE 6: Assign SUC return routes failed.
2018-10-28 02:41:49.669 [ERROR] [age.AssignSucReturnRouteMessageClass] - NODE 8: Assign SUC return routes failed.

Best, Jay

OMR · October 28, 2018, 2:30pm

At work, we use log4cplus , and we have log files for each log level. (FATAL+ERROR+WARN/LOG/DEBUG)
(Someone else set that up, so I’m that familiar with it.)
The DEBUG is set to log to a /tmpfs location (RAM-disk) so that the SSD is spared. (product with a 10yrs life span)
These logs do not survive a restart thought. Also, /tmpfs is linux specific.

mhilbush · October 28, 2018, 2:38pm

Yeah, I’m not running on a pi with an SD card, so clearly leaving this on for a long time will further reduce the life of your SD card. I say further, because it’s inevitable that your SD card will fail. It’s just a matter of when…

In my config, I actually store the zwave log files outside of the openhab directory tree. I store 500 files because I occasionally need to look at trends, repeating errors, etc. over time. It also helps reduce backup time by keeping all but the current log file outside the openhab directory tree.

OMR · October 28, 2018, 3:02pm

The target logfile directory did not match my system, and since my /opt is empty, nothing seemed to happen.
I changed these two lines, and the new logfile appeared automatically after my save:

log4j2.appender.Zwave.fileName = ${openhab.logdir}/zwave.log
log4j2.appender.Zwave.filePattern = ${openhab.logdir}/zwave.log.%i

This expands to /var/log/openhab2/zwave.log

mhilbush · October 28, 2018, 3:03pm

Ah, sorry, I should’ve mentioned that you needed to adjust the paths for your installation.

OMR · October 28, 2018, 10:06pm

Just noticed that 2 more switches, one other Fibaro dimmer-2 and one everspring, had stopped reporting back local ON/OFF switching.
Don’t know exactly when this happened.
I had to apply Controller to AG1 & AG2.
Funny thing was this time I only got it to work in HABMIN, but only after restarting my browser.

Anyhow, my Z-Wave debugging is on, so lets see what happens during the night.

OMR · October 29, 2018, 9:21am

Jury is in.
Still works this morning after network healing 7hrs ago.
So this was probably OH2 upgrade related and no logs exists.

I will leave the Z-Wave DEBUG logging active for some days and keep an eye on this.

jussi_railakari · October 31, 2018, 8:09pm

Hello @chris, thanks for your help! At least Openhab 1.x - 2.3. I have used example for Fibaro Dimmer 2 switch_dimmer channel (0). It has worked correctly on previous version.

So now I changed .items configuration switch_dimmer to switch_dimmer1. Also I updated Openhab snapshot version to openHAB 2.4.0 Build #1404. After I updated newer version, I needed to reconfigure all zwave devices Lifeline to Controller. After that (fibaro dimmer 2) wall button work correctly. Item state from wall switch reported ON / OFF immediately.
Br,
Jussi

jjennings308 · November 13, 2018, 6:57pm

@chris I am also having the same problem since changing to version 2.4. The associated group is turned to node_1 on every reboot which includes updating the system to the latest snapshot every few days.

shorty707 · November 13, 2018, 7:18pm

I have this currently randomly … every restart of openhab some devices stop working.
They get stuck at request nif or loose the association.

will do a debug and post it

jwiseman · November 13, 2018, 7:19pm

This is also happening to me and I’m running OH2.3. Tried to change them to Controller but it reverts back to node_1. I’m running 2 types of zWave devices on my network. Not sure if this behavior is OK or NOT?

Best, Jay

OMR · November 13, 2018, 8:53pm

No problems for 15d now.
I too have noticed that Controller associations are listed as node_1 after a reboot, but things work OK.
Isn’t the Controller node #1 anyway?

Landstad · November 13, 2018, 9:33pm

I too experience this. But by itself the name in the GUI doesn’t really matter (node_1, controller or “” - as long as the controller receives reports everything is okay).