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

Race condition in log rotation leads to warning log

XMLWordPrintable

    • Icon: Bug Bug
    • Resolution: Unresolved
    • Icon: Minor Minor
    • workflow-job-plugin
    • None
    • Jenkins (core) 2.129
      Workflow Job Plugin 2.21

      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)

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

              Created:
              Updated: