Unable to force restore registry modules

[martinjanocko]

Bicep version > az bicep version
Bicep CLI version 0.23.1 (b02de2da48)

> az --version azure-cli 2.55.0

core 2.55.0 telemetry 1.1.0

Dependencies: msal 1.24.0b2 azure-mgmt-resource 23.1.0b2

Python location 'C:\Program Files (x86)\Microsoft SDKs\Azure\CLI2\python.exe' Extensions directory 'C:\Users\work.azure\cliextensions'

Python (Windows) 3.11.5 (tags/v3.11.5:cce6ba9, Aug 24 2023, 14:21:31) [MSC v.1936 32 bit (Intel)]

Describe the bug When running az bicep restore -f .\main.bicep --force following error is displayed:

Error BCP190: The module with reference "br:\<redacted-registry>.azurecr.io/bicepmodules/messagingservice:default" has not been restored.

When running az bicep restore -f .\main.bicep the modules are restored as expected.

I am successfully logged in with az login. Deleting cache at %USERPROFILE%\.bicep\br\ does not seem to make a difference.

To Reproduce Steps to reproduce the behavior:

1. Run az bicep restore -f .\main.bicep --force with main.bicep containing a reference to azure registry.

Additional context

> az bicep restore -f .\main.bicep --force --debug
cli.knack.cli: Command arguments: ['bicep', 'restore', '-f', '.\\main.bicep', '--force', '--debug']
cli.knack.cli: __init__ debug log:
Enable color in terminal.
cli.knack.cli: Event: Cli.PreExecute []
cli.knack.cli: Event: CommandParser.OnGlobalArgumentsCreate [<function CLILogging.on_global_arguments at 0x0189E7F8>, <function OutputProducer.on_global_arguments at 0x01BC68E8>, <function CLIQuery.on_global_arguments at 0x01BE86B8>]
cli.knack.cli: Event: CommandInvoker.OnPreCommandTableCreate []
cli.azure.cli.core: Modules found from index for 'bicep': ['azure.cli.command_modules.resource']
cli.azure.cli.core: Loading command modules:
cli.azure.cli.core: Name                  Load Time    Groups  Commands
cli.azure.cli.core: resource                  0.111        51       228
cli.azure.cli.core: Total (1)                 0.111        51       228
cli.azure.cli.core: Loaded 51 groups, 228 commands.
cli.azure.cli.core: Found a match in the command table.
cli.azure.cli.core: Raw command  : bicep restore
cli.azure.cli.core: Command table: bicep restore
cli.knack.cli: Event: CommandInvoker.OnPreCommandTableTruncate [<function AzCliLogging.init_command_file_logging at 0x03CEBED8>]
cli.azure.cli.core.azlogging: metadata file logging enabled - writing logs to 'C:\Users\work\.azure\commands\2023-12-14.10-30-16.bicep_restore.39464.log'.
az_command_data_logger: command args: bicep restore -f {} --force --debug
cli.knack.cli: Event: CommandInvoker.OnPreArgumentLoad [<function register_global_subscription_argument.<locals>.add_subscription_parameter at 0x03D25028>]
cli.knack.cli: Event: CommandInvoker.OnPostArgumentLoad []
cli.knack.cli: Event: CommandInvoker.OnPostCommandTableCreate [<function register_ids_argument.<locals>.add_ids_arguments at 0x03D2E398>, <function register_cache_arguments.<locals>.add_cache_arguments at 0x03D2E3E8>]
cli.knack.cli: Event: CommandInvoker.OnCommandTableLoaded []
cli.knack.cli: Event: CommandInvoker.OnPreParseArgs []
cli.knack.cli: Event: CommandInvoker.OnPostParseArgs [<function OutputProducer.handle_output_argument at 0x01BC6938>, <function CLIQuery.handle_query_parameter at 0x01BE8708>, <function register_ids_argument.<locals>.parse_ids_arguments at 0x03D2E348>]
cli.azure.cli.command_modules.resource._bicep: Current value of "use_binary_from_path": false.
cli.azure.cli.command_modules.resource._bicep: Bicep CLI installation path: C:\Users\work\.azure\bin\bicep.exe
cli.azure.cli.command_modules.resource._bicep: Bicep CLI installed: True.
cli.azure.cli.core.azclierror: Traceback (most recent call last):
  File "D:\a\_work\1\s\build_scripts\windows\artifacts\cli\Lib\site-packages\azure/cli/command_modules/resource/_bicep.py", line 312, in _run_command
  File "subprocess.py", line 502, in check_returncode
subprocess.CalledProcessError: Command '['C:\\Users\\work\\.azure\\bin\\bicep.exe', 'restore', '.\\main.bicep', '--force']' returned non-zero exit status 1.

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "D:\a\_work\1\s\build_scripts\windows\artifacts\cli\Lib\site-packages\knack/cli.py", line 233, in invoke
  File "D:\a\_work\1\s\build_scripts\windows\artifacts\cli\Lib\site-packages\azure/cli/core/commands/__init__.py", line 663, in execute
  File "D:\a\_work\1\s\build_scripts\windows\artifacts\cli\Lib\site-packages\azure/cli/core/commands/__init__.py", line 726, in _run_jobs_serially
  File "D:\a\_work\1\s\build_scripts\windows\artifacts\cli\Lib\site-packages\azure/cli/core/commands/__init__.py", line 697, in _run_job
  File "D:\a\_work\1\s\build_scripts\windows\artifacts\cli\Lib\site-packages\azure/cli/core/commands/__init__.py", line 333, in __call__
  File "D:\a\_work\1\s\build_scripts\windows\artifacts\cli\Lib\site-packages\azure/cli/core/commands/command_operation.py", line 121, in handler
  File "D:\a\_work\1\s\build_scripts\windows\artifacts\cli\Lib\site-packages\azure/cli/command_modules/resource/custom.py", line 4559, in restore_bicep_file
  File "D:\a\_work\1\s\build_scripts\windows\artifacts\cli\Lib\site-packages\azure/cli/command_modules/resource/_bicep.py", line 107, in run_bicep_command
  File "D:\a\_work\1\s\build_scripts\windows\artifacts\cli\Lib\site-packages\azure/cli/command_modules/resource/_bicep.py", line 328, in _run_command
azure.cli.core.azclierror.UnclassifiedUserFault: <redacted-bicep-path>(25,32) : Error BCP190: The module with reference "br:<redacted-registry>.azurecr.io/bicepmodules/messagingservice:default" has not been restored.

cli.azure.cli.core.azclierror: <redacted-bicep-path>(25,32) : Error BCP190: The module with reference "br:<redacted-registry>.azurecr.io/bicepmodules/messagingservice:default" has not been restored.
az_command_data_logger: <redacted-bicep-path>(25,32) : Error BCP190: The module with reference "br:<redacted-registry>.azurecr.io/bicepmodules/messagingservice:default" has not been restored.
cli.knack.cli: Event: Cli.PostExecute [<function AzCliLogging.deinit_cmd_metadata_logging at 0x03CF0078>]
az_command_data_logger: exit code: 1
cli.__main__: Command ran in 6.466 seconds (init: 0.266, invoke: 6.200)
telemetry.main: Begin splitting cli events and extra events, total events: 1
telemetry.client: Accumulated 0 events. Flush the clients.
telemetry.main: Finish splitting cli events and extra events, cli events: 1
telemetry.save: Save telemetry record of length 3629 in cache
telemetry.main: Begin creating telemetry upload process.
telemetry.process: Creating upload process: "C:\Program Files (x86)\Microsoft SDKs\Azure\CLI2\python.exe C:\Program Files (x86)\Microsoft SDKs\Azure\CLI2\Lib\site-packages\azure\cli\telemetry\__init__.pyc C:\Users\work\.azure"
telemetry.process: Return from creating process
telemetry.main: Finish creating telemetry upload process.

[majastrz]

@martinjanocko We won't be able to figure out the root cause without more detailed logs. Could you set the following environment variables before running the command that is failing?

  BICEP_TRACING_ENABLED: True
  BICEP_TRACING_VERBOSITY: Full

[martinjanocko]

hi, running the latest Bicep CLI version 0.25.53 (c0ad57dff6) i am no longer able to reproduce this issue. thanks for your help!

[majastrz]

Thanks for confirming!

[martinjanocko]

@majastrz even though i could not reproduce the issue locally, it surfaced again in one of our deployment pipelines.

the setup is:

main.bicep
  - br:<redacted>.azurecr.io/bicepmodules/storageaccount:default
  - br:<redacted>.azurecr.io/bicepmodules/keyvault-add:default
  - br:<redacted>.azurecr.io/bicepmodules/auto-serviceplan:default
  - function.bicep
    - br:<redacted>.azurecr.io/bicepmodules/functionapp-v2:default

calling restore

az bicep install --version v0.25.53

$env:BICEP_TRACING_ENABLED = "True"
$env:BICEP_TRACING_VERBOSITY = "Full"

az bicep restore --file main.bicep --force --debug

For each bicep module i can see TRACE: Authenticated attempt to pull artifact .. except for the functionapp-v2 referenced in functionapp.bicep file.

Task log attached with debug and tracing enabled. restore-task.log

If you could have a look that would be greatly appreciated. Thank you!

[majastrz]

It appears that we are not even attempting to restore br:<redacted>.azurecr.io/bicepmodules/functionapp-v2:default. I attempted to recreate the project structure on my end and was unable to reproduce the behavior 😟.

1. Does this happen consistently or intermittently?
2. What happens if you do bicep build instead of bicep restore? Are there any build errors or warnings?

[martinjanocko]

Hi, I can't reproduce this locally. This issue appears when running Azure pipeline on MS hosted agent with vmImage: windows-latest and the az bicep restore is part of a AzureCli task. I have not tested private agents, different image or tasks.

1. this happens consistently with newer bicep versions. Last known working version is v0.21.1.
2. bicep build works as expected, no errors and trace contains TRACE: Authenticated attempt to pull artifact for module br:<redacted>.azurecr.io/bicepmodules/functionapp-v2:default.

From further testing it seems like the --force parameter causes the issue. Calling az bicep restore --file main.bicep succeeds as expected and trace logs contain TRACE: Authenticated attempt to pull artifact for module br:<redacted>.azurecr.io/bicepmodules/functionapp-v2:default.