-
Type:
Bug
-
Status: Resolved (View Workflow)
-
Priority:
Low
-
Resolution: Won't Fix
-
Affects Version/s: None
-
Fix Version/s: Future
-
Component/s: ofagent-py
-
Labels:
-
Story Points:5
-
Epic Link:
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]:
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]:
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 = "
"
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
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]:
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":""}