search

Azure / azure-cli

Azure Command-Line Interface
MIT License
4k stars 2.98k forks source link

az containerapp commands output error on stderr #29980

Open dsczltch opened 3 weeks ago

dsczltch commented 3 weeks ago

Describe the bug

The command writes error to the standard output which makes it fail in CI pipeline. az containerapp command often display error information on the standard output. Therefore we need to use the failOnStdErr option to true (in Azure DevOps) to fail the task when this happen. However, since wednesday 25 september, some output errors are displayed even when it works well, which makes all our deployments to fail.

Related command

az containerapp update

Errors

[error]

/ Running .. | Running ..

[error]Script has output to stderr. Failing as failOnStdErr is set to true.

Issue script & Debug output

2024-09-26T09:30:59.3832601Z | Running ..DEBUG: cli.azure.cli.core.util: Found subscription ID SUBSCRIPTION_ID_MASKED in the URL https://management.azure.com/subscriptions/SUBSCRIPTION_ID_MASKED/providers/Microsoft.App/locations/francecentral/containerappOperationResults/037ac9fc-90a0-4fec-8d71-9308298b56df?api-version=2024-03-01&t=638629398441513134&c=MASKED 2024-09-26T09:30:59.3841654Z DEBUG: cli.azure.cli.core.util: Retrieving token for resource https://management.core.windows.net/, subscription SUBSCRIPTION_ID_MASKED 2024-09-26T09:30:59.3843010Z DEBUG: urllib3.util.retry: Converted retries value: 1 -> Retry(total=1, connect=None, read=None, redirect=None, status=None) 2024-09-26T09:30:59.3844736Z DEBUG: msal.authority: Initializing with Entra authority: https://login.microsoftonline.com/ID_MASKED 2024-09-26T09:30:59.3849979Z DEBUG: msal.authority: openid_config("https://login.microsoftonline.com/ID_MASKED/v2.0/.well-known/openid-configuration") = {'token_endpoint': 'https://login.microsoftonline.com/ID_MASKED/oauth2/v2.0/token', 'token_endpoint_auth_methods_supported': ['client_secret_post', 'private_key_jwt', 'client_secret_basic'], 'jwks_uri': 'https://login.microsoftonline.com/ID_MASKED/discovery/v2.0/keys', 'response_modes_supported': ['query', 'fragment', 'form_post'], 'subject_types_supported': ['pairwise'], 'id_token_signing_alg_values_supported': ['RS256'], 'response_types_supported': ['code', 'id_token', 'code id_token', 'id_token token'], 'scopes_supported': ['openid', 'profile', 'email', 'offline_access'], 'issuer': 'https://login.microsoftonline.com/ID_MASKED/v2.0', 'request_uri_parameter_supported': False, 'userinfo_endpoint': 'https://graph.microsoft.com/oidc/userinfo', 'authorization_endpoint': 'https://login.microsoftonline.com/ID_MASKED/oauth2/v2.0/authorize', 'device_authorization_endpoint': 'https://login.microsoftonline.com/ID_MASKED/oauth2/v2.0/devicecode', 'http_logout_supported': True, 'frontchannel_logout_supported': True, 'end_session_endpoint': 'https://login.microsoftonline.com/ID_MASKED/oauth2/v2.0/logout', 'claims_supported': ['sub', 'iss', 'cloud_instance_name', 'cloud_instance_host_name', 'cloud_graph_host_name', 'msgraph_host', 'aud', 'exp', 'iat', 'auth_time', 'acr', 'nonce', 'preferred_username', 'name', 'tid', 'ver', 'at_hash', 'c_hash', 'email'], 'kerberos_endpoint': 'https://login.microsoftonline.com/ID_MASKED/kerberos', 'tenant_region_scope': 'EU', 'cloud_instance_name': 'microsoftonline.com', 'cloud_graph_host_name': 'graph.windows.net', 'msgraph_host': 'graph.microsoft.com', 'rbac_url': 'https://pas.windows.net'} 2024-09-26T09:30:59.3855136Z DEBUG: msal.application: Broker enabled? None 2024-09-26T09:30:59.3857140Z DEBUG: cli.azure.cli.core.auth.msal_authentication: ServicePrincipalCredential.get_token: scopes=('https://management.core.windows.net//.default',), kwargs={} 2024-09-26T09:30:59.3858330Z DEBUG: msal.application: Cache hit an AT 2024-09-26T09:30:59.3859438Z DEBUG: msal.telemetry: Generate or reuse correlation_id: 3452927f-d457-401b-ab57-c29d5fde9972 2024-09-26T09:30:59.3868981Z INFO: cli.azure.cli.core.util: Request URL: 'https://management.azure.com/subscriptions/SUBSCRIPTION_ID_MASKED/providers/Microsoft.App/locations/francecentral/containerappOperationResults/037ac9fc-90a0-4fec-8d71-9308298b56df?api-version=2024-03-01&t=638629398441513134&c=MASKED' 2024-09-26T09:30:59.3878031Z INFO: cli.azure.cli.core.util: Request method: 'GET' 2024-09-26T09:30:59.3879021Z INFO: cli.azure.cli.core.util: Request headers: 2024-09-26T09:30:59.3880359Z INFO: cli.azure.cli.core.util: 'User-Agent': 'python/3.11.8 (Linux-5.15.153.1-1.cm2-x86_64-with-glibc2.36) AZURECLI/2.64.0 (DEB) VSTS_151c32f3-f21f-4434-8b15-25c958202171_build_364_0' 2024-09-26T09:30:59.3881690Z INFO: cli.azure.cli.core.util: 'Accept-Encoding': 'gzip, deflate' 2024-09-26T09:30:59.3882688Z INFO: cli.azure.cli.core.util: 'Accept': '/' 2024-09-26T09:30:59.3883683Z INFO: cli.azure.cli.core.util: 'Connection': 'keep-alive' 2024-09-26T09:30:59.3884813Z INFO: cli.azure.cli.core.util: 'x-ms-client-request-id': '22bad57d-398e-41d8-a352-fefd60f0cfcb' 2024-09-26T09:30:59.3885917Z INFO: cli.azure.cli.core.util: 'CommandName': 'containerapp update' 2024-09-26T09:30:59.3887051Z INFO: cli.azure.cli.core.util: 'ParameterSetName': '--name --resource-group --image --debug' 2024-09-26T09:30:59.3888275Z INFO: cli.azure.cli.core.util: 'Authorization': 'Bearer 2024-09-26T09:30:59.3889236Z INFO: cli.azure.cli.core.util: Request body: 2024-09-26T09:30:59.3890142Z INFO: cli.azure.cli.core.util: None 2024-09-26T09:30:59.3891175Z DEBUG: urllib3.connectionpool: Starting new HTTPS connection (1): management.azure.com:443 2024-09-26T09:30:59.7105448Z DEBUG: urllib3.connectionpool: https://management.azure.com:443 "GET /subscriptions/SUBSCRIPTION_ID_MASKED/providers/Microsoft.App/locations/francecentral/containerappOperationResults/037ac9fc-90a0-4fec-8d71-9308298b56df?api-version=2024-03-01&t=638629398441513134&c=MASKED HTTP/1.1" 200 3661 2024-09-26T09:30:59.7120179Z INFO: cli.azure.cli.core.util: Response status: 200 2024-09-26T09:30:59.7121210Z INFO: cli.azure.cli.core.util: Response headers: 2024-09-26T09:30:59.7122266Z INFO: cli.azure.cli.core.util: 'Cache-Control': 'no-cache' 2024-09-26T09:30:59.7123469Z INFO: cli.azure.cli.core.util: 'Pragma': 'no-cache' 2024-09-26T09:30:59.7124558Z INFO: cli.azure.cli.core.util: 'Content-Length': '3661' 2024-09-26T09:30:59.7125721Z INFO: cli.azure.cli.core.util: 'Content-Type': 'application/json; charset=utf-8' 2024-09-26T09:30:59.7126856Z INFO: cli.azure.cli.core.util: 'Expires': '-1' 2024-09-26T09:30:59.7128197Z INFO: cli.azure.cli.core.util: 'Vary': 'Accept-Encoding' 2024-09-26T09:30:59.7129525Z INFO: cli.azure.cli.core.util: 'x-ms-ratelimit-remaining-subscription-reads': '249' 2024-09-26T09:30:59.7131461Z INFO: cli.azure.cli.core.util: 'api-supported-versions': '2022-03-01, 2022-06-01-preview, 2022-10-01, 2022-11-01-preview, 2023-04-01-preview, 2023-05-01, 2023-05-02-preview, 2023-08-01-preview, 2023-11-02-preview, 2024-02-02-preview, 2024-03-01, 2024-08-02-preview' 2024-09-26T09:30:59.7132874Z INFO: cli.azure.cli.core.util: 'X-Powered-By': 'ASP.NET' 2024-09-26T09:30:59.7133987Z INFO: cli.azure.cli.core.util: 'x-ms-ratelimit-remaining-subscription-global-reads': '3749' 2024-09-26T09:30:59.7135387Z INFO: cli.azure.cli.core.util: 'x-ms-request-id': '917b7f86-4366-43a7-bdb8-e7d89feb56e6' 2024-09-26T09:30:59.7137270Z INFO: cli.azure.cli.core.util: 'x-ms-correlation-request-id': '917b7f86-4366-43a7-bdb8-e7d89feb56e6' 2024-09-26T09:30:59.7139284Z INFO: cli.azure.cli.core.util: 'x-ms-routing-request-id': 'FRANCECENTRAL:20240926T093059Z:917b7f86-4366-43a7-bdb8-e7d89feb56e6' 2024-09-26T09:30:59.7140516Z INFO: cli.azure.cli.core.util: 'Strict-Transport-Security': 'max-age=31536000; includeSubDomains' 2024-09-26T09:30:59.7141621Z INFO: cli.azure.cli.core.util: 'X-Content-Type-Options': 'nosniff' 2024-09-26T09:30:59.7142633Z INFO: cli.azure.cli.core.util: 'X-Cache': 'CONFIG_NOCACHE' 2024-09-26T09:30:59.7143821Z INFO: cli.azure.cli.core.util: 'X-MSEdge-Ref': 'Ref A: 7E049269CF2C4082ABD6ED3B7ACAF824 Ref B: VIEEDGE1910 Ref C: 2024-09-26T09:30:59Z' 2024-09-26T09:30:59.7144968Z INFO: cli.azure.cli.core.util: 'Date': 'Thu, 26 Sep 2024 09:30:59 GMT' 2024-09-26T09:30:59.7146169Z INFO: cli.azure.cli.core.util: Response content: 2024-09-26T09:30:59.7155227Z INFO: cli.azure.cli.core.util: {"id":"/subscriptions/SUBSCRIPTION_ID_MASKED/resourceGroups/do1-compute-rg/providers/Microsoft.App/containerapps/do1-NAME_MASKED-ca","name":"do1-NAME_MASKED-ca","type":"Microsoft.App/containerApps","location":"France Central","tags":{"Component":"NAME_MASKED","Creator":"Terraform","Env":"do1","ProjectName":"NAME_MASKED.com"},"systemData":{"createdBy":"","createdByType":"Application","createdAt":"2024-06-27T13:01:22.7476807","lastModifiedBy":"***","lastModifiedByType":"Application","lastModifiedAt":"2024-09-26T09:30:43.9638161"},"properties":{"provisioningState":"Succeeded","runningStatus":"Running","managedEnvironmentId":"/subscriptions/SUBSCRIPTION_ID_MASKED/resourceGroups/do1-compute-rg/providers/Microsoft.App/managedEnvironments/do1-shared-cae","environmentId":"/subscriptions/SUBSCRIPTION_ID_MASKED/resourceGroups/do1-compute-rg/providers/Microsoft.App/managedEnvironments/do1-shared-cae","workloadProfileName":"Consumption","outboundIpAddresses":null,"latestRevisionName":"do1-NAME_MASKED-ca--drhar7n","latestReadyRevisionName":"do1-NAME_MASKED-ca--drhar7n","latestRevisionFqdn":"do1-NAME_MASKED-ca--drhar7n.CONTAINER_APP_ENV_MASKED.francecentral.azurecontainerapps.io","customDomainVerificationId":"A453E6FA0E0DEB19EC0CB32F1BB8C43B0B2FA0A1D243136A9B09BA36A8535493","configuration":{"secrets":[{"name":"acrsecret"}],"activeRevisionsMode":"Single","ingress":{"fqdn":"do1-NAME_MASKED-ca.CONTAINER_APP_ENV_MASKED.francecentral.azurecontainerapps.io","external":true,"targetPort":8080,"exposedPort":0,"transport":"Auto","traffic":[{"weight":100,"latestRevision":true}],"customDomains":[{"name":"NAME_MASKED.do1.NAME_MASKED.work","certificateId":"/subscriptions/SUBSCRIPTION_ID_MASKED/resourceGroups/do1-compute-rg/providers/Microsoft.App/managedEnvironments/do1-shared-cae/certificates/NAME_MASKED-work-certificate-secondary","bindingType":"SniEnabled"}],"allowInsecure":false,"ipSecurityRestrictions":null,"corsPolicy":null,"clientCertificateMode":null,"stickySessions":null,"additionalPortMappings":null},"registries":[{"server":"ACR_MASKED.azurecr.io","username":"ACR_MASKED","passwordSecretRef":"acrsecret","identity":""}],"dapr":null,"maxInactiveRevisions":100,"service":null},"template":{"revisionSuffix":"","terminationGracePeriodSeconds":null,"containers":[{"image":"ACR_MASKED.azurecr.io/api-NAME_MASKED:20240926-2-123326","name":"do1-NAME_MASKED-ca","env":[{"name":"env","value":"do1"},{"name":"ASPNETCORE_ENVIRONMENT","value":"do1"},{"name":"ASPNETCORE_FORWARDEDHEADERS_ENABLED","value":"true"},{"name":"IS_CONTAINER_APP","value":"true"}],"resources":{"cpu":0.25,"memory":"0.5Gi","ephemeralStorage":"1Gi"},"probes":[],"volumeMounts":[{"volumeName":"do1-shared-cae-storage","mountPath":"/do1sharedcaefs"}]}],"initContainers":null,"scale":{"minReplicas":1,"maxReplicas":5,"rules":[{"name":"memoryscalerule","custom":{"type":"memory","metadata":{"type":"Utilization","value":"70"}}},{"name":"cpuscalerule","custom":{"type":"cpu","metadata":{"type":"Utilization","value":"70"}}}]},"volumes":[{"name":"do1-shared-cae-storage","storageType":"AzureFile","storageName":"do1-shared-cae-storage"}],"serviceBinds":null},"eventStreamEndpoint":"https://francecentral.azurecontainerapps.dev/subscriptions/SUBSCRIPTION_ID_MASKED/resourceGroups/do1-compute-rg/containerApps/do1-NAME_MASKED-ca/eventstream","delegatedIdentities":[]},"identity":{"type":"SystemAssigned","principalId":"c25dd8b0-62ba-4931-8062-040fb1c0cd8f","tenantId":"ID_MASKED"}} 2024-09-26T09:30:59.7161515Z 2024-09-26T09:30:59.7162799Z DEBUG: cli.knack.cli: Event: CommandInvoker.OnTransformResult [<function _resource_group_transform at 0x7462aad9b560>, <function _x509_from_base64_to_hex_transform at 0x7462aad9b600>] 2024-09-26T09:30:59.7163982Z DEBUG: cli.knack.cli: Event: CommandInvoker.OnFilterResult [] 2024-09-26T09:30:59.7165014Z DEBUG: cli.knack.cli: Event: Cli.SuccessfulExecute [] 2024-09-26T09:30:59.7166078Z DEBUG: cli.knack.cli: Event: Cli.PostExecute [<function AzCliLogging.deinit_cmd_metadata_logging at 0x7462aafc6160>] 2024-09-26T09:30:59.7167084Z INFO: az_command_data_logger: exit code: 0 2024-09-26T09:30:59.7168059Z INFO: cli.main: Command ran in 17.402 seconds (init: 0.102, invoke: 17.300) 2024-09-26T09:30:59.7423970Z INFO: telemetry.main: Begin splitting cli events and extra events, total events: 1 2024-09-26T09:30:59.7425355Z INFO: telemetry.client: Accumulated 0 events. Flush the clients. 2024-09-26T09:30:59.7426906Z INFO: telemetry.main: Finish splitting cli events and extra events, cli events: 1 2024-09-26T09:30:59.7429221Z INFO: telemetry.save: Save telemetry record of length 3763 in cache file under /azp/_work/_temp/.azclitask/telemetry/20240926093059742 2024-09-26T09:30:59.7431339Z INFO: telemetry.main: Begin creating telemetry upload process. 2024-09-26T09:30:59.7434512Z INFO: telemetry.process: Creating upload process: "/opt/az/bin/python3 /opt/az/lib/python3.11/site-packages/azure/cli/telemetry/init.py /azp/_work/_temp/.azclitask /azp/_work/_temp/.azclitask/telemetry/20240926093059742" 2024-09-26T09:30:59.7437048Z INFO: telemetry.process: Return from creating process 1499 2024-09-26T09:30:59.7438570Z INFO: telemetry.main: Finish creating telemetry upload process. 2024-09-26T09:30:59.8240949Z URL to check: do1-NAME_MASKED-ca--drhar7n.CONTAINER_APP_ENV_MASKED.francecentral.azurecontainerapps.io 2024-09-26T09:30:59.8303755Z Attempt N°1 (do1-NAME_MASKED-ca--drhar7n.CONTAINER_APP_ENV_MASKED.francecentral.azurecontainerapps.io) 2024-09-26T09:31:00.0738241Z Status code 200. 2024-09-26T09:31:00.0739951Z The healthcheck process succeeded. 2024-09-26T09:31:00.1365239Z 2024-09-26T09:31:00.1443752Z ##[error]DEBUG: cli.knack.cli: Command arguments: ['containerapp', 'update', '--name', 'do1-NAME_MASKED-ca', '--resource-group', 'do1-compute-rg', '--image', 'ACR_MASKED.azurecr.io/api-NAME_MASKED:20240926-2-123326', '--debug'] DEBUG: cli.knack.cli: init debug log: Cannot enable color. DEBUG: cli.knack.cli: Event: Cli.PreExecute [] DEBUG: cli.knack.cli: Event: CommandParser.OnGlobalArgumentsCreate [<function CLILogging.on_global_arguments at 0x7462abd18180>, <function OutputProducer.on_global_arguments at 0x7462abcc6340>, <function CLIQuery.on_global_arguments at 0x7462abadbe20>] DEBUG: cli.knack.cli: Event: CommandInvoker.OnPreCommandTableCreate [] DEBUG: cli.azure.cli.core: Modules found from index for 'containerapp': ['azure.cli.command_modules.containerapp', 'azure.cli.command_modules.serviceconnector'] DEBUG: cli.azure.cli.core: Loading command modules: DEBUG: cli.azure.cli.core: Name Load Time Groups Commands DEBUG: cli.azure.cli.core: containerapp 0.193 37 123 2024-09-26T09:31:00.1456161Z ##[error]Script has output to stderr. Failing as failOnStdErr is set to true. 2024-09-26T09:31:00.1459929Z [command]/usr/bin/az account clear 2024-09-26T09:31:00.5922083Z ##[section]Finishing: Container : Update image

Expected behavior

The containerapp update command should run correctly without outputing errors on the standard output.

Environment Summary

/usr/bin/az --version azure-cli 2.64.0 core 2.64.0 telemetry 1.1.0 Dependencies: msal 1.30.0 azure-mgmt-resource 23.1.1 Python location '/opt/az/bin/python3' Extensions directory '/home/agent/.azure/cliextensions' Python (Linux) 3.11.8 (main, Aug 28 2024, 05:46:04) [GCC 12.2.0]

Additional context

The environment version of the az cli or other tools has not been upgraded. Therefore, the root cause of the issue might be from the Azure backend since we did not update the cli az.

yonzhan commented 3 weeks ago

Thank you for opening this issue, we will look into it.

JasonRodman commented 2 weeks ago

Any news on this? This started to fail all of our release pipelines today.

celluj34 commented 2 weeks ago

We are also experiencing this error. Not correlated to region, managed instance, number of container apps, vnet, or anything I can tell. This is similarly blocking our PRs due to failOnStdErr set to true.

ranat5 commented 2 weeks ago

We are also experiencing the same issue, changing az-cli version (2.6.0, 2.6.2, 2.64) does not seem to help. Everything was working well, up until a week before & we started noticing this issue without changing anything on our end.

As mentioned in the initial post - its confusing, since the containerApp update works just fine with the changes (even though it throws an error in the logs) and we would like to continue using the failOnStandardError: true flag in our pipeline!

celluj34 commented 2 weeks ago

As mentioned in the initial post - its confusing, since the containerApp update works just fine with the changes (even though it throws an error in the logs) and we would like to continue using the failOnStandardError: true flag in our pipeline!

This is a good point to ensure is highlighted - the new container app revision is still provisioned and started successfully. You can go into the portal to check the Activity Log and see it's running. The only other thing that looks 'off' is the time between the Accepted status and Succeeded status, but I don't know if that's normal or not.

image

sg-vintri commented 2 weeks ago

@yonzhan We are impacted too. Due to this, Azure Pipelines fails and are interrupting our releases. While we could temporarily unblock ourselves by setting "failOnStdErr " to false, this would put us in a risky situation during our production releases as we are allowing the deployments to continue even in case of a potential genuine error.

dsczltch commented 2 weeks ago

@anthonychu could you please have a look to this issue regarding Container App?
It has been opened for 1 week, multiple customers are impacted and it is still not assigned.

ranat5 commented 1 week ago

Any progress on this? It still continues to to be a problem with our deployments in production :(

Greedygre commented 1 week ago

Hi @dsczltch @ranat5 @sg-vintri

The ##[error] / Running .. | Running ..

was log by this code when polling the result of updating containerapp: https://github.com/Azure/azure-cli/blob/095d5249b248b4f6a7df603526a69080523e3f0a/src/azure-cli/azure/cli/command_modules/containerapp/_clients.py#L35

Base on the CLI guidelines

Command output must go to stdout, everything else to stderr (log/status/errors).

So the Running output with stderr.

For a workaround you can add --no-wait, wait a few seconds then check the provisioningState.

Greedygre commented 1 week ago

Hi @dsczltch @ranat5 @sg-vintri

Containerapp side didn't change the logic for log Running ...

I'm curious if your pipeline will fail due to the same error if you run the following command: az acr create -n {acr-name} -g {resource-group-name} --sku Standard --location eastus

It will log Running too.

ranat5 commented 1 week ago

Hi @Greedygre - I tried creating an ACR with the above, and even though it momentarily shows "running" state, it creates it successfully without any error messages (so seems like it does not push the intermediate logs to stderr?). az cli version 2.64.0. Was something fixed?

Greedygre commented 1 week ago

Hi @Greedygre - I tried creating an ACR with the above, and even though it momentarily shows "running" state, it creates it successfully without any error messages (so seems like it does not push the intermediate logs to stderr?). az cli version 2.64.0. Was something fixed?

Do you try create ACR in your pipeline too? I think it will fail pipeline too. Thanks for trying. https://github.com/Azure/azure-cli/blob/72b03fb53cb7426209fe1d3c50532f2aae86f170/src/azure-cli-core/azure/cli/core/commands/progress.py#L175-L185

Base on the code, it push logs to stderr: Image

Update Containerapp momentarily shows "running" state too.