Application-gateway-kubernetes-ingress: Failed to refresh the Token
Describe the bug
The ingress controller is running for almost 40 days without restarts and issues. Then, a few days ago, without apparent reason fails to refresh the token. Other resources around it, such as mic and nmi did not change, managed identity did not change in the meantime... Note that managed identity has a Reader role on a resource group, where the gateway is located.
I haven't tried to recreate a pod, because I would like to find the root cause first. I have same setup on the production cluster, and I am afraid it can happen there and break my applications.
Does anyone have an idea what might went wrong, and where to look?
To Reproduce
Not sure how to reproduce
Ingress Controller details
- Output of
kubectl describe pod <ingress controller>
Name: fantastic-waterbuffalo-ingress-azure-66b968bbbc-wds6z
Namespace: default
Priority: 0
PriorityClassName: <none>
Node: aks-agentpool-15375443-6/10.0.0.159
Start Time: Fri, 25 Oct 2019 14:02:06 +0200
Labels: aadpodidbinding=fantastic-waterbuffalo-ingress-azure
app=ingress-azure
pod-template-hash=66b968bbbc
release=fantastic-waterbuffalo
Annotations: <none>
Status: Running
IP: 10.0.0.172
Controlled By: ReplicaSet/fantastic-waterbuffalo-ingress-azure-66b968bbbc
Containers:
ingress-azure:
Container ID: docker://553e5262ac6537629f4a90aaf26b38648a8ba287938df454b044c31b84f7d820
Image: mcr.microsoft.com/azure-application-gateway/kubernetes-ingress:0.10.0-rc4
Image ID: docker-pullable://mcr.microsoft.com/azure-application-gateway/kubernetes-ingress@sha256:4579e970084e58ce84f85e783c2e57e2e38fbf22b4204076bc80f7e464475917
Port: <none>
Host Port: <none>
State: Running
Started: Fri, 25 Oct 2019 14:02:30 +0200
Ready: True
Restart Count: 0
Liveness: http-get http://:8123/health/alive delay=15s timeout=1s period=20s #success=1 #failure=3
Readiness: http-get http://:8123/health/ready delay=5s timeout=1s period=10s #success=1 #failure=3
Environment Variables from:
fantastic-waterbuffalo-cm-ingress-azure ConfigMap Optional: false
Environment:
AZURE_CONTEXT_LOCATION: /etc/appgw/azure.json
AGIC_POD_NAME: fantastic-waterbuffalo-ingress-azure-66b968bbbc-wds6z (v1:metadata.name)
AGIC_POD_NAMESPACE: default (v1:metadata.namespace)
KUBERNETES_PORT_443_TCP_ADDR: xxxxxxx
KUBERNETES_PORT: xxxxxx
KUBERNETES_PORT_443_TCP: xxxxx
KUBERNETES_SERVICE_HOST: xxxx
Mounts:
/etc/appgw/azure.json from azure (rw)
/var/run/secrets/kubernetes.io/serviceaccount from fantastic-waterbuffalo-sa-ingress-azure-token-5gwd7 (ro)
Conditions:
Type Status
Initialized True
Ready True
ContainersReady True
PodScheduled True
Volumes:
azure:
Type: HostPath (bare host directory volume)
Path: /etc/kubernetes/azure.json
HostPathType: File
fantastic-waterbuffalo-sa-ingress-azure-token-5gwd7:
Type: Secret (a volume populated by a Secret)
SecretName: fantastic-waterbuffalo-sa-ingress-azure-token-5gwd7
Optional: false
QoS Class: BestEffort
Node-Selectors: <none>
Tolerations: node.kubernetes.io/not-ready:NoExecute for 300s
node.kubernetes.io/unreachable:NoExecute for 300s
Events: <none>
Output of `kubectl logs
.
E1210 12:27:27.393806 1 mutate_app_gateway.go:34] unable to get specified AppGateway [xxx-xx-xx], check AppGateway identifier, error=[azure.BearerAuthorizer#WithAuthorization: Failed to refresh the Token for request to https://management.azure.com/subscriptions/xxx-xx-xx/resourceGroups/xxx-xx-xx/providers/Microsoft.Network/applicationGateways/xxx-xx-xx?api-version=2019-06-01: StatusCode=403 -- Original Error: adal: Refresh request failed. Status Code = '403'. Response body: adal: Refresh request failed. Status Code = '400'. Response body: {"error":"invalid_request","error_description":"Identity not found"} ] E1210 12:27:27.393881 1 worker.go:49] Error mutating AKS from k8s event. unable to get specified AppGateway (CTRL001) E1210 12:27:27.529038 1 mutate_app_gateway.go:34] unable to get specified AppGateway [xxx-xx-xx], check AppGateway identifier, error=[azure.BearerAuthorizer#WithAuthorization: Failed to refresh the Token for request to https://management.azure.com/subscriptions/xxx-xx-xx/resourceGroups/xxx-xx-xx/providers/Microsoft.Network/applicationGateways/xxx-xx-xx?api-version=2019-06-01: StatusCode=403 -- Original Error: adal: Refresh request failed. Status Code = '403'. Response body: adal: Refresh request failed. Status Code = '400'. Response body: {"error":"invalid_request","error_description":"Identity not found"} ] E1210 12:27:27.529097 1 worker.go:53] Error mutating App Gateway config from k8s event. unable to get specified AppGateway (CTRL001) E1210 12:27:32.687335 1 mutate_app_gateway.go:34] unable to get specified AppGateway [xxx-xx-xx], check AppGateway identifier, error=[azure.BearerAuthorizer#WithAuthorization: Failed to refresh the Token for request to https://management.azure.com/subscriptions/xxx-xx-xx/resourceGroups/xxx-xx-xx/providers/Microsoft.Network/applicationGateways/xxx-xx-xx?api-version=2019-06-01: StatusCode=403 -- Original Error: adal: Refresh request failed. Status Code = '403'. Response body: adal: Refresh request failed. Status Code = '400'. Response body: {"error":"invalid_request","error_description":"Identity not found"} ] E1210 12:27:32.687756 1 worker.go:49] Error mutating AKS from k8s event. unable to get specified AppGateway (CTRL001) E1210 12:27:32.947537 1 mutate_app_gateway.go:34] unable to get specified AppGateway [xxx-xx-xx], check AppGateway identifier, error=[azure.BearerAuthorizer#WithAuthorization: Failed to refresh the Token for request to https://management.azure.com/subscriptions/xxx-xx-xx/resourceGroups/xxx-xx-xx/providers/Microsoft.Network/applicationGateways/xxx-xx-xx?api-version=2019-06-01: StatusCode=403 -- Original Error: adal: Refresh request failed. Status Code = '403'. Response body: adal: Refresh request failed. Status Code = '400'. Response body: {"error":"invalid_request","error_description":"Identity not found"} ] E1210 12:27:32.947736 1 worker.go:53] Error mutating App Gateway config from k8s event. unable to get specified AppGateway (CTRL001)
```Any Azure support tickets associated with this issue.
maybe related https://github.com/Azure/application-gateway-kubernetes-ingress/issues/117
aleksmark
All 16 comments
@aleksmark can you check the aad pod identity pod logs for errors ?
akshaysngupta
on 12 Dec 2019
@akshaysngupta
mic logs
W1112 11:28:42.953032 1 main.go:29] --kubeconfig not passed will use InClusterConfig
I1112 11:28:42.953584 1 main.go:32] kubeconfig () cloudconfig (/etc/kubernetes/azure.json)
I1112 11:28:42.953788 1 mic.go:52] Starting to create the pod identity client. Version: 0.0.0-dev. Build date: 2019-01-30-18:43
I1112 11:28:42.959149 1 crd.go:156] CRD watchers started
I1112 11:28:43.155116 1 pod.go:66] Pod cache synchronized. Took 200.143498ms
I1112 11:28:43.155175 1 pod.go:72] Pod watcher started !!
I1112 11:28:43.155192 1 main.go:46] AAD Pod identity controller initialized!!
I1112 11:28:43.155211 1 mic.go:120] Sync thread started.
nmi deamon pod that is running on the same node as ingress controller besides standard logs entries
time="2019-12-11T05:54:02Z" level=info msg="node(aks-agentpool-xxxxxx-x) hostip(10.0.0.159) metadataaddress(xxxx:80) nmiport(2579)"
time="2019-12-11T05:54:02Z" level=info msg="Rules for table(nat) chain(aad-metadata) rules(-N aad-metadata, -A aad-metadata ! -s 127.0.0.1/32 -d xxxx.xxxx.xxxx.xxxx/32 -p tcp -m tcp --dport 80 -j DNAT --to-destination 10.0.0.159:2579, -A aad-metadata -j RETURN)"
also has
time="2019-12-12T12:40:01Z" level=info msg="matched identityType:0 clientid:xxxx-xxxx-xxxx-xxxx resource:https://management.azure.com/" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.0.0.172
time="2019-12-12T12:40:01Z" level=error msg="failed to get service principal token for pod:default/fantastic-waterbuffalo-ingress-azure-66b968bbbc-wds6z, adal: Refresh request failed. Status Code = '400'. Response body: {\"error\":\"invalid_request\",\"error_description\":\"Identity not found\"}" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.0.0.172
time="2019-12-12T12:40:01Z" level=info msg="Status (403) took 486282353 ns" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.0.0.172
@aleksmark this looks like an issue in either AAD Pod identity or IMDS (instance metadata service) that is responsible for responding to token requests. I am investigating this further with the identity team. Will soon provide an update.
akshaysngupta
on 12 Dec 2019
@aleksmark We might need more information about your AKS cluster. Would you mind creating a support case on AKS Cluster and sharing the support case number ?
akshaysngupta
on 13 Dec 2019
@akshaysngupta I opened an issue with MS support with support request id: # 119121623002019
Also, I tried to create a new ingress controller with the same configuration in another namespace.
It seems that it had issues with permissions, but after a few retries, it started and now it is working as expected.
AGIC Identity requires 'Contributor' access on Application Gateway and 'Reader' access on Application Gateway's Resource Group;
Is it possible that something changed on Azure regarding permissions and now AGAIC needs a contributor role for some resources? But on the other hand, how come it started after few retries. I haven't change permissions in the meantime. Strange...
Btw, I haven't removed the old AGAIC, it is still up and running and having the same issues.
Full log of newly created AGAIC:
ERROR: logging before flag.Parse: I1216 09:25:56.039206 1 main.go:286] Using verbosity level 3 from environment variable APPGW_VERBOSITY_LEVEL
I1216 09:25:56.180732 1 environment.go:163] KUBERNETES_WATCHNAMESPACE is not set. Watching all available namespaces.
I1216 09:25:56.180761 1 main.go:126] App Gateway Details: Subscription: xxxxx-xxxx-xxxx-xxx, Resource Group: xxxxxx, Name: xxxxx
I1216 09:25:56.180776 1 auth.go:90] Creating authorizer from Azure Managed Service Identity
E1216 09:25:57.185365 1 auth.go:28] Possible reasons: AKS Service Principal requires 'Managed Identity Operator' access on Controller Identity; 'identityResourceID' and/or 'identityClientID' are incorrect in the Helm config; AGIC Identity requires 'Contributor' access on Application Gateway and 'Reader' access on Application Gateway's Resource Group;
E1216 09:25:57.185410 1 auth.go:41] Unexpected ARM status code on GET existing App Gateway config: 403
E1216 09:25:57.185420 1 auth.go:49] Failed fetching config for App Gateway instance. Will retry in 10s. Error: azure.BearerAuthorizer#WithAuthorization: Failed to refresh the Token for request to https://management.azure.com/subscriptions/xxxxxxx/resourceGroups/xxxxx/providers/Microsoft.Network/applicationGateways/xxxxxxx?api-version=2019-06-01: StatusCode=403 -- Original Error: adal: Refresh request failed. Status Code = '403'. Response body: adal: Refresh request failed. Status Code = '400'. Response body: {"error":"invalid_request","error_description":"Identity not found"}
E1216 09:26:07.240003 1 auth.go:28] Possible reasons: AKS Service Principal requires 'Managed Identity Operator' access on Controller Identity; 'identityResourceID' and/or 'identityClientID' are incorrect in the Helm config; AGIC Identity requires 'Contributor' access on Application Gateway and 'Reader' access on Application Gateway's Resource Group;
E1216 09:26:07.240138 1 auth.go:41] Unexpected ARM status code on GET existing App Gateway config: 403
E1216 09:26:07.240175 1 auth.go:49] Failed fetching config for App Gateway instance. Will retry in 10s. Error: azure.BearerAuthorizer#WithAuthorization: Failed to refresh the Token for request to https://management.azure.com/subscriptions/xxxxxxxx/resourceGroups/xxxxxxx/providers/Microsoft.Network/applicationGateways/xxxxxxxx?api-version=2019-06-01: StatusCode=403 -- Original Error: adal: Refresh request failed. Status Code = '403'. Response body: adal: Refresh request failed. Status Code = '400'. Response body: {"error":"invalid_request","error_description":"Identity not found"}
E1216 09:26:17.484745 1 auth.go:28] Possible reasons: AKS Service Principal requires 'Managed Identity Operator' access on Controller Identity; 'identityResourceID' and/or 'identityClientID' are incorrect in the Helm config; AGIC Identity requires 'Contributor' access on Application Gateway and 'Reader' access on Application Gateway's Resource Group;
E1216 09:26:17.484896 1 auth.go:41] Unexpected ARM status code on GET existing App Gateway config: 403
E1216 09:26:17.484998 1 auth.go:49] Failed fetching config for App Gateway instance. Will retry in 10s. Error: azure.BearerAuthorizer#WithAuthorization: Failed to refresh the Token for request to https://management.azure.com/subscriptions/xxxxxxx/resourceGroups/xxxxxx/providers/Microsoft.Network/applicationGateways/xxxxxxx?api-version=2019-06-01: StatusCode=403 -- Original Error: adal: Refresh request failed. Status Code = '403'. Response body: adal: Refresh request failed. Status Code = '400'. Response body: {"error":"invalid_request","error_description":"Identity not found"}
I1216 09:26:28.222426 1 main.go:173] Ingress Controller will observe all namespaces.
I1216 09:26:28.389846 1 context.go:125] k8s context run started
I1216 09:26:28.389896 1 context.go:164] Waiting for initial cache sync
I1216 09:26:28.490964 1 context.go:172] Initial cache sync done
I1216 09:26:28.490988 1 context.go:173] k8s context run finished
I1216 09:26:28.491462 1 httpserver.go:57] Starting API Server on :8123
I1216 09:26:28.491896 1 worker.go:33] Worker started
I1216 09:26:29.088058 1 mutate_app_gateway.go:148] BEGIN AppGateway deployment
I1216 09:27:10.476006 1 mutate_app_gateway.go:176] Applied App Gateway config in 41.38791352s
I1216 09:27:10.476064 1 mutate_app_gateway.go:192] cache: Updated with latest applied config.
I1216 09:27:10.486208 1 mutate_app_gateway.go:197] END AppGateway deployment
I1216 09:28:28.102286 1 mutate_app_gateway.go:148] BEGIN AppGateway deployment
I1216 09:29:09.444287 1 mutate_app_gateway.go:176] Applied App Gateway config in 41.341961808s
I1216 09:29:09.444411 1 mutate_app_gateway.go:192] cache: Updated with latest applied config.
I1216 09:29:09.459028 1 mutate_app_gateway.go:197] END AppGateway deployment
I1216 09:29:10.140856 1 mutate_app_gateway.go:148] BEGIN AppGateway deployment
I1216 09:29:51.708957 1 mutate_app_gateway.go:176] Applied App Gateway config in 41.568066813s
I1216 09:29:51.708997 1 mutate_app_gateway.go:192] cache: Updated with latest applied config.
I1216 09:29:51.719604 1 mutate_app_gateway.go:197] END AppGateway deployment
I1216 09:29:52.373281 1 mutate_app_gateway.go:148] BEGIN AppGateway deployment
I1216 09:30:33.786273 1 mutate_app_gateway.go:176] Applied App Gateway config in 41.412957973s
I1216 09:30:33.786312 1 mutate_app_gateway.go:192] cache: Updated with latest applied config.
I1216 09:30:33.800317 1 mutate_app_gateway.go:197] END AppGateway deployment
Update:
After a call with MS support, we realized that AKS service principal was not expired.
Anyways, we tried to reset the credentials but that did not solve the issue.
MS guys will continue the investigation.
aleksmark
on 23 Dec 2019
@akshaysngupta here is the feedback from MS support. I hope it helps.
The problem here is that IMDS is calling on an old id to get the credentials, hence the NotFound exceptions. Here are the logs. I’ve separated the logs by IdentityPut/IdentityDelete pairs.
env_time ActivityId operationName resultSignature IdentityType arpId
2019-10-21 00:53:49.9099003 f37ee0d6-7ca9-4088-a68e-5074b0ae42cb IdentityPutRequest Http Status Code OK UserAssigned
2019-10-21 00:53:50.2384424 bc6e920f-820d-4a33-b407-5260fba0168b SaCredentialsPostRequestV2 Http Status Code Unauthorized 49d5c2bb-e0db-4e30-9895-d126444d40d0
2019-10-21 00:53:50.4394575 aa9d3426-d8fd-4ba3-a8f7-6d8854536aaf SaCredentialsPostRequestV2 Http Status Code OK 49d5c2bb-e0db-4e30-9895-d126444d40d0
2019-10-21 00:54:06.4106687 8985443a-f96f-4dfb-a974-3f7fc7813ca6 UaCredentialsPostRequestV2 Http Status Code OK 49d5c2bb-e0db-4e30-9895-d126444d40d0
2019-10-21 17:54:15.9790192 3ce49b0c-4191-41fe-84dd-87fe3ad2e2d1 IdentityDeleteRequest Http Status Code NoContent
2019-10-21 20:59:59.2098105 8310cb5d-f93b-47f5-a5a3-85d940473edb IdentityPutRequest Http Status Code OK UserAssigned
2019-10-21 20:59:59.6003608 5cdecfda-c2f2-4e46-8811-e1e067329ee4 SaCredentialsPostRequestV2 Http Status Code Unauthorized 1e0d7235-a489-4127-98d9-dafc52b044db
2019-10-21 21:00:00.0222595 481c56ed-4ef9-4e4f-88f9-4d717b4fc2ef SaCredentialsPostRequestV2 Http Status Code OK 1e0d7235-a489-4127-98d9-dafc52b044db
2019-10-22 22:18:05.7256874 03aaf1aa-0911-49c1-a8cc-6fadc0ed7702 IdentityDeleteRequest Http Status Code NoContent
2019-10-22 23:13:45.0493829 57f8499b-8c6c-4ca3-aa6c-d56f41a22454 IdentityPutRequest Http Status Code OK UserAssigned
2019-10-22 23:13:45.4087741 432e9c0b-af68-43a7-a222-4ac8949be880 SaCredentialsPostRequestV2 Http Status Code Unauthorized 5909768c-621c-4408-af06-f4052dae9734
2019-10-22 23:13:45.5962566 9b1c945c-8270-44d7-9c14-889380d96ee8 SaCredentialsPostRequestV2 Http Status Code OK 5909768c-621c-4408-af06-f4052dae9734
2019-10-22 23:55:35.9891800 2f4fb96f-e0e0-4fbc-976c-ee2554da95bb IdentityDeleteRequest Http Status Code NoContent
2019-10-23 00:35:31.2383302 d3f6b78c-99c8-4325-b72d-a5b8ac185613 IdentityPutRequest Http Status Code OK UserAssigned
2019-10-23 00:35:31.5982529 82eb61d7-5e59-46ae-bf9e-4c1d0642172f SaCredentialsPostRequestV2 Http Status Code Unauthorized c68bc9a4-0226-46d7-9127-c3fc10652a55
2019-10-23 00:35:31.7545088 d8f40e89-5ba7-4fc4-95d5-41312d093570 SaCredentialsPostRequestV2 Http Status Code OK c68bc9a4-0226-46d7-9127-c3fc10652a55
2019-10-24 14:58:57.3390648 b460be4d-b9e4-410f-ba95-9b03da1a02db SaCredentialsPostRequestV2 Http Status Code Unauthorized c68bc9a4-0226-46d7-9127-c3fc10652a55
2019-10-24 14:58:57.4796952 b4a92d67-c1bc-403f-a7e3-65d8abb0886e SaCredentialsPostRequestV2 Http Status Code OK c68bc9a4-0226-46d7-9127-c3fc10652a55
2019-10-25 00:28:55.7513552 77e7647d-765c-4b57-9c4d-be0915cf4a8a UaCredentialsPostRequestV2 Http Status Code NotFound 49d5c2bb-e0db-4e30-9895-d126444d40d0
2019-10-25 08:32:19.8690252 bf25aecb-5efa-47cd-87ae-7a57b4d5ae76 UaCredentialsPostRequestV2 Http Status Code NotFound 49d5c2bb-e0db-4e30-9895-d126444d40d0
2019-10-25 12:02:07.8764691 0f5f47f2-8c4d-4a57-afa9-f96c5b576d9e IdentityPutRequest Http Status Code OK UserAssigned
2019-10-27 12:50:29.6681188 be5da02e-65b4-4363-a96f-92957024e6bb UaCredentialsPostRequestV2 Http Status Code NotFound 49d5c2bb-e0db-4e30-9895-d126444d40d0
2019-10-27 22:16:36.7654453 b33946c1-79fd-421a-a05a-35a03368f958 UaCredentialsPostRequestV2 Http Status Code NotFound 49d5c2bb-e0db-4e30-9895-d126444d40d0
So basically, there were a few creation/deletion/identity assignments on "/subscriptions/xxxxxxxx-xxxx-xxxx-xxxx-xxxxx/resourcegroups/xxxxxxxxx/providers/microsoft.compute/virtualmachines/aks-agentpool-15375443-6".
Every time, that resource is created, we generate a new id (arpid) that has to be sent in the credential request. The valid arpid from the last creation of the resource (2019-10-23 00:35) is c68bc9a4-0226-46d7-9127-c3fc10652a55. However, the call is made using the very first arpid that was associated with that resource : 49d5c2bb-e0db-4e30-9895-d126444d40d0. On the backend, we try to find that resource identified with the arpid but it results in a NotFound since it has been deleted on 2019-10-21 at 17:54:15.
In fact, there was a single call that same target endpoint that was successful since it had the correct arpid:
env_time ActivityId operationName resultSignature arpId
2019-12-09 06:22:23.4221772 ff25cc6f-bc2c-4667-a79b-0ff19a5aa576 UaCredentialsPostRequestV2 Http Status Code OK c68bc9a4-0226-46d7-9127-c3fc10652a55
This leads me to think that it is not a IMDS caching issue, but more of a configuration/client error.
I hope this helps understanding why you had problems authenticating. If some questions remains, feel free to ask!
more info from the ms support, on the issue:
I have tried to locate IMDS verbose logs from the node to no avail. It seems like the logs have been wiped from the disk and do not cover the period where the error occurs so it is impossible for us to verify what the cache values were at the time of the calls.
We do have a hunch that this could be related to a different cache issue than the one I was thinking about initially.
The issue – for which a fix is in the pipeline – happens when all identities are removed from a resource and added again. At that moment clientId match but since the resource has been recreated in the background, it has a new internal azure resource id. This leads to an invalid cache entry that is used by IMDS. The mitigation is to restart the node to clear the cache. We cannot confirm at 100% that this happened, because of the lost logs but given the sequence of operations on your resources, it is highly likely.
A recommendation for your production environment that has a similar setup, is to not to a succession of PUT/PATCH and DELETE on the resource that could lead to be in that state. At least, not until the fix is deployed globally.
Looks like it's caching issue on azure side
aleksmark
on 24 Jan 2020
Hello, I'm having the same problem after re-create my storage accounts, how can I fix caching issues?
qzhou-hmcts
on 23 Mar 2020
@qzhou-hmcts Would you be able to open a support case on AKS ?
akshaysngupta
on 13 Apr 2020
Closing issue here. Underlying issue is related to caching problem in AKS.
akshaysngupta
on 13 Apr 2020
How are you solving the caching issue? By restarting the node? @akshaysngupta @aleksmark
anshupitlia
on 18 May 2020
@anshupitlia Azure support fix this for me
aleksmark
on 1 Jun 2020
How the issue was fixed?
dummy-andra
on 25 Mar 2021
Not very satisfying resolution of the ticket.. i still dont know what to do...
dirien
on 9 Apr 2021
@palma21 Can you take a look at this issue ?
akshaysngupta
on 2 May 2021
Related issues
sowsan
·
6Comments
aelmanaa
·
3Comments
onybo
·
6Comments
gitflo1
·
3Comments
jweyrich
·
5Comments