[VOL-3380] Functional area specific logging

Change-Id: I67414da013d8fc82827fcdb69d4f8a34040625d3
diff --git a/internal/pkg/swupg/onu_image_status.go b/internal/pkg/swupg/onu_image_status.go
new file mode 100755
index 0000000..4e1215f
--- /dev/null
+++ b/internal/pkg/swupg/onu_image_status.go
@@ -0,0 +1,361 @@
+/*
+ * Copyright 2020-present Open Networking Foundation
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ * http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+//Package swupg provides the utilities for onu sw upgrade
+package swupg
+
+import (
+	"context"
+	"encoding/hex"
+	"fmt"
+	"sync"
+	"time"
+
+	"github.com/opencord/omci-lib-go"
+	me "github.com/opencord/omci-lib-go/generated"
+	"github.com/opencord/voltha-lib-go/v7/pkg/log"
+	cmn "github.com/opencord/voltha-openonu-adapter-go/internal/pkg/common"
+	"github.com/opencord/voltha-protos/v5/go/voltha"
+)
+
+//OnuImageStatus implements methods to get status info of onu images
+type OnuImageStatus struct {
+	deviceID               string
+	pDeviceHandler         cmn.IdeviceHandler
+	pDevEntry              cmn.IonuDeviceEntry
+	pOmciCC                *cmn.OmciCC
+	requestedAttributes    me.AttributeValueMap
+	mutexWaitingForResp    sync.RWMutex
+	waitingForResp         bool
+	respChannel            chan cmn.Message
+	mutexPLastTxMeInstance sync.RWMutex
+	pLastTxMeInstance      *me.ManagedEntity
+}
+
+const (
+	cImgVersion     = "Version"
+	cImgIsCommitted = "IsCommitted"
+	cImgIsActive    = "IsActive"
+	cImgIsValid     = "IsValid"
+	cImgProductCode = "ProductCode"
+	cImgImageHash   = "ImageHash"
+)
+const cResponse = "response: "
+
+//NewOnuImageStatus creates a new instance of OnuImageStatus
+func NewOnuImageStatus(apDeviceHandler cmn.IdeviceHandler, apDevEntry cmn.IonuDeviceEntry) *OnuImageStatus {
+	return &OnuImageStatus{
+		deviceID:            apDeviceHandler.GetDeviceID(),
+		pDeviceHandler:      apDeviceHandler,
+		pDevEntry:           apDevEntry,
+		pOmciCC:             apDevEntry.GetDevOmciCC(),
+		requestedAttributes: make(me.AttributeValueMap),
+		waitingForResp:      false,
+		respChannel:         make(chan cmn.Message),
+	}
+}
+
+// GetOnuImageStatus - TODO: add comment
+func (oo *OnuImageStatus) GetOnuImageStatus(ctx context.Context) (*voltha.OnuImages, error) {
+
+	if !oo.pDeviceHandler.IsReadyForOmciConfig() {
+		logger.Errorw(ctx, "command rejected - improper device state", log.Fields{"device-id": oo.deviceID})
+		return nil, fmt.Errorf("command-rejected-improper-device-state")
+	}
+	if oo.pOmciCC == nil {
+		logger.Errorw(ctx, "omciCC not ready to receive omci messages", log.Fields{"device-id": oo.deviceID})
+		return nil, fmt.Errorf("omciCC-not-ready-to-receive-omci-messages")
+	}
+	var images voltha.OnuImages
+
+	for i := cmn.FirstSwImageMeID; i <= cmn.SecondSwImageMeID; i++ {
+		logger.Debugw(ctx, "GetOnuImageStatus for image id", log.Fields{"image-id": i, "device-id": oo.deviceID})
+
+		var image voltha.OnuImage
+
+		// TODO: Since the summed length of the attributes exceeds the capacity of a single response,
+		// it is distributed on several requests here. It should be discussed whether, in the course of a refactoring,
+		// a global mechanism should be implemented that automates this distribution - which would entail quite some
+		// changes on the respective receiver sides.
+
+		oo.requestedAttributes = me.AttributeValueMap{cImgVersion: "", cImgIsCommitted: 0, cImgIsActive: 0, cImgIsValid: 0}
+		if err := oo.requestOnuImageAttributes(ctx, uint16(i), &image); err != nil {
+			logger.Errorw(ctx, err.Error(), log.Fields{"requestedAttributes": oo.requestedAttributes, "device-id": oo.deviceID})
+			return nil, err
+		}
+		oo.requestedAttributes = me.AttributeValueMap{cImgProductCode: ""}
+		if err := oo.requestOnuImageAttributes(ctx, uint16(i), &image); err != nil {
+			logger.Errorw(ctx, err.Error(), log.Fields{"requestedAttributes": oo.requestedAttributes, "device-id": oo.deviceID})
+			return nil, err
+		}
+		oo.requestedAttributes = me.AttributeValueMap{cImgImageHash: 0}
+		if err := oo.requestOnuImageAttributes(ctx, uint16(i), &image); err != nil {
+			logger.Errorw(ctx, err.Error(), log.Fields{"requestedAttributes": oo.requestedAttributes, "device-id": oo.deviceID})
+			return nil, err
+		}
+		images.Items = append(images.Items, &image)
+	}
+	logger.Debugw(ctx, "images of the ONU", log.Fields{"images": images})
+	oo.updateOnuSwImageIndications(ctx, &images)
+	oo.updateOnuSwImagePersistentData(ctx)
+	return &images, nil
+}
+
+func (oo *OnuImageStatus) requestOnuImageAttributes(ctx context.Context, imageID uint16, image *voltha.OnuImage) error {
+	oo.mutexPLastTxMeInstance.Lock()
+	meInstance, err := oo.pOmciCC.SendGetMe(log.WithSpanFromContext(context.TODO(), ctx), me.SoftwareImageClassID,
+		imageID, oo.requestedAttributes, oo.pDeviceHandler.GetOmciTimeout(), true, oo.respChannel)
+	if err != nil {
+		oo.mutexPLastTxMeInstance.Unlock()
+		logger.Errorw(ctx, "can't send omci request to get data for image id", log.Fields{"image-id": imageID, "device-id": oo.deviceID})
+		return fmt.Errorf("can't-send-omci-request-to-get-data-for-image-id-%d", imageID)
+	}
+	oo.pLastTxMeInstance = meInstance
+	oo.mutexPLastTxMeInstance.Unlock()
+
+	if err = oo.waitForGetOnuImageStatus(ctx, image); err != nil {
+		logger.Errorw(ctx, err.Error(), log.Fields{"device-id": oo.deviceID})
+		return err
+	}
+	return nil
+}
+
+func (oo *OnuImageStatus) waitForGetOnuImageStatus(ctx context.Context, image *voltha.OnuImage) error {
+	oo.setWaitingForResp(true)
+	select {
+	// maybe be also some outside cancel (but no context modeled for the moment ...)
+	case <-ctx.Done():
+		logger.Errorw(ctx, "waitForGetOnuImageStatus context done", log.Fields{"device-id": oo.deviceID})
+		oo.setWaitingForResp(false)
+		return fmt.Errorf("wait-for-image-status-context-done")
+	case <-time.After(oo.pOmciCC.GetMaxOmciTimeoutWithRetries() * time.Second):
+		logger.Errorw(ctx, "waitForGetOnuImageStatus timeout", log.Fields{"device-id": oo.deviceID})
+		oo.setWaitingForResp(false)
+		return fmt.Errorf("wait-for-image-status-timeout")
+	case message, ok := <-oo.respChannel:
+		if !ok {
+			logger.Errorw(ctx, "waitForGetOnuImageStatus response error", log.Fields{"device-id": oo.deviceID})
+			oo.setWaitingForResp(false)
+			return fmt.Errorf("wait-for-image-status-response-error")
+		}
+		switch message.Type {
+		case cmn.OMCI:
+			msg, _ := message.Data.(cmn.OmciMessage)
+			oo.setWaitingForResp(false)
+			return oo.processGetOnuImageStatusResp(ctx, msg, image)
+		case cmn.TestMsg:
+			msg, _ := message.Data.(cmn.TestMessage)
+			if msg.TestMessageVal == cmn.AbortMessageProcessing {
+				logger.Info(ctx, "waitForGetOnuImageStatus abort msg received", log.Fields{"device-id": oo.deviceID})
+				oo.setWaitingForResp(false)
+				return fmt.Errorf("wait-for-image-status-abort-msg-received")
+			}
+		default:
+			logger.Errorw(ctx, "waitForGetOnuImageStatus wrong msg type received", log.Fields{"msgType": message.Type, "device-id": oo.deviceID})
+			oo.setWaitingForResp(false)
+			return fmt.Errorf("wait-for-image-status-response-error")
+		}
+	}
+	logger.Errorw(ctx, "waitForGetOnuImageStatus processing error", log.Fields{"device-id": oo.deviceID})
+	oo.setWaitingForResp(false)
+	return fmt.Errorf("wait-for-image-status-processing-error")
+
+}
+
+func (oo *OnuImageStatus) processGetOnuImageStatusResp(ctx context.Context, msg cmn.OmciMessage, image *voltha.OnuImage) error {
+	if msg.OmciMsg.MessageType != omci.GetResponseType {
+		logger.Errorw(ctx, "processGetOnuImageStatusResp wrong response type received", log.Fields{"respType": msg.OmciMsg.MessageType, "device-id": oo.deviceID})
+		return fmt.Errorf("process-image-status-response-error")
+	}
+	msgLayer := (*msg.OmciPacket).Layer(omci.LayerTypeGetResponse)
+	if msgLayer == nil {
+		logger.Errorw(ctx, "processGetOnuImageStatusResp omci Msg layer not found", log.Fields{"device-id": oo.deviceID})
+		return fmt.Errorf("process-image-status-response-error")
+	}
+	msgObj, msgOk := msgLayer.(*omci.GetResponse)
+	if !msgOk {
+		logger.Errorw(ctx, "processGetOnuImageStatusResp omci msgObj layer could not be found", log.Fields{"device-id": oo.deviceID})
+		return fmt.Errorf("process-image-status-response-error")
+	}
+	oo.mutexPLastTxMeInstance.RLock()
+	if oo.pLastTxMeInstance != nil {
+		if msgObj.EntityClass == oo.pLastTxMeInstance.GetClassID() &&
+			msgObj.EntityInstance == oo.pLastTxMeInstance.GetEntityID() {
+			oo.mutexPLastTxMeInstance.RUnlock()
+			if err := oo.processAttributesReceived(ctx, msgObj, image); err != nil {
+				logger.Errorw(ctx, err.Error(), log.Fields{"device-id": oo.deviceID})
+				return err
+			}
+			return nil
+		}
+		oo.mutexPLastTxMeInstance.RUnlock()
+		logger.Errorw(ctx, "processGetOnuImageStatusResp wrong MeInstance received", log.Fields{"device-id": oo.deviceID})
+		return fmt.Errorf("process-image-status-response-error")
+	}
+	oo.mutexPLastTxMeInstance.RUnlock()
+	logger.Errorw(ctx, "processGetOnuImageStatusResp pLastTxMeInstance is nil", log.Fields{"device-id": oo.deviceID})
+	return fmt.Errorf("process-image-status-response-error")
+}
+
+func (oo *OnuImageStatus) processAttributesReceived(ctx context.Context, msgObj *omci.GetResponse, image *voltha.OnuImage) error {
+	meAttributes := msgObj.Attributes
+	logger.Debugw(ctx, "processAttributesReceived", log.Fields{"attributes": meAttributes, "device-id": oo.deviceID})
+
+	for k := range oo.requestedAttributes {
+
+		if msgObj.Result != me.Success && k != cImgProductCode && k != cImgImageHash {
+			logger.Errorw(ctx, "processAttributesReceived retrieval of mandatory attributes failed",
+				log.Fields{"device-id": oo.deviceID})
+			return fmt.Errorf("process-image-status-response-error")
+		}
+		switch k {
+
+		// mandatory attributes
+		case cImgIsCommitted:
+			if meAttributes[cImgIsCommitted].(uint8) == cmn.SwIsCommitted {
+				image.IsCommited = true
+			} else {
+				image.IsCommited = false
+			}
+		case cImgIsActive:
+			if meAttributes[cImgIsActive].(uint8) == cmn.SwIsActive {
+				image.IsActive = true
+			} else {
+				image.IsActive = false
+			}
+		case cImgIsValid:
+			if meAttributes[cImgIsValid].(uint8) == cmn.SwIsValid {
+				image.IsValid = true
+			} else {
+				image.IsValid = false
+			}
+		case cImgVersion:
+			image.Version = cmn.TrimStringFromMeOctet(meAttributes[cImgVersion])
+
+		// optional attributes
+		case cImgProductCode:
+			if msgObj.Result == me.Success {
+				image.ProductCode = cmn.TrimStringFromMeOctet(meAttributes[cImgProductCode])
+			} else {
+				sResult := msgObj.Result.String()
+				logger.Infow(ctx, "processAttributesReceived - ProductCode",
+					log.Fields{"result": sResult, "unsupported attribute mask": msgObj.UnsupportedAttributeMask, "device-id": oo.deviceID})
+				image.ProductCode = cResponse + sResult
+			}
+		case cImgImageHash:
+			if msgObj.Result == me.Success {
+				bytes, _ := me.InterfaceToOctets(meAttributes[cImgImageHash])
+				image.Hash = hex.EncodeToString(bytes)
+			} else {
+				sResult := msgObj.Result.String()
+				logger.Infow(ctx, "processAttributesReceived - ImageHash",
+					log.Fields{"result": sResult, "unsupported attribute mask": msgObj.UnsupportedAttributeMask, "device-id": oo.deviceID})
+				image.Hash = cResponse + sResult
+			}
+		}
+	}
+	return nil
+}
+
+func (oo *OnuImageStatus) updateOnuSwImageIndications(ctx context.Context, images *voltha.OnuImages) {
+
+	oo.pDevEntry.LockMutexOnuSwImageIndications()
+	onuSwImageIndications := oo.pDevEntry.GetOnuSwImageIndications()
+	validActiveImageFound := false
+	for i := cmn.FirstSwImageMeID; i <= cmn.SecondSwImageMeID; i++ {
+		if images.Items[i].IsActive && images.Items[i].IsValid {
+			onuSwImageIndications.ActiveEntityEntry.EntityID = uint16(i)
+			onuSwImageIndications.ActiveEntityEntry.Valid = images.Items[i].IsValid
+			onuSwImageIndications.ActiveEntityEntry.Version = images.Items[i].Version
+			if images.Items[i].IsCommited {
+				onuSwImageIndications.ActiveEntityEntry.IsCommitted = cmn.SwIsCommitted
+			} else {
+				onuSwImageIndications.ActiveEntityEntry.IsCommitted = cmn.SwIsUncommitted
+			}
+			validActiveImageFound = true
+			break
+		}
+	}
+	if !validActiveImageFound {
+		onuSwImageIndications.ActiveEntityEntry.Valid = false
+	}
+	validInactiveImageFound := false
+	for i := cmn.FirstSwImageMeID; i <= cmn.SecondSwImageMeID; i++ {
+		if !images.Items[i].IsActive && images.Items[i].IsValid {
+			onuSwImageIndications.InActiveEntityEntry.EntityID = uint16(i)
+			onuSwImageIndications.InActiveEntityEntry.Valid = images.Items[i].IsValid
+			onuSwImageIndications.InActiveEntityEntry.Version = images.Items[i].Version
+			if images.Items[i].IsCommited {
+				onuSwImageIndications.InActiveEntityEntry.IsCommitted = cmn.SwIsCommitted
+			} else {
+				onuSwImageIndications.InActiveEntityEntry.IsCommitted = cmn.SwIsUncommitted
+			}
+			validInactiveImageFound = true
+			break
+		}
+	}
+	if !validInactiveImageFound {
+		onuSwImageIndications.InActiveEntityEntry.Valid = false
+	}
+	oo.pDevEntry.SetOnuSwImageIndications(onuSwImageIndications)
+	oo.pDevEntry.UnlockMutexOnuSwImageIndications()
+}
+
+func (oo *OnuImageStatus) updateOnuSwImagePersistentData(ctx context.Context) {
+
+	activeImageVersion := oo.pDevEntry.GetActiveImageVersion(ctx)
+	oo.pDevEntry.LockMutexPersOnuConfig()
+	persActiveSwVersion := oo.pDevEntry.GetPersActiveSwVersion()
+	if persActiveSwVersion != activeImageVersion {
+		logger.Infow(ctx, "Active SW version has been changed at ONU - update persistent data",
+			log.Fields{"old version": persActiveSwVersion,
+				"new version": activeImageVersion, "device-id": oo.deviceID})
+		oo.pDevEntry.SetPersActiveSwVersion(activeImageVersion)
+		oo.pDevEntry.UnlockMutexPersOnuConfig()
+		if err := oo.pDeviceHandler.StorePersistentData(ctx); err != nil {
+			logger.Warnw(ctx, "store persistent data error - continue for now as there will be additional write attempts",
+				log.Fields{"device-id": oo.deviceID, "err": err})
+		}
+		return
+	}
+	oo.pDevEntry.UnlockMutexPersOnuConfig()
+}
+
+func (oo *OnuImageStatus) setWaitingForResp(value bool) {
+	oo.mutexWaitingForResp.Lock()
+	oo.waitingForResp = value
+	oo.mutexWaitingForResp.Unlock()
+}
+
+func (oo *OnuImageStatus) isWaitingForResp() bool {
+	oo.mutexWaitingForResp.RLock()
+	value := oo.waitingForResp
+	oo.mutexWaitingForResp.RUnlock()
+	return value
+}
+
+//CancelProcessing ensures that interrupted processing is canceled while waiting for a response
+func (oo *OnuImageStatus) CancelProcessing(ctx context.Context) {
+	if oo.isWaitingForResp() {
+		abortMsg := cmn.Message{
+			Type: cmn.TestMsg,
+			Data: cmn.TestMessage{
+				TestMessageVal: cmn.AbortMessageProcessing,
+			},
+		}
+		oo.respChannel <- abortMsg
+	}
+}