[VOL-3655] Hardening: Cope with vendor-specific error-results of ONUs due to unsupported OMCI-MEs
[VOL-3642] Optimize logging with level "info" used for scale test
plus minor refactorizations
Change-Id: Ib2127048dc11bba55632494fb8aa77355b958900
diff --git a/internal/pkg/onuadaptercore/device_handler.go b/internal/pkg/onuadaptercore/device_handler.go
index 3f53050..7328abd 100644
--- a/internal/pkg/onuadaptercore/device_handler.go
+++ b/internal/pkg/onuadaptercore/device_handler.go
@@ -90,6 +90,22 @@
cOnuActivatedEvent = "ONU_ACTIVATED"
)
+const (
+ // device reasons
+ drActivatingOnu = "activating-onu"
+ drStartingOpenomci = "starting-openomci"
+ drDiscoveryMibsyncComplete = "discovery-mibsync-complete"
+ drInitialMibDownloaded = "initial-mib-downloaded"
+ drTechProfileConfigDownloadSuccess = "tech-profile-config-download-success"
+ drOmciFlowsPushed = "omci-flows-pushed"
+ drOmciAdminLock = "omci-admin-lock"
+ drOnuReenabled = "onu-reenabled"
+ drStoppingOpenomci = "stopping-openomci"
+ drRebooting = "rebooting"
+ drOmciFlowsDeleted = "omci-flows-deleted"
+ drTechProfileConfigDeleteSuccess = "tech-profile-config-delete-success"
+)
+
//deviceHandler will interact with the ONU ? device.
type deviceHandler struct {
deviceID string
@@ -249,13 +265,13 @@
msgBody := msg.GetBody()
onuIndication := &oop.OnuIndication{}
if err := ptypes.UnmarshalAny(msgBody, onuIndication); err != nil {
- logger.Warnw("cannot-unmarshal-onu-indication-msg-body", log.Fields{
+ logger.Warnw("onu-ind-request-cannot-unmarshal-msg-body", log.Fields{
"device-id": dh.deviceID, "error": err})
return err
}
onuOperstate := onuIndication.GetOperState()
- logger.Debugw("inter-adapter-recv-onu-ind", log.Fields{"device-id": dh.deviceID,
+ logger.Infow("onu-ind-request", log.Fields{"device-id": dh.deviceID,
"OnuId": onuIndication.GetOnuId(),
"AdminState": onuIndication.GetAdminState(), "OperState": onuOperstate,
"SNR": onuIndication.GetSerialNumber()})
@@ -275,6 +291,8 @@
func (dh *deviceHandler) processInterAdapterTechProfileDownloadReqMessage(
msg *ic.InterAdapterMessage) error {
+ logger.Infow("tech-profile-download-request", log.Fields{"device-id": dh.deviceID})
+
pDevEntry := dh.getOnuDeviceEntry(true)
if pDevEntry == nil {
logger.Errorw("No valid OnuDevice - aborting", log.Fields{"device-id": dh.deviceID})
@@ -354,6 +372,8 @@
func (dh *deviceHandler) processInterAdapterDeleteGemPortReqMessage(
msg *ic.InterAdapterMessage) error {
+ logger.Infow("delete-gem-port-request", log.Fields{"device-id": dh.deviceID})
+
pDevEntry := dh.getOnuDeviceEntry(true)
if pDevEntry == nil {
logger.Errorw("No valid OnuDevice - aborting", log.Fields{"device-id": dh.deviceID})
@@ -411,6 +431,8 @@
func (dh *deviceHandler) processInterAdapterDeleteTcontReqMessage(
msg *ic.InterAdapterMessage) error {
+ logger.Infow("delete-tcont-request", log.Fields{"device-id": dh.deviceID})
+
pDevEntry := dh.getOnuDeviceEntry(true)
if pDevEntry == nil {
logger.Errorw("No valid OnuDevice - aborting", log.Fields{"device-id": dh.deviceID})
@@ -646,7 +668,7 @@
//note that disableDevice sequences in some 'ONU active' state may yield also
// "tech...delete-success" or "omci-flow-deleted" according to further received requests in the end
// - inblock state checking to prevent possibly unneeded processing (on command repitition)
- if dh.deviceReason != "omci-admin-lock" {
+ if dh.deviceReason != drOmciAdminLock {
//disable-device shall be just a UNi/ONU-G related admin state setting
//all other configurations/FSM's shall not be impacted and shall execute as required by the system
@@ -667,15 +689,10 @@
//TODO with VOL-3045/VOL-3046: return the error and stop further processing
logger.Errorw("error-updating-device-state", log.Fields{"device-id": dh.deviceID, "error": err})
}
-
- logger.Debugw("DeviceReasonUpdate upon disable", log.Fields{
- "reason": "omci-admin-lock", "device-id": dh.deviceID})
// DeviceReason to update acc.to modified py code as per beginning of Sept 2020
- if err := dh.coreProxy.DeviceReasonUpdate(context.TODO(), dh.deviceID, "omci-admin-lock"); err != nil {
- //TODO with VOL-3045/VOL-3046: return the error and stop further processing
- logger.Errorw("error-updating-reason-state", log.Fields{"device-id": dh.deviceID, "error": err})
- }
- dh.deviceReason = "omci-admin-lock"
+
+ //TODO with VOL-3045/VOL-3046: catch and return error, valid for all occurrences in the codebase
+ _ = dh.deviceReasonUpdate(drOmciAdminLock, false)
}
}
}
@@ -854,12 +871,9 @@
logger.Errorw("error-updating-device-state", log.Fields{"device-id": dh.deviceID, "error": err})
return err
}
- if err := dh.coreProxy.DeviceReasonUpdate(context.TODO(), dh.deviceID, "rebooting"); err != nil {
- //TODO with VOL-3045/VOL-3046: return the error and stop further processing
- logger.Errorw("error-updating-reason-state", log.Fields{"device-id": dh.deviceID, "error": err})
+ if err := dh.deviceReasonUpdate(drRebooting, false); err != nil {
return err
}
- dh.deviceReason = "rebooting"
dh.ReadyForSpecificOmciConfig = false
return nil
}
@@ -884,12 +898,13 @@
dh.device.Root = false
dh.device.Vendor = "OpenONU"
dh.device.Model = "go"
- dh.device.Reason = "activating-onu"
- dh.deviceReason = "activating-onu"
+ dh.device.Reason = drActivatingOnu
+ dh.deviceReason = drActivatingOnu
dh.logicalDeviceID = dh.deviceID // really needed - what for ??? //TODO!!!
if !dh.reconciling {
+ logger.Infow("DeviceUpdate", log.Fields{"deviceReason": dh.device.Reason, "device-id": dh.deviceID})
_ = dh.coreProxy.DeviceUpdate(context.TODO(), dh.device)
} else {
logger.Debugw("reconciling - don't notify core about DeviceUpdate",
@@ -1156,9 +1171,9 @@
dh.setOnuDeviceEntry(deviceEntry, onuTechProfProc)
// fire deviceEntry ready event to spread to possibly waiting processing
dh.deviceEntrySet <- true
- logger.Infow("onuDeviceEntry-added", log.Fields{"device-id": dh.deviceID})
+ logger.Debugw("onuDeviceEntry-added", log.Fields{"device-id": dh.deviceID})
} else {
- logger.Infow("onuDeviceEntry-add: Device already exists", log.Fields{"device-id": dh.deviceID})
+ logger.Debugw("onuDeviceEntry-add: Device already exists", log.Fields{"device-id": dh.deviceID})
}
// might be updated with some error handling !!!
return nil
@@ -1206,16 +1221,7 @@
logger.Errorw("No valid OnuDevice -aborting", log.Fields{"device-id": dh.deviceID})
return fmt.Errorf("no valid OnuDevice: %s", dh.deviceID)
}
- if !dh.reconciling {
- if err := dh.coreProxy.DeviceReasonUpdate(context.TODO(), dh.deviceID, "starting-openomci"); err != nil {
- //TODO with VOL-3045/VOL-3046: return the error and stop further processing
- logger.Errorw("error-DeviceReasonUpdate to starting-openomci", log.Fields{"device-id": dh.deviceID, "error": err})
- }
- } else {
- logger.Debugw("reconciling - don't notify core about DeviceReasonUpdate to starting-openomci",
- log.Fields{"device-id": dh.deviceID})
- }
- dh.deviceReason = "starting-openomci"
+ _ = dh.deviceReasonUpdate(drStartingOpenomci, dh.reconciling)
/* this might be a good time for Omci Verify message? */
verifyExec := make(chan bool)
@@ -1355,7 +1361,7 @@
func (dh *deviceHandler) updateInterface(onuind *oop.OnuIndication) error {
//state checking to prevent unneeded processing (eg. on ONU 'unreachable' and 'down')
// (but note that the deviceReason may also have changed to e.g. TechProf*Delete_Success in between)
- if dh.deviceReason != "stopping-openomci" {
+ if dh.deviceReason != drStoppingOpenomci {
logger.Debugw("updateInterface-started - stopping-device", log.Fields{"device-id": dh.deviceID})
//stop all running FSM processing - make use of the DH-state as mirrored in the deviceReason
@@ -1392,17 +1398,12 @@
dh.disableUniPortStateUpdate()
- dh.deviceReason = "stopping-openomci"
dh.ReadyForSpecificOmciConfig = false
- if err := dh.coreProxy.DeviceReasonUpdate(context.TODO(), dh.deviceID, "stopping-openomci"); err != nil {
- //TODO with VOL-3045/VOL-3046: return the error and stop further processing
- logger.Errorw("error-DeviceReasonUpdate to stopping-openomci",
- log.Fields{"device-id": dh.deviceID, "error": err})
+ if err := dh.deviceReasonUpdate(drStoppingOpenomci, false); err != nil {
// abort: system behavior is just unstable ...
return err
}
-
logger.Debugw("call DeviceStateUpdate upon update interface", log.Fields{"ConnectStatus": voltha.ConnectStatus_UNREACHABLE,
"OperStatus": voltha.OperStatus_DISCOVERED, "device-id": dh.deviceID})
if err := dh.coreProxy.DeviceStateUpdate(context.TODO(), dh.deviceID,
@@ -1479,22 +1480,8 @@
func (dh *deviceHandler) processMibDatabaseSyncEvent(devEvent OnuDeviceEvent) {
logger.Debugw("MibInSync event received, adding uni ports and locking the ONU interfaces", log.Fields{"device-id": dh.deviceID})
- if !dh.reconciling {
- //initiate DevStateUpdate
- if err := dh.coreProxy.DeviceReasonUpdate(context.TODO(), dh.deviceID, "discovery-mibsync-complete"); err != nil {
- //TODO with VOL-3045/VOL-3046: return the error and stop further processing
- logger.Errorw("error-DeviceReasonUpdate to mibsync-complete", log.Fields{
- "device-id": dh.deviceID, "error": err})
- } else {
- logger.Infow("dev reason updated to MibSync complete", log.Fields{"device-id": dh.deviceID})
- }
- } else {
- logger.Debugw("reconciling - don't notify core about DeviceReasonUpdate to mibsync-complete",
- log.Fields{"device-id": dh.deviceID})
- }
- //set internal state anyway - as it was done
- dh.deviceReason = "discovery-mibsync-complete"
+ _ = dh.deviceReasonUpdate(drDiscoveryMibsyncComplete, dh.reconciling)
pDevEntry := dh.getOnuDeviceEntry(false)
i := uint8(0) //UNI Port limit: see MaxUnisPerOnu (by now 16) (OMCI supports max 255 p.b.)
if unigInstKeys := pDevEntry.pOnuDB.getSortedInstKeys(me.UniGClassID); len(unigInstKeys) > 0 {
@@ -1590,20 +1577,7 @@
logger.Debugw("reconciling - don't notify core about DeviceStateUpdate to ACTIVE",
log.Fields{"device-id": dh.deviceID})
}
- if !dh.reconciling {
- if err := dh.coreProxy.DeviceReasonUpdate(context.TODO(), dh.deviceID, "initial-mib-downloaded"); err != nil {
- //TODO with VOL-3045/VOL-3046: return the error and stop further processing
- logger.Errorw("error-DeviceReasonUpdate to initial-mib-downloaded",
- log.Fields{"device-id": dh.deviceID, "error": err})
- } else {
- logger.Infow("dev reason updated to initial-mib-downloaded", log.Fields{"device-id": dh.deviceID})
- }
- } else {
- logger.Debugw("reconciling - don't notify core about DeviceReasonUpdate to initial-mib-downloaded",
- log.Fields{"device-id": dh.deviceID})
- }
- //set internal state anyway - as it was done
- dh.deviceReason = "initial-mib-downloaded"
+ _ = dh.deviceReasonUpdate(drInitialMibDownloaded, dh.reconciling)
dh.ReadyForSpecificOmciConfig = true
// *** should generate UniUnlockStateDone event *****
if dh.pUnlockStateFsm == nil {
@@ -1638,14 +1612,9 @@
logger.Errorw("error-updating-device-state", log.Fields{"device-id": dh.deviceID, "error": err})
}
- logger.Debugw("DeviceReasonUpdate upon disable", log.Fields{
- "reason": "omci-admin-lock", "device-id": dh.deviceID})
+ logger.Debugw("DeviceReasonUpdate upon disable", log.Fields{"reason": drOmciAdminLock, "device-id": dh.deviceID})
// DeviceReason to update acc.to modified py code as per beginning of Sept 2020
- if err := dh.coreProxy.DeviceReasonUpdate(context.TODO(), dh.deviceID, "omci-admin-lock"); err != nil {
- //TODO with VOL-3045/VOL-3046: return the error and stop further processing
- logger.Errorw("error-updating-reason-state", log.Fields{"device-id": dh.deviceID, "error": err})
- }
- dh.deviceReason = "omci-admin-lock"
+ _ = dh.deviceReasonUpdate(drOmciAdminLock, false)
//transfer the modified logical uni port state
dh.disableUniPortStateUpdate()
@@ -1661,13 +1630,9 @@
}
logger.Debugw("DeviceReasonUpdate upon re-enable", log.Fields{
- "reason": "onu-reenabled", "device-id": dh.deviceID})
+ "reason": drOnuReenabled, "device-id": dh.deviceID})
// DeviceReason to update acc.to modified py code as per beginning of Sept 2020
- if err := dh.coreProxy.DeviceReasonUpdate(context.TODO(), dh.deviceID, "onu-reenabled"); err != nil {
- //TODO with VOL-3045/VOL-3046: return the error and stop further processing
- logger.Errorw("error-updating-reason-state", log.Fields{"device-id": dh.deviceID, "error": err})
- }
- dh.deviceReason = "onu-reenabled"
+ _ = dh.deviceReasonUpdate(drOnuReenabled, false)
//transfer the modified logical uni port state
dh.enableUniPortStateUpdate()
@@ -1678,23 +1643,9 @@
logger.Debugw("OmciAniConfigDone event received", log.Fields{"device-id": dh.deviceID})
// attention: the device reason update is done based on ONU-UNI-Port related activity
// - which may cause some inconsistency
- if dh.deviceReason != "tech-profile-config-download-success" {
+ if dh.deviceReason != drTechProfileConfigDownloadSuccess {
// which may be the case from some previous actvity even on this UNI Port (but also other UNI ports)
- if !dh.reconciling {
- if err := dh.coreProxy.DeviceReasonUpdate(context.TODO(), dh.deviceID, "tech-profile-config-download-success"); err != nil {
- //TODO with VOL-3045/VOL-3046: return the error and stop further processing
- logger.Errorw("error-DeviceReasonUpdate to tech-profile-config-download-success",
- log.Fields{"device-id": dh.deviceID, "error": err})
- } else {
- logger.Infow("update dev reason to tech-profile-config-download-success",
- log.Fields{"device-id": dh.deviceID})
- }
- } else {
- logger.Debugw("reconciling - don't notify core about DeviceReasonUpdate to tech-profile-config-download-success",
- log.Fields{"device-id": dh.deviceID})
- }
- //set internal state anyway - as it was done
- dh.deviceReason = "tech-profile-config-download-success"
+ _ = dh.deviceReasonUpdate(drTechProfileConfigDownloadSuccess, dh.reconciling)
}
if dh.reconciling {
go dh.reconcileDeviceFlowConfig()
@@ -1703,18 +1654,9 @@
logger.Debugw("OmciAniResourceRemoved event received", log.Fields{"device-id": dh.deviceID})
// attention: the device reason update is done based on ONU-UNI-Port related activity
// - which may cause some inconsistency
- if dh.deviceReason != "tech-profile-config-delete-success" {
+ if dh.deviceReason != drTechProfileConfigDeleteSuccess {
// which may be the case from some previous actvity even on this ONU port (but also other UNI ports)
- if err := dh.coreProxy.DeviceReasonUpdate(context.TODO(), dh.deviceID, "tech-profile-config-delete-success"); err != nil {
- //TODO with VOL-3045/VOL-3046: return the error and stop further processing
- logger.Errorw("error-DeviceReasonUpdate to tech-profile-config-delete-success",
- log.Fields{"device-id": dh.deviceID, "error": err})
- } else {
- logger.Infow("update dev reason to tech-profile-config-delete-success",
- log.Fields{"device-id": dh.deviceID})
- }
- //set internal state anyway - as it was done
- dh.deviceReason = "tech-profile-config-delete-success"
+ _ = dh.deviceReasonUpdate(drTechProfileConfigDeleteSuccess, false)
}
}
}
@@ -1726,40 +1668,18 @@
// - which may cause some inconsistency
if aDevEvent == OmciVlanFilterAddDone {
- if dh.deviceReason != "omci-flows-pushed" {
+ if dh.deviceReason != drOmciFlowsPushed {
// which may be the case from some previous actvity on another UNI Port of the ONU
// or even some previous flow add activity on the same port
- if !dh.reconciling {
- if err := dh.coreProxy.DeviceReasonUpdate(context.TODO(), dh.deviceID, "omci-flows-pushed"); err != nil {
- logger.Errorw("error-DeviceReasonUpdate to omci-flows-pushed",
- log.Fields{"device-id": dh.deviceID, "error": err})
- } else {
- logger.Infow("updated dev reason to omci-flows-pushed",
- log.Fields{"device-id": dh.deviceID})
- }
- } else {
- logger.Debugw("reconciling - don't notify core about DeviceReasonUpdate to omci-flows-pushed",
- log.Fields{"device-id": dh.deviceID})
- }
- //set internal state anyway - as it was done
- dh.deviceReason = "omci-flows-pushed"
-
+ _ = dh.deviceReasonUpdate(drOmciFlowsPushed, dh.reconciling)
if dh.reconciling {
go dh.reconcileMetrics()
}
}
} else {
- if dh.deviceReason != "omci-flows-deleted" {
+ if dh.deviceReason != drOmciFlowsDeleted {
//not relevant for reconcile
- if err := dh.coreProxy.DeviceReasonUpdate(context.TODO(), dh.deviceID, "omci-flows-deleted"); err != nil {
- logger.Errorw("error-DeviceReasonUpdate to omci-flows-deleted",
- log.Fields{"device-id": dh.deviceID, "error": err})
- } else {
- logger.Infow("updated dev reason to omci-flows-deleted",
- log.Fields{"device-id": dh.deviceID})
- }
- //set internal state anyway - as it was done
- dh.deviceReason = "omci-flows-deleted"
+ _ = dh.deviceReasonUpdate(drOmciFlowsDeleted, false)
}
}
}
@@ -1922,10 +1842,10 @@
chLSFsm := make(chan Message, 2048)
var sFsmName string
if aAdminState {
- logger.Infow("createLockStateFSM", log.Fields{"device-id": dh.deviceID})
+ logger.Debugw("createLockStateFSM", log.Fields{"device-id": dh.deviceID})
sFsmName = "LockStateFSM"
} else {
- logger.Infow("createUnlockStateFSM", log.Fields{"device-id": dh.deviceID})
+ logger.Debugw("createUnlockStateFSM", log.Fields{"device-id": dh.deviceID})
sFsmName = "UnLockStateFSM"
}
@@ -2383,6 +2303,23 @@
"device-id": dh.deviceID, "called from": aCallerIdent})
}
+func (dh *deviceHandler) deviceReasonUpdate(deviceReason string, dontNotifyCore bool) error {
+
+ dh.deviceReason = deviceReason
+ if !dontNotifyCore {
+ //TODO with VOL-3045/VOL-3046: return the error and stop further processing at calling position
+ if err := dh.coreProxy.DeviceReasonUpdate(context.TODO(), dh.deviceID, deviceReason); err != nil {
+ logger.Errorw("DeviceReasonUpdate: error",
+ log.Fields{"deviceReason": deviceReason, "device-id": dh.deviceID, "error": err})
+ return err
+ }
+ logger.Infow("DeviceReasonUpdate: success", log.Fields{"deviceReason": deviceReason, "device-id": dh.deviceID})
+ return nil
+ }
+ logger.Infow("Don't notify core about DeviceReasonUpdate", log.Fields{"deviceReason": deviceReason, "device-id": dh.deviceID})
+ return nil
+}
+
func (dh *deviceHandler) combineErrorStrings(errS ...error) error {
var errStr string = ""
for _, err := range errS {