IPAM failures when running kubernetes scale test

[tomdee]

I'm not sure if this is a libcalico issue or a kubernetes plugin issue.

When spinning up pods on 25 hosts, I hit this issue on two of the hosts. It caused one pod to fail on the problem hosts. The other hosts had no problems.

2015-12-18 19:50:33,201 1335 INFO No initialization work to perform
2015-12-18 20:04:29,722 2284 [dcdc7ab5159b] INFO Executing Calico pod-creation hook
2015-12-18 20:04:29,729 2284 [dcdc7ab5159b] INFO Configuring pod default/pinger-wgrjp (container_id dcdc7ab5159b3c4fd4b5eac21934892cbfed57d784dad770a483f82386cbd112)
2015-12-18 20:04:29,810 2284 [dcdc7ab5159b] INFO Configuring Calico network interface
2015-12-18 20:04:29,826 2284 [dcdc7ab5159b] INFO Using Calico IPAM
2015-12-18 20:04:29,827 2284 [dcdc7ab5159b] INFO pycalico.ipam: Auto-assign 1 IPv4, 0 IPv6 addrs
2015-12-18 20:04:29,848 2284 [dcdc7ab5159b] INFO pycalico.ipam: Ran out of affine blocks for calico-19 in pool None
2015-12-18 20:04:30,617 2322 [1a4a23d29095] INFO Executing Calico pod-creation hook
2015-12-18 20:04:30,619 2322 [1a4a23d29095] INFO Configuring pod default/pinger-v9hq9 (container_id 1a4a23d29095b633f5d89bd883062f29d53f8185e71e8e02bd1cdc722b39163f)
2015-12-18 20:04:30,750 2322 [1a4a23d29095] INFO Configuring Calico network interface
2015-12-18 20:04:30,813 2322 [1a4a23d29095] INFO Using Calico IPAM
2015-12-18 20:04:30,814 2322 [1a4a23d29095] INFO pycalico.ipam: Auto-assign 1 IPv4, 0 IPv6 addrs
2015-12-18 20:04:30,966 2322 [1a4a23d29095] INFO pycalico.ipam: Ran out of affine blocks for calico-19 in pool None
2015-12-18 20:04:33,081 2322 [1a4a23d29095] ERROR Error networking pod - cleaning up
Traceback (most recent call last):
  File "<string>", line 120, in create
  File "<string>", line 334, in _configure_interface
  File "<string>", line 374, in _create_endpoint
  File "<string>", line 428, in _assign_container_ip
  File "/code/build/calico/out00-PYZ.pyz/pycalico.ipam", line 413, in auto_assign_ips
  File "/code/build/calico/out00-PYZ.pyz/pycalico.ipam", line 506, in _auto_assign
  File "/code/build/calico/out00-PYZ.pyz/pycalico.ipam", line 153, in _new_affine_block
  File "/code/build/calico/out00-PYZ.pyz/pycalico.ipam", line 188, in _claim_block_affinity
  File "/code/build/calico/out00-PYZ.pyz/etcd.client", line 584, in delete
  File "/code/build/calico/out00-PYZ.pyz/etcd.client", line 848, in wrapper
  File "/code/build/calico/out00-PYZ.pyz/etcd.client", line 928, in _handle_server_response
  File "/code/build/calico/out00-PYZ.pyz/etcd", line 304, in handle
EtcdKeyNotFound: Key not found : /calico/ipam/v2/host/calico-19/ipv4/block/192.168.4.128-26
2015-12-18 20:04:33,083 2322 [1a4a23d29095] INFO Removing networking from pod default/pinger-v9hq9 (container id 1a4a23d29095b633f5d89bd883062f29d53f8185e71e8e02bd1cdc722b39163f)
2015-12-18 20:04:33,120 2322 [1a4a23d29095] ERROR Error cleaning up pod
Traceback (most recent call last):
  File "<string>", line 129, in create
  File "<string>", line 155, in delete
SystemExit: 0
2015-12-18 20:04:33,120 2322 [1a4a23d29095] INFO Done cleaning up
2015-12-18 20:04:34,014 2284 [dcdc7ab5159b] INFO pycalico.ipam: Auto-assigned IPv4s ['192.168.5.0']
2015-12-18 20:04:34,054 2284 [dcdc7ab5159b] INFO pycalico.ipam: Auto-assigned IPv6s []
2015-12-18 20:04:34,055 2284 [dcdc7ab5159b] INFO Creating Calico endpoint with IPs [IPAddress('192.168.5.0')]
2015-12-18 20:04:34,442 2284 [dcdc7ab5159b] INFO Finished configuring network interface
2015-12-18 20:04:34,443 2284 [dcdc7ab5159b] INFO Created Calico endpoint: 8eac3af4a5c211e58b7f080027684567
2015-12-18 20:04:34,632 2284 [dcdc7ab5159b] INFO Setting profile 'default-profile' on endpoint 8eac3af4a5c211e58b7f080027684567
2015-12-18 20:04:34,889 2284 [dcdc7ab5159b] INFO Successfully configured networking for pod default/pinger-wgrjp
2015-12-18 20:04:34,899 2284 [dcdc7ab5159b] WARNING TIMING,setup,default,pinger-wgrjp,dcdc7ab5159b3c4fd4b5eac21934892cbfed57d784dad770a483f82386cbd112,5.17914915085
2015-12-18 20:04:36,948 2416 [dcdc7ab5159b] WARNING TIMING,status,pinger-wgrjp,default,dcdc7ab5159b3c4fd4b5eac21934892cbfed57d784dad770a483f82386cbd112,0.0975790023804
2015-12-18 20:04:38,013 2456 [f2ed777024f6] INFO Executing Calico pod-creation hook
2015-12-18 20:04:38,015 2456 [f2ed777024f6] INFO Configuring pod default/pinger-jmt3z (container_id f2ed777024f6f17635456c81c169790818061ff358a0d473fb9454ff818a4d53)
2015-12-18 20:04:38,121 2456 [f2ed777024f6] INFO Configuring Calico network interface
2015-12-18 20:04:38,247 2456 [f2ed777024f6] INFO Using Calico IPAM
2015-12-18 20:04:38,248 2456 [f2ed777024f6] INFO pycalico.ipam: Auto-assign 1 IPv4, 0 IPv6 addrs
2015-12-18 20:04:39,024 2456 [f2ed777024f6] INFO pycalico.ipam: Auto-assigned IPv4s ['192.168.5.1']
2015-12-18 20:04:39,177 2456 [f2ed777024f6] INFO pycalico.ipam: Auto-assigned IPv6s []
2015-12-18 20:04:39,177 2456 [f2ed777024f6] INFO Creating Calico endpoint with IPs [IPAddress('192.168.5.1')]
2015-12-18 20:04:39,872 2456 [f2ed777024f6] INFO Finished configuring network interface
2015-12-18 20:04:39,873 2456 [f2ed777024f6] INFO Created Calico endpoint: 91b9e336a5c211e59066080027684567

[robbrockbank]

@caseydavenport Do you happen to know what version of libcalico this would have been using?

[caseydavenport]

Hm. @tomdee was using a master build of our kubernetes plugin, which I believe should pull in whatever is used in the latest calico/build container.

[spikecurtis]

This is a new bug. #47, which is similar, occurred during a read call. This fails on delete.

[tomdee]

@spikecurtis Are you expecting to work on this in the next few days? Otherwise I'll take it off your hands?

[spikecurtis]

@tomdee I haven't started on this because I was worried it would interfere with @robbrockbank's other changes in this area. Happy to have you take it