problem: when ingesting DSpace files sometimes transfers fail to approve ("Unable to find unapproved transfer directory.")

[hakamine]

Sometimes automation tools fail to approve transfers, requiring manual intervention (i.e., approve manually in the dashboard). Log shows:

...
INFO      2017-09-06 21:05:01  transfer.py:388  Ready to start
INFO      2017-09-06 21:05:01  transfer.py:414  Approving ITEM@2429-19448.zip
INFO      2017-09-06 21:05:07  transfer.py:398  Failed approve, try 1 of 3
INFO      2017-09-06 21:05:07  transfer.py:414  Approving ITEM@2429-19448.zip
INFO      2017-09-06 21:05:13  transfer.py:398  Failed approve, try 2 of 3
INFO      2017-09-06 21:05:13  transfer.py:414  Approving ITEM@2429-19448.zip
INFO      2017-09-06 21:05:19  transfer.py:398  Failed approve, try 3 of 3
WARNING   2017-09-06 21:05:19  transfer.py:400  Not approved
...

When this happens, the corresponding database entry does not update (running the automated transfer script again does not update it), so for the package that needed to be manually approved and had the ingest completed, unit_type is "transfer" and status remains blank, also uuid is blank :

$ sqlite3 /var/archivematica/automation-tools/transfers.db "select * from unit order by id DESC limit 3;"
33150||ITEM@2429-19448.zip|transfer|||0|2017-09-06 21:05:19.837795
33149|c35028bf-a2e8-47a7-8049-20dea6fa44ad|ITEM@2429-19445.zip|ingest|COMPLETE||0|2017-09-06 20:35:07.745142
33148|62ba497b-14c7-4114-b1ff-124eb550e02f|ITEM@2429-1936.zip|ingest|COMPLETE||0|2017-09-06 20:05:08.633923

It is not clear how to be able to reproduce this problem. (Error above occurred in the dev/dspace branch)

[hakamine]

Log with extra info:

...
INFO      2017-09-13 16:05:23  transfer.py:388  Ready to start
INFO      2017-09-13 16:05:23  transfer.py:414  Approving ITEM@2429-24573.zip
INFO      2017-09-13 16:05:29  transfer.py:424  Found waiting transfer: ITEM@2429-24573.zip
INFO      2017-09-13 16:05:29  transfer.py:429  URL: http://127.0.0.1/api/transfer/approve/; Params: {u'username': 'autob
ot', u'directory': 'ITEM@2429-24573.zip', u'api_key': '<api-key>', u'type': u'dspace'};
INFO      2017-09-13 16:05:29  transfer.py:431  Response: <Response [500]>
INFO      2017-09-13 16:05:29  transfer.py:432  Response text: {"message": "Unable to find unapproved transfer directory.
", "error": true}
INFO      2017-09-13 16:05:29  transfer.py:398  Failed approve, try 1 of 3
INFO      2017-09-13 16:05:29  transfer.py:414  Approving ITEM@2429-24573.zip
INFO      2017-09-13 16:05:35  transfer.py:424  Found waiting transfer: ITEM@2429-24573.zip
INFO      2017-09-13 16:05:35  transfer.py:429  URL: http://127.0.0.1/api/transfer/approve/; Params: {u'username': 'autobot', u'directory': 'ITEM@2429-24573.zip', u'api_key': '<api-key>', u'type': u'dspace'};
INFO      2017-09-13 16:05:35  transfer.py:431  Response: <Response [500]>
INFO      2017-09-13 16:05:35  transfer.py:432  Response text: {"message": "Unable to find unapproved transfer directory.", "error": true}
INFO      2017-09-13 16:05:35  transfer.py:398  Failed approve, try 2 of 3
INFO      2017-09-13 16:05:35  transfer.py:414  Approving ITEM@2429-24573.zip
INFO      2017-09-13 16:05:41  transfer.py:424  Found waiting transfer: ITEM@2429-24573.zip
INFO      2017-09-13 16:05:41  transfer.py:429  URL: http://127.0.0.1/api/transfer/approve/; Params: {u'username': 'autobot', u'directory': 'ITEM@2429-24573.zip', u'api_key': '<api-key>', u'type': u'dspace'};
INFO      2017-09-13 16:05:42  transfer.py:431  Response: <Response [500]>
INFO      2017-09-13 16:05:42  transfer.py:432  Response text: {"message": "Unable to find unapproved transfer directory.", "error": true}
INFO      2017-09-13 16:05:42  transfer.py:398  Failed approve, try 3 of 3
WARNING   2017-09-13 16:05:42  transfer.py:400  Not approved
...

[hakamine]

The API error "Unable to find unapproved transfer directory" comes from this code block: https://github.com/artefactual/archivematica/blob/stable/1.6.x/src/dashboard/src/components/api/views.py#L442-L474 . It looks for the corresponding job using the following ORM query:

job = models.Job.objects.filter(directory=db_transfer_path, currentstep='Awaiting decision')[0]

but this query failed producing an exception.

For some reason job.directory is sometimes missing the ending slash, and when this happens the query fails.

For example in this case:

>>> from main import models
>>> job = models.Job.objects.filter(currentstep='Awaiting decision')[0]
>>> job.sipuuid
u'cd4833aa-fb38-4d80-be94-b0a8abdaafb1'
>>> job.directory
u'%sharedPath%watchedDirectories/activeTransfers/Dspace/ITEM@2429-24573.zip'

When trying to approve the transfer (using curl), got the same error:

curl -v --data "username=autobot&api_key=<api-key>&type=dspace&directory=ITEM@2429-24573.zip"  "http://127.0.0.1/api/transfer/approve/"
...
{"message": "Unable to find unapproved transfer directory.", "error": true}

Tried adding the missing slash:

>>> job.directory
u'%sharedPath%watchedDirectories/activeTransfers/Dspace/ITEM@2429-24573.zip'
>>> job.directory = u'%sharedPath%watchedDirectories/activeTransfers/Dspace/ITEM@2429-24573.zip/'
>>> job.directory
u'%sharedPath%watchedDirectories/activeTransfers/Dspace/ITEM@2429-24573.zip/'
>>> job.save()
>>>

After this, the transfer could be approved:

artefactual@courtenay2:~$ curl -v --data "username=autobot&api_key=<api-key>&type=dspace&directory=ITEM@2429-24573.zip"  "http://127.0.0.1/api/transfer/approve/"
...
{"message": "Approval successful.", "uuid": "cd4833aa-fb38-4d80-be94-b0a8abdaafb1"}

The problem does not happen with every transfer stated by the automation tools instance, but only sporadically, which makes it harder to troubleshoot.

[hakamine]

This problem was caused by the 00_file_to_folder.py pre-transfer script, that copies the zip file to a directory of the same name before approving the transfer (i.e., transfer is "started" as a file but then it is converted to a directory before the automation tools tries to "approve" it). Copying the zip file to a directory in advance of running the automation script, and removing the 00_file_to_folder.py script from the pre-transfers directory, prevents the problem to happen.

[hakamine]

I found a way to reproduce this problem, and now can confirm that the problem is caused by the 00_file_to_folder.py pre-transfer script. What happens is roughly as follows:

1. The automation tools transfers.py script does a start_transfer API call to the Archivematica dashboard
2. The Archivematica dashboard copies the transfer source to a watched directory
3. After the dashboard copies the source to a watched directory and returns the API call to the transfers.py script, the following two things happen, and the order in which they do will determine if the transfer can be approved or not: 3a. The automation tools' transfers.py script executes the 00_file_to_folder.py pre-transfer script (moving the DSpace .zip file in the watched directory to a subdirectory of the same name) 3b. The MCP Server finds the transfer source in the watched directory, creating a unit and job chain to process it

If 3a. occurs before than 3b. then the transfer can be approved without failure If 3b. occurs before than 3a. then the problem occurs (the transfer will fail to approve), the reason being that the parameter containing the path information in the job object no longer matches the actual path of the DSpace file in the watched directory (because it was moved by the 00_file_to_folder script)

The 00_file_to_folder.py pre-transfer script is a "hack" used to allow other transformation scripts to run, which require transfer sources to be inside a directory. However as explained above, the execution order that it needs to work can't be guaranteed.

Work around:

• Before running the automation tools transfer.py script, copy the DSpace .zip file inside a directory in the transfer source location
• Remove the 00_file_to_folder.py pre-transfer script

[ross-spencer]

Moving to: archivematica/issues#361