/* 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"); });