nmstate / kubernetes-nmstate

Declarative node network configuration driven through Kubernetes API.
GNU General Public License v2.0
172 stars 86 forks source link

NNCP apply takes *very long* time to apply; nmstatectl does not #1242

Open k8scoder192 opened 1 month ago

k8scoder192 commented 1 month ago

What happened: Apply of a nncp takes over 60 seconds. If I exec into the node's nmstate-handler pod and use nmstatectl to create an interface (vlan or bridge) it takes seconds.

What you expected to happen: Apply of nncp to apply quickly

How to reproduce it (as minimally and precisely as possible): Apply a yaml such as this

apiVersion: nmstate.io/v1
kind: NodeNetworkConfigurationPolicy
metadata:
  name: svc-uc-v108-dal4-qz4-sr7-rk047-s04
spec:
  desiredState:
    interfaces:
    - ipv4:
        dhcp: false
        enabled: false
      mac-address: 02:10:2c:2c:7e:52
      name: svc-uc-v108
      state: up
      type: vlan
      vlan:
        base-iface: bond1
        id: 108
  nodeSelector:
    kubernetes.io/hostname: dal4-qz4-sr7-rk047-s04

Anything else we need to know?: nmstate version --> kubernetes-nmstate-handler:v0.80.0

Environment:

Kernel

5.15.0-1020

kubectl logs nmstate-handler-9zkz6 -n nmstate

{"level":"info","ts":"2024-05-28T15:48:59.214Z","logger":"enactmentstatus","msg":"status: {DesiredState:interfaces:\n- bridge:\n    options:\n      stp:\n        enabled: false\n    port:\n    - name: usb-int-v53\n      vlan:\n        mode: trunk\n        trunk-tags:\n        - id-range:\n            max: 4094\n            min: 2\n  ipv4:\n    dhcp: false\n    enabled: false\n  mac-address: 02:20:34:a8:07:57\n  name: usb-int-br53\n  state: up\n  type: linux-bridge\n DesiredStateMetaInfo:{Version: TimeStamp:0001-01-01 00:00:00 +0000 UTC} CapturedStates:map[] PolicyGeneration:1 Conditions:[{Type:Progressing Status:True Reason:ConfigurationProgressing Message:Applying desired state LastHeartbeatTime:2024-05-28 15:48:59.21462073 +0000 UTC m=+3231.903715825 LastTransitionTime:2024-05-28 15:48:59.21462073 +0000 UTC m=+3231.903715825} {Type:Failing Status:Unknown Reason:ConfigurationProgressing Message: LastHeartbeatTime:2024-05-28 15:48:59.214621417 +0000 UTC m=+3231.903716506 LastTransitionTime:2024-05-28 15:48:59.214621417 +0000 UTC m=+3231.903716506} {Type:Available Status:Unknown Reason:ConfigurationProgressing Message: LastHeartbeatTime:2024-05-28 15:48:59.214623185 +0000 UTC m=+3231.903718275 LastTransitionTime:2024-05-28 15:48:59.214623185 +0000 UTC m=+3231.903718275} {Type:Pending Status:False Reason:ConfigurationProgressing Message: LastHeartbeatTime:2024-05-28 15:48:59.214623966 +0000 UTC m=+3231.903719056 LastTransitionTime:2024-05-28 15:48:59.214623966 +0000 UTC m=+3231.903719056} {Type:Aborted Status:False Reason:ConfigurationProgressing Message: LastHeartbeatTime:2024-05-28 15:48:59.214624079 +0000 UTC m=+3231.903719168 LastTransitionTime:2024-05-28 15:48:59.214624079 +0000 UTC m=+3231.903719168}]}","enactment":"dal4-qz4-sr7-rk047-s04.usb-int-br53-dal4-qz4-sr7-rk047-s04"}
{"level":"info","ts":"2024-05-28T15:48:59.222Z","logger":"enactmentstatus","msg":"enactment updated at the node: true","enactment":"dal4-qz4-sr7-rk047-s04.usb-int-br53-dal4-qz4-sr7-rk047-s04"}
{"level":"info","ts":"2024-05-28T15:48:59.306Z","logger":"policyconditions","msg":"numberOfNmstateMatchingNodes: 1, enactments count: {failed: {true: 0, false: 0, unknown: 1}, progressing: {true: 1, false: 0, unknown: 0}, pending: {true: 0, false: 1, unknown: 0}, available: {true: 0, false: 0, unknown: 1}, aborted: {true: 0, false: 1, unknown: 0}}","policy":"usb-int-br53-dal4-qz4-sr7-rk047-s04"}
{"level":"info","ts":"2024-05-28T15:48:59.306Z","logger":"policyconditions","msg":"SetPolicyProgressing"}
{"level":"info","ts":"2024-05-28T15:49:03.879Z","logger":"probe","msg":"Running 'ping' probe"}
{"level":"info","ts":"2024-05-28T15:49:04.581Z","logger":"probe","msg":"Running 'dns' probe"}
{"level":"info","ts":"2024-05-28T15:49:05.185Z","logger":"probe","msg":"Running 'api-server' probe"}
I0528 15:49:06.236434       1 request.go:601] Waited for 1.046322626s due to client-side throttling, not priority and fairness, request: GET:https://172.16.0.1:443/apis/objectbucket.io/v1alpha1?timeout=32s
{"level":"info","ts":"2024-05-28T15:49:07.048Z","logger":"probe","msg":"Running 'node-readiness' probe"}
{"level":"info","ts":"2024-05-28T15:49:07.063Z","logger":"controllers.NodeNetworkConfigurationPolicy","msg":"nmstate","nodenetworkconfigurationpolicy":"/usb-int-br53-dal4-qz4-sr7-rk047-s04","output":"setOutput: dns-resolver: {}\nroute-rules: {}\nroutes: {}\ninterfaces:\n- name: usb-int-br53\n  type: linux-bridge\n  state: up\n  mac-address: 02:20:34:a8:07:57\n  ipv4:\n    enabled: false\n    dhcp: false\n  bridge:\n    options:\n      stp:\n        enabled: false\n    port:\n    - name: usb-int-v53\n      vlan:\n        mode: trunk\n        trunk-tags:\n        - id-range:\n            min: 2\n            max: 4094\novs-db: {}\novn: {}\n\n \n"}
{"level":"info","ts":"2024-05-28T15:49:07.063Z","logger":"enactmentconditions","msg":"NotifySuccess","enactment":"dal4-qz4-sr7-rk047-s04.usb-int-br53-dal4-qz4-sr7-rk047-s04"}
{"level":"info","ts":"2024-05-28T15:49:07.067Z","logger":"enactmentstatus","msg":"status: {DesiredState:interfaces:\n- bridge:\n    options:\n      stp:\n        enabled: false\n    port:\n    - name: usb-int-v53\n      vlan:\n        mode: trunk\n        trunk-tags:\n        - id-range:\n            max: 4094\n            min: 2\n  ipv4:\n    dhcp: false\n    enabled: false\n  mac-address: 02:20:34:a8:07:57\n  name: usb-int-br53\n  state: up\n  type: linux-bridge\n DesiredStateMetaInfo:{Version: TimeStamp:0001-01-01 00:00:00 +0000 UTC} CapturedStates:map[] PolicyGeneration:1 Conditions:[{Type:Progressing Status:False Reason:SuccessfullyConfigured Message: LastHeartbeatTime:2024-05-28 15:49:07.067145399 +0000 UTC m=+3239.756240528 LastTransitionTime:2024-05-28 15:49:07.067145399 +0000 UTC m=+3239.756240528} {Type:Failing Status:False Reason:SuccessfullyConfigured Message: LastHeartbeatTime:2024-05-28 15:49:07.067145008 +0000 UTC m=+3239.756240137 LastTransitionTime:2024-05-28 15:49:07.067145008 +0000 UTC m=+3239.756240137} {Type:Available Status:True Reason:SuccessfullyConfigured Message:successfully reconciled LastHeartbeatTime:2024-05-28 15:49:07.067144298 +0000 UTC m=+3239.756239442 LastTransitionTime:2024-05-28 15:49:07.067144298 +0000 UTC m=+3239.756239442} {Type:Pending Status:False Reason:SuccessfullyConfigured Message: LastHeartbeatTime:2024-05-28 15:49:07.06714591 +0000 UTC m=+3239.756241040 LastTransitionTime:2024-05-28 15:48:59 +0000 UTC} {Type:Aborted Status:False Reason:SuccessfullyConfigured Message: LastHeartbeatTime:2024-05-28 15:49:07.067146601 +0000 UTC m=+3239.756241728 LastTransitionTime:2024-05-28 15:48:59 +0000 UTC}]}","enactment":"dal4-qz4-sr7-rk047-s04.usb-int-br53-dal4-qz4-sr7-rk047-s04"}
{"level":"info","ts":"2024-05-28T15:49:07.082Z","logger":"enactmentstatus","msg":"enactment updated at the node: true","enactment":"dal4-qz4-sr7-rk047-s04.usb-int-br53-dal4-qz4-sr7-rk047-s04"}
{"level":"info","ts":"2024-05-28T15:49:07.082Z","logger":"controllers.NodeNetworkConfigurationPolicy.forceNNSRefresh","msg":"forcing NodeNetworkState refresh after NNCP applied","node":"dal4-qz4-sr7-rk047-s04"}
{"level":"info","ts":"2024-05-28T15:49:07.319Z","logger":"policyconditions","msg":"numberOfNmstateMatchingNodes: 1, enactments count: {failed: {true: 0, false: 1, unknown: 0}, progressing: {true: 0, false: 1, unknown: 0}, pending: {true: 0, false: 1, unknown: 0}, available: {true: 1, false: 0, unknown: 0}, aborted: {true: 0, false: 1, unknown: 0}}","policy":"usb-int-br53-dal4-qz4-sr7-rk047-s04"}
{"level":"info","ts":"2024-05-28T15:49:07.320Z","logger":"policyconditions","msg":"SetPolicySuccess"}
{"level":"info","ts":"2024-05-28T15:49:07.335Z","logger":"controllers.NodeNetworkConfigurationPolicy","msg":"Policy node selectors does not match node, removing previous enactment if any","nodenetworkconfigurationpolicy":"/cos-dp-br53-dal4-qz4-sr7-rk047-s06"}
{"level":"info","ts":"2024-05-28T15:49:07.421Z","logger":"policyconditions","msg":"numberOfNmstateMatchingNodes: 1, enactments count: {failed: {true: 0, false: 1, unknown: 0}, progressing: {true: 0, false: 1, unknown: 0}, pending: {true: 0, false: 1, unknown: 0}, available: {true: 1, false: 0, unknown: 0}, aborted: {true: 0, false: 1, unknown: 0}}","policy":"cos-dp-br53-dal4-qz4-sr7-rk047-s06"}
{"level":"info","ts":"2024-05-28T15:49:07.421Z","logger":"policyconditions","msg":"SetPolicySuccess"}
{"level":"info","ts":"2024-05-28T15:49:07.435Z","logger":"controllers.NodeNetworkConfigurationPolicy","msg":"Policy node selectors does not match node, removing previous enactment if any","nodenetworkconfigurationpolicy":"/svc-uc-v108-dal4-qz4-sr7-rk046-s06"}
{"level":"info","ts":"2024-05-28T15:49:07.518Z","logger":"policyconditions","msg":"numberOfNmstateMatchingNodes: 1, enactments count: {failed: {true: 0, false: 1, unknown: 0}, progressing: {true: 0, false: 1, unknown: 0}, pending: {true: 0, false: 1, unknown: 0}, available: {true: 1, false: 0, unknown: 0}, aborted: {true: 0, false: 1, unknown: 0}}","policy":"svc-uc-v108-dal4-qz4-sr7-rk046-s06"}
{"level":"info","ts":"2024-05-28T15:49:07.518Z","logger":"policyconditions","msg":"SetPolicySuccess"}
{"level":"info","ts":"2024-05-28T15:49:07.533Z","logger":"controllers.NodeNetworkConfigurationPolicy","msg":"Policy node selectors does not match node, removing previous enactment if any","nodenetworkconfigurationpolicy":"/default-br90-dal4-qz4-sr7-rk049-s06"}
{"level":"info","ts":"2024-05-28T15:49:07.620Z","logger":"policyconditions","msg":"numberOfNmstateMatchingNodes: 1, enactments count: {failed: {true: 0, false: 1, unknown: 0}, progressing: {true: 0, false: 1, unknown: 0}, pending: {true: 0, false: 1, unknown: 0}, available: {true: 1, false: 0, unknown: 0}, aborted: {true: 0, false: 1, unknown: 0}}","policy":"default-br90-dal4-qz4-sr7-rk049-s06"}
{"level":"info","ts":"2024-05-28T15:49:07.620Z","logger":"policyconditions","msg":"SetPolicySuccess"}
{"level":"info","ts":"2024-05-28T15:49:07.635Z","logger":"controllers.NodeNetworkConfigurationPolicy","msg":"Policy node selectors does not match node, removing previous enactment if any","nodenetworkconfigurationpolicy":"/svc-uc-v39-dal4-qz4-sr7-rk048-s06"}
{"level":"info","ts":"2024-05-28T15:49:07.721Z","logger":"policyconditions","msg":"numberOfNmstateMatchingNodes: 1, enactments count: {failed: {true: 0, false: 1, unknown: 0}, progressing: {true: 0, false: 1, unknown: 0}, pending: {true: 0, false: 1, unknown: 0}, available: {true: 1, false: 0, unknown: 0}, aborted: {true: 0, false: 1, unknown: 0}}","policy":"svc-uc-v39-dal4-qz4-sr7-rk048-s06"}
{"level":"info","ts":"2024-05-28T15:49:07.721Z","logger":"policyconditions","msg":"SetPolicySuccess"}
{"level":"info","ts":"2024-05-28T15:49:07.738Z","logger":"controllers.NodeNetworkConfigurationPolicy","msg":"Policy node selectors does not match node, removing previous enactment if any","nodenetworkconfigurationpolicy":"/usb-int-br106-dal4-qz4-sr7-rk048-s06"}
{"level":"info","ts":"2024-05-28T15:49:07.819Z","logger":"policyconditions","msg":"numberOfNmstateMatchingNodes: 1, enactments count: {failed: {true: 0, false: 1, unknown: 0}, progressing: {true: 0, false: 1, unknown: 0}, pending: {true: 0, false: 1, unknown: 0}, available: {true: 1, false: 0, unknown: 0}, aborted: {true: 0, false: 1, unknown: 0}}","policy":"usb-int-br106-dal4-qz4-sr7-rk048-s06"}
{"level":"info","ts":"2024-05-28T15:49:07.819Z","logger":"policyconditions","msg":"SetPolicySuccess"}
{"level":"info","ts":"2024-05-28T15:49:07.835Z","logger":"controllers.NodeNetworkConfigurationPolicy","msg":"Policy node selectors does not match node, removing previous enactment if any","nodenetworkconfigurationpolicy":"/svc-uc-br37-dal4-qz4-sr7-rk047-s06"}
{"level":"info","ts":"2024-05-28T15:49:07.920Z","logger":"policyconditions","msg":"numberOfNmstateMatchingNodes: 1, enactments count: {failed: {true: 0, false: 1, unknown: 0}, progressing: {true: 0, false: 1, unknown: 0}, pending: {true: 0, false: 1, unknown: 0}, available: {true: 1, false: 0, unknown: 0}, aborted: {true: 0, false: 1, unknown: 0}}","policy":"svc-uc-br37-dal4-qz4-sr7-rk047-s06"}
{"level":"info","ts":"2024-05-28T15:49:07.920Z","logger":"policyconditions","msg":"SetPolicySuccess"}
{"level":"info","ts":"2024-05-28T15:49:07.935Z","logger":"controllers.NodeNetworkConfigurationPolicy","msg":"Policy node selectors does not match node, removing previous enactment if any","nodenetworkconfigurationpolicy":"/svc-uc-v37-dal4-qz4-sr7-rk048-s06"}
{"level":"info","ts":"2024-05-28T15:49:08.050Z","logger":"policyconditions","msg":"numberOfNmstateMatchingNodes: 1, enactments count: {failed: {true: 0, false: 1, unknown: 0}, progressing: {true: 0, false: 1, unknown: 0}, pending: {true: 0, false: 1, unknown: 0}, available: {true: 1, false: 0, unknown: 0}, aborted: {true: 0, false: 1, unknown: 0}}","policy":"svc-uc-v37-dal4-qz4-sr7-rk048-s06"}
{"level":"info","ts":"2024-05-28T15:49:08.050Z","logger":"policyconditions","msg":"SetPolicySuccess"}
{"level":"info","ts":"2024-05-28T15:49:08.069Z","logger":"controllers.NodeNetworkConfigurationPolicy","msg":"Policy node selectors does not match node, removing previous enactment if any","nodenetworkconfigurationpolicy":"/svc-vsi-br107-dal4-qz4-sr7-rk048-s06"}
{"level":"info","ts":"2024-05-28T15:49:08.157Z","logger":"policyconditions","msg":"numberOfNmstateMatchingNodes: 1, enactments count: {failed: {true: 0, false: 1, unknown: 0}, progressing: {true: 0, false: 1, unknown: 0}, pending: {true: 0, false: 1, unknown: 0}, available: {true: 1, false: 0, unknown: 0}, aborted: {true: 0, false: 1, unknown: 0}}","policy":"svc-vsi-br107-dal4-qz4-sr7-rk048-s06"}
{"level":"info","ts":"2024-05-28T15:49:08.157Z","logger":"policyconditions","msg":"SetPolicySuccess"}
{"level":"info","ts":"2024-05-28T15:49:08.173Z","logger":"controllers.NodeNetworkConfigurationPolicy","msg":"Policy node selectors does not match node, removing previous enactment if any","nodenetworkconfigurationpolicy":"/svc-uc-v108-dal4-qz4-sr7-rk049-s06"}
{"level":"info","ts":"2024-05-28T15:49:08.263Z","logger":"policyconditions","msg":"numberOfNmstateMatchingNodes: 1, enactments count: {failed: {true: 0, false: 1, unknown: 0}, progressing: {true: 0, false: 1, unknown: 0}, pending: {true: 0, false: 1, unknown: 0}, available: {true: 1, false: 0, unknown: 0}, aborted: {true: 0, false: 1, unknown: 0}}","policy":"svc-uc-v108-dal4-qz4-sr7-rk049-s06"}
{"level":"info","ts":"2024-05-28T15:49:08.263Z","logger":"policyconditions","msg":"SetPolicySuccess"}
{"level":"info","ts":"2024-05-28T15:49:08.279Z","logger":"controllers.NodeNetworkConfigurationPolicy","msg":"Policy node selectors does not match node, removing previous enactment if any","nodenetworkconfigurationpolicy":"/default-br90-dal4-qz4-sr7-rk048-s06"}
{"level":"info","ts":"2024-05-28T15:49:08.366Z","logger":"policyconditions","msg":"numberOfNmstateMatchingNodes: 1, enactments count: {failed: {true: 0, false: 1, unknown: 0}, progressing: {true: 0, false: 1, unknown: 0}, pending: {true: 0, false: 1, unknown: 0}, available: {true: 1, false: 0, unknown: 0}, aborted: {true: 0, false: 1, unknown: 0}}","policy":"default-br90-dal4-qz4-sr7-rk048-s06"}
{"level":"info","ts":"2024-05-28T15:49:08.366Z","logger":"policyconditions","msg":"SetPolicySuccess"}
{"level":"info","ts":"2024-05-28T15:49:08.382Z","logger":"controllers.NodeNetworkConfigurationPolicy","msg":"Policy node selectors does not match node, removing previous enactment if any","nodenetworkconfigurationpolicy":"/svc-uc-br43-dal4-qz4-sr7-rk048-s06"}
{"level":"info","ts":"2024-05-28T15:49:08.466Z","logger":"policyconditions","msg":"numberOfNmstateMatchingNodes: 1, enactments count: {failed: {true: 0, false: 1, unknown: 0}, progressing: {true: 0, false: 1, unknown: 0}, pending: {true: 0, false: 1, unknown: 0}, available: {true: 1, false: 0, unknown: 0}, aborted: {true: 0, false: 1, unknown: 0}}","policy":"svc-uc-br43-dal4-qz4-sr7-rk048-s06"}
{"level":"info","ts":"2024-05-28T15:49:08.466Z","logger":"policyconditions","msg":"SetPolicySuccess"}
{"level":"info","ts":"2024-05-28T15:49:08.482Z","logger":"controllers.NodeNetworkConfigurationPolicy","msg":"Policy node selectors does not match node, removing previous enactment if any","nodenetworkconfigurationpolicy":"/svc-vsi-v107-dal4-qz4-sr7-rk048-s06"}
{"level":"info","ts":"2024-05-28T15:49:08.567Z","logger":"policyconditions","msg":"numberOfNmstateMatchingNodes: 1, enactments count: {failed: {true: 0, false: 1, unknown: 0}, progressing: {true: 0, false: 1, unknown: 0}, pending: {true: 0, false: 1, unknown: 0}, available: {true: 1, false: 0, unknown: 0}, aborted: {true: 0, false: 1, unknown: 0}}","policy":"svc-vsi-v107-dal4-qz4-sr7-rk048-s06"}
{"level":"info","ts":"2024-05-28T15:49:08.567Z","logger":"policyconditions","msg":"SetPolicySuccess"}
{"level":"info","ts":"2024-05-28T15:49:08.587Z","logger":"enactmentconditions","msg":"Reset","enactment":"dal4-qz4-sr7-rk047-s04.svc-uc-v108-dal4-qz4-sr7-rk047-s04"}
{"level":"info","ts":"2024-05-28T15:49:08.590Z","logger":"enactmentstatus","msg":"status: {DesiredState:interfaces:\n- ipv4:\n    dhcp: false\n    enabled: false\n  mac-address: 02:10:2c:2c:7e:52\n  name: svc-uc-v108\n  state: up\n  type: vlan\n  vlan:\n    base-iface: bond1\n    id: 108\n DesiredStateMetaInfo:{Version: TimeStamp:0001-01-01 00:00:00 +0000 UTC} CapturedStates:map[] PolicyGeneration:1 Conditions:[]}","enactment":"dal4-qz4-sr7-rk047-s04.svc-uc-v108-dal4-qz4-sr7-rk047-s04"}
{"level":"info","ts":"2024-05-28T15:49:08.598Z","logger":"enactmentstatus","msg":"enactment updated at the node: true","enactment":"dal4-qz4-sr7-rk047-s04.svc-uc-v108-dal4-qz4-sr7-rk047-s04"}
{"level":"info","ts":"2024-05-28T15:49:09.358Z","logger":"enactmentstatus","msg":"status: {DesiredState:interfaces:\n- ipv4:\n    dhcp: false\n    enabled: false\n  mac-address: 02:10:2c:2c:7e:52\n  name: svc-uc-v108\n  state: up\n  type: vlan\n  vlan:\n    base-iface: bond1\n    id: 108\n DesiredStateMetaInfo:{Version: TimeStamp:0001-01-01 00:00:00 +0000 UTC} CapturedStates:map[] PolicyGeneration:1 Conditions:[]}","enactment":"dal4-qz4-sr7-rk047-s04.svc-uc-v108-dal4-qz4-sr7-rk047-s04"}
{"level":"info","ts":"2024-05-28T15:49:09.367Z","logger":"enactmentstatus","msg":"enactment updated at the node: true","enactment":"dal4-qz4-sr7-rk047-s04.svc-uc-v108-dal4-qz4-sr7-rk047-s04"}
{"level":"info","ts":"2024-05-28T15:49:09.474Z","logger":"enactmentconditions","msg":"NotifyProgressing","enactment":"dal4-qz4-sr7-rk047-s04.svc-uc-v108-dal4-qz4-sr7-rk047-s04"}
{"level":"info","ts":"2024-05-28T15:49:09.477Z","logger":"enactmentstatus","msg":"status: {DesiredState:interfaces:\n- ipv4:\n    dhcp: false\n    enabled: false\n  mac-address: 02:10:2c:2c:7e:52\n  name: svc-uc-v108\n  state: up\n  type: vlan\n  vlan:\n    base-iface: bond1\n    id: 108\n DesiredStateMetaInfo:{Version: TimeStamp:0001-01-01 00:00:00 +0000 UTC} CapturedStates:map[] PolicyGeneration:1 Conditions:[{Type:Progressing Status:True Reason:ConfigurationProgressing Message:Applying desired state LastHeartbeatTime:2024-05-28 15:49:09.477075435 +0000 UTC m=+3242.166170578 LastTransitionTime:2024-05-28 15:49:09.477075435 +0000 UTC m=+3242.166170578} {Type:Failing Status:Unknown Reason:ConfigurationProgressing Message: LastHeartbeatTime:2024-05-28 15:49:09.477076702 +0000 UTC m=+3242.166171846 LastTransitionTime:2024-05-28 15:49:09.477076702 +0000 UTC m=+3242.166171846} {Type:Available Status:Unknown Reason:ConfigurationProgressing Message: LastHeartbeatTime:2024-05-28 15:49:09.477077817 +0000 UTC m=+3242.166172945 LastTransitionTime:2024-05-28 15:49:09.477077817 +0000 UTC m=+3242.166172945} {Type:Pending Status:False Reason:ConfigurationProgressing Message: LastHeartbeatTime:2024-05-28 15:49:09.477079183 +0000 UTC m=+3242.166174311 LastTransitionTime:2024-05-28 15:49:09.477079183 +0000 UTC m=+3242.166174311} {Type:Aborted Status:False Reason:ConfigurationProgressing Message: LastHeartbeatTime:2024-05-28 15:49:09.477079649 +0000 UTC m=+3242.166174778 LastTransitionTime:2024-05-28 15:49:09.477079649 +0000 UTC m=+3242.166174778}]}","enactment":"dal4-qz4-sr7-rk047-s04.svc-uc-v108-dal4-qz4-sr7-rk047-s04"}
{"level":"info","ts":"2024-05-28T15:49:09.485Z","logger":"enactmentstatus","msg":"enactment updated at the node: true","enactment":"dal4-qz4-sr7-rk047-s04.svc-uc-v108-dal4-qz4-sr7-rk047-s04"}
{"level":"info","ts":"2024-05-28T15:49:09.565Z","logger":"policyconditions","msg":"numberOfNmstateMatchingNodes: 1, enactments count: {failed: {true: 0, false: 0, unknown: 1}, progressing: {true: 1, false: 0, unknown: 0}, pending: {true: 0, false: 1, unknown: 0}, available: {true: 0, false: 0, unknown: 1}, aborted: {true: 0, false: 1, unknown: 0}}","policy":"svc-uc-v108-dal4-qz4-sr7-rk047-s04"}
{"level":"info","ts":"2024-05-28T15:49:09.565Z","logger":"policyconditions","msg":"SetPolicyProgressing"}

I killed the pod and a new one properly started up. Tried the apply for another vlan interface and it still took > 60s to apply

I attached the full logs of nmstate-handler-9zkz6 logs--svc-uc-v108-apply.txt

qinqon commented 1 month ago

kubernetes-nmstate do some probes before commit the changes to ensure that it do not break the cluster, that's where the time goes on.

k8scoder192 commented 1 month ago

@qinqon did you look at the full logs? It's NOT due to the probes. The probes come back extremely quick. Something else is wrong.

Edit I also noticed this is only happening on 1 worker node. If I look at the logs of the other nmstate-handler pods, they aren't constantly reporting "enactment updated at the node: true". Something is triggering this pod to constantly perform state changes like below for all the interfaces

journalctl -S today -u NetworkManager.service -f (output on the node I see the problem on)

May 31 18:12:37 dal4-qz4-sr7-rk047-s04 NetworkManager[2025380]: <info>  [1717179157.9313] device (usb-int-v87): state change: deactivating -> disconnected (reason 'new-activation', sys-iface-state: 'managed')
May 31 18:12:37 dal4-qz4-sr7-rk047-s04 NetworkManager[2025380]: <info>  [1717179157.9321] device (usb-int-v87): Activation: starting connection 'usb-int-v87' (74ec521d-7a67-4ade-82ae-19f6892e645c)
May 31 18:12:37 dal4-qz4-sr7-rk047-s04 NetworkManager[2025380]: <info>  [1717179157.9326] device (usb-int-v87): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'managed')
May 31 18:12:37 dal4-qz4-sr7-rk047-s04 NetworkManager[2025380]: <info>  [1717179157.9342] device (usb-int-v87): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
May 31 18:12:37 dal4-qz4-sr7-rk047-s04 NetworkManager[2025380]: <info>  [1717179157.9371] device (usb-int-v87): state change: config -> ip-config (reason 'none', sys-iface-state: 'managed')
May 31 18:12:38 dal4-qz4-sr7-rk047-s04 NetworkManager[2025380]: <info>  [1717179158.0251] device (usb-int-br87): attached bridge port usb-int-v87
May 31 18:12:38 dal4-qz4-sr7-rk047-s04 NetworkManager[2025380]: <info>  [1717179158.0251] device (usb-int-v87): Activation: connection 'usb-int-v87' enslaved, continuing activation
May 31 18:12:38 dal4-qz4-sr7-rk047-s04 NetworkManager[2025380]: <info>  [1717179158.0256] device (usb-int-v87): state change: ip-config -> ip-check (reason 'none', sys-iface-state: 'managed')
May 31 18:12:38 dal4-qz4-sr7-rk047-s04 NetworkManager[2025380]: <info>  [1717179158.0281] device (usb-int-v87): state change: ip-check -> secondaries (reason 'none', sys-iface-state: 'managed')
May 31 18:12:38 dal4-qz4-sr7-rk047-s04 NetworkManager[2025380]: <info>  [1717179158.0283] device (usb-int-v87): state change: secondaries -> activated (reason 'none', sys-iface-state: 'managed')
May 31 18:12:38 dal4-qz4-sr7-rk047-s04 NetworkManager[2025380]: <info>  [1717179158.0287] device (usb-int-v87): Activation: successful, device activated.
May 31 18:12:42 dal4-qz4-sr7-rk047-s04 NetworkManager[2025380]: <info>  [1717179162.9356] checkpoint[0x55bcd4c8d450]: destroy /org/freedesktop/NetworkManager/Checkpoint/292
May 31 18:12:42 dal4-qz4-sr7-rk047-s04 NetworkManager[2025380]: <info>  [1717179162.9390] audit: op="checkpoint-destroy" arg="/org/freedesktop/NetworkManager/Checkpoint/292" pid=2292492 uid=0 result="success"
May 31 18:12:46 dal4-qz4-sr7-rk047-s04 NetworkManager[2025380]: <info>  [1717179166.5941] audit: op="checkpoint-create" arg="/org/freedesktop/NetworkManager/Checkpoint/293" pid=2292893 uid=0 result="success"
May 31 18:12:46 dal4-qz4-sr7-rk047-s04 NetworkManager[2025380]: <info>  [1717179166.5968] audit: op="checkpoint-adjust-rollback-timeout" arg="/org/freedesktop/NetworkManager/Checkpoint/293" pid=2292893 uid=0 result="success"
May 31 18:12:47 dal4-qz4-sr7-rk047-s04 NetworkManager[2025380]: <info>  [1717179167.3864] audit: op="connection-update" uuid="c504a0fa-730b-4182-8b98-f404ab44c196" name="usb-int-br67" args="connection.timestamp" pid=2292893 uid=0 result="success"
May 31 18:12:47 dal4-qz4-sr7-rk047-s04 NetworkManager[2025380]: <info>  [1717179167.5521] audit: op="device-reapply" interface="usb-int-br67" ifindex=177998 pid=2292893 uid=0 result="success"
May 31 18:12:47 dal4-qz4-sr7-rk047-s04 NetworkManager[2025380]: <info>  [1717179167.5563] audit: op="checkpoint-adjust-rollback-timeout" arg="/org/freedesktop/NetworkManager/Checkpoint/293" pid=2292893 uid=0 result="succe

When I look at NNCP for that node, they are constantly going from "Available SuccessfullyConfigured" to blank status then back to "Available SuccessfullyConfigured". When that happens I see the above journalctl output for that particular interface.

I really need to figure out why k8s nmstate is behaving this way. This node's nmstate-handler pod restarted this week. The other node's pods have been up for 200+ days. I'm afraid to bound the other node's pods because of this odd behavior.