Files on Windows mount volume have wrong timestamp while being read

[bechhansen]

• I have tried with the latest version of my channel (Stable or Edge)
• I have uploaded Diagnostics
• Diagnostics ID:

Expected behavior

When accessing files located on a Windows mount from within a container, I expect to get the correct access, modify and change timestamps of the file.

E.g. when calling the command stat on a file, I expect something like:

File: 'test.txt'
Size: 59 Blocks: 0 IO Block: 4096 regular file
Device: 5bh/91d Inode: 8 Links: 1
Access: (0755/-rwxr-xr-x) Uid: ( 0/ root) Gid: ( 0/ root)
Access: 2020-01-22 14:19:15.999862300 +0000
Modify: 2020-01-22 14:41:56.241291700 +0000
Change: 2020-01-22 14:17:00.233181300 +0000

Actual behavior

When calling stat on a file, while it is being read from another command prompt I get this result:

File: 'test.txt'
Size: 59 Blocks: 0 IO Block: 4096 regular file
Device: 5bh/91d Inode: 8 Links: 1
Access: (0755/-rwxr-xr-x) Uid: ( 0/ root) Gid: ( 0/ root)
Access: 1970-01-01 00:00:00.000000000 +0000
Modify: 1970-01-01 00:00:00.000000000 +0000
Change: 1970-01-01 00:00:00.000000000 +0000

The timestamp seems to be undefined.

We have see this behavior on two individual Windows computers efter updating Docker today.

The bug makes our Wildfly server auto deploy our application over and over again, as the server think our deployable artifacts has changed.

Information

• Windows Version:
  Windows 10

• Docker Desktop Version:
  2.2.0.0 (42247)

• Are you running inside a virtualized Windows e.g. on a cloud server or on a mac VM:
  Hyper-V

Steps to reproduce the behavior

I have created the issue sometime by doing something like:

1. Create container and access shell by calling:

docker run -it --name test -v C:/Windows/Temp:/opt --rm alpine /bin/ash

2. Create new file on volume from within the container by calling:

echo Testing > /opt/test.txt

3. See timestamps on file by calling:

stat /opt/test.txt

4. Continually read file by calling:

while :; do cat /opt/test.txt; done

5. Open a fresh shell on your Windows computer and connect to the running test container by doing:

docker exec -ti test /bin/ash

6. See timestamps on file in the new shell by calling:

stat /opt/test.txt

See that timestamps are:
Access: 1970-01-01 00:00:00.000000000 +0000
Modify: 1970-01-01 00:00:00.000000000 +0000
Change: 1970-01-01 00:00:00.000000000 +0000

[simonferquel]

very likely to be the same root issue as with #5528

[stephen-turner]

Confirmed, I reproduced this on my machine.

[stephen-turner]

I have reproduced this by doing the while loop and then the stat in the same terminal, no need for a second terminal. However, I can't reproduce it reliably with either recipe. Maybe 1 in every 3 or 4 times.

[joelharkes]

I'm having lots of issues that file changes in mounted volumes are not detected (both in php and nodejs development), i guess this is the root cause as well.

[stephen-turner]

Update: we've now managed to make a minimal repro case for this and we're working on finding the root cause. Interestingly, turning off file caching doesn't seem to fix it as we assumed it would.

[stephen-turner]

We have a new private build which (we believe) fixes this bug. https://download-stage.docker.com/win/stable/42579/Docker%20Desktop%20Installer.exe. Please try it and let us know how you get on.

[joelharkes]

@stephen-turner great work i will try it now and report back if i have any issues.
Do i need to completly uinstall docker first? (and from private version updating to new production version?)
what is the best practise in this case?

[stephen-turner]

No, just running the installer should upgrade cleanly (in both cases).

[bechhansen]

Hi @stephen-turner

First of all, thank you for the quick effort.
I have tried the new build a few times, but unfortunately the issue is still there.

For the new build I have not been able to see the wrong timestamp anymore, when using the stat command.
However the Wildfly auto deploy functionality still see files as changed, even though I have not touched them.

This makes the Wildfly application server redeploy my artifacts in an infinite loop.

[stephen-turner]

Thanks for retesting it, @bechhansen. It's hard to tell whether that's the same issue or not from the description. If you were able to produce a set of repro steps, that would be very helpful.

[bechhansen]

I think I have found the Java code for the deployment scanner in Wildfly.
https://github.com/wildfly/wildfly-core/blob/master/deployment-scanner/src/main/java/org/jboss/as/server/deployment/scanner/FileSystemDeploymentService.java

I think this is the method that detects if a files has changed and should be redeployed.
I can see it also uses the timestamp for the parent folder. Have you verified that folder timestamps are also correct and stable?

private long getDeploymentTimestamp(File deploymentFile) {
        if (deploymentFile.isDirectory()) {
            // Scan for most recent file
            long latest = deploymentFile.lastModified();
            for (File child : listDirectoryChildren(deploymentFile)) {
                long childTimestamp = getDeploymentTimestamp(child);
                if (childTimestamp > latest) {
                    latest = childTimestamp;
                }
            }
            return latest;
        } else {
            return deploymentFile.lastModified();
        }
    }

I will try to find the time to build a Docker Image with a Java code snippet using this method to reproduce the issue.

[stephen-turner]

@bechhansen Thanks. It would be interesting to know whether you see incorrect file or folder timestamps inside the container when this issue occurs.

[bechhansen]

@stephen-turner

I have created a small Java application that is using the aforementioned method.
The code can be found here:
https://github.com/bechhansen/docker-win-5543

The image is build and pushed to Docker Hub. It should be able to run by doing:

docker run -v c:/temp:/tmp/test bechhansen/5543:latest

I have not personally tested it on 2.2.0.1, as I have deadlines preventing me from uninstalling/installing Docker. Maybe you can have a go?

[stephen-turner]

I don't see any problems running that even on 2.2.0.0. What is the directory structure of your project? If you have nested directories mounted inside different containers, you are probably seeing #5530.

[joelharkes]

For me everything seems fixed. Thanks for all the hard work!

[jpetitte]

2.2.0.1 seems to have fixed the saving problems we were seeing in VS Code with remote containers:
microsoft/vscode-remote-release#2256

worked for me.

[bechhansen]

Hi @stephen-turner

I have now had the time to look into this again. You are absolutely right. My application did not reproduce the issue.

I have had another look at the Wildfly deployment code, and I have created another small application I think is reproducing the issue. It is located here:
https://github.com/bechhansen/docker-win-5543/blob/master/Test.java

The application is creating two files, and tries to set the modification timestamp of the second file to be the same as for the first file. Apparently there is an issue with setting the modification time.

I have push the new application as a Docker image under the name

bechhansen/5543:1

If you run the container without using host volume you should see that everything works:

docker run bechhansen/5543:1

But run it using a volume on your Windows host, you should be able to see it fail:

docker run -v c:/temp:/tmp/test bechhansen/5543:1

[bechhansen]

@stephen-turner

Sometimes I actually get an error telling me that the file I'm trying to set modification time for does not exist, even though I have just created it. I don't see this behavior when not using a volume. I think this is also a bug.

Exception in thread "main" java.nio.file.NoSuchFileException: /tmp/test/deployment/1581020630588-2.txt
at java.base/sun.nio.fs.UnixException.translateToIOException(UnixException.java:92)
at java.base/sun.nio.fs.UnixException.rethrowAsIOException(UnixException.java:111)
at java.base/sun.nio.fs.UnixException.rethrowAsIOException(UnixException.java:116)
at java.base/sun.nio.fs.UnixFileAttributeViews$Basic.setTimes(UnixFileAttributeViews.java:93)
at java.base/java.nio.file.Files.setLastModifiedTime(Files.java:2433)
at Test.main(Test.java:26)

If you see the same error, try to run the container a few more times.

[stephen-turner]

@bechhansen Thanks for the repro case. We've released a new version, which I've tested fixes this. You can get it from https://download-stage.docker.com/win/stable/42644/Docker%20Desktop%20Installer.exe. Thanks again for helping us pin down these issues.

[bechhansen]

@stephen-turner

Thank you. I can confirm 2.2.0.2 has fixed the issue.
The Wildfly auto-deployment functionality is again working when using a host volume.

[stephen-turner]

Great, thank you for testing it and confirming.

[stephen-turner]

We have just released 2.2.0.3, which fixes this issue, so closing this ticket. In case any Edge users are watching this ticket, it will be on the Edge channel tomorrow too.

[EricHripko]

I got the update notification for 2.2.0.3 despite being on stable channel. Is this intentional?

[mat007]

@EricHripko yes, 2.2.0.3 is on the Stable channel.

[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