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]

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.