[VOL-2778] Cleaning up DHCP logs
Change-Id: Ia34062a44bf86997a69e00a12644fc6ccda3b762
diff --git a/internal/bbsim/devices/onu.go b/internal/bbsim/devices/onu.go
index 9116b31..458678a 100644
--- a/internal/bbsim/devices/onu.go
+++ b/internal/bbsim/devices/onu.go
@@ -357,7 +357,7 @@
} else if msg.Type == packetHandlers.DHCP {
_ = dhcp.HandleNextBbrPacket(o.ID, o.PonPortID, o.Sn(), o.DoneChannel, msg.Packet, client)
}
- // BBR specific messages
+ // BBR specific messages
case OmciIndication:
msg, _ := message.Data.(OmciIndicationMessage)
o.handleOmci(msg, client)
@@ -611,6 +611,7 @@
func (o *Onu) handleFlowAdd(msg OnuFlowUpdateMessage) {
onuLogger.WithFields(log.Fields{
+ "Cookie": msg.Flow.Cookie,
"DstPort": msg.Flow.Classifier.DstPort,
"EthType": fmt.Sprintf("%x", msg.Flow.Classifier.EthType),
"FlowId": msg.Flow.FlowId,
diff --git a/internal/bbsim/devices/services.go b/internal/bbsim/devices/services.go
index bee3065..360bd4a 100644
--- a/internal/bbsim/devices/services.go
+++ b/internal/bbsim/devices/services.go
@@ -130,7 +130,9 @@
service.DHCPState = fsm.NewFSM(
"created",
fsm.Events{
- {Name: "start_dhcp", Src: []string{"created", "eap_response_success_received", "dhcp_discovery_sent", "dhcp_request_sent", "dhcp_ack_received", "dhcp_failed"}, Dst: "dhcp_started"},
+ // TODO only allow transitions to dhcp_start from success or failure, not in-between states
+ // TODO forcefully fail DHCP if we don't get an ack in X seconds
+ {Name: "start_dhcp", Src: []string{"created", "dhcp_discovery_sent", "dhcp_request_sent", "dhcp_ack_received", "dhcp_failed"}, Dst: "dhcp_started"},
{Name: "dhcp_discovery_sent", Src: []string{"dhcp_started"}, Dst: "dhcp_discovery_sent"},
{Name: "dhcp_request_sent", Src: []string{"dhcp_discovery_sent"}, Dst: "dhcp_request_sent"},
{Name: "dhcp_ack_received", Src: []string{"dhcp_request_sent"}, Dst: "dhcp_ack_received"},
@@ -191,11 +193,10 @@
"IntfId": s.Onu.PonPortID,
"OnuSn": s.Onu.Sn(),
"Name": s.Name,
- }).Debug("DHCP flow is not for this service, ignoring")
+ }).Trace("DHCP flow is not for this service, ignoring")
return
}
- // NOTE since we're matching the flow tag, this may not be required
if !s.NeedsDhcp {
serviceLogger.WithFields(log.Fields{
"OnuId": s.Onu.ID,
@@ -203,11 +204,11 @@
"OnuSn": s.Onu.Sn(),
"Name": s.Name,
"NeedsDhcp": s.NeedsDhcp,
- }).Debug("Won't start DHCP as it is not required")
+ }).Trace("Won't start DHCP as it is not required")
return
}
- // TODO check if the EAPOL flow was received before starting auth
+ // TODO check if the DHCP flow was received before starting auth
if err := s.DHCPState.Event("start_dhcp"); err != nil {
serviceLogger.WithFields(log.Fields{
@@ -257,12 +258,12 @@
"OnuSn": s.Onu.Sn(),
"Name": s.Name,
"messageType": msg.Type,
- }).Debug("Received message on Service Packet Channel")
+ }).Trace("Received message on Service Packet Channel")
if msg.Type == packetHandlers.EAPOL {
eapol.HandleNextPacket(msg.OnuId, msg.IntfId, s.GemPort, s.Onu.Sn(), s.Onu.PortNo, s.EapolState, msg.Packet, stream, nil)
} else if msg.Type == packetHandlers.DHCP {
- _ = dhcp.HandleNextPacket(s.Onu.PonPort.Olt.ID, s.Onu.ID, s.Onu.PonPortID, s.Onu.Sn(), s.Onu.PortNo, s.CTag, s.GemPort, s.HwAddress, s.DHCPState, msg.Packet, s.UsPonCTagPriority, stream)
+ _ = dhcp.HandleNextPacket(s.Onu.PonPort.Olt.ID, s.Onu.ID, s.Onu.PonPortID, s.Name, s.Onu.Sn(), s.Onu.PortNo, s.CTag, s.GemPort, s.HwAddress, s.DHCPState, msg.Packet, s.UsPonCTagPriority, stream)
}
}
}
@@ -325,7 +326,7 @@
"GemPortId": s.GemPort,
}).Debugf("HandleDHCPStart")
- if err := dhcp.SendDHCPDiscovery(s.Onu.PonPort.Olt.ID, s.Onu.PonPortID, s.Onu.ID, int(s.CTag), s.GemPort,
+ if err := dhcp.SendDHCPDiscovery(s.Onu.PonPort.Olt.ID, s.Onu.PonPortID, s.Onu.ID, s.Name, int(s.CTag), s.GemPort,
s.Onu.Sn(), s.Onu.PortNo, s.DHCPState, s.HwAddress, s.UsPonCTagPriority, stream); err != nil {
serviceLogger.WithFields(log.Fields{
"OnuId": s.Onu.ID,
diff --git a/internal/bbsim/responders/dhcp/dhcp.go b/internal/bbsim/responders/dhcp/dhcp.go
index 98a254f..9f8b035 100644
--- a/internal/bbsim/responders/dhcp/dhcp.go
+++ b/internal/bbsim/responders/dhcp/dhcp.go
@@ -265,7 +265,7 @@
return nil
}
-func sendDHCPRequest(oltId int, ponPortId uint32, onuId uint32, serialNumber string, portNo uint32,
+func sendDHCPRequest(oltId int, ponPortId uint32, onuId uint32, serviceName string, serialNumber string, portNo uint32,
cTag int, gemPortId uint32, onuStateMachine *fsm.FSM, onuHwAddress net.HardwareAddr,
offeredIp net.IP, pbit uint8, stream bbsim.Stream) error {
dhcp := createDHCPReq(oltId, ponPortId, onuId, onuHwAddress, offeredIp)
@@ -305,10 +305,11 @@
}
dhcpLogger.WithFields(log.Fields{
- "OnuId": onuId,
- "IntfId": ponPortId,
- "OnuSn": serialNumber,
- "OfferedIp": offeredIp.String(),
+ "OnuId": onuId,
+ "IntfId": ponPortId,
+ "OnuSn": serialNumber,
+ "OfferedIp": offeredIp.String(),
+ "ServiceName": serviceName,
}).Infof("DHCPRequest Sent")
return nil
}
@@ -325,7 +326,7 @@
return nil
}
-func SendDHCPDiscovery(oltId int, ponPortId uint32, onuId uint32, cTag int, gemPortId uint32,
+func SendDHCPDiscovery(oltId int, ponPortId uint32, onuId uint32, serviceName string, cTag int, gemPortId uint32,
serialNumber string, portNo uint32, stateMachine *fsm.FSM, onuHwAddress net.HardwareAddr,
pbit uint8, stream bbsim.Stream) error {
@@ -334,9 +335,10 @@
if err != nil {
dhcpLogger.WithFields(log.Fields{
- "OnuId": onuId,
- "IntfId": ponPortId,
- "OnuSn": serialNumber,
+ "OnuId": onuId,
+ "IntfId": ponPortId,
+ "OnuSn": serialNumber,
+ "ServiceName": serviceName,
}).Errorf("Cannot serializeDHCPPacket: %s", err)
if err := updateDhcpFailed(onuId, ponPortId, serialNumber, stateMachine); err != nil {
return err
@@ -354,9 +356,10 @@
if err := sendDHCPPktIn(msg, portNo, gemPortId, stream); err != nil {
dhcpLogger.WithFields(log.Fields{
- "OnuId": onuId,
- "IntfId": ponPortId,
- "OnuSn": serialNumber,
+ "OnuId": onuId,
+ "IntfId": ponPortId,
+ "OnuSn": serialNumber,
+ "ServiceName": serviceName,
}).Errorf("Cannot sendDHCPPktIn: %s", err)
if err := updateDhcpFailed(onuId, ponPortId, serialNumber, stateMachine); err != nil {
return err
@@ -364,31 +367,34 @@
return err
}
dhcpLogger.WithFields(log.Fields{
- "OnuId": onuId,
- "IntfId": ponPortId,
- "OnuSn": serialNumber,
- }).Infof("DHCPDiscovery Sent")
+ "OnuId": onuId,
+ "IntfId": ponPortId,
+ "OnuSn": serialNumber,
+ "ServiceName": serviceName,
+ }).Info("DHCPDiscovery Sent")
if err := stateMachine.Event("dhcp_discovery_sent"); err != nil {
dhcpLogger.WithFields(log.Fields{
- "OnuId": onuId,
- "IntfId": ponPortId,
- "OnuSn": serialNumber,
+ "OnuId": onuId,
+ "IntfId": ponPortId,
+ "OnuSn": serialNumber,
+ "ServiceName": serviceName,
}).Errorf("Error while transitioning ONU State %v", err)
}
return nil
}
-func HandleNextPacket(oltId int, onuId uint32, ponPortId uint32, serialNumber string, portNo uint32,
+func HandleNextPacket(oltId int, onuId uint32, ponPortId uint32, serviceName string, serialNumber string, portNo uint32,
cTag int, gemPortId uint32, onuHwAddress net.HardwareAddr, onuStateMachine *fsm.FSM,
pkt gopacket.Packet, pbit uint8, stream bbsim.Stream) error {
dhcpLayer, err := GetDhcpLayer(pkt)
if err != nil {
dhcpLogger.WithFields(log.Fields{
- "OnuId": onuId,
- "IntfId": ponPortId,
- "OnuSn": serialNumber,
+ "OnuId": onuId,
+ "IntfId": ponPortId,
+ "OnuSn": serialNumber,
+ "ServiceName": serviceName,
}).Errorf("Can't get DHCP Layer from Packet: %v", err)
if err := updateDhcpFailed(onuId, ponPortId, serialNumber, onuStateMachine); err != nil {
return err
@@ -398,9 +404,10 @@
dhcpMessageType, err := GetDhcpMessageType(dhcpLayer)
if err != nil {
dhcpLogger.WithFields(log.Fields{
- "OnuId": onuId,
- "IntfId": ponPortId,
- "OnuSn": serialNumber,
+ "OnuId": onuId,
+ "IntfId": ponPortId,
+ "OnuSn": serialNumber,
+ "ServiceName": serviceName,
}).Errorf("Can't get DHCP Message Type from DHCP Layer: %v", err)
if err := updateDhcpFailed(onuId, ponPortId, serialNumber, onuStateMachine); err != nil {
return err
@@ -411,11 +418,12 @@
if dhcpLayer.Operation == layers.DHCPOpReply {
if dhcpMessageType == layers.DHCPMsgTypeOffer {
offeredIp := dhcpLayer.YourClientIP
- if err := sendDHCPRequest(oltId, ponPortId, onuId, serialNumber, portNo, cTag, gemPortId, onuStateMachine, onuHwAddress, offeredIp, pbit, stream); err != nil {
+ if err := sendDHCPRequest(oltId, ponPortId, onuId, serviceName, serialNumber, portNo, cTag, gemPortId, onuStateMachine, onuHwAddress, offeredIp, pbit, stream); err != nil {
dhcpLogger.WithFields(log.Fields{
- "OnuId": onuId,
- "IntfId": ponPortId,
- "OnuSn": serialNumber,
+ "OnuId": onuId,
+ "IntfId": ponPortId,
+ "OnuSn": serialNumber,
+ "ServiceName": serviceName,
}).Errorf("Can't send DHCP Request: %s", err)
if err := updateDhcpFailed(onuId, ponPortId, serialNumber, onuStateMachine); err != nil {
return err
@@ -424,33 +432,37 @@
}
if err := onuStateMachine.Event("dhcp_request_sent"); err != nil {
dhcpLogger.WithFields(log.Fields{
- "OnuId": onuId,
- "IntfId": ponPortId,
- "OnuSn": serialNumber,
- }).Errorf("Error while transitioning ONU State %v", err)
+ "OnuId": onuId,
+ "IntfId": ponPortId,
+ "OnuSn": serialNumber,
+ "ServiceName": serviceName,
+ }).Errorf("Error while transitioning State %v", err)
}
} else if dhcpMessageType == layers.DHCPMsgTypeAck {
// NOTE once the ack is received we don't need to do anything but change the state
if err := onuStateMachine.Event("dhcp_ack_received"); err != nil {
dhcpLogger.WithFields(log.Fields{
- "OnuId": onuId,
- "IntfId": ponPortId,
- "OnuSn": serialNumber,
- }).Errorf("Error while transitioning ONU State %v", err)
+ "OnuId": onuId,
+ "IntfId": ponPortId,
+ "OnuSn": serialNumber,
+ "ServiceName": serviceName,
+ }).Errorf("Error while transitioning State %v", err)
}
dhcpLogger.WithFields(log.Fields{
- "OnuId": onuId,
- "IntfId": ponPortId,
- "OnuSn": serialNumber,
+ "OnuId": onuId,
+ "IntfId": ponPortId,
+ "OnuSn": serialNumber,
+ "ServiceName": serviceName,
}).Infof("DHCP State machine completed")
}
// NOTE do we need to care about DHCPMsgTypeRelease??
} else {
dhcpLogger.WithFields(log.Fields{
- "OnuId": onuId,
- "IntfId": ponPortId,
- "OnuSn": serialNumber,
+ "OnuId": onuId,
+ "IntfId": ponPortId,
+ "OnuSn": serialNumber,
+ "ServiceName": serviceName,
}).Warnf("Unsupported DHCP Operation: %s", dhcpLayer.Operation.String())
}
diff --git a/internal/bbsim/responders/dhcp/dhcp_test.go b/internal/bbsim/responders/dhcp/dhcp_test.go
index aea2048..cb6d9b7 100644
--- a/internal/bbsim/responders/dhcp/dhcp_test.go
+++ b/internal/bbsim/responders/dhcp/dhcp_test.go
@@ -74,7 +74,7 @@
fail: false,
}
- if err := SendDHCPDiscovery(oltId, ponPortId, onuId, 900, gemPortId, serialNumber, portNo, dhcpStateMachine, mac, 7, stream); err != nil {
+ if err := SendDHCPDiscovery(oltId, ponPortId, onuId, "hsia", 900, gemPortId, serialNumber, portNo, dhcpStateMachine, mac, 7, stream); err != nil {
t.Errorf("SendDHCPDiscovery returned an error: %v", err)
t.Fail()
}