Creation of logical device fails with no mac address set for the device

On a repeat create + delete loop test with voltha-2.1 latest and bbsim using kind-voltha full environment, the test fails sometimes and logical device list would be empty in voltha

The reason for that, is that is when the device state transitions to operational state up and admin state active , it triggers a device state machine transition to create logical device in the core.

Creation of logical device fails as device does not have SERIAL NUMBER or MAC ADDRESS as its NONE or EMPTY and refuses to create!

 

When the OLT up indication gets to adapter and device state goes operationally active with admin state enabled, create logical device device state machine trigger results in the following failure:

This results in a condition where no logical device exists and hence the system test fails.

{"level":"info","ts":"2019-10-14T21:54:19.144Z","msg":"CreateLogicalDevice","instanceId":"voltha-rw-core-12-65b99947bd-qhck8","caller":"device_manager.CreateLogic     alDevice:983"}

4079 {"level":"debug","ts":"2019-10-14T21:54:19.144Z","msg":"creating-logical-device","instanceId":"voltha-rw-core-12-65b99947bd-qhck8","caller":"logical_device_manage     r.createLogicalDevice:157","deviceId":"129128b8105ed2d0bf3abaf3"}
4080

{"level":"error","ts":"2019-10-14T21:54:19.144Z","msg":"mac-address-not-set","instanceId":"voltha-rw-core-12-65b99947bd-qhck8","caller":"[logical_device_manager.cr|https://slack-redir.net/link?url=http%3A%2F%2Flogical_device_manager.cr]     eateLogicalDevice:170","deviceId":"129128b8105ed2d0bf3abaf3","stacktrace":"[github.com/opencord/voltha-go/common/log.Errorw\n\t/go/src/github.com/opencord/voltha-g|https://slack-redir.net/link?url=http%3A%2F%2Fgithub.com%2Fopencord%2Fvoltha-go%2Fcommon%2Flog.Errorw%5Cn%5Ct%2Fgo%2Fsrc%2Fgithub.com%2Fopencord%2Fvoltha-g]     o/common/log/log.go:721\[ngithub.com/opencord/voltha-go/rw_core/core.(*LogicalDeviceManager).createLogicalDevice\n\t/go/src/github.com/opencord/voltha-go/rw_core/c|https://slack-redir.net/link?url=http%3A%2F%2Fngithub.com%2Fopencord%2Fvoltha-go%2Frw_core%2Fcore.(*LogicalDeviceManager).createLogicalDevice%5Cn%5Ct%2Fgo%2Fsrc%2Fgithub.com%2Fopencord%2Fvoltha-go%2Frw_core%2Fc]     ore/logical_device_manager.go:170\[ngithub.com/opencord/voltha-go/rw_core/core.(*DeviceManager).CreateLogicalDevice\n\t/go/src/github.com/opencord/voltha-go/rw_cor|https://slack-redir.net/link?url=http%3A%2F%2Fngithub.com%2Fopencord%2Fvoltha-go%2Frw_core%2Fcore.(*DeviceManager).CreateLogicalDevice%5Cn%5Ct%2Fgo%2Fsrc%2Fgithub.com%2Fopencord%2Fvoltha-go%2Frw_cor]     e/core/device_manager.go:991\[ngithub.com/opencord/voltha-go/rw_core/core.(*DeviceManager).processTransition\n\t/go/src/github.com/opencord/voltha-go/rw_core/core/|https://slack-redir.net/link?url=http%3A%2F%2Fngithub.com%2Fopencord%2Fvoltha-go%2Frw_core%2Fcore.(*DeviceManager).processTransition%5Cn%5Ct%2Fgo%2Fsrc%2Fgithub.com%2Fopencord%2Fvoltha-go%2Frw_core%2Fcore%2F]     device_manager.go:946\[ngithub.com/opencord/voltha-go/rw_core/core.(*DeviceAgent).processUpdate.func1\n\t/go/src/github.com/opencord/voltha-go/rw_core/core/device_|https://slack-redir.net/link?url=http%3A%2F%2Fngithub.com%2Fopencord%2Fvoltha-go%2Frw_core%2Fcore.(*DeviceAgent).processUpdate.func1%5Cn%5Ct%2Fgo%2Fsrc%2Fgithub.com%2Fopencord%2Fvoltha-go%2Frw_core%2Fcore%2Fdevice_]     agent.go:1015"}

 
However at 21:54:16 that is 3 seconds before the transition to create logical device,
the device data was updated with the mac from the adapter invoking DeviceUpdate:
(before the creation as the update device from adapter comes first)
 

{"level":"debug","ts":"2019-10-14T21:54:16.525Z","msg":"updateDeviceUsingAdapterData","instanceId":"voltha-rw-core-12-65b99947bd-qhck8","caller":"     device_manager.updateDeviceUsingAdapterData:649","deviceid":"129128b8105ed2d0bf3abaf3","device":"id:\"129128b8105ed2d0bf3abaf3\" type:\"openolt\"      root:true vendor:\"BBSim\" model:\"asfvolt16\" hardware_version:\"emulated\" serial_number:\"BBSIM_OLT_0\" adapter:\"openolt\" mac_address:\"00:00     :0a:62:31:a5\" host_and_port:\"10.98.49.165:50060\" admin_state:PREPROVISIONED flows:<> flow_groups:<> "}

3599 {"level":"debug","ts":"2019-10-14T21:54:16.525Z","msg":"updateDeviceUsingAdapterData","instanceId":"voltha-rw-core-12-65b99947bd-qhck8","caller":"     device_agent.updateDeviceUsingAdapterData:1047","deviceId":"129128b8105ed2d0bf3abaf3"}There is a updateData warning updating db that follows:{"level":"debug","ts":"2019-10-14T21:54:16.539Z","msg":"updating-persisted-data","instanceId":"voltha-rw-core-12-65b99947bd-qhck8","caller":"persi     sted_revision.UpdateData:257","hash":"8f1335c215d6"}
3626

{"level":"warn","ts":"2019-10-14T21:54:16.539Z","msg":"data-is-older-than-current","instanceId":"voltha-rw-core-12-65b99947bd-qhck8","caller":"non     _persisted_revision.UpdateData:289","ctx-ts":1571090056525563448,"rev-ts":1571090056526603294,"stacktrace":"[github.com/opencord/voltha-go/common/l|https://slack-redir.net/link?url=http%3A%2F%2Fgithub.com%2Fopencord%2Fvoltha-go%2Fcommon%2Fl]     og.Warnw\n\t/go/src/github.com/opencord/voltha-go/common/log/log.go:700\[ngithub.com/opencord/voltha-go/db/model.(*NonPersistedRevision).UpdateData|https://slack-redir.net/link?url=http%3A%2F%2Fngithub.com%2Fopencord%2Fvoltha-go%2Fdb%2Fmodel.(*NonPersistedRevision).UpdateData]     \n\t/go/src/github.com/opencord/voltha-go/db/model/non_persisted_revision.go:289\[ngithub.com/opencord/voltha-go/db/model.(*PersistedRevision).Upda|https://slack-redir.net/link?url=http%3A%2F%2Fngithub.com%2Fopencord%2Fvoltha-go%2Fdb%2Fmodel.(*PersistedRevision).Upda]     teData\n\t/go/src/github.com/opencord/voltha-go/db/model/persisted_revision.go:259\[ngithub.com/opencord/voltha-go/db/model.(*node).doUpdate\n\t/go|https://slack-redir.net/link?url=http%3A%2F%2Fngithub.com%2Fopencord%2Fvoltha-go%2Fdb%2Fmodel.(*node).doUpdate%5Cn%5Ct%2Fgo]     /src/github.com/opencord/voltha-go/db/model/node.go:615\[ngithub.com/opencord/voltha-go/db/model.(*node).Update\n\t/go/src/github.com/opencord/volt|https://slack-redir.net/link?url=http%3A%2F%2Fngithub.com%2Fopencord%2Fvoltha-go%2Fdb%2Fmodel.(*node).Update%5Cn%5Ct%2Fgo%2Fsrc%2Fgithub.com%2Fopencord%2Fvolt]     ha-go/db/model/node.go:477\[ngithub.com/opencord/voltha-go/db/model.(*node).Update\n\t/go/src/github.com/opencord/voltha-go/db/model/node.go:529\ng|https://slack-redir.net/link?url=http%3A%2F%2Fngithub.com%2Fopencord%2Fvoltha-go%2Fdb%2Fmodel.(*node).Update%5Cn%5Ct%2Fgo%2Fsrc%2Fgithub.com%2Fopencord%2Fvoltha-go%2Fdb%2Fmodel%2Fnode.go%3A529%5Cng]     [ithub.com/opencord/voltha-go/db/model.(*root).Update\n\t/go/src/github.com/opencord/voltha-go/db/model/root.go:199\ngithub.com/opencord/voltha-go/|https://slack-redir.net/link?url=http%3A%2F%2Fithub.com%2Fopencord%2Fvoltha-go%2Fdb%2Fmodel.(*root).Update%5Cn%5Ct%2Fgo%2Fsrc%2Fgithub.com%2Fopencord%2Fvoltha-go%2Fdb%2Fmodel%2Froot.go%3A199%5Cngithub.com%2Fopencord%2Fvoltha-go%2F]     db/model.(*Proxy).Update\n\t/go/src/github.com/opencord/voltha-go/db/model/proxy.go:305\[ngithub.com/opencord/voltha-go/rw_core/core.(*DeviceAgent)|https://slack-redir.net/link?url=http%3A%2F%2Fngithub.com%2Fopencord%2Fvoltha-go%2Frw_core%2Fcore.(*DeviceAgent)]     .updateDeviceInStoreWithoutLock\n\t/go/src/github.com/opencord/voltha-go/rw_core/core/device_agent.go:1324\[ngithub.com/opencord/voltha-go/rw_core/|https://slack-redir.net/link?url=http%3A%2F%2Fngithub.com%2Fopencord%2Fvoltha-go%2Frw_core%2F]     core.(*DeviceAgent).updateDeviceUsingAdapterData\n\t/go/src/github.com/opencord/voltha-go/rw_core/core/device_agent.go:1053\[ngithub.com/opencord/v|https://slack-redir.net/link?url=http%3A%2F%2Fngithub.com%2Fopencord%2Fv]     oltha-go/rw_core/core.(*DeviceManager).updateDeviceUsingAdapterData\n\t/go/src/github.com/opencord/voltha-go/rw_core/core/device_manager.go:651"}

3627 {"level":"debug","ts":"2019-10-14T21:54:16.539Z","msg":"adding-callback","instanceId":"voltha-rw-core-12-65b99947bd-qhck8","caller":"node.makeLate     st:146","previousData":"id:\"129128b8105ed2d0bf3abaf3\" type:\"openolt\" root:true adapter:\"openolt\" host_and_port:\"10.98.49.165:50060\" admin_     state:ENABLED oper_status:ACTIVATING flows:<> flow_groups:<> ","latestData":"id:\"129128b8105ed2d0bf3abaf3\" type:\"openolt\" root:true adapter:\"     openolt\" host_and_port:\"10.98.49.165:50060\" admin_state:ENABLED oper_status:ACTIVATING flows:<> flow_groups:<> ","callbacks":{"a39a82b0f10d":{}     },"type":"POST_UPDATE"}
 
It seems that the model update with the new adapter data has failed as the model thinks that the KV store data is newer than the one getting loaded and hence seems to be discarding the data. 
 
However the only event that comes before was a little while back during enable device that seems to have triggered the persistent watch to update the model revision. 
 
I don't see any clash of model stores while updating adapter data.
Logs are attached.
Failure in line 4080 but interesting stuff starts at line 3598 updateDeviceUsingAdapterData followed by the log of "keeping-revision-data" which seems to indicate that an older data is being retained for the adapter.