NoSuchUpload exception when finalizing mirrored file

[hannes-ucsc]

For this particular digest (24c359680cb24161a5cae6e9dd5f8e90) there were two files (see #7670 for why) but we end up with three, not two FinalizeFileAction messages because the MirrorPartAction for part 13 of one of the files was received twice. I checked the executions for part 12 and it does not seem a message for part 13 was sent twice. Instead, AWS Lambda invoked the function twice for the same message, even though the first invocation was successful. Both invocations queued a new message for part 14, so we ended up three "threads" instead of the expected two. In other words, the thread for file d35fa3c7 was forked at part 13. There were still only two concurrent uploads, but parts 13 and higher were uploaded twice. Two of the resulting three FinalizeFileMessages succeeded: one completed its upload, creating the object, the other one discarded its upload and succeeded anyways (this is what the fix for #7662 entailed). The third FinalizeFileAction failed because its upload had been discarded by the second FinalizeFileMessage. It would also have failed had its upload been completed.

CloudWatch Logs Insights
region: us-east-1
log-group-names: /aws/lambda/azul-indexer-anvilprod-mirror
data-sources:
facets:
start-time: 2025-12-31T21:44:21.179Z
end-time: 2026-01-01T08:48:18.569Z
query-string:

fields @timestamp, substr(@requestId, 0, 8) as request, substr(file.uuid, 0, 8) as file, action, part.index as part
| filter file.md5 = '24c359680cb24161a5cae6e9dd5f8e90' 
| filter @message like /Worker (failed|successfully)/
| parse @message "Worker * " as result
| sort @timestamp asc

---

@timestamp	request	file	action	part	result
2025-12-31 23:21:50.891	dd711bee	55f89925	MirrorFileAction		successfully
2025-12-31 23:22:20.023	c1c5aa43	d35fa3c7	MirrorFileAction		successfully
2025-12-31 23:41:33.983	7f4be90c	55f89925	MirrorPartAction	1	successfully
2025-12-31 23:42:02.593	a9e16d4a	d35fa3c7	MirrorPartAction	1	successfully
2026-01-01 00:00:15.996	02508105	55f89925	MirrorPartAction	2	successfully
2026-01-01 00:00:46.084	4056f61c	d35fa3c7	MirrorPartAction	2	successfully
2026-01-01 00:19:12.060	f667c26f	55f89925	MirrorPartAction	3	successfully
2026-01-01 00:19:41.868	d93dd8cc	d35fa3c7	MirrorPartAction	3	successfully
2026-01-01 00:38:08.692	55013357	55f89925	MirrorPartAction	4	successfully
2026-01-01 00:38:38.295	837fc026	d35fa3c7	MirrorPartAction	4	successfully
2026-01-01 00:56:52.275	a6fd4f52	55f89925	MirrorPartAction	5	successfully
2026-01-01 00:57:22.776	9aa26483	d35fa3c7	MirrorPartAction	5	successfully
2026-01-01 01:15:50.430	3280be6f	55f89925	MirrorPartAction	6	successfully
2026-01-01 01:16:19.690	71789c54	d35fa3c7	MirrorPartAction	6	successfully
2026-01-01 01:34:50.490	80c13990	55f89925	MirrorPartAction	7	successfully
2026-01-01 01:35:20.445	6a8a5774	d35fa3c7	MirrorPartAction	7	successfully
2026-01-01 01:53:47.554	cd440d0a	55f89925	MirrorPartAction	8	successfully
2026-01-01 01:54:17.282	d2141520	d35fa3c7	MirrorPartAction	8	successfully
2026-01-01 02:12:49.768	ed94a265	55f89925	MirrorPartAction	9	successfully
2026-01-01 02:13:18.969	d1f3ee52	d35fa3c7	MirrorPartAction	9	successfully
2026-01-01 02:31:54.847	a72230b8	55f89925	MirrorPartAction	10	successfully
2026-01-01 02:32:23.391	5867fe60	d35fa3c7	MirrorPartAction	10	successfully
2026-01-01 02:50:48.290	85142801	55f89925	MirrorPartAction	11	successfully
2026-01-01 02:51:18.670	9290eb84	d35fa3c7	MirrorPartAction	11	successfully
2026-01-01 03:09:45.091	29ac9885	55f89925	MirrorPartAction	12	successfully
2026-01-01 03:10:17.645	a0527570	d35fa3c7	MirrorPartAction	12	successfully
2026-01-01 03:28:48.840	29f13f9e	55f89925	MirrorPartAction	13	successfully
2026-01-01 03:29:21.974	1ee59f9d	d35fa3c7	MirrorPartAction	13	successfully
2026-01-01 03:43:34.801	e98f3cea	d35fa3c7	MirrorPartAction	13	successfully
2026-01-01 03:44:03.297	8f440d97	55f89925	MirrorPartAction	14	successfully
2026-01-01 03:44:32.998	44696bc7	d35fa3c7	MirrorPartAction	14	successfully
2026-01-01 03:48:21.975	fab7f5c3	d35fa3c7	MirrorPartAction	14	successfully
2026-01-01 03:48:51.461	efb155a0	55f89925	MirrorPartAction	15	successfully
2026-01-01 03:49:20.793	53a51d38	d35fa3c7	MirrorPartAction	15	successfully
2026-01-01 03:53:14.972	118aab0a	d35fa3c7	MirrorPartAction	15	successfully
2026-01-01 03:53:46.491	e12da7bd	55f89925	MirrorPartAction	16	successfully
2026-01-01 03:54:16.637	c53f00d1	d35fa3c7	MirrorPartAction	16	successfully
2026-01-01 03:58:05.132	82dbae8f	d35fa3c7	MirrorPartAction	16	successfully
2026-01-01 03:58:36.190	31411e63	55f89925	MirrorPartAction	17	successfully
2026-01-01 03:59:05.881	e3a83a45	d35fa3c7	MirrorPartAction	17	successfully
2026-01-01 04:02:59.522	5abf10ad	d35fa3c7	MirrorPartAction	17	successfully
2026-01-01 04:03:31.619	fbc9aa5e	55f89925	MirrorPartAction	18	successfully
2026-01-01 04:04:02.774	bc9226b3	d35fa3c7	MirrorPartAction	18	successfully
2026-01-01 04:07:46.027	3e3e3cd4	d35fa3c7	MirrorPartAction	18	successfully
2026-01-01 04:08:18.020	efc9b5a6	55f89925	MirrorPartAction	19	successfully
2026-01-01 04:08:47.735	7f368a1d	d35fa3c7	MirrorPartAction	19	successfully
2026-01-01 04:12:40.060	0de546dc	d35fa3c7	MirrorPartAction	19	successfully
2026-01-01 04:13:13.247	8a249402	55f89925	MirrorPartAction	20	successfully
2026-01-01 04:13:42.222	f93283c6	d35fa3c7	MirrorPartAction	20	successfully
2026-01-01 04:17:31.529	4fdff4d9	d35fa3c7	MirrorPartAction	20	successfully
2026-01-01 04:18:05.618	67c56477	55f89925	MirrorPartAction	21	successfully
2026-01-01 04:18:34.637	948e8fdb	d35fa3c7	MirrorPartAction	21	successfully
2026-01-01 04:22:18.306	1c29c1f2	d35fa3c7	MirrorPartAction	21	successfully
2026-01-01 04:22:51.307	fa6f89c5	55f89925	MirrorPartAction	22	successfully
2026-01-01 04:23:22.206	9f93b414	d35fa3c7	MirrorPartAction	22	successfully
2026-01-01 04:27:10.408	ec5014d3	d35fa3c7	MirrorPartAction	22	successfully
2026-01-01 04:27:44.874	a2009d6f	55f89925	MirrorPartAction	23	successfully
2026-01-01 04:28:17.046	1e35a398	d35fa3c7	MirrorPartAction	23	successfully
2026-01-01 04:32:07.566	7fc063d8	d35fa3c7	MirrorPartAction	23	successfully
2026-01-01 04:32:40.623	09356764	55f89925	MirrorPartAction	24	successfully
2026-01-01 04:33:13.030	eec47db4	d35fa3c7	MirrorPartAction	24	successfully
2026-01-01 04:36:55.711	38a0d461	d35fa3c7	MirrorPartAction	24	successfully
2026-01-01 04:37:30.715	bcb5e0ef	55f89925	MirrorPartAction	25	successfully
2026-01-01 04:38:00.514	38214cb6	d35fa3c7	MirrorPartAction	25	successfully
2026-01-01 04:41:47.140	db57e028	d35fa3c7	MirrorPartAction	25	successfully
2026-01-01 04:42:21.935	c727d5f8	55f89925	MirrorPartAction	26	successfully
2026-01-01 04:42:52.367	99d715f3	d35fa3c7	MirrorPartAction	26	successfully
2026-01-01 04:46:31.783	7d84e4a7	d35fa3c7	MirrorPartAction	26	successfully
2026-01-01 04:47:06.518	df447ef2	55f89925	MirrorPartAction	27	successfully
2026-01-01 04:47:36.060	3333027c	d35fa3c7	MirrorPartAction	27	successfully
2026-01-01 04:51:09.027	a37dfd25	d35fa3c7	MirrorPartAction	27	successfully
2026-01-01 04:51:42.345	a3bba965	55f89925	MirrorPartAction	28	successfully
2026-01-01 04:52:09.849	5c741c4b	d35fa3c7	MirrorPartAction	28	successfully
2026-01-01 04:55:40.262	3492a601	d35fa3c7	MirrorPartAction	28	successfully
2026-01-01 04:55:44.441	1613985d	55f89925	FinalizeFileAction		successfully
2026-01-01 04:56:10.894	f40cebb4	d35fa3c7	FinalizeFileAction		successfully
2026-01-01 04:59:29.789	a6fd9c28	d35fa3c7	FinalizeFileAction		failed
2026-01-01 05:06:19.485	c437a15f	d35fa3c7	FinalizeFileAction		failed
2026-01-01 05:12:58.131	028a122f	d35fa3c7	FinalizeFileAction		failed
2026-01-01 05:19:31.185	9e57c978	d35fa3c7	FinalizeFileAction		failed
2026-01-01 05:26:12.824	06729a73	d35fa3c7	FinalizeFileAction		failed
2026-01-01 05:32:31.539	cb45f53e	d35fa3c7	FinalizeFileAction		failed
2026-01-01 05:38:49.156	776884cf	d35fa3c7	FinalizeFileAction		failed
2026-01-01 05:45:00.209	1d32af78	d35fa3c7	FinalizeFileAction		failed
2026-01-01 05:51:01.934	e0066c0f	d35fa3c7	FinalizeFileAction		failed
2026-01-01 05:57:00.999	ce0e7253	d35fa3c7	FinalizeFileAction		failed

---

The failures were all caused by

Traceback (most recent call last):
  File "/var/task/azul/indexer/action_controller.py", line 57, in _handle_events
    message_handler(action)
    ~~~~~~~~~~~~~~~^^^^^^^^
  File "/var/task/azul/indexer/mirror_controller.py", line 73, in message_handler
    self.service(action.catalog).mirror(action)
    ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~^^^^^^^^
  File "/var/task/azul/indexer/mirror_service.py", line 470, in mirror
    self._queue_messages(self._mirror(action))
                         ~~~~~~~~~~~~^^^^^^^^
  File "/var/lang/lib/python3.13/functools.py", line 975, in _method
    return dispatch(args[0].__class__).__get__(obj, cls)(*args, **kwargs)
           ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~^^^^^^^^^^^^^^^^^
  File "/var/task/azul/indexer/mirror_service.py", line 627, in _
    self._storage.complete_multipart_upload(object_key=object_key,
    ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^
                                            upload_id=a.upload.upload_id,
                                            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
                                            etags=a.upload.etags,
                                            ^^^^^^^^^^^^^^^^^^^^^
                                            overwrite=False)
                                            ^^^^^^^^^^^^^^^^
  File "/var/task/azul/service/storage_service.py", line 206, in complete_multipart_upload
    self._handle_overwrite(e, object_key)
    ~~~~~~~~~~~~~~~~~~~~~~^^^^^^^^^^^^^^^
  File "/var/task/azul/service/storage_service.py", line 345, in _handle_overwrite
    raise exception
  File "/var/task/azul/service/storage_service.py", line 204, in complete_multipart_upload
    self._s3.complete_multipart_upload(**request)
    ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~^^^^^^^^^^^
  File "/opt/python/botocore/client.py", line 602, in _api_call
    return self._make_api_call(operation_name, kwargs)
           ~~~~~~~~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^^
  File "/opt/python/botocore/context.py", line 123, in wrapper
    return func(*args, **kwargs)
  File "/opt/python/botocore/client.py", line 1078, in _make_api_call
    raise error_class(parsed_response, operation_name)
botocore.errorfactory.NoSuchUpload: An error occurred (NoSuchUpload) when calling the CompleteMultipartUpload operation: The specified upload does not exist. The upload ID may be invalid, or the upload may have been aborted or completed.

[hannes-ucsc]

We observe that 14min pass between the invocations for part 13 file of d35fa3c7. This is greater than the 5min deduplication window for SQS. However the messages for part 14 of that file are handled within 5 min of each other. This strongly suggests that the messages for part 15 were also queued within 5min of each other. Currently the deduplication ID of mirror action messages is a random v4 UUID, which essentially disables deduplication. Using a meaningful deduplication ID, such as the file ID and the part index, would introduce at least a chance of merging the threads again.