Issue

Description of problem: We have a customer constantly getting the auditd service failing to start at boot with the following message: -------- 8< ---------------- 8< ---------------- 8< ---------------- 8< -------- ... auditd[987]: Error receiving audit netlink packet (No buffer space available) ... auditd[987]: Error setting audit daemon pid (No buffer space available) ... auditd[987]: Unable to set audit pid, exiting -------- 8< ---------------- 8< ---------------- 8< ---------------- 8< -------- This happens even when setting audit_backlog_limit=16384 on the kernel command line. The service being configured to restart automatically, the next start works fine and auditd seems then to be stable. ENOBUFS is expected to happen when netlink socket gets unsynchronized, which should not happen here with such large backlog, knowing that no rules are loaded at all yet (we booted the initramfs and are now just after switchroot). A few seconds before auditd starts (and fail), we can see message suppressions: -------- 8< ---------------- 8< ---------------- 8< ---------------- 8< -------- ... kernel: kauditd_printk_skb: 161 callbacks suppressed -------- 8< ---------------- 8< ---------------- 8< ---------------- 8< -------- It looks like to me this is closely related: the customer always see suppressions, but doesn't reproduce the issue when there are less than 100 suppressions. ANALYSIS AT USERSPACE LEVEL: strace shows AUDIT_SET/AUDIT_STATUS_PID message is sent, then reply is ENOBUFS: -------- 8< ---------------- 8< ---------------- 8< ---------------- 8< -------- 08:14:30.025976 sendto(3<NETLINK:[AUDIT:1274]>, [ {nlmsg_len=60, nlmsg_type=AUDIT_SET, nlmsg_flags=NLM_F_REQUEST|NLM_F_ACK, nlmsg_seq=3, nlmsg_pid=0} , "\x04\x00\x00...\x00\xfa\x04\x00..."], 60, 0, {sa_family=AF_NETLINK, nl_pid=0, nl_groups=00000000} , 12) = 60 <0.000110> ^^^^ ^^^^^^^^ AUDIT_STATUS_PID PID of auditd : 08:14:30.026106 recvfrom(3<NETLINK:[AUDIT:1274]>, 0x7ffc23e7cd90, 8988, MSG_PEEK|MSG_DONTWAIT, 0x7ffc23e7a9dc, [12]) = -1 ENOBUFS (No buffer space available) <0.000001> -------- 8< ---------------- 8< ---------------- 8< ---------------- 8< -------- We have audit_set_pid() call audit_send() which in turn calls __audit_send(), the latter waiting for Acknowledge through calling check_ack(): -------- 8< ---------------- 8< ---------------- 8< ---------------- 8< -------- 435 int audit_set_pid(int fd, uint32_t pid, rep_wait_t wmode) 436 { 437 struct audit_status s; 438 struct audit_reply rep; 439 struct pollfd pfd[1]; 440 int rc; 441 442 memset(&s, 0, sizeof(s)); 443 s.mask = AUDIT_STATUS_PID; 444 s.pid = pid; 445 rc = audit_send(fd, AUDIT_SET, &s, sizeof(s)); 446 if (rc < 0) { 447 audit_msg(audit_priority(errno), 448 "Error setting audit daemon pid (%s)", 449 strerror(-rc)); 450 return rc; 451 } : 255 int audit_send(int fd, int type, const void *data, unsigned int size) 256 { : 260 rc = __audit_send(fd, type, data, size, &seq); : 204 int __audit_send(int fd, int type, const void *data, unsigned int size, int *seq) 205 { : 239 do { 240 retval = sendto(fd, &req, req.nlh.nlmsg_len, 0, 241 (struct sockaddr*)&addr, sizeof(addr)); 242 } while (retval < 0 && errno == EINTR); 243 if (retval == (int)req.nlh.nlmsg_len) 244 return check_ack(fd); : 271 static int check_ack(int fd) 272 { : 288 rc = audit_get_reply(fd, &rep, GET_REPLY_NONBLOCKING, MSG_PEEK); : 292 } else if (rc < 0) 293 return rc; : -------- 8< ---------------- 8< ---------------- 8< ---------------- 8< -------- We have check_ack() failing with ENOBUFS, which is returned by the kernel. On the auditd level, I'm convinced auditd is just a victim of kernel's behavior, assuming it's expected the reply to be first on the netlink socket receive buffer. (EARLY) ANALYSIS AT KERNEL LEVEL: We have the following function being entered to process the message: -------- 8< ---------------- 8< ---------------- 8< ---------------- 8< -------- 1204 static int audit_receive_msg(struct sk_buff *skb, struct nlmsghdr *nlh) 1205 { : 1243 case AUDIT_SET: { 1244 struct audit_status s; : 1258 if (s.mask & AUDIT_STATUS_PID) { : 1293 if (new_pid) { 1294 /* register a new auditd connection */ 1295 err = auditd_set(req_pid, 1296 NETLINK_CB(skb).portid, 1297 sock_net(NETLINK_CB(skb).sk)); 1298 if (audit_enabled != AUDIT_OFF) 1299 audit_log_config_change("audit_pid", 1300 new_pid, 1301 auditd_pid, 1302 err ? 0 : 1); 1303 if (err) 1304 return err; 1305 1306 /* try to process any backlog */ 1307 wake_up_interruptible(&kauditd_wait); 1308 } else { : -------- 8< ---------------- 8< ---------------- 8< ---------------- 8< -------- On line 1295, auditd_set() is called, then later on line 1307 the backlog thread is unblocked. It's unclear to me who sends the reply back, I don't see this in auditd_set() at all. audit_send_reply() doesn't seem to be called as well. I believe there is a race between waking up the backlog thread and sending the reply: because the backlog buffer would be full, ENOBUFS would be returned somehow, before the AUDIT_SET reply would have been set. It's just an hypothesis for now, I'm not able to find out how and by whom the reply is actually crafted and sent. Version-Release number of selected component (if applicable): RHEL9.2 kernels including latest 5.14.0-284.18.1.el9_2.x86_64 How reproducible: Frequently on customer's system I can reproduce the issue on my QEMU/KVM quite reliably, with audit_backlog_limit=320 but definitely not with customer's settings Steps to Reproduce: 1. Install a QEMU/KVM with minimal profile 1 CPU / 2GB memory 2. Disable automatic startup of auditd service and automatic restart and set some kernel command line parameters systemctl disable auditd mkdir -p /etc/systemd/system/auditd.service.d echo -e "[Service]\nRestart=no" > /etc/systemd/system/auditd.service.d/no_restart.conf grubby --update-kernel ALL --args="audit=1 audit_rate_limit=0 audit_backlog_limit=320 log_buf_len=15M ignore_loglevel printk.devkmsg=on" reboot 3. Start auditd service by hand just after suppressions were seen on the console at login prompt (~10 seconds after login prompt appears) $ ssh vm-rhel9 systemctl start auditd Job for auditd.service failed because the control process exited with error code. See "systemctl status auditd.service" and "journalctl -xeu auditd.service" for details. $ ssh vm-rhel9 journalctl -b -u auditd Jun 29 09:52:20 vm-rhel9 systemd[1]: Starting Security Auditing Service... Jun 29 09:52:20 vm-rhel9 auditd[1147]: No plugins found, not dispatching events Jun 29 09:52:20 vm-rhel9 auditd[1147]: Error receiving audit netlink packet (No buffer space available) Jun 29 09:52:20 vm-rhel9 auditd[1147]: Error setting audit daemon pid (No buffer space available) Jun 29 09:52:20 vm-rhel9 auditd[1147]: Unable to set audit pid, exiting Jun 29 09:52:20 vm-rhel9 auditd[1146]: Cannot daemonize (Success) Jun 29 09:52:20 vm-rhel9 auditd[1146]: The audit daemon is exiting. Jun 29 09:52:20 vm-rhel9 systemd[1]: auditd.service: Control process exited, code=exited, status=1/FAILURE Actual results: See above Expected results: auditd started properly

Release Notes

No. of Comments

Resolution

Done-Errata