strace.go

// Copyright 2018 Google Inc.
//
// Licensed under the Apache License, Version 2.0 (the "License");
// you may not use this file except in compliance with the License.
// You may obtain a copy of the License at
//
//     http://www.apache.org/licenses/LICENSE-2.0
//
// Unless required by applicable law or agreed to in writing, software
// distributed under the License is distributed on an "AS IS" BASIS,
// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
// See the License for the specific language governing permissions and
// limitations under the License.

// Package strace implements the logic to print out the input and the return value
// of each traced syscall.
package strace

import (
	"encoding/binary"
	"fmt"
	"strconv"
	"strings"
	"syscall"
	"time"

	"gvisor.googlesource.com/gvisor/pkg/abi/linux"
	"gvisor.googlesource.com/gvisor/pkg/bits"
	"gvisor.googlesource.com/gvisor/pkg/eventchannel"
	"gvisor.googlesource.com/gvisor/pkg/sentry/arch"
	"gvisor.googlesource.com/gvisor/pkg/sentry/kernel"
	pb "gvisor.googlesource.com/gvisor/pkg/sentry/strace/strace_go_proto"
	slinux "gvisor.googlesource.com/gvisor/pkg/sentry/syscalls/linux"
	"gvisor.googlesource.com/gvisor/pkg/sentry/usermem"
)

// DefaultLogMaximumSize is the default LogMaximumSize.
const DefaultLogMaximumSize = 1024

// LogMaximumSize determines the maximum display size for data blobs (read,
// write, etc.).
var LogMaximumSize uint = DefaultLogMaximumSize

// EventMaximumSize determines the maximum size for data blobs (read, write,
// etc.) sent over the event channel. Default is 0 because most clients cannot
// do anything useful with binary text dump of byte array arguments.
var EventMaximumSize uint

func iovecs(t *kernel.Task, addr usermem.Addr, iovcnt int, printContent bool, maxBytes uint64) string {
	if iovcnt < 0 || iovcnt > linux.UIO_MAXIOV {
		return fmt.Sprintf("%#x (error decoding iovecs: invalid iovcnt)", addr)
	}
	ars, err := t.CopyInIovecs(addr, iovcnt)
	if err != nil {
		return fmt.Sprintf("%#x (error decoding iovecs: %v)", addr, err)
	}

	var totalBytes uint64
	var truncated bool
	iovs := make([]string, iovcnt)
	for i := 0; !ars.IsEmpty(); i, ars = i+1, ars.Tail() {
		ar := ars.Head()
		if ar.Length() == 0 || !printContent {
			iovs[i] = fmt.Sprintf("{base=%#x, len=%d}", ar.Start, ar.Length())
			continue
		}

		size := uint64(ar.Length())
		if truncated || totalBytes+size > maxBytes {
			truncated = true
			size = maxBytes - totalBytes
		} else {
			totalBytes += uint64(ar.Length())
		}

		b := make([]byte, size)
		amt, err := t.CopyIn(ar.Start, b)
		if err != nil {
			iovs[i] = fmt.Sprintf("{base=%#x, len=%d, %q..., error decoding string: %v}", ar.Start, ar.Length(), b[:amt], err)
			continue
		}

		dot := ""
		if truncated {
			// Indicate truncation.
			dot = "..."
		}
		iovs[i] = fmt.Sprintf("{base=%#x, len=%d, %q%s}", ar.Start, ar.Length(), b[:amt], dot)
	}

	return fmt.Sprintf("%#x %s", addr, strings.Join(iovs, ", "))
}

func dump(t *kernel.Task, addr usermem.Addr, size uint, maximumBlobSize uint) string {
	origSize := size
	if size > maximumBlobSize {
		size = maximumBlobSize
	}
	if size == 0 {
		return ""
	}

	b := make([]byte, size)
	amt, err := t.CopyIn(addr, b)
	if err != nil {
		return fmt.Sprintf("%#x (error decoding string: %s)", addr, err)
	}

	dot := ""
	if uint(amt) < origSize {
		// ... if we truncated the dump.
		dot = "..."
	}

	return fmt.Sprintf("%#x %q%s", addr, b[:amt], dot)
}

func path(t *kernel.Task, addr usermem.Addr) string {
	path, err := t.CopyInString(addr, syscall.PathMax)
	if err != nil {
		return fmt.Sprintf("%#x (error decoding path: %s)", addr, err)
	}
	return fmt.Sprintf("%#x %s", addr, path)
}

func fdpair(t *kernel.Task, addr usermem.Addr) string {
	var fds [2]int32
	_, err := t.CopyIn(addr, &fds)
	if err != nil {
		return fmt.Sprintf("%#x (error decoding fds: %s)", addr, err)
	}

	return fmt.Sprintf("%#x [%d %d]", addr, fds[0], fds[1])
}

func uname(t *kernel.Task, addr usermem.Addr) string {
	var u linux.UtsName
	if _, err := t.CopyIn(addr, &u); err != nil {
		return fmt.Sprintf("%#x (error decoding utsname: %s)", addr, err)
	}

	return fmt.Sprintf("%#x %s", addr, u)
}

func utimensTimespec(t *kernel.Task, addr usermem.Addr) string {
	if addr == 0 {
		return "null"
	}

	var tim linux.Timespec
	if _, err := t.CopyIn(addr, &tim); err != nil {
		return fmt.Sprintf("%#x (error decoding timespec: %s)", addr, err)
	}

	var ns string
	switch tim.Nsec {
	case linux.UTIME_NOW:
		ns = "UTIME_NOW"
	case linux.UTIME_OMIT:
		ns = "UTIME_OMIT"
	default:
		ns = fmt.Sprintf("%v", tim.Nsec)
	}
	return fmt.Sprintf("%#x {sec=%v nsec=%s}", addr, tim.Sec, ns)
}

func timespec(t *kernel.Task, addr usermem.Addr) string {
	if addr == 0 {
		return "null"
	}

	var tim linux.Timespec
	if _, err := t.CopyIn(addr, &tim); err != nil {
		return fmt.Sprintf("%#x (error decoding timespec: %s)", addr, err)
	}
	return fmt.Sprintf("%#x {sec=%v nsec=%v}", addr, tim.Sec, tim.Nsec)
}

func timeval(t *kernel.Task, addr usermem.Addr) string {
	if addr == 0 {
		return "null"
	}

	var tim linux.Timeval
	if _, err := t.CopyIn(addr, &tim); err != nil {
		return fmt.Sprintf("%#x (error decoding timeval: %s)", addr, err)
	}

	return fmt.Sprintf("%#x {sec=%v usec=%v}", addr, tim.Sec, tim.Usec)
}

func utimbuf(t *kernel.Task, addr usermem.Addr) string {
	if addr == 0 {
		return "null"
	}

	var utim syscall.Utimbuf
	if _, err := t.CopyIn(addr, &utim); err != nil {
		return fmt.Sprintf("%#x (error decoding utimbuf: %s)", addr, err)
	}

	return fmt.Sprintf("%#x {actime=%v, modtime=%v}", addr, utim.Actime, utim.Modtime)
}

func stat(t *kernel.Task, addr usermem.Addr) string {
	if addr == 0 {
		return "null"
	}

	var stat linux.Stat
	if _, err := t.CopyIn(addr, &stat); err != nil {
		return fmt.Sprintf("%#x (error decoding stat: %s)", addr, err)
	}
	return fmt.Sprintf("%#x {dev=%d, ino=%d, mode=%s, nlink=%d, uid=%d, gid=%d, rdev=%d, size=%d, blksize=%d, blocks=%d, atime=%s, mtime=%s, ctime=%s}", addr, stat.Dev, stat.Ino, linux.FileMode(stat.Mode), stat.Nlink, stat.UID, stat.GID, stat.Rdev, stat.Size, stat.Blksize, stat.Blocks, time.Unix(stat.ATime.Sec, stat.ATime.Nsec), time.Unix(stat.MTime.Sec, stat.MTime.Nsec), time.Unix(stat.CTime.Sec, stat.CTime.Nsec))
}

func itimerval(t *kernel.Task, addr usermem.Addr) string {
	if addr == 0 {
		return "null"
	}

	interval := timeval(t, addr)
	value := timeval(t, addr+usermem.Addr(binary.Size(linux.Timeval{})))
	return fmt.Sprintf("%#x {interval=%s, value=%s}", addr, interval, value)
}

func stringVector(t *kernel.Task, addr usermem.Addr) string {
	vec, err := t.CopyInVector(addr, slinux.ExecMaxElemSize, slinux.ExecMaxTotalSize)
	if err != nil {
		return fmt.Sprintf("%#x {error copying vector: %v}", addr, err)
	}
	s := fmt.Sprintf("%#x [", addr)
	for i, v := range vec {
		if i != 0 {
			s += ", "
		}
		s += fmt.Sprintf("%q", v)
	}
	s += "]"
	return s
}

func rusage(t *kernel.Task, addr usermem.Addr) string {
	if addr == 0 {
		return "null"
	}

	var ru linux.Rusage
	if _, err := t.CopyIn(addr, &ru); err != nil {
		return fmt.Sprintf("%#x (error decoding rusage: %s)", addr, err)
	}
	return fmt.Sprintf("%#x %+v", addr, ru)
}

// pre fills in the pre-execution arguments for a system call. If an argument
// cannot be interpreted before the system call is executed, then a hex value
// will be used. Note that a full output slice will always be provided, that is
// len(return) == len(args).
func (i *SyscallInfo) pre(t *kernel.Task, args arch.SyscallArguments, maximumBlobSize uint) []string {
	var output []string

	for arg := range args {
		if arg >= len(i.format) {
			break
		}
		switch i.format[arg] {
		case WriteBuffer:
			output = append(output, dump(t, args[arg].Pointer(), args[arg+1].SizeT(), maximumBlobSize))
		case WriteIOVec:
			output = append(output, iovecs(t, args[arg].Pointer(), int(args[arg+1].Int()), true /* content */, uint64(maximumBlobSize)))
		case IOVec:
			output = append(output, iovecs(t, args[arg].Pointer(), int(args[arg+1].Int()), false /* content */, uint64(maximumBlobSize)))
		case SendMsgHdr:
			output = append(output, msghdr(t, args[arg].Pointer(), true /* content */, uint64(maximumBlobSize)))
		case RecvMsgHdr:
			output = append(output, msghdr(t, args[arg].Pointer(), false /* content */, uint64(maximumBlobSize)))
		case Path:
			output = append(output, path(t, args[arg].Pointer()))
		case ExecveStringVector:
			output = append(output, stringVector(t, args[arg].Pointer()))
		case SockAddr:
			output = append(output, sockAddr(t, args[arg].Pointer(), uint32(args[arg+1].Uint64())))
		case SockLen:
			output = append(output, sockLenPointer(t, args[arg].Pointer()))
		case SockFamily:
			output = append(output, SocketFamily.Parse(uint64(args[arg].Int())))
		case SockType:
			output = append(output, sockType(args[arg].Int()))
		case SockProtocol:
			output = append(output, sockProtocol(args[arg-2].Int(), args[arg].Int()))
		case SockFlags:
			output = append(output, sockFlags(args[arg].Int()))
		case Timespec:
			output = append(output, timespec(t, args[arg].Pointer()))
		case UTimeTimespec:
			output = append(output, utimensTimespec(t, args[arg].Pointer()))
		case ItimerVal:
			output = append(output, itimerval(t, args[arg].Pointer()))
		case Timeval:
			output = append(output, timeval(t, args[arg].Pointer()))
		case Utimbuf:
			output = append(output, utimbuf(t, args[arg].Pointer()))
		case CloneFlags:
			output = append(output, CloneFlagSet.Parse(uint64(args[arg].Uint())))
		case OpenFlags:
			output = append(output, open(uint64(args[arg].Uint())))
		case Mode:
			output = append(output, linux.FileMode(args[arg].ModeT()).String())
		case FutexOp:
			output = append(output, futex(uint64(args[arg].Uint())))
		case PtraceRequest:
			output = append(output, PtraceRequestSet.Parse(args[arg].Uint64()))
		case Oct:
			output = append(output, "0o"+strconv.FormatUint(args[arg].Uint64(), 8))
		case Hex:
			fallthrough
		default:
			output = append(output, "0x"+strconv.FormatUint(args[arg].Uint64(), 16))
		}
	}

	return output
}

// post fills in the post-execution arguments for a system call. This modifies
// the given output slice in place with arguments that may only be interpreted
// after the system call has been executed.
func (i *SyscallInfo) post(t *kernel.Task, args arch.SyscallArguments, rval uintptr, output []string, maximumBlobSize uint) {
	for arg := range output {
		if arg >= len(i.format) {
			break
		}
		switch i.format[arg] {
		case ReadBuffer:
			output[arg] = dump(t, args[arg].Pointer(), uint(rval), maximumBlobSize)
		case ReadIOVec:
			printLength := uint64(rval)
			if printLength > uint64(maximumBlobSize) {
				printLength = uint64(maximumBlobSize)
			}
			output[arg] = iovecs(t, args[arg].Pointer(), int(args[arg+1].Int()), true /* content */, printLength)
		case WriteIOVec, IOVec, WriteBuffer:
			// We already have a big blast from write.
			output[arg] = "..."
		case SendMsgHdr:
			output[arg] = msghdr(t, args[arg].Pointer(), false /* content */, uint64(maximumBlobSize))
		case RecvMsgHdr:
			output[arg] = msghdr(t, args[arg].Pointer(), true /* content */, uint64(maximumBlobSize))
		case PipeFDs:
			output[arg] = fdpair(t, args[arg].Pointer())
		case Uname:
			output[arg] = uname(t, args[arg].Pointer())
		case Stat:
			output[arg] = stat(t, args[arg].Pointer())
		case PostSockAddr:
			output[arg] = postSockAddr(t, args[arg].Pointer(), args[arg+1].Pointer())
		case SockLen:
			output[arg] = sockLenPointer(t, args[arg].Pointer())
		case PostTimespec:
			output[arg] = timespec(t, args[arg].Pointer())
		case PostItimerVal:
			output[arg] = itimerval(t, args[arg].Pointer())
		case Timeval:
			output[arg] = timeval(t, args[arg].Pointer())
		case Rusage:
			output[arg] = rusage(t, args[arg].Pointer())
		}
	}
}

// printEntry prints the given system call entry.
func (i *SyscallInfo) printEnter(t *kernel.Task, args arch.SyscallArguments) []string {
	output := i.pre(t, args, LogMaximumSize)

	switch len(output) {
	case 0:
		t.Infof("%s E %s()", t.Name(), i.name)
	case 1:
		t.Infof("%s E %s(%s)", t.Name(), i.name,
			output[0])
	case 2:
		t.Infof("%s E %s(%s, %s)", t.Name(), i.name,
			output[0], output[1])
	case 3:
		t.Infof("%s E %s(%s, %s, %s)", t.Name(), i.name,
			output[0], output[1], output[2])
	case 4:
		t.Infof("%s E %s(%s, %s, %s, %s)", t.Name(), i.name,
			output[0], output[1], output[2], output[3])
	case 5:
		t.Infof("%s E %s(%s, %s, %s, %s, %s)", t.Name(), i.name,
			output[0], output[1], output[2], output[3], output[4])
	case 6:
		t.Infof("%s E %s(%s, %s, %s, %s, %s, %s)", t.Name(), i.name,
			output[0], output[1], output[2], output[3], output[4], output[5])
	}

	return output
}

// printExit prints the given system call exit.
func (i *SyscallInfo) printExit(t *kernel.Task, elapsed time.Duration, output []string, args arch.SyscallArguments, retval uintptr, err error, errno int) {
	var rval string
	if err == nil {
		// Fill in the output after successful execution.
		i.post(t, args, retval, output, LogMaximumSize)
		rval = fmt.Sprintf("%#x (%v)", retval, elapsed)
	} else {
		rval = fmt.Sprintf("%#x errno=%d (%s) (%v)", retval, errno, err, elapsed)
	}

	switch len(output) {
	case 0:
		t.Infof("%s X %s() = %s", t.Name(), i.name,
			rval)
	case 1:
		t.Infof("%s X %s(%s) = %s", t.Name(), i.name,
			output[0], rval)
	case 2:
		t.Infof("%s X %s(%s, %s) = %s", t.Name(), i.name,
			output[0], output[1], rval)
	case 3:
		t.Infof("%s X %s(%s, %s, %s) = %s", t.Name(), i.name,
			output[0], output[1], output[2], rval)
	case 4:
		t.Infof("%s X %s(%s, %s, %s, %s) = %s", t.Name(), i.name,
			output[0], output[1], output[2], output[3], rval)
	case 5:
		t.Infof("%s X %s(%s, %s, %s, %s, %s) = %s", t.Name(), i.name,
			output[0], output[1], output[2], output[3], output[4], rval)
	case 6:
		t.Infof("%s X %s(%s, %s, %s, %s, %s, %s) = %s", t.Name(), i.name,
			output[0], output[1], output[2], output[3], output[4], output[5], rval)
	}
}

// sendEnter sends the syscall enter to event log.
func (i *SyscallInfo) sendEnter(t *kernel.Task, args arch.SyscallArguments) []string {
	output := i.pre(t, args, EventMaximumSize)

	event := pb.Strace{
		Process:  t.Name(),
		Function: i.name,
		Info: &pb.Strace_Enter{
			Enter: &pb.StraceEnter{},
		},
	}
	for _, arg := range output {
		event.Args = append(event.Args, arg)
	}
	eventchannel.Emit(&event)

	return output
}

// sendExit sends the syscall exit to event log.
func (i *SyscallInfo) sendExit(t *kernel.Task, elapsed time.Duration, output []string, args arch.SyscallArguments, rval uintptr, err error, errno int) {
	if err == nil {
		// Fill in the output after successful execution.
		i.post(t, args, rval, output, EventMaximumSize)
	}

	exit := &pb.StraceExit{
		Return:    fmt.Sprintf("%#x", rval),
		ElapsedNs: elapsed.Nanoseconds(),
	}
	if err != nil {
		exit.Error = err.Error()
		exit.ErrNo = int64(errno)
	}
	event := pb.Strace{
		Process:  t.Name(),
		Function: i.name,
		Info:     &pb.Strace_Exit{Exit: exit},
	}
	for _, arg := range output {
		event.Args = append(event.Args, arg)
	}
	eventchannel.Emit(&event)
}

type syscallContext struct {
	info        SyscallInfo
	args        arch.SyscallArguments
	start       time.Time
	logOutput   []string
	eventOutput []string
	flags       uint32
}

// SyscallEnter implements kernel.Stracer.SyscallEnter. It logs the syscall
// entry trace.
func (s SyscallMap) SyscallEnter(t *kernel.Task, sysno uintptr, args arch.SyscallArguments, flags uint32) interface{} {
	info, ok := s[sysno]
	if !ok {
		info = SyscallInfo{
			name:   fmt.Sprintf("sys_%d", sysno),
			format: defaultFormat,
		}
	}

	var output, eventOutput []string
	if bits.IsOn32(flags, kernel.StraceEnableLog) {
		output = info.printEnter(t, args)
	}
	if bits.IsOn32(flags, kernel.StraceEnableEvent) {
		eventOutput = info.sendEnter(t, args)
	}

	return &syscallContext{
		info:        info,
		args:        args,
		start:       time.Now(),
		logOutput:   output,
		eventOutput: eventOutput,
		flags:       flags,
	}
}

// SyscallExit implements kernel.Stracer.SyscallExit. It logs the syscall
// exit trace.
func (s SyscallMap) SyscallExit(context interface{}, t *kernel.Task, sysno, rval uintptr, err error) {
	errno := t.ExtractErrno(err, int(sysno))
	c := context.(*syscallContext)

	elapsed := time.Since(c.start)
	if bits.IsOn32(c.flags, kernel.StraceEnableLog) {
		c.info.printExit(t, elapsed, c.logOutput, c.args, rval, err, errno)
	}
	if bits.IsOn32(c.flags, kernel.StraceEnableEvent) {
		c.info.sendExit(t, elapsed, c.eventOutput, c.args, rval, err, errno)
	}
}

// ConvertToSysnoMap converts the names to a map keyed on the syscall number and value set to true.
// The map is in a convenient format to call SyscallFlagsTable.Enable().
func (s SyscallMap) ConvertToSysnoMap(syscalls []string) (map[uintptr]bool, error) {
	if syscalls == nil {
		// Sentinel: no list.
		return nil, nil
	}

	l := make(map[uintptr]bool)
	for _, sc := range syscalls {
		// Try to match this system call.
		sysno, ok := s.ConvertToSysno(sc)
		if !ok {
			return nil, fmt.Errorf("syscall %q not found", sc)
		}
		l[sysno] = true
	}

	// Success.
	return l, nil
}

// ConvertToSysno converts the name to system call number. Returns false
// if syscall with same name is not found.
func (s SyscallMap) ConvertToSysno(syscall string) (uintptr, bool) {
	for sysno, info := range s {
		if info.name != "" && info.name == syscall {
			return sysno, true
		}
	}
	return 0, false
}

// Name returns the syscall name.
func (s SyscallMap) Name(sysno uintptr) string {
	if info, ok := s[sysno]; ok {
		return info.name
	}
	return fmt.Sprintf("sys_%d", sysno)
}

// Initialize prepares all syscall tables for use by this package.
//
// N.B. This is not in an init function because we can't be sure all syscall
// tables are registered with the kernel when init runs.
//
// TODO: remove kernel package dependencies from this package and
// have the kernel package self-initialize all syscall tables.
func Initialize() {
	for _, table := range kernel.SyscallTables() {
		// Is this known?
		sys, ok := Lookup(table.OS, table.Arch)
		if !ok {
			continue
		}

		table.Stracer = sys
	}
}

// SinkType defines where to send straces to.
type SinkType uint32

const (
	// SinkTypeLog sends straces to text log
	SinkTypeLog SinkType = 1 << iota

	// SinkTypeEvent sends strace to event log
	SinkTypeEvent
)

func convertToSyscallFlag(sinks SinkType) uint32 {
	ret := uint32(0)
	if bits.IsOn32(uint32(sinks), uint32(SinkTypeLog)) {
		ret |= kernel.StraceEnableLog
	}
	if bits.IsOn32(uint32(sinks), uint32(SinkTypeEvent)) {
		ret |= kernel.StraceEnableEvent
	}
	return ret
}

// Enable enables the syscalls in whitelist in all syscall tables.
//
// Preconditions: Initialize has been called.
func Enable(whitelist []string, sinks SinkType) error {
	flags := convertToSyscallFlag(sinks)
	for _, table := range kernel.SyscallTables() {
		// Is this known?
		sys, ok := Lookup(table.OS, table.Arch)
		if !ok {
			continue
		}

		// Convert to a set of system calls numbers.
		wl, err := sys.ConvertToSysnoMap(whitelist)
		if err != nil {
			return err
		}

		table.FeatureEnable.Enable(flags, wl, true)
	}

	// Done.
	return nil
}

// Disable will disable Strace for all system calls and missing syscalls.
//
// Preconditions: Initialize has been called.
func Disable(sinks SinkType) {
	flags := convertToSyscallFlag(sinks)
	for _, table := range kernel.SyscallTables() {
		// Strace will be disabled for all syscalls including missing.
		table.FeatureEnable.Enable(flags, nil, false)
	}
}

// EnableAll enables all syscalls in all syscall tables.
//
// Preconditions: Initialize has been called.
func EnableAll(sinks SinkType) {
	flags := convertToSyscallFlag(sinks)
	for _, table := range kernel.SyscallTables() {
		// Is this known?
		if _, ok := Lookup(table.OS, table.Arch); !ok {
			continue
		}

		table.FeatureEnable.EnableAll(flags)
	}
}