MAAS

Network testing fail - ntp

Bug #1697209 reported by David Britton
22
This bug affects 3 people
Affects Status Importance Assigned to Milestone
MAAS
Confirmed
Undecided
Unassigned

Bug Description

MAAS Version 2.2.0~rc1 (bzr5922-0ubuntu1~16.04.1)

remote refid st t when poll reach delay offset jitter
==============================================================================
0.ubuntu.pool.n .POOL. 16 p - 64 0 0.000 0.000 0.000
1.ubuntu.pool.n .POOL. 16 p - 64 0 0.000 0.000 0.000
2.ubuntu.pool.n .POOL. 16 p - 64 0 0.000 0.000 0.000
3.ubuntu.pool.n .POOL. 16 p - 64 0 0.000 0.000 0.000
ntp.ubuntu.com .POOL. 16 p - 64 0 0.000 0.000 0.000
+69.89.207.99 .PPS. 1 u 169 256 377 49.638 1.873 2.100
+129.250.35.250 249.224.99.213 2 u 228 256 377 24.948 2.381 4.371
-72.14.183.239 216.218.254.202 2 u 220 256 377 25.269 3.026 0.473
*204.9.54.119 .CDMA. 1 u 236 256 377 34.439 3.890 1.073
-198.58.105.63 130.207.244.240 2 u 122 256 377 25.158 2.699 1.097
ntpd: error while loading shared libraries: libcap.so.2: cannot stat shared object: Permission denied
Job for ntp.service failed because the control process exited with error code. See "systemctl status ntp.service" and "journalctl -xe" for details.

Revision history for this message
Andres Rodriguez (andreserl) wrote :

Hi David,

I don't understand your bug report. Can you please elaborate?

Changed in maas:
status: New → Incomplete
Revision history for this message
David Britton (dpb) wrote :

NTP test fails every time for me. Fails to load a shared object - libcap.so.2

Changed in maas:
status: Incomplete → New
Revision history for this message
Andres Rodriguez (andreserl) wrote :

Can you please attach cloud-init logs from the ephemeral environment as well as the "systemctl status ntp.service output?

Also, make sure that:

1. You running the latest MAAS (seems you running RC1)
2. You are using the latest images.

If this is a library issue indeed, then this issue is higher up on the stack.

Changed in maas:
status: New → Incomplete
Revision history for this message
Takashi Sogabe (sogabe) wrote :
Download full text (22.3 KiB)

I encountered the same issue.
It seems that timing issues of Ubuntu image. I would like to know how to workaround that.

- MAAS
  2.1.5+bzr5596
- Image
  Ubuntu Xenial 16.04LTS

- Cloud-init log
Jun 29 03:12:23 node01 cloud-init[1100]: Generating locales (this might take a while)...
Jun 29 03:12:23 node01 pollinate[1093]: client verified challenge/response with [https://entropy.ubuntu.com/]
Jun 29 03:12:23 node01 pollinate[1093]: client hashed response from [https://entropy.ubuntu.com/]
Jun 29 03:12:23 node01 pollinate[1093]: client successfully seeded [/dev/urandom]
Jun 29 03:12:23 node01 systemd[1]: Started Pollinate to seed the pseudo random number generator.
Jun 29 03:12:23 node01 systemd[1]: Starting OpenBSD Secure Shell server...
Jun 29 03:12:23 node01 sshd[1274]: Server listening on 0.0.0.0 port 22.
Jun 29 03:12:23 node01 sshd[1274]: Server listening on :: port 22.
Jun 29 03:12:23 node01 systemd[1]: Started OpenBSD Secure Shell server.
Jun 29 03:12:23 node01 systemd[1]: Reached target Multi-User System.
Jun 29 03:12:23 node01 systemd[1]: Reached target Graphical Interface.
Jun 29 03:12:23 node01 systemd[1]: Starting Update UTMP about System Runlevel Changes...
Jun 29 03:12:23 node01 systemd[1]: Started Update UTMP about System Runlevel Changes.
Jun 29 03:12:24 node01 cloud-init[1100]: en_US.UTF-8... done
Jun 29 03:12:24 node01 cloud-init[1100]: Generation complete.
Jun 29 03:12:27 node01 cloud-init[1100]: Hit:1 http://archive.ubuntu.com/ubuntu xenial InRelease
Jun 29 03:12:27 node01 cloud-init[1100]: Get:2 http://archive.ubuntu.com/ubuntu xenial-updates InRelease [102 kB]
Jun 29 03:12:28 node01 cloud-init[1100]: Get:3 http://archive.ubuntu.com/ubuntu xenial-backports InRelease [102 kB]
Jun 29 03:12:29 node01 cloud-init[1100]: Get:4 http://archive.ubuntu.com/ubuntu xenial-security InRelease [102 kB]
Jun 29 03:12:29 node01 cloud-init[1100]: Get:5 http://archive.ubuntu.com/ubuntu xenial/main Sources [868 kB]
Jun 29 03:12:29 node01 cloud-init[1100]: Get:6 http://archive.ubuntu.com/ubuntu xenial/restricted Sources [4808 B]
Jun 29 03:12:30 node01 cloud-init[1100]: Get:7 http://archive.ubuntu.com/ubuntu xenial/universe Sources [7728 kB]
Jun 29 03:12:31 node01 cloud-init[1100]: Get:8 http://archive.ubuntu.com/ubuntu xenial/multiverse Sources [179 kB]
Jun 29 03:12:31 node01 cloud-init[1100]: Get:9 http://archive.ubuntu.com/ubuntu xenial/universe amd64 Packages [7532 kB]
Jun 29 03:12:32 node01 cloud-init[1100]: Get:10 http://archive.ubuntu.com/ubuntu xenial/universe Translation-en [4354 kB]
Jun 29 03:12:33 node01 cloud-init[1100]: Get:11 http://archive.ubuntu.com/ubuntu xenial/multiverse amd64 Packages [144 kB]
Jun 29 03:12:33 node01 cloud-init[1100]: Get:12 http://archive.ubuntu.com/ubuntu xenial/multiverse Translation-en [106 kB]
Jun 29 03:12:34 node01 cloud-init[1100]: Get:13 http://archive.ubuntu.com/ubuntu xenial-updates/main Sources [257 kB]
Jun 29 03:12:34 node01 cloud-init[1100]: Get:14 http://archive.ubuntu.com/ubuntu xenial-updates/restricted Sources [3000 B]
Jun 29 03:12:35 node01 cloud-init[1100]: Get:15 http://archive.ubuntu.com/ubuntu xenial-updates/universe Sources [162 kB]
Jun 29 03:12:35 node01 cloud-init[1100]: Get:16 http://...

Changed in maas:
status: Incomplete → Confirmed
Revision history for this message
Takashi Sogabe (sogabe) wrote :

I tried image of Ubuntu 14.04 LTS "Trusty Tahr", and the image worked well in the environment.

Revision history for this message
Marius Žalinauskas (marius-zalinauskas) wrote :
Download full text (4.1 KiB)

MAAS Version 2.1.3, same NTP problems reported by David here too. Starting ntpd fails with 'ntpd: error while loading shared libraries: libcap.so.2: cannot stat shared object: Permission denied'

More details from a random machine right after deployment failure was reported:

root@16043:~# md5sum /usr/sbin/ntpd /lib/x86_64-linux-gnu/libcap.so.2.24
acfc023bbe52589aaa37123d4241a80d /usr/sbin/ntpd
04e66ed8b7975afff143e686f6f3d4aa /lib/x86_64-linux-gnu/libcap.so.2.24
root@16043:~#
root@16043:~#
root@16043:~# ls -ld /lib/x86_64-linux-gnu /lib
drwxr-xr-x 20 root root 447 Jun 28 14:19 /lib
drwxr-xr-x 4 root root 4824 Jun 28 14:17 /lib/x86_64-linux-gnu
root@16043:~#
root@16043:~#
root@16043:~# ls -l /lib/x86_64-linux-gnu/libcap.so.2.24 /lib/x86_64-linux-gnu/libcap.so.2
lrwxrwxrwx 1 root root 14 Oct 23 2015 /lib/x86_64-linux-gnu/libcap.so.2 -> libcap.so.2.24
-rw-r--r-- 1 root root 23128 Oct 23 2015 /lib/x86_64-linux-gnu/libcap.so.2.24
root@16043:~#
root@16043:~#
root@16043:~# ldd /usr/sbin/ntpd
    linux-vdso.so.1 => (0x00007ffe931fd000)
    libcap.so.2 => /lib/x86_64-linux-gnu/libcap.so.2 (0x00007f4c13da9000)
    libopts.so.25 => /usr/lib/x86_64-linux-gnu/libopts.so.25 (0x00007f4c13b88000)
    libm.so.6 => /lib/x86_64-linux-gnu/libm.so.6 (0x00007f4c1387e000)
    libcrypto.so.1.0.0 => /lib/x86_64-linux-gnu/libcrypto.so.1.0.0 (0x00007f4c1343a000)
    libpthread.so.0 => /lib/x86_64-linux-gnu/libpthread.so.0 (0x00007f4c1321d000)
    libc.so.6 => /lib/x86_64-linux-gnu/libc.so.6 (0x00007f4c12e52000)
    /lib64/ld-linux-x86-64.so.2 (0x000055c5ff7c3000)
    libdl.so.2 => /lib/x86_64-linux-gnu/libdl.so.2 (0x00007f4c12c4e000)
root@16043:~#
root@16043:~#
root@16043:~# ntpd -h
ntpd: error while loading shared libraries: libcap.so.2: cannot stat shared object: Permission denied
root@16043:~#
root@16043:~#
root@16043:~# strace ntpd -h
execve("/usr/sbin/ntpd", ["ntpd", "-h"], [/* 19 vars */]) = 0
brk(NULL) = 0x260f000
access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f55520a9000
access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
fstat(3, 0x7ffd5413d490) = -1 EACCES (Permission denied)
close(3) = 0
open("/lib/x86_64-linux-gnu/tls/x86_64/libcap.so.2", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/lib/x86_64-linux-gnu/tls/x86_64", 0x7ffd5413d4e0) = -1 ENOENT (No such file or directory)
open("/lib/x86_64-linux-gnu/tls/libcap.so.2", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/lib/x86_64-linux-gnu/tls", 0x7ffd5413d4e0) = -1 ENOENT (No such file or directory)
open("/lib/x86_64-linux-gnu/x86_64/libcap.so.2", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/lib/x86_64-linux-gnu/x86_64", 0x7ffd5413d4e0) = -1 ENOENT (No such file or directory)
open("/lib/x86_64-linux-gnu/libcap.so.2", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\260\30\0\0\0\0\0\0"..., 832) = 832
fstat(3, 0x7ffd5413d4e0) = -1 EACCES...

Read more...

Revision history for this message
Marius Žalinauskas (marius-zalinauskas) wrote :
Download full text (6.3 KiB)

Looks like problems with AppArmour. Take a look at messages from /var/log/syslog:

Jun 29 14:10:54 16043 systemd[1]: Starting LSB: Start NTP daemon...
Jun 29 14:10:54 16043 ntp[2352]: * Starting NTP server ntpd
Jun 29 14:10:54 16043 ntpd[2362]: ntpd 4.2.8p4@1.3265-o Wed Apr 5 13:28:07 UTC 2017 (1): Starting
Jun 29 14:10:54 16043 ntpd[2362]: Command line: /usr/sbin/ntpd -p /var/run/ntpd.pid -g -u 112:116
Jun 29 14:10:54 16043 ntp[2352]: ...done.
Jun 29 14:10:54 16043 systemd[1]: Started LSB: Start NTP daemon.
Jun 29 14:10:54 16043 ntpd[2364]: proto: precision = 0.076 usec (-24)
Jun 29 14:10:54 16043 ntpd[2364]: Listen and drop on 0 v6wildcard [::]:123
Jun 29 14:10:54 16043 ntpd[2364]: Listen and drop on 1 v4wildcard 0.0.0.0:123
Jun 29 14:10:54 16043 ntpd[2364]: Listen normally on 2 lo 127.0.0.1:123
Jun 29 14:10:54 16043 ntpd[2364]: Listen normally on 3 enp3s0 93.115.27.45:123
Jun 29 14:10:54 16043 ntpd[2364]: Listen normally on 4 lo [::1]:123
Jun 29 14:10:54 16043 ntpd[2364]: Listen normally on 5 enp3s0 [fe80::202:c9ff:fe55:9ac0%4]:123
Jun 29 14:10:54 16043 ntpd[2364]: Listening on routing socket on fd #22 for interface updates
Jun 29 14:10:54 16043 cloud-init[1208]: Processing triggers for libc-bin (2.23-0ubuntu9) ...
Jun 29 14:10:54 16043 kernel: [ 40.880454] audit_printk_skb: 9 callbacks suppressed
Jun 29 14:10:54 16043 kernel: [ 40.880457] audit: type=1400 audit(1498745454.780:15): apparmor="STATUS" operation="profile_load" profile="unconfined" name="/usr/sbin/ntpd" pid=2373 comm="apparmor_parser"
Jun 29 14:10:54 16043 cloud-init[1208]: Processing triggers for systemd (229-4ubuntu17) ...
Jun 29 14:10:54 16043 systemd[1]: Reloading.
Jun 29 14:10:54 16043 systemd[1]: snapd.refresh.timer: Adding 5h 47min 45.349958s random time.
Jun 29 14:10:54 16043 systemd[1]: snapd.refresh.timer: Adding 23min 34.329195s random time.
Jun 29 14:10:54 16043 systemd[1]: Started ACPI event daemon.
Jun 29 14:10:54 16043 cloud-init[1208]: Processing triggers for ureadahead (0.100.0-19) ...
Jun 29 14:10:55 16043 systemd[1]: Stopping LSB: Start NTP daemon...
Jun 29 14:10:55 16043 ntp[2430]: * Stopping NTP server ntpd
Jun 29 14:10:55 16043 ntpd[2364]: ntpd exiting on signal 15 (Terminated)
Jun 29 14:10:55 16043 ntp[2430]: ...done.
Jun 29 14:10:55 16043 ntpd[2364]: 93.115.27.250 local addr 93.115.27.45 -> <null>
Jun 29 14:10:55 16043 systemd[1]: Stopped LSB: Start NTP daemon.
Jun 29 14:10:55 16043 systemd[1]: Starting LSB: Start NTP daemon...
Jun 29 14:10:55 16043 ntp[2443]: * Starting NTP server ntpd
Jun 29 14:10:55 16043 ntp[2443]: /usr/sbin/ntpd: error while loading shared libraries: libcap.so.2: cannot stat shared object: Permission denied
Jun 29 14:10:55 16043 ntp[2443]: ...fail!
Jun 29 14:10:55 16043 systemd[1]: ntp.service: Control process exited, code=exited status=127
Jun 29 14:10:55 16043 systemd[1]: Failed to start LSB: Start NTP daemon.
Jun 29 14:10:55 16043 systemd[1]: ntp.service: Unit entered failed state.
Jun 29 14:10:55 16043 systemd[1]: ntp.service: Failed with result 'exit-code'.
Jun 29 14:10:55 16043 kernel: [ 41.922900] audit: type=1400 audit(1498745455.824:16): apparmor="DENIED" operation="getattr" info="Failed name lookup - d...

Read more...

Revision history for this message
to-hiro (to-hiro) wrote :
Download full text (4.4 KiB)

I had a similar error with my 2.1.5+bzr5596-0ubuntu1~16.04.1.

Jun 29 08:41:25 nuc1-1 systemd[1]: Stopping LSB: Start NTP daemon...
Jun 29 08:41:25 nuc1-1 ntp[2504]: * Stopping NTP server ntpd
Jun 29 08:41:25 nuc1-1 ntp[2504]: ...done.
Jun 29 08:41:25 nuc1-1 ntpd[2438]: ntpd exiting on signal 15 (Terminated)
Jun 29 08:41:25 nuc1-1 ntpd[2438]: 192.168.122.1 local addr 192.168.100.113 -> <null>
Jun 29 08:41:25 nuc1-1 systemd[1]: Stopped LSB: Start NTP daemon.
Jun 29 08:41:25 nuc1-1 systemd[1]: Starting LSB: Start NTP daemon...
Jun 29 08:41:25 nuc1-1 ntp[2517]: * Starting NTP server ntpd
Jun 29 08:41:25 nuc1-1 ntp[2517]: /usr/sbin/ntpd: error while loading shared libraries: libcap.so.2: cannot stat shared object: Permission denied
Jun 29 08:41:25 nuc1-1 ntp[2517]: ...fail!
Jun 29 08:41:25 nuc1-1 systemd[1]: ntp.service: Control process exited, code=exited status=127
Jun 29 08:41:25 nuc1-1 systemd[1]: Failed to start LSB: Start NTP daemon.
Jun 29 08:41:25 nuc1-1 systemd[1]: ntp.service: Unit entered failed state.
Jun 29 08:41:25 nuc1-1 systemd[1]: ntp.service: Failed with result 'exit-code'.
Jun 29 08:41:25 nuc1-1 kernel: [ 46.122827] audit: type=1400 audit(1498725685.668:16): apparmor="DENIED" operation="getattr" info="Failed name lookup - disconnected path" error=-13 profile="/usr/sbin/ntpd" name="overlay/etc/ld.so.cache" pid=2526 comm="ntpd" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
Jun 29 08:41:25 nuc1-1 kernel: [ 46.122846] audit: type=1400 audit(1498725685.668:17): apparmor="DENIED" operation="getattr" info="Failed name lookup - disconnected path" error=-13 profile="/usr/sbin/ntpd" name="lib/x86_64-linux-gnu/libcap.so.2.24" pid=2526 comm="ntpd" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
Jun 29 08:41:25 nuc1-1 cloud-init[1276]: Cloud-init v. 0.7.9 running 'modules:config' at Thu, 29 Jun 2017 08:40:54 +0000. Up 14.84 seconds.
Jun 29 08:41:25 nuc1-1 cloud-init[1276]: 2017-06-29 08:41:25,677 - cc_ntp.py[ERROR]: Failed to reload/start ntp service: Unexpected error while running command.
Jun 29 08:41:25 nuc1-1 cloud-init[1276]: Command: ['systemctl', 'reload-or-restart', 'ntp']
Jun 29 08:41:25 nuc1-1 cloud-init[1276]: Exit code: 1
Jun 29 08:41:25 nuc1-1 cloud-init[1276]: Reason: -
Jun 29 08:41:25 nuc1-1 cloud-init[1276]: Stdout: -
Jun 29 08:41:25 nuc1-1 cloud-init[1276]: Stderr: Job for ntp.service failed because the control process exited with error code. See "systemctl status ntp.service" and "journalctl -xe" for details.
Jun 29 08:41:25 nuc1-1 cloud-init[1276]: Traceback (most recent call last):
Jun 29 08:41:25 nuc1-1 cloud-init[1276]: File "/usr/lib/python3/dist-packages/cloudinit/config/cc_ntp.py", line 78, in handle
Jun 29 08:41:25 nuc1-1 cloud-init[1276]: reload_ntp(systemd=cloud.distro.uses_systemd())
Jun 29 08:41:25 nuc1-1 cloud-init[1276]: File "/usr/lib/python3/dist-packages/cloudinit/config/cc_ntp.py", line 140, in reload_ntp
Jun 29 08:41:25 nuc1-1 cloud-init[1276]: util.subp(cmd, capture=True)
Jun 29 08:41:25 nuc1-1 cloud-init[1276]: File "/usr/lib/python3/dist-packages/cloudinit/util.py", line 1821, in subp
Jun 29 08:41:25 nuc1-1 cloud-init[1276]: cmd=args)
Jun 29 08:41:25 nuc1-1 cloud-in...

Read more...

Revision history for this message
to-hiro (to-hiro) wrote :

apparmor/library related datas from sample vm

norihiro@nuc:~/Downloads/MAASfail$ sudo grep -r ld.so ./*
./apparmor.d/usr.lib.snapd.snap-confine.real: /etc/ld.so.cache r,
./apparmor.d/usr.lib.snapd.snap-confine.real: /etc/ld.so.cache r,
./apparmor.d/abstractions/ubuntu-helpers: # paths (man ld.so)).
./apparmor.d/abstractions/base: # ld.so.cache and ld are used to load shared libraries; they are best
./apparmor.d/abstractions/base: /etc/ld.so.cache mr,
./apparmor.d/usr.sbin.rsyslogd: #/{,var/}run/mysqld/mysqld.sock rw,
./log/apt/term.log:ERROR: ld.so: object 'libeatmydata.so' from LD_PRELOAD cannot be preloaded (cannot open shared object file): ignored.
./log/cloud-init-output.log:ERROR: ld.so: object 'libeatmydata.so' from LD_PRELOAD cannot be preloaded (cannot open shared object file): ignored.
./log/syslog:Jun 30 02:02:31 nuc2-1 cloud-init[1282]: ERROR: ld.so: object 'libeatmydata.so' from LD_PRELOAD cannot be preloaded (cannot open shared object file): ignored.
norihiro@nuc:~/Downloads/MAASfail$ sudo grep -r libcap ./*
norihiro@nuc:~/Downloads/MAASfail$

Revision history for this message
Dominique Poulain (dominique-poulain) wrote :

This issue looks identical to <https://bugs.launchpad.net/cloud-init/+bug/1701297> 'NTP reload failure (causing deployment failures with MAAS)'.

Revision history for this message
Marius Žalinauskas (marius-zalinauskas) wrote :

Yup, Dominique, it definitely is. Have looked at /proc/cmdline in the lab where MAAS 2.2 is installed – it does have apparmor=0 while 2.1.x does not.

Revision history for this message
to-hiro (to-hiro) wrote :

Confirmed both following workarounds can avoid the issue.

1. Use different image (hwe) for the instance.
2. Set kernel parameter "apparmor=0" for the instance.

Revision history for this message
Dominique Poulain (dominique-poulain) wrote :

Thanks Marius, to-hiro!

The workarounds to-hiro mentioned are already mentioned by Andres in 1701297. To further clarify for future readers of this bug:

1) consists in picking the hwe-16.04 kernel instead of the default (ga) when deploying
2) involves setting the Global Kernel Parameters in Settings, per <https://docs.ubuntu.com/maas/2.1/en/installconfig-nodes-kernel-boot-options>

I will mark this bug as a duplicate of 1701297.

Revision history for this message
Marius Žalinauskas (marius-zalinauskas) wrote :

Used patch from commit https://git.launchpad.net/maas/commit/?id=df9a79b9dba9c9beee8c2c272263085f5dc02bad to modify /usr/lib/python3/dist-packages/provisioningserver/kernel_opts.py, restarted associated services and solved the problem on MAAS 2.1.

It would be nice if the patch would be officially backported to 2.1 branch.

Revision history for this message
Andres Rodriguez (andreserl) wrote :

FWIW, 2.1 is deprecated. 2.2 will replace 2.1 in Xenial in the coming weeks.

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.
Subscribing...

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.