VOL-947 Moved the netcfg update listener and factory within activate method
Added better logging to indicate where radius packets are being sent and whats received.
6/19 - Improved logging a bit more to track down EAP reply before radius is sent
Change-Id: If74cb4315db0123625be84285d581e3f1f959d80
diff --git a/src/main/java/org/opencord/aaa/AaaConfig.java b/src/main/java/org/opencord/aaa/AaaConfig.java
index 8ffdf00..8c7aa47 100644
--- a/src/main/java/org/opencord/aaa/AaaConfig.java
+++ b/src/main/java/org/opencord/aaa/AaaConfig.java
@@ -17,6 +17,7 @@
import com.fasterxml.jackson.databind.JsonNode;
import com.fasterxml.jackson.databind.node.ArrayNode;
+import org.apache.commons.lang3.builder.ToStringBuilder;
import com.google.common.collect.ImmutableSet;
@@ -287,4 +288,9 @@
}
return builder.build();
}
+
+ @Override
+ public String toString() {
+ return ToStringBuilder.reflectionToString(this);
+ }
}
diff --git a/src/main/java/org/opencord/aaa/AaaManager.java b/src/main/java/org/opencord/aaa/AaaManager.java
index 4fc0fab..c920864 100755
--- a/src/main/java/org/opencord/aaa/AaaManager.java
+++ b/src/main/java/org/opencord/aaa/AaaManager.java
@@ -19,6 +19,7 @@
import org.apache.felix.scr.annotations.Deactivate;
import org.apache.felix.scr.annotations.Reference;
import org.apache.felix.scr.annotations.ReferenceCardinality;
+import org.apache.commons.lang3.builder.ToStringBuilder;
import org.onlab.packet.DeserializationException;
import org.onlab.packet.EAP;
import org.onlab.packet.EAPOL;
@@ -194,10 +195,13 @@
@Activate
public void activate() {
- netCfgService.registerConfigFactory(factory);
appId = coreService.registerApplication(APP_NAME);
+ netCfgService.addListener(cfgListener);
+ netCfgService.registerConfigFactory(factory);
customInfo = new CustomizationInfo(subsService, deviceService);
cfgListener.reconfigureNetwork(netCfgService.getConfig(appId, AaaConfig.class));
+ log.info("Starting with config {} {}", this, newCfg);
+
configureRadiusCommunication();
// register our event handler
@@ -208,7 +212,6 @@
StateMachine.setAccessDeviceService(accessDeviceService);
impl.initializeLocalState(newCfg);
- netCfgService.addListener(cfgListener);
impl.requestIntercepts();
@@ -283,6 +286,7 @@
switch (radiusPacket.getCode()) {
case RADIUS.RADIUS_CODE_ACCESS_CHALLENGE:
+ log.debug("RADIUS packet: RADIUS_CODE_ACCESS_CHALLENGE");
RADIUSAttribute radiusAttrState = radiusPacket.getAttribute(RADIUSAttribute.RADIUS_ATTR_STATE);
byte[] challengeState = null;
if (radiusAttrState != null) {
@@ -295,9 +299,11 @@
stateMachine.vlanId(),
EAPOL.EAPOL_PACKET,
eapPayload, stateMachine.priorityCode());
+ log.debug("Send EAP challenge response to supplicant {}", stateMachine.supplicantAddress().toString());
sendPacketToSupplicant(eth, stateMachine.supplicantConnectpoint());
break;
case RADIUS.RADIUS_CODE_ACCESS_ACCEPT:
+ log.debug("RADIUS packet: RADIUS_CODE_ACCESS_ACCEPT");
//send an EAPOL - Success to the supplicant.
byte[] eapMessageSuccess =
radiusPacket.getAttribute(RADIUSAttribute.RADIUS_ATTR_EAP_MESSAGE).getValue();
@@ -308,12 +314,14 @@
stateMachine.vlanId(),
EAPOL.EAPOL_PACKET,
eapPayload, stateMachine.priorityCode());
+ log.info("Send EAP success message to supplicant {}", stateMachine.supplicantAddress().toString());
sendPacketToSupplicant(eth, stateMachine.supplicantConnectpoint());
stateMachine.authorizeAccess();
break;
case RADIUS.RADIUS_CODE_ACCESS_REJECT:
+ log.debug("RADIUS packet: RADIUS_CODE_ACCESS_REJECT");
//send an EAPOL - Failure to the supplicant.
byte[] eapMessageFailure;
eapPayload = new EAP();
@@ -332,6 +340,7 @@
stateMachine.vlanId(),
EAPOL.EAPOL_PACKET,
eapPayload, stateMachine.priorityCode());
+ log.warn("Send EAP failure message to supplicant {}", stateMachine.supplicantAddress().toString());
sendPacketToSupplicant(eth, stateMachine.supplicantConnectpoint());
stateMachine.denyAccess();
@@ -354,6 +363,11 @@
packetService.emit(packet);
}
+ @Override
+ public String toString() {
+ return ToStringBuilder.reflectionToString(this);
+ }
+
// our handler defined as a private inner class
/**
@@ -448,6 +462,7 @@
switch (eapol.getEapolType()) {
case EAPOL.EAPOL_START:
+ log.debug("EAP packet: EAPOL_START");
stateMachine.start();
stateMachine.setSupplicantConnectpoint(inPacket.receivedFrom());
@@ -459,13 +474,16 @@
Ethernet eth = buildEapolResponse(srcMac, MacAddress.valueOf(nasMacAddress),
ethPkt.getVlanID(), EAPOL.EAPOL_PACKET,
eapPayload, stateMachine.priorityCode());
+
stateMachine.setSupplicantAddress(srcMac);
stateMachine.setVlanId(ethPkt.getVlanID());
+ log.debug("Getting EAP identity from supplicant {}", stateMachine.supplicantAddress().toString());
sendPacketToSupplicant(eth, stateMachine.supplicantConnectpoint());
break;
case EAPOL.EAPOL_LOGOFF:
+ log.debug("EAP packet: EAPOL_LOGOFF");
if (stateMachine.state() == StateMachine.STATE_AUTHORIZED) {
stateMachine.logoff();
}
@@ -480,6 +498,7 @@
switch (dataType) {
case EAP.ATTR_IDENTITY:
+ log.debug("EAP packet: EAPOL_PACKET ATTR_IDENTITY");
// request id access to RADIUS
stateMachine.setUsername(eapPacket.getData());
@@ -493,6 +512,7 @@
stateMachine.requestAccess();
break;
case EAP.ATTR_MD5:
+ log.debug("EAP packet: EAPOL_PACKET ATTR_MD5");
// verify if the EAP identifier corresponds to the
// challenge identifier from the client state
// machine.
@@ -513,6 +533,7 @@
}
break;
case EAP.ATTR_TLS:
+ log.debug("EAP packet: EAPOL_PACKET ATTR_TLS");
// request id access to RADIUS
radiusPayload = getRadiusPayload(stateMachine, stateMachine.identifier(), eapPacket);
radiusPayload = pktCustomizer.customizePacket(radiusPayload, inPacket);
@@ -532,11 +553,12 @@
break;
default:
+ log.warn("Unknown EAP packet type");
return;
}
break;
default:
- log.trace("Skipping EAPOL message {}", eapol.getEapolType());
+ log.debug("Skipping EAPOL message {}", eapol.getEapolType());
}
}
}
@@ -553,6 +575,7 @@
* @param cfg configuration object
*/
private void reconfigureNetwork(AaaConfig cfg) {
+ log.info("Reconfiguring AaaConfig from config: {}", cfg);
if (cfg == null) {
newCfg = new AaaConfig();
@@ -609,7 +632,7 @@
AaaConfig cfg = netCfgService.getConfig(appId, AaaConfig.class);
reconfigureNetwork(cfg);
- log.info("Reconfigured");
+ log.info("Reconfigured: {}", cfg.toString());
}
}
}
diff --git a/src/main/java/org/opencord/aaa/SocketBasedRadiusCommunicator.java b/src/main/java/org/opencord/aaa/SocketBasedRadiusCommunicator.java
index bb99f09..6b64a18 100755
--- a/src/main/java/org/opencord/aaa/SocketBasedRadiusCommunicator.java
+++ b/src/main/java/org/opencord/aaa/SocketBasedRadiusCommunicator.java
@@ -92,6 +92,8 @@
log.error("Can't open RADIUS socket", ex);
}
+ log.info("Remote RADIUS Server: {}:{}", radiusIpAddress, radiusServerPort);
+
executor = Executors.newSingleThreadExecutor(
new ThreadFactoryBuilder()
.setNameFormat("AAA-radius-%d").build());
@@ -134,7 +136,8 @@
radiusIpAddress, radiusServerPort);
socket.send(packet);
- log.info("Packet sent to Radius Server using socket packet = {}", packet);
+ log.debug("Packet sent to Radius Server {}:{} using socket",
+ radiusIpAddress, radiusServerPort);
} catch (IOException e) {
log.info("Cannot send packet to RADIUS server", e);
}
@@ -145,7 +148,7 @@
InboundPacket pkt = context.inPacket();
Ethernet ethPkt = pkt.parsed();
- log.trace("Skipping Ethernet packet type {}",
+ log.debug("Skipping Ethernet packet type {}",
EthType.EtherType.lookup(ethPkt.getEtherType()));
}
@@ -165,7 +168,7 @@
new DatagramPacket(packetBuffer, packetBuffer.length);
DatagramSocket socket = radiusSocket;
socket.receive(inboundBasePacket);
- log.info("Packet #{} received", packetNumber++);
+ log.debug("Packet #{} received", packetNumber++);
try {
inboundRadiusPacket =
RADIUS.deserializer()