roaster icon indicating copy to clipboard operation
roaster copied to clipboard

feat(log): allow to pass in custom loggers

Open line-o opened this issue 3 years ago • 17 comments

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>

line-o avatar Feb 06 '23 11:02 line-o

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

line-o avatar Feb 07 '23 12:02 line-o

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 ?

duncdrum avatar Feb 07 '23 13:02 duncdrum

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

line-o avatar Feb 07 '23 13:02 line-o

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

duncdrum avatar Feb 07 '23 13:02 duncdrum

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

line-o avatar Feb 07 '23 13:02 line-o

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

duncdrum avatar Feb 07 '23 13:02 duncdrum

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?

line-o avatar Feb 07 '23 13:02 line-o

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

duncdrum avatar Feb 07 '23 13:02 duncdrum

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?

line-o avatar Feb 07 '23 13:02 line-o

Or can we access stdout and stderr

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

duncdrum avatar Feb 07 '23 13:02 duncdrum

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 avatar Feb 07 '23 13:02 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 avatar Feb 07 '23 13:02 line-o

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

line-o avatar Feb 07 '23 13:02 line-o

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

duncdrum avatar Feb 07 '23 13:02 duncdrum

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

line-o avatar Feb 07 '23 14:02 line-o

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.

duncdrum avatar Feb 07 '23 15:02 duncdrum

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

line-o avatar Feb 07 '23 15:02 line-o