apparmor blocks ntpd activity

Bug #1475019 reported by Aleksandr Shaposhnikov on 2015-07-15
14
This bug affects 3 people
Affects Status Importance Assigned to Milestone
Mirantis OpenStack
High
Denis Puchkin

Bug Description

Steps to reproduce:

Deploy MOS 6.1 Release masternode.
Deploy Ubuntu+HA+GRE+Murano cluster
Let it run for ~1 day with moderate load but I'm not sure that this is required step because even after deployment of MOS you should be able to see errors in dmesg output/logs.

Observed behavior:

dmesg output on controllers shows that some ntpd actions got blocked by apparmor.

Example:
[161285.625440] type=1400 audit(1436992670.687:2852): apparmor="DENIED" operation="sendmsg" info="Failed name lookup - disconnected path" error=-13 profile="/usr/sbin/ntpd" name="dev/log" pid=38632 comm="ntpd" requested_mask="w" denied_mask="w" fsuid=0 ouid=0
[161285.625550] type=1400 audit(1436992670.687:2853): apparmor="DENIED" operation="sendmsg" info="Failed name lookup - disconnected path" error=-13 profile="/usr/sbin/ntpd" name="dev/log" pid=38632 comm="ntpd" requested_mask="w" denied_mask="w" fsuid=0 ouid=0
[161285.626730] type=1400 audit(1436992670.687:2854): apparmor="DENIED" operation="sendmsg" info="Failed name lookup - disconnected path" error=-13 profile="/usr/sbin/ntpd" name="dev/log" pid=1325 comm="ntpd" requested_mask="w" denied_mask="w" fsuid=0 ouid=0
[161285.627169] type=1400 audit(1436992670.687:2855): apparmor="DENIED" operation="sendmsg" info="Failed name lookup - disconnected path" error=-13 profile="/usr/sbin/ntpd" name="dev/log" pid=1325 comm="ntpd" requested_mask="w" denied_mask="w" fsuid=0 ouid=0
[161285.627250] type=1400 audit(1436992670.687:2856): apparmor="DENIED" operation="sendmsg" info="Failed name lookup - disconnected path" error=-13 profile="/usr/sbin/ntpd" name="dev/log" pid=1325 comm="ntpd" requested_mask="w" denied_mask="w" fsuid=0 ouid=0
[161285.630618] type=1400 audit(1436992670.691:2857): apparmor="DENIED" operation="sendmsg" info="Failed name lookup - disconnected path" error=-13 profile="/usr/sbin/ntpd" name="dev/log" pid=1325 comm="ntpd" requested_mask="w" denied_mask="w" fsuid=0 ouid=0
[161285.632064] type=1400 audit(1436992670.691:2858): apparmor="DENIED" operation="sendmsg" info="Failed name lookup - disconnected path" error=-13 profile="/usr/sbin/ntpd" name="dev/log" pid=1325 comm="ntpd" requested_mask="w" denied_mask="w" fsuid=0 ouid=0
[161285.632112] type=1400 audit(1436992670.691:2859): apparmor="DENIED" operation="sendmsg" info="Failed name lookup - disconnected path" error=-13 profile="/usr/sbin/ntpd" name="dev/log" pid=1325 comm="ntpd" requested_mask="w" denied_mask="w" fsuid=0 ouid=0
[161285.632157] type=1400 audit(1436992670.691:2860): apparmor="DENIED" operation="sendmsg" info="Failed name lookup - disconnected path" error=-13 profile="/usr/sbin/ntpd" name="dev/log" pid=1325 comm="ntpd" requested_mask="w" denied_mask="w" fsuid=0 ouid=0

Snapshot will be attached upon uploading.

Vitaly Sedelnik (vsedelnik) wrote :

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

Changed in mos:
status: New → Incomplete
assignee: nobody → Aleksandr Shaposhnikov (alashai8)
milestone: none → 6.1-updates

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.

Changed in mos:
assignee: Aleksandr Shaposhnikov (alashai8) → Vitaly Sedelnik (vsedelnik)
description: updated
Changed in mos:
importance: Undecided → Medium
status: Incomplete → Confirmed
assignee: Vitaly Sedelnik (vsedelnik) → MOS Sustaining (mos-sustaining)
Denis Meltsaykin (dmeltsaykin) wrote :

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

Changed in mos:
status: Confirmed → Incomplete
status: Incomplete → Won't Fix
Hamza (h16mara) wrote :

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

tags: added: customer-found
Andrii Petrenko (aplsms) on 2016-04-14
Changed in mos:
status: Won't Fix → New
importance: Medium → High
tags: added: support
Andrii Petrenko (aplsms) wrote :
Download full text (13.0 KiB)

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...

Denis Puchkin (dpuchkin) on 2016-04-20
Changed in mos:
assignee: MOS Maintenance (mos-maintenance) → Denis Puchkin (dpuchkin)
Denis Puchkin (dpuchkin) wrote :

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

Denis Puchkin (dpuchkin) wrote :

closed as invalid, explanation in the comments above

Changed in mos:
status: New → Invalid
To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers