Improving logs

Change-Id: I75021b47851b3af946dc3a9b41a516934b4b2e3a
diff --git a/go.mod b/go.mod
new file mode 100644
index 0000000..6ea046e
--- /dev/null
+++ b/go.mod
@@ -0,0 +1,5 @@
+module gerrit.opencord.org/omci-sim
+
+go 1.12
+
+require github.com/sirupsen/logrus v1.4.2
diff --git a/go.sum b/go.sum
new file mode 100644
index 0000000..400b0b0
--- /dev/null
+++ b/go.sum
@@ -0,0 +1,7 @@
+github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38=
+github.com/konsorten/go-windows-terminal-sequences v1.0.1/go.mod h1:T0+1ngSBFLxvqU3pZ+m/2kptfBszLMUkC4ZK/EgS/cQ=
+github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4=
+github.com/sirupsen/logrus v1.4.2/go.mod h1:tLMulIdttU9McNUspp0xgXVQah82FyeX6MwdIuYE2rE=
+github.com/stretchr/objx v0.1.1/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME=
+github.com/stretchr/testify v1.2.2/go.mod h1:a8OnRcib4nhh0OaRAV+Yts87kKdq0PP7pXfy6kDkUVs=
+golang.org/x/sys v0.0.0-20190422165155-953cdadca894/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
diff --git a/omci_common.go b/omci_common.go
index 223fe0e..55c3b02 100644
--- a/omci_common.go
+++ b/omci_common.go
@@ -18,7 +18,7 @@
 
 import (
 	"fmt"
-	"log"
+	log "github.com/sirupsen/logrus"
 )
 
 type OmciError struct {
@@ -38,7 +38,10 @@
 }
 
 func GetAttributes(class OmciClass, content OmciContent, key OnuKey, pkt []byte) []byte {
-	log.Printf("GetAttributes() invoked with onu key: %+v\n", key)
+	log.WithFields(log.Fields{
+		"IntfId": key.IntfId,
+		"OnuId": key.OnuId,
+	}).Tracef("GetAttributes() invoked")
 
 	switch class {
 	case ANIG:
@@ -53,7 +56,11 @@
 	default:
 		// For unimplemented MEs, just fill in the attribute mask and return 0 values for the requested attributes
 		// TODO implement Get for unimplemented MEs as well
-		log.Printf("Unimplemeted GetAttributes for ME Class: %v " +
+		log.WithFields(log.Fields{
+			"IntfId": key.IntfId,
+			"OnuId": key.OnuId,
+			"class": class,
+		}).Warnf("Unimplemeted GetAttributes for ME Class: %v " +
 		    "Filling with zero value for the requested attributes", class)
 		AttributesMask := getAttributeMask(content)
 		pkt[8] = 0x00 // Command Processed Successfully
@@ -66,6 +73,9 @@
 
 func getAttributeMask(content OmciContent) int {
 	// mask is present in pkt[8] and pkt[9]
-	log.Printf("GetAttributeMask() invoked\n content[0] , content[1]: %+v, %+v", content[0], content[1])
+	log.WithFields(log.Fields{
+		"content[0]": content[0],
+		"content[1]": content[1],
+	}).Tracef("GetAttributeMask() invoked")
 	return (int(content[0]) << 8) | int(content[1])
 }
diff --git a/omci_defs.go b/omci_defs.go
index e278d9b..dfa0f52 100644
--- a/omci_defs.go
+++ b/omci_defs.go
@@ -19,7 +19,8 @@
 	"bytes"
 	"encoding/binary"
 	"errors"
-	"log"
+	"fmt"
+	log "github.com/sirupsen/logrus"
 )
 
 //
@@ -29,6 +30,60 @@
 // OmciMsgType represents a OMCI message-type
 type OmciMsgType byte
 
+func (t OmciMsgType) PrettyPrint() string {
+	switch t {
+	case Create:
+		return "Create"
+	case Delete:
+		return "Delete"
+	case Set:
+		return "Set"
+	case Get:
+		return "Get"
+	case GetAllAlarms:
+		return "GetAllAlarms"
+	case GetAllAlarmsNext:
+		return "GetAllAlarmsNext"
+	case MibUpload:
+		return "MibUpload"
+	case MibUploadNext:
+		return "MibUploadNext"
+	case MibReset:
+		return "MibReset"
+	case AlarmNotification:
+		return "AlarmNotification"
+	case AttributeValueChange:
+		return "AttributeValueChange"
+	case Test:
+		return "Test"
+	case StartSoftwareDownload:
+		return "StartSoftwareDownload"
+	case DownloadSection:
+		return "DownloadSection"
+	case EndSoftwareDownload:
+		return "EndSoftwareDownload"
+	case ActivateSoftware:
+		return "ActivateSoftware"
+	case CommitSoftware:
+		return "CommitSoftware"
+	case SynchronizeTime:
+		return "SynchronizeTime"
+	case Reboot:
+		return "Reboot"
+	case GetNext:
+		return "GetNext"
+	case TestResult:
+		return "TestResult"
+	case GetCurrentData:
+		return "GetCurrentData"
+	case SetTable:
+		return "SetTable"
+	default:
+		log.Warnf("Cant't convert state %v to string", t)
+		return string(t)
+	}
+}
+
 const (
 	// Message Types
 	_                                 = iota
@@ -90,8 +145,11 @@
 	r := bytes.NewReader(pkt)
 
 	if err := binary.Read(r, binary.BigEndian, &m); err != nil {
-		log.Printf("binary.Read failed: %s", err)
-		return 0, 0, 0, 0, 0, OmciContent{}, errors.New("binary.Read failed")
+		log.WithFields(log.Fields{
+			"Packet": pkt,
+			"omciMsg": fmt.Sprintf("%x", pkt),
+		}).Errorf("Failed to read packet: %s", err)
+		return 0, 0, 0, 0, 0, OmciContent{}, errors.New("Failed to read packet")
 	}
 	/*    Message Type = Set
 	      0... .... = Destination Bit: 0x0
@@ -99,7 +157,15 @@
 	      ..0. .... = Acknowledgement: 0x0
 	      ...0 1000 = Message Type: Set (8)
 	*/
-	log.Printf("OmciRun - TransactionId: %d MessageType: %d, ME Class: %d, ME Instance: %d, Content: %x",
-		m.TransactionId, m.MessageType&0x1F, m.MessageId.Class, m.MessageId.Instance, m.Content)
+
+	log.WithFields(log.Fields{
+		"TransactionId": m.TransactionId,
+		"MessageType": m.MessageType.PrettyPrint(),
+		"MeClass": m.MessageId.Class,
+		"MeInstance": m.MessageId.Instance,
+		"Conent": m.Content,
+		"Packet": pkt,
+	}).Tracef("Parsing OMCI Packet")
+
 	return m.TransactionId, m.DeviceId, m.MessageType & 0x1F, m.MessageId.Class, m.MessageId.Instance, m.Content, nil
 }
diff --git a/omci_handlers.go b/omci_handlers.go
index 1ebaaea..ec7f712 100644
--- a/omci_handlers.go
+++ b/omci_handlers.go
@@ -20,7 +20,7 @@
 	"encoding/binary"
 	"errors"
 	"fmt"
-	"log"
+	log "github.com/sirupsen/logrus"
 )
 
 type OmciMsgHandler func(class OmciClass, content OmciContent, key OnuKey) ([]byte, error)
@@ -42,9 +42,15 @@
 func mibReset(class OmciClass, content OmciContent, key OnuKey) ([]byte, error) {
 	var pkt []byte
 
-	log.Printf("%v - Omci MibReset", key)
+	log.WithFields(log.Fields{
+		"IntfId": key.IntfId,
+		"OnuId": key.OnuId,
+	}).Tracef("Omci MibReset")
 	if state, ok := OnuOmciStateMap[key]; ok {
-		log.Printf("%v - Reseting OnuOmciState", key)
+		log.WithFields(log.Fields{
+		"IntfId": key.IntfId,
+		"OnuId": key.OnuId,
+	}).Tracef("Reseting OnuOmciState")
 		state.ResetOnuOmciState()
 	}
 
@@ -61,7 +67,10 @@
 func mibUpload(class OmciClass, content OmciContent, key OnuKey) ([]byte, error) {
 	var pkt []byte
 
-	log.Printf("%v - Omci MibUpload", key)
+	log.WithFields(log.Fields{
+		"IntfId": key.IntfId,
+		"OnuId": key.OnuId,
+	}).Tracef("Omci MibUpload")
 
 	pkt = []byte{
 		0x00, 0x00, 0x00, 0x00, 0x00, 0x02, 0x00, 0x00,
@@ -84,7 +93,11 @@
 
 	// commandNumber is the "Command number" attribute received in "MIB Upload Next" OMCI message
 	commandNumber := (uint16(content[1])) | (uint16(content[0])<<8)
-	log.Printf("%v - Omci MibUploadNext %d", key, commandNumber)
+	log.WithFields(log.Fields{
+		"IntfId": key.IntfId,
+		"OnuId": key.OnuId,
+		"CommandNumber": commandNumber,
+	}).Tracef("Omci MibUploadNext")
 
 	switch commandNumber {
 	case 0:
@@ -235,7 +248,7 @@
 	     218, 222, 226, 230, 234, 238, 242, 246,
 	     250, 254, 258, 262, 266, 270, 274, 278:
 		// Prior-Q with mask downstream
-		log.Println("Mib-upload for prior-q with mask")
+		log.Tracef("Mib-upload for prior-q with mask")
 		// For downstream PQ, pkt[10] is 0x00
 		// So the instanceId will be like 0x0001, 0x0002,... etc
 		pkt = []byte{
@@ -278,7 +291,7 @@
 
 		// Only for verification. To be removed
 		if state.tcontPointer > state.tcontInstance {
-			log.Println("Error: Invalid TcontPointer")
+			log.Tracef("Error: Invalid TcontPointer")
 			break
 		}
 
@@ -363,7 +376,7 @@
 
 	default:
 		state.extraMibUploadCtr++
-		errstr := fmt.Sprintf("%v - Invalid MibUpload request: %d, extras: %d", key, state.mibUploadCtr, state.extraMibUploadCtr)
+		errstr := fmt.Sprintf("%v - Invalid MibUpload request: %d, extras: %d", key, state.mibUploadCtr, state)
 		return nil, errors.New(errstr)
 	}
 
@@ -382,7 +395,10 @@
 		0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00,
 		0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00}
 
-	log.Printf("%v - Omci Set", key)
+	log.WithFields(log.Fields{
+		"IntfId": key.IntfId,
+		"OnuId": key.OnuId,
+	}).Tracef("Omci Set")
 
 	return pkt, nil
 }
@@ -392,11 +408,17 @@
 
 	if class == GEMPortNetworkCTP {
 		if onuOmciState, ok := OnuOmciStateMap[key]; !ok {
-			log.Printf("%v - ONU Key Error", key)
+			log.WithFields(log.Fields{
+				"IntfId": key.IntfId,
+				"OnuId": key.OnuId,
+			}).Tracef("ONU Key Error")
 			return nil, errors.New("ONU Key Error")
 		} else {
 			onuOmciState.gemPortId = binary.BigEndian.Uint16(content[:2])
-			log.Printf("%v - Gem Port Id %d", key, onuOmciState.gemPortId)
+			log.WithFields(log.Fields{
+				"IntfId": key.IntfId,
+				"OnuId": key.OnuId,
+			}).Tracef("Gem Port Id %d", key, onuOmciState)
 			// FIXME
 			OnuOmciStateMap[key].state = DONE
 		}
@@ -410,7 +432,10 @@
 		0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00,
 		0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00}
 
-	log.Printf("%v - Omci Create", key)
+	log.WithFields(log.Fields{
+		"IntfId": key.IntfId,
+		"OnuId": key.OnuId,
+	}).Tracef("Omci Create")
 
 	return pkt, nil
 }
@@ -428,7 +453,10 @@
 
 	pkt = GetAttributes(class, content, key, pkt)
 
-	log.Printf("%v - Omci Get", key)
+	log.WithFields(log.Fields{
+		"IntfId": key.IntfId,
+		"OnuId": key.OnuId,
+	}).Tracef("Omci Get")
 	return pkt, nil
 }
 
@@ -443,7 +471,10 @@
 		0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00,
 		0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00}
 
-	log.Printf("%v - Omci GetAllAlarms", key)
+	log.WithFields(log.Fields{
+		"IntfId": key.IntfId,
+		"OnuId": key.OnuId,
+	}).Tracef("Omci GetAllAlarms")
 
 	return pkt, nil
 }
@@ -459,7 +490,10 @@
 		0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00,
 		0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00}
 
-	log.Printf("%v - Omci syncTime", key)
+	log.WithFields(log.Fields{
+		"IntfId": key.IntfId,
+		"OnuId": key.OnuId,
+	}).Tracef("Omci syncTime")
 
 	return pkt, nil
 }
@@ -475,7 +509,10 @@
 		0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00,
 		0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00}
 
-	log.Printf("%v - Omci GetAllAlarmsNext", key)
+	log.WithFields(log.Fields{
+		"IntfId": key.IntfId,
+		"OnuId": key.OnuId,
+	}).Tracef("Omci GetAllAlarmsNext")
 
 	return pkt, nil
 }
@@ -491,7 +528,10 @@
 		0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00,
 		0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00}
 
-	log.Printf("%v - Omci Delete", key)
+	log.WithFields(log.Fields{
+		"IntfId": key.IntfId,
+		"OnuId": key.OnuId,
+	}).Tracef("Omci Delete")
 
 	return pkt, nil
 }
@@ -506,7 +546,10 @@
 		0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00,
 		0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00}
 
-	log.Printf("%v - Omci Reboot", key)
+	log.WithFields(log.Fields{
+		"IntfId": key.IntfId,
+		"OnuId": key.OnuId,
+	}).Tracef("Omci Reboot")
 	return pkt, nil
 }
 
diff --git a/omci_sim.go b/omci_sim.go
index 50335f2..5980db1 100644
--- a/omci_sim.go
+++ b/omci_sim.go
@@ -16,20 +16,33 @@
 
 package core
 
-import "log"
-
+import (
+	"fmt"
+	log "github.com/sirupsen/logrus"
+)
 
 func OmciSim(intfId uint32, onuId uint32, request []byte) ([]byte, error) {
 	var resp []byte
 
 	transactionId, deviceId, msgType, class, instance, content, err := ParsePkt(request)
 	if err != nil {
-		log.Printf("ONU {intfid:%d, onuid:%d} - Cannot parse omci msg", intfId, onuId)
-		return resp, &OmciError{"Cannot parse omci msg"}
+		log.WithFields(log.Fields{
+			"IntfId": intfId,
+			"OnuId": onuId,
+		}).Errorf("Cannot parse OMCI msg")
+		return resp, &OmciError{"Cannot parse OMCI msg"}
 	}
 
-	log.Printf("ONU {intfid:%d, onuid:%d} - OmciRun - transactionId: %d msgType: %d, ME Class: %d, ME Instance: %d",
-		intfId, onuId, transactionId, msgType, class, instance)
+	log.WithFields(log.Fields{
+		"IntfId": intfId,
+		"OnuId": onuId,
+		"TransactionId": transactionId,
+		"MessageType": msgType.PrettyPrint(),
+		"MeClass": class,
+		"MeInstance": instance,
+		//"Conent": content,
+		"omciMsg": fmt.Sprintf("%x", content),
+	}).Debugf("Processing OMCI pakcet")
 
 	key := OnuKey{intfId, onuId}
 	if _, ok := OnuOmciStateMap[key]; !ok {
@@ -37,13 +50,21 @@
 	}
 
 	if _, ok := Handlers[msgType]; !ok {
-		log.Printf("ONU {intfid:%d, onuid:%d} - Ignore omci msg (msgType %d not handled)", intfId, onuId, msgType)
+		log.WithFields(log.Fields{
+			"IntfId": intfId,
+			"OnuId": onuId,
+			"msgType": msgType,
+		}).Errorf("Ignoring omci msg (msgType %d not handled)", msgType)
 		return resp, &OmciError{"Unimplemented omci msg"}
 	}
 
 	resp, err = Handlers[msgType](class, content, key)
 	if err != nil {
-		log.Printf("ONU {intfid:%d, onuid:%d} - Unable to send a successful response, error:%s", intfId, onuId, err)
+		log.WithFields(log.Fields{
+			"IntfId": intfId,
+			"OnuId": onuId,
+			"msgType": msgType,
+		}).Errorf("Unable to send a successful response, error: %s", err)
 		return resp, nil
 	}
 
@@ -76,7 +97,12 @@
 		}
 	}
 
-	log.Printf("OMCI-SIM Response %+x\n", resp)
+	log.WithFields(log.Fields{
+		"IntfId": intfId,
+		"OnuId": onuId,
+		"msgType": msgType.PrettyPrint(),
+		"omciMsg": fmt.Sprintf("%x", resp),
+	}).Debugf("OMCI-SIM Response")
 
 	return resp, nil
-}
+}
\ No newline at end of file
diff --git a/omci_state.go b/omci_state.go
index 6af433f..34d5b5e 100644
--- a/omci_state.go
+++ b/omci_state.go
@@ -18,6 +18,7 @@
 import (
 	"errors"
 	"fmt"
+	log "github.com/sirupsen/logrus"
 )
 
 type OnuOmciState struct {
@@ -78,3 +79,8 @@
 	errmsg := fmt.Sprintf("ONU {intfid:%d, onuid:%d} - Failed to find a key in OnuOmciStateMap", intfId, onuId)
 	return 0, errors.New(errmsg)
 }
+
+func CheckIsTeo() string {
+	log.Warn("It's TEO!")
+	return "It's TEO!"
+}