Skip to content

Commit

Permalink
feat: Instance ID tracking
Browse files Browse the repository at this point in the history 
Each tracked class can have an associated ID field, which defaults to
"id".  If the ID field is null or doesn't exist on the instance, a
generated ID will be assigned instead.

For a class called "Foo", the generated IDs would be of the form
"Foo_1".  Each class will have its own counters that start at 1 for
the first instance logged.  These IDs should be easy to search for in
the log window to correlate calls and events involving specific
instances.

The generated IDs will be shown in the log window in two ways:
 1. On a call or event, for the instance the log is tied to
 2. In serialized data for a call or event (arguments, return values,
    etc)

Change-Id: I189059ffda90adf8385b50325333750476cdf8f6
  • Loading branch information
@joeyparrish
joeyparrish committed Nov 8, 2021
1 parent 45cf349 commit 8d3beb1
Show file tree
Hide file tree
Showing 4 changed files with 98 additions and 20 deletions.
10 changes: 7 additions & 3 deletions eme-trace-config.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -46,8 +46,6 @@ function emeLogger(log) {
// Log to the default logger in the JS console.
TraceAnything.defaultLogger(log);

// TODO: Discuss instances and properties with xhwang before finalizing

// This is not needed and can't be easily serialized.
delete log.instance;

Expand Down Expand Up @@ -210,11 +208,15 @@ function getSerializable(obj) {
// Clone the fields of an object into serializable versions.
const clone = {};
for (const k in obj) {
if (k == '__TraceAnything__' || typeof obj[k] == 'function') {
if (k.startsWith('__TraceAnything') || typeof obj[k] == 'function') {
continue;
}
clone[k] = getSerializable(obj[k]);
}
// Make sure generated IDs get logged. Do this through a synthetic field.
if ('__TraceAnythingId__' in obj && !('id' in clone)) {
clone.autoId = obj.__TraceAnythingId__;
}
if (obj.constructor != Object) {
// If it's an object with a type, send that info, too.
return {
Expand Down Expand Up @@ -270,6 +272,8 @@ TraceAnything.traceMember(
TraceAnything.traceClass(MediaKeys, options);
TraceAnything.traceClass(MediaKeySystemAccess, options);
TraceAnything.traceClass(MediaKeySession, combineOptions(options, {
idProperty: 'sessionId',

skipProperties: options.skipProperties.concat([
// Also skip logging certain noisy properites on MediaKeySession.
'expiration',
Expand Down
17 changes: 12 additions & 5 deletions log-window.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -123,14 +123,19 @@ class EmeLogWindow {
const heading = document.createElement('h3');
li.appendChild(heading);

const title = document.createElement('div');
title.classList.add('title');
heading.appendChild(title);
heading.appendChild(document.createTextNode(' '));

const time = document.createElement('div');
time.classList.add('time');
heading.appendChild(time);
heading.appendChild(document.createElement('br'));

const instanceId = document.createElement('div');
instanceId.classList.add('instance-id');
heading.appendChild(instanceId);
heading.appendChild(document.createElement('br'));

const title = document.createElement('div');
title.classList.add('title');
heading.appendChild(title);

const timestamp = new Date(log.timestamp);
// ISO date strings look like '2021-10-21T22:54:46.629Z', which is dense a
Expand All @@ -144,6 +149,8 @@ class EmeLogWindow {
time.textContent += ` - duration: ${log.duration.toFixed(1)} ms`;
}

instanceId.textContent = log.instanceId;

const data = document.createElement('pre');
data.classList.add('data');
li.appendChild(data);
Expand Down
18 changes: 13 additions & 5 deletions log.html
View file
Original file line number Diff line number Diff line change
Expand Up @@ -30,6 +30,19 @@
display: none; /* initially hidden */
}

h3 {
padding-top: 1em;
}

.time {
display: inline-block;
}

.instance-id {
display: inline-block;
color: gray;
}

.title {
display: inline-block;
color: blue;
Expand All @@ -38,11 +51,6 @@
.title.warning {
color: red;
}

.time {
display: inline-block;
margin-left: 1em;
}
</style>
</head>
<body>
Expand Down
73 changes: 66 additions & 7 deletions trace-anything.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -43,10 +43,11 @@ class TraceAnything {
TraceAnything._shimmedClasses.set(ctor, options);

return function(...args) {
const className = ctor.name;
const log = {
timestamp: Date.now(),
type: TraceAnything.LogTypes.Constructor,
className: ctor.name,
className,
args,
};

Expand All @@ -55,6 +56,7 @@ class TraceAnything {
const traced = TraceAnything.traceObject(original, options);

log.instance = traced;
log.instanceId = TraceAnything._getId(traced, className, options);
log.result = original;
log.duration = Date.now() - log.timestamp;
options.logger(log);
Expand Down Expand Up @@ -88,6 +90,7 @@ class TraceAnything {
}

const ctor = Object.getPrototypeOf(object).constructor;
const className = ctor.name;
const traced = options.inPlace ? object : {};

// A list of all property names.
Expand Down Expand Up @@ -116,7 +119,7 @@ class TraceAnything {
continue;
}

TraceAnything._shimMember(traced, object, k, ctor.name, options);
TraceAnything._shimMember(traced, object, k, className, options);
}

traced.__TraceAnythingEvents__ = new Set();
Expand All @@ -125,15 +128,15 @@ class TraceAnything {
// Shim any "on" event listener properties.
for (const k of allProperties.filter((k) => k.startsWith('on'))) {
TraceAnything._shimEventListenerProperty(
traced, object, k, ctor.name, options);
traced, object, k, className, options);
}

// If there's an addEventListener method, we will use that to discover
// events the app is listening for that may not have a corresponding "on"
// property.
if (object.addEventListener) {
TraceAnything._shimEventListenersDynamically(
traced, object, ctor.name, options);
traced, object, className, options);
}
}

Expand All @@ -147,7 +150,7 @@ class TraceAnything {
traced.__TraceAnythingEvents__.add(eventName);

const listener = TraceAnything._shimEventListener(
object, () => {}, ctor.name, eventName, options);
object, () => {}, className, eventName, options);
traced.addEventListener(eventName, listener);
}

Expand All @@ -159,6 +162,14 @@ class TraceAnything {
// Make sure we can tell later what is shimmed already.
traced.__TraceAnything__ = true;

// We ignore the return value, but this has the side-effect of setting the
// generated ID on "traced". This call ensures that when we log this
// object as a return value, its ID will show up in the logs and can be
// correlated to later calls where it is the instance on which methods or
// events are logged. Also, this is done after all the shims are
// installed, so that we don't shim the auto-generated ID property.
TraceAnything._getId(traced, className, options);

return traced;
}

Expand Down Expand Up @@ -335,6 +346,7 @@ class TraceAnything {
timestamp: Date.now(),
type: TraceAnything.LogTypes.Method,
instance: this,
instanceId: TraceAnything._getId(this, className, options),
className,
methodName: k,
args,
Expand All @@ -361,13 +373,15 @@ class TraceAnything {

const promiseShim = new Promise((resolve, reject) => {
returnValue.then((asyncValue) => {
asyncValue = TraceAnything._shimReturnValue(asyncValue, options);

if (!options.logAsyncResultsImmediately) {
log.result = asyncValue;
log.duration = Date.now() - log.timestamp;
options.logger(log);
}

resolve(TraceAnything._shimReturnValue(asyncValue, options));
resolve(asyncValue);
}, (error) => {
if (!options.logAsyncResultsImmediately) {
delete log.result;
Expand Down Expand Up @@ -484,6 +498,7 @@ class TraceAnything {
duration: 0,
type: TraceAnything.LogTypes.Setter,
instance: traced,
instanceId: TraceAnything._getId(traced, className, options),
className,
memberName: k,
value,
Expand All @@ -500,6 +515,7 @@ class TraceAnything {
timestamp: Date.now(),
type: TraceAnything.LogTypes.Getter,
instance: traced,
instanceId: TraceAnything._getId(traced, className, options),
className,
memberName: k,
};
Expand All @@ -526,6 +542,7 @@ class TraceAnything {
timestamp: Date.now(),
type: TraceAnything.LogTypes.Setter,
instance: traced,
instanceId: TraceAnything._getId(traced, className, options),
className,
memberName: k,
};
Expand Down Expand Up @@ -567,6 +584,7 @@ class TraceAnything {
duration: 0,
type: TraceAnything.LogTypes.Event,
instance: traced,
instanceId: TraceAnything._getId(traced, className, options),
className,
eventName: `${k} Promise resolved`,
event: {
Expand All @@ -580,6 +598,7 @@ class TraceAnything {
duration: 0,
type: TraceAnything.LogTypes.Event,
instance: traced,
instanceId: TraceAnything._getId(traced, className, options),
className,
eventName: `${k} Promise rejected`,
event: {
Expand Down Expand Up @@ -745,6 +764,7 @@ class TraceAnything {
duration: 0,
type: TraceAnything.LogTypes.Event,
instance: traced,
instanceId: TraceAnything._getId(traced, className, options),
className,
eventName,
event,
Expand Down Expand Up @@ -817,6 +837,26 @@ class TraceAnything {
}
return null;
}

/**
* @param {!Object} traced The traced object.
* @param {string} className The class name.
* @param {TraceAnything.Options} options
* @return {string} The existing or newly-auto-generated ID for the object.
* @private
*/
static _getId(traced, className, options) {
if (options.idProperty && options.idProperty in traced) {
return traced[options.idProperty];
}

if (traced.__TraceAnythingId__ == null) {
let id = TraceAnything._nextGeneratedId.get(className) || 1;
TraceAnything._nextGeneratedId.set(className, id + 1);
traced.__TraceAnythingId__ = className + '_' + id;
}
return traced.__TraceAnythingId__;
}
}

/**
Expand All @@ -839,6 +879,7 @@ TraceAnything.LogTypes = {
* duration: Number,
* type: TraceAnything.LogTypes,
* instance: (!Object|undefined),
* instanceId: (string|undefined),
* message: (string|undefined),
* className: (string|undefined),
* methodName: (string|undefined),
Expand All @@ -860,6 +901,9 @@ TraceAnything.LogTypes = {
* The type of log.
* @property {(!Object|undefined)} instance
* The instance on which this method call / getter / setter / event occurred.
* @property {(string|undefined)} instanceId
* The instance ID. May be auto-generated for some types.
* See TraceAnything.Options.idProperty.
* @property {(string|undefined)} message
* A message for Warning-type logs.
* @property {(string|undefined)} className
Expand Down Expand Up @@ -894,7 +938,7 @@ TraceAnything.defaultLogger = (log) => {
// NOTE: We are not combining everything into a single string in the default
// logger, because the JS console is actually capable of printing complex
// values like objects and arrays.
let logPrefix = 'TraceAnything: ';
let logPrefix = `TraceAnything: (ID ${log.instanceId}) `;

if (log.type == TraceAnything.LogTypes.Warning) {
console.warn(logPrefix + log.message);
Expand Down Expand Up @@ -1033,6 +1077,11 @@ TraceAnything.defaultLogger = (log) => {
* static once logged. This also makes the duration of a log reflect the time
* spent waiting for the Promise to be resolved or rejected.
* By default, true.
* @property {string} idProperty
* The name of a property to use to identify instances in the logs. If null,
* or if the associated property does not exist on the object, TraceAnything
* will generate an ID automatically.
* By default, "id".
*/
TraceAnything.Options;

Expand All @@ -1057,6 +1106,7 @@ TraceAnything.defaultOptions = {
exploreResultFields: [],
logger: TraceAnything.defaultLogger,
logAsyncResultsImmediately: true,
idProperty: "id",
};

/**
Expand All @@ -1080,3 +1130,12 @@ TraceAnything._tracedElementNames = new Map();
* @private {MutationObserver}
*/
TraceAnything._newElementObserver = null;

/**
* The next ID for objects which need an ID generated for the logs.
* ID numbers are per-type, and the map is indexed by type name.
* See also TraceAnything.Options.idProperty and TraceAnything.Log.instanceId.
*
* @private {Map<string, number>}
*/
TraceAnything._nextGeneratedId = new Map();

0 comments on commit 8d3beb1

Please sign in to comment.