[Date Prev][Date Next]   [Thread Prev][Thread Next]   [Thread Index] [Date Index] [Author Index]

/var/log/messages: backlog limit exceeded




Howdy,

I am currently working with the attached test, config3_test, that I have pasted into a text file below. Config3 (assertions 4 and 5) fail on multiple platforms that contain audit-0.9.4-1, although they will pass with earlier audits. When it is ran the messages file in var/log/messages is filled with the following repeating lines during the problem cases.

Jun 15 09:36:05 xracer1 auditd: The audit daemon is exiting.
Jun 15 09:36:05 xracer1 kernel: audit: audit_backlog=257 > audit_backlog_limit=256
Jun 15 09:36:06 xracer1 auditd: auditd startup failed
Jun 15 09:36:06 xracer1 kernel: audit: audit_lost=65593 audit_rate_limit=0 audit_backlog_limit=256
Jun 15 09:36:06 xracer1 kernel: audit: backlog limit exceeded
Jun 15 09:36:06 xracer1 kernel: audit: audit_backlog=257 > audit_backlog_limit=256
Jun 15 09:36:06 xracer1 auditd: auditd startup succeeded
Jun 15 09:36:06 xracer1 kernel: audit: audit_lost=65594 audit_rate_limit=0 audit_backlog_limit=256
Jun 15 09:36:06 xracer1 kernel: audit: backlog limit exceeded
Jun 15 09:36:06 xracer1 kernel: audit: audit_backlog=257 > audit_backlog_limit=256
Jun 15 09:36:06 xracer1 kernel: audit: audit_lost=65595 audit_rate_limit=0 audit_backlog_limit=256
Jun 15 09:36:06 xracer1 kernel: audit: backlog limit exceeded
Jun 15 09:36:06 xracer1 kernel: audit: audit_backlog=257 > audit_backlog_limit=256
Jun 15 09:36:06 xracer1 kernel: audit: audit_lost=65596 audit_rate_limit=0 audit_backlog_limit=256

Jun 15 09:36:06 xracer1 kernel: audit: backlog limit exceeded

The problem persists even with changing the backlog limit. Here are the results in /var/log/messages with different limits.

backlog limit < 8000:  Jun 15 00:38:43 bracer3 kernel: audit: backlog limit exceeded
     Jun 15 00:38:43 bracer3 auditd[6013]: Audit daemon rotating log file s
     Jun 15 00:38:43 bracer3 kernel: audit: audit_backlog=8001 > audit_backlog_limit=8000
backlog limit > 9000
    Jun 15 00:48:29 bracer3 auditd: auditd shutdown failed
    Jun 15 00:48:29 bracer3 auditd: Value -1 should only be numbers - line 10
    Jun 15 00:48:29 bracer3 auditd: The audit daemon is exiting.
    Jun 15 00:48:29 bracer3 auditd: auditd startup failed
    Jun 15 00:48:36 bracer3 auditd: auditd startup succeeded
    Jun 15 00:48:36 bracer3 auditd[6832]: Init complete, audit pid set to: 6832
    Jun 15 00:48:37 bracer3 auditd[6832]: Audit daemon rotating log files
    Jun 15 00:49:08 bracer3 last message repeated 109 times
    Jun 15 00:49:17 bracer3 last message repeated 33 times
    Jun 15 00:49:20 bracer3 auditd[6832]: The audit daemon is exiting.
    Jun 15 00:49:21 bracer3 auditd: auditd shutdown succeeded
    Jun 15 00:49:21 bracer3 kernel: audit: *NO* daemon at audit_pid=6832
    Jun 15 00:49:21 bracer3 kernel: audit(1118814561.489:5030167): auid=500 removed an audit rule
    Jun 15 00:49:21 bracer3 kernel:
    Jun 15 00:49:21 bracer3 kernel: audit(1118814561.693:5030173): auid=500 removed an audit rule
    Jun 15 00:49:21 bracer3 kernel:
    Jun 15 00:49:21 bracer3 kernel: audit(1118814561.897:5030179): auid=500 removed an audit rule
    Jun 15 00:49:21 bracer3 kernel:
    Jun 15 00:49:22 bracer3 kernel: audit(1118814562.101:5030185): auid=500 removed an audit rule
    Jun 15 00:49:22 bracer3 kernel:
    Jun 15 00:49:22 bracer3 kernel: audit(1118814562.305:5030191): auid=500 removed an audit rule
    Jun 15 00:49:22 bracer3 kernel:
    Jun 15 00:49:22 bracer3 kernel: audit(1118814562.509:5030197): auid=500 removed an audit rule
    Jun 15 00:49:22 bracer3 kernel:

When the commands are done manually for only assertion 4 it passes. This is because assertion 3 causes the load that sends the messages to /var/log/messages. Here is the loop and ruleset used by assertion 3.
 for (lc1 = 0; lc1 < 2000; lc1++) {
            syscall(__NR_mkdir,dirname,mode);
            syscall(__NR_chmod,dirname,mode);
            syscall(__NR_rmdir,dirname);
          }

  /* Create rules using auditctl. */
     system("auditctl -a entry,always -S mkdir");
     system("auditctl -a entry,always -S chmod");
     system("auditctl -a entry,always -S rmdir");
     system("auditctl -a exit,always -S mkdir");
     system("auditctl -a exit,always -S chmod");
     system("auditctl -a exit,always -S rmdir");

The line assertion 4 creates and searches for in /var/log/messages is there but followed by many rows of the backlog limit messages pushing it to the top of the file making it difficult to find.

Denise Garrett
dmgarret us ibm com










/*
 *   Copyright (c) International Business Machines  Corp.2005
 *
 *   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; either version 2 of the License, or
 *   (at your option) any later version.
 *
 *   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
 *
 ***************************************************************************
 * File: config3_test.c
 *
 * Description:  
 *             
 *
 * Total Tests: 6 assertions
 *
 * Test Name: config3_test
 *
 * Test Assertion & Strategy: See Detailed Test Design below for steps
 *                            to test the following keywords and values:
 *
 *                                num_logs (0=no rotation, 99 max value)
 *
 *      To ensure auditd.conf is in a known state, the original file will
 *      be saved and a predetermined file will be used, original file
 *      restored at test end.
 *
 *                            Creation of more than 5 log files will be 
 *                            done in the stress test.
 *
 *                            See config2_test for testing the following:
 *
 *                               log_file
 *                               log_format (only RAW is valid)
 *                               flush (none, incremental, data, sync)
 *                               freq (only valid with flush=incremental)
 *
 *                            See config4_test for testing the following:
 *
 *                                max_log_file
 *                                max_log_size_action (ignore, syslog,
 *                                  suspend, rotate)
 *
 *                            See the Disk Handling tests for these:
 *
 *                                space left
 *                                space left action (ignore, syslog, suspend,
 *                                  single, halt)
 *                                admin_space_left
 *                                admin_space_left_action (ignore, syslog, 
 *                                  suspend, single, halt)
 *                                disk_full_action (ignore, syslog, suspend,
 *                                  single, halt)
 *
 *      Since the log files will be very large, they will not be saved by
 *      this test.
 *  
 *      If running individually, be sure environment variable CAPP exists,
 *      even if set to nothing, or test will terminate with BROK Sig 11.
 *      For CAPP testing, export CAPP=ON.  If runltp is used, it sets CAPP.
 *
 * Usage:  <for command-line>
 *  config3_test  
 *
 * History:
 *
 * FLAG   DATE     NAME               DESCRIPTION
 *       4/08/05  krisw us ibm com  Created this test
 *       4/15/05  krisw us ibm com  Review fixes: init mode, check audit
 *                                  start.
 *
 ************************* DETAILED TEST DESIGN **************************
 * Assertion    Description           |         Expected Result
 *************************************************************************
 * Setup: Save /etc/auditd.conf, stop |
 *        auditd and remove audit.log |
 *        Create some rules.          |
 *                                    |
 * num_logs tests (action = rotate    |
 * max_log_file 1M)                   |
 *                                    |
 * 1 num_logs = 0                     | No rotation 
 * 2 num_logs = 1                     | No rotation
 * 3 num_logs = 99 Verify records are | Rotation
 *   found.                           |
 * 4 num_logs = 100                   | Auditd start error
 * 5 num_logs = -1                    | Auditd start error
 * 6 num_logs = 5, verify record found| Rotation; expected record found
 *   in most recent file (new rule).  |
 *                                    | 
 * Cleanup: Restore original config   |
 * file; remove audit.log file.       |                 
 *                                    |
 *************************************************************************/
#include <stdio.h>
#include <stdlib.h>
#include <sys/types.h>
#include <sys/stat.h>
#include <errno.h>
#include <sys/fcntl.h>
#include <asm/unistd.h>

#include "test.h"
#include "usctest.h"
#include "audit_read.h"

char *TCID = "config3_test";
int TST_TOTAL = 6;
extern int Tst_count;

char dirname[40] ="";
mode_t mode;               /* mode for directory creation*/

int rc1 = 0;
int rc2 = 0;
int rc3 = 0;

void setup();
void cleanup();
void makerules();
void checkrecords();

int main(int ac, char **av)
{
     int lc;			/* loop counter */
     int lc1;                   /* loop counter for filling log file */
     char *msg;			/* message returned from parse_opts */
     int rc;

/* parse standard command line options */
 
     if ((msg = parse_opts(ac, av, (option_t *)NULL, NULL)) != (char *)NULL){
	tst_brkm(TBROK, cleanup, "OPTION PARSING ERROR - %s", msg);
	/*NOTREACHED*/
     }

     setup();	/* Call global setup for test */

        /*
         * check looping state if -i option given on the command line
         */
     for (lc = 0; TEST_LOOPING(lc); lc++) {
               Tst_count = 0;          /* reset Tst_count while looping. */
               TEST_RETURN = -1;        /* reset verify value while looping. */

  /* Test 1 - num_logs = 0, max_log_file_action = ROTATE (Set by setup.)*/

    /* Exercise rules repeatedly to exceed max_log_file size. */
 
     for (lc1 = 0; lc1 < 1000; lc1++) {

        syscall(__NR_mkdir,dirname,mode);
        syscall(__NR_chmod,dirname,mode);
        syscall(__NR_rmdir,dirname);
     }

    /* Verify a second log file has NOT been created. */
     TEST(system("ls /var/log/audit/audit.log.1")); 
     if (TEST_RETURN != 256){
        tst_resm(TFAIL, "Second log file was found, not expected.");
     }else {
        tst_resm(TPASS, "Second log file NOT found as expected.");
     }

    /* Stop auditd . */
        system("service auditd stop");

    /* Remove /var/log/audit/audit/audit.log. */
        system("rm -f /var/log/audit/audit.log");

/* Test 2 - num_logs = 1, max_log_file_action = ROTATE */

  /* Change num_logs value to 1. */
        system("sed -e 's/num_logs = 0/num_logs = 1/g' /etc/auditd.conf --in-place");

  /* Restart auditd . */
        rc = system("service auditd start");
        sleep(2);
        if (rc != 0) {
           tst_resm(TFAIL, "Auditd start failed.");
        } else {

  /* Exercise rules repeatedly to increase log file size. */

          for (lc1 = 0; lc1 < 1000; lc1++) {
            syscall(__NR_mkdir,dirname,mode);
            syscall(__NR_chmod,dirname,mode);
            syscall(__NR_rmdir,dirname);
          }

  /* Verify a second log file has NOT been created. */
          TEST(system("ls /var/log/audit/audit.log.1"));
          if (TEST_RETURN != 256){
            tst_resm(TFAIL, "Second log file was found, not expected.");
          }else {
            tst_resm(TPASS, "Second log file NOT found as expected.");
          }

    /* Stop auditd . */
          system("service auditd stop");
        } /* End of check for auditd start. */

/* Test 3 - num_logs = 99, max_log_file_action = ROTATE */

  /* Change num_logs value to 99. */
        system("sed -e 's/num_logs = 1/num_logs = 99/g' /etc/auditd.conf --in-place");

  /* Restart auditd . */
        rc = system("service auditd start");
        sleep(2);
        if (rc != 0) {
           tst_resm(TFAIL, "Auditd start failed.");
        } else {

  /* Exercise rules repeatedly to increase log file size. */

  /* Get start time to narrow down record selection in verify. */
       audit_record->start_time=time(NULL);
     
        for (lc1 = 0; lc1 < 2000; lc1++) {
            syscall(__NR_mkdir,dirname,mode);
            syscall(__NR_chmod,dirname,mode);
            syscall(__NR_rmdir,dirname);
          }
          sleep (2);

  /* Get end time to narrow down selection for verification. */
        audit_record->end_time=time(NULL);
        sleep(1);

  /* Verify a second log file HAS been created. */
          TEST(system("ls /var/log/audit/audit.log.1"));
          if (TEST_RETURN != 0){
            tst_resm(TFAIL, "Second log file was NOT found.");
          }else {
            tst_resm(TINFO, "Second log file WAS found as expected.");
 
  /* Verify records are found. */
            checkrecords();

            if (rc1 !=1 || rc2 != 1 || rc3 !=1){
              tst_resm(TFAIL,"Expected record not found. mkdir=%d, chmod=%d, rmdir=%d", rc1, rc2, rc3);
            } else {
              tst_resm(TPASS, "Expected records found!");
            }
          } /* End of check for second log file. */
          
  /* Stop auditd. */
          system("service auditd stop");
        } /* End of check for auditd start. */
      
  /* Remove /var/log/audit/audit.log. */
     system("rm -f /var/log/audit/audit.log*");

/* Test 4 - num_logs = 100, max_log_file_action = ROTATE */

  /* Change num_logs value to 100. */
        system("sed -e 's/num_logs = 99/num_logs = 100/g' /etc/auditd.conf --in-place");

  /* Clear /var/log/messages */
        system("cat /dev/null > /var/log/messages");

  /* Restart auditd . */
        TEST(system("service auditd start"));

        if (TEST_RETURN == 0){
           tst_resm(TFAIL, "Auditd started; no error for num_logs 100.");
           system("service auditd stop");
        }else {
           tst_resm(TINFO, "Auditd did not start, as expected.");
           system("tail -n 15 /var/log/messages > msg.log");
           TEST(system("grep 'num_logs must be 99 or less' msg.log"));
           if (TEST_RETURN != 0) {
               tst_resm(TFAIL, "Expected message not found.");
           } else {
               tst_resm(TPASS, "Expected message found in /var/log/messages.");
           }
        }

/* Test 5 - num_logs = -1, max_log_file_action = ROTATE */

  /* Change num_logs value to -1. */
        system("sed -e 's/num_logs = 100/num_logs = -1/g' /etc/auditd.conf --in-place");

  /* Clear /var/log/messages */
        system("cat /dev/null > /var/log/messages");
        system("rm -f /var/log/messages.*");

  /* Restart auditd. */
        TEST(system("service auditd start"));
        if (TEST_RETURN == 0){
           tst_resm(TFAIL, "Auditd started; no error for num_logs -1.");
           system("service auditd stop");
        }else {
           system("tail -n 10 /var/log/messages > msg.log");
           TEST(system("grep 'Value -1 should only be numbers - line 9' msg.log"));
           if (TEST_RETURN != 0) {
               tst_resm(TFAIL, "Expected message not found.");
           } else {
               tst_resm(TPASS, "Expected message found in /var/log/messages.");
           }
        }

/* Test 6 - num_logs = 5, max_log_file_action = ROTATE */
  /* Change num_logs value to 5. */

        system("sed -e 's/num_logs = -1/num_logs = 5/g' /etc/auditd.conf --in-place");

  /* Restart auditd . */
        TEST(system("service auditd start"));
        if (TEST_RETURN != 0) {
           tst_resm(TFAIL, "Auditd start failed.");
        } else {

  /* Exercise rules repeatedly to increase log file size. */

          for (lc1 = 0; lc1 < 10000; lc1++) {
            syscall(__NR_mkdir,dirname,mode);
            syscall(__NR_chmod,dirname,mode);
            syscall(__NR_rmdir,dirname);
          }

          sleep (2);

  /* Verify a fifth log file HAS been created. */
          TEST(system("ls /var/log/audit/audit.log.4"));
          if (TEST_RETURN != 0){
             tst_resm(TFAIL, "Fifth log file was NOT found.");
          }else {
             tst_resm(TINFO, "Fifth log file WAS found as expected.");
  /* Add a new rule. */ 
             system("auditctl -a entry,always -S chown");

  /* Verify a record can be found for the new rule creation. */
             system("tail -n 4 /var/log/audit/audit.log > msg.log");
             if  ( (!strcmp( getenv("CAPP"),"ON")) )  {  
             TEST(system("grep 'auid=500 added an audit rule' msg.log"));
               if (TEST_RETURN != 0) {
                 tst_resm(TFAIL, "Expected record NOT found.");
               } else {
                 tst_resm(TPASS, "Expected record WAS found.");
               }
             } else {
               TEST(system("grep 'added an audit rule' msg.log"));
               if (TEST_RETURN != 0) {
                 tst_resm(TFAIL, "Expected record NOT found.");
               } else {
                 tst_resm(TPASS, "Expected record WAS found.");
               }
             }/* End of check for CAPP = ON. */
          } /* End of check for fifth log file. */

/* Stop auditd. */
   system("service auditd stop");
        } /* End of check for auditd start. */

/* Remove /var/log/audit/audit.log files. */
   system("rm -f /var/log/audit/audit.log*");

 }    /* End of loop for looping state */

     cleanup();

     /*NOTREACHED*/
     return(0);
}

/*
 * setup() - performs all ONE TIME setup for this test
 */
void
setup(void)
{

/* Initialize mode. */
         mode = (S_IRWXU | S_IRWXG | S_IRWXO);

/* capture signals */
     tst_sig(FORK, DEF_HANDLER, cleanup);

/* Stop auditd. */
     system("service auditd stop");
	
/* Save the auditd.conf file to another name. */
     system("mv -f /etc/auditd.conf /etc/auditd.conf.save");

/* Save the audit.rules file to another name. */
     system("mv -f /etc/audit.rules /etc/audit.rules.save");

/* Remove the audit.log file. */
     system("rm -f /var/log/audit/audit.log");

/* Copy the test configuration file to auditd.conf. NOTE: This ensures
   we know exactly what is in the file at the start of the test. */
     system("cp ./config3.conf /etc/auditd.conf");
 
/* Create the expected results structure. */
     audit_record =(struct expected *)malloc(sizeof(struct expected));

/* Pause if that option was specified */
     TEST_PAUSE;

/* make a temp directory and cd to it */
     tst_tmpdir();

/* Set dirname to name of directory test will create. */
     sprintf(dirname, "config3");

/* Create rules using auditctl. */
     makerules();

/* Restart auditd to pick up new values in auditd.conf. */
     system("service auditd start");
}

/* makerules() - Create auditctl rules for this test */
void
makerules()
{
/* First clear any existing rules. */
     system("auditctl -D");
     
/* Create rules using auditctl. */
     system("auditctl -a entry,always -S mkdir");
     system("auditctl -a entry,always -S chmod");
     system("auditctl -a entry,always -S rmdir");
     system("auditctl -a exit,always -S mkdir");
     system("auditctl -a exit,always -S chmod");
     system("auditctl -a exit,always -S rmdir");
}

/* checkrecords() - Check for records from mkdir, chmod, and rmdir. */
void checkrecords()
{
/* Set up expected results and send to verify for mkdir, chmod, rmdir. */
     audit_record->syscallno=__NR_mkdir;
     strcpy(audit_record->audittype,"SYSCALL");
     audit_record->auid = get_login_uid();
     audit_record->uid=getuid();
     audit_record->pid=getpid();
     audit_record->exit=0;
     audit_record->argv[0]=(unsigned long)dirname;
     audit_record->argv[1]=(unsigned long)mode;
     strcpy(audit_record->objectname,dirname);

     rc1 = audit_verify(audit_record,2);

     strcpy(audit_record->audittype,"SYSCALL");
     audit_record->syscallno=(__NR_chmod);
     audit_record->uid=getuid();
     audit_record->pid=getpid();
     audit_record->auid = get_login_uid();
     audit_record->exit=0;
     strcpy(audit_record->objectname,dirname);
     audit_record->argv[0] = (unsigned long) dirname;
     audit_record->argv[1] = mode;

     rc2 = audit_verify(audit_record,2);

     audit_record->syscallno=__NR_rmdir;
     strcpy(audit_record->audittype,"SYSCALL");
     audit_record->uid=getuid();
     audit_record->pid=getpid();
     audit_record->auid=get_login_uid();
     audit_record->exit=0;
     audit_record->argv[0]=(unsigned long)dirname;
     strcpy(audit_record->objectname,dirname);

     rc3 = audit_verify(audit_record,1);
}

/*
 * cleanup() - performs all ONE TIME cleanup for this test at completion or
 *	       premature exit.
 */

void
cleanup(void)
{
/*
 * print timing stats if that option was specified.
 * print errno log if that option was specified.
 */

/* Delete rules using auditctl. */
      system("auditctl -D");

/* Restore the /etc/auditd.conf file. */
      system("mv -f /etc/auditd.conf.save /etc/auditd.conf");

/* Restore the /etc/audit.rules file. */
      system("mv -f /etc/audit.rules.save /etc/audit.rules");

/* Remove /var/log/audit/audit.log files. */
      system("rm -f /var/log/audit/audit.log*");

      free(audit_record);

      TEST_CLEANUP;

/* Remove tmp dir and all files in it */
      tst_rmdir();

/* exit with return code appropriate for results */
      tst_exit();
}


[Date Prev][Date Next]   [Thread Prev][Thread Next]   [Thread Index] [Date Index] [Author Index]