Bug 1488516

Summary: Docker run returns error 139 when docker storage is changed w/o SELinux
Product: [Fedora] Fedora Reporter: Aaron Weitekamp <aweiteka>
Component: dockerAssignee: Daniel Walsh <dwalsh>
Status: CLOSED EOL QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: medium Docs Contact:
Priority: unspecified    
Version: 26CC: 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: ---

Description Aaron Weitekamp 2017-09-05 14:56:28 UTC
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"

Comment 1 Daniel Walsh 2017-09-05 15:43:04 UTC
What avc's are you seeing

ausearch -m avc -ts recent

Comment 2 Aaron Weitekamp 2017-09-05 21:03:30 UTC
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

Comment 3 Daniel Walsh 2017-09-06 10:27:33 UTC
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.

Comment 4 Aaron Weitekamp 2017-09-06 12:30:12 UTC
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.

Comment 5 Fedora End Of Life 2018-05-03 08:32:03 UTC
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.

Comment 6 Fedora End Of Life 2018-05-29 12:48:13 UTC
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.