ACS-2002 Enhance T-Router debug (#867)

Modifications to allow the enterprise repo to add transform debug from the t-router to the repo's log.

Addition of TransformerDebugTest

pom.xml

@@ -51,7 +51,7 @@
         <dependency.alfresco-log-sanitizer.version>0.2</dependency.alfresco-log-sanitizer.version>
         <dependency.activiti-engine.version>5.23.0</dependency.activiti-engine.version>
         <dependency.activiti.version>5.23.0</dependency.activiti.version>
-        <dependency.alfresco-transform-model.version>1.4.3</dependency.alfresco-transform-model.version>
+        <dependency.alfresco-transform-model.version>1.4.5</dependency.alfresco-transform-model.version>
         <dependency.alfresco-greenmail.version>6.2</dependency.alfresco-greenmail.version>
         <dependency.acs-event-model.version>0.0.13</dependency.acs-event-model.version>
 

repository/src/main/java/org/alfresco/repo/content/transform/AbstractLocalTransform.java

@@ -2,7 +2,7 @@
  * #%L
  * Alfresco Repository
  * %%
- * Copyright (C) 2019 Alfresco Software Limited
+ * Copyright (C) 2019 - 2022 Alfresco Software Limited
  * %%
  * This file is part of the Alfresco software.
  * If the software was purchased under a paid Alfresco license, the terms of
@@ -181,9 +181,9 @@ public abstract class AbstractLocalTransform implements LocalTransform
                 Set<String> allowedMimetypes = strictMimetypeExceptions.get(declaredMimetype);
                 if (allowedMimetypes != null && allowedMimetypes.contains(detectedMimetype))
                 {
-                    String fileName = transformerDebug.getFileName(sourceNodeRef, true, 0);
+                    String filename = transformerDebug.getFilename(sourceNodeRef, true);
                     String readerSourceMimetype = reader.getMimetype();
-                    String message = "Transformation of ("+fileName+
+                    String message = "Transformation of ("+filename+
                             ") has not taken place because the declared mimetype ("+
                             readerSourceMimetype+") does not match the detected mimetype ("+
                             detectedMimetype+").";

repository/src/main/java/org/alfresco/repo/content/transform/TransformerDebug.java

@@ -2,7 +2,7 @@
  * #%L
  * Alfresco Repository
  * %%
- * Copyright (C) 2005 - 2020 Alfresco Software Limited
+ * Copyright (C) 2005 - 2022 Alfresco Software Limited
  * %%
  * This file is part of the Alfresco software. 
  * If the software was purchased under a paid Alfresco license, the terms of 
@@ -26,29 +26,22 @@
 package org.alfresco.repo.content.transform;
 
 import org.alfresco.model.ContentModel;
-import org.alfresco.repo.content.metadata.AsynchronousExtractor;
 import org.alfresco.service.cmr.repository.MimetypeService;
 import org.alfresco.service.cmr.repository.NodeRef;
 import org.alfresco.service.cmr.repository.NodeService;
-import org.alfresco.util.EqualsHelper;
 import org.alfresco.util.LogTee;
 import org.alfresco.util.PropertyCheck;
 import org.apache.commons.logging.Log;
 import org.apache.commons.logging.LogFactory;
 
 import java.util.ArrayDeque;
+import java.util.Collection;
 import java.util.Deque;
 import java.util.Iterator;
 import java.util.Map;
-import java.util.Set;
 import java.util.StringJoiner;
 import java.util.concurrent.atomic.AtomicInteger;
 
-import static org.alfresco.repo.rendition2.RenditionDefinition2.SOURCE_ENCODING;
-import static org.alfresco.repo.rendition2.RenditionDefinition2.SOURCE_NODE_REF;
-import static org.alfresco.repo.rendition2.RenditionDefinition2.TARGET_ENCODING;
-import static org.alfresco.repo.rendition2.RenditionDefinition2.TIMEOUT;
-
 /**
  * Debugs transformers selection and activity.<p>
  *
@@ -60,16 +53,32 @@ import static org.alfresco.repo.rendition2.RenditionDefinition2.TIMEOUT;
  */
 public class TransformerDebug
 {
+    public static final String TIMEOUT =  "timeout";
+    public static final String SOURCE_ENCODING = "sourceEncoding";
+    public static final String SOURCE_NODE_REF = "sourceNodeRef";
+    public static final String TARGET_ENCODING = "targetEncoding";
+    public static final String TRANSFORM_NAMESPACE = "transform:";
+    public static final String MIMETYPE_METADATA_EXTRACT = "alfresco-metadata-extract";
+    public static final String MIMETYPE_METADATA_EMBED = "alfresco-metadata-embed";
+
     protected static final String FINISHED_IN = "Finished in ";
     protected static final String NO_TRANSFORMERS = "No transformers";
     protected static final String TRANSFORM_SERVICE_NAME = "TransformService";
 
-    private Log info;
+    private static final int REFERENCE_SIZE = 15;
-    protected Log logger;
+
+    protected ExtensionLookup extensionLookup;
+    private Log singleLineLog;
+    protected Log multiLineLog;
     protected NodeService nodeService;
     protected MimetypeService mimetypeService;
     private final ThreadLocal<Integer> previousTransformId = ThreadLocal.withInitial(()->-1);
 
+    public interface ExtensionLookup
+    {
+        String getExtension(String mimetype);
+    }
+
     protected enum Call
     {
         AVAILABLE,
@@ -143,7 +152,6 @@ public class TransformerDebug
         private Call callType;
         private Frame parent;
         private int childId;
-        protected Set<UnavailableTransformer> unavailableTransformers;
         private String failureReason;
         private long sourceSize;
         private String transformerName;
@@ -165,6 +173,11 @@ public class TransformerDebug
             start = System.currentTimeMillis();
         }
 
+        static void reset()
+        {
+            uniqueId.set(0);
+        }
+
         private int getId()
         {
             if (id == -1)
@@ -210,65 +223,19 @@ public class TransformerDebug
         }
     }
 
-    @Deprecated
+    public void setExtensionLookup(ExtensionLookup extensionLookup)
-    protected class UnavailableTransformer implements Comparable<UnavailableTransformer>
     {
-        protected final String name;
+        this.extensionLookup = extensionLookup;
-        protected final String priority;
-        protected final long maxSourceSizeKBytes;
-        protected final transient boolean debug;
-        
-        UnavailableTransformer(String name, String priority, long maxSourceSizeKBytes, boolean debug)
-        {
-            this.name = name;
-            this.priority = priority;
-            this.maxSourceSizeKBytes = maxSourceSizeKBytes;
-            this.debug = debug;
-        }
-        
-        @Override
-        public int hashCode()
-        {
-            int hashCode = 37 * name.hashCode();
-            hashCode += 37 * maxSourceSizeKBytes;
-            return hashCode;
-        }
-
-        @Override
-        public boolean equals(Object obj)
-        {
-            if (this == obj)
-            {
-                return true;
-            }
-            else if (obj instanceof UnavailableTransformer)
-            {
-                UnavailableTransformer that = (UnavailableTransformer) obj;
-                return
-                    EqualsHelper.nullSafeEquals(name, that.name) &&
-                    maxSourceSizeKBytes == that.maxSourceSizeKBytes;
-            }
-            else
-            {
-                return false;
-            }
-        }
-
-        @Override
-        public int compareTo(UnavailableTransformer o)
-        {
-            return name.compareTo(o.name);
-        }
     }
 
     public void setTransformerLog(Log transformerLog)
     {
-        info = new LogTee(LogFactory.getLog(TransformerLog.class), transformerLog);
+        singleLineLog = new LogTee(LogFactory.getLog(TransformerLog.class), transformerLog);
     }
 
     public void setTransformerDebugLog(Log transformerDebugLog)
     {
-        logger = new LogTee(LogFactory.getLog(TransformerDebug.class), transformerDebugLog);
+        multiLineLog = new LogTee(LogFactory.getLog(TransformerDebug.class), transformerDebugLog);
     }
 
     public void setNodeService(NodeService nodeService)
@@ -279,6 +246,7 @@ public class TransformerDebug
     public void setMimetypeService(MimetypeService mimetypeService)
     {
         this.mimetypeService = mimetypeService;
+        setExtensionLookup(mimetype -> mimetypeService.getExtension(mimetype));
     }
 
     public void setPreviousTransformId(int id)
@@ -295,8 +263,8 @@ public class TransformerDebug
     {
         PropertyCheck.mandatory(this, "nodeService", nodeService);
         PropertyCheck.mandatory(this, "mimetypeService", mimetypeService);
-        PropertyCheck.mandatory(this, "transformerLog", info);
+        PropertyCheck.mandatory(this, "transformerLog", singleLineLog);
-        PropertyCheck.mandatory(this, "transformerDebugLog", logger);
+        PropertyCheck.mandatory(this, "transformerDebugLog", multiLineLog);
     }
 
     public void pushTransform(String transformerName, String fromUrl, String sourceMimetype,
@@ -361,15 +329,15 @@ public class TransformerDebug
         }
         log(frame.sourceMimetype+' '+frame.targetMimetype, false);
 
-        String fileName = getFileName(frame.sourceNodeRef, firstLevel, sourceSize);
+        String filename = getFilename(frame.sourceNodeRef, firstLevel);
         log(getSourceAndTargetExt(frame.sourceMimetype, frame.targetMimetype) +
-                ((fileName != null) ? fileName+' ' : "")+
+                ((filename != null) ? filename+' ' : "")+
                 ((sourceSize >= 0) ? fileSize(sourceSize)+' ' : "") +
                 (firstLevel ? getRenditionName(renditionName) : "") + message);
         if (firstLevel)
         {
             log(options);
-            String nodeRef = getNodeRef(frame.sourceNodeRef, firstLevel, sourceSize);
+            String nodeRef = getNodeRef(frame.sourceNodeRef);
             if (!nodeRef.isEmpty())
             {
                 log(nodeRef);
@@ -377,17 +345,6 @@ public class TransformerDebug
         }
     }
 
-    public void debug(String sourceMimetype, String targetMimetype, NodeRef sourceNodeRef, long sourceSize,
-                      Map<String, String> options, String renditionName, String message)
-    {
-        String fileName = getFileName(sourceNodeRef, true, -1);
-        log("              "+ getSourceAndTargetExt(sourceMimetype, targetMimetype) +
-                ((fileName != null) ? fileName+' ' : "")+
-                ((sourceSize >= 0) ? fileSize(sourceSize)+' ' : "") +
-                (getRenditionName(renditionName)) + message);
-        log(options);
-    }
-
     private void log(Map<String, String> options)
     {
         if (options != null)
@@ -452,7 +409,7 @@ public class TransformerDebug
                 logInfo(frame, size, ms);
 
                 boolean firstLevel = size == 1;
-                if (!suppressFinish && (firstLevel || logger.isTraceEnabled()))
+                if (!suppressFinish && (firstLevel || multiLineLog.isTraceEnabled()))
                 {
                     log(FINISHED_IN + ms +
                         (frame.callType == Call.AVAILABLE && !suppressChecking? " Just checking if a transformer is available" : "") +
@@ -470,12 +427,12 @@ public class TransformerDebug
 
     private void logInfo(Frame frame, int size, String ms)
     {
-        if (info.isDebugEnabled())
+        if (singleLineLog.isDebugEnabled())
         {
             String failureReason = frame.getFailureReason();
             boolean firstLevel = size == 1;
             String sourceAndTargetExt = getSourceAndTargetExt(frame.sourceMimetype, frame.targetMimetype);
-            String fileName = getFileName(frame.sourceNodeRef, firstLevel, frame.sourceSize);
+            String filename = getFilename(frame.sourceNodeRef, firstLevel);
             long sourceSize = frame.getSourceSize();
             String transformerName = frame.getTransformerName();
             String renditionName = frame.getRenditionName();
@@ -486,26 +443,6 @@ public class TransformerDebug
                 debug = firstLevel;
                 level = "INFO";
                 failureReason = NO_TRANSFORMERS;
-                
-                // If trace and trace is disabled do nothing
-                if (debug || info.isTraceEnabled())
-                {
-                    // Work out size reason that there are no transformers
-                    if (frame.unavailableTransformers != null)
-                    {
-                        level = "WARN";
-                        long smallestMaxSourceSizeKBytes = Long.MAX_VALUE;
-                        for (UnavailableTransformer unavailable: frame.unavailableTransformers)
-                        {
-                            if (smallestMaxSourceSizeKBytes > unavailable.maxSourceSizeKBytes && unavailable.maxSourceSizeKBytes > 0)
-                            {
-                                smallestMaxSourceSizeKBytes = unavailable.maxSourceSizeKBytes;
-                            }
-                        }
-                        smallestMaxSourceSizeKBytes = smallestMaxSourceSizeKBytes == Long.MAX_VALUE ? 0 : smallestMaxSourceSizeKBytes;
-                        failureReason = "No transformers as file is > "+fileSize(smallestMaxSourceSizeKBytes*1024);
-                    }
-                }
             }
             else if (frame.callType == Call.TRANSFORM)
             {
@@ -517,20 +454,20 @@ public class TransformerDebug
 
             if (level != null)
             {
-                infoLog(getReference(debug, false, false), sourceAndTargetExt, level, fileName, sourceSize,
+                infoLog(getReference(firstLevel, false, false), sourceAndTargetExt, level, filename, sourceSize,
                         transformerName, renditionName, failureReason, ms, debug);
             }
         }
     }
 
-    private void infoLog(String reference, String sourceAndTargetExt, String level, String fileName,
+    private void infoLog(String reference, String sourceAndTargetExt, String level, String filename,
             long sourceSize, String transformerName, String renditionName, String failureReason, String ms, boolean debug)
     {
         String message =
                 reference +
                 sourceAndTargetExt +
                 (level == null ? "" : level+' ') +
-                (fileName == null ? "" : fileName) +
+                (filename == null ? "" : filename) +
                 (sourceSize >= 0 ? ' '+fileSize(sourceSize) : "") +
                 (ms == null || ms.isEmpty() ? "" : ' '+ms)+
                 (transformerName == null ? "" : ' '+transformerName) +
@@ -538,11 +475,11 @@ public class TransformerDebug
                 (failureReason == null ? "" : ' '+failureReason.trim());
         if (debug)
         {
-            info.debug(message);
+            singleLineLog.debug(message);
         }
         else
         {
-            info.trace(message);
+            singleLineLog.trace(message);
         }
     }
 
@@ -552,7 +489,7 @@ public class TransformerDebug
     public boolean isEnabled()
     {
         // Don't check ThreadInfo.getDebugOutput() as availableTransformers() may upgrade from trace to debug.
-        return logger.isDebugEnabled() || info.isDebugEnabled() || ThreadInfo.getStringBuilder() != null;
+        return multiLineLog.isDebugEnabled() || singleLineLog.isDebugEnabled() || ThreadInfo.getStringBuilder() != null;
     }
 
     /**
@@ -617,7 +554,6 @@ public class TransformerDebug
                 log(message);
             }
 
-            
             Deque<Frame> ourStack = ThreadInfo.getStack();
             if (!ourStack.isEmpty())
             {
@@ -661,13 +597,13 @@ public class TransformerDebug
 
     private void log(String message, Throwable t, boolean debug, boolean usePreviousRef)
     {
-        if (debug && ThreadInfo.getDebugOutput() && logger.isDebugEnabled())
+        if (debug && ThreadInfo.getDebugOutput() && multiLineLog.isDebugEnabled())
         {
-            logger.debug(getReference(false, false, usePreviousRef)+message, t);
+            multiLineLog.debug(getReference(false, false, usePreviousRef)+message, t);
         }
-        else if (logger.isTraceEnabled())
+        else if (multiLineLog.isTraceEnabled())
         {
-            logger.trace(getReference(false, false, usePreviousRef)+message, t);
+            multiLineLog.trace(getReference(false, false, usePreviousRef)+message, t);
         }
 
         if (debug)
@@ -729,7 +665,7 @@ public class TransformerDebug
             String ref = "";
             if (id >= 0)
             {
-                ref = Integer.toString(id)+spaces(13);
+                ref = Integer.toString(id)+spaces(REFERENCE_SIZE);
             }
             return ref;
         }
@@ -775,73 +711,75 @@ public class TransformerDebug
             }
             else
             {
-                sb.append(spaces(13-sb.length()+lengthOfFirstId)); // Try to pad to level 7
+                sb.append(spaces(REFERENCE_SIZE-sb.length()+lengthOfFirstId)); // Try to pad to level 7
             }
         }
         return sb.toString();
     }
 
-    public String getFileName(NodeRef sourceNodeRef, boolean firstLevel, long sourceSize)
+    public String getFilename(NodeRef sourceNodeRef, boolean firstLevel)
     {
-        return getFileNameOrNodeRef(sourceNodeRef, firstLevel, sourceSize, true);
+        String result = null;
-    }
-
-    private String getNodeRef(NodeRef sourceNodeRef, boolean firstLevel, long sourceSize)
-    {
-        return getFileNameOrNodeRef(sourceNodeRef, firstLevel, sourceSize, false);
-    }
-    
-    private String getFileNameOrNodeRef(NodeRef sourceNodeRef, boolean firstLevel, long sourceSize, boolean getName)
-    {
-        String result = getName ? null : "";
         if (sourceNodeRef != null)
         {
             try
             {
-                result = getName
+                result = (String)nodeService.getProperty(sourceNodeRef, ContentModel.PROP_NAME);
-                        ? (String)nodeService.getProperty(sourceNodeRef, ContentModel.PROP_NAME)
-                        : sourceNodeRef.toString()+" ";
             }
             catch (RuntimeException e)
             {
-                // ignore (normally InvalidNodeRefException) but we should ignore other RuntimeExceptions too
+                // ignore (InvalidNodeRefException/MalformedNodeRefException) but we should ignore other RuntimeExceptions too
             }
         }
-        if (result == null)
+        if (result == null && !firstLevel)
         {
-            if (!firstLevel)
+            result = "<<TemporaryFile>>";
-            {
-                result = getName ? "<<TemporaryFile>>" : "";
-            }
-            else if (sourceSize < 0)
-            {
-                // fileName = "<<AnyFile>>"; commented out as it does not add to debug readability
-            }
         }
         return result;
     }
 
+    private String getNodeRef(NodeRef sourceNodeRef)
+    {
+        return sourceNodeRef == null ? "" : sourceNodeRef.toString();
+    }
+
     protected String getSourceAndTargetExt(String sourceMimetype, String targetMimetype)
     {
         String sourceExt = getMimetypeExt(sourceMimetype);
         String targetExt = getMimetypeExt(targetMimetype);
-        targetExt = AsynchronousExtractor.getExtension(targetMimetype, sourceExt, targetExt);
+        targetExt = replaceWithMetadataExtensionIfEmbedOrExtract(targetMimetype, sourceExt, targetExt);
         return sourceExt + targetExt + spaces(1+4-targetExt.length());
     }
 
+    public static String replaceWithMetadataExtensionIfEmbedOrExtract(String targetMimetype, String sourceExtension, String targetExtension)
+    {
+        return isMetadataExtractMimetype(targetMimetype)
+                ? "json"
+                : isMetadataEmbedMimetype(targetMimetype)
+                ? sourceExtension
+                : targetExtension;
+    }
+
     protected String getMimetypeExt(String mimetype)
     {
         StringBuilder sb = new StringBuilder("");
-        if (mimetypeService == null)
+        if (extensionLookup == null)
+        {
+            sb.append(mimetype);
+        }
+        else
+        {
+            String mimetypeExt = extensionLookup.getExtension(mimetype);
+            if (mimetypeExt == null)
             {
                 sb.append(mimetype);
             }
             else
             {
-            String mimetypeExt = mimetypeService.getExtension(mimetype);
                 sb.append(mimetypeExt);
                 sb.append(spaces(4 - mimetypeExt.length()));   // Pad to normal max ext (4)
             }
+        }
         sb.append(' ');
         return sb.toString();
     }
@@ -907,7 +845,7 @@ public class TransformerDebug
      * Debugs a request to the Transform Service
      */
     public int debugTransformServiceRequest(String sourceMimetype, long sourceSize, NodeRef sourceNodeRef,
-                                            int contentHashcode, String fileName, String targetMimetype,
+                                            int contentHashcode, String filename, String targetMimetype,
                                             Map<String, String> options, String renditionName)
     {
         if (isEnabled())
@@ -915,43 +853,90 @@ public class TransformerDebug
             pushMisc();
             String sourceAndTargetExt = getSourceAndTargetExt(sourceMimetype, targetMimetype);
             debug(sourceAndTargetExt +
-                    ((fileName != null) ? fileName + ' ' : "") +
+                    ((filename != null) ? filename + ' ' : "") +
                     ((sourceSize >= 0) ? fileSize(sourceSize) + ' ' : "") +
                     getRenditionName(renditionName) + " "+ TRANSFORM_SERVICE_NAME);
-            log(options);
-            log(sourceNodeRef.toString() + ' ' + contentHashcode);
             String reference = getReference(true, false, false);
-            infoLog(reference, sourceAndTargetExt, null, fileName, sourceSize, TRANSFORM_SERVICE_NAME,
+            infoLog(reference, sourceAndTargetExt, null, filename, sourceSize, TRANSFORM_SERVICE_NAME,
                     renditionName, null, "", true);
         }
         return pop(Call.AVAILABLE, true, false);
     }
 
-    private String getRenditionName(String renditionName)
+    String getRenditionName(String renditionName)
     {
         return renditionName != null
-            ? "-- "+ AsynchronousExtractor.getRenditionName(renditionName)+" -- "
+                ? "-- "+ replaceWithMetadataRenditionNameIfEmbedOrExtract(renditionName)+" -- "
                 : "";
     }
 
+    static String replaceWithMetadataRenditionNameIfEmbedOrExtract(String renditionName)
+    {
+        String transformName = getTransformName(renditionName);
+        return    transformName != null && transformName.startsWith(MIMETYPE_METADATA_EXTRACT)
+                ? "metadataExtract"
+                : transformName != null && transformName.startsWith(MIMETYPE_METADATA_EMBED)
+                ? "metadataEmbed"
+                : renditionName;
+    }
+
+    static String getTransformName(String renditionName)
+    {
+        return renditionName == null || !renditionName.startsWith(TRANSFORM_NAMESPACE)
+                ? null
+                : renditionName.substring(TRANSFORM_NAMESPACE.length());
+    }
+
+    public static boolean isMetadataExtractMimetype(String targetMimetype)
+    {
+        return MIMETYPE_METADATA_EXTRACT.equals(targetMimetype);
+    }
+
+    public static boolean isMetadataEmbedMimetype(String targetMimetype)
+    {
+        return MIMETYPE_METADATA_EMBED.equals(targetMimetype);
+    }
+
     /**
      * Debugs a response to the Transform Service
      */
-    public void debugTransformServiceResponse(NodeRef sourceNodeRef, int contentHashcode,
+    public void debugTransformServiceResponse(long requested, int id, String msg, Collection<String> debugLines)
-                                              long requested, int id, String sourceExt, String targetExt, String msg)
+    {
+        boolean suppressFinish = debugTransformServiceResponsePreConsume(requested, id, msg, debugLines);
+        debugTransformServiceResponsePostConsume(suppressFinish);
+    }
+
+    /**
+     * Debugs a response to the Transform Service
+     */
+    public boolean debugTransformServiceResponsePreConsume(long requested, int id, String msg, Collection<String> debugLines)
+    {
+        boolean suppressFinish = id == -1 || requested == -1;
+        if (isEnabled())
         {
             pushMisc();
             Frame frame = ThreadInfo.getStack().getLast();
             frame.id = id;
-        boolean suppressFinish = id == -1 || requested == -1;
             if (!suppressFinish)
             {
                 frame.start = requested;
             }
             debug(msg);
-        debug(sourceNodeRef.toString() + ' ' +contentHashcode);
+            debugLines.forEach(line -> multiLineLog.debug(line));
+        }
+        return suppressFinish;
+    }
+
+    /**
+     * Debugs a response to the Transform Service
+     */
+    public void debugTransformServiceResponsePostConsume(boolean suppressFinish)
+    {
+        if (isEnabled())
+        {
             pop(Call.AVAILABLE, suppressFinish, true);
         }
+    }
 
     /**
      * Obtains a String for log messages.

repository/src/test/java/org/alfresco/AllUnitTestsSuite.java

@@ -2,7 +2,7 @@
  * #%L
  * Alfresco Repository
  * %%
- * Copyright (C) 2005 - 2021 Alfresco Software Limited
+ * Copyright (C) 2005 - 2022 Alfresco Software Limited
  * %%
  * This file is part of the Alfresco software. 
  * If the software was purchased under a paid Alfresco license, the terms of 
@@ -191,6 +191,7 @@ import org.junit.runners.Suite;
     org.alfresco.service.cmr.repository.TransformationOptionLimitsTest.class,
     org.alfresco.service.cmr.repository.TransformationOptionPairTest.class,
     org.alfresco.repo.content.transform.TransformerConfigTestSuite.class,
+    org.alfresco.repo.content.transform.TransformerDebugTest.class,
     org.alfresco.service.cmr.repository.TemporalSourceOptionsTest.class,
     org.alfresco.repo.content.metadata.MetadataExtracterLimitsTest.class,
     org.alfresco.repo.content.caching.quota.StandardQuotaStrategyMockTest.class,

repository/src/test/java/org/alfresco/repo/content/transform/TransformerDebugTest.java

@@ -0,0 +1,392 @@
+/*
+ * #%L
+ * Alfresco Repository
+ * %%
+ * Copyright (C) 2005 - 2022 Alfresco Software Limited
+ * %%
+ * This file is part of the Alfresco software.
+ * If the software was purchased under a paid Alfresco license, the terms of
+ * the paid license agreement will prevail.  Otherwise, the software is
+ * provided under the following open source license terms:
+ *
+ * Alfresco is free software: you can redistribute it and/or modify
+ * it under the terms of the GNU Lesser General Public License as published by
+ * the Free Software Foundation, either version 3 of the License, or
+ * (at your option) any later version.
+ *
+ * Alfresco is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+ * GNU Lesser General Public License for more details.
+ *
+ * You should have received a copy of the GNU Lesser General Public License
+ * along with Alfresco. If not, see <http://www.gnu.org/licenses/>.
+ * #L%
+ */
+package org.alfresco.repo.content.transform;
+
+import com.google.common.collect.ImmutableMap;
+import org.alfresco.model.ContentModel;
+import org.alfresco.service.cmr.repository.NodeRef;
+import org.alfresco.service.cmr.repository.NodeService;
+import org.alfresco.util.LogAdapter;
+import org.apache.commons.logging.Log;
+import org.junit.Before;
+import org.junit.Test;
+import org.mockito.Mock;
+import org.mockito.MockitoAnnotations;
+
+import java.util.Map;
+import java.util.concurrent.atomic.AtomicReference;
+
+import static org.junit.Assert.assertEquals;
+import static org.mockito.ArgumentMatchers.any;
+import static org.mockito.Mockito.doReturn;
+
+public class TransformerDebugTest
+{
+    public static final String RENDITION_2B = "renditionName1";
+    public static final String TRANSFORMER_A2B = "transformerA2B";
+    public static final String TRANSFORMER_A2C = "transformerA2C";
+    public static final String TRANSFORMER_C2B = "transformerC2B";
+
+    private TransformerDebug transformerDebug;
+
+    public static final String MIMETYPE_A = "mimetypeA";
+    public static final String MIMETYPE_A_EXT = "a";
+    public static final String MIMETYPE_B = "mimetypeB";
+    public static final String MIMETYPE_B_EXT = "bbb";
+    public static final String MIMETYPE_C = "mimetypeC";
+    public static final String MIMETYPE_C_EXT = "ccc";
+    public static final String MIMETYPE_DOCX = "application/vnd.openxmlformats-officedocument.wordprocessingml.document";
+    public static final String MIMETYPE_DOCX_EXT = "docx";
+    public static final String MIMETYPE_LONGER = "mimetypeLonger";
+    public static final String MIMETYPE_LONGER_EXT = "longer";
+
+    private static final Map<String, String> testMimetypeService = ImmutableMap.of(
+            MIMETYPE_A, MIMETYPE_A_EXT,
+            MIMETYPE_B, MIMETYPE_B_EXT,
+            MIMETYPE_C, MIMETYPE_C_EXT,
+            MIMETYPE_DOCX, MIMETYPE_DOCX_EXT,
+            MIMETYPE_LONGER, MIMETYPE_LONGER_EXT);
+
+    private StringBuilder singleLine;
+    private StringBuilder multiLine;
+    private AtomicReference<LogLevel> singleLineLogLevel = new AtomicReference<>();
+    private AtomicReference<LogLevel> multiLineLogLevel = new AtomicReference<>();
+    private Map<String, String> options;
+
+    @Mock
+    private NodeService nodeService;
+    private NodeRef sourceNodeRef = new NodeRef("workspace://SpacesStore/parent");
+
+    @Before
+    public void setUp()
+    {
+        MockitoAnnotations.initMocks(this);
+        TransformerDebug.Frame.reset();
+        singleLine = new StringBuilder();
+        multiLine = new StringBuilder();
+        singleLineLogLevel.set(LogLevel.DEBUG);
+        multiLineLogLevel.set(LogLevel.DEBUG);
+        transformerDebug = new TransformerDebug();
+        transformerDebug.setExtensionLookup(mimetype -> testMimetypeService.get(mimetype));
+        transformerDebug.setTransformerDebugLog(new DummyLog(multiLine, multiLineLogLevel));
+        transformerDebug.setTransformerLog(new DummyLog(singleLine, singleLineLogLevel));
+        transformerDebug.setNodeService(nodeService);
+        options = ImmutableMap.of(
+                "option1", "value1",
+                "option2", "value2");
+        doReturn("filename1.a").when(nodeService).getProperty(sourceNodeRef, ContentModel.PROP_NAME);
+    }
+
+    private static String getSanitisedActual(StringBuilder debug)
+    {
+        return debug.toString()
+                .replaceAll(" [\\d,]+ ms", " nn ms"); // the time can change
+    }
+
+    @Test
+    public void testSingleLevelTransformDebug()
+    {
+        String expectedSingleLine =
+                "DEBUG 0 a    bbb  INFO filename1.a 1 KB nn ms transformerA2B -- renditionName1 -- ";
+        String expectedMultiLine =
+                "DEBUG 0               a    bbb  filename1.a 1 KB -- renditionName1 -- transformerA2B\n" +
+                "DEBUG 0                 option1=\"value1\"\n" +
+                "DEBUG 0                 option2=\"value2\"\n" +
+                "DEBUG 0               workspace://SpacesStore/parent\n" +
+                "DEBUG 0               Finished in nn ms\n";
+
+        testSingleLevelTransform(expectedSingleLine, expectedMultiLine);
+    }
+
+    @Test
+    public void testSingleLevelTransformTrace()
+    {
+        singleLineLogLevel.set(LogLevel.TRACE);
+        multiLineLogLevel.set(LogLevel.TRACE);
+
+        String expectedSingleLine =
+                "DEBUG 0 a    bbb  INFO filename1.a 1 KB nn ms transformerA2B -- renditionName1 -- ";
+        String expectedMultiLine =
+                "TRACE 0               fromUrl1\n" +
+                "TRACE 0               mimetypeA mimetypeB\n" +
+                "DEBUG 0               a    bbb  filename1.a 1 KB -- renditionName1 -- transformerA2B\n" +
+                "DEBUG 0                 option1=\"value1\"\n" +
+                "DEBUG 0                 option2=\"value2\"\n" +
+                "DEBUG 0               workspace://SpacesStore/parent\n" +
+                "DEBUG 0               Finished in nn ms\n";
+
+        testSingleLevelTransform(expectedSingleLine, expectedMultiLine);
+    }
+
+    @Test
+    public void testSingleLevelTransformInfo()
+    {
+        singleLineLogLevel.set(LogLevel.INFO);
+        multiLineLogLevel.set(LogLevel.INFO);
+
+        String expectedSingleLine = "";
+        String expectedMultiLine = "";
+
+        testSingleLevelTransform(expectedSingleLine, expectedMultiLine);
+    }
+
+    private void testSingleLevelTransform(String expectedSingleLine, String expectedMultiLine)
+    {
+        transformerDebug.pushTransform(TRANSFORMER_A2B, "fromUrl1", MIMETYPE_A, MIMETYPE_B,
+                1024, options, RENDITION_2B, sourceNodeRef);
+        transformerDebug.popTransform();
+
+        assertEquals(expectedSingleLine, getSanitisedActual(singleLine));
+        assertEquals(expectedMultiLine, getSanitisedActual(multiLine));
+    }
+
+    @Test
+    public void testMultiLevelTransformDebug()
+    {
+        String expectedSingleLine =
+                "DEBUG 0 a    bbb  INFO filename1.a 1 KB nn ms transformerA2B -- renditionName1 -- ";
+        String expectedMultiLine =
+                "DEBUG 0               a    bbb  filename1.a 1 KB -- renditionName1 -- transformerA2B\n" +
+                "DEBUG 0                 option1=\"value1\"\n" +
+                "DEBUG 0                 option2=\"value2\"\n" +
+                "DEBUG 0               workspace://SpacesStore/parent\n" +
+                "DEBUG 0.1             a    ccc  filename1.a 1 KB transformerA2C\n" +
+                "DEBUG 0.2             ccc  bbb  filename1.a 1 KB transformerC2B\n" +
+                "DEBUG 0               Finished in nn ms\n";
+
+        testMultiLevelTransform(expectedSingleLine, expectedMultiLine);
+    }
+
+    @Test
+    public void testMultiLevelTransformTrace()
+    {
+        singleLineLogLevel.set(LogLevel.TRACE);
+        multiLineLogLevel.set(LogLevel.TRACE);
+
+        String expectedSingleLine =
+                "TRACE 0.1             a    ccc  INFO filename1.a 1 KB nn ms transformerA2C -- renditionName1 -- \n" +
+                "TRACE 0.2             ccc  bbb  INFO filename1.a 1 KB nn ms transformerC2B -- renditionName1 -- \n" +
+                "DEBUG 0 a    bbb  INFO filename1.a 1 KB nn ms transformerA2B -- renditionName1 -- ";
+        String expectedMultiLine =
+                "TRACE 0               fromUrl1\n" +
+                "TRACE 0               mimetypeA mimetypeB\n" +
+                "DEBUG 0               a    bbb  filename1.a 1 KB -- renditionName1 -- transformerA2B\n" +
+                "DEBUG 0                 option1=\"value1\"\n" +
+                "DEBUG 0                 option2=\"value2\"\n" +
+                "DEBUG 0               workspace://SpacesStore/parent\n" +
+                "TRACE 0.1             fromUrl1\n" +
+                "TRACE 0.1             mimetypeA mimetypeC\n" +
+                "DEBUG 0.1             a    ccc  filename1.a 1 KB transformerA2C\n" +
+                "TRACE 0.1             Finished in nn ms\n" +
+                "TRACE 0.2             fromUrl1\n" +
+                "TRACE 0.2             mimetypeC mimetypeB\n" +
+                "DEBUG 0.2             ccc  bbb  filename1.a 1 KB transformerC2B\n" +
+                "TRACE 0.2             Finished in nn ms\n" +
+                "DEBUG 0               Finished in nn ms\n";
+
+        testMultiLevelTransform(expectedSingleLine, expectedMultiLine);
+    }
+
+    @Test
+    public void testMultiLevelTransformInfo()
+    {
+        singleLineLogLevel.set(LogLevel.INFO);
+        multiLineLogLevel.set(LogLevel.INFO);
+
+        String expectedSingleLine = "";
+        String expectedMultiLine = "";
+
+        testMultiLevelTransform(expectedSingleLine, expectedMultiLine);
+    }
+
+    private void testMultiLevelTransform(String expectedSingleLine, String expectedMultiLine)
+    {
+        transformerDebug.pushTransform(TRANSFORMER_A2B, "fromUrl1", MIMETYPE_A, MIMETYPE_B,
+                1024, options, RENDITION_2B, sourceNodeRef);
+        transformerDebug.pushTransform(TRANSFORMER_A2C, "fromUrl1", MIMETYPE_A, MIMETYPE_C,
+                1024, options, RENDITION_2B, sourceNodeRef);
+        transformerDebug.popTransform();
+        transformerDebug.pushTransform(TRANSFORMER_C2B, "fromUrl1", MIMETYPE_C, MIMETYPE_B,
+                1024, options, RENDITION_2B, sourceNodeRef);
+        transformerDebug.popTransform();
+        transformerDebug.popTransform();
+
+        assertEquals(expectedSingleLine, getSanitisedActual(singleLine));
+        assertEquals(expectedMultiLine, getSanitisedActual(multiLine));
+    }
+
+    @Test
+    public void testReplaceWithMetadataExtensionIfEmbedOrExtract()
+    {
+        assertEquals("json", transformerDebug.replaceWithMetadataExtensionIfEmbedOrExtract(
+                "alfresco-metadata-extract", "jpeg", "targetExtension"));
+        assertEquals("jpeg", transformerDebug.replaceWithMetadataExtensionIfEmbedOrExtract(
+                "alfresco-metadata-embed", "jpeg", "targetExtension"));
+        assertEquals(MIMETYPE_DOCX_EXT, transformerDebug.replaceWithMetadataExtensionIfEmbedOrExtract(
+                MIMETYPE_DOCX, "jpeg", MIMETYPE_DOCX_EXT));
+    }
+
+    @Test
+    public void testGetMimetypeExt()
+    {
+        assertEquals(MIMETYPE_A_EXT  +"    ", transformerDebug.getMimetypeExt(MIMETYPE_A));
+        assertEquals(MIMETYPE_B_EXT    +"  ", transformerDebug.getMimetypeExt(MIMETYPE_B));
+        assertEquals(MIMETYPE_DOCX_EXT  +" ", transformerDebug.getMimetypeExt(MIMETYPE_DOCX));
+        assertEquals(MIMETYPE_LONGER_EXT+" ", transformerDebug.getMimetypeExt(MIMETYPE_LONGER)); // not padded to 4 spaces
+
+        assertEquals("unknown"          +" ", transformerDebug.getMimetypeExt("unknown"));       // not padded
+        assertEquals("x"                +" ", transformerDebug.getMimetypeExt("x"));             // not padded
+    }
+
+    @Test
+    public void testSpaces()
+    {
+        assertEquals("",        transformerDebug.spaces(-1));
+        assertEquals("",        transformerDebug.spaces(0));
+        assertEquals(" ",       transformerDebug.spaces(1));
+        assertEquals("   ",     transformerDebug.spaces(3));
+        assertEquals("     ",   transformerDebug.spaces(5));
+    }
+
+    @Test
+    public void testMs()
+    {
+        assertEquals("-1 ms",        transformerDebug.ms(-1));
+        assertEquals("0 ms",         transformerDebug.ms(0));
+        assertEquals("1 ms",         transformerDebug.ms(1));
+        assertEquals("2 ms",         transformerDebug.ms(2));
+        assertEquals("123 ms",       transformerDebug.ms(123));
+        assertEquals("1,234 ms",     transformerDebug.ms(1234));
+        assertEquals("3,600,000 ms", transformerDebug.ms(3600000));
+    }
+
+    @Test
+    public void testFileSize()
+    {
+        assertEquals("unlimited", transformerDebug.fileSize(-1));
+        assertEquals("0 bytes",   transformerDebug.fileSize(0));
+        assertEquals("1 byte",    transformerDebug.fileSize(1));
+        assertEquals("2 bytes",   transformerDebug.fileSize(2));
+        assertEquals("2 KB",      transformerDebug.fileSize(2L*1024));
+        assertEquals("3 MB",      transformerDebug.fileSize(3L*1024*1024));
+        assertEquals("4 GB",      transformerDebug.fileSize(4L*1024*1024*1024));
+        assertEquals("5 TB",      transformerDebug.fileSize(5L*1024*1024*1024*1024));
+
+        assertEquals("1.4 KB",    transformerDebug.fileSize(1L*1024 + 511));
+        assertEquals("1.5 KB",    transformerDebug.fileSize(1L*1024 + 512));
+        assertEquals("1.9 KB",    transformerDebug.fileSize(2L*1024 - 1));
+
+        assertEquals("2.9 MB",      transformerDebug.fileSize(3L*1024*1024           - 1));
+        assertEquals("3.9 GB",      transformerDebug.fileSize(4L*1024*1024*1024      - 1));
+        assertEquals("4.9 TB",      transformerDebug.fileSize(5L*1024*1024*1024*1024 - 1));
+    }
+
+    @Test
+    public void testGetRenditionName()
+    {
+        assertEquals("",                                 transformerDebug.getRenditionName(null));
+        assertEquals("-- doclib -- ",                    transformerDebug.getRenditionName("doclib"));
+        assertEquals("-- metadataExtract -- ",           transformerDebug.getRenditionName("transform:alfresco-metadata-extract"));
+        assertEquals("-- metadataEmbed -- ",             transformerDebug.getRenditionName("transform:alfresco-metadata-embed"));
+        assertEquals("-- transform:customTransform -- ", transformerDebug.getRenditionName("transform:customTransform"));
+    }
+
+    @Test
+    public void testGetTransformName()
+    {
+        assertEquals(null,                        transformerDebug.getTransformName(null));
+        assertEquals(null,                        transformerDebug.getTransformName("doclib"));
+        assertEquals("alfresco-metadata-extract", transformerDebug.getTransformName("transform:alfresco-metadata-extract"));
+        assertEquals("alfresco-metadata-embed",   transformerDebug.getTransformName("transform:alfresco-metadata-embed"));
+        assertEquals("customTransform",           transformerDebug.getTransformName("transform:customTransform"));
+    }
+
+    private enum LogLevel
+    {
+        INFO, DEBUG, TRACE;
+
+        boolean isSet(LogLevel levelSet)
+        {
+            return levelSet != null && this.compareTo(levelSet) <= 0;
+        }
+    }
+
+    private class DummyLog extends LogAdapter
+    {
+        private final StringBuilder stringBuilder;
+        private final AtomicReference<LogLevel> logLevel;
+
+        public DummyLog(StringBuilder stringBuilder, AtomicReference<LogLevel> logLevel)
+        {
+            super(null);
+            this.stringBuilder = stringBuilder;
+            this.logLevel = logLevel;
+        }
+
+        @Override
+        public boolean isDebugEnabled()
+        {
+            return LogLevel.DEBUG.isSet(logLevel.get());
+        }
+
+        @Override
+        public boolean isTraceEnabled()
+        {
+            return LogLevel.TRACE.isSet(logLevel.get());
+        }
+
+        @Override
+        public void debug(Object message, Throwable throwable)
+        {
+            if (isDebugEnabled())
+            {
+                append(message, throwable, "DEBUG ");
+            }
+        }
+
+        @Override
+        public void trace(Object message, Throwable throwable)
+        {
+            if (isTraceEnabled())
+            {
+                append(message, throwable, "TRACE ");
+            }
+        }
+
+        private void append(Object message, Throwable throwable, String prefix)
+        {
+            if (stringBuilder.length() > 0)
+            {
+                stringBuilder.append('\n');
+            }
+            stringBuilder.append(prefix).append(message);
+            if (throwable != null)
+            {
+                stringBuilder.append("\n      ").append(throwable.getMessage());
+            }
+        }
+    }
+}