Docker json-file logging driver hangs when rotating files on Windows #39274
Description
Description
Docker json-file logging driver hangs when rotating files on Windows. Once a container gets in hung state, no more log entries are saved for it unless docker or the container is restarted.
PS> Get-EventLog -LogName Application -Source Docker shows the following error messages:
Failed to log msg "" for logger json-file: error removing oldest log file: remove C:\ProgramData\docker\containers\e9b7722458801aadcfdc6f37a7d44c077c36d3680a906a305dad878e9cf6a9ae\e9b7722458801aadcfdc6f37a7d44c077c36d3680a906a305dad878e9cf6a9ae-json.log.1: The process cannot access the file because it is being used by another process.
(REPEATED UNTIL MITIGATED)
Failed to log msg "" for logger json-file: error closing file: close C:\ProgramData\docker\containers\e9b7722458801aadcfdc6f37a7d44c077c36d3680a906a305dad878e9cf6a9ae\e9b7722458801aadcfdc6f37a7d44c077c36d3680a906a305dad878e9cf6a9ae-json.log: file already closed.
The issue does not happen every time but happens quite frequently.
Steps to reproduce the issue:
0. Run a Windows 2019 OS VM with docker using named pipes.
- Run a docker container on the VM which outputs some log entries. Set this container to use json-file logging driver with 1M file size and 2 file-limit.
- Create another docker container which is has the docker named pipe mounted. Run periodic ContainerLogs API call for the container in step 1 in this container.
- Let the setup run until Event log entries start showing the error messages described above. Once this state is reached, no more logs are captured in the json files.
Describe the results you received:
- Container logs stop getting captured on log file rotation.
Describe the results you expected:
- Container logs should not get stuck.
Additional information you deem important (e.g. issue happens only occasionally):
This issue does not occur every time. But it happens very frequently when multiple containers are running on multiple VMs.
Output of docker version:
> docker version
Client:
Version: 18.09.3
API version: 1.39
Go version: go1.10.8
Git commit: 142dfcedca
Built: 02/28/2019 06:33:17
OS/Arch: windows/amd64
Experimental: false
Server:
Engine:
Version: 18.09.3
API version: 1.39 (minimum version 1.24)
Go version: go1.10.8
Git commit: 142dfcedca
Built: 02/28/2019 06:31:15
OS/Arch: windows/amd64
Experimental: false
Output of docker info:
Containers: 4
Running: 4
Paused: 0
Stopped: 0
Images: 4
Server Version: 18.09.3
Storage Driver: windowsfilter
Windows:
Logging Driver: json-file
Plugins:
Volume: local
Network: ics l2bridge l2tunnel nat null overlay transparent
Log: awslogs etwlogs fluentd gelf json-file local logentries splunk syslog
Swarm: inactive
Default Isolation: process
Kernel Version: 10.0 17763 (17763.1.amd64fre.rs5_release.180914-1434)
Operating System: Windows Server 2019 Datacenter Version 1809 (OS Build 17763.316)
OSType: windows
Architecture: x86_64
CPUs: 4
Total Memory: 15GiB
Name: dc48a85165fcf24
ID: KCKO:GJP5:M7R3:IE45:2LVF:FCYR:MOBJ:DFS7:BBV6:L4XV:DRZY:ZA5M
Docker Root Dir: C:\ProgramData\docker
Debug Mode (client): false
Debug Mode (server): false
Registry: https://index.docker.io/v1/
Labels:
Experimental: false
Insecure Registries:
127.0.0.0/8
Live Restore Enabled: false
Additional environment details (AWS, VirtualBox, physical, etc.):
Windows 2019 VM on GCP
Mitigations = restart affected container, or restart docker service on Windows.
docker inspect output on a container which got into this state
> docker inspect e9b
[
{
"Id": "e9b7722458801aadcfdc6f37a7d44c077c36d3680a906a305dad878e9cf6a9ae",
"Created": "REDACTED",
"Path": "REDACTED",
"Args": [
"REDACTED"
],
"State": {
"Status": "running",
"Running": true,
"Paused": false,
"Restarting": false,
"OOMKilled": false,
"Dead": false,
"Pid": 3648,
"ExitCode": 0,
"Error": "",
"StartedAt": "2019-05-28T00:52:02.4274538Z",
"FinishedAt": "2019-05-28T00:52:00.7740957Z"
},
"Image": "sha256:b301392b301239e154b21e03c8b77c03abd14e8ab3459835036a411998b60fd8",
"ResolvConfPath": "",
"HostnamePath": "",
"HostsPath": "",
"LogPath": "C:\\ProgramData\\docker\\containers\\e9b7722458801aadcfdc6f37a7d44c077c36d3680a906a305dad878e9cf6a9ae\\e9b7722458801aadcfdc6f37a7d44c077c36d3680a906a305dad878e9cf6a9ae-json.log",
"Name": "REDACTED",
"RestartCount": 0,
"Driver": "windowsfilter",
"Platform": "windows",
"MountLabel": "",
"ProcessLabel": "",
"AppArmorProfile": "",
"ExecIDs": null,
"HostConfig": {
"Binds": [
"REDACTED"
],
"ContainerIDFile": "",
"LogConfig": {
"Type": "json-file",
"Config": {
"max-file": "2",
"max-size": "1m"
}
},
"NetworkMode": "nat",
"PortBindings": null,
"RestartPolicy": {
"Name": "unless-stopped",
"MaximumRetryCount": 0
},
"AutoRemove": false,
"VolumeDriver": "",
"VolumesFrom": null,
"CapAdd": null,
"CapDrop": null,
"Dns": null,
"DnsOptions": null,
"DnsSearch": null,
"ExtraHosts": null,
"GroupAdd": null,
"IpcMode": "",
"Cgroup": "",
"Links": null,
"OomScoreAdj": 0,
"PidMode": "",
"Privileged": false,
"PublishAllPorts": false,
"ReadonlyRootfs": false,
"SecurityOpt": null,
"UTSMode": "",
"UsernsMode": "",
"ShmSize": 0,
"ConsoleSize": [
0,
0
],
"Isolation": "process",
"CpuShares": 0,
"Memory": 0,
"NanoCpus": 0,
"CgroupParent": "",
"BlkioWeight": 0,
"BlkioWeightDevice": null,
"BlkioDeviceReadBps": null,
"BlkioDeviceWriteBps": null,
"BlkioDeviceReadIOps": null,
"BlkioDeviceWriteIOps": null,
"CpuPeriod": 0,
"CpuQuota": 0,
"CpuRealtimePeriod": 0,
"CpuRealtimeRuntime": 0,
"CpusetCpus": "",
"CpusetMems": "",
"Devices": null,
"DeviceCgroupRules": null,
"DiskQuota": 0,
"KernelMemory": 0,
"MemoryReservation": 0,
"MemorySwap": 0,
"MemorySwappiness": null,
"OomKillDisable": null,
"PidsLimit": 0,
"Ulimits": null,
"CpuCount": 0,
"CpuPercent": 0,
"IOMaximumIOps": 0,
"IOMaximumBandwidth": 0,
"MaskedPaths": null,
"ReadonlyPaths": null
},
"GraphDriver": {
"Data": {
"dir": "C:\\ProgramData\\docker\\windowsfilter\\e9b7722458801aadcfdc6f37a7d44c077c36d3680a906a305dad878e9cf6a9ae"
},
"Name": "windowsfilter"
},
"Mounts": [
{
"Type": "bind",
"Source": "REDACTED",
"Destination": "REDACTED",
"Mode": "",
"RW": true,
"Propagation": ""
}
],
"Config": {
"Hostname": "REDACTED",
"Domainname": "",
"User": "",
"AttachStdin": false,
"AttachStdout": false,
"AttachStderr": false,
"Tty": false,
"OpenStdin": false,
"StdinOnce": false,
"Env": null,
"Cmd": [
"REDACTED",
],
"Image": "REDACTED",
"Volumes": null,
"WorkingDir": "",
"Entrypoint": [],
"OnBuild": null,
"Labels": {
"agent.config": "REDACTED",
"agent.managed": "true"
},
"StopSignal": "SIGTERM"
},
"NetworkSettings": {
"Bridge": "",
"SandboxID": "e9b7722458801aadcfdc6f37a7d44c077c36d3680a906a305dad878e9cf6a9ae",
"HairpinMode": false,
"LinkLocalIPv6Address": "",
"LinkLocalIPv6PrefixLen": 0,
"Ports": {},
"SandboxKey": "e9b7722458801aadcfdc6f37a7d44c077c36d3680a906a305dad878e9cf6a9ae",
"SecondaryIPAddresses": null,
"SecondaryIPv6Addresses": null,
"EndpointID": "",
"Gateway": "",
"GlobalIPv6Address": "",
"GlobalIPv6PrefixLen": 0,
"IPAddress": "",
"IPPrefixLen": 0,
"IPv6Gateway": "",
"MacAddress": "",
"Networks": {
"nat": {
"IPAMConfig": null,
"Links": null,
"Aliases": null,
"NetworkID": "93a8f0003991defdec723729ef537a49ecab734ede99e070a8dd1181ff79137e",
"EndpointID": "8d8509776404f0d0532d5afe3132c5a4a63e94e0b5fcb94751d53f24e29e1f9a",
"Gateway": "REDACTED",
"IPAddress": "REDACTED",
"IPPrefixLen": 16,
"IPv6Gateway": "",
"GlobalIPv6Address": "",
"GlobalIPv6PrefixLen": 0,
"MacAddress": "00:15:5d:02:1c:ff",
"DriverOpts": null
}
}
}
}
]