Problem: Delayed transfer status

[jens-st]

Expected behaviour
After starting a transfer Archivematica returns a transfer uuid. The status of the uuid can be check right away and returns a valid state.

Current behaviour
After upgrading to AM 1.15.1 (from 1.14) we notice a long time period (sometimes >6min) until a valid status is available. Before that the status API returns Unable to determine the status of the unit ***UUID***.
(Side note: The transfer itself is valid, does not fail and is eventually archived successful.)

EXAMPLE dashboard log

ERROR     2024-02-22 16:01:01  archivematica.dashboard:views:status:282:  Unable to determine the status of the unit 35f3138c-a3ad-46b9-b4ad-8259411f2ba7 (list index out of range)
ERROR     2024-02-22 16:01:11  archivematica.dashboard:views:status:282:  Unable to determine the status of the unit 35f3138c-a3ad-46b9-b4ad-8259411f2ba7 (list index out of range)
ERROR     2024-02-22 16:01:22  archivematica.dashboard:views:status:282:  Unable to determine the status of the unit 35f3138c-a3ad-46b9-b4ad-8259411f2ba7 (list index out of range)
ERROR     2024-02-22 16:01:32  archivematica.dashboard:views:status:282:  Unable to determine the status of the unit 35f3138c-a3ad-46b9-b4ad-8259411f2ba7 (list index out of range)
ERROR     2024-02-22 16:01:42  archivematica.dashboard:views:status:282:  Unable to determine the status of the unit 35f3138c-a3ad-46b9-b4ad-8259411f2ba7 (list index out of range)
ERROR     2024-02-22 16:01:52  archivematica.dashboard:views:status:282:  Unable to determine the status of the unit 35f3138c-a3ad-46b9-b4ad-8259411f2ba7 (list index out of range)
ERROR     2024-02-22 16:02:02  archivematica.dashboard:views:status:282:  Unable to determine the status of the unit 35f3138c-a3ad-46b9-b4ad-8259411f2ba7 (list index out of range)
ERROR     2024-02-22 16:02:12  archivematica.dashboard:views:status:282:  Unable to determine the status of the unit 35f3138c-a3ad-46b9-b4ad-8259411f2ba7 (list index out of range)
ERROR     2024-02-22 16:02:23  archivematica.dashboard:views:status:282:  Unable to determine the status of the unit 35f3138c-a3ad-46b9-b4ad-8259411f2ba7 (list index out of range)
ERROR     2024-02-22 16:02:33  archivematica.dashboard:views:status:282:  Unable to determine the status of the unit 35f3138c-a3ad-46b9-b4ad-8259411f2ba7 (list index out of range)
ERROR     2024-02-22 16:02:43  archivematica.dashboard:views:status:282:  Unable to determine the status of the unit 35f3138c-a3ad-46b9-b4ad-8259411f2ba7 (list index out of range)
ERROR     2024-02-22 16:02:53  archivematica.dashboard:views:status:282:  Unable to determine the status of the unit 35f3138c-a3ad-46b9-b4ad-8259411f2ba7 (list index out of range)

EXAMPLE starting transfer & checking transfer status (with curl)

2024-02-22T16:00:51+0100 | HTTP 202 | TRANSFER UUID 35f3138c-a3ad-46b9-b4ad-8259411f2ba7
2024-02-22T16:01:01+0100 | HTTP 400 | Unable to determine the status of the unit 35f3138c-a3ad-46b9-b4ad-8259411f2ba7
2024-02-22T16:01:11+0100 | HTTP 400 | Unable to determine the status of the unit 35f3138c-a3ad-46b9-b4ad-8259411f2ba7
2024-02-22T16:01:22+0100 | HTTP 400 | Unable to determine the status of the unit 35f3138c-a3ad-46b9-b4ad-8259411f2ba7
2024-02-22T16:01:32+0100 | HTTP 400 | Unable to determine the status of the unit 35f3138c-a3ad-46b9-b4ad-8259411f2ba7
2024-02-22T16:01:42+0100 | HTTP 400 | Unable to determine the status of the unit 35f3138c-a3ad-46b9-b4ad-8259411f2ba7
2024-02-22T16:01:52+0100 | HTTP 400 | Unable to determine the status of the unit 35f3138c-a3ad-46b9-b4ad-8259411f2ba7
2024-02-22T16:02:02+0100 | HTTP 400 | Unable to determine the status of the unit 35f3138c-a3ad-46b9-b4ad-8259411f2ba7
2024-02-22T16:02:13+0100 | HTTP 400 | Unable to determine the status of the unit 35f3138c-a3ad-46b9-b4ad-8259411f2ba7
2024-02-22T16:02:23+0100 | HTTP 400 | Unable to determine the status of the unit 35f3138c-a3ad-46b9-b4ad-8259411f2ba7
2024-02-22T16:02:33+0100 | HTTP 400 | Unable to determine the status of the unit 35f3138c-a3ad-46b9-b4ad-8259411f2ba7
2024-02-22T16:02:43+0100 | HTTP 400 | Unable to determine the status of the unit 35f3138c-a3ad-46b9-b4ad-8259411f2ba7
2024-02-22T16:02:53+0100 | HTTP 400 | Unable to determine the status of the unit 35f3138c-a3ad-46b9-b4ad-8259411f2ba7
2024-02-22T16:03:03+0100 | HTTP 200 | Fetched status for 35f3138c-a3ad-46b9-b4ad-8259411f2ba7 successfully.
2024-02-22T16:03:14+0100 | HTTP 200 | Fetched status for 35f3138c-a3ad-46b9-b4ad-8259411f2ba7 successfully.
2024-02-22T16:03:24+0100 | HTTP 200 | Fetched status for 35f3138c-a3ad-46b9-b4ad-8259411f2ba7 successfully.

EXAMPLE storage service log

DEBUG     2024-02-22 16:00:51  locations.api.resources:resources:_move_files_between_locations:543:  Moving files from this location is not allowed
DEBUG     2024-02-22 16:00:51  locations.models.space:space:move_to_storage_service:341:  TO: src: mnt/ingest/test_status_minimalistic/.
DEBUG     2024-02-22 16:00:51  locations.models.space:space:move_to_storage_service:342:  TO: dst: /var/archivematica/sharedDirectory/tmp/tmpd7rj4krs/TEST-TRANSFER_2024-02-22T16-00-51/.
DEBUG     2024-02-22 16:00:51  locations.models.space:space:move_to_storage_service:343:  TO: staging: /var/archivematica/storage_service
INFO      2024-02-22 16:00:51  locations.models.space:space:move_rsync:545:  Moving from /mnt/ingest/test_status_minimalistic/. to /var/archivematica/storage_service/var/archivematica/sharedDirectory/tmp/tmpd7rj4krs/TEST-TRANSFER_2024-02-22T16-00-51/.
INFO      2024-02-22 16:00:51  locations.models.space:space:move_rsync:587:  rsync command: ['rsync', '-t', '-O', '--protect-args', '-vv', '--chmod=Fug+rw,o-rwx,Dug+rwx,o-rwx', '-r', '/mnt/ingest/test_status_minimalistic/.', '/var/archivematica/storage_service/var/archivematica/sharedDirectory/tmp/tmpd7rj4krs/TEST-TRANSFER_2024-02-22T16-00-51/.']
DEBUG     2024-02-22 16:02:56  locations.models.space:space:move_from_storage_service:418:  FROM: src: /var/archivematica/sharedDirectory/tmp/tmpd7rj4krs/TEST-TRANSFER_2024-02-22T16-00-51/.
DEBUG     2024-02-22 16:02:56  locations.models.space:space:move_from_storage_service:419:  FROM: dst: /var/archivematica/sharedDirectory/tmp/tmpd7rj4krs/TEST-TRANSFER_2024-02-22T16-00-51/.
INFO      2024-02-22 16:02:56  locations.models.space:space:move_rsync:545:  Moving from /var/archivematica/storage_service/var/archivematica/sharedDirectory/tmp/tmpd7rj4krs/TEST-TRANSFER_2024-02-22T16-00-51/./ to /var/archivematica/sharedDirectory/tmp/tmpd7rj4krs/TEST-TRANSFER_2024-02-22T16-00-51/.
DEBUG     2024-02-22 16:02:56  locations.models.space:space:move_rsync:559:  os.rename failed, trying with normalized paths
INFO      2024-02-22 16:03:23  locations.api.resources:resources:hydrate_current_location:1036:  `current_location` was augmented: `/api/v2/location/26873b4d-6872-44e1-9037-78098fbe36d8/`
INFO      2024-02-22 16:03:23  locations.models.package:package:store_aip:852:  store_aip called in Package class of SS
INFO      2024-02-22 16:03:23  locations.models.package:package:store_aip:853:  store_aip got origin_path currentlyProcessing/TEST-TRANSFER_2024-02-22T16-00-51-d2571e8b-d388-4649-bf53-aa70f8194653/TEST-TRANSFER_2024-02-22T16-00-51-d2571e8b-d388-4649-bf53-aa70f8194653/
DEBUG     2024-02-22 16:03:23  common.utils:utils:uuid_to_path:703:  path d257/1e8b/d388/4649/bf53/aa70/f819/4653
INFO      2024-02-22 16:03:23  locations.models.package:package:should_have_pointer_file:806:  Package should not have a pointer file because /var/archivematica/sharedDirectory/currentlyProcessing/TEST-TRANSFER_2024-02-22T16-00-51-d2571e8b-d388-4649-bf53-aa70f8194653/TEST-TRANSFER_2024-02-22T16-00-51-d2571e8b-d388-4649-bf53-aa70f8194653/ is not a file
DEBUG     2024-02-22 16:03:23  locations.models.space:space:posix_move:313:  posix_move: source_path: var/archivematica/sharedDirectory/currentlyProcessing/TEST-TRANSFER_2024-02-22T16-00-51-d2571e8b-d388-4649-bf53-aa70f8194653/TEST-TRANSFER_2024-02-22T16-00-51-d2571e8b-d388-4649-bf53-aa70f8194653/
DEBUG     2024-02-22 16:03:23  locations.models.space:space:posix_move:314:  posix_move: destination_path: var/archivematica/sharedDirectory/www/AIPsStore/d257/1e8b/d388/4649/bf53/aa70/f819/4653/TEST-TRANSFER_2024-02-22T16-00-51-d2571e8b-d388-4649-bf53-aa70f8194653
DEBUG     2024-02-22 16:03:23  locations.models.space:space:posix_move:315:  posix_move: destination_space.path: /
INFO      2024-02-22 16:03:23  locations.models.space:space:move_rsync:545:  Moving from /var/archivematica/sharedDirectory/currentlyProcessing/TEST-TRANSFER_2024-02-22T16-00-51-d2571e8b-d388-4649-bf53-aa70f8194653/TEST-TRANSFER_2024-02-22T16-00-51-d2571e8b-d388-4649-bf53-aa70f8194653/ to /var/archivematica/sharedDirectory/www/AIPsStore/d257/1e8b/d388/4649/bf53/aa70/f819/4653/TEST-TRANSFER_2024-02-22T16-00-51-d2571e8b-d388-4649-bf53-aa70f8194653

Steps to reproduce

1. start transfer: https://www.archivematica.org/en/docs/archivematica-1.15/dev-manual/api/api-reference-archivematica/#package
2. loop status with returned uuid: https://www.archivematica.org/en/docs/archivematica-1.15/dev-manual/api/api-reference-archivematica/#status

Your environment (version of Archivematica, operating system, other relevant details)

• Ubuntu 22.04 Server with package installation of Archivematica 1.15.1 & Storage Service 0.21.1

---

For Artefactual use:

Before you close this issue, you must check off the following:

• All pull requests related to this issue are properly linked
• All pull requests related to this issue have been merged
• A testing plan for this issue has been implemented and passed (testing plan information should be included in the issue body or comments)
• Documentation regarding this issue has been written and merged (if applicable)
• Details about this issue have been added to the release notes (if applicable)