Repository: kubernetes/kubernetes
File: pkg/scheduler/util/assumecache/assume_cache.go (Go)

Code before:
	storedVersion, err := c.getObjVersion(name, objInfo.latestObj)
	if err != nil {
		return err
	}

	if newVersion < storedVersion {
		return fmt.Errorf("%v %q is out of sync (stored: %d, assume: %d)", c.description, name, storedVersion, newVersion)
	}

	c.pushEvent(objInfo.latestObj, obj)

	// Only update the cached object
	oldObj := objInfo.latestObj
	objInfo.latestObj = obj
	if loggerV := c.logger.V(6); loggerV.Enabled() {
		c.logger.V(5).Info("Assumed object", "description", c.description, "cacheKey", name, "version", newVersion, "oldObj", klog.Format(oldObj), "newObj", klog.Format(obj))
	} else {
		c.logger.V(5).Info("Assumed object", "description", c.description, "cacheKey", name, "version", newVersion)
	}
	return nil
}

// Restore the informer cache's version of the object.
func (c *AssumeCache) Restore(objName string) {
	defer c.emitEvents()
	c.rwMutex.Lock()
	defer c.rwMutex.Unlock()

	objInfo, err := c.getObjInfo(objName)
	if err != nil {
		// This could be expected if object got deleted
		c.logger.V(5).Info("Restore object", "description", c.description, "cacheKey", objName, "err", err)
	} else {
		if objInfo.latestObj != objInfo.apiObj {
			c.pushEvent(objInfo.latestObj, objInfo.apiObj)
			objInfo.latestObj = objInfo.apiObj
		}
		c.logger.V(5).Info("Restored object", "description", c.description, "cacheKey", objName)
	}
}

// AddEventHandler adds an event handler to the cache. Events to a
// single handler are delivered sequentially, but there is no
// coordination between different handlers. A handler may use the
// cache.
//
// The return value can be used to wait for cache synchronization.
func (c *AssumeCache) AddEventHandler(handler cache.ResourceEventHandler) cache.ResourceEventHandlerRegistration {
	defer c.emitEvents()
	c.rwMutex.Lock()
	defer c.rwMutex.Unlock()

Review comment (bug):
This log snippet (from https://storage.googleapis.com/kubernetes-ci-logs/logs/ci-kubernetes-e2e-gci-gce-containerd/2007547529339604992/artifacts/bootstrap-e2e-master/kube-scheduler.log, GCE cluster, -v=4) shows that the "Assumed object" isn't really informative on its own:

```
I0103 20:27:52.742957      11 eventhandlers.go:391] "Add event for scheduled pod" pod="webhook-2738/sample-webhook-deployment-7c5c95bb96-htr47"
I0103 20:27:52.743095      11 eventhandlers.go:352] "Delete event for unscheduled pod" pod="webhook-2738/sample-webhook-deployment-7c5c95bb96-htr47"
I0103 20:27:52.753795      11 eventhandlers.go:424] "Update event for scheduled pod" pod="persistent-local-volumes-test-6988/hostexec-bootstrap-e2e-minion-group-2x0m-ks979"
I0103 20:27:52.754874      11 eventhandlers.go:424] "Update event for scheduled pod" pod="dra-2041/tester-1"
I0103 20:27:52.795316      11 assume_cache.go:460] "Assumed object" description="ResourceClaim" cacheKey="dra-2041/external-claim" version=4047
I0103 20:27:52.797009      11 default_binder.go:69] "Attempting to bind pod to node" logger="Bind.DefaultBinder" pod="dra-2041/tester-3" node="bootstrap-e2e-minion-group-sp9p"
I0103 20:27:52.820383      11 schedule_one.go:337] "Successfully bound pod to node" pod="dra-2041/tester-3" node="bootstrap-e2e-minion-group-sp9p" evaluatedNodes=5 feasibleNodes=1
I0103 20:27:52.832540      11 eventhandlers.go:391] "Add event for scheduled pod" pod="dra-2041/tester-3"
I0103 20:27:52.832920      11 eventhandlers.go:352] "Delete event for unscheduled pod" pod="dra-2041/tester-3"
I0103 20:27:52.841879      11 eventhandlers.go:424] "Update event for scheduled pod" pod="provisioning-2233/pod-subpath-test-preprovisionedpv-2xv5"
I0103 20:27:52.860033      11 assume_cache.go:460] "Assumed object" description="ResourceClaim" cacheKey="dra-2041/external-claim" version=4051
I0103 20:27:52.860107      11 default_binder.go:69] "Attempting to bind pod to node" logger="Bind.DefaultBinder" pod="dra-2041/tester-2" node="bootstrap-e2e-minion-group-sp9p"
```

It's targeted towards a developer, but as one such developer I don't get all the information that I need. From the commit message:

    Debugging that issue depends on seeing all changes related to assume cache
    changes (not just the single "Assumed object") and in-flight claims. We could
    make them all V(4) (= "debug level") but they seem more appropriate for V(5) (=
    "trace level"), so the assume cache verbosity gets toned down to that.


Code after:
	}

	newVersion, err := c.getObjVersion(name, obj)
	if err != nil {
		return err
	}

	storedVersion, err := c.getObjVersion(name, objInfo.latestObj)
	if err != nil {
		return err
	}

	if newVersion < storedVersion {
		return fmt.Errorf("%v %q is out of sync (stored: %d, assume: %d)", c.description, name, storedVersion, newVersion)
	}

	c.pushEvent(objInfo.latestObj, obj)

	// Only update the cached object
	oldObj := objInfo.latestObj
	objInfo.latestObj = obj
	if loggerV := c.logger.V(6); loggerV.Enabled() {
		loggerV.Info("Assumed object", "description", c.description, "cacheKey", name, "version", newVersion, "oldObj", klog.Format(oldObj), "newObj", klog.Format(obj))
	} else {
		c.logger.V(5).Info("Assumed object", "description", c.description, "cacheKey", name, "version", newVersion)
	}
	return nil
}

// Restore the informer cache's version of the object.
func (c *AssumeCache) Restore(objName string) {
	defer c.emitEvents()
	c.rwMutex.Lock()
	defer c.rwMutex.Unlock()

	objInfo, err := c.getObjInfo(objName)
	if err != nil {
		// This could be expected if object got deleted
		c.logger.V(5).Info("Restore object", "description", c.description, "cacheKey", objName, "err", err)
	} else {
		if objInfo.latestObj != objInfo.apiObj {
			c.pushEvent(objInfo.latestObj, objInfo.apiObj)
			objInfo.latestObj = objInfo.apiObj
		}
		c.logger.V(5).Info("Restored object", "description", c.description, "cacheKey", objName)
	}
}

// AddEventHandler adds an event handler to the cache. Events to a
// single handler are delivered sequentially, but there is no
// coordination between different handlers. A handler may use the