746084 - provide extended logging for a11y module

Status: RESOLVED FIXED

(Core :: Disability Access APIs, defect)

Description

[alexander :surkov (:asurkov)]

1) I'm not really interested in logging levels but interesting to log certain logic paths like
a) notification.treeupdate logs things related with accessible tree update
b) notification.textupdate logs things related with text changes
c) notification.other logs all other notifications like DOM events
d) notification logs everything related with a11y notifications (a-c items together)

2) we need to be able to turn on the logging on runtime
3) we need to able to turn on/off logging form JS to do logging for specific intermittent orange mochitest

It sounds prlog is not very suitable because
a) it doesn't have native support of hierarchical logging (see 1st requirement)
b) it doesn't watch environment variable changes (see 3d requirement)
c) we should compute all logging info always not depending whether specific logging module is active or not (see macros in nsAccDocManager.h like NS_LOG_ACCDOC_SHELLLOADTYPE)

Ideas, objections, thoughts?

Comment 1

[Trevor Saunders (:tbsaunde)]

(In reply to alexander :surkov from comment #0)
> 1) I'm not really interested in logging levels but interesting to log

seems fine, I've never found levels to be very useful, I tend to find either you want logging on or off.

> certain logic paths like
> a) notification.treeupdate logs things related with accessible tree update
> b) notification.textupdate logs things related with text changes
> c) notification.other logs all other notifications like DOM events
> d) notification logs everything related with a11y notifications (a-c items
> together)

do we need more than a bitfield for this?

I'm thinking of an api something like

> 2) we need to be able to turn on the logging on runtime

not sure what this means out side of js, do you want to be able to do it from a debugger or something else?  If so what sort of ability does the msvc debugger give you for fiddling with the debugged programs state? (I'm more familiar with gdb)

> 3) we need to able to turn on/off logging form JS to do logging for specific
> intermittent orange mochitest
> 
> It sounds prlog is not very suitable because
> a) it doesn't have native support of hierarchical logging (see 1st
> requirement)
> b) it doesn't watch environment variable changes (see 3d requirement)

yeah, that's not how env variables work, though iirc someone had an evil hack to turn nspr logging on during runtime.

> c) we should compute all logging info always not depending whether specific
> logging module is active or not (see macros in nsAccDocManager.h like
> NS_LOG_ACCDOC_SHELLLOADTYPE)

I'm not sure I follow, don't we define those macros to be nothing in normal builds?

> Ideas, objections, thoughts?

I feel kind of bad doing it, but I doubt it'll be that much code, and probably more complicated and just anoying to try to make something similar but not the same work, so unless there already is something like this I'd say lets just roll our own something like this

typedef uint32_t MSGType;
a11y::Log(MSGType aType, char* msg)
{
  if (!aType & gLogFlags)
    return;

  printf(msg);
  printf("\n");
}

we might want to write some helper wrappers, or have a var args version too, but I suspect nobody else will possilby have what want there, so we'll be rolling that ourselves in any case.

Comment 2

[alexander :surkov (:asurkov)]

(In reply to Trevor Saunders (:tbsaunde) from comment #1)

> > certain logic paths like
> > a) notification.treeupdate logs things related with accessible tree update
> > b) notification.textupdate logs things related with text changes
> > c) notification.other logs all other notifications like DOM events
> > d) notification logs everything related with a11y notifications (a-c items
> > together)
> 
> do we need more than a bitfield for this?

yeah, bitfield is enough I think (at least for implementation)

> > 2) we need to be able to turn on the logging on runtime
> 
> not sure what this means out side of js, do you want to be able to do it
> from a debugger or something else?  If so what sort of ability does the msvc
> debugger give you for fiddling with the debugged programs state? (I'm more
> familiar with gdb)

I meant just having env variable you set up before running the browser. That should be enough for now

> > c) we should compute all logging info always not depending whether specific
> > logging module is active or not (see macros in nsAccDocManager.h like
> > NS_LOG_ACCDOC_SHELLLOADTYPE)
> 
> I'm not sure I follow, don't we define those macros to be nothing in normal
> builds?

Right. But I meant debug builds. Things like NS_LOG_ACCDOC_SHELLLOADTYPE can have several 'if' statements before they log something. If we replace those printf on prlog's printf then we should compute all things not depending whether prlog env variable is set or not.

> > Ideas, objections, thoughts?

> we might want to write some helper wrappers, or have a var args version too,
> but I suspect nobody else will possilby have what want there, so we'll be
> rolling that ourselves in any case.

yep, I started to play with that. Just wanted to make sure we are on the same page.

Comment 3

[Trevor Saunders (:tbsaunde)]

> > > Ideas, objections, thoughts?
> 
> > we might want to write some helper wrappers, or have a var args version too,
> > but I suspect nobody else will possilby have what want there, so we'll be
> > rolling that ourselves in any case.
> 
> yep, I started to play with that. Just wanted to make sure we are on the
> same page.

sounds fine by me

Comment 4

[alexander :surkov (:asurkov)]

Attachment: patch

Comment 5

[alexander :surkov (:asurkov)]

I forgot to clean up nsAccDocManager.h, done locally

Comment 6

[alexander :surkov (:asurkov)]

Attachment: patch2

Comment 7

[alexander :surkov (:asurkov)]

Comment on attachment 620169 [details] [diff] [review]
patch2

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

::: accessible/src/base/Logging.cpp
@@ +54,5 @@
> +    token += tokenLen;
> +    if (*token == '\0')
> +      break;
> +
> +    token++; // skip ',' char

I changed this to
if (*token == ',')
  token++; // skip ',' char

Comment 8

[Trevor Saunders (:tbsaunde)]

Comment on attachment 620169 [details] [diff] [review]
patch2

>+   * Enable logging for the given modules, all other modules aren't logged.
>+   *
>+   * @param aModules [in] list of modules, format is comma separated list
>+   *                      like 'docload,doccreate'.
>+   * @note Works on debug build only.

I guess xpidl's preprocessor is laim and doesn't support ifdef either? :(

>+#include "AccEvent.h"
>+#include "nsAccessibilityService.h"
>+
>+#include "nsCoreUtils.h"
>+#include "nsDocAccessible.h"

shouldn't these be in the first group?

>+void
>+EnableLogging(const char* aModulesStr)

static?

>+  static const PRUint32 modulesCnt = ArrayLength(modules);

what is the point of this constant?

btw *foo == '\0' turns out to be the same as !*foo

>+    size_t tokenLen = strcspn(token, ",");
>+    for (PRUint32 moduleIdx = 0; moduleIdx < modulesCnt; moduleIdx++) {

kind of funny to see PR types when everything else in this function is straight C++

>+      if (strncmp(token, modules[moduleIdx], tokenLen) == 0) {

you can do !strncmp() if you like

>+        sModules |= moduleIdx;

that seems sketchy, what happens if 1 and 3 are both found?

>+void
>+LogDocURI(nsIDocument* aDocumentNode)

static? take a const arg?

>+void
>+LogDocShellState(nsIDocument* aDocumentNode)

same?

>+{
>+  nsCAutoString docShellBusy;
>+  nsCOMPtr<nsISupports> container = aDocumentNode->GetContainer();
>+  if (container) {
>+    nsCOMPtr<nsIDocShell> docShell = do_QueryInterface(container);

does that always succeed?

>+    PRUint32 busyFlags = nsIDocShell::BUSY_FLAGS_NONE;
>+    docShell->GetBusyFlags(&busyFlags);
>+    if (busyFlags == nsIDocShell::BUSY_FLAGS_NONE)
>+      docShellBusy.AppendLiteral("'none'");
>+    if (busyFlags & nsIDocShell::BUSY_FLAGS_BUSY)
>+      docShellBusy.AppendLiteral("'busy'");
>+    if (busyFlags & nsIDocShell::BUSY_FLAGS_BEFORE_PAGE_LOAD)
>+      docShellBusy.AppendLiteral(", 'before page load'");
>+    if (busyFlags & nsIDocShell::BUSY_FLAGS_PAGE_LOADING)
>+      docShellBusy.AppendLiteral(", 'page loading'");
>+  }
>+  else {

} else {

>+    docShellBusy.AppendLiteral("[failed]");
>+  }
>+  printf("docshell busy: %s", docShellBusy.get());

you don't print a new line here

I'd consider not building up a string, and instead just print bits as you know them.

>+void
>+LogDocType(nsIDocument* aDocumentNode)

static?

>+void
>+LogDocShellTree(nsIDocument* aDocumentNode)

static, const doc?

>+void
>+LogDocState(nsIDocument* aDocumentNode)

static, const doc?  Well, maybe not const since it could get anoying and perf doesn't matter, but static seems sumantically nice here.

>+{
>+  const char* docState = 0;

nsnull, if you don't like NULL?

>+
>+  // log address
>+  printf("    ");
>+  printf("DOM id: %p, acc id: %p",
>+         static_cast<void*>(aDocumentNode), static_cast<void*>(aDocument));
>+  printf("\n    ");

we don't comment we're printing the pointer everywhere else, and it seems sort of obvious.

>+
>+  // log document info
>+  if (aDocumentNode) {
>+    LogDocURI(aDocumentNode);
>+    printf("\n    ");
>+    LogDocShellState(aDocumentNode);
>+    printf("; ");
>+    LogDocType(aDocumentNode);
>+    printf("\n    ");
>+    LogDocShellTree(aDocumentNode);
>+    printf("\n    ");
>+    LogDocState(aDocumentNode);
>+    printf("\n    ");

all these printf("\n") are kind of funny

>+logs::CheckEnv()
>+{
>+  EnableLogging(PR_GetEnv("A11YLOG"));

we seem to use getenv() directly a bit now, but up to you I guess.

>+namespace logs {

nit, log or logging sounds better english to me fwiw

>+#ifdef DEBUG
>+    if (logs::IsEnabled(logs::eDocLoad))
>+      logs::DocLoad("document loaded", aWebProgress, aRequest, aStateFlags);
>+#endif

it'd be nice if we didn't need to spray #ifdef DEBUG all over  I wonder if defining inline functions that do nothing in the non debug case would introduce any negative effect.

>+++ b/accessible/src/generic/OuterDocAccessible.cpp
>@@ -33,16 +33,17 @@
>  * and other provisions required by the GPL or the LGPL. If you do not delete
>  * the provisions above, a recipient may use your version of this file under
>  * the terms of any one of the MPL, the GPL or the LGPL.
>  *
>  * ***** END LICENSE BLOCK ***** */
> 
> #include "OuterDocAccessible.h"
> 
>+#include "Logging.h"

ifdef?

Comment 9

[alexander :surkov (:asurkov)]

(In reply to Trevor Saunders (:tbsaunde) from comment #8)
> I guess xpidl's preprocessor is laim and doesn't support ifdef either? :(

it seems so, at least I didn't see any example in mc. But it doesn't seem we really want this otherwise it means that JS code should ifdef things as well.

> >+void
> >+EnableLogging(const char* aModulesStr)
> 
> static?

you know a difference between static on non static function in cpp, practices?

> >+  static const PRUint32 modulesCnt = ArrayLength(modules);
> 
> what is the point of this constant?

ok, I'll remove it

> btw *foo == '\0' turns out to be the same as !*foo

I think I'd prefer to keep it explicitly

> >+    size_t tokenLen = strcspn(token, ",");
> >+    for (PRUint32 moduleIdx = 0; moduleIdx < modulesCnt; moduleIdx++) {
> 
> kind of funny to see PR types when everything else in this function is
> straight C++

ok, changed to unsigned int

> >+      if (strncmp(token, modules[moduleIdx], tokenLen) == 0) {
> 
> you can do !strncmp() if you like

I'd keep it explicit since it's not boolean value.

> >+        sModules |= moduleIdx;
> 
> that seems sketchy, what happens if 1 and 3 are both found?

3 and that's ok, right?

> >+  nsCAutoString docShellBusy;
> >+  nsCOMPtr<nsISupports> container = aDocumentNode->GetContainer();
> >+  if (container) {
> >+    nsCOMPtr<nsIDocShell> docShell = do_QueryInterface(container);
> 
> does that always succeed?

seems so

> >+  printf("docshell busy: %s", docShellBusy.get());
> 
> you don't print a new line here

it appears it shouldn't be

> I'd consider not building up a string, and instead just print bits as you
> know them.

ok

> >+{
> >+  const char* docState = 0;
> 
> nsnull, if you don't like NULL?

ok

> >+
> >+  // log address
> >+  printf("    ");
> >+  printf("DOM id: %p, acc id: %p",
> >+         static_cast<void*>(aDocumentNode), static_cast<void*>(aDocument));
> >+  printf("\n    ");
> 
> we don't comment we're printing the pointer everywhere else, and it seems
> sort of obvious.

it was supposed to group these 3 printfs to keep separately for printfs below.

> >+    LogDocShellTree(aDocumentNode);
> >+    printf("\n    ");
> >+    LogDocState(aDocumentNode);
> >+    printf("\n    ");
> 
> all these printf("\n") are kind of funny

why? :)

> >+logs::CheckEnv()
> >+{
> >+  EnableLogging(PR_GetEnv("A11YLOG"));
> 
> we seem to use getenv() directly a bit now, but up to you I guess.

what's difference?

> >+namespace logs {
> 
> nit, log or logging sounds better english to me fwiw

then logging ('log' is in collision on os x)

> 
> >+#ifdef DEBUG
> >+    if (logs::IsEnabled(logs::eDocLoad))
> >+      logs::DocLoad("document loaded", aWebProgress, aRequest, aStateFlags);
> >+#endif
> 
> it'd be nice if we didn't need to spray #ifdef DEBUG all over  I wonder if
> defining inline functions that do nothing in the non debug case would
> introduce any negative effect.

I think I'd try to keep release build not affected at all (even potentially)

Comment 10

[alexander :surkov (:asurkov)]

Trevor, ping

Comment 11

[Trevor Saunders (:tbsaunde)]

(In reply to alexander :surkov from comment #10)
> Trevor, ping

sorry, thought I'd replied, but looks like that didn't happen...

(In reply to alexander :surkov from comment #9)
> (In reply to Trevor Saunders (:tbsaunde) from comment #8)
> > I guess xpidl's preprocessor is laim and doesn't support ifdef either? :(
> 
> it seems so, at least I didn't see any example in mc. But it doesn't seem we
> really want this otherwise it means that JS code should ifdef things as well.

ok

> > >+void
> > >+EnableLogging(const char* aModulesStr)
> > 
> > static?
> 
> you know a difference between static on non static function in cpp,
> practices?

static means the function can't be used outside the file its defined in, which I think you want here since its sort of implementation detail.

> > >+      if (strncmp(token, modules[moduleIdx], tokenLen) == 0) {
> > 
> > you can do !strncmp() if you like
> 
> I'd keep it explicit since it's not boolean value.

ok, I'm osrt of used to the 1strcmp() thing from reading parsing code, but if you like explicit I don't mind.

> > >+        sModules |= moduleIdx;
> > 
> > that seems sketchy, what happens if 1 and 3 are both found?
> 
> 3 and that's ok, right?

so, you have enum { 1 << 0, 1 << 1, 1 << 2 }; right?  suppose you findonly the third mode in spot 2 of the array is enabled, then you do sMode |= 2 right?  but don't you want sMode |= 1 << 2 so sMode & 1 << 2 checks if its enabled?


> > >+
> > >+  // log address
> > >+  printf("    ");
> > >+  printf("DOM id: %p, acc id: %p",
> > >+         static_cast<void*>(aDocumentNode), static_cast<void*>(aDocument));
> > >+  printf("\n    ");
> > 
> > we don't comment we're printing the pointer everywhere else, and it seems
> > sort of obvious.
> 
> it was supposed to group these 3 printfs to keep separately for printfs
> below.

ok, btw why can't it just be one printf?

> > >+    LogDocShellTree(aDocumentNode);
> > >+    printf("\n    ");
> > >+    LogDocState(aDocumentNode);
> > >+    printf("\n    ");
> > 
> > all these printf("\n") are kind of funny
> 
> why? :)

just sort of funny functions don't tkae care of it themselves, but I guess that's so they're more useful.  I guess I'm fine with it since text formating generally isn't fun or interesting.

> 
> > >+logs::CheckEnv()
> > >+{
> > >+  EnableLogging(PR_GetEnv("A11YLOG"));
> > 
> > we seem to use getenv() directly a bit now, but up to you I guess.
> 
> what's difference?

just less indirection through nspr so less cross library calls.

> > >+namespace logs {
> > 
> > nit, log or logging sounds better english to me fwiw
> 
> then logging ('log' is in collision on os x)

ok, I guess i can live with that.

> > >+#ifdef DEBUG
> > >+    if (logs::IsEnabled(logs::eDocLoad))
> > >+      logs::DocLoad("document loaded", aWebProgress, aRequest, aStateFlags);
> > >+#endif
> > 
> > it'd be nice if we didn't need to spray #ifdef DEBUG all over  I wonder if
> > defining inline functions that do nothing in the non debug case would
> > introduce any negative effect.
> 
> I think I'd try to keep release build not affected at all (even potentially)

fiar, but 4 lines is sort of long and anoying.  I'd be very very suprised if MOZ_ALLWAYS_INLINE void Foo() { } ever effected anything.

Comment 12

[alexander :surkov (:asurkov)]

(In reply to Trevor Saunders (:tbsaunde) from comment #11)

> so, you have enum { 1 << 0, 1 << 1, 1 << 2 }; right?  suppose you findonly
> the third mode in spot 2 of the array is enabled, then you do sMode |= 2
> right?  but don't you want sMode |= 1 << 2 so sMode & 1 << 2 checks if its
> enabled?

oops

> > it was supposed to group these 3 printfs to keep separately for printfs
> > below.
> 
> ok, btw why can't it just be one printf?

ok, it was used for better structuring (here's new line, here's 4 spaces offset etc) but I don't mind.

> just sort of funny functions don't tkae care of it themselves, but I guess
> that's so they're more useful.

yes

> 
> > 
> > > >+logs::CheckEnv()
> > > >+{
> > > >+  EnableLogging(PR_GetEnv("A11YLOG"));
> > > 
> > > we seem to use getenv() directly a bit now, but up to you I guess.
> > 
> > what's difference?
> 
> just less indirection through nspr so less cross library calls.

I heard the point of PR_GetEnv is that it guarantees that getting an env is consistent across platforms.

> > I think I'd try to keep release build not affected at all (even potentially)
> 
> fiar, but 4 lines is sort of long and anoying.  I'd be very very suprised if
> MOZ_ALLWAYS_INLINE void Foo() { } ever effected anything.

yes it's longer but it has benefits, usually you just skip over all DEBUG code when you read the code.

Comment 13

[alexander :surkov (:asurkov)]

Attachment: patch3

Comment 14

[alexander :surkov (:asurkov)]

Trevor, ping

Comment 15

[Trevor Saunders (:tbsaunde)]

> > > > >+logs::CheckEnv()
> > > > >+{
> > > > >+  EnableLogging(PR_GetEnv("A11YLOG"));
> > > > 
> > > > we seem to use getenv() directly a bit now, but up to you I guess.
> > > 
> > > what's difference?
> > 
> > just less indirection through nspr so less cross library calls.
> 
> I heard the point of PR_GetEnv is that it guarantees that getting an env is
> consistent across platforms.

that may have been the point a long time ago, but as far as I can see its just a call to getenv() directly on windows and modern unixes, but I guess its not a big deal either way.

Comment 16

[Trevor Saunders (:tbsaunde)]

Comment on attachment 622742 [details] [diff] [review]
patch3

>+    if (busyFlags & nsIDocShell::BUSY_FLAGS_PAGE_LOADING)
>+      printf(", 'page loading'");
>+  }
>+  else {

} else {

>+enum EModules {
>+  eDocLoad = 1 << 0,
>+  eDocCreate = 1 << 1,
>+  eDocDestroy = 1 << 2,
>+  eDocLifeCycle = eDocLoad | eDocCreate | eDocDestroy

I'm not sure I see how this works, consider I set env variable to "doclifecycle" then sModes = 0x8 or 1 << 3 right? but what you will test for is sModes & 0x7 or 1 | 1<<1 | 1<<2

Comment 17

[alexander :surkov (:asurkov)]

Attachment: patch4

Looks ok?

Comment 18

[alexander :surkov (:asurkov)]

(In reply to alexander :surkov from comment #17)
> Created attachment 624666 [details] [diff] [review]
> patch4
> 
> Looks ok?

Trevor, bumping it in your queue.

Comment 19

[Trevor Saunders (:tbsaunde)]

seems fine, other than I think you should put an  ifdef around the include in nsAccDocManager.cpp

Comment 20

[alexander :surkov (:asurkov)]

https://hg.mozilla.org/integration/mozilla-inbound/rev/eb017ddb11c6

Comment 21

[Ed Morley [:emorley]]

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