with gRPC-fuse on: containers are remounted when other services are started or restarted

[qhenkart]

• [x ] I have tried with the latest version of my channel (Stable or Edge)
• [x ] I have uploaded Diagnostics
• Diagnostics ID:88536E2D-D1AC-4794-B87F-EA52F09784B0/20201212004740

Expected behavior

I can run multiple services using docker-compose on my local machine. It starts fast, uses very little memory, and volumes are properly mounted. (i.e. anything < 2.4)

Actual behavior

with gRPC-fuse I cannot run many services, it consumes the max memory possible and times out before it can stabilize. Without gRPC-fuse, everything works as expected, except volumes are not mounted properly and updates in the host do not propagate to the container (there are issues already for this last point )

Information

• macOS Version: 11.0.1

Diagnostic logs

I've included the diagnostic ID, I don't see "Diagnose & Feedback" in the menu, please tell me how I can provide better or more information

Docker for Mac: 3.0

Steps to reproduce the behavior

I am going to walk you through to be able to reproduce the behavior I have been noticing.

Here is a simple docker file that uses a common/simple go-watcher on golang1.14, The watcher isn't required, but it really easily illustrates all of the problems occurring here

FROM golang:1.14-stretch
RUN go get github.com/cespare/reflex
COPY reflex.conf /

now build the image and tag it. golang:1.14-watcher

now let's create the docker-compose.yml file

I have created an ultra simple server for this example. This server literally does nothing, but that's not the point. please git clone https://github.com/qhenkart/docker-example to $GOPATH/src/github.com/qhenkart/docker-example
and again
git clone https://github.com/qhenkart/docker-example to $GOPATH/src/github.com/qhenkart/docker-example2

at the base of your go path, let's make this docker-compose.yml file

service1:
    image: golang:1.14-watcher
    command: reflex --verbose -r '(\.go$$|go\.mod)'  -s -- go run main.go
    working_dir: /go/src/github.com/qhenkart/docker-example
    volumes:
      - ./go/src/github.com/qhenkart/docker-example:/go/src/github.com/qhenkart/docker-example

  service2:
    image: golang:1.14-watcher
    command: reflex --verbose -r '(\.go$$|go\.mod)' -s -- go run main.go
    working_dir: /go/src/github.com/qhenkart/docker-example2
    volumes:
      - ./go/src/github.com/qhenkart/docker-example2:/go/src/github.com/qhenkart/docker-example2

okay we're ready!
Scenario 1
with gRPC-fuse there is a major crossover between services which causes a massive slowdown, memory leak and if there are many services, a downright failure. Using gRPC-fuse over the last few weeks has destroyed my battery life and productivity. But with this example, we will see why very easily

Let's make sure that the defaults match gRPC-fuse is turned on and buildkit is turned on

open up 2 terminal windows.
terminal 1:
docker-compose up service1
wait for it to say "service started"

terminal 2:
docker-compose up service2

you will notice in terminal 1 the following

service1_1  | [00] Starting service
service1_1  | [00] service started
service1_1  | [info] fsnotify event: "./main.go": REMOVE.    **Here it unmounted every file (in this case just 1) causing the watcher to reset twice**
service1_1  | [00] Killing service
service1_1  | [00] ^Csignal: interrupt
service1_1  | [00] Starting service
service1_1  | [00] service started

In the end, both services are up and available. However, starting service #2 should not remount/restart service #1 . Multiply this by 20 services and add a large file structure to each, and you have a broken system that times out and uses too many resources before it can stabilize

Scenario 2
But since I have you (I hope I still have you), let's showcase what's going on in #5046

Simply turn off gRPC-fuse, and modify the main.go file. You will notice that starting or restarting service #2 does not affect service #1 (yay).... but you will also notice the changes are not updating into the container and a docker-compose restart is required every time a change is made to update the container

Let me know if there is anything I can do to better explain the issue here

[stephen-turner]

Thanks for the report and the analysis, @qhenkart. Assigning to @djs55 to have a look next week.

[djs55]

Thanks @qhenkart for the detailed repro steps -- I'll take a look on monday!

[djs55]

@qhenkart thanks again for the repro instructions. I confirm that it did reproduce for me locally. There seem to be 2 cache invalidation bugs grpcfuse:

1. as you suspected, cross-talk between one container and another. When we start a container we compute which new directories on the host to watch for changes and we then invalidate any corresponding cache entries inside the VM where the container is running. This is necessary because otherwise the container would start with an out-of-date view of the shared filesystem. Unfortunately to work around another bug, we invalidated / rather than only the new shared directory. This meant that when the service2 starts, we invalidate the cache entries for files seen by service1.
2. compounding (1) there are two very similar functions in FUSE called fuse_lowlevel_notify_inval_entry and fuse_lowlevel_notify_delete whose behaviour has evolved over time but the current behaviour is they are both the same, except fuse_lowlevel_notify_delete also triggers an fsnotify DELETE event. We call fuse_lowlevel_notify_delete when a file is deleted from the host (which is fine) but we also call it to drop cache entries when a container starts (which is wrong). This meant that when service2 started we dropped the cache entry (because of bug 1) and used the wrong function (bug 2) which sent service1 a DELETE event. I've fixed this by calling fuse_lowlevel_notify_inval_entry in cases where we aren't sure whether the file still exists or not.

In case you'd like to try it I've made a "preview" build with these fixes: https://desktop-stage.docker.com/mac/preview/50831/Docker.dmg . When I try your example now:

$ docker-compose up service1
Starting 5124_service1_1 ... done
Attaching to 5124_service1_1
service1_1  | Globals set at commandline
service1_1  | | --regex (-r) '[(\.go$|go\.mod)]' (default: '[]')
service1_1  | | --start-service (-s) 'true' (default: 'false')
service1_1  | | --verbose (-v) 'true' (default: 'false')
service1_1  | +---------
service1_1  | Reflex from [commandline]
service1_1  | | ID: 0
service1_1  | | Inverted regex match: "(^|/)\\.git/"
service1_1  | | Inverted regex match: "(^|/)\\.hg/"
service1_1  | | Inverted regex match: "~$"
service1_1  | | Inverted regex match: "\\.swp$"
service1_1  | | Inverted regex match: "\\.#"
service1_1  | | Inverted regex match: "(^|/)#.*#$"
service1_1  | | Inverted regex match: "(^|/)\\.DS_Store$"
service1_1  | | Regex match: "(\\.go$|go\\.mod)"
service1_1  | | Command: [go run main.go]
service1_1  | +---------
service1_1  | 
service1_1  | [00] Starting service
service1_1  | [00] service started

and

$ docker-compose up service2
Starting 5124_service2_1 ... done
Attaching to 5124_service2_1
service2_1  | Globals set at commandline
service2_1  | | --regex (-r) '[(\.go$|go\.mod)]' (default: '[]')
service2_1  | | --start-service (-s) 'true' (default: 'false')
service2_1  | | --verbose (-v) 'true' (default: 'false')
service2_1  | +---------
service2_1  | Reflex from [commandline]
service2_1  | | ID: 0
service2_1  | | Inverted regex match: "(^|/)\\.git/"
service2_1  | | Inverted regex match: "(^|/)\\.hg/"
service2_1  | | Inverted regex match: "~$"
service2_1  | | Inverted regex match: "\\.swp$"
service2_1  | | Inverted regex match: "\\.#"
service2_1  | | Inverted regex match: "(^|/)#.*#$"
service2_1  | | Inverted regex match: "(^|/)\\.DS_Store$"
service2_1  | | Regex match: "(\\.go$|go\\.mod)"
service2_1  | | Command: [go run main.go]
service2_1  | +---------
service2_1  | 
service2_1  | [00] Starting service
service2_1  | [00] service started

so I think it's working correctly.

Let me know if you get a chance to try the build. Note it won't auto-update to a new release so you'll eventually have to download a new build manually.

Thanks again for the clear repro steps -- it was appreciated!

(Edit: fixed the link!)

[qhenkart]

@djs55 I'd love to test it out, but I can't access the link. I get an. oauth requirement asking that I authenticate with an @docker.com email

Thank you so much for the quick turn around and the detailed explanation!

[djs55]

@qhenkart sorry for the internal link! I've updated the link to point to the Docker.dmg file: https://desktop-stage.docker.com/mac/preview/50831/Docker.dmg

[qhenkart]

@djs55 works great! My entire environment is back online and very efficient. Thank you! How will I know when an official update will include these changes?

[djs55]

@qhenkart thanks for the confirmation! When the changes are merged and released the release notes will reference this ticket. We'll try to ping you and close the ticket when the update becomes available. Thanks again for the clear repro steps.

[jbowens]

Hi @djs55, I think we're seeing something similar on cockroachdb/cockroach#57192, which as far as I can tell, is not fixed by the preview Docker.dmg you linked up above though it could be user error. The steps to reproduce are from the CockroachDB docker quickstart: https://www.cockroachlabs.com/docs/stable/start-a-local-cluster-in-docker-mac.html

docker network create -d bridge roachnet

docker run -d \
--name=roach1 \
--hostname=roach1 \
--net=roachnet \
-p 26257:26257 -p 8080:8080  \
-v "${PWD}/cockroach-data/roach1:/cockroach/cockroach-data"  \
cockroachdb/cockroach:v20.2.2 start \
--insecure \
--join=roach1,roach2,roach3

docker run -d \
--name=roach2 \
--hostname=roach2 \
--net=roachnet \
-v "${PWD}/cockroach-data/roach2:/cockroach/cockroach-data" \
cockroachdb/cockroach:v20.2.2 start \
--insecure \
--join=roach1,roach2,roach3

docker run -d \
--name=roach3 \
--hostname=roach3 \
--net=roachnet \
-v "${PWD}/cockroach-data/roach3:/cockroach/cockroach-data" \
cockroachdb/cockroach:v20.2.2 start \
--insecure \
--join=roach1,roach2,roach3

docker exec -it roach1 ./cockroach init --insecure

Typically one or two of the CockroachDB processes will exit, panicking because a file it just wrote no longer exists. If I disable gRPC FUSE file sharing, everything is smooth sailing.

[djs55]

@jbowens thanks for the example-- this seems to go wrong for me too (although I'm unfamiliar with cockroachdb):

I201215 10:27:11.650929 1792 kv/kvserver/stores.go:255 ⋮ [n2] wrote 2 node addresses to persistent storage
F201215 10:27:12.970435 2053 vendor/github.com/cockroachdb/pebble/internal/base/filenames.go:145 ⋮ [n2] ‹000014.sst›:
open ‹/cockroach/cockroach-data/000014.sst›: no such file or directory

I think this is a different kind of failure than the other on the ticket, since it doesn't seem dependent on containers starting or stopping. I suspect it's an issue with cockroachdb attempting to perform some atomic operations on the filesystem and discovering the filesystem semantics aren't 100% correct.

As a workaround (and a performance optimisation) could you try using a docker volume for the database files? Something like

docker volume create roachdb

and then

docker run -d \
...
-v roachdb/roach1:/cockroach/cockroach-data \
...

The data will still be persistent but it will be stored in a native Linux filesystem. This will avoid the problem with the filesystem semantics and also improve performance, since the database backend I/O will not need to be forwarded to the host. It's still possible to access the files on the volume via containers e.g. docker run -it -v roachdb:/roachdb alpine sh (or alpine tar if you want to back it up). Let me know if that helps at all.

Thanks again for the report -- I'll see if I can figure out what's going on with the missing file.

[jbowens]

@djs55 Thanks for the workaround and for looking into it! I thought it might be related to the three containers started in sequence and that the file path on the container side is the same in each. I don't believe I've ever seen the first container's process encounter missing files, which might be another hint.

I'll try the docker volume today, thanks!

[knz]

perform some atomic operations on the filesystem and discovering the filesystem semantics aren't 100% correct.

The issue seems to be more about the ordering of operations than atomicity.
Any idea why this is an issue now where it wasn't an issue before?

[qhenkart]

@djs55 this bug was reintroduced in 3.0.3. following the same walkthrough will present the same bug. Should I make a new ticket?

[stephen-turner]

Apologies. We're fixing it again now. I'll reopen this ticket.

[stephen-turner]

Reopen until the fix has been released in Docker Desktop.

[stephen-turner]

This is fixed again in 3.0.4.

[docker-robott]

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