Organize internal logging around SLF4J and JUL #100

Author: andrus

RELEASE-NOTES.md

@@ -19,6 +19,7 @@
 * #90 Deprecate Ivy artifact syntax for %maven magic
 * #93 Extensions / kernel lifecycle
 * #99 Get rid of SLF4J transitive dependency
+* #100 Organize internal logging around SLF4J and JUL
 
 ## 1.0-a5
 

jjava-distro/src/main/java/org/dflib/jjava/distro/JJava.java

@@ -1,7 +1,6 @@
 package org.dflib.jjava.distro;
 
 import org.dflib.jjava.jupyter.channels.JupyterConnection;
-import org.dflib.jjava.jupyter.channels.JupyterSocket;
 import org.dflib.jjava.jupyter.kernel.KernelConnectionProperties;
 import org.dflib.jjava.kernel.JavaKernel;
 import org.dflib.jjava.kernel.magics.ClasspathMagic;
@@ -20,16 +19,19 @@
 import java.nio.file.Path;
 import java.nio.file.Paths;
 import java.util.Properties;
-import java.util.logging.Level;
 
 /**
  * The main class launching Jupyter Java kernel.
  */
 public class JJava {
 
+    // single-line JUL logging that mimics the default Jupyter format for the label:
+    // [I 2025-10-19 16:15:41.181 ServerApp]
+    private static final String JUL_JUPYTER_LOG_FORMAT = "[%4$.1s %1$tF %1$tT.%1$tL %3$s] %5$s%n";
     private static final String POM_PROPERTIES = "META-INF/maven/org.dflib.jjava/jjava-distro/pom.properties";
 
     public static void main(String[] args) throws Exception {
+
         if (args.length < 1) {
             throw new IllegalArgumentException("Missing connection file argument");
         }
@@ -39,7 +41,7 @@ public static void main(String[] args) throws Exception {
             throw new IllegalArgumentException("Connection file '" + connectionFile + "' isn't a file.");
         }
 
-        JupyterSocket.JUPYTER_LOGGER.setLevel(Level.WARNING);
+        System.setProperty("java.util.logging.SimpleFormatter.format", JUL_JUPYTER_LOG_FORMAT);
 
         KernelConnectionProperties connProps = KernelConnectionProperties.parse(Files.readString(connectionFile));
         JupyterConnection connection = new JupyterConnection(connProps);

jjava-jupyter/pom.xml

@@ -22,6 +22,10 @@
             <groupId>org.zeromq</groupId>
             <artifactId>jeromq</artifactId>
         </dependency>
+        <dependency>
+            <groupId>org.slf4j</groupId>
+            <artifactId>slf4j-api</artifactId>
+        </dependency>
 
         <dependency>
             <groupId>org.junit.jupiter</groupId>

jjava-jupyter/src/main/java/org/dflib/jjava/jupyter/channels/HeartbeatChannel.java

@@ -2,23 +2,23 @@
 
 import org.dflib.jjava.jupyter.kernel.KernelConnectionProperties;
 import org.dflib.jjava.jupyter.messages.HMACGenerator;
+import org.slf4j.LoggerFactory;
 import org.zeromq.SocketType;
 import org.zeromq.ZMQ;
 
 import java.util.concurrent.atomic.AtomicInteger;
-import java.util.logging.Level;
-import java.util.logging.Logger;
+
 
 public class HeartbeatChannel extends JupyterSocket {
-    private static final long HB_DEFAULT_SLEEP_MS = 500;
 
+    private static final long HB_DEFAULT_SLEEP_MS = 500;
     private static final AtomicInteger HEARTBEAT_ID = new AtomicInteger();
 
     private final long sleep;
     private volatile Loop pulse;
 
     public HeartbeatChannel(ZMQ.Context context, HMACGenerator hmacGenerator, long sleep) {
-        super(context, SocketType.REP, hmacGenerator, Logger.getLogger("HeartbeatChannel"));
+        super(context, SocketType.REP, hmacGenerator, LoggerFactory.getLogger("HeartbeatChannel"));
         this.sleep = sleep;
     }
 
@@ -38,7 +38,7 @@ public void bind(KernelConnectionProperties connProps) {
         String channelThreadName = "Heartbeat-" + HEARTBEAT_ID.getAndIncrement();
         String addr = formatAddress(connProps.getTransport(), connProps.getIp(), connProps.getHbPort());
 
-        logger.log(Level.INFO, String.format("Binding %s to %s.", channelThreadName, addr));
+        logger.debug("Binding {} to {}.", channelThreadName, addr);
         super.bind(addr);
 
         ZMQ.Poller poller = super.ctx.poller(1);
@@ -49,22 +49,24 @@ public void bind(KernelConnectionProperties connProps) {
             if (events > 0) {
                 byte[] msg = this.recv();
                 if (msg == null) {
-                    //Error during receive, just continue
-                    super.logger.log(Level.SEVERE, "Poll returned 1 event but could not read the echo string");
+                    // Error during receive, just continue
+                    logger.warn("Poll returned 1 event but could not read the echo string");
                     return;
                 }
+
                 if (!this.send(msg)) {
-                    super.logger.log(Level.SEVERE, "Could not send heartbeat reply");
+                    logger.warn("Could not send heartbeat reply");
                 }
-                super.logger.log(Level.FINEST, "Heartbeat pulse");
+
+                logger.trace("Heartbeat pulse");
             }
         });
         this.pulse.onClose(() -> {
-            logger.log(Level.INFO, channelThreadName + " shutdown.");
+            logger.debug( "{} shutdown.", channelThreadName);
             this.pulse = null;
         });
         this.pulse.start();
-        logger.log(Level.INFO, "Polling on " + channelThreadName);
+        logger.debug("Polling on {}", channelThreadName);
     }
 
     @Override
@@ -80,7 +82,8 @@ public void waitUntilClose() {
         if (this.pulse != null) {
             try {
                 this.pulse.join();
-            } catch (InterruptedException ignored) { }
+            } catch (InterruptedException ignored) {
+            }
         }
     }
 }

jjava-jupyter/src/main/java/org/dflib/jjava/jupyter/channels/IOPubChannel.java

@@ -2,22 +2,20 @@
 
 import org.dflib.jjava.jupyter.kernel.KernelConnectionProperties;
 import org.dflib.jjava.jupyter.messages.HMACGenerator;
+import org.slf4j.LoggerFactory;
 import org.zeromq.SocketType;
 import org.zeromq.ZMQ;
 
-import java.util.logging.Level;
-import java.util.logging.Logger;
-
 public class IOPubChannel extends JupyterSocket {
     public IOPubChannel(ZMQ.Context context, HMACGenerator hmacGenerator) {
-        super(context, SocketType.PUB, hmacGenerator, Logger.getLogger("IOPubChannel"));
+        super(context, SocketType.PUB, hmacGenerator, LoggerFactory.getLogger("IOPubChannel"));
     }
 
     @Override
     public void bind(KernelConnectionProperties connProps) {
         String addr = formatAddress(connProps.getTransport(), connProps.getIp(), connProps.getIopubPort());
 
-        logger.log(Level.INFO, String.format("Binding iopub to %s.", addr));
+        logger.debug("Binding iopub to {}.", addr);
         super.bind(addr);
     }
 }

jjava-jupyter/src/main/java/org/dflib/jjava/jupyter/channels/JupyterSocket.java

@@ -25,6 +25,7 @@
 import org.dflib.jjava.jupyter.messages.publish.PublishStatus;
 import org.dflib.jjava.jupyter.messages.reply.ErrorReply;
 import org.dflib.jjava.jupyter.messages.request.HistoryRequest;
+import org.slf4j.Logger;
 import org.zeromq.SocketType;
 import org.zeromq.ZMQ;
 
@@ -35,33 +36,33 @@
 import java.util.Iterator;
 import java.util.List;
 import java.util.Map;
-import java.util.logging.Logger;
 
 public abstract class JupyterSocket extends ZMQ.Socket {
+
     protected static String formatAddress(String transport, String ip, int port) {
         return transport + "://" + ip + ":" + port;
     }
 
-    private static final byte[] IDENTITY_BLOB_DELIMITER = "<IDS|MSG>".getBytes(StandardCharsets.US_ASCII); // Comes from a python bytestring
+    // Comes from a Python bytestring
+    private static final byte[] IDENTITY_BLOB_DELIMITER = "<IDS|MSG>".getBytes(StandardCharsets.US_ASCII);
+
     private static final Gson replyGson = new GsonBuilder()
             .registerTypeAdapter(HistoryEntry.class, HistoryEntryAdapter.INSTANCE)
             .registerTypeAdapter(ExpressionValue.class, ExpressionValueAdapter.INSTANCE)
             .create();
+
     private static final Gson gson = new GsonBuilder()
             .registerTypeAdapter(KernelTimestamp.class, KernelTimestampAdapter.INSTANCE)
             .registerTypeAdapter(Header.class, HeaderAdapter.INSTANCE)
             .registerTypeAdapter(MessageType.class, MessageTypeAdapter.INSTANCE)
             .registerTypeAdapter(PublishStatus.class, PublishStatusAdapter.INSTANCE)
             .registerTypeAdapter(HistoryRequest.class, HistoryRequestAdapter.INSTANCE)
             .registerTypeHierarchyAdapter(ReplyType.class, new ReplyTypeAdapter(replyGson))
-            //.setPrettyPrinting()
             .create();
     private static final byte[] EMPTY_JSON_OBJECT = "{}".getBytes(StandardCharsets.UTF_8);
     private static final Type JSON_OBJ_AS_MAP = new TypeToken<Map<String, Object>>() {
     }.getType();
 
-    public static final Logger JUPYTER_LOGGER = Logger.getLogger("Jupyter");
-
     protected final ZMQ.Context ctx;
     protected final HMACGenerator hmacGenerator;
     protected final Logger logger;
@@ -71,7 +72,6 @@ protected JupyterSocket(ZMQ.Context context, SocketType type, HMACGenerator hmac
         super(context, type);
         this.ctx = context;
         this.hmacGenerator = hmacGenerator;
-        logger.setParent(JUPYTER_LOGGER);
         this.logger = logger;
         this.closed = false;
     }
@@ -129,7 +129,10 @@ public synchronized Message<?> readMessage() {
         }
 
         Message<?> message = new Message(identities, header, parentHeader, metadata, content, blobs);
-        logger.finer(() -> "Received from " + super.base().getSocketOptx(zmq.ZMQ.ZMQ_LAST_ENDPOINT) + ":\n" + gson.toJson(message));
+
+        if (logger.isTraceEnabled()) {
+            logger.trace("Received from {}:\n{}", super.base().getSocketOptx(zmq.ZMQ.ZMQ_LAST_ENDPOINT), gson.toJson(message));
+        }
 
         return message;
     }
@@ -157,7 +160,9 @@ public synchronized void sendMessage(Message<?> message) {
 
         String hmac = hmacGenerator.calculateSignature(headerRaw, parentHeaderRaw, metadata, content);
 
-        logger.finer(() -> "Sending to " + super.base().getSocketOptx(zmq.ZMQ.ZMQ_LAST_ENDPOINT) + ":\n" + gson.toJson(message));
+        if (logger.isTraceEnabled()) {
+            logger.trace("Sending to {}:\n{}", super.base().getSocketOptx(zmq.ZMQ.ZMQ_LAST_ENDPOINT), gson.toJson(message));
+        }
 
         message.getIdentities().forEach(super::sendMore);
         super.sendMore(IDENTITY_BLOB_DELIMITER);

jjava-jupyter/src/main/java/org/dflib/jjava/jupyter/channels/Loop.java

@@ -1,14 +1,16 @@
 package org.dflib.jjava.jupyter.channels;
 
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
+
 import java.util.Queue;
 import java.util.concurrent.LinkedBlockingQueue;
 import java.util.function.LongSupplier;
 import java.util.function.ToLongFunction;
-import java.util.logging.Logger;
 
 public class Loop extends Thread {
-    private final Logger logger;
 
+    private final Logger logger;
     private volatile boolean running = false;
     private final LongSupplier loopBody;
 
@@ -25,12 +27,9 @@ public Loop(String name, long sleep, Runnable target) {
 
     public Loop(String name, LongSupplier target) {
         super(name);
-
         this.loopBody = target;
-
         this.runNextQueue = new LinkedBlockingQueue<>();
-
-        this.logger = Logger.getLogger("Loop-" + name);
+        this.logger = LoggerFactory.getLogger("Loop-" + name);
     }
 
     public void onClose(Runnable callback) {
@@ -91,36 +90,37 @@ public void run() {
                 try {
                     Thread.sleep(sleep);
                 } catch (InterruptedException e) {
-                    this.logger.info("Loop interrupted. Stopping...");
+                    logger.debug("Loop interrupted. Stopping...");
                     this.running = false;
                 }
             } else if (sleep < 0) {
-                this.logger.info("Loop interrupted by a negative sleep request. Stopping...");
+                logger.debug("Loop interrupted by a negative sleep request. Stopping...");
                 this.running = false;
             }
         }
 
-        this.logger.info("Running loop shutdown callback.");
+        logger.debug("Running loop shutdown callback.");
 
-        if (this.onCloseCb != null)
-            this.onCloseCb.run();
-        this.onCloseCb = null;
+        if (onCloseCb != null) {
+            onCloseCb.run();
+            onCloseCb = null;
+        }
 
-        this.logger.info("Loop stopped.");
+        logger.info("Loop stopped.");
     }
 
     @Override
     public synchronized void start() {
-        this.logger.info("Loop starting...");
+        logger.debug("Loop starting...");
 
-        this.running = true;
+        running = true;
         super.start();
 
-        this.logger.info("Loop started.");
+        logger.info("Loop started.");
     }
 
     public void shutdown() {
-        this.running = false;
-        this.logger.info("Loop shutdown.");
+        running = false;
+        logger.debug("Loop shutdown.");
     }
 }