Tracing with disassembly

By default the tracelog contains only specific events, such as API calls. However, we may also use it to print disassembly of each executed instruction.

Using this feature may slow down the tracing, and make the log very noisy - so it is advised to use it with moderation, only within limited ranges.

It can be enabled by modifying TinyTracer.ini, and setting the range by editing DISASM_START and DISASM_STOP. Both offsets are RVA, relative to the main traced module, and need to be given as hexadecimal numbers.

The disasm log will start when the DISASM_START is hit, and follow into all the watched regions (including shellcodes), till the DISASM_STOP is hit. If the DISASM_STOP is 0 (undefined) the disassembly will continue till the end of the execution. If DISASM_START is 0 (undefined) the feature will be disabled.

Example:

TinyTracer.ini (fragment):

...
DISASM_START=10e4
;DISASM_START (hex):
; An RVA in the traced module from which the disasm should start
DISASM_STOP=0
;DISASM_STOP (hex):
; An RVA in the traced module on which the disasm should end

Tracelog (fragment):

24f;section: [.text]
1426;[.text] -> [.plt.sec]
10e0;section: [.plt.sec]
10e4;[0] bnd jmp qword ptr [rip+0x2ebd] # disasm start
10e4;libc.so.puts
142b;section: [.text]
142b;[0] mov rax, 0xed7adb5afee109e7
1435;[0] mov rdx, 0x8016895bec34971e
143f;[0] mov qword ptr [rbp-0x40], rax
1443;[0] mov qword ptr [rbp-0x38], rdx
[...]

The disasm line is defined as:

[RVA];[[ThreadID]] [disasm line]

Dumping the context

Sometimes, in addition to traced instructions, we want to see what were the values of the registers at particular line. It can be added by enabling the option:

DISASM_CTX=True
;DISASM_CTX:
; When in disasm mode: show the registers changed by every instruction

With this option enabled, every logged disassembly line will be prepended with the line displaying the context. At the start of the disasembly, the values of all registers (as well as the value at the top of the stack) will be dumped. Further on, only the registers that got changed are logged.

Example:

20cb;kernel32.SetUnhandledExceptionFilter
14de;ntdll.RtlInstallFunctionTableCallback
15c4;kernel32.SetUnhandledExceptionFilter
				{ [rsp] -> 0x6944400; rdi = 0x694c4c0; rsp = 0x67ffeb0; rbx = 0x6944400; rdx = 0x694445f; rcx = 0x14089b8e8; rax = 0x14089b8e8; r8 = 0x7efefefefefefeff; r9 = 0x8101010101010100; r10 = 0x80fee0fefef8fefc; r11 = 0x14089b8e8; flags = 0x246 [ P=1 Z=1 I=1 ]; }
1649;[0] call qword ptr [rip+0x89a291] # disasm start
1649;called: ?? [19710000+0]
				{ [rsp] -> 0x14000164f; rsp = 0x67ffea8; }
> 19710000+0;[0] hlt
> 19710000+0;ntdll.KiUserExceptionDispatcher
				{ [rsp] -> 0x7ffcf400cf3c; rdi = 0x1400010b0; rsi = 0x19710000; rbp = 0x19710000; rsp = 0x67fefd8; rbx = 0x0; rdx = 0x0; rcx = 0x19710000; rax = 0x1400010b0; r8 = 0x140000000; r9 = 0x1; r10 = 0x0; r11 = 0x11; r12 = 0x7ffcf40fb450; r14 = 0x19710003; r15 = 0x67ff5c8; flags = 0x206 [ Z=0 ]; }
10b0;[0] mov qword ptr [rsp+0x10], rdx
10b5;[0] mov qword ptr [rsp+0x8], rcx
10ba;[0] sub rsp, 0x48
				{ [rsp] -> 0x0; rsp = 0x67fef90; }
10be;[0] mov ecx, 0xc
				{ rcx = 0xc; }
10c3;[0] call 0x140001778
				{ [rsp] -> 0x1400010c8; rsp = 0x67fef88; }
1778;[0] push rbx
				{ [rsp] -> 0x0; rsp = 0x67fef80; }
177a;[0] sub rsp, 0x20
				{ rsp = 0x67fef60; }
177e;[0] mov rbx, rcx
				{ rbx = 0xc; }
1781;[0] jmp 0x140001792
1792;[0] call 0x140007664

In case of any changes in the EFLAGS register, we will see the value of the full register, plus, the particular flags that has recently changed.

For example:

flags = 0x206 [ Z=0 ];

The content of the EFLAGS register is 0x206, and the flag that recently changed is ZF (zero flag), that was unset.