Log in

View Full Version : pinlog

deroko
November 15th, 2012, 07:22
Here is one small, and (I hope) useful tool. What it will do is to use Pin to trace execution flow of an application, and count how many times instructions are executed. This will produce log file, which later can be imported in ida via ida plugin, and highlight code which is executed. Of course, code which is executed more will have darker highlight, and ones which are executed less will have brighter color.

Tool itself is very simple, so I don't even dare to call it project

It supports x32/x64 both Linux, and Windows

Link with source code : http://deroko.phearless.org/pinlog.zip
Aimless
November 15th, 2012, 12:11
No trace happened inside the process, D.

1) Unzipped pinlog.zip file to D:\pinlog\

2) Opened command prompt, and went to D:\pinlog\bin\

3) Copied notepad.exe from C:\Windows\notepad.exe to D:\pinlog\bin\

4) RAN THE FOLLOWING COMMAND INSIDE THE D:\PINLOG\BIN DIR: pinlog.exe d:\pinlog\bin\notepad.exe notepad.exe notepad.log

ERROR: No trace happened inside process.

Running WinXP, SP3, 32-bit. Ran command prompt under normal as well as administrator privileges. Nothing. Same error.

Any ideas what I could be doing wrong?

Have Phun
deroko
November 15th, 2012, 12:22
Do you have pintools in your PATH environment? As it has to be in your path, otherwise it won't start trace at all as Pin tools are required for trace to work.
Aimless
November 15th, 2012, 12:46
Quote:
[Originally Posted by deroko;93688]Do you have pintools in your PATH environment? As it has to be in your path, otherwise it won't start trace at all as Pin tools are required for trace to work.


So, what should I add in the path?

D:\PINLOG\

OR

D:\PINLOG\BIN\

OR

D:\PINLOG\BIN\WIN32\

Have Phun


<<<EDITED AFTER 15 minutes>>>

OK.

Tried all three above.
Tried it in user variables
Tried it in Environment variables

Same error.

What could I be doing wrong?

Have Phun
deroko
November 15th, 2012, 12:52
Ah sorry, this is what you need from Intel (Pin Tool), as trace.dll are only dlls which will use pin tool as framework to count executed instructions:

http://software.intel.com/en-us/articles/pintool-downloads

So you will have to add path to this, and after everything should be good. I've used, and compiled trace.dlls with version for msvc9 (although any of them should be fine). Hope this solves issue
Aimless
November 16th, 2012, 00:49
Ah!

NOW it works The logfile is generated.

Will import it in IDA and keep you updated how it goes.

Have Phun
deroko
November 16th, 2012, 05:03
Great Looking forward to results
Kayaker
November 16th, 2012, 09:12
I seem to be having problems. I copied everything from the msvc9 Intel download to c:\pintools and added that to both the user and system PATH variable, then rebooted.

After getting the error message I traced with Olly to see what was going on. The formatted command line used with CreateProcess is presumably correct, that API returns non-zero.

CommandLine = "pin -smc_strict 1 -follow_execv 1 -t "C:\pintools\pinlog\bin\pin32\trace.dll" -p notepad.exe -- "c:\pintools\pinlog\bin\notepad.exe""

Where it seems to fail is on the following MapViewOfFile. A pointer is returned to the mapped view (0x1010000), and also registers in the Olly Memory Map window, but there's nothing in the mapping.

Since there's nothing in the mapping, the following "No trace happened inside process" error is inevitable.

Have I somehow not set the PATH variable correctly? I tried a few variations, currently:
c:\pintools\;c:\pintools\ia32\bin\

I do have Comodo running, and it indicated that pin.exe was executing notepad.exe, so pin.exe must at least have gotten the message. I haven't tried it without Comodo yet.
deroko
November 16th, 2012, 09:35
Hmm Comodo, might be that trace.dll cann't open shared memory needed to log information if comodo is blocking that. I don't have comodo, so I cann't retest, but if you have clean vmware image you can try there maybe? It should work, as I've tried on several x32/x64 systems

Path in your case is c:\pintools so it's correct
Indy
November 16th, 2012, 10:13
No trace happened inside process".
deroko
November 16th, 2012, 10:21
@Indy: you installed pin tool from intel, and is path to pin in your PATH env?
Indy
November 16th, 2012, 10:37
deroko
Yes. Env("Path" = "c:\pintools; c:\pintools\pin32".

2680
deroko
November 16th, 2012, 10:38
You have pin.log, so there was some error What's inside?
Aimless
November 16th, 2012, 11:14
Hello All,

I'm going to outline here what I've done to get it to working perfectly (that means, not only generating a log, but also in IDA):

1. I downloaded PINLOG from dekero's site.

2. Unzipped it to: D:\pinlog

3. Downloaded PINTOOLS compiled with vs9.

4. Unzipped it to: D:\pin (Yes, I changed the unzipped directory name from pin-2.12-53271-msvc9-ia32_intel64-windows to a simple pin)

5. Right-clicked My Computer, Went to Advanced Tab, Pressed the Environment Variables Button and in the SYSTEM Tab, EDITED the path to point it to: C:\WINXP;d:\pin; (many more directories in the path, but you get the idea.)

6. Pressed OK. No need to reboot.

7. Opened a command prompt (no need to open a privileged one). Running CMD from RUN will do.

8. cd D:\PINLOG\BIN

9. COPY C:\windows\notepad.exe . (this copies the notepad.exe to the current d:\pinlog\bin directory)

10. Run the command: pinlog.exe d:\pinlog\bin\notepad.exe notepad.exe notepad.log (important here is to note the second parameter is the FULL pathname and executable name.)

11. Do your stuff.

12. Notepad -> File -> Exit

13. Open IDA. Open Notepad.exe and wait till it's finished.

14. Select File->Scripts and select loadlog.py

15. Select notepad.log as selected in the box.

16. And...it's on!

Have Phun
deroko
November 16th, 2012, 11:34
Great writeup, hope everybody will get it working now

@Kayaker: I've just tried with Comodo Internet Security in vmware, and it works ok, so Comodo is not an issue
Indy
November 16th, 2012, 12:36
deroko
Quote:
Pin 2.11 kit 49303
E: Pintool version does not match pin
Pin: @CHARM-VERSION: $Id: version.cpp 49303 2012-04-03 18:22:23Z nshalev $
Tool: @CHARM-VERSION: $Id: version.cpp 53241 2012-08-06 11:18:41Z tevi $
deroko
November 16th, 2012, 12:40
Ah, you need latest pin tool : http://software.intel.com/sites/landingpage/pintool/downloads/pin-2.12-53271-msvc9-ia32_intel64-windows.zip

This should solve your problem.
Indy
November 16th, 2012, 13:07
ok. how to see the log ?

http://s001.radikal.ru/i196/1211/93/fcd2f1156532.png (http://www.radikal.ru)

This tool is better than the usual trace ?

In my not
deroko
November 16th, 2012, 14:11
Ah, you need IDA with python support so you can use loadlog.py to load log into IDA. This is the plugin you need for it : http://code.google.com/p/idapython/

By default it comes with IDA, I even think that demo IDA 6.3 comes with it, or at least leaked version from ESET should have it (if I recall correctly it should be 6.1)
Kayaker
November 16th, 2012, 23:49
Strange, I can't get it working under XP or Win7 VM either. The PATH variable is correct, else pin.exe would never run.

Process Monitor indicates everything is going well until notepad tries to load trace.dll, then the process exits without starting up. The following output shows some relevant loading steps, the first column is the log index, so the sequential numbers show how LoadImage/trace.dll is immediately followed by a ThreadExit.

Code:


 10983    pin.exe    2528    Process Create    c:\pinlog\bin\notepad.exe    SUCCESS    PID: 136, Command line: "c:\pinlog\bin\notepad.exe"

 10984    notepad.exe    136    Process Start        SUCCESS    Parent PID: 2528

 10985    notepad.exe    136    Thread Create        SUCCESS    Thread ID: 1912



 11080    notepad.exe    136    Load Image    C:\pinlog\bin\NOTEPAD.EXE    SUCCESS    Image Base: 0x1000000, Image Size: 0x14000

 11082    notepad.exe    136    Load Image    C:\WINDOWS\system32\ntdll.dll    SUCCESS    Image Base: 0x7c900000, Image Size: 0xb2000

 11262    notepad.exe    136    Load Image    C:\WINDOWS\system32\kernel32.dll    SUCCESS    Image Base: 0x7c800000, Image Size: 0xf6000



 11305    pin.exe    2528    Load Image    C:\pintools\ia32\bin\pinvm.dll    SUCCESS    Image Base: 0x54000000, Image Size: 0x4a8000

 11332    notepad.exe    136    Load Image    C:\pintools\ia32\bin\pinvm.dll    SUCCESS    Image Base: 0x54000000, Image Size: 0x4a8000



 11358    notepad.exe    136    Load Image    C:\pinlog\bin\pin32\trace.dll    SUCCESS    Image Base: 0x55000000, Image Size: 0x1e7000

 11359    notepad.exe    136    Thread Exit        SUCCESS    User Time: 0.0156250, Kernel Time: 0.0156250

 11360    notepad.exe    136    Process Exit    SUCCESS    Exit Status: -1, User Time: 0.0312500, Kernel Time: 0.0156250


I'll have to try to debug trace.dll loading to see if it gets as far as PIN_StartProgram().

And also test pintools independantly of pinlog to see if there's some configuration step I need for my system. Deroko, do you have a recommendation how I should do that? Build one of the pin example tools and test that?
Aimless
November 17th, 2012, 00:23
Hello K.

You're not supposed to run pin.exe AT ALL. You're not even supposed to TOUCH anything from the intel pintools directory, except to unzip and put its path in the system variable.

To generate a log, You'll need to run pinlog.exe from dereko's zipped files.

Ignore this if that's what you are doing.

Have Phun
Kayaker
November 17th, 2012, 01:13
Hi A.

Yeah, "pinlog c:\pinlog\bin\notepad.exe notepad.exe notepad.log" is the only command I execute. Pintools is untouched in its own PATH defined directory.
In turn pin.exe starts up, which executes notepad which begins loading its system dlls as normal. Then trace.dll gets loaded as indicated by the Process Monitor log, but notepad immediately exits, followed soon after by pin.exe then pinlog.exe, with no logfile created.

Unless I've really fouled up something, several times, I can't understand why notepad just doesn't continue to load and display. That's why I wanted to test pintools by itself to see if there's some config or system setting required, unique to my system for some unknown reason.
deroko
November 17th, 2012, 05:15
If there is pin.log generated by pintool, can you post it's content, so I can see what went wrong? Becuase from your loading trace, seems that process exits, so it might be older version of pintool, or some other error, but I can see this only from pin.log, which should be located in same directory from where you started pinlog.exe.

@Kayaker, you can also run trace.dll as standalone as, pinlog.exe just allocated 50mb shared memory with low integrity so even sandboxed processes with low integrity can write to it:
pin -follow_execv 1 -t <path_to_trace.dll> -- notepad.exe
Kayaker
November 18th, 2012, 01:16
Quote:
[Originally Posted by deroko;93690]I've used, and compiled trace.dlls with version for msvc9 (although any of them should be fine).


Apparently not. Unfortunately pintools only seems to generate a pin.log error log when the Revision number is different from the compiled Tool (like the error Indy got), but not when the compiler version used is different (which is what my problem was).

To explain, I had originally downloaded the Rev. 53271 vc10 version of pintools, since I have vc10 and was envisioning recompiling the examples etc.

Pinlog didn't work, but no error log was produced. I then used the Rev. 53271 vc9 version, which is what pinlog was compiled with, and finally got it working (yay!). I *thought* I had done that originally before I mentioned the problem, but must have screwed that up.

I tried another malware analysis Tool example I found that had been compiled with Rev. 33543 vc8 version of pintools, and this one did give me a pinlog.log error log explaining the problem (mismatching Pin and Tool CHARM-VERSION).

So unfortunately it seems you need the exact Revision *and* compiler version of pintools to run someone elses Tool. If the Revision number is incorrect, you will get an error log. If the compiler version is incorrect, you won't get an error log, which makes it even more confusing.

Maybe someone else can confirm all this, but that's what my evidence points to. Just means you have to recompile a tool from source, but does make it a bit annoying when you want to share your tool with others.


I did do some reversing on the problem before I came to a solution. I used Softice BPLOAD to break on trace.dll being loaded, followed that back to pintools pinvm.dll which calls the Tool (trace.dll) main() function. It quietly crashed in PIN_Init(argc, argv). A loop was being called, trying to match a string. When it wasn't found it seemed to record an unlogged "could not find match for attribute" error and simply exited. Further details are probably moot at this point.


In any case, thanks for the tool Deroko and the introduction to Pintools. I used it on a upx packed file and it definitely highlights the most used loops. I wonder how many color ranges vs execution counts could be defined before the display got nauseating to look at?

Regards,
Kayaker
deroko
November 18th, 2012, 05:31
Glad it worked so after all tool and version used to compile have to match. Luckily I've provided sources, and makefile for sources

Regarding colors, it's tough question. In my experiments everything more than 13 colors makes your eyes go crazy That why I use stepping of 10 execs to advance to next color. What I did, is to use this python script to find colors which would show the best count of executed instructions, and still not kill your eyes when having some code executed too many times:

Code:


import colorsys

import idaapi

import idc



some_random_func = 0x00402A17;



#clear colors, so I can rerun code...

function = idaapi.func_item_iterator_t();

function.set(idaapi.get_func(some_random_func));



b_ok = function.first();

function.next_code();

function.next_code();

for x in range(0, 25):

        ea = function.current();

        idc.SetColor(ea, CIC_ITEM, 0xFFFFFFFF);

        function.next_code();



r = 0x00/255.0;

g = 0x00/255.0;

b = 0xff/255.0;

dec = 0.0;



#do colors again...

function = idaapi.func_item_iterator_t();

function.set(idaapi.get_func(some_random_func));



b_ok = function.first();

function.next_code();

function.next_code();



(h,s,v) = colorsys.rgb_to_hsv(r,g,b);

s -= 0.35;

(r,g,b) = colorsys.hsv_to_rgb(h,s,v);



for x in range(0, 15):

        (h,s,v) = colorsys.rgb_to_hsv(r,g,b);

        s -= dec;

	(r,g,b) = colorsys.hsv_to_rgb(h,s,v);

	

	ida_color = (int(b*255) << 16) + (int(g*255) << 8) + int(r*255);

        ea = function.current(); 

        idc.SetColor(ea, CIC_ITEM, ida_color);

        dec = 0.04;

        function.next_code();


At the end what could have been done is to keep blue for all instructions in, lets say 0-100 execs, green 100-200, and above 200 as red, which is easy to implement, and would give even better overview of how many times instructions are executed
Indy
November 18th, 2012, 06:16
What does this subj when it detects the sysgate(sysenter/syscall/int 2e) ?
deroko
November 18th, 2012, 14:07
Well syscalls, it's up to pin to handle it, and it handles it properly
trietptm
November 19th, 2012, 08:34
In case someone needs, pinlog doesn't support the redirection operator > such as: pinlog.exe c:\victim\victim.exe victim.exe > log.log
You should use: pinlog.exe c:\victim\victim.exe victim.exe > log.log
like the example in readme.txt .