Artifact packaging with Octopus push step now intermittently fails with 2023.05

Without access to the TeamCity source code I can only guess at what is going on here - but is there now some sort of attempt at caching files produced by a build by the ArtifactsBuilder code? Because we are intermittently seeing builds fail at our Octopus: Push Packages step whereby it is saying that files are missing, yet it should not be considering those files at all because they have (intentionally) been removed by the previous step in the build process?

This is a *new* problem that only started with 2023.05, our builds had been running successfully for a number of years before this. Now we see failures every night, with four nightly builds usually 2 of them will fail (they are not running concurrently).

In our build process after generating the output to folders, we have a custom tool (called "Shrinkwrap") which is run in the next step which de-duplicates the binaries in that output folder within the agent workspace, moving/deleting binaries into a shared folder. That step completes fine according to the logs.

The next step is then the Octopus Deploy plugin for TeamCity doing a "Push", which as part of it's configuration we have it zipping up various folders in the output. It has package paths specified like this:

%myapp.package.files.dir%/**/* => Packages\%OctopusDeploy.ProjectName%.%build.number%+%OctopusDeploy.ReleaseName%.zip
%myapp.package.octopus.dir%/**/* => Packages\%OctopusDeploy.ProjectName%_DeployScripts.%build.number%+%Oct

That code relies on the JetBrains ArtifactsBuilder code it would appear:

https://github.com/OctopusDeploy/Octopus-TeamCity/blob/main/octopus-agent/src/main/java/octopus/teamcity/agent/OctopusPushPackageBuildProcess.java

The error we see in the logs is this - showing the ending of the previous "Shrinkwrap" step then leading into the failure of the TeamCity ArtifactsBuilder where it is trying to reference a file that is no longer in that subfolder:

[10:33:29] : [Step 15/18] Shrinkwrap analysis completed.
[10:33:29] : [Step 15/18] Process exited with code 0
[10:33:29]E: Step 16/18: OctopusDeploy: Push Packages (4s)
[10:33:30]W: [Step 16/18] Creating archive MyBuild.zip (4s)
[10:33:30] : [Creating archive MyBuild.zip] Creating D:\TeamCityAgents\BuildAgent1\temp\buildTmp\ZipPreprocessor17939394160745743877\MyBuild.zip
[10:33:30] : [Creating archive MyBuild.zip] Adding: AppDeploy
[10:33:30] : [Creating archive MyBuild.zip] Adding: MyApp.AppDeploy.adm
[10:33:30] : [Creating archive MyBuild.zip] Adding: Binaries
[10:33:30] : [Creating archive MyBuild.zip] Adding: Clients
[10:33:30] : [Creating archive MyBuild.zip] Adding: BatchProcessing
[10:33:30] : [Creating archive MyBuild.zip] Adding: MyApp.Batch.BatchProcessing.exe
[10:33:30] : [Creating archive MyBuild.zip] Adding: MyApp.Batch.BatchProcessing.exe.config
[10:33:30] : [Creating archive MyBuild.zip] Adding: MyApp.Batch.BatchProcessing.pdb
[10:33:30] : [Creating archive MyBuild.zip] Adding 1372 more file(s)...
[10:33:34]W: [Creating archive MyBuild.zip] Error while creating archive 'MyBuild.zip': java.io.IOException: Error while closing archive 'Packages/MyBuild.zip' with 1382 entries: Error adding file 'D:\TeamCityAgents\BuildAgent1\work\e006f3186b338389\Packages\Files\Binaries\Services\RegulatoryFeedEngine\Rebex.Networking.dll' as entry 'Binaries/Services/RegulatoryFeedEngine/Rebex.Networking.dll' to archive: java.nio.file.NoSuchFileException: D:\TeamCityAgents\BuildAgent1\work\e006f3186b338389\Packages\Files\Binaries\Services\RegulatoryFeedEngine\Rebex.Networking.dll
[10:33:34]W: [Step 16/18] jetbrains.buildServer.agent.ArtifactPreprocessingFailedException: Error while creating archive 'MyBuild.zip': java.io.IOException: Error while closing archive 'Packages/MyBuild.zip' with 1382 entries: Error adding file 'D:\TeamCityAgents\BuildAgent1\work\e006f3186b338389\Packages\Files\Binaries\Services\RegulatoryFeedEngine\Rebex.Networking.dll' as entry 'Binaries/Services/RegulatoryFeedEngine/Rebex.Networking.dll' to archive: java.nio.file.NoSuchFileException: D:\TeamCityAgents\BuildAgent1\work\e006f3186b338389\Packages\Files\Binaries\Services\RegulatoryFeedEngine\Rebex.Networking.dll
at jetbrains.buildServer.agent.impl.artifacts.ArchivePreprocessor.reportProblem(ArchivePreprocessor.java:193)
at jetbrains.buildServer.agent.impl.artifacts.ArchivePreprocessor.processArtifacts(ArchivePreprocessor.java:88)
at jetbrains.buildServer.agent.impl.artifacts.BatchArchivePreprocessor.processArtifacts(BatchArchivePreprocessor.java:54)
at jetbrains.buildServer.agent.impl.artifacts.ArtifactsBuilder.preprocessAndZip(ArtifactsBuilder.java:222)
at jetbrains.buildServer.agent.impl.artifacts.ArtifactsBuilder.processArtifacts(ArtifactsBuilder.java:94)
at jetbrains.buildServer.agent.impl.artifacts.ArtifactsBuilder.build(ArtifactsBuilder.java:58)
at octopus.teamcity.agent.OctopusPushPackageBuildProcess.start(OctopusPushPackageBuildProcess.java:75)
at jetbrains.buildServer.agent.impl.buildStages.runnerStages.start.CallRunnerStage.doBuildStage(CallRunnerStage.java:60)
at jetbrains.buildServer.agent.impl.buildStages.RunnerStagesExecutor$1.callStage(RunnerStagesExecutor.java:27)
at jetbrains.buildServer.agent.impl.buildStages.RunnerStagesExecutor$1.callStage(RunnerStagesExecutor.java:18)
at jetbrains.buildServer.agent.impl.buildStages.StagesExecutor.callRunStage(StagesExecutor.java:76)
at jetbrains.buildServer.agent.impl.buildStages.StagesExecutor.doStages(StagesExecutor.java:35)
at jetbrains.buildServer.agent.impl.buildStages.RunnerStagesExecutor.doStages(RunnerStagesExecutor.java:18)
at jetbrains.buildServer.agent.impl.buildStages.startStages.steps.RunnerContextExecutor.executeBuildStepStages(RunnerContextExecutor.java:45)
at jetbrains.buildServer.agent.impl.buildStages.startStages.steps.RunAllBuildStepsStage.runBuildStep(RunAllBuildStepsStage.java:190)
at jetbrains.buildServer.agent.impl.buildStages.startStages.steps.RunAllBuildStepsStage.runStep(RunAllBuildStepsStage.java:176)
at jetbrains.buildServer.agent.impl.buildStages.startStages.steps.RunAllBuildStepsStage.executeBuildRunners(RunAllBuildStepsStage.java:126)
at jetbrains.buildServer.agent.impl.buildStages.startStages.steps.RunAllBuildStepsStage.doBuildStage(RunAllBuildStepsStage.java:58)
at jetbrains.buildServer.agent.impl.buildStages.BuildStagesExecutor$1.callStage(BuildStagesExecutor.java:33)
at jetbrains.buildServer.agent.impl.buildStages.BuildStagesExecutor$1.callStage(BuildStagesExecutor.java:24)
at jetbrains.buildServer.agent.impl.buildStages.StagesExecutor.callRunStage(StagesExecutor.java:76)
at jetbrains.buildServer.agent.impl.buildStages.StagesExecutor.doStages(StagesExecutor.java:35)
at jetbrains.buildServer.agent.impl.buildStages.BuildStagesExecutor.doStages(BuildStagesExecutor.java:24)
at jetbrains.buildServer.agent.impl.BuildRunActionImpl.doStages(BuildRunActionImpl.java:93)
at jetbrains.buildServer.agent.impl.BuildRunActionImpl.runBuild(BuildRunActionImpl.java:65)
at jetbrains.buildServer.agent.impl.BuildAgentImpl.doActualBuild(BuildAgentImpl.java:345)
at jetbrains.buildServer.agent.impl.BuildAgentImpl.access$100(BuildAgentImpl.java:63)
at jetbrains.buildServer.agent.impl.BuildAgentImpl$1.run(BuildAgentImpl.java:294)
at java.base/java.lang.Thread.run(Thread.java:829)
Caused by: java.io.IOException: Error while closing archive 'Packages/MyBuild.zip' with 1382 entries: Error adding file 'D:\TeamCityAgents\BuildAgent1\work\e006f3186b338389\Packages\Files\Binaries\Services\RegulatoryFeedEngine\Rebex.Networking.dll' as entry 'Binaries/Services/RegulatoryFeedEngine/Rebex.Networking.dll' to archive: java.nio.file.NoSuchFileException: D:\TeamCityAgents\BuildAgent1\work\e006f3186b338389\Packages\Files\Binaries\Services\RegulatoryFeedEngine\Rebex.Networking.dll
at jetbrains.buildServer.agent.impl.artifacts.ArchivePreprocessor.putFilesToArchive(ArchivePreprocessor.java:138)
at jetbrains.buildServer.agent.impl.artifacts.ArchivePreprocessor.processArtifacts(ArchivePreprocessor.java:79)
... 27 more
Caused by: java.io.IOException: Error adding file 'D:\TeamCityAgents\BuildAgent1\work\e006f3186b338389\Packages\Files\Binaries\Services\RegulatoryFeedEngine\Rebex.Networking.dll' as entry 'Binaries/Services/RegulatoryFeedEngine/Rebex.Networking.dll' to archive: java.nio.file.NoSuchFileException: D:\TeamCityAgents\BuildAgent1\work\e006f3186b338389\Packages\Files\Binaries\Services\RegulatoryFeedEngine\Rebex.Networking.dll
at jetbrains.buildServer.agent.impl.artifacts.ZipPreprocessor.processFile(ZipPreprocessor.java:98)
at jetbrains.buildServer.agent.impl.artifacts.BatchArchivePreprocessor.flushFilesQueue(BatchArchivePreprocessor.java:86)
at jetbrains.buildServer.agent.impl.artifacts.BatchArchivePreprocessor.closeArchive(BatchArchivePreprocessor.java:59)
at jetbrains.buildServer.agent.impl.artifacts.ZipPreprocessor.closeArchive(ZipPreprocessor.java:139)
at jetbrains.buildServer.agent.impl.artifacts.ArchivePreprocessor.putFilesToArchive(ArchivePreprocessor.java:133)
... 28 more
Caused by: java.nio.file.NoSuchFileException: D:\TeamCityAgents\BuildAgent1\work\e006f3186b338389\Packages\Files\Binaries\Services\RegulatoryFeedEngine\Rebex.Networking.dll
at java.base/sun.nio.fs.WindowsException.translateToIOException(WindowsException.java:85)
at java.base/sun.nio.fs.WindowsException.rethrowAsIOException(WindowsException.java:103)
at java.base/sun.nio.fs.WindowsException.rethrowAsIOException(WindowsException.java:108)
at java.base/sun.nio.fs.WindowsFileSystemProvider.newByteChannel(WindowsFileSystemProvider.java:235)
at java.base/java.nio.file.Files.newByteChannel(Files.java:371)
at java.base/java.nio.file.Files.newByteChannel(Files.java:422)
at java.base/java.nio.file.spi.FileSystemProvider.newInputStream(FileSystemProvider.java:420)
at java.base/java.nio.file.Files.newInputStream(Files.java:156)
at jetbrains.buildServer.agent.impl.artifacts.ZipPreprocessor.processFile(ZipPreprocessor.java:91)
... 32 more
 
[10:33:34]E: [Step 16/18] Failed to start build runner 'octopus.push.package'
[10:33:34]E: [Step 16/18] Step OctopusDeploy: Push Packages failed with unexpected error
[10:33:34]E: [Step 16/18] Error message: Step OctopusDeploy: Push Packages failed with unexpected error

 

I don't understand why the ArtifactsBuilder is trying to include in the zip a file which is no longer in that folder. The Shrinkwrap tool has finished as shown by the log (it's process does not exit before all file copies/moves are completed). My suspicion is that the ArtifactsBuilder is not taking a fresh look at files in the folder and is perhaps instead relying on some cached set/file watchers to detect changes and that is where this is all going wrong now?

0
10 comments

We had to work around this issue by adding a delay step in before the Octopus step - once we did this the problem has gone. Which all but confirms my theory above - that there is some sort of caching by ArtifactsBuilder and in particular circumstances that cache is not being refreshed quickly enough for services that subsequently make use of it (an Octopus Deploy plugin in this case).

It is a crappy workaround - but at least it stops the builds failing until someone from JetBrains bothers to responds to this post.

0
Hello,

  My current theory is that Shrinkwrap step leaves a process which finalizes file processing, and there is a race condition, i.e. ArtifactsBuilder collects the list of files to archive first (when OctopusPushPackageBuildProcess step starts), and then actually compresses them, and at the second stage one of the collected files from the list is gone. I'd consider to double check that Shrinkwrap does not leave a process which finalizes its work, could you do it somehow?

  The only change we've made in TeamCity's ArtifactsBuilder code was related to the processing of symbolic links, and I don't think this is related to the problem you notice.

  Kind regards,
  KIR
0

Hi Kirill,

Shrinkwrap was indeed the first thing I looked at. However all it is doing is simple File.Copy, File.Delete operations within a C# executable that completely exits prior to TeamCity starting the next step. As I mentioned in the original post this process has worked flawlessly for years - the only thing that obviously changed was the latest TeamCity version upgrade (I continuously upgrade each time TeamCity reminds me to, so not like we were coming from an old version).

We have got our reliability of builds working back by keeping that delay step in I mentioned above - it is not ideal but as we have a workaround it isn't something we are going to invest a lot more time on. With no visibility to your source code I can make no other suggestions - whether that code is relying on file system change event notifications which are not happening, it is using cached data or some other bug that has introduced this behaviour.

0
Hi, the change we've made into the code relates to handling of symlinks. I.e. previously TeamCity archived the symlinks by content, now it may archive the symlink as is, i.e. as a reference to another file. 

But there is no caching involved, i.e. each publishing operation reads a list of files from the filesystem from scratch and then puts the collected files into the archive.

Which version of TeamCity did you use before the upgrade?

Thanks,
0
And another question - the files which cannot be found - are they removed by the Shrinkwrap process?
0

Hi Kirill - not sure how to determine what the previous version was? As I mentioned I always install within a day or two of TeamCity notifying me that a new version is available, so it would have been whatever version you guys released publicly before 2023.05 build 129203 which has had the issue. I see there is now 129321 available so that will be installed today.

And yes the files not found are indeed removed by Shrinkwrap. Our TeamCity release build compiles various C# service executables into a series of subfolders. We then want to zip that whole parent output folder up for handing off to Octopus, however to reduce the zip size down we have a de-duplication step performed by our Shrinkwrap tool. It iterates across all those output subfolders, finds any duplicated dlls between them, moves one copy of each into a "common" folder, records the original positions in a manifest file and then deletes all the remaining "duplicates" from those folders.

So in the error stack I posted, the "RegulatoryFeedEngine" subfolder containing the binaries for that service included a "Rebex.Networking.dll" when it was compiled by the TeamCity build step. However as other services also had that particular .dll, Shrinkwrap would have done either a .NET File.Move() to the shared  folder or a File.Delete() on it. There is no background threading in Shrinkwrap, it is a synchronous process with very simple file operations.

However when the Octopus step executes and invokes the TeamCity Java api for archiving, for whatever reason it is thinking that there should still be a Rebex.Networking.dll in that Services folder, tries to add it to the archive it is generating, and of course fails because the file is not physically present in that folder. You can see the Shrinkwrap process executable executed at 10:33:29 in that log above, then a second later the Octopus step starts trying to archive the folder contents and boom...

It didn't happen "every single time without fail" - if a developer manually triggered the build it usually succeeded. Yet the scheduled builds were failing "most" days after the TeamCity upgrade. It was very intermittent - but adding a 15 second delay step in between Shrinkwrap and Octopus allowed "something" on the server to get itself up to date such that it has worked flawlessly again ever since.

Very confusing given you are saying there is no caching. We don't use symlinks that I am aware of. On our Windows 2019 build server we have both TeamCity itself and 3 TeamCity agents all on that same machine. 

0
Hello,

 May I ask you to add an intermediate build step which would list the "RegulatoryFeedEngine" folder contents after Shrinkwrap step got executed? 
 This would ensure that the problem comes from TeamCity caching side and not some async processing of the Shrinkwrap tool.

 What do you think?

 Thanks,
 KIR
0

Hi Kirill - sure that sounds an interesting idea. I will see what it reports the next few days (as this was an intermittent issue) across the builds to see if at any stage files appear listed which should not be and let you know.

0

Hi Kirill, just a small update for you. I added a Powershell step to list out the files, and as expected it shows them deleted from the folder after the Shrinkwrap step. I have now disabled the "delay" step I added (keeping the Powershell list step) - and it has run successfully all the way through which is not overly helpful in pointing out the culprit!

Of course two things have now changed since the original problem above - a subsequent TeamCity update installed, plus adding this Powershell step which itself will be causing a small delay between Shrinkwrap finishing executing and the Octopus packaging step running.

Will give it another day or two to see if the problem reoccurs with the current setup, if not then try disabling the Powershell list step and see how it behaves then. It always was an intermittent problem unfortunately so don't want to celebrate it quietly fixing itself without a longer run...

0
Hello,

 Thank you for the follow-up. Let's wait for a case when / if the problem appears, and if so, it would be interesting to see the logs from the Powershell step with logging.
 But hope it somehow will be resolved :)

 Keeping fingers crossed,
 KIR
0

Please sign in to leave a comment.