Audit for live supervision

[Steve Grubb]

On Saturday 16 August 2008 07:19:27 Kay Hayen wrote:
> [ time descending, sequence number ascending problem ]
>
> > What this indicates is that there was some recursion before the syscall
> > triggered an event. The syscall context exists from sycall entry to exit.
> > If during the middle a signal is delivered, the syscall is not finished.
> > Instead it runs the signal handler associated with the signal. The signal
> > handler might make syscalls which are then handled using the existing
> > syscall context via linked list. When that occurs, the timestamp is not
> > being updated. Not sure that is appropriate or why the original time
> > really mattered. But that is what you are observing. My guess is SIGTERM
> > is being delivered during another syscall.
>
> That raised the following question to me: We have "entry" rules defined.
> When we saw that we get exit codes, the conclusion was that "entry" and
> "exit" are not different for every syscall. Can you confirm?

They are different in that some things are not defined at entry while all 
things are defined at exit. I believe you can write all audit rules as exit 
rules without any noticable differences. if have an entry rule that evaluates 
to never, then it does speed things up since it no longer needs to collect 
aux records. With respect to the time, its set when audit_log_start is called 
which is always on exit for any rules that involve syscalls (that is when the 
exit code is valid).


> I tried to change our rules to "exit,always" from "entry,always", but it
> didn't make a difference. Can you confirm that only one exit is traced and
> do you think audit can be enhanced to trace these extra exits of syscalls
> like FORK.

Yes, I think the kernel could be updated to return twice. This would need to 
be sent upstream and I think 2.6.28 is the next chance.


> > > Seems like a bug? Can you have a look at it?
> >
> > I'll check on why we don't update the time stamp during syscall
> > recursion.
>
> Thanks a lot. I guess, the expectation could be that "exit" traces have the
> datation of the "exit" and not "entry".

See above about timestamp generation.


> > Then there is a problem of correlation. If I have 1 rule that expands to
> > 2, then how can I do a compare of what's in memory vs what rules are on
> > disk? IOW, how do I tell that someone typed:
> >
> >  -a entry,always -F arch=b32 -S clone -S fork -S vfork
> >  -a entry,always -F arch=b64 -S clone -S fork -S vfork
> >
> > or just
> >
> > -a entry,always -S clone -S fork -S vfork
> >
> > because auditctl would make 2 from 1. This is a really tricky issue and
> > if we didn't care about correlation...or about outdated tools we trust
> > too much...we could do this.
>
> That's understood. And a typical danger of user friendly abstraction is
> that it causes confusion. As I said, -F was bound to "filter" in my mind.

-F means field. In this case, the filter does use the arch field to select 
which syscalls become events. But we put it before the syscall so that 
auditctl looks it up in the right table. It might possibly be more correct to 
introduce a selector for -S, but then people won't like giving it twice.


> > ausyscall x86_64 clone
> > 56
> >
> > ausyscall i386 clone
> > 120
>
> Very good. We have initially defined a hash in Python manually with what we
> encounter, but we can rather use that to create them. We specifically have
> the problem of visiting a s390 site, where it will handy to have these
> already in place. There is no such function in libaudit, is there?

For what? 


> > We have an audit parsing library. It takes this into account.
>
> I have looked at it, and auparse_init doesn't seem to support reading from
> the socket itself, does it?

You mean the netlink socket?


> It could be AUSOURCE_FILE. And there there is the issue that the logs on
> disk seem to be different from what format we get on the socket. 

yes it is.

> In an ideal world, we would like to note that the audit socket is readable,
> hand it (or an arbitrarily truncated chunk of data) from it to libaudit,
> ask it for events until it says there are not more. That would leave the
> truncated line/event issue to libaudit. Is that part of the code?

libaudit should pull complete events from the kernel unless an execve has an 
excessive number of arguments or large sized arguments.


> > Look at the syscall record. It is always emitted with multi-line records.
> > It has an items count. Each auxiliary (path in this case) record has an
> > item number. You can tell when you have everything. Single line entries
> > do not have an items field. Also note that the record comprising an event
> > comes out of the kernel in a backwards order.
>
> Ah, we simply ignored the type=PATH etc. elements. But what I mean is that
> of the syscall itself, the arguments seemed to be on new lines:
>
> This is from Python code:
>
>     data = _audit_socket.recv( 32*1024 )
>     print data
>
> node=Annuitka type=SYSCALL msg=audit(1218880198.814:42205): arch=c000003e
> syscall=59 success=yes exit=0 a0=16cc168 a1=1464c08 a2=1588008 a3=0 items=2
> ppid=3864 pid=19928 auid=4294967295 uid=1000 gid=1000 euid=1000 suid=1000
> fsuid=1000 egid=1000 sgid=1000 fsgid=1000 tty=pts3 ses=4294967295 comm="ls"
> exe="/bin/ls" key=(null)
> node=Annuitka type=EXECVE msg=audit(1218880198.814:42205): argc=2 a0="ls"
> a1="--color=auto"
>
> node=Annuitka type=CWD msg=audit(1218880198.814:42205):
> cwd="/data/home/anna/comsoft/v7a1-ps2-acs/src/acs"
> node=Annuitka type=PATH msg=audit(1218880198.814:42205): item=0
> name="/bin/ls" inode=1651626 dev=08:12 mode=0100755 ouid=0 ogid=0
> rdev=00:00
> node=Annuitka type=PATH msg=audit(1218880198.814:42205): item=1 name=(null)
> inode=779612 dev=08:12 mode=0100755 ouid=0 ogid=0 rdev=00:00
> node=Annuitka type=EOE msg=audit(1218880198.814:42205):
>
> Note that we get a SYSCALL with 2 items, and then in order the items - from
> the socket. But inbetween we get type=EXECVE it doesn't have an item
> number,

I suppose that could be fixed.

> and worse the new line before 'a1=--color-auto' is real and so is 
> the empty line after it. I have another example of a "gnash" call from
> Konqueror with no less than 29 arguments.

That is coming from here, and I think a patch was submitted fixing it.

http://lxr.linux.no/linux+v2.6.26.2/kernel/auditsc.c#L1114



> That means, in order to parse the socket, we should check argc, right? I
> think we would prefer very long lines like they are in /var/log/audit
> instead, making these kinds of steps optional.
>
> Actually I don't understand the differences in format. I assume they serve
> the purpose of making things readable?

Yes. From the kernel is a structure with some text. For logging we want it all 
text.


> > > This is in hope that indeed continued lines always start with a
> > > non-space and type lines always start with a space. Would you consider
> > > this format worthy and possible to change?
> >
> > Don't like changing formats as that affects test suites.
>
> That " type=" start is a self-confusion of ours. Starting with 1.6 the
> node= part was added, and some hack was still in place that removes
> "node=hostname" and leaves the space there. Sorry about that.

You can remove or add the node field. Its controlled by the name_format config 
item.


> > > I have no idea how much it represents and existing external interface,
> > > but I can imagine you can't change it (easily). Probably the end of
> > > type= must be detected by terminating empty line in case of those that
> > > can be continued. But it would be very ugly to have to know the event
> > > types that have this so early in the decoding process.
> >
> > We have a parsing library, auparse, that handles the rules of audit
> > parsing. Look for auparse.h for the API.
>
> If you confirm that can handles the parsing from the socket, as suggested
> above, we may persue that path and can ignore strangeness of the format
> once its handled by the library.

The audit parsing library wants to read text strings as you would find them on 
disk. The kernel keeps type separate as an integer so that decisions can be 
made about what the record means without having to do a text to int 
conversion. So, the audit daemon does the reformatting after it decides that 
it a record type that we are interested in.


> > > > > 2. We don't want to poll periodically, but rather only wake up (and
> > > > > then with minimal latency) when something interesting happened. We
> > > > > would want to poll a periodic check that forks are still reported,
> > > > > so we would detect a loss of service from audit.
> > > >
> > > > You might write a audispd plugin for this.
> > >
> > > Did you mean for the periodic check,
> >
> > There is a realtime interface for the audit stream. You can write either
> > a new event dispatcher or a plugin to the existing one. Seeing as you are
> > more concerned with assurance, I'd just replace the current dispatcher
> > with your own. I have a description of this here:
> >
> > http://people.redhat.com/sgrubb/audit/audit-rt-events.txt
>
> I saw that too, but I thought it would be better to build upon the existing
> effort. I think that's a viable alternative and potentially could be more
> robust to us. At least it could be that audisp seems to try and solve
> problems we don't have or want.

You have 4 points to get the audit stream, in order of distance from the event 
generation: the audit netlink socket, auditd realtime interface, audisp 
plugin interface, and the af_unix socket created by the af_unix plugin from 
audispd. For higher reliability where you don't want of need any other audit 
processing interfering, I would say use either of the first 2.


> Looking at the source I saw that node name is something that audisp indeed
> adds the node name and that auditd doesn't log EOEs, explaining some of the
> differences. I didn't find why audisp has extra new lines, or if auditd
> removed these.

Auditd strips these before writing to disk. The realtime interface sends the 
event just as it was received by the kernel.


> > > or for the whole job, that means our supervision process?
> >
> > The supervision process. Then again, maybe you want to replace the audit
> > daemon and handle events your own way. libaudit has all the primitives
> > for that. So, I guess that brings up the question of how you are
> > accessing the audit event stream. Are you reading straight from netlink
> > or the disk?
>
> From the files is out of question. We thought of the audit sub deamon as
> something that simply allows to access the audit stream live, but that it
> is otherwise the same as the file.

The data can be either binary or string. Binary means that its exactly the 
same format that comes from thekernel unchanged. String means that its been 
formatted just like you would see on disk. But it appears that its not 
stripping the 0X0A out of the text. It probably should.

> Like auditd would accept things from the kernel, write it to a file and hand
> it to audisp as well which would then provide it to others. Isn't that the
> design? 

Yes.

-Steve