azure-container-networking: [cni] Timed out on locking store, err:Store is locked.

Is this a request for help?:

Yes.

Is this an ISSUE or FEATURE REQUEST? (choose one):

ISSUE.

Which release version?:

Plugin azure-vnet version v1.0.10.

Which component (CNI/IPAM/CNM/CNS):

CNI

Which Operating System (Linux/Windows):

Windows Server 1803

PS C:\k> $(Get-ItemProperty -Path "C:\windows\system32\hal.dll").VersionInfo.FileVersion
10.0.17134.1 (WinBuild.160101.0800)

---

Which Orchestrator and version (e.g. Kubernetes, Docker)

S C:\k> .\kubectl.exe version
Client Version: version.Info{Major:"1", Minor:"11", GitVersion:"v1.11.1", GitCommit:"b1b29978270dc22fecc592ac55d903350454310a", GitTreeState:"clean", BuildDate:"2018-07-17T18:53:20Z", GoVersion:"go1.10.3", Compiler:"gc", Platform:"windows/amd64"}

What happened: Windows containers can’t start.

2018/08/31 04:37:22 [cni] Timed out on locking store, err:Store is locked.
2018/08/31 04:37:22 Failed to initialize key-value store of network plugin, err:Store is locked.
2018/08/31 04:37:22 Report plugin error
2018/08/31 04:37:22 [cni] Timed out on locking store, err:Store is locked.
2018/08/31 04:37:22 Failed to initialize key-value store of network plugin, err:Store is locked.
2018/08/31 04:37:22 Report plugin error
2018/08/31 04:37:22 Going to send Telemetry report to hostnetagent http://169.254.169.254/machine/plugins?comp=netagent&type=cnireport
2018/08/31 04:37:22 "Start Flag false CniSucceeded false Name CNI Version v1.0.10 ErrorMessage Store is locked vnet [] 
				Context AzureCNI SubContext "
2018/08/31 04:37:22 OrchestratorDetails &{  kubectl command failed due to exit status 1}
2018/08/31 04:37:22 OSDetails &{windows    }
2018/08/31 04:37:22 SystemDetails &{0 0 0 0 0 0 }
2018/08/31 04:37:22 InterfaceDetails &{Primary 10.240.0.0/12 10.240.0.127 00:0d:3a:2f:bd:ac vEthernet (Ethernet 2) 30 0 }
2018/08/31 04:37:22 BridgeDetails <nil>
2018/08/31 04:37:22 Going to send Telemetry report to hostnetagent http://169.254.169.254/machine/plugins?comp=netagent&type=cnireport
2018/08/31 04:37:22 "Start Flag false CniSucceeded false Name CNI Version v1.0.10 ErrorMessage Store is locked vnet [] 
				Context AzureCNI SubContext "
2018/08/31 04:37:22 OrchestratorDetails &{  kubectl command failed due to exit status 1}
2018/08/31 04:37:22 OSDetails &{windows    }
2018/08/31 04:37:22 SystemDetails &{0 0 0 0 0 0 }
2018/08/31 04:37:22 InterfaceDetails &{Primary 10.240.0.0/12 10.240.0.127 00:0d:3a:2f:bd:ac vEthernet (Ethernet 2) 30 0 }
2018/08/31 04:37:22 BridgeDetails <nil>
2018/08/31 04:37:22 Send telemetry success 200
2018/08/31 04:37:22 SetReportState succeeded
2018/08/31 04:37:22 Send telemetry success 200
2018/08/31 04:37:22 SetReportState succeeded
E0831 04:37:22.384629    3540 cni.go:280] Error deleting network: netplugin failed but error parsing its diagnostic message "": unexpected end of JSON input
E0831 04:37:22.384629    3540 remote_runtime.go:115] StopPodSandbox "982a32ac758ba632a7f5feb185f9c27ad2a83899c2678e44f1f27fe7edf98470" from runtime service failed: rpc error: code = Unknown desc = NetworkPlugin cni failed to teardown pod "omega-75977c8875-kdr8r_default" network: netplugin failed but error parsing its diagnostic message "": unexpected end of JSON input
E0831 04:37:22.385560    3540 kuberuntime_gc.go:153] Failed to stop sandbox "982a32ac758ba632a7f5feb185f9c27ad2a83899c2678e44f1f27fe7edf98470" before removing: rpc error: code = Unknown desc = NetworkPlugin cni failed to teardown pod "omega-75977c8875-kdr8r_default" network: netplugin failed but error parsing its diagnostic message "": unexpected end of JSON input
E0831 04:37:22.386548    3540 cni.go:280] Error deleting network: netplugin failed but error parsing its diagnostic message "": unexpected end of JSON input
E0831 04:37:22.388545    3540 remote_runtime.go:115] StopPodSandbox "c6ae99e68ba79e053cd0e9dbb9790a18ba2c87ba77e897e0133aee2d81b260ff" from runtime service failed: rpc error: code = Unknown desc = NetworkPlugin cni failed to teardown pod "omega-56957d9b4f-n74ng_default" network: netplugin failed but error parsing its diagnostic message "": unexpected end of JSON input
E0831 04:37:22.388545    3540 kuberuntime_manager.go:799] Failed to stop sandbox {"docker" "c6ae99e68ba79e053cd0e9dbb9790a18ba2c87ba77e897e0133aee2d81b260ff"}
E0831 04:37:22.388545    3540 kuberuntime_manager.go:594] killPodWithSyncResult failed: failed to "KillPodSandbox" for "10373f27-ac8d-11e8-957b-000d3a2fb36b" with KillPodSandboxError: "rpc error: code = Unknown desc = NetworkPlugin cni failed to teardown pod \"omega-56957d9b4f-n74ng_default\" network: netplugin failed but error parsing its diagnostic message \"\": unexpected end of JSON input"
E0831 04:37:22.388545    3540 pod_workers.go:186] Error syncing pod 10373f27-ac8d-11e8-957b-000d3a2fb36b ("omega-56957d9b4f-n74ng_default(10373f27-ac8d-11e8-957b-000d3a2fb36b)"), skipping: failed to "KillPodSandbox" for "10373f27-ac8d-11e8-957b-000d3a2fb36b" with KillPodSandboxError: "rpc error: code = Unknown desc = NetworkPlugin cni failed to teardown pod \"omega-56957d9b4f-n74ng_default\" network: netplugin failed but error parsing its diagnostic message \"\": unexpected end of JSON input"
I0831 04:37:22.980153    3540 kuberuntime_manager.go:403] No ready sandbox for pod "omega-56957d9b4f-vvc4b_default(103ab3cc-ac8d-11e8-957b-000d3a2fb36b)" can be found. Need to start a new one
E0831 04:37:23.523553    3540 helpers.go:735] eviction manager: failed to construct signal: "allocatableMemory.available" error: system container "pods" not found in metrics
W0831 04:37:23.523553    3540 helpers.go:808] eviction manager: no observation found for eviction signal nodefs.inodesFree
2018/08/31 04:37:24 [cni] Timed out on locking store, err:Store is locked.
2018/08/31 04:37:24 Failed to initialize key-value store of network plugin, err:Store is locked.
2018/08/31 04:37:24 Report plugin error
2018/08/31 04:37:24 Going to send Telemetry report to hostnetagent http://169.254.169.254/machine/plugins?comp=netagent&type=cnireport
2018/08/31 04:37:24 "Start Flag false CniSucceeded false Name CNI Version v1.0.10 ErrorMessage Store is locked vnet [] 
				Context AzureCNI SubContext "
2018/08/31 04:37:24 OrchestratorDetails &{  kubectl command failed due to exit status 1}
2018/08/31 04:37:24 OSDetails &{windows    }
2018/08/31 04:37:24 SystemDetails &{0 0 0 0 0 0 }
2018/08/31 04:37:24 InterfaceDetails &{Primary 10.240.0.0/12 10.240.0.127 00:0d:3a:2f:bd:ac vEthernet (Ethernet 2) 30 0 }
2018/08/31 04:37:24 BridgeDetails <nil>
2018/08/31 04:37:24 Send telemetry success 200
2018/08/31 04:37:24 SetReportState succeeded
E0831 04:37:24.725070    3540 cni.go:280] Error deleting network: netplugin failed but error parsing its diagnostic message "": unexpected end of JSON input
E0831 04:37:24.727071    3540 remote_runtime.go:115] StopPodSandbox "fdd2080644a1a376a1bcd7c24bd10b2c276dc738fd1a7315cf99c89ac1ea4a44" from runtime service failed: rpc error: code = Unknown desc = NetworkPlugin cni failed to teardown pod "omega-75977c8875-kdr8r_default" network: netplugin failed but error parsing its diagnostic message "": unexpected end of JSON input
E0831 04:37:24.727071    3540 kuberuntime_gc.go:153] Failed to stop sandbox "fdd2080644a1a376a1bcd7c24bd10b2c276dc738fd1a7315cf99c89ac1ea4a44" before removing: rpc error: code = Unknown desc = NetworkPlugin cni failed to teardown pod "omega-75977c8875-kdr8r_default" network: netplugin failed but error parsing its diagnostic message "": unexpected end of JSON input
2018/08/31 04:37:25 [cni] Timed out on locking store, err:Store is locked.
2018/08/31 04:37:25 Failed to initialize key-value store of network plugin, err:Store is locked.
2018/08/31 04:37:25 Report plugin error
2018/08/31 04:37:25 Going to send Telemetry report to hostnetagent http://169.254.169.254/machine/plugins?comp=netagent&type=cnireport
2018/08/31 04:37:25 "Start Flag false CniSucceeded false Name CNI Version v1.0.10 ErrorMessage Store is locked vnet [] 
				Context AzureCNI SubContext "
2018/08/31 04:37:25 OrchestratorDetails &{  kubectl command failed due to exit status 1}
2018/08/31 04:37:25 OSDetails &{windows    }
2018/08/31 04:37:25 SystemDetails &{0 0 0 0 0 0 }
2018/08/31 04:37:25 InterfaceDetails &{Primary 10.240.0.0/12 10.240.0.127 00:0d:3a:2f:bd:ac vEthernet (Ethernet 2) 30 0 }
2018/08/31 04:37:25 BridgeDetails <nil>
2018/08/31 04:37:25 Send telemetry success 200
2018/08/31 04:37:25 SetReportState succeeded
E0831 04:37:25.292113    3540 cni.go:280] Error deleting network: netplugin failed but error parsing its diagnostic message "": unexpected end of JSON input
E0831 04:37:25.292113    3540 remote_runtime.go:115] StopPodSandbox "54d875a7d4c241270bb044e618d70d7563d89a1782c5fc4736aa2dcaf8d20c35" from runtime service failed: rpc error: code = Unknown desc = NetworkPlugin cni failed to teardown pod "omega-56957d9b4f-vvc4b_default" network: netplugin failed but error parsing its diagnostic message "": unexpected end of JSON input
E0831 04:37:25.292113    3540 kuberuntime_manager.go:799] Failed to stop sandbox {"docker" "54d875a7d4c241270bb044e618d70d7563d89a1782c5fc4736aa2dcaf8d20c35"}
E0831 04:37:25.292113    3540 kuberuntime_manager.go:594] killPodWithSyncResult failed: failed to "KillPodSandbox" for "103ab3cc-ac8d-11e8-957b-000d3a2fb36b" with KillPodSandboxError: "rpc error: code = Unknown desc = NetworkPlugin cni failed to teardown pod \"omega-56957d9b4f-vvc4b_default\" network: netplugin failed but error parsing its diagnostic message \"\": unexpected end of JSON input"
E0831 04:37:25.293019    3540 pod_workers.go:186] Error syncing pod 103ab3cc-ac8d-11e8-957b-000d3a2fb36b ("omega-56957d9b4f-vvc4b_default(103ab3cc-ac8d-11e8-957b-000d3a2fb36b)"), skipping: failed to "KillPodSandbox" for "103ab3cc-ac8d-11e8-957b-000d3a2fb36b" with KillPodSandboxError: "rpc error: code = Unknown desc = NetworkPlugin cni failed to teardown pod \"omega-56957d9b4f-vvc4b_default\" network: netplugin failed but error parsing its diagnostic message \"\": unexpected end of JSON input"
2018/08/31 04:37:26 [cni] Timed out on locking store, err:Store is locked.
2018/08/31 04:37:26 Failed to initialize key-value store of network plugin, err:Store is locked.
2018/08/31 04:37:26 Report plugin error
2018/08/31 04:37:26 Going to send Telemetry report to hostnetagent http://169.254.169.254/machine/plugins?comp=netagent&type=cnireport
2018/08/31 04:37:26 "Start Flag false CniSucceeded false Name CNI Version v1.0.10 ErrorMessage Store is locked vnet [] 
				Context AzureCNI SubContext "
2018/08/31 04:37:26 OrchestratorDetails &{  kubectl command failed due to exit status 1}
2018/08/31 04:37:26 OSDetails &{windows    }
2018/08/31 04:37:26 SystemDetails &{0 0 0 0 0 0 }
2018/08/31 04:37:26 InterfaceDetails &{Primary 10.240.0.0/12 10.240.0.127 00:0d:3a:2f:bd:ac vEthernet (Ethernet 2) 30 0 }
2018/08/31 04:37:26 BridgeDetails <nil>
2018/08/31 04:37:26 Send telemetry success 200
2018/08/31 04:37:26 SetReportState succeeded
E0831 04:37:27.004305    3540 cni.go:280] Error deleting network: netplugin failed but error parsing its diagnostic message "": unexpected end of JSON input
E0831 04:37:27.004305    3540 remote_runtime.go:115] StopPodSandbox "5d7824902507684675fb387f26c64b5cfd8a8275bacf153b09a130676154ce0f" from runtime service failed: rpc error: code = Unknown desc = NetworkPlugin cni failed to teardown pod "omega-75977c8875-kdr8r_default" network: netplugin failed but error parsing its diagnostic message "": unexpected end of JSON input
E0831 04:37:27.004305    3540 kuberuntime_gc.go:153] Failed to stop sandbox "5d7824902507684675fb387f26c64b5cfd8a8275bacf153b09a130676154ce0f" before removing: rpc error: code = Unknown desc = NetworkPlugin cni failed to teardown pod "omega-75977c8875-kdr8r_default" network: netplugin failed but error parsing its diagnostic message "": unexpected end of JSON input

---

What you expected to happen:

No errors.

How to reproduce it (as minimally and precisely as possible):

We just have an hybrid cluster, with one Windows node. This consistantly happens each time we start a container. This problem appeared when we migrated to Windows Server 1803.

Anything else we need to know:

Two related issues that have been open for several months now. https://github.com/Azure/azure-container-networking/issues/145 https://github.com/Azure/azure-container-networking/issues/232