moby: Windows docker -f doesn't follow instantly
BUG REPORT INFORMATION
Description
Windows docker -f doesn’t follow instantly as expected. Most the times It just outputted the history logs and stuck there , seldom it outputted new logs every one minute. This happens ONLY to Windows docker.
Steps to reproduce the issue:
1.
docker run -d --name=log-tester microsoft/windowsservercore powershell while ($true) {$d=Get-Date; write-host 'Time is:' $d; Sleep 1}
2.
docker logs -f log-tester
Describe the results you received: Logs didn’t get printed every second. Instead, only history logs were outputted but new logs either didn’t printed (most testcases) or printed in a batch every one minute (in very few testcases)
Describe the results you expected: logs should be outputted in stream instantly. In this particular testcase, logs should get printed every second.
Output of docker version:
C:\Users\Administrator>docker version
Client:
Version: 1.14.0-dev
API version: 1.26
Go version: go1.7.3
Git commit: f93c04d
Built: Sat Dec 17 15:16:54 2016
OS/Arch: windows/amd64
Server:
Version: 1.14.0-dev
API version: 1.26
Minimum API version: 1.24
Go version: go1.7.3
Git commit: f93c04d
Built: Sat Dec 17 15:16:54 2016
OS/Arch: windows/amd64
Experimental: false
Output of docker info:
C:\Users\Administrator>docker info
Containers: 8
Running: 3
Paused: 0
Stopped: 5
Images: 25
Server Version: 1.14.0-dev
Storage Driver: windowsfilter
Windows:
Logging Driver: json-file
Plugins:
Volume: local
Network: l2bridge l2tunnel nat null overlay transparent
Swarm: inactive
Default Isolation: process
Kernel Version: 10.0 14393 (14393.351.amd64fre.rs1_release_inmarket.161014-1755)
Operating System: Windows Server 2016 Standard
OSType: windows
Architecture: x86_64
CPUs: 2
Total Memory: 3.999 GiB
Name: WIN2016-DOCKER-01
ID: MCVH:SYEM:X2IN:FRIH:CYGH:HGLB:PAKZ:XAME:2IE7:PNZF:XTTL:EDLM
Docker Root Dir: C:\ProgramData\docker
Debug Mode (client): false
Debug Mode (server): false
Registry: https://index.docker.io/v1/
Experimental: false
Insecure Registries:
192.168.180.200:5000
127.0.0.0/8
Live Restore Enabled: false
Additional environment details (AWS, VirtualBox, physical, etc.): VMware Workstation 12.5.1 Virtual Machine
About this issue
- Original URL
- State: closed
- Created 7 years ago
- Reactions: 6
- Comments: 25 (18 by maintainers)
https://github.com/moby/moby/blob/aba2735e3fe66333ac1064bed3b476f30b1d1c00/daemon/logger/loggerutils/logfile.go#L644 Changing to filenotify.NewPollingWatcher() allowed the logs to follow 😃 Currently we fallback to polling watcher if fsnotify watcher has errors. Maybe for Windows, we can use polling watcher by default. I can make the change if this is approved
Happens on OSX too
I looked into issue to root cause.
The issue is with the Windows file caching where the file data is lazily written to the disk. The docker logs with follow flag is based on a file watcher on the docker log file. As Windows is not committing the bytes to the disk, there is no system notifications for file update and hence the watch signals are not firing at all. I have verified that certain actions like reopening the log file either manually or by issuing docker logs is triggering the writing to disk and fires the watch signal and there by flushes the logs on the follow stream. Other actions that trigger the logs on follow stream are, refresh the explorer of the container folder, opening the log file in the notepad etc. The file watcher is based on the underlying OS ReadDirectoryChangesW() system call which is some how not detecting the writes to the cache. It is detecting writes to the disk. The same behavior is observed by using the .net FileSystemWatcher class.
Some possible options to workaround this issue with Windows are
Any thoughts? @johnstep @thaJeztah
A quick testing with filenotify.NewPollingWatcher() showed that the write events are fired. So this watcher based on polling should work