To clarify, I don't think sshd is causing an issue, I think the audit system is in some broken state (broken from my perspective, this could be working as intended) where processes attempting to send audit messages are hanging. The backtrace is meant to show an example of a process hung trying to send an audit message. This happened almost immediately after starting osquery on the instance, where osquery attempted to acquire the audit handle when it was already being held by another process: Lacework. Hopefully this makes more sense. I ran into this issue on a subset (~20) of my instances while attempting to deploy osquery to a few hundred instances in my fleet. It looks like it's only affecting a range of kernels. I'm going to try and put together a reproduction case.

Unaffected
4.4.41-36.55.amzn1.x86_64

Affected
4.9.51-10.52.amzn1.x86_64
4.9.77-31.58.amzn1.x86_64


Preston

On Mon, Jun 18, 2018 at 11:50 AM, Richard Guy Briggs <rgb@redhat.com> wrote:
On 2018-06-14 23:12, Preston Bennes wrote:
> Greetings audit mailing list,
>
> I've got an AWS instance running an Amazon Linux kernel,
> 4.9.77-31.58.amzn1.x86_64
> with the base OS being CentOS 6. The instance had one program with the
> audit handle (Proprietary closed source software, Lacework agent). I
> installed and started OSQuery which attempted to acquire the audit handle.
> I'm unsure if osquery was successful or not, because I was unable to ssh in
> to the server to investigate. I ended up having to restart the instance.
> Almost immediately after starting osquery, sshd got stuck in D state.
> syslog has a hung task warning and backtrace that provides some information:

[reformatting dump info to be more readable...]
> INFO: task sshd:1840 blocked for more than 10 seconds.
> Tainted: G            E   4.9.77-31.58.amzn1.x86_64 #1
> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> sshd            D    0  1840   1839 0x00000080
> 0000000000000000 ffff8802025c6540 ffff88003684d940 ffff880205f3bb80
> ffff8802072582c0 ffffc900049bfc60 ffffffff81556e62 0000000000000001
> 004200ca00000001 ffff8802072582c0 0000000000000000 ffffffff81a65140
> Call Trace:
> [<ffffffff81556e62>] ? __schedule+0x242/0x700
> [<ffffffff8155734c>] schedule+0x2c/0x80
> [<ffffffff815575ee>] schedule_preempt_disabled+0xe/0x10
> [<ffffffff81558f05>] __mutex_lock_slowpath+0x95/0x110
> [<ffffffff8147a6f8>] ? __alloc_skb+0x78/0x1e0
> [<ffffffff81558f97>] mutex_lock+0x17/0x30
> [<ffffffff811178bd>] audit_receive+0x1d/0x90
> [<ffffffff814c4976>] netlink_unicast+0x176/0x220
> [<ffffffff814c4cf6>] netlink_sendmsg+0x2d6/0x390
> [<ffffffff814719fe>] sock_sendmsg+0x3e/0x50
> [<ffffffff81471ead>] SYSC_sendto+0x11d/0x150
> [<ffffffff8111c68b>] ? __audit_syscall_entry+0xbb/0x100
> [<ffffffff81003478>] ? syscall_trace_enter+0x1c8/0x2c0
> [<ffffffff814728ee>] SyS_sendto+0xe/0x10
> [<ffffffff81003b09>] do_syscall_64+0x59/0xc0
> [<ffffffff8155bd70>] entry_SYSCALL64_slow_path+0x25/0x25
>
> I've been doing some reading (ex.
> https://www.redhat.com/archives/linux-audit/2016-February/msg00025.html )
> and my understanding is that osquery should have been able to acquire the
> audit handle, trampling lacework's ("Last one wins"), but I don't have

"Last one wins" has been fixed for a couple of years now.  That
behaviour orphaned a previous daemon which was a bug.  For your usage,
there still can "only be one".  There is work to enable multiple audit
daemons, but not for this sort of reason.

> access to the Lacework code to know how it might handle that situation (I'm
> engaging their support separately). I also noticed the patch set for 4.17
> seemed to include some changes around the code path in the backtrace. I'm
> trying to understand this behavior and determine if it's a bug, if said bug
> has already been fixed by a patch between 4.9.77 and 4.17, or that this
> issue is a lack of my understanding of the behavior of the audit system. It
> is surprising to me that an audit system related issue would result in sshd
> getting stuck in D state. Several other processes on the system continued
> running without incident. Processed launched out of cron also got stuck in
> D state. I would be grateful for some expert insight. If this isn't a bug
> and is a misunderstanding on my part, is there any way to configure the
> audit system such that an issue won't result in processes getting stuck in
> D state?

I don't quite understand how sshd is implicated other than it sending
USER class messages to audit for logging.  This shouldn't conflict with
any daemon contention issues.

> Thanks,
> Preston Bennes

- RGB

--
Richard Guy Briggs <rgb@redhat.com>
Sr. S/W Engineer, Kernel Security, Base Operating Systems
Remote, Ottawa, Red Hat Canada
IRC: rgb, SunRaycer
Voice: +1.647.777.2635, Internal: (81) 32635