[SEBA-342] Log cleanup
Change-Id: I6db4a6dd376d3237af449232f015d1782af174c4
diff --git a/core/core_server.go b/core/core_server.go
index 55166dc..48f0ed8 100644
--- a/core/core_server.go
+++ b/core/core_server.go
@@ -98,7 +98,7 @@
}
nnni := s.Olt.NumNniIntf
- logger.Info("OLT ID: %d was retrieved.\n", s.Olt.ID)
+ logger.Info("OLT ID: %d was retrieved.", s.Olt.ID)
for intfid := nnni; intfid < npon+nnni; intfid++ {
s.Onumap[intfid] = device.NewOnus(oltid, intfid, nonus, nnni)
}
@@ -204,23 +204,23 @@
}
olt.OperState = "up"
*olt.InternalState = device.OLT_UP
- logger.Info("OLT %s sent OltInd.\n", olt.Name)
+ logger.Info("OLT %s sent OltInd.", olt.Name)
// OLT sends Interface Indication to Adapter
if err := sendIntfInd(stream, olt); err != nil {
- logger.Error("Fail to sendIntfInd: %v\n", err)
+ logger.Error("Fail to sendIntfInd: %v", err)
return err
}
- logger.Info("OLT %s sent IntfInd.\n", olt.Name)
+ logger.Info("OLT %s sent IntfInd.", olt.Name)
// OLT sends Operation Indication to Adapter after activating each interface
//time.Sleep(IF_UP_TIME * time.Second)
*olt.InternalState = device.PONIF_UP
if err := sendOperInd(stream, olt); err != nil {
- logger.Error("Fail to sendOperInd: %v\n", err)
+ logger.Error("Fail to sendOperInd: %v", err)
return err
}
- logger.Info("OLT %s sent OperInd.\n", olt.Name)
+ logger.Info("OLT %s sent OperInd.", olt.Name)
// OLT sends ONU Discover Indication to Adapter after ONU discovery
for intfid, _ := range s.Onumap {
@@ -229,7 +229,7 @@
for intfid, _ := range s.Onumap {
sendOnuDiscInd(stream, s.Onumap[intfid])
- logger.Info("OLT id:%d sent ONUDiscInd.\n", olt.ID)
+ logger.Info("OLT id:%d sent ONUDiscInd.", olt.ID)
}
// OLT Sends OnuInd after waiting all of those ONUs up
@@ -242,7 +242,7 @@
for intfid, _ := range s.Onumap {
sendOnuInd(stream, s.Onumap[intfid], s.IndInterval)
- logger.Info("OLT id:%d sent ONUInd.\n", olt.ID)
+ logger.Info("OLT id:%d sent ONUInd.", olt.ID)
}
return nil
}
@@ -327,7 +327,7 @@
onuid := onu.OnuID
ioinfo, err := s.identifyUniIoinfo("inside", intfid, onuid)
if err != nil {
- logger.Error("Fail to identifyUniIoinfo (onuid: %d): %v\n", onuid, err)
+ utils.LoggerWithOnu(onu).Error("Fail to identifyUniIoinfo (onuid: %d): %v", onuid, err)
return err
}
uhandler := ioinfo.handler
@@ -350,7 +350,7 @@
case unipkt := <-unichannel:
logger.Debug("Received packet in grpc Server from UNI.")
if unipkt.Info == nil || unipkt.Info.iotype != "uni" {
- logger.Info("WARNING: This packet does not come from UNI ")
+ logger.Debug("WARNING: This packet does not come from UNI ")
continue
}
@@ -361,57 +361,39 @@
layerEth := pkt.Layer(layers.LayerTypeEthernet)
le, _ := layerEth.(*layers.Ethernet)
ethtype := le.EthernetType
- onu, _ := getOnuByID(s.Onumap, onuid)
+ onu, _ := s.GetOnuByID(onuid)
if ethtype == 0x888e {
- logger.WithFields(log.Fields{
- "serial_number": utils.OnuToSn(onu),
- "gemId": gemid,
- "interfaceId": intfid,
- "onuId": onuid,
- }).Debug("Received upstream packet is EAPOL.")
+ utils.LoggerWithOnu(onu).WithFields(log.Fields{
+ "gemId": gemid,
+ }).Info("Received upstream packet is EAPOL.")
} else if layerDHCP := pkt.Layer(layers.LayerTypeDHCPv4); layerDHCP != nil {
- logger.WithFields(log.Fields{
- "serial_number": utils.OnuToSn(onu),
- "gemId": gemid,
- "interfaceId": intfid,
- "onuId": onuid,
- }).Debug("Received upstream packet is DHCP.")
+ utils.LoggerWithOnu(onu).WithFields(log.Fields{
+ "gemId": gemid,
+ }).Info("Received upstream packet is DHCP.")
//C-TAG
sn := convB2S(onu.SerialNumber.VendorSpecific)
if ctag, ok := s.CtagMap[sn]; ok == true {
tagpkt, err := PushVLAN(pkt, uint16(ctag))
if err != nil {
- logger.WithFields(log.Fields{
- "serial_number": utils.OnuToSn(onu),
- "gemId": gemid,
- "interfaceId": intfid,
- "onuId": onuid,
+ utils.LoggerWithOnu(onu).WithFields(log.Fields{
+ "gemId": gemid,
}).Error("Fail to tag C-tag")
} else {
pkt = tagpkt
}
} else {
- logger.WithFields(log.Fields{
- "serial_number": utils.OnuToSn(onu),
- "gemId": gemid,
- "interfaceId": intfid,
- "onuId": onuid,
- "sn": sn,
- "cTagMap": s.CtagMap,
+ utils.LoggerWithOnu(onu).WithFields(log.Fields{
+ "gemId": gemid,
+ "cTagMap": s.CtagMap,
}).Error("Could not find onuid in CtagMap", onuid, sn, s.CtagMap)
}
} else {
continue
}
- logger.WithFields(log.Fields{
- "serial_number": utils.OnuToSn(onu),
- "gemId": gemid,
- "interfaceId": intfid,
- "onuId": onuid,
- }).Debug("sendPktInd")
+ utils.LoggerWithOnu(onu).Info("sendPktInd - UNI Packet")
data = &openolt.Indication_PktInd{PktInd: &openolt.PacketIndication{IntfType: "pon", IntfId: intfid, GemportId: gemid, Pkt: pkt.Data()}}
if err := stream.Send(&openolt.Indication{Data: data}); err != nil {
logger.Error("Fail to send PktInd indication.", err)
@@ -420,19 +402,16 @@
case nnipkt := <-nnichannel:
if nnipkt.Info == nil || nnipkt.Info.iotype != "nni" {
- logger.Info("WARNING: This packet does not come from NNI ")
+ logger.Debug("WARNING: This packet does not come from NNI ")
continue
}
onuid := nnipkt.Info.onuid
onu, _ := getOnuByID(s.Onumap, onuid)
- logger.Debug("Received packet in grpc Server from NNI.")
+ utils.LoggerWithOnu(onu).Info("Received packet in grpc Server from NNI.")
intfid := nnipkt.Info.intfid
pkt := nnipkt.Pkt
- logger.WithFields(log.Fields{
- "interfaceId": intfid,
- "serial_number": utils.OnuToSn(onu),
- }).Info("sendPktInd")
+ utils.LoggerWithOnu(onu).Info("sendPktInd - NNI Packet")
data = &openolt.Indication_PktInd{PktInd: &openolt.PacketIndication{IntfType: "nni", IntfId: intfid, Pkt: pkt.Data()}}
if err := stream.Send(&openolt.Indication{Data: data}); err != nil {
logger.Error("Fail to send PktInd indication.", err)
@@ -453,15 +432,15 @@
func (s *Server) onuPacketOut(intfid uint32, onuid uint32, rawpkt gopacket.Packet) error {
layerEth := rawpkt.Layer(layers.LayerTypeEthernet)
+ onu, _ := s.GetOnuByID(onuid)
+
if layerEth != nil {
pkt, _ := layerEth.(*layers.Ethernet)
ethtype := pkt.EthernetType
if ethtype == 0x888e {
- logger.Debug("Received downstream packet is EAPOL.")
- //logger.Println(rawpkt.Dump())
+ utils.LoggerWithOnu(onu).Info("Received downstream packet is EAPOL.")
} else if layerDHCP := rawpkt.Layer(layers.LayerTypeDHCPv4); layerDHCP != nil {
- logger.Debug("Received downstream packet is DHCP.")
- //logger.Println(rawpkt.Dump())
+ utils.LoggerWithOnu(onu).Info("Received downstream packet is DHCP.")
rawpkt, _, _ = PopVLAN(rawpkt)
rawpkt, _, _ = PopVLAN(rawpkt)
} else {
@@ -525,6 +504,10 @@
return nil, err
}
+func (s *Server) GetOnuByID(onuid uint32) (*device.Onu, error) {
+ return getOnuByID(s.Onumap, onuid)
+}
+
func getOnuByID(onumap map[uint32][]*device.Onu, onuid uint32) (*device.Onu, error) {
for _, onus := range onumap {
for _, onu := range onus {
@@ -534,7 +517,10 @@
}
}
err := errors.New("No matched OnuID is found ")
- logger.Error("%s", err)
+ logger.WithFields(log.Fields{
+ "onumap": onumap,
+ "onuid": onuid,
+ }).Error(err)
return nil, err
}
diff --git a/core/grpc_service.go b/core/grpc_service.go
index 75d8845..61096f4 100644
--- a/core/grpc_service.go
+++ b/core/grpc_service.go
@@ -20,131 +20,134 @@
"net"
"gerrit.opencord.org/voltha-bbsim/common/logger"
+ "gerrit.opencord.org/voltha-bbsim/common/utils"
"gerrit.opencord.org/voltha-bbsim/device"
"gerrit.opencord.org/voltha-bbsim/protos"
"github.com/google/gopacket"
"github.com/google/gopacket/layers"
+ log "github.com/sirupsen/logrus"
"golang.org/x/net/context"
"google.golang.org/grpc"
)
// gRPC Service
func (s *Server) DisableOlt(c context.Context, empty *openolt.Empty) (*openolt.Empty, error) {
- logger.Info("OLT receives DisableOLT()\n")
+ logger.Debug("OLT receives DisableOLT()")
if s.EnableServer != nil {
if err := sendOltIndDown(*s.EnableServer); err != nil {
return new(openolt.Empty), err
}
- logger.Info("Successfuly sent OLT DOWN indication")
+ logger.Debug("Successfuly sent OLT DOWN indication")
}
return new(openolt.Empty), nil
}
func (s *Server) ReenableOlt(c context.Context, empty *openolt.Empty) (*openolt.Empty, error) {
- logger.Info("OLT receives Reenable()\n")
+ logger.Debug("OLT receives Reenable()")
return new(openolt.Empty), nil
}
func (s *Server) CollectStatistics(c context.Context, empty *openolt.Empty) (*openolt.Empty, error) {
- logger.Info("OLT receives CollectStatistics()\n")
+ logger.Debug("OLT receives CollectStatistics()")
return new(openolt.Empty), nil
}
func (s *Server) GetDeviceInfo(c context.Context, empty *openolt.Empty) (*openolt.DeviceInfo, error) {
- logger.Info("OLT receives GetDeviceInfo()\n")
- devinfo := new(openolt.DeviceInfo)
- devinfo.Vendor = "EdgeCore"
- devinfo.Model = "asfvolt16"
- devinfo.HardwareVersion = ""
- devinfo.FirmwareVersion = ""
- devinfo.Technology = "xgspon"
- devinfo.PonPorts = 1
- devinfo.OnuIdStart = 1
- devinfo.OnuIdEnd = 255
- devinfo.AllocIdStart = 1024
- devinfo.AllocIdEnd = 16383
- devinfo.GemportIdStart = 1024
- devinfo.GemportIdEnd = 65535
- devinfo.FlowIdStart = 1
- devinfo.FlowIdEnd = 16383
+ logger.Debug("OLT receives GetDeviceInfo()")
+ devinfo := new(openolt.DeviceInfo)
+ devinfo.Vendor = "EdgeCore"
+ devinfo.Model = "asfvolt16"
+ devinfo.HardwareVersion = ""
+ devinfo.FirmwareVersion = ""
+ devinfo.Technology = "xgspon"
+ devinfo.PonPorts = 1
+ devinfo.OnuIdStart = 1
+ devinfo.OnuIdEnd = 255
+ devinfo.AllocIdStart = 1024
+ devinfo.AllocIdEnd = 16383
+ devinfo.GemportIdStart = 1024
+ devinfo.GemportIdEnd = 65535
+ devinfo.FlowIdStart = 1
+ devinfo.FlowIdEnd = 16383
- /*
- for intf_id := 0; intf_id < 16; intf_id++ {
- r := new(openolt.DeviceInfo_DeviceResourceRanges)
+ /*
+ for intf_id := 0; intf_id < 16; intf_id++ {
+ r := new(openolt.DeviceInfo_DeviceResourceRanges)
- r.IntfIds = append(r.IntfIds, uint32(intf_id))
+ r.IntfIds = append(r.IntfIds, uint32(intf_id))
- r.Technology = "xgspon"
+ r.Technology = "xgspon"
- p := new(openolt.DeviceInfo_DeviceResourceRanges_Pool)
- p.Type = openolt.DeviceInfo_DeviceResourceRanges_Pool_ONU_ID
- p.Sharing = openolt.DeviceInfo_DeviceResourceRanges_Pool_DEDICATED_PER_INTF
- p.Start = 1
- p.End = 255
- r.Pools = append(r.Pools, p)
+ p := new(openolt.DeviceInfo_DeviceResourceRanges_Pool)
+ p.Type = openolt.DeviceInfo_DeviceResourceRanges_Pool_ONU_ID
+ p.Sharing = openolt.DeviceInfo_DeviceResourceRanges_Pool_DEDICATED_PER_INTF
+ p.Start = 1
+ p.End = 255
+ r.Pools = append(r.Pools, p)
- p = new(openolt.DeviceInfo_DeviceResourceRanges_Pool)
- p.Type = openolt.DeviceInfo_DeviceResourceRanges_Pool_ALLOC_ID
- p.Sharing = openolt.DeviceInfo_DeviceResourceRanges_Pool_SHARED_BY_ALL_INTF_SAME_TECH
- p.Start = 1024
- p.End = 16383
- r.Pools = append(r.Pools, p)
+ p = new(openolt.DeviceInfo_DeviceResourceRanges_Pool)
+ p.Type = openolt.DeviceInfo_DeviceResourceRanges_Pool_ALLOC_ID
+ p.Sharing = openolt.DeviceInfo_DeviceResourceRanges_Pool_SHARED_BY_ALL_INTF_SAME_TECH
+ p.Start = 1024
+ p.End = 16383
+ r.Pools = append(r.Pools, p)
- p = new(openolt.DeviceInfo_DeviceResourceRanges_Pool)
- p.Type = openolt.DeviceInfo_DeviceResourceRanges_Pool_GEMPORT_ID
- p.Sharing = openolt.DeviceInfo_DeviceResourceRanges_Pool_SHARED_BY_ALL_INTF_ALL_TECH
- p.Start = 1024
- p.End = 65535
- r.Pools = append(r.Pools, p)
+ p = new(openolt.DeviceInfo_DeviceResourceRanges_Pool)
+ p.Type = openolt.DeviceInfo_DeviceResourceRanges_Pool_GEMPORT_ID
+ p.Sharing = openolt.DeviceInfo_DeviceResourceRanges_Pool_SHARED_BY_ALL_INTF_ALL_TECH
+ p.Start = 1024
+ p.End = 65535
+ r.Pools = append(r.Pools, p)
- p = new(openolt.DeviceInfo_DeviceResourceRanges_Pool)
- p.Type = openolt.DeviceInfo_DeviceResourceRanges_Pool_FLOW_ID
- p.Sharing = openolt.DeviceInfo_DeviceResourceRanges_Pool_SHARED_BY_ALL_INTF_ALL_TECH
- p.Start = 1
- p.End = 16383
- r.Pools = append(r.Pools, p)
+ p = new(openolt.DeviceInfo_DeviceResourceRanges_Pool)
+ p.Type = openolt.DeviceInfo_DeviceResourceRanges_Pool_FLOW_ID
+ p.Sharing = openolt.DeviceInfo_DeviceResourceRanges_Pool_SHARED_BY_ALL_INTF_ALL_TECH
+ p.Start = 1
+ p.End = 16383
+ r.Pools = append(r.Pools, p)
- devinfo.Ranges = append(devinfo.Ranges, r)
- }
- */
+ devinfo.Ranges = append(devinfo.Ranges, r)
+ }
+ */
return devinfo, nil
}
func (s *Server) ActivateOnu(c context.Context, onu *openolt.Onu) (*openolt.Empty, error) {
- logger.Info("OLT receives ActivateONU()\n")
+ logger.Debug("OLT receives ActivateONU()")
result := device.ValidateONU(*onu, s.Onumap)
if result == true {
matched, error := getOnuBySN(s.Onumap, onu.SerialNumber)
if error != nil {
- logger.Fatal("%s\n", error)
+ logger.Fatal("%s", error)
}
onuid := onu.OnuId
matched.OnuID = onuid
matched.UpdateIntStatus(device.ONU_ACTIVATED)
- logger.Info("ONU IntfID: %d OnuID: %d activated succesufully.\n", onu.IntfId, onu.OnuId)
+ logger.Debug("ONU IntfID: %d OnuID: %d activated succesufully.", onu.IntfId, onu.OnuId)
}
return new(openolt.Empty), nil
}
func (s *Server) DeactivateOnu(c context.Context, onu *openolt.Onu) (*openolt.Empty, error) {
- logger.Info("OLT receives DeactivateONU()\n")
+ logger.Debug("OLT receives DeactivateONU()")
return new(openolt.Empty), nil
}
func (s *Server) DeleteOnu(c context.Context, onu *openolt.Onu) (*openolt.Empty, error) {
- logger.Info("OLT receives DeleteONU()\n")
+ logger.Debug("OLT receives DeleteONU()")
return new(openolt.Empty), nil
}
func (s *Server) OmciMsgOut(c context.Context, msg *openolt.OmciMsg) (*openolt.Empty, error) {
- logger.Info("OLT %d receives OmciMsgOut to IF %v (ONU-ID: %v) pkt:%x.\n", s.Olt.ID, msg.IntfId, msg.OnuId, msg.Pkt)
+ logger.Debug("OLT %d receives OmciMsgOut to IF %v (ONU-ID: %v) pkt:%x.", s.Olt.ID, msg.IntfId, msg.OnuId, msg.Pkt)
//s.olt.Queue = append(s.olt.Queue, *msg)
return new(openolt.Empty), nil
}
func (s *Server) OnuPacketOut(c context.Context, packet *openolt.OnuPacket) (*openolt.Empty, error) {
- logger.Info("OLT %d receives OnuPacketOut () to IF-ID:%d ONU-ID %d.\n", s.Olt.ID, packet.IntfId, packet.OnuId)
+ onu, _ := s.GetOnuByID(packet.OnuId)
+ utils.LoggerWithOnu(onu).Debug("OLT %d receives OnuPacketOut () to IF-ID:%d ONU-ID %d.", s.Olt.ID, packet.IntfId, packet.OnuId)
onuid := packet.OnuId
intfid := packet.IntfId
rawpkt := gopacket.NewPacket(packet.Pkt, layers.LayerTypeEthernet, gopacket.Default)
@@ -155,7 +158,7 @@
}
func (s *Server) UplinkPacketOut(c context.Context, packet *openolt.UplinkPacket) (*openolt.Empty, error) {
- logger.Info("OLT %d receives UplinkPacketOut().\n", s.Olt.ID)
+ logger.Debug("OLT %d receives UplinkPacketOut().", s.Olt.ID)
rawpkt := gopacket.NewPacket(packet.Pkt, layers.LayerTypeEthernet, gopacket.Default)
if err := s.uplinkPacketOut(rawpkt); err != nil {
return new(openolt.Empty), err
@@ -164,38 +167,47 @@
}
func (s *Server) FlowAdd(c context.Context, flow *openolt.Flow) (*openolt.Empty, error) {
- logger.Info("OLT %d receives FlowAdd().\n", s.Olt.ID)
- logger.Debug("Flow's ONU-ID: %d, CTAG: %d\n", flow.OnuId, flow.Action.IVid)
- //onuid := uint32(flow.OnuId)
- //ctag := flow.Action.IVid
- //s.CtagMap[onuid] = ctag
+
+ onu, _ := s.GetOnuByID(uint32(flow.OnuId))
+
+ utils.LoggerWithOnu(onu).WithFields(log.Fields{
+ "olt": s.Olt.ID,
+ "c_tag": flow.Action.IVid,
+ }).Debug("OLT receives FlowAdd().")
+
return new(openolt.Empty), nil
}
func (s *Server) FlowRemove(c context.Context, flow *openolt.Flow) (*openolt.Empty, error) {
- logger.Info("OLT %d receives FlowRemove().\n", s.Olt.ID)
+ onu, _ := s.GetOnuByID(uint32(flow.OnuId))
+
+ utils.LoggerWithOnu(onu).WithFields(log.Fields{
+ "olt": s.Olt.ID,
+ "c_tag": flow.Action.IVid,
+ }).Debug("OLT receives FlowRemove().")
+
return new(openolt.Empty), nil
}
func (s *Server) HeartbeatCheck(c context.Context, empty *openolt.Empty) (*openolt.Heartbeat, error) {
- logger.Info("OLT %d receives HeartbeatCheck().\n", s.Olt.ID)
+ logger.Debug("OLT %d receives HeartbeatCheck().", s.Olt.ID)
signature := new(openolt.Heartbeat)
signature.HeartbeatSignature = s.Olt.HeartbeatSignature
return signature, nil
}
func (s *Server) EnablePonIf(c context.Context, intf *openolt.Interface) (*openolt.Empty, error) {
- logger.Info("OLT %d receives EnablePonIf().\n", s.Olt.ID)
+ logger.Debug("OLT %d receives EnablePonIf().", s.Olt.ID)
return new(openolt.Empty), nil
}
func (s *Server) DisablePonIf(c context.Context, intf *openolt.Interface) (*openolt.Empty, error) {
- logger.Info("OLT %d receives DisablePonIf().\n", s.Olt.ID)
+ logger.Debug("OLT %d receives DisablePonIf().", s.Olt.ID)
return new(openolt.Empty), nil
}
func (s *Server) Reboot(c context.Context, empty *openolt.Empty) (*openolt.Empty, error) {
- logger.Info("OLT %d receives Reboot ().\n", s.Olt.ID)
+ logger.Debug("OLT %d receives Reboot ().", s.Olt.ID)
// Initialize OLT & Env
logger.Debug("Initialized by Reboot")
s.Disable()
@@ -203,19 +215,19 @@
}
func (s *Server) EnableIndication(empty *openolt.Empty, stream openolt.Openolt_EnableIndicationServer) error {
- logger.Info("OLT receives EnableInd.\n")
+ logger.Debug("OLT receives EnableInd.")
defer func() {
logger.Debug("grpc EnableIndication Done")
}()
if err := s.Enable(&stream); err != nil {
- logger.Error("Failed to Enable Core: %v\n", err)
+ logger.Error("Failed to Enable Core: %v", err)
return err
}
return nil
}
func NewGrpcServer(addrport string) (l net.Listener, g *grpc.Server, e error) {
- logger.Info("Listening %s ...", addrport)
+ logger.Debug("Listening %s ...", addrport)
g = grpc.NewServer()
l, e = net.Listen("tcp", addrport)
return
diff --git a/core/io_info.go b/core/io_info.go
index 867c88c..d104efc 100644
--- a/core/io_info.go
+++ b/core/io_info.go
@@ -41,7 +41,7 @@
}
}
err := errors.New("No matched Ioinfo is found")
- logger.Error(err)
+ logger.Error("identifyUniIoinfo %s", err)
return nil, err
}
@@ -52,7 +52,7 @@
}
}
err := errors.New("No matched Ioinfo is found")
- logger.Error(err)
+ logger.Error("IdentifyNniIoinfo %s", err)
return nil, err
}
@@ -65,7 +65,7 @@
}
if len(ioinfos) == 0 {
err := errors.New("No matched Ioinfo is found")
- logger.Error(err)
+ logger.Error("GetUniIoinfos %s", err)
return nil, err
}
return ioinfos, nil
diff --git a/core/io_worker.go b/core/io_worker.go
index 9a6cb6c..2657e4c 100644
--- a/core/io_worker.go
+++ b/core/io_worker.go
@@ -32,7 +32,7 @@
logger.Debug("recvWorker runs. handler: %v", *handler)
packetSource := gopacket.NewPacketSource(handler, handler.LinkType())
for packet := range packetSource.Packets() {
- logger.Debug("recv packet from IF: %v \n", *handler)
+ logger.Debug("recv packet from IF: %v ", *handler)
//logger.Println(packet.Dump())
pkt := Packet{}
pkt.Info = io
@@ -44,18 +44,18 @@
func SendUni(handle *pcap.Handle, packet gopacket.Packet) {
err := handle.WritePacketData(packet.Data())
if err != nil {
- logger.Error("Error in send packet to UNI-IF: %v e:%s\n", *handle, err)
+ logger.Error("Error in send packet to UNI-IF: %v e:%s", *handle, err)
}
- logger.Debug("Successfully send packet to UNI-IF: %v \n", *handle)
+ logger.Debug("Successfully send packet to UNI-IF: %v ", *handle)
//logger.Println(packet.Dump())
}
func SendNni(handle *pcap.Handle, packet gopacket.Packet) {
err := handle.WritePacketData(packet.Data())
if err != nil {
- logger.Error("Error in send packet to NNI e:%s\n", err)
+ logger.Error("Error in send packet to NNI e:%s", err)
}
- logger.Debug("send packet to NNI-IF: %v \n", *handle)
+ logger.Debug("send packet to NNI-IF: %v ", *handle)
//logger.Println(packet.Dump())
}
@@ -183,6 +183,6 @@
if err != nil {
return nil, err
}
- logger.Debug("Server handle is created for %s\n", vethname)
+ logger.Debug("Server handle is created for %s", vethname)
return handle, nil
}
diff --git a/core/mediator.go b/core/mediator.go
index a6d67b0..ee25264 100644
--- a/core/mediator.go
+++ b/core/mediator.go
@@ -129,7 +129,7 @@
wg.Add(1)
go func() {
if err := server.Start(); err != nil { //Blocking
- logger.Error(err)
+ logger.Error("Start %s", err)
}
wg.Done()
return
diff --git a/core/openolt_service.go b/core/openolt_service.go
index 41e6548..364d0c3 100644
--- a/core/openolt_service.go
+++ b/core/openolt_service.go
@@ -23,13 +23,12 @@
"gerrit.opencord.org/voltha-bbsim/common/utils"
"gerrit.opencord.org/voltha-bbsim/device"
"gerrit.opencord.org/voltha-bbsim/protos"
- log "github.com/sirupsen/logrus"
)
func sendOltIndUp(stream openolt.Openolt_EnableIndicationServer, olt *device.Olt) error {
data := &openolt.Indication_OltInd{OltInd: &openolt.OltIndication{OperState: "up"}}
if err := stream.Send(&openolt.Indication{Data: data}); err != nil {
- logger.Error("Failed to send OLT UP indication: %v\n", err)
+ logger.Error("Failed to send OLT UP indication: %v", err)
return err
}
return nil
@@ -38,7 +37,7 @@
func sendOltIndDown(stream openolt.Openolt_EnableIndicationServer) error {
data := &openolt.Indication_OltInd{OltInd: &openolt.OltIndication{OperState: "down"}}
if err := stream.Send(&openolt.Indication{Data: data}); err != nil {
- logger.Error("Failed to send OLT DOWN indication: %v\n", err)
+ logger.Error("Failed to send OLT DOWN indication: %v", err)
return err
}
return nil
@@ -50,10 +49,10 @@
if intf.Type == "pon" { // There is no need to send IntfInd for NNI
data := &openolt.Indication_IntfInd{&openolt.IntfIndication{IntfId: intf.IntfID, OperState: intf.OperState}}
if err := stream.Send(&openolt.Indication{Data: data}); err != nil {
- logger.Error("Failed to send Intf [id: %d] indication : %v\n", i, err)
+ logger.Error("Failed to send Intf [id: %d] indication : %v", i, err)
return err
}
- logger.Info("SendIntfInd olt:%d intf:%d (%s)\n", olt.ID, intf.IntfID, intf.Type)
+ logger.Info("SendIntfInd olt:%d intf:%d (%s)", olt.ID, intf.IntfID, intf.Type)
}
}
return nil
@@ -64,10 +63,10 @@
intf := olt.Intfs[i]
data := &openolt.Indication_IntfOperInd{&openolt.IntfOperIndication{Type: intf.Type, IntfId: intf.IntfID, OperState: intf.OperState}}
if err := stream.Send(&openolt.Indication{Data: data}); err != nil {
- logger.Error("Failed to send IntfOper [id: %d] indication : %v\n", i, err)
+ logger.Error("Failed to send IntfOper [id: %d] indication : %v", i, err)
return err
}
- logger.Info("SendOperInd olt:%d intf:%d (%s)\n", olt.ID, intf.IntfID, intf.Type)
+ logger.Info("SendOperInd olt:%d intf:%d (%s)", olt.ID, intf.IntfID, intf.Type)
}
return nil
}
@@ -76,15 +75,10 @@
for i, onu := range onus {
data := &openolt.Indication_OnuDiscInd{&openolt.OnuDiscIndication{IntfId: onu.IntfID, SerialNumber: onu.SerialNumber}}
if err := stream.Send(&openolt.Indication{Data: data}); err != nil {
- logger.Error("Failed to send ONUDiscInd [id: %d]: %v\n", i, err)
+ logger.Error("Failed to send ONUDiscInd [id: %d]: %v", i, err)
return err
}
- logger.WithFields(log.Fields{
- "serial_number": utils.OnuToSn(onu),
- "interfaceId": onu.IntfID,
- "onuId": onu.OnuID,
- "oltId": onu.OltID,
- }).Info("sendONUDiscInd Onuid")
+ utils.LoggerWithOnu(onu).Info("sendONUDiscInd Onuid")
}
return nil
}
@@ -94,15 +88,10 @@
time.Sleep(time.Duration(delay) * time.Second)
data := &openolt.Indication_OnuInd{&openolt.OnuIndication{IntfId: onu.IntfID, OnuId: onu.OnuID, OperState: "up", AdminState: "up", SerialNumber: onu.SerialNumber}}
if err := stream.Send(&openolt.Indication{Data: data}); err != nil {
- logger.Error("Failed to send ONUInd [id: %d]: %v\n", i, err)
+ logger.Error("Failed to send ONUInd [id: %d]: %v", i, err)
return err
}
- logger.WithFields(log.Fields{
- "serial_number": utils.OnuToSn(onu),
- "interfaceId": onu.IntfID,
- "onuId": onu.OnuID,
- "oltId": onu.OltID,
- }).Info("sendONUInd Onuid")
+ utils.LoggerWithOnu(onu).Info("sendONUInd Onuid")
}
return nil
}
diff --git a/core/tester.go b/core/tester.go
index cd4f96a..e665aa3 100644
--- a/core/tester.go
+++ b/core/tester.go
@@ -23,6 +23,7 @@
"time"
"gerrit.opencord.org/voltha-bbsim/common/logger"
+ "gerrit.opencord.org/voltha-bbsim/common/utils"
log "github.com/sirupsen/logrus"
"golang.org/x/sync/errgroup"
)
@@ -116,6 +117,11 @@
exec.Command("touch", "/var/run/dhcpd.pid").Run() //This is for DHCP server activation
}
+type UniVeth struct {
+ OnuId uint32
+ Veth string
+}
+
func (t *Tester) exeAAATest(ctx context.Context, s *Server, wait int) error {
tick := time.NewTicker(time.Second)
defer tick.Stop()
@@ -125,9 +131,13 @@
return err
}
- univeths := []string{}
+ univeths := []UniVeth{}
for _, info := range infos {
- univeths = append(univeths, info.Name)
+ uv := UniVeth{
+ OnuId: info.onuid,
+ Veth: info.Name,
+ }
+ univeths = append(univeths, uv)
}
for sec := 1; sec <= wait; sec++ {
@@ -136,13 +146,13 @@
logger.Debug("exeAAATest thread receives close ")
return nil
case <-tick.C:
- logger.WithField("seconds", wait-sec).Info("exeAAATest stands by ...")
+ logger.WithField("seconds", wait-sec).Info("exeAAATest stands by ... ", wait-sec)
if sec == wait {
wg := sync.WaitGroup{}
wg.Add(1)
go func() error {
defer wg.Done()
- err = activateWPASups(ctx, univeths, t.Intvl)
+ err = activateWPASups(ctx, univeths, t.Intvl, s)
if err != nil {
return err
}
@@ -179,9 +189,13 @@
return err
}
- univeths := []string{}
+ univeths := []UniVeth{}
for _, info := range infos {
- univeths = append(univeths, info.Name)
+ uv := UniVeth{
+ OnuId: info.onuid,
+ Veth: info.Name,
+ }
+ univeths = append(univeths, uv)
}
for sec := 1; sec <= wait; sec++ {
@@ -190,13 +204,13 @@
logger.Debug("exeDHCPTest thread receives close ")
return nil
case <-tick.C:
- logger.WithField("seconds", wait-sec).Info("exeDHCPTest stands by ...")
+ logger.WithField("seconds", wait-sec).Info("exeDHCPTest stands by ... ", wait-sec)
if sec == wait {
wg := sync.WaitGroup{}
wg.Add(1)
go func() error {
defer wg.Done()
- err = activateDHCPClients(ctx, univeths, t.Intvl)
+ err = activateDHCPClients(ctx, univeths, t.Intvl, s)
if err != nil {
return err
}
@@ -221,7 +235,7 @@
return nil
}
-func activateWPASups(ctx context.Context, vethnames []string, intvl int) error {
+func activateWPASups(ctx context.Context, vethnames []UniVeth, intvl int, s *Server) error {
tick := time.NewTicker(time.Duration(intvl) * time.Second)
defer tick.Stop()
i := 0
@@ -230,10 +244,9 @@
case <-tick.C:
if i < len(vethnames) {
vethname := vethnames[i]
- if err := activateWPASupplicant(vethname); err != nil {
+ if err := activateWPASupplicant(vethname, s); err != nil {
return err
}
- logger.Debug("activateWPASupplicant for interface %v\n", vethname)
i++
}
case <-ctx.Done():
@@ -244,7 +257,7 @@
return nil
}
-func activateDHCPClients(ctx context.Context, vethnames []string, intvl int) error {
+func activateDHCPClients(ctx context.Context, vethnames []UniVeth, intvl int, s *Server) error {
tick := time.NewTicker(time.Duration(intvl) * time.Second)
defer tick.Stop()
i := 0
@@ -253,12 +266,9 @@
case <-tick.C:
if i < len(vethnames) {
vethname := vethnames[i]
- if err := activateDHCPClient(vethname); err != nil {
+ if err := activateDHCPClient(vethname, s); err != nil {
return err
}
- logger.WithFields(log.Fields{
- "interface": vethname,
- }).Debug("activateDHCPClient")
i++
}
case <-ctx.Done():
@@ -272,55 +282,61 @@
func killProcess(name string) error {
err := exec.Command("pkill", name).Run()
if err != nil {
- logger.Error("Fail to pkill %s: %v\n", name, err)
+ logger.Error("Fail to pkill %s: %v", name, err)
return err
}
- logger.Info("Successfully killed %s\n", name)
+ logger.Info("Successfully killed %s", name)
return nil
}
-func activateWPASupplicant(vethname string) (err error) {
+func activateWPASupplicant(univeth UniVeth, s *Server) (err error) {
cmd := "/sbin/wpa_supplicant"
conf := "/etc/wpa_supplicant/wpa_supplicant.conf"
- err = exec.Command(cmd, "-D", "wired", "-i", vethname, "-c", conf).Start()
+ err = exec.Command(cmd, "-D", "wired", "-i", univeth.Veth, "-c", conf).Start()
+ onu, _ := s.GetOnuByID(univeth.OnuId)
if err != nil {
- logger.Error("Fail to activateWPASupplicant() for :%s %v\n", vethname, err)
+ utils.LoggerWithOnu(onu).WithFields(log.Fields{
+ "err": err,
+ "veth": univeth.Veth,
+ }).Error("Fail to activateWPASupplicant()", err)
return
}
- logger.Info("activateWPASupplicant() for :%s\n", vethname)
+ logger.Info("activateWPASupplicant() for :%s", univeth.Veth)
return
}
-func activateDHCPClient(vethname string) (err error) {
- logger.Debug("activateDHCPClient() start for: %s\n", vethname)
- cmd := exec.Command("/usr/local/bin/dhclient", vethname)
- // if err := cmd.Run(); err != nil {
+func activateDHCPClient(univeth UniVeth, s *Server) (err error) {
+ onu, _ := s.GetOnuByID(univeth.OnuId)
+ utils.LoggerWithOnu(onu).WithFields(log.Fields{
+ "veth": univeth.Veth,
+ }).Info("activateDHCPClient() start for: %s", univeth)
+ cmd := exec.Command("/usr/local/bin/dhclient", univeth.Veth)
if err := cmd.Start(); err != nil {
- logger.Error("Fail to activateDHCPClient() for: %s", vethname)
- logger.Panic(err)
+ logger.Error("Fail to activateDHCPClient() for: %s", univeth)
+ logger.Panic("activateDHCPClient %s", err)
}
- logger.Debug("activateDHCPClient() done for: %s\n", vethname)
+ logger.Debug("activateDHCPClient() done for: %s", univeth)
return
}
func activateDHCPServer(veth string, serverip string) error {
err := exec.Command("ip", "addr", "add", serverip, "dev", veth).Run()
if err != nil {
- logger.Error("Fail to add ip to %s address: %s\n", veth, err)
+ logger.Error("Fail to add ip to %s address: %s", veth, err)
return err
}
err = exec.Command("ip", "link", "set", veth, "up").Run()
if err != nil {
- logger.Error("Fail to set %s up: %s\n", veth, err)
+ logger.Error("Fail to set %s up: %s", veth, err)
return err
}
cmd := "/usr/local/bin/dhcpd"
conf := "/etc/dhcp/dhcpd.conf"
err = exec.Command(cmd, "-cf", conf, veth).Run()
if err != nil {
- logger.Error("Fail to activateDHCP Server (): %s\n", err)
+ logger.Error("Fail to activateDHCP Server (): %s", err)
return err
}
- logger.Info("DHCP Server is successfully activated !\n")
+ logger.Info("DHCP Server is successfully activated !")
return err
}