Closed Bug 1718404 Opened 4 years ago Closed 4 years ago

High frequency browser/components/places/tests/browser/interactions/browser_interactions_typing.js | Should have stored at least this amount of typing time. - 0 > 0 - JS frame :: mochitests/content/browser/browser/components/places/tests/browser/in

Categories

(Firefox :: Bookmarks & History, defect, P5)

defect

Tracking

()

RESOLVED FIXED
94 Branch
Tracking Status
firefox-esr78 --- unaffected
firefox-esr91 --- fixed
firefox92 --- unaffected
firefox93 --- fixed
firefox94 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: acreskey)

References

(Regression)

Details

(Keywords: intermittent-failure, regression, Whiteboard: [stockwell unknown])

Attachments

(1 file)

Filed by: nbeleuzu [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=343940344&repo=try
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/e28zjWhVSxKob3qsoIFThw/runs/0/artifacts/public/logs/live_backing.log


[task 2021-06-26T14:01:14.943Z] 14:01:14     INFO - TEST-PASS | browser/components/places/tests/browser/interactions/browser_interactions_typing.js | Should have saved the keypresses into the database - 9 == 9 - 
[task 2021-06-26T14:01:14.944Z] 14:01:14     INFO - Buffered messages finished
[task 2021-06-26T14:01:14.944Z] 14:01:14     INFO - TEST-UNEXPECTED-FAIL | browser/components/places/tests/browser/interactions/browser_interactions_typing.js | Should have stored at least this amount of typing time. - 0 > 0 - JS frame :: chrome://mochitests/content/browser/browser/components/places/tests/browser/interactions/head.js :: assertDatabaseValues :: line 116
[task 2021-06-26T14:01:14.944Z] 14:01:14     INFO - Stack trace:
[task 2021-06-26T14:01:14.944Z] 14:01:14     INFO - chrome://mochitests/content/browser/browser/components/places/tests/browser/interactions/head.js:assertDatabaseValues:116
[task 2021-06-26T14:01:14.945Z] 14:01:14     INFO - reload
[task 2021-06-26T14:01:14.945Z] 14:01:14     INFO - GECKO(5280) | console.debug: InteractionsManager: "End of interaction"
[task 2021-06-26T14:01:14.946Z] 14:01:14     INFO - GECKO(5280) | console.debug: InteractionsManager: "Add to store: " ({url:"https://example.com/browser/browser/components/places/tests/browser/keyword_form.html", totalViewTime:17.463638000001083, typingTime:1, keypresses:10, created_at:1624716074794, updated_at:1624716074812})
[task 2021-06-26T14:01:14.946Z] 14:01:14     INFO - GECKO(5280) | console.debug: InteractionsManager: "New interaction" ({isActive:true, url:"https://example.com/browser/browser/components/places/tests/browser/keyword_form.html"})
[task 2021-06-26T14:01:14.946Z] 14:01:14     INFO - GECKO(5280) | console.debug: InteractionsManager: "Storing 1 entries in the database"
[task 2021-06-26T14:01:14.947Z] 14:01:14     INFO - Found 2 interactions:
[task 2021-06-26T14:01:14.947Z] 14:01:14     INFO -  [{"url":"https://example.com/browser/browser/components/places/tests/browser/keyword_form.html","keypresses":9,"typingTime":0,"totalViewTime":453},{"url":"https://example.com/browser/browser/components/places/tests/browser/keyword_form.html","keypresses":10,"typingTime":1,"totalViewTime":17}]

This went to almost perma-fail after Bug 1717920 landed here.
Andrew, could you please have a look over what's going on here? Thank you.

Flags: needinfo?(acreskey)
Regressed by: 1717920
Summary: Intermittent browser/components/places/tests/browser/interactions/browser_interactions_typing.js | Should have stored at least this amount of typing time. - 0 > 0 - JS frame :: chrome://mochitests/content/browser/browser/components/places/tests/browser/in → High frequency browser/components/places/tests/browser/interactions/browser_interactions_typing.js | Should have stored at least this amount of typing time. - 0 > 0 - JS frame :: mochitests/content/browser/browser/components/places/tests/browser/in
Has Regression Range: --- → yes

Update:
There have been 36 failures within the last 7 days, all on OS X 11 WebRender Shippable opt.
Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=350616070&repo=autoland&lineNumber=5254

[task 2021-09-06T00:27:33.634Z] 00:27:33     INFO - TEST-START | browser/components/places/tests/browser/interactions/browser_interactions_typing.js
[task 2021-09-06T00:27:33.634Z] 00:27:33     INFO - GECKO(2676) | console.debug: InteractionsManager: "Database reset"
[task 2021-09-06T00:27:33.636Z] 00:27:33     INFO - GECKO(2676) | console.debug: InteractionsManager: "Database reset"
[task 2021-09-06T00:27:33.639Z] 00:27:33     INFO - GECKO(2676) | console.debug: InteractionsManager: "Tab switched"
[task 2021-09-06T00:27:33.639Z] 00:27:33     INFO - GECKO(2676) | console.debug: InteractionsManager: "No interaction to update"
[task 2021-09-06T00:27:33.655Z] 00:27:33     INFO - GECKO(2676) | console.debug: InteractionsManager: "Tracking a new interaction" ({isActive:true, url:"https://example.com/browser/browser/components/places/tests/browser/keyword_form.html", referrer:(void 0)})
[task 2021-09-06T00:27:33.976Z] 00:27:33     INFO - GECKO(2676) | console.debug: InteractionsManager: "Saw the end of an interaction"
[task 2021-09-06T00:27:33.980Z] 00:27:33     INFO - GECKO(2676) | console.debug: InteractionsManager: "Add to store: " ({url:"https://example.com/browser/browser/components/places/tests/browser/keyword_form.html", referrer:(void 0), totalViewTime:320.4067083333339, typingTime:0, keypresses:0, scrollingTime:0, scrollingDistance:0, created_at:1630888053655, updated_at:1630888053978})
[task 2021-09-06T00:27:33.980Z] 00:27:33     INFO - GECKO(2676) | console.debug: InteractionsManager: "Preparing interaction for storage" ({url:"https://example.com/browser/browser/components/places/tests/browser/keyword_form.html", referrer:(void 0), totalViewTime:320.4067083333339, typingTime:0, keypresses:0, scrollingTime:0, scrollingDistance:0, created_at:1630888053655, updated_at:1630888053978})
[task 2021-09-06T00:27:33.988Z] 00:27:33     INFO - GECKO(2676) | console.debug: InteractionsManager: "Tracking a new interaction" ({isActive:true, url:"https://example.com/browser", referrer:(void 0)})
[task 2021-09-06T00:27:33.989Z] 00:27:33     INFO - GECKO(2676) | console.debug: InteractionsManager: "Storing 1 entries in the database"
[task 2021-09-06T00:27:33.990Z] 00:27:33     INFO - GECKO(2676) | console.debug: SnapshotsManager: "Testing 1 potential snapshots"
[task 2021-09-06T00:27:33.995Z] 00:27:33     INFO - GECKO(2676) | console.debug: InteractionsManager: "Saw the end of an interaction"
<...>
[task 2021-09-06T00:27:39.427Z] 00:27:39     INFO - TEST-PASS | browser/components/places/tests/browser/interactions/browser_interactions_typing.js | Should have stored at least this amount of typing time. - 1 > 0 - 
[task 2021-09-06T00:27:39.427Z] 00:27:39     INFO - reload
[task 2021-09-06T00:27:39.427Z] 00:27:39     INFO - Found 2 interactions:
[task 2021-09-06T00:27:39.427Z] 00:27:39     INFO -  [{"url":"https://example.com/browser/browser/components/places/tests/browser/keyword_form.html","referrerUrl":null,"keypresses":9,"typingTime":1,"totalViewTime":706,"scrollingTime":0,"scrollingDistance":0},{"url":"https://example.com/browser/browser/components/places/tests/browser/keyword_form.html","referrerUrl":null,"keypresses":10,"typingTime":0,"totalViewTime":14,"scrollingTime":0,"scrollingDistance":0}]
[task 2021-09-06T00:27:39.427Z] 00:27:39     INFO - TEST-PASS | browser/components/places/tests/browser/interactions/browser_interactions_typing.js | Found the expected number of entries - 2 == 2 - 
[task 2021-09-06T00:27:39.428Z] 00:27:39     INFO - TEST-PASS | browser/components/places/tests/browser/interactions/browser_interactions_typing.js | Should have saved the page into the database - "https://example.com/browser/browser/components/places/tests/browser/keyword_form.html" == "https://example.com/browser/browser/components/places/tests/browser/keyword_form.html" - 
[task 2021-09-06T00:27:39.428Z] 00:27:39     INFO - TEST-PASS | browser/components/places/tests/browser/interactions/browser_interactions_typing.js | Should have saved the keypresses into the database - 9 == 9 - 
[task 2021-09-06T00:27:39.428Z] 00:27:39     INFO - TEST-PASS | browser/components/places/tests/browser/interactions/browser_interactions_typing.js | Should have stored at least this amount of typing time. - 1 > 0 - 
[task 2021-09-06T00:27:39.428Z] 00:27:39     INFO - TEST-PASS | browser/components/places/tests/browser/interactions/browser_interactions_typing.js | Should have saved the page into the database - "https://example.com/browser/browser/components/places/tests/browser/keyword_form.html" == "https://example.com/browser/browser/components/places/tests/browser/keyword_form.html" - 
[task 2021-09-06T00:27:39.428Z] 00:27:39     INFO - TEST-PASS | browser/components/places/tests/browser/interactions/browser_interactions_typing.js | Should have saved the keypresses into the database - 10 == 10 - 
[task 2021-09-06T00:27:39.428Z] 00:27:39     INFO - Buffered messages finished
[task 2021-09-06T00:27:39.429Z] 00:27:39     INFO - TEST-UNEXPECTED-FAIL | browser/components/places/tests/browser/interactions/browser_interactions_typing.js | Should have stored at least this amount of typing time. - 0 > 0 - JS frame :: chrome://mochitests/content/browser/browser/components/places/tests/browser/interactions/head.js :: assertDatabaseValues :: line 121
[task 2021-09-06T00:27:39.429Z] 00:27:39     INFO - Stack trace:
[task 2021-09-06T00:27:39.429Z] 00:27:39     INFO - chrome://mochitests/content/browser/browser/components/places/tests/browser/interactions/head.js:assertDatabaseValues:121
[task 2021-09-06T00:27:39.429Z] 00:27:39     INFO - GECKO(2676) | console.debug: InteractionsManager: "Tab switched"
[task 2021-09-06T00:27:39.429Z] 00:27:39     INFO - Leaving test bound test_typing_and_reload
[task 2021-09-06T00:27:39.429Z] 00:27:39     INFO - Entering test bound test_switch_tabs_no_typing
[task 2021-09-06T00:27:39.429Z] 00:27:39     INFO - GECKO(2676) | console.debug: InteractionsManager: "Database reset"
[task 2021-09-06T00:27:39.429Z] 00:27:39     INFO - GECKO(2676) | console.debug: InteractionsManager: "Add to store: " ({url:"https://example.com/browser/browser/components/places/tests/browser/keyword_form.html", referrer:(void 0), totalViewTime:3.7450416666670208, typingTime:0, keypresses:0, scrollingTime:0, scrollingDistance:0, created_at:1630888059288, updated_at:1630888059295})
[task 2021-09-06T00:27:39.430Z] 00:27:39     INFO - GECKO(2676) | console.debug: InteractionsManager: "Preparing interaction for storage" ({url:"https://example.com/browser/browser/components/places/tests/browser/keyword_form.html", referrer:(void 0), totalViewTime:3.7450416666670208, typingTime:0, keypresses:0, scrollingTime:0, scrollingDistance:0, created_at:1630888059288, updated_at:1630888059295})
[task 2021-09-06T00:27:39.430Z] 00:27:39     INFO - GECKO(2676) | console.debug: InteractionsManager: "Tab switched"
[task 2021-09-06T00:27:39.430Z] 00:27:39     INFO - GECKO(2676) | console.debug: InteractionsManager: "No interaction to update"
<...>
[task 2021-09-06T00:27:42.145Z] 00:27:42     INFO - TEST-OK | browser/components/places/tests/browser/interactions/browser_interactions_typing.js | took 8512ms
[task 2021-09-06T00:27:42.148Z] 00:27:42     INFO - GECKO(2676) | console.debug: InteractionsManager: "Tab switched"
[task 2021-09-06T00:27:42.148Z] 00:27:42     INFO - GECKO(2676) | console.debug: InteractionsManager: "No interaction to update"
[task 2021-09-06T00:27:42.149Z] 00:27:42     INFO - checking window state
[task 2021-09-06T00:27:42.150Z] 00:27:42     INFO - TEST-START | browser/components/places/tests/browser/interactions/browser_interactions_view_time.js
Whiteboard: [stockwell needswork:owner]

Marco, as the owner of this component, could you help us assign it to someone?
Thank you.

Flags: needinfo?(mak)

I think I might know what's happening here. The typing plus reload is potentially happening too fast, taking less than 1ms to complete. I'll try adding in a small delay and see if that helps.

Assignee: nobody → standard8
Flags: needinfo?(mak)
Flags: needinfo?(acreskey)

Thanks :standard8 - let me know if you want me to take this one over.

Patch incoming.

Assignee: standard8 → acreskey

Fix a scenario where it was possible, in automation, for the typing interaction time to report 0ms due to rounding of fractional milliseconds.

In addition, now sending keystrokes individually as this is a better simulation of how users type.

The patch looks like it resolve the intermittent:
https://treeherder.mozilla.org/jobs?repo=try&revision=3119d0a152cd81f7da4338c9f82de0d714a1436d&selectedTaskRun=ZB2WSWnQSAG_mC8gLmDn3A.0

:CosminS, thanks for flagging this one.

Pushed by acreskey@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/436407544606 Fix high frequency browser_interactions_typing.js failure r=Standard8
Status: NEW → RESOLVED
Closed: 4 years ago
Resolution: --- → FIXED
Target Milestone: --- → 94 Branch

Should we uplift to beta? Thanks

Flags: needinfo?(acreskey)

The fix is extremely low risk to users, so I am in favor of uplifting this.

Flags: needinfo?(acreskey)

OK, could you request the uplift to beta via our bugzilla uplift form? Thanks

Flags: needinfo?(acreskey)

(In reply to Pascal Chevrel:pascalc from comment #25)

OK, could you request the uplift to beta via our bugzilla uplift form? Thanks

Hi Pascal - certainly. Can you point me to where those forms are? I have done that before and I haven't found help on it.

(In reply to Andrew Creskey [:acreskey] [he/him] from comment #26)

(In reply to Pascal Chevrel:pascalc from comment #25)

OK, could you request the uplift to beta via our bugzilla uplift form? Thanks

Hi Pascal - certainly. Can you point me to where those forms are? I have done that before and I haven't found help on it.

Here is a screencast showing how to trigger the form in Bugzilla UI https://video.chevrel.org/demos/upliftRequestForm.mp4

Comment on attachment 9240524 [details]
Bug 1718404 - Fix high frequency browser_interactions_typing.js failure r=standard8

Beta/Release Uplift Approval Request

  • User impact if declined: There is no impact to users.
    The change fixes a rounding error which was making an automated tests fail (for a currently unused feature - user interactions).
  • Is this code covered by automated tests?: Yes
  • Has the fix been verified in Nightly?: Yes
  • Needs manual test from QE?: No
  • If yes, steps to reproduce:
  • List of other uplifts needed: None
  • Risk to taking this patch: Low
  • Why is the change risky/not risky? (and alternatives if risky): The change is not risky for two reasons:
    -The feature, user interactions in history metadata, is disabled by default.
    -The change is only to a calculation for that feature and to the automated tests.
  • String changes made/needed:
Flags: needinfo?(acreskey)
Attachment #9240524 - Flags: approval-mozilla-beta?

(In reply to Pascal Chevrel:pascalc from comment #27)

(In reply to Andrew Creskey [:acreskey] [he/him] from comment #26)

(In reply to Pascal Chevrel:pascalc from comment #25)

OK, could you request the uplift to beta via our bugzilla uplift form? Thanks

Hi Pascal - certainly. Can you point me to where those forms are? I have done that before and I haven't found help on it.

Here is a screencast showing how to trigger the form in Bugzilla UI https://video.chevrel.org/demos/upliftRequestForm.mp4

Thank you Pascal - the screencast is worth 1000 words.

Comment on attachment 9240524 [details]
Bug 1718404 - Fix high frequency browser_interactions_typing.js failure r=standard8

Approved for 93.0b7, thanks.

Attachment #9240524 - Flags: approval-mozilla-beta? → approval-mozilla-beta+

Can you run an uplift this of this onto ESR91 through Try to confirm that the fix works there too?

Flags: needinfo?(ryanvm) → needinfo?(ctuns)

We don't run fission tests on ESR91. I don't see any failures on that Try push for non-Fission jobs?

Flags: needinfo?(ryanvm) → needinfo?(nbeleuzu)

Comment on attachment 9240524 [details]
Bug 1718404 - Fix high frequency browser_interactions_typing.js failure r=standard8

ESR Uplift Approval Request

  • If this is not a sec:{high,crit} bug, please state case for ESR consideration: frequent test failure
  • User impact if declined: none
  • Fix Landed on Version: 94
  • Risk to taking this patch: Low
  • Why is the change risky/not risky? (and alternatives if risky): only rounds up time duration for typing
  • String or UUID changes made by this patch: none
Attachment #9240524 - Flags: approval-mozilla-esr91?
Flags: needinfo?(ctuns)

The failures were only on Fission jobs but I thought it worth mentioning them.

Flags: needinfo?(nbeleuzu)

Comment on attachment 9240524 [details]
Bug 1718404 - Fix high frequency browser_interactions_typing.js failure r=standard8

Approved for 91.3esr.

Attachment #9240524 - Flags: approval-mozilla-esr91? → approval-mozilla-esr91+
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: