Question regarding audit message interpretation

Question regarding audit message interpretation

[Kangkook Jee]

Hi, all

I have a question regarding how to interpret the audit message that we got for
an open system call. In most cases, we observe a single item (path) information
followed by 'syscall' and 'cwd' messages. However, in some cases, we see 2 or 3
items (paths) followed by 'syscall' and 'cwd' messages like following cases.

CASE 1:

Jan 14 11:00:01 hostname kernel: [4980285.399982] type=1300 audit(1421233201.056:893730395): arch=c000003e syscall=2 success=yes exit=5 a0=7ffff4ae5830 a1=c2 a2=180 a3=2233546f14d99 items=2 ppid=983 pid=5723 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 ses=4294967295 tty=(none) comm="cron" exe="/usr/sbin/cron" key=(null)
Jan 14 11:00:01 hostname kernel: [4980285.399985] type=1307 audit(1421233201.056:893730395):  cwd="/var/spool/cron"
Jan 14 11:00:01 hostname kernel: [4980285.399988] type=1302 audit(1421233201.056:893730395): item=0 name="/tmp/" inode=40961 dev=ca:01 mode=041777 ouid=0 ogid=0 rdev=00:00
Jan 14 11:00:01 hostname kernel: [4980285.399990] type=1302 audit(1421233201.056:893730395): item=1 name="/tmp/tmpfS9woiP" inode=30733 dev=ca:01 mode=0100600 ouid=0 ogid=0 rdev=00:00

CASE 2:

Jan 14 11:19:37 hostname kernel: [4981461.529450] type=1300 audit(1421234377.184:894228556): arch=c000003e syscall=2 success=yes exit=5 a0=fa9700 a1=441 a2=1b6 a3=0 items=3 ppid=5727 pid=5728 auid=4294967295 uid=1000 gid=1000 euid=1000 suid=1000 fsuid=1000 egid=1000 sgid=1000 fsgid=1000 ses=4294967295 tty=(none) comm="Run" exe="/usr/bin/perl" key=(null)
Jan 14 11:19:37 hostname kernel: [4981461.529454] type=1307 audit(1421234377.184:894228556):  cwd="/home/ubuntu/benchmarks/UnixBench/testdir"
Jan 14 11:19:37 hostname kernel: [4981461.529458] type=1302 audit(1421234377.184:894228556): item=0 name="/home/ubuntu/benchmarks/UnixBench/results/" inode=396144 dev=ca:01 mode=040775 ouid=1000 ogid=1000 rdev=00:00
Jan 14 11:19:37 hostname kernel: [4981461.529460] type=1302 audit(1421234377.184:894228556): item=1 name=(null) inode=440344 dev=ca:01 mode=0100664 ouid=1000 ogid=1000 rdev=00:00
Jan 14 11:19:37 hostname kernel: [4981461.529463] type=1302 audit(1421234377.184:894228556): item=2 name=(null) inode=440344 dev=ca:01 mode=0100664 ouid=1000 ogid=1000 rdev=00:00

I investigated audit source code a bit and found out that these are produced as
a result of enumerations over audit_context.names_list data structure. But, I'm
still not clear how and when entries for this data structure are filled.

Could anyone explain what would it mean to have multiple items (paths) means for
a single open syscall invocation?

Thanks a lot for your help in advance. 

Regards, Kangkook

Re: Question regarding audit message interpretation

[Richard Guy Briggs]

On 15/01/14, Kangkook Jee wrote:
> Hi, all

Hi Kangkook,

> I have a question regarding how to interpret the audit message that we got for
> an open system call. In most cases, we observe a single item (path) information
> followed by 'syscall' and 'cwd' messages. However, in some cases, we see 2 or 3
> items (paths) followed by 'syscall' and 'cwd' messages like following cases.
> 
> CASE 1:
> 
> Jan 14 11:00:01 hostname kernel: [4980285.399982] type=1300 audit(1421233201.056:893730395): arch=c000003e syscall=2 success=yes exit=5 a0=7ffff4ae5830 a1=c2 a2=180 a3=2233546f14d99 items=2 ppid=983 pid=5723 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 ses=4294967295 tty=(none) comm="cron" exe="/usr/sbin/cron" key=(null)
> Jan 14 11:00:01 hostname kernel: [4980285.399985] type=1307 audit(1421233201.056:893730395):  cwd="/var/spool/cron"
> Jan 14 11:00:01 hostname kernel: [4980285.399988] type=1302 audit(1421233201.056:893730395): item=0 name="/tmp/" inode=40961 dev=ca:01 mode=041777 ouid=0 ogid=0 rdev=00:00
> Jan 14 11:00:01 hostname kernel: [4980285.399990] type=1302 audit(1421233201.056:893730395): item=1 name="/tmp/tmpfS9woiP" inode=30733 dev=ca:01 mode=0100600 ouid=0 ogid=0 rdev=00:00
> 
> CASE 2:
> 
> Jan 14 11:19:37 hostname kernel: [4981461.529450] type=1300 audit(1421234377.184:894228556): arch=c000003e syscall=2 success=yes exit=5 a0=fa9700 a1=441 a2=1b6 a3=0 items=3 ppid=5727 pid=5728 auid=4294967295 uid=1000 gid=1000 euid=1000 suid=1000 fsuid=1000 egid=1000 sgid=1000 fsgid=1000 ses=4294967295 tty=(none) comm="Run" exe="/usr/bin/perl" key=(null)
> Jan 14 11:19:37 hostname kernel: [4981461.529454] type=1307 audit(1421234377.184:894228556):  cwd="/home/ubuntu/benchmarks/UnixBench/testdir"
> Jan 14 11:19:37 hostname kernel: [4981461.529458] type=1302 audit(1421234377.184:894228556): item=0 name="/home/ubuntu/benchmarks/UnixBench/results/" inode=396144 dev=ca:01 mode=040775 ouid=1000 ogid=1000 rdev=00:00
> Jan 14 11:19:37 hostname kernel: [4981461.529460] type=1302 audit(1421234377.184:894228556): item=1 name=(null) inode=440344 dev=ca:01 mode=0100664 ouid=1000 ogid=1000 rdev=00:00
> Jan 14 11:19:37 hostname kernel: [4981461.529463] type=1302 audit(1421234377.184:894228556): item=2 name=(null) inode=440344 dev=ca:01 mode=0100664 ouid=1000 ogid=1000 rdev=00:00
> 
> I investigated audit source code a bit and found out that these are produced as
> a result of enumerations over audit_context.names_list data structure. But, I'm
> still not clear how and when entries for this data structure are filled.

There has been active work done recently to fix this problem.  Your case
#2 is clearly an example of what we've been seeing.

Paul Moore sent a patch in early December and another at the end of
December, followed by a patchset from January 8th in an attempt to clean
things up for good:
	https://www.redhat.com/archives/linux-audit/2014-December/msg00001.html
		audit: correctly record file names with different path name types
	https://www.redhat.com/archives/linux-audit/2014-December/msg00108.html
		audit: create private file name copies when auditing inodes
	https://www.redhat.com/archives/linux-audit/2015-January/msg00016.html
		"Overhaul the audit filename handling"

See also:
	https://bugzilla.redhat.com/show_bug.cgi?id=1155208

> Could anyone explain what would it mean to have multiple items (paths) means for
> a single open syscall invocation?

Usually directory and file.

> Thanks a lot for your help in advance. 
> 
> Regards, Kangkook

- RGB

--
Richard Guy Briggs <rbriggs@redhat.com>
Senior Software Engineer, Kernel Security, AMER ENG Base Operating Systems, Red Hat
Remote, Ottawa, Canada
Voice: +1.647.777.2635, Internal: (81) 32635, Alt: +1.613.693.0684x3545

Re: Question regarding audit message interpretation

[Kangkook Jee]

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

Dear Richard

Thanks a lot for your prompt reply. 
According to your email and patches that you provided, CASE 2 is regarded as a clear error case. 

Then, How about CASE 1? Is this an error case or an intended behavior? 
If it is an error case, I assume we need to use the last item (in this case 'item=1’) for the open path. 
If not, what is the reason to have two items and what does each stand for?

Thanks again for your help in advance.

/Kangkook


> On Jan 14, 2015, at 9:30 AM, Richard Guy Briggs <rgb@redhat.com> wrote:
> 
> On 15/01/14, Kangkook Jee wrote:
>> Hi, all
> 
> Hi Kangkook,
> 
>> I have a question regarding how to interpret the audit message that we got for
>> an open system call. In most cases, we observe a single item (path) information
>> followed by 'syscall' and 'cwd' messages. However, in some cases, we see 2 or 3
>> items (paths) followed by 'syscall' and 'cwd' messages like following cases.
>> 
>> CASE 1:
>> 
>> Jan 14 11:00:01 hostname kernel: [4980285.399982] type=1300 audit(1421233201.056:893730395): arch=c000003e syscall=2 success=yes exit=5 a0=7ffff4ae5830 a1=c2 a2=180 a3=2233546f14d99 items=2 ppid=983 pid=5723 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 ses=4294967295 tty=(none) comm="cron" exe="/usr/sbin/cron" key=(null)
>> Jan 14 11:00:01 hostname kernel: [4980285.399985] type=1307 audit(1421233201.056:893730395):  cwd="/var/spool/cron"
>> Jan 14 11:00:01 hostname kernel: [4980285.399988] type=1302 audit(1421233201.056:893730395): item=0 name="/tmp/" inode=40961 dev=ca:01 mode=041777 ouid=0 ogid=0 rdev=00:00
>> Jan 14 11:00:01 hostname kernel: [4980285.399990] type=1302 audit(1421233201.056:893730395): item=1 name="/tmp/tmpfS9woiP" inode=30733 dev=ca:01 mode=0100600 ouid=0 ogid=0 rdev=00:00
>> 
>> CASE 2:
>> 
>> Jan 14 11:19:37 hostname kernel: [4981461.529450] type=1300 audit(1421234377.184:894228556): arch=c000003e syscall=2 success=yes exit=5 a0=fa9700 a1=441 a2=1b6 a3=0 items=3 ppid=5727 pid=5728 auid=4294967295 uid=1000 gid=1000 euid=1000 suid=1000 fsuid=1000 egid=1000 sgid=1000 fsgid=1000 ses=4294967295 tty=(none) comm="Run" exe="/usr/bin/perl" key=(null)
>> Jan 14 11:19:37 hostname kernel: [4981461.529454] type=1307 audit(1421234377.184:894228556):  cwd="/home/ubuntu/benchmarks/UnixBench/testdir"
>> Jan 14 11:19:37 hostname kernel: [4981461.529458] type=1302 audit(1421234377.184:894228556): item=0 name="/home/ubuntu/benchmarks/UnixBench/results/" inode=396144 dev=ca:01 mode=040775 ouid=1000 ogid=1000 rdev=00:00
>> Jan 14 11:19:37 hostname kernel: [4981461.529460] type=1302 audit(1421234377.184:894228556): item=1 name=(null) inode=440344 dev=ca:01 mode=0100664 ouid=1000 ogid=1000 rdev=00:00
>> Jan 14 11:19:37 hostname kernel: [4981461.529463] type=1302 audit(1421234377.184:894228556): item=2 name=(null) inode=440344 dev=ca:01 mode=0100664 ouid=1000 ogid=1000 rdev=00:00
>> 
>> I investigated audit source code a bit and found out that these are produced as
>> a result of enumerations over audit_context.names_list data structure. But, I'm
>> still not clear how and when entries for this data structure are filled.
> 
> There has been active work done recently to fix this problem.  Your case
> #2 is clearly an example of what we've been seeing.
> 
> Paul Moore sent a patch in early December and another at the end of
> December, followed by a patchset from January 8th in an attempt to clean
> things up for good:
> 	https://www.redhat.com/archives/linux-audit/2014-December/msg00001.html <https://www.redhat.com/archives/linux-audit/2014-December/msg00001.html>
> 		audit: correctly record file names with different path name types
> 	https://www.redhat.com/archives/linux-audit/2014-December/msg00108.html <https://www.redhat.com/archives/linux-audit/2014-December/msg00108.html>
> 		audit: create private file name copies when auditing inodes
> 	https://www.redhat.com/archives/linux-audit/2015-January/msg00016.html <https://www.redhat.com/archives/linux-audit/2015-January/msg00016.html>
> 		"Overhaul the audit filename handling"
> 
> See also:
> 	https://bugzilla.redhat.com/show_bug.cgi?id=1155208 <https://bugzilla.redhat.com/show_bug.cgi?id=1155208>
> 
>> Could anyone explain what would it mean to have multiple items (paths) means for
>> a single open syscall invocation?
> 
> Usually directory and file.
> 
>> Thanks a lot for your help in advance. 
>> 
>> Regards, Kangkook
> 
> - RGB
> 
> --
> Richard Guy Briggs <rbriggs@redhat.com <mailto:rbriggs@redhat.com>>
> Senior Software Engineer, Kernel Security, AMER ENG Base Operating Systems, Red Hat
> Remote, Ottawa, Canada
> Voice: +1.647.777.2635, Internal: (81) 32635, Alt: +1.613.693.0684x3545


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

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