Разрешение Dovecot auth-worker отклонено для PAM и даже / dev / log

Проблема

У меня проблема с dovecot аутентификацией пользователей через pam_sss.so (в контейнере LXC, который может быть связан, а может и не быть).

# doveadm auth login semenov
Password:
passdb: semenov auth failed
extra fields:
  user=semenov

# tail /var/log/dovecot.log
...
May 02 16:41:40 auth: Debug: auth client connected (pid=11327)
May 02 16:41:40 auth: Debug: client in: AUTH    1   PLAIN   service=doveadm resp=xxxxxxxxxxxxxx (previous base64 data may contain sensitive data)
May 02 16:41:40 auth-worker(11317): Debug: pam(semenov): lookup service=dovecot
May 02 16:41:40 auth-worker(11317): Debug: pam(semenov): #1/1 style=1 msg=Password:
May 02 16:41:40 auth-worker(11317): Info: pam(semenov): pam_authenticate() failed: Authentication service cannot retrieve authentication info
May 02 16:41:42 auth: Debug: client passdb out: FAIL    1   user=semenov

Конфигурация PAM временно упрощена до минимума:

# cat /etc/pam.d/dovecot
auth requisite pam_sss.so
account requisite pam_sss.so
session requisite pam_permit.so
password requisite pam_sss.so

Запуск strace для pamtester

Чтобы убедиться, что PAM настроен правильно, давайте посмотрим, что происходит с pamtester:

# strace -tt -s 2048 pamtester dovecot semenov authenticate
...
16:28:49.898190 getuid()                = 0
16:28:49.898216 getgid()                = 0
16:28:49.898242 stat("/var/lib/sss/pipes/private/pam", {st_mode=S_IFSOCK|0600, st_size=0, ...}) = 0
16:28:49.898276 fstat(-1, 0x7ffd51cb7140) = -1 EBADF (Bad file descriptor)
16:28:49.898304 socket(PF_LOCAL, SOCK_STREAM, 0) = 3
16:28:49.898335 fcntl(3, F_GETFL)       = 0x2 (flags O_RDWR)
16:28:49.898363 fcntl(3, F_SETFL, O_RDWR|O_NONBLOCK) = 0
16:28:49.898389 fcntl(3, F_GETFD)       = 0
16:28:49.898421 fcntl(3, F_SETFD, FD_CLOEXEC) = 0
16:28:49.898449 connect(3, {sa_family=AF_LOCAL, sun_path="/var/lib/sss/pipes/private/pam"}, 110) = 0
16:28:49.898498 fstat(3, {st_mode=S_IFSOCK|0777, st_size=0, ...}) = 0
16:28:49.898537 poll([{fd=3, events=POLLOUT}], 1, 300000) = 1 ([{fd=3, revents=POLLOUT}])
16:28:49.898570 sendto(3, "\24\0\0\0\1\0\0\0\0\0\0\0\0\0\0\0", 16, MSG_NOSIGNAL, NULL, 0) = 16
....
16:28:51.375595 socket(PF_LOCAL, SOCK_DGRAM|SOCK_CLOEXEC, 0) = 4
16:28:51.375624 connect(4, {sa_family=AF_LOCAL, sun_path="/dev/log"}, 110) = 0
16:28:51.375658 sendto(4, "<86>May  2 16:28:51 pamtester: pam_sss(dovecot:auth): authentication success; logname=semenov uid=0 euid=0 tty= ruser= rhost= user=semenov", 138, MSG_NOSIGNAL, NULL, 0) = 138
...
pamtester: successfully authenticated

Факты:

uid / gid - это 0
/var/lib/sss/pipes/private/pam открывается нормально
/dev/log открывается нормально

Запуск strace для doveadm

# doveadm auth login semenov

а затем в другой консоли:

# strace -tt -s 2048 -p $(ps aufx|grep 'dovecot/auth -w'|grep -v grep|awk '{print $2}')
...
16:41:40.649304 getuid()                = 0
16:41:40.649331 getgid()                = 0
16:41:40.649358 stat("/var/lib/sss/pipes/private/pam", {st_mode=S_IFSOCK|0600, st_size=0, ...}) = 0
16:41:40.649391 fstat(-1, 0x7ffde94080e0) = -1 EBADF (Bad file descriptor)
16:41:40.649419 socket(PF_LOCAL, SOCK_STREAM, 0) = 7
16:41:40.649450 fcntl(7, F_GETFL)       = 0x2 (flags O_RDWR)
16:41:40.649478 fcntl(7, F_SETFL, O_RDWR|O_NONBLOCK) = 0
16:41:40.649505 fcntl(7, F_GETFD)       = 0
16:41:40.649532 fcntl(7, F_SETFD, FD_CLOEXEC) = 0
16:41:40.649559 connect(7, {sa_family=AF_LOCAL, sun_path="/var/lib/sss/pipes/private/pam"}, 110) = -1 EACCES (Permission denied)
16:41:40.649600 close(7)                = 0
16:41:40.649639 socket(PF_LOCAL, SOCK_DGRAM|SOCK_CLOEXEC, 0) = 7
16:41:40.649667 connect(7, {sa_family=AF_LOCAL, sun_path="/dev/log"}, 110) = -1 EACCES (Permission denied)
16:41:40.649706 close(7)                = 0
....
16:41:40.650284 socket(PF_NETLINK, SOCK_RAW, NETLINK_AUDIT) = 7
16:41:40.650312 fcntl(7, F_SETFD, FD_CLOEXEC) = 0
16:41:40.650342 sendto(7, "\200\0\0\0L\4\5\0\2\0\0\0\0\0\0\0op=PAM:authentication acct=\"semenov\" exe=\"/usr/lib/dovecot/auth\" hostname=? addr=? terminal=dovecot res=failed\0\0", 128, 0, {sa_family=AF_NETLINK, pid=0, groups=00000000}, 12) = 128
16:41:40.650385 poll([{fd=7, events=POLLIN}], 1, 500) = 1 ([{fd=7, revents=POLLIN}])
16:41:40.650417 recvfrom(7, "$\0\0\0\2\0\0\0\2\0\0\0005,\0\0\0\0\0\0\200\0\0\0L\4\5\0\2\0\0\0\0\0\0\0", 8988, MSG_PEEK|MSG_DONTWAIT, {sa_family=AF_NETLINK, pid=0, groups=00000000}, [12]) = 36
16:41:40.650449 recvfrom(7, "$\0\0\0\2\0\0\0\2\0\0\0005,\0\0\0\0\0\0\200\0\0\0L\4\5\0\2\0\0\0\0\0\0\0", 8988, MSG_DONTWAIT, {sa_family=AF_NETLINK, pid=0, groups=00000000}, [12]) = 36
16:41:40.650486 close(7)                = 0
16:41:40.650519 write(2, "\1\00211317 pam(semenov): pam_authenticate() failed: Authentication service cannot retrieve authentication info\n", 108) = 108

Факты:

uid / gid все еще 0, но:
открытие /var/lib/sss/pipes/private/pam возвращается EACCES
открытие /dev/log возвращается EACCES

Настройка LXC

Все происходит в неограниченном контейнере LXC:

# cat /usr/share/lxc/config/common.conf.d/999-my.conf
lxc.aa_profile = unconfined
lxc.cgroup.devices.allow = a
lxc.cap.drop =

Во время теста на хосте было зарегистрировано следующее:

May  2 16:41:40 pve kernel: [10218.310055] audit: type=1400 audit(1462185700.636:1342): apparmor="ALLOWED" operation="file_perm" profile="/usr/lib/dovecot/auth" name="/run/dovecot/auth-login" pid=18118 comm="auth" requested_mask="w" denied_mask="w" fsuid=0 ouid=115
May  2 16:41:40 pve kernel: [10218.310067] audit: type=1400 audit(1462185700.636:1344): apparmor="ALLOWED" operation="file_perm" profile="/usr/lib/dovecot/auth" name="/run/dovecot/auth-login" pid=18118 comm="auth" requested_mask="r" denied_mask="r" fsuid=0 ouid=115
May  2 16:41:40 pve kernel: [10218.320050] audit: type=1400 audit(1462185700.644:1346): apparmor="ALLOWED" operation="sendmsg" info="Failed name lookup - disconnected path" error=-13 profile="/usr/lib/dovecot/auth" name="run/systemd/journal/dev-log" pid=18120 comm="auth" requested_mask="w" denied_mask="w" fsuid=0 ouid=0

И это на контейнере:

May  2 16:41:40 sys kernel: [10218.319942] audit: type=1400 audit(1462185700.644:1345): apparmor="ALLOWED" operation="connect" info="Failed name lookup - disconnected path" error=-13 profile="/usr/lib/dovecot/auth" name="var/lib/sss/pipes/private/pam" pid=18120 comm="auth" requested_mask="wr" denied_mask="wr
" fsuid=0 ouid=0
May  2 16:41:40 sys kernel: [10218.320501] audit: type=1400 audit(1462185700.648:1347): apparmor="ALLOWED" operation="connect" info="Failed name lookup - disconnected path" error=-13 profile="/usr/lib/dovecot/auth" name="var/lib/sss/pipes/private/pam" pid=18120 comm="auth" requested_mask="wr" denied_mask="wr
" fsuid=0 ouid=0
May  2 16:41:40 sys kernel: [10218.320599] audit: type=1400 audit(1462185700.648:1348): apparmor="ALLOWED" operation="sendmsg" info="Failed name lookup - disconnected path" error=-13 profile="/usr/lib/dovecot/auth" name="run/systemd/journal/dev-log" pid=18120 comm="auth" requested_mask="w" denied_mask="w" fs
uid=0 ouid=0

Полное отключение apparmor на хосте LXC (update-rc.d apparmor disable && reboot) исправил проблему. Через год (после многочисленных dist-апгрейдов) проблема повторилась, но исправление помогло снова.

Буду рад найти лучшее решение.