I am in dire need of help. I dont know when this error arises as I am unable to reproduce this bug on my own. Our center of attention is ServiceToService.setClientLoggingInResponse() method (which is called from RequestProcessor class line:12) . I have log printing the following output from bottom to top. We see memcache error on third logged statement. It occurs in MCache.readFromCache() method then it goes to catch block of RequestProcessor class (line 15 of RequestProcessor class). I am unable to comprehend why it is in catch block of RequestProcessor. Because I thought I have everything cover in setClientLoggingInResponse(). I thought if memcache error arises it should go to line 48 in setClientLoggingInResponse() method. But as log shows it didn’t. I have two questions.

1. Why it didn’t end up in line 48 in setClientLoggingInResponse() method but rather end up in catch block (line 15 of RequestProcessor class)
2. What should I do so that it stays in setClientLoggingInResponse() and does only this memory.addToMemory(locationUuid, {})

LOGS

2024-05-30 21:18:45 
{"level":100,"time":1717085925098,"pid":19,"hostname":"","msg":"preparing error response","method":"RequestProcessor.prepareErrorResponse"}
2024-05-30 21:18:45 
{"level":600,"time":1717085925098,"pid":19,"hostname":"","msg":"failed to process request","method":"RequestProcessor.process"}
2024-05-30 21:18:45 
{"level":400,"time":1717085925097,"pid":19,"hostname":"","msg":"memcache error: Server at kvs-memcached-client-logging:11211 not available while reading key=5c6c2ac0-1e7e-11ef-bc70-dba3d3ca35f7","method":"Client.<anonymous>"}
2024-05-30 21:18:45 
{"level":100,"time":1717085925097,"pid":19,"hostname":"","msg":"Data is not in memory for:","method":"ServiceToService.setClientLoggingInResponse"}
2024-05-30 21:18:45 
{"level":100,"time":1717085925097,"pid":19,"hostname":"","msg":"setClientLoggingInResponse","method":"ServiceToService.setClientLoggingInResponse"}

RequestProcessor Class

class RequestProcessor {
  static async process(requestOptions, tick = () => {}, ignoreAppKeyValidation) {

    const uniqueTimerIds = RequestProcessor.createUniqueTimerIds();
    _.set(requestOptions, 'uniqueTimerIds', uniqueTimerIds);

    try {

      tick('before RequestProcessor.callService...');
      await RequestProcessor.callService(requestOptions, tick);
      tick('after RequestProcessor.callService...');
      await RequestProcessor.setClientLoggingInResponse(requestOptions);
      RequestProcessor.prepareResponse(requestOptions);
    } catch (error) {
      logger.error('failed to process request', { error: error.message });
      RequestProcessor.prepareErrorResponse(requestOptions, error.message, error.errorCode);
    }

    LoggerStatus.tokenLogger(requestOptions, metrics);
  }

  static async callService(requestOptions, tick) {
    await serviceToService.callService(requestOptions, tick);
  }

  static prepareResponse(requestOptions) {
    logger.debug('preparing response', { payload: requestOptions.payload });
    serviceToService.prepareResponse(requestOptions);
  }

  static prepareErrorResponse(requestOptions, errorText, errorCode) {
    logger.debug('preparing error response', { errorText, errorCode, payload: requestOptions.payload });
    serviceToService.prepareErrorResponse(requestOptions, errorText, errorCode);
  }

  static async setClientLoggingInResponse(requestOptions) {
    await serviceToService.setClientLoggingInResponse(requestOptions);
  }
}

RequestProcessor.serviceToService = serviceToService;

module.exports = RequestProcessor;

ServiceToService Class

class ServiceToService {
  constructor() {
        // statments
  }

  async setClientLoggingInResponse(requestOptions) {
    const { payload } = requestOptions;
    logger.debug(`setClientLoggingInResponse`, payload);
    let cachedData = {};
    try {
      if (this.CLIENT_LOGGING_ENABLE && payload.access && payload.access.location && payload.access.location.uuid) {
        const locationUuid = payload.access.location.uuid;
        if (!memory.getFromMemory(locationUuid)) {
            logger.debug(`Data is not in memory for:`, locationUuid);
            const cacheKey = locationUuid;
            const timer = new Promise(resolve => setTimeout(resolve, this.CLIENT_LOGGING_MAX_READ_TIME_MS));
            const readFromCache = cache.readFromCache(cacheKey);

            const result = await Promise.race([timer, readFromCache]);
            
            if (result) { 
              logger.debug(`Won Race, Result found for:`, { locationUuid, result });
              try {
                cachedData = JSON.parse(result); 
                memory.addToMemory(locationUuid, cachedData)
                
              } catch (jsonError) {
                logger.info(`JSON decoding error: ${jsonError.message}`);
                cachedData = {};
                memory.addToMemory(locationUuid, cachedData)
              }
            }
            else
            {
              readFromCache.then(function(result)  //whenever response finishes after losing race condition with timer, store in memory the value as described below
              {
                logger.debug(`Lost Race, Result found for:`, { locationUuid, result });
                try {
                  cachedData = JSON.parse(result); // if result is not found (undefined) still catch will run and {} will store
                  memory.addToMemory(locationUuid, cachedData)
                } catch (jsonError) {
                  logger.info(`JSON decoding error: ${jsonError.message}`);
                  memory.addToMemory(locationUuid, {})
                }
              }).catch(function(e){
                  logger.info(`Error while reading memcache:`);
                  memory.addToMemory(locationUuid, {})
              });
            }
        }

        let obj = memory.getFromMemory(locationUuid); // need to make fresh call in case above process has set the object
        if (obj && Object.keys(obj).length > 0) {  // if object is not empty ({})
          logger.debug(`Found locationUuid=${locationUuid} in memory with value=`, obj);
          requestOptions.response._client_logging = obj;
        }
      }

    }
    catch(e)
    {
      memory.addToMemory(locationUuid, {}); // point 4 of spec IMPORTANT
      logger.debug(`Eception in setClientLoggingInResponse ${JSON.stringify(e)}`);
    }
  }
}

module.exports = ServiceToService;

MCache Class

const config = require('../config');
const Memcached = require('memcached');
const { logger } = require('logger-wrapper');
class MCache {
    constructor({ memcached }) {
      this.memcached = memcached;  
      this.readFromCache = this.readFromCache.bind(this);
      this.writeToCache = this.writeToCache.bind(this);
    }
  
    async readFromCache(key) {
      return new Promise((resolve, reject) => {
        this.memcached.get(key, (err, data) => {
          if (err) {
            logger.warning(`memcache error: ${err.message} while reading key=${key}`);
            reject(err);
          }
  
          resolve(data);
        });
      });
    }
  
    // other methods
  }

    const memcached = new Memcached(`${config.get('MEMCACHED_HOST')}:${config.get('MEMCACHED_PORT')}`);
    const mCache = new MCache({ memcached });

  module.exports = mCache;