diff --git a/src/main/java/io/github/ktestify/io/core/AbstractSynchronousConsumer.java b/src/main/java/io/github/ktestify/io/core/AbstractSynchronousConsumer.java index 241d600..9c0754a 100644 --- a/src/main/java/io/github/ktestify/io/core/AbstractSynchronousConsumer.java +++ b/src/main/java/io/github/ktestify/io/core/AbstractSynchronousConsumer.java @@ -104,15 +104,31 @@ protected AbstractSynchronousConsumer( public Boolean call() throws ConsumerException { try { Req request = buildRequest(); + log.info( + "Executing synchronous request via '{}'.", client.getClass().getSimpleName()); List> records = client.execute(request); MatchContext matchContext = buildMatchContext(); + log.info( + "Running matcher '{}' on {} response record(s).", + matcher.getClass().getSimpleName(), + records.size()); MatchResult result = matcher.match(records, matchContext); - log.debug("Match result: passed={}, diff={}", result.isPassed(), result.getDiff()); + if (result.isPassed()) { + log.info( + "Synchronous validation PASSED with matcher '{}'.", + matcher.getClass().getSimpleName()); + } else { + log.error( + "Synchronous validation FAILED with matcher '{}': {}", + matcher.getClass().getSimpleName(), + result.getDiff()); + } return result.isPassed(); } catch (FetchException e) { + log.error("Synchronous request execution failed: {}", e.getMessage()); throw new ConsumerException(e.getMessage(), e); } } diff --git a/src/main/java/io/github/ktestify/io/core/PollingRequestResponseClient.java b/src/main/java/io/github/ktestify/io/core/PollingRequestResponseClient.java index db385bf..6e6922f 100644 --- a/src/main/java/io/github/ktestify/io/core/PollingRequestResponseClient.java +++ b/src/main/java/io/github/ktestify/io/core/PollingRequestResponseClient.java @@ -75,18 +75,23 @@ public List> execute(Req request) throws FetchException { long deadlineMs = System.currentTimeMillis() + timeoutMs; List> lastResult = null; FetchException lastFailure = null; + int attempt = 0; + + log.info("Starting polling request (timeout={}ms, pollInterval={}ms).", timeoutMs, pollIntervalMs); do { + attempt++; try { List> result = delegate.execute(request); lastResult = result; lastFailure = null; if (untilPredicate.test(result)) { - log.debug("Polling predicate satisfied."); + log.info("Polling predicate satisfied on attempt #{}.", attempt); return result; } + log.debug("Polling attempt #{} did not satisfy predicate; retrying...", attempt); } catch (FetchException e) { - log.debug("Polling attempt failed: {}", e.getMessage()); + log.debug("Polling attempt #{} failed: {}", attempt, e.getMessage()); lastFailure = e; } @@ -97,12 +102,19 @@ public List> execute(Req request) throws FetchException { } while (true); if (lastResult == null) { + log.error( + "Polling failed after {} attempt(s) within {}ms without obtaining any response.", + attempt, + timeoutMs); throw lastFailure != null ? lastFailure : new FetchException("Polling produced no result within " + timeoutMs + "ms."); } - log.warn("Polling predicate never satisfied within {}ms, returning the last result obtained.", timeoutMs); + log.warn( + "Polling predicate never satisfied after {} attempt(s) within {}ms, returning the last result obtained.", + attempt, + timeoutMs); return lastResult; } diff --git a/src/main/java/io/github/ktestify/io/inputs/DynamicVariableProcessor.java b/src/main/java/io/github/ktestify/io/inputs/DynamicVariableProcessor.java index 09a2619..6e76af8 100644 --- a/src/main/java/io/github/ktestify/io/inputs/DynamicVariableProcessor.java +++ b/src/main/java/io/github/ktestify/io/inputs/DynamicVariableProcessor.java @@ -51,9 +51,13 @@ public String process(String input) { String format = matcher.group(GROUP_FORMAT) != null ? matcher.group(GROUP_FORMAT) : ""; if (DynamicVariableFactory.isRegistered(variableName)) { - LOGGER.info("Processing dynamic variable: {} with format: {}", variableName, format); DynamicVariable variable = DynamicVariableFactory.getVariable(variableName); String replacement = variable.process(format); + LOGGER.info( + "Resolved dynamic variable '{{{}{}}}': '{}'", + variableName, + format.isEmpty() ? "" : ":" + format, + replacement); matcher.appendReplacement(sb, Matcher.quoteReplacement(replacement)); } else { LOGGER.warn("Dynamic variable {} is not registered, keeping it unchanged.", variableName); diff --git a/src/main/java/io/github/ktestify/io/kafka/AbstractKafkaConsumer.java b/src/main/java/io/github/ktestify/io/kafka/AbstractKafkaConsumer.java index b00ad15..ef09e0b 100644 --- a/src/main/java/io/github/ktestify/io/kafka/AbstractKafkaConsumer.java +++ b/src/main/java/io/github/ktestify/io/kafka/AbstractKafkaConsumer.java @@ -83,18 +83,26 @@ public Boolean call() throws ConsumerException { try (KafkaRecordFetcher fetcher = new KafkaRecordFetcher<>(context)) { List> records = fetcher.fetch(); MatchContext matchContext = buildMatchContext(); + log.info( + "Running matcher '{}' on {} fetched record(s) from topic '{}'.", + matcher.getClass().getSimpleName(), + records.size(), + context.getTopic().getNamespacedTopic()); MatchResult result = matcher.match(records, matchContext); - log.debug( - "Match result for topic '{}': passed={}, diff={}", - context.getTopic().getNamespacedTopic(), - result.isPassed(), - result.getDiff()); - if (!result.isPassed()) { + log.error( + "Validation FAILED on topic '{}' with matcher '{}': {}", + context.getTopic().getNamespacedTopic(), + matcher.getClass().getSimpleName(), + result.getDiff()); throw new AssertionError("Consumer validation failed for topic '" + context.getTopic().getNamespacedTopic() + "': " + result.getDiff()); } + log.info( + "Validation PASSED on topic '{}' with matcher '{}'.", + context.getTopic().getNamespacedTopic(), + matcher.getClass().getSimpleName()); return true; } catch (FetchException e) { diff --git a/src/main/java/io/github/ktestify/io/kafka/AbstractKafkaProducer.java b/src/main/java/io/github/ktestify/io/kafka/AbstractKafkaProducer.java index c6f9a68..87ad8cd 100644 --- a/src/main/java/io/github/ktestify/io/kafka/AbstractKafkaProducer.java +++ b/src/main/java/io/github/ktestify/io/kafka/AbstractKafkaProducer.java @@ -99,6 +99,11 @@ protected Topic getTopic() { protected ProducerRecord buildRecord(K key, V value) { var record = new ProducerRecord<>(getTopic().getNamespacedTopic(), key, value); if (!headers.isEmpty()) { + logger.debug( + "Attaching {} header(s) to record for topic '{}': {}", + headers.size(), + getTopic().getNamespacedTopic(), + headers.keySet()); for (Header header : headers.entrySet().stream() .map(e -> (Header) new RecordHeader(e.getKey(), e.getValue().getBytes(StandardCharsets.UTF_8))) .toList()) { @@ -110,9 +115,17 @@ var record = new ProducerRecord<>(getTopic().getNamespacedTopic(), key, value); protected String resolvePayload() { if (inlinePayload != null && !inlinePayload.isEmpty()) { + logger.debug( + "Resolved inline payload ({} chars) for topic '{}'.", + inlinePayload.length(), + getTopic().getNamespacedTopic()); return inlinePayload; } if (payloadFile != null) { + logger.debug( + "Reading payload from file '{}' for topic '{}'.", + payloadFile.getPath(), + getTopic().getNamespacedTopic()); return FileUtils.getFileContent(payloadFile); } throw new ProducerException("No payload content was provided"); @@ -121,15 +134,24 @@ protected String resolvePayload() { protected String resolveSchema() throws IOException, RestClientException { SchemaRegistryClient client = SchemaRegistryClientFactory.createClient(); if (!StringUtils.isBlank(context.getSchemaName())) { - return client.getLatestSchemaMetadata(context.getSchemaName() + "-value") - .getSchema(); + String subject = context.getSchemaName() + "-value"; + logger.info("Resolving latest Avro schema for subject '{}' from Schema Registry.", subject); + return client.getLatestSchemaMetadata(subject).getSchema(); } String subject = context.getTopic().getNamespacedTopic() + "-value"; if (context.getSchemaVersion() == null || context.getSchemaVersion().isEmpty()) { + logger.info("Resolving latest Avro schema for subject '{}' from Schema Registry.", subject); return client.getLatestSchemaMetadata(subject).getSchema(); } else { - return client.getSchemaMetadata(subject, Integer.parseInt(context.getSchemaVersion())) - .getSchema(); + try { + int version = Integer.parseInt(context.getSchemaVersion()); + logger.info("Resolving Avro schema for subject '{}' (version {}) from Schema Registry.", subject, version); + return client.getSchemaMetadata(subject, version).getSchema(); + } catch (NumberFormatException e) { + throw new ProducerException( + "Invalid schema version '" + context.getSchemaVersion() + "' for subject '" + subject + "'. Expected an integer.", + e); + } } } } diff --git a/src/main/java/io/github/ktestify/io/kafka/KafkaRecordFetcher.java b/src/main/java/io/github/ktestify/io/kafka/KafkaRecordFetcher.java index 83f1955..54a847d 100644 --- a/src/main/java/io/github/ktestify/io/kafka/KafkaRecordFetcher.java +++ b/src/main/java/io/github/ktestify/io/kafka/KafkaRecordFetcher.java @@ -25,6 +25,7 @@ import io.github.ktestify.models.ConsumedRecord; import io.github.ktestify.models.MatchedRecord; import java.time.Duration; +import java.time.Instant; import java.util.*; import java.util.concurrent.ConcurrentHashMap; import java.util.concurrent.TimeUnit; @@ -158,8 +159,9 @@ public void close() { * an explicit reset, for example from the {@code clear known messages} step. */ public static void clearMatchedRecords() { + int count = MATCHED_RECORDS.size(); MATCHED_RECORDS.clear(); - log.debug("KafkaRecordFetcher: matched-records registry cleared."); + log.info("KafkaRecordFetcher: cleared {} record(s) from the matched-records deduplication registry.", count); } // ========================================================================= @@ -180,13 +182,17 @@ private void subscribeAndAwaitAssignment(long deadlineNanos) throws FetchExcepti long pollIntervalMs = frameworkConfig.getPollIntervalMillis(); while (kafkaConsumer.assignment().isEmpty()) { if (System.nanoTime() >= deadlineNanos) { + log.error( + "Timed out after {}ms waiting for partition assignment on topic '{}'.", + readTimeoutMs, + namespacedTopic); throw new FetchTimeoutException("Timed out after " + readTimeoutMs + "ms waiting for partition assignment on topic '" + namespacedTopic + "'. Check that the broker is reachable and the topic exists."); } kafkaConsumer.poll(Duration.ofMillis(pollIntervalMs)); } - log.debug("Partition assignment received for topic '{}'.", namespacedTopic); + log.info("Assigned partition(s) {} for topic '{}'.", kafkaConsumer.assignment(), namespacedTopic); } /** @@ -244,7 +250,11 @@ private long calculateDeltaTime() { */ private void seekToOffset(long deltaTimestamp, long deadlineNanos) { Set assignments = kafkaConsumer.assignment(); - log.debug(MESSAGE_CONSUMER_SEEKING_TO_OFFSET, deltaTimestamp); + log.info( + "Seeking partitions {} to timestamp {} ({})", + assignments, + deltaTimestamp, + Instant.ofEpochMilli(deltaTimestamp)); Map timestampMap = assignments.stream().collect(Collectors.toMap(tp -> tp, tp -> deltaTimestamp)); @@ -257,9 +267,14 @@ private void seekToOffset(long deltaTimestamp, long deadlineNanos) { log.trace(MESSAGE_CONSUMER_OFFSET_FOR_TIMESTAMP, offsetAndTimestamp); if (offsetAndTimestamp != null) { kafkaConsumer.seek(topicPartition, offsetAndTimestamp.offset()); + log.info( + "Partition {} seeked to offset {} (timestamp={}).", + topicPartition, + offsetAndTimestamp.offset(), + Instant.ofEpochMilli(offsetAndTimestamp.timestamp())); } else { kafkaConsumer.seekToEnd(Collections.singletonList(topicPartition)); - log.debug(MESSAGE_CONSUMER_OFFSETS_NULL_SEEK_TO_LATEST, topicPartition.partition()); + log.info(MESSAGE_CONSUMER_OFFSETS_NULL_SEEK_TO_LATEST, topicPartition.partition()); } }); } @@ -292,11 +307,15 @@ private List> pollUntilRecordFound(long deadlineNanos) throws } List> accumulated = new ArrayList<>(); - log.debug( - "Polling topic '{}' in {} mode, target={} record(s).", + log.info( + "Polling topic '{}' in {} mode (target={} record(s), timeout={}ms, expectedKey={}).", namespacedTopic, batchMode ? "BATCH" : "SINGLE", - targetSize); + targetSize, + readTimeoutMs, + context.getExpectedRecordKey() != null + ? "'" + context.getExpectedRecordKey() + "' (" + context.getKeyMatchStrategy() + ")" + : ""); while (System.nanoTime() < deadlineNanos) { ConsumerRecords batch = kafkaConsumer.poll(Duration.ofMillis(pollIntervalMs)); @@ -310,11 +329,18 @@ private List> pollUntilRecordFound(long deadlineNanos) throws } ConsumedRecord consumed = ConsumedRecord.fromKafkaRecord(record); if (!tryClaim(consumed)) { - log.debug(MESSAGE_CONSUMER_RECORD_ALREADY_MATCHED, consumed.toMatchedRecord()); + log.info(MESSAGE_CONSUMER_RECORD_ALREADY_MATCHED, consumed.toMatchedRecord()); continue; } - log.info(MESSAGE_CONSUMER_GOT_RECORD_WITH_KEY_AND_VALUE, record.key(), record.value()); + log.info( + "Claimed record from topic '{}' [partition={}, offset={}, key={}, timestamp={}].", + namespacedTopic, + record.partition(), + record.offset(), + record.key(), + Instant.ofEpochMilli(record.timestamp())); + log.debug(MESSAGE_CONSUMER_GOT_RECORD_WITH_KEY_AND_VALUE, record.key(), record.value()); accumulated.add(consumed); // In SINGLE mode return immediately on the first passing record. @@ -338,11 +364,18 @@ private List> pollUntilRecordFound(long deadlineNanos) throws if (!accumulated.isEmpty()) { // Partial batch: give the claimed records back before reporting the timeout. accumulated.forEach(this::release); + log.warn( + "Timed out after {}ms waiting for {} record(s) on topic '{}': only {} collected (released back to registry).", + readTimeoutMs, + targetSize, + namespacedTopic, + accumulated.size()); throw new FetchTimeoutException("Timed out after " + readTimeoutMs + "ms waiting for " + targetSize + " record(s) on topic '" + namespacedTopic + "': only " + accumulated.size() + " collected."); } + log.debug("Timed out after {}ms waiting for a record on topic '{}'.", readTimeoutMs, namespacedTopic); throw new FetchTimeoutException( "Timed out after " + readTimeoutMs + "ms waiting for a record on topic '" + namespacedTopic + "'."); } diff --git a/src/main/java/io/github/ktestify/io/kafka/impl/AvroKafkaProducer.java b/src/main/java/io/github/ktestify/io/kafka/impl/AvroKafkaProducer.java index faf2246..a2f09d9 100644 --- a/src/main/java/io/github/ktestify/io/kafka/impl/AvroKafkaProducer.java +++ b/src/main/java/io/github/ktestify/io/kafka/impl/AvroKafkaProducer.java @@ -73,6 +73,12 @@ protected void produce() { JsonObject payload = AvroUtils.getJsonElementFromFile(resolvePayload()).getAsJsonObject(); GenericRecord recordValue = (GenericRecord) AvroUtils.convertJsonToAvro(payload, schema); + logger.debug( + "Producing Avro record to topic '{}' with key '{}' and schema '{}':\n{}", + getTopic().getNamespacedTopic(), + context.getRecordKey(), + schema.getFullName(), + recordValue); ProducerRecord record = buildRecord(context.getRecordKey(), recordValue); RecordMetadata metadata = producer.send(record).get(); logger.info( @@ -84,11 +90,23 @@ protected void produce() { metadata.timestamp()); } catch (InterruptedException e) { Thread.currentThread().interrupt(); + logger.error( + "Interrupted while producing Avro message to topic '{}'", + getTopic().getNamespacedTopic(), + e); throw new ProducerException("Interrupted while producing Avro message", e); } catch (ExecutionException e) { + logger.error( + "Failed to produce Avro message to topic '{}': {}", + getTopic().getNamespacedTopic(), + e.getCause() != null ? e.getCause().getMessage() : e.getMessage()); throw new ProducerException("Failed to produce Avro message", e.getCause()); } catch (IOException | RestClientException e) { + logger.error( + "Failed to read schema or payload for Avro message on topic '{}': {}", + getTopic().getNamespacedTopic(), + e.getMessage()); throw new ProducerException("Failed to read schema or payload for Avro message", e); } } diff --git a/src/main/java/io/github/ktestify/io/kafka/impl/RawKafkaProducer.java b/src/main/java/io/github/ktestify/io/kafka/impl/RawKafkaProducer.java index 2ee419f..052e512 100644 --- a/src/main/java/io/github/ktestify/io/kafka/impl/RawKafkaProducer.java +++ b/src/main/java/io/github/ktestify/io/kafka/impl/RawKafkaProducer.java @@ -58,6 +58,11 @@ protected void produce() { try { String payload = resolvePayload(); String key = context.getRecordKey(); + logger.debug( + "Producing raw record to topic '{}' with key '{}':\n{}", + getTopic().getNamespacedTopic(), + key, + payload); ProducerRecord record = buildRecord(key, payload); RecordMetadata metadata = producer.send(record).get(); logger.info( @@ -69,8 +74,16 @@ protected void produce() { metadata.timestamp()); } catch (InterruptedException e) { Thread.currentThread().interrupt(); + logger.error( + "Interrupted while producing raw message to topic '{}'", + getTopic().getNamespacedTopic(), + e); throw new ProducerException("Interrupted while producing raw message", e); } catch (ExecutionException e) { + logger.error( + "Failed to produce raw message to topic '{}': {}", + getTopic().getNamespacedTopic(), + e.getCause() != null ? e.getCause().getMessage() : e.getMessage()); throw new ProducerException("Failed to produce raw message", e.getCause()); } } diff --git a/src/main/java/io/github/ktestify/match/impl/AvroFieldsRecordMatcher.java b/src/main/java/io/github/ktestify/match/impl/AvroFieldsRecordMatcher.java index 5639706..90ef907 100644 --- a/src/main/java/io/github/ktestify/match/impl/AvroFieldsRecordMatcher.java +++ b/src/main/java/io/github/ktestify/match/impl/AvroFieldsRecordMatcher.java @@ -71,8 +71,14 @@ public MatchResult match(List> records, MatchConte String actualValue = AvroJson.of(value); log.debug("Avro field match against inline value, key: '{}', expected: '{}'", key, expected); if (AvroUtils.doesAvroValueFromKeyMatchesRecord(expected, key, actualValue)) { + log.info("Avro field '{}' matches expected value '{}'.", key, expected); return MatchResult.pass(expected, actualValue); } + log.error( + "Avro field '{}' does not match expected value '{}'.\nActual record:\n{}", + key, + expected, + actualValue); return MatchResult.fail( "Avro field '" + key + "' does not match expected value '" + expected + "'.", expected, @@ -93,8 +99,15 @@ public MatchResult match(List> records, MatchConte String actualValue = AvroJson.of(value); log.debug("Avro field match against file, key: '{}', file: '{}'", key, context.getMatchFilePath()); if (AvroUtils.doesAvroValueFromKeyMatchesRecords(key, expectedRecord, actualValue)) { + log.info("Avro field '{}' matches expected file '{}'.", key, context.getMatchFilePath()); return MatchResult.pass(expectedRecord, actualValue); } + log.error( + "Avro field '{}' does not match expected file '{}'.\nExpected record:\n{}\nActual record:\n{}", + key, + context.getMatchFilePath(), + expectedRecord, + actualValue); return MatchResult.fail( "Avro field '" + key + "' does not match fields in file '" + context.getMatchFilePath() + "'.", expectedRecord, @@ -137,8 +150,14 @@ private MatchResult matchMultipleFields(List> reco } if (mismatches.isEmpty()) { + log.info("All {} Avro field(s) matched expected values: {}.", keyValues.size(), keyValues); return MatchResult.pass(keyValues.toString(), actualValue); } + log.error( + "Avro multi-field match failed ({} mismatch(es)): {}\nActual record:\n{}", + mismatches.size(), + String.join(" ", mismatches), + actualValue); return MatchResult.fail(String.join(" ", mismatches), keyValues.toString(), actualValue); } } diff --git a/src/main/java/io/github/ktestify/match/impl/AvroFileRecordMatcher.java b/src/main/java/io/github/ktestify/match/impl/AvroFileRecordMatcher.java index 5c2a5de..d488bc0 100644 --- a/src/main/java/io/github/ktestify/match/impl/AvroFileRecordMatcher.java +++ b/src/main/java/io/github/ktestify/match/impl/AvroFileRecordMatcher.java @@ -145,7 +145,7 @@ private MatchResult matchBatchLazy( int matchedIndex = -1; for (int j = 0; j < filePaths.size(); j++) { - if (!matchedFiles[j] && matchesExpectedContent(expectedContents.get(j), actualValue, context)) { + if (!matchedFiles[j] && matchesExpectedContentQuietly(expectedContents.get(j), actualValue, context)) { matchedIndex = j; break; } @@ -168,9 +168,10 @@ private MatchResult matchBatchLazy( } } log.error( - "Avro record at index {} did not match any remaining expected file. Unmatched files: {}", + "Avro record at index {} did not match any remaining expected file. Unmatched files: {}\nActual record:\n{}", i, - unmatchedFiles); + unmatchedFiles, + actualValue); return MatchResult.fail( "Record at index " + i + " did not match any remaining expected file. Unmatched files: " + unmatchedFiles, @@ -189,4 +190,12 @@ private boolean matchesExpectedContent(String expectedValue, String actualValue, } return AvroUtils.doesAvroRecordsSmartMatches(expectedValue, actualValue); } + + private boolean matchesExpectedContentQuietly(String expectedValue, String actualValue, MatchContext context) { + if (context.getExcludedFields() != null && !context.getExcludedFields().isEmpty()) { + return AvroUtils.doesAvroRecordsSmartMatchesWithExclusionsQuietly( + expectedValue, actualValue, context.getExcludedFields()); + } + return AvroUtils.doesAvroRecordsSmartMatchesQuietly(expectedValue, actualValue); + } } diff --git a/src/main/java/io/github/ktestify/match/impl/FieldsRecordMatcher.java b/src/main/java/io/github/ktestify/match/impl/FieldsRecordMatcher.java index 38d5bf2..e0a2b7b 100644 --- a/src/main/java/io/github/ktestify/match/impl/FieldsRecordMatcher.java +++ b/src/main/java/io/github/ktestify/match/impl/FieldsRecordMatcher.java @@ -72,8 +72,10 @@ public MatchResult match(List> records, MatchContext cont log.debug("Fields match: expected='{}', actual='{}'", expectedField, actualField); if (expectedField.equals(actualField)) { + log.info("Field at {} matches expected value '{}'.", position, expectedField); return MatchResult.pass(expectedField, actualField); } + log.error("Field at {} does not match: expected '{}', actual '{}'.", position, expectedField, actualField); return MatchResult.fail("Field at " + position + " does not match.", expectedField, actualField); } diff --git a/src/main/java/io/github/ktestify/match/impl/XPathRecordMatcher.java b/src/main/java/io/github/ktestify/match/impl/XPathRecordMatcher.java index e862e77..da78e27 100644 --- a/src/main/java/io/github/ktestify/match/impl/XPathRecordMatcher.java +++ b/src/main/java/io/github/ktestify/match/impl/XPathRecordMatcher.java @@ -70,8 +70,16 @@ public MatchResult match(List> records, MatchContext cont boolean result = XMLUtils.compareXMLByXPaths(actual, expected, context.getExcludedFields()); if (result) { + log.info( + "XML XPath comparison passed against '{}' for XPath(s): {}.", + context.getMatchFilePath(), + context.getExcludedFields()); return MatchResult.pass(expected, actual); } + log.error( + "XML XPath comparison failed against '{}' for XPath(s): {}.", + context.getMatchFilePath(), + context.getExcludedFields()); return MatchResult.fail( "XML XPath comparison failed (XPaths: " + context.getExcludedFields() + ").", expected, actual); } diff --git a/src/main/java/io/github/ktestify/match/impl/XmlRecordMatcher.java b/src/main/java/io/github/ktestify/match/impl/XmlRecordMatcher.java index 09a5bd9..49b25ea 100644 --- a/src/main/java/io/github/ktestify/match/impl/XmlRecordMatcher.java +++ b/src/main/java/io/github/ktestify/match/impl/XmlRecordMatcher.java @@ -75,15 +75,20 @@ public MatchResult match(List> records, MatchContext cont boolean result; if (!effectiveExclusions.isEmpty()) { - log.debug("Excluding XML elements: {}", effectiveExclusions); + log.info("Excluding XML elements from comparison: {}", effectiveExclusions); result = XMLUtils.compareXML(actual, expected, effectiveExclusions); } else { result = XMLUtils.compareXML(actual, expected); } if (result) { + log.info("XML record matches expected file '{}'.", context.getMatchFilePath()); return MatchResult.pass(expected, actual); } + log.error( + "XML record does not match expected file '{}' (excluded: {}).", + context.getMatchFilePath(), + effectiveExclusions); return MatchResult.fail( "XML documents do not match (excluded: " + effectiveExclusions + ").", expected, actual); } diff --git a/src/main/java/io/github/ktestify/utils/XMLUtils.java b/src/main/java/io/github/ktestify/utils/XMLUtils.java index 8e9f395..334ac41 100644 --- a/src/main/java/io/github/ktestify/utils/XMLUtils.java +++ b/src/main/java/io/github/ktestify/utils/XMLUtils.java @@ -271,7 +271,7 @@ public static boolean compareXMLByXPaths(String actualValue, String expectedValu private static void logDiff(Diff diff) { for (Difference difference : diff.getDifferences()) { Comparison c = difference.getComparison(); - LOGGER.debug( + LOGGER.error( """ Difference found: ----------------------------------- diff --git a/src/main/java/io/github/ktestify/utils/serdes/AvroUtils.java b/src/main/java/io/github/ktestify/utils/serdes/AvroUtils.java index cbad55b..e3ef30d 100644 --- a/src/main/java/io/github/ktestify/utils/serdes/AvroUtils.java +++ b/src/main/java/io/github/ktestify/utils/serdes/AvroUtils.java @@ -258,6 +258,41 @@ public static boolean doesAvroRecordsSmartMatchesWithExclusions( return deepEquals(expectedMap, actualMap, excludedKeys); } + /** + * Quiet variant of {@link #doesAvroRecordsSmartMatches(String, String)} used when probing multiple candidate files + * or array elements so that non-matching candidates log at DEBUG instead of ERROR. + * + * @param expectedRecord the expected Avro record in JSON format + * @param actualRecord the actual Avro record in JSON format + * @return true if the records match semantically, false otherwise + * @since 1.2.6 + */ + public static boolean doesAvroRecordsSmartMatchesQuietly( + @NonNull String expectedRecord, @NonNull String actualRecord) { + return doesAvroRecordsSmartMatchesWithExclusionsQuietly(expectedRecord, actualRecord, Collections.emptyList()); + } + + /** + * Quiet variant of {@link #doesAvroRecordsSmartMatchesWithExclusions(String, String, List)} used when probing + * multiple candidate files or array elements so that non-matching candidates log at DEBUG instead of ERROR. + * + * @param expectedRecord the expected Avro record in JSON format + * @param actualRecord the actual Avro record in JSON format + * @param excludedKeys list of keys to exclude from comparison + * @return true if the records match (excluding specified keys), false otherwise + * @since 1.2.6 + */ + public static boolean doesAvroRecordsSmartMatchesWithExclusionsQuietly( + @NonNull String expectedRecord, @NonNull String actualRecord, @NonNull List excludedKeys) { + Objects.requireNonNull(expectedRecord, AVRO_UTILS_EXPECTED_RECORD_NULL); + Objects.requireNonNull(actualRecord, AVRO_UTILS_ACTUAL_RECORD_NULL); + Objects.requireNonNull(excludedKeys, "Excluded keys list cannot be null"); + + var expectedConverted = convertDatesToTimestamps(new HashMap<>(convertJsonToMap(expectedRecord))); + var actualConverted = convertDatesToTimestamps(new HashMap<>(convertJsonToMap(actualRecord))); + return performDeepEqualsComparison(expectedConverted, actualConverted, excludedKeys, "", false); + } + /** * Performs deep equality comparison between two maps representing Avro records. * @@ -279,7 +314,7 @@ public static boolean deepEquals( var expectedConverted = convertDatesToTimestamps(new HashMap<>(expectedValueMap)); var actualConverted = convertDatesToTimestamps(new HashMap<>(actualValueMap)); - return performDeepEqualsComparison(expectedConverted, actualConverted, Collections.emptyList(), ""); + return performDeepEqualsComparison(expectedConverted, actualConverted, Collections.emptyList(), "", true); } /** @@ -320,7 +355,7 @@ public static boolean deepEquals( var expectedConverted = convertDatesToTimestamps(new HashMap<>(expectedValueMap)); var actualConverted = convertDatesToTimestamps(new HashMap<>(actualValueMap)); - return performDeepEqualsComparison(expectedConverted, actualConverted, excludedKeys, ""); + return performDeepEqualsComparison(expectedConverted, actualConverted, excludedKeys, "", true); } // =========================================== @@ -551,7 +586,8 @@ private static boolean performDeepEqualsComparison( Map expectedValueMap, Map actualValueMap, List excludedKeys, - String parentPath) { + String parentPath, + boolean logErrors) { long expectedExcludedCount = expectedValueMap.keySet().stream() .filter(k -> isKeyExcluded(k, buildQualifiedKey(parentPath, k), excludedKeys)) @@ -564,7 +600,7 @@ private static boolean performDeepEqualsComparison( long effectiveActualSize = actualValueMap.size() - actualExcludedCount; if (effectiveExpectedSize != effectiveActualSize) { - LOGGER.error(AVRO_UTILS_RECORD_MISMATCH); + logMismatch(logErrors, AVRO_UTILS_RECORD_MISMATCH); if (LOGGER.isDebugEnabled()) { LOGGER.debug( AVRO_UTILS_RECORD_MISMATCH_DETAILS, @@ -578,7 +614,7 @@ private static boolean performDeepEqualsComparison( } if (expectedValueMap.equals(actualValueMap)) { - LOGGER.info(AVRO_UTILS_VALUES_STRICTLY_MATCH); + LOGGER.debug(AVRO_UTILS_VALUES_STRICTLY_MATCH); return true; } @@ -591,14 +627,14 @@ private static boolean performDeepEqualsComparison( } if (!actualValueMap.containsKey(key)) { - LOGGER.error("Missing key {} in actual value", key); + logMismatch(logErrors, "Missing key '{}' in actual value (path: '{}')", key, qualifiedKey); return false; } var expectedValue = entry.getValue(); var actualValue = actualValueMap.get(key); - if (!compareValues(expectedValue, actualValue, excludedKeys, key, qualifiedKey)) { + if (!compareValues(expectedValue, actualValue, excludedKeys, key, qualifiedKey, logErrors)) { return false; } } @@ -654,7 +690,12 @@ private static boolean isKeyExcluded(String key, String qualifiedKey, List excludedKeys, String key, String qualifiedKey) { + Object expectedValue, + Object actualValue, + List excludedKeys, + String key, + String qualifiedKey, + boolean logErrors) { if (expectedValue instanceof Map && actualValue instanceof Map) { LOGGER.debug( AVRO_UTILS_NESTED_OBJECT_FOUND, expectedValue.getClass().getSimpleName()); @@ -662,7 +703,8 @@ private static boolean compareValues( (Map) expectedValue, (Map) actualValue, excludedKeys, - qualifiedKey)) { + qualifiedKey, + logErrors)) { LOGGER.debug(AVRO_UTILS_NESTED_OBJECT_NOT_MATCH); return false; } @@ -671,16 +713,18 @@ private static boolean compareValues( AVRO_UTILS_NESTED_OBJECT_FOUND + " key : {}", expectedValue.getClass().getSimpleName(), key); - if (!deepEqualsList((List) expectedValue, (List) actualValue, excludedKeys, qualifiedKey)) { - LOGGER.error("Value mismatch for key {} values does not match for a list", key); + if (!deepEqualsList( + (List) expectedValue, (List) actualValue, excludedKeys, qualifiedKey, logErrors)) { + logMismatch(logErrors, "Value mismatch for key {}: list values do not match", qualifiedKey); return false; } } else if (actualValue instanceof Instant actualInstant && expectedValue instanceof String expectedString) { var parsedExpected = parseExpectedInstant(expectedString); if (parsedExpected == null || !parsedExpected.equals(actualInstant)) { - LOGGER.error( + logMismatch( + logErrors, AVRO_UTILS_VALUES_MISMATCH_WITH_CLASS_NAMES, - key, + qualifiedKey, expectedValue, expectedValue.getClass().getSimpleName(), actualValue, @@ -691,9 +735,10 @@ private static boolean compareValues( && expectedValue instanceof String expectedString) { var parsedExpected = parseExpectedLocalDateTime(expectedString); if (parsedExpected == null || !parsedExpected.equals(actualLocalDateTime)) { - LOGGER.error( + logMismatch( + logErrors, AVRO_UTILS_VALUES_MISMATCH_WITH_CLASS_NAMES, - key, + qualifiedKey, expectedValue, expectedValue.getClass().getSimpleName(), actualValue, @@ -703,9 +748,10 @@ private static boolean compareValues( } else if (actualValue instanceof LocalDate actualLocalDate && expectedValue instanceof String expectedString) { var parsedExpected = parseExpectedLocalDate(expectedString); if (parsedExpected == null || !parsedExpected.equals(actualLocalDate)) { - LOGGER.error( + logMismatch( + logErrors, AVRO_UTILS_VALUES_MISMATCH_WITH_CLASS_NAMES, - key, + qualifiedKey, expectedValue, expectedValue.getClass().getSimpleName(), actualValue, @@ -714,13 +760,14 @@ private static boolean compareValues( } } else if (expectedValue == null) { if (actualValue != null) { - LOGGER.error(AVRO_UTILS_VALUES_MISMATCH_SHOULD_BE_NULL, key, actualValue); + logMismatch(logErrors, AVRO_UTILS_VALUES_MISMATCH_SHOULD_BE_NULL, qualifiedKey, actualValue); return false; } } else if (!expectedValue.equals(actualValue)) { - LOGGER.error( + logMismatch( + logErrors, AVRO_UTILS_VALUES_MISMATCH_WITH_CLASS_NAMES, - key, + qualifiedKey, expectedValue, expectedValue.getClass().getSimpleName(), actualValue, @@ -731,6 +778,14 @@ private static boolean compareValues( return true; } + private static void logMismatch(boolean logErrors, String format, Object... args) { + if (logErrors) { + LOGGER.error(format, args); + } else { + LOGGER.debug(format, args); + } + } + /** * Parses an expected date string as an {@link Instant}, trying several supported precisions. * @@ -818,20 +873,25 @@ private static LocalDate parseExpectedLocalDate(String expectedValue) { * @return true if lists are equal, false otherwise */ private static boolean deepEqualsList( - List expectedList, List actualList, List excludedKeys, String parentPath) { + List expectedList, + List actualList, + List excludedKeys, + String parentPath, + boolean logErrors) { if (expectedList.size() != actualList.size()) { - LOGGER.error("List size mismatch. Expected: {}, Actual: {}", expectedList.size(), actualList.size()); + logMismatch( + logErrors, "List size mismatch. Expected: {}, Actual: {}", expectedList.size(), actualList.size()); return false; } // For primitive arrays or mixed types, fall back to ordered comparison if (expectedList.isEmpty() || !isObjectArray(expectedList)) { - return deepEqualsListOrdered(expectedList, actualList, excludedKeys, parentPath); + return deepEqualsListOrdered(expectedList, actualList, excludedKeys, parentPath, logErrors); } // Smart matching for object arrays - match regardless of order - return deepEqualsListUnordered(expectedList, actualList, excludedKeys, parentPath); + return deepEqualsListUnordered(expectedList, actualList, excludedKeys, parentPath, logErrors); } /** @@ -854,7 +914,11 @@ private static boolean isObjectArray(List list) { * @return true if lists are equal in order, false otherwise */ private static boolean deepEqualsListOrdered( - List expectedList, List actualList, List excludedKeys, String parentPath) { + List expectedList, + List actualList, + List excludedKeys, + String parentPath, + boolean logErrors) { LOGGER.debug("Performing ordered array comparison for {} expected objects", expectedList.size()); for (int i = 0; i < expectedList.size(); i++) { var expected = expectedList.get(i); @@ -862,11 +926,16 @@ private static boolean deepEqualsListOrdered( if (expected instanceof Map && actual instanceof Map) { if (!performDeepEqualsComparison( - (Map) expected, (Map) actual, excludedKeys, parentPath)) { + (Map) expected, + (Map) actual, + excludedKeys, + parentPath, + logErrors)) { return false; } } else if (!Objects.equals(expected, actual)) { - LOGGER.error("List element mismatch at index {}. Expected: {}, Actual: {}", i, expected, actual); + logMismatch( + logErrors, "List element mismatch at index {}. Expected: {}, Actual: {}", i, expected, actual); return false; } } @@ -885,7 +954,11 @@ private static boolean deepEqualsListOrdered( * @return true if all expected objects find matches in actual list, false otherwise */ private static boolean deepEqualsListUnordered( - List expectedList, List actualList, List excludedKeys, String parentPath) { + List expectedList, + List actualList, + List excludedKeys, + String parentPath, + boolean logErrors) { LOGGER.debug("Performing smart unordered array comparison for {} expected objects", expectedList.size()); // Keep track of which actual objects have been matched @@ -904,7 +977,7 @@ private static boolean deepEqualsListUnordered( var actualObject = (Map) actualList.get(actualIndex); - if (performDeepEqualsComparison(expectedObject, actualObject, excludedKeys, parentPath)) { + if (performDeepEqualsComparison(expectedObject, actualObject, excludedKeys, parentPath, false)) { LOGGER.debug( "Found match for expected object at index {} with actual object at index {}", expectedIndex, @@ -916,7 +989,8 @@ private static boolean deepEqualsListUnordered( } if (!foundMatch) { - LOGGER.error( + logMismatch( + logErrors, "No matching object found in actual list for expected object at index {}: \n {}", expectedIndex, expectedObject); @@ -986,8 +1060,19 @@ public static boolean doesAvroValueFromKeyMatchesRecord( return matchNestedValue(expectedValue, nestedKey, actualValueMap); } else { LOGGER.debug(AVRO_UTILS_EXPECTED_KEY_CONTAINED_IN_MAIN_OBJECT, nestedKey); - return actualValueMap.containsKey(nestedKey) - && expectedValue.equals(String.valueOf(actualValueMap.get(nestedKey))); + if (!actualValueMap.containsKey(nestedKey)) { + LOGGER.error("Avro field '{}' is missing in actual record.", nestedKey); + return false; + } + Object actualVal = actualValueMap.get(nestedKey); + boolean matches = expectedValue.equals(String.valueOf(actualVal)); + if (!matches) { + LOGGER.error( + "Avro field '{}' mismatch: expected '{}', actual '{}'", nestedKey, expectedValue, actualVal); + } else { + LOGGER.debug("Avro field '{}' matched value '{}'.", nestedKey, expectedValue); + } + return matches; } } @@ -1060,7 +1145,17 @@ private static boolean matchNestedValue( actual = ((Map) actual).get(key); } - return actual != null && expectedValue.equals(String.valueOf(actual)); + boolean matches = actual != null && expectedValue.equals(String.valueOf(actual)); + if (!matches) { + LOGGER.error( + "Nested Avro field '{}' mismatch: expected '{}', actual '{}'", + nestedKey, + expectedValue, + actual); + } else { + LOGGER.debug("Nested Avro field '{}' matched value '{}'.", nestedKey, expectedValue); + } + return matches; } catch (ClassCastException e) { LOGGER.error("Error traversing nested objects", e); return false; @@ -1080,7 +1175,19 @@ private static boolean matchNestedValue( */ private static boolean matchValue( String key, Map expectedValueMap, Map actualValueMap) { - return expectedValueMap.containsKey(key) && Objects.equals(expectedValueMap.get(key), actualValueMap.get(key)); + if (!expectedValueMap.containsKey(key)) { + LOGGER.error("Key '{}' is not present in expected Avro record.", key); + return false; + } + Object expectedVal = expectedValueMap.get(key); + Object actualVal = actualValueMap.get(key); + boolean matches = Objects.equals(expectedVal, actualVal); + if (!matches) { + LOGGER.error("Avro field '{}' mismatch: expected '{}', actual '{}'", key, expectedVal, actualVal); + } else { + LOGGER.debug("Avro field '{}' matched value '{}'.", key, expectedVal); + } + return matches; } // =========================================== diff --git a/src/test/java/io/github/ktestify/io/kafka/KafkaProducerConsumerUnitTest.java b/src/test/java/io/github/ktestify/io/kafka/KafkaProducerConsumerUnitTest.java new file mode 100644 index 0000000..79a0b32 --- /dev/null +++ b/src/test/java/io/github/ktestify/io/kafka/KafkaProducerConsumerUnitTest.java @@ -0,0 +1,185 @@ +/* + * Copyright 2026 Nil MALHOMME (malhomme.nil+oss@icloud.com) + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ +package io.github.ktestify.io.kafka; + +import static org.junit.jupiter.api.Assertions.*; + +import io.github.ktestify.exceptions.ConsumerException; +import io.github.ktestify.exceptions.ProducerException; +import io.github.ktestify.io.kafka.impl.AvroKafkaConsumer; +import io.github.ktestify.io.kafka.impl.RawKafkaConsumer; +import io.github.ktestify.io.kafka.impl.RawKafkaProducer; +import io.github.ktestify.match.BatchMatchStrategy; +import io.github.ktestify.match.KeyMatchStrategy; +import io.github.ktestify.match.RecordMatcherFactory; +import io.github.ktestify.models.Topic; +import java.io.File; +import java.nio.charset.StandardCharsets; +import java.nio.file.Files; +import java.nio.file.Path; +import java.time.Duration; +import java.util.List; +import java.util.Map; +import org.apache.avro.generic.GenericRecord; +import org.apache.kafka.clients.consumer.ConsumerRecord; +import org.apache.kafka.clients.consumer.MockConsumer; +import org.apache.kafka.clients.consumer.OffsetAndTimestamp; +import org.apache.kafka.clients.consumer.internals.AutoOffsetResetStrategy; +import org.apache.kafka.clients.producer.MockProducer; +import org.apache.kafka.common.TopicPartition; +import org.apache.kafka.common.serialization.StringSerializer; +import org.junit.jupiter.api.DisplayName; +import org.junit.jupiter.api.Test; +import org.junit.jupiter.api.io.TempDir; + +@DisplayName("Kafka Producer and Consumer Unit Tests") +class KafkaProducerConsumerUnitTest { + + @TempDir + Path tempDir; + + @Test + @DisplayName("RawKafkaProducer sends inline and file payloads with headers using MockProducer") + void rawKafkaProducerSendsWithHeaders() throws Exception { + MockProducer mockProducer = + new MockProducer<>(true, null, new StringSerializer(), new StringSerializer()); + Topic topic = + Topic.builder().topicName("orders").topicType(Topic.Type.INPUT).build(); + + File payloadFile = tempDir.resolve("payload.json").toFile(); + Files.writeString(payloadFile.toPath(), "{\"orderId\":\"ORD-1\"}", StandardCharsets.UTF_8); + + ProducerContext ctx = ProducerContext.builder() + .topic(topic) + .producer(mockProducer) + .payloadFile(payloadFile) + .recordKey("key-1") + .headers(Map.of("traceId", "abc-123")) + .build(); + + new RawKafkaProducer(ctx).send(); + assertEquals(1, mockProducer.history().size()); + assertEquals("key-1", mockProducer.history().getFirst().key()); + + RawKafkaProducer inlineProducer = + new RawKafkaProducer(topic, Map.of(), mockProducer, null, Map.of(), "{\"inline\":true}"); + inlineProducer.send(); + assertEquals(2, mockProducer.history().size()); + } + + @Test + @DisplayName("RawKafkaProducer wraps ExecutionException in ProducerException") + void rawKafkaProducerHandlesSendFailure() { + MockProducer mockProducer = + new MockProducer<>(false, null, new StringSerializer(), new StringSerializer()); + Topic topic = + Topic.builder().topicName("orders").topicType(Topic.Type.INPUT).build(); + + ProducerContext ctx = ProducerContext.builder() + .topic(topic) + .producer(mockProducer) + .payload("{\"orderId\":\"ORD-1\"}") + .build(); + + RawKafkaProducer producer = new RawKafkaProducer(ctx); + Thread completer = new Thread(() -> { + while (mockProducer.history().isEmpty()) { + Thread.onSpinWait(); + } + mockProducer.errorNext(new RuntimeException("broker down")); + }); + completer.start(); + + assertThrows(ProducerException.class, producer::send); + } + + @Test + @DisplayName("RawKafkaConsumer fetches and matches records via MockConsumer") + void rawKafkaConsumerFetchesAndMatches() throws Exception { + KafkaRecordFetcher.clearMatchedRecords(); + TopicPartition tp = new TopicPartition("orders-out", 0); + MockConsumer mockConsumer = new MockConsumer<>(AutoOffsetResetStrategy.EARLIEST.name()) { + @Override + public Map offsetsForTimes( + Map timestampsToSearch, Duration timeout) { + return Map.of(tp, new OffsetAndTimestamp(0L, System.currentTimeMillis())); + } + }; + + File expectedFile = tempDir.resolve("expected.json").toFile(); + Files.writeString(expectedFile.toPath(), "{\"orderId\":\"ORD-1\"}", StandardCharsets.UTF_8); + + mockConsumer.schedulePollTask(() -> { + mockConsumer.rebalance(List.of(tp)); + mockConsumer.updateBeginningOffsets(Map.of(tp, 0L)); + mockConsumer.updateEndOffsets(Map.of(tp, 1L)); + }); + mockConsumer.schedulePollTask(() -> { + mockConsumer.addRecord(new ConsumerRecord<>("orders-out", 0, 0L, "key-1", "{\"orderId\":\"ORD-1\"}")); + }); + + Topic topic = Topic.builder() + .topicName("orders-out") + .topicType(Topic.Type.OUTPUT) + .build(); + + ConsumerContext ctx = ConsumerContext.builder() + .topic(topic) + .consumer(mockConsumer) + .matchMethod(RecordMatcherFactory.METHOD_MATCH_FILE) + .matchFilePath(expectedFile.getAbsolutePath()) + .expectedRecordKey("key-1") + .keyMatchStrategy(KeyMatchStrategy.EXACT) + .batchMatchStrategy(BatchMatchStrategy.POSITIONAL) + .readTimeout(2000L) + .consumerDeltaTime(10000L) + .referenceTimestamp(System.currentTimeMillis()) + .build(); + + RawKafkaConsumer consumer = new RawKafkaConsumer(ctx); + assertTrue(consumer.call()); + } + + @Test + @DisplayName("AvroKafkaConsumer resolves default matcher and rejects INPUT topic") + void avroKafkaConsumerContextValidation() { + MockConsumer mockConsumer = new MockConsumer<>(AutoOffsetResetStrategy.EARLIEST.name()); + Topic outputTopic = Topic.builder() + .topicName("avro-out") + .topicType(Topic.Type.OUTPUT) + .build(); + + ConsumerContext ctx = ConsumerContext.builder() + .topic(outputTopic) + .consumer(mockConsumer) + .matchMethod(RecordMatcherFactory.METHOD_MATCH_FILE) + .matchFilePaths(List.of("dummy.json")) + .excludedFields(List.of("ts")) + .isBatchConsumer(false) + .batchSize(1) + .build(); + + AvroKafkaConsumer avroConsumer = new AvroKafkaConsumer(ctx); + assertNotNull(avroConsumer); + + assertThrows( + ConsumerException.class, + () -> ConsumerContext.builder() + .topic(outputTopic) + .consumer(null) + .build()); + } +} diff --git a/src/test/java/io/github/ktestify/match/impl/AvroFileRecordMatcherTest.java b/src/test/java/io/github/ktestify/match/impl/AvroFileRecordMatcherTest.java index c1a65e2..ba66a8c 100644 --- a/src/test/java/io/github/ktestify/match/impl/AvroFileRecordMatcherTest.java +++ b/src/test/java/io/github/ktestify/match/impl/AvroFileRecordMatcherTest.java @@ -164,6 +164,18 @@ void batchLazyPassOutOfOrder() throws ComparisonException { assertTrue(result.isPassed()); } + @Test + @DisplayName("passes in LAZY mode with excluded fields when Avro records are out of order") + void batchLazyPassWithExcludedFields() throws ComparisonException { + MatchContext ctx = MatchContext.builder() + .matchFilePaths(BATCH_FILES) + .batchMatchStrategy(BatchMatchStrategy.LAZY) + .excludedFields(List.of("status")) + .build(); + MatchResult result = matcher.match(avroRecords(r3, r1, r2), ctx); + assertTrue(result.isPassed()); + } + @Test @DisplayName("fails in LAZY mode when duplicate Avro record cannot match remaining files") void batchLazyFailOnDuplicateRecord() throws ComparisonException { diff --git a/src/test/java/io/github/ktestify/utils/serdes/AvroUtilsTest.java b/src/test/java/io/github/ktestify/utils/serdes/AvroUtilsTest.java index d31e2c4..91e86a4 100644 --- a/src/test/java/io/github/ktestify/utils/serdes/AvroUtilsTest.java +++ b/src/test/java/io/github/ktestify/utils/serdes/AvroUtilsTest.java @@ -2890,5 +2890,45 @@ void shouldAccountForEffectiveSize_WhenNestedFieldExcludedViaDotNotation() { assertTrue(AvroUtils.deepEquals(expected, actual, List.of("RootField.NestedField2"))); } + + @Test + @DisplayName("deepEquals - unordered object list matching should not emit ERROR logs when candidates match") + void shouldNotEmitErrorLogsWhenUnorderedListMatches() { + String expectedJson = "{\"items\": [{\"id\": 1, \"name\": \"first\"}, {\"id\": 2, \"name\": \"second\"}]}"; + String actualJson = "{\"items\": [{\"id\": 2, \"name\": \"second\"}, {\"id\": 1, \"name\": \"first\"}]}"; + + var ctx = + (org.apache.logging.log4j.core.LoggerContext) org.apache.logging.log4j.LogManager.getContext(false); + var loggerConfig = ctx.getConfiguration().getLoggerConfig(AvroUtils.class.getName()); + List errorEvents = new ArrayList<>(); + var appender = + new org.apache.logging.log4j.core.appender.AbstractAppender( + "avro-test-appender", null, null, true, null) { + @Override + public void append(org.apache.logging.log4j.core.LogEvent event) { + if (event.getLevel() == org.apache.logging.log4j.Level.ERROR) { + errorEvents.add(event.toImmutable()); + } + } + }; + appender.start(); + loggerConfig.addAppender(appender, org.apache.logging.log4j.Level.ALL, null); + ctx.updateLoggers(); + try { + assertTrue(AvroUtils.doesAvroRecordsSmartMatches(expectedJson, actualJson)); + assertTrue( + errorEvents.isEmpty(), + "Expected no ERROR logs during successful unordered list comparison, got: " + errorEvents); + + assertFalse(AvroUtils.doesAvroRecordsSmartMatchesQuietly( + "{\"items\": [{\"id\": 1}]}", "{\"items\": [{\"id\": 99}]}")); + assertTrue( + errorEvents.isEmpty(), "Expected no ERROR logs during quiet comparison, got: " + errorEvents); + } finally { + loggerConfig.removeAppender("avro-test-appender"); + appender.stop(); + ctx.updateLoggers(); + } + } } }