Closed Bug 1332993 Opened 9 years ago Closed 9 years ago

Error logs written on profile fetch 304 response

Categories

(Firefox :: Firefox Accounts, defect, P1)

Product:
Firefox
Component:
Firefox Accounts
Type:
defect

Tracking

()

Status:
RESOLVED FIXED
Milestone:
Firefox 54
Tracking Flags:
Tracking Status
firefox54 --- fixed

People

(Reporter: markh, Assigned: eoger)

References

Details

Attachments

(1 file)

Bug 1332993 - Do not write logs on FxA profile 304 response.
59 bytes, text/x-review-board-request
markh
: review+
Details
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)
Assignee: nobody → eoger
Status: NEW → ASSIGNED
Priority: -- → P1
Sorry about this, I removed a bit too much code when I simplified the error handling in bug 1323102.
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 (...) });?
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+
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)
Pushed by eoger@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/ccc602619a07 Do not write logs on FxA profile 304 response. r=markh
See Also: → 1333431
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)
Sorry about that, re-landing the fixed patch.
Flags: needinfo?(eoger)
Pushed by eoger@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/d7c0d2ef9e10 Do not write logs on FxA profile 304 response. r=markh
https://hg.mozilla.org/mozilla-central/rev/d7c0d2ef9e10
Status: ASSIGNED → RESOLVED
Closed: 9 years ago
status-firefox54: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla54
Product: Core → Firefox
Target Milestone: mozilla54 → Firefox 54
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: