Swarmkit reallocates network subnets before subnet resources are completely freed

During testing I have found that immediately after processing a set of requests to destroy a service and its networks, swarm may reallocate the subnets for those networks before the actual tasks and networks are completely removed from the swarm nodes. This can lead to a situation where a node attempts to start a task including creating its network attachments only to find that that the subnet that it is supposed to used for the task's network is still in use. This manifests in an error log of the form

May 29 22:17:32 e2e-ubuntu-0 dockerd[23299]: time="2018-05-29T22:17:32.632924876Z" level=error msg="fatal task error" error="failed to allocate gateway (10.0.0.1): Address already in use" module=node/agent/taskmanager node.       id=z48gq4tlcf1asg2y04tp8w7tv service.id=yr8g7exbd9oltrdxu7g5txqjm task.id=p12whhw1qzmnfdek0yjy1tftm

and causes the node to reject the task. Eventually the swarm should reach consistency, but this behavior is a bit antisocial.

Here is an example of one such run:

May 29 22:17:32 e2e-ubuntu-0 dockerd[23299]: time="2018-05-29T22:17:32.427997381Z" level=debug msg="Calling GET /v1.37/networks?filters=%7B%22label%22%3A%7B%22XXXXXXX%22%3Atrue%2C%22testname%3DXXXXXXXX%22%3Atrue%2C%22uuid%3Da9568dd7-92ac-4eaf-ac8a-6c9749024c77%22%3Atrue%7D%7D"
May 29 22:17:32 e2e-ubuntu-0 dockerd[23299]: time="2018-05-29T22:17:32.429252638Z" level=debug msg="Calling DELETE /v1.37/networks/819g857mkcx5gaw5pamxuei4j"
May 29 22:17:32 e2e-ubuntu-0 dockerd[23299]: time="2018-05-29T22:17:32.430803256Z" level=debug msg="ReleaseAddress(GlobalDefault/10.0.0.0/24, 10.0.0.2)"
May 29 22:17:32 e2e-ubuntu-0 dockerd[23299]: time="2018-05-29T22:17:32.430881174Z" level=debug msg="Released address PoolID:GlobalDefault/10.0.0.0/24, Address:10.0.0.2 Sequence:App: ipam/default/data, ID: GlobalDefault/10.0.0.0/24, DBIndex: 0x0, Bits: 256, Unselected: 238, Sequence: (0xf94401ff, 1)->(0x0, 6)->(0x1, 1)->end Curr:32"
May 29 22:17:32 e2e-ubuntu-0 dockerd[23299]: time="2018-05-29T22:17:32.431054996Z" level=debug msg="Calling DELETE /v1.37/networks/k4dymcoglufi1c3v09b6c1mbf"
May 29 22:17:32 e2e-ubuntu-0 dockerd[23299]: time="2018-05-29T22:17:32.433090957Z" level=debug msg="ReleaseAddress(GlobalDefault/10.0.0.0/24, 10.0.0.3)"
...
May 29 22:17:32 e2e-ubuntu-0 dockerd[23299]: time="2018-05-29T22:17:32.436458822Z" level=debug msg="Released address PoolID:GlobalDefault/10.0.0.0/24, Address:10.0.0.1 Sequence:App: ipam/default/data, ID: GlobalDefault/10.0.0.0/24, DBIndex: 0x0, Bits: 256, Unselected: 241, Sequence: (0xc14401ff, 1)->(0x0, 6)->(0x1, 1)->end Curr:32"
May 29 22:17:32 e2e-ubuntu-0 dockerd[23299]: time="2018-05-29T22:17:32.436485347Z" level=debug msg="ReleasePool(GlobalDefault/10.0.0.0/24)"
...
May 29 22:17:32 e2e-ubuntu-0 dockerd[23299]: time="2018-05-29T22:17:32.449592965Z" level=debug msg="Calling POST /v1.37/networks/create"
May 29 22:17:32 e2e-ubuntu-0 dockerd[23299]: time="2018-05-29T22:17:32.449701840Z" level=debug msg="form data: {\"Attachable\":false,\"CheckDuplicate\":true,\"ConfigFrom\":null,\"ConfigOnly\":false,\"Driver\":\"overlay\",\"EnableIPv6\":false,\"IPAM\":null,\"Ingress\":false,\"Internal\":false,\"Labels\":{\"XXXXXXXX\":\"\",\"testname\":\"YYYYYYYYY\",\"uuid\":\"a9568dd7-92ac-4eaf-ac8a-6c9749024c77\"},\"Name\":\"YYYYYYYY\",\"Options\":null,\"Scope\":\"\"}"
May 29 22:17:32 e2e-ubuntu-0 dockerd[23299]: time="2018-05-29T22:17:32.451610423Z" level=debug msg="ReleaseAddress(GlobalDefault/10.0.2.0/24, 10.0.2.1)"
May 29 22:17:32 e2e-ubuntu-0 dockerd[23299]: time="2018-05-29T22:17:32.451642782Z" level=debug msg="Released address PoolID:GlobalDefault/10.0.2.0/24, Address:10.0.2.1 Sequence:App: ipam/default/data, ID: GlobalDefault/10.0.2.0/24, DBIndex: 0x0, Bits: 256, Unselected: 243, Sequence: (0xc2e64380, 1)->(0x0, 6)->(0x1, 1)->end Curr:25"
May 29 22:17:32 e2e-ubuntu-0 dockerd[23299]: time="2018-05-29T22:17:32.451660051Z" level=debug msg="ReleasePool(GlobalDefault/10.0.2.0/24)"
May 29 22:17:32 e2e-ubuntu-0 dockerd[23299]: time="2018-05-29T22:17:32.451848044Z" level=debug msg="ReleaseAddress(GlobalDefault/10.0.3.0/24, 10.0.3.2)"
May 29 22:17:32 e2e-ubuntu-0 dockerd[23299]: time="2018-05-29T22:17:32.451877234Z" level=debug msg="Released address PoolID:GlobalDefault/10.0.3.0/24, Address:10.0.3.2 Sequence:App: ipam/default/data, ID: GlobalDefault/10.0.3.0/24, DBIndex: 0x0, Bits: 256, Unselected: 238, Sequence: (0xfac7fc00, 1)->(0x0, 6)->(0x1, 1)->end Curr:22"
May 29 22:17:32 e2e-ubuntu-0 dockerd[23299]: time="2018-05-29T22:17:32.452991996Z" level=debug msg="Calling POST /v1.37/services/create"
May 29 22:17:32 e2e-ubuntu-0 dockerd[23299]: time="2018-05-29T22:17:32.453097311Z" level=debug msg="form data: {\"EndpointSpec\":{\"Ports\":[{\"Protocol\":\"tcp\",\"PublishMode\":\"ingress\",\"TargetPort\":80}]},\"Labels\":{\"XXXXXXXX\":\"\",\"testname\":\"YYYYYYYY\",\"uuid\":\"a9568dd7-92ac-4eaf-ac8a-6c9749024c77\"},\"Mode\":{\"Replicated\":{\"Replicas\":3}},\"Name\":\"YYYYYYYY\",\"TaskTemplate\":{\"ContainerSpec\":{\"Command\":[\"FOO\",\"BAR\"],\"Healthcheck\":{\"Interval\":1000000000,\"Retries\":30,\"Test\":[\"CMD\",\"curl\",\"--fail\",\"http://localhost/ready\"]},\"Image\":\"XXXXXXXX\",\"StopGracePeriod\":18000000000},\"ForceUpdate\":0,\"Networks\":[{\"Target\":\"snpd7gym5zc0m6ptr49judiek\"}]}}"
May 29 22:17:32 e2e-ubuntu-0 dockerd[23299]: time="2018-05-29T22:17:32.453431107Z" level=debug msg="ReleaseAddress(GlobalDefault/10.0.3.0/24, 10.0.3.3)"
...
May 29 22:17:32 e2e-ubuntu-0 dockerd[23299]: time="2018-05-29T22:17:32.458853963Z" level=debug msg="RequestPool(GlobalDefault, , , map[], false)"
May 29 22:17:32 e2e-ubuntu-0 dockerd[23299]: time="2018-05-29T22:17:32.459090850Z" level=debug msg="RequestAddress(GlobalDefault/10.0.0.0/24, <nil>, map[com.docker.network.ipam.serial:true RequestAddressType:com.docker.network.gateway])"
May 29 22:17:32 e2e-ubuntu-0 dockerd[23299]: time="2018-05-29T22:17:32.459110425Z" level=debug msg="Request address PoolID:10.0.0.0/24 App: ipam/default/data, ID: GlobalDefault/10.0.0.0/24, DBIndex: 0x0, Bits: 256, Unselected: 254, Sequence: (0x80000000, 1)->(0x0, 6)->(0x1, 1)->end Curr:0 Serial:true PrefAddress:<nil> "
May 29 22:17:32 e2e-ubuntu-0 dockerd[23299]: time="2018-05-29T22:17:32.459090706Z" level=debug msg="memberlist: Stream connection from=172.31.44.135:46992"
May 29 22:17:32 e2e-ubuntu-0 dockerd[23299]: time="2018-05-29T22:17:32.459883427Z" level=debug msg="RequestAddress(GlobalDefault/10.0.0.0/24, <nil>, map[com.docker.network.ipam.serial:true])"
May 29 22:17:32 e2e-ubuntu-0 dockerd[23299]: time="2018-05-29T22:17:32.459903452Z" level=debug msg="Request address PoolID:10.0.0.0/24 App: ipam/default/data, ID: GlobalDefault/10.0.0.0/24, DBIndex: 0x0, Bits: 256, Unselected: 253, Sequence: (0xc0000000, 1)->(0x0, 6)->(0x1, 1)->end Curr:2 Serial:true PrefAddress:<nil> "
May 29 22:17:32 e2e-ubuntu-0 dockerd[23299]: time="2018-05-29T22:17:32.459923184Z" level=debug msg="RequestAddress(GlobalDefault/10.0.0.0/24, <nil>, map[com.docker.network.ipam.serial:true])"
May 29 22:17:32 e2e-ubuntu-0 dockerd[23299]: time="2018-05-29T22:17:32.459935091Z" level=debug msg="Request address PoolID:10.0.0.0/24 App: ipam/default/data, ID: GlobalDefault/10.0.0.0/24, DBIndex: 0x0, Bits: 256, Unselected: 252, Sequence: (0xe0000000, 1)->(0x0, 6)->(0x1, 1)->end Curr:3 Serial:true PrefAddress:<nil> "
May 29 22:17:32 e2e-ubuntu-0 dockerd[23299]: time="2018-05-29T22:17:32.459949597Z" level=debug msg="RequestAddress(GlobalDefault/10.0.0.0/24, <nil>, map[com.docker.network.ipam.serial:true])"
May 29 22:17:32 e2e-ubuntu-0 dockerd[23299]: time="2018-05-29T22:17:32.459960523Z" level=debug msg="Request address PoolID:10.0.0.0/24 App: ipam/default/data, ID: GlobalDefault/10.0.0.0/24, DBIndex: 0x0, Bits: 256, Unselected: 251, Sequence: (0xf0000000, 1)->(0x0, 6)->(0x1, 1)->end Curr:4 Serial:true PrefAddress:<nil> "
May 29 22:17:32 e2e-ubuntu-0 dockerd[23299]: time="2018-05-29T22:17:32.463555661Z" level=debug msg="RequestAddress(GlobalDefault/10.255.0.0/16, <nil>, map[com.docker.network.ipam.serial:true])"
May 29 22:17:32 e2e-ubuntu-0 dockerd[23299]: time="2018-05-29T22:17:32.463836756Z" level=debug msg="Request address PoolID:10.255.0.0/16 App: ipam/default/data, ID: GlobalDefault/10.255.0.0/16, DBIndex: 0x0, Bits: 65536, Unselected: 65528, Sequence: (0xfa800000, 1)->(0x0, 2046)->(0x1, 1)->end Curr:9 Serial:true PrefAddress:<nil> "
May 29 22:17:32 e2e-ubuntu-0 dockerd[23299]: time="2018-05-29T22:17:32.464125834Z" level=debug msg="RequestAddress(GlobalDefault/10.0.0.0/24, <nil>, map[com.docker.network.ipam.serial:true])"
May 29 22:17:32 e2e-ubuntu-0 dockerd[23299]: time="2018-05-29T22:17:32.464387180Z" level=debug msg="Request address PoolID:10.0.0.0/24 App: ipam/default/data, ID: GlobalDefault/10.0.0.0/24, DBIndex: 0x0, Bits: 256, Unselected: 250, Sequence: (0xf8000000, 1)->(0x0, 6)->(0x1, 1)->end Curr:5 Serial:true PrefAddress:<nil> "
May 29 22:17:32 e2e-ubuntu-0 dockerd[23299]: time="2018-05-29T22:17:32.465258046Z" level=debug msg="task 2ynv28b5tj5wl7etsxnlhxe7r was marked pending allocation" module=node node.id=z48gq4tlcf1asg2y04tp8w7tv
May 29 22:17:32 e2e-ubuntu-0 dockerd[23299]: time="2018-05-29T22:17:32.465323009Z" level=debug msg="task cn375x7crhdijd14lwpffj3h1 was marked pending allocation" module=node node.id=z48gq4tlcf1asg2y04tp8w7tv
May 29 22:17:32 e2e-ubuntu-0 dockerd[23299]: time="2018-05-29T22:17:32.465381398Z" level=debug msg="task p12whhw1qzmnfdek0yjy1tftm was marked pending allocation" module=node node.id=z48gq4tlcf1asg2y04tp8w7tv
May 29 22:17:32 e2e-ubuntu-0 dockerd[23299]: time="2018-05-29T22:17:32.465440180Z" level=debug msg="RequestAddress(GlobalDefault/10.255.0.0/16, <nil>, map[com.docker.network.ipam.serial:true])"
May 29 22:17:32 e2e-ubuntu-0 dockerd[23299]: time="2018-05-29T22:17:32.465465421Z" level=debug msg="Request address PoolID:10.255.0.0/16 App: ipam/default/data, ID: GlobalDefault/10.255.0.0/16, DBIndex: 0x0, Bits: 65536, Unselected: 65527, Sequence: (0xfac00000, 1)->(0x0, 2046)->(0x1, 1)->end Curr:10 Serial:true PrefAddress:<nil> "
May 29 22:17:32 e2e-ubuntu-0 dockerd[23299]: time="2018-05-29T22:17:32.465490940Z" level=debug msg="RequestAddress(GlobalDefault/10.0.0.0/24, <nil>, map[com.docker.network.ipam.serial:true])"
May 29 22:17:32 e2e-ubuntu-0 dockerd[23299]: time="2018-05-29T22:17:32.465508924Z" level=debug msg="Request address PoolID:10.0.0.0/24 App: ipam/default/data, ID: GlobalDefault/10.0.0.0/24, DBIndex: 0x0, Bits: 256, Unselected: 249, Sequence: (0xfc000000, 1)->(0x0, 6)->(0x1, 1)->end Curr:6 Serial:true PrefAddress:<nil> "
May 29 22:17:32 e2e-ubuntu-0 dockerd[23299]: time="2018-05-29T22:17:32.465535612Z" level=debug msg="allocated task p12whhw1qzmnfdek0yjy1tftm, state update PENDING" method="(*Allocator).allocateTask" module=node node.id=z48gq4tlcf1asg2y04tp8w7tv
May 29 22:17:32 e2e-ubuntu-0 dockerd[23299]: time="2018-05-29T22:17:32.465588639Z" level=debug msg="RequestAddress(GlobalDefault/10.255.0.0/16, <nil>, map[com.docker.network.ipam.serial:true])"
May 29 22:17:32 e2e-ubuntu-0 dockerd[23299]: time="2018-05-29T22:17:32.465612345Z" level=debug msg="Request address PoolID:10.255.0.0/16 App: ipam/default/data, ID: GlobalDefault/10.255.0.0/16, DBIndex: 0x0, Bits: 65536, Unselected: 65526, Sequence: (0xfae00000, 1)->(0x0, 2046)->(0x1, 1)->end Curr:11 Serial:true PrefAddress:<nil> "
May 29 22:17:32 e2e-ubuntu-0 dockerd[23299]: time="2018-05-29T22:17:32.465640227Z" level=debug msg="RequestAddress(GlobalDefault/10.0.0.0/24, <nil>, map[com.docker.network.ipam.serial:true])"
May 29 22:17:32 e2e-ubuntu-0 dockerd[23299]: time="2018-05-29T22:17:32.465660818Z" level=debug msg="Request address PoolID:10.0.0.0/24 App: ipam/default/data, ID: GlobalDefault/10.0.0.0/24, DBIndex: 0x0, Bits: 256, Unselected: 248, Sequence: (0xfe000000, 1)->(0x0, 6)->(0x1, 1)->end Curr:7 Serial:true PrefAddress:<nil> "
May 29 22:17:32 e2e-ubuntu-0 dockerd[23299]: time="2018-05-29T22:17:32.465686374Z" level=debug msg="allocated task 2ynv28b5tj5wl7etsxnlhxe7r, state update PENDING" method="(*Allocator).allocateTask" module=node node.id=z48gq4tlcf1asg2y04tp8w7tv
May 29 22:17:32 e2e-ubuntu-0 dockerd[23299]: time="2018-05-29T22:17:32.465735375Z" level=debug msg="RequestAddress(GlobalDefault/10.255.0.0/16, <nil>, map[com.docker.network.ipam.serial:true])"
May 29 22:17:32 e2e-ubuntu-0 dockerd[23299]: time="2018-05-29T22:17:32.465756015Z" level=debug msg="Request address PoolID:10.255.0.0/16 App: ipam/default/data, ID: GlobalDefault/10.255.0.0/16, DBIndex: 0x0, Bits: 65536, Unselected: 65525, Sequence: (0xfaf00000, 1)->(0x0, 2046)->(0x1, 1)->end Curr:12 Serial:true PrefAddress:<nil> "
May 29 22:17:32 e2e-ubuntu-0 dockerd[23299]: time="2018-05-29T22:17:32.465780915Z" level=debug msg="RequestAddress(GlobalDefault/10.0.0.0/24, <nil>, map[com.docker.network.ipam.serial:true])"
May 29 22:17:32 e2e-ubuntu-0 dockerd[23299]: time="2018-05-29T22:17:32.465800799Z" level=debug msg="Request address PoolID:10.0.0.0/24 App: ipam/default/data, ID: GlobalDefault/10.0.0.0/24, DBIndex: 0x0, Bits: 256, Unselected: 247, Sequence: (0xff000000, 1)->(0x0, 6)->(0x1, 1)->end Curr:8 Serial:true PrefAddress:<nil> "
May 29 22:17:32 e2e-ubuntu-0 dockerd[23299]: time="2018-05-29T22:17:32.465826750Z" level=debug msg="allocated task cn375x7crhdijd14lwpffj3h1, state update PENDING" method="(*Allocator).allocateTask" module=node node.id=z48gq4tlcf1asg2y04tp8w7tv
May 29 22:17:32 e2e-ubuntu-0 dockerd[23299]: time="2018-05-29T22:17:32.465967818Z" level=debug msg="committed allocated task p12whhw1qzmnfdek0yjy1tftm, state update {2018-05-29T22:17:32.465530728Z PENDING pending task scheduling  <nil> nil  (timestamp: nil Timestamp)}" module=node node.id=z48gq4tlcf1asg2y04tp8w7tv
May 29 22:17:32 e2e-ubuntu-0 dockerd[23299]: time="2018-05-29T22:17:32.466079930Z" level=debug msg="committed allocated task 2ynv28b5tj5wl7etsxnlhxe7r, state update {2018-05-29T22:17:32.465682512Z PENDING pending task scheduling  <nil> nil  (timestamp: nil Timestamp)}" module=node node.id=z48gq4tlcf1asg2y04tp8w7tv
May 29 22:17:32 e2e-ubuntu-0 dockerd[23299]: time="2018-05-29T22:17:32.466184172Z" level=debug msg="committed allocated task cn375x7crhdijd14lwpffj3h1, state update {2018-05-29T22:17:32.465822324Z PENDING pending task scheduling  <nil> nil  (timestamp: nil Timestamp)}" module=node node.id=z48gq4tlcf1asg2y04tp8w7tv
May 29 22:17:32 e2e-ubuntu-0 dockerd[23299]: time="2018-05-29T22:17:32.468491567Z" level=debug msg="Task p12whhw1qzmnfdek0yjy1tftm is already in allocated state PENDING" method="(*Allocator).doTaskAlloc" module=node node.id=z48gq4tlcf1asg2y04tp8w7tv
May 29 22:17:32 e2e-ubuntu-0 dockerd[23299]: time="2018-05-29T22:17:32.468745048Z" level=debug msg="Task 2ynv28b5tj5wl7etsxnlhxe7r is already in allocated state PENDING" method="(*Allocator).doTaskAlloc" module=node node.id=z48gq4tlcf1asg2y04tp8w7tv
May 29 22:17:32 e2e-ubuntu-0 dockerd[23299]: time="2018-05-29T22:17:32.468797787Z" level=debug msg="Task cn375x7crhdijd14lwpffj3h1 is already in allocated state PENDING" method="(*Allocator).doTaskAlloc" module=node node.id=z48gq4tlcf1asg2y04tp8w7tv
...
May 29 22:17:32 e2e-ubuntu-0 dockerd[23299]: time="2018-05-29T22:17:32.631980916Z" level=debug msg="Allocating IPv4 pools for network YYYYYYYY (snpd7gym5zc0m6ptr49judiek)"
May 29 22:17:32 e2e-ubuntu-0 dockerd[23299]: time="2018-05-29T22:17:32Z" level=debug msg="event published" module="containerd/tasks" ns=moby topic="/tasks/exec-started" type=containerd.events.TaskExecStarted
May 29 22:17:32 e2e-ubuntu-0 dockerd[23299]: time="2018-05-29T22:17:32.632518284Z" level=debug msg="RequestPool(LocalDefault, 10.0.0.0/24, , map[], false)"
May 29 22:17:32 e2e-ubuntu-0 dockerd[23299]: time="2018-05-29T22:17:32.632782068Z" level=debug msg="RequestAddress(LocalDefault/10.0.0.0/24, 10.0.0.1, map[RequestAddressType:com.docker.network.gateway])"
May 29 22:17:32 e2e-ubuntu-0 dockerd[23299]: time="2018-05-29T22:17:32.632849465Z" level=debug msg="Request address PoolID:10.0.0.0/24 App: ipam/default/data, ID: LocalDefault/10.0.0.0/24, DBIndex: 0x0, Bits: 256, Unselected: 252, Sequence: (0xc1000000, 1)->(0x0, 6)->(0x1, 1)->end Curr:0 Serial:false PrefAddress:10.0.0.1 "
May 29 22:17:32 e2e-ubuntu-0 dockerd[23299]: time="2018-05-29T22:17:32.632883701Z" level=debug May 29 22:17:32 e2e-ubuntu-0 dockerd[23299]: time="2018-05-29T22:17:32.632902732Z" level=debug msg="ReleasePool(LocalDefault/10.0.0.0/24)"
May 29 22:17:32 e2e-ubuntu-0 dockerd[23299]: time="2018-05-29T22:17:32.632924876Z" level=error msg="fatal task error" error="failed to allocate gateway (10.0.0.1): Address already in use" module=node/agent/taskmanager node.id=z48gq4tlcf1asg2y04tp8w7tv service.id=yr8g7exbd9oltrdxu7g5txqjm task.id=p12whhw1qzmnfdek0yjy1tftm
May 29 22:17:32 e2e-ubuntu-0 dockerd[23299]: time="2018-05-29T22:17:32.632969068Z" level=debug msg="state changed" module=node/agent/taskmanager node.id=z48gq4tlcf1asg2y04tp8w7tv service.id=yr8g7exbd9oltrdxu7g5txqjm state.desired=RUNNING state.transition="PREPARING->REJECTED" task.id=p12whhw1qzmnfdek0yjy1tftm

The intuitively correct behavior would be for swarm to wait for confirmation of the release of resources before reallocating them. This sounds like a significant change, however.

The issue names no source files, tests, or entry points. Start by tracing the network deletion and task allocation sequence described in the logs, then reproduce the destroy-and-recreate workload. Done means subnet reuse no longer causes task rejection or the reported address-in-use error while resources are still being removed.