ln -sf a b ... leaves tmp files around in mirroring use case.

[petersilva]

As discovered by client, reproduced in sarrac test cases... in an hpc mirroring configuration, when

• you have an ln -sf a b command.
• a (the thing being linked to) does not exist.
• you end up with two links in the destination... the normal one, an a second one with ln -sf temp name (typically starts with Cuxxxx)

[petersilva]

from adding an appropriate ln -sf to the mirroring tests cases in sarrac... can see this log of the python subscriber:

2025-01-08 15:40:41,187 [INFO] sarracenia.flowcb.log after_accept accepted: (lag: 0.56 ) {  '_deleteOnPost':'{'_format', 'subtopic', 'new_relPath', '_mask_index', 'new_file', 'ack_id', 'exchange', 'local_offset', 'new_subtopic', 'new_baseUrl', 'topic', '_matches', 'new_dir', 'post_fileOp', 'post_format'}', '_format':'v03', '_mask_index':'0', '_matches':'<re.Match object; span=(0, 78), match='file:/home/peter/Sarracenia/metpx-sr3c/shim_dirA/>', 'ack_id':'{  'broker':'localhost:5672//', 'channel_id':'2', 'connection_id':'67c0dc40-21b0-4ac9-adad-ed24d47b128f_sub', 'delivery_tag':'9' }', 'baseUrl':'file:/home/peter/Sarracenia/metpx-sr3c/shim_dirA', 'exchange':'xs_feed', 'fileOp':'{  'link':'/home/peter/Sarracenia/metpx-sr3c/shim_dirB/broken_do_not_exist', 'rename':'/home/peter/Sarracenia/metpx-sr3c/shim_dirB/CupsDUov' }', 'local_offset':'0', 'new_baseUrl':'file:/home/peter/Sarracenia/metpx-sr3c/shim_dirA', 'new_dir':'/home/peter/Sarracenia/metpx-sr3c/shim_dirB', 'new_file':'symlink_to_non_existent_place', 'new_relPath':'home/peter/Sarracenia/metpx-sr3c/shim_dirB/symlink_to_non_existent_place', 'new_subtopic':'['home', 'peter', 'Sarracenia', 'metpx-sr3c', 'shim_dirB']', 'post_fileOp':'{  'link':'/home/peter/Sarracenia/metpx-sr3c/shim_dirA/broken_do_not_exist', 'rename':'/home/peter/Sarracenia/metpx-sr3c/shim_dirA/CupsDUov' }', 'post_format':'v03', 'pubTime':'20250108T204040.62556141', 'relPath':'symlink_to_non_existent_place', 'source':'tfeed', 'subtopic':'[]', 'topic':'v03.post', 'toto':'pig' }
2025-01-08 15:40:41,187 [DEBUG] sarracenia.flow filter B filtered incoming: 1, ok: 0 (directories: 0), rejected: 0, failed: 0 stop_requested: False have_vip: ['AnyAddressIsFine']
2025-01-08 15:40:41,187 [DEBUG] sarracenia.flow do_download chdir /home/peter/Sarracenia/metpx-sr3c/shim_dirB
2025-01-08 15:40:41,187 [INFO] sarracenia.flow renameOneItem old file /home/peter/Sarracenia/metpx-sr3c/shim_dirB/CupsDUov not found, if destination (/home/peter/Sarracenia/metpx-sr3c/shim_dirB/symlink_to_non_existent_place) missing, then fall back to copy
2025-01-08 15:40:41,187 [DEBUG] sarracenia.flow link1file message is to link symlink_to_non_existent_place to /home/peter/Sarracenia/metpx-sr3c/shim_dirB/broken_do_not_exist

• sr3 decides that old file isn't there... so it does not rename it.

[petersilva]

problem is here:

   if not os.path.exists(old):

This test fails if the old is a broken symlink.

[reidsunderland]

There's another case where this is still happening.

When a symlink already exists and you update/overwrite it, it creates the link using a temporary name, then renames the temporary name to the proper name, overwriting the existing link in the process.

# ln target link_name
ln -sf broken_do_not_exist symlink_to_non_existent_place
strace ln -sf broken_do_not_exist symlink_to_non_existent_place


# link_name stat fails - file pointed to by the existing link doesn't exist
stat("symlink_to_non_existent_place", 0x7ffdd65d3d10) = -1 ENOENT (No such file or directory)

# link_name lstat success - link itself already exists
lstat("symlink_to_non_existent_place", {st_mode=S_IFLNK|0777, st_size=19, ...}) = 0

# target stat fails, target does not exist
stat("broken_do_not_exist", 0x7ffdd65d3b70) = -1 ENOENT (No such file or directory)

# symlinkat fails, link already exists
symlinkat("broken_do_not_exist", AT_FDCWD, "symlink_to_non_existent_place") = -1 EEXIST (File exists)

# makes a random symlink instead
symlinkat("broken_do_not_exist", AT_FDCWD, "CuQm4qss") = 0

# renames it to overwrite existing
renameat(AT_FDCWD, "CuQm4qss", AT_FDCWD, "symlink_to_non_existent_place") = 0

But when there's multiple subscriber instances, it's possible to hit a race condition where the rename message gets processed before the link message. The rename fails because the link with the temporary name hasn't been created yet, then the link creation happens shortly after, so we're left with only the temporary name on the subscriber side.

[reidsunderland]

I wrote a plugin to simulate the race condition:

import logging
from sarracenia.flowcb import FlowCB

logger = logging.getLogger(__name__)

class Screw_up_order(FlowCB):
    """ for testing shim

        re-order worklist so that rename + link fileOp events are processed before link creation events
        example messages:
        2025-04-02 20:58:15,394 [INFO] shim published: { "pubTime":"20250402205815.39313447", "baseUrl":"file:/home/sarra/metpx-sr3c-3.25.03rc3-x64/shim_dirA", "relPath":"CucZxOOZ", "topic":"v03.post", "toto":"pig", "fileOp" : { "link":"../libsr3shim.c"}}

        2025-04-02 20:58:15,395 [INFO] shim published: { "pubTime":"20250402205815.39473321", "baseUrl":"file:/home/sarra/metpx-sr3c-3.25.03rc3-x64/shim_dirA", "relPath":"file_to_delete", "topic":"v03.post", "toto":"pig", "fileOp" : { "link":"../libsr3shim.c", "rename" : "/fs/homeu2/ssc/di/ras000/metpx-sr3c-3.25.03rc3-x64/shim_dirA/CucZxOOZ" }}

        simulates a race condition where multiple instances are running
        and the rename is handled before the link is created
    """

    def __init__(self, options):
        super().__init__(options, logger)
        self.late = []

    def after_accept(self, worklist):
        new_incoming = []
        for msg in worklist.incoming:
            if 'fileOp' in msg:
                # delay links so the link+rename gets handled first
                if 'link' in msg['fileOp'] and 'rename' not in msg['fileOp']:
                    self.late.append(msg)
                    logger.info(f"delaying link msg: {msg}")
                else:
                    new_incoming.append(msg)

        worklist.incoming = new_incoming
        new_incoming = []

        for msg in worklist.incoming:
            if 'fileOp' in msg:
                if 'link' in msg['fileOp'] and 'rename' in msg['fileOp']:
                    rename_src = msg['fileOp']['rename']
                    new_late = []
                    for latemsg in self.late:
                        if rename_src.endswith(latemsg['relPath']):
                            logger.info(f"releasing delayed msg {msg}")
                            new_incoming.append(latemsg)
                        else:
                            new_late.append(latemsg) # keep waiting
                    self.late = new_late

        worklist.incoming.extend(new_incoming)

        if self.stop_requested:
            worklist.incoming.extend(self.late)
            logger.info(f"releasing all delayed msgs {self.late}")

[reidsunderland]

These are the two messages posted when overwriting a link that already exists (the strace is two comments up: #1366 (comment)):

# creates link Cu2b1kQl --> ../libsr3shim.c
2025-04-15 19:10:44,804 [INFO] shim published: { "pubTime":"20250415191044.80296384", "baseUrl":"file:/home/sarra/metpx-sr3c-3.25.03rc3-x64/shim_dirA", "relPath":"Cu2b1kQl", "topic":"v03.post", "toto":"pig", "fileOp" : { "link":"../libsr3shim.c"}}

# renames Cu2b1kQl to file_to_delete
2025-04-15 19:10:44,806 [INFO] shim published: { "pubTime":"20250415191044.80472194", "baseUrl":"file:/home/sarra/metpx-sr3c-3.25.03rc3-x64/shim_dirA", "relPath":"file_to_delete", "topic":"v03.post", "toto":"pig", "fileOp" : { "link":"../libsr3shim.c", "rename" : "/home/sarra/metpx-sr3c-3.25.03rc3-x64/shim_dirA/Cu2b1kQl" }}

Everything works fine if they are processed in order. If the link+rename is processed first, this is what happens:

# rename Cu2b1kQl to file_to_delete fails because Cu2b1kQl doesn't exist
# falls through to "download", creating link file_to_delete --> ../libsr3shim.c (this is good - this is the final link we want)
2025-04-15 19:10:44,806 [INFO] shim published: { "pubTime":"20250415191044.80472194", "baseUrl":"file:/home/sarra/metpx-sr3c-3.25.03rc3-x64/shim_dirA", "relPath":"file_to_delete", "topic":"v03.post", "toto":"pig", "fileOp" : { "link":"../libsr3shim.c", "rename" : "/home/sarra/metpx-sr3c-3.25.03rc3-x64/shim_dirA/Cu2b1kQl" }}

# creates link Cu2b1kQl --> ../libsr3shim.c
2025-04-15 19:10:44,804 [INFO] shim published: { "pubTime":"20250415191044.80296384", "baseUrl":"file:/home/sarra/metpx-sr3c-3.25.03rc3-x64/shim_dirA", "relPath":"Cu2b1kQl", "topic":"v03.post", "toto":"pig", "fileOp" : { "link":"../libsr3shim.c"}}

# temporary Cu2b1kQl  link remains on destination

My first thought was to have the link rename message get retried when it fails. But that could introduce other problems since the rename retry might happen minutes later (if it goes through the retry diskqueue).

If the link is supposed to point to a directory (e.g. root/abc -> /real/path/abc_real), in the meantime other downloads that are supposed to go into root/abc will probably create the abc directory.

Other options:

1. retry the rename a few times using self.o.attempts but do not put the message into worklist.failed to be retried with the diskqueue logic. If the rename fails after multiple attempts, fall through to "download" like the code currently does.
   • not super robust, but it might be good enough to fix the race condition case
2. keep existing fall through to "download" behaviour and put the failed rename message into the diskqueue for retry later
   • first time the message comes through, the rename will fail because the source (temporary link name) hasn't been created yet.
     • put message into worklist.failed for retry later
     • also fall through to "download" - link will be created with the proper name
   • once the original link creation message gets processed (by another instance) the link will be created with the temporary name
   • at some point, the link+rename message will be retried from the diskqueue and the rename will happen. This should remove/cleanup the temporary link.
3. fix this on the publish (C) side by only posting one message instead of two (not sure how difficult this would be)