Error while adding a second Calico managed network interface to a LXD container

gistfile1.txt

vagrant@ubuntu-bionic:~/shared_folder/scripts$ ./lxd-attach-calico.sh lxd2 backend callxd1
2018-12-11 16:12:33.244 [DEBUG][26444] plugin.go 63: /var/lib/calico/nodename exists
2018-12-11 16:12:33.244 [DEBUG][26444] utils.go 59: Read node name from file: ubuntu-bionic
2018-12-11 16:12:33.244 [DEBUG][26444] utils.go 69: Using node name ubuntu-bionic
2018-12-11 16:12:33.244 [DEBUG][26444] utils.go 425: Getting WEP identifiers with arguments: IgnoreUnknown=1, for node ubuntu-bionic
2018-12-11 16:12:33.244 [DEBUG][26444] utils.go 426: Loaded k8s arguments: {{true} <nil>   }
2018-12-11 16:12:33.244 [INFO][26444] plugin.go 75: Extracted identifiers EndpointIDs=&utils.WEPIdentifiers{Namespace:"default", WEPName:"", WorkloadEndpointIdentifiers:names.WorkloadEndpointIdentifiers{Node:"ubuntu-bionic", Orchestrator:"cni", Endpoint:"callxd1", Workload:"", Pod:"", ContainerID:"cnitool-f21388e577474665726b"}}
2018-12-11 16:12:33.245 [DEBUG][26444] load.go 70: Loading config from environment
2018-12-11 16:12:33.245 [DEBUG][26444] client.go 30: Using datastore type 'etcdv3'
2018-12-11 16:12:33.245 [DEBUG][26444] etcdv3.go 306: Processing Get request model-etcdKey=ClusterInformation(default) rev=""
2018-12-11 16:12:33.245 [DEBUG][26444] etcdv3.go 324: Calling Get on etcdv3 client etcdv3-etcdKey="/calico/resources/v3/projectcalico.org/clusterinformations/default" model-etcdKey=ClusterInformation(default) rev=""
2018-12-11 16:12:33.247 [DEBUG][26444] etcdv3.go 342: Processing List request list-interface=WorkloadEndpoint rev=""
2018-12-11 16:12:33.247 [DEBUG][26444] etcdv3.go 360: Performing a name-prefix query list-interface=WorkloadEndpoint rev=""
2018-12-11 16:12:33.247 [DEBUG][26444] etcdv3.go 381: Calling Get on etcdv3 client etcdv3-etcdKey="/calico/resources/v3/projectcalico.org/workloadendpoints/default/ubuntu--bionic-cni-cnitool--f21388e577474665726b-" list-interface=WorkloadEndpoint rev=""
2018-12-11 16:12:33.248 [DEBUG][26444] etcdv3.go 387: Processing response from etcdv3 etcdv3-etcdKey="/calico/resources/v3/projectcalico.org/workloadendpoints/default/ubuntu--bionic-cni-cnitool--f21388e577474665726b-" list-interface=WorkloadEndpoint numResults=0 rev=""
2018-12-11 16:12:33.248 [DEBUG][26444] plugin.go 125: Retrieved list of endpoints: &{{WorkloadEndpointList projectcalico.org/v3} { 48 } []} ContainerID="cnitool-f21388e577474665726b"
2018-12-11 16:12:33.248 [DEBUG][26444] plugin.go 235: Looking for IPAM plugin in paths ContainerID="cnitool-f21388e577474665726b" paths="/usr/local/bin" type="calico-ipam"
2018-12-11 16:12:33.259 [DEBUG][26453] load.go 70: Loading config from environment
2018-12-11 16:12:33.259 [DEBUG][26453] client.go 30: Using datastore type 'etcdv3'
2018-12-11 16:12:33.260 [DEBUG][26453] utils.go 425: Getting WEP identifiers with arguments: IgnoreUnknown=1, for node ubuntu-bionic
2018-12-11 16:12:33.260 [DEBUG][26453] utils.go 426: Loaded k8s arguments: {{true} <nil>   }
2018-12-11 16:12:33.260 [DEBUG][26453] utils.go 464: Generated IPAM handle ContainerID="cnitool-f21388e577474665726b" HandleID="backend.cnitool-f21388e577474665726b" Network="backend" Workload="ubuntu--bionic-cni-cnitool--f21388e577474665726b-callxd1"
Calico CNI IPAM request count IPv4=1 IPv6=0
2018-12-11 16:12:33.260 [DEBUG][26453] etcdv3.go 342: Processing List request list-interface=IPPool rev=""
2018-12-11 16:12:33.260 [DEBUG][26453] resource.go 220: Get Global Resource key from /calico/resources/v3/projectcalico.org/ippools
2018-12-11 16:12:33.260 [DEBUG][26453] resource.go 223: Didn't match regex
2018-12-11 16:12:33.260 [DEBUG][26453] etcdv3.go 364: Performing a parent-prefix query list-interface=IPPool rev=""
2018-12-11 16:12:33.260 [DEBUG][26453] etcdv3.go 381: Calling Get on etcdv3 client etcdv3-etcdKey="/calico/resources/v3/projectcalico.org/ippools/" list-interface=IPPool rev=""
2018-12-11 16:12:33.261 [DEBUG][26453] etcdv3.go 387: Processing response from etcdv3 etcdv3-etcdKey="/calico/resources/v3/projectcalico.org/ippools/" list-interface=IPPool numResults=6 rev=""
2018-12-11 16:12:33.262 [DEBUG][26453] conversion.go 33: Processing etcdv3 entry etcdv3-etcdKey="/calico/resources/v3/projectcalico.org/ippools/default-ipv4-ippool"
2018-12-11 16:12:33.262 [DEBUG][26453] resource.go 220: Get Global Resource key from /calico/resources/v3/projectcalico.org/ippools/default-ipv4-ippool
2018-12-11 16:12:33.262 [DEBUG][26453] conversion.go 35: Key is valid and converted to model-etcdKey model-etcdKey=IPPool(default-ipv4-ippool)
2018-12-11 16:12:33.262 [DEBUG][26453] conversion.go 37: Value is valid - return KVPair with parsed value
2018-12-11 16:12:33.262 [DEBUG][26453] conversion.go 33: Processing etcdv3 entry etcdv3-etcdKey="/calico/resources/v3/projectcalico.org/ippools/default-ipv6-ippool"
2018-12-11 16:12:33.263 [DEBUG][26453] resource.go 220: Get Global Resource key from /calico/resources/v3/projectcalico.org/ippools/default-ipv6-ippool
2018-12-11 16:12:33.263 [DEBUG][26453] conversion.go 35: Key is valid and converted to model-etcdKey model-etcdKey=IPPool(default-ipv6-ippool)
2018-12-11 16:12:33.263 [DEBUG][26453] conversion.go 37: Value is valid - return KVPair with parsed value
2018-12-11 16:12:33.263 [DEBUG][26453] conversion.go 33: Processing etcdv3 entry etcdv3-etcdKey="/calico/resources/v3/projectcalico.org/ippools/lxd-ipv4-pool-backend"
2018-12-11 16:12:33.264 [DEBUG][26453] resource.go 220: Get Global Resource key from /calico/resources/v3/projectcalico.org/ippools/lxd-ipv4-pool-backend
2018-12-11 16:12:33.264 [DEBUG][26453] conversion.go 35: Key is valid and converted to model-etcdKey model-etcdKey=IPPool(lxd-ipv4-pool-backend)
2018-12-11 16:12:33.264 [DEBUG][26453] conversion.go 37: Value is valid - return KVPair with parsed value
2018-12-11 16:12:33.264 [DEBUG][26453] conversion.go 33: Processing etcdv3 entry etcdv3-etcdKey="/calico/resources/v3/projectcalico.org/ippools/lxd-ipv4-pool-frontend"
2018-12-11 16:12:33.265 [DEBUG][26453] resource.go 220: Get Global Resource key from /calico/resources/v3/projectcalico.org/ippools/lxd-ipv4-pool-frontend
2018-12-11 16:12:33.265 [DEBUG][26453] conversion.go 35: Key is valid and converted to model-etcdKey model-etcdKey=IPPool(lxd-ipv4-pool-frontend)
2018-12-11 16:12:33.265 [DEBUG][26453] conversion.go 37: Value is valid - return KVPair with parsed value
2018-12-11 16:12:33.265 [DEBUG][26453] conversion.go 33: Processing etcdv3 entry etcdv3-etcdKey="/calico/resources/v3/projectcalico.org/ippools/lxd-ipv6-pool-backend"
2018-12-11 16:12:33.265 [DEBUG][26453] resource.go 220: Get Global Resource key from /calico/resources/v3/projectcalico.org/ippools/lxd-ipv6-pool-backend
2018-12-11 16:12:33.266 [DEBUG][26453] conversion.go 35: Key is valid and converted to model-etcdKey model-etcdKey=IPPool(lxd-ipv6-pool-backend)
2018-12-11 16:12:33.266 [DEBUG][26453] conversion.go 37: Value is valid - return KVPair with parsed value
2018-12-11 16:12:33.266 [DEBUG][26453] conversion.go 33: Processing etcdv3 entry etcdv3-etcdKey="/calico/resources/v3/projectcalico.org/ippools/lxd-ipv6-pool-frontend"
2018-12-11 16:12:33.266 [DEBUG][26453] resource.go 220: Get Global Resource key from /calico/resources/v3/projectcalico.org/ippools/lxd-ipv6-pool-frontend
2018-12-11 16:12:33.266 [DEBUG][26453] conversion.go 35: Key is valid and converted to model-etcdKey model-etcdKey=IPPool(lxd-ipv6-pool-frontend)
2018-12-11 16:12:33.267 [DEBUG][26453] conversion.go 37: Value is valid - return KVPair with parsed value
2018-12-11 16:12:33.267 [INFO][26453] utils.go 594: Resolved pool name lxd-ipv4-pool-backend to cidr 10.3.0.0/16
2018-12-11 16:12:33.267 [DEBUG][26453] etcdv3.go 342: Processing List request list-interface=IPPool rev=""
2018-12-11 16:12:33.268 [DEBUG][26453] resource.go 220: Get Global Resource key from /calico/resources/v3/projectcalico.org/ippools
2018-12-11 16:12:33.268 [DEBUG][26453] resource.go 223: Didn't match regex
2018-12-11 16:12:33.268 [DEBUG][26453] etcdv3.go 364: Performing a parent-prefix query list-interface=IPPool rev=""
2018-12-11 16:12:33.268 [DEBUG][26453] etcdv3.go 381: Calling Get on etcdv3 client etcdv3-etcdKey="/calico/resources/v3/projectcalico.org/ippools/" list-interface=IPPool rev=""
2018-12-11 16:12:33.269 [DEBUG][26453] etcdv3.go 387: Processing response from etcdv3 etcdv3-etcdKey="/calico/resources/v3/projectcalico.org/ippools/" list-interface=IPPool numResults=6 rev=""
2018-12-11 16:12:33.269 [DEBUG][26453] conversion.go 33: Processing etcdv3 entry etcdv3-etcdKey="/calico/resources/v3/projectcalico.org/ippools/default-ipv4-ippool"
2018-12-11 16:12:33.269 [DEBUG][26453] resource.go 220: Get Global Resource key from /calico/resources/v3/projectcalico.org/ippools/default-ipv4-ippool
2018-12-11 16:12:33.269 [DEBUG][26453] conversion.go 35: Key is valid and converted to model-etcdKey model-etcdKey=IPPool(default-ipv4-ippool)
2018-12-11 16:12:33.269 [DEBUG][26453] conversion.go 37: Value is valid - return KVPair with parsed value
2018-12-11 16:12:33.269 [DEBUG][26453] conversion.go 33: Processing etcdv3 entry etcdv3-etcdKey="/calico/resources/v3/projectcalico.org/ippools/default-ipv6-ippool"
2018-12-11 16:12:33.269 [DEBUG][26453] resource.go 220: Get Global Resource key from /calico/resources/v3/projectcalico.org/ippools/default-ipv6-ippool
2018-12-11 16:12:33.269 [DEBUG][26453] conversion.go 35: Key is valid and converted to model-etcdKey model-etcdKey=IPPool(default-ipv6-ippool)
2018-12-11 16:12:33.269 [DEBUG][26453] conversion.go 37: Value is valid - return KVPair with parsed value
2018-12-11 16:12:33.269 [DEBUG][26453] conversion.go 33: Processing etcdv3 entry etcdv3-etcdKey="/calico/resources/v3/projectcalico.org/ippools/lxd-ipv4-pool-backend"
2018-12-11 16:12:33.269 [DEBUG][26453] resource.go 220: Get Global Resource key from /calico/resources/v3/projectcalico.org/ippools/lxd-ipv4-pool-backend
2018-12-11 16:12:33.269 [DEBUG][26453] conversion.go 35: Key is valid and converted to model-etcdKey model-etcdKey=IPPool(lxd-ipv4-pool-backend)
2018-12-11 16:12:33.269 [DEBUG][26453] conversion.go 37: Value is valid - return KVPair with parsed value
2018-12-11 16:12:33.269 [DEBUG][26453] conversion.go 33: Processing etcdv3 entry etcdv3-etcdKey="/calico/resources/v3/projectcalico.org/ippools/lxd-ipv4-pool-frontend"
2018-12-11 16:12:33.269 [DEBUG][26453] resource.go 220: Get Global Resource key from /calico/resources/v3/projectcalico.org/ippools/lxd-ipv4-pool-frontend
2018-12-11 16:12:33.269 [DEBUG][26453] conversion.go 35: Key is valid and converted to model-etcdKey model-etcdKey=IPPool(lxd-ipv4-pool-frontend)
2018-12-11 16:12:33.269 [DEBUG][26453] conversion.go 37: Value is valid - return KVPair with parsed value
2018-12-11 16:12:33.269 [DEBUG][26453] conversion.go 33: Processing etcdv3 entry etcdv3-etcdKey="/calico/resources/v3/projectcalico.org/ippools/lxd-ipv6-pool-backend"
2018-12-11 16:12:33.269 [DEBUG][26453] resource.go 220: Get Global Resource key from /calico/resources/v3/projectcalico.org/ippools/lxd-ipv6-pool-backend
2018-12-11 16:12:33.269 [DEBUG][26453] conversion.go 35: Key is valid and converted to model-etcdKey model-etcdKey=IPPool(lxd-ipv6-pool-backend)
2018-12-11 16:12:33.269 [DEBUG][26453] conversion.go 37: Value is valid - return KVPair with parsed value
2018-12-11 16:12:33.269 [DEBUG][26453] conversion.go 33: Processing etcdv3 entry etcdv3-etcdKey="/calico/resources/v3/projectcalico.org/ippools/lxd-ipv6-pool-frontend"
2018-12-11 16:12:33.269 [DEBUG][26453] resource.go 220: Get Global Resource key from /calico/resources/v3/projectcalico.org/ippools/lxd-ipv6-pool-frontend
2018-12-11 16:12:33.269 [DEBUG][26453] conversion.go 35: Key is valid and converted to model-etcdKey model-etcdKey=IPPool(lxd-ipv6-pool-frontend)
2018-12-11 16:12:33.269 [DEBUG][26453] conversion.go 37: Value is valid - return KVPair with parsed value
Calico CNI IPAM handle=backend.cnitool-f21388e577474665726b
2018-12-11 16:12:33.269 [INFO][26453] ipam_plugin.go 185: Auto assigning IP ContainerID="cnitool-f21388e577474665726b" HandleID="backend.cnitool-f21388e577474665726b" Workload="ubuntu--bionic-cni-cnitool--f21388e577474665726b-callxd1" assignArgs=ipam.AutoAssignArgs{Num4:1, Num6:0, HandleID:(*string)(0xc4202b2bb0), Attrs:map[string]string(nil), Hostname:"ubuntu-bionic", IPv4Pools:[]net.IPNet{net.IPNet{IPNet:net.IPNet{IP:net.IP{0xa, 0x3, 0x0, 0x0}, Mask:net.IPMask{0xff, 0xff, 0x0, 0x0}}}}, IPv6Pools:[]net.IPNet{}, MaxBlocksPerHost:0}
2018-12-11 16:12:33.269 [DEBUG][26453] ipam.go 1300: Using hostname=ubuntu-bionic
2018-12-11 16:12:33.269 [INFO][26453] ipam.go 76: Auto-assign 1 ipv4, 0 ipv6 addrs for host 'ubuntu-bionic'
2018-12-11 16:12:33.270 [DEBUG][26453] ipam.go 82: Assigning IPv4 addresses
2018-12-11 16:12:33.270 [DEBUG][26453] etcdv3.go 342: Processing List request list-interface=IPPool rev=""
2018-12-11 16:12:33.270 [DEBUG][26453] resource.go 220: Get Global Resource key from /calico/resources/v3/projectcalico.org/ippools
2018-12-11 16:12:33.270 [DEBUG][26453] resource.go 223: Didn't match regex
2018-12-11 16:12:33.270 [DEBUG][26453] etcdv3.go 364: Performing a parent-prefix query list-interface=IPPool rev=""
2018-12-11 16:12:33.270 [DEBUG][26453] etcdv3.go 381: Calling Get on etcdv3 client etcdv3-etcdKey="/calico/resources/v3/projectcalico.org/ippools/" list-interface=IPPool rev=""
2018-12-11 16:12:33.270 [DEBUG][26453] etcdv3.go 387: Processing response from etcdv3 etcdv3-etcdKey="/calico/resources/v3/projectcalico.org/ippools/" list-interface=IPPool numResults=6 rev=""
2018-12-11 16:12:33.270 [DEBUG][26453] conversion.go 33: Processing etcdv3 entry etcdv3-etcdKey="/calico/resources/v3/projectcalico.org/ippools/default-ipv4-ippool"
2018-12-11 16:12:33.270 [DEBUG][26453] resource.go 220: Get Global Resource key from /calico/resources/v3/projectcalico.org/ippools/default-ipv4-ippool
2018-12-11 16:12:33.270 [DEBUG][26453] conversion.go 35: Key is valid and converted to model-etcdKey model-etcdKey=IPPool(default-ipv4-ippool)
2018-12-11 16:12:33.270 [DEBUG][26453] conversion.go 37: Value is valid - return KVPair with parsed value
2018-12-11 16:12:33.270 [DEBUG][26453] conversion.go 33: Processing etcdv3 entry etcdv3-etcdKey="/calico/resources/v3/projectcalico.org/ippools/default-ipv6-ippool"
2018-12-11 16:12:33.270 [DEBUG][26453] resource.go 220: Get Global Resource key from /calico/resources/v3/projectcalico.org/ippools/default-ipv6-ippool
2018-12-11 16:12:33.270 [DEBUG][26453] conversion.go 35: Key is valid and converted to model-etcdKey model-etcdKey=IPPool(default-ipv6-ippool)
2018-12-11 16:12:33.270 [DEBUG][26453] conversion.go 37: Value is valid - return KVPair with parsed value
2018-12-11 16:12:33.270 [DEBUG][26453] conversion.go 33: Processing etcdv3 entry etcdv3-etcdKey="/calico/resources/v3/projectcalico.org/ippools/lxd-ipv4-pool-backend"
2018-12-11 16:12:33.270 [DEBUG][26453] resource.go 220: Get Global Resource key from /calico/resources/v3/projectcalico.org/ippools/lxd-ipv4-pool-backend
2018-12-11 16:12:33.270 [DEBUG][26453] conversion.go 35: Key is valid and converted to model-etcdKey model-etcdKey=IPPool(lxd-ipv4-pool-backend)
2018-12-11 16:12:33.270 [DEBUG][26453] conversion.go 37: Value is valid - return KVPair with parsed value
2018-12-11 16:12:33.270 [DEBUG][26453] conversion.go 33: Processing etcdv3 entry etcdv3-etcdKey="/calico/resources/v3/projectcalico.org/ippools/lxd-ipv4-pool-frontend"
2018-12-11 16:12:33.270 [DEBUG][26453] resource.go 220: Get Global Resource key from /calico/resources/v3/projectcalico.org/ippools/lxd-ipv4-pool-frontend
2018-12-11 16:12:33.270 [DEBUG][26453] conversion.go 35: Key is valid and converted to model-etcdKey model-etcdKey=IPPool(lxd-ipv4-pool-frontend)
2018-12-11 16:12:33.270 [DEBUG][26453] conversion.go 37: Value is valid - return KVPair with parsed value
2018-12-11 16:12:33.270 [DEBUG][26453] conversion.go 33: Processing etcdv3 entry etcdv3-etcdKey="/calico/resources/v3/projectcalico.org/ippools/lxd-ipv6-pool-backend"
2018-12-11 16:12:33.270 [DEBUG][26453] resource.go 220: Get Global Resource key from /calico/resources/v3/projectcalico.org/ippools/lxd-ipv6-pool-backend
2018-12-11 16:12:33.270 [DEBUG][26453] conversion.go 35: Key is valid and converted to model-etcdKey model-etcdKey=IPPool(lxd-ipv6-pool-backend)
2018-12-11 16:12:33.270 [DEBUG][26453] conversion.go 37: Value is valid - return KVPair with parsed value
2018-12-11 16:12:33.270 [DEBUG][26453] conversion.go 33: Processing etcdv3 entry etcdv3-etcdKey="/calico/resources/v3/projectcalico.org/ippools/lxd-ipv6-pool-frontend"
2018-12-11 16:12:33.270 [DEBUG][26453] resource.go 220: Get Global Resource key from /calico/resources/v3/projectcalico.org/ippools/lxd-ipv6-pool-frontend
2018-12-11 16:12:33.270 [DEBUG][26453] conversion.go 35: Key is valid and converted to model-etcdKey model-etcdKey=IPPool(lxd-ipv6-pool-frontend)
2018-12-11 16:12:33.270 [DEBUG][26453] conversion.go 37: Value is valid - return KVPair with parsed value
2018-12-11 16:12:33.270 [DEBUG][26453] client.go 150: Got list of all IPPools: &{{IPPoolList projectcalico.org/v3} { 48 } [{{IPPool projectcalico.org/v3} {default-ipv4-ippool    f90a26e2-fd5b-11e8-b6dc-02c44c503abe 4 0 2018-12-11 15:46:49 +0000 UTC <nil> <nil> map[] map[] [] nil [] } {192.168.0.0/16 Never true false 26 <nil> false}} {{IPPool projectcalico.org/v3} {default-ipv6-ippool    f90a6f62-fd5b-11e8-b6dc-02c44c503abe 5 0 2018-12-11 15:46:49 +0000 UTC <nil> <nil> map[] map[] [] nil [] } {fd1a:27d3:93dd::/48 Never false false 122 <nil> false}} {{IPPool projectcalico.org/v3} {lxd-ipv4-pool-backend    050a5229-fd5d-11e8-baa7-02c44c503abe 12 0 2018-12-11 15:54:19 +0000 UTC <nil> <nil> map[] map[] [] nil [] } {10.3.0.0/16 CrossSubnet true false 26 <nil> false}} {{IPPool projectcalico.org/v3} {lxd-ipv4-pool-frontend    04fa7577-fd5d-11e8-b5ca-02c44c503abe 10 0 2018-12-11 15:54:19 +0000 UTC <nil> <nil> map[] map[] [] nil [] } {10.1.0.0/16 CrossSubnet true false 26 <nil> false}} {{IPPool projectcalico.org/v3} {lxd-ipv6-pool-backend    0510a426-fd5d-11e8-860d-02c44c503abe 13 0 2018-12-11 15:54:19 +0000 UTC <nil> <nil> map[] map[] [] nil [] } {2001:db8:1222:1::/64 Never false false 122 <nil> false}} {{IPPool projectcalico.org/v3} {lxd-ipv6-pool-frontend    05031af5-fd5d-11e8-af84-02c44c503abe 11 0 2018-12-11 15:54:19 +0000 UTC <nil> <nil> map[] map[] [] nil [] } {2001:db8:1234:1::/64 Never false false 122 <nil> false}}]}
2018-12-11 16:12:33.270 [DEBUG][26453] client.go 156: Adding pool (192.168.0.0/16) to the enabled IPPool list
2018-12-11 16:12:33.270 [DEBUG][26453] client.go 161: Ignoring IPPool: fd1a:27d3:93dd::/48. IP version is different.
2018-12-11 16:12:33.270 [DEBUG][26453] client.go 156: Adding pool (10.3.0.0/16) to the enabled IPPool list
2018-12-11 16:12:33.270 [DEBUG][26453] client.go 156: Adding pool (10.1.0.0/16) to the enabled IPPool list
2018-12-11 16:12:33.270 [DEBUG][26453] client.go 161: Ignoring IPPool: 2001:db8:1222:1::/64. IP version is different.
2018-12-11 16:12:33.270 [DEBUG][26453] client.go 161: Ignoring IPPool: 2001:db8:1234:1::/64. IP version is different.
2018-12-11 16:12:33.270 [DEBUG][26453] ipam.go 214: enabled Pools: [{{IPPool projectcalico.org/v3} {default-ipv4-ippool    f90a26e2-fd5b-11e8-b6dc-02c44c503abe 4 0 2018-12-11 15:46:49 +0000 UTC <nil> <nil> map[] map[] [] nil [] } {192.168.0.0/16 Never true false 26 <nil> false}} {{IPPool projectcalico.org/v3} {lxd-ipv4-pool-backend    050a5229-fd5d-11e8-baa7-02c44c503abe 12 0 2018-12-11 15:54:19 +0000 UTC <nil> <nil> map[] map[] [] nil [] } {10.3.0.0/16 CrossSubnet true false 26 <nil> false}} {{IPPool projectcalico.org/v3} {lxd-ipv4-pool-frontend    04fa7577-fd5d-11e8-b5ca-02c44c503abe 10 0 2018-12-11 15:54:19 +0000 UTC <nil> <nil> map[] map[] [] nil [] } {10.1.0.0/16 CrossSubnet true false 26 <nil> false}}]
2018-12-11 16:12:33.270 [DEBUG][26453] ipam.go 217: requested IPPools: [10.3.0.0/16]
2018-12-11 16:12:33.270 [INFO][26453] ipam.go 260: Looking up existing affinities for host handle="backend.cnitool-f21388e577474665726b" host="ubuntu-bionic"
2018-12-11 16:12:33.271 [DEBUG][26453] etcdv3.go 342: Processing List request list-interface=model.BlockAffinityListOptions{Host:"ubuntu-bionic", IPVersion:4} rev=""
2018-12-11 16:12:33.271 [DEBUG][26453] block_affinity.go 93: Get Block affinity key from /calico/ipam/v2/host/ubuntu-bionic/ipv4/block
2018-12-11 16:12:33.271 [DEBUG][26453] block_affinity.go 96: /calico/ipam/v2/host/ubuntu-bionic/ipv4/block didn't match regex
2018-12-11 16:12:33.271 [DEBUG][26453] etcdv3.go 364: Performing a parent-prefix query list-interface=model.BlockAffinityListOptions{Host:"ubuntu-bionic", IPVersion:4} rev=""
2018-12-11 16:12:33.271 [DEBUG][26453] etcdv3.go 381: Calling Get on etcdv3 client etcdv3-etcdKey="/calico/ipam/v2/host/ubuntu-bionic/ipv4/block/" list-interface=model.BlockAffinityListOptions{Host:"ubuntu-bionic", IPVersion:4} rev=""
2018-12-11 16:12:33.271 [DEBUG][26453] etcdv3.go 387: Processing response from etcdv3 etcdv3-etcdKey="/calico/ipam/v2/host/ubuntu-bionic/ipv4/block/" list-interface=model.BlockAffinityListOptions{Host:"ubuntu-bionic", IPVersion:4} numResults=2 rev=""
2018-12-11 16:12:33.271 [DEBUG][26453] conversion.go 33: Processing etcdv3 entry etcdv3-etcdKey="/calico/ipam/v2/host/ubuntu-bionic/ipv4/block/10.1.140.192-26"
2018-12-11 16:12:33.271 [DEBUG][26453] block_affinity.go 93: Get Block affinity key from /calico/ipam/v2/host/ubuntu-bionic/ipv4/block/10.1.140.192-26
2018-12-11 16:12:33.271 [DEBUG][26453] conversion.go 35: Key is valid and converted to model-etcdKey model-etcdKey=BlockAffinityKey(cidr=10.1.140.192/26, host=ubuntu-bionic)
2018-12-11 16:12:33.271 [DEBUG][26453] conversion.go 37: Value is valid - return KVPair with parsed value
2018-12-11 16:12:33.271 [DEBUG][26453] conversion.go 33: Processing etcdv3 entry etcdv3-etcdKey="/calico/ipam/v2/host/ubuntu-bionic/ipv4/block/10.3.140.192-26"
2018-12-11 16:12:33.271 [DEBUG][26453] block_affinity.go 93: Get Block affinity key from /calico/ipam/v2/host/ubuntu-bionic/ipv4/block/10.3.140.192-26
2018-12-11 16:12:33.271 [DEBUG][26453] conversion.go 35: Key is valid and converted to model-etcdKey model-etcdKey=BlockAffinityKey(cidr=10.3.140.192/26, host=ubuntu-bionic)
2018-12-11 16:12:33.271 [DEBUG][26453] conversion.go 37: Value is valid - return KVPair with parsed value
2018-12-11 16:12:33.271 [DEBUG][26453] ipam.go 265: Found 1 affine IPv4 blocks for host: [10.3.140.192/26] handle="backend.cnitool-f21388e577474665726b" host="ubuntu-bionic"
2018-12-11 16:12:33.271 [INFO][26453] ipam.go 284: Trying affinity for 10.3.140.192/26 handle="backend.cnitool-f21388e577474665726b" host="ubuntu-bionic"
2018-12-11 16:12:33.271 [DEBUG][26453] etcdv3.go 306: Processing Get request model-etcdKey=BlockAffinityKey(cidr=10.3.140.192/26, host=ubuntu-bionic) rev=""
2018-12-11 16:12:33.271 [DEBUG][26453] etcdv3.go 324: Calling Get on etcdv3 client etcdv3-etcdKey="/calico/ipam/v2/host/ubuntu-bionic/ipv4/block/10.3.140.192-26" model-etcdKey=BlockAffinityKey(cidr=10.3.140.192/26, host=ubuntu-bionic) rev=""
2018-12-11 16:12:33.271 [INFO][26453] ipam.go 124: Attempting to load block cidr=10.3.140.192/26 host="ubuntu-bionic"
2018-12-11 16:12:33.271 [DEBUG][26453] etcdv3.go 306: Processing Get request model-etcdKey=BlockKey(cidr=10.3.140.192/26) rev=""
2018-12-11 16:12:33.271 [DEBUG][26453] etcdv3.go 324: Calling Get on etcdv3 client etcdv3-etcdKey="/calico/ipam/v2/assignment/ipv4/block/10.3.140.192-26" model-etcdKey=BlockKey(cidr=10.3.140.192/26) rev=""
2018-12-11 16:12:33.272 [INFO][26453] ipam.go 201: Affinity is confirmed and block has been loaded cidr=10.3.140.192/26 host="ubuntu-bionic"
2018-12-11 16:12:33.272 [INFO][26453] ipam.go 693: Attempting to assign 1 addresses from block block=10.3.140.192/26 handle="backend.cnitool-f21388e577474665726b" host="ubuntu-bionic"
2018-12-11 16:12:33.272 [DEBUG][26453] ipam_block.go 338: New allocation attribute: model.AllocationAttribute{AttrPrimary:(*string)(0xc4202b2bb0), AttrSecondary:map[string]string(nil)} handle="backend.cnitool-f21388e577474665726b"
2018-12-11 16:12:33.272 [DEBUG][26453] ipam_block.go 86: Block 10.3.140.192/26 returned ips: [10.3.140.194]
2018-12-11 16:12:33.272 [DEBUG][26453] ipam.go 710: Incrementing handle block=10.3.140.192/26 handle="backend.cnitool-f21388e577474665726b" host="ubuntu-bionic"
2018-12-11 16:12:33.272 [DEBUG][26453] etcdv3.go 306: Processing Get request model-etcdKey=IPAMHandleKey(id=backend.cnitool-f21388e577474665726b) rev=""
2018-12-11 16:12:33.272 [DEBUG][26453] etcdv3.go 324: Calling Get on etcdv3 client etcdv3-etcdKey="/calico/ipam/v2/handle/backend.cnitool-f21388e577474665726b" model-etcdKey=IPAMHandleKey(id=backend.cnitool-f21388e577474665726b) rev=""
2018-12-11 16:12:33.272 [DEBUG][26453] etcdv3.go 331: No results returned from etcdv3 client etcdv3-etcdKey="/calico/ipam/v2/handle/backend.cnitool-f21388e577474665726b" model-etcdKey=IPAMHandleKey(id=backend.cnitool-f21388e577474665726b) rev=""
2018-12-11 16:12:33.272 [INFO][26453] ipam.go 1126: Creating new handle: backend.cnitool-f21388e577474665726b
2018-12-11 16:12:33.272 [DEBUG][26453] etcdv3.go 96: Processing Create request model-etcdKey=IPAMHandleKey(id=backend.cnitool-f21388e577474665726b) rev="" ttl=0s value=&model.IPAMHandle{HandleID:"backend.cnitool-f21388e577474665726b", Block:map[string]int{"10.3.140.192/26":1}}
2018-12-11 16:12:33.272 [DEBUG][26453] etcdv3.go 111: Performing etcdv3 transaction for Create request etcdv3-etcdKey="/calico/ipam/v2/handle/backend.cnitool-f21388e577474665726b" model-etcdKey=IPAMHandleKey(id=backend.cnitool-f21388e577474665726b) rev="" ttl=0s value=&model.IPAMHandle{HandleID:"backend.cnitool-f21388e577474665726b", Block:map[string]int{"10.3.140.192/26":1}}
2018-12-11 16:12:33.273 [INFO][26453] ipam.go 716: Writing block in order to claim IPs block=10.3.140.192/26 handle="backend.cnitool-f21388e577474665726b" host="ubuntu-bionic"
2018-12-11 16:12:33.273 [DEBUG][26453] etcdv3.go 151: Processing Update request model-etcdKey=BlockKey(cidr=10.3.140.192/26) rev="44" ttl=0s value=&model.AllocationBlock{CIDR:net.IPNet{IPNet:net.IPNet{IP:net.IP{0xa, 0x3, 0x8c, 0xc0}, Mask:net.IPMask{0xff, 0xff, 0xff, 0xc0}}}, Affinity:(*string)(0xc420264cc0), StrictAffinity:false, Allocations:[]*int{(*int)(0xc420245170), (*int)(nil), (*int)(0xc420245490), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil)}, Unallocated:[]int{3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16, 17, 18, 19, 20, 21, 22, 23, 24, 25, 26, 27, 28, 29, 30, 31, 32, 33, 34, 35, 36, 37, 38, 39, 40, 41, 42, 43, 44, 45, 46, 47, 48, 49, 50, 51, 52, 53, 54, 55, 56, 57, 58, 59, 60, 61, 62, 63, 1}, Attributes:[]model.AllocationAttribute{model.AllocationAttribute{AttrPrimary:(*string)(nil), AttrSecondary:map[string]string(nil)}, model.AllocationAttribute{AttrPrimary:(*string)(0xc4202b2bb0), AttrSecondary:map[string]string(nil)}}, HostAffinity:(*string)(nil)}
2018-12-11 16:12:33.273 [DEBUG][26453] etcdv3.go 170: Performing etcdv3 transaction for Update request etcdv3-etcdKey="/calico/ipam/v2/assignment/ipv4/block/10.3.140.192-26" model-etcdKey=BlockKey(cidr=10.3.140.192/26) rev="44" ttl=0s value=&model.AllocationBlock{CIDR:net.IPNet{IPNet:net.IPNet{IP:net.IP{0xa, 0x3, 0x8c, 0xc0}, Mask:net.IPMask{0xff, 0xff, 0xff, 0xc0}}}, Affinity:(*string)(0xc420264cc0), StrictAffinity:false, Allocations:[]*int{(*int)(0xc420245170), (*int)(nil), (*int)(0xc420245490), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil)}, Unallocated:[]int{3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16, 17, 18, 19, 20, 21, 22, 23, 24, 25, 26, 27, 28, 29, 30, 31, 32, 33, 34, 35, 36, 37, 38, 39, 40, 41, 42, 43, 44, 45, 46, 47, 48, 49, 50, 51, 52, 53, 54, 55, 56, 57, 58, 59, 60, 61, 62, 63, 1}, Attributes:[]model.AllocationAttribute{model.AllocationAttribute{AttrPrimary:(*string)(nil), AttrSecondary:map[string]string(nil)}, model.AllocationAttribute{AttrPrimary:(*string)(0xc4202b2bb0), AttrSecondary:map[string]string(nil)}}, HostAffinity:(*string)(nil)}
2018-12-11 16:12:33.275 [INFO][26453] ipam.go 726: Successfully claimed IPs: [10.3.140.194] block=10.3.140.192/26 handle="backend.cnitool-f21388e577474665726b" host="ubuntu-bionic"
2018-12-11 16:12:33.275 [INFO][26453] ipam.go 316: Block '10.3.140.192/26' provided addresses: [10.3.140.194] handle="backend.cnitool-f21388e577474665726b" host="ubuntu-bionic"
2018-12-11 16:12:33.275 [DEBUG][26453] etcdv3.go 306: Processing Get request model-etcdKey=IPAMConfigKey() rev=""
2018-12-11 16:12:33.275 [DEBUG][26453] etcdv3.go 324: Calling Get on etcdv3 client etcdv3-etcdKey="/calico/ipam/v2/config" model-etcdKey=IPAMConfigKey() rev=""
2018-12-11 16:12:33.275 [DEBUG][26453] etcdv3.go 331: No results returned from etcdv3 client etcdv3-etcdKey="/calico/ipam/v2/config" model-etcdKey=IPAMConfigKey() rev=""
2018-12-11 16:12:33.275 [DEBUG][26453] ipam.go 327: Allocate new blocks? Config: &{StrictAffinity:false AutoAllocateBlocks:true} handle="backend.cnitool-f21388e577474665726b" host="ubuntu-bionic"
2018-12-11 16:12:33.275 [INFO][26453] ipam.go 472: Auto-assigned 1 out of 1 IPv4s: [10.3.140.194] handle="backend.cnitool-f21388e577474665726b" host="ubuntu-bionic"
Calico CNI IPAM assigned addresses IPv4=[10.3.140.194] IPv6=[]
2018-12-11 16:12:33.276 [INFO][26453] ipam_plugin.go 213: IPAM Result ContainerID="cnitool-f21388e577474665726b" HandleID="backend.cnitool-f21388e577474665726b" Workload="ubuntu--bionic-cni-cnitool--f21388e577474665726b-callxd1" result.IPs=[]*current.IPConfig{(*current.IPConfig)(0xc42020b200)}
2018-12-11 16:12:33.278 [INFO][26444] plugin.go 237: Got result from IPAM plugin ContainerID="cnitool-f21388e577474665726b" IPAM result=IP:[{Version:4 Interface:<nil> Address:{IP:10.3.140.194 Mask:ffffffff} Gateway:<nil>}], DNS:{Nameservers:[] Domain: Search:[] Options:[]}
2018-12-11 16:12:33.278 [DEBUG][26444] plugin.go 279: Populated endpoint (without nets) ContainerID="cnitool-f21388e577474665726b" endpoint=&v3.WorkloadEndpoint{TypeMeta:v1.TypeMeta{Kind:"WorkloadEndpoint", APIVersion:"projectcalico.org/v3"}, ObjectMeta:v1.ObjectMeta{Name:"ubuntu--bionic-cni-cnitool--f21388e577474665726b-callxd1", GenerateName:"", Namespace:"default", SelfLink:"", UID:"", ResourceVersion:"", Generation:0, CreationTimestamp:v1.Time{Time:time.Time{wall:0x0, ext:0, loc:(*time.Location)(nil)}}, DeletionTimestamp:(*v1.Time)(nil), DeletionGracePeriodSeconds:(*int64)(nil), Labels:map[string]string{}, Annotations:map[string]string(nil), OwnerReferences:[]v1.OwnerReference(nil), Initializers:(*v1.Initializers)(nil), Finalizers:[]string(nil), ClusterName:""}, Spec:v3.WorkloadEndpointSpec{Orchestrator:"cni", Workload:"", Node:"ubuntu-bionic", ContainerID:"cnitool-f21388e577474665726b", Pod:"", Endpoint:"callxd1", IPNetworks:[]string(nil), IPNATs:[]v3.IPNAT(nil), IPv4Gateway:"", IPv6Gateway:"", Profiles:[]string{"backend"}, InterfaceName:"", MAC:"", Ports:[]v3.EndpointPort(nil)}}
2018-12-11 16:12:33.278 [INFO][26444] plugin.go 285: Populated endpoint (with nets) ContainerID="cnitool-f21388e577474665726b" endpoint=&v3.WorkloadEndpoint{TypeMeta:v1.TypeMeta{Kind:"WorkloadEndpoint", APIVersion:"projectcalico.org/v3"}, ObjectMeta:v1.ObjectMeta{Name:"ubuntu--bionic-cni-cnitool--f21388e577474665726b-callxd1", GenerateName:"", Namespace:"default", SelfLink:"", UID:"", ResourceVersion:"", Generation:0, CreationTimestamp:v1.Time{Time:time.Time{wall:0x0, ext:0, loc:(*time.Location)(nil)}}, DeletionTimestamp:(*v1.Time)(nil), DeletionGracePeriodSeconds:(*int64)(nil), Labels:map[string]string{}, Annotations:map[string]string(nil), OwnerReferences:[]v1.OwnerReference(nil), Initializers:(*v1.Initializers)(nil), Finalizers:[]string(nil), ClusterName:""}, Spec:v3.WorkloadEndpointSpec{Orchestrator:"cni", Workload:"", Node:"ubuntu-bionic", ContainerID:"cnitool-f21388e577474665726b", Pod:"", Endpoint:"callxd1", IPNetworks:[]string{"10.3.140.194/32"}, IPNATs:[]v3.IPNAT(nil), IPv4Gateway:"", IPv6Gateway:"", Profiles:[]string{"backend"}, InterfaceName:"", MAC:"", Ports:[]v3.EndpointPort(nil)}}
Calico CNI using IPs: [10.3.140.194/32]
2018-12-11 16:12:33.278 [INFO][26444] network_linux.go 76: Setting the host side veth name to calicnitool-f21 ContainerID="cnitool-f21388e577474665726b"
2018-12-11 16:12:33.279 [DEBUG][26444] network_linux.go 131: Found MAC for container veth ContainerID="cnitool-f21388e577474665726b" MAC="86:3c:ba:2c:2f:0f"
2018-12-11 16:12:33.279 [ERROR][26444] network_linux.go 241: Error creating veth: failed to add route inside the container: file exists ContainerID="cnitool-f21388e577474665726b"
2018-12-11 16:12:33.279 [INFO][26444] utils.go 545: Cleaning up IP allocations for failed ADD ContainerID="cnitool-f21388e577474665726b"
Calico CNI releasing IP address
2018-12-11 16:12:33.279 [DEBUG][26444] utils.go 170: Looking for IPAM plugin in paths ContainerID="cnitool-f21388e577474665726b" paths="/usr/local/bin" type="calico-ipam"
2018-12-11 16:12:33.292 [DEBUG][26459] load.go 70: Loading config from environment
2018-12-11 16:12:33.292 [DEBUG][26459] client.go 30: Using datastore type 'etcdv3'
2018-12-11 16:12:33.292 [DEBUG][26459] utils.go 59: Read node name from file: ubuntu-bionic
2018-12-11 16:12:33.293 [DEBUG][26459] utils.go 69: Using node name ubuntu-bionic
2018-12-11 16:12:33.293 [DEBUG][26459] utils.go 425: Getting WEP identifiers with arguments: IgnoreUnknown=1, for node ubuntu-bionic
2018-12-11 16:12:33.293 [DEBUG][26459] utils.go 426: Loaded k8s arguments: {{true} <nil>   }
2018-12-11 16:12:33.293 [DEBUG][26459] utils.go 464: Generated IPAM handle ContainerID="cnitool-f21388e577474665726b" HandleID="backend.cnitool-f21388e577474665726b" Network="backend" Workload="ubuntu--bionic-cni-cnitool--f21388e577474665726b-callxd1"
2018-12-11 16:12:33.293 [INFO][26459] ipam_plugin.go 257: Releasing address using handleID ContainerID="cnitool-f21388e577474665726b" HandleID="backend.cnitool-f21388e577474665726b" Workload="ubuntu--bionic-cni-cnitool--f21388e577474665726b-callxd1"
2018-12-11 16:12:33.293 [INFO][26459] ipam.go 1035: Releasing all IPs with handle 'backend.cnitool-f21388e577474665726b'
2018-12-11 16:12:33.293 [DEBUG][26459] etcdv3.go 306: Processing Get request model-etcdKey=IPAMHandleKey(id=backend.cnitool-f21388e577474665726b) rev=""
2018-12-11 16:12:33.293 [DEBUG][26459] etcdv3.go 324: Calling Get on etcdv3 client etcdv3-etcdKey="/calico/ipam/v2/handle/backend.cnitool-f21388e577474665726b" model-etcdKey=IPAMHandleKey(id=backend.cnitool-f21388e577474665726b) rev=""
2018-12-11 16:12:33.294 [INFO][26459] ipam.go 1054: Querying block so we can release IPs by handle cidr=10.3.140.192/26 handle="backend.cnitool-f21388e577474665726b"
2018-12-11 16:12:33.294 [DEBUG][26459] etcdv3.go 306: Processing Get request model-etcdKey=BlockKey(cidr=10.3.140.192/26) rev=""
2018-12-11 16:12:33.294 [DEBUG][26459] etcdv3.go 324: Calling Get on etcdv3 client etcdv3-etcdKey="/calico/ipam/v2/assignment/ipv4/block/10.3.140.192-26" model-etcdKey=BlockKey(cidr=10.3.140.192/26) rev=""
2018-12-11 16:12:33.295 [DEBUG][26459] ipam_block.go 267: Attribute indexes to release: [1]
2018-12-11 16:12:33.295 [DEBUG][26459] ipam_block.go 218: 0 in [1]
2018-12-11 16:12:33.295 [INFO][26459] ipam.go 1074: Block has 1 IPs with the given handle cidr=10.3.140.192/26 handle="backend.cnitool-f21388e577474665726b"
2018-12-11 16:12:33.295 [INFO][26459] ipam.go 1096: Updating block to release IPs cidr=10.3.140.192/26 handle="backend.cnitool-f21388e577474665726b"
2018-12-11 16:12:33.295 [DEBUG][26459] etcdv3.go 151: Processing Update request model-etcdKey=BlockKey(cidr=10.3.140.192/26) rev="50" ttl=0s value=&model.AllocationBlock{CIDR:net.IPNet{IPNet:net.IPNet{IP:net.IP{0xa, 0x3, 0x8c, 0xc0}, Mask:net.IPMask{0xff, 0xff, 0xff, 0xc0}}}, Affinity:(*string)(0xc4200c2f30), StrictAffinity:false, Allocations:[]*int{(*int)(0xc42009ba40), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil)}, Unallocated:[]int{3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16, 17, 18, 19, 20, 21, 22, 23, 24, 25, 26, 27, 28, 29, 30, 31, 32, 33, 34, 35, 36, 37, 38, 39, 40, 41, 42, 43, 44, 45, 46, 47, 48, 49, 50, 51, 52, 53, 54, 55, 56, 57, 58, 59, 60, 61, 62, 63, 1, 2}, Attributes:[]model.AllocationAttribute{model.AllocationAttribute{AttrPrimary:(*string)(nil), AttrSecondary:map[string]string(nil)}}, HostAffinity:(*string)(nil)}
2018-12-11 16:12:33.295 [DEBUG][26459] etcdv3.go 170: Performing etcdv3 transaction for Update request etcdv3-etcdKey="/calico/ipam/v2/assignment/ipv4/block/10.3.140.192-26" model-etcdKey=BlockKey(cidr=10.3.140.192/26) rev="50" ttl=0s value=&model.AllocationBlock{CIDR:net.IPNet{IPNet:net.IPNet{IP:net.IP{0xa, 0x3, 0x8c, 0xc0}, Mask:net.IPMask{0xff, 0xff, 0xff, 0xc0}}}, Affinity:(*string)(0xc4200c2f30), StrictAffinity:false, Allocations:[]*int{(*int)(0xc42009ba40), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil), (*int)(nil)}, Unallocated:[]int{3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16, 17, 18, 19, 20, 21, 22, 23, 24, 25, 26, 27, 28, 29, 30, 31, 32, 33, 34, 35, 36, 37, 38, 39, 40, 41, 42, 43, 44, 45, 46, 47, 48, 49, 50, 51, 52, 53, 54, 55, 56, 57, 58, 59, 60, 61, 62, 63, 1, 2}, Attributes:[]model.AllocationAttribute{model.AllocationAttribute{AttrPrimary:(*string)(nil), AttrSecondary:map[string]string(nil)}}, HostAffinity:(*string)(nil)}
2018-12-11 16:12:33.296 [INFO][26459] ipam.go 1109: Successfully released IPs from block cidr=10.3.140.192/26 handle="backend.cnitool-f21388e577474665726b"
2018-12-11 16:12:33.296 [DEBUG][26459] etcdv3.go 306: Processing Get request model-etcdKey=IPAMHandleKey(id=backend.cnitool-f21388e577474665726b) rev=""
2018-12-11 16:12:33.296 [DEBUG][26459] etcdv3.go 324: Calling Get on etcdv3 client etcdv3-etcdKey="/calico/ipam/v2/handle/backend.cnitool-f21388e577474665726b" model-etcdKey=IPAMHandleKey(id=backend.cnitool-f21388e577474665726b) rev=""
2018-12-11 16:12:33.297 [DEBUG][26459] ipam.go 1187: Deleting handle: backend.cnitool-f21388e577474665726b
2018-12-11 16:12:33.297 [DEBUG][26459] etcdv3.go 243: Processing Delete request model-etcdKey=IPAMHandleKey(id=backend.cnitool-f21388e577474665726b) rev="49"
2018-12-11 16:12:33.297 [DEBUG][26459] etcdv3.go 260: Performing etcdv3 transaction for Delete request etcdv3-etcdKey="/calico/ipam/v2/handle/backend.cnitool-f21388e577474665726b" model-etcdKey=IPAMHandleKey(id=backend.cnitool-f21388e577474665726b) rev="49"
2018-12-11 16:12:33.297 [DEBUG][26459] ipam.go 1198: Decremented handle 'backend.cnitool-f21388e577474665726b' by 1
2018-12-11 16:12:33.297 [INFO][26459] ipam_plugin.go 266: Released address using handleID ContainerID="cnitool-f21388e577474665726b" HandleID="backend.cnitool-f21388e577474665726b" Workload="ubuntu--bionic-cni-cnitool--f21388e577474665726b-callxd1"
2018-12-11 16:12:33.297 [INFO][26459] ipam_plugin.go 275: Releasing address using workloadID ContainerID="cnitool-f21388e577474665726b" HandleID="backend.cnitool-f21388e577474665726b" Workload="ubuntu--bionic-cni-cnitool--f21388e577474665726b-callxd1"
2018-12-11 16:12:33.298 [INFO][26459] ipam.go 1035: Releasing all IPs with handle 'cnitool-f21388e577474665726b'
2018-12-11 16:12:33.298 [DEBUG][26459] etcdv3.go 306: Processing Get request model-etcdKey=IPAMHandleKey(id=cnitool-f21388e577474665726b) rev=""
2018-12-11 16:12:33.298 [DEBUG][26459] etcdv3.go 324: Calling Get on etcdv3 client etcdv3-etcdKey="/calico/ipam/v2/handle/cnitool-f21388e577474665726b" model-etcdKey=IPAMHandleKey(id=cnitool-f21388e577474665726b) rev=""
2018-12-11 16:12:33.298 [DEBUG][26459] etcdv3.go 331: No results returned from etcdv3 client etcdv3-etcdKey="/calico/ipam/v2/handle/cnitool-f21388e577474665726b" model-etcdKey=IPAMHandleKey(id=cnitool-f21388e577474665726b) rev=""
2018-12-11 16:12:33.298 [DEBUG][26459] ipam_plugin.go 281: Asked to release address but it doesn't exist. Ignoring ContainerID="cnitool-f21388e577474665726b" HandleID="backend.cnitool-f21388e577474665726b" Workload="ubuntu--bionic-cni-cnitool--f21388e577474665726b-callxd1" workloadID="cnitool-f21388e577474665726b"
failed to add route inside the container: file exists