S3 sync tasks hang when destination sub-collections do not exist

[alanking]

When scanning an S3 bucket, sync jobs hang when the target collection does not exist and is a sub-collection of another collection which does not exist. If the job is stopped, the collection is created (and attendant parent collections), and then the job is restarted, the scan will complete as expected.

Example: If the destination collection is /tempZone/home/rods/a/b/c and /tempZone/home/rods/a does not exist, the object with destination logical path /tempZone/home/rods/a/b/c/foo.txt will generate a sync task and the task will hang indefinitely.

[alanking]

We can't really add a test for this without #132 but I feel like this may be fixed...

[trel]

Can we test it manually?

Doesn't seem to have anything to really set up first?

[alanking]

A manual test is good enough to close this as well, I think.

[trel]

good good.

[alanking]

I am able to reproduce this with the changes in #267. Here's what I did...

I have a bucket in Minio called ingest-test-bucket. There is an object in this bucket at path /ingest-test-bucket/a/b/c/me.jpg. I will attempt to sync the /ingest-test-bucket/a/ folder to my iRODS collection /tempZone/home/rods/ingest-test-bucket/a/b/c. /tempZone/home/rods/ingest-test-bucket collection exists, but /tempZone/home/rods/ingest-test-bucket/a does not exist (and clearly neither /tempZone/home/rods/ingest-test-bucket/a/b nor /tempZone/home/rods/ingest-test-bucket/a/b/c exist).

Here's the command I ran:

python3 -m irods_capability_automated_ingest.irods_sync start \
    /ingest-test-bucket/a/ \
    /tempZone/home/rods/ingest-test-bucket/a/b/c \
    --s3_keypair /s3_keypair \
    --s3_endpoint_domain minio:19000 \
    --s3_insecure_connection \
    --synchronous --progress --log_level INFO

I realize that sync'ing the a folder to a/b/c sub-collection is confusing, but if you ignore the names, it could be a legitimate use case. In any case, we should either create the intermediate collections, or fail. The current behavior is that the task hangs forever. Here's the last thing that I see from Celery before it hangs forever:

[2024-09-12 17:53:58,567: WARNING/ForkPoolWorker-2] {"event": "synchronizing file. path = a/b/c/me.jpg", "logger": "irods_sync//INFO", "level": "info", "@timestamp": "2024-09-12T17:53:58.567259+00:00"}
[2024-09-12 17:53:58,568: INFO/ForkPoolWorker-2] Acquired Lock('lock:sync_file:a/b/c/me.jpg:/tempZone/home/rods/ingest-test-bucket/a/b/c').
[2024-09-12 17:53:58,568: WARNING/ForkPoolWorker-2] {"path": "a/b/c/me.jpg", "t0": null, "t": 1726163638.568265, "ctime": 1726163576.294, "event": "synchronizing file", "logger": "irods_sync//INFO", "level": "info", "@timestamp": "2024-09-12T17:53:58.568299+00:00"}
[2024-09-12 17:53:58,569: WARNING/ForkPoolWorker-2] {"event": "iRODS Idle Time set to: 60", "logger": "irods_sync//INFO", "level": "info", "@timestamp": "2024-09-12T17:53:58.569095+00:00"}
[2024-09-12 17:53:58,672: INFO/ForkPoolWorker-2] Acquired Lock('lock:create_dirs:a/b/c').
[2024-09-12 17:53:58,678: INFO/ForkPoolWorker-2] Acquired Lock('lock:create_dirs:a/b').
[2024-09-12 17:53:58,684: INFO/ForkPoolWorker-2] Acquired Lock('lock:create_dirs:a').
[2024-09-12 17:53:58,690: INFO/ForkPoolWorker-2] Acquired Lock('lock:create_dirs:').

It's getting stuck on the recursive call in create_dirs:

irods_capability_automated_ingest/irods_capability_automated_ingest/sync_irods.py

Lines 46 to 73 in dfbe556

	def create_dirs(logger, session, meta, **options):
	target = meta["target"]
	path = meta["path"]
	config = meta["config"]
	event_handler = custom_event_handler(meta)
	if target.startswith("/"):
	r = get_redis(config)
	if not session.collections.exists(target):
	with redis_lock.Lock(r, "create_dirs:" + path):
	if not session.collections.exists(target):
	meta2 = meta.copy()
	meta2["target"] = dirname(target)
	meta2["path"] = dirname(path)
	create_dirs(logger, session, meta2, **options)
	event_handler.call(
	"on_coll_create",
	logger,
	create_dir,
	logger,
	session,
	meta,
	**options,
	)
	else:
	raise Exception(
	"create_dirs: relative path; target:[" + target + "]; path:[" + path + "]"
	)

Might be an accidental deadlock as well. In any case, something is wrong with how this function is handling S3 paths.

[trel]

I think I follow.... perhaps trying to sync /ingest-test-bucket/a/ into /tempZone/home/rods/ingest-test-bucket/x/y/z would prove clearer. Just a suggestion.

Why does it have to be a recursive call? Can't we just mkdir -p it once and move on? Perhaps because of policy, we wanted to hit each level on the way up?

Hmm.

[trel]

Perhaps more importantly... note the last Lock...

[2024-09-12 17:53:58,690: INFO/ForkPoolWorker-2] Acquired Lock('lock:create_dirs:').

Seems there is nothing after that colon on the end... did we go too far?

[korydraughn]

Who is managing the locks?
Is that the ingest tool or celery?

[alanking]

Why does it have to be a recursive call? Can't we just mkdir -p it once and move on? Perhaps because of policy, we wanted to hit each level on the way up?

Hmm.

I think this is why it's done this way, yes.

Perhaps more importantly... note the last Lock...

[2024-09-12 17:53:58,690: INFO/ForkPoolWorker-2] Acquired Lock('lock:create_dirs:').

Seems there is nothing after that colon on the end... did we go too far?

I think that it went too far and that is the crux of this issue.

Who is managing the locks? Is that the ingest tool or celery?

The ingest tool is managing the locks. The code linked above is part of the "iRODS side" of a sync_file task. Notice the call to redis_lock.Lock.

We are syncing the file /ingest-test-bucket/a/b/c/me.jpg to /tempZone/home/rods/ingest-test-bucket/a/b/c BUT the path seems to be... incomplete. The bucket name has been chopped off the front, making the path appear to be non-absolute (or at least not "normalized").

[korydraughn]

Ah, I see what you mean now.

The loss of the leading forward slash does look related. Do successful runs show a leading forward slash on the paths?

[alanking]

When syncing a filesystem in this manner, the lock uses a path which starts with a forward slash, yeah. And no deadlock problems like this for syncing filesystems.

[alanking]

I was able to reproduce this with a filesystem sync as well with a very simple directory structure.

python3 -m irods_capability_automated_ingest.irods_sync start \
    /data/ufs/dir0 \
    /tempZone/home/rods/a/b/c/d/e/f/g/h/i

Here's the lock acquisition output

[2024-10-02 19:35:19,419: INFO/ForkPoolWorker-1] Acquired Lock('lock:create_dirs:/data/ufs/dir0').
[2024-10-02 19:35:19,425: INFO/ForkPoolWorker-1] Acquired Lock('lock:create_dirs:/data/ufs').
[2024-10-02 19:35:19,431: INFO/ForkPoolWorker-1] Acquired Lock('lock:create_dirs:/data').
[2024-10-02 19:35:19,437: INFO/ForkPoolWorker-1] Acquired Lock('lock:create_dirs:/').

It has to do with the fact that the destination collection has more elements in its path than the source path.

Here's kind of what's happening...

create_dirs sees that /tempZone/home/rods/a/b/c/d/e/f/g/h/i does not exist, so it acquires the lock using the source path /data/ufs/dir0 as a key, and then ascends one subcollection to see whether it needs to create the parent. It does this until it reaches a collection which exists (in this case, /tempZone/home/rods), and this is the base case.

So here's how it shakes out...

Iteration 0:
source (lock key): /data/ufs/dir0
destination (does not exist): /tempZone/home/rods/a/b/c/d/e/f/g/h/i

Iteration 1:
source (lock key): /data/ufs
destination (does not exist): /tempZone/home/rods/a/b/c/d/e/f/g/h

Iteration 2:
source (lock key): /data
destination (does not exist): /tempZone/home/rods/a/b/c/d/e/f/g

Iteration 3:
source (lock key): /
destination (does not exist): /tempZone/home/rods/a/b/c/d/e/f

Iteration 4:
source (lock key - already acquired): /
destination (does not exist): /tempZone/home/rods/a/b/c/d/e

On iteration 4 it gets stuck. I'm not sure why this isn't raising a redis_lock.AlreadyAcquired (https://python-redis-lock.readthedocs.io/en/latest/reference/redis_lock.html#redis_lock.AlreadyAcquired) because there is only one worker in this case.

So the question on my mind is... why are we using "path" (the source directory path) as the key rather than "target" (the destination collection path)? The "path" isn't even really a factor. I tried using the "target" as the key for the redis_lock and it seems to fix the problem.

[trel]

Good sleuthing.

Agreed, we should iterate using the thing we're iterating through. Can't think of a downside... unless there is some coordination with other parts of the system that are assuming the 'source' information is the key...

And it's always been this way?

[alanking]

The "path" has been the string used for the for the redis_lock key ever since the lock was introduced.

[trel]

Okay - so just an incorrect/insufficient implementation. Carry on.