search

aws / karpenter-provider-aws

Karpenter is a Kubernetes Node Autoscaler built for flexibility, performance, and simplicity.
https://karpenter.sh
Apache License 2.0
6.8k stars 957 forks source link

Node take 100s to start #3102

Closed royb-tabit closed 1 year ago

royb-tabit commented 1 year ago

Version

Karpenter Version: v0.20.0 Kubernetes Version: v1.23

Expected Behavior

Node to be in Ready state in about 60 seconds or less

Actual Behavior

000s instance registered to the cluster 038s cloud-init finish 055s kube-proxy is running between 080s and 100s Node is in Ready state

When comparing to "aws-autoscaler" performance with the same lunchTemplet we get about 70s until Node is in ready state.

Steps to Reproduce the Problem

AMI-ID (used in launchTemplate): ami-0c64fd5283c4bfc45

Name:                   rosapi-dev
Namespace:              applications
Labels:                 app.kubernetes.io/instance=rosapi-dev
                        app.kubernetes.io/managed-by=Helm
                        app.kubernetes.io/name=rosapi-dev
                        helm.sh/chart=k8s-service-0.2.0
Annotations:            deployment.kubernetes.io/revision: 43
                        meta.helm.sh/release-name: rosapi-dev
                        meta.helm.sh/release-namespace: applications
                        sidecar.jaegertracing.io/inject: false
Selector:               app.kubernetes.io/instance=rosapi-dev,app.kubernetes.io/name=rosapi-dev,g
runtwork.io/deployment-type=main
Replicas:               1 desired | 1 updated | 1 total | 1 available | 0 unavailable
StrategyType:           RollingUpdate
MinReadySeconds:        0
RollingUpdateStrategy:  25% max unavailable, 25% max surge
Pod Template:
  Labels:           app.kubernetes.io/instance=rosapi-dev
                    app.kubernetes.io/name=rosapi-dev
                    gruntwork.io/deployment-type=main
  Annotations:      kubectl.kubernetes.io/restartedAt: 2022-12-09T18:47:05Z
                    prometheus.io/path: /metrics
                    prometheus.io/port: 1234
                    prometheus.io/scrape: true
  Service Account:  rosapi-dev
  Containers:
   rosapi-dev:
    Image:       ${my_account}.dkr.ecr.eu-west-1.amazonaws.com/rosapi-dev:tag
    Ports:       1234/TCP, 1234/TCP, 1234/TCP
    Host Ports:  0/TCP, 0/TCP, 0/TCP
    Command:
      node
      inpact.js
    Limits:
      cpu:     500m
      memory:  1000Mi
    Requests:
      cpu:     500m
      memory:  1000Mi
    Liveness:  http-get http://:liveness/status delay=15s timeout=2s period=30s #success=1 #failu
re=3
    Startup:   http-get http://:1234/status%3FstartupProbe delay=0s timeout=1s period=10s #succes
s=1 #failure=30
    Environment:
        ...
    Mounts:
      /tmp/LogDir from my-volume (rw)
  Volumes:
   my-volume:
    Type:       EmptyDir (a temporary directory that shares a pod's lifetime)
    Medium:
    SizeLimit:  <unset>
  sidecar:
    Image:      ${my_account}.dkr.ecr.eu-west-1.amazonaws.com/tabit-filebeat:tag
    Port:       80/TCP
    Host Port:  0/TCP
    Limits:
      cpu:     250m
      memory:  500Mi
    Requests:
      cpu:     250m
      memory:  500Mi
    Environment:
        ..
    Mounts:
      /tmp/LogDir from my-volume (rw)
  Volumes:
   my-volume:
    Type:       EmptyDir (a temporary directory that shares a pod's lifetime)
    Medium:
    SizeLimit:  <unset>

  apiVersion: karpenter.sh/v1alpha5
  kind: Provisioner
  metadata:
    name: arm
  spec:
    consolidation:
      enabled: true
    requirements:
      - key: karpenter.sh/capacity-type
        operator: In
        values: ["spot", "on-demand"]
      - key: kubernetes.io/arch
        operator: In
        values:
          - arm64
    limits:
      resources:
        cpu: 1000
    providerRef:
      name: arm
    ttlSecondsUntilExpired: 2592000
apiVersion: karpenter.k8s.aws/v1alpha1
  kind: AWSNodeTemplate
  metadata:
    name: arm
  spec:
    subnetSelector:
      aws-ids: my-subnets
    tags:
      karpenter.sh/discovery: my-cluster
    launchTemplate: my-template

USER-DATA:

MIME-Version: 1.0
Content-Type: multipart/mixed; boundary="//"

--//
Content-Type: text/x-shellscript; charset="us-ascii"
#!/bin/bash
set -ex
B64_CLUSTER_CA=MY_CERTIFICATE API_SERVER_URL=MY_URL
K8S_CLUSTER_DNS_IP=My_IP
/etc/eks/bootstrap.sh eks-dev --b64-cluster-ca $B64_CLUSTER_CA --apiserver-endpoint $API_SERVER_URL --dns-cluster-ip $K8S_CLUSTER_DNS_IP 

--//--

Resource Specs and Logs

Karpenter Logs (lunching node in 11:27:02.675):

2022-12-22T11:17:38.032Z    DEBUG   Successfully created the logger.
2022-12-22T11:17:38.032Z    DEBUG   Logging level set to: debug
{"level":"info","ts":1671707858.0355446,"logger":"fallback","caller":"injection/injection.go:63","msg":"Starting informers..."}
2022-12-22T11:17:38.135Z    DEBUG   controller  waiting for configmaps  {"commit": "f60dacd", "configmaps": ["karpenter-global-settings"]}
2022-12-22T11:17:38.639Z    DEBUG   controller  karpenter-global-settings config "karpenter-global-settings" config was added or updated: settings.Settings{BatchMaxDuration:v1.Duration{Duration:10000000000}, BatchIdleDuration:v1.Duration{Duration:1000000000}} {"commit": "f60dacd"}
2022-12-22T11:17:38.639Z    DEBUG   controller  karpenter-global-settings config "karpenter-global-settings" config was added or updated: settings.Settings{ClusterName:"eks-dev", ClusterEndpoint:"https://5CB5A2BEA0EC2C64E4CD95AF23947A97.yl4.eu-west-1.eks.amazonaws.com", DefaultInstanceProfile:"Karpenter-eks-dev-20221218174041557300000001", EnablePodENI:false, EnableENILimitedPodDensity:true, IsolatedVPC:false, NodeNameConvention:"ip-name", VMMemoryOverheadPercent:0.075, InterruptionQueueName:"Karpenter-eks-dev", Tags:map[string]string{}} {"commit": "f60dacd"}
2022-12-22T11:17:38.770Z    DEBUG   controller.aws  discovered region   {"commit": "f60dacd", "region": "eu-west-1"}
2022-12-22T11:17:38.777Z    DEBUG   controller.aws  discovered kube dns {"commit": "f60dacd", "kube-dns-ip": "172.20.0.10"}
2022/12/22 11:17:38 Registering 2 clients
2022/12/22 11:17:38 Registering 2 informer factories
2022/12/22 11:17:38 Registering 3 informers
2022/12/22 11:17:38 Registering 6 controllers
2022-12-22T11:17:38.968Z    DEBUG   controller.aws  discovered version  {"commit": "f60dacd", "version": "v0.20.0"}
2022-12-22T11:17:38.970Z    INFO    controller  Starting server {"commit": "f60dacd", "path": "/metrics", "kind": "metrics", "addr": "[::]:8080"}
2022-12-22T11:17:38.970Z    INFO    controller  Starting server {"commit": "f60dacd", "kind": "health probe", "addr": "[::]:8081"}
I1222 11:17:39.071776       1 leaderelection.go:248] attempting to acquire leader lease karpenter/karpenter-leader-election...
2022-12-22T11:17:39.097Z    INFO    controller  Starting informers...   {"commit": "f60dacd"}
2022-12-22T11:17:39.341Z    INFO    controller.aws.pricing  updated spot pricing with instance types and offerings  {"commit": "f60dacd", "instance-type-count": 607, "offering-count": 1680}
2022-12-22T11:17:41.473Z    INFO    controller.aws.pricing  updated on-demand pricing   {"commit": "f60dacd", "instance-type-count": 595}
I1222 11:17:56.062762       1 leaderelection.go:258] successfully acquired lease karpenter/karpenter-leader-election
2022-12-22T11:17:56.062Z    INFO    controller.provisioner  starting controller {"commit": "f60dacd"}
2022-12-22T11:17:56.063Z    INFO    controller.deprovisioning   starting controller {"commit": "f60dacd"}
2022-12-22T11:17:56.063Z    INFO    controller.metricscraper    starting controller {"commit": "f60dacd"}
2022-12-22T11:17:56.063Z    INFO    controller  Starting EventSource    {"commit": "f60dacd", "controller": "node-state", "controllerGroup": "", "controllerKind": "Node", "source": "kind source: *v1.Node"}
2022-12-22T11:17:56.063Z    INFO    controller  Starting Controller {"commit": "f60dacd", "controller": "node-state", "controllerGroup": "", "controllerKind": "Node"}
2022-12-22T11:17:56.064Z    INFO    controller  Starting EventSource    {"commit": "f60dacd", "controller": "provisioning", "controllerGroup": "", "controllerKind": "Pod", "source": "kind source: *v1.Pod"}
2022-12-22T11:17:56.064Z    INFO    controller  Starting Controller {"commit": "f60dacd", "controller": "provisioning", "controllerGroup": "", "controllerKind": "Pod"}
2022-12-22T11:17:56.064Z    INFO    controller  Starting EventSource    {"commit": "f60dacd", "controller": "provisionerstate", "controllerGroup": "karpenter.sh", "controllerKind": "Provisioner", "source": "kind source: *v1alpha5.Provisioner"}
2022-12-22T11:17:56.064Z    INFO    controller  Starting Controller {"commit": "f60dacd", "controller": "provisionerstate", "controllerGroup": "karpenter.sh", "controllerKind": "Provisioner"}
2022-12-22T11:17:56.065Z    INFO    controller  Starting EventSource    {"commit": "f60dacd", "controller": "pod-state", "controllerGroup": "", "controllerKind": "Pod", "source": "kind source: *v1.Pod"}
2022-12-22T11:17:56.065Z    INFO    controller  Starting Controller {"commit": "f60dacd", "controller": "pod-state", "controllerGroup": "", "controllerKind": "Pod"}
2022-12-22T11:17:56.065Z    INFO    controller  Starting EventSource    {"commit": "f60dacd", "controller": "termination", "controllerGroup": "", "controllerKind": "Node", "source": "kind source: *v1.Node"}
2022-12-22T11:17:56.065Z    INFO    controller  Starting Controller {"commit": "f60dacd", "controller": "termination", "controllerGroup": "", "controllerKind": "Node"}
2022-12-22T11:17:56.066Z    INFO    controller  Starting EventSource    {"commit": "f60dacd", "controller": "node", "controllerGroup": "", "controllerKind": "Node", "source": "kind source: *v1.Node"}
2022-12-22T11:17:56.066Z    INFO    controller  Starting EventSource    {"commit": "f60dacd", "controller": "node", "controllerGroup": "", "controllerKind": "Node", "source": "kind source: *v1alpha5.Provisioner"}
2022-12-22T11:17:56.066Z    INFO    controller  Starting EventSource    {"commit": "f60dacd", "controller": "node", "controllerGroup": "", "controllerKind": "Node", "source": "kind source: *v1.Pod"}
2022-12-22T11:17:56.066Z    INFO    controller  Starting EventSource    {"commit": "f60dacd", "controller": "node", "controllerGroup": "", "controllerKind": "Node", "source": "channel source: 0xc000d9ba90"}
2022-12-22T11:17:56.066Z    INFO    controller  Starting Controller {"commit": "f60dacd", "controller": "node", "controllerGroup": "", "controllerKind": "Node"}
2022-12-22T11:17:56.066Z    INFO    controller  Starting EventSource    {"commit": "f60dacd", "controller": "provisionermetrics", "controllerGroup": "karpenter.sh", "controllerKind": "Provisioner", "source": "kind source: *v1alpha5.Provisioner"}
2022-12-22T11:17:56.066Z    INFO    controller  Starting Controller {"commit": "f60dacd", "controller": "provisionermetrics", "controllerGroup": "karpenter.sh", "controllerKind": "Provisioner"}
2022-12-22T11:17:56.066Z    INFO    controller  Starting EventSource    {"commit": "f60dacd", "controller": "podmetrics", "controllerGroup": "", "controllerKind": "Pod", "source": "kind source: *v1.Pod"}
2022-12-22T11:17:56.066Z    INFO    controller  Starting Controller {"commit": "f60dacd", "controller": "podmetrics", "controllerGroup": "", "controllerKind": "Pod"}
2022-12-22T11:17:56.066Z    INFO    controller  Starting EventSource    {"commit": "f60dacd", "controller": "inflightchecks", "controllerGroup": "", "controllerKind": "Node", "source": "kind source: *v1.Node"}
2022-12-22T11:17:56.066Z    INFO    controller  Starting Controller {"commit": "f60dacd", "controller": "inflightchecks", "controllerGroup": "", "controllerKind": "Node"}
2022-12-22T11:17:56.066Z    INFO    controller  Starting EventSource    {"commit": "f60dacd", "controller": "counter", "controllerGroup": "karpenter.sh", "controllerKind": "Provisioner", "source": "kind source: *v1alpha5.Provisioner"}
2022-12-22T11:17:56.067Z    INFO    controller  Starting EventSource    {"commit": "f60dacd", "controller": "counter", "controllerGroup": "karpenter.sh", "controllerKind": "Provisioner", "source": "kind source: *v1.Node"}
2022-12-22T11:17:56.067Z    INFO    controller  Starting Controller {"commit": "f60dacd", "controller": "counter", "controllerGroup": "karpenter.sh", "controllerKind": "Provisioner"}
2022-12-22T11:17:56.067Z    INFO    controller.interruption starting controller {"commit": "f60dacd"}
2022-12-22T11:17:56.067Z    DEBUG   controller.interruption watching interruption queue {"commit": "f60dacd", "queue": "Karpenter-eks-dev"}
2022-12-22T11:17:56.067Z    DEBUG   controller.aws  hydrating the launch template cache {"commit": "f60dacd", "tag-key": "karpenter.k8s.aws/cluster", "tag-value": "eks-dev"}
2022-12-22T11:17:56.117Z    DEBUG   controller.aws  finished hydrating the launch template cache    {"commit": "f60dacd", "tag-key": "karpenter.k8s.aws/cluster", "tag-value": "eks-dev", "item-count": 0}
2022-12-22T11:17:56.165Z    INFO    controller  Starting workers    {"commit": "f60dacd", "controller": "provisioning", "controllerGroup": "", "controllerKind": "Pod", "worker count": 10}
2022-12-22T11:17:56.165Z    INFO    controller  Starting workers    {"commit": "f60dacd", "controller": "pod-state", "controllerGroup": "", "controllerKind": "Pod", "worker count": 10}
2022-12-22T11:17:56.264Z    INFO    controller  Starting workers    {"commit": "f60dacd", "controller": "podmetrics", "controllerGroup": "", "controllerKind": "Pod", "worker count": 1}
2022-12-22T11:17:56.364Z    INFO    controller  Starting workers    {"commit": "f60dacd", "controller": "node-state", "controllerGroup": "", "controllerKind": "Node", "worker count": 10}
2022-12-22T11:17:56.364Z    INFO    controller  Starting workers    {"commit": "f60dacd", "controller": "node", "controllerGroup": "", "controllerKind": "Node", "worker count": 10}
2022-12-22T11:17:56.372Z    INFO    controller  Starting workers    {"commit": "f60dacd", "controller": "termination", "controllerGroup": "", "controllerKind": "Node", "worker count": 10}
2022-12-22T11:17:56.388Z    INFO    controller  Starting workers    {"commit": "f60dacd", "controller": "provisionermetrics", "controllerGroup": "karpenter.sh", "controllerKind": "Provisioner", "worker count": 1}
2022-12-22T11:17:56.397Z    INFO    controller  Starting workers    {"commit": "f60dacd", "controller": "provisionerstate", "controllerGroup": "karpenter.sh", "controllerKind": "Provisioner", "worker count": 10}
2022-12-22T11:17:56.398Z    INFO    controller  Starting workers    {"commit": "f60dacd", "controller": "inflightchecks", "controllerGroup": "", "controllerKind": "Node", "worker count": 10}
2022-12-22T11:17:56.403Z    INFO    controller  Starting workers    {"commit": "f60dacd", "controller": "counter", "controllerGroup": "karpenter.sh", "controllerKind": "Provisioner", "worker count": 10}
2022-12-22T11:17:57.505Z    DEBUG   controller.deprovisioning   discovered EC2 instance types   {"commit": "f60dacd", "instance-type-count": 588}
2022-12-22T11:17:57.578Z    DEBUG   controller.deprovisioning   discovered subnets  {"commit": "f60dacd", "subnets": ["subnet-a59be2fe (eu-west-1a)", "subnet-b26a6bfb (eu-west-1c)", "subnet-803f03e7 (eu-west-1b)"]}
2022-12-22T11:17:57.724Z    DEBUG   controller.deprovisioning   discovered EC2 instance types zonal offerings for subnets   {"commit": "f60dacd", "subnet-selector": "{\"aws-ids\":\"subnet-a59be2fe, subnet-803f03e7, subnet-b26a6bfb\"}"}
2022-12-22T11:17:57.887Z    INFO    controller.inflightchecks   Inflight check failed for node, Expected 20Gi of resource ephemeral-storage, but found 10473452Ki (49.9% of expected)   {"commit": "f60dacd", "node": "ip-10-2-20-144.eu-west-1.compute.internal"}
2022-12-22T11:17:57.908Z    INFO    controller.inflightchecks   Inflight check failed for node, Expected 20Gi of resource ephemeral-storage, but found 10473452Ki (49.9% of expected)   {"commit": "f60dacd", "node": "ip-10-2-25-170.eu-west-1.compute.internal"}
2022-12-22T11:17:58.480Z    DEBUG   controller.deprovisioning   relaxing soft constraints for pod since it previously failed to schedule, removing: spec.affinity.podAffinity.preferredDuringSchedulingIgnoredDuringExecution[0]={"weight":100,"podAffinityTerm":{"labelSelector":{"matchLabels":{"app.kubernetes.io/name":"kube-state-metrics"}},"topologyKey":"kubernetes.io/hostname"}}  {"commit": "f60dacd", "pod": "newrelic/newrelic-bundle-nrk8s-ksm-6b7f676f76-scbs8"}
2022-12-22T11:17:59.034Z    DEBUG   controller.deprovisioning   relaxing soft constraints for pod since it previously failed to schedule, removing: spec.affinity.podAffinity.preferredDuringSchedulingIgnoredDuringExecution[0]={"weight":100,"podAffinityTerm":{"labelSelector":{"matchLabels":{"app.kubernetes.io/name":"kube-state-metrics"}},"topologyKey":"kubernetes.io/hostname"}}  {"commit": "f60dacd", "pod": "newrelic/newrelic-bundle-nrk8s-ksm-6b7f676f76-scbs8"}
2022-12-22T11:18:09.707Z    DEBUG   controller.deprovisioning   relaxing soft constraints for pod since it previously failed to schedule, removing: spec.affinity.podAffinity.preferredDuringSchedulingIgnoredDuringExecution[0]={"weight":100,"podAffinityTerm":{"labelSelector":{"matchLabels":{"app.kubernetes.io/name":"kube-state-metrics"}},"topologyKey":"kubernetes.io/hostname"}}  {"commit": "f60dacd", "pod": "newrelic/newrelic-bundle-nrk8s-ksm-6b7f676f76-scbs8"}
2022-12-22T11:18:10.352Z    DEBUG   controller.deprovisioning   relaxing soft constraints for pod since it previously failed to schedule, removing: spec.affinity.podAffinity.preferredDuringSchedulingIgnoredDuringExecution[0]={"weight":100,"podAffinityTerm":{"labelSelector":{"matchLabels":{"app.kubernetes.io/name":"kube-state-metrics"}},"topologyKey":"kubernetes.io/hostname"}}  {"commit": "f60dacd", "pod": "newrelic/newrelic-bundle-nrk8s-ksm-6b7f676f76-scbs8"}
2022-12-22T11:18:20.951Z    DEBUG   controller.deprovisioning   relaxing soft constraints for pod since it previously failed to schedule, removing: spec.affinity.podAffinity.preferredDuringSchedulingIgnoredDuringExecution[0]={"weight":100,"podAffinityTerm":{"labelSelector":{"matchLabels":{"app.kubernetes.io/name":"kube-state-metrics"}},"topologyKey":"kubernetes.io/hostname"}}  {"commit": "f60dacd", "pod": "newrelic/newrelic-bundle-nrk8s-ksm-6b7f676f76-scbs8"}
2022-12-22T11:18:21.509Z    DEBUG   controller.deprovisioning   relaxing soft constraints for pod since it previously failed to schedule, removing: spec.affinity.podAffinity.preferredDuringSchedulingIgnoredDuringExecution[0]={"weight":100,"podAffinityTerm":{"labelSelector":{"matchLabels":{"app.kubernetes.io/name":"kube-state-metrics"}},"topologyKey":"kubernetes.io/hostname"}}  {"commit": "f60dacd", "pod": "newrelic/newrelic-bundle-nrk8s-ksm-6b7f676f76-scbs8"}
2022-12-22T11:18:32.136Z    DEBUG   controller.deprovisioning   relaxing soft constraints for pod since it previously failed to schedule, removing: spec.affinity.podAffinity.preferredDuringSchedulingIgnoredDuringExecution[0]={"weight":100,"podAffinityTerm":{"labelSelector":{"matchLabels":{"app.kubernetes.io/name":"kube-state-metrics"}},"topologyKey":"kubernetes.io/hostname"}}  {"commit": "f60dacd", "pod": "newrelic/newrelic-bundle-nrk8s-ksm-6b7f676f76-scbs8"}
2022-12-22T11:18:32.671Z    DEBUG   controller.deprovisioning   relaxing soft constraints for pod since it previously failed to schedule, removing: spec.affinity.podAffinity.preferredDuringSchedulingIgnoredDuringExecution[0]={"weight":100,"podAffinityTerm":{"labelSelector":{"matchLabels":{"app.kubernetes.io/name":"kube-state-metrics"}},"topologyKey":"kubernetes.io/hostname"}}  {"commit": "f60dacd", "pod": "newrelic/newrelic-bundle-nrk8s-ksm-6b7f676f76-scbs8"}
2022-12-22T11:18:43.252Z    DEBUG   controller.deprovisioning   relaxing soft constraints for pod since it previously failed to schedule, removing: spec.affinity.podAffinity.preferredDuringSchedulingIgnoredDuringExecution[0]={"weight":100,"podAffinityTerm":{"labelSelector":{"matchLabels":{"app.kubernetes.io/name":"kube-state-metrics"}},"topologyKey":"kubernetes.io/hostname"}}  {"commit": "f60dacd", "pod": "newrelic/newrelic-bundle-nrk8s-ksm-6b7f676f76-scbs8"}
2022-12-22T11:18:43.878Z    DEBUG   controller.deprovisioning   relaxing soft constraints for pod since it previously failed to schedule, removing: spec.affinity.podAffinity.preferredDuringSchedulingIgnoredDuringExecution[0]={"weight":100,"podAffinityTerm":{"labelSelector":{"matchLabels":{"app.kubernetes.io/name":"kube-state-metrics"}},"topologyKey":"kubernetes.io/hostname"}}  {"commit": "f60dacd", "pod": "newrelic/newrelic-bundle-nrk8s-ksm-6b7f676f76-scbs8"}
2022-12-22T11:18:54.436Z    DEBUG   controller.deprovisioning   relaxing soft constraints for pod since it previously failed to schedule, removing: spec.affinity.podAffinity.preferredDuringSchedulingIgnoredDuringExecution[0]={"weight":100,"podAffinityTerm":{"labelSelector":{"matchLabels":{"app.kubernetes.io/name":"kube-state-metrics"}},"topologyKey":"kubernetes.io/hostname"}}  {"commit": "f60dacd", "pod": "newrelic/newrelic-bundle-nrk8s-ksm-6b7f676f76-scbs8"}
2022-12-22T11:18:55.186Z    DEBUG   controller.deprovisioning   relaxing soft constraints for pod since it previously failed to schedule, removing: spec.affinity.podAffinity.preferredDuringSchedulingIgnoredDuringExecution[0]={"weight":100,"podAffinityTerm":{"labelSelector":{"matchLabels":{"app.kubernetes.io/name":"kube-state-metrics"}},"topologyKey":"kubernetes.io/hostname"}}  {"commit": "f60dacd", "pod": "newrelic/newrelic-bundle-nrk8s-ksm-6b7f676f76-scbs8"}
2022-12-22T11:18:56.231Z    INFO    controller.provisioner  found provisionable pod(s)  {"commit": "f60dacd", "pods": 1}
2022-12-22T11:18:56.231Z    INFO    controller.provisioner  computed new node(s) to fit pod(s)  {"commit": "f60dacd", "nodes": 1, "pods": 1}
2022-12-22T11:18:56.234Z    INFO    controller.provisioner  launching node with 1 pods requesting {"cpu":"1325m","memory":"2007081728","pods":"5"} from types c6gn.large, c6g.large, c6gd.large, c7g.large, m6gd.large and 57 other(s)  {"commit": "f60dacd", "provisioner": "arm"}
2022-12-22T11:18:58.366Z    INFO    controller.provisioner.cloudprovider    launched new instance   {"commit": "f60dacd", "provisioner": "arm", "launched-instance": "i-0cab0c7c6e9fa1785", "hostname": "ip-10-2-22-17.eu-west-1.compute.internal", "type": "c6gd.large", "zone": "eu-west-1b", "capacity-type": "spot"}
2022-12-22T11:19:05.820Z    DEBUG   controller.deprovisioning   relaxing soft constraints for pod since it previously failed to schedule, removing: spec.affinity.podAffinity.preferredDuringSchedulingIgnoredDuringExecution[0]={"weight":100,"podAffinityTerm":{"labelSelector":{"matchLabels":{"app.kubernetes.io/name":"kube-state-metrics"}},"topologyKey":"kubernetes.io/hostname"}}  {"commit": "f60dacd", "pod": "newrelic/newrelic-bundle-nrk8s-ksm-6b7f676f76-scbs8"}
2022-12-22T11:19:06.381Z    DEBUG   controller.deprovisioning   relaxing soft constraints for pod since it previously failed to schedule, removing: spec.affinity.podAffinity.preferredDuringSchedulingIgnoredDuringExecution[0]={"weight":100,"podAffinityTerm":{"labelSelector":{"matchLabels":{"app.kubernetes.io/name":"kube-state-metrics"}},"topologyKey":"kubernetes.io/hostname"}}  {"commit": "f60dacd", "pod": "newrelic/newrelic-bundle-nrk8s-ksm-6b7f676f76-scbs8"}
2022-12-22T11:20:30.778Z    DEBUG   controller.deprovisioning   relaxing soft constraints for pod since it previously failed to schedule, removing: spec.affinity.podAffinity.preferredDuringSchedulingIgnoredDuringExecution[0]={"weight":100,"podAffinityTerm":{"labelSelector":{"matchLabels":{"app.kubernetes.io/name":"kube-state-metrics"}},"topologyKey":"kubernetes.io/hostname"}}  {"commit": "f60dacd", "pod": "newrelic/newrelic-bundle-nrk8s-ksm-6b7f676f76-scbs8"}
2022-12-22T11:23:07.864Z    DEBUG   controller.deprovisioning   discovered EC2 instance types   {"commit": "f60dacd", "instance-type-count": 588}
2022-12-22T11:25:35.029Z    DEBUG   controller.deprovisioning   relaxing soft constraints for pod since it previously failed to schedule, removing: spec.affinity.podAffinity.preferredDuringSchedulingIgnoredDuringExecution[0]={"weight":100,"podAffinityTerm":{"labelSelector":{"matchLabels":{"app.kubernetes.io/name":"kube-state-metrics"}},"topologyKey":"kubernetes.io/hostname"}}  {"commit": "f60dacd", "pod": "newrelic/newrelic-bundle-nrk8s-ksm-6b7f676f76-scbs8"}
2022-12-22T11:27:01.221Z    INFO    controller.termination  cordoned node   {"commit": "f60dacd", "node": "ip-10-2-22-17.eu-west-1.compute.internal"}
2022-12-22T11:27:02.666Z    INFO    controller.provisioner  found provisionable pod(s)  {"commit": "f60dacd", "pods": 1}
2022-12-22T11:27:02.666Z    INFO    controller.provisioner  computed new node(s) to fit pod(s)  {"commit": "f60dacd", "nodes": 1, "pods": 1}
2022-12-22T11:27:02.675Z    INFO    controller.provisioner  launching node with 1 pods requesting {"cpu":"1325m","memory":"2007081728","pods":"5"} from types c6gd.large, c6gn.large, c6g.large, c7g.large, m6g.large and 57 other(s)   {"commit": "f60dacd", "provisioner": "arm"}
2022-12-22T11:27:05.271Z    INFO    controller.provisioner.cloudprovider    launched new instance   {"commit": "f60dacd", "provisioner": "arm", "launched-instance": "i-02ed0c4c15274fc20", "hostname": "ip-10-2-23-188.eu-west-1.compute.internal", "type": "c6gd.large", "zone": "eu-west-1b", "capacity-type": "spot"}
2022-12-22T11:27:40.624Z    DEBUG   controller.deprovisioning   relaxing soft constraints for pod since it previously failed to schedule, removing: spec.affinity.podAffinity.preferredDuringSchedulingIgnoredDuringExecution[0]={"weight":100,"podAffinityTerm":{"labelSelector":{"matchLabels":{"app.kubernetes.io/name":"kube-state-metrics"}},"topologyKey":"kubernetes.io/hostname"}}  {"commit": "f60dacd", "pod": "newrelic/newrelic-bundle-nrk8s-ksm-6b7f676f76-scbs8"}
2022-12-22T11:27:41.165Z    DEBUG   controller.deprovisioning   relaxing soft constraints for pod since it previously failed to schedule, removing: spec.affinity.podAffinity.preferredDuringSchedulingIgnoredDuringExecution[0]={"weight":100,"podAffinityTerm":{"labelSelector":{"matchLabels":{"app.kubernetes.io/name":"kube-state-metrics"}},"topologyKey":"kubernetes.io/hostname"}}  {"commit": "f60dacd", "pod": "newrelic/newrelic-bundle-nrk8s-ksm-6b7f676f76-scbs8"}
2022-12-22T11:27:43.497Z    INFO    controller.termination  deleted node    {"commit": "f60dacd", "node": "ip-10-2-22-17.eu-west-1.compute.internal"}
2022-12-22T11:27:51.946Z    DEBUG   controller.deprovisioning   relaxing soft constraints for pod since it previously failed to schedule, removing: spec.affinity.podAffinity.preferredDuringSchedulingIgnoredDuringExecution[0]={"weight":100,"podAffinityTerm":{"labelSelector":{"matchLabels":{"app.kubernetes.io/name":"kube-state-metrics"}},"topologyKey":"kubernetes.io/hostname"}}  {"commit": "f60dacd", "pod": "newrelic/newrelic-bundle-nrk8s-ksm-6b7f676f76-scbs8"}
2022-12-22T11:27:52.514Z    DEBUG   controller.deprovisioning   relaxing soft constraints for pod since it previously failed to schedule, removing: spec.affinity.podAffinity.preferredDuringSchedulingIgnoredDuringExecution[0]={"weight":100,"podAffinityTerm":{"labelSelector":{"matchLabels":{"app.kubernetes.io/name":"kube-state-metrics"}},"topologyKey":"kubernetes.io/hostname"}}  {"commit": "f60dacd", "pod": "newrelic/newrelic-bundle-nrk8s-ksm-6b7f676f76-scbs8"}
2022-12-22T11:27:56.457Z    INFO    controller.inflightchecks   Inflight check failed for node, Expected 20Gi of resource ephemeral-storage, but found 10473452Ki (49.9% of expected)   {"commit": "f60dacd", "node": "ip-10-2-20-144.eu-west-1.compute.internal"}
2022-12-22T11:27:56.543Z    INFO    controller.inflightchecks   Inflight check failed for node, Expected 20Gi of resource ephemeral-storage, but found 10473452Ki (49.9% of expected)   {"commit": "f60dacd", "node": "ip-10-2-25-170.eu-west-1.compute.internal"}
2022-12-22T11:28:03.206Z    DEBUG   controller.deprovisioning   relaxing soft constraints for pod since it previously failed to schedule, removing: spec.affinity.podAffinity.preferredDuringSchedulingIgnoredDuringExecution[0]={"weight":100,"podAffinityTerm":{"labelSelector":{"matchLabels":{"app.kubernetes.io/name":"kube-state-metrics"}},"topologyKey":"kubernetes.io/hostname"}}  {"commit": "f60dacd", "pod": "newrelic/newrelic-bundle-nrk8s-ksm-6b7f676f76-scbs8"}
2022-12-22T11:28:03.853Z    DEBUG   controller.deprovisioning   relaxing soft constraints for pod since it previously failed to schedule, removing: spec.affinity.podAffinity.preferredDuringSchedulingIgnoredDuringExecution[0]={"weight":100,"podAffinityTerm":{"labelSelector":{"matchLabels":{"app.kubernetes.io/name":"kube-state-metrics"}},"topologyKey":"kubernetes.io/hostname"}}  {"commit": "f60dacd", "pod": "newrelic/newrelic-bundle-nrk8s-ksm-6b7f676f76-scbs8"}
2022-12-22T11:28:15.116Z    DEBUG   controller.deprovisioning   discovered EC2 instance types   {"commit": "f60dacd", "instance-type-count": 588}
2022-12-22T11:28:27.169Z    DEBUG   controller.deprovisioning   relaxing soft constraints for pod since it previously failed to schedule, removing: spec.affinity.podAffinity.preferredDuringSchedulingIgnoredDuringExecution[0]={"weight":100,"podAffinityTerm":{"labelSelector":{"matchLabels":{"app.kubernetes.io/name":"kube-state-metrics"}},"topologyKey":"kubernetes.io/hostname"}}  {"commit": "f60dacd", "pod": "newrelic/newrelic-bundle-nrk8s-ksm-6b7f676f76-scbs8"}
2022-12-22T11:28:38.839Z    DEBUG   controller.deprovisioning   relaxing soft constraints for pod since it previously failed to schedule, removing: spec.affinity.podAffinity.preferredDuringSchedulingIgnoredDuringExecution[0]={"weight":100,"podAffinityTerm":{"labelSelector":{"matchLabels":{"app.kubernetes.io/name":"kube-state-metrics"}},"topologyKey":"kubernetes.io/hostname"}}  {"commit": "f60dacd", "pod": "newrelic/newrelic-bundle-nrk8s-ksm-6b7f676f76-scbs8"}
2022-12-22T11:29:00.634Z    DEBUG   controller.deprovisioning   relaxing soft constraints for pod since it previously failed to schedule, removing: spec.affinity.podAffinity.preferredDuringSchedulingIgnoredDuringExecution[0]={"weight":100,"podAffinityTerm":{"labelSelector":{"matchLabels":{"app.kubernetes.io/name":"kube-state-metrics"}},"topologyKey":"kubernetes.io/hostname"}}  {"commit": "f60dacd", "pod": "newrelic/newrelic-bundle-nrk8s-ksm-6b7f676f76-scbs8"}

kube-proxy:

I1222 11:27:58.975278       1 flags.go:64] FLAG: --add-dir-header="false"
I1222 11:27:58.975342       1 flags.go:64] FLAG: --alsologtostderr="false"
I1222 11:27:58.975351       1 flags.go:64] FLAG: --bind-address="0.0.0.0"
I1222 11:27:58.975356       1 flags.go:64] FLAG: --bind-address-hard-fail="false"
I1222 11:27:58.975361       1 flags.go:64] FLAG: --boot-id-file="/proc/sys/kernel/random/boot_id"
I1222 11:27:58.975365       1 flags.go:64] FLAG: --cleanup="false"
I1222 11:27:58.975368       1 flags.go:64] FLAG: --cluster-cidr=""
I1222 11:27:58.975372       1 flags.go:64] FLAG: --config="/var/lib/kube-proxy-config/config"
I1222 11:27:58.975376       1 flags.go:64] FLAG: --config-sync-period="15m0s"
I1222 11:27:58.975384       1 flags.go:64] FLAG: --conntrack-max-per-core="32768"
I1222 11:27:58.975389       1 flags.go:64] FLAG: --conntrack-min="131072"
I1222 11:27:58.975393       1 flags.go:64] FLAG: --conntrack-tcp-timeout-close-wait="1h0m0s"
I1222 11:27:58.975396       1 flags.go:64] FLAG: --conntrack-tcp-timeout-established="24h0m0s"
I1222 11:27:58.975399       1 flags.go:64] FLAG: --detect-local-mode=""
I1222 11:27:58.975403       1 flags.go:64] FLAG: --feature-gates=""
I1222 11:27:58.975415       1 flags.go:64] FLAG: --healthz-bind-address="0.0.0.0:10256"
I1222 11:27:58.975420       1 flags.go:64] FLAG: --healthz-port="10256"
I1222 11:27:58.975423       1 flags.go:64] FLAG: --help="false"
I1222 11:27:58.975426       1 flags.go:64] FLAG: --hostname-override=""
I1222 11:27:58.975429       1 flags.go:64] FLAG: --iptables-masquerade-bit="14"
I1222 11:27:58.975432       1 flags.go:64] FLAG: --iptables-min-sync-period="1s"
I1222 11:27:58.975435       1 flags.go:64] FLAG: --iptables-sync-period="30s"
I1222 11:27:58.975442       1 flags.go:64] FLAG: --ipvs-exclude-cidrs="[]"
I1222 11:27:58.975448       1 flags.go:64] FLAG: --ipvs-min-sync-period="0s"
I1222 11:27:58.975451       1 flags.go:64] FLAG: --ipvs-scheduler=""
I1222 11:27:58.975455       1 flags.go:64] FLAG: --ipvs-strict-arp="false"
I1222 11:27:58.975458       1 flags.go:64] FLAG: --ipvs-sync-period="30s"
I1222 11:27:58.975464       1 flags.go:64] FLAG: --ipvs-tcp-timeout="0s"
I1222 11:27:58.975467       1 flags.go:64] FLAG: --ipvs-tcpfin-timeout="0s"
I1222 11:27:58.975470       1 flags.go:64] FLAG: --ipvs-udp-timeout="0s"
I1222 11:27:58.975476       1 flags.go:64] FLAG: --kube-api-burst="10"
I1222 11:27:58.975479       1 flags.go:64] FLAG: --kube-api-content-type="application/vnd.kubernetes.protobuf"
I1222 11:27:58.975483       1 flags.go:64] FLAG: --kube-api-qps="5"
I1222 11:27:58.975488       1 flags.go:64] FLAG: --kubeconfig=""
I1222 11:27:58.975491       1 flags.go:64] FLAG: --log-backtrace-at=":0"
I1222 11:27:58.975496       1 flags.go:64] FLAG: --log-dir=""
I1222 11:27:58.975502       1 flags.go:64] FLAG: --log-file=""
I1222 11:27:58.975505       1 flags.go:64] FLAG: --log-file-max-size="1800"
I1222 11:27:58.975509       1 flags.go:64] FLAG: --log-flush-frequency="5s"
I1222 11:27:58.975512       1 flags.go:64] FLAG: --logtostderr="true"
I1222 11:27:58.975515       1 flags.go:64] FLAG: --machine-id-file="/etc/machine-id,/var/lib/dbus/machine-id"
I1222 11:27:58.975519       1 flags.go:64] FLAG: --masquerade-all="false"
I1222 11:27:58.975522       1 flags.go:64] FLAG: --master=""
I1222 11:27:58.975527       1 flags.go:64] FLAG: --metrics-bind-address="127.0.0.1:10249"
I1222 11:27:58.975531       1 flags.go:64] FLAG: --metrics-port="10249"
I1222 11:27:58.975534       1 flags.go:64] FLAG: --nodeport-addresses="[]"
I1222 11:27:58.975543       1 flags.go:64] FLAG: --one-output="false"
I1222 11:27:58.975546       1 flags.go:64] FLAG: --oom-score-adj="-999"
I1222 11:27:58.975549       1 flags.go:64] FLAG: --profiling="false"
I1222 11:27:58.975553       1 flags.go:64] FLAG: --proxy-mode=""
I1222 11:27:58.975560       1 flags.go:64] FLAG: --proxy-port-range=""
I1222 11:27:58.975564       1 flags.go:64] FLAG: --show-hidden-metrics-for-version=""
I1222 11:27:58.975567       1 flags.go:64] FLAG: --skip-headers="false"
I1222 11:27:58.975570       1 flags.go:64] FLAG: --skip-log-headers="false"
I1222 11:27:58.975573       1 flags.go:64] FLAG: --stderrthreshold="2"
I1222 11:27:58.975576       1 flags.go:64] FLAG: --udp-timeout="250ms"
I1222 11:27:58.975580       1 flags.go:64] FLAG: --v="2"
I1222 11:27:58.975583       1 flags.go:64] FLAG: --version="false"
I1222 11:27:58.975591       1 flags.go:64] FLAG: --vmodule=""
I1222 11:27:58.975594       1 flags.go:64] FLAG: --write-config-to=""
I1222 11:27:58.976964       1 server.go:436] "Using lenient decoding as strict decoding failed" err="strict decoding error: unknown field \"max\", unknown field \"resourceContainer\""
I1222 11:27:58.977108       1 feature_gate.go:245] feature gates: &{map[]}
I1222 11:27:58.977190       1 feature_gate.go:245] feature gates: &{map[]}
I1222 11:27:59.013551       1 node.go:163] Successfully retrieved node IP: 10.2.23.188
I1222 11:27:59.013587       1 server_others.go:138] "Detected node IP" address="10.2.23.188"
I1222 11:27:59.013793       1 server_others.go:175] "DetectLocalMode" LocalMode="ClusterCIDR"
I1222 11:27:59.017211       1 server_others.go:206] "Using iptables Proxier"
I1222 11:27:59.017239       1 server_others.go:213] "kube-proxy running in dual-stack mode" ipFamily=IPv4
I1222 11:27:59.017250       1 server_others.go:214] "Creating dualStackProxier for iptables"
I1222 11:27:59.017257       1 server_others.go:475] "Detect-local-mode set to ClusterCIDR, but no cluster CIDR defined"
I1222 11:27:59.017270       1 server_others.go:524] "Defaulting to no-op detect-local" detect-local-mode="ClusterCIDR"
I1222 11:27:59.017332       1 utils.go:400] "Changed sysctl" name="net/ipv4/conf/all/route_localnet" before=0 after=1
I1222 11:27:59.017364       1 proxier.go:280] "Using iptables mark for masquerade" ipFamily=IPv4 mark="0x00004000"
I1222 11:27:59.017388       1 proxier.go:324] "Iptables sync params" ipFamily=IPv4 minSyncPeriod="1s" syncPeriod="30s" burstSyncs=2
I1222 11:27:59.017410       1 proxier.go:334] "Iptables supports --random-fully" ipFamily=IPv4
I1222 11:27:59.017436       1 proxier.go:280] "Using iptables mark for masquerade" ipFamily=IPv6 mark="0x00004000"
I1222 11:27:59.017451       1 proxier.go:324] "Iptables sync params" ipFamily=IPv6 minSyncPeriod="1s" syncPeriod="30s" burstSyncs=2
I1222 11:27:59.017462       1 proxier.go:334] "Iptables supports --random-fully" ipFamily=IPv6
I1222 11:27:59.017624       1 server.go:656] "Version info" version="v1.23.7-eks-fba872d"
I1222 11:27:59.018130       1 sysinfo.go:232] Found node without cache information, nodeDir: /sys/devices/system/node/node0
I1222 11:27:59.018341       1 conntrack.go:100] "Set sysctl" entry="net/netfilter/nf_conntrack_max" value=131072
I1222 11:27:59.018409       1 conntrack.go:52] "Setting nf_conntrack_max" nf_conntrack_max=131072
I1222 11:27:59.018570       1 mount_linux.go:208] Detected OS without systemd
I1222 11:27:59.018809       1 conntrack.go:83] "Setting conntrack hashsize" conntrack hashsize=32768
I1222 11:27:59.031804       1 conntrack.go:100] "Set sysctl" entry="net/netfilter/nf_conntrack_tcp_timeout_close_wait" value=3600
I1222 11:27:59.031981       1 config.go:226] "Starting endpoint slice config controller"
I1222 11:27:59.032061       1 shared_informer.go:240] Waiting for caches to sync for endpoint slice config
I1222 11:27:59.032147       1 config.go:317] "Starting service config controller"
I1222 11:27:59.032216       1 shared_informer.go:240] Waiting for caches to sync for service config
I1222 11:27:59.034421       1 service.go:304] "Service updated ports" service="applications/k8s-message-hub" portCount=1
I1222 11:27:59.034454       1 service.go:304] "Service updated ports" service="applications/kafka" portCount=1
I1222 11:27:59.034470       1 service.go:304] "Service updated ports" service="default/kubernetes" portCount=1
I1222 11:27:59.034484       1 service.go:304] "Service updated ports" service="fargate/practicom" portCount=1
I1222 11:27:59.034500       1 service.go:304] "Service updated ports" service="kube-system/kubernetes-dashboard" portCount=1
I1222 11:27:59.034526       1 service.go:304] "Service updated ports" service="kubernetes-dashboard/kubernetes-dashboard" portCount=1
I1222 11:27:59.034546       1 service.go:304] "Service updated ports" service="newrelic/newrelic-bundle-kube-state-metrics" portCount=1
I1222 11:27:59.034562       1 service.go:304] "Service updated ports" service="applications/sample-2" portCount=1
I1222 11:27:59.034575       1 service.go:304] "Service updated ports" service="fargate/optima" portCount=1
I1222 11:27:59.034605       1 service.go:304] "Service updated ports" service="fargate/redis-load-tester" portCount=1
I1222 11:27:59.034620       1 service.go:304] "Service updated ports" service="kube-system/cluster-autoscaler-aws-cluster-autoscaler" portCount=1
I1222 11:27:59.034634       1 service.go:304] "Service updated ports" service="kubernetes-dashboard/dashboard-metrics-scraper" portCount=1
I1222 11:27:59.034646       1 service.go:304] "Service updated ports" service="applications/sync-worker" portCount=1
I1222 11:27:59.034666       1 service.go:304] "Service updated ports" service="karpenter/karpenter" portCount=2
I1222 11:27:59.034688       1 service.go:304] "Service updated ports" service="kube-system/aws-load-balancer-webhook-service" portCount=1
I1222 11:27:59.034702       1 service.go:304] "Service updated ports" service="newrelic/newrelic-bundle-nri-metadata-injection" portCount=1
I1222 11:27:59.034715       1 service.go:304] "Service updated ports" service="fargate/fg-tabitorder" portCount=1
I1222 11:27:59.034728       1 service.go:304] "Service updated ports" service="fargate/optima-reports" portCount=1
I1222 11:27:59.034741       1 service.go:304] "Service updated ports" service="fargate/rosworker-fargate" portCount=1
I1222 11:27:59.034755       1 service.go:304] "Service updated ports" service="kube-system/heapster" portCount=1
I1222 11:27:59.034767       1 service.go:304] "Service updated ports" service="applications/k8-logzp" portCount=1
I1222 11:27:59.034785       1 service.go:304] "Service updated ports" service="applications/k8-shift-celery" portCount=1
I1222 11:27:59.034806       1 service.go:304] "Service updated ports" service="applications/k8-shift" portCount=1
I1222 11:27:59.034821       1 service.go:304] "Service updated ports" service="kube-system/monitoring-influxdb" portCount=1
I1222 11:27:59.034834       1 service.go:304] "Service updated ports" service="observability/simple-prod-query" portCount=1
I1222 11:27:59.034854       1 service.go:304] "Service updated ports" service="applications/sample" portCount=1
I1222 11:27:59.034880       1 service.go:304] "Service updated ports" service="kube-system/kube-dns" portCount=2
I1222 11:27:59.034894       1 service.go:304] "Service updated ports" service="kube-system/metrics-server" portCount=1
I1222 11:27:59.034920       1 service.go:304] "Service updated ports" service="observability/simple-prod-collector" portCount=4
I1222 11:27:59.034933       1 service.go:304] "Service updated ports" service="applications/k8-internus" portCount=1
I1222 11:27:59.034946       1 service.go:304] "Service updated ports" service="applications/k8-street-map" portCount=1
I1222 11:27:59.034965       1 service.go:304] "Service updated ports" service="applications/rosapi-dev" portCount=1
I1222 11:27:59.034978       1 service.go:304] "Service updated ports" service="fargate/sample" portCount=1
I1222 11:27:59.133127       1 shared_informer.go:247] Caches are synced for endpoint slice config 
I1222 11:27:59.133196       1 proxier.go:782] "Not syncing iptables until Services and Endpoints have been received from master"
I1222 11:27:59.133126       1 shared_informer.go:247] Caches are synced for service config 
I1222 11:27:59.133263       1 proxier.go:782] "Not syncing iptables until Services and Endpoints have been received from master"
I1222 11:27:59.133292       1 service.go:419] "Adding new service port" portName="kube-system/heapster" servicePort="172.20.202.128:80/TCP"
I1222 11:27:59.133310       1 service.go:419] "Adding new service port" portName="kubernetes-dashboard/kubernetes-dashboard" servicePort="172.20.221.116:443/TCP"
I1222 11:27:59.133323       1 service.go:419] "Adding new service port" portName="newrelic/newrelic-bundle-kube-state-metrics:http" servicePort="172.20.73.16:8080/TCP"
I1222 11:27:59.133335       1 service.go:419] "Adding new service port" portName="fargate/optima-reports:app" servicePort="172.20.141.112:80/TCP"
I1222 11:27:59.133353       1 service.go:419] "Adding new service port" portName="kube-system/kube-dns:dns" servicePort="172.20.0.10:53/UDP"
I1222 11:27:59.133364       1 service.go:419] "Adding new service port" portName="kube-system/kube-dns:dns-tcp" servicePort="172.20.0.10:53/TCP"
I1222 11:27:59.133374       1 service.go:419] "Adding new service port" portName="kube-system/metrics-server:https" servicePort="172.20.145.196:443/TCP"
I1222 11:27:59.133385       1 service.go:419] "Adding new service port" portName="applications/k8-street-map:app" servicePort="172.20.18.129:80/TCP"
I1222 11:27:59.133397       1 service.go:419] "Adding new service port" portName="default/kubernetes:https" servicePort="172.20.0.1:443/TCP"
I1222 11:27:59.133412       1 service.go:419] "Adding new service port" portName="applications/k8-logzp:app" servicePort="172.20.75.85:80/TCP"
I1222 11:27:59.133423       1 service.go:419] "Adding new service port" portName="applications/k8-internus:app" servicePort="172.20.9.226:80/TCP"
I1222 11:27:59.133433       1 service.go:419] "Adding new service port" portName="fargate/sample:app" servicePort="172.20.147.63:80/TCP"
I1222 11:27:59.133444       1 service.go:419] "Adding new service port" portName="kube-system/kubernetes-dashboard" servicePort="172.20.47.78:443/TCP"
I1222 11:27:59.133456       1 service.go:419] "Adding new service port" portName="kube-system/monitoring-influxdb" servicePort="172.20.91.146:8086/TCP"
I1222 11:27:59.133470       1 service.go:419] "Adding new service port" portName="observability/simple-prod-query:query" servicePort="172.20.7.165:16686/TCP"
I1222 11:27:59.133482       1 service.go:419] "Adding new service port" portName="observability/simple-prod-collector:c-binary-trft" servicePort="172.20.57.110:14268/TCP"
I1222 11:27:59.133495       1 service.go:419] "Adding new service port" portName="observability/simple-prod-collector:zipkin" servicePort="172.20.57.110:9411/TCP"
I1222 11:27:59.133505       1 service.go:419] "Adding new service port" portName="observability/simple-prod-collector:grpc" servicePort="172.20.57.110:14250/TCP"
I1222 11:27:59.133515       1 service.go:419] "Adding new service port" portName="observability/simple-prod-collector:c-tchan-trft" servicePort="172.20.57.110:14267/TCP"
I1222 11:27:59.133526       1 service.go:419] "Adding new service port" portName="applications/k8s-message-hub:app" servicePort="172.20.42.160:80/TCP"
I1222 11:27:59.133538       1 service.go:419] "Adding new service port" portName="karpenter/karpenter:http-metrics" servicePort="172.20.114.42:8080/TCP"
I1222 11:27:59.133549       1 service.go:419] "Adding new service port" portName="karpenter/karpenter:https-webhook" servicePort="172.20.114.42:443/TCP"
I1222 11:27:59.133562       1 service.go:419] "Adding new service port" portName="kube-system/aws-load-balancer-webhook-service:webhook-server" servicePort="172.20.189.40:443/TCP"
I1222 11:27:59.133572       1 service.go:419] "Adding new service port" portName="applications/k8-shift-celery:app" servicePort="172.20.23.55:80/TCP"
I1222 11:27:59.133585       1 service.go:419] "Adding new service port" portName="applications/k8-shift:app" servicePort="172.20.5.123:80/TCP"
I1222 11:27:59.133597       1 service.go:419] "Adding new service port" portName="applications/rosapi-dev:app" servicePort="172.20.129.208:80/TCP"
I1222 11:27:59.133610       1 service.go:419] "Adding new service port" portName="applications/kafka:app" servicePort="172.20.252.248:80/TCP"
I1222 11:27:59.133624       1 service.go:419] "Adding new service port" portName="applications/sample-2:app" servicePort="172.20.113.108:80/TCP"
I1222 11:27:59.133637       1 service.go:419] "Adding new service port" portName="fargate/optima:app" servicePort="172.20.21.153:80/TCP"
I1222 11:27:59.133652       1 service.go:419] "Adding new service port" portName="fargate/redis-load-tester:app" servicePort="172.20.198.23:80/TCP"
I1222 11:27:59.133663       1 service.go:419] "Adding new service port" portName="kubernetes-dashboard/dashboard-metrics-scraper" servicePort="172.20.93.243:8000/TCP"
I1222 11:27:59.133675       1 service.go:419] "Adding new service port" portName="applications/sync-worker:app" servicePort="172.20.224.148:80/TCP"
I1222 11:27:59.133686       1 service.go:419] "Adding new service port" portName="newrelic/newrelic-bundle-nri-metadata-injection" servicePort="172.20.43.160:443/TCP"
I1222 11:27:59.133696       1 service.go:419] "Adding new service port" portName="fargate/practicom:app" servicePort="172.20.83.31:80/TCP"
I1222 11:27:59.133707       1 service.go:419] "Adding new service port" portName="fargate/rosworker-fargate:app" servicePort="172.20.88.100:80/TCP"
I1222 11:27:59.133718       1 service.go:419] "Adding new service port" portName="fargate/fg-tabitorder:app" servicePort="172.20.74.83:80/TCP"
I1222 11:27:59.133729       1 service.go:419] "Adding new service port" portName="applications/sample:app" servicePort="172.20.216.207:80/TCP"
I1222 11:27:59.133754       1 service.go:419] "Adding new service port" portName="kube-system/cluster-autoscaler-aws-cluster-autoscaler:http" servicePort="172.20.70.233:8085/TCP"
I1222 11:27:59.134016       1 proxier.go:807] "Stale service" protocol="udp" servicePortName="kube-system/kube-dns:dns" clusterIP="172.20.0.10"
I1222 11:27:59.134023       1 proxier.go:823] "Syncing iptables rules"
I1222 11:27:59.186084       1 proxier.go:790] "SyncProxyRules complete" elapsed="52.832323ms"
I1222 11:27:59.186107       1 proxier.go:823] "Syncing iptables rules"
I1222 11:27:59.213728       1 proxier.go:790] "SyncProxyRules complete" elapsed="27.604593ms"
I1222 11:29:20.182334       1 proxier.go:823] "Syncing iptables rules"
I1222 11:29:20.241245       1 proxier.go:790] "SyncProxyRules complete" elapsed="69.137817ms"
I1222 11:29:47.107778       1 proxier.go:823] "Syncing iptables rules"
I1222 11:29:47.134222       1 proxier.go:790] "SyncProxyRules complete" elapsed="26.489282ms"
{"level":"info","ts":"2022-12-22T11:28:20.326Z","caller":"entrypoint.sh","msg":"Validating env variables ..."}
{"level":"info","ts":"2022-12-22T11:28:20.327Z","caller":"entrypoint.sh","msg":"Install CNI binaries.."}
{"level":"info","ts":"2022-12-22T11:28:20.338Z","caller":"entrypoint.sh","msg":"Starting IPAM daemon in the background ... "}
{"level":"info","ts":"2022-12-22T11:28:20.339Z","caller":"entrypoint.sh","msg":"Checking for IPAM connectivity ... "}
{"level":"info","ts":"2022-12-22T11:28:21.344Z","caller":"entrypoint.sh","msg":"Retrying waiting for IPAM-D"}
{"level":"info","ts":"2022-12-22T11:28:22.349Z","caller":"entrypoint.sh","msg":"Retrying waiting for IPAM-D"}
{"level":"info","ts":"2022-12-22T11:28:22.365Z","caller":"entrypoint.sh","msg":"Copying config file ... "}
{"level":"info","ts":"2022-12-22T11:28:22.369Z","caller":"entrypoint.sh","msg":"Successfully copied CNI plugin binary and config file."}
{"level":"info","ts":"2022-12-22T11:28:22.370Z","caller":"entrypoint.sh","msg":"Foregrounding IPAM daemon ..."}

Community Note

royb-tabit commented 1 year ago

EC2 logs:

ec2 logs:

 0000D4 (v02 AMAZON AMZNPPTT 00000001 AMZN 00000001)
[    0.000000] ACPI: SPCR: console: uart,mmio,0x90a0000,115200
[    0.000000] ACPI: NUMA: Failed to initialise from firmware
[    0.000000] NUMA: Faking a node at [mem 0x0000000040000000-0x00000004b9ffffff]
[    0.000000] NUMA: NODE_DATA [mem 0x4b982a800-0x4b982bfff]
[    0.000000] Zone ranges:
[    0.000000]   DMA32    [mem 0x0000000040000000-0x00000000ffffffff]
[    0.000000]   Normal   [mem 0x0000000100000000-0x00000004b9ffffff]
[    0.000000] Movable zone start for each node
[    0.000000] Early memory node ranges
[    0.000000]   node   0: [mem 0x0000000040000000-0x00000000786effff]
[    0.000000]   node   0: [mem 0x00000000786f0000-0x000000007872ffff]
[    0.000000]   node   0: [mem 0x0000000078730000-0x000000007bbfffff]
[    0.000000]   node   0: [mem 0x000000007bc00000-0x000000007bfdffff]
[    0.000000]   node   0: [mem 0x000000007bfe0000-0x000000007fffffff]
[    0.000000]   node   0: [mem 0x0000000400000000-0x00000004b9ffffff]
[    0.000000] Zeroed struct page in unavailable ranges: 64 pages
[    0.000000] Initmem setup node 0 [mem 0x0000000040000000-0x00000004b9ffffff]
[    0.000000] psci: probing for conduit method from ACPI.
[    0.000000] psci: PSCIv1.0 detected in firmware.
[    0.000000] psci: Using standard PSCI v0.2 function IDs
[    0.000000] psci: Trusted OS migration not required
[    0.000000] psci: SMC Calling Convention v1.1
[    0.000000] ACPI: SRAT not present
[    0.000000] percpu: Embedded 32 pages/cpu s93144 r8192 d29736 u131072
[    0.000000] Detected PIPT I-cache on CPU0
[    0.000000] CPU features: detected: GIC system register CPU interface
[    0.000000] CPU features: detected: Hardware dirty bit management
[    0.000000] CPU features: detected: Speculative Store Bypassing Safe (SSBS)
[    0.000000] CPU features: detected: ARM erratum 1418040
[    0.000000] CPU features: detected: ARM erratum 1542419 (kernel portion)
[    0.000000] CPU features: detected: Spectre-BHB
[    0.000000] Fallback order for Node 0: 0 
[    0.000000] Built 1 zonelists, mobility grouping on.  Total pages: 1008000
[    0.000000] Policy zone: Normal
[    0.000000] Kernel command line: BOOT_IMAGE=/boot/vmlinuz-5.4.219-126.411.amzn2.aarch64 root=UUID=8e2e8eec-62db-4f3c-98c9-cac9f4c74f58 ro console=tty0 console=ttyS0,115200n8 net.ifnames=0 biosdevname=0 nvme_core.io_timeout=4294967295 rd.emergency=poweroff rd.shell=0 LANG=en_US.UTF-8 KEYTABLE=us
[    0.000000] Dentry cache hash table entries: 524288 (order: 10, 4194304 bytes, linear)
[    0.000000] Inode-cache hash table entries: 262144 (order: 9, 2097152 bytes, linear)
[    0.000000] mem auto-init: stack:off, heap alloc:off, heap free:off
[    0.000000] software IO TLB: mapped [mem 0x71d20000-0x75d20000] (64MB)
[    0.000000] Memory: 3838764K/4096000K available (11964K kernel code, 1806K rwdata, 7316K rodata, 1408K init, 8800K bss, 191700K reserved, 65536K cma-reserved)
[    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=2, Nodes=1
[    0.000000] ftrace: allocating 37352 entries in 146 pages
[    0.000000] rcu: Hierarchical RCU implementation.
[    0.000000] rcu:     RCU restricting CPUs from NR_CPUS=4096 to nr_cpu_ids=2.
[    0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 10 jiffies.
[    0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=2
[    0.000000] NR_IRQS: 64, nr_irqs: 64, preallocated irqs: 0
[    0.000000] GICv3: 96 SPIs implemented
[    0.000000] GICv3: 0 Extended SPIs implemented
[    0.000000] GICv3: Distributor has no Range Selector support
[    0.000000] GICv3: 16 PPIs implemented
[    0.000000] GICv3: no VLPI support, no direct LPI support
[    0.000000] GICv3: CPU0: found redistributor 0 region 0:0x0000000010200000
[    0.000000] ACPI: SRAT not present
[    0.000000] ITS [mem 0x10080000-0x1009ffff]
[    0.000000] ITS@0x0000000010080000: allocated 8192 Devices @4b4d50000 (indirect, esz 8, psz 64K, shr 1)
[    0.000000] ITS@0x0000000010080000: allocated 8192 Interrupt Collections @4b4d60000 (flat, esz 8, psz 64K, shr 1)
[    0.000000] GICv3: using LPI property table @0x00000004b4d70000
[    0.000000] ITS: Using hypervisor restricted LPI range [128]
[    0.000000] GICv3: CPU0: using allocated LPI pending table @0x00000004b4d80000
[    0.000000] rcu:     Offload RCU callbacks from CPUs: (none).
[    0.000000] arch_timer: Enabling local workaround for ARM erratum 1418040
[    0.000000] arch_timer: cp15 timer(s) running at 121.87MHz (virt).
[    0.000000] clocksource: arch_sys_counter: mask: 0xffffffffffffff max_cycles: 0x383759f8ff, max_idle_ns: 881590415659 ns
[    0.000001] sched_clock: 56 bits at 121MHz, resolution 8ns, wraps every 4398046511103ns
[    0.000034] Console: colour dummy device 80x25
[    0.000148] printk: console [tty0] enabled
[    0.000164] ACPI: Core revision 20190816
[    0.000206] Calibrating delay loop (skipped), value calculated using timer frequency.. 243.75 BogoMIPS (lpj=1218750)
[    0.000211] pid_max: default: 32768 minimum: 301
[    0.000227] LSM: Security Framework initializing
[    0.000233] Yama: becoming mindful.
[    0.000238] SELinux:  Initializing.
[    0.000247] *** VALIDATE SELinux ***
[    0.000276] Mount-cache hash table entries: 8192 (order: 4, 65536 bytes, linear)
[    0.000281] Mountpoint-cache hash table entries: 8192 (order: 4, 65536 bytes, linear)
[    0.000293] *** VALIDATE tmpfs ***
[    0.000405] *** VALIDATE proc ***
[    0.000450] *** VALIDATE cgroup1 ***
[    0.000452] *** VALIDATE cgroup2 ***
[    0.000607] ASID allocator initialised with 32768 entries
[    0.000622] rcu: Hierarchical SRCU implementation.
[    0.000871] Platform MSI: ITS@0x10080000 domain created
[    0.000876] PCI/MSI: ITS@0x10080000 domain created
[    0.000880] Remapping and enabling EFI services.
[    0.001014] smp: Bringing up secondary CPUs ...
[    0.001160] Detected PIPT I-cache on CPU1
[    0.001174] GICv3: CPU1: found redistributor 1 region 0:0x0000000010220000
[    0.001218] GICv3: CPU1: using allocated LPI pending table @0x00000004b4d90000
[    0.001235] arch_timer: Enabling local workaround for ARM erratum 1418040
[    0.001245] CPU1: Booted secondary processor 0x0000000001 [0x413fd0c1]
[    0.001286] smp: Brought up 1 node, 2 CPUs
[    0.001295] SMP: Total of 2 processors activated.
[    0.001297] CPU features: detected: Privileged Access Never
[    0.001299] CPU features: detected: LSE atomic instructions
[    0.001301] CPU features: detected: User Access Override
[    0.001303] CPU features: detected: 32-bit EL0 Support
[    0.001304] CPU features: detected: Common not Private translations
[    0.001306] CPU features: detected: RAS Extension Support
[    0.001308] CPU features: detected: Data cache clean to the PoU not required for I/D coherence
[    0.001310] CPU features: detected: Instruction cache invalidation not required for I/D coherence
[    0.001313] CPU features: detected: CRC32 instructions
[    0.025158] CPU: All CPU(s) started at EL1
[    0.025172] alternatives: patching kernel code
[    0.025780] devtmpfs: initialized
[    0.026020] Registered cp15_barrier emulation handler
[    0.026030] Registered setend emulation handler
[    0.026078] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
[    0.026084] futex hash table entries: 512 (order: 3, 32768 bytes, linear)
[    0.026414] pinctrl core: initialized pinctrl subsystem
[    0.026523] SMBIOS 3.0.0 present.
[    0.026527] DMI: Amazon EC2 c6gd.large/, BIOS 1.0 11/1/2018
[    0.026641] NET: Registered protocol family 16
[    0.026863] DMA: preallocated 256 KiB pool for atomic allocations
[    0.026866] audit: initializing netlink subsys (disabled)
[    0.026910] audit: type=2000 audit(0.020:1): state=initialized audit_enabled=0 res=1
[    0.027027] cpuidle: using governor menu
[    0.027069] hw-breakpoint: found 6 breakpoint and 4 watchpoint registers.
[    0.027098] ACPI: bus type PCI registered
[    0.027100] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5
[    0.027111] Serial: AMBA PL011 UART driver
[    0.028255] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages
[    0.028259] HugeTLB registered 32.0 MiB page size, pre-allocated 0 pages
[    0.028261] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages
[    0.028263] HugeTLB registered 64.0 KiB page size, pre-allocated 0 pages
[    0.062889] cryptd: max_cpu_qlen set to 1000
[    0.069660] ACPI: Added _OSI(Module Device)
[    0.069665] ACPI: Added _OSI(Processor Device)
[    0.069667] ACPI: Added _OSI(3.0 _SCP Extensions)
[    0.069669] ACPI: Added _OSI(Processor Aggregator Device)
[    0.069672] ACPI: Added _OSI(Linux-Dell-Video)
[    0.069674] ACPI: Added _OSI(Linux-Lenovo-NV-HDMI-Audio)
[    0.069676] ACPI: Added _OSI(Linux-HPI-Hybrid-Graphics)
[    0.070288] ACPI: 1 ACPI AML tables successfully acquired and loaded
[    0.070467] ACPI: Interpreter enabled
[    0.070469] ACPI: Using GIC for interrupt routing
[    0.070478] ACPI: MCFG table detected, 1 entries
[    0.072189] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-0f])
[    0.072198] acpi PNP0A08:00: _OSC: OS supports [ExtendedConfig ASPM ClockPM Segments MSI HPX-Type3]
[    0.072268] acpi PNP0A08:00: _OSC: platform does not support [SHPCHotplug LTR]
[    0.072324] acpi PNP0A08:00: _OSC: OS now controls [PCIeHotplug PME AER PCIeCapability]
[    0.072408] acpi PNP0A08:00: ECAM area [mem 0x20000000-0x20ffffff] reserved by PNP0C02:00
[    0.072416] acpi PNP0A08:00: ECAM at [mem 0x20000000-0x20ffffff] for [bus 00-0f]
[    0.072432] Remapped I/O 0x000000001fff0000 to [io  0x0000-0xffff window]
[    0.072650] acpiphp: Slot [1] registered
[    0.072663] acpiphp: Slot [2] registered
[    0.072674] acpiphp: Slot [3] registered
[    0.072686] acpiphp: Slot [4] registered
[    0.072698] acpiphp: Slot [5] registered
[    0.072709] acpiphp: Slot [6] registered
[    0.072720] acpiphp: Slot [7] registered
[    0.072731] acpiphp: Slot [8] registered
[    0.072742] acpiphp: Slot [9] registered
[    0.072754] acpiphp: Slot [10] registered
[    0.072766] acpiphp: Slot [11] registered
[    0.072778] acpiphp: Slot [12] registered
[    0.072789] acpiphp: Slot [13] registered
[    0.072800] acpiphp: Slot [14] registered
[    0.072811] acpiphp: Slot [15] registered
[    0.072822] acpiphp: Slot [16] registered
[    0.072834] acpiphp: Slot [17] registered
[    0.072845] acpiphp: Slot [18] registered
[    0.072855] acpiphp: Slot [19] registered
[    0.072866] acpiphp: Slot [20] registered
[    0.072877] acpiphp: Slot [21] registered
[    0.072890] acpiphp: Slot [22] registered
[    0.072901] acpiphp: Slot [23] registered
[    0.072912] acpiphp: Slot [24] registered
[    0.072923] acpiphp: Slot [25] registered
[    0.072933] acpiphp: Slot [26] registered
[    0.072944] acpiphp: Slot [27] registered
[    0.072956] acpiphp: Slot [28] registered
[    0.072967] acpiphp: Slot [29] registered
[    0.072977] acpiphp: Slot [30] registered
[    0.072988] acpiphp: Slot [31] registered
[    0.073007] PCI host bridge to bus 0000:00
[    0.073010] pci_bus 0000:00: root bus resource [mem 0x80000000-0xffffffff window]
[    0.073012] pci_bus 0000:00: root bus resource [io  0x0000-0xffff window]
[    0.073015] pci_bus 0000:00: root bus resource [mem 0x400000000000-0x407fffffffff window]
[    0.073017] pci_bus 0000:00: root bus resource [bus 00-0f]
[    0.073048] pci 0000:00:00.0: [1d0f:0200] type 00 class 0x060000
[    0.073315] pci 0000:00:01.0: [1d0f:8250] type 00 class 0x070003
[    0.073370] pci 0000:00:01.0: reg 0x10: [mem 0x8011e000-0x8011efff]
[    0.073597] pci 0000:00:04.0: [1d0f:8061] type 00 class 0x010802
[    0.074781] pci 0000:00:04.0: reg 0x10: [mem 0x80118000-0x8011bfff]
[    0.078896] pci 0000:00:04.0: PME# supported from D0 D1 D2 D3hot D3cold
[    0.079100] pci 0000:00:05.0: [1d0f:ec20] type 00 class 0x020000
[    0.079150] pci 0000:00:05.0: reg 0x10: [mem 0x80114000-0x80117fff]
[    0.079178] pci 0000:00:05.0: reg 0x18: [mem 0x80000000-0x800fffff pref]
[    0.079205] pci 0000:00:05.0: reg 0x20: [mem 0x80100000-0x8010ffff]
[    0.079387] pci 0000:00:05.0: PME# supported from D0 D1 D2 D3hot D3cold
[    0.079601] pci 0000:00:1f.0: [1d0f:cd01] type 00 class 0x010802
[    0.079891] pci 0000:00:1f.0: reg 0x10: [mem 0x80110000-0x80113fff]
[    0.080366] pci 0000:00:1f.0: reg 0x18: [mem 0x8011c000-0x8011dfff pref]
[    0.081463] pci 0000:00:1f.0: PME# supported from D0 D1 D2 D3hot D3cold
[    0.081612] pci 0000:00:05.0: BAR 2: assigned [mem 0x80000000-0x800fffff pref]
[    0.081622] pci 0000:00:05.0: BAR 4: assigned [mem 0x80100000-0x8010ffff]
[    0.081630] pci 0000:00:04.0: BAR 0: assigned [mem 0x80110000-0x80113fff]
[    0.082253] pci 0000:00:05.0: BAR 0: assigned [mem 0x80114000-0x80117fff]
[    0.082262] pci 0000:00:1f.0: BAR 0: assigned [mem 0x80118000-0x8011bfff]
[    0.082393] pci 0000:00:1f.0: BAR 2: assigned [mem 0x8011c000-0x8011dfff pref]
[    0.082401] pci 0000:00:01.0: BAR 0: assigned [mem 0x8011e000-0x8011efff]
[    0.082412] pci_bus 0000:00: resource 4 [mem 0x80000000-0xffffffff window]
[    0.082414] pci_bus 0000:00: resource 5 [io  0x0000-0xffff window]
[    0.082416] pci_bus 0000:00: resource 6 [mem 0x400000000000-0x407fffffffff window]
[    0.082448] ACPI: PCI Interrupt Link [GSI0] (IRQs *35)
[    0.082455] ACPI: PCI Interrupt Link [GSI1] (IRQs *36)
[    0.082462] ACPI: PCI Interrupt Link [GSI2] (IRQs *37)
[    0.082468] ACPI: PCI Interrupt Link [GSI3] (IRQs *38)
[    0.082785] iommu: Default domain type: Translated 
[    0.082832] vgaarb: loaded
[    0.082913] SCSI subsystem initialized
[    0.082978] ACPI: bus type USB registered
[    0.082997] usbcore: registered new interface driver usbfs
[    0.083004] usbcore: registered new interface driver hub
[    0.083010] usbcore: registered new device driver usb
[    0.083081] EDAC MC: Ver: 3.0.0
[    0.083197] Registered efivars operations
[    0.083357] NetLabel: Initializing
[    0.083360] NetLabel:  domain hash size = 128
[    0.083362] NetLabel:  protocols = UNLABELED CIPSOv4 CALIPSO
[    0.083374] NetLabel:  unlabeled traffic allowed by default
[    0.083460] clocksource: Switched to clocksource arch_sys_counter
[    0.103746] *** VALIDATE bpf ***
[    0.103805] VFS: Disk quotas dquot_6.6.0
[    0.103818] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes)
[    0.103840] *** VALIDATE ramfs ***
[    0.103842] *** VALIDATE hugetlbfs ***
[    0.103889] pnp: PnP ACPI init
[    0.103984] system 00:00: [mem 0x20000000-0x2fffffff] could not be reserved
[    0.103994] pnp: PnP ACPI: found 1 devices
[    0.105371] thermal_sys: Registered thermal governor 'fair_share'
[    0.105371] thermal_sys: Registered thermal governor 'step_wise'
[    0.105374] thermal_sys: Registered thermal governor 'user_space'
[    0.105408] NET: Registered protocol family 2
[    0.105439] IP idents hash table entries: 65536 (order: 7, 524288 bytes, linear)
[    0.105913] tcp_listen_portaddr_hash hash table entries: 2048 (order: 3, 32768 bytes, linear)
[    0.105933] TCP established hash table entries: 32768 (order: 6, 262144 bytes, linear)
[    0.106017] TCP bind hash table entries: 32768 (order: 7, 524288 bytes, linear)
[    0.106188] TCP: Hash tables configured (established 32768 bind 32768)
[    0.106204] UDP hash table entries: 2048 (order: 4, 65536 bytes, linear)
[    0.106235] UDP-Lite hash table entries: 2048 (order: 4, 65536 bytes, linear)
[    0.106286] NET: Registered protocol family 1
[    0.106291] NET: Registered protocol family 44
[    0.106351] PCI: CLS 0 bytes, default 64
[    0.106386] Trying to unpack rootfs image as initramfs...
[    0.125923] Freeing initrd memory: 9440K
[    0.126088] hw perfevents: enabled with armv8_pmuv3_0 PMU driver, 4 counters available
[    0.126092] kvm [1]: HYP mode not available
[    0.142535] Initialise system trusted keyrings
[    0.142570] workingset: timestamp_bits=44 max_order=20 bucket_order=0
[    0.143494] zbud: loaded
[    0.143642] SGI XFS with ACLs, security attributes, no debug enabled
[    0.144011] NET: Registered protocol family 38
[    0.144017] Key type asymmetric registered
[    0.144019] Asymmetric key parser 'x509' registered
[    0.144027] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 250)
[    0.144063] io scheduler mq-deadline registered
[    0.144065] io scheduler kyber registered
[    0.144085] io scheduler bfq registered
[    0.144710] pl061_gpio ARMH0061:00: PL061 GPIO chip registered
[    0.144760] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4
[    0.146269] input: Power Button as /devices/LNXSYSTM:00/LNXSYBUS:00/PNP0C0C:00/input/input0
[    0.146290] ACPI: Power Button [PWRB]
[    0.146419] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled
[    0.146700] PCI Interrupt Link [GSI2] enabled at IRQ 37
[    0.146732] serial 0000:00:01.0: enabling device (0010 -> 0012)
[    0.146887] printk: console [ttyS0] disabled
[    0.172567] 0000:00:01.0: ttyS0 at MMIO 0x8011e000 (irq = 6, base_baud = 115200) is a 16550A
[    0.421939] printk: console [ttyS0] enabled
[    0.422889] rdac: device handler registered
[    0.423593] hp_sw: device handler registered
[    0.424264] emc: device handler registered
[    0.424913] alua: device handler registered
[    0.425854] PCI Interrupt Link [GSI0] enabled at IRQ 35
[    0.426718] nvme nvme0: pci function 0000:00:04.0
[    0.427522] PCI Interrupt Link [GSI3] enabled at IRQ 38
[    0.428378] nvme nvme1: pci function 0000:00:1f.0
[    0.429206] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
[    0.430289] ehci-pci: EHCI PCI platform driver
[    0.430967] ohci_hcd: USB 1.1 'Open' Host Controller (OHCI) Driver
[    0.431904] ohci-pci: OHCI PCI platform driver
[    0.432572] uhci_hcd: USB Universal Host Controller Interface driver
[    0.433601] usbcore: registered new interface driver usbserial_generic
[    0.434582] usbserial: USB Serial support registered for generic
[    0.435527] mousedev: PS/2 mouse device common for all mice
[    0.436522] rtc-efi rtc-efi: registered as rtc0
[    0.437217] i2c /dev entries driver
[    0.437754] IR NEC protocol handler initialized
[    0.438459] IR RC5(x/sz) protocol handler initialized
[    0.439223] IR RC6 protocol handler initialized
[    0.439914] IR JVC protocol handler initialized
[    0.440599] IR Sony protocol handler initialized
[    0.441325] IR SANYO protocol handler initialized
[    0.442027] IR Sharp protocol handler initialized
[    0.442738] IR MCE Keyboard/mouse protocol handler initialized
[    0.443631] IR XMP protocol handler initialized
[    0.444383] EFI Variables Facility v0.08 2004-May-17
[    0.446422] hidraw: raw HID events driver (C) Jiri Kosina
[    0.447283] usbcore: registered new interface driver usbhid
[    0.448092] usbhid: USB HID core driver
[    0.448709] drop_monitor: Initializing network drop monitor service
[    0.449713] Initializing XFRM netlink socket
[    0.450456] NET: Registered protocol family 10
[    0.451315] Segment Routing with IPv6
[    0.451910] NET: Registered protocol family 17
[    0.452738] registered taskstats version 1
[    0.453379] Loading compiled-in X.509 certificates
[    0.455521] alg: No test for pkcs1pad(rsa,sha1) (pkcs1pad(rsa-generic,sha1))
[    0.457308] Loaded X.509 cert 'Build time autogenerated kernel key: fccc455f7ccdaede87bba1b9018e85d3dd892f88'
[    0.458821] zswap: loaded using pool lzo/zbud
[    0.461114] Key type big_key registered
[    0.461967] rtc-efi rtc-efi: setting system clock to 2022-12-22T11:27:16 UTC (1671708436)
[    0.665307] nvme nvme0: 2/0/0 default/read/poll queues
[    0.666521] nvme nvme1: 2/0/0 default/read/poll queues
[    0.671011] GPT:Primary header thinks Alt. header is not at the end of the disk.
[    0.672134] GPT:8388607 != 20971519
[    0.672677] GPT:Alternate GPT header not at the end of the disk.
[    0.673610] GPT:8388607 != 20971519
[    0.674160] GPT: Use GNU Parted to correct GPT errors.
[    0.674954]  nvme0n1: p1 p128
[    0.714176] Freeing unused kernel memory: 1408K
[    0.714983] Run /init as init process
[    0.753862] systemd[1]: systemd 219 running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 -SECCOMP +BLKID +ELFUTILS +KMOD +IDN)
[    0.756616] systemd[1]: Detected virtualization amazon.
[    0.757410] systemd[1]: Detected architecture arm64.
[    0.758151] systemd[1]: Running in initial RAM disk.

Welcome to Amazon Linux 2 dracut-033-535.amzn2.1.6 (Initramfs)!

[    0.760804] systemd[1]: No hostname configured.
[    0.761517] systemd[1]: Set hostname to <localhost>.
[    0.762294] systemd[1]: Initializing machine ID from VM UUID.
[    0.785736] systemd[1]: Reached target Timers.
[  OK  ] Reached target Timers.
[    0.787781] systemd[1]: Created slice Root Slice.
[  OK  ] Created slice Root Slice.
[    0.789599] systemd[1]: Listening on udev Control Socket.
[  OK  ] Listening on udev Control Socket.
[  OK  ] Created slice System Slice.
[  OK  ] Listening on Journal Socket.
[  OK  ] Reached target Slices.
[  OK  ] Reached target Swap.
         Starting Create list of required st... nodes for the current kernel...
[  OK  ] Started Dispatch Password Requests to Console Directory Watch.
[  OK  ] Reached target Paths.
         Starting Journal Service...
[  OK  ] Reached target Local File Systems.
[  OK  ] Listening on udev Kernel Socket.
[  OK  ] Reached target Sockets.
         Starting Apply Kernel Variables...
[  OK  ] Started Journal Service.
[  OK  ] Started Create list of required sta...ce nodes for the current kernel.
[  OK  ] Started Apply Kernel Variables.
         Starting Create Static Device Nodes in /dev...
[  OK  ] Started Create Static Device Nodes in /dev.
         Starting udev Kernel Device Manager...
[  OK  ] Started udev Kernel Device Manager.
         Starting udev Coldplug all Devices...
         Mounting Configuration File System...
[  OK  ] Mounted Configuration File System.
[  OK  ] Started udev Coldplug all Devices.
         Starting dracut initqueue hook...
[  OK  ] Reached target System Initialization.
[  OK  ] Reached target Basic System.
[  OK  ] Found device Amazon Elastic Block Store /.
         Starting File System Check on /dev/...c-62db-4f3c-98c9-cac9f4c74f58...
[  OK  ] Started File System Check on /dev/d...eec-62db-4f3c-98c9-cac9f4c74f58.
[  OK  ] Started dracut initqueue hook.
[  OK  ] Reached target Remote File Systems (Pre).
[  OK  ] Reached target Remote File Systems.
         Mounting /sysroot...
[    1.174778] XFS (nvme0n1p1): Mounting V5 Filesystem
[    2.254001] XFS (nvme0n1p1): Ending clean mount
[  OK  ] Mounted /sysroot.
[  OK  ] Reached target Initrd Root File System.
         Starting Reload Configuration from the Real Root...
[  OK  ] Started Reload Configuration from the Real Root.
[  OK  ] Reached target Initrd File Systems.
[  OK  ] Reached target Initrd Default Target.
         Starting dracut pre-pivot and cleanup hook...
[  OK  ] Started dracut pre-pivot and cleanup hook.
         Starting Cleaning Up and Shutting Down Daemons...
[  OK  ] Stopped target Timers.
[  OK  ] Stopped dracut pre-pivot and cleanup hook.
[  OK  ] Stopped target Initrd Default Target.
[  OK  ] Stopped target Basic System.
[  OK  ] Stopped target Paths.
[  OK  ] Stopped target Slices.
[  OK  ] Stopped target System Initialization.
         Stopping udev Kernel Device Manager...
[  OK  ] Stopped target Local File Systems.
[  OK  ] Stopped Apply Kernel Variables.
[  OK  ] Stopped target Sockets.
[  OK  ] Stopped target Remote File Systems.
[  OK  ] Stopped target Remote File Systems (Pre).
[  OK  ] Stopped dracut initqueue hook.
[  OK  ] Stopped udev Coldplug all Devices.
[  OK  ] Stopped target Swap.
[  OK  ] Stopped Dispatch Password Requests to Console Directory Watch.
[  OK  ] Stopped udev Kernel Device Manager.
[  OK  ] Stopped Create Static Device Nodes in /dev.
[  OK  ] Stopped Create list of required sta...ce nodes for the current kernel.
[  OK  ] Closed udev Control Socket.
[  OK  ] Closed udev Kernel Socket.
         Starting Cleanup udevd DB...
[  OK  ] Started Cleaning Up and Shutting Down Daemons.
[  OK  ] Started Cleanup udevd DB.
[  OK  ] Reached target Switch Root.
         Starting Switch Root...
[    2.805136] systemd-journald[255]: Received SIGTERM from PID 1 (systemd).
[    3.258099] printk: systemd: 13 output lines suppressed due to ratelimiting
[    4.930360] SELinux:  Disabled at runtime.
[    5.093480] audit: type=1404 audit(1671708441.129:2): enforcing=0 old_enforcing=0 auid=4294967295 ses=4294967295 enabled=0 old-enabled=1 lsm=selinux res=1

Welcome to Amazon Linux 2!

[  OK  ] Stopped Switch Root.
[  OK  ] Stopped Journal Service.
         Starting Journal Service...
[  OK  ] Listening on LVM2 poll daemon socket.
[  OK  ] Created slice system-serial\x2dgetty.slice.
         Starting Read and set NIS domainname from /etc/sysconfig/network...
         Starting Create list of required st... nodes for the current kernel...
         Mounting Debug File System...
[  OK  ] Reached target Local Encrypted Volumes.
[  OK  ] Listening on udev Kernel Socket.
         Mounting POSIX Message Queue File System...
[  OK  ] Listening on LVM2 metadata daemon socket.
         Mounting Huge Pages File System...
[  OK  ] Listening on /dev/initctl Compatibility Named Pipe.
[  OK  ] Created slice system-getty.slice.
[  OK  ] Listening on Device-mapper event daemon FIFOs.
[  OK  ] Started Forward Password Requests to Wall Directory Watch.
[  OK  ] Started Dispatch Password Requests to Console Directory Watch.
         Starting Remount Root and Kernel File Systems...
[  OK  ] Created slice User and Session Slice.
[  OK  ] Listening on udev Control Socket.
         Starting Monitoring of LVM2 mirrors... dmeventd or progress polling...
[  OK  ] Stopped target Switch Root.
         Starting Setup Virtual Console...
[  OK  ] Stopped target Initrd File Systems.
[  OK  ] Reached target Slices.
[  OK  ] Reached target Swap.
[  OK  ] Listening on Delayed Shutdown Socket.
[  OK  ] Created slice system-selinux\x2dpol...grate\x2dlocal\x2dchanges.slice.
[  OK  ] Set up automount Arbitrary Executab...ats File System Automount Point.
[  OK  ] Stopped target Initrd Root File System.
[  OK  ] Started Create list of required sta...ce nodes for the current kernel.
         Starting Create Static Device Nodes in /dev...
[  OK  ] Mounted Debug File System.
[  OK  ] Mounted POSIX Message Queue File System.
[  OK  ] Mounted Huge Pages File System.
[  OK  ] Started Setup Virtual Console.
[  OK  ] Started Journal Service.
[  OK  ] Started Read and set NIS domainname from /etc/sysconfig/network.
[  OK  ] Started LVM2 metadata daemon.
[    8.474969] xfs filesystem being remounted at / supports timestamps until 2038 (0x7fffffff)
[  OK  ] Started Remount Root and Kernel File Systems.
         Starting udev Coldplug all Devices...
         Starting Flush Journal to Persistent Storage...
         Starting Configure read-only root support...
         Starting Relabel kernel modules early in the boot, if needed...
[  OK  ] Started Relabel kernel modules early in the boot, if needed.
         Starting Load Kernel Modules...
[  OK  ] Started udev Coldplug all Devices.
[    8.671140] systemd-journald[370]: Received request to flush runtime journal from PID 1
[  OK  ] Started Flush Journal to Persistent Storage.
[  OK  ] Started Configure read-only root support.
         Starting Load/Save Random Seed...
[  OK  ] Started Load/Save Random Seed.
[  OK  ] Started Create Static Device Nodes in /dev.
         Starting udev Kernel Device Manager...
[    9.231127] bridge: filtering via arp/ip/ip6tables is no longer available by default. Update your scripts to load br_netfilter if you need this.
[    9.236806] Bridge firewalling registered
[    9.475528] PCI Interrupt Link [GSI1] enabled at IRQ 36
[    9.476360] ena 0000:00:05.0: Elastic Network Adapter (ENA) v2.8.0g
[    9.477349] ena 0000:00:05.0: enabling device (0010 -> 0012)
[  OK  ] Started udev Kernel Device Manager.
[    9.489106] ena 0000:00:05.0: ENA device version: 0.10
[    9.489912] ena 0000:00:05.0: ENA controller version: 0.0.1 implementation version 1
[    9.592094] ena 0000:00:05.0: Elastic Network Adapter (ENA) found at mem 80114000, mac addr 02:f4:87:4f:09:79
[  OK  ] Started Load Kernel Modules.
         Starting Apply Kernel Variables...
[  OK  ] Found device /dev/ttyS0.
[  OK  ] Started Apply Kernel Variables.
[  OK  ] Found device Amazon Elastic Block Store EFI\x20System\x20Partition.
[  OK  ] Started Monitoring of LVM2 mirrors,...ng dmeventd or progress polling.
[  OK  ] Reached target Local File Systems (Pre).
         Mounting /boot/efi...
[  OK  ] Mounted /boot/efi.
[  OK  ] Reached target Local File Systems.
         Starting Commit a transient machine-id on disk...
         Starting Create Volatile Files and Directories...
         Starting Preprocess NFS configuration...
[  OK  ] Started Commit a transient machine-id on disk.
[  OK  ] Started Create Volatile Files and Directories.
         Starting Security Auditing Service...
         Mounting RPC Pipe File System...
[  OK  ] Started Preprocess NFS configuration.
[   12.109715] RPC: Registered named UNIX socket transport module.
[   12.110634] RPC: Registered udp transport module.
[   12.111355] RPC: Registered tcp transport module.
[   12.112074] RPC: Registered tcp NFSv4.1 backchannel transport module.
[  OK  ] Mounted RPC Pipe File System.
[  OK  ] Reached target rpc_pipefs.target.
[  OK  ] Started Security Auditing Service.
         Starting Update UTMP about System Boot/Shutdown...
[  OK  ] Started Update UTMP about System Boot/Shutdown.
[  OK  ] Reached target System Initialization.
[  OK  ] Listening on RPCbind Server Activation Socket.
         Starting RPC bind service...
[  OK  ] Listening on D-Bus System Message Bus Socket.
[  OK  ] Reached target Sockets.
[  OK  ] Started Flexible branding.
[  OK  ] Reached target Paths.
[  OK  ] Reached target Basic System.
         Starting NTP client/server...
         Starting Hardware RNG Entropy Gatherer Wake threshold service...
[  OK  ] Started D-Bus System Message Bus.
[   12.715854] xfs filesystem being remounted at /tmp supports timestamps until 2038 (0x7fffffff)
[   12.717901] xfs filesystem being remounted at /var/tmp supports timestamps until 2038 (0x7fffffff)
[  OK  ] Started irqbalance daemon.
         Starting GSSAPI Proxy Daemon...
         Starting Initial cloud-init job (pre-networking)...
         Starting Login Service...
         Starting Dump dmesg to /var/log/dmesg...
[  OK  ] Started Daily Cleanup of Temporary Directories.
[  OK  ] Reached target Timers.
[  OK  ] Started Hardware RNG Entropy Gatherer Wake threshold service.
[  OK  ] Started Hardware RNG Entropy Gatherer Daemon.
[  OK  ] Started Login Service.
[  OK  ] Started RPC bind service.
[  OK  ] Started NTP client/server.
[  OK  ] Started Dump dmesg to /var/log/dmesg.
[  OK  ] Started GSSAPI Proxy Daemon.
[  OK  ] Reached target NFS client services.
[  OK  ] Reached target Remote File Systems (Pre).
[  OK  ] Reached target Remote File Systems.
[   17.112396] cloud-init[514]: Cloud-init v. 19.3-46.amzn2 running 'init-local' at Thu, 22 Dec 2022 11:27:33 +0000. Up 17.02 seconds.
[  OK  ] Started Initial cloud-init job (pre-networking).
[  OK  ] Reached target Network (Pre).
         Starting LSB: Bring up/down networking...
[   19.055648] ena 0000:00:05.0 eth0: Local page cache is disabled for less than 16 channels
[  OK  ] Started LSB: Bring up/down networking.
         Starting Initial cloud-init job (metadata service crawler)...
[  OK  ] Reached target Network.
         Starting Postfix Mail Transport Agent...
[   19.554358] cloud-init[819]: Cloud-init v. 19.3-46.amzn2 running 'init' at Thu, 22 Dec 2022 11:27:35 +0000. Up 19.52 seconds.
[   19.567713] cloud-init[819]: ci-info: +++++++++++++++++++++++++++++++++++++Net device info++++++++++++++++++++++++++++++++++++++
[   19.571432] cloud-init[819]: ci-info: +--------+------+---------------------------+---------------+--------+-------------------+
[   19.575854] cloud-init[819]: ci-info: | Device |  Up  |          Address          |      Mask     | Scope  |     Hw-Address    |
[   19.578982] cloud-init[819]: ci-info: +--------+------+---------------------------+---------------+--------+-------------------+
[   19.582095] cloud-init[819]: ci-info: |  eth0  | True |        10.2.23.188        | 255.255.254.0 | global | 02:f4:87:4f:09:79 |
[   19.585223] cloud-init[819]: ci-info: |  eth0  | True | fe80::f4:87ff:fe4f:979/64 |       .       |  link  | 02:f4:87:4f:09:79 |
[   19.588302] cloud-init[819]: ci-info: |   lo   | True |         127.0.0.1         |   255.0.0.0   |  host  |         .         |
[   19.591427] cloud-init[819]: ci-info: |   lo   | True |          ::1/128          |       .       |  host  |         .         |
[   19.594507] cloud-init[819]: ci-info: +--------+------+---------------------------+---------------+--------+-------------------+
[   19.597574] cloud-init[819]: ci-info: +++++++++++++++++++++++++++++++Route IPv4 info+++++++++++++++++++++++++++++++
[   19.600778] cloud-init[819]: ci-info: +-------+-----------------+-----------+-----------------+-----------+-------+
[   19.603721] cloud-init[819]: ci-info: | Route |   Destination   |  Gateway  |     Genmask     | Interface | Flags |
[   19.606541] cloud-init[819]: ci-info: +-------+-----------------+-----------+-----------------+-----------+-------+
[   19.609303] cloud-init[819]: ci-info: |   0   |     0.0.0.0     | 10.2.22.1 |     0.0.0.0     |    eth0   |   UG  |
[   19.612090] cloud-init[819]: ci-info: |   1   |    10.2.22.0    |  0.0.0.0  |  255.255.254.0  |    eth0   |   U   |
[   19.614857] cloud-init[819]: ci-info: |   2   | 169.254.169.254 |  0.0.0.0  | 255.255.255.255 |    eth0   |   UH  |
[   19.617641] cloud-init[819]: ci-info: +-------+-----------------+-----------+-----------------+-----------+-------+
[   19.620393] cloud-init[819]: ci-info: +++++++++++++++++++Route IPv6 info+++++++++++++++++++
[   19.622645] cloud-init[819]: ci-info: +-------+-------------+---------+-----------+-------+
[   19.624871] cloud-init[819]: ci-info: | Route | Destination | Gateway | Interface | Flags |
[   19.627480] cloud-init[819]: ci-info: +-------+-------------+---------+-----------+-------+
[   19.629813] cloud-init[819]: ci-info: |   9   |  fe80::/64  |    ::   |    eth0   |   U   |
[   19.632147] cloud-init[819]: ci-info: |   11  |    local    |    ::   |    eth0   |   U   |
[   19.634807] cloud-init[819]: ci-info: |   12  |  multicast  |    ::   |    eth0   |   U   |
[   19.637068] cloud-init[819]: ci-info: +-------+-------------+---------+-----------+-------+
         Starting Hostname Service...
[   19.974955] xfs filesystem being remounted at /tmp supports timestamps until 2038 (0x7fffffff)
[   19.976689] xfs filesystem being remounted at /var/tmp supports timestamps until 2038 (0x7fffffff)
[  OK  ] Started Hostname Service.
[  OK  ] Started Postfix Mail Transport Agent.
[  OK  ] Started Initial cloud-init job (metadata service crawler).
[  OK  ] Reached target Network is Online.
[  OK  ] Started amazon-ssm-agent.
         Starting System Logging Service...
         Starting Dynamically Generate Message Of The Day...
         Starting Notify NFS peers of a restart...
         Starting OpenSSH Server Key Generation...
[  OK  ] Reached target Cloud-config availability.
         Starting Apply the settings specified in cloud-config...
         Starting Permit User Sessions...
[  OK  ] Started Notify NFS peers of a restart.
[  OK  ] Started Permit User Sessions.
[  OK  ] Started Serial Getty on ttyS0.
[  OK  ] Started Getty on tty1.
[  OK  ] Reached target Login Prompts.
[  OK  ] Started Command Scheduler.
[  OK  ] Started System Logging Service.
[  OK  ] Started OpenSSH Server Key Generation.
         Starting OpenSSH server daemon...
[   21.362323] cloud-init[1017]: Cloud-init v. 19.3-46.amzn2 running 'modules:config' at Thu, 22 Dec 2022 11:27:37 +0000. Up 21.30 seconds.
[  OK  ] Started OpenSSH server daemon.
[   22.120770] cloud-init[1017]: Loaded plugins: priorities, update-motd, versionlock
2022/12/22 11:27:39Z: Amazon SSM Agent v3.1.1732.0 is running
2022/12/22 11:27:39Z: OsProductName: Amazon Linux
2022/12/22 11:27:39Z: OsVersion: 2

Amazon Linux 2
Kernel 5.4.219-126.411.amzn2.aarch64 on an aarch64

ip-10-2-23-188 login: [   27.421605] cloud-init[1017]: --> pcre2-10.23-2.amzn2.0.2.aarch64 from installed removed (updateinfo)
[   27.423099] cloud-init[1017]: --> aws-cfn-bootstrap-2.0-20.amzn2.noarch from amzn2-core removed (updateinfo)
[   27.424493] cloud-init[1017]: --> tzdata-2022e-1.amzn2.0.1.noarch from @amzn2-core removed (updateinfo)
[   27.424596] cloud-init[1017]: --> 12:dhclient-4.2.5-79.amzn2.1.2.aarch64 from amzn2-core removed (updateinfo)
[   27.424683] cloud-init[1017]: --> nspr-4.34.0-3.1.amzn2.aarch64 from amzn2-core removed (updateinfo)
[   27.424763] cloud-init[1017]: --> 12:dhcp-libs-4.2.5-79.amzn2.1.1.aarch64 from installed removed (updateinfo)
[   27.424840] cloud-init[1017]: --> glibc-all-langpacks-2.26-61.amzn2.aarch64 from @amzn2-core removed (updateinfo)
[   27.424925] cloud-init[1017]: --> glibc-minimal-langpack-2.26-61.amzn2.aarch64 from @amzn2-core removed (updateinfo)
[   27.425007] cloud-init[1017]: --> 1:python2-dateutil-2.6.1-3.amzn2.noarch from amzn2-core removed (updateinfo)
[   27.425089] cloud-init[1017]: --> pcre2-10.23-11.amzn2.0.1.aarch64 from amzn2-core removed (updateinfo)
[   27.425173] cloud-init[1017]: --> aws-cfn-bootstrap-2.0-10.amzn2.noarch from @amzn2-core removed (updateinfo)
[   27.425255] cloud-init[1017]: --> python2-jsonschema-2.5.1-3.amzn2.0.2.noarch from amzn2-core removed (updateinfo)
[   27.425337] cloud-init[1017]: --> nss-util-3.79.0-1.amzn2.aarch64 from amzn2-core removed (updateinfo)
[   27.425416] cloud-init[1017]: --> glibc-all-langpacks-2.26-62.amzn2.aarch64 from amzn2-core removed (updateinfo)
[   27.425500] cloud-init[1017]: --> python2-rsa-3.4.1-1.amzn2.0.3.noarch from amzn2-core removed (updateinfo)
[   27.425580] cloud-init[1017]: --> glibc-minimal-langpack-2.26-62.amzn2.aarch64 from amzn2-core removed (updateinfo)
[   27.425658] cloud-init[1017]: --> python2-colorama-0.3.9-3.amzn2.0.1.noarch from amzn2-core removed (updateinfo)
[   27.425736] cloud-init[1017]: --> python2-jmespath-0.9.3-1.amzn2.0.2.noarch from amzn2-core removed (updateinfo)
[   27.425816] cloud-init[1017]: --> nss-tools-3.79.0-4.amzn2.aarch64 from amzn2-core removed (updateinfo)
[   27.425900] cloud-init[1017]: --> glibc-2.26-62.amzn2.aarch64 from amzn2-core removed (updateinfo)
[   27.425981] cloud-init[1017]: --> e2fsprogs-libs-1.42.9-19.amzn2.aarch64 from installed removed (updateinfo)
[   27.426059] cloud-init[1017]: --> ncurses-libs-6.0-8.20170212.amzn2.1.3.aarch64 from installed removed (updateinfo)
[   27.426136] cloud-init[1017]: --> nss-sysinit-3.79.0-4.amzn2.aarch64 from amzn2-core removed (updateinfo)
[   27.426231] cloud-init[1017]: --> libcom_err-1.42.9-19.amzn2.aarch64 from installed removed (updateinfo)
[   27.426314] cloud-init[1017]: --> ncurses-base-6.0-8.20170212.amzn2.1.4.noarch from amzn2-core removed (updateinfo)
[   27.426394] cloud-init[1017]: --> python2-jmespath-0.9.3-1.amzn2.0.1.noarch from @amzn2-core removed (updateinfo)
[   27.426473] cloud-init[1017]: --> libblkid-2.30.2-2.amzn2.0.7.aarch64 from installed removed (updateinfo)
[   27.426551] cloud-init[1017]: --> e2fsprogs-libs-1.42.9-19.amzn2.0.1.aarch64 from amzn2-core removed (updateinfo)
[   27.426632] cloud-init[1017]: --> nspr-4.32.0-1.amzn2.0.1.aarch64 from installed removed (updateinfo)
[   27.426712] cloud-init[1017]: --> libsmartcols-2.30.2-2.amzn2.0.10.aarch64 from amzn2-core removed (updateinfo)
[   27.426798] cloud-init[1017]: --> 12:dhcp-common-4.2.5-79.amzn2.1.1.aarch64 from installed removed (updateinfo)
[   27.426879] cloud-init[1017]: --> libuuid-2.30.2-2.amzn2.0.10.aarch64 from amzn2-core removed (updateinfo)
[   27.426960] cloud-init[1017]: --> ncurses-base-6.0-8.20170212.amzn2.1.3.noarch from installed removed (updateinfo)
[   27.427040] cloud-init[1017]: --> systemd-libs-219-78.amzn2.0.21.aarch64 from amzn2-core removed (updateinfo)
[   27.427120] cloud-init[1017]: --> python-colorama-0.3.2-3.amzn2.noarch from @amzn2-core removed (updateinfo)
[   27.427195] cloud-init[1017]: --> util-linux-2.30.2-2.amzn2.0.7.aarch64 from installed removed (updateinfo)
[   27.427271] cloud-init[1017]: --> python2-pyasn1-0.1.9-7.amzn2.0.2.noarch from amzn2-core removed (updateinfo)
[   27.427355] cloud-init[1017]: --> libss-1.42.9-19.amzn2.aarch64 from installed removed (updateinfo)
[   27.427436] cloud-init[1017]: --> python2-rsa-3.4.1-1.amzn2.0.1.noarch from @amzn2-core removed (updateinfo)
[   27.481057] cloud-init[1017]: --> 12:dhcp-common-4.2.5-79.amzn2.1.2.aarch64 from amzn2-core removed (updateinfo)
[   27.481253] cloud-init[1017]: --> libcrypt-2.26-62.amzn2.aarch64 from amzn2-core removed (updateinfo)
[   27.481415] cloud-init[1017]: --> nss-sysinit-3.67.0-4.amzn2.0.2.aarch64 from installed removed (updateinfo)
[   27.481623] cloud-init[1017]: --> curl-7.79.1-7.amzn2.0.1.aarch64 from amzn2-core removed (updateinfo)
[   27.481774] cloud-init[1017]: --> e2fsprogs-1.42.9-19.amzn2.0.1.aarch64 from amzn2-core removed (updateinfo)
[   27.481958] cloud-init[1017]: --> libfdisk-2.30.2-2.amzn2.0.7.aarch64 from installed removed (updateinfo)
[   27.482124] cloud-init[1017]: --> nss-softokn-freebl-3.67.0-3.amzn2.0.1.aarch64 from installed removed (updateinfo)
[   27.482304] cloud-init[1017]: --> nss-util-3.67.0-1.amzn2.0.1.aarch64 from installed removed (updateinfo)
[   27.482468] cloud-init[1017]: --> ncurses-libs-6.0-8.20170212.amzn2.1.4.aarch64 from amzn2-core removed (updateinfo)
[   27.482646] cloud-init[1017]: --> python2-jsonschema-2.5.1-3.amzn2.0.1.noarch from installed removed (updateinfo)
[   27.482811] cloud-init[1017]: --> glibc-locale-source-2.26-61.amzn2.aarch64 from @amzn2-core removed (updateinfo)
[   27.482979] cloud-init[1017]: --> libsmartcols-2.30.2-2.amzn2.0.7.aarch64 from installed removed (updateinfo)
[   27.483150] cloud-init[1017]: --> libmount-2.30.2-2.amzn2.0.7.aarch64 from installed removed (updateinfo)
[   27.483324] cloud-init[1017]: --> 12:dhcp-libs-4.2.5-79.amzn2.1.2.aarch64 from amzn2-core removed (updateinfo)
[   27.483493] cloud-init[1017]: --> nss-softokn-freebl-3.79.0-4.amzn2.aarch64 from amzn2-core removed (updateinfo)
[   27.483668] cloud-init[1017]: --> libmount-2.30.2-2.amzn2.0.10.aarch64 from amzn2-core removed (updateinfo)
[   27.483836] cloud-init[1017]: --> nss-tools-3.67.0-4.amzn2.0.2.aarch64 from installed removed (updateinfo)
[   27.484007] cloud-init[1017]: --> libblkid-2.30.2-2.amzn2.0.10.aarch64 from amzn2-core removed (updateinfo)
[   27.484177] cloud-init[1017]: --> glibc-2.26-61.amzn2.aarch64 from @amzn2-core removed (updateinfo)
[   27.484346] cloud-init[1017]: --> systemd-219-78.amzn2.0.21.aarch64 from amzn2-core removed (updateinfo)
[   27.484517] cloud-init[1017]: --> python-six-1.9.0-2.amzn2.noarch from installed removed (updateinfo)
[   27.484686] cloud-init[1017]: --> tzdata-2022f-1.amzn2.0.1.noarch from amzn2-core removed (updateinfo)
[   27.484857] cloud-init[1017]: --> ncurses-6.0-8.20170212.amzn2.1.3.aarch64 from installed removed (updateinfo)
[   27.485033] cloud-init[1017]: --> glibc-locale-source-2.26-62.amzn2.aarch64 from amzn2-core removed (updateinfo)
[   27.485208] cloud-init[1017]: --> 1:python2-dateutil-2.6.0-3.amzn2.0.1.noarch from @amzn2-core removed (updateinfo)
[   27.485383] cloud-init[1017]: --> systemd-sysv-219-78.amzn2.0.20.aarch64 from installed removed (updateinfo)
[   27.485551] cloud-init[1017]: --> libcurl-7.79.1-7.amzn2.0.1.aarch64 from amzn2-core removed (updateinfo)
[   27.485725] cloud-init[1017]: --> libcrypt-2.26-61.amzn2.aarch64 from @amzn2-core removed (updateinfo)
[   27.485909] cloud-init[1017]: --> libfdisk-2.30.2-2.amzn2.0.10.aarch64 from amzn2-core removed (updateinfo)
[   27.486062] cloud-init[1017]: --> libss-1.42.9-19.amzn2.0.1.aarch64 from amzn2-core removed (updateinfo)
[   27.486233] cloud-init[1017]: --> xfsprogs-5.0.0-10.amzn2.0.1.aarch64 from amzn2-core removed (updateinfo)
[   27.486397] cloud-init[1017]: --> python2-six-1.11.0-8.amzn2.0.1.noarch from amzn2-core removed (updateinfo)
[   27.486570] cloud-init[1017]: --> glibc-common-2.26-61.amzn2.aarch64 from @amzn2-core removed (updateinfo)
[   27.486741] cloud-init[1017]: --> nss-3.79.0-4.amzn2.aarch64 from amzn2-core removed (updateinfo)
[   27.486917] cloud-init[1017]: --> e2fsprogs-1.42.9-19.amzn2.aarch64 from installed removed (updateinfo)
[   27.487085] cloud-init[1017]: --> systemd-219-78.amzn2.0.20.aarch64 from installed removed (updateinfo)
[   27.487254] cloud-init[1017]: --> nss-softokn-3.79.0-4.amzn2.aarch64 from amzn2-core removed (updateinfo)
[   27.487432] cloud-init[1017]: --> util-linux-2.30.2-2.amzn2.0.10.aarch64 from amzn2-core removed (updateinfo)
[   27.487601] cloud-init[1017]: --> xfsprogs-4.5.0-18.amzn2.0.1.aarch64 from installed removed (updateinfo)
[   27.487773] cloud-init[1017]: --> systemd-sysv-219-78.amzn2.0.21.aarch64 from amzn2-core removed (updateinfo)
[   27.487937] cloud-init[1017]: --> libuuid-2.30.2-2.amzn2.0.7.aarch64 from installed removed (updateinfo)
[   27.529340] cloud-init[1017]: --> 12:dhclient-4.2.5-79.amzn2.1.1.aarch64 from installed removed (updateinfo)
[   27.529430] cloud-init[1017]: --> libcom_err-1.42.9-19.amzn2.0.1.aarch64 from amzn2-core removed (updateinfo)
[   27.529599] cloud-init[1017]: --> curl-7.79.1-4.amzn2.0.1.aarch64 from installed removed (updateinfo)
[   27.529766] cloud-init[1017]: --> glibc-common-2.26-62.amzn2.aarch64 from amzn2-core removed (updateinfo)
[   27.529933] cloud-init[1017]: --> nss-3.67.0-4.amzn2.0.2.aarch64 from installed removed (updateinfo)
[   27.530105] cloud-init[1017]: --> libcurl-7.79.1-4.amzn2.0.1.aarch64 from installed removed (updateinfo)
[   27.530281] cloud-init[1017]: --> systemd-libs-219-78.amzn2.0.20.aarch64 from installed removed (updateinfo)
[   27.530450] cloud-init[1017]: --> nss-softokn-3.67.0-3.amzn2.0.1.aarch64 from installed removed (updateinfo)
[   27.530616] cloud-init[1017]: --> python2-pyasn1-0.1.9-7.amzn2.0.1.noarch from installed removed (updateinfo)
[   27.530808] cloud-init[1017]: --> ncurses-6.0-8.20170212.amzn2.1.4.aarch64 from amzn2-core removed (updateinfo)
[   27.530974] cloud-init[1017]: 9 package(s) needed (+0 related) for security, out of 54 available
[   27.531132] cloud-init[1017]: Resolving Dependencies
[   27.531305] cloud-init[1017]: --> Running transaction check
[   27.531473] cloud-init[1017]: ---> Package dbus.aarch64 1:1.10.24-7.amzn2 will be updated
[   27.531656] cloud-init[1017]: ---> Package dbus.aarch64 1:1.10.24-7.amzn2.0.2 will be an update
[   27.560026] cloud-init[1017]: ---> Package dbus-libs.aarch64 1:1.10.24-7.amzn2 will be updated
[   27.561730] cloud-init[1017]: ---> Package dbus-libs.aarch64 1:1.10.24-7.amzn2.0.2 will be an update
[   27.565621] cloud-init[1017]: ---> Package expat.aarch64 0:2.1.0-14.amzn2.0.1 will be updated
[   27.569614] cloud-init[1017]: ---> Package expat.aarch64 0:2.1.0-15.amzn2.0.2 will be an update
[   27.571220] cloud-init[1017]: ---> Package kpartx.aarch64 0:0.4.9-127.amzn2 will be updated
[   27.573567] cloud-init[1017]: ---> Package kpartx.aarch64 0:0.4.9-136.amzn2 will be an update
[   27.576648] cloud-init[1017]: ---> Package libtiff.aarch64 0:4.0.3-35.amzn2.0.2 will be updated
[   27.583319] cloud-init[1017]: ---> Package libtiff.aarch64 0:4.0.3-35.amzn2.0.5 will be an update
[   27.590796] cloud-init[1017]: ---> Package python3.aarch64 0:3.7.10-1.amzn2.0.1 will be updated
[   27.600111] cloud-init[1017]: ---> Package python3.aarch64 0:3.7.15-1.amzn2.0.2 will be an update
[   27.609713] cloud-init[1017]: ---> Package python3-libs.aarch64 0:3.7.10-1.amzn2.0.1 will be updated
[   27.611822] cloud-init[1017]: ---> Package python3-libs.aarch64 0:3.7.15-1.amzn2.0.2 will be an update
[   27.638988] cloud-init[1017]: ---> Package vim-data.noarch 2:9.0.475-1.amzn2.0.1 will be updated
[   27.641871] cloud-init[1017]: ---> Package vim-data.noarch 2:9.0.828-1.amzn2.0.1 will be an update
[   27.643235] cloud-init[1017]: ---> Package vim-minimal.aarch64 2:9.0.475-1.amzn2.0.1 will be updated
[   27.645619] cloud-init[1017]: ---> Package vim-minimal.aarch64 2:9.0.828-1.amzn2.0.1 will be an update
[   28.167933] cloud-init[1017]: --> Finished Dependency Resolution
[   28.194564] cloud-init[1017]: Dependencies Resolved
[   28.197835] cloud-init[1017]: ================================================================================
[   28.199391] cloud-init[1017]: Package          Arch        Version                      Repository      Size
[   28.200581] cloud-init[1017]: ================================================================================
[   28.200828] cloud-init[1017]: Updating:
[   28.200919] cloud-init[1017]: dbus             aarch64     1:1.10.24-7.amzn2.0.2        amzn2-core     244 k
[   28.200999] cloud-init[1017]: dbus-libs        aarch64     1:1.10.24-7.amzn2.0.2        amzn2-core     167 k
[   28.201081] cloud-init[1017]: expat            aarch64     2.1.0-15.amzn2.0.2           amzn2-core      88 k
[   28.201164] cloud-init[1017]: kpartx           aarch64     0.4.9-136.amzn2              amzn2-core      81 k
[   28.201249] cloud-init[1017]: libtiff          aarch64     4.0.3-35.amzn2.0.5           amzn2-core     172 k
[   28.201328] cloud-init[1017]: python3          aarch64     3.7.15-1.amzn2.0.2           amzn2-core      72 k
[   28.201405] cloud-init[1017]: python3-libs     aarch64     3.7.15-1.amzn2.0.2           amzn2-core     9.7 M
[   28.201485] cloud-init[1017]: vim-data         noarch      2:9.0.828-1.amzn2.0.1        amzn2-core      77 k
[   28.201563] cloud-init[1017]: vim-minimal      aarch64     2:9.0.828-1.amzn2.0.1        amzn2-core     710 k
[   28.201643] cloud-init[1017]: Transaction Summary
[   28.201723] cloud-init[1017]: ================================================================================
[   28.201800] cloud-init[1017]: Upgrade  9 Packages
[   28.201905] cloud-init[1017]: Total download size: 11 M
[   28.201989] cloud-init[1017]: Downloading packages:
[   28.326916] cloud-init[1017]: Delta RPMs disabled because /usr/bin/applydeltarpm not installed.
[   28.579689] cloud-init[1017]: --------------------------------------------------------------------------------
[   28.581435] cloud-init[1017]: Total                                               45 MB/s |  11 MB  00:00
[   28.692086] cloud-init[1017]: Running transaction check
[   28.789143] cloud-init[1017]: Running transaction test
[   29.298684] cloud-init[1017]: Transaction test succeeded
[   29.299860] cloud-init[1017]: Running transaction
[   31.405796] cloud-init[1017]: Updating   : expat-2.1.0-15.amzn2.0.2.aarch64                            1/18
[   31.469522] cloud-init[1017]: Updating   : python3-libs-3.7.15-1.amzn2.0.2.aarch64                     2/18
[   31.489987] cloud-init[1017]: Updating   : python3-3.7.15-1.amzn2.0.2.aarch64                          3/18
[   31.518122] cloud-init[1017]: Updating   : 2:vim-data-9.0.828-1.amzn2.0.1.noarch                       4/18
[   31.583657] cloud-init[1017]: Updating   : 1:dbus-libs-1.10.24-7.amzn2.0.2.aarch64                     5/18
[   31.658373] cloud-init[1017]: Updating   : 1:dbus-1.10.24-7.amzn2.0.2.aarch64                          6/18
[   31.695361] cloud-init[1017]: Updating   : 2:vim-minimal-9.0.828-1.amzn2.0.1.aarch64                   7/18
[   31.725472] cloud-init[1017]: Updating   : libtiff-4.0.3-35.amzn2.0.5.aarch64                          8/18
[   31.746455] cloud-init[1017]: Updating   : kpartx-0.4.9-136.amzn2.aarch64                              9/18
[   31.911537] cloud-init[1017]: Cleanup    : 1:dbus-1.10.24-7.amzn2.aarch64                             10/18
[   31.962376] cloud-init[1017]: Cleanup    : python3-libs-3.7.10-1.amzn2.0.1.aarch64                    11/18
[   31.981387] cloud-init[1017]: Cleanup    : python3-3.7.10-1.amzn2.0.1.aarch64                         12/18
[   32.003257] cloud-init[1017]: Cleanup    : 2:vim-minimal-9.0.475-1.amzn2.0.1.aarch64                  13/18
[   32.021133] cloud-init[1017]: Cleanup    : 2:vim-data-9.0.475-1.amzn2.0.1.noarch                      14/18
[   32.049522] cloud-init[1017]: Cleanup    : expat-2.1.0-14.amzn2.0.1.aarch64                           15/18
[   32.075346] cloud-init[1017]: Cleanup    : 1:dbus-libs-1.10.24-7.amzn2.aarch64                        16/18
[   32.100039] cloud-init[1017]: Cleanup    : libtiff-4.0.3-35.amzn2.0.2.aarch64                         17/18
[   32.129002] cloud-init[1017]: Cleanup    : kpartx-0.4.9-127.amzn2.aarch64                             18/18
[  OK  ] Stopped Dynamically Generate Message Of The Day.
         Starting Dynamically Generate Message Of The Day...
[   32.148654] cloud-init[1017]: Verifying  : python3-3.7.15-1.amzn2.0.2.aarch64                          1/18
[   32.158132] cloud-init[1017]: Verifying  : kpartx-0.4.9-136.amzn2.aarch64                              2/18
[   32.168698] cloud-init[1017]: Verifying  : 2:vim-minimal-9.0.828-1.amzn2.0.1.aarch64                   3/18
[   32.178210] cloud-init[1017]: Verifying  : 1:dbus-libs-1.10.24-7.amzn2.0.2.aarch64                     4/18
[   32.186404] cloud-init[1017]: Verifying  : expat-2.1.0-15.amzn2.0.2.aarch64                            5/18
[   32.196219] cloud-init[1017]: Verifying  : 1:dbus-1.10.24-7.amzn2.0.2.aarch64                          6/18
[   32.206866] cloud-init[1017]: Verifying  : 2:vim-data-9.0.828-1.amzn2.0.1.noarch                       7/18
[   32.216599] cloud-init[1017]: Verifying  : python3-libs-3.7.15-1.amzn2.0.2.aarch64                     8/18
[   32.226516] cloud-init[1017]: Verifying  : libtiff-4.0.3-35.amzn2.0.5.aarch64                          9/18
[   32.228326] cloud-init[1017]: Verifying  : expat-2.1.0-14.amzn2.0.1.aarch64                           10/18
[   32.230777] cloud-init[1017]: Verifying  : libtiff-4.0.3-35.amzn2.0.2.aarch64                         11/18
[   32.232432] cloud-init[1017]: Verifying  : 1:dbus-libs-1.10.24-7.amzn2.aarch64                        12/18
[   32.234075] cloud-init[1017]: Verifying  : 1:dbus-1.10.24-7.amzn2.aarch64                             13/18
[   32.236239] cloud-init[1017]: Verifying  : python3-libs-3.7.10-1.amzn2.0.1.aarch64                    14/18
[   32.238536] cloud-init[1017]: Verifying  : 2:vim-minimal-9.0.475-1.amzn2.0.1.aarch64                  15/18
[   32.239495] cloud-init[1017]: Verifying  : 2:vim-data-9.0.475-1.amzn2.0.1.noarch                      16/18
[   32.240532] cloud-init[1017]: Verifying  : python3-3.7.10-1.amzn2.0.1.aarch64                         17/18
[   32.295782] cloud-init[1017]: Verifying  : kpartx-0.4.9-127.amzn2.aarch64                             18/18
[   32.297186] cloud-init[1017]: Updated:
[   32.297754] cloud-init[1017]: dbus.aarch64 1:1.10.24-7.amzn2.0.2
[   32.298583] cloud-init[1017]: dbus-libs.aarch64 1:1.10.24-7.amzn2.0.2
[   32.298677] cloud-init[1017]: expat.aarch64 0:2.1.0-15.amzn2.0.2
[   32.298760] cloud-init[1017]: kpartx.aarch64 0:0.4.9-136.amzn2
[   32.298841] cloud-init[1017]: libtiff.aarch64 0:4.0.3-35.amzn2.0.5
[   32.298922] cloud-init[1017]: python3.aarch64 0:3.7.15-1.amzn2.0.2
[   32.299001] cloud-init[1017]: python3-libs.aarch64 0:3.7.15-1.amzn2.0.2
[   32.299081] cloud-init[1017]: vim-data.noarch 2:9.0.828-1.amzn2.0.1
[   32.299157] cloud-init[1017]: vim-minimal.aarch64 2:9.0.828-1.amzn2.0.1
[   32.299663] cloud-init[1017]: Complete!
[  OK  ] Started Apply the settings specified in cloud-config.
         Starting Execute cloud user/final scripts...
[   32.711475] cloud-init[1158]: Cloud-init v. 19.3-46.amzn2 running 'modules:final' at Thu, 22 Dec 2022 11:27:48 +0000. Up 32.65 seconds.
[   32.724833] cloud-init[1158]: + ...
[   32.740995] cloud-init[1158]: + /etc/eks/bootstrap.sh eks-dev --b64-cluster-ca ...
[   33.602502] cloud-init[1158]: Using kubelet version 1.23.9
[   33.607378] cloud-init[1158]: Using dockerd as the container runtime
[   33.732573] cloud-init[1158]: ‘/etc/eks/iptables-restore.service’ -> ‘/etc/systemd/system/iptables-restore.service’
[  OK  ] Created slice User Slice of root.
[  OK  ] Started Session c1 of user root.
[  OK  ] Removed slice User Slice of root.
[   33.938975] cloud-init[1158]: Created symlink from /etc/systemd/system/multi-user.target.wants/iptables-restore.service to /etc/systemd/system/iptables-restore.service.
[   34.237686] cloud-init[1158]: Created symlink from /etc/systemd/system/multi-user.target.wants/docker.service to /usr/lib/systemd/system/docker.service.
         Starting containerd container runtime...
         Starting Docker Socket for the API.
[  OK  ] Listening on Docker Socket for the API.
[  OK  ] Started containerd container runtime.
         Starting Docker Application Container Engine...
[  OK  ] Started Dynamically Generate Message Of The Day.
[   36.493079] bpfilter: Loaded bpfilter_umh pid 1396
[   36.493253] Started bpfilter
[  OK  ] Started Docker Application Container Engine.
[  OK  ] Reached target Multi-User System.
[  OK  ] Reached target Graphical Interface.
         Starting Update UTMP about System Runlevel Changes...
[   37.211557] cloud-init[1158]: Created symlink from /etc/systemd/system/multi-user.target.wants/kubelet.service to /etc/systemd/system/kubelet.service.
[  OK  ] Started Update UTMP about System Runlevel Changes.
         Starting Kubernetes Kubelet...
[  OK  ] Started Kubernetes Kubelet.
[   37.334039] cloud-init[1158]: nvidia-smi not found
[   37.335593] cloud-init[1158]: ci-info: no authorized ssh keys fingerprints found for user ec2-user.
ci-info: no authorized ssh keys fingerprints found for user ec2-user.
<14>Dec 22 11:27:53 ec2: 
<14>Dec 22 11:27:53 ec2: #############################################################
<14>Dec 22 11:27:53 ec2: -----BEGIN SSH HOST KEY FINGERPRINTS-----
<14>Dec 22 11:27:53 ec2: -----END SSH HOST KEY FINGERPRINTS-----
<14>Dec 22 11:27:53 ec2: #############################################################
-----BEGIN SSH HOST KEY KEYS-----

[   37.378101] cloud-init[1158]: Cloud-init v. 19.3-46.amzn2 finished at Thu, 22 Dec 2022 11:27:53 +0000. Datasource DataSourceEc2.  Up 37.37 seconds
[  OK  ] Started Execute cloud user/final scripts.
[  OK  ] Reached target Cloud-init target.
[   40.497668] cgroup: cgroup: disabling cgroup2 socket matching due to net_prio or net_cls activation
[   42.459919] IPVS: Registered protocols (TCP, UDP, SCTP, AH, ESP)
[   42.460881] IPVS: Connection hash table configured (size=4096, memory=32Kbytes)
[   42.462066] IPVS: ipvs loaded.
[   42.465171] IPVS: [rr] scheduler registered.
[   42.469202] IPVS: [wrr] scheduler registered.
[   42.472244] IPVS: [sh] scheduler registered.
[   77.246088] xfs filesystem being remounted at /var/lib/kubelet/pods/4116baf8-8459-4e29-890d-bd4335b72a94/volume-subpaths/nri-kubernetes-config/kubelet/0 supports timestamps until 2038 (0x7fffffff)
[   97.473574] xfs filesystem being remounted at /var/lib/kubelet/pods/4116baf8-8459-4e29-890d-bd4335b72a94/volume-subpaths/config/agent/0 supports timestamps until 2038 (0x7fffffff)
njtran commented 1 year ago

Hey @royb-tabit, thanks for the loads of information! By chance do you know what you've changed since the setup to make your node startup time go from 60s to 100s? Have you changed the AMI, the user data, or added more pod/node constraints? If it hasn't been at 60s at all, that'd be good to know too.

royb-tabit commented 1 year ago

Hey @njtran, Thanks for your question. We never got to see karpenter finish at 60s, the only reference I have is our aws-node-autoscaler that use the same user-data and image. it take him about 65s-70s, and it seems that once the kube-proxy start (on aws-node-autoscaler) it gos to 'ready state' much faster.

bwagner5 commented 1 year ago

The discrepancy may be that Karpenter creates the node right when the instance is launched and the cluster-autoscaler will wait for the kubelet to come online to register the node with the API server which will make it look like the node came online faster, but the actual time between the EC2 instance being launched and the node going Ready should be mostly the same between Karpenter and Cluster Autoscaler.

royb-tabit commented 1 year ago

Hey @bwagner5, We started timing the cluster-autoscaler from the instance creation on AWS (it takes for the instance to register about 30s, after that about 25s for kube-proxy to start and 10s for the Node to be Ready - overall 65s)

bwagner5 commented 1 year ago

@royb-tabit Would you be able to run this node timing tool that we recently open sourced on both the node launched by Karpenter and the node launched by cluster-autoscaler? https://github.com/awslabs/node-latency-for-k8s

You can run the binary on the node after the instance is launched or you can run it as a DaemonSet. If you can post the timing chart that the tool produces on stdout, that may help narrow down the issue.

royb-tabit commented 1 year ago

Hey @bwagner5 , Sure that sounds great. I'll get back with the results.

royb-tabit commented 1 year ago

Hey @bwagner5 , I ran the DeamonSet, but it had some issues connecting the data, do you have an idea why?

EDIT: These logs are from Karpenter Node, I will make one for AWS ClusterAutoscaler as well.

2023/01/03 09:29:11 Unable to retrieve timing for Event "Kube-APIServer Throttled": no matches in /var/log/messages* for regex ".*Waited for .* due to client-side throttling, not priority and fairness, request: .*"
2023/01/03 09:29:11 Unable to retrieve timing for Event "Fleet Requested": operation error EC2: DescribeTags, failed to resolve service endpoint, an AWS region is required, but was not found
2023/01/03 09:29:11 Unable to retrieve timing for Event "Pod Ready": no matches in /var/log/messages* for regex ".*default/.* Type:ContainerStarted.*"
2023/01/03 09:29:17 Unable to retrieve timing for Event "Kube-APIServer Throttled": no matches in /var/log/messages* for regex ".*Waited for .* due to client-side throttling, not priority and fairness, request: .*"
2023/01/03 09:29:17 Unable to retrieve timing for Event "Fleet Requested": operation error EC2: DescribeTags, failed to resolve service endpoint, an AWS region is required, but was not found
2023/01/03 09:29:17 Unable to retrieve timing for Event "Pod Ready": no matches in /var/log/messages* for regex ".*default/.* Type:ContainerStarted.*"
2023/01/03 09:29:23 Unable to retrieve timing for Event "Kube-APIServer Throttled": no matches in /var/log/messages* for regex ".*Waited for .* due to client-side throttling, not priority and fairness, request: .*"
2023/01/03 09:29:23 Unable to retrieve timing for Event "Fleet Requested": operation error EC2: DescribeTags, failed to resolve service endpoint, an AWS region is required, but was not found
2023/01/03 09:29:23 Unable to retrieve timing for Event "Pod Ready": no matches in /var/log/messages* for regex ".*default/.* Type:ContainerStarted.*"
2023/01/03 09:29:29 Unable to retrieve timing for Event "Kube-APIServer Throttled": no matches in /var/log/messages* for regex ".*Waited for .* due to client-side throttling, not priority and fairness, request: .*"
2023/01/03 09:29:29 Unable to retrieve timing for Event "Fleet Requested": operation error EC2: DescribeTags, failed to resolve service endpoint, an AWS region is required, but was not found
2023/01/03 09:29:29 Unable to retrieve timing for Event "Pod Ready": no matches in /var/log/messages* for regex ".*default/.* Type:ContainerStarted.*"
2023/01/03 09:29:36 Unable to retrieve timing for Event "Kube-APIServer Throttled": no matches in /var/log/messages* for regex ".*Waited for .* due to client-side throttling, not priority and fairness, request: .*"
2023/01/03 09:29:36 Unable to retrieve timing for Event "Fleet Requested": operation error EC2: DescribeTags, failed to resolve service endpoint, an AWS region is required, but was not found
2023/01/03 09:29:36 Unable to retrieve timing for Event "Pod Ready": no matches in /var/log/messages* for regex ".*default/.* Type:ContainerStarted.*"
2023/01/03 09:29:41 unable to measure terminal events: []
2023/01/03 09:29:41 Error with event "Kube-APIServer Throttled" timing: no matches in /var/log/messages* for regex ".*Waited for .* due to client-side throttling, not priority and fairness, request: .*"
2023/01/03 09:29:41 Error with event "Fleet Requested" timing: operation error EC2: DescribeTags, failed to resolve service endpoint, an AWS region is required, but was not found
2023/01/03 09:29:41 Error with event "Pod Ready" timing: no matches in /var/log/messages* for regex ".*default/.* Type:ContainerStarted.*"
2023/01/03 09:29:41 Error emitting CloudWatch metrics: operation error CloudWatch: PutMetricData, failed to resolve service endpoint, an AWS region is required, but was not found; operation error CloudWatch: PutMetricData, failed to resolve service endpoint, an AWS region is required, but was not found; operation error CloudWatch: PutMetricData, failed to resolve service endpoint, an AWS region is required, but was not found; operation error CloudWatch: PutMetricData, failed to resolve service endpoint, an AWS region is required, but was not found; operation error CloudWatch: PutMetricData, failed to resolve service endpoint, an AWS region is required, but was not found; operation error CloudWatch: PutMetricData, failed to resolve service endpoint, an AWS region is required, but was not found; operation error CloudWatch: PutMetricData, failed to resolve service endpoint, an AWS region is required, but was not found; operation error CloudWatch: PutMetricData, failed to resolve service endpoint, an AWS region is required, but was not found; operation error CloudWatch: PutMetricData, failed to resolve service endpoint, an AWS region is required, but was not found; operation error CloudWatch: PutMetricData, failed to resolve service endpoint, an AWS region is required, but was not found; operation error CloudWatch: PutMetricData, failed to resolve service endpoint, an AWS region is required, but was not found; operation error CloudWatch: PutMetricData, failed to resolve service endpoint, an AWS region is required, but was not found; operation error CloudWatch: PutMetricData, failed to resolve service endpoint, an AWS region is required, but was not found; operation error CloudWatch: PutMetricData, failed to resolve service endpoint, an AWS region is required, but was not found; operation error CloudWatch: PutMetricData, failed to resolve service endpoint, an AWS region is required, but was not found; operation error CloudWatch: PutMetricData, failed to resolve service endpoint, an AWS region is required, but was not found; operation error CloudWatch: PutMetricData, failed to resolve service endpoint, an AWS region is required, but was not found; operation error CloudWatch: PutMetricData, failed to resolve service endpoint, an AWS region is required, but was not found; operation error CloudWatch: PutMetricData, failed to resolve service endpoint, an AWS region is required, but was not found; operation error CloudWatch: PutMetricData, failed to resolve service endpoint, an AWS region is required, but was not found; operation error CloudWatch: PutMetricData, failed to resolve service endpoint, an AWS region is required, but was not found; operation error CloudWatch: PutMetricData, failed to resolve service endpoint, an AWS region is required, but was not found
2023/01/03 09:29:41 Serving Prometheus metrics on :2112
### i-03ede22dbea2d9533 (10.2.25.151) | t3a.large | x86_64 | eu-west-1c | ami-0b55230f107a87100
|           EVENT            |      TIMESTAMP       |      T      | COMMENT |
|----------------------------|----------------------|-------------|---------|
| Pod Created                | 0001-01-01T00:00:00Z | 0s          |         |
| Instance Pending           | 2023-01-03T09:27:38Z | 9223372037s |         |
| VM Initialized             | 2023-01-03T09:27:48Z | 9223372037s |         |
| Network Start              | 2023-01-03T09:27:58Z | 9223372037s |         |
| Network Ready              | 2023-01-03T09:27:59Z | 9223372037s |         |
| Cloud-Init Initial Start   | 2023-01-03T09:27:59Z | 9223372037s |         |
| Cloud-Init Config Start    | 2023-01-03T09:28:01Z | 9223372037s |         |
| Cloud-Init Final Start     | 2023-01-03T09:28:17Z | 9223372037s |         |
| Containerd Start           | 2023-01-03T09:28:24Z | 9223372037s |         |
| Containerd Initialized     | 2023-01-03T09:28:27Z | 9223372037s |         |
| Kubelet Start              | 2023-01-03T09:28:32Z | 9223372037s |         |
| Cloud-Init Final Finish    | 2023-01-03T09:28:32Z | 9223372037s |         |
| Kubelet Initialized        | 2023-01-03T09:28:38Z | 9223372037s |         |
| Kubelet Registered         | 2023-01-03T09:28:39Z | 9223372037s |         |
| Kube-Proxy Start           | 2023-01-03T09:28:43Z | 9223372037s |         |
| VPC CNI Init Start         | 2023-01-03T09:28:47Z | 9223372037s |         |
| AWS Node Start             | 2023-01-03T09:28:57Z | 9223372037s |         |
| VPC CNI Plugin Initialized | 2023-01-03T09:28:58Z | 9223372037s |         |
| Node Ready                 | 2023-01-03T09:29:10Z | 9223372037s |         |
royb-tabit commented 1 year ago

These are the AWS ClusterAutoscaler logs:

2023/01/03 10:22:35 Unable to retrieve timing for Event "Kube-Proxy Start": no matches in /var/log/messages* for regex ".*CreateContainer within sandbox .*Name:kube-proxy.* returns container id.*"
2023/01/03 10:22:35 Unable to retrieve timing for Event "Fleet Requested": operation error EC2: DescribeTags, failed to resolve service endpoint, an AWS region is required, but was not found
2023/01/03 10:22:35 Unable to retrieve timing for Event "Pod Ready": no matches in /var/log/messages* for regex ".*default/.* Type:ContainerStarted.*"
2023/01/03 10:22:35 Unable to retrieve timing for Event "Kube-APIServer Throttled": no matches in /var/log/messages* for regex ".*Waited for .* due to client-side throttling, not priority and fairness, request: .*"
2023/01/03 10:22:35 Unable to retrieve timing for Event "VPC CNI Plugin Initialized": unable to open log file /var/log/pods/kube-system_aws-node-kg5w6_8db9b5c6-2a38-43f7-950f-85ee79e15338/aws-node/0.log: open /var/log/pods/kube-system_aws-node-kg5w6_8db9b5c6-2a38-43f7-950f-85ee79e15338/aws-node/0.log: no such file or directory
2023/01/03 10:22:35 Unable to retrieve timing for Event "AWS Node Start": no matches in /var/log/messages* for regex ".*CreateContainer within sandbox .*Name:aws-node.* returns container id.*"
2023/01/03 10:22:35 Unable to retrieve timing for Event "VPC CNI Init Start": no matches in /var/log/messages* for regex ".*CreateContainer within sandbox .*Name:aws-vpc-cni-init.* returns container id.*"
2023/01/03 10:22:40 Unable to retrieve timing for Event "Kube-Proxy Start": no matches in /var/log/messages* for regex ".*CreateContainer within sandbox .*Name:kube-proxy.* returns container id.*"
2023/01/03 10:22:40 Unable to retrieve timing for Event "Fleet Requested": operation error EC2: DescribeTags, failed to resolve service endpoint, an AWS region is required, but was not found
2023/01/03 10:22:40 Unable to retrieve timing for Event "Pod Ready": no matches in /var/log/messages* for regex ".*default/.* Type:ContainerStarted.*"
2023/01/03 10:22:40 Unable to retrieve timing for Event "Kube-APIServer Throttled": no matches in /var/log/messages* for regex ".*Waited for .* due to client-side throttling, not priority and fairness, request: .*"
2023/01/03 10:22:40 Unable to retrieve timing for Event "VPC CNI Plugin Initialized": unable to open log file /var/log/pods/kube-system_aws-node-kg5w6_8db9b5c6-2a38-43f7-950f-85ee79e15338/aws-node/0.log: open /var/log/pods/kube-system_aws-node-kg5w6_8db9b5c6-2a38-43f7-950f-85ee79e15338/aws-node/0.log: no such file or directory
2023/01/03 10:22:40 Unable to retrieve timing for Event "AWS Node Start": no matches in /var/log/messages* for regex ".*CreateContainer within sandbox .*Name:aws-node.* returns container id.*"
2023/01/03 10:22:40 Unable to retrieve timing for Event "VPC CNI Init Start": no matches in /var/log/messages* for regex ".*CreateContainer within sandbox .*Name:aws-vpc-cni-init.* returns container id.*"
2023/01/03 10:22:45 Unable to retrieve timing for Event "Kube-Proxy Start": no matches in /var/log/messages* for regex ".*CreateContainer within sandbox .*Name:kube-proxy.* returns container id.*"
2023/01/03 10:22:45 Unable to retrieve timing for Event "Fleet Requested": operation error EC2: DescribeTags, failed to resolve service endpoint, an AWS region is required, but was not found
2023/01/03 10:22:45 Unable to retrieve timing for Event "Pod Ready": no matches in /var/log/messages* for regex ".*default/.* Type:ContainerStarted.*"
2023/01/03 10:22:45 Unable to retrieve timing for Event "Kube-APIServer Throttled": no matches in /var/log/messages* for regex ".*Waited for .* due to client-side throttling, not priority and fairness, request: .*"
2023/01/03 10:22:45 Unable to retrieve timing for Event "VPC CNI Plugin Initialized": unable to open log file /var/log/pods/kube-system_aws-node-kg5w6_8db9b5c6-2a38-43f7-950f-85ee79e15338/aws-node/0.log: open /var/log/pods/kube-system_aws-node-kg5w6_8db9b5c6-2a38-43f7-950f-85ee79e15338/aws-node/0.log: no such file or directory
2023/01/03 10:22:45 Unable to retrieve timing for Event "AWS Node Start": no matches in /var/log/messages* for regex ".*CreateContainer within sandbox .*Name:aws-node.* returns container id.*"
2023/01/03 10:22:45 Unable to retrieve timing for Event "VPC CNI Init Start": no matches in /var/log/messages* for regex ".*CreateContainer within sandbox .*Name:aws-vpc-cni-init.* returns container id.*"
2023/01/03 10:22:51 Unable to retrieve timing for Event "Kube-Proxy Start": no matches in /var/log/messages* for regex ".*CreateContainer within sandbox .*Name:kube-proxy.* returns container id.*"
2023/01/03 10:22:51 Unable to retrieve timing for Event "Fleet Requested": operation error EC2: DescribeTags, failed to resolve service endpoint, an AWS region is required, but was not found
2023/01/03 10:22:51 Unable to retrieve timing for Event "Pod Ready": no matches in /var/log/messages* for regex ".*default/.* Type:ContainerStarted.*"
2023/01/03 10:22:51 Unable to retrieve timing for Event "Kube-APIServer Throttled": no matches in /var/log/messages* for regex ".*Waited for .* due to client-side throttling, not priority and fairness, request: .*"
2023/01/03 10:22:51 Unable to retrieve timing for Event "VPC CNI Plugin Initialized": unable to open log file /var/log/pods/kube-system_aws-node-kg5w6_8db9b5c6-2a38-43f7-950f-85ee79e15338/aws-node/0.log: open /var/log/pods/kube-system_aws-node-kg5w6_8db9b5c6-2a38-43f7-950f-85ee79e15338/aws-node/0.log: no such file or directory
2023/01/03 10:22:51 Unable to retrieve timing for Event "AWS Node Start": no matches in /var/log/messages* for regex ".*CreateContainer within sandbox .*Name:aws-node.* returns container id.*"
2023/01/03 10:22:51 Unable to retrieve timing for Event "VPC CNI Init Start": no matches in /var/log/messages* for regex ".*CreateContainer within sandbox .*Name:aws-vpc-cni-init.* returns container id.*"
2023/01/03 10:22:56 Unable to retrieve timing for Event "Kube-Proxy Start": no matches in /var/log/messages* for regex ".*CreateContainer within sandbox .*Name:kube-proxy.* returns container id.*"
2023/01/03 10:22:56 Unable to retrieve timing for Event "Fleet Requested": operation error EC2: DescribeTags, failed to resolve service endpoint, an AWS region is required, but was not found
2023/01/03 10:22:56 Unable to retrieve timing for Event "Pod Ready": no matches in /var/log/messages* for regex ".*default/.* Type:ContainerStarted.*"
2023/01/03 10:22:56 Unable to retrieve timing for Event "Kube-APIServer Throttled": no matches in /var/log/messages* for regex ".*Waited for .* due to client-side throttling, not priority and fairness, request: .*"
2023/01/03 10:22:56 Unable to retrieve timing for Event "VPC CNI Plugin Initialized": unable to open log file /var/log/pods/kube-system_aws-node-kg5w6_8db9b5c6-2a38-43f7-950f-85ee79e15338/aws-node/0.log: open /var/log/pods/kube-system_aws-node-kg5w6_8db9b5c6-2a38-43f7-950f-85ee79e15338/aws-node/0.log: no such file or directory
2023/01/03 10:22:56 Unable to retrieve timing for Event "AWS Node Start": no matches in /var/log/messages* for regex ".*CreateContainer within sandbox .*Name:aws-node.* returns container id.*"
2023/01/03 10:22:56 Unable to retrieve timing for Event "VPC CNI Init Start": no matches in /var/log/messages* for regex ".*CreateContainer within sandbox .*Name:aws-vpc-cni-init.* returns container id.*"
2023/01/03 10:23:01 Unable to retrieve timing for Event "Kube-Proxy Start": no matches in /var/log/messages* for regex ".*CreateContainer within sandbox .*Name:kube-proxy.* returns container id.*"
2023/01/03 10:23:01 Unable to retrieve timing for Event "Fleet Requested": operation error EC2: DescribeTags, failed to resolve service endpoint, an AWS region is required, but was not found
2023/01/03 10:23:01 Unable to retrieve timing for Event "Pod Ready": no matches in /var/log/messages* for regex ".*default/.* Type:ContainerStarted.*"
2023/01/03 10:23:01 Unable to retrieve timing for Event "Kube-APIServer Throttled": no matches in /var/log/messages* for regex ".*Waited for .* due to client-side throttling, not priority and fairness, request: .*"
2023/01/03 10:23:01 Unable to retrieve timing for Event "VPC CNI Plugin Initialized": unable to open log file /var/log/pods/kube-system_aws-node-kg5w6_8db9b5c6-2a38-43f7-950f-85ee79e15338/aws-node/0.log: open /var/log/pods/kube-system_aws-node-kg5w6_8db9b5c6-2a38-43f7-950f-85ee79e15338/aws-node/0.log: no such file or directory
2023/01/03 10:23:01 Unable to retrieve timing for Event "AWS Node Start": no matches in /var/log/messages* for regex ".*CreateContainer within sandbox .*Name:aws-node.* returns container id.*"
2023/01/03 10:23:01 Unable to retrieve timing for Event "VPC CNI Init Start": no matches in /var/log/messages* for regex ".*CreateContainer within sandbox .*Name:aws-vpc-cni-init.* returns container id.*"
2023/01/03 10:23:06 unable to measure terminal events: []
### i-07d24f53e7c1c879b (10.2.22.234) | t2.large | x86_64 | eu-west-1b | ami-0de933c15c9b49fb5
2023/01/03 10:23:06 Error with event "Kube-Proxy Start" timing: no matches in /var/log/messages* for regex ".*CreateContainer within sandbox .*Name:kube-proxy.* returns container id.*"
2023/01/03 10:23:06 Error with event "Fleet Requested" timing: operation error EC2: DescribeTags, failed to resolve service endpoint, an AWS region is required, but was not found
2023/01/03 10:23:06 Error with event "Pod Ready" timing: no matches in /var/log/messages* for regex ".*default/.* Type:ContainerStarted.*"
2023/01/03 10:23:06 Error with event "Kube-APIServer Throttled" timing: no matches in /var/log/messages* for regex ".*Waited for .* due to client-side throttling, not priority and fairness, request: .*"
2023/01/03 10:23:06 Error with event "VPC CNI Plugin Initialized" timing: unable to open log file /var/log/pods/kube-system_aws-node-kg5w6_8db9b5c6-2a38-43f7-950f-85ee79e15338/aws-node/0.log: open /var/log/pods/kube-system_aws-node-kg5w6_8db9b5c6-2a38-43f7-950f-85ee79e15338/aws-node/0.log: no such file or directory
2023/01/03 10:23:06 Error with event "AWS Node Start" timing: no matches in /var/log/messages* for regex ".*CreateContainer within sandbox .*Name:aws-node.* returns container id.*"
2023/01/03 10:23:06 Error with event "VPC CNI Init Start" timing: no matches in /var/log/messages* for regex ".*CreateContainer within sandbox .*Name:aws-vpc-cni-init.* returns container id.*"
|          EVENT           |      TIMESTAMP       |      T      | COMMENT |
|--------------------------|----------------------|-------------|---------|
| Pod Created              | 0001-01-01T00:00:00Z | 0s          |         |
| Instance Pending         | 2023-01-03T10:20:59Z | 9223372037s |         |
| VM Initialized           | 2023-01-03T10:21:15Z | 9223372037s |         |
| Network Ready            | 2023-01-03T10:21:19Z | 9223372037s |         |
| Cloud-Init Initial Start | 2023-01-03T10:21:19Z | 9223372037s |         |
| Network Start            | 2023-01-03T10:21:19Z | 9223372037s |         |
| Cloud-Init Config Start  | 2023-01-03T10:21:21Z | 9223372037s |         |
| Cloud-Init Final Start   | 2023-01-03T10:21:32Z | 9223372037s |         |
| Containerd Start         | 2023-01-03T10:21:34Z | 9223372037s |         |
| Containerd Initialized   | 2023-01-03T10:21:35Z | 9223372037s |         |
| Kubelet Start            | 2023-01-03T10:21:38Z | 9223372037s |         |
| Cloud-Init Final Finish  | 2023-01-03T10:21:38Z | 9223372037s |         |
| Kubelet Initialized      | 2023-01-03T10:21:39Z | 9223372037s |         |
| Kubelet Registered       | 2023-01-03T10:21:39Z | 9223372037s |         |
| Node Ready               | 2023-01-03T10:22:10Z | 9223372037s |         |
2023/01/03 10:23:06 Error emitting CloudWatch metrics: operation error CloudWatch: PutMetricData, failed to resolve service endpoint, an AWS region is required, but was not found; operation error CloudWatch: PutMetricData, failed to resolve service endpoint, an AWS region is required, but was not found; operation error CloudWatch: PutMetricData, failed to resolve service endpoint, an AWS region is required, but was not found; operation error CloudWatch: PutMetricData, failed to resolve service endpoint, an AWS region is required, but was not found; operation error CloudWatch: PutMetricData, failed to resolve service endpoint, an AWS region is required, but was not found; operation error CloudWatch: PutMetricData, failed to resolve service endpoint, an AWS region is required, but was not found; operation error CloudWatch: PutMetricData, failed to resolve service endpoint, an AWS region is required, but was not found; operation error CloudWatch: PutMetricData, failed to resolve service endpoint, an AWS region is required, but was not found; operation error CloudWatch: PutMetricData, failed to resolve service endpoint, an AWS region is required, but was not found; operation error CloudWatch: PutMetricData, failed to resolve service endpoint, an AWS region is required, but was not found; operation error CloudWatch: PutMetricData, failed to resolve service endpoint, an AWS region is required, but was not found; operation error CloudWatch: PutMetricData, failed to resolve service endpoint, an AWS region is required, but was not found; operation error CloudWatch: PutMetricData, failed to resolve service endpoint, an AWS region is required, but was not found; operation error CloudWatch: PutMetricData, failed to resolve service endpoint, an AWS region is required, but was not found; operation error CloudWatch: PutMetricData, failed to resolve service endpoint, an AWS region is required, but was not found; operation error CloudWatch: PutMetricData, failed to resolve service endpoint, an AWS region is required, but was not found; operation error CloudWatch: PutMetricData, failed to resolve service endpoint, an AWS region is required, but was not found; operation error CloudWatch: PutMetricData, failed to resolve service endpoint, an AWS region is required, but was not found; operation error CloudWatch: PutMetricData, failed to resolve service endpoint, an AWS region is required, but was not found; operation error CloudWatch: PutMetricData, failed to resolve service endpoint, an AWS region is required, but was not found; operation error CloudWatch: PutMetricData, failed to resolve service endpoint, an AWS region is required, but was not found; operation error CloudWatch: PutMetricData, failed to resolve service endpoint, an AWS region is required, but was not found
2023/01/03 10:23:06 Serving Prometheus metrics on :2112
ellistarn commented 1 year ago

AWS region is required

@bwagner5 is more familiar, but maybe there's a way to set this?

bwagner5 commented 1 year ago

Looks like it doesn't have permissions to access the K8s API or AWS APIs. Looks like I missed a README update when I added those events, so you'd need to install it with an IAM role for those events to work.

But most of the data is here.

Cluster Autoscaler Launch-to-Ready:

EVENT TIMESTAMP T COMMENT
Instance Pending 2023-01-03T10:20:59Z 0s
VM Initialized 2023-01-03T10:21:15Z 16s
Network Ready 2023-01-03T10:21:19Z 20s
Cloud-Init Initial Start 2023-01-03T10:21:19Z 20s
Network Start 2023-01-03T10:21:19Z 20s
Cloud-Init Config Start 2023-01-03T10:21:21Z 22s
Cloud-Init Final Start 2023-01-03T10:21:32Z 33s
Containerd Start 2023-01-03T10:21:34Z 35s
Containerd Initialized 2023-01-03T10:21:35Z 36s
Kubelet Start 2023-01-03T10:21:38Z 39s
Cloud-Init Final Finish 2023-01-03T10:21:38Z 39s
Kubelet Initialized 2023-01-03T10:21:39Z 40s
Kubelet Registered 2023-01-03T10:21:39Z 40s
Node Ready 2023-01-03T10:22:10Z 71s

Karpenter Launch-to-Ready:

EVENT TIMESTAMP T COMMENT
Instance Pending 2023-01-03T09:27:38Z 0s
VM Initialized 2023-01-03T09:27:48Z 10s
Network Start 2023-01-03T09:27:58Z 20s
Network Ready 2023-01-03T09:27:59Z 21s
Cloud-Init Initial Start 2023-01-03T09:27:59Z 21s
Cloud-Init Config Start 2023-01-03T09:28:01Z 23s
Cloud-Init Final Start 2023-01-03T09:28:17Z 39s
Containerd Start 2023-01-03T09:28:24Z 46s
Containerd Initialized 2023-01-03T09:28:27Z 49s
Kubelet Start 2023-01-03T09:28:32Z 54s
Cloud-Init Final Finish 2023-01-03T09:28:32Z 54s
Kubelet Initialized 2023-01-03T09:28:38Z 60s
Kubelet Registered 2023-01-03T09:28:39Z 61s
Kube-Proxy Start 2023-01-03T09:28:43Z 65s
VPC CNI Init Start 2023-01-03T09:28:47Z 69s
AWS Node Start 2023-01-03T09:28:57Z 79s
VPC CNI Plugin Initialized 2023-01-03T09:28:58Z 80s
Node Ready 2023-01-03T09:29:10Z 92s

It looks like different AMIs are being used between the CA and Karpenter nodes. The Karpenter one appears to be a slightly older EKS Optimized AL2 AMI compared to the CA one.

One notable different in latency is between the Cloud-init Final Start and Containerd Start (2s vs 7s). Is there a difference in the user-data that is used between CA and Karpenter?

It looks like the CNI wasn't picked up by the node latency tool for Cluster Autoscaler. Are the nodes launched with Cluster Autoscaler using the VPC CNI with a default setup?

I'll also note that t* instance types can have variable startup times. I'd be curious if you see better results on an m6i.large or similar (non-burstable) instance type.

sidewinder12s commented 1 year ago

Latest versions of the EKS AMI and the VPC CNI have some optimizations around startup and they appear to actively be tackling startup time.

https://github.com/aws/amazon-vpc-cni-k8s/pull/2138

https://github.com/awslabs/amazon-eks-ami/issues/1099

github-actions[bot] commented 1 year ago

Labeled for closure due to inactivity in 10 days.