Logging with XQuery

Question

I'm using XQuery 3.0 to transform an incoming message to fit my system. The XQuery is called from an Apache Camel Route via the transform EIP.

Example:
transform().xquery("resource:classpath:xquery/myxquery.xquery",String.class)

While the transformation works without problems it would be nice, since it's partly very complex, to be able to log some informations directly during the transformation process.

So I wanted to ask if it is possible to log "into" logback directly from XQuery?

I already searched stackoverflow and of course https://www.w3.org/TR/xquery-30-use-cases/ and other sources, but I just couldn't find any information about how to log in Xquery.

My project structure is:

• Spring-Boot 2 application
• Apache-Camel as Routing framework
• Logback as Logging framework

Update: For the integration of XQuery in the Apache-Camel Framework I use the org.apache.camel:camel-saxon-starter:2.22.2.

Answer 1

Update: Because the use of fn:trace was kind of ugly I searched further and now I use the extension mechanism from Saxon to provide different logging functions which can be accessed via xquery:

For more information see the documentation: http://www.saxonica.com/documentation/#!extensibility/integratedfunctions/ext-full-J

Here is what I did for logging (tested with Saxon-HE, Camel is not mandatory, I just use it by coincidence):

First step:

Extend the class net.sf.saxon.lib.ExtensionFunctionDefinition

public class XQueryInfoLogFunctionDefinition extends ExtensionFunctionDefinition{

    private static final Logger log = LoggerFactory.getLogger(XQueryInfoLogFunctionDefinition.class);

    private final XQueryInfoExtensionFunctionCall functionCall = new XQueryInfoExtensionFunctionCall();

    private static final String PREFIX = "log";

    @Override
    public StructuredQName getFunctionQName() {
        return new StructuredQName(PREFIX, "http://thehandofnod.com/saxon-extension", "info");
    }

    @Override
    public SequenceType[] getArgumentTypes() {
        return new SequenceType[] { SequenceType.SINGLE_STRING };
    }

    @Override
    public SequenceType getResultType(SequenceType[] suppliedArgumentTypes) {
        return SequenceType.VOID;
    }

    @Override
    public ExtensionFunctionCall makeCallExpression() {
        return functionCall;
    }

}

Second step:

Implement the FunctionCall class

public class XQueryInfoExtensionFunctionCall extends ExtensionFunctionCall {

    private static final Logger log = LoggerFactory.getLogger(XQueryInfoLogFunctionDefinition.class);

    @Override
    public Sequence call(XPathContext context, Sequence[] arguments) throws XPathException {
        if (arguments != null && arguments.length > 0) {
            log.info(((StringValue) arguments[0]).getStringValue());
        } else
            throw new IllegalArgumentException("We need a message");
        return EmptySequence.getInstance();
    }
}

Third step:

Configure the SaxonConfiguration and bind it into the camel context:

    public static void main(String... args) throws Exception {
        Main main = new Main();

        Configuration saxonConfig = Configuration.newConfiguration(); 
        saxonConfig.registerExtensionFunction(new XQueryInfoLogFunctionDefinition());

        main.bind("saxonConfig", saxonConfig);
        main.addRouteBuilder(new MyRouteBuilder());
        main.run(args);
    }

Fourth step:

Define the SaxonConfig in your XQueryEndpoint: .to("xquery:test.xquery?configuration=#saxonConfig");

Fifth step:

Call it in your xquery:

declare namespace log="http://thehandofnod.com/saxon-extension";
log:info("Das ist ein INFO test")

Original post a.k.a How to overwrite the fn:trace Funktion:

Thanks to Martin Honnen I tried the fn:trace function. Problem was that by default it logs into the System.err Printstream and that's not what I wanted, because I wanted to combine the fn:trace function with the Logback Logging-Framework.

So I debugged the net.sf.saxon.functions.Trace methods and came to the following solution for my project setup.

1. Write a custom TraceListener which extends from net.sf.saxon.trace.XQueryTraceListener and implement the methods enter and leave in a way that the InstructionInfo with constructType == 2041 (for user-trace) is forwarded to the SLF4J-API. Example (for only logging the message):

@Override
    public void enter(InstructionInfo info, XPathContext context) {
        // no call to super to keep it simple.
        String nachricht = (String) info.getProperty("label");
        if (info.getConstructType() == 2041 && StringUtils.hasText(nachricht)) {
            getLogger().info(nachricht);
        }
    }

    @Override
    public void leave(InstructionInfo info) {
        // no call to super to keep it simple.
    }

2. set the custom trace listener into your net.sf.saxon.Configuration Bean via setTraceListener

3. Call your xquery file from camel via the XQueryEndpoint because only there it is possible to overwrite the Configuration with an option: .to("xquery:/xquery/myxquery.xquery?configuration=#saxonConf"). Unfortunately the transform().xquery(...) uses it's own objects without the possibility to configure them.

4. call {fn:trace($element/text(),"Das ist ein Tracing Test")} in your xquery and see the message in your log.