Bug 760099 - add more loggin capabilities, r=tbsaunde
authorAlexander Surkov <surkov.alexander@gmail.com>
Sat, 02 Jun 2012 10:58:44 +0900
changeset 95960 e65e082823d70100909f49429bd3f856ad226f8a
parent 95959 40270cf81989c6e8d06f7fd009a5dd4e10985194
child 95961 70288798e65f8b1b32ea87c194d7bb5f8297848a
push id270
push userpvanderbeken@mozilla.com
push dateThu, 06 Mar 2014 09:24:21 +0000
reviewerstbsaunde
bugs760099
milestone15.0a1
Bug 760099 - add more loggin capabilities, r=tbsaunde
accessible/src/base/Logging.cpp
accessible/src/base/Logging.h
accessible/src/base/NotificationController.cpp
accessible/src/base/NotificationController.h
accessible/src/base/nsCaretAccessible.cpp
accessible/src/generic/RootAccessible.cpp
accessible/tests/mochitest/common.js
accessible/tests/mochitest/events.js
accessible/tests/mochitest/events/test_docload.xul
--- a/accessible/src/base/Logging.cpp
+++ b/accessible/src/base/Logging.cpp
@@ -10,16 +10,17 @@
 #include "DocAccessible.h"
 #include "nsAccessibilityService.h"
 #include "nsCoreUtils.h"
 #include "OuterDocAccessible.h"
 
 #include "nsDocShellLoadTypes.h"
 #include "nsIChannel.h"
 #include "nsIInterfaceRequestorUtils.h"
+#include "nsISelectionPrivate.h"
 #include "nsTraceRefcntImpl.h"
 #include "nsIWebProgress.h"
 #include "prenv.h"
 
 using namespace mozilla;
 using namespace mozilla::a11y;
 
 ////////////////////////////////////////////////////////////////////////////////
@@ -39,20 +40,27 @@ EnableLogging(const char* aModulesStr)
   if (!aModulesStr)
     return;
 
   static ModuleRep modules[] = {
     { "docload", logging::eDocLoad },
     { "doccreate", logging::eDocCreate },
     { "docdestroy", logging::eDocDestroy },
     { "doclifecycle", logging::eDocLifeCycle },
+
+    { "events", logging::eEvents },
     { "platforms", logging::ePlatforms },
     { "stack", logging::eStack },
     { "text", logging::eText },
-    { "tree", logging::eTree }
+    { "tree", logging::eTree },
+
+    { "DOMEvents", logging::eDOMEvents },
+    { "focus", logging::eFocus },
+    { "selection", logging::eSelection },
+    { "notifications", logging::eNotifications }
   };
 
   const char* token = aModulesStr;
   while (*token != '\0') {
     size_t tokenLen = strcspn(token, ",");
     for (unsigned int idx = 0; idx < ArrayLength(modules); idx++) {
       if (strncmp(token, modules[idx].mStr, tokenLen) == 0) {
         sModules |= modules[idx].mModule;
@@ -449,16 +457,37 @@ void
 logging::OuterDocDestroy(OuterDocAccessible* aOuterDoc)
 {
   MsgBegin(sDocDestroyTitle, "outerdoc shutdown");
   logging::Address("outerdoc", aOuterDoc);
   MsgEnd();
 }
 
 void
+logging::SelChange(nsISelection* aSelection, DocAccessible* aDocument)
+{
+  nsCOMPtr<nsISelectionPrivate> privSel(do_QueryInterface(aSelection));
+
+  PRInt16 type = 0;
+  privSel->GetType(&type);
+
+  const char* strType = 0;
+  if (type == nsISelectionController::SELECTION_NORMAL)
+    strType = "normal";
+  else if (type == nsISelectionController::SELECTION_SPELLCHECK)
+    strType = "spellcheck";
+  else
+    strType = "unknown";
+
+  bool isIgnored = !aDocument || !aDocument->IsContentLoaded();
+  printf("\nSelection changed, selection type: %s, notification %s\n",
+         strType, (isIgnored ? "ignored" : "pending"));
+}
+
+void
 logging::MsgBegin(const char* aTitle, const char* aMsgText, ...)
 {
   printf("\nA11Y %s: ", aTitle);
 
   va_list argptr;
   va_start(argptr, aMsgText);
   vprintf(aMsgText, argptr);
   va_end(argptr);
@@ -489,23 +518,26 @@ void
 logging::Text(const char* aText)
 {
   printf("  %s\n", aText);
 }
 
 void
 logging::Address(const char* aDescr, Accessible* aAcc)
 {
-  nsINode* node = aAcc->GetNode();
+  if (!aAcc->IsDoc()) {
+    printf("    %s accessible: %p, node: %p\n", aDescr,
+           static_cast<void*>(aAcc), static_cast<void*>(aAcc->GetNode()));
+  }
+
+  DocAccessible* doc = aAcc->Document();
   nsIDocument* docNode = aAcc->GetDocumentNode();
-  DocAccessible* doc = GetAccService()->GetDocAccessibleFromCache(docNode);
-  printf("    %s accessible: %p, node: %p\n", aDescr,
-         static_cast<void*>(aAcc), static_cast<void*>(node));
-  printf("    docacc for %s accessible: %p, node: %p\n", aDescr,
+  printf("    document: %p, node: %p\n",
          static_cast<void*>(doc), static_cast<void*>(docNode));
+
   printf("    ");
   LogDocURI(docNode);
   printf("\n");
 }
 
 void
 logging::Node(const char* aDescr, nsINode* aNode)
 {
--- a/accessible/src/base/Logging.h
+++ b/accessible/src/base/Logging.h
@@ -12,34 +12,42 @@
 
 class AccEvent;
 class Accessible;
 class DocAccessible;
 
 class nsIDocument;
 class nsINode;
 class nsIRequest;
+class nsISelection;
 class nsIWebProgress;
 
 namespace mozilla {
 namespace a11y {
 
 class OuterDocAccessible;
 
 namespace logging {
 
 enum EModules {
   eDocLoad = 1 << 0,
   eDocCreate = 1 << 1,
   eDocDestroy = 1 << 2,
   eDocLifeCycle = eDocLoad | eDocCreate | eDocDestroy,
-  ePlatforms = 1 << 3,
-  eStack = 1 << 4,
-  eText = 1 << 5,
-  eTree = 1 << 6
+
+  eEvents = 1 << 3,
+  ePlatforms = 1 << 4,
+  eStack = 1 << 5,
+  eText = 1 << 6,
+  eTree = 1 << 7,
+
+  eDOMEvents = 1 << 8,
+  eFocus = 1 << 9,
+  eSelection = 1 << 10,
+  eNotifications = eDOMEvents | eSelection | eFocus
 };
 
 /**
  * Return true if any of the given modules is logged.
  */
 bool IsEnabled(PRUint32 aModules);
 
 /**
@@ -72,40 +80,45 @@ void DocDestroy(const char* aMsg, nsIDoc
                 DocAccessible* aDocument = nsnull);
 
 /**
  * Log the outer document was destroyed.
  */
 void OuterDocDestroy(OuterDocAccessible* OuterDoc);
 
 /**
+ * Log the selection change.
+ */
+void SelChange(nsISelection* aSelection, DocAccessible* aDocument);
+
+/**
  * Log the message ('title: text' format) on new line. Print the start and end
  * boundaries of the message body designated by '{' and '}' (2 spaces indent for
  * body).
  */
 void MsgBegin(const char* aTitle, const char* aMsgText, ...);
 void MsgEnd();
 
 /**
- * Log the entry into message body (4 spaces offset).
+ * Log the entry into message body (4 spaces indent).
  */
 void MsgEntry(const char* aEntryText, ...);
 
 /**
  * Log the text, two spaces offset is used.
  */
 void Text(const char* aText);
 
 /**
- * Log the accesisble object address (4 spaces indent).
+ * Log the accessible object address as message entry (4 spaces indent).
  */
 void Address(const char* aDescr, Accessible* aAcc);
 
 /**
- * Log the DOM node info.
+ * Log the DOM node info as message entry.
  */
 void Node(const char* aDescr, nsINode* aNode);
 
 /**
  * Log the call stack, two spaces offset is used.
  */
 void Stack();
 
--- a/accessible/src/base/NotificationController.cpp
+++ b/accessible/src/base/NotificationController.cpp
@@ -294,16 +294,24 @@ NotificationController::WillRefresh(mozi
   // process it synchronously.
   mObservingState = eRefreshObserving;
 
   // Process only currently queued events.
   nsTArray<nsRefPtr<AccEvent> > events;
   events.SwapElements(mEvents);
 
   PRUint32 eventCount = events.Length();
+#ifdef DEBUG
+  if (eventCount > 0 && logging::IsEnabled(logging::eEvents)) {
+    logging::MsgBegin("EVENTS", "events processing");
+    logging::Address("document", mDocument);
+    logging::MsgEnd();
+  }
+#endif
+
   for (PRUint32 idx = 0; idx < eventCount; idx++) {
     AccEvent* accEvent = events[idx];
     if (accEvent->mEventRule != AccEvent::eDoNotEmit) {
       Accessible* target = accEvent->GetAccessible();
       if (!target || target->IsDefunct())
         continue;
 
       // Dispatch the focus event if target is still focused.
--- a/accessible/src/base/NotificationController.h
+++ b/accessible/src/base/NotificationController.h
@@ -5,23 +5,24 @@
 
 #ifndef NotificationController_h_
 #define NotificationController_h_
 
 #include "AccEvent.h"
 #include "nsCycleCollectionParticipant.h"
 #include "nsRefreshDriver.h"
 
+#ifdef DEBUG
+#include "Logging.h"
+#endif
+
 class Accessible;
 class DocAccessible;
 class nsIContent;
 
-// Uncomment to log notifications processing.
-//#define DEBUG_NOTIFICATIONS
-
 /**
  * Notification interface.
  */
 class Notification
 {
 public:
   virtual ~Notification() { };
 
@@ -130,18 +131,19 @@ public:
    *        the notification is processed.
    */
   template<class Class, class Arg>
   inline void HandleNotification(Class* aInstance,
                                  typename TNotification<Class, Arg>::Callback aMethod,
                                  Arg* aArg)
   {
     if (!IsUpdatePending()) {
-#ifdef DEBUG_NOTIFICATIONS
-      printf("\nsync notification processing\n");
+#ifdef DEBUG
+      if (mozilla::a11y::logging::IsEnabled(mozilla::a11y::logging::eNotifications))
+        mozilla::a11y::logging::Text("sync notification processing");
 #endif
       (aInstance->*aMethod)(aArg);
       return;
     }
 
     nsRefPtr<Notification> notification =
       new TNotification<Class, Arg>(aInstance, aMethod, aArg);
     if (notification && mNotifications.AppendElement(notification))
--- a/accessible/src/base/nsCaretAccessible.cpp
+++ b/accessible/src/base/nsCaretAccessible.cpp
@@ -176,37 +176,19 @@ nsCaretAccessible::NotifySelectionChange
                                           PRInt16 aReason)
 {
   NS_ENSURE_ARG(aDOMDocument);
   NS_ENSURE_STATE(mRootAccessible);
 
   nsCOMPtr<nsIDocument> documentNode(do_QueryInterface(aDOMDocument));
   DocAccessible* document = GetAccService()->GetDocAccessible(documentNode);
 
-#ifdef DEBUG_NOTIFICATIONS
-  nsCOMPtr<nsISelectionPrivate> privSel(do_QueryInterface(aSelection));
-
-  PRInt16 type = 0;
-  privSel->GetType(&type);
-
-  if (type == nsISelectionController::SELECTION_NORMAL ||
-      type == nsISelectionController::SELECTION_SPELLCHECK) {
-
-    bool isNormalSelection =
-      (type == nsISelectionController::SELECTION_NORMAL);
-
-    bool isIgnored = !document || !document->IsContentLoaded();
-    printf("\nSelection changed, selection type: %s, notification %s\n",
-           (isNormalSelection ? "normal" : "spellcheck"),
-           (isIgnored ? "ignored" : "pending"));
-  } else {
-    bool isIgnored = !document || !document->IsContentLoaded();
-    printf("\nSelection changed, selection type: unknown, notification %s\n",
-               (isIgnored ? "ignored" : "pending"));
-  }
+#ifdef DEBUG
+  if (logging::IsEnabled(logging::eSelection))
+    logging::SelChange(aSelection, document);
 #endif
 
   // Don't fire events until document is loaded.
   if (document && document->IsContentLoaded()) {
     // The caret accessible has the same lifetime as the root accessible, and
     // this outlives all its descendant document accessibles, so that we are
     // guaranteed that the notification is processed before the caret accessible
     // is destroyed.
--- a/accessible/src/generic/RootAccessible.cpp
+++ b/accessible/src/generic/RootAccessible.cpp
@@ -268,34 +268,25 @@ RootAccessible::HandleEvent(nsIDOMEvent*
   nsCOMPtr<nsINode> origTargetNode(do_QueryInterface(DOMEventTarget));
   if (!origTargetNode)
     return NS_OK;
 
   DocAccessible* document =
     GetAccService()->GetDocAccessible(origTargetNode->OwnerDoc());
 
   if (document) {
-#ifdef DEBUG_NOTIFICATIONS
-    if (origTargetNode->IsElement()) {
-      nsIContent* elm = origTargetNode->AsElement();
-
-      nsAutoString tag;
-      elm->Tag()->ToString(tag);
-
-      nsIAtom* atomid = elm->GetID();
-      nsCAutoString id;
-      if (atomid)
-        atomid->ToUTF8String(id);
-
+#ifdef DEBUG
+    if (logging::IsEnabled(logging::eDOMEvents)) {
       nsAutoString eventType;
       aDOMEvent->GetType(eventType);
 
-      printf("\nPend DOM event processing for %s@id='%s', type: %s\n\n",
-             NS_ConvertUTF16toUTF8(tag).get(), id.get(),
-             NS_ConvertUTF16toUTF8(eventType).get());
+      logging::MsgBegin("DOMEvents", "event '%s' handled",
+                        NS_ConvertUTF16toUTF8(eventType).get());
+      logging::Node("target", origTargetNode);
+      logging::MsgEnd();
     }
 #endif
 
     // Root accessible exists longer than any of its descendant documents so
     // that we are guaranteed notification is processed before root accessible
     // is destroyed.
     document->HandleNotification<RootAccessible, nsIDOMEvent>
       (this, &RootAccessible::ProcessDOMEvent, aDOMEvent);
--- a/accessible/tests/mochitest/common.js
+++ b/accessible/tests/mochitest/common.js
@@ -81,16 +81,28 @@ const kSquareBulletText = String.fromCha
 
 /**
  * nsIAccessibleRetrieval service.
  */
 var gAccRetrieval = Components.classes["@mozilla.org/accessibleRetrieval;1"].
   getService(nsIAccessibleRetrieval);
 
 /**
+ * Enable/disable logging.
+ */
+function enableLogging(aModules)
+{
+  gAccRetrieval.setLogging(aModules);
+}
+function disableLogging()
+{
+  gAccRetrieval.setLogging("");
+}
+
+/**
  * Invokes the given function when document is loaded and focused. Preferable
  * to mochitests 'addLoadEvent' function -- additionally ensures state of the
  * document accessible is not busy.
  *
  * @param aFunc  the function to invoke
  */
 function addA11yLoadEvent(aFunc, aWindow)
 {
--- a/accessible/tests/mochitest/events.js
+++ b/accessible/tests/mochitest/events.js
@@ -48,16 +48,21 @@ var gA11yEventDumpID = "";
 var gA11yEventDumpToConsole = false;
 
 /**
  * Set up this variable to dump event processing into error console.
  */
 var gA11yEventDumpToAppConsole = false;
 
 /**
+ * Semicolon separated set of logging features.
+ */
+var gA11yEventDumpFeature = "";
+
+/**
  * Executes the function when requested event is handled.
  *
  * @param aEventType  [in] event type
  * @param aTarget     [in] event target
  * @param aFunc       [in] function to call when event is handled
  * @param aContext    [in, optional] object in which context the function is
  *                    called
  * @param aArg1       [in, optional] argument passed into the function
@@ -535,16 +540,18 @@ function eventQueue(aEventType)
 
       for (var idx = 0; idx < this.mEventSeq.length; idx++) {
         var eventType = this.getEventType(idx);
 
         if (gLogger.isEnabled()) {
           var msg = "registered";
           if (this.isEventUnexpected(idx))
             msg += " unexpected";
+          if (this.mEventSeq[idx].async)
+            msg += " async";
 
           msg += ": event type: " + this.getEventTypeAsString(idx) +
             ", target: " + this.getEventTargetDescr(idx, true);
 
           gLogger.logToConsole(msg);
           gLogger.logToDOM(msg, true);
         }
 
@@ -1516,16 +1523,25 @@ var gA11yEventObserver =
             " text: " + event.modifiedText;
         }
 
         info += ". Target: " + prettyName(event.accessible);
 
         if (listenersArray)
           info += ". Listeners count: " + listenersArray.length;
 
+        if (gLogger.hasFeature("parentchain:" + type)) {
+          info += "\nParent chain:\n";
+          var acc = event.accessible;
+          while (acc) {
+            info += "  " + prettyName(acc) + "\n";
+            acc = acc.parent;
+          }
+        }
+
         eventFromDumpArea = false;
         gLogger.log(info);
       }
     }
 
     // Do not notify listeners if event is result of event log changes.
     if (!listenersArray || eventFromDumpArea)
       return;
@@ -1658,16 +1674,30 @@ var gLogger =
 
   /**
    * Log message to error console.
    */
   logToAppConsole: function logger_logToAppConsole(aMsg)
   {
     if (gA11yEventDumpToAppConsole)
       Services.console.logStringMessage("events: " + aMsg);
+  },
+
+  /**
+   * Return true if logging feature is enabled.
+   */
+  hasFeature: function logger_hasFeature(aFeature)
+  {
+    var startIdx = gA11yEventDumpFeature.indexOf(aFeature);
+    if (startIdx == - 1)
+      return false;
+
+    var endIdx = startIdx + aFeature.length;
+    return endIdx == gA11yEventDumpFeature.length ||
+      gA11yEventDumpFeature[endIdx] == ";";
   }
 };
 
 
 ////////////////////////////////////////////////////////////////////////////////
 // Sequence
 
 /**
--- a/accessible/tests/mochitest/events/test_docload.xul
+++ b/accessible/tests/mochitest/events/test_docload.xul
@@ -179,36 +179,39 @@
         return "load error page: '" + aURLDescr + "'";
       }
     }
 
     ////////////////////////////////////////////////////////////////////////////
     // Tests
 
     gA11yEventDumpToConsole = true; // debug
+    gA11yEventDumpFeature = "parentchain:reorder";
 
     var gQueue = null;
     function doTests()
     {
+      enableLogging("events");
+
       gQueue = new eventQueue();
 
       var dataURL =
         "data:text/html,<html><body><iframe src='http://example.com'></iframe></body></html>";
       gQueue.push(new loadNestedDocURIInvoker(dataURL));
 
       gQueue.push(new loadURIInvoker("about:"));
       gQueue.push(new userReloadInvoker());
       gQueue.push(new loadURIInvoker("about:mozilla"));
       gQueue.push(new reloadInvoker());
       gQueue.push(new loadErrorPageInvoker("www.wronguri.wronguri",
                                            "Server not found"));
       gQueue.push(new loadErrorPageInvoker("https://nocert.example.com:443",
                                           "Untrusted Connection"));
 
-      gQueue.onFinish = function() { closeBrowserWindow(); }
+      gQueue.onFinish = function() { closeBrowserWindow(); disableLogging(); }
       gQueue.invoke();
     }
 
     SimpleTest.waitForExplicitFinish();
     openBrowserWindow(doTests);
   ]]>
   </script>