diff --git a/.github/workflows/node.js.yml b/.github/workflows/node.js.yml index 3438442..e8df794 100644 --- a/.github/workflows/node.js.yml +++ b/.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 diff --git a/README.md b/README.md index c7d3656..2c79d9d 100644 --- a/README.md +++ b/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 diff --git a/content/body.xqm b/content/body.xqm index fe9fe31..41f247e 100644 --- a/content/body.xqm +++ b/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') ) ) }; diff --git a/content/roaster.xqm b/content/roaster.xqm index 6c082fc..1a6df93 100644 --- a/content/roaster.xqm +++ b/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* { diff --git a/content/router.xql b/content/router.xql index 63c971d..04f6d98 100644 --- a/content/router.xql +++ b/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}`]``) }; diff --git a/content/util.xql b/content/util.xql index 9f9a5f9..06e337e 100644 --- a/content/util.xql +++ b/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'), ()) }; diff --git a/test/app/modules/custom-router.xq b/test/app/modules/custom-router.xq index 029a663..c5215a7 100644 --- a/test/app/modules/custom-router.xq +++ b/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 +) diff --git a/test/app/modules/jwt-auth.xqm b/test/app/modules/jwt-auth.xqm index 7854337..2582be5 100644 --- a/test/app/modules/jwt-auth.xqm +++ b/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) diff --git a/test/array.test.js b/test/array.test.js index 6fcd28a..7b90e2b 100644 --- a/test/array.test.js +++ b/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 }) }) diff --git a/test/custom.test.js b/test/custom.test.js index 3d4befc..2049c7b 100644 --- a/test/custom.test.js +++ b/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) + }) + }) +}) diff --git a/test/mediatype.test.js b/test/mediatype.test.js index c706a67..41bf00d 100644 --- a/test/mediatype.test.js +++ b/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)