From mboxrd@z Thu Jan 1 00:00:00 1970 From: Klaus Heinrich Kiwi Subject: Re: event loss with dispatcher? Date: Thu, 08 Nov 2007 18:15:08 -0500 Message-ID: <1194563708.10377.13.camel@klausk.br.ibm.com> Reply-To: klausk@br.ibm.com Mime-Version: 1.0 Content-Type: text/plain Content-Transfer-Encoding: 7bit Return-path: List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Sender: linux-audit-bounces@redhat.com Errors-To: linux-audit-bounces@redhat.com To: "sgrubb@redhat.com" , "Linux-audit@redhat.com" List-Id: linux-audit@redhat.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);