Logging improvements in the SAML daemon.

1 files changed, 377 insertions, 263 deletions

diff --git a/saml/saml.js b/saml/saml.js
index 43844f2..6a48af1 100644
--- a/saml/saml.js
+++ b/saml/saml.js
@@ -40,28 +40,44 @@ process.on('uncaughtException', function (error) {
 });
 
 // ================================================================================
-// Misc
+// SP and IdP definitions
 // ================================================================================
 
-var assertionConsumerServiceURL = 'https://codeq.si/Shibboleth.sso/SAML2/POST',
+// SP (that's us)
+//---------------
+    // our URL where the IdP responds with a login result
+var assertionConsumerServiceURL = 'https://codeq.si/Shibboleth.sso/SAML2/POST', // must be a POST
+    // our issuer ID
     SPIssuer = 'https://codeq.si/sp/201509281041',
+    // our encryption key for signing requests
     privateCert = fs.readFileSync('/etc/shibboleth/sp-key.pem', 'utf8'),
+    // the status value that signals a success of an operation (a SAML constant)
     SamlStatusSuccess = 'urn:oasis:names:tc:SAML:2.0:status:Success';
 
 // IdP: idp.aai.arnes.si
-var SSOServiceURL = 'https://idp.aai.arnes.si/simplesaml/saml2/idp/SSOService.php',
-    SLOServiceURL = 'https://idp.aai.arnes.si/simplesaml/saml2/idp/SingleLogoutService.php',
+//----------------------
+    // the IdP's single-sign-on page URL, where a user is redirected to perform his/her login
+var SSOServiceURL = 'https://idp.aai.arnes.si/simplesaml/saml2/idp/SSOService.php', // must be a GET
+    // the IdP's single-logout page URL, where a user is redirected to perform his/her (global) logout
+    SLOServiceURL = 'https://idp.aai.arnes.si/simplesaml/saml2/idp/SingleLogoutService.php', // must be a GET
+    // the IdP's issuer ID
     IdPIssuer = 'https://idp.aai.arnes.si/idp/20090116',
+    // the IdP's public certificate to verify signatures with
     IdPKeyInfoProvider = new xmlCrypto.FileKeyInfo('/etc/shibboleth/idp.crt');
 
 /*
 // IdP: idp.uni-lj.si
+//--------------------
 var SSOServiceURL = 'https://idp.uni-lj.si/simplesaml/saml2/idp/SSOService.php',
     SLOServiceURL = 'https://idp.uni-lj.si/simplesaml/saml2/idp/SingleLogoutService.php',
     IdPIssuer = 'https://idp.uni-lj.si/idp/20100525',
     IdPKeyInfoProvider = new xmlCrypto.FileKeyInfo('/etc/shibboleth/idp.uni-lj.si.crt');
  */
 
+// ================================================================================
+// Misc
+// ================================================================================
+
 var idChars = '0123456789abcdef',
     makeRequestId = function () {
         var idParts = [],
@@ -76,33 +92,39 @@ var waitingLogins = {}, // maps sid to waiter
     parkedLogoutRequests = {};
 
 var makeSamlRedirectUrl = function (serviceUrl, queryKey, queryObj, additionalData, callback) {
-    var xml = xmlbuilder.create(queryObj).end();
-    logger.debug('Redirecting with ' + queryKey + ' to ' + serviceUrl + ':\n' + xml);
-    zlib.deflateRaw(xml, function (err, buffer) {
-        var svcUrl, signer, query, keys, i, key;
-        if (err) {
-            callback(err, null);
-            return;
-        }
-        query = {
-            'SigAlg': 'http://www.w3.org/2000/09/xmldsig#rsa-sha1'
-        };
-        query[queryKey] = buffer.toString('base64');
-        if (additionalData && (typeof additionalData === 'object')) {
-            keys = Object.keys(additionalData);
-            for (i = keys.length - 1; i >= 0; i--) {
-                key = keys[i];
-                query[key] = additionalData[key];
+    var xml = null;
+    try {
+        xml = xmlbuilder.create(queryObj).end();
+        logger.debug('Redirecting with ' + queryKey + ' to ' + serviceUrl + ':\n' + xml);
+        zlib.deflateRaw(xml, function (err, buffer) {
+            var svcUrl, signer, query, keys, i, key;
+            if (err) {
+                callback(err, null, xml);
+                return;
             }
-        }
-        signer = crypto.createSign('RSA-SHA1');
-        signer.update(querystring.stringify(query));
-        query.Signature = signer.sign(privateCert, 'base64');
-        svcUrl = url.parse(serviceUrl);
-        svcUrl.query = query;
-        delete svcUrl.search;
-        callback(null, url.format(svcUrl));
-    });
+            query = {
+                'SigAlg': 'http://www.w3.org/2000/09/xmldsig#rsa-sha1'
+            };
+            query[queryKey] = buffer.toString('base64');
+            if (additionalData && (typeof additionalData === 'object')) {
+                keys = Object.keys(additionalData);
+                for (i = keys.length - 1; i >= 0; i--) {
+                    key = keys[i];
+                    query[key] = additionalData[key];
+                }
+            }
+            signer = crypto.createSign('RSA-SHA1');
+            signer.update(querystring.stringify(query));
+            query.Signature = signer.sign(privateCert, 'base64');
+            svcUrl = url.parse(serviceUrl);
+            svcUrl.query = query;
+            delete svcUrl.search;
+            callback(null, url.format(svcUrl), xml);
+        });
+    }
+    catch (e) {
+        callback(e, null, xml);
+    }
 };
 
 var makeWaiter = function (sid) {
@@ -268,58 +290,79 @@ var handleLogoutResponse = function (xml, form, res) {
         issuer = null,
         status = null,
         waiter = null,
-        doc, rootNode, attributes, i, inResponseTo, node;
-    doc = new xmldom.DOMParser().parseFromString(xml);
-    rootNode = doc.documentElement;
-    if (rootNode.localName != 'LogoutResponse') {
-        errors.push('not a LogoutResponse: ' + rootNode.localName);
-    }
-    else {
-        attributes = rootNode.attributes;
-        for (i = attributes.length - 1; i >= 0; i--) {
-            if (attributes[i].localName === 'InResponseTo') {
-                inResponseTo = attributes[i].value;
-                break;
-            }
+        responded = false, // don't respond if we already responded (and failed)
+        doc, rootNode, attributes, i, inResponseTo, node, m;
+    try {
+        doc = new xmldom.DOMParser().parseFromString(xml);
+        rootNode = doc.documentElement;
+        if (rootNode.localName != 'LogoutResponse') {
+            errors.push('not a LogoutResponse: ' + rootNode.localName);
         }
-        if (!inResponseTo) errors.push('request ID that this message is a response to is missing');
         else {
-            waiter = parkedLogoutRequests[inResponseTo];
-            if (!waiter) errors.push('there is no session waiting on request ID ' + inResponseTo);
+            attributes = rootNode.attributes;
+            for (i = attributes.length - 1; i >= 0; i--) {
+                if (attributes[i].localName === 'InResponseTo') {
+                    inResponseTo = attributes[i].value;
+                    break;
+                }
+            }
+            if (!inResponseTo) errors.push('request ID that this message is a response to is missing');
             else {
+                waiter = parkedLogoutRequests[inResponseTo];
+                if (!waiter) errors.push('there is no session waiting on request ID ' + inResponseTo);
+                else delete parkedLogoutRequests[inResponseTo];
+            }
+            node = rootNode.firstChild;
+            while (node) {
+                switch (node.localName) {
+                    case 'Issuer':
+                        issuer = node.firstChild.data;
+                        break;
+                    case 'Status':
+                        status = xmlStatusOk(node);
+                        break;
+                    default:
+//                    errors.push('Unknown/unsupported top XML node: ' + node.localName + ', prefix: ' + node.prefix);
+                        break;
+                }
+                node = node.nextSibling;
+            }
+            if (issuer === null) errors.push('Issuer is not set');
+            else if (issuer !== IdPIssuer) errors.push('Invalid IdP issuer: ' + issuer);
+            if (status === null) errors.push('response status is not set');
+            else if (!status) errors.push('response status is not OK');
+        }
+        if (errors.length > 0) {
+            if (waiter) {
                 waiter.done = Date.now();
-                delete parkedLogoutRequests[inResponseTo];
+                waiter.responseReject(new Error(errors.join(', ')));
             }
+            if (errors.length > 1) m = 'Multiple errors:\n' + errors.join('\n  ');
+            //logger.error(''); // TODO: continue here
+            else m = 'Error: ' + errors[0];
         }
-        node = rootNode.firstChild;
-        while (node) {
-            switch (node.localName) {
-                case 'Issuer':
-                    issuer = node.firstChild.data;
-                    break;
-                case 'Status':
-                    status = xmlStatusOk(node);
-                    break;
-                default:
-//                    errors.push('Unknown/unsupported top XML node: ' + node.localName + ', prefix: ' + node.prefix);
-                    break;
+        else {
+            if (waiter) {
+                waiter.done = Date.now();
+                waiter.responseResolve();
             }
-            node = node.nextSibling;
+            m = 'OK';
         }
-        if (issuer === null) errors.push('Issuer is not set');
-        else if (issuer !== IdPIssuer) errors.push('Invalid IdP issuer: ' + issuer);
-        if (status === null) errors.push('response status is not set');
-        else if (!status) errors.push('response status is not OK');
-    }
-    res.set('Content-Type', 'text/plain');
-    if (errors.length > 0) {
-        if (errors.length > 1) res.send('Multiple errors:\n  ' + errors.join('\n  '));
-        else res.send('Error: ' + errors[0]);
-        if (waiter) waiter.responseReject(new Error(errors.join(', ')));
+        responded = true;
+        res.set('Content-Type', 'text/plain');
+        res.send(m);
     }
-    else {
-        res.send('OK');
-        if (waiter) waiter.responseResolve();
+    catch (e) {
+        m = 'Error while processing a logout response: ' + e;
+        logException(m + '\n' + xml, e);
+        if (waiter) {
+            waiter.done = Date.now();
+            waiter.responseReject(e);
+        }
+        if (!responded) {
+            res.set('Content-Type', 'text/plain');
+            res.send(m);
+        }
     }
 };
 
@@ -328,75 +371,92 @@ var handleLogoutRequest = function (xml, form, res) {
     var errors = [],
         nameId = null,
         sessionIndex = null,
+        responded = false, // don't respond if we already responded (and failed)
         doc, rootNode, attributes, i, requestId, node,
-        responseObj, responseId;
-    doc = new xmldom.DOMParser().parseFromString(xml);
-    rootNode = doc.documentElement;
-    if (rootNode.localName != 'LogoutRequest') {
-        errors.push('not a LogoutRequest: ' + rootNode.localName);
-    }
-    else {
-        attributes = rootNode.attributes;
-        for (i = attributes.length - 1; i >= 0; i--) {
-            if (attributes[i].localName === 'ID') {
-                requestId = attributes[i].value;
-                break;
-            }
+        responseObj, responseId, m;
+    try {
+        doc = new xmldom.DOMParser().parseFromString(xml);
+        rootNode = doc.documentElement;
+        if (rootNode.localName != 'LogoutRequest') {
+            errors.push('not a LogoutRequest: ' + rootNode.localName);
         }
-        if (!requestId) errors.push('request ID is missing');
-        node = rootNode.firstChild;
-        while (node) {
-            switch (node.localName) {
-                case 'Issuer':
-                    if (node.firstChild.data !== IdPIssuer) errors.push('ERROR: invalid IdP issuer: ' + node.firstChild.data);
-                    break;
-                case 'NameID':
-                    nameId = parseNameID(node);
-                    break;
-                case 'SessionIndex':
-                    sessionIndex = node.firstChild && node.firstChild.data;
+        else {
+            attributes = rootNode.attributes;
+            for (i = attributes.length - 1; i >= 0; i--) {
+                if (attributes[i].localName === 'ID') {
+                    requestId = attributes[i].value;
                     break;
+                }
+            }
+            if (!requestId) errors.push('request ID is missing');
+            node = rootNode.firstChild;
+            while (node) {
+                switch (node.localName) {
+                    case 'Issuer':
+                        if (node.firstChild.data !== IdPIssuer) errors.push('ERROR: invalid IdP issuer: ' + node.firstChild.data);
+                        break;
+                    case 'NameID':
+                        nameId = parseNameID(node);
+                        break;
+                    case 'SessionIndex':
+                        sessionIndex = node.firstChild && node.firstChild.data;
+                        break;
+                }
+                node = node.nextSibling;
+            }
+            if (!nameId) errors.push('NameID not present');
+            else {
+                if (!nameId['#text']) errors.push('NameID is empty');
             }
-            node = node.nextSibling;
         }
-        if (!nameId) errors.push('NameID not present');
-        else {
-            if (!nameId['#text']) errors.push('NameID is empty');
+        if (errors.length > 0) {
+            logger.error('A third party requested a global SAML logout, but there were errors; original request:\n' + xml + '\nErrors:\n' + errors.join('\n'));
+            responded = true;
+            res.set('Content-Type', 'text/plain');
+            res.send(errors.join('\n'));
         }
-    }
-    if (errors.length > 0) {
-        res.set('Content-Type', 'text/plain');
-        res.send(errors.join('\n'));
-    }
-    else {
-        responseId = makeRequestId();
-        responseObj = {
-            'samlp:LogoutResponse': {
-                '@xmlns:samlp': 'urn:oasis:names:tc:SAML:2.0:protocol',
-                '@xmlns:saml': 'urn:oasis:names:tc:SAML:2.0:assertion',
-                '@Version': '2.0',
-                '@Destination': SLOServiceURL,
-                '@ID': responseId,
-                '@IssueInstant': new Date().toISOString(),
-                '@InResponseTo': requestId,
-                'saml:Issuer' : {
-                    '#text': SPIssuer
-                },
-                'samlp:Status': {
-                    'samlp:StatusCode': {
-                        '@Value': 'urn:oasis:names:tc:SAML:2.0:status:Success'
+        else {
+            responseId = makeRequestId();
+            responseObj = {
+                'samlp:LogoutResponse': {
+                    '@xmlns:samlp': 'urn:oasis:names:tc:SAML:2.0:protocol',
+                    '@xmlns:saml': 'urn:oasis:names:tc:SAML:2.0:assertion',
+                    '@Version': '2.0',
+                    '@Destination': SLOServiceURL,
+                    '@ID': responseId,
+                    '@IssueInstant': new Date().toISOString(),
+                    '@InResponseTo': requestId,
+                    'saml:Issuer': {
+                        '#text': SPIssuer
+                    },
+                    'samlp:Status': {
+                        'samlp:StatusCode': {
+                            '@Value': 'urn:oasis:names:tc:SAML:2.0:status:Success'
+                        }
                     }
                 }
-            }
-        };
-        makeSamlRedirectUrl(SLOServiceURL, 'SAMLRequest', responseObj, form.RelayState ? {RelayState: form.RelayState} : null, function (err, svcUrl) {
-            if (err) {
-                logException('Error while assembling the Logout SAML response: ' + err, err);
-                res.send('Failed: ' + err);
-                return;
-            }
-            res.redirect(svcUrl); // redirect to the IdP
-        });
+            };
+            makeSamlRedirectUrl(SLOServiceURL, 'SAMLRequest', responseObj, form.RelayState ? {RelayState: form.RelayState} : null, function (err, svcUrl, responseXml) {
+                if (err) {
+                    logException('Error while assembling the SAML logout response; original request:\n' + xml + '\nError: ' + err, err);
+                    responded = true;
+                    res.set('Content-Type', 'text/plain');
+                    res.send('Failed: ' + err);
+                    return;
+                }
+                logger.debug('Responding to a third party logout request:\n' + xml + '\nResponse:\n' + responseXml);
+                responded = true;
+                res.redirect(svcUrl); // redirect to the IdP
+            });
+        }
+    }
+    catch (e) {
+        m = 'Error while processing a third party logout request: ' + e;
+        logException(m + '\n' + xml, e);
+        if (!responded) {
+            res.set('Content-Type', 'text/plain');
+            res.send(m);
+        }
     }
 };
 
@@ -404,12 +464,16 @@ var handleLogoutRequest = function (xml, form, res) {
 // SAML web request handlers
 // ================================================================================
 
-// redirect to login on Arnes AAI, https://codeq.si/Shibboleth.sso/Login
+// redirect to login at IdP, https://codeq.si/Shibboleth.sso/Login
 http_app.get('/Shibboleth.sso/Login', function (req, res) {
     var sid = req.query.sid,
+        responded = false, // don't respond if we already responded (and failed)
         waiter, requestId, request;
     try {
         if (!sid) {
+            logger.error('Login request without SID, query parameters: ' + JSON.stringify(req.query));
+            responded = true;
+            res.set('Content-Type', 'text/plain');
             res.send('SID not set');
             return;
         }
@@ -432,14 +496,17 @@ http_app.get('/Shibboleth.sso/Login', function (req, res) {
                 }
             }
         };
-        makeSamlRedirectUrl(SSOServiceURL, 'SAMLRequest', request, null, function (err, svcUrl) {
+        makeSamlRedirectUrl(SSOServiceURL, 'SAMLRequest', request, null, function (err, svcUrl, responseXml) {
             if (err) {
-                logException('Error while assembling the Login SAML request: ' + err, err);
+                logException('Error while assembling the Login SAML request for sid=' + sid + ': ' + err, err);
                 waiter.done = Date.now();
                 waiter.reject(err instanceof Error ? err : new Error(err));
+                responded = true;
+                res.set('Content-Type', 'text/plain');
                 res.send('Failed: ' + err);
                 return;
             }
+            responded = true;
             res.redirect(svcUrl); // redirect to the IdP
             parkedLoginRequests[requestId] = waiter;
             waiter.parked = Date.now();
@@ -447,68 +514,95 @@ http_app.get('/Shibboleth.sso/Login', function (req, res) {
         });
     }
     catch (e) {
-        logException('Exception while processing login request: ' + e, e);
-        res.send('Error: ' + e);
+        logException('Exception while processing login request with query parameters ' + JSON.stringify(req.query) + ': ' + e, e);
         if (waiter) {
             waiter.done = Date.now();
             waiter.reject(e);
         }
+        if (!responded) {
+            res.set('Content-Type', 'text/plain');
+            res.send('Error: ' + e);
+        }
     }
 });
 
-// redirect to logout on Arnes AAI, https://codeq.si/Shibboleth.sso/Logout
+// redirect to logout at IdP, https://codeq.si/Shibboleth.sso/Logout
 http_app.get('/Shibboleth.sso/Logout', function (req, res) {
     var sid = req.query.sid,
+        responded = false,
         waiter, requestId, request;
-    if (!sid) {
-        res.send('SID not set');
-        return;
-    }
-
-    waiter = waitingLogouts[sid];
-    if (!waiter) waitingLogouts[sid] = waiter = makeDoubleWaiter(sid);
+    try {
+        if (!sid) {
+            logger.error('Logout request without SID, query parameters: ' + JSON.stringify(req.query));
+            responded = true;
+            res.set('Content-Type', 'text/plain');
+            res.send('SID not set');
+            return;
+        }
 
-    waiter.promise
-        .then(function (samlData) {
-            requestId = makeRequestId();
-            request = {
-                'samlp:LogoutRequest': {
-                    '@xmlns:samlp': 'urn:oasis:names:tc:SAML:2.0:protocol',
-                    '@xmlns:saml': 'urn:oasis:names:tc:SAML:2.0:assertion',
-                    '@Version': '2.0',
-                    '@Destination': SLOServiceURL,
-                    '@ID': requestId,
-                    '@IssueInstant': new Date().toISOString(),
-                    'saml:Issuer' : {
-                        '#text': SPIssuer
-                    },
-                    'saml:NameID': samlData.NameID
-                }
-            };
-            if (samlData.SessionIndex) request['samlp:LogoutRequest']['samlp:SessionIndex'] = {'#text': samlData.SessionIndex};
-            makeSamlRedirectUrl(SLOServiceURL, 'SAMLRequest', request, null, function (err, svcUrl) {
-                if (err) {
-                    logException('Error while assembling the Logout SAML request: ' + err, err);
+        waiter = waitingLogouts[sid];
+        if (!waiter) waitingLogouts[sid] = waiter = makeDoubleWaiter(sid);
+
+        waiter.promise
+            .then(function (samlData) {
+                requestId = makeRequestId();
+                request = {
+                    'samlp:LogoutRequest': {
+                        '@xmlns:samlp': 'urn:oasis:names:tc:SAML:2.0:protocol',
+                        '@xmlns:saml': 'urn:oasis:names:tc:SAML:2.0:assertion',
+                        '@Version': '2.0',
+                        '@Destination': SLOServiceURL,
+                        '@ID': requestId,
+                        '@IssueInstant': new Date().toISOString(),
+                        'saml:Issuer': {
+                            '#text': SPIssuer
+                        },
+                        'saml:NameID': samlData.NameID
+                    }
+                };
+                if (samlData.SessionIndex) request['samlp:LogoutRequest']['samlp:SessionIndex'] = {'#text': samlData.SessionIndex};
+                makeSamlRedirectUrl(SLOServiceURL, 'SAMLRequest', request, null, function (err, svcUrl, requestXml) {
+                    if (err) {
+                        logException('Error while assembling the Logout SAML request for sid=' + sid + ': ' + err, err);
+                        waiter.done = Date.now();
+                        waiter.responseReject(err instanceof Error ? err : new Error(err));
+                        responded = true;
+                        res.set('Content-Type', 'text/plain');
+                        res.send('Failed: ' + err);
+                        return;
+                    }
+                    logger.debug('Redirecting with a logout request:\n' + requestXml);
+                    responded = true;
+                    res.redirect(svcUrl); // redirect to the IdP
+                    parkedLogoutRequests[requestId] = waiter;
+                    waiter.parked = Date.now();
+                    waiter.requestId = requestId;
+                });
+            })
+            .catch(function (e) {
+                logException('Exception while processing logout request: ' + e, e);
+                if (waiter) {
+                    if (requestId) delete parkedLogoutRequests[requestId];
                     waiter.done = Date.now();
-                    waiter.responseReject(err instanceof Error ? err : new Error(err));
-                    res.send('Failed: ' + err);
-                    return;
+                    waiter.responseReject(e);
                 }
-                res.redirect(svcUrl); // redirect to the IdP
-                parkedLogoutRequests[requestId] = waiter;
-                waiter.parked = Date.now();
-                waiter.requestId = requestId;
-            });
-        })
-        .catch(function (e) {
-            logException('Exception while processing login request: ' + e, e);
+                responded = true;
+                res.set('Content-Type', 'text/plain');
+                res.send('Error: ' + e);
+            })
+            .done();
+    }
+    catch (e) {
+        logException('Exception while processing logout request: ' + e, e);
+        if (waiter) {
+            waiter.done = Date.now();
+            waiter.reject(e);
+        }
+        if (!responded) {
+            res.set('Content-Type', 'text/plain');
             res.send('Error: ' + e);
-            if (waiter) {
-                waiter.done = Date.now();
-                waiter.responseReject(e);
-            }
-        })
-        .done();
+        }
+    }
 });
 
 // user logged in, read the credentials
@@ -522,100 +616,117 @@ http_app.post('/Shibboleth.sso/SAML2/POST', function (req, res) {
         status = null,
         assertion = null,
         waiter = null,
-        attributes, i, key, value, xml, doc, rootNode, node, NameID, Format, SPNameQualifier, SessionIndex, samlData, userData;
-    value = form.SAMLResponse;
-    if (!value) {
-        errors.push('no SAMLResponse');
-    }
-    else {
-        xml = new Buffer(value, 'base64').toString('utf8');
-        doc = new xmldom.DOMParser().parseFromString(xml);
-        rootNode = doc.documentElement;
-        if (rootNode.localName != 'Response') {
-            errors.push('the root XML node is not a Response: ' + rootNode.localName);
+        responded = false, // don't respond if we already responded (and failed)
+        attributes, i, key, value, xml, doc, rootNode, node, NameID, SessionIndex, samlData, userData, m;
+    try {
+        value = form.SAMLResponse;
+        if (!value) {
+            errors.push('no SAMLResponse');
         }
         else {
-            attributes = rootNode.attributes;
-            for (i = attributes.length - 1; i >= 0; i--) {
-                if (attributes[i].localName === 'InResponseTo') {
-                    inResponseTo = attributes[i].value;
-                    break;
-                }
+            xml = new Buffer(value, 'base64').toString('utf8');
+            doc = new xmldom.DOMParser().parseFromString(xml);
+            rootNode = doc.documentElement;
+            if (rootNode.localName != 'Response') {
+                errors.push('the root XML node is not a Response: ' + rootNode.localName);
             }
-            if (!inResponseTo) errors.push('request ID that this message is a response to is missing');
             else {
-                waiter = parkedLoginRequests[inResponseTo];
-                if (!waiter) errors.push('there is no session waiting on request ID ' + inResponseTo);
-                else {
-                    waiter.done = Date.now();
-                    delete parkedLoginRequests[inResponseTo];
-                }
-                node = rootNode.firstChild;
-                while (node) {
-                    switch (node.localName) {
-                        case 'Issuer':
-                            issuer = node.firstChild.data;
-                            break;
-                        case 'Signature':
-                            signature = validateXmlSignature(xml, node);
-                            break;
-                        case 'Status':
-                            status = xmlStatusOk(node);
-                            break;
-                        case 'Assertion':
-                            assertion = parseAssertion(xml, node);
-                            break;
-                        default:
-//                                errors.push('Unknown/unsupported top XML node: ' + node.localName + ', prefix: ' + node.prefix + '<br>\n');
-                            break;
+                attributes = rootNode.attributes;
+                for (i = attributes.length - 1; i >= 0; i--) {
+                    if (attributes[i].localName === 'InResponseTo') {
+                        inResponseTo = attributes[i].value;
+                        break;
                     }
-                    node = node.nextSibling;
                 }
-                if (issuer === null) errors.push('Issuer is not set');
-                else if (issuer !== IdPIssuer) errors.push('Invalid IdP issuer: ' + issuer);
-                if (signature === null) errors.push('the response is not signed');
-                else if (!signature) errors.push('IdP signature is invalid');
-                if (status === null) errors.push('status is not set');
-                else if (!status) errors.push('response status is not OK');
-                if (!assertion) errors.push('no assertions supplied, no attributes present');
+                if (!inResponseTo) errors.push('request ID that this message is a response to is missing');
                 else {
-                    if ((typeof assertion.signatureOk !== 'undefined') && (!assertion.signatureOk)) errors.push('assertion signature is invalid');
-                    samlData = {};
-                    node = assertion.subject;
-                    if (!node) errors.push('assertion subject is not set');
+                    waiter = parkedLoginRequests[inResponseTo];
+                    if (!waiter) errors.push('there is no session waiting on request ID ' + inResponseTo);
                     else {
-                        node = node.NameID;
-                        if (!node) errors.push('assertion subject\'s NameID is not set');
-                        else {
-                            if (!node['#text']) errors.push('assertion subject\'s NameID is empty');
-                            samlData['NameID'] = node;
+                        waiter.done = Date.now();
+                        delete parkedLoginRequests[inResponseTo];
+                    }
+                    node = rootNode.firstChild;
+                    while (node) {
+                        switch (node.localName) {
+                            case 'Issuer':
+                                issuer = node.firstChild.data;
+                                break;
+                            case 'Signature':
+                                signature = validateXmlSignature(xml, node);
+                                break;
+                            case 'Status':
+                                status = xmlStatusOk(node);
+                                break;
+                            case 'Assertion':
+                                assertion = parseAssertion(xml, node);
+                                break;
+                            default:
+//                                errors.push('Unknown/unsupported top XML node: ' + node.localName + ', prefix: ' + node.prefix + '<br>\n');
+                                break;
                         }
+                        node = node.nextSibling;
                     }
-                    if (assertion.SessionIndex) samlData['SessionIndex'] = assertion.SessionIndex;
-                    node = assertion.attributes;
-                    if (!node) errors.push('no attributes supplied');
+                    if (issuer === null) errors.push('Issuer is not set');
+                    else if (issuer !== IdPIssuer) errors.push('Invalid IdP issuer: ' + issuer);
+                    if (signature === null) errors.push('the response is not signed');
+                    else if (!signature) errors.push('IdP signature is invalid');
+                    if (status === null) errors.push('status is not set');
+                    else if (!status) errors.push('response status is not OK');
+                    if (!assertion) errors.push('no assertions supplied, no attributes present');
                     else {
-                        userData = {};
-                        samlData.userData = userData;
-                        keys = Object.keys(node);
-                        for (i = keys.length - 1; i >= 0; i--) {
-                            key = keys[i];
-                            userData[key] = node[key];
+                        if ((typeof assertion.signatureOk !== 'undefined') && (!assertion.signatureOk)) errors.push('assertion signature is invalid');
+                        samlData = {};
+                        node = assertion.subject;
+                        if (!node) errors.push('assertion subject is not set');
+                        else {
+                            node = node.NameID;
+                            if (!node) errors.push('assertion subject\'s NameID is not set');
+                            else {
+                                if (!node['#text']) errors.push('assertion subject\'s NameID is empty');
+                                samlData['NameID'] = node;
+                            }
+                        }
+                        if (assertion.SessionIndex) samlData['SessionIndex'] = assertion.SessionIndex;
+                        node = assertion.attributes;
+                        if (!node) errors.push('no attributes supplied');
+                        else {
+                            userData = {};
+                            samlData.userData = userData;
+                            keys = Object.keys(node);
+                            for (i = keys.length - 1; i >= 0; i--) {
+                                key = keys[i];
+                                userData[key] = node[key];
+                            }
                         }
                     }
                 }
             }
         }
+        if (errors.length > 0) {
+            logger.debug('Errors processing a login response:\nSAMLResponse=' + value + '\nDecoded XML:\n' + xml + '\nErrors:\n' + errors.join('\n'));
+            if (waiter) waiter.reject(new Error(errors.join(', ')));
+            if (errors.length > 1) m = 'Multiple errors:\n  ' + errors.join('\n  ');
+            else m = 'Error: ' + errors[0];
+        }
+        else {
+            logger.debug('Received a successful login response:\n' + xml);
+            if (waiter) waiter.resolve(samlData);
+            m = 'OK';
+        }
+        responded = true;
+        res.set('Content-Type', 'text/plain');
+        res.send(m);
     }
-    res.set('Content-Type', 'text/plain');
-    if (errors.length > 0) {
-        if (errors.length > 1) res.send('Multiple errors:\n  ' + errors.join('\n  '));
-        else res.send('Error: ' + errors[0]);
-        if (waiter) waiter.reject(new Error(errors.join(', ')));
-    }
-    else {
-        res.send('OK');
-        if (waiter) waiter.resolve(samlData);
+    catch (e) {
+        m = 'Error while processing a login response: ' + e;
+        if (xml) logException(m + '\n' + xml, e);
+        else if (value) logException(m + '\nSAMLResponse=' + value, e);
+        else logException(m, e);
+        if (!responded) {
+            res.set('Content-Type', 'text/plain');
+            res.send(m);
+        }
     }
 });
 
@@ -632,7 +743,10 @@ http_app.get('/Shibboleth.sso/SLO/Redirect', function (req, res) {
         };
     if (form.SAMLRequest) zlib.inflateRaw(new Buffer(form.SAMLRequest, 'base64'), function (err, buffer) {delegateToHandler(err, buffer, handleLogoutRequest);});
     else if (form.SAMLResponse) zlib.inflateRaw(new Buffer(form.SAMLResponse, 'base64'), function (err, buffer) {delegateToHandler(err, buffer, handleLogoutResponse);});
-    else res.send('Invalid SAML logout request.');
+    else {
+        logger.error('Invalid SAML logout request/response, query string: ' + JSON.stringify(req.query));
+        res.send('Invalid SAML logout request/response.');
+    }
 });
 
 // ================================================================================