[NRID] DSS 5xx Errors during Concurrent Requests USS Qualifier Test Scenario

[wing-utm-sharing-airspace]

Describe the bug
We see timeouts that appear to be coming from the DSS intermittently when running the USS Qualifier Concurrent Requests scenario.

To Reproduce
We're testing on a DSS pool with 7 instances each with 3 crdb nodes
DSS is running v0.21.1
CRDB v24.1.3

Run the USS Qualifier Concurrent Requests scenario. It doesn't fail every time, but we've seen it in ~3/10 runs.

Expected behavior
Expect the DSS to pass USS Qualifier scenarios.

Screenshots
SQL statement latency seems to be relatively low:

KV transactions latency spikes during this test scenario:

Slow transaction of note:

Example USS Qualifier failure:
s19 - ASTM NetRID DSS_ Concurrent Requests Crash.html

[UPDATE: attach scenario correlating with CRBD screenshots]s19 - ASTM NetRID DSS_ Concurrent Requests 12:3 12UTC.html

[BenjaminPelletier]

I think there are at least two separate things to address based on this information:

1. The scenario shouldn't crash. Any exception in a scenario is a bug -- in this case, the TimeoutError should have been caught and reported rather than crashing the scenario. This seems like an easy fix.

2. There shouldn't be a timeout. This seems like the substantive issue we need to diagnose.

[BenjaminPelletier]

(with my Wing-eng hat on rather than my InterUSS hat)

Looking at the logs for Wing's DSS instance, I see the GET -> 404s listed in the logs between 15:34:13.442 and 15:34:20.414 (these are listed in s19 above) and the durations of all of these queries seems to be 2-3ms, as reported in these logs (presumably network traversals account for the 60-80ms logged by uss_qualifier). Immediately following, I see many PUT ISA calls (as expected). The first one completes in 49ms, but then their durations grow quickly (though not monotonically). The 14th call is the first one over a second in duration. The duration increase is obvious, but not consistent -- for instance, one PUT ISA operation completing at 15:34:29.190 took 2.37s while the next operation completing at 15:34:29.303 took 144ms. I do not see any errors logged, and I also do not see any log entries with a duration of longer than 9.9 seconds.

@barroco @the-glu This suggests to me that we do not log operations that had their context canceled due to a timeout. This is exactly the time when we want the most thorough logging. Would it be feasible to thoroughly log as many details as we can determine about any operation that is canceled due to a timeout? Specifically, it seems like an ideal behavior would be for any timed-out operation to enqueue a background operation that would perform a mini investigation, collecting as much information as we know to collect to troubleshoot why that specific operation took so long and storing it where it could be easily retrieved later.

[wing-utm-sharing-airspace]

For some additional data points on smaller DSS pools:

I have also seen timeouts during the concurrent requests scenario with another DSS pool that has 6 instances (again each with 3 crdb nodes). This behavior was observed in 2/6 automated test runs. Example report:

s19 - ASTM NetRID DSS_ Concurrent Requests Timeout No Crash.html

I have also seen this flavor of failure against a much smaller DSS pool comprised of only 3 nodes but don't have great data yet on how frequently this is happening:

s9 - ASTM NetRID DSS_ Concurrent Requests 3 node pool.html

[wing-utm-sharing-airspace]

Adding CRDB screenshots that correlate with the original test run posted in the description:
s19 - ASTM NetRID DSS_ Concurrent Requests Crash.html

[BenjaminPelletier]

I've been trying to reproduce this issue with our ability to deploy a local DSS pool with realistic cloud network behavior (latency and packet loss). In particular, I was looking to test the hypothesis that a large DSS pool is a determining factor in causing this problem (hypothesized before comment noting occurrence on 3-node pool). I deployed 13 DSS instances, each with 3 nodes, locally with:

NUM_USS=13
NUM_NODES=3
INTRA_USS_NETEM_CONF="delay 600us 40us 25% distribution normal loss 0.0005%"
INTER_USS_NETEM_CONF="delay 36ms 40ms 50% distribution paretonormal loss 0.25% 15%"

...and then I ran the netrid_concurrency test configuration. This configuration runs the concurrency test scenario on each local DSS node, so a total of 39 test runs, and I didn't see any failures/timeouts. The latency for creating an ISA is high, but consistently well below the timeout threshold:

So, it seems like pool size alone is not sufficient to cause this problem with typical reported latencies (if I interpret correctly). For comparison, here is a 3 USS x 3 nodes equivalent test (same netem conf):

[BenjaminPelletier]

To make sure we're all looking at the same things, I want to clearly label the occurrences reported here and their characteristics; please let me know if I summarized anything incorrectly.

• Occurrence A
  • 7x3 pool, DSS v0.21.1, CRDB v24.1.3
  • Graphs from first comment
    • 99th percentile SQL statements service latency was not affected
    • 99th percentile KV transaction duration spiked to 10s
  • s19 - ASTM NetRID DSS_ Concurrent Requests 12:3 12UTC.html
    • First query initiated 2026-06-03T12:12:31.948092Z
    • No crash/exception, failed to create ISA 00000176-6d92-409c-8fd9-a36decc60000 in e201 at 12:12:49.8, query appears to have received plaintext (presumably gateway error) and 504 after 10+ seconds
  • Latency visualization according to DSS logs pulled from GCP Logs Explorer: cloud_latency.zip
  • DSS errors in GCP Logs Explorer contain 6 pairs of "context canceled" errors like:

    [
      {
        "stacktrace": "Could not insert ISA\n --- at /app/pkg/rid/server/v2/isa_handler.go:106 (Server.CreateIdentificationServiceArea) ---\nCaused by: Error updating notification indices\n --- at /app/pkg/rid/application/isa.go:122 (app.InsertISA.func1) ---\nCaused by: Error in rows query result\n --- at /app/pkg/rid/store/datastore/subscriptions.go:61 (repo.process) ---\nCaused by: context canceled",
        "level": "error",
        "caller": "errors/errors.go:86",
        "msg": "Uncoded error during unary server call",
        "error": "context canceled",
        "ts": "2026-06-03T12:12:49.583Z",
        "error_id": "E:b92a28d0-9f2c-401d-aad9-6c402fae439a"
      },
      {
        "error_id": "E:5ca5553d-bc21-46fe-ade8-cf5c76a4d728",
        "error": "context canceled",
        "msg": "Uncoded error during unary server call",
        "ts": "2026-06-03T12:12:49.583Z",
        "caller": "errors/errors.go:86",
        "level": "error",
        "stacktrace": "Got an unexpected error\n --- at /app/pkg/rid/server/v2/isa_handler.go:115 (Server.CreateIdentificationServiceArea) ---\nCaused by: Could not insert ISA\n --- at /app/pkg/rid/server/v2/isa_handler.go:106 (Server.CreateIdentificationServiceArea) ---\nCaused by: Error updating notification indices\n --- at /app/pkg/rid/application/isa.go:122 (app.InsertISA.func1) ---\nCaused by: Error in rows query result\n --- at /app/pkg/rid/store/datastore/subscriptions.go:61 (repo.process) ---\nCaused by: context canceled"
      }
    ]

• Occurrence B
  • 7x3 pool, DSS v0.21.1, CRDB v24.1.3
  • Graphs in fifth comment
    • 99th percentile SQL statements service latency was not affected
    • Transaction restarts spiked
    • 99th percentile transaction latency spiked
  • s19 - ASTM NetRID DSS_ Concurrent Requests Crash.html
    • First query initiated 2026-06-04T15:34:13.399974Z
    • Crash from TimeoutError at 2026-06-04T15:34:30.822428Z, presumably from create ISA call, query not logged
  • Additional observations in third comment
  • Latency visualization according to DSS logs pulled from GCP Logs Explorer: cloud_latency.zip
  • No errors in GCP logs from around the time of TimeoutError
• Occurrence C
  • 6x3 pool
  • s19 - ASTM NetRID DSS_ Concurrent Requests Timeout No Crash.html
    • First query initiated 2026-06-05T23:15:46.361071Z
    • ISA 00000176-6d92-409c-8fd9-a36decc60032 deletion failure at e2507 reported 23:16:39 from query at e2439, query appears to have received plaintext (presumably gateway error) and 504 after 10+ seconds
  • DSS errors pulled from GCP Logs Explorer:

      {
        "stacktrace": "Could not delete ISA\n --- at /app/pkg/rid/server/v2/isa_handler.go:234 (Server.DeleteIdentificationServiceArea) ---\nCaused by: Error updating notification indices\n --- at /app/pkg/rid/application/isa.go:88 (app.DeleteISA.func1) ---\nCaused by: Error in rows query result\n --- at /app/pkg/rid/store/datastore/subscriptions.go:61 (repo.process) ---\nCaused by: context canceled",
        "caller": "errors/errors.go:86",
        "ts": "2026-06-05T23:16:39.150Z",
        "msg": "Uncoded error during unary server call",
        "error_id": "E:4b605ad8-b5bf-4804-b9ca-6e0fd54a890e",
        "error": "context canceled",
        "level": "error"
      },
      {
        "error_id": "E:7d61c116-0cec-41c8-9b57-f7549d143de7",
        "error": "context canceled",
        "level": "error",
        "stacktrace": "Got an unexpected error\n --- at /app/pkg/rid/server/v2/isa_handler.go:245 (Server.DeleteIdentificationServiceArea) ---\nCaused by: Could not delete ISA\n --- at /app/pkg/rid/server/v2/isa_handler.go:234 (Server.DeleteIdentificationServiceArea) ---\nCaused by: Error updating notification indices\n --- at /app/pkg/rid/application/isa.go:88 (app.DeleteISA.func1) ---\nCaused by: Error in rows query result\n --- at /app/pkg/rid/store/datastore/subscriptions.go:61 (repo.process) ---\nCaused by: context canceled",
        "ts": "2026-06-05T23:16:39.150Z",
        "caller": "errors/errors.go:86",
        "msg": "Uncoded error during unary server call"
      }

• Occurrence D
  • 1x3 pool, presumably old DSS version since this test was in August 2025
  • s9 - ASTM NetRID DSS_ Concurrent Requests 3 node pool.html
    • First query initiated 2025-08-11T23:10:14.717974Z
    • Crash from TimeoutError at 2025-08-11T23:10:33.094316Z, presumably from create ISA call, query not logged
  • GCP logs are no longer available for this occurrence

[the-glu]

Trying to debug the issue locally, I noticed with tracing that I do have high latencies dues to the limit of open connections to the pool (4), with the transactions mostly waiting to get a connection to the pool

I don't know what the value of the settings in different scenarios, but increasing this may improve duration of individual requests. Notice however it's not going to make global throughput faster.

I was also not able to reproduce the issue with KV spikes and transactions restart.

On the KV spike chart, the color of the spiking node like seems to be the same, is there an issue with a specific crdb node that has limited resources, like limited CPU burst in the cloud?

I also noticed that CRDB plan/indexes seems very wrong (e.g. id / cells are rarely used), but forcing to use correct ones didn't improve anything locally.

Finally, I tried a direct locust scenario in locust, like the one made for SCD, I was able to sustain 120 inserts / second for a few minutes without any issue (something that was not the case in SCD).

[wing-utm-sharing-airspace]

On the KV spike chart, the color of the spiking node like seems to be the same, is there an issue with a specific crdb node that has limited resources, like limited CPU burst in the cloud?

I don't believe so. For the test run in #1509 (comment), The two nodes with the highest transaction latency appeared to be sitting under 25% CPU usage.

Nodes with high KV latency:

CPU Usage: