Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Improve lockable-resources build (job) page #673

Merged
merged 29 commits into from
Sep 17, 2024

Merge branch 'master' into feature/performance

85ed13b
Select commit
Loading
Failed to load commit list.
Merged

Improve lockable-resources build (job) page #673

Merge branch 'master' into feature/performance
85ed13b
Select commit
Loading
Failed to load commit list.
ci.jenkins.io / Tests / windows-17 / Build (windows-17) failed Sep 17, 2024 in 0s

org.jenkins.plugins.lockableresources.LockStepTest.reserveInsideLockHonoured failed

Send us feedback

Details

org.jenkins.plugins.lockableresources.LockStepTest.reserveInsideLockHonoured

Expected: a string containing "Locked resource reservedBy 1-5: null"
     but: was "Started
[Pipeline] Start of Pipeline
[Pipeline] timeout
Timeout set to expire in 2 min 0 sec
[Pipeline] {
[Pipeline] parallel
[Pipeline] { (Branch: p1)
[Pipeline] { (Branch: p2)
[Pipeline] { (Branch: p3)
[Pipeline] lock
Trying to acquire lock on [Label: label1]
Lock acquired on [Label: label1]
[Pipeline] {
[Pipeline] sleep
Sleeping for 1 sec
[Pipeline] echo
Locked resource cause 3-1: not locked yet
[Pipeline] sleep
Sleeping for 2 sec
[Pipeline] echo
VAR IS resource1
[Pipeline] echo
Locked resource cause 1-1: [resource1] is locked by reserveInsideLockHonoured#1 at Sep 17, 2024, 7:10 AM
[Pipeline] echo
Locked resource reservedBy 1-1: null
[Pipeline] echo
Locked resource cause 1-2a: [resource1] is locked by reserveInsideLockHonoured#1 at Sep 17, 2024, 7:10 AM
[Pipeline] echo
Locked resource reservedBy 1-2a: null
[Pipeline] echo
LockableResourcesManager did not reserve an already locked resource; hack it!
[Pipeline] echo
Locked resource cause 1-2b: [resource1] is reserved by test2b at Sep 17, 2024, 7:10 AM
[Pipeline] echo
Locked resource reservedBy 1-2b: test2b
[Pipeline] echo
Unlocking parallel closure 1
[Pipeline] }
Lock released on resource [Label: label1]
[Pipeline] // lock
[Pipeline] echo
Locked resource cause 1-3 (after unlock): [resource1] is reserved by test2b at <unknown>
[Pipeline] echo
Locked resource reservedBy 1-3: test2b
[Pipeline] echo
Ended locked parallel closure 1 with resource reserved, sleeping...
[Pipeline] sleep
Sleeping for 5 sec
[Pipeline] echo
Locked resource cause 2-1: not locked yet
[Pipeline] lock
Trying to acquire lock on [Label: label1]
Found 0 available resource(s). Waiting for correct amount: 1.
Blocking causes: 
  The resource [resource1] is reserved by test2b.
Found 0 available resource(s). Waiting for correct amount: 1.
Blocking causes: 
  The resource [resource1] is reserved by test2b.
[Label: label1] is not free, waiting for execution ...
[Required label: label1] added into queue at position 0
[Pipeline] lock
Trying to acquire lock on [Label: label1]
Found 0 available resource(s). Waiting for correct amount: 1.
Blocking causes: 
  The resource [resource1] is reserved by test2b.
Found 0 available resource(s). Waiting for correct amount: 1.
Blocking causes: 
  The resource [resource1] is reserved by test2b.
[Label: label1] is not free, waiting for execution ...
[Required label: label1] added into queue at position 1
[Pipeline] echo
Locked resource cause 1-4: [resource1] is reserved by test2b at <unknown>
[Pipeline] echo
Locked resource reservedBy 1-4: test2b
[Pipeline] echo
Resetting Locked resource via LRM and sleeping ...
[Pipeline] sleep
Sleeping for 5 sec
[Pipeline] echo
Un-reserving Locked resource via LRM and sleeping...
Lock acquired on [Label: label1]
[Pipeline] sleep
Sleeping for 5 sec
[Pipeline] {
[Pipeline] echo
VAR2 IS resource1
[Pipeline] sleep
Sleeping for 1 sec
[Pipeline] echo
Locked resource cause 2-2: [resource1] is locked by reserveInsideLockHonoured#1 at Sep 17, 2024, 7:10 AM
[Pipeline] echo
Locked resource reservedBy 2-2: null
[Pipeline] echo
Setting (directly) and dropping (via LRM) a reservation on locked resource
[Pipeline] sleep
Sleeping for 3 sec
[Pipeline] echo
Locked resource cause 1-5: [resource1] is reserved by test2-1 at Sep 17, 2024, 7:10 AM
[Pipeline] echo
Locked resource reservedBy 1-5: test2-1
[Pipeline] sleep
Sleeping for 5 sec
[Pipeline] echo
Just sleeping...
[Pipeline] sleep
Sleeping for 20 sec
[Pipeline] sleep
Sleeping for 5 sec
[Pipeline] echo
Locked resource cause 1-6: [resource1] is locked by reserveInsideLockHonoured#1 at <unknown>
"
Stack trace 
java.lang.AssertionError: 

Expected: a string containing "Locked resource reservedBy 1-5: null"
     but: was "Started
[Pipeline] Start of Pipeline
[Pipeline] timeout
Timeout set to expire in 2 min 0 sec
[Pipeline] {
[Pipeline] parallel
[Pipeline] { (Branch: p1)
[Pipeline] { (Branch: p2)
[Pipeline] { (Branch: p3)
[Pipeline] lock
Trying to acquire lock on [Label: label1]
Lock acquired on [Label: label1]
[Pipeline] {
[Pipeline] sleep
Sleeping for 1 sec
[Pipeline] echo
Locked resource cause 3-1: not locked yet
[Pipeline] sleep
Sleeping for 2 sec
[Pipeline] echo
VAR IS resource1
[Pipeline] echo
Locked resource cause 1-1: [resource1] is locked by reserveInsideLockHonoured#1 at Sep 17, 2024, 7:10 AM
[Pipeline] echo
Locked resource reservedBy 1-1: null
[Pipeline] echo
Locked resource cause 1-2a: [resource1] is locked by reserveInsideLockHonoured#1 at Sep 17, 2024, 7:10 AM
[Pipeline] echo
Locked resource reservedBy 1-2a: null
[Pipeline] echo
LockableResourcesManager did not reserve an already locked resource; hack it!
[Pipeline] echo
Locked resource cause 1-2b: [resource1] is reserved by test2b at Sep 17, 2024, 7:10 AM
[Pipeline] echo
Locked resource reservedBy 1-2b: test2b
[Pipeline] echo
Unlocking parallel closure 1
[Pipeline] }
Lock released on resource [Label: label1]
[Pipeline] // lock
[Pipeline] echo
Locked resource cause 1-3 (after unlock): [resource1] is reserved by test2b at <unknown>
[Pipeline] echo
Locked resource reservedBy 1-3: test2b
[Pipeline] echo
Ended locked parallel closure 1 with resource reserved, sleeping...
[Pipeline] sleep
Sleeping for 5 sec
[Pipeline] echo
Locked resource cause 2-1: not locked yet
[Pipeline] lock
Trying to acquire lock on [Label: label1]
Found 0 available resource(s). Waiting for correct amount: 1.
Blocking causes: 
  The resource [resource1] is reserved by test2b.
Found 0 available resource(s). Waiting for correct amount: 1.
Blocking causes: 
  The resource [resource1] is reserved by test2b.
[Label: label1] is not free, waiting for execution ...
[Required label: label1] added into queue at position 0
[Pipeline] lock
Trying to acquire lock on [Label: label1]
Found 0 available resource(s). Waiting for correct amount: 1.
Blocking causes: 
  The resource [resource1] is reserved by test2b.
Found 0 available resource(s). Waiting for correct amount: 1.
Blocking causes: 
  The resource [resource1] is reserved by test2b.
[Label: label1] is not free, waiting for execution ...
[Required label: label1] added into queue at position 1
[Pipeline] echo
Locked resource cause 1-4: [resource1] is reserved by test2b at <unknown>
[Pipeline] echo
Locked resource reservedBy 1-4: test2b
[Pipeline] echo
Resetting Locked resource via LRM and sleeping ...
[Pipeline] sleep
Sleeping for 5 sec
[Pipeline] echo
Un-reserving Locked resource via LRM and sleeping...
Lock acquired on [Label: label1]
[Pipeline] sleep
Sleeping for 5 sec
[Pipeline] {
[Pipeline] echo
VAR2 IS resource1
[Pipeline] sleep
Sleeping for 1 sec
[Pipeline] echo
Locked resource cause 2-2: [resource1] is locked by reserveInsideLockHonoured#1 at Sep 17, 2024, 7:10 AM
[Pipeline] echo
Locked resource reservedBy 2-2: null
[Pipeline] echo
Setting (directly) and dropping (via LRM) a reservation on locked resource
[Pipeline] sleep
Sleeping for 3 sec
[Pipeline] echo
Locked resource cause 1-5: [resource1] is reserved by test2-1 at Sep 17, 2024, 7:10 AM
[Pipeline] echo
Locked resource reservedBy 1-5: test2-1
[Pipeline] sleep
Sleeping for 5 sec
[Pipeline] echo
Just sleeping...
[Pipeline] sleep
Sleeping for 20 sec
[Pipeline] sleep
Sleeping for 5 sec
[Pipeline] echo
Locked resource cause 1-6: [resource1] is locked by reserveInsideLockHonoured#1 at <unknown>
"
	at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
	at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:6)
	at org.jvnet.hudson.test.JenkinsRule.assertLogContains(JenkinsRule.java:1570)
	at org.jenkins.plugins.lockableresources.LockStepTest.reserveInsideLockHonoured(LockStepTest.java:1480)
	at java.base/java.lang.reflect.Method.invoke(Method.java:569)
	at org.jvnet.hudson.test.JenkinsRule$1.evaluate(JenkinsRule.java:655)
	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
	at java.base/java.lang.Thread.run(Thread.java:840)
Standard error 
0.016 [id=448]	INFO	o.jvnet.hudson.test.JenkinsRule#createWebServer: Running on http://localhost:49323/jenkins/
   1.345 [id=461]	INFO	jenkins.InitReactorRunner$1#onAttained: Started initialization
   1.346 [id=460]	INFO	jenkins.InitReactorRunner$1#onAttained: Listed all plugins
   1.349 [id=461]	INFO	j.b.api.BouncyCastlePlugin#start: C:\Jenkins\agent\workspace\lockable-resources-plugin_PR-673\target\tmp\j h3334939523318924432\plugins\bouncycastle-api\WEB-INF\optional-lib not found; for non RealJenkinsRule this is fine and can be ignored.
   1.613 [id=466]	INFO	jenkins.InitReactorRunner$1#onAttained: Prepared all plugins
   1.616 [id=461]	INFO	jenkins.InitReactorRunner$1#onAttained: Started all plugins
   1.617 [id=467]	INFO	jenkins.InitReactorRunner$1#onAttained: Augmented all extensions
   2.802 [id=465]	INFO	jenkins.InitReactorRunner$1#onAttained: System config loaded
   2.825 [id=467]	INFO	jenkins.InitReactorRunner$1#onAttained: System config adapted
   2.825 [id=462]	INFO	jenkins.InitReactorRunner$1#onAttained: Loaded all jobs
   2.826 [id=462]	INFO	o.j.p.l.NodesMirror#createNodeResources: lockable-resources-plugin: configure node resources
   2.826 [id=465]	INFO	jenkins.InitReactorRunner$1#onAttained: Configuration for all jobs updated
   2.927 [id=465]	INFO	jenkins.InitReactorRunner$1#onAttained: Completed initialization
   3.162 [reserveInsideLockHonoured #1] Started
   3.691 [reserveInsideLockHonoured #1] [Pipeline] Start of Pipeline
   3.854 [reserveInsideLockHonoured #1] [Pipeline] timeout
   3.854 [reserveInsideLockHonoured #1] Timeout set to expire in 2 min 0 sec
   3.854 [reserveInsideLockHonoured #1] [Pipeline] {
   3.957 [reserveInsideLockHonoured #1] [Pipeline] parallel
   4.008 [reserveInsideLockHonoured #1] [Pipeline] { (Branch: p1)
   4.008 [reserveInsideLockHonoured #1] [Pipeline] { (Branch: p2)
   4.059 [reserveInsideLockHonoured #1] [Pipeline] { (Branch: p3)
   4.161 [reserveInsideLockHonoured #1] [Pipeline] lock
   4.161 [reserveInsideLockHonoured #1] Trying to acquire lock on [Label: label1]
   4.212 [reserveInsideLockHonoured #1] Lock acquired on [Label: label1]
   4.212 [reserveInsideLockHonoured #1] [Pipeline] {
   4.264 [reserveInsideLockHonoured #1] [Pipeline] sleep
   4.264 [reserveInsideLockHonoured #1] Sleeping for 1 sec
   4.316 [reserveInsideLockHonoured #1] [Pipeline] echo
   4.316 [reserveInsideLockHonoured #1] Locked resource cause 3-1: not locked yet
   4.368 [reserveInsideLockHonoured #1] [Pipeline] sleep
   4.368 [reserveInsideLockHonoured #1] Sleeping for 2 sec
   4.470 [reserveInsideLockHonoured #1] [Pipeline] echo
   4.470 [reserveInsideLockHonoured #1] VAR IS resource1
   4.572 [reserveInsideLockHonoured #1] [Pipeline] echo
   4.572 [reserveInsideLockHonoured #1] Locked resource cause 1-1: [resource1] is locked by reserveInsideLockHonoured#1 at Sep 17, 2024, 7:10 AM
   4.628 [reserveInsideLockHonoured #1] [Pipeline] echo
   4.629 [reserveInsideLockHonoured #1] Locked resource reservedBy 1-1: null
   4.681 [reserveInsideLockHonoured #1] [Pipeline] echo
   4.681 [reserveInsideLockHonoured #1] Locked resource cause 1-2a: [resource1] is locked by reserveInsideLockHonoured#1 at Sep 17, 2024, 7:10 AM
   4.732 [reserveInsideLockHonoured #1] [Pipeline] echo
   4.785 [reserveInsideLockHonoured #1] Locked resource reservedBy 1-2a: null
   4.837 [reserveInsideLockHonoured #1] [Pipeline] echo
   4.839 [reserveInsideLockHonoured #1] LockableResourcesManager did not reserve an already locked resource; hack it!
   4.942 [reserveInsideLockHonoured #1] [Pipeline] echo
   4.942 [reserveInsideLockHonoured #1] Locked resource cause 1-2b: [resource1] is reserved by test2b at Sep 17, 2024, 7:10 AM
   4.995 [reserveInsideLockHonoured #1] [Pipeline] echo
   4.996 [reserveInsideLockHonoured #1] Locked resource reservedBy 1-2b: test2b
   5.050 [reserveInsideLockHonoured #1] [Pipeline] echo
   5.101 [reserveInsideLockHonoured #1] Unlocking parallel closure 1
   5.101 [reserveInsideLockHonoured #1] [Pipeline] }
   5.152 [reserveInsideLockHonoured #1] Lock released on resource [Label: label1]
   5.257 [reserveInsideLockHonoured #1] [Pipeline] // lock
   5.361 [reserveInsideLockHonoured #1] [Pipeline] echo
   5.361 [reserveInsideLockHonoured #1] Locked resource cause 1-3 (after unlock): [resource1] is reserved by test2b at <unknown>
   5.412 [reserveInsideLockHonoured #1] [Pipeline] echo
   5.412 [reserveInsideLockHonoured #1] Locked resource reservedBy 1-3: test2b
   5.463 [reserveInsideLockHonoured #1] [Pipeline] echo
   5.463 [reserveInsideLockHonoured #1] Ended locked parallel closure 1 with resource reserved, sleeping...
   5.514 [reserveInsideLockHonoured #1] [Pipeline] sleep
   5.566 [reserveInsideLockHonoured #1] Sleeping for 5 sec
   5.671 [reserveInsideLockHonoured #1] [Pipeline] echo
   5.671 [reserveInsideLockHonoured #1] Locked resource cause 2-1: not locked yet
   5.722 [reserveInsideLockHonoured #1] [Pipeline] lock
   5.722 [reserveInsideLockHonoured #1] Trying to acquire lock on [Label: label1]
   5.722 [reserveInsideLockHonoured #1] Found 0 available resource(s). Waiting for correct amount: 1.
   5.722 [reserveInsideLockHonoured #1] Blocking causes: 
   5.722 [reserveInsideLockHonoured #1]   The resource [resource1] is reserved by test2b.
   5.722 [reserveInsideLockHonoured #1] Found 0 available resource(s). Waiting for correct amount: 1.
   5.722 [reserveInsideLockHonoured #1] Blocking causes: 
   5.722 [reserveInsideLockHonoured #1]   The resource [resource1] is reserved by test2b.
   5.722 [reserveInsideLockHonoured #1] [Label: label1] is not free, waiting for execution ...
   5.722 [reserveInsideLockHonoured #1] [Required label: label1] added into queue at position 0
   6.440 [reserveInsideLockHonoured #1] [Pipeline] lock
   6.440 [reserveInsideLockHonoured #1] Trying to acquire lock on [Label: label1]
   6.440 [reserveInsideLockHonoured #1] Found 0 available resource(s). Waiting for correct amount: 1.
   6.440 [reserveInsideLockHonoured #1] Blocking causes: 
   6.440 [reserveInsideLockHonoured #1]   The resource [resource1] is reserved by test2b.
   6.440 [reserveInsideLockHonoured #1] Found 0 available resource(s). Waiting for correct amount: 1.
   6.440 [reserveInsideLockHonoured #1] Blocking causes: 
   6.440 [reserveInsideLockHonoured #1]   The resource [resource1] is reserved by test2b.
   6.440 [reserveInsideLockHonoured #1] [Label: label1] is not free, waiting for execution ...
   6.440 [reserveInsideLockHonoured #1] [Required label: label1] added into queue at position 1
  10.609 [reserveInsideLockHonoured #1] [Pipeline] echo
  10.609 [reserveInsideLockHonoured #1] Locked resource cause 1-4: [resource1] is reserved by test2b at <unknown>
  10.637 [id=448]	INFO	o.j.p.l.LockStepTest#reserveInsideLockHonoured: GOOD: Did not encounter Bug #1 (parallel p2 gets the lock on a still-reserved resource)!
  10.660 [reserveInsideLockHonoured #1] [Pipeline] echo
  10.660 [reserveInsideLockHonoured #1] Locked resource reservedBy 1-4: test2b
  10.660 [reserveInsideLockHonoured #1] [Pipeline] echo
  10.711 [reserveInsideLockHonoured #1] Resetting Locked resource via LRM and sleeping ...
  10.763 [reserveInsideLockHonoured #1] [Pipeline] sleep
  10.763 [reserveInsideLockHonoured #1] Sleeping for 5 sec
  15.780 [reserveInsideLockHonoured #1] [Pipeline] echo
  15.831 [reserveInsideLockHonoured #1] Un-reserving Locked resource via LRM and sleeping...
  15.984 [reserveInsideLockHonoured #1] Lock acquired on [Label: label1]
  16.088 [reserveInsideLockHonoured #1] [Pipeline] sleep
  16.139 [reserveInsideLockHonoured #1] Sleeping for 5 sec
  16.241 [reserveInsideLockHonoured #1] [Pipeline] {
  16.600 [reserveInsideLockHonoured #1] [Pipeline] echo
  16.756 [reserveInsideLockHonoured #1] VAR2 IS resource1
  16.911 [reserveInsideLockHonoured #1] [Pipeline] sleep
  16.962 [reserveInsideLockHonoured #1] Sleeping for 1 sec
  17.988 [reserveInsideLockHonoured #1] [Pipeline] echo
  18.040 [reserveInsideLockHonoured #1] Locked resource cause 2-2: [resource1] is locked by reserveInsideLockHonoured#1 at Sep 17, 2024, 7:10 AM
  18.042 [reserveInsideLockHonoured #1] [Pipeline] echo
  18.095 [reserveInsideLockHonoured #1] Locked resource reservedBy 2-2: null
  18.148 [reserveInsideLockHonoured #1] [Pipeline] echo
  18.199 [reserveInsideLockHonoured #1] Setting (directly) and dropping (via LRM) a reservation on locked resource
  18.250 [reserveInsideLockHonoured #1] [Pipeline] sleep
  18.250 [reserveInsideLockHonoured #1] Sleeping for 3 sec
  21.184 [reserveInsideLockHonoured #1] [Pipeline] echo
  21.184 [reserveInsideLockHonoured #1] Locked resource cause 1-5: [resource1] is reserved by test2-1 at Sep 17, 2024, 7:10 AM
  21.235 [reserveInsideLockHonoured #1] [Pipeline] echo
  21.235 [reserveInsideLockHonoured #1] Locked resource reservedBy 1-5: test2-1
  21.286 [reserveInsideLockHonoured #1] [Pipeline] sleep
  21.286 [reserveInsideLockHonoured #1] Sleeping for 5 sec
  21.440 [reserveInsideLockHonoured #1] [Pipeline] echo
  21.492 [reserveInsideLockHonoured #1] Just sleeping...
  21.492 [reserveInsideLockHonoured #1] [Pipeline] sleep
  21.543 [reserveInsideLockHonoured #1] Sleeping for 20 sec
  26.366 [reserveInsideLockHonoured #1] [Pipeline] sleep
  26.366 [reserveInsideLockHonoured #1] Sleeping for 5 sec
  31.433 [reserveInsideLockHonoured #1] [Pipeline] echo
  31.480 [id=448]	INFO	o.j.p.l.LockStepTest#reserveInsideLockHonoured: GOOD: Did not encounter Bug #2a (Parallel 2 did not start after Parallel 1 finished and resource later released)!
  31.484 [reserveInsideLockHonoured #1] Locked resource cause 1-6: [resource1] is locked by reserveInsideLockHonoured#1 at <unknown>
  31.485 [id=448]	WARNING	o.j.h.t.RemainingActivityListener#onTearDown: reserveInsideLockHonoured #1 still seems to be running, which could break deletion of log files or metadata
  31.488 [id=448]	INFO	hudson.lifecycle.Lifecycle#onStatusUpdate: Stopping Jenkins
  31.535 [reserveInsideLockHonoured #1] [Pipeline] echo
  31.535 [reserveInsideLockHonoured #1] Locked resource reservedBy 1-6: null
  31.586 [reserveInsideLockHonoured #1] [Pipeline] }
  31.621 [id=448]	INFO	hudson.lifecycle.Lifecycle#onStatusUpdate: Jenkins stopped
  31.707 [id=448]	INFO	o.j.h.t.TemporaryDirectoryAllocator#dispose: deleting C:\Jenkins\agent\workspace\lockable-resources-plugin_PR-673\target\tmp\j h3334939523318924432
Standard out 
=== Starting reserveInsideLockHonoured(org.jenkins.plugins.lockableresources.LockStepTest)
View more details on ci.jenkins.io