Runbook Timeout Settings

Octopus Server
, , ,
23

Hey @Hossein.Margani,

Just to make sure I am understanding fully, the above error is the result of inputting your command into my example and the chocolatey command timing out? Does this mean that your tasks are no longer hanging and correctly fail, but you want the chocolatey error to output?

This error: Exception has been thrown by the target of an invocation. ---> System.AggregateException: One or more errors occurred. ---> System.IO.IOException: The process cannot access the file 'C:\Octopus\Work\20211228092818-349309-34' because it is being used by another process.

Is oftentimes indicative of antivirus on the machine. Is there AV running on that machine?

Please let me know about both questions.

Best,
Jeremy

24

Here is the script in the runbook that I ran:

$ErrorActionPreference = 'Stop'

$maximumRuntimeSeconds = 5
$timeoutSeconds = [Int]2 * 60

$process = Start-Process -FilePath powershell.exe -ArgumentList "-Command $env:ChocolateyInstall\bin\choco.exe upgrade all -y" -PassThru

Start-Sleep -Seconds $timeoutSeconds
try
{
    $process | Wait-Process -Timeout $maximumRuntimeSeconds -ErrorAction Stop
    Write-Warning -Message 'Process successfully completed within timeout.'
}
catch
{
    Write-Warning -Message 'Process exceeded timeout, will be killed now.'
    $process | Stop-Process -Force
}

And here is the output after that exception:

Process exceeded timeout, will be killed now.
The action Run Upgrade All on UK-LON-PC-G94HK failed
25

Hi,

The error in your above stack trace can mean antivirus is blocking something, that may be what is causing chocolatey to fail. Does the machine have antivirus?

Is the issue you are now facing that you want to see the output of the start-process, or something else?

Best,
Jeremy

26
  1. There may be anti virus on the machine, but I cannot stop it. Why anti virus may block such a thing?
  2. Yes I want to see the output of the chocolatey command, which with your script I can’t.
27

Hey @Hossein.Margani,

At this point, it might be best to take a step back and look at why chocolatey is failing in the first place before we continue down the road of creating a timeout workaround.

If you remote into these machines and run the command manually in a PowerShell terminal logged in as the Octopus Tentacle service account, does it always succeed? Are certain machines failing and others aren’t? Are certain chocolatey apps failing to upgrade consistently? Is there a pattern?

Are you able to whitelist the Octopus directory and also the Chocolatey folders of all your chocolatey apps in Antivirus?

Looking forward to hearing back.

Best,
Jeremy

28

Hi Jeremy,

I have already tested the chocolatey command, and it’s all fine and exiting the process quickly when it’s success or error. But it seems Octopus cannot detect that the process created by Start-Process is finished.

29

Hi @Hossein.Margani,

Could you please confirm if you’ve successfully performed what Jeremy requested?

We must determine that all the environmental factors align with what Octopus is doing, and then we can make one change to determine if that variable is the culprit.

In this scenario, we would expect AV or similar to be blocking. Can you please:

  1. Log in remotely to the Tentacle Machine as the Octopus Tentacle Service user.
  2. Run the chocolatey script that throws the error you’re experiencing in a regular (not admin) PowerShell context.

Your Chocolatey logs aren’t being written to the Task Log because Start-Process creates an independent process, which will not log to the Octopus Task Log.
This could be what’s holding that mutex on any files, too, if the processes are separate.

It is possible to redirect stdout and stderr from this new process to a text file, which may be helpful.
However, it may be better to use a different method other than start-process to see if this executes as expected.

Kind Regards,
Adam

30

Yes I know that.

I will connect to the machine remotely, but before that when running the initial script before creating this ticket, I saw that chocolatey command was finished as I saw the finishing logs, even I checked Task Manager in windows, the chocolatey command wasn’t running, but Octopus task didn’t finish the task.

31

Here is the output right now, chocolatey command is finished at 10:13:

Task ID:        ServerTasks-349483
Related IDs:    RunbookRuns-1656, RunbookSnapshots-280, Projects-1421, Runbooks-121, Spaces-1, Environments-483
Task status:    Executing
Task queued:    Wednesday, 29 December 2021 9:28:21 AM +00:00
Task started:   Wednesday, 29 December 2021 9:28:21 AM +00:00
Task duration:  1 hour
Server version: 2020.6.4809+Branch.release-2020.6.Sha.3b393f23b33a7402f2c63eac7bd59644c84fb11b
Server node:    octopusdeploy-web-6db5696b94-q9zz5

                    | == Running: Run Upgrade All Chocolatey Packages on XXX ==
09:28:21   Verbose  |   Guided failure is not enabled for this task
                    | 
                    |   == Running: Step 1: Run Upgrade All ==
                    |   
                    |     == Running: XXXX==
09:28:21   Verbose  |       Octopus Server version: 2020.6.4809+Branch.release-2020.6.Sha.3b393f23b33a7402f2c63eac7bd59644c84fb11b
09:28:21   Verbose  |       Environment Information:
                    |       IsRunningInContainer: True
                    |       OperatingSystem: Linux 5.4.0-1046-azure #48~18.04.1-Ubuntu SMP Tue Apr 13 19:41:38 UTC 2021
                    |       OsBitVersion: x64
                    |       Is64BitProcess: True
                    |       CurrentUser: root
                    |       MachineName: octopusdeploy-web-6db5696b94-q9zz5
                    |       ProcessorCount: 4
                    |       CurrentDirectory: /Octopus
                    |       TempDirectory: /tmp/
                    |       HostProcessName: Octopus.Server
                    |       PID: 1
09:28:21   Verbose  |       Executing Run Upgrade All (type Run a Script) on XXXX
09:28:22   Verbose  |       Executable directory is C:\WINDOWS\system32\WindowsPowershell\v1.0
09:28:22   Verbose  |       Executable name or full path: C:\WINDOWS\system32\WindowsPowershell\v1.0\PowerShell.exe
09:28:22   Verbose  |       No user context provided. Running as current user.
09:28:22   Verbose  |       Starting C:\WINDOWS\system32\WindowsPowershell\v1.0\PowerShell.exe in working directory 'C:\Octopus\Work\20211229092821-349483-83' using 'Western European (DOS)' encoding running as 'NT AUTHORITY\SYSTEM' with the same environment variables as the launching process
09:28:22   Verbose  |       Process C:\WINDOWS\system32\WindowsPowershell\v1.0\PowerShell.exe in C:\Octopus\Work\20211229092821-349483-83 exited with code 0
09:28:22   Verbose  |       Using Calamari.netfx 17.0.3
09:28:22   Verbose  |       Using Calamari.netfx 17.0.3
09:28:23   Verbose  |       Executable directory is C:\WINDOWS\system32\WindowsPowershell\v1.0
09:28:23   Verbose  |       Executable name or full path: C:\WINDOWS\system32\WindowsPowershell\v1.0\PowerShell.exe
09:28:23   Verbose  |       No user context provided. Running as current user.
09:28:23   Verbose  |       Starting C:\WINDOWS\system32\WindowsPowershell\v1.0\PowerShell.exe in working directory 'C:\Octopus\Work\20211229092822-349483-84' using 'Western European (DOS)' encoding running as 'NT AUTHORITY\SYSTEM' with the same environment variables as the launching process
09:28:24   Verbose  |       Calamari Version: 17.0.3
09:28:24   Verbose  |       Environment Information:
09:28:24   Verbose  |       OperatingSystem: Microsoft Windows NT 10.0.19043.0
09:28:24   Verbose  |       OsBitVersion: x64
09:28:24   Verbose  |       Is64BitProcess: True
09:28:24   Verbose  |       CurrentUser: NT AUTHORITY\SYSTEM
09:28:24   Verbose  |       MachineName: XXXX
09:28:24   Verbose  |       ProcessorCount: 4
09:28:24   Verbose  |       CurrentDirectory: C:\Octopus\Work\20211229092822-349483-84
09:28:24   Verbose  |       TempDirectory: C:\WINDOWS\TEMP\
09:28:24   Verbose  |       HostProcess: Calamari (32584)
09:28:25   Verbose  |       Performing variable substitution on 'C:\Octopus\Work\20211229092822-349483-84\Script.ps1'
09:28:25   Verbose  |       Executing 'C:\Octopus\Work\20211229092822-349483-84\Script.ps1'
09:28:25   Verbose  |       Setting Proxy Environment Variables
09:28:26   Verbose  |       e[32;1mName                           Valuee[0m
09:28:26   Verbose  |       e[32;1m----                           -----e[0m
09:28:26   Verbose  |       PSVersion                      7.2.1
09:28:26   Verbose  |       PSEdition                      Core
09:28:26   Verbose  |       GitCommitId                    7.2.1
09:28:26   Verbose  |       OS                             Microsoft Windows 10.0.19043
09:28:26   Verbose  |       Platform                       Win32NT
09:28:26   Verbose  |       PSCompatibleVersions           {1.0, 2.0, 3.0, 4.0.}
09:28:26   Verbose  |       PSRemotingProtocolVersion      2.3
09:28:26   Verbose  |       SerializationVersion           1.1.0.1
09:28:26   Verbose  |       WSManStackVersion              3.0
09:28:26   Verbose  |       PowerShell Environment Information:
09:28:26   Verbose  |       OperatingSystem: Microsoft Windows NT 10.0.19043.0
09:28:26   Verbose  |       OsBitVersion: x64
09:28:26   Verbose  |       Is64BitProcess: True
09:28:26   Verbose  |       CurrentUser: NT AUTHORITY\SYSTEM
09:28:26   Verbose  |       MachineName: XXXX
09:28:26   Verbose  |       ProcessorCount: 4
09:28:26   Verbose  |       CurrentDirectory: C:\Octopus\Work\20211229092822-349483-84
09:28:26   Verbose  |       CurrentLocation: C:\Octopus\Work\20211229092822-349483-84
09:28:26   Verbose  |       TempDirectory: C:\WINDOWS\TEMP\
09:28:26   Verbose  |       HostProcess: pwsh (27852)
09:28:26   Verbose  |       Invoking target script C:\Octopus\Work\20211229092822-349483-84\Script.ps1 with  parameters.
09:28:26   Info     |       Update-AllChocolateyPackages STARTED
09:28:26   Info     |       Update-AllChocolateyPackages FINISHED
09:28:27   Info     |       Chocolatey v0.11.3
09:28:28   Info     |       Upgrading the following packages:
09:28:28   Info     |       all
09:28:28   Info     |       By upgrading, you accept licenses for the packages.
...
                            XXX is the latest version available based on your source(s).
...
09:28:34   Info     |       You have postman v7.33.1 installed. Version 9.4.1 is available based on your source(s).
09:28:41   Info     |       Progress: Downloading postman 9.4.1... 18%
09:28:41   Info     |       Progress: Downloading postman 9.4.1... 54%
09:28:41   Info     |       Progress: Downloading postman 9.4.1... 90%
09:28:41   Info     |       Progress: Downloading postman 9.4.1... 100%
09:28:41   Info     |       postman v9.4.1 [Approved]
09:28:41   Info     |       postman package files upgrade completed. Performing other installation steps.
09:28:43   Info     |       File appears to be downloaded already. Verifying with package checksum to determine if it needs to be redownloaded.
09:28:45   Info     |       Hashes match.
09:28:51   Info     |       Hashes match.
09:28:51   Info     |       Installing postman...
10:13:42   Info     |       Chocolatey timed out waiting for the command to finish. The timeout
10:13:42   Info     |       specified (or the default value) was '2700' seconds. Perhaps try a
10:13:42   Info     |       higher `--execution-timeout`? See `choco -h` for details.
10:13:42   Info     |       The upgrade of postman was NOT successful.
10:13:42   Info     |       Error while running 'C:\ProgramData\chocolatey\lib\postman\tools\chocolateyInstall.ps1'.
10:13:42   Info     |       See log for details.
...
                            XXX is the latest version available based on your source(s).
...
10:13:52   Info     |       Chocolatey upgraded 0/72 packages. 1 packages failed.
10:13:52   Info     |       See the log for details (C:\ProgramData\chocolatey\logs\chocolatey.log).
10:13:52   Info     |       Failures
10:13:52   Info     |       - postman (exited -1) - Error while running 'C:\ProgramData\chocolatey\lib\postman\tools\chocolateyInstall.ps1'.
10:13:52   Info     |       See log for details.

But the task in Octopus is still in Executing state.
Calamari.exe processes with ids: 32584 and 47676 are still running.
Powershell.exe processes running with Ids: 48016 and 12332.
Multiple postman setup processes are still running too.

To me it’s like the child processes of chocolatey command or tentacle script have finished but Octopus cannot detect that.

As soon as I killed the postman setup processes in task manager, the Octopus task also finished.

Should I do something with my powershell script so that Octopus task finished when chocolatey command does?

32

Hi @Hossein.Margani,

I wonder if capturing the exit code for the Chocolatey process and feeding that back to the Octopus Task is the best way forward?

$process = Start-Process `
  -NoNewWindow `
  -FilePath "$env:ChocolateyInstall\bin\choco.exe" `
  -ArgumentList "upgrade all -y" `
  -PassThru `
  -Wait

$exitCode = $process.ExitCode
if ($exitCode -eq 0){
    exit 0
} else {
    exit $exitCode
}

Adding the -Wait and -PassThru parameters will force the task to wait for the process to finish before resuming.

I wrote the above inside the forum message box, so I haven’t had a chance to test it and it may be inaccurate syntactically however, this may be something that will allow the PowerShell process to exit upon successful installation of Chocolatey.

Kind Regards,
Adam

33

Thank you Adam,

I will check it.

34

The code had no problem, but it didn’t make any difference.
The only thing I see is that when I manually end postman setup process, Octopus shows an error instead of success.

35

Hi @Hossein.Margani,

Would you be able to send over a raw task log for one of the deployments you tried that errored out?
You should be able to upload it for me to view here: Support Files.

Would it maybe be worth it to capture the output of the process? I also wonder if you’re able to attach a full version of the script you’re running; to allow me to attempt a 1:1 repro of the issue.

Kind Regards,
Adam

36

I uploaded the raw logs.
Here is the complete script for the runbook:

$ErrorActionPreference = 'Stop'

$process = Start-Process `
  -NoNewWindow `
  -FilePath "$env:ChocolateyInstall\bin\choco.exe" `
  -ArgumentList "upgrade all -y" `
  -PassThru `
  -Wait

$exitCode = $process.ExitCode
if ($exitCode -eq 0){
    exit 0
} else {
    exit $exitCode
}

And remember the raw log now shows that the task is finished with an error, but it was actually hanging, and it exited because I ended the process for postman setup.

For reproducing I think you can run choco install postman --version 7.33.1 to install version v7.33.1 on a machine, and then run a runbook with above script on that machine.

37

Hey @Hossein.Margani,

Thanks for providing that script.

So to make sure I know the process; this script is looking to update all applications previously installed with Chocolatey and at the moment the only package being updated is Postman?

Kind Regards,
Adam

38

Yes that is correct Adam.

39

Hi @Hossein.Margani,

Unfortunately, I have some bad news.

My testing had similar results to your own; my install for Postman was hanging and, even though successful on the host machine, wouldn’t report back to Octopus to say the process had been completed.

I tried several methods to work around this but to no avail.

I then tried with an application other than Postman: notepadplusplus.

Installing Notepad++ version 8.1.9.2 to my system using Chocolatey:
image

I then ran the script within Octopus to upgrade Notepad++:
choco upgrade notepadplusplus -y

image
image1020×599 102 KB

Success, but why? After further investigation, I found that other people were complaining about Postman hanging on install on specific versions; I wonder if this is the reason why we’re both experiencing this behaviour?

I’d recommend, for now, until Postman can release an upgrade that allows for installing in a non-interactive window, you can add a pin to the current postman version to exclude it from upgrade all calls.

$choco = "$env:ChocolateyInstall/bin/choco.exe"
$postmanVersion = (.$choco list --local-only "postman")[1].Split(" ")[1]
.$choco pin add --name="postman" --version=$postmanVersion
.$choco upgrade all -y
.$choco pin remove --name="postman"

The above command should find whatever version the current system is running of Postman, add that version to a Chocolatey pin, upgrade all other applications and then remove the pin from Postman.

I hope this helps, and my apologies I couldn’t find a better solution for you; hopefully, the next version of Postman allows sleeker installs via Chocolatey.

Kind Regards,
Adam

40

Thank you Adam,

That’s actually a good news that I am not alone.

Thank you very much, I found another chocolatey package which was complaining about disk space during upgrade via a popup dialog, which also made the Octopus task hanging.

Unfortunately we don’t know about such a process hanging until it happens.
I was wondering if we can kill the upgrade process when it happens or after a timeout.

41

Hi @Hossein.Margani,

You should be able to use the script quoted above to kill a task if the run-time goes above a specified value, you can also redirect stderr and stdout to a file to view.

I took the liberty of modifying the script to fit your use case and also include the pinning method I used earlier to stop Postman from updating.

For easy access, you can save this file to an artefact within the deployment, allowing you to access the files from the task view.

# Leave this low as you will want the process to get killed in the try block if it's still running.
$maximumRuntimeSeconds = 5

# Add Postman Pin
$choco = "$env:ChocolateyInstall/bin/choco.exe"
$postmanVersion = (.$choco list --local-only "postman")[1].Split(" ")[1]
.$choco pin add --name="postman" --version=$postmanVersion

# Specify Process as Chocolatey Upgrade with output redirection
$process = Start-Process -FilePath powershell.exe -ArgumentList '.$choco upgrade all -y' -PassThru -RedirectStandardOutput stdout.txt -RedirectStandardError stderr.txt

# Specify Choco update timeout - Set to 10 minutes.
Start-Sleep -s 1200

try
{
    $process | Wait-Process -Timeout $maximumRuntimeSeconds -ErrorAction Stop
    Write-Warning -Message 'Process successfully completed within the timeout.'
}
catch
{
    Write-Warning -Message 'Process exceeded timeout, will be killed now.'
    $process | Stop-Process -Force
}

# Remove Postman Pin
.$choco pin remove --name="postman"

# Create Artifacts for output
New-OctopusArtifact "stdout.txt"
New-OctopusArtifact "stderr.txt"

I hope this helps! Let me know if you’re able to get it running as you’d like.

Kind Regards,
Adam

42

This topic was automatically closed 31 days after the last reply. New replies are no longer allowed.