Extension for version 6.7.0. Added logging for runtime of functions i…

…nside `pxVerify`

pom.xml

@@ -7,7 +7,7 @@
  <name>PerimeterX JAVA SDK</name>
  <groupId>com.perimeterx</groupId>
  <artifactId>perimeterx-sdk</artifactId>
- <version>6.7.0</version>
+ <version>6.7.0-rc-extended-logging</version>
 
  <packaging>jar</packaging>
  <description>PerimeterX Java SDK</description>

src/main/java/com/perimeterx/api/PerimeterX.java

@@ -69,6 +69,7 @@
 import java.util.Base64;
 
 import static com.perimeterx.utils.Constants.*;
+import static com.perimeterx.utils.PXCommonUtils.logTime;
 import static java.util.Objects.isNull;
 
 /**
@@ -155,49 +156,53 @@ public PerimeterX(PXConfiguration configuration, HostnameProvider hostnameProvid
  * @throws PXException - PXException
  */
  public PXContext pxVerify(HttpServletRequest req, HttpServletResponseWrapper responseWrapper) throws PXException {
- PXContext context = null;
- logger.debug(PXLogger.LogReason.DEBUG_STARTING_REQUEST_VERIFICATION);
-
- try {
- if (isValidTelemetryRequest(req)) {
- activityHandler.handleEnforcerTelemetryActivity(this.configuration, UpdateReason.COMMAND);
- return null;
- }
-
- if (!moduleEnabled()) {
- logger.debug(PXLogger.LogReason.DEBUG_MODULE_DISABLED);
- return null;
- }
-
- context = new PXContext(req, this.ipProvider, this.hostnameProvider, configuration);
+ return logTime("pxVerify", () -> {
+ PXContext context = null;
+ logger.debug(PXLogger.LogReason.DEBUG_STARTING_REQUEST_VERIFICATION);
+
+ try {
+ if (logTime("isValidTelemetryRequest", () -> isValidTelemetryRequest(req))) {
+ logTime("activityHandler.handleEnforcerTelemetryActivity", () -> activityHandler.handleEnforcerTelemetryActivity(this.configuration, UpdateReason.COMMAND));
+ return null;
+ }
 
- if (shouldReverseRequest(req, responseWrapper)) {
- context.setFirstPartyRequest(true);
- return context;
- }
+  if (!moduleEnabled()) {
+  logger.debug(PXLogger.LogReason.DEBUG_MODULE_DISABLED);
+  return null;
+  }
 
- //if path ext is defined at whitelist, let the request pass
- if (configuration.isExtWhiteListed(req.getRequestURI())) {
- return null;
- }
+ context = logTime("new PXContext", () -> new PXContext(req, this.ipProvider, this.hostnameProvider, configuration));
 
- handleCookies(context);
- addCustomHeadersToRequest(req, context);
+ if (logTime("shouldReverseRequest", () -> shouldReverseRequest(req, responseWrapper))) {
+ context.setFirstPartyRequest(true);
+ return context;
+ }
 
- context.setVerified(verificationHandler.handleVerification(context, responseWrapper));
- } catch (Exception e) {
- // If any general exception is being thrown, notify in page_request activity
- if (context != null) {
- if (!context.getS2sErrorReasonInfo().isErrorSet()) {
- EnforcerErrorUtils.handleEnforcerError(context, "Unexpected error", e);
+ //if path ext is defined at whitelist, let the request pass
+ if (configuration.isExtWhiteListed(req.getRequestURI())) {
+ return null;
  }
 
- activityHandler.handlePageRequestedActivity(context);
- context.setVerified(true);
+ final PXContext finalContext = context;
+ logTime("handleCookies", () -> handleCookies(finalContext));
+ logTime("addCustomHeadersToRequest", () -> addCustomHeadersToRequest(req, finalContext));
+
+ context.setVerified(logTime("verificationHandler.handleVerification", () -> verificationHandler.handleVerification(finalContext, responseWrapper)));
+ } catch (Exception e) {
+ final PXContext finalContext = context;
+ // If any general exception is being thrown, notify in page_request activity
+ if (context != null) {
+ if (!context.getS2sErrorReasonInfo().isErrorSet()) {
+ logTime("EnforcerErrorUtils.handleEnforcerError", () -> EnforcerErrorUtils.handleEnforcerError(finalContext, "Unexpected error", e));
+ }
+
+ logTime("activityHandler.handlePageRequestedActivity", () -> activityHandler.handlePageRequestedActivity(finalContext));
+ context.setVerified(true);
+ }
  }
- }
 
- return context;
+ return context;
+ });
  }
 
  private boolean moduleEnabled() {
@@ -339,7 +344,7 @@ public void setVerificationHandler(VerificationHandler verificationHandler) {
 
  @Override
  public void close() throws IOException {
- if(this.pxClient != null) {
+ if (this.pxClient != null) {
  this.pxClient.close();
  }
  }

src/main/java/com/perimeterx/api/activities/BufferedActivityHandler.java

@@ -14,6 +14,7 @@
 import java.util.concurrent.atomic.AtomicInteger;
 import java.util.concurrent.locks.ReentrantLock;
 
+import static com.perimeterx.utils.PXCommonUtils.logTime;
 import static com.perimeterx.utils.PXLogger.LogReason.ERROR_TELEMETRY_EXCEPTION;
 
 
@@ -39,41 +40,53 @@ public BufferedActivityHandler(PXClient client, PXConfiguration configuration) {
 
  @Override
  public void handleBlockActivity(PXContext context) throws PXException {
- Activity activity = ActivityFactory.createActivity(Constants.ACTIVITY_BLOCKED, configuration.getAppId(), context);
- handleSendActivities(activity);
+ logTime("handleBlockActivity", () -> {
+ Activity activity = ActivityFactory.createActivity(Constants.ACTIVITY_BLOCKED, configuration.getAppId(), context);
+ handleSendActivities(activity);
+ });
+
  }
 
  @Override
  public void handlePageRequestedActivity(PXContext context) throws PXException {
- Activity activity = ActivityFactory.createActivity(Constants.ACTIVITY_PAGE_REQUESTED, configuration.getAppId(), context);
- handleSendActivities(activity);
+ logTime("handlePageRequestedActivity", () -> {
+ Activity activity = ActivityFactory.createActivity(Constants.ACTIVITY_PAGE_REQUESTED, configuration.getAppId(), context);
+ handleSendActivities(activity);
+ });
+
  }
 
  @Override
  public void handleEnforcerTelemetryActivity(PXConfiguration pxConfig, UpdateReason updateReason) throws PXException {
- try {
- EnforcerTelemetryActivityDetails details = new EnforcerTelemetryActivityDetails(pxConfig, updateReason);
- EnforcerTelemetry enforcerTelemetry = new EnforcerTelemetry("enforcer_telemetry", pxConfig.getAppId(), details);
- this.client.sendEnforcerTelemetry(enforcerTelemetry);
- } catch (IOException e) {
- throw new PXException(ERROR_TELEMETRY_EXCEPTION.toString(), e);
- }
+ logTime("handleEnforcerTelemetryActivity", () -> {
+ try {
+ EnforcerTelemetryActivityDetails details = new EnforcerTelemetryActivityDetails(pxConfig, updateReason);
+ EnforcerTelemetry enforcerTelemetry = new EnforcerTelemetry("enforcer_telemetry", pxConfig.getAppId(), details);
+ this.client.sendEnforcerTelemetry(enforcerTelemetry);
+ } catch (IOException e) {
+ throw new PXException(ERROR_TELEMETRY_EXCEPTION.toString(), e);
+ }
+ });
  }
 
  @Override
  public void handleAdditionalS2SActivity(PXContext context) throws PXException {
- final Activity activity = createAdditionalS2SActivity(context);
- handleSendActivities(activity);
+ logTime("handleAdditionalS2SActivity", () -> {
+ final Activity activity = createAdditionalS2SActivity(context);
+ handleSendActivities(activity);
+ });
  }
 
  public Activity createAdditionalS2SActivity(PXContext context) {
- final Activity activity = ActivityFactory.createActivity(Constants.ACTIVITY_ADDITIONAL_S2S, configuration.getAppId(), context);
+ return logTime("createAdditionalS2SActivity", () -> {
+ final Activity activity = ActivityFactory.createActivity(Constants.ACTIVITY_ADDITIONAL_S2S, configuration.getAppId(), context);
 
- if(isRequireRawUsername(context)) {
- ((AdditionalS2SActivityDetails) activity.getDetails())
- .setUsername(context.getLoginData().getLoginCredentials().getRawUsername());
- }
- return activity;
+ if (isRequireRawUsername(context)) {
+ ((AdditionalS2SActivityDetails) activity.getDetails())
+ .setUsername(context.getLoginData().getLoginCredentials().getRawUsername());
+ }
+ return activity;
+ });
  }
 
  private boolean isRequireRawUsername(PXContext context) {
@@ -85,37 +98,42 @@ private boolean isRequireRawUsername(PXContext context) {
  }
 
  private void handleSendActivities(Activity activity) throws PXException {
- bufferedActivities.add(activity);
- int count = counter.incrementAndGet();
- if (count > maxBufferLength) {
- handleOverflow();
- }
+ logTime("handleSendActivities", () -> {
+ bufferedActivities.add(activity);
+ int count = counter.incrementAndGet();
+ if (count > maxBufferLength) {
+ handleOverflow();
+ }
+ });
  }
 
  private void handleOverflow() throws PXException {
- ConcurrentLinkedQueue<Activity> activitiesToSend;
- if (lock.tryLock()) {
- try {
- activitiesToSend = flush();
- } finally {
- lock.unlock();
+ logTime("handleOverflow", () -> {
+ ConcurrentLinkedQueue<Activity> activitiesToSend;
+ if (lock.tryLock()) {
+ try {
+ activitiesToSend = flush();
+ } finally {
+ lock.unlock();
+ }
+ sendAsync(activitiesToSend);
  }
- sendAsync(activitiesToSend);
- }
+ });
  }
 
  private void sendAsync(ConcurrentLinkedQueue<Activity> activitiesToSend) throws PXException {
- if (activitiesToSend == null) {
- return;
- }
-
- List<Activity> activitiesLocal = activitiesAsList(activitiesToSend);
- try {
- client.sendBatchActivities(activitiesLocal);
- } catch (Exception e) {
- throw new PXException(e);
- }
+ logTime("sendAsync", () -> {
+ if (activitiesToSend == null) {
+ return;
+ }
 
+ List<Activity> activitiesLocal = activitiesAsList(activitiesToSend);
+ try {
+ client.sendBatchActivities(activitiesLocal);
+ } catch (Exception e) {
+ throw new PXException(e);
+ }
+ });
  }
 
  private List<Activity> activitiesAsList(ConcurrentLinkedQueue<Activity> activityQueue) {

src/main/java/com/perimeterx/api/verificationhandler/DefaultVerificationHandler.java

@@ -13,6 +13,7 @@
 import java.io.UnsupportedEncodingException;
 import java.net.URLEncoder;
 
+import static com.perimeterx.utils.PXCommonUtils.logTime;
 import static com.perimeterx.utils.PXLogger.LogReason.DEBUG_S2S_SCORE_IS_HIGHER_THAN_BLOCK;
 import static com.perimeterx.utils.PXLogger.LogReason.DEBUG_S2S_SCORE_IS_LOWER_THAN_BLOCK;
 
@@ -35,29 +36,31 @@ public DefaultVerificationHandler(PXConfiguration pxConfiguration, ActivityHandl
 
  @Override
  public boolean handleVerification(PXContext context, HttpServletResponseWrapper responseWrapper) throws PXException {
- boolean verified = shouldPassRequest(context);
+ boolean verified = logTime("shouldPassRequest", () -> shouldPassRequest(context));
 
- setPxhdCookie(context, responseWrapper);
+ logTime("setPxhdCookie", () -> setPxhdCookie(context, responseWrapper));
 
  if (!verified && !context.isMonitoredRequest()) {
- this.blockHandler.handleBlocking(context, this.pxConfiguration, responseWrapper);
+ logTime("blockHandler.handleBlocking",() -> this.blockHandler.handleBlocking(context, this.pxConfiguration, responseWrapper));
  }
 
- try {
- if (verified) {
- logger.debug("Passing request {} {}", verified, this.pxConfiguration.getModuleMode());
-
- // Not blocking request and sending page_requested activity to px if configured as true
- if (this.pxConfiguration.isSendPageActivities()) {
- this.activityHandler.handlePageRequestedActivity(context);
+ logTime("anonymousAsyncActivitiesSender" , () -> {
+ try {
+ if (verified) {
+ logger.debug("Passing request {} {}", verified, this.pxConfiguration.getModuleMode());
+
+ // Not blocking request and sending page_requested activity to px if configured as true
+ if (this.pxConfiguration.isSendPageActivities()) {
+ this.activityHandler.handlePageRequestedActivity(context);
+ }
+ } else {
+ logger.debug("Request invalid");
+ this.activityHandler.handleBlockActivity(context);
  }
- } else {
- logger.debug("Request invalid");
- this.activityHandler.handleBlockActivity(context);
+ } catch (PXException pxException) {
+ logger.error("Error occurred while handle activities", pxException);
  }
- } catch (PXException pxException) {
- logger.error("Error occurred while handle activities", pxException);
- }
+ });
 
  return verified || context.isMonitoredRequest();
  }

src/main/java/com/perimeterx/internals/PXCookieValidator.java

@@ -11,6 +11,8 @@
 import com.perimeterx.utils.PXLogger;
 import org.apache.commons.lang3.StringUtils;
 
+import static com.perimeterx.utils.PXCommonUtils.logTime;
+
 /**
  * PXCookieValidator
  * <p>
@@ -40,7 +42,7 @@ public boolean verify(PXContext context) {
  if (context.isMobileToken()) {
  PXCookieOriginalTokenValidator mobileVerifier = new PXCookieOriginalTokenValidator(pxConfiguration);
  mobileError = mobileVerifier.getMobileError(context);
- mobileVerifier.verify(context);
+ logTime("mobileVerifier.verify", () -> mobileVerifier.verify(context));
  if (!StringUtils.isEmpty(mobileError)) {
  context.setS2sCallReason("mobile_error_" + mobileError);
  return false;

src/main/java/com/perimeterx/internals/PXS2SValidator.java

@@ -15,6 +15,7 @@
 import com.perimeterx.utils.PXLogger;
 import org.apache.http.conn.ConnectTimeoutException;
 
+import static com.perimeterx.utils.PXCommonUtils.logTime;
 import static org.apache.commons.lang3.StringUtils.*;
 
 /**
@@ -48,7 +49,7 @@ public boolean verify(PXContext pxContext) {
  long rtt;
 
  try {
- response = pxClient.riskApiCall(pxContext);
+ response = logTime("pxClient.riskApiCall", () -> pxClient.riskApiCall(pxContext));
  } catch (ConnectTimeoutException e) {
  // Timeout handling - report pass reason and proceed with request
  pxContext.setPassReason(PassReason.S2S_TIMEOUT);