Added periodic timed out request cleaner to SAML daemon.

1 files changed, 115 insertions, 9 deletions

diff --git a/saml/saml.js b/saml/saml.js
index 6a48af1..3eff569 100644
--- a/saml/saml.js
+++ b/saml/saml.js
@@ -337,9 +337,9 @@ var handleLogoutResponse = function (xml, form, res) {
                 waiter.done = Date.now();
                 waiter.responseReject(new Error(errors.join(', ')));
             }
-            if (errors.length > 1) m = 'Multiple errors:\n' + errors.join('\n  ');
-            //logger.error(''); // TODO: continue here
+            if (errors.length > 1) m = 'Multiple errors:\n  ' + errors.join('\n  ');
             else m = 'Error: ' + errors[0];
+            logger.error('Received a SAML logout response and encountered errors processing it; response:\n' + xml + '\nErrors:\n  ' + errors.join('\n  '));
         }
         else {
             if (waiter) {
@@ -347,6 +347,7 @@ var handleLogoutResponse = function (xml, form, res) {
                 waiter.responseResolve();
             }
             m = 'OK';
+            logger.debug('Received a SAML logout response:\n' + xml);
         }
         responded = true;
         res.set('Content-Type', 'text/plain');
@@ -496,7 +497,7 @@ http_app.get('/Shibboleth.sso/Login', function (req, res) {
                 }
             }
         };
-        makeSamlRedirectUrl(SSOServiceURL, 'SAMLRequest', request, null, function (err, svcUrl, responseXml) {
+        makeSamlRedirectUrl(SSOServiceURL, 'SAMLRequest', request, null, function (err, svcUrl, requestXml) {
             if (err) {
                 logException('Error while assembling the Login SAML request for sid=' + sid + ': ' + err, err);
                 waiter.done = Date.now();
@@ -506,6 +507,7 @@ http_app.get('/Shibboleth.sso/Login', function (req, res) {
                 res.send('Failed: ' + err);
                 return;
             }
+            logger.debug('Redirecting to IdP with a login request:\n' + requestXml);
             responded = true;
             res.redirect(svcUrl); // redirect to the IdP
             parkedLoginRequests[requestId] = waiter;
@@ -571,7 +573,7 @@ http_app.get('/Shibboleth.sso/Logout', function (req, res) {
                         res.send('Failed: ' + err);
                         return;
                     }
-                    logger.debug('Redirecting with a logout request:\n' + requestXml);
+                    logger.debug('Redirecting to IdP with a logout request:\n' + requestXml);
                     responded = true;
                     res.redirect(svcUrl); // redirect to the IdP
                     parkedLogoutRequests[requestId] = waiter;
@@ -741,11 +743,26 @@ http_app.get('/Shibboleth.sso/SLO/Redirect', function (req, res) {
             }
             handler(buffer.toString('utf8'), form, 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 {
-        logger.error('Invalid SAML logout request/response, query string: ' + JSON.stringify(req.query));
-        res.send('Invalid SAML logout request/response.');
+    try {
+        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 {
+            logger.error('Invalid SAML logout request/response, query string: ' + JSON.stringify(req.query));
+            res.set('Content-Type', 'text/plain');
+            res.send('Invalid SAML logout request/response.');
+        }
+    }
+    catch (e) {
+        logException('Error while processing a SAML logout request/response, querystring=' + JSON.stringify(req.query) + ': ' + e, e);
+        try {
+            res.set('Content-Type', 'text/plain');
+            res.send('Error: ' + e);
+        }
+        catch (e2) {} // ignore
     }
 });
 
@@ -804,3 +821,92 @@ http_app.get('/Shibboleth.sso/WaitLogout', function (req, res) {
         res.json({'code': 1, 'message': '' + err});
     }).done();
 });
+
+// ================================================================================
+// A periodic cleaner: rejects and purges timed out requests
+// ================================================================================
+
+var cleanerTimer = setInterval(function () { // run every 10 seconds
+    var youngestTime = Date.now() - 300000, // request timeout: 5 minutes
+        keys = Object.keys(parkedLoginRequests),
+        i, key, waiter;
+    // parked logins: the user was already redirected at IdP for login
+    for (i = keys.length - 1; i >= 0; i--) {
+        key = keys[i];
+        waiter = parkedLoginRequests[key];
+        if (waiter.parked < youngestTime) {
+            if (waiter.promise.isPending()) {
+                logger.warn('A login request timed out at IdP: sid=' + waiter.sid + ', requestId=' + waiter.requestId)
+                waiter.promise.reject(new Error('Request timed out waiting for IdP login reply'));
+            }
+            else {
+                logger.info('Encountered a parked login request which has already been resolved: sid=' + waiter.sid + ', requestId=' + waiter.requestId);
+            }
+            delete parkedLoginRequests[key];
+            delete waitingLogins[waiter.sid];
+        }
+    }
+    // waiting logins; the user's sid was registered, but the user itself may not have been redirected at IdP for login yet
+    keys = Object.keys(waitingLogins);
+    for (i = keys.length - 1; i >= 0; i--) {
+        key = keys[i];
+        waiter = waitingLogins[key];
+        if ((waiter.parked || waiter.created) < youngestTime) {
+            if (waiter.promise.isPending()) {
+                if (waiter.parked) logger.warn('A login request, marked as parked but not encountered among parked requests, timed out at requester: sid=' + sid + ', requestId=' + waiter.requestId);
+                else logger.warn('A login request timed out at requester, with no outstanding request at IdP: sid=' + waiter.sid);
+                waiter.promise.reject(new Error('Request timed out waiting for user to start the login process'));
+            }
+            else {
+                logger.info('Encountered a waiting login request which has already been resolved: sid=' + waiter.sid + ', requestId=' + waiter.requestId);
+            }
+            delete waitingLogins[key];
+            if (waiter.requestId) delete parkedLoginRequests[waiter.requestId];
+        }
+    }
+    // parked logouts: the user was already redirected at IdP for logout, if the registration data was already provided, otherwise it's still waiting for redirection
+    keys = Object.keys(parkedLogoutRequests);
+    for (i = keys.length - 1; i >= 0; i--) {
+        key = keys[i];
+        waiter = parkedLogoutRequests[key];
+        if (waiter.parked < youngestTime) {
+            if (waiter.promise.isPending()) {
+                logger.warn('A logout request timed out waiting for registration info: sid=' + waiter.sid);
+                waiter.response.reject(new Error('Timed out waiting for registration info'));
+                if (waiter.responsePromise.isPending()) waiter.responsePromise.reject(new Error('Timed out waiting for registration info'));
+            }
+            else if (waiter.responsePromise.isPending()) {
+                logger.warn('A logout request timed out at IdP: sid=' + waiter.sid + ', requestId=' + waiter.requestId)
+                waiter.responsePromise.reject(new Error('Request timed out waiting for IdP logout reply'));
+            }
+            else {
+                logger.info('Encountered a parked logout request which has already been resolved: sid=' + waiter.sid + ', requestId=' + waiter.requestId);
+            }
+            delete parkedLogoutRequests[key];
+            delete waitingLogouts[waiter.sid];
+        }
+    }
+    // waiting logouts; the user's sid and registration data was registered, but the user itself may not have been redirected at IdP for logout yet
+    keys = Object.keys(waitingLogouts);
+    for (i = keys.length - 1; i >= 0; i--) {
+        key = keys[i];
+        waiter = waitingLogouts[key];
+        if ((waiter.parked || waiter.created) < youngestTime) {
+            if (waiter.promise.isPending()) {
+                if (waiter.parked) logger.warn('A logout request, marked as parked but not encountered among parked requests, timed out waiting for registration info: sid=' + sid + ', requestId=' + waiter.requestId); // this should be impossible: how can you go for logout at IdP if you have no registration info?
+                else logger.warn('A logout request timed out waiting for registration info, with no outstanding request at IdP: sid=' + waiter.sid);
+                waiter.response.reject(new Error('Timed out waiting for registration info'));
+                if (waiter.responsePromise.isPending()) waiter.responsePromise.reject(new Error('Timed out waiting for registration info'));
+            }
+            else if (waiter.responsePromise.isPending()) {
+                logger.warn('A logout request timed out at IdP: sid=' + waiter.sid + ', requestId=' + waiter.requestId)
+                waiter.responsePromise.reject(new Error('Request timed out waiting for IdP logout reply'));
+            }
+            else {
+                logger.info('Encountered a waiting logout request which has already been resolved: sid=' + waiter.sid + ', requestId=' + waiter.requestId);
+            }
+            delete waitingLogouts[key];
+            if (waiter.requestId) delete parkedLogoutRequests[waiter.requestId];
+        }
+    }
+}, 10000);