On Mon, Jun 25, 2012 at 5:58 PM, Sanne Grinovero <sanne(a)infinispan.org&gt; wrote: > > Hi all, > the testsuite on master is regularly hanging for me, and I get all > threads waiting while this one is spinning on the put() operation. > > java.lang.Thread.State: RUNNABLE >        at java.util.HashMap.put(HashMap.java:374) >        at org.testng.SuiteRunner.runTest(SuiteRunner.java:320) >        at org.testng.SuiteRunner.access$000(SuiteRunner.java:34) >        at org.testng.SuiteRunner$SuiteWorker.run(SuiteRunner.java:351) >        at > org.testng.internal.thread.ThreadUtil$CountDownLatchedRunnable.run(ThreadUtil.java:147) >        at > java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) >        at > java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) >        at java.lang.Thread.run(Thread.java:662) > > > Clearly the parallel testsuite is not synchronizing properly on the > HashMap, this looks like a TestNG bug. > > So I've tried to update to latest 6.5.2; from the Changelog this looks > like fixed, as is a very long list of other issues; not least > > "Fixed: Skipped tests were not always counted" > > which might address the strange numbers we had noticed on Jenkins. > Excellent! > > But I'm still unable to run the full testsuite; what follows are the > reasons from several different attempts: > > > testng-SyncBasicSingleLockOptimisticTest) Exiting because > lock.singlelock.SyncBasicSingleLockOptimisticTest has NOT shut down > all the cache managers it has started !!!!!!! > > testng-SyncBasicSingleLockOptimisticTest) Exiting because > lock.singlelock.SyncBasicSingleLockOptimisticTest has NOT shut down > all the cache managers it has started !!!!! > > (testng-BasicSingleLockOptimisticTest) Exiting because > lock.singlelock.BasicSingleLockOptimisticTest has NOT shut down all > the cache managers it has started !!!!!!! > > (testng-BasicSingleLockOptimisticTest) Exiting because > lock.singlelock.BasicSingleLockOptimisticTest has NOT shut down all > the cache managers it has started !!!!!!! > > (testng-SyncBasicSingleLockOptimisticTest) Exiting because > lock.singlelock.SyncBasicSingleLockOptimisticTest has NOT shut down > all the cache managers it has started !!!!!!! > > > Looking into the BasicSingleLockOptimisticTest I'm not seeing how this > could be possible, so I'm wondering if this could be a problem related > to the TestNG update? Any thoughts? > Galder and I saw the same thing with another test in Jenkins: https://issues.jboss.org/browse/ISPN-2117?focusedCommentId=12702926&p... To reiterate here, there was/is another concurrency issue in the maven-surefire-plugin that caused it to sometimes skip @AfterMethod methods after a failure. Galder upgraded the plugin to 2.12 hoping it would fix the problem, but if you're still seeing I guess that wasn't enough...

Cheers Dan _______________________________________________ infinispan-dev mailing list infinispan-dev(a)lists.jboss.org https://lists.jboss.org/mailman/listinfo/infinispan-dev

On Mon, Jun 25, 2012 at 10:48 PM, Sanne Grinovero <sanne(a)infinispan.org <mailto:sanne@infinispan.org>> wrote: On 25 June 2012 20:06, Dan Berindei <dan.berindei(a)gmail.com <mailto:dan.berindei@gmail.com>> wrote: > On Mon, Jun 25, 2012 at 5:58 PM, Sanne Grinovero <sanne(a)infinispan.org <mailto:sanne@infinispan.org>> > wrote: >> >> Hi all, >> the testsuite on master is regularly hanging for me, and I get all >> threads waiting while this one is spinning on the put() operation. >> >> java.lang.Thread.State: RUNNABLE >> at java.util.HashMap.put(HashMap.java:374) >> at org.testng.SuiteRunner.runTest(SuiteRunner.java:320) >> at org.testng.SuiteRunner.access$000(SuiteRunner.java:34) >> at org.testng.SuiteRunner$SuiteWorker.run(SuiteRunner.java:351) >> at >> org.testng.internal.thread.ThreadUtil$CountDownLatchedRunnable.run(ThreadUtil.java:147) >> at >> java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) >> at >> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) >> at java.lang.Thread.run(Thread.java:662) >> >> >> Clearly the parallel testsuite is not synchronizing properly on the >> HashMap, this looks like a TestNG bug. >> >> So I've tried to update to latest 6.5.2; from the Changelog this looks >> like fixed, as is a very long list of other issues; not least >> >> "Fixed: Skipped tests were not always counted" >> >> which might address the strange numbers we had noticed on Jenkins. >> > > Excellent! > > >> >> But I'm still unable to run the full testsuite; what follows are the >> reasons from several different attempts: >> >> >> testng-SyncBasicSingleLockOptimisticTest) Exiting because >> lock.singlelock.SyncBasicSingleLockOptimisticTest has NOT shut down >> all the cache managers it has started !!!!!!! >> >> testng-SyncBasicSingleLockOptimisticTest) Exiting because >> lock.singlelock.SyncBasicSingleLockOptimisticTest has NOT shut down >> all the cache managers it has started !!!!! >> >> (testng-BasicSingleLockOptimisticTest) Exiting because >> lock.singlelock.BasicSingleLockOptimisticTest has NOT shut down all >> the cache managers it has started !!!!!!! >> >> (testng-BasicSingleLockOptimisticTest) Exiting because >> lock.singlelock.BasicSingleLockOptimisticTest has NOT shut down all >> the cache managers it has started !!!!!!! >> >> (testng-SyncBasicSingleLockOptimisticTest) Exiting because >> lock.singlelock.SyncBasicSingleLockOptimisticTest has NOT shut down >> all the cache managers it has started !!!!!!! >> >> >> Looking into the BasicSingleLockOptimisticTest I'm not seeing how this >> could be possible, so I'm wondering if this could be a problem related >> to the TestNG update? Any thoughts? >> > > Galder and I saw the same thing with another test in Jenkins: > https://issues.jboss.org/browse/ISPN-2117?focusedCommentId=12702926&p... > > To reiterate here, there was/is another concurrency issue in the > maven-surefire-plugin that caused it to sometimes skip @AfterMethod methods > after a failure. Galder upgraded the plugin to 2.12 hoping it would fix the > problem, but if you're still seeing I guess that wasn't enough... Thanks Dan! Strange that this happens to me consistently on the same test.. do you know what is supposed to trigger this @AfterMethod failure? Is there a reference to the Surefire issue? I'm not sure why you can reproduce it so reliably, but it's probably related to the fact that this test always fails for you (and it doesn't fail for us). I didn't find any related issue in the surefire JIRA, if you can still reproduce it with maven-surefire-report-plugin 2.12 I'd say create a new issue yourself and paste the ConcurrentModificationException stack trace from your logs (or give it to me and I'll create the issue). I had a quick look at the 2.12 source code and it seems like the problem is still there: TestSetRunListener.writeTestOutput can still modify the list of lines in testStdOut after a failure (because our caches keep on running and logging stuff), and in parallel TestSetRunListener.testFailed will call TestSetRunListener.getAsString, which will iterate over testStdOut. Since there is no synchronization in either writeTestOutput or in getAsString, it's possible to get a ConcurrentModificationException there. Cheers Dan _______________________________________________ infinispan-dev mailing list infinispan-dev(a)lists.jboss.org https://lists.jboss.org/mailman/listinfo/infinispan-dev

On 26 June 2012 08:53, Adrian Nistor <anistor(a)redhat.com&gt; wrote: > Have you tried to disable console logging and log only to a file? That > 'cured' the ConcurrentModificationException for me. Strange suggestions, but it works.. :D Now I have Failed tests: testSTWithThirdWritingNonTxCache(org.infinispan.statetransfer.StateTransferFunctionalTest): Entry under key [test100] was [null] but expected [100] _______________________________________________ infinispan-dev mailing list infinispan-dev(a)lists.jboss.org https://lists.jboss.org/mailman/listinfo/infinispan-dev

On 26 June 2012 16:38, Adrian Nistor <anistor(a)redhat.com&gt; wrote: > Surefire-report plugin tries to capture the console output and holds it in a > List of text lines and later it willattach the captured text to the test > results report. The implementation is a bit clunky and if you have many > threads logging to the console you'll most likely encounter that pesky > ConcurrentModificationException. Disabling the console appender 'fixes' this > :) I trust you but didn't understand you. What console are you talking about? I disabled the CONSOLE appender from lo4j, how can Surefire know about the log4j configuration? > I'm thinking on fixing this properly and submitting a patch to Maven. That would be great! > Adrian > > > On 06/26/2012 05:41 PM, Sanne Grinovero wrote: >> On 26 June 2012 08:53, Adrian Nistor <anistor(a)redhat.com&gt; wrote: >>> Have you tried to disable console logging and log only to a file? That >>> 'cured' the ConcurrentModificationException for me. >> Strange suggestions, but it works.. :D >> >> Now I have >> >> Failed tests: >> >> testSTWithThirdWritingNonTxCache(org.infinispan.statetransfer.StateTransferFunctionalTest): >> Entry under key [test100] was [null] but expected [100] >> _______________________________________________ >> infinispan-dev mailing list >> infinispan-dev(a)lists.jboss.org >> https://lists.jboss.org/mailman/listinfo/infinispan-dev > >

On 26 June 2012 16:55, Adrian Nistor <anistor(a)redhat.com&gt; wrote: > It doesn't know or care about it. But by disabling log4j console appender > you minimize the amount of text written to console and the risk to trigger > the surefire-report bug. because it returns quicker?

Thanks Adrian, Is the log4j console appender being redirected by surefire? On 26 June 2012 21:21, Adrian Nistor <anistor(a)redhat.com&gt; wrote: > Hi Sanne, > > I know the explanation was a bit laconic so I'll try to expand it a bit. > surefire has a buffer (a List actually) were console output is > accumulated during each test. > The list is synchronized so multiple threads writing to console is not > causing List corruption. > There is a very sensitive moment though at the end of the test when this > List of text lines is consolidated into a StringBuffer that is added to > the test report. Unfortunately during consolidation the List is accessed > without proper synchronization and if some stray thread outlives the > test and continues to generate output or we run multiple tests > concurrently - this will most likely cause a > ConcurrentModificationException. Of course this problem is avoided if > you disable logging to console :). Actually not entirely avoided, but > minimized, because some tests also write to console directly using > System.out.println() and that can still trigger the issue. > > Adrian > > On 06/26/2012 07:33 PM, Sanne Grinovero wrote: >> On 26 June 2012 16:55, Adrian Nistor <anistor(a)redhat.com&gt; wrote: >>> It doesn't know or care about it. But by disabling log4j console appender >>> you minimize the amount of text written to console and the risk to trigger >>> the surefire-report bug. >> because it returns quicker? > > _______________________________________________ > infinispan-dev mailing list > infinispan-dev(a)lists.jboss.org > https://lists.jboss.org/mailman/listinfo/infinispan-dev _______________________________________________ infinispan-dev mailing list infinispan-dev(a)lists.jboss.org https://lists.jboss.org/mailman/listinfo/infinispan-dev

The entire System.out and System.err is redirected. I don't want to think what this means in the context of concurrent test execution... On 06/26/2012 11:32 PM, Sanne Grinovero wrote: > Thanks Adrian, > Is the log4j console appender being redirected by surefire? > > On 26 June 2012 21:21, Adrian Nistor <anistor(a)redhat.com&gt; wrote: >> Hi Sanne, >> >> I know the explanation was a bit laconic so I'll try to expand it a bit. >> surefire has a buffer (a List actually) were console output is >> accumulated during each test. >> The list is synchronized so multiple threads writing to console is not >> causing List corruption. >> There is a very sensitive moment though at the end of the test when this >> List of text lines is consolidated into a StringBuffer that is added to >> the test report. Unfortunately during consolidation the List is accessed >> without proper synchronization and if some stray thread outlives the >> test and continues to generate output or we run multiple tests >> concurrently - this will most likely cause a >> ConcurrentModificationException. Of course this problem is avoided if >> you disable logging to console :). Actually not entirely avoided, but >> minimized, because some tests also write to console directly using >> System.out.println() and that can still trigger the issue. >> >> Adrian >> >> On 06/26/2012 07:33 PM, Sanne Grinovero wrote: >>> On 26 June 2012 16:55, Adrian Nistor <anistor(a)redhat.com&gt; wrote: >>>> It doesn't know or care about it. But by disabling log4j console appender >>>> you minimize the amount of text written to console and the risk to trigger >>>> the surefire-report bug. >>> because it returns quicker? >> _______________________________________________ >> infinispan-dev mailing list >> infinispan-dev(a)lists.jboss.org >> https://lists.jboss.org/mailman/listinfo/infinispan-dev > _______________________________________________ > infinispan-dev mailing list > infinispan-dev(a)lists.jboss.org > https://lists.jboss.org/mailman/listinfo/infinispan-dev _______________________________________________ infinispan-dev mailing list infinispan-dev(a)lists.jboss.org https://lists.jboss.org/mailman/listinfo/infinispan-dev

On 27 June 2012 12:51, Adrian Nistor <anistor(a)redhat.com&gt; wrote: > I've just submitted the surefire ConcurrentModificationException issue > (http://jira.codehaus.org/browse/SUREFIRE-879) and also created a pull > request for the (trivial) fix. Let's hope they will be quick to handle > it. This has the potential of eliminating many of our random test failures. Awesome!

Yup. No iteration on elements here. Copying is done atomically because it is based on ArrayList's constructor which uses Collection.toArray() which is also atomic in this case because the passed in List happens to be wrapped by Collections.synchronizedList() in all usages. I tested this and it fixes the issue.

On 06/27/2012 03:13 PM, Sanne Grinovero wrote: > Are you sure that resolved the problem? > > When you wrap a list into a new ArrayList, it might still need to > iterate on it's elements, depending on which implementation of List is > being used. > > So that might indeed fix it but depends on the List implementation :-( > > On 27 June 2012 13:03, Sanne Grinovero <sanne(a)infinispan.org&gt; wrote: >> On 27 June 2012 12:51, Adrian Nistor <anistor(a)redhat.com&gt; wrote: >>> I've just submitted the surefire ConcurrentModificationException issue >>> (http://jira.codehaus.org/browse/SUREFIRE-879) and also created a pull >>> request for the (trivial) fix. Let's hope they will be quick to handle >>> it. This has the potential of eliminating many of our random test failures. >> Awesome! > _______________________________________________ > infinispan-dev mailing list > infinispan-dev(a)lists.jboss.org > https://lists.jboss.org/mailman/listinfo/infinispan-dev _______________________________________________ infinispan-dev mailing list infinispan-dev(a)lists.jboss.org https://lists.jboss.org/mailman/listinfo/infinispan-dev

I've just submitted the surefire ConcurrentModificationException issue (http://jira.codehaus.org/browse/SUREFIRE-879) and also created a pull request for the (trivial) fix. Let's hope they will be quick to handle it. This has the potential of eliminating many of our random test failures. On 06/26/2012 11:59 PM, Adrian Nistor wrote: > The entire System.out and System.err is redirected. I don't want to > think what this means in the context of concurrent test execution... > > On 06/26/2012 11:32 PM, Sanne Grinovero wrote: >> Thanks Adrian, >> Is the log4j console appender being redirected by surefire? >> >> On 26 June 2012 21:21, Adrian Nistor <anistor(a)redhat.com&gt; wrote: >>> Hi Sanne, >>> >>> I know the explanation was a bit laconic so I'll try to expand it a bit. >>> surefire has a buffer (a List actually) were console output is >>> accumulated during each test. >>> The list is synchronized so multiple threads writing to console is not >>> causing List corruption. >>> There is a very sensitive moment though at the end of the test when this >>> List of text lines is consolidated into a StringBuffer that is added to >>> the test report. Unfortunately during consolidation the List is accessed >>> without proper synchronization and if some stray thread outlives the >>> test and continues to generate output or we run multiple tests >>> concurrently - this will most likely cause a >>> ConcurrentModificationException. Of course this problem is avoided if >>> you disable logging to console :). Actually not entirely avoided, but >>> minimized, because some tests also write to console directly using >>> System.out.println() and that can still trigger the issue. >>> >>> Adrian >>> >>> On 06/26/2012 07:33 PM, Sanne Grinovero wrote: >>>> On 26 June 2012 16:55, Adrian Nistor <anistor(a)redhat.com&gt; wrote: >>>>> It doesn't know or care about it. But by disabling log4j console appender >>>>> you minimize the amount of text written to console and the risk to trigger >>>>> the surefire-report bug. >>>> because it returns quicker? >>> _______________________________________________ >>> infinispan-dev mailing list >>> infinispan-dev(a)lists.jboss.org >>> https://lists.jboss.org/mailman/listinfo/infinispan-dev >> _______________________________________________ >> infinispan-dev mailing list >> infinispan-dev(a)lists.jboss.org >> https://lists.jboss.org/mailman/listinfo/infinispan-dev > > _______________________________________________ > infinispan-dev mailing list > infinispan-dev(a)lists.jboss.org > https://lists.jboss.org/mailman/listinfo/infinispan-dev _______________________________________________ infinispan-dev mailing list infinispan-dev(a)lists.jboss.org https://lists.jboss.org/mailman/listinfo/infinispan-dev