Merge pull request #318 from telefonicaid/bug/cacheUndefinedWithMulti…

…pleWaitingTokens

Bug/cache undefined with multiple waiting tokens

CHANGES_NEXT_RELEASE

@@ -0,0 +1 @@
+- Error 503 in pep when many tokens are requested simultaneously #316

lib/services/cacheUtils.js

@@ -26,6 +26,7 @@
 var config = require('../../config'),
     async = require('async'),
     domainModule = require('domain'),
+    logger = require('logops'),
     NodeCache = require('node-cache'),
     EventEmitter = require('events').EventEmitter;
 
@@ -48,7 +49,9 @@ function createCache() {
         },
         channel: cacheChannel,
         updating: {
-            subservice: false
+            subservice: {},
+            roles: {},
+            user: {}
         }
     };
 }
@@ -66,11 +69,14 @@ function cleanCache(cache) {
 }
 
 function createDomainEnabledCacheHandler(domain, processValueFn, cache, cacheType, cacheKey, callback) {
-    return function(error) {
+    return function(error, value) {
         if (error) {
+            logger.debug('Error found creating cache domain handler');
             callback(error);
         } else {
             domain.enter();
+            logger.debug('Value found for cache type [%s] key [%s]: %s', cacheType, cacheKey, value);
+            logger.debug('Processing with value: %s', JSON.stringify(cache.data[cacheType].get(cacheKey)[cacheKey]));
             processValueFn(cache.data[cacheType].get(cacheKey)[cacheKey], callback);
         }
     };
@@ -91,10 +97,18 @@ function createDomainEnabledCacheHandler(domain, processValueFn, cache, cacheTyp
 function cacheAndHold(cache, cacheType, cacheKey, retrieveRequestFn, processValueFn, callback) {
     var cachedValue = cache.data[cacheType].get(cacheKey);
 
+    function getCacheEventId() {
+        return cacheType + ':' + cacheKey;
+    }
+
     if (cachedValue[cacheKey]) {
+        logger.debug('Value found in the cache [%s] for key [%s]: %s', cacheType, cacheKey, cachedValue[cacheKey]);
+
         processValueFn(cachedValue[cacheKey], callback);
-    } else if (cache.updating[cacheType]) {
-        cache.channel.on(cacheType,
+    } else if (cache.updating[cacheType][cacheKey]) {
+        logger.debug('Cache type [%s] updating for key [%s]. Waiting.', cacheType, cacheKey);
+
+        cache.channel.on(getCacheEventId(),
             createDomainEnabledCacheHandler(
                 domainModule.active,
                 processValueFn,
@@ -104,18 +118,21 @@ function cacheAndHold(cache, cacheType, cacheKey, retrieveRequestFn, processValu
                 callback)
             );
     } else {
-        cache.updating[cacheType] = true;
+        logger.debug('Value [%s] not found in cache. Retrieving new value.', cacheKey);
+        cache.updating[cacheType][cacheKey] = true;
         cache.channel.removeAllListeners(cacheType);
-        cache.channel.on(cacheType, function(error, value) {
+        cache.channel.on(getCacheEventId(), function(error, value) {
             callback(error, value);
         });
 
         async.waterfall([
             retrieveRequestFn,
             processValueFn
         ], function(error, value) {
-            cache.channel.emit(cacheType, error, value);
-            cache.channel.removeAllListeners(cacheType);
+            logger.debug('Value [%s] for type [%s] processed with value: %s.', cacheKey, cacheType, value);
+
+            cache.channel.emit(getCacheEventId(), error, value);
+            cache.channel.removeAllListeners(getCacheEventId());
         });
     }
 }

lib/services/keystoneAuth.js

@@ -136,7 +136,7 @@ function retrieveRoles(req, callback) {
         logger.debug('Extracting roles for token: %j', options);
 
         request(options, function retrieveRolesHandler(error, response, body) {
-            cache.updating.roles = false;
+            cache.updating.roles[cacheKey] = false;
 
             if (body) {
                 logger.debug('Keystone response retrieving roles:\n\n %j', body);
@@ -189,6 +189,9 @@ function retrieveUser(req, callback) {
             req.serviceId = cachedValue.serviceId;
             req.domainName = cachedValue.domainName;
             req.userId = cachedValue.userId;
+
+            logger.debug('User value processed with value: %j', cachedValue);
+
             innerCb(null, req.userId);
         } else {
             logger.error('Undefined cache value retrieving user from Keystone for service [%s] and subservice [%s]',
@@ -214,7 +217,7 @@ function retrieveUser(req, callback) {
 
         request(options, function(error, response, body) {
             /* jshint camelcase: false */
-            cache.updating.user = false;
+            cache.updating.user[userToken] = false;
 
             if (body) {
                 logger.debug('Keystone response retrieving user:\n\n %j', body);
@@ -242,19 +245,32 @@ function retrieveUser(req, callback) {
                         serviceId: body.token.project.domain.id,
                         userId: body.token['OS-TRUST:trust'].trustor_user.id
                     };
-                } else {
+
+                    innerCb(null, cachedValue);
+
+                } else if (body.token.user && body.token.user.domain &&
+                    body.token.user.domain.id && body.token.user.id) {
+
                     cachedValue = {
                         domainName: body.token.user.domain.name,
                         serviceId: body.token.user.domain.id,
                         userId: body.token.user.id
                     };
-                }
 
-                req.userData = cachedValue;
+                    req.userData = cachedValue;
+
+                    cache.data.user.set(userToken, cachedValue, function(error) {
+                        logger.debug('Value [%j] saved in the cache for token [%s](%s)', cachedValue, userToken, error);
 
-                cache.data.user.set(userToken, cachedValue);
+                        innerCb(null, cachedValue);
+                    });
 
-                innerCb(null, cachedValue);
+                } else {
+                    logger.error('Right response from Keystone without all the needed data:\n%s',
+                        JSON.stringify(body, null, 4));
+
+                    innerCb(new errors.KeystoneAuthenticationError(500));
+                }
             } else if (response.statusCode === 404) {
                 currentToken = null;
                 logger.error('Invalid user token: %s', currentToken);
@@ -314,7 +330,7 @@ function retrieveSubserviceId(req, callback) {
         logger.debug('Retrieving subservice ID from keystone: %j', options);
 
         request(options, function(error, response, body) {
-            cache.updating.subservice = false;
+            cache.updating.subservice[cacheKey] = false;
 
             if (body) {
                 logger.debug('Keystone response retrieving subservice ID:\n\n %j', body);