add event timing framework to base driver
MODIFY
lib/basedriver/commands/session.js
lib/basedriver/commands/session.js
@@ -64,6 +64,9 @@ commands.getSessions = async function () {
};
commands.getSession = async function () {
+ if (this.caps.eventTimings) {
+ return Object.assign({}, this.caps, {events: this.eventHistory});
+ }
return this.caps;
};

MODIFY
lib/basedriver/desired-caps.js
lib/basedriver/desired-caps.js
@@ -58,6 +58,9 @@ let desiredCapabilityConstraints = {
},
locale: {
isString: true
+ },
+ eventTimings: {
+ isBoolean: true
}
};

MODIFY
lib/basedriver/driver.js
lib/basedriver/driver.js
@@ -11,6 +11,11 @@ import { util } from 'appium-support';
const NEW_COMMAND_TIMEOUT_MS = 60 * 1000;
+const EVENT_SESSION_INIT = 'newSessionRequested';
+const EVENT_SESSION_START = 'newSessionStarted';
+const EVENT_SESSION_QUIT_START = 'quitSessionRequested';
+const EVENT_SESSION_QUIT_DONE = 'quitSessionFinished';
+
class BaseDriver extends MobileJsonWireProtocol {
constructor (opts = {}, shouldValidateCaps = true) {
@@ -51,6 +56,35 @@ class BaseDriver extends MobileJsonWireProtocol {
// allow subclasses to have internal drivers
this.managedDrivers = [];
+
+ // store event timings
+ this._eventHistory = {
+ commands: [] // commands get a special place
+ };
+ }
+
+ /*
+ * make eventHistory a property and return a cloned object so a consumer can't
+ * inadvertently change data outside of logEvent
+ */
+ get eventHistory () {
+ return _.cloneDeep(this._eventHistory);
+ }
+
+ /*
+ * API method for driver developers to log timings for important events
+ */
+ logEvent (eventName) {
+ if (eventName === "commands") {
+ throw new Error("Cannot log commands directly");
+ }
+ if (typeof eventName !== "string") {
+ throw new Error(`Invalid eventName ${eventName}`);
+ }
+ if (!this._eventHistory[eventName]) {
+ this._eventHistory[eventName] = [];
+ }
+ this._eventHistory[eventName].push(Date.now());
}
/*
@@ -140,6 +174,14 @@ class BaseDriver extends MobileJsonWireProtocol {
// and ensuring that we execute commands one at a time. This method is called
// by MJSONWP's express router.
async executeCommand (cmd, ...args) {
+ // get start time for this command, and log in special cases
+ let startTime = Date.now();
+ if (cmd === 'createSession') {
+ this.logEvent(EVENT_SESSION_INIT);
+ } else if (cmd === 'deleteSession') {
+ this.logEvent(EVENT_SESSION_QUIT_START);
+ }
+
// if we had a command timer running, clear it now that we're starting
// a new command and so don't want to time out
this.clearNewCommandTimeout();
@@ -188,6 +230,15 @@ class BaseDriver extends MobileJsonWireProtocol {
this.startNewCommandTimeout();
}
+ // log timing information about this command
+ let endTime = Date.now();
+ this._eventHistory.commands.push({cmd, startTime, endTime});
+ if (cmd === 'createSession') {
+ this.logEvent(EVENT_SESSION_START);
+ } else if (cmd === 'deleteSession') {
+ this.logEvent(EVENT_SESSION_QUIT_DONE);
+ }
+
return res;
}

MODIFY
test/basedriver/driver-e2e-tests.js
test/basedriver/driver-e2e-tests.js
@@ -18,6 +18,32 @@ function baseDriverE2ETests (DriverClass, defaultCaps = {}) {
await baseServer.close();
});
+ function startSession (caps) {
+ return request({
+ url: 'http://localhost:8181/wd/hub/session',
+ method: 'POST',
+ json: {desiredCapabilities: caps, requiredCapabilities: {}},
+ });
+ }
+
+ function endSession (id) {
+ return request({
+ url: `http://localhost:8181/wd/hub/session/${id}`,
+ method: 'DELETE',
+ json: true,
+ simple: false
+ });
+ }
+
+ function getSession (id) {
+ return request({
+ url: `http://localhost:8181/wd/hub/session/${id}`,
+ method: 'GET',
+ json: true,
+ simple: false
+ });
+ }
+
describe('session handling', () => {
it('should create session and retrieve a session id, then delete it', async () => {
let res = await request({
@@ -51,23 +77,10 @@ function baseDriverE2ETests (DriverClass, defaultCaps = {}) {
});
describe('command timeouts', () => {
- function startSession (timeout) {
+ function startTimeoutSession (timeout) {
let caps = _.clone(defaultCaps);
caps.newCommandTimeout = timeout;
- return request({
- url: 'http://localhost:8181/wd/hub/session',
- method: 'POST',
- json: {desiredCapabilities: caps, requiredCapabilities: {}},
- });
- }
-
- function endSession (id) {
- return request({
- url: `http://localhost:8181/wd/hub/session/${id}`,
- method: 'DELETE',
- json: true,
- simple: false
- });
+ return startSession(caps);
}
d.findElement = function () {
@@ -80,13 +93,13 @@ function baseDriverE2ETests (DriverClass, defaultCaps = {}) {
}.bind(d);
it('should set a default commandTimeout', async () => {
- let newSession = await startSession();
+ let newSession = await startTimeoutSession();
d.newCommandTimeoutMs.should.be.above(0);
await endSession(newSession.sessionId);
});
it('should timeout on commands using commandTimeout cap', async () => {
- let newSession = await startSession(0.25);
+ let newSession = await startTimeoutSession(0.25);
await request({
url: `http://localhost:8181/wd/hub/session/${d.sessionId}/element`,
@@ -107,7 +120,7 @@ function baseDriverE2ETests (DriverClass, defaultCaps = {}) {
});
it('should not timeout with commandTimeout of false', async () => {
- let newSession = await startSession(0.1);
+ let newSession = await startTimeoutSession(0.1);
let start = Date.now();
let res = await request({
url: `http://localhost:8181/wd/hub/session/${d.sessionId}/elements`,
@@ -121,7 +134,7 @@ function baseDriverE2ETests (DriverClass, defaultCaps = {}) {
it('should not timeout with commandTimeout of 0', async () => {
d.newCommandTimeoutMs = 2;
- let newSession = await startSession(0);
+ let newSession = await startTimeoutSession(0);
await request({
url: `http://localhost:8181/wd/hub/session/${d.sessionId}/element`,
@@ -143,7 +156,7 @@ function baseDriverE2ETests (DriverClass, defaultCaps = {}) {
});
it('should not timeout if its just the command taking awhile', async () => {
- let newSession = await startSession(0.25);
+ let newSession = await startTimeoutSession(0.25);
await request({
url: `http://localhost:8181/wd/hub/session/${d.sessionId}/element`,
method: 'POST',
@@ -164,7 +177,7 @@ function baseDriverE2ETests (DriverClass, defaultCaps = {}) {
it('should not have a timer running before or after a session', async () => {
should.not.exist(d.noCommandTimer);
- let newSession = await startSession(0.25);
+ let newSession = await startTimeoutSession(0.25);
newSession.sessionId.should.equal(d.sessionId);
should.exist(d.noCommandTimer);
await endSession(newSession.sessionId);
@@ -212,6 +225,26 @@ function baseDriverE2ETests (DriverClass, defaultCaps = {}) {
});
});
+ describe('event timings', () => {
+ it('should not add timings if not using opt-in cap', async () => {
+ let session = await startSession(defaultCaps);
+ let res = await getSession(session.sessionId);
+ should.not.exist(res.events);
+ await endSession(session.sessionId);
+ });
+ it('should add start session timings', async () => {
+ let caps = Object.assign({}, defaultCaps, {eventTimings: true});
+ let session = await startSession(caps);
+ let res = (await getSession(session.sessionId)).value;
+ should.exist(res.events);
+ should.exist(res.events.newSessionRequested);
+ should.exist(res.events.newSessionStarted);
+ res.events.newSessionRequested[0].should.be.a('number');
+ res.events.newSessionStarted[0].should.be.a('number');
+ await endSession(session.sessionId);
+ });
+ });
+
});
}

MODIFY
test/basedriver/driver-tests.js
test/basedriver/driver-tests.js
@@ -264,6 +264,76 @@ function baseDriverUnitTests (DriverClass, defaultCaps = {}) {
});
});
});
+
+ describe('event timing framework', () => {
+ let beforeStartTime;
+ beforeEach(async () => {
+ beforeStartTime = Date.now();
+ d.shouldValidateCaps = false;
+ await d.executeCommand('createSession', [defaultCaps]);
+ });
+ describe('#eventHistory', () => {
+ it('should have an eventHistory property', () => {
+ should.exist(d.eventHistory);
+ should.exist(d.eventHistory.commands);
+ });
+
+ it('should have a session start timing after session start', () => {
+ let {newSessionRequested, newSessionStarted} = d.eventHistory;
+ newSessionRequested.should.have.length(1);
+ newSessionStarted.should.have.length(1);
+ newSessionRequested[0].should.be.a('number');
+ newSessionStarted[0].should.be.a('number');
+ (newSessionRequested[0] >= beforeStartTime).should.be.true;
+ (newSessionStarted[0] >= newSessionRequested[0]).should.be.true;
+ });
+
+ it('should include a commands list', async () => {
+ await d.executeCommand('getStatus', []);
+ d.eventHistory.commands.length.should.equal(2);
+ d.eventHistory.commands[1].cmd.should.equal('getStatus');
+ d.eventHistory.commands[1].startTime.should.be.a('number');
+ d.eventHistory.commands[1].endTime.should.be.a('number');
+ });
+ });
+ describe('#logEvent', () => {
+ it('should allow logging arbitrary events', () => {
+ d.logEvent('foo');
+ d.eventHistory.foo[0].should.be.a('number');
+ (d.eventHistory.foo[0] >= beforeStartTime).should.be.true;
+ });
+ it('should not allow reserved or oddly formed event names', () => {
+ (() => {
+ d.logEvent('commands');
+ }).should.throw();
+ (() => {
+ d.logEvent(1);
+ }).should.throw();
+ (() => {
+ d.logEvent({});
+ }).should.throw();
+ });
+ });
+ it('should allow logging the same event multiple times', () => {
+ d.logEvent('bar');
+ d.logEvent('bar');
+ d.eventHistory.bar.should.have.length(2);
+ d.eventHistory.bar[1].should.be.a('number');
+ (d.eventHistory.bar[1] >= d.eventHistory.bar[0]).should.be.true;
+ });
+ describe('getSession decoration', () => {
+ it('should decorate getSession response if opt-in cap is provided', async () => {
+ let res = await d.getSession();
+ should.not.exist(res.events);
+
+ d.caps.eventTimings = true;
+ res = await d.getSession();
+ should.exist(res.events);
+ should.exist(res.events.newSessionRequested);
+ res.events.newSessionRequested[0].should.be.a('number');
+ });
+ });
+ });
});
}

add event timing framework to base driver