{var%20f='http://v.t.sina.com.cn/share/share.php?appkey=1515056452',u=z||d.location,p=['&url=',e(u),'&title=',e(t||d.title),'&source=',e(r),'&sourceUrl=',e(l),'&content=',c||'gb2312','&pic=',e(p||'')].join('');function%20a(){if(!window.open([f,p].join(''),'mb',['toolbar=0,status=0,resizable=1,width=440,height=430,left=',(s.width-440)/2,',top=',(s.height-430)/2].join('')))u.href=[f,p].join('');};if(/Firefox/.test(navigator.userAgent))setTimeout(a,0);else%20a();})(screen,document,encodeURIComponent,'','','https://www.manongdao.com/data/attach/logo/logo.png', '推荐 成全新的幸福 的问题《Sonar analysis fails with SocketTimeoutException》','https://www.manongdao.com/q-1250549.html','页面编码gb2312|utf-8默认gb2312'));){kind=link}
I'm having sporadic failures due to a SocketTimeoutException when trying to run Sonar from ant.
Setup: I've got Sonar 4.0 running on a RHEL 6 box configured to run with Postgres 9.2. I do a nightly build of 175 projects using Jenkins 1.544. I've had Jenkins building the projects serially with a single executor on a slave machine but recently I've added a second slave via swarm so now I have two nodes (each with a single executor), building in parallel. I run sonar from ant using the sonar ant task and this largely works pretty well.
When I just had a single slave I would occasionally have a job fail with a SocketTimeoutException when trying to load the bootstrap properties. Now that I've added a second node this seems to be happening much more frequently. Interestingly I have also seen the same failure when I build a project on the command line using ant. This does not seem to be a server resource issue. I'm the sole user of the sonar server and I'm able to get this error without any real load on it.
Here's the stack trace I got when running from the command line this morning:
[exec] BUILD FAILED [exec] /var/lib/jenkins/sonar.buildfile:113: org.sonar.runner.impl.RunnerException: Unable to execute Sonar [exec] at org.sonar.runner.impl.BatchLauncher$1.delegateExecution(BatchLauncher.java:79) [exec] at org.sonar.runner.impl.BatchLauncher$1.run(BatchLauncher.java:63) [exec] at java.security.AccessController.doPrivileged(Native Method) [exec] at org.sonar.runner.impl.BatchLauncher.doExecute(BatchLauncher.java:57) [exec] at org.sonar.runner.impl.BatchLauncher.execute(BatchLauncher.java:50) [exec] at org.sonar.runner.api.EmbeddedRunner.doExecute(EmbeddedRunner.java:71) [exec] at org.sonar.runner.api.Runner.execute(Runner.java:89) [exec] at org.sonar.ant.SonarTask.launchAnalysis(SonarTask.java:53) [exec] at org.sonar.ant.SonarTask.execute(SonarTask.java:48) [exec] at org.apache.tools.ant.UnknownElement.execute(UnknownElement.java:291) [exec] at sun.reflect.GeneratedMethodAccessor4.invoke(Unknown Source) [exec] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [exec] at java.lang.reflect.Method.invoke(Method.java:601) [exec] at org.apache.tools.ant.dispatch.DispatchUtils.execute(DispatchUtils.java:106) [exec] at org.apache.tools.ant.Task.perform(Task.java:348) [exec] at org.apache.tools.ant.Target.execute(Target.java:392) [exec] at org.apache.tools.ant.Target.performTasks(Target.java:413) [exec] at org.apache.tools.ant.Project.executeSortedTargets(Project.java:1399) [exec] at org.apache.tools.ant.Project.executeTarget(Project.java:1368) [exec] at org.apache.tools.ant.helper.DefaultExecutor.executeTargets(DefaultExecutor.java:41) [exec] at org.apache.tools.ant.Project.executeTargets(Project.java:1251) [exec] at org.apache.tools.ant.Main.runBuild(Main.java:811) [exec] at org.apache.tools.ant.Main.startAnt(Main.java:217) [exec] at org.apache.tools.ant.launch.Launcher.run(Launcher.java:280) [exec] at org.apache.tools.ant.launch.Launcher.main(Launcher.java:109) [exec] Caused by: org.sonar.api.utils.SonarException: Unable to request: /batch_bootstrap/properties?dryRun=false [exec] at org.sonar.batch.bootstrap.ServerClient.request(ServerClient.java:92) [exec] at org.sonar.batch.bootstrap.ServerClient.request(ServerClient.java:82) [exec] at org.sonar.batch.bootstrap.ServerClient.request(ServerClient.java:78) [exec] at org.sonar.batch.bootstrap.BatchSettings.downloadSettings(BatchSettings.java:97) [exec] at org.sonar.batch.bootstrap.BatchSettings.init(BatchSettings.java:72) [exec] at org.sonar.batch.bootstrap.BatchSettings.<init>(BatchSettings.java:55) [exec] at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) [exec] at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57) [exec] at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) [exec] at java.lang.reflect.Constructor.newInstance(Constructor.java:525) [exec] at org.picocontainer.injectors.AbstractInjector.newInstance(AbstractInjector.java:145) [exec] at org.picocontainer.injectors.ConstructorInjector$1.run(ConstructorInjector.java:342) [exec] at org.picocontainer.injectors.AbstractInjector$ThreadLocalCyclicDependencyGuard.observe(AbstractInjector.java:270) [exec] at org.picocontainer.injectors.ConstructorInjector.getComponentInstance(ConstructorInjector.java:364) [exec] at org.picocontainer.injectors.AbstractInjectionFactory$LifecycleAdapter.getComponentInstance(AbstractInjectionFactory.java:56) [exec] at org.picocontainer.behaviors.AbstractBehavior.getComponentInstance(AbstractBehavior.java:64) [exec] at org.picocontainer.behaviors.Stored.getComponentInstance(Stored.java:91) [exec] at org.picocontainer.DefaultPicoContainer.getInstance(DefaultPicoContainer.java:698) [exec] at org.picocontainer.DefaultPicoContainer.getComponent(DefaultPicoContainer.java:646) [exec] at org.picocontainer.DefaultPicoContainer.getComponent(DefaultPicoContainer.java:631) [exec] at org.picocontainer.parameters.BasicComponentParameter$1.resolveInstance(BasicComponentParameter.java:118) [exec] at org.picocontainer.parameters.ComponentParameter$1.resolveInstance(ComponentParameter.java:136) [exec] at org.picocontainer.injectors.SingleMemberInjector.getParameter(SingleMemberInjector.java:78) [exec] at org.picocontainer.injectors.SingleMemberInjector.getMemberArguments(SingleMemberInjector.java:61) [exec] at org.picocontainer.injectors.MethodInjector.getMemberArguments(MethodInjector.java:100) [exec] at org.picocontainer.injectors.MethodInjector$2.run(MethodInjector.java:112) [exec] at org.picocontainer.injectors.AbstractInjector$ThreadLocalCyclicDependencyGuard.observe(AbstractInjector.java:270) [exec] at org.picocontainer.injectors.MethodInjector.decorateComponentInstance(MethodInjector.java:120) [exec] at org.picocontainer.injectors.CompositeInjector.decorateComponentInstance(CompositeInjector.java:58) [exec] at org.picocontainer.injectors.Reinjector.reinject(Reinjector.java:142) [exec] at org.picocontainer.injectors.ProviderAdapter.getComponentInstance(ProviderAdapter.java:96) [exec] at org.picocontainer.DefaultPicoContainer.getInstance(DefaultPicoContainer.java:698) [exec] at org.picocontainer.DefaultPicoContainer.getComponent(DefaultPicoContainer.java:646) [exec] at org.picocontainer.DefaultPicoContainer.getComponent(DefaultPicoContainer.java:631) [exec] at org.picocontainer.parameters.BasicComponentParameter$1.resolveInstance(BasicComponentParameter.java:118) [exec] at org.picocontainer.parameters.ComponentParameter$1.resolveInstance(ComponentParameter.java:136) [exec] at org.picocontainer.injectors.SingleMemberInjector.getParameter(SingleMemberInjector.java:78) [exec] at org.picocontainer.injectors.ConstructorInjector$CtorAndAdapters.getParameterArguments(ConstructorInjector.java:309) [exec] at org.picocontainer.injectors.ConstructorInjector$1.run(ConstructorInjector.java:335) [exec] at org.picocontainer.injectors.AbstractInjector$ThreadLocalCyclicDependencyGuard.observe(AbstractInjector.java:270) [exec] at org.picocontainer.injectors.ConstructorInjector.getComponentInstance(ConstructorInjector.java:364) [exec] at org.picocontainer.injectors.AbstractInjectionFactory$LifecycleAdapter.getComponentInstance(AbstractInjectionFactory.java:56) [exec] at org.picocontainer.behaviors.AbstractBehavior.getComponentInstance(AbstractBehavior.java:64) [exec] at org.picocontainer.behaviors.Stored.getComponentInstance(Stored.java:91) [exec] at org.picocontainer.DefaultPicoContainer.getInstance(DefaultPicoContainer.java:698) [exec] at org.picocontainer.DefaultPicoContainer.getComponent(DefaultPicoContainer.java:646) [exec] at org.picocontainer.DefaultPicoContainer.getComponent(DefaultPicoContainer.java:631) [exec] at org.picocontainer.parameters.BasicComponentParameter$1.resolveInstance(BasicComponentParameter.java:118) [exec] at org.picocontainer.parameters.ComponentParameter$1.resolveInstance(ComponentParameter.java:136) [exec] at org.picocontainer.injectors.SingleMemberInjector.getParameter(SingleMemberInjector.java:78) [exec] at org.picocontainer.injectors.ConstructorInjector$CtorAndAdapters.getParameterArguments(ConstructorInjector.java:309) [exec] at org.picocontainer.injectors.ConstructorInjector$1.run(ConstructorInjector.java:335) [exec] at org.picocontainer.injectors.AbstractInjector$ThreadLocalCyclicDependencyGuard.observe(AbstractInjector.java:270) [exec] at org.picocontainer.injectors.ConstructorInjector.getComponentInstance(ConstructorInjector.java:364) [exec] at org.picocontainer.injectors.AbstractInjectionFactory$LifecycleAdapter.getComponentInstance(AbstractInjectionFactory.java:56) [exec] at org.picocontainer.behaviors.AbstractBehavior.getComponentInstance(AbstractBehavior.java:64) [exec] at org.picocontainer.behaviors.Stored.getComponentInstance(Stored.java:91) [exec] at org.picocontainer.DefaultPicoContainer.instantiateComponentAsIsStartable(DefaultPicoContainer.java:1033) [exec] at org.picocontainer.DefaultPicoContainer.addAdapterIfStartable(DefaultPicoContainer.java:1025) [exec] at org.picocontainer.DefaultPicoContainer.startAdapters(DefaultPicoContainer.java:1002) [exec] at org.picocontainer.DefaultPicoContainer.start(DefaultPicoContainer.java:766) [exec] at org.sonar.api.platform.ComponentContainer.startComponents(ComponentContainer.java:91) [exec] at org.sonar.api.platform.ComponentContainer.execute(ComponentContainer.java:77) [exec] at org.sonar.batch.bootstrapper.Batch.startBatch(Batch.java:92) [exec] at org.sonar.batch.bootstrapper.Batch.execute(Batch.java:74) [exec] at org.sonar.runner.batch.IsolatedLauncher.execute(IsolatedLauncher.java:45) [exec] at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [exec] at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) [exec] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [exec] at java.lang.reflect.Method.invoke(Method.java:601) [exec] at org.sonar.runner.impl.BatchLauncher$1.delegateExecution(BatchLauncher.java:75) [exec] ... 24 more [exec] Caused by: java.net.SocketTimeoutException: Read timed out [exec] at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) [exec] at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57) [exec] at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) [exec] at java.lang.reflect.Constructor.newInstance(Constructor.java:525) [exec] at sun.net.www.protocol.http.HttpURLConnection$6.run(HttpURLConnection.java:1674) [exec] at sun.net.www.protocol.http.HttpURLConnection$6.run(HttpURLConnection.java:1672) [exec] at java.security.AccessController.doPrivileged(Native Method) [exec] at sun.net.www.protocol.http.HttpURLConnection.getChainedException(HttpURLConnection.java:1670) [exec] at sun.net.www.protocol.http.HttpURLConnection.getInputStream(HttpURLConnection.java:1243) [exec] at java.net.HttpURLConnection.getResponseCode(HttpURLConnection.java:468) [exec] at org.sonar.api.utils.HttpDownloader$BaseHttpDownloader$HttpInputSupplier.getInput(HttpDownloader.java:274) [exec] at org.sonar.api.utils.HttpDownloader$BaseHttpDownloader$HttpInputSupplier.getInput(HttpDownloader.java:235) [exec] at org.sonar.batch.bootstrap.ServerClient.request(ServerClient.java:88) [exec] ... 94 more [exec] Caused by: java.net.SocketTimeoutException: Read timed out [exec] at java.net.SocketInputStream.socketRead0(Native Method) [exec] at java.net.SocketInputStream.read(SocketInputStream.java:150) [exec] at java.net.SocketInputStream.read(SocketInputStream.java:121) [exec] at java.io.BufferedInputStream.fill(BufferedInputStream.java:235) [exec] at java.io.BufferedInputStream.read1(BufferedInputStream.java:275) [exec] at java.io.BufferedInputStream.read(BufferedInputStream.java:334) [exec] at sun.net.www.http.HttpClient.parseHTTPHeader(HttpClient.java:633) [exec] at sun.net.www.http.HttpClient.parseHTTP(HttpClient.java:579) [exec] at sun.net.www.protocol.http.HttpURLConnection.getInputStream(HttpURLConnection.java:1322) [exec] at sun.net.www.protocol.http.HttpURLConnection.getHeaderField(HttpURLConnection.java:2677) [exec] at java.net.URLConnection.getContentEncoding(URLConnection.java:533) [exec] at org.sonar.api.utils.HttpDownloader$BaseHttpDownloader$HttpInputSupplier.getInput(HttpDownloader.java:272) [exec] ... 96 more [exec] [exec] Total time: 23 seconds
I looked in the sonar access.log and can see the initial connection and redirect from the failure listed above:
172.20.2.172 - - [01/01/2014:09:45:25 -0500] "GET /api/server/version HTTP/1.1" 200 3 "-" "Ant/2.1" 172.20.2.172 - - [01/01/2014:09:45:26 -0500] "GET /batch_bootstrap/index HTTP/1.1" 302 125 "-" "Ant/2.1" 172.20.2.172 - - [01/01/2014:09:45:26 -0500] "GET /deploy/bootstrap/index.txt HTTP/1.1" 200 3899 "-" "Ant/2.1"
Interestingly I took a look at the log a bit later and it seems to show the failed connection 30 minutes after I had initiated the build:
172.20.2.172 - - [01/01/2014:09:45:25 -0500] "GET /api/server/version HTTP/1.1" 200 3 "-" "Ant/2.1" 172.20.2.172 - - [01/01/2014:09:45:26 -0500] "GET /batch_bootstrap/index HTTP/1.1" 302 125 "-" "Ant/2.1" 172.20.2.172 - - [01/01/2014:09:45:26 -0500] "GET /deploy/bootstrap/index.txt HTTP/1.1" 200 3899 "-" "Ant/2.1" 172.20.2.172 - - [01/01/2014:10:16:20 -0500] "GET /batch_bootstrap/properties?dryRun=false HTTP/1.1" 401 41 "-" "Sonar null/null"
Now I am using the LDAP plugin to authenticate sonar users against active directory and I've read that that could cause some slowness, possibly resulting in a timeout. I added ncsd but haven't noticed any improvement. I also upgraded to use sonar-ant-task-2.1.jar but didn't see a change. I'm able to access /batch_bootstrap/properties?dryRun=false from my browser, although sometimes it takes longer then others. If I rerun a failed job it almost always succeeds on the second attempt.
I'm not sure what to try next. I'd like to scale up the number of swarm nodes but I'm afraid that will just result in more failures. I don't like having to tell developers to ignore build failure emails. Due to the number of jobs, I'm able to run into this issue with regularity. If anyone has logging or configuration changes that they think would help avoid or isolate the issue I'm open to trying them.
Thanks - Sam
Update: I created a short script to fetch /batch_bootstrap/properties?dryRun=false and send the result to /dev/null using curl. I set a the curl --max-time to 2 seconds and put it on a cron to run every 2 minutes. Almost every request completes before the 2 second timeout (only 26 failures over 48 hours, all from 00:30 - 01:00 when I have some maintenance tasks running). Since I started pinging the server this way I haven't had any more builds fail due to a SocketTimeoutException. I don't really like this as a solution but it seems to be working for now. I'm still interested in alternatives if anyone has one to try.
Update: I was able to back off the frequency of the cron to instead only run every 5 minutes without seeing the problem. When I tried only running it ever 10 minutes I saw the SocketTimeoutException failure again. I also ran a general yum update for good measure but that apparently hasn't improved things.
Thanks - Sam
Update: this got progressively worse with Sonar 4.5 when elasticsearch was broken out as a separate process. In the sonar log file I had several of these failures:
2014.12.24 03:42:28 ERROR web[o.s.s.s.SearchClient] could not execute request: org.elasticsearch.action.get.GetRequestBuilder@48c9ec56
org.elasticsearch.client.transport.NoNodeAvailableException: No node available
I recorded the load over time and found that it was getting higher than I had expected during the nightly build cycle. Still I didn't see any other weird behavior other than the sonar failures. Some new hardware recently became available so I moved sonar onto a new box all by itself. Since doing that all I haven't seen any more build failures related to timeouts.
So if anyone sees similar, errors of this type would seem to indicate that you need to dedicate more resources.
Thanks - Sam