Tracing does not log the exception-generating instruction if windbg-handled?
MCher
checking triggers an exception, windbg kicks in, I print the faulting
thread's ID, exception and context records, etc, then stop the trace.
To find the crash, I look for the last instance of the executable's
module execution in the trace. The trace at that point looks quite
odd, missing the instruction targeted by a jmp. The address is valid
(middle of msvcrt.dll!memmove) and present elsewhere in the trace.
Instead of the expected memmove address the trace shows the start of
KiUserExceptionDispatcher. Fair enough, memmove takes an exception,
but the jmp therein seems totally valid and should be a part of the
trace. I suppose it is possible that earlier the process has trashed
its text, but hardly to the point of making the jmp invalid. Besides
the exception record shows the exception in memmove that is missing
from the trace.
So, is the trace's omission of the exception-generating instruction
deliberate? After all, the instruction has not got retired. But it
would still be helpful to log it. TEMU does get the first crack at it.
ExceptionAddress: 77c47410 (msvcrt!memmove+0x00000160)
ExceptionCode: c0000005 (Access violation)
ExceptionFlags: 00000000
NumberParameters: 2
Parameter[0]: 00000000
Parameter[1]: 0411d000
Attempt to read from address 0411d000
(07441503)77c472e1: jb 0x0000000077c4730c J@[0x0000002b]
[4](R) T0
(07441504)77c4730c: jmp DWORD PTR [ecx*4+0x77c4738c]
M@0x77c4738c[0x77c473ef][4](R) T0
# Here 0x77c47410 is in memmove and is a valid
destination present elsewhere in the trace.
# From x.functions: 0x77c472b0 msvcrt.dll memmove
0x372b0
(07441505)77c473ef: jmp DWORD PTR [edx*4+0x77c473f8]
M@0x77c473fc[0x77c47410][4](R) T0
# This is 0x7c90e47c ntdll.dll
KiUserExceptionDispatcher 0xe47c
# Expecting this instead (from few instructions earlier
in the trace: (07411907)77c47410: mov al,BYTE PTR [esi]
(07441506)7c90e47c: mov ecx,DWORD PTR [esp+0x4]
M@0x03b3f6c8[0x03b3f6e8][4](R) T1 {15 (4444, 273020) (4444, 273020)
(4444, 273020) (4444, 27302\
0) } R@ecx[0x00000000][4](W) T0
--Mike
Stephen McCamant
MC> My "failing" trace does not end with a crash, rather: internal
MC> error- checking triggers an exception, windbg kicks in, I print
MC> the faulting thread's ID, exception and context records, etc, then
MC> stop the trace. To find the crash, I look for the last instance
MC> of the executable's module execution in the trace. The trace at
MC> that point looks quite odd, missing the instruction targeted by a
MC> jmp. The address is valid (middle of msvcrt.dll!memmove) and
MC> present elsewhere in the trace. Instead of the expected memmove
MC> address the trace shows the start of
MC> KiUserExceptionDispatcher. Fair enough, memmove takes an
MC> exception, but the jmp therein seems totally valid and should be a
MC> part of the trace. I suppose it is possible that earlier the
MC> process has trashed its text, but hardly to the point of making
MC> the jmp invalid. Besides the exception record shows the exception
MC> in memmove that is missing from the trace.
MC> So, is the trace's omission of the exception-generating
MC> instruction deliberate? After all, the instruction has not got
MC> retired. But it would still be helpful to log it. TEMU does get
MC> the first crack at it.
I think your analysis of the situation here is correct. I wouldn't go
so far as to say the omission is deliberate, but there is a design
choice here that leads to the possibility of faulting instructions
being omitted from the trace. We've tried to make this work, but it's
quite possible you've run across a case that isn't currently covered.
The basic approach Tracecap takes is to write the instruction trace
record after the execution of an instruction has completed (using
TEMU's insn_end callback). We generally want to do this so that the
trace record for an instruction can show the state of the machine
after the instruction's execution. But as I think you've hypothesized,
this decision means that if the execution of an instruction is
interrupted, the trace record for that instruction won't naturally
appear in the trace.
Since the instruction that causes an exception is often an interesting
one, Tracecap does attempt to write the instruction, but as part of
its exception (error) detection machinery. If Tracecap recognizes that
the process has caught an exception, part of its special handling is
to write the partially-filled-in trace record.
But this special case occurs only if Tracecap explicitly recognizes
the exception. So if you aren't already using it, giving the command
"detect exception on" to Tracecap may be enough to make Tracecap give
you the extra trace record you're looking for.
Another possibility might be that you're running into a limitation of
the exception detector. I believe it works by hooking the
KiUserExceptionDispatcher routine, which does look like it appears in
your trace, but perhaps some other aspect of how the exception is
handled in your case is causing Tracecap to miss it. For instance you
mention using WinDBG on the process at the same time, which is
certainly not the configuration we most commonly use. If you can
isolate something different about the exception process that causes a
problem for the exception detector it probably wouldn't be hard to
fix.
Hope this helps,
-- Stephen
MCher
the crash, despite the lack of the faulting instruction, by finding
that instruction's dependencies by hand. E.g., given that ESI contains
the bad pointer, I find the last instruction that sets ESI and slice
from there.
--Mike
On Nov 10, 5:10 pm, Stephen McCamant <s...@CS.Berkeley.EDU> wrote:
MCher
but also kills the VM. Had to specify "action stoptracing on", which
then gives me control necessary to save procmon and windbg info. So,
all is well, except it does seem to perturb the trace somehow
(probably the sequence/size of allocations), leading to a similar
(memmove) but slightly different crash.
--Mike