Problem/Testing Description
Been doing some testing with the new fuota-server. Something is occurring when the server performs the Setup/Ans parts of the process. I’ve pulled some logs and timestamped debug output from an array of 10 test devices. It appears that the McSetupReq and subsequent McSetupAns are fated to collide.
Setup
- Latest stable AS 3.14, NS 3.12.3 , FS 3.0.0-test.2
- 1 single MT Conduit, semtech pktforw + chirpstack gw bridge
- 10 node devices (class-C)
Behavior & Logs
What appears to be occurring, is that fuota-server queues up all the McSetupReq at once, causing all 10 setup requests to be sent within 2 seconds. When device 2, for example, is receiving its McSetupReq, device 1 is attempting to answer with McSetupAns. Since the gateway is not full-duplex, this particular timing is always setting us up for collisions.
I used the debug output from all 10 devices to get timestamps on their McSetupReq and attempted McSetupAns. The result was the following timings. Note the timestamp is in secs.ms. As you can see, the “answers” of the earlier devices are colliding with the “requests” of later devices.
"McSetupReq" "McSetupAns"
31.587 31.758
31.801 31.976
32.017 32.198
32.233 32.435
32.450 32.636
32.647 32.975
32.862 33.116
33.079 33.479
33.296 33.680
33.491 33.986
Here is the fuota-server logfile, showing the missed answers:
# Deployment grpc call
18:23:47 level=info msg="storage: deployment created" id=a41fa7eb-0e20-487b-9190-7b2e052e049d
18:23:47 level=info msg="storage: deployment device created" deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa0001000037
18:23:47 level=info msg="storage: deployment device created" deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa000100003a
18:23:47 level=info msg="storage: deployment device created" deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa000100003b
18:23:47 level=info msg="storage: deployment device created" deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa0001000035
18:23:47 level=info msg="storage: deployment device created" deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa0001000036
18:23:47 level=info msg="storage: deployment device created" deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa0001000038
18:23:47 level=info msg="storage: deployment device created" deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa0001000039
18:23:47 level=info msg="storage: deployment device created" deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa000100003c
18:23:47 level=info msg="storage: deployment device created" deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa0001000033
18:23:47 level=info msg="storage: deployment device created" deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa0001000034
18:23:47 level=info msg="finished client unary call" grpc.code=OK grpc.method=Get grpc.service=api.ApplicationService grpc.time_ms=2.883 span.kind=client system=grpc
18:23:47 level=info msg="finished client unary call" grpc.code=OK grpc.method=Create grpc.service=api.MulticastGroupService grpc.time_ms=7.163 span.kind=client system=grpc
# fuota-server setup MC group in LNS and add all devices to it
18:23:47 level=info msg="fuota: multicast-group created" deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d multicast_group_id=63da2cb0-1c77-4bee-a605-6e7f3705ab7f
18:23:47 level=info msg="fuota: add devices to multicast-group" deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d
18:23:47 level=info msg="fuota: add device to multicast-group" deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa0001000035 multicast_group_id=63da2cb0-1c77-4bee-a605-6e7f3705ab7f
18:23:47 level=info msg="finished client unary call" grpc.code=OK grpc.method=AddDevice grpc.service=api.MulticastGroupService grpc.time_ms=7.585 span.kind=client system=grpc
18:23:47 level=info msg="fuota: add device to multicast-group" deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa0001000036 multicast_group_id=63da2cb0-1c77-4bee-a605-6e7f3705ab7f
18:23:47 level=info msg="finished client unary call" grpc.code=OK grpc.method=AddDevice grpc.service=api.MulticastGroupService grpc.time_ms=7.022 span.kind=client system=grpc
18:23:47 level=info msg="fuota: add device to multicast-group" deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa0001000037 multicast_group_id=63da2cb0-1c77-4bee-a605-6e7f3705ab7f
18:23:47 level=info msg="finished client unary call" grpc.code=OK grpc.method=AddDevice grpc.service=api.MulticastGroupService grpc.time_ms=7.21 span.kind=client system=grpc
18:23:47 level=info msg="fuota: add device to multicast-group" deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa000100003a multicast_group_id=63da2cb0-1c77-4bee-a605-6e7f3705ab7f
18:23:47 level=info msg="finished client unary call" grpc.code=OK grpc.method=AddDevice grpc.service=api.MulticastGroupService grpc.time_ms=7.089 span.kind=client system=grpc
18:23:47 level=info msg="fuota: add device to multicast-group" deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa000100003b multicast_group_id=63da2cb0-1c77-4bee-a605-6e7f3705ab7f
18:23:47 level=warning msg="[transport] transport: http2Server.HandleStreams failed to read frame: read tcp 172.31.61.185:8070->209.180.18.10:65133: read: connection reset by peer"
18:23:47 level=info msg="finished client unary call" grpc.code=OK grpc.method=AddDevice grpc.service=api.MulticastGroupService grpc.time_ms=7.033 span.kind=client system=grpc
18:23:47 level=info msg="fuota: add device to multicast-group" deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa0001000033 multicast_group_id=63da2cb0-1c77-4bee-a605-6e7f3705ab7f
18:23:47 level=info msg="finished client unary call" grpc.code=OK grpc.method=AddDevice grpc.service=api.MulticastGroupService grpc.time_ms=6.924 span.kind=client system=grpc
18:23:47 level=info msg="fuota: add device to multicast-group" deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa0001000034 multicast_group_id=63da2cb0-1c77-4bee-a605-6e7f3705ab7f
18:23:47 level=info msg="finished client unary call" grpc.code=OK grpc.method=AddDevice grpc.service=api.MulticastGroupService grpc.time_ms=6.862 span.kind=client system=grpc
18:23:47 level=info msg="fuota: add device to multicast-group" deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa0001000038 multicast_group_id=63da2cb0-1c77-4bee-a605-6e7f3705ab7f
18:23:47 level=info msg="finished client unary call" grpc.code=OK grpc.method=AddDevice grpc.service=api.MulticastGroupService grpc.time_ms=6.791 span.kind=client system=grpc
18:23:47 level=info msg="fuota: add device to multicast-group" deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa0001000039 multicast_group_id=63da2cb0-1c77-4bee-a605-6e7f3705ab7f
18:23:47 level=info msg="finished client unary call" grpc.code=OK grpc.method=AddDevice grpc.service=api.MulticastGroupService grpc.time_ms=7.011 span.kind=client system=grpc
18:23:47 level=info msg="fuota: add device to multicast-group" deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa000100003c multicast_group_id=63da2cb0-1c77-4bee-a605-6e7f3705ab7f
18:23:47 level=info msg="finished client unary call" grpc.code=OK grpc.method=AddDevice grpc.service=api.MulticastGroupService grpc.time_ms=7.194 span.kind=client system=grpc
# McSetupReq attempt #1
18:23:47 level=info msg="fuota: starting multicast-setup for devices" deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d
18:23:47 level=info msg="fuota: initiate multicast-setup for device" attempt=1 deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa0001000035
18:23:47 level=info msg="finished client unary call" grpc.code=OK grpc.method=Enqueue grpc.service=api.DeviceQueueService grpc.time_ms=9.165 span.kind=client system=grpc
18:23:47 level=info msg="storage: deployment log created" command=McGroupSetupReq deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa0001000035
18:23:47 level=info msg="fuota: initiate multicast-setup for device" attempt=1 deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa0001000036
18:23:48 level=info msg="finished client unary call" grpc.code=OK grpc.method=Enqueue grpc.service=api.DeviceQueueService grpc.time_ms=9.846 span.kind=client system=grpc
18:23:48 level=info msg="storage: deployment log created" command=McGroupSetupReq deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa0001000036
18:23:48 level=info msg="fuota: initiate multicast-setup for device" attempt=1 deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa0001000037
18:23:48 level=info msg="finished client unary call" grpc.code=OK grpc.method=Enqueue grpc.service=api.DeviceQueueService grpc.time_ms=9.489 span.kind=client system=grpc
18:23:48 level=info msg="storage: deployment log created" command=McGroupSetupReq deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa0001000037
18:23:48 level=info msg="fuota: initiate multicast-setup for device" attempt=1 deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa000100003a
18:23:48 level=info msg="finished client unary call" grpc.code=OK grpc.method=Enqueue grpc.service=api.DeviceQueueService grpc.time_ms=9.607 span.kind=client system=grpc
18:23:48 level=info msg="storage: deployment log created" command=McGroupSetupReq deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa000100003a
18:23:48 level=info msg="fuota: initiate multicast-setup for device" attempt=1 deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa000100003b
18:23:48 level=info msg="finished client unary call" grpc.code=OK grpc.method=Enqueue grpc.service=api.DeviceQueueService grpc.time_ms=8.88 span.kind=client system=grpc
18:23:48 level=info msg="storage: deployment log created" command=McGroupSetupReq deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa000100003b
18:23:48 level=info msg="fuota: initiate multicast-setup for device" attempt=1 deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa0001000033
18:23:48 level=info msg="finished client unary call" grpc.code=OK grpc.method=Enqueue grpc.service=api.DeviceQueueService grpc.time_ms=9.018 span.kind=client system=grpc
18:23:48 level=info msg="storage: deployment log created" command=McGroupSetupReq deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa0001000033
18:23:48 level=info msg="fuota: initiate multicast-setup for device" attempt=1 deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa0001000034
18:23:48 level=info msg="finished client unary call" grpc.code=OK grpc.method=Enqueue grpc.service=api.DeviceQueueService grpc.time_ms=8.641 span.kind=client system=grpc
18:23:48 level=info msg="storage: deployment log created" command=McGroupSetupReq deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa0001000034
18:23:48 level=info msg="fuota: initiate multicast-setup for device" attempt=1 deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa0001000038
18:23:48 level=info msg="finished client unary call" grpc.code=OK grpc.method=Enqueue grpc.service=api.DeviceQueueService grpc.time_ms=8.684 span.kind=client system=grpc
18:23:48 level=info msg="storage: deployment log created" command=McGroupSetupReq deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa0001000038
18:23:48 level=info msg="fuota: initiate multicast-setup for device" attempt=1 deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa0001000039
18:23:48 level=info msg="finished client unary call" grpc.code=OK grpc.method=Enqueue grpc.service=api.DeviceQueueService grpc.time_ms=8.596 span.kind=client system=grpc
18:23:48 level=info msg="storage: deployment log created" command=McGroupSetupReq deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa0001000039
18:23:48 level=info msg="fuota: initiate multicast-setup for device" attempt=1 deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa000100003c
18:23:48 level=info msg="finished client unary call" grpc.code=OK grpc.method=Enqueue grpc.service=api.DeviceQueueService grpc.time_ms=8.884 span.kind=client system=grpc
18:23:48 level=info msg="storage: deployment log created" command=McGroupSetupReq deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa000100003c
# McSetupAns (only gets 7/10)
18:23:50 level=info msg="fuota: multicast-setup command received" cid=McGroupSetupReq deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa0001000033
18:23:50 level=info msg="fuota: McGroupSetupAns received" deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa0001000033 id_error=false mc_group_id=0
18:23:50 level=info msg="storage: deployment log created" command=McGroupSetupAns deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa0001000033
18:23:50 level=info msg="storage: deployment device updated" deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa0001000033
18:23:50 level=info msg="fuota: multicast-setup command received" cid=McGroupSetupReq deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa0001000035
18:23:50 level=info msg="fuota: McGroupSetupAns received" deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa0001000035 id_error=false mc_group_id=0
18:23:50 level=info msg="storage: deployment log created" command=McGroupSetupAns deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa0001000035
18:23:50 level=info msg="storage: deployment device updated" deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa0001000035
18:23:51 level=info msg="fuota: multicast-setup command received" cid=McGroupSetupReq deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa0001000037
18:23:51 level=info msg="fuota: McGroupSetupAns received" deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa0001000037 id_error=false mc_group_id=0
18:23:51 level=info msg="storage: deployment log created" command=McGroupSetupAns deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa0001000037
18:23:51 level=info msg="storage: deployment device updated" deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa0001000037
18:23:51 level=info msg="fuota: multicast-setup command received" cid=McGroupSetupReq deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa0001000038
18:23:51 level=info msg="fuota: McGroupSetupAns received" deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa0001000038 id_error=false mc_group_id=0
18:23:51 level=info msg="storage: deployment log created" command=McGroupSetupAns deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa0001000038
18:23:51 level=info msg="storage: deployment device updated" deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa0001000038
18:23:51 level=info msg="fuota: multicast-setup command received" cid=McGroupSetupReq deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa000100003a
18:23:51 level=info msg="fuota: McGroupSetupAns received" deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa000100003a id_error=false mc_group_id=0
18:23:51 level=info msg="storage: deployment log created" command=McGroupSetupAns deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa000100003a
18:23:51 level=info msg="storage: deployment device updated" deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa000100003a
18:23:52 level=info msg="fuota: multicast-setup command received" cid=McGroupSetupReq deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa0001000039
18:23:52 level=info msg="fuota: McGroupSetupAns received" deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa0001000039 id_error=false mc_group_id=0
18:23:52 level=info msg="storage: deployment log created" command=McGroupSetupAns deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa0001000039
18:23:52 level=info msg="storage: deployment device updated" deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa0001000039
18:23:52 level=info msg="fuota: multicast-setup command received" cid=McGroupSetupReq deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa000100003b
18:23:52 level=info msg="fuota: McGroupSetupAns received" deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa000100003b id_error=false mc_group_id=0
18:23:52 level=info msg="storage: deployment log created" command=McGroupSetupAns deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa000100003b
18:23:52 level=info msg="storage: deployment device updated" deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa000100003b
# McSetupReq attempt #2 (remaining 3 devices)
18:24:18 level=info msg="fuota: initiate multicast-setup for device" attempt=2 deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa0001000036
18:24:18 level=info msg="finished client unary call" grpc.code=OK grpc.method=Enqueue grpc.service=api.DeviceQueueService grpc.time_ms=11.416 span.kind=client system=grpc
18:24:18 level=info msg="storage: deployment log created" command=McGroupSetupReq deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa0001000036
18:24:18 level=info msg="fuota: initiate multicast-setup for device" attempt=2 deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa000100003c
18:24:18 level=info msg="finished client unary call" grpc.code=OK grpc.method=Enqueue grpc.service=api.DeviceQueueService grpc.time_ms=9.411 span.kind=client system=grpc
18:24:18 level=info msg="storage: deployment log created" command=McGroupSetupReq deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa000100003c
18:24:18 level=info msg="fuota: initiate multicast-setup for device" attempt=2 deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa0001000034
18:24:18 level=info msg="finished client unary call" grpc.code=OK grpc.method=Enqueue grpc.service=api.DeviceQueueService grpc.time_ms=8.82 span.kind=client system=grpc
18:24:18 level=info msg="storage: deployment log created" command=McGroupSetupReq deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa0001000034
# McSetupAns (only gets 2 out of the remaining 3)
18:24:21 level=info msg="fuota: multicast-setup command received" cid=McGroupSetupReq deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa0001000036
18:24:21 level=info msg="fuota: McGroupSetupAns received" deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa0001000036 id_error=false mc_group_id=0
18:24:21 level=info msg="storage: deployment log created" command=McGroupSetupAns deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa0001000036
18:24:21 level=info msg="storage: deployment device updated" deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa0001000036
18:24:21 level=info msg="fuota: multicast-setup command received" cid=McGroupSetupReq deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa000100003c
18:24:21 level=info msg="fuota: McGroupSetupAns received" deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa000100003c id_error=false mc_group_id=0
18:24:21 level=info msg="storage: deployment log created" command=McGroupSetupAns deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa000100003c
18:24:21 level=info msg="storage: deployment device updated" deployment_id=a41fa7eb-0e20-487b-9190-7b2e052e049d dev_eui=aaaaaa000100003c
Ideas
I think this would be solved if the time between sending each McSetupReq was spaced a bit more so that device N has a chance to reply with its McSetupAns before the McSetupReq downlink for N+1 is sent (thus putting the gateway radio in TX mode and missing the Ans for device N). Am I missing something here? Seems like with the current scheme it will always induce collisions unless you had a full-duplex gateway.
I am guessing the same thing will happen with the McClassCSessionReq/Ans and the FragSetupReq/Ans. I am also not positive when all devices will ask for the time sync in this process, looks like that might be up to the device implementation though.