Bug 1488516
| Summary: | Docker run returns error 139 when docker storage is changed w/o SELinux | ||
|---|---|---|---|
| Product: | [Fedora] Fedora | Reporter: | Aaron Weitekamp <aweiteka> |
| Component: | docker | Assignee: | Daniel Walsh <dwalsh> |
| Status: | CLOSED EOL | QA Contact: | Fedora Extras Quality Assurance <extras-qa> |
| Severity: | medium | Docs Contact: | |
| Priority: | unspecified | ||
| Version: | 26 | CC: | adimania, admiller, amurdaca, andreas.bierfert, bbaude, dwalsh, fkluknav, ichavero, jcajka, jchaloup, lsm5, marianne, miminar, nalin, vbatts |
| Target Milestone: | --- | ||
| Target Release: | --- | ||
| Hardware: | Unspecified | ||
| OS: | Unspecified | ||
| Whiteboard: | |||
| Fixed In Version: | Doc Type: | If docs needed, set a value | |
| Doc Text: | Story Points: | --- | |
| Clone Of: | Environment: | ||
| Last Closed: | 2018-05-29 12:48:13 UTC | Type: | Bug |
| Regression: | --- | Mount Type: | --- |
| Documentation: | --- | CRM: | |
| Verified Versions: | Category: | --- | |
| oVirt Team: | --- | RHEL 7.3 requirements from Atomic Host: | |
| Cloudforms Team: | --- | Target Upstream Version: | |
| Embargoed: | |||
What avc's are you seeing ausearch -m avc -ts recent It looks like this corresponds to the error:
$ sudo ausearch -m avc -ts 09/05/2017 00:00:00
----
time->Tue Sep 5 09:19:47 2017
type=AVC msg=audit(1504617587.260:466): avc: denied { read execute } for pid=11096 comm="bash" path="/usr/bin/bash" dev="dm-3" ino=4854937 scontext=system_u:system_r:container_t:s0:c478,c692 tcontext=system_u:object_r:home_root_t:s0 tclass=file permissive=0
----
time->Tue Sep 5 09:27:08 2017
type=AVC msg=audit(1504618028.288:477): avc: denied { read execute } for pid=11604 comm="bash" path="/usr/bin/bash" dev="dm-3" ino=4854937 scontext=system_u:system_r:container_t:s0:c392,c983 tcontext=system_u:object_r:home_root_t:s0 tclass=file permissive=0
----
time->Tue Sep 5 09:30:21 2017
type=AVC msg=audit(1504618221.316:489): avc: denied { read execute } for pid=11894 comm="bash" path="/usr/bin/bash" dev="dm-3" ino=4854937 scontext=system_u:system_r:container_t:s0:c306,c485 tcontext=system_u:object_r:home_root_t:s0 tclass=file permissive=0
These AVC's indicate that the labeling did not work. home_root_t is the label of /home. This indicates that the directory under overaly is labeled as home_root_t. The proper way to label the directory is semanage fcontext -a -e /var/lib/docker /home/aweiteka/docker restorecon -R -v /home/aweiteka/docker This says label all content under /home/aweiteka/docker as if it was under /var/lib/docker. The overlay directories should get labeled container_share_t. That makes sense. The purpose of this bug is that the symptom was really difficult to troubleshoot: exit code 139->SELinux denial. I don't know how common the '-g ALT_DIR' option is but logging the permissions error would be ideal. At a minimum the error and fix are now documented here, even if we close this as WONTFIX/NOTABUG. This message is a reminder that Fedora 26 is nearing its end of life. Approximately 4 (four) weeks from now Fedora will stop maintaining and issuing updates for Fedora 26. It is Fedora's policy to close all bug reports from releases that are no longer maintained. At that time this bug will be closed as EOL if it remains open with a Fedora 'version' of '26'. Package Maintainer: If you wish for this bug to remain open because you plan to fix it in a currently maintained version, simply change the 'version' to a later Fedora version. Thank you for reporting this issue and we are sorry that we were not able to fix it before Fedora 26 is end of life. If you would still like to see this bug fixed and are able to reproduce it against a later version of Fedora, you are encouraged change the 'version' to a later Fedora version prior this bug is closed as described in the policy above. Although we aim to fix as many bugs as possible during every release's lifetime, sometimes those efforts are overtaken by events. Often a more recent Fedora release includes newer upstream software that fixes bugs or makes them obsolete. Fedora 26 changed to end-of-life (EOL) status on 2018-05-29. Fedora 26 is no longer maintained, which means that it will not receive any further security or bug fix updates. As a result we are closing this bug. If you can reproduce this bug against a currently maintained version of Fedora please feel free to reopen this bug against that version. If you are unable to reopen this bug, please file a new report against the current release. If you experience problems, please add a comment to this bug. Thank you for reporting this bug and we are sorry it could not be fixed. |
Description of problem: When using an alternate storage directory for docker without the correct SELinux context all containers exit with error code 139. There are no hints in the log about the error Version-Release number of selected component (if applicable): $ cat /etc/fedora-release Fedora release 26 (Twenty Six) $ rpm -q docker runc kernel docker-1.13.1-22.gitb5e3294.fc26.x86_64 runc-1.0.1-1.gitc5ec254.fc26.x86_64 kernel-4.11.8-300.fc26.x86_64 kernel-4.12.8-300.fc26.x86_64 kernel-4.12.9-300.fc26.x86_64 How reproducible: always Steps to Reproduce: 1. Create an alternate directory for docker e.g., mkdir -p /home/aweiteka/docker 1. Start docker with an alternate storage path defined in /etc/sysconfig/docker OPTIONS='--debug --selinux-enabled --log-driver=journald -g /home/aweiteka/docker' 1. Restart docker: systemctl restart docker.service 1. docker run -it --rm fedora bash Actual results: $ echo $? 139 See docker log below. Expected results: Error in docker log saying cannot create container due to permissions. It's interesting docker can pull images in this broken state. SELinux commands to fix: semanage fcontext -a -t container_var_lib_t '/home/aweiteka/docker(/.*)?' restorecon -RF /home/aweiteka/docker Additional info: Docker log: Sep 05 09:30:20 aweiteka-t470s dockerd-current[1188]: time="2017-09-05T09:30:20.978133037-04:00" level=debug msg="Calling GET /_ping" Sep 05 09:30:20 aweiteka-t470s dockerd-current[1188]: time="2017-09-05T09:30:20.979443066-04:00" level=info msg="{Action=_ping, Username=aweiteka, LoginUID=19340, PID=11856}" Sep 05 09:30:20 aweiteka-t470s dockerd-current[1188]: time="2017-09-05T09:30:20.979749550-04:00" level=debug msg="AuthZ request using plugin rhel-push-plugin" Sep 05 09:30:20 aweiteka-t470s dockerd-current[1188]: time="2017-09-05T09:30:20.980551808-04:00" level=debug msg="AuthZ response using plugin rhel-push-plugin" Sep 05 09:30:20 aweiteka-t470s dockerd-current[1188]: time="2017-09-05T09:30:20.982922476-04:00" level=debug msg="Calling POST /v1.26/containers/create" Sep 05 09:30:20 aweiteka-t470s dockerd-current[1188]: time="2017-09-05T09:30:20.983137519-04:00" level=debug msg="form data: {\"AttachStderr\":true,\"AttachStdin\":true,\"AttachStdout\":true,\"Cmd\":[\"bash\"],\"Domainname\":\"\",\"Entrypoint\":null,\"Env\":[],\"HostConfig\":{\"AutoRemove\":true,\"Binds\":null,\"BlkioDeviceReadBps\":null,\"BlkioDeviceReadIOps\":null,\"BlkioDeviceWriteBps\":null,\"BlkioDeviceWriteIOps\":null,\"BlkioWeight\":0,\"BlkioWeightDevice\":null,\"CapAdd\":null,\"CapDrop\":null,\"Cgroup\":\"\",\"CgroupParent\":\"\",\"ConsoleSize\":[0,0],\"ContainerIDFile\":\"\",\"CpuCount\":0,\"CpuPercent\":0,\"CpuPeriod\":0,\"CpuQuota\":0,\"CpuRealtimePeriod\":0,\"CpuRealtimeRuntime\":0,\"CpuShares\":0,\"CpusetCpus\":\"\",\"CpusetMems\":\"\",\"Devices\":[],\"DiskQuota\":0,\"Dns\":[],\"DnsOptions\":[],\"DnsSearch\":[],\"ExtraHosts\":null,\"GroupAdd\":null,\"IOMaximumBandwidth\":0,\"IOMaximumIOps\":0,\"IpcMode\":\"\",\"Isolation\":\"\",\"KernelMemory\":0,\"Links\":null,\"LogConfig\":{\"Config\":{},\"Type\":\"\"},\"Memory\":0,\"MemoryReservation\":0,\"MemorySwap\":0,\"MemorySwappiness\":-1,\"NanoCpus\":0,\"NetworkMode\":\"default\",\"OomKillDisable\":false,\"OomScoreAdj\":0,\"PidMode\":\"\",\"PidsLimit\":0,\"PortBindings\":{},\"Privileged\":false,\"PublishAllPorts\":false,\"ReadonlyRootfs\":false,\"RestartPolicy\":{\"MaximumRetryCount\":0,\"Name\":\"no\"},\"SecurityOpt\":null,\"ShmSize\":0,\"UTSMode\":\"\",\"Ulimits\":null,\"UsernsMode\":\"\",\"VolumeDriver\":\"\",\"VolumesFrom\":null},\"Hostname\":\"\",\"Image\":\"fedora\",\"Labels\":{},\"NetworkingConfig\":{\"EndpointsConfig\":{}},\"OnBuild\":null,\"OpenStdin\":true,\"StdinOnce\":true,\"Tty\":true,\"User\":\"\",\"Volumes\":{},\"WorkingDir\":\"\"}" Sep 05 09:30:20 aweiteka-t470s dockerd-current[1188]: time="2017-09-05T09:30:20.983226630-04:00" level=info msg="{Action=create, Username=aweiteka, LoginUID=19340, PID=11856}" Sep 05 09:30:20 aweiteka-t470s dockerd-current[1188]: time="2017-09-05T09:30:20.983439570-04:00" level=debug msg="AuthZ request using plugin rhel-push-plugin" Sep 05 09:30:21 aweiteka-t470s dockerd-current[1188]: time="2017-09-05T09:30:21.027109684-04:00" level=debug msg="container mounted via layerStore: /home/aweiteka/docker/overlay2/031deb70d7ce80153071187b8d13eef663356eb6ae334e1a51afa372ec089821/merged" Sep 05 09:30:21 aweiteka-t470s dockerd-current[1188]: time="2017-09-05T09:30:21.051955150-04:00" level=debug msg="AuthZ response using plugin rhel-push-plugin" Sep 05 09:30:21 aweiteka-t470s dockerd-current[1188]: time="2017-09-05T09:30:21.052902041-04:00" level=debug msg="Calling POST /v1.26/containers/9b8acc48ab45315bc08c00b4cd05eb52fb28503f224e80648e795f9751ea1574/attach?stderr=1&stdin=1&stdout=1&stream=1" Sep 05 09:30:21 aweiteka-t470s dockerd-current[1188]: time="2017-09-05T09:30:21.053458967-04:00" level=info msg="{Action=attach, ID=9b8acc48ab45315bc08c00b4cd05eb52fb28503f224e80648e795f9751ea1574, Username=aweiteka, LoginUID=19340, PID=11856}" Sep 05 09:30:21 aweiteka-t470s dockerd-current[1188]: time="2017-09-05T09:30:21.053746285-04:00" level=debug msg="AuthZ request using plugin rhel-push-plugin" Sep 05 09:30:21 aweiteka-t470s dockerd-current[1188]: time="2017-09-05T09:30:21.054162408-04:00" level=debug msg="attach: stdin: begin" Sep 05 09:30:21 aweiteka-t470s dockerd-current[1188]: time="2017-09-05T09:30:21.054216944-04:00" level=debug msg="attach: stderr: begin" Sep 05 09:30:21 aweiteka-t470s dockerd-current[1188]: time="2017-09-05T09:30:21.054247110-04:00" level=debug msg="attach: stdout: begin" Sep 05 09:30:21 aweiteka-t470s dockerd-current[1188]: time="2017-09-05T09:30:21.054610449-04:00" level=debug msg="Calling GET /v1.26/events?filters=%7B%22container%22%3A%7B%229b8acc48ab45315bc08c00b4cd05eb52fb28503f224e80648e795f9751ea1574%22%3Atrue%7D%2C%22type%22%3A%7B%22container%22%3Atrue%7D%7D" Sep 05 09:30:21 aweiteka-t470s dockerd-current[1188]: time="2017-09-05T09:30:21.054683072-04:00" level=debug msg="{Action=events, Username=aweiteka, LoginUID=19340, PID=11856}" Sep 05 09:30:21 aweiteka-t470s dockerd-current[1188]: time="2017-09-05T09:30:21.054700670-04:00" level=debug msg="AuthZ request using plugin rhel-push-plugin" Sep 05 09:30:21 aweiteka-t470s dockerd-current[1188]: time="2017-09-05T09:30:21.055439260-04:00" level=debug msg="Calling POST /v1.26/containers/9b8acc48ab45315bc08c00b4cd05eb52fb28503f224e80648e795f9751ea1574/start" Sep 05 09:30:21 aweiteka-t470s dockerd-current[1188]: time="2017-09-05T09:30:21.055770517-04:00" level=info msg="{Action=start, ID=9b8acc48ab45315bc08c00b4cd05eb52fb28503f224e80648e795f9751ea1574, Username=aweiteka, LoginUID=19340, PID=11856, Config={Hostname=9b8acc48ab45, AttachStdin=true, AttachStdout=true, AttachStderr=true, Tty=true, OpenStdin=true, StdinOnce=true, Env=[DISTTAG=f26container FGC=f26], Cmd=[bash], ArgsEscaped=false, Image=fedora, NetworkDisabled=false, Labels=map[name:fedora license:MIT version:26 vendor:Fedora Project]}, HostConfig={LogConfig={Type:journald Config:map[]}, NetworkMode=default, PortBindings=map[], RestartPolicy={Name:no MaximumRetryCount:0}, AutoRemove=true, DNS=[], DNSOptions=[], DNSSearch=[], Privileged=false, PublishAllPorts=false, ReadonlyRootfs=false, ShmSize=67108864, Runtime=oci, Resources={CPUShares:0 Memory:0 NanoCPUs:0 CgroupParent: BlkioWeight:0 BlkioWeightDevice:[] BlkioDeviceReadBps:[] BlkioDeviceWriteBps:[] BlkioDeviceReadIOps:[] BlkioDeviceWriteIOps:[] CPUPeriod:0 CPUQuota:0 CPURealtimePeriod:0 CPURealtimeRuntime:0 CpusetCpus: CpusetMems: Devices:[] DiskQuota:0 KernelMemory:0 MemoryReservation:0 MemorySwap:0 MemorySwappiness:0xc4208c5588 OomKillDisable:0xc4208c5592 PidsLimit:0 Ulimits:[] CPUCount:0 CPUPercent:0 IOMaximumIOps:0 IOMaximumBandwidth:0}}}" Sep 05 09:30:21 aweiteka-t470s dockerd-current[1188]: time="2017-09-05T09:30:21.056007764-04:00" level=debug msg="AuthZ request using plugin rhel-push-plugin" Sep 05 09:30:21 aweiteka-t470s dockerd-current[1188]: time="2017-09-05T09:30:21.060525689-04:00" level=debug msg="container mounted via layerStore: /home/aweiteka/docker/overlay2/031deb70d7ce80153071187b8d13eef663356eb6ae334e1a51afa372ec089821/merged" Sep 05 09:30:21 aweiteka-t470s dockerd-current[1188]: time="2017-09-05T09:30:21.060696261-04:00" level=debug msg="Assigning addresses for endpoint cranky_noyce's interface on network bridge" Sep 05 09:30:21 aweiteka-t470s dockerd-current[1188]: time="2017-09-05T09:30:21.060718500-04:00" level=debug msg="RequestAddress(LocalDefault/172.17.0.0/16, <nil>, map[])" Sep 05 09:30:21 aweiteka-t470s dockerd-current[1188]: time="2017-09-05T09:30:21.081516464-04:00" level=debug msg="Assigning addresses for endpoint cranky_noyce's interface on network bridge" Sep 05 09:30:21 aweiteka-t470s dockerd-current[1188]: time="2017-09-05T09:30:21.089915370-04:00" level=debug msg="Programming external connectivity on endpoint cranky_noyce (2ae9289dfaf8adb3a9a168cdb0c881b339a6b3968e75d7182ed1d632c28ec0bc)" Sep 05 09:30:21 aweiteka-t470s dockerd-current[1188]: time="2017-09-05T09:30:21.094823444-04:00" level=debug msg="createSpec: cgroupsPath: system.slice:docker:9b8acc48ab45315bc08c00b4cd05eb52fb28503f224e80648e795f9751ea1574" Sep 05 09:30:21 aweiteka-t470s dockerd-current[1188]: time="2017-09-05T09:30:21.197439512-04:00" level=debug msg="sandbox set key processing took 40.284052ms for container 9b8acc48ab45315bc08c00b4cd05eb52fb28503f224e80648e795f9751ea1574" Sep 05 09:30:21 aweiteka-t470s dockerd-current[1188]: time="2017-09-05T09:30:21.340533859-04:00" level=debug msg="libcontainerd: received containerd event: &types.Event{Type:\"start-container\", Id:\"9b8acc48ab45315bc08c00b4cd05eb52fb28503f224e80648e795f9751ea1574\", Status:0x0, Pid:\"\", Timestamp:(*timestamp.Timestamp)(0xc420a26390)}" Sep 05 09:30:21 aweiteka-t470s dockerd-current[1188]: time="2017-09-05T09:30:21.350865769-04:00" level=debug msg="AuthZ response using plugin rhel-push-plugin" Sep 05 09:30:21 aweiteka-t470s dockerd-current[1188]: time="2017-09-05T09:30:21.351084110-04:00" level=debug msg="libcontainerd: event unhandled: type:\"start-container\" id:\"9b8acc48ab45315bc08c00b4cd05eb52fb28503f224e80648e795f9751ea1574\" timestamp:<seconds:1504618221 nanos:340281011 > " Sep 05 09:30:21 aweiteka-t470s dockerd-current[1188]: time="2017-09-05T09:30:21.354746774-04:00" level=debug msg="Calling POST /v1.26/containers/9b8acc48ab45315bc08c00b4cd05eb52fb28503f224e80648e795f9751ea1574/resize?h=37&w=119" Sep 05 09:30:21 aweiteka-t470s dockerd-current[1188]: time="2017-09-05T09:30:21.354918052-04:00" level=info msg="{Action=resize, ID=9b8acc48ab45315bc08c00b4cd05eb52fb28503f224e80648e795f9751ea1574, Username=aweiteka, LoginUID=19340, PID=11856}" Sep 05 09:30:21 aweiteka-t470s dockerd-current[1188]: time="2017-09-05T09:30:21.356339727-04:00" level=debug msg="AuthZ request using plugin rhel-push-plugin" Sep 05 09:30:21 aweiteka-t470s dockerd-current[1188]: time="2017-09-05T09:30:21.357878647-04:00" level=debug msg="AuthZ response using plugin rhel-push-plugin" Sep 05 09:30:21 aweiteka-t470s dockerd-current[1188]: time="2017-09-05T09:30:21.405689717-04:00" level=debug msg="libcontainerd: received containerd event: &types.Event{Type:\"exit\", Id:\"9b8acc48ab45315bc08c00b4cd05eb52fb28503f224e80648e795f9751ea1574\", Status:0x8b, Pid:\"init\", Timestamp:(*timestamp.Timestamp)(0xc420a08ef0)}" Sep 05 09:30:21 aweiteka-t470s dockerd-current[1188]: time="2017-09-05T09:30:21.406013880-04:00" level=debug msg="attach: stderr: end" Sep 05 09:30:21 aweiteka-t470s dockerd-current[1188]: time="2017-09-05T09:30:21.406025360-04:00" level=debug msg="attach: stdout: end" Sep 05 09:30:21 aweiteka-t470s dockerd-current[1188]: time="2017-09-05T09:30:21.406045000-04:00" level=debug msg="attach: stdin: end" Sep 05 09:30:21 aweiteka-t470s dockerd-current[1188]: time="2017-09-05T09:30:21.406091880-04:00" level=debug msg="AuthZ response using plugin rhel-push-plugin" Sep 05 09:30:21 aweiteka-t470s dockerd-current[1188]: time="2017-09-05T09:30:21.406264990-04:00" level=debug msg="Closing buffered stdin pipe" Sep 05 09:30:21 aweiteka-t470s dockerd-current[1188]: time="2017-09-05T09:30:21.406297178-04:00" level=debug msg="Revoking external connectivity on endpoint cranky_noyce (2ae9289dfaf8adb3a9a168cdb0c881b339a6b3968e75d7182ed1d632c28ec0bc)" Sep 05 09:30:21 aweiteka-t470s dockerd-current[1188]: time="2017-09-05T09:30:21.483116466-04:00" level=debug msg="Releasing addresses for endpoint cranky_noyce's interface on network bridge" Sep 05 09:30:21 aweiteka-t470s dockerd-current[1188]: time="2017-09-05T09:30:21.483733373-04:00" level=debug msg="ReleaseAddress(LocalDefault/172.17.0.0/16, 172.17.0.2)" Sep 05 09:30:21 aweiteka-t470s dockerd-current[1188]: time="2017-09-05T09:30:21.585877584-04:00" level=debug msg="Client context cancelled, stop sending events" Sep 05 09:30:21 aweiteka-t470s dockerd-current[1188]: time="2017-09-05T09:30:21.585916133-04:00" level=debug msg="AuthZ response using plugin rhel-push-plugin"