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)
Tracking
()
RESOLVED
WORKSFORME
People
(Reporter: philor, Unassigned)
Details
(Keywords: intermittent-failure, Whiteboard: [leave open])
Attachments
(1 file)
2.30 KB,
patch
|
benjamin
:
review+
gfritzsche
:
checkin+
|
Details | Diff | Splinter Review |
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 - <<<<<<<
Comment 2•10 years ago
|
||
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)
Comment 3•10 years ago
|
||
Some additional tracing so we hopefully get a better idea next time.
Attachment #8413728 -
Flags: review?(benjamin)
Updated•10 years ago
|
Attachment #8413728 -
Flags: review?(benjamin) → review+
Comment 4•10 years ago
|
||
https://hg.mozilla.org/integration/fx-team/rev/d25120c7a148
Whiteboard: [leave open]
Updated•10 years ago
|
Attachment #8413728 -
Flags: checkin+
Comment hidden (Legacy TBPL/Treeherder Robot) |
Comment hidden (Legacy TBPL/Treeherder Robot) |
Comment hidden (Legacy TBPL/Treeherder Robot) |
Comment hidden (Legacy TBPL/Treeherder Robot) |
Comment hidden (Legacy TBPL/Treeherder Robot) |
Comment hidden (Legacy TBPL/Treeherder Robot) |
Comment hidden (Legacy TBPL/Treeherder Robot) |
Comment hidden (Legacy TBPL/Treeherder Robot) |
Comment hidden (Legacy TBPL/Treeherder Robot) |
Comment hidden (Legacy TBPL/Treeherder Robot) |
Comment hidden (Legacy TBPL/Treeherder Robot) |
Comment hidden (Legacy TBPL/Treeherder Robot) |
Comment hidden (Legacy TBPL/Treeherder Robot) |
Comment hidden (Legacy TBPL/Treeherder Robot) |
Comment hidden (Legacy TBPL/Treeherder Robot) |
Comment hidden (Legacy TBPL/Treeherder Robot) |
Comment hidden (Legacy TBPL/Treeherder Robot) |
Comment hidden (Legacy TBPL/Treeherder Robot) |
Comment hidden (Legacy TBPL/Treeherder Robot) |
Comment hidden (Legacy TBPL/Treeherder Robot) |
Comment hidden (Legacy TBPL/Treeherder Robot) |
Comment hidden (Legacy TBPL/Treeherder Robot) |
Comment hidden (Legacy TBPL/Treeherder Robot) |
Comment hidden (Legacy TBPL/Treeherder Robot) |
Comment hidden (Legacy TBPL/Treeherder Robot) |
Updated•8 years ago
|
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.
Description
•