Closed timja closed 14 years ago
due to JENKINS-5977 ?
I encountered the same problem with multiple jobs hanging while trying to archive. I was forced to revert to 1.377. I've attached my thread dump in case it helps.
I also have this issue after I upgrade to 1.378,
downgrade to 1.377,it works
Same here. We use windows slaves, but it also hangs on archiving artifacts with 1.378!
Downgrade helps.
I'm having the same issue after going to 1.378. It happened on both Linux and Windows slaves. I'm pretty sure I had it happen on the Master as well, though, which is Linux. I had to downgrade as well.
I think we're seeing something similar, though it's while collecting test results. Here's a stack dump of the slave:
Thread Dump
Channel reader thread: channel
"Channel reader thread: channel" Id=8 Group=main RUNNABLE (in native)
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(Unknown Source)
at java.io.FilterInputStream.read(Unknown Source)
at java.io.BufferedInputStream.fill(Unknown Source)
at java.io.BufferedInputStream.read(Unknown Source)
main
"main" Id=1 Group=main WAITING on hudson.remoting.Channel@14f8dab
at java.lang.Object.wait(Native Method)
Ping thread for channel hudson.remoting.Channel@14f8dab:channel
"Ping thread for channel hudson.remoting.Channel@14f8dab:channel" Id=9 Group=main TIMED_WAITING
at java.lang.Thread.sleep(Native Method)
at hudson.remoting.PingThread.run(PingThread.java:86)
Pipe writer thread: channel
"Pipe writer thread: channel" Id=11 Group=main WAITING on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@54f3b2
at sun.misc.Unsafe.park(Native Method)
pool-1-thread-1
"pool-1-thread-1" Id=10 Group=main RUNNABLE (in native)
at java.io.WinNTFileSystem.list(Native Method)
at java.io.File.list(Unknown Source)
at org.apache.tools.ant.DirectoryScanner.scandir(DirectoryScanner.java:1230)
at org.apache.tools.ant.DirectoryScanner.scandir(DirectoryScanner.java:1259)
at org.apache.tools.ant.DirectoryScanner.scandir(DirectoryScanner.java:1259)
at org.apache.tools.ant.DirectoryScanner.scandir(DirectoryScanner.java:1259)
at org.apache.tools.ant.DirectoryScanner.scandir(DirectoryScanner.java:1259)
at org.apache.tools.ant.DirectoryScanner.scandir(DirectoryScanner.java:1259)
at org.apache.tools.ant.DirectoryScanner.scandir(DirectoryScanner.java:1259)
at org.apache.tools.ant.DirectoryScanner.scandir(DirectoryScanner.java:1259)
at org.apache.tools.ant.DirectoryScanner.scandir(DirectoryScanner.java:1259)
at org.apache.tools.ant.DirectoryScanner.scandir(DirectoryScanner.java:1259)
at org.apache.tools.ant.DirectoryScanner.scandir(DirectoryScanner.java:1259)
at org.apache.tools.ant.DirectoryScanner.scandir(DirectoryScanner.java:1184)
at org.apache.tools.ant.DirectoryScanner.scandir(DirectoryScanner.java:1146)
at org.apache.tools.ant.DirectoryScanner.checkIncludePatterns(DirectoryScanner.java:928)
at org.apache.tools.ant.DirectoryScanner.scan(DirectoryScanner.java:882)
Number of locked synchronizers = 1
pool-1-thread-10
"pool-1-thread-10" Id=51 Group=main RUNNABLE
at sun.management.ThreadImpl.dumpThreads0(Native Method)
at sun.management.ThreadImpl.dumpAllThreads(Unknown Source)
at hudson.Functions.getThreadInfos(Functions.java:775)
at hudson.util.RemotingDiagnostics$GetThreadDump.call(RemotingDiagnostics.java:75)
at hudson.util.RemotingDiagnostics$GetThreadDump.call(RemotingDiagnostics.java:71)
at hudson.remoting.UserRequest.perform(UserRequest.java:114)
at hudson.remoting.UserRequest.perform(UserRequest.java:48)
at hudson.remoting.Request$2.run(Request.java:270)
at java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)
at java.util.concurrent.FutureTask$Sync.innerRun(Unknown Source)
at java.util.concurrent.FutureTask.run(Unknown Source)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(Unknown Source)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
at java.lang.Thread.run(Unknown Source)
Number of locked synchronizers = 1
Attach Listener
"Attach Listener" Id=4 Group=system RUNNABLE
Finalizer
"Finalizer" Id=3 Group=system WAITING on java.lang.ref.ReferenceQueue$Lock@14bff0a
at java.lang.Object.wait(Native Method)
Reference Handler
"Reference Handler" Id=2 Group=system WAITING on java.lang.ref.Reference$Lock@5506e9
at java.lang.Object.wait(Native Method)
I had similar situation with cygwin slaves on 1.378. Had to stop archive, causing the following error
Archiving artifacts
ERROR: Failed to archive artifacts: CD_STAGE/* hudson.util.IOException2: Failed to extract D:/soft/cygwin/tmp/hudson/workspace/SPOTS_V14M_BASE-Windows_lv1-LATEST/CD_STAGE/* at hudson.FilePath.readFromTar(FilePath.java:1577) at hudson.FilePath.copyRecursiveTo(FilePath.java:1491) at hudson.tasks.ArtifactArchiver.perform(ArtifactArchiver.java:117) at hudson.tasks.BuildStepMonitor$1.perform(BuildStepMonitor.java:19) 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:137) Caused by: java.io.IOException at hudson.remoting.FastPipedInputStream.read(FastPipedInputStream.java:173) at hudson.util.HeadBufferingStream.read(HeadBufferingStream.java:61) at java.util.zip.InflaterInputStream.fill(InflaterInputStream.java:221) at java.util.zip.InflaterInputStream.read(InflaterInputStream.java:141) at java.util.zip.GZIPInputStream.read(GZIPInputStream.java:92) at org.apache.tools.tar.TarBuffer.readBlock(TarBuffer.java:257) at org.apache.tools.tar.TarBuffer.readRecord(TarBuffer.java:223) at hudson.org.apache.tools.tar.TarInputStream.read(TarInputStream.java:345) at java.io.FilterInputStream.read(FilterInputStream.java:90) at org.apache.commons.io.IOUtils.copyLarge(IOUtils.java:1025) at org.apache.commons.io.IOUtils.copy(IOUtils.java:999) at hudson.util.IOUtils.copy(IOUtils.java:33) at hudson.FilePath.readFromTar(FilePath.java:1565) ... 12 more
I confirm that the issue appears in 1.378 and disappears when downgrading to 1.377
rsteele, your issue in the test report collection appears to be of a completely different nature. In your thread dump, there's nothing hanging either. I suspect you have a fairly broad file mask that's causing a deep directory traversal.
Please see http://wiki.jenkins-ci.org/display/JENKINS/Build+is+hanging and report your thread dump, both on the master and the slave. Also tell us the name of the slave your build was running, so that we know where to focus on.
Does this reproduce consistently all the time?
FYI, I reproduced this trivially - I set up a new instance of 1.378, with an SSH slave on another computer. I then set up a job running on that slave - the job did nothing but download a large file (40mb or so), and then attempt to archive it. This hangs. The master and slave are both Linux boxes.
gj:
Happens to me on the master, with no slaves configured.
(well, originally, there were some, I removed them just to be sure)
Will post a thread dump next time this happens.
(Linux 2.6.26-2-amd64 #1 SMP Sun Jun 20 20:16:30 UTC 2010 x86_64 GNU/Linux)
This reproduces 100% or close to 100% for a large multimodule build I run at work (~300-400 MB of artifacts).
I have created a test case which reproduces less reliably but reproduces nonetheless. I checked the attached pom into a local git repo and setup a job to run it every minute. I got a hang after about 30 builds. This pom just jars up two copies of hudson-war-1.378.war to create a 59 MB artifact.
Attaching thread dump from where my simple pom reproduced the problem.
kohsuke: you're right, the pattern is very broad (and our workspace is very large), and maybe I just didn't let it run long enough (I waited 15 minutes before killing the job--and then I had to get things working again) but there must be a performance change then: the symptoms went away when I downgraded...
I'm still failing to reproduce the problem here.
For those who can reproduce this easily, please let me know how you launch your slave.
I use Linux on both nodes with the ssh slaves plugin. I have seen this hang on master and slaves with larger, real world jobs. I've only reproduced on the slave with my test case. I will run the master node for a while to see what happens.
I haven't been able to reproduce the issue on the master node with my test case.
Code changed in hudson
User: : kohsuke
Path:
branches/rc/remoting/src/main/java/hudson/remoting/Channel.java
branches/rc/remoting/src/main/java/hudson/remoting/PipeWindow.java
branches/rc/remoting/src/main/java/hudson/remoting/ProxyOutputStream.java
branches/rc/remoting/src/test/java/hudson/remoting/PipeTest.java
trunk/www/changelog.html
http://jenkins-ci.org/commit/35460
Log:
[FIXED JENKINS-5977 JENKINS-7572] the incorrect use of WeakHashMap resulted in two instances of PipeWindows for the same OID.
Thanks for the fix. This was rather painful to deal with. I have upgraded to 1.379 and am trying a build I know hits the problem.
Looks good. I had a rather large job which never completed successfully on 1.378, even on the master node, and I have some jobs which were rather dicey on the slave. 1.379 seems stable for these.
For no it is good but in jobs logs I have thousands of lines like :
Oct 3, 2010 11:42:03 PM hudson.remoting.PipeWindow$Real decrease INFO: decrease(60,8192)->16384 Oct 3, 2010 11:42:03 PM hudson.remoting.PipeWindow$Real decrease INFO: decrease(60,8192)->8192 Oct 3, 2010 11:42:03 PM hudson.remoting.PipeWindow$Real decrease INFO: decrease(60,8192)->0 Oct 3, 2010 11:42:03 PM hudson.remoting.PipeWindow$Real increase INFO: increase(60,8192)->8192 Oct 3, 2010 11:42:03 PM hudson.remoting.PipeWindow$Real increase INFO: increase(60,8192)->16384 Oct 3, 2010 11:42:03 PM hudson.remoting.PipeWindow$Real decrease INFO: decrease(60,8192)->8192 Oct 3, 2010 11:42:03 PM hudson.remoting.PipeWindow$Real increase INFO: increase(60,8192)->16384 Oct 3, 2010 11:42:03 PM hudson.remoting.PipeWindow$Real decrease INFO: decrease(60,8192)->8192 Oct 3, 2010 11:42:03 PM hudson.remoting.PipeWindow$Real increase INFO: increase(60,8192)->16384 Oct 3, 2010 11:42:03 PM hudson.remoting.PipeWindow$Real decrease INFO: decrease(60,8192)->8192 Oct 3, 2010 11:42:03 PM hudson.remoting.PipeWindow$Real increase INFO: increase(60,8192)->16384 Oct 3, 2010 11:42:03 PM hudson.remoting.PipeWindow$Real decrease INFO: decrease(60,8192)->8192 Oct 3, 2010 11:42:03 PM hudson.remoting.PipeWindow$Real increase INFO: increase(60,8192)->16384 Oct 3, 2010 11:42:03 PM hudson.remoting.PipeWindow$Real decrease INFO: decrease(60,8192)->8192 Oct 3, 2010 11:42:03 PM hudson.remoting.PipeWindow$Real increase INFO: increase(60,8192)->16384 Oct 3, 2010 11:42:03 PM hudson.remoting.PipeWindow$Real decrease INFO: decrease(60,8192)->8192 Oct 3, 2010 11:42:03 PM hudson.remoting.PipeWindow$Real decrease INFO: decrease(60,8192)->0 Oct 3, 2010 11:42:03 PM hudson.remoting.PipeWindow$Real increase INFO: increase(60,8192)->8192 Oct 3, 2010 11:42:03 PM hudson.remoting.PipeWindow$Real increase INFO: increase(60,8192)->16384 Oct 3, 2010 11:42:03 PM hudson.remoting.PipeWindow$Real increase INFO: increase(60,8192)->24576 Oct 3, 2010 11:42:03 PM hudson.remoting.PipeWindow$Real increase INFO: increase(60,8192)->32768 Oct 3, 2010 11:42:03 PM hudson.remoting.PipeWindow$Real increase INFO: increase(60,8192)->40960 Oct 3, 2010 11:42:03 PM hudson.remoting.PipeWindow$Real increase INFO: increase(60,8192)->49152 Oct 3, 2010 11:42:03 PM hudson.remoting.PipeWindow$Real increase INFO: increase(60,8192)->57344 Oct 3, 2010 11:42:03 PM hudson.remoting.PipeWindow$Real increase INFO: increase(60,8192)->65536
You added some logs in INFO level. I suppose you wanted to do it in DEBUG level.
Logs are almost unreadable because of that. I think I'll need to wait 1.380 and to come back to 1.377
pafo:
Still failing (Hudson 1.379) random modules inside maven build :
Logs :
[HUDSON] Archiving site from Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real decrease
INFO: decrease(4,29)->131043
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real decrease
INFO: decrease(4,105)->130938
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real decrease
INFO: decrease(4,4)->130934
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real decrease
INFO: decrease(4,80)->130854
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real decrease
INFO: decrease(4,1)->130853
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real increase
INFO: increase(4,29)->130882
/home/ci-hudson/jobs/
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real increase
INFO: increase(4,105)->130987
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real increase
INFO: increase(4,4)->130991
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real increase
INFO: increase(4,80)->131071
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real increase
INFO: increase(4,1)->131072
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real decrease
INFO: decrease(152,8052)->123020
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real decrease
INFO: decrease(152,8192)->114828
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real decrease
INFO: decrease(152,3539)->111289
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real increase
INFO: increase(152,8052)->119341
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real increase
INFO: increase(152,8192)->127533
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real increase
INFO: increase(152,3539)->131072
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real decrease
INFO: decrease(152,97150)->33922
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real increase
INFO: increase(152,97150)->131072
FATAL: Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real decrease
INFO: decrease(4,7)->131065
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real increase
INFO: increase(4,7)->131072
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real decrease
INFO: decrease(4,214)->130858
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real decrease
INFO: decrease(4,1)->130857
Unable to copy site from /home/ci-hudson/jobs/
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real increase
INFO: increase(4,214)->131071
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real increase
INFO: increase(4,1)->131072
INFO: decrease(4,7)->131065
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real increase
INFO: increase(4,7)->131072
AAAAOct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real decrease
INFO: decrease(4,4)->131068
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real decrease
INFO: decrease(4,116)->130952
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real increase
INFO: increase(4,4)->130956
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real decrease
INFO: decrease(4,4)->130952
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real decrease
INFO: decrease(4,4)->130948
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real decrease
INFO: decrease(4,2127)->128821
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real decrease
INFO: decrease(4,56)->128765
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real decrease
INFO: decrease(4,56)->128709
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real decrease
INFO: decrease(4,84)->128625
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real decrease
INFO: decrease(4,87)->128538
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real decrease
INFO: decrease(4,73)->128465
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real decrease
INFO: decrease(4,113)->128352
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real decrease
INFO: decrease(4,95)->128257
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real decrease
INFO: decrease(4,104)->128153
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real decrease
INFO: decrease(4,113)->128040
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real decrease
INFO: decrease(4,103)->127937
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real decrease
INFO: decrease(4,120)->127817
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real decrease
INFO: decrease(4,111)->127706
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real decrease
INFO: decrease(4,99)->127607
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real decrease
INFO: decrease(4,106)->127501
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real decrease
INFO: decrease(4,67)->127434
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real decrease
INFO: decrease(4,65)->127369
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real decrease
INFO: decrease(4,58)->127311
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real decrease
INFO: decrease(4,64)->127247
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real decrease
INFO: decrease(4,82)->127165
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real decrease
INFO: decrease(4,90)->127075
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real decrease
INFO: decrease(4,53)->127022
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real decrease
INFO: decrease(4,72)->126950
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real decrease
INFO: decrease(4,64)->126886
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real decrease
INFO: decrease(4,50)->126836
WB+LCAAAAAAAAABb85aBtbiIQSmjNKU4P08vOT+vOD8nVc8DzHWtSE4tKMnMz/PLL0ldFVf2c+b/lb5MDAwVRQxSaBqcITRIIQMEMIIUFgAAckCEiWAAAAA=[0mOct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real decrease
INFO: decrease(4,58)->126778
hudson.util.IOException2: hudson.util.IOException2: Not in GZIP format
stream=e8a60dd1a435d1b039f8863978d0143c68061e300337e811d6eb12d6e910d6ea10966912946a1014ab13844ae01e8690ed06923ef3823cf1826c7a40569c49c62c897a8cc1ad06e7aab408f35509f25408a22fe01d865024c9131c8652d5e9132d3893dd72243f0ca71bb0247f1d44bfed477718c9d46e46f12a98b1d98aa9d14346478471a92161a6267ebc32fea28ad4d6e2e86114eb218c73dc9171c09afe10cef7349477d091ed2856f89a13cf5b8444b6abd65182e45192ccd32889a314c56b6ec22f10725b317247199a633e5247993a031e920308ab027fcba36cc3ed78eda33cf3a72946b37196d5512e55516e9ad2a2837eeab3117a47975cb732ec5ee438ef3f5bdb7fb1b9bff3e153a9dfcb02dfe3ea88dba91eef4b439f17063d290edfa9466c97254c5e4abf9e9bb85055901a12fca7f9df2487a1cce1e4dc0430bd7625b1a31a3816b3fc3ff2bf97556db3d7b195e136b24d270d4fa740d9387c65272a635b24b4e2be70a99c6d8c59742b275c5335c39bf8855e8fa714b1c7986ff83faf52cfa3d2c6c869b61999fd92ff1597b3194d9e1b954fc927164ec45f7f49445376d567ebe9074405280653e1aeddeb07dee56b3760879c532a3a655218e22bc4171b15cbaf85be5dedf1af5c9986cd14f2bf9af25da71b4c7b77f3d06070c51e3d624f1cd3448c70c4ead2f9e0d7437203ca31a1afd03d200b5ae6e2049a1ae11636b74a25eedc6fd30a075bc09ecc16b8bfb7bff7565cc5f5560941b55f7bf3cd1a0845fb677b63edd2b7690b659c0f032b253d4a3a7d871a54d2577bbd9b2e1df68f6317831196aceb13e890ee2c0c4aac4ce674b1870ed554fccd359bd82c98a04259d45bb677e1e7576d107322b7c7baf4a4cac11f13b95ab07314e46407f518c89c2a2a2730cf6cecb54416a54635a1d4ac3b6adc2daa501c567fc8ae02b5c92a7a39f643459234a199dd2a0d9e6e1ea614f6784dfd69d62210339a9c4cbbad3295438ba0326499a77a967f60f92336ebb887a1267b914d55127749881f969cf454a12dfef02a5c9d9958b92a49909a120d8ffd5280df1477e2fa4889ac45895c3c05b545160a0db1342a4e725c08dc0534990ac7ae69871127734ce177c715a9bf6c07257235b7cb276616d2406798ea57e471392a52b3b1396b0bab2665cfbbc062480da4166331fab04d93580b7bfda638baf099f0389320dc333cc92b9b43b2504339a578311330166dc432e3246dd0cae2245df8f34a158668b082a60429781915a20deb882552c2271a23973d59883b67be3b340aea7a041b51e386c5a00f6332b7088c122aa48e12882e648ea831fa30c0b16953d7876fb264eac271e8237c4670382a3251b179666b76e6ffb2d7fbbf6a7f84ff3f3bff0b3cfe7dfe57f8d7fcdf9f637f30ffafb7a4bebfb2d9cec636d82f3227bd
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real decrease
INFO: decrease(4,80)->126698
at hudson.FilePath.copyRecursiveTo(FilePath.java:1474)
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real increase
INFO: increase(4,116)->126814
at hudson.FilePath.copyRecursiveTo(FilePath.java:1399)
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real increase
INFO: increase(4,4)->126818
at hudson.maven.reporters.MavenSiteArchiver.postExecute(MavenSiteArchiver.java:81)
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real increase
INFO: increase(4,4)->126822
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real increase
INFO: increase(4,2127)->128949
at hudson.maven.MavenModuleSetBuild$Builder.postExecute(MavenModuleSetBuild.java:772)
at hudson.maven.MavenBuilder$Adapter.postExecute(MavenBuilder.java:300)
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real increase
INFO: increase(4,56)->129005
at hudson.maven.agent.PluginManagerInterceptor$1MojoIntercepterImpl.callPost(PluginManagerInterceptor.java:170)
at hudson.maven.agent.PluginManagerInterceptor.executeMojo(PluginManagerInterceptor.java:183)
at org.apache.maven.lifecycle.DefaultLifecycleExecutor.executeGoals(DefaultLifecycleExecutor.java:694)
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real decrease
INFO: decrease(4,80)->128925
at org.apache.maven.lifecycle.DefaultLifecycleExecutor.executeStandaloneGoal(DefaultLifecycleExecutor.java:569)
at org.apache.maven.lifecycle.DefaultLifecycleExecutor.executeGoal(DefaultLifecycleExecutor.java:539)
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real increase
INFO: increase(4,56)->128981
at org.apache.maven.lifecycle.DefaultLifecycleExecutor.executeGoalAndHandleFailures(DefaultLifecycleExecutor.java:387)
at org.apache.maven.lifecycle.DefaultLifecycleExecutor.executeTaskSegments(DefaultLifecycleExecutor.java:348)
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real decrease
INFO: decrease(4,62)->128919
at org.apache.maven.lifecycle.DefaultLifecycleExecutor.execute(DefaultLifecycleExecutor.java:180)
at org.apache.maven.lifecycle.LifecycleExecutorInterceptor.execute(LifecycleExecutorInterceptor.java:65)
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real increase
INFO: increase(4,84)->129003
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real increase
INFO: increase(4,87)->129090
at org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:328)
at org.apache.maven.DefaultMaven.execute(DefaultMaven.java:138)
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real increase
INFO: increase(4,73)->129163
at org.apache.maven.cli.MavenCli.main(MavenCli.java:362)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real decrease
INFO: decrease(4,61)->129102
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real increase
at java.lang.reflect.Method.invoke(Method.java:597)
INFO: increase(4,113)->129215
at org.codehaus.classworlds.Launcher.launchEnhanced(Launcher.java:315)
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real increase
INFO: increase(4,95)->129310
at org.codehaus.classworlds.Launcher.launch(Launcher.java:255)
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real increase
INFO: increase(4,104)->129414
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real increase
INFO: increase(4,113)->129527
at hudson.maven.agent.Main.launch(Main.java:165)
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real increase
INFO: increase(4,103)->129630
at hudson.maven.MavenBuilder.call(MavenBuilder.java:165)
at hudson.maven.MavenModuleSetBuild$Builder.call(MavenModuleSetBuild.java:694)
at hudson.maven.MavenModuleSetBuild$Builder.call(MavenModuleSetBuild.java:638)
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real decrease
INFO: decrease(4,52)->129578
at hudson.remoting.UserRequest.perform(UserRequest.java:114)
at hudson.remoting.UserRequest.perform(UserRequest.java:48)
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real increase
INFO: increase(4,120)->129698
at hudson.remoting.Request$2.run(Request.java:270)
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real increase
INFO: increase(4,111)->129809
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441)
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real decrease
INFO: decrease(4,76)->129733
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real increase
INFO: increase(4,99)->129832
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real decrease
INFO: decrease(4,71)->129761
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real increase
INFO: increase(4,106)->129867
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real decrease
INFO: decrease(4,61)->129806
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real increase
INFO: increase(4,67)->129873
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real decrease
INFO: decrease(4,88)->129785
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real increase
INFO: increase(4,65)->129850
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real decrease
INFO: decrease(4,84)->129766
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real increase
INFO: increase(4,58)->129824
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real decrease
INFO: decrease(4,42)->129782
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real increase
INFO: increase(4,64)->129846
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real increase
INFO: increase(4,82)->129928
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real increase
INFO: increase(4,90)->130018
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real decrease
INFO: decrease(4,2153)->127865
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real increase
INFO: increase(4,53)->127918
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real increase
INFO: increase(4,72)->127990
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real increase
INFO: increase(4,64)->128054
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real decrease
INFO: decrease(4,54)->128000
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real increase
INFO: increase(4,50)->128050
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real decrease
INFO: decrease(4,54)->127996
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real increase
INFO: increase(4,58)->128054
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real increase
INFO: increase(4,80)->128134
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real decrease
INFO: decrease(4,61)->128073
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real increase
INFO: increase(4,80)->128153
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real decrease
INFO: decrease(4,56)->128097
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real increase
INFO: increase(4,62)->128159
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real decrease
INFO: decrease(4,13)->128146
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real increase
INFO: increase(4,61)->128207
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real increase
INFO: increase(4,52)->128259
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real increase
INFO: increase(4,76)->128335
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real decrease
INFO: decrease(4,2112)->126223
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real decrease
INFO: decrease(4,64)->126159
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real decrease
INFO: decrease(4,50)->126109
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real decrease
INFO: decrease(4,50)->126059
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real decrease
INFO: decrease(4,65)->125994
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real decrease
INFO: decrease(4,12)->125982
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real decrease
INFO: decrease(4,51)->125931
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real decrease
INFO: decrease(4,71)->125860
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real decrease
INFO: decrease(4,66)->125794
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real decrease
INFO: decrease(4,64)->125730
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real decrease
INFO: decrease(4,13)->125717
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)
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real increase
INFO: increase(4,71)->125788
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
at java.lang.Thread.run(Thread.java:619)
Caused by: java.util.concurrent.ExecutionException: hudson.util.IOException2: Not in GZIP format
stream=e8a60dd1a435d1b039f8863978d0143c68061e300337e811d6eb12d6e910d6ea10966912946a1014ab13844ae01e8690ed06923ef3823cf1826c7a40569c49c62c897a8cc1ad06e7aab408f35509f25408a22fe01d865024c9131c8652d5e9132d3893dd72243f0ca71bb0247f1d44bfed477718c9d46e46f12a98b1d98aa9d14346478471a92161a6267ebc32fea28ad4d6e2e86114eb218c73dc9171c09afe10cef7349477d091ed2856f89a13cf5b8444b6abd65182e45192ccd32889a314c56b6ec22f10725b317247199a633e5247993a031e920308ab027fcba36cc3ed78eda33cf3a72946b37196d5512e55516e9ad2a2837eeab3117a47975cb732ec5ee438ef3f5bdb7fb1b9bff3e153a9dfcb02dfe3ea88dba91eef4b439f17063d290edfa9466c97254c5e4abf9e9bb85055901a12fca7f9df2487a1cce1e4dc0430bd7625b1a31a3816b3fc3ff2bf97556db3d7b195e136b24d270d4fa740d9387c65272a635b24b4e2be70a99c6d8c59742b275c5335c39bf8855e8fa714b1c7986ff83faf52cfa3d2c6c869b61999fd92ff1597b3194d9e1b954fc927164ec45f7f49445376d567ebe9074405280653e1aeddeb07dee56b3760879c532a3a655218e22bc4171b15cbaf85be5dedf1af5c9986cd14f2bf9af25da71b4c7b77f3d06070c51e3d624f1cd3448c70c4ead2f9e0d7437203ca31a1afd03d200b5ae6e2049a1ae11636b74a25eedc6fd30a075bc09ecc16b8bfb7bff7565cc5f5560941b55f7bf3cd1a0845fb677b63edd2b7690b659c0f032b253d4a3a7d871a54d2577bbd9b2e1df68f6317831196aceb13e890ee2c0c4aac4ce674b1870ed554fccd359bd82c98a04259d45bb677e1e7576d107322b7c7baf4a4cac11f13b95ab07314e46407f518c89c2a2a2730cf6cecb54416a54635a1d4ac3b6adc2daa501c567fc8ae02b5c92a7a39f643459234a199dd2a0d9e6e1ea614f6784dfd69d62210339a9c4cbbad3295438ba0326499a77a967f60f92336ebb887a1267b914d55127749881f969cf454a12dfef02a5c9d9958b92a49909a120d8ffd5280df1477e2fa4889ac45895c3c05b545160a0db1342a4e725c08dc0534990ac7ae69871127734ce177c715a9bf6c07257235b7cb276616d2406798ea57e471392a52b3b1396b0bab2665cfbbc062480da4166331fab04d93580b7bfda638baf099f0389320dc333cc92b9b43b2504339a578311330166dc432e3246dd0cae2245df8f34a158668b082a60429781915a20deb882552c2271a23973d59883b67be3b340aea7a041b51e386c5a00f6332b7088c122aa48e12882e648ea831fa30c0b16953d7876fb264eac271e8237c4670382a3251b179666b76e6ffb2d7fbbf6a7f84ff3f3bff0b3cfe7dfe57f8d7fcdf9f637f30ffafb7a4bebfb2d9cec636d82f3227bd
at hudson.remoting.Channel$2.adapt(Channel.java:663)
at hudson.remoting.Channel$2.adapt(Channel.java:658)
at hudson.remoting.FutureAdapter.get(FutureAdapter.java:55)
at hudson.FilePath.copyRecursiveTo(FilePath.java:1472)
... 35 more
Caused by: hudson.util.IOException2: Not in GZIP format
stream=e8a60dd1a435d1b039f8863978d0143c68061e300337e811d6eb12d6e910d6ea10966912946a1014ab13844ae01e8690ed06923ef3823cf1826c7a40569c49c62c897a8cc1ad06e7aab408f35509f25408a22fe01d865024c9131c8652d5e9132d3893dd72243f0ca71bb0247f1d44bfed477718c9d46e46f12a98b1d98aa9d14346478471a92161a6267ebc32fea28ad4d6e2e86114eb218c73dc9171c09afe10cef7349477d091ed2856f89a13cf5b8444b6abd65182e45192ccd32889a314c56b6ec22f10725b317247199a633e5247993a031e920308ab027fcba36cc3ed78eda33cf3a72946b37196d5512e55516e9ad2a2837eeab3117a47975cb732ec5ee438ef3f5bdb7fb1b9bff3e153a9dfcb02dfe3ea88dba91eef4b439f17063d290edfa9466c97254c5e4abf9e9bb85055901a12fca7f9df2487a1cce1e4dc0430bd7625b1a31a3816b3fc3ff2bf97556db3d7b195e136b24d270d4fa740d9387c65272a635b24b4e2be70a99c6d8c59742b275c5335c39bf8855e8fa714b1c7986ff83faf52cfa3d2c6c869b61999fd92ff1597b3194d9e1b954fc927164ec45f7f49445376d567ebe9074405280653e1aeddeb07dee56b3760879c532a3a655218e22bc4171b15cbaf85be5dedf1af5c9986cd14f2bf9af25da71b4c7b77f3d06070c51e3d624f1cd3448c70c4ead2f9e0d7437203ca31a1afd03d200b5ae6e2049a1ae11636b74a25eedc6fd30a075bc09ecc16b8bfb7bff7565cc5f5560941b55f7bf3cd1a0845fb677b63edd2b7690b659c0f032b253d4a3a7d871a54d2577bbd9b2e1df68f6317831196aceb13e890ee2c0c4aac4ce674b1870ed554fccd359bd82c98a04259d45bb677e1e7576d107322b7c7baf4a4cac11f13b95ab07314e46407f518c89c2a2a2730cf6cecb54416a54635a1d4ac3b6adc2daa501c567fc8ae02b5c92a7a39f643459234a199dd2a0d9e6e1ea614f6784dfd69d62210339a9c4cbbad3295438ba0326499a77a967f60f92336ebb887a1267b914d55127749881f969cf454a12dfef02a5c9d9958b92a49909a120d8ffd5280df1477e2fa4889ac45895c3c05b545160a0db1342a4e725c08dc0534990ac7ae69871127734ce177c715a9bf6c07257235b7cb276616d2406798ea57e471392a52b3b1396b0bab2665cfbbc062480da4166331fab04d93580b7bfda638baf099f0389320dc333cc92b9b43b2504339a578311330166dc432e3246dd0cae2245df8f34a158668b082a60429781915a20deb882552c2271a23973d59883b67be3b340aea7a041b51e386c5a00f6332b7088c122aa48e12882e648ea831fa30c0b16953d7876fb264eac271e8237c4670382a3251b179666b76e6ffb2d7fbbf6a7f84ff3f3bff0b3cfe7dfe57f8d7fcdf9f637f30ffafb7a4bebfb2d9cec636d82f3227bd
at hudson.FilePath$TarCompression$2.extract(FilePath.java:534)
at hudson.FilePath$32.invoke(FilePath.java:1463)
at hudson.FilePath$32.invoke(FilePath.java:1460)
at hudson.FilePath$FileCallableWrapper.call(FilePath.java:1899)
... 9 more
Caused by: java.io.IOException: Not in GZIP format
at java.util.zip.GZIPInputStream.readHeader(GZIPInputStream.java:137)
at java.util.zip.GZIPInputStream.
at hudson.FilePath$TarCompression$2.extract(FilePath.java:530)
... 12 more
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real increase
INFO: increase(4,61)->125849
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real increase
INFO: increase(4,88)->125937
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real increase
INFO: increase(4,84)->126021
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real increase
INFO: increase(4,42)->126063
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real increase
INFO: increase(4,2153)->128216
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real increase
INFO: increase(4,54)->128270
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real increase
INFO: increase(4,54)->128324
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real increase
INFO: increase(4,61)->128385
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real increase
INFO: increase(4,56)->128441
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real increase
INFO: increase(4,13)->128454
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real increase
INFO: increase(4,2112)->130566
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real increase
INFO: increase(4,64)->130630
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real increase
INFO: increase(4,50)->130680
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real increase
INFO: increase(4,50)->130730
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real increase
INFO: increase(4,65)->130795
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real increase
INFO: increase(4,12)->130807
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real increase
INFO: increase(4,51)->130858
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real increase
INFO: increase(4,71)->130929
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real increase
INFO: increase(4,66)->130995
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real increase
INFO: increase(4,64)->131059
Oct 4, 2010 12:39:57 PM hudson.remoting.PipeWindow$Real increase
INFO: increase(4,13)->131072
Code changed in hudson
User: : kohsuke
Path:
trunk/hudson/main/remoting/src/main/java/hudson/remoting/PipeWindow.java
http://jenkins-ci.org/commit/35531
Log:
JENKINS-7572 debug logging code crept in. Meant to be FINER, not INFO.
The excessive logging problem is covered in JENKINS-7662 and is fixed toward 1.380.
The gzip format issue appears to be a different problem — perhaps a failure caused by JENKINS-7662.
So marking this issue closed once again.
Integrated in hudson_main_trunk #314
[Originally depends on: JENKINS-5977]
I just deployed 1.378 and now I have several jobs frozen on step : [HUDSON] Archiving ...
This is probably related to the change :
JENKINS-7013But there is no stacktrace or error reported.
Jobs are in this state after several hours.
I killed them.
Originally reported by aheritier, imported from: Endless Archiving step ..