Node 12:0 CC Security: wrong authentication. Packet ignored

[geirgp]

I have 2 secure devices which both seem to produce some random errors in the log:

Code: Select all

[2015-11-23 17:13:19.063] [I] [zway] Node 12:0 CC Security: Received a secure message
[2015-11-23 17:13:19.064] [W] [zway] Node 12:0 CC Security: wrong authentication. Packet ignored

See below for full log.

I have not figured out if there are any lost reports (lifeline, etc) or other information due to this error, I'm wondering if anyone knows how severe these errors are?

The devices in question are:
Fibaro Smoke Detector FGSD-002
Aeon Labs Smart Switch 5 Gen 5 EU

Note that both devices have fully completed the interviews. I have also tried factory reset of both the devices as well as the z-way-server, and z-way reinstall. multiple times.

If you take a look at the log excerpt at the bottom you will also see that Node 12 (the Aeon switch) security stuff actually seems to be working fine. Most of the received secure messages are decrypted without any errors, and there are infrequent random security errors. If i grep the log on "wrong" it seems to happen a couple of times per hour:

Code: Select all

$ tail -n 20000 -f /var/log/docker/z-way-server/z-way-server.log |grep wrong
[2015-11-23 13:00:00.868] [W] [zway] Node 12:0 CC Security: wrong authentication. Packet ignored
[2015-11-23 13:10:01.020] [W] [zway] Node 12:0 CC Security: wrong authentication. Packet ignored
[2015-11-23 13:20:49.028] [W] [zway] Node 12:0 CC Security: wrong authentication. Packet ignored
[2015-11-23 13:22:58.033] [W] [zway] Node 12:0 CC Security: wrong authentication. Packet ignored
[2015-11-23 14:40:01.229] [W] [zway] Node 12:0 CC Security: wrong authentication. Packet ignored
[2015-11-23 15:02:58.043] [W] [zway] Node 12:0 CC Security: wrong authentication. Packet ignored
[2015-11-23 15:34:34.040] [W] [zway] Node 12:0 CC Security: wrong authentication. Packet ignored
[2015-11-23 15:37:10.048] [W] [zway] Node 12:0 CC Security: wrong authentication. Packet ignored
[2015-11-23 15:43:13.061] [W] [zway] Node 12:0 CC Security: wrong authentication. Packet ignored
[2015-11-23 16:11:49.066] [W] [zway] Node 12:0 CC Security: wrong authentication. Packet ignored
[2015-11-23 16:20:01.098] [W] [zway] Node 12:0 CC Security: wrong authentication. Packet ignored
[2015-11-23 16:42:58.059] [W] [zway] Node 12:0 CC Security: wrong authentication. Packet ignored
[2015-11-23 16:46:25.064] [W] [zway] Node 12:0 CC Security: wrong authentication. Packet ignored
[2015-11-23 17:04:10.062] [W] [zway] Node 12:0 CC Security: wrong authentication. Packet ignored
[2015-11-23 17:13:19.064] [W] [zway] Node 12:0 CC Security: wrong authentication. Packet ignored
[2015-11-23 17:34:07.068] [W] [zway] Node 12:0 CC Security: wrong authentication. Packet ignored

full log, mostly successful security stuff, but one error like the on at the top - followed by a successfully decrypted packet again

Code: Select all

[2015-11-23 17:13:07.068] [I] [zway] Node 12:0 CC Security: Received a secure message
[2015-11-23 17:13:07.068] [D] [zway] SETDATA devices.12.instances.0.commandClasses.152.data.firstPart = **********
[2015-11-23 17:13:07.068] [I] [zway] Node 12:0 CC Security: passing decrypted packet to application level: [ 32 02 21 74 00 00 01 f4 00 00 00 00 00 00 ]
[2015-11-23 17:13:07.068] [D] [zway] SETDATA devices.12.instances.0.commandClasses.50.data.2.val = 0.500000
[2015-11-23 17:13:07.069] [D] [zway] SETDATA devices.12.instances.0.commandClasses.50.data.2.delta = 0 (0x00000000)
[2015-11-23 17:13:07.069] [D] [zway] SETDATA devices.12.instances.0.commandClasses.50.data.2.ratetype = 1 (0x00000001)
[2015-11-23 17:13:07.069] [D] [zway] SETDATA devices.12.instances.0.commandClasses.50.data.2.previous = 0.000000
[2015-11-23 17:13:07.069] [D] [zway] SETDATA devices.12.instances.0.commandClasses.50.data.2 = Empty
[2015-11-23 17:13:07.099] [I] [core] Notification: device-info (device-electric): {"dev":"Aeon Labs Electric (12.0.50.2) Meter","l":"0.5 W"}
[2015-11-23 17:13:10.012] [D] [zway] RECEIVED: ( 01 08 00 04 00 0C 02 98 40 25 )
[2015-11-23 17:13:10.012] [D] [zway] SENT ACK
[2015-11-23 17:13:10.012] [D] [zway] SETDATA devices.12.data.lastReceived = 0 (0x00000000)
[2015-11-23 17:13:10.013] [I] [zway] Node 12:0 CC Security: sending Nonce Report
[2015-11-23 17:13:10.040] [D] [zway] SETDATA devices.12.data.lastPacketInfo.delivered = True
[2015-11-23 17:13:10.040] [D] [zway] SETDATA devices.12.data.lastPacketInfo.packetLength = 13 (0x0000000d)
[2015-11-23 17:13:10.040] [D] [zway] SETDATA devices.12.data.lastPacketInfo.deliveryTime = 16 (0x00000010)
[2015-11-23 17:13:10.041] [D] [zway] SETDATA devices.12.data.lastPacketInfo = **********
[2015-11-23 17:13:10.041] [D] [zway] SETDATA devices.12.data.lastSend = 5374966 (0x005203f6)
[2015-11-23 17:13:10.065] [D] [zway] SETDATA devices.12.data.lastReceived = 0 (0x00000000)
[2015-11-23 17:13:10.065] [I] [zway] Node 12:0 CC Security: Received a secure message
[2015-11-23 17:13:10.065] [D] [zway] SETDATA devices.12.instances.0.commandClasses.152.data.firstPart = **********
[2015-11-23 17:13:10.065] [I] [zway] Node 12:0 CC Security: passing decrypted packet to application level: [ 32 02 21 74 00 00 00 00 00 00 00 00 00 00 ]
[2015-11-23 17:13:10.065] [D] [zway] SETDATA devices.12.instances.0.commandClasses.50.data.2.val = 0.000000
[2015-11-23 17:13:10.066] [D] [zway] SETDATA devices.12.instances.0.commandClasses.50.data.2.delta = 0 (0x00000000)
[2015-11-23 17:13:10.066] [D] [zway] SETDATA devices.12.instances.0.commandClasses.50.data.2.ratetype = 1 (0x00000001)
[2015-11-23 17:13:10.066] [D] [zway] SETDATA devices.12.instances.0.commandClasses.50.data.2.previous = 0.000000
[2015-11-23 17:13:10.066] [D] [zway] SETDATA devices.12.instances.0.commandClasses.50.data.2 = Empty
[2015-11-23 17:13:10.080] [I] [core] Notification: device-info (device-electric): {"dev":"Aeon Labs Electric (12.0.50.2) Meter","l":"0 W"}
[2015-11-23 17:13:19.012] [D] [zway] RECEIVED: ( 01 08 00 04 00 0C 02 98 40 25 )
[2015-11-23 17:13:19.012] [D] [zway] SENT ACK
[2015-11-23 17:13:19.013] [D] [zway] SETDATA devices.12.data.lastReceived = 0 (0x00000000)
[2015-11-23 17:13:19.013] [I] [zway] Node 12:0 CC Security: sending Nonce Report
[2015-11-23 17:13:19.040] [D] [zway] SETDATA devices.12.data.lastPacketInfo.delivered = True
[2015-11-23 17:13:19.040] [D] [zway] SETDATA devices.12.data.lastPacketInfo.packetLength = 13 (0x0000000d)
[2015-11-23 17:13:19.040] [D] [zway] SETDATA devices.12.data.lastPacketInfo.deliveryTime = 16 (0x00000010)
[2015-11-23 17:13:19.040] [D] [zway] SETDATA devices.12.data.lastPacketInfo = **********
[2015-11-23 17:13:19.040] [D] [zway] SETDATA devices.12.data.lastSend = 5375850 (0x0052076a)
[2015-11-23 17:13:19.063] [D] [zway] SETDATA devices.12.data.lastReceived = 0 (0x00000000)
[2015-11-23 17:13:19.063] [I] [zway] Node 12:0 CC Security: Received a secure message
[2015-11-23 17:13:19.064] [W] [zway] Node 12:0 CC Security: wrong authentication. Packet ignored
[2015-11-23 17:13:22.324] [D] [zway] SETDATA devices.12.data.lastReceived = 0 (0x00000000)
[2015-11-23 17:13:22.324] [I] [zway] Node 12:0 CC Security: sending Nonce Report
[2015-11-23 17:13:22.326] [D] [zway] SETDATA devices.12.data.lastReceived = 0 (0x00000000)
[2015-11-23 17:13:22.326] [I] [zway] Node 12:0 CC Security: sending Nonce Report
[2015-11-23 17:13:22.335] [D] [zway] SETDATA devices.12.data.lastReceived = 0 (0x00000000)
[2015-11-23 17:13:22.336] [I] [zway] Node 12:0 CC Security: sending Nonce Report
[2015-11-23 17:13:22.346] [D] [zway] SETDATA devices.12.data.lastReceived = 0 (0x00000000)
[2015-11-23 17:13:22.346] [I] [zway] Node 12:0 CC Security: sending Nonce Report
[2015-11-23 17:13:22.365] [D] [zway] SETDATA devices.12.data.lastPacketInfo.delivered = True
[2015-11-23 17:13:22.366] [D] [zway] SETDATA devices.12.data.lastPacketInfo.packetLength = 13 (0x0000000d)
[2015-11-23 17:13:22.366] [D] [zway] SETDATA devices.12.data.lastPacketInfo.deliveryTime = 9 (0x00000009)
[2015-11-23 17:13:22.366] [D] [zway] SETDATA devices.12.data.lastPacketInfo = **********
[2015-11-23 17:13:22.366] [D] [zway] SETDATA devices.12.data.lastSend = 5376178 (0x005208b2)
[2015-11-23 17:13:22.376] [D] [zway] SETDATA devices.12.data.lastReceived = 0 (0x00000000)
[2015-11-23 17:13:22.376] [I] [zway] Node 12:0 CC Security: Received a secure message
[2015-11-23 17:13:22.376] [D] [zway] SETDATA devices.12.instances.0.commandClasses.152.data.firstPart = **********
[2015-11-23 17:13:22.377] [I] [zway] Node 12:0 CC Security: passing decrypted packet to application level: [ 32 02 21 74 00 00 00 00 00 00 00 00 00 00 ]

how bad is this?

oh, by the way: z-way-2.1.2-rc17

[PoltoS]

Looks like you losot your network security key..... Looks like last log was earlier than first

[geirgp]

Looks like you losot your network security key

I find that a bit strange when there are a lot of messsages like this one:

Code: Select all

[2015-11-23 17:13:07.068] [I] [zway] Node 12:0 CC Security: Received a secure message
[2015-11-23 17:13:07.068] [D] [zway] SETDATA devices.12.instances.0.commandClasses.152.data.firstPart = **********
[2015-11-23 17:13:07.068] [I] [zway] Node 12:0 CC Security: passing decrypted packet to application level: [ 32 02 21 74 00 00 01 f4 00 00 00 00 00 00 ]

They are much more frequent than the error messages, and to me indicate that the network key must be intact - stuff is surely being decrypted.. right?

Could you please clarify how it is possible to lose the network key?

I presume the key is saved in a z-way config file somewhere, so a fresh install of z-way should have me lose the key - am I right?

In that case, yes, I have lost the key - several times actually, but also restored it (at least I believe I have): I have been playing with docker + z-way and restoring the system from a backup.

I created the backup file after the first fresh install + device inclusion with successful interviews. On subsequent installs I've used this backup file, which seems to restore all interview results & device selection. I also assumed it included the network key, is that not correct?

Looks like last log was earlier than first

not sure exactly what you mean, but on the first log i did a grep on "wrong" to illustrate how often this decrypt error occured, so that log goes back a couple of hours.

For the last log I just found one of these error messages, and copied out some log statements both before and after it. the idea was to show that it looks like packets from the same node (12) are successfully decrypted both before and after the "wrong authentication" - error.

[2015-11-23 17:13:10.065] [zway] Node 12:0 CC Security: Received a secure message
[2015-11-23 17:13:10.065] [D] [zway] SETDATA devices.12.instances.0.commandClasses.152.data.firstPart = **********
[2015-11-23 17:13:10.065] [zway] Node 12:0 CC Security: passing decrypted packet to application level: [ 32 02 21 74 00 00 00 00 00 00 00 00 00 00 ]

[PoltoS]

This part of log just means Z-Way tried to assemble the received packet and failed on decryption.

The key is stored in Z-Way files and are saved in backup. May be SD card failed at some point?

[geirgp]

This part of log just means Z-Way tried to assemble the received packet and failed on decryption.

The key is stored in Z-Way files and are saved in backup. May be SD card failed at some point?

That could be the issue, it was the only thing I didn't reinstall. I wiped the SD card everything seems to be in order now.