[VOL-3536] Error and loggin enhancements.
- Removing VERBOSE level and moving to just debug
- adding deviceId where missing for achieve bettere debugging
- add other parameters to returned errors
Change-Id: I6cb2301bba90a294726f87e94d4352b43f00f912
diff --git a/internal/pkg/onuadaptercore/device_handler.go b/internal/pkg/onuadaptercore/device_handler.go
index 2951a2f..61ce8dc 100644
--- a/internal/pkg/onuadaptercore/device_handler.go
+++ b/internal/pkg/onuadaptercore/device_handler.go
@@ -928,7 +928,7 @@
device := dh.device
if device == nil {
/*TODO: needs to handle error scenarios */
- logger.Error("Failed to fetch handler device")
+ logger.Errorw("Failed to fetch handler device", log.Fields{"device-id": dh.deviceID})
e.Cancel(err)
return
}
@@ -1201,7 +1201,7 @@
if pMibUlFsm != nil {
if pMibUlFsm.Is(ulStDisabled) {
if err := pMibUlFsm.Event(ulEvStart); err != nil {
- logger.Errorw("MibSyncFsm: Can't go to state starting", log.Fields{"err": err})
+ logger.Errorw("MibSyncFsm: Can't go to state starting", log.Fields{"deviceId": dh.deviceID, "err": err})
return fmt.Errorf("can't go to state starting: %s", dh.deviceID)
}
logger.Debugw("MibSyncFsm", log.Fields{"state": string(pMibUlFsm.Current())})
@@ -1209,12 +1209,12 @@
//Determine if this ONU has ever synchronized
if true { //TODO: insert valid check
if err := pMibUlFsm.Event(ulEvResetMib); err != nil {
- logger.Errorw("MibSyncFsm: Can't go to state resetting_mib", log.Fields{"err": err})
+ logger.Errorw("MibSyncFsm: Can't go to state resetting_mib", log.Fields{"deviceId": dh.deviceID, "err": err})
return fmt.Errorf("can't go to state resetting_mib: %s", dh.deviceID)
}
} else {
if err := pMibUlFsm.Event(ulEvExamineMds); err != nil {
- logger.Errorw("MibSyncFsm: Can't go to state examine_mds", log.Fields{"err": err})
+ logger.Errorw("MibSyncFsm: Can't go to state examine_mds", log.Fields{"deviceId": dh.deviceID, "err": err})
return fmt.Errorf("can't go to examine_mds: %s", dh.deviceID)
}
logger.Debugw("state of MibSyncFsm", log.Fields{"state": string(pMibUlFsm.Current())})
@@ -1225,7 +1225,8 @@
// Event(ulEvMismatch)
}
} else {
- logger.Errorw("wrong state of MibSyncFsm - want: disabled", log.Fields{"have": string(pMibUlFsm.Current())})
+ logger.Errorw("wrong state of MibSyncFsm - want: disabled", log.Fields{"have": string(pMibUlFsm.Current()),
+ "deviceId": dh.deviceID})
return fmt.Errorf("wrong state of MibSyncFsm: %s", dh.deviceID)
}
} else {
@@ -1403,20 +1404,21 @@
if pMibDlFsm != nil {
if pMibDlFsm.Is(dlStDisabled) {
if err := pMibDlFsm.Event(dlEvStart); err != nil {
- logger.Errorw("MibDownloadFsm: Can't go to state starting", log.Fields{"err": err})
+ logger.Errorw("MibDownloadFsm: Can't go to state starting", log.Fields{"deviceId": dh.deviceID, "err": err})
// maybe try a FSM reset and then again ... - TODO!!!
} else {
logger.Debugw("MibDownloadFsm", log.Fields{"state": string(pMibDlFsm.Current())})
// maybe use more specific states here for the specific download steps ...
if err := pMibDlFsm.Event(dlEvCreateGal); err != nil {
- logger.Errorw("MibDownloadFsm: Can't start CreateGal", log.Fields{"err": err})
+ logger.Errorw("MibDownloadFsm: Can't start CreateGal", log.Fields{"deviceId": dh.deviceID, "err": err})
} else {
logger.Debugw("state of MibDownloadFsm", log.Fields{"state": string(pMibDlFsm.Current())})
//Begin MIB data download (running autonomously)
}
}
} else {
- logger.Errorw("wrong state of MibDownloadFsm - want: disabled", log.Fields{"have": string(pMibDlFsm.Current())})
+ logger.Errorw("wrong state of MibDownloadFsm - want: disabled", log.Fields{"have": string(pMibDlFsm.Current()),
+ "deviceId": dh.deviceID})
// maybe try a FSM reset and then again ... - TODO!!!
}
/***** Mib download started */
diff --git a/internal/pkg/onuadaptercore/mib_download.go b/internal/pkg/onuadaptercore/mib_download.go
index 95a406d..74881f8 100644
--- a/internal/pkg/onuadaptercore/mib_download.go
+++ b/internal/pkg/onuadaptercore/mib_download.go
@@ -19,7 +19,7 @@
import (
"context"
- "errors"
+ "fmt"
"time"
"github.com/looplab/fsm"
@@ -149,17 +149,17 @@
{
msgLayer := (*msg.OmciPacket).Layer(omci.LayerTypeCreateResponse)
if msgLayer == nil {
- logger.Error("Omci Msg layer could not be detected for CreateResponse")
+ logger.Errorw("Omci Msg layer could not be detected for CreateResponse", log.Fields{"device-id": onuDeviceEntry.deviceID})
return
}
msgObj, msgOk := msgLayer.(*omci.CreateResponse)
if !msgOk {
- logger.Error("Omci Msg layer could not be assigned for CreateResponse")
+ logger.Errorw("Omci Msg layer could not be assigned for CreateResponse", log.Fields{"device-id": onuDeviceEntry.deviceID})
return
}
logger.Debugw("CreateResponse Data", log.Fields{"device-id": onuDeviceEntry.deviceID, "data-fields": msgObj})
if msgObj.Result != me.Success {
- logger.Errorw("Omci CreateResponse Error - later: drive FSM to abort state ?", log.Fields{"Error": msgObj.Result})
+ logger.Errorw("Omci CreateResponse Error - later: drive FSM to abort state ?", log.Fields{"device-id": onuDeviceEntry.deviceID, "Error": msgObj.Result})
// possibly force FSM into abort or ignore some errors for some messages? store error for mgmt display?
return
}
@@ -197,17 +197,18 @@
{
msgLayer := (*msg.OmciPacket).Layer(omci.LayerTypeSetResponse)
if msgLayer == nil {
- logger.Error("Omci Msg layer could not be detected for SetResponse")
+ logger.Errorw("Omci Msg layer could not be detected for SetResponse", log.Fields{"device-id": onuDeviceEntry.deviceID})
return
}
msgObj, msgOk := msgLayer.(*omci.SetResponse)
if !msgOk {
- logger.Error("Omci Msg layer could not be assigned for SetResponse")
+ logger.Errorw("Omci Msg layer could not be assigned for SetResponse", log.Fields{"device-id": onuDeviceEntry.deviceID})
return
}
logger.Debugw("SetResponse Data", log.Fields{"device-id": onuDeviceEntry.deviceID, "data-fields": msgObj})
if msgObj.Result != me.Success {
- logger.Errorw("Omci SetResponse Error - later: drive FSM to abort state ?", log.Fields{"Error": msgObj.Result})
+ logger.Errorw("Omci SetResponse Error - later: drive FSM to abort state ?", log.Fields{"device-id": onuDeviceEntry.deviceID,
+ "Error": msgObj.Result})
// possibly force FSM into abort or ignore some errors for some messages? store error for mgmt display?
return
}
@@ -229,7 +230,8 @@
} //SetResponseType
default:
{
- logger.Errorw("Rx OMCI MibDownload unhandled MsgType", log.Fields{"omciMsgType": msg.OmciMsg.MessageType})
+ logger.Errorw("Rx OMCI MibDownload unhandled MsgType", log.Fields{"device-id": onuDeviceEntry.deviceID,
+ "omciMsgType": msg.OmciMsg.MessageType})
return
}
} // switch msg.OmciMsg.MessageType
@@ -247,7 +249,8 @@
//verify response
err := onuDeviceEntry.waitforOmciResponse(meInstance)
if err != nil {
- logger.Error("InitialBridgeSetup failed at MBSP, aborting MIB Download!")
+ logger.Errorw("InitialBridgeSetup failed at MBSP, aborting MIB Download!",
+ log.Fields{"device-id": onuDeviceEntry.deviceID})
_ = onuDeviceEntry.pMibDownloadFsm.pFsm.Event(dlEvReset)
return
}
@@ -259,7 +262,8 @@
//verify response
err = onuDeviceEntry.waitforOmciResponse(meInstance)
if err != nil {
- logger.Error("InitialBridgeSetup failed at MBPCD, aborting MIB Download!")
+ logger.Errorw("InitialBridgeSetup failed at MBPCD, aborting MIB Download!",
+ log.Fields{"device-id": onuDeviceEntry.deviceID})
_ = onuDeviceEntry.pMibDownloadFsm.pFsm.Event(dlEvReset)
return
}
@@ -271,7 +275,8 @@
//verify response
err = onuDeviceEntry.waitforOmciResponse(meInstance)
if err != nil {
- logger.Error("InitialBridgeSetup failed at EVTOCD, aborting MIB Download!")
+ logger.Errorw("InitialBridgeSetup failed at EVTOCD, aborting MIB Download!",
+ log.Fields{"device-id": onuDeviceEntry.deviceID})
_ = onuDeviceEntry.pMibDownloadFsm.pFsm.Event(dlEvReset)
return
}
@@ -289,7 +294,7 @@
// logger.Info("MibDownload-bridge-init message reception canceled", log.Fields{"for device-id": onuDeviceEntry.deviceID})
case <-time.After(30 * time.Second): //3s was detected to be to less in 8*8 bbsim test with debug Info/Debug
logger.Warnw("MibDownload-bridge-init timeout", log.Fields{"for device-id": onuDeviceEntry.deviceID})
- return errors.New("mibDownloadBridgeInit timeout")
+ return fmt.Errorf("mibDownloadBridgeInit timeout %s", onuDeviceEntry.deviceID)
case success := <-onuDeviceEntry.omciMessageReceived:
if success {
logger.Debug("MibDownload-bridge-init response received")
@@ -297,6 +302,6 @@
}
// should not happen so far
logger.Warnw("MibDownload-bridge-init response error", log.Fields{"for device-id": onuDeviceEntry.deviceID})
- return errors.New("mibDownloadBridgeInit responseError")
+ return fmt.Errorf("mibDownloadBridgeInit responseError %s", onuDeviceEntry.deviceID)
}
}
diff --git a/internal/pkg/onuadaptercore/mib_sync.go b/internal/pkg/onuadaptercore/mib_sync.go
index eef2f70..a2015bc 100644
--- a/internal/pkg/onuadaptercore/mib_sync.go
+++ b/internal/pkg/onuadaptercore/mib_sync.go
@@ -149,7 +149,7 @@
var fistLevelMap map[string]interface{}
if err = json.Unmarshal(mibTmpBytes, &fistLevelMap); err != nil {
- logger.Error("MibSync FSM - Failed to unmarshal template", log.Fields{"error": err, "device-id": onuDeviceEntry.deviceID})
+ logger.Errorw("MibSync FSM - Failed to unmarshal template", log.Fields{"error": err, "device-id": onuDeviceEntry.deviceID})
} else {
for fistLevelKey, firstLevelValue := range fistLevelMap {
logger.Debugw("MibSync FSM - fistLevelKey", log.Fields{"fistLevelKey": fistLevelKey})
@@ -184,7 +184,8 @@
logger.Debugw("No MIB template found", log.Fields{"path": path, "device-id": onuDeviceEntry.deviceID})
}
} else {
- logger.Errorf("Get from kvstore operation failed for path %s", path)
+ logger.Errorf("Get from kvstore operation failed for path",
+ log.Fields{"path": path, "device-id": onuDeviceEntry.deviceID})
}
if meStoredFromTemplate {
logger.Debug("MibSync FSM - valid MEs stored from template")
@@ -292,15 +293,16 @@
_ = onuDeviceEntry.pMibUploadFsm.pFsm.Event(ulEvGetVendorAndSerial)
return
}
- logger.Errorw("Omci MibResetResponse Error", log.Fields{"Error": msgObj.Result})
+ logger.Errorw("Omci MibResetResponse Error", log.Fields{"deviceId": onuDeviceEntry.deviceID, "Error": msgObj.Result})
} else {
- logger.Error("Omci Msg layer could not be assigned")
+ logger.Errorw("Omci Msg layer could not be assigned", log.Fields{"deviceId": onuDeviceEntry.deviceID})
}
} else {
- logger.Error("Omci Msg layer could not be detected")
+ logger.Errorw("Omci Msg layer could not be detected", log.Fields{"deviceId": onuDeviceEntry.deviceID})
}
} else {
- logger.Errorw("Omci MibResetResponse received", log.Fields{"in state ": onuDeviceEntry.pMibUploadFsm.pFsm.Current})
+ logger.Errorw("Wrong Omci MibResetResponse received", log.Fields{"in state ": onuDeviceEntry.pMibUploadFsm.pFsm.Current,
+ "deviceId": onuDeviceEntry.deviceID})
}
logger.Info("MibSync Msg", log.Fields{"Stopped handling of MibSyncChan for device-id": onuDeviceEntry.deviceID})
_ = onuDeviceEntry.pMibUploadFsm.pFsm.Event(ulEvStop)
@@ -310,12 +312,12 @@
func (onuDeviceEntry *OnuDeviceEntry) handleOmciMibUploadResponseMessage(msg OmciMessage) {
msgLayer := (*msg.OmciPacket).Layer(omci.LayerTypeMibUploadResponse)
if msgLayer == nil {
- logger.Error("Omci Msg layer could not be detected")
+ logger.Errorw("Omci Msg layer could not be detected", log.Fields{"deviceId": onuDeviceEntry.deviceID})
return
}
msgObj, msgOk := msgLayer.(*omci.MibUploadResponse)
if !msgOk {
- logger.Error("Omci Msg layer could not be assigned")
+ logger.Errorw("Omci Msg layer could not be assigned", log.Fields{"deviceId": onuDeviceEntry.deviceID})
return
}
logger.Debugw("MibUploadResponse Data for:", log.Fields{"deviceId": onuDeviceEntry.deviceID, "data-fields": msgObj})
@@ -324,7 +326,7 @@
if onuDeviceEntry.PDevOmciCC.uploadSequNo < onuDeviceEntry.PDevOmciCC.uploadNoOfCmds {
_ = onuDeviceEntry.PDevOmciCC.sendMibUploadNext(context.TODO(), ConstDefaultOmciTimeout, true)
} else {
- logger.Error("Invalid number of commands received for:", log.Fields{"deviceId": onuDeviceEntry.deviceID, "uploadNoOfCmds": onuDeviceEntry.PDevOmciCC.uploadNoOfCmds})
+ logger.Errorw("Invalid number of commands received for:", log.Fields{"deviceId": onuDeviceEntry.deviceID, "uploadNoOfCmds": onuDeviceEntry.PDevOmciCC.uploadNoOfCmds})
//TODO right action?
_ = onuDeviceEntry.pMibUploadFsm.pFsm.Event(ulEvTimeout)
}
@@ -332,9 +334,10 @@
func (onuDeviceEntry *OnuDeviceEntry) handleOmciMibUploadNextResponseMessage(msg OmciMessage) {
msgLayer := (*msg.OmciPacket).Layer(omci.LayerTypeMibUploadNextResponse)
+
//TODO: temporary change due to VOL-3532
// if msgLayer == nil {
- // logger.Error("Omci Msg layer could not be detected")
+ // logger.Errorw("Omci Msg layer could not be detected", log.Fields{"deviceId": onuDeviceEntry.deviceID})
// return
// }
if msgLayer != nil {
@@ -376,9 +379,7 @@
if msgObj.EntityClass == onuDeviceEntry.PDevOmciCC.pLastTxMeInstance.GetClassID() && msgObj.EntityInstance == entityID {
meAttributes := msgObj.Attributes
meInstance := onuDeviceEntry.PDevOmciCC.pLastTxMeInstance.GetName()
- if onuDeviceEntry.mibDebugLevel == "VERBOSE" {
- logger.Debugf("MibSync FSM - GetResponse Data for %s", log.Fields{"deviceId": onuDeviceEntry.deviceID, "data-fields": msgObj}, meInstance)
- }
+ logger.Debugf("MibSync FSM - GetResponse Data for %s", log.Fields{"deviceId": onuDeviceEntry.deviceID, "data-fields": msgObj}, meInstance)
switch meInstance {
case "OnuG":
onuDeviceEntry.vendorID = fmt.Sprintf("%s", meAttributes["VendorId"])
@@ -436,23 +437,21 @@
}
}
} else {
- logger.Errorw("Omci GetResponse Error", log.Fields{"Error": msgObj.Result})
+ logger.Errorw("Omci GetResponse Error", log.Fields{"deviceId": onuDeviceEntry.deviceID, "Error": msgObj.Result})
}
} else {
- logger.Error("Omci Msg layer could not be assigned for GetResponse")
+ logger.Errorw("Omci Msg layer could not be assigned for GetResponse", log.Fields{"deviceId": onuDeviceEntry.deviceID})
}
} else {
- logger.Error("Omci Msg layer could not be detected for GetResponse")
+ logger.Errorw("Omci Msg layer could not be detected for GetResponse", log.Fields{"deviceId": onuDeviceEntry.deviceID})
}
logger.Info("MibSync Msg", log.Fields{"Stopped handling of MibSyncChan for device-id": onuDeviceEntry.deviceID})
_ = onuDeviceEntry.pMibUploadFsm.pFsm.Event(ulEvStop)
}
func (onuDeviceEntry *OnuDeviceEntry) handleOmciMessage(msg OmciMessage) {
- if onuDeviceEntry.mibDebugLevel == "VERBOSE" {
- logger.Debugw("MibSync Msg", log.Fields{"OmciMessage received for device-id": onuDeviceEntry.deviceID,
- "msgType": msg.OmciMsg.MessageType})
- }
+ logger.Debugw("MibSync Msg", log.Fields{"OmciMessage received for device-id": onuDeviceEntry.deviceID,
+ "msgType": msg.OmciMsg.MessageType, "msg": msg})
//further analysis could be done here based on msg.OmciMsg.Payload, e.g. verification of error code ...
switch msg.OmciMsg.MessageType {
case omci.MibResetResponseType:
@@ -467,6 +466,9 @@
case omci.GetResponseType:
onuDeviceEntry.handleOmciGetResponseMessage(msg)
+ default:
+ log.Warnw("Unknown Message Type", log.Fields{"msgType": msg.OmciMsg.MessageType})
+
}
}
diff --git a/internal/pkg/onuadaptercore/omci_ani_config.go b/internal/pkg/onuadaptercore/omci_ani_config.go
index 0103788..4669751 100644
--- a/internal/pkg/onuadaptercore/omci_ani_config.go
+++ b/internal/pkg/onuadaptercore/omci_ani_config.go
@@ -19,7 +19,6 @@
import (
"context"
- "errors"
"fmt"
"strconv"
"time"
@@ -550,12 +549,14 @@
func (oFsm *uniPonAniConfigFsm) handleOmciAniConfigCreateResponseMessage(msg OmciMessage) {
msgLayer := (*msg.OmciPacket).Layer(omci.LayerTypeCreateResponse)
if msgLayer == nil {
- logger.Error("Omci Msg layer could not be detected for CreateResponse")
+ logger.Errorw("Omci Msg layer could not be detected for CreateResponse",
+ log.Fields{"device-id": oFsm.pAdaptFsm.deviceID})
return
}
msgObj, msgOk := msgLayer.(*omci.CreateResponse)
if !msgOk {
- logger.Error("Omci Msg layer could not be assigned for CreateResponse")
+ logger.Errorw("Omci Msg layer could not be assigned for CreateResponse",
+ log.Fields{"device-id": oFsm.pAdaptFsm.deviceID})
return
}
logger.Debugw("CreateResponse Data", log.Fields{"device-id": oFsm.pAdaptFsm.deviceID, "data-fields": msgObj})
@@ -588,17 +589,20 @@
func (oFsm *uniPonAniConfigFsm) handleOmciAniConfigSetResponseMessage(msg OmciMessage) {
msgLayer := (*msg.OmciPacket).Layer(omci.LayerTypeSetResponse)
if msgLayer == nil {
- logger.Error("UniPonAniConfigFsm - Omci Msg layer could not be detected for SetResponse")
+ logger.Errorw("UniPonAniConfigFsm - Omci Msg layer could not be detected for SetResponse",
+ log.Fields{"device-id": oFsm.pAdaptFsm.deviceID})
return
}
msgObj, msgOk := msgLayer.(*omci.SetResponse)
if !msgOk {
- logger.Error("UniPonAniConfigFsm - Omci Msg layer could not be assigned for SetResponse")
+ logger.Errorw("UniPonAniConfigFsm - Omci Msg layer could not be assigned for SetResponse",
+ log.Fields{"device-id": oFsm.pAdaptFsm.deviceID})
return
}
logger.Debugw("UniPonAniConfigFsm SetResponse Data", log.Fields{"device-id": oFsm.pAdaptFsm.deviceID, "data-fields": msgObj})
if msgObj.Result != me.Success {
- logger.Errorw("UniPonAniConfigFsm - Omci SetResponse Error - later: drive FSM to abort state ?", log.Fields{"Error": msgObj.Result})
+ logger.Errorw("UniPonAniConfigFsm - Omci SetResponse Error - later: drive FSM to abort state ?",
+ log.Fields{"device-id": oFsm.pAdaptFsm.deviceID, "Error": msgObj.Result})
// possibly force FSM into abort or ignore some errors for some messages? store error for mgmt display?
return
}
@@ -642,7 +646,8 @@
} //SetResponseType
default:
{
- logger.Errorw("uniPonAniConfigFsm - Rx OMCI unhandled MsgType", log.Fields{"omciMsgType": msg.OmciMsg.MessageType})
+ logger.Errorw("uniPonAniConfigFsm - Rx OMCI unhandled MsgType",
+ log.Fields{"omciMsgType": msg.OmciMsg.MessageType, "device-id": oFsm.pAdaptFsm.deviceID})
return
}
}
@@ -807,7 +812,7 @@
// logger.Infow("LockState-bridge-init message reception canceled", log.Fields{"for device-id": oFsm.pAdaptFsm.deviceID})
case <-time.After(30 * time.Second): //3s was detected to be to less in 8*8 bbsim test with debug Info/Debug
logger.Warnw("UniPonAniConfigFsm multi entity timeout", log.Fields{"for device-id": oFsm.pAdaptFsm.deviceID})
- return errors.New("uniPonAniConfigFsm multi entity timeout")
+ return fmt.Errorf("uniPonAniConfigFsm multi entity timeout %s", oFsm.pAdaptFsm.deviceID)
case success := <-oFsm.omciMIdsResponseReceived:
if success {
logger.Debug("uniPonAniConfigFsm multi entity response received")
@@ -815,6 +820,6 @@
}
// should not happen so far
logger.Warnw("uniPonAniConfigFsm multi entity response error", log.Fields{"for device-id": oFsm.pAdaptFsm.deviceID})
- return errors.New("uniPonAniConfigFsm multi entity responseError")
+ return fmt.Errorf("uniPonAniConfigFsm multi entity responseError %s", oFsm.pAdaptFsm.deviceID)
}
}
diff --git a/internal/pkg/onuadaptercore/omci_cc.go b/internal/pkg/onuadaptercore/omci_cc.go
index 06458ee..8a02b44 100644
--- a/internal/pkg/onuadaptercore/omci_cc.go
+++ b/internal/pkg/onuadaptercore/omci_cc.go
@@ -23,6 +23,7 @@
"encoding/binary"
"encoding/hex"
"errors"
+ "fmt"
"strconv"
"sync"
@@ -205,23 +206,23 @@
}
} else {
logger.Errorw("received omci-message too small for OmciBaseFormat - abort", log.Fields{"Length": len(rxMsg)})
- return errors.New("rxOmciMessage too small for BaseFormat")
+ return fmt.Errorf("rxOmciMessage too small for BaseFormat %s", oo.deviceID)
}
packet := gopacket.NewPacket(rxMsg, omci.LayerTypeOMCI, gopacket.NoCopy)
if packet == nil {
- logger.Error("omci-message could not be decoded")
- return errors.New("could not decode rxMsg as OMCI")
+ logger.Errorw("omci-message could not be decoded", log.Fields{"deviceID": oo.deviceID})
+ return fmt.Errorf("could not decode rxMsg as OMCI %s", oo.deviceID)
}
omciLayer := packet.Layer(omci.LayerTypeOMCI)
if omciLayer == nil {
- logger.Error("omci-message could not decode omci layer")
- return errors.New("could not decode omci layer")
+ logger.Errorw("omci-message could not decode omci layer", log.Fields{"deviceID": oo.deviceID})
+ return fmt.Errorf("could not decode omci layer %s", oo.deviceID)
}
omciMsg, ok := omciLayer.(*omci.OMCI)
if !ok {
- logger.Error("omci-message could not assign omci layer")
- return errors.New("could not assign omci layer")
+ logger.Errorw("omci-message could not assign omci layer", log.Fields{"deviceID": oo.deviceID})
+ return fmt.Errorf("could not assign omci layer %s", oo.deviceID)
}
logger.Debugw("omci-message-decoded:", log.Fields{"omciMsgType": omciMsg.MessageType,
"transCorrId": strconv.FormatInt(int64(omciMsg.TransactionID), 16), "DeviceIdent": omciMsg.DeviceIdentifier})
@@ -232,8 +233,9 @@
return oo.receiveOnuMessage(ctx, omciMsg)
}
logger.Errorw("Unexpected TransCorrId != 0 not accepted for autonomous messages",
- log.Fields{"msgType": omciMsg.MessageType, "payload": hex.EncodeToString(omciMsg.Payload)})
- return errors.New("autonomous Omci Message with TranSCorrId != 0 not acccepted")
+ log.Fields{"msgType": omciMsg.MessageType, "payload": hex.EncodeToString(omciMsg.Payload),
+ "deviceID": oo.deviceID})
+ return fmt.Errorf("autonomous Omci Message with TranSCorrId != 0 not acccepted %s", oo.deviceID)
}
//logger.Debug("RxMsg is a Omci Response Message: try to schedule it to the requester")
@@ -248,8 +250,8 @@
oo.mutexRxSchedMap.Unlock()
} else {
oo.mutexRxSchedMap.Unlock()
- logger.Error("omci-message-response for not registered transCorrId")
- return errors.New("could not find registered response handler tor transCorrId")
+ logger.Errorw("omci-message-response for not registered transCorrId", log.Fields{"deviceID": oo.deviceID})
+ return fmt.Errorf("could not find registered response handler tor transCorrId %s", oo.deviceID)
}
return nil
@@ -460,7 +462,7 @@
/*TODO: needs to handle error scenarios */
logger.Errorw("Failed to fetch device", log.Fields{"err": err, "ParentId": oo.pBaseDeviceHandler.deviceID,
"ChildId": oo.deviceID})
- return errors.New("failed to fetch device")
+ return fmt.Errorf("failed to fetch device %s", oo.deviceID)
}
logger.Debugw("omci-message-sending", log.Fields{"fromDeviceType": oo.pBaseDeviceHandler.DeviceType,
@@ -475,7 +477,7 @@
//fromType,toType,toDevId, ProxyDevId
oo.pBaseDeviceHandler.DeviceType, oo.pBaseDeviceHandler.ProxyAddressType,
oo.deviceID, oo.pBaseDeviceHandler.ProxyAddressID, ""); sendErr != nil {
- logger.Errorw("send omci request error", log.Fields{"error": sendErr})
+ logger.Errorw("send omci request error", log.Fields{"ChildId": oo.deviceID, "error": sendErr})
return sendErr
}
oo.txQueue.Remove(queueElement) // Dequeue
@@ -545,7 +547,7 @@
if oo.pOnuDeviceEntry == nil {
logger.Errorw("Abort receiving OMCI response, DeviceEntryPointer is nil", log.Fields{
"device-id": oo.deviceID})
- return errors.New("deviceEntryPointer is nil")
+ return fmt.Errorf("deviceEntryPointer is nil %s", oo.deviceID)
}
// no further test on SeqNo is done here, assignment from rxScheduler is trusted
@@ -612,7 +614,8 @@
}
err = oo.pOnuDeviceEntry.waitForRebootResponse(responseChannel)
if err != nil {
- logger.Error("aborting ONU Reboot!")
+ logger.Errorw("aborting ONU Reboot!", log.Fields{
+ "Err": err, "device-id": oo.deviceID})
_ = oo.pOnuDeviceEntry.pMibDownloadFsm.pFsm.Event("reset")
return err
}
diff --git a/internal/pkg/onuadaptercore/omci_test_request.go b/internal/pkg/onuadaptercore/omci_test_request.go
index 6449760..c62a4c6 100644
--- a/internal/pkg/onuadaptercore/omci_test_request.go
+++ b/internal/pkg/onuadaptercore/omci_test_request.go
@@ -19,7 +19,7 @@
import (
"context"
- "errors"
+ "fmt"
//"sync"
//"time"
@@ -104,7 +104,7 @@
pkt, err := serialize(omci.GetRequestType, request, tid)
if err != nil {
//omciLogger.WithFields(log.Fields{ ...
- logger.Errorw("Cannot serialize Onu2-G GetRequest", log.Fields{"Err": err})
+ logger.Errorw("Cannot serialize Onu2-G GetRequest", log.Fields{"device-id": oo.deviceID, "Err": err})
return nil, err
}
// hexEncode would probably work as well, but not needed and leads to wrong logs on OltAdapter frame
@@ -124,7 +124,7 @@
logger.Debugw("verify-omci-message-response error", log.Fields{"incorrect TransCorrId": omciMsg.TransactionID,
"expected": oo.txSeqNo})
oo.verifyDone <- false
- return errors.New("unexpected TransCorrId")
+ return fmt.Errorf("unexpected TransCorrId %s", oo.deviceID)
}
if omciMsg.MessageType == omci.GetResponseType {
logger.Debugw("verify-omci-message-response", log.Fields{"correct RespType": omciMsg.MessageType})
@@ -132,7 +132,7 @@
logger.Debugw("verify-omci-message-response error", log.Fields{"incorrect RespType": omciMsg.MessageType,
"expected": omci.GetResponseType})
oo.verifyDone <- false
- return errors.New("unexpected MessageType")
+ return fmt.Errorf("unexpected MessageType %s", oo.deviceID)
}
//TODO!!! further tests on the payload should be done here ...
diff --git a/internal/pkg/onuadaptercore/omci_vlan_config.go b/internal/pkg/onuadaptercore/omci_vlan_config.go
index 34eeef6..cda4905 100644
--- a/internal/pkg/onuadaptercore/omci_vlan_config.go
+++ b/internal/pkg/onuadaptercore/omci_vlan_config.go
@@ -20,7 +20,7 @@
import (
"context"
"encoding/binary"
- "errors"
+ "fmt"
"strconv"
"sync"
"time"
@@ -281,7 +281,7 @@
} else {
logger.Errorw("UniVlanConfigFsm flow limit exceeded", log.Fields{
"device-id": oFsm.pAdaptFsm.deviceID})
- return errors.New(" UniVlanConfigFsm flow limit exceeded")
+ return fmt.Errorf(" UniVlanConfigFsm flow limit exceeded %s", oFsm.pAdaptFsm.deviceID)
}
}
return nil
@@ -577,17 +577,20 @@
{
msgLayer := (*msg.OmciPacket).Layer(omci.LayerTypeCreateResponse)
if msgLayer == nil {
- logger.Error("Omci Msg layer could not be detected for CreateResponse")
+ logger.Errorw("Omci Msg layer could not be detected for CreateResponse",
+ log.Fields{"device-id": oFsm.pAdaptFsm.deviceID})
return
}
msgObj, msgOk := msgLayer.(*omci.CreateResponse)
if !msgOk {
- logger.Error("Omci Msg layer could not be assigned for CreateResponse")
+ logger.Errorw("Omci Msg layer could not be assigned for CreateResponse",
+ log.Fields{"device-id": oFsm.pAdaptFsm.deviceID})
return
}
logger.Debugw("CreateResponse Data", log.Fields{"device-id": oFsm.pAdaptFsm.deviceID, "data-fields": msgObj})
if msgObj.Result != me.Success {
- logger.Errorw("Omci CreateResponse Error - later: drive FSM to abort state ?", log.Fields{"Error": msgObj.Result})
+ logger.Errorw("Omci CreateResponse Error - later: drive FSM to abort state ?", log.Fields{"device-id": oFsm.pAdaptFsm.deviceID,
+ "Error": msgObj.Result})
// possibly force FSM into abort or ignore some errors for some messages? store error for mgmt display?
return
}
@@ -612,17 +615,20 @@
{
msgLayer := (*msg.OmciPacket).Layer(omci.LayerTypeSetResponse)
if msgLayer == nil {
- logger.Error("UniVlanConfigFsm - Omci Msg layer could not be detected for SetResponse")
+ logger.Errorw("UniVlanConfigFsm - Omci Msg layer could not be detected for SetResponse",
+ log.Fields{"device-id": oFsm.pAdaptFsm.deviceID})
return
}
msgObj, msgOk := msgLayer.(*omci.SetResponse)
if !msgOk {
- logger.Error("UniVlanConfigFsm - Omci Msg layer could not be assigned for SetResponse")
+ logger.Errorw("UniVlanConfigFsm - Omci Msg layer could not be assigned for SetResponse",
+ log.Fields{"device-id": oFsm.pAdaptFsm.deviceID})
return
}
logger.Debugw("UniVlanConfigFsm SetResponse Data", log.Fields{"deviceId": oFsm.pAdaptFsm.deviceID, "data-fields": msgObj})
if msgObj.Result != me.Success {
- logger.Errorw("UniVlanConfigFsm - Omci SetResponse Error - later: drive FSM to abort state ?", log.Fields{"Error": msgObj.Result})
+ logger.Errorw("UniVlanConfigFsm - Omci SetResponse Error - later: drive FSM to abort state ?",
+ log.Fields{"deviceId": oFsm.pAdaptFsm.deviceID, "Error": msgObj.Result})
// possibly force FSM into abort or ignore some errors for some messages? store error for mgmt display?
return
}
@@ -639,7 +645,8 @@
} //SetResponseType
default:
{
- logger.Errorw("UniVlanConfigFsm - Rx OMCI unhandled MsgType", log.Fields{"omciMsgType": msg.OmciMsg.MessageType})
+ logger.Errorw("UniVlanConfigFsm - Rx OMCI unhandled MsgType",
+ log.Fields{"omciMsgType": msg.OmciMsg.MessageType, "deviceId": oFsm.pAdaptFsm.deviceID})
return
}
}
@@ -899,7 +906,7 @@
// logger.Infow("LockState-bridge-init message reception canceled", log.Fields{"for device-id": oFsm.pAdaptFsm.deviceID})
case <-time.After(30 * time.Second): //AS FOR THE OTHER OMCI FSM's
logger.Warnw("UniVlanConfigFsm multi entity timeout", log.Fields{"for device-id": oFsm.pAdaptFsm.deviceID})
- return errors.New("uniVlanConfigFsm multi entity timeout")
+ return fmt.Errorf("uniVlanConfigFsm multi entity timeout %s", oFsm.pAdaptFsm.deviceID)
case success := <-oFsm.omciMIdsResponseReceived:
if success {
logger.Debug("UniVlanConfigFsm multi entity response received")
@@ -907,6 +914,6 @@
}
// should not happen so far
logger.Warnw("UniVlanConfigFsm multi entity response error", log.Fields{"for device-id": oFsm.pAdaptFsm.deviceID})
- return errors.New("uniVlanConfigFsm multi entity responseError")
+ return fmt.Errorf("uniVlanConfigFsm multi entity responseError %s", oFsm.pAdaptFsm.deviceID)
}
}
diff --git a/internal/pkg/onuadaptercore/onu_device_entry.go b/internal/pkg/onuadaptercore/onu_device_entry.go
index 8c1d097..aa2d5f0 100644
--- a/internal/pkg/onuadaptercore/onu_device_entry.go
+++ b/internal/pkg/onuadaptercore/onu_device_entry.go
@@ -245,7 +245,6 @@
devState OnuDeviceEvent
// for mibUpload
mibAuditDelay uint16
- mibDebugLevel string
// for mibUpload
pMibUploadFsm *AdapterFsm //could be handled dynamically and more general as pAdapterFsm - perhaps later
@@ -306,7 +305,6 @@
onuDeviceEntry.mibAuditDelay = onuDeviceEntry.supportedFsms["mib-synchronizer"].auditDelay
logger.Debugw("MibAudit is set to", log.Fields{"Delay": onuDeviceEntry.mibAuditDelay})
- onuDeviceEntry.mibDebugLevel = "normal" //set to "verbose" if you want to have all output, possibly later also per config option!
// Omci related Mib upload sync state machine
mibUploadChan := make(chan Message, 2048)
onuDeviceEntry.pMibUploadFsm = NewAdapterFsm("MibUpload", deviceID, mibUploadChan)
@@ -410,8 +408,8 @@
},
)
if onuDeviceEntry.pMibDownloadFsm == nil || onuDeviceEntry.pMibDownloadFsm.pFsm == nil {
- logger.Error("MibDownloadFsm could not be instantiated!!")
- // some specifc error treatment - or waiting for crash ???
+ logger.Errorw("MibDownloadFsm could not be instantiated", log.Fields{"device-id": deviceID})
+ // TODO some specifc error treatment - or waiting for crash ?
}
onuDeviceEntry.mibTemplateKVStore = onuDeviceEntry.baseDeviceHandler.setBackend(cBasePathMibTemplateKvStore)
@@ -441,31 +439,31 @@
oo.coreProxy, oo.adapterProxy)
if oo.PDevOmciCC == nil {
logger.Errorw("Could not create devOmciCc - abort", log.Fields{"for device-id": oo.deviceID})
- return errors.New("could not create devOmciCc")
+ return fmt.Errorf("could not create devOmciCc %s", oo.deviceID)
}
oo.started = true
- logger.Info("OnuDeviceEntry-started")
+ logger.Infow("OnuDeviceEntry-started", log.Fields{"for device-id": oo.deviceID})
return nil
}
//stop terminates the session
func (oo *OnuDeviceEntry) stop(ctx context.Context) error {
- logger.Info("stopping-OnuDeviceEntry")
+ logger.Infow("stopping-OnuDeviceEntry", log.Fields{"for device-id": oo.deviceID})
oo.started = false
//oo.exitChannel <- 1
// maybe also the omciCC should be stopped here - for now not as no real processing is expected here - maybe needs consolidation
- logger.Info("OnuDeviceEntry-stopped")
+ logger.Infow("OnuDeviceEntry-stopped", log.Fields{"for device-id": oo.deviceID})
return nil
}
func (oo *OnuDeviceEntry) reboot(ctx context.Context) error {
- logger.Info("reboot-OnuDeviceEntry")
+ logger.Infow("reboot-OnuDeviceEntry", log.Fields{"for device-id": oo.deviceID})
if err := oo.PDevOmciCC.sendReboot(context.TODO(), ConstDefaultOmciTimeout, true, oo.omciRebootMessageReceivedChannel); err != nil {
logger.Errorw("onu didn't reboot", log.Fields{"for device-id": oo.deviceID})
return err
}
- logger.Info("OnuDeviceEntry-reboot")
+ logger.Infow("OnuDeviceEntry-reboot", log.Fields{"for device-id": oo.deviceID})
return nil
}
@@ -473,30 +471,31 @@
select {
case <-time.After(3 * time.Second): //3s was detected to be to less in 8*8 bbsim test with debug Info/Debug
logger.Warnw("Reboot timeout", log.Fields{"for device-id": oo.deviceID})
- return errors.New("rebootTimeout")
+ return fmt.Errorf("rebootTimeout")
case data := <-responseChannel:
switch data.Data.(OmciMessage).OmciMsg.MessageType {
case omci.RebootResponseType:
{
msgLayer := (*data.Data.(OmciMessage).OmciPacket).Layer(omci.LayerTypeRebootResponse)
if msgLayer == nil {
- return errors.New("omci Msg layer could not be detected for RebootResponseType")
+ return fmt.Errorf("omci Msg layer could not be detected for RebootResponseType")
}
msgObj, msgOk := msgLayer.(*omci.GetResponse)
if !msgOk {
- return errors.New("omci Msg layer could not be assigned for RebootResponseType")
+ return fmt.Errorf("omci Msg layer could not be assigned for RebootResponseType %s", oo.deviceID)
}
logger.Debugw("CreateResponse Data", log.Fields{"device-id": oo.deviceID, "data-fields": msgObj})
if msgObj.Result != me.Success {
- logger.Errorw("Omci RebootResponseType Error ", log.Fields{"Error": msgObj.Result})
+ logger.Errorw("Omci RebootResponseType Error ", log.Fields{"device-id": oo.deviceID, "Error": msgObj.Result})
// possibly force FSM into abort or ignore some errors for some messages? store error for mgmt display?
- return errors.New("omci RebootResponse Result Error indication")
+ return fmt.Errorf("omci RebootResponse Result Error indication %s for device %s",
+ msgObj.Result, oo.deviceID)
}
return nil
}
}
logger.Warnw("Reboot response error", log.Fields{"for device-id": oo.deviceID})
- return errors.New("unexpected OmciResponse type received")
+ return fmt.Errorf("unexpected OmciResponse type received %s", oo.deviceID)
}
}
diff --git a/internal/pkg/onuadaptercore/onu_uni_port.go b/internal/pkg/onuadaptercore/onu_uni_port.go
index 0406cc9..8bc029d 100644
--- a/internal/pkg/onuadaptercore/onu_uni_port.go
+++ b/internal/pkg/onuadaptercore/onu_uni_port.go
@@ -19,7 +19,6 @@
import (
"context"
- "errors"
"fmt"
"strconv"
"strings"
@@ -143,7 +142,7 @@
} else {
logger.Warnw("could not create Voltha UniPort", log.Fields{
"device-id": apDeviceHandler.device.Id, "PortNo": oo.portNo})
- return errors.New("create Voltha UniPort failed")
+ return fmt.Errorf("create Voltha UniPort %d failed on %s", oo.portNo, apDeviceHandler.device.Id)
}
return nil
}
diff --git a/internal/pkg/onuadaptercore/onu_uni_tp.go b/internal/pkg/onuadaptercore/onu_uni_tp.go
index f47025b..d9578fe 100644
--- a/internal/pkg/onuadaptercore/onu_uni_tp.go
+++ b/internal/pkg/onuadaptercore/onu_uni_tp.go
@@ -21,6 +21,7 @@
"context"
"encoding/json"
"errors"
+ "fmt"
"strconv"
"strings"
"sync"
@@ -166,7 +167,8 @@
if pCurrentUniPort == nil {
logger.Errorw("TechProfile configuration aborted: requested uniID not found in PortDB",
log.Fields{"device-id": onuTP.deviceID, "uniID": aUniID})
- onuTP.procResult = errors.New("techProfile config aborted: requested uniID not found")
+ onuTP.procResult = fmt.Errorf("techProfile config aborted: requested uniID not found %d on %s",
+ aUniID, onuTP.deviceID)
return
}
@@ -178,7 +180,7 @@
// (ANI) configuration of this port has to be removed first
// (moreover in this case a possibly existing flow configuration is also not valid anymore and needs clean-up as well)
// existence of configuration can be detected based on tp stored TCONT's
- //TODO!!!:
+ //TODO:
/* if tcontMap not empty {
go onuTP.deleteAniSideConfig(ctx, aUniID, processingStep)
if !onuTP.waitForTimeoutOrCompletion(ctx, chTpConfigProcessingStep, processingStep) {
@@ -195,7 +197,8 @@
//timeout or error detected
logger.Debugw("tech-profile related configuration aborted on read",
log.Fields{"device-id": onuTP.deviceID, "UniId": aUniID})
- onuTP.procResult = errors.New("techProfile config aborted: tech-profile read issue")
+ onuTP.procResult = fmt.Errorf("techProfile config aborted: tech-profile read issue for %d on %s",
+ aUniID, onuTP.deviceID)
return
}
@@ -208,7 +211,8 @@
//timeout or error detected
logger.Debugw("tech-profile related configuration aborted on set",
log.Fields{"device-id": onuTP.deviceID, "UniId": aUniID})
- onuTP.procResult = errors.New("techProfile config aborted: Omci AniSideConfig failed")
+ onuTP.procResult = fmt.Errorf("techProfile config aborted: Omci AniSideConfig failed %d on %s",
+ aUniID, onuTP.deviceID)
//this issue here means that the AniConfigFsm has not finished successfully
//which requires to reset it to allow for new usage, e.g. also on a different UNI
//(without that it would be reset on device down indication latest)
@@ -219,13 +223,15 @@
// strange: UNI entry exists, but no ANI data, maybe such situation should be cleared up (if observed)
logger.Debugw("no Tcont/Gem data for this UNI found - abort", log.Fields{
"device-id": onuTP.deviceID, "uniID": aUniID})
- onuTP.procResult = errors.New("techProfile config aborted: no Tcont/Gem data found for this UNI")
+ onuTP.procResult = fmt.Errorf("techProfile config aborted: no Tcont/Gem data found for this UNI %d on %s",
+ aUniID, onuTP.deviceID)
return
}
} else {
logger.Debugw("no PonAni data for this UNI found - abort", log.Fields{
"device-id": onuTP.deviceID, "uniID": aUniID})
- onuTP.procResult = errors.New("techProfile config aborted: no AniSide data found for this UNI")
+ onuTP.procResult = fmt.Errorf("techProfile config aborted: no AniSide data found for this UNI %d on %s",
+ aUniID, onuTP.deviceID)
return
}
}
diff --git a/internal/pkg/onuadaptercore/openonu.go b/internal/pkg/onuadaptercore/openonu.go
index 7ad98f0..ce33c8e 100644
--- a/internal/pkg/onuadaptercore/openonu.go
+++ b/internal/pkg/onuadaptercore/openonu.go
@@ -175,7 +175,7 @@
//Get_ofp_device_info returns OFP information for the given device
func (oo *OpenONUAC) Get_ofp_device_info(device *voltha.Device) (*ic.SwitchCapability, error) {
logger.Errorw("device-handler-not-set", log.Fields{"device-id": device.Id})
- return nil, errors.New("device-handler-not-set")
+ return nil, fmt.Errorf("device-handler-not-set %s", device.Id)
}
//Get_ofp_port_info returns OFP port information for the given device
diff --git a/internal/pkg/onuadaptercore/uniportadmin.go b/internal/pkg/onuadaptercore/uniportadmin.go
index 0726be4..dea2a06 100644
--- a/internal/pkg/onuadaptercore/uniportadmin.go
+++ b/internal/pkg/onuadaptercore/uniportadmin.go
@@ -19,7 +19,7 @@
import (
"context"
- "errors"
+ "fmt"
"time"
"github.com/looplab/fsm"
@@ -315,12 +315,14 @@
if msg.OmciMsg.MessageType == omci.SetResponseType {
msgLayer := (*msg.OmciPacket).Layer(omci.LayerTypeSetResponse)
if msgLayer == nil {
- logger.Error("LockStateFsm - Omci Msg layer could not be detected for SetResponse")
+ logger.Errorw("LockStateFsm - Omci Msg layer could not be detected for SetResponse",
+ log.Fields{"device-id": oFsm.pAdaptFsm.deviceID})
return
}
msgObj, msgOk := msgLayer.(*omci.SetResponse)
if !msgOk {
- logger.Error("LockStateFsm - Omci Msg layer could not be assigned for SetResponse")
+ logger.Errorw("LockStateFsm - Omci Msg layer could not be assigned for SetResponse",
+ log.Fields{"device-id": oFsm.pAdaptFsm.deviceID})
return
}
logger.Debugw("LockStateFsm SetResponse Data", log.Fields{"device-id": oFsm.pAdaptFsm.deviceID, "data-fields": msgObj})
@@ -402,7 +404,7 @@
// logger.Infow("LockState-bridge-init message reception canceled", log.Fields{"for device-id": oFsm.pAdaptFsm.deviceID})
case <-time.After(30 * time.Second): //3s was detected to be to less in 8*8 bbsim test with debug Info/Debug
logger.Warnw("LockStateFSM uni-set timeout", log.Fields{"for device-id": oFsm.pAdaptFsm.deviceID})
- return errors.New("lockStateFsm uni-set timeout")
+ return fmt.Errorf("lockStateFsm uni-set timeout for device-id %s", oFsm.pAdaptFsm.deviceID)
case success := <-oFsm.omciLockResponseReceived:
if success {
logger.Debug("LockStateFSM uni-set response received")
@@ -410,6 +412,6 @@
}
// should not happen so far
logger.Warnw("LockStateFSM uni-set response error", log.Fields{"for device-id": oFsm.pAdaptFsm.deviceID})
- return errors.New("lockStateFsm uni-set responseError")
+ return fmt.Errorf("lockStateFsm uni-set responseError for device-id %s", oFsm.pAdaptFsm.deviceID)
}
}