Improve diagnostic in case of failues by adding more debug logging an…

…d a debug -D option
Endava · Mar 29, 2022 · 233e9e9 · 233e9e9
1 parent 8a7eea7
commit 233e9e9
Show file tree

Hide file tree

Showing 19 changed files with 105 additions and 11 deletions.
diff --git a/src/main/java/com/endava/cats/command/CatsCommand.java b/src/main/java/com/endava/cats/command/CatsCommand.java
@@ -124,6 +124,7 @@ public void doLogic() throws IOException {
     private void initGlobalData(OpenAPI openAPI) {
         Map<String, Schema> allSchemasFromOpenApi = OpenApiUtils.getSchemas(openAPI, processingArguments.getContentType());
         globalContext.getSchemaMap().putAll(allSchemasFromOpenApi);
+        LOGGER.debug("Schemas: {}", allSchemasFromOpenApi.keySet());
     }
 
     public void startFuzzing(OpenAPI openAPI) {
@@ -194,7 +195,7 @@ public void fuzzPath(Map.Entry<String, PathItem> pathItemEntry, OpenAPI openAPI)
         List<FuzzingData> fuzzingDataList = fuzzingDataFactory.fromPathItem(pathItemEntry.getKey(), pathItemEntry.getValue(), openAPI);
 
         if (fuzzingDataList.isEmpty()) {
-            LOGGER.warning("Skipping path {}. HTTP method not supported yet!", pathItemEntry.getKey());
+            LOGGER.warning("There was a problem fuzzing path {}.", pathItemEntry.getKey());
             return;
         }
 

diff --git a/src/main/java/com/endava/cats/command/ListCommand.java b/src/main/java/com/endava/cats/command/ListCommand.java
@@ -1,8 +1,8 @@
 package com.endava.cats.command;
 
+import com.endava.cats.Fuzzer;
 import com.endava.cats.annotations.ContractInfoFuzzer;
 import com.endava.cats.annotations.FieldFuzzer;
-import com.endava.cats.Fuzzer;
 import com.endava.cats.annotations.HeaderFuzzer;
 import com.endava.cats.annotations.HttpFuzzer;
 import com.endava.cats.annotations.SanitizeAndValidate;
@@ -70,6 +70,7 @@ void listContractPaths() {
             LOGGER.star("Available paths:");
             openAPI.getPaths().keySet().stream().sorted().map(item -> "\t " + item).forEach(LOGGER::info);
         } catch (IOException e) {
+            LOGGER.debug("Exception while reading contract!", e);
             LOGGER.error("Error while reading contract: {}", e.getMessage());
         }
     }

diff --git a/src/main/java/com/endava/cats/command/ReplayCommand.java b/src/main/java/com/endava/cats/command/ReplayCommand.java
@@ -74,6 +74,7 @@ public void run() {
                 this.executeTestCase(testCaseFileName);
                 LOGGER.complete("Finish executing {}", testCaseFileName);
             } catch (IOException e) {
+                LOGGER.debug("Exception while replaying test!", e);
                 LOGGER.error("Something went wrong while replaying {}: {}", testCaseFileName, e.toString());
             }
         }

diff --git a/src/main/java/com/endava/cats/command/RunCommand.java b/src/main/java/com/endava/cats/command/RunCommand.java
@@ -89,6 +89,7 @@ public void run() {
             catsCommand.processingArguments.setContentType(this.contentType);
             catsCommand.run();
         } catch (IOException e) {
+            LOGGER.debug("Exception while processing file!", e);
             LOGGER.error("Something went wrong while processing input file: {}", e.getMessage());
         }
     }

diff --git a/src/main/java/com/endava/cats/command/TemplateFuzzCommand.java b/src/main/java/com/endava/cats/command/TemplateFuzzCommand.java
@@ -119,6 +119,7 @@ public void run() {
             templateFuzzer.fuzz(fuzzingData);
             afterFuzz();
         } catch (IOException e) {
+            LOGGER.debug("Exception while fuzzing given data!", e);
             LOGGER.error("Something went wrong while fuzzing: {}", e.getMessage());
         }
     }

diff --git a/src/main/java/com/endava/cats/dsl/CatsDSLParser.java b/src/main/java/com/endava/cats/dsl/CatsDSLParser.java
@@ -3,13 +3,16 @@
 import com.endava.cats.dsl.impl.EnvVariableParser;
 import com.endava.cats.dsl.impl.RequestVariableParser;
 import com.endava.cats.dsl.impl.SpringELParser;
+import io.github.ludovicianul.prettylogger.PrettyLogger;
+import io.github.ludovicianul.prettylogger.PrettyLoggerFactory;
 
 import javax.inject.Singleton;
 import java.util.Map;
 import java.util.Optional;
 
 @Singleton
 public class CatsDSLParser {
+    private static final PrettyLogger LOGGER = PrettyLoggerFactory.getLogger(CatsDSLParser.class);
     private static final Map<String, Parser> PARSERS = Map.of(
             "T(", new SpringELParser(),
             "$$", new EnvVariableParser(),
@@ -25,6 +28,7 @@ public class CatsDSLParser {
     public String parseAndGetResult(String valueFromFile, String jsonPayload) {
         Optional<Map.Entry<String, Parser>> parserEntry = PARSERS.entrySet().stream().filter(entry -> valueFromFile.startsWith(entry.getKey())).findAny();
         if (parserEntry.isPresent()) {
+            LOGGER.debug("Identified parser {}", parserEntry.get().getValue().getClass().getSimpleName());
             return parserEntry.get().getValue().parse(valueFromFile, jsonPayload);
         }
 

diff --git a/src/main/java/com/endava/cats/dsl/impl/SpringELParser.java b/src/main/java/com/endava/cats/dsl/impl/SpringELParser.java
@@ -37,6 +37,7 @@ public String parse(String expression, String payload) {
 
             return String.valueOf(spelExpressionParser.parseExpression(expression).getValue(context));
         } catch (Exception e) {
+            log.debug("Something went wrong while parsing!", e);
             log.error("Failed to parse {} as invalid syntax: {}", expression, e.getMessage());
             return expression;
         }

diff --git a/src/main/java/com/endava/cats/factory/FuzzingDataFactory.java b/src/main/java/com/endava/cats/factory/FuzzingDataFactory.java
@@ -2,14 +2,16 @@
 
 import com.endava.cats.args.FilesArguments;
 import com.endava.cats.args.ProcessingArguments;
-import com.endava.cats.model.generator.PayloadGenerator;
 import com.endava.cats.http.HttpMethod;
 import com.endava.cats.model.CatsGlobalContext;
 import com.endava.cats.model.CatsHeader;
 import com.endava.cats.model.FuzzingData;
+import com.endava.cats.model.generator.PayloadGenerator;
 import com.endava.cats.util.OpenApiUtils;
 import com.google.gson.JsonElement;
 import com.google.gson.JsonParser;
+import io.github.ludovicianul.prettylogger.PrettyLogger;
+import io.github.ludovicianul.prettylogger.PrettyLoggerFactory;
 import io.swagger.v3.oas.models.OpenAPI;
 import io.swagger.v3.oas.models.Operation;
 import io.swagger.v3.oas.models.PathItem;
@@ -43,7 +45,7 @@
  */
 @ApplicationScoped
 public class FuzzingDataFactory {
-
+    private static final PrettyLogger LOGGER = PrettyLoggerFactory.getLogger(FuzzingDataFactory.class);
     private static final String SYNTH_SCHEMA_NAME = "CatsGetSchema";
     private static final String ANY_OF = "ANY_OF";
     private static final String ONE_OF = "ONE_OF";
@@ -70,22 +72,27 @@ public FuzzingDataFactory(FilesArguments filesArguments, ProcessingArguments pro
     public List<FuzzingData> fromPathItem(String path, PathItem item, OpenAPI openAPI) {
         List<FuzzingData> fuzzingDataList = new ArrayList<>();
         if (item.getPost() != null) {
+            LOGGER.debug("Identified POST method for path {}", path);
             fuzzingDataList.addAll(this.getFuzzDataForPost(path, item, item.getPost(), openAPI));
         }
 
         if (item.getPut() != null) {
+            LOGGER.debug("Identified PUT method for path {}", path);
             fuzzingDataList.addAll(this.getFuzzDataForPut(path, item, item.getPut(), openAPI));
         }
 
         if (item.getPatch() != null) {
+            LOGGER.debug("Identified PATCH method for path {}", path);
             fuzzingDataList.addAll(this.getFuzzDataForPatch(path, item, item.getPatch(), openAPI));
         }
 
         if (item.getGet() != null) {
+            LOGGER.debug("Identified GET method for path {}", path);
             fuzzingDataList.addAll(this.getFuzzingDataForGet(path, item, item.getGet(), openAPI));
         }
 
         if (item.getDelete() != null) {
+            LOGGER.debug("Identified DELETE method for path {}", path);
             fuzzingDataList.addAll(this.getFuzzingDataForDelete(path, item, item.getDelete(), openAPI));
         }
 
@@ -170,13 +177,16 @@ private List<FuzzingData> getFuzzDataForHttpMethod(String path, PathItem item, O
         MediaType mediaType = this.getMediaType(operation, openAPI);
 
         if (mediaType == null) {
+            LOGGER.debug("Wasn't able to determine the media type for path {}, method {}", path, method);
             return Collections.emptyList();
         }
         List<String> reqSchemaNames = this.getCurrentRequestSchemaName(mediaType);
+        LOGGER.debug("Request schema names identified for path {}, method {}: {}", path, method, reqSchemaNames);
 
         Map<String, List<String>> responses = this.getResponsePayloads(operation, operation.getResponses().keySet());
         Map<String, List<String>> responsesContentTypes = this.getResponseContentTypes(operation, operation.getResponses().keySet());
         List<String> requestContentTypes = this.getRequestContentTypes(operation, openAPI);
+        LOGGER.debug("Request content types for path {}, method {}: {}", path, method, requestContentTypes);
 
         for (String reqSchemaName : reqSchemaNames) {
             List<String> payloadSamples = this.getRequestPayloadsSamples(mediaType, reqSchemaName);
@@ -212,11 +222,13 @@ private List<FuzzingData> getFuzzDataForNonBodyMethods(String path, PathItem ite
 
         globalContext.getSchemaMap().put(SYNTH_SCHEMA_NAME + operation.getOperationId(), syntheticSchema);
         Set<String> queryParams = this.extractQueryParams(syntheticSchema);
+        LOGGER.debug("Query params for path {}, method {}: {}", path, method, queryParams);
 
         List<String> payloadSamples = this.getRequestPayloadsSamples(null, SYNTH_SCHEMA_NAME + operation.getOperationId());
-        Map<String, List<String>> responses = this.getResponsePayloads(operation, operation.getResponses().keySet());
         Map<String, List<String>> responsesContentTypes = this.getResponseContentTypes(operation, operation.getResponses().keySet());
+        Map<String, List<String>> responses = this.getResponsePayloads(operation, operation.getResponses().keySet());
         List<String> requestContentTypes = this.getRequestContentTypes(operation, openAPI);
+        LOGGER.debug("Request content types for path {}, method {}: {}", path, method, requestContentTypes);
 
         return payloadSamples.stream().map(payload -> FuzzingData.builder().method(method).path(path).headers(this.extractHeaders(operation)).payload(payload)
                 .responseCodes(operation.getResponses().keySet()).reqSchema(syntheticSchema).pathItem(item)

diff --git a/src/main/java/com/endava/cats/fuzzer/CustomFuzzerUtil.java b/src/main/java/com/endava/cats/fuzzer/CustomFuzzerUtil.java
@@ -296,6 +296,7 @@ private String replaceElementWithCustomValue(Map.Entry<String, String> keyValue,
             FuzzingStrategy fuzzingStrategy = FuzzingStrategy.replace().withData(toReplace);
             return catsUtil.replaceField(payload, keyValue.getKey(), fuzzingStrategy).getJson();
         } catch (Exception e) {
+            log.debug("Something went wrong while parsing!", e);
             log.warning("Property [{}] does not exist", keyValue.getKey());
             return payload;
         }

diff --git a/src/main/java/com/endava/cats/fuzzer/fields/FunctionalFuzzer.java b/src/main/java/com/endava/cats/fuzzer/fields/FunctionalFuzzer.java
@@ -74,7 +74,8 @@ private boolean isMatchingHttpMethod(Object currentValues, HttpMethod httpMethod
      * rather than the order defined by the OpenAPI contract.
      */
     public void executeCustomFuzzerTests() {
-        MDC.put("fuzzer", "CF");
+        LOGGER.debug("Executing {} functional tests.", executions.size());
+        MDC.put("fuzzer", "FF");
         MDC.put("fuzzerKey", "FunctionalFuzzer");
 
         Collections.sort(executions);
@@ -90,12 +91,14 @@ public void executeCustomFuzzerTests() {
 
     public void replaceRefData() throws IOException {
         if (filesArguments.getRefDataFile() != null) {
+            LOGGER.debug("Replacing variables in refData file with output variables from FunctionaFuzzer!");
             List<String> refDataLines = Files.readAllLines(filesArguments.getRefDataFile().toPath());
             List<String> updatedLines = refDataLines.stream().map(this::replaceWithVariable).collect(Collectors.toList());
             String currentFile = filesArguments.getRefDataFile().getAbsolutePath();
             Path file = Paths.get(currentFile.substring(0, currentFile.lastIndexOf(".")) + "_replaced.yml");
             Files.write(file, updatedLines, StandardCharsets.UTF_8);
         } else if (filesArguments.isCreateRefData()) {
+            LOGGER.debug("Creating refData file with output variables from FuctionalFuzzer!");
             customFuzzerUtil.writeRefDataFileWithOutputVariables();
         }
     }

diff --git a/src/main/java/com/endava/cats/fuzzer/fields/base/BaseBoundaryFieldFuzzer.java b/src/main/java/com/endava/cats/fuzzer/fields/base/BaseBoundaryFieldFuzzer.java
@@ -18,7 +18,6 @@
  * The assumption is that expected response is a 4XX code when sending out of boundary values for the fuzzed fields.
  */
 public abstract class BaseBoundaryFieldFuzzer extends ExpectOnly4XXBaseFieldsFuzzer {
-
     protected BaseBoundaryFieldFuzzer(ServiceCaller sc, TestCaseListener lr, CatsUtil cu, FilesArguments cp) {
         super(sc, lr, cu, cp);
     }
@@ -33,18 +32,22 @@ public List<FuzzingStrategy> getFieldFuzzingStrategy(FuzzingData data, String fu
         Schema<?> schema = data.getRequestPropertyTypes().get(fuzzedField);
 
         if (this.fuzzedFieldHasAnAssociatedSchema(schema)) {
+            logger.debug("Field {} has an associated schema", fuzzedField);
             logger.info("Field [{}] schema is [{}] and type [{}]", fuzzedField, schema.getClass().getSimpleName(), schema.getType());
-
             if (this.isFieldFuzzable(fuzzedField, data) && this.fuzzerGeneratedBoundaryValue(schema)) {
+                logger.debug("Field {} is fuzzable and has boundary value", fuzzedField);
                 logger.start("[{}]. Start fuzzing...", getSchemasThatTheFuzzerWillApplyTo().stream().map(Class::getSimpleName).collect(Collectors.toSet()));
                 return Collections.singletonList(FuzzingStrategy.replace().withData(this.getBoundaryValue(schema)));
             } else if (!this.hasBoundaryDefined(fuzzedField, data)) {
+                logger.debug("Field {} does not have a boundary defined", fuzzedField);
                 logger.skip("Boundaries not defined. Will skip fuzzing...");
                 return Collections.singletonList(FuzzingStrategy.skip().withData("No LEFT or RIGHT boundary info within the contract!"));
             } else if (!this.isStringFormatRecognizable(schema) && isRequestSchemaMatchingFuzzerType(schema)) {
+                logger.debug("Field {} has format unrecognizable {}", fuzzedField, schema.getFormat());
                 logger.skip("String format not supplied or not recognized [{}]", schema.getFormat());
                 return Collections.singletonList(FuzzingStrategy.skip().withData("String format not supplied or not recognized!"));
             } else {
+                logger.debug("Data type not matching. Skipping fuzzing for {}", fuzzedField);
                 logger.skip("Not [{}]. Will skip fuzzing...", getSchemasThatTheFuzzerWillApplyTo().stream().map(Class::getSimpleName).collect(Collectors.toSet()));
             }
         }

diff --git a/src/main/java/com/endava/cats/fuzzer/fields/base/BaseFieldsFuzzer.java b/src/main/java/com/endava/cats/fuzzer/fields/base/BaseFieldsFuzzer.java
@@ -56,10 +56,12 @@ public void fuzz(FuzzingData data) {
         fieldsToBeRemoved.forEach(allFields::remove);
 
         if (allFields.isEmpty()) {
+            logger.debug("Not fields to fuzz. Skip fuzzing!");
             logger.skip("Skipped due to: no fields to fuzz!");
         } else {
             for (String fuzzedField : allFields) {
                 for (FuzzingStrategy fuzzingStrategy : this.getFieldFuzzingStrategy(data, fuzzedField)) {
+                    logger.debug("Running strategy {} for {}", fuzzingStrategy.name(), fuzzedField);
                     testCaseListener.createAndExecuteTest(logger, this, () -> process(data, fuzzedField, fuzzingStrategy));
                 }
             }
@@ -73,6 +75,7 @@ protected void process(FuzzingData data, String fuzzedField, FuzzingStrategy fuz
                 this.typeOfDataSentToTheService(), fuzzedField, fuzzingStrategy.truncatedValue(), fuzzingConstraints.getRequiredString());
 
         if (this.isFuzzingPossible(data, fuzzedField, fuzzingStrategy)) {
+            logger.debug("Fuzzing possible...");
             FuzzingResult fuzzingResult = catsUtil.replaceField(data.getPayload(), fuzzedField, fuzzingStrategy);
             boolean isFuzzedValueMatchingPattern = this.isFuzzedValueMatchingPattern(fuzzingResult.getFuzzedValue(), data, fuzzedField);
 
@@ -87,6 +90,7 @@ protected void process(FuzzingData data, String fuzzedField, FuzzingStrategy fuz
             testCaseListener.addExpectedResult(logger, "Should return [{}]", expectedResponseCodeBasedOnConstraints.asString());
             testCaseListener.reportResult(logger, data, response, expectedResponseCodeBasedOnConstraints);
         } else {
+            logger.debug("Fuzzing not possible!");
             FuzzingStrategy strategy = this.createSkipStrategy(fuzzingStrategy);
             testCaseListener.skipTest(logger, strategy.process(""));
         }

diff --git a/src/main/java/com/endava/cats/fuzzer/fields/base/ExactValuesInFieldsFuzzer.java b/src/main/java/com/endava/cats/fuzzer/fields/base/ExactValuesInFieldsFuzzer.java
@@ -1,9 +1,9 @@
 package com.endava.cats.fuzzer.fields.base;
 
 import com.endava.cats.args.FilesArguments;
-import com.endava.cats.http.ResponseCodeFamily;
 import com.endava.cats.generator.simple.StringGenerator;
 import com.endava.cats.http.HttpMethod;
+import com.endava.cats.http.ResponseCodeFamily;
 import com.endava.cats.io.ServiceCaller;
 import com.endava.cats.model.FuzzingData;
 import com.endava.cats.report.TestCaseListener;
@@ -54,6 +54,7 @@ public List<Class<? extends Schema>> getSchemasThatTheFuzzerWillApplyTo() {
     @Override
     public String getBoundaryValue(Schema schema) {
         if (getExactMethod().apply(schema) == null) {
+            logger.debug("Null value for applied boundary function!");
             return null;
         }
         String pattern = schema.getPattern() != null ? schema.getPattern() : StringGenerator.ALPHANUMERIC_PLUS;

diff --git a/src/main/java/com/endava/cats/fuzzer/headers/base/BaseHeadersFuzzer.java b/src/main/java/com/endava/cats/fuzzer/headers/base/BaseHeadersFuzzer.java
@@ -1,8 +1,8 @@
 package com.endava.cats.fuzzer.headers.base;
 
 import com.endava.cats.Fuzzer;
-import com.endava.cats.http.ResponseCodeFamily;
 import com.endava.cats.generator.Cloner;
+import com.endava.cats.http.ResponseCodeFamily;
 import com.endava.cats.io.ServiceCaller;
 import com.endava.cats.io.ServiceData;
 import com.endava.cats.model.CatsHeader;
@@ -38,6 +38,7 @@ public void fuzz(FuzzingData fuzzingData) {
 
         for (CatsHeader header : clonedHeaders) {
             for (FuzzingStrategy fuzzingStrategy : fuzzStrategy()) {
+                logger.debug("Fuzzing strategy {} for header {}", fuzzingStrategy.name(), header);
                 testCaseListener.createAndExecuteTest(logger, this, () -> process(fuzzingData, clonedHeaders, header, fuzzingStrategy));
             }
         }

diff --git a/src/main/java/com/endava/cats/fuzzer/special/TemplateFuzzer.java b/src/main/java/com/endava/cats/fuzzer/special/TemplateFuzzer.java
@@ -94,6 +94,7 @@ String replacePath(FuzzingData data, String withData, String targetField) {
                 finalPath = finalPath.replace(url.getQuery(), replacedQuery);
             }
         } catch (Exception e) {
+            LOGGER.debug("There was a problem parsing given path!", e);
             LOGGER.warn("There was an issue parsing {}: {}", data.getPath(), e.getMessage());
         }
 
@@ -124,6 +125,7 @@ private List<String> getAllPayloads(int payloadSize) {
                 return Files.readAllLines(Path.of(userArguments.getWords().getAbsolutePath()), StandardCharsets.UTF_8);
             }
         } catch (IOException e) {
+            LOGGER.debug("Something went wrong while fuzzing!", e);
             LOGGER.error("Something went wrong while reading user supplied dictionary: {}", e.getMessage());
         }
         return Collections.emptyList();

diff --git a/src/main/java/com/endava/cats/io/ServiceCaller.java b/src/main/java/com/endava/cats/io/ServiceCaller.java
@@ -179,6 +179,7 @@ private SSLSocketFactory buildSslSocketFactory(TrustManager[] trustAllCerts) thr
     @DryRun
     public CatsResponse call(ServiceData data) {
         String processedPayload = this.replacePayloadWithRefData(data);
+        LOGGER.debug("Payload replaced with ref data: {}", processedPayload);
 
         List<CatsRequest.Header> headers = this.buildHeaders(data);
         CatsRequest catsRequest = CatsRequest.builder()
@@ -197,6 +198,7 @@ public CatsResponse call(ServiceData data) {
 
             LOGGER.note("Final list of request headers: {}", headers);
             LOGGER.note("Final payload: {}", processedPayload);
+            LOGGER.note("Final url: {}", url);
 
             CatsResponse response = this.callService(catsRequest, data.getFuzzedFields());