Frame parsing failure

[mikomarrache]

Hi,

I just got to this in the logs:

2020-09-24 13:35:35.489 TRACE 27528 --- [AshFrameHandler] c.z.z.d.e.internal.ash.AshFrameHandler   : ASH RX: 45
2020-09-24 13:35:35.489 TRACE 27528 --- [AshFrameHandler] c.z.z.d.e.internal.ash.AshFrameHandler   : ASH RX: 5D
2020-09-24 13:35:35.489 TRACE 27528 --- [AshFrameHandler] c.z.z.d.e.internal.ash.AshFrameHandler   : ASH RX: A1
2020-09-24 13:35:35.489 TRACE 27528 --- [AshFrameHandler] c.z.z.d.e.internal.ash.AshFrameHandler   : ASH RX: A9
2020-09-24 13:35:35.489 TRACE 27528 --- [AshFrameHandler] c.z.z.d.e.internal.ash.AshFrameHandler   : ASH RX: 54
2020-09-24 13:35:35.490 TRACE 27528 --- [AshFrameHandler] c.z.z.d.e.internal.ash.AshFrameHandler   : ASH RX: 2A
2020-09-24 13:35:35.490 TRACE 27528 --- [AshFrameHandler] c.z.z.d.e.internal.ash.AshFrameHandler   : ASH RX: 15
2020-09-24 13:35:35.490 TRACE 27528 --- [AshFrameHandler] c.z.z.d.e.internal.ash.AshFrameHandler   : ASH RX: DB
2020-09-24 13:35:35.490 TRACE 27528 --- [AshFrameHandler] c.z.z.d.e.internal.ash.AshFrameHandler   : ASH RX: D1
2020-09-24 13:35:35.490 TRACE 27528 --- [AshFrameHandler] c.z.z.d.e.internal.ash.AshFrameHandler   : ASH RX: 7E
2020-09-24 13:35:35.490 DEBUG 27528 --- [AshFrameHandler] c.z.z.d.e.internal.ash.AshFrameHandler   : <-- RX ASH frame: AshFrameData [frmNum=4, ackNum=5, reTx=false, data=1F 80 01 00 00 00]
2020-09-24 13:35:35.490 TRACE 27528 --- [AshFrameHandler] c.z.z.d.e.internal.ash.AshFrameHandler   : ASH: RX Timer took 74ms, timer now 400ms
2020-09-24 13:35:35.490 DEBUG 27528 --- [AshFrameHandler] c.z.z.d.e.internal.ash.AshFrameHandler   : ASH: Frame acked and removed AshFrameData [frmNum=4, ackNum=4, reTx=false, data=1F 00 01 53 00 01 FF 00]
2020-09-24 13:35:35.494 DEBUG 27528 --- [AshFrameHandler] c.z.zigbee.dongle.ember.ezsp.EzspFrame   : Error creating instance of EzspFrame
	
	java.lang.reflect.InvocationTargetException: null
		at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
		at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
		at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
		at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
		at com.zsmartsystems.zigbee.dongle.ember.ezsp.EzspFrame.createHandler(EzspFrame.java:473)
		at com.zsmartsystems.zigbee.dongle.ember.internal.ash.AshFrameHandler$1.run(AshFrameHandler.java:219)
	Caused by: java.lang.ArrayIndexOutOfBoundsException: 6
		at com.zsmartsystems.zigbee.dongle.ember.internal.serializer.EzspDeserializer.deserializeUInt8(EzspDeserializer.java:85)
		at com.zsmartsystems.zigbee.dongle.ember.ezsp.command.EzspVersionResponse.<init>(EzspVersionResponse.java:58)
		... 6 common frames omitted

2020-09-24 13:35:35.494 TRACE 27528 --- [AshFrameHandler] c.z.z.d.e.internal.ash.AshFrameHandler   : ASH RX EZSP: null
2020-09-24 13:35:35.494 DEBUG 27528 --- [AshFrameHandler] c.z.z.d.e.internal.ash.AshFrameHandler   : ASH: No frame handler created for AshFrameData [frmNum=4, ackNum=5, reTx=false, data=1F 80 01 00 00 00]
2020-09-24 13:35:35.494 DEBUG 27528 --- [AshFrameHandler] c.z.z.d.e.internal.ash.AshFrameHandler   : --> TX ASH frame: AshFrameAck [ackNum=5, notRdy=false]

For some reason, the library parses the received frame as an EzspVersionResponse (because the calculated frame ID is 0), therefore the exception thrown inside the constructor.

I'm not sure why yet but this seems to be related to EzspFrame.ezspVersion.

When the library starts, EzspFrame.ezspVersion = EZSP_MIN_VERSION (4). Then, the library sends an EzspVersionRequest (desired protocol version 4) and receives the protocol version from the NCP (8 in my case). Another EzspVersionRequest is sent with desired protocol version 8. EzspFrame.ezspVersion is now changed to 8. If the NCP is restarted (the application stays alive), the error happens.

In order to reprduce the issue easily, you can replace the following:

    /**
     * The current version of EZSP being used
     */
    protected static int ezspVersion = EZSP_MIN_VERSION;

by:

    /**
     * The current version of EZSP being used
     */
    protected static int ezspVersion = 8;

[cdjackson]

From a quick look, it seems that the response from the device is corrupt.

[cdjackson]

I confirm that this is a known bug in the NCP - I was discussing this with Silabs FAE a few weeks back.

[mikomarrache]

Thanks for your answer.

Is there a link to follow evolution of the issue?

Le jeu. 24 sept. 2020 à 20:27, Chris Jackson [email protected] a écrit :

I confirm that this is a known bug in the NCP - I was discussing this with Silabs FAE a few weeks back.

— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub https://github.com/zsmartsystems/com.zsmartsystems.zigbee/issues/1145#issuecomment-698481871, or unsubscribe https://github.com/notifications/unsubscribe-auth/ACAXKI5LXLJC36UQLIUYJGLSHN6QNANCNFSM4RYEMXHA .

[cdjackson]

No - I don't have a link. It was a private discussion with one of the FAEs which came up in a totally unrelated issue - he was just asking if I used the latest firmware and if I'd seen this issue. Maybe there is a discussion on their forum, although I've not seen anything. The impression I got from the discussion is it was not understood -:

[mikomarrache]

Which stack version are you using? If 6.7.6.0+, are you able to reproduce the issue?

[cdjackson]

I use a load of different stacks. I think issue only occurs with 6.8. As you can see in the email above, I was unable to reproduce it with the stack that has the problem.

[mikomarrache]

I confirm the issue exists with 6.7.6.0 and 6.7.7.0 as well.

I'm able to reproduce the issue by simply adding a static block:

static {
        EzspFrame.setEzspVersion(8);
}

Even when you start directly with version 8 instead of 4, you don't get the exception?

[cdjackson]

I would suggest that we close this - this doesn't seem to be a problem in the library - the frame returned from the NCP is incorrectly formatted, so there's going to be an error.

What do you think? Do you have any suggestion for improving the library response?

Even when you start directly with version 8 instead of 4, you don't get the exception?

Maybe this works around the problem, but it will clearly cause other problems since the system will then not be compatible with some versions of the EZSP.

[mikomarrache]

Indeed, it is a bug in the NCP code. Closing the ticket.

[mikomarrache]

We still observe this issue with version 6.7.8.0.

[cdjackson]

I'll reopen this - I have seen other reports (or logs) with this error, so I agree it still exists. I have personally never seen it and I'm not sure what is going on. Maybe the change in the NCP format is now the issue - I need to analyses this further.