Race condition by resync in CRD

[rastislavs]

Accidental race condition by resync in CRD: the resync is first delayed, thanks to it, all data changes are delayed as well, the resync ultimately finishes, but the following data changes are ignored. The result: no changes in CRD in k8s API are reflected into Contiv ETCD.

time="2019-07-31 12:09:11.96762" level=info msg="Starting agent version: v3.2.0-45-g5b9bd3681-dirty" BuildDate="2019-07-31T06:38" CommitHash=5b9bd3681225988f7beafe9e1993c703a0773b54 loc="agent/agent.go(134)" logger=agent
time="2019-07-31 12:09:21.96891" level=warning msg="Failed to connect to Etcd: context deadline exceeded" endpoints="[10.0.2.15:32379]" loc="etcd/bytes_broker_impl.go(60)" logger=etcd
time="2019-07-31 12:09:21.96915" level=info msg="Loading kubernetes client config" kubeconfig= loc="crd/plugin_impl_crd.go(117)" logger=crd
time="2019-07-31 12:09:21.96913" level=info msg="ETCD server [10.0.2.15:32379] not reachable in init phase. Agent will continue to try to connect every 2000000000 second(s)" loc="etcd/plugin_impl_etcd.go(203)" logger=etcd
ERROR: logging before flag.Parse: W0731 12:09:21.970120       1 client_config.go:552] Neither --kubeconfig nor --master was specified.  Using the inClusterConfig.  This might not work.
time="2019-07-31 12:09:21.97299" level=info msg="ContivTelemetryCache init done" loc="cache/telemetry_cache.go(144)" logger=crd.-telemetryCache
time="2019-07-31 12:09:21.97329" level=info msg="Telemetry-Controller: initializing..." loc="telemetry/telemetry_controller.go(101)" logger=crd.-telemetryController
time="2019-07-31 12:09:21.97336" level=info msg="Creating Telemetry CRD" loc="telemetry/telemetry_controller.go(253)" logger=crd.-telemetryController
time="2019-07-31 12:09:21.99320" level=info msg="NodeConfig-Controller: initializing..." loc="nodeconfig/node_config_controller.go(88)" logger=crd.-nodeConfigController
time="2019-07-31 12:09:21.99333" level=info msg="Creating NodeConfig CRD" loc="nodeconfig/node_config_controller.go(247)" logger=crd.-nodeConfigController
time="2019-07-31 12:09:21.99760" level=info msg="CustomNetwork-Controller: initializing..." loc="customnetwork/custom_network_controller.go(89)" logger=crd.-customNetworkController
time="2019-07-31 12:09:21.99771" level=info msg="Creating CustomNetwork CRD" loc="customnetwork/custom_network_controller.go(249)" logger=crd.-customNetworkController
time="2019-07-31 12:09:22.00551" level=info msg="ExternalInterface-Controller: initializing..." loc="externalinterface/external_interface_controller.go(91)" logger=crd.-externalInterfaceController
time="2019-07-31 12:09:22.00561" level=info msg="Creating ExternalInterface CRD" loc="externalinterface/external_interface_controller.go(251)" logger=crd.-externalInterfaceController
time="2019-07-31 12:09:22.01025" level=info msg="ServiceFunctionChain-Controller: initializing..." loc="servicefunctionchain/service_function_chain_controller.go(89)" logger=crd.-serviceFunctionChainController
time="2019-07-31 12:09:22.01037" level=info msg="Creating ServiceFunctionChain CRD" loc="servicefunctionchain/service_function_chain_controller.go(249)" logger=crd.-serviceFunctionChainController
time="2019-07-31 12:09:22.01445" level=info msg="Listening on http://0.0.0.0:9090" loc="rest/plugin_impl_rest.go(108)" logger=http
time="2019-07-31 12:09:22.01452" level=info msg="Starting health http-probe on port 9090" loc="probe/plugin_impl_probe.go(74)" logger=probe
time="2019-07-31 12:09:22.01463" level=info msg="Unable to register prometheus-probe handler, Prometheus is nil" loc="probe/plugin_impl_probe.go(86)" logger=probe
time="2019-07-31 12:09:22.01473" level=info msg="Resync starting for 1 registrations (crd)" loc="resync/plugin_impl_resync.go(103)" logger=resync
time="2019-07-31 12:09:22.01484" level=info msg="Resync done (took: 0s)" loc="resync/plugin_impl_resync.go(117)" logger=resync
time="2019-07-31 12:09:22.01497" level=info msg="Agent started with 10 plugins (took 10.047s)" loc="agent/agent.go(179)" logger=agent
time="2019-07-31 12:09:22.01478" level=info msg="Start campaign in crd leader election" loc="crd/plugin_impl_crd.go(271)" logger=crd
time="2019-07-31 12:09:22.01713" level=error msg="connection is not established" loc="crd/plugin_impl_crd.go(275)" logger=crd
time="2019-07-31 12:09:23.96973" level=info msg="Connecting to ETCD [10.0.2.15:32379] ..." loc="etcd/plugin_impl_etcd.go(208)" logger=etcd
time="2019-07-31 12:09:23.97133" level=info msg="Connected to Etcd (took 1.520495ms)" endpoints="[10.0.2.15:32379]" loc="etcd/bytes_broker_impl.go(60)" logger=etcd
time="2019-07-31 12:09:23.97280" level=info msg="ETCD server [10.0.2.15:32379] connected" loc="etcd/plugin_impl_etcd.go(219)" logger=etcd
time="2019-07-31 12:09:23.97956" level=info msg="Resync starting for 2 registrations (crd, ContivTelemetry Resources)" loc="resync/plugin_impl_resync.go(103)" logger=resync
time="2019-07-31 12:09:23.98124" level=info msg="Delaying RESYNC config" config="&{0xc0000be290 map[k8s/node/:0xc000598600 allocatedIDs/:0xc0003dc190 k8s/pod/:0xc0005984a0] 0xc0000c00e0}" loc="crd/plugin_impl_crd.go(312)" logger=crd
time="2019-07-31 12:09:23.98143" level=info msg="Resync done (took: 2ms)" loc="resync/plugin_impl_resync.go(117)" logger=resync
time="2019-07-31 12:09:25.55322" level=info msg="Delaying data-change" config="&{0xc0000be290 [0xc0005840a0] 0xc00000c038}" loc="crd/plugin_impl_crd.go(326)" logger=crd
time="2019-07-31 12:09:25.63112" level=info msg="Delaying data-change" config="&{0xc0000be290 [0xc0005841a0] 0xc00000c060}" loc="crd/plugin_impl_crd.go(326)" logger=crd
time="2019-07-31 12:09:26.18007" level=info msg="Delaying data-change" config="&{0xc0000be290 [0xc0005842a0] 0xc00000c080}" loc="crd/plugin_impl_crd.go(326)" logger=crd
time="2019-07-31 12:09:27.53217" level=info msg="Delaying data-change" config="&{0xc0000be290 [0xc000606a20] 0xc0000c0100}" loc="crd/plugin_impl_crd.go(326)" logger=crd
time="2019-07-31 12:09:27.57246" level=info msg="Delaying data-change" config="&{0xc0000be290 [0xc000606b00] 0xc0000c0128}" loc="crd/plugin_impl_crd.go(326)" logger=crd
time="2019-07-31 12:09:37.50871" level=info msg="Delaying data-change" config="&{0xc0000be290 [0xc000584c00] 0xc00000c0b0}" loc="crd/plugin_impl_crd.go(326)" logger=crd
time="2019-07-31 12:09:59.22022" level=info msg="Delaying data-change" config="&{0xc0000be290 [0xc000607580] 0xc0000c01b8}" loc="crd/plugin_impl_crd.go(326)" logger=crd
time="2019-07-31 12:10:01.21807" level=info msg="Delaying data-change" config="&{0xc0000be290 [0xc00055ce00] 0xc00058c0a8}" loc="crd/plugin_impl_crd.go(326)" logger=crd
time="2019-07-31 12:10:03.21467" level=info msg="Delaying data-change" config="&{0xc0000be290 [0xc000607780] 0xc0000c0268}" loc="crd/plugin_impl_crd.go(326)" logger=crd
time="2019-07-31 12:10:11.21443" level=info msg="Delaying data-change" config="&{0xc0000be290 [0xc000506700] 0xc00025c3b8}" loc="crd/plugin_impl_crd.go(326)" logger=crd
time="2019-07-31 12:10:15.23540" level=info msg="Delaying data-change" config="&{0xc0000be290 [0xc000506980] 0xc00025c3f8}" loc="crd/plugin_impl_crd.go(326)" logger=crd
time="2019-07-31 12:10:21.23002" level=info msg="Delaying data-change" config="&{0xc0000be290 [0xc000607fa0] 0xc0000c02b0}" loc="crd/plugin_impl_crd.go(326)" logger=crd
time="2019-07-31 12:10:23.21596" level=info msg="Delaying data-change" config="&{0xc0000be290 [0xc0005857c0] 0xc00000c0f0}" loc="crd/plugin_impl_crd.go(326)" logger=crd
time="2019-07-31 12:10:31.22419" level=info msg="Delaying data-change" config="&{0xc0000be290 [0xc0005071c0] 0xc00025c470}" loc="crd/plugin_impl_crd.go(326)" logger=crd