Details
-
Improvement
-
Resolution: Cannot Reproduce
-
Major
Description
We frequently have timeouts (ie taking more than 120 seconds):
-------------------------------------------------------
T E S T S
-------------------------------------------------------
Running org.xwiki.test.escaping.AllTests
18:13:32.108 [main] INFO o.x.test.integration.XWikiExecutor - Checking if an XWiki server is already started at [http://localhost:8080]
18:13:47.307 [main] INFO o.x.test.integration.XWikiExecutor - No server is responding on [http://localhost:8080/xwiki/bin/view/Main?xpage=plain] after [15] seconds
18:13:47.307 [main] INFO o.x.test.integration.XWikiExecutor - Starting XWiki server at [http://localhost:8080]
18:13:48.128 [main] INFO o.x.test.integration.XWikiExecutor - Checking that XWiki is up and running...
18:13:49.783 [Thread-1] INFO o.x.t.i.XWikiLogOutputStream - Starting Jetty on port 8080 ...
18:14:06.837 [Thread-2] ERROR o.x.t.i.XWikiLogOutputStream - 2012-12-20 18:14:06.836:INFO::jetty-7.4.5.v20110725
18:14:07.122 [Thread-2] ERROR o.x.t.i.XWikiLogOutputStream - 2012-12-20 18:14:07.121:INFO::Opened /home/hudsonagent/hudson_root/workspace/xwiki-enterprise-test-escaping-4.3/xwiki-enterprise-test/xwiki-enterprise-test-escaping/target/xwiki-enterprise-jetty-hsqldb-4.3-SNAPSHOT/data/logs/2012_12_20.request.log
18:14:07.126 [Thread-2] ERROR o.x.t.i.XWikiLogOutputStream - 2012-12-20 18:14:07.126:INFO::Deployment monitor /home/hudsonagent/hudson_root/workspace/xwiki-enterprise-test-escaping-4.3/xwiki-enterprise-test/xwiki-enterprise-test-escaping/target/xwiki-enterprise-jetty-hsqldb-4.3-SNAPSHOT/jetty/contexts at interval 1
18:14:07.297 [Thread-2] ERROR o.x.t.i.XWikiLogOutputStream - 2012-12-20 18:14:07.296:INFO::Deployable added: /home/hudsonagent/hudson_root/workspace/xwiki-enterprise-test-escaping-4.3/xwiki-enterprise-test/xwiki-enterprise-test-escaping/target/xwiki-enterprise-jetty-hsqldb-4.3-SNAPSHOT/jetty/contexts/root.xml
18:14:09.120 [Thread-2] ERROR o.x.t.i.XWikiLogOutputStream - 2012-12-20 18:14:09.120:INFO::NO JSP Support for /, did not find org.apache.jasper.servlet.JspServlet
18:14:11.739 [Thread-2] ERROR o.x.t.i.XWikiLogOutputStream - 2012-12-20 18:14:11.739:INFO::started o.e.j.w.WebAppContext{/,file:/home/hudsonagent/hudson_root/workspace/xwiki-enterprise-test-escaping-4.3/xwiki-enterprise-test/xwiki-enterprise-test-escaping/target/xwiki-enterprise-jetty-hsqldb-4.3-SNAPSHOT/webapps/root/},/home/hudsonagent/hudson_root/workspace/xwiki-enterprise-test-escaping-4.3/xwiki-enterprise-test/xwiki-enterprise-test-escaping/target/xwiki-enterprise-jetty-hsqldb-4.3-SNAPSHOT/jetty/../webapps/root
18:14:11.748 [Thread-2] ERROR o.x.t.i.XWikiLogOutputStream - 2012-12-20 18:14:11.748:INFO::Deployable added: /home/hudsonagent/hudson_root/workspace/xwiki-enterprise-test-escaping-4.3/xwiki-enterprise-test/xwiki-enterprise-test-escaping/target/xwiki-enterprise-jetty-hsqldb-4.3-SNAPSHOT/jetty/contexts/xwiki.xml
18:15:48.268 [main] INFO o.x.test.integration.XWikiExecutor - No server is responding on [http://localhost:8080/xwiki/bin/view/Main?xpage=plain] after [120] seconds
18:15:48.268 [main] INFO o.x.test.integration.XWikiExecutor - Failed to start XWiki in [120] seconds, last error code [-1], message []
Tests run: 1, Failures: 0, Errors: 1, Skipped: 0, Time elapsed: 155.923 sec <<< FAILURE!
org.xwiki.test.escaping.AllTests Time elapsed: 155922 sec <<< ERROR!
java.lang.RuntimeException: Failed to start XWiki in [120] seconds, last error code [-1], message []
at org.xwiki.test.integration.XWikiExecutor.waitForXWikiToLoad(XWikiExecutor.java:247)
at org.xwiki.test.integration.XWikiExecutor.start(XWikiExecutor.java:181)
at org.xwiki.test.escaping.framework.SingleXWikiExecutor.start(SingleXWikiExecutor.java:78)
at org.xwiki.test.escaping.AllTests.init(AllTests.java:55)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
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.RunBefores.evaluate(RunBefores.java:27)
at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:30)
at org.junit.runners.ParentRunner.run(ParentRunner.java:300)
at org.junit.extensions.cpsuite.ClasspathSuite.run(ClasspathSuite.java:194)
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 sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
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)
Here's a quick analysis:
[12/21/12 9:04:41 AM] Vincent Massol: Hi guys
[12/21/12 9:05:34 AM] Vincent Massol: we've noticed that Jetty has been starting very slowly on CI and I believe this could be caused by the move to the cloud since we didn't have it before. It seems the new machines may not have enough entropy for our needs according to http://docs.codehaus.org/display/JETTY/Connectors+slow+to+startup
[12/21/12 9:05:53 AM] Vincent Massol: Thus the start of xwiki now takes longer than 120 seconds in lots of cases
[12/21/12 9:06:04 AM] Vincent Massol: which leads to aborting of the test (we have a timeout at 120 seconds)
[12/21/12 9:06:22 AM] Vincent Massol: This message has been removed.
[12/21/12 9:07:28 AM] Vincent Massol: I'll set up some debugging options to ensure this is what is happening
[12/21/12 9:07:45 AM] Vincent Massol: (the link that led me to this conclusion: http://stackoverflow.com/questions/2398268/jetty-startup-delay )
[12/21/12 9:41:47 AM] Vincent Massol: ok so on agent1 and 6 the entroopy is low:
[12/21/12 9:41:48 AM] Vincent Massol: cat /proc/sys/kernel/random/entropy_avail
[12/21/12 9:42:08 AM] Vincent Massol: [hudsonagent@agent-6 ~]$ cat /proc/sys/kernel/random/entropy_avail
132[hudsonagent@agent-1 ~]$ cat /proc/sys/kernel/random/entropy_avail
149
[12/21/12 9:42:23 AM] Vincent Massol: and here (http://whatan00b.com/slow-apache-starts-on-ubuntu) it says:
[12/21/12 9:42:31 AM] Vincent Massol: "My system was returning a value somewhere around 150-200 and went down to nothing while Apache was generating its digtest. When I looked at the same file on other systems, they were all 2000+, an obvious problem."
[12/21/12 9:42:49 AM] Vincent Massol: 3853 on marius's machine
[12/21/12 9:44:15 AM] Marius Dumitru Florea: (ubuntu 12.10, x86_64)
[12/21/12 9:47:37 AM] Vincent Massol: at the bottom of http://www.raptorized.com/2006/08/11/apache-hangs-on-digest-secret-generation/ it says to use instead:
[12/21/12 9:47:41 AM] Vincent Massol: euse -i urandom
[12/21/12 9:47:46 AM] Vincent Massol: "This will make apache fetch randomness from /dev/urandom directly, therefore giving the same result as rng-tools. The proper solution would be to just re-emerge dev-libs/apr with the urandom use flag enabled."