From 9550f7a0c908743b8172587299255cec9fee881e Mon Sep 17 00:00:00 2001 From: slugzero Date: Thu, 8 Jun 2023 16:24:47 +0200 Subject: [PATCH] Attempt to send requests once even when queue is not empty --- src/controller/model/endpoint.ts | 10 +- test/controller.test.ts | 152 ++++++++++++++++++++++--------- 2 files changed, 113 insertions(+), 49 deletions(-) diff --git a/src/controller/model/endpoint.ts b/src/controller/model/endpoint.ts index c4b1f5f905..fa4989c07f 100644 --- a/src/controller/model/endpoint.ts +++ b/src/controller/model/endpoint.ts @@ -296,7 +296,7 @@ class Endpoint extends Entity { debug.info(`Request Queue (${this.deviceIeeeAddress}/${this.ID}): send success`); request.resolve(result); } catch (error) { - debug.error(`Request Queue (${this.deviceIeeeAddress}/${this.ID}): send failed, expires in ` + + debug.info(`Request Queue (${this.deviceIeeeAddress}/${this.ID}): send failed, expires in ` + `${(request.expires - now) / 1000} seconds`); request.reject(error); } @@ -393,16 +393,14 @@ class Endpoint extends Entity { } return request.send(); } - // If we already have something queued, we queue directly to avoid - // messing up the ordering too much. - // If a send is already in progress or if this is a bulk message, we also queue directly. - if (this.hasPendingRequests() || request.sendPolicy === 'bulk' || this.sendInProgress) { + // If this is a bulk message, we queue directly. + if (request.sendPolicy === 'bulk') { debug.info(logPrefix + `queue request (${this.pendingRequests.size} / ${this.sendInProgress})))`); return this.queueRequest(request); } try { - debug.info(logPrefix + `send request (queue empty)`); + debug.info(logPrefix + `send request`); return await request.send(); } catch(error) { // If we got a failed transaction, the device is likely sleeping. diff --git a/test/controller.test.ts b/test/controller.test.ts index a077208ea5..ce3d632e6b 100755 --- a/test/controller.test.ts +++ b/test/controller.test.ts @@ -4429,8 +4429,8 @@ describe('Controller', () => { // We need to send the data after it's been queued, but before we await // the promise. Hijacking queueRequest seems easiest. const origQueueRequest = endpoint.queueRequest; - endpoint.queueRequest = async (req, d) => { - const f = origQueueRequest.call(endpoint, req, d, 'active'); + endpoint.queueRequest = async (req) => { + const f = origQueueRequest.call(endpoint, req); const data = { wasBroadcast: false, @@ -4455,11 +4455,20 @@ describe('Controller', () => { const device = controller.getDeviceByIeeeAddr('0x129'); device.pendingRequestTimeout = 10000; const endpoint = device.getEndpoint(1); + // We need to wait for the data to be queued + const origQueueRequest = endpoint.queueRequest; + endpoint.queueRequest = async (req) => { + const f = origQueueRequest.call(endpoint, req); + jest.advanceTimersByTime(10); + return f; + }; endpoint.pendingRequests.add(new Request(async () => {}, [], 100)); mocksendZclFrameToEndpoint.mockClear(); - mocksendZclFrameToEndpoint.mockReturnValueOnce(null) + mocksendZclFrameToEndpoint.mockImplementationOnce(async () => {throw new Error('Dogs barking too hard');}); + mocksendZclFrameToEndpoint.mockReturnValueOnce(null); + const nextTick = new Promise (process.nextTick); const result = endpoint.write('genOnOff', {onOff: 1}, {disableResponse: true, sendWhen: 'active'}); - expect(mocksendZclFrameToEndpoint).toHaveBeenCalledTimes(0); + expect(mocksendZclFrameToEndpoint).toHaveBeenCalledTimes(1); const data = { wasBroadcast: false, @@ -4469,13 +4478,13 @@ describe('Controller', () => { linkquality: 50, groupID: 1, } - + await nextTick; await mockAdapterEvents['zclData'](data); await result; - expect(mocksendZclFrameToEndpoint).toHaveBeenCalledTimes(1); + expect(mocksendZclFrameToEndpoint).toHaveBeenCalledTimes(2); expect((await result)).toBe(undefined); await mockAdapterEvents['zclData'](data); - expect(mocksendZclFrameToEndpoint).toHaveBeenCalledTimes(1); + expect(mocksendZclFrameToEndpoint).toHaveBeenCalledTimes(2); }); it('Write with sendWhen active error', async () => { @@ -4484,11 +4493,20 @@ describe('Controller', () => { const device = controller.getDeviceByIeeeAddr('0x129'); device.pendingRequestTimeout = 10000; const endpoint = device.getEndpoint(1); + // We need to wait for the data to be queued + const origQueueRequest = endpoint.queueRequest; + endpoint.queueRequest = async (req) => { + const f = origQueueRequest.call(endpoint, req); + jest.advanceTimersByTime(10); + return f; + }; endpoint.pendingRequests.add(new Request(async () => {}, [], 100)); mocksendZclFrameToEndpoint.mockClear(); - mocksendZclFrameToEndpoint.mockImplementationOnce(async () => {throw new Error('Dogs barking too hard')}); + mocksendZclFrameToEndpoint.mockImplementation(async () => {throw new Error('Dogs barking too hard')}); + const nextTick = new Promise (process.nextTick); const result = endpoint.write('genOnOff', {onOff: 1}, {disableResponse: true, sendWhen: 'active'}); - expect(mocksendZclFrameToEndpoint).toHaveBeenCalledTimes(0); + await nextTick; + expect(mocksendZclFrameToEndpoint).toHaveBeenCalledTimes(1); let error = null; try { @@ -4505,7 +4523,7 @@ describe('Controller', () => { } catch (e) { error = e; } - expect(mocksendZclFrameToEndpoint).toHaveBeenCalledTimes(1); + expect(mocksendZclFrameToEndpoint).toHaveBeenCalledTimes(2); expect(error.message).toStrictEqual(`Write 0x129/1 genOnOff({"onOff":1}, {"sendWhen":"active","timeout":10000,"disableResponse":true,"disableRecovery":false,"disableDefaultResponse":true,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed (Dogs barking too hard)`); }); @@ -4515,11 +4533,28 @@ describe('Controller', () => { const device = controller.getDeviceByIeeeAddr('0x129'); device.pendingRequestTimeout = 10000; const endpoint = device.getEndpoint(1); + + // We need to wait for the data to be queued, but not for the promise to resolve + const origQueueRequest = endpoint.queueRequest; + endpoint.queueRequest = async (req) => { + const f = origQueueRequest.call(endpoint, req); + jest.advanceTimersByTime(10); + return f; + }; + //add a request with empty data and a ZclFrame to the queue endpoint.pendingRequests.add(new Request(async () => {}, [], 100)); // Queue content: // 1. empty request mocksendZclFrameToEndpoint.mockClear(); + mocksendZclFrameToEndpoint.mockImplementationOnce(async () => {throw new Error('Error one')}); + mocksendZclFrameToEndpoint.mockImplementationOnce(async () => {throw new Error('Error two')}); + mocksendZclFrameToEndpoint.mockImplementationOnce(async () => {throw new Error('Error three')}); + mocksendZclFrameToEndpoint.mockImplementationOnce(async () => {throw new Error('Error four')}); + mocksendZclFrameToEndpoint.mockImplementationOnce(async () => {throw new Error('Error five')}); + mocksendZclFrameToEndpoint.mockImplementationOnce(async () => {throw new Error('Error six')}); + mocksendZclFrameToEndpoint.mockImplementationOnce(async () => {throw new Error('Error seven')}); + mocksendZclFrameToEndpoint.mockImplementationOnce(async () => {throw new Error('Error eight')}); mocksendZclFrameToEndpoint.mockImplementationOnce(async () => {}); mocksendZclFrameToEndpoint.mockImplementationOnce(async () => {throw new Error('Dogs barking too hard')}); mocksendZclFrameToEndpoint.mockReturnValueOnce( {frame: {Payload: new Array( {"attrId": 1, "attrData": "one", "status": 0})}}); @@ -4528,43 +4563,48 @@ describe('Controller', () => { mocksendZclFrameToEndpoint.mockReturnValueOnce( {frame: {Payload: new Array( {"attrId": 4, "attrData": "four", "status": 0})}}); let result1, result2: Promise ; endpoint.write('genOnOff', {onOff: 0, startUpOnOff: 0}, {disableResponse: true, sendWhen: 'active'}); + await new Promise (process.nextTick); // Queue content: // 1. empty // 2. ZCL write 'genOnOff' {onOff: 0, startUpOnOff: 0} + expect(endpoint.pendingRequests.size).toStrictEqual (2); result1 = endpoint.write('genOnOff', {onOff: 0}, {disableResponse: true, sendWhen: 'active'}); + await new Promise (process.nextTick); // Queue content: // 1. empty // 2. ZCL write 'genOnOff' {startUpOnOff: 0} // 3. ZCL write 'genOnOff' {onOff: 0} --> result1 expect(endpoint.pendingRequests.size).toStrictEqual (3); - expect(mocksendZclFrameToEndpoint).toHaveBeenCalledTimes(0); + expect(mocksendZclFrameToEndpoint).toHaveBeenCalledTimes(2); //add another non-ZCL request, should go directly to queue without errors - endpoint.sendRequest(5, [], (d) => d+1); + const result6 = endpoint.sendRequest(5, [], (d) => {throw new Error(d+1);}); + await new Promise (process.nextTick); // Queue content: // 1. empty // 2. ZCL write 'genOnOff' {startUpOnOff: 0} // 3. ZCL write 'genOnOff' {onOff: 0} // 4. add 1 expect(endpoint.pendingRequests.size).toStrictEqual (4); - expect(mocksendZclFrameToEndpoint).toHaveBeenCalledTimes(0); + expect(mocksendZclFrameToEndpoint).toHaveBeenCalledTimes(2); let error = null; try { // Add the same ZCL request with different payload again, the first one should be rejected and removed from the queue result2 = endpoint.write('genOnOff', {onOff: 1}, {disableResponse: true, sendWhen: 'active'}); - await result1; + expect (await result1).rejects.toBe("asas"); + } catch (e) { + error = e; // Queue content: // 1. empty // 2. ZCL write 'genOnOff' {startUpOnOff: 0} // 3. add 1 // 4. ZCL write 'genOnOff' {onOff: 1} --> result2 expect(endpoint.pendingRequests.size).toStrictEqual (4); - } catch (e) { - error = e; } // Now add the same ZCL request with same payload again. The previous one should *not* be rejected but removed from the queue const result3 = endpoint.write('genOnOff', {onOff: 1}, {disableResponse: true, sendWhen: 'active'}); + await new Promise (process.nextTick); // Queue content: // 1. empty // 2. ZCL write 'genOnOff' {startUpOnOff: 0} @@ -4574,7 +4614,9 @@ describe('Controller', () => { // writeUndiv request should not be divided, so both should go to the queue endpoint.write('genOnOff', {onOff: 0, startUpOnOff: 0}, {disableResponse: true, sendWhen: 'active', writeUndiv: true}); + await new Promise (process.nextTick); endpoint.write('genOnOff', {startUpOnOff: 1}, {disableResponse: true, sendWhen: 'active', writeUndiv: true}); + await new Promise (process.nextTick); // Queue content: // 1. empty // 2. ZCL write 'genOnOff' {startUpOnOff: 0} @@ -4586,7 +4628,9 @@ describe('Controller', () => { // read requests should be combined to one const result4 = endpoint.read('genOnOff', ['onOff'], {disableResponse: false, sendWhen: 'active'}); + await new Promise (process.nextTick); const result5 = endpoint.read('genOnOff', ['onOff'], {disableResponse: false, sendWhen: 'active'}); + await new Promise (process.nextTick); // Queue content: // 1. empty // 2. ZCL write 'genOnOff' {startUpOnOff: 0} @@ -4594,8 +4638,9 @@ describe('Controller', () => { // 4. ZCL write 'genOnOff' {onOff: 1} --> result2, result3 // 5. ZCL writeUndiv 'genOnOff' {onOff: 0, startUpOnOff: 0} // 6. ZCL writeUndiv 'genOnOff' {startUpOnOff: 1} - // 7. ZCL read 'genOnOff' --> result4, result4 + // 7. ZCL read 'genOnOff' --> result4, result5 expect(endpoint.pendingRequests.size).toStrictEqual (7); + expect(mocksendZclFrameToEndpoint).toHaveBeenCalledTimes(8); try { // Implicit checkin, there are 5 ZclFrames and 2 other requests left in the queue: @@ -4608,22 +4653,25 @@ describe('Controller', () => { groupID: 1, }); - await result3; - expect (result3).rejects.toStrictEqual({"3": "yes"}); + await result6; } catch (e) { try { - await result2; - } catch(e) { - error = e; + await result3; + } catch (e) { + try { + await result2; + } catch(e) { + error = e; + } } } expect (result4).resolves.toStrictEqual({"3": "three"}); expect (result5).resolves.toStrictEqual({"3": "three"}); - expect(mocksendZclFrameToEndpoint).toHaveBeenCalledTimes(5); - expect(mocksendZclFrameToEndpoint.mock.calls[0][3].Payload).toStrictEqual ([{"attrData": 0, "attrId": 16387, "dataType": 48}]); - expect(mocksendZclFrameToEndpoint.mock.calls[1][3].Payload).toStrictEqual ([{"attrData": 1, "attrId": 0, "dataType": 16}]); - expect(mocksendZclFrameToEndpoint.mock.calls[2][3].Payload).toStrictEqual ([{"attrData": 0, "attrId": 0, "dataType": 16}, {"attrData": 0, "attrId": 16387, "dataType": 48}]); - expect(mocksendZclFrameToEndpoint.mock.calls[3][3].Payload).toStrictEqual ([{"attrData": 1, "attrId": 16387, "dataType": 48}]); + expect(mocksendZclFrameToEndpoint).toHaveBeenCalledTimes(13); + expect(mocksendZclFrameToEndpoint.mock.calls[8][3].Payload).toStrictEqual ([{"attrData": 0, "attrId": 16387, "dataType": 48}]); + expect(mocksendZclFrameToEndpoint.mock.calls[9][3].Payload).toStrictEqual ([{"attrData": 1, "attrId": 0, "dataType": 16}]); + expect(mocksendZclFrameToEndpoint.mock.calls[10][3].Payload).toStrictEqual ([{"attrData": 0, "attrId": 0, "dataType": 16}, {"attrData": 0, "attrId": 16387, "dataType": 48}]); + expect(mocksendZclFrameToEndpoint.mock.calls[11][3].Payload).toStrictEqual ([{"attrData": 1, "attrId": 16387, "dataType": 48}]); expect(error.message).toStrictEqual(`Write 0x129/1 genOnOff({"onOff":1}, {"sendWhen":"active","timeout":10000,"disableResponse":true,"disableRecovery":false,"disableDefaultResponse":true,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed (Write 0x129/1 genOnOff({"onOff":1}, {"sendWhen":"active","timeout":10000,"disableResponse":true,"disableRecovery":false,"disableDefaultResponse":true,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed (Dogs barking too hard))`); }); @@ -4641,13 +4689,11 @@ describe('Controller', () => { mocksendZclFrameToEndpoint.mockClear(); mocksendZclFrameToEndpoint.mockImplementationOnce(async () => { throw new Error('Dogs barking too hard');}); - endpoint.pendingRequests.add(new Request(async () => {}, [], 100)); - const result = endpoint.write('genOnOff', {onOff: 10}, {disableResponse: true, sendWhen: 'active'}); - expect(mocksendZclFrameToEndpoint).toHaveBeenCalledTimes(0); - - Date.now.mockReturnValue(1001000); - let error = null; - try { + // We need to send the data after it's been queued, but before we await + // the promise. Hijacking queueRequest seems easiest. + const origQueueRequest = endpoint.queueRequest; + endpoint.queueRequest = async (req) => { + const f = origQueueRequest.call(endpoint, req); await mockAdapterEvents['zclData']({ wasBroadcast: false, @@ -4658,11 +4704,21 @@ describe('Controller', () => { groupID: 1, }); + return f; + }; + + endpoint.pendingRequests.add(new Request(async () => {}, [], 100)); + const result = endpoint.write('genOnOff', {onOff: 10}, {disableResponse: true, sendWhen: 'active'}); + expect(mocksendZclFrameToEndpoint).toHaveBeenCalledTimes(1); + + Date.now.mockReturnValue(1001000); + let error = null; + try { await result; } catch (e) { error = e; } - expect(mocksendZclFrameToEndpoint).toHaveBeenCalledTimes(0); + expect(mocksendZclFrameToEndpoint).toHaveBeenCalledTimes(1); expect(endpoint.pendingRequests.size).toBe(0); Date.now.mockReturnValue(150); }); @@ -4673,13 +4729,22 @@ describe('Controller', () => { const device = controller.getDeviceByIeeeAddr('0x174'); await device.interview(); mocksendZclFrameToEndpoint.mockClear(); + mocksendZclFrameToEndpoint.mockImplementationOnce(() => {throw new Error("dogs barking too hard");}); const endpoint = device.getEndpoint(1); + const origQueueRequest = endpoint.queueRequest; + endpoint.queueRequest = async (req) => { + const f = origQueueRequest.call(endpoint, req); + jest.advanceTimersByTime(10); + return f; + }; endpoint.pendingRequests.add(new Request(async () => { await endpoint.sendPendingRequests(false);}, [], 100)); + const nextTick = new Promise (process.nextTick); const result = endpoint.write('genOnOff', {onOff: 10}, {disableResponse: true, sendWhen: 'active'}); + await nextTick; await endpoint.sendPendingRequests(false); await result; - expect(mocksendZclFrameToEndpoint).toHaveBeenCalledTimes(1); + expect(mocksendZclFrameToEndpoint).toHaveBeenCalledTimes(2); expect(endpoint.pendingRequests.size).toBe(0); }); @@ -4758,10 +4823,11 @@ describe('Controller', () => { const endpoint = device.getEndpoint(1); endpoint.pendingRequests.add(new Request(async () => {}, [], 100, 'fastpoll', undefined, undefined, () => {}, () => {})); mocksendZclFrameToEndpoint.mockClear(); + mocksendZclFrameToEndpoint.mockImplementationOnce(() => {throw new Error("dogs barking too hard");}); mocksendZclFrameToEndpoint.mockReturnValueOnce(null); const result = endpoint.write('genOnOff', {onOff: 1}, {disableResponse: true}); - expect(mocksendZclFrameToEndpoint).toHaveBeenCalledTimes(0); + expect(mocksendZclFrameToEndpoint).toHaveBeenCalledTimes(1); await mockAdapterEvents['zclData']({ wasBroadcast: false, @@ -4773,7 +4839,7 @@ describe('Controller', () => { }); - expect(mocksendZclFrameToEndpoint).toHaveBeenCalledTimes(0); + expect(mocksendZclFrameToEndpoint).toHaveBeenCalledTimes(1); await mockAdapterEvents['zclData']({ wasBroadcast: false, @@ -4784,9 +4850,9 @@ describe('Controller', () => { groupID: undefined, }); - expect(mocksendZclFrameToEndpoint).toHaveBeenCalledTimes(1); + expect(mocksendZclFrameToEndpoint).toHaveBeenCalledTimes(2); - const checkinrsp = mocksendZclFrameToEndpoint.mock.calls[0]; + const checkinrsp = mocksendZclFrameToEndpoint.mock.calls[1]; expect(checkinrsp[0]).toBe('0x174'); expect(checkinrsp[1]).toBe(174); expect(checkinrsp[2]).toBe(1); @@ -4796,13 +4862,13 @@ describe('Controller', () => { expect((await result)).toBe(undefined); - const cmd = mocksendZclFrameToEndpoint.mock.calls[1]; + const cmd = mocksendZclFrameToEndpoint.mock.calls[2]; expect(cmd[0]).toBe('0x174'); expect(cmd[1]).toBe(174); expect(cmd[2]).toBe(1); expect(cmd[3].Cluster.name).toBe('genOnOff'); - const fastpollstop = mocksendZclFrameToEndpoint.mock.calls[2]; + const fastpollstop = mocksendZclFrameToEndpoint.mock.calls[3]; expect(fastpollstop[0]).toBe('0x174'); expect(fastpollstop[1]).toBe(174); expect(fastpollstop[2]).toBe(1); @@ -4810,7 +4876,7 @@ describe('Controller', () => { expect(fastpollstop[3].Command.name).toBe('fastPollStop'); expect(fastpollstop[3].Payload).toStrictEqual({}); - expect(mocksendZclFrameToEndpoint).toHaveBeenCalledTimes(3); + expect(mocksendZclFrameToEndpoint).toHaveBeenCalledTimes(4); }); it('Handle retransmitted Xiaomi messages', async () => {