thread 'integration_tests::instances::test_instance_metrics' panicked at 'attempt to subtract with overflow'

[iliana]

https://github.com/oxidecomputer/omicron/runs/10768352787 / https://buildomat.eng.oxide.computer/wg/0/details/01GQ6DS2KJ0QDM6YWDNRZDTCHZ/B44Zl5JIuOAhkn5GInFdH46LbPhq8Dq00FztPZBK0cQJCm5s/01GQ6DSB1H70J2FKRWK36STEQ6#S11679:

---- integration_tests::instances::test_instance_metrics stdout ----
--
log file: /var/tmp/omicron_tmp/test_all-df03734e17da7df2-test_instance_metrics.51359.58.log
note: configured to log to "/var/tmp/omicron_tmp/test_all-df03734e17da7df2-test_instance_metrics.51359.58.log"
thread 'integration_tests::instances::test_instance_metrics' panicked at 'attempt to subtract with overflow', nexus/tests/integration_tests/metrics.rs:33:36
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
WARN: dropped CockroachInstance without cleaning it up first (there may still be a child process running and a temporary directory leaked)
WARN: temporary directory leaked: /var/tmp/omicron_tmp/.tmpm1YIU2
WARN: dropped ClickHouseInstance without cleaning it up first (there may still be a child process running and a temporary directory leaked)

omicron/nexus/tests/integration_tests/metrics.rs

Lines 26 to 39 in d6dc72f

	pub async fn query_for_latest_metric(
	client: &ClientTestContext,
	path: &str,
	) -> i64 {
	let measurements: ResultsPage<Measurement> =
	objects_list_page_authz(client, path).await;
	let item = &measurements.items[measurements.items.len() - 1];
	let datum = match item.datum() {
	Datum::I64(c) => c,
	_ => panic!("Unexpected datum type {:?}", item.datum()),
	};
	return *datum;
	}

This panics if measurements.items.len() == 0.

[smklein]

Almost definitely a result of #1782 ; I can look

[smklein]

Here's what that test is supposed to be doing...

We're supposed to be querying the "project" and "org" we created to see how much space they report to be using.

We first do that by querying the DB for those values, which indicates they've been inserted:

omicron/nexus/tests/integration_tests/instances.rs

Lines 545 to 553 in d6dc72f

	// Query the view of these metrics stored within CRDB
	let opctx =
	OpContext::for_tests(cptestctx.logctx.log.new(o!()), datastore.clone());
	let virtual_provisioning_collection = datastore
	.virtual_provisioning_collection_get(&opctx, project_id)
	.await
	.unwrap();
	assert_eq!(virtual_provisioning_collection.cpus_provisioned, 0);
	assert_eq!(virtual_provisioning_collection.ram_provisioned.to_bytes(), 0);

We also want to query the Nexus API, to test that the metrics are being offloaded to Clickhouse and Oximeter properly.

So we check the utilization URL:

omicron/nexus/tests/integration_tests/instances.rs

Lines 555 to 562 in d6dc72f

	// Query the view of these metrics stored within Clickhouse
	let metric_url = |metric_type: &str, id: Uuid| {
	format!(
	"/system/metrics/{metric_type}?start_time={:?}&end_time={:?}&id={id}",
	Utc::now() - chrono::Duration::seconds(30),
	Utc::now() + chrono::Duration::seconds(30),
	)
	};

HOWEVER, these metrics might not live in Clickhouse after inserting these values into Nexus. This would mean a call to the utilization URL fails, since no data exists. Nexus collects metrics by storing them locally, then offloading them to Clickhouse through Oximeter. In Oximeter's language, Nexus is a "producer" of metrics, that is periodically polled.

... I tried to avoid this by calling

omicron/nexus/tests/integration_tests/instances.rs

Line 563 in d6dc72f

oximeter.force_collect().await;

Which should be forcing Oximeter to collect the metrics from Nexus and dump 'em to Clickhouse:

omicron/oximeter/collector/src/lib.rs

Lines 550 to 556 in e69a5a3

	/// Forces Oximeter to perform a collection immediately.
	///
	/// This is particularly useful during tests, which would prefer to
	/// avoid waiting until a collection interval completes.
	pub async fn force_collect(&self) {
	self.server.app_private().force_collection().await
	}

I wasn't totally sure if there was some delay along the Oximeter --> Clickhouse pathway, but I can look at that now.

It seems collection_task, which operates on the CollectionMessage::Collect message, issues perform_collection, which writes the result to an mpsc::Sender. Looks like this "sender" is cloned from the OximeterAgent::result_sender, so it looks like the OximeterAgent::result_receiver (the receiving end of this channel) gets sent to a function called results_sink... which looks like it's added to a batch that only is emitted when it crosses certain size threshold or a timeout is crossed. Hrm. This might be causing a longer delay than expected.

I suppose it's possible that this delays the transfer of metrics from Nexus -> Oximeter -> Clickhouse, which would result in this error where "no metrics are visible in Clickhouse". I'll add a PR to fix that behavior.

EDIT: #2188 is that PR