Eliminating repetitive vcore logs.
Making vcore logs more manageable by removing repetitive logs
for ListDevices, ListDevicePorts etc., that clog up the logs
and reduce performance. Also handling logs for flow updates,
packet-ins and packet-outs.
Change-Id: Ida985f9b74143d051acca357c52df72751f8b320
diff --git a/voltha/adapters/iadapter.py b/voltha/adapters/iadapter.py
index e066365..a6488d0 100644
--- a/voltha/adapters/iadapter.py
+++ b/voltha/adapters/iadapter.py
@@ -135,8 +135,8 @@
raise NotImplementedError()
def update_flows_bulk(self, device, flows, groups):
- log.info('bulk-flow-update', device_id=device.id,
- flows=flows, groups=groups)
+ log.info('bulk-flow-update', device_id=device.id)
+ #flows=flows, groups=groups)
assert len(groups.items) == 0
handler = self.devices_handlers[device.id]
return handler.update_flow_table(flows.items)
diff --git a/voltha/core/adapter_agent.py b/voltha/core/adapter_agent.py
index 0565425..43e0000 100644
--- a/voltha/core/adapter_agent.py
+++ b/voltha/core/adapter_agent.py
@@ -82,7 +82,7 @@
@property
def name(self):
return self.adapter_name
-
+
@inlineCallbacks
def start(self):
self.log.debug('starting')
@@ -661,7 +661,8 @@
out_port = get_port_out(ofp_packet_out)
frame = ofp_packet_out.data
self.log.debug('rcv-packet-out', logical_device_id=logical_device_id,
- egress_port_no=out_port, adapter_name=self.adapter_name)
+ egress_port_no=out_port, adapter_name=self.adapter_name,
+ data=hexify(ofp_packet_out.data))
self.adapter.receive_packet_out(logical_device_id, out_port, frame)
def add_logical_port(self, logical_device_id, port):
@@ -1053,4 +1054,3 @@
def forward_onu_detect_state(self, device_id, state):
topic = self._gen_onu_detect_proxy_address_topic(device_id)
self.event_bus.publish(topic, state)
-
diff --git a/voltha/core/device_agent.py b/voltha/core/device_agent.py
index 5466fa9..2eca638 100644
--- a/voltha/core/device_agent.py
+++ b/voltha/core/device_agent.py
@@ -450,10 +450,10 @@
:return: None
"""
self.current_flows = self.flows_proxy.get('/')
- self.log.debug('pre-processing-flows',
- logical_device_id=self.last_data.id,
- desired_flows=flows,
- existing_flows=self.current_flows)
+ # self.log.debug('pre-processing-flows',
+ # logical_device_id=self.last_data.id,
+ # desired_flows=flows,
+ # existing_flows=self.current_flows)
if self.flow_changes is None:
self.flow_changes = FlowChanges()
@@ -477,14 +477,15 @@
self.log.debug('pre-processed-flows',
logical_device_id=self.last_data.id,
- flow_changes=self.flow_changes)
+ flows_to_add=len(self.flow_changes.to_add.items),
+ flows_to_remove=len(self.flow_changes.to_remove.items))
@inlineCallbacks
def _flow_table_updated(self, flows):
try:
self.log.debug('flow-table-updated',
- logical_device_id=self.last_data.id, flows=flows)
+ logical_device_id=self.last_data.id)
if self.flow_changes is not None and (len(self.flow_changes.to_remove.items) == 0) and (len(
self.flow_changes.to_add.items) == 0):
self.log.debug('no-flow-update-required',
diff --git a/voltha/core/dispatcher.py b/voltha/core/dispatcher.py
index 9a3ffd1..fcc00ff 100644
--- a/voltha/core/dispatcher.py
+++ b/voltha/core/dispatcher.py
@@ -200,7 +200,8 @@
log.debug('local-dispatch', core_id=core_id)
method = getattr(self.local_handler, method_name)
res = method(request, context=context)
- log.debug('local-dispatch-result', res=res, context=context)
+ # log.debug('local-dispatch-result', res=res, context=context)
+ log.debug('local-dispatch-result', context=context)
return res
@inlineCallbacks
diff --git a/voltha/core/global_handler.py b/voltha/core/global_handler.py
index c5b21dc..dd7467f 100644
--- a/voltha/core/global_handler.py
+++ b/voltha/core/global_handler.py
@@ -166,7 +166,7 @@
Empty(),
context,
broadcast=True)
- log.debug('grpc-response', response=response)
+ # log.debug('grpc-response', response=response)
returnValue(response)
@twisted_async
@@ -178,7 +178,7 @@
Empty(),
context,
broadcast=True)
- log.debug('grpc-response', response=response)
+ # log.debug('grpc-response', response=response)
returnValue(response)
@twisted_async
@@ -190,7 +190,7 @@
request,
context,
id=request.id)
- log.debug('grpc-response', response=response)
+ # log.debug('grpc-response', response=response)
if isinstance(response, DispatchError):
log.warn('grpc-error-response', error=response.error_code)
context.set_details(
@@ -198,7 +198,7 @@
context.set_code(response.error_code)
returnValue(LogicalDevice())
else:
- log.debug('grpc-success-response', response=response)
+ # log.debug('grpc-success-response', response=response)
returnValue(response)
@twisted_async
@@ -210,7 +210,7 @@
request,
context,
id=request.id)
- log.debug('grpc-response', response=response)
+ # log.debug('grpc-response', response=response)
if isinstance(response, DispatchError):
log.warn('grpc-error-response', error=response.error_code)
context.set_details(
@@ -218,7 +218,7 @@
context.set_code(response.error_code)
returnValue(Ports())
else:
- log.debug('grpc-success-response', response=response)
+ # log.debug('grpc-success-response', response=response)
returnValue(response)
@twisted_async
@@ -230,7 +230,7 @@
request,
context,
id=request.id)
- log.debug('grpc-response', response=response)
+ # log.debug('grpc-response', response=response)
if isinstance(response, DispatchError):
log.warn('grpc-error-response', error=response.error_code)
context.set_details(
@@ -238,7 +238,7 @@
context.set_code(response.error_code)
returnValue(LogicalPort())
else:
- log.debug('grpc-success-response', response=response)
+ # log.debug('grpc-success-response', response=response)
returnValue(response)
@twisted_async
@@ -249,7 +249,7 @@
request,
context,
id=request.id)
- log.debug('grpc-response', response=response)
+ # log.debug('grpc-response', response=response)
if isinstance(response, DispatchError):
log.warn('grpc-error-response', error=response.error_code)
context.set_details(
@@ -257,7 +257,7 @@
context.set_code(response.error_code)
returnValue(Flows())
else:
- log.debug('grpc-success-response', response=response)
+ # log.debug('grpc-success-response', response=response)
returnValue(response)
@twisted_async
@@ -408,7 +408,7 @@
Empty(),
context,
broadcast=True)
- log.debug('grpc-response', response=response)
+ # log.debug('grpc-response', response=response)
returnValue(response)
@twisted_async
@@ -537,14 +537,14 @@
request,
context,
id=request.id)
- log.debug('grpc-response', response=response)
+ # log.debug('grpc-response', response=response)
if isinstance(response, DispatchError):
log.warn('grpc-error-response', error=response.error_code)
context.set_details('Device \'{}\' error'.format(request.id))
context.set_code(response.error_code)
returnValue(Ports())
else:
- log.debug('grpc-success-response', response=response)
+ # log.debug('grpc-success-response', response=response)
returnValue(response)
@twisted_async
@@ -1856,4 +1856,4 @@
returnValue(OperationResp(code=OperationResp.OPERATION_FAILURE))
else:
log.debug('grpc-success-response', response=response)
- returnValue(response)
\ No newline at end of file
+ returnValue(response)
diff --git a/voltha/core/logical_device_agent.py b/voltha/core/logical_device_agent.py
index a40d215..db2eba4 100644
--- a/voltha/core/logical_device_agent.py
+++ b/voltha/core/logical_device_agent.py
@@ -333,12 +333,12 @@
flow.packet_count = old_flow.packet_count
flows[idx] = flow
changed = updated = True
- self.log.debug('flow-updated', flow=flow)
+ self.log.debug('flow-updated')
else:
flows.append(flow)
changed = True
- self.log.debug('flow-added', flow=mod)
+ self.log.debug('flow-added')
# write back to model
if changed:
@@ -678,15 +678,15 @@
# ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ PACKET_OUT ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
def packet_out(self, ofp_packet_out):
- self.log.debug('packet-out', packet=ofp_packet_out)
+ self.log.debug('packet-out')
topic = 'packet-out:{}'.format(self.logical_device_id)
self.event_bus.publish(topic, ofp_packet_out)
# ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ PACKET_IN ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
def handle_packet_in_event(self, _, msg):
- self.log.debug('handle-packet-in', msg=msg)
logical_port_no, packet = msg
+ self.log.debug('handle-packet-in', logical_port_no=logical_port_no)
packet_in = ofp.ofp_packet_in(
# buffer_id=0,
reason=ofp.OFPR_ACTION,
@@ -706,8 +706,8 @@
self.packet_in(packet_in)
def packet_in(self, ofp_packet_in):
- self.log.info('packet-in', logical_device_id=self.logical_device_id,
- pkt=ofp_packet_in, data=hexify(ofp_packet_in.data))
+ # self.log.info('packet-in', logical_device_id=self.logical_device_id)
+ # pkt=ofp_packet_in, data=hexify(ofp_packet_in.data))
self.local_handler.send_packet_in(
self.logical_device_id, ofp_packet_in)
@@ -723,10 +723,10 @@
:return: None
"""
current_flows = self.flows_proxy.get('/')
- self.log.debug('pre-processing-flows',
- logical_device_id=self.logical_device_id,
- desired_flows=flows,
- existing_flows=current_flows)
+ # self.log.debug('pre-processing-flows',
+ # logical_device_id=self.logical_device_id,
+ # desired_flows=flows,
+ # existing_flows=current_flows)
current_flow_ids = set(f.id for f in current_flows.items)
desired_flow_ids = set(f.id for f in flows.items)
@@ -745,14 +745,14 @@
self._no_flow_changes_required = False
self.log.debug('flows-preprocess-output', current_flows=len(
- current_flow_ids), new_flows=len(desired_flow_ids),
+ current_flow_ids), pre_process_notify_flows=len(desired_flow_ids),
adding_flows=len(self._flows_ids_to_add),
removing_flows=len(self._flows_ids_to_remove))
def _flow_table_updated(self, flows):
self.log.debug('flow-table-updated',
- logical_device_id=self.logical_device_id, flows=flows)
+ logical_device_id=self.logical_device_id)
if self._no_flow_changes_required:
# Stats changes, no need to process further