Should open syscall records occur without a path record?

Should open syscall records occur without a path record?

[John D. Ramsdell]

[-- Attachment #1: Type: text/plain, Size: 946 bytes --]

I have a test suite that generates every system call analyzed by our
package.  The suite runs several programs that do a variety of things,
including opening files.  I traced the set of programs, and retrieved
the records using

ausearch -r -p P > P.txt

where P is the process ID of each traced program.

When I attempt to analyze the logs, my program blows up because it
assumes that every syscall audit event for the open syscall will
include a PATH record.  I made a quick edit of the analysis program,
and discovered that 24 open syscall records have no PATH record, and
sometimes the CWD record is missing too.

$ python auditopen.py -i ../autsv/*.txt
Of 421 events with a SYSCALL record with syscall=open
401 have CWD
397 have PATH
0 have CWD but no PATH
$

Is it appropriate for audit analysis programs to assume a PATH record
will be available with every open syscall event?  I cannot see how to
do my analysis without the PATH record.


[-- Attachment #2: audit open check --]
[-- Type: text/plain, Size: 7616 bytes --]

#! /usr/bin/python -E

"""Analyzes audit output.

Some more documentation should go here.

Package: @PACKAGE@
Version: @VERSION@

"""

# Authors: John D. Ramsdell
#
# Copyright (C) 2007 The MITRE Corporation
# see file 'COPYING' for use and warranty information
#
# This program is free software; you can redistribute it and/or
# modify it under the terms of the GNU General Public License as
# published by the Free Software Foundation; version 2 only
#
# This program is distributed in the hope that it will be useful,
# but WITHOUT ANY WARRANTY; without even the implied warranty of
# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
# GNU General Public License for more details.
#
# You should have received a copy of the GNU General Public License
# along with this program; if not, write to the Free Software
# Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA 02111-1307 USA

import sys, getopt, auparse, os.path, copy, string

# Log Parsing

class AuditLog(object):
    """AuditLog(AuParser or file, bool)

    Encapsulates a log accessed by the auparse module.  It provides an
    iterator to the log's events.  Each call to the next method of
    the iterator returns an AuditEvent.  The boolean determines if
    numeric entities in fields are interpreted.

    """
    def __init__(self, au, interpret = False):
        if isinstance(au, file):
            self.au = auparse.AuParser(auparse.AUSOURCE_FILE_POINTER, au)
        else:
            self.au = au
        self.interpret = interpret

    def __iter__(self):
        return AuditLogIter(self)

class AuditLogIter(object):
    """AuditLogIter(AuditLog)

    An iterator for an audit log.

    """
    def __init__(self, aulog):
        self.au = aulog.au
        self.interpret = aulog.interpret

    def next(self):
        """Returns an AuditEvent

        """
        au = self.au
        interpret = self.interpret
        if not au.parse_next_event():
            raise StopIteration()
        event = AuditEvent(au.get_timestamp())
        for i in range(au.get_num_records()):
            record = AuditRecord(event)
            for j in range(au.get_num_fields()):
                name = au.get_field_name()
                if interpret:
                    value = au.interpret_field()
                else:
                    value = au.get_field_str()
                record[name] = value
                au.next_field()
            event.append(record)
            au.next_record()
        return event

class AuditEvent(list):
    """AuditEvent(AuEvent)

    An audit event is represented as a list of AuditRecord's.  Each
    AuditRecord is a dictionary that represents one of the records
    that make up the event.

    """
    def __init__(self, timestamp):
        self.timestamp = timestamp

    def get_timestamp(self):
        """Get the timestamp associated with this event."""
        return self.timestamp

    def find_record_of_type(self, typ):
        """Find record of type

        Returns a record in the event that has the given type.
        Returns None when there is no such record.

        """
        for record in self:
            try:                 
                if record["type"] == typ:
                    return record
            except KeyError:
                pass
        return None

    def find_value(self, name):
        """Find a value

        Returns a value associated with the given name in some record
        in the event.  Raises KeyError if no field has the given name.

        """
        for record in self:
            try:
                return record[name]
            except KeyError:
                pass
        raise KeyError

    def find_path_record(self, item):
        """Find a PATH record for the given item.

        Returns the PATH record for the given item.  Return None if
        PATH record cannot be found.

        """
        item = str(item)                # Ensure item is a string
        for record in self:
            if record.is_path_record(item):
                return record
        return None

class AuditRecord(dict):
    """AuditRecord(AuditEvent)

    An audit record is a dictionary.
    
    """
    def __init__(self, event):
        self.event = event

    def get_event(self):
        """Get the event associated with this record."""
        return self.event
    
    def is_path_record(self, item):
        """Is this a PATH record for the given item?"""
        try:
            return self["type"] == "PATH" and self["item"] == item
        except KeyError:
            return False

def args2aulog():
    """Make an AuditLog from command line arguments

    Create an audit log object based on the command line arguments
    passsed to this program.

    Returns an AuditLog.

    """
    interpret = False                   # Event reading mode
    output_file = None                  # Output file name for results
    try:
        long_opts = ["help", "interpret", "raw", "output="]
        opts, args = getopt.getopt(sys.argv[1:], "hiro:", long_opts)
    except getopt.GetoptError:
        # Bad options
        usage()
        sys.exit(2)
    for o, a in opts:
        if o in ("-h", "--help"):
            # Print help information
            usage()
            sys.exit(0)
        elif o in ("-i", "--interpret"):
            interpret = True
        elif o in ("-r", "--raw"):
            interpret = False
        elif o in ("-o", "--output"):
            # Record output file name
            output_file = a
    # Determine input source
    if len(args) > 0:
        au = auparse.AuParser(auparse.AUSOURCE_FILE_ARRAY, args)
        sys.stdin.close()
    else:
        au = sys.stdin
    # Open output file as standard output
    if output_file:
        sys.stdout.close()
        try:
            sys.stdout = file(output_file, 'w')
        except IOError:
            sys.stderr.write("cannot open %s for writing" % output_file)
            sys.exit(1)
    return AuditLog(au, interpret)

def usage():
    """Show usage

    Print a ussage message that includes version information.

    """
    help = """Version: %s %s
Usage: %s [OPTIONS] [FILE...]

  -o FILE, --output=FILE     output to FILE (default is standard output)
  -i,      --interpret       interpret numeric entities into text
  -r       --raw             do not interpret numeric entities (default)
  -h,      --help            print this message and exit

With no FILEs, read from the standard input.
"""
    sys.stderr.write(help % ("@PACKAGE@", "@VERSION@", sys.argv[0]))

# Consume a log

def run(log):
    """The main loop for consuming a log."""
    openno = 0
    cwdno = 0
    pathno = 0
    cwdnopathno = 0
    for event in log:
        record = event.find_record_of_type("SYSCALL")
        if record:
            syscall = record["syscall"]
            if syscall == "open":
                openno = openno + 1
                has_cwd = event.find_record_of_type("CWD")
                has_path = event.find_record_of_type("PATH")
                if has_cwd:
                    cwdno = cwdno + 1
                if has_path:
                    pathno = pathno + 1
                if has_path and not has_cwd:
                    cwdnopathno = cwdnopathno + 1
    print "Of %d events with a SYSCALL record with syscall=open" % openno
    print "%d have CWD" % cwdno
    print "%d have PATH" % pathno
    print "%d have CWD but no PATH" % cwdnopathno

def main():
    """Main routine

    Perform command line processing and then conume the log.

    """
    run(args2aulog())

if __name__ == "__main__":
    main()

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

Re: Should open syscall records occur without a path record?

[Steve Grubb]

On Monday 23 July 2007 09:09:22 John D. Ramsdell wrote:
> Is it appropriate for audit analysis programs to assume a PATH record
> will be available with every open syscall event?  I cannot see how to
> do my analysis without the PATH record.

There should be a PATH record for every open. Have you verified the logs or 
trusting ausearch? (Trying to figure out if there is a kernel problem or 
search problem.) As a first step, I'd construct some kind of regex command to 
see if you can verify that the kernel is recording PATH records for all 
opens. You may need to narrow the test case so that there aren't as many 
records to dig through.

-Steve

Re: Should open syscall records occur without a path record?

[John D. Ramsdell]

Steve Grubb <sgrubb@redhat.com> writes:

> There should be a PATH record for every open.

Okay, I'll direct my search as you suggested.  I'll delete the current
audit log, restart my daemon, run the test suite, and then compare the
raw log with what one gets from ausearch.  I'll modify my python
program to print the timestamp of an open event without a path, easing
the task of finding the record in the raw data.  Alas, the part of my
day free of meetings is at an end, but I'll get on this soon.

John

PS.  The output of my program should have said:

$ python auditopen.py -i ../autsv/*.txt
Of 421 events with a SYSCALL record with syscall=open
401 have CWD
397 have PATH
0 have PATH but no CWN
$

The last line in the original message erroneously said:

0 have CWD but no PATH

Re: Should open syscall records occur without a path record?

[John D. Ramsdell]

Steve Grubb <sgrubb@redhat.com> writes:

> There should be a PATH record for every open. Have you verified the
> logs or trusting ausearch?

The short version of what I found is that the missing PATH records
always appear in the raw logs, but both ausearch and auparse fail to
return some PATH records with their associated SYSCALL record.  A PATH
record gets ignored when another syscall event record occurs between
the SYSCALL record and the PATH record.

I'll send you a long version of my results off line as the data to
support the report is voluminous.

John

Re: Should open syscall records occur without a path record?

[Steve Grubb]

On Monday 23 July 2007 14:47:33 John D. Ramsdell wrote:
> A PATH record gets ignored when another syscall event record occurs between
> the SYSCALL record and the PATH record.

OK good. That is a known problem (bz 235398) that should be worked on right 
after we get the improved dispatcher finished. 

-Steve

Re: Should open syscall records occur without a path record?

[John D. Ramsdell]

Steve Grubb <sgrubb@redhat.com> writes:

> OK good. That is a known problem (bz 235398) that should be worked
> on right after we get the improved dispatcher finished.

Hmm.  I'm wedged if I cannot process open system call records.  I bet
I can quickly write some script that interchanges adjacent audit
records that are out of order in the raw logs, so as to allow me to
proceed.  If someone else has a record sorter, please send it along.

John

Re: Should open syscall records occur without a path record?

[Steve Grubb]

On Monday 23 July 2007 15:41:31 John D. Ramsdell wrote:
> I bet
> I can quickly write some script that interchanges adjacent audit
> records that are out of order in the raw logs, so as to allow me to
> proceed.  If someone else has a record sorter, please send it along.

setroubleshoot is written in python and it sorts its input stream to solve 
this in the mean time. You might look there for some example code.

-Steve

Re: Should open syscall records occur without a path record?

[John D. Ramsdell]

Steve Grubb <sgrubb@redhat.com> writes:

> setroubleshoot is written in python and it sorts its input stream to solve 
> this in the mean time. You might look there for some example code.

I was unable to find the relevant code with a quick look, but I didn't
take much time as I knew a short script would to do the trick.  I just
sorted on the serial numbers in the audit message.  Diff'ing showed
quite a bit of motion in the sorted output.  Also, I notice that in
just one message, the msg field value does not end with a colon:

type=DAEMON_START msg=audit(1185203485.586:824) auditd start, ver=1.5.5, format=raw, auid=500 pid=24638 res=success, auditd pid=24638

John

#! /bin/sh

python -E -c '
import sys, re

def main():
    pattern = re.compile("\smsg=audit\(\d+\.\d+:(\d+)\):?\s")
    for line in sys.stdin:
        match = pattern.search(line)
        if not match:
            sys.stderr.write("cannot parse audit message: '\''%s'\''\n" % line)
            sys.exit(1)
        sys.stdout.write(match.group(1) + "\t" + line)

if __name__ == "__main__":
    main()
' | sort -n -s -k 1 | cut -f 2-

Re: Should open syscall records occur without a path record?

[Steve Grubb]

On Tuesday 24 July 2007 08:06:44 am John D. Ramsdell wrote:
> Also, I notice that in
> just one message, the msg field value does not end with a colon:
>
> type=DAEMON_START msg=audit(1185203485.586:824) auditd start, ver=1.5.5,
> format=raw, auid=500 pid=24638 res=success, auditd pid=24638

Actually, it looks like all the DAEMON_  records are missing a ':' after the 
timestamp. The parsers are not exactly looking for it, but I'll add it for 
consistency.

-Steve