1332993 - Error logs written on profile fetch 304 response

Reporter

Description

•

7 years ago

I just saw the following in my logs:

> 1485154464249   Services.Common.RESTRequest     DEBUG   GET https://profile.accounts.firefox.com/v1/profile 304
> 1485154464250   FirefoxAccounts ERROR   Background refresh of profile failed, bumping _cachedAt: {"name":"FxAccountsProfileClientError","code":304,"errno":997,"error":"PARSE_ERROR","message":null}
> 1485154464250   FirefoxAccounts ERROR   Background refresh of profile failed, bumping _cachedAt: {"name":"FxAccountsProfileClientError","code":304,"errno":997,"error":"PARSE_ERROR","message":null}

which seems bad :)

(see also bug 1332992, but I doubt that's related)

Edouard Oger [:eoger]

Assignee

Updated

•

7 years ago

Assignee: nobody → eoger

Status: NEW → ASSIGNED

Priority: -- → P1

Comment hidden (mozreview-request)

Review commit: https://reviewboard.mozilla.org/r/106564/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/106564/

Edouard Oger [:eoger]

Assignee

Comment 2

•

7 years ago

Sorry about this, I removed a bit too much code when I simplified the error handling in bug 1323102.

Mark Hammond [:markh] [:mhammond]

Reporter

Comment 3

•

7 years ago

mozreview-review

Comment on attachment 8829471 [details]
Bug 1332993 - Do not write logs on FxA profile 304 response.

https://reviewboard.mozilla.org/r/106564/#review107802

Thanks - please land this, but can you please open a bug for the fact we still end up at https://dxr.mozilla.org/mozilla-central/source/services/fxaccounts/FxAccountsProfileClient.jsm#160 in this case, which seems wrong :)

::: services/fxaccounts/FxAccountsProfile.jsm:104
(Diff revision 1)
>          return this.client.fetchProfile(etag);
>        })
>        .then(response => {
>          return this._cacheProfile(response);
>        })
>        .then(body => { // finally block

You don't need to return body, so here you could maybe write .then(onFinally, () => {
  onFinally();
  if (...)
});?

Mark Hammond [:markh] [:mhammond]

Reporter

Comment 4

•

7 years ago

mozreview-review

Comment on attachment 8829471 [details]
Bug 1332993 - Do not write logs on FxA profile 304 response.

https://reviewboard.mozilla.org/r/106564/#review107808

Attachment #8829471 - Flags: review?(markh) → review+

Edouard Oger [:eoger]

Assignee

Comment 5

•

7 years ago

mozreview-review-reply

Comment on attachment 8829471 [details]
Bug 1332993 - Do not write logs on FxA profile 304 response.

https://reviewboard.mozilla.org/r/106564/#review107802

> You don't need to return body, so here you could maybe write .then(onFinally, () => {
>   onFinally();
>   if (...)
> });?

I think we actually do (see line 140)

Pulsebot

Comment 6

•

7 years ago

Pushed by eoger@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/ccc602619a07
Do not write logs on FxA profile 304 response. r=markh

Edouard Oger [:eoger]

Assignee

Updated

•

7 years ago

Comment 7

•

7 years ago

Backed out for failing xpcshell test test_accounts.js at least on Linux:

https://hg.mozilla.org/integration/autoland/rev/467f94f27eb9dae7250ae85421ce7587b31bc229

Push with failures: https://treeherder.mozilla.org/#/jobs?repo=autoland&revision=ccc602619a070489179dc8d807326d5ee85f1406
Failure log: https://treeherder.mozilla.org/logviewer.html#?job_id=71546489&repo=autoland

[task 2017-01-24T16:32:18.841343Z] 16:32:18     INFO -  TEST-PASS | services/fxaccounts/tests/xpcshell/test_accounts.js | test_getSignedInUserProfile - [test_getSignedInUserProfile : 1368] true == true
[task 2017-01-24T16:32:18.843323Z] 16:32:18     INFO -  TEST-PASS | services/fxaccounts/tests/xpcshell/test_accounts.js | test_getSignedInUserProfile - [test_getSignedInUserProfile : 1369] "image" == "image"
[task 2017-01-24T16:32:18.846746Z] 16:32:18     INFO -  (xpcshell/head.js) | test run_next_test 38 pending (2)
[task 2017-01-24T16:32:18.848406Z] 16:32:18     INFO -  (xpcshell/head.js) | test test_getSignedInUserProfile finished (2)
[task 2017-01-24T16:32:18.849994Z] 16:32:18     INFO -  services/fxaccounts/tests/xpcshell/test_accounts.js | Starting test_getSignedInUserProfile_error_uses_account_data
[task 2017-01-24T16:32:18.851552Z] 16:32:18     INFO -  (xpcshell/head.js) | test test_getSignedInUserProfile_error_uses_account_data pending (2)
[task 2017-01-24T16:32:18.853089Z] 16:32:18     INFO -  PROCESS | 13182 | 1485275536439	FirefoxAccounts	DEBUG	setSignedInUser - aborting any existing flows
[task 2017-01-24T16:32:18.854913Z] 16:32:18     INFO -  (xpcshell/head.js) | test run_next_test 38 finished (2)
[task 2017-01-24T16:32:18.856749Z] 16:32:18     INFO -  PROCESS | 13182 | 1485275536441	FirefoxAccounts	DEBUG	Notifying observers of fxaccounts:onlogin
[task 2017-01-24T16:32:18.859320Z] 16:32:18     INFO -  PROCESS | 13182 | 1485275536443	FirefoxAccounts	ERROR	Could not retrieve profile data: boom
[task 2017-01-24T16:32:18.861196Z] 16:32:18     INFO -  PROCESS | 13182 | 1485275536443	FirefoxAccounts	ERROR	Could not retrieve profile data: boom
[task 2017-01-24T16:32:18.866390Z] 16:32:18     INFO -  PROCESS | 13182 | 1485275536444	FirefoxAccounts	ERROR	FxA rejecting with error UNKNOWN_ERROR, details: boom
[task 2017-01-24T16:32:18.868379Z] 16:32:18     INFO -  PROCESS | 13182 | 1485275536444	FirefoxAccounts	ERROR	FxA rejecting with error UNKNOWN_ERROR, details: boom
[task 2017-01-24T16:32:18.870261Z] 16:32:18     INFO -  TEST-PASS | services/fxaccounts/tests/xpcshell/test_accounts.js | test_getSignedInUserProfile_error_uses_account_data - [test_getSignedInUserProfile_error_uses_account_data : 1397] "UNKNOWN_ERROR" == "UNKNOWN_ERROR"
[task 2017-01-24T16:32:18.871901Z] 16:32:18     INFO -  PROCESS | 13182 | 1485275536448	FirefoxAccounts	DEBUG	destroying device and session
[task 2017-01-24T16:32:18.873621Z] 16:32:18     INFO -  PROCESS | 13182 | 1485275536448	FirefoxAccounts	DEBUG	Notifying observers of fxaccounts:onlogout
[task 2017-01-24T16:32:18.875627Z] 16:32:18     INFO -  TEST-PASS | services/fxaccounts/tests/xpcshell/test_accounts.js | test_getSignedInUserProfile_error_uses_account_data - [test_getSignedInUserProfile_error_uses_account_data : 1399] true == true
[task 2017-01-24T16:32:18.877085Z] 16:32:18     INFO -  (xpcshell/head.js) | test run_next_test 39 pending (2)
[task 2017-01-24T16:32:18.878728Z] 16:32:18     INFO -  (xpcshell/head.js) | test test_getSignedInUserProfile_error_uses_account_data finished (2)
[task 2017-01-24T16:32:18.880388Z] 16:32:18     INFO -  PROCESS | 13182 | 1485275536451	FirefoxAccounts	DEBUG	Notifying observers of testhelper-fxa-signout-complete
[task 2017-01-24T16:32:18.882315Z] 16:32:18     INFO -  services/fxaccounts/tests/xpcshell/test_accounts.js | Starting test_getSignedInUserProfile_unverified_account
[task 2017-01-24T16:32:18.884331Z] 16:32:18     INFO -  (xpcshell/head.js) | test test_getSignedInUserProfile_unverified_account pending (2)
[task 2017-01-24T16:32:18.886367Z] 16:32:18     INFO -  PROCESS | 13182 | 1485275536455	FirefoxAccounts	DEBUG	setSignedInUser - aborting any existing flows
[task 2017-01-24T16:32:18.894337Z] 16:32:18     INFO -  (xpcshell/head.js) | test run_next_test 39 finished (2)
[task 2017-01-24T16:32:18.896131Z] 16:32:18     INFO -  PROCESS | 13182 | 1485275536463	FirefoxAccounts	DEBUG	startVerifiedCheck: false
[task 2017-01-24T16:32:18.897969Z] 16:32:18     INFO -  PROCESS | 13182 | 1485275536464	FirefoxAccounts	DEBUG	whenVerified promise starts polling for verified email
[task 2017-01-24T16:32:18.899729Z] 16:32:18     INFO -  PROCESS | 13182 | 1485275536464	FirefoxAccounts	DEBUG	entering pollEmailStatus: start
[task 2017-01-24T16:32:18.901509Z] 16:32:18     INFO -  PROCESS | 13182 | 1485275536465	FirefoxAccounts	DEBUG	checkEmailStatus -> {"email":"nobody@example.com","verified":false}
[task 2017-01-24T16:32:18.903225Z] 16:32:18     INFO -  PROCESS | 13182 | 1485275536466	FirefoxAccounts	DEBUG	polling with timeout = 100
[task 2017-01-24T16:32:18.904851Z] 16:32:18     INFO -  PROCESS | 13182 | 1485275536466	FirefoxAccounts	DEBUG	startVerifiedCheck: false
[task 2017-01-24T16:32:18.906514Z] 16:32:18     INFO -  PROCESS | 13182 | 1485275536467	FirefoxAccounts	DEBUG	Notifying observers of fxaccounts:onlogin
[task 2017-01-24T16:32:18.908272Z] 16:32:18     INFO -  PROCESS | 13182 | 1485275536495	FirefoxAccounts	DEBUG	FxAccountsProfileClient: Initialized
[task 2017-01-24T16:32:18.910029Z] 16:32:18     INFO -  PROCESS | 13182 | JavaScript strict warning: resource://gre/modules/FxAccounts.jsm, line 1583: ReferenceError: reference to undefined property "profileCache"
[task 2017-01-24T16:32:18.911660Z] 16:32:18     INFO -  PROCESS | 13182 | 1485275536497	FirefoxAccounts	DEBUG	FxAccountsProfileClient: Requested profile
[task 2017-01-24T16:32:18.913299Z] 16:32:18     INFO -  PROCESS | 13182 | 1485275536498	FirefoxAccounts	DEBUG	getOAuthToken enter
[task 2017-01-24T16:32:18.915119Z] 16:32:18     INFO -  PROCESS | 13182 | 1485275536499	FirefoxAccounts	ERROR	FxA rejecting with error UNVERIFIED_ACCOUNT, details: undefined
[task 2017-01-24T16:32:18.916861Z] 16:32:18     INFO -  PROCESS | 13182 | 1485275536499	FirefoxAccounts	ERROR	FxA rejecting with error UNVERIFIED_ACCOUNT, details: undefined
[task 2017-01-24T16:32:18.918442Z] 16:32:18     INFO -  PROCESS | 13182 | *************************
[task 2017-01-24T16:32:18.920071Z] 16:32:18     INFO -  PROCESS | 13182 | A coding exception was thrown in a Promise rejection callback.
[task 2017-01-24T16:32:18.926244Z] 16:32:18     INFO -  PROCESS | 13182 | See https://developer.mozilla.org/Mozilla/JavaScript_code_modules/Promise.jsm/Promise
[task 2017-01-24T16:32:18.927950Z] 16:32:18     INFO -  PROCESS | 13182 | Full message: ReferenceError: e is not defined
[task 2017-01-24T16:32:18.929621Z] 16:32:18     INFO -  PROCESS | 13182 | Full stack: _fetchAndCacheProfileInternal/<@resource://gre/modules/FxAccountsProfile.jsm:110:11
[task 2017-01-24T16:32:18.931393Z] 16:32:18     INFO -  PROCESS | 13182 | process@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:920:21
[task 2017-01-24T16:32:18.933145Z] 16:32:18     INFO -  PROCESS | 13182 | walkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:801:7
[task 2017-01-24T16:32:18.934968Z] 16:32:18     INFO -  PROCESS | 13182 | Promise*scheduleWalkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:734:11
[task 2017-01-24T16:32:18.936562Z] 16:32:18     INFO -  PROCESS | 13182 | schedulePromise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:765:7
[task 2017-01-24T16:32:18.938336Z] 16:32:18     INFO -  PROCESS | 13182 | Promise.prototype.then@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:450:5
[task 2017-01-24T16:32:18.939904Z] 16:32:18     INFO -  PROCESS | 13182 | this.AccountState@resource://gre/modules/FxAccounts.jsm:96:29
[task 2017-01-24T16:32:18.941523Z] 16:32:18     INFO -  PROCESS | 13182 | newAccountState@/home/worker/workspace/build/tests/xpcshell/tests/services/fxaccounts/tests/xpcshell/test_accounts.js:159:14
[task 2017-01-24T16:32:18.943038Z] 16:32:18     INFO -  PROCESS | 13182 | initialize@resource://gre/modules/FxAccounts.jsm:381:32
[task 2017-01-24T16:32:18.944741Z] 16:32:18     INFO -  PROCESS | 13182 | this.FxAccounts@resource://gre/modules/FxAccounts.jsm:347:3
[task 2017-01-24T16:32:18.950267Z] 16:32:18     INFO -  PROCESS | 13182 | MockFxAccounts@/home/worker/workspace/build/tests/xpcshell/tests/services/fxaccounts/tests/xpcshell/test_accounts.js:146:10
[task 2017-01-24T16:32:18.952174Z] 16:32:18     INFO -  PROCESS | 13182 | test_getSignedInUserProfile_unverified_account@/home/worker/workspace/build/tests/xpcshell/tests/services/fxaccounts/tests/xpcshell/test_accounts.js:1407:13
[task 2017-01-24T16:32:18.953795Z] 16:32:18     INFO -  PROCESS | 13182 | _run_next_test@/home/worker/workspace/build/tests/xpcshell/head.js:1577:11
[task 2017-01-24T16:32:18.955473Z] 16:32:18     INFO -  PROCESS | 13182 | run@/home/worker/workspace/build/tests/xpcshell/head.js:710:9
[task 2017-01-24T16:32:18.957042Z] 16:32:18     INFO -  PROCESS | 13182 | _do_main@/home/worker/workspace/build/tests/xpcshell/head.js:210:5
[task 2017-01-24T16:32:18.958623Z] 16:32:18     INFO -  PROCESS | 13182 | _execute_test@/home/worker/workspace/build/tests/xpcshell/head.js:545:5
[task 2017-01-24T16:32:18.960022Z] 16:32:18     INFO -  PROCESS | 13182 | @-e:1:1
[task 2017-01-24T16:32:18.961461Z] 16:32:18     INFO -  PROCESS | 13182 | *************************
[task 2017-01-24T16:32:18.964417Z] 16:32:18     INFO -  PROCESS | 13182 | 1485275536505	FirefoxAccounts	ERROR	Could not retrieve profile data: ReferenceError: e is not defined (resource://gre/modules/FxAccountsProfile.jsm:110:11) JS Stack trace: _fetchAndCacheProfileInternal/<@FxAccountsProfile.jsm:110:11 < process@Promise-backend.js:920:21 < walkerLoop@Promise-backend.js:801:7 < Promise*scheduleWalkerLoop@Promise-backend.js:734:11 < schedulePromise@Promise-backend.js:765:7 < Promise.prototype.then@Promise-backend.js:450:5 < this.AccountState@FxAccounts.jsm:96:29 < newAccountState@test_accounts.js:159:14 < initialize@FxAccounts.jsm:381:32 < this.FxAccounts@FxAccounts.jsm:347:3 < MockFxAccounts@test_accounts.js:146:10 < test_getSignedInUserProfile_unverified_account@test_accounts.js:1407:13 < _run_next_test@head.js:1577:11 < run@head.js:710:9 < _do_main@head.js:210:5 < _execute_test@head.js:545:5 < @-e:1:1
[task 2017-01-24T16:32:18.967552Z] 16:32:18     INFO -  PROCESS | 13182 | 1485275536505	FirefoxAccounts	ERROR	Could not retrieve profile data: ReferenceError: e is not defined (resource://gre/modules/FxAccountsProfile.jsm:110:11) JS Stack trace: _fetchAndCacheProfileInternal/<@FxAccountsProfile.jsm:110:11 < process@Promise-backend.js:920:21 < walkerLoop@Promise-backend.js:801:7 < Promise*scheduleWalkerLoop@Promise-backend.js:734:11 < schedulePromise@Promise-backend.js:765:7 < Promise.prototype.then@Promise-backend.js:450:5 < this.AccountState@FxAccounts.jsm:96:29 < newAccountState@test_accounts.js:159:14 < initialize@FxAccounts.jsm:381:32 < this.FxAccounts@FxAccounts.jsm:347:3 < MockFxAccounts@test_accounts.js:146:10 < test_getSignedInUserProfile_unverified_account@test_accounts.js:1407:13 < _run_next_test@head.js:1577:11 < run@head.js:710:9 < _do_main@head.js:210:5 < _execute_test@head.js:545:5 < @-e:1:1
[task 2017-01-24T16:32:18.975303Z] 16:32:18     INFO -  PROCESS | 13182 | 1485275536512	FirefoxAccounts	ERROR	FxA rejecting with error UNKNOWN_ERROR, details: ReferenceError: e is not defined (resource://gre/modules/FxAccountsProfile.jsm:110:11) JS Stack trace: _fetchAndCacheProfileInternal/<@FxAccountsProfile.jsm:110:11 < process@Promise-backend.js:920:21 < walkerLoop@Promise-backend.js:801:7 < Promise*scheduleWalkerLoop@Promise-backend.js:734:11 < schedulePromise@Promise-backend.js:765:7 < Promise.prototype.then@Promise-backend.js:450:5 < this.AccountState@FxAccounts.jsm:96:29 < newAccountState@test_accounts.js:159:14 < initialize@FxAccounts.jsm:381:32 < this.FxAccounts@FxAccounts.jsm:347:3 < MockFxAccounts@test_accounts.js:146:10 < test_getSignedInUserProfile_unverified_account@test_accounts.js:1407:13 < _run_next_test@head.js:1577:11 < run@head.js:710:9 < _do_main@head.js:210:5 < _execute_test@head.js:545:5 < @-e:1:1
[task 2017-01-24T16:32:18.980158Z] 16:32:18     INFO -  PROCESS | 13182 | 1485275536512	FirefoxAccounts	ERROR	FxA rejecting with error UNKNOWN_ERROR, details: ReferenceError: e is not defined (resource://gre/modules/FxAccountsProfile.jsm:110:11) JS Stack trace: _fetchAndCacheProfileInternal/<@FxAccountsProfile.jsm:110:11 < process@Promise-backend.js:920:21 < walkerLoop@Promise-backend.js:801:7 < Promise*scheduleWalkerLoop@Promise-backend.js:734:11 < schedulePromise@Promise-backend.js:765:7 < Promise.prototype.then@Promise-backend.js:450:5 < this.AccountState@FxAccounts.jsm:96:29 < newAccountState@test_accounts.js:159:14 < initialize@FxAccounts.jsm:381:32 < this.FxAccounts@FxAccounts.jsm:347:3 < MockFxAccounts@test_accounts.js:146:10 < test_getSignedInUserProfile_unverified_account@test_accounts.js:1407:13 < _run_next_test@head.js:1577:11 < run@head.js:710:9 < _do_main@head.js:210:5 < _execute_test@head.js:545:5 < @-e:1:1
[task 2017-01-24T16:32:18.985005Z] 16:32:18  WARNING -  TEST-UNEXPECTED-FAIL | services/fxaccounts/tests/xpcshell/test_accounts.js | test_getSignedInUserProfile_unverified_account - [test_getSignedInUserProfile_unverified_account : 1413] "UNKNOWN_ERROR" == "UNVERIFIED_ACCOUNT"
[task 2017-01-24T16:32:18.986188Z] 16:32:18     INFO -  /home/worker/workspace/build/tests/xpcshell/tests/services/fxaccounts/tests/xpcshell/test_accounts.js:test_getSignedInUserProfile_unverified_account/</<:1413

Flags: needinfo?(eoger)

Comment hidden (mozreview-request)

Comment on attachment 8829471 [details]
Bug 1332993 - Do not write logs on FxA profile 304 response.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/106564/diff/1-2/

Edouard Oger [:eoger]

Assignee

Comment 9

•

7 years ago

Sorry about that, re-landing the fixed patch.

Flags: needinfo?(eoger)

Pulsebot

Comment 10

•

7 years ago

Pushed by eoger@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/d7c0d2ef9e10
Do not write logs on FxA profile 304 response. r=markh

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

Comment 11

•

7 years ago

bugherder

https://hg.mozilla.org/mozilla-central/rev/d7c0d2ef9e10

Status: ASSIGNED → RESOLVED

Closed: 7 years ago

status-firefox54: --- → fixed

Resolution: --- → FIXED

Target Milestone: --- → mozilla54

BMO Automation

Updated

•

7 years ago

Product: Core → Firefox

Dylan Hardison [:dylan] (he/him)

Updated

•

7 years ago

Target Milestone: mozilla54 → Firefox 54

Bugzilla

Quick Search

Error logs written on profile fetch 304 response

Categories

(Firefox :: Firefox Accounts, defect, P1)

Tracking

()

People

(Reporter: markh, Assigned: eoger)

References

Details

Crash Data

Security

(public)

User Story

Attachments

(1 file)

Description

Updated

Comment 1

Comment 2

Comment 3

Comment 4

Comment 5

Comment 6

Updated

Comment 7

Comment 8

Comment 9

Comment 10

Comment 11

Updated

Updated

Attachment

General

Description

File Name

Content Type