Skip to content

Commit 48b0b0f

Browse files
zijianjoyalikn
zijianjoy
and
alikn
authored
Fix custom trace event dispatch before initialization for Performance Monitoring (#3850)
 Co-authored-by: alikn <[email protected]>
1 parent a831aec commit 48b0b0f

File tree

5 files changed

+93
-21
lines changed

5 files changed

+93
-21
lines changed

‎.changeset/fifty-snakes-shout.md

+6
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,6 @@
1+
---
2+
'@firebase/performance': patch
3+
'firebase': patch
4+
---
5+
6+
Moved `loggingEnabled` check to wait until performance initialization finishes, thus avoid dropping custom traces right after getting `performance` object.

‎packages-exp/performance-exp/src/services/perf_logger.test.ts

+31-2
Original file line numberDiff line numberDiff line change
@@ -70,7 +70,6 @@ describe('Performance Monitoring > perf_logger', () => {
7070
}
7171

7272
setupApi(self);
73-
7473
const fakeFirebaseApp = ({
7574
options: { appId: APP_ID }
7675
} as unknown) as FirebaseApp;
@@ -87,7 +86,6 @@ describe('Performance Monitoring > perf_logger', () => {
8786
stub(transportService, 'transportHandler').callsFake(mockTransportHandler);
8887
stub(Api.prototype, 'getUrl').returns(PAGE_URL);
8988
stub(Api.prototype, 'getTimeOrigin').returns(TIME_ORIGIN);
90-
stub(initializationService, 'isPerfInitialized').returns(true);
9189
stub(attributeUtils, 'getEffectiveConnectionType').returns(
9290
EFFECTIVE_CONNECTION_TYPE
9391
);
@@ -98,6 +96,29 @@ describe('Performance Monitoring > perf_logger', () => {
9896
});
9997

10098
describe('logTrace', () => {
99+
it('will not drop custom events sent before initialization finishes', async () => {
100+
getIidStub.returns(IID);
101+
stub(attributeUtils, 'getVisibilityState').returns(VISIBILITY_STATE);
102+
stub(initializationService, 'isPerfInitialized').returns(false);
103+
104+
// Simulates logging being enabled after initialization completes.
105+
const initializationPromise = Promise.resolve().then(() => {
106+
SettingsService.getInstance().loggingEnabled = true;
107+
SettingsService.getInstance().logTraceAfterSampling = true;
108+
});
109+
stub(initializationService, 'getInitializationPromise').returns(
110+
initializationPromise
111+
);
112+
113+
const trace = new Trace(performanceController, TRACE_NAME);
114+
trace.record(START_TIME, DURATION);
115+
await initializationPromise.then(() => {
116+
clock.tick(1);
117+
});
118+
119+
expect(addToQueueStub).to.be.called;
120+
});
121+
101122
it('creates, serializes and sends a trace to transport service', () => {
102123
const EXPECTED_TRACE_MESSAGE =
103124
`{` +
@@ -107,6 +128,7 @@ describe('Performance Monitoring > perf_logger', () => {
107128
"counters":{"counter1":3},"custom_attributes":{"attr":"val"}}}`;
108129
getIidStub.returns(IID);
109130
stub(attributeUtils, 'getVisibilityState').returns(VISIBILITY_STATE);
131+
stub(initializationService, 'isPerfInitialized').returns(true);
110132
SettingsService.getInstance().loggingEnabled = true;
111133
SettingsService.getInstance().logTraceAfterSampling = true;
112134
const trace = new Trace(performanceController, TRACE_NAME);
@@ -124,6 +146,7 @@ describe('Performance Monitoring > perf_logger', () => {
124146
it('does not log an event if cookies are disabled in the browser', () => {
125147
stub(Api.prototype, 'requiredApisAvailable').returns(false);
126148
stub(attributeUtils, 'getVisibilityState').returns(VISIBILITY_STATE);
149+
stub(initializationService, 'isPerfInitialized').returns(true);
127150
const trace = new Trace(performanceController, TRACE_NAME);
128151
trace.record(START_TIME, DURATION);
129152
clock.tick(1);
@@ -145,6 +168,7 @@ describe('Performance Monitoring > perf_logger', () => {
145168
"counter31":31,"counter32":32}}}`;
146169
getIidStub.returns(IID);
147170
stub(attributeUtils, 'getVisibilityState').returns(VISIBILITY_STATE);
171+
stub(initializationService, 'isPerfInitialized').returns(true);
148172
SettingsService.getInstance().loggingEnabled = true;
149173
SettingsService.getInstance().logTraceAfterSampling = true;
150174
const trace = new Trace(performanceController, TRACE_NAME);
@@ -169,6 +193,7 @@ describe('Performance Monitoring > perf_logger', () => {
169193
"custom_attributes":{"attr1":"val1","attr2":"val2","attr3":"val3","attr4":"val4","attr5":"val5"}}}`;
170194
getIidStub.returns(IID);
171195
stub(attributeUtils, 'getVisibilityState').returns(VISIBILITY_STATE);
196+
stub(initializationService, 'isPerfInitialized').returns(true);
172197
SettingsService.getInstance().loggingEnabled = true;
173198
SettingsService.getInstance().logTraceAfterSampling = true;
174199
const trace = new Trace(performanceController, TRACE_NAME);
@@ -198,6 +223,7 @@ describe('Performance Monitoring > perf_logger', () => {
198223
"client_start_time_us":${flooredStartTime},"duration_us":${DURATION * 1000},\
199224
"counters":{"domInteractive":10000,"domContentLoadedEventEnd":20000,"loadEventEnd":10000,\
200225
"_fp":40000,"_fcp":50000,"_fid":90000}}}`;
226+
stub(initializationService, 'isPerfInitialized').returns(true);
201227
getIidStub.returns(IID);
202228
SettingsService.getInstance().loggingEnabled = true;
203229
SettingsService.getInstance().logTraceAfterSampling = true;
@@ -303,6 +329,7 @@ describe('Performance Monitoring > perf_logger', () => {
303329
"response_payload_bytes":${RESOURCE_PERFORMANCE_ENTRY.transferSize},\
304330
"client_start_time_us":${START_TIME},\
305331
"time_to_response_completed_us":${TIME_TO_RESPONSE_COMPLETED}}}`;
332+
stub(initializationService, 'isPerfInitialized').returns(true);
306333
getIidStub.returns(IID);
307334
stub(attributeUtils, 'getVisibilityState').returns(VISIBILITY_STATE);
308335
SettingsService.getInstance().loggingEnabled = true;
@@ -347,6 +374,7 @@ describe('Performance Monitoring > perf_logger', () => {
347374
workerStart: 0,
348375
toJSON: () => {}
349376
};
377+
stub(initializationService, 'isPerfInitialized').returns(true);
350378
getIidStub.returns(IID);
351379
SettingsService.getInstance().loggingEnabled = true;
352380
SettingsService.getInstance().logNetworkAfterSampling = true;
@@ -390,6 +418,7 @@ describe('Performance Monitoring > perf_logger', () => {
390418
workerStart: 0,
391419
toJSON: () => {}
392420
};
421+
stub(initializationService, 'isPerfInitialized').returns(true);
393422
getIidStub.returns(IID);
394423
SettingsService.getInstance().loggingEnabled = true;
395424
SettingsService.getInstance().logNetworkAfterSampling = true;

‎packages-exp/performance-exp/src/services/perf_logger.ts

+12-9
Original file line numberDiff line numberDiff line change
@@ -122,13 +122,6 @@ export function logTrace(trace: Trace): void {
122122
return;
123123
}
124124

125-
if (
126-
!settingsService.loggingEnabled ||
127-
!settingsService.logTraceAfterSampling
128-
) {
129-
return;
130-
}
131-
132125
if (isPerfInitialized()) {
133126
sendTraceLog(trace);
134127
} else {
@@ -142,9 +135,19 @@ export function logTrace(trace: Trace): void {
142135
}
143136

144137
function sendTraceLog(trace: Trace): void {
145-
if (getIid()) {
146-
setTimeout(() => sendLog(trace, ResourceType.Trace), 0);
138+
if (!getIid()) {
139+
return;
147140
}
141+
142+
const settingsService = SettingsService.getInstance();
143+
if (
144+
!settingsService.loggingEnabled ||
145+
!settingsService.logTraceAfterSampling
146+
) {
147+
return;
148+
}
149+
150+
setTimeout(() => sendLog(trace, ResourceType.Trace), 0);
148151
}
149152

150153
export function logNetworkRequest(networkRequest: NetworkRequest): void {

‎packages/performance/src/services/perf_logger.test.ts

+31-1
Original file line numberDiff line numberDiff line change
@@ -75,7 +75,6 @@ describe('Performance Monitoring > perf_logger', () => {
7575
stub(transportService, 'transportHandler').callsFake(mockTransportHandler);
7676
stub(Api.prototype, 'getUrl').returns(PAGE_URL);
7777
stub(Api.prototype, 'getTimeOrigin').returns(TIME_ORIGIN);
78-
stub(initializationService, 'isPerfInitialized').returns(true);
7978
stub(attributeUtils, 'getEffectiveConnectionType').returns(
8079
EFFECTIVE_CONNECTION_TYPE
8180
);
@@ -89,6 +88,29 @@ describe('Performance Monitoring > perf_logger', () => {
8988
});
9089

9190
describe('logTrace', () => {
91+
it('will not drop custom events sent before initialization finishes', async () => {
92+
getIidStub.returns(IID);
93+
stub(attributeUtils, 'getVisibilityState').returns(VISIBILITY_STATE);
94+
stub(initializationService, 'isPerfInitialized').returns(false);
95+
96+
// Simulates logging being enabled after initialization completes.
97+
const initializationPromise = Promise.resolve().then(() => {
98+
SettingsService.getInstance().loggingEnabled = true;
99+
SettingsService.getInstance().logTraceAfterSampling = true;
100+
});
101+
stub(initializationService, 'getInitializationPromise').returns(
102+
initializationPromise
103+
);
104+
105+
const trace = new Trace(TRACE_NAME);
106+
trace.record(START_TIME, DURATION);
107+
await initializationPromise.then(() => {
108+
clock.tick(1);
109+
});
110+
111+
expect(addToQueueStub).to.be.called;
112+
});
113+
92114
it('creates, serializes and sends a trace to transport service', () => {
93115
const EXPECTED_TRACE_MESSAGE =
94116
`{` +
@@ -98,6 +120,7 @@ describe('Performance Monitoring > perf_logger', () => {
98120
"counters":{"counter1":3},"custom_attributes":{"attr":"val"}}}`;
99121
getIidStub.returns(IID);
100122
stub(attributeUtils, 'getVisibilityState').returns(VISIBILITY_STATE);
123+
stub(initializationService, 'isPerfInitialized').returns(true);
101124
SettingsService.getInstance().loggingEnabled = true;
102125
SettingsService.getInstance().logTraceAfterSampling = true;
103126
const trace = new Trace(TRACE_NAME);
@@ -115,6 +138,7 @@ describe('Performance Monitoring > perf_logger', () => {
115138
it('does not log an event if cookies are disabled in the browser', () => {
116139
stub(Api.prototype, 'requiredApisAvailable').returns(false);
117140
stub(attributeUtils, 'getVisibilityState').returns(VISIBILITY_STATE);
141+
stub(initializationService, 'isPerfInitialized').returns(true);
118142
const trace = new Trace(TRACE_NAME);
119143
trace.record(START_TIME, DURATION);
120144
clock.tick(1);
@@ -136,6 +160,7 @@ describe('Performance Monitoring > perf_logger', () => {
136160
"counter31":31,"counter32":32}}}`;
137161
getIidStub.returns(IID);
138162
stub(attributeUtils, 'getVisibilityState').returns(VISIBILITY_STATE);
163+
stub(initializationService, 'isPerfInitialized').returns(true);
139164
SettingsService.getInstance().loggingEnabled = true;
140165
SettingsService.getInstance().logTraceAfterSampling = true;
141166
const trace = new Trace(TRACE_NAME);
@@ -160,6 +185,7 @@ describe('Performance Monitoring > perf_logger', () => {
160185
"custom_attributes":{"attr1":"val1","attr2":"val2","attr3":"val3","attr4":"val4","attr5":"val5"}}}`;
161186
getIidStub.returns(IID);
162187
stub(attributeUtils, 'getVisibilityState').returns(VISIBILITY_STATE);
188+
stub(initializationService, 'isPerfInitialized').returns(true);
163189
SettingsService.getInstance().loggingEnabled = true;
164190
SettingsService.getInstance().logTraceAfterSampling = true;
165191
const trace = new Trace(TRACE_NAME);
@@ -189,6 +215,7 @@ describe('Performance Monitoring > perf_logger', () => {
189215
"client_start_time_us":${flooredStartTime},"duration_us":${DURATION * 1000},\
190216
"counters":{"domInteractive":10000,"domContentLoadedEventEnd":20000,"loadEventEnd":10000,\
191217
"_fp":40000,"_fcp":50000,"_fid":90000}}}`;
218+
stub(initializationService, 'isPerfInitialized').returns(true);
192219
getIidStub.returns(IID);
193220
SettingsService.getInstance().loggingEnabled = true;
194221
SettingsService.getInstance().logTraceAfterSampling = true;
@@ -289,6 +316,7 @@ describe('Performance Monitoring > perf_logger', () => {
289316
"response_payload_bytes":${RESOURCE_PERFORMANCE_ENTRY.transferSize},\
290317
"client_start_time_us":${START_TIME},\
291318
"time_to_response_completed_us":${TIME_TO_RESPONSE_COMPLETED}}}`;
319+
stub(initializationService, 'isPerfInitialized').returns(true);
292320
getIidStub.returns(IID);
293321
stub(attributeUtils, 'getVisibilityState').returns(VISIBILITY_STATE);
294322
SettingsService.getInstance().loggingEnabled = true;
@@ -330,6 +358,7 @@ describe('Performance Monitoring > perf_logger', () => {
330358
workerStart: 0,
331359
toJSON: () => {}
332360
};
361+
stub(initializationService, 'isPerfInitialized').returns(true);
333362
getIidStub.returns(IID);
334363
SettingsService.getInstance().loggingEnabled = true;
335364
SettingsService.getInstance().logNetworkAfterSampling = true;
@@ -370,6 +399,7 @@ describe('Performance Monitoring > perf_logger', () => {
370399
workerStart: 0,
371400
toJSON: () => {}
372401
};
402+
stub(initializationService, 'isPerfInitialized').returns(true);
373403
getIidStub.returns(IID);
374404
SettingsService.getInstance().loggingEnabled = true;
375405
SettingsService.getInstance().logNetworkAfterSampling = true;

‎packages/performance/src/services/perf_logger.ts

+13-9
Original file line numberDiff line numberDiff line change
@@ -120,18 +120,12 @@ export function logTrace(trace: Trace): void {
120120
return;
121121
}
122122

123-
if (
124-
!settingsService.loggingEnabled ||
125-
!settingsService.logTraceAfterSampling
126-
) {
127-
return;
128-
}
129-
130123
if (isPerfInitialized()) {
131124
sendTraceLog(trace);
132125
} else {
133126
// Custom traces can be used before the initialization but logging
134127
// should wait until after.
128+
135129
getInitializationPromise().then(
136130
() => sendTraceLog(trace),
137131
() => sendTraceLog(trace)
@@ -140,9 +134,19 @@ export function logTrace(trace: Trace): void {
140134
}
141135

142136
function sendTraceLog(trace: Trace): void {
143-
if (getIid()) {
144-
setTimeout(() => sendLog(trace, ResourceType.Trace), 0);
137+
if (!getIid()) {
138+
return;
145139
}
140+
141+
const settingsService = SettingsService.getInstance();
142+
if (
143+
!settingsService.loggingEnabled ||
144+
!settingsService.logTraceAfterSampling
145+
) {
146+
return;
147+
}
148+
149+
setTimeout(() => sendLog(trace, ResourceType.Trace), 0);
146150
}
147151

148152
export function logNetworkRequest(networkRequest: NetworkRequest): void {

0 commit comments

Comments
 (0)