[Bug]: tar files are not deleted after successful globus transfer

[tangq]

What happened?

The documentation indicates that "--keep to keep a copy of the tar files on the local file system after they have been transferred to HPSS. Normally, they are deleted after successful transfer." So, without --keep, the tar files should be deleted after successful transfer. But the tar files are not deleted when transferred successfully via globus. I might not use the zstash command correctly. If so, sorry for the false alarm.

I reproduced this with a simple test on Chrysalis.
touch tst.txt
zstash create -v --non-blocking --hpss=globus://nersc/~/E3SMv3_dev/tst --maxsize 128 .

The log line Calling hpss_put to dispatch archive file 000000.tar [keep, non_blocking] = [False, True] confirms the keep flag is False.

Here is the complete log:

For help, please see https://e3sm-project.github.io/zstash. Ask questions at https://github.com/E3SM-Project/zstash/discussions/categories/q-a.
DEBUG: 20250605_035238_623132: Running zstash create
DEBUG: Local path : /lcrc/group/e3sm2/ac.qtang/tst
DEBUG: HPSS path  : globus://nersc/~/E3SMv3_dev/tst
DEBUG: Max size  : 137438953472
DEBUG: Keep local tar files  : False
DEBUG: Making sure input path exists and is a directory
DEBUG: 20250605_035238_623404:Calling globus_activate(hpss)
INFO: Creating client of type <class 'globus_sdk.services.auth.client.native_client.NativeAppAuthClient'> for service "auth"
INFO: Finished initializing AuthLoginClient. client_id='6c1629cf-446c-49e7-af95-323c6412397f', type(authorizer)=<class 'globus_sdk.authorizers.base.NullAuthorizer'>
INFO: Setting up RefreshTokenAuthorizer with auth_client=[instance:23455989535200]
INFO: Setting up a RenewingAuthorizer. It will use an auth type of Bearer and can handle 401s.
INFO: RenewingAuthorizer will start by using access_token with hash "6e0977482bceb074128f911539d014c5907e30d53bcf7fa9c0c1d1b7240ff704"
INFO: Setting up an AccessTokenAuthorizer. It will use an auth type of Bearer and cannot handle 401s.
INFO: Creating client of type <class 'globus_sdk.services.transfer.client.TransferClient'> for service "transfer"
INFO: TransferClient.endpoint_autoactivate(15288284-7006-4041-ba1a-6b52501e49f1)
INFO: request done (success)
INFO: TransferClient.endpoint_autoactivate(9cd89cfd-6d04-11e5-ba46-22000b92c6ec)
INFO: request done (success)
DEBUG: 20250605_035239_319250: Creating local cache directory
DEBUG: 20250605_035239_319398: Calling create_database()
DEBUG: 20250605_035239_319454:Creating index database
INFO: Gathering list of files to archive
INFO: 20250605_035239_420308: Creating new tar archive 000000.tar
INFO: Archiving tst.txt
DEBUG: 20250605_035239_423862: Closing tar archive 000000.tar
INFO: 20250605_035239_424067: (add_files): Completed archive file 000000.tar
INFO: tar name=000000.tar, tar size=10240, tar md5=21d45155d348307f7db791b620a07d96
INFO: 20250605_035239_429147: DIVING: (add_files): Calling hpss_put to dispatch archive file 000000.tar [keep, non_blocking] = [False, True]
INFO: 20250605_035239_429204: in hpss_transfer, prev_transfers is starting as []
INFO: Transferring file to HPSS: zstash/000000.tar
INFO: 20250605_035239_429272: DIVING: hpss calls globus_transfer(name=000000.tar)
INFO: 20250605_035239_429301: Entered globus_transfer() for name = 000000.tar
DEBUG: 20250605_035239_429322: non_blocking = True
INFO: Creating a new TransferData object
INFO: TransferClient.get_submission_id(None)
INFO: request done (success)
INFO: TransferData.DATA_TYPE = transfer
INFO: TransferData.DATA = []
INFO: TransferData.source_endpoint = 15288284-7006-4041-ba1a-6b52501e49f1
INFO: TransferData.destination_endpoint = 9cd89cfd-6d04-11e5-ba46-22000b92c6ec
INFO: TransferData.label = tst 000000
INFO: TransferData.submission_id = 867de2ca-41c0-11f0-8ee3-0256b1e82d1f
INFO: TransferData.verify_checksum = True
INFO: TransferData.preserve_timestamp = True
INFO: TransferData.encrypt_data = False
INFO: TransferData.skip_source_errors = False
INFO: TransferData.fail_on_quota_errors = True
INFO: TransferData.delete_destination_extra = False
INFO: TransferData.notify_on_succeeded = True
INFO: TransferData.notify_on_failed = True
INFO: TransferData.notify_on_inactive = True
INFO: 20250605_035239_455518: TransferData: accumulated items:
   (routine)  PUSHING (#1) STORED source item: /lcrc/group/e3sm2/ac.qtang/tst/zstash/000000.tar
INFO: 20250605_035239_455593: DIVING: Submit Transfer for tst 000000
INFO: TransferClient.submit_transfer(...)
INFO: request done (success)
INFO: 20250605_035241_289602: SURFACE Submit Transfer returned new task_id = 867de1e9-41c0-11f0-b34a-0256b1e82d1f for label tst 000000
INFO: 20250605_035241_289676: NO BLOCKING (task_wait) for task_id 867de1e9-41c0-11f0-b34a-0256b1e82d1f
INFO: 20250605_035241_289736: SURFACE hpss globus_transfer(name=000000.tar) returns UNKNOWN
INFO: 20250605_035241_289815: SURFACE (add_files): Called hpss_put to dispatch archive file 000000.tar
DEBUG: 20250605_035241_296579: calling hpss_put() for zstash/index.db
INFO: 20250605_035241_296765: in hpss_transfer, prev_transfers is starting as []
INFO: Transferring file to HPSS: zstash/index.db
INFO: 20250605_035241_296862: DIVING: hpss calls globus_transfer(name=index.db)
INFO: 20250605_035241_296899: Entered globus_transfer() for name = index.db
DEBUG: 20250605_035241_296922: non_blocking = False
INFO: Creating a new TransferData object
INFO: TransferClient.get_submission_id(None)
INFO: request done (success)
INFO: TransferData.DATA_TYPE = transfer
INFO: TransferData.DATA = []
INFO: TransferData.source_endpoint = 15288284-7006-4041-ba1a-6b52501e49f1
INFO: TransferData.destination_endpoint = 9cd89cfd-6d04-11e5-ba46-22000b92c6ec
INFO: TransferData.label = tst index
INFO: TransferData.submission_id = 879ade90-41c0-11f0-aad5-0256b1e82d1f
INFO: TransferData.verify_checksum = True
INFO: TransferData.preserve_timestamp = True
INFO: TransferData.encrypt_data = False
INFO: TransferData.skip_source_errors = False
INFO: TransferData.fail_on_quota_errors = True
INFO: TransferData.delete_destination_extra = False
INFO: TransferData.notify_on_succeeded = True
INFO: TransferData.notify_on_failed = True
INFO: TransferData.notify_on_inactive = True
INFO: TransferClient.get_task(867de1e9-41c0-11f0-b34a-0256b1e82d1f, ...)
INFO: request done (success)
INFO: 20250605_035241_351599: Previous task_id 867de1e9-41c0-11f0-b34a-0256b1e82d1f Still Active. Returning ACTIVE.
INFO: 20250605_035241_351678: SURFACE hpss globus_transfer(name=index.db) returns ACTIVE
DEBUG: 20250605_035241_351756: calling globus_finalize()
INFO: 20250605_035241_351807: FINAL TransferData: accumulated items:
    (finalize) PUSHING (2) source item: /lcrc/group/e3sm2/ac.qtang/tst/zstash/index.db
INFO: 20250605_035241_351862: DIVING: Submit Transfer for tst index
INFO: TransferClient.submit_transfer(...)
INFO: request done (success)

What machine were you running on?

Chrysalis

Environment

e3sm_unified_1.11.1

Minimal Complete Verifiable Example (MCVE)

Relevant log output

Anything else we need to know?

No response

[forsyth2]

@TonyB9000 I want to make sure I'm not missing something here; I know we had a lot of discussion about keep's interaction with non-blocking when implementing #363.

I am able to produce the above on Chrysalis with:

# Do all the steps to actually get Globus authenticated.
touch tst.txt
zstash create -v --non-blocking --hpss=globus://nersc/~/E3SMv3_dev/tst --maxsize 128 .
ls zstash/
# 000000.tar  index.db

In https://github.com/E3SM-Project/zstash/blob/main/zstash/hpss.py, we have:

        if transfer_type == "put":
            if not keep:
                if (scheme != "globus") or (globus_status == "SUCCEEDED"):
                    # Note: This is intended to fulfill the default removal of successfully-transfered
                    # tar files when keep=False, irrespective of non-blocking status
                    logger.debug(
                        f"{ts_utc()}: deleting transfered files {prev_transfers}"
                    )
                    for src_path in prev_transfers:
                        os.remove(src_path)
                    prev_transfers = curr_transfers
                    curr_transfers = list()
                    logger.info(
                        f"{ts_utc()}: prev_transfers has been set to {prev_transfers}"
                    )

So, if I recall correctly, we were collecting list of files to eventually delete (after Globus succeeded). What I'm imagining here is that in in this small example, zstash finishes before the one and only Globus transfer, so we never get back to this block.

@tangq When you ran into the issue originally (before making the reproduction example), was there only one data transfer and/or were only some of the tars kept? I imagine there might be an edge case where the last few tars in the transfer queue don't get removed.

@TonyB9000 Does that sound like a reasonable explanation or am I forgetting something? Thanks!

[tangq]

@forsyth2 , actually all tar files were kept. I had a case I submitted last night and just completed on Chrysalis at /lcrc/group/e3sm2/ac.qtang/E3SMv3_dev/20250110.v3.narrm.WCYCL1850.chrysalis/zstash

with this command:
zstash create -v --non-blocking --exclude="archive/rest/???[!05]-*/,post/scripts/,old/" --hpss=globus://nersc/~/E3SMv3_dev/20250110.v3.narrm.WCYCL1850.chrysalis --maxsize 128 .

[forsyth2]

@tangq Thanks, that adds context. @TonyB9000 Do you have any insights here?

[TonyB9000]

@forsyth2 What you describe sounds right. I recall being a bit vexed by the code that would handle most of the routine transfers with one function, but then called a "final" transfer function at the end (perhaps for the "index.db" file), and that transfer followed different rules. I could (and should) revisit my test-harness/directories. They employed "zstash" where both endpoints are identical, and the "transfer" was a glorified way to move files form one directory to another. By selecting to generate certain mixed of small and very-large files (in specific sort orders) one could track whether the blocking-vs-non-blocking behaviors were working, and I do recall issues with source files being retained even with "--keep = False" (no "--keep" supplied on the command line.) I think possible interaction with blocking may affect this (overriding "keep" in some way).

My Recollection: With "blocking", each file submission for transfer must return (transfer completed) before a new tar file would be created. Since any completed tar-file would be submitted for transfer (and a new transfer would then commence, since none could be "still active"), this would always force a single-tar-file transfer (create 1, transfer 1) sequence.

With non-blocking, the first tar-file created gets submitted for transfer (and gets transferred, as no transfers are active), but returns immediately, allowing more tar-files to be created and submitted. But if a transfer is already active, the result of the submission would simply be to add that tar-file (path) to the pending submit-structure. The addition of a tar-file submission that finally occurs when the previous transfer has completed would initiate the transfer of the latest filled-structure, and upon any subsequent transfer submissions, a new "pending" structure would be created and populated.

What bothered me, I think, is that the "submission control" function only "wakes up" to take action (even to test if a previous transfer has completed) when it receives a new submission request. I could be wrong. From my viewpoint, it would be easier to understand if the first submission launches a "transfer-service" (separate background process) that transfers the contents of a directory-snapshot, and ignores new arrivals to the directory while the transfer is ongoing, and exits when it find the directory empty. This is not a problem, because any late submissions that discover the transfer process is no longer running simply launches a new one. (There are other ways to do this, like NOT exiting on an empty directory unless a "no more files" flag is set., etc).

[forsyth2]

The addition of a tar-file submission that finally occurs when the previous transfer has completed would initiate the transfer of the latest filled-structure, and upon any subsequent transfer submissions, a new "pending" structure would be created and populated.

Yes, that is my recollection as well.

What bothered me, I think, is that the "submission control" function only "wakes up" to take action (even to test if a previous transfer has completed) when it receives a new submission request.

Yes, that was my initial thinking, but as @tangq notes above, all tars are being kept, not just the ones from the latest transfer. So, that can't be the full story here.

Strangely, per our 3/24 meeting notes, 1) one user confirmed using the latest zstash deletes tars after transfer, and 2) @golaz confirmed zstash update behaved as expected for both the --non-blocking on & off cases.

In short, I thought we had confirmed the behavior from multiple angles but now there is a counterexample.

[TonyB9000]

@forsyth2 Do we know the examples are from the same version?
Also, it is possible that Globus is sending differend status signals.
We REALLY need to implement a "VeryVerbose" mode, that highlights every significant step, so that a user can re-run their own case, get the behavior claimed, and we can walk through the log to identify the issue.

[forsyth2]

@tangq mentioned Unified 1.11.1 in the issue description.
The change log shows the following relevant changes

• 1/8: Non block testing #355
• 3/11: Non block testing fix #363
  (3/24: that meeting notes page I linked above)
• 3/25: Bump to 1.4.4 #373 (this is what's in Unified 1.11.1)

[tangq]

For the record, I am deleting the tar files under /lcrc/group/e3sm2/ac.qtang/E3SMv3_dev/20250110.v3.narrm.WCYCL1850.chrysalis/zstash to free disk space.

[TonyB9000]

@forsyth2 It took more than 34 minutes to read through that history of comments - a great refresher. I hope to have the cycles to consider a zstash refactor effort. I would really benefit from a flowchart. I would flowchart the existing app, then flowchart an idealized refactor, and then implement the refactor, using the new flowchart as a guide.

[forsyth2]

@TonyB9000 wow, yes that was a long thread, thanks for going through that. I agree a flowchart would be quite useful. I have our authentication work #370 labeled as a refactor, but I imagine you mean a larger refactor that really cleans up the entire codebase? That would also be great, if in fact there are cycles to do so.

[TonyB9000]

@forsyth2 As far as the globus_auth work goes, I really believe we need to engineer a minimalist globus_auth functionality (ideally, both for globus_sdk work and globus_cli, where there is no sign of zstash present). Then we can isolate when and where failures exists, determine if our (my) credentials or environment are an issue, etc. Where we go the globus_sdk-route, we should strive to create a "globus_cli_lite" functionality for a test utility (sans all the globus_cli bells and whistles, just a very simple point-to-point transfer between private, non-HPSS endpoints). Then, if we run into insurmountable issues, we can hand the pure "globus code" to the globus dev team and ask them what we are doing wrong.

[tangq]

It may be known already - This issue doesn't occur if --non-blocking is not used for the same simulation case. I notice that when non-blocking is true, I see globus tasks (>50) for every tar file on their webpage, but when it's false, the webpage only shows a couple (<10). This might hint some issues with globus.

[TonyB9000]

@tangq Thank you for the heads up. We may need to do certain "volume"testing as well. Presently, I cannot seem to get past the authentication phase (ok with Globus web, but fail with zstash), so a bare-bones auth test (especially, varying endpoints) should be the first item. For the SDK side of things, I need to understandthe precise difference between using the Globus native auth/transfer client, and the "fair-research-login" auth/transfer client.. Sasha's "esgpublish" uses the globus_cli method - a third possibility.