Transfers getting "lost" in currentlyProcessing in version 1.12.1.

[Ranjit Khera]

Hi,

We've recently hit an issue where transfers are getting "lost" in currentlyProcessing.

The MCP Server log shows this:

DEBUG     2021-08-23 13:30:19  archivematica.mcp.server.packages:packages:create_package:357:  Transfer object created: f9914753-48e9-4213-a08b-eed5d278b441
DEBUG     2021-08-23 13:30:19  archivematica.mcp.server.packages:packages:create_package:363:  Package f9914753-48e9-4213-a08b-eed5d278b441: starting transfer ((u'TestG', u'standard', u'7df649da-1d7a-49f1-8912-b9dd285b6448:/var/archivematica/transfer/nextcloud/cro-transfer/dhod1/DIG 0207-25', u'/var/archivematica/sharedDirectory/tmp/tmpUB4SwW'))
DEBUG     2021-08-23 13:30:19  archivematica.mcp.server.packages:packages:_start_package_transfer_with_auto_approval:425:  Package f9914753-48e9-4213-a08b-eed5d278b441: determined vars transfer_rel=tmp/tmpUB4SwW/TestG, filepath=/var/archivematica/sharedDirectory/tmp/tmpUB4SwW/TestG, path=7df649da-1d7a-49f1-8912-b9dd285b6448:/var/archivematica/transfer/nextcloud/cro-transfer/dhod1/DIG 0207-25/.
DEBUG     2021-08-23 13:30:19  archivematica.mcp.server.packages:packages:_start_package_transfer_with_auto_approval:432:  Package f9914753-48e9-4213-a08b-eed5d278b441: copying chosen contents from transfer sources (from=7df649da-1d7a-49f1-8912-b9dd285b6448:/var/archivematica/transfer/nextcloud/cro-transfer/dhod1/DIG 0207-25/., to=tmp/tmpUB4SwW/TestG)
DEBUG     2021-08-23 13:30:19  archivematica.common:storageService:get_location:199:  Storage locations returned: [{u'uuid': u'7a6afc46-0fa3-422b-a8be-de39cd2af195', u'pipeline': [u'/api/v2/pipeline/c60212a8-328f-4848-b07d-4f366afb61c9/'], u'used': 0, u'description': None, u'space': u'/api/v2/space/3db54a43-e054-4458-8739-fec4509f678f/', u'enabled': True, u'quota': None, u'relative_path': u'var/archivematica/sharedDirectory/', u'purpose': u'CP', u'path': u'/var/archivematica/sharedDirectory', u'resource_uri': u'/api/v2/location/7a6afc46-0fa3-422b-a8be-de39cd2af195/'}]
DEBUG     2021-08-23 13:30:19  archivematica.common:storageService:get_location:199:  Storage locations returned: [{u'uuid': u'7df649da-1d7a-49f1-8912-b9dd285b6448', u'pipeline': [u'/api/v2/pipeline/c60212a8-328f-4848-b07d-4f366afb61c9/'], u'used': 0, u'description': u'cro-upload.in.wcc', u'space': u'/api/v2/space/3db54a43-e054-4458-8739-fec4509f678f/', u'enabled': True, u'quota': None, u'relative_path': u'/var/archivematica/transfer/nextcloud/cro-transfer', u'purpose': u'TS', u'path': u'/var/archivematica/transfer/nextcloud/cro-transfer', u'resource_uri': u'/api/v2/location/7df649da-1d7a-49f1-8912-b9dd285b6448/'}]
DEBUG     2021-08-23 13:30:19  archivematica.mcp.server.packages:packages:_copy_from_transfer_sources:255:  source: dhod1/DIG 0207-25/., destination: /var/archivematica/sharedDirectory/tmp/tmpUB4SwW/TestG/.
DEBUG     2021-08-23 13:30:55  archivematica.mcp.server.packages:packages:_start_package_transfer_with_auto_approval:436:  Package f9914753-48e9-4213-a08b-eed5d278b441: moving package to processing directory
DEBUG     2021-08-23 13:30:55  archivematica.mcp.server.packages:packages:_start_package_transfer_with_auto_approval:441:  Package f9914753-48e9-4213-a08b-eed5d278b441: starting workflow processing
DEBUG     2021-08-23 13:30:55  archivematica.mcp.server.jobs.chain:chain:__init__:101:  Creating JobChain 6953950b-c101-4f4c-a0c3-0cd0684afe5e for package f9914753-48e9-4213-a08b-eed5d278b441 (initial link 045c43ae-d6cf-44f7-97d6-c8a602748565)

This is what's in the Storage Service log:

DEBUG     2021-08-23 14:30:19  locations.api.resources:resources:_move_files_between_locations:480:  Moving files from this location is not allowed
DEBUG     2021-08-23 14:30:19  locations.models.space:space:move_to_storage_service:344:  TO: src: /var/archivematica/transfer/nextcloud/cro-transfer/dhod1/DIG 0207-25/.
DEBUG     2021-08-23 14:30:19  locations.models.space:space:move_to_storage_service:345:  TO: dst: /var/archivematica/sharedDirectory/tmp/tmpUB4SwW/TestG/.
DEBUG     2021-08-23 14:30:19  locations.models.space:space:move_to_storage_service:346:  TO: staging: /var/archivematica/storage_service
INFO      2021-08-23 14:30:19  locations.models.space:space:move_rsync:550:  Moving from /var/archivematica/transfer/nextcloud/cro-transfer/dhod1/DIG 0207-25/. to /var/archivematica/storage_service/var/archivematica/sharedDirectory/tmp/tmpUB4SwW/TestG/.
INFO      2021-08-23 14:30:19  locations.models.space:space:move_rsync:592:  rsync command: ['rsync', '-t', '-O', '--protect-args', '-vv', '--chmod=Fug+rw,o-rwx,Dug+rwx,o-rwx', '-r', '/var/archivematica/transfer/nextcloud/cro-transfer/dhod1/DIG 0207-25/.', '/var/archivem
atica/storage_service/var/archivematica/sharedDirectory/tmp/tmpUB4SwW/TestG/.']
DEBUG     2021-08-23 14:30:21  locations.models.async_manager:async_manager:_watchdog_loop:123:  Watchdog sees 0 tasks running
DEBUG     2021-08-23 14:30:26  locations.models.async_manager:async_manager:_watchdog_loop:123:  Watchdog sees 0 tasks running
DEBUG     2021-08-23 14:30:31  locations.models.async_manager:async_manager:_watchdog_loop:123:  Watchdog sees 0 tasks running
DEBUG     2021-08-23 14:30:36  locations.models.async_manager:async_manager:_watchdog_loop:123:  Watchdog sees 0 tasks running
DEBUG     2021-08-23 14:30:41  locations.models.async_manager:async_manager:_watchdog_loop:123:  Watchdog sees 0 tasks running
DEBUG     2021-08-23 14:30:46  locations.models.async_manager:async_manager:_watchdog_loop:123:  Watchdog sees 0 tasks running
DEBUG     2021-08-23 14:30:51  locations.models.async_manager:async_manager:_watchdog_loop:123:  Watchdog sees 0 tasks running
DEBUG     2021-08-23 14:30:55  locations.models.space:space:move_from_storage_service:421:  FROM: src: /var/archivematica/sharedDirectory/tmp/tmpUB4SwW/TestG/.
DEBUG     2021-08-23 14:30:55  locations.models.space:space:move_from_storage_service:422:  FROM: dst: /var/archivematica/sharedDirectory/tmp/tmpUB4SwW/TestG/.
INFO      2021-08-23 14:30:55  locations.models.space:space:move_rsync:550:  Moving from /var/archivematica/storage_service/var/archivematica/sharedDirectory/tmp/tmpUB4SwW/TestG/./ to /var/archivematica/sharedDirectory/tmp/tmpUB4SwW/TestG/.
DEBUG     2021-08-23 14:30:55  locations.models.space:space:move_rsync:564:  os.rename failed, trying with normalized paths

There are no log messages for this process in the MCP Client log.

I can see a entry in the MCP database for it:

MariaDB [MCP]> select * from Transfers where transferUUID='f9914753-48e9-4213-a08b-eed5d278b441';
+--------------------------------------+---------------------------------------+------+-------------+---------------------+----------------+-------------+-------+--------+----------------------------+----------+------------------+
| transferUUID                         | currentLocation                       | type | accessionID | sourceOfAcquisition | typeOfTransfer | description | notes | hidden | transferMetadataSetRowUUID | dirUUIDs | access_system_id |
+--------------------------------------+---------------------------------------+------+-------------+---------------------+----------------+-------------+-------+--------+----------------------------+----------+------------------+
| f9914753-48e9-4213-a08b-eed5d278b441 | %sharedPath%currentlyProcessing/TestG |      |             |                     |                |             |       |      0 | NULL                       |        0 |                  |
+--------------------------------------+---------------------------------------+------+-------------+---------------------+----------------+-------------+-------+--------+----------------------------+----------+------------------+
1 row in set (0.00 sec)

But it doesn't show up in any of the tabs on the web interface.

How do I fix this? Or where can I get more info (or increase logging) to diagnose this?

We are running Archivematica 1.12.1 on RHEL 7.

Thanks for the help.

Ranjit.

[John Gostick]

Hi Ranjit,

Did you manage to resolve this? I am seeing the same symptoms at the moment and cannot figure out how to get Transfers going again...

Thanks

John

[Jonny]

Hi,

I've just picked up this problem was Ranjit, as he's left but we're still getting the exact same problem with 1.13.2. We also have another server setup as our test environment which doesn't have this problem, but we're not sure what's different between them or where to look.

@jag...@cam.ac.uk, did you ever get yours working and if so, how did you go about it?

[Jonny]

Anyone able to help here?