istio-policy pod presents CrashLoopBackOff every few seconds

9/30/2019

I am fighting the below error for the last day or so. Please help with any idea.

Here is my configuration:

Install:

ISTIO_VERSION=istio-1.2.6
GATEWAYS=gateways

kubectl create ns istio-system

helm install $ISTIO_VERSION/install/kubernetes/helm/istio-init \
    --name istio-init \
    --namespace istio-system

helm install $ISTIO_VERSION/install/kubernetes/helm/istio \
--name istio \
--namespace istio-system \
--values $GATEWAYS/values.yaml 

values.yaml is istio/install/kubernetes/helm/istio/values-istio-demo.yaml

Node is fine:

Namespace                  Name                                       CPU Requests  CPU Limits  Memory Requests  Memory Limits  AGE
  ---------                  ----                                       ------------  ----------  ---------------  -------------  ---
  flight                     dragon-dc789456b-tlbqd                     100m (5%)     2 (103%)    128Mi (5%)       128Mi (5%)     7d3h
  istio-system               istio-citadel-b676479fb-pncst              10m (0%)      0 (0%)      0 (0%)           0 (0%)         8m46s
  istio-system               istio-egressgateway-9d45cfb7d-l5g6t        10m (0%)      2 (103%)    40Mi (1%)        256Mi (11%)    8m47s
  istio-system               istio-galley-5694ff64dc-6n57h              10m (0%)      0 (0%)      0 (0%)           0 (0%)         8m47s
  istio-system               istio-ingressgateway-6849cf65c8-xm2ng      10m (0%)      2 (103%)    40Mi (1%)        1Gi (47%)      8m47s
  istio-system               istio-pilot-5c5bf5c9bc-xx8zb               20m (1%)      2 (103%)    140Mi (6%)       1Gi (47%)      8m46s
  istio-system               istio-policy-8fbf8b499-nvwsr               20m (1%)      2 (103%)    140Mi (6%)       1Gi (47%)      8m46s
  istio-system               istio-sidecar-injector-56cb646f8d-x8gfx    10m (0%)      0 (0%)      0 (0%)           0 (0%)         8m46s
  istio-system               prometheus-776fdf7479-cwddf                10m (0%)      0 (0%)      0 (0%)           0 (0%)         8m46s
  kube-system                coredns-745c97fd79-4bflf                   100m (5%)     0 (0%)      70Mi (3%)        170Mi (7%)     8d
  kube-system                coredns-745c97fd79-w7mvr                   100m (5%)     0 (0%)      70Mi (3%)        170Mi (7%)     8d
  kube-system                coredns-autoscaler-657d77ffbf-6qt4q        20m (1%)      0 (0%)      10Mi (0%)        0 (0%)         8d
  kube-system                kube-proxy-kbltl                           100m (5%)     0 (0%)      0 (0%)           0 (0%)         3d9h
  kube-system                kubernetes-dashboard-6f697bd9f5-4dpm9      100m (5%)     100m (5%)   50Mi (2%)        500Mi (23%)    8d
  kube-system                metrics-server-58699455bc-szmhm            0 (0%)        0 (0%)      0 (0%)           0 (0%)         8d
  kube-system                tiller-deploy-57f498469-4gk9m              0 (0%)        0 (0%)      0 (0%)           0 (0%)         8d
  kube-system                tunnelfront-d754df55-ngwqs                 10m (0%)      0 (0%)      64Mi (2%)        0 (0%)         8d
Allocated resources:
  (Total limits may be over 100 percent, i.e., overcommitted.)
  Resource                       Requests     Limits
  --------                       --------     ------
  cpu                            630m (32%)   10100m (523%)
  memory                         752Mi (34%)  4296Mi (199%)
  ephemeral-storage              0 (0%)       0 (0%)
  attachable-volumes-azure-disk  0            0

Error:

stio-system istio-policy-8fbf8b499-nvwsr 1/2 CrashLoopBackOff 6 6m5s Warning Unhealthy 9m38s (x9 over 10m) kubelet, aks-nodepool1-20283962-1 Liveness probe failed: Get http://10.244.1.237:15014/version: dial tcp 10.244.1.237:15014: connect: connection refused

Events:
  Type     Reason       Age                     From                               Message
  ----     ------       ----                    ----                               -------
  Normal   Scheduled    10m                     default-scheduler                  Successfully assigned istio-system/istio-policy-8fbf8b499-nvwsr to aks-nodepool1-20283962-1
  Warning  FailedMount  10m                     kubelet, aks-nodepool1-20283962-1  MountVolume.SetUp failed for volume "istio-mixer-service-account-token-sdhhh" : couldn't propagate object cache: timed out waiting for the condition
  Warning  FailedMount  10m                     kubelet, aks-nodepool1-20283962-1  MountVolume.SetUp failed for volume "policy-adapter-secret" : couldn't propagate object cache: timed out waiting for the condition
  Normal   Pulled       10m                     kubelet, aks-nodepool1-20283962-1  Container image "docker.io/istio/proxyv2:1.2.6" already present on machine
  Normal   Created      10m                     kubelet, aks-nodepool1-20283962-1  Created container istio-proxy
  Normal   Started      10m                     kubelet, aks-nodepool1-20283962-1  Started container istio-proxy
  Normal   Killing      9m58s (x2 over 10m)     kubelet, aks-nodepool1-20283962-1  Container mixer failed liveness probe, will be restarted
  Normal   Pulled       9m57s (x3 over 10m)     kubelet, aks-nodepool1-20283962-1  Container image "docker.io/istio/mixer:1.2.6" already present on machine
  Normal   Started      9m57s (x3 over 10m)     kubelet, aks-nodepool1-20283962-1  Started container mixer
  Normal   Created      9m57s (x3 over 10m)     kubelet, aks-nodepool1-20283962-1  Created container mixer
  Warning  Unhealthy    9m38s (x9 over 10m)     kubelet, aks-nodepool1-20283962-1  Liveness probe failed: Get http://10.244.1.237:15014/version: dial tcp 10.244.1.237:15014: connect: connection refused
  Warning  BackOff      5m36s (x17 over 8m57s)  kubelet, aks-nodepool1-20283962-1  Back-off restarting failed container

Edit

Adding the logs

Mixer:

2019-09-30T07:11:07.621303Z     info    mcp     Requesting following collections:
2019-09-30T07:11:07.621341Z     info    mcp       [0] istio/policy/v1beta1/rules
2019-09-30T07:11:07.621352Z     info    mcp       [1] istio/config/v1alpha2/templates
2019-09-30T07:11:07.621355Z     info    mcp       [2] istio/config/v1alpha2/adapters
2019-09-30T07:11:07.621358Z     info    mcp       [3] istio/policy/v1beta1/attributemanifests
2019-09-30T07:11:07.621366Z     info    mcp       [4] istio/policy/v1beta1/handlers
2019-09-30T07:11:07.621369Z     info    mcp       [5] istio/policy/v1beta1/instances
2019-09-30T07:11:07.621382Z     info    parsed scheme: ""
2019-09-30T07:11:07.621401Z     info    scheme "" not registered, fallback to default scheme
2019-09-30T07:11:07.621415Z     info    ccResolverWrapper: sending update to cc: {[{istio-galley.istio-system.svc:9901 0  <nil>}] <nil>}
2019-09-30T07:11:07.621420Z     info    ClientConn switching balancer to "pick_first"
2019-09-30T07:11:07.621491Z     info    Awaiting for config store sync...
2019-09-30T07:11:07.621555Z     info    pickfirstBalancer: HandleSubConnStateChange: 0xc000bac360, CONNECTING
2019-09-30T07:11:07.621703Z     info    mcp     (re)trying to establish new MCP sink stream
gc 3 @0.041s 8%: 0.16+9.6+0.004 ms clock, 0.33+8.0/9.2/12+0.008 ms cpu, 6->6->4 MB, 7 MB goal, 6 P
2019-09-30T07:11:07.623952Z     info    pickfirstBalancer: HandleSubConnStateChange: 0xc000bac360, READY
2019-09-30T07:11:07.632586Z     info    mcp     New MCP sink stream created
2019-09-30T07:11:07.641645Z     info    Starting runtime config watch...
2019-09-30T07:11:07.641726Z     info    Built new config.Snapshot: id='0'
2019-09-30T07:11:07.641765Z     info    Cleaning up handler table, with config ID:-1
2019-09-30T07:11:07.644321Z     info    Built new config.Snapshot: id='1'
2019-09-30T07:11:07.644378Z     info    adapters        getting kubeconfig from: ""     {"adapter": "kubernetesenv.istio-system"}
2019-09-30T07:11:07.644411Z     warn    Neither --kubeconfig nor --master was specified.  Using the inClusterConfig.  This might not work.
2019-09-30T07:11:07.645661Z     info    adapters        Waiting for kubernetes cache sync...    {"adapter": "kubernetesenv.istio-system"}
gc 4 @0.110s 4%: 0.073+14+0.004 ms clock, 0.14+1.2/7.9/30+0.008 ms cpu, 8->9->6 MB, 9 MB goal, 6 P
2019-09-30T07:11:07.745792Z     info    adapters        Cache sync successful.  {"adapter": "kubernetesenv.istio-system"}
2019-09-30T07:11:07.745868Z     info    adapters        getting kubeconfig from: ""     {"adapter": "kubernetesenv.istio-system"}
2019-09-30T07:11:07.745913Z     warn    Neither --kubeconfig nor --master was specified.  Using the inClusterConfig.  This might not work.
2019-09-30T07:11:07.747326Z     info    Setting up event handlers
2019-09-30T07:11:07.747502Z     info    Starting Secrets controller
2019-09-30T07:11:07.747720Z     info    Waiting for informer caches to sync
2019-09-30T07:11:07.748131Z     info    Cleaning up handler table, with config ID:0
2019-09-30T07:11:07.748700Z     info    Starting monitor server...
Istio Mixer: root@0798c310-d8da-11e9-89ce-86619cd7d75e-docker.io/istio-1.2.6-b26019f05195188378be9118b0f0fa7613f7ebb4-dirty-Modified
Starting gRPC server on port 9091
2019-09-30T07:11:07.759675Z     info    ControlZ available at 127.0.0.1:9876
gc 5 @0.676s 1%: 0.045+8.6+0.006 ms clock, 0.090+6.7/8.4/10+0.013 ms cpu, 12->12->6 MB, 13 MB goal, 6 P
GC forced
gc 6 @120.763s 0%: 0.015+8.3+0.004 ms clock, 0.030+0/8.2/6.3+0.009 ms cpu, 12->12->6 MB, 13 MB goal, 6 P
scvg0: inuse: 12, idle: 46, sys: 59, released: 0, consumed: 59 (MB)
GC forced
gc 7 @240.863s 0%: 0.033+8.3+0.005 ms clock, 0.067+0/7.3/12+0.011 ms cpu, 12->12->6 MB, 13 MB goal, 6 P
scvg1: inuse: 13, idle: 45, sys: 59, released: 0, consumed: 59 (MB)
GC forced
gc 8 @360.963s 0%: 0.012+8.7+0.004 ms clock, 0.025+0/8.8/8.7+0.009 ms cpu, 12->12->6 MB, 13 MB goal, 6 P
scvg2: 0 MB released
scvg2: inuse: 14, idle: 44, sys: 59, released: 0, consumed: 58 (MB)
GC forced
gc 9 @481.039s 0%: 0.013+27+0.005 ms clock, 0.027+0/13/57+0.010 ms cpu, 12->12->6 MB, 13 MB goal, 6 P
scvg3: inuse: 15, idle: 43, sys: 59, released: 0, consumed: 58 (MB)
GC forced
gc 10 @601.163s 0%: 0.13+7.7+0.004 ms clock, 0.27+0/7.9/8.3+0.009 ms cpu, 11->11->6 MB, 13 MB goal, 6 P
GC forced
gc 11 @721.263s 0%: 0.016+11+0.004 ms clock, 0.032+0/11/28+0.008 ms cpu, 12->12->6 MB, 13 MB goal, 6 P
scvg4: inuse: 12, idle: 46, sys: 59, released: 0, consumed: 58 (MB)
GC forced
gc 12 @841.363s 0%: 0.048+8.6+0.004 ms clock, 0.097+0/8.7/19+0.009 ms cpu, 10->10->6 MB, 13 MB goal, 6 P
scvg5: inuse: 13, idle: 45, sys: 59, released: 0, consumed: 58 (MB)
GC forced
gc 13 @961.463s 0%: 0.014+8.2+0.004 ms clock, 0.028+0/8.5/6.3+0.009 ms cpu, 12->12->6 MB, 13 MB goal, 6 P
scvg6: 0 MB released
scvg6: inuse: 14, idle: 44, sys: 59, released: 0, consumed: 58 (MB)
GC forced
gc 14 @1081.563s 0%: 0.041+12+0.004 ms clock, 0.083+0/13/10+0.009 ms cpu, 12->12->6 MB, 13 MB goal, 6 P

Istio-Proxy

2019-09-30T07:03:44.608327Z     info    PilotSAN []string(nil)
2019-09-30T07:03:44.608429Z     info    Starting proxy agent
2019-09-30T07:03:44.608561Z     info    watching /etc/certs for changes
2019-09-30T07:03:44.608572Z     info    Received new config, resetting budget
2019-09-30T07:03:44.608576Z     info    Reconciling retry (budget 10)
2019-09-30T07:03:44.608600Z     info    Epoch 0 starting
2019-09-30T07:03:44.608633Z     info    Envoy command: [-c /etc/istio/proxy/envoy.yaml --restart-epoch 0 --drain-time-s 45 --parent-shutdown-time-s 60 --service-cluster istio-policy --service-node sidecar~10.244.1.237~istio-policy-8fbf8b499-nvwsr.istio-system~istio-system.svc.cluster.local --max-obj-name-len 189 --local-address-ip-version v4 --allow-unknown-fields -l warning --component-log-level misc:error]
2019-09-30T07:04:01.697784Z     info    watchFileEvents: "/etc/certs/..2019_09_30_07_04_01.483358293": CREATE
2019-09-30T07:04:01.697824Z     info    watchFileEvents: "/etc/certs/..2019_09_30_07_04_01.483358293": MODIFY|ATTRIB
2019-09-30T07:04:01.697832Z     info    watchFileEvents: "/etc/certs/key.pem": CREATE
2019-09-30T07:04:01.697897Z     info    watchFileEvents: "/etc/certs/root-cert.pem": CREATE
2019-09-30T07:04:01.697947Z     info    watchFileEvents: "/etc/certs/cert-chain.pem": CREATE
2019-09-30T07:04:01.698048Z     info    watchFileEvents: "/etc/certs/..data_tmp": RENAME
2019-09-30T07:04:01.698181Z     info    watchFileEvents: "/etc/certs/..data": CREATE
2019-09-30T07:04:01.698200Z     info    watchFileEvents: "/etc/certs/..2019_09_30_07_03_38.857856170": DELETE
2019-09-30T07:04:11.698075Z     info    watchFileEvents: notifying
2019-09-30T07:04:11.698499Z     info    Received new config, resetting budget
2019-09-30T07:04:11.698603Z     info    Reconciling retry (budget 10)
2019-09-30T07:04:11.698683Z     info    Epoch 1 starting
2019-09-30T07:04:11.698791Z     info    Envoy command: [-c /etc/istio/proxy/envoy.yaml --restart-epoch 1 --drain-time-s 45 --parent-shutdown-time-s 60 --service-cluster istio-policy --service-node sidecar~10.244.1.237~istio-policy-8fbf8b499-nvwsr.istio-system~istio-system.svc.cluster.local --max-obj-name-len 189 --local-address-ip-version v4 --allow-unknown-fields -l warning --component-log-level misc:error]
[2019-09-30 07:04:11.717][12][warning][main] [external/envoy/source/server/server.cc:537] shutting down admin due to child startup
[2019-09-30 07:04:11.718][12][warning][main] [external/envoy/source/server/server.cc:546] terminating parent process
[2019-09-30 07:05:11.733][12][warning][main] [external/envoy/source/server/server.cc:426] caught SIGTERM
2019-09-30T07:05:11.736753Z     info    Epoch 0 exited normally
2019-09-30T07:05:11.737082Z     warn    Failed to delete config file /etc/istio/proxy/envoy-rev0.json for 0, remove /etc/istio/proxy/envoy-rev0.json: no such file or directory
-- user3053247
azure-kubernetes
istio
kubernetes

0 Answers