Adding trace logging to emitted and received packets

Change-Id: Id23be0d7fb70258c5de9900f099575404329746a
diff --git a/src/main/java/org/opencord/aaa/AaaManager.java b/src/main/java/org/opencord/aaa/AaaManager.java
index 120f14f..b527d91 100755
--- a/src/main/java/org/opencord/aaa/AaaManager.java
+++ b/src/main/java/org/opencord/aaa/AaaManager.java
@@ -15,6 +15,13 @@
  */
 package org.opencord.aaa;
 
+import static org.onosproject.net.config.basics.SubjectFactories.APP_SUBJECT_FACTORY;
+import static org.slf4j.LoggerFactory.getLogger;
+
+import java.net.InetAddress;
+import java.nio.ByteBuffer;
+import java.util.Map;
+
 import org.apache.commons.lang3.builder.ToStringBuilder;
 import org.apache.felix.scr.annotations.Component;
 import org.apache.felix.scr.annotations.Deactivate;
@@ -55,13 +62,6 @@
 import org.osgi.service.component.annotations.Activate;
 import org.slf4j.Logger;
 
-import java.net.InetAddress;
-import java.nio.ByteBuffer;
-import java.util.Map;
-
-import static org.onosproject.net.config.basics.SubjectFactories.APP_SUBJECT_FACTORY;
-import static org.slf4j.LoggerFactory.getLogger;
-
 /**
  * AAA application for ONOS.
  */
@@ -269,9 +269,13 @@
      */
     public void handleRadiusPacket(RADIUS radiusPacket)
             throws StateMachineException, DeserializationException {
+        if (log.isTraceEnabled()) {
+            log.trace("Received RADIUS packet {}", radiusPacket);
+        }
         StateMachine stateMachine = StateMachine.lookupStateMachineById(radiusPacket.getIdentifier());
         if (stateMachine == null) {
-            log.error("Invalid session identifier {}, exiting...", radiusPacket.getIdentifier());
+            log.error("Invalid packet identifier {}, could not find corresponding "
+                    + "state machine ... exiting", radiusPacket.getIdentifier());
             return;
         }
 
@@ -354,6 +358,11 @@
         TrafficTreatment treatment = DefaultTrafficTreatment.builder().setOutput(connectPoint.port()).build();
         OutboundPacket packet = new DefaultOutboundPacket(connectPoint.deviceId(),
                                                           treatment, ByteBuffer.wrap(ethernetPkt.serialize()));
+        if (log.isTraceEnabled()) {
+            EAPOL eap = ((EAPOL) ethernetPkt.getPayload());
+            log.trace("Sending eapol payload {} enclosed in {} to supplicant at {}",
+                      eap, ethernetPkt, connectPoint);
+        }
         packetService.emit(packet);
     }
 
@@ -433,12 +442,22 @@
             DeviceId deviceId = inPacket.receivedFrom().deviceId();
             PortNumber portNumber = inPacket.receivedFrom().port();
             String sessionId = deviceId.toString() + portNumber.toString();
-            StateMachine stateMachine = StateMachine.lookupStateMachineBySessionId(sessionId);
-            if (stateMachine == null) {
-                stateMachine = new StateMachine(sessionId);
+            EAPOL eapol = (EAPOL) ethPkt.getPayload();
+            if (log.isTraceEnabled()) {
+                log.trace("Received EAPOL packet {} in enclosing packet {} from "
+                        + "dev/port: {}/{}", eapol, ethPkt, deviceId,
+                          portNumber);
             }
 
-            EAPOL eapol = (EAPOL) ethPkt.getPayload();
+            StateMachine stateMachine = StateMachine.lookupStateMachineBySessionId(sessionId);
+            if (stateMachine == null) {
+                log.debug("Creating new state machine for sessionId: {} for "
+                                + "dev/port: {}/{}", sessionId, deviceId, portNumber);
+                stateMachine = new StateMachine(sessionId);
+            } else {
+                log.debug("Using existing state-machine for sessionId: {}", sessionId);
+            }
+
 
             switch (eapol.getEapolType()) {
                 case EAPOL.EAPOL_START:
diff --git a/src/main/java/org/opencord/aaa/SocketBasedRadiusCommunicator.java b/src/main/java/org/opencord/aaa/SocketBasedRadiusCommunicator.java
index fd6e495..e402aae 100755
--- a/src/main/java/org/opencord/aaa/SocketBasedRadiusCommunicator.java
+++ b/src/main/java/org/opencord/aaa/SocketBasedRadiusCommunicator.java
@@ -15,7 +15,18 @@
  */
 package org.opencord.aaa;
 
-import com.google.common.util.concurrent.ThreadFactoryBuilder;
+import static org.onosproject.net.packet.PacketPriority.CONTROL;
+import static org.slf4j.LoggerFactory.getLogger;
+
+import java.io.IOException;
+import java.net.DatagramPacket;
+import java.net.DatagramSocket;
+import java.net.InetAddress;
+import java.net.InetSocketAddress;
+import java.net.UnknownHostException;
+import java.util.concurrent.ExecutorService;
+import java.util.concurrent.Executors;
+
 import org.onlab.packet.DeserializationException;
 import org.onlab.packet.EthType;
 import org.onlab.packet.Ethernet;
@@ -28,17 +39,7 @@
 import org.onosproject.net.packet.PacketService;
 import org.slf4j.Logger;
 
-import java.io.IOException;
-import java.net.DatagramPacket;
-import java.net.DatagramSocket;
-import java.net.InetAddress;
-import java.net.InetSocketAddress;
-import java.net.UnknownHostException;
-import java.util.concurrent.ExecutorService;
-import java.util.concurrent.Executors;
-
-import static org.onosproject.net.packet.PacketPriority.CONTROL;
-import static org.slf4j.LoggerFactory.getLogger;
+import com.google.common.util.concurrent.ThreadFactoryBuilder;
 
 /**
  * Handles Socket based communication with the RADIUS server.
@@ -141,10 +142,11 @@
                 }
                 DatagramPacket packet =
                         new DatagramPacket(data, data.length, address, radiusServerPort);
-
+                if (log.isTraceEnabled()) {
+                    log.trace("Sending packet {} to Radius Server {}:{} using socket",
+                              radiusPacket, address, radiusServerPort);
+                }
                 socket.send(packet);
-                log.debug("Packet sent to Radius Server {}:{} using socket",
-                        address, radiusServerPort);
             } catch (UnknownHostException uhe) {
                 log.warn("Unable to resolve host {}", radiusHost);
             }
@@ -157,9 +159,11 @@
     public void handlePacketFromServer(PacketContext context) {
         InboundPacket pkt = context.inPacket();
         Ethernet ethPkt = pkt.parsed();
-
-        log.debug("Skipping Ethernet packet type {}",
-                EthType.EtherType.lookup(ethPkt.getEtherType()));
+        if (log.isTraceEnabled() && ethPkt.getEtherType() != Ethernet.TYPE_LLDP
+                && ethPkt.getEtherType() != Ethernet.TYPE_BSN) {
+            log.trace("Skipping Ethernet packet type {}",
+                      EthType.EtherType.lookup(ethPkt.getEtherType()));
+        }
     }
 
     class RadiusListener implements Runnable {