refactor: normalize logging

CHANGELOG.md

@@ -5,6 +5,14 @@ The format is based on [Keep a Changelog](https://keepachangelog.com/en/1.0.0/),
 and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0.html).
 
 ## [Unreleased]
+### Changed
+- Normalized logging using Keyple coding standards.
+### Upgraded
+- `keyple-plugin-java-api` from `2.3.1` to `2.3.2` (code source not impacted)
+- `keyple-distributed-remote-java-api` from `3.1.0` to `3.1.1` (code source not impacted)
+- `keyple-distributed-local-java-api` from `2.2.0` to `2.2.1` (code source not impacted)
+- `keyple-util-java-lib` from `2.4.0` to `2.4.1` (code source not impacted)
+- `slf4j-api` from `1.7.32` to `1.7.36` (`compileOnly`)
 
 ## [3.4.0] - 2025-11-21
 ### Upgraded

build.gradle.kts

@@ -17,13 +17,14 @@ dependencies {
   implementation("org.eclipse.keypop:keypop-reader-java-api:2.1.0")
   implementation("org.eclipse.keypop:keypop-card-java-api:2.0.1")
   implementation("org.eclipse.keyple:keyple-common-java-api:2.0.2")
-  implementation("org.eclipse.keyple:keyple-plugin-java-api:2.3.1")
-  implementation("org.eclipse.keyple:keyple-distributed-remote-java-api:3.1.0")
-  implementation("org.eclipse.keyple:keyple-distributed-local-java-api:2.2.0")
-  implementation("org.eclipse.keyple:keyple-util-java-lib:2.4.0")
+  implementation("org.eclipse.keyple:keyple-plugin-java-api:2.3.2")
+  implementation("org.eclipse.keyple:keyple-distributed-remote-java-api:3.1.1")
+  implementation("org.eclipse.keyple:keyple-distributed-local-java-api:2.2.1")
+  implementation("org.eclipse.keyple:keyple-util-java-lib:2.4.1")
   implementation("com.google.code.gson:gson:2.10.1")
-  implementation("org.slf4j:slf4j-api:1.7.32")
-  testImplementation("org.slf4j:slf4j-simple:1.7.32")
+  compileOnly("org.slf4j:slf4j-api:1.7.36")
+
+  testImplementation("org.slf4j:slf4j-simple:1.7.36")
   testImplementation(platform("org.junit:junit-bom:5.10.2"))
   testImplementation("org.junit.jupiter:junit-jupiter")
   testImplementation("org.junit.vintage:junit-vintage-engine")

gradle.properties

@@ -2,7 +2,7 @@
 group = org.eclipse.keyple
 title = Keyple Service Java Lib
 description = Keyple core components
-version = 3.4.0-SNAPSHOT
+version = 3.4.1-SNAPSHOT
 
 # Java Configuration
 javaSourceLevel = 1.8

src/main/java/org/eclipse/keyple/core/service/AbstractObservableLocalPluginAdapter.java

@@ -66,18 +66,20 @@ abstract class AbstractObservableLocalPluginAdapter extends LocalPluginAdapter
    * @since 2.0.0
    */
   final void notifyObservers(final PluginEvent event) {
-
     if (logger.isDebugEnabled()) {
       logger.debug(
-          "Plugin [{}] notifies event [{}] to {} observer(s)",
+          "[plugin={}] Notifying observers [eventType={}, readerNames={}, observerCount={}]",
           getName(),
           event.getType().name(),
+          event.getReaderNames(),
           countObservers());
     }
-
     for (PluginObserverSpi observer : observationManager.getObservers()) {
       notifyObserver(observer, event);
     }
+    if (logger.isDebugEnabled()) {
+      logger.debug("[plugin={}] Observers notified", getName());
+    }
   }
 
   /**
@@ -93,8 +95,13 @@ private void notifyObserver(PluginObserverSpi observer, PluginEvent event) {
       try {
         observationManager.getObservationExceptionHandler().onPluginObservationError(getName(), e);
       } catch (Exception e2) {
-        logger.error("Event notification error: {}", e2.getMessage(), e2);
-        logger.error("Original cause: {}", e.getMessage(), e);
+        logger.error(
+            "[plugin={}] Failed to notify observer [reason={}]", getName(), e.getMessage(), e);
+        logger.error(
+            "[plugin={}] Failed to notify observation exception handler [reason={}]",
+            getName(),
+            e2.getMessage(),
+            e2);
       }
     }
   }

src/main/java/org/eclipse/keyple/core/service/AbstractPluginAdapter.java

@@ -110,7 +110,11 @@ void unregister() {
       try {
         ((AbstractReaderAdapter) reader).unregister();
       } catch (Exception e) {
-        logger.warn("Error unregistering reader [{}]: {}", reader.getName(), e.getMessage());
+        logger.warn(
+            "[plugin={}] Failed to unregister reader [name={}, reason={}]",
+            pluginName,
+            reader.getName(),
+            e.getMessage());
       }
     }
     readers.clear();

src/main/java/org/eclipse/keyple/core/service/AbstractReaderAdapter.java

@@ -111,14 +111,14 @@ final List<CardSelectionResponseApi> transmitCardSelectionRequests(
 
     List<CardSelectionResponseApi> cardSelectionResponses = null;
 
-    if (logger.isTraceEnabled()) {
+    if (logger.isDebugEnabled()) {
       long timeStamp = System.nanoTime();
       long elapsed10ms = (timeStamp - before) / 100000;
       this.before = timeStamp;
-      logger.trace(
-          "Reader [{}] --> cardSelectionRequests: {}, elapsed {} ms",
-          this.getName(),
-          cardSelectionRequests,
+      logger.debug(
+          "[reader={}] Send [type=CardSelectionRequests, cardSelectionRequestCount={}, elapsedMs={}]",
+          getName(),
+          cardSelectionRequests.size(),
           elapsed10ms / 10.0);
     }
 
@@ -130,14 +130,14 @@ final List<CardSelectionResponseApi> transmitCardSelectionRequests(
       throw new CardBrokenCommunicationException(
           e.getCardResponse(), false, "An unexpected status word was received", e);
     } finally {
-      if (logger.isTraceEnabled()) {
+      if (logger.isDebugEnabled()) {
         long timeStamp = System.nanoTime();
         long elapsed10ms = (timeStamp - before) / 100000;
         this.before = timeStamp;
-        logger.trace(
-            "Reader [{}] <-- cardSelectionResponses: {}, elapsed {} ms",
-            this.getName(),
-            cardSelectionResponses,
+        logger.debug(
+            "[reader={}] Receive [type=CardSelectionResponses, cardSelectionResponseCount={}, elapsedMs={}]",
+            getName(),
+            cardSelectionResponses != null ? cardSelectionResponses.size() : 0,
             elapsed10ms / 10.0);
       }
     }
@@ -250,28 +250,28 @@ public final CardResponseApi transmitCardRequest(
 
     CardResponseApi cardResponse = null;
 
-    if (logger.isTraceEnabled()) {
+    if (logger.isDebugEnabled()) {
       long timeStamp = System.nanoTime();
       long elapsed10ms = (timeStamp - before) / 100000;
       this.before = timeStamp;
-      logger.trace(
-          "Reader [{}] --> cardRequest: {}, elapsed {} ms",
-          this.getName(),
-          cardRequest,
+      logger.debug(
+          "[reader={}] Send [type=CardRequest, apduRequestCount={}, elapsedMs={}]",
+          getName(),
+          cardRequest.getApduRequests().size(),
           elapsed10ms / 10.0);
     }
 
     try {
       cardResponse = processCardRequest(cardRequest, channelControl);
     } finally {
-      if (logger.isTraceEnabled()) {
+      if (logger.isDebugEnabled()) {
         long timeStamp = System.nanoTime();
         long elapsed10ms = (timeStamp - before) / 100000;
         this.before = timeStamp;
-        logger.trace(
-            "Reader [{}] <-- cardResponse: {}, elapsed {} ms",
-            this.getName(),
-            cardResponse,
+        logger.debug(
+            "[reader={}] Receive [type=CardResponse, apduResponseCount={}, elapsedMs={}]",
+            getName(),
+            cardResponse != null ? cardResponse.getApduResponses().size() : 0,
             elapsed10ms / 10.0);
       }
     }

src/main/java/org/eclipse/keyple/core/service/ApduResponseAdapter.java

@@ -12,7 +12,7 @@
 package org.eclipse.keyple.core.service;
 
 import java.util.Arrays;
-import org.eclipse.keyple.core.util.json.JsonUtil;
+import org.eclipse.keyple.core.util.HexUtil;
 import org.eclipse.keypop.card.ApduResponseApi;
 
 /**
@@ -67,13 +67,20 @@ public int getStatusWord() {
   }
 
   /**
-   * Converts the APDU response into a string where the data is encoded in a json format.
+   * Returns a string representation of the object.
    *
-   * @return A not empty String
+   * @return A string that represents the current state of the object.
    * @since 2.0.0
    */
   @Override
   public String toString() {
-    return "APDU_RESPONSE = " + JsonUtil.toJson(this);
+    return "ApduResponseAdapter{"
+        + "apdu='"
+        + HexUtil.toHex(apdu)
+        + '\''
+        + ", statusWord='"
+        + HexUtil.toHex(statusWord)
+        + '\''
+        + '}';
   }
 }

src/main/java/org/eclipse/keyple/core/service/AutonomousObservableLocalPluginAdapter.java

@@ -45,7 +45,8 @@ final class AutonomousObservableLocalPluginAdapter extends AbstractObservableLoc
       autonomousObservablePluginSpi.setCallback(this);
     } catch (Exception e) {
       if (logger.isTraceEnabled()) {
-        logger.trace("Method 'setCallback(...)' unavailable for legacy plugin: {}", e.getMessage());
+        logger.trace(
+            "[plugin={}] Method 'setCallback(...)' unavailable for legacy plugin", getName());
       }
       autonomousObservablePluginSpi.connect(this);
     }
@@ -84,13 +85,13 @@ public void onReaderDisconnected(Set<String> readerNames) {
     for (String readerName : readerNames) {
       CardReader reader = this.getReader(readerName);
       if (reader == null) {
-        logger.warn("Plugin [{}] unable to remove unknown reader [{}]", this.getName(), readerName);
+        logger.warn("[plugin={}] Unable to remove unknown reader [name={}]", getName(), readerName);
       } else {
         // unregister and remove reader
         ((LocalReaderAdapter) reader).unregister();
         getReadersMap().remove(reader.getName());
         logger.info(
-            "Plugin [{}] removes reader [{}] from readers list", this.getName(), reader.getName());
+            "[plugin={}] Reader removed from readers list [name={}]", getName(), reader.getName());
         notifyReaders.add(readerName);
       }
     }
@@ -109,6 +110,6 @@ private void addReader(ReaderSpi readerSpi) {
     reader.register();
     getReadersMap().put(reader.getName(), reader);
     logger.info(
-        "Plugin [{}] adds reader [{}] to readers list", this.getName(), readerSpi.getName());
+        "[plugin={}] Reader added to readers list [name={}]", getName(), readerSpi.getName());
   }
 }

src/main/java/org/eclipse/keyple/core/service/BasicCardSelectorAdapter.java

@@ -11,7 +11,6 @@
  ************************************************************************************** */
 package org.eclipse.keyple.core.service;
 
-import org.eclipse.keyple.core.util.json.JsonUtil;
 import org.eclipse.keypop.reader.selection.BasicCardSelector;
 
 /**
@@ -66,13 +65,20 @@ public BasicCardSelector filterByPowerOnData(String powerOnDataRegex) {
   }
 
   /**
-   * Converts the current instance into a string where the data is encoded in a json format.
+   * Returns a string representation of the object.
    *
-   * @return A not empty String
+   * @return A string that represents the current state of the object.
    * @since 3.0.0
    */
   @Override
   public String toString() {
-    return "BASIC_CARD_SELECTOR = " + JsonUtil.toJson(this);
+    return "BasicCardSelectorAdapter{"
+        + "logicalProtocolName='"
+        + logicalProtocolName
+        + '\''
+        + ", powerOnDataRegex='"
+        + powerOnDataRegex
+        + '\''
+        + '}';
   }
 }

src/main/java/org/eclipse/keyple/core/service/CardInsertionActiveMonitoringJobAdapter.java

@@ -31,6 +31,8 @@ final class CardInsertionActiveMonitoringJobAdapter extends AbstractMonitoringJo
   private static final Logger logger =
       LoggerFactory.getLogger(CardInsertionActiveMonitoringJobAdapter.class);
 
+  private static final String JOB_ID = "INSERTION_ACTIVE";
+
   private final long sleepDurationMillis;
   private final boolean monitorInsertion;
   private final CardReader reader;
@@ -76,7 +78,8 @@ public void run() {
         try {
           if (logger.isTraceEnabled()) {
             logger.trace(
-                "Start monitoring job polling process using 'isCardPresent()' method on reader [{}]",
+                "[fsmJob={}, reader={}] Starting monitoring job polling process using 'isCardPresent()'",
+                JOB_ID,
                 reader.getName());
           }
           // re-init loop value to true
@@ -85,15 +88,15 @@ public void run() {
             // polls for CARD_INSERTED
             if (monitorInsertion && reader.isCardPresent()) {
               if (logger.isTraceEnabled()) {
-                logger.trace("Card present");
+                logger.trace("[fsmJob={}, reader={}] Card present", JOB_ID, reader.getName());
               }
               monitoringState.onEvent(ObservableLocalReaderAdapter.InternalEvent.CARD_INSERTED);
               return;
             }
             // polls for CARD_REMOVED
             if (!monitorInsertion && !reader.isCardPresent()) {
               if (logger.isTraceEnabled()) {
-                logger.trace("Card not present");
+                logger.trace("[fsmJob={}, reader={}] Card not present", JOB_ID, reader.getName());
               }
               loop.set(false);
               monitoringState.onEvent(ObservableLocalReaderAdapter.InternalEvent.CARD_REMOVED);
@@ -109,7 +112,10 @@ public void run() {
             }
           }
           if (logger.isTraceEnabled()) {
-            logger.trace("Monitoring job polling process stopped");
+            logger.trace(
+                "[fsmJob={}, reader={}] Monitoring job polling process stopped",
+                JOB_ID,
+                reader.getName());
           }
         } catch (RuntimeException e) {
           ((ObservableLocalReaderAdapter) reader)

src/main/java/org/eclipse/keyple/core/service/CardInsertionPassiveMonitoringJobAdapter.java

@@ -41,6 +41,8 @@ final class CardInsertionPassiveMonitoringJobAdapter extends AbstractMonitoringJ
   private static final Logger logger =
       LoggerFactory.getLogger(CardInsertionPassiveMonitoringJobAdapter.class);
 
+  private static final String JOB_ID = "INSERTION_PASSIVE";
+
   private final ObservableReaderSpi readerSpi;
 
   /**
@@ -76,7 +78,10 @@ Runnable getMonitoringJob(final AbstractObservableStateAdapter monitoringState)
       public void run() {
         try {
           if (logger.isTraceEnabled()) {
-            logger.trace("Start monitoring job process on reader [{}]", getReader().getName());
+            logger.trace(
+                "[fsmJob={}, reader={}] Starting monitoring job process",
+                JOB_ID,
+                getReader().getName());
           }
           if (readerSpi instanceof CardInsertionWaiterBlockingSpi) {
             ((CardInsertionWaiterBlockingSpi) readerSpi).waitForCardInsertion();
@@ -87,11 +92,16 @@ public void run() {
         } catch (ReaderIOException e) {
           // just warn as it can be a disconnection of the reader.
           logger.warn(
-              "Monitoring job error while processing card insertion event on reader [{}]: {}",
+              "[fsmJob={}, reader={}] Failed to process card insertion event [reason={}]",
+              JOB_ID,
               getReader().getName(),
               e.getMessage());
         } catch (TaskCanceledException e) {
-          logger.warn("Monitoring job process cancelled: {}", e.getMessage());
+          logger.warn(
+              "[fsmJob={}, reader={}] Monitoring job process cancelled [reason={}]",
+              JOB_ID,
+              getReader().getName(),
+              e.getMessage());
         } catch (RuntimeException e) {
           getReader()
               .getObservationExceptionHandler()
@@ -109,15 +119,17 @@ public void run() {
   @Override
   void stop() {
     if (logger.isTraceEnabled()) {
-      logger.trace("Stop monitoring job process");
+      logger.trace(
+          "[fsmJob={}, reader={}] Stopping monitoring job process", JOB_ID, getReader().getName());
     }
     if (readerSpi instanceof CardInsertionWaiterBlockingSpi) {
       ((CardInsertionWaiterBlockingSpi) readerSpi).stopWaitForCardInsertion();
     } else if (readerSpi instanceof WaitForCardInsertionBlockingSpi) {
       ((WaitForCardInsertionBlockingSpi) readerSpi).stopWaitForCardInsertion();
     }
     if (logger.isTraceEnabled()) {
-      logger.trace("Monitoring job process stopped");
+      logger.trace(
+          "[fsmJob={}, reader={}] Monitoring job process stopped", JOB_ID, getReader().getName());
     }
   }
 }