Skip to content

Commit

Permalink
Logging improvements (#17)
Browse files Browse the repository at this point in the history 
Fixes #16
  • Loading branch information
@slominskir
slominskir committed Feb 14, 2024
1 parent 8a13828 commit 49a76d8
Show file tree
Hide file tree
Showing 5 changed files with 110 additions and 34 deletions.
3 changes: 2 additions & 1 deletion src/main/java/org/jlab/epics2web/controller/WebConsole.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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;

Expand Down Expand Up @@ -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);
Expand Down
75 changes: 64 additions & 11 deletions src/main/java/org/jlab/epics2web/epics/ChannelManager.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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()) {
Expand Down Expand Up @@ -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);
}

/**
Expand All @@ -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);
}
}
50 changes: 39 additions & 11 deletions src/main/java/org/jlab/epics2web/epics/ChannelMonitor.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand All @@ -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
Expand Down Expand Up @@ -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});
}

/**
Expand Down Expand Up @@ -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.
*
Expand All @@ -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);
}
Expand Down Expand Up @@ -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);
}
Expand All @@ -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
Expand All @@ -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);
Expand All @@ -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;
Expand All @@ -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);
}
}

Expand All @@ -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 {

Expand Down Expand Up @@ -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
Expand Down
10 changes: 0 additions & 10 deletions src/main/resources/logging.properties
View file

This file was deleted.

6 changes: 5 additions & 1 deletion src/main/webapp/WEB-INF/views/console.jsp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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>
Expand Down

0 comments on commit 49a76d8

Please sign in to comment.