OpenZWave / open-zwave

a C++ library to control Z-Wave Networks via a USB Z-Wave Controller.
http://www.openzwave.net/
GNU Lesser General Public License v3.0
1.05k stars 912 forks source link

Labels of PST02 in Secure Mode are wrong in ozwcp #1899

Open petergebruers opened 5 years ago

petergebruers commented 5 years ago

Originally posted by @gizmocuz in https://github.com/OpenZWave/open-zwave/issues/1896#issuecomment-515752364

I do have a strange issue with the PST02 !

When i included the node 'secure', and operating the device magnet to simulate a door open/close, i am receiving strange index values with strange labels, or no labels at all:

image

I excluded it, included it in the normal way, and it seems to work much better !!

Excluded it... included it secure again....

Again strange values are received:

image

Last test, exclude, include normal again, working without any issue !

I think this is unrelated to this issue, but there is something not correct here...

Originally posted by @gizmocuz in https://github.com/OpenZWave/open-zwave/issues/1896#issuecomment-515752364

petergebruers commented 5 years ago

You don't happen to have an OZW_Log.txt from the start of inclusion (secure mode) up to the point where you call a refresh on this device in ozwcp?

gizmocuz commented 5 years ago

@petergebruers , hereby a log from the include moment, till some strange index are received:

OZW_PST02_Secure_Log.zip

And here a log after a restart (node was already included secure)... not doing anything (sensor is under my hands while typing)...

OZW_PST02_After_Restart_Log.zip

petergebruers commented 5 years ago

Thanks for the log, that really helped.

I can see what causes this, but I still have to work out the details in the source code, and a fix... But explaining it is step 1.

The PST02 sends "encapsulated multi-command" meaning it can pack multiple CCs into one or more transmissions, this makes the data transfer more efficient.

If the number of commmands is low, it fits in to one encrypted packet and OZW decodes this as expected. For example:

2019-07-28 20:08:45.489 Info, Node010, Received encapsulated multi-command from node 10
2019-07-28 20:08:45.489 Info, Node010, Received SensorMultiLevel report from node 10, instance 1, Air Temperature: value=84F
2019-07-28 20:08:45.490 Detail, Node010, Refreshed Value: old value=-40.0, new value=84, type=decimal
2019-07-28 20:08:45.491 Detail, Node010, Changes to this value are not verified
2019-07-28 20:08:45.492 Info, Node010, End of encapsulated multi-command from node 10

The source packet is 2019-07-28 20:08:45.485 Detail, Node010, Decrypted Packet: 0x00, 0x8f, 0x01, 0x01, 0x06, 0x31, 0x05, 0x01, 0x0a, 0x00, 0x54

Manual decode:

0x00 btfield is zero 0x8f COMMAND_CLASS_MULTI_CMD

SDS13783 Z-Wave Transport-Encapsulation Command Class Specification.pdf

0x01 MULTI_CMD_ENCAP 0x01 Number of commands 0x06 Command Length 1

So now we get at command 1

0x31 COMMAND_CLASS_SENSOR_MULTILEVEL (assuming level 1 here) 0x05 report 0x01 Sensor type: Air Temperature 0x0a = 0b00001010 -> size 2, scale Fahrenheit 0x00 = MSB 0x54 = LSB == 84 Fahrenheit

So te information in the log is correct.

When I scroll down in the log I find an "encapsulated multi-command" that does NOT fit in one encrypted packet... So here's what happens.

2019-07-28 20:08:45.867 Info, Node010, Received encapsulated multi-command from node 10
2019-07-28 20:08:45.869 Info, Node010, Received Battery report from node 10: level=100
2019-07-28 20:08:45.869 Detail, Node010, Refreshed Value: old value=100, new value=100, type=byte
2019-07-28 20:08:45.870 Detail, Node010, Changes to this value are not verified
2019-07-28 20:08:45.871 Info, Node010, Received Notification report (>v1): Type: Access Control (6) Event: Door/Window Closed (23) Status: true, Param Length: 0
2019-07-28 20:08:45.872 Detail, Node010, Initial read of value
2019-07-28 20:08:45.873 Info, Node010, Received SensorMultiLevel report from node 10, instance 1, Illuminance: value=95%
2019-07-28 20:08:45.874 Detail, Node010, Refreshed Value: old value=76, new value=95, type=decimal
2019-07-28 20:08:45.875 Detail, Node010, Changes to this value are not verified
2019-07-28 20:08:45.876 Info, Node010, Received SensorMultiLevel report from node 10, instance 1, Water Temperature: value=97C
2019-07-28 20:08:45.877 Detail, Node010, Initial read of value
2019-07-28 20:08:45.877 Info, Node010, End of encapsulated multi-command from node 10

You might think it makes sense, but it doesn't........ the PST02 does not have "Water Temperature: value=97C"... The first 3 Values makes sense, the 4th one does not make sense.

2019-07-28 20:08:45.854 Detail, Node010, Decrypted Packet: 0x11, 0x8f, 0x01, 0x04, 0x03, 0x80, 0x03, 0x64, 0x09, 0x71, 0x05, 0x00, 0x00, 0x00, 0xff, 0x06, 0x17, 0x00, 0x05, 0x31, 0x05, 0x03, 0x01, 0x5f, 0x06, 0x31, 0x05

Ah, now it gets interesting!

0x11 bitfield is NOT zero. = 0b10001 meaning "sequenced" and "sequence 1" 0x8f COMMAND_CLASS_MULTI_CMD

0x01 MULTI_CMD_ENCAP 0x04 Number of commands 0x03 Command Length 1

So... This is going to be only "part 1"

So Lets chop the multicmd...

0x04, 0x03, 0x80, 0x03, 0x64, - battery - OK 0x09, 0x71, 0x05, 0x00, 0x00, 0x00, 0xff, 0x06, 0x17, 0x00, - notification - makes sense 0x05, 0x31, 0x05, 0x03, 0x01, 0x5f, - sensor - very plausible 0x06, 0x31, 0x05 - sensor incomplete -> garbage decoded, prints 'Water Temperature'

OZW should not decode the 4th encapsulated command yet, more data follows as

Packet 2: 0x12, 0x8f, 0x01, 0x04, 0x03, 0x80, 0x03, 0x64, 0x09, 0x71, 0x05, 0x00, 0x00, 0x00, 0xff, 0x06, 0x16, 0x00, 0x05, 0x31, 0x05, 0x03, 0x01, 0x5f, 0x06, 0x31, 0x05

petergebruers commented 5 years ago

A quick update. I have tried to reproduce this with a Z-Unoe because it supports multi command, but unfortunately I cannot force it to exceed that size of a single encrypted packet. I am rather new to the security class so I've decided to build a simulator to "inject" packets like the PST02 does, so I can test/debug this. A possible first easy to implement improvement is to check in multicmd if the encapsulated packet fits in the data packet. If it does not, drop it and log an error. The root cause of the issue is in Driver::ProcessMsg and this is more difficult to solve. My preliminary investigation tells me it does nog handle the bits "Second Frame | Sequenced | Sequence Counter" of the SECURITY_MESSAGE_ENCAPSULATION(_NONCE_GET)... See SDS13783 Z-Wave Transport-Encapsulation Command Class Specification. I need more time.

petergebruers commented 5 years ago

This problem will be affected by Justin's proposal to implement S2 security:

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

As he has mentioned, when implementing S2 it is a good idea to revisit the various "encapsulation" commands. (Transport Encapsulation spec, 2.3.5 Encapsulation order overview)

Fishwaldo commented 5 years ago

Yeah. We don’t handle sequenced frames in S0. This is maybe the 2nd device I’ve heard of that has frames longer than a single packet.

It just needs a buffer and should be handled in ZWSecurity. I believe there is a todo comment in there.

petergebruers commented 5 years ago

Okay, I'll try to fix this, even when it affects a small number of devices... I've got some captures of a PST02 in secure mode, I should be able to test this. A usual, I will be slow but I'll try anyway ;)

petergebruers commented 5 years ago

@gizmocuz step 1 (of 2) of fixing this has been merged in master, that is OpenZwave Version 1.6-910-g0c01380b

This will avoid creation of the bogus data and in OZW_Log you'll see:

Error, Node013, Multi-command command part 4 with base 22 is invalid, end > highest_index (28 > 24)

gizmocuz commented 5 years ago

@petergebruers , thank you for this !! I tested the patch and it is working great so far !!!

petergebruers commented 5 years ago

Quick update to let you know I am still working on the fix of the secure packet handling. I mean the implementation of sequenced S0 messages, as sent by the PST02. There are several reasons why you don't see any progress on this, I'll give a few. The main reason is that I want to be sure it does not break anything. This means I have to do thorough testing. I also have to keep in mind there are a few reports of possible issues with S0 in combination with certain devices or circumstances...

For example:

"Encrypted SwitchBinaryCmd_Get sometimes fails, timing issue in OZW or busy network?" https://github.com/OpenZWave/open-zwave/issues/1851

"No idea where to start with this error that causes my Z-wave network to hang" https://github.com/OpenZWave/open-zwave/issues/1949

The other reasons are: a bit of uncertainty about sequence counter and handling of time-outs, thee need to implement a bit of state machine, and me trying to get up-to-speed with modern C++ (which is in fact C++11 as that is the minimum for OZW).

As a bonus, when this is implemented, OZW might advertise multi-cmd support as requested:

"MULTI_CMD_CLASS class is not advertized by OZW when it responds to a node info request" #1137

petergebruers commented 4 years ago

Still working on this. Doing a good "RTFM" solved a mistery and also suggests a workaround to have all reports in secure mode, without fixing S0 command class in OpenZWave.

@Fishwaldo you asked "why is it doing multi command"? We expected the device to check the NIF of the controller but I know it does not do that. Also, if it did, then the controller NIF would not advertise Multi Command CC and then the device would not use it...

RTFM:

// PAR 7 Bit 1: Enable Sending motion OFF - default = 0 no OFF! // PAR 7 Bit 2: Enable PIR super sensitivity - default is on // PAR 7 Bit 4: Bit4: Notification Type, 0: Using Notification Report. 1: Using Sensor Binary Report. - 0 = default // PAR 7 Bit 5: Disable Multi CC in auto report. (1:Disable, 0:Enable) - 0 is default

Ah, parameter 7 bit 5 defaults to using Multi Command. I checked, setting that bit disables it and then all reports

@gizmocuz I am not sure if you were testing or this was an issue you had yourself... Anyway if it annoys you, try setting parameter 7 to decimal 54, this will also enable the use of the older SensorBinary CC exposing Motion/Tamper/Door as a switch instead of an alarm:

// Example: Send motion off, use sensor binary: // bin(54) // = 0b110110

This would mean, especially in secure mode, the device is active for a longer period of time and battery life may be impacted. I have no clue how much extra drain, it is somewhat tricky to measure...

gizmocuz commented 4 years ago

Thank you for continuing working on this !! I did not test with changing parameter 7, in fact i think i did not change any parameter... ;) But I hope to test with this today. Probably i would prefer a value of 48 (0b110000) It would be great to support multi command/sequenced frames in S0 and it seems valid, and maybe other devices will do so in the feature... But if it will break anything, maybe we could adjust the help/comments for this parameter to provide two sample values that should work with OZW