search

kubernetes-sigs / cloud-provider-equinix-metal

Kubernetes Cloud Provider for Equinix Metal (formerly Packet Cloud Controller Manager)
https://deploy.equinix.com/labs/cloud-provider-equinix-metal
Apache License 2.0
74 stars 27 forks source link

CCM only requests IPs once for a given service #206

Closed vasu1124 closed 2 years ago

vasu1124 commented 3 years ago

If you give the IP back (set the service to ClusterIP), the IP request is deleted properly after some time. But if you then request the LoadBalancer again, you get the same IP in K8s (state is somewhere cached?), but the CCM does not request a working IP from the IPAM (dashboard is empty). And of course the "re-used" IP does not work.

deitch commented 3 years ago

Can you give a step-by-step guide to reproducing this one? And if you are able to reproduce it, logs from CCM with --v=5 would help.

vasu1124 commented 3 years ago

As requested:

    spec:
      containers:
      - command:
        - ./cloud-provider-equinix-metal
        - --cloud-provider=equinixmetal
        - --leader-elect=false
        - --allow-untagged-cloud=true
        - --authentication-skip-lookup=true
        - --kubeconfig=/var/lib/cloud-controller-manager/kubeconfig
        - --v=5
        env:
        - name: METAL_API_KEY
          valueFrom:
            secretKeyRef:
              key: apiToken
              name: cloudprovider
        - name: METAL_PROJECT_ID
          valueFrom:
            secretKeyRef:
              key: projectID
              name: cloudprovider
        - name: METAL_FACILITY_NAME
          value: ewr1
        - name: METAL_LOAD_BALANCER
          value: metallb:///
        image: docker.io/equinix/cloud-provider-equinix-metal:v3.2.0
        imagePullPolicy: IfNotPresent
        name: cloud-provider-equinix-metal

(I used v3.2.0, the same effect is with v3.2.2)

Flag --allow-untagged-cloud has been deprecated, This flag is deprecated and will be removed in a future release. A cluster-id will be required on cloud instances.
I1005 13:56:38.707240       1 main.go:240] authToken: '<masked>'
I1005 13:56:38.707274       1 main.go:240] projectID: '************************************'
I1005 13:56:38.707278       1 main.go:240] load balancer config: ''%!s(MISSING)
I1005 13:56:38.707284       1 main.go:240] metallb:///
I1005 13:56:38.707288       1 main.go:240] facility: 'ewr1'
I1005 13:56:38.707293       1 main.go:240] local ASN: '65000'
I1005 13:56:38.707296       1 main.go:240] Elastic IP Tag: ''
I1005 13:56:38.707300       1 main.go:240] API Server Port: '0'
I1005 13:56:38.707304       1 main.go:240] BGP Node Selector: ''
I1005 13:56:38.707367       1 plugins.go:61] Registered cloud provider "equinixmetal"
Flag --allow-untagged-cloud has been deprecated, This flag is deprecated and will be removed in a future release. A cluster-id will be required on cloud instances.
Flag --allow-untagged-cloud has been deprecated, This flag is deprecated and will be removed in a future release. A cluster-id will be required on cloud instances.
I1005 13:56:38.707632       1 flags.go:59] FLAG: --add-dir-header="false"
I1005 13:56:38.707647       1 flags.go:59] FLAG: --address="0.0.0.0"
I1005 13:56:38.707652       1 flags.go:59] FLAG: --allocate-node-cidrs="false"
I1005 13:56:38.707656       1 flags.go:59] FLAG: --allow-untagged-cloud="true"
I1005 13:56:38.707659       1 flags.go:59] FLAG: --alsologtostderr="false"
I1005 13:56:38.707664       1 flags.go:59] FLAG: --authentication-kubeconfig=""
I1005 13:56:38.707675       1 flags.go:59] FLAG: --authentication-skip-lookup="true"
I1005 13:56:38.707680       1 flags.go:59] FLAG: --authentication-token-webhook-cache-ttl="10s"
I1005 13:56:38.707691       1 flags.go:59] FLAG: --authentication-tolerate-lookup-failure="false"
I1005 13:56:38.707696       1 flags.go:59] FLAG: --authorization-always-allow-paths="[/healthz]"
I1005 13:56:38.707710       1 flags.go:59] FLAG: --authorization-kubeconfig=""
I1005 13:56:38.707715       1 flags.go:59] FLAG: --authorization-webhook-cache-authorized-ttl="10s"
I1005 13:56:38.707720       1 flags.go:59] FLAG: --authorization-webhook-cache-unauthorized-ttl="10s"
I1005 13:56:38.707725       1 flags.go:59] FLAG: --bind-address="0.0.0.0"
I1005 13:56:38.707731       1 flags.go:59] FLAG: --cert-dir=""
I1005 13:56:38.707736       1 flags.go:59] FLAG: --cidr-allocator-type="RangeAllocator"
I1005 13:56:38.707741       1 flags.go:59] FLAG: --client-ca-file=""
I1005 13:56:38.707746       1 flags.go:59] FLAG: --cloud-config=""
I1005 13:56:38.707751       1 flags.go:59] FLAG: --cloud-provider="equinixmetal"
I1005 13:56:38.707756       1 flags.go:59] FLAG: --cluster-cidr=""
I1005 13:56:38.707760       1 flags.go:59] FLAG: --cluster-name="kubernetes"
I1005 13:56:38.707766       1 flags.go:59] FLAG: --concurrent-service-syncs="1"
I1005 13:56:38.707772       1 flags.go:59] FLAG: --configure-cloud-routes="true"
I1005 13:56:38.707777       1 flags.go:59] FLAG: --contention-profiling="false"
I1005 13:56:38.707783       1 flags.go:59] FLAG: --controller-start-interval="0s"
I1005 13:56:38.707788       1 flags.go:59] FLAG: --controllers="[*]"
I1005 13:56:38.707801       1 flags.go:59] FLAG: --external-cloud-volume-plugin=""
I1005 13:56:38.707806       1 flags.go:59] FLAG: --feature-gates=""
I1005 13:56:38.707814       1 flags.go:59] FLAG: --help="false"
I1005 13:56:38.707819       1 flags.go:59] FLAG: --http2-max-streams-per-connection="0"
I1005 13:56:38.707825       1 flags.go:59] FLAG: --kube-api-burst="30"
I1005 13:56:38.707833       1 flags.go:59] FLAG: --kube-api-content-type="application/vnd.kubernetes.protobuf"
I1005 13:56:38.707839       1 flags.go:59] FLAG: --kube-api-qps="20"
I1005 13:56:38.707854       1 flags.go:59] FLAG: --kubeconfig="/var/lib/cloud-controller-manager/kubeconfig"
I1005 13:56:38.707864       1 flags.go:59] FLAG: --leader-elect="false"
I1005 13:56:38.707877       1 flags.go:59] FLAG: --leader-elect-lease-duration="15s"
I1005 13:56:38.707882       1 flags.go:59] FLAG: --leader-elect-renew-deadline="10s"
I1005 13:56:38.707888       1 flags.go:59] FLAG: --leader-elect-resource-lock="endpointsleases"
I1005 13:56:38.707892       1 flags.go:59] FLAG: --leader-elect-resource-name="cloud-controller-manager"
I1005 13:56:38.707896       1 flags.go:59] FLAG: --leader-elect-resource-namespace="kube-system"
I1005 13:56:38.707899       1 flags.go:59] FLAG: --leader-elect-retry-period="2s"
I1005 13:56:38.707905       1 flags.go:59] FLAG: --log-backtrace-at=":0"
I1005 13:56:38.707920       1 flags.go:59] FLAG: --log-dir=""
I1005 13:56:38.707925       1 flags.go:59] FLAG: --log-file=""
I1005 13:56:38.707929       1 flags.go:59] FLAG: --log-file-max-size="1800"
I1005 13:56:38.707941       1 flags.go:59] FLAG: --log-flush-frequency="5s"
I1005 13:56:38.707946       1 flags.go:59] FLAG: --logtostderr="true"
I1005 13:56:38.707951       1 flags.go:59] FLAG: --master=""
I1005 13:56:38.707956       1 flags.go:59] FLAG: --min-resync-period="12h0m0s"
I1005 13:56:38.707966       1 flags.go:59] FLAG: --node-monitor-period="5s"
I1005 13:56:38.707969       1 flags.go:59] FLAG: --node-status-update-frequency="5m0s"
I1005 13:56:38.707974       1 flags.go:59] FLAG: --node-sync-period="0s"
I1005 13:56:38.707978       1 flags.go:59] FLAG: --one-output="false"
I1005 13:56:38.707983       1 flags.go:59] FLAG: --permit-port-sharing="false"
I1005 13:56:38.707993       1 flags.go:59] FLAG: --port="0"
I1005 13:56:38.707996       1 flags.go:59] FLAG: --profiling="true"
I1005 13:56:38.707999       1 flags.go:59] FLAG: --provider-config=""
I1005 13:56:38.708004       1 flags.go:59] FLAG: --requestheader-allowed-names="[]"
I1005 13:56:38.708015       1 flags.go:59] FLAG: --requestheader-client-ca-file=""
I1005 13:56:38.708019       1 flags.go:59] FLAG: --requestheader-extra-headers-prefix="[x-remote-extra-]"
I1005 13:56:38.708026       1 flags.go:59] FLAG: --requestheader-group-headers="[x-remote-group]"
I1005 13:56:38.708042       1 flags.go:59] FLAG: --requestheader-username-headers="[x-remote-user]"
I1005 13:56:38.708054       1 flags.go:59] FLAG: --route-reconciliation-period="10s"
I1005 13:56:38.708060       1 flags.go:59] FLAG: --secure-port="10258"
I1005 13:56:38.708064       1 flags.go:59] FLAG: --skip-headers="false"
I1005 13:56:38.708069       1 flags.go:59] FLAG: --skip-log-headers="false"
I1005 13:56:38.708073       1 flags.go:59] FLAG: --stderrthreshold="2"
I1005 13:56:38.708076       1 flags.go:59] FLAG: --tls-cert-file=""
I1005 13:56:38.708079       1 flags.go:59] FLAG: --tls-cipher-suites="[]"
I1005 13:56:38.708082       1 flags.go:59] FLAG: --tls-min-version=""
I1005 13:56:38.708085       1 flags.go:59] FLAG: --tls-private-key-file=""
I1005 13:56:38.708088       1 flags.go:59] FLAG: --tls-sni-cert-key="[]"
I1005 13:56:38.708092       1 flags.go:59] FLAG: --use-service-account-credentials="false"
I1005 13:56:38.708095       1 flags.go:59] FLAG: --v="5"
I1005 13:56:38.708098       1 flags.go:59] FLAG: --version="false"
I1005 13:56:38.708103       1 flags.go:59] FLAG: --vmodule=""
I1005 13:56:39.802035       1 serving.go:331] Generated self-signed cert in-memory
I1005 13:56:40.597348       1 controllermanager.go:127] Version: v0.0.0-master+$Format:%h$
I1005 13:56:40.597422       1 cloud.go:186] called HasClusterID
I1005 13:56:40.597490       1 healthz.go:158] No default health checks specified. Installing the ping handler.
I1005 13:56:40.597681       1 healthz.go:162] Installing health checkers for (/healthz): "ping"
I1005 13:56:40.598427       1 tlsconfig.go:200] loaded serving cert ["Generated self signed cert"]: "localhost@1633442199" [serving] validServingFor=[127.0.0.1,localhost,localhost] issuer="localhost-ca@1633442199" (2021-10-05 12:56:38 +0000 UTC to 2022-10-05 12:56:38 +0000 UTC (now=2021-10-05 13:56:40.598405749 +0000 UTC))
I1005 13:56:40.598595       1 named_certificates.go:53] loaded SNI cert [0/"self-signed loopback"]: "apiserver-loopback-client@1633442200" [serving] validServingFor=[apiserver-loopback-client] issuer="apiserver-loopback-client-ca@1633442200" (2021-10-05 12:56:39 +0000 UTC to 2022-10-05 12:56:39 +0000 UTC (now=2021-10-05 13:56:40.598587948 +0000 UTC))
I1005 13:56:40.598620       1 secure_serving.go:197] Serving securely on [::]:10258
I1005 13:56:40.598633       1 cloud.go:107] called Initialize
I1005 13:56:40.598700       1 tlsconfig.go:240] Starting DynamicServingCertificateController
I1005 13:56:40.598825       1 loadbalancers.go:44] loadBalancers.init(): started
I1005 13:56:40.607950       1 loadbalancers.go:72] loadbalancer implementation enabled: metallb
I1005 13:56:40.607964       1 loadbalancers.go:84] loadBalancers.init(): complete
I1005 13:56:40.607971       1 bgp.go:64] bgp.init(): enabling BGP on project
I1005 13:56:41.036502       1 bgp.go:68] bgp.init(): BGP enabled
I1005 13:56:41.036526       1 eip_controlplane_reconciliation.go:65] controlPlaneEndpointManager.init(): enabling BGP on project
I1005 13:56:41.036541       1 cloud.go:192] called startNodesWatcher
I1005 13:56:41.036548       1 cloud.go:198] startNodesWatcher(): creating nodesInformer
I1005 13:56:41.036568       1 cloud.go:200] startNodesWatcher(): adding event handlers
I1005 13:56:41.036588       1 cloud.go:233] startNodesWatcher(): nodesInformer.Run()
I1005 13:56:41.036607       1 cloud.go:238] startNodesWatcher(): waiting for caches to sync
I1005 13:56:41.036705       1 reflector.go:207] Starting reflector *v1.Node (0s) from pkg/mod/k8s.io/client-go@v0.19.4/tools/cache/reflector.go:156
I1005 13:56:41.036724       1 reflector.go:243] Listing and watching *v1.Node from pkg/mod/k8s.io/client-go@v0.19.4/tools/cache/reflector.go:156
I1005 13:56:41.038494       1 loadbalancers.go:132] loadbalancers.reconcileNodes(): called for nodes [&Node{ObjectMeta:*******
I1005 13:56:41.038917       1 loadbalancers.go:146] loadbalancers.reconcileNodes(): reconciling add node shoot--core--eqxm-vasu-small-pool-6476c-9zcpr
I1005 13:56:41.038927       1 devices.go:227] called deviceIDFromProviderID with providerID equinixmetal://************************************
I1005 13:56:41.136714       1 shared_informer.go:270] caches populated
I1005 13:56:41.136734       1 cloud.go:242] nodes watcher started
I1005 13:56:41.136741       1 cloud.go:249] called startServicesWatcher
I1005 13:56:41.136793       1 cloud.go:288] startServicesWatcher(): servicesInformer.Run()
I1005 13:56:41.136816       1 cloud.go:293] startServicesWatcher(): waiting for caches to sync
I1005 13:56:41.136865       1 reflector.go:207] Starting reflector *v1.Service (0s) from pkg/mod/k8s.io/client-go@v0.19.4/tools/cache/reflector.go:156
I1005 13:56:41.136881       1 reflector.go:243] Listing and watching *v1.Service from pkg/mod/k8s.io/client-go@v0.19.4/tools/cache/reflector.go:156
I1005 13:56:41.138611       1 loadbalancers.go:197] loadbalancer.reconcileServices(): 0 starting
I1005 13:56:41.138644       1 loadbalancers.go:198] loadbalancer.reconcileServices(): services []*v1.Service{(*v1.Service)(0xc0003e0c00)}
I1005 13:56:41.228097       1 loadbalancers.go:187] loadbalancers.reconcileNodes(): config changed, done
I1005 13:56:41.228118       1 devices.go:266] devices.reconcileNodes(): called for nodes [shoot--core--eqxm-vasu-small-pool-6476c-9zcpr]
I1005 13:56:41.228126       1 devices.go:271] instances.reconcileNodes(): add node shoot--core--eqxm-vasu-small-pool-6476c-9zcpr
I1005 13:56:41.228130       1 devices.go:279] instances.reconcileNodes(): setting annotations on node shoot--core--eqxm-vasu-small-pool-6476c-9zcpr
I1005 13:56:41.236933       1 shared_informer.go:270] caches populated
I1005 13:56:41.236949       1 cloud.go:297] services watcher started
I1005 13:56:41.236957       1 cloud.go:138] Initialize complete
I1005 13:56:41.236966       1 controllermanager.go:244] Starting "cloud-node-lifecycle"
I1005 13:56:41.237216       1 node_lifecycle_controller.go:77] Sending events to api server
I1005 13:56:41.237257       1 cloud.go:150] called Instances
W1005 13:56:41.237267       1 cloud.go:156] The Equinix Metal cloud provider does not support InstancesV2
I1005 13:56:41.237280       1 controllermanager.go:254] Started "cloud-node-lifecycle"
I1005 13:56:41.237287       1 controllermanager.go:244] Starting "service"
I1005 13:56:41.238171       1 cloud.go:144] called LoadBalancer
E1005 13:56:41.238186       1 core.go:97] Failed to start service controller: the cloud provider does not support external load balancers
W1005 13:56:41.238192       1 controllermanager.go:251] Skipping "service"
I1005 13:56:41.238197       1 controllermanager.go:244] Starting "route"
I1005 13:56:41.238206       1 core.go:108] Will not configure cloud provider routes for allocate-node-cidrs: false, configure-cloud-routes: true.
W1005 13:56:41.238211       1 controllermanager.go:251] Skipping "route"
I1005 13:56:41.238218       1 controllermanager.go:244] Starting "cloud-node"
I1005 13:56:41.239157       1 node_controller.go:108] Sending events to api server.
I1005 13:56:41.239194       1 cloud.go:150] called Instances
W1005 13:56:41.239203       1 cloud.go:156] The Equinix Metal cloud provider does not support InstancesV2
I1005 13:56:41.239242       1 controllermanager.go:254] Started "cloud-node"
W1005 13:56:41.240588       1 cloud.go:156] The Equinix Metal cloud provider does not support InstancesV2
I1005 13:56:41.240598       1 cloud.go:150] called Instances
I1005 13:56:41.240603       1 devices.go:65] called NodeAddressesByProviderID with providerID equinixmetal://******************************
I1005 13:56:41.240607       1 devices.go:251] called deviceFromProviderID with providerID equinixmetal://******************************
I1005 13:56:41.240611       1 devices.go:227] called deviceIDFromProviderID with providerID equinixmetal://******************************
I1005 13:56:41.240616       1 devices.go:192] called deviceByID with ID ******************************
I1005 13:56:41.240853       1 reflector.go:207] Starting reflector *v1.Node (15h4m19.638041124s) from pkg/mod/k8s.io/client-go@v0.19.4/tools/cache/reflector.go:156
I1005 13:56:41.240868       1 reflector.go:243] Listing and watching *v1.Node from pkg/mod/k8s.io/client-go@v0.19.4/tools/cache/reflector.go:156
I1005 13:56:41.240882       1 reflector.go:207] Starting reflector *v1.Service (30s) from pkg/mod/k8s.io/client-go@v0.19.4/tools/cache/reflector.go:156
I1005 13:56:41.240893       1 reflector.go:243] Listing and watching *v1.Service from pkg/mod/k8s.io/client-go@v0.19.4/tools/cache/reflector.go:156
I1005 13:56:41.242069       1 node_controller.go:320] This node shoot--core--eqxm-vasu-small-pool-6476c-9zcpr is registered without the cloud taint. Will not process.
I1005 13:56:41.242095       1 controller.go:708] Detected change in list of current cluster nodes. New node set: map[shoot--core--eqxm-vasu-small-pool-6476c-9zcpr:{}]
I1005 13:56:41.242120       1 controller.go:716] Successfully updated 0 out of 0 load balancers to direct traffic to the updated set of nodes
E1005 13:56:41.478610       1 devices.go:283] instances.reconcileNodes(): could not get private network info for node shoot--core--eqxm-vasu-small-pool-6476c-9zcpr: GET https://api.equinix.com/metal/v1/devices/equinixmetal:/******************************?include=ip_addresses.parent_block%2Cparent_block%2Cfacility: 404 Not found 
I1005 13:56:41.478660       1 devices.go:316] instances.reconcileNodes(): complete
I1005 13:56:41.478668       1 bgp.go:95] bgp.reconcileNodes(): called for nodes [shoot--core--eqxm-vasu-small-pool-6476c-9zcpr]
I1005 13:56:41.478674       1 bgp.go:100] bgp.reconcileNodes(): add node shoot--core--eqxm-vasu-small-pool-6476c-9zcpr
I1005 13:56:41.478678       1 bgp.go:106] bgp.reconcileNodes(): enabling BGP on node shoot--core--eqxm-vasu-small-pool-6476c-9zcpr
I1005 13:56:41.478682       1 devices.go:227] called deviceIDFromProviderID with providerID equinixmetal://******************************
I1005 13:56:41.655978       1 bgp.go:111] bgp.reconcileNodes(): bgp enabled on node shoot--core--eqxm-vasu-small-pool-6476c-9zcpr
I1005 13:56:41.655999       1 bgp.go:114] bgp.reconcileNodes(): setting annotations on node shoot--core--eqxm-vasu-small-pool-6476c-9zcpr
I1005 13:56:41.656004       1 devices.go:227] called deviceIDFromProviderID with providerID equinixmetal://******************************
I1005 13:56:41.895406       1 bgp.go:171] bgp.reconcileNodes(): no change to annotations for shoot--core--eqxm-vasu-small-pool-6476c-9zcpr
I1005 13:56:41.895428       1 bgp.go:178] bgp.reconcileNodes(): complete
I1005 13:56:41.895435       1 eip_controlplane_reconciliation.go:77] controlPlaneEndpoint.reconcile: new reconciliation
E1005 13:56:41.895441       1 cloud.go:206] failed to update and sync node for add shoot--core--eqxm-vasu-small-pool-6476c-9zcpr for handler: control plane apiserver port not provided or determined, cannot check, will try again on next loop
I1005 13:56:41.986081       1 loadbalancers.go:219] loadbalancer.reconcileServices(): valid services []*v1.Service{}
E1005 13:56:41.986137       1 cloud.go:262] failed to update and sync service for add kube-system/calico-typha-monitoring: elastic ip tag is empty. Nothing to do
I1005 13:56:41.986150       1 loadbalancers.go:197] loadbalancer.reconcileServices(): 0 starting
I1005 13:56:41.986161       1 loadbalancers.go:198] loadbalancer.reconcileServices(): services []*v1.Service{(*v1.Service)(0xc0003e0e10)}
I1005 13:56:42.777103       1 loadbalancers.go:219] loadbalancer.reconcileServices(): valid services []*v1.Service{}
E1005 13:56:42.777133       1 cloud.go:262] failed to update and sync service for add kube-system/calico-felix-monitoring: elastic ip tag is empty. Nothing to do
I1005 13:56:42.777158       1 loadbalancers.go:197] loadbalancer.reconcileServices(): 0 starting
I1005 13:56:42.777168       1 loadbalancers.go:198] loadbalancer.reconcileServices(): services []*v1.Service{(*v1.Service)(0xc0003e1020)}
I1005 13:56:43.544906       1 loadbalancers.go:219] loadbalancer.reconcileServices(): valid services []*v1.Service{}
E1005 13:56:43.544934       1 cloud.go:262] failed to update and sync service for add kube-system/node-exporter: elastic ip tag is empty. Nothing to do
I1005 13:56:43.544951       1 loadbalancers.go:197] loadbalancer.reconcileServices(): 0 starting
I1005 13:56:43.544958       1 loadbalancers.go:198] loadbalancer.reconcileServices(): services []*v1.Service{(*v1.Service)(0xc0003e1230)}
I1005 13:56:44.296239       1 loadbalancers.go:219] loadbalancer.reconcileServices(): valid services []*v1.Service{}
E1005 13:56:44.296260       1 cloud.go:262] failed to update and sync service for add kube-system/kube-dns: elastic ip tag is empty. Nothing to do
I1005 13:56:44.296278       1 loadbalancers.go:197] loadbalancer.reconcileServices(): 0 starting
I1005 13:56:44.296284       1 loadbalancers.go:198] loadbalancer.reconcileServices(): services []*v1.Service{(*v1.Service)(0xc0003e1440)}
I1005 13:56:45.076793       1 loadbalancers.go:219] loadbalancer.reconcileServices(): valid services []*v1.Service{}
E1005 13:56:45.076814       1 cloud.go:262] failed to update and sync service for add kube-system/metrics-server: elastic ip tag is empty. Nothing to do
I1005 13:56:45.076830       1 loadbalancers.go:197] loadbalancer.reconcileServices(): 0 starting
I1005 13:56:45.076837       1 loadbalancers.go:198] loadbalancer.reconcileServices(): services []*v1.Service{(*v1.Service)(0xc0003e1650)}
I1005 13:56:45.824902       1 loadbalancers.go:219] loadbalancer.reconcileServices(): valid services []*v1.Service{}
E1005 13:56:45.824929       1 cloud.go:262] failed to update and sync service for add kube-system/kube-proxy: elastic ip tag is empty. Nothing to do
I1005 13:56:45.824949       1 loadbalancers.go:197] loadbalancer.reconcileServices(): 0 starting
I1005 13:56:45.824960       1 loadbalancers.go:198] loadbalancer.reconcileServices(): services []*v1.Service{(*v1.Service)(0xc0003e1860)}
I1005 13:56:46.702573       1 loadbalancers.go:219] loadbalancer.reconcileServices(): valid services []*v1.Service{}
E1005 13:56:46.702602       1 cloud.go:262] failed to update and sync service for add kube-system/apiserver-proxy: elastic ip tag is empty. Nothing to do
I1005 13:56:46.702623       1 loadbalancers.go:197] loadbalancer.reconcileServices(): 0 starting
I1005 13:56:46.702633       1 loadbalancers.go:198] loadbalancer.reconcileServices(): services []*v1.Service{(*v1.Service)(0xc0003e1a70)}
I1005 13:56:47.526105       1 loadbalancers.go:219] loadbalancer.reconcileServices(): valid services []*v1.Service{}
E1005 13:56:47.526129       1 cloud.go:262] failed to update and sync service for add kube-system/blackbox-exporter: elastic ip tag is empty. Nothing to do
I1005 13:56:47.526150       1 loadbalancers.go:197] loadbalancer.reconcileServices(): 0 starting
I1005 13:56:47.526159       1 loadbalancers.go:198] loadbalancer.reconcileServices(): services []*v1.Service{(*v1.Service)(0xc0003e1c80)}
I1005 13:56:48.379350       1 loadbalancers.go:219] loadbalancer.reconcileServices(): valid services []*v1.Service{}
E1005 13:56:48.379398       1 cloud.go:262] failed to update and sync service for add kube-system/calico-typha: elastic ip tag is empty. Nothing to do
I1005 13:56:48.379416       1 loadbalancers.go:197] loadbalancer.reconcileServices(): 0 starting
I1005 13:56:48.379428       1 loadbalancers.go:198] loadbalancer.reconcileServices(): services []*v1.Service{(*v1.Service)(0xc0003e1e90)}
I1005 13:56:49.118407       1 loadbalancers.go:219] loadbalancer.reconcileServices(): valid services []*v1.Service{}
E1005 13:56:49.118429       1 cloud.go:262] failed to update and sync service for add default/kubernetes: elastic ip tag is empty. Nothing to do
I1005 13:57:11.242476       1 reflector.go:369] pkg/mod/k8s.io/client-go@v0.19.4/tools/cache/reflector.go:156: forcing resync
I1005 13:57:41.237173       1 loadbalancers.go:197] loadbalancer.reconcileServices(): 2 starting
I1005 13:57:41.237197       1 loadbalancers.go:198] loadbalancer.reconcileServices(): services []*v1.Service{(*v1.Service)(0xc0003e1440), (*v1.Service)(0xc0003e1650), (*v1.Service)(0xc0003e1c80), (*v1.Service)(0xc0003e1020), (*v1.Service)(0xc0003e1230), (*v1.Service)(0xc0003e1860), (*v1.Service)(0xc0003e1a70), (*v1.Service)(0xc0003e1e90), (*v1.Service)(0xc0003e0c00), (*v1.Service)(0xc0003e0e10)}
I1005 13:57:41.242641       1 reflector.go:369] pkg/mod/k8s.io/client-go@v0.19.4/tools/cache/reflector.go:156: forcing resync
I1005 13:57:42.141322       1 loadbalancers.go:219] loadbalancer.reconcileServices(): valid services []*v1.Service{}
I1005 13:57:42.141356       1 loadbalancers.go:280] loadbalancer.reconcileServices(): sync: getting all IP reservations
I1005 13:57:42.911419       1 loadbalancers.go:307] loadbalancer.reconcileServices(): sync: valid tags map[]
I1005 13:57:42.911449       1 loadbalancers.go:308] loadbalancer.reconcileServices(): sync: valid svc IPs map[]
I1005 13:57:42.913986       1 metallb.go:86] metallb.SyncServices(): actual configmap IPs []
I1005 13:57:42.914014       1 loadbalancers.go:316] loadbalancer.reconcileServices(): sync: all reservations with emTag []*packngo.IPAddressReservation{}
E1005 13:57:42.914024       1 cloud.go:314] failed to update and sync services: elastic ip tag is empty. Nothing to do
I1005 13:57:42.914036       1 loadbalancers.go:132] loadbalancers.reconcileNodes(): called for nodes [&Node{ObjectMeta:******
I1005 13:57:42.915011       1 devices.go:227] called deviceIDFromProviderID with providerID equinixmetal://******************************
I1005 13:57:43.100474       1 loadbalancers.go:187] loadbalancers.reconcileNodes(): config changed, done
I1005 13:57:43.100493       1 devices.go:266] devices.reconcileNodes(): called for nodes [shoot--core--eqxm-vasu-small-pool-6476c-9zcpr]
I1005 13:57:43.100501       1 devices.go:271] instances.reconcileNodes(): add node shoot--core--eqxm-vasu-small-pool-6476c-9zcpr
I1005 13:57:43.100505       1 devices.go:279] instances.reconcileNodes(): setting annotations on node shoot--core--eqxm-vasu-small-pool-6476c-9zcpr
E1005 13:57:43.237312       1 devices.go:283] instances.reconcileNodes(): could not get private network info for node shoot--core--eqxm-vasu-small-pool-6476c-9zcpr: GET https://api.equinix.com/metal/v1/devices/equinixmetal:/******************************?include=ip_addresses.parent_block%2Cparent_block%2Cfacility: 404 Not found 
I1005 13:57:43.237357       1 devices.go:316] instances.reconcileNodes(): complete
I1005 13:57:43.237369       1 bgp.go:95] bgp.reconcileNodes(): called for nodes [shoot--core--eqxm-vasu-small-pool-6476c-9zcpr]
I1005 13:57:43.237377       1 bgp.go:100] bgp.reconcileNodes(): add node shoot--core--eqxm-vasu-small-pool-6476c-9zcpr
I1005 13:57:43.237382       1 bgp.go:106] bgp.reconcileNodes(): enabling BGP on node shoot--core--eqxm-vasu-small-pool-6476c-9zcpr
I1005 13:57:43.237388       1 devices.go:227] called deviceIDFromProviderID with providerID equinixmetal://******************************
I1005 13:57:43.421406       1 bgp.go:111] bgp.reconcileNodes(): bgp enabled on node shoot--core--eqxm-vasu-small-pool-6476c-9zcpr
I1005 13:57:43.421428       1 bgp.go:114] bgp.reconcileNodes(): setting annotations on node shoot--core--eqxm-vasu-small-pool-6476c-9zcpr
I1005 13:57:43.421446       1 devices.go:227] called deviceIDFromProviderID with providerID equinixmetal://******************************
I1005 13:57:43.600773       1 bgp.go:171] bgp.reconcileNodes(): no change to annotations for shoot--core--eqxm-vasu-small-pool-6476c-9zcpr
I1005 13:57:43.600794       1 bgp.go:178] bgp.reconcileNodes(): complete
I1005 13:57:43.600802       1 eip_controlplane_reconciliation.go:77] controlPlaneEndpoint.reconcile: new reconciliation
E1005 13:57:43.600807       1 cloud.go:323] failed to update and sync nodes: control plane apiserver port not provided or determined, cannot check, will try again on next loop
I1005 13:57:53.535953       1 loadbalancers.go:197] loadbalancer.reconcileServices(): 0 starting
I1005 13:57:53.535972       1 loadbalancers.go:198] loadbalancer.reconcileServices(): services []*v1.Service{(*v1.Service)(0xc0004c3440)}
I1005 13:57:54.330867       1 loadbalancers.go:219] loadbalancer.reconcileServices(): valid services []*v1.Service{}
E1005 13:57:54.330900       1 cloud.go:262] failed to update and sync service for add istio-system/istiod: elastic ip tag is empty. Nothing to do
I1005 13:58:11.242782       1 reflector.go:369] pkg/mod/k8s.io/client-go@v0.19.4/tools/cache/reflector.go:156: forcing resync
I1005 13:58:18.051599       1 loadbalancers.go:197] loadbalancer.reconcileServices(): 0 starting
I1005 13:58:18.051619       1 loadbalancers.go:198] loadbalancer.reconcileServices(): services []*v1.Service{(*v1.Service)(0xc0003f2fc0)}
I1005 13:58:19.000302       1 loadbalancers.go:219] loadbalancer.reconcileServices(): valid services []*v1.Service{(*v1.Service)(0xc0003f2fc0)}
I1005 13:58:19.000349       1 loadbalancers.go:225] loadbalancer.reconcileServices(): add: service istio-ingressgateway
I1005 13:58:19.000373       1 loadbalancers.go:351] processing istio-system/istio-ingressgateway with existing IP assignment 
I1005 13:58:19.000394       1 loadbalancers.go:354] no IP assigned for service istio-system/istio-ingressgateway; searching reservations
I1005 13:58:19.000404       1 loadbalancers.go:360] no IP assignment found for istio-system/istio-ingressgateway, requesting
I1005 13:58:23.196115       1 loadbalancers.go:393] assigning IP 139.178.65.52 to istio-system/istio-ingressgateway
I1005 13:58:23.201782       1 loadbalancers.go:407] successfully assigned 139.178.65.52 update service istio-system/istio-ingressgateway
I1005 13:58:23.201793       1 event.go:291] "Event occurred" object="istio-system/istio-ingressgateway" kind="Service" apiVersion="v1" type="Normal" reason="LoadbalancerIP" message=" -> 139.178.65.52"
I1005 13:58:23.203712       1 metallb.go:199] mapping IP 139.178.65.52/32
I1005 13:58:23.203728       1 metallb.go:229] config changed, updating
I1005 13:58:23.203865       1 metallb.go:249] patching configmap:
{"data":{"config":"peers:\n- my-asn: 65000\n  peer-asn: 65530\n  peer-address: 10.99.173.128\n  peer-port: 0\n  hold-time: \"\"\n  router-id: \"\"\n  node-selectors:\n  - match-labels:\n      kubernetes.io/hostname: shoot--core--eqxm-vasu-small-pool-6476c-9zcpr\n    match-expressions: []\n  password: \"\"\nbgp-communities: {}\naddress-pools:\n- protocol: bgp\n  name: istio-system/istio-ingressgateway\n  addresses:\n  - 139.178.65.52/32\n  avoid-buggy-ips: false\n  auto-assign: false\n  bgp-advertisements: []\n"}}
E1005 13:58:23.206962       1 cloud.go:262] failed to update and sync service for add istio-system/istio-ingressgateway: elastic ip tag is empty. Nothing to do
I1005 13:58:41.242958       1 reflector.go:369] pkg/mod/k8s.io/client-go@v0.19.4/tools/cache/reflector.go:156: forcing resync
I1005 13:58:43.600979       1 loadbalancers.go:197] loadbalancer.reconcileServices(): 2 starting
I1005 13:58:43.601060       1 loadbalancers.go:198] loadbalancer.reconcileServices(): services []*v1.Service{(*v1.Service)(0xc0004c3440), (*v1.Service)(0xc000015440), (*v1.Service)(0xc0003e0c00), (*v1.Service)(0xc0003e0e10), (*v1.Service)(0xc0003e1860), (*v1.Service)(0xc0003e1a70), (*v1.Service)(0xc0003e1e90), (*v1.Service)(0xc0003e1020), (*v1.Service)(0xc0003e1230), (*v1.Service)(0xc0003e1440), (*v1.Service)(0xc0003e1650), (*v1.Service)(0xc0003e1c80)}
I1005 13:58:44.642151       1 loadbalancers.go:219] loadbalancer.reconcileServices(): valid services []*v1.Service{(*v1.Service)(0xc000015440)}
I1005 13:58:44.642175       1 loadbalancers.go:271] loadbalancer.reconcileServices(): sync: service istio-ingressgateway
I1005 13:58:44.642189       1 loadbalancers.go:351] processing istio-system/istio-ingressgateway with existing IP assignment 139.178.65.52
I1005 13:58:44.644663       1 metallb.go:199] mapping IP 139.178.65.52/32
I1005 13:58:44.644684       1 metallb.go:223] address already on ConfigMap, unchanged
I1005 13:58:44.644697       1 loadbalancers.go:280] loadbalancer.reconcileServices(): sync: getting all IP reservations
I1005 13:58:45.490171       1 loadbalancers.go:307] loadbalancer.reconcileServices(): sync: valid tags map[service=NiN8iRoN5ip1NIbo0soMgUZ9sfQqJ8KFBfYiCSf0KyA=:true]
I1005 13:58:45.490202       1 loadbalancers.go:308] loadbalancer.reconcileServices(): sync: valid svc IPs map[139.178.65.52/32:true]
I1005 13:58:45.493867       1 metallb.go:86] metallb.SyncServices(): actual configmap IPs [139.178.65.52/32]
I1005 13:58:45.493888       1 loadbalancers.go:316] loadbalancer.reconcileServices(): sync: all reservations with emTag []*packngo.IPAddressReservation{(*packngo.IPAddressReservation)(0xc000c64c00)}
E1005 13:58:45.493900       1 cloud.go:314] failed to update and sync services: elastic ip tag is empty. Nothing to do
I1005 13:58:45.493911       1 loadbalancers.go:132] loadbalancers.reconcileNodes(): called for nodes [&Node{ObjectMeta:*****
I1005 13:58:45.494297       1 devices.go:227] called deviceIDFromProviderID with providerID equinixmetal://******************************
I1005 13:58:45.717343       1 loadbalancers.go:187] loadbalancers.reconcileNodes(): config changed, done
I1005 13:58:45.717369       1 devices.go:266] devices.reconcileNodes(): called for nodes [shoot--core--eqxm-vasu-small-pool-6476c-9zcpr]
I1005 13:58:45.717378       1 devices.go:271] instances.reconcileNodes(): add node shoot--core--eqxm-vasu-small-pool-6476c-9zcpr
I1005 13:58:45.717383       1 devices.go:279] instances.reconcileNodes(): setting annotations on node shoot--core--eqxm-vasu-small-pool-6476c-9zcpr
E1005 13:58:45.892014       1 devices.go:283] instances.reconcileNodes(): could not get private network info for node shoot--core--eqxm-vasu-small-pool-6476c-9zcpr: GET https://api.equinix.com/metal/v1/devices/equinixmetal:/******************************?include=ip_addresses.parent_block%2Cparent_block%2Cfacility: 404 Not found 
I1005 13:58:45.892047       1 devices.go:316] instances.reconcileNodes(): complete
I1005 13:58:45.892058       1 bgp.go:95] bgp.reconcileNodes(): called for nodes [shoot--core--eqxm-vasu-small-pool-6476c-9zcpr]
I1005 13:58:45.892066       1 bgp.go:100] bgp.reconcileNodes(): add node shoot--core--eqxm-vasu-small-pool-6476c-9zcpr
I1005 13:58:45.892070       1 bgp.go:106] bgp.reconcileNodes(): enabling BGP on node shoot--core--eqxm-vasu-small-pool-6476c-9zcpr
I1005 13:58:45.892074       1 devices.go:227] called deviceIDFromProviderID with providerID equinixmetal://******************************
I1005 13:58:46.085877       1 bgp.go:111] bgp.reconcileNodes(): bgp enabled on node shoot--core--eqxm-vasu-small-pool-6476c-9zcpr
I1005 13:58:46.085893       1 bgp.go:114] bgp.reconcileNodes(): setting annotations on node shoot--core--eqxm-vasu-small-pool-6476c-9zcpr
I1005 13:58:46.085898       1 devices.go:227] called deviceIDFromProviderID with providerID equinixmetal://******************************
I1005 13:58:46.293152       1 bgp.go:171] bgp.reconcileNodes(): no change to annotations for shoot--core--eqxm-vasu-small-pool-6476c-9zcpr
I1005 13:58:46.293172       1 bgp.go:178] bgp.reconcileNodes(): complete
I1005 13:58:46.293191       1 eip_controlplane_reconciliation.go:77] controlPlaneEndpoint.reconcile: new reconciliation
E1005 13:58:46.293197       1 cloud.go:323] failed to update and sync nodes: control plane apiserver port not provided or determined, cannot check, will try again on next loop
I1005 14:05:02.942705       1 eip_controlplane_reconciliation.go:77] controlPlaneEndpoint.reconcile: new reconciliation
E1005 14:05:02.942710       1 cloud.go:323] failed to update and sync nodes: control plane apiserver port not provided or determined, cannot check, will try again on next loop
I1005 14:05:11.245065       1 reflector.go:369] pkg/mod/k8s.io/client-go@v0.19.4/tools/cache/reflector.go:156: forcing resync
I1005 14:05:11.917512       1 event.go:291] "Event occurred" object="istio-system/istio-ingressgateway" kind="Service" apiVersion="v1" type="Normal" reason="Type" message="LoadBalancer -> ClusterIP"
I1005 14:05:41.245235       1 reflector.go:369] pkg/mod/k8s.io/client-go@v0.19.4/tools/cache/reflector.go:156: forcing resync
I1005 14:05:50.142652       1 reflector.go:515] pkg/mod/k8s.io/client-go@v0.19.4/tools/cache/reflector.go:156: Watch close - *v1.Service total 16 items received
I1005 14:06:02.942839       1 loadbalancers.go:197] loadbalancer.reconcileServices(): 2 starting
I1005 14:06:02.942864       1 loadbalancers.go:198] loadbalancer.reconcileServices(): services []*v1.Service{(*v1.Service)(0xc0003e0c00), (*v1.Service)(0xc0003e0e10), (*v1.Service)(0xc0003e1860), (*v1.Service)(0xc0003e1a70), (*v1.Service)(0xc0003e1e90), (*v1.Service)(0xc0004c3440), (*v1.Service)(0xc0003f98c0), (*v1.Service)(0xc0003e1020), (*v1.Service)(0xc0003e1230), (*v1.Service)(0xc0003e1440), (*v1.Service)(0xc0003e1650), (*v1.Service)(0xc0003e1c80)}
I1005 14:06:03.891325       1 loadbalancers.go:219] loadbalancer.reconcileServices(): valid services []*v1.Service{}
I1005 14:06:03.891349       1 loadbalancers.go:280] loadbalancer.reconcileServices(): sync: getting all IP reservations
I1005 14:06:04.682832       1 loadbalancers.go:307] loadbalancer.reconcileServices(): sync: valid tags map[]
I1005 14:06:04.682853       1 loadbalancers.go:308] loadbalancer.reconcileServices(): sync: valid svc IPs map[]
I1005 14:06:04.685103       1 metallb.go:86] metallb.SyncServices(): actual configmap IPs [139.178.65.52/32]
I1005 14:06:04.685119       1 metallb.go:89] metallb.SyncServices(): removing from configmap ip 139.178.65.52/32 not in valid list
I1005 14:06:04.685125       1 metallb.go:205] unmapping IP 139.178.65.52/32
I1005 14:06:04.685131       1 metallb.go:229] config changed, updating
I1005 14:06:04.685211       1 metallb.go:249] patching configmap:
{"data":{"config":"peers:\n- my-asn: 65000\n  peer-asn: 65530\n  peer-address: 10.99.173.128\n  peer-port: 0\n  hold-time: \"\"\n  router-id: \"\"\n  node-selectors:\n  - match-labels:\n      kubernetes.io/hostname: shoot--core--eqxm-vasu-small-pool-6476c-9zcpr\n    match-expressions: []\n  password: \"\"\nbgp-communities: {}\naddress-pools: []\n"}}
I1005 14:06:04.688321       1 loadbalancers.go:316] loadbalancer.reconcileServices(): sync: all reservations with emTag []*packngo.IPAddressReservation{(*packngo.IPAddressReservation)(0xc000553800)}
I1005 14:06:04.688342       1 loadbalancers.go:326] loadbalancer.reconcileServices(): sync: removing reservation with service= tag but not in validTags list &packngo.IPAddressReservation{IpAddressCommon:packngo.IpAddressCommon{ID:"3b802032-0caf-476f-81af-048662d4000c", Address:"139.178.65.52", Gateway:"139.178.65.52", Network:"139.178.65.52", AddressFamily:4, Netmask:"255.255.255.255", Public:true, CIDR:32, Created:"2021-10-05T13:58:19Z", Updated:"", Href:"/metal/v1/ips/3b802032-0caf-476f-81af-048662d4000c", Management:false, Manageable:true, Metro:(*packngo.Metro)(0xc000ba7000), Project:packngo.Href{Href:"/metal/v1/projects/**********************************"}, Global:false, Tags:[]string{"usage=cloud-provider-equinix-metal-auto", "service=NiN8iRoN5ip1NIbo0soMgUZ9sfQqJ8KFBfYiCSf0KyA=", "cluster=4f488f72-f385-4023-af32-99d0ba2424c1"}, ParentBlock:(*packngo.ParentBlock)(nil), CustomData:map[string]interface {}{}}, Assignments:[]*packngo.IPAddressAssignment{}, Facility:(*packngo.Facility)(0xc0001ab1f0), Available:"/metal/v1/ips/3b802032-0caf-476f-81af-048662d4000c/available", Addon:true, Bill:true, Description:(*string)(0xc00062c230)}
E1005 14:06:07.882396       1 cloud.go:314] failed to update and sync services: elastic ip tag is empty. Nothing to do
I1005 14:06:07.882426       1 loadbalancers.go:132] loadbalancers.reconcileNodes(): called for nodes [&Node{ObjectMeta:****
I1005 14:06:07.882778       1 devices.go:227] called deviceIDFromProviderID with providerID equinixmetal://*************************
I1005 14:06:08.149592       1 loadbalancers.go:187] loadbalancers.reconcileNodes(): config changed, done
I1005 14:06:08.149612       1 devices.go:266] devices.reconcileNodes(): called for nodes [shoot--core--eqxm-vasu-small-pool-6476c-9zcpr]
I1005 14:06:08.149620       1 devices.go:271] instances.reconcileNodes(): add node shoot--core--eqxm-vasu-small-pool-6476c-9zcpr
I1005 14:06:08.149624       1 devices.go:279] instances.reconcileNodes(): setting annotations on node shoot--core--eqxm-vasu-small-pool-6476c-9zcpr
E1005 14:06:08.310809       1 devices.go:283] instances.reconcileNodes(): could not get private network info for node shoot--core--eqxm-vasu-small-pool-6476c-9zcpr: GET https://api.equinix.com/metal/v1/devices/equinixmetal:/*************************?include=ip_addresses.parent_block%2Cparent_block%2Cfacility: 404 Not found 
I1005 14:06:08.310838       1 devices.go:316] instances.reconcileNodes(): complete
I1005 14:06:08.310847       1 bgp.go:95] bgp.reconcileNodes(): called for nodes [shoot--core--eqxm-vasu-small-pool-6476c-9zcpr]
I1005 14:06:08.310853       1 bgp.go:100] bgp.reconcileNodes(): add node shoot--core--eqxm-vasu-small-pool-6476c-9zcpr
I1005 14:06:08.310857       1 bgp.go:106] bgp.reconcileNodes(): enabling BGP on node shoot--core--eqxm-vasu-small-pool-6476c-9zcpr
I1005 14:06:08.310861       1 devices.go:227] called deviceIDFromProviderID with providerID equinixmetal://*************************
I1005 14:06:08.530887       1 bgp.go:111] bgp.reconcileNodes(): bgp enabled on node shoot--core--eqxm-vasu-small-pool-6476c-9zcpr
I1005 14:06:08.530908       1 bgp.go:114] bgp.reconcileNodes(): setting annotations on node shoot--core--eqxm-vasu-small-pool-6476c-9zcpr
I1005 14:06:08.530913       1 devices.go:227] called deviceIDFromProviderID with providerID equinixmetal://*************************
I1005 14:06:08.755257       1 bgp.go:171] bgp.reconcileNodes(): no change to annotations for shoot--core--eqxm-vasu-small-pool-6476c-9zcpr
I1005 14:06:08.755279       1 bgp.go:178] bgp.reconcileNodes(): complete
I1005 14:06:08.755286       1 eip_controlplane_reconciliation.go:77] controlPlaneEndpoint.reconcile: new reconciliation
E1005 14:06:08.755291       1 cloud.go:323] failed to update and sync nodes: control plane apiserver port not provided or determined, cannot check, will try again on next loop
I1005 14:06:11.245401       1 reflector.go:369] pkg/mod/k8s.io/client-go@v0.19.4/tools/cache/reflector.go:156: forcing resync
I1005 14:06:41.245599       1 reflector.go:369] pkg/mod/k8s.io/client-go@v0.19.4/tools/cache/reflector.go:156: forcing resync
W1005 14:06:42.418782       1 cloud.go:156] The Equinix Metal cloud provider does not support InstancesV2
I1005 14:06:42.418801       1 cloud.go:150] called Instances
I1005 14:06:42.418809       1 devices.go:65] called NodeAddressesByProviderID with providerID equinixmetal://*************************
I1005 14:06:42.418815       1 devices.go:251] called deviceFromProviderID with providerID equinixmetal://*************************
I1005 14:06:42.418821       1 devices.go:227] called deviceIDFromProviderID with providerID equinixmetal://*************************
I1005 14:06:42.418827       1 devices.go:192] called deviceByID with ID *************************
I1005 14:11:43.137869       1 devices.go:192] called deviceByID with ID *********
I1005 14:11:55.514561       1 event.go:291] "Event occurred" object="istio-system/istio-ingressgateway" kind="Service" apiVersion="v1" type="Normal" reason="Type" message="ClusterIP -> LoadBalancer"
I1005 14:12:11.248064       1 reflector.go:369] pkg/mod/k8s.io/client-go@v0.19.4/tools/cache/reflector.go:156: forcing resync
I1005 14:12:24.044202       1 reflector.go:515] pkg/mod/k8s.io/client-go@v0.19.4/tools/cache/reflector.go:156: Watch close - *v1.Node total 56 items received
I1005 14:12:24.671761       1 loadbalancers.go:197] loadbalancer.reconcileServices(): 2 starting
I1005 14:12:24.671783       1 loadbalancers.go:198] loadbalancer.reconcileServices(): services []*v1.Service{(*v1.Service)(0xc0003e1020), (*v1.Service)(0xc0003e1230), (*v1.Service)(0xc0003e1440), (*v1.Service)(0xc0003e1650), (*v1.Service)(0xc0003e1c80), (*v1.Service)(0xc0003e0c00), (*v1.Service)(0xc0003e0e10), (*v1.Service)(0xc0003e1860), (*v1.Service)(0xc0003e1a70), (*v1.Service)(0xc0003e1e90), (*v1.Service)(0xc0004c3440), (*v1.Service)(0xc0006d18c0)}
I1005 14:12:26.219336       1 loadbalancers.go:219] loadbalancer.reconcileServices(): valid services []*v1.Service{(*v1.Service)(0xc0006d18c0)}
I1005 14:12:26.219368       1 loadbalancers.go:271] loadbalancer.reconcileServices(): sync: service istio-ingressgateway
I1005 14:12:26.219388       1 loadbalancers.go:351] processing istio-system/istio-ingressgateway with existing IP assignment 139.178.65.52
I1005 14:12:26.222139       1 metallb.go:199] mapping IP 139.178.65.52/32
I1005 14:12:26.222155       1 metallb.go:229] config changed, updating
I1005 14:12:26.222282       1 metallb.go:249] patching configmap:
{"data":{"config":"peers:\n- my-asn: 65000\n  peer-asn: 65530\n  peer-address: 10.99.173.128\n  peer-port: 0\n  hold-time: \"\"\n  router-id: \"\"\n  node-selectors:\n  - match-labels:\n      kubernetes.io/hostname: shoot--core--eqxm-vasu-small-pool-6476c-9zcpr\n    match-expressions: []\n  password: \"\"\nbgp-communities: {}\naddress-pools:\n- protocol: bgp\n  name: istio-system/istio-ingressgateway\n  addresses:\n  - 139.178.65.52/32\n  avoid-buggy-ips: false\n  auto-assign: false\n  bgp-advertisements: []\n"}}
I1005 14:12:26.225306       1 loadbalancers.go:280] loadbalancer.reconcileServices(): sync: getting all IP reservations
I1005 14:12:27.051260       1 loadbalancers.go:307] loadbalancer.reconcileServices(): sync: valid tags map[service=NiN8iRoN5ip1NIbo0soMgUZ9sfQqJ8KFBfYiCSf0KyA=:true]
I1005 14:12:27.051286       1 loadbalancers.go:308] loadbalancer.reconcileServices(): sync: valid svc IPs map[]
I1005 14:12:27.053340       1 metallb.go:86] metallb.SyncServices(): actual configmap IPs [139.178.65.52/32]
I1005 14:12:27.053356       1 metallb.go:89] metallb.SyncServices(): removing from configmap ip 139.178.65.52/32 not in valid list
I1005 14:12:27.053361       1 metallb.go:205] unmapping IP 139.178.65.52/32
I1005 14:12:27.053366       1 metallb.go:229] config changed, updating
I1005 14:12:27.053443       1 metallb.go:249] patching configmap:
{"data":{"config":"peers:\n- my-asn: 65000\n  peer-asn: 65530\n  peer-address: 10.99.173.128\n  peer-port: 0\n  hold-time: \"\"\n  router-id: \"\"\n  node-selectors:\n  - match-labels:\n      kubernetes.io/hostname: shoot--core--eqxm-vasu-small-pool-6476c-9zcpr\n    match-expressions: []\n  password: \"\"\nbgp-communities: {}\naddress-pools: []\n"}}
I1005 14:12:27.055838       1 loadbalancers.go:316] loadbalancer.reconcileServices(): sync: all reservations with emTag []*packngo.IPAddressReservation{}
E1005 14:12:27.055858       1 cloud.go:314] failed to update and sync services: elastic ip tag is empty. Nothing to do
I1005 14:12:27.055868       1 loadbalancers.go:132] loadbalancers.reconcileNodes(): called for nodes [&Node{ObjectMeta:*******
I1005 14:12:27.056246       1 devices.go:227] called deviceIDFromProviderID with providerID equinixmetal://*********
I1005 14:12:27.279014       1 loadbalancers.go:187] loadbalancers.reconcileNodes(): config changed, done
I1005 14:12:27.279041       1 devices.go:266] devices.reconcileNodes(): called for nodes [shoot--core--eqxm-vasu-small-pool-6476c-9zcpr]
I1005 14:12:27.279053       1 devices.go:271] instances.reconcileNodes(): add node shoot--core--eqxm-vasu-small-pool-6476c-9zcpr
I1005 14:12:27.279059       1 devices.go:279] instances.reconcileNodes(): setting annotations on node shoot--core--eqxm-vasu-small-pool-6476c-9zcpr
E1005 14:12:27.761095       1 devices.go:283] instances.reconcileNodes(): could not get private network info for node shoot--core--eqxm-vasu-small-pool-6476c-9zcpr: GET https://api.equinix.com/metal/v1/devices/equinixmetal:/*********?include=ip_addresses.parent_block%2Cparent_block%2Cfacility: 404 Not found 
I1005 14:12:27.761127       1 devices.go:316] instances.reconcileNodes(): complete
I1005 14:12:27.761137       1 bgp.go:95] bgp.reconcileNodes(): called for nodes [shoot--core--eqxm-vasu-small-pool-6476c-9zcpr]
I1005 14:12:27.761143       1 bgp.go:100] bgp.reconcileNodes(): add node shoot--core--eqxm-vasu-small-pool-6476c-9zcpr
I1005 14:12:27.761147       1 bgp.go:106] bgp.reconcileNodes(): enabling BGP on node shoot--core--eqxm-vasu-small-pool-6476c-9zcpr
I1005 14:12:27.761151       1 devices.go:227] called deviceIDFromProviderID with providerID equinixmetal://*********
I1005 14:12:27.974992       1 bgp.go:111] bgp.reconcileNodes(): bgp enabled on node shoot--core--eqxm-vasu-small-pool-6476c-9zcpr
I1005 14:12:27.975012       1 bgp.go:114] bgp.reconcileNodes(): setting annotations on node shoot--core--eqxm-vasu-small-pool-6476c-9zcpr
I1005 14:12:27.975017       1 devices.go:227] called deviceIDFromProviderID with providerID equinixmetal://*********
I1005 14:12:28.209201       1 bgp.go:171] bgp.reconcileNodes(): no change to annotations for shoot--core--eqxm-vasu-small-pool-6476c-9zcpr
I1005 14:12:28.209223       1 bgp.go:178] bgp.reconcileNodes(): complete
I1005 14:12:28.209230       1 eip_controlplane_reconciliation.go:77] controlPlaneEndpoint.reconcile: new reconciliation
E1005 14:12:28.209235       1 cloud.go:323] failed to update and sync nodes: control plane apiserver port not provided or determined, cannot check, will try again on next loop
I1005 14:12:41.248233       1 reflector.go:369] pkg/mod/k8s.io/client-go@v0.19.4/tools/cache/reflector.go:156: forcing resync
deitch commented 3 years ago

@vasu1124 you do like structured issues. Hats off to you. This makes it easier.

After you give the IP back, i.e. switch it to type=ClusterIP, what does the Service look like? Can you get its spec and post it here? I think I know what is going on, but need to be sure.

vasu1124 commented 3 years ago

The Service does move to a proper state with LoadBalancer and IP (actually the very same IP as handed out before). I can't get to the manifest anymore. But as mentioned, no request went to the equinix system, at least it was not registered under the IP Dashboard.

deitch commented 3 years ago

No I meant the previous. There are three state changes here:

  1. Create the service of type loadbalancer 
  2. Switch it to type clusterip
  3. Switch it to type loadbalancer

I want to see what the spec is after stage two, before stage 3

vasu1124 commented 3 years ago

Oh you mean if spec.status.loadBalancer: is empty or has the IP? I would guess it had the IP due to line I1005 14:12:26.219388 1 loadbalancers.go:351] processing istio-system/istio-ingressgateway with existing IP assignment 139.178.65.52 ... hold on let me check.

deitch commented 3 years ago

Status.loadBalancerIP and Spec.loadBalancerIP

vasu1124 commented 3 years ago

1.

spec:
  clusterIP: 100.69.63.22
  clusterIPs:
  - 100.69.63.22
  externalTrafficPolicy: Cluster
...
  loadBalancerIP: 147.75.199.133
  sessionAffinity: None
  type: LoadBalancer
status:
  loadBalancer:
    ingress:
    - ip: 147.75.199.133

2.

spec:
  clusterIP: 100.69.63.22
  clusterIPs:
  - 100.69.63.22
  loadBalancerIP: 147.75.199.133
...
  sessionAffinity: None
  type: ClusterIP
status:
  loadBalancer: {}

And ha! that's the bug. If I delete the spec.loadBalancerIP manually before step 3, then all works as expected.

(Why? Does this not affect everybody else? Or am I the only one complaining?)

deitch commented 3 years ago

That was what I thought it might be.

CCM depends on spec.loadBalancerIP to know if an IP has been assigned or not. It places it there when it assigns it, and doesn't need to remove it when it's deleted (as the resource is, by definition, deleted).

What it doesn't quite know what to do with is when you switch it.

From stage 2 to stage 3, from CCM's perspective, it looks like a newly created load balancer that already has an IP, so why assign one?

I'm open to logic that can handle this use case.

deitch commented 2 years ago

I am fairly confident that #224 eliminates this issue. As we switched to the standard load balancer API, everything happens via:

EnsureLoadBalancer(ctx context.Context, clusterName string, service *v1Service, nodes []*v1.Node) (*v1.LoadBalancerStatus, error)

which is implemented here.

We no longer look at the spec or loadbalancerIP; it just gets a call EnsureLoadBalancer(), and it sees if one is assigned in EQXM. If yes, pass it on; if not, create one.

I will close the issue, but feel free to open if it can be reproduced with the latest.