Page 1 of 1

Security interview works?

Posted: 04 Jan 2016 21:10
by bogr
I've got problems with interview in security mode. Is it suppose to work for v2.1.1? Looking at release notes for 2.2.0 it looks like some fixes has been done for this version? I'm using an Aeon Multisensor 6 (gen 5).

The log looks like:

Code: Select all

[2016-01-04 18:52:36.664] [I] [zway] Adding job: Add/re-include node to network
[2016-01-04 18:52:36.673] [D] [zway] SENDING (cb 0x07): ( 01 05 00 4A C1 07 76 )
[2016-01-04 18:52:36.675] [D] [zway] RECEIVED ACK
[2016-01-04 18:52:36.684] [D] [zway] RECEIVED: ( 01 07 00 4A 07 01 00 00 B4 )
[2016-01-04 18:52:36.684] [D] [zway] SENT ACK
[2016-01-04 18:52:36.684] [D] [zway] SETDATA controller.data.lastIncludedDevice = Empty
[2016-01-04 18:52:36.685] [D] [zway] SETDATA controller.data.lastExcludedDevice = Empty
[2016-01-04 18:52:36.685] [I] [zway] Job 0x4a (Add/re-include node to network): Ready to add - push button on the device to be added
[2016-01-04 18:52:36.685] [D] [zway] SETDATA controller.data.controllerState = 1 (0x00000001)
[2016-01-04 18:52:38.738] [D] [zway] RECEIVED: ( 01 07 00 4A 07 02 00 00 B7 )
[2016-01-04 18:52:38.739] [D] [zway] SENT ACK
[2016-01-04 18:52:38.740] [I] [zway] Job 0x4a (Add/re-include node to network): Node found: #0
[2016-01-04 18:52:38.740] [D] [zway] SETDATA controller.data.controllerState = 2 (0x00000002)
[2016-01-04 18:52:38.930] [D] [zway] RECEIVED: ( 01 1A 00 4A 07 03 09 13 04 21 01 5E 86 72 59 85 73 71 84 80 30 31 70 98 7A EF 5A C3 )
[2016-01-04 18:52:38.931] [D] [zway] SENT ACK
[2016-01-04 18:52:38.932] [I] [zway] Job 0x4a (Add/re-include node to network): Adding slave: #9
[2016-01-04 18:52:38.932] [D] [zway] SETDATA controller.data.controllerState = 3 (0x00000003)
[2016-01-04 18:52:38.933] [D] [zway] SETDATA controller.data.lastIncludedDevice = 9 (0x00000009)
[2016-01-04 18:52:38.933] [D] [zway] SETDATA devices.9.data = Empty
[2016-01-04 18:52:38.934] [D] [zway] SETDATA devices.9.instances.0.data = Empty
[2016-01-04 18:52:38.934] [D] [zway] SETDATA devices.9.instances.0.data.dynamic = Empty
[2016-01-04 18:52:38.934] [D] [zway] SETDATA devices.9.instances.0.data.dynamic = False
[2016-01-04 18:52:38.935] [D] [zway] SETDATA devices.9.instances.0.data.genericType = Empty
[2016-01-04 18:52:38.935] [D] [zway] SETDATA devices.9.instances.0.data.genericType = 0 (0x00000000)
[2016-01-04 18:52:38.936] [D] [zway] SETDATA devices.9.instances.0.data.specificType = Empty
[2016-01-04 18:52:38.936] [D] [zway] SETDATA devices.9.instances.0.data.specificType = 0 (0x00000000)
[2016-01-04 18:52:38.936] [D] [zway] SETDATA devices.9.data.basicType = Empty
[2016-01-04 18:52:38.937] [D] [zway] SETDATA devices.9.data.genericType = Empty
[2016-01-04 18:52:38.937] [D] [zway] SETDATA devices.9.data.specificType = Empty
[2016-01-04 18:52:38.937] [D] [zway] SETDATA devices.9.data.infoProtocolSpecific = Empty
[2016-01-04 18:52:38.938] [D] [zway] SETDATA devices.9.data.deviceTypeString = Empty
[2016-01-04 18:52:38.938] [D] [zway] SETDATA devices.9.data.isVirtual = Empty
[2016-01-04 18:52:38.939] [D] [zway] SETDATA devices.9.data.isListening = Empty
[2016-01-04 18:52:38.939] [D] [zway] SETDATA devices.9.data.isRouting = Empty
[2016-01-04 18:52:38.939] [D] [zway] SETDATA devices.9.data.isAwake = Empty
[2016-01-04 18:52:38.940] [D] [zway] SETDATA devices.9.data.optional = Empty
[2016-01-04 18:52:38.940] [D] [zway] SETDATA devices.9.data.isFailed = Empty
[2016-01-04 18:52:38.940] [D] [zway] SETDATA devices.9.data.beam = Empty
[2016-01-04 18:52:38.941] [D] [zway] SETDATA devices.9.data.sensor250 = Empty
[2016-01-04 18:52:38.941] [D] [zway] SETDATA devices.9.data.sensor1000 = Empty
[2016-01-04 18:52:38.941] [D] [zway] SETDATA devices.9.data.neighbours = Empty
[2016-01-04 18:52:38.942] [D] [zway] SETDATA devices.9.data.manufacturerId = Empty
[2016-01-04 18:52:38.942] [D] [zway] SETDATA devices.9.data.vendorString = Empty
[2016-01-04 18:52:38.943] [D] [zway] SETDATA devices.9.data.manufacturerProductType = Empty
[2016-01-04 18:52:38.943] [D] [zway] SETDATA devices.9.data.manufacturerProductId = Empty
[2016-01-04 18:52:38.943] [D] [zway] SETDATA devices.9.data.ZWLib = Empty
[2016-01-04 18:52:38.944] [D] [zway] SETDATA devices.9.data.ZWProtocolMajor = Empty
[2016-01-04 18:52:38.944] [D] [zway] SETDATA devices.9.data.ZWProtocolMinor = Empty
[2016-01-04 18:52:38.944] [D] [zway] SETDATA devices.9.data.SDK = Empty
[2016-01-04 18:52:38.945] [D] [zway] SETDATA devices.9.data.applicationMajor = Empty
[2016-01-04 18:52:38.945] [D] [zway] SETDATA devices.9.data.applicationMinor = Empty
[2016-01-04 18:52:38.945] [D] [zway] SETDATA devices.9.data.nodeInfoFrame = Empty
[2016-01-04 18:52:38.946] [D] [zway] SETDATA devices.9.data.ZDDXMLFile = Empty
[2016-01-04 18:52:38.946] [D] [zway] SETDATA devices.9.data.lastSend = Empty
[2016-01-04 18:52:38.946] [D] [zway] SETDATA devices.9.data.lastNonceGet = Empty
[2016-01-04 18:52:38.947] [D] [zway] SETDATA devices.9.data.lastReceived = Empty
[2016-01-04 18:52:38.947] [D] [zway] SETDATA devices.9.data.failureCount = Empty
[2016-01-04 18:52:38.947] [D] [zway] SETDATA devices.9.data.keepAwake = Empty
[2016-01-04 18:52:38.948] [D] [zway] SETDATA devices.9.data.countSuccess = Empty
[2016-01-04 18:52:38.948] [D] [zway] SETDATA devices.9.data.countFailed = Empty
[2016-01-04 18:52:38.949] [D] [zway] SETDATA devices.9.data.queueLength = Empty
[2016-01-04 18:52:38.949] [D] [zway] SETDATA devices.9.data.givenName = Empty
[2016-01-04 18:52:38.949] [D] [zway] SETDATA devices.9.data.lastPacketInfo = Empty
[2016-01-04 18:52:38.950] [D] [zway] SETDATA devices.9.data.lastPacketInfo.deliveryTime = Empty
[2016-01-04 18:52:38.950] [D] [zway] SETDATA devices.9.data.lastPacketInfo.delivered = Empty
[2016-01-04 18:52:38.950] [D] [zway] SETDATA devices.9.data.lastPacketInfo.packetLength = Empty
[2016-01-04 18:52:38.951] [D] [zway] SETDATA devices.9.data.basicType = 0 (0x00000000)
[2016-01-04 18:52:38.951] [D] [zway] SETDATA devices.9.data.genericType = 0 (0x00000000)
[2016-01-04 18:52:38.951] [D] [zway] SETDATA devices.9.data.specificType = 0 (0x00000000)
[2016-01-04 18:52:38.952] [D] [zway] SETDATA devices.9.data.infoProtocolSpecific = 0 (0x00000000)
[2016-01-04 18:52:38.952] [D] [zway] SETDATA devices.9.data.deviceTypeString = ""
[2016-01-04 18:52:38.952] [D] [zway] SETDATA devices.9.data.isVirtual = False
[2016-01-04 18:52:38.953] [D] [zway] SETDATA devices.9.data.isListening = True
[2016-01-04 18:52:38.953] [D] [zway] SETDATA devices.9.data.isRouting = False
[2016-01-04 18:52:38.953] [D] [zway] SETDATA devices.9.data.isAwake = False
[2016-01-04 18:52:38.954] [D] [zway] SETDATA devices.9.data.optional = False
[2016-01-04 18:52:38.954] [D] [zway] SETDATA devices.9.data.isFailed = False
[2016-01-04 18:52:38.954] [D] [zway] SETDATA devices.9.data.beam = False
[2016-01-04 18:52:38.955] [D] [zway] SETDATA devices.9.data.sensor250 = False
[2016-01-04 18:52:38.955] [D] [zway] SETDATA devices.9.data.sensor1000 = False
[2016-01-04 18:52:38.955] [D] [zway] SETDATA devices.9.data.neighbours = Empty
[2016-01-04 18:52:38.956] [D] [zway] SETDATA devices.9.data.manufacturerId = 0 (0x00000000)
[2016-01-04 18:52:38.956] [D] [zway] SETDATA devices.9.data.manufacturerProductType = 0 (0x00000000)
[2016-01-04 18:52:38.956] [D] [zway] SETDATA devices.9.data.manufacturerProductId = 0 (0x00000000)
[2016-01-04 18:52:38.957] [D] [zway] SETDATA devices.9.data.applicationMajor = 0 (0x00000000)
[2016-01-04 18:52:38.957] [D] [zway] SETDATA devices.9.data.applicationMinor = 0 (0x00000000)
[2016-01-04 18:52:38.957] [D] [zway] SETDATA devices.9.data.ZWProtocolMajor = 0 (0x00000000)
[2016-01-04 18:52:38.958] [D] [zway] SETDATA devices.9.data.ZWProtocolMinor = 0 (0x00000000)
[2016-01-04 18:52:38.958] [D] [zway] SETDATA devices.9.data.ZWLib = 0 (0x00000000)
[2016-01-04 18:52:38.958] [D] [zway] SETDATA devices.9.data.SDK = ""
[2016-01-04 18:52:38.959] [D] [zway] SETDATA devices.9.data.vendorString = ""
[2016-01-04 18:52:38.959] [D] [zway] SETDATA devices.9.data.nodeInfoFrame = Empty
[2016-01-04 18:52:38.960] [D] [zway] SETDATA devices.9.data.ZDDXMLFile = ""
[2016-01-04 18:52:38.960] [D] [zway] SETDATA devices.9.data.keepAwake = False
[2016-01-04 18:52:38.960] [D] [zway] SETDATA devices.9.data.countSuccess = 0 (0x00000000)
[2016-01-04 18:52:38.961] [D] [zway] SETDATA devices.9.data.countFailed = 0 (0x00000000)
[2016-01-04 18:52:38.961] [D] [zway] SETDATA devices.9.data.queueLength = 0 (0x00000000)
[2016-01-04 18:52:38.961] [D] [zway] SETDATA devices.9.data.lastReceived = 0 (0x00000000)
[2016-01-04 18:52:38.962] [D] [zway] SETDATA devices.9.data.lastSend = 0 (0x00000000)
[2016-01-04 18:52:38.962] [D] [zway] SETDATA devices.9.data.failureCount = 0 (0x00000000)
[2016-01-04 18:52:38.962] [D] [zway] SETDATA devices.9.data.givenName = ""
[2016-01-04 18:52:38.963] [I] [zway] Adding job: Get node protocol information
[2016-01-04 18:52:38.963] [I] [zway] Adding job: Get routing table line
[2016-01-04 18:52:38.963] [I] [zway] Adding job: Check if node is failed
[2016-01-04 18:52:38.964] [I] [zway] Adding job: Get routing table line
[2016-01-04 18:52:38.964] [D] [zway] Job 0x80 (Get routing table line): removing duplicate
[2016-01-04 18:52:38.964] [D] [zway] SETDATA devices.9.data.basicType = 4 (0x00000004)
[2016-01-04 18:52:38.965] [D] [zway] SETDATA devices.9.data.genericType = 33 (0x00000021)
[2016-01-04 18:52:38.965] [D] [zway] SETDATA devices.9.instances.0.data.genericType = 33 (0x00000021)
[2016-01-04 18:52:38.966] [D] [zway] SETDATA devices.9.data.specificType = 1 (0x00000001)
[2016-01-04 18:52:38.966] [D] [zway] SETDATA devices.9.instances.0.data.specificType = 1 (0x00000001)
[2016-01-04 18:52:38.968] [D] [zway] SETDATA devices.9.data.deviceTypeString = "Routing Multilevel Sensor"
[2016-01-04 18:52:38.969] [D] [zway] SETDATA devices.9.data.nodeInfoFrame = byte[16]
[2016-01-04 18:52:38.971] [D] [zway]   ( 5E 86 72 59 85 73 71 84 80 30 31 70 98 7A EF 5A )
[2016-01-04 18:52:38.979] [D] [zway] SENDING: ( 01 04 00 62 09 90 )
[2016-01-04 18:52:38.981] [D] [zway] RECEIVED ACK
[2016-01-04 18:52:38.982] [D] [zway] RECEIVED: ( 01 04 01 62 00 98 )
[2016-01-04 18:52:38.982] [D] [zway] SENT ACK
[2016-01-04 18:52:38.983] [D] [zway] SETDATA devices.9.data.isFailed = False
[2016-01-04 18:52:38.983] [I] [zway] Job 0x62 (Check if node is failed): Node 9 is operating
[2016-01-04 18:52:38.984] [D] [zway] Job 0x62 (Check if node is failed): success
[2016-01-04 18:52:38.984] [I] [zway] Removing job: Check if node is failed
[2016-01-04 18:52:39.264] [D] [zway] RECEIVED: ( 01 07 00 4A 07 05 09 00 B9 )
[2016-01-04 18:52:39.265] [D] [zway] SENT ACK
[2016-01-04 18:52:39.265] [D] [zway] SETDATA controller.data.controllerState = 4 (0x00000004)
[2016-01-04 18:52:39.266] [I] [zway] Job 0x4a (Add/re-include node to network): Protocol done
[2016-01-04 18:52:39.266] [I] [zway] Loading Command Classes for device 9
[2016-01-04 18:52:39.267] [I] [zway] Node 9:0 supports CC Basic
[2016-01-04 18:52:39.267] [D] [zway] SETDATA devices.9.instances.0.commandClasses.32.data = Empty
[2016-01-04 18:52:39.268] [D] [zway] SETDATA devices.9.instances.0.commandClasses.32.data.supported = Empty
[2016-01-04 18:52:39.268] [D] [zway] SETDATA devices.9.instances.0.commandClasses.32.data.supported = True
[2016-01-04 18:52:39.269] [D] [zway] SETDATA devices.9.instances.0.commandClasses.32.data.version = Empty
[2016-01-04 18:52:39.269] [D] [zway] SETDATA devices.9.instances.0.commandClasses.32.data.version = 1 (0x00000001)
[2016-01-04 18:52:39.270] [D] [zway] SETDATA devices.9.instances.0.commandClasses.32.data.security = Empty
[2016-01-04 18:52:39.270] [D] [zway] SETDATA devices.9.instances.0.commandClasses.32.data.security = False
[2016-01-04 18:52:39.270] [D] [zway] SETDATA devices.9.instances.0.commandClasses.32.data.interviewDone = Empty
[2016-01-04 18:52:39.271] [D] [zway] SETDATA devices.9.instances.0.commandClasses.32.data.interviewCounter = Empty
[2016-01-04 18:52:39.271] [D] [zway] SETDATA devices.9.instances.0.commandClasses.32.data.interviewDone = False
[2016-01-04 18:52:39.271] [D] [zway] SETDATA devices.9.instances.0.commandClasses.32.data.interviewCounter = 10 (0x0000000a)
[2016-01-04 18:52:39.272] [D] [zway] SETDATA devices.9.instances.0.commandClasses.32.data.level = Empty
[2016-01-04 18:52:39.272] [I] [zway] Node 9:0 supports CC SensorBinary
[2016-01-04 18:52:39.272] [D] [zway] SETDATA devices.9.instances.0.commandClasses.48.data = Empty
[2016-01-04 18:52:39.273] [D] [zway] SETDATA devices.9.instances.0.commandClasses.48.data.supported = Empty
[2016-01-04 18:52:39.273] [D] [zway] SETDATA devices.9.instances.0.commandClasses.48.data.supported = True
[2016-01-04 18:52:39.276] [D] [zway] SETDATA devices.9.instances.0.commandClasses.48.data.version = Empty
[2016-01-04 18:52:39.277] [D] [zway] SETDATA devices.9.instances.0.commandClasses.48.data.version = 1 (0x00000001)
[2016-01-04 18:52:39.277] [D] [zway] SETDATA devices.9.instances.0.commandClasses.48.data.security = Empty
[2016-01-04 18:52:39.278] [D] [zway] SETDATA devices.9.instances.0.commandClasses.48.data.security = False
[2016-01-04 18:52:39.278] [D] [zway] SETDATA devices.9.instances.0.commandClasses.48.data.interviewDone = Empty
[2016-01-04 18:52:39.278] [D] [zway] SETDATA devices.9.instances.0.commandClasses.48.data.interviewCounter = Empty
[2016-01-04 18:52:39.279] [D] [zway] SETDATA devices.9.instances.0.commandClasses.48.data.interviewDone = False
[2016-01-04 18:52:39.279] [D] [zway] SETDATA devices.9.instances.0.commandClasses.48.data.interviewCounter = 10 (0x0000000a)
[2016-01-04 18:52:39.280] [D] [zway] SETDATA devices.9.instances.0.commandClasses.48.data.typemask = Empty
[2016-01-04 18:52:39.280] [I] [zway] Node 9:0 supports CC SensorMultilevel
[2016-01-04 18:52:39.281] [D] [zway] SETDATA devices.9.instances.0.commandClasses.49.data = Empty
[2016-01-04 18:52:39.281] [D] [zway] SETDATA devices.9.instances.0.commandClasses.49.data.supported = Empty
[2016-01-04 18:52:39.281] [D] [zway] SETDATA devices.9.instances.0.commandClasses.49.data.supported = True
[2016-01-04 18:52:39.282] [D] [zway] SETDATA devices.9.instances.0.commandClasses.49.data.version = Empty
[2016-01-04 18:52:39.282] [D] [zway] SETDATA devices.9.instances.0.commandClasses.49.data.version = 1 (0x00000001)
[2016-01-04 18:52:39.282] [D] [zway] SETDATA devices.9.instances.0.commandClasses.49.data.security = Empty
[2016-01-04 18:52:39.283] [D] [zway] SETDATA devices.9.instances.0.commandClasses.49.data.security = False
[2016-01-04 18:52:39.283] [D] [zway] SETDATA devices.9.instances.0.commandClasses.49.data.interviewDone = Empty
[2016-01-04 18:52:39.283] [D] [zway] SETDATA devices.9.instances.0.commandClasses.49.data.interviewCounter = Empty
[2016-01-04 18:52:39.284] [D] [zway] SETDATA devices.9.instances.0.commandClasses.49.data.interviewDone = False
[2016-01-04 18:52:39.284] [D] [zway] SETDATA devices.9.instances.0.commandClasses.49.data.interviewCounter = 10 (0x0000000a)
[2016-01-04 18:52:39.284] [D] [zway] SETDATA devices.9.instances.0.commandClasses.49.data.typemask = Empty
[2016-01-04 18:52:39.285] [I] [zway] Node 9:0 supports CC AssociationGroupInformation
[2016-01-04 18:52:39.285] [D] [zway] SETDATA devices.9.instances.0.commandClasses.89.data = Empty
[2016-01-04 18:52:39.286] [D] [zway] SETDATA devices.9.instances.0.commandClasses.89.data.supported = Empty
[2016-01-04 18:52:39.286] [D] [zway] SETDATA devices.9.instances.0.commandClasses.89.data.supported = True
[2016-01-04 18:52:39.286] [D] [zway] SETDATA devices.9.instances.0.commandClasses.89.data.version = Empty
[2016-01-04 18:52:39.287] [D] [zway] SETDATA devices.9.instances.0.commandClasses.89.data.version = 1 (0x00000001)
[2016-01-04 18:52:39.287] [D] [zway] SETDATA devices.9.instances.0.commandClasses.89.data.security = Empty
[2016-01-04 18:52:39.287] [D] [zway] SETDATA devices.9.instances.0.commandClasses.89.data.security = False
[2016-01-04 18:52:39.288] [D] [zway] SETDATA devices.9.instances.0.commandClasses.89.data.interviewDone = Empty
[2016-01-04 18:52:39.288] [D] [zway] SETDATA devices.9.instances.0.commandClasses.89.data.interviewCounter = Empty
[2016-01-04 18:52:39.288] [D] [zway] SETDATA devices.9.instances.0.commandClasses.89.data.interviewDone = False
[2016-01-04 18:52:39.289] [D] [zway] SETDATA devices.9.instances.0.commandClasses.89.data.interviewCounter = 10 (0x0000000a)
[2016-01-04 18:52:39.289] [D] [zway] SETDATA devices.9.instances.0.commandClasses.89.data.dynamic = Empty
[2016-01-04 18:52:39.289] [I] [zway] Node 9:0 supports CC ZWavePlusInfo
[2016-01-04 18:52:39.290] [D] [zway] SETDATA devices.9.instances.0.commandClasses.94.data = Empty
[2016-01-04 18:52:39.290] [D] [zway] SETDATA devices.9.instances.0.commandClasses.94.data.supported = Empty

[snip]..

[2016-01-04 18:52:39.502] [I] [zway] Node 9:0 CC Security: sending Network Key Set
[2016-01-04 18:52:39.502] [I] [zway] Adding job: Network Key Set
[2016-01-04 18:52:39.502] [I] [zway] Node 9:0 CC Security: sending Nonce Get
[2016-01-04 18:52:39.503] [D] [zway] SETDATA devices.9.instances.0.commandClasses.152.data.rNonceAckWait = **********
[2016-01-04 18:52:39.503] [I] [zway] Adding job: Nonce Get
[2016-01-04 18:52:39.503] [D] [zway] SETDATA devices.9.data.lastNonceGet = 7217517 (0x006e216d)
[2016-01-04 18:52:39.561] [D] [zway] SENDING (cb 0x09): ( 01 09 00 13 09 02 98 40 05 09 3A )
[2016-01-04 18:52:39.563] [D] [zway] RECEIVED ACK
[2016-01-04 18:52:39.567] [D] [zway] RECEIVED: ( 01 04 01 13 01 E8 )
[2016-01-04 18:52:39.567] [D] [zway] SENT ACK
[2016-01-04 18:52:39.567] [D] [zway] Delivered to Z-Wave stack
[2016-01-04 18:52:39.582] [D] [zway] RECEIVED: ( 01 07 00 13 09 00 00 02 E0 )
[2016-01-04 18:52:39.583] [D] [zway] SENT ACK
[2016-01-04 18:52:39.583] [I] [zway] Job 0x13 (Nonce Get): Delivered
[2016-01-04 18:52:39.584] [D] [zway] SETDATA devices.9.data.lastPacketInfo.delivered = True
[2016-01-04 18:52:39.584] [D] [zway] SETDATA devices.9.data.lastPacketInfo.packetLength = 5 (0x00000005)
[2016-01-04 18:52:39.584] [D] [zway] SETDATA devices.9.data.lastPacketInfo.deliveryTime = 15 (0x0000000f)
[2016-01-04 18:52:39.585] [D] [zway] SETDATA devices.9.data.lastPacketInfo = **********
[2016-01-04 18:52:39.585] [D] [zway] SendData Response with callback 0x09 received: received by recipient
[2016-01-04 18:52:39.585] [D] [zway] SETDATA devices.9.data.lastSend = 7217525 (0x006e2175)
[2016-01-04 18:52:39.586] [D] [zway] Job 0x13 (Nonce Get): success
[2016-01-04 18:52:39.586] [D] [zway] SETDATA devices.9.instances.0.commandClasses.152.data.rNonceAckWait = **********
[2016-01-04 18:52:39.586] [I] [zway] Removing job: Nonce Get
[2016-01-04 18:52:39.602] [D] [zway] RECEIVED: ( 01 10 00 04 00 09 0A 98 80 D4 D4 D2 40 7E 67 9B 91 71 )
[2016-01-04 18:52:39.603] [D] [zway] SENT ACK
[2016-01-04 18:52:39.604] [D] [zway] SETDATA devices.9.data.lastReceived = 0 (0x00000000)
[2016-01-04 18:52:39.604] [I] [zway] Node 9:0 CC Security: received Nonce Report
[2016-01-04 18:52:39.604] [D] [zway] SETDATA devices.9.instances.0.commandClasses.152.data.rNonce = **********
[2016-01-04 18:52:39.605] [I] [zway] Removing job: Network Key Set
[2016-01-04 18:52:39.605] [I] [zway] Node 9:0 CC Security: Sending a secure message
[2016-01-04 18:52:39.605] [I] [zway] Node 9:0 CC Security: sending encrypted packet: Network Key Set
[2016-01-04 18:52:39.606] [D] [zway] SETDATA devices.9.instances.0.commandClasses.152.data.toFollow = False
[2016-01-04 18:52:39.606] [D] [zway] SETDATA devices.9.data.lastNonceGet = Empty
[2016-01-04 18:52:39.606] [I] [zway] Adding job: Security, Network Key Set
[2016-01-04 18:52:39.652] [D] [zway] SENDING (cb 0x0a): ( 01 2D 00 13 09 26 98 81 7C F5 FC 31 8E 41 1C 2E 6C B6 ED 8C C4 0A 25 6E BC DF 84 6A 33 3D 7C 5A 7A 31 EC D4 9E AA DA 37 95 47 E4 8C 05 0A CA )
[2016-01-04 18:52:39.657] [D] [zway] RECEIVED ACK
[2016-01-04 18:52:39.662] [D] [zway] RECEIVED: ( 01 04 01 13 01 E8 )
[2016-01-04 18:52:39.662] [D] [zway] SENT ACK
[2016-01-04 18:52:39.662] [I] [zway] Job 0x13 (Security, Network Key Set): Response received - transfered to encapsulated jobs
[2016-01-04 18:52:39.663] [D] [zway] Delivered to Z-Wave stack
[2016-01-04 18:52:39.663] [D] [zway] Delivered to Z-Wave stack
[2016-01-04 18:52:39.683] [D] [zway] RECEIVED: ( 01 07 00 13 0A 00 00 02 E3 )
[2016-01-04 18:52:39.683] [D] [zway] SENT ACK
[2016-01-04 18:52:39.684] [I] [zway] Job 0x13 (Security, Network Key Set): Callback received - transfered to encapsulated jobs
[2016-01-04 18:52:39.684] [I] [zway] Job 0x13 (Network Key Set): Delivered
[2016-01-04 18:52:39.684] [D] [zway] SendData Response with callback 0x0a received: received by recipient
[2016-01-04 18:52:39.684] [I] [zway] Job 0x13 (Security, Network Key Set): Delivered
[2016-01-04 18:52:39.685] [D] [zway] SETDATA devices.9.data.lastPacketInfo.delivered = True
[2016-01-04 18:52:39.685] [D] [zway] SETDATA devices.9.data.lastPacketInfo.packetLength = 41 (0x00000029)
[2016-01-04 18:52:39.685] [D] [zway] SETDATA devices.9.data.lastPacketInfo.deliveryTime = 21 (0x00000015)
[2016-01-04 18:52:39.685] [D] [zway] SETDATA devices.9.data.lastPacketInfo = **********
[2016-01-04 18:52:39.686] [D] [zway] SendData Response with callback 0x0a received: received by recipient
[2016-01-04 18:52:39.686] [D] [zway] SETDATA devices.9.data.lastSend = 7217535 (0x006e217f)
[2016-01-04 18:52:39.686] [D] [zway] Job 0x13 (Security, Network Key Set): success
[2016-01-04 18:52:39.686] [I] [zway] Removing job: Security, Network Key Set
[2016-01-04 18:52:39.713] [D] [zway] RECEIVED: ( 01 08 00 04 00 09 02 98 40 20 )
[2016-01-04 18:52:39.713] [D] [zway] SENT ACK
[2016-01-04 18:52:39.714] [D] [zway] SETDATA devices.9.data.lastReceived = 0 (0x00000000)
...
What should I look for in the logs to get any hints about errors? There are no explicit errors. Interview status is "Device interview stage is not complete".

Job queue says:

Code: Select all

n	U	W	S	E	D 	Ack	Resp	Cbk	Timeout 	NodeId	Description	Progress	Buffer
0		W	S			-	-	-	0.20	9	SensorMultilevel V5 Get		9 4 31 4 1b 0 5
0		W	S			-	-	-	0.20	9	Wakeup interval set		9 6 84 4 0 1 2c 1 5
0		W	S			-	-	-	0.20	9	Wakeup Get		9 2 84 5 5
1		W				-	-	-	0.20	9	Nonce Get	Not delivered to recipient	9 2 98 40 5
0			S			-	-	-	0.20	9	SensorBinary Get		9 2 30 2 5
0			S			-	-	-	0.20	9	Alarm Get (v3)		9 5 71 4 0 7 0 5
0			S			-	-	-	0.20	9	SensorMultilevel V5 Get		9 4 31 4 1 0 5
0			S			-	-	-	0.20	9	SensorMultilevel V5 Get		9 4 31 4 3 8 5
0			S			-	-	-	0.20	9	SensorMultilevel V5 Get		9 4 31 4 5 0 5
0			S			-	-	-	0.20	9	SensorMultilevel V5 Get		9 4 31 4 1b 0 5 

Re: Security interview works?

Posted: 05 Jan 2016 02:25
by bogr
Hmmm, just in case somebody else has the same problems, I managed to solve this. Checking the "View Interview Result" I saw that "AssociationGroupInformation" and "Alarm" CommandClasses did not finish the interview. So, I "just" pressed the "force interview"-button for those and suddenly everything works :twisted: .

It would, though, be nice to get an explanation for this behaviour, and if I should expect some other issues regarding secure mode?

Re: Security interview works?

Posted: 10 Jan 2016 13:45
by jet11x
I often find interviews don't complete and forcing doesn't always help. Interested to see free to Job queue above, I see there is web page for Expert UI that I didn't realise existed at <your-pi>/expert/#/network/queue

Re: Security interview works?

Posted: 12 Jan 2016 04:53
by Plainsane
I have never had a device interview successfully and always have to. Do what you did here.

Re: Security interview works?

Posted: 12 Jan 2016 22:22
by bogr
Yes, that's my experience too, _but_ only in security mode. Even if I have the device sitting on top of the pi, so the distance can't be an issue. Otherwise it works great.