feat(log): allow to pass in custom loggers

.github/workflows/node.js.yml

@@ -1,6 +1,3 @@
-# This workflow will do a clean install of node dependencies, build the source code and run tests across different versions of node
-# For more information see: https://help.github.com/actions/language-and-framework-guides/using-nodejs-with-github-actions
-
 name: Test and Release
 
 on: [push, pull_request]
@@ -19,7 +16,7 @@ jobs:
           - exist-version: latest
             experimental: true
     services:
-      exist:
+      existdb:
         image: existdb/existdb:${{ matrix.exist-version }}
         ports:
           - 8443:8443
@@ -37,6 +34,8 @@ jobs:
       - name: Install dependencies
         run: npm ci
       - name: Run tests
+        env:
+          EXISTDB_CONTAINER_NAME: ${{ job.services.existdb.id }}
         run: npm test
   release:
     name: Release

README.md

@@ -189,6 +189,35 @@ declare function custom-router:use-beep-boop ($request as map(*), $response as m
 Roaster transparently handles data from multipart/form-data requests to keep route handlers short and readable.
 Please see the [file upload documentation](doc/file-upload.md) for more details on this.
 
+## Logging
+
+Roaster allows to pass in a fourth parameter to `roaster:route#4`.
+It defaults to using util:log as before.
+
+All route handlers will receive a reference to that logging function.
+
+```xquery
+declare function my:log($level as xs:string, $data as item()*) as empty-sequence() {
+    util:log-system-out(
+        upper-case($level) || " " || 
+        serialize($data, map{ "method": "adaptive" }))
+};
+```
+
+A custom logging function must expect two parameters:
+
+- The $level with the possible values 'trace', 'debug', 'info', 'warn', and 'error'
+- $data is a sequence of items, you might want to serialize it to your needs
+
+```xquery
+roaster:route(
+    $my:api,
+    my:lookup#1,
+    $my:middlewares,
+    my:log#2
+)
+```
+
 ## Limitations
 
 The library does not support yet support following OpenAPI feature(s): 
@@ -267,7 +296,15 @@ This included the test application in `test/app`.
 
 To run the local test suite you need an instance of eXist running on `localhost:8080` and `npm` to be available in your path. To test against a different different server, or use a different user or password you can copy `.env.example` to `.env` and edit it to your needs.
 
-Run the test suite with
+There is a testsuite that will only work if you are running existdb in a docker container named "roater-test-db". This is also the name of the service started in CI.
+
+So a normal setup to test on your local machine is
+
+```sh
+docker run --name roaster-test-db -p 8443:8443 -p 8080:8080 existdb/existdb:6.4.0
+```
+
+And then run the test suite with
 
 ```shell
 npm test

content/body.xqm

@@ -130,7 +130,7 @@ declare function body:content-type ($request as map(*)) as map(*) {
             else error(
                 $errors:BODY_CONTENT_TYPE,
                 "Body with media-type '" || $media-type || "' is not allowed", 
-                $request
+                map:remove($request, 'logger')
             )
     )
 };

content/roaster.xqm

@@ -77,11 +77,24 @@ declare function roaster:resolve-pointer ($config as map(*), $ref as xs:string*)
  : 3. If two paths have the same (normalized) length, prioritize by appearance in API files, first one wins
  :)
 declare function roaster:route($api-files as xs:string+, $lookup as function(xs:string) as function(*)?) {
-    router:route($api-files, $lookup, auth:standard-authorization#2)
+    router:route($api-files, $lookup, auth:standard-authorization#2, util:log#2)
 };
 
-declare function roaster:route($api-files as xs:string+, $lookup as function(xs:string) as function(*)?, $middleware) {
-    router:route($api-files, $lookup, $middleware)
+declare function roaster:route(
+    $api-files as xs:string+,
+    $lookup as function(xs:string) as function(*)?,
+    $middleware as (function(map(*), map(*)) as map(*)+)*
+) {
+    router:route($api-files, $lookup, $middleware, util:log#2)
+};
+
+declare function roaster:route(
+    $api-files as xs:string+,
+    $lookup as function(xs:string) as function(*)?,
+    $middleware as (function(map(*), map(*)) as map(*)+)*,
+    $logger as function(xs:string, item()*) as empty-sequence()
+) {
+    router:route($api-files, $lookup, $middleware, $logger)
 };
 
 declare function roaster:accepted-content-types () as xs:string* {

content/router.xql

@@ -77,18 +77,24 @@ declare function router:resolve-pointer($config as map(*), $ref as xs:string*) {
  : 2. use the matching route with the longest normalized pattern
  : 3. If two paths have the same (normalized) length, prioritize by appearance in API files, first one wins
  :)
-declare function router:route ($api-files as xs:string+, $lookup as function(xs:string) as function(*)?, $middlewares as function(*)*) {
+declare function router:route (
+    $api-files as xs:string+,
+    $lookup as function(xs:string) as function(*)?,
+    $middlewares as (function(map(*), map(*)) as map(*)+)*,
+    $logger as function(xs:string, item()*) as empty-sequence()
+) {
     let $controller := request:get-attribute("$exist:controller")
     let $base-collection := ``[`{repo:get-root()}`/`{$controller}`/]``
 
     let $request-data := map { 
         "id": util:uuid(),
         "method": request:get-method() => lower-case(),
-        "path": request:get-attribute("$exist:path")
+        "path": request:get-attribute("$exist:path"),
+        "logger": $logger
     }
 
     return (
-        util:log("debug", ``[[`{$request-data?id}`] request `{$request-data?method}` `{$request-data?path}`]``),
+        $logger("debug", ``[[`{$request-data?id}`] request `{$request-data?method}` `{$request-data?path}`]``),
         try {
             (: load router definitions :)
             let $specs :=
@@ -116,7 +122,7 @@ declare function router:route ($api-files as xs:string+, $lookup as function(xs:
                     (: if there are multiple matches, prefer the one matching the longest pattern and the highest priority :)
                     let $matching-routes-with-specificity := for-each($matching-routes, router:add-specificity#1)
                     return (
-                        util:log("debug", map {
+                        $logger("debug", map {
                             "ambiguous route" : $request-data?path,
                             "method" : $request-data?method,
                             "matching definitions" : array { 
@@ -135,7 +141,7 @@ declare function router:route ($api-files as xs:string+, $lookup as function(xs:
                 )
 
             return
-                router:process-request($first-match, $lookup, $middlewares)
+                router:process-request($first-match, $lookup, $middlewares, $logger)
 
         } catch * {
             let $error :=
@@ -158,7 +164,7 @@ declare function router:route ($api-files as xs:string+, $lookup as function(xs:
                     errors:get-status-code-from-error($err:code)
 
             return
-                router:error($status-code, $error, $lookup)
+                router:error($status-code, $error, $lookup, $logger)
         }
     )
 };
@@ -222,7 +228,12 @@ declare %private function router:sort-by-specificity-and-priority ($route as map
     $route?priority (: sort ascending :)
 };
 
-declare %private function router:process-request ($pattern-map as map(*), $lookup as function(*), $custom-middlewares as function(*)*) {
+declare %private function router:process-request (
+    $pattern-map as map(*),
+    $lookup as function(*),
+    $custom-middlewares as function(*)*,
+    $logger as function(xs:string, item()*) as empty-sequence()
+) {
     let $route :=
         if (map:contains($pattern-map?config, $pattern-map?method)) then 
             $pattern-map?config?($pattern-map?method)
@@ -249,7 +260,7 @@ declare %private function router:process-request ($pattern-map as map(*), $looku
 
     return (
         router:write-response($status, $response, $route),
-        util:log("debug", ``[[`{$base-request?id}`] `{$base-request?method}` `{$base-request?path}`: `{$status}`]``)
+        $logger("debug", ``[[`{$base-request?id}`] `{$base-request?method}` `{$base-request?path}`: `{$status}`]``)
     )
 };
 
@@ -401,8 +412,13 @@ declare %private function router:error-description ($description as xs:string?,
  : OAS configuration for the route and "_response" is the response data provided by the user function
  : in the third argument of error().
  :)
-declare %private function router:error ($code as xs:integer, $error as map(*), $lookup as function(xs:string) as function(*)?) {
-    router:log-error($code, $error),
+declare %private function router:error (
+    $code as xs:integer,
+    $error as map(*),
+    $lookup as function(xs:string) as function(*)?,
+    $logger as function(xs:string, item()*) as empty-sequence()
+) {
+    router:log-error($code, $error, $logger),
     (: unwrap error data :)
     let $route := $error?_request?config
     let $error := $error?_error
@@ -433,7 +449,7 @@ declare %private function router:error ($code as xs:integer, $error as map(*), $
                         "line": $err:line-number, "column": $err:column-number
                     }
                 return (
-                    router:log-error(500, $_error),
+                    router:log-error(500, $_error, $logger),
                     router:default-error-handler(500, $_error)
                 )
             }
@@ -542,10 +558,14 @@ declare %private function router:is-rethrown-error($value as item()*) as xs:bool
     map:contains($value, "_error")
 };
 
-declare %private function router:log-error ($code as xs:integer, $data as map(*)) as empty-sequence() {
+declare %private function router:log-error (
+    $code as xs:integer,
+    $data as map(*),
+    $logger as function(xs:string, item()*) as empty-sequence()
+) as empty-sequence() {
     let $error := $data?_error => serialize(map{"method": "json"})
     return
-        util:log("error", 
+        $logger("error", 
             ``[[`{$data?_request?id}`] `{$data?_request?method}` `{$data?_request?path}`: `{$code}`
             `{$error}`]``)
 };

content/util.xql

@@ -46,5 +46,5 @@ declare function rutil:getDBUser() as map(*) {
  : to handler functions.
  :)
 declare function rutil:debug($request as map(*)) {
-    router:response(200, "application/json", $request, ())
+    router:response(200, "application/json", map:remove($request, 'logger'), ())
 };

test/app/modules/custom-router.xq

@@ -66,4 +66,33 @@ declare variable $custom-router:use := (
     custom-router:use-beep-boop#2
 );
 
-roaster:route($custom-router:definitions, custom-router:lookup#1, $custom-router:use)
+(:~
+ : Example of a custom logger that will output to standarad out and standard error depending on level
+ : This logger is also used for testing
+ :)
+declare function custom-router:log-std ($level as xs:string, $message as item()*) as empty-sequence() {
+    let $norm-level := upper-case($level)
+    let $serialized := serialize($message, map{"method": "adaptive"})
+    let $log-function :=
+        switch($norm-level)
+            case 'ERROR' return util:log-system-err#1
+            default return util:log-system-out#1
+
+    return $log-function(``[`{$norm-level}` `{$serialized}`]``)
+};
+
+(:~
+ : Example of a custom logger application logger.
+ : While this offers greater flexiblity, additional changes need to be made to the log4j configuration
+ : of the exist-db instance the application will be running on.
+ :)
+declare function custom-router:log-app ($level as xs:string, $message as item()*) as empty-sequence() {
+    util:log-app($level, "roasted.app.logger", $message)
+};
+
+roaster:route(
+    $custom-router:definitions,
+    custom-router:lookup#1,
+    $custom-router:use,
+    custom-router:log-std#2
+)

test/app/modules/jwt-auth.xqm

@@ -51,6 +51,7 @@ declare function jwt-auth:issue-token ($request as map(*)) {
         return
             if ($loggedin and $username = $user?name)
             then (
+                $request?logger('info', ``[[`{$request?id}`] New token issued for `{$username}`]``),
                 router:response(201, (), map {
                     "user": $user,
                     "token": $jwt-auth:jwt?create($user)

test/array.test.js

@@ -393,7 +393,7 @@ describe('sending more than one value for a non-array parameter', function () {
     })
 
     it('the error description starts with an actionable message', async function () {
-        console.log(message)
+        // console.log(message)
         expect(message.startsWith('Multiple values were provided for query-parameter "string", which is not declared an array')).to.be.true
     })
 })

test/custom.test.js

@@ -1,7 +1,14 @@
-const util = require('./util.js');
+const { promisify } = require('node:util');
+const child_process = require('node:child_process');
+const exec = promisify(child_process.exec);
+
 const chai = require('chai');
 const expect = chai.expect;
 
+const util = require('./util.js');
+
+const dockerTestInstanceName = process.env.EXISTDB_CONTAINER_NAME ?? 'roaster-test-db'
+
 describe('public route with custom middleware', function () {
     const pathParameter = '1/2/this/is/just/a/test'
     let publicRouteResult
@@ -192,3 +199,48 @@ describe("requesting a token as guest", function () {
 
     })
 });
+
+describe("when using a custom logger that outputs to stdout and stderr", function () {
+    let standardOut, standardError
+
+    function filterLogs (output, match) {
+        return output.split('\n')
+            .filter(l => l.startsWith(match))
+    }
+
+    before(async function () {
+        // request route that logs
+        await util.axios.post('jwt/token', util.adminCredentials)
+        // read docker logs
+        const { stdout, stderr } = await exec(`docker logs ${dockerTestInstanceName}`)
+        standardOut = stdout
+        standardError = stderr
+    })
+
+    it('stdout and stderr were read from docker', function () {
+        expect(standardOut).to.exist
+        expect(standardError).to.exist
+    })
+
+    describe("the custom logs", function () {
+        let customOut, customErr
+
+        before(async function () {
+            // filter docker logs
+            customOut = filterLogs(standardOut, '(Line: -1 /db/apps/roasted/modules/custom-router.xq)')
+            customErr = filterLogs(standardError, '(Line: -1 /db/apps/roasted/modules/custom-router.xq) ERROR ')
+        })
+
+
+        it('debug messages can be found in stdout', function () {
+            expect(customOut.length).greaterThan(0)
+        })
+        it('error messages can be found in stderr', function () {
+            expect(customErr.length).greaterThan(0)
+        })
+        it('has log messages emitted from a route handler', function () {
+            const adminTokenIssued = customOut.filter(l => l.endsWith('New token issued for admin"'))
+            expect(adminTokenIssued.length).to.be.greaterThan(0)
+        })
+    })
+})

test/mediatype.test.js

@@ -703,19 +703,21 @@ test.
 
 describe("with invalid content-type header", function () {
     let uploadResponse
-    before(function () {
-        return util.axios.post(
-            'api/paths/invalid.stuff',
-            'asd;lfkjdas;flkja',
-            {
-                headers: { 
-                    'Content-Type': 'my/thing',
-                    'Authorization': 'Basic YWRtaW46'
+    before(async function () {
+        try {
+            uploadResponse = await util.axios.post(
+                'api/paths/invalid.stuff',
+                'asd;lfkjdas;flkja',
+                {
+                    headers: {
+                        'Content-Type': 'my/thing',
+                        'Authorization': 'Basic YWRtaW46'
+                    }
                 }
-            }
-        )
-        .then(r => uploadResponse = r)
-        .catch(e => uploadResponse = e.response)
+            )
+        } catch (e) {
+            return uploadResponse = e.response
+        }
     })
     it("is rejected as Bad Request", function () {
         expect(uploadResponse.status).to.equal(400)