974990 - RESTRequest should read intl.accept_languages as infrequently as possible

Status: RESOLVED FIXED

(Firefox :: Firefox Accounts, defect)

Description

[Jed Parsons (use needinfo, please) [:jedp, :jparsons]]

Per Bug 955953 Comment 13

Read the intl.accept_languages the first time a RESTRequest is instantiated, and then subsequently only when we observe "nsPref:changed" for this pref.

This should reduce the overhead of accessing the pref, and also take care of the potential log spam on error.

Comment 1

[Jed Parsons (use needinfo, please) [:jedp, :jparsons]]

Attachment: 974990-accept-languages.patch

Hi, Richard,

This is a first stab at a patch.  I have three questions I'd like your advice on, if you don't mind:

- Is it too gross to have the stateful Intl object in rest.js?  Should it be moved to another file?  I feel like this is also wasting memory for people who don't use hawk requests.

- Am I fooling myself with the uninit() method in there?  Is it ever going to be called when the object is cleaned up?  Does it matter?  What's the best practice for removing this perpetual observer?

- I've set up the tests to make use of do_execute_soon() in order to give the pref listener in Intl a chance to catch changes.  Am I fooling myself here, too?  If this is not a guaranteed way to wait for the observer queue to drain and all listeners to have a chance to react, what is the right way?

As always, many thanks,
j

Comment 2

[Richard Newman [:rnewman]]

Comment on attachment 8379229 [details] [diff] [review]
974990-accept-languages.patch

Review of attachment 8379229 [details] [diff] [review]:
-----------------------------------------------------------------

Now is probably a good time to move HAWKAuthenticatedRESTRequest, and Intl, into services/common/hawkrequest.js. That solves your first concern.

Yeah, you're probably fooling yourself with uninit, but at least you can use it for testing.

Re do_execute_soon: take a look in services/common/tests/unit/test_restrequest.js for the use of CommonUtils.nextTick, which is a strictly less shitty way to decide which event loop tick your code runs on.

::: services/common/rest.js
@@ +757,5 @@
> +// pref is changed.
> +this.Intl = function Intl() {
> +  // We won't actually query the pref until the first time we need it
> +  this._accepted = "";
> +  this._readOnce = false;

s/_readOnce/_everRead

@@ +772,5 @@
> +    Services.prefs.removeObserver("intl.accept_languages", this);
> +  },
> +
> +  observe: function(subject, topic, data) {
> +    this.readPref();

And

  this._readOnce = true;

-- if it changes before you make a HAWK request, and you don't set this, you'll fetch twice.

::: services/common/tests/unit/test_restrequest.js
@@ +871,5 @@
> +        setLanguage(languages[testCount]);
> +        nextTest();
> +        return;
> +      }
> +      Services.prefs.removeObserver("intl.accept_languages", nextTest);

And you should be calling hawk._intl.uninit() at some point, maybe in a cleanup phase.

@@ +873,5 @@
> +        return;
> +      }
> +      Services.prefs.removeObserver("intl.accept_languages", nextTest);
> +      do_test_finished();
> +      run_next_test();

Don't mix these two.

@@ +883,2 @@
>  add_test(function test_hawk_authenticated_request() {
>    do_test_pending();

Not needed. Call run_next_test when you're ready.

@@ +931,5 @@
>        response.bodyOutputStream.write(message, message.length);
> +      } catch(err) {
> +        message = JSON.stringify({error: err});
> +      response.setStatusLine(request.httpVersion, 200, "OK");
> +      response.bodyOutputStream.write(message, message.length);

Alignment.

@@ +970,3 @@
>  });
> +
> +add_test(function test_hawk_langauge_pref_changed() {

s/gauge/guage

@@ +1032,5 @@
> +
> +      Services.prefs.resetUserPrefs();
> +
> +      do_test_finished();
> +      server.stop(run_next_test);

Don't mix these.

Comment 3

[Jed Parsons (use needinfo, please) [:jedp, :jparsons]]

(In reply to Richard Newman [:rnewman] from comment #2)
> Comment on attachment 8379229 [details] [diff] [review]
> 974990-accept-languages.patch
> 
> Review of attachment 8379229 [details] [diff] [review]:
> -----------------------------------------------------------------

Thank you for your super-fast feedback, rnewman.

> Now is probably a good time to move HAWKAuthenticatedRESTRequest, and Intl,
> into services/common/hawkrequest.js. That solves your first concern.

Done.

I've renamed hawk.js to hawkclient.js to avoid confusion.

> Yeah, you're probably fooling yourself with uninit, but at least you can use
> it for testing.

Ok.

> Re do_execute_soon: take a look in
> services/common/tests/unit/test_restrequest.js for the use of
> CommonUtils.nextTick, which is a strictly less **** way to decide which
> event loop tick your code runs on.

Perfect.  Thanks.  I see from the documentation that this ensures my code will run on the next tick, not some later tick, as do_execute_soon would do.  This makes me feel more confident about not causing intermittent orange failures.

> ::: services/common/rest.js
> @@ +757,5 @@
> > +// pref is changed.
> > +this.Intl = function Intl() {
> > +  // We won't actually query the pref until the first time we need it
> > +  this._accepted = "";
> > +  this._readOnce = false;
> 
> s/_readOnce/_everRead

Better.  Thanks.

> @@ +772,5 @@
> > +    Services.prefs.removeObserver("intl.accept_languages", this);
> > +  },
> > +
> > +  observe: function(subject, topic, data) {
> > +    this.readPref();
> 
> And
> 
>   this._readOnce = true;
> 
> -- if it changes before you make a HAWK request, and you don't set this,
> you'll fetch twice.

It seems unlikely that this would happen.  Should I handle this differently?

> ::: services/common/tests/unit/test_restrequest.js
> @@ +871,5 @@
> > +        setLanguage(languages[testCount]);
> > +        nextTest();
> > +        return;
> > +      }
> > +      Services.prefs.removeObserver("intl.accept_languages", nextTest);
> 
> And you should be calling hawk._intl.uninit() at some point, maybe in a
> cleanup phase.

Done.

> @@ +873,5 @@
> > +        return;
> > +      }
> > +      Services.prefs.removeObserver("intl.accept_languages", nextTest);
> > +      do_test_finished();
> > +      run_next_test();
> 
> Don't mix these two.

Thanks.  I have to break this habit.

> @@ +883,2 @@
> >  add_test(function test_hawk_authenticated_request() {
> >    do_test_pending();
> 
> Not needed. Call run_next_test when you're ready.

Thanks.

> @@ +931,5 @@
> >        response.bodyOutputStream.write(message, message.length);
> > +      } catch(err) {
> > +        message = JSON.stringify({error: err});
> > +      response.setStatusLine(request.httpVersion, 200, "OK");
> > +      response.bodyOutputStream.write(message, message.length);
> 
> Alignment.

Sorry, this was residue of a hasty try/catch to debug the server.  I've removed the code.

> @@ +970,3 @@
> >  });
> > +
> > +add_test(function test_hawk_langauge_pref_changed() {
> 
> s/gauge/guage

Semper sic erro.

> @@ +1032,5 @@
> > +
> > +      Services.prefs.resetUserPrefs();
> > +
> > +      do_test_finished();
> > +      server.stop(run_next_test);
> 
> Don't mix these.

Unmixed.

Thank you again for your comments!  This was very helpful.

Comment 4

[Jed Parsons (use needinfo, please) [:jedp, :jparsons]]

Attachment: hawk request access lang prefs as infrequently as possible

f=rnewman

Addresses comments in Comment 2

This patch to be applied over Bug 945363 and Bug 955953; Waiting for those to land.

Comment 5

[Jed Parsons (use needinfo, please) [:jedp, :jparsons]]

Actually this doesn't need Bug 945363.

Comment 6

[Richard Newman [:rnewman]]

Comment on attachment 8379376 [details] [diff] [review]
hawk request access lang prefs as infrequently as possible

Review of attachment 8379376 [details] [diff] [review]:
-----------------------------------------------------------------

rs=me

::: services/common/hawkrequest.js
@@ +112,5 @@
> +    Services.prefs.removeObserver("intl.accept_languages", this);
> +  },
> +
> +  observe: function(subject, topic, data) {
> +    this.readPref();

Yes, it's unlikely that someone will change the pref before the first request… but in the interests of thoroughness, might as well set the _everRead flag here. (Or just set it in `readPref`!)

Comment 7

[Jed Parsons (use needinfo, please) [:jedp, :jparsons]]

(In reply to Richard Newman [:rnewman] from comment #6)
> Comment on attachment 8379376 [details] [diff] [review]
> hawk request access lang prefs as infrequently as possible
> 
> Review of attachment 8379376 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> rs=me

w00t!

> ::: services/common/hawkrequest.js
> @@ +112,5 @@
> > +    Services.prefs.removeObserver("intl.accept_languages", this);
> > +  },
> > +
> > +  observe: function(subject, topic, data) {
> > +    this.readPref();
> 
> Yes, it's unlikely that someone will change the pref before the first
> request… but in the interests of thoroughness, might as well set the
> _everRead flag here. (Or just set it in `readPref`!)

Good point!  Done.

Comment 8

[Jed Parsons (use needinfo, please) [:jedp, :jparsons]]

Attachment: hawk request access lang prefs as infrequently as possible

sr=rnewman

With last proposed change

Comment 9

[Jed Parsons (use needinfo, please) [:jedp, :jparsons]]

xpcshell tests suddenly broken on inbound:

  DistutilsFileError: can't copy '/Users/zeus/code/firefox/build_inbound/dist/plugins/JavaTest.plugin/Contents/Info.plist': doesn't exist or not a regular file

Possibly related to last pulled changeset?:

  changeset:   169779:128cbf1edc40
  summarn:     Backed out 7 changesets (bug 406541, bug 738396, bug 852315, bug 971273, bug 971279) for various java/plugin-related failures

Holding off on checking in until this is sorted out and I can re-run all the tests one last time.

Comment 10

[Richard Newman [:rnewman]]

(In reply to Jed Parsons (use needinfo, please) [:jedp, :jparsons] from comment #8)
> Created attachment 8379409 [details] [diff] [review]
> hawk request access lang prefs as infrequently as possible
> 
> sr=rnewman
> 
> With last proposed change

N.B., rs == rubberstamp, sr == superreview :P

Comment 11

[Jed Parsons (use needinfo, please) [:jedp, :jparsons]]

LOL.  I'm still learning this language, I guess.

Comment 12

[Jed Parsons (use needinfo, please) [:jedp, :jparsons]]

Attachment: 974990-accept-languages.patch

r=rnewman

Comment 13

[Jed Parsons (use needinfo, please) [:jedp, :jparsons]]

(In reply to Jed Parsons (use needinfo, please) [:jedp, :jparsons] from comment #9)
> xpcshell tests suddenly broken on inbound:

Still broken today with no patches applied.  But mozilla-central is alive and kicking, and this patch applies with all green tests.

Comment 14

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/integration/fx-team/rev/96fd88a4d311

Comment 15

[Jed Parsons (use needinfo, please) [:jedp, :jparsons]]

RyanVM called to an orange error thrown on WinXP when running the test suite:

  https://tbpl.mozilla.org/?rev=069f663e7e64&tree=Fx-Team

The relevant bits of the log: 

12:09:17     INFO -  Services.Common.RESTRequest	TRACE	onStartRequest: POST http://localhost:3248/foo
12:09:17     INFO -  Services.Common.RESTRequest	TRACE	Channel for POST http://localhost:3248/foo returned status code 2147500036
12:09:17  WARNING -  TEST-UNEXPECTED-FAIL | C:/slave/test/build/tests/xpcshell/tests/services/common/tests/unit/test_hawkrequest.js | [Exception... "NS_ERROR_ABORT"  nsresult: "0x80004004 (NS_ERROR_ABORT)"  location: "JS frame :: resource://services-common/rest.js :: onStopRequest :: line 443"  data: no] == null - See following stack:
12:09:17     INFO -  JS frame :: C:/slave/test/build/tests/xpcshell/tests/services/common/tests/unit/test_hawkrequest.js :: test_hawk_language_pref_changed/secondTest/< :: line 202
12:09:17     INFO -  JS frame :: resource://services-common/rest.js :: onStopRequest :: line 444
12:09:17     INFO -  native frame :: <unknown filename> :: <TOP_LEVEL> :: line 0
12:09:17     INFO -  TEST-INFO | (xpcshell/head.js) | exiting test
12:09:17     INFO -  !!! error running onStopped callback: TypeError: callback is not a function

Perhaps the http requests are coming too rapidly in succession?

Comment 16

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

I backed this out for that orange in https://tbpl.mozilla.org/php/getParsedLog.php?id=35159732&tree=Fx-Team

It only seemed to happen on the retriggers on the WinXP PGO run (but not every single time).

Comment 17

[Jed Parsons (use needinfo, please) [:jedp, :jparsons]]

Thanks, Wes, for helping debug by getting some more log messages.  In each case, it's line 202 in test_hawkrequest.js that's resulting in the error.  At that line, we are POSTing a request to the test http server for the second time.  The server is not accepting the request.

I feel like I've seen problems like this in windows tests when there are too many open connections to a server.  Maybe we need to have some explicit wait for the connection to hangup?

Comment 18

[Jed Parsons (use needinfo, please) [:jedp, :jparsons]]

Attachment: hawk request access lang prefs as infrequently as possible

Modified test_hawk_language_pref_changed().  It still toggles the language pref twice.  Now, however, on the first change, it checks that the hawk request object has noticed the change.  On the second change, it checks that the hawk request headers have the correct accept-language field.  Thus it will only hit the test server once over the course of the test, which I hope will cure the wobbliness on XP.

Still works perfectly in local tests.  Running for WinXP:

https://tbpl.mozilla.org/?tree=Try&rev=2cb96db329c0

Comment 19

[Jed Parsons (use needinfo, please) [:jedp, :jparsons]]

Comment on attachment 8381523 [details] [diff] [review]
hawk request access lang prefs as infrequently as possible

Hi, Richard,

As described in Comment 18, I've revised one of the tests so that WinXP won't have an apoplexy when I call a test http server twice in one test.  I still don't know what the root cause of this festering WinXP animosity is [1], but as with other tests, reducing the number of client requests on the server appears to have effected a reconciliation.

The test still achieves the same purpose as before: It proves that change of language pref is observed by the hawk client helper.  Before I check this in, since I have made a change to the patch, I wanted to confirm that it could still carry your imprimatur.

Thanks again for looking!
j

[1] I can't help noticing that the XP in WinXP looks not unlike a squinty face sticking its tongue out at me.  I am trying not to take it personally.

Comment 20

[Richard Newman [:rnewman]]

(In reply to Jed Parsons (use needinfo, please) [:jedp, :jparsons] from comment #19)
> I still don't know what the root cause of this festering WinXP animosity is

WinXP hates all human life, particularly when caged in automation.

(You wouldn't believe the number of tests I've seen fail only on XP, in a manner inexplicable by man. Ph'nglui mglw'nafh Cthulhu R'lyeh wgah'nagl fhtagn.)

Comment 21

[Richard Newman [:rnewman]]

Comment on attachment 8381523 [details] [diff] [review]
hawk request access lang prefs as infrequently as possible

Review of attachment 8381523 [details] [diff] [review]:
-----------------------------------------------------------------

If the test fails when you disable the logic you added, I'm happy.

Comment 22

[Jed Parsons (use needinfo, please) [:jedp, :jparsons]]

Commence staring contest with WinXP ...

Comment 23

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/integration/fx-team/rev/319fd4968916

*blink*

Comment 24

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/319fd4968916

Comment 25

[Jed Parsons (use needinfo, please) [:jedp, :jparsons]]

\o/