Support bundle stuck in collecting status (should use multi-part upload to sled agent)

[askfongjojo]

I made a new bundle on rack3 (the first time ever in this environment) and its state didn't not progress beyond collecting after many hours.

oxide --profile colo bundle list
[
  {
    "id": "c6b507df-cb67-47c4-8887-ba9fc0fc0034",
    "reason_for_creation": "Created by external API",
    "state": "collecting",
    "time_created": "2025-07-09T01:01:12.246530Z"
  }
]

I looked up the bundle's dataset info from the database

root@[fd00:1122:3344:116::3]:32221/omicron> select * from support_bundle;
                   id                  |         time_created         |   reason_for_creation   | reason_for_failure |   state    |               zpool_id               |              dataset_id              |            assigned_nexus
---------------------------------------+------------------------------+-------------------------+--------------------+------------+--------------------------------------+--------------------------------------+---------------------------------------
  c6b507df-cb67-47c4-8887-ba9fc0fc0034 | 2025-07-09 01:01:12.24653+00 | Created by external API | NULL               | collecting | de682b18-afaf-4d53-b62e-934f6bd4a1f8 | 003d27e0-57e4-4d55-963e-af47e4e526f1 | 95ebe94d-0e68-421d-9260-c30bd7fe4bd6
(1 row)

The dataset that was supposed to receive the bundle remained empty:

BRM42220015 # ls -l /pool/ext/de682b18-afaf-4d53-b62e-934f6bd4a1f8/crypt/debug/c6b507df-cb67-47c4-8887-ba9fc0fc0034/
total 0

The assigned nexus log showed that the collector background task was doing the work:

angela@castle /staff/angela $ grep c6b507df oxide-nexus.log.1752023701 | head -30 | looker
01:01:18.330Z INFO 95ebe94d-0e68-421d-9260-c30bd7fe4bd6 (ServerContext): SupportBundleCollector: Found bundle to collect
    background_task = support_bundle_collector
    bundle = c6b507df-cb67-47c4-8887-ba9fc0fc0034
    bundles_in_queue = 1
    file = nexus/src/app/background/tasks/support_bundle_collector.rs:364
01:01:18.330Z INFO 95ebe94d-0e68-421d-9260-c30bd7fe4bd6 (ServerContext): Collecting bundle as local file
    background_task = support_bundle_collector
    bundle = c6b507df-cb67-47c4-8887-ba9fc0fc0034
    file = nexus/src/app/background/tasks/support_bundle_collector.rs:562
01:01:18.367Z DEBG 95ebe94d-0e68-421d-9260-c30bd7fe4bd6 (ServerContext): client request
    background_task = support_bundle_collector
    body = None
    bundle = c6b507df-cb67-47c4-8887-ba9fc0fc0034
    method = GET
    uri = http://[fd00:1122:3344:11f::2]:12225/local/all-sp-ids
01:01:18.367Z DEBG 95ebe94d-0e68-421d-9260-c30bd7fe4bd6 (ServerContext): client response
    background_task = support_bundle_collector
    bundle = c6b507df-cb67-47c4-8887-ba9fc0fc0034
    result = Ok(Response { url: "http://[fd00:1122:3344:11f::2]:12225/local/all-sp-ids", status: 200, headers: {"content-type": "application/json", "x-request-id": "46a2fcee-08ee-49a9-8f72-4329dd215192", "content-length": "929", "date": "Wed, 09 Jul 2025 01:01:17 GMT"} })
01:01:18.367Z DEBG 95ebe94d-0e68-421d-9260-c30bd7fe4bd6 (ServerContext): client request
    background_task = support_bundle_collector
    body = None
    bundle = c6b507df-cb67-47c4-8887-ba9fc0fc0034
    method = GET
    uri = http://[fd00:1122:3344:11f::2]:12225/sp/sled/7/task-dump
01:01:18.367Z DEBG 95ebe94d-0e68-421d-9260-c30bd7fe4bd6 (ServerContext): client request
    background_task = support_bundle_collector
    body = None
    bundle = c6b507df-cb67-47c4-8887-ba9fc0fc0034
    method = GET
    uri = http://[fd00:1122:3344:11f::2]:12225/sp/sled/24/task-dump
01:01:18.367Z DEBG 95ebe94d-0e68-421d-9260-c30bd7fe4bd6 (ServerContext): client request
    background_task = support_bundle_collector
    body = None
    bundle = c6b507df-cb67-47c4-8887-ba9fc0fc0034
    method = GET
    uri = http://[fd00:1122:3344:11f::2]:12225/sp/switch/0/task-dump
01:01:18.367Z DEBG 95ebe94d-0e68-421d-9260-c30bd7fe4bd6 (ServerContext): client request
    background_task = support_bundle_collector
    body = None
    bundle = c6b507df-cb67-47c4-8887-ba9fc0fc0034
    method = GET
    uri = http://[fd00:1122:3344:11f::2]:12225/sp/sled/28/task-dump
01:01:18.367Z DEBG 95ebe94d-0e68-421d-9260-c30bd7fe4bd6 (ServerContext): client request
    background_task = support_bundle_collector
    body = None
    bundle = c6b507df-cb67-47c4-8887-ba9fc0fc0034
    method = GET
    uri = http://[fd00:1122:3344:11f::2]:12225/sp/sled/20/task-dump
01:01:18.367Z DEBG 95ebe94d-0e68-421d-9260-c30bd7fe4bd6 (ServerContext): client request
    background_task = support_bundle_collector
    body = None
    bundle = c6b507df-cb67-47c4-8887-ba9fc0fc0034
    method = GET
    uri = http://[fd00:1122:3344:11f::2]:12225/sp/switch/1/task-dump
01:01:18.367Z DEBG 95ebe94d-0e68-421d-9260-c30bd7fe4bd6 (ServerContext): client request
    background_task = support_bundle_collector
    body = None
    bundle = c6b507df-cb67-47c4-8887-ba9fc0fc0034
    method = GET
    uri = http://[fd00:1122:3344:11f::2]:12225/sp/sled/29/task-dump
01:01:18.367Z DEBG 95ebe94d-0e68-421d-9260-c30bd7fe4bd6 (ServerContext): client request
    background_task = support_bundle_collector
    body = None
    bundle = c6b507df-cb67-47c4-8887-ba9fc0fc0034
    method = GET
    uri = http://[fd00:1122:3344:11f::2]:12225/sp/sled/22/task-dump
01:01:18.367Z DEBG 95ebe94d-0e68-421d-9260-c30bd7fe4bd6 (ServerContext): client request
    background_task = support_bundle_collector
    body = None
    bundle = c6b507df-cb67-47c4-8887-ba9fc0fc0034
    method = GET
    uri = http://[fd00:1122:3344:11f::2]:12225/sp/sled/0/task-dump
01:01:18.367Z DEBG 95ebe94d-0e68-421d-9260-c30bd7fe4bd6 (ServerContext): client request
    background_task = support_bundle_collector
    body = None
    bundle = c6b507df-cb67-47c4-8887-ba9fc0fc0034
    method = GET
    uri = http://[fd00:1122:3344:11f::2]:12225/sp/sled/5/task-dump
01:01:18.367Z DEBG 95ebe94d-0e68-421d-9260-c30bd7fe4bd6 (ServerContext): client request
    background_task = support_bundle_collector
    body = None
    bundle = c6b507df-cb67-47c4-8887-ba9fc0fc0034
    method = GET
    uri = http://[fd00:1122:3344:11f::2]:12225/sp/sled/4/task-dump
01:01:18.367Z DEBG 95ebe94d-0e68-421d-9260-c30bd7fe4bd6 (ServerContext): client request
    background_task = support_bundle_collector
    body = None
    bundle = c6b507df-cb67-47c4-8887-ba9fc0fc0034
    method = GET
    uri = http://[fd00:1122:3344:11f::2]:12225/sp/sled/6/task-dump
01:01:18.367Z DEBG 95ebe94d-0e68-421d-9260-c30bd7fe4bd6 (ServerContext): client request
    background_task = support_bundle_collector
    body = None
    bundle = c6b507df-cb67-47c4-8887-ba9fc0fc0034
    method = GET
    uri = http://[fd00:1122:3344:11f::2]:12225/sp/sled/9/task-dump
01:01:18.367Z DEBG 95ebe94d-0e68-421d-9260-c30bd7fe4bd6 (ServerContext): client request
    background_task = support_bundle_collector
    body = None
    bundle = c6b507df-cb67-47c4-8887-ba9fc0fc0034
    method = GET
    uri = http://[fd00:1122:3344:11f::2]:12225/sp/power/0/task-dump
01:01:18.368Z DEBG 95ebe94d-0e68-421d-9260-c30bd7fe4bd6 (ServerContext): client request
    background_task = support_bundle_collector
    body = None
    bundle = c6b507df-cb67-47c4-8887-ba9fc0fc0034
    method = GET
    uri = http://[fd00:1122:3344:11f::2]:12225/sp/sled/31/task-dump
01:01:18.368Z DEBG 95ebe94d-0e68-421d-9260-c30bd7fe4bd6 (ServerContext): client request
    background_task = support_bundle_collector
    body = None
    bundle = c6b507df-cb67-47c4-8887-ba9fc0fc0034
    method = GET
    uri = http://[fd00:1122:3344:11f::2]:12225/sp/sled/13/task-dump
01:01:18.373Z DEBG 95ebe94d-0e68-421d-9260-c30bd7fe4bd6 (ServerContext): client response
    background_task = support_bundle_collector
    bundle = c6b507df-cb67-47c4-8887-ba9fc0fc0034
    result = Ok(Response { url: "http://[fd00:1122:3344:11f::2]:12225/sp/sled/7/task-dump", status: 200, headers: {"content-type": "application/json", "x-request-id": "bf0a7286-96f8-41aa-9ee7-3dc58ee4f194", "content-length": "1", "date": "Wed, 09 Jul 2025 01:01:18 GMT"} })
01:01:18.373Z DEBG 95ebe94d-0e68-421d-9260-c30bd7fe4bd6 (ServerContext): client response
    background_task = support_bundle_collector
    bundle = c6b507df-cb67-47c4-8887-ba9fc0fc0034
    result = Ok(Response { url: "http://[fd00:1122:3344:11f::2]:12225/sp/power/0/task-dump", status: 200, headers: {"content-type": "application/json", "x-request-id": "b8704e84-5aeb-43e8-8772-63ecfec50588", "content-length": "1", "date": "Wed, 09 Jul 2025 01:01:18 GMT"} })
01:01:18.373Z DEBG 95ebe94d-0e68-421d-9260-c30bd7fe4bd6 (ServerContext): client request
    background_task = support_bundle_collector
    body = None
    bundle = c6b507df-cb67-47c4-8887-ba9fc0fc0034
    method = GET
    uri = http://[fd00:1122:3344:11f::2]:12225/sp/sled/3/task-dump
01:01:18.373Z DEBG 95ebe94d-0e68-421d-9260-c30bd7fe4bd6 (ServerContext): client request
    background_task = support_bundle_collector
    body = None
    bundle = c6b507df-cb67-47c4-8887-ba9fc0fc0034
    method = GET
    uri = http://[fd00:1122:3344:11f::2]:12225/sp/sled/2/task-dump
01:01:18.373Z DEBG 95ebe94d-0e68-421d-9260-c30bd7fe4bd6 (ServerContext): client response
    background_task = support_bundle_collector
    bundle = c6b507df-cb67-47c4-8887-ba9fc0fc0034
    result = Ok(Response { url: "http://[fd00:1122:3344:11f::2]:12225/sp/sled/28/task-dump", status: 200, headers: {"content-type": "application/json", "x-request-id": "4c05f0a6-8541-40c1-b34d-0366f22fa767", "content-length": "1", "date": "Wed, 09 Jul 2025 01:01:18 GMT"} })
01:01:18.373Z DEBG 95ebe94d-0e68-421d-9260-c30bd7fe4bd6 (ServerContext): client response
    background_task = support_bundle_collector
    bundle = c6b507df-cb67-47c4-8887-ba9fc0fc0034
    result = Ok(Response { url: "http://[fd00:1122:3344:11f::2]:12225/sp/sled/5/task-dump", status: 200, headers: {"content-type": "application/json", "x-request-id": "838690ad-3c40-4bd7-90a8-5f416ecc19ad", "content-length": "1", "date": "Wed, 09 Jul 2025 01:01:18 GMT"} })
01:01:18.373Z DEBG 95ebe94d-0e68-421d-9260-c30bd7fe4bd6 (ServerContext): client response
    background_task = support_bundle_collector
    bundle = c6b507df-cb67-47c4-8887-ba9fc0fc0034
    result = Ok(Response { url: "http://[fd00:1122:3344:11f::2]:12225/sp/sled/6/task-dump", status: 200, headers: {"content-type": "application/json", "x-request-id": "3d38a033-ce0f-4587-b977-a16ca9e86162", "content-length": "1", "date": "Wed, 09 Jul 2025 01:01:18 GMT"} })
01:01:18.373Z DEBG 95ebe94d-0e68-421d-9260-c30bd7fe4bd6 (ServerContext): client response
    background_task = support_bundle_collector
    bundle = c6b507df-cb67-47c4-8887-ba9fc0fc0034
    result = Ok(Response { url: "http://[fd00:1122:3344:11f::2]:12225/sp/sled/29/task-dump", status: 200, headers: {"content-type": "application/json", "x-request-id": "1ab05012-1d88-4098-92b4-6132508078e9", "content-length": "1", "date": "Wed, 09 Jul 2025 01:01:18 GMT"} })
01:01:18.373Z DEBG 95ebe94d-0e68-421d-9260-c30bd7fe4bd6 (ServerContext): client response
    background_task = support_bundle_collector
    bundle = c6b507df-cb67-47c4-8887-ba9fc0fc0034
    result = Ok(Response { url: "http://[fd00:1122:3344:11f::2]:12225/sp/sled/0/task-dump", status: 200, headers: {"content-type": "application/json", "x-request-id": "78360e15-080d-4f1a-abeb-a847c66cd10c", "content-length": "1", "date": "Wed, 09 Jul 2025 01:01:18 GMT"} })
01:01:18.373Z DEBG 95ebe94d-0e68-421d-9260-c30bd7fe4bd6 (ServerContext): client response
    background_task = support_bundle_collector
    bundle = c6b507df-cb67-47c4-8887-ba9fc0fc0034
    result = Ok(Response { url: "http://[fd00:1122:3344:11f::2]:12225/sp/switch/0/task-dump", status: 200, headers: {"content-type": "application/json", "x-request-id": "c92d82c0-63c2-4500-be40-98fcd18a0016", "content-length": "1", "date": "Wed, 09 Jul 2025 01:01:18 GMT"} })

In between, the collector hit some errors:

01:01:33.380Z ERRO 95ebe94d-0e68-421d-9260-c30bd7fe4bd6 (ServerContext): failed to capture task dumps
    background_task = support_bundle_collector
    bundle = c6b507df-cb67-47c4-8887-ba9fc0fc0034
    error = SP power 1: failed to get task dump count from SP: Error Response: status: 503 Service Unavailable; headers: {"content-type": "application/json", "x-request-id": "424eb413-81c0-4c33-82c0-0a029020114d", "content-length": "198", "date": "Wed, 09 Jul 2025 01:01:20 GMT"}; value: Error { error_code: Some("SpCommunicationFailed"), message: "error communicating with SP SpIdentifier { typ: Power, slot: 1 }: no SP discovered", request_id: "424eb413-81c0-4c33-82c0-0a029020114d" }
    file = nexus/src/app/background/tasks/support_bundle_collector.rs:1031
01:01:33.380Z ERRO 95ebe94d-0e68-421d-9260-c30bd7fe4bd6 (ServerContext): failed to capture task dumps
    background_task = support_bundle_collector
    bundle = c6b507df-cb67-47c4-8887-ba9fc0fc0034
    error = SP sled 24: failed to get task dump count from SP: Error Response: status: 503 Service Unavailable; headers: {"content-type": "application/json", "x-request-id": "be60285f-baf5-4b8c-b419-6ac16e4efc58", "content-length": "198", "date": "Wed, 09 Jul 2025 01:01:20 GMT"}; value: Error { error_code: Some("SpCommunicationFailed"), message: "error communicating with SP SpIdentifier { typ: Sled, slot: 24 }: no SP discovered", request_id: "be60285f-baf5-4b8c-b419-6ac16e4efc58" }
    file = nexus/src/app/background/tasks/support_bundle_collector.rs:1031
01:01:33.381Z ERRO 95ebe94d-0e68-421d-9260-c30bd7fe4bd6 (ServerContext): failed to capture task dumps
    background_task = support_bundle_collector
    bundle = c6b507df-cb67-47c4-8887-ba9fc0fc0034
    error = SP sled 9: failed to get task dump count from SP: Error Response: status: 503 Service Unavailable; headers: {"content-type": "application/json", "x-request-id": "d6f417ea-c5ec-419d-bedf-e006360a9ebf", "content-length": "197", "date": "Wed, 09 Jul 2025 01:01:20 GMT"}; value: Error { error_code: Some("SpCommunicationFailed"), message: "error communicating with SP SpIdentifier { typ: Sled, slot: 9 }: no SP discovered", request_id: "d6f417ea-c5ec-419d-bedf-e006360a9ebf" }
    file = nexus/src/app/background/tasks/support_bundle_collector.rs:1031
01:01:33.381Z ERRO 95ebe94d-0e68-421d-9260-c30bd7fe4bd6 (ServerContext): failed to capture task dumps
    background_task = support_bundle_collector
    bundle = c6b507df-cb67-47c4-8887-ba9fc0fc0034
    error = SP sled 22: failed to get task dump count from SP: Error Response: status: 503 Service Unavailable; headers: {"content-type": "application/json", "x-request-id": "0b44e793-3d95-4774-bbf4-f2628d3cae40", "content-length": "224", "date": "Wed, 09 Jul 2025 01:01:31 GMT"}; value: Error { error_code: Some("SpCommunicationFailed"), message: "error communicating with SP SpIdentifier { typ: Sled, slot: 22 }: RPC call failed (gave up after 5 attempts)", request_id: "0b44e793-3d95-4774-bbf4-f2628d3cae40" }
    file = nexus/src/app/background/tasks/support_bundle_collector.rs:1031
01:01:33.381Z ERRO 95ebe94d-0e68-421d-9260-c30bd7fe4bd6 (ServerContext): failed to capture task dumps
    background_task = support_bundle_collector
    bundle = c6b507df-cb67-47c4-8887-ba9fc0fc0034
    error = SP sled 4: failed to get task dump count from SP: Communication Error: error sending request for url (http://[fd00:1122:3344:11f::2]:12225/sp/sled/4/task-dump): error sending request for url (http://[fd00:1122:3344:11f::2]:12225/sp/sled/4/task-dump): operation timed out
    file = nexus/src/app/background/tasks/support_bundle_collector.rs:1031
01:01:33.381Z ERRO 95ebe94d-0e68-421d-9260-c30bd7fe4bd6 (ServerContext): failed to capture task dumps
    background_task = support_bundle_collector
    bundle = c6b507df-cb67-47c4-8887-ba9fc0fc0034
    error = SP sled 18: failed to get task dump count from SP: Communication Error: error sending request for url (http://[fd00:1122:3344:11f::2]:12225/sp/sled/18/task-dump): error sending request for url (http://[fd00:1122:3344:11f::2]:12225/sp/sled/18/task-dump): operation timed out
    file = nexus/src/app/background/tasks/support_bundle_collector.rs:1031
01:01:33.381Z ERRO 95ebe94d-0e68-421d-9260-c30bd7fe4bd6 (ServerContext): failed to capture task dumps
    background_task = support_bundle_collector
    bundle = c6b507df-cb67-47c4-8887-ba9fc0fc0034
    error = SP sled 30: failed to get task dump count from SP: Communication Error: error sending request for url (http://[fd00:1122:3344:11f::2]:12225/sp/sled/30/task-dump): error sending request for url (http://[fd00:1122:3344:11f::2]:12225/sp/sled/30/task-dump): operation timed out
    file = nexus/src/app/background/tasks/support_bundle_collector.rs:1031

And it was supposedly completed after 6+ mins:

01:07:36.752Z INFO 95ebe94d-0e68-421d-9260-c30bd7fe4bd6 (ServerContext): Bundle Collection completed
    background_task = support_bundle_collector
    bundle = c6b507df-cb67-47c4-8887-ba9fc0fc0034
    file = nexus/src/app/background/tasks/support_bundle_collector.rs:485

It's unclear if the errors caused the bundle to not be persisted or there were some other errors it hit that contributed to the stuck status.

[askfongjojo]

The complete nexus log is lcoated in /staff/core/omicron-8556.
@smklein @papertigers - Is there any additional information I can collect from the rack to troubleshoot this issue?

[askfongjojo]

Btw, rack3 is on r15 which predates #8438. I did look under the /pool/int/*/debug directories to see if I could find any intermediate log artifacts but there wasn't anything besides propolis zone bundles.

[papertigers]

Btw, rack3 is on r15 which predates #8438. I did look under the /pool/int/*/debug directories to see if I could find any intermediate log artifacts but there wasn't anything besides propolis zone bundles.

That's because we are using a tempfile that gets immediately unlinked. You would be able to see the open fd from sled-agents perspective if you run a command like: pilot host exec -O -c "pgrep sled-agent | xargs -n1 pfiles" 0-31

EDIT: would you also be able to run the same command above but swap pfiles for pstack

[augustuswm]

The sled SP failures there all corresponding to expunged sleds. I am not clear on what

01:01:33.380Z ERRO 95ebe94d-0e68-421d-9260-c30bd7fe4bd6 (ServerContext): failed to capture task dumps
    background_task = support_bundle_collector
    bundle = c6b507df-cb67-47c4-8887-ba9fc0fc0034
    error = SP power 1: failed to get task dump count from SP: Error Response: status: 503 Service Unavailable; headers: {"content-type": "application/json", "x-request-id": "424eb413-81c0-4c33-82c0-0a029020114d", "content-length": "198", "date": "Wed, 09 Jul 2025 01:01:20 GMT"}; value: Error { error_code: Some("SpCommunicationFailed"), message: "error communicating with SP SpIdentifier { typ: Power, slot: 1 }: no SP discovered", request_id: "424eb413-81c0-4c33-82c0-0a029020114d" }
    file = nexus/src/app/background/tasks/support_bundle_collector.rs:1031

is targeting specifically, but can try to figure it out.

[augustuswm]

Placing files in catacomb:/staff/rack3/2025-07-09/omicron-8556

[smklein]

Things that we are seeing that are a little odd:

1. We're seeing "Found bundle to collect" and "Bundle Collection completed" exactly once in the Nexus logs - this implies the support bundle collector in Nexus successfully made a temporary directory of support bundle contents.
2. However, after collection of this support bundle, we have not observed the support bundle on the targets sled/zpool. This implies that the "zipping + transfer" part of the collection wasn't successful (or just hasn't completed)
3. When running pstack on the Nexus process, we're still a thread running extract_zip_file - this is a function used by the background task during support bundle collection, when pulling logs from individual sleds and re-formatting them. It's unclear to us why this is still executing -- after "bundle collection complete", this task should have terminated.
4. We're also seeing recursively_add_directory_to_zipfile functions running - this is a function used by Nexus to turn "a directory version of a support bundle" into a "zipfile ready to transfer to the sled agent". The fact that this is running implies we haven't contacted a sled agent yet to move the file over. However, we should probably very this.

So, some questions:

• Why is extract_zip_file still running after the bundle collection has "completed"?
• Why is recursively_add_directory_to_zipfile still executing without terminating?

[askfongjojo]

I picked a particular set of zone logs to see if it has been reported by sled-agent being processed more than once

angela@castle /staff/core/omicron-8556 $ grep '/support/logs/download/oxz_nexus_95ebe94d-0e68-421d-9260-c30bd7fe4bd6?max_rotated=5' oxide-sled-agent.log 
{"msg":"request completed","v":0,"name":"SledAgent","level":30,"time":"2025-07-09T03:37:53.743565613Z","hostname":"BRM42220035","pid":643,"uri":"/support/logs/download/oxz_nexus_95ebe94d-0e68-421d-9260-c30bd7fe4bd6?max_rotated=5","method":"GET","req_id":"1efe9325-2d87-46d5-90e8-72a475565601","remote_addr":"[fd00:1122:3344:108::3]:52326","local_addr":"[fd00:1122:3344:108::1]:12345","component":"dropshot (SledAgent)","file":"/home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/dropshot-0.16.2/src/server.rs:867","latency_us":6681420,"response_code":200}
{"msg":"request completed","v":0,"name":"SledAgent","level":30,"time":"2025-07-09T04:11:47.851581889Z","hostname":"BRM42220035","pid":643,"uri":"/support/logs/download/oxz_nexus_95ebe94d-0e68-421d-9260-c30bd7fe4bd6?max_rotated=5","method":"GET","req_id":"74be44fa-97fc-42f0-9d70-b47be71e9f34","remote_addr":"[fd00:1122:3344:108::3]:62557","local_addr":"[fd00:1122:3344:108::1]:12345","component":"dropshot (SledAgent)","file":"/home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/dropshot-0.16.2/src/server.rs:867","latency_us":6384497,"response_code":200}
{"msg":"request completed","v":0,"name":"SledAgent","level":30,"time":"2025-07-09T04:45:57.0064272Z","hostname":"BRM42220035","pid":643,"uri":"/support/logs/download/oxz_nexus_95ebe94d-0e68-421d-9260-c30bd7fe4bd6?max_rotated=5","method":"GET","req_id":"efb35630-ca5b-45db-a6f1-5d8960cbeb2b","remote_addr":"[fd00:1122:3344:108::3]:58736","local_addr":"[fd00:1122:3344:108::1]:12345","component":"dropshot (SledAgent)","file":"/home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/dropshot-0.16.2/src/server.rs:867","latency_us":7844155,"response_code":200}
{"msg":"request completed","v":0,"name":"SledAgent","level":30,"time":"2025-07-09T05:20:15.839347772Z","hostname":"BRM42220035","pid":643,"uri":"/support/logs/download/oxz_nexus_95ebe94d-0e68-421d-9260-c30bd7fe4bd6?max_rotated=5","method":"GET","req_id":"d8cfabd1-9e99-4758-b613-d4717269e3fa","remote_addr":"[fd00:1122:3344:108::3]:45981","local_addr":"[fd00:1122:3344:108::1]:12345","component":"dropshot (SledAgent)","file":"/home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/dropshot-0.16.2/src/server.rs:867","latency_us":6848261,"response_code":200}
{"msg":"request completed","v":0,"name":"SledAgent","level":30,"time":"2025-07-09T05:54:26.502770803Z","hostname":"BRM42220035","pid":643,"uri":"/support/logs/download/oxz_nexus_95ebe94d-0e68-421d-9260-c30bd7fe4bd6?max_rotated=5","method":"GET","req_id":"9dad2f37-1c7c-42af-b437-a8c9b3105341","remote_addr":"[fd00:1122:3344:108::3]:58988","local_addr":"[fd00:1122:3344:108::1]:12345","component":"dropshot (SledAgent)","file":"/home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/dropshot-0.16.2/src/server.rs:867","latency_us":7070640,"response_code":200}
{"msg":"request completed","v":0,"name":"SledAgent","level":30,"time":"2025-07-09T06:28:57.452864719Z","hostname":"BRM42220035","pid":643,"uri":"/support/logs/download/oxz_nexus_95ebe94d-0e68-421d-9260-c30bd7fe4bd6?max_rotated=5","method":"GET","req_id":"43c9daf5-4d8f-4e5b-b4e0-3f0b37ed25ec","remote_addr":"[fd00:1122:3344:108::3]:63235","local_addr":"[fd00:1122:3344:108::1]:12345","component":"dropshot (SledAgent)","file":"/home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/dropshot-0.16.2/src/server.rs:867","latency_us":7968923,"response_code":200}
{"msg":"request completed","v":0,"name":"SledAgent","level":30,"time":"2025-07-09T07:03:24.789214074Z","hostname":"BRM42220035","pid":643,"uri":"/support/logs/download/oxz_nexus_95ebe94d-0e68-421d-9260-c30bd7fe4bd6?max_rotated=5","method":"GET","req_id":"a006e312-470c-4ac3-86a2-f32a34926642","remote_addr":"[fd00:1122:3344:108::3]:44750","local_addr":"[fd00:1122:3344:108::1]:12345","component":"dropshot (SledAgent)","file":"/home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/dropshot-0.16.2/src/server.rs:867","latency_us":6741312,"response_code":200}
{"msg":"request completed","v":0,"name":"SledAgent","level":30,"time":"2025-07-09T07:38:07.80214593Z","hostname":"BRM42220035","pid":643,"uri":"/support/logs/download/oxz_nexus_95ebe94d-0e68-421d-9260-c30bd7fe4bd6?max_rotated=5","method":"GET","req_id":"1667d7a3-1065-43b0-bbeb-459a08d18be0","remote_addr":"[fd00:1122:3344:108::3]:61486","local_addr":"[fd00:1122:3344:108::1]:12345","component":"dropshot (SledAgent)","file":"/home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/dropshot-0.16.2/src/server.rs:867","latency_us":7757679,"response_code":200}
{"msg":"request completed","v":0,"name":"SledAgent","level":30,"time":"2025-07-09T08:12:49.780337701Z","hostname":"BRM42220035","pid":643,"uri":"/support/logs/download/oxz_nexus_95ebe94d-0e68-421d-9260-c30bd7fe4bd6?max_rotated=5","method":"GET","req_id":"ce6422e2-afea-4577-8fcb-fe165f2f78b9","remote_addr":"[fd00:1122:3344:108::3]:35902","local_addr":"[fd00:1122:3344:108::1]:12345","component":"dropshot (SledAgent)","file":"/home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/dropshot-0.16.2/src/server.rs:867","latency_us":8056808,"response_code":200}
{"msg":"request completed","v":0,"name":"SledAgent","level":30,"time":"2025-07-09T08:47:42.07208966Z","hostname":"BRM42220035","pid":643,"uri":"/support/logs/download/oxz_nexus_95ebe94d-0e68-421d-9260-c30bd7fe4bd6?max_rotated=5","method":"GET","req_id":"b1f8b50b-2fa7-45d5-af1e-6ca3f3ded80e","remote_addr":"[fd00:1122:3344:108::3]:34132","local_addr":"[fd00:1122:3344:108::1]:12345","component":"dropshot (SledAgent)","file":"/home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/dropshot-0.16.2/src/server.rs:867","latency_us":6602888,"response_code":200}
{"msg":"request completed","v":0,"name":"SledAgent","level":30,"time":"2025-07-09T09:22:42.135813199Z","hostname":"BRM42220035","pid":643,"uri":"/support/logs/download/oxz_nexus_95ebe94d-0e68-421d-9260-c30bd7fe4bd6?max_rotated=5","method":"GET","req_id":"064a4ce0-8773-49d5-839e-3223a0b769c1","remote_addr":"[fd00:1122:3344:108::3]:32804","local_addr":"[fd00:1122:3344:108::1]:12345","component":"dropshot (SledAgent)","file":"/home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/dropshot-0.16.2/src/server.rs:867","latency_us":8871463,"response_code":200}
{"msg":"request completed","v":0,"name":"SledAgent","level":30,"time":"2025-07-09T09:57:52.063503016Z","hostname":"BRM42220035","pid":643,"uri":"/support/logs/download/oxz_nexus_95ebe94d-0e68-421d-9260-c30bd7fe4bd6?max_rotated=5","method":"GET","req_id":"f0abd58d-6fbb-43a7-be9e-e10530256eab","remote_addr":"[fd00:1122:3344:108::3]:33418","local_addr":"[fd00:1122:3344:108::1]:12345","component":"dropshot (SledAgent)","file":"/home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/dropshot-0.16.2/src/server.rs:867","latency_us":7506195,"response_code":200}
{"msg":"request completed","v":0,"name":"SledAgent","level":30,"time":"2025-07-09T10:33:14.112137771Z","hostname":"BRM42220035","pid":643,"uri":"/support/logs/download/oxz_nexus_95ebe94d-0e68-421d-9260-c30bd7fe4bd6?max_rotated=5","method":"GET","req_id":"9b89c78e-c21a-403a-ab7f-676c426a33c3","remote_addr":"[fd00:1122:3344:108::3]:33844","local_addr":"[fd00:1122:3344:108::1]:12345","component":"dropshot (SledAgent)","file":"/home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/dropshot-0.16.2/src/server.rs:867","latency_us":6321744,"response_code":200}
{"msg":"request completed","v":0,"name":"SledAgent","level":30,"time":"2025-07-09T11:08:38.539123341Z","hostname":"BRM42220035","pid":643,"uri":"/support/logs/download/oxz_nexus_95ebe94d-0e68-421d-9260-c30bd7fe4bd6?max_rotated=5","method":"GET","req_id":"612cf662-960a-4b23-b410-ae5766d90688","remote_addr":"[fd00:1122:3344:108::3]:61619","local_addr":"[fd00:1122:3344:108::1]:12345","component":"dropshot (SledAgent)","file":"/home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/dropshot-0.16.2/src/server.rs:867","latency_us":7782244,"response_code":200}
{"msg":"request completed","v":0,"name":"SledAgent","level":30,"time":"2025-07-09T11:44:16.594937426Z","hostname":"BRM42220035","pid":643,"uri":"/support/logs/download/oxz_nexus_95ebe94d-0e68-421d-9260-c30bd7fe4bd6?max_rotated=5","method":"GET","req_id":"554864ac-2d7a-4ff0-838b-d03843a04663","remote_addr":"[fd00:1122:3344:108::3]:50095","local_addr":"[fd00:1122:3344:108::1]:12345","component":"dropshot (SledAgent)","file":"/home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/dropshot-0.16.2/src/server.rs:867","latency_us":6758492,"response_code":200}
{"msg":"request completed","v":0,"name":"SledAgent","level":30,"time":"2025-07-09T12:20:16.089003528Z","hostname":"BRM42220035","pid":643,"uri":"/support/logs/download/oxz_nexus_95ebe94d-0e68-421d-9260-c30bd7fe4bd6?max_rotated=5","method":"GET","req_id":"1817fc3b-f813-4ca0-8425-26921010e659","remote_addr":"[fd00:1122:3344:108::3]:63464","local_addr":"[fd00:1122:3344:108::1]:12345","component":"dropshot (SledAgent)","file":"/home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/dropshot-0.16.2/src/server.rs:867","latency_us":8661588,"response_code":200}
{"msg":"request completed","v":0,"name":"SledAgent","level":30,"time":"2025-07-09T12:56:08.703294555Z","hostname":"BRM42220035","pid":643,"uri":"/support/logs/download/oxz_nexus_95ebe94d-0e68-421d-9260-c30bd7fe4bd6?max_rotated=5","method":"GET","req_id":"b7af0b4c-9515-44aa-bee6-1df5fa99710c","remote_addr":"[fd00:1122:3344:108::3]:39261","local_addr":"[fd00:1122:3344:108::1]:12345","component":"dropshot (SledAgent)","file":"/home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/dropshot-0.16.2/src/server.rs:867","latency_us":7520070,"response_code":200}
{"msg":"request completed","v":0,"name":"SledAgent","level":30,"time":"2025-07-09T13:32:12.822783027Z","hostname":"BRM42220035","pid":643,"uri":"/support/logs/download/oxz_nexus_95ebe94d-0e68-421d-9260-c30bd7fe4bd6?max_rotated=5","method":"GET","req_id":"ac440485-7140-490c-9b14-dca1543c81a9","remote_addr":"[fd00:1122:3344:108::3]:53676","local_addr":"[fd00:1122:3344:108::1]:12345","component":"dropshot (SledAgent)","file":"/home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/dropshot-0.16.2/src/server.rs:867","latency_us":5706207,"response_code":200}
{"msg":"request completed","v":0,"name":"SledAgent","level":30,"time":"2025-07-09T14:08:19.167986652Z","hostname":"BRM42220035","pid":643,"uri":"/support/logs/download/oxz_nexus_95ebe94d-0e68-421d-9260-c30bd7fe4bd6?max_rotated=5","method":"GET","req_id":"82079119-cccc-4641-87ec-1df800f44df6","remote_addr":"[fd00:1122:3344:108::3]:51503","local_addr":"[fd00:1122:3344:108::1]:12345","component":"dropshot (SledAgent)","file":"/home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/dropshot-0.16.2/src/server.rs:867","latency_us":7408670,"response_code":200}
{"msg":"request completed","v":0,"name":"SledAgent","level":30,"time":"2025-07-09T14:44:43.553720466Z","hostname":"BRM42220035","pid":643,"uri":"/support/logs/download/oxz_nexus_95ebe94d-0e68-421d-9260-c30bd7fe4bd6?max_rotated=5","method":"GET","req_id":"6afe8b7e-6a69-4e86-8799-47618c29eb4e","remote_addr":"[fd00:1122:3344:108::3]:37474","local_addr":"[fd00:1122:3344:108::1]:12345","component":"dropshot (SledAgent)","file":"/home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/dropshot-0.16.2/src/server.rs:867","latency_us":5937196,"response_code":200}
{"msg":"request completed","v":0,"name":"SledAgent","level":30,"time":"2025-07-09T15:21:03.043827518Z","hostname":"BRM42220035","pid":643,"uri":"/support/logs/download/oxz_nexus_95ebe94d-0e68-421d-9260-c30bd7fe4bd6?max_rotated=5","method":"GET","req_id":"f8b22096-6e74-4baf-b859-0a3c471775f6","remote_addr":"[fd00:1122:3344:108::3]:54539","local_addr":"[fd00:1122:3344:108::1]:12345","component":"dropshot (SledAgent)","file":"/home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/dropshot-0.16.2/src/server.rs:867","latency_us":8653675,"response_code":200}
{"msg":"request completed","v":0,"name":"SledAgent","level":30,"time":"2025-07-09T15:57:29.887299408Z","hostname":"BRM42220035","pid":643,"uri":"/support/logs/download/oxz_nexus_95ebe94d-0e68-421d-9260-c30bd7fe4bd6?max_rotated=5","method":"GET","req_id":"f21dcc60-e10b-4c86-ac13-b126abc3335c","remote_addr":"[fd00:1122:3344:108::3]:35414","local_addr":"[fd00:1122:3344:108::1]:12345","component":"dropshot (SledAgent)","file":"/home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/dropshot-0.16.2/src/server.rs:867","latency_us":8116093,"response_code":200}
{"msg":"request completed","v":0,"name":"SledAgent","level":30,"time":"2025-07-09T16:34:00.340161284Z","hostname":"BRM42220035","pid":643,"uri":"/support/logs/download/oxz_nexus_95ebe94d-0e68-421d-9260-c30bd7fe4bd6?max_rotated=5","method":"GET","req_id":"aee34bd9-2c42-4764-b70e-316d8e2a6a73","remote_addr":"[fd00:1122:3344:108::3]:53943","local_addr":"[fd00:1122:3344:108::1]:12345","component":"dropshot (SledAgent)","file":"/home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/dropshot-0.16.2/src/server.rs:867","latency_us":7667132,"response_code":200}
{"msg":"request completed","v":0,"name":"SledAgent","level":30,"time":"2025-07-09T17:11:01.517142755Z","hostname":"BRM42220035","pid":643,"uri":"/support/logs/download/oxz_nexus_95ebe94d-0e68-421d-9260-c30bd7fe4bd6?max_rotated=5","method":"GET","req_id":"e05dcd25-99b6-4919-a318-ee3fdcf0463d","remote_addr":"[fd00:1122:3344:108::3]:63467","local_addr":"[fd00:1122:3344:108::1]:12345","component":"dropshot (SledAgent)","file":"/home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/dropshot-0.16.2/src/server.rs:867","latency_us":6243677,"response_code":200}

Does it mean that some kind of retry has been going on?

[augustuswm]

It looks like the background task is failing and continuing to attempt to re-run:

root@oxz_switch1:~# OMDB_NEXUS_URL=http://[fd00:1122:3344:108::3]:12221 omdb nexus background-tasks show support_bundle_collector
note: using Nexus URL http://[fd00:1122:3344:108::3]:12221
task: "support_bundle_collector"
  configured period: every 30s
  currently executing: iter 109287, triggered by a dependent task completing
    started at 2025-07-09T17:47:27.365Z, running for 414284ms
  last completed activation: iter 109286, triggered by a dependent task completing
    started at 2025-07-09T17:10:32.559Z (2629s ago) and ran for 2214662ms
warning: failed to interpret task details: Error("invalid type: map, expected a string", line: 0, column: 0): Object {"cleanup_err": Null, "cleanup_report": Object {"db_destroying_bundles_removed": Number(0), "db_failing_bundles_updated": Number(0), "sled_bundles_delete_failed": Number(0), "sled_bundles_deleted_not_found": Number(0), "sled_bundles_deleted_ok": Number(0)}, "collection_err": Object {"collect_error": String("Error Response: status: 400 Bad Request; headers: {\"content-type\": \"application/json\", \"x-request-id\": \"cf2d79e6-f004-4356-90d6-9b1b1ef068c7\", \"content-length\": \"129\", \"date\": \"Wed, 09 Jul 2025 17:47:24 GMT\"}; value: Error { error_code: None, message: \"request body exceeded maximum size of 2147483648 bytes\", request_id: \"cf2d79e6-f004-4356-90d6-9b1b1ef068c7\" }")}, "collection_report": Null}

[augustuswm]

From sled-agent log on sled 19:

BRM42220015 # cat `svcs -L sled-agent` | grep cf2d79e6-f004-4356-90d6-9b1b1ef068c7 | looker
17:47:24.710Z INFO SledAgent (dropshot (SledAgent)): request completed
    error_message_external = request body exceeded maximum size of 2147483648 bytes
    error_message_internal = request body exceeded maximum size of 2147483648 bytes
    file = /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/dropshot-0.16.2/src/server.rs:855
    latency_us = 46481351
    local_addr = [fd00:1122:3344:109::1]:12345
    method = POST
    remote_addr = [fd00:1122:3344:108::3]:63804
    req_id = cf2d79e6-f004-4356-90d6-9b1b1ef068c7
    response_code = 400
    uri = /support-bundles/de682b18-afaf-4d53-b62e-934f6bd4a1f8/003d27e0-57e4-4d55-963e-af47e4e526f1/c6b507df-cb67-47c4-8887-ba9fc0fc0034?hash=715b47222272c4db6af42ec927abcf71c3f2321a9fbe9506436a14e4601a7bbf

[smklein]

We have answers to a handful of things:

• Nexus is failing to store support bundles on the Sled Agent because it's making a request to transfer a 2+ GiB file, which sled agent rejects
• Nexus's background task is not running "collection" + "transfer" concurrently -- it's still serializing them, but retrying later when the background task fires again, after the transfer fails.

[askfongjojo]

Knowing what we know now, I was able to find the corresponding error in nexus (when it first happened):

BRM42220035 # grep 'request body exceeded' /pool/ext/95220093-e3b8-4f7f-9f5a-cb32cb75180a/crypt/debug/oxz_nexus_95ebe94d-0e68-421d-9260-c30bd7fe4bd6/oxide-nexus:default.log.1752025501 | looker
01:39:43.841Z DEBG 95ebe94d-0e68-421d-9260-c30bd7fe4bd6 (ServerContext): activation complete
    background_task = support_bundle_collector
    elapsed = 2305.420309181s
    iteration = 109259
    status = {"cleanup_err":null,"cleanup_report":{"db_destroying_bundles_removed":0,"db_failing_bundles_updated":0,"sled_bundles_delete_failed":0,"sled_bundles_deleted_not_found":0,"sled_bundles_deleted_ok":0},"collection_err":{"collect_error":"Error Response: status: 400 Bad Request; headers: {\\"content-type\\": \\"application/json\\", \\"x-request-id\\": \\"aa66e6a0-1012-44bc-a1e1-8f65170bf3b7\\", \\"content-length\\": \\"129\\", \\"date\\": \\"Wed, 09 Jul 2025 01:39:41 GMT\\"}; value: Error { error_code: None, message: \\"request body exceeded maximum size of 2147483648 bytes\\", request_id: \\"aa66e6a0-1012-44bc-a1e1-8f65170bf3b7\\" }"},"collection_report":null}

Would it be possible for the background task to keep a count of errors without resetting it in each new iteration?

[smklein]

We discussed per-endpoint max bundle sizes -- turns out, this already exists:

omicron/sled-agent/api/src/lib.rs

Lines 66 to 68 in cddd41e

	// TODO This was the previous API-wide max; what is the largest support bundle
	// we expect to need to store?
	const SUPPORT_BUNDLE_MAX_BYTES: usize = 2 * 1024 * 1024 * 1024;