Bug 2004632

Summary: When LE takes a large amount of time, multiple whereabouts are seen
Product: OpenShift Container Platform Reporter: Martin Kennelly <mkennell>
Component: NetworkingAssignee: Douglas Smith <dosmith>
Networking sub component: multus QA Contact: Weibin Liang <weliang>
Status: CLOSED ERRATA Docs Contact:
Severity: high    
Priority: urgent CC: bbennett
Version: 4.10   
Target Milestone: ---   
Target Release: 4.10.0   
Hardware: All   
OS: All   
Whiteboard:
Fixed In Version: Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of:
: 2009493 (view as bug list) Environment:
Last Closed: 2022-03-10 16:10:53 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On:    
Bug Blocks: 2009493    
Attachments:
Description Flags
wb debug logs for allocate IP. One pod present on node. none

Description Martin Kennelly 2021-09-15 17:04:06 UTC 
Created attachment 1823405 [details]
wb debug logs for allocate IP. One pod present on node.

Description of problem:
During scale testing, I saw pod periodically created and destroyed, then stuck on DEL loop. 

Example output from WB debug log:
19:46:12Z [debug] ADD
20:02:58Z [debug] DEL 
20:03:59Z [debug] DEL 
20:04:59Z [debug] DEL 
20:05:59Z [debug] DEL
etc

If pod is not created in ~5m, kubelet kills the pod because it doesn’t detect that a sandbox status has been populated:


Sep 10 19:29:33 ip-10-0-165-101 hyperkube[1430]: I0910 19:29:33.549539    1430 kuberuntime_manager.go:483] "No sandbox for pod can be found. Need to start a new one" pod="default/whereabouts-scale-test-748g8"
Sep 10 19:29:34 ip-10-0-165-101 hyperkube[1430]: I0910 19:29:34.550139    1430 kuberuntime_manager.go:483] "No sandbox for pod can be found. Need to start a new one" pod="default/whereabouts-scale-test-7zqzr"

Old instance of WB still remain active. 
If a pod requesting an IP using whereabouts doesn’t start in ~5 mins, you add another connection to the backend and the old connection persists.

See attach output from WB log file during allocate IP phase.

All instances were elected as leader at the same time and all were trying to allocate IP for the pod. 

Version-Release number of selected component (if applicable):


How reproducible:
At scale - greater than 600 pods which have a WB managed IP, you will see this. 

Steps to Reproduce:
1. Use this script to setup the test that will cause congestion and long LE period for pods  - https://github.com/maiqueb/whereabouts-stopwatch/pull/5
2. Cordon a node
4. Uncordon node
5. Schedule a new pod requesting IP using WB
6. Check if pod landed on node that was previously uncordoned - if not use nodeSelector and try again.
7. Wait more than 5 mins, and see ensure pod has not received IP.
8. On node, use ps to view WB instances. There should be at least 2 instances of WB.


Actual results:
multiple WB instances for a single pod

Expected results:
one wb instance per pod

Additional info:
Comment 1 Martin Kennelly 2021-09-16 14:01:13 UTC 
I think, I see the issue in the code - in pkg/storage/kubernetes/ipam.go:

go func() {
   defer wg.Done()
   ctx, cancel := context.WithCancel(context.Background())
   res := make(chan error)

   go func() {
      logging.Debugf("Started leader election")
      le.Run(ctx)
      logging.Debugf("Finished leader election")
      res <- nil
   }()

LE never ends and needs a timeout. It should be context.WithTimeout().
Comment 2 Martin Kennelly 2021-09-20 11:29:29 UTC 
Here is a possible implementation of a fix:
https://github.com/k8snetworkplumbingwg/whereabouts/pull/142
Comment 5 Weibin Liang 2021-10-15 20:08:15 UTC 
Flow the steps in description, all the pods can get the unical IP addresses from two WB instances, tested in 4.10.0-0.nightly-2021-10-15-025303

[weliang@weliang whereabouts-stopwatch]$ oc get pods | grep test | awk '{print $1}' | xargs -I {} oc exec -t {} -- ip a | grep "inet 10.10" | awk '{print $2}' | sort | uniq | wc -l
406
[weliang@weliang whereabouts-stopwatch]$ oc get pod | grep Running | wc -l
406
Comment 8 errata-xmlrpc 2022-03-10 16:10:53 UTC 
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory (Moderate: OpenShift Container Platform 4.10.3 security update), and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHSA-2022:0056