A log format analyzing tool from existing text log file

NOTE: This article was written mainly by machine translation. I apologize if this is hard to understand.

I created a log format analysing tool in Go and this post introduce it.

What is "log format analysis"?

In this post, "log format" means like format string in C, Go or etc.

log.Printf("Requested from %s", ipAddr)

This code output following logs.

2018/05/23 23:25:00 Requested from 10.0.2.1
2018/05/23 23:25:10 Requested from 192.168.1.5
2018/05/23 23:25:24 Requested from 10.0.1.5

The original format is embedded in %s as IP address and output as text like below. Since this example is very simple, it is easy to guess from the bottom to the top, but as the content becomes more complicated it is rarely common to say, 'What is this value or fixed statement?' The tool created this time is to infer the format statement (close to) above from the output below. We are implementing two functions for This tool: 1) Estimate the format from already output log file , and 2) Use the estimated format and see where the log corresponding to that format appeared in the log file.

Why the tool is required?

This tool is unnecessary in environments that handle only normalized and structured log data, but it is useful in the following situations.

• When you want to grasp the whole picture of the log : I think that it is particularly frequent in the context of security analysis, but there are times when it is necessary to see a large amount of logs that have never been seen before and to draw knowledge from there . Even if you try to view with the less command at all, it is severe for humans, so what kind of logs are there as a whole? And what kind of distribution do you do? If you find out that it is, the analysis will be much easier. Especially in the security analysis, it is not the log concerning the usual service accounting for 99% of the whole in many cases, it is the point where something abnormality happened. Since it is easy for errors and processing that are not normally seen to occur, logs when abnormality happens, if you can grasp where logs with abnormal logs = unusual formats appear, we will analyze them first by focusing on them You can make a foothold.
• If you need to reuse logs output in text format : If you are already running a service etc. and you want to output logs in text, add the log to the regular expression etc. It is necessary to extract the value being processed. If you have a specification, it is nice, but if not, you can see the source code or write a regular expression → make sure it is exhaustive → fix the regular expression, you have to repeat things like it is rather troublesome ((I think there are tsukkom that such an environment is more funny, but it was rarely a situation, especially in the former position). This tool does not estimate the regular expression of the value to be extracted, but it will be easier to work because it can cover how far it can be done from the existing logs.

Usage

If you already have Go language environment, you can install it by go get github.com/m-mizutani/logptn

https://github.com/m-mizutani/logptn

For example, I try to use this tool with following logs.

$ cat test.log
Feb  1 07:56:49 pylon sshd[5153]: pam_unix(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=192.168.0.3  user=root
Feb  1 07:56:51 pylon sshd[5153]: Failed password for root from 192.168.0.3 port 7176 ssh2
Feb  1 07:56:51 pylon sshd[5153]: Connection closed by 192.168.0.3 [preauth]
Feb  1 08:01:26 pylon sshd[5156]: Invalid user upload from 192.168.0.3
Feb  1 08:01:26 pylon sshd[5156]: input_userauth_request: invalid user upload [preauth]
Feb  1 08:01:26 pylon sshd[5156]: pam_unix(sshd:auth): check pass; user unknown
Feb  1 08:01:26 pylon sshd[5156]: pam_unix(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=192.168.0.3
Feb  1 08:01:28 pylon sshd[5156]: Failed password for invalid user upload from 192.168.0.3 port 51058 ssh2
Feb  1 08:01:28 pylon sshd[5156]: Connection closed by 192.168.0.3 [preauth]
Feb  1 08:05:01 pylon CRON[5159]: pam_unix(cron:session): session opened for user root by (uid=0)
Feb  1 08:05:01 pylon CRON[5159]: pam_unix(cron:session): session closed for user root
Feb  1 08:05:54 pylon sshd[5162]: pam_unix(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=192.168.0.3  user=root
Feb  1 08:05:56 pylon sshd[5162]: Failed password for root from 192.168.0.3 port 33005 ssh2
Feb  1 08:05:56 pylon sshd[5162]: Connection closed by 192.168.0.3 [preauth]
Feb  1 08:10:28 pylon sshd[5165]: Invalid user mythtv from 192.168.0.3
Feb  1 08:10:28 pylon sshd[5165]: input_userauth_request: invalid user mythtv [preauth]
Feb  1 08:10:28 pylon sshd[5165]: pam_unix(sshd:auth): check pass; user unknown
Feb  1 08:10:28 pylon sshd[5165]: pam_unix(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=192.168.0.3
Feb  1 08:10:30 pylon sshd[5165]: Failed password for invalid user mythtv from 192.168.0.3 port 59978 ssh2
Feb  1 08:10:30 pylon sshd[5165]: Connection closed by 192.168.0.3 [preauth]
Feb  1 08:15:01 pylon CRON[5168]: pam_unix(cron:session): session opened for user root by (uid=0)
Feb  1 08:15:01 pylon CRON[5168]: pam_unix(cron:session): session closed for user root
Feb  1 08:15:26 pylon sshd[5171]: pam_unix(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=10.2.3.4  user=root
Feb  1 08:15:28 pylon sshd[5171]: Failed password for root from 10.2.3.4 port 60733 ssh2
Feb  1 08:15:28 pylon sshd[5171]: Connection closed by 10.2.3.4 [preauth]
Feb  1 08:17:01 pylon CRON[5173]: pam_unix(cron:session): session opened for user root by (uid=0)
Feb  1 08:17:01 pylon CRON[5173]: pam_unix(cron:session): session closed for user root
Feb  1 08:20:35 pylon sshd[5177]: pam_unix(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=10.2.3.4  user=root
Feb  1 08:20:37 pylon sshd[5177]: Failed password for root from 10.2.3.4 port 44877 ssh2
Feb  1 08:20:37 pylon sshd[5177]: Connection closed by 10.2.3.4 [preauth]
Feb  1 08:25:01 pylon CRON[5180]: pam_unix(cron:session): session opened for user root by (uid=0)
Feb  1 08:25:01 pylon CRON[5180]: pam_unix(cron:session): session closed for user root
Feb  1 08:25:16 pylon sshd[5183]: Invalid user user from 10.2.3.4

From above log data, the tool output following result.

./logptn test.log
2018/05/20 13:30:55 arg:test.log
     4 [4ffb267b] Feb  1 *:*:* pylon sshd[*]: pam_unix(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=*  user=root
     4 [845f4659] Feb  1 *:*:* pylon sshd[*]: Failed password for root from * port * ssh2
     6 [847ccf35] Feb  1 *:*:* pylon sshd[*]: Connection closed by * [preauth]
     3 [de051cd9] Feb  1 08:*:* pylon sshd[*]: Invalid user * from *
     2 [8e9e2a13] Feb  1 08:*:* pylon sshd[*]: input_userauth_request: invalid user * [preauth]
     2 [22190c74] Feb  1 08:*:* pylon sshd[*]: pam_unix(sshd:auth): check pass; user unknown
     2 [83fba2bf] Feb  1 08:*:* pylon sshd[*]: pam_unix(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=192.168.0.3
     2 [f1ba83ea] Feb  1 08:*:* pylon sshd[*]: Failed password for invalid user * from 192.168.0.3 port * ssh2
     4 [e4a6f815] Feb  1 08:*:01 pylon CRON[*]: pam_unix(cron:session): session opened for user root by (uid=0)
     4 [5256845b] Feb  1 08:*:01 pylon CRON[*]: pam_unix(cron:session): session closed for user root

In this output, it is "the number of times that format appeared" "format ID" "estimated format" from the left. Also, in the estimated format, the part that is supposed to be embedded as a value is replaced by the symbol *. In this example there are few samples, so the IP address part is not *, but as the number of samples increases it will also be replaced with *. The above is output in human readable text format, but it can also be output in json format so that it can be handled by another program.

./logptn test.log -d sjson | jq . 
{
  "formats": [
    {
      "segments": [
        "Feb  1 ",
        null,
        ":",
        null,
        ":",
        null,
        " pylon sshd[",
        null,
        "]: pam_unix(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=",
        null,
        "  user=root"
      ],
      "count": 4
    },
(snip)

In addition, you can display in HTML format how many lines of that log format the format appeared.

$ ./logptn  ./var/log/secure -d heatmap -o secure.html

With the above command you can create a heat map showing the format of the log and what line it occurred. The heat map is the format estimated on the left, the top header is the number of lines (the line number to the line number), and the right is the total log number. The image below is a little small and hard to see, but the HTML file itself can also be downloaded from here.

Large size image

Performance

The calculation amount is O (NM), N is the total number of logs included in the log file, M is the estimated number of formats. I tried with various log files, but M converges to about 10 to 100, so N is the total number of logs affected. Although it measures only miscellaneous, I moved it with MacBookPro Early 2015 (2.7 GHz Intel Core i 5) for data that is about M = 40 and ran around 30,000 logs / sec. Perhaps it can be optimized more in terms of code, but I have not done so far yet.

Comments

[Lior Banai]

if you have gRPC support you can stream logs to my real time log server and view it in my Analogy Log Viewer that support gRPC