Details

Description

Large reporting jobs, where Cobertura output is large (many files around 1MB, totaling 18MB), will have issues while copying "coverage.xml" files from slave machine to main Hudson server.

No error in logs on Slave machine, but we find the following error on the Hudson Server:

Oct 21, 2010 4:40:03 AM hudson.remoting.ProxyOutputStream$Chunk$1 run
WARNING: Failed to write to stream
java.io.IOException: Bad file descriptor
at java.io.FileOutputStream.writeBytes(Native Method)
at java.io.FileOutputStream.write(FileOutputStream.java:247)
at hudson.remoting.ProxyOutputStream$Chunk$1.run(ProxyOutputStream.java:185)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
at java.util.concurrent.FutureTask.run(FutureTask.java:138)
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:619)

The build actually fails then with following stack trace:

Publishing Cobertura coverage report...
Publishing Cobertura coverage results...
FATAL: Unable to parse /home/hudson/hudson/server_installation/jobs/projectname/builds/2010-10-21_03-00-32/coverage35.xml
hudson.util.IOException2: Cannot parse coverage results
at hudson.plugins.cobertura.CoberturaCoverageParser.parse(CoberturaCoverageParser.java:89)
at hudson.plugins.cobertura.CoberturaCoverageParser.parse(CoberturaCoverageParser.java:52)
at hudson.plugins.cobertura.CoberturaPublisher.perform(CoberturaPublisher.java:262)
at hudson.tasks.BuildStepMonitor$3.perform(BuildStepMonitor.java:36)
at hudson.model.AbstractBuild$AbstractRunner.perform(AbstractBuild.java:601)
at hudson.model.AbstractBuild$AbstractRunner.performAllBuildSteps(AbstractBuild.java:580)
at hudson.model.AbstractBuild$AbstractRunner.performAllBuildSteps(AbstractBuild.java:558)
at hudson.model.Build$RunnerImpl.post2(Build.java:157)
at hudson.model.AbstractBuild$AbstractRunner.post(AbstractBuild.java:528)
at hudson.model.Run.run(Run.java:1303)
at hudson.model.FreeStyleBuild.run(FreeStyleBuild.java:46)
at hudson.model.ResourceController.execute(ResourceController.java:88)
at hudson.model.Executor.run(Executor.java:139)
Caused by: org.xml.sax.SAXParseException: XML document structures must start and end within the same entity.
at com.sun.org.apache.xerces.internal.util.ErrorHandlerWrapper.createSAXParseException(ErrorHandlerWrapper.java:195)
at com.sun.org.apache.xerces.internal.util.ErrorHandlerWrapper.fatalError(ErrorHandlerWrapper.java:174)
at com.sun.org.apache.xerces.internal.impl.XMLErrorReporter.reportError(XMLErrorReporter.java:388)
at com.sun.org.apache.xerces.internal.impl.XMLScanner.reportFatalError(XMLScanner.java:1411)
at com.sun.org.apache.xerces.internal.impl.XMLDocumentFragmentScannerImpl.endEntity(XMLDocumentFragmentScannerImpl.java:902)
at com.sun.org.apache.xerces.internal.impl.XMLDocumentScannerImpl.endEntity(XMLDocumentScannerImpl.java:605)
at com.sun.org.apache.xerces.internal.impl.XMLEntityManager.endEntity(XMLEntityManager.java:1393)
at com.sun.org.apache.xerces.internal.impl.XMLEntityScanner.load(XMLEntityScanner.java:1763)
at com.sun.org.apache.xerces.internal.impl.XMLEntityScanner.skipSpaces(XMLEntityScanner.java:1492)
at com.sun.org.apache.xerces.internal.impl.XMLDocumentFragmentScannerImpl.scanAttribute(XMLDocumentFragmentScannerImpl.java:1520)
at com.sun.org.apache.xerces.internal.impl.XMLDocumentFragmentScannerImpl.scanStartElement(XMLDocumentFragmentScannerImpl.java:1316)
at com.sun.org.apache.xerces.internal.impl.XMLDocumentFragmentScannerImpl$FragmentContentDriver.next(XMLDocumentFragmentScannerImpl.java:2747)
at com.sun.org.apache.xerces.internal.impl.XMLDocumentScannerImpl.next(XMLDocumentScannerImpl.java:648)
at com.sun.org.apache.xerces.internal.impl.XMLDocumentFragmentScannerImpl.scanDocument(XMLDocumentFragmentScannerImpl.java:510)
at com.sun.org.apache.xerces.internal.parsers.XML11Configuration.parse(XML11Configuration.java:807)
at com.sun.org.apache.xerces.internal.parsers.XML11Configuration.parse(XML11Configuration.java:737)
at com.sun.org.apache.xerces.internal.parsers.XMLParser.parse(XMLParser.java:107)
at com.sun.org.apache.xerces.internal.parsers.AbstractSAXParser.parse(AbstractSAXParser.java:1205)
at com.sun.org.apache.xerces.internal.jaxp.SAXParserImpl$JAXPSAXParser.parse(SAXParserImpl.java:522)
at javax.xml.parsers.SAXParser.parse(SAXParser.java:395)
at javax.xml.parsers.SAXParser.parse(SAXParser.java:198)
at hudson.plugins.cobertura.CoberturaCoverageParser.parse(CoberturaCoverageParser.java:81)
... 12 more
Email was triggered for: Failure
Sending email for trigger: Failure
Sending email to: xx@xx.com
Finished: FAILURE

Looking at the file "coverage35.xml" on the Hudson server, we see that the size is 983040 bytes. However, in the slave workspace, this file is 1023819 bytes.

=> As the file size 983040 is a multiple of 64k, and the difference between the original and copied is less than 64k, it is tempting to say that the error must be caused by some buffering issue and/or lack of a output "flush"

terjestrand
added a comment - 21/Oct/10 12:51 PM Sorry, scratch that last comment. It cannot be a buffer issue, as of course, it is probably the final write that is failing with the IO exception mentioned.

"Bad file descriptor" indicates someone closing a file handle underneath the Java code that's using FileOutputStream. This is incorrect. If I FileOutputStream.close() before FileOutputStream.write() I get the same error. So this could be a simple ordering problem.

Kohsuke Kawaguchi
added a comment - 19/Nov/10 6:57 PM - edited"Bad file descriptor" indicates someone closing a file handle underneath the Java code that's using FileOutputStream. This is incorrect. If I FileOutputStream.close() before FileOutputStream.write() I get the same error. So this could be a simple ordering problem.
See http://256.com/gray/docs/misc/java_bad_file_descriptor_close_bug.shtml — which version of JDK are you using?

StevenTheAmusing
added a comment - 05/Jan/11 11:21 AM We are seeing this problem on our server as well. The workaround is to move all the affected jobs to make them run on the master. This is not a sustainable workaround for us, however.

And this just in: the logical volumes on our build machine were experiencing problems (half of the Raid pair was dead). Some or all of our problems may be related to this issue - but it is not clear why it would have affected Cobertura files only, and as described by the OP.

StevenTheAmusing
added a comment - 10/Jan/11 4:48 PM And this just in: the logical volumes on our build machine were experiencing problems (half of the Raid pair was dead). Some or all of our problems may be related to this issue - but it is not clear why it would have affected Cobertura files only, and as described by the OP.

I think we have the same problem when the changelog.xml is being copied from slave to master. It causes a big problem, because we use a groovy script to check the changelog to determine if subsequent builds should run or not.

Feb 8, 2011 7:39:43 AM hudson.remoting.ProxyOutputStream$Chunk$1 run
WARNING: Failed to write to stream
java.io.IOException: Bad file descriptor
at java.io.FileOutputStream.writeBytes(Native Method)
at java.io.FileOutputStream.write(FileOutputStream.java:247)
at hudson.remoting.ProxyOutputStream$Chunk$1.run(ProxyOutputStream.java:185)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441)
at hudson.remoting.ProxyOutputStream$Chunk$1.run(ProxyOutputStream.java:185)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
at java.util.concurrent.FutureTask.run(FutureTask.java:138)
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:619)
Feb 8, 2011 7:39:43 AM org.apache.commons.digester.Digester fatalError
SEVERE: Parse Fatal Error at line 1 column 1: Premature end of file.
org.xml.sax.SAXParseException: Premature end of file.
at com.sun.org.apache.xerces.internal.util.ErrorHandlerWrapper.createSAXParseException(ErrorHandlerWrapper.java:195)
at ...
...
at hudson.scm.CVSChangeLogSet.parse(CVSChangeLogSet.java:101)
at hudson.scm.CVSChangeLogParser.parse(CVSChangeLogParser.java:38)
at hudson.scm.CVSChangeLogParser.parse(CVSChangeLogParser.java:36)
at hudson.model.AbstractBuild.calcChangeSet(AbstractBuild.java:671)
at hudson.model.AbstractBuild.access$600(AbstractBuild.java:86)
at hudson.model.AbstractBuild$AbstractRunner.checkout(AbstractBuild.java:484)
at hudson.model.AbstractBuild$AbstractRunner.run(AbstractBuild.java:411)
at hudson.model.Run.run(Run.java:1324)
at hudson.model.FreeStyleBuild.run(FreeStyleBuild.java:46)
at hudson.model.ResourceController.execute(ResourceController.java:88)
at hudson.model.Executor.run(Executor.java:139)
hudson.util.IOException2: Failed to parse /home/nmsuser/.hudson/jobs/9_0_R3DEV_DEV/builds/2011-02-08_07-37-04/changelog.xml
at hudson.scm.CVSChangeLogSet.parse(CVSChangeLogSet.java:105)
at hudson.scm.CVSChangeLogParser.parse(CVSChangeLogParser.java:38)
at hudson.scm.CVSChangeLogParser.parse(CVSChangeLogParser.java:36)
at hudson.model.AbstractBuild.calcChangeSet(AbstractBuild.java:671)
at hudson.model.AbstractBuild.access$600(AbstractBuild.java:86)
at hudson.model.AbstractBuild$AbstractRunner.checkout(AbstractBuild.java:484)
at hudson.model.AbstractBuild$AbstractRunner.run(AbstractBuild.java:411)
at hudson.model.Run.run(Run.java:1324)
at hudson.model.FreeStyleBuild.run(FreeStyleBuild.java:46)
at hudson.model.ResourceController.execute(ResourceController.java:88)
at hudson.model.Executor.run(Executor.java:139)

Anne Sullivan
added a comment - 08/Feb/11 1:38 PM - edited I think we have the same problem when the changelog.xml is being copied from slave to master. It causes a big problem, because we use a groovy script to check the changelog to determine if subsequent builds should run or not.
Feb 8, 2011 7:39:43 AM hudson.remoting.ProxyOutputStream$Chunk$1 run
WARNING: Failed to write to stream
java.io.IOException: Bad file descriptor
at java.io.FileOutputStream.writeBytes(Native Method)
at java.io.FileOutputStream.write(FileOutputStream.java:247)
at hudson.remoting.ProxyOutputStream$Chunk$1.run(ProxyOutputStream.java:185)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441)
at hudson.remoting.ProxyOutputStream$Chunk$1.run(ProxyOutputStream.java:185)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
at java.util.concurrent.FutureTask.run(FutureTask.java:138)
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:619)
Feb 8, 2011 7:39:43 AM org.apache.commons.digester.Digester fatalError
SEVERE: Parse Fatal Error at line 1 column 1: Premature end of file.
org.xml.sax.SAXParseException: Premature end of file.
at com.sun.org.apache.xerces.internal.util.ErrorHandlerWrapper.createSAXParseException(ErrorHandlerWrapper.java:195)
at ...
...
at hudson.scm.CVSChangeLogSet.parse(CVSChangeLogSet.java:101)
at hudson.scm.CVSChangeLogParser.parse(CVSChangeLogParser.java:38)
at hudson.scm.CVSChangeLogParser.parse(CVSChangeLogParser.java:36)
at hudson.model.AbstractBuild.calcChangeSet(AbstractBuild.java:671)
at hudson.model.AbstractBuild.access$600(AbstractBuild.java:86)
at hudson.model.AbstractBuild$AbstractRunner.checkout(AbstractBuild.java:484)
at hudson.model.AbstractBuild$AbstractRunner.run(AbstractBuild.java:411)
at hudson.model.Run.run(Run.java:1324)
at hudson.model.FreeStyleBuild.run(FreeStyleBuild.java:46)
at hudson.model.ResourceController.execute(ResourceController.java:88)
at hudson.model.Executor.run(Executor.java:139)
hudson.util.IOException2: Failed to parse /home/nmsuser/.hudson/jobs/9_0_R3DEV_DEV/builds/2011-02-08_07-37-04/changelog.xml
at hudson.scm.CVSChangeLogSet.parse(CVSChangeLogSet.java:105)
at hudson.scm.CVSChangeLogParser.parse(CVSChangeLogParser.java:38)
at hudson.scm.CVSChangeLogParser.parse(CVSChangeLogParser.java:36)
at hudson.model.AbstractBuild.calcChangeSet(AbstractBuild.java:671)
at hudson.model.AbstractBuild.access$600(AbstractBuild.java:86)
at hudson.model.AbstractBuild$AbstractRunner.checkout(AbstractBuild.java:484)
at hudson.model.AbstractBuild$AbstractRunner.run(AbstractBuild.java:411)
at hudson.model.Run.run(Run.java:1324)
at hudson.model.FreeStyleBuild.run(FreeStyleBuild.java:46)
at hudson.model.ResourceController.execute(ResourceController.java:88)
at hudson.model.Executor.run(Executor.java:139)