From 7218c3e94e003958687506e07b4a5c4418d6ef1d Mon Sep 17 00:00:00 2001 From: Alejandro Revilla Date: Mon, 26 Aug 2024 18:46:13 -0300 Subject: [PATCH] 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/src/dist/deploy/00_logger.xml | 24 ++++- .../src/main/java/org/jpos/iso/ISOServer.java | 96 +++++++++++-------- .../org/jpos/iso/ISOServerAcceptEvent.java | 3 +- .../iso/ISOServerClientDisconnectEvent.java | 3 +- .../java/org/jpos/iso/ISOServerEvent.java | 21 ++++ .../org/jpos/iso/ISOServerShutdownEvent.java | 4 +- .../main/java/org/jpos/log/AuditLogEvent.java | 8 +- .../main/java/org/jpos/log/evt/Listen.java | 31 ++++++ .../main/java/org/jpos/log/evt/LogEvt.java | 2 +- .../java/org/jpos/log/evt/SessionEnd.java | 5 + .../java/org/jpos/log/evt/SessionStart.java | 22 +++++ .../main/java/org/jpos/log/evt/Warning.java | 23 +++++ .../src/main/java/org/jpos/util/LogEvent.java | 4 + 13 files changed, 196 insertions(+), 50 deletions(-) create mode 100644 jpos/src/main/java/org/jpos/iso/ISOServerEvent.java create mode 100644 jpos/src/main/java/org/jpos/log/evt/Listen.java create mode 100644 jpos/src/main/java/org/jpos/log/evt/SessionEnd.java create mode 100644 jpos/src/main/java/org/jpos/log/evt/SessionStart.java create mode 100644 jpos/src/main/java/org/jpos/log/evt/Warning.java diff --git a/jpos/src/dist/deploy/00_logger.xml b/jpos/src/dist/deploy/00_logger.xml index 7159d6db2a..3119bf843d 100644 --- a/jpos/src/dist/deploy/00_logger.xml +++ b/jpos/src/dist/deploy/00_logger.xml @@ -1,11 +1,27 @@ - + - - - + + + + + + + + + + + + + + + + + + + diff --git a/jpos/src/main/java/org/jpos/iso/ISOServer.java b/jpos/src/main/java/org/jpos/iso/ISOServer.java index 74d390abca..ca598de5dd 100644 --- 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,9 +304,17 @@ 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(); @@ -319,6 +322,9 @@ public void run() { baseChannel.setCounters(bc.getMsgInCounter(), bc.getMsgOutCounter()); } try { + WeakReference 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,7 +490,7 @@ 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(); } @@ -491,13 +498,9 @@ public void run() { } final ServerChannel channel = (ServerChannel) clientSideChannel.clone(); channel.accept (serverSocket); - if (connectionCount.getAndIncrement() % 100 == 0) { purgeChannels (); } - WeakReference 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,8 +784,16 @@ 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); } @@ -790,5 +801,10 @@ private void log (String level, String message) { 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 index d19746b3af..e7769eeb44 100644 --- 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 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 index affd497801..8008fb9aa3 100644 --- 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 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 new file mode 100644 index 0000000000..e917dd884b --- /dev/null +++ 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 . + */ + +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 index c6d4e33333..caae7ca1ed 100644 --- 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 index 0a6fa0f320..88e587b333 100644 --- 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 new file mode 100644 index 0000000000..00c33f2dcc --- /dev/null +++ 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 . + */ + +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 { } \ No newline at end of file diff --git a/jpos/src/main/java/org/jpos/log/evt/LogEvt.java b/jpos/src/main/java/org/jpos/log/evt/LogEvt.java index 4ba41a2f40..79f69f965d 100644 --- 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 events) { } \ No newline at end of file diff --git a/jpos/src/main/java/org/jpos/log/evt/SessionEnd.java b/jpos/src/main/java/org/jpos/log/evt/SessionEnd.java new file mode 100644 index 0000000000..a639340181 --- /dev/null +++ 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 { } diff --git a/jpos/src/main/java/org/jpos/log/evt/SessionStart.java b/jpos/src/main/java/org/jpos/log/evt/SessionStart.java new file mode 100644 index 0000000000..e63674a0f9 --- /dev/null +++ b/jpos/src/main/java/org/jpos/log/evt/SessionStart.java @@ -0,0 +1,22 @@ +package org.jpos.log.evt;/* + * 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 . + */ + +import org.jpos.log.AuditLogEvent; + +public record SessionStart(int connections, int permits, String info) implements AuditLogEvent { +} diff --git a/jpos/src/main/java/org/jpos/log/evt/Warning.java b/jpos/src/main/java/org/jpos/log/evt/Warning.java new file mode 100644 index 0000000000..13236a8ac5 --- /dev/null +++ b/jpos/src/main/java/org/jpos/log/evt/Warning.java @@ -0,0 +1,23 @@ +/* + * 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 . + */ + +package org.jpos.log.evt; + +import org.jpos.log.AuditLogEvent; + +public record Warning (String warn) implements AuditLogEvent { } diff --git a/jpos/src/main/java/org/jpos/util/LogEvent.java b/jpos/src/main/java/org/jpos/util/LogEvent.java index 93067df293..4c858ef4c9 100644 --- a/jpos/src/main/java/org/jpos/util/LogEvent.java +++ b/jpos/src/main/java/org/jpos/util/LogEvent.java @@ -209,6 +209,10 @@ public LogEvent withTraceId (UUID uuid) { this.traceId = uuid.toString().replace("-", ""); return this; } + public LogEvent withSource (LogSource source) { + setSource(source); + return this; + } public LogEvent add (Object o) { addMessage(o); return this;