open-zwave icon indicating copy to clipboard operation
open-zwave copied to clipboard

Published 20 hours ago • verified publisher icon OpenZWave

FIBARO FGT001 Heat Controller does not report Setpoint

Open michapr opened this issue 6 years ago • 20 comments

Hi, Using Version: 1.6-808-gbb0a4bf7-dirty and checking with OZW Control Panel

Seems that Fibaro Thermostat is reporting the setpoint in two different ways:

  1. If changing the Setpoint manual at the thermostat - all is fine and will be reported in OZW Panel (and in Domoticz).
2019-10-09 17:20:00.133 Detail, Node008,   Received: 0x01, 0x10, 0x00, 0x04, 0x00, 0x08, 0x0a, 0x60, 0x0d, 0x01, 0x01, 0x43, 0x03, 0x01, 0x22, 0x00, 0xb4, 0x53
2019-10-09 17:20:00.133 Detail,
2019-10-09 17:20:00.134 Info, Node008, Received a MultiChannelEncap from node 8, endpoint 1 for Command Class COMMAND_CLASS_THERMOSTAT_SETPOINT
2019-10-09 17:20:00.134 Detail, Node008, Refreshed Value: old value=20.0, new value=18.0, type=decimal
2019-10-09 17:20:00.134 Detail, Node008, Changes to this value are not verified
2019-10-09 17:20:00.135 Info, Node008, Received thermostat setpoint report: Setpoint Heating 1 = 18.0C
2019-10-09 17:20:00.135 Detail, Node008, Notification: ValueChanged

If changing the setpoint via Z-Wave command the new Setpoint value will not be shown in Panel (and not in Domoticz) but will be changed at Thermostat. The command for return value seems to be different, and not to be detected by OZW in this case:

2019-10-09 17:18:46.413 Info, Node008, Value::Set - COMMAND_CLASS_THERMOSTAT_SETPOINT - Heating 1 - 1 - 1 - 24
2019-10-09 17:18:46.414 Detail, Node008, Queuing (Send) MultiChannel Encapsulated (instance=1): ThermostatSetpointCmd_Set (Node=8): 0x01, 0x10, 0x00, 0x13, 0x08, 0x09, 0x60, 0x0d, 0x01, 0x01, 0x43, 0x01, 0x01, 0x01, 0x18, 0x25, 0xe9, 0x06
2019-10-09 17:18:46.415 Detail, Node008, Queuing (Send) MultiChannel Encapsulated (instance=1): ThermostatSetpointCmd_Get (Node=8): 0x01, 0x0e, 0x00, 0x13, 0x08, 0x07, 0x60, 0x0d, 0x01, 0x01, 0x43, 0x02, 0x01, 0x25, 0xea, 0x0f
2019-10-09 17:18:46.415 Detail,
2019-10-09 17:18:46.416 Info, Node008, Sending (Send) message (Callback ID=0xe9, Expected Reply=0x13) - MultiChannel Encapsulated (instance=1): ThermostatSetpointCmd_Set (Node=8): 0x01, 0x10, 0x00, 0x13, 0x08, 0x09, 0x60, 0x0d, 0x01, 0x01, 0x43, 0x01, 0x01, 0x01, 0x18, 0x25, 0xe9, 0x06
2019-10-09 17:18:46.416 Info, Node008, Encrypted Flag is 0
2019-10-09 17:18:46.426 Detail, Node008,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2019-10-09 17:18:46.427 Detail, Node008,   ZW_SEND_DATA delivered to Z-Wave stack
2019-10-09 17:18:47.667 Detail, Node008,   Received: 0x01, 0x07, 0x00, 0x13, 0xe9, 0x00, 0x00, 0x7d, 0x7f
2019-10-09 17:18:47.668 Detail, Node008,   ZW_SEND_DATA Request with callback ID 0xe9 received (expected 0xe9)
2019-10-09 17:18:47.668 Info, Node008, Request RTT 1251 Average Request RTT 824
2019-10-09 17:18:47.669 Detail, Node008,   Expected callbackId was received
2019-10-09 17:18:47.669 Detail, Node008,   Expected reply was received
2019-10-09 17:18:47.669 Detail, Node008,   Message transaction complete
2019-10-09 17:18:47.670 Detail,
2019-10-09 17:18:47.670 Detail, Node008, Removing current message
2019-10-09 17:18:47.671 Detail,
2019-10-09 17:18:47.671 Info, Node008, Sending (Send) message (Callback ID=0xea, Expected Reply=0x04) - MultiChannel Encapsulated (instance=1): ThermostatSetpointCmd_Get (Node=8): 0x01, 0x0e, 0x00, 0x13, 0x08, 0x07, 0x60, 0x0d, 0x01, 0x01, 0x43, 0x02, 0x01, 0x25, 0xea, 0x0f
2019-10-09 17:18:47.671 Info, Node008, Encrypted Flag is 0
2019-10-09 17:18:47.680 Detail, Node008,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2019-10-09 17:18:47.680 Detail, Node008,   ZW_SEND_DATA delivered to Z-Wave stack
2019-10-09 17:18:47.702 Detail, Node008,   Received: 0x01, 0x07, 0x00, 0x13, 0xea, 0x00, 0x00, 0x03, 0x02
2019-10-09 17:18:47.702 Detail, Node008,   ZW_SEND_DATA Request with callback ID 0xea received (expected 0xea)
2019-10-09 17:18:47.703 Info, Node008, Request RTT 30 Average Request RTT 427
2019-10-09 17:18:47.703 Detail, Node008,   Expected callbackId was received
2019-10-09 17:18:47.722 Detail, Node008,   Received: 0x01, 0x0e, 0x00, 0x04, 0x00, 0x08, 0x08, 0x60, 0x0d, 0x00, 0x01, 0x22, 0x01, 0x01, 0x02, 0xb9
2019-10-09 17:18:47.722 Detail,
2019-10-09 17:18:47.723 Info, Node008, Response RTT 50 Average Response RTT 54
2019-10-09 17:18:47.723 Info, Node008, MultiChannelEncap with endpoint set to 0 - Send to Root Device
2019-10-09 17:18:47.723 Detail, Node008,   Expected reply and command class was received
2019-10-09 17:18:47.724 Detail, Node008,   Message transaction complete
2019-10-09 17:18:47.724 Detail,
2019-10-09 17:18:47.725 Detail, Node008, Removing current message
2019-10-09 17:18:47.725 Detail, Node008, Notification: Notification - NoOperation

Any chance to get the return value after changing the Setpoint? If you need more info / logs please tell me.

Thanks, Michael

michapr avatar Oct 09 '19 15:10 michapr

Hi! I hope you don't mind me saying this... That is interesting behavior. But I don't know how to fix it.
I am rather new to OpenZWave so maybe that's why I have not seen this before...

What is happening imho is this: OpenZWave asks the setpoint, that is log line

(Send) message (Callback ID=0xea, Expected Reply=0x04) - MultiChannel Encapsulated (instance=1): ThermostatSetpointCmd_Get

Then the reply...

Received: 0x01, 0x0e, 0x00, 0x04, 0x00, 0x08, 0x08, 0x60, 0x0d, 0x00, 0x01, 0x22, 0x01, 0x01, 0x02, 0xb9

That is 0x60 means mulitchannel encap, that is expected, but here is the encapsulated command:

0x22 = COMMAND_CLASS_APPLICATION_STATUS (See 4.2.2 Application Busy Command in SDS13782 Z-Wave Management Command Class Specification.pdf) 0x01 = APPLICATION_BUSY 0x01 = "Try again in Wait Time seconds" 0x02 = two seconds...

So my guess is the FGT-001 is busy after processing that "Set" command and wants the "Get' to be retried after 2 seconds.

I've never used the APPLICATION_STATUS CC but I see it is handled in open-zwave/cpp/src/command_classes/ApplicationStatus.cpp

	notification->SetUserAlertNotification(Notification::Alert_ApplicationStatus_Retry);
	notification->SetRetry(_data[2]);

Now I am a bit confused here, I don't see in your log a notification mentioning this retry, instead I see Notification: "Notification - NoOperation".

Anyway, even when that Notification would be there, I don't think that would solve anything for you because then the application (eg Domoticz or ozwcp) would have to decode the Alert_ApplicationStatus_Retry and do something with it. Which probably is not the case...

@Fishwaldo am I on the right track here? Any idea on how to solve or work around this?

petergebruers avatar Oct 09 '19 18:10 petergebruers

Can add the log from Z-Way, for same device. Maybe it can help to understand how they solve it. (at 06:15 a timer was working)

[2019-10-08 06:15:00.657] [I] [core] ---  ZWayVDev_zway_5-1-67-1 performCommand processing: {"0":"exact","1":{"level":"24"}}
[2019-10-08 06:15:00.658] [D] [zway] SETDATA devices.5.instances.1.commandClasses.67.data.1.setVal = 24.000000
[2019-10-08 06:15:00.658] [D] [zway] SETDATA devices.5.instances.0.commandClasses.108.data.51 = Empty
[2019-10-08 06:15:00.658] [D] [zway] SETDATA devices.5.instances.0.commandClasses.108.data.51.status = Empty
[2019-10-08 06:15:00.658] [D] [zway] SETDATA devices.5.instances.0.commandClasses.108.data.51.duration = Empty
[2019-10-08 06:15:00.659] [D] [zway] SETDATA devices.5.instances.0.commandClasses.108.data.51.moreStatusUpdates = Empty
[2019-10-08 06:15:00.659] [D] [zway] SETDATA devices.5.instances.0.commandClasses.108.data.51.lastEvent = Empty
[2019-10-08 06:15:00.659] [D] [zway] SETDATA devices.5.instances.0.commandClasses.108.data.51.status = 255 (0x000000ff)
[2019-10-08 06:15:00.659] [D] [zway] SETDATA devices.5.instances.0.commandClasses.108.data.51.duration = 0 (0x00000000)
[2019-10-08 06:15:00.659] [D] [zway] SETDATA devices.5.instances.0.commandClasses.108.data.51.moreStatusUpdates = False
[2019-10-08 06:15:00.659] [D] [zway] SETDATA devices.5.instances.0.commandClasses.108.data.51.lastEvent = 14330419 (0x00daaa33)
[2019-10-08 06:15:00.659] [D] [zway] SETDATA devices.5.instances.0.commandClasses.108.data.51 = Empty
[2019-10-08 06:15:00.659] [D] [zway] SETDATA devices.5.instances.0.commandClasses.108.data.lastSession = 51 (0x00000033)
[2019-10-08 06:15:00.659] [I] [zway] Using security scheme S2 Authenticated
[2019-10-08 06:15:00.659] [I] [zway] Adding job: ThermostatSetPoint Set
[2019-10-08 06:15:00.660] [I] [zway] Adding job: Security S2 Encapsulation (S2 Authenticated), ThermostatSetPoint Set
[2019-10-08 06:15:00.661] [D] [zway] SETDATA devices.5.instances.0.commandClasses.108.data.52 = Empty
[2019-10-08 06:15:00.661] [D] [zway] SETDATA devices.5.instances.0.commandClasses.108.data.52.status = Empty
[2019-10-08 06:15:00.661] [D] [zway] SETDATA devices.5.instances.0.commandClasses.108.data.52.duration = Empty
[2019-10-08 06:15:00.661] [D] [zway] SETDATA devices.5.instances.0.commandClasses.108.data.52.moreStatusUpdates = Empty
[2019-10-08 06:15:00.661] [D] [zway] SETDATA devices.5.instances.0.commandClasses.108.data.52.lastEvent = Empty
[2019-10-08 06:15:00.661] [D] [zway] SETDATA devices.5.instances.0.commandClasses.108.data.52.status = 255 (0x000000ff)
[2019-10-08 06:15:00.661] [D] [zway] SETDATA devices.5.instances.0.commandClasses.108.data.52.duration = 0 (0x00000000)
[2019-10-08 06:15:00.661] [D] [zway] SETDATA devices.5.instances.0.commandClasses.108.data.52.moreStatusUpdates = False
[2019-10-08 06:15:00.661] [D] [zway] SETDATA devices.5.instances.0.commandClasses.108.data.52.lastEvent = 14330420 (0x00daaa34)
[2019-10-08 06:15:00.662] [D] [zway] SETDATA devices.5.instances.0.commandClasses.108.data.52 = Empty
[2019-10-08 06:15:00.662] [D] [zway] SETDATA devices.5.instances.0.commandClasses.108.data.lastSession = 52 (0x00000034)
[2019-10-08 06:15:00.662] [I] [zway] Using security scheme S2 Authenticated
[2019-10-08 06:15:00.662] [I] [zway] Adding job: ThermostatMode Set
[2019-10-08 06:15:00.671] [D] [zway] SENDING (cb 0x89): ( 01 21 00 13 05 1A 9F 03 2A 00 75 DE 7A 46 01 89 67 86 85 76 85 88 1A DC A8 2E 5F 5C 82 63 DC 9F 05 89 09 )
[2019-10-08 06:15:00.671] [D] [zway] Secure payload: ( 60 0D 00 01 6C 01 B3 06 43 01 01 22 00 F0 )
[2019-10-08 06:15:00.675] [D] [zway] RECEIVED ACK
[2019-10-08 06:15:00.680] [D] [zway] RECEIVED: ( 01 04 01 13 01 E8 )
[2019-10-08 06:15:00.680] [D] [zway] SENT ACK
[2019-10-08 06:15:00.680] [I] [zway] Job 0x13 (Security S2 Encapsulation (S2 Authenticated), ThermostatSetPoint Set): Response received - transfered to encapsulated jobs
[2019-10-08 06:15:00.680] [D] [zway] Delivered to Z-Wave stack
[2019-10-08 06:15:00.680] [D] [zway] Delivered to Z-Wave stack
[2019-10-08 06:15:00.689] [I] [core] Notification: device-info (device-status): {"dev":"Fibaro Thermostat Heat (5.1)","l":"24 °C","location":1}
[2019-10-08 06:15:02.000] [D] [zway] RECEIVED: ( 01 07 00 13 89 00 00 84 E6 )
[2019-10-08 06:15:02.000] [D] [zway] SENT ACK
[2019-10-08 06:15:02.000] [I] [zway] Job 0x13 (Security S2 Encapsulation (S2 Authenticated), ThermostatSetPoint Set): Callback received - transfered to encapsulated jobs
[2019-10-08 06:15:02.000] [I] [zway] Job 0x13 (ThermostatSetPoint Set): Delivered
[2019-10-08 06:15:02.000] [D] [zway] SendData Response with callback 0x89 received: received by recipient
[2019-10-08 06:15:02.001] [D] [zway] Job 0x13 (ThermostatSetPoint Set): success
[2019-10-08 06:15:02.001] [I] [zway] Waiting for job reply: ThermostatSetPoint Set
[2019-10-08 06:15:02.001] [I] [zway] Job 0x13 (Security S2 Encapsulation (S2 Authenticated), ThermostatSetPoint Set): Delivered
[2019-10-08 06:15:02.001] [D] [zway] SendData Response with callback 0x89 received: received by recipient
[2019-10-08 06:15:02.001] [D] [zway] SETDATA devices.5.data.lastSendInternal = **********
[2019-10-08 06:15:02.001] [D] [zway] SETDATA devices.5.data.lastSend = 14330552 (0x00daaab8)
[2019-10-08 06:15:02.001] [D] [zway] Job 0x13 (Security S2 Encapsulation (S2 Authenticated), ThermostatSetPoint Set): success
[2019-10-08 06:15:02.001] [I] [zway] Removing job: Security S2 Encapsulation (S2 Authenticated), ThermostatSetPoint Set
[2019-10-08 06:15:02.264] [D] [zway] RECEIVED: ( 01 1B 00 04 00 05 15 9F 03 84 00 66 B8 93 42 F8 D0 6E 8B AE 36 22 6F F5 D5 C6 2C 5D 68 )
[2019-10-08 06:15:02.265] [D] [zway] SENT ACK
[2019-10-08 06:15:02.265] [D] [zway] SETDATA devices.5.data.lastReceived = 0 (0x00000000)
[2019-10-08 06:15:02.266] [I] [zway] Node 5:0 CC SecurityS2: passing S2 Authenticated decrypted packet to application level: [ 60 0d 01 00 6c 02 33 ff 00 ]
[2019-10-08 06:15:02.266] [D] [zway] SETDATA devices.5.instances.1.commandClasses.108.data.51 = Empty
[2019-10-08 06:15:02.266] [D] [zway] SETDATA devices.5.instances.1.commandClasses.108.data.51.status = Empty
[2019-10-08 06:15:02.266] [D] [zway] SETDATA devices.5.instances.1.commandClasses.108.data.51.duration = Empty
[2019-10-08 06:15:02.266] [D] [zway] SETDATA devices.5.instances.1.commandClasses.108.data.51.moreStatusUpdates = Empty
[2019-10-08 06:15:02.266] [D] [zway] SETDATA devices.5.instances.1.commandClasses.108.data.51.lastEvent = Empty
[2019-10-08 06:15:02.266] [D] [zway] SETDATA devices.5.instances.1.commandClasses.108.data.51.status = 255 (0x000000ff)
[2019-10-08 06:15:02.266] [D] [zway] SETDATA devices.5.instances.1.commandClasses.108.data.51.duration = 0 (0x00000000)
[2019-10-08 06:15:02.266] [D] [zway] SETDATA devices.5.instances.1.commandClasses.108.data.51.moreStatusUpdates = False
[2019-10-08 06:15:02.266] [D] [zway] SETDATA devices.5.instances.1.commandClasses.108.data.51.lastEvent = 14330578 (0x00daaad2)
[2019-10-08 06:15:02.267] [D] [zway] SETDATA devices.5.instances.1.commandClasses.108.data.51 = Empty
[2019-10-08 06:15:02.267] [D] [zway] Received reply on job (ThermostatSetPoint Set)
[2019-10-08 06:15:02.267] [I] [zway] Node 5:1 CC Supervision: Setter packet was confirmed: ThermostatSetPoint Set
[2019-10-08 06:15:02.267] [D] [zway] SETDATA devices.5.instances.1.commandClasses.67.data.1.size = **********
[2019-10-08 06:15:02.267] [D] [zway] SETDATA devices.5.instances.1.commandClasses.67.data.1.precision = **********
[2019-10-08 06:15:02.267] [D] [zway] SETDATA devices.5.instances.1.commandClasses.67.data.1.deviceScale = 0 (0x00000000)
[2019-10-08 06:15:02.267] [D] [zway] SETDATA devices.5.instances.1.commandClasses.67.data.1.deviceScaleString = "°C"
[2019-10-08 06:15:02.267] [D] [zway] SETDATA devices.5.instances.1.commandClasses.67.data.1.val = 24.000000
[2019-10-08 06:15:02.267] [D] [zway] SETDATA devices.5.instances.1.commandClasses.67.data.1.setVal = 24.000000
[2019-10-08 06:15:02.267] [D] [zway] SETDATA devices.5.instances.1.commandClasses.67.data.1 = Empty
[2019-10-08 06:15:02.268] [I] [zway] Adding job: Security S2 Encapsulation (S2 Authenticated), ThermostatMode Set
[2019-10-08 06:15:02.285] [D] [zway] SENDING (cb 0x8a): ( 01 1E 00 13 05 17 9F 03 2B 00 C7 6E 19 4E 60 11 05 6F 7C 06 AD BA 5C 4D 2B BD 3B 4B 6E 05 8A C9 )
[2019-10-08 06:15:02.285] [D] [zway] Secure payload: ( 60 0D 00 01 6C 01 B4 03 40 01 01 )
[2019-10-08 06:15:02.288] [D] [zway] RECEIVED ACK
[2019-10-08 06:15:02.294] [D] [zway] RECEIVED: ( 01 04 01 13 01 E8 )
[2019-10-08 06:15:02.295] [D] [zway] SENT ACK
[2019-10-08 06:15:02.295] [I] [zway] Job 0x13 (Security S2 Encapsulation (S2 Authenticated), ThermostatMode Set): Response received - transfered to encapsulated jobs
[2019-10-08 06:15:02.295] [D] [zway] Delivered to Z-Wave stack
[2019-10-08 06:15:02.295] [D] [zway] Delivered to Z-Wave stack
[2019-10-08 06:15:02.319] [D] [zway] RECEIVED: ( 01 07 00 13 8A 00 00 03 62 )
[2019-10-08 06:15:02.320] [D] [zway] SENT ACK
[2019-10-08 06:15:02.320] [I] [zway] Job 0x13 (Security S2 Encapsulation (S2 Authenticated), ThermostatMode Set): Callback received - transfered to encapsulated jobs
[2019-10-08 06:15:02.320] [I] [zway] Job 0x13 (ThermostatMode Set): Delivered
[2019-10-08 06:15:02.320] [D] [zway] SendData Response with callback 0x8a received: received by recipient
[2019-10-08 06:15:02.320] [D] [zway] Job 0x13 (ThermostatMode Set): success
[2019-10-08 06:15:02.320] [I] [zway] Waiting for job reply: ThermostatMode Set
[2019-10-08 06:15:02.320] [I] [zway] Job 0x13 (Security S2 Encapsulation (S2 Authenticated), ThermostatMode Set): Delivered
[2019-10-08 06:15:02.320] [D] [zway] SendData Response with callback 0x8a received: received by recipient
[2019-10-08 06:15:02.320] [D] [zway] SETDATA devices.5.data.lastSendInternal = **********
[2019-10-08 06:15:02.320] [D] [zway] SETDATA devices.5.data.lastSend = 14330583 (0x00daaad7)
[2019-10-08 06:15:02.320] [D] [zway] Job 0x13 (Security S2 Encapsulation (S2 Authenticated), ThermostatMode Set): success
[2019-10-08 06:15:02.320] [I] [zway] Removing job: Security S2 Encapsulation (S2 Authenticated), ThermostatMode Set
[2019-10-08 06:15:02.569] [D] [zway] RECEIVED: ( 01 1B 00 04 00 05 15 9F 03 85 00 6F 80 E3 53 15 FE 13 16 5C 1D 4F 21 22 D0 7A 90 B6 D9 )
[2019-10-08 06:15:02.569] [D] [zway] SENT ACK
[2019-10-08 06:15:02.570] [D] [zway] SETDATA devices.5.data.lastReceived = 0 (0x00000000)
[2019-10-08 06:15:02.571] [I] [zway] Node 5:0 CC SecurityS2: passing S2 Authenticated decrypted packet to application level: [ 60 0d 01 00 6c 02 34 ff 00 ]
[2019-10-08 06:15:02.571] [D] [zway] SETDATA devices.5.instances.1.commandClasses.108.data.52 = Empty
[2019-10-08 06:15:02.571] [D] [zway] SETDATA devices.5.instances.1.commandClasses.108.data.52.status = Empty
[2019-10-08 06:15:02.571] [D] [zway] SETDATA devices.5.instances.1.commandClasses.108.data.52.duration = Empty
[2019-10-08 06:15:02.571] [D] [zway] SETDATA devices.5.instances.1.commandClasses.108.data.52.moreStatusUpdates = Empty
[2019-10-08 06:15:02.571] [D] [zway] SETDATA devices.5.instances.1.commandClasses.108.data.52.lastEvent = Empty
[2019-10-08 06:15:02.571] [D] [zway] SETDATA devices.5.instances.1.commandClasses.108.data.52.status = 255 (0x000000ff)
[2019-10-08 06:15:02.571] [D] [zway] SETDATA devices.5.instances.1.commandClasses.108.data.52.duration = 0 (0x00000000)
[2019-10-08 06:15:02.571] [D] [zway] SETDATA devices.5.instances.1.commandClasses.108.data.52.moreStatusUpdates = False
[2019-10-08 06:15:02.571] [D] [zway] SETDATA devices.5.instances.1.commandClasses.108.data.52.lastEvent = 14330608 (0x00daaaf0)
[2019-10-08 06:15:02.571] [D] [zway] SETDATA devices.5.instances.1.commandClasses.108.data.52 = Empty
[2019-10-08 06:15:02.571] [D] [zway] Received reply on job (ThermostatMode Set)
[2019-10-08 06:15:02.571] [I] [zway] Node 5:1 CC Supervision: Setter packet was confirmed: ThermostatMode Set
[2019-10-08 06:15:02.572] [D] [zway] SETDATA devices.5.instances.1.commandClasses.64.data.mode = 1 (0x00000001)
[2019-10-08 06:15:02.640] [D] [zway] RECEIVED: ( 01 1B 00 04 00 05 15 9F 03 85 00 6F 80 E3 53 15 FE 13 16 5C 1D 4F 21 22 D0 7A 90 B6 D9 )
[2019-10-08 06:15:02.640] [D] [zway] SENT ACK
[2019-10-08 06:15:02.641] [D] [zway] SETDATA devices.5.data.lastReceived = 0 (0x00000000)
[2019-10-08 06:15:22.257] [D] [zway] Job 0x13: deleted from queue

Michael

michapr avatar Oct 09 '19 18:10 michapr

@michapr there is no "Get" in that Z-Way log. The device was included with S2 security and they use CC Supervision to confirm secure delivery... OZW does not implement S2 right now (it is on the todo list).

petergebruers avatar Oct 09 '19 18:10 petergebruers

right, forgot about it ;) Here is a log without S2 (value will be changed in interface): Anyway is using CC Supervision, device was included insecure - and the S2 Key was not requested.

[2019-10-09 21:33:00.192] [I] [core] ---  ZWayVDev_zway_16-1-67-1 performCommand processing: {"0":"exact","1":{"level":"18"}}
[2019-10-09 21:33:00.193] [D] [zway] SETDATA devices.16.instances.1.commandClasses.67.data.1.setVal = 18.000000
[2019-10-09 21:33:00.194] [D] [zway] SETDATA devices.16.instances.0.commandClasses.108.data.21 = Empty
[2019-10-09 21:33:00.194] [D] [zway] SETDATA devices.16.instances.0.commandClasses.108.data.21.status = Empty
[2019-10-09 21:33:00.194] [D] [zway] SETDATA devices.16.instances.0.commandClasses.108.data.21.duration = Empty
[2019-10-09 21:33:00.194] [D] [zway] SETDATA devices.16.instances.0.commandClasses.108.data.21.moreStatusUpdates = Empty
[2019-10-09 21:33:00.194] [D] [zway] SETDATA devices.16.instances.0.commandClasses.108.data.21.lastEvent = Empty
[2019-10-09 21:33:00.194] [D] [zway] SETDATA devices.16.instances.0.commandClasses.108.data.21.status = 255 (0x000000ff)
[2019-10-09 21:33:00.194] [D] [zway] SETDATA devices.16.instances.0.commandClasses.108.data.21.duration = 0 (0x00000000)
[2019-10-09 21:33:00.194] [D] [zway] SETDATA devices.16.instances.0.commandClasses.108.data.21.moreStatusUpdates = False
[2019-10-09 21:33:00.194] [D] [zway] SETDATA devices.16.instances.0.commandClasses.108.data.21.lastEvent = 9838154 (0x00961e4a)
[2019-10-09 21:33:00.194] [D] [zway] SETDATA devices.16.instances.0.commandClasses.108.data.21 = Empty
[2019-10-09 21:33:00.194] [D] [zway] SETDATA devices.16.instances.0.commandClasses.108.data.lastSession = 21 (0x00000015)
[2019-10-09 21:33:00.194] [I] [zway] Adding job: ThermostatSetPoint Set
[2019-10-09 21:33:00.195] [D] [zway] SETDATA devices.16.instances.0.commandClasses.108.data.22 = Empty
[2019-10-09 21:33:00.195] [D] [zway] SETDATA devices.16.instances.0.commandClasses.108.data.22.status = Empty
[2019-10-09 21:33:00.195] [D] [zway] SETDATA devices.16.instances.0.commandClasses.108.data.22.duration = Empty
[2019-10-09 21:33:00.195] [D] [zway] SETDATA devices.16.instances.0.commandClasses.108.data.22.moreStatusUpdates = Empty
[2019-10-09 21:33:00.195] [D] [zway] SETDATA devices.16.instances.0.commandClasses.108.data.22.lastEvent = Empty
[2019-10-09 21:33:00.195] [D] [zway] SETDATA devices.16.instances.0.commandClasses.108.data.22.status = 255 (0x000000ff)
[2019-10-09 21:33:00.196] [D] [zway] SETDATA devices.16.instances.0.commandClasses.108.data.22.duration = 0 (0x00000000)
[2019-10-09 21:33:00.196] [D] [zway] SETDATA devices.16.instances.0.commandClasses.108.data.22.moreStatusUpdates = False
[2019-10-09 21:33:00.196] [D] [zway] SETDATA devices.16.instances.0.commandClasses.108.data.22.lastEvent = 9838154 (0x00961e4a)
[2019-10-09 21:33:00.196] [D] [zway] SETDATA devices.16.instances.0.commandClasses.108.data.22 = Empty
[2019-10-09 21:33:00.196] [D] [zway] SETDATA devices.16.instances.0.commandClasses.108.data.lastSession = 22 (0x00000016)
[2019-10-09 21:33:00.196] [I] [zway] Adding job: ThermostatMode Set
[2019-10-09 21:33:00.201] [D] [zway] SENDING (cb 0x47): ( 01 19 00 13 10 12 56 01 60 0D 00 01 6C 01 95 06 43 01 01 22 00 B4 B8 6B 05 47 76 )
[2019-10-09 21:33:00.204] [D] [zway] RECEIVED ACK
[2019-10-09 21:33:00.211] [D] [zway] RECEIVED: ( 01 04 01 13 01 E8 )
[2019-10-09 21:33:00.211] [D] [zway] SENT ACK
[2019-10-09 21:33:00.211] [D] [zway] Delivered to Z-Wave stack
[2019-10-09 21:33:00.231] [I] [core] Notification: device-info (device-status): {"dev":"Fibaro Thermostat Heat (16.1)","l":"18 °C","location":1}
[2019-10-09 21:33:01.505] [D] [zway] RECEIVED: ( 01 07 00 13 47 00 00 82 2E )
[2019-10-09 21:33:01.505] [D] [zway] SENT ACK
[2019-10-09 21:33:01.505] [I] [zway] Job 0x13 (ThermostatSetPoint Set): Delivered
[2019-10-09 21:33:01.506] [D] [zway] SendData Response with callback 0x47 received: received by recipient
[2019-10-09 21:33:01.506] [D] [zway] SETDATA devices.16.data.lastSendInternal = **********
[2019-10-09 21:33:01.506] [D] [zway] SETDATA devices.16.data.lastSend = 9838284 (0x00961ecc)
[2019-10-09 21:33:01.506] [D] [zway] Job 0x13 (ThermostatSetPoint Set): success
[2019-10-09 21:33:01.506] [I] [zway] Waiting for job reply: ThermostatSetPoint Set
[2019-10-09 21:33:01.707] [D] [zway] RECEIVED: ( 01 13 00 04 00 10 0D 56 01 60 0D 01 00 6C 02 15 FF 00 65 86 A9 )
[2019-10-09 21:33:01.708] [D] [zway] SENT ACK
[2019-10-09 21:33:01.709] [D] [zway] SETDATA devices.16.data.lastReceived = 0 (0x00000000)
[2019-10-09 21:33:01.709] [D] [zway] SETDATA devices.16.instances.1.commandClasses.108.data.21 = Empty
[2019-10-09 21:33:01.709] [D] [zway] SETDATA devices.16.instances.1.commandClasses.108.data.21.status = Empty
[2019-10-09 21:33:01.709] [D] [zway] SETDATA devices.16.instances.1.commandClasses.108.data.21.duration = Empty
[2019-10-09 21:33:01.710] [D] [zway] SETDATA devices.16.instances.1.commandClasses.108.data.21.moreStatusUpdates = Empty
[2019-10-09 21:33:01.710] [D] [zway] SETDATA devices.16.instances.1.commandClasses.108.data.21.lastEvent = Empty
[2019-10-09 21:33:01.710] [D] [zway] SETDATA devices.16.instances.1.commandClasses.108.data.21.status = 255 (0x000000ff)
[2019-10-09 21:33:01.710] [D] [zway] SETDATA devices.16.instances.1.commandClasses.108.data.21.duration = 0 (0x00000000)
[2019-10-09 21:33:01.711] [D] [zway] SETDATA devices.16.instances.1.commandClasses.108.data.21.moreStatusUpdates = False
[2019-10-09 21:33:01.711] [D] [zway] SETDATA devices.16.instances.1.commandClasses.108.data.21.lastEvent = 9838304 (0x00961ee0)
[2019-10-09 21:33:01.711] [D] [zway] SETDATA devices.16.instances.1.commandClasses.108.data.21 = Empty
[2019-10-09 21:33:01.711] [D] [zway] Received reply on job (ThermostatSetPoint Set)
[2019-10-09 21:33:01.711] [I] [zway] Node 16:1 CC Supervision: Setter packet was confirmed: ThermostatSetPoint Set
[2019-10-09 21:33:01.712] [D] [zway] SETDATA devices.16.instances.1.commandClasses.67.data.1.size = **********
[2019-10-09 21:33:01.712] [D] [zway] SETDATA devices.16.instances.1.commandClasses.67.data.1.precision = **********
[2019-10-09 21:33:01.712] [D] [zway] SETDATA devices.16.instances.1.commandClasses.67.data.1.deviceScale = 0 (0x00000000)
[2019-10-09 21:33:01.713] [D] [zway] SETDATA devices.16.instances.1.commandClasses.67.data.1.deviceScaleString = "°C"
[2019-10-09 21:33:01.713] [D] [zway] SETDATA devices.16.instances.1.commandClasses.67.data.1.val = 18.000000
[2019-10-09 21:33:01.713] [D] [zway] SETDATA devices.16.instances.1.commandClasses.67.data.1.setVal = 18.000000
[2019-10-09 21:33:01.713] [D] [zway] SETDATA devices.16.instances.1.commandClasses.67.data.1 = Empty
[2019-10-09 21:33:01.714] [D] [zway] SENDING (cb 0x48): ( 01 16 00 13 10 0F 56 01 60 0D 00 01 6C 01 96 03 40 01 01 45 41 05 48 2F )
[2019-10-09 21:33:01.717] [D] [zway] RECEIVED ACK
[2019-10-09 21:33:01.723] [D] [zway] RECEIVED: ( 01 04 01 13 01 E8 )
[2019-10-09 21:33:01.723] [D] [zway] SENT ACK
[2019-10-09 21:33:01.723] [D] [zway] Delivered to Z-Wave stack
[2019-10-09 21:33:01.745] [D] [zway] RECEIVED: ( 01 07 00 13 48 00 00 02 A1 )
[2019-10-09 21:33:01.746] [D] [zway] SENT ACK
[2019-10-09 21:33:01.746] [I] [zway] Job 0x13 (ThermostatMode Set): Delivered
[2019-10-09 21:33:01.747] [D] [zway] SendData Response with callback 0x48 received: received by recipient
[2019-10-09 21:33:01.747] [D] [zway] SETDATA devices.16.data.lastSendInternal = **********
[2019-10-09 21:33:01.747] [D] [zway] SETDATA devices.16.data.lastSend = 9838307 (0x00961ee3)
[2019-10-09 21:33:01.747] [D] [zway] Job 0x13 (ThermostatMode Set): success
[2019-10-09 21:33:01.748] [I] [zway] Waiting for job reply: ThermostatMode Set
[2019-10-09 21:33:02.001] [D] [zway] RECEIVED: ( 01 13 00 04 00 10 0D 56 01 60 0D 01 00 6C 02 16 FF 00 3C D6 A3 )
[2019-10-09 21:33:02.002] [D] [zway] SENT ACK
[2019-10-09 21:33:02.002] [D] [zway] SETDATA devices.16.data.lastReceived = 0 (0x00000000)
[2019-10-09 21:33:02.003] [D] [zway] SETDATA devices.16.instances.1.commandClasses.108.data.22 = Empty
[2019-10-09 21:33:02.003] [D] [zway] SETDATA devices.16.instances.1.commandClasses.108.data.22.status = Empty
[2019-10-09 21:33:02.004] [D] [zway] SETDATA devices.16.instances.1.commandClasses.108.data.22.duration = Empty
[2019-10-09 21:33:02.004] [D] [zway] SETDATA devices.16.instances.1.commandClasses.108.data.22.moreStatusUpdates = Empty
[2019-10-09 21:33:02.004] [D] [zway] SETDATA devices.16.instances.1.commandClasses.108.data.22.lastEvent = Empty
[2019-10-09 21:33:02.005] [D] [zway] SETDATA devices.16.instances.1.commandClasses.108.data.22.status = 255 (0x000000ff)
[2019-10-09 21:33:02.005] [D] [zway] SETDATA devices.16.instances.1.commandClasses.108.data.22.duration = 0 (0x00000000)
[2019-10-09 21:33:02.006] [D] [zway] SETDATA devices.16.instances.1.commandClasses.108.data.22.moreStatusUpdates = False
[2019-10-09 21:33:02.006] [D] [zway] SETDATA devices.16.instances.1.commandClasses.108.data.22.lastEvent = 9838333 (0x00961efd)
[2019-10-09 21:33:02.006] [D] [zway] SETDATA devices.16.instances.1.commandClasses.108.data.22 = Empty
[2019-10-09 21:33:02.007] [D] [zway] Received reply on job (ThermostatMode Set)
[2019-10-09 21:33:02.007] [I] [zway] Node 16:1 CC Supervision: Setter packet was confirmed: ThermostatMode Set
[2019-10-09 21:33:02.008] [D] [zway] SETDATA devices.16.instances.1.commandClasses.64.data.mode = 1 (0x00000001)
[2019-10-09 21:33:03.641] [D] [zway] Job 0x13: deleted from queue

michapr avatar Oct 09 '19 19:10 michapr

I have noticed, if make a polling request then the right value will be given. Not sure, could it be a workaround for the

0x01 = "Try again in Wait Time seconds" 0x02 = two seconds...

So my guess is the FGT-001 is busy after processing that "Set" command and wants the "Get' to be retried after 2 seconds.

Or is there any other solution possible?

michapr avatar Oct 11 '19 07:10 michapr

Polling will drain your battery. Your application can "set" the thermostat, wait 2 seconds then call "bool Manager::RefreshValue(ValueID const& _id)" - the device should then report its actual value. That is a kind of one-shot poll.

petergebruers avatar Oct 11 '19 08:10 petergebruers

If you are running HomeAssistant, an automation can call Z-Wave services, they're listed here:

https://www.home-assistant.io/docs/z-wave/services/

IIRC the service is "refresh_node_value"

Cannot tell you much more about it...

petergebruers avatar Oct 11 '19 08:10 petergebruers

I was thinking about a "one-time-call" of course ;) After the "busy code" of device.

I'm not looking for a solution for myself, but all OZW users, like Domoticz, HomeAssistant etc. So a solution in OZW would be the best and right way ;)

michapr avatar Oct 11 '19 14:10 michapr

Sure. It is open source. You can contribute... I do this in my spare time as a hobby.

petergebruers avatar Oct 11 '19 14:10 petergebruers

If I could, I'd do it right now. But unfortunately I have no experience with the code, so I hope someone else can do this much better and faster ;)

michapr avatar Oct 11 '19 15:10 michapr

Hi! Unfortunately we're understaffed... And some things require a (rather big) refactor.

BTW thanks for the logs files, always good to have them. Looking at Z-Way the most elegant solution would be to support COMMAND_CLASS_SUPERVISION because that eliminates the need to do a "get".

This is on the todo list, under "S2 Tasks":

https://github.com/OpenZWave/open-zwave/issues/1827

Part of the effort to support S2 is to refactor OpenZWave so it can support proper stacking of multicmd, supervision (not available right now), multi channel (supported), security (S0 exists but is kind of hacked-in) and transport (not available right now).

Note to self: I still wonder though what would happen if you send 2 thermostat set points in fast succession to the FGT-001. I think in case of supervision encap, the second one would cause a "working" status. Without supervision (but not doing a get) that might cause "application busy". So still need some way to handle this.

petergebruers avatar Oct 12 '19 13:10 petergebruers

Ive seen a application status message a few times, and yeah, generally means the device is busy doing something else. I've never seen it on a GET though, only SETS

Fishwaldo avatar Oct 14 '19 03:10 Fishwaldo

Dependent on #1827

Fishwaldo avatar Nov 25 '19 08:11 Fishwaldo

Looks like implementing COMMAND_CLASS_SUPERVISION in ThermostatSetpoint::SetValue() is a good way to deal with this issue indeed. I've started programming it, made some progress, and hopefully can make it into a PR at some point. I wonder, is there a dev mailing list for OpenZwave? Just to check my ideas?

markruys avatar Dec 09 '20 21:12 markruys

Okay, I've implemented Supervision CC and use it to set the Fibaro FGT001 and get confirmation without an explicit get. Code works (for me), but is definitely not production quality.

Example:

2020-12-12 22:29:53.430 Info, Node009, Value::Set - COMMAND_CLASS_THERMOSTAT_SETPOINT - Heating 1 - 1 - 1 - 21
2020-12-12 22:29:53.430 Detail, Node009, Queuing (Send) MultiChannel Encapsulated (instance=1): Supervisioned: ThermostatSetpointCmd_Set (Node=9): 0x01, 0x14, 0x00, 0x13, 0x09, 0x0d, 0x60, 0x0d, 0x01, 0x01, 0x6c, 0x01, 0x81, 0x05, 0x43, 0x01, 0x01, 0x01, 0x15, 0x25, 0x2e, 0x24
2020-12-12 22:29:53.431 Detail, 
2020-12-12 22:29:53.431 Info, Node009, Sending (Send) message (Callback ID=0x2e, Expected Reply=0x13) - MultiChannel Encapsulated (instance=1): Supervisioned: ThermostatSetpointCmd_Set (Node=9): 0x01, 0x14, 0x00, 0x13, 0x09, 0x0d, 0x60, 0x0d, 0x01, 0x01, 0x6c, 0x01, 0x81, 0x05, 0x43, 0x01, 0x01, 0x01, 0x15, 0x25, 0x2e, 0x24
2020-12-12 22:29:53.431 Info, Node009, Encrypted Flag is 0
2020-12-12 22:29:53.440 Detail, Node009,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2020-12-12 22:29:53.440 Detail, Node009,   ZW_SEND_DATA delivered to Z-Wave stack
2020-12-12 22:29:54.747 Detail, Node009,   Received: 0x01, 0x07, 0x00, 0x13, 0x2e, 0x00, 0x00, 0x83, 0x46
2020-12-12 22:29:54.747 Detail, Node009,   ZW_SEND_DATA Request with callback ID 0x2e received (expected 0x2e)
2020-12-12 22:29:54.747 Info, Node009, Request RTT 1315 Average Request RTT 672
2020-12-12 22:29:54.747 Detail, Node009,   Expected callbackId was received
2020-12-12 22:29:54.747 Detail, Node009,   Expected reply was received
2020-12-12 22:29:54.747 Detail, Node009,   Message transaction complete
2020-12-12 22:29:54.747 Detail, 
2020-12-12 22:29:54.747 Detail, Node009, Removing current message
2020-12-12 22:29:54.870 Detail, Node009,   Received: 0x01, 0x0f, 0x00, 0x04, 0x00, 0x09, 0x09, 0x60, 0x0d, 0x01, 0x01, 0x6c, 0x02, 0x01, 0xff, 0x00, 0x09
2020-12-12 22:29:54.870 Detail, 
2020-12-12 22:29:54.870 Info, Node009, Received a MultiChannelEncap from node 9, endpoint 1 for Command Class COMMAND_CLASS_SUPERVISION
2020-12-12 22:29:54.870 Info, Node009, Received SupervisionReport: session id 1, status 0xff, duration 0 sec, more status updates 0
2020-12-12 22:29:54.870 Detail, Node009, Value Updated: old value=21.5, new value=21, type=decimal
2020-12-12 22:29:54.870 Detail, Node009, Changes to this value are not verified
2020-12-12 22:29:54.870 Info, Node009, Confirmed thermostat setpoint Heating 1 to 21C
2020-12-12 22:29:54.871 Detail, Node009, Notification: ValueChanged CC: COMMAND_CLASS_THERMOSTAT_SETPOINT Instance: 1 Index: 1

markruys avatar Dec 12 '20 21:12 markruys

@markruys could you please share your code so I can test it in my case?

rafallo avatar Dec 21 '20 09:12 rafallo

Sure. I need some feedback on the implementation by OpenZWave devels before I dare to make it into a PR. It works for my case perfectly well, you can find it at https://github.com/markruys/open-zwave/tree/feature/Supervision

markruys avatar Dec 22 '20 16:12 markruys

Hi @markruys, thanks for your work in implementing a solution for this case. I also have issues with the Heat Controller 'set' command. Would really appreciate if you could make this into a pull request 👍 :)!

robinjanssen91 avatar Jan 02 '21 10:01 robinjanssen91

Pull request can be found here: ~#2525~ #2584.

markruys avatar Jan 03 '21 12:01 markruys

Thanks @markruys ! You're awesome! Hope it gets reviewed and approved soon so everybody can enjoy your great work 👍 !

robinjanssen91 avatar Jan 03 '21 12:01 robinjanssen91