Return value printing

[mxmssh]

We have to add return value printing for each API call printed.

[jtesta]

@mxmssh What is the blocking issue with adding return value printing, if any? If DynamoRIO supports most of the pieces we need to put this together, then if you pointed me in the right direction for how to get started, I may be able to give it a shot!

[mxmssh]

@jtesta I am trying to remember what was an issue. Basically, there are no technical limitations to implement that. It shouldn't be as simple as

1. Add post handler here

   drltrace/drltrace_src/drltrace.cpp

   Line 317 in 6b1d4dd

   drwrap_wrap_ex(func, lib_entry, NULL, (void *) sym->name, 0);

2. Use drwrap_get_retval() to get and print return value after the function exits.

However, when we trace API calls, there is one problem. Let's say our program calls CreateFileA and we want to trace all low API names from kernel32.dll/kernelbase.dll/ntdll.dll called by CreateFileA. In this case, we will print

1. CreateFileA + args,
2. Then all APIs called by CreateFileA
3. return value of CreateFileA
   So, we need somehow to handle this situation and notify a user that function has exited and we print its return values. For example:

kernel32dll!CreateFileA
args
    kernelbasedll!APICallA
    args
         ntdll!APICallB
         args
         returnvalue of APICallB is X
    return value of APICallA is Y
return value of CreateFileA is Z

Intentations are not required, I just listed them to make it simpler to read.

[jtesta]

Right. I was thinking the only real solution is to cache the function calls until the return value is received, then print it all out at once. Any other approach would be impossible for a human to follow, and would also cause the log file to grow even larger than it already is.

Thanks for the pointer! I'll see about experimenting with it in the next few days.

[mxmssh]

Good luck, feel free to ask me if you have any questions regarding DynamoRIO or drltrace.

[jtesta]

So I gave it a shot, and got it working well under Linux. Then I tried it on Windows and it consistently crashed. It turns out that calling dr_get_thread_id() or drwrap_get_retval() during certain post-function callbacks causes it.

Here's a small patch to drltrace.cpp which reproduces the issue:

diff --git a/drltrace_src/drltrace.cpp b/drltrace_src/drltrace.cpp
index d8959c0..64aa9d2 100644
--- a/drltrace_src/drltrace.cpp
+++ b/drltrace_src/drltrace.cpp
@@ -377,6 +377,19 @@ lib_entry(void *wrapcxt, INOUT void **user_data)
 }
 
 static void
+lib_exit(void *wrapcxt, void *user_data)
+{
+  const char *function_name = (const char *)user_data;
+  void *drcontext = drwrap_get_drcontext(wrapcxt);
+
+  DR_TRY_EXCEPT(drcontext, {
+    dr_fprintf(outf, "Return value for %s (thread ID %u): %p\n", function_name, dr_get_thread_id(drcontext), drwrap_get_retval(wrapcxt));
+  }, {
+    dr_fprintf(outf, "Exception thrown when processing thread ID/return value for function %s\n", function_name);
+  });
+}
+
+static void
 iterate_exports(const module_data_t *info, bool add)
 {
     dr_symbol_export_iterator_t *exp_iter =
@@ -405,13 +418,13 @@ iterate_exports(const module_data_t *info, bool add)
         if (func != NULL) {
             if (add) {
                 IF_DEBUG(bool ok =)
-                    drwrap_wrap_ex(func, lib_entry, NULL, (void *) sym->name, 0);
+                    drwrap_wrap_ex(func, lib_entry, lib_exit, (void *) sym->name, 0);
                 ASSERT(ok, "wrap request failed");
                 VNOTIFY(2, "wrapping export %s!%s @" PFX NL,
                        dr_module_preferred_name(info), sym->name, func);
             } else {
                 IF_DEBUG(bool ok =)
-                    drwrap_unwrap(func, lib_entry, NULL);
+                    drwrap_unwrap(func, lib_entry, lib_exit);
                 ASSERT(ok, "unwrap request failed");
             }
         }

Here's a screen shot of the crash when run as drltrace.exe -logdir . -- calc.exe:

(Note that the screen shot shows references to Cygwin, but I didn't use that to compile; I only used it for git operations. I compiled it with VS 2013, just as the instructions say.)

I found that a partial work-around is skipping the callbacks for ZwCallbackReturn, KiUserCallbackDispatcher, and ExpInterlockedPopEntrySListResume. The program will run for longer in that case, but still ultimately crashes.

If we can get this bug fixed, then we'll have return value printing for both Linux & Windows, which would be a huge improvement!

P.S. If you want to see what I have so far (which would be ready for merging if not for this Windows bug), see here: https://github.com/jtesta/drltrace/tree/retval

[mxmssh]

It seems like an issue with DynamoRIO itself. Since they have shifted the focus from Windows to Linux&MacOS + AMD64, Windows platform is low priority now, so I am not sure they will fix it... Anyway, it makes sense to open an issue in DynamoRIO official repo. In the meantime, I will try to debug it and see what we can do. Do you work with the latest DynamoRIO?

[jtesta]

Yes, I did also try it with the master branch of DynamoRIO from a couple days ago. Same results. I'll open an issue on their repo.

Here's a quick question: are calls to the pre- and post-function callbacks thread-safe? If not, I'll need to add some locking functionality.

[mxmssh]

It should be thread-safe (I bet DynamoRIO knows how to handle it)

[mxmssh]

Spent some time debugging it today. We have NULL pointer dereference. Take a look into my comment for DynamoRIO/dynamorio#4068