Device or resource busy error in transfer?

[Buddha Buck]

Hi,

I'm running Archivematica 1.6.1/Storage Service 0.10.1 on a CentOS server, recently upgraded from 1.6.0/0.10.0. We are currently testing and evaluating Archivematica.

Since the upgrade, I have been unable to start a transfer successfully. 

Looking at the /var/log/archivematica/storage-service/storage_service_debug.log file, I see (for my most recent failed transfer) the following:

DEBUG     2017-08-22 12:36:58  locations.models.space:space:move_to_storage_service:264:  TO: src: transfer_source/2017-05-18_02/.
DEBUG     2017-08-22 12:36:58  locations.models.space:space:move_to_storage_service:265:  TO: dst: /var/archivematica/sharedDirectory/tmp/tmpqG9KN8/bb-5/.
DEBUG     2017-08-22 12:36:58  locations.models.space:space:move_to_storage_service:266:  TO: staging: /var/archivematica/storage_service
INFO      2017-08-22 12:36:58  locations.models.space:space:move_rsync:421:  Moving from /home/bb233/s3mountpoint/transfer_source/2017-05-18_02/. to /var/archivematica/storage_service/var/archivematica/sharedDirectory/tmp/tmpqG9KN8/bb-5/.
INFO      2017-08-22 12:36:58  locations.models.space:space:move_rsync:449:  rsync command: ['rsync', '-t', '-O', '--protect-args', '-vv', '--chmod=ugo+rw', '-r', '/home/bb233/s3mountpoint/transfer_source/2017-05-18_02/.', '/var/archivematica/storage_service/var/archivematica/sharedDirectory/tmp/tmpqG9KN8/bb-5/.']
DEBUG     2017-08-22 12:36:58  locations.models.space:space:move_from_storage_service:333:  FROM: src: /var/archivematica/sharedDirectory/tmp/tmpqG9KN8/bb-5/.
DEBUG     2017-08-22 12:36:58  locations.models.space:space:move_from_storage_service:334:  FROM: dst: /var/archivematica/sharedDirectory/tmp/tmpqG9KN8/bb-5/.
INFO      2017-08-22 12:36:58  locations.models.space:space:move_rsync:421:  Moving from /var/archivematica/storage_service/var/archivematica/sharedDirectory/tmp/tmpqG9KN8/bb-5/./ to /var/archivematica/sharedDirectory/tmp/tmpqG9KN8/bb-5/.
DEBUG     2017-08-22 12:36:58  locations.models.space:space:move_rsync:435:  os.rename failed, trying with normalized paths
Traceback (most recent call last):
  File "/usr/share/archivematica/storage-service/locations/models/space.py", line 430, in move_rsync
    os.rename(source, destination)
OSError: [Errno 16] Device or resource busy

The same type of error sequence happens with other attempted transfers.

I tried looking at the code in space.py around where the reported errors is, but it doesn't look offhand like it should throw an OSError (it appears to catch OSErrors, actually). With the extremely short traceback in the logs, I can't tell where it's being called from.

Just now, I looked at the initial transfer to .../tmp/tmpqG9KN8/bb-5/. and I found that the bb-5 directory didn't exist. I tried the rsync command by hand, and it failed because of the missing bb-5 directory. I created the directory and the rsync-by-hand worked. Unfortunately, I know that if I try another transfer, it'll create a new temp directory.

Does anyone have any suggestions what I should try next?

Thanks,

  Buddha

[Justin Simpson]

Do you know what the filesystems are for the two locations (the transfer source location and the shared Directory)?

The os error is coming from the operating system, when the Storage Service is trying to run the rsync command to move from one to the other.  

You could try looking at your syslog and seeing if there are errors related to one of the mount points.  I am guessing that one of those filesystems is a CIFS share.  You could try unmounting and remounting the remote filesystem and see if the errors go away.

Justin Simpson
Director of Archivematica Technical Services
www.artefactual.com
604-527-2056

--
You received this message because you are subscribed to the Google Groups "Archivematica Tech" group.
To unsubscribe from this group and stop receiving emails from it, send an email to archivematica-tech+unsub...@googlegroups.com.
To post to this group, send email to archivematica-tech@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/archivematica-tech/527588d1-6490-4a7d-8675-3dfc878177bf%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Buddha Buck]

On Tuesday, August 22, 2017 at 4:45:16 PM UTC-4, Justin Simpson wrote:

Do you know what the filesystems are for the two locations (the transfer source location and the shared Directory)?

The transfer source is an s3fs-mounted S3 bucket. The shared directory is on root.

 

The os error is coming from the operating system, when the Storage Service is trying to run the rsync command to move from one to the other.  

The rsync command is trying to move the file from the S3 bucket to .../sharedDirectory/tmp/tmpqG9KN8/bb-5/. 

The directory .../sharedDirectory/tmpqG9KN8 exists, but .../sharedDirectory/tmp/tmpqG9KN8/bb-5 does not. 

When I run the rsync command at the command line (as " rsync -t -O --protect-args -vv --chmod=ugo+rw -r /home/bb233/s3mountpoint/transfer_source/2017-05-18_02/. /var/archivematica/storage_service/var/archivematica/sharedDirectory/tmp/tmpqG9KN8/bb-5/.") it fails because  the .../bb-5 directory does not exist.

When I create the .../bb-5 directory and rerun the rsync command at the command line, the rsync command succeeds.

The logs suggest that Archivematica is failing not when copying from the transfer source, but when trying to copy from the temp directory. 

I can read from the transfer source fine.

[Justin Simpson]

Thanks, I see a bit better now.  The transfer source location is in the default 'local filesystem' Space (in the storage service) - it looks like part of the root filesystem to Archivematica, it happens to be using s3fs to mount an s3 bucket, is that correct?

Can you look at /var/log/archivematica/sharedDirectory/watchedDirectories/activeTransfers/standardTransfer/ and see if your content made it there?

If you have a new folder in the standardTransfers/ folder, then you might just need to restart gearman.

Can you verify that the gearman-job-server is running?  

sudo service gearman-job-server status

The basic process that is going on here is this:

1) folders in sharedDirectory/watchedDirectories are listed in the watchedDirectories table in the mysql database.  

2) The mcp-server monitors those folders and when new content shows up, it starts a new workflow, and sends a job to gearman

3) gearman  distributes jobs to mcp-client workers.  

4) When the job requires user input (e.g. 'approve transfer'), gearman doesn't send any jobs to mcp client workers, it waits for input from the dashboard

5) The dashboard gets a list of jobs that are waiting for user input by querying

gearman, and displays them in the ui (you get the drop down beside the 'approve tranfser' job)

6) a user can provide input, via the gui, or via the dashboard api (approve_transfer endpoint)

7) gearman sends the next job to mcp client scripts, processing continues.

I think it is possible that your transfer made it to the watched directory, but the services didn't restart properly for some reason after upgrading.

If you restart gearman and then the services that depend on it, do your test transfers show up in the dashboard?

sudo service gearman-job-server restart

sudo service archivematica-mcp-server restart

sudo service archivematica-mcp-client restart

sudo service archivematica-dashboard restart

If your content is not getting to the watched directory, then this will not help.

I am able to replicate the log entries you are showing with a quick test on what I think it is a similar set up.  I see the same OSError [16] in the debug log. However, the transfer is getting copied to the sharedDirectory, from the temp directory, and showing up in the dashboard, I can click to 'accept transfer'.

The line of code that is logging the OS error is here:

https://github.com/artefactual/archivematica-storage-service/blob/stable/0.10.x/storage_service/locations/models/space.py#L439

You were looking around here already, as you pointed out, this is not throwing an OSError, it is catching one.

The code in this Try block is using os.rename() as the equivalent of a 'mv' command - if the source and destination are on the same filesystem, it should be faster to do a 'mv', instead of rsync.  The OSError is getting caught, and logged, and then the code should fallback to using rsync, and the content should get into the sharedDirectory.

In my test just now, that is happening for me.  Here is the relevant part of the storage service debug log. it looks exactly the same as your:

DEBUG     2017-08-23 08:36:37  locations.models.space:space:move_to_storage_service:264:  TO: src: home/artefactual/archivematica-sampledata/SampleTransfers/Images/pictures/.

DEBUG     2017-08-23 08:36:37  locations.models.space:space:move_to_storage_service:265:  TO: dst: /var/archivematica/sharedDirectory/tmp/tmpeJGwSW/temp2/.

DEBUG     2017-08-23 08:36:37  locations.models.space:space:move_to_storage_service:266:  TO: staging: /var/archivematica/storage_service

INFO      2017-08-23 08:36:37  locations.models.space:space:move_rsync:421:  Moving from /home/artefactual/archivematica-sampledata/SampleTransfers/Images/pictures/. to /var/archivematica/storage_service/var/archivematica/sharedDirectory/tmp/tmpeJGwSW/temp2/.

INFO      2017-08-23 08:36:37  locations.models.space:space:move_rsync:449:  rsync command: ['rsync', '-t', '-O', '--protect-args', '-vv', '--chmod=ugo+rw', '-r', '/home/artefactual/archivematica-sampledata/SampleTransfers/Images/pictures/.', '/var/archivematica/storage_service/var/archivematica/sharedDirectory/tmp/tmpeJGwSW/temp2/.']

DEBUG     2017-08-23 08:36:37  locations.models.space:space:move_from_storage_service:333:  FROM: src: /var/archivematica/sharedDirectory/tmp/tmpeJGwSW/temp2/.

DEBUG     2017-08-23 08:36:37  locations.models.space:space:move_from_storage_service:334:  FROM: dst: /var/archivematica/sharedDirectory/tmp/tmpeJGwSW/temp2/.

INFO      2017-08-23 08:36:37  locations.models.space:space:move_rsync:421:  Moving from /var/archivematica/storage_service/var/archivematica/sharedDirectory/tmp/tmpeJGwSW/temp2/./ to /var/archivematica/sharedDirectory/tmp/tmpeJGwSW/temp2/.

DEBUG     2017-08-23 08:36:37  locations.models.space:space:move_rsync:435:  os.rename failed, trying with normalized paths

Traceback (most recent call last):

  File "/usr/lib/archivematica/storage-service/locations/models/space.py", line 430, in move_rsync

    os.rename(source, destination)

OSError: [Errno 16] Device or resource busy

There was never an 'errno 16' error with 1.6.0, so something has changed, but it should not be affecting your ability to start transfers.

It is worth looking into what is causing this error more. I can work around it by commenting out the 2 Try blocks in that part of the code (just use rsync, don't try 'mv').  This stops the error from being reported in the log.  For me, the end result is the same, in both cases the transfer can be approved.

Hope that helps, curious to hear your feedback.

Justin Simpson
Director of Archivematica Technical Services
www.artefactual.com
604-527-2056

--
You received this message because you are subscribed to the Google Groups "Archivematica Tech" group.
To unsubscribe from this group and stop receiving emails from it, send an email to archivematica-tech+unsub...@googlegroups.com.
To post to this group, send email to archivematica-tech@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msgid/archivematica-tech/3ccbd7cf-8410-4447-9a59-c15bb9fd9cf0%40googlegroups.com.

[Buddha Buck]

On Wednesday, August 23, 2017 at 12:08:02 PM UTC-4, Justin Simpson wrote:

Thanks, I see a bit better now.  The transfer source location is in the default 'local filesystem' Space (in the storage service) - it looks like part of the root filesystem to Archivematica, it happens to be using s3fs to mount an s3 bucket, is that correct?

Yes.

 

Can you look at /var/log/archivematica/sharedDirectory/watchedDirectories/activeTransfers/standardTransfer/ and see if your content made it there?

It's there.

 

If you have a new folder in the standardTransfers/ folder, then you might just need to restart gearman.

Can you verify that the gearman-job-server is running?  

sudo service gearman-job-server status

I'm using CentOS, so it's "sudo systemctl status gearmand", and it claims to be running.

 

The basic process that is going on here is this:

1) folders in sharedDirectory/watchedDirectories are listed in the watchedDirectories table in the mysql database.  

2) The mcp-server monitors those folders and when new content shows up, it starts a new workflow, and sends a job to gearman

3) gearman  distributes jobs to mcp-client workers.  

4) When the job requires user input (e.g. 'approve transfer'), gearman doesn't send any jobs to mcp client workers, it waits for input from the dashboard

5) The dashboard gets a list of jobs that are waiting for user input by querying

gearman, and displays them in the ui (you get the drop down beside the 'approve tranfser' job)

6) a user can provide input, via the gui, or via the dashboard api (approve_transfer endpoint)

7) gearman sends the next job to mcp client scripts, processing continues.

Thanks for the detailed description. That helps my understanding of what the process is.

 

I think it is possible that your transfer made it to the watched directory, but the services didn't restart properly for some reason after upgrading.

If you restart gearman and then the services that depend on it, do your test transfers show up in the dashboard?

sudo service gearman-job-server restart

sudo service archivematica-mcp-server restart

sudo service archivematica-mcp-client restart

sudo service archivematica-dashboard restart

I now have 19 new transfers awaiting approval. Did I mention that I tried several approaches before asking the list?

Thank you for your help.

I had thought I tried restarting all the relevant services; I guess I missed some, or did them in the wrong order.

There was never an 'errno 16' error with 1.6.0, so something has changed, but it should not be affecting your ability to start transfers.

It doesn't appear to be, but it certainly was a red herring keeping me from looking in the right place. 

[Tiago Delboni]

Just adding some info...

We run Archivematica 1.6.0 + Storage Service 0.10.0 on CentOS and we see the message "OSError: [Errno 16] Device or resource busy" whenever we start a transfer with whitespace in "Transfer name":

DEBUG     2017-08-28 11:25:05  locations.models.space:space:move_rsync:435:  os.rename failed, trying with normalized paths

Traceback (most recent call last):
  File "/usr/share/archivematica/storage-service/locations/models/space.py", line 430, in move_rsync
    os.rename(source, destination)
OSError: [Errno 16] Device or resource busy

Looking into the code it is nothing to be worried about, as it is part of the operation's normal flow: first it tries "mv source destination". If the move fails, it prints error messages and then try to move the normalized paths.

	# Try using mv, and if that fails, fallback to rsync
	chmod_command = ['chmod', '--recursive', 'ug+rw,o+r', destination]
	try:
	os.rename(source, destination)
	# Set permissions (rsync does with --chmod=ugo+rw)
	subprocess.call(chmod_command)
	return
	except OSError:
	LOGGER.debug('os.rename failed, trying with normalized paths', exc_info=True)
	source_norm = os.path.normpath(source)
	dest_norm = os.path.normpath(destination)
	try:
	os.rename(source_norm, dest_norm)
	# Set permissions (rsync does with --chmod=ugo+rw)
	subprocess.call(chmod_command)
	return
	except OSError:
	LOGGER.debug('os.rename failed, falling back to rsync. Source: %s; Destination: %s', source_norm, dest_norm, exc_info=True)

[thomas.no...@gmail.com]

Hi.

I don't have a solution, but more information.
I have done some debugging and have found that it fails with copy and move because the destination string is faulty:

In /usr/share/python/archivematica-storage-service/lib/python2.7/site-packages/storage_service/locations/api/resources.py (line 340) 
data["files"] = [{u'source': u'2f3b2e78-bbbf-42a2-9b69-98ad60205cf6_1/.', u'destination': u'/xxxx/xxxx/sharedDirectory/tmp/tmpY0p2SB/2f3b2e78-bbbf-42a2-9b69-98ad60205cf6_1/.'}]

which makes /usr/lib/archivematica/storage-service/locations/models/space.py fail with the rsync-command: 

['rsync', '-t', '-O', '--protect-args', '-vv', '--chmod=ugo+rw', '-r', '/xxxx/xxxx/Transfer_Source/2f3b2e78-bbbf-42a2-9b69-98ad60205cf6_1/.', '/var/archivematica/storage_service/tilda_storage/am/sharedDirectory/tmp/tmpJsAV2v/2f3b2e78-bbbf-42a2-9b69-98ad60205cf6_1/.']

I ran the command in a terminal and removed /. in the end of the destination string... that worked. 

I tried to do a simple fix in /usr/lib/archivematica/storage-service/locations/models/space.py but of course I got new errors :-/ (because why should there be an easy work around)

We run Archivematica 1.6.1 on Ubuntu 16.04.3 xenial

Regards

Thomas Nording