Z-Stack: Rewrite device entry in the coordinator's child table if sen…

…ding fails (#680)

* Attempt to rewrite device entry in the child table if sending fails

Sometimes the coordinator stops setting the PENDING flag before sending frames to sleepy end devices.
Rewriting the device entry in the child table seems to fix this, at least temporarily.
If sending a frame fails, try to rewrite the device's entry and try again
(if there is already an entry, and only if the device is listed as a sleepy end device, aka CHILD_RFD)

* Additional test for branch coverage

* Check for AssocAdd/AssocRemove support; fix debug output

src/adapter/z-stack/adapter/zStackAdapter.ts

@@ -501,6 +501,20 @@ class ZStackAdapter extends Adapter {
             } catch (error) {
                 debug('Response timeout (%s:%d,%d)', ieeeAddr, networkAddress, responseAttempt);
                 if (responseAttempt < 1 && !disableRecovery) {
+                    // No response could be because the radio of the end device is turned off:
+                    // Sometimes the coordinator does not properly set the PENDING flag.
+                    // Try to rewrite the device entry in the association table, this fixes it sometimes.
+                    const match =  await this.znp.request(
+                        Subsystem.UTIL, 'assocGetWithAddress',{extaddr: ieeeAddr, nwkaddr: networkAddress}
+                    );
+                    debug(`Response timeout recovery: Node relation ${match.payload.noderelation} (${ieeeAddr})`);
+                    if (this.supportsAssocAdd() && this.supportsAssocRemove() && match.payload.noderelation == 1) {
+                        debug(`Response timeout recovery: Rewrite association table entry (${ieeeAddr})`);
+                        await this.znp.request(Subsystem.UTIL, 'assocRemove', {ieeeadr: ieeeAddr});
+                        assocRestore =
+                            {ieeeadr: ieeeAddr, nwkaddr: networkAddress, noderelation: match.payload.noderelation};
+                        await this.znp.request(Subsystem.UTIL, 'assocAdd', assocRestore);
+                    }
                     // No response could be of invalid route, e.g. when message is send to wrong parent of end device.
                     await this.discoverRoute(networkAddress);
                     return this.sendZclFrameToEndpointInternal(

test/adapter/z-stack/adapter.test.ts

@@ -2453,6 +2453,34 @@ describe("zstack-adapter", () => {
         basicMocks();
         await adapter.start();
 
+        mockZnpRequest.mockClear();
+        assocGetWithAddressNodeRelation = 2;
+        const responseMismatchFrame = Zcl.ZclFrame.create(Zcl.FrameType.GLOBAL, Zcl.Direction.SERVER_TO_CLIENT, true, null, 102, 'readRsp', 0, [{attrId: 0, attrData: 5, dataType: 32, status: 0}]);
+        const frame = Zcl.ZclFrame.create(Zcl.FrameType.GLOBAL, Zcl.Direction.CLIENT_TO_SERVER, false, null, 100, 'read', 0, [{attrId: 0}]);
+        const objectMismatch = {type: Type.AREQ, subsystem: Subsystem.AF, command: 'incomingMsg', payload: {clusterid: 0, srcendpoint: 20, srcaddr: 2, linkquality: 101, groupid: 12, data: responseMismatchFrame.toBuffer()}};
+        let error;
+        try {
+            mockSetTimeout();
+            const response = adapter.sendZclFrameToEndpoint('0x02', 2, 20, frame, 1, false, false);
+            znpReceived(objectMismatch);
+            await response;
+        } catch (e) {
+            error = e;
+        }
+
+        expect(mockQueueExecute.mock.calls[0][1]).toBe(2);
+        expect(mockZnpRequest).toBeCalledTimes(4);
+        expect(mockZnpRequest).toHaveBeenNthCalledWith(1, 4, "dataRequest", {"clusterid": 0, "data": frame.toBuffer(), "destendpoint": 20, "dstaddr": 2, "len": 5, "options": 0, "radius": 30, "srcendpoint": 1, "transid": 1}, 99)
+        expect(mockZnpRequest).toHaveBeenNthCalledWith(2, 7, "assocGetWithAddress", {extaddr: '0x02', nwkaddr: 2})
+        expect(mockZnpRequest).toHaveBeenNthCalledWith(3, 5, 'extRouteDisc', {dstAddr: 2, options: 0, radius: Constants.AF.DEFAULT_RADIUS})
+        expect(mockZnpRequest).toHaveBeenNthCalledWith(4, 4, "dataRequest", {"clusterid": 0, "data": frame.toBuffer(), "destendpoint": 20, "dstaddr": 2, "len": 5, "options": 0, "radius": 30, "srcendpoint": 1, "transid": 2}, 99)
+        expect(error).toStrictEqual(new Error("Timeout - 2 - 20 - 100 - 0 - 1 after 1ms"));
+    });
+
+    it('Send zcl frame network address timeout should discover route, rewrite child entry and retry for sleepy end device', async () => {
+        basicMocks();
+        await adapter.start();
+
         mockZnpRequest.mockClear();
 
         const responseMismatchFrame = Zcl.ZclFrame.create(Zcl.FrameType.GLOBAL, Zcl.Direction.SERVER_TO_CLIENT, true, null, 102, 'readRsp', 0, [{attrId: 0, attrData: 5, dataType: 32, status: 0}]);
@@ -2469,10 +2497,13 @@ describe("zstack-adapter", () => {
         }
 
         expect(mockQueueExecute.mock.calls[0][1]).toBe(2);
-        expect(mockZnpRequest).toBeCalledTimes(3);
+        expect(mockZnpRequest).toBeCalledTimes(6);
         expect(mockZnpRequest).toHaveBeenNthCalledWith(1, 4, "dataRequest", {"clusterid": 0, "data": frame.toBuffer(), "destendpoint": 20, "dstaddr": 2, "len": 5, "options": 0, "radius": 30, "srcendpoint": 1, "transid": 1}, 99)
-        expect(mockZnpRequest).toHaveBeenNthCalledWith(2, 5, 'extRouteDisc', {dstAddr: 2, options: 0, radius: Constants.AF.DEFAULT_RADIUS})
-        expect(mockZnpRequest).toHaveBeenNthCalledWith(3, 4, "dataRequest", {"clusterid": 0, "data": frame.toBuffer(), "destendpoint": 20, "dstaddr": 2, "len": 5, "options": 0, "radius": 30, "srcendpoint": 1, "transid": 2}, 99)
+        expect(mockZnpRequest).toHaveBeenNthCalledWith(2, 7, "assocGetWithAddress", {extaddr: '0x02', nwkaddr: 2})
+        expect(mockZnpRequest).toHaveBeenNthCalledWith(3, 7, "assocRemove", {ieeeadr: '0x02'})
+        expect(mockZnpRequest).toHaveBeenNthCalledWith(4, 7, "assocAdd",         {ieeeadr: '0x02', nwkaddr: 2, noderelation: 1})
+        expect(mockZnpRequest).toHaveBeenNthCalledWith(5, 5, 'extRouteDisc', {dstAddr: 2, options: 0, radius: Constants.AF.DEFAULT_RADIUS})
+        expect(mockZnpRequest).toHaveBeenNthCalledWith(6, 4, "dataRequest", {"clusterid": 0, "data": frame.toBuffer(), "destendpoint": 20, "dstaddr": 2, "len": 5, "options": 0, "radius": 30, "srcendpoint": 1, "transid": 2}, 99)
         expect(error).toStrictEqual(new Error("Timeout - 2 - 20 - 100 - 0 - 1 after 1ms"));
     });