Frida logging hacks

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 <[email protected]>
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