4
\$\begingroup\$

I am still a Python beginner and would appreciate some help with this code.

I am looking through some firewall log files, more specific all lines with Deny in them. For those files I am extracting the protocol, source IP, destination IP and destination port. The output is summarized and a hit counter is added (thanks memoselyk). Everything is working as intended but some optimization is still needed.

What I still try to optimize is:

  • If I enter a >3GB log file it will take a LONG time. Of course it is a large file but we are talking many hours.

  • The output could need some tweaking, especially getting rid of the [, ] and ' characters, and tab the output. I've actually been trying for some hours but no success.

  • I have to do some optimization in regards to ICMP traffic, but I will give this a go later. In short it is due to my regex where i use the / character, but this isn't present in ICMP traffic.

Any help would be appreciated.

Example log output:

Nov  9 00:36:10 firewall %ASA-4-106023: Deny tcp src outside:1.1.1.1/43882 dst outside:2.2.2.2/23 by access-group "outside-in" [0x0, 0x0]
Nov  9 00:36:10 firewall %ASA-4-106023: Deny tcp src outside:1.1.1.1/38780 dst outside:2.2.2.2/23 by access-group "outside-in" [0x0, 0x0]
Nov  9 00:36:11 firewall %ASA-4-106023: Deny tcp src outside:1.1.1.1/8273 dst outside:2.2.2.2/23 by access-group "outside-in" [0x0, 0x0]
Nov  9 00:36:12 firewall %ASA-4-106023: Deny tcp src outside:1.1.1.1/23433 dst outside:2.2.2.22/23 by access-group "outside-in" [0x0, 0x0]
Nov  9 00:36:12 firewall %ASA-4-106023: Deny tcp src outside:1.1.1.1/25175 dst outside:2.2.2.24/23 by access-group "outside-in" [0x0, 0x0]
Nov  9 00:36:12 firewall %ASA-4-106023: Deny tcp src outside:1.1.1.1/15855 dst outside:2.2.2.26/23 by access-group "outside-in" [0x0, 0x0]
Nov  9 00:36:12 firewall %ASA-4-106023: Deny tcp src outside:1.1.1.1/24574 dst outside:2.2.2.27/23 by access-group "outside-in" [0x0, 0x0]
Nov  9 00:36:12 firewall %ASA-4-106023: Deny tcp src outside:1.1.1.1/21797 dst outside:2.2.2.29/23 by access-group "outside-in" [0x0, 0x0]
Nov  9 00:36:12 firewall %ASA-4-106023: Deny udp src outside:3.3.3.3/12112 dst outside:2.2.2.99/53031 by access-group "outside-in" [0x0, 0x0]
Nov  9 00:36:13 firewall %ASA-4-106023: Deny icmp src outside:4.4.4.4 dst services:2.2.2.211 (type 11, code 1) by access-group "outside-in" [0x0, 0x0]
Nov  9 00:36:17 firewall %ASA-4-106023: Deny icmp src outside:4.4.4.4 dst services:2.2.2.10 (type 3, code 3) by access-group "outside-in" [0x0, 0x0]

My code so far:

import re       #for regular expressions - to match ip's
import sys      #for parsing command line opts
from collections import Counter

# if file is specified on command line, parse, else ask for file
if sys.argv[1:]:
    print "File: %s" % (sys.argv[1])
    logfile = sys.argv[1]
else:
    logfile = raw_input("Please enter a file to parse, e.g /var/log/secure: ")

data = open(logfile, 'r')
match = []
seen = Counter()

# find all Deny lines and append them in a list
for lines in data :
    extract = re.findall('Deny.*"' ,lines)
    for i in extract :
        match.append(i)

# extract different keywords from Deny lines
for lines in match :
    prot = str(re.findall('Deny\s(.+?)\ssrc',lines))
    ip_src = str(re.findall('src.*?:([0-9a-f].*?)/', lines))
    ip_dst = str(re.findall('dst.*?:([0-9a-f].*?)/', lines))
    #ip_sport = str(re.findall('src.*?[0-9a-f].*?/([0-9].*?)\s', lines))        # uncomment if you want source port also, and add ip_sport to summarized below
    ip_dport = str(re.findall('dst.*?[0-9a-f].*?/([0-9].*?)\s', lines))

    summarized = prot + ip_src + ip_dst + ip_dport
    seen.update([summarized])

for x in seen.most_common() :
    print x[0]+' :'+'     hitcnt='+str(x[1])

Output:

['tcp']['1.1.1.1']['2.2.2.2']['23'] :     hitcnt=3
['icmp'][][][] :     hitcnt=2
['udp']['3.3.3.3']['2.2.2.99']['53031'] :     hitcnt=1
['tcp']['1.1.1.1']['2.2.2.22']['23'] :     hitcnt=1
['tcp']['1.1.1.1']['2.2.2.24']['23'] :     hitcnt=1
['tcp']['1.1.1.1']['2.2.2.29']['23'] :     hitcnt=1
['tcp']['1.1.1.1']['2.2.2.26']['23'] :     hitcnt=1
['tcp']['1.1.1.1']['2.2.2.27']['23'] :     hitcnt=1

If possible it would be cool if was able to process large files faster, and output would look something like this

prot  source   destination  port     hitcnt
tcp   1.1.1.1  2.2.2.2      23     : hitcnt=3
icmp  1.1.2.1  2.2.2.3             : hitcnt=2
udp   3.3.3.3  2.2.2.99     53031  : hitcnt=1
\$\endgroup\$
  • \$\begingroup\$ Follow-up on this SO post. \$\endgroup\$ – Mast Nov 11 '15 at 22:16
5
\$\begingroup\$

Your main problem is the gathering of all matching lines in match, whilst you rather should process each line as you go. In addition you compile the regexp for each hit, and you compile multiple regexp's when one should suffice.

Lastly to get a better output, you could use print('{} {} {}'.format(protocol, src, dst) or a variant of this to pretty print your result.

Here is some code which runs considerable faster than your variant:

import re       #for regular expressions - to match ip's
import sys      #for parsing command line opts
from collections import Counter

DENY_PATTERN = re.compile(r'Deny\s(?P<protocol>.+?)\ssrc.*?:(?P<src>[0-9a-f\.]*)/?.*?\s.*?dst.*?:(?P<dst>[0-9a-f\.]*)((/(?P<dst_port>[0-9]*)\s)|\s)')
LINE_FORMAT='{0:<6.6} {1:<12.12} {2:<12.12} {3:<6.6} {4}'


def process_log_file(logfile):
    """Reads through the log_file, and returns a counter based on Deny-lines."""


    # Process file line by line
    with open(logfile, 'r') as data:
        seen = Counter()

        # find all Deny line and append them in a list
        for line in data :

            # If line has 'Deny ' in it, then check it some more
            if 'Deny ' in line:
                seen.update(DENY_PATTERN.findall(line)) 

    return seen


def print_counter(counter):
    """Pretty print the result of the counter."""

    print(LINE_FORMAT.format('prot', 'source', 'destination',  'port', 'hitcnt'))
    print(LINE_FORMAT.format(*tuple(('------------------',) * 5)))
    for (protocol, src, dst, _, _, dst_port), count in counter.most_common():
        print(LINE_FORMAT.format(protocol, src, dst, dst_port, count))


if __name__ == '__main__':
    # if file is specified on command line, parse, else ask for file
    if sys.argv[1:]:
        print "File: %s" % (sys.argv[1])
        logfile = sys.argv[1]
    else:
        logfile = raw_input("Please enter a file to parse, e.g /var/log/secure: ")

    denial_counter = process_log_file(logfile)
    print_counter(denial_counter)

Code restructure

I've restructured your code to accomodate the already commented issues, and some more style related issues:

  • Separated business logic from presentation – By using process_log_file() and print_counter() I've separated the logic calculating the data, and that part of the code printing the output. This is a good thing to do
  • Introduced the if __name__ == '__main__': construct – This construction makes it possible to run the script as a standalone script, and therefore it is a natural place to do the check if a file has been supplied through arguments, or if you have to enter it manually. This combined with the functions also makes it possible to use the script as a module where you can process multiple log files, and maybe extend with other print functions
  • Removed memory consuming match list – I've simplified the logic not using the intermediate match-list, which required a lot of memory. Instead I process the line directly, and update the counter, which is returned from process_log_file.
  • Tuple assignment in for loop – Within print_counter() there is a loop where I use Pythons builtin expansion to tuples to get easy access to each of the captured groups (and ignoring two of them using _), before I use the prebuilt LINE_FORMAT to make a nice output. See Format string syntax for the syntax, and there are some example on that page as well.

Some notes on regular expressions

Note also that your original regexp where somewhat flaky, that is when you test against [0-9a-f].*? which you used for src and dst, this matches a string starting with 0-9a-f, but it can continue with whatever, so both 1.1.1.1 and 1something_else would match it!

In the new variant I've used [0-9a-f\.]*? to match any combination of digits, 'a-f' and period ., which is a loose translation of an ip-address. I further used (?P<name>...) to name the groups, which isn't strictly neccessary, but can be useful sometimes. I've also added a (...|...) near the end to pick up the dst address when matching the 'icmp' lines.

A neat tool to test regexp's is found at http://regex101.com, and your regexp is found here. This site also explains the regexp to some extent. I've played a little more with this regex, so try out the different version in the drop down menu near the top.

Added version handling icmp info

Here is the currently latest version of the regexp, where I also have added some explanation:

DENY_PATTERN = re.compile( # https://regex101.com/r/pO9tV0/6
r'''Deny\s(?P<protocol>.+?)\s     # Matches "Deny <protocol> "
    src.*?:(?P<src>[0-9a-f\.]*)   # Matches "src...:<src>"
    (?:/(?P<src_port>)[0-9]*)?\s  # Non-capturing optional, matches "/<src> "
    dst.*?:(?P<dst>[0-9a-f\.]*)   # Matches "dst...:<dst>"
    (?:                   # Starts non-capturing alternate group ...
       /(?P<dst_port>[0-9]*)      # Matches "/<dst_port>"
     |                    # ... next alternate group ...
       \s\((?P<icmp_spec>         # Start matching " (<icmp_spec>"
          type\s(?P<type>[0-9]*),\s   # Matches "type <type>, "
         code\s(?P<code>[0-9]*)       # Matches "code <code>"
         )\)                      # End matching for "<icmp_spec>)"
     )                    # ... ends alternate group
    \s                            # Locks the end at whitespace
    ''', re.X)  # The re.X allows for whitespace and comments within regex

which needs a little change to the print_counter() function as I've added some groups, and changed into non-capturing groups for some of the others:

def print_counter(counter):
    """Pretty print the result of the counter."""

    print(LINE_FORMAT.format('prot', 'source', 'destination',  'port', 'hitcnt'))
    print(LINE_FORMAT.format(*tuple(('------------------',) * 5)))
    for (protocol, src, src_port, dst, dst_port, icmp_spec, icmp_type, icmp_code), count in counter.most_common():
        if icmp_code or icmp_type:
            dst_port = '{}, {}'.format(icmp_code, icmp_type)

        print(LINE_FORMAT.format(protocol, src, dst, dst_port, count))

Output example

Output when running this script, without the extended icmp handling, surrounded by a time command on a file of size 1.550.000.000 bytes which was a serious duplication of a slight modification of your test input:

File: test_basis_11000K
prot   source       destination  port   hitcnt
------ ------------ ------------ ------ ------------------
tcp    1.1.1.1      2.2.2.2      23     3000000
tcp    1.1.1.1      2.2.2.25     25     2000000
icmp   4.4.4.4      2.2.2.10            1000000
tcp    1.1.1.1      2.2.2.22     23     1000000
tcp    1.1.1.1      2.2.2.27     23     1000000
udp    3.3.3.3      2.2.2.99     53031  1000000
tcp    1.1.1.1      2.2.2.29     23     1000000
icmp   4.4.4.4      2.2.2.211           1000000

real    1m29.334s
user    1m28.134s
sys 0m0.825s

So now it runs in 1.5 minutes, and that is not that bad for a 1.5GB file.

\$\endgroup\$
  • \$\begingroup\$ Hello holroy. Thank you very much for you effort. I've just tried to run you code and it is perfect !!! Now I will have to sit down and try analyse your code and comments in order to learn from it. Again THANK YOU very much :o) \$\endgroup\$ – joni Nov 12 '15 at 7:01
  • \$\begingroup\$ Hi again. Would it also be possible to implement same logic with this log line? Nov 11 00:00:09 firewall %ASA-3-710003: TCP access denied by ACL from 1.1.1.1/50624 to internet:5.5.5.5/80 - (notice a denied instead of Deny) \$\endgroup\$ – joni Nov 12 '15 at 11:34
  • \$\begingroup\$ Hmm can't seem to make it work. DENY_PATTERN2 = re.compile(r'%ASA.+?:\s(?P<protocol2>.+?)\saccess\sdenied\sby\sACL\sfrom\s(?P<src2>[0-9a-f\.:]*)/?.*?\sto\s.*?:(?P<dst2>[0-9a-f\.:]*)((/(?P<dst_port2>[0-9]*)\s))') and if 'TCP|UDP ' in line : seen.update(DENY_PATTERN2.findall(line)) \$\endgroup\$ – joni Nov 12 '15 at 13:29
  • \$\begingroup\$ actually I did already try denied and access denied but still no match. Is it correct that I need to make a "deny_pattern2" and also a protocol2, src2 etc.? I tried with above regex and a new if in line but I never see any output from the denied log lines. I guess my regex must be off :o) \$\endgroup\$ – joni Nov 12 '15 at 13:43
  • \$\begingroup\$ @Joni, Come join me in chat.stackexchange.com/rooms/31653/…, and we can discuss your other deleted question a bit... :-) \$\endgroup\$ – holroy Nov 16 '15 at 15:31
5
\$\begingroup\$

So you load an entire file (3+Gb), then collect all the "Deny" lines in a match list (another 3+Gb). That's a serious waste of RAM, and a huge burden on the cache and page tables. No wonder it runs so slow.

Notice that lines have no context, and each one could be processed independently. Streaming is an obvious optimization:

    for line in data:
        process_line(line)

Also notice that the line structure is very well-defined (that is, every field you are interested in has a fixed number), so regex is overkill:

    for line in data:
        fields = line.split()
        if fields[5] != 'Deny':
            continue
        ....

In any case, if you want to use regular expressions, compile them.

\$\endgroup\$
  • \$\begingroup\$ Thank you for your comments. I will try to "process" the input :o) \$\endgroup\$ – joni Nov 12 '15 at 7:02

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.