From d7413460e1f41be2ea09a44efaa9d8fca9ce5874 Mon Sep 17 00:00:00 2001 From: OleksandrVidinieiev <56632770+OleksandrVidinieiev@users.noreply.github.com> Date: Sat, 16 Sep 2023 11:49:34 +0300 Subject: [PATCH 1/2] CIRC-1709: Add support for logging variables (#1321) * CIRC-1709 Populate logging context * CIRC-1709 Do not clear logging context * CIRC-1709 Add logging * CIRC-1709 Remove redundant info from log * CIRC-1709 Make public constant private * CIRC-1709 Do not clear logging context --- .../circulation/CirculationVerticle.java | 4 +- .../support/logging/LogHelper.java | 39 ++++++++++++------- 2 files changed, 29 insertions(+), 14 deletions(-) diff --git a/src/main/java/org/folio/circulation/CirculationVerticle.java b/src/main/java/org/folio/circulation/CirculationVerticle.java index 753cad90bf..93fcdd01c7 100644 --- a/src/main/java/org/folio/circulation/CirculationVerticle.java +++ b/src/main/java/org/folio/circulation/CirculationVerticle.java @@ -73,7 +73,9 @@ public void start(Promise startFuture) { this.server = vertx.createHttpServer(); - router.route().handler(rc -> LogHelper.logRequest(rc, log)); + router.route() + .handler(LogHelper::populateLoggingContext) + .handler(rc -> LogHelper.logRequest(rc, log)); new HealthResource().register(router); new TenantActivationResource().register(router); diff --git a/src/main/java/org/folio/circulation/support/logging/LogHelper.java b/src/main/java/org/folio/circulation/support/logging/LogHelper.java index 527edee473..a742d58040 100644 --- a/src/main/java/org/folio/circulation/support/logging/LogHelper.java +++ b/src/main/java/org/folio/circulation/support/logging/LogHelper.java @@ -1,37 +1,33 @@ package org.folio.circulation.support.logging; import static java.util.stream.Collectors.toList; -import static org.folio.circulation.support.http.OkapiHeader.REQUEST_ID; -import static org.folio.circulation.support.http.OkapiHeader.TENANT; -import io.vertx.ext.web.RoutingContext; import java.lang.invoke.MethodHandles; import java.util.Collection; import java.util.function.Function; +import org.apache.logging.log4j.LogManager; +import org.apache.logging.log4j.Logger; import org.folio.circulation.domain.MultipleRecords; import org.folio.circulation.support.http.client.Response; import org.folio.circulation.support.results.Result; -import org.apache.logging.log4j.LogManager; -import org.apache.logging.log4j.Logger; +import org.folio.okapi.common.logging.FolioLoggingContext; +import org.folio.rest.RestVerticle; + +import io.vertx.core.http.HttpServerRequest; +import io.vertx.ext.web.RoutingContext; public class LogHelper { private static final Logger log = LogManager.getLogger(MethodHandles.lookup().lookupClass()); + private static final String MODULE_NAME = "mod-circulation"; private LogHelper() { throw new UnsupportedOperationException("Do not instantiate"); } - private static String null2empty(String s) { - return (s == null) ? "" : s; - } - public static void logRequest(RoutingContext rc, Logger logger) { if (logger.isInfoEnabled()) { - logger.info("[{}] [{}] {} {}", - null2empty(rc.request().getHeader(REQUEST_ID)), - null2empty(rc.request().getHeader(TENANT)), - rc.request().method(), rc.request().path()); + logger.info("Invoking {} {}", rc.request().method(), rc.request().path()); } rc.next(); } @@ -73,4 +69,21 @@ public static String asString(Collection collection, Function collection.size(), collection.stream().map(elementMapper).collect(toList())); } + + public static void populateLoggingContext(RoutingContext routingContext) { + final HttpServerRequest request = routingContext.request(); + String tenantId = request.getHeader(RestVerticle.OKAPI_HEADER_TENANT); + String requestId = request.getHeader(RestVerticle.OKAPI_REQUESTID_HEADER); + String userId = request.getHeader(RestVerticle.OKAPI_USERID_HEADER); + + log.debug("populateLoggingContext:: populating context: tenantId={}, requestId={}, userId={}", + tenantId, requestId, userId); + + FolioLoggingContext.put(FolioLoggingContext.TENANT_ID_LOGGING_VAR_NAME, tenantId); + FolioLoggingContext.put(FolioLoggingContext.REQUEST_ID_LOGGING_VAR_NAME, requestId); + FolioLoggingContext.put(FolioLoggingContext.USER_ID_LOGGING_VAR_NAME, userId); + FolioLoggingContext.put(FolioLoggingContext.MODULE_ID_LOGGING_VAR_NAME, MODULE_NAME); + + routingContext.next(); + } } From cc0d1f28b978f5c0e9a5a0f4b6de01c089335880 Mon Sep 17 00:00:00 2001 From: Roman Barannyk <53909129+roman-barannyk@users.noreply.github.com> Date: Mon, 18 Sep 2023 18:42:02 +0300 Subject: [PATCH 2/2] CIRC-1809 add logging to circulation rules package (#1325) * CIRC-1809 add logging to circulation rules package * CIRC-1809 fix typo --- .../rules/AppliedRuleConditions.java | 2 +- .../rules/CirculationRuleMatch.java | 2 +- .../rules/CirculationRulesProcessor.java | 27 ++++++++++++++++++- .../org/folio/circulation/rules/Drools.java | 26 ++++++++++++++++++ .../circulation/rules/ExecutableRules.java | 10 +++++++ .../org/folio/circulation/rules/Match.java | 3 +++ .../rules/cache/CirculationRulesCache.java | 12 +++++---- 7 files changed, 74 insertions(+), 8 deletions(-) diff --git a/src/main/java/org/folio/circulation/rules/AppliedRuleConditions.java b/src/main/java/org/folio/circulation/rules/AppliedRuleConditions.java index 074bcf1ed2..5223251b88 100644 --- a/src/main/java/org/folio/circulation/rules/AppliedRuleConditions.java +++ b/src/main/java/org/folio/circulation/rules/AppliedRuleConditions.java @@ -9,7 +9,7 @@ public class AppliedRuleConditions { boolean isPatronGroupPresent; public AppliedRuleConditions(boolean isItemTypePresent, - boolean isLoanTypePresent, boolean isPatronGroupPresent) { + boolean isLoanTypePresent, boolean isPatronGroupPresent) { this.isItemTypePresent = isItemTypePresent; this.isLoanTypePresent = isLoanTypePresent; diff --git a/src/main/java/org/folio/circulation/rules/CirculationRuleMatch.java b/src/main/java/org/folio/circulation/rules/CirculationRuleMatch.java index 7dfd142b66..7206cf9705 100644 --- a/src/main/java/org/folio/circulation/rules/CirculationRuleMatch.java +++ b/src/main/java/org/folio/circulation/rules/CirculationRuleMatch.java @@ -6,7 +6,7 @@ public class CirculationRuleMatch { private final AppliedRuleConditions appliedRuleConditions; public CirculationRuleMatch(String policyId, - AppliedRuleConditions appliedRuleConditions) { + AppliedRuleConditions appliedRuleConditions) { this.policyId = policyId; this.appliedRuleConditions = appliedRuleConditions; diff --git a/src/main/java/org/folio/circulation/rules/CirculationRulesProcessor.java b/src/main/java/org/folio/circulation/rules/CirculationRulesProcessor.java index 4889f7a6a3..289263b974 100644 --- a/src/main/java/org/folio/circulation/rules/CirculationRulesProcessor.java +++ b/src/main/java/org/folio/circulation/rules/CirculationRulesProcessor.java @@ -38,10 +38,14 @@ public CirculationRulesProcessor(String tenantId, CollectionResourceClient circu public CompletableFuture> getLoanPolicyAndMatch( RulesExecutionParameters params) { + log.debug("getLoanPolicyAndMatch:: parameters params: {}", params); + return executeRules(params, ExecutableRules::determineLoanPolicy); } public CompletableFuture> getLoanPolicies(RulesExecutionParameters params) { + log.debug("getLoanPolicies:: parameters params: {}", params); + return triggerRules(params, (drools, newParams) -> drools.loanPolicies(newParams.toMap(), newParams.getLocation())); } @@ -49,10 +53,14 @@ public CompletableFuture> getLoanPolicies(RulesExecutionParame public CompletableFuture> getLostItemPolicyAndMatch( RulesExecutionParameters params) { + log.debug("getLostItemPolicyAndMatch:: parameters params: {}", params); + return executeRules(params, ExecutableRules::determineLostItemPolicy); } public CompletableFuture> getLostItemPolicies(RulesExecutionParameters params) { + log.debug("getLostItemPolicies:: parameters params: {}", params); + return triggerRules(params, (drools, newParams) -> drools.lostItemPolicies(newParams.toMap(), newParams.getLocation())); } @@ -60,10 +68,14 @@ public CompletableFuture> getLostItemPolicies(RulesExecutionPa public CompletableFuture> getNoticePolicyAndMatch( RulesExecutionParameters params) { + log.debug("getNoticePolicyAndMatch:: parameters params: {}", params); + return executeRules(params, ExecutableRules::determineNoticePolicy); } public CompletableFuture> getNoticePolicies(RulesExecutionParameters params) { + log.debug("getNoticePolicies:: parameters params: {}", params); + return triggerRules(params, (drools, newParams) -> drools.noticePolicies(newParams.toMap(), newParams.getLocation())); } @@ -71,10 +83,14 @@ public CompletableFuture> getNoticePolicies(RulesExecutionPara public CompletableFuture> getOverduePolicyAndMatch( RulesExecutionParameters params) { + log.debug("getOverduePolicyAndMatch:: parameters params: {}", params); + return executeRules(params, ExecutableRules::determineOverduePolicy); } public CompletableFuture> getOverduePolicies(RulesExecutionParameters params) { + log.debug("getOverduePolicies:: parameters params: {}", params); + return triggerRules(params, (drools, newParams) -> drools.overduePolicies(newParams.toMap(), newParams.getLocation())); } @@ -82,10 +98,14 @@ public CompletableFuture> getOverduePolicies(RulesExecutionPar public CompletableFuture> getRequestPolicyAndMatch( RulesExecutionParameters params) { + log.debug("getRequestPolicyAndMatch:: parameters params: {}", params); + return executeRules(params, ExecutableRules::determineRequestPolicy); } public CompletableFuture> getRequestPolicies(RulesExecutionParameters params) { + log.debug("getRequestPolicies:: parameters params: {}", params); + return triggerRules(params, (drools, newParams) -> drools.requestPolicies(newParams.toMap(), newParams.getLocation())); } @@ -114,8 +134,13 @@ private CompletableFuture> executeRules(RulesExecutionParameters p rulesExecutor.apply(rules, parametersWithLocation))); } - private CompletableFuture> fetchLocation(RulesExecutionParameters params) { + private CompletableFuture> fetchLocation( + RulesExecutionParameters params) { + + log.debug("fetchLocation:: parameters params: {}", params); + if (params.getLocation() != null) { + log.info("fetchLocation:: location is not null"); return ofAsync(() -> params); } diff --git a/src/main/java/org/folio/circulation/rules/Drools.java b/src/main/java/org/folio/circulation/rules/Drools.java index 6f27e67192..529ccb9a20 100644 --- a/src/main/java/org/folio/circulation/rules/Drools.java +++ b/src/main/java/org/folio/circulation/rules/Drools.java @@ -5,11 +5,14 @@ import static org.folio.circulation.resources.AbstractCirculationRulesEngineResource.LOCATION_ID_NAME; import static org.folio.circulation.resources.AbstractCirculationRulesEngineResource.PATRON_TYPE_ID_NAME; import static org.folio.circulation.support.json.JsonPropertyWriter.write; +import static org.folio.circulation.support.utils.LogUtil.asJson; import java.util.Collections; import java.util.Set; import java.util.stream.Collectors; +import org.apache.logging.log4j.LogManager; +import org.apache.logging.log4j.Logger; import org.drools.core.definitions.rule.impl.RuleImpl; import org.drools.core.event.DefaultAgendaEventListener; import org.folio.circulation.domain.Location; @@ -33,6 +36,7 @@ public class Drools { // https://docs.jboss.org/drools/release/6.2.0.CR1/drools-docs/html/ch19.html // http://www.deepakgaikwad.net/index.php/2016/05/16/drools-tutorial-beginners.html + private static final Logger log = LogManager.getLogger(CirculationRulesProcessor.class); private final KieContainer kieContainer; /** @@ -59,6 +63,8 @@ public Drools(String tenantId, String drools) { } private KieSession createSession(MultiMap params, Location location, Match match) { + log.debug("createSession:: parameters params: {}, location: {}, match: {}", params.size(), + location, match); String itemTypeId = params.get(ITEM_TYPE_ID_NAME); String loanTypeId = params.get(LOAN_TYPE_ID_NAME); String patronGroupId = params.get(PATRON_TYPE_ID_NAME); @@ -71,6 +77,7 @@ private KieSession createSession(MultiMap params, Location location, Match match kieSession.insert(new PatronGroup(patronGroupId)); kieSession.insert(new ItemLocation(locationId)); if (location != null) { + log.info("createSession:: location is not null"); kieSession.insert(new Institution(location.getInstitutionId())); kieSession.insert(new Campus(location.getCampusId())); kieSession.insert(new Library(location.getLibraryId())); @@ -86,6 +93,7 @@ private KieSession createSession(MultiMap params, Location location, Match match * @return CirculationRuleMatch object with the name of the loan policy and rule conditions */ public CirculationRuleMatch loanPolicy(MultiMap params, Location location) { + log.debug("loanPolicy:: params params: {}, location: {}", params.size(), location); final var match = new Match(); final KieSession kieSession = createSession(params, location, match); final RuleEventListener ruleEventListener = new RuleEventListener(); @@ -110,6 +118,7 @@ public CirculationRuleMatch loanPolicy(MultiMap params, Location location) { * @return matches, each match has a loanPolicyId and a circulationRuleLine field */ public JsonArray loanPolicies(MultiMap params, Location location) { + log.debug("loanPolicies:: params params: {}, location: {}", params.size(), location); final var match = new Match(); final KieSession kieSession = createSession(params, location, match); @@ -125,6 +134,7 @@ public JsonArray loanPolicies(MultiMap params, Location location) { } kieSession.dispose(); + log.info("loanPolicies:: result: {}", () -> asJson(array.stream().toList())); return array; } @@ -135,6 +145,7 @@ public JsonArray loanPolicies(MultiMap params, Location location) { * @return CirculationRuleMatch object with the name of the loan policy and rule conditions */ public CirculationRuleMatch requestPolicy(MultiMap params, Location location) { + log.debug("requestPolicy:: parameters params: {}, location: {}", params, location); final var match = new Match(); final KieSession kieSession = createSession(params, location, match); @@ -153,6 +164,8 @@ public CirculationRuleMatch requestPolicy(MultiMap params, Location location) { * @return matches, each match has a requestPolicyId and a circulationRuleLine field */ public JsonArray requestPolicies(MultiMap params, Location location) { + log.debug("requestPolicy:: parameters params: {}, location: {}", params, location); + final var match = new Match(); final KieSession kieSession = createSession(params, location, match); @@ -169,6 +182,7 @@ public JsonArray requestPolicies(MultiMap params, Location location) { kieSession.dispose(); + log.info("requestPolicies:: result: {}", () -> asJson(array.stream().toList())); return array; } @@ -179,6 +193,7 @@ public JsonArray requestPolicies(MultiMap params, Location location) { * @return CirculationRuleMatch object with the name of the loan policy and rule conditions */ public CirculationRuleMatch noticePolicy(MultiMap params, Location location) { + log.debug("noticePolicy:: parameters params: {}, location: {}", params.size(), location); final var match = new Match(); final KieSession kieSession = createSession(params, location, match); @@ -197,6 +212,7 @@ public CirculationRuleMatch noticePolicy(MultiMap params, Location location) { * @return matches, each match has a noticePolicyId and a circulationRuleLine field */ public JsonArray noticePolicies(MultiMap params, Location location) { + log.debug("noticePolicies:: parameters params: {}, location: {}", params.size(), location); final var match = new Match(); final KieSession kieSession = createSession(params, location, match); @@ -212,6 +228,7 @@ public JsonArray noticePolicies(MultiMap params, Location location) { } kieSession.dispose(); + log.info("noticePolicies:: result: {}", () -> asJson(array.stream().toList())); return array; } @@ -223,6 +240,7 @@ public JsonArray noticePolicies(MultiMap params, Location location) { * @return CirculationRuleMatch object with the name of the loan policy and rule conditions */ public CirculationRuleMatch overduePolicy(MultiMap params, Location location) { + log.debug("overduePolicy:: parameters params: {}, location: {}", params, location); final var match = new Match(); final KieSession kieSession = createSession(params, location, match); @@ -241,6 +259,7 @@ public CirculationRuleMatch overduePolicy(MultiMap params, Location location) { * @return matches, each match has a overduePolicyId and a circulationRuleLine field */ public JsonArray overduePolicies(MultiMap params, Location location) { + log.debug("overduePolicies:: parameters params: {}, location: {}", params, location); final var match = new Match(); final KieSession kieSession = createSession(params, location, match); @@ -256,6 +275,8 @@ public JsonArray overduePolicies(MultiMap params, Location location) { } kieSession.dispose(); + log.info("overduePolicies:: result: {}", () -> asJson(array.stream().toList())); + return array; } @@ -266,6 +287,8 @@ public JsonArray overduePolicies(MultiMap params, Location location) { * @return CirculationRuleMatch object with the name of the loan policy and rule conditions */ public CirculationRuleMatch lostItemPolicy(MultiMap params, Location location) { + log.debug("lostItemPolicy:: parameters params: {}, location: {}", params, location); + final var match = new Match(); final KieSession kieSession = createSession(params, location, match); @@ -284,6 +307,7 @@ public CirculationRuleMatch lostItemPolicy(MultiMap params, Location location) { * @return matches, each match has a lostItemPolicyId and a circulationRuleLine field */ public JsonArray lostItemPolicies(MultiMap params, Location location) { + log.debug("lostItemPolicies:: parameters params: {}, location: {}", params, location); final var match = new Match(); final KieSession kieSession = createSession(params, location, match); @@ -299,6 +323,7 @@ public JsonArray lostItemPolicies(MultiMap params, Location location) { } kieSession.dispose(); + log.info("lostItemPolicies:: result: {}", () -> asJson(array.stream().toList())); return array; } @@ -346,6 +371,7 @@ public void afterMatchFired(AfterMatchFiredEvent event) { RuleImpl rule = (RuleImpl) event.getMatch().getRule(); if (rule.getLhs() != null && rule.getLhs().getChildren() != null) { + log.info("afterMatchFired:: getting rule conditions"); ruleConditionElements = rule.getLhs().getChildren().stream() .map(Object::toString) .map(this::getRuleConditionFromStringRuleRepresentation) diff --git a/src/main/java/org/folio/circulation/rules/ExecutableRules.java b/src/main/java/org/folio/circulation/rules/ExecutableRules.java index 3c0e92b593..5809348651 100644 --- a/src/main/java/org/folio/circulation/rules/ExecutableRules.java +++ b/src/main/java/org/folio/circulation/rules/ExecutableRules.java @@ -31,22 +31,32 @@ public ExecutableRules(String text, Drools drools) { } public Result determineLoanPolicy(RulesExecutionParameters parameters) { + log.debug("determineLoanPolicy:: parameters parameters: {}", parameters); + return determinePolicy(parameters, drools::loanPolicy, "loan policy"); } public Result determineRequestPolicy(RulesExecutionParameters parameters) { + log.debug("determineRequestPolicy:: parameters parameters: {}", parameters); + return determinePolicy(parameters, drools::requestPolicy, "request policy"); } public Result determineNoticePolicy(RulesExecutionParameters parameters) { + log.debug("determineNoticePolicy:: parameters parameters: {}", parameters); + return determinePolicy(parameters, drools::noticePolicy, "notice policy"); } public Result determineLostItemPolicy(RulesExecutionParameters parameters) { + log.debug("determineLostItemPolicy:: parameters parameters: {}", parameters); + return determinePolicy(parameters, drools::lostItemPolicy, "lost item policy"); } public Result determineOverduePolicy(RulesExecutionParameters parameters) { + log.debug("determineOverduePolicy:: parameters parameters: {}", parameters); + return determinePolicy(parameters, drools::overduePolicy, "overdude policy"); } diff --git a/src/main/java/org/folio/circulation/rules/Match.java b/src/main/java/org/folio/circulation/rules/Match.java index e91161229e..8ac885c756 100644 --- a/src/main/java/org/folio/circulation/rules/Match.java +++ b/src/main/java/org/folio/circulation/rules/Match.java @@ -1,8 +1,11 @@ package org.folio.circulation.rules; +import lombok.ToString; + /** * Store the result of a rule match. */ +@ToString public class Match { /** loan policy of the matching rule */ @SuppressWarnings("squid:ClassVariableVisibilityCheck") // Drools directly uses public fields diff --git a/src/main/java/org/folio/circulation/rules/cache/CirculationRulesCache.java b/src/main/java/org/folio/circulation/rules/cache/CirculationRulesCache.java index 2188d0f7d6..81060de3ae 100644 --- a/src/main/java/org/folio/circulation/rules/cache/CirculationRulesCache.java +++ b/src/main/java/org/folio/circulation/rules/cache/CirculationRulesCache.java @@ -42,14 +42,16 @@ public void dropCache() { } private boolean rulesExist(String tenantId) { + log.debug("rulesExist:: parameters tenantId: {}", tenantId); Rules rules = rulesMap.get(tenantId); - + log.info("rulesExist:: result: {}", rules != null); return rules != null; } public CompletableFuture> reloadRules(String tenantId, CollectionResourceClient circulationRulesClient) { - log.info("Reloading rules for tenant {}", tenantId); + + log.debug("reloadRules:: parameters tenant: {}", tenantId); return circulationRulesClient.get() .thenApply(r -> r.map(response -> getRulesAsText(response, tenantId))) @@ -57,11 +59,11 @@ public CompletableFuture> reloadRules(String tenantId, } private static String getRulesAsText(Response response, String tenantId) { - log.info("Fetched rules for tenant {}", tenantId); - + log.debug("getRulesAsText:: parameters tenantId: {}", tenantId); + final var circulationRules = new JsonObject(response.getBody()); var encodeRules = circulationRules.encodePrettily(); - log.info("circulationRules = {}", encodeRules); + log.info("getRulesAsText:: circulationRules: {}", encodeRules); return circulationRules.getString("rulesAsText"); }