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

  • LAYER 8 Global Moderator

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


    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  48326  24.13.snipped    23      TCP    S
    2016-09-10 05:43:49 +00:00      94snipped56      1  48326  24.13.snipped    23      TCP    S
    2016-09-10 05:44:26 +00:00      94snipped56      1 28403  24.13.snipped    23      TCP    S
    2016-09-10 05:44:50 +00:00      94snipped56      1    22101  24.13.snipped    995    TCP    S
    2016-09-10 05:49:22 +00:00      94snipped56      1  35024  24.13.snipped    995    TCP    S
    2016-09-10 05:53:19 +00:00      94snipped56      1  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 48326 24.13.snipped 23 TCP S
    2016-09-10 05:43:49 +00:00 94snipped56 1 48326 24.13.snipped 23 TCP S
    2016-09-10 05:44:26 +00:00 94snipped56 1 28403 24.13.snipped 23 TCP S
    2016-09-10 05:44:50 +00:00 94snipped56 1 22101 24.13.snipped 995 TCP S
    2016-09-10 05:49:22 +00:00 94snipped56 1 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') ) {
    # read the log
    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' ) {
    # 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";
    # done reading the log
    # dealing with errors
    if ( $lasttime>=$time ) {
      log_error("no new lines added to log since last run OK");
    if ( $linecnt==0 ){
       log_error("no new lines found to submit to dshield OK");
    # safe the "last run" time stamp for the next time we will run.

    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.

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

Log in to reply