diff options
Diffstat (limited to 'toolkit/components/telemetry/tests/unit/test_TelemetrySend.js')
| -rw-r--r-- | toolkit/components/telemetry/tests/unit/test_TelemetrySend.js | 427 |
1 files changed, 427 insertions, 0 deletions
diff --git a/toolkit/components/telemetry/tests/unit/test_TelemetrySend.js b/toolkit/components/telemetry/tests/unit/test_TelemetrySend.js new file mode 100644 index 000000000..88ff8cf44 --- /dev/null +++ b/toolkit/components/telemetry/tests/unit/test_TelemetrySend.js @@ -0,0 +1,427 @@ +/* Any copyright is dedicated to the Public Domain. + http://creativecommons.org/publicdomain/zero/1.0/ +*/ + +// This tests the public Telemetry API for submitting pings. + +"use strict"; + +Cu.import("resource://gre/modules/TelemetryController.jsm", this); +Cu.import("resource://gre/modules/TelemetrySession.jsm", this); +Cu.import("resource://gre/modules/TelemetrySend.jsm", this); +Cu.import("resource://gre/modules/TelemetryUtils.jsm", this); +Cu.import("resource://gre/modules/Services.jsm", this); +Cu.import("resource://gre/modules/Preferences.jsm", this); +Cu.import("resource://gre/modules/osfile.jsm", this); + +const PREF_TELEMETRY_SERVER = "toolkit.telemetry.server"; + +const MS_IN_A_MINUTE = 60 * 1000; + +function countPingTypes(pings) { + let countByType = new Map(); + for (let p of pings) { + countByType.set(p.type, 1 + (countByType.get(p.type) || 0)); + } + return countByType; +} + +function setPingLastModified(id, timestamp) { + const path = OS.Path.join(TelemetryStorage.pingDirectoryPath, id); + return OS.File.setDates(path, null, timestamp); +} + +// Mock out the send timer activity. +function waitForTimer() { + return new Promise(resolve => { + fakePingSendTimer((callback, timeout) => { + resolve([callback, timeout]); + }, () => {}); + }); +} + +// Allow easy faking of readable ping ids. +// This helps with debugging issues with e.g. ordering in the send logic. +function fakePingId(type, number) { + const HEAD = "93bd0011-2c8f-4e1c-bee0-"; + const TAIL = "000000000000"; + const N = String(number); + const id = HEAD + type + TAIL.slice(type.length, - N.length) + N; + fakeGeneratePingId(() => id); + return id; +} + +var checkPingsSaved = Task.async(function* (pingIds) { + let allFound = true; + for (let id of pingIds) { + const path = OS.Path.join(TelemetryStorage.pingDirectoryPath, id); + let exists = false; + try { + exists = yield OS.File.exists(path); + } catch (ex) {} + + if (!exists) { + dump("checkPingsSaved - failed to find ping: " + path + "\n"); + allFound = false; + } + } + + return allFound; +}); + +function histogramValueCount(h) { + return h.counts.reduce((a, b) => a + b); +} + +add_task(function* test_setup() { + // Trigger a proper telemetry init. + do_get_profile(true); + // Make sure we don't generate unexpected pings due to pref changes. + yield setEmptyPrefWatchlist(); + Services.prefs.setBoolPref(PREF_TELEMETRY_ENABLED, true); +}); + +// Test the ping sending logic. +add_task(function* test_sendPendingPings() { + const TYPE_PREFIX = "test-sendPendingPings-"; + const TEST_TYPE_A = TYPE_PREFIX + "A"; + const TEST_TYPE_B = TYPE_PREFIX + "B"; + + const TYPE_A_COUNT = 20; + const TYPE_B_COUNT = 5; + + let histSuccess = Telemetry.getHistogramById("TELEMETRY_SUCCESS"); + let histSendTimeSuccess = Telemetry.getHistogramById("TELEMETRY_SEND_SUCCESS"); + let histSendTimeFail = Telemetry.getHistogramById("TELEMETRY_SEND_FAILURE"); + histSuccess.clear(); + histSendTimeSuccess.clear(); + histSendTimeFail.clear(); + + // Fake a current date. + let now = TelemetryUtils.truncateToDays(new Date()); + now = fakeNow(futureDate(now, 10 * 60 * MS_IN_A_MINUTE)); + + // Enable test-mode for TelemetrySend, otherwise we won't store pending pings + // before the module is fully initialized later. + TelemetrySend.setTestModeEnabled(true); + + // Submit some pings without the server and telemetry started yet. + for (let i = 0; i < TYPE_A_COUNT; ++i) { + fakePingId("a", i); + const id = yield TelemetryController.submitExternalPing(TEST_TYPE_A, {}); + yield setPingLastModified(id, now.getTime() + (i * 1000)); + } + + Assert.equal(TelemetrySend.pendingPingCount, TYPE_A_COUNT, + "Should have correct pending ping count"); + + // Submit some more pings of a different type. + now = fakeNow(futureDate(now, 5 * MS_IN_A_MINUTE)); + for (let i = 0; i < TYPE_B_COUNT; ++i) { + fakePingId("b", i); + const id = yield TelemetryController.submitExternalPing(TEST_TYPE_B, {}); + yield setPingLastModified(id, now.getTime() + (i * 1000)); + } + + Assert.equal(TelemetrySend.pendingPingCount, TYPE_A_COUNT + TYPE_B_COUNT, + "Should have correct pending ping count"); + + Assert.deepEqual(histSuccess.snapshot().counts, [0, 0, 0], + "Should not have recorded any sending in histograms yet."); + Assert.equal(histSendTimeSuccess.snapshot().sum, 0, + "Should not have recorded any sending in histograms yet."); + Assert.equal(histSendTimeFail.snapshot().sum, 0, + "Should not have recorded any sending in histograms yet."); + + // Now enable sending to the ping server. + now = fakeNow(futureDate(now, MS_IN_A_MINUTE)); + PingServer.start(); + Preferences.set(PREF_TELEMETRY_SERVER, "http://localhost:" + PingServer.port); + + let timerPromise = waitForTimer(); + yield TelemetryController.testReset(); + let [pingSendTimerCallback, pingSendTimeout] = yield timerPromise; + Assert.ok(!!pingSendTimerCallback, "Should have a timer callback"); + + // We should have received 10 pings from the first send batch: + // 5 of type B and 5 of type A, as sending is newest-first. + // The other pings should be delayed by the 10-pings-per-minute limit. + let pings = yield PingServer.promiseNextPings(10); + Assert.equal(TelemetrySend.pendingPingCount, TYPE_A_COUNT - 5, + "Should have correct pending ping count"); + PingServer.registerPingHandler(() => Assert.ok(false, "Should not have received any pings now")); + let countByType = countPingTypes(pings); + + Assert.equal(countByType.get(TEST_TYPE_B), TYPE_B_COUNT, + "Should have received the correct amount of type B pings"); + Assert.equal(countByType.get(TEST_TYPE_A), 10 - TYPE_B_COUNT, + "Should have received the correct amount of type A pings"); + + Assert.deepEqual(histSuccess.snapshot().counts, [0, 10, 0], + "Should have recorded sending success in histograms."); + Assert.equal(histogramValueCount(histSendTimeSuccess.snapshot()), 10, + "Should have recorded successful send times in histograms."); + Assert.equal(histogramValueCount(histSendTimeFail.snapshot()), 0, + "Should not have recorded any failed sending in histograms yet."); + + // As we hit the ping send limit and still have pending pings, a send tick should + // be scheduled in a minute. + Assert.ok(!!pingSendTimerCallback, "Timer callback should be set"); + Assert.equal(pingSendTimeout, MS_IN_A_MINUTE, "Send tick timeout should be correct"); + + // Trigger the next tick - we should receive the next 10 type A pings. + PingServer.resetPingHandler(); + now = fakeNow(futureDate(now, pingSendTimeout)); + timerPromise = waitForTimer(); + pingSendTimerCallback(); + [pingSendTimerCallback, pingSendTimeout] = yield timerPromise; + + pings = yield PingServer.promiseNextPings(10); + PingServer.registerPingHandler(() => Assert.ok(false, "Should not have received any pings now")); + countByType = countPingTypes(pings); + + Assert.equal(countByType.get(TEST_TYPE_A), 10, "Should have received the correct amount of type A pings"); + + // We hit the ping send limit again and still have pending pings, a send tick should + // be scheduled in a minute. + Assert.equal(pingSendTimeout, MS_IN_A_MINUTE, "Send tick timeout should be correct"); + + // Trigger the next tick - we should receive the remaining type A pings. + PingServer.resetPingHandler(); + now = fakeNow(futureDate(now, pingSendTimeout)); + yield pingSendTimerCallback(); + + pings = yield PingServer.promiseNextPings(5); + PingServer.registerPingHandler(() => Assert.ok(false, "Should not have received any pings now")); + countByType = countPingTypes(pings); + + Assert.equal(countByType.get(TEST_TYPE_A), 5, "Should have received the correct amount of type A pings"); + + yield TelemetrySend.testWaitOnOutgoingPings(); + PingServer.resetPingHandler(); +}); + +add_task(function* test_sendDateHeader() { + fakeNow(new Date(Date.UTC(2011, 1, 1, 11, 0, 0))); + yield TelemetrySend.reset(); + + let pingId = yield TelemetryController.submitExternalPing("test-send-date-header", {}); + let req = yield PingServer.promiseNextRequest(); + let ping = decodeRequestPayload(req); + Assert.equal(req.getHeader("Date"), "Tue, 01 Feb 2011 11:00:00 GMT", + "Telemetry should send the correct Date header with requests."); + Assert.equal(ping.id, pingId, "Should have received the correct ping id."); +}); + +// Test the backoff timeout behavior after send failures. +add_task(function* test_backoffTimeout() { + const TYPE_PREFIX = "test-backoffTimeout-"; + const TEST_TYPE_C = TYPE_PREFIX + "C"; + const TEST_TYPE_D = TYPE_PREFIX + "D"; + const TEST_TYPE_E = TYPE_PREFIX + "E"; + + let histSuccess = Telemetry.getHistogramById("TELEMETRY_SUCCESS"); + let histSendTimeSuccess = Telemetry.getHistogramById("TELEMETRY_SEND_SUCCESS"); + let histSendTimeFail = Telemetry.getHistogramById("TELEMETRY_SEND_FAILURE"); + + // Failing a ping send now should trigger backoff behavior. + let now = fakeNow(2010, 1, 1, 11, 0, 0); + yield TelemetrySend.reset(); + PingServer.stop(); + + histSuccess.clear(); + histSendTimeSuccess.clear(); + histSendTimeFail.clear(); + + fakePingId("c", 0); + now = fakeNow(futureDate(now, MS_IN_A_MINUTE)); + let sendAttempts = 0; + let timerPromise = waitForTimer(); + yield TelemetryController.submitExternalPing(TEST_TYPE_C, {}); + let [pingSendTimerCallback, pingSendTimeout] = yield timerPromise; + Assert.equal(TelemetrySend.pendingPingCount, 1, "Should have one pending ping."); + ++sendAttempts; + + const MAX_BACKOFF_TIMEOUT = 120 * MS_IN_A_MINUTE; + for (let timeout = 2 * MS_IN_A_MINUTE; timeout <= MAX_BACKOFF_TIMEOUT; timeout *= 2) { + Assert.ok(!!pingSendTimerCallback, "Should have received a timer callback"); + Assert.equal(pingSendTimeout, timeout, "Send tick timeout should be correct"); + + let callback = pingSendTimerCallback; + now = fakeNow(futureDate(now, pingSendTimeout)); + timerPromise = waitForTimer(); + yield callback(); + [pingSendTimerCallback, pingSendTimeout] = yield timerPromise; + ++sendAttempts; + } + + timerPromise = waitForTimer(); + yield pingSendTimerCallback(); + [pingSendTimerCallback, pingSendTimeout] = yield timerPromise; + Assert.equal(pingSendTimeout, MAX_BACKOFF_TIMEOUT, "Tick timeout should be capped"); + ++sendAttempts; + + Assert.deepEqual(histSuccess.snapshot().counts, [sendAttempts, 0, 0], + "Should have recorded sending failure in histograms."); + Assert.equal(histSendTimeSuccess.snapshot().sum, 0, + "Should not have recorded any sending success in histograms yet."); + Assert.greater(histSendTimeFail.snapshot().sum, 0, + "Should have recorded send failure times in histograms."); + Assert.equal(histogramValueCount(histSendTimeFail.snapshot()), sendAttempts, + "Should have recorded send failure times in histograms."); + + // Submitting a new ping should reset the backoff behavior. + fakePingId("d", 0); + now = fakeNow(futureDate(now, MS_IN_A_MINUTE)); + timerPromise = waitForTimer(); + yield TelemetryController.submitExternalPing(TEST_TYPE_D, {}); + [pingSendTimerCallback, pingSendTimeout] = yield timerPromise; + Assert.equal(pingSendTimeout, 2 * MS_IN_A_MINUTE, "Send tick timeout should be correct"); + sendAttempts += 2; + + // With the server running again, we should send out the pending pings immediately + // when a new ping is submitted. + PingServer.start(); + TelemetrySend.setServer("http://localhost:" + PingServer.port); + fakePingId("e", 0); + now = fakeNow(futureDate(now, MS_IN_A_MINUTE)); + timerPromise = waitForTimer(); + yield TelemetryController.submitExternalPing(TEST_TYPE_E, {}); + + let pings = yield PingServer.promiseNextPings(3); + let countByType = countPingTypes(pings); + + Assert.equal(countByType.get(TEST_TYPE_C), 1, "Should have received the correct amount of type C pings"); + Assert.equal(countByType.get(TEST_TYPE_D), 1, "Should have received the correct amount of type D pings"); + Assert.equal(countByType.get(TEST_TYPE_E), 1, "Should have received the correct amount of type E pings"); + + yield TelemetrySend.testWaitOnOutgoingPings(); + Assert.equal(TelemetrySend.pendingPingCount, 0, "Should have no pending pings left"); + + Assert.deepEqual(histSuccess.snapshot().counts, [sendAttempts, 3, 0], + "Should have recorded sending failure in histograms."); + Assert.greater(histSendTimeSuccess.snapshot().sum, 0, + "Should have recorded sending success in histograms."); + Assert.equal(histogramValueCount(histSendTimeSuccess.snapshot()), 3, + "Should have recorded sending success in histograms."); + Assert.equal(histogramValueCount(histSendTimeFail.snapshot()), sendAttempts, + "Should have recorded send failure times in histograms."); +}); + +add_task(function* test_discardBigPings() { + const TEST_PING_TYPE = "test-ping-type"; + + let histSizeExceeded = Telemetry.getHistogramById("TELEMETRY_PING_SIZE_EXCEEDED_SEND"); + let histDiscardedSize = Telemetry.getHistogramById("TELEMETRY_DISCARDED_SEND_PINGS_SIZE_MB"); + let histSuccess = Telemetry.getHistogramById("TELEMETRY_SUCCESS"); + let histSendTimeSuccess = Telemetry.getHistogramById("TELEMETRY_SEND_SUCCESS"); + let histSendTimeFail = Telemetry.getHistogramById("TELEMETRY_SEND_FAILURE"); + for (let h of [histSizeExceeded, histDiscardedSize, histSuccess, histSendTimeSuccess, histSendTimeFail]) { + h.clear(); + } + + // Generate a 2MB string and create an oversized payload. + const OVERSIZED_PAYLOAD = {"data": generateRandomString(2 * 1024 * 1024)}; + + // Reset the histograms. + Telemetry.getHistogramById("TELEMETRY_PING_SIZE_EXCEEDED_SEND").clear(); + Telemetry.getHistogramById("TELEMETRY_DISCARDED_SEND_PINGS_SIZE_MB").clear(); + + // Submit a ping of a normal size and check that we don't count it in the histogram. + yield TelemetryController.submitExternalPing(TEST_PING_TYPE, { test: "test" }); + yield TelemetrySend.testWaitOnOutgoingPings(); + + Assert.equal(histSizeExceeded.snapshot().sum, 0, "Telemetry must report no oversized ping submitted."); + Assert.equal(histDiscardedSize.snapshot().sum, 0, "Telemetry must report no oversized pings."); + Assert.deepEqual(histSuccess.snapshot().counts, [0, 1, 0], "Should have recorded sending success."); + Assert.equal(histogramValueCount(histSendTimeSuccess.snapshot()), 1, "Should have recorded send success time."); + Assert.greater(histSendTimeSuccess.snapshot().sum, 0, "Should have recorded send success time."); + Assert.equal(histogramValueCount(histSendTimeFail.snapshot()), 0, "Should not have recorded send failure time."); + + // Submit an oversized ping and check that it gets discarded. + yield TelemetryController.submitExternalPing(TEST_PING_TYPE, OVERSIZED_PAYLOAD); + yield TelemetrySend.testWaitOnOutgoingPings(); + + Assert.equal(histSizeExceeded.snapshot().sum, 1, "Telemetry must report 1 oversized ping submitted."); + Assert.equal(histDiscardedSize.snapshot().counts[2], 1, "Telemetry must report a 2MB, oversized, ping submitted."); + Assert.deepEqual(histSuccess.snapshot().counts, [0, 1, 0], "Should have recorded sending success."); + Assert.equal(histogramValueCount(histSendTimeSuccess.snapshot()), 1, "Should have recorded send success time."); + Assert.greater(histSendTimeSuccess.snapshot().sum, 0, "Should have recorded send success time."); + Assert.equal(histogramValueCount(histSendTimeFail.snapshot()), 0, "Should not have recorded send failure time."); +}); + +add_task(function* test_evictedOnServerErrors() { + const TEST_TYPE = "test-evicted"; + + yield TelemetrySend.reset(); + + let histEvicted = Telemetry.getHistogramById("TELEMETRY_PING_EVICTED_FOR_SERVER_ERRORS"); + let histSuccess = Telemetry.getHistogramById("TELEMETRY_SUCCESS"); + let histSendTimeSuccess = Telemetry.getHistogramById("TELEMETRY_SEND_SUCCESS"); + let histSendTimeFail = Telemetry.getHistogramById("TELEMETRY_SEND_FAILURE"); + for (let h of [histEvicted, histSuccess, histSendTimeSuccess, histSendTimeFail]) { + h.clear(); + } + + // Write a custom ping handler which will return 403. This will trigger ping eviction + // on client side. + PingServer.registerPingHandler((req, res) => { + res.setStatusLine(null, 403, "Forbidden"); + res.processAsync(); + res.finish(); + }); + + // Clear the histogram and submit a ping. + let pingId = yield TelemetryController.submitExternalPing(TEST_TYPE, {}); + yield TelemetrySend.testWaitOnOutgoingPings(); + + Assert.equal(histEvicted.snapshot().sum, 1, + "Telemetry must report a ping evicted due to server errors"); + Assert.deepEqual(histSuccess.snapshot().counts, [0, 1, 0]); + Assert.equal(histogramValueCount(histSendTimeSuccess.snapshot()), 1); + Assert.greater(histSendTimeSuccess.snapshot().sum, 0); + Assert.equal(histogramValueCount(histSendTimeFail.snapshot()), 0); + + // The ping should not be persisted. + yield Assert.rejects(TelemetryStorage.loadPendingPing(pingId), "The ping must not be persisted."); + + // Reset the ping handler and submit a new ping. + PingServer.resetPingHandler(); + pingId = yield TelemetryController.submitExternalPing(TEST_TYPE, {}); + + let ping = yield PingServer.promiseNextPings(1); + Assert.equal(ping[0].id, pingId, "The correct ping must be received"); + + // We should not have updated the error histogram. + yield TelemetrySend.testWaitOnOutgoingPings(); + Assert.equal(histEvicted.snapshot().sum, 1, "Telemetry must report only one ping evicted due to server errors"); + Assert.deepEqual(histSuccess.snapshot().counts, [0, 2, 0]); + Assert.equal(histogramValueCount(histSendTimeSuccess.snapshot()), 2); + Assert.equal(histogramValueCount(histSendTimeFail.snapshot()), 0); +}); + +// Test that the current, non-persisted pending pings are properly saved on shutdown. +add_task(function* test_persistCurrentPingsOnShutdown() { + const TEST_TYPE = "test-persistCurrentPingsOnShutdown"; + const PING_COUNT = 5; + yield TelemetrySend.reset(); + PingServer.stop(); + Assert.equal(TelemetrySend.pendingPingCount, 0, "Should have no pending pings yet"); + + // Submit new pings that shouldn't be persisted yet. + let ids = []; + for (let i=0; i<5; ++i) { + ids.push(fakePingId("f", i)); + TelemetryController.submitExternalPing(TEST_TYPE, {}); + } + + Assert.equal(TelemetrySend.pendingPingCount, PING_COUNT, "Should have the correct pending ping count"); + + // Triggering a shutdown should persist the pings. + yield TelemetrySend.shutdown(); + Assert.ok((yield checkPingsSaved(ids)), "All pending pings should have been persisted"); + + // After a restart the pings should have been found when scanning. + yield TelemetrySend.reset(); + Assert.equal(TelemetrySend.pendingPingCount, PING_COUNT, "Should have the correct pending ping count"); +}); |