Re: event loss with dispatcher?

[Klaus Heinrich Kiwi <klausk@br.ibm.com>]

On Thu, 08 Nov 2007 16:55:22 -0500, Steve Grubb wrote:

> On Thursday 08 November 2007 16:17:52 klausk@br.ibm.com wrote:
>> Any tips on how can I debug this further?
> 
> I'd put some syslog()'s  in the main event loop of the dispatcher to see
> what is coming in and some in the output where its writing to the
> descriptor.
> 
> -Steve

Added a syslog() in the auditd code just before writev() to pipe, and 
another in audit dispatcher just after readv() from pipe (code attached 
in the end). I see every record coming out of the daemon, but some 
records are lost at the dispatcher input:

[watch event]
Nov  8 17:57:13 kwuser3 auditd[10304]: auditd, **out**: audit(1194562633.937:58313): arch=80000016 syscall=5 success=yes exit=3 a0=800fa310 a1=241 a2=1b6 a3=0 items=1 ppid=28559 pid=28561 auid=0 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=pts1 comm="bash" exe="/bin/bash" subj=root:system_r:unconfined_t:s0-s0:c0.c1023 key=(null)
Nov  8 17:57:13 kwuser3 auditd[10304]: auditd, **out**: audit(1194562633.937:58313):  cwd="/root/audit-1.6.2_"
Nov  8 17:57:13 kwuser3 auditd[10304]: auditd, **out**: audit(1194562633.937:58313): item=0 name="/root/file" inode=1109999 dev=fd:00 mode=0100644 ouid=0 ogid=0 rdev=00:00 obj=root:object_r:user_home_t:s0
Nov  8 17:57:13 kwuser3 audispd: audispd, **in**: audit(1194562633.937:58313): arch=80000016 syscall=5 success=yes exit=3 a0=800fa310 a1=241 a2=1b6 a3=0 items=1 ppid=28559 pid=28561 auid=0 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=pts1 comm="bash" exe="/bin/bash" subj=root:system_r:unconfined_t:s0-s0:c0.c1023 key=(null)
Nov  8 17:57:13 kwuser3 audispd: audispd, **in**: audit(1194562633.937:58313): item=0 name="/root/file" inode=1109999 dev=fd:00 mode=0100644 ouid=0 ogid=0 rdev=00:00 obj=root:object_r:user_home_t:s0

[remove rules]
Nov  8 17:58:01 kwuser3 auditd[10304]: auditd, **out**: audit(1194562681.217:58314): auid=0 subj=root:system_r:auditctl_t:s0-s0:c0.c1023 op=remove rule key=(null) list=4 res=1
Nov  8 17:58:01 kwuser3 audispd: audispd, **in**: audit(1194562681.217:58314): auid=0 subj=root:system_r:auditctl_t:s0-s0:c0.c1023 op=remove rule key=(null) list=4 res=1

[add watch again]
Nov  8 17:58:16 kwuser3 auditd[10304]: auditd, **out**: audit(1194562696.747:58315): auid=0 subj=root:system_r:auditctl_t:s0-s0:c0.c1023 op=add rule key=(null) list=4 res=1
Nov  8 17:58:16 kwuser3 audispd: audispd, **in**: audit(1194562696.747:58315): auid=0 subj=root:system_r:auditctl_t:s0-s0:c0.c1023 op=add rule key=(null) list=4 res=1

[watch event - this time not event the PATH record came through]
Nov  8 17:58:21 kwuser3 auditd[10304]: auditd, **out**: audit(1194562701.897:58316): arch=80000016 syscall=5 success=yes exit=3 a0=80122b40 a1=241 a2=1b6 a3=0 items=1 ppid=28559 pid=28561 auid=0 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=pts1 comm="bash" exe="/bin/bash" subj=root:system_r:unconfined_t:s0-s0:c0.c1023 key=(null)
Nov  8 17:58:21 kwuser3 auditd[10304]: auditd, **out**: audit(1194562701.897:58316):  cwd="/root/audit-1.6.2_"
Nov  8 17:58:21 kwuser3 auditd[10304]: auditd, **out**: audit(1194562701.897:58316): item=0 name="/root/file" inode=1109999 dev=fd:00 mode=0100644 ouid=0 ogid=0 rdev=00:00 obj=root:object_r:user_home_t:s0
Nov  8 17:58:21 kwuser3 audispd: audispd, **in**: audit(1194562701.897:58316): arch=80000016 syscall=5 success=yes exit=3 a0=80122b40 a1=241 a2=1b6 a3=0 items=1 ppid=28559 pid=28561 auid=0 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=pts1 comm="bash" exe="/bin/bash" subj=root:system_r:unconfined_t:s0-s0:c0.c1023 key=(null)

--------------

Still don't have a clue of what's going on. here's the patch used:

diff -purN audit-1.6.2/audisp/audispd.c audit-1.6.2_/audisp/audispd.c
--- audit-1.6.2/audisp/audispd.c	2007-11-08 18:06:28.000000000 -0500
+++ audit-1.6.2_/audisp/audispd.c	2007-11-08 17:48:30.000000000 -0500
@@ -697,6 +697,11 @@ static void process_inbound_event(int fd
 		rc = readv(fd, vec, 2);
 	} while (rc < 0 && errno == EINTR);
 	if (rc > 0) { 
+		char buf[MAX_AUDIT_MESSAGE_LENGTH];
+		strncpy(buf, vec[1].iov_base, vec[1].iov_len);
+		buf[vec[1].iov_len] = '\0';
+		syslog(LOG_ERR, "audispd, **in**: %s", buf);
+
 		enqueue(e);
 	}
 }
diff -purN audit-1.6.2/src/auditd-dispatch.c audit-1.6.2_/src/auditd-dispatch.c
--- audit-1.6.2/src/auditd-dispatch.c	2007-09-17 10:43:01.000000000 -0400
+++ audit-1.6.2_/src/auditd-dispatch.c	2007-11-08 17:47:00.000000000 -0500
@@ -160,6 +160,13 @@ int dispatch_event(const struct audit_re
 	vec[1].iov_base = (void*)rep->message;
 	vec[1].iov_len = rep->len;
 
+	{
+		char buf[MAX_AUDIT_MESSAGE_LENGTH];
+		strncpy(buf, vec[1].iov_base, vec[1].iov_len);
+		buf[vec[1].iov_len] = '\0';
+		syslog(LOG_ERR, "auditd, **out**: %s", buf);
+	}
+
 	do {
 		rc = writev(disp_pipe[1], vec, 2);
 	} while (rc < 0 && errno == EAGAIN && count++ < 8);