[BGPCEP-814] BmpMockDispatcherTest Created: 18/Jul/18  Updated: 26/Jul/18  Resolved: 26/Jul/18

Status: Resolved
Project: bgpcep
Component/s: BMP
Affects Version/s: None
Fix Version/s: Fluorine

Type: Bug Priority: Medium
Reporter: Claudio David Gasparini Assignee: Matej Perina
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: Zip Archive bgpcep-logs-with-patch-74267.zip     Text File org.opendaylight.protocol.bmp.impl.app.BmpMonitorImplTest-output.txt     Text File test.txt    

 Description   

Console Logs:
https://logs.opendaylight.org/releng/vex-yul-odl-jenkins-1/autorelease-release-fluorine/149

Jenkins Build:
https://jenkins.opendaylight.org/releng/job/autorelease-release-fluorine/149/

 

01:58:17 testCreateClient(org.opendaylight.protocol.bmp.mock.BmpMockDispatcherTest)  Time elapsed: 31.072 sec  <<< FAILURE!01:58:17 java.lang.AssertionError*01:58:17*       at org.junit.Assert.fail(Assert.java:86)01:58:17       at org.junit.Assert.assertTrue(Assert.java:41)01:58:17       at org.junit.Assert.assertTrue(Assert.java:52)01:58:17       at org.opendaylight.protocol.bmp.mock.BmpMockDispatcherTest.lambda$testCreateClient$2(BmpMockDispatcherTest.java:78)01:58:17       at org.opendaylight.protocol.util.CheckUtil.checkEquals(CheckUtil.java:138)01:58:17       at org.opendaylight.protocol.util.CheckUtil.checkEquals(CheckUtil.java:130)01:58:17       at org.opendaylight.protocol.bmp.mock.BmpMockDispatcherTest.testCreateClient(BmpMockDispatcherTest.java:78)01:58:17       at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)01:58:17       at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)01:58:17       at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)01:58:17       at java.lang.reflect.Method.invoke(Method.java:498)01:58:17       at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:47)01:58:17       at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)01:58:17       at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:44)01:58:17       at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)01:58:17       at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)01:58:17       at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:271)01:58:17       at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:70)01:58:17       at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:50)01:58:17       at org.junit.runners.ParentRunner$3.run(ParentRunner.java:238)01:58:17       at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:63)01:58:17       at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:236)01:58:17       at org.junit.runners.ParentRunner.access$000(ParentRunner.java:53)01:58:17       at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:229)01:58:17       at org.junit.runners.ParentRunner.run(ParentRunner.java:309)01:58:17       at org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:283)01:58:17       at org.apache.maven.surefire.junit4.JUnit4Provider.executeWithRerun(JUnit4Provider.java:173)01:58:17       at org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:153)01:58:17       at org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:128)01:58:17       at org.apache.maven.surefire.booter.ForkedBooter.invokeProviderInSameClassLoader(ForkedBooter.java:203)01:58:17       at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:155)01:58:17       at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:103)

 Comments   
Comment by Matej Perina [ 18/Jul/18 ]

made hundred runs... all successfull... marking as false positive fail

test.txt

Comment by Claudio David Gasparini [ 18/Jul/18 ]

answer to email from community, you might need some test under sandbox, ask Adam what are his recommendations to go from here.

Comment by Matej Perina [ 19/Jul/18 ]

try to replicate in snadbox

Comment by Matej Perina [ 19/Jul/18 ]

bash command to run test hundred times from maven:

for i in {1..100}; do mvn test -pl :bgp-bmp-mock -Dtest=BmpMockDispatcherTest; done

Comment by Thanh Ha (zxiiro) [ 20/Jul/18 ]

I hit this issue in my own local build (see logs below). matej.perina I think testing against a single module run won't help you reproduce we really need to rebuild the entirety of bgpcep.

What additional logging can I grab for you to help troubleshoot?

[INFO] ------------------------------------------------------------------------
[INFO] Building bgp-bmp-impl 0.10.0-SNAPSHOT
[INFO] ------------------------------------------------------------------------
[INFO] 
[INFO] --- maven-clean-plugin:3.0.0:clean (default-clean) @ bgp-bmp-impl ---
[INFO] 
[INFO] --- maven-enforcer-plugin:3.0.0-M1:enforce (enforce-maven) @ bgp-bmp-impl ---
[INFO] 
[INFO] --- maven-enforcer-plugin:3.0.0-M1:enforce (enforce-banned-dependencies) @ bgp-bmp-impl ---
[INFO] 
[INFO] --- git-commit-id-plugin:2.2.4:revision (get-git-infos) @ bgp-bmp-impl ---
[INFO] 
[INFO] --- jacoco-maven-plugin:0.8.1:prepare-agent (pre-unit-test) @ bgp-bmp-impl ---
[INFO] argLine set to -javaagent:/tmp/r/org/jacoco/org.jacoco.agent/0.8.1/org.jacoco.agent-0.8.1-runtime.jar=destfile=/home/zxiiro/git/odl/bgpcep/bmp/bmp-impl/target/code-coverage/jacoco.exec,excludes=**/gen/**:**/generated-sources/**:**/generated-test-sources/**:**/yang-gen/**:**/yang-gen-config/**:**/yang-gen-sal/**:**/yang-gen-code/**:**/pax/**
[INFO] 
[INFO] --- maven-checkstyle-plugin:2.17:check (check-license) @ bgp-bmp-impl ---
[INFO] Starting audit...
Audit done.
[INFO] 
[INFO] --- maven-checkstyle-plugin:2.17:check (default) @ bgp-bmp-impl ---
[INFO] Starting audit...
Audit done.
[INFO] 
[INFO] >>> maven-pmd-plugin:3.8:cpd-check (cpd) > :cpd @ bgp-bmp-impl >>>
[INFO] 
[INFO] --- maven-pmd-plugin:3.8:cpd (cpd) @ bgp-bmp-impl ---
[INFO] 
[INFO] <<< maven-pmd-plugin:3.8:cpd-check (cpd) < :cpd @ bgp-bmp-impl <<<
[INFO] 
[INFO] 
[INFO] --- maven-pmd-plugin:3.8:cpd-check (cpd) @ bgp-bmp-impl ---
[INFO] 
[INFO] 
[INFO] --- maven-dependency-plugin:3.0.2:unpack (unpack-license) @ bgp-bmp-impl ---
[INFO] Configured Artifact: org.opendaylight.odlparent:odl-license:3.1.2:jar
[INFO] Unpacking /tmp/r/org/opendaylight/odlparent/odl-license/3.1.2/odl-license-3.1.2.jar to /home/zxiiro/git/odl/bgpcep/bmp/bmp-impl/target/classes with includes "" and excludes "META-INF/**"
[INFO] 
[INFO] --- maven-resources-plugin:3.0.1:resources (default-resources) @ bgp-bmp-impl ---
[INFO] Using 'UTF-8' encoding to copy filtered resources.
[INFO] Copying 1 resource
[INFO] 
[INFO] --- maven-compiler-plugin:3.7.0:compile (default-compile) @ bgp-bmp-impl ---
[INFO] Changes detected - recompiling the module!
[INFO] Compiling 21 source files to /home/zxiiro/git/odl/bgpcep/bmp/bmp-impl/target/classes
[INFO] /home/zxiiro/git/odl/bgpcep/bmp/bmp-impl/src/main/java/org/opendaylight/protocol/bmp/impl/config/BmpDeployerImpl.java: /home/zxiiro/git/odl/bgpcep/bmp/bmp-impl/src/main/java/org/opendaylight/protocol/bmp/impl/config/BmpDeployerImpl.java uses unchecked or unsafe operations.
[INFO] /home/zxiiro/git/odl/bgpcep/bmp/bmp-impl/src/main/java/org/opendaylight/protocol/bmp/impl/config/BmpDeployerImpl.java: Recompile with -Xlint:unchecked for details.
[INFO] 
[INFO] >>> findbugs-maven-plugin:3.0.5:check (analyze-compile) > :findbugs @ bgp-bmp-impl >>>
[INFO] 
[INFO] --- findbugs-maven-plugin:3.0.5:findbugs (findbugs) @ bgp-bmp-impl ---
[INFO] Fork Value is true
[INFO] Done FindBugs Analysis....
[INFO] 
[INFO] <<< findbugs-maven-plugin:3.0.5:check (analyze-compile) < :findbugs @ bgp-bmp-impl <<<
[INFO] 
[INFO] 
[INFO] --- findbugs-maven-plugin:3.0.5:check (analyze-compile) @ bgp-bmp-impl ---
[INFO] BugInstance size is 0
[INFO] Error size is 0
[INFO] No errors/warnings found
[INFO] 
[INFO] --- maven-remote-resources-plugin:1.5:process (default) @ bgp-bmp-impl ---
[INFO] 
[INFO] --- maven-resources-plugin:3.0.1:testResources (default-testResources) @ bgp-bmp-impl ---
[INFO] Using 'UTF-8' encoding to copy filtered resources.
[INFO] skip non existing resourceDirectory /home/zxiiro/git/odl/bgpcep/bmp/bmp-impl/src/test/resources
[INFO] Copying 1 resource
[INFO] 
[INFO] --- maven-compiler-plugin:3.7.0:testCompile (default-testCompile) @ bgp-bmp-impl ---
[INFO] Changes detected - recompiling the module!
[INFO] Compiling 4 source files to /home/zxiiro/git/odl/bgpcep/bmp/bmp-impl/target/test-classes
[INFO] 
[INFO] --- maven-antrun-plugin:1.8:run (move-autowire-test) @ bgp-bmp-impl ---
[INFO] Executing tasks

main:
     [echo] Moving autowire.xml to org/opendaylight/blueprint
[INFO] Executed tasks
[INFO] 
[INFO] --- maven-surefire-plugin:2.18.1:test (default-test) @ bgp-bmp-impl ---
[INFO] Surefire report directory: /home/zxiiro/git/odl/bgpcep/bmp/bmp-impl/target/surefire-reports

-------------------------------------------------------
 T E S T S
-------------------------------------------------------
Running org.opendaylight.protocol.bmp.impl.app.BmpMonitorImplTest
Tests run: 2, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 13.869 sec - in org.opendaylight.protocol.bmp.impl.app.BmpMonitorImplTest
Running org.opendaylight.protocol.bmp.impl.session.BmpDispatcherImplTest
Tests run: 1, Failures: 0, Errors: 1, Skipped: 0, Time elapsed: 1.245 sec <<< FAILURE! - in org.opendaylight.protocol.bmp.impl.session.BmpDispatcherImplTest
testCreateServer(org.opendaylight.protocol.bmp.impl.session.BmpDispatcherImplTest)  Time elapsed: 1.228 sec  <<< ERROR!
com.google.common.base.VerifyException
        at com.google.common.base.Verify.verify(Verify.java:99)
        at org.opendaylight.protocol.util.CheckUtil.waitFutureSuccess(CheckUtil.java:42)
        at org.opendaylight.protocol.bmp.impl.session.BmpDispatcherImplTest.testCreateServer(BmpDispatcherImplTest.java:90)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:47)
        at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
        at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:44)
        at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
        at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
        at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
        at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:271)
        at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:70)
        at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:50)
        at org.junit.runners.ParentRunner$3.run(ParentRunner.java:238)
        at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:63)
        at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:236)
        at org.junit.runners.ParentRunner.access$000(ParentRunner.java:53)
        at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:229)
        at org.junit.runners.ParentRunner.run(ParentRunner.java:309)
        at org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:283)
        at org.apache.maven.surefire.junit4.JUnit4Provider.executeWithRerun(JUnit4Provider.java:173)
        at org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:153)
        at org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:128)
        at org.apache.maven.surefire.booter.ForkedBooter.invokeProviderInSameClassLoader(ForkedBooter.java:203)
        at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:155)
        at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:103)

Running org.opendaylight.protocol.bmp.impl.session.BmpSessionImplTest
Tests run: 5, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.783 sec - in org.opendaylight.protocol.bmp.impl.session.BmpSessionImplTest

Results :

Tests in error: 
  BmpDispatcherImplTest.testCreateServer:90 » Verify

Tests run: 8, Failures: 0, Errors: 1, Skipped: 0
Comment by Thanh Ha (zxiiro) [ 20/Jul/18 ]

I wrote the following script to run bgpcep builds in an infinite loop and collect the stdout log on error. To use it "cd" to the bgpcep directory and run the script.

#!/bin/bash
logdir=/tmp/buildlogs
mkdir -p "$logdir"
while true; do
    rm -rf /tmp/r/org/opendaylight
    mvn clean install --show-version --batch-mode -Djenkins \
        -Dorg.slf4j.simpleLogger.log.org.apache.maven.cli.transfer.Slf4jMavenTransferListener=warn \
        -Dmaven.repo.local=/tmp/r \
        -Dorg.ops4j.pax.url.mvn.localRepository=/tmp/r \
        -P!karaf \
        -Pignore-lispflowmapping-integrationtest \
        -Dsft.heap.max=4g \
        -Dskip.karaf.featureTest=true | tee /tmp/log

    if grep 'BUILD FAILURE' /tmp/log; then
        logfile=$(mktemp --tmpdir="$logdir" --suffix=.log build-XXXXXXXX)
        logfile_name=$(basename $logfile)
        mv "/tmp/log" "$logfile"
        surefire_dir=$(grep '\[ERROR\] Please refer to' "$logfile" | awk '{print $5}')
        if [ ! -z "$surefire_dir" ]; then
            zip -jr "$logdir/${logfile_name}.zip" "$surefire_dir"
        fi
    fi
done
Comment by Thanh Ha (zxiiro) [ 20/Jul/18 ]

Just remembered mvn doesn't return an error code when it fails

I'll tweak the script.

Edit: Script updated to parse the logs.

Comment by Claudio David Gasparini [ 20/Jul/18 ]

Hi Thanh, thank you for your help.

I pushed a possible fix for this issue, could you please give it a try, and check if you are able to still reproduce the issue.

 

Thanks and regards,

Comment by Thanh Ha (zxiiro) [ 20/Jul/18 ]

Hi Claudio,

I've pulled down the patch and will run at in Rackspace as well as my 2 laptops continuously for the weekend and report back.

Regards,
Thanh

Comment by Thanh Ha (zxiiro) [ 21/Jul/18 ]

bgpcep-logs-with-patch-74267.zip

I wrote a writeup here https://lists.opendaylight.org/pipermail/bgpcep-dev/2018-July/001372.html but I'll repeat some of it here too.

I ran bgpcep builds with patch 74267 for 24 hrs on 3 different systems and found that I was only able to reproduce the issue on a 4 core system. It seems like running the tests on an 8 core machine does not reproduce the issue. I guess the moc tests in bgpcep may be heavily threaded and requires 8 cores to succeed?

The easy solution here would be throw more money and resources at the builder and bump autorelease builds to an 8 core machine but I do want to stress that back in Rackspace we used to use a 2 core machine to build autorelease and since moving to Vexxhost we bumped it up to 4 cores so already double what was originally available in the past.

Comment by Matej Perina [ 26/Jul/18 ]

I was finally able to reproduce the issue with the script. Meantime there was another patch from claudio and one more autorelease fail which uncovered problem with syncing server and client creation within test. After applying these two patches I wasn't able to replicate the issue again. 

 

https://git.opendaylight.org/gerrit/#/c/74272/

https://git.opendaylight.org/gerrit/#/c/74390/

Comment by Matej Perina [ 26/Jul/18 ]

https://git.opendaylight.org/gerrit/#/c/74272/

https://git.opendaylight.org/gerrit/#/c/74390/ 

 solves the issue

Generated at Wed Feb 07 19:14:11 UTC 2024 using Jira 8.20.10#820010-sha1:ace47f9899e9ee25d7157d59aa17ab06aee30d3d.