work on this huge structured logging rabbit hole

In order to test some of the new renderers, you can call: q2 -Dlog.simple=false -Dlog.xml=true or q2 -Dlog.simple=false -Dlog.json=true or q2 -Dlog.simple=false -Dlog.markdown=true Without these properties (that can also be placed in the environment, or config YAML file, the system uses the previous (jPOS 2) log format.
jpos · Aug 26, 2024 · 7218c3e · 7218c3e
1 parent 00fec3a
commit 7218c3e
Show file tree

Hide file tree

Showing 13 changed files with 196 additions and 50 deletions.
diff --git a/jpos/src/dist/deploy/00_logger.xml b/jpos/src/dist/deploy/00_logger.xml
@@ -1,11 +1,27 @@
 <?xml version="1.0" encoding="UTF-8"?>
 
-<logger name="Q2" class="org.jpos.q2.qbean.LoggerAdaptor">
+<logger name="Q2" class="org.jpos.q2.qbean.LoggerAdaptor" realm="system">
   <property name="redirect" value="stdout, stderr" />
-  <!-- log-listener class="org.jpos.util.FlatLogListener" /-->
-  <log-listener class="org.jpos.util.SimpleLogListener" />
 
-  <log-listener class="org.jpos.util.DailyLogListener">
+  <log-listener class="org.jpos.util.SimpleLogListener" enabled="${log.simple:true}" />
+
+  <log-listener class="org.jpos.util.SimpleLogListener" enabled="${log.xml:false}">
+    <writer class="org.jpos.util.XmlLogWriter" enabled="true" />
+  </log-listener>
+
+  <log-listener class="org.jpos.util.SimpleLogListener" enabled="${log.json:false}">
+    <writer class="org.jpos.util.JsonLogWriter" enabled="true" />
+  </log-listener>
+
+  <log-listener class="org.jpos.util.SimpleLogListener" enabled="${log.markdown:false}">
+    <writer class="org.jpos.util.MarkdownLogWriter" enabled="true" />
+  </log-listener>
+
+<!--  <log-listener class="org.jpos.util.SimpleLogListener" enabled="true">-->
+<!--    <writer class="org.jpos.util.TxtLogWriter" enabled="true" />-->
+<!--  </log-listener>-->
+
+  <log-listener class="org.jpos.util.DailyLogListener" enabled="true">
     <property name="window" value="86400" /> <!-- optional, default one day -->
     <!--needed-->
     <property name="prefix" value="log/q2" />

diff --git a/jpos/src/main/java/org/jpos/iso/ISOServer.java b/jpos/src/main/java/org/jpos/iso/ISOServer.java
@@ -42,10 +42,10 @@
 import org.jpos.core.Configuration;
 import org.jpos.core.ConfigurationException;
 import org.jpos.jfr.ChannelEvent;
+import org.jpos.log.AuditLogEvent;
+import org.jpos.log.evt.*;
 import org.jpos.util.*;
 
-import static org.jpos.jfr.ChannelEvent.*;
-
 /**
  * Accept ServerChannel sessions and forwards them to ISORequestListeners
  * @author Alejandro P. Revilla
@@ -96,6 +96,7 @@ private enum PermLogPolicy {
     private int permitsCount = DEFAULT_MAX_SESSIONS;
     private static final long SMALL_RELAX = 250;
     private static final long LONG_RELAX = 5000;
+    private final UUID uuid = UUID.randomUUID();
 
    /**
     * @param port port to listen
@@ -259,19 +260,13 @@ private void shutdownChannels () {
             }
         }
     }
-    private void purgeChannels () {
-        Iterator iter = channels.entrySet().iterator();
-        while (iter.hasNext()) {
-            Map.Entry entry = (Map.Entry) iter.next();
-            WeakReference ref = (WeakReference) entry.getValue();
-            ISOChannel c = (ISOChannel) ref.get ();
-            if (c == null || !c.isConnected()) {
-                iter.remove ();
-            }
-        }
+    private void purgeChannels() {
+        channels.entrySet().removeIf(entry -> {
+            ISOChannel channel = entry.getValue().get();
+            return channel == null || !channel.isConnected();
+        });
     }
 
-
     @Override
     public ServerSocket createServerSocket(int port) throws IOException {
         ServerSocket ss = new ServerSocket();
@@ -309,16 +304,27 @@ protected Session(ServerChannel channel) {
         public void run() {
             setChanged ();
             notifyObservers ();
+            UUID sessionUUID = uuid;
+            String sessionInfo = "";
             if (channel instanceof BaseChannel baseChannel) {
-                LogEvent ev = new LogEvent (this, "session-start", connectionCount.get() + "/" + permitsCount);
                 Socket socket = baseChannel.getSocket ();
+                sessionInfo = socket.toString();
+                sessionUUID = getSocketUUID(socket);
+                LogEvent ev = new LogEvent()
+                  .withSource(this)
+                  .withTraceId(sessionUUID)
+                  .add(new SessionStart(connectionCount.get(), permitsCount, sessionInfo)
+                );
                 if (!checkPermission (socket, ev))
                     return;
                 realm = realm + "/" + socket.getInetAddress().getHostAddress() + ":" + socket.getPort();
                 if (clientSideChannel instanceof BaseChannel bc)
                     baseChannel.setCounters(bc.getMsgInCounter(), bc.getMsgOutCounter());
             }
             try {
+                WeakReference<ISOChannel> wr = new WeakReference<> (channel);
+                channels.put (channel.getName(), wr);
+                channels.put (LAST, wr); // we are most likely the last one
                 while (true) try {
                     ISOMsg m = channel.receive();
                     lastTxn = System.currentTimeMillis();
@@ -353,7 +359,12 @@ public void run() {
                 Logger.log (new LogEvent (this, "session-error", ex));
                 fireEvent(new ISOServerClientDisconnectEvent(ISOServer.this, channel));
             }
-            Logger.log (new LogEvent (this, "session-end ", connectionCount.decrementAndGet() + "/" + permitsCount));
+            Logger.log(new LogEvent()
+              .withSource(this)
+              .withTraceId(sessionUUID)
+              .add(new SessionEnd(connectionCount.get(), permitsCount, sessionInfo)
+              )
+            );
         }
         @Override
         public void setLogger (Logger logger, String realm) {
@@ -462,16 +473,12 @@ public void run() {
                 if (permits.availablePermits() <= 0) {
                     LockSupport.parkNanos(Duration.ofMillis(SMALL_RELAX).toNanos());
                     if (round % 240 == 0 && cfg.getBoolean("permits-exhaustion-warning", true)) {
-                        log ("warn", "permits exhausted " + serverSocket.toString());
+                        log(new Warning("permits exhausted " + serverSocket.toString()));
                     }
                     continue;
                 }
                 serverSocket = socketFactory.createServerSocket(port);
-                log ("iso-server",
-                    "listening on " + (bindAddr != null ? bindAddr + ":" : "port ") + port
-                    + ", permits=" + permits.availablePermits()
-                    + (backlog > 0 ? ", backlog="+backlog : "")
-                );
+                log (new Listen(port, bindAddr, permits.availablePermits(), backlog));
                 while (!shutdown) {
                     try {
                         if (permits.availablePermits() <= 0) {
@@ -483,21 +490,17 @@ public void run() {
                                 serverSocket.close();
                                 fireEvent(new ISOServerShutdownEvent(this));
                             } catch (IOException e){
-                                log ("iso-server", Caller.info() + ":" + e.getMessage());
+                                log (new ThrowableAuditLogEvent(e));
                             } finally {
                                 jfr.commit();
                             }
                             continue serverLoop;
                         }
                         final ServerChannel channel = (ServerChannel) clientSideChannel.clone();
                         channel.accept (serverSocket);
-
                         if (connectionCount.getAndIncrement() % 100 == 0) {
                             purgeChannels ();
                         }
-                        WeakReference<ISOChannel> wr = new WeakReference<> (channel);
-                        channels.put (channel.getName(), wr);
-                        channels.put (LAST, wr);
                         executor.submit (() -> {
                             try {
                                 permits.acquireUninterruptibly();
@@ -514,17 +517,17 @@ public void run() {
                         }
                     } catch (SocketException e) {
                         if (!shutdown) {
-                            Logger.log (new LogEvent (this, "iso-server", e));
+                            log (new ThrowableAuditLogEvent(e));
                             relax();
                             continue serverLoop;
                         }
                     } catch (IOException e) {
-                        Logger.log (new LogEvent (this, "iso-server", e));
+                        log (new ThrowableAuditLogEvent(e));
                         relax();
                     }
                 } // while !shutdown
             } catch (Throwable e) {
-                Logger.log (new LogEvent (this, "iso-server", e));
+                log (new ThrowableAuditLogEvent(e));
                 relax();
             }
         }
@@ -552,7 +555,7 @@ public void setName (String name) {
     public static ISOServer getServer (String name)
         throws NameRegistrar.NotFoundException
     {
-        return (ISOServer) NameRegistrar.get ("server."+name);
+        return NameRegistrar.get ("server."+name);
     }
     /**
      * @return this ISOServer's name ("" if no name was set)
@@ -654,11 +657,11 @@ public String getCountersAsString () {
         StringBuilder sb = new StringBuilder ();
         int cnt[] = getCounters();
         sb.append ("connected=");
-        sb.append (Integer.toString(cnt[2]));
+        sb.append (cnt[2]);
         sb.append (", rx=");
-        sb.append (Integer.toString(cnt[0]));
+        sb.append (cnt[0]);
         sb.append (", tx=");
-        sb.append (Integer.toString(cnt[1]));
+        sb.append (cnt[1]);
         sb.append (", last=");
         sb.append (lastTxn);
         if (lastTxn > 0) {
@@ -740,12 +743,12 @@ public void dump (PrintStream p, String indent) {
                 sb.append (inner);
                 sb.append (entry.getKey());
                 sb.append (": rx=");
-                sb.append (Integer.toString (cc[ISOChannel.RX]));
+                sb.append (cc[ISOChannel.RX]);
                 sb.append (", tx=");
-                sb.append (Integer.toString (cc[ISOChannel.TX]));
+                sb.append (cc[ISOChannel.TX]);
                 sb.append (", last=");
-                sb.append (Long.toString(lastTxn));
-                p.println (sb.toString());
+                sb.append (lastTxn);
+                p.println (sb);
             }
         }
     }
@@ -766,7 +769,7 @@ public void fireEvent(EventObject event) {
             try {
                 l.handleISOServerEvent(event);
             }
-            catch (Exception ignore) {
+            catch (Throwable ignore) {
                 /*
                  * Don't want an exception from a handler to exit the loop or
                  * let it bubble up.
@@ -781,14 +784,27 @@ public void fireEvent(EventObject event) {
         }
     }
 
+    private void log (AuditLogEvent log) {
+        Logger.log(new LogEvent()
+          .withSource(this)
+          .withTraceId(uuid)
+          .add(log)
+        );
+    }
+
     private void log (String level, String message) {
-        LogEvent evt = new LogEvent (this, level);
+        LogEvent evt = new LogEvent (this, level).withTraceId(uuid);
         evt.addMessage (message);
         Logger.log (evt);
     }
 
     public int getActiveConnections () {
         return permitsCount - permits.availablePermits();
     }
-}
 
+    private UUID getSocketUUID(Socket socket) {
+        return socket != null ?
+          new UUID(uuid.getMostSignificantBits(), uuid.getLeastSignificantBits() ^ socket.hashCode()) :
+          uuid;
+    }
+}
diff --git a/jpos/src/main/java/org/jpos/iso/ISOServerAcceptEvent.java b/jpos/src/main/java/org/jpos/iso/ISOServerAcceptEvent.java
@@ -19,8 +19,9 @@
 package org.jpos.iso;
 
 import java.lang.ref.WeakReference;
+import java.util.EventObject;
 
-public class ISOServerAcceptEvent extends java.util.EventObject {
+public final class ISOServerAcceptEvent extends EventObject implements ISOServerEvent {
     private WeakReference<ISOChannel> channelRef;
     public ISOServerAcceptEvent(ISOServer source, ISOChannel channel) {
         super(source);

diff --git a/jpos/src/main/java/org/jpos/iso/ISOServerClientDisconnectEvent.java b/jpos/src/main/java/org/jpos/iso/ISOServerClientDisconnectEvent.java
@@ -19,8 +19,9 @@
 package org.jpos.iso;
 
 import java.lang.ref.WeakReference;
+import java.util.EventObject;
 
-public class ISOServerClientDisconnectEvent extends java.util.EventObject {
+public final class ISOServerClientDisconnectEvent extends EventObject implements ISOServerEvent {
     private WeakReference<ISOChannel> channelRef;
     public ISOServerClientDisconnectEvent(Object source,  ISOChannel channel) {
         super(source);

diff --git a/jpos/src/main/java/org/jpos/iso/ISOServerEvent.java b/jpos/src/main/java/org/jpos/iso/ISOServerEvent.java
@@ -0,0 +1,21 @@
+/*
+ * jPOS Project [http://jpos.org]
+ * Copyright (C) 2000-2010 Alejandro P. Revilla
+ *
+ * This program is free software: you can redistribute it and/or modify
+ * it under the terms of the GNU Affero General Public License as
+ * published by the Free Software Foundation, either version 3 of the
+ * License, or (at your option) any later version.
+ *
+ * This program is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+ * GNU Affero General Public License for more details.
+ *
+ * You should have received a copy of the GNU Affero General Public License
+ * along with this program.  If not, see <http://www.gnu.org/licenses/>.
+ */
+
+package org.jpos.iso;
+
+public sealed interface ISOServerEvent permits ISOServerAcceptEvent, ISOServerClientDisconnectEvent, ISOServerShutdownEvent { }
diff --git a/jpos/src/main/java/org/jpos/iso/ISOServerShutdownEvent.java b/jpos/src/main/java/org/jpos/iso/ISOServerShutdownEvent.java
@@ -18,7 +18,9 @@
 
 package org.jpos.iso;
 
-public class ISOServerShutdownEvent extends java.util.EventObject {
+import java.util.EventObject;
+
+public final class ISOServerShutdownEvent extends EventObject implements ISOServerEvent {
     public ISOServerShutdownEvent(Object source) {
         super(source);
     }

diff --git a/jpos/src/main/java/org/jpos/log/AuditLogEvent.java b/jpos/src/main/java/org/jpos/log/AuditLogEvent.java
@@ -28,6 +28,7 @@
   property = "t"
 )
 @JsonSubTypes({
+  @JsonSubTypes.Type(value = Warning.class, name = "warn"),
   @JsonSubTypes.Type(value = Start.class, name = "start"),
   @JsonSubTypes.Type(value = Stop.class, name = "stop"),
   @JsonSubTypes.Type(value = Deploy.class, name = "deploy"),
@@ -39,7 +40,10 @@
   @JsonSubTypes.Type(value = License.class, name = "license"),
   @JsonSubTypes.Type(value = SysInfo.class, name = "sysinfo"),
   @JsonSubTypes.Type(value = Connect.class, name = "connect"),
-  @JsonSubTypes.Type(value = Disconnect.class, name = "disconnect")
+  @JsonSubTypes.Type(value = Disconnect.class, name = "disconnect"),
+  @JsonSubTypes.Type(value = Listen.class, name = "listen"),
+  @JsonSubTypes.Type(value = SessionStart.class, name = "session-start"),
+  @JsonSubTypes.Type(value = SessionEnd.class, name = "session-end")
 })
 
-public sealed interface AuditLogEvent permits Connect, Deploy, DeployActivity, Disconnect, License, LogMessage, Shutdown, Start, Stop, SysInfo, ThrowableAuditLogEvent, UnDeploy { }
+public sealed interface AuditLogEvent permits Connect, Deploy, DeployActivity, Disconnect, License, Listen, LogMessage, SessionEnd, SessionStart, Shutdown, Start, Stop, SysInfo, ThrowableAuditLogEvent, UnDeploy, Warning { }
diff --git a/jpos/src/main/java/org/jpos/log/evt/Listen.java b/jpos/src/main/java/org/jpos/log/evt/Listen.java
@@ -0,0 +1,31 @@
+/*
+ * jPOS Project [http://jpos.org]
+ * Copyright (C) 2000-2010 Alejandro P. Revilla
+ *
+ * This program is free software: you can redistribute it and/or modify
+ * it under the terms of the GNU Affero General Public License as
+ * published by the Free Software Foundation, either version 3 of the
+ * License, or (at your option) any later version.
+ *
+ * This program is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+ * GNU Affero General Public License for more details.
+ *
+ * You should have received a copy of the GNU Affero General Public License
+ * along with this program.  If not, see <http://www.gnu.org/licenses/>.
+ */
+
+package org.jpos.log.evt;
+
+import com.fasterxml.jackson.annotation.JsonInclude;
+import org.jpos.log.AuditLogEvent;
+
+import java.net.InetAddress;
+
+public record Listen(
+  int port,
+  @JsonInclude(JsonInclude.Include.NON_NULL) InetAddress bindAddr,
+  int permits,
+  int backlog
+) implements AuditLogEvent {  }
diff --git a/jpos/src/main/java/org/jpos/log/evt/LogEvt.java b/jpos/src/main/java/org/jpos/log/evt/LogEvt.java
@@ -32,5 +32,5 @@ public record LogEvt(
   @JacksonXmlProperty(isAttribute = true) @JsonProperty("trace-id") String traceId,
   @JacksonXmlProperty(isAttribute = true) String realm,
   @JacksonXmlProperty(isAttribute = true) String tag,
-  @JacksonXmlProperty(isAttribute = true) Long elapsed,
+  @JacksonXmlProperty(isAttribute = true) Long lifespan,
   @JsonProperty("evt") @JacksonXmlElementWrapper(useWrapping = false) List<AuditLogEvent> events) { }
diff --git a/jpos/src/main/java/org/jpos/log/evt/SessionEnd.java b/jpos/src/main/java/org/jpos/log/evt/SessionEnd.java
@@ -0,0 +1,5 @@
+package org.jpos.log.evt;
+
+import org.jpos.log.AuditLogEvent;
+
+public record SessionEnd(int connections, int permits, String info) implements AuditLogEvent { }