[logback-dev] unstable build

Harris, Carl ceharris at vt.edu
Tue Apr 16 20:48:31 CEST 2013 

Last couple of commits should help reduce timing sensitivity in the SocketConnectorBaseTest and SocketAppenderTest.  Anxious to hear if this improves matters for you Broc.

carl


On Apr 16, 2013, at 2:00 PM, Broc Seib wrote:

Here it is:


-------------------------------------------------------------------------------
Test set: ch.qos.logback.core.net.SocketConnectorBaseTest
-------------------------------------------------------------------------------
Tests run: 3, Failures: 1, Errors: 0, Skipped: 0, Time elapsed: 5.596 sec <<< FAILURE!
testConnect(ch.qos.logback.core.net.SocketConnectorBaseTest)  Time elapsed: 0.081 sec
testConnectEventually(ch.qos.logback.core.net.SocketConnectorBaseTest)  Time elapsed: 2.514 sec
testConnectionFails(ch.qos.logback.core.net.SocketConnectorBaseTest)  Time elapsed: 0.001 sec  <<< FAILURE!
java.lang.AssertionError
at org.junit.Assert.fail(Assert.java:92)
at org.junit.Assert.assertTrue(Assert.java:43)
at org.junit.Assert.assertFalse(Assert.java:68)
at org.junit.Assert.assertFalse(Assert.java:79)
at ch.qos.logback.core.net.SocketConnectorBaseTest.testConnectionFails(SocketConnectorBaseTest.java:89)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:601)
at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:45)
at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:15)
at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:42)
at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:20)
at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:28)
at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:30)
at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:263)
at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:68)
at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:47)
at org.junit.runners.ParentRunner$3.run(ParentRunner.java:231)
at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:60)
at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:229)
at org.junit.runners.ParentRunner.access$000(ParentRunner.java:50)
at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:222)
at org.junit.runners.ParentRunner.run(ParentRunner.java:300)
at org.junit.runners.Suite.runChild(Suite.java:128)
at org.junit.runners.Suite.runChild(Suite.java:24)
at org.junit.runners.ParentRunner$3.run(ParentRunner.java:231)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
at java.util.concurrent.FutureTask.run(FutureTask.java:166)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
at java.lang.Thread.run(Thread.java:722)





On Tue, Apr 16, 2013 at 1:56 PM, Harris, Carl <ceharris at vt.edu<mailto:ceharris at vt.edu>> wrote:
Broc,

Would you please send the surefire-report for the test ch.qos.logback.core.net.SocketConnectorBaseTest,
so I can take a look to see where/why it is failing?

logback-core/target/surefire-reports/ch.qos.logback.core.net.SocketConnectorBaseTest.txt

Thanks,

carl




On Apr 16, 2013, at 1:02 PM, Broc Seib wrote:

Hi Ceki,

I just updated to the latest code you just committed, 56e8ab2192697bc27a8cfbd8441db62aff53e87c but I think there is a different problem now.

bseib at BSEIB-WIN7 /c/gitrepo
$ rm -rf logback

bseib at BSEIB-WIN7 /c/gitrepo
$ git clone https://github.com/qos-ch/logback.git
Cloning into 'logback'...
remote: Counting objects: 52855, done.
remote: Compressing objects: 100% (13701/13701), done.
remote: Total 52855 (delta 26607), reused 52138 (delta 26038)
Receiving objects: 100% (52855/52855), 20.13 MiB | 1.17 MiB/s, done.
Resolving deltas: 100% (26607/26607), done.

bseib at BSEIB-WIN7 /c/gitrepo
$ cd logback/

bseib at BSEIB-WIN7 /c/gitrepo/logback (master)
$ git log -1
commit 56e8ab2192697bc27a8cfbd8441db62aff53e87c
Merge: 2ff61c7 513e380
Author: Ceki Gulcu <ceki at qos.ch<mailto:ceki at qos.ch><mailto:ceki at qos.ch<mailto:ceki at qos.ch>>>
Date:   Tue Apr 16 18:09:23 2013 +0200

    Merge branch 'master' of github.com:qos-ch/logback


And then 'mvn clean; mvn install':

[...]
Running ch.qos.logback.core.joran.conditional.IfThenElseAndIncludeCompositionTest
Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.635 sec
includeNestedWithinIf(ch.qos.logback.core.joran.conditional.IfThenElseAndIncludeCompositionTest)  Time elapsed: 0.635 sec

Results :

Failed tests:   testConnectionFails(ch.qos.logback.core.net.SocketConnectorBaseTest)
  lossyAppenderShouldOnlyLooseCertainEvents(ch.qos.logback.core.AsyncAppenderBaseTest): expected:<8> but was:<10>

Tests run: 424, Failures: 2, Errors: 0, Skipped: 6

[INFO] ------------------------------------------------------------------------
[INFO] Reactor Summary:
[INFO]
[INFO] Logback-Parent .................................... SUCCESS [0.244s]
[INFO] Logback Core Module ............................... FAILURE [27.251s]
[INFO] Logback Classic Module ............................ SKIPPED
[INFO] Logback Access Module ............................. SKIPPED
[INFO] Logback Site ...................................... SKIPPED
[INFO] Logback Examples Module ........................... SKIPPED
[INFO] ------------------------------------------------------------------------
[INFO] BUILD FAILURE
[INFO] ------------------------------------------------------------------------
[INFO] Total time: 28.014s
[INFO] Finished at: Tue Apr 16 12:51:50 EDT 2013
[INFO] Final Memory: 28M/308M
[INFO] ------------------------------------------------------------------------
[ERROR] Failed to execute goal org.apache.maven.plugins:maven-surefire-plugin:2.12.4:test (default-test) on project logback-core: There are test failures.






On Tue, Apr 16, 2013 at 12:42 PM, ceki <ceki at qos.ch<mailto:ceki at qos.ch><mailto:ceki at qos.ch<mailto:ceki at qos.ch>>> wrote:

I am hoping that commit [1] should make the test failures in logback-core/src/test/java/ch/qos/logback/core/rolling disappear.

[1] https://github.com/qos-ch/logback/commit/2ff61c7c1cb0562



On 16.04.2013 06:05, Broc Seib wrote:
Yes, I've done "mvn clean; mvn install" but still get a failure. I'm
also on a 3.4GHz Win7 box with a SSD. Is there any possibility of a
timing sensitivity for being "too fast"?


Tests run: 7, Failures: 0, Errors: 1, Skipped: 0, Time elapsed: 0.557
sec <<< FA
ILURE!
withZipCompression_FileSet_NoRestart_7(ch.qos.logback.core.rolling.SizeAndTimeBa
sedFNATP_Test)  Time elapsed: 0.201 sec
withGZCompression_FileBlank_NoRestart_6(ch.qos.logback.core.rolling.SizeAndTimeB
asedFNATP_Test)  Time elapsed: 0.006 sec  <<< ERROR!
java.io.FileNotFoundException:
target\test-output\910764289\test6-2013-04-15_23_
47_35-1.txt (The system cannot find the file specified)
         at java.io.FileInputStream.open(Native Method)
         at java.io.FileInputStream.<init>(FileInputStream.java:138)
         at
ch.qos.logback.core.testUtil.FileToBufferUtil.regularReadIntoList(Fil
eToBufferUtil.java:60)
         at
ch.qos.logback.core.testUtil.FileToBufferUtil.readIntoList(FileToBuff
erUtil.java:38)
         at
ch.qos.logback.core.rolling.ScaffoldingForRollingTests.fileContentChe
ck(ScaffoldingForRollingTests.java:84)
         at
ch.qos.logback.core.rolling.ScaffoldingForRollingTests.sortedContentC
heck(ScaffoldingForRollingTests.java:99)
         at
ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP_Test.generic(SizeAn
dTimeBasedFNATP_Test.java:130)
         at
ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP_Test.withGZCompress
ion_FileBlank_NoRestart_6(SizeAndTimeBasedFNATP_Test.java:189)
         at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
         at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.
java:57)
         at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAcces
sorImpl.java:43)
         at java.lang.reflect.Method.invoke(Method.java:601)
         at
org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(Framework
Method.java:45)
         at
org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCal
lable.java:15)
         at
org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMe
thod.java:42)
         at
org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMet
hod.java:20)
         at
org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.
java:28)
         at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:263)
         at
org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRun
ner.java:68)
         at
org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRun
ner.java:47)
         at org.junit.runners.ParentRunner$3.run(ParentRunner.java:231)
         at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:60)
         at
org.junit.runners.ParentRunner.runChildren(ParentRunner.java:229)
         at org.junit.runners.ParentRunner.access$000(ParentRunner.java:50)
         at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:222)
         at org.junit.runners.ParentRunner.run(ParentRunner.java:300)
         at org.junit.runners.Suite.runChild(Suite.java:128)
         at org.junit.runners.Suite.runChild(Suite.java:24)
         at org.junit.runners.ParentRunner$3.run(ParentRunner.java:231)
         at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:47
1)
         at
java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
         at java.util.concurrent.FutureTask.run(FutureTask.java:166)
         at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.
java:1110)
         at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor
.java:603)
         at java.lang.Thread.run(Thread.java:722)

withGZCompression_FileSet_NoRestart_5(ch.qos.logback.core.rolling.SizeAndTimeBas
edFNATP_Test)  Time elapsed: 0.067 sec
noCompression_FileSet_WithStopStart_4(ch.qos.logback.core.rolling.SizeAndTimeBas
edFNATP_Test)  Time elapsed: 0.102 sec
noCompression_FileBlank_WithStopStart_3(ch.qos.logback.core.rolling.SizeAndTimeB
asedFNATP_Test)  Time elapsed: 0.061 sec
noCompression_FileBlank_NoRestart_2(ch.qos.logback.core.rolling.SizeAndTimeBased
FNATP_Test)  Time elapsed: 0.036 sec
noCompression_FileSet_NoRestart_1(ch.qos.logback.core.rolling.SizeAndTimeBasedFN
ATP_Test)  Time elapsed: 0.039 sec
Running ch.qos.logback.core.recovery.ResilientOutputStreamTest
Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.288 sec
verifyRecuperationAfterFailure(ch.qos.logback.core.recovery.ResilientOutputStrea
mTest)  Time elapsed: 0.288 sec
Running ch.qos.logback.core.rolling.helper.CompressTest
Tests run: 3, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.253 sec
test2(ch.qos.logback.core.rolling.helper.CompressTest)  Time elapsed:
0.223 sec
test1(ch.qos.logback.core.rolling.helper.CompressTest)  Time elapsed:
0.018 sec
test3(ch.qos.logback.core.rolling.helper.CompressTest)  Time elapsed:
0.012 sec

Results :

Tests in error:

withGZCompression_FileBlank_NoRestart_6(ch.qos.logback.core.rolling.SizeAndTim
eBasedFNATP_Test):
target\test-output\910764289\test6-2013-04-15_23_47_35-1.txt
(The system cannot find the file specified)

Tests run: 424, Failures: 0, Errors: 1, Skipped: 6

[INFO]
------------------------------------------------------------------------
[INFO] Reactor Summary:
[INFO]
[INFO] Logback-Parent .................................... SUCCESS [0.338s]
[INFO] Logback Core Module ............................... FAILURE [28.279s]
[INFO] Logback Classic Module ............................ SKIPPED
[INFO] Logback Access Module ............................. SKIPPED
[INFO] Logback Site ...................................... SKIPPED
[INFO] Logback Examples Module ........................... SKIPPED
[INFO]
------------------------------------------------------------------------
[INFO] BUILD FAILURE
[INFO]
------------------------------------------------------------------------
[INFO] Total time: 29.140s
[INFO] Finished at: Mon Apr 15 23:47:54 EDT 2013
[INFO] Final Memory: 28M/241M
[INFO]
------------------------------------------------------------------------
[ERROR] Failed to execute goal
org.apache.maven.plugins:maven-surefire-plugin:2.
12.4:test (default-test) on project logback-core: There are test failures.



On Mon, Apr 15, 2013 at 2:47 PM, ceki <ceki at qos.ch<mailto:ceki at qos.ch><mailto:ceki at qos.ch<mailto:ceki at qos.ch>> <mailto:ceki at qos.ch<mailto:ceki at qos.ch><mailto:ceki at qos.ch<mailto:ceki at qos.ch>>>>

wrote:

    Hi Broc,

    No, it is not just you. Some of the logback test cases are time
    sensitive and fail from time to time, especially if the host machine
    is "slow". Making the build more robust is on our todo list.

    We now have jenkins running on such a slow machine. For example, on
    http://logback.qos.ch/jenkins/ build 24 was successful whereas build
    25 failed:

    http://logback.qos.ch/jenkins/__job/logback/24/
    <http://logback.qos.ch/jenkins/job/logback/24/>
    http://logback.qos.ch/jenkins/__job/logback/25/
    <http://logback.qos.ch/jenkins/job/logback/25/>

    So, at least it's easier to reproduce the fails.

    Anyway, have you tried relaunching the build with "mvn clean; mvn
    install" ?

    BTW, since about 10 days, the logback build no longer depends on
    Scala for testing. It should be now much easier to set up logback
    within your favorite IDE.



    On 15.04.2013 20:11, Broc Seib wrote:

        Do we have stable builds yet?

        I cloned a fresh copy of logback yesterday, and "mvn install" still
        failed for me. Is it just me?

        Broc


        On Thu, Apr 4, 2013 at 9:20 AM, Ceki Gülcü <ceki at qos.ch<mailto:ceki at qos.ch><mailto:ceki at qos.ch<mailto:ceki at qos.ch>>
        <mailto:ceki at qos.ch<mailto:ceki at qos.ch><mailto:ceki at qos.ch<mailto:ceki at qos.ch>>>
        <mailto:ceki at qos.ch<mailto:ceki at qos.ch><mailto:ceki at qos.ch<mailto:ceki at qos.ch>> <mailto:ceki at qos.ch<mailto:ceki at qos.ch><mailto:ceki at qos.ch<mailto:ceki at qos.ch>>>>> wrote:


             As shown on [1], the logback build on the Jenkins server on
             cloudbees is unstable.

             The failures are probably due to timeout issue. I'll work on

             ch.qos.logback.core.____FileAppenderResilienceTest.____smoke

        ch.qos.logback.core.recovery.____ResilientOutputStreamTest.____verifyRecuperationAfterFailure


        ch.qos.logback.core.spi.____AppenderAttachableImplLockTest____.detachAppenderBoom



             Carl, could you please have a look at

        ch.qos.logback.core.net<http://ch.qos.logback.core.net/><http://ch.qos.logback.core.net/> <http://ch.qos.logback.core.net<http://ch.qos.logback.core.net/><http://ch.qos.logback.core.net/>>
             <http://ch.qos.logback.core<http://ch.qos.logback.core/>.<http://ch.qos.logback.core./>__net
        <http://ch.qos.logback.core.net<http://ch.qos.logback.core.net/><http://ch.qos.logback.core.net/>>>.____SocketConnectorBaseTest.____testConnect

                ?

             You should be able to logon at

        https://grandcentral<https://grandcentral/>.<https://grandcentral./>__cloudbe__es.com/<http://cloudbe__es.com/><http://cloudbe__es.com/> <http://cloudbees.com/>


             <https://grandcentral<https://grandcentral/>.<https://grandcentral./>__cloudbees.com/<http://cloudbees.com/><http://cloudbees.com/>
        <https://grandcentral.cloudbees.com/>>

             click on JenkinsCI (top right) and launch builds
        interactively. (You
             need to click on the login link in Jenkins located on the
        top right
             corner).

             Cheers,

             --
             Ceki

             [1]
        https://logback.ci.cloudbees<https://logback.ci.cloudbees/>.<https://logback.ci.cloudbees./>____com/job/logback/12/__testReport/

        <https://logback.ci.cloudbees<https://logback.ci.cloudbees/>.<https://logback.ci.cloudbees./>__com/job/logback/12/testReport/
        <https://logback.ci.cloudbees.com/job/logback/12/testReport/>__>



    --
    Ceki
    65% of statistics are made up on the spot

    _________________________________________________
    logback-dev mailing list
    logback-dev at qos.ch<mailto:logback-dev at qos.ch><mailto:logback-dev at qos.ch<mailto:logback-dev at qos.ch>> <mailto:logback-dev at qos.ch<mailto:logback-dev at qos.ch><mailto:logback-dev at qos.ch<mailto:logback-dev at qos.ch>>>
    http://mailman.qos.ch/mailman/__listinfo/logback-dev
    <http://mailman.qos.ch/mailman/listinfo/logback-dev>





_______________________________________________
logback-dev mailing list
logback-dev at qos.ch<mailto:logback-dev at qos.ch><mailto:logback-dev at qos.ch<mailto:logback-dev at qos.ch>>
http://mailman.qos.ch/mailman/listinfo/logback-dev



--
Ceki
65% of statistics are made up on the spot
_______________________________________________
logback-dev mailing list
logback-dev at qos.ch<mailto:logback-dev at qos.ch><mailto:logback-dev at qos.ch<mailto:logback-dev at qos.ch>>
http://mailman.qos.ch/mailman/listinfo/logback-dev

_______________________________________________
logback-dev mailing list
logback-dev at qos.ch<mailto:logback-dev at qos.ch><mailto:logback-dev at qos.ch<mailto:logback-dev at qos.ch>>
http://mailman.qos.ch/mailman/listinfo/logback-dev

_______________________________________________
logback-dev mailing list
logback-dev at qos.ch<mailto:logback-dev at qos.ch>
http://mailman.qos.ch/mailman/listinfo/logback-dev

_______________________________________________
logback-dev mailing list
logback-dev at qos.ch<mailto:logback-dev at qos.ch>
http://mailman.qos.ch/mailman/listinfo/logback-dev

More information about the logback-dev mailing list