feat(log): allow to pass in custom loggers

[line-o]

Add new function signature roaster:route#4 allowing to pass in a custom log function.
This allows for control what is logged where and how.

Log to stdout and stderr

declare function custom-router:log-std ($level as xs:string, $message as item()*) as empty-sequence() {
    switch(lower-case($level))
    case 'error' return util:log-system-err($message)
    default return util:log-system-out($message)
};
roaster:route($custom-router:definitions, custom-router:lookup#1, $custom-router:use, custom-router:log-std#2)

Log using util:log-app

declare function custom-router:log-app ($level as xs:string, $message as item()*) as empty-sequence() {
    util:log-app($level, "custom.log", $message)
};
roaster:route($custom-router:definitions, custom-router:lookup#1, $custom-router:use, custom-router:log-app#2)

For the above to work the logger needs to be added to log4j2.xml

<Logger name="custom.log" additivity="false" level="debug">
    <AppenderRef ref="exist.core"/><!-- or choose a different appender that you added -->
</Logger>

update

The request map now has a logger property that is a reference to the function that roaster uses to log its messages.
This allows any route handler to also log to that output.

declare function my:route ($request) {
    $request?log('info', 'my:route was called.'),
    "Hello World!"
};

That does also apply to middlewares

declare function my:middleware ($request, $response) {
    $request?log('info', 'my:middleware was called.'),
    $request,
    $response
};

[duncdrum]

Code looks good, and function is useful. I'm kind of missing an assertion in the testsuite that actually ensures that the custom logger is used, and the default logger is not.

[line-o]

@duncdrum Do you have an idea how to test this properly?

[duncdrum]

Not sure i understand your question, create a test log entry, and make sure that it only appears in the custom.log. Take a message that appears in exist.log by default, put it into custom.log and then check that the message is no longer present in exist.log ?

[line-o]

@duncdrum That's what I was looking for :) How does one access the logs of the docker container within GitHub-actions?

[duncdrum]

docker log ... for exist.log
docker cp ... for custom.log

[line-o]

What is the default log-level within exist-db stock images?

[duncdrum]

WARN i think, its in the config file in the core repo

[line-o]

It's safe to assume INFO, I guess. This would limit testability to errors at the moment.
If we would really venture into testing the custom log capability we need to alter the log4j configuration within the container. Can you point me to an example - or documentation - how to do that?

[duncdrum]

https://github.com/eXist-db/exist/blob/develop/exist-docker/src/main/xslt/log4j2-docker.xslt
https://github.com/duncdrum/distroless-exist/blob/main/.github/workflows/ci-java8.yml#L56
https://github.com/duncdrum/distroless-exist/blob/main/Dockerfile#L48

any of these will do, just copy the log4j file into the image

[line-o]

I think for now it would make sense to just test that certain messages are logged to exist.log and others are not.
Or can we access stdout and stderr?

[duncdrum]

Or can we access stdout and stderr

We can but testing the presence of certain messages in exist.log is the more important bit.

[line-o]

Yes, testing that log output is written to exist.log by default needs to be added. But for that the log4j configuration does not need to be altered.
If we have access to stdout and stderr and can make sure that the custom router logs are found there we would test both cases and would not have to go through the extra steps.

[line-o]

Aha, in the docker log configuration all messages with level INFO are directed to stdout
https://github.com/eXist-db/exist/blob/3ece92c5a1006ace8f9713d378e7393d18471043/exist-docker/src/main/xslt/log4j2-docker.xslt#L33
TIL

[line-o]

From my manual testing I could see that the message format is predictably different, though.
Would that suffice, @duncdrum ?

[duncdrum]

show me the message format preferably in code, and i ll tell you

[line-o]

I'll give you an example: When passing custom-router:log-std#2 to roaster:route will result in a call like

$logger("info", "[f6ad7ba0-8722-431f-ad7b-a08722e31f59] request get /jwt/public/1/2/this/is/just/a/test")

This yields following output to stdout

(Line: 72 /db/apps/roasted/modules/custom-router.xq) [f6ad7ba0-8722-431f-ad7b-a08722e31f59] request get /jwt/public/1/2/this/is/just/a/test

Each line will always start with (Line: 72 /db/apps/roasted/modules/custom-router.xq).
Output from the default logger (util:log#2) with the same message and level on the other hand

2023-02-06 12:30:36,743 [qtp77738832-38] INFO  (LogFunction.java [writeLog]:205) - (Line: -1 $EXIST_HOME/etc/../data/expathrepo/roaster-1.8.0/content/roaster.xqm) [f6ad7ba0-8722-431f-ad7b-a08722e31f59] request get /jwt/public/1/2/this/is/just/a/test

[duncdrum]

Looks like good testcase. Although users might actually more care about actual log files on disc.

As long as there are some tests I m happy. Whichever you are more comfortable with.

[line-o]

The whole logging facility has 0 coverage at the moment. Testing docker stdout will bring us a big leap forward.