vpnkit-bridge.exe having too many handles open

grepfruit commented 4 years ago

[X] I have tried with the latest version of my channel (Stable or Edge)
[X] I have uploaded Diagnostics
Diagnostics ID: 3717065E-9758-42BF-B1A1-95AAEA9B2174/20200221211409

Expected behavior

vpnkit-bridge.exe has a reasonable amount of handles and a reasonable active memory working set.

Actual behavior

vpnkit-bridge.exe has 563153 system handles as reported by Task Manager and a working set of 625272K, which seems like too much.

vpnkit-bridge

Information

Windows Version: Windows 10 Pro
Docker Desktop Version: 2.2.0.3(42716)
Are you running inside a virtualized Windows e.g. on a cloud server or on a mac VM: No

Steps to reproduce the behavior

So far I noticed this happening just once.

jaireth commented 4 years ago

Looks like we've got a Zombie Process: https://randomascii.wordpress.com/2018/02/11/zombie-processes-are-eating-your-memory/

dfoster-cb911 commented 4 years ago

Getting this myself 😭

Windows Version: Windows 10 Pro Docker Desktop Version: 2.2.0.4(43472) Are you running inside a virtualized Windows e.g. on a cloud server or on a mac VM: No

cjrh commented 4 years ago

Windows Version: Windows 10 Pro Docker Desktop Version: 2.2.0.5 (43884)

Same behavior that the handle count rises over time. However: I am using PyCharm on my current project and once my PyCharm connects to the docker daemon at tcp://localhost:2375, the rate of handle accumulation is much more rapid (and this is reproducible). I have not yet checked whether that behaviour is the same with PyCharm connected to docker, but a different/empty project open. I was wondering whether anyone else seeing this is using either PyCharm, or a different IntelliJ IDE with docker integration, or if the dramatic handle-increase happens even with docker CLI only. To be clear, the handle count of vpnkit-bridge.exe still rises over time even if I don't connect with PyCharm - but the speed of the rise is much much lower.

grepfruit commented 4 years ago

I checked opened handles of vpnkit-bridge.exe using Process Monitor and 99% of them seem to be File handle to a named pipe "\Device\NamedPipe\docker_engine_linux" - so I guess that's what's leaking.

cjrh commented 4 years ago

There's a program provided by Microsoft called PipeList, provided here: https://docs.microsoft.com/en-us/sysinternals/downloads/pipelist

Running this and filtering for the named pipe docker_engine_linux every few seconds:

PS F:\downloads\PipeList> date; .\pipelist64.exe | grep docker_engine_linux
Sun Apr  5 10:44:48 EAST 2020
docker_engine_linux                           13816               -1
PS F:\downloads\PipeList> date; .\pipelist64.exe | grep docker_engine_linux
Sun Apr  5 10:44:50 EAST 2020
docker_engine_linux                           13820               -1
PS F:\downloads\PipeList> date; .\pipelist64.exe | grep docker_engine_linux
Sun Apr  5 10:44:54 EAST 2020
docker_engine_linux                           13829               -1
PS F:\downloads\PipeList> date; .\pipelist64.exe | grep docker_engine_linux
Sun Apr  5 10:44:57 EAST 2020
docker_engine_linux                           13833               -1
PS F:\downloads\PipeList> date; .\pipelist64.exe | grep docker_engine_linux
Sun Apr  5 10:45:00 EAST 2020
docker_engine_linux                           13838               -1
PS F:\downloads\PipeList> date; .\pipelist64.exe | grep docker_engine_linux
Sun Apr  5 10:45:03 EAST 2020
docker_engine_linux                           13847               -1
PS F:\downloads\PipeList> date; .\pipelist64.exe | grep docker_engine_linux
Sun Apr  5 10:45:06 EAST 2020
docker_engine_linux                           13855               -1
PS F:\downloads\PipeList> date; .\pipelist64.exe | grep docker_engine_linux
Sun Apr  5 10:45:09 EAST 2020
docker_engine_linux                           13860               -1
PS F:\downloads\PipeList> date; .\pipelist64.exe | grep docker_engine_linux
Sun Apr  5 10:45:11 EAST 2020
docker_engine_linux                           13864               -1
PS F:\downloads\PipeList> date; .\pipelist64.exe | grep docker_engine_linux
Sun Apr  5 10:45:14 EAST 2020
docker_engine_linux                           13869               -1
PS F:\downloads\PipeList> date; .\pipelist64.exe | grep docker_engine_linux
Sun Apr  5 10:45:17 EAST 2020
docker_engine_linux                           13878               -1
PS F:\downloads\PipeList> date; .\pipelist64.exe | grep docker_engine_linux
Sun Apr  5 10:45:21 EAST 2020
docker_engine_linux                           13886               -1

The column headers, not shown above because grep removes them, are:

Pipe Name                                    Instances       Max Instances
---------                                    ---------       -------------

As I said in my previous comment, this rate of increase in the instances is much lower when I have not connected PyCharm to docker. PyCharm connects to docker via the legacy tcp://localhost:2375 endpoint.

In the docker log file, I have copied below a section that corresponds to a similar time window as the output from PipeList above, to show that something, presumably PyCharm, is frequently hitting the docker API endpoint to read the current state. I imagine this is how PyCharm maintains its state to reflect docker state:

log file: C:\Users\caleb\AppData\Roaming\Docker\log\vm\docker.log

2020-04-05T00:44:41Z docker time="2020-04-05T00:44:41.681390886Z" level=debug msg="Calling GET /v1.38/images/json"
2020-04-05T00:44:41Z docker time="2020-04-05T00:44:41.734269887Z" level=debug msg="Calling GET /v1.38/containers/json?all=true"
2020-04-05T00:44:41Z docker time="2020-04-05T00:44:41.739862687Z" level=debug msg="Calling GET /v1.38/images/json"
2020-04-05T00:44:42Z docker time="2020-04-05T00:44:42.372800004Z" level=debug msg="Calling GET /v1.38/images/json"
2020-04-05T00:44:43Z docker time="2020-04-05T00:44:43.740043940Z" level=debug msg="Calling GET /v1.38/containers/json?all=true"
2020-04-05T00:44:43Z docker time="2020-04-05T00:44:43.760860340Z" level=debug msg="Calling GET /v1.38/images/json"
2020-04-05T00:44:43Z docker time="2020-04-05T00:44:43.821181242Z" level=debug msg="Calling GET /v1.38/containers/json?all=true"
2020-04-05T00:44:43Z docker time="2020-04-05T00:44:43.826927542Z" level=debug msg="Calling GET /v1.38/images/json"
2020-04-05T00:44:45Z docker time="2020-04-05T00:44:45.825836394Z" level=debug msg="Calling GET /v1.38/containers/json?all=true"
2020-04-05T00:44:45Z docker time="2020-04-05T00:44:45.888375096Z" level=debug msg="Calling GET /v1.38/images/json"
2020-04-05T00:44:45Z docker time="2020-04-05T00:44:45.935816497Z" level=debug msg="Calling GET /v1.38/containers/json?all=true"
2020-04-05T00:44:45Z docker time="2020-04-05T00:44:45.941318597Z" level=debug msg="Calling GET /v1.38/images/json"
2020-04-05T00:44:47Z docker time="2020-04-05T00:44:47.440153825Z" level=debug msg="Calling GET /v1.38/images/json"
2020-04-05T00:44:47Z docker time="2020-04-05T00:44:47.937478033Z" level=debug msg="Calling GET /v1.38/containers/json?all=true"
2020-04-05T00:44:47Z docker time="2020-04-05T00:44:47.943948633Z" level=debug msg="Calling GET /v1.38/images/json"
2020-04-05T00:44:47Z docker time="2020-04-05T00:44:47.992690134Z" level=debug msg="Calling GET /v1.38/containers/json?all=true"
2020-04-05T00:44:47Z docker time="2020-04-05T00:44:47.998660634Z" level=debug msg="Calling GET /v1.38/images/json"
2020-04-05T00:44:49Z docker time="2020-04-05T00:44:49.997263367Z" level=debug msg="Calling GET /v1.38/containers/json?all=true"
2020-04-05T00:44:50Z docker time="2020-04-05T00:44:50.019847568Z" level=debug msg="Calling GET /v1.38/images/json"
2020-04-05T00:44:50Z docker time="2020-04-05T00:44:50.081432469Z" level=debug msg="Calling GET /v1.38/containers/json?all=true"
2020-04-05T00:44:50Z docker time="2020-04-05T00:44:50.087642969Z" level=debug msg="Calling GET /v1.38/images/json"
2020-04-05T00:44:52Z docker time="2020-04-05T00:44:52.088448302Z" level=debug msg="Calling GET /v1.38/containers/json?all=true"
2020-04-05T00:44:52Z docker time="2020-04-05T00:44:52.122159703Z" level=debug msg="Calling GET /v1.38/images/json"
2020-04-05T00:44:52Z docker time="2020-04-05T00:44:52.181470904Z" level=debug msg="Calling GET /v1.38/containers/json?all=true"
2020-04-05T00:44:52Z docker time="2020-04-05T00:44:52.187572004Z" level=debug msg="Calling GET /v1.38/images/json"
2020-04-05T00:44:52Z docker time="2020-04-05T00:44:52.503151509Z" level=debug msg="Calling GET /v1.38/images/json"
2020-04-05T00:44:54Z docker time="2020-04-05T00:44:54.183464837Z" level=debug msg="Calling GET /v1.38/containers/json?all=true"
2020-04-05T00:44:54Z docker time="2020-04-05T00:44:54.193502337Z" level=debug msg="Calling GET /v1.38/images/json"
2020-04-05T00:44:54Z docker time="2020-04-05T00:44:54.236591238Z" level=debug msg="Calling GET /v1.38/containers/json?all=true"
2020-04-05T00:44:54Z docker time="2020-04-05T00:44:54.242048437Z" level=debug msg="Calling GET /v1.38/images/json"
2020-04-05T00:44:56Z docker time="2020-04-05T00:44:56.237161901Z" level=debug msg="Calling GET /v1.38/containers/json?all=true"
2020-04-05T00:44:56Z docker time="2020-04-05T00:44:56.243197191Z" level=debug msg="Calling GET /v1.38/images/json"
2020-04-05T00:44:56Z docker time="2020-04-05T00:44:56.292056514Z" level=debug msg="Calling GET /v1.38/containers/json?all=true"
2020-04-05T00:44:56Z docker time="2020-04-05T00:44:56.297786105Z" level=debug msg="Calling GET /v1.38/images/json"
2020-04-05T00:44:57Z docker time="2020-04-05T00:44:57.544771545Z" level=debug msg="Calling GET /v1.38/images/json"
2020-04-05T00:44:58Z docker time="2020-04-05T00:44:58.288690875Z" level=debug msg="Calling GET /v1.38/containers/json?all=true"
2020-04-05T00:44:58Z docker time="2020-04-05T00:44:58.296024164Z" level=debug msg="Calling GET /v1.38/images/json"
2020-04-05T00:44:58Z docker time="2020-04-05T00:44:58.359127965Z" level=debug msg="Calling GET /v1.38/containers/json?all=true"
2020-04-05T00:44:58Z docker time="2020-04-05T00:44:58.364576656Z" level=debug msg="Calling GET /v1.38/images/json"
2020-04-05T00:45:00Z docker time="2020-04-05T00:45:00.359237001Z" level=debug msg="Calling GET /v1.38/containers/json?all=true"
2020-04-05T00:45:00Z docker time="2020-04-05T00:45:00.364714701Z" level=debug msg="Calling GET /v1.38/images/json"
2020-04-05T00:45:00Z docker time="2020-04-05T00:45:00.410463901Z" level=debug msg="Calling GET /v1.38/containers/json?all=true"
2020-04-05T00:45:00Z docker time="2020-04-05T00:45:00.416487001Z" level=debug msg="Calling GET /v1.38/images/json"
2020-04-05T00:45:02Z docker time="2020-04-05T00:45:02.408497780Z" level=debug msg="Calling GET /v1.38/containers/json?all=true"
2020-04-05T00:45:02Z docker time="2020-04-05T00:45:02.414631579Z" level=debug msg="Calling GET /v1.38/images/json"
2020-04-05T00:45:02Z docker time="2020-04-05T00:45:02.474861061Z" level=debug msg="Calling GET /v1.38/containers/json?all=true"
2020-04-05T00:45:02Z docker time="2020-04-05T00:45:02.480730059Z" level=debug msg="Calling GET /v1.38/images/json"
2020-04-05T00:45:02Z docker time="2020-04-05T00:45:02.588223427Z" level=debug msg="Calling GET /v1.38/images/json"
2020-04-05T00:45:04Z docker time="2020-04-05T00:45:04.467781669Z" level=debug msg="Calling GET /v1.38/containers/json?all=true"
2020-04-05T00:45:04Z docker time="2020-04-05T00:45:04.485493364Z" level=debug msg="Calling GET /v1.38/images/json"
2020-04-05T00:45:04Z docker time="2020-04-05T00:45:04.549437845Z" level=debug msg="Calling GET /v1.38/containers/json?all=true"
2020-04-05T00:45:04Z docker time="2020-04-05T00:45:04.555062444Z" level=debug msg="Calling GET /v1.38/images/json"
2020-04-05T00:45:06Z docker time="2020-04-05T00:45:06.550189651Z" level=debug msg="Calling GET /v1.38/containers/json?all=true"
2020-04-05T00:45:06Z docker time="2020-04-05T00:45:06.555775350Z" level=debug msg="Calling GET /v1.38/images/json"
2020-04-05T00:45:06Z docker time="2020-04-05T00:45:06.606718335Z" level=debug msg="Calling GET /v1.38/containers/json?all=true"
2020-04-05T00:45:06Z docker time="2020-04-05T00:45:06.612444333Z" level=debug msg="Calling GET /v1.38/images/json"
2020-04-05T00:45:07Z docker time="2020-04-05T00:45:07.647002526Z" level=debug msg="Calling GET /v1.38/images/json"
2020-04-05T00:45:08Z docker time="2020-04-05T00:45:08.603747142Z" level=debug msg="Calling GET /v1.38/containers/json?all=true"
2020-04-05T00:45:08Z docker time="2020-04-05T00:45:08.609274540Z" level=debug msg="Calling GET /v1.38/images/json"
2020-04-05T00:45:08Z docker time="2020-04-05T00:45:08.669683223Z" level=debug msg="Calling GET /v1.38/containers/json?all=true"
2020-04-05T00:45:08Z docker time="2020-04-05T00:45:08.674913021Z" level=debug msg="Calling GET /v1.38/images/json"
2020-04-05T00:45:10Z docker time="2020-04-05T00:45:10.669802214Z" level=debug msg="Calling GET /v1.38/containers/json?all=true"
2020-04-05T00:45:10Z docker time="2020-04-05T00:45:10.676264710Z" level=debug msg="Calling GET /v1.38/images/json"
2020-04-05T00:45:10Z docker time="2020-04-05T00:45:10.735471276Z" level=debug msg="Calling GET /v1.38/containers/json?all=true"
2020-04-05T00:45:10Z docker time="2020-04-05T00:45:10.741200373Z" level=debug msg="Calling GET /v1.38/images/json"
2020-04-05T00:45:12Z docker time="2020-04-05T00:45:12.698817434Z" level=debug msg="Calling GET /v1.38/images/json"
2020-04-05T00:45:12Z docker time="2020-04-05T00:45:12.730433716Z" level=debug msg="Calling GET /v1.38/containers/json?all=true"
2020-04-05T00:45:12Z docker time="2020-04-05T00:45:12.736313812Z" level=debug msg="Calling GET /v1.38/images/json"
2020-04-05T00:45:12Z docker time="2020-04-05T00:45:12.791066380Z" level=debug msg="Calling GET /v1.38/containers/json?all=true"
2020-04-05T00:45:12Z docker time="2020-04-05T00:45:12.796398477Z" level=debug msg="Calling GET /v1.38/images/json"
2020-04-05T00:45:14Z docker time="2020-04-05T00:45:14.787488119Z" level=debug msg="Calling GET /v1.38/containers/json?all=true"
2020-04-05T00:45:14Z docker time="2020-04-05T00:45:14.794664515Z" level=debug msg="Calling GET /v1.38/images/json"
2020-04-05T00:45:14Z docker time="2020-04-05T00:45:14.848650084Z" level=debug msg="Calling GET /v1.38/containers/json?all=true"
2020-04-05T00:45:14Z docker time="2020-04-05T00:45:14.854170881Z" level=debug msg="Calling GET /v1.38/images/json"
2020-04-05T00:45:16Z docker time="2020-04-05T00:45:16.842970924Z" level=debug msg="Calling GET /v1.38/containers/json?all=true"
2020-04-05T00:45:16Z docker time="2020-04-05T00:45:16.851188419Z" level=debug msg="Calling GET /v1.38/images/json"
2020-04-05T00:45:16Z docker time="2020-04-05T00:45:16.903227589Z" level=debug msg="Calling GET /v1.38/containers/json?all=true"
2020-04-05T00:45:16Z docker time="2020-04-05T00:45:16.908413086Z" level=debug msg="Calling GET /v1.38/images/json"
2020-04-05T00:45:17Z docker time="2020-04-05T00:45:17.761436660Z" level=debug msg="Calling GET /v1.38/images/json"
2020-04-05T00:45:18Z docker time="2020-04-05T00:45:18.898789142Z" level=debug msg="Calling GET /v1.38/containers/json?all=true"
2020-04-05T00:45:18Z docker time="2020-04-05T00:45:18.904986652Z" level=debug msg="Calling GET /v1.38/images/json"
2020-04-05T00:45:19Z docker time="2020-04-05T00:45:19.016960129Z" level=debug msg="Calling GET /v1.38/containers/json?all=true"
2020-04-05T00:45:19Z docker time="2020-04-05T00:45:19.023510539Z" level=debug msg="Calling GET /v1.38/images/json"
2020-04-05T00:45:21Z docker time="2020-04-05T00:45:21.018063394Z" level=debug msg="Calling GET /v1.38/containers/json?all=true"
2020-04-05T00:45:21Z docker time="2020-04-05T00:45:21.023812703Z" level=debug msg="Calling GET /v1.38/images/json"
2020-04-05T00:45:21Z docker time="2020-04-05T00:45:21.140590088Z" level=debug msg="Calling GET /v1.38/containers/json?all=true"
2020-04-05T00:45:21Z docker time="2020-04-05T00:45:21.146702198Z" level=debug msg="Calling GET /v1.38/images/json"
2020-04-05T00:45:22Z docker time="2020-04-05T00:45:22.900608672Z" level=debug msg="Calling GET /v1.38/images/json"
2020-04-05T00:45:23Z docker time="2020-04-05T00:45:23.070083940Z" level=debug msg="Calling GET /v1.38/containers/json?all=true"
2020-04-05T00:45:23Z docker time="2020-04-05T00:45:23.076179450Z" level=debug msg="Calling GET /v1.38/images/json"
2020-04-05T00:45:23Z docker time="2020-04-05T00:45:23.220642678Z" level=debug msg="Calling GET /v1.38/containers/json?all=true"
2020-04-05T00:45:23Z docker time="2020-04-05T00:45:23.228172590Z" level=debug msg="Calling GET /v1.38/images/json"
2020-04-05T00:45:25Z docker time="2020-04-05T00:45:25.155147015Z" level=debug msg="Calling GET /v1.38/containers/json?all=true"
2020-04-05T00:45:25Z docker time="2020-04-05T00:45:25.162398713Z" level=debug msg="Calling GET /v1.38/images/json"
2020-04-05T00:45:25Z docker time="2020-04-05T00:45:25.304054291Z" level=debug msg="Calling GET /v1.38/containers/json?all=true"
2020-04-05T00:45:25Z docker time="2020-04-05T00:45:25.310104390Z" level=debug msg="Calling GET /v1.38/images/json"
2020-04-05T00:45:27Z docker time="2020-04-05T00:45:27.222819100Z" level=debug msg="Calling GET /v1.38/containers/json?all=true"
2020-04-05T00:45:27Z docker time="2020-04-05T00:45:27.232224617Z" level=debug msg="Calling GET /v1.38/images/json"
2020-04-05T00:45:27Z docker time="2020-04-05T00:45:27.365582854Z" level=debug msg="Calling GET /v1.38/containers/json?all=true"
2020-04-05T00:45:27Z docker time="2020-04-05T00:45:27.374319070Z" level=debug msg="Calling GET /v1.38/images/json"

(There is an offest of 10 hours because the PS dates are in UTC+10 and the docker logs are in UTC).

So it looks like each of these GET requests is allocating resources but not freeing them when the response is returned.

That is what we're seeing in task manager:

I can produce the same effect by running docker -H localhost info in a shell loop so it doesn't seem to be PyCharm specific.

cjrh commented 4 years ago

I'll add that I put in quite some effort to read the OCaml source for vpnkit to find out where these resources were being allocated and freed, but I have no experience with that language whatsoever and it proved to be too difficult in a short turnaround. Sorry I can't be of more help here. I am happy to test out new binaries of vpnkit.exe and vpnkit-bridge.exe if docker devs want someone to test things out. I'm happy to switch out binaries in my existing installation and so on.

mat007 commented 4 years ago

Thanks for reporting this and digging into it! It’s been added to our backlog and we’ll have a look as soon as possible, hopefully next sprint. vpnkit-bridge is a closed source component intended to work with but separate to vpnkit.

mat007 commented 4 years ago

We have fixed this on our master branch and it will be available both in the next Edge and Stable versions. Thanks!

cjrh commented 4 years ago

Docker Desktop Edge 2.3.0.0 was released April 20, I can confirm that it fixes this issue 👍

mat007 commented 4 years ago

Thank you for confirming it @cjrh ! I’ll go ahead and close this issue then.

docker-robott commented 4 years ago

Closed issues are locked after 30 days of inactivity. This helps our team focus on active issues.

If you have found a problem that seems similar to this, please open a new issue.

Send feedback to Docker Community Slack channels #docker-for-mac or #docker-for-windows. /lifecycle locked

docker / for-win