Log Templater Files

$Id: README,v 1.8 2012/01/18 06:47:21 rdilley Exp $
=== Templater (tmpltr)

by Ron Dilley <ron.dilley@uberadmin.com>

For the latest information on tmpltr, please see:
http://www.uberadmin.com/Projects/tmpltr/

== What is Templater (tmpltr)?

Templater is a small and fast log processor that provides
simple artificial ignorance capabilities.  You use the tool
to process past log data and store templates that represent
normal log line structures.  You then run the tool against
current or target logs and all normal patterns are automatically
ignored.

The parser is fast and capable of processing millions of
lines per minute.  For weblogs and firewall logs, I average
9M lines per minute on a 2GHz x86 machine running *NIX.

The template strategy was originally proposed by a friend
of mine in 2003 who later built a tool called never before
seen (NBS*) which also provides artificial ignorance for
arbitrary text data as well as text structures.

* http://www.ranum.com/security/computer_security/code/nbs.tar

== Why use it?

I built this tool to solve a log analysis problem that I have
suffered through while responding to many security breaches.
Invariably, I need to find a needle in a haystack of log data.

If you need to find a pattern that has not occurred previously,
then this is the tool for you.

== Implementation

Templater has a simple command lines interface.  In it's
simplest form, pass a text file as an argument and the output
will be list of counts and unique templates with the first
full log line separated by a '||'.

Including the first full log line with each unique template
allows for quick recognition of the log lines that map to
the unique template.

To get a list of all the options, you can execute the
command with the -h or --help switch.

----
$ ./src/tmpltr --help
tmpltr v0.5 [Jan 18 2012 - 01:45:11]

syntax: tmpltr [options] filename [filename ...]
 -c|--cluster          show invariable fields in output
 -d|--debug (0-9)      enable debugging info
 -g|--greedy           ignore quotes
 -h|--help             this info
 -n|--cnum {num}       Max cluster args [default: 1]
 -t|--templates {file} load templates to ignore
 -v|--version          display version information
 -w|--write {file}     save templates to file
 filename              one or more files to process, use '-' to read from stdin

The debug option is most useful when the tool is compiled
with the --ENABLE-DEBUG switch.
----

A typical run of tmpltr is to pass the target log file as an
argument and send the output through 'sort -n' to produce
the following sorted list of unique templates and their
frequency of occurent from least to most prevalent.

I normally go through the list in this order to speed up
catching the anonlylous patterns.

----
% tmpltr /var/log/secure.log | sort -n
Opening [/var/log/secure.log] for read
           7 %s %d %d:%d:%d %s %s[%d]: %s %s(): %s %d %s %s %s:%s||Dec 12 20:49:59 Rons-MacBook-Pro authorizationhost[1056]: in od_record_attribute_create_cfstring(): returned 2 attributes for dsAttrTypeStandard:AuthenticationAuthority
           7 %s %d %d:%d:%d %s %s[%d]: %s %s(): %s %d %s %s||Dec 12 20:49:59 Rons-MacBook-Pro authorizationhost[1056]: in pam_sm_authenticate(): Kerberos 5 refuses you
           7 %s %d %d:%d:%d %s %s[%d]: %s %s(): %s %s %s %s %s %s||Dec 12 20:49:59 Rons-MacBook-Pro authorizationhost[1056]: in pam_sm_authenticate(): Failed to determine Kerberos principa  name.
           7 %s %d %d:%d:%d %s %s[%d]: %s %s(): %s %s %s %s||Dec 12 20:49:59 Rons-MacBook-Pro authorizationhost[1056]: in od_principal_for_user(): No authentication authority returned
           7 %s %d %d:%d:%d %s %s[%d]: %s %s(): %s %s()||Dec 12 20:49:59 Rons-MacBook-Pro authorizationhost[1056]: in pam_sm_setcred(): Done getpwnam()
           7 %s %d %d:%d:%d %s %s[%d]: %s %s(): %s %s, %s: %d %d||Dec 12 20:49:59 Rons-MacBook-Pro authorizationhost[1056]: in pam_sm_setcred(): Got euid, egid: 0 0
           7 %s %d %d:%d:%d %s %s[%d]: %s %s(): %s %s: %d %s %d||Dec 12 20:49:59 Rons-MacBook-Pro authorizationhost[1056]: in ac_complete(): ac_complete returned: 0 for 502
           7 %s %d %d:%d:%d %s %s[%d]: %s %s(): %s %s: (%s)||Dec 12 20:49:59 Rons-MacBook-Pro authorizationhost[1056]: in pam_sm_authenticate(): Got ruser: (null)
           7 %s %d %d:%d:%d %s %s[%d]: %s %s(): %s - %s %s %s %s %s %d.||Dec 12 20:49:59 Rons-MacBook-Pro authorizationhost[1056]: in pam_sm_acct_mgmt(): OpenDirectory - Membership cache T L set to 1800.
           7 %s %d %d:%d:%d %s %s[%d]: %s %s(): %s: %s %s %s %s||Dec 12 20:49:59 Rons-MacBook-Pro authorizationhost[1056]: in pam_sm_setcred(): pam_sm_setcred: krb5 user rdilley doesn't ha e a principal
           7 %s %d %d:%d:%d %s %s[%d]: %s %s(): %s: %s %s||Dec 12 20:49:59 Rons-MacBook-Pro authorizationhost[1056]: in pam_sm_setcred(): pam_sm_setcred: ntlm done
           8 %s %d %d:%d:%d %s %s[%d]:     %s : %s=%s ; %s=/%s/%s/%s/%s/%s ; %s=%s ; %s=/%s/%s %s -%s//%s/%s/%s/%s||Dec 12 21:08:48 Rons-MacBook-Pro sudo[829]:     root : TTY=unknown ; PWD /private/tmp/PKInstallSandbox.IDea5j/Scripts/com.apple.pkg.DeveloperToolsLeo.hfuS3V ; USER=root ; COMMAND=/bin/launchctl load -w //System/Library/LaunchDaemons/com.apple.docsetinstalld.pli t
           8 %s %d %d:%d:%d %s %s[%d]:     %s : %s=%s ; %s=/%s/%s/%s/%s/%s ; %s=%s ; %s=/%s/%s %s //%s/%s/%s/%s||Dec 12 20:51:54 Rons-MacBook-Pro sudo[1343]:     root : TTY=unknown ; PWD=/ rivate/tmp/PKInstallSandbox.flT0Di/Scripts/com.apple.pkg.AppleMobileDeviceSupport.z2x5aw ; USER=root ; COMMAND=/bin/launchctl unload //System/Library/LaunchDaemons/com.apple.usbmuxd.plist
           8 %s %d %d:%d:%d %s %s[%d]: %s %s||Dec 12 14:57:04 localhost com.apple.SecurityServer[24]: Entering service
          14 %s %d %d:%d:%d %s %s[%d]: %s %s(): %s %s() & %s()||Dec 12 20:49:59 Rons-MacBook-Pro authorizationhost[1056]: in pam_sm_setcred(): Done setegid() & seteuid()
          14 %s %d %d:%d:%d %s %s[%d]: %s %s(): %s: %d||Dec 12 20:49:59 Rons-MacBook-Pro authorizationhost[1056]: in od_principal_for_user(): failed: 7
          14 %s %d %d:%d:%d %s %s[%d]: %s %s(): %s: %s||Dec 12 20:49:59 Rons-MacBook-Pro authorizationhost[1056]: in pam_sm_authenticate(): pam_sm_authenticate: ntlm
          17 %s %d %d:%d:%d %s %s[%d]: %s %d %s||Dec 12 14:57:03 localhost com.apple.SecurityServer[24]: Session 100000 created
          18 %s %d %d:%d:%d %s %s[%d]: %s %s %s %s '%s' %s %s '%s' [%d] %s %s %s %s '%s' [%d]||Dec 12 20:50:11 Rons-MacBook-Pro com.apple.SecurityServer[24]: Failed to authorize right 'sys em.install.app-store-software' by client '/System/Library/PrivateFrameworks/PackageKit.framework/Versions/A/Resources/installd' [1158] for authorization created by '/System/Library/CoreSer ices/Software Update.app' [1129]
          21 %s %d %d:%d:%d %s %s[%d]: %s %s(): %s %s: %s||Dec 12 20:49:59 Rons-MacBook-Pro authorizationhost[1056]: in pam_sm_authenticate(): Got user: rdilley
          35 %s %d %d:%d:%d %s %s[%d]: %s %s(): %s %s||Dec 12 20:49:59 Rons-MacBook-Pro authorizationhost[1056]: in pam_sm_authenticate(): Done cleanup3
          74 %s %d %d:%d:%d: --- %s %s %s %d %s ---||Dec 12 20:48:18: --- last message repeated 1 time ---
        3264 %s %d %d:%d:%d %s %s[%d]: %s %s %s '%s' %s %s '%s' [%d] %s %s %s %s '%s' [%d]||Dec 12 14:57:04 localhost com.apple.SecurityServer[24]: Succeeded authorizing right 'com.apple.S rviceManagement.daemons.modify' by client '/usr/libexec/UserEventAgent' [11] for authorization created by '/usr/libexec/UserEventAgent' [11]
----

If the standard templating mode is obscuring too much information, you can switch to clustering mode (-c).  This reduces the parsing speed, but allows the templates to retain all of the non-variable strings.  I normally strip off the trailing example line when running in this mode just to keep the line length more managable.  Below is an example of the same log processed with the clustering (-c) parsing option.

----
bash-3.2$ ./tmpltr -c /var/log/secure.log | sort -n
Opening [/var/log/secure.log] for read
           7 Dec %d %d:%d:%d Rons-MacBook-Pro authorizationhost[%d]: in ac_complete(): ac_complete returned: 0 for 502||Dec 12 20:49:59 Rons-MacBook-Pro authorizationhost[1056]: in ac_complete(): ac_complete returned: 0 for 502
           7 Dec %d %d:%d:%d Rons-MacBook-Pro authorizationhost[%d]: in od_principal_for_user(): No authentication authority returned||Dec 12 20:49:59 Rons-MacBook-Pro authorizationhost[1056]: in od_principal_for_user(): No authentication authority returned
           7 Dec %d %d:%d:%d Rons-MacBook-Pro authorizationhost[%d]: in od_record_attribute_create_cfstring(): returned 2 attributes for dsAttrTypeStandard:AuthenticationAuthority||Dec 12 20:49:59 Rons-MacBook-Pro authorizationhost[1056]: in od_record_attribute_create_cfstring(): returned 2 attributes for dsAttrTypeStandard:AuthenticationAuthority
           7 Dec %d %d:%d:%d Rons-MacBook-Pro authorizationhost[%d]: in pam_sm_acct_mgmt(): OpenDirectory - Membership cache TTL set to 1800.||Dec 12 20:49:59 Rons-MacBook-Pro authorizationhost[1056]: in pam_sm_acct_mgmt(): OpenDirectory - Membership cache TTL set to 1800.
           7 Dec %d %d:%d:%d Rons-MacBook-Pro authorizationhost[%d]: in pam_sm_authenticate(): Failed to determine Kerberos principal name.||Dec 12 20:49:59 Rons-MacBook-Pro authorizationhost[1056]: in pam_sm_authenticate(): Failed to determine Kerberos principal name.
           7 Dec %d %d:%d:%d Rons-MacBook-Pro authorizationhost[%d]: in pam_sm_authenticate(): Got ruser: (null)||Dec 12 20:49:59 Rons-MacBook-Pro authorizationhost[1056]: in pam_sm_authenticate(): Got ruser: (null)
           7 Dec %d %d:%d:%d Rons-MacBook-Pro authorizationhost[%d]: in pam_sm_authenticate(): Kerberos 5 refuses you||Dec 12 20:49:59 Rons-MacBook-Pro authorizationhost[1056]: in pam_sm_authenticate(): Kerberos 5 refuses you
           7 Dec %d %d:%d:%d Rons-MacBook-Pro authorizationhost[%d]: in pam_sm_setcred(): Done getpwnam()||Dec 12 20:49:59 Rons-MacBook-Pro authorizationhost[1056]: in pam_sm_setcred(): Done getpwnam()
           7 Dec %d %d:%d:%d Rons-MacBook-Pro authorizationhost[%d]: in pam_sm_setcred(): Got euid, egid: 0 0||Dec 12 20:49:59 Rons-MacBook-Pro authorizationhost[1056]: in pam_sm_setcred(): Got euid, egid: 0 0
           7 Dec %d %d:%d:%d Rons-MacBook-Pro authorizationhost[%d]: in pam_sm_setcred(): pam_sm_setcred: krb5 user rdilley doesn't have a principal||Dec 12 20:49:59 Rons-MacBook-Pro authorizationhost[1056]: in pam_sm_setcred(): pam_sm_setcred: krb5 user rdilley doesn't have a principal
           7 Dec %d %d:%d:%d Rons-MacBook-Pro authorizationhost[%d]: in pam_sm_setcred(): pam_sm_setcred: ntlm done||Dec 12 20:49:59 Rons-MacBook-Pro authorizationhost[1056]: in pam_sm_setcred(): pam_sm_setcred: ntlm done
           8 Dec %d %d:%d:%d %s %s[%d]: %s %s||Dec 12 14:57:04 localhost com.apple.SecurityServer[24]: Entering service
           8 Dec 12 %d:%d:%d Rons-MacBook-Pro sudo[%d]:     root : TTY=unknown ; PWD=/private/tmp/%s/Scripts/%s ; USER=root ; COMMAND=/bin/launchctl %s //System/Library/LaunchDaemons/%s||Dec 12 20:51:54 Rons-MacBook-Pro sudo[1343]:     root : TTY=unknown ; PWD=/private/tmp/PKInstallSandbox.flT0Di/Scripts/com.apple.pkg.AppleMobileDeviceSupport.z2x5aw ; USER=root ; COMMAND=/bin/launchctl unload //System/Library/LaunchDaemons/com.apple.usbmuxd.plist
           8 Dec 12 21:%d:%d Rons-MacBook-Pro sudo[%d]:     root : TTY=unknown ; PWD=/private/tmp/%s/Scripts/%s ; USER=%s ; COMMAND=/bin/launchctl load -w//System/Library/%s/%s||Dec 12 21:08:48 Rons-MacBook-Pro sudo[829]:     root : TTY=unknown ; PWD=/private/tmp/PKInstallSandbox.IDea5j/Scripts/com.apple.pkg.DeveloperToolsLeo.hfuS3V ; USER=root ; COMMAND=/bin/launchctl load -w //System/Library/LaunchDaemons/com.apple.docsetinstalld.plist
          14 Dec %d %d:%d:%d Rons-MacBook-Pro authorizationhost[%d]: in %s(): %s: %d||Dec 12 20:49:59 Rons-MacBook-Pro authorizationhost[1056]: in od_principal_for_user(): failed: 7
          14 Dec %d %d:%d:%d Rons-MacBook-Pro authorizationhost[%d]: in %s(): %s: ntlm||Dec 12 20:49:59 Rons-MacBook-Pro authorizationhost[1056]: in pam_sm_authenticate(): pam_sm_authenticate: ntlm
          14 Dec %d %d:%d:%d Rons-MacBook-Pro authorizationhost[%d]: in pam_sm_setcred(): Done %s() & %s()||Dec 12 20:49:59 Rons-MacBook-Pro authorizationhost[1056]: in pam_sm_setcred(): Done setegid() & seteuid()
          17 Dec %d %d:%d:%d %s com.apple.SecurityServer[24]: Session %d %s||Dec 12 14:57:03 localhost com.apple.SecurityServer[24]: Session 100000 created
          18 Dec %d %d:%d:%d Rons-MacBook-Pro com.apple.SecurityServer[24]: Failed to authorize right '%s' by client '/System/Library/PrivateFrameworks/PackageKit.framework/Versions/A/Resources/installd' [%d] for authorization created by '%s' [%d]||Dec 12 20:50:11 Rons-MacBook-Pro com.apple.SecurityServer[24]: Failed to authorize right 'system.install.app-store-software' by client '/System/Library/PrivateFrameworks/PackageKit.framework/Versions/A/Resources/installd' [1158] for authorization created by '/System/Library/CoreServices/Software Update.app' [1129]
          21 Dec %d %d:%d:%d Rons-MacBook-Pro authorizationhost[%d]: in %s(): Got %s: %s||Dec 12 20:49:59 Rons-MacBook-Pro authorizationhost[1056]: in pam_sm_authenticate(): Got user: rdilley
          35 Dec %d %d:%d:%d Rons-MacBook-Pro authorizationhost[%d]: in %s(): %s %s||Dec 12 20:49:59 Rons-MacBook-Pro authorizationhost[1056]: in pam_sm_authenticate(): Done cleanup3
          74 Dec %d %d:%d:%d: --- last message repeated %d %s ---||Dec 12 20:48:18: --- last message repeated 1 time ---
        3265 Dec %d %d:%d:%d %s com.apple.SecurityServer[24]: Succeeded authorizing right '%s' by client '%s' [%d] for authorization created by '%s' [%d]||Dec 12 14:57:04 localhost com.apple.SecurityServer[24]: Succeeded authorizing right 'com.apple.ServiceManagement.daemons.modify' by client '/usr/libexec/UserEventAgent' [11] for authorization created by '/usr/libexec/UserEventAgent' [11]
----

You can use the same syntax but also store copies of all
of the unique templates by using the '-w {fname}' switch.
When you do this, the file references with the switch is
over written with a <CR> delimited list of the templates.

The template file can be used with the '-t {fname}' switch
to provide artificial ignorance capabilities.

----
% tmpltr -w ignore.templates /var/log/system.log | sort -n
----

After the above run of the tool, a file named ignore.templates
is created in the current directory as shown below:

----
$ cat ignore.templates

%s %d %d:%d:%d %s [%s].%s[%d]: [%s] [%s %s] %s %s %s %s %s://%s/%s/%s (%s %s %s %s://%s %s %s)
%s %d %d:%d:%d %s %s[%d]: %s %s %s "%s"
%s %d %d:%d:%d %s %s %s[%d]: %s: %s %s %d %s:
%s %d %d:%d:%d %s %s[%d]: %s: %s - %s %d - %s %s
%s %d %d:%d:%d %s %s[%d]: %s %s %s %s %s %s - %s %s %s %s %s
%s %d %d:%d:%d %s %s[%d]: %s %s
%s %d %d:%d:%d %s %s[%d]: %s(%d.%d.%d.%d) (%s=%d): %s %s %s %s
%s %d %d:%d:%d %s %s[%d]: %s %s %s/%s %s %s %s %s %s %s %d %d %s %d:%d:%d, %s %s %s %s %s %d %d %s %d:%d:%d
%s %d %d:%d:%d %s %s[%d]: %s %s %s %d, %s
%s %d %d:%d:%d %s %s[%d] (%s[%d]): %s %s %s %s: %d
%s %d %d:%d:%d %s %s[%d]: %s %s %s %s %s %s
%s %d %d:%d:%d %s [%s].%s[%d]: %s %s, %s=-%d
%s %d %d:%d:%d %s %s[%d]: %s %s %s %s %s %s %s %s: /%s/%s/%s/%d.%d.%d.%s
%s %d %d:%d:%d %s %s[%d]: %s %s %s %s (%s: %d) - %s %s:%d.%d, # %s %s: %d, # %s %s %s: %d, %s %s: %s, %s %s %s: %d, %s %s %s: %d
%s %d %d:%d:%d %s %s[%d]: %s %s %s %s %s %d %s
%s %d %d:%d:%d %s %s[%d]: %s %s %s %s %s %s: %s:/%s/%s/%s
%s %d %d:%d:%d %s %s[%d]: %s %s %s %d %s
%s %d %d:%d:%d %s %s[%d]: %s %s -%d.%d %c
%s %d %d:%d:%d %s %s[%d]: %s: %s %s
%s %d %d:%d:%d %s %s[%d] (%s): %s %s: %s %s %s %d %s
%s %d %d:%d:%d %s %s[%d]: _%s: %s %s %s %s '%s'
%s %d %d:%d:%d %s %s[%d]: %s: %s %s %s %s %s (%d.%d.%d.%d)
%s %d %d:%d:%d %s %s[%d]: %s %s %s %s %s, %s:%d/%d/%d %d:%d:%d.%d %s - %s:%d/%d/%d %d:%d:%d.%d %s = %s:%d.%d
%s %d %d:%d:%d %s %s[%d]: %s: %s %s %s %s %d
%s %d %d:%d:%d %s %s[%d]: %s: %s - %s %d - %s
%s %d %d:%d:%d %s [%s].%s[%d]: [%s] [%s %s] %s %s %s %s %s://%s/%s/%s (%s %s %s %s: %s %s)
%s %d %d:%d:%d %s %s %s %s[%d]: %s %s %s %s (%s: %d) - %s %s:%d.%d, # %s %s: %d, # %s %s %s: %d, %s %s: %s, %s %s %s: %d, %s %s %s: %d
%s %d %d:%d:%d %s %s[%d]: %s %s %s
%s %d %d:%d:%d %s %s[%d]: %s(%d.%d.%d.%d) (%s=%d): %s %s %s
%s %d %d:%d:%d %s [%s].%s[%d]: %s %s %s %s %s %s %s - %s %s %s %s %s %s %s
%s %d %d:%d:%d %s %s[%d]: %s %s %s: %s
%s %d %d:%d:%d %s %s[%d]: %s %s, -%d
%s %d %d:%d:%d: --- %s %s %s %d %s ---
%s %d %d:%d:%d %s %s[%d]: %s %s %s %s
%s %d %d:%d:%d %s %s[%d]: %s: %s %s %s %s %s %s
----

You can now pass this file back into tmpltr and all
log lines that match an existing template pattern will
be ignored.  This is the real utility of the tool.  Using
this teqnique, you can train tmpltr to ignore all log
patterns that have been seen before and only show log
templates for new patterns.

This is how I use to tool during incident repsonse.  I
push all the log data that I have for the period of my
choice before the detected event into tmpltr and save
the pattern file, then run tmpltr against the log data for
the period around when the detected event happened.

----
$ ./tmpltr -t ignore.templates /var/log/system.log
----

A couple of things to note about the '-w' and '-t' switches:

If you use the '-w' switch in conjunction with the '-t',
you should not read from and write to the same file.  This
version of tmpltr would allow you to do it without an issue
if you pass the read '-t {fname}' arguments before the
write '-w {fname}' arguments but future versions may not
work as expected.

Additionally, when you load templates using the '-t' switch
then write all the templates using the '-w' switch, then
new file will contain all of the templates loaded from the
template file as well as any new unique templates discovered
in the processing of the log files.

In this way, i you can have your most recent saved template file
always contain all of the templates that have been discovered.

By default, the tool assumes that anything inside of a pair
of double quotes is a single string.  This is really helpful
when processing log lines where unstrctured data is included
bounded by double quotes.  The user agent strings in Apache
web logs is a good example of this.  There are times though
when it is really nice to be able to tokenize the data between
those double quotes.  You can use the greedy (-g) switch to
ignore the double quotes and everything between them will be
parsed the same was as all other patterns in the line.

== Security Implications

Assume that there are errors in the tmpltr source that
would allow a specially crafted logs to allow an attacker
to exploit tmpltr to gain access to the computer that it is
running on!!!  Don't trust this software and install and use
it at your own risk.

== Bugs

I am not a programmer by any stretch of the imagination.  I
have attempted to remove the obvious bugs and other
programmer related errors but please keep in mind the first
sentence.  If you find an issue with code, please send me
an e-mail with details and I will be happy to look into
it.

Ron Dilley
ron.dilley@uberadmin.com