540633 - Improvements to httpd.js debugging logs

Status: RESOLVED FIXED

(Testing :: General, defect)

Description

[Zack Weinberg (:zwol)]

Attachment: patch

This patch makes a few improvements to httpd.js debugging logs:

1) All messages printed with dumpn() are prefixed with "HTTPD-INFO | " to make them easy to scan for.
2) Optionally, the prefix can include a timestamp.
3) Mochitests can enable and disable httpd.js debugging in the middle of a run by loading a magic URL (/server/debug?[012]).  This could easily be cloned to other test suites.

This was very helpful while investigating bug 536603, and seems like it would be worthwhile infrastructure for future such bugs.

Comment 1

[Jeff Walden [:Waldo]]

Comment on attachment 422348 [details] [diff] [review]
patch

>diff --git a/netwerk/test/httpserver/httpd.js b/netwerk/test/httpserver/httpd.js

> /** dump(str) with a trailing "\n" -- only outputs if DEBUG */

This comment, in addition to being wrong with this patch (maybe "Logs a string not already terminated by a newline if DEBUG."), is now disconnected from the function, which would break JS auto-doc-generation schemes like jsdoc if they were ever seriously used on this file (I've done so experimentally once or twice).  Move the comment back next to the function statement.


>+var first_stamp = null;

Underscores are verboten in httpd.js style except in all-caps constants, and this ain't one -- |firstStamp|.

> function dumpn(str)
> {
>-  if (DEBUG)
>-    dump(str + "\n");
>+  if (DEBUG) {

Bracing style is

  if (DEBUG)
  {
    // stuff
  }


>+    var prefix = "HTTPD-INFO | ";

Make this |const|.


>+    if (DEBUG_TIMESTAMP) {

Brace.


>+      if (first_stamp === null) {
>+        first_stamp = new Date();
>+      }

Single-line ifs don't need braces.

Don't use a Date object here -- initialize |firstStamp| to 0 at declaration, and assign |Date.now()| if |firstStamp == 0|.


>+      var elapsed = (new Date() - first_stamp)/1000; // in decimal seconds

|Date.now()| again, and put spaces around /.


>+      var min = Math.floor(elapsed/60);

Spaces around /.


>+      var sec = elapsed - 60*min;

Spaces around *, except that isn't |elapsed % 60| more readable?

(Egads, what Mozilla code are you working with that condones under-whitespacing of binary operators?  ;-) )


>+      if (sec < 10)
>+        prefix += min + ":0" + sec.toFixed(3) + " | ";
>+      else
>+        prefix += min + ":" + sec.toFixed(3) + " | ";
>+    }
>+    dump(prefix + str + "\n");

Newline above the dump() here.


>diff --git a/testing/mochitest/server.js b/testing/mochitest/server.js

>@@ -292,16 +293,46 @@ function serverShutdown(metadata, respon
> 
>   var body = "Server shut down.";
>   response.bodyOutputStream.write(body, body.length);
> 
>   dumpn("Server shutting down now...");
>   server.stop(serverStopped);
> }
> 
>+// /server/debug?[012]
>+function serverDebug(metadata, response)
>+{
>+  var mode;
>+  if (metadata.queryString.length != 1) {
>+    throw HTTP_400;
>+  } else if (metadata.queryString[0] == '0') {

Blank line between the first if and the second one, and nix else because it's pointless.

The HTTP_* values are all server-internal; the proper way to do this would be to start the function with:

  response.setStatusLine(metadata.httpVersion, 500, "Bad debugging level");

and change the |throw| into a |return|.  It's fine to call this method multiple times (assuming no output's been sent yet, that is), and the last call wins.


>+    // do this now so it gets logged with the old mode
>+    dumpn("Server debug logs disabled.");

This dumpn is redundant with the one below.


>+    DEBUG = false;
>+    DEBUG_TIMESTAMP = false;
>+    mode = "disabled";
>+  } else if (metadata.queryString[0] == '1') {
>+    DEBUG = true;
>+    DEBUG_TIMESTAMP = false;
>+    mode = "enabled";
>+  } else if (metadata.queryString[0] == '2') {
>+    DEBUG = true;
>+    DEBUG_TIMESTAMP = true;
>+    mode = "enabled, with timestamps";
>+  } else {
>+    throw HTTP_400;

This can be a |return| with the suggestion above.

Grabbing out the first character via |queryString[0]| is pointless, because we've already verified that the query string is a single character -- just compare to |metadata.queryString| directly.  Also, use |===| for more predictability than |==| (which generally may coerce its arguments to different types, even if not here), and use "" instead of '' for strings.


>+  response.setStatusLine("1.1", 200, "OK");

Note that this will overwrite the status line set by the initial error-ful call I suggest above.

Comment 2

[Zack Weinberg (:zwol)]

Got some questions and objections for you on this one.

(In reply to comment #1)
> (From update of attachment 422348 [details] [diff] [review])
> >diff --git a/netwerk/test/httpserver/httpd.js b/netwerk/test/httpserver/httpd.js
> 
> > /** dump(str) with a trailing "\n" -- only outputs if DEBUG */
> 
> This comment, in addition to being wrong with this patch (maybe "Logs a string
> not already terminated by a newline if DEBUG."), is now disconnected from the
> function, which would break JS auto-doc-generation schemes like jsdoc if they
> were ever seriously used on this file (I've done so experimentally once or
> twice).  Move the comment back next to the function statement.

Ok.

> >+var first_stamp = null;
> 
> Underscores are verboten in httpd.js style except in all-caps constants, and
> this ain't one -- |firstStamp|.

Ok.  Insert whine about StudlyCaps being less readable here, however.

> Bracing style is
> 
>   if (DEBUG)
>   {
>     // stuff
>   }

Ok, but I reiterate my amazement at brace-on-own-line style within Mozilla code.

> >+    var prefix = "HTTPD-INFO | ";
> 
> Make this |const|.

Ok.

> Don't use a Date object here -- initialize |firstStamp| to 0 at declaration,
> and assign |Date.now()| if |firstStamp == 0|.

Ok, but isn't Date.now() exactly the same thing as new Date()?

> >+      var elapsed = (new Date() - first_stamp)/1000; // in decimal seconds
> 
> |Date.now()| again, and put spaces around /.
> 
> >+      var min = Math.floor(elapsed/60);
> 
> Spaces around /.
> 
> >+      var sec = elapsed - 60*min;
> 
> Spaces around *, except that isn't |elapsed % 60| more readable?
> 
> (Egads, what Mozilla code are you working with that condones under-whitespacing
> of binary operators?  ;-) )

I prefer not to put whitespace around division or multiply, especially when they are used together with addition or subtraction.  It visually emphasizes the order of operations.  Nobody else has objected to this.

"elapsed % 60" is inappropriate here, IMO, because the numbers involved are floating point (fractions of a second).

Thus, I would much prefer to leave all these as they are (modulo new Date() vs Date.now()).

> >+      if (sec < 10)
> >+        prefix += min + ":0" + sec.toFixed(3) + " | ";
> >+      else
> >+        prefix += min + ":" + sec.toFixed(3) + " | ";
> >+    }
> >+    dump(prefix + str + "\n");
> 
> Newline above the dump() here.

Ok.  (I put blank lines in, or leave them out, based on which way I think it's more readable in context; in this case, the dump() consumes the result of the if block, so it belongs together with it; but it's not important.)

> >+  var mode;
> >+  if (metadata.queryString.length != 1) {
> >+    throw HTTP_400;
> >+  } else if (metadata.queryString[0] == '0') {
> 
> Blank line between the first if and the second one, and nix else because it's
> pointless.
> 
> The HTTP_* values are all server-internal; the proper way to do this would be
> to start the function with:
> 
>   response.setStatusLine(metadata.httpVersion, 500, "Bad debugging level");
> 
> and change the |throw| into a |return|.  It's fine to call this method multiple
> times (assuming no output's been sent yet, that is), and the last call wins.

Ok.

> >+    // do this now so it gets logged with the old mode
> >+    dumpn("Server debug logs disabled.");
> 
> This dumpn is redundant with the one below.

Not so; when we hit this case, the dumpn() below this point happens after logging has been disabled, and therefore does not actually do anything.  I think it's important for there to be an explicit indication in the logfile when HTTPD logging is intentionally stopped, so we need this one.

> >+  } else if (metadata.queryString[0] == '2') {
> >+    DEBUG = true;
> >+    DEBUG_TIMESTAMP = true;
> >+    mode = "enabled, with timestamps";
> >+  } else {
> >+    throw HTTP_400;
> 
> This can be a |return| with the suggestion above.
> 
> Grabbing out the first character via |queryString[0]| is pointless, because
> we've already verified that the query string is a single character -- just
> compare to |metadata.queryString| directly.  Also, use |===| for more
> predictability than |==| (which generally may coerce its arguments to different
> types, even if not here), and use "" instead of '' for strings.

Ok.  I had been under the impression that === was not safe on strings, though.  Are they guaranteed to be unique?

> >+  response.setStatusLine("1.1", 200, "OK");
> 
> Note that this will overwrite the status line set by the initial error-ful call
> I suggest above.

Yah, but does that mean anything needs to change here?

Comment 3

[Jeff Walden [:Waldo]]

(In reply to comment #2)
> Ok, but isn't Date.now() exactly the same thing as new Date()?

No.  |new Date()| creates a full-blown Date object, which is more or less a wrapper around a numeric time stamp.  The value of it is that you have manipulator methods to, say, adjust the year of a date, or the hour or minute.  |Date.now()| is just the value of that numeric time stamp.  You're not manipulating dates here; you just want a time stamp.  (Well, really you want a way to measure time intervals -- robarnold could and has talked about this at length -- but JS doesn't offer any such way at present.)  The full Date object is overkill for your purposes.

It's also perhaps worth pointing out that while |new Date()| must always allocate an object, increasing heap usage and all that, the value of |Date.now()| consumes much less heap space.  Eventually it won't even consume any, once we change the JS value representation to store double values without indirection, rather than having to "box" doubles and store them in the heap (a double JS value is internally a pointer to a double right now, even if in the language any variable with the value 3.5 is equal to any other such value).  However, that's much less important than the simple fact that you don't need the power of a Date object, so you shouldn't use one.


> > >+      var elapsed = (new Date() - first_stamp)/1000; // in decimal seconds
> > 
> > |Date.now()| again, and put spaces around /.
> > 
> > >+      var min = Math.floor(elapsed/60);
> > 
> > Spaces around /.
> > 
> > >+      var sec = elapsed - 60*min;
> > 
> > Spaces around *, except that isn't |elapsed % 60| more readable?
> > 
> > (Egads, what Mozilla code are you working with that condones
> > under-whitespacing of binary operators?  ;-) )
> 
> I prefer not to put whitespace around division or multiply, especially when
> they are used together with addition or subtraction.  It visually emphasizes
> the order of operations.  Nobody else has objected to this.

This surprises me greatly; I've never seen anything anywhere in Mozilla that under-whitespaces any binary operators, not even on this order-of-operations basis (I'd overparenthesize if I had this concern, suspect others would usually do the same as is sometimes done for && combined with ||).  :-)  Guess we're both learning something here.  However, the request still stands.


> "elapsed % 60" is inappropriate here, IMO, because the numbers involved are
> floating point (fractions of a second).

Oh, right, I forgot that you'd pre-divided to convert milliseconds to seconds.  I'm kind of leery of pre-dividing earlier than necessary like this, but this is already written and works, so whatever.


> Ok.  (I put blank lines in, or leave them out, based on which way I think it's
> more readable in context; in this case, the dump() consumes the result of the
> if block, so it belongs together with it; but it's not important.)

Interesting rationale.  I think I tend to break up code with empty lines based on whether a description in pseudo-code would have performed two steps or just one at a broad level -- then you get exceptions.  The one I apply here is that assignment to a variable, followed by a step whose effect is to maybe tweak that variable, isn't whitespace-split.  In this case I mentally split it as "let prefix be...", "if DEBUG_TIMESTAMP then substeps", "dump prefix plus...".  Because the effect of the "if DEBUG_TIMESTAMP" is to modify the prefix, it gets splatted against the declaration/assignment of prefix.


> > This dumpn is redundant with the one below.
> 
> Not so; when we hit this case, the dumpn() below this point happens after
> logging has been disabled, and therefore does not actually do anything.  I
> think it's important for there to be an explicit indication in the logfile
> when HTTPD logging is intentionally stopped, so we need this one.

Tricksy; I should have seen that -- especially given the comment right above!  FAIL me.  Too bad this weird-ish way of doing things doesn't have an obvious way of being done more clearly.


> Ok.  I had been under the impression that === was not safe on strings,
> though. Are they guaranteed to be unique?

Any non-object value in JS compares == and === to a copy of that value.  (It may not be a copy under the hood -- we atomize string literals, property names, ASCII characters, strings which are non-negative integers less than 256, and possibly a couple other interesting classes of strings.  Depending on the course of calculation you might get a string as an atom without knowing it or trying to do so, and if you compare it to another string that's atomized the equality check becomes O(1).  However, that's solely an optimization.)  In JS any string compares equal by === to any other string which contains the same characters in the same order.  String *objects* created by |new String("foo")| are different and don't compare equal to each other (or even to themselves) by ===, which is why the object types for the primitive values (String, Number, Boolean) are to be avoided.  (It gets even worse if you consider them with == because transitivity is violated: if |a=new String("a")| and |b="a"| and |c=new String("a")|, |a == b| and |b == c| but |!(a == c)|.  This is another reason to generally avoid ==.)


> > >+  response.setStatusLine("1.1", 200, "OK");
> > 
> > Note that this will overwrite the status line set by the initial
> > error-ful call I suggest above.
> 
> Yah, but does that mean anything needs to change here?

No, it's good, merely being informative.  (I considered making that more explicit but guessed that just saying "Note" without instructions would be clear enough to avoid confusion -- my bad.)

Comment 4

[Zack Weinberg (:zwol)]

Revised patch shortly...

(In reply to comment #3)
> (In reply to comment #2)
> > Ok, but isn't Date.now() exactly the same thing as new Date()?
> 
> No.  |new Date()| creates a full-blown Date object, which is more or less a
> wrapper around a numeric time stamp.  The value of it is that you have
> manipulator methods to, say, adjust the year of a date, or the hour or minute. 
> |Date.now()| is just the value of that numeric time stamp.  You're not
> manipulating dates here; you just want a time stamp.  (Well, really you want a
> way to measure time intervals -- robarnold could and has talked about this at
> length -- but JS doesn't offer any such way at present.)  The full Date object
> is overkill for your purposes.

Thanks for the clarification!  I think I latched onto the "Date.now() is nonstandard" note on MDC and didn't register the important part, which is that its return value is a number rather than a Date object.

> > I prefer not to put whitespace around division or multiply, especially when
> > they are used together with addition or subtraction.  It visually emphasizes
> > the order of operations.  Nobody else has objected to this.
> 
> This surprises me greatly; I've never seen anything anywhere in Mozilla that
> under-whitespaces any binary operators, not even on this order-of-operations
> basis (I'd overparenthesize if I had this concern, suspect others would
> usually do the same as is sometimes done for && combined with ||).  :-)
> Guess we're both learning something here.  However, the request still stands.
> 
> > "elapsed % 60" is inappropriate here, IMO, because the numbers involved are
> > floating point (fractions of a second).
> 
> Oh, right, I forgot that you'd pre-divided to convert milliseconds to
> seconds. I'm kind of leery of pre-dividing earlier than necessary like
> this, but this is already written and works, so whatever.

On reread, it winds up being clearer like so:

      var elapsed = Date.now() - firstStamp; // milliseconds
      var min = Math.floor(elapsed / 60000);
      var sec = (elapsed % 60000) / 1000;

I'm not a fan of the large numbers, but I do think it's better to avoid having a stealth fractional component that has to be preserved (and therefore one must avoid the use of modulus).

> > Ok.  I had been under the impression that === was not safe on strings,
> > though. Are they guaranteed to be unique?
> 
> Any non-object value in JS compares == and === to a copy of that value.

I had been under the impression that == in JS was functionally equivalent to Lisp 'equal' and === was functionally equivalent to 'eq', therefore === was almost never what one wanted.  I see now that neither of them really correspond to any Lisp concept...

> (It gets even worse if you consider them with == because transitivity
> is violated: if |a=new String("a")| and |b="a"| and |c=new String("a")|,
> |a == b| and |b == c| but |!(a == c)|.  This is another reason to
> generally avoid ==.)

Yuck!

Comment 5

[Zack Weinberg (:zwol)]

Attachment: patch v2

Here's the revision.  I tested it by running mochitests and then poking at the /server/debug magic URL while they were running.

The approach you suggested for responding to a bad debug level trips a bug in Firefox -- the body of the code 400 response is empty, so you get a blank screen.  (Bug 442255.)  But I think we can live with that.

Comment 6

[Jeff Walden [:Waldo]]

Comment on attachment 425252 [details] [diff] [review]
patch v2

>diff --git a/netwerk/test/httpserver/httpd.js b/netwerk/test/httpserver/httpd.js

>+      if (firstStamp == 0)
>+        firstStamp = Date.now();

===


>+      var elapsed = Date.now() - firstStamp; // milliseconds
>+      var min = Math.floor(elapsed / 60000);
>+      var sec = (elapsed % 60000) / 1000;

Like!


>diff --git a/testing/mochitest/server.js b/testing/mochitest/server.js

>+  if (metadata.queryString.length != 1)
>+    return;

!==

Comment 7

[Jeff Walden [:Waldo]]

I wouldn't call the empty-error-page thing a bug -- bad UI maybe, but entirely reasonable behavior.

I tweaked the Date.now page on MDC to mention that it's new in ES5, also to add a compatibility section with a workaround for JS engines that don't yet support it.

Comment 8

[Zack Weinberg (:zwol)]

I made the changes you reuqested in comment 6 and will land after a smoke test.

> I wouldn't call the empty-error-page thing a bug -- bad UI maybe, but entirely
> reasonable behavior.

It's surely something to be dealt with at the UI level, but I do think it's a bug that you can't tell the difference between a 4xx and a 2xx response if they happen to have empty bodies.  Makes network debugging that much harder.  (Firebug *can* tell the difference, though, so it's not that important.)

> I tweaked the Date.now page on MDC to mention that it's new in ES5, also to add
> a compatibility section with a workaround for JS engines that don't yet support
> it.

Thanks!  Might be good to also tweak the tag on the main Date page ("ES5" instead of "nonstandard").  I'd do it but I seem to have forgotten my devmo password

Comment 9

[Jeff Walden [:Waldo]]

Sheppy, are there templates for "New in ES5", or no?  Date.now needs it, array extras should be updated with it as well, come to think of it.

Comment 10

[Zack Weinberg (:zwol)]

http://hg.mozilla.org/mozilla-central/rev/c2391819c4ec

Comment 11

[Eric Shepherd [:sheppy]]

There aren't templates for that, since we typically refer to stuff as to which JavaScript version they correspond to rather than to ECMAScript versions. Is that something we need to reconsider?

I don't like the idea of having to correlate between both JavaScript and ECMAScript versions though; that seems like a lot of complication.

Comment 12

[Jeff Walden [:Waldo]]

Hm, I guess that's fair, if unfortunate -- practically, authors care greatly about the difference between extensions they can only use in one browser and extensions they can use in many.  While it's important to know when something can be used in Mozilla, it's equally important to know when it can be used elsewhere as well.  I'm not really sure what's a good solution here, but I'm at least placated by the current stopgap, so I'm not going to spend more time thinking about this.