fix E2E_UPDATE_DEVICE_3 failure

[luogangyi]

What type of PR is this?

Uncomment only one /kind <> line, hit enter to put that in a new line, and remove leading whitespaces from that line:

/kind api-change
/kind bug
/kind cleanup
/kind design
/kind documentation
/kind test
/kind failing-test
/kind feature

What this PR does / why we need it:
to solve e2e test occasional failure on E2E_UPDATE_DEVICE_3

Which issue(s) this PR fixes:

Fixes #1627

Special notes for your reviewer:

Does this PR introduce a user-facing change?:

NONE

[luogangyi]

/hold

[luogangyi]

add some key log to see what happened

[daixiang0]

@luogangyi For test, you may pull request in your own repo then you can get admin premission and no need to wait.

[luogangyi]

@luogangyi For test, you may pull request in your own repo then you can get admin premission and no need to wait.

OK， I will try.

[luogangyi]

I0524 15:31:33.040450   19621 process.go:162] received msg from cloud-hub:{Header:{ID:a4f24ff3-8c65-4f86-a0bc-a2552718c685 ParentID:3cf8b27a-6f74-4c8f-9349-8ff0d7a9889b Timestamp:1590334293040 ResourceVersion:594 Sync:false} Router:{Source:devicecontroller Group:twin Operation:update Resource:membership} Content:map[added_devices:<nil> event_id:8b703d77-9107-490b-bff6-846ce771a0ff removed_devices:[map[description:TISensorTag id:sensor-tag-instance-01 name:sensor-tag-instance-01 twin:map[io-data:map[expected:map[metadata:map[timestamp:1.59033429304e+12] value:1] expected_version:map[cloud:611 edge:0] metadata:map[type:int] optional:false]]]] timestamp:1.59033429304e+12]}
I0524 15:31:33.040563   19621 process.go:286] DeviceTwin receive msg
I0524 15:31:33.040578   19621 process.go:51] Send msg to the CommModule module in twin
I0524 15:31:33.040637   19621 process.go:66] Send msg to the MemModule module in twin
I0524 15:31:33.040651   19621 membership.go:119] Membership event
I0524 15:31:33.040696   19621 communicate.go:36] receive msg commModule
I0524 15:31:33.040707   19621 communicate.go:112] CONFIRM EVENT
I0524 15:31:33.040714   19621 membership.go:257] Begin to remove devices
I0524 15:31:33.040714   19621 communicate.go:117] CommModule deal confirm msgID 3cf8b27a-6f74-4c8f-9349-8ff0d7a9889b
I0524 15:31:33.046380   19621 membership.go:278] Delete document of device sensor-tag-instance-01 successful
I0524 15:31:33.046466   19621 membership.go:304] Remove device sensor-tag-instance-01 successful
I0524 15:31:33.046483   19621 communicate.go:36] receive msg commModule
I0524 15:31:33.089472   19621 process.go:162] received msg from cloud-hub:{Header:{ID:7d08a86f-716b-48a2-ad0e-a1e19612142f ParentID:3cf8b27a-6f74-4c8f-9349-8ff0d7a9889b Timestamp:1590334293089 ResourceVersion:594 Sync:false} Router:{Source:devicecontroller Group:twin Operation:update Resource:membership} Content:map[added_devices:[map[description:TISimplelinkSensorTag id:sensor-tag-instance-02 name:sensor-tag-instance-02 twin:map[temperature-enable:map[expected:map[metadata:map[timestamp:1.590334293089e+12] value:OFF] expected_version:map[cloud:615 edge:0] metadata:map[type:string] optional:false]]]] event_id:53dbb8aa-5595-44f7-b8fe-64e2b2c2ef0a removed_devices:<nil> timestamp:1.590334293089e+12]}
I0524 15:31:33.089556   19621 process.go:162] received msg from cloud-hub:{Header:{ID:82577e60-1427-4449-a352-1238b8267eba ParentID:3cf8b27a-6f74-4c8f-9349-8ff0d7a9889b Timestamp:1590334293089 ResourceVersion:594 Sync:false} Router:{Source:devicecontroller Group:twin Operation:update Resource:device/sensor-tag-instance-02/twin/cloud_updated} Content:map[event_id:91992726-1ce7-4f70-97d3-a417d5a9dbfb timestamp:1.590334293089e+12 twin:map[temperature-enable:map[expected:map[metadata:map[timestamp:1.590334293089e+12] value:ON] expected_version:map[cloud:616 edge:0] metadata:map[type:string] optional:false]]]}
I0524 15:31:33.089593   19621 process.go:286] DeviceTwin receive msg
I0524 15:31:33.089605   19621 process.go:51] Send msg to the CommModule module in twin
I0524 15:31:33.089651   19621 process.go:66] Send msg to the TwinModule module in twin
I0524 15:31:33.089661   19621 twin.go:89] Twin Sync EVENT
I0524 15:31:33.091223   19621 twin.go:107] Begin to update twin of the device sensor-tag-instance-02
E0524 15:31:33.091247   19621 dtcontext.go:81] GetMutex device sensor-tag-instance-02 not exist
I0524 15:31:33.091252   19621 twin.go:166] Begin to deal device twin of the device sensor-tag-instance-02
E0524 15:31:33.091260   19621 twin.go:171] Update twin rejected due to the device sensor-tag-instance-02 is not existed
I0524 15:31:33.091266   19621 twin.go:233] Deal update result of device sensor-tag-instance-02: Build and send result
I0524 15:31:33.091324   19621 twin.go:253] Deal update result of device sensor-tag-instance-02: send result
E0524 15:31:33.091338   19621 dtcontext.go:81] GetMutex device sensor-tag-instance-02 not exist
I0524 15:31:33.091351   19621 process.go:286] DeviceTwin receive msg
I0524 15:31:33.091359   19621 process.go:51] Send msg to the CommModule module in twin
I0524 15:31:33.091404   19621 process.go:66] Send msg to the MemModule module in twin
I0524 15:31:33.091416   19621 membership.go:119] Membership event
I0524 15:31:33.091469   19621 membership.go:166] Add devices to edge group
I0524 15:31:33.091803   19621 communicate.go:36] receive msg commModule
I0524 15:31:33.091814   19621 communicate.go:112] CONFIRM EVENT
I0524 15:31:33.091820   19621 communicate.go:117] CommModule deal confirm msgID 3cf8b27a-6f74-4c8f-9349-8ff0d7a9889b
I0524 15:31:33.091831   19621 communicate.go:36] receive msg commModule
I0524 15:31:33.091839   19621 communicate.go:36] receive msg commModule
I0524 15:31:33.091844   19621 communicate.go:112] CONFIRM EVENT
I0524 15:31:33.091848   19621 communicate.go:117] CommModule deal confirm msgID 3cf8b27a-6f74-4c8f-9349-8ff0d7a9889b
I0524 15:31:33.095152   19621 membership.go:227] Add device twin during first adding device sensor-tag-instance-02
I0524 15:31:33.095166   19621 twin.go:166] Begin to deal device twin of the device sensor-tag-instance-02

Finally, we see what happened.

Device update action immediately after Device create action, and there is no gurantee that edge core will process device create action first.
We should make sure device is created first and then doing update

[daixiang0]

Good catch!

[luogangyi]

/hold cancel

[luogangyi]

/hold cancel

[fisherxu]

/lgtm
/approve

Thanks for the fix!

[kubeedge-bot]

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: fisherxu

The full list of commands accepted by this bot can be found here.

The pull request process is described here

Needs approval from an approver in each of these files:

• tests/e2e/OWNERS [fisherxu]

Approvers can indicate their approval by writing /approve in a comment
Approvers can cancel approval by writing /approve cancel in a comment