Not syncing both directions suddenly

[nurtext]

Error/Feature Requestion/Docs

All docker container are up, but not syncing between /host_sync and /app_sync. /app_sync to /host_sync is working.

Docker Driver

d4m

Sync strategy

native_osx

docker-compose.yml

version: '2'

services:
    api:
        container_name: api
        image: api
        build: .
        ports:
            - 8888:80
        volumes:
            - ./app:/srv/api/app
            - ./bin:/srv/api/bin
            - ./src:/srv/api/src
            - ./tests:/srv/api/tests
            - ./web:/srv/api/web
            - ./vendor:/srv/api/vendor
        environment:
            DATABASE_HOST: "127.0.0.1"

docker-compose-dev.yml

version: '2'

services:
    api:
        volumes:
            - api-app-sync:/srv/api/app:nocopy
            - api-bin-sync:/srv/api/bin:nocopy
            - api-src-sync:/srv/api/src:nocopy
            - api-tests-sync:/srv/api/tests:nocopy
            - api-web-sync:/srv/api/web:nocopy
            - api-vendor-sync:/srv/api/vendor:nocopy

volumes:
    api-app-sync:
        external: true

    api-bin-sync:
        external: true

    api-src-sync:
        external: true

    api-tests-sync:
        external: true

    api-web-sync:
        external: true

    api-vendor-sync:
        external: true

docker-sync.yml

version: '2'

options:
    verbose: true

syncs:
    api-app-sync:
        src: './app/'

    api-bin-sync:
        src: './bin/'

    api-src-sync:
        src: './src/'

    api-tests-sync:
        src: './tests/'

    api-web-sync:
        src: './web/'

    api-vendor-sync:
        src: './vendor/'

docker ps output

CONTAINER ID        IMAGE                            COMMAND                  CREATED             STATUS              PORTS                            NAMES
72ee4eb5a02b        api                              "docker-php-entryp..."   2 minutes ago       Up 2 minutes        9000/tcp, 0.0.0.0:8888->80/tcp   api
7ec87ccaa84f        eugenmayer/unison:hostsync_0.2   "/entrypoint.sh su..."   15 minutes ago      Up 2 minutes        500/tcp                          api-vendor-sync
de22a140b897        eugenmayer/unison:hostsync_0.2   "/entrypoint.sh su..."   16 minutes ago      Up 2 minutes        500/tcp                          api-web-sync
b1d749f9c992        eugenmayer/unison:hostsync_0.2   "/entrypoint.sh su..."   16 minutes ago      Up 2 minutes        500/tcp                          api-tests-sync
62d9a55979a3        eugenmayer/unison:hostsync_0.2   "/entrypoint.sh su..."   16 minutes ago      Up 2 minutes        500/tcp                          api-src-sync
0af351c80ed8        eugenmayer/unison:hostsync_0.2   "/entrypoint.sh su..."   16 minutes ago      Up 2 minutes        500/tcp                          api-bin-sync
45d5f50d0659        eugenmayer/unison:hostsync_0.2   "/entrypoint.sh su..."   16 minutes ago      Up 2 minutes        500/tcp                          api-app-sync

docker-sync list output

      ok  Found configuration at /Users/cedric/api/docker-sync.yml

api-app-sync On address : api-bin-sync On address : api-src-sync On address : api-tests-sync On address : api-web-sync On address : api-vendor-sync On address :

OS

macOS 10.11.6

[michaelbaudino]

Hi @nurtext,

First, thanks for the detailed description 👍

Could you please add the output of docker logs api-web-sync ? (or whatever *-sync container you're trying to sync files with)

[codycraven]

I've ran into this intermittently since going to native_osx. There is nothing visible in docker logs that indicates a problem, however I suspect it stems from timestamps being out of sync between the host and the container.

In my local configs I'm now applying volumes to my containers that use docker-sync volumes like so:

    api:
        volumes:
            - /etc/localtime:/etc/localtime:ro # Fix TZ issues w/ docker-sync?
            - api-app-sync:/srv/api/app:nocopy
            - api-bin-sync:/srv/api/bin:nocopy
            - api-src-sync:/srv/api/src:nocopy
            - api-tests-sync:/srv/api/tests:nocopy
            - api-web-sync:/srv/api/web:nocopy
            - api-vendor-sync:/srv/api/vendor:nocopy

I don't know how to reproduce the issue so I'll need to see overtime if this "fix" prevents the state from occurring.

Update: This doesn't work.

[EugenMayer]

@codycraven so the issue was your time? (does it work now?)

since timestamp compares are used to detect if a file has been changed, that could be cause

[codycraven]

@EugenMayer thus far I have not encountered sync failing since implementing this earlier today.

My PR for my team was merged about an hour ago, so I should know by mid-week next week if this solved it (most of our team is traveling tomorrow and Monday is a holiday so I won't have a good sample until then).

[EugenMayer]

Very interesting, lets see how this turns out @codycraven - keep us posted. We do handle timezones: https://github.com/EugenMayer/docker-sync/blob/master/lib/docker-sync/sync_strategy/native_osx.rb#L86 in the sync container.

So if your app container does not do that and your TZ differs, that is a good source for issues. This leaves us with the question, how we could solve this for the docker-sync user - seems like we can only do that by documentation?

[michaelbaudino]

Ho, yes, this is very confusing 😕

→ date && docker exec frontend-sync date && docker-compose run frontend date
Fri May 26 10:52:41 CEST 2017
Thu May 25 20:32:38 CEST 2017
Thu May 25 18:33:07 UTC 2017

On MacOS Sierra 10.12.4.

[EugenMayer]

Thats a very common docker issue its basically there always, just not always visible. but since we compare timestamps on 2 different containers, that happens

[azamat163]

Hi guys! I also encountered such a problem, but solved it with the help of the Mac OS update to 10.12.5. It helped me.

[EugenMayer]

That is pretty odd, how does this get fixed by an Mac OS update .. were did you had this hint from? Which OS did you had before, El Capitan?

[azamat163]

Yes,10.11.4

[EugenMayer]

@codycraven are you / your collegues on El Capitan?

[codycraven]

@EugenMayer I'm on Sierra. Looking at the native_osx.rb Docker run command is what gave me the idea to sync the time zone. Going a step further (if this doesn't resolve it) a colleague had the idea to sync the containers (VM) and host with NTP.

[nurtext]

Same timezone on host and all docker containers, problem still remains:

> date && docker exec api date && docker exec api-app-sync date
Mon May 29 11:39:34 CEST 2017
Mon May 29 11:39:34 CEST 2017
Mon May 29 11:39:34 CEST 2017

Logfile:

> docker logs api-app-sync
2017-05-29 11:29:05,061 CRIT Supervisor running as root (no user in config file)
2017-05-29 11:29:05,062 WARN Included extra file "/etc/supervisor.conf.d/supervisor.daemon.conf" during parsing
2017-05-29 11:29:05,097 INFO RPC interface 'supervisor' initialized
2017-05-29 11:29:05,097 CRIT Server 'unix_http_server' running without any HTTP authentication checking
2017-05-29 11:29:05,097 INFO supervisord started with pid 1
2017-05-29 11:29:06,100 INFO spawned: 'unison' with pid 27
2017-05-29 11:29:07,271 INFO success: unison entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)

Edit: Maybe this is another puzzle piece, but I doubt so: I recently moved from ubuntu:trusty-20170214 to php:7.1-fpm-alpine. Previous setup was working fine with native_osx sync

[michaelbaudino]

I discovered something that may help: my team leader (who's running the exact same Docker Compose and Docker Sync config than I do) is impacted by this problem and using @codycraven's workaround to share /etc/localtime fixed the issue for him (thanks for that, @codycraven, btw 🎩 ).

The only difference I can think of is that my containers and host seem totally desynchronized while his containers seem to have more consistent times:

→ date && docker exec frontend-sync date && docker-compose run frontend date
Mon 29 May 2017 16:49:06 BST
Mon May 29 16:49:06 BST 2017
Mon May 29 15:49:18 UTC 2017

[EugenMayer]

@michaelbaudino are you using any "--prefer newer" syntax?

[michaelbaudino]

Nope: we use the default. Here is our exact config: https://gist.github.com/michaelbaudino/1c83c253794e5b6bd0cc8fc47c1b4951

[EugenMayer]

@michaelbaudino what about OS differences, are you running Sierra and he is running El Capitan?

Still trying to understand the pattern here

[michaelbaudino]

Nope, we are both on Sierra 10.12.4.

Actually, we were, because I upgraded to 10.12.5 about 5 minutes ago 😄

[codycraven]

@michaelbaudino when you added the TZ fix had you destroyed your old containers/volumes before bringing them back up or just stopped them?

[codycraven]

I just ran into this again on my machine. The time is synchronized perfectly so I continued digging.

I checked the file I modified in my host within the docker-sync container and was astounded to find that the file within /host_sync/ was the old version that does not match what is on my host.

Based on this, it appears that the volume mount into the docker-sync container is somehow breaking.

Update This appears to be a false failure. I created a copy of my project in a new directory and ran it while debugging something. I failed to properly clean up afterwards as my sync container's bind mount was pointed at my copied directory instead of the one I was working on.

[masev]

I have exactly the same issue. I updated to the last version of Sierra and tried the hack to share localtime with no luck ...

Tell me if I can help you by giving more info.

[EugenMayer]

Ok so what we have right now is that:

a) the timezone does matter - but not for everyone.

b) Sierra or el Capitan are not significant also - both could have this issue

c) there is no pattern in the project configuration or anything too special

---

Bottom line is, that we need to draw a tighter circle around the issue, it's far too broad right now. Suggestions:

I) we write a wiki guide on how to debug issues or gather information - this is overdue anyway. So compare host/app any, check /tmp/unison . How to enter a snyc container, how to manually restart the inner unison project

II) we gather information from all people having this issue and all not having this one and see, were we have important differences - I would suggest a Google spreadsheet for this probably

Anybody willing to help bootstrapping this?

[nurtext]

@EugenMayer Since I'm depending upon a working docker-sync for the next release of my project, I'm willing to help. Tell me what's up next and I'll do my best.

[codycraven]

I'm in, I can start work on a debug guide tomorrow (or contribute to it if someone else starts one).

[nurtext]

Some more debugging for you:

Cleaned up everything: intermediate containers, docker-sync-stack, containers, etc. No change at all.

Changed a file on host: no result.

1. docker exec -it api-app-sync /bin/bash
2. ps aux
3. kill -9 $PID_OF_UNISON

Changed file got recognized:

Contacting server...
Looking for changes
Reconciling changes
changed  ---->            Resources/views/root.html.twig
Propagating updates
UNISON 2.48.4 started propagating changes at 09:52:26.44 on 31 May 2017
[BGN] Updating file Resources/views/root.html.twig from /host_sync to /app_sync
[END] Updating file Resources/views/root.html.twig
UNISON 2.48.4 finished propagating changes at 09:52:26.45 on 31 May 2017
Saving synchronizer state
Synchronization complete at 09:52:26  (1 item transferred, 0 skipped, 0 failed)
Looking for changes

Tried to change a file afterwards: Same behavior and no more changes got recognized.

Result of ps aux:

PID   USER     TIME   COMMAND
    1 root       0:00 {supervisord} /usr/bin/python /usr/bin/supervisord
   16 root       0:00 tail -F /tmp/unison.log
   24 root       0:00 /bin/bash
   68 root       0:00 tail -f unison-stdout---supervisor-T9b2x9.log
   69 root       0:00 /bin/bash
   75 root       0:00 unison -prefer /host_sync -numericids -repeat watch -auto -batch /host_sync /app_sync -logfile /tmp/unison.log
   76 root       0:00 /usr/local/bin/unison-fsmonitor
   79 root       0:00 ps aux

[EugenMayer]

@nurtext @codycraven great. First - lets put in the guide in place, since that will be the first thing to ensure we are all doing reproductionable steps and are all on the same way - the only way to really find the actual issue pattern. Could you help with https://github.com/EugenMayer/docker-sync/issues/415

@codycraven if you start the guide, i join you adding what i know about the containers, images, supervisord, debugging and things like that - please all chats about this further in https://github.com/EugenMayer/docker-sync/issues/413 - i created a first outline of what we should do and why, feel free to actually be bold in any sense - i just emptied my mind there

@michaelbaudino Mr. Spec, anything we could do with spec to formalize testing? I guess we would need to start with the bash thingy and it will take longer then we want to get this thing on the line, right? Created https://github.com/EugenMayer/docker-sync/issues/414 for this - lets see

Please try to spread the comments for the topics across the outer issues - the only thing we should do in this tickets is giving analysis results and give people a spot to "i am also effected" - and also advertise debugging steps / new things we want to know to get it fixed.

Lets get our hands dirty on this - i see that is a serious issue here and we need to get this done ASAP, but i will need assistance to get it into a timeframe it suits you.

[nurtext]

Some more debugging according according to the guide in the wiki…

Host Sync working:

> diff -q "$DEBUG_DOCKER_FILE" <(docker exec "$DEBUG_DOCKER_SYNC" cat "/host_sync/$DEBUG_DOCKER_FILE")
> 

App Sync not working:

> diff -q "$DEBUG_DOCKER_FILE" <(docker exec "$DEBUG_DOCKER_SYNC" cat "/app_sync/$DEBUG_DOCKER_FILE")
Files Resources/views/root.html.twig and /dev/fd/11 differ

Log is empty:

> docker exec "$DEBUG_DOCKER_SYNC" tail -n70 /tmp/unison.log
> 

Missing directory:

> docker container inspect --format '{{(index .Mounts 1).Source}}' "$DEBUG_DOCKER_SYNC"
/var/lib/docker/volumes/api-app-sync/_data
> docker exec "$DEBUG_DOCKER_SYNC" ls -la /var/lib/docker/volumes/api-app-sync/_data
No such file or directory
> ls -la /var/lib/docker/volumes/api-app-sync/_data
No such file or directory

Will now try to reset d4m…

[EugenMayer]

No log means no unison is actually starting @nurtext, please see the supervisor logs for the reasons that this does not actually work or try to restart unison:

supervisorctl restart unison

[nurtext]

@EugenMayer Resetting d4m helped. Sync is working again. I guess this won't help finding the real cause of the issue, but here's a clue:

Before resetting d4m:

> docker container inspect --format '{{(index .Mounts 1).Source}}' "$DEBUG_DOCKER_SYNC"
/var/lib/docker/volumes/api-app-sync/_data

After resetting d4m:

> docker container inspect --format '{{(index .Mounts 1).Source}}' "$DEBUG_DOCKER_SYNC"
/Users/cedric/Git/Project/api/app

This is the correct path indeed and I don't know why Docker was thinking that /var/lib/docker/... was the correct path.

[EugenMayer]

the latter path is the local path, i guess the one you posted first is from the xhyve VM - but yes, that one is odd and still interesting. @nurtext you actually have been written host_sync is working, right - that makes this even less likely, since that wrong host paths would result in host_sync being not synced ..

The other way is, that the files are synced but due to a symlink or wrong path above fs-events have not been triggered. Still pretty dark

[nurtext]

@EugenMayer Very strange indeed since app_sync -> host_sync was working a few days ago as I started this topic. Never tested again since then…

However I guess fs-events weren't triggered, thus no sync has been made. This could be an explanation for the host_sync -> app_sync working after killing / restarting unison: https://github.com/EugenMayer/docker-sync/issues/410#issuecomment-305114984

[jenswegar]

Experiencing this same issue it seems.

System: macOS Sierra 10.12.5 docker sync 0.4.6 Docker for Mac 17.03.1-ce-mac12 (17661) [newest version at time of writing]

host sync seems to work (no output from command below):

> diff -q "$DEBUG_DOCKER_FILE" <(docker exec "$DEBUG_DOCKER_SYNC" cat "/host_sync/$DEBUG_DOCKER_FILE")
> 

app sync seems to fail:

> diff -q "$DEBUG_DOCKER_FILE" <(docker exec "$DEBUG_DOCKER_SYNC" cat "/app_sync/$DEBUG_DOCKER_FILE")
> Files web/themes/custom/xyz_2017/css/style.css and /dev/fd/63 differ

log is empty,even after file change on host:

> docker exec "$DEBUG_DOCKER_SYNC" tail -n70 /tmp/unison.log
> 

running docker-sync clean, rebuilding my local images for the affected project (docker-compose build) and restarting Docker for Mac seems to have corrected the issue for now.

[codycraven]

Interesting tidbit - I had two co-workers run into this problem on two different days. The ultimate solution ended up being a down, docker-sync clean, shut down, then re-start and up.

I'm guessing we're running into some sort of limit where the Unison process can no longer track changes. I'm trying to learn more about Unison to figure out what it could be.

[jenswegar]

This might be of interest: Today the sync started to act up again (stopped to sync from host to app), but this time all I did was restart the Docker for Mac daemon. However, when I just tried to use the "restart" button in the Docker for Mac toolbar menu, the restart just hanged itself (never completed). I had to use Docker for Mac menu -> Preferences -> Daemon -> Advanced and there the "reset your daemon settings" option for the restart to go through.

So maybe the issue with the sync is that some process hangs itself in the background. Does native_osx sync use rsync somehow? Because I've heard from colleagues who work with backups in the Qnap world that rsync has a tendency to go ape shit if synching very large amounts of files (what large amounts means remained unclear still)

[donnykurnia]

@jenswegar native_osx using unison. Docker for Mac indeed can hang while restarting, but it's not only because of docker-sync. If your Mac runs up the resources, Docker for Mac will be swapped out from memory and this will cause the daemon getting slower. See the resources usage using Activity Monitor.

[eggie5]

this was just happening to me post native-mac sync strategy update: sync was only working 1-way. The fix for me like someone noted above was: docker-sync clean

[hyviquel]

I'm noticing similar problems as well on my macbook since I'm using native-mac sync strategy... Let me know if you want me to test anything.

[Cethy]

I, too, seems to have this problem regularly on osX (macbook), seemingly related to a memory usage issue.

I managed to unblock it with a simple "manual" docker-sync sync.

[michaelbaudino]

Just to add some content to the current thoughts, this bug bit me again yesterday while setting up our development environment on a new team member MacOS Sierra 10.12.5 (with Docker 17.06.0-ce): synchronization (using native_osx) was simply not working in any way (neither from container to host, nor from host to container).

Running docker-sync stop; docker-sync clean; docker-sync start did not fix it (we tried twice). Restarting the Docker engine did fix it, though 🤷‍♂️

Anyway, the real interesting this I noticed was that changes on host (made using Visual Studio Code and nano with the same results) were successfully propagated to /host_sync but not to /app_sync. I tried to monitor the FS events (using inotify -r -m /host_sync from inside the sync container) and I was surprised to see that changes on host were correctly applied in /host_sync but without any FS event being triggered 😲 (which explains why Unison did not see anything and thus did not propagate the changes to /app_sync).

I know that FS events in osxfs is rather incomplete, but that's not the problem here: we were using a (supposed to be) supported FS event (modification event).

I also saw docker/for-mac#681 that might be related and is in progress to be fixed by moby/moby#33048 (and its implementation in moby/moby#33375) which I find very promising 😊.

Final note: I cannot ask my team members to stay in a state where "the bug can be replicated but they cannot work" obviously, so I was happy when it magically auto-solved by restarting the Docker engine and thus I still do not know how to reproduce consistently or what is the cause factor 😞

[EugenMayer]

@michaelbaudino thank you for finally confirming what i was suggesting all the times.

Since all people reported a running host sync and all people reported that restarting the stack does not help AND restarting the inner unison does not help, it was the only option left, failing FS-Events on the linux container, not properly propagated when syncing with OSXFS.

great you found an actual issue, i will try to join the discussion there.

Since a mac restart is actually not needed, but a docker-engine restart seems to fix it, it is a plain docker for mac issues, no strings attached.

That at least for now is an outcome - but also one we cannot really influence/autodetect and quick fix. We could put some effort into actually trying to do test-changes in a special host mount, like a health check container, and if we do not see any events, we inform the user, but that is a huge amount of effort and will just not fix it, but rather make it transparent.

Not sure how we could proceed here - its clear that this bug does only happen for native_osx, since the unison strategy does not rely on OSXFS and its FS events, but rather on OSX fsevents, with the huge drawback in performance during watching the codebase.

[michaelbaudino]

Well, fixing Docker For Mac is the very essence of Docker Sync, isn't it? 😜

[huersch]

sorry for opening another issue. I didn't recognise this one.

I can validate that restarting docker for mac at least temporally fix this issue and also I do have different time zones on the docker-compose container compared to the host and sync container.

Sadly we can reproduce the issue on several devices. I have the feeling that it always works the first time you start a sync.

If I can do anything of help, please let me know. Since several colleagues have this problem and this is pretty crucial for us, we will investigate further and will let you know if we find something new.

[michaelbaudino]

@huersch Thanks for your report.

Something that would indeed help would be to find the factor that lets us reproduce the bug on demand. So far, we've identified some symptoms, but not the reproduction factor 😕

[EugenMayer]

That won't be easy, since it might be hidden in the filesystem implementation of OSXFS. We might play around with ulimit values, since I expect this bug to correlate with the amount of file changes per time span. One of the common preconditions to force the bug is, changing branches or generating assist with gulp and alikes. Also i smell an indication that the performance of your Mac does influence the probability .. it seems higher performance lets you avoid it.

Combining that means, that we might see a queue which fills up with change events, e.g. in OSXFS, when this one is not worked through fast enough, we hit limits and processesing of the queue stalls completely, probably to e.g. to many open file handles. Rrstarting containers and docker sync does.not help as expected, since the queue is part of the osxfs layer between xhyve and osx... Rrstarting d4m helps since this hard flushes the queue.

This issue might in fact be related to the xhyve VM and limits in there. We need to find a way to analyze the VM logs and fsstats when the issue happens

[huersch]

Do you think changing sync strategy to rsync would fix it temporally? We just need to sync files from host to app.

[EugenMayer]

It will fix one thing and introduce a LOT more CPU load on the host due to the fswatch watchers - its a tradeof

[mf-lit]

One of the common preconditions to force the bug is, changing branches or generating assist with gulp and alikes.

Yes, these are two circumstances where we are definitely seeing the problem. I can reliably reproduce the issue by leaving a loop running that keeps checking out different branches, meanwhile I'll start changing some test files.

[btaylor-ihr]

Eugen asked me to pass on that restarting my Docker appears to have fixed the issue. I jumped on https://github.com/EugenMayer/docker-sync/issues/452 and said I have the same issue

My docker-sync was dying at least once every day. I was traditionally destroying the volume and syncing again with a fresh volume, but that took anywhere up to 40 minutes to complete. After his tip about restarting Docker, I gave it a shot. I have Docker Community Edition 17.06.0-ce-mac19 and I run Sierra (10.12.6). Not sure if that makes any difference.

My docker-sync.yml

version: "2"

options:
  compose-file-path: 'docker-compose.yml'
  compose-dev-file-path: 'docker-compose-osx.yml'
syncs:
  lapis-unison-sync:
    src: '.'
    sync_strategy: 'native_osx'
    sync_excludes: ['.git', '.github', '.idea', '.gitignore', 'node_modules', '.DS_Store']
    sync_userid: ${WWW_DATA_USER_ID}

I give 4 CPUs and 2.0GB to Docker. My host machine has 16GB of memory, and a 2GHz intel Core i5 on the 13" 2016 two thunderbolt 3 version of Mackbook Pro. I can't say for sure how many files I sync, but it's in the early thousands

[chris-aeviator]

I can confirm experiencing the same issue similar to https://github.com/EugenMayer/docker-sync/issues/410#issuecomment-325578867 . My sync is dying mostly multiple times per day, sometimes not at all.

I am syncing a Drupal 8 environment with roughly 64.000 files with all dependencies - as long as everything is fine - everything is fine :)

I realized that restarting Docker / Docker-Sync helps sometimes but is not a guarantee. Today I was experiencing multiple "hickups" again and couldnt solve the issue by restarting, but strangely after about 5-10 Min the sync happened without doing anything.

To all others experiencing the issue, try to just wait and look into the log docker-sync logs , everytime I had the dying sync it was hundreds of twig cache files (Drupal related) beeing responsible for the delay.

[zedtux]

I'm now facing the same issue: The sync is working and after a while it simply stops.

Looking around in the sync volume container, I can see the files well synchronised on the /host_sync folder, but not in the /app_folder (this is true for file creation/editing/deletion). The top command shows me the normal processes running, no high load, and inotify (with the alpine image, inotify is not available, so I used inotifyd and inotifywatch, but they are blind).

To solve this, I have to stop the stack, run a docker-sync-stack clean and docker-sync-stack start.

I'm trying to read more about unison in order to check who to get more information from it, but for now I can't figure out why is that happening.