After updating Jenkins core 2.220 => 2.222 this morning I often see such warning logs, but not necessarily every time a build ends (I think). I naively guess this might be a kind of race condition between the project pipeline's build discarder and the new default BackgroundGlobalBuildDiscarder. Example with "ACME-Pipeline": Builds:
- Build #328: 20200227-094910-revb07cd7f2 (27-Feb-2020 09:49) Started by manual triggering by <USER>
- Build #329: 20200227-100803-revb07cd7f2 (27-Feb-2020 10:08) Started by manual triggering by <USER>
- Build #330: 20200227-102515-revb8388d5e (27-Feb-2020 10:25) Started by GitLab push by <USER>
(Mind Jenkins log timestamps in UTC format: 1h behind local time) Build #254 is deleted at ~09:15:57 (UTC), i.e. ~10:15:57 (local time), becase build #329 finished at that time:
...
2020-02-27 08:57:05.977+0000 [id=3886] INFO o.j.p.workflow.job.WorkflowRun#finish: ACME/ACME-Pipeline #328 completed: UNSTABLE
2020-02-27 08:57:06.029+0000 [id=52] WARNING o.j.p.workflow.job.WorkflowRun#lambda$finish$2: failed to perform log rotation after ACME/ACME-Pipeline #328
Also: java.nio.file.NoSuchFileException: /var/lib/jenkins/jobs/ACME/jobs/ACME-Pipeline/builds/253 -> /var/lib/jenkins/jobs/ACME/jobs/ACME-Pipeline/builds/.253
at sun.nio.fs.UnixException.translateToIOException(UnixException.java:86)
at sun.nio.fs.UnixException.rethrowAsIOException(UnixException.java:102)
at sun.nio.fs.UnixCopyFile.move(UnixCopyFile.java:396)
at sun.nio.fs.UnixFileSystemProvider.move(UnixFileSystemProvider.java:262)
at java.nio.file.Files.move(Files.java:1395)
at hudson.model.Run.delete(Run.java:1621)
at hudson.tasks.LogRotator.perform(LogRotator.java:166)
jenkins.util.io.CompositeIOException: Failed to rotate logs for [ACME/ACME-Pipeline #253]
at hudson.tasks.LogRotator.perform(LogRotator.java:223)
at hudson.model.Job.logRotate(Job.java:469)
at org.jenkinsci.plugins.workflow.job.WorkflowRun.lambda$finish$2(WorkflowRun.java:608)
at jenkins.security.ImpersonatingScheduledExecutorService$1.run(ImpersonatingScheduledExecutorService.java:58)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
2020-02-27 09:04:30.707+0000 [id=4502] INFO hudson.model.AsyncPeriodicWork#lambda$doRun$0: Started jobAnalytics
2020-02-27 09:04:30.710+0000 [id=4502] INFO hudson.model.AsyncPeriodicWork#lambda$doRun$0: Finished jobAnalytics. 2 ms
2020-02-27 09:10:38.198+0000 [id=4695] INFO ...
...
2020-02-27 09:13:57.462+0000 [id=4786] INFO o.j.p.workflow.job.WorkflowRun#finish: ANOTHER-Pipeline #1864 completed: SUCCESS
...
2020-02-27 09:15:57.057+0000 [id=5018] INFO o.j.p.workflow.job.WorkflowRun#finish: ACME/ACME-Pipeline #329 completed: UNSTABLE
2020-02-27 09:15:57.081+0000 [id=5018] WARNING j.m.BackgroundGlobalBuildDiscarder#lambda$processJob$0: An exception occurred when executing Project Build Discarder
Also: java.nio.file.NoSuchFileException: /var/lib/jenkins/jobs/ACME/jobs/ACME-Pipeline/builds/254 -> /var/lib/jenkins/jobs/ACME/jobs/ACME-Pipeline/builds/.254
at sun.nio.fs.UnixException.translateToIOException(UnixException.java:86)
at sun.nio.fs.UnixException.rethrowAsIOException(UnixException.java:102)
at sun.nio.fs.UnixCopyFile.move(UnixCopyFile.java:396)
at sun.nio.fs.UnixFileSystemProvider.move(UnixFileSystemProvider.java:262)
at java.nio.file.Files.move(Files.java:1395)
at hudson.model.Run.delete(Run.java:1621)
at hudson.tasks.LogRotator.perform(LogRotator.java:166)
jenkins.util.io.CompositeIOException: Failed to rotate logs for [ACME/ACME-Pipeline #254]
at hudson.tasks.LogRotator.perform(LogRotator.java:223)
at hudson.model.Job.logRotate(Job.java:469)
at jenkins.model.JobGlobalBuildDiscarderStrategy.apply(JobGlobalBuildDiscarderStrategy.java:54)
at jenkins.model.BackgroundGlobalBuildDiscarder.lambda$processJob$0(BackgroundGlobalBuildDiscarder.java:67)
at java.lang.Iterable.forEach(Iterable.java:75)
at jenkins.model.BackgroundGlobalBuildDiscarder.processJob(BackgroundGlobalBuildDiscarder.java:61)
at jenkins.model.GlobalBuildDiscarderListener.onFinalized(GlobalBuildDiscarderListener.java:49)
at hudson.model.listeners.RunListener.fireFinalized(RunListener.java:255)
at hudson.model.Run.onEndBuilding(Run.java:2018)
at org.jenkinsci.plugins.workflow.job.WorkflowRun.finish(WorkflowRun.java:613)
at org.jenkinsci.plugins.workflow.job.WorkflowRun.access$800(WorkflowRun.java:133)
at org.jenkinsci.plugins.workflow.job.WorkflowRun$GraphL.onNewHead(WorkflowRun.java:1014)
at org.jenkinsci.plugins.workflow.cps.CpsFlowExecution.notifyListeners(CpsFlowExecution.java:1463)
at org.jenkinsci.plugins.workflow.cps.CpsThreadGroup$3.run(CpsThreadGroup.java:488)
at org.jenkinsci.plugins.workflow.cps.CpsVmExecutorService$1.run(CpsVmExecutorService.java:38)
at hudson.remoting.SingleLaneExecutorService$1.run(SingleLaneExecutorService.java:131)
at jenkins.util.ContextResettingExecutorService$1.run(ContextResettingExecutorService.java:28)
at jenkins.security.ImpersonatingExecutorService$1.run(ImpersonatingExecutorService.java:59)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
2020-02-27 09:23:10.248+0000 [id=5162] INFO ...
...
2020-02-27 09:25:15.414+0000 [id=4373] INFO c.d.g.webhook.GitLabWebHook#getDynamic: WebHook called with url: /project/ACME/ACME-Pipeline
2020-02-27 09:25:15.417+0000 [id=4373] INFO c.d.g.t.h.AbstractWebHookTriggerHandler#handle: ACME/ACME-Pipeline triggered for push.
2020-02-27 09:25:21.711+0000 [id=5162] INFO c.d.g.util.CommitStatusUpdater#retrieveGitlabProjectIds: Retrieving gitlab project ids
2020-02-27 09:25:21.753+0000 [id=5162] INFO c.d.g.util.CommitStatusUpdater#updateCommitStatus: Updating build '101' to 'running'
2020-02-27 09:28:24.803+0000 [id=5336] INFO ...
...
2020-02-27 09:34:59.317+0000 [id=5600] INFO c.d.g.util.CommitStatusUpdater#retrieveGitlabProjectIds: Retrieving gitlab project ids
2020-02-27 09:34:59.406+0000 [id=5600] INFO c.d.g.util.CommitStatusUpdater#updateCommitStatus: Updating build '101' to 'failed'
2020-02-27 09:34:59.666+0000 [id=5671] INFO hudson.model.AsyncPeriodicWork#lambda$doRun$0: Started Periodic background build discarder
2020-02-27 09:34:59.765+0000 [id=5671] INFO hudson.model.AsyncPeriodicWork#lambda$doRun$0: Finished Periodic background build discarder. 99 ms
2020-02-27 09:34:59.809+0000 [id=5600] INFO o.j.p.workflow.job.WorkflowRun#finish: ACME/ACME-Pipeline #330 completed: UNSTABLE
2020-02-27 09:35:55.259+0000 [id=5105] INFO c.d.g.webhook.GitLabWebHook#getDynamic: WebHook called with url: /project/ACME/ACME-Pipeline
2020-02-27 09:35:55.262+0000 [id=5105] INFO c.d.g.t.h.AbstractWebHookTriggerHandler#handle: ACME/ACME-Pipeline triggered for push.
2020-02-27 09:35:58.525+0000 [id=5589] INFO c.d.g.util.CommitStatusUpdater#retrieveGitlabProjectIds: Retrieving gitlab project ids
2020-02-27 09:35:58.567+0000 [id=5589] INFO c.d.g.util.CommitStatusUpdater#updateCommitStatus: Updating build '101' to 'running'
2020-02-27 09:42:40.260+0000 [id=5958] INFO c.d.g.util.CommitStatusUpdater#retrieveGitlabProjectIds: Retrieving gitlab project ids
2020-02-27 09:42:40.371+0000 [id=5958] INFO c.d.g.util.CommitStatusUpdater#updateCommitStatus: Updating build '101' to 'success'
2020-02-27 09:42:40.957+0000 [id=5896] INFO o.j.p.workflow.job.WorkflowRun#finish: ACME/ACME-Pipeline #331 completed: SUCCESS
2020-02-27 09:42:40.985+0000 [id=28] WARNING o.j.p.workflow.job.WorkflowRun#lambda$finish$2: failed to perform log rotation after ACME/ACME-Pipeline #331
Also: java.nio.file.NoSuchFileException: /var/lib/jenkins/jobs/ACME/jobs/ACME-Pipeline/builds/256 -> /var/lib/jenkins/jobs/ACME/jobs/ACME-Pipeline/builds/.256
at sun.nio.fs.UnixException.translateToIOException(UnixException.java:86)
at sun.nio.fs.UnixException.rethrowAsIOException(UnixException.java:102)
at sun.nio.fs.UnixCopyFile.move(UnixCopyFile.java:396)
at sun.nio.fs.UnixFileSystemProvider.move(UnixFileSystemProvider.java:262)
at java.nio.file.Files.move(Files.java:1395)
at hudson.model.Run.delete(Run.java:1621)
at hudson.tasks.LogRotator.perform(LogRotator.java:166)
jenkins.util.io.CompositeIOException: Failed to rotate logs for [ACME/ACME-Pipeline #256]
at hudson.tasks.LogRotator.perform(LogRotator.java:223)
at hudson.model.Job.logRotate(Job.java:469)
at org.jenkinsci.plugins.workflow.job.WorkflowRun.lambda$finish$2(WorkflowRun.java:608)
at jenkins.security.ImpersonatingScheduledExecutorService$1.run(ImpersonatingScheduledExecutorService.java:58)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
2020-02-27 09:43:57.529+0000 [id=6061] INFO o.j.p.workflow.job.WorkflowRun#finish: ANOTHER-Pipeline #1865 completed: SUCCESS
2020-02-27 09:52:06.135+0000 [id=4371] INFO c.d.g.webhook.GitLabWebHook#getDynamic: WebHook called with url: /project/ACME/ACME-Pipeline
...
At 09:58 (local time) build #254 is still there:
jenkins@jenkins2:~$ date
Don Feb 27 09:58:15 CET 2020
jenkins@jenkins2:~$
jenkins@jenkins2:~$ ll /var/lib/jenkins/jobs/ACME/jobs/ACME-Pipeline/builds/
total 328
drwxr-xr-x 81 jenkins unix-user 4096 Feb 27 09:57 ./
drwxr-xr-x 4 jenkins unix-user 4096 Feb 27 09:49 ../
drwxr-xr-x 5 jenkins unix-user 4096 Nov 5 07:08 105/
drwxr-xr-x 5 jenkins unix-user 4096 Dez 1 00:37 135/
drwxr-xr-x 5 jenkins unix-user 4096 Jän 1 00:36 186/
drwxr-xr-x 5 jenkins unix-user 4096 Jän 21 10:06 254/ // !!!
drwxr-xr-x 4 jenkins unix-user 4096 Jän 21 10:15 255/
drwxr-xr-x 5 jenkins unix-user 4096 Jän 21 10:56 256/
drwxr-xr-x 5 jenkins unix-user 4096 Jän 21 11:07 257/
drwxr-xr-x 5 jenkins unix-user 4096 Jän 21 14:09 258/
drwxr-xr-x 4 jenkins unix-user 4096 Jän 21 14:13 259/
drwxr-xr-x 5 jenkins unix-user 4096 Jän 21 14:36 260/
drwxr-xr-x 4 jenkins unix-user 4096 Jän 21 14:40 261/
drwxr-xr-x 5 jenkins unix-user 4096 Jän 21 15:17 262/
drwxr-xr-x 5 jenkins unix-user 4096 Jän 22 00:37 263/
drwxr-xr-x 5 jenkins unix-user 4096 Jän 23 00:37 264/
drwxr-xr-x 5 jenkins unix-user 4096 Jän 23 15:55 265/
drwxr-xr-x 4 jenkins unix-user 4096 Jän 23 15:59 266/
drwxr-xr-x 5 jenkins unix-user 4096 Jän 24 00:37 267/
drwxr-xr-x 5 jenkins unix-user 4096 Jän 24 14:10 268/
drwxr-xr-x 5 jenkins unix-user 4096 Jän 25 00:36 269/
drwxr-xr-x 5 jenkins unix-user 4096 Jän 26 00:36 270/
drwxr-xr-x 5 jenkins unix-user 4096 Jän 27 00:36 271/
drwxr-xr-x 5 jenkins unix-user 4096 Jän 28 00:36 272/
drwxr-xr-x 5 jenkins unix-user 4096 Jän 28 08:30 273/
drwxr-xr-x 4 jenkins unix-user 4096 Jän 28 08:33 274/
drwxr-xr-x 5 jenkins unix-user 4096 Jän 29 00:36 275/
drwxr-xr-x 5 jenkins unix-user 4096 Jän 30 00:36 276/
drwxr-xr-x 5 jenkins unix-user 4096 Feb 1 00:36 277/
drwxr-xr-x 5 jenkins unix-user 4096 Feb 1 00:36 278/
drwxr-xr-x 5 jenkins unix-user 4096 Feb 2 00:36 279/
drwxr-xr-x 5 jenkins unix-user 4096 Feb 3 00:36 280/
drwxr-xr-x 5 jenkins unix-user 4096 Feb 3 10:17 281/
drwxr-xr-x 5 jenkins unix-user 4096 Feb 3 10:23 282/
drwxr-xr-x 4 jenkins unix-user 4096 Feb 3 10:33 283/
drwxr-xr-x 4 jenkins unix-user 4096 Feb 3 16:38 284/
drwxr-xr-x 4 jenkins unix-user 4096 Feb 4 00:33 285/
drwxr-xr-x 4 jenkins unix-user 4096 Feb 4 09:03 286/
drwxr-xr-x 4 jenkins unix-user 4096 Feb 4 09:38 287/
drwxr-xr-x 4 jenkins unix-user 4096 Feb 4 14:46 288/
drwxr-xr-x 5 jenkins unix-user 4096 Feb 4 15:26 289/
drwxr-xr-x 5 jenkins unix-user 4096 Feb 5 00:36 290/
drwxr-xr-x 5 jenkins unix-user 4096 Feb 5 13:43 291/
drwxr-xr-x 5 jenkins unix-user 4096 Feb 6 00:36 292/
drwxr-xr-x 5 jenkins unix-user 4096 Feb 7 00:36 293/
drwxr-xr-x 5 jenkins unix-user 4096 Feb 8 00:36 294/
drwxr-xr-x 5 jenkins unix-user 4096 Feb 9 00:36 295/
drwxr-xr-x 5 jenkins unix-user 4096 Feb 10 00:36 296/
drwxr-xr-x 5 jenkins unix-user 4096 Feb 10 08:45 297/
drwxr-xr-x 5 jenkins unix-user 4096 Feb 11 07:37 298/
drwxr-xr-x 5 jenkins unix-user 4096 Feb 11 07:44 299/
drwxr-xr-x 5 jenkins unix-user 4096 Feb 11 07:49 300/
drwxr-xr-x 5 jenkins unix-user 4096 Feb 11 08:03 301/
drwxr-xr-x 5 jenkins unix-user 4096 Feb 12 00:36 302/
drwxr-xr-x 5 jenkins unix-user 4096 Feb 12 09:07 303/
drwxr-xr-x 5 jenkins unix-user 4096 Feb 13 00:37 304/
drwxr-xr-x 5 jenkins unix-user 4096 Feb 14 00:37 305/
drwxr-xr-x 5 jenkins unix-user 4096 Feb 15 00:36 306/
drwxr-xr-x 5 jenkins unix-user 4096 Feb 16 00:36 307/
drwxr-xr-x 5 jenkins unix-user 4096 Feb 17 00:36 308/
drwxr-xr-x 5 jenkins unix-user 4096 Feb 18 00:36 309/
drwxr-xr-x 5 jenkins unix-user 4096 Feb 18 06:35 310/
drwxr-xr-x 5 jenkins unix-user 4096 Feb 19 00:38 311/
drwxr-xr-x 5 jenkins unix-user 4096 Feb 19 07:47 312/
drwxr-xr-x 5 jenkins unix-user 4096 Feb 20 00:39 313/
drwxr-xr-x 5 jenkins unix-user 4096 Feb 20 08:47 314/
drwxr-xr-x 5 jenkins unix-user 4096 Feb 20 14:33 315/
drwxr-xr-x 5 jenkins unix-user 4096 Feb 21 00:44 316/
drwxr-xr-x 5 jenkins unix-user 4096 Feb 22 00:43 317/
drwxr-xr-x 5 jenkins unix-user 4096 Feb 23 00:43 318/
drwxr-xr-x 5 jenkins unix-user 4096 Feb 24 00:43 319/
drwxr-xr-x 5 jenkins unix-user 4096 Feb 25 00:43 320/
drwxr-xr-x 5 jenkins unix-user 4096 Feb 25 08:39 321/
drwxr-xr-x 5 jenkins unix-user 4096 Feb 25 09:10 322/
drwxr-xr-x 5 jenkins unix-user 4096 Feb 25 10:23 323/
drwxr-xr-x 5 jenkins unix-user 4096 Feb 25 10:53 324/
drwxr-xr-x 5 jenkins unix-user 4096 Feb 26 00:43 325/
drwxr-xr-x 5 jenkins unix-user 4096 Feb 27 00:43 326/
drwxr-xr-x 5 jenkins unix-user 4096 Feb 27 09:45 327/
drwxr-xr-x 5 jenkins unix-user 4096 Feb 27 09:57 328/
drwxr-xr-x 5 jenkins unix-user 4096 Nov 5 07:08 47/
-rw-r--r-- 1 jenkins unix-user 0 Sep 11 08:21 legacyIds
-rw-r--r-- 1 jenkins unix-user 134 Feb 27 09:57 permalinks
jenkins@jenkins2:~$
jenkins@jenkins2:~$ ll /var/lib/jenkins/jobs/ACME/jobs/ACME-Pipeline/builds/ | wc -l
84
jenkins@jenkins2:~$
jenkins@jenkins2:~$ ll /var/lib/jenkins/jobs/ACME/jobs/ACME-Pipeline/builds/ | grep 25
drwxr-xr-x 5 jenkins unix-user 4096 Jän 21 10:06 254/ // !!!
drwxr-xr-x 4 jenkins unix-user 4096 Jän 21 10:15 255/
drwxr-xr-x 5 jenkins unix-user 4096 Jän 21 10:56 256/
drwxr-xr-x 5 jenkins unix-user 4096 Jän 21 11:07 257/
drwxr-xr-x 5 jenkins unix-user 4096 Jän 21 14:09 258/
drwxr-xr-x 4 jenkins unix-user 4096 Jän 21 14:13 259/
drwxr-xr-x 5 jenkins unix-user 4096 Jän 25 00:36 269/
drwxr-xr-x 5 jenkins unix-user 4096 Feb 25 00:43 320/
drwxr-xr-x 5 jenkins unix-user 4096 Feb 25 08:39 321/
drwxr-xr-x 5 jenkins unix-user 4096 Feb 25 09:10 322/
drwxr-xr-x 5 jenkins unix-user 4096 Feb 25 10:23 323/
drwxr-xr-x 5 jenkins unix-user 4096 Feb 25 10:53 324/
drwxr-xr-x 5 jenkins unix-user 4096 Feb 26 00:43 325/
At 10:33 (local time) build #254 is definitely deleted:
jenkins@jenkins2:~$ date
Don Feb 27 10:33:04 CET 2020
jenkins@jenkins2:~$
jenkins@jenkins2:~$ ll /var/lib/jenkins/jobs/ACME/jobs/ACME-Pipeline/builds/ | grep 25
drwxr-xr-x 82 jenkins unix-user 4096 Feb 27 10:25 ./
drwxr-xr-x 4 jenkins unix-user 4096 Feb 27 10:25 ../
drwxr-xr-x 4 jenkins unix-user 4096 Jän 21 10:15 255/
drwxr-xr-x 5 jenkins unix-user 4096 Jän 21 10:56 256/
drwxr-xr-x 5 jenkins unix-user 4096 Jän 21 11:07 257/
drwxr-xr-x 5 jenkins unix-user 4096 Jän 21 14:09 258/
drwxr-xr-x 4 jenkins unix-user 4096 Jän 21 14:13 259/
drwxr-xr-x 5 jenkins unix-user 4096 Jän 25 00:36 269/
drwxr-xr-x 5 jenkins unix-user 4096 Feb 25 00:43 320/
drwxr-xr-x 5 jenkins unix-user 4096 Feb 25 08:39 321/
drwxr-xr-x 5 jenkins unix-user 4096 Feb 25 09:10 322/
drwxr-xr-x 5 jenkins unix-user 4096 Feb 25 10:23 323/
drwxr-xr-x 5 jenkins unix-user 4096 Feb 25 10:53 324/
drwxr-xr-x 5 jenkins unix-user 4096 Feb 26 00:43 325/
jenkins@jenkins2:~$ ll /var/lib/jenkins/jobs/ACME/jobs/ACME-Pipeline/builds/ | wc -l
85
Presumably a possible workaround would be manually deleting the new default BackgroundGlobalBuildDiscarder from the global Jenkins system configuration – however, I think this should be fixed, as it might affect all existing pipelines with a project build discarder, i.e. really a lot of existing Jenkins users? |