Bug 317813: Add Discovery tracing in Java reference implementation

4 files changed, 211 insertions, 22 deletions

diff --git a/plugins/org.eclipse.tm.tcf.core/src/org/eclipse/tm/internal/tcf/core/LoggingUtil.java b/plugins/org.eclipse.tm.tcf.core/src/org/eclipse/tm/internal/tcf/core/LoggingUtil.java
new file mode 100644
index 000000000..68465b989
--- /dev/null
+++ b/plugins/org.eclipse.tm.tcf.core/src/org/eclipse/tm/internal/tcf/core/LoggingUtil.java
@@ -0,0 +1,63 @@
+/*******************************************************************************
+ * Copyright (c) 2010 Freescale Semiconductor, Inc. and others.
+ * All rights reserved. This program and the accompanying materials
+ * are made available under the terms of the Eclipse Public License v1.0
+ * which accompanies this distribution, and is available at
+ * http://www.eclipse.org/legal/epl-v10.html
+ *
+ * Contributors:
+ *     Freescale Semiconductor - initial API and implementation
+ *******************************************************************************/
+package org.eclipse.tm.internal.tcf.core;
+
+import java.text.DecimalFormatSymbols;
+
+import org.eclipse.tm.tcf.protocol.Protocol;
+
+/**
+ * Internal utility methods used for logging/tracing.
+ */
+public class LoggingUtil {
+
+    private static final char DECIMAL_DELIMITER = new DecimalFormatSymbols().getDecimalSeparator();
+
+    /**
+     * Returns a relative timestamp in the form "seconds,milliseconds". Each
+     * segment is zero-padded to three digits, ensuring a consistent length of
+     * seven characters. The timestamp has no absolute meaning. It is merely the
+     * elapsed time since January 1, 1970 UT truncated at 999 seconds. Do not
+     * use this for production code, especially for mathematically determining
+     * the relative time between two events, since the counter will flip to zero
+     * roughly every 16 minutes.
+     */
+    public static String getDebugTime() {
+        StringBuilder traceBuilder = new StringBuilder();
+
+        // Record the time
+        long time = System.currentTimeMillis();
+        long seconds = (time / 1000) % 1000;
+        if (seconds < 100) traceBuilder.append('0');
+        if (seconds < 10) traceBuilder.append('0');
+        traceBuilder.append(seconds);
+        traceBuilder.append(DECIMAL_DELIMITER);
+        long millis = time % 1000;
+        if (millis < 100) traceBuilder.append('0');
+        if (millis < 10) traceBuilder.append('0');
+        traceBuilder.append(millis);
+        return traceBuilder.toString();
+    }
+
+    /**
+     * Trace hooks should use this method to log a message. It prepends the
+     * message with a timestamp and sends it to the TCF logger facility. The
+     * logger implementation may or may not inject its own timestamp. For
+     * tracing, we definitely need one, so we introduce a minimal, relative-time
+     * stamp.
+     *
+     * @param msg
+     *            the trace message
+     */
+    public static void trace(String msg) {
+        Protocol.log(LoggingUtil.getDebugTime() + ' ' + msg, null);
+    }
+}
diff --git a/plugins/org.eclipse.tm.tcf.core/src/org/eclipse/tm/internal/tcf/services/local/LocatorService.java b/plugins/org.eclipse.tm.tcf.core/src/org/eclipse/tm/internal/tcf/services/local/LocatorService.java
index 03a940fcb..b6bd9b52c 100644
--- a/plugins/org.eclipse.tm.tcf.core/src/org/eclipse/tm/internal/tcf/services/local/LocatorService.java
+++ b/plugins/org.eclipse.tm.tcf.core/src/org/eclipse/tm/internal/tcf/services/local/LocatorService.java
@@ -10,6 +10,7 @@
  *******************************************************************************/
 package org.eclipse.tm.internal.tcf.services.local;
 
+import java.io.UnsupportedEncodingException;
 import java.lang.reflect.Method;
 import java.net.DatagramPacket;
 import java.net.DatagramSocket;
@@ -25,8 +26,10 @@ import java.util.HashSet;
 import java.util.Iterator;
 import java.util.List;
 import java.util.Map;
+import java.util.Map.Entry;
 
 import org.eclipse.tm.internal.tcf.core.LocalPeer;
+import org.eclipse.tm.internal.tcf.core.LoggingUtil;
 import org.eclipse.tm.internal.tcf.core.RemotePeer;
 import org.eclipse.tm.internal.tcf.core.ServiceManager;
 import org.eclipse.tm.internal.tcf.core.TransportManager;
@@ -67,6 +70,12 @@ public class LocatorService implements ILocator {
 
     private InetAddress loopback_addr;
 
+    /**
+     * Flag indicating whether tracing of the the discovery activity is enabled
+     * or not.
+     */
+    static boolean TRACE_DISCOVERY = System.getProperty("org.eclipse.tm.tcf.core.tracing.discovery") != null;
+
     private static class SubNet {
         final int prefix_length;
         final InetAddress address;
@@ -294,9 +303,15 @@ public class LocatorService implements ILocator {
             out_buf[7] = 0;
             try {
                 socket = new DatagramSocket(DISCOVEY_PORT);
+                if (TRACE_DISCOVERY) {
+                    LoggingUtil.trace("Became the master agent (bound to port " + socket.getLocalPort() + ")");
+                }
             }
             catch (SocketException x) {
                 socket = new DatagramSocket();
+                if (TRACE_DISCOVERY) {
+                    LoggingUtil.trace("Became a slave agent (bound to port " + socket.getLocalPort() + ")");
+                }
             }
             socket.setBroadcast(true);
             input_thread.setName("TCF Locator Receiver");
@@ -607,6 +622,13 @@ public class LocatorService implements ILocator {
             if (subnets.contains(s)) continue;
             subnets.add(s);
         }
+        if (TRACE_DISCOVERY) {
+            StringBuilder str = new StringBuilder("Refreshed subnet list:");
+            for (SubNet subnet : subnets) {
+                str.append("\n\t* address=" + subnet.address + ", broadcast=" + subnet.broadcast);
+            }
+            LoggingUtil.trace(str.toString());
+        }
     }
 
     private byte[] getUTF8Bytes(String s) {
@@ -619,6 +641,15 @@ public class LocatorService implements ILocator {
         }
     }
 
+    /** Used for tracing */
+    private static String packetTypes[] = new String[] {
+            null,
+            "CONF_REQ_INFO",
+            "CONF_PEER_INFO",
+            "CONF_REQ_SLAVES",
+            "CONF_SLAVES_INFO"
+    };
+
     private boolean sendDatagramPacket(SubNet subnet, int size, InetAddress addr, int port) {
         try {
             if (addr == null) {
@@ -631,6 +662,14 @@ public class LocatorService implements ILocator {
             if (!subnet.contains(addr)) return false;
             if (port == socket.getLocalPort() && addr.equals(subnet.address)) return false;
             socket.send(new DatagramPacket(out_buf, size, addr, port));
+
+            if (TRACE_DISCOVERY) {
+                Map<String,String> map = null;
+                if (out_buf[4] == CONF_PEER_INFO) {
+                    parsePeerAtrributes(out_buf, 8);
+                }
+                traceDiscoveryPacket(false, packetTypes[out_buf[4]], map, addr, port);
+            }
         }
         catch (Exception x) {
             log("Cannot send datagram packet to " + addr, x);
@@ -639,6 +678,37 @@ public class LocatorService implements ILocator {
         return true;
     }
 
+    /**
+     * Parse peer attributes in CONF_INFO_PEER packet data
+     *
+     * @param data
+     *            the packet section that contain the peer attributes
+     * @param size
+     *            the number of bytes in [data] that contain peer attributes
+     * @return a map containing the attributes
+     * @throws UnsupportedEncodingException
+     */
+    private static Map<String,String> parsePeerAtrributes(byte[] data, int size) throws UnsupportedEncodingException {
+        Map<String,String> map = new HashMap<String,String>();
+        String s = new String(data, 8, size - 8, "UTF-8");
+        int l = s.length();
+        int i = 0;
+        while (i < l) {
+            int i0 = i;
+            while (i < l && s.charAt(i) != '=' && s.charAt(i) != 0) i++;
+            int i1 = i;
+            if (i < l && s.charAt(i) == '=') i++;
+            int i2 = i;
+            while (i < l && s.charAt(i) != 0) i++;
+            int i3 = i;
+            if (i < l && s.charAt(i) == 0) i++;
+            String key = s.substring(i0, i1);
+            String val = s.substring(i2, i3);
+            map.put(key, val);
+        }
+        return map;
+    }
+
     private void sendPeersRequest(InetAddress addr, int port) {
         out_buf[4] = CONF_REQ_INFO;
         for (SubNet subnet : subnets) {
@@ -806,27 +876,14 @@ public class LocatorService implements ILocator {
 
     private void handlePeerInfoPacket(DatagramPacket p) {
         try {
-            Map<String,String> map = new HashMap<String,String>();
-            String s = new String(p.getData(), 8, p.getLength() - 8, "UTF-8");
-            int l = s.length();
-            int i = 0;
-            while (i < l) {
-                int i0 = i;
-                while (i < l && s.charAt(i) != '=' && s.charAt(i) != 0) i++;
-                int i1 = i;
-                if (i < l && s.charAt(i) == '=') i++;
-                int i2 = i;
-                while (i < l && s.charAt(i) != 0) i++;
-                int i3 = i;
-                if (i < l && s.charAt(i) == 0) i++;
-                String key = s.substring(i0, i1);
-                String val = s.substring(i2, i3);
-                map.put(key, val);
-            }
+            Map<String,String> map = parsePeerAtrributes(p.getData(), p.getLength());
             String id = map.get(IPeer.ATTR_ID);
             if (id == null) throw new Exception("Invalid peer info: no ID");
             InetAddress peer_addr = getInetAddress(map.get(IPeer.ATTR_IP_HOST));
             if (peer_addr == null) return;
+            if (TRACE_DISCOVERY) {
+                traceDiscoveryPacket(true, "CONF_PEER_INFO", map, p);
+            }
             for (SubNet subnet : subnets) {
                 if (!subnet.contains(peer_addr)) continue;
                 IPeer peer = peers.get(id);
@@ -845,6 +902,9 @@ public class LocatorService implements ILocator {
     }
 
     private void handleReqInfoPacket(DatagramPacket p, Slave sl, long time) {
+        if (TRACE_DISCOVERY) {
+            traceDiscoveryPacket(true, "CONF_REQ_INFO", null, p);
+        }
         sendAll(p.getAddress(), p.getPort(), sl, time);
     }
 
@@ -868,6 +928,9 @@ public class LocatorService implements ILocator {
                 if (i < l && s.charAt(i) == 0) i++;
                 int port = Integer.parseInt(s.substring(port0, port1));
                 if (port != DISCOVEY_PORT) {
+                    if (TRACE_DISCOVERY) {
+                        traceDiscoveryPacket(true, "CONF_SLAVES_INFOS", null, p);
+                    }
                     String host = s.substring(host0, host1);
                     InetAddress addr = getInetAddress(host);
                     if (addr != null) {
@@ -890,6 +953,9 @@ public class LocatorService implements ILocator {
     }
 
     private void handleReqSlavesPacket(DatagramPacket p, Slave sl, long time) {
+        if (TRACE_DISCOVERY) {
+            traceDiscoveryPacket(true, "CONF_REQ_SLAVES", null, p);
+        }
         if (sl != null) sl.last_req_slaves_time = time;
         sendSlavesInfo(p.getAddress(), p.getPort(),  time);
     }
@@ -927,4 +993,42 @@ public class LocatorService implements ILocator {
         assert Protocol.isDispatchThread();
         listeners.remove(listener);
     }
+
+    /**
+     * Log that a TCF Discovery packet has be sent or received. The trace is
+     * sent to stdout. This should be called only if the tracing has been turned
+     * on via java property definitions.
+     *
+     * @param received
+     *            true if the packet was sent, otherwise it was received
+     * @param type
+     *            a string specifying the type of packet, e.g., "CONF_PEER_INFO"
+     * @param attrs
+     *            a set of attributes relevant to the type of packet (typically
+     *            a peer's attributes)
+     * @param addr
+     *            the network address the packet is being sent to
+     * @param port
+     *            the port the packet is being sent to
+     */
+    private static void traceDiscoveryPacket(boolean received, String type, Map<String,String> attrs, InetAddress addr, int port) {
+        assert TRACE_DISCOVERY;
+        StringBuilder str = new StringBuilder(type + (received ? " received from " : " sent to ") +  addr + "/" + port);
+        if (attrs != null) {
+            Iterator<Entry<String, String>> iter = attrs.entrySet().iterator();
+            while (iter.hasNext()) {
+                Entry<String, String> entry = iter.next();
+                str.append("\n\t" + entry.getKey() + '=' + entry.getValue());
+            }
+        }
+        LoggingUtil.trace(str.toString());
+    }
+
+    /**
+     * Convenience variant that takes a DatagramPacket for specifying the target address and
+     * port
+     */
+    private static void traceDiscoveryPacket(boolean received, String type, Map<String,String> attrs, DatagramPacket packet) {
+        traceDiscoveryPacket(received, type, attrs, packet.getAddress(), packet.getPort());
+    }
 }
diff --git a/plugins/org.eclipse.tm.tcf/.options b/plugins/org.eclipse.tm.tcf/.options
new file mode 100644
index 000000000..38d422df7
--- /dev/null
+++ b/plugins/org.eclipse.tm.tcf/.options
@@ -0,0 +1,2 @@
+org.eclipse.tm.tcf/debug = false

+org.eclipse.tm.tcf/debug/discovery = false

diff --git a/plugins/org.eclipse.tm.tcf/src/org/eclipse/tm/tcf/Activator.java b/plugins/org.eclipse.tm.tcf/src/org/eclipse/tm/tcf/Activator.java
index 2bbdc981e..a106d9c42 100644
--- a/plugins/org.eclipse.tm.tcf/src/org/eclipse/tm/tcf/Activator.java
+++ b/plugins/org.eclipse.tm.tcf/src/org/eclipse/tm/tcf/Activator.java
@@ -49,6 +49,9 @@ public class Activator extends Plugin {
         }
     };
 
+    /** Eclipse tracing option, plug-in wide */
+    private static boolean TRACE;
+
     /**
      * Constructor.
      */
@@ -73,17 +76,34 @@ public class Activator extends Plugin {
     public void start(BundleContext context) throws Exception {
         super.start(context);
         debug = Platform.inDebugMode();
+
+        TRACE = "true".equals(Platform.getDebugOption("org.eclipse.tm.tcf/debug")); //$NON-NLS-1$
+        if (TRACE && "true".equals(Platform.getDebugOption("org.eclipse.tm.tcf/debug/discovery"))) {
+            System.setProperty("org.eclipse.tm.tcf.core.tracing.discovery", "true");
+        }
+
         ChannelTCP.setSSLContext(TCFSecurityManager.createSSLContext());
         Protocol.setLogger(new ILogger() {
 
             public void log(String msg, Throwable x) {
-                if (debug) {
-                    System.err.println(msg);
+                // Normally, we hook the TCF logging service (ILogger) to the
+                // Plug-in logger. Trace hooks in the code use the TCF logger.
+                // The Plug-in logger isn't really designed for large amounts of
+                // trace data, though, so redirect to stdout when tracing is
+                // enabled.
+                if (TRACE) {
+                    System.out.println(msg);
                     if (x != null) x.printStackTrace();
                 }
-                if (plugin != null && getLog() != null) {
-                    getLog().log(new Status(IStatus.ERROR,
-                            getBundle().getSymbolicName(), IStatus.OK, msg, x));
+                else {
+                    if (debug) {
+                        System.err.println(msg);
+                        if (x != null) x.printStackTrace();
+                    }
+                    if (plugin != null && getLog() != null) {
+                        getLog().log(new Status(IStatus.ERROR,
+                                getBundle().getSymbolicName(), IStatus.OK, msg, x));
+                    }
                 }
             }
         });