ACS-8766: Adjust live-ingester logging to be more descriptive in case of error

.secrets.baseline

@@ -227,15 +227,15 @@
         "filename": "distribution/src/main/resources/docker-compose/docker-compose.yml",
         "hashed_secret": "40f81ac66c7cb246ded7b83e15ca0bf5d7f57eee",
         "is_verified": false,
-        "line_number": 305,
+        "line_number": 307,
         "is_secret": false
       },
       {
         "type": "Secret Keyword",
         "filename": "distribution/src/main/resources/docker-compose/docker-compose.yml",
         "hashed_secret": "d033e22ae348aeb5660fc2140aec35850c4da997",
         "is_verified": false,
-        "line_number": 309,
+        "line_number": 311,
         "is_secret": false
       }
     ],
@@ -296,5 +296,5 @@
       }
     ]
   },
-  "generated_at": "2024-09-09T09:53:24Z"
+  "generated_at": "2024-09-13T10:03:50Z"
 }

common/src/main/java/org/alfresco/hxi_connector/common/repository/filter/CollectionFilter.java

@@ -42,7 +42,7 @@ public static boolean filter(Collection<String> fields, Collection<String> allow
         final boolean allow = isAllowed(fields, allowed);
         final boolean deny = isDenied(fields, denied);
         boolean result = allow && !deny;
-        log.atDebug().log("Node fields collection: {}. Allowed values: {}. Denied values: {}. Is allowed: {}", fields, allowed, denied, result);
+        log.atDebug().log("Filtering :: Node fields collection: {}. Allowed values: {}. Denied values: {}. Is allowed: {}", fields, allowed, denied, result);
         return result;
     }
 

common/src/main/java/org/alfresco/hxi_connector/common/repository/filter/FieldFilter.java

@@ -41,7 +41,7 @@ public static boolean filter(String nodeField, List<String> allowed, List<String
         final boolean allow = isAllowed(nodeField, allowed);
         final boolean deny = isDenied(nodeField, denied);
         boolean result = allow && !deny;
-        log.atDebug().log("Node field: {}. Allowed values: {}. Denied values: {}. Is allowed: {}", nodeField, allowed, denied, result);
+        log.atDebug().log("Filtering :: Node field: {}. Allowed values: {}. Denied values: {}. Is allowed: {}", nodeField, allowed, denied, result);
         return result;
     }
 

distribution/src/main/resources/docker-compose/docker-compose.yml

@@ -294,9 +294,11 @@ services:
         condition: service_started
       transform-router:
         condition: service_healthy
+      alfresco:
+        condition: service_healthy
     environment:
       JAVA_TOOL_OPTIONS: -agentlib:jdwp=transport=dt_socket,address=*:5007,server=y,suspend=n
-      LOGGING_LEVEL_ORG_ALFRESCO: DEBUG
+      LOGGING_LEVEL_ORG_ALFRESCO: INFO
       SPRING_ACTIVEMQ_BROKERURL: nio://activemq:61616
       ALFRESCO_REPOSITORY_BASEURL: http://alfresco:8080/alfresco
       ALFRESCO_TRANSFORM_SHAREDFILESTORE_BASEURL: http://shared-file-store:8099
@@ -323,7 +325,7 @@ services:
         condition: service_healthy
     environment:
       JAVA_TOOL_OPTIONS: -agentlib:jdwp=transport=dt_socket,address=*:5008,server=y,suspend=n
-      LOGGING_LEVEL_ORG_ALFRESCO: DEBUG
+      LOGGING_LEVEL_ORG_ALFRESCO: INFO
       SPRING_ACTIVEMQ_BROKERURL: nio://activemq:61616
       SPRING_DATASOURCE_URL: jdbc:postgresql://postgres:5432/alfresco
       SPRING_DATASOURCE_USERNAME: alfresco
@@ -342,7 +344,7 @@ services:
         condition: service_healthy
     environment:
       JAVA_TOOL_OPTIONS: -agentlib:jdwp=transport=dt_socket,address=*:5009,server=y,suspend=n
-      LOGGING_LEVEL_ORG_ALFRESCO: DEBUG
+      LOGGING_LEVEL_ORG_ALFRESCO: INFO
       SPRING_ACTIVEMQ_BROKERURL: nio://activemq:61616
       ALFRESCO_REPOSITORY_BASEURL: http://alfresco:8080/alfresco
       HYLANDEXPERIENCE_INSIGHT_PREDICTIONS_BASEURL: http://hxinsight-mock:8080

e2e-test/src/test/java/org/alfresco/hxi_connector/e2e_test/CreateNodeE2eTest.java

@@ -134,7 +134,7 @@ public void beforeAll() throws IOException, InterruptedException
         repositoryClient = new RepositoryClient(repository.getBaseUrl(), ADMIN_USER);
         WireMock.configureFor(hxInsightMock.getHost(), hxInsightMock.getPort());
         // wait for repo to load transform config
-        RetryUtils.retryWithBackoff(() -> assertThat(transformRouter.getLogs()).contains("GET Transform Config version"), 700);
+        RetryUtils.retryWithBackoff(() -> assertThat(transformRouter.getLogs()).contains("GET Transform Config version"), 800);
     }
 
     @AfterEach

e2e-test/src/test/java/org/alfresco/hxi_connector/e2e_test/UpdateNodeE2eTest.java

@@ -141,7 +141,7 @@ public class UpdateNodeE2eTest
             .dependsOn(postgres, activemq);
     @Container
     private static final GenericContainer<?> liveIngester = createLiveIngesterContainer()
-            .dependsOn(activemq, hxInsightMock);
+            .dependsOn(activemq, repository, hxInsightMock);
     @Container
     private static final GenericContainer<?> predictionApplier = createPredictionApplierContainer()
             .dependsOn(activemq, hxInsightMock, repository, liveIngester);

live-ingester/src/integration-test/java/org/alfresco/hxi_connector/live_ingester/adapters/messaging/hx_insight/HxInsightEventPublisherIntegrationTest.java

@@ -54,9 +54,13 @@
 import java.time.OffsetDateTime;
 import java.util.Collections;
 import java.util.HashMap;
+import java.util.List;
 import java.util.Map;
 
+import ch.qos.logback.classic.spi.ILoggingEvent;
+import ch.qos.logback.core.read.ListAppender;
 import com.github.tomakehurst.wiremock.client.WireMock;
+import com.github.tomakehurst.wiremock.http.Body;
 import org.junit.jupiter.api.BeforeAll;
 import org.junit.jupiter.api.Test;
 import org.springframework.boot.autoconfigure.EnableAutoConfiguration;
@@ -89,6 +93,7 @@
 import org.alfresco.hxi_connector.common.exception.EndpointServerErrorException;
 import org.alfresco.hxi_connector.common.test.docker.util.DockerContainers;
 import org.alfresco.hxi_connector.common.test.docker.util.DockerTags;
+import org.alfresco.hxi_connector.common.test.util.LoggingUtils;
 import org.alfresco.hxi_connector.live_ingester.IntegrationCamelTestBase;
 import org.alfresco.hxi_connector.live_ingester.adapters.auth.LiveIngesterAuthClient;
 import org.alfresco.hxi_connector.live_ingester.adapters.config.IntegrationProperties;
@@ -184,6 +189,26 @@ void testPublishMessage_clientError_dontRetry()
         assertThat(thrown).cause().isInstanceOf(EndpointClientErrorException.class);
     }
 
+    @Test
+    @SuppressWarnings({"ThrowableNotThrown", "ResultOfMethodCallIgnored"})
+    void testLoggingOnError()
+    {
+        // given
+        givenThat(post(INGEST_PATH)
+                .willReturn(badRequest().withResponseBody(new Body("{\"error\": \"Bad request\"}"))));
+        ListAppender<ILoggingEvent> logEntries = LoggingUtils.createLogsListAppender(HxInsightEventPublisher.class);
+
+        // when
+        catchThrowable(() -> ingestionEngineEventPublisher.publishMessage(NODE_EVENT));
+
+        // then
+        List<String> logs = logEntries.list.stream().map(ILoggingEvent::getFormattedMessage).toList();
+        assertThat(logs)
+                .isNotEmpty()
+                .last().asString()
+                .contains("Authorization=***", "Body: {\"error\": \"Bad request\"}");
+    }
+
     @DynamicPropertySource
     static void overrideProperties(DynamicPropertyRegistry registry)
     {

live-ingester/src/integration-test/java/org/alfresco/hxi_connector/live_ingester/adapters/messaging/hx_insight/storage/connector/HttpFileUploaderIntegrationTest.java

@@ -39,6 +39,8 @@
 import java.util.ArrayList;
 import java.util.List;
 
+import ch.qos.logback.classic.spi.ILoggingEvent;
+import ch.qos.logback.core.read.ListAppender;
 import lombok.Cleanup;
 import org.apache.hc.client5.http.HttpHostConnectException;
 import org.junit.jupiter.api.BeforeAll;
@@ -59,6 +61,7 @@
 import org.alfresco.hxi_connector.common.exception.EndpointClientErrorException;
 import org.alfresco.hxi_connector.common.exception.EndpointServerErrorException;
 import org.alfresco.hxi_connector.common.test.docker.util.DockerContainers;
+import org.alfresco.hxi_connector.common.test.util.LoggingUtils;
 import org.alfresco.hxi_connector.live_ingester.IntegrationCamelTestBase;
 import org.alfresco.hxi_connector.live_ingester.adapters.config.IntegrationProperties;
 import org.alfresco.hxi_connector.live_ingester.adapters.messaging.hx_insight.storage.local.LocalStorageClient;
@@ -165,6 +168,31 @@ void testUpload_clientError_dontRetry() throws IOException
         assertThat(thrown).cause().isInstanceOf(EndpointClientErrorException.class);
     }
 
+    @Test
+    @SuppressWarnings({"ThrowableNotThrown", "ResultOfMethodCallIgnored"})
+    void testLoggingOnError() throws IOException
+    {
+        // given
+        @Cleanup
+        InputStream fileContent = new ByteArrayInputStream(OBJECT_CONTENT.getBytes());
+        File fileToUpload = new File(fileContent);
+        URL preSignedUrl = s3StorageMock.generatePreSignedUploadUrl("invalid-bucket", OBJECT_KEY, OBJECT_CONTENT_TYPE);
+
+        FileUploadRequest fileUploadRequest = new FileUploadRequest(fileToUpload, OBJECT_CONTENT_TYPE, preSignedUrl);
+        ListAppender<ILoggingEvent> logEntries = LoggingUtils.createLogsListAppender(HttpFileUploader.class);
+
+        // when
+        catchThrowable(() -> fileUploader.upload(fileUploadRequest, NODE_ID));
+
+        // then
+        List<String> logs = logEntries.list.stream().map(ILoggingEvent::getFormattedMessage).toList();
+        assertThat(logs)
+                .isNotEmpty()
+                .last().asString()
+                .contains("<Code>NoSuchBucket</Code>", "<BucketName>invalid-bucket</BucketName>")
+                .doesNotContain("Authorization=");
+    }
+
     @DynamicPropertySource
     static void overrideProperties(DynamicPropertyRegistry registry)
     {

live-ingester/src/integration-test/java/org/alfresco/hxi_connector/live_ingester/adapters/messaging/hx_insight/storage/connector/PreSignedUrlRequesterIntegrationTest.java

@@ -56,11 +56,15 @@
 import java.time.OffsetDateTime;
 import java.util.Collections;
 import java.util.HashMap;
+import java.util.List;
 import java.util.Map;
 
+import ch.qos.logback.classic.spi.ILoggingEvent;
+import ch.qos.logback.core.read.ListAppender;
 import com.fasterxml.jackson.core.io.JsonEOFException;
 import com.fasterxml.jackson.databind.exc.MismatchedInputException;
 import com.github.tomakehurst.wiremock.client.WireMock;
+import com.github.tomakehurst.wiremock.http.Body;
 import com.github.tomakehurst.wiremock.http.Fault;
 import org.apache.hc.core5.http.NoHttpResponseException;
 import org.junit.jupiter.api.BeforeAll;
@@ -94,6 +98,7 @@
 import org.alfresco.hxi_connector.common.exception.EndpointServerErrorException;
 import org.alfresco.hxi_connector.common.test.docker.util.DockerContainers;
 import org.alfresco.hxi_connector.common.test.docker.util.DockerTags;
+import org.alfresco.hxi_connector.common.test.util.LoggingUtils;
 import org.alfresco.hxi_connector.live_ingester.IntegrationCamelTestBase;
 import org.alfresco.hxi_connector.live_ingester.adapters.auth.LiveIngesterAuthClient;
 import org.alfresco.hxi_connector.live_ingester.adapters.config.IntegrationProperties;
@@ -266,6 +271,26 @@ void testRequestStorageLocation_serverDown_doRetry()
                 .cause().isInstanceOf(NoHttpResponseException.class);
     }
 
+    @Test
+    @SuppressWarnings({"ThrowableNotThrown", "ResultOfMethodCallIgnored"})
+    void testLoggingOnError()
+    {
+        // given
+        givenThat(post(PRE_SIGNED_URL_PATH)
+                .willReturn(badRequest().withResponseBody(new Body("{\"error\": \"Bad request\"}"))));
+        ListAppender<ILoggingEvent> logEntries = LoggingUtils.createLogsListAppender(PreSignedUrlRequester.class);
+
+        // when
+        catchThrowable(locationRequester::requestStorageLocation);
+
+        // then
+        List<String> logs = logEntries.list.stream().map(ILoggingEvent::getFormattedMessage).toList();
+        assertThat(logs)
+                .isNotEmpty()
+                .last().asString()
+                .contains("Authorization=***", "Body: {\"error\": \"Bad request\"}");
+    }
+
     @DynamicPropertySource
     static void overrideProperties(DynamicPropertyRegistry registry)
     {

live-ingester/src/integration-test/java/org/alfresco/hxi_connector/live_ingester/adapters/messaging/transform/storage/SharedFileStoreClientIntegrationTest.java

@@ -39,8 +39,12 @@
 import static software.amazon.awssdk.http.HttpStatusCode.OK;
 
 import java.io.InputStream;
+import java.util.List;
 
+import ch.qos.logback.classic.spi.ILoggingEvent;
+import ch.qos.logback.core.read.ListAppender;
 import com.github.tomakehurst.wiremock.client.WireMock;
+import com.github.tomakehurst.wiremock.http.Body;
 import lombok.SneakyThrows;
 import org.junit.jupiter.api.BeforeAll;
 import org.junit.jupiter.api.Test;
@@ -59,6 +63,7 @@
 import org.alfresco.hxi_connector.common.exception.EndpointClientErrorException;
 import org.alfresco.hxi_connector.common.exception.EndpointServerErrorException;
 import org.alfresco.hxi_connector.common.test.docker.util.DockerContainers;
+import org.alfresco.hxi_connector.common.test.util.LoggingUtils;
 import org.alfresco.hxi_connector.live_ingester.IntegrationCamelTestBase;
 import org.alfresco.hxi_connector.live_ingester.adapters.config.IntegrationProperties;
 import org.alfresco.hxi_connector.live_ingester.domain.ports.transform_engine.TransformEngineFileStorage;
@@ -147,6 +152,27 @@ void testDownloadFile_clientError_dontRetry()
         assertThat(thrown).cause().isInstanceOf(EndpointClientErrorException.class);
     }
 
+    @Test
+    @SuppressWarnings({"ThrowableNotThrown", "ResultOfMethodCallIgnored"})
+    void testLoggingOnError()
+    {
+        // given
+        givenThat(get(SFS_DOWNLOAD_FILE_PATH)
+                .willReturn(badRequest().withResponseBody(new Body("{\"error\": \"Bad request\"}"))));
+        ListAppender<ILoggingEvent> logEntries = LoggingUtils.createLogsListAppender(SharedFileStoreClient.class);
+
+        // when
+        catchThrowable(() -> sharedFileStoreClient.downloadFile(FILE_ID));
+
+        // then
+        List<String> logs = logEntries.list.stream().map(ILoggingEvent::getFormattedMessage).toList();
+        assertThat(logs)
+                .isNotEmpty()
+                .last().asString()
+                .contains("Body: {\"error\": \"Bad request\"}")
+                .doesNotContain("Authorization=");
+    }
+
     @DynamicPropertySource
     static void overrideProperties(DynamicPropertyRegistry registry)
     {

live-ingester/src/integration-test/java/org/alfresco/hxi_connector/live_ingester/domain/usecase/e2e/bulk_ingester/BulkIngesterEventIntegrationTest.java

@@ -162,6 +162,5 @@ void shouldIngestMetadataAndContent()
                     "replyQueue": "org.alfresco.hxinsight-connector.transform.response"
                 }""".formatted(REQUEST_ID_PLACEHOLDER);
         containerSupport.verifyATSRequestReceived(expectedATSRequest);
-
     }
 }

live-ingester/src/main/java/org/alfresco/hxi_connector/live_ingester/adapters/config/jackson/DeleteNodeEventSerializer.java

@@ -26,13 +26,16 @@
 
 package org.alfresco.hxi_connector.live_ingester.adapters.config.jackson;
 
+import static java.util.Locale.ENGLISH;
+
 import com.fasterxml.jackson.core.JsonGenerator;
 import com.fasterxml.jackson.databind.SerializerProvider;
 import com.fasterxml.jackson.databind.ser.std.StdSerializer;
 import org.springframework.stereotype.Component;
 
 import org.alfresco.hxi_connector.live_ingester.adapters.config.jackson.exception.JsonSerializationException;
 import org.alfresco.hxi_connector.live_ingester.domain.ports.ingestion_engine.DeleteNodeEvent;
+import org.alfresco.hxi_connector.live_ingester.domain.usecase.metadata.model.EventType;
 
 @Component
 public class DeleteNodeEventSerializer extends StdSerializer<DeleteNodeEvent>
@@ -57,8 +60,7 @@ public void serialize(DeleteNodeEvent event, JsonGenerator jgen, SerializerProvi
             jgen.writeStringField("objectId", event.getObjectId());
             jgen.writeStringField("sourceId", event.getSourceId());
             jgen.writeNumberField("sourceTimestamp", event.getTimestamp());
-
-            jgen.writeStringField("eventType", "delete");
+            jgen.writeStringField("eventType", serializeEventType(event.getEventType()));
 
             jgen.writeEndObject();
         }
@@ -67,4 +69,9 @@ public void serialize(DeleteNodeEvent event, JsonGenerator jgen, SerializerProvi
             throw new JsonSerializationException("Property serialization failed", e);
         }
     }
+
+    private String serializeEventType(EventType eventType)
+    {
+        return eventType.toString().toLowerCase(ENGLISH);
+    }
 }

live-ingester/src/main/java/org/alfresco/hxi_connector/live_ingester/adapters/messaging/hx_insight/HxInsightEventPublisher.java

@@ -26,6 +26,8 @@
 package org.alfresco.hxi_connector.live_ingester.adapters.messaging.hx_insight;
 
 import static org.apache.camel.Exchange.HTTP_RESPONSE_CODE;
+import static org.apache.camel.LoggingLevel.DEBUG;
+import static org.apache.camel.LoggingLevel.INFO;
 
 import static org.alfresco.hxi_connector.common.adapters.messaging.repository.ApplicationInfoProvider.USER_AGENT_DATA;
 import static org.alfresco.hxi_connector.common.util.ErrorUtils.UNEXPECTED_STATUS_CODE_MESSAGE;
@@ -38,6 +40,7 @@
 import org.apache.camel.Exchange;
 import org.apache.camel.LoggingLevel;
 import org.apache.camel.builder.RouteBuilder;
+import org.slf4j.event.Level;
 import org.springframework.retry.annotation.Backoff;
 import org.springframework.retry.annotation.Retryable;
 import org.springframework.stereotype.Component;
@@ -47,6 +50,7 @@
 import org.alfresco.hxi_connector.common.exception.EndpointServerErrorException;
 import org.alfresco.hxi_connector.common.util.ErrorUtils;
 import org.alfresco.hxi_connector.live_ingester.adapters.config.IntegrationProperties;
+import org.alfresco.hxi_connector.live_ingester.adapters.messaging.util.LoggingUtils;
 import org.alfresco.hxi_connector.live_ingester.domain.exception.LiveIngesterRuntimeException;
 import org.alfresco.hxi_connector.live_ingester.domain.ports.ingestion_engine.IngestionEngineEventPublisher;
 import org.alfresco.hxi_connector.live_ingester.domain.ports.ingestion_engine.NodeEvent;
@@ -69,19 +73,22 @@ public class HxInsightEventPublisher extends RouteBuilder implements IngestionEn
     public void configure()
     {
         // @formatter:off
+        String ingestionEndpoint = integrationProperties.hylandExperience().ingester().endpoint() + ApplicationInfoProvider.USER_AGENT_PARAM;
         onException(Exception.class)
-            .log(LoggingLevel.ERROR, log, "Unexpected response. Body: ${body}")
+            .log(LoggingLevel.ERROR, log, "Ingestion :: Unexpected response - Endpoint: %s".formatted(ingestionEndpoint))
+            .process(exchange -> LoggingUtils.logMaskedExchangeState(exchange, log, Level.ERROR))
             .process(this::wrapErrorIfNecessary)
             .stop();
 
         from(LOCAL_ENDPOINT)
             .id(ROUTE_ID)
+            .log(INFO, log, "Ingestion :: Sending event of type: ${body.eventType} for node with ID: ${body.objectId}")
             .marshal()
             .json()
-            .log("Sending event ${body}")
             .setProperty(USER_AGENT_DATA, applicationInfoProvider::getUserAgentData)
+            .log(DEBUG, log, "Ingestion :: Sending event: ${body}. Headers: ${headers}. Endpoint: " + ingestionEndpoint)
             .process(authService::setHxIAuthorizationHeaders)
-            .toD(integrationProperties.hylandExperience().ingester().endpoint() + ApplicationInfoProvider.USER_AGENT_PARAM)
+            .toD(ingestionEndpoint)
             .choice()
             .when(header(HTTP_RESPONSE_CODE).isNotEqualTo(String.valueOf(EXPECTED_STATUS_CODE)))
                 .process(this::throwExceptionOnUnexpectedStatusCode)
@@ -123,5 +130,4 @@ private void wrapErrorIfNecessary(Exchange exchange)
 
         ErrorUtils.wrapErrorAndThrowIfNecessary(cause, retryReasons, LiveIngesterRuntimeException.class);
     }
-
 }