Artifactory download fails on removing temp file, but the lock seems to come from its own threads

[DeDixs]

Describe the bug

When using jf.exe on a Jenkins build server to download artifacts using a spec file as input every now and then a failing download occurs, with a message:

03:00:37 [Error] Failed to close reader: remove C:\Users\userA\AppData\Local\Temp\jfrog.cli.temp.-1736906327-1915232773: The process cannot access the file because it is being used by another process.
03:00:37 [Info] Trace ID for JFrog Platform logs: ff38bc27579ea9b3
03:00:37 [Error] download finished with errors, please review the logs

Due to this the download fails. The failing download can more or less happen for any artifact that is being downloaded.

Current behavior

The error message seems to come from the jfrog-client-go repo, contentreader.go:

// Cleanup the reader data.
func (cr *ContentReader) Close() error {
	for _, filePath := range cr.filesPaths {
		if filePath == "" {
			continue
		}
		if err := errorutils.CheckError(os.Remove(filePath)); err != nil {
			return errors.New("Failed to close reader: " + err.Error())
		}
	}
	cr.filesPaths = nil
	return nil
}

In order to make sure this is not interference of another tool (e.g. virus scanner) ProcessMonitor was executed until the issue occurred. This showed that only jf.exe was accessing the file when it happens - the contentreader tries to remove the file but some other thread still seems to have it open. It seems to be a race condition that only happens on rare occasions, most of the times no issue occurs. It also only seems to occur on Windows, it cannot be reproduced using jf on Linux.

The temp file itself that is reported in the error is still available on the machine that ran the command (since it could not be deleted), its contents do not look suspicious:

{
"results" : [ {
  "repo" : "artifactory-build-info",
  "path" : "BuildName",
  "name" : "219-1732718248695.json",
  "type" : "file",
  "size" : 9053,
  "created" : "2024-11-27T15:38:34.726+01:00",
  "created_by" : "userA",
  "modified" : "2024-11-27T15:38:34.600+01:00",
  "modified_by" : "userA",
  "updated" : "2024-11-27T15:38:34.727+01:00"
} ],
"range" : {
  "start_pos" : 0,
  "end_pos" : 1,
  "total" : 1,
  "limit" : 1
}
}

Reproduction steps

Unfortunately there is no easy way to reproduce it. It simply happens on a Jenkins build server every now and then, breaking the build pipeline. In order to investigate builds were triggered manually until the issue occurred. Just using
jf.exe rt dl --spec <spec>.json
should also reproduce it, but the occurrence is low.

Expected behavior

The download does not fail on trying to remove a temp file that jfrog-cli (jf.exe) has created by itself.

JFrog CLI version

2.73.0

Operating system type and version

Windows 11 23H2

JFrog Artifactory version

7.77.14

JFrog Xray version

N.A.

[agrasth]

Hey @DeDixs,

Thank you for reporting this issue.

We understand that using jf.exe on a Jenkins build server to download artifacts intermittently results in the error:

03:00:37 [Error] Failed to close reader: remove C:\Users\userA\AppData\Local\Temp\jfrog.cli.temp.-1736906327-1915232773: The process cannot access the file because it is being used by another process.
03:00:37 [Info] Trace ID for JFrog Platform logs: ff38bc27579ea9b3
03:00:37 [Error] download finished with errors, please review the logs

Reproduction Attempts:
Despite efforts to create concurrency scenarios involving parallel uploads and downloads, the issue could not be consistently reproduced. This suggests the problem might depend on specific timing, system conditions, or Jenkins environment intricacies.

Possible Factors:

1. Jenkins Environment: Investigate Jenkins job configurations, especially around workspace cleanups and concurrency settings.
2. System Behavior: Check for any background processes such as antivirus software that might intermittently lock files.
3. Enhanced Logging: Increase verbosity of JFrog CLI's logging to gather more detailed insights.

Is this issue still persisting for you currently? Any insights you can share regarding recent occurrences would be helpful.
We appreciate your patience.

[DeDixs]

Hi @agrasth ,

Thank you for reaching out, and for digging in to it.

Yes, the issue still persists. In the past we have tried to catch it where we ran ProcessMonitor, which showed that jf.exe was the only process accessing the file. However later on we realized that we did not run ProcessMonitor as admin, so potentially it is still caused by a service running as admin - we are in a corporate environment, our IT department requires us to run certain processes.

Since it kept on hampering us we decided to implement a workaround: we monitor the output of jf.exe and if the message about accessing the log file occurs we retry the download. Since it only happens infrequently this has worked out for us - although we only recently made the change (which is also why I did not post an update yet, we need a bit more time to draw conclusions).

That said, this mainly means that the root cause may not be in jf.exe. Potentially jf.exe could handle it more gracefully - possibly continuing the download process after logging the message. That way we would not need a retry on our end. But honestly the urgency has dropped a lot, so if you decide to reject this bug I will understand.