[bugfix] Log xsl:message output from fn:transform() to Elemental's log

Closes #234

Author: Laurettta

exist-core/src/main/java/org/exist/xquery/functions/fn/transform/Transform.java

@@ -53,6 +53,9 @@
 import net.sf.saxon.s9api.*;
 import net.sf.saxon.serialize.SerializationProperties;
 import net.sf.saxon.trans.UncheckedXPathException;
+
+import java.io.IOException;
+import java.io.StringWriter;
 import org.apache.logging.log4j.LogManager;
 import org.apache.logging.log4j.Logger;
 import org.exist.dom.QName;
@@ -67,8 +70,10 @@
 import org.w3c.dom.Node;
 
 import javax.annotation.Nonnull;
+import javax.annotation.Nullable;
 import javax.xml.transform.ErrorListener;
 import javax.xml.transform.Source;
+import javax.xml.transform.SourceLocator;
 import javax.xml.transform.TransformerException;
 import javax.xml.transform.dom.DOMSource;
 import java.net.URI;
@@ -79,6 +84,7 @@
 
 import static com.evolvedbinary.j8fu.tuple.Tuple.Tuple;
 import static org.exist.util.StringUtil.isNullOrEmpty;
+import static org.exist.util.StringUtil.notNullOrEmpty;
 import static org.exist.xquery.functions.fn.transform.Options.Option.*;
 
 /**
@@ -104,7 +110,7 @@
  */
 public class Transform {
 
-    private static final Logger LOGGER =  LogManager.getLogger(org.exist.xquery.functions.fn.transform.Transform.class);
+    private static Logger LOGGER =  LogManager.getLogger(org.exist.xquery.functions.fn.transform.Transform.class);
     private static final org.exist.xquery.functions.fn.transform.Transform.ErrorListenerLog4jAdapter ERROR_LISTENER = new Transform.ErrorListenerLog4jAdapter(Transform.LOGGER);
 
     final Convert.ToSaxon toSaxon = new Convert.ToSaxon() {
@@ -161,6 +167,7 @@ public Sequence eval(final Sequence[] args, final Sequence contextSequence) thro
                 }
 
                 final Xslt30Transformer xslt30Transformer = xsltExecutable.load30();
+                xslt30Transformer.setMessageListener(new XsltMessageListener(context.getBroker().getBrokerPool().getSaxonProcessor(), getLogger()));
 
                 options.initialMode.ifPresent(qNameValue -> xslt30Transformer.setInitialMode(Convert.ToSaxon.of(qNameValue.getQName())));
                 xslt30Transformer.setInitialTemplateParameters(options.templateParams, false);
@@ -464,6 +471,19 @@ private static Optional<Source> getSourceNode(final Optional<NodeValue> sourceNo
         return sourceNode.map(NodeValue::getNode).map(node -> new DOMSource(node, baseURI.getStringValue()));
     }
 
+    /**
+     * Designed to be package-protected accessible so that we can observe logging in tests.
+     *
+     * @param logger the logger to use in testing.
+     */
+    static void setLogger(final Logger logger) {
+        LOGGER = logger;
+    }
+
+    private Logger getLogger() {
+        return LOGGER;
+    }
+
     private static class ErrorListenerLog4jAdapter implements ErrorListener {
         private final Logger logger;
 
@@ -532,4 +552,55 @@ public PendingException(String message, Throwable cause) {
             super(message, cause);
         }
     }
+
+    private static class XsltMessageListener implements MessageListener {
+
+        private final Processor processor;
+        private final Logger logger;
+
+        public XsltMessageListener(final Processor processor, final Logger logger) {
+            this.processor = processor;
+            this.logger = logger;
+        }
+
+        @Override
+        public void message(final XdmNode content, final boolean terminate, final SourceLocator locator) {
+
+            try (final StringWriter writer = new StringWriter()) {
+                final Serializer serializer = processor.newSerializer();
+                serializer.setOutputProperty(Serializer.Property.OMIT_XML_DECLARATION, "yes");
+                serializer.setOutputWriter(writer);
+                serializer.serializeNode(content);
+
+                @Nullable final String source;
+                final int sourceLine;
+                final int sourceColumn;
+                if (locator != null) {
+                    source = locator.getSystemId();
+                    sourceLine = locator.getLineNumber();
+                    sourceColumn = locator.getColumnNumber();
+                } else {
+                    source = null;
+                    sourceLine = -1;
+                    sourceColumn = -1;
+                }
+
+                final StringBuilder tag = new StringBuilder("<xsl:message terminate=\"" + terminate + "\"");
+                if (notNullOrEmpty(source)) {
+                    tag.append(" source=\"").append(source).append("\"");
+                }
+                if (sourceLine != -1) {
+                    tag.append(" sourceLine=\"").append(sourceLine).append("\"");
+                    tag.append(" sourceColumn=\"").append(sourceColumn).append("\"");
+                }
+                tag.append(">");
+
+                logger.info("{}{}</xsl:message>", tag.toString(), writer.toString());
+            } catch (final SaxonApiException e) {
+                logger.error("Unable to serialize xsl:message content", e);
+            } catch (final IOException e) {
+                logger.error("Unable to close xsl:message writer", e);
+            }
+        }
+    }
 }

exist-core/src/test/java/org/exist/xquery/functions/fn/transform/FunTransformITTest.java

@@ -21,6 +21,8 @@
 package org.exist.xquery.functions.fn.transform;
 
 import com.evolvedbinary.j8fu.tuple.Tuple2;
+import org.apache.logging.log4j.Logger;
+import org.easymock.Capture;
 import org.exist.EXistException;
 import org.exist.collections.Collection;
 import org.exist.security.PermissionDeniedException;
@@ -49,9 +51,17 @@
 
 import javax.xml.transform.Source;
 import java.io.IOException;
+import java.util.ArrayList;
+import java.util.List;
 import java.util.Optional;
 
 import static com.evolvedbinary.j8fu.tuple.Tuple.Tuple;
+import static org.easymock.EasyMock.capture;
+import static org.easymock.EasyMock.createMock;
+import static org.easymock.EasyMock.expect;
+import static org.easymock.EasyMock.newCapture;
+import static org.easymock.EasyMock.replay;
+import static org.easymock.EasyMock.verify;
 import static org.junit.Assert.*;
 
 /**
@@ -247,6 +257,50 @@ public void identityMixedMemoryAndPersistentDom() throws XPathException, Permiss
         expectQuery(IDENTITY_MIXED_XSLT_QUERY_5, expected);
     }
 
+    @Test
+    public void xslMessageIsLogged() throws EXistException, PermissionDeniedException, IOException, XPathException {
+
+        // set a mock logger so we can capture the log output for our test
+        final Logger mockLogger = createMock(Logger.class);
+        Transform.setLogger(mockLogger);
+
+        // expectations
+        final Capture<String> formatPattern = newCapture();
+        final Capture<String> startTagCapture = newCapture();
+        final Capture<String> logMessageCapture = newCapture();
+        mockLogger.info(capture(formatPattern), capture(startTagCapture), capture(logMessageCapture));
+
+        // reset mock state before test
+        replay(mockLogger);
+
+        // execute test
+        final String query =
+            "fn:transform(map {\n" +
+            "  \"stylesheet-text\": '<xsl:stylesheet xmlns:xsl=\"http://www.w3.org/1999/XSL/Transform\" version=\"2.0\">\n" +
+            "    <xsl:template match=\"/\">\n" +
+            "      <xsl:message>Hello from XSLT</xsl:message>\n" +
+            "    </xsl:template>\n" +
+            "  </xsl:stylesheet>',\n" +
+            "  \"source-node\": document { <in/> }\n" +
+            "})?output";
+
+        final BrokerPool pool = existEmbeddedServer.getBrokerPool();
+        try (final DBBroker broker = pool.get(Optional.of(pool.getSecurityManager().getSystemSubject()));
+             final XQueryUtil.QueryResult queryResult = XQueryUtil.query(broker, new StringSource(query), false, null, null, null, null, null)) {
+            assertNotNull(queryResult.result);
+        }
+
+        // verify our expectations
+        verify(mockLogger);
+
+        // check our assertions about the log message
+        final String startTag = startTagCapture.getValue();
+        final String message = logMessageCapture.getValue();
+
+        assertEquals("<xsl:message terminate=\"false\" sourceLine=\"3\" sourceColumn=\"20\">", startTag);
+        assertEquals("Hello from XSLT", message);
+    }
+
     private static void expectQuery(final String query, final Source expected) throws EXistException, XPathException, PermissionDeniedException, IOException {
         final BrokerPool pool = existEmbeddedServer.getBrokerPool();
         try(final DBBroker broker = pool.get(Optional.of(pool.getSecurityManager().getSystemSubject()));