Centralize system call logging (#602)

* Remove per-syscall logging

* Make Cpu.read_string() stop reading at first symbolic byte

* Centralize syscall logging

* Update helper docstring

* Update arg/ret expansion

* Check for issymbolic first

* Tiny hex format change
This commit is contained in:
Yan Ivnitskiy
2017-11-28 18:36:33 -05:00
committed by GitHub
parent 3c7d92bfcd
commit 481e41991d
2 changed files with 73 additions and 79 deletions
+73 -18
View File
@@ -1,6 +1,7 @@
import inspect
import logging
import StringIO
import string
import sys
import types
@@ -274,20 +275,16 @@ class Abi(object):
yield base
base += word_bytes
def invoke(self, model, prefix_args=None):
def get_argument_values(self, model, prefix_args):
'''
Invoke a callable `model` as if it was a native function. If
:func:`~manticore.models.isvariadic` returns true for `model`, `model` receives a single
argument that is a generator for function arguments. Pass a tuple of
arguments for `prefix_args` you'd like to precede the actual
arguments.
Extract arguments for model from the environment and return as a tuple that
is ready to be passed to the model.
:param callable model: Python model of the function
:param tuple prefix_args: Parameters to pass to model before actual ones
:return: The result of calling `model`
:return: Arguments to be passed to the model
:rtype: tuple
'''
prefix_args = prefix_args or ()
spec = inspect.getargspec(model)
if spec.varargs:
@@ -312,12 +309,31 @@ class Abi(object):
# TODO(mark) this is here as a hack to avoid circular import issues
from ...models import isvariadic
if isvariadic(model):
arguments = prefix_args + (argument_iter,)
else:
arguments = prefix_args + tuple(islice(argument_iter, nargs))
return arguments
def invoke(self, model, prefix_args=None):
'''
Invoke a callable `model` as if it was a native function. If
:func:`~manticore.models.isvariadic` returns true for `model`, `model` receives a single
argument that is a generator for function arguments. Pass a tuple of
arguments for `prefix_args` you'd like to precede the actual
arguments.
:param callable model: Python model of the function
:param tuple prefix_args: Parameters to pass to model before actual ones
:return: The result of calling `model`
'''
prefix_args = prefix_args or ()
arguments = self.get_argument_values(model, prefix_args)
try:
if isvariadic(model):
result = model(*(prefix_args + (argument_iter,)))
else:
argument_tuple = prefix_args + tuple(islice(argument_iter, nargs))
result = model(*argument_tuple)
result = model(*arguments)
except ConcretizeArgument as e:
assert e.argnum >= len(prefix_args), "Can't concretize a constant arg"
idx = e.argnum - len(prefix_args)
@@ -339,10 +355,15 @@ class Abi(object):
return result
platform_logger = logging.getLogger('manticore.platforms.platform')
class SyscallAbi(Abi):
'''
A system-call specific ABI.
Captures model arguments and return values for centralized logging.
'''
def syscall_number(self):
'''
Extract the index of the invoked syscall.
@@ -351,6 +372,42 @@ class SyscallAbi(Abi):
'''
raise NotImplementedError
def get_argument_values(self, model, prefix_args):
self._last_arguments = super(SyscallAbi, self).get_argument_values(model, prefix_args)
return self._last_arguments
def invoke(self, model, prefix_args=None):
# invoke() will call get_argument_values()
self._last_arguments = ()
ret = super(SyscallAbi, self).invoke(model, prefix_args)
if platform_logger.isEnabledFor(logging.DEBUG):
# Try to expand strings up to max_arg_expansion
max_arg_expansion = 32
# Add a hex representation to return if greater than min_hex_expansion
min_hex_expansion = 0x80
args = []
for arg in self._last_arguments:
arg_s = "0x{:x}".format(arg)
if self._cpu.memory.access_ok(arg, 'r'):
s = self._cpu.read_string(arg, max_arg_expansion)
if all(c in string.printable for c in s):
if len(s) == max_arg_expansion:
s = s + '..'
if len(s) > 2:
arg_s = arg_s + ' ({})'.format(s.translate(None, '\n'))
args.append(arg_s)
args_s = ', '.join(args)
ret_s = '{}'.format(ret)
if ret > min_hex_expansion:
ret_s = ret_s + '(0x{:x})'.format(ret)
platform_logger.debug('%s(%s) -> %s', model.im_func.func_name, args_s, ret_s)
############################################################################
# Abstract cpu encapsulating common cpu methods used by platforms and executor.
class Cpu(Eventful):
@@ -578,7 +635,7 @@ class Cpu(Eventful):
def read_string(self, where, max_length=None):
'''
Read a NUL-terminated concrete buffer from memory.
Read a NUL-terminated concrete buffer from memory. Stops reading at first symbolic byte.
:param int where: Address to read string from
:param int max_length:
@@ -591,9 +648,7 @@ class Cpu(Eventful):
while True:
c = self.read_int(where, 8)
assert not issymbolic(c)
if c == 0:
if issymbolic(c) or c == 0:
break
if max_length is not None:
-61
View File
@@ -1122,7 +1122,6 @@ class Linux(Platform):
"Fd not seekable. Returning EBADF"))
return -errno.EBADF
logger.debug("LSEEK(%d, 0x%08x (%d), %d)", fd, offset, signed_offset, whence)
return 0
def sys_read(self, fd, buf, count):
@@ -1143,13 +1142,6 @@ class Linux(Platform):
self.syscall_trace.append(("_read", fd, data))
self.current.write_bytes(buf, data)
logger.debug("READ(%d, 0x%08x, %d, 0x%08x) -> <%s> (size:%d)",
fd,
buf,
count,
len(data),
repr(data)[:min(count,10)],
len(data))
return len(data)
def sys_write(self, fd, buf, count):
@@ -1217,10 +1209,6 @@ class Linux(Platform):
break
filename += c
logger.debug("access(%s, %x) -> %r",
filename,
mode,
os.access(filename, mode))
if os.access(filename, mode):
return 0
else:
@@ -1248,7 +1236,6 @@ class Linux(Platform):
uname_buf = ''.join(pad(pair[1]) for pair in info)
self.current.write_bytes(old_utsname, uname_buf)
logger.debug("sys_newuname(...) -> %s", uname_buf)
return 0
def sys_brk(self, brk):
@@ -1269,7 +1256,6 @@ class Linux(Platform):
addr = mem.mmap(mem._ceil(self.elf_brk), size, perms)
assert mem._ceil(self.elf_brk) == addr, "Error in brk!"
self.elf_brk += size
logger.debug("sys_brk(0x%08x) -> 0x%08x", brk, self.elf_brk)
return self.elf_brk
def sys_arch_prctl(self, code, addr):
@@ -1290,7 +1276,6 @@ class Linux(Platform):
assert code == ARCH_SET_FS
self.current.FS = 0x63
self.current.set_descriptor(self.current.FS, addr, 0x4000, 'rw')
logger.debug("sys_arch_prctl(%04x, %016x) -> 0", code, addr)
return 0
def sys_ioctl(self, fd, request, argp):
@@ -1345,8 +1330,6 @@ class Linux(Platform):
except OSError as e:
ret = -e.errno
logger.debug("sys_rename('%s', '%s') -> %s", oldname, newname, ret)
return ret
def sys_fsync(self, fd):
@@ -1362,8 +1345,6 @@ class Linux(Platform):
except BadFd:
ret = -errno.EINVAL
logger.debug("sys_fsync(%d) -> %d", fd, ret)
return ret
def sys_getpid(self, v):
@@ -1415,7 +1396,6 @@ class Linux(Platform):
return -errno.EBADF
newfd = self._dup(fd)
logger.debug('sys_dup(%d) -> %d', fd, newfd)
return newfd
def sys_dup2(self, fd, newfd):
@@ -1445,7 +1425,6 @@ class Linux(Platform):
self.files[newfd] = self.files[fd]
logger.debug('sys_dup2(%d,%d) -> %d', fd, newfd, newfd)
return newfd
def sys_close(self, fd):
@@ -1478,7 +1457,6 @@ class Linux(Platform):
else:
data = os.readlink(filename)[:bufsize]
self.current.write_bytes(buf, data)
logger.debug("READLINK %d %x %d -> %s",path,buf,bufsize,data)
return len(data)
def sys_mmap_pgoff(self, address, size, prot, flags, fd, offset):
@@ -1557,13 +1535,6 @@ class Linux(Platform):
cpu.memory.munmap(result, size)
result = -1
logger.debug("sys_mmap(%s, 0x%x, %s, %x, %d) - (0x%x)",
actually_mapped,
size,
perms,
flags,
fd,
result)
return result
def sys_mprotect(self, start, size, prot):
@@ -1579,7 +1550,6 @@ class Linux(Platform):
'''
perms = perms_from_protflags(prot)
ret = self.current.memory.mprotect(start, size, perms)
logger.debug("sys_mprotect(0x%016x, 0x%x, %s) -> %r (%r)", start, size, perms, ret, prot)
return 0
def sys_munmap(self, addr, size):
@@ -1653,12 +1623,6 @@ class Linux(Platform):
total += len(data)
cpu.write_bytes(buf, data)
self.syscall_trace.append(("_read", fd, data))
logger.debug("READV(%r, %r, %r) -> <%r> (size:%r)",
fd,
buf,
size,
data,
len(data))
return total
def sys_writev(self, fd, iov, count):
@@ -1688,7 +1652,6 @@ class Linux(Platform):
data = ""
for j in xrange(0,size):
data += Operators.CHR(cpu.read_int(buf + j, 8))
logger.debug("WRITEV(%r, %r, %r) -> <%r> (size:%r)",fd, buf, size, data, len(data))
data = self._transform_write_data(data)
write_fd.write(data)
self.syscall_trace.append(("_write", fd, data))
@@ -1757,30 +1720,23 @@ class Linux(Platform):
self.sched()
self.running.remove(procid)
#self.procs[procid] = None
logger.debug("EXIT_GROUP PROC_%02d %s", procid, ctypes.c_int32(error_code).value)
if len(self.running) == 0 :
raise TerminateState("Program finished with exit status: %r" % ctypes.c_int32(error_code).value, testcase=True)
return error_code
def sys_ptrace(self, request, pid, addr, data):
logger.debug("sys_ptrace(%016x, %d, %016x, %016x) -> 0", request, pid, addr, data)
return 0
def sys_nanosleep(self, req, rem):
logger.debug("sys_nanosleep(...)")
return 0
def sys_set_tid_address(self, tidptr):
logger.debug("sys_set_tid_address(%016x) -> 0", tidptr)
return 1000 #tha pid
def sys_faccessat(self, dirfd, pathname, mode, flags):
filename = self.current.read_string(pathname)
logger.debug("sys_faccessat(%016x, %s, %x, %x) -> 0", dirfd, filename, mode, flags)
return -1
def sys_set_robust_list(self, head, length):
logger.debug("sys_set_robust_list(%016x, %d) -> -1", head, length)
return -1
def sys_futex(self, uaddr, op, val, timeout, uaddr2, val3):
logger.debug("sys_futex(...) -> -1")
return -1
def sys_getrlimit(self, resource, rlim):
ret = -1
@@ -1790,14 +1746,11 @@ class Linux(Platform):
# see the BUGS section in getrlimit(2) man page.
self.current.write_bytes(rlim, struct.pack('<LL', *rlimit_tup))
ret = 0
logger.debug("sys_getrlimit(%x, %x) -> %d", resource, rlim, ret)
return ret
def sys_fadvise64(self, fd, offset, length, advice):
logger.debug("sys_fadvise64(%x, %x, %x, %x) -> 0", fd, offset, length, advice)
return 0
def sys_gettimeofday(self, tv, tz):
logger.debug("sys_gettimeofday(%x, %x) -> 0", tv, tz)
return 0
def sys_socket(self, domain, socket_type, protocol):
@@ -1812,7 +1765,6 @@ class Linux(Platform):
f = SocketDesc(domain, socket_type, protocol)
fd = self._open(f)
logger.debug("socket(%d, %d, %d) -> %d", domain, socket_type, protocol, fd)
return fd
def _is_sockfd(self, sockfd):
@@ -1825,11 +1777,9 @@ class Linux(Platform):
return -errno.EBADF
def sys_bind(self, sockfd, address, address_len):
logger.debug("bind(%d, %x, %d)", sockfd, address, address_len)
return self._is_sockfd(sockfd)
def sys_listen(self, sockfd, backlog):
logger.debug("listen(%d, %d)", sockfd, backlog)
return self._is_sockfd(sockfd)
def sys_accept(self, sockfd, addr, addrlen, flags):
@@ -1839,7 +1789,6 @@ class Linux(Platform):
sock = Socket()
fd = self._open(sock)
logger.debug('accept(%d, %x, %d, %d) -> %d', sockfd, addr, addrlen, flags, fd)
return fd
def sys_recv(self, sockfd, buf, count, flags):
@@ -1855,10 +1804,6 @@ class Linux(Platform):
self.current.write_bytes(buf, data)
self.syscall_trace.append(("_recv", sockfd, data))
logger.debug("recv(%d, 0x%08x, %d, 0x%08x) -> <%s> (size:%d)",
sockfd, buf, count, len(data), repr(data)[:min(count,32)],
len(data))
return len(data)
@@ -2119,8 +2064,6 @@ class Linux(Platform):
bufstat += to_timespec(nw, stat.st_mtime) # long st_mtime, nsec;
bufstat += to_timespec(nw, stat.st_ctime) # long st_ctime, nsec;
logger.debug("sys_newfstat(%d, ...) -> %d bytes", fd, len(bufstat))
self.current.write_bytes(buf, bufstat)
return 0
@@ -2146,8 +2089,6 @@ class Linux(Platform):
def to_timespec(ts):
return struct.pack('<LL', int(ts), int(ts % 1 * 1e9))
logger.debug("sys_fstat %d", fd)
bufstat = add(8, stat.st_dev) # dev_t st_dev;
bufstat += add(4, 0) # __pad1
bufstat += add(4, stat.st_ino) # unsigned long st_ino;
@@ -2191,8 +2132,6 @@ class Linux(Platform):
def to_timespec(ts):
return struct.pack('<LL', int(ts), int(ts % 1 * 1e9))
logger.debug("sys_fstat64 %d", fd)
bufstat = add(8, stat.st_dev) # unsigned long long st_dev;
bufstat += add(4, 0) # unsigned char __pad0[4];
bufstat += add(4, stat.st_ino) # unsigned long __st_ino;