100% CPU when selinux is enforcing

Asterisk Asterisk Support
1

I’ve been driving myself nuts trying to resolve a problem with running Asterisk under selinux

I’ve worked through all the various permissions, and have asterisk running just fine as far as functionality is concerned (i.e. no errors loading anything, and no selinux errors whether run as permissive or enforcing).

However, once I run it under Enforcing, the CPU jumps to 100%, and stays there.

Here’s what strace has to say about it (over and over again):

$ sudo strace -fp 5640
[pid 5640] write(1, “\0”, 1 <unfinished …>
[pid 5640] <… write resumed> ) = 1
[pid 6353] epoll_wait(22, <unfinished …>
[pid 6238] epoll_wait(12, <unfinished …>
[pid 5640] poll([{fd=-1}, {fd=0, events=POLLIN}], 2, -1) = 1 ([{fd=0, revents=POLLIN}])
[pid 5640] read(0, “”, 1) = 0
[pid 5640] write(1, “\0”, 1) = 1
[pid 5640] poll([{fd=-1}, {fd=0, events=POLLIN}], 2, -1) = 1 ([{fd=0, revents=POLLIN}])
[pid 5640] read(0, “”, 1) = 0
[pid 5640] write(1, “\0”, 1) = 1
[pid 5640] poll([{fd=-1}, {fd=0, events=POLLIN}], 2, -1) = 1 ([{fd=0, revents=POLLIN}])
[pid 5640] read(0, “”, 1) = 0
[pid 5640] write(1, “\0”, 1) = 1
[pid 5640] poll([{fd=-1}, {fd=0, events=POLLIN}], 2, -1) = 1 ([{fd=0, revents=POLLIN}])
[pid 5640] read(0, “”, 1) = 0
[pid 5640] write(1, “\0”, 1) = 1
[pid 5640] poll([{fd=-1}, {fd=0, events=POLLIN}], 2, -1) = 1 ([{fd=0, revents=POLLIN}])
[pid 5640] read(0, “”, 1) = 0
[pid 5640] write(1, “\0”, 1) = 1
[pid 5640] poll([{fd=-1}, {fd=0, events=POLLIN}], 2, -1) = 1 ([{fd=0, revents=POLLIN}])
[pid 5640] read(0, “”, 1) = 0
[pid 5640] write(1, “\0”, 1) = 1
[pid 5640] poll([{fd=-1}, {fd=0, events=POLLIN}], 2, -1) = 1 ([{fd=0, revents=POLLIN}])
[pid 5640] read(0, “”, 1) = 0
[pid 5640] write(1, “\0”, 1) = 1
[pid 5640] poll([{fd=-1}, {fd=0, events=POLLIN}], 2, -1) = 1 ([{fd=0, revents=POLLIN}])
[pid 5640] read(0, “”, 1) = 0
[pid 5640] write(1, “\0”, 1) = 1
[pid 5640] poll([{fd=-1}, {fd=0, events=POLLIN}], 2, -1) = 1 ([{fd=0, revents=POLLIN}])
[pid 5640] read(0, “”, 1) = 0
[pid 5640] write(1, “\0”, 1) = 1
[pid 5640] poll([{fd=-1}, {fd=0, events=POLLIN}], 2, -1) = 1 ([{fd=0, revents=POLLIN}])
[pid 5640] read(0, “”, 1) = 0
[pid 5640] write(1, “\0”, 1) = 1
[pid 5640] poll([{fd=-1}, {fd=0, events=POLLIN}], 2, -1) = 1 ([{fd=0, revents=POLLIN}])
[pid 5640] read(0, “”, 1) = 0
[pid 5640] write(1, “\0”, 1) = 1
[pid 5640] poll([{fd=-1}, {fd=0, events=POLLIN}], 2, -1) = 1 ([{fd=0, revents=POLLIN}])
[pid 5640] read(0, “”, 1) = 0
[pid 5640] write(1, “\0”, 1) = 1
[pid 5640] poll([{fd=-1}, {fd=0, events=POLLIN}], 2, -1) = 1 ([{fd=0, revents=POLLIN}])
[pid 5640] read(0, “”, 1) = 0
[pid 5640] write(1, “\0”, 1) = 1
[pid 5640] poll([{fd=-1}, {fd=0, events=POLLIN}], 2, -1) = 1 ([{fd=0, revents=POLLIN}])
[pid 5640] read(0, “”, 1) = 0
[pid 5640] write(1, “\0”, 1) = 1
[pid 5640] poll([{fd=-1}, {fd=0, events=POLLIN}], 2, -1) = 1 ([{fd=0, revents=POLLIN}])
[pid 5640] read(0, “”, 1) = 0
[pid 5640] write(1, “\0”, 1) = 1
[pid 5640] poll([{fd=-1}, {fd=0, events=POLLIN}], 2, -1) = 1 ([{fd=0, revents=POLLIN}])
[pid 5640] read(0, “”, 1) = 0
[pid 5640] write(1, “\0”, 1) = 1
[pid 5640] poll([{fd=-1}, {fd=0, events=POLLIN}], 2, -1) = 1 ([{fd=0, revents=POLLIN}])
[pid 5640] read(0, “”, 1) = 0
[pid 5640] write(1, “\0”, 1) = 1
[pid 5640] poll([{fd=-1}, {fd=0, events=POLLIN}], 2, -1) = 1 ([{fd=0, revents=POLLIN}])
[pid 5640] read(0, “”, 1) = 0
[pid 5640] write(1, “\0”, 1) = 1
[pid 5640] poll([{fd=-1}, {fd=0, events=POLLIN}], 2, -1) = 1 ([{fd=0, revents=POLLIN}])
[pid 5640] read(0, “”, 1) = 0
[pid 5640] write(1, “\0”, 1) = 1
[pid 5640] poll([{fd=-1}, {fd=0, events=POLLIN}], 2, -1) = 1 ([{fd=0, revents=POLLIN}])
[pid 5640] read(0, “”, 1) = 0
[pid 5640] write(1, “\0”, 1) = 1
[pid 5640] poll([{fd=-1}, {fd=0, events=POLLIN}], 2, -1) = 1 ([{fd=0, revents=POLLIN}])
[pid 5640] read(0, “”, 1) = 0
[pid 5640] write(1, “\0”, 1) = 1
[pid 5640] poll([{fd=-1}, {fd=0, events=POLLIN}], 2, -1) = 1 ([{fd=0, revents=POLLIN}])
[pid 5640] read(0, “”, 1) = 0
[pid 5640] write(1, “\0”, 1) = 1
[pid 5640] poll([{fd=-1}, {fd=0, events=POLLIN}], 2, -1) = 1 ([{fd=0, revents=POLLIN}])
[pid 5640] read(0, “”, 1) = 0
[pid 5640] write(1, “\0”, 1) = 1
[pid 5640] poll([{fd=-1}, {fd=0, events=POLLIN}], 2, -1) = 1 ([{fd=0, revents=POLLIN}])
[pid 5640] read(0, “”, 1) = 0
[pid 5640] write(1, “\0”, 1) = 1
[pid 5640] poll([{fd=-1}, {fd=0, events=POLLIN}], 2, -1) = 1 ([{fd=0, revents=POLLIN}])
[pid 5640] read(0, “”, 1) = 0
[pid 5640] write(1, “\0”, 1) = 1
[pid 5640] poll([{fd=-1}, {fd=0, events=POLLIN}], 2, -1) = 1 ([{fd=0, revents=POLLIN}])
[pid 5640] read(0, “”, 1) = 0
[pid 5640] write(1, “\0”, 1) = 1
[pid 5640] poll([{fd=-1}, {fd=0, events=POLLIN}], 2, -1) = 1 ([{fd=0, revents=POLLIN}])
[pid 5640] read(0, “”, 1) = 0
[pid 5640] write(1, “\0”, 1) = 1
[pid 5640] poll([{fd=-1}, {fd=0, events=POLLIN}], 2, -1) = 1 ([{fd=0, revents=POLLIN}])
[pid 5640] read(0, “”, 1) = 0
[pid 5640] write(1, “\0”, 1) = 1
[pid 5640] poll([{fd=-1}, {fd=0, events=POLLIN}], 2, -1) = 1 ([{fd=0, revents=POLLIN}])
[pid 5640] read(0, “”, 1) = 0
[pid 6353] <… epoll_wait resumed> , 16, 10) = 0
[pid 6238] <… epoll_wait resumed> , 16, 10) = 0
[pid 5640] write(1, “\0”, 1 <unfinished …>
[pid 6353] epoll_wait(22, <unfinished …>
[pid 6238] epoll_wait(12, <unfinished …>
[pid 5640] <… write resumed> ) = 1
[pid 5640] poll([{fd=-1}, {fd=0, events=POLLIN}], 2, -1) = 1 ([{fd=0, revents=POLLIN}])
[pid 5640] read(0, “”, 1) = 0
[pid 5640] write(1, “\0”, 1) = 1
[pid 5640] poll([{fd=-1}, {fd=0, events=POLLIN}], 2, -1) = 1 ([{fd=0, revents=POLLIN}])
[pid 5640] read(0, “”, 1) = 0
[pid 5640] write(1, “\0”, 1) = 1
[pid 5640] poll([{fd=-1}, {fd=0, events=POLLIN}], 2, -1) = 1 ([{fd=0, revents=POLLIN}])
[pid 5640] read(0, “”, 1) = 0
[pid 5640] write(1, “\0”, 1) = 1
[pid 5640] poll([{fd=-1}, {fd=0, events=POLLIN}], 2, -1) = 1 ([{fd=0, revents=POLLIN}])
[pid 5640] read(0, “”, 1) = 0
[pid 5640] write(1, “\0”, 1) = 1
[pid 5640] poll([{fd=-1}, {fd=0, events=POLLIN}], 2, -1) = 1 ([{fd=0, revents=POLLIN}])
[pid 5640] read(0, “”, 1) = 0
[pid 5640] write(1, “\0”, 1) = 1
[pid 5640] poll([{fd=-1}, {fd=0, events=POLLIN}], 2, -1) = 1 ([{fd=0, revents=POLLIN}])
[pid 5640] read(0, “”, 1) = 0
[pid 5640] write(1, “\0”, 1) = 1
[pid 5640] poll([{fd=-1}, {fd=0, events=POLLIN}], 2, -1) = 1 ([{fd=0, revents=POLLIN}])
[pid 5640] read(0, “”, 1) = 0
[pid 5640] write(1, “\0”, 1) = 1
[pid 5640] poll([{fd=-1}, {fd=0, events=POLLIN}], 2, -1) = 1 ([{fd=0, revents=POLLIN}])
[pid 5640] read(0, “”, 1) = 0
[pid 5640] write(1, “\0”, 1) = 1
[pid 5640] poll([{fd=-1}, {fd=0, events=POLLIN}], 2, -1) = 1 ([{fd=0, revents=POLLIN}])
[pid 5640] read(0, “”, 1) = 0
[pid 5640] write(1, “\0”, 1) = 1
[pid 5640] poll([{fd=-1}, {fd=0, events=POLLIN}], 2, -1) = 1 ([{fd=0, revents=POLLIN}])
[pid 5640] read(0, “”, 1) = 0
[pid 5640] write(1, “\0”, 1) = 1
[pid 5640] poll([{fd=-1}, {fd=0, events=POLLIN}], 2, -1) = 1 ([{fd=0, revents=POLLIN}])
[pid 5640] read(0, “”, 1) = 0
[pid 5640] write(1, “\0”, 1) = 1
[pid 5640] poll([{fd=-1}, {fd=0, events=POLLIN}], 2, -1) = 1 ([{fd=0, revents=POLLIN}])
[pid 5640] read(0, “”, 1) = 0
[pid 5640] write(1, “\0”, 1) = 1
[pid 5640] poll([{fd=-1}, {fd=0, events=POLLIN}], 2, -1) = 1 ([{fd=0, revents=POLLIN}])
[pid 5640] read(0, “”, 1) = 0
[pid 5640] write(1, “\0”, 1) = 1
[pid 5640] poll([{fd=-1}, {fd=0, events=POLLIN}], 2, -1) = 1 ([{fd=0, revents=POLLIN}])
[pid 5640] read(0, “”, 1) = 0
[pid 5640] write(1, “\0”, 1) = 1
[pid 5640] poll([{fd=-1}, {fd=0, events=POLLIN}], 2, -1) = 1 ([{fd=0, revents=POLLIN}])
[pid 5640] read(0, “”, 1) = 0
[pid 5640] write(1, “\0”, 1) = 1
[pid 5640] poll([{fd=-1}, {fd=0, events=POLLIN}], 2, -1) = 1 ([{fd=0, revents=POLLIN}])
[pid 5640] read(0, “”, 1) = 0
[pid 5640] write(1, “\0”, 1) = 1
[pid 5640] poll([{fd=-1}, {fd=0, events=POLLIN}], 2, -1) = 1 ([{fd=0, revents=POLLIN}])
[pid 5640] read(0, “”, 1) = 0
[pid 5640] write(1, “\0”, 1) = 1
[pid 5640] poll([{fd=-1}, {fd=0, events=POLLIN}], 2, -1) = 1 ([{fd=0, revents=POLLIN}])
[pid 5640] read(0, “”, 1) = 0
[pid 5640] write(1, “\0”, 1) = 1
[pid 5640] poll([{fd=-1}, {fd=0, events=POLLIN}], 2, -1) = 1 ([{fd=0, revents=POLLIN}])
[pid 5640] read(0, “”, 1) = 0
[pid 5640] write(1, “\0”, 1) = 1
[pid 5640] poll([{fd=-1}, {fd=0, events=POLLIN}], 2, -1) = 1 ([{fd=0, revents=POLLIN}])
[pid 5640] read(0, “”, 1) = 0
[pid 5640] write(1, “\0”, 1) = 1
[pid 5640] poll([{fd=-1}, {fd=0, events=POLLIN}], 2, -1) = 1 ([{fd=0, revents=POLLIN}])
[pid 5640] read(0, “”, 1) = 0
[pid 5640] write(1, “\0”, 1) = 1
[pid 5640] poll([{fd=-1}, {fd=0, events=POLLIN}], 2, -1) = 1 ([{fd=0, revents=POLLIN}])
[pid 5640] read(0, “”, 1) = 0
[pid 5640] write(1, “\0”, 1) = 1
[pid 5640] poll([{fd=-1}, {fd=0, events=POLLIN}], 2, -1) = 1 ([{fd=0, revents=POLLIN}])
[pid 6353] <… epoll_wait resumed> , 16, 10) = 0
[pid 6238] <… epoll_wait resumed> , 16, 10) = 0
[pid 6353] epoll_wait(22, <unfinished …>
[pid 6238] epoll_wait(12, <unfinished …>
[pid 5640] read(0, “”, 1) = 0
[pid 5640] write(1, “\0”, 1) = 1
[pid 5640] poll([{fd=-1}, {fd=0, events=POLLIN}], 2, -1) = 1 ([{fd=0, revents=POLLIN}])
[pid 5640] read(0, “”, 1) = 0
[pid 5640] write(1, “\0”, 1) = 1
[pid 5640] poll([{fd=-1}, {fd=0, events=POLLIN}], 2, -1) = 1 ([{fd=0, revents=POLLIN}])
[pid 5640] read(0, “”, 1) = 0
[pid 5640] write(1, “\0”, 1) = 1
[pid 5640] poll([{fd=-1}, {fd=0, events=POLLIN}], 2, -1) = 1 ([{fd=0, revents=POLLIN}])
[pid 5640] read(0, “”, 1) = 0
[pid 5640] write(1, “\0”, 1) = 1
[pid 5640] poll([{fd=-1}, {fd=0, events=POLLIN}], 2, -1) = 1 ([{fd=0, revents=POLLIN}])
[pid 5640] read(0, “”, 1) = 0
[pid 5640] write(1, “\0”, 1) = 1
[pid 5640] poll([{fd=-1}, {fd=0, events=POLLIN}], 2, -1) = 1 ([{fd=0, revents=POLLIN}])
[pid 5640] read(0, “”, 1) = 0
[pid 5640] write(1, “\0”, 1) = 1
[pid 5640] poll([{fd=-1}, {fd=0, events=POLLIN}], 2, -1) = 1 ([{fd=0, revents=POLLIN}])
[pid 5640] read(0, “”, 1) = 0
[pid 5640] write(1, “\0”, 1) = 1
[pid 5640] poll([{fd=-1}, {fd=0, events=POLLIN}], 2, -1) = 1 ([{fd=0, revents=POLLIN}])
[pid 5640] read(0, “”, 1) = 0
[pid 5640] write(1, “\0”, 1) = 1
[pid 5640] poll([{fd=-1}, {fd=0, events=POLLIN}], 2, -1) = 1 ([{fd=0, revents=POLLIN}])
[pid 5640] read(0, “”, 1) = 0
[pid 5640] write(1, “\0”, 1) = 1
[pid 5640] poll([{fd=-1}, {fd=0, events=POLLIN}], 2, -1) = 1 ([{fd=0, revents=POLLIN}])
[pid 5640] read(0, “”, 1) = 0
[pid 5640] write(1, “\0”, 1) = 1
[pid 5640] poll([{fd=-1}, {fd=0, events=POLLIN}], 2, -1) = 1 ([{fd=0, revents=POLLIN}])
[pid 5640] read(0, “”, 1) = 0
[pid 5640] write(1, “\0”, 1) = 1
[pid 5640] poll([{fd=-1}, {fd=0, events=POLLIN}], 2, -1) = 1 ([{fd=0, revents=POLLIN}])
[pid 5640] read(0, “”, 1) = 0
[pid 5640] write(1, “\0”, 1) = 1
[pid 5640] poll([{fd=-1}, {fd=0, events=POLLIN}], 2, -1) = 1 ([{fd=0, revents=POLLIN}])
[pid 5640] read(0, “”, 1) = 0
[pid 5640] write(1, “\0”, 1) = 1
[pid 5640] poll([{fd=-1}, {fd=0, events=POLLIN}], 2, -1) = 1 ([{fd=0, revents=POLLIN}])
[pid 5640] read(0, “”, 1) = 0
[pid 5640] write(1, “\0”, 1) = 1
[pid 5640] poll([{fd=-1}, {fd=0, events=POLLIN}], 2, -1) = 1 ([{fd=0, revents=POLLIN}])
[pid 5640] read(0, “”, 1) = 0
[pid 5640] write(1, “\0”, 1) = 1

And if I look at the file handles for Asterisk, I get this:

$ sudo ls /proc/5640/fd -l
total 0
lrwx------. 1 asterisk asterisk 64 Mar 17 23:32 0 -> /null
lrwx------. 1 asterisk asterisk 64 Mar 17 23:32 1 -> /null
lrwx------. 1 asterisk asterisk 64 Mar 17 23:32 10 -> socket:[27400]
lrwx------. 1 asterisk asterisk 64 Mar 17 23:32 11 -> socket:[27402]
lrwx------. 1 asterisk asterisk 64 Mar 17 23:32 12 -> anon_inode:[eventpoll]
lrwx------. 1 asterisk asterisk 64 Mar 17 23:32 13 -> socket:[27592]
lrwx------. 1 asterisk asterisk 64 Mar 17 23:32 14 -> socket:[27593]
lrwx------. 1 asterisk asterisk 64 Mar 17 23:32 15 -> socket:[27490]
lrwx------. 1 asterisk asterisk 64 Mar 17 23:32 16 -> socket:[27531]
lrwx------. 1 asterisk asterisk 64 Mar 17 23:32 17 -> socket:[27595]
lrwx------. 1 asterisk asterisk 64 Mar 17 23:32 18 -> socket:[27596]
lrwx------. 1 asterisk asterisk 64 Mar 17 23:32 19 -> socket:[27597]
lrwx------. 1 asterisk asterisk 64 Mar 17 23:32 2 -> /null
lrwx------. 1 asterisk asterisk 64 Mar 17 23:32 20 -> socket:[27598]
lr-x------. 1 asterisk asterisk 64 Mar 17 23:32 21 -> /dev/urandom
lrwx------. 1 asterisk asterisk 64 Mar 17 23:32 22 -> anon_inode:[eventpoll]
lr-x------. 1 asterisk asterisk 64 Mar 17 23:32 23 -> anon_inode:inotify
lrwx------. 1 asterisk asterisk 64 Mar 17 23:32 24 -> anon_inode:[eventfd]
l-wx------. 1 asterisk asterisk 64 Mar 17 23:32 25 -> /var/log/asterisk/queue_log
lrwx------. 1 asterisk asterisk 64 Mar 17 23:32 26 -> socket:[35668]
lrwx------. 1 asterisk asterisk 64 Mar 17 23:32 27 -> socket:[35669]
lrwx------. 1 asterisk asterisk 64 Mar 17 23:32 28 -> socket:[35670]
lrwx------. 1 asterisk asterisk 64 Mar 17 23:32 3 -> /var/lib/asterisk/astdb.sqlite3
lr-x------. 1 asterisk asterisk 64 Mar 17 23:32 4 -> /dev/urandom
lrwx------. 1 asterisk asterisk 64 Mar 17 23:32 5 -> socket:[27012]
l-wx------. 1 asterisk asterisk 64 Mar 17 23:32 6 -> /var/log/asterisk/messages
l-wx------. 1 asterisk asterisk 64 Mar 17 23:32 7 -> /var/log/asterisk/full
lr-x------. 1 asterisk asterisk 64 Mar 17 23:32 8 -> /dev/urandom
lrwx------. 1 asterisk asterisk 64 Mar 17 23:32 9 -> socket:[27394]

I’m at the limit of my code troubleshooting abilities. What is Asterisk trying to do? What is blocking it? I cannot find anything that explains it.

Any ideas on next steps would be gratefully appreciated.

Jim

2

Oh, another thing to note: If I log in as the user ‘asterisk’ (the user I’m running it as), and start asterisk with

$ asterisk -c

(or for shits n giggles):

$ /usr/sbin/asterisk -f -vvvg -c

The problem does not occur.

It’s only when the daemonized version runs that this CPU spike happens

I notice that when it start successfully, file descriptors 0,1 and 2 are assigned to /dev/pts/3 instead of /null, so that’s got to be a clue of some sort:

lrwx------. 1 asterisk asterisk 64 Mar 18 04:34 0 -> /dev/pts/3
lrwx------. 1 asterisk asterisk 64 Mar 18 04:34 1 -> /dev/pts/3
lrwx------. 1 asterisk asterisk 64 Mar 18 04:34 10 -> socket:[70078]
lrwx------. 1 asterisk asterisk 64 Mar 18 04:34 11 -> socket:[70079]
lrwx------. 1 asterisk asterisk 64 Mar 18 04:34 12 -> anon_inode:[eventpoll]
lrwx------. 1 asterisk asterisk 64 Mar 18 04:34 13 -> socket:[70107]
lrwx------. 1 asterisk asterisk 64 Mar 18 04:34 14 -> socket:[70108]
lrwx------. 1 asterisk asterisk 64 Mar 18 04:34 15 -> socket:[70094]
lrwx------. 1 asterisk asterisk 64 Mar 18 04:34 16 -> socket:[70100]
lrwx------. 1 asterisk asterisk 64 Mar 18 04:34 17 -> socket:[70109]
lrwx------. 1 asterisk asterisk 64 Mar 18 04:34 18 -> socket:[70110]
lrwx------. 1 asterisk asterisk 64 Mar 18 04:34 19 -> socket:[70111]
lrwx------. 1 asterisk asterisk 64 Mar 18 04:34 2 -> /dev/pts/3
lrwx------. 1 asterisk asterisk 64 Mar 18 04:34 20 -> socket:[70112]
lr-x------. 1 asterisk asterisk 64 Mar 18 04:34 21 -> /dev/urandom
lrwx------. 1 asterisk asterisk 64 Mar 18 04:34 22 -> anon_inode:[eventpoll]
lr-x------. 1 asterisk asterisk 64 Mar 18 04:34 23 -> anon_inode:inotify
lrwx------. 1 asterisk asterisk 64 Mar 18 04:34 24 -> anon_inode:[eventfd]
l-wx------. 1 asterisk asterisk 64 Mar 18 04:34 25 -> /var/log/asterisk/queue_log
lrwx------. 1 asterisk asterisk 64 Mar 18 04:34 3 -> /var/lib/asterisk/astdb.sqlite3
lr-x------. 1 asterisk asterisk 64 Mar 18 04:34 4 -> /dev/urandom
lrwx------. 1 asterisk asterisk 64 Mar 18 04:34 5 -> socket:[70072]
l-wx------. 1 asterisk asterisk 64 Mar 18 04:34 6 -> /var/log/asterisk/messages
l-wx------. 1 asterisk asterisk 64 Mar 18 04:34 7 -> /var/log/asterisk/full
lr-x------. 1 asterisk asterisk 64 Mar 18 04:34 8 -> /dev/urandom
lrwx------. 1 asterisk asterisk 64 Mar 18 04:34 9 -> socket:[70076]

3

After a bit more digging, I found this article:
https://wiki.gentoo.org/wiki/SELinux/Tutorials/Where_to_find_SELinux_permission_denial_detail
Which, after some head scratching, led me to try this:

$ sesearch --dontaudit | grep fd | grep asterisk
   dontaudit asterisk_t unpriv_userdomain : fd use ;

So … what that means is that the reason I’m not getting anything in the logs, is that any relevant errors that might have been in the /var/log/messages file have been suppressed …

$ sudo semodule --disable_dontaudit --build

Once I disable the errors, things start to show up in the logs.

Mar 24 08:53:45 ch31 setroubleshoot: SELinux is preventing /usr/sbin/asterisk from read access on the chr_file /dev/tty9. For complete SELinux messages run: sealert -l 9228e18f-8fbc-4d62-b23e-0d59072bc6
Mar 24 08:53:45 ch31 python: SELinux is preventing /usr/sbin/asterisk from read access on the chr_file /dev/tty9.#012#012*****  Plugin catchall_boolean (89.3 confidence) suggests   ******************#01k should be allowed read access on the tty9 chr_file by default.#012Then you should report this as a bug.#012You can generate a local policy module to allow this access.#012Do#012allow this access for n

aaaaaand that gives what we need to correct the problem. Fixed it by changing one of the selinux booleans:

$ sudo setsebool -P daemons_use_tty 1

Probably this is a bug, but since everybody just ignores selinux, I’ll leave this here in hopes someone finds it useful.

For the rest, it’ll be in the book (5th edition).

4

The reference to tty9 will be from the startup script, not form Asterisk itself.