[VOL-2311] Cleaning up logs
Change-Id: I4205eb67c8f404cc4073e94f2bd784f81dd7d334
diff --git a/VERSION b/VERSION
index 7c8d436..21bb5e1 100644
--- a/VERSION
+++ b/VERSION
@@ -1 +1 @@
-2.2.5-dev
+2.2.5
diff --git a/python/adapters/brcm_openomci_onu/brcm_openomci_onu_adapter.py b/python/adapters/brcm_openomci_onu/brcm_openomci_onu_adapter.py
index 5094cfc..54840e7 100644
--- a/python/adapters/brcm_openomci_onu/brcm_openomci_onu_adapter.py
+++ b/python/adapters/brcm_openomci_onu/brcm_openomci_onu_adapter.py
@@ -60,7 +60,7 @@
]
def __init__(self, core_proxy, adapter_proxy, config):
- log.debug('function-entry', config=config)
+ log.debug('BrcmOpenomciOnuAdapter-function-entry', config=config)
self.core_proxy = core_proxy
self.adapter_proxy = adapter_proxy
self.config = config
@@ -177,7 +177,7 @@
:param device: A Voltha.Device object.
:return: Will return result of self test
"""
- log.info('self-test-device - Not implemented yet', device=device.id)
+ log.info('self-test-device - Not implemented yet', device_id=device.id, serial_number=device.serial_number)
raise NotImplementedError()
def delete_device(self, device):
@@ -194,7 +194,7 @@
# TODO(smbaker): When BrcmOpenomciOnuAdapter is updated to inherit from OnuAdapter, this function can be deleted
def update_pm_config(self, device, pm_config):
- log.info("adapter-update-pm-config", device=device,
+ log.info("adapter-update-pm-config", device_id=device.id, serial_number=device.serial_number,
pm_config=pm_config)
handler = self.devices_handlers[device.id]
handler.update_pm_config(device, pm_config)
@@ -247,13 +247,15 @@
def get_ofp_port_info(self, device, port_no):
ofp_port_info = self.devices_handlers[device.id].get_ofp_port_info(device, port_no)
- log.debug('get_ofp_port_info', device_id=device.id, ofp_port_info=ofp_port_info)
+ log.debug('get_ofp_port_info', device_id=device.id,
+ port_name=ofp_port_info.port.ofp_port.name, port_no=ofp_port_info.port.device_port_no)
return ofp_port_info
def process_inter_adapter_message(self, msg):
- log.debug('process-inter-adapter-message', msg=msg)
# Unpack the header to know which device needs to handle this message
if msg.header:
+ log.debug('process-inter-adapter-message', type=msg.header.type, from_topic=msg.header.from_topic,
+ to_topic=msg.header.to_topic, to_device_id=msg.header.to_device_id)
handler = self.devices_handlers[msg.header.to_device_id]
handler.process_inter_adapter_message(msg)
diff --git a/python/adapters/brcm_openomci_onu/brcm_openomci_onu_handler.py b/python/adapters/brcm_openomci_onu/brcm_openomci_onu_handler.py
index a800368..6b1cec0 100644
--- a/python/adapters/brcm_openomci_onu/brcm_openomci_onu_handler.py
+++ b/python/adapters/brcm_openomci_onu/brcm_openomci_onu_handler.py
@@ -37,6 +37,7 @@
import pyvoltha.common.openflow.utils as fd
from pyvoltha.common.utils.registry import registry
+from pyvoltha.adapters.common.frameio.frameio import hexify
from pyvoltha.common.utils.nethelpers import mac_str_to_tuple
from pyvoltha.common.config.config_backend import ConsulStore
from pyvoltha.common.config.config_backend import EtcdStore
@@ -66,8 +67,6 @@
OP = EntityOperations
RC = ReasonCodes
-log = structlog.get_logger()
-
_STARTUP_RETRY_WAIT = 20
@@ -75,7 +74,7 @@
def __init__(self, adapter, device_id):
self.log = structlog.get_logger(device_id=device_id)
- self.log.debug('function-entry')
+ self.log.debug('BrcmOpenomciOnuHandler')
self.adapter = adapter
self.core_proxy = adapter.core_proxy
self.adapter_proxy = adapter.adapter_proxy
@@ -214,7 +213,7 @@
# Called once when the adapter creates the device/onu instance
@inlineCallbacks
def activate(self, device):
- self.log.debug('function-entry', device=device)
+ self.log.debug('activate-device', device_id=device.id, serial_number=device.serial_number)
assert device.parent_id
assert device.parent_port_no
@@ -224,7 +223,7 @@
self.parent_id = device.parent_id
self._pon_port_number = device.parent_port_no
if self.enabled is not True:
- self.log.info('activating-new-onu')
+ self.log.info('activating-new-onu', device_id=device.id, serial_number=device.serial_number)
# populate what we know. rest comes later after mib sync
device.root = False
device.vendor = 'OpenONU'
@@ -235,11 +234,11 @@
self.logical_device_id = self.device_id
yield self.core_proxy.device_update(device)
- self.log.debug('device updated', device=device)
+ self.log.debug('device updated', device_id=device.id, serial_number=device.serial_number)
yield self._init_pon_state()
- self.log.debug('pon state initialized', device=device)
+ self.log.debug('pon state initialized', device_id=device.id, serial_number=device.serial_number)
############################################################################
# Setup Alarm handler
self.events = AdapterEvents(self.core_proxy, device.id, self.logical_device_id,
@@ -252,13 +251,13 @@
'heartbeat': self.heartbeat,
OnuOmciPmMetrics.OMCI_DEV_KEY: self._onu_omci_device
}
- self.log.debug('create-OnuPmMetrics', serial_number=device.serial_number)
+ self.log.debug('create-OnuPmMetrics', device_id=device.id, serial_number=device.serial_number)
self.pm_metrics = OnuPmMetrics(self.events, self.core_proxy, self.device_id,
self.logical_device_id, device.serial_number,
grouped=True, freq_override=False, **kwargs)
pm_config = self.pm_metrics.make_proto()
self._onu_omci_device.set_pm_config(self.pm_metrics.omci_pm.openomci_interval_pm)
- self.log.info("initial-pm-config", pm_config=pm_config)
+ self.log.info("initial-pm-config",device_id=device.id, serial_number=device.serial_number)
yield self.core_proxy.device_pm_config_update(pm_config, init=True)
# Note, ONU ID and UNI intf set in add_uni_port method
@@ -288,7 +287,7 @@
# Called once when the adapter needs to re-create device. usually on vcore restart
@inlineCallbacks
def reconcile(self, device):
- self.log.debug('function-entry', device=device)
+ self.log.debug('reconcile-device', device_id=device.id, serial_number=device.serial_number)
# first we verify that we got parent reference and proxy info
assert device.parent_id
@@ -318,15 +317,23 @@
@inlineCallbacks
def _init_pon_state(self):
- self.log.debug('function-entry', deviceId=self.device_id)
+ self.log.debug('_init-pon-state', device_id=self.device_id, device_logical_id=self.logical_device_id)
self._pon = PonPort.create(self, self._pon_port_number)
self._pon.add_peer(self.parent_id, self._pon_port_number)
- self.log.debug('adding-pon-port-to-agent', pon=self._pon.get_port())
+ self.log.debug('adding-pon-port-to-agent',
+ type=self._pon.get_port().type,
+ admin_state=self._pon.get_port().admin_state,
+ oper_status=self._pon.get_port().oper_status,
+ )
yield self.core_proxy.port_created(self.device_id, self._pon.get_port())
- self.log.debug('added-pon-port-to-agent', pon=self._pon.get_port())
+ self.log.debug('added-pon-port-to-agent',
+ type=self._pon.get_port().type,
+ admin_state=self._pon.get_port().admin_state,
+ oper_status=self._pon.get_port().oper_status,
+ )
# Create and start the OpenOMCI ONU Device Entry for this ONU
self._onu_omci_device = self.omci_agent.add_device(self.device_id,
@@ -339,7 +346,7 @@
self._pon.enabled = True
def delete(self, device):
- self.log.info('delete-onu', device=device)
+ self.log.info('delete-onu', device_id=device.id, serial_number=device.serial_number)
if self.parent_adapter:
try:
self.parent_adapter.delete_child_device(self.parent_id, device)
@@ -498,7 +505,7 @@
# Calling this assumes the onu is active/ready and had at least an initial mib downloaded. This gets called from
# flow decomposition that ultimately comes from onos
def update_flow_table(self, device, flows):
- self.log.debug('function-entry', device=device, flows=flows)
+ self.log.debug('update-flow-table', device_id=device.id, serial_number=device.serial_number)
#
# We need to proxy through the OLT to get to the ONU
@@ -691,31 +698,35 @@
"set_vlan_vid": _set_vlan_vid}
def get_tx_id(self):
- self.log.debug('function-entry')
+ self.log.debug('get-tx-id')
self.tx_id += 1
return self.tx_id
def process_inter_adapter_message(self, request):
- self.log.debug('process-inter-adapter-message', msg=request)
+ self.log.debug('process-inter-adapter-message', type=request.header.type, from_topic=request.header.from_topic,
+ to_topic=request.header.to_topic, to_device_id=request.header.to_device_id)
try:
if request.header.type == InterAdapterMessageType.OMCI_REQUEST:
omci_msg = InterAdapterOmciMessage()
request.body.Unpack(omci_msg)
- self.log.debug('inter-adapter-recv-omci', omci_msg=omci_msg)
+ self.log.debug('inter-adapter-recv-omci', omci_msg=hexify(omci_msg.message))
self.receive_message(omci_msg.message)
elif request.header.type == InterAdapterMessageType.ONU_IND_REQUEST:
onu_indication = OnuIndication()
request.body.Unpack(onu_indication)
- self.log.debug('inter-adapter-recv-onu-ind', onu_indication=onu_indication)
+ self.log.debug('inter-adapter-recv-onu-ind', onu_id=onu_indication.onu_id,
+ oper_state=onu_indication.oper_state, admin_state=onu_indication.admin_state,
+ serial_number=onu_indication.serial_number)
if onu_indication.oper_state == "up":
self.create_interface(onu_indication)
elif onu_indication.oper_state == "down" or onu_indication.oper_state=="unreachable":
self.update_interface(onu_indication)
else:
- self.log.error("unknown-onu-indication", onu_indication=onu_indication)
+ self.log.error("unknown-onu-indication", onu_id=onu_indication.onu_id,
+ serial_number=onu_indication.serial_number)
elif request.header.type == InterAdapterMessageType.TECH_PROFILE_DOWNLOAD_REQUEST:
tech_msg = InterAdapterTechProfileDownloadMessage()
@@ -733,7 +744,8 @@
# Called each time there is an onu "up" indication from the olt handler
@inlineCallbacks
def create_interface(self, onu_indication):
- self.log.debug('function-entry', onu_indication=onu_indication)
+ self.log.debug('create-interface', onu_id=onu_indication.onu_id,
+ serial_number=onu_indication.serial_number)
self._onu_indication = onu_indication
yield self.core_proxy.device_state_update(self.device_id, oper_status=OperStatus.ACTIVATING,
@@ -752,7 +764,8 @@
# TODO: possibly other reasons to "update" from the olt?
@inlineCallbacks
def update_interface(self, onu_indication):
- self.log.debug('function-entry', onu_indication=onu_indication)
+ self.log.debug('update-interface', onu_id=onu_indication.onu_id,
+ serial_number=onu_indication.serial_number)
if onu_indication.oper_state == 'down' or onu_indication.oper_state == "unreachable":
self.log.debug('stopping-openomci-statemachine')
@@ -774,7 +787,7 @@
# Not currently called by olt or anything else
@inlineCallbacks
def remove_interface(self, data):
- self.log.debug('function-entry', data=data)
+ self.log.debug('remove-interface', data=data)
self.log.debug('stopping-openomci-statemachine')
reactor.callLater(0, self._onu_omci_device.stop)
@@ -812,14 +825,14 @@
# Not currently called. Would be called presumably from the olt handler
def create_multicast_gemport(self, data):
- self.log.debug('function-entry', data=data)
+ self.log.debug('create-multicast-gem-port', data=data)
# TODO: create objects and populate for later omci calls
def disable(self, device):
- self.log.debug('function-entry', device=device)
+ self.log.debug('disable', device_id=device.id, serial_number=device.serial_number)
try:
- self.log.info('sending-uni-lock-towards-device', device=device)
+ self.log.info('sending-uni-lock-towards-device', device_id=device.id, serial_number=device.serial_number)
@inlineCallbacks
def stop_anyway(reason):
@@ -843,11 +856,11 @@
self._deferred = self._onu_omci_device.task_runner.queue_task(task)
self._deferred.addCallbacks(stop_anyway, stop_anyway)
except Exception as e:
- log.exception('exception-in-onu-disable', exception=e)
+ self.log.exception('exception-in-onu-disable', exception=e)
@inlineCallbacks
def reenable(self, device):
- self.log.debug('function-entry', device=device)
+ self.log.debug('reenable', device_id=device.id, serial_number=device.serial_number)
try:
# Start up OpenOMCI state machines for this device
# this will ultimately resync mib and unlock unis on successful redownloading the mib
@@ -857,7 +870,7 @@
reactor.callLater(1, self._onu_omci_device.start, device)
self._heartbeat.enabled = True
except Exception as e:
- log.exception('exception-in-onu-reenable', exception=e)
+ self.log.exception('exception-in-onu-reenable', exception=e)
@inlineCallbacks
def reboot(self):
@@ -899,7 +912,7 @@
# Called just before openomci state machine is started. These listen for events from selected state machines,
# most importantly, mib in sync. Which ultimately leads to downloading the mib
def _subscribe_to_events(self):
- self.log.debug('function-entry')
+ self.log.debug('subscribe-to-events')
# OMCI MIB Database sync status
bus = self._onu_omci_device.event_bus
@@ -915,7 +928,7 @@
# Called when the mib is in sync
def in_sync_handler(self, _topic, msg):
- self.log.debug('function-entry', _topic=_topic, msg=msg)
+ self.log.debug('in-sync-handler', _topic=_topic, msg=msg)
if self._in_sync_subscription is not None:
try:
in_sync = msg[IN_SYNC_KEY]
@@ -934,7 +947,7 @@
self.log.exception('in-sync', e=e)
def capabilties_handler(self, _topic, _msg):
- self.log.debug('function-entry', _topic=_topic, msg=_msg)
+ self.log.debug('capabilities-handler', _topic=_topic, msg=_msg)
if self._capabilities_subscription is not None:
self.log.debug('capabilities-handler-done')
@@ -943,7 +956,7 @@
# Implement your own MibDownloadTask if you wish to setup something different by default
@inlineCallbacks
def _mib_in_sync(self):
- self.log.debug('function-entry')
+ self.log.debug('mib-in-sync')
omci = self._onu_omci_device
in_sync = omci.mib_db_in_sync
@@ -1056,7 +1069,7 @@
@inlineCallbacks
def _add_uni_port(self, device, entity_id, uni_id, uni_type=UniType.PPTP):
- self.log.debug('function-entry')
+ self.log.debug('add-uni-port')
uni_no = self.mk_uni_port_num(self._onu_indication.intf_id, self._onu_indication.onu_id, uni_id)
@@ -1095,7 +1108,7 @@
@inlineCallbacks
def onu_active_event(self):
- self.log.debug('function-entry')
+ self.log.debug('onu-active-event')
try:
device = yield self.core_proxy.get_device(self.device_id)
parent_device = yield self.core_proxy.get_device(self.parent_id)
diff --git a/python/adapters/brcm_openomci_onu/main.py b/python/adapters/brcm_openomci_onu/main.py
index 6e33571..f6d45ef 100755
--- a/python/adapters/brcm_openomci_onu/main.py
+++ b/python/adapters/brcm_openomci_onu/main.py
@@ -21,6 +21,7 @@
import argparse
import os
import time
+import logging
import arrow
import yaml
@@ -279,7 +280,18 @@
self.args = args = parse_args()
self.config = load_config(args)
- verbosity_adjust = (args.verbose or 0) - (args.quiet or 0)
+ # log levels in python are:
+ # 1 - DEBUG => verbosity_adjust = 0
+ # 2 - INFO => verbosity_adjust = 1
+ # 3 - WARNING => verbosity_adjust = 2
+ # 4 - ERROR
+ # 5 - CRITICAL
+ # If no flags are set we want to stick with INFO,
+ # if verbose is set we want to go down to DEBUG
+ # if quiet is set we want to go up to WARNING
+ # if you set both, you're doing something non-sense and you'll be back at INFO
+
+ verbosity_adjust = 1 - (args.verbose or 0) + (args.quiet or 0)
self.log = setup_logging(self.config.get('logging', {}),
args.instance_id,
verbosity_adjust=verbosity_adjust)
@@ -287,8 +299,7 @@
regex=args.container_name_regex)
self.adapter_version = self.get_version()
- self.log.info('OpenONU-Adapter-Version', version=
- self.adapter_version)
+ self.log.info('OpenONU-Adapter-Version', version=self.adapter_version)
if not args.no_banner:
print_banner(self.log)
diff --git a/python/requirements.txt b/python/requirements.txt
index 80f9ae0..c8e2a23 100644
--- a/python/requirements.txt
+++ b/python/requirements.txt
@@ -1,2 +1,2 @@
voltha-protos==2.1.0
-pyvoltha==2.3.0
+pyvoltha==2.3.1