Interviews start disappearing

[ridewithstyle]

Hi there,

since the upgrade to 3.0 some of my devices start losing interviews. I have multiple Eurotronic Spirit Plus and Komforthaus SpiritPlus (7 to be exact)

1.
One of them suddenly "lost" the security interview and fail to do a new interview cycle

Can't find anything special in the log once I try it

Code: Select all

[2020-02-02 15:48:31.617] [D] [zway] SETDATA devices.58.data.lastReceived = 0 (0x00000000)
[2020-02-02 15:48:31.617] [I] [zway] Node 58:0 CC Security: sending Nonce Report
[2020-02-02 15:48:31.617] [D] [zway] SETDATA devices.58.data.isAwake = True
[2020-02-02 15:48:31.617] [I] [zway] Job 0x13 (Wakeup Sleep): Cancelling job: Wakeup Sleep
[2020-02-02 15:48:31.618] [I] [zway] Removing job: Wakeup Sleep
[2020-02-02 15:48:31.618] [W] [zway] Can not detect if this is a request or set/report - don't expect a reply
[2020-02-02 15:48:31.618] [I] [zway] Adding job: Nonce Report
[2020-02-02 15:48:31.619] [D] [zway] SENDING (cb 0xb4): ( 01 11 00 13 3A 0A 98 80 E4 17 EE 85 F2 77 D8 37 05 B4 96 )
[2020-02-02 15:48:31.622] [D] [zway] RECEIVED ACK
[2020-02-02 15:48:31.625] [D] [zway] RECEIVED: ( 01 04 01 13 01 E8 )
[2020-02-02 15:48:31.625] [D] [zway] SENT ACK
[2020-02-02 15:48:31.625] [D] [zway] Delivered to Z-Wave stack
[2020-02-02 15:48:31.856] [I] [core] [BaseModule-21] Set lastLevel to 10.37 for Astronomy_153_altitude (was 10.49)
[2020-02-02 15:48:31.960] [D] [zway] RECEIVED: ( 01 07 00 13 B4 00 00 21 7E )
[2020-02-02 15:48:31.960] [D] [zway] SENT ACK
[2020-02-02 15:48:31.961] [I] [zway] Job 0x13 (Nonce Report): Delivered
[2020-02-02 15:48:31.961] [D] [zway] SendData Response with callback 0xb4 received: received by recipient
[2020-02-02 15:48:31.961] [D] [zway] SETDATA devices.58.data.lastSendInternal = **********
[2020-02-02 15:48:31.961] [D] [zway] SETDATA devices.58.data.lastSend = 51048 (0x0000c768)
[2020-02-02 15:48:31.961] [D] [zway] Job 0x13 (Nonce Report): success
[2020-02-02 15:48:31.961] [I] [zway] Removing job: Nonce Report
[2020-02-02 15:48:32.060] [I] [core] [BaseModule-21] Set lastLevel to 227.76 for Astronomy_153_azimuth (was 227.55)
[2020-02-02 15:48:32.149] [D] [zway] RECEIVED: ( 01 1C 00 04 00 3A 16 98 81 54 B5 58 EB 60 8D CE 2E 00 E5 E4 E4 F3 67 0E AB 65 1E 82 C7 67 )
[2020-02-02 15:48:32.149] [D] [zway] SENT ACK
[2020-02-02 15:48:32.150] [D] [zway] SETDATA devices.58.data.lastReceived = 0 (0x00000000)
[2020-02-02 15:48:32.150] [I] [zway] Node 58:0 CC Security: Received a secure message
[2020-02-02 15:48:32.150] [D] [zway] SETDATA devices.58.instances.0.commandClasses.152.data.firstPart = **********
[2020-02-02 15:48:32.150] [I] [zway] Node 58:0 CC Security: passing decrypted packet to application level: [ 84 07 ]
[2020-02-02 15:48:32.150] [I] [zway] Node 58:0 CC Wakeup: Wakeup notification
[2020-02-02 15:48:32.150] [D] [zway] SETDATA devices.58.instances.0.commandClasses.132.data.lastWakeup = 1580654912 (0x5e36e140)
[2020-02-02 15:48:32.150] [D] [zway] SETDATA devices.58.data.lastSendInternal = **********
[2020-02-02 15:48:32.151] [D] [zway] SETDATA devices.58.data.lastNonceGet = 50066 (0x0000c392)
[2020-02-02 15:48:32.151] [D] [zway] Running wakeup handler for node 58
[2020-02-02 15:48:32.151] [D] [zway] SETDATA devices.58.instances.0.commandClasses.132.data.lastSleep = 1580654912 (0x5e36e140)
[2020-02-02 15:48:32.151] [I] [zway] Node 58:0 CC Wakeup: Send node to sleep
[2020-02-02 15:48:32.151] [I] [zway] Using security scheme S0
[2020-02-02 15:48:32.151] [I] [zway] Adding job: Wakeup Sleep
[2020-02-02 15:48:32.151] [I] [zway] Node 58:0 CC Security: sending Nonce Get
[2020-02-02 15:48:32.151] [D] [zway] SETDATA devices.58.instances.0.commandClasses.152.data.rNonceAckWait = **********
[2020-02-02 15:48:32.152] [I] [zway] Job 0x13 (Wakeup Sleep): Cancelling job: Wakeup Sleep
[2020-02-02 15:48:32.152] [I] [zway] Removing job: Wakeup Sleep
[2020-02-02 15:48:32.152] [I] [zway] Adding job: Nonce Get
[2020-02-02 15:48:32.152] [D] [zway] SETDATA devices.58.instances.0.commandClasses.132.data.lastSleep = 1580654912 (0x5e36e140)
[2020-02-02 15:48:32.152] [I] [zway] Node 58:0 CC Wakeup: Send node to sleep
[2020-02-02 15:48:32.152] [I] [zway] Using security scheme S0
[2020-02-02 15:48:32.152] [I] [zway] Adding job: Wakeup Sleep
[2020-02-02 15:48:32.152] [D] [zway] SETDATA devices.58.data.lastNonceGet = 51066 (0x0000c77a)
[2020-02-02 15:48:32.170] [D] [zway] SENDING (cb 0xb5): ( 01 09 00 13 3A 02 98 40 05 B5 B5 )
[2020-02-02 15:48:32.172] [D] [zway] RECEIVED ACK
[2020-02-02 15:48:32.175] [D] [zway] RECEIVED: ( 01 04 01 13 01 E8 )
[2020-02-02 15:48:32.176] [D] [zway] SENT ACK
[2020-02-02 15:48:32.176] [D] [zway] Delivered to Z-Wave stack
[2020-02-02 15:48:32.482] [D] [zway] RECEIVED: ( 01 07 00 13 B5 00 00 1E 40 )
[2020-02-02 15:48:32.482] [D] [zway] SENT ACK
[2020-02-02 15:48:32.482] [I] [zway] Job 0x13 (Nonce Get): Delivered
[2020-02-02 15:48:32.482] [D] [zway] SendData Response with callback 0xb5 received: received by recipient
[2020-02-02 15:48:32.482] [D] [zway] SETDATA devices.58.data.lastSendInternal = **********
[2020-02-02 15:48:32.483] [D] [zway] SETDATA devices.58.data.lastSend = 51098 (0x0000c79a)
[2020-02-02 15:48:32.483] [D] [zway] Job 0x13 (Nonce Get): success
[2020-02-02 15:48:32.483] [D] [zway] SETDATA devices.58.instances.0.commandClasses.152.data.rNonceAckWait = **********
[2020-02-02 15:48:32.483] [D] [zway] SETDATA devices.58.data.lastNonceGet = 51098 (0x0000c79a)
[2020-02-02 15:48:32.483] [I] [zway] Waiting for job reply: Nonce Get
[2020-02-02 15:48:32.636] [D] [zway] RECEIVED: ( 01 10 00 04 00 3A 0A 98 80 C3 8B 04 BA 33 F0 B7 7B 3A )
[2020-02-02 15:48:32.637] [D] [zway] SENT ACK
[2020-02-02 15:48:32.637] [D] [zway] SETDATA devices.58.data.lastReceived = 0 (0x00000000)
[2020-02-02 15:48:32.637] [D] [zway] Received reply on job (Nonce Get)
[2020-02-02 15:48:32.637] [D] [zway] SETDATA devices.58.instances.0.commandClasses.152.data.rNonceAckWait = **********
[2020-02-02 15:48:32.637] [D] [zway] SETDATA devices.58.data.lastNonceGet = 51113 (0x0000c7a9)
[2020-02-02 15:48:32.637] [I] [zway] Node 58:0 CC Security: received Nonce Report
[2020-02-02 15:48:32.637] [D] [zway] SETDATA devices.58.instances.0.commandClasses.152.data.rNonce = **********
[2020-02-02 15:48:32.637] [I] [zway] Node 58:0 CC Security: Sending a secure message
[2020-02-02 15:48:32.638] [I] [zway] Node 58:0 CC Security: sending encrypted packet: Wakeup Sleep
[2020-02-02 15:48:32.638] [D] [zway] SETDATA devices.58.instances.0.commandClasses.152.data.toFollow = False
[2020-02-02 15:48:32.638] [D] [zway] SETDATA devices.58.data.lastNonceGet = Empty
[2020-02-02 15:48:32.638] [I] [zway] Adding job: Security, Wakeup Sleep
[2020-02-02 15:48:32.638] [D] [zway] SENDING (cb 0xb6): ( 01 1D 00 13 3A 16 98 81 D6 A9 0D 30 3C 84 C7 E2 EA F5 EE C3 CC AB 45 93 4A 05 B8 9B 05 B6 47 )
[2020-02-02 15:48:32.639] [D] [zway] Secure payload: ( 84 08 )
[2020-02-02 15:48:32.646] [D] [zway] RECEIVED ACK
[2020-02-02 15:48:32.646] [D] [zway] RECEIVED: ( 01 04 01 13 01 E8 )
[2020-02-02 15:48:32.646] [D] [zway] SENT ACK
[2020-02-02 15:48:32.646] [I] [zway] Job 0x13 (Security, Wakeup Sleep): Response received - transfered to encapsulated jobs
[2020-02-02 15:48:32.646] [D] [zway] Delivered to Z-Wave stack
[2020-02-02 15:48:32.646] [D] [zway] Delivered to Z-Wave stack
[2020-02-02 15:48:33.016] [D] [zway] RECEIVED: ( 01 07 00 13 B6 00 00 24 79 )
[2020-02-02 15:48:33.017] [D] [zway] SENT ACK
[2020-02-02 15:48:33.017] [I] [zway] Job 0x13 (Security, Wakeup Sleep): Callback received - transfered to encapsulated jobs
[2020-02-02 15:48:33.017] [I] [zway] Job 0x13 (Wakeup Sleep): Delivered
[2020-02-02 15:48:33.017] [D] [zway] SendData Response with callback 0xb6 received: received by recipient
[2020-02-02 15:48:33.017] [D] [zway] Job 0x13 (Wakeup Sleep): success
[2020-02-02 15:48:33.017] [D] [zway] SETDATA devices.58.data.isAwake = False
[2020-02-02 15:48:33.017] [D] [zway] Sending the queue for node 58 into sleep
[2020-02-02 15:48:33.017] [I] [zway] Removing job: Wakeup Sleep
[2020-02-02 15:48:33.017] [I] [zway] Job 0x13 (Security, Wakeup Sleep): Delivered
[2020-02-02 15:48:33.018] [D] [zway] SendData Response with callback 0xb6 received: received by recipient
[2020-02-02 15:48:33.018] [D] [zway] SETDATA devices.58.data.lastSendInternal = **********
[2020-02-02 15:48:33.018] [D] [zway] SETDATA devices.58.data.lastSend = 51150 (0x0000c7ce)
[2020-02-02 15:48:33.018] [D] [zway] Job 0x13 (Security, Wakeup Sleep): success
[2020-02-02 15:48:33.018] [I] [zway] Removing job: Security, Wakeup Sleep
[2020-02-02 15:48:34.685] [D] [zway] Job 0x13: deleted from queue
[2020-02-02 15:48:35.735] [D] [zway] RECEIVED: ( 01 08 00 04 00 38 02 98 40 11 )
[2020-02-02 15:48:35.735] [D] [zway] SENT ACK
[2020-02-02 15:48:35.735] [D] [zway] SETDATA devices.56.data.lastReceived = 0 (0x00000000)
[2020-02-02 15:48:35.736] [I] [zway] Node 56:0 CC Security: sending Nonce Report
[2020-02-02 15:48:35.736] [W] [zway] Can not detect if this is a request or set/report - don't expect a reply
[2020-02-02 15:48:35.736] [I] [zway] Adding job: Nonce Report
[2020-02-02 15:48:35.736] [D] [zway] SENDING (cb 0xb7): ( 01 11 00 13 38 0A 98 80 7B A1 DE F4 8B B4 DE B2 05 B7 C6 )
[2020-02-02 15:48:35.745] [D] [zway] RECEIVED ACK
[2020-02-02 15:48:35.745] [D] [zway] RECEIVED: ( 01 04 01 13 01 E8 )
[2020-02-02 15:48:35.745] [D] [zway] SENT ACK
[2020-02-02 15:48:35.745] [D] [zway] Delivered to Z-Wave stack
[2020-02-02 15:48:35.862] [D] [zway] RECEIVED: ( 01 07 00 13 B7 00 00 0C 50 )
[2020-02-02 15:48:35.862] [D] [zway] SENT ACK
[2020-02-02 15:48:35.862] [I] [zway] Job 0x13 (Nonce Report): Delivered
[2020-02-02 15:48:35.862] [D] [zway] SendData Response with callback 0xb7 received: received by recipient
[2020-02-02 15:48:35.862] [D] [zway] SETDATA devices.56.data.lastSendInternal = **********
[2020-02-02 15:48:35.863] [D] [zway] SETDATA devices.56.data.lastSend = 51421 (0x0000c8dd)
[2020-02-02 15:48:35.863] [D] [zway] Job 0x13 (Nonce Report): success
[2020-02-02 15:48:35.863] [I] [zway] Removing job: Nonce Report
[2020-02-02 15:48:36.010] [D] [zway] RECEIVED: ( 01 20 00 04 00 38 1A 98 81 0B C3 0D 38 70 C4 82 97 D4 3A A1 10 18 E7 69 7B 42 08 E8 19 C7 46 0C 00 38 )
[2020-02-02 15:48:36.010] [D] [zway] SENT ACK
[2020-02-02 15:48:36.011] [D] [zway] SETDATA devices.56.data.lastReceived = 0 (0x00000000)
[2020-02-02 15:48:36.011] [I] [zway] Node 56:0 CC Security: Received a secure message
[2020-02-02 15:48:36.011] [D] [zway] SETDATA devices.56.instances.0.commandClasses.152.data.firstPart = **********
[2020-02-02 15:48:36.011] [I] [zway] Node 56:0 CC Security: passing decrypted packet to application level: [ 31 05 01 42 07 9a ]
[2020-02-02 15:48:36.011] [D] [zway] SETDATA devices.56.instances.0.commandClasses.49.data.1.deviceScale = 0 (0x00000000)
[2020-02-02 15:48:36.013] [D] [zway] SETDATA devices.56.instances.0.commandClasses.49.data.1.scaleString = "°C"
[2020-02-02 15:48:36.013] [D] [zway] SETDATA devices.56.instances.0.commandClasses.49.data.1.val = 19.459999
[2020-02-02 15:48:36.013] [D] [zway] SETDATA devices.56.instances.0.commandClasses.49.data.1 = Empty

One of them completes security and all except "Firmware Update"
unable to update data: devices[56].instances[0].commandClasses[122].Interview()

I did a full factory reset of one of the spirits and included it in S2 unauthenticated and still the Security Interview and the S2 Interview do not show "OK"

Am I missing something here? Do I have to take additional steps?

Best Regards,
rws

[PoltoS]

We need full inclusion log to analyze

[ridewithstyle]

Hello PoltoS,

just to ensure that there is no hardware error, I bought another new Eurotronic Spirit for comparison.

First I removed the logfile and restarted the razberry and tried to renew the interview of one of my failing thermostats, as you can see in the logs.

Then I included the brand new spirit plus from eurotronic, same issue.

Please dig in, let me know if I can help to debug.

Best Regards,
rws

[ridewithstyle]

Hi PoltoS,

could you find anything?

Best Regards,
rws

[PoltoS]

Sorry, I'm out if work now. Please send it to me by mail and I check when back to work

[ridewithstyle]

Sorry, I somehow missed your reply. Did you get the chance to take a look at the uploaded inclusion log from me? The behaviour didn't change with 3.0.5, still the same issues with disappearing interviews.

Any way I can help debug?

Best Regards,
rws

[PoltoS]

I suppose your mail is in a huge list of mails from last months. Can you resend it please and refresh the question?

[ridewithstyle]

The full inclusion log is four posts up attached to my post from Feb 9th. I never sent an email, I don't even have your email, you profile doesn't show any.

After the inclusion I also manually triggered the interviews, it's also in the logs.

TL;DR: after the upgrade to 3.0, my interviews of my thermostats disappeared one after another and I couldn't redo them, they don't finish. I even bought a brand new eurotronic spirit-z and the same happened.

[ridewithstyle]

issue persists with 3.0.6

[equathza]

The log entries, a few I think are interesting:

Code: Select all

[2020-02-09 15:29:08.916] [I] [zway] Node 88:0 CC AssociationGroupInformation: Association CC interview is not complete - can not proceed with interview

[2020-02-09 15:28:41.808] [D] [zway] Security S2 inclusion timeout event
[2020-02-09 15:28:41.812] [W] [zway] Node 88:0 CC SecurityS2: Security S2 key negociation with node 88 failed, KEX fail reason: Unknown Security S2 KEX failure reason (0)

[2020-02-09 15:50:23.874] [I] [zway] Node 88:0 CC SecurityS2 Interview abandoned due to many retries

A basic question:
Did you exclude the problematic device first? (Even brand new out of box)
> Please try to exclude your device first, and then (re)include your device.

Further more, I see your chip is running an older (5.04) firmware version, check if you can upgrade your controller firmware from the expertUI.
> Create a back-up of your controller before you start! > Under Network > Controller Info you can find the upgrade button.
> Folow the instruction of the firmware upgrade carefully. i.e. sometimes the update procedure need a power off for completion!
When the upgrade firmware button doesn't show you any firmware available, please report back! I don't want you to mess around with trial and error, as you may damage you device.