Nexus busted after its initial startup raced with another Nexus populating "system" VpcRouter

[davepacheco]

Here's the CI failure: https://github.com/oxidecomputer/omicron/pull/5962/checks?check_run_id=26826135569

This PR is non-trivial and it's conceivable that my changes introduced this but I don't yet see how. The helios-deploy job failed in the usual way (timing out after 600s trying to log in):

2024-06-28 22:19:52.051692811 UTC: login failed: logging in: error sending request for url (https://recovery.sys.oxide.test/v1/login/recovery/local): error trying to connect: error:0A000419:SSL routines:ssl3_read_bytes:tlsv1 alert access denied:ssl/record/rec_layer_s3.c:1605:SSL alert number 49
Error: logging in

Caused by:
    timed out after 600.598279588s

That TLS error can reflect that there are no certificates, and so a problem with the "external endpoints" task. I went to the Nexus logs to look for errors and found that one Nexus failed some of the first-time-setup steps:

2024-06-28T22:10:18.588Z    ERRO    nexus (DataLoader): gave up trying to populate built-in PopulateBuiltinVpcs
error_message = InternalError { internal_message: "Unknown diesel error creating VpcRouter called \\"system\\": Record not found" }
file = nexus/src/populate.rs:126
2024-06-28T22:10:18.588Z    ERRO    nexus: populate failed
file = nexus/src/app/mod.rs:528
2024-06-28T22:10:18.588Z    ERRO    nexus: saga request channel closed!
file = nexus/src/app/mod.rs:544

One possibility here is that before my PR, we would still have run the background tasks that eventually configure TLS, whereas now we won't. But at best the old code would have been papering over this problem.

[davepacheco]

The Unknown diesel error creating VpcRouter called \\"system\\ error is coming from here: https://github.com/oxidecomputer/omicron/blob/e514bc8262f404f1d28b7b5e3ef39712dccb81f2/nexus/db-queries/src/db/error.rs#L248

and the cause is a NotFound error that's raised when we use something like get_result to execute the query, which we are doing here: https://github.com/oxidecomputer/omicron/blob/e514bc8262f404f1d28b7b5e3ef39712dccb81f2/nexus/db-queries/src/db/datastore/vpc.rs#L1090

The stack is:

• PopulateBuiltinVpcs's implementation calls datastore.load_builtin_vpcs(opctx)
• I haven't confirmed this but I think we're winding up at this call to self.vpc_create_router().
• That invokes the query above using get_result().

It's a little surprising for an INSERT to return NotFound. But we are expecting a row because we're using get_result_async(). And we're expecting that row because we're using INSERT ... RETURNING ..., which returns the newly-inserted row. That we got 0 rows here tells us that we didn't insert it. That can only happen for this query if there was another row with the same id. This is a totally normal and expected condition if some other Nexus already went through the populate step. Now, we already have tests for populators being idempotent, so my guess is that normally if this has already been inserted, then we won't make it this far into load_builtin_vpcs(), and what actually happened here was a race. I'll look for more evidence of that.

[davepacheco]

Yeah, I think we have Nexus instances racing. Here's the point in three different Nexus logs where we started this populator:

• https://buildomat.eng.oxide.computer/wg/0/artefact/01J1GA6EKS3CWWXT1DP2BCKBZA/QOLKB9lvis27b73Ofm8KDtGiG4pYM2v27qyQAaiqHbu87pJp/01J1GA72CXJV2XM8HSEFWP104G/01J1GF4XW30GZCND4VHY0GM1X2/oxide-nexus:default.log.0?format=x-bunyan#L179
• https://buildomat.eng.oxide.computer/wg/0/artefact/01J1GA6EKS3CWWXT1DP2BCKBZA/QOLKB9lvis27b73Ofm8KDtGiG4pYM2v27qyQAaiqHbu87pJp/01J1GA72CXJV2XM8HSEFWP104G/01J1GF5JQPMXY8NZCGWNJB3V4N/oxide-nexus:default.log.0?format=x-bunyan#L173
• https://buildomat.eng.oxide.computer/wg/0/artefact/01J1GA6EKS3CWWXT1DP2BCKBZA/QOLKB9lvis27b73Ofm8KDtGiG4pYM2v27qyQAaiqHbu87pJp/01J1GA72CXJV2XM8HSEFWP104G/01J1GF3748QTXGDA0ZBQYDF1NK/oxide-nexus:default.log.0?format=x-bunyan#L178

The first of these Nexus instances went on to the next populate step, so it must have succeeded. The second and third ones both gave up.

The timeline is:

2024-06-28T22:10:18.480Z Nexus 1: "attempting to create built-in VPCs"
2024-06-28T22:10:18.504Z Nexus 2: "attempting to create built-in VPCs"
2024-06-28T22:10:18.510Z Nexus 3: "attempting to create built-in VPCs"
2024-06-28T22:10:18.584Z Nexus 2 reports the "not found" error
2024-06-28T22:10:18.588Z Nexus 3 reports the "not found" error
2024-06-28T22:10:18.664Z Nexus 1: "attempting to create built-in VPC firewall rules", which implies it had finished creating the built-in VPCs

This is not a smoking gun (I don't think that's possible without more fine-grained logging from the VPC populate steps) but it's consistent with the explanation that these raced with each other.

In this case, prior to #5962, the impact would be:

• Two of the three Nexus instances would not have re-activated background tasks after the populate step, which means many of the background tasks might be broken until their next periodic activation, which further means that basically any other part of Nexus might be broken until that happens (e.g., TLS certificates, inventory collection, etc.)
• One of the three Nexus instances should have been working normally.

I think there are three potential takeaways here:

• After #5962, those two Nexus instances would never start working again because tasks never got started. I'm not sure whether this is a bug or not. "Populate" really needs to work -- if it fails, it's hard to know that anything else can work. But I guess there's probably not harm in starting the background tasks after the populate step regardless of whether the populate step completed or not.
• I think the simplest fix for this specific problem is: instead of using RETURNING, just always fetch the row (which we may or may not have just inserted). We might also be able to do something like INSERT INTO ... ON CONFLICT SET id = id RETURNING * so that the row technically gets updated by the INSERT (even though the data doesn't actually change). I think we might do this in some other places.
• There's another problem which is that we didn't catch this during automated testing. It's really essential that populators are idempotent and we have tests that run the populators multiple times to make sure that they are. I think that didn't catch this because this populator does multiple things and the first one is idempotent so the test passes. If we break each of the steps in this populator into separate populators, then the framework could catch issues like this.

[davepacheco]

I found another example where we do the ON CONFLICT SET id = id for this exact reason (I think! There's not much explanation in the comment.): https://github.com/oxidecomputer/omicron/blob/653964be121425c55955a6e4f58d9e1b8cda83da/nexus/db-queries/src/db/datastore/rack.rs#L236-L237