oleavr/frida-logging.md

## frida-logging.md

      
    Raw
  

              frida-logging.md
            
          
    Frida logging helper

For adding temporary logging to help understand behavior. For when it is
impractical to use Frida to instrument Frida.
Choose one of these and copy-paste it into e.g. lib/interfaces/session.vala,
then use log_event ("name='%s'", name); to log.
When something appears to be hanging, try applying: x-async-debug.patch.
For logging-hack-file.vala, add the following line to lib/interfaces/meson.build
right after the line specifying the vala_header option:
  vala_args: ['--pkg=posix'],


## logging-hack-file.vala
namespace Frida {
	private static Mutex log_mutex;
	private static Timer log_timer = null;
	private static Gee.HashMap<uint, uint> log_threads = null;
	private const uint[] log_palette = { 36, 35, 33, 32, 31, 34 };
	private static uint log_palette_offset = 0;

	public void log_event (string format, ...) {
		var builder = new StringBuilder ();

		log_mutex.lock ();

		uint time_delta;
		if (log_timer == null) {
			log_timer = new Timer ();
			log_threads = new Gee.HashMap<uint, uint> ();

			time_delta = 0;
		} else {
			time_delta = (uint) (log_timer.elapsed () * 1000.0);
			log_timer.reset ();
		}
		if (time_delta > 0) {
			builder.append_printf ("\n*** +%u ms\n", time_delta);
		}

		var tid = (uint) Gum.Process.get_current_thread_id ();

		var color = log_threads[tid];
		if (color == 0) {
			color = log_palette[log_palette_offset];
			log_palette_offset = (log_palette_offset + 1) % log_palette.length;
			log_threads[tid] = color;
		}
		builder.append_printf ("\033[0;%um", color);

		builder.append_printf ("[thread %04x] ", tid);

		var args = va_list ();
		builder.append_vprintf (format, args);

		builder.append ("\033[0m\n");

		var logfile = FileStream.open ("/data/local/tmp/frida-debug/pid_%u-uid_%u.log".printf (Posix.getpid (), (uint) Posix.getuid ()), "a");
		if (logfile != null) {
			logfile.write (builder.str.data);
			logfile = null;
		}

		log_mutex.unlock ();
	}
}

## logging-hack-stderr.vala
namespace Frida {
	private static Mutex log_mutex;
	private static Timer log_timer = null;
	private static Gee.HashMap<uint, uint> log_threads = null;
	private const uint[] log_palette = { 36, 35, 33, 32, 31, 34 };
	private static uint log_palette_offset = 0;

	public void log_event (string format, ...) {
		var builder = new StringBuilder ();

		log_mutex.lock ();

		uint time_delta;
		if (log_timer == null) {
			log_timer = new Timer ();
			log_threads = new Gee.HashMap<uint, uint> ();

			time_delta = 0;
		} else {
			time_delta = (uint) (log_timer.elapsed () * 1000.0);
			log_timer.reset ();
		}
		if (time_delta > 0) {
			builder.append_printf ("\n*** +%u ms\n", time_delta);
		}

		var tid = (uint) Gum.Process.get_current_thread_id ();

		var color = log_threads[tid];
		if (color == 0) {
			color = log_palette[log_palette_offset];
			log_palette_offset = (log_palette_offset + 1) % log_palette.length;
			log_threads[tid] = color;
		}
		builder.append_printf ("\033[0;%um", color);

		builder.append_printf ("[thread %04x] ", tid);

		var args = va_list ();
		builder.append_vprintf (format, args);

		builder.append ("\033[0m\n");

		stderr.write (builder.str.data);

		log_mutex.unlock ();
	}
}

## nativecallback-uaf.patch
diff --git a/bindings/gumjs/gumquickcore.c b/bindings/gumjs/gumquickcore.c
index b0b54c3e..6ffa7179 100644
--- a/bindings/gumjs/gumquickcore.c
+++ b/bindings/gumjs/gumquickcore.c
@@ -139,6 +139,10 @@ struct _GumQuickNativeCallback
   ffi_type ** atypes;
   GSList * data;

+  gboolean destroyed;
+  gchar * ctor_stack;
+  gchar * dtor_stack;
+
   GumQuickCore * core;
 };

@@ -1131,6 +1135,8 @@ _gum_quick_core_dispose (GumQuickCore * self)
   self->weak_map_delete_method = JS_NULL;

   gum_quick_core_teardown_atoms (self);
+
+  self->disposed = TRUE;
 }

 void
@@ -3437,6 +3443,33 @@ invalid_value:
   }
 }

+static gchar *
+gum_quick_capture_js_stack_here (GumQuickCore * core)
+{
+  gchar * result;
+  JSContext * ctx = core->ctx;
+  JSValue exception_val, stack_val;
+  const char * stack, * newline;
+
+  if (core->disposed)
+    return g_strdup ("<teardown>");
+
+  JS_ThrowInternalError (ctx, "oops");
+  exception_val = JS_GetException (ctx);
+
+  stack_val = JS_GetPropertyStr (ctx, exception_val, "stack");
+  stack = JS_ToCString (ctx, stack_val);
+
+  newline = strchr (stack, '\n');
+  result = g_strdup ((newline != NULL) ? newline + 1 : stack);
+
+  JS_FreeCString (ctx, stack);
+  JS_FreeValue (ctx, stack_val);
+  JS_FreeValue (ctx, exception_val);
+
+  return result;
+}
+
 GUMJS_DEFINE_CONSTRUCTOR (gumjs_native_callback_construct)
 {
   JSValue wrapper = JS_NULL;
@@ -3518,6 +3551,8 @@ GUMJS_DEFINE_CONSTRUCTOR (gumjs_native_callback_construct)
       JS_DupValue (ctx, func),
       0);

+  cb->ctor_stack = gum_quick_capture_js_stack_here (core);
+
   return wrapper;

 alloc_failed:
@@ -3560,6 +3595,10 @@ GUMJS_DEFINE_FINALIZER (gumjs_native_callback_finalize)
 static void
 gum_quick_native_callback_finalize (GumQuickNativeCallback * callback)
 {
+  callback->destroyed = TRUE;
+  callback->dtor_stack = gum_quick_capture_js_stack_here (callback->core);
+
+#if 0
   ffi_closure_free (callback->closure);

   while (callback->data != NULL)
@@ -3571,6 +3610,7 @@ gum_quick_native_callback_finalize (GumQuickNativeCallback * callback)
   g_free (callback->atypes);

   g_slice_free (GumQuickNativeCallback, callback);
+#endif
 }

 static void
@@ -3592,6 +3632,15 @@ gum_quick_native_callback_invoke (ffi_cif * cif,
   JSValue * argv;
   JSValue result;

+  if (self->destroyed)
+  {
+    g_critical ("NativeCallback use-after-free detected!\n\nCreated here:\n%s"
+        "\n\nDestroyed here:\n%s",
+        self->ctor_stack,
+        self->dtor_stack);
+    return;
+  }
+
   _gum_quick_scope_enter (&scope, core);

   JS_DupValue (ctx, self->wrapper);
diff --git a/bindings/gumjs/gumquickcore.h b/bindings/gumjs/gumquickcore.h
index 43cbd355..136b7c8c 100644
--- a/bindings/gumjs/gumquickcore.h
+++ b/bindings/gumjs/gumquickcore.h
@@ -63,6 +63,7 @@ struct _GumQuickCore
   JSContext * ctx;
   GHashTable * module_data;
   GumQuickScope * current_scope;
+  gboolean disposed;

   GRecMutex * mutex;
   volatile guint usage_count;

## x-async-debug.patch
diff --git a/src/frida.vala b/src/frida.vala
index eb431593..11002e37 100644
--- a/src/frida.vala
+++ b/src/frida.vala
@@ -2602,8 +2602,11 @@ namespace Frida {

 		private async void do_perform_operation () {
 			try {
+				printerr (">>> %s\n", this.get_type ().name ());
 				result = yield perform_operation ();
+				printerr ("<<< %s\n", this.get_type ().name ());
 			} catch (GLib.Error e) {
+				printerr ("<<< %s error=\"%s\"\n", this.get_type ().name (), e.message);
 				error = e;
 			}


## x-gum-logging.patch
commit 1251a7f314022f126266127fd174a472ac7b9710
Author: Ole André Vadla Ravnås <oleavr@gmail.com>
Date:   Tue Aug 20 23:21:49 2019 +0200

    Add temporary logging to investigate Interceptor issue

diff --git a/gum/backend-arm/guminterceptor-arm.c b/gum/backend-arm/guminterceptor-arm.c
index 2be32087..cf878acf 100644
--- a/gum/backend-arm/guminterceptor-arm.c
+++ b/gum/backend-arm/guminterceptor-arm.c
@@ -420,6 +420,8 @@ _gum_interceptor_backend_create_trampoline (GumInterceptorBackend * self,
   ctx->overwritten_prologue_len = reloc_bytes;
   memcpy (ctx->overwritten_prologue, function_address, reloc_bytes);

+  gum_log ("\t[ctx=%p] Generated on_enter=%p on_leave=%p", ctx, ctx->on_enter_trampoline, ctx->on_leave_trampoline);
+
   return TRUE;
 }

@@ -459,6 +461,7 @@ _gum_interceptor_backend_activate_trampoline (GumInterceptorBackend * self,
         gum_emit_push_cpu_context_high_part (tw);
         gum_thumb_writer_put_bl_imm (tw,
             GUM_ADDRESS (ctx->trampoline_deflector->trampoline));
+        gum_log ("\t[ctx=%p] Using shared Thumb deflector at %p", ctx, ctx->trampoline_deflector->trampoline);
       }
       else
       {
@@ -466,12 +469,14 @@ _gum_interceptor_backend_activate_trampoline (GumInterceptorBackend * self,
             GUM_INTERCEPTOR_THUMB_TINY_REDIRECT_SIZE);
         gum_thumb_writer_put_b_imm (tw,
             GUM_ADDRESS (ctx->trampoline_deflector->trampoline));
+        gum_log ("\t[ctx=%p] Using dedicated Thumb deflector at %p", ctx, ctx->trampoline_deflector->trampoline);
       }
     }
     else
     {
       gum_thumb_writer_put_ldr_reg_address (tw, ARM_REG_PC,
           GUM_ADDRESS (ctx->on_enter_trampoline));
+      gum_log ("\t[ctx=%p] Using direct Thumb branch", ctx);
     }

     gum_thumb_writer_flush (tw);
@@ -490,11 +495,13 @@ _gum_interceptor_backend_activate_trampoline (GumInterceptorBackend * self,
           GUM_INTERCEPTOR_ARM_TINY_REDIRECT_SIZE);
       gum_arm_writer_put_b_imm (aw,
           GUM_ADDRESS (ctx->trampoline_deflector->trampoline));
+      gum_log ("\t[ctx=%p] Using dedicated ARM deflector at %p", ctx, ctx->trampoline_deflector->trampoline);
     }
     else
     {
       gum_arm_writer_put_ldr_reg_address (aw, ARM_REG_PC,
           GUM_ADDRESS (ctx->on_enter_trampoline));
+      gum_log ("\t[ctx=%p] Using direct ARM branch", ctx);
     }

     gum_arm_writer_flush (aw);
@@ -508,6 +515,7 @@ _gum_interceptor_backend_deactivate_trampoline (GumInterceptorBackend * self,
                                                 gpointer prologue)
 {
   memcpy (prologue, ctx->overwritten_prologue, ctx->overwritten_prologue_len);
+  gum_log ("\t[ctx=%p] Deactivated", ctx);
 }

 gpointer
diff --git a/gum/gum.c b/gum/gum.c
index 06539a12..b3eda4f7 100644
--- a/gum/gum.c
+++ b/gum/gum.c
@@ -602,6 +602,44 @@ gum_on_log_message (const gchar * log_domain,
 #endif
 }

+void
+gum_log (const gchar * format,
+         ...)
+{
+  static GumInterceptor * interceptor = NULL;
+  gchar * path, * message;
+  va_list args;
+  FILE * file;
+
+  if (interceptor == NULL)
+  {
+    interceptor = gum_interceptor_obtain ();
+  }
+
+  gum_interceptor_ignore_current_thread (interceptor);
+
+  path = g_strdup_printf ("/data/local/tmp/frida-debug/pid_%u-uid_%u.log", getpid (), getuid ());
+
+  va_start (args, format);
+  message = g_strdup_vprintf (format, args);
+  va_end (args);
+
+  file = fopen (path, "a");
+  if (file != NULL)
+  {
+    fputs (message, file);
+    fputc ('\n', file);
+
+    fclose (file);
+  }
+
+  g_free (message);
+
+  g_free (path);
+
+  gum_interceptor_unignore_current_thread (interceptor);
+}
+
 static GumAddress *
 gum_address_copy (const GumAddress * address)
 {
diff --git a/gum/gumdefs.h b/gum/gumdefs.h
index 57e19414..a2b7c25f 100644
--- a/gum/gumdefs.h
+++ b/gum/gumdefs.h
@@ -447,6 +447,8 @@ GUM_API void gum_cpu_context_replace_return_value (GumCpuContext * self,
 GUM_API GType gum_address_get_type (void) G_GNUC_CONST;
 GUM_API GType gum_cpu_type_get_type (void) G_GNUC_CONST;

+GUM_API void gum_log (const gchar * format, ...);
+
 G_END_DECLS

 #endif
diff --git a/gum/guminterceptor.c b/gum/guminterceptor.c
index 00d08790..14f9e171 100644
--- a/gum/guminterceptor.c
+++ b/gum/guminterceptor.c
@@ -15,6 +15,7 @@
 #include "gumprocess.h"
 #include "gumtls.h"

+#include <dlfcn.h>
 #include <string.h>

 #ifdef HAVE_MIPS
@@ -665,6 +666,22 @@ gum_interceptor_instrument (GumInterceptor * self,
   if (ctx == NULL)
     return NULL;

+  {
+    Dl_info info;
+    const gchar * name;
+
+    if (dladdr (function_address, &info) != 0 && info.dli_sname != NULL)
+    {
+      name = info.dli_sname;
+    }
+    else
+    {
+      name = "(unknown)";
+    }
+
+    gum_log ("Hooking %p (%s) => ctx=%p", function_address, name, ctx);
+  }
+
   if (!_gum_interceptor_backend_create_trampoline (self->backend, ctx))
   {
     gum_function_context_finalize (ctx);
@@ -1204,6 +1221,8 @@ _gum_function_context_begin_invocation (GumFunctionContext * function_ctx,
   system_error = gum_thread_get_system_error ();
 #endif

+  gum_log ("[ctx=%p] begin_invocation()", function_ctx);
+
   if (interceptor->selected_thread_id != 0)
   {
     invoke_listeners =
@@ -1322,6 +1341,8 @@ _gum_function_context_end_invocation (GumFunctionContext * function_ctx,
   GPtrArray * listener_entries;
   guint i;

+  gum_log ("[ctx=%p] end_invocation()", function_ctx);
+
 #ifdef G_OS_WIN32
   system_error = gum_thread_get_system_error ();
 #endif
	namespace Frida {
	private static Mutex log_mutex;
	private static Timer log_timer = null;
	private static Gee.HashMap<uint, uint> log_threads = null;
	private const uint[] log_palette = { 36, 35, 33, 32, 31, 34 };
	private static uint log_palette_offset = 0;

	public void log_event (string format, ...) {
	var builder = new StringBuilder ();

	log_mutex.lock ();

	uint time_delta;
	if (log_timer == null) {
	log_timer = new Timer ();
	log_threads = new Gee.HashMap<uint, uint> ();

	time_delta = 0;
	} else {
	time_delta = (uint) (log_timer.elapsed () * 1000.0);
	log_timer.reset ();
	}
	if (time_delta > 0) {
	builder.append_printf ("\n*** +%u ms\n", time_delta);
	}

	var tid = (uint) Gum.Process.get_current_thread_id ();

	var color = log_threads[tid];
	if (color == 0) {
	color = log_palette[log_palette_offset];
	log_palette_offset = (log_palette_offset + 1) % log_palette.length;
	log_threads[tid] = color;
	}
	builder.append_printf ("\033[0;%um", color);

	builder.append_printf ("[thread %04x] ", tid);

	var args = va_list ();
	builder.append_vprintf (format, args);

	builder.append ("\033[0m\n");

	var logfile = FileStream.open ("/data/local/tmp/frida-debug/pid_%u-uid_%u.log".printf (Posix.getpid (), (uint) Posix.getuid ()), "a");
	if (logfile != null) {
	logfile.write (builder.str.data);
	logfile = null;
	}

	log_mutex.unlock ();
	}
	}
	diff --git a/bindings/gumjs/gumquickcore.c b/bindings/gumjs/gumquickcore.c
	index b0b54c3e..6ffa7179 100644
	--- a/bindings/gumjs/gumquickcore.c
	+++ b/bindings/gumjs/gumquickcore.c
	@@ -139,6 +139,10 @@ struct _GumQuickNativeCallback
	ffi_type ** atypes;
	GSList * data;

	+ gboolean destroyed;
	+ gchar * ctor_stack;
	+ gchar * dtor_stack;
	+
	GumQuickCore * core;
	};

	@@ -1131,6 +1135,8 @@ _gum_quick_core_dispose (GumQuickCore * self)
	self->weak_map_delete_method = JS_NULL;

	gum_quick_core_teardown_atoms (self);
	+
	+ self->disposed = TRUE;
	}

	void
	@@ -3437,6 +3443,33 @@ invalid_value:
	}
	}

	+static gchar *
	+gum_quick_capture_js_stack_here (GumQuickCore * core)
	+{
	+ gchar * result;
	+ JSContext * ctx = core->ctx;
	+ JSValue exception_val, stack_val;
	+ const char * stack, * newline;
	+
	+ if (core->disposed)
	+ return g_strdup ("<teardown>");
	+
	+ JS_ThrowInternalError (ctx, "oops");
	+ exception_val = JS_GetException (ctx);
	+
	+ stack_val = JS_GetPropertyStr (ctx, exception_val, "stack");
	+ stack = JS_ToCString (ctx, stack_val);
	+
	+ newline = strchr (stack, '\n');
	+ result = g_strdup ((newline != NULL) ? newline + 1 : stack);
	+
	+ JS_FreeCString (ctx, stack);
	+ JS_FreeValue (ctx, stack_val);
	+ JS_FreeValue (ctx, exception_val);
	+
	+ return result;
	+}
	+
	GUMJS_DEFINE_CONSTRUCTOR (gumjs_native_callback_construct)
	{
	JSValue wrapper = JS_NULL;
	@@ -3518,6 +3551,8 @@ GUMJS_DEFINE_CONSTRUCTOR (gumjs_native_callback_construct)
	JS_DupValue (ctx, func),
	0);

	+ cb->ctor_stack = gum_quick_capture_js_stack_here (core);
	+
	return wrapper;

	alloc_failed:
	@@ -3560,6 +3595,10 @@ GUMJS_DEFINE_FINALIZER (gumjs_native_callback_finalize)
	static void
	gum_quick_native_callback_finalize (GumQuickNativeCallback * callback)
	{
	+ callback->destroyed = TRUE;
	+ callback->dtor_stack = gum_quick_capture_js_stack_here (callback->core);
	+
	+#if 0
	ffi_closure_free (callback->closure);

	while (callback->data != NULL)
	@@ -3571,6 +3610,7 @@ gum_quick_native_callback_finalize (GumQuickNativeCallback * callback)
	g_free (callback->atypes);

	g_slice_free (GumQuickNativeCallback, callback);
	+#endif
	}

	static void
	@@ -3592,6 +3632,15 @@ gum_quick_native_callback_invoke (ffi_cif * cif,
	JSValue * argv;
	JSValue result;

	+ if (self->destroyed)
	+ {
	+ g_critical ("NativeCallback use-after-free detected!\n\nCreated here:\n%s"
	+ "\n\nDestroyed here:\n%s",
	+ self->ctor_stack,
	+ self->dtor_stack);
	+ return;
	+ }
	+
	_gum_quick_scope_enter (&scope, core);

	JS_DupValue (ctx, self->wrapper);
	diff --git a/bindings/gumjs/gumquickcore.h b/bindings/gumjs/gumquickcore.h
	index 43cbd355..136b7c8c 100644
	--- a/bindings/gumjs/gumquickcore.h
	+++ b/bindings/gumjs/gumquickcore.h
	@@ -63,6 +63,7 @@ struct _GumQuickCore
	JSContext * ctx;
	GHashTable * module_data;
	GumQuickScope * current_scope;
	+ gboolean disposed;

	GRecMutex * mutex;
	volatile guint usage_count;
	diff --git a/src/frida.vala b/src/frida.vala
	index eb431593..11002e37 100644
	--- a/src/frida.vala
	+++ b/src/frida.vala
	@@ -2602,8 +2602,11 @@ namespace Frida {

	private async void do_perform_operation () {
	try {
	+ printerr (">>> %s\n", this.get_type ().name ());
	result = yield perform_operation ();
	+ printerr ("<<< %s\n", this.get_type ().name ());
	} catch (GLib.Error e) {
	+ printerr ("<<< %s error=\"%s\"\n", this.get_type ().name (), e.message);
	error = e;
	}
	commit 1251a7f314022f126266127fd174a472ac7b9710
	Author: Ole André Vadla Ravnås <oleavr@gmail.com>
	Date: Tue Aug 20 23:21:49 2019 +0200

	Add temporary logging to investigate Interceptor issue

	diff --git a/gum/backend-arm/guminterceptor-arm.c b/gum/backend-arm/guminterceptor-arm.c
	index 2be32087..cf878acf 100644
	--- a/gum/backend-arm/guminterceptor-arm.c
	+++ b/gum/backend-arm/guminterceptor-arm.c
	@@ -420,6 +420,8 @@ _gum_interceptor_backend_create_trampoline (GumInterceptorBackend * self,
	ctx->overwritten_prologue_len = reloc_bytes;
	memcpy (ctx->overwritten_prologue, function_address, reloc_bytes);

	+ gum_log ("\t[ctx=%p] Generated on_enter=%p on_leave=%p", ctx, ctx->on_enter_trampoline, ctx->on_leave_trampoline);
	+
	return TRUE;
	}

	@@ -459,6 +461,7 @@ _gum_interceptor_backend_activate_trampoline (GumInterceptorBackend * self,
	gum_emit_push_cpu_context_high_part (tw);
	gum_thumb_writer_put_bl_imm (tw,
	GUM_ADDRESS (ctx->trampoline_deflector->trampoline));
	+ gum_log ("\t[ctx=%p] Using shared Thumb deflector at %p", ctx, ctx->trampoline_deflector->trampoline);
	}
	else
	{
	@@ -466,12 +469,14 @@ _gum_interceptor_backend_activate_trampoline (GumInterceptorBackend * self,
	GUM_INTERCEPTOR_THUMB_TINY_REDIRECT_SIZE);
	gum_thumb_writer_put_b_imm (tw,
	GUM_ADDRESS (ctx->trampoline_deflector->trampoline));
	+ gum_log ("\t[ctx=%p] Using dedicated Thumb deflector at %p", ctx, ctx->trampoline_deflector->trampoline);
	}
	}
	else
	{
	gum_thumb_writer_put_ldr_reg_address (tw, ARM_REG_PC,
	GUM_ADDRESS (ctx->on_enter_trampoline));
	+ gum_log ("\t[ctx=%p] Using direct Thumb branch", ctx);
	}

	gum_thumb_writer_flush (tw);
	@@ -490,11 +495,13 @@ _gum_interceptor_backend_activate_trampoline (GumInterceptorBackend * self,
	GUM_INTERCEPTOR_ARM_TINY_REDIRECT_SIZE);
	gum_arm_writer_put_b_imm (aw,
	GUM_ADDRESS (ctx->trampoline_deflector->trampoline));
	+ gum_log ("\t[ctx=%p] Using dedicated ARM deflector at %p", ctx, ctx->trampoline_deflector->trampoline);
	}
	else
	{
	gum_arm_writer_put_ldr_reg_address (aw, ARM_REG_PC,
	GUM_ADDRESS (ctx->on_enter_trampoline));
	+ gum_log ("\t[ctx=%p] Using direct ARM branch", ctx);
	}

	gum_arm_writer_flush (aw);
	@@ -508,6 +515,7 @@ _gum_interceptor_backend_deactivate_trampoline (GumInterceptorBackend * self,
	gpointer prologue)
	{
	memcpy (prologue, ctx->overwritten_prologue, ctx->overwritten_prologue_len);
	+ gum_log ("\t[ctx=%p] Deactivated", ctx);
	}

	gpointer
	diff --git a/gum/gum.c b/gum/gum.c
	index 06539a12..b3eda4f7 100644
	--- a/gum/gum.c
	+++ b/gum/gum.c
	@@ -602,6 +602,44 @@ gum_on_log_message (const gchar * log_domain,
	#endif
	}

	+void
	+gum_log (const gchar * format,
	+ ...)
	+{
	+ static GumInterceptor * interceptor = NULL;
	+ gchar * path, * message;
	+ va_list args;
	+ FILE * file;
	+
	+ if (interceptor == NULL)
	+ {
	+ interceptor = gum_interceptor_obtain ();
	+ }
	+
	+ gum_interceptor_ignore_current_thread (interceptor);
	+
	+ path = g_strdup_printf ("/data/local/tmp/frida-debug/pid_%u-uid_%u.log", getpid (), getuid ());
	+
	+ va_start (args, format);
	+ message = g_strdup_vprintf (format, args);
	+ va_end (args);
	+
	+ file = fopen (path, "a");
	+ if (file != NULL)
	+ {
	+ fputs (message, file);
	+ fputc ('\n', file);
	+
	+ fclose (file);
	+ }
	+
	+ g_free (message);
	+
	+ g_free (path);
	+
	+ gum_interceptor_unignore_current_thread (interceptor);
	+}
	+
	static GumAddress *
	gum_address_copy (const GumAddress * address)
	{
	diff --git a/gum/gumdefs.h b/gum/gumdefs.h
	index 57e19414..a2b7c25f 100644
	--- a/gum/gumdefs.h
	+++ b/gum/gumdefs.h
	@@ -447,6 +447,8 @@ GUM_API void gum_cpu_context_replace_return_value (GumCpuContext * self,
	GUM_API GType gum_address_get_type (void) G_GNUC_CONST;
	GUM_API GType gum_cpu_type_get_type (void) G_GNUC_CONST;

	+GUM_API void gum_log (const gchar * format, ...);
	+
	G_END_DECLS

	#endif
	diff --git a/gum/guminterceptor.c b/gum/guminterceptor.c
	index 00d08790..14f9e171 100644
	--- a/gum/guminterceptor.c
	+++ b/gum/guminterceptor.c
	@@ -15,6 +15,7 @@
	#include "gumprocess.h"
	#include "gumtls.h"

	+#include <dlfcn.h>
	#include <string.h>

	#ifdef HAVE_MIPS
	@@ -665,6 +666,22 @@ gum_interceptor_instrument (GumInterceptor * self,
	if (ctx == NULL)
	return NULL;

	+ {
	+ Dl_info info;
	+ const gchar * name;
	+
	+ if (dladdr (function_address, &info) != 0 && info.dli_sname != NULL)
	+ {
	+ name = info.dli_sname;
	+ }
	+ else
	+ {
	+ name = "(unknown)";
	+ }
	+
	+ gum_log ("Hooking %p (%s) => ctx=%p", function_address, name, ctx);
	+ }
	+
	if (!_gum_interceptor_backend_create_trampoline (self->backend, ctx))
	{
	gum_function_context_finalize (ctx);
	@@ -1204,6 +1221,8 @@ _gum_function_context_begin_invocation (GumFunctionContext * function_ctx,
	system_error = gum_thread_get_system_error ();
	#endif

	+ gum_log ("[ctx=%p] begin_invocation()", function_ctx);
	+
	if (interceptor->selected_thread_id != 0)
	{
	invoke_listeners =
	@@ -1322,6 +1341,8 @@ _gum_function_context_end_invocation (GumFunctionContext * function_ctx,
	GPtrArray * listener_entries;
	guint i;

	+ gum_log ("[ctx=%p] end_invocation()", function_ctx);
	+
	#ifdef G_OS_WIN32
	system_error = gum_thread_get_system_error ();
	#endif