[#QB-663] junit TEST-*.xml files are locked by QB2 buildagent process

QuickBuild

junit TEST-*.xml files are locked by QB2 buildagent process

Created: 06/Oct/10 12:33 PM Updated: 07/Dec/10 04:12 AM

Component/s:

None

Affects Version/s:

None

Fix Version/s:

3.1.11

Original Estimate:

Unknown

Remaining Estimate:

Unknown

Time Spent:

Unknown

File Attachments:

com.pmease.quickbuild.plugin.report.engine_2.1.21.jar (708 kb)

Image Attachments:

1. QB2StackScreenShot.jpg
(152 kb)

Environment:

« Hide

Quickbuild version: 2.1.48 - Wed Jul 28 11:55:51 CEST 2010
Windows (windows server 2008SP2)

Description

« Hide

During one step that is present in all our configuration (svn-clean, which deletes non-versioned files from the workspace), we get the following error on windows systems:

04:38:48,086 [clean-svn@lab18:8811] WARN - C:\qb2\workspace\trunk\all\integrationtests\osgi.integrationtest.test\report\TEST-com.dynatrace.diagnostics.integrationtest.memdump.rootPath.MemoryDumpRootPathTest$ComplexGraphRootPathInProcessCollectorTest.xml - The process cannot access the file because it is being used by another process.

svn-clean is a perl script, that triggers a "del" if svn status indicates a non-versioned file.

After adding some diagnostics functionality to this script to find out which process holds the handle to this files, we discovered that it is the QuickBuild Agent process. (to do this, we run sysinternals handle.exe in the case a file cannot be deleted. This shows the handles and the process id which holds the files open)
Since the svn-clean step is right at the beginning of each configuration, I suppose the files must be left open from a previously running configuration.

In many cases we have several builds that fail right behind each other because of this, and each of these builds show the same handle-ids and process ids of the files that are being held open by another process.
It has also been verified, that there are no 2 builds running in parallel on the same workspace, or other custom processes do so.

In our outer-most master step we configured simple logging to record start and stop times of builds. Using this log it could be shown, that the last build that was running without svn-clean problems finished successfully at 2010-10-04 13:27:10, without any problems or exceptions found in the respective logfile. The next build that was running on that same workspace failed in svn-clean at 2010-10-05 00:48:37.
Until 2010-10-06 00:25:06, all builds that ran against this workspace failed in svn-clean.
The next build, starting at 2010-10-06 00:25:08 was running successfully again, without any user interaction or whatsoever (after all, it was in the dead of night).
There are also no log entries that indicate any action regarding the files in question (or anything else).

Without doing further introspection, i would suppose this is a resource leak during junit-report generation.

Description

During one step that is present in all our configuration (svn-clean, which deletes non-versioned files from the workspace), we get the following error on windows systems: 04:38:48,086 [clean-svn@lab18:8811] WARN - C:\qb2\workspace\trunk\all\integrationtests\osgi.integrationtest.test\report\TEST-com.dynatrace.diagnostics.integrationtest.memdump.rootPath.MemoryDumpRootPathTest$ComplexGraphRootPathInProcessCollectorTest.xml - The process cannot access the file because it is being used by another process. svn-clean is a perl script, that triggers a "del" if svn status indicates a non-versioned file. After adding some diagnostics functionality to this script to find out which process holds the handle to this files, we discovered that it is the QuickBuild Agent process. (to do this, we run sysinternals handle.exe in the case a file cannot be deleted. This shows the handles and the process id which holds the files open) Since the svn-clean step is right at the beginning of each configuration, I suppose the files must be left open from a previously running configuration. In many cases we have several builds that fail right behind each other because of this, and each of these builds show the same handle-ids and process ids of the files that are being held open by another process. It has also been verified, that there are no 2 builds running in parallel on the same workspace, or other custom processes do so. In our outer-most master step we configured simple logging to record start and stop times of builds. Using this log it could be shown, that the last build that was running without svn-clean problems finished successfully at 2010-10-04 13:27:10, without any problems or exceptions found in the respective logfile. The next build that was running on that same workspace failed in svn-clean at 2010-10-05 00:48:37. Until 2010-10-06 00:25:06, all builds that ran against this workspace failed in svn-clean. The next build, starting at 2010-10-06 00:25:08 was running successfully again, without any user interaction or whatsoever (after all, it was in the dead of night). There are also no log entries that indicate any action regarding the files in question (or anything else). Without doing further introspection, i would suppose this is a resource leak during junit-report generation.

Show »

All

Comments

Work Log

Change History

Sort Order:

[ Permlink | « Hide ]

Robin Shen [06/Oct/10 01:08 PM]

Please send data backup of your QuickBuild instance to [robin AT pmease DOT com], as well as the build log containing the error. Please also tell which configuration is in trouble.

[ Permlink | « Hide ]

Robin Shen [06/Oct/10 01:24 PM]

Please also do another test if it is convenient for you: temporarily disable the JUnit report publish step by setting the step condition to "false" to see if the file is still locked by QuickBuild.

[ Permlink | « Hide ]

Ronald Brindl [08/Oct/10 09:30 AM]

I sent the qb2 database backup to [robin AT pmease DOT com].

I am sorry, since we are currently in release cycle, i cannot turn off junit report publishing now. Since this problem happens "sporadically", i would have to turn it of for quite a long time to be sure, it does not happen without junit report publishing.
Maybe we can do this after our current release is out. In the meantime, i will watch the the build logs, if this problem happens again.

[ Permlink | « Hide ]

Ronald Brindl [01/Dec/10 12:55 PM]

We did another intense analysis session.
During this session we instrumented the quickbuild Agents with our product, dynaTrace.
On one hand, we used it to generate memory dumps when this problem happens, but we also instrumented a selected set of methods within QuickbuildAgent.
Our product was configured to initiate GarbageCollections before it does a memdump. The interesting part was, that after gc, there where no FileInputStream Objects left, whereas before the gc, there where around 50 (in an idle QB Agent).

The analysis run afterwards showed the following:
During junit report generation, DefaultGenerator.generate() is called.
Further down the stack, XMLHelper.readXML() is called, which calls getEncoding(File file).
getEncoding creates a FileReader (and thus a FileInputStream), which is never closed in that method.
This is a resource leak.
The file handles get closed only when there is a gc and the FileInputStreams get collected. The finalize() method of FileInputStream does a close(), thus the handles are freed.

[ Permlink | « Hide ]

Steve Luo [01/Dec/10 01:15 PM]

WOW, what a great product - dynatrace, it is so cool.
Thank you for pointing out the problem, it will be fixed soon.

[ Permlink | « Hide ]

Ronald Brindl [06/Dec/10 03:44 PM]

Will there be a backport to QB2 ?
We cannot upgrade to QB3 within the next 2 months or so.
Thank you!

[ Permlink | « Hide ]

Steve Luo [07/Dec/10 04:12 AM]

A patch version 2.1.52 is created, or you can use the attached report engine plugin to replace the old one.