Upgrade ginkgo test with use of Eventually instead of time funcs

[harshad16]

Instead of use of time function (Ex here ) we should use some of the Eventually wait helpers. docs

Originally posted by @jiridanek in #373 (comment)

[jiridanek]

Here's my brief survey on how to handle timing

• ginkgo/gomega has Eventually and Consistently; kubebuilder demo uses that, but they have 10s treshold for Consistently, which seems huge (but conceptually necessary)
  • this should work most of the time, except maybe for the Consistently assertions I'm unhappy with
• some tests in other projects run Reconcile themselves in the test code directly, not through controller-manager, so they know exactly when reconcile happened; tried to see if there's nonintrusive way to hook into controller-manager, but there does not seem to be; working without controller-manager is not sufficiently faithful to real deployment for me
  • this could be wrapped, make ObservableReconciler type that informs about how the Reconcile function proceeded and it can be then checked when no further reconciles are expected; but that's not really any better than the prometheus metric below I guess
• metrics that controller-manager serves, they look good and watching these, we may use lower thresholds for Eventually because we can get workqueue stats (condition the wait on number of items processed remains constant, number of items in queue is 0, and if this holds for a second, then we know reconciler is done; possibly check for hold-up reconcile as there's a stat for that too, all this can be done in a helper function)
  • and to do that, either use the http endpoint or get the metrics directly from an exposed global variable

sources:

• https://superorbital.io/blog/testing-production-controllers/

[jiridanek]

Example of metrics

# HELP certwatcher_read_certificate_errors_total Total number of certificate read errors
# TYPE certwatcher_read_certificate_errors_total counter
certwatcher_read_certificate_errors_total 0
# HELP certwatcher_read_certificate_total Total number of certificate reads
# TYPE certwatcher_read_certificate_total counter
certwatcher_read_certificate_total 1
# HELP controller_runtime_active_workers Number of currently used workers per controller
# TYPE controller_runtime_active_workers gauge
controller_runtime_active_workers{controller="notebook"} 0
# HELP controller_runtime_max_concurrent_reconciles Maximum number of concurrent reconciles per controller
# TYPE controller_runtime_max_concurrent_reconciles gauge
controller_runtime_max_concurrent_reconciles{controller="notebook"} 1
# HELP controller_runtime_reconcile_errors_total Total number of reconciliation errors per controller
# TYPE controller_runtime_reconcile_errors_total counter
controller_runtime_reconcile_errors_total{controller="notebook"} 0
# HELP controller_runtime_reconcile_time_seconds Length of time per reconciliation per controller
# TYPE controller_runtime_reconcile_time_seconds histogram
controller_runtime_reconcile_time_seconds_bucket{controller="notebook",le="0.005"} 2
controller_runtime_reconcile_time_seconds_bucket{controller="notebook",le="0.01"} 6
controller_runtime_reconcile_time_seconds_bucket{controller="notebook",le="0.025"} 9
controller_runtime_reconcile_time_seconds_bucket{controller="notebook",le="0.05"} 9
controller_runtime_reconcile_time_seconds_bucket{controller="notebook",le="0.1"} 9
controller_runtime_reconcile_time_seconds_bucket{controller="notebook",le="0.15"} 9
controller_runtime_reconcile_time_seconds_bucket{controller="notebook",le="0.2"} 9
controller_runtime_reconcile_time_seconds_bucket{controller="notebook",le="0.25"} 9
controller_runtime_reconcile_time_seconds_bucket{controller="notebook",le="0.3"} 9
controller_runtime_reconcile_time_seconds_bucket{controller="notebook",le="0.35"} 9
controller_runtime_reconcile_time_seconds_bucket{controller="notebook",le="0.4"} 9
controller_runtime_reconcile_time_seconds_bucket{controller="notebook",le="0.45"} 9
controller_runtime_reconcile_time_seconds_bucket{controller="notebook",le="0.5"} 9
controller_runtime_reconcile_time_seconds_bucket{controller="notebook",le="0.6"} 9
controller_runtime_reconcile_time_seconds_bucket{controller="notebook",le="0.7"} 9
controller_runtime_reconcile_time_seconds_bucket{controller="notebook",le="0.8"} 9
controller_runtime_reconcile_time_seconds_bucket{controller="notebook",le="0.9"} 9
controller_runtime_reconcile_time_seconds_bucket{controller="notebook",le="1"} 9
controller_runtime_reconcile_time_seconds_bucket{controller="notebook",le="1.25"} 9
controller_runtime_reconcile_time_seconds_bucket{controller="notebook",le="1.5"} 9
controller_runtime_reconcile_time_seconds_bucket{controller="notebook",le="1.75"} 9
controller_runtime_reconcile_time_seconds_bucket{controller="notebook",le="2"} 9
controller_runtime_reconcile_time_seconds_bucket{controller="notebook",le="2.5"} 9
controller_runtime_reconcile_time_seconds_bucket{controller="notebook",le="3"} 9
controller_runtime_reconcile_time_seconds_bucket{controller="notebook",le="3.5"} 9
controller_runtime_reconcile_time_seconds_bucket{controller="notebook",le="4"} 9
controller_runtime_reconcile_time_seconds_bucket{controller="notebook",le="4.5"} 9
controller_runtime_reconcile_time_seconds_bucket{controller="notebook",le="5"} 9
controller_runtime_reconcile_time_seconds_bucket{controller="notebook",le="6"} 9
controller_runtime_reconcile_time_seconds_bucket{controller="notebook",le="7"} 10
controller_runtime_reconcile_time_seconds_bucket{controller="notebook",le="8"} 10
controller_runtime_reconcile_time_seconds_bucket{controller="notebook",le="9"} 10
controller_runtime_reconcile_time_seconds_bucket{controller="notebook",le="10"} 10
controller_runtime_reconcile_time_seconds_bucket{controller="notebook",le="15"} 10
controller_runtime_reconcile_time_seconds_bucket{controller="notebook",le="20"} 10
controller_runtime_reconcile_time_seconds_bucket{controller="notebook",le="25"} 10
controller_runtime_reconcile_time_seconds_bucket{controller="notebook",le="30"} 10
controller_runtime_reconcile_time_seconds_bucket{controller="notebook",le="40"} 10
controller_runtime_reconcile_time_seconds_bucket{controller="notebook",le="50"} 10
controller_runtime_reconcile_time_seconds_bucket{controller="notebook",le="60"} 10
controller_runtime_reconcile_time_seconds_bucket{controller="notebook",le="+Inf"} 10
controller_runtime_reconcile_time_seconds_sum{controller="notebook"} 6.0877451659999995
controller_runtime_reconcile_time_seconds_count{controller="notebook"} 10
# HELP controller_runtime_reconcile_total Total number of reconciliations per controller
# TYPE controller_runtime_reconcile_total counter
controller_runtime_reconcile_total{controller="notebook",result="error"} 0
controller_runtime_reconcile_total{controller="notebook",result="requeue"} 0
controller_runtime_reconcile_total{controller="notebook",result="requeue_after"} 0
controller_runtime_reconcile_total{controller="notebook",result="success"} 10
# HELP controller_runtime_webhook_latency_seconds Histogram of the latency of processing admission requests
# TYPE controller_runtime_webhook_latency_seconds histogram
controller_runtime_webhook_latency_seconds_bucket{webhook="/mutate-notebook-v1",le="0.005"} 2
controller_runtime_webhook_latency_seconds_bucket{webhook="/mutate-notebook-v1",le="0.01"} 2
controller_runtime_webhook_latency_seconds_bucket{webhook="/mutate-notebook-v1",le="0.025"} 2
controller_runtime_webhook_latency_seconds_bucket{webhook="/mutate-notebook-v1",le="0.05"} 2
controller_runtime_webhook_latency_seconds_bucket{webhook="/mutate-notebook-v1",le="0.1"} 2
controller_runtime_webhook_latency_seconds_bucket{webhook="/mutate-notebook-v1",le="0.25"} 2
controller_runtime_webhook_latency_seconds_bucket{webhook="/mutate-notebook-v1",le="0.5"} 2
controller_runtime_webhook_latency_seconds_bucket{webhook="/mutate-notebook-v1",le="1"} 2
controller_runtime_webhook_latency_seconds_bucket{webhook="/mutate-notebook-v1",le="2.5"} 2
controller_runtime_webhook_latency_seconds_bucket{webhook="/mutate-notebook-v1",le="5"} 2
controller_runtime_webhook_latency_seconds_bucket{webhook="/mutate-notebook-v1",le="10"} 2
controller_runtime_webhook_latency_seconds_bucket{webhook="/mutate-notebook-v1",le="+Inf"} 2
controller_runtime_webhook_latency_seconds_sum{webhook="/mutate-notebook-v1"} 0.002899084
controller_runtime_webhook_latency_seconds_count{webhook="/mutate-notebook-v1"} 2
# HELP controller_runtime_webhook_requests_in_flight Current number of admission requests being served.
# TYPE controller_runtime_webhook_requests_in_flight gauge
controller_runtime_webhook_requests_in_flight{webhook="/mutate-notebook-v1"} 0
# HELP controller_runtime_webhook_requests_total Total number of admission requests by HTTP status code.
# TYPE controller_runtime_webhook_requests_total counter
controller_runtime_webhook_requests_total{code="200",webhook="/mutate-notebook-v1"} 2
controller_runtime_webhook_requests_total{code="500",webhook="/mutate-notebook-v1"} 0
# HELP go_gc_duration_seconds A summary of the pause duration of garbage collection cycles.
# TYPE go_gc_duration_seconds summary
go_gc_duration_seconds{quantile="0"} 2.725e-05
go_gc_duration_seconds{quantile="0.25"} 3.3834e-05
go_gc_duration_seconds{quantile="0.5"} 4.45e-05
go_gc_duration_seconds{quantile="0.75"} 0.000105792
go_gc_duration_seconds{quantile="1"} 0.000196792
go_gc_duration_seconds_sum 0.001412457
go_gc_duration_seconds_count 20
# HELP go_goroutines Number of goroutines that currently exist.
# TYPE go_goroutines gauge
go_goroutines 152
# HELP go_info Information about the Go environment.
# TYPE go_info gauge
go_info{version="go1.23.2"} 1
# HELP go_memstats_alloc_bytes Number of bytes allocated and still in use.
# TYPE go_memstats_alloc_bytes gauge
go_memstats_alloc_bytes 1.3463432e+07
# HELP go_memstats_alloc_bytes_total Total number of bytes allocated, even if freed.
# TYPE go_memstats_alloc_bytes_total counter
go_memstats_alloc_bytes_total 9.4976624e+07
# HELP go_memstats_buck_hash_sys_bytes Number of bytes used by the profiling bucket hash table.
# TYPE go_memstats_buck_hash_sys_bytes gauge
go_memstats_buck_hash_sys_bytes 1.508725e+06
# HELP go_memstats_frees_total Total number of frees.
# TYPE go_memstats_frees_total counter
go_memstats_frees_total 572800
# HELP go_memstats_gc_sys_bytes Number of bytes used for garbage collection system metadata.
# TYPE go_memstats_gc_sys_bytes gauge
go_memstats_gc_sys_bytes 3.7754e+06
# HELP go_memstats_heap_alloc_bytes Number of heap bytes allocated and still in use.
# TYPE go_memstats_heap_alloc_bytes gauge
go_memstats_heap_alloc_bytes 1.3463432e+07
# HELP go_memstats_heap_idle_bytes Number of heap bytes waiting to be used.
# TYPE go_memstats_heap_idle_bytes gauge
go_memstats_heap_idle_bytes 1.1362304e+07
# HELP go_memstats_heap_inuse_bytes Number of heap bytes that are in use.
# TYPE go_memstats_heap_inuse_bytes gauge
go_memstats_heap_inuse_bytes 2.043904e+07
# HELP go_memstats_heap_objects Number of allocated objects.
# TYPE go_memstats_heap_objects gauge
go_memstats_heap_objects 44656
# HELP go_memstats_heap_released_bytes Number of heap bytes released to OS.
# TYPE go_memstats_heap_released_bytes gauge
go_memstats_heap_released_bytes 5.5296e+06
# HELP go_memstats_heap_sys_bytes Number of heap bytes obtained from system.
# TYPE go_memstats_heap_sys_bytes gauge
go_memstats_heap_sys_bytes 3.1801344e+07
# HELP go_memstats_last_gc_time_seconds Number of seconds since 1970 of last garbage collection.
# TYPE go_memstats_last_gc_time_seconds gauge
go_memstats_last_gc_time_seconds 1.729666788756192e+09
# HELP go_memstats_lookups_total Total number of pointer lookups.
# TYPE go_memstats_lookups_total counter
go_memstats_lookups_total 0
# HELP go_memstats_mallocs_total Total number of mallocs.
# TYPE go_memstats_mallocs_total counter
go_memstats_mallocs_total 617456
# HELP go_memstats_mcache_inuse_bytes Number of bytes in use by mcache structures.
# TYPE go_memstats_mcache_inuse_bytes gauge
go_memstats_mcache_inuse_bytes 14400
# HELP go_memstats_mcache_sys_bytes Number of bytes used for mcache structures obtained from system.
# TYPE go_memstats_mcache_sys_bytes gauge
go_memstats_mcache_sys_bytes 15600
# HELP go_memstats_mspan_inuse_bytes Number of bytes in use by mspan structures.
# TYPE go_memstats_mspan_inuse_bytes gauge
go_memstats_mspan_inuse_bytes 357760
# HELP go_memstats_mspan_sys_bytes Number of bytes used for mspan structures obtained from system.
# TYPE go_memstats_mspan_sys_bytes gauge
go_memstats_mspan_sys_bytes 391680
# HELP go_memstats_next_gc_bytes Number of heap bytes when next garbage collection will take place.
# TYPE go_memstats_next_gc_bytes gauge
go_memstats_next_gc_bytes 2.6274448e+07
# HELP go_memstats_other_sys_bytes Number of bytes used for other system allocations.
# TYPE go_memstats_other_sys_bytes gauge
go_memstats_other_sys_bytes 2.665723e+06
# HELP go_memstats_stack_inuse_bytes Number of bytes in use by the stack allocator.
# TYPE go_memstats_stack_inuse_bytes gauge
go_memstats_stack_inuse_bytes 1.671168e+06
# HELP go_memstats_stack_sys_bytes Number of bytes obtained from system for stack allocator.
# TYPE go_memstats_stack_sys_bytes gauge
go_memstats_stack_sys_bytes 1.671168e+06
# HELP go_memstats_sys_bytes Number of bytes obtained from system.
# TYPE go_memstats_sys_bytes gauge
go_memstats_sys_bytes 4.182964e+07
# HELP go_threads Number of OS threads created.
# TYPE go_threads gauge
go_threads 20
# HELP notebook_create_total Total times of creating notebooks
# TYPE notebook_create_total counter
notebook_create_total{namespace="developer"} 1
# HELP rest_client_requests_total Number of HTTP requests, partitioned by status code, method, and host.
# TYPE rest_client_requests_total counter
rest_client_requests_total{code="200",host="127.0.0.1:61864",method="GET"} 39
rest_client_requests_total{code="200",host="127.0.0.1:61864",method="PATCH"} 1
rest_client_requests_total{code="200",host="127.0.0.1:61864",method="PUT"} 17
rest_client_requests_total{code="201",host="127.0.0.1:61864",method="POST"} 29
rest_client_requests_total{code="404",host="127.0.0.1:61864",method="GET"} 4
rest_client_requests_total{code="404",host="127.0.0.1:61864",method="PUT"} 1
# HELP workqueue_adds_total Total number of adds handled by workqueue
# TYPE workqueue_adds_total counter
workqueue_adds_total{name="notebook"} 10
# HELP workqueue_depth Current depth of workqueue
# TYPE workqueue_depth gauge
workqueue_depth{name="notebook"} 0
# HELP workqueue_longest_running_processor_seconds How many seconds has the longest running processor for workqueue been running.
# TYPE workqueue_longest_running_processor_seconds gauge
workqueue_longest_running_processor_seconds{name="notebook"} 0
# HELP workqueue_queue_duration_seconds How long in seconds an item stays in workqueue before being requested
# TYPE workqueue_queue_duration_seconds histogram
workqueue_queue_duration_seconds_bucket{name="notebook",le="1e-08"} 0
workqueue_queue_duration_seconds_bucket{name="notebook",le="1e-07"} 0
workqueue_queue_duration_seconds_bucket{name="notebook",le="1e-06"} 0
workqueue_queue_duration_seconds_bucket{name="notebook",le="9.999999999999999e-06"} 3
workqueue_queue_duration_seconds_bucket{name="notebook",le="9.999999999999999e-05"} 3
workqueue_queue_duration_seconds_bucket{name="notebook",le="0.001"} 3
workqueue_queue_duration_seconds_bucket{name="notebook",le="0.01"} 8
workqueue_queue_duration_seconds_bucket{name="notebook",le="0.1"} 8
workqueue_queue_duration_seconds_bucket{name="notebook",le="1"} 9
workqueue_queue_duration_seconds_bucket{name="notebook",le="10"} 10
workqueue_queue_duration_seconds_bucket{name="notebook",le="100"} 10
workqueue_queue_duration_seconds_bucket{name="notebook",le="1000"} 10
workqueue_queue_duration_seconds_bucket{name="notebook",le="+Inf"} 10
workqueue_queue_duration_seconds_sum{name="notebook"} 6.152192666
workqueue_queue_duration_seconds_count{name="notebook"} 10
# HELP workqueue_retries_total Total number of retries handled by workqueue
# TYPE workqueue_retries_total counter
workqueue_retries_total{name="notebook"} 0
# HELP workqueue_unfinished_work_seconds How many seconds of work has been done that is in progress and hasn't been observed by work_duration. Large values indicate stuck threads. One can deduce the number of stuck threads by observing the rate at which this increases.
# TYPE workqueue_unfinished_work_seconds gauge
workqueue_unfinished_work_seconds{name="notebook"} 0
# HELP workqueue_work_duration_seconds How long in seconds processing an item from workqueue takes.
# TYPE workqueue_work_duration_seconds histogram
workqueue_work_duration_seconds_bucket{name="notebook",le="1e-08"} 0
workqueue_work_duration_seconds_bucket{name="notebook",le="1e-07"} 0
workqueue_work_duration_seconds_bucket{name="notebook",le="1e-06"} 0
workqueue_work_duration_seconds_bucket{name="notebook",le="9.999999999999999e-06"} 0
workqueue_work_duration_seconds_bucket{name="notebook",le="9.999999999999999e-05"} 0
workqueue_work_duration_seconds_bucket{name="notebook",le="0.001"} 1
workqueue_work_duration_seconds_bucket{name="notebook",le="0.01"} 6
workqueue_work_duration_seconds_bucket{name="notebook",le="0.1"} 9
workqueue_work_duration_seconds_bucket{name="notebook",le="1"} 9
workqueue_work_duration_seconds_bucket{name="notebook",le="10"} 10
workqueue_work_duration_seconds_bucket{name="notebook",le="100"} 10
workqueue_work_duration_seconds_bucket{name="notebook",le="1000"} 10
workqueue_work_duration_seconds_bucket{name="notebook",le="+Inf"} 10
workqueue_work_duration_seconds_sum{name="notebook"} 6.087815251
workqueue_work_duration_seconds_count{name="notebook"} 10