From 3722ba02b142ca974b405fa896f0e62fc1a60446 Mon Sep 17 00:00:00 2001 From: Andreas Huber Date: Sun, 5 Feb 2017 09:53:25 +0100 Subject: [PATCH] add slf4j via log4j 2 logging --- .../lucares/recommind/logs/TcpIngestor.java | 48 +++++++++++-------- .../db/ingestor/TcpIngestorTest.java | 8 +++- performanceDb/build.gradle | 6 +++ .../performance/db/BlockingQueueIterator.java | 8 ++++ .../src/main/resources/log4j2.properties | 13 +++++ 5 files changed, 61 insertions(+), 22 deletions(-) create mode 100644 performanceDb/src/main/resources/log4j2.properties diff --git a/pdb-plotting/src/main/java/org/lucares/recommind/logs/TcpIngestor.java b/pdb-plotting/src/main/java/org/lucares/recommind/logs/TcpIngestor.java index 4b60595..9f83061 100644 --- a/pdb-plotting/src/main/java/org/lucares/recommind/logs/TcpIngestor.java +++ b/pdb-plotting/src/main/java/org/lucares/recommind/logs/TcpIngestor.java @@ -6,6 +6,7 @@ import java.io.InputStreamReader; import java.io.PrintWriter; import java.net.ServerSocket; import java.net.Socket; +import java.net.SocketAddress; import java.net.SocketTimeoutException; import java.nio.file.Path; import java.time.OffsetDateTime; @@ -23,6 +24,9 @@ import org.lucares.pdb.api.Entry; import org.lucares.pdb.api.Tags; import org.lucares.performance.db.BlockingQueueIterator; import org.lucares.performance.db.PerformanceDb; +import org.lucares.performance.db.ingestor.TcpIngestorTest; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; import com.fasterxml.jackson.core.type.TypeReference; import com.fasterxml.jackson.databind.MappingIterator; @@ -30,6 +34,7 @@ import com.fasterxml.jackson.databind.ObjectMapper; import com.fasterxml.jackson.databind.ObjectReader; public class TcpIngestor implements AutoCloseable { + private static final Logger LOGGER = LoggerFactory.getLogger(TcpIngestorTest.class); public static final int PORT = 17347; @@ -58,8 +63,9 @@ public class TcpIngestor implements AutoCloseable { @Override public Void call() throws Exception { - Thread.currentThread().setName("worker-" + clientSocket.getInetAddress()); - System.out.println("opening streams to client"); + final SocketAddress clientAddress = clientSocket.getRemoteSocketAddress(); + Thread.currentThread().setName("worker-" + clientAddress); + LOGGER.info("opening streams to client"); try (PrintWriter out = new PrintWriter(clientSocket.getOutputStream(), true); BufferedReader in = new BufferedReader(new InputStreamReader(clientSocket.getInputStream())); @@ -69,11 +75,11 @@ public class TcpIngestor implements AutoCloseable { double duration = 0.0; int count = 0; - System.out.println("reading from stream"); + LOGGER.info("reading from stream"); while (iterator.hasNext()) { final long start = System.nanoTime(); - // System.out.println("read: " + line); + // LOGGER.info("read: " + line); @SuppressWarnings("unchecked") final Map object = (Map) iterator.next(); @@ -83,7 +89,7 @@ public class TcpIngestor implements AutoCloseable { count++; if (count == 100000) { - // System.out.println("reading " + count + " took " + + // LOGGER.info("reading " + count + " took " + // duration + "ms"); duration = 0.0; count = 0; @@ -94,7 +100,7 @@ public class TcpIngestor implements AutoCloseable { } } - System.out.println("connection closed"); + LOGGER.info("connection closed: " + clientAddress); } return null; @@ -148,9 +154,9 @@ public class TcpIngestor implements AutoCloseable { } public TcpIngestor(final Path dataDirectory) { - System.out.println("opening performance db: " + dataDirectory); + LOGGER.info("opening performance db: " + dataDirectory); db = new PerformanceDb(dataDirectory); - System.out.println("performance db open"); + LOGGER.info("performance db open"); } public void start() throws Exception { @@ -179,17 +185,17 @@ public class TcpIngestor implements AutoCloseable { Thread.currentThread().setName("socket-listener"); try (ServerSocket serverSocket = new ServerSocket( PORT/* , 10, InetAddress.getLocalHost() */);) { - System.out.println("listening on port " + PORT); + LOGGER.info("listening on port " + PORT); serverSocket.setSoTimeout((int) TimeUnit.MILLISECONDS.toMillis(100)); while (acceptNewConnections.get()) { try { final Socket clientSocket = serverSocket.accept(); - System.out.println("accepted connection: " + clientSocket.getRemoteSocketAddress()); + LOGGER.info("accepted connection: " + clientSocket.getRemoteSocketAddress()); workerThreadPool.submit(new Handler(clientSocket, queue)); - System.out.println("handler submitted"); + LOGGER.info("handler submitted"); } catch (final SocketTimeoutException e) { // expected every 100ms // needed to be able to stop the server @@ -197,20 +203,20 @@ public class TcpIngestor implements AutoCloseable { e.printStackTrace(); } } - System.out.println("not accepting new connections. "); + LOGGER.info("not accepting new connections. "); - System.out.println("stopping worker pool"); + LOGGER.info("stopping worker pool"); workerThreadPool.shutdown(); try { workerThreadPool.awaitTermination(10, TimeUnit.MINUTES); - System.out.println("workers stopped"); + LOGGER.info("workers stopped"); } catch (final InterruptedException e) { e.printStackTrace(); } - System.out.println("adding poison"); + LOGGER.info("adding poison"); queue.offer(Entry.POISON); } catch (final Exception e) { - e.printStackTrace(); + LOGGER.error("", e); throw e; } return null; @@ -219,16 +225,16 @@ public class TcpIngestor implements AutoCloseable { @Override public void close() { acceptNewConnections.set(false); - System.out.println("stopped accept thread"); + LOGGER.info("stopped accept thread"); serverThreadPool.shutdown(); try { serverThreadPool.awaitTermination(10, TimeUnit.MINUTES); } catch (final InterruptedException e) { - e.printStackTrace(); + Thread.interrupted(); } - System.out.println("closing database"); + LOGGER.info("closing database"); db.close(); - System.out.println("close done"); + LOGGER.info("close done"); } public static void main(final String[] args) throws Exception { @@ -236,7 +242,7 @@ public class TcpIngestor implements AutoCloseable { Runtime.getRuntime().addShutdownHook(new Thread() { @Override public void run() { - System.out.println("shutdown hook"); + LOGGER.info("shutdown hook"); } }); diff --git a/pdb-plotting/src/test/java/org/lucares/performance/db/ingestor/TcpIngestorTest.java b/pdb-plotting/src/test/java/org/lucares/performance/db/ingestor/TcpIngestorTest.java index cd86cba..f5e22c5 100644 --- a/pdb-plotting/src/test/java/org/lucares/performance/db/ingestor/TcpIngestorTest.java +++ b/pdb-plotting/src/test/java/org/lucares/performance/db/ingestor/TcpIngestorTest.java @@ -20,6 +20,8 @@ import org.lucares.pdb.api.Entry; import org.lucares.performance.db.FileUtils; import org.lucares.performance.db.PerformanceDb; import org.lucares.recommind.logs.TcpIngestor; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; import org.testng.Assert; import org.testng.annotations.AfterMethod; import org.testng.annotations.BeforeMethod; @@ -31,6 +33,9 @@ import liquibase.exception.LiquibaseException; @Test public class TcpIngestorTest { + + private static final Logger LOGGER = LoggerFactory.getLogger(TcpIngestorTest.class); + private Path dataDirectory; @BeforeMethod @@ -67,7 +72,7 @@ public class TcpIngestorTest { send(entryA, entryB); } catch (final Exception e) { - e.printStackTrace(); + LOGGER.error("", e); throw e; } @@ -100,6 +105,7 @@ public class TcpIngestorTest { channel.write(src); channel.close(); + LOGGER.trace("closed sender connection"); } private SocketChannel connect() throws IOException { diff --git a/performanceDb/build.gradle b/performanceDb/build.gradle index 96a0736..1300014 100644 --- a/performanceDb/build.gradle +++ b/performanceDb/build.gradle @@ -3,4 +3,10 @@ dependencies { compile project(':pdb-api') compile 'org.lucares:ludb:1.0.20170101101722' compile 'com.fasterxml.jackson.core:jackson-databind:2.8.6' + + + + compile 'org.apache.logging.log4j:log4j-api:2.8' + compile 'org.apache.logging.log4j:log4j-core:2.8' + compile group: 'org.apache.logging.log4j', name: 'log4j-slf4j-impl', version: '2.8' } diff --git a/performanceDb/src/main/java/org/lucares/performance/db/BlockingQueueIterator.java b/performanceDb/src/main/java/org/lucares/performance/db/BlockingQueueIterator.java index d20c337..977047e 100644 --- a/performanceDb/src/main/java/org/lucares/performance/db/BlockingQueueIterator.java +++ b/performanceDb/src/main/java/org/lucares/performance/db/BlockingQueueIterator.java @@ -3,8 +3,13 @@ package org.lucares.performance.db; import java.util.Optional; import java.util.concurrent.BlockingQueue; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; + public final class BlockingQueueIterator implements BlockingIterator { + private static final Logger LOGGER = LoggerFactory.getLogger(BlockingQueueIterator.class); + private final BlockingQueue queue; private boolean closed = false; @@ -23,9 +28,12 @@ public final class BlockingQueueIterator implements BlockingIterator { return Optional.empty(); } + LOGGER.trace("wait for next entry"); final E next = queue.take(); + LOGGER.trace("received entry: {}", next); if (next == poison) { + LOGGER.trace("received poison"); closed = true; return Optional.empty(); } diff --git a/performanceDb/src/main/resources/log4j2.properties b/performanceDb/src/main/resources/log4j2.properties new file mode 100644 index 0000000..c70bf9f --- /dev/null +++ b/performanceDb/src/main/resources/log4j2.properties @@ -0,0 +1,13 @@ +name = PropertiesConfig +appenders = console + + +appender.console.type = Console +appender.console.name = STDOUT +appender.console.layout.type = PatternLayout +appender.console.layout.pattern = %d{yyyy-MM-dd HH:mm:ss.SSS} [%-5level] [%t] %c{1} - %msg%n + + + +rootLogger.level = trace +rootLogger.appenderRef.stdout.ref = STDOUT \ No newline at end of file