event loss with dispatcher?

event loss with dispatcher?

[Klaus Heinrich Kiwi]

Hi,

 I'm trying to debug a potential problem with the dispatcher mechanism
in version 1.6.2. Long story short, I saw that some records were being
missed in the remote system (using the audisp-racf plugin), couldn't
find anything wrong with the code, so I enabled the syslog plugin,
trying to match the the syslog with the audit log output - At least in
my system, they are not matching.

In cases where there are more than one record per event, (eg. SYSCALL,
CWD, PATH), the majority of times only the syscall record is sent to the
syslog.. in rare cases I could see the path or the cwd record as well.
The impression that this would be a timing issue increased when I tried
to debug the daemon itself, placing a breakpoint in the
distribute_event() and/or dispatch_event() functions - in that case, I
could see all records going through, both in the execution path as in
the syslog.

Later also placed some debugging hooks in the process_inbound_event() in
the dispatcher code, and saw that records were already missing at that
point.

The lossy/lossless setting for the dispatcher queue doesn't appear to
affect this behavior. My tests involves a filesystem watch - when
triggered, only 3 records are generated (so not anywhere near the 128K
buffer size)

My env: RHEL 5 GA on s390x (sorry - no other box available for testing
at this time) with audit 1.6.2 (built from src.rpm as downloaded from
Steve's website).

Steve, btw, can you hold the audisp-racf merge a little bit? Found some
issues with selinux policy, the mapping to the remote system and believe
it or not, the plugin name itself :(

 Thanks,

 -Klaus Kiwi

Re: event loss with dispatcher?

[Steve Grubb]

On Thursday 08 November 2007 11:54:16 Klaus Heinrich Kiwi wrote:
> My env: RHEL 5 GA on s390x (sorry - no other box available for testing
> at this time) with audit 1.6.2 (built from src.rpm as downloaded from
> Steve's website).

Use the source rpm from rawhide or Fedora 8. There's a couple bugfixes that I 
backported from the development tarball.

> Steve, btw, can you hold the audisp-racf merge a little bit?

I was about to do that. Just send a fresh set of patches to the mail list when 
you are ready.

-Steve

Re: event loss with dispatcher?

[klausk]

[-- Attachment #1.1: Type: text/plain, Size: 708 bytes --]

(sorry for the html e-mail)

Steve Grubb <sgrubb@redhat.com> wrote on 11/08/2007 12:34:54 PM:

> On Thursday 08 November 2007 11:54:16 Klaus Heinrich Kiwi wrote:
> > My env: RHEL 5 GA on s390x (sorry - no other box available for testing
> > at this time) with audit 1.6.2 (built from src.rpm as downloaded from
> > Steve's website).
> 
> Use the source rpm from rawhide or Fedora 8. There's a couple bugfixes 
that I 
> backported from the development tarball.

Still happening on rawhide package audit-1.6.2-4

Any tips on how can I debug this further?

 Klaus
-- 
Klaus Heinrich Kiwi/Brazil/IBM <klausk@br.ibm.com>
Software Engineer
IBM STG, Linux Technology Center
Phone:(+55-19) 2132-1909 [T/L 839-1909]

[-- Attachment #1.2: Type: text/html, Size: 1039 bytes --]

[-- Attachment #2: Type: text/plain, Size: 0 bytes --]

Re: event loss with dispatcher?

[Steve Grubb]

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

Re: event loss with dispatcher?

[John Dennis]

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?

My apologies, but I haven't been following this thread because I've had 
my head down with other work, but by any chance could the missing audit 
data be explained by out of order event ID's in the audit stream? This 
was a limitation of auparse but I know Steve was planning on fixing 
this. If it hasn't been fixed auparse will appear to drop audit records 
from an event if the audit records for a single event are not 
contigious. Actually I think you'll get multiple copies of the same 
event with each copy containing only part of the audit data, a scenario 
that's confusing and would give the appearance of missing data. Just a 
thought, not sure if it's relevant.

-- 
John Dennis <jdennis@redhat.com>

Re: event loss with dispatcher?

[Steve Grubb]

On Thursday 08 November 2007 21:20:42 John Dennis wrote:
> 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?
>
> but by any chance could the missing audit data be explained by out of order
> event ID's in the audit stream?

No chance. :)

Audispd does not link against the audit parsing library nor has a concept of a 
full event - it just distributes what it has. If the configuration option is 
to send string data to plugins, it does convert the type number to a string 
value by a lookup function in libaudit, but that's full extent of it doing 
anything to the event its passing along.

-Steve

Re: event loss with dispatcher?

[Klaus Heinrich Kiwi]

On Thu, 08 Nov 2007 11:54:16 -0500, Klaus Heinrich Kiwi wrote:

> Hi,
> 
>  I'm trying to debug a potential problem with the dispatcher mechanism
> in version 1.6.2. Long story short, I saw that some records were being
> missed in the remote system (using the audisp-racf plugin), couldn't
> find anything wrong with the code, so I enabled the syslog plugin,
> trying to match the the syslog with the audit log output - At least in
> my system, they are not matching.
...

Looks like this was fixed in 1.6.4

 -Klaus K.

Re: event loss with dispatcher?

[Klaus Heinrich Kiwi]

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);

Re: event loss with dispatcher?

[James Antill]

[-- Attachment #1.1: Type: text/plain, Size: 1697 bytes --]

On Thu, 2007-11-08 at 18:15 -0500, Klaus Heinrich Kiwi wrote:
> 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:
[...]
> Still don't have a clue of what's going on. here's the patch used:

 Byte stream I/O 101. The "readv" side is:

         /* Get header first. it is fixed size */
        vec[0].iov_base = &e->hdr;
        vec[0].iov_len = sizeof(struct audit_dispatcher_header);

        /* Next payload */
        vec[1].iov_base = &e->data;
        vec[1].iov_len = MAX_AUDIT_MESSAGE_LENGTH;

        do {
                rc = readv(fd, vec, 2);
        } while (rc < 0 && errno == EINTR);
        if (rc > 0) {
                enqueue(e);
        }

...where enqueue() assumes that a single "message" and _only_ a single
"message" has been read, SOCK_STREAM makes no such guarantee. As more
messages are produced from auditd it becomes more likely the OS will
merge multiple "messages".
 The writev() sides of audispd are broken in a similar way, although
that might be more obvious as it will just start corrupting the byte
stream.

-- 
James Antill <jantill@redhat.com>

[-- Attachment #1.2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 189 bytes --]

[-- Attachment #2: Type: text/plain, Size: 0 bytes --]