com.zsmartsystems.zigbee icon indicating copy to clipboard operation
com.zsmartsystems.zigbee copied to clipboard
verified publisher icon zsmartsystems

InitiateKeyEstablishmentRequestCommandSuccess(com.zsmartsystems.zigbee.app.seclient.ZclKeyEstablishmentServerTest) is unstable

Open leonschenk opened this issue 3 years ago • 6 comments

Describe the bug InitiateKeyEstablishmentRequestCommandSuccess(com.zsmartsystems.zigbee.app.seclient.ZclKeyEstablishmentServerTest) is failing sometimes.

To Reproduce mvn clean install (until the test fails)

Expected behavior All tests pass each time

Additional context I have not analyzed the issue

leonschenk avatar Nov 02 '22 21:11 leonschenk

I've just run this 30 times and it's not failed. Please can you at least provide some logs showing what the problem is.

cdjackson avatar Nov 02 '22 22:11 cdjackson

[INFO] Scanning for projects... [INFO] [INFO] ---------< com.zsmartsystems.zigbee:com.zsmartsystems.zigbee >---------- [INFO] Building com.zsmartsystems.zigbee 1.4.10-SNAPSHOT [INFO] --------------------------------[ jar ]--------------------------------- [INFO] [INFO] --- maven-clean-plugin:2.5:clean (default-clean) @ com.zsmartsystems.zigbee --- [INFO] Deleting E:\zsmarttest\com.zsmartsystems.zigbee\com.zsmartsystems.zigbee\target [INFO] [INFO] --- jacoco-maven-plugin:0.8.5:prepare-agent (jacoco-prepare-agent) @ com.zsmartsystems.zigbee --- [INFO] argLine set to -javaagent:C:\Users\leon_\.m2\repository\org\jacoco\org.jacoco.agent\0.8.5\org.jacoco.agent-0.8.5-runtime.jar=destfile=E:\zsmarttest\com.zsmartsystems.zigbee\com.zsmartsystems.zigbee\target\jacoco.exec [INFO] [INFO] --- maven-resources-plugin:2.6:resources (default-resources) @ com.zsmartsystems.zigbee --- [INFO] Using 'UTF-8' encoding to copy filtered resources. [INFO] skip non existing resourceDirectory E:\zsmarttest\com.zsmartsystems.zigbee\com.zsmartsystems.zigbee\src\main\resources [INFO] [INFO] --- maven-compiler-plugin:3.8.0:compile (default-compile) @ com.zsmartsystems.zigbee --- [INFO] Changes detected - recompiling the module! [INFO] Compiling 806 source files to E:\zsmarttest\com.zsmartsystems.zigbee\com.zsmartsystems.zigbee\target\classes [INFO] /E:/zsmarttest/com.zsmartsystems.zigbee/com.zsmartsystems.zigbee/src/main/java/com/zsmartsystems/zigbee/zcl/ZclFieldDeserializer.java: Some input files use or override a deprecated API. [INFO] /E:/zsmarttest/com.zsmartsystems.zigbee/com.zsmartsystems.zigbee/src/main/java/com/zsmartsystems/zigbee/zcl/ZclFieldDeserializer.java: Recompile with -Xlint:deprecation for details. [INFO] /E:/zsmarttest/com.zsmartsystems.zigbee/com.zsmartsystems.zigbee/src/main/java/com/zsmartsystems/zigbee/zcl/ZclFieldSerializer.java: Some input files use unchecked or unsafe operations. [INFO] /E:/zsmarttest/com.zsmartsystems.zigbee/com.zsmartsystems.zigbee/src/main/java/com/zsmartsystems/zigbee/zcl/ZclFieldSerializer.java: Recompile with -Xlint:unchecked for details. [INFO] [INFO] --- maven-bundle-plugin:3.5.0:manifest (bundle-manifest) @ com.zsmartsystems.zigbee --- [WARNING] Manifest com.zsmartsystems.zigbee:com.zsmartsystems.zigbee:jar:1.4.10-SNAPSHOT : Export com.zsmartsystems.zigbee, has 1, private references [com.zsmartsystems.zigbee.internal], [WARNING] Manifest com.zsmartsystems.zigbee:com.zsmartsystems.zigbee:jar:1.4.10-SNAPSHOT : Export com.zsmartsystems.zigbee.zcl, has 1, private references [com.zsmartsystems.zigbee.internal], [INFO] [INFO] --- maven-resources-plugin:2.6:testResources (default-testResources) @ com.zsmartsystems.zigbee --- [INFO] Using 'UTF-8' encoding to copy filtered resources. [INFO] skip non existing resourceDirectory E:\zsmarttest\com.zsmartsystems.zigbee\com.zsmartsystems.zigbee\src\test\resources [INFO] [INFO] --- maven-compiler-plugin:3.8.0:testCompile (default-testCompile) @ com.zsmartsystems.zigbee --- [INFO] Changes detected - recompiling the module! [INFO] Compiling 103 source files to E:\zsmarttest\com.zsmartsystems.zigbee\com.zsmartsystems.zigbee\target\test-classes [INFO] /E:/zsmarttest/com.zsmartsystems.zigbee/com.zsmartsystems.zigbee/src/test/java/com/zsmartsystems/zigbee/zcl/ZclClusterTest.java: Some input files use or override a deprecated API. [INFO] /E:/zsmarttest/com.zsmartsystems.zigbee/com.zsmartsystems.zigbee/src/test/java/com/zsmartsystems/zigbee/zcl/ZclClusterTest.java: Recompile with -Xlint:deprecation for details. [INFO] /E:/zsmarttest/com.zsmartsystems.zigbee/com.zsmartsystems.zigbee/src/test/java/com/zsmartsystems/zigbee/TestUtilities.java: Some input files use unchecked or unsafe operations. [INFO] /E:/zsmarttest/com.zsmartsystems.zigbee/com.zsmartsystems.zigbee/src/test/java/com/zsmartsystems/zigbee/TestUtilities.java: Recompile with -Xlint:unchecked for details. [INFO] [INFO] --- maven-surefire-plugin:2.12.4:test (default-test) @ com.zsmartsystems.zigbee --- [INFO] Surefire report directory: E:\zsmarttest\com.zsmartsystems.zigbee\com.zsmartsystems.zigbee\target\surefire-reports

T E S T S

Running com.zsmartsystems.zigbee.app.basic.ZigBeeBasicServerExtensionTest Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 2.416 sec Running com.zsmartsystems.zigbee.app.discovery.ZigBeeDiscoveryExtensionTest WARNING: An illegal reflective access operation has occurred WARNING: Illegal reflective access by com.zsmartsystems.zigbee.TestUtilities (file:/E:/zsmarttest/com.zsmartsystems.zigbee/com.zsmartsystems.zigbee/target/test-classes/) to field java.lang.reflect.Field.modifiers WARNING: Please consider reporting this to the maintainers of com.zsmartsystems.zigbee.TestUtilities WARNING: Use --illegal-access=warn to enable warnings of further illegal reflective access operations WARNING: All illegal access operations will be denied in a future release Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.844 sec Running com.zsmartsystems.zigbee.app.discovery.ZigBeeNetworkDiscovererTest Tests run: 5, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.312 sec Running com.zsmartsystems.zigbee.app.discovery.ZigBeeNodeServiceDiscovererTest Tests run: 4, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.346 sec Running com.zsmartsystems.zigbee.app.iasclient.ZclIasZoneClientTest Tests run: 5, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.338 sec Running com.zsmartsystems.zigbee.app.otaupgrade.ZclOtaUpgradeServerTest ZigBeeOtaServer [status=OTA_WAITING, cluster=Mock for ZclOtaUpgradeCluster, hashCode: 177104030, otaFile=Mock for ZigBeeOtaFile, hashCode: 2013461582] Tests run: 7, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 1.483 sec Running com.zsmartsystems.zigbee.app.otaupgrade.ZigBeeOtaFileTest ZigBeeOtaFile [headerVersion=256, manufacturerCode=4660, imageType=0006, fileVersion=12345678, stackVersion=ZIGBEE_PRO, headerString=A.String, imageSize=78] Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0 sec Running com.zsmartsystems.zigbee.app.otaupgrade.ZigBeeOtaUpgradeExtensionTest Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.141 sec Running com.zsmartsystems.zigbee.app.seclient.SmartEnergyClientTest --- networkStateUpdated --- MatchDescriptorResponse_DISCOVER_KEY_ESTABLISHMENT_CLUSTER --- keyEstablishmentCallback --- timer_DISCOVER_METERING_SERVERS MatchDescriptorRequest [null -> FFFD/0, cluster=0006, TID=--, nwkAddrOfInterest=FFFD, profileId=0109, inClusterList=[1794], outClusterList=[]] --- timer_PERFORM_KEY_ESTABLISHMENT --- timer_DISCOVER_KEY_ESTABLISHMENT_CLUSTER MatchDescriptorRequest [null -> 0000/0, cluster=0006, TID=--, nwkAddrOfInterest=0000, profileId=0109, inClusterList=[2048], outClusterList=[]] --- testStartupShutdown Tests run: 7, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.283 sec Running com.zsmartsystems.zigbee.app.seclient.ZclKeyEstablishmentClientTest --- HandleInitiateKeyEstablishmentResponseLongKey --- HandleTerminateKeyEstablishment --- HandleInitiateKeyEstablishmentResponseFraudulent --- InitiateKeyEstablishmentResponseInvalidIssuer --- HandleInitiateKeyEstablishmentResponseShortKey --- HandleInitiateKeyEstablishmentResponseInvalidSuite --- testStartShutdown Tests run: 7, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.11 sec Running com.zsmartsystems.zigbee.app.seclient.ZclKeyEstablishmentServerTest --- HandleTerminateKeyEstablishment --- InitiateKeyEstablishmentRequestCommandSuccess --- HandleConfirmKeyRequestBadKey --- HandleEphemeralDataRequestUninitialised --- InitiateKeyEstablishmentRequestCommandUnknownIssuer --- Success InitiateKeyEstablishmentResponse [Key Establishment: null -> null, cluster=0800, TID=--, requestedKeyEstablishmentSuite=1, ephemeralDataGenerateTime=44, confirmKeyGenerateTime=55, identity=ByteArray [value=02 00 CA A1 5B 4B EE DE 65 C3 13 9A 5C 3B C4 0C 9A D1 53 85 4A 27 00 22 A3 00 00 17 31 F3 54 45 53 54 53 45 43 41 01 09 10 83 01 23 45 67 89 0A]] EphemeralDataResponse [Key Establishment: null -> null, cluster=0800, TID=--, ephemeralData=ByteArray [value=02 00 CA A1 5B 4B EE DE 65]] ConfirmKeyResponse [Key Establishment: null -> null, cluster=0800, TID=--, secureMessageAuthenticationCode=ByteArray [value=02 00 CA A1 5B 4B EE DE 65]] --- HandleConfirmKeyRequestUninitialised Tests run: 7, Failures: 1, Errors: 0, Skipped: 0, Time elapsed: 0.141 sec <<< FAILURE! InitiateKeyEstablishmentRequestCommandSuccess(com.zsmartsystems.zigbee.app.seclient.ZclKeyEstablishmentServerTest) Time elapsed: 0.017 sec <<< FAILURE! java.lang.AssertionError: expected:<UNINITIALISED> but was:<FAILED> at org.junit.Assert.fail(Assert.java:89) at org.junit.Assert.failNotEquals(Assert.java:835) at org.junit.Assert.assertEquals(Assert.java:120) at org.junit.Assert.assertEquals(Assert.java:146) at com.zsmartsystems.zigbee.app.seclient.ZclKeyEstablishmentServerTest.InitiateKeyEstablishmentRequestCommandSuccess(ZclKeyEstablishmentServerTest.java:101) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.base/java.lang.reflect.Method.invoke(Method.java:566) at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:59) at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12) at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:56) at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17) at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306) at org.junit.runners.BlockJUnit4ClassRunner$1.evaluate(BlockJUnit4ClassRunner.java:100) at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:366) at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:103) at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:63) at org.junit.runners.ParentRunner$4.run(ParentRunner.java:331) at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:79) at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:329) at org.junit.runners.ParentRunner.access$100(ParentRunner.java:66) at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:293) at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306) at org.junit.runners.ParentRunner.run(ParentRunner.java:413) at org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:252) at org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:141) at org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:112) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.base/java.lang.reflect.Method.invoke(Method.java:566) at org.apache.maven.surefire.util.ReflectionUtils.invokeMethodWithArray(ReflectionUtils.java:189) at org.apache.maven.surefire.booter.ProviderFactory$ProviderProxy.invoke(ProviderFactory.java:165) at org.apache.maven.surefire.booter.ProviderFactory.invokeProvider(ProviderFactory.java:85) at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:115) at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:75)

leonschenk avatar Nov 02 '22 23:11 leonschenk

@cdjackson here you see the logging from mvn clean install > logfile.log. It fails approximately once per 4 build cycles. I build on windows.

leonschenk avatar Nov 02 '22 23:11 leonschenk

Thanks. I don't think I've ever seen this fail here and this code has been included in the library for a few years. It also hasn't ever failed with CI which runs on every PR and merge etc...

cdjackson avatar Nov 02 '22 23:11 cdjackson

It's also strange that the output from the error looks invalid -:

java.lang.AssertionError: expected: but was:

This can't be right since the line that reports to have a problem is this -:

        assertEquals(KeyEstablishmentState.UNINITIALISED,
                TestUtilities.getField(ZclKeyEstablishmentServer.class, keServer, "keyEstablishmentState"));

This shows that it is expected to be UNINITIALISED, so I don't know why the test output is printed as blank.

If I change this test so it will fail, you can see it prints out the expected and actual values -:

java.lang.AssertionError: expected:<COMPLETE> but was:<UNINITIALISED>
	at org.junit.Assert.fail(Assert.java:89)
	at org.junit.Assert.failNotEquals(Assert.java:835)
	at org.junit.Assert.assertEquals(Assert.java:120)
	at org.junit.Assert.assertEquals(Assert.java:146)
	at com.zsmartsystems.zigbee.app.seclient.ZclKeyEstablishmentServerTest.InitiateKeyEstablishmentRequestCommandSuccess(ZclKeyEstablishmentServerTest.java:101)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)

I've run just this test class loads more times and can't make it fail (other than if I change the expected result as above ;) ).

I wonder if there's something else going on with your environment given it seems to print invalid information. Maybe you can take a look at this if you get a chance?

cdjackson avatar Nov 02 '22 23:11 cdjackson

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

stale[bot] avatar Jan 08 '23 00:01 stale[bot]