radareorg / radare2-r2pipe

Access radare2 via pipe from any programming language!
389 stars 99 forks source link

Python: Truncated output from r2.cmd #54

Open Wenzel opened 6 years ago

Wenzel commented 6 years ago

Hi,

I am testing r2pipe in Python and i have a case where the url that open generates a lot of output. The rest of my script attempt to run pd 10 and get the result:

r2 = r2pipe.open(url, ['-d'])
output = r2.cmd("pd 10")
logging.info(output)
r2.cmd('q!')

When logging prints the content of output, the output appears to have been truncated:

libvirt: QEMU Driver error : Domain not found: no domain with matching name 'xenwin7'
--failed to find kvm domain
LibVMI Version 0.11.0
LibVMI Driver Mode 0
--completed driver init.
--got id from name (xenwin7 --> 2)
**set image_type = xenwin7
**set allocated_ram_size = 7d04a000, max_physical_address = 0xff000000
libvirt: QEMU Driver error : Domain not found: no domain with matching name 'xenwin7'
= attach 1452 1452
= attach 1452 0
INFO:root:_reg_profile
__open
VM: xenwin7, PID: 1452
Initializing LibVMI
--failed to find kvm domain
LibVMI Version 0.11.0
LibVMI Driver Mode 0
--completed driver init.
--got id from name (xenwin7 --> 2)
**set image_type = xenwin7
**set allocated_ram_size = 7d04a000, max_physical_address = 0xff000000
**set pae = 1
**set pse = 1
**set lme = 1
**IA-32e paging
**sanity checking cr3 = 0x0000000000187000
--looking for config file at /home/tarrma/fsecure/radare2-extras/vmi/libvmi.conf
--looking for config file at /home/tarrma/etc/libvmi.conf
--looking for config file at /home/tarrma/etc/libvmi.conf
--looking for config file at /etc/libvmi.conf
**Using config file at /etc/libvmi.conf
**set os_type to Windows.
LibVMI Suggestion: set win_ntoskrnl=0x281b000 in libvmi.conf for faster startup.
LibVMI Suggestion: set win_kdbg=0x1e9070 in libvmi.conf for faster startup.
LibVMI Suggestion: set win_kdvb=0xfffff80002a04070 in libvmi.conf for faster startup.
__reg_profile
__getpid
__getpid
__select
__system command: pid 1452
__kill, sig: 0
__reg_read, type: 0, size:7168
__reg_profile
__getpid
__getpid
__select
__system command: pid 1452
__kill, sig: 0
__reg_read, type: 0, size:7168
Attaching to pid 1452...
Listening on VMI events...
Listening on VMI events...
cb_on_cr3_load
Intercepted PID: 860, CR3: 0x14cd1000
Listening on VMI events...
cb_on_cr3_load
Intercepted PID: 4, CR3: 0x187000
Listening on VMI events...
cb_on_cr3_load
Intercepted PID: 380, CR3: 0x20c66000
Listening on VMI events...
cb_on_cr3_load
Intercepted PID: 1476, CR3: 0x68eb9000
Listening on VMI events...
cb_on_cr3_load
Intercepted PID: 4, CR3: 0x187000
Listening on VMI events...
cb_on_cr3_load
Intercepted PID: 380, CR3: 0x20c66000
Listening on VMI events...
cb_on_cr3_load
Intercepted PID: 4, CR3: 0x187000
Listening on VMI events...
cb_on_cr3_load
Intercepted PID: 380, CR3: 0x20c66000
Listening on VMI events...
cb_on_cr3_load
Intercepted PID: 4, CR3: 0x187000
Listening on VMI events...
cb_on_cr3_load
Intercepted PID: 380, CR3: 0x20c66000
Listening on VMI events...
cb_on_cr3_load
Intercepted PID: 1476, CR3: 0x68eb9000
Listening on VMI events...
cb_on_cr3_load
Intercepted PID: 4, CR3: 0x187000
Listening on VMI events...
cb_on_cr3_load
Intercepted PID: 380, CR3: 0x20c66000
Listening on VMI events...
cb_on_cr3_load
Intercepted PID: 4, CR3: 0x187000
Listening on VMI events...
cb_on_cr3_load
Intercepted PID: 380, CR3: 0x20c66000
Listening on VMI events...
cb_on_cr3_load
Intercepted PID: 4, CR3: 0x187000
Listening on VMI events...
cb_on_cr3_load
Intercepted PID: 380, CR3: 0x20c66000
Listening on VMI events...
cb_on_cr3_load
Intercepted PID: 4, CR3: 0x187000
Listening on VMI events...
cb_on_cr3_load
Intercepted PID: 1476, CR3: 0x68eb9000
Listening on VMI events...
cb_on_cr3_load
Intercepted PID: 4, CR3: 0x187000
Listening on VMI events...
cb_on_cr3_load
Intercepted PID: 380, CR3: 0x20c66000
Listening on VMI events...
cb_on_cr3_load
Intercepted PID: 4, CR3: 0x187000
Listening on VMI events...
cb_on_cr3_load
Intercepted PID: 1724, CR3: 0x505f9000
Listening on VMI events...
cb_on_cr3_load
Intercepted PID: 4, CR3: 0x187000
Listening on VMI events...
cb_on_cr3_load
Intercepted PID: 572, CR3: 0xeaaf000
Listening on VMI events...
cb_on_cr3_load
Intercepted PID: 572, CR3: 0xeaaf000
Listening on VMI events...
cb_on_cr3_load
Intercepted PID: 4, CR3: 0x187000
Listening on VMI events...
cb_on_cr3_load
Intercepted PID: 1156, CR3: 0x187ff000
Listening on VMI events...
cb_on_cr3_load
Intercepted PID: 4, CR3: 0x187000
Listening on VMI events...
cb_on_cr3_load
Intercepted PID: 1476, CR3: 0x68eb9000
Listening on VMI events...
cb_on_cr3_load
Intercepted PID: 4, CR3: 0x187000
Listening on VMI events...
cb_on_cr3_load
Intercepted PID: 808, CR3: 0x15088000
Listening on VMI events...
cb_on_cr3_load
Intercepted PID: 808, CR3: 0x15088000
Listening on VMI events...
cb_on_cr3_load
Intercepted PID: 4, CR3: 0x187000
Listening on VMI events...
cb_on_cr3_load
Intercepted PID: 472, CR3: 0x20066000
Listening on VMI events...
cb_on_cr3_load
Intercepted PID: 4, CR3: 0x187000
Listening on VMI events...
cb_on_cr3_load
Intercep

As you can see the last line is Intercep, and this whole output is the one from the open method. So there is a limit somewhere in the buffer returned by r2.cmd, which prevents me from receiving the complete output of my commands.

Info

r2 -v
radare2 2.5.0-git 17625 @ linux-x86-64 git.2.4.0-103-g1b30ca2
commit: 1b30ca283c9f8a2b04add7020f7e1165ee857f8f build: 2018-03-14__13:38:18

pip3 info r2pipe
Name: r2pipe
Version: 0.9.8
Summary: Pipe interface for radare2
Home-page: http://rada.re
Author: pancake
Author-email: pancake@nopcode.org
License: MIT
Location: /usr/local/lib/python3.5/dist-packages
Requires: 

Thanks !

radare commented 6 years ago

can you len(output) to see if thats a magic value like 4096 or so?

radare commented 6 years ago

are you printing any \x00 nullbyte?

Wenzel commented 6 years ago

@radare interesting, the output is always almost a magic size:

either this:

INFO:root:output len: 4095

or this value:

INFO:root:output len: 8191

=)

Wenzel commented 6 years ago

@radare no, i'm not printing any buffer, just strings. this works fine with r2.

Wenzel commented 6 years ago

For example, if i try to intercept the kernel process (the one which is the most frequently scheduled), the script is working and i have pd 10 output:

len(output) here is 3457

libvirt: QEMU Driver error : Domain not found: no domain with matching name 'xenwin7'
--failed to find kvm domain
LibVMI Version 0.11.0
LibVMI Driver Mode 0
--completed driver init.
--got id from name (xenwin7 --> 2)
**set image_type = xenwin7
**set allocated_ram_size = 7d04a000, max_physical_address = 0xff000000
libvirt: QEMU Driver error : Domain not found: no domain with matching name 'xenwin7'
= attach 4 4
= attach 4 0
read 0xfffffffffffffe88: vmi_failure
read 0x28: vmi_failure
read (nil): vmi_failure
read (nil): vmi_failure
read 0x4: vmi_failure
read 0x165: vmi_failure
INFO:root:output len: 3457
INFO:root:__reg_profile
__open
VM: xenwin7, PID: 4
Initializing LibVMI
--failed to find kvm domain
LibVMI Version 0.11.0
LibVMI Driver Mode 0
--completed driver init.
--got id from name (xenwin7 --> 2)
**set image_type = xenwin7
**set allocated_ram_size = 7d04a000, max_physical_address = 0xff000000
**set pae = 1
**set pse = 1
**set lme = 1
**IA-32e paging
**sanity checking cr3 = 0x0000000000187000
--looking for config file at /home/tarrma/fsecure/radare2-extras/vmi/libvmi.conf
--looking for config file at /home/tarrma/etc/libvmi.conf
--looking for config file at /home/tarrma/etc/libvmi.conf
--looking for config file at /etc/libvmi.conf
**Using config file at /etc/libvmi.conf
**set os_type to Windows.
LibVMI Suggestion: set win_ntoskrnl=0x281b000 in libvmi.conf for faster startup.
LibVMI Suggestion: set win_kdbg=0x1e9070 in libvmi.conf for faster startup.
LibVMI Suggestion: set win_kdvb=0xfffff80002a04070 in libvmi.conf for faster startup.
__reg_profile
__getpid
__getpid
__select
__system command: pid 4
__kill, sig: 0
__reg_read, type: 0, size:7168
__reg_profile
__getpid
__getpid
__select
__system command: pid 4
__kill, sig: 0
__reg_read, type: 0, size:7168
Attaching to pid 4...
Listening on VMI events...
Listening on VMI events...
cb_on_cr3_load
Intercepted PID: 380, CR3: 0x20c66000
Listening on VMI events...
cb_on_cr3_load
Intercepted PID: 1476, CR3: 0x68eb9000
Listening on VMI events...
cb_on_cr3_load
Intercepted PID: 4, CR3: 0x187000
__select
__system command: pid 4
__kill, sig: 0
__reg_read, type: 0, size:7168
__select
__system command: pid 4
__kill, sig: 0
__reg_read, type: 0, size:7168
__system command: pid 4
__kill, sig: 0
__reg_read, type: 0, size:7168
__kill, sig: 0
__reg_read, type: 0, size:7168
__reg_read, type: 1, size:7168
__reg_read, type: 2, size:7168
__reg_read, type: 3, size:7168
__reg_read, type: 4, size:7168
__reg_read, type: 5, size:7168
__reg_read, type: 6, size:7168
__read, offset: fffff800028931a9
__read, offset: fffff800028931a9
__kill, sig: 0
__reg_read, type: 0, size:7168
            ;-- rip:
            0xfffff800028931a9      4c8bbb88feff.  mov r15, qword [rbx - 0x178]
            0xfffff800028931b0      488b6e28       mov rbp, qword [rsi + 0x28]
            0xfffff800028931b4      49896f04       mov qword [r15 + 4], rbp
            0xfffff800028931b8      48896b28       mov qword [rbx + 0x28], rbp
            0xfffff800028931bc      f7057e741800.  test dword [0xfffff80002a1a644], 4
        ,=< 0xfffff800028931c6      0f850b010000   jne 0xfffff800028932d7
        |   0xfffff800028931cc      c6474900       mov byte [rdi + 0x49], 0
        |   0xfffff800028931d0      0fbe86650100.  movsx eax, byte [rsi + 0x165]
        |   0xfffff800028931d7      84c0           test al, al
       ,==< 0xfffff800028931d9      0f8489000000   je 0xfffff80002893268
radare commented 6 years ago

Enotime right now but you may want to check the code of r2pipe with that simple test and try to fix the read loop and send a pr if you can. Otherwise i will try to find time but thats not easy for me

On 14 Mar 2018, at 13:12, Mathieu Tarral notifications@github.com wrote:

For example, if i try to intercept the kernel process (the one which is the most frequently scheduled), the script is working and i have pd 10 output:

len(output) here is 3457

libvirt: QEMU Driver error : Domain not found: no domain with matching name 'xenwin7' --failed to find kvm domain LibVMI Version 0.11.0 LibVMI Driver Mode 0 --completed driver init. --got id from name (xenwin7 --> 2) set image_type = xenwin7 set allocated_ram_size = 7d04a000, max_physical_address = 0xff000000 libvirt: QEMU Driver error : Domain not found: no domain with matching name 'xenwin7' = attach 4 4 = attach 4 0 read 0xfffffffffffffe88: vmi_failure read 0x28: vmi_failure read (nil): vmi_failure read (nil): vmi_failure read 0x4: vmi_failure read 0x165: vmi_failure INFO:root:output len: 3457 INFO:root:reg_profile __open VM: xenwin7, PID: 4 Initializing LibVMI --failed to find kvm domain LibVMI Version 0.11.0 LibVMI Driver Mode 0 --completed driver init. --got id from name (xenwin7 --> 2) set image_type = xenwin7 set allocated_ram_size = 7d04a000, max_physical_address = 0xff000000 set pae = 1 set pse = 1 set lme = 1 IA-32e paging sanity checking cr3 = 0x0000000000187000 --looking for config file at /home/tarrma/fsecure/radare2-extras/vmi/libvmi.conf --looking for config file at /home/tarrma/etc/libvmi.conf --looking for config file at /home/tarrma/etc/libvmi.conf --looking for config file at /etc/libvmi.conf Using config file at /etc/libvmi.conf **set os_type to Windows. LibVMI Suggestion: set win_ntoskrnl=0x281b000 in libvmi.conf for faster startup. LibVMI Suggestion: set win_kdbg=0x1e9070 in libvmi.conf for faster startup. LibVMI Suggestion: set win_kdvb=0xfffff80002a04070 in libvmi.conf for faster startup. reg_profile getpid getpid select system command: pid 4 kill, sig: 0 reg_read, type: 0, size:7168 reg_profile getpid getpid select system command: pid 4 kill, sig: 0 reg_read, type: 0, size:7168 Attaching to pid 4... Listening on VMI events... Listening on VMI events... cb_on_cr3_load Intercepted PID: 380, CR3: 0x20c66000 Listening on VMI events... cb_on_cr3_load Intercepted PID: 1476, CR3: 0x68eb9000 Listening on VMI events... cb_on_cr3_load Intercepted PID: 4, CR3: 0x187000 select system command: pid 4 kill, sig: 0 reg_read, type: 0, size:7168 select system command: pid 4 kill, sig: 0 reg_read, type: 0, size:7168 system command: pid 4 kill, sig: 0 __reg_read, type: 0, size:7168 kill, sig: 0 reg_read, type: 0, size:7168 __reg_read, type: 1, size:7168 reg_read, type: 2, size:7168 reg_read, type: 3, size:7168 __reg_read, type: 4, size:7168 reg_read, type: 5, size:7168 __reg_read, type: 6, size:7168 read, offset: fffff800028931a9 read, offset: fffff800028931a9 kill, sig: 0 reg_read, type: 0, size:7168 ;-- rip: 0xfffff800028931a9 4c8bbb88feff. mov r15, qword [rbx - 0x178] 0xfffff800028931b0 488b6e28 mov rbp, qword [rsi + 0x28] 0xfffff800028931b4 49896f04 mov qword [r15 + 4], rbp 0xfffff800028931b8 48896b28 mov qword [rbx + 0x28], rbp 0xfffff800028931bc f7057e741800. test dword [0xfffff80002a1a644], 4 ,=< 0xfffff800028931c6 0f850b010000 jne 0xfffff800028932d7 | 0xfffff800028931cc c6474900 mov byte [rdi + 0x49], 0 | 0xfffff800028931d0 0fbe86650100. movsx eax, byte [rsi + 0x165] | 0xfffff800028931d7 84c0 test al, al ,==< 0xfffff800028931d9 0f8489000000 je 0xfffff80002893268 — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub, or mute the thread.

quim0 commented 6 years ago

Here:

r2 = r2pipe.open(url, ['-d'])

What url are you using? Can't reproduce using process.

Wenzel commented 6 years ago

@quim0 i'm developing a debugger plugin based on virtual machine introspection: Here: https://github.com/Wenzel/radare2-extras/blob/python/vmi/r2vmi.py#L47

Ask me if you want to test a script or a behavior :)

quim0 commented 6 years ago

Are you sure you're not printing any nullbytes? Because I still can't reproduce. I've not used your plugin with qemu yet, but I'm able to print >15K characters with it without any problem, so idk if this is related to r2pipe.

>> import r2pipe
>> r = r2pipe.open('vmi://foo:1234')
>> print len(r.cmd('px 0x10000'))
16383
Wenzel commented 6 years ago

hmm, if you would print a nullbyte, the buffer length would not be a magic number like 4095 in my opinion.

Thank you for investigating. I will take a look next week if i can

radare commented 6 years ago

Any specific info like OS? Or python version?

Can you cook a small script to test if that works or not to include in the testsuite and for us to test?

Thanks

On 16 Mar 2018, at 19:52, Mathieu Tarral notifications@github.com wrote:

hmm, if you would print a nullbyte, the buffer length would not be a magic number like 4095 in my opinion.

Thank you for investigating. I will take a look next week if i can

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub, or mute the thread.

radare commented 6 years ago

ping

Wenzel commented 6 years ago

Hello, you know it's the week-end don't you :)

but anyway: OS: Ubuntu 16.04 stable Python 3.5.2

I made a video to demonstrate how it happens: https://drive.google.com/file/d/1D8Zj2MB35y3lq7MxcpVgC4CJmvDSxkdH/view?usp=sharing

Also note that i'm opening the url with the -d flag, to enable the debugging mode.

Wenzel commented 6 years ago

@radare i made some progress on this bug, it's still here, and i have a Dockerfile for you to reproduce:

FROM radare/radare2

USER root
RUN apt-get update && apt-get install -y build-essential git libtool \
        libvirt-dev autoconf pkg-config flex bison libglib2.0-dev libxen-dev libjson-c-dev \
        python3-pip python3-docopt
USER r2

# install libvmi
RUN git clone https://github.com/libvmi/libvmi
USER root
RUN cd libvmi && ./autogen.sh && ./configure --prefix=/usr && make && make install
USER r2

# vmi plugin
RUN git clone https://github.com/Wenzel/r2vmi -b debug_r2pipe
ENV PKG_CONFIG_PATH /usr/lib/pkgconfig
RUN cd r2vmi && make install

# r2pipe
USER root
RUN pip3 install r2pipe
USER r2

ENTRYPOINT python3 r2vmi/examples/debug_r2pipe.py vm explorer

output:

...
Print line 888...
Print line 889...
Print line 890...
Print line 891...
Print line 892...
Print line 893...
Print line 894...
Print line 895...
Print line 896...
Print line 897...
Print line 898...
Print line 899...
Print line 900...
Print line 901...
Print line 902...
Print line 903...
Print line 904...
Print line 905...
Print line 906...
Print line 907...
Print line 908...
Print line 909...
Print line 910...
Print lin__read, offset: 0
read (nil): vmi_failure

__reg_read, type: 0, size:7168
INFO:root:size of output: 16383

We should have seen a pd 10 output being printed.

r2pipe script i'm using

    r2_url = "vmi://{}:{}".format(vm_name,target)
    r2 = r2pipe.open(r2_url, ["-d"])
    output = r2.cmd('pd 10')
    logging.info(output)
    logging.info("size of output: %s", len(output))

Thanks guys !