Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Dev debuglog #4

Open
wants to merge 7 commits into
base: master
Choose a base branch
from
Open

Dev debuglog #4

Show file tree
Hide file tree
Changes from 4 commits
Commits
Show all changes
7 commits
Select commit Hold shift + click to select a range
a684d26
make debug logging configurable
Jun 26, 2021
51f192e
removed unused dependency on console module
Jun 26, 2021
a22d87c
do not store/check SAML request ids when accepting unsolicited SAML a…
Jun 26, 2021
56eca4e
[doc] clarifications and debugging hints
Sep 7, 2021
0107b08
[improve] minor changes suggested by reviewers
Sep 8, 2021
89535a9
[ignore] add missing else clause
Sep 8, 2021
5f05b90
[improve] review and standardize log messages
Sep 9, 2021
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
36 changes: 33 additions & 3 deletions README.md
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -47,6 +47,21 @@ client to some SP resource, as in "give this authenticated user access to
resource /X". In the sports event analogy these are comparable to sponsored
VIP lounge tickets issued by the IDP, to bypass the SP crowd.

## What is Supposed to Happen? (the functional view)

* Some client request comes in and gets handed off to controller.xql
* controller.xql logic notices SAML is enabled and client has no SAML token
* controller.xql redirects user browser to remote SAML IDP for authentication
* Remote SAML IDP presents authentication dialog, authenticates the user, and
returns an authentication assertion to the eXist SP on endpoint `/SAML2SP`
* controller.xql handles SAML assertion on endpoint `/SAML2SP` and checks SAML
authentication result. If auth successful, insert SAML token into user
browser and redirect user browser to the place she intended to go (before
getting SAML intercepted). This is SAML "relaystate", arbitrary data,
typically a URI.
* on next request, client will bypass SAML interception because it has a SAML
token (this token means "I have successfully authenticated").

## How to use (in technical terms)

Existdb-saml is an application library that can be added through the eXist
Expand Down Expand Up @@ -161,13 +176,13 @@ then (
(: handle SP endpoint to process SAML response in HTTP POST :)
else if($exist:path = "/SAML2SP")
then (
let $log := util:log('info', "SAML2SP: processing SAML response")
let $log := exsaml:log('info', "SAML2SP: processing SAML response")
let $status := exsaml:process-saml-response-post()
let $log := util:log('debug', "endpoint SAML2SP; status: " || $status/@code)
let $log := exsaml:log('info', "endpoint SAML2SP; status: " || $status/@code)
return
if ($status/@code >= 0) then
(: forward to page that was requested by the user :)
let $debug := util:log("info", "Auth success - code " || $status/@code || " - relaystate: " || $status/@relaystate)
let $debug := exsaml:log("info", "Auth success - code " || $status/@code || " - relaystate: " || $status/@relaystate)
return
<dispatch xmlns="http://exist.sourceforge.net/NS/exist">
<redirect url="{$status/@relaystate}"/>
Expand All @@ -182,6 +197,21 @@ else (
)
```

## Debugging

This module logs to the main eXist logfile `$EXIST_HOME/logs/exist.log`.

The very first debugging operation is looking for exceptions and Java stack
traces in the main eXist logfile. These often indicate a serious issue that
may lead to followup errors.

All logging uses an `exsaml:log()` wrapper function, so it is possible to
"grep" for SAML messages in the exist logfile from the shell like this:

```sh
grep exsaml: $EXIST_HOME/logs/exist.log | less
```

## Misc

### Security
Expand Down
5 changes: 3 additions & 2 deletions content/config-exsaml.xml
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,5 +1,6 @@
<!-- To disable SAML authentication, set @enabled="false" -->
<config enabled="false">
<!-- To enable SAML authentication, set @enabled="true" -->
<!-- To enable debugging, set @debug="true" -->
<config enabled="false" debug="false">

<!-- In SAML terminology, the eXist DB is the "service provider" (SP)
which uses a remote "identity provider" (IDP, eg PingFederate) to
Expand Down
113 changes: 64 additions & 49 deletions content/exsaml.xqm
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -13,9 +13,6 @@ declare namespace xsi="http://www.w3.org/2001/XMLSchema-instance";
import module namespace compression="http://exist-db.org/xquery/compression";
import module namespace crypto="http://expath.org/ns/crypto";

(: other modules :)
(:import module namespace console="http://exist-db.org/xquery/console";:)

declare variable $exsaml:version := doc("../expath-pkg.xml")/*:package/@version/string();

(: pull config from config-exsaml.xml :)
Expand All @@ -28,7 +25,7 @@ declare %private variable $exsaml:sp-fallback-rs := data($exsaml:config/sp/@fall
declare %private variable $exsaml:idp-ent := data($exsaml:config/idp/@entity);
declare %private variable $exsaml:idp-uri := data($exsaml:config/idp/@endpoint);
declare %private variable $exsaml:idp-certfile := data($exsaml:config/idp/@certfile);
declare %private variable $exsaml:idp-unsolicited := data($exsaml:config/idp/@accept-unsolicited);
declare %private variable $exsaml:idp-unsolicited := if (data($exsaml:config/idp/@accept-unsolicited) = "true") then ( true() ) else ( false() );
chakl marked this conversation as resolved.
Show resolved Hide resolved
declare %private variable $exsaml:idp-force-rs := data($exsaml:config/idp/@force-relaystate);
declare %private variable $exsaml:idp-verify-issuer := data($exsaml:config/idp/@verify-issuer);

Expand All @@ -51,13 +48,24 @@ declare %private variable $exsaml:fake-user := data($exsaml:config/fake-idp/@u
declare %private variable $exsaml:fake-group := data($exsaml:config/fake-idp/@group);

(: SAML specific constants and non-configurable vars :)
declare %private variable $exsaml:saml-coll-reqid := "/db/apps/existdb-saml/saml-request-ids";
declare %private variable $exsaml:saml-coll-reqid-name := "saml-request-ids";
declare %private variable $exsaml:saml-coll-reqid-base := "/db/apps/existdb-saml";
declare %private variable $exsaml:saml-version := "2.0";
declare %private variable $exsaml:status-success := "urn:oasis:names:tc:SAML:2.0:status:Success";
(: debugging only to simulate failure in fake-idp :)
declare %private variable $exsaml:status-badauth := "urn:oasis:names:tc:SAML:2.0:status:AuthnFailed";
declare variable $exsaml:ERROR := xs:QName("saml:error");

(:~
: this sets the log level for debug log statements, depending on the top-level
: "debug" attribute
: * if debug="false" (default) the value is "debug". This means the log
: msg gets logged at "debug" level and is usually NOT shown in the logs.
: * if debug="true" the value is "info". This means the log msg gets logged
: at "info" level and IS usually shown in the logs.
:)
declare variable $exsaml:logdebug := if (data($exsaml:config/@debug) = "true")
then ( "info" ) else ( "debug" );

(: may be used to check if SAML is enabled at all :)
declare function exsaml:is-enabled() {
Expand Down Expand Up @@ -90,19 +98,18 @@ declare function exsaml:info() {
declare function exsaml:build-authnreq-redir-url($relaystate as xs:string) {
let $log := exsaml:log("info", "building SAML auth request redir-url; relaystate: " || $relaystate)
let $req := exsaml:build-saml-authnreq()
let $log := exsaml:log("debug", "build-authnreq-redir-url; req: " || $req)
let $log := exsaml:log($exsaml:logdebug, "build-authnreq-redir-url; req: " || $req)

(: deflate and base64 encode request :)
let $ser := fn:serialize($req)
(: let $log := exsaml:log("debug", "build-authnreq-redir-url; ser: " || $ser):)
let $log := exsaml:log($exsaml:logdebug, "build-authnreq-redir-url; ser: " || $ser)
let $bin := util:string-to-binary($ser)
(: let $log := exsaml:log("debug", "build-authnreq-redir-url; bin: " || $bin):)
let $log := exsaml:log($exsaml:logdebug, "build-authnreq-redir-url; bin: " || $bin)
let $zip := compression:deflate($bin, true())
(: let $log := exsaml:log("debug", "build-authnreq-redir-url; zip: " || $zip):)
let $log := exsaml:log($exsaml:logdebug, "build-authnreq-redir-url; zip: " || $zip)
(: urlencode base64 request data :)
let $urlenc := xmldb:encode($zip)

let $log := exsaml:log("debug", "build-authnreq-redir-url; urlenc: " || $urlenc)
let $log := exsaml:log($exsaml:logdebug, "build-authnreq-redir-url; urlenc: " || $urlenc)

return $exsaml:idp-uri || "?SAMLRequest=" || $urlenc || "&amp;RelayState=" || xmldb:encode($relaystate)
};
Expand All @@ -123,30 +130,34 @@ declare %private function exsaml:build-saml-authnreq() {
};

declare %private function exsaml:store-authnreqid-as-exsol-user($id as xs:string, $instant as xs:string) {
let $saml-coll-reqid := $exsaml:saml-coll-reqid-base || "/" || $exsaml:saml-coll-reqid-name
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Since this value is rather static I would argue it is better to have it built once as declared variable of the module.

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

That would mean

declare %private variable $exsaml:saml-coll-reqid-base := "/db/apps/existdb-saml";
declare %private variable $exsaml:saml-coll-reqid := $exsaml:saml-coll-reqid-base || "/" || "saml-request-ids";

and that looks dirty to me.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I was thinking more like:

declare %private variable $exsaml:saml-coll-reqid-base := "/db/apps/existdb-saml";
declare %private variable $exsaml:saml-coll-reqid-name := "saml-request-ids";
declare %private variable $exsaml:saml-coll-reqid := $exsaml:saml-coll-reqid-base || "/" || $exsaml:saml-coll-reqid-name;

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I was arguing that declareing a variable value derived from a previously declared variable might be wrong. Does the Xquery standard specify that declarations get processed sequentially? Don't think so, but I may be wrong.

let $create-collection :=
if (
not(xmldb:collection-available($exsaml:saml-coll-reqid))
not(xmldb:collection-available($saml-coll-reqid))
chakl marked this conversation as resolved.
Show resolved Hide resolved
)
then (
let $log := exsaml:log("info", "collection " || $exsaml:saml-coll-reqid || " does not exist, attempting to create it")
let $log := exsaml:log("info", "collection " || $saml-coll-reqid || " does not exist, attempting to create it")
return
xmldb:create-collection("/db/apps/existdb-saml", "saml-request-ids")
xmldb:create-collection($exsaml:saml-coll-reqid-base, $exsaml:saml-coll-reqid-name)
)
else ()
return
xmldb:store($exsaml:saml-coll-reqid, $id, <reqid>{$instant}</reqid>)
xmldb:store($saml-coll-reqid, $id, <reqid>{$instant}</reqid>)

};

(: store issued request ids in a collection, :)
(: store issued request ids in a collection :)
(: this is pointless if we are configured to accept unsolicited SAML assertions :)
declare %private function exsaml:store-authnreqid($id as xs:string, $instant as xs:string) {
let $log := exsaml:log("info", "storing SAML request id: " || $id || ", date: " || $instant)
return
system:as-user(
if (not($exsaml:idp-unsolicited)) then (
chakl marked this conversation as resolved.
Show resolved Hide resolved
let $log := exsaml:log("info", "storing SAML request id: " || $id || ", date: " || $instant)
chakl marked this conversation as resolved.
Show resolved Hide resolved
return
system:as-user(
$exsaml:exsaml-user,
$exsaml:exsaml-pass,
exsaml:store-authnreqid-as-exsol-user($id, $instant)
)
)
)
};

(: ==== FUNCTIONS TO PROCESS AND VALIDATE A SAML AUTHN RESPONSE ==== :)
Expand All @@ -170,9 +181,9 @@ declare function exsaml:process-saml-response-post() {
fn:parse-xml-fragment($decode-resp)
)

let $debug := exsaml:log("debug", "START SAML RESPONSE ")
let $debug := exsaml:log("debug", $resp)
let $debug := exsaml:log("debug", "END SAML RESPONSE ")
let $debug := exsaml:log($exsaml:logdebug, "START SAML RESPONSE ")
let $debug := exsaml:log($exsaml:logdebug, $resp)
let $debug := exsaml:log($exsaml:logdebug, "END SAML RESPONSE ")

return
if($resp = "error")
Expand All @@ -192,17 +203,17 @@ declare function exsaml:process-saml-response-post() {
let $rsout :=
(: if we accept IDP-initiated SAML *and* use a forced landing page :)
if ($exsaml:idp-unsolicited and $exsaml:idp-force-rs != "") then (
let $debug := exsaml:log("debug", "evaluated to: $exsaml:idp-unsolicited and $exsaml:idp-force-rs != ''")
let $debug := exsaml:log("debug", "$exsaml:idp-force-rs is: " || $exsaml:idp-force-rs || " evaluated: " || string-length($exsaml:idp-force-rs) )
let $debug := exsaml:log($exsaml:logdebug, "evaluated to: $exsaml:idp-unsolicited and $exsaml:idp-force-rs != ''")
let $debug := exsaml:log($exsaml:logdebug, "$exsaml:idp-force-rs is: " || $exsaml:idp-force-rs || " evaluated: " || string-length($exsaml:idp-force-rs) )
return
$exsaml:idp-force-rs
)
(: otherwise accept relaystate from the SAML response :)
else if ($rsin != "") then (
let $debug := exsaml:log("info", "Relay State as provided by SSO: " || $rsin)
let $debug := exsaml:log($exsaml:logdebug, "Relay State as provided by SSO: " || $rsin)
return $rsin
) else (
let $debug := exsaml:log("info", "no Relay State provided by SSO, switching to SP fallback relaystate: " || $exsaml:sp-fallback-rs)
let $debug := exsaml:log($exsaml:logdebug, "no Relay State provided by SSO, switching to SP fallback relaystate: " || $exsaml:sp-fallback-rs)
return
$exsaml:sp-fallback-rs
)
Expand Down Expand Up @@ -237,8 +248,8 @@ declare function exsaml:process-saml-response-post() {
exsaml:set-saml-token($auth/@nameid, $auth/@authndate)
else ()

let $debug := exsaml:log("info", "finished exsaml:process-saml-response-post. auth: ")
let $debug := exsaml:log("info", fn:serialize($auth))
let $debug := exsaml:log($exsaml:logdebug, "finished exsaml:process-saml-response-post. auth: ")
let $debug := exsaml:log($exsaml:logdebug, fn:serialize($auth))
return $auth
)
} catch * {
Expand Down Expand Up @@ -367,18 +378,23 @@ declare %private function exsaml:validate-saml-assertion($assertion as item()) {
};

(: retrieve issued SAML request id and delete if answered :)
(: this is pointless if we are configured to accept unsolicited SAML assertions :)
declare %private function exsaml:check-authnreqid($reqid as xs:string) {
let $log := exsaml:log("info", "verifying SAML request id: " || $reqid)
return
if (system:as-user($exsaml:exsaml-user, $exsaml:exsaml-pass,
exists(doc($exsaml:saml-coll-reqid||"/"||$reqid)) and empty(xmldb:remove($exsaml:saml-coll-reqid, $reqid)))) then
$reqid
else ""
if (not($exsaml:idp-unsolicited)) then (
chakl marked this conversation as resolved.
Show resolved Hide resolved
let $log := exsaml:log("info", "verifying SAML request id: " || $reqid)
let $saml-coll-reqid := $exsaml:saml-coll-reqid-base || "/" || $exsaml:saml-coll-reqid-name
return
if (system:as-user($exsaml:exsaml-user,
$exsaml:exsaml-pass,
exists(doc($saml-coll-reqid||"/"||$reqid))
and empty(xmldb:remove($saml-coll-reqid, $reqid))))
chakl marked this conversation as resolved.
Show resolved Hide resolved
then ( $reqid ) else ( "" )
) else ( $reqid )
};

(: verify XML signature of a SAML response :)
declare %private function exsaml:verify-response-signature($resp as item()) {
let $log := exsaml:log("debug", "verify-response-signature: " || $resp)
let $log := exsaml:log($exsaml:logdebug, "verify-response-signature: " || $resp)
let $res :=
(: if $idp-certfile is configured, use that to validate XML signature :)
if ($exsaml:idp-certfile != "") then (
Expand All @@ -394,7 +410,7 @@ declare %private function exsaml:verify-response-signature($resp as item()) {

(: verify XML signature of a SAML assertion :)
declare %private function exsaml:verify-assertion-signature($assertion as item()) {
let $log := exsaml:log("debug", "verify-assertion-signature " || $assertion)
let $log := exsaml:log($exsaml:logdebug, "verify-assertion-signature " || $assertion)
let $res :=
(: if $idp-certfile is configured, use that to validate XML signature :)
if ($exsaml:idp-certfile != "") then (
Expand All @@ -412,11 +428,11 @@ declare %private function exsaml:verify-assertion-signature($assertion as item()
used to get group membership of an authenticated user, which gets passed
as SAML attribute assertions by the IDP :)
declare %private function exsaml:fetch-saml-attribute-values($attrname as xs:string, $as as node()) {
let $log := exsaml:log("debug", "fetch-saml-attribute " || $attrname || ", " || fn:serialize($as))
let $log := exsaml:log($exsaml:logdebug, "fetch-saml-attribute " || $attrname || ", " || fn:serialize($as))
let $seq :=
for $a in $as/saml:AttributeStatement/saml:Attribute[@Name=$attrname]/saml:AttributeValue
return $a/text()
let $log := exsaml:log("debug", "fetch-saml-attribute: " || fn:serialize($seq))
let $log := exsaml:log($exsaml:logdebug, "fetch-saml-attribute: " || fn:serialize($seq))
return $seq
};

Expand Down Expand Up @@ -454,7 +470,7 @@ declare %private function exsaml:create-user-password($nameid as xs:string) {
:)
declare function exsaml:check-valid-saml-token() {
let $raw := session:get-attribute($exsaml:token-name)
let $log := exsaml:log("debug", "checking saml token, name: " || $exsaml:token-name || ", value: " || $raw)
let $log := exsaml:log($exsaml:logdebug, "checking saml token, name: " || $exsaml:token-name || ", value: " || $raw)

let $tokdata := fn:tokenize($raw, $exsaml:token-separator)
return
Expand Down Expand Up @@ -487,7 +503,7 @@ declare function exsaml:invalidate-saml-token() {

(: return the HMAC of the string token passed in :)
declare %private function exsaml:hmac-tokval($tokval as xs:string) as xs:string {
let $log := exsaml:log("debug", "hmac-tokval; t: " || $tokval || ", key: " || $exsaml:hmac-key)
let $log := exsaml:log($exsaml:logdebug, "hmac-tokval; t: " || $tokval || ", key: " || $exsaml:hmac-key)
let $key := $exsaml:hmac-key || ""
let $alg := $exsaml:hmac-alg || ""

Expand All @@ -496,7 +512,7 @@ declare %private function exsaml:hmac-tokval($tokval as xs:string) as xs:string

(: build string token: join nameid and validto by $exsaml:token-separator :)
declare %private function exsaml:build-string-token($nameid as xs:string, $validto as xs:string) as xs:string {
let $log := exsaml:log("debug", "build-string-token; n: " || $nameid || ", v: " || $validto)
let $log := exsaml:log($exsaml:logdebug, "build-string-token; n: " || $nameid || ", v: " || $validto)
return $nameid || $exsaml:token-separator || $validto
};

Expand All @@ -515,15 +531,15 @@ declare %private function exsaml:set-saml-token($nameid as xs:string, $authndate

(: process SAML AuthnRequest, return SAML Response via POST :)
declare function exsaml:process-saml-request() {
let $log := exsaml:log("debug", "process-saml-request")
let $log := exsaml:log($exsaml:logdebug, "process-saml-request")
let $raw := request:get-parameter("SAMLRequest", "")
let $log := exsaml:log("debug", "process-saml-request; raw: " || $raw)
let $log := exsaml:log($exsaml:logdebug, "process-saml-request; raw: " || $raw)
let $uncomp := compression:inflate($raw, true())
let $log := exsaml:log("debug", "process-saml-request; uncomp: " || $uncomp)
let $log := exsaml:log($exsaml:logdebug, "process-saml-request; uncomp: " || $uncomp)
let $strg := util:base64-decode($uncomp)
let $log := exsaml:log("debug", "process-saml-request; strg: " || $strg)
let $log := exsaml:log($exsaml:logdebug, "process-saml-request; strg: " || $strg)
let $req := fn:parse-xml-fragment($strg)
let $log := exsaml:log("debug", "process-saml-request; req: " || $req)
let $log := exsaml:log($exsaml:logdebug, "process-saml-request; req: " || $req)
let $rs := request:get-parameter("RelayState", false())

let $resp := exsaml:fake-idp-response($req, $rs)
Expand All @@ -532,7 +548,7 @@ declare function exsaml:process-saml-request() {

(: fake SAML IDP response: build response and return via XHTML autosubmit form :)
declare %private function exsaml:fake-idp-response($req as node(), $rs as xs:string) {
let $log := exsaml:log("debug", "fake-idp-response")
let $log := exsaml:log($exsaml:logdebug, "fake-idp-response")
let $resp := exsaml:build-saml-fakeresp($req)
let $b64resp := util:base64-encode(fn:serialize($resp))

Expand Down Expand Up @@ -631,7 +647,6 @@ declare %private function exsaml:gen-id() {

(: generic log function, returns true for easy use in if constructs :)
declare function exsaml:log($level as xs:string, $msg as xs:string) {
(: let $l := console:log("exsaml: " || $msg):)
let $l := util:log($level, "exsaml: " || $msg)
return true()
};