From 49a76d8716c1dd1d08fcf91dbfe05e1c16a7ec04 Mon Sep 17 00:00:00 2001 From: Ryan Slominski Date: Wed, 14 Feb 2024 12:11:26 -0500 Subject: [PATCH] Logging improvements (#17) Fixes #16 --- .../jlab/epics2web/controller/WebConsole.java | 3 +- .../jlab/epics2web/epics/ChannelManager.java | 75 ++++++++++++++++--- .../jlab/epics2web/epics/ChannelMonitor.java | 50 ++++++++++--- src/main/resources/logging.properties | 10 --- src/main/webapp/WEB-INF/views/console.jsp | 6 +- 5 files changed, 110 insertions(+), 34 deletions(-) delete mode 100644 src/main/resources/logging.properties diff --git a/src/main/java/org/jlab/epics2web/controller/WebConsole.java b/src/main/java/org/jlab/epics2web/controller/WebConsole.java index c5d3c40..014c156 100644 --- a/src/main/java/org/jlab/epics2web/controller/WebConsole.java +++ b/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 monitorMap = channelManager.getMonitorMap(); + Map monitorMap = channelManager.getMonitorMap(); Map> clientMap = sessionManager.getClientMap(); request.setAttribute("monitorMap", monitorMap); diff --git a/src/main/java/org/jlab/epics2web/epics/ChannelManager.java b/src/main/java/org/jlab/epics2web/epics/ChannelManager.java index ed59cac..8721db7 100644 --- a/src/main/java/org/jlab/epics2web/epics/ChannelManager.java +++ b/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 removeAll(PvListener listener) { * * @return The PV to monitor map */ - public Map getMonitorMap() { - Map map; - Map 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 getMonitorMap() { + // Really want readonly copy version here, but too lazy to make immutable ChannelMonitor + return new HashMap<>(monitorMap); } /** @@ -326,8 +381,6 @@ public Map getMonitorMap() { * @return The listener to PVs map */ public Map> getClientMap() { - Map> map; - map = Collections.unmodifiableMap(clientMap); - return map; + return Collections.unmodifiableMap(clientMap); } } diff --git a/src/main/java/org/jlab/epics2web/epics/ChannelMonitor.java b/src/main/java/org/jlab/epics2web/epics/ChannelMonitor.java index be53784..21c4f5a 100644 --- a/src/main/java/org/jlab/epics2web/epics/ChannelMonitor.java +++ b/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 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 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 diff --git a/src/main/resources/logging.properties b/src/main/resources/logging.properties deleted file mode 100644 index 3537e82..0000000 --- a/src/main/resources/logging.properties +++ /dev/null @@ -1,10 +0,0 @@ -handlers = org.apache.juli.FileHandler, java.util.logging.ConsoleHandler - -org.apache.juli.FileHandler.level = INFO -org.apache.juli.FileHandler.directory = ${catalina.base}/logs -org.apache.juli.FileHandler.prefix = epics2web. - -java.util.logging.ConsoleHandler.level = INFO -java.util.logging.ConsoleHandler.formatter = java.util.logging.SimpleFormatter - -org.jlab.level = INFO \ No newline at end of file diff --git a/src/main/webapp/WEB-INF/views/console.jsp b/src/main/webapp/WEB-INF/views/console.jsp index b275c4b..b8ccea6 100644 --- a/src/main/webapp/WEB-INF/views/console.jsp +++ b/src/main/webapp/WEB-INF/views/console.jsp @@ -63,6 +63,8 @@ PV + State + Last Update Clients @@ -70,7 +72,9 @@ - + + - +