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/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);

src/main/java/com/perimeterx/models/PXContext.java

@@ -33,6 +33,7 @@
 
 import static com.perimeterx.utils.Constants.BREACHED_ACCOUNT_KEY_NAME;
 import static com.perimeterx.utils.PXCommonUtils.cookieHeadersNames;
+import static com.perimeterx.utils.PXCommonUtils.logTime;
 
 /**
  * PXContext - Populate relevant data from HttpRequest
@@ -226,20 +227,20 @@ public PXContext(final HttpServletRequest request, final IPProvider ipProvider,
     }
 
     private void initContext(final HttpServletRequest request, PXConfiguration pxConfiguration) {
-        this.headers = PXCommonUtils.getHeadersFromRequest(request);
+        this.headers = logTime("PXCommonUtils.getHeadersFromRequest", () -> PXCommonUtils.getHeadersFromRequest(request));
 
         if (headers.containsKey(Constants.MOBILE_SDK_AUTHORIZATION_HEADER) || headers.containsKey(Constants.MOBILE_SDK_TOKENS_HEADER)) {
             logger.debug(PXLogger.LogReason.DEBUG_MOBILE_SDK_DETECTED);
             this.isMobileToken = true;
             this.cookieOrigin = Constants.HEADER_ORIGIN;
         }
-        parseCookies(request, isMobileToken);
-        generateLoginData(request, pxConfiguration);
+        logTime("parseCookies", () -> parseCookies(request, isMobileToken));
+        logTime("generateLoginData", () -> generateLoginData(request, pxConfiguration));
 
         this.firstPartyRequest = false;
         this.userAgent = request.getHeader("user-agent");
         this.uri = request.getRequestURI();
-        this.fullUrl = extractURL(request); //full URL with query string
+        this.fullUrl = logTime("extractURL", () ->extractURL(request)); //full URL with query string
         this.blockReason = BlockReason.NONE;
         this.passReason = PassReason.NONE;
         this.s2sErrorReasonInfo = new S2SErrorReasonInfo();
@@ -257,9 +258,9 @@ private void initContext(final HttpServletRequest request, PXConfiguration pxCon
         Function<? super HttpServletRequest, ? extends CustomParameters> customParametersExtraction = pxConfiguration.getCustomParametersExtraction();
         try {
             if (customParametersExtraction != null) {
-                this.customParameters = customParametersExtraction.apply(this.request);
+                this.customParameters = logTime("customParametersExtraction.apply", () -> customParametersExtraction.apply(this.request));
             } else {
-                this.customParameters = customParametersProvider.buildCustomParameters(pxConfiguration, this);
+                this.customParameters = logTime("customParametersProvider.buildCustomParameters", () -> customParametersProvider.buildCustomParameters(pxConfiguration, this));
             }
         } catch (Exception e) {
             logger.debug("failed to extract custom parameters from custom function", e);
@@ -327,41 +328,46 @@ private void parseCookies(HttpServletRequest request, boolean isMobileToken) {
         List<RawCookieData> tokens = new ArrayList<>();
         List<RawCookieData> originalTokens = new ArrayList<>();
         if (isMobileToken) {
-            headerParser = new MobileCookieHeaderParser();
+            logTime("anonymousParseCookiesMobile", () -> {
+                // This was changed because it is not possible to override a value inside a function.
+                HeaderParser hp = new MobileCookieHeaderParser();
 
-            String tokensHeader = request.getHeader(Constants.MOBILE_SDK_TOKENS_HEADER);
-            tokens.addAll(headerParser.createRawCookieDataList(tokensHeader));
+                String tokensHeader = request.getHeader(Constants.MOBILE_SDK_TOKENS_HEADER);
+                tokens.addAll(hp.createRawCookieDataList(tokensHeader));
 
-            String authCookieHeader = request.getHeader(Constants.MOBILE_SDK_AUTHORIZATION_HEADER);
-            tokens.addAll(headerParser.createRawCookieDataList(authCookieHeader));
+                String authCookieHeader = request.getHeader(Constants.MOBILE_SDK_AUTHORIZATION_HEADER);
+                tokens.addAll(hp.createRawCookieDataList(authCookieHeader));
 
-            String originalTokensHeader = request.getHeader(Constants.MOBILE_SDK_ORIGINAL_TOKENS_HEADER);
-            originalTokens.addAll(headerParser.createRawCookieDataList(originalTokensHeader));
+                String originalTokensHeader = request.getHeader(Constants.MOBILE_SDK_ORIGINAL_TOKENS_HEADER);
+                originalTokens.addAll(hp.createRawCookieDataList(originalTokensHeader));
 
-            String originalTokenHeader = request.getHeader(Constants.MOBILE_SDK_ORIGINAL_TOKEN_HEADER);
-            originalTokens.addAll(headerParser.createRawCookieDataList(originalTokenHeader));
+                String originalTokenHeader = request.getHeader(Constants.MOBILE_SDK_ORIGINAL_TOKEN_HEADER);
+                originalTokens.addAll(hp.createRawCookieDataList(originalTokenHeader));
 
-            this.tokens = tokens;
-            if (!originalTokens.isEmpty()) {
-                this.originalTokens = originalTokens;
-            }
+                this.tokens = tokens;
+                if (!originalTokens.isEmpty()) {
+                    this.originalTokens = originalTokens;
+                }
 
-            ObjectMapper mapper = new ObjectMapper();
-            this.pxde = mapper.createObjectNode();
-            this.pxdeVerified = true;
+                ObjectMapper mapper = new ObjectMapper();
+                this.pxde = mapper.createObjectNode();
+                this.pxdeVerified = true;
+            });
         } else {
-            Cookie[] cookies = request.getCookies();
-            String[] cookieHeaders = cookieHeadersNames(getPxConfiguration())
-                    .stream()
-                    .map(request::getHeader)
-                    .toArray(String[]::new);
-            this.requestCookieNames = CookieNamesExtractor.extractCookieNames(cookies);
-            setVidAndPxhd(cookies);
-            tokens.addAll(headerParser.createRawCookieDataList(cookieHeaders));
-            this.tokens = tokens;
-            DataEnrichmentCookie deCookie = headerParser.getRawDataEnrichmentCookie(this.tokens, this.pxConfiguration.getCookieKey());
-            this.pxde = deCookie.getJsonPayload();
-            this.pxdeVerified = deCookie.isValid();
+            logTime("anonymousParseCookiesElse", () -> {
+                Cookie[] cookies = request.getCookies();
+                String[] cookieHeaders = cookieHeadersNames(getPxConfiguration())
+                        .stream()
+                        .map(request::getHeader)
+                        .toArray(String[]::new);
+                this.requestCookieNames = CookieNamesExtractor.extractCookieNames(cookies);
+                setVidAndPxhd(cookies);
+                tokens.addAll(headerParser.createRawCookieDataList(cookieHeaders));
+                this.tokens = tokens;
+                DataEnrichmentCookie deCookie = headerParser.getRawDataEnrichmentCookie(this.tokens, this.pxConfiguration.getCookieKey());
+                this.pxde = deCookie.getJsonPayload();
+                this.pxdeVerified = deCookie.isValid();
+            });
         }
     }
 

src/main/java/com/perimeterx/utils/PXCallable.java

@@ -0,0 +1,6 @@
+package com.perimeterx.utils;
+
+@FunctionalInterface
+public interface PXCallable<T,E extends Throwable> {
+    T apply() throws E;
+}

src/main/java/com/perimeterx/utils/PXCallableVoid.java

@@ -0,0 +1,6 @@
+package com.perimeterx.utils;
+
+@FunctionalInterface
+public interface PXCallableVoid<E extends Throwable> {
+    void apply() throws E;
+}

src/main/java/com/perimeterx/utils/PXCommonUtils.java

@@ -17,6 +17,7 @@
  * Created by nitzangoldfeder on 16/07/2017.
  */
 public class PXCommonUtils {
+    private static final PXLogger logger = PXLogger.getLogger(PXCommonUtils.class);
 
     public static List<Header> getDefaultHeaders(String authToken) {
         Header contentType = new BasicHeader(HttpHeaders.CONTENT_TYPE, "application/json");
@@ -59,4 +60,33 @@ public static List<String> cookieHeadersNames(PXConfiguration configuration) {
 
         return lst;
     }
+
+    /**
+     * Logs the runtime of a given function. returns the result of the execution
+     * whether it's a Throwable or value.
+     *
+     * @param methodName the name of the method to be logged
+     * @param f          the function to execute
+     * @param <T>        type of successful execution
+     * @param <E>        type of failed execution
+     * @return the success result of the execution
+     * @throws E the throwable that will be thrown if the function fails
+     */
+    public static <T, E extends Throwable> T logTime(String methodName, PXCallable<T, E> f) throws E {
+        long s = System.currentTimeMillis();
+        try {
+            return f.apply();
+        } finally {
+            long e = System.currentTimeMillis();
+            logger.debug(String.format("TIMELOGGER - %s execution time is (%d)ms", methodName, e - s));
+        }
+    }
+
+    public static <E extends Throwable> void logTime(String methodName, PXCallableVoid<E> f) throws E {
+        // Using the other signature.
+        logTime(methodName, () -> {
+            f.apply();
+            return null;
+        });
+    }
 }

web/pom.xml

@@ -25,7 +25,7 @@
         <dependency>
             <groupId>com.perimeterx</groupId>
             <artifactId>perimeterx-sdk</artifactId>
-            <version>6.7.0</version>
+            <version>6.7.0-rc-extended-logging</version>
             <scope>compile</scope>
         </dependency>
         <dependency>