Determining why docker command hands at startup in WSL2

In this quick post we demonstrate using strace to diagnose why docker is starting so danged slowly

In a recent migration to wsl2) in order to allow filesystem notifications in mounted volumes (hot reloading) I upgraded my windows desktop from WSL1 to WSL2

In the process the docker command started taking ~30s to execute. There has been a good deal of mucking about to figure out what's going on, I didn't immediately know what was going on.

➜ time docker
...
docker  0.07s user 0.01s system 0% cpu 32.139 total

Reaching for a handy tool I used strace to figure out what was taking so danged long.

-o - set output file
-t - enable timestamps

➜ strace -o docker-startup.txt -t docker
10:47:20 execve("/usr/bin/docker", ["docker"], [/* 25 vars */]) = 0
...

...
10:47:20 connect(3, {sa_family=AF_INET, sin_port=htons(2375), sin_addr=inet_addr("172.22.48.1")}, 16) = -1 EINPROGRESS (Operation now in progress)
10:47:20 epoll_ctl(4, EPOLL_CTL_ADD, 3, {EPOLLIN|EPOLLOUT|EPOLLRDHUP|EPOLLET, {u32=2729680648, u64=140272066600712}}) = 0
10:47:20 futex(0xc000518148, FUTEX_WAKE_PRIVATE, 1) = 1
10:47:20 epoll_pwait(4, [], 128, 0, NULL, 824638701380) = 0
10:47:20 futex(0x55df0de55d88, FUTEX_WAIT_PRIVATE, 0, NULL) = 0
10:47:25 futex(0x55df0de55d88, FUTEX_WAIT_PRIVATE, 0, NULL) = 0
10:47:30 futex(0x55df0de55d88, FUTEX_WAIT_PRIVATE, 0, NULL) = 0
10:47:35 futex(0x55df0de55d88, FUTEX_WAIT_PRIVATE, 0, NULL) = 0
10:47:40 futex(0x55df0de55d88, FUTEX_WAIT_PRIVATE, 0, NULL) = 0
10:47:45 futex(0x55df0de55d88, FUTEX_WAIT_PRIVATE, 0, NULL) = 0
10:47:50 futex(0x55df0de55d88, FUTEX_WAIT_PRIVATE, 0, NULL) = 0
10:47:52 futex(0x55df0de55d88, FUTEX_WAIT_PRIVATE, 0, NULL) = 0
10:47:52 futex(0xc0004d24c8, FUTEX_WAKE_PRIVATE, 1) = 1

Scanning for when the timestamp jumps it's pretty clear by the repeated 5 second increments on a WAIT that there is a timeout occurring, and scanning upward the 172.22.48.1 is a familiar sequence. I had been playing with changing the DOCKER_HOST and it was timing out

➜ vim ~/.zshrc
Delete the line
export DOCKER_HOST=tcp://172.22.48.1:2375

➜ time docker
docker  0.05s user 0.04s system 66% cpu 0.137 total

Much better.

In other interesting news, I saw this in the strace:

10:47:20 newfstatat(AT_FDCWD, "/usr/local/sbin/pass", 0xc00001d898, 0) = -1 ENOENT (No such file or directory)
10:47:20 newfstatat(AT_FDCWD, "/usr/local/bin/pass", 0xc00001d968, 0) = -1 ENOENT (No such file or directory)
10:47:20 newfstatat(AT_FDCWD, "/usr/sbin/pass", 0xc00001da38, 0) = -1 ENOENT (No such file or directory)
10:47:20 newfstatat(AT_FDCWD, "/usr/bin/pass", 0xc00001db08, 0) = -1 ENOENT (No such file or directory)
10:47:20 newfstatat(AT_FDCWD, "/sbin/pass", 0xc00001dbd8, 0) = -1 ENOENT (No such file or directory)
10:47:20 newfstatat(AT_FDCWD, "/bin/pass", 0xc00001dca8, 0) = -1 ENOENT (No such file or directory)
...
10:47:20 newfstatat(AT_FDCWD, "/usr/local/sbin/docker-credential-secretservice", 0xc000033898, 0) = -1 ENOENT (No such file or directory)
10:47:20 newfstatat(AT_FDCWD, "/usr/local/bin/docker-credential-secretservice", 0xc000033968, 0) = -1 ENOENT (No such file or directory)
10:47:20 newfstatat(AT_FDCWD, "/usr/sbin/docker-credential-secretservice", 0xc000033a38, 0) = -1 ENOENT (No such file or directory)
10:47:20 newfstatat(AT_FDCWD, "/usr/bin/docker-credential-secretservice", 0xc000033b08, 0) = -1 ENOENT (No such file or directory)
10:47:20 newfstatat(AT_FDCWD, "/sbin/docker-credential-secretservice", 0xc000033bd8, 0) = -1 ENOENT (No such file or directory)
10:47:20 newfstatat(AT_FDCWD, "/bin/docker-credential-secretservice", 0xc000033ca8, 0) = -1 ENOENT (No such file or directory)
10:47:20 newfstatat(AT_FDCWD, "/usr/games/docker-credential-secretservice", 0xc000033d78, 0) = -1 ENOENT (No such file or directory)
10:47:20 newfstatat(AT_FDCWD, "/usr/local/games/docker-credential-secretservice", 0xc000033e48, 0) = -1 ENOENT (No such file or directory)

It looks like docker is sniffing for a password manager. Spooky stuff!