Azure-pipelines-tasks: Powershell task goes into 'debug' mode for some errors which hangs the pipeline forever

[BillyONeal]

Required Information

Entering this information will route you directly to the right team and expedite traction.

Question, Bug, or Feature?
Bug.

Enter Task Name: PowerShell@2

Environment

• Server - Azure Pipelines

  • If using Azure Pipelines, provide the account name, team project name, build definition name/build number: dev.azure.com/vcpkg, "public", "microsoft.vcpkg.pr".

• Agent - Hosted or Private: Private, Windows Server 2019, 1.628.2

Issue Description

This report is in response to the failed build here: https://dev.azure.com/vcpkg/public/_build/results?buildId=37246&view=logs&j=84da4f4a-968a-5b5c-16e9-f444c845396d&t=8cdf6620-a129-5b70-3f3e-822630a64446

You can see our tool, vcpkg, invoked pacman to download some msys2 things, which failed. That all is fine and is our fault for depending on flaky external servers, not the agent. However, after that fails it looks like the task crashes starting from the " Working Directory: C:/agent/_work/1/s/downloads/tools/msys2" line:

Building package ffmpeg[avresample,core]:arm64-windows...
Could not locate cached archive: C:\agent\_work\1\s\archives\dd\dd46a9137e8d69b1bd7857a16f54b496bdf40dfa.zip
-- Downloading https://github.com/ffmpeg/ffmpeg/archive/n4.2.tar.gz...
-- Extracting source C:/agent/_work/1/s/downloads/ffmpeg-ffmpeg-n4.2.tar.gz
-- Applying patch 0001-create-lib-libraries.patch
-- Applying patch 0003-fix-windowsinclude.patch
-- Applying patch 0004-fix-debug-build.patch
-- Applying patch 0005-fix-libvpx-linking.patch
-- Applying patch 0006-fix-StaticFeatures.patch
-- Using source at C:/agent/_work/1/s/buildtrees/ffmpeg/src/n4.2-a4d149a5c6
-- Downloading https://www.tortall.net/projects/yasm/snapshots/v1.3.0.6.g1962/yasm-1.3.0.6.g1962.exe...
-- Installing: C:/agent/_work/1/s/downloads/tools/yasm/1.3.0.6/yasm.exe
-- Acquiring MSYS2...
-- Downloading https://sourceforge.net/projects/msys2/files/Base/x86_64/msys2-base-x86_64-20190524.tar.xz/download...
gpg: /etc/pacman.d/gnupg/trustdb.gpg: trustdb created
gpg: no ultimately trusted keys found
gpg: starting migration from earlier GnuPG versions
gpg: porting secret keys from '/etc/pacman.d/gnupg/secring.gpg' to gpg-agent
gpg: migration succeeded
gpg: Generating pacman keyring master key...
gpg: key 8A01FBB0ECFCE852 marked as ultimately trusted
gpg: directory '/etc/pacman.d/gnupg/openpgp-revocs.d' created
gpg: revocation certificate stored as '/etc/pacman.d/gnupg/openpgp-revocs.d/F341A5A61B865E09770CB3418A01FBB0ECFCE852.rev'
gpg: Done
==> Updating trust database...
gpg: marginals needed: 3  completes needed: 1  trust model: pgp
gpg: depth: 0  valid:   1  signed:   0  trust: 0-, 0q, 0n, 0m, 0f, 1u
==> Appending keys from msys2.gpg...
==> Locally signing trusted keys in keyring...
  -> Locally signing key D55E7A6D7CE9BA1587C0ACACF40D263ECA25678A...
  -> Locally signing key 123D4D51A1793859C2BE916BBBE514E53E0D0813...
  -> Locally signing key B91BCF3303284BF90CC043CA9F418C233E652008...
  -> Locally signing key 9DD0D4217D75A33B896159E6DA7EF2ABAEEA755C...
==> Importing owner trust values...
gpg: setting ownertrust to 4
gpg: setting ownertrust to 4
gpg: setting ownertrust to 4
gpg: inserting ownertrust of 4
==> Updating trust database...
gpg: marginals needed: 3  completes needed: 1  trust model: pgp
gpg: depth: 0  valid:   1  signed:   4  trust: 0-, 0q, 0n, 0m, 0f, 1u
gpg: depth: 1  valid:   4  signed:   3  trust: 0-, 0q, 0n, 4m, 0f, 0u
gpg: depth: 2  valid:   3  signed:   0  trust: 3-, 0q, 0n, 0m, 0f, 0u
:: Synchronizing package databases...
downloading mingw32.db...
downloading mingw32.db.sig...
downloading mingw64.db...
downloading mingw64.db.sig...
downloading msys.db...
downloading msys.db.sig...
:: Starting core system upgrade...
warning: resolving dependencies...
terminate other MSYS2 programs before proceeding
looking for conflicting packages...

Packages (8) bash-4.4.023-2  filesystem-2020.02-2  libzstd-1.4.4-2  mintty-1~3.1.4-1  msys2-runtime-3.1.4-1  pacman-5.2.1-6  pacman-mirrors-20200329-1  zstd-1.4.4-2

Total Download Size:   16.96 MiB
Total Installed Size:  65.76 MiB
Net Upgrade Size:      -3.96 MiB

:: Proceed with installation? [Y/n] 
:: Retrieving packages...
downloading msys2-runtime-3.1.4-1-x86_64.pkg.tar.zst...
downloading bash-4.4.023-2-x86_64.pkg.tar.xz...
downloading filesystem-2020.02-2-x86_64.pkg.tar.xz...
downloading mintty-1~3.1.4-1-x86_64.pkg.tar.xz...
downloading pacman-mirrors-20200329-1-any.pkg.tar.xz...
downloading libzstd-1.4.4-2-x86_64.pkg.tar.xz...
downloading zstd-1.4.4-2-x86_64.pkg.tar.xz...
downloading pacman-5.2.1-6-x86_64.pkg.tar.xz...
checking keyring...
checking package integrity...
loading package files...
error: could not open file /var/cache/pacman/pkg/msys2-runtime-3.1.4-1-x86_64.pkg.tar.zst: Child process exited with status 127
error: failed to commit transaction (cannot open package file)
Errors occurred, no packages were upgraded.
-- Acquiring MSYS2... OK
-- Acquiring MSYS Packages...
CMake Error at scripts/cmake/vcpkg_execute_required_process.cmake:72 (message):
    Command failed: C:/agent/_work/1/s/downloads/tools/msys2/msys64/usr/bin/bash.exe --noprofile --norc -c "pacman -Sy --noconfirm --needed perl gcc diffutils make"
    Working Directory: C:/agent/_work/1/s/downloads/tools/msys2
    Error code: 1
Entering debug mode. Use h or ? for help. 

At 
C:\agent\_work\_tasks\PowerShell_e213ff0f-5d5c-4791-802d-52ea3e7be1f1\2.169.0\ps_modules\VstsTaskSdk\ToolFunctions.ps1:
113 char:13

+         if ($originalEncoding) {

+             ~~~~~~~~~~~~~~~~~
[DBG]: PS C:\agent\_work\1\s>> 

It looks like this line is being highlighted for some reason: https://github.com/microsoft/azure-pipelines-task-lib/blob/c532de60cd68ba382b17d574c669333beabe0b9f/powershell/VstsTaskSdk/ToolFunctions.ps1#L113

Nothing a build does should be putting the whole agent out of commission.

[BillyONeal]

(I'm not sure exactly what is causing it to get stuck but if I had to guess, I'd guess we're emitting something not accepted in the encoding the powershell task thinks we're using)

[strega-nil]

Should we downgrade?

[BillyONeal]

@strega-nil Downgrade what?

[strega-nil]

Azure pipelines

[anatolybolshakov]

Hi @BillyONeal is this issue still reproducable for you?

[BillyONeal]

@anatolybolshakov No but we stopped using PowerShell for this at all as a workaround.

[anatolybolshakov]

@BillyONeal do you use a self-hosted agent? Looks like there was some breakpoint set up, you can retrieve all breakpoints in current powershell session by 'Get-PSBreakpoint' command

[BillyONeal]

It just happened again today: https://dev.azure.com/vcpkg/public/_build/results?buildId=39800&view=logs&j=878666d5-db33-5b27-9e7d-b0c7ee352005&t=3980505e-92f5-53ef-75a8-4f2e70b97516

We use 'Scale Set Agents' and do not have the ability to remote to them. Those machines build arbitrary PRs from GitHub so we are fairly restrictive in terms of the firewall rules we apply (example: https://github.com/BillyONeal/temp-vmss-demo/pull/1/files ).

It looks like PowerShell or Pipelines are attempting to decode and reencode some of this output, and when that fails because some of the results are bogus Unicode or similar the result is PowerShell throwing an exception, resulting in this hang.

[BillyONeal]

I'm now wondering if using pwsh rather than powershell might help?

[anatolybolshakov]

pwsh is using PowerShell Core - if it's installed on agent. I think it could help if there's some Powershell version specific bug... Could you try to swtich on it?

[BillyONeal]

Next time we do a VM deployment I'll see about getting Powershell Core in the image so we can try. Unfortunately the issue is somewhat intermittent and we have not found the exact trigger :(

[anatolybolshakov]

Hi @BillyONeal, do you have any updates about this attempt with Powershell Core?

[BillyONeal]

@anatolybolshakov No, we haven't updated the VMs since we last spoke; that probably won't happen until sometime after August 1st.

[anatolybolshakov]

Ok, thanks - please just let me know once you try it

[anatolybolshakov]

Hi @BillyONeal, have you tried to update VMs, do you have any updates?

[BillyONeal]

No, I intend to do that when I go back to the vcpkg team starting next week.

[BillyONeal]

https://github.com/microsoft/vcpkg/pull/12884/ should turn on pwsh and we'll see if we get stuck again

[anatolybolshakov]

Hi @BillyONeal, I see that microsoft/vcpkg#12884 is merged - do you have any updates with testing it?

[BillyONeal]

We haven't seen it happen yet but it was never a consistent repro. Feel free to close for now and we'll reopen if we see it again.

[anatolybolshakov]

@BillyONeal ok, thanks! I'm closing it at the moment, please feel free to reopen it again if it appears