Bug 1488516 - Docker run returns error 139 when docker storage is changed w/o SELinux
Summary: Docker run returns error 139 when docker storage is changed w/o SELinux
Status: CLOSED EOL
Alias: None
Product: Fedora
Classification: Fedora
Component: docker
Version: 26
Hardware: Unspecified
OS: Unspecified
unspecified
medium
Target Milestone: ---
Assignee: Daniel Walsh
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Keywords:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2017-09-05 14:56 UTC by Aaron Weitekamp
Modified: 2018-05-29 12:48 UTC (History)
15 users (show)

(edit)
Clone Of:
(edit)
Last Closed: 2018-05-29 12:48:13 UTC


Attachments (Terms of Use)

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.


Note You need to log in before you can comment on or make changes to this bug.