Append the current session identifier to the protocol name prefix
MODIFY
lib/protocol/protocol.js
lib/protocol/protocol.js
@@ -9,9 +9,10 @@ import B from 'bluebird';
import BaseDriver from '../basedriver/driver';
import LRU from 'lru-cache';
+const GENERIC_PROTOCOL = 'GENERIC';
const mjsonwpLog = logger.getLogger('MJSONWP');
const w3cLog = logger.getLogger('W3C');
-const genericProtocolLog = logger.getLogger('GENERIC');
+const genericProtocolLog = logger.getLogger(GENERIC_PROTOCOL);
const JSONWP_SUCCESS_STATUS_CODE = 0;
// TODO: Make this value configurable as a server side capability
@@ -35,7 +36,28 @@ const IMG_EL_URL_RE = new RegExp(
class Protocol {}
-function getLogByProtocol (protocol) {
+class SessionsCache {
+ constructor (max) {
+ this._cache = new LRU({ max });
+ }
+
+ getLogger (sessionId, protocol) {
+ if (sessionId) {
+ if (this._cache.has(sessionId)) {
+ const value = this._cache.get(sessionId);
+ if (value.logger) {
+ return value.logger;
+ }
+ protocol = protocol || value.protocol;
+ }
+ // Always create a new logger instance for ids
+ // that are not in the current sessions list,
+ // so we can still see such ids as prefixes
+ return logger.getLogger(`${protocol || GENERIC_PROTOCOL} ` +
+ `(${sessionId.substring(0, Math.min(sessionId.length, 8))})`);
+ }
+
+ // Fall back to protocol name-only logger if session id is unknown
switch (protocol) {
case BaseDriver.DRIVER_PROTOCOL.W3C:
return w3cLog;
@@ -46,21 +68,37 @@ function getLogByProtocol (protocol) {
}
}
-// This cache is useful when a session gets terminated
-// and removed from the sessions list in the umbrella driver,
-// but the client still tries to send a command to this session id.
-// So we know how to properly wrap the error message for it
-const PROTOCOLS_MAPPING_CACHE = new LRU({
- max: 100,
-});
+ getProtocol (sessionId) {
+ return (this._cache.get(sessionId) || {}).protocol;
+ }
-function cacheProtocolValue (value, sessionId) {
+ putSession (sessionId, value) {
if (sessionId && value) {
- PROTOCOLS_MAPPING_CACHE.set(sessionId, value);
+ this._cache.set(sessionId, {
+ protocol: value,
+ // We don't want to cache the logger instance for each random session id in the cache
+ // in order to save memory. Instead we only cache loggers for valid ids that
+ // are returned by `createSession` call and reset them after `deleteSession` is called
+ logger: this.getLogger(sessionId, value),
+ });
}
return value;
}
+ resetLogger (sessionId) {
+ if (this._cache.has(sessionId)) {
+ this._cache.get(sessionId).logger = null;
+ }
+ }
+}
+
+// This cache is useful when a session gets terminated
+// and removed from the sessions list in the umbrella driver,
+// but the client still tries to send a command to this session id.
+// So we know how to properly wrap the error message for it
+const SESSIONS_CACHE = new SessionsCache(100);
+
+
function extractProtocol (driver, sessionId = null) {
const dstDriver = _.isFunction(driver.driverForSession)
? driver.driverForSession(sessionId)
@@ -73,7 +111,7 @@ function extractProtocol (driver, sessionId = null) {
}
// Extract the protocol for the current session if the given driver is the umbrella one
- return dstDriver ? dstDriver.protocol : PROTOCOLS_MAPPING_CACHE.get(sessionId);
+ return dstDriver ? dstDriver.protocol : SESSIONS_CACHE.getProtocol(sessionId);
}
function isSessionCommand (command) {
@@ -306,7 +344,8 @@ function buildHandler (app, method, path, spec, driver, isSessCmd) {
}
// run the driver command wrapped inside the argument validators
- getLogByProtocol(currentProtocol).debug(`Calling ${driver.constructor.name}.${spec.command}() with args: ` +
+ SESSIONS_CACHE.getLogger(req.params.sessionId, currentProtocol).debug(`Calling ` +
+ `${driver.constructor.name}.${spec.command}() with args: ` +
_.truncate(JSON.stringify(args), {length: LOG_OBJ_LENGTH}));
if (driver.executeCommand) {
@@ -331,8 +370,8 @@ function buildHandler (app, method, path, spec, driver, isSessCmd) {
// unpack createSession response
if (spec.command === CREATE_SESSION_COMMAND) {
newSessionId = driverRes[0];
- cacheProtocolValue(currentProtocol, newSessionId);
- getLogByProtocol(currentProtocol)
+ SESSIONS_CACHE.putSession(newSessionId, currentProtocol);
+ SESSIONS_CACHE.getLogger(newSessionId, currentProtocol)
.debug(`Cached the protocol value '${currentProtocol}' for the new session ${newSessionId}`);
if (currentProtocol === BaseDriver.DRIVER_PROTOCOL.MJSONWP) {
driverRes = driverRes[1];
@@ -359,10 +398,9 @@ function buildHandler (app, method, path, spec, driver, isSessCmd) {
// delete should not return anything even if successful
if (spec.command === DELETE_SESSION_COMMAND) {
- getLogByProtocol(currentProtocol)
+ SESSIONS_CACHE.getLogger(req.params.sessionId, currentProtocol)
.debug(`Received response: ${_.truncate(JSON.stringify(driverRes), {length: LOG_OBJ_LENGTH})}`);
- getLogByProtocol(currentProtocol)
- .debug('But deleting session, so not returning');
+ SESSIONS_CACHE.getLogger(req.params.sessionId, currentProtocol).debug('But deleting session, so not returning');
driverRes = null;
}
@@ -380,8 +418,15 @@ function buildHandler (app, method, path, spec, driver, isSessCmd) {
httpResBody.status = (_.isNil(driverRes) || _.isUndefined(driverRes.status)) ? JSONWP_SUCCESS_STATUS_CODE : driverRes.status;
}
httpResBody.value = driverRes;
- getLogByProtocol(currentProtocol).debug(`Responding to client with driver.${spec.command}() ` +
- `result: ${_.truncate(JSON.stringify(driverRes), {length: LOG_OBJ_LENGTH})}`);
+ SESSIONS_CACHE.getLogger(req.params.sessionId || newSessionId, currentProtocol).debug(`Responding ` +
+ `to client with driver.${spec.command}() result: ${_.truncate(JSON.stringify(driverRes), {length: LOG_OBJ_LENGTH})}`);
+
+ if (spec.command === DELETE_SESSION_COMMAND) {
+ // We don't want to keep the logger instance in the cache
+ // after the session is deleted, because it contains the logging history
+ // and consumes the memory
+ SESSIONS_CACHE.resetLogger(req.params.sessionId);
+ }
} catch (err) {
// if anything goes wrong, figure out what our response should be
// based on the type of error that we encountered
@@ -395,7 +440,8 @@ function buildHandler (app, method, path, spec, driver, isSessCmd) {
// is the first part of the stack trace
errMsg = `${err.message} ${errMsg}`;
}
- getLogByProtocol(currentProtocol).debug(`Encountered internal error running command: ${errMsg}`);
+ SESSIONS_CACHE.getLogger(req.params.sessionId || newSessionId, currentProtocol).debug(`Encountered ` +
+ `internal error running command: ${errMsg}`);
if (isErrorType(err, errors.ProxyRequestError)) {
actualErr = err.getActualError();
}
@@ -487,8 +533,8 @@ function driverShouldDoJwpProxy (driver, req, command) {
}
async function doJwpProxy (driver, req, res) {
- const log = getLogByProtocol(extractProtocol(driver, req.params.sessionId));
- log.info('Driver proxy active, passing request on via HTTP proxy');
+ SESSIONS_CACHE.getLogger(req.params.sessionId, extractProtocol(driver, req.params.sessionId))
+ .info('Driver proxy active, passing request on via HTTP proxy');
// check that the inner driver has a proxy function
if (!driver.canProxy(req.params.sessionId)) {

Append the current session identifier to the protocol name prefix (#259)