Pod does not start if cni deployed as a network add-on

[vikas choudhary]

WORKAROUND:
In the "default" section of kuryr.conf add "use_stderr = true"
[DEFAULT]
use_stderr = true

Error log is pod status:
0s 0s 1 kubelet, dell-r620-01.perf.lab.eng.rdu.redhat.com Warning FailedSync Error syncing pod, skipping:failed to "CreatePodSandbox" for "my.pod1_kube-system(01a1265d-574d-11e7-8d87-bc305bf4e400)" with CreatePodSandboxError: "CreatePodSandbox for pod \"my.pod1_kube-system(01a1265d-574d-11e7-8d87-bc305bf4e400)\" failed: rpc error: code = 2 desc = NetworkPlugin cni failed to set up pod \"my.pod1_kube-system\" network: invalid character '-' after top-level value"

More logs from kubelet:
Jun 22 04:56:35 dell-r620-01.perf.lab.eng.rdu.redhat.com kubelet[14290]: 2017-06-22 04:56:35.531 9179 INFO kuryr_kubernetes.watcher [-] Stopped watching '/api/v1/namespaces/kube-system/pods?fieldSelector=metadata.name=my.pod1'
Jun 22 04:56:35 dell-r620-01.perf.lab.eng.rdu.redhat.com kubelet[14290]: 2017-06-22 04:56:35.531 9179 DEBUG kuryr_kubernetes.cni.api [-] CNI output: {'cniVersion': '0.3.0', 'ip4': {'ip': '10.0.0.11/26', 'gateway': '10.0.0.1'}} _write_dict site-packages/kuryr_kubernetes/cni/api.py:106
Jun 22 04:56:35 dell-r620-01.perf.lab.eng.rdu.redhat.com kubelet[14290]: 2017-06-22 04:56:35.532 9179 DEBUG kuryr_kubernetes.cni.main [-] Exiting with status 0 run site-packages/kuryr_kubernetes/cni/main.py:99
Jun 22 04:56:35 dell-r620-01.perf.lab.eng.rdu.redhat.com kubelet[14290]: Error in sys.excepthook:
Jun 22 04:56:35 dell-r620-01.perf.lab.eng.rdu.redhat.com kubelet[14290]: Traceback (most recent call last):
Jun 22 04:56:35 dell-r620-01.perf.lab.eng.rdu.redhat.com kubelet[14290]: File "site-packages/oslo_log/log.py", line 193, in logging_excepthook
Jun 22 04:56:35 dell-r620-01.perf.lab.eng.rdu.redhat.com kubelet[14290]: File "logging/__init__.py", line 1481, in critical
Jun 22 04:56:35 dell-r620-01.perf.lab.eng.rdu.redhat.com kubelet[14290]: File "logging/__init__.py", line 1212, in critical
Jun 22 04:56:35 dell-r620-01.perf.lab.eng.rdu.redhat.com kubelet[14290]: File "logging/__init__.py", line 1286, in _log
Jun 22 04:56:35 dell-r620-01.perf.lab.eng.rdu.redhat.com kubelet[14290]: File "logging/__init__.py", line 1296, in handle
Jun 22 04:56:35 dell-r620-01.perf.lab.eng.rdu.redhat.com kubelet[14290]: File "logging/__init__.py", line 1336, in callHandlers
Jun 22 04:56:35 dell-r620-01.perf.lab.eng.rdu.redhat.com kubelet[14290]: File "logging/__init__.py", line 759, in handle
Jun 22 04:56:35 dell-r620-01.perf.lab.eng.rdu.redhat.com kubelet[14290]: File "site-packages/oslo_privsep/daemon.py", line 168, in emit
Jun 22 04:56:35 dell-r620-01.perf.lab.eng.rdu.redhat.com kubelet[14290]: File "site-packages/oslo_privsep/comm.py", line 193, in send
Jun 22 04:56:35 dell-r620-01.perf.lab.eng.rdu.redhat.com kubelet[14290]: File "site-packages/oslo_privsep/comm.py", line 55, in send
Jun 22 04:56:35 dell-r620-01.perf.lab.eng.rdu.redhat.com kubelet[14290]: socket.error: [Errno 32] Broken pipe
Jun 22 04:56:35 dell-r620-01.perf.lab.eng.rdu.redhat.com kubelet[14290]: Original exception was:
Jun 22 04:56:35 dell-r620-01.perf.lab.eng.rdu.redhat.com kubelet[14290]: Traceback (most recent call last):
Jun 22 04:56:35 dell-r620-01.perf.lab.eng.rdu.redhat.com kubelet[14290]: File "kuryr-cni", line 11, in <module>
Jun 22 04:56:35 dell-r620-01.perf.lab.eng.rdu.redhat.com kubelet[14290]: File "site-packages/kuryr_kubernetes/cni/main.py", line 98, in run
Jun 22 04:56:35 dell-r620-01.perf.lab.eng.rdu.redhat.com kubelet[14290]: File "site-packages/kuryr_kubernetes/cni/api.py", line 100, in run
Jun 22 04:56:35 dell-r620-01.perf.lab.eng.rdu.redhat.com kubelet[14290]: File "site-packages/kuryr_kubernetes/cni/api.py", line 113, in _write_exception
Jun 22 04:56:35 dell-r620-01.perf.lab.eng.rdu.redhat.com kubelet[14290]: File "site-packages/kuryr_kubernetes/cni/api.py", line 106, in _write_dict
Jun 22 04:56:35 dell-r620-01.perf.lab.eng.rdu.redhat.com kubelet[14290]: File "logging/__init__.py", line 1440, in debug
Jun 22 04:56:35 dell-r620-01.perf.lab.eng.rdu.redhat.com kubelet[14290]: File "logging/__init__.py", line 1155, in debug
Jun 22 04:56:35 dell-r620-01.perf.lab.eng.rdu.redhat.com kubelet[14290]: File "logging/__init__.py", line 1286, in _log
Jun 22 04:56:35 dell-r620-01.perf.lab.eng.rdu.redhat.com kubelet[14290]: File "logging/__init__.py", line 1296, in handle
Jun 22 04:56:35 dell-r620-01.perf.lab.eng.rdu.redhat.com kubelet[14290]: File "logging/__init__.py", line 1336, in callHandlers
Jun 22 04:56:35 dell-r620-01.perf.lab.eng.rdu.redhat.com kubelet[14290]: File "logging/__init__.py", line 759, in handle
Jun 22 04:56:35 dell-r620-01.perf.lab.eng.rdu.redhat.com kubelet[14290]: File "site-packages/oslo_privsep/daemon.py", line 168, in emit
Jun 22 04:56:35 dell-r620-01.perf.lab.eng.rdu.redhat.com kubelet[14290]: File "site-packages/oslo_privsep/comm.py", line 193, in send
Jun 22 04:56:35 dell-r620-01.perf.lab.eng.rdu.redhat.com kubelet[14290]: File "site-packages/oslo_privsep/comm.py", line 55, in send
Jun 22 04:56:35 dell-r620-01.perf.lab.eng.rdu.redhat.com kubelet[14290]: socket.error: [Errno 32] Broken pipe
Jun 22 04:56:35 dell-r620-01.perf.lab.eng.rdu.redhat.com kubelet[14290]: Failed to execute script kuryr-cni
Jun 22 04:56:35 dell-r620-01.perf.lab.eng.rdu.redhat.com kubelet[14290]: I0622 04:56:35.634105 14290 kuberuntime_manager.go:622] Created PodSandbox "0b3479559f593878c6399943c95cec55d8d6ccedfa0b0a3235d2c5dfed9b0d7b" for pod "my.pod1_kube-system(a91113d3-5728-11e7-b396-bc305bf4e400)"
Jun 22 04:56:35 dell-r620-01.perf.lab.eng.rdu.redhat.com kubelet[14290]: I0622 04:56:35.645661 14290 generic.go:343] PLEG: Write status for my.pod1/kube-system: &container.PodStatus{ID:"a91113d3-5728-11e7-b396-bc305bf4e400", Name:"my.pod1", Namespace:"kube-system", IP:"10.0.0.11", ContainerStatuses:[]*container.ContainerStatus{}, SandboxStatuses:[]*runtime.PodSandboxStatus{(*runtime.PodSandboxStatus)(0xc422b26000)}} (err: <nil>)

[Michal Dulko (michal-dulko-f)]

Is this still an issue after when we have [1]?

[1] https://github.com/openstack/kuryr-kubernetes/blob/master/tools/generate_k8s_resource_definitions.sh#L83

[Michal Dulko (michal-dulko-f)]

I'm closing this as I haven't seen it either locally or in gates for some time now.

[Peng Liu (pliu)]

I hit the same issue and fixed with the same workaround.

Apr 17 02:58:08 overcloud-novacompute-1.localdomain kubelet[68180]: E0417 02:58:08.363663 68180 cni.go:259] Error adding network: invalid character '-' after top-level value
Apr 17 02:58:08 overcloud-novacompute-1.localdomain kubelet[68180]: E0417 02:58:08.363684 68180 cni.go:227] Error while adding to cni network: invalid character '-' after top-level value
Apr 17 02:58:08 overcloud-novacompute-1.localdomain kubelet[68180]: E0417 02:58:08.449707 68180 remote_runtime.go:92] RunPodSandbox from runtime service failed: rpc error: code = Unknown desc = NetworkPlugin cni failed to set up pod "kuryrpoc_default" network: invalid character '-' after top-level value
Apr 17 02:58:08 overcloud-novacompute-1.localdomain kubelet[68180]: E0417 02:58:08.449745 68180 kuberuntime_sandbox.go:54] CreatePodSandbox for pod "kuryrpoc_default(3e53763a-4189-11e8-ba27-52540049ded8)" failed: rpc error: code = Unknown desc = NetworkPlugin cni failed to set up pod "kuryrpoc_default" network: invalid character '-' after top-level value
Apr 17 02:58:08 overcloud-novacompute-1.localdomain kubelet[68180]: E0417 02:58:08.449767 68180 kuberuntime_manager.go:646] createPodSandbox for pod "kuryrpoc_default(3e53763a-4189-11e8-ba27-52540049ded8)" failed: rpc error: code = Unknown desc = NetworkPlugin cni failed to set up pod "kuryrpoc_default" network: invalid character '-' after top-level value
Apr 17 02:58:08 overcloud-novacompute-1.localdomain kubelet[68180]: E0417 02:58:08.449810 68180 pod_workers.go:186] Error syncing pod 3e53763a-4189-11e8-ba27-52540049ded8 ("kuryrpoc_default(3e53763a-4189-11e8-ba27-52540049ded8)"), skipping: failed to "CreatePodSandbox" for "kuryrpoc_default(3e53763a-4189-11e8-ba27-52540049ded8)" with CreatePodSandboxError: "CreatePodSandbox for pod \"kuryrpoc_default(3e53763a-4189-11e8-ba27-52540049ded8)\" failed: rpc error: code = Unknown desc = NetworkPlugin cni failed to set up pod \"kuryrpoc_default\" network: invalid character '-' after top-level value"

[Michal Dulko (michal-dulko-f)]

We set that by default now.