Timing info shows red 1 as time

Discussions about RaZberry - Z-Wave board for Raspberry computer
Post Reply
ScotsDon
Posts: 50
Joined: 28 Jul 2015 20:55

Timing info shows red 1 as time

Post by ScotsDon »

Using Expert UI, under Network / Timing Info, I sometimes see a series of red 1's as the times (under Last Packets in 10 ms units). Red indicates a failed transmission, but if so, surely it would not take 10 msec?? So what does this mean?

When I get a genuine failure, it is more like a red 250 (2.5 seconds).

I am using Zway v4.1.0, a Razberry7 with SDK Version: 7.17.00 and Serial API Version: 07.13

See below, Node 13:

Screenshot 2023-07-20 163411.png
Screenshot 2023-07-20 163411.png (193.14 KiB) Viewed 11255 times
Nodes 12 and 13 are side by side and one of the furthest from the R Pi controller.

ScotsDon
User avatar
PoltoS
Posts: 7579
Joined: 26 Jan 2011 19:36

Re: Timing info shows red 1 as time

Post by PoltoS »

Sometimes the SDK is very fast to say that it was not delivered. Better to check in the log, because I agree, it had to take longer. Please show the log of that moment
ScotsDon
Posts: 50
Joined: 28 Jul 2015 20:55

Re: Timing info shows red 1 as time

Post by ScotsDon »

I'm not sure of exactly when it happened. It's run every 3 hours. I've looked at the z-way-server.log for each episode from 1800 the previous day to 1500 of the day (20 July), pulled out the relevant secion, and used Notepad++ to run a Compare. There are differences in the data values, but no obvious error meassage. I think I ran a Reorganistaion at 17:06 the previous day. The only thing I have spotted is that a Background Noise Level job sometimes gets started during the Node 13 run, although this Noise job seems to run every 30 seconds, so must also interfere with the other nodes as well. I attach the log extract for the 03:00 run, where the Background Noise Level job runs at 03:01:03.989 during the Node 13 run.

I will keep an eye on the Timing Info and try to pull out the actual log of when it happened.

ScotsDon

Log extract at 03:00

[2023-07-20 03:01:00.051] [zway] Using security scheme S2 Authenticated
[2023-07-20 03:01:00.051] [zway] Adding job: SwitchBinary Get to node 13
[2023-07-20 03:01:00.058] [zway] Adding job: Security S2 Encapsulation (S2 Authenticated), SwitchBinary Get to node 13
[2023-07-20 03:01:00.069] [D] [zway] Secure payload: ( 60 0D 00 01 25 02 )
[2023-07-20 03:01:00.069] [D] [zway] SENDING (cb 0xeb): ( 01 19 00 13 0D 12 9F 03 AD 00 3D F8 4B 12 BF 4B FA 37 0D D5 66 4F B1 4F 25 EB BF )
[2023-07-20 03:01:00.072] [D] [zway] RECEIVED ACK
[2023-07-20 03:01:00.074] [D] [zway] RECEIVED: ( 01 04 01 13 01 E8 )
[2023-07-20 03:01:00.074] [D] [zway] SENT ACK
[2023-07-20 03:01:00.074] [zway] Job 0x13 (Security S2 Encapsulation (S2 Authenticated), SwitchBinary Get to node 13): Response received - transfered to encapsulated jobs
[2023-07-20 03:01:00.074] [D] [zway] Delivered to Z-Wave stack
[2023-07-20 03:01:00.074] [D] [zway] Delivered to Z-Wave stack
[2023-07-20 03:01:00.131] [D] [zway] RECEIVED: ( 01 1D 00 13 EB 00 00 05 02 B6 7F 7F 7F 7F 00 00 03 07 04 00 00 03 01 00 00 7F 7F 7F 7F 7F D6 )
[2023-07-20 03:01:00.131] [D] [zway] SENT ACK
[2023-07-20 03:01:00.131] [zway] Job 0x13 (Security S2 Encapsulation (S2 Authenticated), SwitchBinary Get to node 13): Callback received - transfered to encapsulated jobs
[2023-07-20 03:01:00.131] [zway] Job 0x13 (SwitchBinary Get to node 13): Delivered
[2023-07-20 03:01:00.131] [D] [zway] SendData Response with callback 0xeb received: received by recipient
[2023-07-20 03:01:00.131] [D] [zway] Job 0x13 (SwitchBinary Get to node 13): success
[2023-07-20 03:01:00.132] [zway] Waiting for job reply: SwitchBinary Get from node 13
[2023-07-20 03:01:00.132] [zway] Job 0x13 (Security S2 Encapsulation (S2 Authenticated), SwitchBinary Get to node 13): Delivered
[2023-07-20 03:01:00.133] [D] [zway] SendData Response with callback 0xeb received: received by recipient
[2023-07-20 03:01:00.133] [D] [zway] SETDATA devices.13.data.lastSendInternal = **********
[2023-07-20 03:01:00.133] [D] [zway] SETDATA devices.13.data.lastSend = 3508093 (0x0035877d)
[2023-07-20 03:01:00.133] [D] [zway] Job 0x13 (Security S2 Encapsulation (S2 Authenticated), SwitchBinary Get to node 13): success
[2023-07-20 03:01:00.133] [zway] Removing job: Security S2 Encapsulation (S2 Authenticated), SwitchBinary Get to node 13
[2023-07-20 03:01:00.214] [D] [zway] RECEIVED: ( 01 1E 00 04 00 0D 15 9F 03 B9 00 BE 4E CE 03 2B 72 46 02 CB EA 2D A5 A3 8A 6E 7C 8A B6 00 00 56 )
[2023-07-20 03:01:00.214] [D] [zway] SENT ACK
[2023-07-20 03:01:00.215] [D] [zway] SETDATA devices.13.data.lastReceived = 0 (0x00000000)
[2023-07-20 03:01:00.215] [zway] Node 13:0 CC SecurityS2: passing S2 Authenticated decrypted packet to application level: [ 60 0d 01 00 25 03 00 00 00 ]
[2023-07-20 03:01:00.216] [D] [zway] Received reply on job (SwitchBinary Get to node 13)
[2023-07-20 03:01:00.216] [D] [zway] SETDATA devices.13.instances.1.commandClasses.37.data.level = False
[2023-07-20 03:01:02.788] [D] [zway] Job 0x13: deleted from queue
[2023-07-20 03:01:03.989] [I] [zway] Adding job: Get background noise level
[2023-07-20 03:01:03.999] [D] [zway] SENDING: ( 01 03 00 3B C7 )
[2023-07-20 03:01:04.000] [D] [zway] RECEIVED ACK
[2023-07-20 03:01:04.001] [D] [zway] RECEIVED: ( 01 07 01 3B A8 A4 A4 7F 15 )
[2023-07-20 03:01:04.001] [D] [zway] SENT ACK
[2023-07-20 03:01:04.001] [D] [zway] SETDATA controller.data.statistics.backgroundRSSI.channel1 = 168 (0x000000a8)
[2023-07-20 03:01:04.001] [D] [zway] SETDATA controller.data.statistics.backgroundRSSI.channel2 = 164 (0x000000a4)
[2023-07-20 03:01:04.002] [D] [zway] SETDATA controller.data.statistics.backgroundRSSI.channel3 = 164 (0x000000a4)
[2023-07-20 03:01:04.002] [I] [zway] Job 0x3b (Get background noise level): RSSI Ch#1: -88 dBm, Ch#2: -92 dBm, Ch#3: -92 dBm
[2023-07-20 03:01:04.002] [D] [zway] Job 0x3b (Get background noise level): success
[2023-07-20 03:01:04.002] [I] [zway] Removing job: Get background noise level
[2023-07-20 03:01:04.182] [D] [zway] SETDATA devices.13.instances.0.commandClasses.108.data.6 = Empty
[2023-07-20 03:01:04.182] [D] [zway] SETDATA devices.13.instances.0.commandClasses.108.data.6.status = Empty
[2023-07-20 03:01:04.182] [D] [zway] SETDATA devices.13.instances.0.commandClasses.108.data.6.duration = Empty
[2023-07-20 03:01:04.182] [D] [zway] SETDATA devices.13.instances.0.commandClasses.108.data.6.moreStatusUpdates = Empty
[2023-07-20 03:01:04.182] [D] [zway] SETDATA devices.13.instances.0.commandClasses.108.data.6.lastEvent = Empty
[2023-07-20 03:01:04.182] [D] [zway] SETDATA devices.13.instances.0.commandClasses.108.data.6.status = 255 (0x000000ff)
[2023-07-20 03:01:04.182] [D] [zway] SETDATA devices.13.instances.0.commandClasses.108.data.6.duration = 0 (0x00000000)
[2023-07-20 03:01:04.182] [D] [zway] SETDATA devices.13.instances.0.commandClasses.108.data.6.moreStatusUpdates = False
[2023-07-20 03:01:04.183] [D] [zway] SETDATA devices.13.instances.0.commandClasses.108.data.6.lastEvent = 3508488 (0x00358908)
[2023-07-20 03:01:04.183] [D] [zway] SETDATA devices.13.instances.0.commandClasses.108.data.6 = Empty
[2023-07-20 03:01:04.183] [D] [zway] SETDATA devices.13.instances.0.commandClasses.108.data.lastSession = 6 (0x00000006)
[2023-07-20 03:01:04.183] [I] [zway] Using security scheme S2 Authenticated
[2023-07-20 03:01:04.183] [I] [zway] Adding job: SwitchBinary Set to node 13
[2023-07-20 03:01:04.187] [I] [zway] Adding job: Security S2 Encapsulation (S2 Authenticated), SwitchBinary Set to node 13
[2023-07-20 03:01:04.198] [D] [zway] Secure payload: ( 60 0D 00 01 6C 01 86 04 25 01 00 FF )
[2023-07-20 03:01:04.198] [D] [zway] SENDING (cb 0xec): ( 01 1F 00 13 0D 18 9F 03 AE 00 81 9D CC D3 DC C3 89 5C FC B2 8D AE B0 33 95 32 48 75 E6 4F 25 EC 09 )
[2023-07-20 03:01:04.202] [D] [zway] RECEIVED ACK
[2023-07-20 03:01:04.203] [D] [zway] RECEIVED: ( 01 04 01 13 01 E8 )
[2023-07-20 03:01:04.203] [D] [zway] SENT ACK
[2023-07-20 03:01:04.203] [I] [zway] Job 0x13 (Security S2 Encapsulation (S2 Authenticated), SwitchBinary Set to node 13): Response received - transfered to encapsulated jobs
[2023-07-20 03:01:04.203] [D] [zway] Delivered to Z-Wave stack
[2023-07-20 03:01:04.204] [D] [zway] Delivered to Z-Wave stack
[2023-07-20 03:01:04.414] [D] [zway] RECEIVED: ( 01 1D 00 13 EC 00 00 14 02 B6 7F 7F 7F 7F 00 00 03 07 04 00 00 03 02 00 00 7F 7F 7F 7F 7F C3 )
[2023-07-20 03:01:04.415] [D] [zway] SENT ACK
[2023-07-20 03:01:04.415] [I] [zway] Job 0x13 (Security S2 Encapsulation (S2 Authenticated), SwitchBinary Set to node 13): Callback received - transfered to encapsulated jobs
[2023-07-20 03:01:04.415] [I] [zway] Job 0x13 (SwitchBinary Set to node 13): Delivered
[2023-07-20 03:01:04.415] [D] [zway] SendData Response with callback 0xec received: received by recipient
[2023-07-20 03:01:04.415] [D] [zway] Job 0x13 (SwitchBinary Set to node 13): success
[2023-07-20 03:01:04.415] [I] [zway] Waiting for job reply: SwitchBinary Set from node 13
[2023-07-20 03:01:04.415] [I] [zway] Job 0x13 (Security S2 Encapsulation (S2 Authenticated), SwitchBinary Set to node 13): Delivered
[2023-07-20 03:01:04.415] [D] [zway] SendData Response with callback 0xec received: received by recipient
[2023-07-20 03:01:04.416] [D] [zway] SETDATA devices.13.data.lastSendInternal = **********
[2023-07-20 03:01:04.416] [D] [zway] SETDATA devices.13.data.lastSend = 3508510 (0x0035891e)
[2023-07-20 03:01:04.416] [D] [zway] Job 0x13 (Security S2 Encapsulation (S2 Authenticated), SwitchBinary Set to node 13): success
[2023-07-20 03:01:04.416] [I] [zway] Removing job: Security S2 Encapsulation (S2 Authenticated), SwitchBinary Set to node 13
[2023-07-20 03:01:04.495] [D] [zway] RECEIVED: ( 01 1E 00 04 00 0D 15 9F 03 BA 00 24 86 53 1D 0B F6 68 29 01 D2 32 7C AC 05 EC 22 CC B6 00 00 0B )
[2023-07-20 03:01:04.495] [D] [zway] SENT ACK
[2023-07-20 03:01:04.496] [D] [zway] SETDATA devices.13.data.lastReceived = 0 (0x00000000)
[2023-07-20 03:01:04.496] [I] [zway] Node 13:0 CC SecurityS2: passing S2 Authenticated decrypted packet to application level: [ 60 0d 01 00 6c 02 06 ff 00 ]
[2023-07-20 03:01:04.496] [D] [zway] SETDATA devices.13.instances.1.commandClasses.108.data.6 = Empty
[2023-07-20 03:01:04.497] [D] [zway] SETDATA devices.13.instances.1.commandClasses.108.data.6.status = Empty
[2023-07-20 03:01:04.497] [D] [zway] SETDATA devices.13.instances.1.commandClasses.108.data.6.duration = Empty
[2023-07-20 03:01:04.497] [D] [zway] SETDATA devices.13.instances.1.commandClasses.108.data.6.moreStatusUpdates = Empty
[2023-07-20 03:01:04.497] [D] [zway] SETDATA devices.13.instances.1.commandClasses.108.data.6.lastEvent = Empty
[2023-07-20 03:01:04.497] [D] [zway] SETDATA devices.13.instances.1.commandClasses.108.data.6.status = 255 (0x000000ff)
[2023-07-20 03:01:04.497] [D] [zway] SETDATA devices.13.instances.1.commandClasses.108.data.6.duration = 0 (0x00000000)
[2023-07-20 03:01:04.497] [D] [zway] SETDATA devices.13.instances.1.commandClasses.108.data.6.moreStatusUpdates = False
[2023-07-20 03:01:04.497] [D] [zway] SETDATA devices.13.instances.1.commandClasses.108.data.6.lastEvent = 3508517 (0x00358925)
[2023-07-20 03:01:04.497] [D] [zway] SETDATA devices.13.instances.1.commandClasses.108.data.6 = Empty
[2023-07-20 03:01:04.497] [D] [zway] Received reply on job (SwitchBinary Set to node 13)
[2023-07-20 03:01:04.497] [I] [zway] Node 13:1 CC Supervision: Setter packet was confirmed: SwitchBinary Set
[2023-07-20 03:01:04.497] [D] [zway] SETDATA devices.13.instances.1.commandClasses.37.data.level = False
[2023-07-20 03:01:04.497] [D] [zway] SETDATA devices.13.data.lastSendInternal = **********
[2023-07-20 03:01:05.953] [D] [zway] Job 0x13: deleted from queue
[2023-07-20 03:01:05.964] [D] [zway] Job 0x13: deleted from queue
[2023-07-20 03:01:06.422] [D] [zway] Node 13:1 CC SwitchBinary: Unsolicited report received, skipping Get
[2023-07-20 03:01:10.096] [D] [zway] Job 0x13: deleted from queue
[2023-07-20 03:01:10.106] [D] [zway] Job 0x13: deleted from queue
[2023-07-20 03:01:13.186] [D] [zway] Job 0x13: deleted from queue
[2023-07-20 03:01:13.196] [D] [zway] Job 0x13: deleted from queue
[2023-07-20 03:01:17.305] [D] [zway] Job 0x13: deleted from queue
[2023-07-20 03:01:17.315] [D] [zway] Job 0x13: deleted from queue
[2023-07-20 03:01:20.385] [D] [zway] Job 0x13: deleted from queue
[2023-07-20 03:01:20.396] [D] [zway] Job 0x13: deleted from queue
[2023-07-20 03:01:24.248] [D] [zway] Job 0x3b: deleted from queue
[2023-07-20 03:01:24.655] [D] [zway] Job 0x13: deleted from queue
[2023-07-20 03:01:24.665] [D] [zway] Job 0x13: deleted from queue
User avatar
PoltoS
Posts: 7579
Joined: 26 Jan 2011 19:36

Re: Timing info shows red 1 as time

Post by PoltoS »

There is nothing wrong in this log. The device is always reachable. the red one means the corresponding packet was not delivered
Post Reply