Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

F33: chrony.dhcp-propagation test failing #643

Closed
dustymabe opened this issue Oct 2, 2020 · 10 comments
Closed

F33: chrony.dhcp-propagation test failing #643

dustymabe opened this issue Oct 2, 2020 · 10 comments
Assignees
@sohankunkerkar
Labels
jira for syncing to jira

Comments

@dustymabe
Copy link
Member

This test is failing in the Fedora 33 rebase (coreos/fedora-coreos-config#640). We'll disable the test for now to unblock. @sohankunkerkar can you take a look?

Test failure details:

[dustymabe@media fedora]$ cosa kola run ext.config.chrony.dhcp-propagation
COREOS_ASSEMBLER_CONTAINER_RUNTIME_ARGS=-v /var/b/shared/code/github.com/coreos/coreos-assembler//mantle/bin/:/usr/local/bin/:ro
COREOS_ASSEMBLER_GIT=/var/b/shared/code/github.com/coreos/coreos-assembler/
COREOS_ASSEMBLER_CONFIG_GIT=/var/b/shared/code/github.com/coreos/fedora-coreos-config/
+ podman run --rm -ti --security-opt label=disable --privileged --uidmap=1000:0:1 --uidmap=0:1:1000 --uidmap 1001:1001:64536 -v /var/b/shared/assembler/fedora:/srv/ --device /dev/kvm --device /dev/fuse --tmpfs /tmp -v /var/tmp:/var/tmp n
⚠️  Skipping kola test pattern "fcos.internet":
⚠️  https://github.com/coreos/coreos-assembler/pull/1478
⚠️  Skipping kola test pattern "podman.workflow":
⚠️  https://github.com/coreos/coreos-assembler/pull/1478
kola -p qemu-unpriv --output-dir tmp/kola run ext.config.chrony.dhcp-propagation --denylist-test fcos.internet --denylist-test podman.workflow
=== RUN   ext.config.chrony.dhcp-propagation
systemctl status kola-runext.service:
● kola-runext.service
     Loaded: loaded (/etc/systemd/system/kola-runext.service; static)
     Active: deactivating (stop-sigterm) (Result: exit-code) since Fri 2020-10-02 19:23:26 UTC; 864ms ago
    Process: 1245 ExecStart=/usr/local/bin/kola-runext-dhcp-propagation (code=exited, status=1/FAILURE)
   Main PID: 1245 (code=exited, status=1/FAILURE)
      Tasks: 2 (limit: 1071)
     Memory: 162.9M
     CGroup: /system.slice/kola-runext.service
             └─4129 /usr/bin/conmon --api-version 1 -c bde647eb6aedb05d33481e35c242a43ec7bf5a993083dc5c5deb43a1d6ff087d -u bde647eb6aedb05d33481e35c242a43ec7bf5a993083dc5c5deb43a1d6ff087d -r /usr/bin/runc -b /var/lib/containers/storage/d

Oct 02 19:23:24 qemu0 kola-runext-dhcp-propagation[1245]: + [[ MS Name/IP address         Stratum Poll Reach LastRx Last sample
Oct 02 19:23:24 qemu0 kola-runext-dhcp-propagation[1245]: ===============================================================================
Oct 02 19:23:24 qemu0 kola-runext-dhcp-propagation[1245]: ^+ 68-69-221-61.nbfr.hsdb.s>     1   6   377    29   -428us[ -428us] +/-   39ms
Oct 02 19:23:24 qemu0 kola-runext-dhcp-propagation[1245]: ^- ns2.vedur.is                  3   6   377    28  -8670us[-8670us] +/-  105ms
Oct 02 19:23:24 qemu0 kola-runext-dhcp-propagation[1245]: ^* ip.0xt.ca                     2   6   377    31  +1909us[+1071us] +/-   17ms
Oct 02 19:23:24 qemu0 kola-runext-dhcp-propagation[1245]: ^- ht-time01.isnic.is            1   6   377    29  -8027us[-8027us] +/-   66ms != *\t\i\m\e\-\c\-\g\.\n\i\s\t\.\g\o\v* ]]
Oct 02 19:23:24 qemu0 kola-runext-dhcp-propagation[1245]: + echo 'waiting for ntp server to appear'
Oct 02 19:23:24 qemu0 kola-runext-dhcp-propagation[1245]: waiting for ntp server to appear
Oct 02 19:23:24 qemu0 kola-runext-dhcp-propagation[1245]: + sleep 1
Oct 02 19:23:25 qemu0 kola-runext-dhcp-propagation[1245]: + retries=1
Oct 02 19:23:25 qemu0 kola-runext-dhcp-propagation[1245]: + [[ 1 -gt 0 ]]
Oct 02 19:23:25 qemu0 kola-runext-dhcp-propagation[1245]: + [[ ! MS Name/IP address         Stratum Poll Reach LastRx Last sample
Oct 02 19:23:25 qemu0 kola-runext-dhcp-propagation[1245]: ===============================================================================
Oct 02 19:23:25 qemu0 kola-runext-dhcp-propagation[1245]: ^+ 68-69-221-61.nbfr.hsdb.s>     1   6   377    29   -428us[ -428us] +/-   39ms
Oct 02 19:23:25 qemu0 kola-runext-dhcp-propagation[1245]: ^- ns2.vedur.is                  3   6   377    28  -8670us[-8670us] +/-  105ms
Oct 02 19:23:25 qemu0 kola-runext-dhcp-propagation[1245]: ^* ip.0xt.ca                     2   6   377    31  +1909us[+1071us] +/-   17ms
Oct 02 19:23:25 qemu0 kola-runext-dhcp-propagation[1245]: ^- ht-time01.isnic.is            1   6   377    29  -8027us[-8027us] +/-   66ms =~ time-c-g\.nist\.gov ]]
Oct 02 19:23:25 qemu0 kola-runext-dhcp-propagation[8346]: ++ chronyc sources
Oct 02 19:23:25 qemu0 kola-runext-dhcp-propagation[1245]: + NTPSERVER='MS Name/IP address         Stratum Poll Reach LastRx Last sample
Oct 02 19:23:25 qemu0 kola-runext-dhcp-propagation[1245]: ===============================================================================
Oct 02 19:23:25 qemu0 kola-runext-dhcp-propagation[1245]: ^+ 68-69-221-61.nbfr.hsdb.s>     1   6   377    30   -428us[ -428us] +/-   39ms
Oct 02 19:23:25 qemu0 kola-runext-dhcp-propagation[1245]: ^- ns2.vedur.is                  3   6   377    29  -8670us[-8670us] +/-  105ms
Oct 02 19:23:25 qemu0 kola-runext-dhcp-propagation[1245]: ^* ip.0xt.ca                     2   6   377    32  +1909us[+1071us] +/-   17ms
Oct 02 19:23:25 qemu0 kola-runext-dhcp-propagation[1245]: ^- ht-time01.isnic.is            1   6   377    30  -8027us[-8027us] +/-   66ms'
Oct 02 19:23:25 qemu0 kola-runext-dhcp-propagation[1245]: + [[ MS Name/IP address         Stratum Poll Reach LastRx Last sample
Oct 02 19:23:25 qemu0 kola-runext-dhcp-propagation[1245]: ===============================================================================
Oct 02 19:23:25 qemu0 kola-runext-dhcp-propagation[1245]: ^+ 68-69-221-61.nbfr.hsdb.s>     1   6   377    30   -428us[ -428us] +/-   39ms
Oct 02 19:23:25 qemu0 kola-runext-dhcp-propagation[1245]: ^- ns2.vedur.is                  3   6   377    29  -8670us[-8670us] +/-  105ms
Oct 02 19:23:25 qemu0 kola-runext-dhcp-propagation[1245]: ^* ip.0xt.ca                     2   6   377    32  +1909us[+1071us] +/-   17ms
Oct 02 19:23:25 qemu0 kola-runext-dhcp-propagation[1245]: ^- ht-time01.isnic.is            1   6   377    30  -8027us[-8027us] +/-   66ms != *\t\i\m\e\-\c\-\g\.\n\i\s\t\.\g\o\v* ]]
Oct 02 19:23:25 qemu0 kola-runext-dhcp-propagation[1245]: + echo 'waiting for ntp server to appear'
Oct 02 19:23:25 qemu0 kola-runext-dhcp-propagation[1245]: waiting for ntp server to appear
Oct 02 19:23:25 qemu0 kola-runext-dhcp-propagation[1245]: + sleep 1
Oct 02 19:23:26 qemu0 kola-runext-dhcp-propagation[1245]: + retries=0
Oct 02 19:23:26 qemu0 kola-runext-dhcp-propagation[1245]: + [[ 0 -gt 0 ]]
Oct 02 19:23:26 qemu0 kola-runext-dhcp-propagation[1245]: + '[' 0 -eq 0 ']'
Oct 02 19:23:26 qemu0 kola-runext-dhcp-propagation[1245]: + echo 'propagation of ntp server information via dhcp failed'
Oct 02 19:23:26 qemu0 kola-runext-dhcp-propagation[1245]: propagation of ntp server information via dhcp failed
Oct 02 19:23:26 qemu0 kola-runext-dhcp-propagation[1245]: + exit 1
Oct 02 19:23:26 qemu0 systemd[1]: kola-runext.service: Main process exited, code=exited, status=1/FAILURE
--- FAIL: ext.config.chrony.dhcp-propagation (376.15s)
        harness.go:694: kolet failed: : kolet run-test-unit failed: Error: Unit kola-runext.service exited with code 1
2020-10-02T19:23:27Z cli: Unit kola-runext.service exited with code 1: Process exited with status 1
FAIL, output in tmp/kola
Error: harness: test suite failed
2020-10-02T19:23:29Z cli: harness: test suite failed
+ rc=1
+ set +x
@sohankunkerkar sohankunkerkar added the jira for syncing to jira label Oct 2, 2020
@sohankunkerkar
Copy link
Member

@dustymabe Thanks for tracking down this issue. I will dig into it and update this ticket with my findings.

dustymabe added a commit to dustymabe/fedora-coreos-config that referenced this issue Oct 2, 2020
@dustymabe
tests: add chrony.dhcp-propagation to denylist for f33
a666d0e 
The ext.config.chrony.dhcp-propagation test is failing on Fedora 33
for now. Exclude running the test on `next` and `next-devel`.

coreos/fedora-coreos-tracker#643
@dustymabe dustymabe mentioned this issue Oct 2, 2020
Merged
dustymabe added a commit to dustymabe/fedora-coreos-config that referenced this issue Oct 5, 2020
@dustymabe
tests: add chrony.dhcp-propagation to denylist for f33
bff87c5 
The ext.config.chrony.dhcp-propagation test is failing on Fedora 33
for now. Exclude running the test on `next` and `next-devel`.

coreos/fedora-coreos-tracker#643
(cherry picked from commit a666d0e)
dustymabe added a commit to dustymabe/fedora-coreos-config that referenced this issue Oct 5, 2020
@dustymabe
tests: add chrony.dhcp-propagation to denylist for f33
138f72e 
The ext.config.chrony.dhcp-propagation test is failing on Fedora 33
for now. Exclude running the test on `next` and `next-devel`.

coreos/fedora-coreos-tracker#643
dustymabe added a commit to coreos/fedora-coreos-config that referenced this issue Oct 5, 2020
@dustymabe
tests: add chrony.dhcp-propagation to denylist for f33
0f46156 
The ext.config.chrony.dhcp-propagation test is failing on Fedora 33
for now. Exclude running the test on `next` and `next-devel`.

coreos/fedora-coreos-tracker#643
@sohankunkerkar
Copy link
Member

Alright, after synchronous debugging with @dustymabe, it looks like the chrony.dhcp-propagation test was failing due to SELinux issues. Attaching journald logs to get better picture here:

# journalctl | grep "chrony"
Oct 13 20:32:56 fedora chronyd[880]: chronyd version 4.0-pre4 starting (+CMDMON +NTP +REFCLOCK +RTC +PRIVDROP +SCFILTER +SIGND +ASYNCDNS +NTS +SECHASH +IPV6 +DEBUG)
Oct 13 20:32:56 fedora chronyd[880]: Using right/UTC timezone to obtain leap second data
Oct 13 20:32:56 fedora audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=chronyd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Oct 13 20:33:06 fedora chronyd[880]: Selected source 159.203.82.102 (2.fedora.pool.ntp.org)
Oct 13 20:33:06 fedora chronyd[880]: System clock TAI offset set to 37 seconds
Oct 13 20:33:07 fedora chronyd[880]: Selected source 66.85.78.80 (2.fedora.pool.ntp.org)
Oct 13 20:34:12 fedora chronyd[880]: Selected source 159.203.82.102 (2.fedora.pool.ntp.org)
Oct 13 20:37:01 fedora audit[1106]: USER_CMD pid=1106 uid=1000 auid=1000 ses=1 subj=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 msg='cwd="/run/chrony-dhcp" cmd="su" exe="/usr/bin/sudo" terminal=pts/0 res=success'
Oct 13 20:37:01 fedora sudo[1106]:     core : TTY=pts/0 ; PWD=/run/chrony-dhcp ; USER=root ; COMMAND=/usr/bin/su
Oct 13 20:37:01 fedora kernel: audit: type=1123 audit(1602621421.899:247): pid=1106 uid=1000 auid=1000 ses=1 subj=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 msg='cwd="/run/chrony-dhcp" cmd="su" exe="/usr/bin/sudo" terminal=pts/0 res=success'
Oct 13 20:39:13 fedora audit[880]: AVC avc:  denied  { read } for  pid=880 comm="chronyd" name="veth-host.sources" dev="tmpfs" ino=49654 scontext=system_u:system_r:chronyd_t:s0 tcontext=system_u:object_r:initrc_var_run_t:s0 tclass=file permissive=0
Oct 13 21:02:59 fedora audit[880]: AVC avc:  denied  { read } for  pid=880 comm="chronyd" name="veth-host.sources" dev="tmpfs" ino=49654 scontext=system_u:system_r:chronyd_t:s0 tcontext=system_u:object_r:initrc_var_run_t:s0 tclass=file permissive=0
Oct 13 21:02:59 fedora kernel: audit: type=1400 audit(1602622979.925:359): avc:  denied  { read } for  pid=880 comm="chronyd" name="veth-host.sources" dev="tmpfs" ino=49654 scontext=system_u:system_r:chronyd_t:s0 tcontext=system_u:object_r:initrc_var_run_t:s0 tclass=file permissive=0
Oct 13 21:15:17 fedora audit[880]: AVC avc:  denied  { read } for  pid=880 comm="chronyd" name="veth-host.sources" dev="tmpfs" ino=49654 scontext=system_u:system_r:chronyd_t:s0 tcontext=system_u:object_r:initrc_var_run_t:s0 tclass=file permissive=0
Oct 13 21:15:17 fedora kernel: audit: type=1400 audit(1602623717.299:361): avc:  denied  { read } for  pid=880 comm="chronyd" name="veth-host.sources" dev="tmpfs" ino=49654 scontext=system_u:system_r:chronyd_t:s0 tcontext=system_u:object_r:initrc_var_run_t:s0 tclass=file permissive=0
Oct 13 21:18:23 fedora audit[880]: AVC avc:  denied  { read } for  pid=880 comm="chronyd" name="veth-host.sources" dev="tmpfs" ino=54571 scontext=system_u:system_r:chronyd_t:s0 tcontext=system_u:object_r:initrc_var_run_t:s0 tclass=file permissive=0
Oct 13 21:18:23 fedora kernel: audit: type=1400 audit(1602623903.470:362): avc:  denied  { read } for  pid=880 comm="chronyd" name="veth-host.sources" dev="tmpfs" ino=54571 scontext=system_u:system_r:chronyd_t:s0 tcontext=system_u:object_r:initrc_var_run_t:s0 tclass=file permissive=0
Oct 13 21:26:17 fedora audit[880]: AVC avc:  denied  { read } for  pid=880 comm="chronyd" name="veth-host.sources" dev="tmpfs" ino=53937 scontext=system_u:system_r:chronyd_t:s0 tcontext=system_u:object_r:initrc_var_run_t:s0 tclass=file permissive=0
Oct 13 21:26:17 fedora kernel: audit: type=1400 audit(1602624377.267:363): avc:  denied  { read } for  pid=880 comm="chronyd" name="veth-host.sources" dev="tmpfs" ino=53937 scontext=system_u:system_r:chronyd_t:s0 tcontext=system_u:object_r:initrc_var_run_t:s0 tclass=file permissive=0
Oct 13 21:31:02 fedora audit[880]: AVC avc:  denied  { read } for  pid=880 comm="chronyd" name="veth-host.sources" dev="tmpfs" ino=53937 scontext=system_u:system_r:chronyd_t:s0 tcontext=system_u:object_r:initrc_var_run_t:s0 tclass=file permissive=0
Oct 13 21:31:02 fedora kernel: audit: type=1400 audit(1602624662.922:365): avc:  denied  { read } for  pid=880 comm="chronyd" name="veth-host.sources" dev="tmpfs" ino=53937 scontext=system_u:system_r:chronyd_t:s0 tcontext=system_u:object_r:initrc_var_run_t:s0 tclass=file permissive=0

A quick fix for this issue is to set SELinux mode to permissive and run that test again. However, from the OS (FCOS, Fedora etc.) perspective, we will need to fix this issue upstream by setting up an appropriate SELinux policy for the chrony-dhcp change. I was wondering if there's a way to patch this issue in FCOS for the time being (something similar to this fix) until we wait for the upstream bits to land in FCOS.

@cgwalters
Copy link
Member

Does it work to chcon -t etc_t /run/chrony-dhcp in the code?

@cgwalters
Copy link
Member

If changing the file type doesn't help then usual SOP here is to file a Bugzilla against selinux-policy and attach the denials and let them fix it. If you want to do it yourself that's probably a lot more involved, I'd take a look at recent changes to the source code.

In this case though I think it is by far the simplest to change the target file type.

@sohankunkerkar
Copy link
Member

sohankunkerkar commented Oct 14, 2020 •
edited
Loading

FWIW, this a known issue with F-33: https://bugzilla.redhat.com/show_bug.cgi?id=1880948

@dustymabe
Copy link
Member Author

I talked with Zdenek and it's on his radar. Also proposed the bug as a Fedora 33 Freeze Exception.

@cgwalters
Copy link
Member

OK one thing I had missed is that the condition

# Exit if support for dhcp4-change landed in the chrony package.
# See upstream thread: https://listengine.tuxfamily.org/chrony.tuxfamily.org/chrony-dev/2020/05/msg00022.html
[ -f /usr/lib/NetworkManager/dispatcher.d/20-chrony-dhcp ] && \
    grep -q "dhcp4-change" /usr/lib/NetworkManager/dispatcher.d/20-chrony-dhcp && \
    exit 0

is now triggering in f33, so any fix like the chcon above needs to go in chrony itself.

@zpytela
Copy link

zpytela commented Oct 14, 2020

There are 2 PRs in place now which could address the issue. Frankly, I am not convinced it covers all scenarios, but I failed to reproduce the AVCs as reported by other users.

fedora-selinux/selinux-policy-contrib#344
fedora-selinux/selinux-policy#456

Please review if you can.

@sohankunkerkar
Copy link
Member

There are 2 PRs in place now which could address the issue. Frankly, I am not convinced it covers all scenarios, but I failed to reproduce the AVCs as reported by other users.

fedora-selinux/selinux-policy-contrib#344
fedora-selinux/selinux-policy#456

Please review if you can.

I just tested these changes on F-33 and the chrony.dhcp-propagation test is passing now.

@sohankunkerkar sohankunkerkar mentioned this issue Oct 20, 2020
Merged
@dustymabe dustymabe added the status/pending-next-release Fixed upstream. Waiting on a next release. label Oct 20, 2020
@dustymabe dustymabe mentioned this issue Oct 21, 2020
Closed
@dustymabe
Copy link
Member Author

The fix for this went into next stream release 33.20201020.1.0. Please try out the new release and report issues.

@dustymabe dustymabe removed the status/pending-next-release Fixed upstream. Waiting on a next release. label Oct 21, 2020
kelvinfan001 pushed a commit to kelvinfan001/fedora-coreos-config that referenced this issue Dec 14, 2020
@dustymabe @kelvinfan001
tests: add chrony.dhcp-propagation to denylist for f33
30e64b2 
The ext.config.chrony.dhcp-propagation test is failing on Fedora 33
for now. Exclude running the test on `next` and `next-devel`.

coreos/fedora-coreos-tracker#643
kelvinfan001 pushed a commit to kelvinfan001/fedora-coreos-config that referenced this issue Dec 14, 2020
@sohankunkerkar @kelvinfan001
kola-denylist: remove chrony.dhcp-propagation reference
2f949ca 
This reverts commit coreos@0f46156.
The new version SELinux policy(3.14.6-29) for f-33 fixes an issue with the chronyd from reading the sources file
that allows chrony to read NTP server data propagated via DHCP.

Closes: coreos/fedora-coreos-tracker#643
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@sohankunkerkar sohankunkerkar

Labels
jira for syncing to jira
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
4 participants
@cgwalters @dustymabe @zpytela @sohankunkerkar