Streamline debugging infrastructure even more

5 files changed, 136 insertions, 73 deletions

diff --git a/src/hb-blob.cc b/src/hb-blob.cc
index f6537cd..2d0c016 100644
--- a/src/hb-blob.cc
+++ b/src/hb-blob.cc
@@ -243,27 +243,27 @@ _try_make_writable_inplace_unix (hb_blob_t *blob)
 #endif
 
   if ((uintptr_t) -1L == pagesize) {
-    DEBUG_MSG (BLOB, "%p %s: failed to get pagesize: %s\n", (void *) blob, HB_FUNC, strerror (errno));
+    DEBUG_MSG_FUNC (BLOB, blob, "failed to get pagesize: %s", strerror (errno));
     return FALSE;
   }
-  DEBUG_MSG (BLOB, "%p %s: pagesize is %lu\n", (void *) blob, HB_FUNC, (unsigned long) pagesize);
+  DEBUG_MSG_FUNC (BLOB, blob, "pagesize is %lu", (unsigned long) pagesize);
 
   mask = ~(pagesize-1);
   addr = (const char *) (((uintptr_t) blob->data) & mask);
   length = (const char *) (((uintptr_t) blob->data + blob->length + pagesize-1) & mask)  - addr;
-  DEBUG_MSG (BLOB, "%p %s: calling mprotect on [%p..%p] (%lu bytes)\n",
-		   (void *) blob, HB_FUNC,
-		   addr, addr+length, (unsigned long) length);
+  DEBUG_MSG_FUNC (BLOB, blob,
+		  "calling mprotect on [%p..%p] (%lu bytes)",
+		  addr, addr+length, (unsigned long) length);
   if (-1 == mprotect ((void *) addr, length, PROT_READ | PROT_WRITE)) {
-    DEBUG_MSG (BLOB, "%p %s: %s\n", (void *) blob, HB_FUNC, strerror (errno));
+    DEBUG_MSG_FUNC (BLOB, blob, "mprotect failed: %s", strerror (errno));
     return FALSE;
   }
 
   blob->mode = HB_MEMORY_MODE_WRITABLE;
 
-  DEBUG_MSG (BLOB, "%p %s: successfully made [%p..%p] (%lu bytes) writable\n",
-		   (void *) blob, HB_FUNC,
-		   addr, addr+length, (unsigned long) length);
+  DEBUG_MSG_FUNC (BLOB, blob,
+		  "successfully made [%p..%p] (%lu bytes) writable\n",
+		  addr, addr+length, (unsigned long) length);
   return TRUE;
 #else
   return FALSE;
@@ -273,12 +273,12 @@ _try_make_writable_inplace_unix (hb_blob_t *blob)
 static bool
 _try_writable_inplace (hb_blob_t *blob)
 {
-  DEBUG_MSG (BLOB, "%p %s: making writable inplace\n", (void *) blob, HB_FUNC);
+  DEBUG_MSG_FUNC (BLOB, blob, "making writable inplace\n");
 
   if (_try_make_writable_inplace_unix (blob))
     return TRUE;
 
-  DEBUG_MSG (BLOB, "%p %s: making writable -> FAILED\n", (void *) blob, HB_FUNC);
+  DEBUG_MSG_FUNC (BLOB, blob, "making writable -> FAILED\n");
 
   /* Failed to make writable inplace, mark that */
   blob->mode = HB_MEMORY_MODE_READONLY;
@@ -301,7 +301,7 @@ _try_writable (hb_blob_t *blob)
     return TRUE;
 
 
-  DEBUG_MSG (BLOB, "%p %s -> %p\n", (void *) blob, HB_FUNC, blob->data);
+  DEBUG_MSG_FUNC (BLOB, blob, "currect data is -> %p\n", blob->data);
 
   char *new_data;
 
@@ -309,7 +309,7 @@ _try_writable (hb_blob_t *blob)
   if (unlikely (!new_data))
     return FALSE;
 
-  DEBUG_MSG (BLOB, "%p %s: dupped successfully -> %p\n", (void *) blob, HB_FUNC, blob->data);
+  DEBUG_MSG_FUNC (BLOB, blob, "dupped successfully -> %p\n", blob->data);
 
   memcpy (new_data, blob->data, blob->length);
   _hb_blob_destroy_user_data (blob);
diff --git a/src/hb-object-private.hh b/src/hb-object-private.hh
index 37b4703..1b25443 100644
--- a/src/hb-object-private.hh
+++ b/src/hb-object-private.hh
@@ -191,10 +191,10 @@ struct _hb_object_header_t {
   }
 
   inline void trace (const char *function) const {
-    DEBUG_MSG (OBJECT, "OBJECT(%p) refcount=%d %s\n",
-		       (void *) this,
-		       this ? ref_count.get () : 0,
-		       function);
+    DEBUG_MSG (OBJECT, (void *) this,
+	       "refcount=%d %s",
+	       this ? ref_count.get () : 0,
+	       function);
   }
 
 };
diff --git a/src/hb-open-type-private.hh b/src/hb-open-type-private.hh
index b20e5ca..ab2a346 100644
--- a/src/hb-open-type-private.hh
+++ b/src/hb-open-type-private.hh
@@ -144,29 +144,6 @@ ASSERT_STATIC (Type::min_size + 1 <= sizeof (_Null##Type))
 #define Null(Type) Null<Type>()
 
 
-/*
- * Trace
- */
-
-
-template <int max_depth>
-struct hb_trace_t {
-  explicit hb_trace_t (unsigned int *pdepth_, const char *what, const char *function, const void *obj) : pdepth(pdepth_) {
-    (void) (*pdepth < max_depth &&
-	    fprintf (stderr, "%s(%p) %-*d-> %s\n", what, obj, *pdepth, *pdepth, function));
-    if (max_depth) ++*pdepth;
-  }
-  ~hb_trace_t (void) { if (max_depth) --*pdepth; }
-
-  private:
-  unsigned int *pdepth;
-};
-template <> /* Optimize when tracing is disabled */
-struct hb_trace_t<0> {
-  explicit hb_trace_t (unsigned int *pdepth HB_UNUSED, const char *what HB_UNUSED, const char *function HB_UNUSED, const void *obj HB_UNUSED) {}
-};
-
-
 
 /*
  * Sanitize
@@ -178,7 +155,7 @@ struct hb_trace_t<0> {
 
 
 #define TRACE_SANITIZE() \
-	hb_trace_t<HB_DEBUG_SANITIZE> trace (&c->debug_depth, "SANITIZE", HB_FUNC, this); \
+	hb_auto_trace_t<HB_DEBUG_SANITIZE> trace (&c->debug_depth, "SANITIZE", this, NULL, HB_FUNC);
 
 
 struct hb_sanitize_context_t
@@ -196,15 +173,17 @@ struct hb_sanitize_context_t
     this->edit_count = 0;
     this->debug_depth = 0;
 
-    DEBUG_MSG (SANITIZE, "sanitize %p init [%p..%p] (%lu bytes)\n",
-			 (void *) this->blob, this->start, this->end,
-			 (unsigned long) (this->end - this->start));
+    DEBUG_MSG (SANITIZE, this->blob,
+	       "init [%p..%p] (%lu bytes)",
+	       this->start, this->end,
+	       (unsigned long) (this->end - this->start));
   }
 
   inline void finish (void)
   {
-    DEBUG_MSG (SANITIZE, "sanitize %p fini [%p..%p] %u edit requests\n",
-			 (void *) this->blob, this->start, this->end, this->edit_count);
+    DEBUG_MSG (SANITIZE, this->blob,
+	       "fini [%p..%p] %u edit requests",
+	       this->start, this->end, this->edit_count);
 
     hb_blob_destroy (this->blob);
     this->blob = NULL;
@@ -218,9 +197,8 @@ struct hb_sanitize_context_t
 	       p <= this->end &&
 	       (unsigned int) (this->end - p) >= len;
 
-    DEBUG_MSG_LEVEL (SANITIZE, this->debug_depth,
-		     "SANITIZE(%p) %-*d-> range [%p..%p] (%d bytes) in [%p..%p] -> %s\n",
-		     p,
+    DEBUG_MSG_LEVEL (SANITIZE, this->blob, this->debug_depth,
+		     "%-*d-> range [%p..%p] (%d bytes) in [%p..%p] -> %s",
 		     this->debug_depth, this->debug_depth,
 		     p, p + len, len,
 		     this->start, this->end,
@@ -234,9 +212,8 @@ struct hb_sanitize_context_t
     const char *p = (const char *) base;
     bool overflows = _hb_unsigned_int_mul_overflows (len, record_size);
 
-    DEBUG_MSG_LEVEL (SANITIZE, this->debug_depth,
-		     "SANITIZE(%p) %-*d-> array [%p..%p] (%d*%d=%ld bytes) in [%p..%p] -> %s\n",
-		     p,
+    DEBUG_MSG_LEVEL (SANITIZE, this->blob, this->debug_depth,
+		     "%-*d-> array [%p..%p] (%d*%d=%ld bytes) in [%p..%p] -> %s",
 		     this->debug_depth, this->debug_depth,
 		     p, p + (record_size * len), record_size, len, (unsigned long) record_size * len,
 		     this->start, this->end,
@@ -256,9 +233,8 @@ struct hb_sanitize_context_t
     const char *p = (const char *) base;
     this->edit_count++;
 
-    DEBUG_MSG_LEVEL (SANITIZE, this->debug_depth,
-		     "SANITIZE(%p) %-*d-> edit(%u) [%p..%p] (%d bytes) in [%p..%p] -> %s\n",
-		     p,
+    DEBUG_MSG_LEVEL (SANITIZE, this->blob, this->debug_depth,
+		     "%-*d-> edit(%u) [%p..%p] (%d bytes) in [%p..%p] -> %s",
 		     this->debug_depth, this->debug_depth,
 		     this->edit_count,
 		     p, p + len, len,
@@ -290,7 +266,7 @@ struct Sanitizer
     c->init (blob);
 
   retry:
-    DEBUG_MSG (SANITIZE, "Sanitizer %p start %s\n", (void *) blob, HB_FUNC);
+    DEBUG_MSG_FUNC (SANITIZE, blob, "start");
 
     c->setup ();
 
@@ -304,15 +280,13 @@ struct Sanitizer
     sane = t->sanitize (c);
     if (sane) {
       if (c->edit_count) {
-	DEBUG_MSG (SANITIZE, "Sanitizer %p passed first round with %d edits; doing a second round %s\n",
-			     (void *) blob, c->edit_count, HB_FUNC);
+	DEBUG_MSG_FUNC (SANITIZE, blob, "passed first round with %d edits; going for second round", c->edit_count);
 
         /* sanitize again to ensure no toe-stepping */
         c->edit_count = 0;
 	sane = t->sanitize (c);
 	if (c->edit_count) {
-	  DEBUG_MSG (SANITIZE, "Sanitizer %p requested %d edits in second round; FAILLING %s\n",
-			       (void *) blob, c->edit_count, HB_FUNC);
+	  DEBUG_MSG_FUNC (SANITIZE, blob, "requested %d edits in second round; FAILLING", c->edit_count);
 	  sane = false;
 	}
       }
@@ -325,7 +299,7 @@ struct Sanitizer
 	if (c->start) {
 	  c->writable = true;
 	  /* ok, we made it writable by relocating.  try again */
-	  DEBUG_MSG (SANITIZE, "Sanitizer %p retry %s\n", (void *) blob, HB_FUNC);
+	  DEBUG_MSG_FUNC (SANITIZE, blob, "retry");
 	  goto retry;
 	}
       }
@@ -333,7 +307,7 @@ struct Sanitizer
 
     c->finish ();
 
-    DEBUG_MSG (SANITIZE, "Sanitizer %p %s %s\n", (void *) blob, sane ? "passed" : "FAILED", HB_FUNC);
+    DEBUG_MSG_FUNC (SANITIZE, blob, sane ? "PASSED" : "FAILED");
     if (sane)
       return blob;
     else {
diff --git a/src/hb-ot-layout-gsubgpos-private.hh b/src/hb-ot-layout-gsubgpos-private.hh
index 1d75253..3dcfb21 100644
--- a/src/hb-ot-layout-gsubgpos-private.hh
+++ b/src/hb-ot-layout-gsubgpos-private.hh
@@ -51,7 +51,7 @@ static inline uint8_t allocate_lig_id (hb_buffer_t *buffer) {
 #endif
 
 #define TRACE_APPLY() \
-	hb_trace_t<HB_DEBUG_APPLY> trace (&c->debug_depth, "APPLY", HB_FUNC, this); \
+	hb_auto_trace_t<HB_DEBUG_APPLY> trace (&c->debug_depth, "APPLY", this, NULL, HB_FUNC);
 
 
 HB_BEGIN_DECLS
diff --git a/src/hb-private.hh b/src/hb-private.hh
index f7731df..9482795 100644
--- a/src/hb-private.hh
+++ b/src/hb-private.hh
@@ -45,6 +45,7 @@
  * someway around that. */
 #include <stdio.h>
 #include <errno.h>
+#include <stdarg.h>
 
 HB_BEGIN_DECLS
 
@@ -124,9 +125,11 @@ ASSERT_STATIC (sizeof (hb_var_int_t) == 4);
 #if __GNUC__ >= 3
 #define HB_PURE_FUNC	__attribute__((pure))
 #define HB_CONST_FUNC	__attribute__((const))
+#define HB_PRINTF_FUNC(format_idx, arg_idx) __attribute__((__format__ (__printf__, format_idx, arg_idx)))
 #else
 #define HB_PURE_FUNC
 #define HB_CONST_FUNC
+#define HB_PRINTF_FUCN(format_idx, arg_idx)
 #endif
 #if __GNUC__ >= 4
 #define HB_UNUSED	__attribute__((unused))
@@ -462,27 +465,113 @@ static inline unsigned char TOLOWER (unsigned char c)
 
 /* Debug */
 
+HB_END_DECLS
+
 #ifndef HB_DEBUG
 #define HB_DEBUG 0
 #endif
 
-#define DEBUG_LEVEL(WHAT, LEVEL) (HB_DEBUG_##WHAT && (int) (LEVEL) < (int) (HB_DEBUG_##WHAT))
+static inline bool
+_hb_debug (unsigned int level,
+	   unsigned int max_level)
+{
+  return level < max_level;
+}
+
+#define DEBUG_LEVEL(WHAT, LEVEL) (_hb_debug ((LEVEL), HB_DEBUG_##WHAT))
 #define DEBUG(WHAT) (DEBUG_LEVEL (WHAT, 0))
 
-#define DEBUG_MSG_LEVEL(WHAT, LEVEL, ...) (void) (DEBUG_LEVEL (WHAT, LEVEL)  && fprintf (stderr, __VA_ARGS__))
-#define DEBUG_MSG(WHAT, ...) DEBUG_MSG_LEVEL (WHAT, 0, __VA_ARGS__)
+template <int max_level> inline bool /* always returns TRUE */
+_hb_debug_msg (const char *what,
+	       const void *obj,
+	       const char *func,
+	       bool indented,
+	       int level,
+	       const char *message,
+	       ...) HB_PRINTF_FUNC(6, 7);
+template <int max_level> inline bool /* always returns TRUE */
+_hb_debug_msg (const char *what,
+	       const void *obj,
+	       const char *func,
+	       bool indented,
+	       int level,
+	       const char *message,
+	       ...)
+{
+  va_list ap;
+  va_start (ap, message);
+
+  (void) (_hb_debug (level, max_level) &&
+	  fprintf (stderr, "%s(%p): ", what, obj) &&
+	  (func && fprintf (stderr, "%s: ", func), TRUE) &&
+	  (indented && fprintf (stderr, "%-*d-> ", level + 1, level), TRUE) &&
+	  vfprintf (stderr, message, ap) &&
+	  fprintf (stderr, "\n"));
+
+  va_end (ap);
 
-static inline bool /* always returns TRUE */
-_hb_trace (const char *what,
-	   const char *message,
-	   const void *obj,
-	   unsigned int depth,
-	   unsigned int max_depth)
+  return TRUE;
+}
+template <> inline bool /* always returns TRUE */
+_hb_debug_msg<0> (const char *what,
+		  const void *obj,
+		  const char *func,
+		  bool indented,
+		  int level,
+		  const char *message,
+		  ...) HB_PRINTF_FUNC(6, 7);
+template <> inline bool /* always returns TRUE */
+_hb_debug_msg<0> (const char *what,
+		  const void *obj,
+		  const char *func,
+		  bool indented,
+		  int level,
+		  const char *message,
+		  ...)
 {
-  (void) ((depth < max_depth) && fprintf (stderr, "%s(%p) %-*d-> %s\n", what, obj, depth, depth, message));
   return TRUE;
 }
 
+#define DEBUG_MSG_LEVEL(WHAT, OBJ, LEVEL, ...) _hb_debug_msg<HB_DEBUG_##WHAT> (#WHAT, (OBJ), NULL, FALSE, (LEVEL), __VA_ARGS__)
+#define DEBUG_MSG(WHAT, OBJ, ...) DEBUG_MSG_LEVEL (WHAT, OBJ, 0, __VA_ARGS__)
+#define DEBUG_MSG_FUNC(WHAT, OBJ, ...) _hb_debug_msg<HB_DEBUG_##WHAT> (#WHAT, (OBJ), HB_FUNC, FALSE, 0, __VA_ARGS__)
+
+
+/*
+ * Trace
+ */
+
+template <int max_level>
+struct hb_auto_trace_t {
+  explicit inline hb_auto_trace_t (unsigned int *plevel_,
+				   const char *what,
+				   const void *obj,
+				   const char *func,
+				   const char *message) : plevel(plevel_)
+  {
+    if (max_level) ++*plevel;
+    /* TODO support variadic args here */
+    _hb_debug_msg<max_level> (what, obj, func, TRUE, *plevel, "%s", message);
+  }
+  ~hb_auto_trace_t (void) { if (max_level) --*plevel; }
+
+  private:
+  unsigned int *plevel;
+};
+template <> /* Optimize when tracing is disabled */
+struct hb_auto_trace_t<0> {
+  explicit inline hb_auto_trace_t (unsigned int *plevel_,
+				   const char *what,
+				   const void *obj,
+				   const char *func,
+				   const char *message) {}
+};
+
+HB_BEGIN_DECLS
+
+
+/* Misc */
+
 
 /* Pre-mature optimization:
  * Checks for lo <= u <= hi but with an optimization if lo and hi