From 1561811acad70b8158f0d87ce8fbf7413c6dda02 Mon Sep 17 00:00:00 2001 From: Erik Joelsson Date: Thu, 15 Apr 2021 16:36:07 -0700 Subject: [PATCH 1/7] Implemented LogContext --- .../java/org/openjdk/skara/bot/BotRunner.java | 74 +++++----- .../org/openjdk/skara/bot/LogContext.java | 50 +++++++ .../org/openjdk/skara/bot/LogContextMap.java | 48 +++++++ .../openjdk/skara/bots/cli/BotLauncher.java | 14 +- .../skara/bots/cli/BotLogstashHandler.java | 86 ++--------- .../bots/cli/BotLogstashHandlerTests.java | 133 ++---------------- 6 files changed, 171 insertions(+), 234 deletions(-) create mode 100644 bot/src/main/java/org/openjdk/skara/bot/LogContext.java create mode 100644 bot/src/main/java/org/openjdk/skara/bot/LogContextMap.java diff --git a/bot/src/main/java/org/openjdk/skara/bot/BotRunner.java b/bot/src/main/java/org/openjdk/skara/bot/BotRunner.java index f114620fa..998c1ffc1 100644 --- a/bot/src/main/java/org/openjdk/skara/bot/BotRunner.java +++ b/bot/src/main/java/org/openjdk/skara/bot/BotRunner.java @@ -22,6 +22,7 @@ */ package org.openjdk.skara.bot; +import java.util.concurrent.atomic.AtomicInteger; import org.openjdk.skara.json.JSONValue; import java.io.IOException; @@ -49,6 +50,8 @@ enum TaskPhases { END } + private AtomicInteger workIdCounter = new AtomicInteger(); + private class RunnableWorkItem implements Runnable { private final WorkItem item; @@ -73,16 +76,19 @@ public void run() { scratchPath = scratchPaths.removeFirst(); } - log.log(Level.FINE, "Executing item " + item + " on repository " + scratchPath, TaskPhases.BEGIN); Collection followUpItems = null; - try { - followUpItems = item.run(scratchPath); - } catch (RuntimeException e) { - log.severe("Exception during item execution (" + item + "): " + e.getMessage()); - item.handleRuntimeException(e); - log.throwing(item.toString(), "run", e); - } finally { - log.log(Level.FINE, "Item " + item + " is now done", TaskPhases.END); + try (var __ = new LogContext(Map.of("work_item", item.toString(), + "work_id", String.valueOf(workIdCounter.incrementAndGet())))) { + log.log(Level.FINE, "Executing item " + item + " on repository " + scratchPath, TaskPhases.BEGIN); + try { + followUpItems = item.run(scratchPath); + } catch (RuntimeException e) { + log.severe("Exception during item execution (" + item + "): " + e.getMessage()); + item.handleRuntimeException(e); + log.throwing(item.toString(), "run", e); + } finally { + log.log(Level.FINE, "Item " + item + " is now done", TaskPhases.END); + } } if (followUpItems != null) { followUpItems.forEach(BotRunner.this::submitOrSchedule); @@ -215,19 +221,21 @@ public BotRunner(BotRunnerConfiguration config, List bots) { } private void checkPeriodicItems() { - log.log(Level.FINE, "Starting of checking for periodic items", TaskPhases.BEGIN); - try { - for (var bot : bots) { - var items = bot.getPeriodicItems(); - for (var item : items) { - submitOrSchedule(item); + try (var __ = new LogContext("work_id", String.valueOf(workIdCounter.incrementAndGet()))) { + log.log(Level.FINE, "Starting of checking for periodic items", TaskPhases.BEGIN); + try { + for (var bot : bots) { + var items = bot.getPeriodicItems(); + for (var item : items) { + submitOrSchedule(item); + } } + } catch (RuntimeException e) { + log.severe("Exception during periodic item checking: " + e.getMessage()); + log.throwing("BotRunner", "checkPeriodicItems", e); + } finally { + log.log(Level.FINE, "Done checking periodic items", TaskPhases.END); } - } catch (RuntimeException e) { - log.severe("Exception during periodic item checking: " + e.getMessage()); - log.throwing("BotRunner", "checkPeriodicItems", e); - } finally { - log.log(Level.FINE, "Done checking periodic items", TaskPhases.END); } } @@ -248,20 +256,22 @@ private void itemWatchdog() { } private void processRestRequest(JSONValue request) { - log.log(Level.FINE, "Starting processing of incoming rest request", TaskPhases.BEGIN); - log.fine("Request: " + request); - try { - for (var bot : bots) { - var items = bot.processWebHook(request); - for (var item : items) { - submitOrSchedule(item); + try (var __ = new LogContext("work_id", String.valueOf(workIdCounter.incrementAndGet()))) { + log.log(Level.FINE, "Starting processing of incoming rest request", TaskPhases.BEGIN); + log.fine("Request: " + request); + try { + for (var bot : bots) { + var items = bot.processWebHook(request); + for (var item : items) { + submitOrSchedule(item); + } } + } catch (RuntimeException e) { + log.severe("Exception during rest request processing: " + e.getMessage()); + log.throwing("BotRunner", "processRestRequest", e); + } finally { + log.log(Level.FINE, "Done processing incoming rest request", TaskPhases.END); } - } catch (RuntimeException e) { - log.severe("Exception during rest request processing: " + e.getMessage()); - log.throwing("BotRunner", "processRestRequest", e); - } finally { - log.log(Level.FINE, "Done processing incoming rest request", TaskPhases.END); } } diff --git a/bot/src/main/java/org/openjdk/skara/bot/LogContext.java b/bot/src/main/java/org/openjdk/skara/bot/LogContext.java new file mode 100644 index 000000000..1898aa25f --- /dev/null +++ b/bot/src/main/java/org/openjdk/skara/bot/LogContext.java @@ -0,0 +1,50 @@ +package org.openjdk.skara.bot; + +import java.util.HashMap; +import java.util.Map; +import java.util.logging.Logger; + +/** + * A LogContext is used to temporarily add extra log metadata in the current thread. + * It should be initiated with a try-with-resources construct. The variable itself + * is never used, we only want the controlled automatic close at the end of the try + * block. Typically name the variable __. Example: + * + * try (var __ = new LogContext("foo", "bar")) { + * // some code that logs stuff + * } + */ +public class LogContext implements AutoCloseable { + private static final Logger log = Logger.getLogger("org.openjdk.skara.bot"); + private final Map context = new HashMap<>(); + + public LogContext(String key, String value) { + this.init(Map.of(key, value)); + } + + public LogContext(Map ctx) { + this.init(ctx); + } + + private void init(Map newContext) { + for (var entry : newContext.entrySet()) { + String currentValue = LogContextMap.get(entry.getKey()); + if (currentValue != null) { + if (!currentValue.equals(entry.getValue())) { + log.severe("Tried to override the current LogContext value: " + currentValue + + " for " + entry.getKey() + " with a different value: " + entry.getValue()); + } + } else { + this.context.put(entry.getKey(), entry.getValue()); + LogContextMap.put(entry.getKey(), entry.getValue()); + } + } + + } + + public void close() { + this.context.forEach((key, value) -> { + LogContextMap.remove(key); + }); + } +} diff --git a/bot/src/main/java/org/openjdk/skara/bot/LogContextMap.java b/bot/src/main/java/org/openjdk/skara/bot/LogContextMap.java new file mode 100644 index 000000000..755128275 --- /dev/null +++ b/bot/src/main/java/org/openjdk/skara/bot/LogContextMap.java @@ -0,0 +1,48 @@ +package org.openjdk.skara.bot; + +import java.util.Collections; +import java.util.HashMap; +import java.util.Map; +import java.util.Set; + +/** + * This class holds a static thread local hashmap to store temporary log + * metadata which our custom LogStreamers can pick up and include in log + * messages. + */ +public class LogContextMap { + + private static final ThreadLocal> threadContextMap = new ThreadLocal<>(); + + public static void put(String key, String value) { + if (threadContextMap.get() == null) { + threadContextMap.set(new HashMap<>()); + } + var map = threadContextMap.get(); + map.put(key, value); + } + + public static String get(String key) { + if (threadContextMap.get() != null) { + return threadContextMap.get().get(key); + } else { + return null; + } + } + + public static String remove(String key) { + if (threadContextMap.get() != null) { + return threadContextMap.get().remove(key); + } else { + return null; + } + } + + public static Set> entrySet() { + if (threadContextMap.get() != null) { + return threadContextMap.get().entrySet(); + } else { + return Collections.emptySet(); + } + } +} diff --git a/bots/cli/src/main/java/org/openjdk/skara/bots/cli/BotLauncher.java b/bots/cli/src/main/java/org/openjdk/skara/bots/cli/BotLauncher.java index 3336a6570..e129f3676 100644 --- a/bots/cli/src/main/java/org/openjdk/skara/bots/cli/BotLauncher.java +++ b/bots/cli/src/main/java/org/openjdk/skara/bots/cli/BotLauncher.java @@ -22,6 +22,9 @@ */ package org.openjdk.skara.bots.cli; +import java.time.LocalDate; +import java.time.ZoneId; +import java.time.format.DateTimeFormatter; import org.openjdk.skara.args.*; import org.openjdk.skara.bot.*; import org.openjdk.skara.network.URIBuilder; @@ -41,6 +44,7 @@ public class BotLauncher { private static Logger log; + private static final LocalDate START_TIME = LocalDate.now(); private static void applyLogging(JSONObject config) { LogManager.getLogManager().reset(); @@ -81,11 +85,7 @@ private static void applyLogging(JSONObject config) { if (config.get("log").asObject().contains("logstash")) { var logstashConf = config.get("log").get("logstash").asObject(); var level = Level.parse(logstashConf.get("level").asString()); - var maxRecords = 100; - if (logstashConf.contains("maxrecords")) { - maxRecords = logstashConf.get("maxrecords").asInt(); - } - var handler = new BotLogstashHandler(URIBuilder.base(logstashConf.get("endpoint").asString()).build(), maxRecords); + var handler = new BotLogstashHandler(URIBuilder.base(logstashConf.get("endpoint").asString()).build()); if (logstashConf.contains("fields")) { for (var field : logstashConf.get("fields").asArray()) { if (field.asObject().contains("pattern")) { @@ -99,6 +99,10 @@ private static void applyLogging(JSONObject config) { } } handler.setLevel(level); + var dateTimeFormatter = DateTimeFormatter.ISO_INSTANT + .withLocale(Locale.getDefault()) + .withZone(ZoneId.systemDefault()); + handler.addExtraField("instance_start_time", START_TIME.format(dateTimeFormatter)); log.addHandler(handler); } } diff --git a/bots/cli/src/main/java/org/openjdk/skara/bots/cli/BotLogstashHandler.java b/bots/cli/src/main/java/org/openjdk/skara/bots/cli/BotLogstashHandler.java index 2b49d729e..c940b0922 100644 --- a/bots/cli/src/main/java/org/openjdk/skara/bots/cli/BotLogstashHandler.java +++ b/bots/cli/src/main/java/org/openjdk/skara/bots/cli/BotLogstashHandler.java @@ -22,7 +22,7 @@ */ package org.openjdk.skara.bots.cli; -import org.openjdk.skara.bot.BotTaskAggregationHandler; +import org.openjdk.skara.bot.LogContextMap; import org.openjdk.skara.network.RestRequest; import org.openjdk.skara.json.JSON; @@ -33,12 +33,10 @@ import java.util.*; import java.util.logging.*; import java.util.regex.Pattern; -import java.util.stream.Collectors; -public class BotLogstashHandler extends BotTaskAggregationHandler { +public class BotLogstashHandler extends StreamHandler { private final RestRequest endpoint; private final DateTimeFormatter dateTimeFormatter; - private final int maxRecords; private final Logger log = Logger.getLogger("org.openjdk.skara.bots.cli"); @@ -50,9 +48,8 @@ private static class ExtraField { private final List extraFields; - BotLogstashHandler(URI endpoint, int maxRecords) { + BotLogstashHandler(URI endpoint) { this.endpoint = new RestRequest(endpoint); - this.maxRecords = maxRecords; dateTimeFormatter = DateTimeFormatter.ISO_INSTANT .withLocale(Locale.getDefault()) .withZone(ZoneId.systemDefault()); @@ -81,6 +78,10 @@ private void publishToLogstash(Instant time, Level level, String message, Map entry : LogContextMap.entrySet()) { + query.put(entry.getKey(), entry.getValue()); + } + for (var extraField : extraFields.entrySet()) { query.put(extraField.getKey(), extraField.getValue()); } @@ -94,28 +95,6 @@ private void publishToLogstash(Instant time, Level level, String message, Map getExtraFields(LogRecord record) { var ret = new HashMap(); for (var extraField : extraFields) { @@ -132,57 +111,8 @@ private Map getExtraFields(LogRecord record) { return ret; } - // Remove every entry below minLevel - private List filterRecords(List records, Level minLevel) { - return records.stream() - .filter(entry -> entry.getLevel().intValue() >= minLevel.intValue()) - .collect(Collectors.toList()); - } - - @Override - public void publishAggregated(List task) { - var maxLevel = task.stream() - .max(Comparator.comparingInt(r -> r.getLevel().intValue())) - .map(LogRecord::getLevel) - .orElseThrow(); - if (maxLevel.intValue() < getLevel().intValue()) { - return; - } - - var start = task.get(0).getInstant(); - - // For duplicate keys, the first value seen is retained - var concatenatedFields = task.stream() - .map(this::getExtraFields) - .flatMap(extra -> extra.entrySet().stream()) - .collect(Collectors.toMap(Map.Entry::getKey, Map.Entry::getValue, - (value1, value2) -> value1)); - - // First try to accommodate size limit by filtering out low level logging - if (task.size() > maxRecords) { - task = filterRecords(task, Level.FINER); - } - if (task.size() > maxRecords) { - task = filterRecords(task, Level.FINE); - } - - // If there's still too many lines, strip out the middle - if (task.size() > maxRecords) { - var beginning = task.subList(0, maxRecords / 2); - var end = task.subList(task.size() - maxRecords / 2, task.size()); - task = beginning; - task.addAll(end); - } - - var concatenatedMessage = task.stream() - .map(record -> formatRecord(start, record)) - .collect(Collectors.joining("\n")); - - publishToLogstash(start, maxLevel, concatenatedMessage, concatenatedFields); - } - @Override - public void publishSingle(LogRecord record) { + public void publish(LogRecord record) { if (record.getLevel().intValue() < getLevel().intValue()) { return; } diff --git a/bots/cli/src/test/java/org/openjdk/skara/bots/cli/BotLogstashHandlerTests.java b/bots/cli/src/test/java/org/openjdk/skara/bots/cli/BotLogstashHandlerTests.java index a8c974229..6484c4ae7 100644 --- a/bots/cli/src/test/java/org/openjdk/skara/bots/cli/BotLogstashHandlerTests.java +++ b/bots/cli/src/test/java/org/openjdk/skara/bots/cli/BotLogstashHandlerTests.java @@ -34,7 +34,7 @@ class BotLogstashHandlerTests { @Test void simple() throws IOException { try (var receiver = new RestReceiver()) { - var handler = new BotLogstashHandler(receiver.getEndpoint(), 100); + var handler = new BotLogstashHandler(receiver.getEndpoint()); var record = new LogRecord(Level.INFO, "Hello"); handler.publish(record); @@ -48,7 +48,7 @@ var record = new LogRecord(Level.INFO, "Hello"); @Test void simpleTask() throws IOException { try (var receiver = new RestReceiver()) { - var handler = new BotLogstashHandler(receiver.getEndpoint(), 100); + var handler = new BotLogstashHandler(receiver.getEndpoint()); LoggingBot.runOnce(handler, log -> { log.warning("Hello"); @@ -57,20 +57,23 @@ void simpleTask() throws IOException { }); var requests = receiver.getRequests(); - assertEquals(1, requests.size(), requests.toString()); + assertEquals(3, requests.size(), requests.toString()); assertEquals(Level.WARNING.getName(), requests.get(0).get("level").asString()); assertEquals(Level.WARNING.intValue(), requests.get(0).get("level_value").asInt()); - assertTrue(requests.get(0).get("message").asString().contains("Hello")); - assertTrue(requests.get(0).get("message").asString().contains("Warning")); - assertTrue(requests.get(0).get("message").asString().contains("Bye")); - assertTrue(requests.get(0).get("message").asString().contains(Level.WARNING.toString())); + assertEquals("Hello", requests.get(0).get("message").asString()); + assertEquals("Warning!", requests.get(1).get("message").asString()); + assertEquals("Bye", requests.get(2).get("message").asString()); + assertEquals(Level.WARNING.toString(), requests.get(0).get("level").asString()); + assertNotNull(requests.get(0).get("work_id"), "work_id not set"); + assertTrue(requests.get(0).get("work_item").asString().contains("LoggingBot@"), + "work_item has bad value " + requests.get(0).get("work_item").asString()); } } @Test void extraField() throws IOException { try (var receiver = new RestReceiver()) { - var handler = new BotLogstashHandler(receiver.getEndpoint(), 100); + var handler = new BotLogstashHandler(receiver.getEndpoint()); handler.addExtraField("mandatory", "value"); handler.addExtraField("optional1", "$1", "^H(ello)$"); handler.addExtraField("optional2", "$1", "^(Not found)$"); @@ -88,7 +91,7 @@ var record = new LogRecord(Level.INFO, "Hello"); @Test void extraFieldTask() throws IOException { try (var receiver = new RestReceiver()) { - var handler = new BotLogstashHandler(receiver.getEndpoint(), 100); + var handler = new BotLogstashHandler(receiver.getEndpoint()); handler.addExtraField("mandatory", "value"); handler.addExtraField("optional1", "$1", "^H(ello)$"); handler.addExtraField("optional2", "$1", "^(Not found)$"); @@ -102,119 +105,11 @@ void extraFieldTask() throws IOException { }); var requests = receiver.getRequests(); - assertEquals(1, requests.size(), requests.toString()); + assertEquals(3, requests.size(), requests.toString()); assertEquals("value", requests.get(0).get("mandatory").asString()); assertEquals("ello", requests.get(0).get("optional1").asString()); assertFalse(requests.get(0).contains("optional2")); - assertEquals("ye", requests.get(0).get("optional3").asString()); - assertTrue(requests.get(0).get("greedy").asString().contains("Executing item")); - } - } - - @Test - void filterLowLevels() throws IOException { - try (var receiver = new RestReceiver()) { - var handler = new BotLogstashHandler(receiver.getEndpoint(), 10); - - LoggingBot.runOnce(handler, Level.FINER, log -> { - for (int i = 0; i < 5; ++i) { - log.fine("Fine nr " + i); - } - for (int i = 0; i < 5; ++i) { - log.finer("Finer nr " + i); - } - }); - - var requests = receiver.getRequests(); - var aggregatedLines = requests.stream() - .filter(request -> request.get("message").asString().contains("Executing item")) - .findAny() - .orElseThrow() - .get("message") - .asString() - .lines() - .collect(Collectors.toList()); - - var fineLines = aggregatedLines.stream() - .filter(line -> line.contains("Fine nr")) - .collect(Collectors.toList()); - var finerLines = aggregatedLines.stream() - .filter(line -> line.contains("Finer nr")) - .collect(Collectors.toList()); - assertEquals(5, fineLines.size(), aggregatedLines.toString()); - assertEquals(0, finerLines.size(), aggregatedLines.toString()); - } - } - - @Test - void filterLowestLevels() throws IOException { - try (var receiver = new RestReceiver()) { - var handler = new BotLogstashHandler(receiver.getEndpoint(), 15); - - LoggingBot.runOnce(handler, Level.FINER, log -> { - for (int i = 0; i < 5; ++i) { - log.fine("Fine nr " + i); - } - for (int i = 0; i < 5; ++i) { - log.finer("Finer nr " + i); - } - for (int i = 0; i < 5; ++i) { - log.finest("Finest nr " + i); - } - }); - - var requests = receiver.getRequests(); - var aggregatedLines = requests.stream() - .filter(request -> request.get("message").asString().contains("Executing item")) - .findAny() - .orElseThrow() - .get("message") - .asString() - .lines() - .collect(Collectors.toList()); - - var fineLines = aggregatedLines.stream() - .filter(line -> line.contains("Fine nr")) - .collect(Collectors.toList()); - var finerLines = aggregatedLines.stream() - .filter(line -> line.contains("Finer nr")) - .collect(Collectors.toList()); - var finestLines = aggregatedLines.stream() - .filter(line -> line.contains("Finest nr")) - .collect(Collectors.toList()); - assertEquals(5, fineLines.size(), aggregatedLines.toString()); - assertEquals(5, finerLines.size(), aggregatedLines.toString()); - assertEquals(0, finestLines.size(), aggregatedLines.toString()); - } - } - - @Test - void filterMiddle() throws IOException { - try (var receiver = new RestReceiver()) { - var handler = new BotLogstashHandler(receiver.getEndpoint(), 100); - - LoggingBot.runOnce(handler, Level.FINER, log -> { - for (int i = 0; i < 100; ++i) { - log.fine("Start nr " + i); - } - for (int i = 0; i < 100; ++i) { - log.fine("Middle nr " + i); - } - for (int i = 0; i < 100; ++i) { - log.fine("End nr " + i); - } - }); - - var requests = receiver.getRequests(); - var aggregatedLines = requests.stream() - .filter(request -> request.get("message").asString().contains("Executing item")) - .findAny() - .orElseThrow() - .get("message") - .asString(); - assertTrue(aggregatedLines.contains("Start nr")); - assertFalse(aggregatedLines.contains("Middle nr")); - assertTrue(aggregatedLines.contains("End nr")); + assertEquals("ye", requests.get(2).get("optional3").asString()); } } } From f1ec8ffd7dfe9d930d994a7e1ee7c1f5d9038fcd Mon Sep 17 00:00:00 2001 From: Erik Joelsson Date: Thu, 15 Apr 2021 16:40:28 -0700 Subject: [PATCH 2/7] Corrected comment --- bot/src/main/java/org/openjdk/skara/bot/LogContextMap.java | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/bot/src/main/java/org/openjdk/skara/bot/LogContextMap.java b/bot/src/main/java/org/openjdk/skara/bot/LogContextMap.java index 755128275..4c92d91f5 100644 --- a/bot/src/main/java/org/openjdk/skara/bot/LogContextMap.java +++ b/bot/src/main/java/org/openjdk/skara/bot/LogContextMap.java @@ -7,7 +7,7 @@ /** * This class holds a static thread local hashmap to store temporary log - * metadata which our custom LogStreamers can pick up and include in log + * metadata which our custom StreamHandlers can pick up and include in log * messages. */ public class LogContextMap { From c257abd288b6b13e74fefe1e9fd528dccc374160 Mon Sep 17 00:00:00 2001 From: Erik Joelsson <37597443+erikj79@users.noreply.github.com> Date: Fri, 16 Apr 2021 12:29:28 -0700 Subject: [PATCH 3/7] Update bots/cli/src/main/java/org/openjdk/skara/bots/cli/BotLogstashHandler.java Co-authored-by: Robin Westberg --- .../java/org/openjdk/skara/bots/cli/BotLogstashHandler.java | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/bots/cli/src/main/java/org/openjdk/skara/bots/cli/BotLogstashHandler.java b/bots/cli/src/main/java/org/openjdk/skara/bots/cli/BotLogstashHandler.java index c940b0922..33610f7e2 100644 --- a/bots/cli/src/main/java/org/openjdk/skara/bots/cli/BotLogstashHandler.java +++ b/bots/cli/src/main/java/org/openjdk/skara/bots/cli/BotLogstashHandler.java @@ -78,7 +78,7 @@ private void publishToLogstash(Instant time, Level level, String message, Map entry : LogContextMap.entrySet()) { + for (var entry : LogContextMap.entrySet()) { query.put(entry.getKey(), entry.getValue()); } From b82a7bc7c8c42393a024c109e64d8b8cfc4efd49 Mon Sep 17 00:00:00 2001 From: Erik Joelsson Date: Fri, 16 Apr 2021 12:51:15 -0700 Subject: [PATCH 4/7] Added simple test of LogContext --- .../openjdk/skara/bot/LogContextTests.java | 19 +++++++++++++++++++ 1 file changed, 19 insertions(+) create mode 100644 bot/src/test/java/org/openjdk/skara/bot/LogContextTests.java diff --git a/bot/src/test/java/org/openjdk/skara/bot/LogContextTests.java b/bot/src/test/java/org/openjdk/skara/bot/LogContextTests.java new file mode 100644 index 000000000..4a04b63b1 --- /dev/null +++ b/bot/src/test/java/org/openjdk/skara/bot/LogContextTests.java @@ -0,0 +1,19 @@ +package org.openjdk.skara.bot; + +import org.junit.jupiter.api.Test; + +import static org.junit.jupiter.api.Assertions.assertEquals; +import static org.junit.jupiter.api.Assertions.assertNull; + +public class LogContextTests { + + @Test + public void simple() { + String key = "keyname"; + assertNull(LogContextMap.get(key), "Key " + key + " already present in context"); + try (var __ = new LogContext(key, "value")) { + assertEquals("value", LogContextMap.get(key), "Context property not set"); + } + assertNull(LogContextMap.get(key), "Context property not removed"); + } +} From 6566eb8ae6c3110cceedefe75fc2bb18f659efc5 Mon Sep 17 00:00:00 2001 From: Erik Joelsson Date: Fri, 16 Apr 2021 13:37:25 -0700 Subject: [PATCH 5/7] Fix start time stamp --- .../main/java/org/openjdk/skara/bots/cli/BotLauncher.java | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/bots/cli/src/main/java/org/openjdk/skara/bots/cli/BotLauncher.java b/bots/cli/src/main/java/org/openjdk/skara/bots/cli/BotLauncher.java index e129f3676..f375527dd 100644 --- a/bots/cli/src/main/java/org/openjdk/skara/bots/cli/BotLauncher.java +++ b/bots/cli/src/main/java/org/openjdk/skara/bots/cli/BotLauncher.java @@ -22,7 +22,7 @@ */ package org.openjdk.skara.bots.cli; -import java.time.LocalDate; +import java.time.Instant; import java.time.ZoneId; import java.time.format.DateTimeFormatter; import org.openjdk.skara.args.*; @@ -44,7 +44,7 @@ public class BotLauncher { private static Logger log; - private static final LocalDate START_TIME = LocalDate.now(); + private static final Instant START_TIME = Instant.now(); private static void applyLogging(JSONObject config) { LogManager.getLogManager().reset(); @@ -102,7 +102,7 @@ private static void applyLogging(JSONObject config) { var dateTimeFormatter = DateTimeFormatter.ISO_INSTANT .withLocale(Locale.getDefault()) .withZone(ZoneId.systemDefault()); - handler.addExtraField("instance_start_time", START_TIME.format(dateTimeFormatter)); + handler.addExtraField("instance_start_time", dateTimeFormatter.format(START_TIME)); log.addHandler(handler); } } From 2c315bc25fd63d34c5f517d3e24cc63d7ed615d9 Mon Sep 17 00:00:00 2001 From: Erik Joelsson Date: Mon, 19 Apr 2021 15:54:45 -0700 Subject: [PATCH 6/7] Use HttpClient.sendAsync directly to send to logstash --- bots/cli/src/main/java/module-info.java | 1 + .../skara/bots/cli/BotLogstashHandler.java | 62 ++++++++++++------- .../bots/cli/BotLogstashHandlerTests.java | 55 +++++++++++++--- 3 files changed, 87 insertions(+), 31 deletions(-) diff --git a/bots/cli/src/main/java/module-info.java b/bots/cli/src/main/java/module-info.java index c9243b354..62a24d24d 100644 --- a/bots/cli/src/main/java/module-info.java +++ b/bots/cli/src/main/java/module-info.java @@ -33,6 +33,7 @@ requires org.openjdk.skara.network; requires org.openjdk.skara.version; + requires java.net.http; requires java.sql; exports org.openjdk.skara.bots.cli; diff --git a/bots/cli/src/main/java/org/openjdk/skara/bots/cli/BotLogstashHandler.java b/bots/cli/src/main/java/org/openjdk/skara/bots/cli/BotLogstashHandler.java index 33610f7e2..930baebcc 100644 --- a/bots/cli/src/main/java/org/openjdk/skara/bots/cli/BotLogstashHandler.java +++ b/bots/cli/src/main/java/org/openjdk/skara/bots/cli/BotLogstashHandler.java @@ -23,22 +23,27 @@ package org.openjdk.skara.bots.cli; import org.openjdk.skara.bot.LogContextMap; -import org.openjdk.skara.network.RestRequest; import org.openjdk.skara.json.JSON; -import java.io.*; import java.net.URI; +import java.net.http.*; import java.time.*; import java.time.format.DateTimeFormatter; import java.util.*; +import java.util.concurrent.Future; import java.util.logging.*; import java.util.regex.Pattern; +/** + * Handles logging to logstash. Be careful not to call anything that creates new + * log records from this class as that can cause infinite recursion. + */ public class BotLogstashHandler extends StreamHandler { - private final RestRequest endpoint; + private final URI endpoint; + private final HttpClient httpClient; private final DateTimeFormatter dateTimeFormatter; - private final Logger log = Logger.getLogger("org.openjdk.skara.bots.cli"); - + // Optionally store all futures for testing purposes + private Collection>> futures; private static class ExtraField { String name; @@ -49,7 +54,11 @@ private static class ExtraField { private final List extraFields; BotLogstashHandler(URI endpoint) { - this.endpoint = new RestRequest(endpoint); + this.endpoint = endpoint; + this.httpClient = HttpClient.newBuilder() + .followRedirects(HttpClient.Redirect.NORMAL) + .connectTimeout(Duration.ofSeconds(30)) + .build(); dateTimeFormatter = DateTimeFormatter.ISO_INSTANT .withLocale(Locale.getDefault()) .withZone(ZoneId.systemDefault()); @@ -71,27 +80,28 @@ void addExtraField(String name, String value, String pattern) { } private void publishToLogstash(Instant time, Level level, String message, Map extraFields) { - try { - var query = JSON.object(); - query.put("@timestamp", dateTimeFormatter.format(time)); - query.put("level", level.getName()); - query.put("level_value", level.intValue()); - query.put("message", message); + var query = JSON.object(); + query.put("@timestamp", dateTimeFormatter.format(time)); + query.put("level", level.getName()); + query.put("level_value", level.intValue()); + query.put("message", message); - for (var entry : LogContextMap.entrySet()) { - query.put(entry.getKey(), entry.getValue()); - } + for (var entry : LogContextMap.entrySet()) { + query.put(entry.getKey(), entry.getValue()); + } - for (var extraField : extraFields.entrySet()) { - query.put(extraField.getKey(), extraField.getValue()); - } + for (var extraField : extraFields.entrySet()) { + query.put(extraField.getKey(), extraField.getValue()); + } - endpoint.post("/") - .body(query) - .executeUnparsed(); - } catch (RuntimeException | IOException e) { - log.warning("Exception during logstash publishing: " + e.getMessage()); - log.throwing("BotSlackHandler", "publish", e); + var httpRequest = HttpRequest.newBuilder() + .uri(endpoint) + .header("Content-Type", "application/json") + .POST(HttpRequest.BodyPublishers.ofString(query.toString())) + .build(); + var future = httpClient.sendAsync(httpRequest, HttpResponse.BodyHandlers.discarding()); + if (futures != null) { + futures.add(future); } } @@ -118,4 +128,8 @@ public void publish(LogRecord record) { } publishToLogstash(record.getInstant(), record.getLevel(), record.getMessage(), getExtraFields(record)); } + + void setFuturesCollection(Collection>> futures) { + this.futures = futures; + } } diff --git a/bots/cli/src/test/java/org/openjdk/skara/bots/cli/BotLogstashHandlerTests.java b/bots/cli/src/test/java/org/openjdk/skara/bots/cli/BotLogstashHandlerTests.java index 6484c4ae7..a775611ac 100644 --- a/bots/cli/src/test/java/org/openjdk/skara/bots/cli/BotLogstashHandlerTests.java +++ b/bots/cli/src/test/java/org/openjdk/skara/bots/cli/BotLogstashHandlerTests.java @@ -22,22 +22,35 @@ */ package org.openjdk.skara.bots.cli; -import org.junit.jupiter.api.*; +import org.junit.jupiter.api.Test; import java.io.IOException; -import java.util.logging.*; -import java.util.stream.Collectors; +import java.net.http.HttpResponse; +import java.util.ArrayList; +import java.util.Comparator; +import java.util.concurrent.ExecutionException; +import java.util.concurrent.Future; +import java.util.logging.Level; +import java.util.logging.LogRecord; import static org.junit.jupiter.api.Assertions.*; class BotLogstashHandlerTests { + @Test - void simple() throws IOException { + void simple() throws IOException, ExecutionException, InterruptedException { try (var receiver = new RestReceiver()) { var handler = new BotLogstashHandler(receiver.getEndpoint()); + var futures = new ArrayList>>(); + handler.setFuturesCollection(futures); + var record = new LogRecord(Level.INFO, "Hello"); handler.publish(record); + for (Future> future : futures) { + future.get(); + } + var requests = receiver.getRequests(); assertEquals(1, requests.size(), requests.toString()); assertTrue(requests.get(0).get("message").asString().contains("Hello")); @@ -46,9 +59,11 @@ var record = new LogRecord(Level.INFO, "Hello"); } @Test - void simpleTask() throws IOException { + void simpleTask() throws IOException, ExecutionException, InterruptedException { try (var receiver = new RestReceiver()) { var handler = new BotLogstashHandler(receiver.getEndpoint()); + var futures = new ArrayList>>(); + handler.setFuturesCollection(futures); LoggingBot.runOnce(handler, log -> { log.warning("Hello"); @@ -56,7 +71,15 @@ void simpleTask() throws IOException { log.warning("Bye"); }); + for (Future> future : futures) { + future.get(); + } + var requests = receiver.getRequests(); + // The async message sending means we may get results in any order. Sort on the + // timestamp to get the actual order. + requests.sort(Comparator.comparing(r -> r.get("@timestamp").toString())); + assertEquals(3, requests.size(), requests.toString()); assertEquals(Level.WARNING.getName(), requests.get(0).get("level").asString()); assertEquals(Level.WARNING.intValue(), requests.get(0).get("level_value").asInt()); @@ -71,15 +94,22 @@ void simpleTask() throws IOException { } @Test - void extraField() throws IOException { + void extraField() throws IOException, ExecutionException, InterruptedException { try (var receiver = new RestReceiver()) { var handler = new BotLogstashHandler(receiver.getEndpoint()); + var futures = new ArrayList>>(); + handler.setFuturesCollection(futures); + handler.addExtraField("mandatory", "value"); handler.addExtraField("optional1", "$1", "^H(ello)$"); handler.addExtraField("optional2", "$1", "^(Not found)$"); var record = new LogRecord(Level.INFO, "Hello"); handler.publish(record); + for (Future> future : futures) { + future.get(); + } + var requests = receiver.getRequests(); assertEquals(1, requests.size(), requests.toString()); assertEquals("value", requests.get(0).get("mandatory").asString()); @@ -89,9 +119,12 @@ var record = new LogRecord(Level.INFO, "Hello"); } @Test - void extraFieldTask() throws IOException { + void extraFieldTask() throws IOException, ExecutionException, InterruptedException { try (var receiver = new RestReceiver()) { var handler = new BotLogstashHandler(receiver.getEndpoint()); + var futures = new ArrayList>>(); + handler.setFuturesCollection(futures); + handler.addExtraField("mandatory", "value"); handler.addExtraField("optional1", "$1", "^H(ello)$"); handler.addExtraField("optional2", "$1", "^(Not found)$"); @@ -104,7 +137,15 @@ void extraFieldTask() throws IOException { log.warning("Bye"); }); + for (Future> future : futures) { + future.get(); + } + var requests = receiver.getRequests(); + // The async message sending means we may get results in any order. Sort on the + // timestamp to get the actual order. + requests.sort(Comparator.comparing(r -> r.get("@timestamp").toString())); + assertEquals(3, requests.size(), requests.toString()); assertEquals("value", requests.get(0).get("mandatory").asString()); assertEquals("ello", requests.get(0).get("optional1").asString()); From 6bd3be2bc7b6c6c88c5ddce5137a5ddbb74deda1 Mon Sep 17 00:00:00 2001 From: Erik Joelsson Date: Tue, 20 Apr 2021 06:28:58 -0700 Subject: [PATCH 7/7] Add comment --- .../main/java/org/openjdk/skara/bots/cli/BotLogstashHandler.java | 1 + 1 file changed, 1 insertion(+) diff --git a/bots/cli/src/main/java/org/openjdk/skara/bots/cli/BotLogstashHandler.java b/bots/cli/src/main/java/org/openjdk/skara/bots/cli/BotLogstashHandler.java index 930baebcc..b029ab3ec 100644 --- a/bots/cli/src/main/java/org/openjdk/skara/bots/cli/BotLogstashHandler.java +++ b/bots/cli/src/main/java/org/openjdk/skara/bots/cli/BotLogstashHandler.java @@ -100,6 +100,7 @@ private void publishToLogstash(Instant time, Level level, String message, Map