provide extended logging for a11y module

RESOLVED FIXED in mozilla15

Status

()

Core
Disability Access APIs
RESOLVED FIXED
5 years ago
5 years ago

People

(Reporter: surkov, Assigned: surkov)

Tracking

unspecified
mozilla15
Points:
---

Firefox Tracking Flags

(Not tracked)

Details

Attachments

(1 attachment, 3 obsolete attachments)

(Assignee)

Description

5 years ago
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?
(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.
(Assignee)

Comment 2

5 years ago
(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.
> > > 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
(Assignee)

Comment 4

5 years ago
Created attachment 619884 [details] [diff] [review]
patch
Assignee: nobody → surkov.alexander
Status: NEW → ASSIGNED
Attachment #619884 - Flags: review?(trev.saunders)
(Assignee)

Comment 5

5 years ago
I forgot to clean up nsAccDocManager.h, done locally
(Assignee)

Updated

5 years ago
Attachment #619884 - Attachment is obsolete: true
Attachment #619884 - Flags: review?(trev.saunders)
(Assignee)

Comment 6

5 years ago
Created attachment 620169 [details] [diff] [review]
patch2
Attachment #620169 - Flags: review?(trev.saunders)
(Assignee)

Comment 7

5 years ago
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 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?
(Assignee)

Comment 9

5 years ago
(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)
(Assignee)

Comment 10

5 years ago
Trevor, ping
(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.
(Assignee)

Comment 12

5 years ago
(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.
(Assignee)

Comment 13

5 years ago
Created attachment 622742 [details] [diff] [review]
patch3
Attachment #620169 - Attachment is obsolete: true
Attachment #620169 - Flags: review?(trev.saunders)
Attachment #622742 - Flags: review?(trev.saunders)
(Assignee)

Comment 14

5 years ago
Trevor, ping
> > > > >+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 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
Attachment #622742 - Flags: review?(trev.saunders) → review+
(Assignee)

Comment 17

5 years ago
Created attachment 624666 [details] [diff] [review]
patch4

Looks ok?
Attachment #622742 - Attachment is obsolete: true
(Assignee)

Comment 18

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

Trevor, bumping it in your queue.
seems fine, other than I think you should put an  ifdef around the include in nsAccDocManager.cpp
(Assignee)

Comment 20

5 years ago
https://hg.mozilla.org/integration/mozilla-inbound/rev/eb017ddb11c6
Target Milestone: --- → mozilla15
https://hg.mozilla.org/mozilla-central/rev/eb017ddb11c6
Status: ASSIGNED → RESOLVED
Last Resolved: 5 years ago
Resolution: --- → FIXED
You need to log in before you can comment on or make changes to this bug.