Dshield send pfsense log - issue with reading log entry time?

johnpoz

So stumbled upon an updated script to send pfsense logs to dshields

https://www.dshield.org/forums/diary/Updated+PFSense+Client/20937/1

And I have gotten it to work, had a few bumps for sure somehow when I had pasted it got a CR in the line format so logs were being sent in 2 lines and dshield not putting anything in. I also had a weird setup with my email notification where I was sending to gmail via port 587 and that was working for actual notifications, but this script was choking. Changed to port 465 and checked Enable SMTP over SSL/TLS and now this script will send the email.

And it does send email with the listing from the logs.

2016-09-10 05:43:46 +00:00 94snipped56 1 186.118.8.122 48326 24.13.snipped 23 TCP S
2016-09-10 05:43:49 +00:00 94snipped56 1 186.118.8.122 48326 24.13.snipped 23 TCP S
2016-09-10 05:44:26 +00:00 94snipped56 1 166.250.144.100 28403 24.13.snipped 23 TCP S
2016-09-10 05:44:50 +00:00 94snipped56 1 168.1.128.50 22101 24.13.snipped 995 TCP S
2016-09-10 05:49:22 +00:00 94snipped56 1 106.187.97.102 35024 24.13.snipped 995 TCP S
2016-09-10 05:53:19 +00:00 94snipped56 1 45.33.116.208 37018 24.13.snipped 5904 TCP S

I had changed my TZ to UTC, normally I run it in Central time, but was wondering if that was causing a issue with how it figures out when last entry was sent, etc. So above is an example of how it sends the logs.. Where my UID been snipped out some of it, and my public IP I have snipped out… But this works and get notifications back from dshield

Errors-To: bounces@dshield.org
Reply-To: info@dshield.org
From: admin@dshield.org

Authorized Userid: 94snipped56
Format: DSHIELD
Timezone: +00:00

Lines in file: 565
Lines rejected: none
Unique lines written to database: 565
identical lines are added up on import.

Lines written to database (up to 10):
2016-09-10 05:43:46 +00:00 94snipped56 1 186.118.8.122 48326 24.13.snipped 23 TCP S
2016-09-10 05:43:49 +00:00 94snipped56 1 186.118.8.122 48326 24.13.snipped 23 TCP S
2016-09-10 05:44:26 +00:00 94snipped56 1 166.250.144.100 28403 24.13.snipped 23 TCP S
2016-09-10 05:44:50 +00:00 94snipped56 1 168.1.128.50 22101 24.13.snipped 995 TCP S
2016-09-10 05:49:22 +00:00 94snipped56 1 106.187.97.102 35024 24.13.snipped 995 TCP S

So that looks like great everything is working.. But the problem is its not sending when it should. So I have cron job running every 30 mins, at 11 and 41 past the hour.. What it does is say

Sep 11 13:41:03 php /root/bin/dshieldpfsense.php: no new lines added to log since last run OK
Sep 11 13:11:03 php /root/bin/dshieldpfsense.php: no new lines added to log since last run OK
Sep 11 12:41:04 php /root/bin/dshieldpfsense.php: no new lines added to log since last run OK
Sep 11 12:11:03 php /root/bin/dshieldpfsense.php: no new lines added to log since last run OK
Sep 11 11:41:03 php /root/bin/dshieldpfsense.php: no new lines added to log since last run OK
Sep 11 11:11:04 php /root/bin/dshieldpfsense.php: no new lines added to log since last run OK

But clearly if you look there have been multiple blocks in the log that should be sent up. Between times when script last ran

So you can view the script directly here
https://isc.sans.edu/clients/dshieldpfsense.txt or you can find the link in the above link article about it, etc.

I have emailed the author, but its been a week and nothing back.. And I posted on the above article and nothing. My guess is it has something to do with how pfsense actual uses clog and maybe is not posting the info into the filter.log its opening so when the script run it really just isn't seeing anything new? And have to wait til something fills up for new stuff to get posted to the log based upon the log file size?

Here is snip of the code that looks at last time, runs thru log and then depending errors and exits, etc..


# check when we ran last.
if ( file_exists('/var/run/dshieldlastts') ) {
  $lasttime=file_get_contents('/var/run/dshieldlastts');
}

# read the log
$log=fopen("/var/log/filter.log","r");
while(!feof($log)) {
        $line = fgets($log);
        $line = rtrim($line);
# the name of this function changed in Pfsense 2.3
        if ( $config['version']>=15 ) {
	        $flent = parse_firewall_log_line(trim($line));
	} else {
	        $flent = parse_filter_line(trim($line));
        }

# eliminating ICMP (we don't log that) and TCP with FA and RA flags as these are usually false positives

        if ($flent != "" && in_array($flent['interface'],$interfaces) && $flent['proto']!='ICMP' && $flent['tcpflags']!='FA' && $flent['tcpflags']!='RA' ) {
  	   $time=strtotime($flent['time']);

# check if this log line is newer then the last one we processesed.
   if ( $time>$lasttime) {
      $linesout.=date("Y-m-d H:i:s P",$time)."\t$uid\t1\t{$flent['srcip']}\t{$flent['srcport']}\t{$flent['dstip']}\t{$flent['dstport']}\t{$flent['proto']}\t{$flent['tcpflags']}\n";
   $flent='';
   $linecnt++;
}
        }
}
fclose($log);

# done reading the log

# dealing with errors
if ( $lasttime>=$time ) {
  log_error("no new lines added to log since last run OK");
  exit();
}
if ( $linecnt==0 ){
   log_error("no new lines found to submit to dshield OK");
   exit();
}

# safe the "last run" time stamp for the next time we will run.

file_put_contents('/var/run/dshieldlastts',$time);

How to correct? What I would expect to happen is how often I run this script it should send up the amount of hits in the log since the last time it ran be it 1 hour, 2 hours, 30 mins etc.. so normally you would see it submit small numbers of entries every so often, not like 900 entries in 1 email, and then not run submit again for 12 some hours, etc.

grandrivers

just a wild thought this might be a nice add to pfblockerng or both ids/ips packages