Hank interview not finishing

[bogr]

I have a Hank Scene Controller HKZW-SCN04, which is stuck at 93% interview. It's the AssociationGroupInformation that does not finish, even if trying to "Force Interview" for that specific CommandClass. The log looks like:

Code: Select all

[2020-12-04 17:55:25.940] [I] [zway] Using security scheme S0
[2020-12-04 17:55:25.941] [I] [zway] Adding job: AssociationGroupInformation Info Get
[2020-12-04 17:55:25.941] [I] [zway] Using security scheme S0
[2020-12-04 17:55:25.941] [I] [zway] Adding job: AssociationGroupInformation Name Get
[2020-12-04 17:55:25.941] [I] [zway] Using security scheme S0
[2020-12-04 17:55:25.942] [I] [zway] Adding job: AssociationGroupInformation Name Get
[2020-12-04 17:55:25.942] [I] [zway] Using security scheme S0
[2020-12-04 17:55:25.942] [I] [zway] Adding job: AssociationGroupInformation Name Get
[2020-12-04 17:55:25.942] [I] [zway] Using security scheme S0
[2020-12-04 17:55:25.942] [I] [zway] Adding job: AssociationGroupInformation Name Get
[2020-12-04 17:55:25.943] [I] [zway] Using security scheme S0
[2020-12-04 17:55:25.943] [I] [zway] Adding job: AssociationGroupInformation Name Get
[2020-12-04 17:55:25.943] [I] [zway] Using security scheme S0
[2020-12-04 17:55:25.944] [I] [zway] Adding job: AssociationGroupInformation Name Get
[2020-12-04 17:55:25.944] [I] [zway] Using security scheme S0
[2020-12-04 17:55:25.944] [I] [zway] Adding job: AssociationGroupInformation Name Get
[2020-12-04 17:55:25.945] [I] [zway] Using security scheme S0
[2020-12-04 17:55:25.945] [I] [zway] Adding job: AssociationGroupInformation Name Get
[2020-12-04 17:55:25.945] [I] [zway] Using security scheme S0 
[2020-12-04 17:55:25.945] [I] [zway] Adding job: AssociationGroupInformation Name Get
[2020-12-04 17:55:25.946] [I] [zway] Using security scheme S0
[2020-12-04 17:55:25.946] [I] [zway] Adding job: AssociationGroupInformation Commands Get
[2020-12-04 17:55:25.946] [I] [zway] Using security scheme S0
[2020-12-04 17:55:25.946] [I] [zway] Adding job: AssociationGroupInformation Commands Get
[2020-12-04 17:55:25.946] [I] [zway] Using security scheme S0
[2020-12-04 17:55:25.947] [I] [zway] Adding job: AssociationGroupInformation Commands Get
[2020-12-04 17:55:25.947] [I] [zway] Using security scheme S0
[2020-12-04 17:55:25.947] [I] [zway] Adding job: AssociationGroupInformation Commands Get
[2020-12-04 17:55:25.947] [I] [zway] Using security scheme S0
[2020-12-04 17:55:25.948] [I] [zway] Adding job: AssociationGroupInformation Commands Get
[2020-12-04 17:55:25.948] [I] [zway] Using security scheme S0
[2020-12-04 17:55:25.948] [I] [zway] Adding job: AssociationGroupInformation Commands Get
[2020-12-04 17:55:25.948] [I] [zway] Using security scheme S0
[2020-12-04 17:55:25.948] [I] [zway] Adding job: AssociationGroupInformation Commands Get
[2020-12-04 17:55:25.949] [I] [zway] Using security scheme S0
[2020-12-04 17:55:25.949] [I] [zway] Adding job: AssociationGroupInformation Commands Get
[2020-12-04 17:55:25.949] [I] [zway] Using security scheme S0
[2020-12-04 17:55:25.949] [I] [zway] Adding job: AssociationGroupInformation Commands Get
[2020-12-04 17:55:25.950] [I] [zway] Node 55:0 CC Security: sending Nonce Get
[2020-12-04 17:55:25.950] [D] [zway] SETDATA devices.55.instances.0.commandClasses.152.data.rNonceAckWait = **********
[2020-12-04 17:55:25.950] [I] [zway] Adding job: Nonce Get
[2020-12-04 17:55:25.950] [D] [zway] SETDATA devices.55.data.lastNonceGet = 62984 (0x0000f608)
[2020-12-04 17:55:25.961] [D] [zway] SENDING (cb 0x34): ( 01 09 00 13 37 02 98 40 05 34 39 )
[2020-12-04 17:55:25.963] [D] [zway] RECEIVED ACK
[2020-12-04 17:55:25.966] [D] [zway] RECEIVED: ( 01 04 01 13 01 E8 )
[2020-12-04 17:55:25.966] [D] [zway] SENT ACK
[2020-12-04 17:55:25.967] [D] [zway] Delivered to Z-Wave stack
[2020-12-04 17:55:26.874] [D] [zway] Job 0x3b: deleted from queue
[2020-12-04 17:55:29.250] [D] [zway] RECEIVED: ( 01 18 00 13 34 01 01 49 00 7F 7F 7F 7F 7F 00 01 06 00 00 00 00 02 12 35 37 E3 )
[2020-12-04 17:55:29.251] [D] [zway] SENT ACK
[2020-12-04 17:55:29.251] [I] [zway] Job 0x13 (Nonce Get): Not delivered to recipient
[2020-12-04 17:55:29.252] [D] [zway] SETDATA devices.55.data.isAwake = False
[2020-12-04 17:55:29.253] [D] [zway] Sending the queue for node 55 into sleep
[2020-12-04 17:55:34.006] [D] [zway] RECEIVED: ( 01 0A 00 04 00 37 02 98 40 C1 00 DD )
[2020-12-04 17:55:34.007] [D] [zway] SENT ACK
[2020-12-04 17:55:34.007] [D] [zway] SETDATA devices.55.data.lastReceived = 0 (0x00000000)
[2020-12-04 17:55:34.008] [I] [zway] Node 55:0 CC Security: sending Nonce Report
[2020-12-04 17:55:34.008] [D] [zway] SETDATA devices.55.data.isAwake = True
[2020-12-04 17:55:34.009] [I] [zway] Adding job: Nonce Report
[2020-12-04 17:55:34.009] [D] [zway] SENDING (cb 0x35): ( 01 11 00 13 37 0A 98 80 72 89 57 74 9F EF C5 0B 05 35 8E )
[2020-12-04 17:55:34.020] [D] [zway] RECEIVED ACK
[2020-12-04 17:55:34.021] [D] [zway] RECEIVED: ( 01 04 01 13 01 E8 )
[2020-12-04 17:55:34.022] [D] [zway] SENT ACK
[2020-12-04 17:55:34.022] [D] [zway] Delivered to Z-Wave stack
[2020-12-04 17:55:34.061] [D] [zway] RECEIVED: ( 01 18 00 13 35 00 00 04 01 CC 7F 7F 7F 7F 00 00 04 1B 00 00 00 03 01 00 00 15 )
[2020-12-04 17:55:34.061] [D] [zway] SENT ACK
[2020-12-04 17:55:34.062] [I] [zway] Job 0x13 (Nonce Report): Delivered
[2020-12-04 17:55:34.062] [D] [zway] SendData Response with callback 0x35 received: received by recipient 
[2020-12-04 17:55:34.062] [D] [zway] SETDATA devices.55.data.lastSendInternal = **********
[2020-12-04 17:55:34.062] [D] [zway] SETDATA devices.55.data.lastSend = 63773 (0x0000f91d)
[2020-12-04 17:55:34.063] [D] [zway] Job 0x13 (Nonce Report): success
[2020-12-04 17:55:34.063] [I] [zway] Removing job: Nonce Report
[2020-12-04 17:55:34.143] [D] [zway] RECEIVED: ( 01 21 00 04 00 37 19 98 81 47 6E 04 33 E7 EE 0D 47 14 4D 05 35 73 7A 72 82 8B 64 DE F4 8C AE 59 CD 00 53 )
[2020-12-04 17:55:34.144] [D] [zway] SENT ACK
[2020-12-04 17:55:34.144] [D] [zway] SETDATA devices.55.data.lastReceived = 0 (0x00000000)
[2020-12-04 17:55:34.145] [I] [zway] Node 55:0 CC Security: Received a secure message
[2020-12-04 17:55:34.145] [D] [zway] SETDATA devices.55.instances.0.commandClasses.152.data.firstPart = **********
[2020-12-04 17:55:34.145] [I] [zway] Node 55:0 CC Security: passing decrypted packet to application level: [ 5b 03 22 02 03 ]
[2020-12-04 17:55:34.146] [D] [zway] SETDATA devices.55.instances.0.commandClasses.91.data.sequence = **********
[2020-12-04 17:55:34.146] [E] [zway] Received a command to Command Class 0x5b of controller, but it isn't registered
[2020-12-04 17:55:34.146] [D] [zway] SETDATA devices.55.instances.0.commandClasses.91.data.keyAttribute = 2 (0x00000002)
[2020-12-04 17:55:34.146] [D] [zway] SETDATA devices.55.instances.0.commandClasses.91.data.currentScene = 3 (0x00000003)
[2020-12-04 17:55:34.184] [D] [zway] RECEIVED: ( 01 0A 00 04 00 37 02 98 40 CD 00 D1 )
[2020-12-04 17:55:34.184] [D] [zway] SENT ACK
[2020-12-04 17:55:34.185] [D] [zway] SETDATA devices.55.data.lastReceived = 0 (0x00000000)
[2020-12-04 17:55:34.185] [I] [zway] Node 55:0 CC Security: sending Nonce Report
[2020-12-04 17:55:34.186] [I] [zway] Adding job: Nonce Report
[2020-12-04 17:55:34.186] [D] [zway] SENDING (cb 0x36): ( 01 11 00 13 37 0A 98 80 A9 33 E4 DD 16 F3 F0 40 05 36 1D )
[2020-12-04 17:55:34.194] [D] [zway] RECEIVED ACK
[2020-12-04 17:55:34.194] [D] [zway] RECEIVED: ( 01 04 01 13 01 E8 )
[2020-12-04 17:55:34.194] [D] [zway] SENT ACK
[2020-12-04 17:55:34.195] [D] [zway] Delivered to Z-Wave stack
[2020-12-04 17:55:34.318] [D] [zway] RECEIVED: ( 01 18 00 13 36 00 00 0C 01 CC 7F 7F 7F 7F 00 00 03 1B 00 00 00 03 01 00 00 19 )
[2020-12-04 17:55:34.318] [D] [zway] SENT ACK
[2020-12-04 17:55:34.318] [I] [zway] Job 0x13 (Nonce Report): Delivered
[2020-12-04 17:55:34.319] [D] [zway] SendData Response with callback 0x36 received: received by recipient
[2020-12-04 17:55:34.319] [D] [zway] SETDATA devices.55.data.lastSendInternal = **********
[2020-12-04 17:55:34.320] [D] [zway] SETDATA devices.55.data.lastSend = 63798 (0x0000f936)
[2020-12-04 17:55:34.320] [D] [zway] Job 0x13 (Nonce Report): success
[2020-12-04 17:55:34.320] [I] [zway] Removing job: Nonce Report
[2020-12-04 17:55:34.400] [D] [zway] RECEIVED: ( 01 1F 00 04 00 37 17 98 81 2E 1B 35 66 01 A7 95 CD AC 63 79 E2 A9 55 78 7B 61 D8 03 91 28 CC 00 21 )
[2020-12-04 17:55:34.400] [D] [zway] SENT ACK
[2020-12-04 17:55:34.401] [D] [zway] SETDATA devices.55.data.lastReceived = 0 (0x00000000)
[2020-12-04 17:55:34.401] [I] [zway] Node 55:0 CC Security: Received a secure message
[2020-12-04 17:55:34.401] [D] [zway] SETDATA devices.55.instances.0.commandClasses.152.data.firstPart = **********
[2020-12-04 17:55:34.401] [I] [zway] Node 55:0 CC Security: passing decrypted packet to application level: [ 80 03 64 ]
[2020-12-04 17:55:34.402] [D] [zway] SETDATA devices.55.instances.0.commandClasses.128.data.history.100 = 1607100934 (0x5fca6a06)
[2020-12-04 17:55:34.402] [D] [zway] SETDATA devices.55.instances.0.commandClasses.128.data.last = 100 (0x00000064)
[2020-12-04 17:55:34.566] [D] [zway] RECEIVED: ( 01 0A 00 04 00 37 02 98 40 CD 00 D1 )
[2020-12-04 17:55:34.567] [D] [zway] SENT ACK
[2020-12-04 17:55:34.567] [D] [zway] SETDATA devices.55.data.lastReceived = 0 (0x00000000)
[2020-12-04 17:55:34.568] [I] [zway] Node 55:0 CC Security: sending Nonce Report
[2020-12-04 17:55:34.568] [I] [zway] Adding job: Nonce Report
[2020-12-04 17:55:34.569] [D] [zway] SENDING (cb 0x37): ( 01 11 00 13 37 0A 98 80 F5 A8 ED B9 AB 61 11 44 05 37 7C )
[2020-12-04 17:55:34.576] [D] [zway] RECEIVED ACK
[2020-12-04 17:55:34.576] [D] [zway] RECEIVED: ( 01 04 01 13 01 E8 )
[2020-12-04 17:55:34.577] [D] [zway] SENT ACK
[2020-12-04 17:55:34.577] [D] [zway] Delivered to Z-Wave stack
[2020-12-04 17:55:34.679] [D] [zway] RECEIVED: ( 01 18 00 13 37 00 00 0A 01 CC 7F 7F 7F 7F 00 00 03 1B 00 00 00 03 01 00 00 1E )
[2020-12-04 17:55:34.680] [D] [zway] SENT ACK
[2020-12-04 17:55:34.680] [I] [zway] Job 0x13 (Nonce Report): Delivered
[2020-12-04 17:55:34.680] [D] [zway] SendData Response with callback 0x37 received: received by recipient
[2020-12-04 17:55:34.680] [D] [zway] SETDATA devices.55.data.lastSendInternal = **********
[2020-12-04 17:55:34.681] [D] [zway] SETDATA devices.55.data.lastSend = 63833 (0x0000f959)
[2020-12-04 17:55:34.681] [D] [zway] Job 0x13 (Nonce Report): success
[2020-12-04 17:55:34.681] [I] [zway] Removing job: Nonce Report
[2020-12-04 17:55:34.764] [D] [zway] RECEIVED: ( 01 21 00 04 00 37 19 98 81 ED 7F 26 17 E7 57 54 D4 C6 43 D6 A0 27 0E F5 95 52 B3 E4 73 4B A5 53 CD 00 C2 )
[2020-12-04 17:55:34.764] [D] [zway] SENT ACK
[2020-12-04 17:55:34.765] [D] [zway] SETDATA devices.55.data.lastReceived = 0 (0x00000000)
[2020-12-04 17:55:34.765] [I] [zway] Node 55:0 CC Security: Received a secure message
[2020-12-04 17:55:34.765] [D] [zway] SETDATA devices.55.instances.0.commandClasses.152.data.firstPart = **********
[2020-12-04 17:55:34.765] [I] [zway] Node 55:0 CC Security: passing decrypted packet to application level: [ 5b 03 23 01 03 ]
[2020-12-04 17:55:34.765] [D] [zway] SETDATA devices.55.instances.0.commandClasses.91.data.sequence = **********
[2020-12-04 17:55:34.766] [E] [zway] Received a command to Command Class 0x5b of controller, but it isn't registered
[2020-12-04 17:55:34.766] [D] [zway] SETDATA devices.55.instances.0.commandClasses.91.data.keyAttribute = 1 (0x00000001)
[2020-12-04 17:55:34.766] [D] [zway] SETDATA devices.55.instances.0.commandClasses.91.data.currentScene = 3 (0x00000003)

Looking in the Job Queue, the commands (AssociationGroupInformation Info Get, AssociationGroupInformation Name Get, AssociationGroupInformation Commands Get) never finish.

Any ideas?

[PoltoS]

[2020-12-04 17:55:29.251] [zway] Job 0x13 (Nonce Get): Not delivered to recipient

Wake it up

[bogr]

I actually thought I woke it up (the UI also says "Device is currently awake"). Anyway I discovered my rookie mistake of not doing a simple search first - so I found it seem to be a known problem... . I went for the interviewDone=true trick.

Thanks for the feedback, PoltoS!