Uploaded image for project: 'Jenkins'
  1. Jenkins
  2. JENKINS-52230

Race condition in log rotation leads to warning log

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Open (View Workflow)
    • Priority: Minor
    • Resolution: Unresolved
    • Component/s: workflow-job-plugin
    • Labels:
      None
    • Environment:
      Jenkins (core) 2.129
      Workflow Job Plugin 2.21
    • Similar Issues:

      Description

      I guess this is due to parallel running pipeline instances that finish almost at the same time:

      2018-06-28 07:56:31 INFO [org.jenkinsci.plugins.workflow.job.WorkflowRun finish]   ACME-Pipeline #3078 completed: SUCCESS
      2018-06-28 07:56:31 INFO [org.jenkinsci.plugins.workflow.job.WorkflowRun finish]   ACME-Pipeline #3076 completed: SUCCESS
      2018-06-28 07:56:31 WARNING [org.jenkinsci.plugins.workflow.job.WorkflowRun lambda$finish$1]   failed to perform log rotation after ACME-Pipeline #3076
      java.io.IOException: ACME-Pipeline #2829: /var/lib/jenkins/jobs/ACME-Pipeline/builds/2829 looks to have already been deleted; siblings: [legacyIds, 2871, 2918, 2839, 2995, 2890, 3033, 2897, 2978, 691, 3067, 2980, 2919, 2835, 595, 3017, 2924, 3076, 806, 3054, 805, 2939, 2850, 2975, 2926, 2943, 2862, 2912, 825, 2958, 180, 3073, 2923, 2894, 2949, 2882, 2869, 2976, 3041, 3008, 3045, 2848, 2965, 2870, 3024, 2963, 2838, 2130, 3034, 5, 2853, 2901, 2986, 2841, 2840, 2930, 2973, 2968, 668, 55, 875, 2887, 3056, 3001, 3052, 2935, 3066, 53, 2983, 2895, 3020, 2962, 963, 3044, 2970, 2863, 2867, 2927, 3011, 2990, 2952, 3055, 2909, 718, 3053, 1669, 2932, 876, 2877, 3061, 1005, 868, 3026, 2945, 2996, 809, lastStableBuild, 2830, 3078, 2987, 3049, 2903, 3004, lastUnstableBuild, 3077, 2999, 2904, 2951, 3046, 851, 3016, 2971, 1173, 2977, 41, 1171, 2832, 2954, 871, 3000, 3003, 3027, 3051, 2991, 2885, 2876, 3069, 524, 2947, 2940, 2858, 2913, 3040, 803, 2969, 2891, 2861, lastUnsuccessfulBuild, 2964, 2899, 2900, 3010, 798, 2844, 722, 2948, 2833, 2864, 3070, 2631, 2629, 2888, 2911, 2855, 3058, 2967, 28, 667, .2829, 230, 2907, 2898, 826, 2989, 2966, 2865, 788, 3050, 2915, 421, 49, 1172, 48, 2997, 2961, 360, 2872, 2883, 3064, 2921, 2942, 2959, 710, 2905, 2859, 3019, 3042, 3060, 3025, 3047, 3079, 2957, 2892, 2860, 2866, 2834, lastFailedBuild, 54, 3013, 873, 2878, 3063, 3022, 2981, 317, 690, 1179, 3072, 3005, 37, 2914, 597, 3021, 2873, 869, 2886, 2879, 2946, 10, 2884, 52, 1649, 3007, 467, 56, 2929, 3018, 2906, 605, 2823, 2908, 2985, 2938, 2847, 2856, 2920, 777, 3071, 3035, 2893, 3039, 2984, 2998, 2936, 2979, 3029, 2857, 2922, 3075, 1612, 2846, 3012, 2950, 3002, 2972, 2843, 2982, 669, 596, 3037, 3031, 874, 2994, 2993, 2881, 2931, 2988, 2501, 3032, 2960, 51, 3036, 2868, 3028, 2937, 2933, 2916, 2992, 3059, 1540, 1838, 2974, 2874, 2917, 827, 211, 2902, 3015, 3014, 3030, 2955, 2928, 3048, 3006, 347, 2941, 799, 1485, 2925, 2845, 2896, 2842, 3062, 2910, 2944, 2831, 2837, 2852, 2309, 2875, 3043, 3065, 2889, 3009, 50, 3057, 3068, 2880, 2836, 2854, 2851, 2934, 3038, 3023, 2849, lastSuccessfulBuild, 2953, 2956, 3074]
              at hudson.model.Run.delete(Run.java:1569)
              at hudson.tasks.LogRotator.perform(LogRotator.java:131)
              at hudson.model.Job.logRotate(Job.java:468)
              at org.jenkinsci.plugins.workflow.job.WorkflowRun.lambda$finish$1(WorkflowRun.java:812)
              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)
      

      Maybe the code could be made more thread-safe or consider parallelism and thus avoid the need for logging this warning?

      (The hint in the warning log is correct: the build #2829 has really been deleted)

        Attachments

          Activity

          Hide
          reinholdfuereder Reinhold Füreder added a comment -

          Happened again:

          2019-01-28 15:28:45 INFO [org.jenkinsci.plugins.workflow.job.WorkflowRun finish]   ACME-Pipeline #4623 completed: SUCCESS
          2019-01-28 15:28:45 INFO [org.jenkinsci.plugins.workflow.job.WorkflowRun finish]   ACME-Pipeline #4624 completed: SUCCESS
          2019-01-28 15:28:45 WARNING [org.jenkinsci.plugins.workflow.job.WorkflowRun lambda$finish$1]   failed to perform log rotation after ACME-Pipeline #4624
          java.io.IOException: ACME-Pipeline #4375: /var/lib/jenkins/jobs/ACME-Pipeline/builds/4375 looks to have already been deleted; siblings: [legacyIds, 4519, 4604, 4432, 4581, 4555, 4510, 691, 3841, 4435, 4577, 595, 806, 805, 4
          588, 3824, 4446, 4523, 4426, 825, 180, 4570, 4582, 4526, 4408, 4451, 4576, 3238, 4556, 4433, 4500, 4062, 4548, 4407, 4615, 4525, 4416, 4522, 4580, 4382, 4490, 4606, 4414, 2130, 4625, 4444, 4464, 5, 4443, 4594, 4618, 438
          4, 3579, 4404, 4440, 4396, 668, 4458, 4462, 4542, 55, 875, 53, 4489, 4478, 4448, 4584, 4417, 963, 4486, 4400, 4495, 4469, 4493, 4531, 4485, 4535, 4571, 4374, 4425, 4459, 4503, 718, 1669, 4527, 876, 1005, 868, 4373, 4445
          , 809, 4574, lastStableBuild, 4415, 4532, 4394, 4572, 4438, lastUnstableBuild, 4454, 4528, 4453, 4470, 4483, 4274, 851, 4608, 4605, 1173, 4611, 4484, 41, 4482, 4583, 1171, 4534, 4590, 871, 4401, 4561, 4386, 4377, 4387,
          4405, 524, 4609, 4481, 4472, 4573, 803, 4504, 4559, 4420, 4431, 4378, 4518, 4428, lastUnsuccessfulBuild, 4465, 4427, 4549, 798, 4538, 4552, 4514, 4551, 4455, 4461, 722, 4603, 4452, 2631, 4457, 2629, 4569, 4517, 4477, 45
          93, 28, 4586, 667, 4492, 4543, 4613, 4601, 230, 4388, 4602, 4560, .4375, 826, 4566, 4536, 4449, 4248, 788, 4439, 421, 4610, 49, 4541, 4474, 1172, 3840, 48, 4619, 4513, 4595, 4562, 360, 710, 4434, 4529, 4509, 4568, 4547,
           4512, 3380, 4507, 4591, 4623, 4545, 4567, 4402, 4598, 4410, lastFailedBuild, 54, 4460, 873, 4521, 4554, 4479, 4393, 4614, 4515, 4624, 4450, 4275, 4578, 4565, 4437, 317, 690, 1179, 37, 4466, 597, 4476, 4579, 4621, 4589,
           4539, 869, 4244, 4422, 10, 4412, 4389, 4421, 52, 1649, 4411, 4480, 4540, 4502, 4511, 467, 56, 4436, 605, 2823, 4471, 4496, 4447, 4494, 4530, 4430, 777, 4599, 4242, 4488, 4487, 4399, 4506, 4395, 4587, 4616, 3108, 1612,
          4533, 4546, 4392, 4564, 4499, 4575, 4592, 4467, 4617, 4498, 669, 4442, 596, 874, 2501, 4441, 4413, 4409, 51, 4456, 4544, 4473, 4585, 4497, 4397, 4622, 4390, 1540, 1838, 4419, 4505, 4558, 4597, 4380, 4385, 4403, 4468, 44
          91, 4553, 827, 211, 4383, 4524, 4406, 4563, 4391, 4557, 4398, 4596, 4612, 347, 4520, 799, 1485, 4463, 4475, 4418, 4381, 4063, 4501, 4620, 4423, 4429, 2309, 4550, 4600, 50, 4607, 4537, 4508, 4516, 4376, lastSuccessfulBui
          ld, 4424, 4379]
                  at hudson.model.Run.delete(Run.java:1564)
                  at hudson.tasks.LogRotator.perform(LogRotator.java:131)
                  at hudson.model.Job.logRotate(Job.java:468)
                  at org.jenkinsci.plugins.workflow.job.WorkflowRun.lambda$finish$1(WorkflowRun.java:607)
                  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)
          
          Show
          reinholdfuereder Reinhold Füreder added a comment - Happened again: 2019-01-28 15:28:45 INFO [org.jenkinsci.plugins.workflow.job.WorkflowRun finish] ACME-Pipeline #4623 completed: SUCCESS 2019-01-28 15:28:45 INFO [org.jenkinsci.plugins.workflow.job.WorkflowRun finish] ACME-Pipeline #4624 completed: SUCCESS 2019-01-28 15:28:45 WARNING [org.jenkinsci.plugins.workflow.job.WorkflowRun lambda$finish$1] failed to perform log rotation after ACME-Pipeline #4624 java.io.IOException: ACME-Pipeline #4375: /var/lib/jenkins/jobs/ACME-Pipeline/builds/4375 looks to have already been deleted; siblings: [legacyIds, 4519, 4604, 4432, 4581, 4555, 4510, 691, 3841, 4435, 4577, 595, 806, 805, 4 588, 3824, 4446, 4523, 4426, 825, 180, 4570, 4582, 4526, 4408, 4451, 4576, 3238, 4556, 4433, 4500, 4062, 4548, 4407, 4615, 4525, 4416, 4522, 4580, 4382, 4490, 4606, 4414, 2130, 4625, 4444, 4464, 5, 4443, 4594, 4618, 438 4, 3579, 4404, 4440, 4396, 668, 4458, 4462, 4542, 55, 875, 53, 4489, 4478, 4448, 4584, 4417, 963, 4486, 4400, 4495, 4469, 4493, 4531, 4485, 4535, 4571, 4374, 4425, 4459, 4503, 718, 1669, 4527, 876, 1005, 868, 4373, 4445 , 809, 4574, lastStableBuild, 4415, 4532, 4394, 4572, 4438, lastUnstableBuild, 4454, 4528, 4453, 4470, 4483, 4274, 851, 4608, 4605, 1173, 4611, 4484, 41, 4482, 4583, 1171, 4534, 4590, 871, 4401, 4561, 4386, 4377, 4387, 4405, 524, 4609, 4481, 4472, 4573, 803, 4504, 4559, 4420, 4431, 4378, 4518, 4428, lastUnsuccessfulBuild, 4465, 4427, 4549, 798, 4538, 4552, 4514, 4551, 4455, 4461, 722, 4603, 4452, 2631, 4457, 2629, 4569, 4517, 4477, 45 93, 28, 4586, 667, 4492, 4543, 4613, 4601, 230, 4388, 4602, 4560, .4375, 826, 4566, 4536, 4449, 4248, 788, 4439, 421, 4610, 49, 4541, 4474, 1172, 3840, 48, 4619, 4513, 4595, 4562, 360, 710, 4434, 4529, 4509, 4568, 4547, 4512, 3380, 4507, 4591, 4623, 4545, 4567, 4402, 4598, 4410, lastFailedBuild, 54, 4460, 873, 4521, 4554, 4479, 4393, 4614, 4515, 4624, 4450, 4275, 4578, 4565, 4437, 317, 690, 1179, 37, 4466, 597, 4476, 4579, 4621, 4589, 4539, 869, 4244, 4422, 10, 4412, 4389, 4421, 52, 1649, 4411, 4480, 4540, 4502, 4511, 467, 56, 4436, 605, 2823, 4471, 4496, 4447, 4494, 4530, 4430, 777, 4599, 4242, 4488, 4487, 4399, 4506, 4395, 4587, 4616, 3108, 1612, 4533, 4546, 4392, 4564, 4499, 4575, 4592, 4467, 4617, 4498, 669, 4442, 596, 874, 2501, 4441, 4413, 4409, 51, 4456, 4544, 4473, 4585, 4497, 4397, 4622, 4390, 1540, 1838, 4419, 4505, 4558, 4597, 4380, 4385, 4403, 4468, 44 91, 4553, 827, 211, 4383, 4524, 4406, 4563, 4391, 4557, 4398, 4596, 4612, 347, 4520, 799, 1485, 4463, 4475, 4418, 4381, 4063, 4501, 4620, 4423, 4429, 2309, 4550, 4600, 50, 4607, 4537, 4508, 4516, 4376, lastSuccessfulBui ld, 4424, 4379] at hudson.model.Run.delete(Run.java:1564) at hudson.tasks.LogRotator.perform(LogRotator.java:131) at hudson.model.Job.logRotate(Job.java:468) at org.jenkinsci.plugins.workflow.job.WorkflowRun.lambda$finish$1(WorkflowRun.java:607) 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)

            People

            • Assignee:
              Unassigned
              Reporter:
              reinholdfuereder Reinhold Füreder
            • Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

              Dates

              • Created:
                Updated: