927214 - Intermittent test_healthreporter.js | Test timed out | test failed (with xpcshell return code: 15), see following log | false == true - See following stack

Status: RESOLVED WORKSFORME

(Firefox Health Report Graveyard :: Client: Desktop, defect)

Description

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://tbpl.mozilla.org/php/getParsedLog.php?id=29158753&tree=Mozilla-Inbound
using slave: t-w864-ix-104



16:59:00     INFO -  TEST-PASS | C:\slave\test\build\tests\xpcshell\tests\extensions\cookie\test\unit\test_cookies_sync_failure.js | test passed (time: 10121.000ms)
16:59:00     INFO -  TEST-INFO | C:\slave\test\build\tests\xpcshell\tests\services\metrics\tests\xpcshell\test_metrics_provider_manager.js | running test ...
16:59:18     INFO -  TEST-PASS | C:\slave\test\build\tests\xpcshell\tests\services\metrics\tests\xpcshell\test_metrics_provider_manager.js | test passed (time: 17939.000ms)
16:59:18     INFO -  TEST-INFO | C:\slave\test\build\tests\xpcshell\tests\services\healthreport\tests\xpcshell\test_healthreporter.js | running test ...
17:04:18  WARNING -  TEST-UNEXPECTED-FAIL | C:\slave\test\build\tests\xpcshell\tests\services\healthreport\tests\xpcshell\test_healthreporter.js | Test timed out
17:04:18     INFO -  Can't trigger Breakpad, just killing process
17:04:18  WARNING -  TEST-UNEXPECTED-FAIL | C:\slave\test\build\tests\xpcshell\tests\services\healthreport\tests\xpcshell\test_healthreporter.js | test failed (with xpcshell return code: 15), see following log:
17:04:18     INFO -  >>>>>>>
...
17:04:20     INFO -  Services.Metrics.ProviderManager	DEBUG	Pull-only providers being unregistered.
17:04:20     INFO -  Services.Metrics.ProviderManager	INFO	Shutting down pull-only provider: DummyConstantProvider
17:04:20     INFO -  Sqlite.Connection.data_submission_success	DEBUG	Conn #0: Stmt #159 finished.
17:04:20     INFO -  TEST-PASS | C:/slave/test/build/tests/xpcshell/tests/services/healthreport/tests/xpcshell/test_healthreporter.js | [test_data_submission_success : 629] true == true
17:04:20     INFO -  TEST-PASS | C:/slave/test/build/tests/xpcshell/tests/services/healthreport/tests/xpcshell/test_healthreporter.js | [test_data_submission_success : 630] true == true
17:04:20     INFO -  TEST-PASS | C:/slave/test/build/tests/xpcshell/tests/services/healthreport/tests/xpcshell/test_healthreporter.js | [getValues : 76] [object Object] != null
17:04:20     INFO -  TEST-PASS | C:/slave/test/build/tests/xpcshell/tests/services/healthreport/tests/xpcshell/test_healthreporter.js | [getValues : 78] [object Object] != null
17:04:20     INFO -  Sqlite.Connection.data_submission_success	TRACE	Conn #0: Stmt #160 SELECT field_name, day, value FROM v_daily_counters WHERE measurement_id = :measurement_id - {"measurement_id":1}
17:04:20     INFO -  Sqlite.Connection.data_submission_success	DEBUG	Conn #0: Stmt #160 finished.
17:04:20  WARNING -  TEST-UNEXPECTED-FAIL | C:/slave/test/build/tests/xpcshell/tests/services/healthreport/tests/xpcshell/test_healthreporter.js | false == true - See following stack:
17:04:20     INFO -  JS frame :: C:/slave/test/build/tests/xpcshell/tests/services/healthreport/tests/xpcshell/test_healthreporter.js :: getValues :: line 85
17:04:20     INFO -  JS frame :: resource://gre/modules/Task.jsm :: TaskImpl_run :: line 233
17:04:20     INFO -  JS frame :: resource://gre/modules/Promise.jsm :: <TOP_LEVEL> :: line 719
17:04:20     INFO -  JS frame :: resource://gre/modules/Promise.jsm :: <TOP_LEVEL> :: line 483
17:04:20     INFO -  native frame :: <unknown filename> :: <TOP_LEVEL> :: line 0
17:04:20     INFO -  TEST-INFO | (xpcshell/head.js) | exiting test
17:04:20  WARNING -  TEST-UNEXPECTED-FAIL | resource://gre/modules/commonjs/sdk/core/promise.js | Unexpected exception 2147500036
17:04:20     INFO -  TEST-INFO | (xpcshell/head.js) | exiting test
17:04:20     INFO -  <<<<<<<

Comment 1

[Legacy TBPL/Treeherder Robot]

KWierso
https://tbpl.mozilla.org/php/getParsedLog.php?id=30869759&tree=Mozilla-Inbound
WINNT 6.2 mozilla-inbound opt test xpcshell on 2013-11-20 18:22:05
revision: 1c2b28920048
slave: t-w864-ix-092

TEST-UNEXPECTED-FAIL | C:\slave\test\build\tests\xpcshell\tests\services\healthreport\tests\xpcshell\test_healthreporter.js | Test timed out
TEST-UNEXPECTED-FAIL | C:\slave\test\build\tests\xpcshell\tests\services\healthreport\tests\xpcshell\test_healthreporter.js | test failed (with xpcshell return code: 15), see following log:
Return code: 1

Comment 2

[Gregory Szorc [:gps]]

This is weird. It appears we aren't performing the outbound HTTP request! We stall somewhere after https://hg.mozilla.org/mozilla-central/file/c7cbfa315d46/services/common/rest.js#l311.

This quacks like a rest.js bug or a Necko bug. But given the frequency and the very seldom nature, I wonder if it could be something network related, such as a DNS lookup that never resolves.

Sheriffs: do any of these possibilities sound like existing bugs?

Here is the bad log:

19:25:16     INFO -  Services.HealthReport.HealthReporter	WARN	Recording new remote ID: fbefeb6c-6842-4230-be5c-b1723017f044
19:25:16     INFO -  Services.HealthReport.HealthReporter	INFO	Writing state file: c:\users\cltbld~1.t-w\appdata\local\temp\tmpefhwrk\healthreport\state-data_submission_transport_failure.json
19:25:16     INFO -  Sqlite.Connection.data_submission_transport_failure	TRACE	Conn #0: Stmt #82 INSERT OR REPLACE INTO daily_counters VALUES (:field_id, :days, COALESCE((SELECT value FROM daily_counters WHERE field_id = :field_id AND day = :days ), 0) + :by) - {"field_id":1,"days":16030,"by":1}
19:25:16     INFO -  Services.BagheeraClient	INFO	Uploading data to http://localhost:62013/1.0/submit/test00/fbefeb6c-6842-4230-be5c-b1723017f044
19:25:16     INFO -  Services.BagheeraClient	INFO	Request body length: 228
19:25:16     INFO -  Services.BagheeraClient	DEBUG	POST Length: 228
19:25:16     INFO -  Sqlite.Connection.data_submission_transport_failure	DEBUG	Conn #0: Stmt #82 finished.
19:25:16     INFO -  <<<<<<<
19:25:16     INFO -  TEST-INFO | C:\slave\test\build\tests\xpcshell\tests\services\metrics\tests\xpcshell\test_metrics_provider_manager.js | running test ...
19:27:15     INFO -  TEST-PASS | C:\slave\test\build\tests\xpcshell\tests\services\metrics\tests\xpcshell\test_metrics_provider_manager.js | test passed (time: 119172.000ms)
19:27:1

A proper log looks something like:

0:04.55 Services.HealthReport.HealthReporter   WARN    Recording new remote ID: fdc51ed5-03ae-574a-93b2-b2400cd3028b
 0:04.55 Services.HealthReport.HealthReporter   INFO    Writing state file: /var/folders/20/0m2k6lq56kdf4q_kdgzmhjkw0000gn/T/firefox/xpcshellprofile/healthreport/state-data_submission_transport_failure.json
 0:04.55 Sqlite.Connection.data_submission_transport_failure    TRACE   Conn #0: Stmt #82 INSERT OR REPLACE INTO daily_counters VALUES (:field_id, :days, COALESCE((SELECT value FROM daily_counters WHERE field_id = :field_id AND day = :days ), 0) + :by) - {"field_id":1,"days":16030,"by":1}
 0:04.55 Services.BagheeraClient        INFO    Uploading data to http://localhost:62013/1.0/submit/test00/fdc51ed5-03ae-574a-93b2-b2400cd3028b
 0:04.55 Services.BagheeraClient        INFO    Request body length: 228
 0:04.57 Services.BagheeraClient        DEBUG   POST Length: 228
 0:04.58 Sqlite.Connection.data_submission_transport_failure    DEBUG   Conn #0: Stmt #82 finished.
 0:04.83 Services.BagheeraClient        INFO    Transport failure on request: NS_ERROR_CONNECTION_REFUSED Stack trace: onStopRequest()@resource://services-common/rest.js:438 < <file:unknown>
 0:04.83 Services.HealthReport.HealthReporter   DEBUG   Received Bagheera result.
 0:04.83 Sqlite.Connection.data_submission_transport_failure    TRACE   Conn #0: Stmt #83 INSERT OR REPLACE INTO daily_counters VALUES (:field_id, :days, COALESCE((SELECT value FROM daily_counters WHERE field_id = :field_id AND day = :days ), 0) + :by) - {"field_id":4,"days":16030,"by":1}
 0:04.83 Services.Metrics.ProviderManager       DEBUG   Pull-only providers being unregistered.
 0:04.83 Services.Metrics.ProviderManager       DEBUG   Waiting for in-flight pull-only provider activity to complete before unregistering.
 0:04.83
 0:04.83 TEST-PASS | /Users/gps/src/firefox/obj-firefox.noindex/_tests/xpcshell/services/healthreport/tests/xpcshell/test_healthreporter.js | [test_data_submission_transport_failure : 564] "failure-soft" == "failure-soft"

Comment 3

[Ryan VanderMeulen [:RyanVM]]

Given how it sorta hit all branches at the same time, network sounds like a possibility to me. That said, time is probably going to be better served making the test more robust than getting RelEng to make the network more reliable.

Comment 4

[Gregory Szorc [:gps]]

Patrick: I'm interested in your Necko opinion. Read last 2 comments. A casual audit of rest.js would be appreciated. Is there any way we can test our hypothesis of failing DNS lookup?

Comment 5

[Patrick McManus [:mcmanus]]

it isn't clear to me what the test is doing. Is it looking up "localhost" ? That won't ever need a functioning network.

Comment 6

[Legacy TBPL/Treeherder Robot]

KWierso
https://tbpl.mozilla.org/php/getParsedLog.php?id=31119943&tree=Mozilla-Inbound
Windows 7 32-bit mozilla-inbound opt test xpcshell on 2013-11-26 15:11:12
revision: aa0066b3865c
slave: t-w732-ix-009

TEST-UNEXPECTED-FAIL | C:\slave\test\build\tests\xpcshell\tests\services\healthreport\tests\xpcshell\test_healthreporter.js | Test timed out
TEST-UNEXPECTED-FAIL | C:\slave\test\build\tests\xpcshell\tests\services\healthreport\tests\xpcshell\test_healthreporter.js | test failed (with xpcshell return code: 15), see following log:
Return code: 1

Comment 7

[Legacy TBPL/Treeherder Robot]

KWierso
https://tbpl.mozilla.org/php/getParsedLog.php?id=32944950&tree=Mozilla-Beta
WINNT 6.2 mozilla-beta pgo test xpcshell on 2014-01-13 14:41:16
revision: 598dcd6f37c5
slave: t-w864-ix-092

TEST-UNEXPECTED-FAIL | C:\slave\test\build\tests\xpcshell\tests\services\healthreport\tests\xpcshell\test_healthreporter.js | Test timed out
TEST-UNEXPECTED-FAIL | C:\slave\test\build\tests\xpcshell\tests\services\healthreport\tests\xpcshell\test_healthreporter.js | test failed (with xpcshell return code: 15), see following log:
Return code: 1

Comment 8

[Legacy TBPL/Treeherder Robot]

KWierso
https://tbpl.mozilla.org/php/getParsedLog.php?id=34646220&tree=Mozilla-Inbound
WINNT 6.2 mozilla-inbound pgo test xpcshell on 2014-02-13 15:33:10
revision: 0f18070eb5d6
slave: t-w864-ix-130

TEST-UNEXPECTED-FAIL | C:\slave\test\build\tests\xpcshell\tests\services\healthreport\tests\xpcshell\test_healthreporter.js | test failed (with xpcshell return code: 0), see following log:
TEST-UNEXPECTED-FAIL | C:/slave/test/build/tests/xpcshell/tests/services/healthreport/tests/xpcshell/test_healthreporter.js | false == true - See following stack:
TEST-UNEXPECTED-FAIL | resource://gre/modules/commonjs/sdk/core/promise.js | Unexpected exception 2147500036
Return code: 1

Comment 9

[Legacy TBPL/Treeherder Robot]

philor
https://tbpl.mozilla.org/php/getParsedLog.php?id=35567009&tree=Mozilla-Aurora
WINNT 6.2 mozilla-aurora pgo test xpcshell on 2014-03-03 16:19:49
revision: f6ed13594ecd
slave: t-w864-ix-092

TEST-UNEXPECTED-FAIL | C:\slave\test\build\tests\xpcshell\tests\services\healthreport\tests\xpcshell\test_healthreporter.js | Test timed out
TEST-UNEXPECTED-FAIL | C:\slave\test\build\tests\xpcshell\tests\services\healthreport\tests\xpcshell\test_healthreporter.js | test failed (with xpcshell return code: 15), see following log:
Return code: 1

Comment 10

[Legacy TBPL/Treeherder Robot]

KWierso
https://tbpl.mozilla.org/php/getParsedLog.php?id=35963483&tree=Fx-Team
WINNT 6.2 fx-team pgo test xpcshell on 2014-03-11 14:25:28
revision: f66e3ccb0c41
slave: t-w864-ix-092

TEST-UNEXPECTED-FAIL | C:\slave\test\build\tests\xpcshell\tests\security\manager\ssl\tests\unit\test_ocsp_stapling_expired.js | test failed (with xpcshell return code: 0), see following log:
TEST-UNEXPECTED-FAIL | C:/slave/test/build/tests/xpcshell/tests/security/manager/ssl/tests/unit/test_ocsp_stapling_expired.js | 0 == 1 - See following stack:
TEST-UNEXPECTED-FAIL | C:\slave\test\build\tests\xpcshell\tests\dom\indexedDB\test\unit\test_overlapping_transactions.js | Test timed out
TEST-UNEXPECTED-FAIL | C:\slave\test\build\tests\xpcshell\tests\dom\indexedDB\test\unit\test_overlapping_transactions.js | test failed (with xpcshell return code: 15), see following log:
TEST-UNEXPECTED-FAIL | C:\slave\test\build\tests\xpcshell\tests\services\healthreport\tests\xpcshell\test_healthreporter.js | Test timed out
TEST-UNEXPECTED-FAIL | C:\slave\test\build\tests\xpcshell\tests\services\healthreport\tests\xpcshell\test_healthreporter.js | test failed (with xpcshell return code: 15), see following log:
TEST-UNEXPECTED-FAIL | C:\slave\test\build\tests\xpcshell\tests\toolkit\mozapps\update\tests\unit_base_updater\marFileInUseFallbackStageFailureComplete_win.js | test failed (with xpcshell return code: 0), see following log:
TEST-UNEXPECTED-FAIL | C:\\slave\\test\\build\\tests\\xpcshell\\head.js | exception thrown from do_timeout callback: [Exception... "Component returned failure code: 0x8052000e (NS_ERROR_FILE_IS_LOCKED) [nsIFile.copyToFollowingLinks]"  nsresult: "0x8052000e (NS_ERROR_FILE_IS_LOCKED)"  location: "JS frame :: C:/slave/test/build/tests/xpcshell/tests/toolkit/mozapps/update/tests/unit_base_updater/head_update.js :: runUpdate :: line 2431"  data: no] - See following stack:
Return code: 1

Comment 11

[Legacy TBPL/Treeherder Robot]

philor
https://tbpl.mozilla.org/php/getParsedLog.php?id=38064107&tree=Mozilla-Inbound
WINNT 6.2 mozilla-inbound opt test xpcshell on 2014-04-17 19:09:55
revision: 280c066afbf1
slave: t-w864-ix-092

TEST-UNEXPECTED-FAIL | C:\slave\test\build\tests\xpcshell\tests\services\healthreport\tests\xpcshell\test_healthreporter.js | Test timed out
TEST-UNEXPECTED-FAIL | C:\slave\test\build\tests\xpcshell\tests\services\healthreport\tests\xpcshell\test_healthreporter.js | test failed (with xpcshell return code: 15), see following log:
Return code: 1

Comment 12

[Legacy TBPL/Treeherder Robot]

Tomcat
https://tbpl.mozilla.org/php/getParsedLog.php?id=40929029&tree=Mozilla-Inbound
Windows 7 32-bit mozilla-inbound pgo test xpcshell on 2014-06-02 22:56:20
revision: 917d8912c712
slave: t-w732-ix-099

TEST-UNEXPECTED-FAIL | C:\slave\test\build\tests\xpcshell\tests\services\healthreport\tests\xpcshell\test_healthreporter.js | test failed (with xpcshell return code: 0), see following log:
TEST-UNEXPECTED-FAIL | C:\\slave\\test\\build\\tests\\xpcshell\\head.js | Unexpected exception Error: Could not open connection: 2153971713 at resource://gre/modules/Sqlite.jsm:185 - See following stack:
Return code: 1

Comment 13

[Legacy TBPL/Treeherder Robot]

KWierso
https://tbpl.mozilla.org/php/getParsedLog.php?id=41908806&tree=Mozilla-Central
Ubuntu VM 12.04 x64 mozilla-central opt test xpcshell on 2014-06-17 14:31:49
revision: c4cf1181993e
slave: tst-linux64-spot-101

TEST-UNEXPECTED-FAIL | /builds/slave/test/build/tests/xpcshell/tests/services/healthreport/tests/xpcshell/test_healthreporter.js | Test timed out
TEST-UNEXPECTED-FAIL | /builds/slave/test/build/tests/xpcshell/tests/services/healthreport/tests/xpcshell/test_healthreporter.js | test failed (with xpcshell return code: -6), see following log:
PROCESS-CRASH | /builds/slave/test/build/tests/xpcshell/tests/services/healthreport/tests/xpcshell/test_healthreporter.js | application crashed [@ libc-2.15.so + 0xe8403]
Return code: 1

Comment 14

[Legacy TBPL/Treeherder Robot]

Tomcat
https://tbpl.mozilla.org/php/getParsedLog.php?id=44941531&tree=Mozilla-Inbound
WINNT 6.2 mozilla-inbound opt test xpcshell on 2014-07-30 18:17:02
revision: 72b1c5f4a0bb
slave: t-w864-ix-077

TEST-UNEXPECTED-FAIL | C:\slave\test\build\tests\xpcshell\tests\services\healthreport\tests\xpcshell\test_healthreporter.js | test failed (with xpcshell return code: 0), see following log:
TEST-UNEXPECTED-FAIL | C:\\slave\\test\\build\\tests\\xpcshell\\head.js | Unexpected exception Error: Could not open connection: 2153971713 at resource://gre/modules/Sqlite.jsm:743 - See following stack:
Return code: 1

Comment 15

[Legacy TBPL/Treeherder Robot]

RyanVM
https://tbpl.mozilla.org/php/getParsedLog.php?id=47113830&tree=Fx-Team
WINNT 6.2 fx-team opt test xpcshell on 2014-08-30 16:32:58
revision: cd821c1ef789
slave: t-w864-ix-126

TEST-UNEXPECTED-FAIL | C:\slave\test\build\tests\xpcshell\tests\services\healthreport\tests\xpcshell\test_healthreporter.js | test failed (with xpcshell return code: 0), see following log:
TEST-UNEXPECTED-FAIL | C:/slave/test/build/tests/xpcshell/tests/services/healthreport/tests/xpcshell/test_healthreporter.js | false == true - See following stack:
TEST-UNEXPECTED-FAIL | C:\\slave\\test\\build\\tests\\xpcshell\\head.js | Unexpected exception 2147500036
Return code: 1

Comment 16

[Legacy TBPL/Treeherder Robot]

philor
https://tbpl.mozilla.org/php/getParsedLog.php?id=47456389&tree=B2g-Inbound
WINNT 6.2 b2g-inbound debug test xpcshell on 2014-09-04 20:13:44
revision: 9aa7c2b35358
slave: t-w864-ix-070

TEST-UNEXPECTED-FAIL | C:\slave\test\build\tests\xpcshell\tests\services\healthreport\tests\xpcshell\test_healthreporter.js | Test timed out
TEST-UNEXPECTED-FAIL | C:\slave\test\build\tests\xpcshell\tests\services\healthreport\tests\xpcshell\test_healthreporter.js | test failed (with xpcshell return code: 15), see following log:
TEST-UNEXPECTED-FAIL | C:\slave\test\build\tests\xpcshell\tests\toolkit\mozapps\extensions\test\xpcshell\test_migrateAddonRepository.js | Test timed out
TEST-UNEXPECTED-FAIL | C:\slave\test\build\tests\xpcshell\tests\toolkit\mozapps\extensions\test\xpcshell\test_migrateAddonRepository.js | test failed (with xpcshell return code: 15), see following log:
Return code: 1

Comment 17

[Ed Morley [:emorley]]

Inactive; closing (see bug 1180138).