Skip to content

Fix custom trace event dispatch before initialization for Performance Monitoring #3850

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 7 commits into from
Oct 1, 2020
Merged

Fix custom trace event dispatch before initialization for Performance Monitoring #3850

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
7 commits
Select commit Hold shift + click to select a range
6c1ea7c
Fix custom trace event dispatch before initialization for Performance…
zijianjoy Sep 28, 2020
3284595
fix lint issue
zijianjoy Sep 28, 2020
0914a8c
stub iid
zijianjoy Sep 28, 2020
6b12ba4
Update unit test for logging trace right after initialization
Sep 28, 2020
58b32cf
Apply the same to performance-exp package
zijianjoy Sep 29, 2020
15504c9
update test name based on comments
zijianjoy Sep 30, 2020
8f7a46a
Add changeset
zijianjoy Oct 1, 2020
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
6 changes: 6 additions & 0 deletions .changeset/fifty-snakes-shout.md
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -0,0 +1,6 @@
---
'@firebase/performance': patch
'firebase': patch
---

Moved `loggingEnabled` check to wait until performance initialization finishes, thus avoid dropping custom traces right after getting `performance` object.
33 changes: 31 additions & 2 deletions packages-exp/performance-exp/src/services/perf_logger.test.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -70,7 +70,6 @@ describe('Performance Monitoring > perf_logger', () => {
}

setupApi(self);

const fakeFirebaseApp = ({
options: { appId: APP_ID }
} as unknown) as FirebaseApp;
Expand All @@ -87,7 +86,6 @@ describe('Performance Monitoring > perf_logger', () => {
stub(transportService, 'transportHandler').callsFake(mockTransportHandler);
stub(Api.prototype, 'getUrl').returns(PAGE_URL);
stub(Api.prototype, 'getTimeOrigin').returns(TIME_ORIGIN);
stub(initializationService, 'isPerfInitialized').returns(true);
stub(attributeUtils, 'getEffectiveConnectionType').returns(
EFFECTIVE_CONNECTION_TYPE
);
Expand All @@ -98,6 +96,29 @@ describe('Performance Monitoring > perf_logger', () => {
});

describe('logTrace', () => {
it('will not drop custom events sent before initialization finishes', async () => {
getIidStub.returns(IID);
stub(attributeUtils, 'getVisibilityState').returns(VISIBILITY_STATE);
stub(initializationService, 'isPerfInitialized').returns(false);

// Simulates logging being enabled after initialization completes.
const initializationPromise = Promise.resolve().then(() => {
SettingsService.getInstance().loggingEnabled = true;
SettingsService.getInstance().logTraceAfterSampling = true;
});
stub(initializationService, 'getInitializationPromise').returns(
initializationPromise
);

const trace = new Trace(performanceController, TRACE_NAME);
trace.record(START_TIME, DURATION);
await initializationPromise.then(() => {
clock.tick(1);
});

expect(addToQueueStub).to.be.called;
});

it('creates, serializes and sends a trace to transport service', () => {
const EXPECTED_TRACE_MESSAGE =
`{` +
Expand All @@ -107,6 +128,7 @@ describe('Performance Monitoring > perf_logger', () => {
"counters":{"counter1":3},"custom_attributes":{"attr":"val"}}}`;
getIidStub.returns(IID);
stub(attributeUtils, 'getVisibilityState').returns(VISIBILITY_STATE);
stub(initializationService, 'isPerfInitialized').returns(true);
SettingsService.getInstance().loggingEnabled = true;
SettingsService.getInstance().logTraceAfterSampling = true;
const trace = new Trace(performanceController, TRACE_NAME);
Expand All @@ -124,6 +146,7 @@ describe('Performance Monitoring > perf_logger', () => {
it('does not log an event if cookies are disabled in the browser', () => {
stub(Api.prototype, 'requiredApisAvailable').returns(false);
stub(attributeUtils, 'getVisibilityState').returns(VISIBILITY_STATE);
stub(initializationService, 'isPerfInitialized').returns(true);
const trace = new Trace(performanceController, TRACE_NAME);
trace.record(START_TIME, DURATION);
clock.tick(1);
Expand All @@ -145,6 +168,7 @@ describe('Performance Monitoring > perf_logger', () => {
"counter31":31,"counter32":32}}}`;
getIidStub.returns(IID);
stub(attributeUtils, 'getVisibilityState').returns(VISIBILITY_STATE);
stub(initializationService, 'isPerfInitialized').returns(true);
SettingsService.getInstance().loggingEnabled = true;
SettingsService.getInstance().logTraceAfterSampling = true;
const trace = new Trace(performanceController, TRACE_NAME);
Expand All @@ -169,6 +193,7 @@ describe('Performance Monitoring > perf_logger', () => {
"custom_attributes":{"attr1":"val1","attr2":"val2","attr3":"val3","attr4":"val4","attr5":"val5"}}}`;
getIidStub.returns(IID);
stub(attributeUtils, 'getVisibilityState').returns(VISIBILITY_STATE);
stub(initializationService, 'isPerfInitialized').returns(true);
SettingsService.getInstance().loggingEnabled = true;
SettingsService.getInstance().logTraceAfterSampling = true;
const trace = new Trace(performanceController, TRACE_NAME);
Expand Down Expand Up @@ -198,6 +223,7 @@ describe('Performance Monitoring > perf_logger', () => {
"client_start_time_us":${flooredStartTime},"duration_us":${DURATION * 1000},\
"counters":{"domInteractive":10000,"domContentLoadedEventEnd":20000,"loadEventEnd":10000,\
"_fp":40000,"_fcp":50000,"_fid":90000}}}`;
stub(initializationService, 'isPerfInitialized').returns(true);
getIidStub.returns(IID);
SettingsService.getInstance().loggingEnabled = true;
SettingsService.getInstance().logTraceAfterSampling = true;
Expand Down Expand Up @@ -303,6 +329,7 @@ describe('Performance Monitoring > perf_logger', () => {
"response_payload_bytes":${RESOURCE_PERFORMANCE_ENTRY.transferSize},\
"client_start_time_us":${START_TIME},\
"time_to_response_completed_us":${TIME_TO_RESPONSE_COMPLETED}}}`;
stub(initializationService, 'isPerfInitialized').returns(true);
getIidStub.returns(IID);
stub(attributeUtils, 'getVisibilityState').returns(VISIBILITY_STATE);
SettingsService.getInstance().loggingEnabled = true;
Expand Down Expand Up @@ -347,6 +374,7 @@ describe('Performance Monitoring > perf_logger', () => {
workerStart: 0,
toJSON: () => {}
};
stub(initializationService, 'isPerfInitialized').returns(true);
getIidStub.returns(IID);
SettingsService.getInstance().loggingEnabled = true;
SettingsService.getInstance().logNetworkAfterSampling = true;
Expand Down Expand Up @@ -390,6 +418,7 @@ describe('Performance Monitoring > perf_logger', () => {
workerStart: 0,
toJSON: () => {}
};
stub(initializationService, 'isPerfInitialized').returns(true);
getIidStub.returns(IID);
SettingsService.getInstance().loggingEnabled = true;
SettingsService.getInstance().logNetworkAfterSampling = true;
Expand Down
21 changes: 12 additions & 9 deletions packages-exp/performance-exp/src/services/perf_logger.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -122,13 +122,6 @@ export function logTrace(trace: Trace): void {
return;
}

if (
!settingsService.loggingEnabled ||
!settingsService.logTraceAfterSampling
) {
return;
}

if (isPerfInitialized()) {
sendTraceLog(trace);
} else {
Expand All @@ -142,9 +135,19 @@ export function logTrace(trace: Trace): void {
}

function sendTraceLog(trace: Trace): void {
if (getIid()) {
setTimeout(() => sendLog(trace, ResourceType.Trace), 0);
if (!getIid()) {
return;
}

const settingsService = SettingsService.getInstance();
if (
!settingsService.loggingEnabled ||
!settingsService.logTraceAfterSampling
) {
return;
}

setTimeout(() => sendLog(trace, ResourceType.Trace), 0);
}

export function logNetworkRequest(networkRequest: NetworkRequest): void {
Expand Down
32 changes: 31 additions & 1 deletion packages/performance/src/services/perf_logger.test.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -75,7 +75,6 @@ describe('Performance Monitoring > perf_logger', () => {
stub(transportService, 'transportHandler').callsFake(mockTransportHandler);
stub(Api.prototype, 'getUrl').returns(PAGE_URL);
stub(Api.prototype, 'getTimeOrigin').returns(TIME_ORIGIN);
stub(initializationService, 'isPerfInitialized').returns(true);
stub(attributeUtils, 'getEffectiveConnectionType').returns(
EFFECTIVE_CONNECTION_TYPE
);
Expand All @@ -89,6 +88,29 @@ describe('Performance Monitoring > perf_logger', () => {
});

describe('logTrace', () => {
it('will not drop custom events sent before initialization finishes', async () => {
getIidStub.returns(IID);
stub(attributeUtils, 'getVisibilityState').returns(VISIBILITY_STATE);
stub(initializationService, 'isPerfInitialized').returns(false);

// Simulates logging being enabled after initialization completes.
const initializationPromise = Promise.resolve().then(() => {
SettingsService.getInstance().loggingEnabled = true;
SettingsService.getInstance().logTraceAfterSampling = true;
});
stub(initializationService, 'getInitializationPromise').returns(
initializationPromise
);

const trace = new Trace(TRACE_NAME);
trace.record(START_TIME, DURATION);
await initializationPromise.then(() => {
clock.tick(1);
});

expect(addToQueueStub).to.be.called;
});

it('creates, serializes and sends a trace to transport service', () => {
const EXPECTED_TRACE_MESSAGE =
`{` +
Expand All @@ -98,6 +120,7 @@ describe('Performance Monitoring > perf_logger', () => {
"counters":{"counter1":3},"custom_attributes":{"attr":"val"}}}`;
getIidStub.returns(IID);
stub(attributeUtils, 'getVisibilityState').returns(VISIBILITY_STATE);
stub(initializationService, 'isPerfInitialized').returns(true);
SettingsService.getInstance().loggingEnabled = true;
SettingsService.getInstance().logTraceAfterSampling = true;
const trace = new Trace(TRACE_NAME);
Expand All @@ -115,6 +138,7 @@ describe('Performance Monitoring > perf_logger', () => {
it('does not log an event if cookies are disabled in the browser', () => {
stub(Api.prototype, 'requiredApisAvailable').returns(false);
stub(attributeUtils, 'getVisibilityState').returns(VISIBILITY_STATE);
stub(initializationService, 'isPerfInitialized').returns(true);
const trace = new Trace(TRACE_NAME);
trace.record(START_TIME, DURATION);
clock.tick(1);
Expand All @@ -136,6 +160,7 @@ describe('Performance Monitoring > perf_logger', () => {
"counter31":31,"counter32":32}}}`;
getIidStub.returns(IID);
stub(attributeUtils, 'getVisibilityState').returns(VISIBILITY_STATE);
stub(initializationService, 'isPerfInitialized').returns(true);
SettingsService.getInstance().loggingEnabled = true;
SettingsService.getInstance().logTraceAfterSampling = true;
const trace = new Trace(TRACE_NAME);
Expand All @@ -160,6 +185,7 @@ describe('Performance Monitoring > perf_logger', () => {
"custom_attributes":{"attr1":"val1","attr2":"val2","attr3":"val3","attr4":"val4","attr5":"val5"}}}`;
getIidStub.returns(IID);
stub(attributeUtils, 'getVisibilityState').returns(VISIBILITY_STATE);
stub(initializationService, 'isPerfInitialized').returns(true);
SettingsService.getInstance().loggingEnabled = true;
SettingsService.getInstance().logTraceAfterSampling = true;
const trace = new Trace(TRACE_NAME);
Expand Down Expand Up @@ -189,6 +215,7 @@ describe('Performance Monitoring > perf_logger', () => {
"client_start_time_us":${flooredStartTime},"duration_us":${DURATION * 1000},\
"counters":{"domInteractive":10000,"domContentLoadedEventEnd":20000,"loadEventEnd":10000,\
"_fp":40000,"_fcp":50000,"_fid":90000}}}`;
stub(initializationService, 'isPerfInitialized').returns(true);
getIidStub.returns(IID);
SettingsService.getInstance().loggingEnabled = true;
SettingsService.getInstance().logTraceAfterSampling = true;
Expand Down Expand Up @@ -289,6 +316,7 @@ describe('Performance Monitoring > perf_logger', () => {
"response_payload_bytes":${RESOURCE_PERFORMANCE_ENTRY.transferSize},\
"client_start_time_us":${START_TIME},\
"time_to_response_completed_us":${TIME_TO_RESPONSE_COMPLETED}}}`;
stub(initializationService, 'isPerfInitialized').returns(true);
getIidStub.returns(IID);
stub(attributeUtils, 'getVisibilityState').returns(VISIBILITY_STATE);
SettingsService.getInstance().loggingEnabled = true;
Expand Down Expand Up @@ -330,6 +358,7 @@ describe('Performance Monitoring > perf_logger', () => {
workerStart: 0,
toJSON: () => {}
};
stub(initializationService, 'isPerfInitialized').returns(true);
getIidStub.returns(IID);
SettingsService.getInstance().loggingEnabled = true;
SettingsService.getInstance().logNetworkAfterSampling = true;
Expand Down Expand Up @@ -370,6 +399,7 @@ describe('Performance Monitoring > perf_logger', () => {
workerStart: 0,
toJSON: () => {}
};
stub(initializationService, 'isPerfInitialized').returns(true);
getIidStub.returns(IID);
SettingsService.getInstance().loggingEnabled = true;
SettingsService.getInstance().logNetworkAfterSampling = true;
Expand Down
22 changes: 13 additions & 9 deletions packages/performance/src/services/perf_logger.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -120,18 +120,12 @@ export function logTrace(trace: Trace): void {
return;
}

if (
!settingsService.loggingEnabled ||
!settingsService.logTraceAfterSampling
) {
return;
}

if (isPerfInitialized()) {
sendTraceLog(trace);
} else {
// Custom traces can be used before the initialization but logging
// should wait until after.

getInitializationPromise().then(
() => sendTraceLog(trace),
() => sendTraceLog(trace)
Expand All @@ -140,9 +134,19 @@ export function logTrace(trace: Trace): void {
}

function sendTraceLog(trace: Trace): void {
if (getIid()) {
setTimeout(() => sendLog(trace, ResourceType.Trace), 0);
if (!getIid()) {
return;
}

const settingsService = SettingsService.getInstance();
if (
!settingsService.loggingEnabled ||
!settingsService.logTraceAfterSampling
) {
return;
}

setTimeout(() => sendLog(trace, ResourceType.Trace), 0);
}

export function logNetworkRequest(networkRequest: NetworkRequest): void {
Expand Down