apparmor blocks ntpd activity

Alexander, please provide more information on how to reproduce the issue and what is the impact.

There is nothing special about this bug. I did nothing to get this happens from time to time on the controllers so I don't have clear steps to reproduce that.

Setting this as Won't Fix, as this is medium not a customer-found bug.

Hi,

Hit the same bug on MOS 7.0 too, and due to this timing issue, Ceph triggered a WARN state:
root@node-120:~# ceph health detail
HEALTH_WARN clock skew detected on mon.node-120
mon.node-120 addr 192.168.0.11:6789/0 clock skew 0.0667655s > max 0.05s (latency 0.00134925s):

root@node-120:~# ntpq -p
ntpq: read: Connection refused

NTP daemon is running:
root@node-120:~# pgrep -lf ntp
7221 ntpd

This is the same error message:
root@node-120:~# dmesg | grep ntp | tail -3
[2607440.438987] type=1400 audit(1456327372.337:216): apparmor="DENIED" operation="sendmsg" info="Failed name lookup - disconnected path" error=-13 profile="/usr/sbin/ntpd" name="dev/log" pid=7221 comm="ntpd" requested_mask="w" denied_mask="w" fsuid=0 ouid=0
[2607440.439037] type=1400 audit(1456327372.337:217): apparmor="DENIED" operation="sendmsg" info="Failed name lookup - disconnected path" error=-13 profile="/usr/sbin/ntpd" name="dev/log" pid=7221 comm="ntpd" requested_mask="w" denied_mask="w" fsuid=0 ouid=0
[2607440.439086] type=1400 audit(1456327372.337:218): apparmor="DENIED" operation="sendmsg" info="Failed name lookup - disconnected path" error=-13 profile="/usr/sbin/ntpd" name="dev/log" pid=7221 comm="ntpd" requested_mask="w" denied_mask="w" fsuid=0 ouid=0

Regards,
Hamza

Just got outage of this bug on customer.
I can provide logs by your requests.

<5>Apr 13 21:04:33 controller003 kernel: [4403436.671379] type=1400 audit(1460581470.926:139): apparmor="DENIED" operation="sendmsg" info="Failed name lookup - disconnected path" error=-13 profile="/usr/sbin/ntpd" name="dev/log" pid=14761 comm="ntpd" requested_mask="w" denied_mask="w" fsuid=0 ouid=0
<5>Apr 13 21:04:39 controller003 kernel: [4403436.690432] type=1400 audit(1460581470.946:141): apparmor="DENIED" operation="sendmsg" info="Failed name lookup - disconnected path" error=-13 profile="/usr/sbin/ntpd" name="dev/log" pid=14836 comm="ntpd" requested_mask="w" denied_mask="w" fsuid=0 ouid=0
<5>Apr 13 21:04:44 controller003 kernel: [4403436.691735] type=1400 audit(1460581470.950:143): apparmor="DENIED" operation="sendmsg" info="Failed name lookup - disconnected path" error=-13 profile="/usr/sbin/ntpd" name="dev/log" pid=14836 comm="ntpd" requested_mask="w" denied_mask="w" fsuid=0 ouid=0
<133>Apr 13 21:07:42 controller003 haproxy[39530]: Server cinder-api/controller003 is UP, reason: Layer7 check passed, code: 200, info: "OK", check duration: 1420ms. 3 active and 0 backup servers online. 0 sessions requeued, 0 total in queue.
<5>Apr 13 21:09:05 cGGUTTPLDI003 kernel: [4403701.910191] type=1400 audit(1460581736.010:156): apparmor="DENIED" operation="sendmsg" info="Failed name lookup - disconnected path" error=-13 profile="/usr/sbin/ntpd" name="dev/log" pid=21670 comm="ntpd" requested_mask="w" denied_mask="w" fsuid=0 ouid=0
<133>Apr 13 21:11:28 controller003 haproxy[39530]: Server nova-metadata-api/controller003 is UP, reason: Layer7 check passed, code: 200, info: "OK", check duration: 7590ms. 3 active and 0 backup servers online. 0 sessions requeued, 0 total in queue.
<133>Apr 13 21:12:58 controller003 haproxy[39530]: Server neutron/controller003 is UP, reason: Layer7 check passed, code: 200, info: "OK", check duration: 7033ms. 3 active and 0 backup servers online. 0 sessions requeued, 0 total in queue.
<133>Apr 13 21:16:40 controller003 haproxy[39530]: Backup Server mysqld/controller003 is UP, reason: Layer7 check passed, code: 200, info: "OK", check duration: 7135ms. 1 active and 2 backup servers online. 0 sessions requeued, 0 total in queue.
<133>Apr 13 21:16:47 controller003 haproxy[39530]: Server nova-metadata-api/controller003 is UP, reason: Layer7 check passed, code: 200, info: "OK", check duration: 4316ms. 3 active and 0 backup servers online. 0 sessions requeued, 0 total in queue.
<5>Apr 13 21:21:49 controller003 kernel: [4404469.956111] type=1400 audit(1460582503.594:185): apparmor="DENIED" operation="sendmsg" info="Failed name lookup - disconnected path" error=-13 profile="/usr/sbin/ntpd" name="dev/log" pid=8787 comm="ntpd" requested_mask="w" denied_mask="w" fsuid=0 ouid=0
<5>Apr 13 21:21:57 controller003 kernel: [4404469.957537] type=1400 audit(1460582503.598:188): apparmor="DENIED" operation="sendmsg" info="Failed name lookup - disconnected path" error=-13 profile="/usr/sbin/ntpd" name="dev/log" pid=8787 comm="ntpd" requested_mask="w" denied_mask="w" fsuid=0 ouid=0
<133>Apr 13 21:21:59 controller003 haproxy[39530]: Server neutron/controller003 is UP, r...

Hi
The cause of these apparmor messages is misconfigured ntp apparmor profile,
 but there is nothing terrible

Apparmor banned only messages (like ntp successfully started and listen on socket )
 to rsyslog through /dev/log, this happened because NTP is running in the
 network namespase and apparmor has some issues with that.

Therefore apparmor doesn't not blocks ntpd activity and reason of clock skew in other place

as workaround, to allow ntp send msg to rsyslog you can Add the attach_disconnected flag
 to the ntpd profile /etc/apparmor.d/usr.sbin.ntpd
-/usr/sbin/ntpd {
+/usr/sbin/ntpd flags=(attach_disconnected) {

please note, if you want get ntpd status, you should run ntpd -nq in proper namespace:

# ip netns exec vrouter ntpq -pn
     remote refid st t when poll reach delay offset jitter
==================================================
+85.21.78.91 89.109.251.24 2 u 39m 1024 374 74.328 -7.866 1.642
*193.85.174.5 .GPS. 1 u 40m 1024 174 27.040 2.521 1.731
+191.233.81.105 213.109.127.82 3 u 851 1024 167 19.762 -8.164 3.164

closed as invalid, explanation in the comments above