#!/usr/bin/perl -w use strict; use DBI; use DBD::SQLite; use Net::Whois::IP qw(whoisip_query); use Date::Calc qw(Date_to_Time); use DateTime::HiRes; use DateTime; use File::Util; use Log::Log4perl qw(get_logger); ##initialize Log4perl############################################################ my $log_conf = q( log4perl.category = INFO, Logfile, Screen log4perl.appender.Logfile = Log::Log4perl::Appender::File log4perl.appender.Logfile.filename = auth_examine.log log4perl.appender.Logfile.mode = write log4perl.appender.Logfile.layout = Log::Log4perl::Layout::PatternLayout log4perl.appender.Logfile.layout.ConversionPattern = [%r] %F -%L %m%n log4perl.appender.Screen = Log::Log4perl::Appender::Screen log4perl.appender.Screen.layout = Log::Log4perl::Layout::PatternLayout log4perl.appender.Screen.layout.ConversionPattern = [%r] %F -%L %m%n ); Log::Log4perl::init( \$log_conf ); my $logger = Log::Log4perl::get_logger(); ################################################################################ #nasty globals my ($lc, %run_stats, %file_stats, %known_users, %known_port, %known_ip, %known_whois, %unknown_whois, $db_name, $dbh, @in); ################################################################################ my $exec_dir = "/home/wjw/bin"; my $path_to_db = "/home/wjw/bin/auth_log_analysis.sqlite3"; my $auth_log_path = "/var/log/auth.log"; #test #$exec_dir = "/home/wjw/Devel/wjw-server_utils-work"; #$path_to_db = "/home/wjw/Devel/wjw-server_utils-work/auth_log_analysis.sqlite3"; #$auth_log_path = "/home/wjw/tmp/auth.log"; #end_test $logger->info("Starting"); chdir $exec_dir; #for when this is run as root from cron $file_stats{file_name} = $auth_log_path; $db_name = $path_to_db; my $log = File::Util->new(); $dbh = DBI->connect("dbi:SQLite:dbname=$db_name","","") or $logger->logdie("DBI died connecting to $db_name with -> " . DBI::errstr); @in = $log->load_file($file_stats{file_name}, '--as-lines'); check_log($in[0]); #give the first line of the file to check_log routine run_log('start'); get_knowns(); process_file(); run_log('end'); run_unknowns(); $dbh->disconnect(); $logger->info("Done! Processed " . $run_stats{lines_examined} . " lines of " . $file_stats{file_name}); exit; ################################################################# sub process_file { no strict "refs"; my $w = scalar(@in); @in = splice(@in, $file_stats{skip_to_line}); while (my $line = shift(@in)) { $run_stats{lines_examined} ++; my $response_string; my ($ip,$usr,$port,$time_stamp,$skip) = prep_log_entry($line); next if $skip == 1; #Add into database any users, ports, or ip addresses we have not seen before. #Also add to local hash so if we see them again during this run we don't re-add, or do a who_is again if(not exists $known_ip{$ip}) { my $ct = create_time(); $dbh->do("insert into ip(IP,create_time) values (\'$ip\',\'$ct\')"); $known_ip{$ip} = $ip; $logger->info("New IP added:" . $ip); } if(not exists $known_users{$usr}) { my $ct = create_time(); $dbh->do("insert into users(user,create_time) values(\'$usr\',\'$ct\')"); $known_users{$usr} = $usr; $logger->info("New user added: " . $usr); } if(not exists $known_port{$port}) { my $ct = create_time(); $dbh->do("insert into ports(port,create_time) values(\'$port\',\'$ct\')"); $known_port{$port} = -1; $logger->info("New port added: $port"); } #we always log the attempt to break in! my $ip_id = &build_attempt($ip,$usr,$port,$time_stamp); #This is where we run the who_is and try to get info about the bastard ... if (not exists $known_whois{$ip}) { my ($response) = whoisip_query($ip); $logger->info("who_is attempted on ip" . $ip); if (scalar keys %{$response} > 0) { $known_whois{$ip} = $ip; foreach my $rkey (sort keys (%{$response})) { my $response_line = $response->{$rkey}; if (defined $response_string) { $response_string = "$response_string" . "$rkey " . "->" . " $response_line\n"; } else { $response_string = "$rkey " . "->" . "$response_line\n"; } } if (defined $response_string) { my $ip_id = $dbh->selectrow_arrayref("select eid from ip where ip = \'$ip\'"); my $rs = $dbh->quote($response_string); my $ct = &create_time(); my $time_stamp = $ct; my $stmt = qq(insert into who_is(entry,ip_id,timestamp,create_time) values ($rs, \'@$ip_id[0]\', \'$time_stamp\', \'$ct\')); $dbh->do($stmt); } } } } } ######################################################################################################## sub build_attempt { my ($ip,$usr,$port,$ts) = @_; my $ip_id = $dbh->selectrow_arrayref("select eid from ip where ip = \'$ip\'"); my $usr_id = $dbh->selectrow_arrayref("select eid from users where user = \'$usr\'"); my $port_id = $dbh->selectrow_arrayref("select eid from ports where port = \'$port\'"); my $ct = create_time(); $dbh->do("insert into attempts(ip_id,user_id,port_id,timestamp,create_time) values (\'@$ip_id[0]\',\'@$usr_id[0]\',\'@$port_id[0]\',\'$ts\',\'$ct\')"); return @$ip_id[0]; } ######################################################################################################## #get the info we want from the auth.log entry and prep that info from a formatting perspective sub prep_log_entry() { my $line = shift(@_); my ($ip,$usr,$port,$time_stamp,$skip); chomp($line); if ($line =~ /Failed password for invalid user |Failed password for /) { my @rem = split(/\s/,$'); my $rem = $'; my @pre = split(/\s+/,$`); my $year = Date::Calc::This_Year(1); my $day = $pre[1]; my $month = Date::Calc::Decode_Month($pre[0],1); if (length($month) < 2) { $month = "0" . $month; } if (length($day) < 2) { $day = "0" . $day; } my $time = $pre[2]; $time_stamp = $year . "-" . $month . "-" . $day . "T" . $time; $usr = $rem[0]; $ip = $rem[2]; $port = $rem[4]; $skip = 0; } else { $skip = 1; } return ($ip,$usr,$port,$time_stamp,$skip); } ######################################################################################################## #sub to populate the un/known* hashes sub get_knowns() { #get the list of IP known addresses my $all = $dbh->selectall_arrayref("select eid, IP from ip"); foreach my $row (@$all) { my ($id,$ip) = @$row; $known_ip{$ip} = $id; } my $num = scalar(keys %known_ip); $logger->info($num . " known IP's loaded"); #get the list of known ports $all = $dbh->selectall_arrayref("select eid, port from ports"); foreach my $row (@$all) { my ($id,$port) = @$row; $known_port{$port} = $id; } $num = scalar(keys %known_port); $logger->info($num . " known ports loaded"); #get the list of known users $all = $dbh->selectall_arrayref("select eid, user from users"); foreach my $row (@$all) { my ($id,$user) = @$row; $known_users{$user} = $id; } $num = scalar(keys %known_users); $logger->info($num . " known users loaded"); #who_is addresses we have already found, don't search these again $all = $dbh->selectall_arrayref("select ip from ip where eid in (select ip_id from who_is)"); foreach my $row (@$all) { $known_whois{@$row[0]} = @$row[0]; } $num = scalar(keys %known_whois); $logger->info($num . " known whois results loaded"); #ip addresses we have but do not have who_is results for $all = $dbh->selectall_arrayref("select ip from ip where eid not in (select ip_id from who_is)"); foreach my $row (@$all) { $unknown_whois{@$row[0]} = @$row[0]; } $num = scalar(keys %unknown_whois); $logger->info($num . " ip(s) without who_is results loaded"); } ######################################################################################################## #function to get a record create time. This is by no means perfect, but it should help identify #issues in the database sub create_time { my $ct = DateTime::HiRes->now(); $ct->set_time_zone("America/Chicago"); my $w = $ct->datetime() . "." . $ct->nanosecond(); return $w; } ######################################################################################################### sub run_log { my $arg = shift(@_); if ($arg eq 'start') { my $fn = shift(@_); $run_stats{start_time} = create_time(); if ($file_stats{first_run} == 1 || $file_stats{new_file} == 1) { $logger->info("This is a new auth.log file\n"); return; } my $qs = qq(select last_line_read from run_log where eid = (select max(eid) from run_log)); my $sth = $dbh->prepare($qs); my $rv = $sth->execute() or die $DBI::errstr; while (my @row = $sth->fetchrow_array()) { $file_stats{skip_to_line} = $row[0]; $logger->info("Will be skipping to line " . $file_stats{skip_to_line}); } } if ($arg eq 'end') { $run_stats{end_time} = create_time(); my $qs = qq(insert into run_log (run_time_start, run_time_end, input_file, last_line_read, last_log_first_line) values (\'$run_stats{start_time}\', \'$run_stats{end_time}\', \'$file_stats{file_name}\', \'$run_stats{last_line_processed}\', \'$in[0]\')); $dbh->do($qs); } } ########################################################## #better run logging.... need to capture where we were in log file so as not to re-process records. #base on line count as well as time stamp of last record processed. sub check_log { my ($prev_create_time,$record_count,$first_line_txt); $first_line_txt = shift(@_); #compare last line read in log with current log length, if smaller it is the same file probably $file_stats{line_count} = $log->line_count($file_stats{file_name}); my $qs = qq(select last_line_read from run_log where eid = (select max(eid) from run_log)); my $sth = $dbh->prepare($qs); my $rv = $sth->execute() or die $DBI::errstr; while (my @row = $sth->fetchrow_array()) { $file_stats{skip_to_line} = $row[0]; $logger->info( "Will be skipping to line " . $file_stats{skip_to_line}); } if ($file_stats{line_count} < $file_stats{skip_to_line}) { $file_stats{first_run} = 1; $file_stats{skip_to_line} = 0; } else { $file_stats{first_run} = 0; } $qs = qq(select last_log_first_line from run_log where eid = (select max(eid) from run_log)); $sth = $dbh->prepare($qs); $rv = $sth->execute() or die $DBI::errstr; while (my @row = $sth->fetchrow_array()) { $file_stats{last_log_first_line} = $row[0]; } if ($file_stats{last_log_first_line} eq $first_line_txt) { $file_stats{first_run} = 0; } else { $file_stats{first_run} = 1; $file_stats{skip_to_line} = 0; } if (($file_stats{first_run} == 0) && ($file_stats{skip_to_line} == $file_stats{line_count})) { $logger->info("No new records in file. Exiting\n"); exit; } return; } ############################################################################## sub run_unknowns { #here were do a who_is on ip that don't yet have one for whatever reason no strict "refs"; my $response_string; foreach my $ip (keys %unknown_whois) { my ($response) = whoisip_query($ip); $logger->info("who_is attempted on unknown ip " . $ip); if (scalar keys %{$response} > 0) { $known_whois{$ip} = $ip; foreach my $rkey (sort keys (%{$response})) { my $response_line = $response->{$rkey}; if (defined $response_string) { $response_string = "$response_string" . "$rkey " . "->" . " $response_line\n"; } else { $response_string = "$rkey " . "->" . "$response_line\n"; } } if (defined $response_string) { my $ip_id = $dbh->selectrow_arrayref("select eid from ip where ip = \'$ip\'"); my $rs = $dbh->quote($response_string); my $ct = &create_time(); my $time_stamp = $ct; my $stmt = qq(insert into who_is(entry,ip_id,timestamp,create_time) values ($rs, \'@$ip_id[0]\', \'$time_stamp\', \'$ct\')); $dbh->do($stmt); } } } } #### #!/usr/bin/perl -w use strict; use DBI; use DBD::SQLite; use Date::Calc qw(:all); use DateTime; use CGI qw(:all); my $q = new CGI; my %params = $q->Vars; my $db_name = "/home/wjw/bin/auth_log_analysis.sqlite3"; my $dbh = DBI->connect("dbi:SQLite:dbname=$db_name","","") or die DBI::errstr; my (%results_s, %results_m); my $report_start = get_report_start($params{report_length}); #retrieve the start time of the report #based on the variable handed in. # a hash of queries to be run. the has key is intended to be descriptive enough # to be usefull as titles on a web page. These have single results and go into # the %results_s hash my %qs_s = ( "num_runs" => qq(select count(*) from run_log where run_time_end >= '$report_start'), "num_new_users" => qq(select count(*) from users where create_time > '$report_start'), "num_new_attempts" => qq(select count(*) from attempts where timestamp > '$report_start'), "last_first_line" => qq(select last_log_first_line from run_log where eid = (select max(eid) - 1 from run_log)), "this_first_line" => qq(select last_log_first_line from run_log where eid = (select max(eid) from run_log)), "time_prev_run" => qq(select run_time_end from run_log where eid = (select max(eid) from run_log)) ); # These are queries that return multiple results which are then stored in the # %results_m hash my %qs_m = ( "results_$params{report_length}" => qq(select user, port, ip, timestamp from try1 where timestamp > '$report_start' order by timestamp), "new_ports" => qq(select port from ports where create_time > '$report_start' order by port), "new_users" => qq(select user from users where create_time > '$report_start' order by user), "new_ip" => qq(select ip from ip where create_time > '$report_start'), "who_is" => qq(select ip, entry, timestamp from who_is w join ip i on i.eid = w.ip_id where i.create_time > '$report_start' order by ip_id) ); #do the multi-result queries foreach my $key (keys %qs_m) { my $qs = $qs_m{$key}; my $sth = $dbh->prepare($qs); $sth->execute(); while (my @row = $sth->fetchrow_array()) { my $cnt = scalar(@row); if (scalar(@row) == 1) { push @{ $results_m{$key} }, @row; } elsif(scalar(@row) > 1) { push @{ $results_m{$key} }, join(" ", @row); } } } # do the single result queries foreach my $key (keys %qs_s) { my $qs = $qs_s{$key}; my $sth = $dbh->prepare($qs); $sth->execute(); while (my $row = $sth->fetch()) { $results_s{$key} = @$row[0]; } } if ($results_s{last_first_line} = $results_s{this_first_line}) { $results_s{new_file} = "False"; #print "same log\n"; #debug } $dbh->disconnect(); output(); exit; ################################################################################ sub get_report_start() { my $report_length = shift(@_); if($report_length eq "") { $report_length = -24; } # default to 24 hour report $report_length = $report_length * -1; #negate hours to work with Date::Calc my ($year,$month,$day,$hour,$min,$sec) = Date::Calc::Add_Delta_DHMS(Today_and_Now(), 0,$report_length, 0, 0); #format to iso-8601 form yyyy-mm-ddThh:mm:ss if (length($day) < 2) { $day = "0" . $day; } if (length($month) < 2) { $month = "0" . $month; } if(length($hour) < 2) { $hour = "0" . $hour; } if(length($min) <2 ) { $min = "0" . $min; } if(length($sec) <2 ) { $sec = "0" . $sec; } my $now = "$year\-$month\-$day" ."T" . "$hour\:$min\:$sec"; return $now; } ################################################################################ sub output() { print $q->header(); my $output = qq(\n\n\n\t\n); $output = $output . qq( ); #Output summary table $output = $output . qq(
\t\n); my $table_single_vals = qq(
Summary Values
New File Logged Runs New Users New Attempts Prev Run Time
$results_s{new_file} $results_s{num_runs} $results_s{num_new_users} $results_s{num_new_attempts} $results_s{time_prev_run}

); $output = $output . $table_single_vals; $output = $output . qq(
); my ($s_who_is, $s_attempts, $s_ip, $s_ports, $s_users); foreach my $key ( keys %results_m) { my @tmp = @{$results_m{$key}}; my $count = scalar(@tmp); #Output new IP found if ($key eq "new_ip") { $s_ip = qq(
\n); for my $i (0..scalar(@tmp)) { $tmp[$i] = qq(); } foreach my $i (0..scalar(@tmp) - 1) { $s_ip = $s_ip . qq($tmp[$i]\n); } $s_ip = $s_ip . qq(
IP's Used ($count)
IP
$tmp[$i]
\n); # $output = $output . qq($s_ip
); } #Output new ports found if ($key eq "new_ports") { $s_ports = qq(
\n); for my $i (0..scalar(@tmp)) { $tmp[$i] = qq(); } foreach my $i (0.. scalar(@tmp) - 1) { $s_ports = $s_ports . qq($tmp[$i]\n); } $s_ports = $s_ports . qq(
Ports Added ($count)
Port
$tmp[$i]
\n); # $output = $output . qq($s_ports); } #Output new users found if ($key eq "new_users") { $s_users = qq(
\n); for my $i (0..scalar(@tmp) - 1) { $tmp[$i] = qq(); } foreach my $i (0.. scalar(@tmp)) { $s_users = $s_users . qq($tmp[$i]\n); } $s_users = $s_users . qq(
Uname(s) Added ($count)
Uname
$tmp[$i]
\n); } #Output who_is if ($key eq "who_is") { $s_who_is = qq(
\n); for my $i (0..scalar(@tmp) - 1) { $tmp[$i] =~ s/\n/
/g; $tmp[$i] =~ s/->/---->/g; } for my $i (0..scalar(@tmp)) { $s_who_is = $s_who_is . qq(); } $s_who_is = $s_who_is . qq(
Who_is (Results $count)
WhoIs
$tmp[$i]
); } # Output attempts to table if ($key eq "results_$params{report_length}") { $s_attempts = qq(
); for my $i (0..scalar(@tmp)) { my @str = split(" ",$tmp[$i]); chomp(@str); my $newstr = qq(); foreach my $str (@str) { $str = qq(); $newstr = $newstr . $str; } $newstr = $newstr . qq(); $tmp[$i] = $newstr; } for my $i (0..scalar(@tmp)) { $s_attempts = $s_attempts . qq($tmp[$i]\n); } $s_attempts = $s_attempts . qq(
Attempts Last $params{report_length} Hours ($count)
User Port IP Timestamp
$str
\n); } } my $output_end = qq(); $output = $output . $s_ip . $s_users . $s_ports . $s_attempts . $s_who_is . $output_end; print $output; } ##
## CREATE TABLE sqlite_stat1(tbl,idx,stat); CREATE TABLE "attempts" ( "eid" INTEGER PRIMARY KEY AUTOINCREMENT, "ip_id" INTEGER NOT NULL, "user_id" INTEGER NOT NULL, "port_id" INTEGER NOT NULL, "timestamp" TEXT NOT NULL , "create_time" TEXT); CREATE TABLE sqlite_sequence(name,seq); CREATE TABLE ip ( "eid" INTEGER PRIMARY KEY AUTOINCREMENT, "IP" TEXT NOT NULL , "create_time" TEXT); CREATE TABLE ports ( "eid" INTEGER PRIMARY KEY AUTOINCREMENT, "port" INTERGER NOT NULL, "create_time" TEXT); CREATE TABLE users ( "eid" INTEGER PRIMARY KEY AUTOINCREMENT, "user" TEXT NOT NULL, "create_time" TEXT); CREATE TABLE who_is ( "eid" INTEGER PRIMARY KEY AUTOINCREMENT, "entry" TEXT NOT NULL, "ip_id" INTEGER NOT NULL, "timestamp" TEXT NOT NULL , "create_time" TEXT); CREATE TABLE "run_log" ( "eid" INTEGER PRIMARY KEY AUTOINCREMENT, "run_time_start" TEXT, "run_time_end" TEXT, "input_file" TEXT, "last_log_first_line" TEXT, "last_line_read" INTEGER ); CREATE VIEW try1 as select u.user, p.port, i.ip, a.timestamp, a.create_time from attempts a join ports p on a.port_id = p.eid join ip i on i.eid = a.ip_id join users u on u.eid = a.user_id order by a.timestamp;