From 02b7b77e6787802e703f58b4a8101167b84dc9f4 Mon Sep 17 00:00:00 2001 From: Barry Nouwt Date: Tue, 17 Mar 2026 16:10:04 +0100 Subject: [PATCH 1/4] Modified log statements to see who's involved. --- .../impl/InteractionProcessorImpl.java | 31 +++-- .../impl/MessageRouterImpl.java | 16 +-- .../impl/ReasonerProcessor.java | 108 +++++++++++++----- .../impl/SmartConnectorImpl.java | 17 +-- .../smartconnector/util/KnowledgeNetwork.java | 4 +- 5 files changed, 118 insertions(+), 58 deletions(-) diff --git a/smart-connector/src/main/java/eu/knowledge/engine/smartconnector/impl/InteractionProcessorImpl.java b/smart-connector/src/main/java/eu/knowledge/engine/smartconnector/impl/InteractionProcessorImpl.java index 6e98061f1..ec9aebb72 100644 --- a/smart-connector/src/main/java/eu/knowledge/engine/smartconnector/impl/InteractionProcessorImpl.java +++ b/smart-connector/src/main/java/eu/knowledge/engine/smartconnector/impl/InteractionProcessorImpl.java @@ -175,7 +175,7 @@ private Set filterOtherKnowledgeBases(Set processAskFromMessageRouter(AskMessage a AnswerMessage m = new AnswerMessage(anAskMsg.getToKnowledgeBase(), anAskMsg.getToKnowledgeInteraction(), anAskMsg.getFromKnowledgeBase(), anAskMsg.getFromKnowledgeInteraction(), anAskMsg.getMessageId(), "Received AskMessage wth unknown ToKnowledgeInteractionId"); - LOG.debug("Received AskMessage with unknown ToKnowledgeInteractionId: " + LOG.trace("Received AskMessage with unknown ToKnowledgeInteractionId: " + anAskMsg.getToKnowledgeInteraction().toString()); CompletableFuture f = new CompletableFuture<>(); f.complete(m); @@ -243,7 +243,7 @@ public CompletableFuture processAskFromMessageRouter(AskMessage a // TODO This should happen in the single thread for the knowledge base if (answerKnowledgeInteraction.isMeta()) { - LOG.debug("Contacting my KB to answer KI <{}>", answerKnowledgeInteractionId); + LOG.trace("Contacting my KB to answer KI <{}>", answerKnowledgeInteractionId); } else { LOG.info("Contacting my KB to answer KI <{}>", answerKnowledgeInteractionId); } @@ -255,7 +255,13 @@ public CompletableFuture processAskFromMessageRouter(AskMessage a return future.handle((b, e) -> { if (b != null && e == null) { - LOG.debug("Received ANSWER from KB for KI <{}>: {}", answerKnowledgeInteractionId, b); + + String logStatement = "Received {} binding(s) as answer from KB for KI <{}>"; + if (!answerKnowledgeInteraction.isMeta()) + LOG.debug(logStatement, b.size(), answerKnowledgeInteractionId); + else + LOG.trace(logStatement, b.size(), answerKnowledgeInteractionId); + BindingSet translatedB = Util.translateFromApiBindingSet(b); if (this.shouldValidateInputOutputBindings()) { @@ -280,7 +286,7 @@ public CompletableFuture processAskFromMessageRouter(AskMessage a } }).exceptionally((e) -> { LOG.error("An error occurred while answering a msg: ", e); - LOG.debug("The error occured while answering this message: {}", anAskMsg); + LOG.trace("The error occured while answering this message: {}", anAskMsg); return new AnswerMessage(anAskMsg.getToKnowledgeBase(), answerKnowledgeInteractionId, anAskMsg.getFromKnowledgeBase(), anAskMsg.getFromKnowledgeInteraction(), anAskMsg.getMessageId(), e.getMessage()); @@ -340,7 +346,7 @@ public CompletableFuture processPostFromMessageRouter(PostMessage ReactMessage m = new ReactMessage(aPostMsg.getToKnowledgeBase(), aPostMsg.getToKnowledgeInteraction(), aPostMsg.getFromKnowledgeBase(), aPostMsg.getFromKnowledgeInteraction(), aPostMsg.getMessageId(), "Received PostMessage with unknown ToKnowledgeInteractionId"); - LOG.debug("Received PostMessage with unknown ToKnowledgeInteractionId: " + LOG.trace("Received PostMessage with unknown ToKnowledgeInteractionId: " + aPostMsg.getToKnowledgeInteraction().toString()); CompletableFuture f = new CompletableFuture<>(); f.complete(m); @@ -358,7 +364,7 @@ public CompletableFuture processPostFromMessageRouter(PostMessage // TODO This should happen in the single thread for the knowledge base if (reactKnowledgeInteraction.isMeta()) { - LOG.debug("Contacting my KB to react to KI <{}>", reactKnowledgeInteractionId); + LOG.trace("Contacting my KB to react to KI <{}>", reactKnowledgeInteractionId); } else { LOG.info("Contacting my KB to react to KI <{}>", reactKnowledgeInteractionId); } @@ -367,7 +373,12 @@ public CompletableFuture processPostFromMessageRouter(PostMessage return future.handle((b, e) -> { if (b != null && e == null) { - LOG.debug("Received REACT from KB for KI <{}>: {}", reactKnowledgeInteraction, b); + String logStatement = "Received {} binding(s) as react from KB for KI <{}>"; + if (!reactKnowledgeInteraction.isMeta()) + LOG.debug(logStatement, b.size(), reactKnowledgeInteractionId); + else + LOG.trace(logStatement, b.size(), reactKnowledgeInteractionId); + BindingSet translatedB = Util.translateFromApiBindingSet(b); if (this.shouldValidateInputOutputBindings()) { @@ -393,7 +404,7 @@ public CompletableFuture processPostFromMessageRouter(PostMessage } }).exceptionally((e) -> { LOG.error("An error occurred while reacting to a message:", e); - LOG.debug("The error occured while reacting to this message: {}", aPostMsg); + LOG.trace("The error occured while reacting to this message: {}", aPostMsg); return new ReactMessage(aPostMsg.getToKnowledgeBase(), reactKnowledgeInteractionId, aPostMsg.getFromKnowledgeBase(), aPostMsg.getFromKnowledgeInteraction(), aPostMsg.getMessageId(), e.getMessage()); @@ -539,7 +550,7 @@ public int getReasonerLevel() { private void readAdditionalDomainKnowledge(String pathString) { Path p = FileSystems.getDefault().getPath(pathString); - LOG.debug("Reading additional domain knowledge from path: " + p.toAbsolutePath()); + LOG.trace("Reading additional domain knowledge from path: " + p.toAbsolutePath()); try (BufferedReader r = Files.newBufferedReader(p.toAbsolutePath(), StandardCharsets.UTF_8)) { diff --git a/smart-connector/src/main/java/eu/knowledge/engine/smartconnector/impl/MessageRouterImpl.java b/smart-connector/src/main/java/eu/knowledge/engine/smartconnector/impl/MessageRouterImpl.java index f13bfef8f..f51e56e2d 100644 --- a/smart-connector/src/main/java/eu/knowledge/engine/smartconnector/impl/MessageRouterImpl.java +++ b/smart-connector/src/main/java/eu/knowledge/engine/smartconnector/impl/MessageRouterImpl.java @@ -102,7 +102,7 @@ public CompletableFuture sendAskMessage(AskMessage askMessage) th LOG.error("KB '{}' did not respond within {}s to AskMessage '{}'.", askMessage.getToKnowledgeBase(), this.getWaitTimeout(), askMessage.getMessageId()); else if (e instanceof CancellationException) - LOG.debug("Waiting for AnswerMessage to AskMessage '{}' was cancelled due to a stopping SC.", + LOG.trace("Waiting for AnswerMessage to AskMessage '{}' was cancelled due to a stopping SC.", askMessage.getMessageId()); else LOG.error("A {} occurred while sending an AskMessage.", e.getClass().getSimpleName(), e); @@ -130,7 +130,7 @@ else if (e instanceof CancellationException) throw ioe; } - LOG.debug("Sent AskMessage: {}", askMessage); + LOG.trace("Sent AskMessage: {}", askMessage); return future; } @@ -151,7 +151,7 @@ public CompletableFuture sendPostMessage(PostMessage postMessage) LOG.warn("KB '{}' did not respond within {}s to PostMessage '{}'.", postMessage.getToKnowledgeBase(), this.getWaitTimeout(), postMessage.getMessageId()); else if (e instanceof CancellationException) - LOG.debug("Waiting for ReactMessage to PostMessage '{}' was cancelled due to a stopping SC.", + LOG.trace("Waiting for ReactMessage to PostMessage '{}' was cancelled due to a stopping SC.", postMessage.getMessageId()); else LOG.error("A {} occurred while sending an PostMessage.", e.getClass().getSimpleName(), e); @@ -177,7 +177,7 @@ else if (e instanceof CancellationException) // and re throw throw ioe; } - LOG.debug("Sent PostMessage: {}", postMessage); + LOG.trace("Sent PostMessage: {}", postMessage); return future; } @@ -201,7 +201,7 @@ public void handleAskMessage(AskMessage message) { messageDispatcher.send(reply); } catch (Throwable e) { this.LOG.warn("Could not send reply to message " + message.getMessageId() + ": " + e.getMessage()); - this.LOG.debug("", e); + this.LOG.trace("", e); } }).handle((r, e) -> { @@ -258,7 +258,7 @@ public void handleAnswerMessage(AnswerMessage answerMessage) { + ", but I don't remember sending a message with that ID. It might have taken more than {}s to respond.", this.getWaitTimeout()); } else { - LOG.debug("Received AnswerMessage: {}", answerMessage); + LOG.trace("Received AnswerMessage: {}", answerMessage); future.complete(answerMessage); } } @@ -277,7 +277,7 @@ public void handleReactMessage(ReactMessage reactMessage) { } else { assert reactMessage != null; assert future != null; - LOG.debug("Received ReactMessage: {}", reactMessage); + LOG.trace("Received ReactMessage: {}", reactMessage); future.complete(reactMessage); } } @@ -341,7 +341,7 @@ public void stop() { if (future.cancel(true)) i++; } - LOG.debug("MessageRouterImpl stopped. Cancelled {} message(s).", i); + LOG.trace("MessageRouterImpl stopped. Cancelled {} message(s).", i); } } diff --git a/smart-connector/src/main/java/eu/knowledge/engine/smartconnector/impl/ReasonerProcessor.java b/smart-connector/src/main/java/eu/knowledge/engine/smartconnector/impl/ReasonerProcessor.java index ed912ece4..722f3ec39 100644 --- a/smart-connector/src/main/java/eu/knowledge/engine/smartconnector/impl/ReasonerProcessor.java +++ b/smart-connector/src/main/java/eu/knowledge/engine/smartconnector/impl/ReasonerProcessor.java @@ -13,10 +13,6 @@ import java.util.concurrent.ConcurrentHashMap; import java.util.stream.Collectors; -import org.apache.jena.graph.Node; -import org.apache.jena.sparql.core.Var; -import org.apache.jena.sparql.serializer.SerializationContext; -import org.apache.jena.sparql.util.FmtUtils; import org.slf4j.Logger; import org.slf4j.LoggerFactory; import org.slf4j.helpers.MessageFormatter; @@ -30,6 +26,7 @@ import eu.knowledge.engine.reasoner.SinkBindingSetHandler; import eu.knowledge.engine.reasoner.TaskBoard; import eu.knowledge.engine.reasoner.TransformBindingSetHandler; +import eu.knowledge.engine.reasoner.api.BindingSet; import eu.knowledge.engine.reasoner.api.TripleNode; import eu.knowledge.engine.reasoner.api.TriplePattern; import eu.knowledge.engine.reasoner.rulenode.RuleNode; @@ -38,8 +35,6 @@ import eu.knowledge.engine.smartconnector.api.AskExchangeInfo; import eu.knowledge.engine.smartconnector.api.AskKnowledgeInteraction; import eu.knowledge.engine.smartconnector.api.AskResult; -import eu.knowledge.engine.reasoner.api.Binding; -import eu.knowledge.engine.reasoner.api.BindingSet; import eu.knowledge.engine.smartconnector.api.ExchangeInfo.Initiator; import eu.knowledge.engine.smartconnector.api.ExchangeInfo.Status; import eu.knowledge.engine.smartconnector.api.GraphPattern; @@ -118,7 +113,7 @@ public ReasonerProcessor(Set knowledgeInteractions, Me Rule aRule = new Rule(ruleName, new HashSet<>(Util.translateGraphPatternTo(gp)), new AnswerBindingSetHandler(kii)); store.addRule(aRule); - LOG.debug("Adding ANSWER to store: {}", aRule); + LOG.trace("Adding ANSWER to store: {}", aRule); } else if (kii.getType().equals(Type.REACT)) { ReactKnowledgeInteraction rki = (ReactKnowledgeInteraction) ki; GraphPattern argGp = rki.getArgument(); @@ -134,13 +129,10 @@ public ReasonerProcessor(Set knowledgeInteractions, Me aRule = new Rule(ruleName, Util.translateGraphPatternTo(argGp), resPattern, new ReactBindingSetHandler(kii)); } - store.addRule(aRule); - LOG.debug("Adding REACT to store: {}", aRule); + LOG.trace("Adding REACT to store: {}", aRule); } - } - } @Override @@ -163,7 +155,7 @@ public void planAskInteraction(MyKnowledgeInteractionInfo aAKI) { else aStrategy = aki.getMatchStrategy(); - LOG.debug("Creating reasoner plan with strategy: {}", aStrategy); + LOG.trace("Creating reasoner plan with strategy: {}", aStrategy); this.reasonerPlan = new ReasonerPlan(this.store, aRule, aStrategy.toConfig(true)); } else { LOG.warn("Type should be Ask, not {}", this.myKnowledgeInteraction.getType()); @@ -199,6 +191,20 @@ public CompletableFuture executeAskInteraction(BindingSet someBinding this.knowledgeGaps = bs.isEmpty() ? getKnowledgeGaps(this.reasonerPlan.getStartNode()) : new HashSet(); } + + // extract succeeded nr of exchange infos and nr of failed exchange infos + int nrOfSucceededKIs = 0, nrOfFailedKIs = 0; + for (AskExchangeInfo aei : this.askExchangeInfos) { + if (aei.getStatus().equals(Status.SUCCEEDED)) { + nrOfSucceededKIs++; + } else if (aei.getStatus().equals(Status.FAILED)) { + nrOfFailedKIs++; + } + } + + LOG.info("Finished ask for KI <{}> with {} result bindings involving {} KIs (of which {} failed)", + this.myKnowledgeInteraction.getId(), bs.size(), nrOfSucceededKIs + nrOfFailedKIs, nrOfFailedKIs); + return new AskResult(Util.translateToApiBindingSet(bs), this.askExchangeInfos, this.reasonerPlan, this.knowledgeGaps); }); @@ -211,9 +217,9 @@ private void continueReasoningBackward(BindingSet incomingBS) { final String msg = "Executing (scheduled) tasks for the reasoner should not result in problems."; taskboard = this.reasonerPlan.execute(incomingBS); isComplete = !taskboard.hasTasks(); - LOG.debug("ask:\n{}", this.reasonerPlan); + LOG.trace("Ask: {}", this.reasonerPlan); taskboard.executeScheduledTasks().thenAccept(Void -> { - LOG.debug("All ask tasks finished."); + LOG.trace("All ask tasks finished."); if (isComplete) { BindingSet bs = this.reasonerPlan.getResults(); this.finalBindingSetFuture.complete(bs); @@ -256,7 +262,7 @@ public void planPostInteraction(MyKnowledgeInteractionInfo aPKI) { else aStrategy = pki.getMatchStrategy(); - LOG.debug("Creating reasoner plan with strategy: {}", aStrategy); + LOG.trace("Creating reasoner plan with strategy: {}", aStrategy); this.reasonerPlan = new ReasonerPlan(this.store, aRule, aStrategy.toConfig(false)); } else { @@ -274,6 +280,25 @@ public CompletableFuture executePostInteraction(BindingSet someBindi continueReasoningForward(someBindings, this.captureResultBindingSetHandler); return this.finalBindingSetFuture.thenApply((bs) -> { + + // extract succeeded nr of exchange infos and nr of failed exchange infos + int nrOfSucceededKIs = 0, nrOfFailedKIs = 0; + for (PostExchangeInfo aei : this.postExchangeInfos) { + if (aei.getStatus().equals(Status.SUCCEEDED)) { + nrOfSucceededKIs++; + } else if (aei.getStatus().equals(Status.FAILED)) { + nrOfFailedKIs++; + } + } + + String logMessage = "Finished post for KI <{}> with {} result bindings involving {} KIs (of which {} failed)"; + if (this.myKnowledgeInteraction.isMeta()) + LOG.trace(logMessage, this.myKnowledgeInteraction.getId(), bs.size(), nrOfSucceededKIs + nrOfFailedKIs, + nrOfFailedKIs); + else + LOG.info(logMessage, this.myKnowledgeInteraction.getId(), bs.size(), nrOfSucceededKIs + nrOfFailedKIs, + nrOfFailedKIs); + return new PostResult(Util.translateToApiBindingSet(bs), this.postExchangeInfos, this.reasonerPlan); }); } @@ -285,9 +310,9 @@ private void continueReasoningForward(BindingSet incomingBS, CaptureBindingSetHa TaskBoard taskboard; taskboard = this.reasonerPlan.execute(incomingBS); isComplete = !taskboard.hasTasks(); - LOG.debug("post:\n{}", this.reasonerPlan); + LOG.trace("Post: {}", this.reasonerPlan); taskboard.executeScheduledTasks().thenAccept(Void -> { - LOG.debug("All post tasks finished."); + LOG.trace("All post tasks finished."); if (isComplete) { BindingSet resultBS = new BindingSet(); if (aBindingSetHandler != null && aBindingSetHandler.getBindingSet() != null) { @@ -390,6 +415,14 @@ public CompletableFuture handle(BindingSet bs) { this.kii.getId(), bs); try { + String logMessage = "Contacting KI <{}> while executing <{}>"; + if (!ReasonerProcessor.this.myKnowledgeInteraction.isMeta()) + LOG.debug(logMessage, askMessage.getToKnowledgeInteraction(), + askMessage.getFromKnowledgeInteraction()); + else + LOG.trace(logMessage, askMessage.getToKnowledgeInteraction(), + askMessage.getFromKnowledgeInteraction()); + CompletableFuture sendAskMessage = ReasonerProcessor.this.messageRouter .sendAskMessage(askMessage); Instant aPreviousSend = Instant.now(); @@ -403,13 +436,13 @@ public CompletableFuture handle(BindingSet bs) { askMessage.getMessageId().toString() }); LOG.warn(failedMessage); - LOG.debug("", t); + LOG.trace("", t); return ReasonerProcessor.this .createFailedResponseMessageFromRequestMessage(askMessage, failedMessage); }).thenApply((answerMessage) -> { assert answerMessage != null; - LOG.debug("Received ANSWER message from KI '{}'", answerMessage.getFromKnowledgeInteraction()); + LOG.trace("Received ANSWER message from KI '{}'", answerMessage.getFromKnowledgeInteraction()); BindingSet resultBindingSet = answerMessage.getBindings(); ReasonerProcessor.this.askExchangeInfos @@ -482,6 +515,13 @@ public CompletableFuture handle(BindingSet bs) { ReasonerProcessor.this.myKnowledgeInteraction.getId(), kii.getKnowledgeBaseId(), kii.getId(), bs); try { + String logMessage = "Contacting KI <{}> while executing <{}>"; + if (!ReasonerProcessor.this.myKnowledgeInteraction.isMeta()) + LOG.debug(logMessage, postMessage.getToKnowledgeInteraction(), + postMessage.getFromKnowledgeInteraction()); + else + LOG.trace(logMessage, postMessage.getToKnowledgeInteraction(), + postMessage.getFromKnowledgeInteraction()); CompletableFuture sendPostMessage = ReasonerProcessor.this.messageRouter .sendPostMessage(postMessage); Instant aPreviousSend = Instant.now(); @@ -492,7 +532,7 @@ public CompletableFuture handle(BindingSet bs) { t.getMessage() != null ? t.getMessage() : t.getClass().getSimpleName(), postMessage.getMessageId().toString() }); LOG.warn(failedMessage); - LOG.debug("", t); + LOG.trace("", t); return ReasonerProcessor.this .createFailedResponseMessageFromRequestMessage(postMessage, failedMessage); @@ -549,6 +589,14 @@ public CompletableFuture handle(BindingSet bs) { ReasonerProcessor.this.myKnowledgeInteraction.getId(), kii.getKnowledgeBaseId(), kii.getId(), bs); try { + String logMessage = "Contacting KI <{}> while executing <{}>"; + if (!ReasonerProcessor.this.myKnowledgeInteraction.isMeta()) + LOG.debug(logMessage, postMessage.getToKnowledgeInteraction(), + postMessage.getFromKnowledgeInteraction()); + else + LOG.trace(logMessage, postMessage.getToKnowledgeInteraction(), + postMessage.getFromKnowledgeInteraction()); + CompletableFuture sendPostMessage = ReasonerProcessor.this.messageRouter .sendPostMessage(postMessage); Instant aPreviousSend = Instant.now(); @@ -559,7 +607,7 @@ public CompletableFuture handle(BindingSet bs) { t.getMessage() != null ? t.getMessage() : t.getClass().getSimpleName(), postMessage.getMessageId().toString() }); LOG.warn(failedMessage); - LOG.debug("", t); + LOG.trace("", t); return ReasonerProcessor.this .createFailedResponseMessageFromRequestMessage(postMessage, failedMessage); @@ -619,17 +667,17 @@ public Set getKnowledgeGaps(RuleNode plan) { for (Entry> entry : nodeCoverage.entrySet()) { - LOG.debug("Entry key is {}", entry.getKey()); - LOG.debug("Entry value is {}", entry.getValue()); + LOG.trace("Entry key is {}", entry.getKey()); + LOG.trace("Entry value is {}", entry.getValue()); collectedOrGaps = new HashSet<>(); boolean foundNeighborWithoutGap = false; for (RuleNode neighbor : entry.getValue()) { - LOG.debug("Neighbor is {}", neighbor); + LOG.trace("Neighbor is {}", neighbor); if (!neighbor.getRule().getAntecedent().isEmpty()) { // make sure neighbor has no knowledge gaps - LOG.debug("Neighbor has antecedents, so check if the neighbor has gaps"); + LOG.trace("Neighbor has antecedents, so check if the neighbor has gaps"); // knowledge engine specific code. We ignore meta knowledge interactions when // looking for knowledge gaps, because they are very generic and make finding @@ -640,16 +688,16 @@ public Set getKnowledgeGaps(RuleNode plan) { if (!isMeta && (someGaps = getKnowledgeGaps(neighbor)).isEmpty()) { // found neighbor without knowledge gaps for the current triple, so current // triple is covered. - LOG.debug("Neighbor has no gaps"); + LOG.trace("Neighbor has no gaps"); foundNeighborWithoutGap = true; break; } - LOG.debug("Neighbor has someGaps {}", someGaps); + LOG.trace("Neighbor has someGaps {}", someGaps); collectedOrGaps.addAll(someGaps); } else foundNeighborWithoutGap = true; } - LOG.debug("Found a neighbor without gaps is {}", foundNeighborWithoutGap); + LOG.trace("Found a neighbor without gaps is {}", foundNeighborWithoutGap); if (foundNeighborWithoutGap) continue; @@ -661,11 +709,11 @@ public Set getKnowledgeGaps(RuleNode plan) { kg.add(entry.getKey()); collectedOrGaps.add(kg); } - LOG.debug("CollectedOrGaps is {}", collectedOrGaps); + LOG.trace("CollectedOrGaps is {}", collectedOrGaps); existingOrGaps = mergeGaps(existingOrGaps, collectedOrGaps); } - LOG.debug("Found existingOrGaps {}", existingOrGaps); + LOG.trace("Found existingOrGaps {}", existingOrGaps); return existingOrGaps; } diff --git a/smart-connector/src/main/java/eu/knowledge/engine/smartconnector/impl/SmartConnectorImpl.java b/smart-connector/src/main/java/eu/knowledge/engine/smartconnector/impl/SmartConnectorImpl.java index e810b08e7..b66e258be 100644 --- a/smart-connector/src/main/java/eu/knowledge/engine/smartconnector/impl/SmartConnectorImpl.java +++ b/smart-connector/src/main/java/eu/knowledge/engine/smartconnector/impl/SmartConnectorImpl.java @@ -115,7 +115,7 @@ public URI getKnowledgeBaseId() { public URI register(AskKnowledgeInteraction anAskKI) { this.checkStopped(); URI kiId = this.knowledgeBaseStore.register(anAskKI, false); - LOG.info("Registered Ask KI <{}>.", kiId); + LOG.trace("Registered Ask KI <{}>.", anAskKI); return kiId; } @@ -157,7 +157,7 @@ public void unregister(AskKnowledgeInteraction anAskKI) { public URI register(AnswerKnowledgeInteraction anAnswerKI, AnswerHandler anAnswerHandler) { this.checkStopped(); URI kiId = this.knowledgeBaseStore.register(anAnswerKI, anAnswerHandler, false); - LOG.info("Registered Answer KI <{}>.", kiId); + LOG.trace("Registered Answer KI <{}>.", anAnswerKI); return kiId; } @@ -194,7 +194,7 @@ public void unregister(AnswerKnowledgeInteraction anAnswerKI) { public URI register(PostKnowledgeInteraction aPostKI) { this.checkStopped(); URI kiId = this.knowledgeBaseStore.register(aPostKI, false); - LOG.info("Registered Post KI <{}>.", kiId); + LOG.trace("Registered Post KI <{}>.", aPostKI); return kiId; } @@ -235,7 +235,7 @@ public void unregister(PostKnowledgeInteraction aPostKI) { public URI register(ReactKnowledgeInteraction aReactKI, ReactHandler aReactHandler) { this.checkStopped(); URI kiId = this.knowledgeBaseStore.register(aReactKI, aReactHandler, false); - LOG.info("Registered React KI <{}>.", kiId); + LOG.trace("Registered React KI <{}>.", aReactKI); return kiId; } @@ -481,19 +481,20 @@ private void checkStopped() { } void communicationReady() { - Instant beforePopulate = Instant.now(); - LOG.info("Getting comms ready took {} ms", Duration.between(this.started, beforePopulate).toMillis()); + Instant beforeComms = Instant.now(); + LOG.trace("Getting comms ready took {} ms", Duration.between(this.started, beforeComms).toMillis()); Instant beforeConstructorFinished = Instant.now(); this.constructorFinished.handle((r3, e3) -> { - LOG.info("Constructor finished took {} ms", + LOG.trace("Constructor finished took {} ms", Duration.between(beforeConstructorFinished, Instant.now()).toMillis()); // Populate the initial knowledge base store. + Instant beforePopulate = Instant.now(); this.otherKnowledgeBaseStore.populate().handle((r, e) -> { LOG.info("Populating took {} ms", Duration.between(beforePopulate, Instant.now()).toMillis()); Instant beforeAnnounce = Instant.now(); // Then tell the other knowledge bases about our existence. this.metaKnowledgeBase.postNewKnowledgeBase().handle((r2, e2) -> { - LOG.info("Announcing took {} ms", Duration.between(beforeAnnounce, Instant.now()).toMillis()); + LOG.debug("Announcing took {} ms", Duration.between(beforeAnnounce, Instant.now()).toMillis()); // When that is done, and all peers have acknowledged our existence, we // can proceed to inform the knowledge base that this smart connector is diff --git a/smart-connector/src/main/java/eu/knowledge/engine/smartconnector/util/KnowledgeNetwork.java b/smart-connector/src/main/java/eu/knowledge/engine/smartconnector/util/KnowledgeNetwork.java index d6367526d..9bf8faeef 100644 --- a/smart-connector/src/main/java/eu/knowledge/engine/smartconnector/util/KnowledgeNetwork.java +++ b/smart-connector/src/main/java/eu/knowledge/engine/smartconnector/util/KnowledgeNetwork.java @@ -118,7 +118,7 @@ private void waitForUpToDate() { allUpToDate &= kbUpToDate; upToDate.put(kb, kbUpToDate); if (kbUpToDate) { - LOG.debug("Knowledge Base {} is up to date.", kb.getKnowledgeBaseName()); + LOG.trace("Knowledge Base {} is up to date.", kb.getKnowledgeBaseName()); } } try { @@ -128,7 +128,7 @@ private void waitForUpToDate() { LOG.error("An error occured while waiting for up-to-date.", e); } } - LOG.info("Everyone is up to date after {} rounds!", count); + LOG.trace("Everyone is up to date after {} rounds!", count); } private String getUpToDateInfo(Map upToDate) { From 58d8fd3bae990277c39c48aabd97d698bbb08410 Mon Sep 17 00:00:00 2001 From: Barry Nouwt Date: Thu, 19 Mar 2026 15:33:21 +0100 Subject: [PATCH 2/4] Improve comms ready logging (include reasoner level) --- .../engine/smartconnector/impl/SmartConnectorImpl.java | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/smart-connector/src/main/java/eu/knowledge/engine/smartconnector/impl/SmartConnectorImpl.java b/smart-connector/src/main/java/eu/knowledge/engine/smartconnector/impl/SmartConnectorImpl.java index b66e258be..8ed483883 100644 --- a/smart-connector/src/main/java/eu/knowledge/engine/smartconnector/impl/SmartConnectorImpl.java +++ b/smart-connector/src/main/java/eu/knowledge/engine/smartconnector/impl/SmartConnectorImpl.java @@ -490,11 +490,13 @@ void communicationReady() { // Populate the initial knowledge base store. Instant beforePopulate = Instant.now(); this.otherKnowledgeBaseStore.populate().handle((r, e) -> { - LOG.info("Populating took {} ms", Duration.between(beforePopulate, Instant.now()).toMillis()); + LOG.debug("Populating took {} ms", Duration.between(beforePopulate, Instant.now()).toMillis()); Instant beforeAnnounce = Instant.now(); // Then tell the other knowledge bases about our existence. this.metaKnowledgeBase.postNewKnowledgeBase().handle((r2, e2) -> { - LOG.debug("Announcing took {} ms", Duration.between(beforeAnnounce, Instant.now()).toMillis()); + LOG.info("SC communication ready took {} ms. Default reasoner level: {}", + Duration.between(this.started, Instant.now()).toMillis(), + this.interactionProcessor.getReasonerLevel()); // When that is done, and all peers have acknowledged our existence, we // can proceed to inform the knowledge base that this smart connector is From d59bd35607ddd12b683a5c0ec8dc7403f8394253 Mon Sep 17 00:00:00 2001 From: Barry Nouwt Date: Fri, 20 Mar 2026 10:30:08 +0100 Subject: [PATCH 3/4] Additional improvements to log statements. --- .../smartconnector/impl/InteractionProcessorImpl.java | 4 ++-- .../impl/OtherKnowledgeBaseStoreImpl.java | 6 +++--- .../engine/smartconnector/impl/ReasonerProcessor.java | 11 ++++++++--- 3 files changed, 13 insertions(+), 8 deletions(-) diff --git a/smart-connector/src/main/java/eu/knowledge/engine/smartconnector/impl/InteractionProcessorImpl.java b/smart-connector/src/main/java/eu/knowledge/engine/smartconnector/impl/InteractionProcessorImpl.java index ec9aebb72..c2e96aa65 100644 --- a/smart-connector/src/main/java/eu/knowledge/engine/smartconnector/impl/InteractionProcessorImpl.java +++ b/smart-connector/src/main/java/eu/knowledge/engine/smartconnector/impl/InteractionProcessorImpl.java @@ -256,7 +256,7 @@ public CompletableFuture processAskFromMessageRouter(AskMessage a return future.handle((b, e) -> { if (b != null && e == null) { - String logStatement = "Received {} binding(s) as answer from KB for KI <{}>"; + String logStatement = "Received {} binding(s) as answer from my KB for KI <{}>"; if (!answerKnowledgeInteraction.isMeta()) LOG.debug(logStatement, b.size(), answerKnowledgeInteractionId); else @@ -373,7 +373,7 @@ public CompletableFuture processPostFromMessageRouter(PostMessage return future.handle((b, e) -> { if (b != null && e == null) { - String logStatement = "Received {} binding(s) as react from KB for KI <{}>"; + String logStatement = "Received {} binding(s) as react from my KB for KI <{}>"; if (!reactKnowledgeInteraction.isMeta()) LOG.debug(logStatement, b.size(), reactKnowledgeInteractionId); else diff --git a/smart-connector/src/main/java/eu/knowledge/engine/smartconnector/impl/OtherKnowledgeBaseStoreImpl.java b/smart-connector/src/main/java/eu/knowledge/engine/smartconnector/impl/OtherKnowledgeBaseStoreImpl.java index 08bff0b1f..d67b953a7 100644 --- a/smart-connector/src/main/java/eu/knowledge/engine/smartconnector/impl/OtherKnowledgeBaseStoreImpl.java +++ b/smart-connector/src/main/java/eu/knowledge/engine/smartconnector/impl/OtherKnowledgeBaseStoreImpl.java @@ -92,7 +92,7 @@ public CompletableFuture populate() { @Override public void addKnowledgeBase(OtherKnowledgeBase kb) { if (this.otherKnowledgeBases.containsKey(kb.getId())) { - LOG.warn("Tried to add a knowledge base {}, but it is already in my store! Skipped it.", kb.getId()); + LOG.trace("Tried to add a knowledge base {}, but it is already in my store! Skipped it.", kb.getId()); return; } @@ -106,7 +106,7 @@ public void addKnowledgeBase(OtherKnowledgeBase kb) { @Override public void updateKnowledgeBase(OtherKnowledgeBase kb) { if (!this.otherKnowledgeBases.containsKey(kb.getId())) { - LOG.warn("Tried to update knowledge base {}, but it is not in my store! Skipped it.", kb.getId()); + LOG.trace("Tried to update knowledge base {}, but it is not in my store! Skipped it.", kb.getId()); return; } @@ -120,7 +120,7 @@ public void updateKnowledgeBase(OtherKnowledgeBase kb) { @Override public void removeKnowledgeBase(OtherKnowledgeBase kb) { if (!this.otherKnowledgeBases.containsKey(kb.getId())) { - LOG.warn("Tried to remove knowledge base {}, but it isn't even in my store! Skipped it.", kb.getId()); + LOG.trace("Tried to remove knowledge base {}, but it isn't even in my store! Skipped it.", kb.getId()); return; } diff --git a/smart-connector/src/main/java/eu/knowledge/engine/smartconnector/impl/ReasonerProcessor.java b/smart-connector/src/main/java/eu/knowledge/engine/smartconnector/impl/ReasonerProcessor.java index 722f3ec39..78360fabd 100644 --- a/smart-connector/src/main/java/eu/knowledge/engine/smartconnector/impl/ReasonerProcessor.java +++ b/smart-connector/src/main/java/eu/knowledge/engine/smartconnector/impl/ReasonerProcessor.java @@ -202,8 +202,13 @@ public CompletableFuture executeAskInteraction(BindingSet someBinding } } - LOG.info("Finished ask for KI <{}> with {} result bindings involving {} KIs (of which {} failed)", - this.myKnowledgeInteraction.getId(), bs.size(), nrOfSucceededKIs + nrOfFailedKIs, nrOfFailedKIs); + String logStatement = "Finished ask for KI <{}> with {} result bindings involving {} KI(s) (of which {} failed)"; + if (this.myKnowledgeInteraction.isMeta()) + LOG.trace(logStatement, this.myKnowledgeInteraction.getId(), bs.size(), nrOfSucceededKIs + nrOfFailedKIs, + nrOfFailedKIs); + else + LOG.info(logStatement, this.myKnowledgeInteraction.getId(), bs.size(), nrOfSucceededKIs + nrOfFailedKIs, + nrOfFailedKIs); return new AskResult(Util.translateToApiBindingSet(bs), this.askExchangeInfos, this.reasonerPlan, this.knowledgeGaps); @@ -291,7 +296,7 @@ public CompletableFuture executePostInteraction(BindingSet someBindi } } - String logMessage = "Finished post for KI <{}> with {} result bindings involving {} KIs (of which {} failed)"; + String logMessage = "Finished post for KI <{}> with {} result bindings involving {} KI(s) (of which {} failed)"; if (this.myKnowledgeInteraction.isMeta()) LOG.trace(logMessage, this.myKnowledgeInteraction.getId(), bs.size(), nrOfSucceededKIs + nrOfFailedKIs, nrOfFailedKIs); From b35de6dc1f2c99a72ca8aeb7a52dadd184f94c80 Mon Sep 17 00:00:00 2001 From: Barry Nouwt Date: Fri, 20 Mar 2026 11:16:49 +0100 Subject: [PATCH 4/4] Slightly modify failed part of log statement. --- .../impl/ReasonerProcessor.java | 33 ++++++++++--------- 1 file changed, 17 insertions(+), 16 deletions(-) diff --git a/smart-connector/src/main/java/eu/knowledge/engine/smartconnector/impl/ReasonerProcessor.java b/smart-connector/src/main/java/eu/knowledge/engine/smartconnector/impl/ReasonerProcessor.java index 78360fabd..c9ee03495 100644 --- a/smart-connector/src/main/java/eu/knowledge/engine/smartconnector/impl/ReasonerProcessor.java +++ b/smart-connector/src/main/java/eu/knowledge/engine/smartconnector/impl/ReasonerProcessor.java @@ -6,6 +6,7 @@ import java.util.Collections; import java.util.HashMap; import java.util.HashSet; +import java.util.List; import java.util.Map; import java.util.Map.Entry; import java.util.Set; @@ -193,22 +194,22 @@ public CompletableFuture executeAskInteraction(BindingSet someBinding } // extract succeeded nr of exchange infos and nr of failed exchange infos - int nrOfSucceededKIs = 0, nrOfFailedKIs = 0; + List succeededKIs = new ArrayList(), failedKIs = new ArrayList(); for (AskExchangeInfo aei : this.askExchangeInfos) { if (aei.getStatus().equals(Status.SUCCEEDED)) { - nrOfSucceededKIs++; + succeededKIs.add(aei.getKnowledgeInteractionId().toString()); } else if (aei.getStatus().equals(Status.FAILED)) { - nrOfFailedKIs++; + failedKIs.add(aei.getKnowledgeInteractionId().toString()); } } - String logStatement = "Finished ask for KI <{}> with {} result bindings involving {} KI(s) (of which {} failed)"; + String logStatement = "Finished ask for KI <{}> with {} result bindings involving {} KI(s) (of which {} failed: {})"; if (this.myKnowledgeInteraction.isMeta()) - LOG.trace(logStatement, this.myKnowledgeInteraction.getId(), bs.size(), nrOfSucceededKIs + nrOfFailedKIs, - nrOfFailedKIs); + LOG.trace(logStatement, this.myKnowledgeInteraction.getId(), bs.size(), + succeededKIs.size() + failedKIs.size(), failedKIs.size(), failedKIs); else - LOG.info(logStatement, this.myKnowledgeInteraction.getId(), bs.size(), nrOfSucceededKIs + nrOfFailedKIs, - nrOfFailedKIs); + LOG.info(logStatement, this.myKnowledgeInteraction.getId(), bs.size(), + succeededKIs.size() + failedKIs.size(), failedKIs.size(), failedKIs); return new AskResult(Util.translateToApiBindingSet(bs), this.askExchangeInfos, this.reasonerPlan, this.knowledgeGaps); @@ -287,22 +288,22 @@ public CompletableFuture executePostInteraction(BindingSet someBindi return this.finalBindingSetFuture.thenApply((bs) -> { // extract succeeded nr of exchange infos and nr of failed exchange infos - int nrOfSucceededKIs = 0, nrOfFailedKIs = 0; + List succeededKIs = new ArrayList<>(), failedKIs = new ArrayList<>(); for (PostExchangeInfo aei : this.postExchangeInfos) { if (aei.getStatus().equals(Status.SUCCEEDED)) { - nrOfSucceededKIs++; + succeededKIs.add(aei.getKnowledgeInteractionId().toString()); } else if (aei.getStatus().equals(Status.FAILED)) { - nrOfFailedKIs++; + failedKIs.add(aei.getKnowledgeInteractionId().toString()); } } - String logMessage = "Finished post for KI <{}> with {} result bindings involving {} KI(s) (of which {} failed)"; + String logMessage = "Finished post for KI <{}> with {} result bindings involving {} KI(s) (of which {} failed: {})"; if (this.myKnowledgeInteraction.isMeta()) - LOG.trace(logMessage, this.myKnowledgeInteraction.getId(), bs.size(), nrOfSucceededKIs + nrOfFailedKIs, - nrOfFailedKIs); + LOG.trace(logMessage, this.myKnowledgeInteraction.getId(), bs.size(), + succeededKIs.size() + failedKIs.size(), failedKIs.size(), failedKIs); else - LOG.info(logMessage, this.myKnowledgeInteraction.getId(), bs.size(), nrOfSucceededKIs + nrOfFailedKIs, - nrOfFailedKIs); + LOG.info(logMessage, this.myKnowledgeInteraction.getId(), bs.size(), + succeededKIs.size() + failedKIs.size(), failedKIs.size(), failedKIs); return new PostResult(Util.translateToApiBindingSet(bs), this.postExchangeInfos, this.reasonerPlan); });