Bug 1396297 - setfiles takes a really long time
Summary: setfiles takes a really long time
Keywords:
Status: CLOSED UPSTREAM
Alias: None
Product: Virtualization Tools
Classification: Community
Component: libguestfs
Version: unspecified
Hardware: All
OS: Linux
unspecified
unspecified
Target Milestone: ---
Assignee: Richard W.M. Jones
QA Contact:
URL:
Whiteboard: V2V
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2016-11-17 22:33 UTC by Richard W.M. Jones
Modified: 2017-02-10 13:22 UTC (History)
11 users (show)

Fixed In Version:
Clone Of:
Environment:
Last Closed: 2017-02-10 10:15:50 UTC
Embargoed:


Attachments (Terms of Use)
selinux context files (1.68 MB, application/x-tar)
2016-12-05 16:54 UTC, Derek Atkins
no flags Details

Description Richard W.M. Jones 2016-11-17 22:33:22 UTC
Description of problem:

Original bug report was by Derek Atkins here:
http://lists.ovirt.org/pipermail/users/2016-November/thread.html#43873

It has been reported that virt-v2v takes a very long time
converting certain guests.  The step which fails is where we
run the 'setfiles' command on the guest filesystem.

The reporter supplied me with a disk image which reproduces
the problem on RHEL 7.3.

However I *cannot* reproduce it with Fedora 24 host, so it
seems likely that this is a setfiles bug which is already fixed.
Just need to identify the fix and backport it to RHEL 7.

A simple reproducer (given the disk image) is:

time guestfish --ro -a fc21-64.vmdk -i selinux-relabel /etc/selinux/targeted/contexts/files/file_contexts / force:true

This command runs the host setfiles against the disk image.  It takes
2+ hours to run on RHEL 7.2 and 7.3, but about 30 seconds
on Fedora 24 host.

Version-Release number of selected component (if applicable):

Slow version: policycoreutils-2.5-8.el7.x86_64
Fast version: policycoreutils-2.5-13.fc24.x86_64

How reproducible:

100%

Steps to Reproduce:

Unfortunately I cannot redistribute the filesystem, but if you had
that, then running something like this assuming the problematic filesystem
was mounted at /mnt:

setfiles -q -F -r /mnt /mnt/etc/selinux/targeted/contexts/files/file_contexts /mnt

should demonstrate the problem.

Comment 1 Richard W.M. Jones 2016-11-17 22:33:48 UTC
Assigning to myself because I need to investigate the git commit
which fixes this.

Comment 3 Milos Malik 2016-11-21 09:28:53 UTC
Does setfiles use realpath() function? If yes, it could be similar to https://bugzilla.redhat.com/show_bug.cgi?id=1386498.

Comment 4 Richard W.M. Jones 2016-11-22 12:10:48 UTC
Thanks for pointing me to that bug.  That bug does exist in the
RHEL 7.3 libselinux package.  However I backported the fix and
it does not fix the current bug.

Comment 5 Richard W.M. Jones 2016-11-22 16:09:40 UTC
I finally managed to get a perf report out of this, which is *very*
interesting:

Samples: 2M of event 'cpu-clock', Event count (approx.): 663645000000
  Children      Self  Command   Shared Object      Symbol                      ◆
-   99.13%    97.50%  setfiles  libpcre.so.1.2.0   [.] pcre_exec               ▒
   - 99.03% pcre_exec                                                          ▒
      - 1.60% 0xffffffff8169711d                                               ▒
           0xffffffff81698bd5                                                  ▒
           0xffffffff8108f495                                                  ▒
           0xffffffff8102d365                                                  ▒
         - 0xffffffff81697f5c                                                  ▒
              1.59% 0xffffffff8108f0a8                                         ▒
+    1.62%     0.00%  setfiles  [kernel.kallsyms]  [k] 0xffffffff81697f5c      ▒
+    1.62%     0.00%  setfiles  [kernel.kallsyms]  [k] 0xffffffff8102d365      ▒
+    1.62%     0.00%  setfiles  [kernel.kallsyms]  [k] 0xffffffff8108f495      ▒
+    1.62%     0.00%  setfiles  [kernel.kallsyms]  [k] 0xffffffff81698bd5      ▒
+    1.62%     0.00%  setfiles  [kernel.kallsyms]  [k] 0xffffffff8169711d      ▒
+    1.61%     1.61%  setfiles  [kernel.kallsyms]  [k] 0xffffffff8108f0a8      ▒
+    0.50%     0.00%  setfiles  [unknown]          [k] 0000000000000000        ▒


I noticed several changes upstream related to using pcre2 and
something to do with using hashes to cache something or other
(the latter I didn't fully understand).

Comment 6 Richard W.M. Jones 2016-11-22 17:45:55 UTC
Removing myself from assignee since (1) I think I have done
enough to investigate this bug -- but please let me know if
you need more information; and (2) the list of commits which
might affect or fix this bug is longer than I anticipated.

Comment 7 Petr Lautrbach 2016-12-05 15:57:41 UTC
Are you able to reproduce this with other publicly available images? The name of reported image - fc21-64.vmdk - suggests that the problem filesystem is Fedora 21.

SELinux userspace in Fedora 24 and RHEL-7.3 are almost same. Could this be a pcre issue?

Comment 8 Richard W.M. Jones 2016-12-05 16:06:31 UTC
(In reply to Petr Lautrbach from comment #7)
> Are you able to reproduce this with other publicly available images? The
> name of reported image - fc21-64.vmdk - suggests that the problem filesystem
> is Fedora 21.

I'm not able to reproduce this with any other image.  The image is
proprietary and belongs to the reporter, but I could supply you with
a copy provided it doesn't leave Red Hat.  With the image it should
be simple to reproduce the bug as outlined in comment 0.

> SELinux userspace in Fedora 24 and RHEL-7.3 are almost same. Could this be a
> pcre issue?

pcre is certainly under suspicion.

Comment 9 Derek Atkins 2016-12-05 16:24:34 UTC
(In reply to Petr Lautrbach from comment #7)
> Are you able to reproduce this with other publicly available images? The
> name of reported image - fc21-64.vmdk - suggests that the problem filesystem
> is Fedora 21.

I did see this with other VMs; I do not recall what base version of Fedora were in the others.  I don't know if my ovirt event logs go back far enough to see how long it took to import the half-dozen imports.  I could of course go re-run the tests on my OVA files and let you know which ones took a while, but it was definitely more than one.  But it wasn't all of them -- some of my VMs imported in a few minutes, which is why I filed the bug -- expectations had already been set!  :)

Comment 10 Petr Lautrbach 2016-12-05 16:29:32 UTC
Great. At the beginning, if you can please send me /etc/selinux/targeted/contexts/files/ directory from the image. This directory should not contain as much proprietary data as the whole image but can help with the investigation.

Comment 11 Derek Atkins 2016-12-05 16:52:53 UTC
(In reply to Petr Lautrbach from comment #10)
> Great. At the beginning, if you can please send me
> /etc/selinux/targeted/contexts/files/ directory from the image. This
> directory should not contain as much proprietary data as the whole image but
> can help with the investigation.

I've got a Fedora-20 VM that took just over 4 hours to convert..  Granted, this VM was larger and had more files than the previous FC21 VM.  I've got another FC20 VM but it converted in 2 minutes.

Attached please find the contents of that directory.

Comment 12 Derek Atkins 2016-12-05 16:54:24 UTC
Created attachment 1228111 [details]
selinux context files

contents of /etc/selinux/targeted/contexts/files from my second FC20 slow-import.  Let me know if you need to know the first (fc21) contents?

Comment 13 Milos Malik 2017-02-01 11:22:38 UTC
After replacing the original /etc/selinux/targeted/contexts/files directory content with the content of above-mentioned attachment, I see following results on a clean Fedora24 machine:

# restorecon -RvF /etc/selinux/
restorecon reset /etc/selinux context system_u:object_r:selinux_config_t:s0->system_u:object_r:home_root_t:s0
restorecon reset /etc/selinux/semanage.conf context system_u:object_r:selinux_config_t:s0->system_u:object_r:smokeping_initrc_exec_t:s0
restorecon reset /etc/selinux/targeted context system_u:object_r:selinux_config_t:s0->system_u:object_r:home_root_t:s0
restorecon reset /etc/selinux/targeted/logins context system_u:object_r:selinux_login_config_t:s0->system_u:object_r:home_root_t:s0
Segmentation fault (core dumped)
# echo $?
139
# dmesg | grep -i restorecon
[  315.453085] restorecon[1412]: segfault at 3e800 ip 00007fdc9b653cd7 sp 00007ffd76c19bb8 error 4 in libpcre.so.1.2.8[7fdc9b640000+72000]
[  338.475056] restorecon[1418]: segfault at 3e800 ip 00007f5863df5cd7 sp 00007ffd9edfe318 error 4 in libpcre.so.1.2.8[7f5863de2000+72000]
[  350.587635] restorecon[1426]: segfault at 3e800 ip 00007fd6810d5cd7 sp 00007ffc0f48c1e8 error 4 in libpcre.so.1.2.8[7fd6810c2000+72000]
[  424.089971] restorecon[1434]: segfault at 3e800 ip 00007f8d648bacd7 sp 00007ffe5ae92298 error 4 in libpcre.so.1.2.8[7f8d648a7000+72000]
#

Comment 14 Dalibor Pospíšil 2017-02-10 08:53:00 UTC
I played with the issue and I've found out that it is just matter of the file_contexts.bin. If I use just the text version (if I remove the binary version) it works as expected. So it looks like the binary version is somehow broken in that particular image.

I guess simple rebuild of the policy in that image could solve the issue.

I have whole /etc/selinux directory from the image in /mnt/a.

# time setfiles -pn -F -q /mnt/a/etc/selinux/targeted/contexts/files/file_contexts /etc                                                                                                                        
/mnt/a/etc/selinux/targeted/contexts/files/file_contexts.bin: context system_u:object_r:naemon_var_lib_t:s0 is invalid

real    0m55.474s
user    0m53.902s
sys     0m0.240s
# rm -f /mnt/a/etc/selinux/targeted/contexts/files/file_contexts.bin 
# time setfiles -pn -F -q /mnt/a/etc/selinux/targeted/contexts/files/file_contexts /etc
/mnt/a/etc/selinux/targeted/contexts/files/file_contexts: line 1246 has invalid context system_u:object_r:naemon_var_lib_t:s0
/mnt/a/etc/selinux/targeted/contexts/files/file_contexts: line 1247 has invalid context system_u:object_r:naemon_log_t:s0
/mnt/a/etc/selinux/targeted/contexts/files/file_contexts: line 1248 has invalid context system_u:object_r:naemon_var_run_t:s0
/mnt/a/etc/selinux/targeted/contexts/files/file_contexts: line 1674 has invalid context system_u:object_r:naemon_cache_t:s0
/mnt/a/etc/selinux/targeted/contexts/files/file_contexts: line 2766 has invalid context system_u:object_r:rolekit_unit_file_t:s0
/mnt/a/etc/selinux/targeted/contexts/files/file_contexts: line 3575 has invalid context system_u:object_r:naemon_exec_t:s0
/mnt/a/etc/selinux/targeted/contexts/files/file_contexts: line 3608 has invalid context system_u:object_r:rolekit_exec_t:s0
/mnt/a/etc/selinux/targeted/contexts/files/file_contexts: line 4788 has invalid context system_u:object_r:naemon_initrc_exec_t:s0
5k

real    0m1.157s
user    0m0.893s
sys     0m0.262s
# sefcontext_compile -o /mnt/a/etc/selinux/targeted/contexts/files/file_contexts.bin -p /mnt/a/etc/selinux/targeted/policy/policy.29 /mnt/a/etc/selinux/targeted/contexts/files/file_contexts
# time setfiles -pn -F -q /mnt/a/etc/selinux/targeted/contexts/files/file_contexts /etc
/mnt/a/etc/selinux/targeted/contexts/files/file_contexts.bin: context system_u:object_r:naemon_var_lib_t:s0 is invalid
5k

real    0m0.285s
user    0m0.172s
sys     0m0.111s

I'm current on RHEL-7. 
# rpm -qa | grep -E 'selinux|policycore'
libselinux-python-2.5-8.el7.x86_64
policycoreutils-sandbox-2.5-12.el7.x86_64
selinux-policy-sandbox-3.13.1-117.el7.noarch
selinux-policy-devel-3.13.1-117.el7.noarch
policycoreutils-devel-2.5-12.el7.x86_64
policycoreutils-gui-2.5-12.el7.x86_64
libselinux-2.5-8.el7.x86_64
policycoreutils-2.5-12.el7.x86_64
libselinux-debuginfo-2.5-8.el7.x86_64
policycoreutils-python-2.5-12.el7.x86_64
libselinux-devel-2.5-8.el7.x86_64
selinux-policy-targeted-3.13.1-117.el7.noarch
selinux-policy-minimum-3.13.1-117.el7.noarch
selinux-policy-3.13.1-117.el7.noarch
libselinux-utils-2.5-8.el7.x86_64

Comment 15 Richard W.M. Jones 2017-02-10 09:12:05 UTC
Interesting.  I don't know how this works, but is:

rm -f /mnt/a/etc/selinux/targeted/contexts/files/file_contexts.bin

always a safe thing to do?  It's just a cache which setfiles
will rebuild if it needs to?

Comment 16 Richard W.M. Jones 2017-02-10 09:13:23 UTC
(In reply to Richard W.M. Jones from comment #15)
> rm -f /mnt/a/etc/selinux/targeted/contexts/files/file_contexts.bin

I mean of course:

rm -f /etc/selinux/targeted/contexts/files/file_contexts.bin

Comment 17 Dalibor Pospíšil 2017-02-10 09:36:08 UTC
It shouldn't an issue if those .bin file are removed. It definitely speeds things up. It is not automatically rebuilt but it is rebuilt when policy it rebuilt, like semodule -B.

Comment 18 Richard W.M. Jones 2017-02-10 10:08:05 UTC
OK I'm happy with documenting removing that file as a workaround.

I'm not sure that libguestfs itself ought to be removing the file
since in every other case we've seen that is not necessary, and
libguestfs uses a different version of setfiles from the one
installed in the guest.

Comment 19 Richard W.M. Jones 2017-02-10 10:15:50 UTC
Documented upstream:

https://github.com/libguestfs/libguestfs/commit/2c340682b500d97143623bb82a10fde2f91bd169

Thanks for the investigation.

Comment 20 Dalibor Pospíšil 2017-02-10 13:22:18 UTC
Still, there might be some bug in policycoreutils as Miloš got a segfault, but it was on Fedora.

I've also tried to rebuild the binary file using the system in the image and the built file was identical with the original one. So rebuilding it withing the image does not help. I guess there is (was) some bug which cause the binary is not completely compatible with rhel7 tools version.


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