Time to fix flaky tests

[kirek007]

I've spotted today that some tests are randomly failing time to address it:
1: https://github.com/java-operator-sdk/java-operator-sdk/runs/1595178719?check_suite_focus=true#step:5:255
2. https://github.com/java-operator-sdk/java-operator-sdk/runs/1595145125?check_suite_focus=true (I've rerun all jobs which removes previous log, but it was different issues that 1st one) (maybe @metacosm has job log on mail by any chance?)

[metacosm]

I don't think I do but I noticed that as well: I think it's due to the timer event tests…

[s-soroosh]

Here is the log:
/CC @csviri

https://github.com/java-operator-sdk/java-operator-sdk/pull/273/checks?check_run_id=1614205053

Error:  Tests run: 8, Failures: 1, Errors: 0, Skipped: 0, Time elapsed: 1.877 s <<< FAILURE! - in io.javaoperatorsdk.operator.processing.DefaultEventHandlerTest
Error:  io.javaoperatorsdk.operator.processing.DefaultEventHandlerTest.successfulExecutionResetsTheRetry  Time elapsed: 0.037 s  <<< FAILURE!
org.opentest4j.AssertionFailedError: 

Expecting:
 <0>
to be equal to:
 <1>
but was not.
	at io.javaoperatorsdk.operator.processing.DefaultEventHandlerTest.successfulExecutionResetsTheRetry(DefaultEventHandlerTest.java:203)

[metacosm]

Here's the log for one test that's been failing a lot for me lately:

[INFO] Running io.javaoperatorsdk.operator.processing.event.internal.TimerEventSourceTest
2021-01-05 12:35:26,242 28 i.j.o.p.e.i.TimerEventSource   [DEBUG] Producing event for custom resource id: 7874950b-7f76-4ba9-90f0-b855d3422034
2021-01-05 12:35:26,295 28 i.j.o.p.e.i.TimerEventSource   [DEBUG] Producing event for custom resource id: 7874950b-7f76-4ba9-90f0-b855d3422034
2021-01-05 12:35:26,493 29 i.j.o.p.e.i.TimerEventSource   [DEBUG] Producing event for custom resource id: 7b4b5962-4c2d-4b42-b575-b5a1e8736f5d
2021-01-05 12:35:26,627 30 i.j.o.p.e.i.TimerEventSource   [DEBUG] Producing event for custom resource id: 89b84d62-4c4d-4dd6-85bb-69b4fe3ef527
2021-01-05 12:35:26,774 31 i.j.o.p.e.i.TimerEventSource   [DEBUG] Producing event for custom resource id: 37ed3fd0-3e24-482c-85a7-a4a83fb47b70
2021-01-05 12:35:26,826 31 i.j.o.p.e.i.TimerEventSource   [DEBUG] Producing event for custom resource id: 37ed3fd0-3e24-482c-85a7-a4a83fb47b70
[ERROR] Tests run: 6, Failures: 1, Errors: 0, Skipped: 0, Time elapsed: 0.956 s <<< FAILURE! - in io.javaoperatorsdk.operator.processing.event.internal.TimerEventSourceTest
[ERROR] io.javaoperatorsdk.operator.processing.event.internal.TimerEventSourceTest.producesEventsPeriodically  Time elapsed: 0.134 s  <<< FAILURE!
org.mockito.exceptions.verification.TooFewActualInvocations: 

eventHandler.handleEvent(
    <Capturing argument>
);
Wanted 2 times:
-> at io.javaoperatorsdk.operator.processing.event.internal.TimerEventSourceTest.producesEventsPeriodically(TimerEventSourceTest.java:44)
But was 1 time:
-> at io.javaoperatorsdk.operator.processing.event.internal.TimerEventSource$EventProducerTimeTask.run(TimerEventSource.java:73)

        at io.javaoperatorsdk.operator.processing.event.internal.TimerEventSourceTest.producesEventsPeriodically(TimerEventSourceTest.java:44)

2021-01-05 12:35:26,877 31 i.j.o.p.e.i.TimerEventSource   [DEBUG] Producing event for custom resource id: 37ed3fd0-3e24-482c-85a7-a4a83fb47b70

[csviri]

Hi, kinda busy nowadays, won't be able to look on this soon :(

[metacosm]

See also: https://github.com/java-operator-sdk/java-operator-sdk/runs/2060618098?check_suite_focus=true#step:4:2205

[metacosm]

Here's a failed run log: https://gist.github.com/metacosm/a4da733ab3658dfec2f5160f43d85492

[metacosm]

Here's another run:

2021-08-26 03:12:32,968 1 i.f.k.c.CustomResource         [DEBUG] Calling CustomResource#setKind doesn't do anything because the Kind is computed and shouldn't be changed
2021-08-26 03:12:32,976 1 i.j.o.p.DefaultEventHandler    [DEBUG] Received event: CustomResourceEvent{action=MODIFIED, resource=[ name=test-custom-resource, kind=TestCustomResource, apiVersion=sample.javaoperatorsdk.io/v1 ,resourceVersion=null, markedForDeletion: false ]}
2021-08-26 03:12:32,980 1 i.f.k.c.CustomResource         [DEBUG] Calling CustomResource#setKind doesn't do anything because the Kind is computed and shouldn't be changed
2021-08-26 03:12:32,981 1 i.f.k.c.CustomResource         [DEBUG] Calling CustomResource#setKind doesn't do anything because the Kind is computed and shouldn't be changed
2021-08-26 03:12:32,984 1 i.j.o.p.DefaultEventHandler    [DEBUG] Event processing finished. Scope: ExecutionScope{events=[CustomResourceEvent{action=MODIFIED, resource=[ name=test-custom-resource, kind=TestCustomResource, apiVersion=sample.javaoperatorsdk.io/v1 ,resourceVersion=null, markedForDeletion: false ]}], customResource uid: 2b22bd8b-49b1-47f2-b6ed-02a50d2f5a95, version: null}, PostExecutionControl: PostExecutionControl{onlyFinalizerHandled=false, updatedCustomResource=null, runtimeException=java.lang.RuntimeException: test}
2021-08-26 03:12:32,986 1 i.j.o.p.DefaultEventHandler    [DEBUG] Scheduling timer event for retry with delay:2000 for resource: 2b22bd8b-49b1-47f2-b6ed-02a50d2f5a95
2021-08-26 03:12:32,991 1 i.f.k.c.CustomResource         [DEBUG] Calling CustomResource#setKind doesn't do anything because the Kind is computed and shouldn't be changed
2021-08-26 03:12:32,991 1 i.j.o.p.DefaultEventHandler    [DEBUG] Received event: CustomResourceEvent{action=MODIFIED, resource=[ name=test-custom-resource, kind=TestCustomResource, apiVersion=sample.javaoperatorsdk.io/v1 ,resourceVersion=null, markedForDeletion: false ]}
2021-08-26 03:12:33,002 1 i.j.o.p.DefaultEventHandler    [DEBUG] Executing events for custom resource. Scope: ExecutionScope{events=[CustomResourceEvent{action=MODIFIED, resource=[ name=test-custom-resource, kind=TestCustomResource, apiVersion=sample.javaoperatorsdk.io/v1 ,resourceVersion=null, markedForDeletion: false ]}], customResource uid: 599a09ce-4481-4c11-97da-570834561e18, version: null}
2021-08-26 03:12:33,003 1 i.j.o.p.DefaultEventHandler    [DEBUG] Received event: { class=io.javaoperatorsdk.operator.processing.event.internal.TimerEvent, customResourcesSelector=UIDMatchingPredicate{uid='599a09ce-4481-4c11-97da-570834561e18'}, eventSource=null }
2021-08-26 03:12:33,004 1 i.j.o.p.DefaultEventHandler    [DEBUG] Skipping executing controller for resource id: 599a09ce-4481-4c11-97da-570834561e18. Events in queue: true. Controller in execution: true. Latest CustomResource present: true
2021-08-26 03:12:33,005 1 i.f.k.c.CustomResource         [DEBUG] Calling CustomResource#setKind doesn't do anything because the Kind is computed and shouldn't be changed
2021-08-26 03:12:33,005 1 i.j.o.p.DefaultEventHandler    [DEBUG] Received event: CustomResourceEvent{action=MODIFIED, resource=[ name=test-custom-resource, kind=TestCustomResource, apiVersion=sample.javaoperatorsdk.io/v1 ,resourceVersion=null, markedForDeletion: false ]}
2021-08-26 03:12:33,006 1 i.j.o.p.DefaultEventHandler    [DEBUG] Skipping executing controller for resource id: 599a09ce-4481-4c11-97da-570834561e18. Events in queue: true. Controller in execution: true. Latest CustomResource present: true
2021-08-26 03:12:33,262 19 i.j.o.p.DefaultEventHandler    [DEBUG] Event processing finished. Scope: ExecutionScope{events=[CustomResourceEvent{action=MODIFIED, resource=[ name=test-custom-resource, kind=TestCustomResource, apiVersion=sample.javaoperatorsdk.io/v1 ,resourceVersion=null, markedForDeletion: false ]}], customResource uid: 599a09ce-4481-4c11-97da-570834561e18, version: null}, PostExecutionControl: PostExecutionControl{onlyFinalizerHandled=false, updatedCustomResource=null, runtimeException=null}
2021-08-26 03:12:33,263 19 i.j.o.p.DefaultEventHandler    [DEBUG] Executing events for custom resource. Scope: ExecutionScope{events=[{ class=io.javaoperatorsdk.operator.processing.event.internal.TimerEvent, customResourcesSelector=UIDMatchingPredicate{uid='599a09ce-4481-4c11-97da-570834561e18'}, eventSource=null }, CustomResourceEvent{action=MODIFIED, resource=[ name=test-custom-resource, kind=TestCustomResource, apiVersion=sample.javaoperatorsdk.io/v1 ,resourceVersion=null, markedForDeletion: false ]}], customResource uid: 599a09ce-4481-4c11-97da-570834561e18, version: null}
2021-08-26 03:12:33,269 1 i.f.k.c.CustomResource         [DEBUG] Calling CustomResource#setKind doesn't do anything because the Kind is computed and shouldn't be changed
2021-08-26 03:12:33,269 1 i.j.o.p.DefaultEventHandler    [DEBUG] Received event: CustomResourceEvent{action=MODIFIED, resource=[ name=test-custom-resource, kind=TestCustomResource, apiVersion=sample.javaoperatorsdk.io/v1 ,resourceVersion=null, markedForDeletion: false ]}
2021-08-26 03:12:33,284 1 i.j.o.p.DefaultEventHandler    [DEBUG] Executing events for custom resource. Scope: ExecutionScope{events=[CustomResourceEvent{action=MODIFIED, resource=[ name=test-custom-resource, kind=TestCustomResource, apiVersion=sample.javaoperatorsdk.io/v1 ,resourceVersion=null, markedForDeletion: false ]}], customResource uid: cf5aec28-27b0-4766-903d-0aa78d18f3ce, version: null}
2021-08-26 03:12:33,285 1 i.j.o.p.DefaultEventHandler    [DEBUG] Received event: { class=io.javaoperatorsdk.operator.processing.event.internal.TimerEvent, customResourcesSelector=UIDMatchingPredicate{uid='cf5aec28-27b0-4766-903d-0aa78d18f3ce'}, eventSource=null }
2021-08-26 03:12:33,286 1 i.j.o.p.DefaultEventHandler    [DEBUG] Skipping executing controller for resource id: cf5aec28-27b0-4766-903d-0aa78d18f3ce. Events in queue: true. Controller in execution: true. Latest CustomResource present: true
2021-08-26 03:12:33,304 1 i.f.k.c.CustomResource         [DEBUG] Calling CustomResource#setKind doesn't do anything because the Kind is computed and shouldn't be changed
2021-08-26 03:12:33,304 1 i.f.k.c.CustomResource         [DEBUG] Calling CustomResource#setKind doesn't do anything because the Kind is computed and shouldn't be changed
2021-08-26 03:12:33,304 1 i.j.o.p.DefaultEventHandler    [DEBUG] Received event: CustomResourceEvent{action=MODIFIED, resource=[ name=test-custom-resource, kind=TestCustomResource, apiVersion=sample.javaoperatorsdk.io/v1 ,resourceVersion=null, markedForDeletion: false ]}
2021-08-26 03:12:33,321 1 i.j.o.p.DefaultEventHandler    [DEBUG] Executing events for custom resource. Scope: ExecutionScope{events=[CustomResourceEvent{action=MODIFIED, resource=[ name=test-custom-resource, kind=TestCustomResource, apiVersion=sample.javaoperatorsdk.io/v1 ,resourceVersion=null, markedForDeletion: false ]}], customResource uid: eb75cb09-8836-4eed-8018-93d477465759, version: null}
2021-08-26 03:12:33,331 22 i.j.o.p.DefaultEventHandler    [DEBUG] Event processing finished. Scope: ExecutionScope{events=[CustomResourceEvent{action=MODIFIED, resource=[ name=test-custom-resource, kind=TestCustomResource, apiVersion=sample.javaoperatorsdk.io/v1 ,resourceVersion=null, markedForDeletion: false ]}], customResource uid: eb75cb09-8836-4eed-8018-93d477465759, version: null}, PostExecutionControl: null
2021-08-26 03:12:33,332 1 i.j.o.p.DefaultEventHandler    [DEBUG] Received event: CustomResourceEvent{action=MODIFIED, resource=[ name=test-custom-resource, kind=TestCustomResource, apiVersion=sample.javaoperatorsdk.io/v1 ,resourceVersion=null, markedForDeletion: false ]}
2021-08-26 03:12:33,335 1 i.j.o.p.DefaultEventHandler    [DEBUG] Executing events for custom resource. Scope: ExecutionScope{events=[CustomResourceEvent{action=MODIFIED, resource=[ name=test-custom-resource, kind=TestCustomResource, apiVersion=sample.javaoperatorsdk.io/v1 ,resourceVersion=null, markedForDeletion: false ]}], customResource uid: eb75cb09-8836-4eed-8018-93d477465759, version: null}
2021-08-26 03:12:33,340 22 i.j.o.p.DefaultEventHandler    [DEBUG] Event processing finished. Scope: ExecutionScope{events=[CustomResourceEvent{action=MODIFIED, resource=[ name=test-custom-resource, kind=TestCustomResource, apiVersion=sample.javaoperatorsdk.io/v1 ,resourceVersion=null, markedForDeletion: false ]}], customResource uid: eb75cb09-8836-4eed-8018-93d477465759, version: null}, PostExecutionControl: null
2021-08-26 03:12:33,514 19 i.j.o.p.DefaultEventHandler    [DEBUG] Event processing finished. Scope: ExecutionScope{events=[{ class=io.javaoperatorsdk.operator.processing.event.internal.TimerEvent, customResourcesSelector=UIDMatchingPredicate{uid='599a09ce-4481-4c11-97da-570834561e18'}, eventSource=null }, CustomResourceEvent{action=MODIFIED, resource=[ name=test-custom-resource, kind=TestCustomResource, apiVersion=sample.javaoperatorsdk.io/v1 ,resourceVersion=null, markedForDeletion: false ]}], customResource uid: 599a09ce-4481-4c11-97da-570834561e18, version: null}, PostExecutionControl: PostExecutionControl{onlyFinalizerHandled=false, updatedCustomResource=null, runtimeException=null}
2021-08-26 03:12:33,515 19 i.j.o.p.DefaultEventHandler    [DEBUG] Skipping executing controller for resource id: 599a09ce-4481-4c11-97da-570834561e18. Events in queue: false. Controller in execution: false. Latest CustomResource present: true
2021-08-26 03:12:33,537 21 i.j.o.p.DefaultEventHandler    [DEBUG] Event processing finished. Scope: ExecutionScope{events=[CustomResourceEvent{action=MODIFIED, resource=[ name=test-custom-resource, kind=TestCustomResource, apiVersion=sample.javaoperatorsdk.io/v1 ,resourceVersion=null, markedForDeletion: false ]}], customResource uid: cf5aec28-27b0-4766-903d-0aa78d18f3ce, version: null}, PostExecutionControl: PostExecutionControl{onlyFinalizerHandled=false, updatedCustomResource=null, runtimeException=null}
2021-08-26 03:12:33,538 21 i.j.o.p.DefaultEventHandler    [DEBUG] Executing events for custom resource. Scope: ExecutionScope{events=[{ class=io.javaoperatorsdk.operator.processing.event.internal.TimerEvent, customResourcesSelector=UIDMatchingPredicate{uid='cf5aec28-27b0-4766-903d-0aa78d18f3ce'}, eventSource=null }], customResource uid: cf5aec28-27b0-4766-903d-0aa78d18f3ce, version: null}
2021-08-26 03:12:33,789 21 i.j.o.p.DefaultEventHandler    [DEBUG] Event processing finished. Scope: ExecutionScope{events=[{ class=io.javaoperatorsdk.operator.processing.event.internal.TimerEvent, customResourcesSelector=UIDMatchingPredicate{uid='cf5aec28-27b0-4766-903d-0aa78d18f3ce'}, eventSource=null }], customResource uid: cf5aec28-27b0-4766-903d-0aa78d18f3ce, version: null}, PostExecutionControl: PostExecutionControl{onlyFinalizerHandled=false, updatedCustomResource=null, runtimeException=null}
2021-08-26 03:12:33,791 21 i.j.o.p.DefaultEventHandler    [DEBUG] Skipping executing controller for resource id: cf5aec28-27b0-4766-903d-0aa78d18f3ce. Events in queue: false. Controller in execution: false. Latest CustomResource present: true
2021-08-26 03:12:33,797 1 i.f.k.c.CustomResource         [DEBUG] Calling CustomResource#setKind doesn't do anything because the Kind is computed and shouldn't be changed
2021-08-26 03:12:33,797 1 i.j.o.p.DefaultEventHandler    [DEBUG] Received event: CustomResourceEvent{action=DELETED, resource=[ name=test-custom-resource, kind=TestCustomResource, apiVersion=sample.javaoperatorsdk.io/v1 ,resourceVersion=null, markedForDeletion: false ]}
2021-08-26 03:12:33,808 1 i.j.o.p.DefaultEventHandler    [DEBUG] Executing events for custom resource. Scope: ExecutionScope{events=[CustomResourceEvent{action=DELETED, resource=[ name=test-custom-resource, kind=TestCustomResource, apiVersion=sample.javaoperatorsdk.io/v1 ,resourceVersion=null, markedForDeletion: false ]}], customResource uid: 5f34d425-1544-4c31-93fb-8f15f8414a60, version: null}
2021-08-26 03:12:33,809 25 i.j.o.p.DefaultEventHandler    [DEBUG] Event processing finished. Scope: ExecutionScope{events=[CustomResourceEvent{action=DELETED, resource=[ name=test-custom-resource, kind=TestCustomResource, apiVersion=sample.javaoperatorsdk.io/v1 ,resourceVersion=null, markedForDeletion: false ]}], customResource uid: 5f34d425-1544-4c31-93fb-8f15f8414a60, version: null}, PostExecutionControl: null
2021-08-26 03:12:33,867 1 i.j.o.p.DefaultEventHandlerTest [INFO ] Starting successfulExecutionResetsTheRetry
2021-08-26 03:12:33,867 1 i.f.k.c.CustomResource         [DEBUG] Calling CustomResource#setKind doesn't do anything because the Kind is computed and shouldn't be changed
2021-08-26 03:12:33,867 1 i.f.k.c.CustomResource         [DEBUG] Calling CustomResource#setKind doesn't do anything because the Kind is computed and shouldn't be changed
2021-08-26 03:12:33,868 1 i.j.o.p.DefaultEventHandler    [DEBUG] Received event: CustomResourceEvent{action=MODIFIED, resource=[ name=test-custom-resource, kind=TestCustomResource, apiVersion=sample.javaoperatorsdk.io/v1 ,resourceVersion=null, markedForDeletion: false ]}
2021-08-26 03:12:33,880 1 i.j.o.p.DefaultEventHandler    [DEBUG] Executing events for custom resource. Scope: ExecutionScope{events=[CustomResourceEvent{action=MODIFIED, resource=[ name=test-custom-resource, kind=TestCustomResource, apiVersion=sample.javaoperatorsdk.io/v1 ,resourceVersion=null, markedForDeletion: false ]}], customResource uid: cf1add4a-a9a8-4bef-abc8-64152a52fe90, version: null}
2021-08-26 03:12:33,881 26 i.j.o.p.DefaultEventHandler    [DEBUG] Event processing finished. Scope: ExecutionScope{events=[CustomResourceEvent{action=MODIFIED, resource=[ name=test-custom-resource, kind=TestCustomResource, apiVersion=sample.javaoperatorsdk.io/v1 ,resourceVersion=null, markedForDeletion: false ]}], customResource uid: cf1add4a-a9a8-4bef-abc8-64152a52fe90, version: null}, PostExecutionControl: PostExecutionControl{onlyFinalizerHandled=false, updatedCustomResource=null, runtimeException=java.lang.RuntimeException: test}
2021-08-26 03:12:33,881 26 i.j.o.p.DefaultEventHandler    [DEBUG] Scheduling timer event for retry with delay:2000 for resource: cf1add4a-a9a8-4bef-abc8-64152a52fe90
2021-08-26 03:12:33,891 1 i.j.o.p.DefaultEventHandler    [DEBUG] Received event: CustomResourceEvent{action=MODIFIED, resource=[ name=test-custom-resource, kind=TestCustomResource, apiVersion=sample.javaoperatorsdk.io/v1 ,resourceVersion=null, markedForDeletion: false ]}
2021-08-26 03:12:33,902 1 i.j.o.p.DefaultEventHandler    [DEBUG] Executing events for custom resource. Scope: ExecutionScope{events=[CustomResourceEvent{action=MODIFIED, resource=[ name=test-custom-resource, kind=TestCustomResource, apiVersion=sample.javaoperatorsdk.io/v1 ,resourceVersion=null, markedForDeletion: false ]}, CustomResourceEvent{action=MODIFIED, resource=[ name=test-custom-resource, kind=TestCustomResource, apiVersion=sample.javaoperatorsdk.io/v1 ,resourceVersion=null, markedForDeletion: false ]}], customResource uid: cf1add4a-a9a8-4bef-abc8-64152a52fe90, version: null}
2021-08-26 03:12:33,904 1 i.j.o.p.DefaultEventHandler    [DEBUG] Received event: CustomResourceEvent{action=MODIFIED, resource=[ name=test-custom-resource, kind=TestCustomResource, apiVersion=sample.javaoperatorsdk.io/v1 ,resourceVersion=null, markedForDeletion: false ]}
2021-08-26 03:12:33,905 1 i.j.o.p.DefaultEventHandler    [DEBUG] Skipping executing controller for resource id: cf1add4a-a9a8-4bef-abc8-64152a52fe90. Events in queue: true. Controller in execution: true. Latest CustomResource present: true
2021-08-26 03:12:33,905 26 i.j.o.p.DefaultEventHandler    [DEBUG] Event processing finished. Scope: ExecutionScope{events=[CustomResourceEvent{action=MODIFIED, resource=[ name=test-custom-resource, kind=TestCustomResource, apiVersion=sample.javaoperatorsdk.io/v1 ,resourceVersion=null, markedForDeletion: false ]}, CustomResourceEvent{action=MODIFIED, resource=[ name=test-custom-resource, kind=TestCustomResource, apiVersion=sample.javaoperatorsdk.io/v1 ,resourceVersion=null, markedForDeletion: false ]}], customResource uid: cf1add4a-a9a8-4bef-abc8-64152a52fe90, version: null}, PostExecutionControl: PostExecutionControl{onlyFinalizerHandled=false, updatedCustomResource=null, runtimeException=null}
2021-08-26 03:12:33,906 26 i.j.o.p.DefaultEventHandler    [DEBUG] Marking successful execution for resource: test-custom-resource
2021-08-26 03:12:33,906 26 i.j.o.p.DefaultEventHandler    [DEBUG] Executing events for custom resource. Scope: ExecutionScope{events=[CustomResourceEvent{action=MODIFIED, resource=[ name=test-custom-resource, kind=TestCustomResource, apiVersion=sample.javaoperatorsdk.io/v1 ,resourceVersion=null, markedForDeletion: false ]}], customResource uid: cf1add4a-a9a8-4bef-abc8-64152a52fe90, version: null}
2021-08-26 03:12:33,908 27 i.j.o.p.DefaultEventHandler    [DEBUG] Event processing finished. Scope: ExecutionScope{events=[CustomResourceEvent{action=MODIFIED, resource=[ name=test-custom-resource, kind=TestCustomResource, apiVersion=sample.javaoperatorsdk.io/v1 ,resourceVersion=null, markedForDeletion: false ]}], customResource uid: cf1add4a-a9a8-4bef-abc8-64152a52fe90, version: null}, PostExecutionControl: PostExecutionControl{onlyFinalizerHandled=false, updatedCustomResource=null, runtimeException=null}
2021-08-26 03:12:33,908 27 i.j.o.p.DefaultEventHandler    [DEBUG] Marking successful execution for resource: test-custom-resource
2021-08-26 03:12:33,909 27 i.j.o.p.DefaultEventHandler    [DEBUG] Skipping executing controller for resource id: cf1add4a-a9a8-4bef-abc8-64152a52fe90. Events in queue: false. Controller in execution: false. Latest CustomResource present: true
2021-08-26 03:12:33,916 1 i.j.o.p.DefaultEventHandlerTest [INFO ] Finished successfulExecutionResetsTheRetry
2021-08-26 03:12:33,941 1 i.f.k.c.CustomResource         [DEBUG] Calling CustomResource#setKind doesn't do anything because the Kind is computed and shouldn't be changed
2021-08-26 03:12:33,941 1 i.j.o.p.DefaultEventHandler    [DEBUG] Received event: CustomResourceEvent{action=MODIFIED, resource=[ name=test-custom-resource, kind=TestCustomResource, apiVersion=sample.javaoperatorsdk.io/v1 ,resourceVersion=null, markedForDeletion: false ]}
2021-08-26 03:12:33,957 1 i.j.o.p.DefaultEventHandler    [DEBUG] Executing events for custom resource. Scope: ExecutionScope{events=[CustomResourceEvent{action=MODIFIED, resource=[ name=test-custom-resource, kind=TestCustomResource, apiVersion=sample.javaoperatorsdk.io/v1 ,resourceVersion=null, markedForDeletion: false ]}], customResource uid: d6952375-40bd-44e1-b455-b9388c46084c, version: null}
2021-08-26 03:12:33,959 29 i.j.o.p.DefaultEventHandler    [DEBUG] Event processing finished. Scope: ExecutionScope{events=[CustomResourceEvent{action=MODIFIED, resource=[ name=test-custom-resource, kind=TestCustomResource, apiVersion=sample.javaoperatorsdk.io/v1 ,resourceVersion=null, markedForDeletion: false ]}], customResource uid: d6952375-40bd-44e1-b455-b9388c46084c, version: null}, PostExecutionControl: null
Error:  Tests run: 8, Failures: 1, Errors: 0, Skipped: 0, Time elapsed: 1.034 s <<< FAILURE! - in io.javaoperatorsdk.operator.processing.DefaultEventHandlerTest
Error:  io.javaoperatorsdk.operator.processing.DefaultEventHandlerTest.executesTheControllerInstantlyAfterErrorIfEventsBuffered  Time elapsed: 0.494 s  <<< FAILURE!
org.mockito.exceptions.verification.TooManyActualInvocations: 

eventDispatcher.handleExecution(<any>);
Wanted 1 time:
-> at io.javaoperatorsdk.operator.processing.DefaultEventHandlerTest.executesTheControllerInstantlyAfterErrorIfEventsBuffered(DefaultEventHandlerTest.java:174)
But was 2 times:
-> at io.javaoperatorsdk.operator.processing.ExecutionConsumer.run(ExecutionConsumer.java:25)
-> at io.javaoperatorsdk.operator.processing.ExecutionConsumer.run(ExecutionConsumer.java:25)


	at io.javaoperatorsdk.operator.processing.DefaultEventHandlerTest.executesTheControllerInstantlyAfterErrorIfEventsBuffered(DefaultEventHandlerTest.java:174)

[metacosm]

Yet another log:

[INFO] Running io.javaoperatorsdk.operator.processing.DefaultEventHandlerTest
2021-08-26 16:37:11,844 1 i.f.k.c.CustomResource         [DEBUG] Calling CustomResource#setKind doesn't do anything because the Kind is computed and shouldn't be changed
2021-08-26 16:37:11,847 1 i.j.o.p.DefaultEventHandler    [DEBUG] Received event: CustomResourceEvent{action=MODIFIED, resource=[ name=test-custom-resource, kind=TestCustomResource, apiVersion=sample.javaoperatorsdk.io/v1 ,resourceVersion=null, markedForDeletion: false ]}
2021-08-26 16:37:11,857 1 i.f.k.c.CustomResource         [DEBUG] Calling CustomResource#setKind doesn't do anything because the Kind is computed and shouldn't be changed
2021-08-26 16:37:11,858 1 i.f.k.c.CustomResource         [DEBUG] Calling CustomResource#setKind doesn't do anything because the Kind is computed and shouldn't be changed
2021-08-26 16:37:11,859 1 i.j.o.p.DefaultEventHandler    [DEBUG] Event processing finished. Scope: ExecutionScope{events=[CustomResourceEvent{action=MODIFIED, resource=[ name=test-custom-resource, kind=TestCustomResource, apiVersion=sample.javaoperatorsdk.io/v1 ,resourceVersion=null, markedForDeletion: false ]}], customResource uid: 5fcbd3ca-99c2-4a75-ae47-6605688b4d06, version: null}, PostExecutionControl: PostExecutionControl{onlyFinalizerHandled=false, updatedCustomResource=null, runtimeException=java.lang.RuntimeException: test}
2021-08-26 16:37:11,860 1 i.j.o.p.DefaultEventHandler    [DEBUG] Scheduling timer event for retry with delay:2000 for resource: 5fcbd3ca-99c2-4a75-ae47-6605688b4d06
2021-08-26 16:37:11,872 1 i.f.k.c.CustomResource         [DEBUG] Calling CustomResource#setKind doesn't do anything because the Kind is computed and shouldn't be changed
2021-08-26 16:37:11,873 1 i.j.o.p.DefaultEventHandler    [DEBUG] Received event: CustomResourceEvent{action=MODIFIED, resource=[ name=test-custom-resource, kind=TestCustomResource, apiVersion=sample.javaoperatorsdk.io/v1 ,resourceVersion=null, markedForDeletion: false ]}
2021-08-26 16:37:11,894 1 i.j.o.p.DefaultEventHandler    [DEBUG] Executing events for custom resource. Scope: ExecutionScope{events=[CustomResourceEvent{action=MODIFIED, resource=[ name=test-custom-resource, kind=TestCustomResource, apiVersion=sample.javaoperatorsdk.io/v1 ,resourceVersion=null, markedForDeletion: false ]}], customResource uid: f4983541-06b5-4ee8-a173-33455d17fe48, version: null}
2021-08-26 16:37:11,895 1 i.j.o.p.DefaultEventHandler    [DEBUG] Received event: { class=io.javaoperatorsdk.operator.processing.event.internal.TimerEvent, customResourcesSelector=UIDMatchingPredicate{uid='f4983541-06b5-4ee8-a173-33455d17fe48'}, eventSource=null }
2021-08-26 16:37:11,897 1 i.j.o.p.DefaultEventHandler    [DEBUG] Skipping executing controller for resource id: f4983541-06b5-4ee8-a173-33455d17fe48. Events in queue: true. Controller in execution: true. Latest CustomResource present: true
2021-08-26 16:37:11,897 1 i.f.k.c.CustomResource         [DEBUG] Calling CustomResource#setKind doesn't do anything because the Kind is computed and shouldn't be changed
2021-08-26 16:37:11,898 1 i.j.o.p.DefaultEventHandler    [DEBUG] Received event: CustomResourceEvent{action=MODIFIED, resource=[ name=test-custom-resource, kind=TestCustomResource, apiVersion=sample.javaoperatorsdk.io/v1 ,resourceVersion=null, markedForDeletion: false ]}
2021-08-26 16:37:11,900 1 i.j.o.p.DefaultEventHandler    [DEBUG] Skipping executing controller for resource id: f4983541-06b5-4ee8-a173-33455d17fe48. Events in queue: true. Controller in execution: true. Latest CustomResource present: true
2021-08-26 16:37:12,149 26 i.j.o.p.DefaultEventHandler    [DEBUG] Event processing finished. Scope: ExecutionScope{events=[CustomResourceEvent{action=MODIFIED, resource=[ name=test-custom-resource, kind=TestCustomResource, apiVersion=sample.javaoperatorsdk.io/v1 ,resourceVersion=null, markedForDeletion: false ]}], customResource uid: f4983541-06b5-4ee8-a173-33455d17fe48, version: null}, PostExecutionControl: PostExecutionControl{onlyFinalizerHandled=false, updatedCustomResource=null, runtimeException=null}
2021-08-26 16:37:12,152 26 i.j.o.p.DefaultEventHandler    [DEBUG] Executing events for custom resource. Scope: ExecutionScope{events=[{ class=io.javaoperatorsdk.operator.processing.event.internal.TimerEvent, customResourcesSelector=UIDMatchingPredicate{uid='f4983541-06b5-4ee8-a173-33455d17fe48'}, eventSource=null }, CustomResourceEvent{action=MODIFIED, resource=[ name=test-custom-resource, kind=TestCustomResource, apiVersion=sample.javaoperatorsdk.io/v1 ,resourceVersion=null, markedForDeletion: false ]}], customResource uid: f4983541-06b5-4ee8-a173-33455d17fe48, version: null}
2021-08-26 16:37:12,163 1 i.f.k.c.CustomResource         [DEBUG] Calling CustomResource#setKind doesn't do anything because the Kind is computed and shouldn't be changed
2021-08-26 16:37:12,163 1 i.j.o.p.DefaultEventHandler    [DEBUG] Received event: CustomResourceEvent{action=MODIFIED, resource=[ name=test-custom-resource, kind=TestCustomResource, apiVersion=sample.javaoperatorsdk.io/v1 ,resourceVersion=null, markedForDeletion: false ]}
2021-08-26 16:37:12,183 1 i.j.o.p.DefaultEventHandler    [DEBUG] Executing events for custom resource. Scope: ExecutionScope{events=[CustomResourceEvent{action=MODIFIED, resource=[ name=test-custom-resource, kind=TestCustomResource, apiVersion=sample.javaoperatorsdk.io/v1 ,resourceVersion=null, markedForDeletion: false ]}], customResource uid: 1a2defe5-eb8f-44e1-8cb2-00ef53f07d43, version: null}
2021-08-26 16:37:12,183 1 i.j.o.p.DefaultEventHandler    [DEBUG] Received event: { class=io.javaoperatorsdk.operator.processing.event.internal.TimerEvent, customResourcesSelector=UIDMatchingPredicate{uid='1a2defe5-eb8f-44e1-8cb2-00ef53f07d43'}, eventSource=null }
2021-08-26 16:37:12,185 1 i.j.o.p.DefaultEventHandler    [DEBUG] Skipping executing controller for resource id: 1a2defe5-eb8f-44e1-8cb2-00ef53f07d43. Events in queue: true. Controller in execution: true. Latest CustomResource present: true
2021-08-26 16:37:12,204 1 i.f.k.c.CustomResource         [DEBUG] Calling CustomResource#setKind doesn't do anything because the Kind is computed and shouldn't be changed
2021-08-26 16:37:12,204 1 i.f.k.c.CustomResource         [DEBUG] Calling CustomResource#setKind doesn't do anything because the Kind is computed and shouldn't be changed
2021-08-26 16:37:12,205 1 i.j.o.p.DefaultEventHandler    [DEBUG] Received event: CustomResourceEvent{action=MODIFIED, resource=[ name=test-custom-resource, kind=TestCustomResource, apiVersion=sample.javaoperatorsdk.io/v1 ,resourceVersion=null, markedForDeletion: false ]}
2021-08-26 16:37:12,223 1 i.j.o.p.DefaultEventHandler    [DEBUG] Executing events for custom resource. Scope: ExecutionScope{events=[CustomResourceEvent{action=MODIFIED, resource=[ name=test-custom-resource, kind=TestCustomResource, apiVersion=sample.javaoperatorsdk.io/v1 ,resourceVersion=null, markedForDeletion: false ]}], customResource uid: e5748375-f2d4-446f-9ae7-6c39d77abe00, version: null}
2021-08-26 16:37:12,223 1 i.j.o.p.DefaultEventHandler    [DEBUG] Received event: CustomResourceEvent{action=MODIFIED, resource=[ name=test-custom-resource, kind=TestCustomResource, apiVersion=sample.javaoperatorsdk.io/v1 ,resourceVersion=null, markedForDeletion: false ]}
2021-08-26 16:37:12,226 1 i.j.o.p.DefaultEventHandler    [DEBUG] Skipping executing controller for resource id: e5748375-f2d4-446f-9ae7-6c39d77abe00. Events in queue: true. Controller in execution: true. Latest CustomResource present: true
2021-08-26 16:37:12,227 29 i.j.o.p.DefaultEventHandler    [DEBUG] Event processing finished. Scope: ExecutionScope{events=[CustomResourceEvent{action=MODIFIED, resource=[ name=test-custom-resource, kind=TestCustomResource, apiVersion=sample.javaoperatorsdk.io/v1 ,resourceVersion=null, markedForDeletion: false ]}], customResource uid: e5748375-f2d4-446f-9ae7-6c39d77abe00, version: null}, PostExecutionControl: null
2021-08-26 16:37:12,237 1 i.j.o.p.DefaultEventHandler    [DEBUG] Event processing finished. Scope: ExecutionScope{events=[CustomResourceEvent{action=MODIFIED, resource=[ name=test-custom-resource, kind=TestCustomResource, apiVersion=sample.javaoperatorsdk.io/v1 ,resourceVersion=null, markedForDeletion: false ]}], customResource uid: e5748375-f2d4-446f-9ae7-6c39d77abe00, version: null}, PostExecutionControl: PostExecutionControl{onlyFinalizerHandled=false, updatedCustomResource=null, runtimeException=java.lang.RuntimeException: test}
2021-08-26 16:37:12,238 1 i.j.o.p.DefaultEventHandler    [DEBUG] New events exists for for resource id: e5748375-f2d4-446f-9ae7-6c39d77abe00
2021-08-26 16:37:12,239 1 i.j.o.p.DefaultEventHandler    [DEBUG] Executing events for custom resource. Scope: ExecutionScope{events=[CustomResourceEvent{action=MODIFIED, resource=[ name=test-custom-resource, kind=TestCustomResource, apiVersion=sample.javaoperatorsdk.io/v1 ,resourceVersion=null, markedForDeletion: false ]}, CustomResourceEvent{action=MODIFIED, resource=[ name=test-custom-resource, kind=TestCustomResource, apiVersion=sample.javaoperatorsdk.io/v1 ,resourceVersion=null, markedForDeletion: false ]}], customResource uid: e5748375-f2d4-446f-9ae7-6c39d77abe00, version: null}
2021-08-26 16:37:12,241 29 i.j.o.p.DefaultEventHandler    [DEBUG] Event processing finished. Scope: ExecutionScope{events=[CustomResourceEvent{action=MODIFIED, resource=[ name=test-custom-resource, kind=TestCustomResource, apiVersion=sample.javaoperatorsdk.io/v1 ,resourceVersion=null, markedForDeletion: false ]}, CustomResourceEvent{action=MODIFIED, resource=[ name=test-custom-resource, kind=TestCustomResource, apiVersion=sample.javaoperatorsdk.io/v1 ,resourceVersion=null, markedForDeletion: false ]}], customResource uid: e5748375-f2d4-446f-9ae7-6c39d77abe00, version: null}, PostExecutionControl: null
2021-08-26 16:37:12,260 1 i.f.k.c.CustomResource         [DEBUG] Calling CustomResource#setKind doesn't do anything because the Kind is computed and shouldn't be changed
2021-08-26 16:37:12,260 1 i.j.o.p.DefaultEventHandler    [DEBUG] Received event: CustomResourceEvent{action=DELETED, resource=[ name=test-custom-resource, kind=TestCustomResource, apiVersion=sample.javaoperatorsdk.io/v1 ,resourceVersion=null, markedForDeletion: false ]}
2021-08-26 16:37:12,277 1 i.j.o.p.DefaultEventHandler    [DEBUG] Executing events for custom resource. Scope: ExecutionScope{events=[CustomResourceEvent{action=DELETED, resource=[ name=test-custom-resource, kind=TestCustomResource, apiVersion=sample.javaoperatorsdk.io/v1 ,resourceVersion=null, markedForDeletion: false ]}], customResource uid: b4622895-7ce6-4402-ac6a-ede242146837, version: null}
2021-08-26 16:37:12,278 31 i.j.o.p.DefaultEventHandler    [DEBUG] Event processing finished. Scope: ExecutionScope{events=[CustomResourceEvent{action=DELETED, resource=[ name=test-custom-resource, kind=TestCustomResource, apiVersion=sample.javaoperatorsdk.io/v1 ,resourceVersion=null, markedForDeletion: false ]}], customResource uid: b4622895-7ce6-4402-ac6a-ede242146837, version: null}, PostExecutionControl: null
2021-08-26 16:37:12,339 1 i.j.o.p.DefaultEventHandlerTest [INFO ] Starting successfulExecutionResetsTheRetry
2021-08-26 16:37:12,339 1 i.f.k.c.CustomResource         [DEBUG] Calling CustomResource#setKind doesn't do anything because the Kind is computed and shouldn't be changed
2021-08-26 16:37:12,340 1 i.f.k.c.CustomResource         [DEBUG] Calling CustomResource#setKind doesn't do anything because the Kind is computed and shouldn't be changed
2021-08-26 16:37:12,340 1 i.j.o.p.DefaultEventHandler    [DEBUG] Received event: CustomResourceEvent{action=MODIFIED, resource=[ name=test-custom-resource, kind=TestCustomResource, apiVersion=sample.javaoperatorsdk.io/v1 ,resourceVersion=null, markedForDeletion: false ]}
2021-08-26 16:37:12,357 1 i.j.o.p.DefaultEventHandler    [DEBUG] Executing events for custom resource. Scope: ExecutionScope{events=[CustomResourceEvent{action=MODIFIED, resource=[ name=test-custom-resource, kind=TestCustomResource, apiVersion=sample.javaoperatorsdk.io/v1 ,resourceVersion=null, markedForDeletion: false ]}], customResource uid: 2cd0c291-3aaf-40fa-a970-8312c6cc478f, version: null}
2021-08-26 16:37:12,363 1 i.j.o.p.DefaultEventHandler    [DEBUG] Received event: CustomResourceEvent{action=MODIFIED, resource=[ name=test-custom-resource, kind=TestCustomResource, apiVersion=sample.javaoperatorsdk.io/v1 ,resourceVersion=null, markedForDeletion: false ]}
2021-08-26 16:37:12,365 1 i.j.o.p.DefaultEventHandler    [DEBUG] Skipping executing controller for resource id: 2cd0c291-3aaf-40fa-a970-8312c6cc478f. Events in queue: true. Controller in execution: true. Latest CustomResource present: true
2021-08-26 16:37:12,367 32 i.j.o.p.DefaultEventHandler    [DEBUG] Event processing finished. Scope: ExecutionScope{events=[CustomResourceEvent{action=MODIFIED, resource=[ name=test-custom-resource, kind=TestCustomResource, apiVersion=sample.javaoperatorsdk.io/v1 ,resourceVersion=null, markedForDeletion: false ]}], customResource uid: 2cd0c291-3aaf-40fa-a970-8312c6cc478f, version: null}, PostExecutionControl: PostExecutionControl{onlyFinalizerHandled=false, updatedCustomResource=null, runtimeException=java.lang.RuntimeException: test}
2021-08-26 16:37:12,367 32 i.j.o.p.DefaultEventHandler    [DEBUG] New events exists for for resource id: 2cd0c291-3aaf-40fa-a970-8312c6cc478f
2021-08-26 16:37:12,368 32 i.j.o.p.DefaultEventHandler    [DEBUG] Executing events for custom resource. Scope: ExecutionScope{events=[CustomResourceEvent{action=MODIFIED, resource=[ name=test-custom-resource, kind=TestCustomResource, apiVersion=sample.javaoperatorsdk.io/v1 ,resourceVersion=null, markedForDeletion: false ]}, CustomResourceEvent{action=MODIFIED, resource=[ name=test-custom-resource, kind=TestCustomResource, apiVersion=sample.javaoperatorsdk.io/v1 ,resourceVersion=null, markedForDeletion: false ]}], customResource uid: 2cd0c291-3aaf-40fa-a970-8312c6cc478f, version: null}
2021-08-26 16:37:12,369 32 i.j.o.p.DefaultEventHandler    [DEBUG] Event processing finished. Scope: ExecutionScope{events=[CustomResourceEvent{action=MODIFIED, resource=[ name=test-custom-resource, kind=TestCustomResource, apiVersion=sample.javaoperatorsdk.io/v1 ,resourceVersion=null, markedForDeletion: false ]}, CustomResourceEvent{action=MODIFIED, resource=[ name=test-custom-resource, kind=TestCustomResource, apiVersion=sample.javaoperatorsdk.io/v1 ,resourceVersion=null, markedForDeletion: false ]}], customResource uid: 2cd0c291-3aaf-40fa-a970-8312c6cc478f, version: null}, PostExecutionControl: PostExecutionControl{onlyFinalizerHandled=false, updatedCustomResource=null, runtimeException=null}
2021-08-26 16:37:12,369 32 i.j.o.p.DefaultEventHandler    [DEBUG] Marking successful execution for resource: test-custom-resource
2021-08-26 16:37:12,378 32 i.j.o.p.DefaultEventHandler    [DEBUG] Skipping executing controller for resource id: 2cd0c291-3aaf-40fa-a970-8312c6cc478f. Events in queue: false. Controller in execution: false. Latest CustomResource present: true
2021-08-26 16:37:12,378 1 i.j.o.p.DefaultEventHandler    [DEBUG] Received event: CustomResourceEvent{action=MODIFIED, resource=[ name=test-custom-resource, kind=TestCustomResource, apiVersion=sample.javaoperatorsdk.io/v1 ,resourceVersion=null, markedForDeletion: false ]}
2021-08-26 16:37:12,380 1 i.j.o.p.DefaultEventHandler    [DEBUG] Executing events for custom resource. Scope: ExecutionScope{events=[CustomResourceEvent{action=MODIFIED, resource=[ name=test-custom-resource, kind=TestCustomResource, apiVersion=sample.javaoperatorsdk.io/v1 ,resourceVersion=null, markedForDeletion: false ]}], customResource uid: 2cd0c291-3aaf-40fa-a970-8312c6cc478f, version: null}
2021-08-26 16:37:12,382 32 i.j.o.p.DefaultEventHandler    [DEBUG] Event processing finished. Scope: ExecutionScope{events=[CustomResourceEvent{action=MODIFIED, resource=[ name=test-custom-resource, kind=TestCustomResource, apiVersion=sample.javaoperatorsdk.io/v1 ,resourceVersion=null, markedForDeletion: false ]}], customResource uid: 2cd0c291-3aaf-40fa-a970-8312c6cc478f, version: null}, PostExecutionControl: PostExecutionControl{onlyFinalizerHandled=false, updatedCustomResource=null, runtimeException=null}
2021-08-26 16:37:12,382 32 i.j.o.p.DefaultEventHandler    [DEBUG] Marking successful execution for resource: test-custom-resource
2021-08-26 16:37:12,383 32 i.j.o.p.DefaultEventHandler    [DEBUG] Skipping executing controller for resource id: 2cd0c291-3aaf-40fa-a970-8312c6cc478f. Events in queue: false. Controller in execution: false. Latest CustomResource present: true
2021-08-26 16:37:12,392 1 i.j.o.p.DefaultEventHandlerTest [INFO ] Finished successfulExecutionResetsTheRetry
2021-08-26 16:37:12,403 26 i.j.o.p.DefaultEventHandler    [DEBUG] Event processing finished. Scope: ExecutionScope{events=[{ class=io.javaoperatorsdk.operator.processing.event.internal.TimerEvent, customResourcesSelector=UIDMatchingPredicate{uid='f4983541-06b5-4ee8-a173-33455d17fe48'}, eventSource=null }, CustomResourceEvent{action=MODIFIED, resource=[ name=test-custom-resource, kind=TestCustomResource, apiVersion=sample.javaoperatorsdk.io/v1 ,resourceVersion=null, markedForDeletion: false ]}], customResource uid: f4983541-06b5-4ee8-a173-33455d17fe48, version: null}, PostExecutionControl: PostExecutionControl{onlyFinalizerHandled=false, updatedCustomResource=null, runtimeException=null}
2021-08-26 16:37:12,405 26 i.j.o.p.DefaultEventHandler    [DEBUG] Skipping executing controller for resource id: f4983541-06b5-4ee8-a173-33455d17fe48. Events in queue: false. Controller in execution: false. Latest CustomResource present: true
2021-08-26 16:37:12,414 1 i.f.k.c.CustomResource         [DEBUG] Calling CustomResource#setKind doesn't do anything because the Kind is computed and shouldn't be changed
2021-08-26 16:37:12,414 1 i.j.o.p.DefaultEventHandler    [DEBUG] Received event: CustomResourceEvent{action=MODIFIED, resource=[ name=test-custom-resource, kind=TestCustomResource, apiVersion=sample.javaoperatorsdk.io/v1 ,resourceVersion=null, markedForDeletion: false ]}
2021-08-26 16:37:12,432 1 i.j.o.p.DefaultEventHandler    [DEBUG] Executing events for custom resource. Scope: ExecutionScope{events=[CustomResourceEvent{action=MODIFIED, resource=[ name=test-custom-resource, kind=TestCustomResource, apiVersion=sample.javaoperatorsdk.io/v1 ,resourceVersion=null, markedForDeletion: false ]}], customResource uid: ec6ee088-f40e-44b0-9dbd-947dc498e0c0, version: null}
2021-08-26 16:37:12,436 35 i.j.o.p.DefaultEventHandler    [DEBUG] Event processing finished. Scope: ExecutionScope{events=[CustomResourceEvent{action=MODIFIED, resource=[ name=test-custom-resource, kind=TestCustomResource, apiVersion=sample.javaoperatorsdk.io/v1 ,resourceVersion=null, markedForDeletion: false ]}], customResource uid: ec6ee088-f40e-44b0-9dbd-947dc498e0c0, version: null}, PostExecutionControl: null
2021-08-26 16:37:12,437 28 i.j.o.p.DefaultEventHandler    [DEBUG] Event processing finished. Scope: ExecutionScope{events=[CustomResourceEvent{action=MODIFIED, resource=[ name=test-custom-resource, kind=TestCustomResource, apiVersion=sample.javaoperatorsdk.io/v1 ,resourceVersion=null, markedForDeletion: false ]}], customResource uid: 1a2defe5-eb8f-44e1-8cb2-00ef53f07d43, version: null}, PostExecutionControl: PostExecutionControl{onlyFinalizerHandled=false, updatedCustomResource=null, runtimeException=null}
2021-08-26 16:37:12,439 28 i.j.o.p.DefaultEventHandler    [DEBUG] Executing events for custom resource. Scope: ExecutionScope{events=[{ class=io.javaoperatorsdk.operator.processing.event.internal.TimerEvent, customResourcesSelector=UIDMatchingPredicate{uid='1a2defe5-eb8f-44e1-8cb2-00ef53f07d43'}, eventSource=null }], customResource uid: 1a2defe5-eb8f-44e1-8cb2-00ef53f07d43, version: null}
Error:  Tests run: 8, Failures: 1, Errors: 0, Skipped: 0, Time elapsed: 0.629 s <<< FAILURE! - in io.javaoperatorsdk.operator.processing.DefaultEventHandlerTest
Error:  io.javaoperatorsdk.operator.processing.DefaultEventHandlerTest.successfulExecutionResetsTheRetry  Time elapsed: 0.069 s  <<< FAILURE!
org.opentest4j.AssertionFailedError: 

expected: 1
 but was: 0
	at io.javaoperatorsdk.operator.processing.DefaultEventHandlerTest.successfulExecutionResetsTheRetry(DefaultEventHandlerTest.java:239)

[metacosm]

Note that these tests are failing much more frequently lately… @csviri @adam-sandor 😭

[metacosm]

Integration tests are not immune to flakiness either 😢

[INFO] Running io.javaoperatorsdk.operator.SubResourceUpdateIT
2021-08-30 08:06:22,128 1 i.f.k.c.Config                 [DEBUG] Trying to configure client from Kubernetes config...
2021-08-30 08:06:22,129 1 i.f.k.c.Config                 [DEBUG] Found for Kubernetes config at: [/home/runner/.kube/config].
2021-08-30 08:06:22,263 1 i.j.o.IntegrationTestSupport   [INFO ] Initializing integration test in namespace java-operator-sdk-int-test
2021-08-30 08:06:22,264 1 Default ConfigurationService implementation [WARN ] Configuration for controller 'subresourcetestcustomresourcecontroller' was not found. Known controllers: eventsourcetestcustomresourcecontroller.
2021-08-30 08:06:22,264 1 Default ConfigurationService implementation [INFO ] Created configuration for controller io.javaoperatorsdk.operator.sample.subresource.SubResourceTestCustomResourceController with name subresourcetestcustomresourcecontroller
2021-08-30 08:06:22,339 1 i.j.o.Operator                 [INFO ] Operator SDK 1.9.6-SNAPSHOT (commit: 3cc18e3) built on 2021-08-30T08:04:26.000+0000 starting...
2021-08-30 08:06:22,339 1 i.j.o.Operator                 [INFO ] Client version: 5.7.0
2021-08-30 08:06:22,345 1 i.j.o.Operator                 [INFO ] Server version: 1.21
2021-08-30 08:06:22,350 1 i.f.k.c.d.i.AbstractWatchManager [DEBUG] Watching https://192.168.49.2:8443/apis/sample.javaoperatorsdk/v1/namespaces/java-operator-sdk-int-test/subresourcesample?watch=true...
2021-08-30 08:06:22,448 37 i.f.k.c.d.i.WatcherWebSocketListener [DEBUG] WebSocket successfully opened
2021-08-30 08:06:22,448 1 i.j.o.p.e.i.CustomResourceEventSource [DEBUG] Registered controller io.javaoperatorsdk.operator.sample.subresource.SubResourceTestCustomResource -> io.fabric8.kubernetes.client.dsl.internal.WatchConnectionManager@4a2e7bcb for namespace: java-operator-sdk-int-test
2021-08-30 08:06:22,449 1 i.j.o.Operator                 [INFO ] Registered Controller: 'subresourcetestcustomresourcecontroller' for CRD: 'class io.javaoperatorsdk.operator.sample.subresource.SubResourceTestCustomResource' for namespace(s): [java-operator-sdk-int-test]
2021-08-30 08:06:22,449 1 i.j.o.IntegrationTestSupport   [INFO ] Operator is running with io.javaoperatorsdk.operator.sample.subresource.SubResourceTestCustomResourceController
2021-08-30 08:06:22,449 1 i.j.o.IntegrationTestSupport   [INFO ] Cleaning up namespace java-operator-sdk-int-test
2021-08-30 08:06:22,667 1 i.j.o.IntegrationTestSupport   [INFO ] Cleaned up namespace java-operator-sdk-int-test
2021-08-30 08:06:22,668 1 i.f.k.c.CustomResource         [DEBUG] Calling CustomResource#setKind doesn't do anything because the Kind is computed and shouldn't be changed
2021-08-30 08:06:23,091 41 i.f.k.c.d.i.AbstractWatchManager [DEBUG] Watching https://192.168.49.2:8443/apis/sample.javaoperatorsdk/v1/namespaces/java-operator-sdk-int-test/eventsourcesamples?resourceVersion=481&watch=true...
2021-08-30 08:06:23,091 41 i.f.k.c.d.i.WatchConnectionManager [DEBUG] Closing websocket okhttp3.internal.ws.RealWebSocket@20f2592e
2021-08-30 08:06:23,092 41 i.f.k.c.d.i.WatchConnectionManager [DEBUG] Websocket already closed okhttp3.internal.ws.RealWebSocket@20f2592e
2021-08-30 08:06:23,092 41 i.f.k.c.d.i.WatcherWebSocketListener [WARN ] Exec Failure java.io.InterruptedIOException executor rejected
2021-08-30 08:06:23,093 41 i.f.k.c.d.i.AbstractWatchManager [DEBUG] Reconnect already scheduled
2021-08-30 08:06:24,678 37 i.j.o.p.e.i.CustomResourceEventSource [DEBUG] Event received for action: ADDED, resource: subresource-1
2021-08-30 08:06:24,678 37 i.j.o.p.DefaultEventHandler    [DEBUG] Received event: CustomResourceEvent{action=ADDED, resource=[ name=subresource-1, kind=SubresourceSample, apiVersion=sample.javaoperatorsdk/v1 ,resourceVersion=501, markedForDeletion: false ]}
2021-08-30 08:06:24,682 37 i.j.o.p.DefaultEventHandler    [DEBUG] Executing events for custom resource. Scope: ExecutionScope{events=[CustomResourceEvent{action=ADDED, resource=[ name=subresource-1, kind=SubresourceSample, apiVersion=sample.javaoperatorsdk/v1 ,resourceVersion=501, markedForDeletion: false ]}], customResource uid: ed6ec3bc-95e7-4cd5-af6c-bd3ddd2c91d6, version: 501}
2021-08-30 08:06:24,686 42 i.j.o.p.EventDispatcher        [DEBUG] Handling events: [CustomResourceEvent{action=ADDED, resource=[ name=subresource-1, kind=SubresourceSample, apiVersion=sample.javaoperatorsdk/v1 ,resourceVersion=501, markedForDeletion: false ]}] for resource subresource-1
2021-08-30 08:06:24,686 42 i.j.o.p.EventDispatcher        [DEBUG] Adding finalizer for resource: ed6ec3bc-95e7-4cd5-af6c-bd3ddd2c91d6 version: 501
2021-08-30 08:06:24,686 42 i.j.o.p.EventDispatcher        [DEBUG] Trying to replace resource subresource-1, version: 501
2021-08-30 08:06:24,690 42 i.j.o.p.DefaultEventHandler    [DEBUG] Event processing finished. Scope: ExecutionScope{events=[CustomResourceEvent{action=ADDED, resource=[ name=subresource-1, kind=SubresourceSample, apiVersion=sample.javaoperatorsdk/v1 ,resourceVersion=501, markedForDeletion: false ]}], customResource uid: ed6ec3bc-95e7-4cd5-af6c-bd3ddd2c91d6, version: 501}, PostExecutionControl: PostExecutionControl{onlyFinalizerHandled=true, updatedCustomResource=null, runtimeException=null}
2021-08-30 08:06:24,690 37 i.j.o.p.e.i.CustomResourceEventSource [DEBUG] Event received for action: MODIFIED, resource: subresource-1
2021-08-30 08:06:24,691 42 i.j.o.p.DefaultEventHandler    [DEBUG] Marking successful execution for resource: subresource-1
2021-08-30 08:06:24,692 42 i.j.o.p.DefaultEventHandler    [DEBUG] Skipping executing controller for resource id: ed6ec3bc-95e7-4cd5-af6c-bd3ddd2c91d6. Events in queue: false. Controller in execution: false. Latest CustomResource present: true
2021-08-30 08:06:24,692 37 i.j.o.p.DefaultEventHandler    [DEBUG] Received event: CustomResourceEvent{action=MODIFIED, resource=[ name=subresource-1, kind=SubresourceSample, apiVersion=sample.javaoperatorsdk/v1 ,resourceVersion=502, markedForDeletion: false ]}
2021-08-30 08:06:24,692 37 i.j.o.p.DefaultEventHandler    [DEBUG] Executing events for custom resource. Scope: ExecutionScope{events=[CustomResourceEvent{action=MODIFIED, resource=[ name=subresource-1, kind=SubresourceSample, apiVersion=sample.javaoperatorsdk/v1 ,resourceVersion=502, markedForDeletion: false ]}], customResource uid: ed6ec3bc-95e7-4cd5-af6c-bd3ddd2c91d6, version: 502}
2021-08-30 08:06:24,693 42 i.j.o.p.EventDispatcher        [DEBUG] Handling events: [CustomResourceEvent{action=MODIFIED, resource=[ name=subresource-1, kind=SubresourceSample, apiVersion=sample.javaoperatorsdk/v1 ,resourceVersion=502, markedForDeletion: false ]}] for resource subresource-1
2021-08-30 08:06:24,693 42 i.j.o.p.EventDispatcher        [DEBUG] Executing createOrUpdate for resource subresource-1 with version: 502 with execution scope: ExecutionScope{events=[CustomResourceEvent{action=MODIFIED, resource=[ name=subresource-1, kind=SubresourceSample, apiVersion=sample.javaoperatorsdk/v1 ,resourceVersion=502, markedForDeletion: false ]}], customResource uid: ed6ec3bc-95e7-4cd5-af6c-bd3ddd2c91d6, version: 502}
2021-08-30 08:06:24,694 42 i.j.o.s.s.SubResourceTestCustomResourceController [INFO ] Value: 1
2021-08-30 08:06:24,698 37 i.j.o.p.e.i.CustomResourceEventSource [DEBUG] Event received for action: MODIFIED, resource: subresource-1
2021-08-30 08:06:24,699 37 i.j.o.p.DefaultEventHandler    [DEBUG] Received event: CustomResourceEvent{action=MODIFIED, resource=[ name=subresource-1, kind=SubresourceSample, apiVersion=sample.javaoperatorsdk/v1 ,resourceVersion=503, markedForDeletion: false ]}
2021-08-30 08:06:24,699 37 i.j.o.p.DefaultEventHandler    [DEBUG] Skipping executing controller for resource id: ed6ec3bc-95e7-4cd5-af6c-bd3ddd2c91d6. Events in queue: true. Controller in execution: true. Latest CustomResource present: true
2021-08-30 08:06:24,699 42 i.j.o.p.DefaultEventHandler    [DEBUG] Event processing finished. Scope: ExecutionScope{events=[CustomResourceEvent{action=MODIFIED, resource=[ name=subresource-1, kind=SubresourceSample, apiVersion=sample.javaoperatorsdk/v1 ,resourceVersion=502, markedForDeletion: false ]}], customResource uid: ed6ec3bc-95e7-4cd5-af6c-bd3ddd2c91d6, version: 502}, PostExecutionControl: PostExecutionControl{onlyFinalizerHandled=false, updatedCustomResource=CustomResource{kind='SubresourceSample', apiVersion='sample.javaoperatorsdk/v1', metadata=ObjectMeta(annotations=null, clusterName=null, creationTimestamp=2021-08-30T08:06:24Z, deletionGracePeriodSeconds=null, deletionTimestamp=null, finalizers=[subresourcesample.sample.javaoperatorsdk/finalizer], generateName=null, generation=1, labels=null, managedFields=[ManagedFieldsEntry(apiVersion=sample.javaoperatorsdk/v1, fieldsType=FieldsV1, fieldsV1=FieldsV1(additionalProperties={f:metadata={f:finalizers={.={}, v:"subresourcesample.sample.javaoperatorsdk/finalizer"={}}}, f:status={.={}, f:state={}}, f:spec={.={}, f:value={}}}), manager=okhttp, operation=Update, time=2021-08-30T08:06:24Z, additionalProperties={})], name=subresource-1, namespace=java-operator-sdk-int-test, ownerReferences=[], resourceVersion=503, selfLink=null, uid=ed6ec3bc-95e7-4cd5-af6c-bd3ddd2c91d6, additionalProperties={}), spec=io.javaoperatorsdk.operator.sample.subresource.SubResourceTestCustomResourceSpec@4e60c0c1, status=io.javaoperatorsdk.operator.sample.subresource.SubResourceTestCustomResourceStatus@b624769}, runtimeException=null}
2021-08-30 08:06:24,700 42 i.j.o.p.DefaultEventHandler    [DEBUG] Marking successful execution for resource: subresource-1
2021-08-30 08:06:24,700 42 i.j.o.p.DefaultEventHandler    [DEBUG] Trying to update resource cache from update response for resource: subresource-1 new version: 503 old version: 502
2021-08-30 08:06:24,700 42 i.j.o.p.DefaultEventHandler    [DEBUG] Executing events for custom resource. Scope: ExecutionScope{events=[CustomResourceEvent{action=MODIFIED, resource=[ name=subresource-1, kind=SubresourceSample, apiVersion=sample.javaoperatorsdk/v1 ,resourceVersion=503, markedForDeletion: false ]}], customResource uid: ed6ec3bc-95e7-4cd5-af6c-bd3ddd2c91d6, version: 503}
2021-08-30 08:06:24,700 42 i.j.o.p.EventDispatcher        [DEBUG] Handling events: [CustomResourceEvent{action=MODIFIED, resource=[ name=subresource-1, kind=SubresourceSample, apiVersion=sample.javaoperatorsdk/v1 ,resourceVersion=503, markedForDeletion: false ]}] for resource subresource-1
2021-08-30 08:06:24,700 42 i.j.o.p.EventDispatcher        [DEBUG] Executing createOrUpdate for resource subresource-1 with version: 503 with execution scope: ExecutionScope{events=[CustomResourceEvent{action=MODIFIED, resource=[ name=subresource-1, kind=SubresourceSample, apiVersion=sample.javaoperatorsdk/v1 ,resourceVersion=503, markedForDeletion: false ]}], customResource uid: ed6ec3bc-95e7-4cd5-af6c-bd3ddd2c91d6, version: 503}
2021-08-30 08:06:24,700 42 i.j.o.s.s.SubResourceTestCustomResourceController [INFO ] Value: 1
2021-08-30 08:06:24,704 42 i.j.o.p.DefaultEventHandler    [DEBUG] Event processing finished. Scope: ExecutionScope{events=[CustomResourceEvent{action=MODIFIED, resource=[ name=subresource-1, kind=SubresourceSample, apiVersion=sample.javaoperatorsdk/v1 ,resourceVersion=503, markedForDeletion: false ]}], customResource uid: ed6ec3bc-95e7-4cd5-af6c-bd3ddd2c91d6, version: 503}, PostExecutionControl: PostExecutionControl{onlyFinalizerHandled=false, updatedCustomResource=CustomResource{kind='SubresourceSample', apiVersion='sample.javaoperatorsdk/v1', metadata=ObjectMeta(annotations=null, clusterName=null, creationTimestamp=2021-08-30T08:06:24Z, deletionGracePeriodSeconds=null, deletionTimestamp=null, finalizers=[subresourcesample.sample.javaoperatorsdk/finalizer], generateName=null, generation=1, labels=null, managedFields=[ManagedFieldsEntry(apiVersion=sample.javaoperatorsdk/v1, fieldsType=FieldsV1, fieldsV1=FieldsV1(additionalProperties={f:metadata={f:finalizers={.={}, v:"subresourcesample.sample.javaoperatorsdk/finalizer"={}}}, f:status={.={}, f:state={}}, f:spec={.={}, f:value={}}}), manager=okhttp, operation=Update, time=2021-08-30T08:06:24Z, additionalProperties={})], name=subresource-1, namespace=java-operator-sdk-int-test, ownerReferences=[], resourceVersion=503, selfLink=null, uid=ed6ec3bc-95e7-4cd5-af6c-bd3ddd2c91d6, additionalProperties={}), spec=io.javaoperatorsdk.operator.sample.subresource.SubResourceTestCustomResourceSpec@720df001, status=io.javaoperatorsdk.operator.sample.subresource.SubResourceTestCustomResourceStatus@6b4db826}, runtimeException=null}
2021-08-30 08:06:24,704 42 i.j.o.p.DefaultEventHandler    [DEBUG] Marking successful execution for resource: subresource-1
2021-08-30 08:06:24,704 42 i.j.o.p.DefaultEventHandler    [DEBUG] Trying to update resource cache from update response for resource: subresource-1 new version: 503 old version: 503
2021-08-30 08:06:24,704 42 i.j.o.p.DefaultEventHandler    [DEBUG] Skipping executing controller for resource id: ed6ec3bc-95e7-4cd5-af6c-bd3ddd2c91d6. Events in queue: false. Controller in execution: false. Latest CustomResource present: true
2021-08-30 08:06:24,989 1 i.j.o.IntegrationTestSupport   [INFO ] Deleting namespace java-operator-sdk-int-test and stopping operator
2021-08-30 08:06:27,089 37 i.j.o.p.e.i.CustomResourceEventSource [DEBUG] Event received for action: MODIFIED, resource: subresource-1
2021-08-30 08:06:27,089 37 i.j.o.p.DefaultEventHandler    [DEBUG] Received event: CustomResourceEvent{action=MODIFIED, resource=[ name=subresource-1, kind=SubresourceSample, apiVersion=sample.javaoperatorsdk/v1 ,resourceVersion=510, markedForDeletion: true ]}
2021-08-30 08:06:27,090 37 i.j.o.p.DefaultEventHandler    [DEBUG] Executing events for custom resource. Scope: ExecutionScope{events=[CustomResourceEvent{action=MODIFIED, resource=[ name=subresource-1, kind=SubresourceSample, apiVersion=sample.javaoperatorsdk/v1 ,resourceVersion=510, markedForDeletion: true ]}], customResource uid: ed6ec3bc-95e7-4cd5-af6c-bd3ddd2c91d6, version: 510}
2021-08-30 08:06:27,091 43 i.j.o.p.EventDispatcher        [DEBUG] Handling events: [CustomResourceEvent{action=MODIFIED, resource=[ name=subresource-1, kind=SubresourceSample, apiVersion=sample.javaoperatorsdk/v1 ,resourceVersion=510, markedForDeletion: true ]}] for resource subresource-1
2021-08-30 08:06:27,091 43 i.j.o.p.EventDispatcher        [DEBUG] Executing delete for resource: subresource-1 with version: 510
2021-08-30 08:06:27,091 43 i.j.o.p.EventDispatcher        [DEBUG] Removing finalizer on resource: ed6ec3bc-95e7-4cd5-af6c-bd3ddd2c91d6 with version: 510
2021-08-30 08:06:27,096 37 i.j.o.p.e.i.CustomResourceEventSource [DEBUG] Event received for action: DELETED, resource: subresource-1
2021-08-30 08:06:27,096 37 i.j.o.p.DefaultEventHandler    [DEBUG] Received event: CustomResourceEvent{action=DELETED, resource=[ name=subresource-1, kind=SubresourceSample, apiVersion=sample.javaoperatorsdk/v1 ,resourceVersion=511, markedForDeletion: true ]}
2021-08-30 08:06:27,097 37 i.j.o.p.DefaultEventHandler    [DEBUG] Skipping executing controller for resource id: ed6ec3bc-95e7-4cd5-af6c-bd3ddd2c91d6. Events in queue: true. Controller in execution: true. Latest CustomResource present: true
2021-08-30 08:06:27,097 43 i.j.o.p.DefaultEventHandler    [DEBUG] Event processing finished. Scope: ExecutionScope{events=[CustomResourceEvent{action=MODIFIED, resource=[ name=subresource-1, kind=SubresourceSample, apiVersion=sample.javaoperatorsdk/v1 ,resourceVersion=510, markedForDeletion: true ]}], customResource uid: ed6ec3bc-95e7-4cd5-af6c-bd3ddd2c91d6, version: 510}, PostExecutionControl: PostExecutionControl{onlyFinalizerHandled=false, updatedCustomResource=CustomResource{kind='SubresourceSample', apiVersion='sample.javaoperatorsdk/v1', metadata=ObjectMeta(annotations=null, clusterName=null, creationTimestamp=2021-08-30T08:06:24Z, deletionGracePeriodSeconds=0, deletionTimestamp=2021-08-30T08:06:27Z, finalizers=[], generateName=null, generation=2, labels=null, managedFields=[ManagedFieldsEntry(apiVersion=sample.javaoperatorsdk/v1, fieldsType=FieldsV1, fieldsV1=FieldsV1(additionalProperties={f:status={.={}, f:state={}}, f:spec={.={}, f:value={}}}), manager=okhttp, operation=Update, time=2021-08-30T08:06:24Z, additionalProperties={})], name=subresource-1, namespace=java-operator-sdk-int-test, ownerReferences=[], resourceVersion=510, selfLink=null, uid=ed6ec3bc-95e7-4cd5-af6c-bd3ddd2c91d6, additionalProperties={}), spec=io.javaoperatorsdk.operator.sample.subresource.SubResourceTestCustomResourceSpec@7137b04c, status=io.javaoperatorsdk.operator.sample.subresource.SubResourceTestCustomResourceStatus@75082ab2}, runtimeException=null}
2021-08-30 08:06:27,098 43 i.j.o.p.DefaultEventHandler    [DEBUG] Marking successful execution for resource: subresource-1
2021-08-30 08:06:27,098 43 i.j.o.p.DefaultEventHandler    [DEBUG] Trying to update resource cache from update response for resource: subresource-1 new version: 510 old version: 510
2021-08-30 08:06:27,098 43 i.j.o.p.DefaultEventHandler    [DEBUG] Executing events for custom resource. Scope: ExecutionScope{events=[CustomResourceEvent{action=DELETED, resource=[ name=subresource-1, kind=SubresourceSample, apiVersion=sample.javaoperatorsdk/v1 ,resourceVersion=511, markedForDeletion: true ]}], customResource uid: ed6ec3bc-95e7-4cd5-af6c-bd3ddd2c91d6, version: 511}
2021-08-30 08:06:27,098 44 i.j.o.p.EventDispatcher        [DEBUG] Handling events: [CustomResourceEvent{action=DELETED, resource=[ name=subresource-1, kind=SubresourceSample, apiVersion=sample.javaoperatorsdk/v1 ,resourceVersion=511, markedForDeletion: true ]}] for resource subresource-1
2021-08-30 08:06:27,099 44 i.j.o.p.EventDispatcher        [DEBUG] Skipping dispatch processing because of a Delete event: subresource-1 with version: 511
2021-08-30 08:06:27,101 44 i.j.o.p.DefaultEventHandler    [DEBUG] Event processing finished. Scope: ExecutionScope{events=[CustomResourceEvent{action=DELETED, resource=[ name=subresource-1, kind=SubresourceSample, apiVersion=sample.javaoperatorsdk/v1 ,resourceVersion=511, markedForDeletion: true ]}], customResource uid: ed6ec3bc-95e7-4cd5-af6c-bd3ddd2c91d6, version: 511}, PostExecutionControl: PostExecutionControl{onlyFinalizerHandled=false, updatedCustomResource=null, runtimeException=null}
2021-08-30 08:06:27,101 44 i.j.o.p.DefaultEventHandler    [DEBUG] Marking successful execution for resource: subresource-1
2021-08-30 08:06:32,273 37 i.f.k.c.d.i.WatcherWebSocketListener [WARN ] Exec Failure java.net.SocketException Socket closed
2021-08-30 08:06:32,273 37 i.f.k.c.d.i.WatcherWebSocketListener [DEBUG] Couldn't report exception
io.fabric8.kubernetes.client.KubernetesClientException: Failed to start websocket
	at io.fabric8.kubernetes.client.dsl.internal.WatcherWebSocketListener.onFailure(WatcherWebSocketListener.java:77)
	at okhttp3.internal.ws.RealWebSocket.failWebSocket(RealWebSocket.java:571)
	at okhttp3.internal.ws.RealWebSocket$2.onResponse(RealWebSocket.java:216)
	at okhttp3.RealCall$AsyncCall.execute(RealCall.java:203)
	at okhttp3.internal.NamedRunnable.run(NamedRunnable.java:32)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at java.base/java.lang.Thread.run(Thread.java:829)
Caused by: java.net.SocketException: Socket closed
	at java.base/java.net.SocketInputStream.socketRead0(Native Method)
	at java.base/java.net.SocketInputStream.socketRead(SocketInputStream.java:115)
	at java.base/java.net.SocketInputStream.read(SocketInputStream.java:168)
	at java.base/java.net.SocketInputStream.read(SocketInputStream.java:140)
	at java.base/sun.security.ssl.SSLSocketInputRecord.read(SSLSocketInputRecord.java:478)
	at java.base/sun.security.ssl.SSLSocketInputRecord.readHeader(SSLSocketInputRecord.java:472)
	at java.base/sun.security.ssl.SSLSocketInputRecord.bytesInCompletePacket(SSLSocketInputRecord.java:70)
	at java.base/sun.security.ssl.SSLSocketImpl.readApplicationRecord(SSLSocketImpl.java:1374)
	at java.base/sun.security.ssl.SSLSocketImpl$AppInputStream.read(SSLSocketImpl.java:985)
	at okio.Okio$2.read(Okio.java:140)
	at okio.AsyncTimeout$2.read(AsyncTimeout.java:237)
	at okio.RealBufferedSource.request(RealBufferedSource.java:68)
	at okio.RealBufferedSource.require(RealBufferedSource.java:61)
	at okio.RealBufferedSource.readByte(RealBufferedSource.java:74)
	at okhttp3.internal.ws.WebSocketReader.readHeader(WebSocketReader.java:117)
	at okhttp3.internal.ws.WebSocketReader.processNextFrame(WebSocketReader.java:101)
	at okhttp3.internal.ws.RealWebSocket.loopReader(RealWebSocket.java:274)
	at okhttp3.internal.ws.RealWebSocket$2.onResponse(RealWebSocket.java:214)
	... 5 more
2021-08-30 08:06:32,274 37 i.f.k.c.d.i.AbstractWatchManager [DEBUG] Scheduling reconnect task
2021-08-30 08:06:32,274 37 i.f.k.c.d.i.AbstractWatchManager [DEBUG] Current reconnect backoff is 1000 milliseconds (T0)
2021-08-30 08:06:32,274 1 i.f.k.c.Config                 [DEBUG] Trying to configure client from Kubernetes config...
2021-08-30 08:06:32,274 1 i.f.k.c.Config                 [DEBUG] Found for Kubernetes config at: [/home/runner/.kube/config].
2021-08-30 08:06:32,380 1 i.j.o.IntegrationTestSupport   [INFO ] Initializing integration test in namespace java-operator-sdk-int-test
2021-08-30 08:06:32,533 1 i.j.o.Operator                 [INFO ] Operator SDK 1.9.6-SNAPSHOT (commit: 3cc18e3) built on 2021-08-30T08:04:26.000+0000 starting...
2021-08-30 08:06:32,533 1 i.j.o.Operator                 [INFO ] Client version: 5.7.0
2021-08-30 08:06:32,536 1 i.j.o.Operator                 [INFO ] Server version: 1.21
2021-08-30 08:06:32,547 1 i.f.k.c.d.i.AbstractWatchManager [DEBUG] Watching https://192.168.49.2:8443/apis/sample.javaoperatorsdk/v1/namespaces/java-operator-sdk-int-test/subresourcesample?watch=true...
2021-08-30 08:06:32,604 54 i.f.k.c.d.i.WatcherWebSocketListener [DEBUG] WebSocket successfully opened
2021-08-30 08:06:32,606 1 i.j.o.p.e.i.CustomResourceEventSource [DEBUG] Registered controller io.javaoperatorsdk.operator.sample.subresource.SubResourceTestCustomResource -> io.fabric8.kubernetes.client.dsl.internal.WatchConnectionManager@7112ce6 for namespace: java-operator-sdk-int-test
2021-08-30 08:06:32,607 1 i.j.o.Operator                 [INFO ] Registered Controller: 'subresourcetestcustomresourcecontroller' for CRD: 'class io.javaoperatorsdk.operator.sample.subresource.SubResourceTestCustomResource' for namespace(s): [java-operator-sdk-int-test]
2021-08-30 08:06:32,607 1 i.j.o.IntegrationTestSupport   [INFO ] Operator is running with io.javaoperatorsdk.operator.sample.subresource.SubResourceTestCustomResourceController
2021-08-30 08:06:32,607 1 i.j.o.IntegrationTestSupport   [INFO ] Cleaning up namespace java-operator-sdk-int-test
2021-08-30 08:06:32,836 1 i.j.o.IntegrationTestSupport   [INFO ] Cleaned up namespace java-operator-sdk-int-test
2021-08-30 08:06:32,837 1 i.f.k.c.CustomResource         [DEBUG] Calling CustomResource#setKind doesn't do anything because the Kind is computed and shouldn't be changed
2021-08-30 08:06:32,841 54 i.j.o.p.e.i.CustomResourceEventSource [DEBUG] Event received for action: ADDED, resource: subresource-1
2021-08-30 08:06:32,841 54 i.j.o.p.DefaultEventHandler    [DEBUG] Received event: CustomResourceEvent{action=ADDED, resource=[ name=subresource-1, kind=SubresourceSample, apiVersion=sample.javaoperatorsdk/v1 ,resourceVersion=524, markedForDeletion: false ]}
2021-08-30 08:06:32,842 54 i.j.o.p.DefaultEventHandler    [DEBUG] Executing events for custom resource. Scope: ExecutionScope{events=[CustomResourceEvent{action=ADDED, resource=[ name=subresource-1, kind=SubresourceSample, apiVersion=sample.javaoperatorsdk/v1 ,resourceVersion=524, markedForDeletion: false ]}], customResource uid: cce5743c-c254-4ff8-a48d-2b7480a0e756, version: 524}
2021-08-30 08:06:32,843 58 i.j.o.p.EventDispatcher        [DEBUG] Handling events: [CustomResourceEvent{action=ADDED, resource=[ name=subresource-1, kind=SubresourceSample, apiVersion=sample.javaoperatorsdk/v1 ,resourceVersion=524, markedForDeletion: false ]}] for resource subresource-1
2021-08-30 08:06:32,843 58 i.j.o.p.EventDispatcher        [DEBUG] Executing createOrUpdate for resource subresource-1 with version: 524 with execution scope: ExecutionScope{events=[CustomResourceEvent{action=ADDED, resource=[ name=subresource-1, kind=SubresourceSample, apiVersion=sample.javaoperatorsdk/v1 ,resourceVersion=524, markedForDeletion: false ]}], customResource uid: cce5743c-c254-4ff8-a48d-2b7480a0e756, version: 524}
2021-08-30 08:06:32,843 58 i.j.o.s.s.SubResourceTestCustomResourceController [INFO ] Value: 1
2021-08-30 08:06:32,848 54 i.j.o.p.e.i.CustomResourceEventSource [DEBUG] Event received for action: MODIFIED, resource: subresource-1
2021-08-30 08:06:32,848 54 i.j.o.p.DefaultEventHandler    [DEBUG] Received event: CustomResourceEvent{action=MODIFIED, resource=[ name=subresource-1, kind=SubresourceSample, apiVersion=sample.javaoperatorsdk/v1 ,resourceVersion=525, markedForDeletion: false ]}
2021-08-30 08:06:32,848 54 i.j.o.p.DefaultEventHandler    [DEBUG] Skipping executing controller for resource id: cce5743c-c254-4ff8-a48d-2b7480a0e756. Events in queue: true. Controller in execution: true. Latest CustomResource present: true
2021-08-30 08:06:32,850 58 i.j.o.p.DefaultEventHandler    [DEBUG] Event processing finished. Scope: ExecutionScope{events=[CustomResourceEvent{action=ADDED, resource=[ name=subresource-1, kind=SubresourceSample, apiVersion=sample.javaoperatorsdk/v1 ,resourceVersion=524, markedForDeletion: false ]}], customResource uid: cce5743c-c254-4ff8-a48d-2b7480a0e756, version: 524}, PostExecutionControl: PostExecutionControl{onlyFinalizerHandled=false, updatedCustomResource=CustomResource{kind='SubresourceSample', apiVersion='sample.javaoperatorsdk/v1', metadata=ObjectMeta(annotations=null, clusterName=null, creationTimestamp=2021-08-30T08:06:32Z, deletionGracePeriodSeconds=null, deletionTimestamp=null, finalizers=[subresourcesample.sample.javaoperatorsdk/finalizer], generateName=null, generation=1, labels=null, managedFields=[ManagedFieldsEntry(apiVersion=sample.javaoperatorsdk/v1, fieldsType=FieldsV1, fieldsV1=FieldsV1(additionalProperties={f:metadata={f:finalizers={.={}, v:"subresourcesample.sample.javaoperatorsdk/finalizer"={}}}, f:status={.={}, f:state={}}, f:spec={.={}, f:value={}}}), manager=okhttp, operation=Update, time=2021-08-30T08:06:32Z, additionalProperties={})], name=subresource-1, namespace=java-operator-sdk-int-test, ownerReferences=[], resourceVersion=525, selfLink=null, uid=cce5743c-c254-4ff8-a48d-2b7480a0e756, additionalProperties={}), spec=io.javaoperatorsdk.operator.sample.subresource.SubResourceTestCustomResourceSpec@57ce1fe7, status=io.javaoperatorsdk.operator.sample.subresource.SubResourceTestCustomResourceStatus@773d4074}, runtimeException=null}
2021-08-30 08:06:32,850 58 i.j.o.p.DefaultEventHandler    [DEBUG] Marking successful execution for resource: subresource-1
2021-08-30 08:06:32,850 58 i.j.o.p.DefaultEventHandler    [DEBUG] Trying to update resource cache from update response for resource: subresource-1 new version: 525 old version: 524
2021-08-30 08:06:32,851 58 i.j.o.p.DefaultEventHandler    [DEBUG] Executing events for custom resource. Scope: ExecutionScope{events=[CustomResourceEvent{action=MODIFIED, resource=[ name=subresource-1, kind=SubresourceSample, apiVersion=sample.javaoperatorsdk/v1 ,resourceVersion=525, markedForDeletion: false ]}], customResource uid: cce5743c-c254-4ff8-a48d-2b7480a0e756, version: 525}
2021-08-30 08:06:32,851 58 i.j.o.p.EventDispatcher        [DEBUG] Handling events: [CustomResourceEvent{action=MODIFIED, resource=[ name=subresource-1, kind=SubresourceSample, apiVersion=sample.javaoperatorsdk/v1 ,resourceVersion=525, markedForDeletion: false ]}] for resource subresource-1
2021-08-30 08:06:32,851 58 i.j.o.p.EventDispatcher        [DEBUG] Executing createOrUpdate for resource subresource-1 with version: 525 with execution scope: ExecutionScope{events=[CustomResourceEvent{action=MODIFIED, resource=[ name=subresource-1, kind=SubresourceSample, apiVersion=sample.javaoperatorsdk/v1 ,resourceVersion=525, markedForDeletion: false ]}], customResource uid: cce5743c-c254-4ff8-a48d-2b7480a0e756, version: 525}
2021-08-30 08:06:32,851 58 i.j.o.s.s.SubResourceTestCustomResourceController [INFO ] Value: 1
2021-08-30 08:06:32,854 58 i.j.o.p.DefaultEventHandler    [DEBUG] Event processing finished. Scope: ExecutionScope{events=[CustomResourceEvent{action=MODIFIED, resource=[ name=subresource-1, kind=SubresourceSample, apiVersion=sample.javaoperatorsdk/v1 ,resourceVersion=525, markedForDeletion: false ]}], customResource uid: cce5743c-c254-4ff8-a48d-2b7480a0e756, version: 525}, PostExecutionControl: PostExecutionControl{onlyFinalizerHandled=false, updatedCustomResource=CustomResource{kind='SubresourceSample', apiVersion='sample.javaoperatorsdk/v1', metadata=ObjectMeta(annotations=null, clusterName=null, creationTimestamp=2021-08-30T08:06:32Z, deletionGracePeriodSeconds=null, deletionTimestamp=null, finalizers=[subresourcesample.sample.javaoperatorsdk/finalizer], generateName=null, generation=1, labels=null, managedFields=[ManagedFieldsEntry(apiVersion=sample.javaoperatorsdk/v1, fieldsType=FieldsV1, fieldsV1=FieldsV1(additionalProperties={f:metadata={f:finalizers={.={}, v:"subresourcesample.sample.javaoperatorsdk/finalizer"={}}}, f:status={.={}, f:state={}}, f:spec={.={}, f:value={}}}), manager=okhttp, operation=Update, time=2021-08-30T08:06:32Z, additionalProperties={})], name=subresource-1, namespace=java-operator-sdk-int-test, ownerReferences=[], resourceVersion=525, selfLink=null, uid=cce5743c-c254-4ff8-a48d-2b7480a0e756, additionalProperties={}), spec=io.javaoperatorsdk.operator.sample.subresource.SubResourceTestCustomResourceSpec@711aab8f, status=io.javaoperatorsdk.operator.sample.subresource.SubResourceTestCustomResourceStatus@6c396b38}, runtimeException=null}
2021-08-30 08:06:32,854 58 i.j.o.p.DefaultEventHandler    [DEBUG] Marking successful execution for resource: subresource-1
2021-08-30 08:06:32,854 58 i.j.o.p.DefaultEventHandler    [DEBUG] Trying to update resource cache from update response for resource: subresource-1 new version: 525 old version: 525
2021-08-30 08:06:32,855 58 i.j.o.p.DefaultEventHandler    [DEBUG] Skipping executing controller for resource id: cce5743c-c254-4ff8-a48d-2b7480a0e756. Events in queue: false. Controller in execution: false. Latest CustomResource present: true
2021-08-30 08:06:33,147 1 i.j.o.IntegrationTestSupport   [INFO ] Deleting namespace java-operator-sdk-int-test and stopping operator
2021-08-30 08:06:33,274 41 i.f.k.c.d.i.AbstractWatchManager [DEBUG] Watching https://192.168.49.2:8443/apis/sample.javaoperatorsdk/v1/namespaces/java-operator-sdk-int-test/subresourcesample?resourceVersion=511&watch=true...
2021-08-30 08:06:33,275 41 i.f.k.c.d.i.WatchConnectionManager [DEBUG] Closing websocket okhttp3.internal.ws.RealWebSocket@5f422c03
2021-08-30 08:06:33,275 41 i.f.k.c.d.i.WatchConnectionManager [DEBUG] Websocket already closed okhttp3.internal.ws.RealWebSocket@5f422c03
2021-08-30 08:06:33,275 41 i.f.k.c.d.i.WatcherWebSocketListener [WARN ] Exec Failure java.io.InterruptedIOException executor rejected
2021-08-30 08:06:33,275 41 i.f.k.c.d.i.AbstractWatchManager [DEBUG] Reconnect already scheduled
2021-08-30 08:06:37,251 54 i.j.o.p.e.i.CustomResourceEventSource [DEBUG] Event received for action: MODIFIED, resource: subresource-1
2021-08-30 08:06:37,251 54 i.j.o.p.DefaultEventHandler    [DEBUG] Received event: CustomResourceEvent{action=MODIFIED, resource=[ name=subresource-1, kind=SubresourceSample, apiVersion=sample.javaoperatorsdk/v1 ,resourceVersion=531, markedForDeletion: true ]}
2021-08-30 08:06:37,252 54 i.j.o.p.DefaultEventHandler    [DEBUG] Executing events for custom resource. Scope: ExecutionScope{events=[CustomResourceEvent{action=MODIFIED, resource=[ name=subresource-1, kind=SubresourceSample, apiVersion=sample.javaoperatorsdk/v1 ,resourceVersion=531, markedForDeletion: true ]}], customResource uid: cce5743c-c254-4ff8-a48d-2b7480a0e756, version: 531}
2021-08-30 08:06:37,252 59 i.j.o.p.EventDispatcher        [DEBUG] Handling events: [CustomResourceEvent{action=MODIFIED, resource=[ name=subresource-1, kind=SubresourceSample, apiVersion=sample.javaoperatorsdk/v1 ,resourceVersion=531, markedForDeletion: true ]}] for resource subresource-1
2021-08-30 08:06:37,253 59 i.j.o.p.EventDispatcher        [DEBUG] Executing delete for resource: subresource-1 with version: 531
2021-08-30 08:06:37,253 59 i.j.o.p.EventDispatcher        [DEBUG] Removing finalizer on resource: cce5743c-c254-4ff8-a48d-2b7480a0e756 with version: 531
2021-08-30 08:06:37,258 54 i.j.o.p.e.i.CustomResourceEventSource [DEBUG] Event received for action: DELETED, resource: subresource-1
2021-08-30 08:06:37,258 54 i.j.o.p.DefaultEventHandler    [DEBUG] Received event: CustomResourceEvent{action=DELETED, resource=[ name=subresource-1, kind=SubresourceSample, apiVersion=sample.javaoperatorsdk/v1 ,resourceVersion=532, markedForDeletion: true ]}
2021-08-30 08:06:37,259 54 i.j.o.p.DefaultEventHandler    [DEBUG] Skipping executing controller for resource id: cce5743c-c254-4ff8-a48d-2b7480a0e756. Events in queue: true. Controller in execution: true. Latest CustomResource present: true
2021-08-30 08:06:37,261 59 i.j.o.p.DefaultEventHandler    [DEBUG] Event processing finished. Scope: ExecutionScope{events=[CustomResourceEvent{action=MODIFIED, resource=[ name=subresource-1, kind=SubresourceSample, apiVersion=sample.javaoperatorsdk/v1 ,resourceVersion=531, markedForDeletion: true ]}], customResource uid: cce5743c-c254-4ff8-a48d-2b7480a0e756, version: 531}, PostExecutionControl: PostExecutionControl{onlyFinalizerHandled=false, updatedCustomResource=CustomResource{kind='SubresourceSample', apiVersion='sample.javaoperatorsdk/v1', metadata=ObjectMeta(annotations=null, clusterName=null, creationTimestamp=2021-08-30T08:06:32Z, deletionGracePeriodSeconds=0, deletionTimestamp=2021-08-30T08:06:37Z, finalizers=[], generateName=null, generation=2, labels=null, managedFields=[ManagedFieldsEntry(apiVersion=sample.javaoperatorsdk/v1, fieldsType=FieldsV1, fieldsV1=FieldsV1(additionalProperties={f:status={.={}, f:state={}}, f:spec={.={}, f:value={}}}), manager=okhttp, operation=Update, time=2021-08-30T08:06:32Z, additionalProperties={})], name=subresource-1, namespace=java-operator-sdk-int-test, ownerReferences=[], resourceVersion=531, selfLink=null, uid=cce5743c-c254-4ff8-a48d-2b7480a0e756, additionalProperties={}), spec=io.javaoperatorsdk.operator.sample.subresource.SubResourceTestCustomResourceSpec@4d505842, status=io.javaoperatorsdk.operator.sample.subresource.SubResourceTestCustomResourceStatus@1acf45e8}, runtimeException=null}
2021-08-30 08:06:37,262 59 i.j.o.p.DefaultEventHandler    [DEBUG] Marking successful execution for resource: subresource-1
2021-08-30 08:06:37,262 59 i.j.o.p.DefaultEventHandler    [DEBUG] Trying to update resource cache from update response for resource: subresource-1 new version: 531 old version: 531
2021-08-30 08:06:37,262 59 i.j.o.p.DefaultEventHandler    [DEBUG] Executing events for custom resource. Scope: ExecutionScope{events=[CustomResourceEvent{action=DELETED, resource=[ name=subresource-1, kind=SubresourceSample, apiVersion=sample.javaoperatorsdk/v1 ,resourceVersion=532, markedForDeletion: true ]}], customResource uid: cce5743c-c254-4ff8-a48d-2b7480a0e756, version: 532}
2021-08-30 08:06:37,262 58 i.j.o.p.EventDispatcher        [DEBUG] Handling events: [CustomResourceEvent{action=DELETED, resource=[ name=subresource-1, kind=SubresourceSample, apiVersion=sample.javaoperatorsdk/v1 ,resourceVersion=532, markedForDeletion: true ]}] for resource subresource-1
2021-08-30 08:06:37,262 58 i.j.o.p.EventDispatcher        [DEBUG] Skipping dispatch processing because of a Delete event: subresource-1 with version: 532
2021-08-30 08:06:37,264 58 i.j.o.p.DefaultEventHandler    [DEBUG] Event processing finished. Scope: ExecutionScope{events=[CustomResourceEvent{action=DELETED, resource=[ name=subresource-1, kind=SubresourceSample, apiVersion=sample.javaoperatorsdk/v1 ,resourceVersion=532, markedForDeletion: true ]}], customResource uid: cce5743c-c254-4ff8-a48d-2b7480a0e756, version: 532}, PostExecutionControl: PostExecutionControl{onlyFinalizerHandled=false, updatedCustomResource=null, runtimeException=null}
2021-08-30 08:06:37,265 58 i.j.o.p.DefaultEventHandler    [DEBUG] Marking successful execution for resource: subresource-1
2021-08-30 08:06:42,485 54 i.f.k.c.d.i.WatcherWebSocketListener [WARN ] Exec Failure java.net.SocketException Socket closed
2021-08-30 08:06:42,485 54 i.f.k.c.d.i.WatcherWebSocketListener [DEBUG] Couldn't report exception
io.fabric8.kubernetes.client.KubernetesClientException: Failed to start websocket
	at io.fabric8.kubernetes.client.dsl.internal.WatcherWebSocketListener.onFailure(WatcherWebSocketListener.java:77)
	at okhttp3.internal.ws.RealWebSocket.failWebSocket(RealWebSocket.java:571)
	at okhttp3.internal.ws.RealWebSocket$2.onResponse(RealWebSocket.java:216)
	at okhttp3.RealCall$AsyncCall.execute(RealCall.java:203)
	at okhttp3.internal.NamedRunnable.run(NamedRunnable.java:32)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at java.base/java.lang.Thread.run(Thread.java:829)
Caused by: java.net.SocketException: Socket closed
	at java.base/java.net.SocketInputStream.socketRead0(Native Method)
	at java.base/java.net.SocketInputStream.socketRead(SocketInputStream.java:115)
	at java.base/java.net.SocketInputStream.read(SocketInputStream.java:168)
	at java.base/java.net.SocketInputStream.read(SocketInputStream.java:140)
	at java.base/sun.security.ssl.SSLSocketInputRecord.read(SSLSocketInputRecord.java:478)
	at java.base/sun.security.ssl.SSLSocketInputRecord.readHeader(SSLSocketInputRecord.java:472)
	at java.base/sun.security.ssl.SSLSocketInputRecord.bytesInCompletePacket(SSLSocketInputRecord.java:70)
	at java.base/sun.security.ssl.SSLSocketImpl.readApplicationRecord(SSLSocketImpl.java:1374)
	at java.base/sun.security.ssl.SSLSocketImpl$AppInputStream.read(SSLSocketImpl.java:985)
	at okio.Okio$2.read(Okio.java:140)
	at okio.AsyncTimeout$2.read(AsyncTimeout.java:237)
	at okio.RealBufferedSource.request(RealBufferedSource.java:68)
	at okio.RealBufferedSource.require(RealBufferedSource.java:61)
	at okio.RealBufferedSource.readByte(RealBufferedSource.java:74)
	at okhttp3.internal.ws.WebSocketReader.readHeader(WebSocketReader.java:117)
	at okhttp3.internal.ws.WebSocketReader.processNextFrame(WebSocketReader.java:101)
	at okhttp3.internal.ws.RealWebSocket.loopReader(RealWebSocket.java:274)
	at okhttp3.internal.ws.RealWebSocket$2.onResponse(RealWebSocket.java:214)
	... 5 more
2021-08-30 08:06:42,485 54 i.f.k.c.d.i.AbstractWatchManager [DEBUG] Scheduling reconnect task
2021-08-30 08:06:42,485 54 i.f.k.c.d.i.AbstractWatchManager [DEBUG] Current reconnect backoff is 1000 milliseconds (T0)
2021-08-30 08:06:42,487 1 i.f.k.c.Config                 [DEBUG] Trying to configure client from Kubernetes config...
2021-08-30 08:06:42,487 1 i.f.k.c.Config                 [DEBUG] Found for Kubernetes config at: [/home/runner/.kube/config].
2021-08-30 08:06:42,555 1 i.j.o.IntegrationTestSupport   [INFO ] Initializing integration test in namespace java-operator-sdk-int-test
2021-08-30 08:06:42,605 1 i.j.o.Operator                 [INFO ] Operator SDK 1.9.6-SNAPSHOT (commit: 3cc18e3) built on 2021-08-30T08:04:26.000+0000 starting...
2021-08-30 08:06:42,609 1 i.j.o.Operator                 [INFO ] Client version: 5.7.0
2021-08-30 08:06:42,611 1 i.j.o.Operator                 [INFO ] Server version: 1.21
2021-08-30 08:06:42,616 1 i.f.k.c.d.i.AbstractWatchManager [DEBUG] Watching https://192.168.49.2:8443/apis/sample.javaoperatorsdk/v1/namespaces/java-operator-sdk-int-test/subresourcesample?watch=true...
2021-08-30 08:06:42,668 69 i.f.k.c.d.i.WatcherWebSocketListener [DEBUG] WebSocket successfully opened
2021-08-30 08:06:42,669 1 i.j.o.p.e.i.CustomResourceEventSource [DEBUG] Registered controller io.javaoperatorsdk.operator.sample.subresource.SubResourceTestCustomResource -> io.fabric8.kubernetes.client.dsl.internal.WatchConnectionManager@23da79eb for namespace: java-operator-sdk-int-test
2021-08-30 08:06:42,670 1 i.j.o.Operator                 [INFO ] Registered Controller: 'subresourcetestcustomresourcecontroller' for CRD: 'class io.javaoperatorsdk.operator.sample.subresource.SubResourceTestCustomResource' for namespace(s): [java-operator-sdk-int-test]
2021-08-30 08:06:42,670 1 i.j.o.IntegrationTestSupport   [INFO ] Operator is running with io.javaoperatorsdk.operator.sample.subresource.SubResourceTestCustomResourceController
2021-08-30 08:06:42,670 1 i.j.o.IntegrationTestSupport   [INFO ] Cleaning up namespace java-operator-sdk-int-test
2021-08-30 08:06:42,890 1 i.j.o.IntegrationTestSupport   [INFO ] Cleaned up namespace java-operator-sdk-int-test
2021-08-30 08:06:42,890 1 i.f.k.c.CustomResource         [DEBUG] Calling CustomResource#setKind doesn't do anything because the Kind is computed and shouldn't be changed
2021-08-30 08:06:42,896 69 i.j.o.p.e.i.CustomResourceEventSource [DEBUG] Event received for action: ADDED, resource: subresource-1
2021-08-30 08:06:42,896 69 i.j.o.p.DefaultEventHandler    [DEBUG] Received event: CustomResourceEvent{action=ADDED, resource=[ name=subresource-1, kind=SubresourceSample, apiVersion=sample.javaoperatorsdk/v1 ,resourceVersion=548, markedForDeletion: false ]}
2021-08-30 08:06:42,896 69 i.j.o.p.DefaultEventHandler    [DEBUG] Executing events for custom resource. Scope: ExecutionScope{events=[CustomResourceEvent{action=ADDED, resource=[ name=subresource-1, kind=SubresourceSample, apiVersion=sample.javaoperatorsdk/v1 ,resourceVersion=548, markedForDeletion: false ]}], customResource uid: 71f3636e-cfe8-4c1f-b1c9-d5bcaf80a33e, version: 548}
2021-08-30 08:06:42,897 73 i.j.o.p.EventDispatcher        [DEBUG] Handling events: [CustomResourceEvent{action=ADDED, resource=[ name=subresource-1, kind=SubresourceSample, apiVersion=sample.javaoperatorsdk/v1 ,resourceVersion=548, markedForDeletion: false ]}] for resource subresource-1
2021-08-30 08:06:42,897 73 i.j.o.p.EventDispatcher        [DEBUG] Executing createOrUpdate for resource subresource-1 with version: 548 with execution scope: ExecutionScope{events=[CustomResourceEvent{action=ADDED, resource=[ name=subresource-1, kind=SubresourceSample, apiVersion=sample.javaoperatorsdk/v1 ,resourceVersion=548, markedForDeletion: false ]}], customResource uid: 71f3636e-cfe8-4c1f-b1c9-d5bcaf80a33e, version: 548}
2021-08-30 08:06:42,897 73 i.j.o.s.s.SubResourceTestCustomResourceController [INFO ] Value: 1
2021-08-30 08:06:42,905 69 i.j.o.p.e.i.CustomResourceEventSource [DEBUG] Event received for action: MODIFIED, resource: subresource-1
2021-08-30 08:06:42,905 69 i.j.o.p.DefaultEventHandler    [DEBUG] Received event: CustomResourceEvent{action=MODIFIED, resource=[ name=subresource-1, kind=SubresourceSample, apiVersion=sample.javaoperatorsdk/v1 ,resourceVersion=549, markedForDeletion: false ]}
2021-08-30 08:06:42,905 69 i.j.o.p.DefaultEventHandler    [DEBUG] Skipping executing controller for resource id: 71f3636e-cfe8-4c1f-b1c9-d5bcaf80a33e. Events in queue: true. Controller in execution: true. Latest CustomResource present: true
2021-08-30 08:06:42,911 69 i.j.o.p.e.i.CustomResourceEventSource [DEBUG] Event received for action: MODIFIED, resource: subresource-1
2021-08-30 08:06:42,911 69 i.j.o.p.DefaultEventHandler    [DEBUG] Received event: CustomResourceEvent{action=MODIFIED, resource=[ name=subresource-1, kind=SubresourceSample, apiVersion=sample.javaoperatorsdk/v1 ,resourceVersion=550, markedForDeletion: false ]}
2021-08-30 08:06:42,912 69 i.j.o.p.DefaultEventHandler    [DEBUG] Skipping executing controller for resource id: 71f3636e-cfe8-4c1f-b1c9-d5bcaf80a33e. Events in queue: true. Controller in execution: true. Latest CustomResource present: true
2021-08-30 08:06:42,913 73 i.j.o.p.DefaultEventHandler    [DEBUG] Event processing finished. Scope: ExecutionScope{events=[CustomResourceEvent{action=ADDED, resource=[ name=subresource-1, kind=SubresourceSample, apiVersion=sample.javaoperatorsdk/v1 ,resourceVersion=548, markedForDeletion: false ]}], customResource uid: 71f3636e-cfe8-4c1f-b1c9-d5bcaf80a33e, version: 548}, PostExecutionControl: PostExecutionControl{onlyFinalizerHandled=false, updatedCustomResource=CustomResource{kind='SubresourceSample', apiVersion='sample.javaoperatorsdk/v1', metadata=ObjectMeta(annotations=null, clusterName=null, creationTimestamp=2021-08-30T08:06:42Z, deletionGracePeriodSeconds=null, deletionTimestamp=null, finalizers=[subresourcesample.sample.javaoperatorsdk/finalizer], generateName=null, generation=1, labels=null, managedFields=[ManagedFieldsEntry(apiVersion=sample.javaoperatorsdk/v1, fieldsType=FieldsV1, fieldsV1=FieldsV1(additionalProperties={f:metadata={f:finalizers={.={}, v:"subresourcesample.sample.javaoperatorsdk/finalizer"={}}}, f:status={.={}, f:state={}}, f:spec={.={}, f:value={}}}), manager=okhttp, operation=Update, time=2021-08-30T08:06:42Z, additionalProperties={})], name=subresource-1, namespace=java-operator-sdk-int-test, ownerReferences=[], resourceVersion=549, selfLink=null, uid=71f3636e-cfe8-4c1f-b1c9-d5bcaf80a33e, additionalProperties={}), spec=io.javaoperatorsdk.operator.sample.subresource.SubResourceTestCustomResourceSpec@5268f052, status=io.javaoperatorsdk.operator.sample.subresource.SubResourceTestCustomResourceStatus@56577ec7}, runtimeException=null}
2021-08-30 08:06:42,913 73 i.j.o.p.DefaultEventHandler    [DEBUG] Marking successful execution for resource: subresource-1
2021-08-30 08:06:42,913 73 i.j.o.p.DefaultEventHandler    [DEBUG] Trying to update resource cache from update response for resource: subresource-1 new version: 549 old version: 548
2021-08-30 08:06:42,914 73 i.j.o.p.DefaultEventHandler    [DEBUG] Executing events for custom resource. Scope: ExecutionScope{events=[CustomResourceEvent{action=MODIFIED, resource=[ name=subresource-1, kind=SubresourceSample, apiVersion=sample.javaoperatorsdk/v1 ,resourceVersion=549, markedForDeletion: false ]}, CustomResourceEvent{action=MODIFIED, resource=[ name=subresource-1, kind=SubresourceSample, apiVersion=sample.javaoperatorsdk/v1 ,resourceVersion=550, markedForDeletion: false ]}], customResource uid: 71f3636e-cfe8-4c1f-b1c9-d5bcaf80a33e, version: 550}
2021-08-30 08:06:42,916 73 i.j.o.p.EventDispatcher        [DEBUG] Handling events: [CustomResourceEvent{action=MODIFIED, resource=[ name=subresource-1, kind=SubresourceSample, apiVersion=sample.javaoperatorsdk/v1 ,resourceVersion=549, markedForDeletion: false ]}, CustomResourceEvent{action=MODIFIED, resource=[ name=subresource-1, kind=SubresourceSample, apiVersion=sample.javaoperatorsdk/v1 ,resourceVersion=550, markedForDeletion: false ]}] for resource subresource-1
2021-08-30 08:06:42,916 73 i.j.o.p.EventDispatcher        [DEBUG] Executing createOrUpdate for resource subresource-1 with version: 550 with execution scope: ExecutionScope{events=[CustomResourceEvent{action=MODIFIED, resource=[ name=subresource-1, kind=SubresourceSample, apiVersion=sample.javaoperatorsdk/v1 ,resourceVersion=549, markedForDeletion: false ]}, CustomResourceEvent{action=MODIFIED, resource=[ name=subresource-1, kind=SubresourceSample, apiVersion=sample.javaoperatorsdk/v1 ,resourceVersion=550, markedForDeletion: false ]}], customResource uid: 71f3636e-cfe8-4c1f-b1c9-d5bcaf80a33e, version: 550}
2021-08-30 08:06:42,916 73 i.j.o.s.s.SubResourceTestCustomResourceController [INFO ] Value: new value
2021-08-30 08:06:42,919 73 i.j.o.p.DefaultEventHandler    [DEBUG] Event processing finished. Scope: ExecutionScope{events=[CustomResourceEvent{action=MODIFIED, resource=[ name=subresource-1, kind=SubresourceSample, apiVersion=sample.javaoperatorsdk/v1 ,resourceVersion=549, markedForDeletion: false ]}, CustomResourceEvent{action=MODIFIED, resource=[ name=subresource-1, kind=SubresourceSample, apiVersion=sample.javaoperatorsdk/v1 ,resourceVersion=550, markedForDeletion: false ]}], customResource uid: 71f3636e-cfe8-4c1f-b1c9-d5bcaf80a33e, version: 550}, PostExecutionControl: PostExecutionControl{onlyFinalizerHandled=false, updatedCustomResource=CustomResource{kind='SubresourceSample', apiVersion='sample.javaoperatorsdk/v1', metadata=ObjectMeta(annotations=null, clusterName=null, creationTimestamp=2021-08-30T08:06:42Z, deletionGracePeriodSeconds=null, deletionTimestamp=null, finalizers=[subresourcesample.sample.javaoperatorsdk/finalizer], generateName=null, generation=2, labels=null, managedFields=[ManagedFieldsEntry(apiVersion=sample.javaoperatorsdk/v1, fieldsType=FieldsV1, fieldsV1=FieldsV1(additionalProperties={f:metadata={f:finalizers={.={}, v:"subresourcesample.sample.javaoperatorsdk/finalizer"={}}}, f:status={.={}, f:state={}}, f:spec={.={}, f:value={}}}), manager=okhttp, operation=Update, time=2021-08-30T08:06:42Z, additionalProperties={})], name=subresource-1, namespace=java-operator-sdk-int-test, ownerReferences=[], resourceVersion=550, selfLink=null, uid=71f3636e-cfe8-4c1f-b1c9-d5bcaf80a33e, additionalProperties={}), spec=io.javaoperatorsdk.operator.sample.subresource.SubResourceTestCustomResourceSpec@220ccbd5, status=io.javaoperatorsdk.operator.sample.subresource.SubResourceTestCustomResourceStatus@4f403815}, runtimeException=null}
2021-08-30 08:06:42,919 73 i.j.o.p.DefaultEventHandler    [DEBUG] Marking successful execution for resource: subresource-1
2021-08-30 08:06:42,919 73 i.j.o.p.DefaultEventHandler    [DEBUG] Trying to update resource cache from update response for resource: subresource-1 new version: 550 old version: 550
2021-08-30 08:06:42,920 73 i.j.o.p.DefaultEventHandler    [DEBUG] Skipping executing controller for resource id: 71f3636e-cfe8-4c1f-b1c9-d5bcaf80a33e. Events in queue: false. Controller in execution: false. Latest CustomResource present: true
2021-08-30 08:06:43,225 69 i.f.k.c.d.i.WatcherWebSocketListener [WARN ] Exec Failure java.net.SocketException Socket closed
2021-08-30 08:06:43,225 69 i.f.k.c.d.i.WatcherWebSocketListener [DEBUG] Couldn't report exception
io.fabric8.kubernetes.client.KubernetesClientException: Failed to start websocket
	at io.fabric8.kubernetes.client.dsl.internal.WatcherWebSocketListener.onFailure(WatcherWebSocketListener.java:77)
	at okhttp3.internal.ws.RealWebSocket.failWebSocket(RealWebSocket.java:571)
	at okhttp3.internal.ws.RealWebSocket$2.onResponse(RealWebSocket.java:216)
	at okhttp3.RealCall$AsyncCall.execute(RealCall.java:203)
	at okhttp3.internal.NamedRunnable.run(NamedRunnable.java:32)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at java.base/java.lang.Thread.run(Thread.java:829)
Caused by: java.net.SocketException: Socket closed
	at java.base/java.net.SocketInputStream.socketRead0(Native Method)
	at java.base/java.net.SocketInputStream.socketRead(SocketInputStream.java:115)
	at java.base/java.net.SocketInputStream.read(SocketInputStream.java:168)
	at java.base/java.net.SocketInputStream.read(SocketInputStream.java:140)
	at java.base/sun.security.ssl.SSLSocketInputRecord.read(SSLSocketInputRecord.java:478)
	at java.base/sun.security.ssl.SSLSocketInputRecord.readHeader(SSLSocketInputRecord.java:472)
	at java.base/sun.security.ssl.SSLSocketInputRecord.bytesInCompletePacket(SSLSocketInputRecord.java:70)
	at java.base/sun.security.ssl.SSLSocketImpl.readApplicationRecord(SSLSocketImpl.java:1374)
	at java.base/sun.security.ssl.SSLSocketImpl$AppInputStream.read(SSLSocketImpl.java:985)
	at okio.Okio$2.read(Okio.java:140)
	at okio.AsyncTimeout$2.read(AsyncTimeout.java:237)
	at okio.RealBufferedSource.request(RealBufferedSource.java:68)
	at okio.RealBufferedSource.require(RealBufferedSource.java:61)
	at okio.RealBufferedSource.readByte(RealBufferedSource.java:74)
	at okhttp3.internal.ws.WebSocketReader.readHeader(WebSocketReader.java:117)
	at okhttp3.internal.ws.WebSocketReader.processNextFrame(WebSocketReader.java:101)
	at okhttp3.internal.ws.RealWebSocket.loopReader(RealWebSocket.java:274)
	at okhttp3.internal.ws.RealWebSocket$2.onResponse(RealWebSocket.java:214)
	... 5 more
2021-08-30 08:06:43,225 69 i.f.k.c.d.i.AbstractWatchManager [DEBUG] Scheduling reconnect task
2021-08-30 08:06:43,225 69 i.f.k.c.d.i.AbstractWatchManager [DEBUG] Current reconnect backoff is 1000 milliseconds (T0)
2021-08-30 08:06:43,231 1 i.f.k.c.Config                 [DEBUG] Trying to configure client from Kubernetes config...
2021-08-30 08:06:43,231 1 i.f.k.c.Config                 [DEBUG] Found for Kubernetes config at: [/home/runner/.kube/config].
2021-08-30 08:06:43,286 1 i.j.o.IntegrationTestSupport   [INFO ] Initializing integration test in namespace java-operator-sdk-int-test
2021-08-30 08:06:43,379 1 i.j.o.Operator                 [INFO ] Operator SDK 1.9.6-SNAPSHOT (commit: 3cc18e3) built on 2021-08-30T08:04:26.000+0000 starting...
2021-08-30 08:06:43,379 1 i.j.o.Operator                 [INFO ] Client version: 5.7.0
2021-08-30 08:06:43,380 1 i.j.o.Operator                 [INFO ] Server version: 1.21
2021-08-30 08:06:43,383 1 i.f.k.c.d.i.AbstractWatchManager [DEBUG] Watching https://192.168.49.2:8443/apis/sample.javaoperatorsdk/v1/namespaces/java-operator-sdk-int-test/subresourcesample?watch=true...
2021-08-30 08:06:43,410 80 i.f.k.c.d.i.WatcherWebSocketListener [DEBUG] WebSocket successfully opened
2021-08-30 08:06:43,411 1 i.j.o.p.e.i.CustomResourceEventSource [DEBUG] Registered controller io.javaoperatorsdk.operator.sample.subresource.SubResourceTestCustomResource -> io.fabric8.kubernetes.client.dsl.internal.WatchConnectionManager@2f80cb79 for namespace: java-operator-sdk-int-test
2021-08-30 08:06:43,411 1 i.j.o.Operator                 [INFO ] Registered Controller: 'subresourcetestcustomresourcecontroller' for CRD: 'class io.javaoperatorsdk.operator.sample.subresource.SubResourceTestCustomResource' for namespace(s): [java-operator-sdk-int-test]
2021-08-30 08:06:43,411 1 i.j.o.IntegrationTestSupport   [INFO ] Operator is running with io.javaoperatorsdk.operator.sample.subresource.SubResourceTestCustomResourceController
2021-08-30 08:06:43,411 1 i.j.o.IntegrationTestSupport   [INFO ] Cleaning up namespace java-operator-sdk-int-test
2021-08-30 08:06:43,411 80 i.j.o.p.e.i.CustomResourceEventSource [DEBUG] Event received for action: ADDED, resource: subresource-1
2021-08-30 08:06:43,411 80 i.j.o.p.DefaultEventHandler    [DEBUG] Received event: CustomResourceEvent{action=ADDED, resource=[ name=subresource-1, kind=SubresourceSample, apiVersion=sample.javaoperatorsdk/v1 ,resourceVersion=550, markedForDeletion: false ]}
2021-08-30 08:06:43,413 80 i.j.o.p.DefaultEventHandler    [DEBUG] Executing events for custom resource. Scope: ExecutionScope{events=[CustomResourceEvent{action=ADDED, resource=[ name=subresource-1, kind=SubresourceSample, apiVersion=sample.javaoperatorsdk/v1 ,resourceVersion=550, markedForDeletion: false ]}], customResource uid: 71f3636e-cfe8-4c1f-b1c9-d5bcaf80a33e, version: 550}
2021-08-30 08:06:43,416 82 i.j.o.p.EventDispatcher        [DEBUG] Handling events: [CustomResourceEvent{action=ADDED, resource=[ name=subresource-1, kind=SubresourceSample, apiVersion=sample.javaoperatorsdk/v1 ,resourceVersion=550, markedForDeletion: false ]}] for resource subresource-1
2021-08-30 08:06:43,417 82 i.j.o.p.EventDispatcher        [DEBUG] Executing createOrUpdate for resource subresource-1 with version: 550 with execution scope: ExecutionScope{events=[CustomResourceEvent{action=ADDED, resource=[ name=subresource-1, kind=SubresourceSample, apiVersion=sample.javaoperatorsdk/v1 ,resourceVersion=550, markedForDeletion: false ]}], customResource uid: 71f3636e-cfe8-4c1f-b1c9-d5bcaf80a33e, version: 550}
2021-08-30 08:06:43,417 82 i.j.o.s.s.SubResourceTestCustomResourceController [INFO ] Value: new value
2021-08-30 08:06:43,422 82 i.j.o.p.DefaultEventHandler    [DEBUG] Event processing finished. Scope: ExecutionScope{events=[CustomResourceEvent{action=ADDED, resource=[ name=subresource-1, kind=SubresourceSample, apiVersion=sample.javaoperatorsdk/v1 ,resourceVersion=550, markedForDeletion: false ]}], customResource uid: 71f3636e-cfe8-4c1f-b1c9-d5bcaf80a33e, version: 550}, PostExecutionControl: PostExecutionControl{onlyFinalizerHandled=false, updatedCustomResource=CustomResource{kind='SubresourceSample', apiVersion='sample.javaoperatorsdk/v1', metadata=ObjectMeta(annotations=null, clusterName=null, creationTimestamp=2021-08-30T08:06:42Z, deletionGracePeriodSeconds=null, deletionTimestamp=null, finalizers=[subresourcesample.sample.javaoperatorsdk/finalizer], generateName=null, generation=2, labels=null, managedFields=[ManagedFieldsEntry(apiVersion=sample.javaoperatorsdk/v1, fieldsType=FieldsV1, fieldsV1=FieldsV1(additionalProperties={f:metadata={f:finalizers={.={}, v:"subresourcesample.sample.javaoperatorsdk/finalizer"={}}}, f:status={.={}, f:state={}}, f:spec={.={}, f:value={}}}), manager=okhttp, operation=Update, time=2021-08-30T08:06:42Z, additionalProperties={})], name=subresource-1, namespace=java-operator-sdk-int-test, ownerReferences=[], resourceVersion=550, selfLink=null, uid=71f3636e-cfe8-4c1f-b1c9-d5bcaf80a33e, additionalProperties={}), spec=io.javaoperatorsdk.operator.sample.subresource.SubResourceTestCustomResourceSpec@7ed8ef18, status=io.javaoperatorsdk.operator.sample.subresource.SubResourceTestCustomResourceStatus@7ae7641b}, runtimeException=null}
2021-08-30 08:06:43,422 82 i.j.o.p.DefaultEventHandler    [DEBUG] Marking successful execution for resource: subresource-1
2021-08-30 08:06:43,422 82 i.j.o.p.DefaultEventHandler    [DEBUG] Trying to update resource cache from update response for resource: subresource-1 new version: 550 old version: 550
2021-08-30 08:06:43,422 82 i.j.o.p.DefaultEventHandler    [DEBUG] Skipping executing controller for resource id: 71f3636e-cfe8-4c1f-b1c9-d5bcaf80a33e. Events in queue: false. Controller in execution: false. Latest CustomResource present: true
2021-08-30 08:06:43,488 41 i.f.k.c.d.i.AbstractWatchManager [DEBUG] Watching https://192.168.49.2:8443/apis/sample.javaoperatorsdk/v1/namespaces/java-operator-sdk-int-test/subresourcesample?resourceVersion=532&watch=true...
2021-08-30 08:06:43,488 41 i.f.k.c.d.i.WatchConnectionManager [DEBUG] Closing websocket okhttp3.internal.ws.RealWebSocket@b69bdba
2021-08-30 08:06:43,488 41 i.f.k.c.d.i.WatchConnectionManager [DEBUG] Websocket already closed okhttp3.internal.ws.RealWebSocket@b69bdba
2021-08-30 08:06:43,488 41 i.f.k.c.d.i.WatcherWebSocketListener [WARN ] Exec Failure java.io.InterruptedIOException executor rejected
2021-08-30 08:06:43,489 41 i.f.k.c.d.i.AbstractWatchManager [DEBUG] Reconnect already scheduled
2021-08-30 08:06:44,226 41 i.f.k.c.d.i.AbstractWatchManager [DEBUG] Watching https://192.168.49.2:8443/apis/sample.javaoperatorsdk/v1/namespaces/java-operator-sdk-int-test/subresourcesample?resourceVersion=550&watch=true...
2021-08-30 08:06:44,226 41 i.f.k.c.d.i.WatchConnectionManager [DEBUG] Closing websocket okhttp3.internal.ws.RealWebSocket@5775f0d2
2021-08-30 08:06:44,226 41 i.f.k.c.d.i.WatchConnectionManager [DEBUG] Websocket already closed okhttp3.internal.ws.RealWebSocket@5775f0d2
2021-08-30 08:06:44,227 41 i.f.k.c.d.i.WatcherWebSocketListener [WARN ] Exec Failure java.io.InterruptedIOException executor rejected
2021-08-30 08:06:44,227 41 i.f.k.c.d.i.AbstractWatchManager [DEBUG] Reconnect already scheduled
Error:  Tests run: 4, Failures: 1, Errors: 1, Skipped: 0, Time elapsed: 81.321 s <<< FAILURE! - in io.javaoperatorsdk.operator.SubResourceUpdateIT
Error:  io.javaoperatorsdk.operator.SubResourceUpdateIT.updateCustomResourceAfterSubResourceChange  Time elapsed: 0.742 s  <<< FAILURE!
org.opentest4j.AssertionFailedError: 

expected: 3
 but was: 2
	at io.javaoperatorsdk.operator.SubResourceUpdateIT.lambda$updateCustomResourceAfterSubResourceChange$3(SubResourceUpdateIT.java:105)
	at io.javaoperatorsdk.operator.SubResourceUpdateIT.updateCustomResourceAfterSubResourceChange(SubResourceUpdateIT.java:89)

Error:  io.javaoperatorsdk.operator.SubResourceUpdateIT.updatesSubResourceStatusNoFinalizer  Time elapsed: 60.213 s  <<< ERROR!
org.awaitility.core.ConditionTimeoutException: 
Condition with alias 'all CRs cleaned up' didn't complete within 1 minutes because assertion condition defined as a lambda expression in io.javaoperatorsdk.operator.IntegrationTestSupport 
Expecting empty but was: [CustomResource{kind='SubresourceSample', apiVersion='sample.javaoperatorsdk/v1', metadata=ObjectMeta(annotations=null, clusterName=null, creationTimestamp=2021-08-30T08:06:42Z, deletionGracePeriodSeconds=null, deletionTimestamp=null, finalizers=[subresourcesample.sample.javaoperatorsdk/finalizer], generateName=null, generation=2, labels=null, managedFields=[ManagedFieldsEntry(apiVersion=sample.javaoperatorsdk/v1, fieldsType=FieldsV1, fieldsV1=FieldsV1(additionalProperties={f:metadata={f:finalizers={.={}, v:"subresourcesample.sample.javaoperatorsdk/finalizer"={}}}, f:status={.={}, f:state={}}, f:spec={.={}, f:value={}}}), manager=okhttp, operation=Update, time=2021-08-30T08:06:42Z, additionalProperties={})], name=subresource-1, namespace=java-operator-sdk-int-test, ownerReferences=[], resourceVersion=550, selfLink=null, uid=71f3636e-cfe8-4c1f-b1c9-d5bcaf80a33e, additionalProperties={}), spec=io.javaoperatorsdk.operator.sample.subresource.SubResourceTestCustomResourceSpec@3a8e098a, status=io.javaoperatorsdk.operator.sample.subresource.SubResourceTestCustomResourceStatus@146418af}].
	at io.javaoperatorsdk.operator.SubResourceUpdateIT.initAndCleanup(SubResourceUpdateIT.java:29)
Caused by: java.lang.AssertionError: 

Expecting empty but was: [CustomResource{kind='SubresourceSample', apiVersion='sample.javaoperatorsdk/v1', metadata=ObjectMeta(annotations=null, clusterName=null, creationTimestamp=2021-08-30T08:06:42Z, deletionGracePeriodSeconds=null, deletionTimestamp=null, finalizers=[subresourcesample.sample.javaoperatorsdk/finalizer], generateName=null, generation=2, labels=null, managedFields=[ManagedFieldsEntry(apiVersion=sample.javaoperatorsdk/v1, fieldsType=FieldsV1, fieldsV1=FieldsV1(additionalProperties={f:metadata={f:finalizers={.={}, v:"subresourcesample.sample.javaoperatorsdk/finalizer"={}}}, f:status={.={}, f:state={}}, f:spec={.={}, f:value={}}}), manager=okhttp, operation=Update, time=2021-08-30T08:06:42Z, additionalProperties={})], name=subresource-1, namespace=java-operator-sdk-int-test, ownerReferences=[], resourceVersion=550, selfLink=null, uid=71f3636e-cfe8-4c1f-b1c9-d5bcaf80a33e, additionalProperties={}), spec=io.javaoperatorsdk.operator.sample.subresource.SubResourceTestCustomResourceSpec@3a8e098a, status=io.javaoperatorsdk.operator.sample.subresource.SubResourceTestCustomResourceStatus@146418af}]