Aad-pod-identity: Sporadic inability to fetch credentials using az login --identity

Created on 17 Feb 2020 · 25Comments · Source: Azure/aad-pod-identity

Describe the bug
Seeing the following error when trying to fetch credentials using az login --identity

Logging in using pod identity
[Pipeline] sh
+ az login --identity
ERROR: The command failed with an unexpected error. Here is the traceback:
ERROR: 
Traceback (most recent call last):
  File "/opt/az/lib/python3.6/site-packages/knack/cli.py", line 206, in invoke
    cmd_result = self.invocation.execute(args)
  File "/opt/az/lib/python3.6/site-packages/azure/cli/core/commands/__init__.py", line 603, in execute
    raise ex
  File "/opt/az/lib/python3.6/site-packages/azure/cli/core/commands/__init__.py", line 661, in _run_jobs_serially
    results.append(self._run_job(expanded_arg, cmd_copy))
  File "/opt/az/lib/python3.6/site-packages/azure/cli/core/commands/__init__.py", line 654, in _run_job
    six.reraise(*sys.exc_info())
  File "/opt/az/lib/python3.6/site-packages/six.py", line 693, in reraise
    raise value
  File "/opt/az/lib/python3.6/site-packages/azure/cli/core/commands/__init__.py", line 631, in _run_job
    result = cmd_copy(params)
  File "/opt/az/lib/python3.6/site-packages/azure/cli/core/commands/__init__.py", line 306, in __call__
    return self.handler(*args, **kwargs)
  File "/opt/az/lib/python3.6/site-packages/azure/cli/core/__init__.py", line 485, in default_command_handler
    return op(**command_args)
  File "/opt/az/lib/python3.6/site-packages/azure/cli/command_modules/profile/custom.py", line 125, in login
    return profile.find_subscriptions_in_vm_with_msi(username, allow_no_subscriptions)
  File "/opt/az/lib/python3.6/site-packages/azure/cli/core/_profile.py", line 328, in find_subscriptions_in_vm_with_msi
    msi_creds = MSIAuthentication(resource=resource)
  File "/opt/az/lib/python3.6/site-packages/msrestazure/azure_active_directory.py", line 592, in __init__
    self.set_token()
  File "/opt/az/lib/python3.6/site-packages/msrestazure/azure_active_directory.py", line 600, in set_token
    token_entry = self._vm_msi.get_token(self.resource)
  File "/opt/az/lib/python3.6/site-packages/msrestazure/azure_active_directory.py", line 649, in get_token
    token_entry = self._retrieve_token_from_imds_with_retry(resource)
  File "/opt/az/lib/python3.6/site-packages/msrestazure/azure_active_directory.py", line 704, in _retrieve_token_from_imds_with_retry
    raise HTTPError(request=result.request, response=result.raw)
requests.exceptions.HTTPError
WARNING: 
To open an issue, please run: 'az feedback'

Steps To Reproduce

Create AKS cluster
Install aad pod identity
Create pod with selector label matching what is defined in AzureIdentityBinding
Run az login --identity

If it works, repeat steps 3 and 4 - this issue is sporadic and will often just work, then will fail.

Expected behavior
az login --identity always works

AAD Pod Identity version
1.5.5 (upgraded to see if this would fix the issue, to no avail)

Kubernetes version
1.13.10

Additional context
NMI logs:

time="2020-02-17T14:10:02Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://management.core.windows.net/" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.147
time="2020-02-17T14:10:02Z" level=error msg="failed to get service principal token for pod:cicd/jenkinsdeployer-0cxvf, 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.117.0.147
time="2020-02-17T14:10:02Z" level=info msg="Status (403) took 75126261308 ns" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.147
time="2020-02-17T14:15:17Z" level=error msg="no AzureAssignedIdentity found for pod:cicd/jenkinsdeployer-5j925 in assigned state, getting assigned identities for pod cicd/jenkinsdeployer-5j925 in ASSIGNED state failed after 30 attempts, retry duration [5]s. Error: <nil>" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.130
time="2020-02-17T14:15:17Z" level=info msg="Status (404) took 150007823870 ns" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.130
time="2020-02-17T14:15:37Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://management.core.windows.net/" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.130
time="2020-02-17T14:15:37Z" level=error msg="failed to get service principal token for pod:cicd/jenkinsdeployer-5j925, 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.117.0.130
time="2020-02-17T14:15:37Z" level=info msg="Status (403) took 20124566510 ns" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.130
time="2020-02-17T14:19:48Z" level=error msg="no AzureAssignedIdentity found for pod:cicd/jenkinsdeployer-kwv58 in assigned state, getting assigned identities for pod cicd/jenkinsdeployer-kwv58 in ASSIGNED state failed after 30 attempts, retry duration [5]s. Error: <nil>" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.155
time="2020-02-17T14:19:48Z" level=info msg="Status (404) took 150007845029 ns" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.155
time="2020-02-17T14:20:13Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://management.core.windows.net/" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.155
time="2020-02-17T14:20:13Z" level=error msg="failed to get service principal token for pod:cicd/jenkinsdeployer-kwv58, 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.117.0.155
time="2020-02-17T14:20:13Z" level=info msg="Status (403) took 25232605973 ns" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.155

The NMI timings aren't looking too good here and it looks like the MIC deployment is taking 1min 30 to perform cloud PUT operations

This has been seen before:
https://github.com/Azure/aad-pod-identity/issues/206 - closed
https://github.com/Azure/azure-cli/issues/9537 - not sure this is a CLI issue

bug

Source

cwebbtw

👍2

All 25 comments

@kkmsft happy to provide further logs if this will help

cwebbtw on 17 Feb 2020

@ritazh for awareness

jluk on 18 Feb 2020

👍1

@cwebbtw From the NMI logs posted, there seem to be 2 kinds of errors -

Status Code = '400'. Response body: {\"error\":\"invalid_request\",\"error_description\":\"Identity not found\"}"

For this error -

Are you able to check if the identity that the pod is using exists on the vmss? This can be checked using az vmss identity show command.

no AzureAssignedIdentity found for pod:cicd/jenkinsdeployer-kwv58 in assigned state

MIC creates the AzureAssignedIdentity only after the identity has been successfully assigned to the node. This correlates with the increased time you are observing for the cloud operation PUT request to succeed. Are all the PUT requests for new identities taking around the same time?

Few questions -

How many node pools in the cluster?
How many nodes in the cluster?

aramase on 18 Feb 2020

👍1

@aramase

Are you able to check if the identity that the pod is using exists on the vmss? This can be checked using az vmss identity show command.

The team with this set up are not using VMSS but are instead using availability sets (the cluster was provisioned prior to VMSS being available in AKS and are cross region). Each of the 6 instances in the availability set do not have an existing identity.

MIC creates the AzureAssignedIdentity only after the identity has been successfully assigned to the node. This correlates with the increased time you are observing for the cloud operation PUT request to succeed. Are all the PUT requests for new identities taking around the same time?

The put requests are sporadic unfortunately, sometimes the response times are less than 5 seconds, whereas at other times, we've seen over 100 seconds.

To answer your questions:

1. How many node pools in the cluster?

This cluster was set up with a single agent pool

2. How many nodes in the cluster?

cwebbtw on 18 Feb 2020

@cwebbtw Thank you for the response. Are you able to provide me with the following -

MIC logs
NMI logs
AzureIdentities and AzureIdentityBindings in the cluster with the sensitive information redacted.

It would be great if you can provide me the logs around the time frame you see the errors. I'll also try and see if I can repro with the exact same cluster config.

aramase on 18 Feb 2020

We have enabled verbose logging and will provide the logs for MIC and NMI when this happens. Until then, please see the redacted AzureIdentities and AzureIdentityBindings:

$ kubectl get AzureIdentity azure-identity -o yaml
apiVersion: aadpodidentity.k8s.io/v1
kind: AzureIdentity
metadata:
  name: azure-identity
  namespace: default
spec:
  ClientID: <REDACTED CLIENT ID>
  ResourceID: /subscriptions/<REDACTED SUBSCRIPTION ID>/resourcegroups/<REDACTED GROUP>/providers/Microsoft.ManagedIdentity/userAssignedIdentities/<REDACTED NAME>
  type: 0

$ kubectl get AzureIdentityBinding azure-identity-binding -o yaml
apiVersion: aadpodidentity.k8s.io/v1
kind: AzureIdentityBinding
metadata:
  name: azure-identity-binding
  namespace: default
spec:
  AzureIdentity: azure-identity
  Selector: automation-identity-selector

cwebbtw on 19 Feb 2020

We're not seeing complete failures today but we are seeing slow downs:

See mic logs:

I0220 17:19:00.125656       1 stats.go:98] ** Stats collected **
I0220 17:19:00.125661       1 stats.go:81] Pod listing: 68.5µs
I0220 17:19:00.125693       1 stats.go:81] ID listing: 9.2µs
I0220 17:19:00.125697       1 stats.go:81] Binding listing: 21.4µs
I0220 17:19:00.125701       1 stats.go:81] Assigned ID listing: 5.1µs
I0220 17:19:00.125704       1 stats.go:81] System: 111.9µs
I0220 17:19:00.125708       1 stats.go:81] CacheSync: 0s
I0220 17:19:00.125712       1 stats.go:81] Cloud provider get: 84.040386ms
I0220 17:19:00.125715       1 stats.go:81] Cloud provider put: 2m52.879053167s
I0220 17:19:00.125719       1 stats.go:81] Assigned ID addition: 20.309997ms
I0220 17:19:00.125723       1 stats.go:81] Assigned ID deletion: 43.797001ms
I0220 17:19:00.125728       1 stats.go:88] Number of cloud provider PUT: 2
I0220 17:19:00.125731       1 stats.go:88] Number of cloud provider GET: 2
I0220 17:19:00.125735       1 stats.go:88] Number of assigned ids created in this sync cycle: 1
I0220 17:19:00.125738       1 stats.go:88] Number of assigned ids deleted in this sync cycle: 1
I0220 17:19:00.125741       1 stats.go:81] Find assigned ids to create: 12.7µs
I0220 17:19:00.125744       1 stats.go:81] Find assigned ids to delete: 1.9µs
I0220 17:19:00.125748       1 stats.go:81] Total time to assign or remove IDs: 2m11.959018488s
I0220 17:19:00.125751       1 stats.go:81] Event recording: 0s
I0220 17:19:00.125755       1 stats.go:81] Total: 2m11.960155688s
I0220 17:19:00.125758       1 stats.go:127] *********************

cwebbtw on 20 Feb 2020

This is one of the faster requests but isolated to a single test case where the overall time taken for aad-pod-identity was 18 seconds. In the previous example, it took 2min 52 seconds, and prior to today, unable to assign an identity.

NMI logs:

time="2020-02-20T17:48:31Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://management.core.windows.net/" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.41
time="2020-02-20T17:48:31Z" level=info msg="Status (200) took 15006058702 ns" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.41
time="2020-02-20T17:48:35Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://management.core.windows.net/" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.41
time="2020-02-20T17:48:35Z" level=info msg="Status (200) took 4317223 ns" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.41
time="2020-02-20T17:48:37Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://management.core.windows.net/" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.41
time="2020-02-20T17:48:37Z" level=info msg="Status (200) took 5347928 ns" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.41

MIC logs:

I0220 17:46:49.589223       1 main.go:79] Starting mic process. Version: 1.5.5. Build date: 2020-01-28-23:11
W0220 17:46:49.589276       1 main.go:84] --kubeconfig not passed will use InClusterConfig
I0220 17:46:49.589283       1 main.go:98] kubeconfig () cloudconfig (/etc/kubernetes/azure.json)
I0220 17:46:49.665729       1 main.go:109] Client QPS set to: 5. Burst to: 5
I0220 17:46:49.665766       1 mic.go:92] Starting to create the pod identity client. Version: 1.5.5. Build date: 2020-01-28-23:11
I0220 17:46:49.704739       1 round_trippers.go:405] GET https://10.0.0.1:443/version 200 OK in 36 milliseconds
I0220 17:46:49.704845       1 mic.go:98] Kubernetes server version: v1.13.10
I0220 17:46:49.704867       1 cloudprovider.go:44] Populate AzureConfig from azure.json
I0220 17:46:49.705883       1 mic.go:107] Cloud provider initialized
I0220 17:46:49.706036       1 mic.go:114] CRD client initialized
I0220 17:46:49.706142       1 mic.go:117] Pod Client initialized
I0220 17:46:49.706291       1 log.go:16] Initialized health probe on port &[8080]
I0220 17:46:49.706313       1 log.go:11] Started health probe
I0220 17:46:49.706400       1 log.go:16] Registered views for metric%!(EXTRA *[]interface {}=&[])
I0220 17:46:49.706457       1 log.go:11] Starting Prometheus exporter
I0220 17:46:49.706471       1 log.go:16] Registered and exported metrics on port &[8888]
I0220 17:46:49.706478       1 mic.go:164] Initiating MIC Leader election
I0220 17:46:49.706487       1 leaderelection.go:175] attempting to acquire leader lease  default/aad-pod-identity-mic...
I0220 17:46:49.711608       1 round_trippers.go:405] GET https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 5 milliseconds
I0220 17:46:49.712623       1 leaderelection.go:243] lock is held by aad-pod-identity-mic-5468676458-d2t9s and has not yet expired
I0220 17:46:49.712644       1 leaderelection.go:180] failed to acquire lease default/aad-pod-identity-mic
I0220 17:46:56.265622       1 round_trippers.go:405] GET https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 81 milliseconds
I0220 17:46:56.265798       1 leaderelection.go:243] lock is held by aad-pod-identity-mic-5468676458-d2t9s and has not yet expired
I0220 17:46:56.265815       1 leaderelection.go:180] failed to acquire lease default/aad-pod-identity-mic
I0220 17:47:04.254246       1 round_trippers.go:405] GET https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 5 milliseconds
I0220 17:47:04.254391       1 leaderelection.go:243] lock is held by aad-pod-identity-mic-5468676458-d2t9s and has not yet expired
I0220 17:47:04.254400       1 leaderelection.go:180] failed to acquire lease default/aad-pod-identity-mic
I0220 17:47:11.002790       1 round_trippers.go:405] GET https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 7 milliseconds
I0220 17:47:11.012176       1 round_trippers.go:405] PUT https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 8 milliseconds
I0220 17:47:11.012281       1 leaderelection.go:184] successfully acquired lease default/aad-pod-identity-mic
I0220 17:47:11.012391       1 mic.go:210] MIC client starting..
I0220 17:47:11.012834       1 pod.go:68] Wait for cache to sync
I0220 17:47:11.012906       1 reflector.go:202] Starting reflector *v1.AzureIdentityBinding (10m0s) from pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:99
I0220 17:47:11.012937       1 reflector.go:240] Listing and watching *v1.AzureIdentityBinding from pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:99
I0220 17:47:11.013144       1 reflector.go:202] Starting reflector *v1.AzureIdentity (10m0s) from pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:99
I0220 17:47:11.013164       1 reflector.go:240] Listing and watching *v1.AzureIdentity from pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:99
I0220 17:47:11.013313       1 reflector.go:202] Starting reflector *v1.AzureAssignedIdentity (10m0s) from pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:99
I0220 17:47:11.013331       1 reflector.go:240] Listing and watching *v1.AzureAssignedIdentity from pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:99
I0220 17:47:11.065518       1 reflector.go:202] Starting reflector *v1.Node (30s) from pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:99
I0220 17:47:11.065555       1 reflector.go:240] Listing and watching *v1.Node from pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:99
I0220 17:47:11.065717       1 reflector.go:202] Starting reflector *v1.Pod (30s) from pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:99
I0220 17:47:11.065741       1 reflector.go:240] Listing and watching *v1.Pod from pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:99
I0220 17:47:11.066147       1 round_trippers.go:405] POST https://10.0.0.1:443/api/v1/namespaces/default/events 201 Created in 53 milliseconds
I0220 17:47:11.066150       1 round_trippers.go:405] GET https://10.0.0.1:443/apis/aadpodidentity.k8s.io/v1/azureidentities?limit=500&resourceVersion=0 200 OK in 52 milliseconds
I0220 17:47:11.066177       1 round_trippers.go:405] GET https://10.0.0.1:443/apis/aadpodidentity.k8s.io/v1/azureidentitybindings?limit=500&resourceVersion=0 200 OK in 53 milliseconds
I0220 17:47:11.068668       1 crd.go:183] Binding created
I0220 17:47:11.068668       1 crd.go:214] Identity created
I0220 17:47:11.068738       1 round_trippers.go:405] GET https://10.0.0.1:443/api/v1/nodes?limit=500&resourceVersion=0 200 OK in 3 milliseconds
I0220 17:47:11.074775       1 round_trippers.go:405] GET https://10.0.0.1:443/api/v1/pods?limit=500&resourceVersion=0 200 OK in 8 milliseconds
I0220 17:47:11.075240       1 round_trippers.go:405] GET https://10.0.0.1:443/apis/aadpodidentity.k8s.io/v1/azureassignedidentities?limit=500&resourceVersion=0 200 OK in 9 milliseconds
I0220 17:47:11.075397       1 round_trippers.go:405] GET https://10.0.0.1:443/apis/aadpodidentity.k8s.io/v1/azureidentitybindings?resourceVersion=24423970&timeoutSeconds=427&watch=true 200 OK in 6 milliseconds
I0220 17:47:11.166071       1 shared_informer.go:123] caches populated
I0220 17:47:11.166096       1 mic.go:231] Node client started
I0220 17:47:11.166198       1 round_trippers.go:405] GET https://10.0.0.1:443/apis/aadpodidentity.k8s.io/v1/azureidentities?resourceVersion=24849695&timeoutSeconds=506&watch=true 200 OK in 97 milliseconds
I0220 17:47:11.166199       1 round_trippers.go:405] GET https://10.0.0.1:443/api/v1/nodes?resourceVersion=25091798&timeoutSeconds=319&watch=true 200 OK in 91 milliseconds
I0220 17:47:11.169148       1 round_trippers.go:405] GET https://10.0.0.1:443/apis/aadpodidentity.k8s.io/v1/azureassignedidentities?resourceVersion=25091551&timeoutSeconds=346&watch=true 200 OK in 1 milliseconds
I0220 17:47:11.212965       1 shared_informer.go:123] caches populated
I0220 17:47:11.212987       1 log.go:11] CRD informers started
I0220 17:47:11.212995       1 mic.go:224] CRD client started
I0220 17:47:11.270732       1 pod.go:44] Pod Created
// repeated multiple times - redacted
I0220 17:47:11.271315       1 pod.go:44] Pod Created
I0220 17:47:11.313057       1 shared_informer.go:123] caches populated
I0220 17:47:11.313087       1 pod.go:73] Pod cache synchronized. Took 300.258671ms
I0220 17:47:11.313094       1 pod.go:80] Pod watcher started !!
I0220 17:47:11.313100       1 mic.go:217] Pod client started
I0220 17:47:11.313118       1 mic.go:257] Sync thread started.
I0220 17:47:11.313136       1 mic.go:268] Received event: 6
I0220 17:47:11.313248       1 crd.go:390] Appending binding: default/azure-identity-binding to list.
I0220 17:47:11.313274       1 crd.go:477] Appending Identity: default/azure-identity to list.
I0220 17:47:11.313297       1 mic.go:325] del: map[], add: map[]
I0220 17:47:11.313315       1 mic.go:268] Received event: 3
I0220 17:47:11.313534       1 crd.go:390] Appending binding: default/azure-identity-binding to list.
I0220 17:47:11.313545       1 crd.go:477] Appending Identity: default/azure-identity to list.
I0220 17:47:11.313568       1 mic.go:325] del: map[], add: map[]
I0220 17:47:11.313580       1 mic.go:268] Received event: 0
I0220 17:47:11.313639       1 crd.go:390] Appending binding: default/azure-identity-binding to list.
I0220 17:47:11.313655       1 crd.go:477] Appending Identity: default/azure-identity to list.
I0220 17:47:11.313672       1 mic.go:325] del: map[], add: map[]
I0220 17:47:11.313685       1 mic.go:268] Received event: 0
I0220 17:47:11.313714       1 crd.go:390] Appending binding: default/azure-identity-binding to list.
I0220 17:47:11.313729       1 crd.go:477] Appending Identity: default/azure-identity to list.
I0220 17:47:11.313738       1 mic.go:325] del: map[], add: map[]
I0220 17:47:11.313749       1 mic.go:268] Received event: 0
I0220 17:47:11.313777       1 crd.go:390] Appending binding: default/azure-identity-binding to list.
I0220 17:47:11.313786       1 crd.go:477] Appending Identity: default/azure-identity to list.
I0220 17:47:11.313798       1 mic.go:325] del: map[], add: map[]
I0220 17:47:11.313807       1 mic.go:268] Received event: 0
I0220 17:47:11.313838       1 crd.go:390] Appending binding: default/azure-identity-binding to list.
I0220 17:47:11.313862       1 crd.go:477] Appending Identity: default/azure-identity to list.
I0220 17:47:11.313872       1 mic.go:325] del: map[], add: map[]
I0220 17:47:11.313889       1 mic.go:268] Received event: 0
I0220 17:47:11.313914       1 crd.go:390] Appending binding: default/azure-identity-binding to list.
I0220 17:47:11.313924       1 crd.go:477] Appending Identity: default/azure-identity to list.
I0220 17:47:11.313933       1 mic.go:325] del: map[], add: map[]
I0220 17:47:11.313948       1 mic.go:268] Received event: 0
I0220 17:47:11.314000       1 crd.go:390] Appending binding: default/azure-identity-binding to list.
I0220 17:47:11.314016       1 crd.go:477] Appending Identity: default/azure-identity to list.
I0220 17:47:11.314028       1 mic.go:325] del: map[], add: map[]
I0220 17:47:11.314038       1 mic.go:268] Received event: 0
I0220 17:47:11.314063       1 crd.go:390] Appending binding: default/azure-identity-binding to list.
I0220 17:47:11.314081       1 crd.go:477] Appending Identity: default/azure-identity to list.
I0220 17:47:11.314091       1 mic.go:325] del: map[], add: map[]
I0220 17:47:11.314105       1 mic.go:268] Received event: 0
I0220 17:47:11.314130       1 crd.go:390] Appending binding: default/azure-identity-binding to list.
I0220 17:47:11.314145       1 crd.go:477] Appending Identity: default/azure-identity to list.
I0220 17:47:11.314154       1 mic.go:325] del: map[], add: map[]
I0220 17:47:11.314164       1 mic.go:268] Received event: 0
I0220 17:47:11.314197       1 crd.go:390] Appending binding: default/azure-identity-binding to list.
I0220 17:47:11.314210       1 crd.go:477] Appending Identity: default/azure-identity to list.
I0220 17:47:11.314222       1 mic.go:325] del: map[], add: map[]
I0220 17:47:11.314235       1 mic.go:268] Received event: 0
I0220 17:47:11.314262       1 crd.go:390] Appending binding: default/azure-identity-binding to list.
I0220 17:47:11.314278       1 crd.go:477] Appending Identity: default/azure-identity to list.
I0220 17:47:11.314288       1 mic.go:325] del: map[], add: map[]
I0220 17:47:11.314304       1 mic.go:268] Received event: 0
I0220 17:47:11.314328       1 crd.go:390] Appending binding: default/azure-identity-binding to list.
I0220 17:47:11.314343       1 crd.go:477] Appending Identity: default/azure-identity to list.
I0220 17:47:11.314352       1 mic.go:325] del: map[], add: map[]
I0220 17:47:11.314361       1 mic.go:268] Received event: 0
I0220 17:47:11.314389       1 crd.go:390] Appending binding: default/azure-identity-binding to list.
I0220 17:47:11.314858       1 crd.go:477] Appending Identity: default/azure-identity to list.
I0220 17:47:11.314878       1 mic.go:325] del: map[], add: map[]
I0220 17:47:11.314887       1 mic.go:268] Received event: 0
I0220 17:47:11.314912       1 crd.go:390] Appending binding: default/azure-identity-binding to list.
I0220 17:47:11.314923       1 crd.go:477] Appending Identity: default/azure-identity to list.
I0220 17:47:11.314932       1 mic.go:325] del: map[], add: map[]
I0220 17:47:11.314943       1 mic.go:268] Received event: 0
I0220 17:47:11.315050       1 crd.go:390] Appending binding: default/azure-identity-binding to list.
I0220 17:47:11.315071       1 crd.go:477] Appending Identity: default/azure-identity to list.
I0220 17:47:11.315081       1 mic.go:325] del: map[], add: map[]
I0220 17:47:11.315091       1 mic.go:268] Received event: 0
I0220 17:47:11.315127       1 crd.go:390] Appending binding: default/azure-identity-binding to list.
I0220 17:47:11.315139       1 crd.go:477] Appending Identity: default/azure-identity to list.
I0220 17:47:11.315151       1 mic.go:325] del: map[], add: map[]
I0220 17:47:11.315164       1 mic.go:268] Received event: 0
I0220 17:47:11.315188       1 crd.go:390] Appending binding: default/azure-identity-binding to list.
I0220 17:47:11.315204       1 crd.go:477] Appending Identity: default/azure-identity to list.
I0220 17:47:11.315213       1 mic.go:325] del: map[], add: map[]
I0220 17:47:11.315225       1 mic.go:268] Received event: 0
I0220 17:47:11.315253       1 crd.go:390] Appending binding: default/azure-identity-binding to list.
I0220 17:47:11.315268       1 crd.go:477] Appending Identity: default/azure-identity to list.
I0220 17:47:11.315277       1 mic.go:325] del: map[], add: map[]
I0220 17:47:11.315285       1 mic.go:268] Received event: 0
I0220 17:47:11.315312       1 crd.go:390] Appending binding: default/azure-identity-binding to list.
I0220 17:47:11.315319       1 crd.go:477] Appending Identity: default/azure-identity to list.
I0220 17:47:11.315329       1 mic.go:325] del: map[], add: map[]
I0220 17:47:11.315339       1 mic.go:268] Received event: 0
I0220 17:47:11.315367       1 crd.go:390] Appending binding: default/azure-identity-binding to list.
I0220 17:47:11.315382       1 crd.go:477] Appending Identity: default/azure-identity to list.
I0220 17:47:11.315391       1 mic.go:325] del: map[], add: map[]
I0220 17:47:11.315402       1 mic.go:268] Received event: 0
I0220 17:47:11.315431       1 crd.go:390] Appending binding: default/azure-identity-binding to list.
I0220 17:47:11.315445       1 crd.go:477] Appending Identity: default/azure-identity to list.
I0220 17:47:11.315454       1 mic.go:325] del: map[], add: map[]
I0220 17:47:11.315463       1 mic.go:268] Received event: 0
I0220 17:47:11.315490       1 crd.go:390] Appending binding: default/azure-identity-binding to list.
I0220 17:47:11.315501       1 crd.go:477] Appending Identity: default/azure-identity to list.
I0220 17:47:11.315513       1 mic.go:325] del: map[], add: map[]
I0220 17:47:11.315521       1 mic.go:268] Received event: 0
I0220 17:47:11.315544       1 crd.go:390] Appending binding: default/azure-identity-binding to list.
I0220 17:47:11.315555       1 crd.go:477] Appending Identity: default/azure-identity to list.
I0220 17:47:11.315564       1 mic.go:325] del: map[], add: map[]
I0220 17:47:11.315580       1 mic.go:268] Received event: 0
I0220 17:47:11.315604       1 crd.go:390] Appending binding: default/azure-identity-binding to list.
I0220 17:47:11.315613       1 crd.go:477] Appending Identity: default/azure-identity to list.
I0220 17:47:11.315622       1 mic.go:325] del: map[], add: map[]
I0220 17:47:11.315631       1 mic.go:268] Received event: 0
I0220 17:47:11.315663       1 crd.go:390] Appending binding: default/azure-identity-binding to list.
I0220 17:47:11.315670       1 crd.go:477] Appending Identity: default/azure-identity to list.
I0220 17:47:11.315681       1 mic.go:325] del: map[], add: map[]
I0220 17:47:11.315690       1 mic.go:268] Received event: 0
I0220 17:47:11.315711       1 crd.go:390] Appending binding: default/azure-identity-binding to list.
I0220 17:47:11.315722       1 crd.go:477] Appending Identity: default/azure-identity to list.
I0220 17:47:11.315730       1 mic.go:325] del: map[], add: map[]
I0220 17:47:11.315741       1 mic.go:268] Received event: 0
I0220 17:47:11.315821       1 crd.go:390] Appending binding: default/azure-identity-binding to list.
I0220 17:47:11.315843       1 crd.go:477] Appending Identity: default/azure-identity to list.
I0220 17:47:11.315906       1 mic.go:325] del: map[], add: map[]
I0220 17:47:11.315926       1 mic.go:268] Received event: 0
I0220 17:47:11.365811       1 crd.go:390] Appending binding: default/azure-identity-binding to list.
I0220 17:47:11.365855       1 crd.go:477] Appending Identity: default/azure-identity to list.
I0220 17:47:11.365874       1 mic.go:325] del: map[], add: map[]
I0220 17:47:11.365890       1 mic.go:268] Received event: 0
I0220 17:47:11.365949       1 crd.go:390] Appending binding: default/azure-identity-binding to list.
I0220 17:47:11.365962       1 crd.go:477] Appending Identity: default/azure-identity to list.
I0220 17:47:11.365977       1 mic.go:325] del: map[], add: map[]
I0220 17:47:11.365993       1 mic.go:268] Received event: 0
I0220 17:47:11.366015       1 crd.go:390] Appending binding: default/azure-identity-binding to list.
I0220 17:47:11.366022       1 crd.go:477] Appending Identity: default/azure-identity to list.
I0220 17:47:11.366032       1 mic.go:325] del: map[], add: map[]
I0220 17:47:11.366041       1 mic.go:268] Received event: 0
I0220 17:47:11.366141       1 crd.go:390] Appending binding: default/azure-identity-binding to list.
I0220 17:47:11.365960       1 round_trippers.go:405] GET https://10.0.0.1:443/api/v1/pods?resourceVersion=25091788&timeoutSeconds=329&watch=true 200 OK in 95 milliseconds
I0220 17:47:11.366148       1 crd.go:477] Appending Identity: default/azure-identity to list.
I0220 17:47:11.366227       1 mic.go:325] del: map[], add: map[]
I0220 17:47:11.366249       1 mic.go:268] Received event: 0
I0220 17:47:11.366290       1 crd.go:390] Appending binding: default/azure-identity-binding to list.
I0220 17:47:11.366307       1 crd.go:477] Appending Identity: default/azure-identity to list.
I0220 17:47:11.366317       1 mic.go:325] del: map[], add: map[]
I0220 17:47:11.366328       1 mic.go:268] Received event: 0
I0220 17:47:11.366349       1 crd.go:390] Appending binding: default/azure-identity-binding to list.
I0220 17:47:11.366362       1 crd.go:477] Appending Identity: default/azure-identity to list.
I0220 17:47:11.366371       1 mic.go:325] del: map[], add: map[]
I0220 17:47:11.366380       1 mic.go:268] Received event: 0
I0220 17:47:11.366398       1 crd.go:390] Appending binding: default/azure-identity-binding to list.
I0220 17:47:11.366410       1 crd.go:477] Appending Identity: default/azure-identity to list.
I0220 17:47:11.366421       1 mic.go:325] del: map[], add: map[]
I0220 17:47:11.366430       1 mic.go:268] Received event: 0
I0220 17:47:11.366447       1 crd.go:390] Appending binding: default/azure-identity-binding to list.
I0220 17:47:11.366508       1 crd.go:477] Appending Identity: default/azure-identity to list.
I0220 17:47:11.366517       1 mic.go:325] del: map[], add: map[]
I0220 17:47:11.366526       1 mic.go:268] Received event: 0
I0220 17:47:11.366544       1 crd.go:390] Appending binding: default/azure-identity-binding to list.
I0220 17:47:11.366550       1 crd.go:477] Appending Identity: default/azure-identity to list.
I0220 17:47:11.366558       1 mic.go:325] del: map[], add: map[]
I0220 17:47:11.366571       1 mic.go:268] Received event: 0
I0220 17:47:11.366588       1 crd.go:390] Appending binding: default/azure-identity-binding to list.
I0220 17:47:11.366599       1 crd.go:477] Appending Identity: default/azure-identity to list.
I0220 17:47:11.366616       1 mic.go:325] del: map[], add: map[]
I0220 17:47:11.366626       1 mic.go:268] Received event: 0
I0220 17:47:11.366646       1 crd.go:390] Appending binding: default/azure-identity-binding to list.
I0220 17:47:11.366653       1 crd.go:477] Appending Identity: default/azure-identity to list.
I0220 17:47:11.366661       1 mic.go:325] del: map[], add: map[]
I0220 17:47:11.366669       1 mic.go:268] Received event: 0
I0220 17:47:11.366687       1 crd.go:390] Appending binding: default/azure-identity-binding to list.
I0220 17:47:11.366698       1 crd.go:477] Appending Identity: default/azure-identity to list.
I0220 17:47:11.366706       1 mic.go:325] del: map[], add: map[]
I0220 17:47:11.366716       1 mic.go:268] Received event: 0
I0220 17:47:11.366732       1 crd.go:390] Appending binding: default/azure-identity-binding to list.
I0220 17:47:11.366744       1 crd.go:477] Appending Identity: default/azure-identity to list.
I0220 17:47:11.366755       1 mic.go:325] del: map[], add: map[]
I0220 17:47:11.366764       1 mic.go:268] Received event: 0
I0220 17:47:11.366780       1 crd.go:390] Appending binding: default/azure-identity-binding to list.
I0220 17:47:11.366785       1 crd.go:477] Appending Identity: default/azure-identity to list.
I0220 17:47:11.366793       1 mic.go:325] del: map[], add: map[]
I0220 17:47:11.366807       1 mic.go:268] Received event: 0
I0220 17:47:11.366826       1 crd.go:390] Appending binding: default/azure-identity-binding to list.
I0220 17:47:11.366832       1 crd.go:477] Appending Identity: default/azure-identity to list.
I0220 17:47:11.366840       1 mic.go:325] del: map[], add: map[]
I0220 17:47:11.366850       1 mic.go:268] Received event: 0
I0220 17:47:11.366877       1 crd.go:390] Appending binding: default/azure-identity-binding to list.
I0220 17:47:11.366888       1 crd.go:477] Appending Identity: default/azure-identity to list.
I0220 17:47:11.366899       1 mic.go:325] del: map[], add: map[]
I0220 17:47:11.366908       1 mic.go:268] Received event: 0
I0220 17:47:11.366938       1 crd.go:390] Appending binding: default/azure-identity-binding to list.
I0220 17:47:11.366950       1 crd.go:477] Appending Identity: default/azure-identity to list.
I0220 17:47:11.366958       1 mic.go:325] del: map[], add: map[]
I0220 17:47:11.366969       1 mic.go:268] Received event: 0
I0220 17:47:11.366987       1 crd.go:390] Appending binding: default/azure-identity-binding to list.
I0220 17:47:11.366993       1 crd.go:477] Appending Identity: default/azure-identity to list.
I0220 17:47:11.367001       1 mic.go:325] del: map[], add: map[]
I0220 17:47:11.367012       1 mic.go:268] Received event: 0
I0220 17:47:11.367027       1 crd.go:390] Appending binding: default/azure-identity-binding to list.
I0220 17:47:11.367038       1 crd.go:477] Appending Identity: default/azure-identity to list.
I0220 17:47:11.367048       1 mic.go:325] del: map[], add: map[]
I0220 17:47:11.367057       1 mic.go:268] Received event: 0
I0220 17:47:11.367073       1 crd.go:390] Appending binding: default/azure-identity-binding to list.
I0220 17:47:11.367084       1 crd.go:477] Appending Identity: default/azure-identity to list.
I0220 17:47:11.367092       1 mic.go:325] del: map[], add: map[]
I0220 17:47:11.367101       1 mic.go:268] Received event: 0
I0220 17:47:11.367119       1 crd.go:390] Appending binding: default/azure-identity-binding to list.
I0220 17:47:11.367130       1 crd.go:477] Appending Identity: default/azure-identity to list.
I0220 17:47:11.367138       1 mic.go:325] del: map[], add: map[]
I0220 17:47:11.367147       1 mic.go:268] Received event: 0
I0220 17:47:11.367166       1 crd.go:390] Appending binding: default/azure-identity-binding to list.
I0220 17:47:11.367176       1 crd.go:477] Appending Identity: default/azure-identity to list.
I0220 17:47:11.367186       1 mic.go:325] del: map[], add: map[]
I0220 17:47:11.367195       1 mic.go:268] Received event: 0
I0220 17:47:11.367212       1 crd.go:390] Appending binding: default/azure-identity-binding to list.
I0220 17:47:11.367223       1 crd.go:477] Appending Identity: default/azure-identity to list.
I0220 17:47:11.367231       1 mic.go:325] del: map[], add: map[]
I0220 17:47:11.367240       1 mic.go:268] Received event: 0
I0220 17:47:11.367259       1 crd.go:390] Appending binding: default/azure-identity-binding to list.
I0220 17:47:11.367270       1 crd.go:477] Appending Identity: default/azure-identity to list.
I0220 17:47:11.367280       1 mic.go:325] del: map[], add: map[]
I0220 17:47:11.367289       1 mic.go:268] Received event: 0
I0220 17:47:11.367310       1 crd.go:390] Appending binding: default/azure-identity-binding to list.
I0220 17:47:11.367316       1 crd.go:477] Appending Identity: default/azure-identity to list.
I0220 17:47:11.367342       1 mic.go:325] del: map[], add: map[]
I0220 17:47:11.367351       1 mic.go:268] Received event: 0
I0220 17:47:11.367385       1 crd.go:390] Appending binding: default/azure-identity-binding to list.
I0220 17:47:11.367396       1 crd.go:477] Appending Identity: default/azure-identity to list.
I0220 17:47:11.367404       1 mic.go:325] del: map[], add: map[]
I0220 17:47:11.367413       1 mic.go:268] Received event: 0
I0220 17:47:11.367433       1 crd.go:390] Appending binding: default/azure-identity-binding to list.
I0220 17:47:11.367446       1 crd.go:477] Appending Identity: default/azure-identity to list.
I0220 17:47:11.367454       1 mic.go:325] del: map[], add: map[]
I0220 17:47:11.367463       1 mic.go:268] Received event: 0
I0220 17:47:11.367479       1 crd.go:390] Appending binding: default/azure-identity-binding to list.
I0220 17:47:11.367485       1 crd.go:477] Appending Identity: default/azure-identity to list.
I0220 17:47:11.367495       1 mic.go:325] del: map[], add: map[]
I0220 17:47:11.367504       1 mic.go:268] Received event: 0
I0220 17:47:11.367519       1 crd.go:390] Appending binding: default/azure-identity-binding to list.
I0220 17:47:11.367530       1 crd.go:477] Appending Identity: default/azure-identity to list.
I0220 17:47:11.367539       1 mic.go:325] del: map[], add: map[]
I0220 17:47:11.367548       1 mic.go:268] Received event: 0
I0220 17:47:11.367565       1 crd.go:390] Appending binding: default/azure-identity-binding to list.
I0220 17:47:11.367571       1 crd.go:477] Appending Identity: default/azure-identity to list.
I0220 17:47:11.367580       1 mic.go:325] del: map[], add: map[]
I0220 17:47:11.367589       1 mic.go:268] Received event: 0
I0220 17:47:11.367604       1 crd.go:390] Appending binding: default/azure-identity-binding to list.
I0220 17:47:11.367615       1 crd.go:477] Appending Identity: default/azure-identity to list.
I0220 17:47:11.367626       1 mic.go:325] del: map[], add: map[]
I0220 17:47:11.367635       1 mic.go:268] Received event: 0
I0220 17:47:11.367651       1 crd.go:390] Appending binding: default/azure-identity-binding to list.
I0220 17:47:11.367661       1 crd.go:477] Appending Identity: default/azure-identity to list.
I0220 17:47:11.367671       1 mic.go:325] del: map[], add: map[]
I0220 17:47:14.779283       1 round_trippers.go:405] GET https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 16 milliseconds
I0220 17:47:14.788800       1 round_trippers.go:405] PUT https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 9 milliseconds
I0220 17:47:14.788885       1 leaderelection.go:199] successfully renewed lease default/aad-pod-identity-mic
I0220 17:47:18.544978       1 round_trippers.go:405] GET https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 5 milliseconds
I0220 17:47:18.563486       1 round_trippers.go:405] PUT https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 18 milliseconds
I0220 17:47:18.563700       1 leaderelection.go:199] successfully renewed lease default/aad-pod-identity-mic
I0220 17:47:22.319860       1 round_trippers.go:405] GET https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 5 milliseconds
I0220 17:47:22.330934       1 round_trippers.go:405] PUT https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 10 milliseconds
I0220 17:47:22.331115       1 leaderelection.go:199] successfully renewed lease default/aad-pod-identity-mic
I0220 17:47:26.097205       1 round_trippers.go:405] GET https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 15 milliseconds
I0220 17:47:26.107760       1 round_trippers.go:405] PUT https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 10 milliseconds
I0220 17:47:26.107840       1 leaderelection.go:199] successfully renewed lease default/aad-pod-identity-mic
I0220 17:47:29.863317       1 round_trippers.go:405] GET https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 4 milliseconds
I0220 17:47:29.872468       1 round_trippers.go:405] PUT https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 8 milliseconds
I0220 17:47:29.872603       1 leaderelection.go:199] successfully renewed lease default/aad-pod-identity-mic
I0220 17:47:33.628978       1 round_trippers.go:405] GET https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 5 milliseconds
I0220 17:47:33.641493       1 round_trippers.go:405] PUT https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 12 milliseconds
I0220 17:47:33.641618       1 leaderelection.go:199] successfully renewed lease default/aad-pod-identity-mic
I0220 17:47:37.399399       1 round_trippers.go:405] GET https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 7 milliseconds
I0220 17:47:37.415252       1 round_trippers.go:405] PUT https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 15 milliseconds
I0220 17:47:37.415340       1 leaderelection.go:199] successfully renewed lease default/aad-pod-identity-mic
I0220 17:47:41.171205       1 round_trippers.go:405] GET https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 5 milliseconds
I0220 17:47:41.185398       1 round_trippers.go:405] PUT https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 13 milliseconds
I0220 17:47:41.185515       1 leaderelection.go:199] successfully renewed lease default/aad-pod-identity-mic
I0220 17:47:41.270855       1 reflector.go:286] pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:99: forcing resync
I0220 17:47:44.942305       1 round_trippers.go:405] GET https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 6 milliseconds
I0220 17:47:44.953750       1 round_trippers.go:405] PUT https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 11 milliseconds
I0220 17:47:44.953845       1 leaderelection.go:199] successfully renewed lease default/aad-pod-identity-mic
I0220 17:47:48.728478       1 round_trippers.go:405] GET https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 24 milliseconds
I0220 17:47:48.739165       1 round_trippers.go:405] PUT https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 10 milliseconds
I0220 17:47:48.739254       1 leaderelection.go:199] successfully renewed lease default/aad-pod-identity-mic
I0220 17:47:49.631715       1 pod.go:44] Pod Created
I0220 17:47:49.631751       1 mic.go:268] Received event: 0
I0220 17:47:49.631793       1 crd.go:390] Appending binding: default/azure-identity-binding to list.
I0220 17:47:49.631802       1 crd.go:477] Appending Identity: default/azure-identity to list.
I0220 17:47:49.631819       1 mic.go:422] Pod cicd/jdeployer-92vkn has no assigned node yet. it will be ignored
I0220 17:47:49.631829       1 mic.go:325] del: map[], add: map[]
I0220 17:47:49.647873       1 pod.go:58] Pod Updated
I0220 17:47:49.647898       1 mic.go:268] Received event: 2
I0220 17:47:49.647947       1 crd.go:390] Appending binding: default/azure-identity-binding to list.
I0220 17:47:49.647963       1 crd.go:477] Appending Identity: default/azure-identity to list.
I0220 17:47:49.647977       1 mic.go:434] Found binding match for pod cicd/jdeployer-92vkn with binding default/azure-identity-binding
I0220 17:47:49.647989       1 mic.go:441] Looking up id map: default/azure-identity
I0220 17:47:49.647995       1 mic.go:452] identity default/azure-identity assigned to cicd/jdeployer-92vkn via default/azure-identity-binding
I0220 17:47:49.648025       1 mic.go:647] Binding - {TypeMeta:{Kind:v1.AzureIdentityBinding APIVersion:aadpodidentity.k8s.io/v1} ObjectMeta:{Name:azure-identity-binding GenerateName: Namespace:default SelfLink:/apis/aadpodidentity.k8s.io/v1/namespaces/default/azureidentitybindings/azure-identity-binding UID:0e15f3f0-4f16-11ea-806a-fadb4ba9caab ResourceVersion:23914634 Generation:1 CreationTimestamp:2020-02-14 10:37:53 +0000 UTC DeletionTimestamp:<nil> DeletionGracePeriodSeconds:<nil> Labels:map[app.kubernetes.io/instance:aad-pod-identity app.kubernetes.io/managed-by:Tiller app.kubernetes.io/name:aad-pod-identity helm.sh/chart:aad-pod-identity-1.5.5] Annotations:map[] OwnerReferences:[] Initializers:nil Finalizers:[] ClusterName:} Spec:{ObjectMeta:{Name: GenerateName: Namespace: SelfLink: UID: ResourceVersion: Generation:0 CreationTimestamp:0001-01-01 00:00:00 +0000 UTC DeletionTimestamp:<nil> DeletionGracePeriodSeconds:<nil> Labels:map[] Annotations:map[] OwnerReferences:[] Initializers:nil Finalizers:[] ClusterName:} AzureIdentity:azure-identity Selector:automation-identity-selector Weight:0} Status:{ObjectMeta:{Name: GenerateName: Namespace: SelfLink: UID: ResourceVersion: Generation:0 CreationTimestamp:0001-01-01 00:00:00 +0000 UTC DeletionTimestamp:<nil> DeletionGracePeriodSeconds:<nil> Labels:map[] Annotations:map[] OwnerReferences:[] Initializers:nil Finalizers:[] ClusterName:} AvailableReplicas:0}} Identity - {TypeMeta:{Kind:v1.AzureIdentity APIVersion:aadpodidentity.k8s.io/v1} ObjectMeta:{Name:azure-identity GenerateName: Namespace:default SelfLink:/apis/aadpodidentity.k8s.io/v1/namespaces/default/azureidentities/azure-identity UID:0dfb59f0-4f16-11ea-806a-fadb4ba9caab ResourceVersion:23914617 Generation:1 CreationTimestamp:2020-02-14 10:37:53 +0000 UTC DeletionTimestamp:<nil> DeletionGracePeriodSeconds:<nil> Labels:map[app.kubernetes.io/instance:aad-pod-identity app.kubernetes.io/managed-by:Tiller app.kubernetes.io/name:aad-pod-identity helm.sh/chart:aad-pod-identity-1.5.5] Annotations:map[] OwnerReferences:[] Initializers:nil Finalizers:[] ClusterName:} Spec:{ObjectMeta:{Name: GenerateName: Namespace: SelfLink: UID: ResourceVersion: Generation:0 CreationTimestamp:0001-01-01 00:00:00 +0000 UTC DeletionTimestamp:<nil> DeletionGracePeriodSeconds:<nil> Labels:map[] Annotations:map[] OwnerReferences:[] Initializers:nil Finalizers:[] ClusterName:} Type:0 ResourceID:/subscriptions/<REDACTED>/resourcegroups/<REDACTED>/providers/Microsoft.ManagedIdentity/userAssignedIdentities/<REDACTED> ClientID:<REDACTED> ClientPassword:{Name: Namespace:} TenantID: ADResourceID: ADEndpoint: Replicas:<nil>} Status:{ObjectMeta:{Name: GenerateName: Namespace: SelfLink: UID: ResourceVersion: Generation:0 CreationTimestamp:0001-01-01 00:00:00 +0000 UTC DeletionTimestamp:<nil> DeletionGracePeriodSeconds:<nil> Labels:map[] Annotations:map[] OwnerReferences:[] Initializers:nil Finalizers:[] ClusterName:} AvailableReplicas:0}}
I0220 17:47:49.648207       1 mic.go:648] Making assigned ID: &{TypeMeta:{Kind: APIVersion:} ObjectMeta:{Name:jdeployer-92vkn-cicd-azure-identity GenerateName: Namespace:default SelfLink: UID: ResourceVersion: Generation:0 CreationTimestamp:0001-01-01 00:00:00 +0000 UTC DeletionTimestamp:<nil> DeletionGracePeriodSeconds:<nil> Labels:map[nodename:aks-agentpool-42293377-2 podname:jdeployer-92vkn podnamespace:cicd] Annotations:map[] OwnerReferences:[] Initializers:nil Finalizers:[] ClusterName:} Spec:{ObjectMeta:{Name: GenerateName: Namespace: SelfLink: UID: ResourceVersion: Generation:0 CreationTimestamp:0001-01-01 00:00:00 +0000 UTC DeletionTimestamp:<nil> DeletionGracePeriodSeconds:<nil> Labels:map[] Annotations:map[] OwnerReferences:[] Initializers:nil Finalizers:[] ClusterName:} AzureIdentityRef:0xc000675c00 AzureBindingRef:0xc000675880 Pod:jdeployer-92vkn PodNamespace:cicd NodeName:aks-agentpool-42293377-2 Replicas:<nil>} Status:{ObjectMeta:{Name: GenerateName: Namespace: SelfLink: UID: ResourceVersion: Generation:0 CreationTimestamp:0001-01-01 00:00:00 +0000 UTC DeletionTimestamp:<nil> DeletionGracePeriodSeconds:<nil> Labels:map[] Annotations:map[] OwnerReferences:[] Initializers:nil Finalizers:[] ClusterName:} Status: AvailableReplicas:1}}
I0220 17:47:49.648263       1 mic.go:325] del: map[], add: map[jdeployer-92vkn-cicd-azure-identity:{{ } {jdeployer-92vkn-cicd-azure-identity  default    0 0001-01-01 00:00:00 +0000 UTC <nil> <nil> map[nodename:aks-agentpool-42293377-2 podname:jdeployer-92vkn podnamespace:cicd] map[] [] nil [] } {{      0 0001-01-01 00:00:00 +0000 UTC <nil> <nil> map[] map[] [] nil [] } 0xc000675c00 0xc000675880 jdeployer-92vkn cicd aks-agentpool-42293377-2 <nil>} {{      0 0001-01-01 00:00:00 +0000 UTC <nil> <nil> map[] map[] [] nil [] }  1}}]
I0220 17:47:49.648295       1 mic.go:518] Binding applied: &{TypeMeta:{Kind:v1.AzureIdentityBinding APIVersion:aadpodidentity.k8s.io/v1} ObjectMeta:{Name:azure-identity-binding GenerateName: Namespace:default SelfLink:/apis/aadpodidentity.k8s.io/v1/namespaces/default/azureidentitybindings/azure-identity-binding UID:0e15f3f0-4f16-11ea-806a-fadb4ba9caab ResourceVersion:23914634 Generation:1 CreationTimestamp:2020-02-14 10:37:53 +0000 UTC DeletionTimestamp:<nil> DeletionGracePeriodSeconds:<nil> Labels:map[app.kubernetes.io/instance:aad-pod-identity app.kubernetes.io/managed-by:Tiller app.kubernetes.io/name:aad-pod-identity helm.sh/chart:aad-pod-identity-1.5.5] Annotations:map[] OwnerReferences:[] Initializers:nil Finalizers:[] ClusterName:} Spec:{ObjectMeta:{Name: GenerateName: Namespace: SelfLink: UID: ResourceVersion: Generation:0 CreationTimestamp:0001-01-01 00:00:00 +0000 UTC DeletionTimestamp:<nil> DeletionGracePeriodSeconds:<nil> Labels:map[] Annotations:map[] OwnerReferences:[] Initializers:nil Finalizers:[] ClusterName:} AzureIdentity:azure-identity Selector:automation-identity-selector Weight:0} Status:{ObjectMeta:{Name: GenerateName: Namespace: SelfLink: UID: ResourceVersion: Generation:0 CreationTimestamp:0001-01-01 00:00:00 +0000 UTC DeletionTimestamp:<nil> DeletionGracePeriodSeconds:<nil> Labels:map[] Annotations:map[] OwnerReferences:[] Initializers:nil Finalizers:[] ClusterName:} AvailableReplicas:0}}
I0220 17:47:49.648419       1 mic.go:787] Processing node aks-agentpool-42293377-2, add [1], del [0]
I0220 17:47:49.648442       1 mic.go:807] Initiating assigned id creation for pod - jdeployer-92vkn, binding - azure-identity-binding
I0220 17:47:49.648447       1 crd.go:341] Got assigned id jdeployer-92vkn-cicd-azure-identity to assign
I0220 17:47:49.677428       1 round_trippers.go:405] POST https://10.0.0.1:443/apis/aadpodidentity.k8s.io/v1/namespaces/default/azureassignedidentities 201 Created in 28 milliseconds
I0220 17:47:49.678465       1 crd.go:364] Time take to create jdeployer-92vkn-cicd-azure-identity: 30.009768ms
I0220 17:47:50.636579       1 cloudprovider.go:199] Updating user assigned MSIs on aks-agentpool-42293377-2
I0220 17:47:52.495318       1 round_trippers.go:405] GET https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 5 milliseconds
I0220 17:47:52.504558       1 round_trippers.go:405] PUT https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 9 milliseconds
I0220 17:47:52.504654       1 leaderelection.go:199] successfully renewed lease default/aad-pod-identity-mic
I0220 17:47:56.260785       1 round_trippers.go:405] GET https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 5 milliseconds
I0220 17:47:56.272706       1 round_trippers.go:405] PUT https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 11 milliseconds
I0220 17:47:56.272785       1 leaderelection.go:199] successfully renewed lease default/aad-pod-identity-mic
I0220 17:48:00.040847       1 round_trippers.go:405] GET https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 17 milliseconds
I0220 17:48:00.051088       1 round_trippers.go:405] PUT https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 9 milliseconds
I0220 17:48:00.051236       1 leaderelection.go:199] successfully renewed lease default/aad-pod-identity-mic
I0220 17:48:03.807928       1 round_trippers.go:405] GET https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 6 milliseconds
I0220 17:48:03.822514       1 round_trippers.go:405] PUT https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 14 milliseconds
I0220 17:48:03.822611       1 leaderelection.go:199] successfully renewed lease default/aad-pod-identity-mic
I0220 17:48:07.578861       1 round_trippers.go:405] GET https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 5 milliseconds
I0220 17:48:07.588608       1 round_trippers.go:405] PUT https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 9 milliseconds
I0220 17:48:07.588727       1 leaderelection.go:199] successfully renewed lease default/aad-pod-identity-mic
I0220 17:48:11.271166       1 reflector.go:286] pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:99: forcing resync
I0220 17:48:11.355622       1 round_trippers.go:405] GET https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 16 milliseconds
I0220 17:48:11.375183       1 round_trippers.go:405] PUT https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 19 milliseconds
I0220 17:48:11.375317       1 leaderelection.go:199] successfully renewed lease default/aad-pod-identity-mic
I0220 17:48:15.131823       1 round_trippers.go:405] GET https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 5 milliseconds
I0220 17:48:15.146516       1 round_trippers.go:405] PUT https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 14 milliseconds
I0220 17:48:15.146640       1 leaderelection.go:199] successfully renewed lease default/aad-pod-identity-mic
I0220 17:48:18.901946       1 round_trippers.go:405] GET https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 4 milliseconds
I0220 17:48:18.913915       1 round_trippers.go:405] PUT https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 11 milliseconds
I0220 17:48:18.914065       1 leaderelection.go:199] successfully renewed lease default/aad-pod-identity-mic
I0220 17:48:22.680848       1 round_trippers.go:405] GET https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 16 milliseconds
I0220 17:48:22.690980       1 round_trippers.go:405] PUT https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 9 milliseconds
I0220 17:48:22.691070       1 leaderelection.go:199] successfully renewed lease default/aad-pod-identity-mic
I0220 17:48:26.447074       1 round_trippers.go:405] GET https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 5 milliseconds
I0220 17:48:26.463522       1 round_trippers.go:405] PUT https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 16 milliseconds
I0220 17:48:26.463616       1 leaderelection.go:199] successfully renewed lease default/aad-pod-identity-mic
I0220 17:48:27.155142       1 cloudprovider.go:204] UpdateUserMSI of aks-agentpool-42293377-2 completed in 36.518525036s
I0220 17:48:27.155191       1 crd.go:539] Updating assigned identity default/jdeployer-92vkn-cicd-azure-identity status to Assigned
I0220 17:48:27.189566       1 round_trippers.go:405] PATCH https://10.0.0.1:443/apis/aadpodidentity.k8s.io/v1/namespaces/default/azureassignedidentities/jdeployer-92vkn-cicd-azure-identity 200 OK in 34 milliseconds
I0220 17:48:27.189730       1 crd.go:566] Patch of jdeployer-92vkn-cicd-azure-identity took: 34.438377ms
I0220 17:48:27.189782       1 mic.go:367] Work done: true. Found 1 pods, 1 ids, 1 bindings
I0220 17:48:27.189797       1 mic.go:368] Total work cycles: 62, out of which work was done in: 1.
I0220 17:48:27.189809       1 stats.go:98] ** Stats collected **
I0220 17:48:27.189815       1 stats.go:81] Pod listing: 34µs
I0220 17:48:27.189824       1 stats.go:81] ID listing: 7.9µs
I0220 17:48:27.189828       1 stats.go:81] Binding listing: 17.4µs
I0220 17:48:27.189833       1 stats.go:81] Assigned ID listing: 500ns
I0220 17:48:27.189837       1 stats.go:81] System: 66.1µs
I0220 17:48:27.189841       1 stats.go:81] CacheSync: 0s
I0220 17:48:27.189845       1 stats.go:81] Cloud provider get: 958.040045ms
I0220 17:48:27.189850       1 stats.go:81] Cloud provider put: 36.518506536s
I0220 17:48:27.189854       1 stats.go:81] Assigned ID addition: 30.034368ms
I0220 17:48:27.189858       1 stats.go:81] Assigned ID deletion: 0s
I0220 17:48:27.189861       1 stats.go:88] Number of cloud provider PUT: 1
I0220 17:48:27.189865       1 stats.go:88] Number of cloud provider GET: 1
I0220 17:48:27.189869       1 stats.go:88] Number of assigned ids created in this sync cycle: 1
I0220 17:48:27.189872       1 stats.go:88] Number of assigned ids deleted in this sync cycle: 0
I0220 17:48:27.189876       1 stats.go:81] Find assigned ids to create: 0s
I0220 17:48:27.189880       1 stats.go:81] Find assigned ids to delete: 0s
I0220 17:48:27.189884       1 stats.go:81] Total time to assign or remove IDs: 37.541351226s
I0220 17:48:27.189887       1 stats.go:81] Event recording: 0s
I0220 17:48:27.189891       1 stats.go:81] Total: 37.541895527s
I0220 17:48:27.189895       1 stats.go:127] *********************
I0220 17:48:27.203134       1 round_trippers.go:405] POST https://10.0.0.1:443/api/v1/namespaces/default/events 201 Created in 13 milliseconds
I0220 17:48:30.220025       1 round_trippers.go:405] GET https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 6 milliseconds
I0220 17:48:30.228960       1 round_trippers.go:405] PUT https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 8 milliseconds
I0220 17:48:30.229191       1 leaderelection.go:199] successfully renewed lease default/aad-pod-identity-mic
I0220 17:48:33.995663       1 round_trippers.go:405] GET https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 16 milliseconds
I0220 17:48:34.004934       1 round_trippers.go:405] PUT https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 9 milliseconds
I0220 17:48:34.005034       1 leaderelection.go:199] successfully renewed lease default/aad-pod-identity-mic

Will continue to identify a failing case.

cwebbtw on 20 Feb 2020

I0309 15:43:33.848847       1 mic.go:368] Total work cycles: 41849, out of which work was done in: 9004.
I0309 15:43:33.849011       1 stats.go:98] ** Stats collected **
I0309 15:43:33.849021       1 stats.go:81] Pod listing: 98.801µs
I0309 15:43:33.849029       1 stats.go:81] ID listing: 23.2µs
I0309 15:43:33.849033       1 stats.go:81] Binding listing: 21.2µs
I0309 15:43:33.849037       1 stats.go:81] Assigned ID listing: 4.2µs
I0309 15:43:33.849041       1 stats.go:81] System: 154.801µs
I0309 15:43:33.849044       1 stats.go:81] CacheSync: 0s
I0309 15:43:33.849048       1 stats.go:81] Cloud provider get: 242.453854ms
I0309 15:43:33.849052       1 stats.go:81] Cloud provider put: 6m10.2665936s
I0309 15:43:33.849055       1 stats.go:81] Assigned ID addition: 40.75786ms
I0309 15:43:33.849059       1 stats.go:81] Assigned ID deletion: 14.389423ms
I0309 15:43:33.849063       1 stats.go:88] Number of cloud provider PUT: 3
I0309 15:43:33.849067       1 stats.go:88] Number of cloud provider GET: 3
I0309 15:43:33.849070       1 stats.go:88] Number of assigned ids created in this sync cycle: 2
I0309 15:43:33.849074       1 stats.go:88] Number of assigned ids deleted in this sync cycle: 1
I0309 15:43:33.849077       1 stats.go:81] Find assigned ids to create: 13.2µs
I0309 15:43:33.849081       1 stats.go:81] Find assigned ids to delete: 2.8µs
I0309 15:43:33.849085       1 stats.go:81] Total time to assign or remove IDs: 2m22.10289269s
I0309 15:43:33.849089       1 stats.go:81] Event recording: 0s
I0309 15:43:33.849092       1 stats.go:81] Total: 2m22.104496493s
I0309 15:43:33.849096       1 stats.go:127] *********************
I0309 15:43:34.049247       1 mic.go:268] Received event: 2

Feels concerning that we're seeing:

Cloud provider put: 6m10.2665936s

cwebbtw on 9 Mar 2020

Another dump:

I0309 22:16:17.975571       1 mic.go:787] Processing node aks-agentpool-42293377-3, add [1], del [0]
I0309 22:16:17.975605       1 mic.go:807] Initiating assigned id creation for pod - jenkinsdeployer-dzj18, binding - azure-identity-binding
I0309 22:16:17.975611       1 crd.go:341] Got assigned id jenkinsdeployer-dzj18-cicd-azure-identity to assign
I0309 22:16:18.000620       1 round_trippers.go:405] POST https://10.0.0.1:443/apis/aadpodidentity.k8s.io/v1/namespaces/default/azureassignedidentities 201 Created in 24 milliseconds
I0309 22:16:18.000781       1 crd.go:364] Time take to create jenkinsdeployer-dzj18-cicd-azure-identity: 25.162979ms
I0309 22:16:18.030671       1 cloudprovider.go:199] Updating user assigned MSIs on aks-agentpool-42293377-3
I0309 22:16:18.932969       1 reflector.go:286] pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:99: forcing resync
I0309 22:16:19.804955       1 round_trippers.go:405] GET https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 3 milliseconds
I0309 22:16:19.822557       1 round_trippers.go:405] PUT https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 17 milliseconds
I0309 22:16:19.822640       1 leaderelection.go:199] successfully renewed lease default/aad-pod-identity-mic
I0309 22:16:23.576193       1 round_trippers.go:405] GET https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 3 milliseconds
I0309 22:16:23.585924       1 round_trippers.go:405] PUT https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 9 milliseconds
I0309 22:16:23.586016       1 leaderelection.go:199] successfully renewed lease default/aad-pod-identity-mic
I0309 22:16:27.349462       1 round_trippers.go:405] GET https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 13 milliseconds
I0309 22:16:27.364096       1 round_trippers.go:405] PUT https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 14 milliseconds
I0309 22:16:27.364200       1 leaderelection.go:199] successfully renewed lease default/aad-pod-identity-mic
I0309 22:16:31.126876       1 round_trippers.go:405] GET https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 12 milliseconds
I0309 22:16:31.138372       1 round_trippers.go:405] PUT https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 11 milliseconds
I0309 22:16:31.138468       1 leaderelection.go:199] successfully renewed lease default/aad-pod-identity-mic
I0309 22:16:34.895899       1 round_trippers.go:405] GET https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 6 milliseconds
I0309 22:16:34.907956       1 round_trippers.go:405] PUT https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 11 milliseconds
I0309 22:16:34.908054       1 leaderelection.go:199] successfully renewed lease default/aad-pod-identity-mic
I0309 22:16:38.675836       1 round_trippers.go:405] GET https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 17 milliseconds
I0309 22:16:38.684316       1 round_trippers.go:405] PUT https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 8 milliseconds
I0309 22:16:38.684446       1 leaderelection.go:199] successfully renewed lease default/aad-pod-identity-mic
I0309 22:16:42.438129       1 round_trippers.go:405] GET https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 3 milliseconds
I0309 22:16:42.448042       1 round_trippers.go:405] PUT https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 9 milliseconds
I0309 22:16:42.448146       1 leaderelection.go:199] successfully renewed lease default/aad-pod-identity-mic
I0309 22:16:46.202203       1 round_trippers.go:405] GET https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 3 milliseconds
I0309 22:16:46.210022       1 round_trippers.go:405] PUT https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 7 milliseconds
I0309 22:16:46.210107       1 leaderelection.go:199] successfully renewed lease default/aad-pod-identity-mic
I0309 22:16:48.933433       1 reflector.go:286] pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:99: forcing resync
I0309 22:16:50.003191       1 round_trippers.go:405] GET https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 42 milliseconds
I0309 22:16:50.012712       1 round_trippers.go:405] PUT https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 9 milliseconds
I0309 22:16:50.012812       1 leaderelection.go:199] successfully renewed lease default/aad-pod-identity-mic
I0309 22:16:53.766731       1 round_trippers.go:405] GET https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 3 milliseconds
I0309 22:16:53.774043       1 round_trippers.go:405] PUT https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 7 milliseconds
I0309 22:16:53.774154       1 leaderelection.go:199] successfully renewed lease default/aad-pod-identity-mic
I0309 22:16:57.529232       1 round_trippers.go:405] GET https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 4 milliseconds
I0309 22:16:57.538105       1 round_trippers.go:405] PUT https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 8 milliseconds
I0309 22:16:57.538189       1 leaderelection.go:199] successfully renewed lease default/aad-pod-identity-mic
I0309 22:17:01.307260       1 round_trippers.go:405] GET https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 18 milliseconds
I0309 22:17:01.315812       1 round_trippers.go:405] PUT https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 8 milliseconds
I0309 22:17:01.315946       1 leaderelection.go:199] successfully renewed lease default/aad-pod-identity-mic
I0309 22:17:05.070436       1 round_trippers.go:405] GET https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 4 milliseconds
I0309 22:17:05.077969       1 round_trippers.go:405] PUT https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 7 milliseconds
I0309 22:17:05.078084       1 leaderelection.go:199] successfully renewed lease default/aad-pod-identity-mic
I0309 22:17:07.743932       1 reflector.go:428] pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:99: Watch close - *v1.AzureIdentityBinding total 0 items received
I0309 22:17:07.745625       1 round_trippers.go:405] GET https://10.0.0.1:443/apis/aadpodidentity.k8s.io/v1/azureidentitybindings?resourceVersion=27889787&timeoutSeconds=485&watch=true 200 OK in 1 milliseconds
I0309 22:17:08.832186       1 round_trippers.go:405] GET https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 3 milliseconds
I0309 22:17:08.841755       1 round_trippers.go:405] PUT https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 9 milliseconds
I0309 22:17:08.841857       1 leaderelection.go:199] successfully renewed lease default/aad-pod-identity-mic
I0309 22:17:12.613080       1 round_trippers.go:405] GET https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 20 milliseconds
I0309 22:17:12.621828       1 round_trippers.go:405] PUT https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 8 milliseconds
I0309 22:17:12.621917       1 leaderelection.go:199] successfully renewed lease default/aad-pod-identity-mic
I0309 22:17:14.350944       1 cloudprovider.go:204] UpdateUserMSI of aks-agentpool-42293377-3 completed in 56.320197036s
I0309 22:17:14.350987       1 crd.go:539] Updating assigned identity default/jenkinsdeployer-dzj18-cicd-azure-identity status to Assigned
I0309 22:17:14.365956       1 round_trippers.go:405] PATCH https://10.0.0.1:443/apis/aadpodidentity.k8s.io/v1/namespaces/default/azureassignedidentities/jenkinsdeployer-dzj18-cicd-azure-identity 200 OK in 14 milliseconds
I0309 22:17:14.365996       1 crd.go:566] Patch of jenkinsdeployer-dzj18-cicd-azure-identity took: 14.991147ms
I0309 22:17:14.366029       1 mic.go:367] Work done: true. Found 1 pods, 1 ids, 1 bindings
I0309 22:17:14.366035       1 mic.go:368] Total work cycles: 42601, out of which work was done in: 9184.
I0309 22:17:14.366061       1 stats.go:98] ** Stats collected **
I0309 22:17:14.366115       1 stats.go:81] Pod listing: 91.1µs
I0309 22:17:14.366122       1 stats.go:81] ID listing: 9.4µs
I0309 22:17:14.366127       1 stats.go:81] Binding listing: 24.3µs
I0309 22:17:14.366131       1 stats.go:81] Assigned ID listing: 800ns
I0309 22:17:14.366135       1 stats.go:81] System: 133.4µs
I0309 22:17:14.366138       1 stats.go:81] CacheSync: 0s
I0309 22:17:14.366143       1 stats.go:81] Cloud provider get: 29.806494ms
I0309 22:17:14.366147       1 stats.go:81] Cloud provider put: 56.320161436s
I0309 22:17:14.366151       1 stats.go:81] Assigned ID addition: 25.178479ms
I0309 22:17:14.366155       1 stats.go:81] Assigned ID deletion: 0s
I0309 22:17:14.366159       1 stats.go:88] Number of cloud provider PUT: 1
I0309 22:17:14.366162       1 stats.go:88] Number of cloud provider GET: 1
I0309 22:17:14.366166       1 stats.go:88] Number of assigned ids created in this sync cycle: 1
I0309 22:17:14.366169       1 stats.go:88] Number of assigned ids deleted in this sync cycle: 0
I0309 22:17:14.366173       1 stats.go:81] Find assigned ids to create: 0s
I0309 22:17:14.366176       1 stats.go:81] Find assigned ids to delete: 0s
I0309 22:17:14.366180       1 stats.go:81] Total time to assign or remove IDs: 56.390449358s
I0309 22:17:14.366184       1 stats.go:81] Event recording: 0s
I0309 22:17:14.366188       1 stats.go:81] Total: 56.391041459s
I0309 22:17:14.366192       1 stats.go:127] *********************
I0309 22:17:14.566481       1 mic.go:268] Received event: 2
I0309 22:17:14.566622       1 crd.go:390] Appending binding: default/azure-identity-binding to list.
I0309 22:17:14.566663       1 crd.go:477] Appending Identity: default/azure-identity to list.
I0309 22:17:14.566682       1 mic.go:434] Found binding match for pod cicd/jenkinsdeployer-dzj18 with binding default/azure-identity-binding
I0309 22:17:14.566696       1 mic.go:441] Looking up id map: default/azure-identity
I0309 22:17:14.566703       1 mic.go:452] identity default/azure-identity assigned to cicd/jenkinsdeployer-dzj18 via default/azure-identity-binding
I0309 22:17:14.566712       1 mic.go:647] Binding - {TypeMeta:{Kind:v1.AzureIdentityBinding APIVersion:aadpodidentity.k8s.io/v1} ObjectMeta:{Name:azure-identity-binding GenerateName: Namespace:default SelfLink:/apis/aadpodidentity.k8s.io/v1/namespaces/default/azureidentitybindings/azure-identity-binding UID:0e15f3f0-4f16-11ea-806a-fadb4ba9caab ResourceVersion:23914634 Generation:1 CreationTimestamp:2020-02-14 10:37:53 +0000 UTC DeletionTimestamp:<nil> DeletionGracePeriodSeconds:<nil> Labels:map[app.kubernetes.io/instance:aad-pod-identity app.kubernetes.io/managed-by:Tiller app.kubernetes.io/name:aad-pod-identity helm.sh/chart:aad-pod-identity-1.5.5] Annotations:map[] OwnerReferences:[] Initializers:nil Finalizers:[] ClusterName:} Spec:{ObjectMeta:{Name: GenerateName: Namespace: SelfLink: UID: ResourceVersion: Generation:0 CreationTimestamp:0001-01-01 00:00:00 +0000 UTC DeletionTimestamp:<nil> DeletionGracePeriodSeconds:<nil> Labels:map[] Annotations:map[] OwnerReferences:[] Initializers:nil Finalizers:[] ClusterName:} AzureIdentity:azure-identity Selector:automation-identity-selector Weight:0} Status:{ObjectMeta:{Name: GenerateName: Namespace: SelfLink: UID: ResourceVersion: Generation:0 CreationTimestamp:0001-01-01 00:00:00 +0000 UTC DeletionTimestamp:<nil> DeletionGracePeriodSeconds:<nil> Labels:map[] Annotations:map[] OwnerReferences:[] Initializers:nil Finalizers:[] ClusterName:} AvailableReplicas:0}} Identity - {TypeMeta:{Kind:v1.AzureIdentity APIVersion:aadpodidentity.k8s.io/v1} ObjectMeta:{Name:azure-identity GenerateName: Namespace:default SelfLink:/apis/aadpodidentity.k8s.io/v1/namespaces/default/azureidentities/azure-identity UID:0dfb59f0-4f16-11ea-806a-fadb4ba9caab ResourceVersion:23914617 Generation:1 CreationTimestamp:2020-02-14 10:37:53 +0000 UTC DeletionTimestamp:<nil> DeletionGracePeriodSeconds:<nil> Labels:map[app.kubernetes.io/instance:aad-pod-identity app.kubernetes.io/managed-by:Tiller app.kubernetes.io/name:aad-pod-identity helm.sh/chart:aad-pod-identity-1.5.5] Annotations:map[] OwnerReferences:[] Initializers:nil Finalizers:[] ClusterName:} Spec:{ObjectMeta:{Name: GenerateName: Namespace: SelfLink: UID: ResourceVersion: Generation:0 CreationTimestamp:0001-01-01 00:00:00 +0000 UTC DeletionTimestamp:<nil> DeletionGracePeriodSeconds:<nil> Labels:map[] Annotations:map[] OwnerReferences:[] Initializers:nil Finalizers:[] ClusterName:} Type:0 ResourceID:/subscriptions/393758ae-a6a1-4c2a-bdd7-47b567050cc0/resourcegroups/aq-mgmt-westeurope-v1/providers/Microsoft.ManagedIdentity/userAssignedIdentities/aq-automation-westeurope-v1 ClientID:91bedfbd-01b1-4470-ac44-e454da9e298a ClientPassword:{Name: Namespace:} TenantID: ADResourceID: ADEndpoint: Replicas:<nil>} Status:{ObjectMeta:{Name: GenerateName: Namespace: SelfLink: UID: ResourceVersion: Generation:0 CreationTimestamp:0001-01-01 00:00:00 +0000 UTC DeletionTimestamp:<nil> DeletionGracePeriodSeconds:<nil> Labels:map[] Annotations:map[] OwnerReferences:[] Initializers:nil Finalizers:[] ClusterName:} AvailableReplicas:0}}
I0309 22:17:14.566820       1 mic.go:648] Making assigned ID: &{TypeMeta:{Kind: APIVersion:} ObjectMeta:{Name:jenkinsdeployer-dzj18-cicd-azure-identity GenerateName: Namespace:default SelfLink: UID: ResourceVersion: Generation:0 CreationTimestamp:0001-01-01 00:00:00 +0000 UTC DeletionTimestamp:<nil> DeletionGracePeriodSeconds:<nil> Labels:map[nodename:aks-agentpool-42293377-3 podname:jenkinsdeployer-dzj18 podnamespace:cicd] Annotations:map[] OwnerReferences:[] Initializers:nil Finalizers:[] ClusterName:} Spec:{ObjectMeta:{Name: GenerateName: Namespace: SelfLink: UID: ResourceVersion: Generation:0 CreationTimestamp:0001-01-01 00:00:00 +0000 UTC DeletionTimestamp:<nil> DeletionGracePeriodSeconds:<nil> Labels:map[] Annotations:map[] OwnerReferences:[] Initializers:nil Finalizers:[] ClusterName:} AzureIdentityRef:0xc000a25180 AzureBindingRef:0xc000a24e00 Pod:jenkinsdeployer-dzj18 PodNamespace:cicd NodeName:aks-agentpool-42293377-3 Replicas:<nil>} Status:{ObjectMeta:{Name: GenerateName: Namespace: SelfLink: UID: ResourceVersion: Generation:0 CreationTimestamp:0001-01-01 00:00:00 +0000 UTC DeletionTimestamp:<nil> DeletionGracePeriodSeconds:<nil> Labels:map[] Annotations:map[] OwnerReferences:[] Initializers:nil Finalizers:[] ClusterName:} Status: AvailableReplicas:1}}
I0309 22:17:14.566924       1 mic.go:325] del: map[], add: map[]
I0309 22:17:16.378493       1 round_trippers.go:405] GET https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 6 milliseconds
I0309 22:17:16.385330       1 round_trippers.go:405] PUT https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 6 milliseconds
I0309 22:17:16.385411       1 leaderelection.go:199] successfully renewed lease default/aad-pod-identity-mic
I0309 22:17:18.933772       1 reflector.go:286] pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:99: forcing resync
I0309 22:17:20.140539       1 round_trippers.go:405] GET https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 4 milliseconds
I0309 22:17:20.170700       1 round_trippers.go:405] PUT https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 29 milliseconds
I0309 22:17:20.170823       1 leaderelection.go:199] successfully renewed lease default/aad-pod-identity-mic
I0309 22:17:23.937153       1 round_trippers.go:405] GET https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 15 milliseconds
I0309 22:17:23.944199       1 round_trippers.go:405] PUT https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 6 milliseconds
I0309 22:17:23.944289       1 leaderelection.go:199] successfully renewed lease default/aad-pod-identity-mic
I0309 22:17:27.698439       1 round_trippers.go:405] GET https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 3 milliseconds
I0309 22:17:27.705249       1 round_trippers.go:405] PUT https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 6 milliseconds
I0309 22:17:27.705341       1 leaderelection.go:199] successfully renewed lease default/aad-pod-identity-mic
I0309 22:17:31.459256       1 round_trippers.go:405] GET https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 3 milliseconds
I0309 22:17:31.466403       1 round_trippers.go:405] PUT https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 6 milliseconds
I0309 22:17:31.466554       1 leaderelection.go:199] successfully renewed lease default/aad-pod-identity-mic
I0309 22:17:35.228256       1 round_trippers.go:405] GET https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 11 milliseconds
I0309 22:17:35.237434       1 round_trippers.go:405] PUT https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 8 milliseconds
I0309 22:17:35.237544       1 leaderelection.go:199] successfully renewed lease default/aad-pod-identity-mic
I0309 22:17:38.991701       1 round_trippers.go:405] GET https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 3 milliseconds
I0309 22:17:38.998869       1 round_trippers.go:405] PUT https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 6 milliseconds
I0309 22:17:38.999004       1 leaderelection.go:199] successfully renewed lease default/aad-pod-identity-mic
I0309 22:17:42.753187       1 round_trippers.go:405] GET https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 3 milliseconds
I0309 22:17:42.763980       1 round_trippers.go:405] PUT https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 10 milliseconds
I0309 22:17:42.764122       1 leaderelection.go:199] successfully renewed lease default/aad-pod-identity-mic
I0309 22:17:46.527744       1 round_trippers.go:405] GET https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 13 milliseconds
I0309 22:17:46.538289       1 round_trippers.go:405] PUT https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 10 milliseconds
I0309 22:17:46.538386       1 leaderelection.go:199] successfully renewed lease default/aad-pod-identity-mic
I0309 22:17:48.934208       1 reflector.go:286] pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:99: forcing resync
I0309 22:17:50.292963       1 round_trippers.go:405] GET https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 4 milliseconds
I0309 22:17:50.302178       1 round_trippers.go:405] PUT https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 9 milliseconds
I0309 22:17:50.302272       1 leaderelection.go:199] successfully renewed lease default/aad-pod-identity-mic
I0309 22:17:54.055917       1 round_trippers.go:405] GET https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 3 milliseconds
I0309 22:17:54.064841       1 round_trippers.go:405] PUT https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 8 milliseconds
I0309 22:17:54.064929       1 leaderelection.go:199] successfully renewed lease default/aad-pod-identity-mic
I0309 22:17:57.841657       1 round_trippers.go:405] GET https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 26 milliseconds
I0309 22:17:57.852558       1 round_trippers.go:405] PUT https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 10 milliseconds
I0309 22:17:57.852653       1 leaderelection.go:199] successfully renewed lease default/aad-pod-identity-mic
I0309 22:18:01.606616       1 round_trippers.go:405] GET https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 3 milliseconds
I0309 22:18:01.618997       1 round_trippers.go:405] PUT https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 12 milliseconds
I0309 22:18:01.619102       1 leaderelection.go:199] successfully renewed lease default/aad-pod-identity-mic
I0309 22:18:05.373639       1 round_trippers.go:405] GET https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 4 milliseconds
I0309 22:18:05.381261       1 round_trippers.go:405] PUT https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 7 milliseconds
I0309 22:18:05.381336       1 leaderelection.go:199] successfully renewed lease default/aad-pod-identity-mic
I0309 22:18:09.144630       1 round_trippers.go:405] GET https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 12 milliseconds
I0309 22:18:09.156100       1 round_trippers.go:405] PUT https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 11 milliseconds
I0309 22:18:09.156213       1 leaderelection.go:199] successfully renewed lease default/aad-pod-identity-mic
I0309 22:18:12.910549       1 round_trippers.go:405] GET https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 3 milliseconds
I0309 22:18:12.919027       1 round_trippers.go:405] PUT https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 8 milliseconds
I0309 22:18:12.919196       1 leaderelection.go:199] successfully renewed lease default/aad-pod-identity-mic
I0309 22:18:16.672875       1 round_trippers.go:405] GET https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 3 milliseconds
I0309 22:18:16.679362       1 round_trippers.go:405] PUT https://10.0.0.1:443/api/v1/namespaces/default/endpoints/aad-pod-identity-mic 200 OK in 6 milliseconds
I0309 22:18:16.679442       1 leaderelection.go:199] successfully renewed lease default/aad-pod-identity-mic

with corresponding NMI logs:

time="2020-03-09T22:17:16Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://management.core.windows.net/" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:17:16Z" level=info msg="Status (200) took 90018701453 ns" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:17:24Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://management.core.windows.net/" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:17:24Z" level=info msg="Status (200) took 4557198 ns" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:17:26Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://management.core.windows.net/" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:17:26Z" level=info msg="Status (200) took 4264098 ns" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:17:26Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://management.core.windows.net/" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:17:26Z" level=info msg="Status (200) took 4250498 ns" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:17:28Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://management.core.windows.net/" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:17:28Z" level=info msg="Status (200) took 5629498 ns" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:17:49Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://management.azure.com/" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:17:49Z" level=info msg="Status (200) took 4798898 ns" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:17:52Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://vault.azure.net" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:17:52Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://vault.azure.net" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:17:52Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://vault.azure.net" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:17:52Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://vault.azure.net" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:17:52Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://vault.azure.net" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:17:52Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://vault.azure.net" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:17:52Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://vault.azure.net" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:17:52Z" level=info msg="Status (200) took 3668499 ns" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:17:52Z" level=info msg="Status (200) took 4195199 ns" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:17:52Z" level=info msg="Status (200) took 5863798 ns" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:17:52Z" level=info msg="Status (200) took 8036598 ns" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:17:52Z" level=info msg="Status (200) took 5059999 ns" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:17:52Z" level=info msg="Status (200) took 5303699 ns" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:17:52Z" level=info msg="Status (200) took 5412299 ns" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:17:52Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://vault.azure.net" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:17:52Z" level=info msg="Status (200) took 3371399 ns" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:17:52Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://vault.azure.net" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:17:52Z" level=info msg="Status (200) took 2990099 ns" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:17:52Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://vault.azure.net" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:17:52Z" level=info msg="Status (200) took 3613000 ns" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:17:52Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://vault.azure.net" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:17:52Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://vault.azure.net" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:17:52Z" level=info msg="Status (200) took 4751299 ns" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:17:52Z" level=info msg="Status (200) took 3692500 ns" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:17:52Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://vault.azure.net" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:17:52Z" level=info msg="Status (200) took 3876499 ns" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:17:52Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://vault.azure.net" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:17:52Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://vault.azure.net" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:17:52Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://vault.azure.net" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:17:52Z" level=info msg="Status (200) took 5700899 ns" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:17:52Z" level=info msg="Status (200) took 3147699 ns" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:17:52Z" level=info msg="Status (200) took 3426899 ns" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:17:52Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://vault.azure.net" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:17:52Z" level=info msg="Status (200) took 3863899 ns" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:17:52Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://vault.azure.net" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:17:52Z" level=info msg="Status (200) took 3098500 ns" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:17:52Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://vault.azure.net" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:17:52Z" level=info msg="Status (200) took 6276698 ns" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:17:52Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://vault.azure.net" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:17:52Z" level=info msg="Status (200) took 4459699 ns" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:17:52Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://vault.azure.net" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:17:52Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://vault.azure.net" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:17:52Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://vault.azure.net" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:17:52Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://vault.azure.net" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:17:52Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://vault.azure.net" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:17:52Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://vault.azure.net" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:17:52Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://vault.azure.net" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:17:52Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://vault.azure.net" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:17:52Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://vault.azure.net" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:17:55Z" level=info msg="Status (200) took 3008436409 ns" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:17:55Z" level=info msg="Status (200) took 3007830508 ns" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:17:55Z" level=info msg="Status (200) took 3009566409 ns" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:17:55Z" level=info msg="Status (200) took 3007436109 ns" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:17:55Z" level=info msg="Status (200) took 3019685006 ns" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:17:55Z" level=info msg="Status (200) took 3008211809 ns" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:17:55Z" level=info msg="Status (200) took 3008432309 ns" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:17:55Z" level=info msg="Status (200) took 3010083209 ns" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:17:55Z" level=info msg="Status (200) took 3071444895 ns" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:18:05Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://management.azure.com/" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:18:05Z" level=info msg="Status (200) took 4152099 ns" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:18:17Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://management.azure.com/" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:18:17Z" level=info msg="Status (200) took 5440199 ns" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:18:36Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://management.core.windows.net/" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:18:36Z" level=info msg="Status (200) took 5315199 ns" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:18:38Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://management.core.windows.net/" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:18:38Z" level=info msg="Status (200) took 15142300 ns" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:18:38Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://management.core.windows.net/" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:18:38Z" level=info msg="Status (200) took 3707500 ns" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:18:39Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://management.core.windows.net/" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:18:39Z" level=info msg="Status (200) took 4826800 ns" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:18:53Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://management.azure.com/" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:18:53Z" level=info msg="Status (200) took 4425301 ns" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:18:56Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://vault.azure.net" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:18:56Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://vault.azure.net" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:18:56Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://vault.azure.net" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:18:56Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://vault.azure.net" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:18:56Z" level=info msg="Status (200) took 5814800 ns" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:18:56Z" level=info msg="Status (200) took 5394100 ns" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:18:56Z" level=info msg="Status (200) took 5968600 ns" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:18:56Z" level=info msg="Status (200) took 4216601 ns" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:18:56Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://vault.azure.net" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:18:56Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://vault.azure.net" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:18:56Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://vault.azure.net" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:18:56Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://vault.azure.net" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:18:56Z" level=info msg="Status (200) took 3738300 ns" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:18:56Z" level=info msg="Status (200) took 3911900 ns" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:18:56Z" level=info msg="Status (200) took 3984500 ns" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:18:56Z" level=info msg="Status (200) took 3866500 ns" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:18:56Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://vault.azure.net" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:18:56Z" level=info msg="Status (200) took 2929600 ns" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:18:56Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://vault.azure.net" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:18:56Z" level=info msg="Status (200) took 3612101 ns" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:18:56Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://vault.azure.net" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:18:56Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://vault.azure.net" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:18:56Z" level=info msg="Status (200) took 12194801 ns" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:18:56Z" level=info msg="Status (200) took 12262101 ns" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:18:56Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://vault.azure.net" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:18:56Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://vault.azure.net" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:18:56Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://vault.azure.net" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:18:56Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://vault.azure.net" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:18:56Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://vault.azure.net" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:18:56Z" level=info msg="Status (200) took 7141000 ns" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:18:56Z" level=info msg="Status (200) took 7294300 ns" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:18:56Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://vault.azure.net" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:18:56Z" level=info msg="Status (200) took 9109400 ns" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:18:56Z" level=info msg="Status (200) took 7295201 ns" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:18:56Z" level=info msg="Status (200) took 5857801 ns" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:18:56Z" level=info msg="Status (200) took 3289401 ns" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:18:56Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://vault.azure.net" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:18:56Z" level=info msg="Status (200) took 2943000 ns" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:18:56Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://vault.azure.net" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:18:56Z" level=info msg="Status (200) took 3517900 ns" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:18:56Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://vault.azure.net" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:18:56Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://vault.azure.net" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:18:56Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://vault.azure.net" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:18:56Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://vault.azure.net" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:18:56Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://vault.azure.net" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:18:56Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://vault.azure.net" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:18:56Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://vault.azure.net" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:18:56Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://vault.azure.net" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129
time="2020-03-09T22:18:56Z" level=info msg="matched identityType:0 clientid:91be##### REDACTED #####298a resource:https://vault.azure.net" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.117.0.129

cwebbtw on 9 Mar 2020

@kkmsft @aramase I'm seeing this error continuously from this afternoon. Seeing less than 5% success rate for the calls. Issue is same as @cwebbtw posted. I'm running on VMSS. I'll go through the suggestions and paste the logs. i have also raised a support case as it is affecting our release - 120041323001111. Can you please help?

vishnujanardhanan on 13 Apr 2020

For VMAS, there was a change the compute resource provider which is causing increased time for identity assignment PUT calls. That's what @cwebbtw is observing on the cluster.

@vishnujanardhanan What is the time you are seeing in the MIC logs for the PUT operation? Typically on VMSS, the identity assignment PUT call takes ~40s-1min.

aramase on 13 Apr 2020

@aramase I see the below in the logs

I0413 17:52:03.268069 1 mic.go:317] Found 0 pods, 1 ids, 1 bindings
I0413 17:52:03.268088 1 stats.go:65] * Stats collected *
I0413 17:52:03.268094 1 stats.go:61] Pod listing: 23µs
I0413 17:52:03.268101 1 stats.go:61] ID listing: 14.49086ms
I0413 17:52:03.268105 1 stats.go:61] Binding listing: 28.991222ms
I0413 17:52:03.268108 1 stats.go:61] Assigned ID listing: 3.94029ms
I0413 17:52:03.268112 1 stats.go:61] System: 47.451472ms
I0413 17:52:03.268115 1 stats.go:61] Cloud provider get: 29.085421ms
I0413 17:52:03.268119 1 stats.go:61] Cloud provider put: 37.929095477s
I0413 17:52:03.268122 1 stats.go:61] Assigned ID addition: 0s
I0413 17:52:03.268126 1 stats.go:61] Assigned ID deletion: 17.883551ms
I0413 17:52:03.268129 1 stats.go:61] Find assigned ids to create: 100ns
I0413 17:52:03.268133 1 stats.go:61] Find assigned ids to delete: 0s
I0413 17:52:03.268136 1 stats.go:61] Total time to assign or remove IDs: 37.990430809s
I0413 17:52:03.268140 1 stats.go:61] Event recording: 0s
I0413 17:52:03.268144 1 stats.go:61] Total: 38.037944081s

It seems to take 38 seconds, but az login --identity times-out before.. May i know how to increase the timeout of nmi? And any idea why do i see this suddenly today?

vishnujanardhanan on 13 Apr 2020

It seems to take 38 seconds, but az login --identity times-out before.. May i know how to increase the timeout of nmi? And any idea why do i see this suddenly today?

@vishnujanardhanan 40s-1m is the excepted time for identity assignment in VMSS. NMI already handles retries. By default it retries 16 times with 5s interval (total 80s) unless the request is cancelled before. If you are seeing times in the range > 2 or 3m, it might be because of the current load in the compute services. What is the error log you see in NMI before the timeout?

aramase on 13 Apr 2020

@aramase is this the parameter used for retries? i'm using the default which is 4, so i guess it times-out in 20 seconds

Override number of retries in NMI to find assigned identity in ASSIGNED state (default is 4)
retryAttemptsForAssigned:

vishnujanardhanan on 13 Apr 2020

@vishnujanardhanan These are the flags for retries - https://github.com/Azure/aad-pod-identity/blob/master/charts/aad-pod-identity/values.yaml#L124-L131

The retryAttemptsForCreated default value is 16 and retryAttemptsForAssigned default value is 4. MIC creates an AzureAssignedIdentity in CREATED state first and then assigns the identity to the underlying node (VM/VMSS). After successfully assigning the identity, it switches the state to ASSIGNED. Only after the status changes to ASSIGNED NMI will fetch a token and return. So, NMI first tries 16*5s = 80s to find an AzureAssignedIdentity in CREATED state. If found, then it'll wait an additional 20s to see if the identity moves to ASSIGNED state.

aramase on 13 Apr 2020

@aramase thanks, this is the error I see in nmi logs

time="2020-04-13T18:09:21Z" level=warning msg="failed to get assigned ids for pod:cicd/jenkinsdeployer-tdtx4 in ASSIGNED state, retrying attempt: 1" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.118.77.38
time="2020-04-13T18:09:26Z" level=warning msg="failed to get assigned ids for pod:cicd/jenkinsdeployer-tdtx4 in ASSIGNED state, retrying attempt: 2" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.118.77.38
time="2020-04-13T18:09:26Z" level=info msg="matched identityType:0 clientid:xxxxxxxxx resource:https://management.core.windows.net/" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.118.77.38
time="2020-04-13T18:09:26Z" level=error msg="failed to get service principal token for pod:cicd/jenkinsdeployer-tdtx4, 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.118.77.38
time="2020-04-13T18:09:26Z" level=info msg="Status (403) took 10257911442 ns" req.method=GET req.path=/metadata/identity/oauth2/token req.remote=10.118.77.38

vishnujanardhanan on 13 Apr 2020

@vishnujanardhanan Was the identity recreated with the same name? Looks the clientID doesn't match what's on the vmss which is why token request is error-ing out. Check the output for az vmss identity show -g <rg> -n <vmss name> and see what the client id is.

aramase on 13 Apr 2020

@aramase No, there were no changes made to identity. I have verified the out put of the command and it seems to be the same. I have pasted the output in support case - 120041323001111.

vishnujanardhanan on 13 Apr 2020

and it was working sometime in the evening for few requests, so it works for few requests and it fails for 95 percent of other requests.

vishnujanardhanan on 13 Apr 2020

Are all the requests using the same user MSI? I can't see the output for az vmss command in the support case, but you've confirmed the clientID that you see in the NMI request is the same as the clientID shown in the az vmss identity show output and also the clientID is the same for the user managed identity in the azure portal?

aramase on 13 Apr 2020

are you able to give me your MS email? I shall send them to you?

vishnujanardhanan on 13 Apr 2020

sure, [email protected]

aramase on 13 Apr 2020

Closing this issue as this no longer occurring and the fix for delays in identity assignment for VMAS is rolled out to all the regions. Please feel free to reopen if this is still an issue.

aramase on 10 Jul 2020

@aramase We are still seeing this in Azure Commercial when we are assigning identities to a dozen pods at a time.
Specifically when using the identity for the same MSI across 10 pods spinning up super fast.