gvisor debug

 

 

• Stack traces
• Debugger
• Profiling
  • Docker Proxy

To enable debug and system call logging, add the runtimeArgs below to your Docker configuration (/etc/docker/daemon.json):

{
    "runtimes": {
        "runsc": {
            "path": "/usr/local/bin/runsc",
            "runtimeArgs": [
                "--debug-log=/tmp/runsc/",
                "--debug",
                "--strace"
            ]
       }
    }
}

Note: the last / in --debug-log is needed to interpret it as a directory. Then each runsc command executed will create a separate log file. Otherwise, log messages from all commands will be appended to the same file.

You may also want to pass --log-packets to troubleshoot network problems. Then restart the Docker daemon:

sudo systemctl restart docker

Run your container again, and inspect the files under /tmp/runsc. The log file ending with .boot will contain the strace logs from your application, which can be useful for identifying missing or broken system calls in gVisor. If you are having problems starting the container, the log file ending with .create may have the reason for the failure.

Stack traces

The command runsc debug --stacks collects stack traces while the sandbox is running which can be useful to troubleshoot issues or just to learn more about gVisor. It connects to the sandbox process, collects a stack dump, and writes it to the console. For example:

docker run --runtime=runsc --rm -d alpine sh -c "while true; do echo running; sleep 1; done"
63254c6ab3a6989623fa1fb53616951eed31ac605a2637bb9ddba5d8d404b35b

sudo runsc --root /var/run/docker/runtime-runsc/moby debug --stacks 63254c6ab3a6989623fa1fb53616951eed31ac605a2637bb9ddba5d8d404b35b

Note: --root variable is provided by docker and is normally set to /var/run/docker/runtime-[runtime-name]/moby. If in doubt, --root is logged to runsc logs.

Debugger

You can debug gVisor like any other Golang program. If you’re running with Docker, you’ll need to find the sandbox PID and attach the debugger as root. Here is an example:

bazel build -c dbg //runsc:runsc

docker run --runtime=runsc --rm --name=test -d alpine sleep 1000

docker inspect test | grep Pid | head -n 1

sudo dlv attach <PID>

break mm.MemoryManager.MMap
continue

Profiling

runsc integrates with Go profiling tools and gives you easy commands to profile CPU and heap usage. First you need to enable --profile in the command line options before starting the container:

{
    "runtimes": {
        "runsc-prof": {
            "path": "/usr/local/bin/runsc",
            "runtimeArgs": [
                "--profile"
            ]
       }
    }
}

Note: Enabling profiling loosens the seccomp protection added to the sandbox, and should not be run in production under normal circumstances.

Then restart docker to refresh the runtime options. While the container is running, execute runsc debug to collect profile information and save to a file. Here are the options available:

• –profile-heap: Generates heap profile to the speficied file.
• –profile-cpu: Enables CPU profiler, waits for --duration seconds and generates CPU profile to the speficied file.

For example:

docker run --runtime=runsc-prof --rm -d alpine sh -c "while true; do echo running; sleep 1; done"
63254c6ab3a6989623fa1fb53616951eed31ac605a2637bb9ddba5d8d404b35b

sudo runsc --root /var/run/docker/runtime-runsc-prof/moby debug --profile-heap=/tmp/heap.prof 63254c6ab3a6989623fa1fb53616951eed31ac605a2637bb9ddba5d8d404b35b
sudo runsc --root /var/run/docker/runtime-runsc-prof/moby debug --profile-cpu=/tmp/cpu.prof --duration=30s 63254c6ab3a6989623fa1fb53616951eed31ac605a2637bb9ddba5d8d404b35b

The resulting files can be opened using go tool pprof or pprof. The examples below create image file (.svg) with the heap profile and writes the top functions using CPU to the console:

go tool pprof -svg /usr/local/bin/runsc /tmp/heap.prof
go tool pprof -top /usr/local/bin/runsc /tmp/cpu.prof

Docker Proxy

When forwarding a port to the container, Docker will likely route traffic through the docker-proxy. This proxy may make profiling noisy, so it can be helpful to bypass it. Do so by sending traffic directly to the container IP and port. e.g., if the docker0 IP is 192.168.9.1, the container IP is likely a subsequent IP, such as 192.168.9.2.

 

 

 

oot@cloud:/mycontainer# runsc  --debug  --debug-log=/tmp/runsc/   run  mybusy
/ # ls
bin         dev         etc         hello3.txt  home        proc        root        sys         tmp         usr         var
/ # 

 

root@cloud:/tmp/runsc# ls
runsc.log.20210114-153731.135617.run  runsc.log.20210114-153731.157888.gofer  runsc.log.20210114-153731.160970.boot
root@cloud:/tmp/runsc# 

 

 

root@cloud:/mycontainer# runsc  --strace  --debug-log=/tmp/runsc/   run  mybusy
/ # ls
bin         dev         etc         hello3.txt  home        proc        root        sys         tmp         usr         var
/ # 

 

root@cloud:/tmp/runsc# ls
runsc.log.20210114-153731.135617.run    runsc.log.20210114-153731.160970.boot  runsc.log.20210114-154245.774465.gofer
runsc.log.20210114-153731.157888.gofer  runsc.log.20210114-154245.743642.run   runsc.log.20210114-154245.777554.boot
root@cloud:/tmp/runsc# 

 

 

root@cloud:/gvisor# docker run --runtime=runsc --rm --name=test -d alpine sleep 1000
0f37c0e8480a757d3ca2c0be6a81c13deb1b2ed7034e211bdc622d361dc57fef
root@cloud:/gvisor# docker inspect test | grep Pid | head -n 1
            "Pid": 925361,
root@cloud:/gvisor# 

 

root@cloud:~/delve# dlv attach 925361
Type 'help' for list of commands.
(dlv) break mm.MemoryManager.MMap
Breakpoint 1 set at 0x3edc70 for gvisor.dev/gvisor/pkg/sentry/mm.(*MemoryManager).MMap() pkg/sentry/mm/syscalls.go:75
(dlv) continue

 

demo

 

root@cloud:/gvisor# docker inspect test | grep Pid | head -n 1
            "Pid": 925361,
root@cloud:/gvisor# docker inspect test | grep Pid | head -n 1
            "Pid": 925361,
root@cloud:/gvisor# docker inspect test | grep Pid 
            "Pid": 925361,
            "PidMode": "",
            "PidsLimit": null,
root@cloud:/gvisor# docker exec -it test ps -elf
OCI runtime exec failed: /usr/local/bin/runsc did not terminate successfully: : unknown
root@cloud:/gvisor# 

 

 

root@cloud:~/delve# dlv attach 925361
Type 'help' for list of commands.
(dlv) break mm.MemoryManager.MMap
Breakpoint 1 set at 0x3edc70 for gvisor.dev/gvisor/pkg/sentry/mm.(*MemoryManager).MMap() pkg/sentry/mm/syscalls.go:75
(dlv) continue
> gvisor.dev/gvisor/pkg/sentry/mm.(*MemoryManager).MMap() pkg/sentry/mm/syscalls.go:75 (hits goroutine(32):1 total:1) (PC: 0x3edc70)
Warning: debugging optimized function
(dlv) bt
 0  0x00000000003edc70 in gvisor.dev/gvisor/pkg/sentry/mm.(*MemoryManager).MMap
    at pkg/sentry/mm/syscalls.go:75
 1  0x00000000004de06c in gvisor.dev/gvisor/pkg/sentry/loader.loadParsedELF
    at pkg/sentry/loader/elf.go:505
 2  0x00000000004df348 in gvisor.dev/gvisor/pkg/sentry/loader.loadInitialELF
    at pkg/sentry/loader/elf.go:609
 3  0x00000000004df9e4 in gvisor.dev/gvisor/pkg/sentry/loader.loadELF
    at pkg/sentry/loader/elf.go:651
 4  0x00000000004e1204 in gvisor.dev/gvisor/pkg/sentry/loader.loadExecutable
    at pkg/sentry/loader/loader.go:179
 5  0x00000000004e1824 in gvisor.dev/gvisor/pkg/sentry/loader.Load
    at pkg/sentry/loader/loader.go:222
 6  0x000000000051560c in gvisor.dev/gvisor/pkg/sentry/kernel.(*Kernel).LoadTaskImage
    at pkg/sentry/kernel/task_image.go:150
 7  0x00000000004f4e80 in gvisor.dev/gvisor/pkg/sentry/kernel.(*Kernel).CreateProcess
    at pkg/sentry/kernel/kernel.go:1022
 8  0x00000000006c0f34 in gvisor.dev/gvisor/pkg/sentry/control.(*Proc).execAsync
    at pkg/sentry/control/proc.go:220
 9  0x00000000006c0970 in gvisor.dev/gvisor/pkg/sentry/control.ExecAsync
    at pkg/sentry/control/proc.go:133
10  0x0000000000925470 in gvisor.dev/gvisor/runsc/boot.(*Loader).executeAsync
    at runsc/boot/loader.go:972
11  0x0000000000916a88 in gvisor.dev/gvisor/runsc/boot.(*containerManager).ExecuteAsync
    at runsc/boot/controller.go:321
12  0x0000000000075ec4 in runtime.call64
    at src/runtime/asm_arm64.s:1
13  0x00000000000c0c80 in reflect.Value.call
    at GOROOT/src/reflect/value.go:475
14  0x00000000000c0444 in reflect.Value.Call
    at GOROOT/src/reflect/value.go:336
15  0x0000000000688c30 in gvisor.dev/gvisor/pkg/urpc.(*Server).handleOne
    at pkg/urpc/urpc.go:337
16  0x00000000006897d0 in gvisor.dev/gvisor/pkg/urpc.(*Server).handleRegistered
    at pkg/urpc/urpc.go:432
17  0x000000000068adbc in gvisor.dev/gvisor/pkg/urpc.(*Server).StartHandling.func1
    at pkg/urpc/urpc.go:452
18  0x0000000000077c84 in runtime.goexit
    at src/runtime/asm_arm64.s:1136
(dlv) 

 

demo2

root@cloud:/mycontainer# dlv exec  /usr/local/bin/runsc run  mybusy
Type 'help' for list of commands.
(dlv) b bluepillHandler
Breakpoint 1 set at 0x87b300 for gvisor.dev/gvisor/pkg/sentry/platform/kvm.bluepillHandler() pkg/sentry/platform/kvm/bluepill_unsafe.go:91
(dlv) c

 

 

demo3

 

oot@cloud:/gvisor# docker run --runtime=runsc-kvm --rm --name=test -d alpine sleep 1000
e910cbadcdee750b323188a7ca1d6252b4e0fd658bb196d15fc221cb35229edc
root@cloud:/gvisor# docker inspect test | grep Pid | head -n 1
            "Pid": 926926,
root@cloud:/gvisor# docker exec -it test ps -elf
PID   USER     TIME  COMMAND
    1 root      0:00 sleep 1000
    2 root      0:00 ps -elf

 

root@cloud:/mycontainer# dlv attach 926926
Type 'help' for list of commands.
(dlv) b bluepillHandler
Breakpoint 1 set at 0x87b300 for gvisor.dev/gvisor/pkg/sentry/platform/kvm.bluepillHandler() pkg/sentry/platform/kvm/bluepill_unsafe.go:91
(dlv) continue
> gvisor.dev/gvisor/pkg/sentry/platform/kvm.bluepillHandler() pkg/sentry/platform/kvm/bluepill_unsafe.go:91 (hits goroutine(219):1 total:1) (PC: 0x87b300)
Warning: debugging optimized function
(dlv) bt
0  0x000000000087b300 in gvisor.dev/gvisor/pkg/sentry/platform/kvm.bluepillHandler
   at pkg/sentry/platform/kvm/bluepill_unsafe.go:91
1  0x0000000000881bec in ???
   at ?:-1
2  0x0000ffff90bcf598 in ???
   at ?:-1
3  0x000000000087f514 in gvisor.dev/gvisor/pkg/sentry/platform/kvm.(*vCPU).SwitchToUser
   at pkg/sentry/platform/kvm/machine_arm64_unsafe.go:249
(dlv) clear 1
Breakpoint 1 cleared at 0x87b300 for gvisor.dev/gvisor/pkg/sentry/platform/kvm.bluepillHandler() pkg/sentry/platform/kvm/bluepill_unsafe.go:91
(dlv) quit
Would you like to kill the process? [Y/n] n
root@cloud:/mycontainer# 

 

(dlv) b Socket
Command failed: Location "Socket" ambiguous: golang.org/x/sys/unix.Socket, syscall.Socket, type..eq.gvisor.dev/gvisor/pkg/unet.Socket, gvisor.dev/gvisor/pkg/sentry/syscalls/linux.Socket, gvisor.dev/gvisor/pkg/sentry/socket/netstack.(*provider).Socket…
(dlv) c
received SIGINT, stopping process (will not forward signal)
> syscall.Syscall6() src/syscall/asm_linux_arm64.s:43 (PC: 0x8dccc)
Warning: debugging optimized function
(dlv) b  linux.Socket
Breakpoint 1 set at 0x587f30 for gvisor.dev/gvisor/pkg/sentry/syscalls/linux.Socket() pkg/sentry/syscalls/linux/sys_socket.go:172
(dlv) b netstack.Socket
Command failed: Location "netstack.Socket" ambiguous: gvisor.dev/gvisor/pkg/sentry/socket/netstack.(*provider).Socket, gvisor.dev/gvisor/pkg/sentry/socket/netstack.(*providerVFS2).Socket…
(dlv) b netstack.(*provider).Socket
Breakpoint 2 set at 0x647270 for gvisor.dev/gvisor/pkg/sentry/socket/netstack.(*provider).Socket() pkg/sentry/socket/netstack/provider.go:94
(dlv) b netstack.(*providerVFS2).Socket
Breakpoint 3 set at 0x647960 for gvisor.dev/gvisor/pkg/sentry/socket/netstack.(*providerVFS2).Socket() pkg/sentry/socket/netstack/provider_vfs2.go:38
(dlv) c
> gvisor.dev/gvisor/pkg/sentry/syscalls/linux.Socket() pkg/sentry/syscalls/linux/sys_socket.go:172 (hits goroutine(306):1 total:1) (PC: 0x587f30)
Warning: debugging optimized function
(dlv) bt
0  0x0000000000587f30 in gvisor.dev/gvisor/pkg/sentry/syscalls/linux.Socket
   at pkg/sentry/syscalls/linux/sys_socket.go:172
1  0x0000000000522ea4 in gvisor.dev/gvisor/pkg/sentry/kernel.(*Task).executeSyscall
   at pkg/sentry/kernel/task_syscall.go:104
2  0x0000000000523c5c in gvisor.dev/gvisor/pkg/sentry/kernel.(*Task).doSyscallInvoke
   at pkg/sentry/kernel/task_syscall.go:239
3  0x00000000005238dc in gvisor.dev/gvisor/pkg/sentry/kernel.(*Task).doSyscallEnter
   at pkg/sentry/kernel/task_syscall.go:199
4  0x00000000005233e0 in gvisor.dev/gvisor/pkg/sentry/kernel.(*Task).doSyscall
   at pkg/sentry/kernel/task_syscall.go:174
5  0x0000000000518e00 in gvisor.dev/gvisor/pkg/sentry/kernel.(*runApp).execute
   at pkg/sentry/kernel/task_run.go:282
6  0x0000000000517d9c in gvisor.dev/gvisor/pkg/sentry/kernel.(*Task).run
   at pkg/sentry/kernel/task_run.go:97
7  0x0000000000077c84 in runtime.goexit
   at src/runtime/asm_arm64.s:1136
(dlv) c
> gvisor.dev/gvisor/pkg/sentry/socket/netstack.(*provider).Socket() pkg/sentry/socket/netstack/provider.go:94 (hits goroutine(306):1 total:1) (PC: 0x647270)
Warning: debugging optimized function
(dlv) bt
0  0x0000000000647270 in gvisor.dev/gvisor/pkg/sentry/socket/netstack.(*provider).Socket
   at pkg/sentry/socket/netstack/provider.go:94
1  0x00000000005635f8 in gvisor.dev/gvisor/pkg/sentry/socket.New
   at pkg/sentry/socket/socket.go:310
2  0x0000000000587fb0 in gvisor.dev/gvisor/pkg/sentry/syscalls/linux.Socket
   at pkg/sentry/syscalls/linux/sys_socket.go:183
3  0x0000000000522ea4 in gvisor.dev/gvisor/pkg/sentry/kernel.(*Task).executeSyscall
   at pkg/sentry/kernel/task_syscall.go:104
4  0x0000000000523c5c in gvisor.dev/gvisor/pkg/sentry/kernel.(*Task).doSyscallInvoke
   at pkg/sentry/kernel/task_syscall.go:239
5  0x00000000005238dc in gvisor.dev/gvisor/pkg/sentry/kernel.(*Task).doSyscallEnter
   at pkg/sentry/kernel/task_syscall.go:199
6  0x00000000005233e0 in gvisor.dev/gvisor/pkg/sentry/kernel.(*Task).doSyscall
   at pkg/sentry/kernel/task_syscall.go:174
7  0x0000000000518e00 in gvisor.dev/gvisor/pkg/sentry/kernel.(*runApp).execute
   at pkg/sentry/kernel/task_run.go:282
8  0x0000000000517d9c in gvisor.dev/gvisor/pkg/sentry/kernel.(*Task).run
   at pkg/sentry/kernel/task_run.go:97
9  0x0000000000077c84 in runtime.goexit
   at src/runtime/asm_arm64.s:1136
(dlv) clearall
Breakpoint 1 cleared at 0x587f30 for gvisor.dev/gvisor/pkg/sentry/syscalls/linux.Socket() pkg/sentry/syscalls/linux/sys_socket.go:172
Breakpoint 2 cleared at 0x647270 for gvisor.dev/gvisor/pkg/sentry/socket/netstack.(*provider).Socket() pkg/sentry/socket/netstack/provider.go:94
Breakpoint 3 cleared at 0x647960 for gvisor.dev/gvisor/pkg/sentry/socket/netstack.(*providerVFS2).Socket() pkg/sentry/socket/netstack/provider_vfs2.go:38
(dlv) quit
Would you like to kill the process? [Y/n] n