please provide more info

Question

< timb> please provide more info

timb · Answer

after enabling force reconfigure a few hosts would immediately spewing audit log start callback supressed and audit lost messages followed immediately by ``` 984 078179 Call Trace 984 080639 schedule+0x2bc 0x89b 984 084134 schedule+0x36 0x7c 984 087280 schedule preempt disabled+0xe 0x10 984 091812 mutex lock isra 5+0x20c 0x634 984 096089 release sock+0x8f 0x94 ```

timb · Answer

which leads pretty quick to ``` 1106 935142 INFO task systemd 1 blocked for more than 120 seconds ```

npamnani · Answer

1 what other audit flags you are using 2 Can you provide output of auditctl l 3 Can you provide more log message around this line but pertaining to audit 4 Is system crashing or it becomes non responsive

timb · Answer

these should be the same flags that were in place beyond audit force reconfigure ``` name audit allow config value true name audit allow fim events value false name audit allow fork process events value false name audit allow process events value true name audit allow selinux events value false name audit allow sockets value true name audit allow unix value false name audit allow user events value true name audit debug value false name audit fim debug value false name audit fim show accesses value false name audit force reconfigure value false name audit force unconfigure value false name audit persist value true name audit show partial fim events value false name audit show untracked res warnings value false name disable audit value false ```

timb · Answer

do you want auditctl w or w o force reconfigure enabled and becoming non responsive systemd and sshd block PAM blocks so you can t log in but it still responds to ping etc

timb · Answer

load pretty much infinitely spikes

timb · Answer

i didn t see any log messages specific to audit other than audit lost type messages i can do some looking and scrub them a bit soon if you think it d be helpful

timb · Answer

this is osquery 4 0 2 on newer 4x kernels audit via osquery has been working fine on some of these for gt 1yr until the force reconfigure flag was added

timb · Answer

with and without force reconfigure the only difference appears to be the PID ``` $ sudo auditctl s enabled 1 failure 0 pid 26178 rate limit 0 backlog limit 4096 lost 0 backlog 0 loginuid immutable 0 unlocked ```

timb · Answer

after that is just a sea of audit lost and audit backlog messages let me know if there s anything else that would be useful

npamnani · Answer

< timb> auditctl l with force reconfigure

theopolis · Answer

^ also what does that look like before and after starting osquery

timb · Answer

< npamnani> auditctl l looks the same with and without force reconfigure

timb · Answer

ah l sorry i gave you s one moment

timb · Answer

osquery running w o force reconfigure ``` $ sudo auditctl l echo sudo auditctl s a always exit S connect a always exit S bind a always exit S execve a always exit S execveat enabled 1 failure 0 pid 19405 rate limit 0 backlog limit 4096 lost 0 backlog 0 loginuid immutable 0 unlocked ``` osquery stopped ``` $ sudo auditctl l echo sudo auditctl s No rules enabled 0 failure 1 pid 19405 rate limit 0 backlog limit 0 lost 0 backlog 0 loginuid immutable 0 unlocked ```

timb · Answer

no difference in either with force reconfigure on ``` $ sudo auditctl l echo sudo auditctl s a always exit S connect a always exit S bind a always exit S execve a always exit S execveat enabled 1 failure 0 pid 32732 rate limit 0 backlog limit 4096 lost 0 backlog 0 loginuid immutable 0 unlocked ```

timb · Answer

this is a box that locked up previously but i really have no way to be sure if it s in the same state because it was rebooted to recover we have seen at least one box where it was rebooted to fix this issue and immediately went back into this state as osqueryd came up during startup

npamnani · Answer

thanks < timb> will update you after analyzing

timb · Answer

much appreciated let me know if there s anything else i can do to help

npamnani · Answer

< timb> found reason

timb · Answer

that was fast haha

npamnani · Answer

I had some knowledge around this code

npamnani · Answer

confirming how this problem can stall sshd

npamnani · Answer

if you run your osquery with verbose then you should see lots of audit rules could not be correctly remove message

npamnani · Answer

please check

npamnani · Answer

problem start with check at <https github com osquery osquery blob master osquery events linux auditdnetlink cpp L503>

npamnani · Answer

this check is not correct

npamnani · Answer

since

npamnani · Answer

struct audit message struct nlmsghdr nlh char data MAX AUDIT MESSAGE LENGTH struct audit reply int type int len struct nlmsghdr nlh struct audit message msg

npamnani · Answer

this means rule object size will always be greater than MAX AUDIT MESSAGE LENGTH

npamnani · Answer

so check passes and false is returned

npamnani · Answer

Again at the call site of clearAuditConfiguration <https github com osquery osquery blob master osquery events linux auditdnetlink cpp L651>

npamnani · Answer

without closing the audit netlink handle audit netlink handle is being set to 1

npamnani · Answer

so fd leak here

npamnani · Answer

now final question why it is causing sshd to stall

npamnani · Answer

look at acquireHandle this is in a tight loop Which is calling clearAuditConfiguration and which continuously requesting of audit service in the form of audit rules which ultimately call audit receive of kernel

npamnani · Answer

via control path

npamnani · Answer

2019 10 23T12 03 49 966113+00 00 host kernel 1229 872721 mutex lock+0x2f 0x3a 2019 10 23T12 03 49 969436+00 00 host kernel 1229 876045 audit receive+0x2b 0x9b 2019 10 23T12 03 49 973024+00 00 host kernel 1229 879631 netlink unicast+0x18d 0x255 2019 10 23T12 03 49 976959+00 00 host kernel 1229 883557 netlink sendmsg+0x2df 0x3cc 2019 10 23T12 03 49 980877+00 00 host kernel 1229 887487 sock sendmsg+0x3e 0x4a 2019 10 23T12 03 49 984373+00 00 host kernel 1229 890981 SYSC sendto+0x102 0x18b 2019 10 23T12 03 49 987938+00 00 host kernel 1229 894562 audit syscall entry+0xac 0xef 2019 10 23T12 03 49 992404+00 00 host kernel 1229 899012 syscall trace enter+0x1ce 0x2b8 2019 10 23T12 03 49 996849+00 00 host kernel 1229 903454 SyS sendto+0xe 0x10 2019 10 23T12 03 50 000079+00 00 host kernel 1229 906687 do syscall 64+0x79 0x1b9 2019 10 23T12 03 50 008792+00 00 host kernel 1229 910351

timb · Answer

hmm in this case i don t see that message with verbose i can try to get a few others later today to verify but most of the hosts where this issue presented aren t ones the teams want me melting

npamnani · Answer

static void audit receive struct sk buff skb struct nlmsghdr nlh len MUST be signed for nlmsg next to be able to dec it below 0 if the nlmsg len was not aligned int len int err nlh = nlmsg hdr skb len = skb gt len mutex lock amp audit cmd mutex

timb · Answer

which is always the case isn t it

npamnani · Answer

from kernel source

npamnani · Answer

and sshd not able to acquire the mutex audit cmd mutex

npamnani · Answer

this happen when used with reconfigure

npamnani · Answer

first time there are no rules install then no issue

timb · Answer

because the problem is in deleteAuditRule

npamnani · Answer

once rules are insalled and error happen and code goes to reacquire the netlink socket then control gets in this vicious loop

npamnani · Answer

I will create a fix tomorrow hopefully it will fix your problem

npamnani · Answer

three problems

npamnani · Answer

fd leak tight loop and a check in deleteAuditRule

timb · Answer

that would be great i really appreciate your attention

theopolis · Answer

epic

Ivanlei · Answer

truly epic thank you so much < npamnani>

npamnani · Answer

sorry for delay I definitely fix this time