Logging improvements (#17)

Fixes #16

Author: slominskir

src/main/java/org/jlab/epics2web/controller/WebConsole.java

@@ -10,6 +10,7 @@
 import javax.servlet.http.HttpServletResponse;
 import javax.websocket.Session;
 import org.jlab.epics2web.Application;
+import org.jlab.epics2web.epics.ChannelMonitor;
 import org.jlab.epics2web.websocket.WebSocketSessionManager;
 import org.jlab.epics2web.epics.ChannelManager;
 
@@ -38,7 +39,7 @@ protected void doGet(HttpServletRequest request, HttpServletResponse response)
             throws ServletException, IOException {
 
 
-        Map<String, Integer> monitorMap = channelManager.getMonitorMap();
+        Map<String, ChannelMonitor> monitorMap = channelManager.getMonitorMap();
         Map<Session, Set<String>> clientMap = sessionManager.getClientMap();
 
         request.setAttribute("monitorMap", monitorMap);

src/main/java/org/jlab/epics2web/epics/ChannelManager.java

@@ -9,6 +9,7 @@
 import org.jlab.util.LockAcquisitionTimeoutException;
 
 import java.io.IOException;
+import java.io.UnsupportedEncodingException;
 import java.util.ArrayList;
 import java.util.Collections;
 import java.util.HashMap;
@@ -68,6 +69,65 @@ public ChannelManager(CAJContext context, ScheduledExecutorService timeoutExecut
         this.callbackExecutor = callbackExecutor;
     }
 
+    public static String getDbrValueAsString(DBR dbr) {
+        String strValue = null;
+        if(dbr == null){
+            strValue = "";
+        } else if (dbr.isDOUBLE()) {
+            double value = ((gov.aps.jca.dbr.DOUBLE) dbr).getDoubleValue()[0];
+            if (Double.isFinite(value)) {
+                strValue = String.valueOf(value);
+            } else if (Double.isNaN(value)) {
+                strValue = "NaN";
+            } else {
+                strValue = "Infinity";
+            }
+        } else if (dbr.isFLOAT()) {
+            float value = ((gov.aps.jca.dbr.FLOAT) dbr).getFloatValue()[0];
+            if (Float.isFinite(value)) {
+                strValue = String.valueOf(value);
+            } else if (Float.isNaN(value)) {
+                strValue = "NaN";
+            } else {
+                strValue = "Infinity";
+            }
+        } else if (dbr.isINT()) {
+            int value = ((gov.aps.jca.dbr.INT) dbr).getIntValue()[0];
+            strValue = String.valueOf(value);
+        } else if (dbr.isSHORT()) {
+            short value = ((gov.aps.jca.dbr.SHORT) dbr).getShortValue()[0];
+            strValue = String.valueOf(value);
+        } else if (dbr.isENUM()) {
+            short value = ((gov.aps.jca.dbr.ENUM) dbr).getEnumValue()[0];
+            strValue = String.valueOf(value);
+        } else if (dbr.isBYTE()) {
+            byte[] value = ((gov.aps.jca.dbr.BYTE) dbr).getByteValue();
+            int len = value.length;
+            if (len > 1) {
+                // epics2web generally doesn't handle arrays,
+                // but for BYTE[] assume that data is really "long string".
+                // Text ends at first '\0' or end of array
+                for (int i=0; i<len; ++i)
+                    if (value[i] == 0) {
+                        len = i;
+                        break;
+                    }
+                try {
+                    strValue = new String(value, 0, len, "UTF-8");
+                } catch(UnsupportedEncodingException e) {
+                    throw new RuntimeException("JVM doesn't support UTF-8!");
+                }
+            }
+            else
+                strValue = String.valueOf(value[0]);
+        } else {
+            String value = ((gov.aps.jca.dbr.STRING) dbr).getStringValue()[0];
+            strValue = value;
+        }
+
+        return strValue;
+    }
+
     public void addValueToJSON(JsonObjectBuilder builder, DBR dbr) {
         try {
             if (dbr.isDOUBLE()) {
@@ -309,14 +369,9 @@ public Map<String, Exception> removeAll(PvListener listener) {
      *
      * @return The PV to monitor map
      */
-    public Map<String, Integer> getMonitorMap() {
-        Map<String, Integer> map;
-        Map<String, ChannelMonitor> copy = new HashMap<>(monitorMap); // First copy map so that concurrent changes won't bother us
-        map = new HashMap<>();
-        for (String pv : copy.keySet()) {
-            map.put(pv, copy.get(pv).getListenerCount());
-        }
-        return map;
+    public Map<String, ChannelMonitor> getMonitorMap() {
+        // Really want readonly copy version here, but too lazy to make immutable ChannelMonitor
+        return new HashMap<>(monitorMap);
     }
 
     /**
@@ -326,8 +381,6 @@ public Map<String, Integer> getMonitorMap() {
      * @return The listener to PVs map
      */
     public Map<PvListener, Set<String>> getClientMap() {
-        Map<PvListener, Set<String>> map;
-        map = Collections.unmodifiableMap(clientMap);
-        return map;
+        return Collections.unmodifiableMap(clientMap);
     }
 }

src/main/java/org/jlab/epics2web/epics/ChannelMonitor.java

@@ -15,6 +15,7 @@
 import gov.aps.jca.event.MonitorListener;
 import java.io.Closeable;
 import java.io.IOException;
+import java.util.Date;
 import java.util.Set;
 import java.util.concurrent.*;
 import java.util.concurrent.atomic.AtomicReference;
@@ -27,14 +28,19 @@
  *
  * @author slominskir
  */
-class ChannelMonitor implements Closeable {
+public class ChannelMonitor implements Closeable {
 
     private static final Logger LOGGER = Logger.getLogger(ChannelMonitor.class.getName());
 
-    public static final int PEND_IO_MILLIS = 3000;
     public static final long TIMEOUT_MILLIS = 3000;
 
     private volatile DBR lastDbr = null;
+
+    /**
+     * We don't use TIME typed DBR, so we just track 'received' timestamp (which may differ from IOC 'generated' timestamp)
+     */
+    private volatile Date lastTimestamp = null;
+
     private final AtomicReference<MonitorState> state = new AtomicReference<>(MonitorState.CONNECTING); // We don't use CAJChannel.getConnectionState() because we want to still be "connecting" during enum label fetch
     private final AtomicReference<String[]> enumLabels = new AtomicReference<>(null); // volatile arrays are unsafe due to individual indicies so use AtomicReference instead 
     private Monitor monitor = null; // Keep track of singleton monitor to avoid creating multiple on reconnect after disconnect
@@ -75,10 +81,12 @@ public ChannelMonitor(String pv, CAJContext context, ScheduledExecutorService ti
         this.timeoutExecutor = timeoutExecutor;
         this.callbackExecutor = callbackExecutor;
 
-        //LOGGER.log(Level.FINEST, "Creating channel: {0}", pv);
+        long start = System.currentTimeMillis();
         channel = (CAJChannel) context.createChannel(pv, new TimedChannelConnectionListener());
-
         context.flushIO();
+        long stop = System.currentTimeMillis();
+        float elapsedSeconds = (stop - start) / 1000.0f;
+        LOGGER.log(Level.FINEST, "Created channel {0} in {1} seconds", new Object[]{pv, elapsedSeconds});
     }
 
     /**
@@ -125,6 +133,18 @@ public int getListenerCount() {
         return listeners.size();
     }
 
+    public MonitorState getState() {
+        return state.get();
+    }
+
+    public String getLastValue() {
+        return ChannelManager.getDbrValueAsString(lastDbr);
+    }
+
+    public Date getLastTimestamp() {
+        return lastTimestamp;
+    }
+
     /**
      * Close the ChannelMonitor.
      *
@@ -136,8 +156,12 @@ public void close() throws IOException {
         if (channel != null) {
             try {
                 // channel.destroy(); // method is unsafe (can deadlock)
-                // so use context method instead                
+                // so use context method instead
+                long start = System.currentTimeMillis();
                 context.destroyChannel(channel, false); // Don't force because ChannelManager.get() also uses same context!
+                long stop = System.currentTimeMillis();
+                float elapsedSeconds = (stop - start) / 1000.0f;
+                LOGGER.log(Level.FINEST, "Closed Channel {0} in {1} seconds", new Object[]{pv, elapsedSeconds});
             } catch (CAException e) {
                 throw new IOException("Unable to close channel", e);
             }
@@ -207,7 +231,7 @@ public Void call() throws Exception {
                     boolean connected = (state.get() == MonitorState.CONNECTED);
 
                     if (!connected) {
-                        //LOGGER.log(Level.WARNING, "Unable to connect to channel (timeout)");
+                        LOGGER.log(Level.FINE, "Unable to connect to channel {0} (timeout)", pv);
 
                         notifyPvInfoAll(false);
                     }
@@ -228,7 +252,7 @@ public void connectionChanged(ConnectionEvent ce) {
             callbackExecutor.submit(new Runnable(){
                 @Override
                 public void run() {
-                    //LOGGER.log(Level.FINEST, "Connection Changed - Connected: {0}", ce.isConnected());
+                    LOGGER.log(Level.FINEST, "Channel {0} Connection Changed - Connected: {1}", new Object[]{pv, ce.isConnected()});
 
                     try {
                         future.cancel(false); // only needed for initial connection, on reconnects this will result in "false" return value, which is ignored
@@ -242,8 +266,7 @@ public void run() {
                                 handleRegularConnectionOrReconnect();
                             }
                         } else {
-                            //CAJChannel c = (CAJChannel) ce.getSource();
-                            //LOGGER.log(Level.WARNING, "Unable to connect to channel: {0}", c.getName());
+                            LOGGER.log(Level.FINE, "Notifying clients of disconnect from channel: {0}", pv);
 
                             state.set(MonitorState.DISCONNECTED);
                             notifyPvInfoAll(false);
@@ -265,9 +288,10 @@ public void run() {
          */
         private void handleRegularConnectionOrReconnect() throws
                 IllegalStateException, CAException {
-            // Only create monitor on first connect, afterwards reconnect uses same old monitor
+            // Only create monitor on first connect, afterward reconnect uses same old monitor
             synchronized (this) {
                 if (monitor == null) {
+                    LOGGER.log(Level.FINEST, "Creating {0} Channel Monitor", pv);
                     // We generally don't handle arrays,
                     // except for BYTE[], where we assume a "long string"
                     int count = 1;
@@ -276,6 +300,8 @@ private void handleRegularConnectionOrReconnect() throws
                         count = channel.getElementCount();
                     monitor = channel.addMonitor(channel.getFieldType(), count, Monitor.VALUE, new ChannelMonitorListener());
                     context.flushIO();
+                } else {
+                    LOGGER.log(Level.FINEST, "Reusing existing {0} Channel Monitor", pv);
                 }
             }
 
@@ -291,13 +317,14 @@ private void handleRegularConnectionOrReconnect() throws
          * @throws CAException If unable to initialize
          */
         private void handleEnumConnection() throws IllegalStateException, CAException {
+            LOGGER.log(Level.FINEST, "Fetching enum labels for {0}", pv);
             channel.get(DBRType.LABELS_ENUM, 1, new TimedChannelEnumGetListener());
 
             context.flushIO();
         }
 
         /**
-         * A private inner inner class to respond to an enum label caget.
+         * A private inner class to respond to an enum label caget.
          */
         private class TimedChannelEnumGetListener implements GetListener {
 
@@ -352,6 +379,7 @@ public void monitorChanged(MonitorEvent me) {
             DBR dbr = me.getDBR();
 
             lastDbr = dbr;
+            lastTimestamp = new Date();
 
             // Make sure handlers do not call back into CA lib on this callback thread.
             // We could call in separate thread, but that's costly and then you must

src/main/resources/logging.properties

@@ -63,14 +63,18 @@
             <thead>
                 <tr>
                     <th>PV</th>
+                    <th>State</th>
+                    <th>Last Update</th>
                     <th>Clients</th>
                 </tr>
             </thead>
             <tbody>
                 <c:forEach items="${monitorMap}" var="monitor">
                     <tr>
                         <td><c:out value="${monitor.key}"/></td>
-                        <td><c:out value="${monitor.value}"/></td>
+                        <td><c:out value="${monitor.value.state}"/></td>
+                        <td><fmt:formatDate pattern="MMM dd yyy HH:mm:ss" value="${monitor.value.lastTimestamp}"/> - <c:out value="${monitor.value.lastValue}"/></td>
+                        <td><c:out value="${monitor.value.listenerCount}"/></td>
                     </tr>
                 </c:forEach>
             </tbody>