Skip to content

Bicep for Visual Studio cannot load modules from ACR after upgrading to Azure CLI 2.61 #14246

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom
Open
dozer75 opened this issue Jun 7, 2024 · 11 comments · May be fixed by #16872
Open

Bicep for Visual Studio cannot load modules from ACR after upgrading to Azure CLI 2.61 #14246

dozer75 opened this issue Jun 7, 2024 · 11 comments · May be fixed by #16872
Assignees
@StephenWeatherford
Labels
devdiv Related to Bicep tooling efforts in DevDiv investigate P1 This is planned to be completed before the end of a release
Milestone
v0.37

Comments

@dozer75
Copy link

dozer75 commented Jun 7, 2024

Bicep version
az bicep version 0.28.1
Bicep for Visual Studio version 0.28.1.47646
azure CLI 2.61

Describe the bug
Visual Studio fails to load modules from ACR based registries. It gets the exception:

Severity	Code	Description	Project	File	Line	Suppression State
Error (active)	BCP192	Unable to restore the artifact with reference "br:<myacr>.azurecr.io/bicep/modules/my-module:1.0.0": Unhandled exception: Azure.Identity.AuthenticationFailedException: The ChainedTokenCredential failed due to an unhandled exception: Azure CLI authentication timed out.
 ---> Azure.Identity.AuthenticationFailedException: Azure CLI authentication timed out.
   at Azure.Identity.AzureCliCredential.RequestCliAccessTokenAsync(Boolean async, TokenRequestContext context, CancellationToken cancellationToken)
   at Azure.Identity.AzureCliCredential.GetTokenImplAsync(Boolean async, TokenRequestContext requestContext, CancellationToken cancellationToken)
   at Azure.Identity.CredentialDiagnosticScope.FailWrapAndThrow(Exception ex, String additionalMessage, Boolean isCredentialUnavailable)
   at Azure.Identity.AzureCliCredential.GetTokenImplAsync(Boolean async, TokenRequestContext requestContext, CancellationToken cancellationToken)
   at Azure.Identity.AzureCliCredential.GetTokenAsync(TokenRequestContext requestContext, CancellationToken cancellationToken)
   at Azure.Identity.ChainedTokenCredential.GetTokenImplAsync(Boolean async, TokenRequestContext requestContext, CancellationToken cancellationToken)
   --- End of inner exception stack trace ---
   at Azure.Identity.ChainedTokenCredential.GetTokenImplAsync(Boolean async, TokenRequestContext requestContext, CancellationToken cancellationToken)
   at Azure.Identity.ChainedTokenCredential.GetTokenAsync(TokenRequestContext requestContext, CancellationToken cancellationToken)
   at Azure.Containers.ContainerRegistry.ContainerRegistryRefreshTokenCache.GetRefreshTokenFromCredentialAsync(TokenRequestContext context, String service, Boolean async, CancellationToken cancellationToken)
   at Azure.Containers.ContainerRegistry.ContainerRegistryRefreshTokenCache.GetAcrRefreshTokenAsync(HttpMessage message, TokenRequestContext context, String service, Boolean async)
   at Azure.Containers.ContainerRegistry.ContainerRegistryRefreshTokenCache.GetAcrRefreshTokenAsync(HttpMessage message, TokenRequestContext context, String service, Boolean async)
   at Azure.Containers.ContainerRegistry.ContainerRegistryChallengeAuthenticationPolicy.AuthorizeRequestOnChallengeAsyncInternal(HttpMessage message, Boolean async)
   at Azure.Core.Pipeline.BearerTokenAuthenticationPolicy.ProcessAsync(HttpMessage message, ReadOnlyMemory`1 pipeline, Boolean async)
   at Azure.Core.Pipeline.RedirectPolicy.ProcessAsync(HttpMessage message, ReadOnlyMemory`1 pipeline, Boolean async)
   at Azure.Core.Pipeline.RetryPolicy.ProcessAsync(HttpMessage message, ReadOnlyMemory`1 pipeline, Boolean async)
   at Azure.Core.Pipeline.RetryPolicy.ProcessAsync(HttpMessage message, ReadOnlyMemory`1 pipeline, Boolean async)
   at Azure.Containers.ContainerRegistry.ContainerRegistryRestClient.GetManifestAsync(String name, String reference, String accept, CancellationToken cancellationToken)
   at Azure.Containers.ContainerRegistry.ContainerRegistryContentClient.GetManifestInternalAsync(String reference, Boolean async, CancellationToken cancellationToken)
   at Azure.Containers.ContainerRegistry.ContainerRegistryContentClient.GetManifestAsync(String tagOrDigest, CancellationToken cancellationToken)
   at Bicep.Core.Registry.AzureContainerRegistryManager.DownloadManifestAndLayersAsync(IOciArtifactReference artifactReference, ContainerRegistryContentClient client) in C:\__w\1\s\bicep\src\Bicep.Core\Registry\AzureContainerRegistryManager.cs:line 136
   at Bicep.Core.Registry.AzureContainerRegistryManager.<>c__DisplayClass4_0.<<PullArtifactAsync>g__DownloadManifestInternalAsync|0>d.MoveNext() in C:\__w\1\s\bicep\src\Bicep.Core\Registry\AzureContainerRegistryManager.cs:line 43
--- End of stack trace from previous location ---
   at Bicep.Core.Registry.AzureContainerRegistryManager.PullArtifactAsync(RootConfiguration configuration, IOciArtifactReference artifactReference) in C:\__w\1\s\bicep\src\Bicep.Core\Registry\AzureContainerRegistryManager.cs:line 50
   at Bicep.Core.Registry.OciArtifactRegistry.TryRestoreArtifactAsync(RootConfiguration configuration, OciArtifactReference reference) in C:\__w\1\s\bicep\src\Bicep.Core\Registry\OciArtifactRegistry.cs:line 439

I suspect that this is due to the new (horrible) az login experience Azure CLI 2.61 implemented which requires UI based authentication.

To Reproduce
Steps to reproduce the behavior:

  • Ensure that you have Azure CLI 2.61 installed
  • Have an ACR with a module (Ensure that local cache doesn't contains the module already)
  • Reference that module in your bicep file
  • Open Visual Studio and your bicep file

After a short period of time, the error will occur.

Additional context
Running az bicep restore -file <file>.bicep works.
@github-project-automation github-project-automation bot moved this to Todo in Bicep Jun 7, 2024
@anthony-c-martin anthony-c-martin added the devdiv Related to Bicep tooling efforts in DevDiv label Jun 7, 2024
@puicchan puicchan added this to the v0.29 milestone Jun 7, 2024
@StephenWeatherford StephenWeatherford modified the milestones: v0.29, v0.30 Jun 25, 2024
@puicchan puicchan modified the milestones: v0.30, v0.31 Jul 9, 2024
@puicchan
Copy link

puicchan commented Jul 9, 2024

We are still investigating the root cause. Workaround is to use command line for building.

@StephenWeatherford StephenWeatherford modified the milestones: v0.31, v0.32 Nov 1, 2024
@StephenWeatherford StephenWeatherford moved this from Todo to In Progress in Bicep Nov 4, 2024
@StephenWeatherford StephenWeatherford modified the milestones: v0.32, v0.33 Nov 25, 2024
@CloudCees
Copy link

Is there any update on this?

@StephenWeatherford
Copy link
Contributor

@CloudCees Sorry, it's been hard getting time for it. Is this affecting you badly?

@CloudCees
Copy link

@CloudCees Sorry, it's been hard getting time for it. Is this affecting you badly?

We experience this occasionally, and it happened this time as well. After a few tries with az login and restarting VS Code, it magically disappeared.

@StephenWeatherford
Copy link
Contributor

@CloudCees Please note, this bug is referring to Visual Studio, not Visual Studio Code. If you're seeing problems in Visual Studio Code, please enter a new bug with repro steps. Thanks!

@dozer75 Is this still affecting you? Thanks.

@StephenWeatherford StephenWeatherford moved this from In Progress to Todo in Bicep Jan 8, 2025
@dozer75
Copy link
Author

dozer75 commented Jan 8, 2025

@StephenWeatherford

Yes it still does, however it seems to work partially... I have 4 modules in my bicep, but 2 of them fails while 2 works...

To reproduce this now I deleted the .bicep/br folder before I started Visual Studio. Otherwise I followed the steps described.

@puicchan puicchan modified the milestones: v0.33, v0.34 Jan 9, 2025
@puicchan puicchan added P2 This is important to be completed, but you may not get to it P1 This is planned to be completed before the end of a release and removed P2 This is important to be completed, but you may not get to it labels Jan 9, 2025
@stephaniezyen stephaniezyen moved this from Todo to In Progress in Bicep Feb 12, 2025
@stephaniezyen stephaniezyen modified the milestones: v0.34, v0.35 Feb 26, 2025
@StephenWeatherford
Copy link
Contributor

This is quite confusing. Bicep uses AzureCliCredential, which makes a call to "az account get-access-token --output json --resource https://management.azure.com", which in turn calls into python via az.cmd: ..\python.exe -IBm azure.cli az account get-access-token --output json --resource https://management.azure.com

python seems to take an inordinate amount of time starting up (but not when I run this from command line, only from within VS).

From procmon:
process start at 2:55:10
Image
...
And then nothing interesting until 2:56:24:
Image

During the 1.5 min wait (it varies, sometimes it's much faster, sometimes even slower), there is no logging info from az, so I don't think the python code has even started running.

Here's the start of the logging I get from az (starting at 14:56:25):
25472 : 2025-04-09 14:56:25,234 : DEBUG : cli.knack.log : File logging enabled - writing logs to 'C:\Users<user>.Azure\logs'.
25472 : 2025-04-09 14:56:25,234 : DEBUG : cli.knack.cli : Command arguments: ['account', 'get-access-token', '--output', 'json', '--resource', 'https://management.azure.com']
25472 : 2025-04-09 14:56:25,234 : DEBUG : cli.knack.cli : init debug log:
Cannot enable color.
25472 : 2025-04-09 14:56:25,234 : DEBUG : cli.knack.cli : Event: Cli.PreExecute []
25472 : 2025-04-09 14:56:25,235 : DEBUG : cli.knack.cli : Event: CommandParser.OnGlobalArgumentsCreate [<function CLILogging.on_global_arguments at 0x0000016957CB3240>, <function OutputProducer.on_global_arguments at 0x0000016957E4C0E0>, <function CLIQuery.on_global_arguments at 0x0000016957E754E0>]
25472 : 2025-04-09 14:56:25,238 : DEBUG : cli.knack.cli : Event: CommandInvoker.OnPreCommandTableCreate []
25472 : 2025-04-09 14:56:25,240 : DEBUG : cli.azure.cli.core : Modules found from index for 'account': ['azure.cli.command_modules.profile', 'azure.cli.command_modules.resource']
...

So I don't think it's anything that az is doing (like waiting for user input).

Currently AzureCliCredential has a timeout on waiting for az's get-access-token of 18 seconds. I can increase that to, say, 2 min, but it doesn't seem even that's guaranteed.

@StephenWeatherford
Copy link
Contributor

From both "az bicep restore" CLI and vscode, the delay from starting python and the code running is only 1-2 seconds.

@StephenWeatherford
Copy link
Contributor

Image

ntoskrnl.exe!KeSynchronizeExecution+0x8136
ntoskrnl.exe!KeLowerIrql+0x1a05
ntoskrnl.exe!KeLowerIrql+0x2e27
ntoskrnl.exe!KeWaitForSingleObject+0x256
ntoskrnl.exe!ExReleasePushLockSharedEx+0x9d
ntoskrnl.exe!KeUserModeCallback+0x35c
ntoskrnl.exe!CmCallbackGetKeyObjectID+0x9c30
ntoskrnl.exe!setjmpex+0x9115
ntdll.dll!ZwQueryInformationFile+0x14
KERNELBASE.dll!SetFilePointerEx+0xbb
ucrtbase.dll!fputc+0x2ad
ucrtbase.dll!fseeki64+0xee
ucrtbase.dll!lseeki64+0x28
python312.dll!PyThread_allocate_lock+0x474
python312.dll!PyThread_allocate_lock+0x15f
python312.dll!PyUnicode_InsertThousandsGrouping+0x7a8
python312.dll!PyObject_VectorcallMethod+0xab
python312.dll!PyThread_allocate_lock+0x87c
python312.dll!PyThread_allocate_lock+0x81d
python312.dll!PyThread_allocate_lock+0x682
python312.dll!PyThread_allocate_lock+0x5ab
python312.dll!PyObject_Vectorcall+0x427
python312.dll!PyObject_CallFunction_SizeT+0xdf
python312.dll!PyObject_CallFunction_SizeT+0x48
python312.dll!PyObject_CallMethod+0x58a
python312.dll!PyOS_FSPath+0x1d6
python312.dll!PySet_Add+0x60e
python312.dll!PyObject_Vectorcall+0xcf
python312.dll!PyObject_CallFunction_SizeT+0xdf
python312.dll!PyObject_CallMethod+0xd9
python312.dll!PyObject_CallMethod+0x61
python312.dll!PyList_Insert+0x1042
python312.dll!PyList_Insert+0xda5
python312.dll!Py_ClearStandardStreamEncoding+0x18e
python312.dll!Py_InitializeFromConfig+0x108
python312.dll!Py_InitializeFromConfig+0x82
python312.dll!Py_PreInitializeFromPyArgv+0x3e2
python312.dll!Py_Main+0x3d
python312.dll!Py_Main+0x25
python.exe+0x1230
KERNEL32.DLL!BaseThreadInitThunk+0x1d
ntdll.dll!RtlUserThreadStart+0x28

@StephenWeatherford
Copy link
Contributor

StephenWeatherford commented Apr 10, 2025 •
edited
Loading

Don't think it's waiting for user input because it generally succeeds after a while.

Not a run-in-parallel issue like Azure/azure-sdk-for-net#27722 because it repros with only a single restore.

Admin settings won't let me turn off Defender real-time to see if antivirus is the issue.
But adding python.exe to exclusions doesn't affect anything.
Image

Don't think it's Azure/azure-sdk-for-net#32993 because it does work after a random amount of time.

Doesn't repro if I change az.cmd to call python as the argument to tee.

Changing python's process priority doesn't change anything.
I tried changing StartProcessInfo's settings but didn't seem to help.

Haven't tried downgrading to Az CLI < 2.61. Using CLI 2.71.0, python 3.12.8.

@StephenWeatherford
Copy link
Contributor

It does seem pretty consistent that it does succeed, even if it's long. Longest I've seen so far is 160s (2.7min). I hate increasing timeout for that long if it's inconsistent and is timing out because the process is blocking on something, but since it seems consistent, I'll go ahead and increase to 3 or 4 minutes.

@StephenWeatherford StephenWeatherford linked a pull request Apr 10, 2025 that will close this issue
Draft
@stephaniezyen stephaniezyen modified the milestones: v0.35, v0.36 Apr 30, 2025
@stephaniezyen stephaniezyen modified the milestones: v0.36, v0.37 May 30, 2025
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@StephenWeatherford StephenWeatherford

Labels
devdiv Related to Bicep tooling efforts in DevDiv investigate P1 This is planned to be completed before the end of a release
Projects
Bicep
Status: In Progress
Milestone
v0.37
Development

Successfully merging a pull request may close this issue.

Increase timeout for module restore in VS Azure/bicep
6 participants
@CloudCees @StephenWeatherford @dozer75 @puicchan @anthony-c-martin @stephaniezyen