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-test/src/main/java/org/alfresco/hxi_connector/common/test/docker/util/DockerContainers.java

@@ -310,7 +310,7 @@ public static GenericContainer<?> createLiveIngesterContainerForWireMock(WireMoc
     public static GenericContainer<?> createLiveIngesterContainerForWireMock(WireMockContainer hxInsightMockContainer, AlfrescoRepositoryContainer acsContainer, Network network)
     {
         return createLiveIngesterContainerForWireMock(hxInsightMockContainer, network)
-                .withEnv("ALFRESCO_REPOSITORY_DISCOVERYENDPOINT", "http://%s:8080/alfresco/api/discovery".formatted(acsContainer.getNetworkAliases().stream().findFirst().get()));
+                .withEnv("ALFRESCO_REPOSITORY_BASEURL", "http://%s:8080/alfresco".formatted(acsContainer.getNetworkAliases().stream().findFirst().get()));
     }
 
     public static GenericContainer<?> createPredictionApplierContainerWithin(Network network)

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

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

@@ -156,6 +156,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("timestamp", 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;
@@ -69,19 +71,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))
+            .to("log:%s?level=ERROR&multiline=true&showBody=true&showHeaders=true&showProperties=true&showStackTrace=true".formatted(log.getName()))
             .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)

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

@@ -55,11 +55,13 @@ public class HttpHxInsightStorageClient implements IngestionEngineStorageClient
     public IngestContentResponse upload(File file, String contentType, String nodeId)
     {
         PreSignedUrlResponse preSignedUrlResponse = storageLocationRequester.requestStorageLocation();
-        log.atDebug().log("Storage :: Received target location with transfer ID: {} for node: {}", preSignedUrlResponse.id(), nodeId);
+        log.atDebug().log("Storage :: Received target location with transfer ID: {} for node: {}",
+                preSignedUrlResponse.id(), nodeId);
         URL preSignedUrl = preSignedUrlResponse.url();
         try (InputStream fileData = file.data())
         {
-            log.atDebug().log("Upload :: Transferring to S3 content of node: {} with size of {} bytes", nodeId, fileData.available());
+            log.atDebug().log("Storage :: Uploading content rendition of node: {} with size of {} bytes to: {}",
+                    nodeId, fileData.available(), preSignedUrl.getPath());
             fileUploader.upload(new FileUploadRequest(new File(fileData), contentType, preSignedUrl), nodeId);
         }
         catch (IOException e)

live-ingester/src/main/java/org/alfresco/hxi_connector/live_ingester/adapters/messaging/hx_insight/storage/connector/HttpFileUploader.java

@@ -29,6 +29,7 @@
 import static java.nio.charset.StandardCharsets.UTF_8;
 
 import static org.apache.camel.Exchange.HTTP_RESPONSE_CODE;
+import static org.apache.camel.LoggingLevel.ERROR;
 
 import static org.alfresco.hxi_connector.common.util.ErrorUtils.UNEXPECTED_STATUS_CODE_MESSAGE;
 
@@ -42,7 +43,6 @@
 import lombok.extern.slf4j.Slf4j;
 import org.apache.camel.CamelContext;
 import org.apache.camel.Exchange;
-import org.apache.camel.LoggingLevel;
 import org.apache.camel.builder.RouteBuilder;
 import org.apache.camel.component.http.HttpMethods;
 import org.apache.commons.lang3.StringUtils;
@@ -73,8 +73,10 @@ public class HttpFileUploader extends RouteBuilder implements FileUploader
     public void configure()
     {
         // @formatter:off
+        String uploadEndpoint = "${headers." + STORAGE_LOCATION_HEADER + "}&throwExceptionOnFailure=false";
         onException(Exception.class)
-            .log(LoggingLevel.ERROR, log, "Upload :: Unexpected response while uploading to S3. Body: ${body}")
+            .log(ERROR, log, "Storage :: Unexpected response while uploading content - Endpoint: %s".formatted(uploadEndpoint))
+            .to("log:%s?level=ERROR&multiline=true&showBody=true&showHeaders=true&showProperties=true&showStackTrace=true".formatted(log.getName()))
             .process(this::wrapErrorIfNecessary)
             .stop();
 
@@ -83,7 +85,7 @@ public void configure()
             .setHeader(Exchange.HTTP_METHOD, constant(HttpMethods.PUT))
             .marshal()
             .mimeMultipart()
-            .toD("${headers." + STORAGE_LOCATION_HEADER + "}&throwExceptionOnFailure=false")
+            .toD(uploadEndpoint)
             .choice()
             .when(header(HTTP_RESPONSE_CODE).isNotEqualTo(String.valueOf(EXPECTED_STATUS_CODE)))
                 .process(this::throwExceptionOnUnexpectedStatusCode)
@@ -112,7 +114,7 @@ STORAGE_LOCATION_HEADER, wrapRawToken(fileUploadRequest.storageLocation()),
                     .withHeaders(headers)
                     .withBody(fileData)
                     .request();
-            log.atDebug().log("Upload :: {} rendition of the node: {} successfully uploaded to pre-signed URL: {}", fileUploadRequest.contentType(), nodeId, fileUploadRequest.storageLocation().getPath());
+            log.info("Storage :: Rendition of type: {} for node: {} successfully uploaded to pre-signed URL: {}", fileUploadRequest.contentType(), nodeId, fileUploadRequest.storageLocation().getPath());
         }
         catch (Exception e)
         {
@@ -123,7 +125,7 @@ STORAGE_LOCATION_HEADER, wrapRawToken(fileUploadRequest.storageLocation()),
             }
             catch (IOException ioe)
             {
-                log.atDebug().log("Upload :: Stream reset failed due to: {}", ioe.getMessage());
+                log.warn("Storage :: Rendition stream NOT reset properly after node %s content upload fail due to: %s".formatted(nodeId, ioe.getMessage()), ioe);
                 throw e;
             }
         }

live-ingester/src/main/java/org/alfresco/hxi_connector/live_ingester/adapters/messaging/hx_insight/storage/connector/PreSignedUrlRequester.java

@@ -26,6 +26,7 @@
 package org.alfresco.hxi_connector.live_ingester.adapters.messaging.hx_insight.storage.connector;
 
 import static org.apache.camel.Exchange.HTTP_RESPONSE_CODE;
+import static org.apache.camel.LoggingLevel.ERROR;
 
 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;
@@ -40,7 +41,6 @@
 import lombok.extern.slf4j.Slf4j;
 import org.apache.camel.CamelContext;
 import org.apache.camel.Exchange;
-import org.apache.camel.LoggingLevel;
 import org.apache.camel.builder.RouteBuilder;
 import org.apache.camel.model.dataformat.JsonLibrary;
 import org.springframework.retry.annotation.Backoff;
@@ -75,16 +75,18 @@ public class PreSignedUrlRequester extends RouteBuilder implements StorageLocati
     public void configure()
     {
         // @formatter:off
+        String storageRequestEndpoint = integrationProperties.hylandExperience().storage().location().endpoint() + ApplicationInfoProvider.USER_AGENT_PARAM;
         onException(Exception.class)
-            .log(LoggingLevel.ERROR, log, "Storage :: Unexpected response while requesting pre-signed URL. Body: ${body}")
+            .log(ERROR, log, "Storage :: Unexpected response while requesting pre-signed URL - Endpoint: %s".formatted(storageRequestEndpoint))
+            .to("log:%s?level=ERROR&multiline=true&showBody=true&showHeaders=true&showProperties=true&showStackTrace=true".formatted(log.getName()))
             .process(this::wrapErrorIfNecessary)
             .stop();
 
         from(LOCAL_ENDPOINT)
             .id(ROUTE_ID)
             .setProperty(USER_AGENT_DATA, applicationInfoProvider::getUserAgentData)
             .process(authService::setHxIAuthorizationHeaders)
-            .toD(integrationProperties.hylandExperience().storage().location().endpoint() + ApplicationInfoProvider.USER_AGENT_PARAM)
+            .toD(storageRequestEndpoint)
             .choice()
             .when(header(HTTP_RESPONSE_CODE).isEqualTo(String.valueOf(EXPECTED_STATUS_CODE)))
                 .unmarshal()

live-ingester/src/main/java/org/alfresco/hxi_connector/live_ingester/adapters/messaging/repository/LiveIngesterEventHandler.java

@@ -26,6 +26,8 @@
 package org.alfresco.hxi_connector.live_ingester.adapters.messaging.repository;
 
 import static org.apache.camel.LoggingLevel.DEBUG;
+import static org.apache.camel.LoggingLevel.ERROR;
+import static org.apache.camel.LoggingLevel.INFO;
 
 import lombok.RequiredArgsConstructor;
 import lombok.extern.slf4j.Slf4j;
@@ -51,12 +53,19 @@ public class LiveIngesterEventHandler extends RouteBuilder
     @Override
     public void configure()
     {
+        String eventSource = integrationProperties.alfresco().repository().eventsEndpoint();
+        onException(Exception.class)
+                .log(ERROR, log, "Repository :: Unexpected state while processing event from: %s".formatted(eventSource))
+                .to("log:%s?level=ERROR&multiline=true&showBody=true&showHeaders=true&showProperties=true&showStackTrace=true".formatted(log.getName()))
+                .stop();
+
         SecurityContext securityContext = SecurityContextHolder.getContext();
-        from(integrationProperties.alfresco().repository().eventsEndpoint())
+        from(eventSource)
                 .transacted()
                 .routeId(ROUTE_ID)
-                .log(DEBUG, log, "Received repo event : ${header.JMSMessageID}")
+                .log(DEBUG, log, "Repository :: Received event: ${body}")
                 .setBody(camelEventMapper::repoEventFrom)
+                .log(INFO, log, "Repository :: Received event with ID: ${body.id} and type: ${body.type} for node: ${body.data?.resource?.id}")
                 .process(exchange -> SecurityContextHolder.setContext(securityContext))
                 .process(eventProcessor::process)
                 .end();

live-ingester/src/main/java/org/alfresco/hxi_connector/live_ingester/adapters/messaging/repository/filter/AncestorFilterApplier.java

@@ -49,14 +49,14 @@ public boolean isNodeAllowed(NodeResource nodeResource, Filter filter)
         primaryHierarchy.add(nodeResource.getId());
         final List<String> allowed = filter.path().allow();
         final List<String> denied = filter.path().deny();
-        log.atDebug().log("Applying ancestor filters on repo node id: {}", nodeResource.getId());
+        log.atDebug().log("Filtering :: Applying ancestor filters on repo node id: {}", nodeResource.getId());
         return CollectionFilter.filter(primaryHierarchy, allowed, denied);
     }
 
     @Override
     public boolean isNodeBeforeAllowed(boolean currentlyAllowed, NodeResource nodeResourceBefore, Filter filter)
     {
-        log.atDebug().log("Applying ancestor filters on previous version of repo node id: {}", nodeResourceBefore.getId());
+        log.atDebug().log("Filtering :: Applying ancestor filters on previous version of repo node id: {}", nodeResourceBefore.getId());
         final List<String> primaryHierarchy = nodeResourceBefore.getPrimaryHierarchy();
         if (primaryHierarchy == null)
         {

live-ingester/src/main/java/org/alfresco/hxi_connector/live_ingester/adapters/messaging/repository/filter/AspectFilterApplier.java

@@ -49,7 +49,7 @@ public boolean isNodeAllowed(NodeResource nodeResource, Filter filter)
         final Set<String> aspectNames = SetUtils.emptyIfNull(nodeResource.getAspectNames());
         final List<String> allowed = filter.aspect().allow();
         final List<String> denied = filter.aspect().deny();
-        log.atDebug().log("Applying aspect filters on node id: {}", nodeResource.getId());
+        log.atDebug().log("Filtering :: Applying aspect filters on node id: {}", nodeResource.getId());
         return CollectionFilter.filter(aspectNames, allowed, denied);
     }
 

live-ingester/src/main/java/org/alfresco/hxi_connector/live_ingester/adapters/messaging/repository/filter/RepoEventFilterHandler.java

@@ -87,18 +87,18 @@ private FilteringResults calculateFilteringResults(Exchange exchange, Filter fil
         final boolean eventTypeUpdated = EventUtils.isEventTypeUpdated(repoEvent);
         for (RepoEventFilterApplier filterApplier : repoEventFilterAppliers)
         {
-            log.atDebug().log("Applying filters {} to current repo event of id: {}", filter, repoEvent.getId());
+            log.atDebug().log("Filtering :: Applying filters {} to current repo event of id: {}", filter, repoEvent.getId());
             final boolean allow = filterApplier.isNodeAllowed(repoEvent.getData().getResource(), filter);
             allowCurrentNode = allowCurrentNode && allow;
             if (eventTypeUpdated && allowPreviousNode)
             {
-                log.atDebug().log("Applying filters {} to previous version of repo event of id: {}", filter, repoEvent.getId());
+                log.atDebug().log("Filtering :: Applying filters {} to previous version of repo event of id: {}", filter, repoEvent.getId());
                 allowPreviousNode = filterApplier.isNodeBeforeAllowed(allow, repoEvent.getData().getResourceBefore(), filter);
             }
         }
         final Optional<String> eventTypeOverride = eventTypeUpdated ? resolveEventType(allowPreviousNode, allowCurrentNode) : Optional.empty();
         final boolean overallResult = allowCurrentNode || (allowPreviousNode && eventTypeUpdated);
-        log.atDebug().log("Overall filtering results. Allow: {}, allow current: {}, allow previous: {}", overallResult, allowCurrentNode, allowPreviousNode);
+        log.atDebug().log("Filtering :: Overall filtering results. Allow: {}, allow current: {}, allow previous: {}", overallResult, allowCurrentNode, allowPreviousNode);
         return new FilteringResults(overallResult, eventTypeOverride);
     }