OH2 Z-Wave refactoring and testing... and SECURITY

No - there has been very little change to the binding for a long time. I don’t think it is buggy. If you have a problem, then please provide information on what is wrong - just saying it’s buggy doesn’t really help.

If you are swapping back and forward between the two versions, then it will likely not work. The two bindings are not compatible. If you swap versions, you will need to delete your things and add them back.

If you have included secure devices, they will NOT work with the stable version as the stable version doesn’t support security. Hence the development version.

Of course - I believe that it is stable. As above, if you have a bug to report, then please provide details of the problem.

Hi Chris,

Thank you. I was thinking that the fresh openHAB 2.3.0 stable release (28 mat 2018) embedded the last zwave snapshot binding available before this date. I did not understand that you maintain a stable version without security. I think the version with security has been stable for weeks in my context and it was obvious for me that such a good stuff would be promoted to stable !

So, no bug to report. And many thanks for your work.

Regards,

Romain

Well, for me it does not make sense. First the device lists ASSOCIATION in supported command classes, after that it requests to remove this command class returning version “0”. For sure this is a bug in device’s firmware, but I’d like to solve somehow it.
Here is some code to override command class version but I am not sure how to use it. I assume some properties must be added to the database, but any hint would helpful.

I agree - it’s not meant to do this.

Yes, I’m well aware of this feature. We can add the command class, and we can force the version (this is what I was referring to earlier). However I think that the feature to remove the command class will effectively override this. I need to spend some time to look at this, maybe adding the command class, and forcing the version might work - the class would be removed by the version 0 issue, and then might be added again later.

I was going to play with this as well, but my development machine is not usable and I need to reinstall it unfortunately. :frowning:

I have 2 Z-wave dongles in my system (migrating from one system to another). I added the snapshot binding jar and I can see the first Z-wave dongle in my inbox (wrong tty), but it’s not the one I need to use. I attempted to add the correct one manually in PaperUI, but there’s no obvious way to add it (nothing on the screen to configure?). Should I add the one that is showing and then change the tty setting? I don’t want it to try to talk to the wrong tty.

Adding the controller manually should be exactly the same as it has been since the first version of the binding. Simply go to the things menu, click the + button, select ZWave, select the controller, and fill in the information.

In PaperUI, Configuration -> Things -> Z-wave -> Add Manually -> works - I can add and configure the Z-wave controller.

I had tried Inbox -> Add Manually -> Z-wave -> blank screen. I had tried this latter sequence since the Inbox has the Z-wave controller with the other tty, so it seemed logical that I could add the proper Thing manually through the Inbox. Apparently that is not the case.

Anyway, I have the controller working now. Thanks.

I thought it could also be done through the inbox, but I could be wrong… This logic is nothing to do with the binding and is solely part of the UI…

Anyway, glad you’re up and running :slight_smile: .

Hi @chris,

your binding is very chatty at debug log level, particularly at inclusion time to log it’s comparing against all those potential thing type matches, and at poll time. At the same time it’s somewhat stiff-lipped at info level.
Since I run on Pi and log to NFS (somewhat slower writes), this is actually causing a huge delay in Habmin to display the ‘inclusion’ popup, sometimes it’s even too late. Note I believe this is a pretty common setup, so I’m not just speaking for myself but I believe there’s quite a number of users to be affected by this.

Reducing log level to INFO fixes that but on the other hand does not provide enough information for daily debugging works.
May I ask you to change logging levels a bit to some less output lines on those thing type compares on inclusion (not sure if you’re possibly willing to move them to trace level?)
Could you add some kind of summary line to contain essential data such as node/msg type/value only on each ZWave message on INFO level ? Would help to spot the essential data. Running on debug still requires to ‘parse’ several lines which can be somewhat fatigueing while you’re in need to focus on debugging the problem you’re after.
I think that could be a valuable change. Users could then permanently operate the binding at info level, no more (or just rare) need to change logging levels every time there’s a need for debug.

I always planned on reducing the logging before this version is merged, so yes, things like the thing type comparison, and a lot of the transaction logging will likely just be deleted.

I’m not sure about adding more INFO logging. I’m not sure I completely understand what you mean to be honest? I’m happy to consider something, but there are also guidelines for what should be logged at these levels and it shouldn’t be regular data -:

Only few important things should be logged in info level, e.g. a newly started component or a user file that has been loaded.

A single line output per Z-Wave message (or successful transaction, rather - I don’t mean to show ACKs, retransmits, timeouts etc).

I guess we could argue forever if that fits into the guidelines but clearly it would be valuable to users.
And I think the guideline examples weren’t written with a huge subsystem like your zwave binding in mind so we should be somewhat flexible when it comes to applying them here.

Running on debug all the time obviously is nasty (lots of data produced, painful to parse to find the info you’re looking for due to the sheer amount of data).
Running on info is what most users do, and as of today you always need to switch into debug first if you need to debug a zwave related problem and then reproduce the problem (which sometimes isn’t easy at all 'cause you need to drive OH rules into proper state, too).
Means we don’t have historical data one needs to reconstruct OH state at the time a problem occured.
I believe that with respect to the zwave info needed to resolve the problem on application (rules) level, most of the time that info from my proposed line is sufficient. If we permanently run on info with that message added, we could avoid the need to start a debugging session every time.

Hmmm - I doubt that :wink: . I think that doesn’t fit with INFO, and I’m sure I’ll have people complaining if I do this as that’s still probably tens of thousands of log entries a day on some systems (ie this is not really “few”), and INFO should be nearly no logging I believe.

I will take a look at what can be done to reduce logging though…

Yes, I would be the first one :rofl:
Not every user is logging to a NAS and we already have many, many writes to the sd card with a default setup.

But the idea to move some debug stuff to trace might be a good one :flashlight:

1 Like

Agreed. At binding startup at debug log level, my network generates over 100 MB in a 24 hour period. Of course, it’s less once it reaches steady state. Nonetheless, it can be difficult to track things down with that amount of data.

I rather would vote to pare down debug level, which should make it easier to debug most problems. Trace then could be used to gather information on the most unusual problems.

The big thing is be to be able to have two depth levels of zwave message logging. To users, that really would be a key benefit. One level to it keep switched on all day, to more or less match events.log in terms of frequency and detail level. And the deeper one to explicitly enable for active debugging sessions only. Please reread my explanation above. Another instance of the often encountered difference of a programmer’s vs. the user’s view on things, I guess.
There’ll always be someone to complain if you change things but that’s no argument against.
I’m raising this here for the dev binding to get this adjusted in time before this code gets into wider use (I understood it’s supposed to become part of 2.4) so at least it won’t be THAT many complaints :wink:
We can argue if INFO should be the level to do this at if you believe there’ll be complaints, but we don’t have that many alternatives if we want to stay with available logging system and existing levels, do we ?
I’d be fine, too, to reduce zwave messages to one liners in debug, and to move full zwave message decoding and the thing-comparison and poll debug stuff to trace, how’s about that ?

I think that this is the normal level (Info+) and this should generally result in no routine logging.

This is DEBUG.

We then have TRACE where things get really “messy” :wink:

No, I agree, but I believe that INFO should result in no regular logging - what you are asking for will still result in thousands of messages from the ZWave binding each day, and I know that this will result in complaints (and I believe they would be correct and against the guidelines which states “only few important things” - not ever single message that is sent on the ZWave bus).

For me, DEBUG level should be mainly for the developer - not for the user.

As I said above, the intention was always to reduce the logging. There’s a lot more logging in the development version as it was a major change. A lot of this can be removed, but I don’t want to remove to the level I think you want as then it will be useless for debugging. I can then move things down to trace level, but for debugging, there really needs to be a second level - otherwise we have to log verbose information and normal debug all at TRACE, and that will be a mess as well.

I guess the other question to ask is why do you need what you’re asking for - ie to have a one line summary of each transaction logged at INFO level? Shouldn’t the events log be enough? It summarises all the updates from the bus which I think is basically what you’re looking for with your one line summary?

You as a programmer and me as a user will want to see different things (some to overlap) in what we both would call our ‘debug’ mode, but that’s a somewhat academic discussion since we have to share the existing levels.
So assuming you implemented my proposal to shrink debug output to one-liners and move everything else into trace, I would be running at debug level all day (and @sihui and others to feel that’s too many messages would stay at info).
Yes, this might not show data any more that you (or even I) would hope to see at debug level and require access to in order to perform your or my debugging works.
But I don’t suggest to remove that data but just to move it down one level. So in case of need you or I would level-up to trace. Ok, that’ll now truly be showing everything but in this mode, we would resort to some sort of offline analysis of the logs anyway (so it’s not really that much more work to dissect this now even larger log) while for the reworked debug level to show my one-liners, a ‘live’ tail -f or grep is still feasible
(btw. that’s why I want one-liners, you cannot easily grep for data that’s spread across multiple lines).

No, events are not enough. That’s what we have today and I feel this to be annoying and insufficient for my daily work as a user to operate and eventually debug my home installation. That’s actually the origin why I’m asking you for this log change, and I feel those to have commented already share my view here.
events log doesn’t show the same data, not enough of the relevant data (maybe retransmits, message timing, inclusions, …), it’s not 1:1 events:zwave messages and overall, it only shows data after lots of parsing, conversion and processing in OH where you can never be sure this processing isn’t possibly part of the problem you’re looking after
Those zwave domain one-liners really are the missing link to higher useability (or “debugability”).

Yes, but now you are basically asking for ALL debug information to be in TRACE? Where does TRACE information go? It gets stuck with DEBUG and we have a mess there now.

Do you run your whole system in DEBUG mode? Doesn’t that generate a LOT of other information from the core, and other bindings? I don’t think the ZWave binding is that much different in that respect, but now you want me to remove all (development) debug and only have TRACE level :frowning: . Certainly from my experience, this is the case - yes - the ZWave binding in debug generates a lot of information, but I think so does other parts of the system (doesn’t it?).

I don’t really think this works from a development perspective - sorry.

Your other option may be to play with the logback configuration file to more selectively log information that you want to see?

No, I set log modes per-binding to whatever I feel I need to see for my operations purposes. For ZWave this is messages, so I have to resort to DEBUG although I’d rather like to stay with INFO. Some bindings such as HTTP I run in DEBUG, too, because it’s similar there I don’t see some relevant data in INFO, but usually INFO is a proper default so log level is set to this in most of OH.

Hmm, you’re the boss… but you’re also the only one to do development works on this, aren’t you?
Everone else is a user, so while I clearly respect your pov, I think noone but you will have a problem with having all development related output (DEBUG+TRACE as of today) combined into TRACE only.
Remember my initial suggestion was to use INFO and keep the rest so that wouldn’t happen, but that you dislike too. We both agree that’s not fully in line with the guidelines but we also agree that this has to be some kind of compromise (thus somewhat ‘misuse’ of one or more of the levels) because for a proper solution we’re missing one level.