Skip to content

Instantly share code, notes, and snippets.

Embed
What would you like to do?
Frida logging hacks

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'],
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 ();
}
}
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 ();
}
}
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
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment