Avoid bounce in the ONU State
Retry EAPOL until done
Change-Id: I062e3831905ad27d756a11b147593f4a55051f55
diff --git a/VERSION b/VERSION
index 8041668..6fb571b 100644
--- a/VERSION
+++ b/VERSION
@@ -1 +1 @@
-2.0.1-dev0
+2.0.1-dev1
diff --git a/core/core_server.go b/core/core_server.go
index c03545a..fe677fa 100644
--- a/core/core_server.go
+++ b/core/core_server.go
@@ -308,24 +308,38 @@
}
func (s *Server) updateDevIntState(dev device.Device, state device.DeviceState) {
- logger.Debug("updateDevIntState called state:%d", state)
current := dev.GetIntState()
dev.UpdateIntState(state)
+ logger.Debug("updateDevIntState called state: current %s, next %s", device.ONUState[current], device.ONUState[dev.GetIntState()])
s.stateRepCh <- stateReport{device: dev, current: current, next: state}
if reflect.TypeOf(dev) == reflect.TypeOf(&device.Olt{}) {
- logger.Debug("OLT State updated to:%d", state)
+ logger.Debug("OLT State updated to:%s", device.ONUState[state])
} else if reflect.TypeOf(dev) == reflect.TypeOf(&device.Onu{}) {
- logger.Debug("ONU State updated to:%d", state)
+ logger.Debug("ONU State updated to:%s", device.ONUState[state])
} else {
logger.Error("UpdateDevIntState () doesn't support this device: %s", reflect.TypeOf(dev))
}
}
func (s *Server) updateOnuIntState(intfid uint32, onuid uint32, state device.DeviceState) error {
+
onu, err := s.GetOnuByID(onuid, intfid)
+
if err != nil {
+ logger.Warn("Failed to get ONU %d: %v", onuid, err)
return err
}
+
+ if state == onu.GetIntState(){
+ logger.WithFields(log.Fields{
+ "toState": device.ONUState[state],
+ "currentState": device.ONUState[onu.GetIntState()],
+ }).Warn("Trying to update the state with the same state, ignoring this request")
+ return nil
+ }
+
+ logger.Debug("Transitioning ONU state from %s to %s", device.ONUState[onu.GetIntState()], device.ONUState[state])
+
s.updateDevIntState(onu, state)
return nil
}
diff --git a/core/eapol.go b/core/eapol.go
index cc9f24c..7e465b3 100644
--- a/core/eapol.go
+++ b/core/eapol.go
@@ -22,8 +22,10 @@
"encoding/hex"
"errors"
"fmt"
+ log "github.com/sirupsen/logrus"
"net"
"sync"
+ "time"
"gerrit.opencord.org/voltha-bbsim/common/logger"
"github.com/google/gopacket"
@@ -40,6 +42,10 @@
EAP_SUCCESS
)
+func (eap clientState) String() string {
+ return [...]string{"EAP_START", "EAP_RESPID", "EAP_RESPCHA", "EAP_SUCCESS"}[eap]
+}
+
type eapResponder struct {
clients map[clientKey]*eapClientInstance
eapolIn chan *byteMsg
@@ -89,11 +95,13 @@
responder := getEAPResponder()
clients := responder.clients
if c, ok := clients[clientKey{intfid: msg.IntfId, onuid: msg.OnuId}]; ok {
- logger.Debug("Got client intfid:%d onuid: %d", c.key.intfid, c.key.onuid)
+ logger.Debug("Got client intfid:%d onuid: %d (ClientID: %v)", c.key.intfid, c.key.onuid, c.curId)
nextstate := respondMessage("EAPOL", *c, msg, eapolIn)
c.updateState(nextstate)
} else {
- logger.Error("Failed to find eapol client instance intfid:%d onuid:%d", msg.IntfId, msg.OnuId)
+ logger.WithFields(log.Fields{
+ "clients": clients,
+ }).Errorf("Failed to find eapol client instance intfid:%d onuid:%d", msg.IntfId, msg.OnuId)
}
case <-ctx.Done():
return
@@ -123,6 +131,37 @@
return nextstate
}
+func sendEAPStart(intfid uint32, onuid uint32, client eapClientInstance, bytes []byte, eapolIn chan *byteMsg) error {
+ for {
+ responder := getEAPResponder()
+ clients := responder.clients
+ if c, ok := clients[clientKey{intfid: intfid, onuid: onuid}]; ok {
+ if c.curState == EAP_SUCCESS {
+ logger.WithFields(log.Fields{
+ "int_id": intfid,
+ "onu_id": onuid,
+ }).Debug("EAP_SUCCESS received, stop retrying")
+ break
+ }
+ } else {
+ logger.WithFields(log.Fields{
+ "clients": clients,
+ }).Errorf("Failed to find eapol client instance intfid:%d onuid:%d (sendEAPStart)", intfid, onuid)
+ }
+ if err := sendBytes(clientKey{intfid, onuid}, bytes, eapolIn); err != nil {
+ return errors.New("Failed to send EAPStart")
+ }
+ logger.WithFields(log.Fields{
+ "int_id": intfid,
+ "onu_id": onuid,
+ "eapolIn": eapolIn,
+ "bytes": bytes,
+ }).Debug("EAPStart Sent")
+ time.Sleep(30 * time.Second)
+ }
+ return nil
+}
+
func startEAPClient(intfid uint32, onuid uint32) error {
client := eapClientInstance{key: clientKey{intfid: intfid, onuid: onuid},
srcaddr: &net.HardwareAddr{0x2e, 0x60, 0x70, 0x13, 0x07, byte(onuid)},
@@ -134,10 +173,8 @@
bytes := client.createEAPOL(eap)
resp := getEAPResponder()
eapolIn := resp.eapolIn
- if err := sendBytes(clientKey{intfid, onuid}, bytes, eapolIn); err != nil {
- return errors.New("Failed to send EAPStart")
- }
- logger.Debug("Sending EAPStart")
+ // start a loop that keeps sending EAPOL packets until it succeeds
+ go sendEAPStart(intfid, onuid, client, bytes, eapolIn)
// clients[key{intfid: intfid, onuid: onuid}] = &client
resp.clients[clientKey{intfid: intfid, onuid: onuid}] = &client
return nil
@@ -156,6 +193,7 @@
if cur == EAP_START {
reseap := c.createEAPResID()
pkt := c.createEAPOL(reseap)
+ logger.Debug("Moving from EAP_START to EAP_RESPID")
return EAP_RESPID, pkt, nil
}
} else if eap.Code == layers.EAPCodeRequest && eap.Type == layers.EAPTypeOTP {
@@ -167,12 +205,14 @@
senddata = append([]byte{0x10}, senddata...)
sendeap := c.createEAPResCha(senddata)
pkt := c.createEAPOL(sendeap)
+ logger.Debug("Moving from EAP_RESPID to EAP_RESPCHA")
return EAP_RESPCHA, pkt, nil
}
} else if eap.Code == layers.EAPCodeSuccess && eap.Type == layers.EAPTypeNone {
logger.Debug("Received EAP-Success")
logger.Debug(recvpkt.Dump())
if cur == EAP_RESPCHA {
+ logger.Debug("Moving from EAP_RESPCHA to EAP_SUCCESS")
return EAP_SUCCESS, nil, nil
}
} else {
diff --git a/core/grpc_service.go b/core/grpc_service.go
index d9b3613..a33e21c 100644
--- a/core/grpc_service.go
+++ b/core/grpc_service.go
@@ -253,21 +253,42 @@
"c_tag": flow.Action.IVid,
}).Debug("OLT receives FlowAdd().")
+
// EAPOL flow
if flow.Classifier.EthType == uint32(layers.EthernetTypeEAPOL) {
- logger.Debug("OLT %d receives EAPOL flow IntfID:%d OnuID:%d EType:%x", s.Olt.ID, flow.AccessIntfId, flow.OnuId, flow.Classifier.EthType)
- omcistate := omci.GetOnuOmciState(onu.IntfID, onu.OnuID)
- if omcistate != omci.DONE {
- logger.Warn("FlowAdd() OMCI state %d is not \"DONE\"", omci.GetOnuOmciState(onu.OnuID, onu.IntfID))
+ logger.WithFields(log.Fields{
+ "Classifier.OVid": flow.Classifier.OVid,
+ "Classifier.IVid": flow.Classifier.IVid,
+ "Classifier.EthType": flow.Classifier.EthType,
+ "Classifier.SrcPort": flow.Classifier.SrcPort,
+ "Classifier.DstPort": flow.Classifier.DstPort,
+ "Action.OVid": flow.Action.OVid,
+ "Action.IVid": flow.Action.IVid,
+ "IntfID": flow.AccessIntfId,
+ "OltID": s.Olt.ID,
+ "OnuID": flow.OnuId,
+ "FlowId": flow.FlowId,
+ "UniID": flow.UniId,
+ "PortNo": flow.PortNo,
+ "FlowType": flow.FlowType,
+ }).Debug("OLT receives EAPOL flow")
+
+ if flow.Classifier.OVid == 4091 {
+ omcistate := omci.GetOnuOmciState(onu.IntfID, onu.OnuID)
+ if omcistate != omci.DONE {
+ logger.Warn("FlowAdd() OMCI state %d is not \"DONE\"", omci.GetOnuOmciState(onu.OnuID, onu.IntfID))
+ }
+ _ = s.updateOnuIntState(onu.IntfID, onu.OnuID, device.ONU_OMCIACTIVE)
}
- _ = s.updateOnuIntState(onu.IntfID, onu.OnuID, device.ONU_OMCIACTIVE)
+
}
// DHCP flow
if flow.Classifier.EthType == uint32(layers.EthernetTypeIPv4) {
logger.Debug("Received flow's srcPort:%d dstPort:%d", flow.Classifier.SrcPort, flow.Classifier.DstPort)
if flow.Classifier.SrcPort == uint32(68) && flow.Classifier.DstPort == uint32(67) {
- logger.Debug("OLT %d receives DHCP flow IntfID:%d OnuID:%d EType:%x GemPortID:%d", s.Olt.ID, flow.AccessIntfId, flow.OnuId, flow.Classifier.EthType, flow.GemportId)
+ logger.Debug("OLT %d receives DHCP flow IntfID:%d OnuID:%d EType:%x GemPortID:%d VLanIDs: %d/%d",
+ s.Olt.ID, flow.AccessIntfId, flow.OnuId, flow.Classifier.EthType, flow.GemportId, flow.Classifier.OVid, flow.Classifier.IVid)
omcistate := omci.GetOnuOmciState(onu.IntfID, onu.OnuID)
if omcistate != omci.DONE {
logger.Warn("FlowAdd() OMCI state %d is not \"DONE\"", omci.GetOnuOmciState(onu.OnuID, onu.IntfID))
diff --git a/core/mediator.go b/core/mediator.go
index 44e1d20..b1d33b6 100644
--- a/core/mediator.go
+++ b/core/mediator.go
@@ -174,14 +174,18 @@
next := sr.next
current := sr.current
dev := sr.device
+ key := dev.GetDevkey()
if reflect.TypeOf(dev) == reflect.TypeOf(&device.Olt{}) {
- logger.Debug("Received OLT Device %v Current: %d Next: %d", dev, current, next)
+ logger.WithFields(log.Fields{
+ "device": dev,
+ }).Debugf("Received OLT Device state change %v Current: %d Next: %d", key, current, next)
if err := transitOlt(current, next, m.testmanager, m.opt); err != nil {
logger.Error("%v", err)
}
} else if reflect.TypeOf(dev) == reflect.TypeOf(&device.Onu{}) {
- logger.Debug("Received ONU Device %v Current: %d Next: %d", dev, current, next)
- key := dev.GetDevkey()
+ logger.WithFields(log.Fields{
+ "device": dev,
+ }).Debugf("Received ONU Device state change %v Current: %d Next: %d", key, current, next)
if err := transitOnu(key, current, next, m.testmanager, m.opt); err != nil {
logger.Error("%v", err)
}
@@ -204,15 +208,16 @@
return nil
}
-func transitOnu(key device.Devkey, current device.DeviceState, next device.DeviceState, tm *TestManager, o *option) error {
- logger.Debug("trnsitOnu called with key: %v, current: %d, next: %d", key, current, next)
+func transitOnu(key device.Devkey, previous device.DeviceState, current device.DeviceState, tm *TestManager, o *option) error {
+ logger.Debug("transitOnu called with key: %v, previous: %s, current: %s", key, device.ONUState[previous], device.ONUState[current])
if o.Mode == AAA || o.Mode == BOTH {
- if current == device.ONU_ACTIVE && next == device.ONU_OMCIACTIVE {
+ if previous == device.ONU_ACTIVE && current == device.ONU_OMCIACTIVE {
+ logger.Debug("Starting WPASupplicant for device %v", key)
t := tm.CreateTester("AAA", o, key, activateWPASupplicant, o.aaawait)
if err := tm.StartTester(t); err != nil {
logger.Error("Cannot Start AAA Executer error:%v", err)
}
- } else if current == device.ONU_OMCIACTIVE && next == device.ONU_INACTIVE {
+ } else if previous == device.ONU_OMCIACTIVE && current == device.ONU_INACTIVE {
if err := tm.StopTester("AAA", key); err != nil {
logger.Error("Cannot Stop AAA Executer error:%v", err)
}
@@ -220,12 +225,13 @@
}
if o.Mode == BOTH {
- if current == device.ONU_OMCIACTIVE {
+ if previous == device.ONU_OMCIACTIVE && current == device.ONU_AUTHENTICATED {
+ logger.Debug("Starting DHCP client for device %v", key)
t := tm.CreateTester("DHCP", o, key, activateDHCPClient, o.dhcpwait)
if err := tm.StartTester(t); err != nil {
logger.Error("Cannot Start DHCP Executer error:%v", err)
}
- } else if current == device.ONU_AUTHENTICATED && next == device.ONU_INACTIVE {
+ } else if previous == device.ONU_AUTHENTICATED && current == device.ONU_INACTIVE {
if err := tm.StopTester("DHCP", key); err != nil {
logger.Error("Cannot Stop DHCP Executer error:%v", err)
}
diff --git a/core/tester.go b/core/tester.go
index d35a55b..605d0e4 100644
--- a/core/tester.go
+++ b/core/tester.go
@@ -92,6 +92,8 @@
key := t.Key
waitsec := t.Waitsec
+ // TODO use timers instead of this crazy loop: https://gobyexample.com/timers
+
logger.Debug("StartTester type:%s called with key:%v", testtype, key)
child, cancel := context.WithCancel(tm.ctx)
t.ctx = child
diff --git a/flow/flow.go b/flow/flow.go
index f32e048..8d03bb5 100644
--- a/flow/flow.go
+++ b/flow/flow.go
@@ -19,6 +19,7 @@
import (
"gerrit.opencord.org/voltha-bbsim/common/logger"
openolt "gerrit.opencord.org/voltha-bbsim/protos"
+ log "github.com/sirupsen/logrus"
)
var flowManager FlowManager
@@ -72,7 +73,14 @@
// AddFlow method implemented for DefaultFlowController
func (fc *DefaultFlowController) AddFlow(flow *openolt.Flow) error {
- logger.Debug("AddFlow invoked %v", flow)
+ logger.WithFields(log.Fields{
+ "flow_eth_type": flow.Classifier.EthType,
+ "ovid": flow.Classifier.OVid,
+ "ivid": flow.Classifier.IVid,
+ "onu_id": flow.OnuId,
+ "flow_id": flow.FlowId,
+ "flow_type": flow.FlowType,
+ }).Debugf("AddFlow invoked for onu %d", flow.OnuId)
return nil
}