audit-viewer help needed

F9, permissive/targeted

audit-viewer:
audit-viewer-0.3-1.fc9.x86_64

It was working fine, then I loaded several rpms (below). Now I get this on startup:

Traceback (most recent call last):
File "/usr/share/audit-viewer/main.py", line 71, in <module>
if w.setup_initial_window(args):
File "/usr/share/audit-viewer/main_window.py", line 158, in setup_initial_window

    self.new_list_tab([])

File "/usr/share/audit-viewer/main_window.py", line 176, in new_list_tab
tab = ListTab(filters, self)
File "/usr/share/audit-viewer/list_tab.py", line 161, in __init__
self.refresh()
File "/usr/share/audit-viewer/list_tab.py", line 195, in refresh
event_sequence = self.__refresh_get_event_sequence()
File "/usr/share/audit-viewer/list_tab.py", line 483, in __refresh_get_event_sequence
want_other_fields, True)
File "/usr/share/audit-viewer/main_window.py", line 265, in read_events
keep_raw_records)
File "/usr/share/audit-viewer/event_source.py", line 135, in read_events
e = events[(ts.serial, ts.sec, ts.milli)]
AttributeError: 'NoneType' object has no attribute 'serial'

Any ideas?

Thx,
LCB.

- rpms added from yum.log (starting with working audit-viewer):

Sep 17 13:25:54 Installed: audit-viewer-0.3-1.fc9.x86_64
Sep 17 16:44:32 Updated: scim-libs-1.4.7-24.fc9.x86_64
Sep 17 16:44:32 Updated: sqlite-3.5.9-1.fc9.x86_64
Sep 17 16:44:32 Updated: 12:libdhcp4client-4.0.0-17.fc9.x86_64
Sep 17 16:44:33 Updated: scim-1.4.7-24.fc9.x86_64
Sep 17 16:44:33 Updated: 12:dhclient-4.0.0-17.fc9.x86_64
Sep 17 16:44:34 Updated: alsa-utils-1.0.17-2.fc9.x86_64
Sep 17 16:44:34 Updated: xorg-x11-server-common-1.5.0-1.fc9.x86_64
Sep 17 16:44:35 Updated: xorg-x11-server-Xorg-1.5.0-1.fc9.x86_64
Sep 17 16:44:35 Updated: xorg-x11-drv-evdev-2.0.4-1.fc9.x86_64
Sep 18 11:11:11 Installed: wget-1.11.1-1.fc9.x86_64
Sep 18 13:32:00 Updated: audit-libs-1.7.7-1.fc9.x86_64
Sep 18 13:32:01 Updated: audit-1.7.7-1.fc9.x86_64
Sep 18 13:32:01 Updated: audit-libs-python-1.7.7-1.fc9.x86_64
Sep 18 13:32:02 Installed: system-config-audit-0.4.8-2.fc9.x86_64
Sep 18 13:32:11 Updated: audispd-plugins-1.7.7-1.fc9.x86_64
Sep 18 13:32:12 Installed: audit-debuginfo-1.7.7-1.fc9.x86_64
Sep 18 13:32:13 Updated: audit-libs-devel-1.7.7-1.fc9.x86_64
Sep 18 13:35:28 Installed: mysql-libs-5.0.51a-1.fc9.x86_64
Sep 18 13:35:29 Installed: perl-DBI-1.607-1.fc9.x86_64
Sep 18 13:35:29 Installed: mysql-5.0.51a-1.fc9.x86_64
Sep 18 13:35:29 Installed: perl-DBD-MySQL-4.005-8.fc9.x86_64
Sep 18 13:35:31 Installed: mysql-server-5.0.51a-1.fc9.x86_64
Sep 18 13:35:31 Installed: libpreludedb-0.9.14.1-3.fc9.x86_64
Sep 18 13:35:31 Installed: libpreludedb-mysql-0.9.14.1-3.fc9.x86_64
Sep 18 13:36:41 Installed: libpreludedb-python-0.9.14.1-3.fc9.x86_64
Sep 18 13:36:41 Installed: libprelude-python-0.9.17.2-1.fc9.x86_64
Sep 18 13:36:42 Installed: python-cheetah-2.0.1-2.fc9.x86_64
Sep 18 13:36:42 Installed: prelude-manager-0.9.14.2-1.fc9.x86_64
Sep 18 13:36:43 Installed: prewikka-0.9.14-1.fc9.noarch
Sep 18 13:36:43 Installed: prelude-manager-db-plugin-0.9.14.2-1.fc9.x86_64

LC (Lenny) Bruzenak
[email protected]

Hello,
the attached patch modifies auparse not to handle timestamp 0.x specially by using out-of-band information (parse_state == EVENT_EMPTY) instead of assuming (au->le.e.sec == 0) has a special meaning. As far as I can see, this the two conditions are equivalent if no event has a timestamp 0.x.

The patch also decreases the assumed minimal length of a timestamp.

I have tested this only minimally - I have checked that (make check) succeeds, and that audit-viewer doesn't crash on startup.

This patch fixes handling of the following Lenny's audit record:

I'm curious how this audit record could have been created (notabile is that the previous record has a sequence ID 6758 and a reasonable timestamp). Lenny, Steve, any ideas?

Thank you,
Mirek

Index: auparse/auparse.c
===================================================================
@@ -666,7 +666,7 @@
 	char *ptr;
 
 	errno = 0;
-	ptr = strchr(s+10, ':');
+	ptr = strchr(s+3, ':');
 	if (ptr) {
 		e->serial = strtoul(ptr+1, NULL, 10);
 		*ptr = 0;

@@ -1033,7 +1033,7 @@
 /* Accessors to event data */
 const au_event_t *auparse_get_timestamp(auparse_state_t *au)
 {
-	if (au && au->le.e.sec != 0)
+	if (au && au->parse_state != EVENT_EMPTY)
 		return &au->le.e;
 	else
 		return NULL;

@@ -1251,7 +1251,7 @@
 	free(au->find_field);
 	au->find_field = strdup(name);
 
-	if (au->le.e.sec) {
+	if (au->parse_state != EVENT_EMPTY) {
 		const char *cur_name;
 		rnode *r;
 

@@ -1275,7 +1275,7 @@
 		errno = EINVAL;
 		return NULL;
 	}
-	if (au->le.e.sec) {
+	if (au->parse_state != EVENT_EMPTY) {
 		int moved = 0;
 
 		rnode *r = aup_list_get_cur(&au->le);

@@ -1299,7 +1299,7 @@
 /* Accessors to field data */
 const char *auparse_get_field_name(auparse_state_t *au)
 {
-	if (au->le.e.sec) {
+	if (au->parse_state != EVENT_EMPTY) {
 		rnode *r = aup_list_get_cur(&au->le);
 		if (r) 
 			return nvlist_get_cur_name(&r->nv);

@@ -1310,7 +1310,7 @@
 
 const char *auparse_get_field_str(auparse_state_t *au)
 {
-	if (au->le.e.sec) {
+	if (au->parse_state != EVENT_EMPTY) {
 		rnode *r = aup_list_get_cur(&au->le);
 		if (r) 
 			return nvlist_get_cur_val(&r->nv);

@@ -1321,7 +1321,7 @@
 
 int auparse_get_field_type(auparse_state_t *au)
 {
-        if (au->le.e.sec) {
+        if (au->parse_state != EVENT_EMPTY) {
                 rnode *r = aup_list_get_cur(&au->le);
                 if (r)
                         return nvlist_get_cur_type(r);

@@ -1347,7 +1347,7 @@
 
 const char *auparse_interpret_field(auparse_state_t *au)
 {
-        if (au->le.e.sec) {
+        if (au->parse_state != EVENT_EMPTY) {
                 rnode *r = aup_list_get_cur(&au->le);
                 if (r)
                         return nvlist_interp_cur_val(r);

I assume the timestamp is punched in the kernel audit code. I decided to go rule out aggregation error and went looking on the originating machine. I found a couple more:

[root@hugo ~]# grep "(0.000:" /var/log/audit/audit.log*
/var/log/audit/audit.log.12:node=local-hugo type=AVC msg=audit(0.000:6760): avc: denied { recvfrom } for pid=2589 comm="lockd" saddr=127.0.0.1 src=687 daddr=127.0.0.1 dest=111 netif=lo scontext=system_u:system_r:initrc_t:s0-s15:c0.c1023 tcontext=system_u:system_r:kernel_t:s15:c0.c1023 tclass=association /var/log/audit/audit.log.12:node=local-hugo type=AVC msg=audit(0.000:381): avc: denied { read } for pid=2594 comm="nfsd4" name="v4recovery" dev=dm-0 ino=34482 scontext=system_u:system_r:kernel_t:s15:c0.c1023 tcontext=system_u:object_r:var_lib_nfs_t:s0 tclass=dir /var/log/audit/audit.log.12:node=local-hugo type=AVC msg=audit(0.000:5135): avc: denied { recvfrom } for pid=2595 comm="lockd" saddr=127.0.0.1 src=701 daddr=127.0.0.1 dest=111 netif=lo scontext=system_u:system_r:initrc_t:s0-s15:c0.c1023 tcontext=system_u:system_r:kernel_t:s15:c0.c1023 tclass=association

/var/log/audit/audit.log.12:node=local-hugo type=AVC msg=audit(0.000:388): avc:  denied  { read } for  pid=2593 comm="nfsd4" name="v4recovery" dev=dm-0 ino=34482 scontext=system_u:system_r:kernel_t:s15:c0.c1023 tcontext=system_u:object_r:var_lib_nfs_t:s0 tclass=dir 
/var/log/audit/audit.log.13:node=local-hugo type=AVC msg=audit(0.000:380): avc:  denied  { read } for  pid=2588 comm="nfsd4" name="v4recovery" dev=dm-0 ino=34482 scontext=system_u:system_r:kernel_t:s15:c0.c1023 tcontext=system_u:object_r:var_lib_nfs_t:s0 tclass=dir 

They all appear to be AVCs on denied read/recvfom, maybe there is a timestamp bug in there?

Let me know if I can supply any data/diagnostics. I'll have to leave the kernel code to experts for now...

Thx!
LCB.

LC (Lenny) Bruzenak
[email protected]

LC Bruzenak píše v Po 22. 09. 2008 v 19:38 -0500:

I think I can see what's going on. Those are kernel threads; when they are created, an audit context is created and zeroed. The timestamp is set on system call entry in ordinary threads, but there is no system call entry in kernel threads, so the original zero timestamp is used in all audit records related to kernel threads.

I'm not sure how to fix it, though. Perhaps identify "operation start" points in kernel threads, and update the timestamps in their audit contexts at that time?
Mirek

...

OK; excellent summary!

The bad thing IMO is that ausearch doesn't show these records. It just drops them (and exits with exit value = 1).

LCB.

LC (Lenny) Bruzenak
[email protected]

Eric, Al,

Any ideas how to fix this?

Thanks,
-Steve

Steve, Mirek -

This patch didn't make it into the 1.7.9 code? I have been running with it since its release. Even if the kernel was patched I thought this was good.

Thx,
LCB.

LC (Lenny) Bruzenak
[email protected]

Hello, I have been struggling with this and have not found any solutions yet. NISPOM Chapter 8 requires me to have log accounts of all account lockouts. While the account lockout policy is set, I am unable to figure out the syntax for the watches to add to audit.rules that will show the account lockout event. I have to be able to do this for about 150 systems.

Is it possible to track account lockouts by event or pid? If so, what are the ids for account lockouts for RHEL4 and RHEL5?

Thank you for your help!

Starr-Renee Corbin
Applied Research Lab
The University of Texas at Austin
512-835-3628

pam_tally2 is hardwired to send lockout events to the audit system. Use it rather than pam_tally. They will be in the audit logs as ANOM_LOGIN_FAILURES when the limit is reached, as RESP_ACCT_LOCK_TIMED for the actual locking of the acct, and RESP_ACCT_UNLOCK_TIMED when the acct is unlocked due to time expiration or admin action.

-Steve