From 5a415cca58820db24603cf623812116ea162df18 Mon Sep 17 00:00:00 2001 From: Roman Barannyk <53909129+roman-barannyk@users.noreply.github.com> Date: Fri, 3 Nov 2023 20:47:25 +0200 Subject: [PATCH] [CIRC-1910] Logging - circulation domain (M - U) (#1364) * CIRC-1910 improve logging * CIRC-1910 fix code smells * CIRC-1910 include code review comments --- .../domain/MoveRequestProcessAdapter.java | 28 +++++-- .../domain/MoveRequestService.java | 15 +++- .../circulation/domain/MultipleRecords.java | 30 +++++--- .../folio/circulation/domain/OpeningDay.java | 6 ++ .../domain/OverdueFineService.java | 39 +++++++++- .../OverduePeriodCalculatorService.java | 52 +++++++++++-- .../circulation/domain/ProxyRelationship.java | 6 ++ .../domain/RequestServiceUtility.java | 63 +++++++++++++--- .../domain/StoredRequestRepresentation.java | 5 ++ .../folio/circulation/domain/UpdateItem.java | 31 +++++++- .../folio/circulation/domain/UpdateLoan.java | 25 +++++-- .../domain/UpdateRequestQueue.java | 75 +++++++++++++------ .../domain/UpdateRequestService.java | 8 ++ .../support/http/client/Response.java | 5 +- 14 files changed, 320 insertions(+), 68 deletions(-) diff --git a/src/main/java/org/folio/circulation/domain/MoveRequestProcessAdapter.java b/src/main/java/org/folio/circulation/domain/MoveRequestProcessAdapter.java index d4f280b7ed..831aa5f743 100644 --- a/src/main/java/org/folio/circulation/domain/MoveRequestProcessAdapter.java +++ b/src/main/java/org/folio/circulation/domain/MoveRequestProcessAdapter.java @@ -1,46 +1,64 @@ package org.folio.circulation.domain; +import java.lang.invoke.MethodHandles; import java.util.concurrent.CompletableFuture; +import org.apache.logging.log4j.LogManager; +import org.apache.logging.log4j.Logger; import org.folio.circulation.infrastructure.storage.inventory.ItemRepository; import org.folio.circulation.infrastructure.storage.loans.LoanRepository; import org.folio.circulation.infrastructure.storage.requests.RequestRepository; import org.folio.circulation.support.results.Result; public class MoveRequestProcessAdapter { + private static final Logger log = LogManager.getLogger(MethodHandles.lookup().lookupClass()); private final ItemRepository itemRepository; private final LoanRepository loanRepository; private final RequestRepository requestRepository; public MoveRequestProcessAdapter(ItemRepository itemRepository, LoanRepository loanRepository, - RequestRepository requestRepository) { + RequestRepository requestRepository) { + this.itemRepository = itemRepository; this.loanRepository = loanRepository; this.requestRepository = requestRepository; } CompletableFuture> findDestinationItem( - RequestAndRelatedRecords requestAndRelatedRecords) { + RequestAndRelatedRecords requestAndRelatedRecords) { + + log.debug("findDestinationItem:: parameters requestAndRelatedRecords: {}", + () -> requestAndRelatedRecords); + return itemRepository.fetchById(requestAndRelatedRecords.getDestinationItemId()) .thenApply(r -> r.map(requestAndRelatedRecords::withItem)) .thenComposeAsync(r -> r.after(this::findLoanForItem)); } private CompletableFuture> findLoanForItem( - RequestAndRelatedRecords requestAndRelatedRecords) { + RequestAndRelatedRecords requestAndRelatedRecords) { + return loanRepository.findOpenLoanForRequest(requestAndRelatedRecords.getRequest()) .thenApply(r -> r.map(requestAndRelatedRecords::withLoan)); } CompletableFuture> findSourceItem( - RequestAndRelatedRecords requestAndRelatedRecords) { + RequestAndRelatedRecords requestAndRelatedRecords) { + + log.debug("findSourceItem:: parameters requestAndRelatedRecords: {}", + () -> requestAndRelatedRecords); + return itemRepository.fetchById(requestAndRelatedRecords.getSourceItemId()) .thenApply(result -> result.map(requestAndRelatedRecords::withItem)) .thenComposeAsync(r -> r.after(this::findLoanForItem)); } CompletableFuture> getRequest( - RequestAndRelatedRecords requestAndRelatedRecords) { + RequestAndRelatedRecords requestAndRelatedRecords) { + + log.debug("getRequest:: parameters requestAndRelatedRecords: {}", + () -> requestAndRelatedRecords); + return requestRepository.getById(requestAndRelatedRecords.getRequest().getId()) .thenApply(r -> r.map(requestAndRelatedRecords::withRequest)); } diff --git a/src/main/java/org/folio/circulation/domain/MoveRequestService.java b/src/main/java/org/folio/circulation/domain/MoveRequestService.java index ffed3f354c..3077016093 100644 --- a/src/main/java/org/folio/circulation/domain/MoveRequestService.java +++ b/src/main/java/org/folio/circulation/domain/MoveRequestService.java @@ -3,8 +3,11 @@ import static org.folio.circulation.domain.representations.logs.LogEventType.REQUEST_MOVED; import static org.folio.circulation.support.results.Result.of; +import java.lang.invoke.MethodHandles; import java.util.concurrent.CompletableFuture; +import org.apache.logging.log4j.LogManager; +import org.apache.logging.log4j.Logger; import org.folio.circulation.domain.validation.RequestLoanValidator; import org.folio.circulation.infrastructure.storage.ConfigurationRepository; import org.folio.circulation.infrastructure.storage.requests.RequestPolicyRepository; @@ -24,6 +27,7 @@ public class MoveRequestService { private final ConfigurationRepository configurationRepository; private final EventPublisher eventPublisher; private final RequestQueueRepository requestQueueRepository; + private static final Logger log = LogManager.getLogger(MethodHandles.lookup().lookupClass()); public MoveRequestService(RequestRepository requestRepository, RequestPolicyRepository requestPolicyRepository, UpdateUponRequest updateUponRequest, MoveRequestProcessAdapter moveRequestHelper, @@ -71,11 +75,14 @@ public CompletableFuture> moveRequest( } private RequestAndRelatedRecords pagedRequestIfDestinationItemAvailable( - RequestAndRelatedRecords requestAndRelatedRecords) { + RequestAndRelatedRecords requestAndRelatedRecords) { + log.debug("pagedRequestIfDestinationItemAvailable parameters requestAndRelatedRecords: {}", + () -> requestAndRelatedRecords); Item item = requestAndRelatedRecords.getRequest().getItem(); if (item.getStatus().equals(ItemStatus.AVAILABLE)) { + log.info("pagedRequestIfDestinationItemAvailable:: item: {} is available", item.getItemId()); return requestAndRelatedRecords.withRequestType(RequestType.PAGE); } @@ -85,6 +92,9 @@ private RequestAndRelatedRecords pagedRequestIfDestinationItemAvailable( private CompletableFuture> validateUpdateRequest( RequestAndRelatedRecords requestAndRelatedRecords) { + log.debug("validateUpdateRequest parameters requestAndRelatedRecords: {}", + () -> requestAndRelatedRecords); + return of(() -> requestAndRelatedRecords) .next(RequestServiceUtility::refuseWhenItemDoesNotExist) .next(RequestServiceUtility::refuseWhenInvalidUserAndPatronGroup) @@ -98,6 +108,9 @@ private CompletableFuture> validateUpdateReques private CompletableFuture> updateRelatedObjects( RequestAndRelatedRecords requestAndRelatedRecords) { + log.debug("updateRelatedObjects parameters requestAndRelatedRecords: {}", + () -> requestAndRelatedRecords); + return updateUponRequest.updateItem.onRequestCreateOrUpdate(requestAndRelatedRecords) .thenComposeAsync(r -> r.after(updateUponRequest.updateLoan::onRequestCreateOrUpdate)); } diff --git a/src/main/java/org/folio/circulation/domain/MultipleRecords.java b/src/main/java/org/folio/circulation/domain/MultipleRecords.java index 63e2afea89..fcb48896b1 100644 --- a/src/main/java/org/folio/circulation/domain/MultipleRecords.java +++ b/src/main/java/org/folio/circulation/domain/MultipleRecords.java @@ -4,7 +4,9 @@ import static java.util.stream.Stream.concat; import static org.folio.circulation.support.json.JsonObjectArrayPropertyFetcher.mapToList; import static org.folio.circulation.support.results.Result.succeeded; +import static org.folio.circulation.support.utils.LogUtil.multipleRecordsAsString; +import java.lang.invoke.MethodHandles; import java.util.ArrayList; import java.util.Collection; import java.util.List; @@ -16,6 +18,8 @@ import java.util.function.Predicate; import java.util.stream.Collectors; +import org.apache.logging.log4j.LogManager; +import org.apache.logging.log4j.Logger; import org.folio.circulation.support.http.client.Response; import org.folio.circulation.support.http.client.ResponseInterpreter; import org.folio.circulation.support.results.Result; @@ -25,6 +29,7 @@ public class MultipleRecords { private static final String TOTAL_RECORDS_PROPERTY_NAME = "totalRecords"; + private static final Logger log = LogManager.getLogger(MethodHandles.lookup().lookupClass()); private final Collection records; private final Integer totalRecords; @@ -38,10 +43,11 @@ public static MultipleRecords empty() { return new MultipleRecords<>(new ArrayList<>(), 0); } - public static Result> from( - Response response, - Function mapper, - String recordsPropertyName) { + public static Result> from(Response response, + Function mapper, String recordsPropertyName) { + + log.debug("from:: parameters response: {}, recordsPropertyName: {}", + response, recordsPropertyName); return new ResponseInterpreter>() .flatMapOn(200, r -> from(r.getJson(), mapper, recordsPropertyName)) @@ -49,8 +55,10 @@ public static Result> from( } public static Result> from(JsonObject representation, - Function mapper, - String recordsPropertyName) { + Function mapper, String recordsPropertyName) { + + log.debug("from:: parameters representation: {}, recordsPropertyName: {}", + () -> representation, () -> recordsPropertyName); List wrappedRecords = mapToList(representation, recordsPropertyName, mapper); Integer totalRecords = representation.getInteger(TOTAL_RECORDS_PROPERTY_NAME); @@ -63,6 +71,9 @@ public MultipleRecords combineRecords(MultipleRecords otherRecords, Function> matcher, BiFunction combiner, R defaultOtherRecord) { + log.debug("combineRecords:: parameters otherRecords: {}", + () -> multipleRecordsAsString(otherRecords)); + return mapRecords(mainRecord -> combiner.apply(mainRecord, otherRecords .filter(matcher.apply(mainRecord)) .firstOrElse(defaultOtherRecord))); @@ -113,6 +124,7 @@ public Result> flatMapRecords(Function> mapp } public MultipleRecords combine(MultipleRecords other) { + log.debug("combine:: parameters other: {}", () -> multipleRecordsAsString(other)); final List allRecords = concat(records.stream(), other.records.stream()) .collect(Collectors.toList()); @@ -125,13 +137,11 @@ public MultipleRecords filter(Predicate predicate) { .collect(Collectors.toList()); final int numberOfFilteredOutRecords = totalRecords - filteredRecords.size(); + log.info("filter:: totalRecords: {}", totalRecords); return new MultipleRecords<>(filteredRecords, totalRecords - numberOfFilteredOutRecords); } - public JsonObject asJson( - Function mapper, - String recordsPropertyName) { - + public JsonObject asJson(Function mapper, String recordsPropertyName) { final List mappedRecords = getRecords().stream() .map(mapper) .collect(Collectors.toList()); diff --git a/src/main/java/org/folio/circulation/domain/OpeningDay.java b/src/main/java/org/folio/circulation/domain/OpeningDay.java index 5501ae80d8..529b950b8f 100644 --- a/src/main/java/org/folio/circulation/domain/OpeningDay.java +++ b/src/main/java/org/folio/circulation/domain/OpeningDay.java @@ -6,6 +6,7 @@ import static org.folio.circulation.support.json.JsonPropertyFetcher.getLocalDateProperty; import static org.folio.circulation.support.json.JsonPropertyWriter.write; +import java.lang.invoke.MethodHandles; import java.time.LocalDate; import java.time.ZoneId; import java.time.ZonedDateTime; @@ -13,6 +14,8 @@ import java.util.List; import java.util.stream.Collector; +import org.apache.logging.log4j.LogManager; +import org.apache.logging.log4j.Logger; import org.folio.circulation.support.utils.DateTimeUtil; import lombok.AllArgsConstructor; @@ -31,6 +34,7 @@ public class OpeningDay { private static final String ALL_DAY_KEY = "allDay"; private static final String OPEN_KEY = "open"; private static final String OPENINGS_KEY = "openings"; + private static final Logger log = LogManager.getLogger(MethodHandles.lookup().lookupClass()); private final List openings; private final LocalDate date; @@ -99,6 +103,7 @@ public JsonObject toJson() { write(json, ALL_DAY_KEY, allDay); write(json, OPEN_KEY, open); write(json, OPENINGS_KEY, openingHourToJsonArray()); + log.debug("toJson:: result: {}", () -> json); return json; } @@ -107,6 +112,7 @@ public JsonObject toJson() { * Create a list of {@link OpeningHour OpeningHour} from the provided daily opening object */ private static List createOpeningTimes(JsonObject representation) { + log.debug("createOpeningTimes:: parameters representation: {}", () -> representation); return mapToList(representation, OPENINGS_KEY, OpeningHour::new); } } diff --git a/src/main/java/org/folio/circulation/domain/OverdueFineService.java b/src/main/java/org/folio/circulation/domain/OverdueFineService.java index 08caa26a02..e2174b5cb0 100644 --- a/src/main/java/org/folio/circulation/domain/OverdueFineService.java +++ b/src/main/java/org/folio/circulation/domain/OverdueFineService.java @@ -10,6 +10,7 @@ import static org.folio.circulation.support.results.Result.succeeded; import static org.folio.circulation.support.results.ResultBinding.mapResult; +import java.lang.invoke.MethodHandles; import java.math.BigDecimal; import java.time.ZonedDateTime; @@ -19,6 +20,8 @@ import java.util.function.Predicate; import org.apache.commons.lang3.ObjectUtils; +import org.apache.logging.log4j.LogManager; +import org.apache.logging.log4j.Logger; import org.folio.circulation.domain.policy.OverdueFineCalculationParameters; import org.folio.circulation.domain.policy.OverdueFineInterval; import org.folio.circulation.domain.policy.OverdueFinePolicy; @@ -34,10 +37,12 @@ import org.folio.circulation.support.utils.ClockUtil; import lombok.AllArgsConstructor; +import lombok.ToString; import lombok.With; @AllArgsConstructor public class OverdueFineService { + private static final Logger log = LogManager.getLogger(MethodHandles.lookup().lookupClass()); private final OverdueFinePolicyRepository overdueFinePolicyRepository; private final ItemRepository itemRepository; private final FeeFineOwnerRepository feeFineOwnerRepository; @@ -49,10 +54,12 @@ public class OverdueFineService { public CompletableFuture> createOverdueFineIfNecessary( RenewalContext context) { + log.debug("createOverdueFineIfNecessary:: parameters context: {}", () -> context); final String loggedInUserId = context.getLoggedInUserId(); final Loan loanBeforeRenewal = context.getLoanBeforeRenewal(); if (!shouldChargeOverdueFineOnRenewal(context)) { + log.info("createOverdueFineIfNecessary:: loan on renewal should not be charged"); return completedFuture(succeeded(context)); } @@ -76,7 +83,10 @@ private boolean shouldChargeOverdueFineOnRenewal(RenewalContext renewalContext) public CompletableFuture> createOverdueFineIfNecessary( CheckInContext context, String userId) { + log.debug("createOverdueFineIfNecessary:: parameters context: {}, userId: {}", + () -> context, () -> userId); if (!shouldChargeOverdueFineOnCheckIn(context)) { + log.info("createOverdueFineIfNecessary:: loan on check in should not be charged"); return completedFuture(succeeded(null)); } @@ -118,13 +128,19 @@ private boolean shouldChargeOverdueFineForLostItem(Loan loan) { private CompletableFuture> createOverdueFineIfNecessary(Loan loan, Scenario scenario, String loggedInUserId) { + log.debug("createOverdueFineIfNecessary:: parameters loan: {}, scenario: {}, " + + "loggedInUserId: {}", () -> loan, () -> scenario, () -> loggedInUserId); + return overdueFinePolicyRepository.findOverdueFinePolicyForLoan(succeeded(loan)) - .thenCompose(r -> r.after(l -> scenario.shouldCreateFine(l.getOverdueFinePolicy()) + .thenCompose(r -> r.after(l -> scenario.shouldCreateFine(l.getOverdueFinePolicy()) ? createOverdueFine(l, loggedInUserId) : completedFuture(succeeded(null)))); } private CompletableFuture> createOverdueFine(Loan loan, String loggedInUserId) { + log.debug("createOverdueFine:: parameters loan: {}, loggedInUserId: {}", + () -> loan, () -> loggedInUserId); + return getOverdueMinutes(loan) .thenCompose(r -> r.after(minutes -> calculateOverdueFine(loan, minutes))) .thenCompose(r -> r.after(fineAmount -> createFeeFineRecord(loan, fineAmount, loggedInUserId))); @@ -133,12 +149,15 @@ private CompletableFuture> createOverdueFine(Loan loan, St private CompletableFuture> getOverdueMinutes(Loan loan) { ZonedDateTime systemTime = loan.getReturnDate(); if (systemTime == null) { + log.info("getOverdueMinutes:: returnDate for loan {} is null", loan.getId()); systemTime = ClockUtil.getZonedDateTime(); } return overduePeriodCalculatorService.getMinutes(loan, systemTime); } private CompletableFuture> calculateOverdueFine(Loan loan, Integer overdueMinutes) { + log.debug("calculateOverdueFine:: parameters loan: {}, overdueMinutes: {}", + () -> loan ,() -> overdueMinutes); BigDecimal overdueFine = BigDecimal.ZERO; OverdueFinePolicy overdueFinePolicy = loan.getOverdueFinePolicy(); @@ -163,13 +182,15 @@ private CompletableFuture> calculateOverdueFine(Loan loan, In } } } + log.info("calculateOverdueFine:: result: {}", overdueFine); - return CompletableFuture.completedFuture(succeeded(overdueFine)); + return completedFuture(succeeded(overdueFine)); } private CompletableFuture> lookupItemRelatedRecords( CalculationParameters params) { + log.debug("lookupItemRelatedRecords:: parameters params: {}", () -> params); if (params.feeFine == null) { return completedFuture(succeeded(params)); } @@ -181,6 +202,8 @@ private CompletableFuture> lookupItemRelatedRecord private CompletableFuture> lookupFeeFineOwner( CalculationParameters params) { + log.debug("lookupFeeFineOwner:: parameters params: {}", () -> params); + return Optional.ofNullable(params.item) .map(Item::getLocation) .map(Location::getPrimaryServicePointId) @@ -193,6 +216,8 @@ private CompletableFuture> lookupFeeFineOwner( private CompletableFuture> lookupFeeFine( CalculationParameters params) { + log.debug("lookupFeeFine:: parameters params: {}", () -> params); + return feeFineRepository.getFeeFine(FeeFine.OVERDUE_FINE_TYPE, true) .thenApply(mapResult(params::withFeeFine)); } @@ -200,7 +225,11 @@ private CompletableFuture> lookupFeeFine( private CompletableFuture> createFeeFineRecord(Loan loan, BigDecimal fineAmount, String loggedInUserId) { + log.debug("createFeeFineRecord:: parameters loan: {}, fineAmount: {}, loggedInUserId: {}", + () -> loan, () -> fineAmount, () -> loggedInUserId); + if (fineAmount.compareTo(BigDecimal.ZERO) <= 0) { + log.info("createFeeFineRecord:: fineAmount is 0"); return completedFuture(succeeded(null)); } @@ -215,7 +244,9 @@ private CompletableFuture> createFeeFineRecord(Loan loan, } private CompletableFuture> createAccount(CalculationParameters params) { + log.debug("createAccount:: parameters params: {}", () -> params); if (params.isIncomplete()) { + log.info("createAccount:: params are incomplete"); return completedFuture(succeeded(null)); } @@ -241,11 +272,15 @@ private boolean itemWasLost(ItemStatus itemStatus) { @With @AllArgsConstructor(access = PRIVATE) + @ToString(onlyExplicitlyIncluded = true) private static class CalculationParameters { + @ToString.Include private final Loan loan; private final Item item; private final FeeFineOwner feeFineOwner; + @ToString.Include private final FeeFine feeFine; + @ToString.Include private final BigDecimal fineAmount; private final String loggedInUserId; diff --git a/src/main/java/org/folio/circulation/domain/OverduePeriodCalculatorService.java b/src/main/java/org/folio/circulation/domain/OverduePeriodCalculatorService.java index 59574bd2d2..e70dac0542 100644 --- a/src/main/java/org/folio/circulation/domain/OverduePeriodCalculatorService.java +++ b/src/main/java/org/folio/circulation/domain/OverduePeriodCalculatorService.java @@ -7,7 +7,9 @@ import static org.folio.circulation.support.utils.DateTimeUtil.isAfterMillis; import static org.folio.circulation.support.utils.DateTimeUtil.isBeforeMillis; import static org.folio.circulation.support.utils.DateTimeUtil.isWithinMillis; +import static org.folio.circulation.support.utils.LogUtil.collectionAsString; +import java.lang.invoke.MethodHandles; import java.time.LocalDate; import java.time.ZonedDateTime; import java.time.temporal.ChronoUnit; @@ -15,12 +17,16 @@ import java.util.UUID; import java.util.concurrent.CompletableFuture; +import org.apache.logging.log4j.LogManager; +import org.apache.logging.log4j.Logger; import org.folio.circulation.infrastructure.storage.CalendarRepository; import org.folio.circulation.infrastructure.storage.loans.LoanPolicyRepository; import org.folio.circulation.support.results.Result; +import org.folio.circulation.support.utils.LogUtil; public class OverduePeriodCalculatorService { private static final int ZERO_MINUTES = 0; + private static final Logger log = LogManager.getLogger(MethodHandles.lookup().lookupClass()); private final CalendarRepository calendarRepository; private final LoanPolicyRepository loanPolicyRepository; @@ -33,9 +39,12 @@ public OverduePeriodCalculatorService(CalendarRepository calendarRepository, } public CompletableFuture> getMinutes(Loan loan, ZonedDateTime systemTime) { + log.debug("getMinutes:: parameters loan: {}, systemTime: {}", () -> loan, () -> systemTime); final Boolean shouldCountClosedPeriods = loan.getOverdueFinePolicy().getCountPeriodsWhenServicePointIsClosed(); if (preconditionsAreMet(loan, systemTime, shouldCountClosedPeriods)) { + log.info("getMinutes:: preconditions must be included"); + return completedFuture(loan) .thenComposeAsync(loanPolicyRepository::lookupPolicy) .thenApply(r -> r.map(loan::withLoanPolicy)) @@ -50,28 +59,44 @@ boolean preconditionsAreMet(Loan loan, ZonedDateTime systemTime, Boolean shouldC return shouldCountClosedPeriods != null && loan.isOverdue(systemTime); } - CompletableFuture> getOverdueMinutes(Loan loan, ZonedDateTime systemTime, boolean shouldCountClosedPeriods) { + CompletableFuture> getOverdueMinutes(Loan loan, ZonedDateTime systemTime, + boolean shouldCountClosedPeriods) { + return shouldCountClosedPeriods || getItemLocationPrimaryServicePoint(loan) == null ? minutesOverdueIncludingClosedPeriods(loan, systemTime) : minutesOverdueExcludingClosedPeriods(loan, systemTime); } - private CompletableFuture> minutesOverdueIncludingClosedPeriods(Loan loan, ZonedDateTime systemTime) { + private CompletableFuture> minutesOverdueIncludingClosedPeriods(Loan loan, + ZonedDateTime systemTime) { + + log.debug("minutesOverdueIncludingClosedPeriods:: parameters loan: {}, systemTime: {}", + () -> loan, () -> systemTime); int overdueMinutes = calculateDiffInMinutes(loan.getDueDate(), systemTime); + return completedFuture(succeeded(overdueMinutes)); } - private CompletableFuture> minutesOverdueExcludingClosedPeriods(Loan loan, ZonedDateTime returnDate) { + private CompletableFuture> minutesOverdueExcludingClosedPeriods(Loan loan, + ZonedDateTime returnDate) { + + log.debug("minutesOverdueExcludingClosedPeriods:: parameters loan: {}, returnDate: {}", + () -> loan, () -> returnDate); ZonedDateTime dueDate = loan.getDueDate(); String itemLocationPrimaryServicePoint = getItemLocationPrimaryServicePoint(loan).toString(); + return calendarRepository .fetchOpeningDaysBetweenDates(itemLocationPrimaryServicePoint, dueDate, returnDate) .thenApply(r -> r.next(openingDays -> getOpeningDaysDurationMinutes( openingDays, dueDate, returnDate))); } - Result getOpeningDaysDurationMinutes( - Collection openingDays, ZonedDateTime dueDate, ZonedDateTime returnDate) { + Result getOpeningDaysDurationMinutes(Collection openingDays, + ZonedDateTime dueDate, ZonedDateTime returnDate) { + + log.debug("getOpeningDaysDurationMinutes:: parameters openingDays: {}, " + + "dueDate: {}, returnDate: {}", () -> collectionAsString(openingDays), + () -> dueDate, () -> returnDate); return succeeded( openingDays.stream() @@ -80,9 +105,11 @@ Result getOpeningDaysDurationMinutes( .sum()); } - private int getOpeningDayDurationMinutes( - OpeningDay openingDay, ZonedDateTime dueDate, ZonedDateTime systemTime) { + private int getOpeningDayDurationMinutes(OpeningDay openingDay, ZonedDateTime dueDate, + ZonedDateTime systemTime) { + log.debug("getOpeningDayDurationMinutes:: parameters openingDay: {}, " + + "dueDate: {}, returnDate: {}", () -> openingDay, () -> dueDate, () -> systemTime); ZonedDateTime datePart = openingDay.getDayWithTimeZone(); return openingDay.getOpenings() @@ -95,21 +122,28 @@ private int getOpeningDayDurationMinutes( private int getOpeningHourDurationMinutes(OpeningHour openingHour, ZonedDateTime datePart, ZonedDateTime dueDate, ZonedDateTime returnDate) { + log.debug("getOpeningHourDurationMinutes:: parameters openingHour: {}, " + + "datePart: {}, dueDate: {}, returnDate: {}", () -> openingHour, () -> datePart, + () -> dueDate, () -> returnDate); + if (allNotNull(datePart, dueDate, openingHour.getStartTime(), openingHour.getEndTime())) { final LocalDate date = datePart.toLocalDate(); ZonedDateTime startTime = ZonedDateTime.of(date, openingHour.getStartTime(), datePart.getZone()); ZonedDateTime endTime = ZonedDateTime.of(date, openingHour.getEndTime(), datePart.getZone()); if (isWithinMillis(dueDate, startTime, endTime)) { + log.info("getOpeningHourDurationMinutes:: dueDate is within startTime and endTime"); startTime = dueDate; } if (isWithinMillis(returnDate, startTime, endTime)) { + log.info("getOpeningHourDurationMinutes:: returnDate is within startTime and endTime"); endTime = returnDate; } if (isAfterMillis(endTime, startTime) && isAfterMillis(endTime, dueDate) && isBeforeMillis(startTime, returnDate)) { + log.info("getOpeningHourDurationMinutes:: calculating difference in minutes"); return calculateDiffInMinutes(startTime, endTime); } } @@ -125,14 +159,18 @@ private int calculateDiffInMinutes(ZonedDateTime start, ZonedDateTime end) { } Result adjustOverdueWithGracePeriod(Loan loan, int overdueMinutes) { + log.debug("adjustOverdueWithGracePeriod:: parameters loan: {}, overdueMinutes: {}", + () -> loan, () -> overdueMinutes); int result; if (shouldIgnoreGracePeriod(loan)) { + log.info("adjustOverdueWithGracePeriod:: grace period should be ignored"); result = overdueMinutes; } else { result = overdueMinutes > getGracePeriodMinutes(loan) ? overdueMinutes : ZERO_MINUTES; } + log.info("adjustOverdueWithGracePeriod:: result: {}", result); return Result.succeeded(result); } diff --git a/src/main/java/org/folio/circulation/domain/ProxyRelationship.java b/src/main/java/org/folio/circulation/domain/ProxyRelationship.java index cbde7c84d1..cd820f8740 100644 --- a/src/main/java/org/folio/circulation/domain/ProxyRelationship.java +++ b/src/main/java/org/folio/circulation/domain/ProxyRelationship.java @@ -5,14 +5,18 @@ import static org.folio.circulation.support.json.JsonPropertyFetcher.getNestedStringProperty; import static org.folio.circulation.support.utils.DateTimeUtil.isBeforeMillis; +import java.lang.invoke.MethodHandles; import java.time.ZonedDateTime; import org.apache.commons.lang3.StringUtils; +import org.apache.logging.log4j.LogManager; +import org.apache.logging.log4j.Logger; import org.folio.circulation.support.utils.ClockUtil; import io.vertx.core.json.JsonObject; public class ProxyRelationship { + private static final Logger log = LogManager.getLogger(MethodHandles.lookup().lookupClass()); private final ZonedDateTime expirationDate; private final boolean active; @@ -24,6 +28,7 @@ public ProxyRelationship(JsonObject representation) { } private boolean getActive(JsonObject representation) { + log.debug("getActive:: parameters representation: {}", () -> representation); final String STATUS_PROPERTY_NAME = "status"; if(representation.containsKey(STATUS_PROPERTY_NAME)) { @@ -37,6 +42,7 @@ private boolean getActive(JsonObject representation) { } private ZonedDateTime getExpirationDate(JsonObject representation) { + log.debug("getExpirationDate:: parameters representation: {}", () -> representation); final String EXPIRATION_DATE_PROPERTY_NAME = "expirationDate"; if(representation.containsKey(EXPIRATION_DATE_PROPERTY_NAME) ) { diff --git a/src/main/java/org/folio/circulation/domain/RequestServiceUtility.java b/src/main/java/org/folio/circulation/domain/RequestServiceUtility.java index 99bcbb03f3..486d66bf06 100644 --- a/src/main/java/org/folio/circulation/domain/RequestServiceUtility.java +++ b/src/main/java/org/folio/circulation/domain/RequestServiceUtility.java @@ -8,11 +8,14 @@ import static org.folio.circulation.support.results.Result.of; import static org.folio.circulation.support.results.Result.succeeded; +import java.lang.invoke.MethodHandles; import java.util.HashMap; import java.util.Map; import java.util.Objects; import java.util.function.Predicate; +import org.apache.logging.log4j.LogManager; +import org.apache.logging.log4j.Logger; import org.folio.circulation.domain.Request.Operation; import org.folio.circulation.domain.policy.RequestPolicy; import org.folio.circulation.support.ErrorCode; @@ -24,15 +27,20 @@ public class RequestServiceUtility { private static final String ITEM_ID = "itemId"; private static final String REQUESTER_ID = "requesterId"; private static final String REQUEST_ID = "requestId"; + private static final Logger log = LogManager.getLogger(MethodHandles.lookup().lookupClass()); private RequestServiceUtility() { } static Result refuseWhenInstanceDoesNotExist( RequestAndRelatedRecords requestAndRelatedRecords) { + log.debug("refuseWhenInstanceDoesNotExist:: parameters requestAndRelatedRecords: {}", + () -> requestAndRelatedRecords); if (requestAndRelatedRecords.getRequest().getInstance().isNotFound()) { - return failedValidation("Instance does not exist", INSTANCE_ID, - requestAndRelatedRecords.getRequest().getInstanceId()); + String instanceId = requestAndRelatedRecords.getRequest().getInstanceId(); + log.error("refuseWhenInstanceDoesNotExist:: instance {} does not exist", + instanceId); + return failedValidation("Instance does not exist", INSTANCE_ID, instanceId); } else { return succeeded(requestAndRelatedRecords); } @@ -41,7 +49,11 @@ static Result refuseWhenInstanceDoesNotExist( static Result refuseWhenItemDoesNotExist( RequestAndRelatedRecords requestAndRelatedRecords) { + log.debug("refuseWhenItemDoesNotExist:: parameters requestAndRelatedRecords: {}", + () -> requestAndRelatedRecords); if (requestAndRelatedRecords.getRequest().getItem().isNotFound()) { + String itemId = requestAndRelatedRecords.getRequest().getItemId(); + log.error("refuseWhenItemDoesNotExist:: item {} does not exist", itemId); return failedValidation("Item does not exist", ITEM_ID, requestAndRelatedRecords.getRequest().getItemId()); } else { @@ -52,15 +64,21 @@ static Result refuseWhenItemDoesNotExist( static Result refuseWhenRequestCannotBeFulfilled( RequestAndRelatedRecords requestAndRelatedRecords) { + log.debug("refuseWhenRequestCannotBeFulfilled:: parameters requestAndRelatedRecords: {}", + () -> requestAndRelatedRecords); RequestPolicy requestPolicy = requestAndRelatedRecords.getRequestPolicy(); Request request = requestAndRelatedRecords.getRequest(); RequestType requestType = request.getRequestType(); if (!requestPolicy.allowsType(requestType)) { + log.warn("refuseWhenRequestCannotBeFulfilled:: requestPolicy does not allow " + + "the requestType {}", requestType); return failureDisallowedForRequestType(requestType); } if (!requestPolicy.allowsServicePoint(requestType, request.getPickupServicePointId())) { + log.warn("refuseWhenRequestCannotBeFulfilled:: requestPolicy does not allow servicePoint {}", + request.getPickupServicePointId()); return failedValidation("One or more Pickup locations are no longer available", Map.of(PICKUP_SERVICE_POINT_ID, request.getPickupServicePointId(), REQUEST_TYPE, requestType.toString(), @@ -75,11 +93,15 @@ static Result refuseWhenRequestCannotBeFulfilled( static Result refuseWhenRequestTypeIsNotAllowedForItem( RequestAndRelatedRecords requestAndRelatedRecords) { + log.debug("refuseWhenRequestTypeIsNotAllowedForItem:: parameters requestAndRelatedRecords: {}", + () -> requestAndRelatedRecords); Request request = requestAndRelatedRecords.getRequest(); if (request.getItem().isNotFound() || request.allowedForItem()) { return succeeded(requestAndRelatedRecords); } else { + log.error("refuseWhenRequestTypeIsNotAllowedForItem:: {} is not allowed for item {}", + request.getRequestType(), request.getItem().getItemId()); return failureDisallowedForRequestType(request.getRequestType()); } } @@ -101,9 +123,11 @@ static Result refuseWhenInvalidUserAndPatronGroup( User requester = request.getRequester(); if (requester == null) { + log.error("refuseWhenInvalidUserAndPatronGroup:: user {} is null", request.getUserId()); return failedValidation("A valid user and patron group are required. User is null", "userId", request.getUserId()); } else if (requester.getPatronGroupId() == null) { + log.error("refuseWhenInvalidUserAndPatronGroup:: patronGroup is null"); return failedValidation("A valid patron group is required. PatronGroup ID is null", "PatronGroupId", null); } else { return succeeded(requestAndRelatedRecords); @@ -113,6 +137,8 @@ static Result refuseWhenInvalidUserAndPatronGroup( static Result refuseWhenUserIsInactive( RequestAndRelatedRecords requestAndRelatedRecords) { + log.debug("refuseWhenUserIsInactive:: parameters requestAndRelatedRecords: {}", + () -> requestAndRelatedRecords); Request request = requestAndRelatedRecords.getRequest(); User requester = request.getRequester(); @@ -123,7 +149,7 @@ static Result refuseWhenUserIsInactive( parameters.put(ITEM_ID, request.getItemId()); String message = "Inactive users cannot make requests"; - + log.warn("refuseWhenUserIsInactive:: user {} is inactive", requester.getId()); return failedValidation(new ValidationError(message, parameters)); } else { return of(() -> requestAndRelatedRecords); @@ -133,15 +159,18 @@ static Result refuseWhenUserIsInactive( static Result refuseWhenMovedToDifferentInstance( RequestAndRelatedRecords requestAndRelatedRecords) { + log.debug("refuseWhenMovedToDifferentInstance:: parameters requestAndRelatedRecords: {}", + () -> requestAndRelatedRecords); Request request = requestAndRelatedRecords.getRequest(); Item item = request.getItem(); if (!Objects.equals(item.getInstanceId(), request.getInstanceId())) { HashMap parameters = new HashMap<>(); parameters.put(ITEM_ID, request.getItemId()); parameters.put(INSTANCE_ID, item.getInstanceId()); - return failedValidation( - new ValidationError("Request can only be moved to an item with the same instance ID", - parameters)); + String message = "Request can only be moved to an item with the same instance ID"; + log.warn("refuseWhenMovedToDifferentInstance:: requested instance ID {}" + + "does not match item's instance ID {}", request.getInstanceId(), item.getInstanceId()); + return failedValidation(new ValidationError(message, parameters)); } return succeeded(requestAndRelatedRecords); @@ -150,10 +179,13 @@ static Result refuseWhenMovedToDifferentInstance( static Result refuseTlrProcessingWhenFeatureIsDisabled( RequestAndRelatedRecords requestAndRelatedRecords) { + log.debug("refuseTlrProcessingWhenFeatureIsDisabled:: parameters requestAndRelatedRecords: {}", + () -> requestAndRelatedRecords); Request request = requestAndRelatedRecords.getRequest(); if (!requestAndRelatedRecords.isTlrFeatureEnabled() && request.isTitleLevel()) { - return failedValidation(new ValidationError("Can not process TLR - TLR feature is disabled", - REQUEST_ID, request.getId())); + String message = "Can not process TLR - TLR feature is disabled"; + log.warn("refuseTlrProcessingWhenFeatureIsDisabled:: {}", message); + return failedValidation(new ValidationError(message, REQUEST_ID, request.getId())); } return succeeded(requestAndRelatedRecords); @@ -162,12 +194,16 @@ static Result refuseTlrProcessingWhenFeatureIsDisabled static Result refuseMovingToOrFromHoldTlr( RequestAndRelatedRecords requestAndRelatedRecords, Request originalRequest) { + log.debug("refuseMovingToOrFromHoldTlr:: parameters requestAndRelatedRecords: {}, " + + "originalRequest: {}", requestAndRelatedRecords, originalRequest); Request request = requestAndRelatedRecords.getRequest(); if ((request.isHold() && request.isTitleLevel()) || (originalRequest.isHold() && originalRequest.isTitleLevel())) { - return failedValidation(new ValidationError("Not allowed to move from/to Hold TLR", - REQUEST_ID, request.getId())); + String message = "Not allowed to move from/to Hold TLR"; + log.warn("refuseMovingToOrFromHoldTlr:: {}", message); + + return failedValidation(new ValidationError(message, REQUEST_ID, request.getId())); } return succeeded(requestAndRelatedRecords); @@ -176,6 +212,9 @@ static Result refuseMovingToOrFromHoldTlr( static Result refuseWhenAlreadyRequested( RequestAndRelatedRecords requestAndRelatedRecords) { + log.debug("refuseWhenAlreadyRequested:: parameters requestAndRelatedRecords: {}", + () -> requestAndRelatedRecords); + return requestAndRelatedRecords.getRequestQueue().getRequests().stream() .filter(isAlreadyRequested(requestAndRelatedRecords)) .findFirst() @@ -184,6 +223,7 @@ static Result refuseWhenAlreadyRequested( } private static Predicate isAlreadyRequested(RequestAndRelatedRecords records) { + log.debug("isAlreadyRequested:: parameters records: {}", () -> records); Request request = records.getRequest(); if (records.isTlrFeatureEnabled() && request.isTitleLevel()) { return req -> { @@ -209,6 +249,8 @@ private static Predicate isAlreadyRequested(RequestAndRelatedRecords re private static Result alreadyRequestedFailure( RequestAndRelatedRecords requestAndRelatedRecords, Request existingRequest) { + log.debug("alreadyRequestedFailure:: parameters requestAndRelatedRecords: {}, " + + "existingRequest: {}", () -> requestAndRelatedRecords, () -> existingRequest); Request requestBeingPlaced = requestAndRelatedRecords.getRequest(); HashMap parameters = new HashMap<>(); String message; @@ -234,6 +276,7 @@ private static Result alreadyRequestedFailure( message = "This requester already has an open request for this item"; } + log.info("alreadyRequestedFailure:: message: {}", message); return failedValidation(message, parameters, ITEM_ALREADY_REQUESTED); } diff --git a/src/main/java/org/folio/circulation/domain/StoredRequestRepresentation.java b/src/main/java/org/folio/circulation/domain/StoredRequestRepresentation.java index 7cd931e44a..d023344a1c 100644 --- a/src/main/java/org/folio/circulation/domain/StoredRequestRepresentation.java +++ b/src/main/java/org/folio/circulation/domain/StoredRequestRepresentation.java @@ -18,6 +18,7 @@ public class StoredRequestRepresentation { private static final Logger log = LogManager.getLogger(MethodHandles.lookup().lookupClass()); public JsonObject storedRequest(Request request) { + log.debug("storedRequest:: parameters request: {}", () -> request); final JsonObject representation = request.asJson(); addStoredItemProperties(representation, request.getItem()); @@ -32,6 +33,8 @@ public JsonObject storedRequest(Request request) { } private static void addStoredItemProperties(JsonObject request, Item item) { + log.debug("addStoredItemProperties:: parameters request: {}, item: {}", + () -> request, () -> item); if (item == null || item.isNotFound()) { logUnableAddItemToTheRequest(request, item); return; @@ -101,6 +104,8 @@ private static JsonObject storedUserSummary(User user) { } private static void addSearchIndexProperties(JsonObject requestJson, Request request) { + log.debug("addSearchIndexProperties:: parameters requestJson: {}, request: {}", + () -> requestJson, () -> request); JsonObject searchIndex = new JsonObject(); if (request.hasItem()) { diff --git a/src/main/java/org/folio/circulation/domain/UpdateItem.java b/src/main/java/org/folio/circulation/domain/UpdateItem.java index 6175c35aac..9ba0caa300 100644 --- a/src/main/java/org/folio/circulation/domain/UpdateItem.java +++ b/src/main/java/org/folio/circulation/domain/UpdateItem.java @@ -10,12 +10,15 @@ import static org.folio.circulation.support.results.Result.ofAsync; import static org.folio.circulation.support.results.Result.succeeded; +import java.lang.invoke.MethodHandles; import java.time.ZonedDateTime; import java.util.Optional; import java.util.UUID; import java.util.concurrent.CompletableFuture; import java.util.function.Function; +import org.apache.logging.log4j.LogManager; +import org.apache.logging.log4j.Logger; import org.folio.circulation.infrastructure.storage.inventory.ItemRepository; import org.folio.circulation.services.RequestQueueService; import org.folio.circulation.support.results.Result; @@ -24,25 +27,32 @@ @AllArgsConstructor public class UpdateItem { + private static final Logger log = LogManager.getLogger(MethodHandles.lookup().lookupClass()); private final ItemRepository itemRepository; private final RequestQueueService requestQueueService; public CompletableFuture> onCheckIn(Item item, Request request, UUID checkInServicePointId, String loggedInUserId, ZonedDateTime dateTime) { + log.debug("onCheckIn:: parameters item: {}, request: {}, checkInServicePointId: {}, " + + "loggedInUserId: {}, dateTime: {}", () -> item, () -> request, () -> checkInServicePointId, + () -> loggedInUserId, () -> dateTime); + return changeItemOnCheckIn(item, request, checkInServicePointId) .next(addLastCheckInProperties(checkInServicePointId, loggedInUserId, dateTime)) .after(this::storeItem); } - private Function> addLastCheckInProperties( - UUID checkInServicePointId, String loggedInUserId, ZonedDateTime dateTime) { + private Function> addLastCheckInProperties(UUID checkInServicePointId, + String loggedInUserId, ZonedDateTime dateTime) { + return item -> succeeded(item.withLastCheckIn( new LastCheckIn(dateTime, checkInServicePointId, loggedInUserId))); } private Result changeItemOnCheckIn(Item item, Request request, UUID checkInServicePointId) { - + log.debug("changeItemOnCheckIn parameters item: {}, request: {}, checkInServicePointId: {}", + () -> item, () -> request, () -> checkInServicePointId); if (request != null) { return changeItemWithOutstandingRequest(item, request, checkInServicePointId); } else { @@ -60,6 +70,8 @@ private Result changeItemOnCheckIn(Item item, Request request, UUID checkI private Result changeItemWithOutstandingRequest(Item item, Request request, UUID checkInServicePointId) { + log.debug("changeItemWithOutstandingRequest:: parameters item: {}, request: {}, " + + "checkInServicePointId: {}", () -> item, () -> request, () -> checkInServicePointId); Result itemResult; switch (request.getfulfillmentPreference()) { case HOLD_SHELF: @@ -81,6 +93,7 @@ private Result changeItemWithHoldRequest(Item item, UUID checkInServicePoi String pickupServicePointIdString = request.getPickupServicePointId(); if (pickupServicePointIdString == null) { + log.warn("changeItemWithHoldRequest:: pickupServicePointIdString is null"); return failedValidation( "Failed to check in item due to the highest priority " + "request missing a pickup service point", @@ -102,6 +115,7 @@ private Result changeItemWithDeliveryRequest(Item item, Request request) { public CompletableFuture> onLoanCreated( LoanAndRelatedRecords relatedRecords) { + log.debug("onLoanCreated:: parameters relatedRecords: {}", () -> relatedRecords); //Hack for creating returned loan - should distinguish further up the chain return succeeded(relatedRecords).after(when( records -> loanIsClosed(relatedRecords), UpdateItem::skip, @@ -111,17 +125,23 @@ public CompletableFuture> onLoanCreated( public CompletableFuture> onLoanUpdate( LoanAndRelatedRecords loanAndRelatedRecords) { + log.debug("onLoanUpdate:: parameters loanAndRelatedRecords: {}", + () -> loanAndRelatedRecords); + return onLoanUpdate(loanAndRelatedRecords.getLoan(), loanAndRelatedRecords.getRequestQueue()) .thenApply(itemResult -> itemResult.map(loanAndRelatedRecords::withItem)); } public CompletableFuture> onRequestDeletion(Request request) { + log.debug("onRequestDeletion:: parameters request: {}", () -> request); // Only page request changes item status to 'Paged' // Other request types (Hold and Recall) don't change item status, it stays 'Checked out' if (request.getRequestType() != null && request.getRequestType().isPage() && request.getItem() != null && PAGED.equals(request.getItem().getStatus())) { + log.info("onRequestDeletion:: updating item with Available status"); + return itemRepository.updateItem(request.getItem().changeStatus(AVAILABLE)) .thenApply(r -> r.map(item -> request)); } @@ -130,6 +150,8 @@ public CompletableFuture> onRequestDeletion(Request request) { } private CompletableFuture> onLoanUpdate(Loan loan, RequestQueue requestQueue) { + log.debug("onLoanUpdate parameters loan: {}, requestQueue: {}", () -> loan, + () -> requestQueue); return itemStatusOnLoanUpdate(loan, requestQueue) .thenCompose(r -> r.after(prospectiveStatus -> updateItemWhenNotSameStatus(prospectiveStatus, loan.getItem()))); @@ -138,6 +160,9 @@ private CompletableFuture> onLoanUpdate(Loan loan, RequestQueue req CompletableFuture> onRequestCreateOrUpdate( RequestAndRelatedRecords requestAndRelatedRecords) { + log.debug("onRequestCreateOrUpdate:: parameters requestAndRelatedRecords: {}", + () -> requestAndRelatedRecords); + return of(() -> itemStatusOnRequestCreateOrUpdate(requestAndRelatedRecords)) .after(prospectiveStatus -> updateItemWhenNotSameStatus(prospectiveStatus, requestAndRelatedRecords.getRequest().getItem())) diff --git a/src/main/java/org/folio/circulation/domain/UpdateLoan.java b/src/main/java/org/folio/circulation/domain/UpdateLoan.java index 9464a852a9..6b746936a6 100644 --- a/src/main/java/org/folio/circulation/domain/UpdateLoan.java +++ b/src/main/java/org/folio/circulation/domain/UpdateLoan.java @@ -4,8 +4,11 @@ import static org.folio.circulation.support.results.Result.of; import static org.folio.circulation.support.results.Result.succeeded; +import java.lang.invoke.MethodHandles; import java.util.concurrent.CompletableFuture; +import org.apache.logging.log4j.LogManager; +import org.apache.logging.log4j.Logger; import org.folio.circulation.domain.notice.schedule.LoanScheduledNoticeService; import org.folio.circulation.domain.policy.LoanPolicy; import org.folio.circulation.domain.policy.library.ClosedLibraryStrategyService; @@ -16,14 +19,15 @@ import org.folio.circulation.support.utils.ClockUtil; public class UpdateLoan { + private static final Logger log = LogManager.getLogger(MethodHandles.lookup().lookupClass()); private final ClosedLibraryStrategyService closedLibraryStrategyService; private final LoanRepository loanRepository; private final LoanPolicyRepository loanPolicyRepository; private final LoanScheduledNoticeService scheduledNoticeService; - public UpdateLoan(Clients clients, - LoanRepository loanRepository, - LoanPolicyRepository loanPolicyRepository) { + public UpdateLoan(Clients clients, LoanRepository loanRepository, + LoanPolicyRepository loanPolicyRepository) { + closedLibraryStrategyService = ClosedLibraryStrategyService.using(clients, ClockUtil.getZonedDateTime(), false); this.loanPolicyRepository = loanPolicyRepository; @@ -40,8 +44,10 @@ public UpdateLoan(Clients clients, * @return the request and related records with the possibly updated loan. */ CompletableFuture> onRequestCreateOrUpdate( - RequestAndRelatedRecords requestAndRelatedRecords) { + RequestAndRelatedRecords requestAndRelatedRecords) { + log.debug("onRequestCreateOrUpdate:: parameters requestAndRelatedRecords: {}", + () -> requestAndRelatedRecords); Request request = requestAndRelatedRecords.getRequest(); Loan loan = request.getLoan(); @@ -56,7 +62,9 @@ CompletableFuture> onRequestCreateOrUpdate( } } - private Result updateLoanAction(LoanAndRelatedRecords loanAndRelatedRecords, Request request) { + private Result updateLoanAction( + LoanAndRelatedRecords loanAndRelatedRecords, Request request) { + Loan loan = loanAndRelatedRecords.getLoan(); LoanAction action = request.actionOnCreateOrUpdate(); @@ -70,7 +78,10 @@ private Result updateLoanAction(LoanAndRelatedRecords loa } private CompletableFuture> recall(Loan loan, - RequestAndRelatedRecords requestAndRelatedRecords, Request request) { + RequestAndRelatedRecords requestAndRelatedRecords, Request request) { + + log.debug("recall:: parameters loan: {}, requestAndRelatedRecords: {}, request: {}", + () -> loan, () -> requestAndRelatedRecords, () -> request); if (loan.wasDueDateChangedByRecall()) { // We don't need to apply the recall return completedFuture(succeeded(requestAndRelatedRecords)); @@ -95,6 +106,6 @@ private Result recall(LoanAndRelatedRecords loanAndRelate // loanPolicy.recall is a public method and may be called outside of the context of the // loan.wasDueDateChangedByRecall() condition found in the recall method of this class. return loanPolicy.recall(loan) - .map(loanAndRelatedRecords::withLoan); + .map(loanAndRelatedRecords::withLoan); } } diff --git a/src/main/java/org/folio/circulation/domain/UpdateRequestQueue.java b/src/main/java/org/folio/circulation/domain/UpdateRequestQueue.java index dc8660dfff..261c4c8898 100644 --- a/src/main/java/org/folio/circulation/domain/UpdateRequestQueue.java +++ b/src/main/java/org/folio/circulation/domain/UpdateRequestQueue.java @@ -67,6 +67,8 @@ requestRepository, new ServicePointRepository(clients), new ConfigurationReposit public CompletableFuture> onCheckIn( LoanAndRelatedRecords relatedRecords) { + log.debug("onCheckIn:: parameters relatedRecords: {}", () -> relatedRecords); + //Do not attempt check in for open loan if(relatedRecords.getLoan().isOpen()) { return ofAsync(() -> relatedRecords); @@ -83,6 +85,9 @@ public CompletableFuture> onCheckIn( public CompletableFuture> onCheckIn( RequestQueue requestQueue, Item item, String checkInServicePointId) { + log.debug("onCheckIn:: parameters requestQueue: {}, item: {}, checkInServicePointId: {}", + () -> requestQueue, () -> item, () -> checkInServicePointId); + return requestQueueService.findRequestFulfillableByItem(item, requestQueue) .thenCompose(r -> r.after(request -> updateOutstandingRequestOnCheckIn( request, requestQueue, item, checkInServicePointId))); @@ -99,7 +104,8 @@ private CompletableFuture> updateOutstandingRequestOnCheckI if (requestBeingFulfilled.getItemId() == null || !requestBeingFulfilled.isFor(item)) { requestBeingFulfilled = requestBeingFulfilled.withItem(item); - + log.info("updateOutstandingRequestOnCheckIn:: replacing request in the queue because " + + "another instance of it has been created"); // Replacing request in the queue because another instance of it has been created requestQueue.replaceRequest(requestBeingFulfilled); } @@ -110,18 +116,18 @@ private CompletableFuture> updateOutstandingRequestOnCheckI CompletableFuture> updatedReq; - log.info("updateOutstandingRequestOnCheckIn :: preference:{} ", + log.info("updateOutstandingRequestOnCheckIn:: preference:{} ", requestBeingFulfilled.getfulfillmentPreference()); - log.info("updateOutstandingRequestOnCheckIn :: requestBeingFulfilled.pickupServicePointId:{} ", + log.info("updateOutstandingRequestOnCheckIn:: requestBeingFulfilled.pickupServicePointId:{} ", requestBeingFulfilled.getPickupServicePointId()); switch (requestBeingFulfilled.getfulfillmentPreference()) { case HOLD_SHELF: if (checkInServicePointId.equalsIgnoreCase(requestBeingFulfilled.getPickupServicePointId())) { - log.info("updateOutstandingRequestOnCheckIn :: Updating to awaitingPickUp"); + log.info("updateOutstandingRequestOnCheckIn:: Updating to awaitingPickUp"); return awaitPickup(requestBeingFulfilled,requestQueue); } else { - log.info("updateOutstandingRequestOnCheckIn :: Updating to inTransit"); + log.info("updateOutstandingRequestOnCheckIn:: Updating to inTransit"); updatedReq = putInTransit(requestBeingFulfilled); } @@ -142,11 +148,16 @@ private CompletableFuture> updateOutstandingRequestOnCheckI .thenComposeAsync(result -> result.after(v -> requestQueueRepository.updateRequestsWithChangedPositions(requestQueue))); } - private CompletableFuture> awaitPickup(Request request, RequestQueue requestQueue) { + private CompletableFuture> awaitPickup(Request request, + RequestQueue requestQueue) { + + log.debug("awaitPickup:: parameters request: {}, requestQueue: {}", + () -> request, () -> requestQueue); Request originalRequest = Request.from(request.asJson()); request.changeStatus(RequestStatus.OPEN_AWAITING_PICKUP); if (request.getHoldShelfExpirationDate() == null) { + log.info("awaitPickup:: holdShelfExpirationDate for request {} is null", request.getId()); String pickupServicePointId = request.getPickupServicePointId(); return servicePointRepository.getServicePointById(pickupServicePointId) @@ -167,12 +178,16 @@ private CompletableFuture> awaitPickup(Request request, Req } } - private RequestQueue setHoldShelfExpirationDateWithExpirationDateManagement(ZoneId tenantTimeZone, Request calculatedRequest, - RequestQueue requestQueue, Request originalRequest) { + private RequestQueue setHoldShelfExpirationDateWithExpirationDateManagement( + ZoneId tenantTimeZone, Request calculatedRequest, RequestQueue requestQueue, + Request originalRequest) { - ExpirationDateManagement expirationDateManagement = calculatedRequest.getPickupServicePoint().getHoldShelfClosedLibraryDateManagement(); - String intervalId = calculatedRequest.getPickupServicePoint().getHoldShelfExpiryPeriod().getIntervalId().toUpperCase(); - log.info("setHoldShelfExpirationDateWithExpirationDateManagement expDate before:{}",calculatedRequest.getHoldShelfExpirationDate()); + ExpirationDateManagement expirationDateManagement = calculatedRequest.getPickupServicePoint() + .getHoldShelfClosedLibraryDateManagement(); + String intervalId = calculatedRequest.getPickupServicePoint().getHoldShelfExpiryPeriod() + .getIntervalId().toUpperCase(); + log.info("setHoldShelfExpirationDateWithExpirationDateManagement expDate before:{}", + calculatedRequest.getHoldShelfExpirationDate()); // Old data where strategy is not set so default value but TimePeriod has MINUTES / HOURS if (ExpirationDateManagement.KEEP_THE_CURRENT_DUE_DATE == expirationDateManagement && isShortTerm(intervalId)) { expirationDateManagement = ExpirationDateManagement.KEEP_THE_CURRENT_DUE_DATE_TIME; @@ -214,17 +229,15 @@ private CompletableFuture> awaitDelivery(Request request) { } private Result populateHoldShelfExpirationDate(Request request, ZoneId tenantTimeZone) { + log.debug("populateHoldShelfExpirationDate:: parameters request: {}, tenantTimeZone: {}", + () -> request, () -> tenantTimeZone); ServicePoint pickupServicePoint = request.getPickupServicePoint(); TimePeriod holdShelfExpiryPeriod = pickupServicePoint.getHoldShelfExpiryPeriod(); - log.debug("Using time zone {} and period {}", - tenantTimeZone, - holdShelfExpiryPeriod.getInterval() - ); - - ZonedDateTime holdShelfExpirationDate = - calculateHoldShelfExpirationDate(holdShelfExpiryPeriod, tenantTimeZone); - + log.debug("populateHoldShelfExpirationDate:: using time zone {} and period {}", + () -> tenantTimeZone, holdShelfExpiryPeriod::getInterval); + ZonedDateTime holdShelfExpirationDate = calculateHoldShelfExpirationDate( + holdShelfExpiryPeriod, tenantTimeZone); request.changeHoldShelfExpirationDate(holdShelfExpirationDate); return succeeded(request); @@ -238,17 +251,20 @@ public CompletableFuture> onCheckOut(LoanAndRelate public CompletableFuture> onCheckOut( LoanAndRelatedRecords relatedRecords, Request firstRequest) { + log.debug("onCheckOut:: parameters relatedRecords: {}, firstRequest: {}", + () -> relatedRecords, () -> firstRequest); if (firstRequest == null) { + log.info("onCheckOut:: first request is null"); return completedFuture(succeeded(relatedRecords)); } RequestQueue requestQueue = relatedRecords.getRequestQueue(); Request originalRequest = Request.from(firstRequest.asJson()); - log.info("Closing request '{}'", firstRequest.getId()); + log.info("onCheckOut:: Closing request '{}'", firstRequest.getId()); firstRequest.changeStatus(RequestStatus.CLOSED_FILLED); - log.info("Removing request '{}' from queue", firstRequest.getId()); + log.info("onCheckOut:: Removing request '{}' from queue", firstRequest.getId()); requestQueue.remove(firstRequest); Request updatedRequest = Request.from(firstRequest.asJson()); @@ -264,16 +280,23 @@ public CompletableFuture> onCheckOut( CompletableFuture> onCreate( RequestAndRelatedRecords requestAndRelatedRecords) { + + log.debug("onCreate:: parameters requestAndRelatedRecords: {}", () -> requestAndRelatedRecords); final Request request = requestAndRelatedRecords.getRequest(); final RequestQueue requestQueue = requestAndRelatedRecords.getRequestQueue(); requestQueue.add(request); + return requestQueueRepository.updateRequestsWithChangedPositions(requestQueue) .thenApply(r -> r.map(requestAndRelatedRecords::withRequestQueue)); } CompletableFuture> onCancellation( RequestAndRelatedRecords requestAndRelatedRecords) { + + log.debug("onCancellation:: parameters requestAndRelatedRecords: {}", + () -> requestAndRelatedRecords); if(requestAndRelatedRecords.getRequest().isCancelled()) { + log.info("onCancellation:: request is cancelled"); return requestQueueRepository.updateRequestsWithChangedPositions( requestAndRelatedRecords.getRequestQueue()) .thenApply(r -> r.map(requestAndRelatedRecords::withRequestQueue)); @@ -286,10 +309,13 @@ CompletableFuture> onCancellation( CompletableFuture> onMovedFrom( RequestAndRelatedRecords requestAndRelatedRecords) { + log.debug("onMovedFrom:: parameters requestAndRelatedRecords: {}", + () -> requestAndRelatedRecords); final Request request = requestAndRelatedRecords.getRequest(); if (requestAndRelatedRecords.getSourceItemId().equals(request.getItemId()) && !requestAndRelatedRecords.isTlrFeatureEnabled()) { + log.info("onMovedFrom:: removing request from the requestQueue"); final RequestQueue requestQueue = requestAndRelatedRecords.getRequestQueue(); requestQueue.remove(request); return requestQueueRepository.updateRequestsWithChangedPositions(requestQueue) @@ -302,11 +328,15 @@ CompletableFuture> onMovedFrom( CompletableFuture> onMovedTo( RequestAndRelatedRecords requestAndRelatedRecords) { + + log.debug("onMovedTo:: parameters requestAndRelatedRecords: {}", + () -> requestAndRelatedRecords); final Request request = requestAndRelatedRecords.getRequest(); if (requestAndRelatedRecords.getDestinationItemId().equals(request.getItemId())) { final RequestQueue requestQueue = requestAndRelatedRecords.getRequestQueue(); // NOTE: it is important to remove position when moving request from one queue to another if (requestAndRelatedRecords.isTlrFeatureEnabled()) { + log.info("onMovedTo:: removing request from the requestQueue"); requestQueue.remove(request); } request.removePosition(); @@ -320,6 +350,8 @@ CompletableFuture> onMovedTo( } public CompletableFuture> onDeletion(Request request) { + log.debug("onDeletion:: parameters request: {}", () -> request); + return requestQueueRepository.getByItemId(request.getItemId()) .thenApply(r -> r.map(requestQueue -> { requestQueue.remove(request); @@ -365,6 +397,7 @@ private ZonedDateTime calculateHoldShelfExpirationDate( ZonedDateTime holdShelfExpirationDate = holdShelfExpiryPeriod.getInterval() .addTo(now, holdShelfExpiryPeriod.getDuration()); if (holdShelfExpiryPeriod.isLongTermPeriod()) { + log.info("calculateHoldShelfExpirationDate:: holdShelfExpiryPeriod is long term"); holdShelfExpirationDate = atEndOfDay(holdShelfExpirationDate); } diff --git a/src/main/java/org/folio/circulation/domain/UpdateRequestService.java b/src/main/java/org/folio/circulation/domain/UpdateRequestService.java index 76b760743c..31b43446aa 100644 --- a/src/main/java/org/folio/circulation/domain/UpdateRequestService.java +++ b/src/main/java/org/folio/circulation/domain/UpdateRequestService.java @@ -4,9 +4,12 @@ import static org.folio.circulation.support.ValidationErrorFailure.singleValidationError; import static org.folio.circulation.support.results.Result.succeeded; +import java.lang.invoke.MethodHandles; import java.util.Objects; import java.util.concurrent.CompletableFuture; +import org.apache.logging.log4j.LogManager; +import org.apache.logging.log4j.Logger; import org.folio.circulation.domain.validation.ClosedRequestValidator; import org.folio.circulation.infrastructure.storage.requests.RequestRepository; import org.folio.circulation.resources.RequestNoticeSender; @@ -14,6 +17,7 @@ import org.folio.circulation.support.results.Result; public class UpdateRequestService { + private final Logger log = LogManager.getLogger(MethodHandles.lookup().lookupClass()); private final RequestRepository requestRepository; private final UpdateRequestQueue updateRequestQueue; private final ClosedRequestValidator closedRequestValidator; @@ -36,6 +40,8 @@ public UpdateRequestService(RequestRepository requestRepository, public CompletableFuture> replaceRequest( RequestAndRelatedRecords requestAndRelatedRecords) { + log.debug("replaceRequest:: parameters requestAndRelatedRecords: {}", + () -> requestAndRelatedRecords); Request updated = requestAndRelatedRecords.getRequest(); return requestRepository.getById(updated.getId()) @@ -65,6 +71,8 @@ private Result removeRequestQueuePositionWhenCancelled final Request request = requestAndRelatedRecords.getRequest(); if(request.isCancelled()) { + log.info("removeRequestQueuePositionWhenCancelled:: request {} is cancelled, " + + "removing from the request queue", request.getId()); requestAndRelatedRecords.getRequestQueue().remove(request); } diff --git a/src/main/java/org/folio/circulation/support/http/client/Response.java b/src/main/java/org/folio/circulation/support/http/client/Response.java index cfe7681e3f..b6eb1a7564 100644 --- a/src/main/java/org/folio/circulation/support/http/client/Response.java +++ b/src/main/java/org/folio/circulation/support/http/client/Response.java @@ -3,13 +3,14 @@ import static io.vertx.core.MultiMap.caseInsensitiveMultiMap; import static java.lang.String.format; +import org.apache.commons.lang3.StringUtils; +import org.folio.circulation.support.http.ContentType; + import io.vertx.core.MultiMap; import io.vertx.core.buffer.Buffer; import io.vertx.core.json.JsonObject; import io.vertx.ext.web.client.HttpResponse; import lombok.val; -import org.apache.commons.lang3.StringUtils; -import org.folio.circulation.support.http.ContentType; public class Response { protected final String body;