Sorry - I don’t understand what the issue is? The log you’ve provided looks fine - there’s no errors. The message has been sent from a device - not requested from OH, and it looks like its processed the message ok?
Can you provide some more information on the issue?
^^ the log is triggered because I “open/close” the door sensor.
Its missing to update the “item state”.
The following is from another log when everything works fine and that part is just missing randomly after restarts:
2016-03-28 08:33:40.556 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Updating zwave:device:15348538564:node11:sensor_door to CLOSED
zwave_device_15348538564_node11_sensor_door changed from OPEN to CLOSED
Ok, understood… I know there’s a startup issue that I’m working on at the moment - this might be linked to that… Depending on the order things start in, it’s possible that the thing gets initialised before the node, and then events might not get through. I don’t think this should have changed in the last build, but as it’s a timing issue, it might change on each start.
(or it might be something different of course 
).
This is a Fibaro FGBS001 universal binary sensor.
(I know, just scrolling to find something is almost impossible!)
Thanks - I should have asked before, but which parameter has the problem? I assume when you talk about option 5, and 4 to 7, that this is the option value, but I’m not sure what parameter it is… Looking at the database defintion for anything that has an option of 5, and they all look ok…
The only thing that looks out of place is some of the definitions use a value of -1, which isn’t allowed. I suspect that this might be the issue and it would be linked to the new feature in ESH where the values are validated.
OK,
This is the first post
The post shows option/parameter 5, and I am trying to set it to BASIC_SET - it was empty.
Option/parameter 4 is working, but not 5 nor 6. I guess they might be -1 (hence edit field emtpy?).
Yes, so the problem will be the -1 value. This is a) not a valid value in Z-Wave (all values need to be unsigned) and b) outside of the range set in the database (which is actually what’s causing the error in openHAB).
Great!
I’m not sure I understand how it all ties together, but maybe it would be possible to give some sign in HABmin if an invalid option value is found upon presenting the configuration field.
Or maybe have some scanning for -1 when building the zwave device database (I guess that here’s where the problematic -1 originated).
The database already does this. The database provides a list of warnings on the top of the page, but most people are ignoring these messages. Up till now, it hasn’t mattered, but since ESH is now checking to ensure that values are within the limits, it must be resolved or things will fail.
I’ve fixed the errors for this device at least…
Agreed, but in this case, since the data is statically defined in the database, it should be right there since HABmin can’t do much about. I will add validation though for manually entered data…
1 While unplugging my zstick S2 controller from USB port, I include my another appliance binary swtich by pushing button.
2 then I start openhab by ./start.sh
3 when I push the button my appliance binary swtch.
Every time it shows MISMATCH.
Does any body have some suggestion for this problem? Thank you.
2016-03-28 19:18:54.325 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 13 00 49 84 07 0D 04 10 01 25 31 32 27 70 85 72 86 EF 82 53
2016-03-28 19:18:54.327 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2016-03-28 19:18:54.327 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 13 00 49 84 07 0D 04 10 01 25 31 32 27 70 85 72 86 EF 82 53
2016-03-28 19:18:54.327 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 13 00 49 84 07 0D 04 10 01 25 31 32 27 70 85 72 86 EF 82 53
2016-03-28 19:18:54.328 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationUpdate[0x49], type=Request[0x00], priority=High, dest=255, payload=84 07 0D 04 10 01 25 31 32 27 70 85 72 86 EF 82
2016-03-28 19:18:54.329 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 7: Application update request. Node information received.
2016-03-28 19:18:54.330 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent message Message: class=SendData[0x13], type=Request[0x00], priority=Poll, dest=7, payload=07 01 00
2016-03-28 19:18:54.330 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv message Message: class=ApplicationUpdate[0x49], type=Request[0x00], priority=High, dest=255, payload=84 07 0D 04 10 01 25 31 32 27 70 85 72 86 EF 82
2016-03-28 19:18:54.330 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=ApplicationUpdate, callback id=4, expected=SendData, cancelled=false MISMATCH
Here is my log.
No delegation command ‘OFF’ for item ‘Z_socket1’ to handle for channel
’zwave:aeon_dsc06_00_000:1:switch’, because thing is not initialized (must be in status ONLINE or OFFLINE)
I even do some modification for in source code,
public void initialize() {
logger.debug(“Initializing ZWave thing handler.”);
String nodeParm = this.getThing().getProperties().get(ZWaveBindingConstants.PROPERTY_NODEID);
if (nodeParm == null) {
logger.error("NodeID is not set in {}", this.getThing().getUID());
**String label = this.getThing().getLabel();**
**logger.error("Label = {}", label);**
**if (label.equals("zwave:aeon_dsc06_00_000:1")) {**
**//return;**
**nodeParm = "7";**
**} else {**
**//nodeParm = "7";**
**return;**
**}**
//return;
}
However, my aeon_dsc06_00_000:1:switch still stay in initialization forever.
Also I notice it passes initialization procedure as initialize() function.
2016-03-28 19:18:22.044 [INFO ] [me.event.ThingStatusInfoChangedEvent] - ‘zwave:aeon_dsc06_00_000:1’ changed from UNINITIALIZED to INITIALIZING
2016-03-28 19:18:22.045 [ERROR] [ding.zwave.handler.ZWaveThingHandler] - NodeID is not set in zwave:aeon_dsc06_00_000:1
2016-03-28 19:18:22.045 [ERROR] [ding.zwave.handler.ZWaveThingHandler] - Label = zwave:aeon_dsc06_00_000:1
2016-03-28 19:18:22.045 [ERROR] [ding.zwave.handler.ZWaveThingHandler] - nodeParm is 7
2016-03-28 19:18:22.046 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Initialising channel zwave:aeon_dsc06_00_000:1:meter_kwh
2016-03-28 19:18:22.053 [DEBUG] [org.openhab.binding.zwave ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=316, service.bundleid=174, service.scope=singleton} - org.openhab.binding.zwave
2016-03-28 19:18:22.059 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Initialising cmd channel zwave:aeon_dsc06_00_000:1:meter_kwh
2016-03-28 19:18:22.059 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Initialising poll channel zwave:aeon_dsc06_00_000:1:meter_kwh
2016-03-28 19:18:22.060 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Initialising state channel zwave:aeon_dsc06_00_000:1:meter_kwh
2016-03-28 19:18:22.060 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Initialising channel zwave:aeon_dsc06_00_000:1:meter_watts
2016-03-28 19:18:22.061 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Initialising cmd channel zwave:aeon_dsc06_00_000:1:meter_watts
2016-03-28 19:18:22.062 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Initialising poll channel zwave:aeon_dsc06_00_000:1:meter_watts
2016-03-28 19:18:22.063 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Initialising state channel zwave:aeon_dsc06_00_000:1:meter_watts
2016-03-28 19:18:22.063 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Initialising channel zwave:aeon_dsc06_00_000:1:sensor_power
2016-03-28 19:18:22.065 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Initialising cmd channel zwave:aeon_dsc06_00_000:1:sensor_power
2016-03-28 19:18:22.066 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Initialising poll channel zwave:aeon_dsc06_00_000:1:sensor_power
2016-03-28 19:18:22.066 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Initialising state channel zwave:aeon_dsc06_00_000:1:sensor_power
2016-03-28 19:18:22.067 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Initialising channel zwave:aeon_dsc06_00_000:1:switch_binary
2016-03-28 19:18:22.068 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Initialising cmd channel zwave:aeon_dsc06_00_000:1:switch_binary
2016-03-28 19:18:22.069 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Initialising poll channel zwave:aeon_dsc06_00_000:1:switch_binary
2016-03-28 19:18:22.070 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Initialising state channel zwave:aeon_dsc06_00_000:1:switch_binary
2016-03-28 19:18:22.071 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Polling intialised at 15 seconds - start in 15000 milliseconds.
Can some expert shed some light for my problem?
Thank you.
** pollingJob = scheduler.scheduleAtFixedRate(pollingRunnable, initialPeriod, pollingPeriod * 1000,**
** TimeUnit.MILLISECONDS);**
For here, I notice polling Runnable should be scheduled periodically.
However, I notice in my log that, it only be schedule once.
I even could not see any DEBUG log I have put in. Yes, for debug purpose, I modify 1800s as 15s.
Here is my log,
./openhab.log:2016-03-28 19:18:22.071 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Polling intialised at 15 seconds - start in 15000 milliseconds.
./openhab.log:2016-03-28 19:18:37.072 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Polling…
./openhab.log:2016-03-28 19:18:37.072 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Polling***
Here is my modification,
Can some expert shed some light for my problem? Or I just don’t need to worry about this observation? Thank you very much.
For reference purpose for my problems above, here is my configuration,
.sitemap
Switch item=zstick
Switch item=Z_socket1
.items,
//Switch Z_socket1 “Living Room” (Lights) { zwave=“7:command=SWITCH_BINARY” }
Switch Z_socket1 “Living Room” (Lights) { channel=“zwave:aeon_dsc06_00_000:1:SWITCH” }
//Switch Z_socket1 {channel=“zwave:aeon_dsc06_00_000:1:Switch”}
//Switch Z_socket1 {channel=“zwave:device:1:node7:Switch”}
.things,
security_networkkey=“00 11 22 33 44 55 66 77 88 99 AA BB CC DD EE FF”
//zwave:serial_zstick:1 [port="/dev/ttyUSB0"]
zwave:aeon_dsc06_00_000:1 “zwave:aeon_dsc06_00_000:1” [zwave_nodeid=“7”]
This is just a debug message used to infer transaction status - it is perfectly normal.
Hi chris, thank you for information
But it looks like on controller side, a previous transaction is not completed. So the controller assume another packet instead of this one.
As on paper UI, it shows my appliance switch, which is zwave:aeon_dsc06_00_000:1, stay in initialization forever.
Is there a possibility the incomplete transaction MISMATCH related is part of the initialization?
Although we say the moment I push the button happen to be within a transaction, isn’t that strange this coincidence happen every time I push the button?
Thank you.
And also one other observation is it looks like the control flow call starting polling at the end of initialize function in zwaveThingHandler, then the pollingRunnable which is supposed to be schedule periodically only scheduled once.
Although I do not have solid evidence, it looks like the initialization stage forever problem, the pollingRunnable only schedule once problem and the MISMATCH problem is somehow related.
Can someone shed some light for this?
I don’t think so - what transaction do you mean?
Not from what I’ve seen in the log. As I said earlier, this is perfectly normal - it’s NOT an error.
No - this is EXACTLY what will cause this message. If you press the button, then the message is NOT part of a transaction, and you will see this message for sure. Again, this is normal.
I repeat again, this is NOT an problem. It’s a perfectly normal debug message.
I’m not really sure I follow your problem, or your messages. If the device is continuing to initialise, then this is something we can look at with a proper log. However, I’d really suggest that you try to consolidate your messages rather than writing lots of emails a few minutes apart as it makes it hard to follow, and therefore it’s hard to help you as I can’t follow the issue.
Hi chris, thank you for your confirmation.
It looks like to me there is an incomplete transaction from the code below within checkTransactionComplete,
logger.debug(“Checking transaction complete: Sent message {}”, lastSentMessage.toString());
if (incomingMessage.getMessageClass() == lastSentMessage.getExpectedReply()
&& !incomingMessage.isTransactionCanceled()) {
If you say it isn’t, I will take it and thank you.
Please provide the log as I don’t know what transaction you are referring to…