Exception in ofagent (python) during sanity test

I observed the following ofagent error while tracking an issue after a sanity test failure on jenkins (full log at https://jenkins.opencord.org/job/verify_voltha-go_sanity-test/547/):

voltha/voltha-ofagent-cc5bd45b-m4555[ofagent]: 20200303T151219.622 DEBUG of_connection.dataReceived

{received: 00000000: 04 12 00 10 00 00 00 CA 00 03 00 00 00 00 00 00 ................, len: 16, event: data-received, instance_id: voltha-ofagent-cc5bd45b-m4555}

voltha/voltha-ofagent-cc5bd45b-m4555[ofagent]: 20200303T151219.623 DEBUG of_connection.dataReceived

{len: 16, xid: 202, name: table_stats_request, module: loxi.of13.message, event: received-msg, instance_id: voltha-ofagent-cc5bd45b-m4555}

voltha/voltha-ofagent-cc5bd45b-m4555[ofagent]: 20200303T151219.623 DEBUG of_connection.send

{len: 16, xid: 202, name: table_stats_reply, module: loxi.of13.message, event: sending, instance_id: voltha-ofagent-cc5bd45b-m4555}

voltha/voltha-ofagent-cc5bd45b-m4555[ofagent]: 20200303T151219.623 DEBUG of_connection.send

{sent: 00000000: 04 13 00 10 00 00 00 CA 00 03 00 00 00 00 00 00 ................, event: data-sent, instance_id: voltha-ofagent-cc5bd45b-m4555}

voltha/voltha-ofagent-cc5bd45b-m4555[ofagent]: 20200303T151219.656 DEBUG of_connection.dataReceived

{received: 00000000: 04 12 00 18 00 00 00 0B 00 04 00 00 00 00 00 00 ................ voltha/bbsim-7c997b746c-nlhtr[bbsim]: time="2020-03-03T15:12:19Z" level=warning msg="Stopping OLT gRPC server" module=OLT oltId=BBSIM_OLT_0 voltha/voltha-ofagent-cc5bd45b-m4555[ofagent]: 00000010: FF FF FF FF 00 00 00 00 ........, len: 24, event: data-received, instance_id: voltha-ofagent-cc5bd45b-m4555}

voltha/voltha-ofagent-cc5bd45b-m4555[ofagent]: 20200303T151219.657 DEBUG of_connection.dataReceived

{len: 24, xid: 11, name: port_stats_request, module: loxi.of13.message, event: received-msg, instance_id: voltha-ofagent-cc5bd45b-m4555}

voltha/adapter-open-olt-68bc485c5c-pldb7[adapter-open-olt]:

{"level":"info","ts":"2020-03-03T15:12:19.659Z","msg":"Failed to read from indications","instanceId":"adapter-open-olt-68bc485c5c-pldb7","caller":"device_handler.readIndications:329","err":"rpc error: code = Unavailable desc = transport is closing"}

voltha/adapter-open-olt-68bc485c5c-pldb7[adapter-open-olt]:

{"level":"debug","ts":"2020-03-03T15:12:19.659Z","msg":"Device deleted stoping the read indication thread","instanceId":"adapter-open-olt-68bc485c5c-pldb7","caller":"device_handler.readIndications:331"}

voltha/adapter-open-olt-68bc485c5c-pldb7[adapter-open-olt]:

{"level":"debug","ts":"2020-03-03T15:12:19.659Z","msg":"indications-ended","instanceId":"adapter-open-olt-68bc485c5c-pldb7","caller":"device_handler.readIndications:352","device-id":"44f0b94d8f76396ac0364f01"}

voltha/bbsim-7c997b746c-nlhtr[bbsim]: time="2020-03-03T15:12:19Z" level=debug msg="Changing ONU InternalState from pon_disabled to disabled" IntfId=0 OnuId=1 OnuSn=BBSM00000001 module=ONU
voltha/bbsim-7c997b746c-nlhtr[bbsim]: time="2020-03-03T15:12:19Z" level=debug msg="OLT Indication processing canceled via closed channel" module=OLT
voltha/voltha-rw-core-c4687c578-mvtkv[voltha]:

{"level":"debug","ts":"2020-03-03T15:12:19.659Z","msg":"ListLogicalDevicePorts","instanceId":"voltha-rw-core-c4687c578-mvtkv","caller":"grpc_nbi_api_handler.ListLogicalDevicePorts:409","logicaldeviceid":"id:\"0a0a0a0a0a00\" "}

voltha/bbsim-7c997b746c-nlhtr[bbsim]: time="2020-03-03T15:12:19Z" level=warning msg="Stopped handling OLT Indication Channel" module=OLT
voltha/bbsim-7c997b746c-nlhtr[bbsim]: time="2020-03-03T15:12:19Z" level=debug msg="NNI Indication processing canceled via channel closed" module=OLT
voltha/bbsim-7c997b746c-nlhtr[bbsim]: time="2020-03-03T15:12:19Z" level=warning msg="Stopped handling NNI Channel" module=OLT nniChannel=0xc00007f560
voltha/bbsim-7c997b746c-nlhtr[bbsim]: time="2020-03-03T15:12:19Z" level=error msg="Failed to send Indication_OnuInd: rpc error: code = Unavailable desc = transport is closing"
voltha/bbsim-7c997b746c-nlhtr[bbsim]: time="2020-03-03T15:12:19Z" level=debug msg="Sent Indication_OnuInd" AdminState=down IntfId=0 OnuId=1 OnuSn=BBSM00000001 OperState=down module=ONU
voltha/bbsim-7c997b746c-nlhtr[bbsim]: time="2020-03-03T15:12:19Z" level=debug msg="Stopped handling ONU Indication Channel" module=ONU onuID=1 onuSN=BBSM00000001
voltha/voltha-rw-core-c4687c578-mvtkv[voltha]:

{"level":"debug","ts":"2020-03-03T15:12:19.659Z","msg":"ListLogicalDevicePorts","instanceId":"voltha-rw-core-c4687c578-mvtkv","caller":"logical_device_manager.ListLogicalDevicePorts:382","logicaldeviceid":"0a0a0a0a0a00"}

voltha/voltha-rw-core-c4687c578-mvtkv[voltha]:

{"level":"debug","ts":"2020-03-03T15:12:19.659Z","msg":"proxy-get","instanceId":"voltha-rw-core-c4687c578-mvtkv","caller":"proxy.Get:226","path":"/logical_devices/0a0a0a0a0a00","effective":"/logical_devices/0a0a0a0a0a00","operation":"PROXY_GET"}

voltha/voltha-rw-core-c4687c578-mvtkv[voltha]:

{"level":"debug","ts":"2020-03-03T15:12:19.659Z","msg":"node-get-request","instanceId":"voltha-rw-core-c4687c578-mvtkv","caller":"node.Get:299","path":"/logical_devices/0a0a0a0a0a00","hash":"","depth":0,"reconcile":false,"txid":""}

voltha/voltha-rw-core-c4687c578-mvtkv[voltha]:

{"level":"debug","ts":"2020-03-03T15:12:19.659Z","msg":"Cache entry for *voltha.Voltha: map[adapters:0xc0001c7a80 device_groups:0xc0001c7dc0 device_types:0xc0001c7d00 devices:0xc0001c7c40 event_filters:0xc0001c7ec0 logical_devices:0xc0001c7b40 omci_alarm_database:0xc0003400c0 omci_mib_database:0xc0001c7fc0]","instanceId":"voltha-rw-core-c4687c578-mvtkv","caller":"child_type.ChildrenFields:165"}

voltha/voltha-rw-core-c4687c578-mvtkv[voltha]:

{"level":"debug","ts":"2020-03-03T15:12:19.659Z","msg":"not-using-cache-entry","instanceId":"voltha-rw-core-c4687c578-mvtkv","caller":"node.Get:341","path":"logical_devices/0a0a0a0a0a00","hash":"","depth":0,"reconcile":false,"txid":""}

voltha/voltha-rw-core-c4687c578-mvtkv[voltha]:

{"level":"debug","ts":"2020-03-03T15:12:19.659Z","msg":"loading-from-persistence","instanceId":"voltha-rw-core-c4687c578-mvtkv","caller":"persisted_revision.LoadFromPersistence:353","path":"logical_devices/0a0a0a0a0a00","txid":""}

voltha/voltha-rw-core-c4687c578-mvtkv[voltha]:

{"level":"debug","ts":"2020-03-03T15:12:19.659Z","msg":"retrieve-from-kv","instanceId":"voltha-rw-core-c4687c578-mvtkv","caller":"persisted_revision.LoadFromPersistence:364","path":"logical_devices/0a0a0a0a0a00","txid":""}

voltha/voltha-rw-core-c4687c578-mvtkv[voltha]:

{"level":"debug","ts":"2020-03-03T15:12:19.659Z","msg":"listing-key","pkg":"db","key":"logical_devices/0a0a0a0a0a00","path":"service/voltha/logical_devices/0a0a0a0a0a00"}

voltha/voltha-rw-core-c4687c578-mvtkv[voltha]:

{"level":"debug","ts":"2020-03-03T15:12:19.660Z","msg":"Cache entry for *voltha.Voltha: map[adapters:0xc0001c7a80 device_groups:0xc0001c7dc0 device_types:0xc0001c7d00 devices:0xc0001c7c40 event_filters:0xc0001c7ec0 logical_devices:0xc0001c7b40 omci_alarm_database:0xc0003400c0 omci_mib_database:0xc0001c7fc0]","instanceId":"voltha-rw-core-c4687c578-mvtkv","caller":"child_type.ChildrenFields:165"}

voltha/voltha-rw-core-c4687c578-mvtkv[voltha]:

{"level":"debug","ts":"2020-03-03T15:12:19.660Z","msg":"parsing-data-blobs","instanceId":"voltha-rw-core-c4687c578-mvtkv","caller":"persisted_revision.LoadFromPersistence:387","path":"0a0a0a0a0a00","name":"logical_devices","size":0}

voltha/voltha-rw-core-c4687c578-mvtkv[voltha]:

{"level":"debug","ts":"2020-03-03T15:12:19.660Z","msg":"no-more-data-blobs","instanceId":"voltha-rw-core-c4687c578-mvtkv","caller":"persisted_revision.LoadFromPersistence:449","path":"0a0a0a0a0a00","name":"logical_devices"}

voltha/voltha-rw-core-c4687c578-mvtkv[voltha]:

{"level":"debug","ts":"2020-03-03T15:12:19.660Z","msg":"logicalDevice not in model","instanceId":"voltha-rw-core-c4687c578-mvtkv","caller":"logical_device_manager.load:266","lDeviceId":"0a0a0a0a0a00"}

voltha/voltha-ofagent-cc5bd45b-m4555[ofagent]: 20200303T151219.665 ERROR of_protocol_handler.handle_port_stats_request {req: <loxi.of13.message.port_stats_request object at 0x7f46ab4a96d0>, event: failed-port_stats-request, exception: Traceback (most recent call last):
voltha/voltha-ofagent-cc5bd45b-m4555[ofagent]: File "/ofagent/ofagent/of_protocol_handler.py", line 303, in handle_port_stats_request
voltha/voltha-ofagent-cc5bd45b-m4555[ofagent]: ports = yield rpc.list_ports(self.device_id)
voltha/voltha-ofagent-cc5bd45b-m4555[ofagent]: File "/usr/local/lib/python2.7/dist-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
voltha/voltha-ofagent-cc5bd45b-m4555[ofagent]: result = result.throwExceptionIntoGenerator(g)
voltha/voltha-ofagent-cc5bd45b-m4555[ofagent]: File "/usr/local/lib/python2.7/dist-packages/twisted/python/failure.py", line 491, in throwExceptionIntoGenerator
voltha/voltha-ofagent-cc5bd45b-m4555[ofagent]: return g.throw(self.type, self.value, self.tb)
voltha/voltha-ofagent-cc5bd45b-m4555[ofagent]: File "/ofagent/ofagent/grpc_client.py", line 305, in list_ports
voltha/voltha-ofagent-cc5bd45b-m4555[ofagent]: self.get_core_transaction_metadata(),))
voltha/voltha-ofagent-cc5bd45b-m4555[ofagent]: File "/usr/local/lib/python2.7/dist-packages/twisted/python/threadpool.py", line 250, in inContext
voltha/voltha-ofagent-cc5bd45b-m4555[ofagent]: result = inContext.theWork()
voltha/voltha-ofagent-cc5bd45b-m4555[ofagent]: File "/usr/local/lib/python2.7/dist-packages/twisted/python/threadpool.py", line 266, in <lambda>
voltha/voltha-ofagent-cc5bd45b-m4555[ofagent]: inContext.theWork = lambda: context.call(ctx, func, *args, **kw)
voltha/voltha-ofagent-cc5bd45b-m4555[ofagent]: File "/usr/local/lib/python2.7/dist-packages/twisted/python/context.py", line 122, in callWithContext
voltha/voltha-ofagent-cc5bd45b-m4555[ofagent]: return self.currentContext().callWithContext(ctx, func, *args, **kw)
voltha/voltha-ofagent-cc5bd45b-m4555[ofagent]: File "/usr/local/lib/python2.7/dist-packages/twisted/python/context.py", line 85, in callWithContext
voltha/voltha-ofagent-cc5bd45b-m4555[ofagent]: return func(args,*kw)
voltha/voltha-ofagent-cc5bd45b-m4555[ofagent]: File "/usr/local/lib/python2.7/dist-packages/grpc/channel.py", line 533, in __call_
voltha/voltha-ofagent-cc5bd45b-m4555[ofagent]: return _end_unary_response_blocking(state, call, False, None)
voltha/voltha-ofagent-cc5bd45b-m4555[ofagent]: File "/usr/local/lib/python2.7/dist-packages/grpc/_channel.py", line 467, in _end_unary_response_blocking
voltha/voltha-ofagent-cc5bd45b-m4555[ofagent]: raise _Rendezvous(state, None, None, deadline)
voltha/voltha-ofagent-cc5bd45b-m4555[ofagent]: _Rendezvous: <_Rendezvous of RPC that terminated with:
voltha/voltha-ofagent-cc5bd45b-m4555[ofagent]: status = StatusCode.NOT_FOUND
voltha/voltha-ofagent-cc5bd45b-m4555[ofagent]: details = "0a0a0a0a0a00"
voltha/voltha-ofagent-cc5bd45b-m4555[ofagent]: debug_error_string = "

{"created":"@1583248339.660386952","description":"Error received from peer","file":"src/core/lib/surface/call.cc","file_line":1017,"grpc_message":"0a0a0a0a0a00","grpc_status":5}

"
voltha/voltha-ofagent-cc5bd45b-m4555[ofagent]: >, instance_id: voltha-ofagent-cc5bd45b-m4555}
voltha/radius-5646467f88-vvtf5[radius]: Cleaning up request 12 ID 0 with timestamp +153
voltha/radius-5646467f88-vvtf5[radius]: Ready to process requests.
voltha/voltha-ofagent-cc5bd45b-m4555[ofagent]: 20200303T151220.278 DEBUG of_connection.dataReceived

{received: 00000000: 04 12 00 18 00 00 00 00 00 09 00 00 00 00 00 00 ................ voltha/voltha-ofagent-cc5bd45b-m4555[ofagent]: 00000010: FF FF FF FF 00 00 00 00 04 12 00 18 00 00 00 0B ................ voltha/voltha-ofagent-cc5bd45b-m4555[ofagent]: 00000020: 00 06 00 00 00 00 00 00 FF FF FF FC 00 00 00 00 ................ voltha/voltha-ofagent-cc5bd45b-m4555[ofagent]: 00000030: 04 12 00 10 00 00 00 0C 00 07 00 00 00 00 00 00 ................, len: 64, event: data-received, instance_id: voltha-ofagent-cc5bd45b-m4555}

voltha/voltha-ofagent-cc5bd45b-m4555[ofagent]: 20200303T151220.278 DEBUG of_connection.dataReceived

{len: 64, xid: 0, name: meter_stats_request, module: loxi.of13.message, event: received-msg, instance_id: voltha-ofagent-cc5bd45b-m4555}

voltha/voltha-ofagent-cc5bd45b-m4555[ofagent]: 20200303T151220.279 INFO of_protocol_handler.handle_meter_stats_request

{request: <loxi.of13.message.meter_stats_request object at 0x7f46ab487d90>, event: Received handle_meter_stats_request, instance_id: voltha-ofagent-cc5bd45b-m4555}

voltha/voltha-ofagent-cc5bd45b-m4555[ofagent]: 20200303T151220.279 DEBUG grpc_client.list_meters

{event: list_meters, instance_id: voltha-ofagent-cc5bd45b-m4555}

voltha/voltha-ofagent-cc5bd45b-m4555[ofagent]: 20200303T151220.280 DEBUG of_connection.dataReceived

{len: 64, xid: 11, name: group_stats_request, module: loxi.of13.message, event: received-msg, instance_id: voltha-ofagent-cc5bd45b-m4555}

voltha/voltha-rw-core-c4687c578-mvtkv[voltha]: {"level":"debug","ts":"2020-03-03T15:12:20.280Z","msg":"ListLogicalDeviceMeters","instanceId":"voltha-rw-core-c4687c578-mvtkv","caller":"grpc_nbi_api_handler.ListLogicalDeviceMeters:1096","id":{"id":"0a0a0a0a0a00"}}
voltha/voltha-rw-core-c4687c578-mvtkv[voltha]:

{"level":"debug","ts":"2020-03-03T15:12:20.280Z","msg":"ListLogicalDeviceMeters","instanceId":"voltha-rw-core-c4687c578-mvtkv","caller":"logical_device_manager.ListLogicalDeviceMeters:586","logicalDeviceId":"0a0a0a0a0a00"}

voltha/voltha-ofagent-cc5bd45b-m4555[ofagent]: 20200303T151220.281 DEBUG of_connection.dataReceived

{len: 64, xid: 12, name: group_desc_stats_request, module: loxi.of13.message, event: received-msg, instance_id: voltha-ofagent-cc5bd45b-m4555}

voltha/voltha-rw-core-c4687c578-mvtkv[voltha]:

{"level":"debug","ts":"2020-03-03T15:12:20.280Z","msg":"proxy-get","instanceId":"voltha-rw-core-c4687c578-mvtkv","caller":"proxy.Get:226","path":"/logical_devices/0a0a0a0a0a00","effective":"/logical_devices/0a0a0a0a0a00","operation":"PROXY_GET"}

voltha/voltha-rw-core-c4687c578-mvtkv[voltha]:

{"level":"debug","ts":"2020-03-03T15:12:20.280Z","msg":"node-get-request","instanceId":"voltha-rw-core-c4687c578-mvtkv","caller":"node.Get:299","path":"/logical_devices/0a0a0a0a0a00","hash":"","depth":0,"reconcile":false,"txid":""}

voltha/voltha-rw-core-c4687c578-mvtkv[voltha]:

{"level":"debug","ts":"2020-03-03T15:12:20.281Z","msg":"Cache entry for *voltha.Voltha: map[adapters:0xc0001c7a80 device_groups:0xc0001c7dc0 device_types:0xc0001c7d00 devices:0xc0001c7c40 event_filters:0xc0001c7ec0 logical_devices:0xc0001c7b40 omci_alarm_database:0xc0003400c0 omci_mib_database:0xc0001c7fc0]","instanceId":"voltha-rw-core-c4687c578-mvtkv","caller":"child_type.ChildrenFields:165"}

voltha/voltha-rw-core-c4687c578-mvtkv[voltha]:

{"level":"debug","ts":"2020-03-03T15:12:20.281Z","msg":"not-using-cache-entry","instanceId":"voltha-rw-core-c4687c578-mvtkv","caller":"node.Get:341","reconcile":false,"txid":"","path":"logical_devices/0a0a0a0a0a00","hash":"","depth":0}

voltha/voltha-rw-core-c4687c578-mvtkv[voltha]:

{"level":"debug","ts":"2020-03-03T15:12:20.281Z","msg":"loading-from-persistence","instanceId":"voltha-rw-core-c4687c578-mvtkv","caller":"persisted_revision.LoadFromPersistence:353","path":"logical_devices/0a0a0a0a0a00","txid":""}