Bug 1298121

Summary: Can't record NodeNotSchedulable/NodeSchedulable event when run command quickly
Product: OpenShift Container Platform Reporter: DeShuai Ma <dma>
Component: NodeAssignee: Seth Jennings <sjenning>
Status: CLOSED NOTABUG QA Contact: Xiaoli Tian <xtian>
Severity: low Docs Contact:
Priority: low    
Version: unspecifiedCC: aos-bugs, gblomqui, haowang, jokerman, mmccomas
Target Milestone: ---   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2019-07-03 15:04:12 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:

Description DeShuai Ma 2016-01-13 10:07:44 UTC
Description of problem:
When run manage-node command with --schedulable=false/true quickly, can't record NodeNotSchedulable/NodeSchedulable event. Run one command and wait a moment then run another can record event successfully.

Version-Release number of selected component (if applicable):
openshift v1.1-764-g7e08c95
kubernetes v1.1.0-origin-1107-g4c8e6f4
etcd 2.1.2

How reproducible:
Always

Steps to Reproduce:
1.Check NodeNotSchedulable/NodeSchedulable event
[fedora@ip-172-18-6-98 sample-app]$ oc get event|grep "NodeNotSchedulable"
12m         8m         3         ip-172-18-6-98            Node                                          NodeNotSchedulable   {kubelet ip-172-18-6-98}      Node ip-172-18-6-98 status is now: NodeNotSchedulable
[fedora@ip-172-18-6-98 sample-app]$ oc get event|grep "NodeSchedulable"
10m         8m         3         ip-172-18-6-98            Node                                          NodeSchedulable      {kubelet ip-172-18-6-98}      Node ip-172-18-6-98 status is now: NodeSchedulable

2.Enable/Disable node schedulable quickly
cat > run.sh <<EOF
oadm manage-node ip-172-18-6-98 --schedulable=false
oadm manage-node ip-172-18-6-98 --schedulable=true
EOF
$ sh run.sh

3.Check NodeNotSchedulable/NodeSchedulable event
[fedora@ip-172-18-6-98 sample-app]$ oc get event|grep "NodeNotSchedulable"
14m         10m        3         ip-172-18-6-98            Node                                          NodeNotSchedulable   {kubelet ip-172-18-6-98}      Node ip-172-18-6-98 status is now: NodeNotSchedulable
[fedora@ip-172-18-6-98 sample-app]$ oc get event|grep "NodeSchedulable"
13m         10m        3         ip-172-18-6-98            Node                                          NodeSchedulable      {kubelet ip-172-18-6-98}      Node ip-172-18-6-98 status is now: NodeSchedulable


Actual results:
3.No new NodeNotSchedulable/NodeSchedulable event be recorded

Expected results:
3.Should record NodeNotSchedulable/NodeSchedulable event

Additional info:

Comment 1 Avesh Agarwal 2016-02-03 16:19:46 UTC
Its weird, somehow I am not able to see any events in origin now, still looking why the api server seems to be rejecting all events.

Comment 2 Avesh Agarwal 2016-02-03 16:21:29 UTC
E0203 11:02:32.658211   28129 event.go:188] Server rejected event '&api.Event{TypeMeta:unversioned.TypeMeta{Kind:"", APIVersion:""}, ObjectMeta:api.ObjectMeta{Name:"192.168.122.253.142f7a01c37a7f2d", GenerateName:"", Namespace:"default", SelfLink:"", UID:"", ResourceVersion:"", Generation:0, CreationTimestamp:unversioned.Time{Time:time.Time{sec:0, nsec:0, loc:(*time.Location)(nil)}}, DeletionTimestamp:(*unversioned.Time)(nil), DeletionGracePeriodSeconds:(*int64)(nil), Labels:map[string]string(nil), Annotations:map[string]string(nil)}, InvolvedObject:api.ObjectReference{Kind:"Node", Namespace:"", Name:"192.168.122.253", UID:"192.168.122.253", APIVersion:"", ResourceVersion:"", FieldPath:""}, Reason:"RegisteredNode", Message:"Node 192.168.122.253 event: Registered Node 192.168.122.253 in NodeController", Source:api.EventSource{Component:"controllermanager", Host:""}, FirstTimestamp:unversioned.Time{Time:time.Time{sec:63590112152, nsec:657100589, loc:(*time.Location)(0x51cd8c0)}}, LastTimestamp:unversioned.Time{Time:time.Time{sec:63590112152, nsec:657100589, loc:(*time.Location)(0x51cd8c0)}}, Count:1, Type:"Normal"}': 'Event "192.168.122.253.142f7a01c37a7f2d" is invalid: involvedObject.namespace: invalid value '', Details: not required for node' (will not retry!)

Comment 3 Avesh Agarwal 2016-02-03 17:33:10 UTC
I am able to reproduce the issue.

Comment 4 Avesh Agarwal 2016-02-03 17:34:41 UTC
Please note, I was able to reproduce it with origin/v1.1.1.1 tag as the latest origin master branch has issue as server is rejecting events from node.

Comment 5 Avesh Agarwal 2016-02-03 18:20:07 UTC
It seems that as far as one is as quick as under 5s, there wont be new events shown with oc get events.

Comment 6 Avesh Agarwal 2016-02-04 14:06:40 UTC
I looked into the code and it seems that it is working as expected. So right now it seems like "not a bug".

The reason is that kubelet does not send/record events if it finds that there is not change in its current state (node.Spec.Unschedulable) and old state (oldNodeUnschedulable). 

If the change from Schedulable->Unschedulable->Schedulable is fast enough (every few seconds kubelet updates its status to api server ) that the state remain same Schedulable during this period, no event is generated. And thats why this behaviour.  

I am not sure it is worthwhile to change kubelet behaviour for this issue. So again I would say it sounds like "not a bug" right now. 

Please let me know if it makes sense and we can close this bug.

Comment 9 Greg Blomquist 2019-07-03 15:04:12 UTC
See comment #6