BUILDS_INPROGRESS metric not working as expected

[rgaiacs]

As reported downstream on jupyterhub/mybinder.org-deploy#3594, the binderhub_inprogress_builds / BUILDS_INPROGRESS metric is not working as expected.

Observed	Expected

BUILDS_INPROGRESS is defined in

binderhub/binderhub/builder.py

Line 55 in 5532677

BUILDS_INPROGRESS = Gauge("binderhub_inprogress_builds", "Builds currently in progress")

The Prometheus client_python Gauge() can go up and down but from the observed Grafana visualisation, it is only going up. track_inprogress() is used in

binderhub/binderhub/builder.py

Lines 507 to 597 in 5532677

	with BUILDS_INPROGRESS.track_inprogress():
	done = False
	failed = False
	def _check_result(future):
	nonlocal done
	nonlocal failed
	try:
	r = future.result()
	app_log.debug("task completed: %s", r)
	except Exception:
	app_log.error("task failed", exc_info=True)
	done = True
	failed = True
	# TODO: Propagate error to front-end
	build_starttime = time.perf_counter()
	pool = self.settings["build_pool"]
	# Start building
	submit_future = pool.submit(build.submit)
	submit_future.add_done_callback(_check_result)
	IOLoop.current().add_callback(lambda: submit_future)
	log_future = None
	# initial waiting event
	await self.emit(
	{
	"phase": "waiting",
	"message": "Waiting for build to start...\n",
	}
	)
	while not done:
	progress = await q.get()
	# FIXME: If pod goes into an unrecoverable stage, such as ImagePullBackoff or
	# whatever, we should fail properly.
	if progress.kind == ProgressEvent.Kind.BUILD_STATUS_CHANGE:
	phase = progress.payload.value
	if progress.payload == ProgressEvent.BuildStatus.PENDING:
	# nothing to do, just waiting
	continue
	elif progress.payload == ProgressEvent.BuildStatus.BUILT:
	if build_only:
	message = "Done! Image built\n"
	phase = "ready"
	else:
	message = "Built image, launching...\n"
	event = {
	"phase": phase,
	"message": message,
	"imageName": image_name,
	}
	BUILD_TIME.labels(status="success").observe(
	time.perf_counter() - build_starttime
	)
	BUILD_COUNT.labels(
	status="success", **self.repo_metric_labels
	).inc()
	done = True
	elif progress.payload == ProgressEvent.BuildStatus.RUNNING:
	# start capturing build logs once the pod is running
	if log_future is None:
	log_future = pool.submit(build.stream_logs)
	log_future.add_done_callback(_check_result)
	continue
	elif progress.payload == ProgressEvent.BuildStatus.BUILT:
	# Do nothing, is ok!
	continue
	elif progress.payload == ProgressEvent.BuildStatus.FAILED:
	event = {"phase": phase}
	elif progress.payload == ProgressEvent.BuildStatus.UNKNOWN:
	event = {"phase": phase}
	else:
	raise ValueError(
	f"Found unknown phase {phase} in ProgressEvent"
	)
	elif progress.kind == ProgressEvent.Kind.LOG_MESSAGE:
	# The logs are coming out of repo2docker, so we expect
	# them to be JSON structured anyway
	event = progress.payload
	payload = json.loads(event)
	if payload.get("phase") in ("failure", "failed"):
	failed = True
	BUILD_TIME.labels(status="failure").observe(
	time.perf_counter() - build_starttime
	)
	BUILD_COUNT.labels(
	status="failure", **self.repo_metric_labels
	).inc()
	await self.emit(event)

as described in the Prometheus client_python documentation.

My search pointed me that the cause of this problem could be

• that the process might be terminated before the with block completes
• the async / await instruction

@yuvipanda and @manics what does your experience says?

Should we replace the BUILDS_INPROGRESS with a downstream calculation of BUILDS_STARTED - BUILDS_COMPLETED - BUILDS_FAILED?

[manics]

I think we should try and debug why BUILDS_INPROGRESS.track_inprogress isn't decremented. Is it never decremented, or is it intermittent?

If necessary I think we could subclass Gauge
https://github.com/prometheus/client_python/blob/e1cdc203b1cf5f15c7b9a64d79fccc7907a62ca3/prometheus_client/metrics.py#L470-L478
and InprogressTracker
https://github.com/prometheus/client_python/blob/e1cdc203b1cf5f15c7b9a64d79fccc7907a62ca3/prometheus_client/context_managers.py#L36-L51
to add some logging

[minrk]

It is intermittent. Builds do get decremented, but apparently not always. I wonder if it has to do with cancelled coroutines.

[minrk]

After some tests, it appears that cancelled coroutines do indeed properly exit the context manager. That makes me think that it's actually the get coroutine that's actually never exiting the build block. Which would mean it's not the metric that's wrong, it's the build-watching code that it wraps.

[minrk]

I have an idea here: when an error is raised in the builder, it is caught by _check_result and logged as task failed: .... This also sets done=True, failure=True. This will exit the while not done loop if progress = await q.get() ever receives an event and proceeds to a next iteration.

However, if the error (whatever it is) prevents an event from getting put on the queue, it will never wake, and the loop will be stuck forever. The symptom will be that for some subset of task failed log events (possibly most), the number of BUILD_INPROGRESS will increment and not decrement.

We are currently seeing these errors in the logs:

[E 260114 22:06:27 builder:518] task failed
    Traceback (most recent call last):
      File "/usr/local/lib/python3.13/site-packages/urllib3/response.py", line 779, in _error_catcher
        yield
      File "/usr/local/lib/python3.13/site-packages/urllib3/response.py", line 1248, in read_chunked
        self._update_chunk_length()
        ~~~~~~~~~~~~~~~~~~~~~~~~~^^
      File "/usr/local/lib/python3.13/site-packages/urllib3/response.py", line 1167, in _update_chunk_length
        line = self._fp.fp.readline()  # type: ignore[union-attr]
      File "/usr/local/lib/python3.13/socket.py", line 719, in readinto
        return self._sock.recv_into(b)
               ~~~~~~~~~~~~~~~~~~~~^^^
      File "/usr/local/lib/python3.13/ssl.py", line 1304, in recv_into
        return self.read(nbytes, buffer)
               ~~~~~~~~~^^^^^^^^^^^^^^^^
      File "/usr/local/lib/python3.13/ssl.py", line 1138, in read
        return self._sslobj.read(len, buffer)
               ~~~~~~~~~~~~~~~~~^^^^^^^^^^^^^
    TimeoutError: The read operation timed out
binder-7c49cb99c-tdwvm binder
    The above exception was the direct cause of the following exception:
binder-7c49cb99c-tdwvm binder
    Traceback (most recent call last):
      File "/usr/local/lib/python3.13/site-packages/binderhub/builder.py", line 515, in _check_result
        r = future.result()
      File "/usr/local/lib/python3.13/concurrent/futures/_base.py", line 449, in result
        return self.__get_result()
               ~~~~~~~~~~~~~~~~~^^
      File "/usr/local/lib/python3.13/concurrent/futures/_base.py", line 401, in __get_result
        raise self._exception
      File "/usr/local/lib/python3.13/concurrent/futures/thread.py", line 59, in run
        result = self.fn(*self.args, **self.kwargs)
      File "/usr/local/lib/python3.13/site-packages/binderhub/build.py", line 573, in submit
        for f in w.stream(
                 ~~~~~~~~^
            self.api.list_namespaced_pod,
            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
        ...<3 lines>...
            _request_timeout=KUBE_REQUEST_TIMEOUT,
            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
        ):
        ^
      File "/usr/local/lib/python3.13/site-packages/kubernetes/watch/watch.py", line 134, in stream
        for line in iter_resp_lines(resp):
                    ~~~~~~~~~~~~~~~^^^^^^
      File "/usr/local/lib/python3.13/site-packages/kubernetes/watch/watch.py", line 47, in iter_resp_lines
        for seg in resp.read_chunked(decode_content=False):
                   ~~~~~~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^
      File "/usr/local/lib/python3.13/site-packages/urllib3/response.py", line 1231, in read_chunked
        with self._error_catcher():
             ~~~~~~~~~~~~~~~~~~~^^
      File "/usr/local/lib/python3.13/contextlib.py", line 162, in __exit__
        self.gen.throw(value)
        ~~~~~~~~~~~~~~^^^^^^^
      File "/usr/local/lib/python3.13/site-packages/urllib3/response.py", line 784, in _error_catcher
        raise ReadTimeoutError(self._pool, None, "Read timed out.") from e  # type: ignore[arg-type]
        ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
    urllib3.exceptions.ReadTimeoutError: HTTPSConnectionPool(host='10.43.0.1', port=443): Read timed out.

So I think there are two bugs to fix:

1. (in builder) when an error in the build is caught, make sure to wake the progress q, so that an error in build.submit doesn't leave us waiting forever in BUILDS_INPROGRESS
2. (in build) log and retry the watch on read timeouts, which would prevent the specific error causing this that I can see right now

[minrk]

Yes, I can reproduce this with the FakeBuild if I inject an error into submit, the inprogress builds keep counting up and never counting down. #2054 fixes it in local testing with some injected errors, though I can't exactly see how to easily force a reproducible failure to test this in CI.

[minrk]

While I was able to confirm that #2054 fixed a situation where build could get stuck, mybinder.org is still observing constant ticking up build counts, suggesting there is still an issue here.

[minrk]

Connecting this to #1128 which identifies that we don't actually have any prometheus metrics for builds themselves.

There's still a bug here in that our build_inprogress hangs relatively often and never exits, but it has never actually represented builds in progress

[minrk]

It would probably be useful to connect metrics that actually measure running builds that are not at all related to HTTP requests:

1. add a watcher for pods with the build labels
2. measure build time relative to pod start, not watch start

we are currently using kube_pod_status_phase{pod=~"build-.*", pod!~"build-cache-prune-.*"} and time() - kube_pod_created{pod=~"^build-.*", pod!~"build-cache-prune-.*"}), but these are imprecise proxies, especially the one for build time, which only measures current pod age, and is hard to reconstruct a distribution of finished durations