search

onosproject / onos-config

Configuration subsystem for ONOS (µONOS Architecture)
45 stars 56 forks source link

Performing gNMI Sets in rapid succession creates NetworkChanges, and DeviceChanges but stay PENDING #1045

Closed SeanCondon closed 4 years ago

SeanCondon commented 4 years ago

Describe the bug When gNMI Sets are made in rapid succession, the corresponding NetworkChange objects are created, properly, but no corresponding DeviceChange objects are created.

One time I ran this there were no DeviceChanges, but I cannot reproduce it at the moment. Still this is worth investigating

To Reproduce 1) Create a cluster using onit:

onit create cluster --set onos-cli.enabled=true

2) add a device simulator

onit -c onos add simulator -n devicesim-1

3) Make a set of gnmi Set changes together by pasting all the following in to the terminal

gnmi_cli -address onos-config:5150 -set \
    -proto "update: <path: <target: 'devicesim-1', elem: <name: 'system'> elem: <name: 'clock' > elem: <name: 'config'> elem: <name: 'timezone-name'>> val: <string_val: 'Europe/Dublin'>>" \
    -timeout 5s -en PROTO -alsologtostderr \
    -client_crt /etc/ssl/certs/client1.crt -client_key /etc/ssl/certs/client1.key -ca_crt /etc/ssl/certs/onfca.crt

gnmi_cli -address onos-config:5150 -set \
    -proto "update: <path: <target: 'devicesim-1', elem: <name: 'system'> elem: <name: 'clock' > elem: <name: 'config'> elem: <name: 'timezone-name'>> val: <string_val: 'Europe/London'>>" \
    -timeout 5s -en PROTO -alsologtostderr \
    -client_crt /etc/ssl/certs/client1.crt -client_key /etc/ssl/certs/client1.key -ca_crt /etc/ssl/certs/onfca.crt

gnmi_cli -address onos-config:5150 -set \
    -proto "update: <path: <target: 'devicesim-1', elem: <name: 'system'> elem: <name: 'clock' > elem: <name: 'config'> elem: <name: 'timezone-name'>> val: <string_val: 'Europe/Edinburgh'>>" \
    -timeout 5s -en PROTO -alsologtostderr \
    -client_crt /etc/ssl/certs/client1.crt -client_key /etc/ssl/certs/client1.key -ca_crt /etc/ssl/certs/onfca.crt

gnmi_cli -address onos-config:5150 -set \
    -proto "update: <path: <target: 'devicesim-1', elem: <name: 'system'> elem: <name: 'clock' > elem: <name: 'config'> elem: <name: 'timezone-name'>> val: <string_val: 'Europe/Cardiff'>>" \
    -timeout 5s -en PROTO -alsologtostderr \
    -client_crt /etc/ssl/certs/client1.crt -client_key /etc/ssl/certs/client1.key -ca_crt /etc/ssl/certs/onfca.crt

gnmi_cli -address onos-config:5150 -set \
    -proto "update: <path: <target: 'devicesim-1', elem: <name: 'system'> elem: <name: 'clock' > elem: <name: 'config'> elem: <name: 'timezone-name'>> val: <string_val: 'Europe/Belfast'>>" \
    -timeout 5s -en PROTO -alsologtostderr \
    -client_crt /etc/ssl/certs/client1.crt -client_key /etc/ssl/certs/client1.key -ca_crt /etc/ssl/certs/onfca.crt

4) Verify that the NetworkChanges for the 5 sets are present and but see that only the first 1 are COMPLETE and the others are PENDING

~ $ onos config get network-changes -v

gives

CHANGE                          INDEX  REVISION  PHASE    STATE     REASON   MESSAGE
condescending_gates             1       74       CHANGE   COMPLETE  NONE     
    Device: devicesim-1 (1.0.0)
    |/system/clock/config/timezone-name                |(STRING) Europe/Dublin                  |false  |

angry_wescoff                   2       69       CHANGE   PENDING   NONE     
    Device: devicesim-1 (1.0.0)
    |/system/clock/config/timezone-name                |(STRING) Europe/London                  |false  |

relaxed_thompson                3       73       CHANGE   PENDING   NONE     
    Device: devicesim-1 (1.0.0)
    |/system/clock/config/timezone-name                |(STRING) Europe/Edinburgh               |false  |

objective_babbage               4       78       CHANGE   PENDING   NONE     
    Device: devicesim-1 (1.0.0)
    |/system/clock/config/timezone-name                |(STRING) Europe/Cardiff                 |false  |

musing_mirzakhani               5       81       CHANGE   PENDING   NONE     
    Device: devicesim-1 (1.0.0)
    |/system/clock/config/timezone-name                |(STRING) Europe/Belfast                 |false  |

5) See also the DeviceChanges. The 1st is COMPLETE but the rest are PENDING

onos config get device-changes devicesim-1

gives

CHANGE                          INDEX  REVISION  PHASE    STATE     REASON   MESSAGE
condescending_gates:devicesim-1:1.0.0 1       71       CHANGE   COMPLETE  NONE     
    condescending_gates 1   devicesim-1 1.0.0
    |/system/clock/config/timezone-name                |(STRING) Europe/Dublin                  |false  |

angry_wescoff:devicesim-1:1.0.0 2       68       CHANGE   PENDING   NONE     
    angry_wescoff   2   devicesim-1 1.0.0
    |/system/clock/config/timezone-name                |(STRING) Europe/London                  |false  |

relaxed_thompson:devicesim-1:1.0.0 3       72       CHANGE   PENDING   NONE     
    relaxed_thompson    3   devicesim-1 1.0.0
    |/system/clock/config/timezone-name                |(STRING) Europe/Edinburgh               |false  |

objective_babbage:devicesim-1:1.0.0 4       77       CHANGE   PENDING   NONE     
    objective_babbage   4   devicesim-1 1.0.0
    |/system/clock/config/timezone-name                |(STRING) Europe/Cardiff                 |false  |

musing_mirzakhani:devicesim-1:1.0.0 5       80       CHANGE   PENDING   NONE     
    musing_mirzakhani   5   devicesim-1 1.0.0
    |/system/clock/config/timezone-name                |(STRING) Europe/Belfast                 |false  |

Expected behavior All of the DeviceChanges should transition to COMPLETE

Logs, text or screenshots

{"level":"info","ts":1579291804.551805,"logger":"northbound.diags","caller":"diags/diags.go:217","msg":"ListDeviceChanges called with devicesim-1 . Subscribe true"}
{"level":"info","ts":1579291825.962213,"logger":"northbound.gnmi","caller":"gnmi/set.go:55","msg":"gNMI Set Requestupdate:<path:<elem:<name:\"system\" > elem:<name:\"clock\" > elem:<name:\"config\" > elem:<name:\"timezone-name\" > target:\"devicesim-1\" > val:<string_val:\"Europe/Dublin\" > > "}
{"level":"info","ts":1579291825.9633648,"logger":"northbound.gnmi","caller":"gnmi/set.go:368","msg":"Validating change devicesim-1:Devicesim:1.0.0"}
{"level":"info","ts":1579291825.9661763,"logger":"manager","caller":"manager/setconfig.go:93","msg":"New Configuration for devicesim-1, with version 1.0.0 and type Devicesim, is Valid according to model Devicesim-1.0.0"}
{"level":"info","ts":1579291825.9662223,"logger":"northbound.gnmi","caller":"gnmi/set.go:376","msg":"Validating change devicesim-1:Devicesim:1.0.0 DONE"}
{"level":"info","ts":1579291825.9662404,"logger":"northbound.gnmi","caller":"gnmi/set.go:323","msg":"Testing /system/clock/config/timezone-name for read only"}
{"level":"info","ts":1579291825.966498,"logger":"manager","caller":"manager/setconfig.go:135","msg":"Appending device change device_id:\"devicesim-1\" device_version:\"1.0.0\" device_type:\"Devicesim\" values:<path:\"/system/clock/config/timezone-name\" value:<bytes:\"Europe/Dublin\" type:STRING > > "}
{"level":"info","ts":1579291825.9680502,"logger":"store.device.cache","caller":"cache/cache.go:131","msg":"Updating cache with {devicesim-1 Devicesim 1.0.0}. Size 1 Listeners 2"}
{"level":"info","ts":1579291825.9681122,"logger":"controller.change.network","caller":"network/watcher.go:115","msg":"Received device event for device devicesim-1 1.0.0"}
{"level":"info","ts":1579291825.9681756,"logger":"controller.change.device","caller":"device/watcher.go:59","msg":"Received device event for device devicesim-1 1.0.0"}
{"level":"info","ts":1579291825.9690619,"logger":"controller.change.network","caller":"network/controller.go:73","msg":"Reconciling NetworkChange id:\"condescending_gates\" index:1 revision:58 status:<> created:<seconds:1579291825 nanos:967184446 > updated:<seconds:1579291825 nanos:967184446 > changes:<device_id:\"devicesim-1\" device_version:\"1.0.0\" device_type:\"Devicesim\" values:<path:\"/system/clock/config/timezone-name\" value:<bytes:\"Europe/Dublin\" type:STRING > > > "}
{"level":"info","ts":1579291825.9694939,"logger":"controller.change.network","caller":"network/watcher.go:148","msg":"Updating watch for device devicesim-1:1.0.0"}
{"level":"info","ts":1579291825.9697478,"logger":"controller.change.network","caller":"network/controller.go:171","msg":"Creating DeviceChange index:1 network_change:<id:\"condescending_gates\" index:1 > change:<device_id:\"devicesim-1\" device_version:\"1.0.0\" device_type:\"Devicesim\" values:<path:\"/system/clock/config/timezone-name\" value:<bytes:\"Europe/Dublin\" type:STRING > > > status:<> created:<seconds:-62135596800 > updated:<seconds:-62135596800 >  for condescending_gates"}
{"level":"info","ts":1579291825.970823,"logger":"store.change.device","caller":"device/store.go:235","msg":"Created new device change condescending_gates:devicesim-1:1.0.0"}
{"level":"info","ts":1579291825.9709282,"logger":"northbound.diags","caller":"diags/diags.go:254","msg":"Sending matching change condescending_gates:devicesim-1:1.0.0"}
{"level":"info","ts":1579291825.9724123,"logger":"controller.change.network","caller":"network/controller.go:73","msg":"Reconciling NetworkChange id:\"condescending_gates\" index:1 revision:61 status:<> created:<seconds:1579291825 nanos:967184446 > updated:<seconds:1579291825 nanos:971116914 > changes:<device_id:\"devicesim-1\" device_version:\"1.0.0\" device_type:\"Devicesim\" values:<path:\"/system/clock/config/timezone-name\" value:<bytes:\"Europe/Dublin\" type:STRING > > > refs:<device_change_id:\"condescending_gates:devicesim-1:1.0.0\" > "}
{"level":"info","ts":1579291825.9791565,"logger":"controller.change.network","caller":"network/controller.go:120","msg":"Applying NetworkChange id:\"condescending_gates\" index:1 revision:61 status:<incarnation:1 > created:<seconds:1579291825 nanos:967184446 > updated:<seconds:1579291825 nanos:971116914 > changes:<device_id:\"devicesim-1\" device_version:\"1.0.0\" device_type:\"Devicesim\" values:<path:\"/system/clock/config/timezone-name\" value:<bytes:\"Europe/Dublin\" type:STRING > > > refs:<device_change_id:\"condescending_gates:devicesim-1:1.0.0\" > "}
{"level":"info","ts":1579291825.9841673,"logger":"controller.change.network","caller":"network/controller.go:73","msg":"Reconciling NetworkChange id:\"condescending_gates\" index:1 revision:63 status:<incarnation:1 > created:<seconds:1579291825 nanos:967184446 > updated:<seconds:1579291825 nanos:981830112 > changes:<device_id:\"devicesim-1\" device_version:\"1.0.0\" device_type:\"Devicesim\" values:<path:\"/system/clock/config/timezone-name\" value:<bytes:\"Europe/Dublin\" type:STRING > > > refs:<device_change_id:\"condescending_gates:devicesim-1:1.0.0\" > "}
{"level":"info","ts":1579291825.985558,"logger":"controller.change.network","caller":"network/controller.go:255","msg":"Running DeviceChange id:\"condescending_gates:devicesim-1:1.0.0\" index:1 revision:60 network_change:<id:\"condescending_gates\" index:1 > change:<device_id:\"devicesim-1\" device_version:\"1.0.0\" device_type:\"Devicesim\" values:<path:\"/system/clock/config/timezone-name\" value:<bytes:\"Europe/Dublin\" type:STRING > > > status:<incarnation:1 > created:<seconds:1579291825 nanos:970011807 > updated:<seconds:1579291825 nanos:970011807 > "}
{"level":"info","ts":1579291825.987358,"logger":"controller.change.device","caller":"device/controller.go:81","msg":"Reconciling DeviceChange id:\"condescending_gates:devicesim-1:1.0.0\" index:1 revision:66 network_change:<id:\"condescending_gates\" index:1 > change:<device_id:\"devicesim-1\" device_version:\"1.0.0\" device_type:\"Devicesim\" values:<path:\"/system/clock/config/timezone-name\" value:<bytes:\"Europe/Dublin\" type:STRING > > > status:<incarnation:1 > created:<seconds:1579291825 nanos:970011807 > updated:<seconds:1579291825 nanos:985905751 > "}
{"level":"info","ts":1579291825.9874163,"logger":"controller.change.device","caller":"device/controller.go:89","msg":"Checking Device store for devicesim-1"}
{"level":"info","ts":1579291825.9874914,"logger":"northbound.diags","caller":"diags/diags.go:254","msg":"Sending matching change condescending_gates:devicesim-1:1.0.0"}
{"level":"info","ts":1579291825.9888477,"logger":"controller.change.network","caller":"network/controller.go:73","msg":"Reconciling NetworkChange id:\"condescending_gates\" index:1 revision:63 status:<incarnation:1 > created:<seconds:1579291825 nanos:967184446 > updated:<seconds:1579291825 nanos:981830112 > changes:<device_id:\"devicesim-1\" device_version:\"1.0.0\" device_type:\"Devicesim\" values:<path:\"/system/clock/config/timezone-name\" value:<bytes:\"Europe/Dublin\" type:STRING > > > refs:<device_change_id:\"condescending_gates:devicesim-1:1.0.0\" > "}
{"level":"info","ts":1579291825.989467,"logger":"controller.change.device","caller":"device/controller.go:137","msg":"Applying change device_id:\"devicesim-1\" device_version:\"1.0.0\" device_type:\"Devicesim\" values:<path:\"/system/clock/config/timezone-name\" value:<bytes:\"Europe/Dublin\" type:STRING > >  "}
{"level":"info","ts":1579291825.9895644,"logger":"controller.change.device","caller":"device/controller.go:177","msg":"Reconciler set request for devicesim-1: update:<path:<elem:<name:\"system\" > elem:<name:\"clock\" > elem:<name:\"config\" > elem:<name:\"timezone-name\" > > val:<string_val:\"Europe/Dublin\" > > "}
{"level":"info","ts":1579291825.9896145,"logger":"controller.change.device","caller":"device/controller.go:183","msg":"Target for device devicesim-1: &{{[devicesim-1:11161]  0 5000000000 <nil> <nil> map[]} {0xc003850000} 0xc00057f580 {{0 0} 0 0 0 0}} 0xc00013ae70"}
{"level":"info","ts":1579291825.9898424,"logger":"controller.change.network","caller":"network/controller.go:73","msg":"Reconciling NetworkChange id:\"condescending_gates\" index:1 revision:63 status:<incarnation:1 > created:<seconds:1579291825 nanos:967184446 > updated:<seconds:1579291825 nanos:981830112 > changes:<device_id:\"devicesim-1\" device_version:\"1.0.0\" device_type:\"Devicesim\" values:<path:\"/system/clock/config/timezone-name\" value:<bytes:\"Europe/Dublin\" type:STRING > > > refs:<device_change_id:\"condescending_gates:devicesim-1:1.0.0\" > "}
{"level":"info","ts":1579291826.0001903,"logger":"northbound.gnmi","caller":"gnmi/set.go:55","msg":"gNMI Set Requestupdate:<path:<elem:<name:\"system\" > elem:<name:\"clock\" > elem:<name:\"config\" > elem:<name:\"timezone-name\" > target:\"devicesim-1\" > val:<string_val:\"Europe/London\" > > "}
{"level":"info","ts":1579291826.001698,"logger":"manager","caller":"manager/manager.go:258","msg":"Handling target devicesim-1 as :"}
{"level":"info","ts":1579291826.00174,"logger":"manager","caller":"manager/manager.go:260","msg":"Ignoring device type  and version  from extension for devicesim-1. Using Devicesim and 1.0.0"}
{"level":"info","ts":1579291826.0017607,"logger":"northbound.gnmi","caller":"gnmi/set.go:368","msg":"Validating change devicesim-1:Devicesim:1.0.0"}
{"level":"info","ts":1579291826.0042758,"logger":"manager","caller":"manager/setconfig.go:93","msg":"New Configuration for devicesim-1, with version 1.0.0 and type Devicesim, is Valid according to model Devicesim-1.0.0"}
{"level":"info","ts":1579291826.0043778,"logger":"northbound.gnmi","caller":"gnmi/set.go:376","msg":"Validating change devicesim-1:Devicesim:1.0.0 DONE"}
{"level":"info","ts":1579291826.0043924,"logger":"northbound.gnmi","caller":"gnmi/set.go:323","msg":"Testing /system/clock/config/timezone-name for read only"}
{"level":"info","ts":1579291826.0045838,"logger":"manager","caller":"manager/setconfig.go:135","msg":"Appending device change device_id:\"devicesim-1\" device_version:\"1.0.0\" device_type:\"Devicesim\" values:<path:\"/system/clock/config/timezone-name\" value:<bytes:\"Europe/London\" type:STRING > > "}
{"level":"info","ts":1579291826.0066118,"logger":"controller.change.network","caller":"network/controller.go:73","msg":"Reconciling NetworkChange id:\"angry_wescoff\" index:2 revision:67 status:<> created:<seconds:1579291826 nanos:5039621 > updated:<seconds:1579291826 nanos:5039621 > changes:<device_id:\"devicesim-1\" device_version:\"1.0.0\" device_type:\"Devicesim\" values:<path:\"/system/clock/config/timezone-name\" value:<bytes:\"Europe/London\" type:STRING > > > "}
{"level":"info","ts":1579291826.007302,"logger":"controller.change.network","caller":"network/controller.go:171","msg":"Creating DeviceChange index:2 network_change:<id:\"angry_wescoff\" index:2 > change:<device_id:\"devicesim-1\" device_version:\"1.0.0\" device_type:\"Devicesim\" values:<path:\"/system/clock/config/timezone-name\" value:<bytes:\"Europe/London\" type:STRING > > > status:<> created:<seconds:-62135596800 > updated:<seconds:-62135596800 >  for angry_wescoff"}
{"level":"info","ts":1579291826.0086741,"logger":"store.change.device","caller":"device/store.go:235","msg":"Created new device change angry_wescoff:devicesim-1:1.0.0"}
{"level":"info","ts":1579291826.009139,"logger":"northbound.diags","caller":"diags/diags.go:254","msg":"Sending matching change angry_wescoff:devicesim-1:1.0.0"}
{"level":"info","ts":1579291826.0117967,"logger":"controller.change.network","caller":"network/controller.go:73","msg":"Reconciling NetworkChange id:\"angry_wescoff\" index:2 revision:69 status:<> created:<seconds:1579291826 nanos:5039621 > updated:<seconds:1579291826 nanos:9856080 > changes:<device_id:\"devicesim-1\" device_version:\"1.0.0\" device_type:\"Devicesim\" values:<path:\"/system/clock/config/timezone-name\" value:<bytes:\"Europe/London\" type:STRING > > > refs:<device_change_id:\"angry_wescoff:devicesim-1:1.0.0\" > "}
{"level":"info","ts":1579291826.0154622,"logger":"controller.change.network","caller":"network/controller.go:73","msg":"Reconciling NetworkChange id:\"angry_wescoff\" index:2 revision:69 status:<> created:<seconds:1579291826 nanos:5039621 > updated:<seconds:1579291826 nanos:9856080 > changes:<device_id:\"devicesim-1\" device_version:\"1.0.0\" device_type:\"Devicesim\" values:<path:\"/system/clock/config/timezone-name\" value:<bytes:\"Europe/London\" type:STRING > > > refs:<device_change_id:\"angry_wescoff:devicesim-1:1.0.0\" > "}
{"level":"info","ts":1579291826.0337815,"logger":"northbound.gnmi","caller":"gnmi/set.go:55","msg":"gNMI Set Requestupdate:<path:<elem:<name:\"system\" > elem:<name:\"clock\" > elem:<name:\"config\" > elem:<name:\"timezone-name\" > target:\"devicesim-1\" > val:<string_val:\"Europe/Edinburgh\" > > "}
{"level":"info","ts":1579291826.0350814,"logger":"manager","caller":"manager/manager.go:258","msg":"Handling target devicesim-1 as :"}
{"level":"info","ts":1579291826.0351398,"logger":"manager","caller":"manager/manager.go:260","msg":"Ignoring device type  and version  from extension for devicesim-1. Using Devicesim and 1.0.0"}
{"level":"info","ts":1579291826.0351703,"logger":"northbound.gnmi","caller":"gnmi/set.go:368","msg":"Validating change devicesim-1:Devicesim:1.0.0"}
{"level":"info","ts":1579291826.0389912,"logger":"manager","caller":"manager/setconfig.go:93","msg":"New Configuration for devicesim-1, with version 1.0.0 and type Devicesim, is Valid according to model Devicesim-1.0.0"}
{"level":"info","ts":1579291826.0390532,"logger":"northbound.gnmi","caller":"gnmi/set.go:376","msg":"Validating change devicesim-1:Devicesim:1.0.0 DONE"}
{"level":"info","ts":1579291826.0390759,"logger":"northbound.gnmi","caller":"gnmi/set.go:323","msg":"Testing /system/clock/config/timezone-name for read only"}
{"level":"info","ts":1579291826.0393548,"logger":"manager","caller":"manager/setconfig.go:135","msg":"Appending device change device_id:\"devicesim-1\" device_version:\"1.0.0\" device_type:\"Devicesim\" values:<path:\"/system/clock/config/timezone-name\" value:<bytes:\"Europe/Edinburgh\" type:STRING > > "}
{"level":"info","ts":1579291826.0411646,"logger":"controller.change.device","caller":"device/controller.go:189","msg":"devicesim-1 SetResponse response:<path:<elem:<name:\"system\" > elem:<name:\"clock\" > elem:<name:\"config\" > elem:<name:\"timezone-name\" > > op:UPDATE > "}
{"level":"info","ts":1579291826.0412633,"logger":"controller.change.device","caller":"device/controller.go:125","msg":"Completing DeviceChange id:\"condescending_gates:devicesim-1:1.0.0\" index:1 revision:66 network_change:<id:\"condescending_gates\" index:1 > change:<device_id:\"devicesim-1\" device_version:\"1.0.0\" device_type:\"Devicesim\" values:<path:\"/system/clock/config/timezone-name\" value:<bytes:\"Europe/Dublin\" type:STRING > > > status:<state:COMPLETE incarnation:1 > created:<seconds:1579291825 nanos:970011807 > updated:<seconds:1579291825 nanos:985905751 > "}
{"level":"info","ts":1579291826.0422325,"logger":"controller.change.network","caller":"network/controller.go:73","msg":"Reconciling NetworkChange id:\"relaxed_thompson\" index:3 revision:70 status:<> created:<seconds:1579291826 nanos:39963514 > updated:<seconds:1579291826 nanos:39963514 > changes:<device_id:\"devicesim-1\" device_version:\"1.0.0\" device_type:\"Devicesim\" values:<path:\"/system/clock/config/timezone-name\" value:<bytes:\"Europe/Edinburgh\" type:STRING > > > "}
{"level":"info","ts":1579291826.0428438,"logger":"northbound.diags","caller":"diags/diags.go:254","msg":"Sending matching change condescending_gates:devicesim-1:1.0.0"}
{"level":"info","ts":1579291826.0432482,"logger":"controller.change.network","caller":"network/controller.go:171","msg":"Creating DeviceChange index:3 network_change:<id:\"relaxed_thompson\" index:3 > change:<device_id:\"devicesim-1\" device_version:\"1.0.0\" device_type:\"Devicesim\" values:<path:\"/system/clock/config/timezone-name\" value:<bytes:\"Europe/Edinburgh\" type:STRING > > > status:<> created:<seconds:-62135596800 > updated:<seconds:-62135596800 >  for relaxed_thompson"}
{"level":"info","ts":1579291826.0450888,"logger":"northbound.diags","caller":"diags/diags.go:254","msg":"Sending matching change relaxed_thompson:devicesim-1:1.0.0"}
{"level":"info","ts":1579291826.0451555,"logger":"controller.change.device","caller":"device/controller.go:81","msg":"Reconciling DeviceChange id:\"condescending_gates:devicesim-1:1.0.0\" index:1 revision:71 network_change:<id:\"condescending_gates\" index:1 > change:<device_id:\"devicesim-1\" device_version:\"1.0.0\" device_type:\"Devicesim\" values:<path:\"/system/clock/config/timezone-name\" value:<bytes:\"Europe/Dublin\" type:STRING > > > status:<state:COMPLETE incarnation:1 > created:<seconds:1579291825 nanos:970011807 > updated:<seconds:1579291826 nanos:41877426 > "}
{"level":"info","ts":1579291826.0452836,"logger":"store.change.device","caller":"device/store.go:235","msg":"Created new device change relaxed_thompson:devicesim-1:1.0.0"}
{"level":"info","ts":1579291826.0482547,"logger":"controller.change.device","caller":"device/controller.go:81","msg":"Reconciling DeviceChange id:\"angry_wescoff:devicesim-1:1.0.0\" index:2 revision:68 network_change:<id:\"angry_wescoff\" index:2 > change:<device_id:\"devicesim-1\" device_version:\"1.0.0\" device_type:\"Devicesim\" values:<path:\"/system/clock/config/timezone-name\" value:<bytes:\"Europe/London\" type:STRING > > > status:<> created:<seconds:1579291826 nanos:7601467 > updated:<seconds:1579291826 nanos:7601467 > "}
{"level":"info","ts":1579291826.0488546,"logger":"controller.change.network","caller":"network/controller.go:73","msg":"Reconciling NetworkChange id:\"condescending_gates\" index:1 revision:63 status:<incarnation:1 > created:<seconds:1579291825 nanos:967184446 > updated:<seconds:1579291825 nanos:981830112 > changes:<device_id:\"devicesim-1\" device_version:\"1.0.0\" device_type:\"Devicesim\" values:<path:\"/system/clock/config/timezone-name\" value:<bytes:\"Europe/Dublin\" type:STRING > > > refs:<device_change_id:\"condescending_gates:devicesim-1:1.0.0\" > "}
{"level":"info","ts":1579291826.0490954,"logger":"controller.change.device","caller":"device/controller.go:81","msg":"Reconciling DeviceChange id:\"condescending_gates:devicesim-1:1.0.0\" index:1 revision:71 network_change:<id:\"condescending_gates\" index:1 > change:<device_id:\"devicesim-1\" device_version:\"1.0.0\" device_type:\"Devicesim\" values:<path:\"/system/clock/config/timezone-name\" value:<bytes:\"Europe/Dublin\" type:STRING > > > status:<state:COMPLETE incarnation:1 > created:<seconds:1579291825 nanos:970011807 > updated:<seconds:1579291826 nanos:41877426 > "}
{"level":"info","ts":1579291826.0516534,"logger":"controller.change.network","caller":"network/controller.go:130","msg":"Completing NetworkChange id:\"condescending_gates\" index:1 revision:63 status:<state:COMPLETE incarnation:1 > created:<seconds:1579291825 nanos:967184446 > updated:<seconds:1579291825 nanos:981830112 > changes:<device_id:\"devicesim-1\" device_version:\"1.0.0\" device_type:\"Devicesim\" values:<path:\"/system/clock/config/timezone-name\" value:<bytes:\"Europe/Dublin\" type:STRING > > > refs:<device_change_id:\"condescending_gates:devicesim-1:1.0.0\" > "}
{"level":"info","ts":1579291826.0520782,"logger":"controller.change.device","caller":"device/controller.go:81","msg":"Reconciling DeviceChange id:\"relaxed_thompson:devicesim-1:1.0.0\" index:3 revision:72 network_change:<id:\"relaxed_thompson\" index:3 > change:<device_id:\"devicesim-1\" device_version:\"1.0.0\" device_type:\"Devicesim\" values:<path:\"/system/clock/config/timezone-name\" value:<bytes:\"Europe/Edinburgh\" type:STRING > > > status:<> created:<seconds:1579291826 nanos:43921668 > updated:<seconds:1579291826 nanos:43921668 > "}
{"level":"info","ts":1579291826.0545793,"logger":"controller.change.network","caller":"network/controller.go:73","msg":"Reconciling NetworkChange id:\"relaxed_thompson\" index:3 revision:73 status:<> created:<seconds:1579291826 nanos:39963514 > updated:<seconds:1579291826 nanos:46212735 > changes:<device_id:\"devicesim-1\" device_version:\"1.0.0\" device_type:\"Devicesim\" values:<path:\"/system/clock/config/timezone-name\" value:<bytes:\"Europe/Edinburgh\" type:STRING > > > refs:<device_change_id:\"relaxed_thompson:devicesim-1:1.0.0\" > "}
{"level":"info","ts":1579291826.0569022,"logger":"controller.change.network","caller":"network/controller.go:73","msg":"Reconciling NetworkChange id:\"relaxed_thompson\" index:3 revision:73 status:<> created:<seconds:1579291826 nanos:39963514 > updated:<seconds:1579291826 nanos:46212735 > changes:<device_id:\"devicesim-1\" device_version:\"1.0.0\" device_type:\"Devicesim\" values:<path:\"/system/clock/config/timezone-name\" value:<bytes:\"Europe/Edinburgh\" type:STRING > > > refs:<device_change_id:\"relaxed_thompson:devicesim-1:1.0.0\" > "}
{"level":"info","ts":1579291826.0588417,"logger":"controller.change.network","caller":"network/controller.go:73","msg":"Reconciling NetworkChange id:\"condescending_gates\" index:1 revision:74 status:<state:COMPLETE incarnation:1 > created:<seconds:1579291825 nanos:967184446 > updated:<seconds:1579291826 nanos:52258681 > changes:<device_id:\"devicesim-1\" device_version:\"1.0.0\" device_type:\"Devicesim\" values:<path:\"/system/clock/config/timezone-name\" value:<bytes:\"Europe/Dublin\" type:STRING > > > refs:<device_change_id:\"condescending_gates:devicesim-1:1.0.0\" > "}
{"level":"info","ts":1579291826.0676298,"logger":"northbound.gnmi","caller":"gnmi/set.go:55","msg":"gNMI Set Requestupdate:<path:<elem:<name:\"system\" > elem:<name:\"clock\" > elem:<name:\"config\" > elem:<name:\"timezone-name\" > target:\"devicesim-1\" > val:<string_val:\"Europe/Cardiff\" > > "}
{"level":"info","ts":1579291826.0690794,"logger":"manager","caller":"manager/manager.go:258","msg":"Handling target devicesim-1 as :"}
{"level":"info","ts":1579291826.0691257,"logger":"manager","caller":"manager/manager.go:260","msg":"Ignoring device type  and version  from extension for devicesim-1. Using Devicesim and 1.0.0"}
{"level":"info","ts":1579291826.069143,"logger":"northbound.gnmi","caller":"gnmi/set.go:368","msg":"Validating change devicesim-1:Devicesim:1.0.0"}
{"level":"info","ts":1579291826.071793,"logger":"manager","caller":"manager/setconfig.go:93","msg":"New Configuration for devicesim-1, with version 1.0.0 and type Devicesim, is Valid according to model Devicesim-1.0.0"}
{"level":"info","ts":1579291826.071917,"logger":"northbound.gnmi","caller":"gnmi/set.go:376","msg":"Validating change devicesim-1:Devicesim:1.0.0 DONE"}
{"level":"info","ts":1579291826.0719545,"logger":"northbound.gnmi","caller":"gnmi/set.go:323","msg":"Testing /system/clock/config/timezone-name for read only"}
{"level":"info","ts":1579291826.0722682,"logger":"manager","caller":"manager/setconfig.go:135","msg":"Appending device change device_id:\"devicesim-1\" device_version:\"1.0.0\" device_type:\"Devicesim\" values:<path:\"/system/clock/config/timezone-name\" value:<bytes:\"Europe/Cardiff\" type:STRING > > "}
{"level":"info","ts":1579291826.078042,"logger":"controller.change.network","caller":"network/controller.go:73","msg":"Reconciling NetworkChange id:\"objective_babbage\" index:4 revision:76 status:<> created:<seconds:1579291826 nanos:76630944 > updated:<seconds:1579291826 nanos:76630944 > changes:<device_id:\"devicesim-1\" device_version:\"1.0.0\" device_type:\"Devicesim\" values:<path:\"/system/clock/config/timezone-name\" value:<bytes:\"Europe/Cardiff\" type:STRING > > > "}
{"level":"info","ts":1579291826.0787506,"logger":"controller.change.network","caller":"network/controller.go:171","msg":"Creating DeviceChange index:4 network_change:<id:\"objective_babbage\" index:4 > change:<device_id:\"devicesim-1\" device_version:\"1.0.0\" device_type:\"Devicesim\" values:<path:\"/system/clock/config/timezone-name\" value:<bytes:\"Europe/Cardiff\" type:STRING > > > status:<> created:<seconds:-62135596800 > updated:<seconds:-62135596800 >  for objective_babbage"}
{"level":"info","ts":1579291826.0801272,"logger":"northbound.diags","caller":"diags/diags.go:254","msg":"Sending matching change objective_babbage:devicesim-1:1.0.0"}
{"level":"info","ts":1579291826.0801947,"logger":"store.change.device","caller":"device/store.go:235","msg":"Created new device change objective_babbage:devicesim-1:1.0.0"}
{"level":"info","ts":1579291826.0811496,"logger":"controller.change.device","caller":"device/controller.go:81","msg":"Reconciling DeviceChange id:\"objective_babbage:devicesim-1:1.0.0\" index:4 revision:77 network_change:<id:\"objective_babbage\" index:4 > change:<device_id:\"devicesim-1\" device_version:\"1.0.0\" device_type:\"Devicesim\" values:<path:\"/system/clock/config/timezone-name\" value:<bytes:\"Europe/Cardiff\" type:STRING > > > status:<> created:<seconds:1579291826 nanos:79068631 > updated:<seconds:1579291826 nanos:79068631 > "}
{"level":"info","ts":1579291826.082052,"logger":"controller.change.network","caller":"network/controller.go:73","msg":"Reconciling NetworkChange id:\"objective_babbage\" index:4 revision:78 status:<> created:<seconds:1579291826 nanos:76630944 > updated:<seconds:1579291826 nanos:80730508 > changes:<device_id:\"devicesim-1\" device_version:\"1.0.0\" device_type:\"Devicesim\" values:<path:\"/system/clock/config/timezone-name\" value:<bytes:\"Europe/Cardiff\" type:STRING > > > refs:<device_change_id:\"objective_babbage:devicesim-1:1.0.0\" > "}
{"level":"info","ts":1579291826.0844827,"logger":"controller.change.network","caller":"network/controller.go:73","msg":"Reconciling NetworkChange id:\"objective_babbage\" index:4 revision:78 status:<> created:<seconds:1579291826 nanos:76630944 > updated:<seconds:1579291826 nanos:80730508 > changes:<device_id:\"devicesim-1\" device_version:\"1.0.0\" device_type:\"Devicesim\" values:<path:\"/system/clock/config/timezone-name\" value:<bytes:\"Europe/Cardiff\" type:STRING > > > refs:<device_change_id:\"objective_babbage:devicesim-1:1.0.0\" > "}
{"level":"info","ts":1579291826.0982373,"logger":"northbound.gnmi","caller":"gnmi/set.go:55","msg":"gNMI Set Requestupdate:<path:<elem:<name:\"system\" > elem:<name:\"clock\" > elem:<name:\"config\" > elem:<name:\"timezone-name\" > target:\"devicesim-1\" > val:<string_val:\"Europe/Belfast\" > > "}
{"level":"info","ts":1579291826.0992472,"logger":"manager","caller":"manager/manager.go:258","msg":"Handling target devicesim-1 as :"}
{"level":"info","ts":1579291826.0992804,"logger":"manager","caller":"manager/manager.go:260","msg":"Ignoring device type  and version  from extension for devicesim-1. Using Devicesim and 1.0.0"}
{"level":"info","ts":1579291826.0993013,"logger":"northbound.gnmi","caller":"gnmi/set.go:368","msg":"Validating change devicesim-1:Devicesim:1.0.0"}
{"level":"info","ts":1579291826.1018987,"logger":"manager","caller":"manager/setconfig.go:93","msg":"New Configuration for devicesim-1, with version 1.0.0 and type Devicesim, is Valid according to model Devicesim-1.0.0"}
{"level":"info","ts":1579291826.1019452,"logger":"northbound.gnmi","caller":"gnmi/set.go:376","msg":"Validating change devicesim-1:Devicesim:1.0.0 DONE"}
{"level":"info","ts":1579291826.1019578,"logger":"northbound.gnmi","caller":"gnmi/set.go:323","msg":"Testing /system/clock/config/timezone-name for read only"}
{"level":"info","ts":1579291826.1021664,"logger":"manager","caller":"manager/setconfig.go:135","msg":"Appending device change device_id:\"devicesim-1\" device_version:\"1.0.0\" device_type:\"Devicesim\" values:<path:\"/system/clock/config/timezone-name\" value:<bytes:\"Europe/Belfast\" type:STRING > > "}
{"level":"info","ts":1579291826.1036985,"logger":"controller.change.network","caller":"network/controller.go:73","msg":"Reconciling NetworkChange id:\"musing_mirzakhani\" index:5 revision:79 status:<> created:<seconds:1579291826 nanos:102666101 > updated:<seconds:1579291826 nanos:102666101 > changes:<device_id:\"devicesim-1\" device_version:\"1.0.0\" device_type:\"Devicesim\" values:<path:\"/system/clock/config/timezone-name\" value:<bytes:\"Europe/Belfast\" type:STRING > > > "}
{"level":"info","ts":1579291826.1042402,"logger":"controller.change.network","caller":"network/controller.go:171","msg":"Creating DeviceChange index:5 network_change:<id:\"musing_mirzakhani\" index:5 > change:<device_id:\"devicesim-1\" device_version:\"1.0.0\" device_type:\"Devicesim\" values:<path:\"/system/clock/config/timezone-name\" value:<bytes:\"Europe/Belfast\" type:STRING > > > status:<> created:<seconds:-62135596800 > updated:<seconds:-62135596800 >  for musing_mirzakhani"}
{"level":"info","ts":1579291826.1055074,"logger":"northbound.diags","caller":"diags/diags.go:254","msg":"Sending matching change musing_mirzakhani:devicesim-1:1.0.0"}
{"level":"info","ts":1579291826.105543,"logger":"store.change.device","caller":"device/store.go:235","msg":"Created new device change musing_mirzakhani:devicesim-1:1.0.0"}
{"level":"info","ts":1579291826.1066272,"logger":"controller.change.device","caller":"device/controller.go:81","msg":"Reconciling DeviceChange id:\"musing_mirzakhani:devicesim-1:1.0.0\" index:5 revision:80 network_change:<id:\"musing_mirzakhani\" index:5 > change:<device_id:\"devicesim-1\" device_version:\"1.0.0\" device_type:\"Devicesim\" values:<path:\"/system/clock/config/timezone-name\" value:<bytes:\"Europe/Belfast\" type:STRING > > > status:<> created:<seconds:1579291826 nanos:104635276 > updated:<seconds:1579291826 nanos:104635276 > "}
{"level":"info","ts":1579291826.107588,"logger":"controller.change.network","caller":"network/controller.go:73","msg":"Reconciling NetworkChange id:\"musing_mirzakhani\" index:5 revision:81 status:<> created:<seconds:1579291826 nanos:102666101 > updated:<seconds:1579291826 nanos:105965251 > changes:<device_id:\"devicesim-1\" device_version:\"1.0.0\" device_type:\"Devicesim\" values:<path:\"/system/clock/config/timezone-name\" value:<bytes:\"Europe/Belfast\" type:STRING > > > refs:<device_change_id:\"musing_mirzakhani:devicesim-1:1.0.0\" > "}
{"level":"info","ts":1579291826.1104624,"logger":"controller.change.network","caller":"network/controller.go:73","msg":"Reconciling NetworkChange id:\"musing_mirzakhani\" index:5 revision:81 status:<> created:<seconds:1579291826 nanos:102666101 > updated:<seconds:1579291826 nanos:105965251 > changes:<device_id:\"devicesim-1\" device_version:\"1.0.0\" device_type:\"Devicesim\" values:<path:\"/system/clock/config/timezone-name\" value:<bytes:\"Europe/Belfast\" type:STRING > > > refs:<device_change_id:\"musing_mirzakhani:devicesim-1:1.0.0\" > "}

Additional context One time I ran this there were no DeviceChanges, but I cannot reproduce it at the moment.

adibrastegarnia commented 4 years ago

Added an integration test to detect the problem if it happens again but we can open it anytime if it is needed.