http://www.perlmonks.org?node_id=1056865

Warning: may be cool only to me...

What it is

I recently noticed that my auth.log file seemed fairly large for a server which (should have) no real value to anyone other than me. Taking a gander at it showed that someone had been trying to ssh into it about every 3 seconds for a fair stretch of time. This sort of irritated me. Having been away from Perl for a while, I figured I could brush up a bit on something fairly basic as well as give myself a tool to satisfy my curiosity about these idiots that are trying so hard to break into something with no real $$ related content. I am presenting it here because I have not posted here before, and thought that maybe someone else might find it useful.

Basics

There are three parts to the tool:
  1. auth_examine.pl - examines the current auth.log file looking for a regex match and stores some info about that log entry. It is run once an hour by root:cron on my system
  2. auth_log_analysis.sqlite3 stores info gathered by auth_examine.pl, and of course retrieves said info
  3. auth_log_report.cgi sends some queries to auth_log_analysis.sqlite3 and build some very simple tables that are reasonably informative and easy to read

Resources Used

Perl 5.18 and Sqlite3 on Ubuntu 13.04

Additionally I used the following modules:

Admittedly, I barely used any of them as this was mostly an exercise to refresh my memory

Wandering Thoughts

This is running on my machine currently so I guess one could say it has been tested in one environment.

I read the whole auth.log file into an array then trim the array down using splice based on info stored in the DB. I do this for a couple of reasons:

I did not go out of my way on comments and there is no POD either. It is written in such a way that between log4perl and perl -d anyone should be able to figure out what is going on.

Anyone using it will have to ensure that sane(for their system) paths are supplied in the code(no nice config file, sorry).

I am Tempted..

..to extend the tool to auto-update my iptables and then auto send an email to the who-is result, though I know the IP is probably spoofed

At any rate, following is the tool, rough, ugly and working should you be interested...

auth_examine.pl ->

#!/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::PatternL +ayout log4perl.appender.Logfile.layout.ConversionPattern = [%r] %F -%L % +m%n log4perl.appender.Screen = Log::Log4perl::Appender::Screen log4perl.appender.Screen.layout = Log::Log4perl::Layout::PatternLa +yout 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_analysi +s.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->lo +gdie("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 routi +ne run_log('start'); get_knowns(); process_file(); run_log('end'); run_unknowns(); $dbh->disconnect(); $logger->info("Done! Processed " . $run_stats{lines_examined} . " line +s 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 n +ot seen before. #Also add to local hash so if we see them again during this ru +n 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(\'$us +r\',\'$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(\'$po +rt\',\'$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 b +astard ... 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 fr +om 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,timest +amp,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 wher +e port = \'$port\'"); my $ct = create_time(); $dbh->do("insert into attempts(ip_id,user_id,port_id,timestamp,cre +ate_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 fo +r /) { 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 (s +elect 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 i +n (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, b +ut 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 = (se +lect 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{sk +ip_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_stat +s{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 a +s 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 = (sele +ct 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); } } } }

auth_log_report.cgi ->
#!/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}); #retriev +e 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 descripti +ve 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 >= '$repor +t_start'), "num_new_users" => qq(select count(*) from users where create_time > '$report_st +art'), "num_new_attempts" => qq(select count(*) from attempts where timestamp > '$report_s +tart'), "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 Da +te::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(<!Doctype html>\n\n<html>\n\t<head>\n); $output = $output . qq( <style> table { border:1px solid green; max-height: 95%; min-width 100; background-color: lightgrey; margin: auto; empty-cells:hide; } td { border:1px solid green; padding: 5px; text-align:center; vertical-align:top; } div { margin: auto; } #m_tbls { width:95%; height:600px; } #singles { width: 95%; height: 50px; } #attempts { width: 32%; height: 95%; overflow: auto; float: left; } #users { width: 12%; float: left; height: 95%; overflow: auto; } #ip { width: 10%; float: left; height: 95%; overflow: auto; } #ports { width: 10%; float: left; height: 95%; overflow: auto; } #who_is { width: 32%; float: left; height: 95%; overflow: auto; } #t_ports { width: 95%; background-color: yellow; } #t_users { width:95%; } #t_attempts { width:95%; } #t_ip { width:95%; background-color: yellow; } #t_who_is { width:95%; background-color: yellow; } td.text_left { text-align: left; } th { background-color:green; color:white; } tr { height: 20px; } </style>); #Output summary table $output = $output . qq(<div id="top">\t</head>\n<body>); my $table_single_vals = qq(<table id="singles"> <caption>Summary Values</caption <tr> <th>New File</th> <th>Logged Runs</th> <th>New Users</th> <th>New Attempts</th> <th>Prev Run Time</th> </tr> <tr> <td>$results_s{new_file}</td> <td>$results_s{num_runs}</td> <td>$results_s{num_new_users}</td> <td>$results_s{num_new_attempts}</td> <td>$results_s{time_prev_run}</td> </tr> </table></div><hr>); $output = $output . $table_single_vals; $output = $output . qq(<div id="m_tbls">); 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(<div id="ip"><table id="t_ip"><caption>IP's Used ( +$count)</caption><tr><th>IP</th></tr>\n); for my $i (0..scalar(@tmp)) { $tmp[$i] = qq(<tr><td>$tmp[$i]</td></tr>); } foreach my $i (0..scalar(@tmp) - 1) { $s_ip = $s_ip . qq($tmp[$i]\n); } $s_ip = $s_ip . qq(</table></div>\n); # $output = $output . qq($s_ip</div>); } #Output new ports found if ($key eq "new_ports") { $s_ports = qq(<div id="ports"><table id="t_ports"><caption>Po +rts Added ($count)</caption><tr><th>Port</th></tr>\n); for my $i (0..scalar(@tmp)) { $tmp[$i] = qq(<tr><td>$tmp[$i]</td></tr>); } foreach my $i (0.. scalar(@tmp) - 1) { $s_ports = $s_ports . qq($tmp[$i]\n); } $s_ports = $s_ports . qq(</table></div>\n); # $output = $output . qq($s_ports</div>); } #Output new users found if ($key eq "new_users") { $s_users = qq(<div id="users"><table id="t_users"><caption>Un +ame(s) Added ($count)</caption><tr><th>Uname</th></tr>\n); for my $i (0..scalar(@tmp) - 1) { $tmp[$i] = qq(<tr><td>$tmp[$i]</td></tr>); } foreach my $i (0.. scalar(@tmp)) { $s_users = $s_users . qq($tmp[$i]\n); } $s_users = $s_users . qq(</table></div>\n); } #Output who_is if ($key eq "who_is") { $s_who_is = qq(<div id="who_is"><table id="t_who_is" class="t +ext_left"><caption>Who_is (Results $count) </caption><tr><th>WhoIs</th></tr>\n); for my $i (0..scalar(@tmp) - 1) { $tmp[$i] =~ s/\n/<br>/g; $tmp[$i] =~ s/->/---->/g; } for my $i (0..scalar(@tmp)) { $s_who_is = $s_who_is . qq(<tr><td class="text_left">$tmp[ +$i]</td></tr>); } $s_who_is = $s_who_is . qq(</table></div>); } # Output attempts to table if ($key eq "results_$params{report_length}") { $s_attempts = qq(<div id="attempts"> <table id="t_attempts"> <caption>Attempts Last $params{re +port_length} Hours ($count)</caption> <tr> <th>User</th> <th>Port</th> <th>IP</th> <th>Timestamp</th> </tr>); for my $i (0..scalar(@tmp)) { my @str = split(" ",$tmp[$i]); chomp(@str); my $newstr = qq(<tr>); foreach my $str (@str) { $str = qq(<td>$str</td>); $newstr = $newstr . $str; } $newstr = $newstr . qq(</tr>); $tmp[$i] = $newstr; } for my $i (0..scalar(@tmp)) { $s_attempts = $s_attempts . qq($tmp[$i]\n); } $s_attempts = $s_attempts . qq(</table></div>\n); } } my $output_end = qq(</div></body></html>); $output = $output . $s_ip . $s_users . $s_ports . $s_attempts . $s_ +who_is . $output_end; print $output; }

auth_log_analysis.sqlite3 ->
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;

  • ...the majority is always wrong, and always the last to know about it...
  • ..by my will, and by will alone.. I set my mind in motion