Should open syscall records occur without a path record?

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.

#! /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()

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

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

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

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

-Steve

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

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

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-

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