Closed Bug 1000719 Opened 10 years ago Closed 8 years ago

Intermittent experiments/test/xpcshell/test_telemetry.js | Telemetry log should have 2 entries. - 1 == 2 - See following stack:

Categories

(Toolkit :: Telemetry, defect)

x86
Windows 8
defect
Not set
normal

Tracking

()

RESOLVED WORKSFORME

People

(Reporter: philor, Unassigned)

Details

(Keywords: intermittent-failure, Whiteboard: [leave open])

Attachments

(1 file)

https://tbpl.mozilla.org/php/getParsedLog.php?id=38371494&tree=Fx-Team
WINNT 6.2 fx-team debug test xpcshell on 2014-04-23 20:28:01 PDT for push 3544b8716eb1
slave: t-w864-ix-092

21:09:27     INFO -  Retrying tests that failed when run in parallel.
21:09:27     INFO -  TEST-INFO | C:\slave\test\build\tests\xpcshell\tests\browser\experiments\test\xpcshell\test_telemetry.js | running test ...
21:09:32  WARNING -  TEST-UNEXPECTED-FAIL | C:\slave\test\build\tests\xpcshell\tests\browser\experiments\test\xpcshell\test_telemetry.js | test failed (with xpcshell return code: 0), see following log:
21:09:32     INFO -  >>>>>>>
21:09:32     INFO -  [6908] WARNING: Couldn't get the user appdata directory. Crash events may not be produced.: file c:\\builds\\moz2_slave\\fx-team-w32-d-0000000000000000\\build\\toolkit\\crashreporter\\nsExceptionHandler.cpp, line 2109
21:09:32     INFO -  TEST-INFO | (xpcshell/head.js) | test MAIN run_test pending (1)
21:09:32     INFO -  TEST-INFO | (xpcshell/head.js) | test run_next_test 0 pending (2)
21:09:32     INFO -  TEST-INFO | (xpcshell/head.js) | test MAIN run_test finished (2)
21:09:32     INFO -  TEST-INFO | (xpcshell/head.js) | running event loop
21:09:32     INFO -  TEST-INFO | C:/slave/test/build/tests/xpcshell/tests/browser/experiments/test/xpcshell/test_telemetry.js | Starting test_setup
21:09:32     INFO -  TEST-INFO | (xpcshell/head.js) | test test_setup pending (2)
21:09:32     INFO -  1398312567746	addons.manager	DEBUG	Application has been upgraded
21:09:32     INFO -  1398312567795	addons.manager	DEBUG	Loaded provider scope for resource://gre/modules/addons/XPIProvider.jsm: ["XPIProvider"]
21:09:32     INFO -  1398312567796	addons.manager	DEBUG	Loaded provider scope for resource://gre/modules/LightweightThemeManager.jsm: ["LightweightThemeManager"]
21:09:32     INFO -  TEST-INFO | C:/slave/test/build/tests/xpcshell/tests/browser/experiments/test/xpcshell/test_telemetry.js -> file:///C:/slave/test/build/tests/xpcshell/tests/toolkit/mozapps/extensions/test/xpcshell/head_addons.js | "Mock profileBeforeChange blocker for 'AddonManager: shutting down providers'"
21:09:32     INFO -  1398312567806	addons.xpi	DEBUG	startup
21:09:32     INFO -  1398312567863	addons.xpi	DEBUG	checkForChanges
21:09:32     INFO -  1398312567866	addons.xpi	DEBUG	Empty XPI database, setting schema version preference to 16
21:09:32     INFO -  1398312567867	addons.xpi	DEBUG	No changes found
21:09:32     INFO -  OS Controller Posting message {"fun":"SET_DEBUG","args":[true],"id":1}
21:09:32     INFO -  OS Controller Message posted
21:09:32     INFO -  TEST-INFO | (xpcshell/head.js) | test run_next_test 0 finished (2)
21:09:32     INFO -  OS Controller Posting message {"fun":"makeDir","args":[{"string":"c:\\\\users\\\\cltbld~1.t-w\\\\appdata\\\\local\\\\temp\\\\tmpeyh4ox\\\\healthreport"},null],"id":2}
21:09:32     INFO -  OS Controller Message posted
21:09:32     INFO -  OS Agent Method SET_DEBUG succeeded
21:09:32     INFO -  OS Agent Sending positive reply  id is 1
21:09:32     INFO -  OS Controller Received message from worker {"id":1,"timeStamps":{"entered":1398312567897,"loaded":1398312567938}}
21:09:32     INFO -  OS Agent Received message {"fun":"makeDir","args":[{"string":"c:\\\\users\\\\cltbld~1.t-w\\\\appdata\\\\local\\\\temp\\\\tmpeyh4ox\\\\healthreport"},null],"id":2}
21:09:32     INFO -  OS Agent Calling method makeDir
21:09:32     INFO -  OS Attempting to declare FFI  CreateDirectoryW
21:09:32     INFO -  OS Function CreateDirectoryW declared
21:09:32     INFO -  OS Agent Method makeDir succeeded
21:09:32     INFO -  OS Agent Sending positive reply  id is 2
21:09:32     INFO -  OS Controller Received message from worker {"id":2}
21:09:32     INFO -  OS Controller Posting message {"fun":"remove","args":[{"string":"c:\\\\users\\\\cltbld~1.t-w\\\\appdata\\\\local\\\\temp\\\\tmpeyh4ox\\\\healthreport\\\\lastpayload.json"}],"id":3}
21:09:32     INFO -  OS Controller Message posted
21:09:32     INFO -  OS Agent Received message {"fun":"remove","args":[{"string":"c:\\\\users\\\\cltbld~1.t-w\\\\appdata\\\\local\\\\temp\\\\tmpeyh4ox\\\\healthreport\\\\lastpayload.json"}],"id":3}
21:09:32     INFO -  OS Agent Calling method remove
21:09:32     INFO -  OS Attempting to declare FFI  DeleteFileW
21:09:32     INFO -  OS Function DeleteFileW declared
21:09:32     INFO -  OS Agent Method remove succeeded
21:09:32     INFO -  OS Agent Sending positive reply  id is 3
21:09:32     INFO -  OS Controller Received message from worker {"id":3}
21:09:32     INFO -  OS Controller Posting message {"fun":"remove","args":[{"string":"c:\\\\users\\\\cltbld~1.t-w\\\\appdata\\\\local\\\\temp\\\\tmpeyh4ox\\\\healthreport\\\\lastpayload.json.tmp"}],"id":4}
21:09:32     INFO -  OS Controller Message posted
21:09:32     INFO -  OS Agent Received message {"fun":"remove","args":[{"string":"c:\\\\users\\\\cltbld~1.t-w\\\\appdata\\\\local\\\\temp\\\\tmpeyh4ox\\\\healthreport\\\\lastpayload.json.tmp"}],"id":4}
21:09:32     INFO -  OS Agent Calling method remove
21:09:32     INFO -  OS Agent Method remove succeeded
21:09:32     INFO -  OS Agent Sending positive reply  id is 4
21:09:32     INFO -  OS Controller Received message from worker {"id":4}
21:09:32     INFO -  System JS : WARNING resource://gre/modules/Preferences.jsm:378 - mutating the [[Prototype]] of an object will cause your code to run very slowly; instead create the object with the correct initial [[Prototype]] value using Object.create
21:09:32     INFO -  System JS : WARNING C:/slave/test/build/tests/xpcshell/tests/browser/experiments/test/xpcshell/test_telemetry.js -> file:///C:/slave/test/build/tests/xpcshell/tests/toolkit/mozapps/extensions/test/xpcshell/head_addons.js:1191 - in strict mode code, functions may be declared only at top level or immediately within another function
21:09:32     INFO -  System JS : WARNING resource://gre/modules/Log.jsm:543 - reference to undefined property message.level
21:09:32     INFO -  [6908] WARNING: 1 sort operation has occurred for the SQL statement '0x8d8da00'.  See https://developer.mozilla.org/En/Storage/Warnings details.: file c:\\builds\\moz2_slave\\fx-team-w32-d-0000000000000000\\build\\storage\\src\\mozStoragePrivateHelpers.cpp, line 109
21:09:32     INFO -  [6908] WARNING: 1 sort operation has occurred for the SQL statement '0x8d8dd00'.  See https://developer.mozilla.org/En/Storage/Warnings details.: file c:\\builds\\moz2_slave\\fx-team-w32-d-0000000000000000\\build\\storage\\src\\mozStoragePrivateHelpers.cpp, line 109
21:09:32     INFO -  [6908] WARNING: 1 sort operation has occurred for the SQL statement '0x8d8f100'.  See https://developer.mozilla.org/En/Storage/Warnings details.: file c:\\builds\\moz2_slave\\fx-team-w32-d-0000000000000000\\build\\storage\\src\\mozStoragePrivateHelpers.cpp, line 109
21:09:32     INFO -  [6908] WARNING: 1 sort operation has occurred for the SQL statement '0x8d8e500'.  See https://developer.mozilla.org/En/Storage/Warnings details.: file c:\\builds\\moz2_slave\\fx-team-w32-d-0000000000000000\\build\\storage\\src\\mozStoragePrivateHelpers.cpp, line 109
21:09:32     INFO -  [6908] WARNING: 1 sort operation has occurred for the SQL statement '0x8d8da00'.  See https://developer.mozilla.org/En/Storage/Warnings details.: file c:\\builds\\moz2_slave\\fx-team-w32-d-0000000000000000\\build\\storage\\src\\mozStoragePrivateHelpers.cpp, line 109
21:09:32     INFO -  [6908] WARNING: 1 sort operation has occurred for the SQL statement '0x8d8da00'.  See https://developer.mozilla.org/En/Storage/Warnings details.: file c:\\builds\\moz2_slave\\fx-team-w32-d-0000000000000000\\build\\storage\\src\\mozStoragePrivateHelpers.cpp, line 109
21:09:32     INFO -  [6908] WARNING: 1 sort operation has occurred for the SQL statement '0x8d8f600'.  See https://developer.mozilla.org/En/Storage/Warnings details.: file c:\\builds\\moz2_slave\\fx-team-w32-d-0000000000000000\\build\\storage\\src\\mozStoragePrivateHelpers.cpp, line 109
21:09:32     INFO -  [6908] WARNING: 1 sort operation has occurred for the SQL statement '0x8d8dc00'.  See https://developer.mozilla.org/En/Storage/Warnings details.: file c:\\builds\\moz2_slave\\fx-team-w32-d-0000000000000000\\build\\storage\\src\\mozStoragePrivateHelpers.cpp, line 109
21:09:32     INFO -  [6908] WARNING: 1 sort operation has occurred for the SQL statement '0x8d8e200'.  See https://developer.mozilla.org/En/Storage/Warnings details.: file c:\\builds\\moz2_slave\\fx-team-w32-d-0000000000000000\\build\\storage\\src\\mozStoragePrivateHelpers.cpp, line 109
21:09:32     INFO -  [6908] WARNING: 1 sort operation has occurred for the SQL statement '0x8d8ee00'.  See https://developer.mozilla.org/En/Storage/Warnings details.: file c:\\builds\\moz2_slave\\fx-team-w32-d-0000000000000000\\build\\storage\\src\\mozStoragePrivateHelpers.cpp, line 109
21:09:32     INFO -  [6908] WARNING: 1 sort operation has occurred for the SQL statement '0x8d8da00'.  See https://developer.mozilla.org/En/Storage/Warnings details.: file c:\\builds\\moz2_slave\\fx-team-w32-d-0000000000000000\\build\\storage\\src\\mozStoragePrivateHelpers.cpp, line 109
21:09:32     INFO -  [6908] WARNING: 1 sort operation has occurred for the SQL statement '0x8d8e300'.  See https://developer.mozilla.org/En/Storage/Warnings details.: file c:\\builds\\moz2_slave\\fx-team-w32-d-0000000000000000\\build\\storage\\src\\mozStoragePrivateHelpers.cpp, line 109
21:09:32     INFO -  [6908] WARNING: 1 sort operation has occurred for the SQL statement '0x8d8f100'.  See https://developer.mozilla.org/En/Storage/Warnings details.: file c:\\builds\\moz2_slave\\fx-team-w32-d-0000000000000000\\build\\storage\\src\\mozStoragePrivateHelpers.cpp, line 109
21:09:32     INFO -  OS Controller Posting message {"fun":"remove","args":[{"string":"c:\\\\users\\\\cltbld~1.t-w\\\\appdata\\\\local\\\\temp\\\\tmpeyh4ox\\\\experiments.json"}],"id":5}
21:09:32     INFO -  OS Controller Message posted
21:09:32     INFO -  OS Agent Received message {"fun":"remove","args":[{"string":"c:\\\\users\\\\cltbld~1.t-w\\\\appdata\\\\local\\\\temp\\\\tmpeyh4ox\\\\experiments.json"}],"id":5}
21:09:32     INFO -  OS Agent Calling method remove
21:09:32     INFO -  OS Agent Method remove succeeded
21:09:32     INFO -  OS Agent Sending positive reply  id is 5
21:09:32     INFO -  OS Controller Received message from worker {"id":5}
21:09:32     INFO -  TEST-INFO | (xpcshell/head.js) | test run_next_test 1 pending (2)
21:09:32     INFO -  TEST-INFO | (xpcshell/head.js) | test test_setup finished (2)
21:09:32     INFO -  TEST-INFO | C:/slave/test/build/tests/xpcshell/tests/browser/experiments/test/xpcshell/test_telemetry.js | Starting test_telemetryBasics
21:09:32     INFO -  TEST-INFO | (xpcshell/head.js) | test test_telemetryBasics pending (2)
21:09:32     INFO -  1398312570143	Browser.Experiments.Experiments	TRACE	Experiments #0::enabled=true, true
21:09:32     INFO -  1398312570145	Browser.Experiments.Experiments	TRACE	Experiments #0::Registering instance with Addon Manager.
21:09:32     INFO -  1398312570146	Browser.Experiments.Experiments	TRACE	Experiments #0::Registering previous experiment add-on provider.
21:09:32     INFO -  1398312570147	Browser.Experiments.Experiments	TRACE	Experiments #0::_loadFromCache
21:09:32     INFO -  1398312570149	Browser.Experiments.Experiments	TRACE	Experiments #0::updateManifest()
21:09:32     INFO -  1398312570149	Browser.Experiments.Experiments	TRACE	Experiments #0::_run
21:09:32     INFO -  1398312570149	Browser.Experiments.Experiments	TRACE	Experiments #0::_main iteration
21:09:32     INFO -  TEST-INFO | (xpcshell/head.js) | test run_next_test 1 finished (2)
21:09:32     INFO -  OS Controller Posting message {"fun":"read","args":[{"string":"c:\\\\users\\\\cltbld~1.t-w\\\\appdata\\\\local\\\\temp\\\\tmpeyh4ox\\\\experiments.json"},{"compression":"lz4"},{"compression":"lz4"}],"id":6}
21:09:32     INFO -  OS Controller Message posted
21:09:32     INFO -  OS Agent Received message {"fun":"read","args":[{"string":"c:\\\\users\\\\cltbld~1.t-w\\\\appdata\\\\local\\\\temp\\\\tmpeyh4ox\\\\experiments.json"},{"compression":"lz4"},{"compression":"lz4"}],"id":6}
21:09:32     INFO -  OS Agent Calling method read
21:09:32     INFO -  OS Attempting to declare FFI  CreateFileW
21:09:32     INFO -  OS Function CreateFileW declared
21:09:32     INFO -  OS Agent Error while calling agent method Win error 2 during operation open on file c:\\users\\cltbld~1.t-w\\appdata\\local\\temp\\tmpeyh4ox\\experiments.json (The system cannot find the file specified.
21:09:32     INFO -  )
21:09:32     INFO -  OS Agent Sending back OS.File error Win error 2 during operation open on file c:\\users\\cltbld~1.t-w\\appdata\\local\\temp\\tmpeyh4ox\\experiments.json (The system cannot find the file specified.
21:09:32     INFO -  ) id is 6
21:09:32     INFO -  OS Controller Received message from worker {"fail":{"operation":"open","winLastError":2,"path":"c:\\\\users\\\\cltbld~1.t-w\\\\appdata\\\\local\\\\temp\\\\tmpeyh4ox\\\\experiments.json"},"id":6}
21:09:32     INFO -  1398312570155	Browser.Experiments.Experiments	TRACE	Experiments #0::_loadTask finished ok
21:09:32     INFO -  1398312570155	Browser.Experiments.Experiments	TRACE	Experiments #0::_run
21:09:32     INFO -  1398312570156	Browser.Experiments.Experiments	TRACE	Experiments #0::_loadManifest
21:09:32     INFO -  1398312570161	Browser.Experiments.Experiments	TRACE	Experiments #0::httpGetRequest(http://localhost:58887/manifests/handler)
21:09:32     INFO -  pldhash: for the table at address 08DFA980, the given entrySize of 72 definitely favors chaining over double hashing.
21:09:32     INFO -  1398312572073	Browser.Experiments.Experiments	TRACE	Experiments #0::_loadManifest() - responseText="{"version":1,"experiments":[{"id":"test-experiment-1@tests.mozilla.org","xpiURL":"http://localhost:58887/data/experiment-1.xpi","xpiHash":"sha1:b7280916f3f7052c882f5757c8d96ee186b243de","startTime":1405969200,"endTime":1410289200,"maxActiveSeconds":864000,"appName":["XPCShell"],"channel":["nightly"]},{"id":"test-experiment-2@tests.mozilla.org","xpiURL":"http://localhost:58887/data/experiment-2.xpi","xpiHash":"sha1:5c796089a0612e01a42f84d0cf64080681de0485","startTime":1414609200,"endTime":1418929200,"maxActiveSeconds":864000,"appName":["XPCShell"],"channel":["nightly"]}]}"
21:09:32     INFO -  1398312572074	Browser.Experiments.Experiments	TRACE	Experiments #0::_updateExperiments() - experiments: {"version":1,"experiments":[{"id":"test-experiment-1@tests.mozilla.org","xpiURL":"http://localhost:58887/data/experiment-1.xpi","xpiHash":"sha1:b7280916f3f7052c882f5757c8d96ee186b243de","startTime":1405969200,"endTime":1410289200,"maxActiveSeconds":864000,"appName":["XPCShell"],"channel":["nightly"]},{"id":"test-experiment-2@tests.mozilla.org","xpiURL":"http://localhost:58887/data/experiment-2.xpi","xpiHash":"sha1:5c796089a0612e01a42f84d0cf64080681de0485","startTime":1414609200,"endTime":1418929200,"maxActiveSeconds":864000,"appName":["XPCShell"],"channel":["nightly"]}]}
21:09:32     INFO -  1398312572075	Browser.Experiments.Experiments	TRACE	ExperimentEntry #0::isManifestDataValid() - data: {"id":"test-experiment-1@tests.mozilla.org","xpiURL":"http://localhost:58887/data/experiment-1.xpi","xpiHash":"sha1:b7280916f3f7052c882f5757c8d96ee186b243de","startTime":1405969200,"endTime":1410289200,"maxActiveSeconds":864000,"appName":["XPCShell"],"channel":["nightly"]}
21:09:32     INFO -  1398312572077	Browser.Experiments.Experiments	TRACE	ExperimentEntry #1::isManifestDataValid() - data: {"id":"test-experiment-2@tests.mozilla.org","xpiURL":"http://localhost:58887/data/experiment-2.xpi","xpiHash":"sha1:5c796089a0612e01a42f84d0cf64080681de0485","startTime":1414609200,"endTime":1418929200,"maxActiveSeconds":864000,"appName":["XPCShell"],"channel":["nightly"]}
21:09:32     INFO -  1398312572078	Browser.Experiments.Experiments	TRACE	Experiments #0::_evaluateExperiments
21:09:32     INFO -  1398312572089	addons.xpi-utils	DEBUG	Starting async load of XPI database c:\\users\\cltbld~1.t-w\\appdata\\local\\temp\\tmpeyh4ox\\extensions.json
21:09:32     INFO -  1398312572093	addons.xpi-utils	DEBUG	Rebuilding XPI database with no extensions
21:09:32     INFO -  1398312572098	Browser.Experiments.Experiments	TRACE	ExperimentEntry #0::isApplicable() - now=1401649200, randomValue=0.38268080040999586, data={"id":"test-experiment-1@tests.mozilla.org","xpiURL":"http://localhost:58887/data/experiment-1.xpi","xpiHash":"sha1:b7280916f3f7052c882f5757c8d96ee186b243de","startTime":1405969200,"endTime":1410289200,"maxActiveSeconds":864000,"appName":["XPCShell"],"channel":["nightly"]}
21:09:32     INFO -  1398312572099	Browser.Experiments.Experiments	DEBUG	ExperimentEntry #0::isApplicable() - id=test-experiment-1@tests.mozilla.org - test 'startTime' failed
21:09:32     INFO -  1398312572102	Browser.Experiments.Experiments	TRACE	ExperimentEntry #1::isApplicable() - now=1401649200, randomValue=0.5682743440499917, data={"id":"test-experiment-2@tests.mozilla.org","xpiURL":"http://localhost:58887/data/experiment-2.xpi","xpiHash":"sha1:5c796089a0612e01a42f84d0cf64080681de0485","startTime":1414609200,"endTime":1418929200,"maxActiveSeconds":864000,"appName":["XPCShell"],"channel":["nightly"]}
21:09:32     INFO -  1398312572103	Browser.Experiments.Experiments	DEBUG	ExperimentEntry #1::isApplicable() - id=test-experiment-2@tests.mozilla.org - test 'startTime' failed
21:09:32     INFO -  1398312572106	Browser.Experiments.Experiments	TRACE	Experiments #0::_saveToCache
21:09:32     INFO -  OS Controller Posting message {"fun":"writeAtomic","args":[{"string":"c:\\\\users\\\\cltbld~1.t-w\\\\appdata\\\\local\\\\temp\\\\tmpeyh4ox\\\\experiments.json"},{"ptr":"150248496"},{"tmpPath":{"string":"c:\\\\users\\\\cltbld~1.t-w\\\\appdata\\\\local\\\\temp\\\\tmpeyh4ox\\\\experiments.json.tmp"},"compression":"lz4","bytes":931}],"id":7}
21:09:32     INFO -  OS Controller Message posted
21:09:32     INFO -  OS Agent Received message {"fun":"writeAtomic","args":[{"string":"c:\\\\users\\\\cltbld~1.t-w\\\\appdata\\\\local\\\\temp\\\\tmpeyh4ox\\\\experiments.json"},{"ptr":"150248496"},{"tmpPath":{"string":"c:\\\\users\\\\cltbld~1.t-w\\\\appdata\\\\local\\\\temp\\\\tmpeyh4ox\\\\experiments.json.tmp"},"compression":"lz4","bytes":931}],"id":7}
21:09:32     INFO -  OS Agent Calling method writeAtomic
21:09:32     INFO -  OS Attempting to declare FFI  workerlz4_maxCompressedSize
21:09:32     INFO -  OS Function workerlz4_maxCompressedSize declared
21:09:32     INFO -  OS Attempting to declare FFI  workerlz4_compress
21:09:32     INFO -  OS Function workerlz4_compress declared
21:09:32     INFO -  OS Attempting to declare FFI  SetFilePointer
21:09:32     INFO -  OS Function SetFilePointer declared
21:09:32     INFO -  OS Attempting to declare FFI  WriteFile
21:09:32     INFO -  OS Function WriteFile declared
21:09:32     INFO -  OS Attempting to declare FFI  MoveFileExW
21:09:32     INFO -  OS Function MoveFileExW declared
21:09:32     INFO -  OS Agent Method writeAtomic succeeded
21:09:32     INFO -  OS Agent Sending positive reply 543 id is 7
21:09:32     INFO -  OS Controller Received message from worker {"ok":543,"id":7}
21:09:32     INFO -  1398312572118	Browser.Experiments.Experiments	DEBUG	Experiments #0::_saveToCache saved to c:\\users\\cltbld~1.t-w\\appdata\\local\\temp\\tmpeyh4ox\\experiments.json
21:09:32     INFO -  1398312572118	Browser.Experiments.Experiments	TRACE	Experiments #0::_main finished, scheduling next run
21:09:32     INFO -  1398312572119	Browser.Experiments.Experiments	TRACE	Experiments #0::scheduleExperimentEvaluation() - scheduling for 1405969200000, now: 1401649200000
21:09:32     INFO -  TEST-PASS | C:/slave/test/build/tests/xpcshell/tests/browser/experiments/test/xpcshell/test_telemetry.js | [test_telemetryBasics : 174] Experiment list should be empty.
21:09:32  WARNING -  TEST-UNEXPECTED-FAIL | C:/slave/test/build/tests/xpcshell/tests/browser/experiments/test/xpcshell/test_telemetry.js | Telemetry log should have 2 entries. - 1 == 2 - See following stack:
21:09:32     INFO -  JS frame :: C:/slave/test/build/tests/xpcshell/tests/browser/experiments/test/xpcshell/test_telemetry.js :: test_telemetryBasics :: line 178
21:09:32     INFO -  JS frame :: resource://gre/modules/Task.jsm :: TaskImpl_run :: line 282
21:09:32     INFO -  JS frame :: resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js :: Handler.prototype.process :: line 863
21:09:32     INFO -  JS frame :: resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js :: this.PromiseWalker.walkerLoop :: line 742
21:09:32     INFO -  JS frame :: C:\\slave\\test\\build\\tests\\xpcshell\\head.js :: _do_main :: line 176
21:09:32     INFO -  JS frame :: C:\\slave\\test\\build\\tests\\xpcshell\\head.js :: _execute_test :: line 389
21:09:32     INFO -  JS frame :: -e :: <TOP_LEVEL> :: line 1
21:09:32     INFO -  native frame :: <unknown filename> :: <TOP_LEVEL> :: line 0
21:09:32     INFO -  TEST-INFO | (xpcshell/head.js) | exiting test
21:09:32  WARNING -  TEST-UNEXPECTED-FAIL | C:\\slave\\test\\build\\tests\\xpcshell\\head.js | Unexpected exception 2147500036
21:09:32     INFO -  TEST-INFO | (xpcshell/head.js) | exiting test
21:09:32     INFO -  1398312572292	addons.manager	DEBUG	shutdown
21:09:32     INFO -  1398312572293	addons.xpi	DEBUG	shutdown
21:09:32     INFO -  1398312572293	addons.xpi-utils	DEBUG	shutdown
21:09:32     INFO -  1398312572296	addons.xpi	DEBUG	Notifying XPI shutdown observers
21:09:32     INFO -  1398312572297	addons.manager	DEBUG	Async provider shutdown done
21:09:32     INFO -  TEST-INFO | C:/slave/test/build/tests/xpcshell/tests/browser/experiments/test/xpcshell/test_telemetry.js -> file:///C:/slave/test/build/tests/xpcshell/tests/toolkit/mozapps/extensions/test/xpcshell/head_addons.js | "gXPISaveError set to: null"
21:09:32     INFO -  1398312572565	Browser.Experiments.Experiments	TRACE	Experiments #0::uninit: started
21:09:32     INFO -  1398312572565	Browser.Experiments.Experiments	TRACE	Experiments #0::uninit: finished with _loadTask
21:09:32     INFO -  1398312572565	Browser.Experiments.Experiments	TRACE	Experiments #0::uninit: no previous shutdown
21:09:32     INFO -  1398312572565	Browser.Experiments.Experiments	TRACE	Experiments #0::Unregistering instance with Addon Manager.
21:09:32     INFO -  1398312572565	Browser.Experiments.Experiments	TRACE	Experiments #0::Unregistering previous experiment add-on provider.
21:09:32     INFO -  1398312572567	Browser.Experiments.Experiments	INFO	Experiments #0::Completed uninitialization.
21:09:32     INFO -  OS Controller Posting message {"fun":"Meta_shutdown","args":[false],"id":8}
21:09:32     INFO -  OS Controller Message posted
21:09:32     INFO -  OS Agent Received message {"fun":"Meta_shutdown","args":[false],"id":8}
21:09:32     INFO -  OS Agent Calling method Meta_shutdown
21:09:32     INFO -  OS Agent Method Meta_shutdown succeeded
21:09:32     INFO -  OS Agent Sending positive reply {"data":{"openedFiles":[],"openedDirectoryIterators":[],"killed":false},"meta":{"shutdown":false}} id is 8
21:09:32     INFO -  OS Controller Received message from worker {"ok":{"openedFiles":[],"openedDirectoryIterators":[],"killed":false},"id":8}
21:09:32     INFO -  System JS : ERROR (null):0 - uncaught exception: 2147500037
21:09:32     INFO -  System JS : ERROR (null):0 - uncaught exception: 2147500037
21:09:32     INFO -  System JS : ERROR (null):0 - uncaught exception: 2147500037
21:09:32     INFO -  System JS : ERROR (null):0 - uncaught exception: 2147500037
21:09:32     INFO -  System JS : ERROR C:\\slave\\test\\build\\tests\\xpcshell\\head.js:359 - TypeError: _log_message_with_stack is not a function
21:09:32     INFO -  [6908] WARNING: Leaking the RDF Service.: file c:/builds/moz2_slave/fx-team-w32-d-0000000000000000/build/rdf/build/nsRDFModule.cpp, line 165
21:09:32     INFO -  [6908] WARNING: '!compMgr', file c:/builds/moz2_slave/fx-team-w32-d-0000000000000000/build/xpcom/glue/nsComponentManagerUtils.cpp, line 59
21:09:32     INFO -  [6908] WARNING: OOPDeinit() without successful OOPInit(): file c:\\builds\\moz2_slave\\fx-team-w32-d-0000000000000000\\build\\toolkit\\crashreporter\\nsExceptionHandler.cpp, line 2553
21:09:32     INFO -  [6908] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file c:\\builds\\moz2_slave\\fx-team-w32-d-0000000000000000\\build\\xpcom\\base\\nsTraceRefcnt.cpp, line 142
21:09:32     INFO -  [6908] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file c:\\builds\\moz2_slave\\fx-team-w32-d-0000000000000000\\build\\xpcom\\base\\nsTraceRefcnt.cpp, line 142
21:09:32     INFO -  nsStringStats
21:09:32     INFO -   => mAllocCount:          10447
21:09:32     INFO -   => mReallocCount:          620
21:09:32     INFO -   => mFreeCount:           10447
21:09:32     INFO -   => mShareCount:          14697
21:09:32     INFO -   => mAdoptCount:            542
21:09:32     INFO -   => mAdoptFreeCount:        542
21:09:32     INFO -   => Process ID: 6908, Thread ID: 2380
21:09:32     INFO -  <<<<<<<
Georg, can you take a look?
Flags: needinfo?(georg.fritzsche)
Hm, i'm not seeing yet how we can end up with one entry instead of two.

The log shows we evaluate and reject two experiments:
> ExperimentEntry #0::isApplicable() - now=1401649200, randomValue=0.38268080040999586, data={"id":"test-experiment-1@tests.mozilla.org","xpiURL":"http://localhost:58887/data/experiment-1.xpi","xpiHash":"sha1:b7280916f3f7052c882f5757c8d96ee186b243de","startTime":1405969200,"endTime":1410289200,"maxActiveSeconds":864000,"appName":["XPCShell"],"channel":["nightly"]}
> ExperimentEntry #0::isApplicable() - id=test-experiment-1@tests.mozilla.org - test 'startTime' failed
> ExperimentEntry #1::isApplicable() - now=1401649200, randomValue=0.5682743440499917, data={"id":"test-experiment-2@tests.mozilla.org","xpiURL":"http://localhost:58887/data/experiment-2.xpi","xpiHash":"sha1:5c796089a0612e01a42f84d0cf64080681de0485","startTime":1414609200,"endTime":1418929200,"maxActiveSeconds":864000,"appName":["XPCShell"],"channel":["nightly"]}
> ExperimentEntry #1::isApplicable() - id=test-experiment-2@tests.mozilla.org - test 'startTime' failed

That should get added to the TelemetryLog here:
http://hg.mozilla.org/mozilla-central/annotate/4d926af89907/browser/experiments/Experiments.jsm#l1126

We wait on the _mainTask (and hence _evaluateExperiments) here:
http://hg.mozilla.org/mozilla-central/annotate/4d926af89907/browser/experiments/test/xpcshell/test_telemetry.js#l172

Looking through TelemetryLog & TelemetryPing.getPayload() i don't see async operations we miss waiting on.
Flags: needinfo?(georg.fritzsche)
Some additional tracing so we hopefully get a better idea next time.
Attachment #8413728 - Flags: review?(benjamin)
Attachment #8413728 - Flags: review?(benjamin) → review+
Status: NEW → RESOLVED
Closed: 8 years ago
Resolution: --- → WORKSFORME
You need to log in before you can comment on or make changes to this bug.