FTTH-50632 [log modification of controller and vpagent  package]

Change-Id: Ib46bd1dbd7ba759a1b25f22b377dcefa3a289919
diff --git a/internal/pkg/controller/addflows.go b/internal/pkg/controller/addflows.go
index b303947..7524d00 100644
--- a/internal/pkg/controller/addflows.go
+++ b/internal/pkg/controller/addflows.go
@@ -122,7 +122,7 @@
 		portName, _ := aft.device.GetPortName(aft.flow.PortID)
 		if aft.flow.PortName != portName && portName != "" {
 			for _, flow := range aft.flow.SubFlows {
-				logger.Errorw(ctx, "Skip Flow Update", log.Fields{"Reason": "Port Deleted", "PortName": aft.flow.PortName, "PortNo": aft.flow.PortID, "Cookie": flow.Cookie, "Operation": aft.flow.Command})
+				logger.Warnw(ctx, "Skip Flow Update", log.Fields{"Reason": "Port Deleted", "PortName": aft.flow.PortName, "PortNo": aft.flow.PortID, "Cookie": flow.Cookie, "Operation": aft.flow.Command})
 				if aft.flow.Command == of.CommandDel {
 					aft.device.triggerFlowNotification(ctx, flow.Cookie, aft.flow.Command, of.BwAvailDetails{}, nil)
 				}
@@ -133,7 +133,7 @@
 
 	if !aft.device.isSBOperAllowed(aft.flow.ForceAction) {
 		for _, flow := range aft.flow.SubFlows {
-			logger.Errorw(ctx, "Skipping Flow Table Update", log.Fields{"Reason": "Device State not UP", "State": aft.device.State, "Cookie": flow.Cookie, "Operation": aft.flow.Command})
+			logger.Warnw(ctx, "Skipping Flow Table Update", log.Fields{"Reason": "Device State not UP", "State": aft.device.State, "Cookie": flow.Cookie, "Operation": aft.flow.Command})
 		}
 		return nil
 	}
@@ -151,7 +151,7 @@
 					// Do NOT retry incase of failure with reason: Entry Not Found
 					if aft.flow.Command == of.CommandDel && statusCode != uint32(infraerrorcode.ErrNotExists) {
 						if attempt != MaxRetryCount {
-							logger.Errorw(ctx, "Retrying Flow Delete", log.Fields{"Cookie": flow.GetFlowMod().Cookie, "Attempt": attempt})
+							logger.Warnw(ctx, "Retrying Flow Delete", log.Fields{"Cookie": flow.GetFlowMod().Cookie, "Attempt": attempt})
 							attempt++
 							continue
 						}
diff --git a/internal/pkg/controller/auditdevice.go b/internal/pkg/controller/auditdevice.go
index b322737..fd2e8c8 100644
--- a/internal/pkg/controller/auditdevice.go
+++ b/internal/pkg/controller/auditdevice.go
@@ -84,7 +84,7 @@
 
 // Start to start the task
 func (ad *AuditDevice) Start(ctx context.Context, taskID uint8) error {
-	logger.Warnw(ctx, "Audit Device Task Triggered", log.Fields{"Context": ctx, "taskId": taskID, "Device": ad.device.ID})
+	logger.Infow(ctx, "Audit Device Task Triggered", log.Fields{"Context": ctx, "taskId": taskID, "Device": ad.device.ID})
 	ad.taskID = taskID
 	ad.ctx = ctx
 
@@ -107,6 +107,7 @@
 	missingPorts := make(map[uint32]*ofp.OfpPort)
 	for _, ofpp := range ofpps.Items {
 		missingPorts[ofpp.OfpPort.PortNo] = ofpp.OfpPort
+		logger.Infow(ctx, "Missing Ports", log.Fields{"Ports": ofpp.OfpPort, "missingPorts": missingPorts})
 	}
 
 	var excessPorts []uint32
@@ -138,7 +139,7 @@
 
 	// 1st process the NNI port before all other ports so that the device state can be updated.
 	if vgcPort, ok := ad.device.PortsByID[NNIPortID]; ok {
-		logger.Info(ctx, "Processing NNI port state")
+		logger.Infow(ctx, "Processing NNI port state", log.Fields{"PortNo": vgcPort.ID, "PortName": vgcPort.Name, "PortState": vgcPort.State})
 		processPortState(NNIPortID, vgcPort)
 	}
 
@@ -161,13 +162,13 @@
 	ad.AddMissingPorts(ctx, missingPorts)
 	ad.DelExcessPorts(ctx, excessPorts)
 	ad.device.deviceAuditInProgress = false
-	logger.Warnw(ctx, "Audit Device Task Completed", log.Fields{"Context": ctx, "taskId": taskID, "Device": ad.device.ID})
+	logger.Infow(ctx, "Audit Device Task Completed", log.Fields{"Context": ctx, "taskId": taskID, "Device": ad.device.ID})
 	return nil
 }
 
 // AddMissingPorts to add the missing ports
 func (ad *AuditDevice) AddMissingPorts(cntx context.Context, mps map[uint32]*ofp.OfpPort) {
-	logger.Debugw(ctx, "Device Audit - Add Missing Ports", log.Fields{"NumPorts": len(mps)})
+	logger.Infow(ctx, "Device Audit - Add Missing Ports", log.Fields{"NumPorts": len(mps), "Ports": mps})
 
 	addMissingPort := func(mp *ofp.OfpPort) {
 		logger.Debugw(ctx, "Process Port Add Ind", log.Fields{"Port No": mp.PortNo, "Port Name": mp.Name})
@@ -175,7 +176,7 @@
 		// Error is ignored as it only drops duplicate ports
 		logger.Infow(ctx, "Calling AddPort", log.Fields{"No": mp.PortNo, "Name": mp.Name})
 		if err := ad.device.AddPort(cntx, mp); err != nil {
-			logger.Warnw(ctx, "AddPort Failed", log.Fields{"No": mp.PortNo, "Name": mp.Name, "Reason": err})
+			logger.Warnw(ctx, "AddPort Failed", log.Fields{"Port No": mp.PortNo, "Port Name": mp.Name, "Reason": err})
 		}
 		if mp.State == uint32(ofp.OfpPortState_OFPPS_LIVE) {
 			ad.device.ProcessPortState(cntx, mp.PortNo, mp.State)
@@ -185,7 +186,7 @@
 
 	// 1st process the NNI port before all other ports so that the flow provisioning for UNIs can be enabled
 	if mp, ok := mps[NNIPortID]; ok {
-		logger.Info(ctx, "Adding Missing NNI port")
+		logger.Debugw(ctx, "Adding Missing NNI port", log.Fields{"PortNo": mp.PortNo, "Port Name": mp.Name, "Port Status": mp.State})
 		addMissingPort(mp)
 	}
 
diff --git a/internal/pkg/controller/audittables.go b/internal/pkg/controller/audittables.go
index 26b250e..30e52f6 100644
--- a/internal/pkg/controller/audittables.go
+++ b/internal/pkg/controller/audittables.go
@@ -79,7 +79,7 @@
 // Start is called by the framework and is responsible for implementing
 // the actual task.
 func (att *AuditTablesTask) Start(ctx context.Context, taskID uint8) error {
-	logger.Warnw(ctx, "Audit Table Task Triggered", log.Fields{"Context": ctx, "taskId": taskID, "Device": att.device.ID})
+	logger.Infow(ctx, "Audit Table Task Triggered", log.Fields{"Context": ctx, "taskId": taskID, "Device": att.device.ID})
 	att.taskID = taskID
 	att.ctx = ctx
 	var errInfo error
@@ -111,9 +111,9 @@
 
 	// Triggering deletion of excess groups from device after the corresponding flows are removed
 	// to avoid flow dependency error during group deletion
-	logger.Infow(ctx, "Excess Groups", log.Fields{"Groups": rcvdGroups})
+	logger.Debugw(ctx, "Excess Groups", log.Fields{"Groups": rcvdGroups})
 	att.DelExcessGroups(rcvdGroups)
-	logger.Warnw(ctx, "Audit Table Task Completed", log.Fields{"Context": ctx, "taskId": taskID, "Device": att.device.ID})
+	logger.Infow(ctx, "Audit Table Task Completed", log.Fields{"Context": ctx, "taskId": taskID, "Device": att.device.ID})
 	return errInfo
 }
 
@@ -576,7 +576,7 @@
 	}
 	// 1st process the NNI port before all other ports so that the device state can be updated.
 	if vgcPort, ok := att.device.PortsByID[NNIPortID]; ok {
-		logger.Info(ctx, "Processing NNI port state")
+		logger.Debugw(ctx, "Processing NNI port state", log.Fields{"Port ID": vgcPort.ID, "Port Name": vgcPort.Name})
 		processPortState(NNIPortID, vgcPort)
 	}
 
@@ -592,7 +592,7 @@
 	}
 
 	if att.stop {
-		logger.Errorw(ctx, "Audit Device Task Canceled", log.Fields{"Context": att.ctx, "Task": att.taskID})
+		logger.Warnw(ctx, "Audit Device Task Canceled", log.Fields{"Context": att.ctx, "Task": att.taskID})
 		return tasks.ErrTaskCancelError
 	}
 	att.AddMissingPorts(ctx, missingPorts)
@@ -602,7 +602,7 @@
 
 // AddMissingPorts to add the missing ports
 func (att *AuditTablesTask) AddMissingPorts(cntx context.Context, mps map[uint32]*ofp.OfpPort) {
-	logger.Debugw(ctx, "Device Audit - Add Missing Ports", log.Fields{"NumPorts": len(mps)})
+	logger.Infow(ctx, "Device Audit - Add Missing Ports", log.Fields{"NumPorts": len(mps)})
 
 	addMissingPort := func(mp *ofp.OfpPort) {
 		logger.Debugw(ctx, "Process Port Add Ind", log.Fields{"Port No": mp.PortNo, "Port Name": mp.Name})
@@ -620,7 +620,7 @@
 
 	// 1st process the NNI port before all other ports so that the flow provisioning for UNIs can be enabled
 	if mp, ok := mps[NNIPortID]; ok {
-		logger.Info(ctx, "Adding Missing NNI port")
+		logger.Debugw(ctx, "Adding Missing NNI port", log.Fields{"PortNo": mp.PortNo})
 		addMissingPort(mp)
 	}
 
diff --git a/internal/pkg/controller/changeevent.go b/internal/pkg/controller/changeevent.go
index 77e7e68..ae744d6 100644
--- a/internal/pkg/controller/changeevent.go
+++ b/internal/pkg/controller/changeevent.go
@@ -86,7 +86,7 @@
 		} else if status.PortStatus.Reason == ofp.OfpPortReason_OFPPR_MODIFY {
 			cet.device.ProcessPortUpdate(ctx, portName, portNo, state)
 		}
-		logger.Infow(ctx, "Processed Port Change Event", log.Fields{"Port No": portNo, "Port Name": portName, "State": state, "Reason": status.PortStatus.Reason})
+		logger.Debugw(ctx, "Processed Port Change Event", log.Fields{"Port No": portNo, "Port Name": portName, "State": state, "Reason": status.PortStatus.Reason})
 		return nil
 	}
 	return errors.New("Invalid message received")
diff --git a/internal/pkg/controller/controller.go b/internal/pkg/controller/controller.go
index ffead2b..4e2c4eb 100644
--- a/internal/pkg/controller/controller.go
+++ b/internal/pkg/controller/controller.go
@@ -105,7 +105,7 @@
 	d.ConnectInd(context.TODO(), intf.DeviceDisc)
 	d.packetOutChannel = config.PacketOutChannel
 
-	logger.Warnw(ctx, "Added device", log.Fields{"Device": config.DeviceID, "SerialNo": d.SerialNum, "State": d.State})
+	logger.Debugw(ctx, "Added device", log.Fields{"Device": config.DeviceID, "SerialNo": d.SerialNum, "State": d.State})
 
 	return d
 }
@@ -119,7 +119,7 @@
 	}
 	v.app.DelDevice(cntx, id)
 	d.cancel() // To stop the device tables sync routine
-	logger.Warnw(ctx, "Deleted device", log.Fields{"Device": id})
+	logger.Debugw(ctx, "Deleted device", log.Fields{"Device": id})
 }
 
 // AddControllerTask - add task to controller queue
@@ -568,11 +568,11 @@
 	logger.Info(ctx, "Entering into GetAllMeterInfo method")
 	meters := map[string][]*of.Meter{}
 	for _, device := range v.devices {
-		logger.Infow(ctx, "Inside GetAllMeterInfo method", log.Fields{"deviceId": device.ID})
+		logger.Debugw(ctx, "Inside GetAllMeterInfo method", log.Fields{"deviceId": device.ID, "southbound": device.SouthBoundID, "serial no": device.SerialNum})
 		for _, meter := range device.meters {
 			meters[device.ID] = append(meters[device.ID], meter)
 		}
-		logger.Infow(ctx, "Inside GetAllMeterInfo method", log.Fields{"meters": meters})
+		logger.Debugw(ctx, "Inside GetAllMeterInfo method", log.Fields{"meters": meters})
 	}
 	return meters, nil
 }
@@ -581,14 +581,14 @@
 	logger.Info(ctx, "Entering into GetMeterInfo method")
 	meters := map[string]*of.Meter{}
 	for _, device := range v.devices {
-		logger.Infow(ctx, "Inside GetMeterInfo method", log.Fields{"deviceId": device.ID})
+		logger.Debugw(ctx, "Inside GetMeterInfo method", log.Fields{"deviceId": device.ID})
 		meter, err := device.GetMeter(id)
 		if err != nil {
 			logger.Errorw(ctx, "Failed to fetch the meter", log.Fields{"Reason": err.Error()})
 			return nil, err
 		}
 		meters[device.ID] = meter
-		logger.Infow(ctx, "Inside GetAllMeterInfo method", log.Fields{"Meter": meters})
+		logger.Debugw(ctx, "meters", log.Fields{"Meter": meters})
 	}
 	return meters, nil
 }
@@ -599,7 +599,7 @@
 	for _, device := range v.devices {
 		device.groups.Range(func(key, value interface{}) bool {
 			groupID := key.(uint32)
-			logger.Infow(ctx, "Inside GetGroupList method", log.Fields{"groupID": groupID})
+			logger.Debugw(ctx, "Inside GetGroupList method", log.Fields{"groupID": groupID})
 			//Obtain all groups associated with the device
 			grps, ok := device.groups.Load(groupID)
 			if !ok {
@@ -618,7 +618,7 @@
 	logger.Info(ctx, "Entering into GetGroupList method")
 	var groups *of.Group
 	for _, device := range v.devices {
-		logger.Infow(ctx, "Inside GetGroupList method", log.Fields{"groupID": id})
+		logger.Debugw(ctx, "Inside GetGroupList method", log.Fields{"groupID": id})
 		grps, ok := device.groups.Load(id)
 		if !ok {
 			return nil, errors.New("Group not found")
diff --git a/internal/pkg/controller/controllertasks.go b/internal/pkg/controller/controllertasks.go
index ddffac2..1a2b26d 100644
--- a/internal/pkg/controller/controllertasks.go
+++ b/internal/pkg/controller/controllertasks.go
@@ -70,7 +70,7 @@
 
 	device := GetController().AddDevice(ctx, adt.config)
 	vpagent.GetVPAgent().AddClientToClientMap(adt.config.DeviceID, device)
-	logger.Infow(ctx, "Add Device Task Completed", log.Fields{"Device": adt.config.DeviceID, "SerialNum": adt.config.SerialNum})
+	logger.Infow(ctx, "Add Device Task Completed", log.Fields{"Device": adt.config.DeviceID, "SerialNum": adt.config.SerialNum, "SouthBoundId": adt.config.SouthBoundID})
 
 	return nil
 }
diff --git a/internal/pkg/controller/device.go b/internal/pkg/controller/device.go
index 3ac5600..0bafca7 100644
--- a/internal/pkg/controller/device.go
+++ b/internal/pkg/controller/device.go
@@ -170,7 +170,7 @@
 		var hash uint32
 		err = json.Unmarshal([]byte(flowHash), &hash)
 		if err != nil {
-			logger.Error(ctx, "Failed to unmarshall flowhash")
+			logger.Errorw(ctx, "Failed to unmarshall flowhash", log.Fields{"data": flowHash})
 		} else {
 			device.flowHash = hash
 		}
@@ -191,7 +191,7 @@
 func (d *Device) GetFlow(cookie uint64) (*of.VoltSubFlow, bool) {
 	d.flowLock.RLock()
 	defer d.flowLock.RUnlock()
-	logger.Infow(ctx, "Get Flow", log.Fields{"Cookie": cookie})
+	logger.Debugw(ctx, "Get Flow", log.Fields{"Cookie": cookie})
 	flow, ok := d.flows[cookie]
 	return flow, ok
 }
@@ -201,7 +201,7 @@
 	d.flowLock.RLock()
 	defer d.flowLock.RUnlock()
 	var flows []*of.VoltSubFlow
-	logger.Infow(ctx, "Get All Flows", log.Fields{"deviceID": d.ID})
+	logger.Debugw(ctx, "Get All Flows", log.Fields{"deviceID": d.ID})
 	for _, f := range d.flows {
 		flows = append(flows, f)
 	}
@@ -213,7 +213,7 @@
 	d.flowLock.RLock()
 	defer d.flowLock.RUnlock()
 	var flows []*of.VoltSubFlow
-	logger.Infow(ctx, "Get All Pending Flows", log.Fields{"deviceID": d.ID})
+	logger.Debugw(ctx, "Get All Pending Flows", log.Fields{"deviceID": d.ID})
 	for _, f := range d.flows {
 		if f.State == of.FlowAddPending {
 			flows = append(flows, f)
@@ -226,7 +226,7 @@
 func (d *Device) AddFlow(cntx context.Context, flow *of.VoltSubFlow) error {
 	d.flowLock.Lock()
 	defer d.flowLock.Unlock()
-	logger.Infow(ctx, "AddFlow to device", log.Fields{"Cookie": flow.Cookie})
+	logger.Debugw(ctx, "AddFlow to device", log.Fields{"Cookie": flow.Cookie})
 	if _, ok := d.flows[flow.Cookie]; ok {
 		return errors.New(ErrDuplicateFlow)
 	}
@@ -269,7 +269,7 @@
 		return false
 	} else if flow.OldCookie != 0 && flow.Cookie != flow.OldCookie {
 		if _, ok := d.flows[flow.OldCookie]; ok {
-			logger.Infow(ctx, "Flow present with old cookie", log.Fields{"OldCookie": flow.OldCookie})
+			logger.Debugw(ctx, "Flow present with old cookie", log.Fields{"OldCookie": flow.OldCookie})
 			return true
 		}
 	}
@@ -281,7 +281,7 @@
 	d.flowLock.Lock()
 	defer d.flowLock.Unlock()
 	if _, ok := d.flows[flow.OldCookie]; ok {
-		logger.Infow(ctx, "Flow was added before vgc upgrade. Trying to delete with old cookie",
+		logger.Debugw(ctx, "Flow was added before vgc upgrade. Trying to delete with old cookie",
 			log.Fields{"OldCookie": flow.OldCookie})
 		delete(d.flows, flow.OldCookie)
 		d.DelFlowFromDb(cntx, flow.OldCookie)
@@ -324,7 +324,7 @@
 
 // UpdateGroupEntry - Adds/Updates the group to the device and also to the database
 func (d *Device) UpdateGroupEntry(cntx context.Context, group *of.Group) {
-	logger.Infow(ctx, "Update Group to device", log.Fields{"ID": group.GroupID})
+	logger.Debugw(ctx, "Update Group to device", log.Fields{"ID": group.GroupID})
 	d.groups.Store(group.GroupID, group)
 	d.AddGroupToDb(cntx, group)
 }
@@ -332,7 +332,7 @@
 // AddGroupToDb - Utility to add the group to the device DB
 func (d *Device) AddGroupToDb(cntx context.Context, group *of.Group) {
 	if b, err := json.Marshal(group); err == nil {
-		logger.Infow(ctx, "Adding Group to DB", log.Fields{"grp": group, "Json": string(b)})
+		logger.Debugw(ctx, "Adding Group to DB", log.Fields{"grp": group, "Json": string(b)})
 		if err = db.PutGroup(cntx, d.ID, group.GroupID, string(b)); err != nil {
 			logger.Errorw(ctx, "Write Group to DB failed", log.Fields{"device": d.ID, "groupID": group.GroupID, "Reason": err})
 		}
@@ -466,7 +466,7 @@
 			logger.Warnw(ctx, "Duplicate Meter", log.Fields{"ID": meter.ID})
 		}
 	} else {
-		logger.Warn(ctx, "Unmarshal failed")
+		logger.Warnw(ctx, "Unmarshal failed", log.Fields{"error": err, "meter": string(b)})
 	}
 }
 
@@ -636,7 +636,7 @@
 			logger.Warnw(ctx, "Duplicate Port", log.Fields{"ID": port.ID})
 		}
 	} else {
-		logger.Warn(ctx, "Unmarshal failed")
+		logger.Warnw(ctx, "Unmarshal failed", log.Fields{"port": string(b)})
 	}
 }
 
@@ -660,12 +660,12 @@
 	d.ctx = ctx1
 	d.Tasks.Initialize(ctx1)
 
-	logger.Warnw(ctx, "Device State change Ind: UP", log.Fields{"Device": d.ID})
+	logger.Debugw(ctx, "Device State change Ind: UP", log.Fields{"Device": d.ID})
 	d.State = DeviceStateUP
 	d.TimeStamp = time.Now()
 	GetController().DeviceUpInd(d.ID)
 
-	logger.Warnw(ctx, "Device State change Ind: UP, trigger Audit Tasks", log.Fields{"Device": d.ID})
+	logger.Debugw(ctx, "Device State change Ind: UP, trigger Audit Tasks", log.Fields{"Device": d.ID})
 	t := NewAuditDevice(d, AuditEventDeviceDisc)
 	d.Tasks.AddTask(t)
 
@@ -771,7 +771,7 @@
 
 	for _, port := range d.PortsByID {
 		if port.State != PortStateDown {
-			logger.Infow(ctx, "Resetting Port State to DOWN and Write to DB", log.Fields{"Device": d.ID, "Port": port})
+			logger.Debugw(ctx, "Resetting Port State to DOWN and Write to DB", log.Fields{"Device": d.ID, "Port": port})
 			port.State = PortStateDown
 			d.WritePortToDb(cntx, port)
 		}
@@ -1025,11 +1025,11 @@
 func (d *Device) writeFlowHashToDB(cntx context.Context) {
 	hash, err := json.Marshal(d.flowHash)
 	if err != nil {
-		logger.Errorw(ctx, "failed to marshal flow hash", log.Fields{"hash": d.flowHash})
+		logger.Errorw(ctx, "failed to marshal flow hash", log.Fields{"hash": d.flowHash, "error": err})
 		return
 	}
 	if err := db.PutFlowHash(cntx, d.ID, string(hash)); err != nil {
-		logger.Errorw(ctx, "Failed to add flow hash to DB", log.Fields{"device": d.ID, "hash": d.flowHash})
+		logger.Errorw(ctx, "Failed to add flow hash to DB", log.Fields{"device": d.ID, "hash": d.flowHash, "error": err})
 	}
 }
 
diff --git a/internal/pkg/controller/modgroup.go b/internal/pkg/controller/modgroup.go
index 9fdb478..aca6440 100644
--- a/internal/pkg/controller/modgroup.go
+++ b/internal/pkg/controller/modgroup.go
@@ -87,7 +87,7 @@
 				log.Fields{"groupId": grp.group.GroupID, "groupOp": grp.group.Command, "Status": statusCode, "errorReason": statusMsg})
 			return false
 		}
-		logger.Infow(ctx, "Group Mod Result", log.Fields{"groupID": grp.group.GroupID, "Error Code": statusCode})
+		logger.Debugw(ctx, "Group Mod Result", log.Fields{"groupID": grp.group.GroupID, "Error Code": statusCode})
 		return true
 	}
 
@@ -99,7 +99,7 @@
 	}
 
 	if !grp.device.isSBOperAllowed(grp.group.ForceAction) {
-		logger.Errorw(ctx, "Skipping Group Table Update", log.Fields{"Reason": "Device State not UP", "State": grp.device.State, "GroupID": grp.group.GroupID, "Operation": grp.group.Command})
+		logger.Warnw(ctx, "Skipping Group Table Update", log.Fields{"Reason": "Device State not UP", "State": grp.device.State, "GroupID": grp.group.GroupID, "Operation": grp.group.Command})
 		return nil
 	}