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

[leonschenk]

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

[cdjackson]

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.

[leonschenk]

[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: but was: 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]

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

[cdjackson]

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]

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?

[stale[bot]]

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.