From 451a9d1f6072e79875d0418176c8b88d97d453eb Mon Sep 17 00:00:00 2001 From: Alan Davis Date: Wed, 5 Jan 2022 21:46:41 +0000 Subject: [PATCH] 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 | 2 +- .../transform/AbstractLocalTransform.java | 6 +- .../content/transform/TransformerDebug.java | 357 ++++++++-------- .../java/org/alfresco/AllUnitTestsSuite.java | 3 +- .../transform/TransformerDebugTest.java | 392 ++++++++++++++++++ 5 files changed, 569 insertions(+), 191 deletions(-) create mode 100644 repository/src/test/java/org/alfresco/repo/content/transform/TransformerDebugTest.java diff --git a/pom.xml b/pom.xml index d445f2f06c..7e04372c82 100644 --- a/pom.xml +++ b/pom.xml @@ -51,7 +51,7 @@ 0.2 5.23.0 5.23.0 - 1.4.3 + 1.4.5 6.2 0.0.13 diff --git a/repository/src/main/java/org/alfresco/repo/content/transform/AbstractLocalTransform.java b/repository/src/main/java/org/alfresco/repo/content/transform/AbstractLocalTransform.java index 0b6de7420d..6a4dcf4002 100644 --- a/repository/src/main/java/org/alfresco/repo/content/transform/AbstractLocalTransform.java +++ b/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 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+")."; diff --git a/repository/src/main/java/org/alfresco/repo/content/transform/TransformerDebug.java b/repository/src/main/java/org/alfresco/repo/content/transform/TransformerDebug.java index 8b7cac01b4..6ecdc5571a 100644 --- a/repository/src/main/java/org/alfresco/repo/content/transform/TransformerDebug.java +++ b/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.

* @@ -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; - protected Log logger; + private static final int REFERENCE_SIZE = 15; + + protected ExtensionLookup extensionLookup; + private Log singleLineLog; + protected Log multiLineLog; protected NodeService nodeService; protected MimetypeService mimetypeService; private final ThreadLocal previousTransformId = ThreadLocal.withInitial(()->-1); + public interface ExtensionLookup + { + String getExtension(String mimetype); + } + protected enum Call { AVAILABLE, @@ -92,12 +101,12 @@ public class TransformerDebug private final Deque isTransformableStack = new ArrayDeque(); private boolean debugOutput = true; private StringBuilder sb; - + public static Deque getStack() { return threadInfo.get().stack; } - + public static boolean getDebugOutput() { return threadInfo.get().debugOutput; @@ -107,7 +116,7 @@ public class TransformerDebug { return threadInfo.get().isTransformableStack; } - + public static boolean setDebugOutput(boolean debugOutput) { ThreadInfo thisThreadInfo = threadInfo.get(); @@ -115,7 +124,7 @@ public class TransformerDebug thisThreadInfo.debugOutput = debugOutput; return orig; } - + public static StringBuilder getStringBuilder() { return threadInfo.get().sb; @@ -143,11 +152,10 @@ public class TransformerDebug private Call callType; private Frame parent; private int childId; - protected Set unavailableTransformers; private String failureReason; private long sourceSize; private String transformerName; - + private Frame(Frame parent, String transformerName, String fromUrl, String sourceMimetype, String targetMimetype, long sourceSize, String renditionName, NodeRef sourceNodeRef, Call pushCall, boolean origDebugOutput) { @@ -164,13 +172,18 @@ public class TransformerDebug this.origDebugOutput = origDebugOutput; start = System.currentTimeMillis(); } - + + static void reset() + { + uniqueId.set(0); + } + private int getId() { if (id == -1) { id = parent == null ? uniqueId.getAndIncrement() : ++parent.childId; - } + } return id; } @@ -210,65 +223,19 @@ public class TransformerDebug } } - @Deprecated - protected class UnavailableTransformer implements Comparable + public void setExtensionLookup(ExtensionLookup extensionLookup) { - protected final String name; - 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); - } + this.extensionLookup = extensionLookup; } 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, "transformerDebugLog", logger); + PropertyCheck.mandatory(this, "transformerLog", singleLineLog); + PropertyCheck.mandatory(this, "transformerDebugLog", multiLineLog); } public void pushTransform(String transformerName, String fromUrl, String sourceMimetype, @@ -360,16 +328,16 @@ public class TransformerDebug log(frame.fromUrl, false); } 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 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 options) { if (options != null) @@ -450,16 +407,16 @@ public class TransformerDebug String ms = ms(System.currentTimeMillis() - frame.start); 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" : "") + - (firstLevel ? "\n" : ""), + (firstLevel ? "\n" : ""), firstLevel); } - + setDebugOutput(frame.origDebugOutput); ourStack.pop(); } @@ -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,51 +443,31 @@ 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) { level = failureReason == null || failureReason.length() == 0 ? "INFO" : "ERROR"; - + // Use TRACE logging for all but the first TRANSFORM debug = size == 1 || (size == 2 && ThreadInfo.getStack().peekLast().callType != Call.TRANSFORM); } 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,11 +489,11 @@ 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; } - + /** - * Enable or disable debug log output. Normally used to hide calls to + * Enable or disable debug log output. Normally used to hide calls to * getTransformer as trace rather than debug level log messages. There * are lots of these and it makes it hard to see what is going on. * @param debugOutput if {@code true} both debug and trace is generated. Otherwise all output is trace. @@ -616,8 +553,7 @@ public class TransformerDebug { log(message); } - - + Deque ourStack = ThreadInfo.getStack(); if (!ourStack.isEmpty()) { @@ -635,7 +571,7 @@ public class TransformerDebug t = cause; cause = t.getCause(); } - + String message = t.getMessage(); if (message == null || message.length() == 0) { @@ -648,7 +584,7 @@ public class TransformerDebug { log(message, true); } - + protected void log(String message, boolean debug) { log(message, null, debug); @@ -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,77 +711,79 @@ 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); - } - - 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 : ""; + String result = null; if (sourceNodeRef != null) { try { - result = getName - ? (String)nodeService.getProperty(sourceNodeRef, ContentModel.PROP_NAME) - : sourceNodeRef.toString()+" "; + result = (String)nodeService.getProperty(sourceNodeRef, ContentModel.PROP_NAME); } 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 = getName ? "<>" : ""; - } - else if (sourceSize < 0) - { - // fileName = "<>"; commented out as it does not add to debug readability - } + result = "<>"; } 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 = mimetypeService.getExtension(mimetype); - sb.append(mimetypeExt); - sb.append(spaces(4-mimetypeExt.length())); // Pad to normal max ext (4) + String mimetypeExt = extensionLookup.getExtension(mimetype); + if (mimetypeExt == null) + { + sb.append(mimetype); + } + else + { + sb.append(mimetypeExt); + sb.append(spaces(4 - mimetypeExt.length())); // Pad to normal max ext (4) + } } sb.append(' '); return sb.toString(); } - + protected String spaces(int i) { StringBuilder sb = new StringBuilder(""); @@ -855,12 +793,12 @@ public class TransformerDebug } return sb.toString(); } - + public String ms(long time) { return String.format("%,d ms", time); } - + public String fileSize(long size) { if (size < 0) @@ -876,7 +814,7 @@ public class TransformerDebug for(int i = 0; i < units.length-1; i++) { long nextDivider = divider * 1024; - if(size < nextDivider) + if (size < nextDivider) { return fileSizeFormat(size, divider, units[i]); } @@ -884,12 +822,12 @@ public class TransformerDebug } return fileSizeFormat(size, divider, units[units.length-1]); } - + private String fileSizeFormat(long size, long divider, String unit) { size = size * 10 / divider; int decimalPoint = (int) size % 10; - + StringBuilder sb = new StringBuilder(); sb.append(size/10); if (decimalPoint != 0) @@ -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 options, String renditionName) { if (isEnabled()) @@ -915,42 +853,89 @@ 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, - long requested, int id, String sourceExt, String targetExt, String msg) + public void debugTransformServiceResponse(long requested, int id, String msg, Collection debugLines) + { + 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 debugLines) { - pushMisc(); - Frame frame = ThreadInfo.getStack().getLast(); - frame.id = id; boolean suppressFinish = id == -1 || requested == -1; - if (!suppressFinish) + if (isEnabled()) { - frame.start = requested; + pushMisc(); + Frame frame = ThreadInfo.getStack().getLast(); + frame.id = id; + if (!suppressFinish) + { + frame.start = requested; + } + debug(msg); + 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); } - debug(msg); - debug(sourceNodeRef.toString() + ' ' +contentHashcode); - pop(Call.AVAILABLE, suppressFinish, true); } /** diff --git a/repository/src/test/java/org/alfresco/AllUnitTestsSuite.java b/repository/src/test/java/org/alfresco/AllUnitTestsSuite.java index 168e763b88..3392456a8a 100644 --- a/repository/src/test/java/org/alfresco/AllUnitTestsSuite.java +++ b/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, diff --git a/repository/src/test/java/org/alfresco/repo/content/transform/TransformerDebugTest.java b/repository/src/test/java/org/alfresco/repo/content/transform/TransformerDebugTest.java new file mode 100644 index 0000000000..b15bb24f5a --- /dev/null +++ b/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 . + * #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 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 singleLineLogLevel = new AtomicReference<>(); + private AtomicReference multiLineLogLevel = new AtomicReference<>(); + private Map 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; + + public DummyLog(StringBuilder stringBuilder, AtomicReference 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()); + } + } + } +} \ No newline at end of file