"NOT following direct call from ... to _SEH_prolog4"

[Michael Flanders]

Hi.

I am working on a DynamoRIO client that records an re-playable execution trace. I noticed when instrumenting a 32 bit C program compiled with MSVC (cl.exe) on Windows 10, that the recorded execution trace has a hole after a direct call like the one ending this basic block below:

```

interp: start_pc = 0x7763e424

  0x7763e424  6a 20      push 0x20

  0x7763e426  68 08 c4 6f 77    push 0x776fc408

  0x7763e42b  e8 b4 a0 03 00    call 0x776784e4

        NOT following direct call from 0x7763e42b to 0x776784e4

```

My execution trace here has the address of the call (`0x7763e42b`) and then the address right after it (`0x7763e430`), but nothing in between, so my emulator complains on after falling the call to `0x776784e4` that is has left my execution trace.

Using DynamoRIO's symquery, it looks like this target function address, `0x776784e4`, is in `ntdll.dll` and is `_SEH_prolog4+0x0`.

I couldn't find much documentation on that log message 'NOT following direct call from ...', and I don't know enough of DynamoRIO's internals to understand the context around that `BBPRINT` statement.

Could someone help me understand why this direct call is not being followed? 

I would prefer recording every instruction executed in the trace as faithfully as possible, would it be feasible for me to try to follow and record this call? I think it would probably be acceptable to skip some functions like this if few special functions are not followed.

[Derek Bruening]

"Not following direct call" does not mean that DR does not later follow it: it only means that this basic block won't walk into the call and include the start of the call in the same "basic block" as part of an optimization to elide some branches.

So that message is normal and expected on every call (unless certain runtime options are set).

Every call should be managed by DR.  The only exception is the WOW64 system call gateway where it is much simpler for 32-bit DR to treat that as a system call gateway trap.  But that's an indirect call with a segment prefix so this is not that.

If you use logging https://dynamorio.org/page_logging.html you should be able to see exactly what DR did after that block: what is the subsequent block created?

--
You received this message because you are subscribed to the Google Groups "DynamoRIO Users" group.
To unsubscribe from this group and stop receiving emails from it, send an email to dynamorio-use...@googlegroups.com.
To view this discussion visit https://groups.google.com/d/msgid/dynamorio-users/2fc1a111-9888-4f6c-9020-6bb2e6e757fan%40googlegroups.com.

[Michael Flanders]

With log level 3 on, the text right after this basic block's text is:

```

setting cur_pc (for fall-through) to 0x7763e430
exit_branch_type=0x9 bb->exit_target=0x776784e4
exit_branch_type=0x9 target=0x776784e4 l->flags=0x9809
Fragment 259, tag 0x7763e424, flags 0x1000030, shared, size 437:
[ntdll.dll~LdrLoadDll+0x394,~RtlMultiByteToUnicodeSize-0x86c]
Entry into F259(0x7763e424).0x22026760 (shared)

Exit from sourceless ibl: bb ret []
 (target 0x7763e430 not in cache)
fragment_add_ibl_target tag 0x7763e430, branch 0, F0

d_r_dispatch: target = 0x7763e430

interp: start_pc = 0x7763e430
  0x7763e430  89 55 dc             mov    dword ptr [ebp-0x24], edx
  0x7763e433  8b f9                mov    edi, ecx
  0x7763e435  89 7d d4             mov    dword ptr [ebp-0x2c], edi
  0x7763e438  f6 05 c0 37 71 77 09 test   byte ptr [0x777137c0], 0x09
  0x7763e43f  0f 85 13 b3 04 00    jnz    0x77689758
end_pc = 0x7763e445

```

[Michael Flanders]

I think I see my problem: the code cache basic block for 0x776784e4 is created much earlier in DR's execution of my program, looks like maybe before the entry point of my main exe file, but I have this check before my instrumentation is added to basic blocks:

```

    if (!start_tracing) {
        module_data_t *main_mod = dr_get_main_module();
        DR_ASSERT(main_mod); // TODO, put the main module get somewhere else? in client init?
        if (dr_fragment_app_pc(tag) == (void *)main_mod->entry_point)
        {
            start_tracing = true;
        }
        else
        {
            dr_free_module_data(main_mod);
            return DR_EMIT_DEFAULT;
        }
        dr_free_module_data(main_mod);
    }

```

I would guess that the original, uninstrumented (by me) basic block in the code cache is used when that call instruction goes to `0x7763e424`.

I haven't tried running it again, but I would bet this is the problem.

Thanks Derek!

[Derek Bruening]

It looks like the callee itself was already materialized into the cache earlier.  Did you search the prior logs?  It all looks normal.  There likely was an earlier call from a different call site to the same callee.

Is it possible your tool is mixing up instrumentation time with execution time?  See https://dynamorio.org/API_BT.html#sec_control_points.

To view this discussion visit https://groups.google.com/d/msgid/dynamorio-users/8a41e80c-dd43-41f3-a8e9-e0a27161cc64n%40googlegroups.com.

[Michael Flanders]

> It looks like the callee itself was already materialized into the cache earlier.  Did you search the prior logs?

Yes, looks like this was it. There was an earlier call to the same address earlier that did not receive my instrumentation, so that is why there was a gap in my execution trace. 

Thanks again for the help!