KVScheduler stats does not show dropped transactions

[ondrej-fabry]

The stats provided by KVScheduler currently do not provide metrics about transactions which did not get into the transaction queue.

The following log contains several such errors:

$ kubectl logs vswitch-6666f464b4-5rvn2 -p | grep 'level=error'
time="2019-05-24 07:57:22.36538" level=error msg="Transaction #0 finished with 4 errors" loc="orchestrator/dispatcher.go(119)" logger=orchestrator.dispatcher
time="2019-05-24 07:57:22.36559" level=error msg="getting resync data failed: resync returned error: KeyErrors: [config/vpp/v2/interfaces/GigabitEthernetd/0/0 (CREATE): field name is invalid: DPDK interface with given name does not exists, config/vpp/v2/interfaces/GigabitEthernetd/0/1 (CREATE): field name is invalid: DPDK interface with given name does not exists, config/vpp/v2/interfaces/TenGigabitEthernet6/0/0 (CREATE): field name is invalid: DPDK interface with given name does not exists, config/vpp/v2/interfaces/TenGigabitEthernet6/0/1 (CREATE): field name is invalid: DPDK interface with given name does not exists]" loc="kvdbsync/watch_impl.go(101)" logger=defaultLogger
time="2019-05-24 07:57:22.37015" level=error msg="failed to send notifications to KVScheduler: transaction queue is full" loc="descriptor/link_state.go(149)" logger=vpp-ifplugin.interface-link-state
time="2019-05-24 07:57:22.37023" level=error msg="failed to send notifications to KVScheduler: transaction queue is full" loc="descriptor/link_state.go(149)" logger=vpp-ifplugin.interface-link-state
time="2019-05-24 07:57:22.37028" level=error msg="failed to send notifications to KVScheduler: transaction queue is full" loc="descriptor/link_state.go(149)" logger=vpp-ifplugin.interface-link-state
time="2019-05-24 07:57:22.37033" level=error msg="failed to send notifications to KVScheduler: transaction queue is full" loc="descriptor/link_state.go(149)" logger=vpp-ifplugin.interface-link-state
time="2019-05-24 07:57:22.37039" level=error msg="failed to send notifications to KVScheduler: transaction queue is full" loc="descriptor/link_state.go(149)" logger=vpp-ifplugin.interface-link-state
time="2019-05-24 07:57:22.37044" level=error msg="failed to send notifications to KVScheduler: transaction queue is full" loc="descriptor/link_state.go(149)" logger=vpp-ifplugin.interface-link-state
time="2019-05-24 07:57:22.37050" level=error msg="failed to send notifications to KVScheduler: transaction queue is full" loc="descriptor/link_state.go(149)" logger=vpp-ifplugin.interface-link-state
time="2019-05-24 07:57:22.37055" level=error msg="failed to send notifications to KVScheduler: transaction queue is full" loc="descriptor/link_state.go(149)" logger=vpp-ifplugin.interface-link-state
time="2019-05-24 07:57:22.37060" level=error msg="failed to send notifications to KVScheduler: transaction queue is full" loc="descriptor/link_state.go(149)" logger=vpp-ifplugin.interface-link-state
time="2019-05-24 07:57:22.37066" level=error msg="failed to send notifications to KVScheduler: transaction queue is full" loc="descriptor/link_state.go(149)" logger=vpp-ifplugin.interface-link-state
time="2019-05-24 07:57:22.37071" level=error msg="failed to send notifications to KVScheduler: transaction queue is full" loc="descriptor/link_state.go(149)" logger=vpp-ifplugin.interface-link-state
time="2019-05-24 07:57:22.37077" level=error msg="failed to send notifications to KVScheduler: transaction queue is full" loc="descriptor/link_state.go(149)" logger=vpp-ifplugin.interface-link-state
time="2019-05-24 07:57:22.37083" level=error msg="failed to send notifications to KVScheduler: transaction queue is full" loc="descriptor/link_state.go(149)" logger=vpp-ifplugin.interface-link-state
time="2019-05-24 07:57:22.37088" level=error msg="failed to send notifications to KVScheduler: transaction queue is full" loc="descriptor/link_state.go(149)" logger=vpp-ifplugin.interface-link-state
time="2019-05-24 07:57:22.37094" level=error msg="failed to send notifications to KVScheduler: transaction queue is full" loc="descriptor/link_state.go(149)" logger=vpp-ifplugin.interface-link-state
time="2019-05-24 07:57:22.37100" level=error msg="failed to send notifications to KVScheduler: transaction queue is full" loc="descriptor/link_state.go(149)" logger=vpp-ifplugin.interface-link-state
time="2019-05-24 08:04:33.44595" level=error msg="VPPApiError: VLAN subif already exists (-56)" loc="descriptor/interface_crud.go(122)" logger=vpp-ifplugin.if-descriptor
time="2019-05-24 08:04:33.74587" level=error msg="Transaction #956 finished with 1 errors" loc="orchestrator/dispatcher.go(119)" logger=orchestrator.dispatcher
time="2019-05-24 08:04:33.74596" level=error msg="KeyErrors: [config/vpp/v2/interfaces/sub103101 (CREATE): VPPApiError: VLAN subif already exists (-56)]" loc="syncbase/done.go(40)" logger=defaultLogger
time="2019-05-24 08:04:34.74978" level=error msg="VPPApiError: VLAN subif already exists (-56)" loc="descriptor/interface_crud.go(122)" logger=vpp-ifplugin.if-descriptor
time="2019-05-24 08:04:35.10796" level=error msg="KeyErrors: [config/vpp/v2/interfaces/sub103101 (CREATE): VPPApiError: VLAN subif already exists (-56)]" loc="kvscheduler/txn_process.go(403)" logger=kvscheduler
time="2019-05-24 08:04:37.11340" level=error msg="VPPApiError: VLAN subif already exists (-56)" loc="descriptor/interface_crud.go(122)" logger=vpp-ifplugin.if-descriptor
time="2019-05-24 08:04:37.65665" level=error msg="KeyErrors: [config/vpp/v2/interfaces/sub103101 (CREATE): VPPApiError: VLAN subif already exists (-56)]" loc="kvscheduler/txn_process.go(403)" logger=kvscheduler
time="2019-05-24 08:04:41.66086" level=error msg="VPPApiError: VLAN subif already exists (-56)" loc="descriptor/interface_crud.go(122)" logger=vpp-ifplugin.if-descriptor
time="2019-05-24 08:04:42.07278" level=error msg="KeyErrors: [config/vpp/v2/interfaces/sub103101 (CREATE): VPPApiError: VLAN subif already exists (-56)]" loc="kvscheduler/txn_process.go(403)" logger=kvscheduler

and the KVScheduler metrics (retrieved from http://localhost:9191/scheduler/stats) contain:

{
  "TxnStats": {
    "TotalProcessed": 1988,
    "OperationCount": {
      "CREATE": 3892,
      "DELETE": 294,
      "UPDATE": 0
    },
    "ValueStateCount": {
      "CONFIGURED": 2381,
      "DISCOVERED": 0,
      "FAILED": 1,
      "INVALID": 4,
      "MISSING": 0,
      "NONEXISTENT": 0,
      "OBTAINED": 1010,
      "PENDING": 493,
      "REMOVED": 294,
      "RETRYING": 3,
      "UNIMPLEMENTED": 0
    },
    "ErrorCount": 8,
    "Methods": [ ... ],
}

[ondrej-fabry]

@milanlenco It would be useful to have this resolved.