From 63bbc5e1ddb6e4ffa65841371f1a38fe237033f3 Mon Sep 17 00:00:00 2001 From: Konrad Windszus Date: Mon, 10 Jun 2024 20:57:09 +0200 Subject: [PATCH] Improve error logging of UMAPI Log request with payload in case of warnings/errors Always include group to be synchronized in verbose log Improve retry interval --- .../AuthorizableInstallerServiceImpl.java | 1 + .../tools/actool/ims/IMSUserManagement.java | 47 +++++++++++++++---- .../ims/response/ActionCommandResponse.java | 6 +++ .../tools/actool/ims/IMSUserManagementIT.java | 1 - 4 files changed, 45 insertions(+), 10 deletions(-) diff --git a/accesscontroltool-bundle/src/main/java/biz/netcentric/cq/tools/actool/authorizableinstaller/impl/AuthorizableInstallerServiceImpl.java b/accesscontroltool-bundle/src/main/java/biz/netcentric/cq/tools/actool/authorizableinstaller/impl/AuthorizableInstallerServiceImpl.java index 806e1239..729192d1 100644 --- a/accesscontroltool-bundle/src/main/java/biz/netcentric/cq/tools/actool/authorizableinstaller/impl/AuthorizableInstallerServiceImpl.java +++ b/accesscontroltool-bundle/src/main/java/biz/netcentric/cq/tools/actool/authorizableinstaller/impl/AuthorizableInstallerServiceImpl.java @@ -125,6 +125,7 @@ public void installAuthorizables( authorizableConfigBean, installLog, authorizablesFromConfigurations); if (authorizableConfigBean.isExternalSync() && authorizableConfigBean.isGroup() && !externalGroupManagementServices.isEmpty()) { + installLog.addVerboseMessage(LOG, "Synchronizing external group with id " + authorizableConfigBean.getAuthorizableId() + " and description " + authorizableConfigBean.getDescription()); groupsToSyncWithExternalUserMgmt.add(authorizableConfigBean); } } diff --git a/accesscontroltool-bundle/src/main/java/biz/netcentric/cq/tools/actool/ims/IMSUserManagement.java b/accesscontroltool-bundle/src/main/java/biz/netcentric/cq/tools/actool/ims/IMSUserManagement.java index 57034866..820576b3 100644 --- a/accesscontroltool-bundle/src/main/java/biz/netcentric/cq/tools/actool/ims/IMSUserManagement.java +++ b/accesscontroltool-bundle/src/main/java/biz/netcentric/cq/tools/actool/ims/IMSUserManagement.java @@ -1,5 +1,6 @@ package biz.netcentric.cq.tools.actool.ims; +import java.io.ByteArrayOutputStream; import java.io.IOException; import java.io.InputStreamReader; import java.io.Reader; @@ -10,12 +11,15 @@ import java.util.Collection; import java.util.LinkedList; import java.util.List; +import java.util.Random; import java.util.concurrent.atomic.AtomicInteger; import java.util.stream.Collectors; import org.apache.http.Consts; import org.apache.http.Header; import org.apache.http.HttpEntity; +import org.apache.http.HttpEntityEnclosingRequest; +import org.apache.http.HttpRequest; import org.apache.http.HttpResponse; import org.apache.http.NameValuePair; import org.apache.http.StatusLine; @@ -103,31 +107,38 @@ public class IMSUserManagement implements ExternalGroupManagement { static final class TooManyRequestsRetryStrategy implements ServiceUnavailableRetryStrategy { private final int maxRetryCount; private final int defaultRetryDelayInSeconds; - private int retryDelayInSeconds; + private long retryDelayInMilliseconds; + private final Random random = new Random(); public TooManyRequestsRetryStrategy(int maxRetryCount, int defaultRetryDelayInSeconds) { super(); this.maxRetryCount = maxRetryCount; this.defaultRetryDelayInSeconds = defaultRetryDelayInSeconds; - retryDelayInSeconds = defaultRetryDelayInSeconds; + this.retryDelayInMilliseconds = defaultRetryDelayInSeconds * 1000l; } @Override public boolean retryRequest(HttpResponse response, int executionCount, HttpContext context) { - retryDelayInSeconds = defaultRetryDelayInSeconds; + retryDelayInMilliseconds = defaultRetryDelayInSeconds * 1000l; boolean shouldRetry = (executionCount <= maxRetryCount && response.getStatusLine().getStatusCode() == 429); if (shouldRetry) { Header retryAfterHeader = response.getFirstHeader("Retry-After"); if (retryAfterHeader != null) { - retryDelayInSeconds = Integer.parseInt(retryAfterHeader.getValue()); + // just using the retry-after as is does not work reliably (due to potential concurrent requests) + retryDelayInMilliseconds = Integer.parseInt(retryAfterHeader.getValue()) * 1000l; + LOG.info("Received 429 status with Retry-After header {}", retryDelayInMilliseconds / 1000l); } + // always add some jitter between 0 and 5 seconds + long jitter= random.nextInt(5) * 1000l; + retryDelayInMilliseconds += jitter; + LOG.info("Schedule retry no {} of {} in {} milliseconds (with jitter of {} ms) due to 429 response", executionCount, maxRetryCount, retryDelayInMilliseconds, jitter); } return shouldRetry; } @Override public long getRetryInterval() { - return retryDelayInSeconds * 1000l; + return retryDelayInMilliseconds; } } @@ -182,14 +193,30 @@ public void updateGroups(Collection groupConfigs) throws for (List actionCommandBatch : actionCommandsBatches) { ActionCommandResponse response = sendActionCommand(token, actionCommandBatch); if (!response.errors.isEmpty()) { - throw new IOException("Errors updating groups: " + response.errors); + throw new IOException("Errors updating groups: " + response.errors + " for request " + getRequestInfo(response.associatedRequest)); } if (!response.warnings.isEmpty()) { + LOG.warn("Some warnings during updating groups with request {}", getRequestInfo(response.associatedRequest)); response.warnings.stream().forEach(w -> LOG.warn("Warning updating a group: {}", w)); } } } + static String getRequestInfo(HttpRequest request) throws IOException { + if (request == null) { + return "Unknown"; + } + StringBuilder requestInfo = new StringBuilder(); + requestInfo.append(request); + if (request instanceof HttpEntityEnclosingRequest) { + HttpEntity entity = ((HttpEntityEnclosingRequest) request).getEntity(); + ByteArrayOutputStream bs = new ByteArrayOutputStream(); + entity.writeTo(bs); + requestInfo.append("\nwith payload:\n").append(new String(bs.toByteArray())); + } + return requestInfo.toString(); + } + private ActionCommandResponse sendActionCommand(String token, Collection actions) throws IOException { ObjectMapper objectMapper = new ObjectMapper(); HttpPost httpPost; @@ -211,12 +238,14 @@ public ActionCommandResponse handleResponse( if (statusLine.getStatusCode() >= 300) { throw new HttpResponseException( statusLine.getStatusCode(), - statusLine.getReasonPhrase() + ", body:" + EntityUtils.toString(entity)); + statusLine.getReasonPhrase() + ", body:" + EntityUtils.toString(entity) + ", for request " + getRequestInfo(httpPost)); } if (entity == null) { - throw new ClientProtocolException("Response contains no content"); + throw new ClientProtocolException("Response contains no content for request" + getRequestInfo(httpPost)); } - return objectMapper.readValue(entity.getContent(), ActionCommandResponse.class); + ActionCommandResponse actionCommandResponse = objectMapper.readValue(entity.getContent(), ActionCommandResponse.class); + actionCommandResponse.associatedRequest = httpPost; + return actionCommandResponse; } }; LOG.debug("Calling UMAPI via {}", httpPost); diff --git a/accesscontroltool-bundle/src/main/java/biz/netcentric/cq/tools/actool/ims/response/ActionCommandResponse.java b/accesscontroltool-bundle/src/main/java/biz/netcentric/cq/tools/actool/ims/response/ActionCommandResponse.java index 8decd976..244e9de0 100644 --- a/accesscontroltool-bundle/src/main/java/biz/netcentric/cq/tools/actool/ims/response/ActionCommandResponse.java +++ b/accesscontroltool-bundle/src/main/java/biz/netcentric/cq/tools/actool/ims/response/ActionCommandResponse.java @@ -3,6 +3,9 @@ import java.util.Collections; import java.util.List; +import org.apache.http.client.methods.HttpRequestBase; + +import com.fasterxml.jackson.annotation.JsonIgnore; import com.fasterxml.jackson.annotation.JsonIgnoreProperties; import com.fasterxml.jackson.annotation.JsonProperty; @@ -29,4 +32,7 @@ public ActionCommandResponse() { @JsonProperty("warnings") public List warnings; + + @JsonIgnore + public HttpRequestBase associatedRequest; } diff --git a/accesscontroltool-bundle/src/test/java/biz/netcentric/cq/tools/actool/ims/IMSUserManagementIT.java b/accesscontroltool-bundle/src/test/java/biz/netcentric/cq/tools/actool/ims/IMSUserManagementIT.java index c26bc9f2..0ae0ca56 100644 --- a/accesscontroltool-bundle/src/test/java/biz/netcentric/cq/tools/actool/ims/IMSUserManagementIT.java +++ b/accesscontroltool-bundle/src/test/java/biz/netcentric/cq/tools/actool/ims/IMSUserManagementIT.java @@ -13,7 +13,6 @@ import org.osgi.util.converter.Converters; import biz.netcentric.cq.tools.actool.configmodel.AuthorizableConfigBean; -import biz.netcentric.cq.tools.actool.ims.IMSUserManagement; import biz.netcentric.cq.tools.actool.ims.IMSUserManagement.Configuration; /**