Go на практике. Фильтруем access-логи.

14.02.2019

Не так давно ко мне пришла идея построить систему по анализу трафика вместо Google Analytics, Яндекс Метрики для того, чтобы как можно меньше внешних скриптов и трекеров использовалось на сайте. Будем анализировать access-логи , но для начала хорошо бы их почистить.

Так как сейчас я изучаю Go(golang), то в этой статье попробуем создать утилиту командной строки(cli), которая вычистит “мусор” из логов web-сервера и эти “чистые” данные можно будет использовать в goaccess.

Проблема

После установки и настройки goaccess у меня получился такой график за декабрь:

Посещения за месяц

Цифры впечатляют. Но если пристально взглянуть на другие показатели, например, браузеры, с которых пришли пользователи (user agent), то видно, что не всё так хорошо.

Список браузеров

Получается, что из 2800 запросов:

  • 426 запросов - от неизвестного user agent-a (браузера)
  • 834 запроса - от разных кроулеров и ботов (curl, wget, go http client, Firefox 5.0), из которых 20 - от Яндекс браузера и Avant браузера
  • 248 запросов - от разных агрегаторов RSS лент (Feedly)

В эти запросы включаются все картинки и скрипты. Мне же интереснее смотреть сколько было посещений на главной и в статьях (html страницы).

Формат логов у меня стандартный для nginx:

$remote_addr - $remote_user [$time_local] "$request" $status $body_bytes_sent "$http_referer" "$http_user_agent"

Требования

Значит, нужно разработать утилиту, которая будет чистить логи от “мусора”, а конкретно можно выразить в требованиях:

  1. читать логи из STDIN, выводить в STDOUT bash cat /var/log/nginx/access.log| access-log-filter | goaccess
  2. оставить только успешные запросы со статусом “200”, $status
  3. оставить только запросы на главную страницу (путь “/”) и на статьи (путь “*.html”), смотрим на $request
  4. игнорировать всякие кровлеры и неизвестные браузеры, фильтруем по user_agent
  5. анонимизация ip адресов (можно скинуть кому-нибудь логи и не боятся последствий), последнее число в remote_addr последнее число заменяется нулём.

Реализация

Тоже самое можно написать и в bash при помощи grep, aws,sed, но со временем такой скрипт очень тяжело поддерживать, да и есть дополнительный повод улучшить свои навыки программирования на Go. Полный текст программы можно найти в самом конце статьи, если вам интересно почитать подробнее, то давайте приступим.

1. Разбиваем строку логов в словарь.

Первым делом напишем функцию, преобразующую строку лога в словарь. Создаём файл main.go

package main

import (
	"regexp"
)

func ConvertLogLineToMap(logLine string) map[string]string {
	regexPattern := `(?P<remote_addr>\d+\.\d+\.\d+\.\d+) - -` +
		` \[(?P<time_local>[^\]]+)\] \"(?P<request>.*)\" (?P<status>[0-9]+)` +
		` (?P<body_bytes_sent>[0-9]+) \"(?P<http_referer>.*)\" \"` +
		`(?P<http_user_agent>.+)\"`
	re := regexp.MustCompile(regexPattern)
	parsedMap := make(map[string]string)
	match := re.FindStringSubmatch(logLine)
	if match == nil {
		return nil
	}
	for i, name := range re.SubexpNames() {
		if i != 0 {
			parsedMap[name] = match[i]
		}
	}
	return parsedMap
}


func main() {
}

Эта функция парсит строку

52.87.65.11 - - [02/Nov/2018:06:55:13 +0000] "GET /feed.xml HTTP/1.1" 200 9810 "-" "curl"

и преобразует её в словарь(map) вида:

parsedLine["remote_addr"] = "52.87.65.11"
parsedLine["remote_user"] = ""
parsedLine["time_local"] = "02/Nov/2018:06:55:13 +0000"
parsedLine["request"] = "GET /feed.xml HTTP/1.1"
parsedLine["status"] = "200"
parsedLine["body_bytes_sent"] = "10"
parsedLine["http_referer"] = "-"
parsedLine["http_user_agent"] = "curl"
``````

Это делается для того, чтобы легче было потом обрабатывать отдельные данные, а не парсить каждый раз всю строку.
Советую обратить внимание на [FindStringSubmatch](https://golang.org/pkg/regexp/#Regexp.FindStringSubmatch), он создаёт слайс(slice) c извлечёнными данными, а при помощи [SubexpNames](https://golang.org/pkg/regexp/#Regexp.SubexpNames) можно получить слайс из имён этих параметров. В цикле потом просто связываем два эти слайса в словарь, где ключом будет название поля(status, http_user_agent и т.д.), а значением распознанная информация.

Напишем несколько тестов в файле `main_test.go`:
```golang
package main

import (
	"testing"
)

func assertMaps(t *testing.T, got, want map[string]string) {
	t.Helper()
	for k, _ := range want {
		if got[k] != want[k] {
			t.Errorf("\nexpected value: %s\n     got value: %s", want[k], got[k])
		}
	}
}

func TestConvertLogLine(t *testing.T) {
	logLine := ""
	t.Run("Parsing normal log entry", func(t *testing.T) {
		logLine = `52.87.65.11 - - [02/Nov/2018:06:55:13 +0000] "GET /feed.xml HTTP/1.1" 200 9810 "-" "curl"`
		expectedResult := map[string]string{
			"remote_addr":     "52.87.65.11",
			"remote_user":     "",
			"time_local":      "02/Nov/2018:06:55:13 +0000",
			"request":         "GET /feed.xml HTTP/1.1",
			"status":          "200",
			"body_bytes_sent": "9810",
			"http_referer":    "-",
			"http_user_agent": "curl",
		}
		parsedLine := ConvertLogLineToMap(logLine)
		assertMaps(t, parsedLine, expectedResult)
	})

	t.Run("Parsing normal log entry with empty user agent", func(t *testing.T) {
		logLine = `190.128.131.6 - - [03/Nov/2018:23:25:08 +0000] "" 400 0 "-" "-"`
		expectedResult := map[string]string{
			"remote_addr":     "190.128.131.6",
			"remote_user":     "",
			"time_local":      "03/Nov/2018:23:25:08 +0000",
			"request":         "",
			"status":          "400",
			"body_bytes_sent": "0",
			"http_referer":    "-",
			"http_user_agent": "-",
		}
		parsedLine := ConvertLogLineToMap(logLine)
		assertMaps(t, parsedLine, expectedResult)
	})

	t.Run("Parsing strange line that should fail", func(t *testing.T) {
		logLine = `190.XXXX.XXXXX.XXX - - [03/Nov/2018:23:25:08 +0000] "" 400 0 "-" "-"`
		parsedLine := ConvertLogLineToMap(logLine)
		assertMaps(t, parsedLine, nil)
	})
}

В тестах мы прогоняем строки логов через нашу функцию и проверяем, что результат совпадает с ожидаемым.

Могу сказать, что написание тестов, хоть и отнимает время в начале, но зато существенно экономит его, когда хочется что-нибудь дописать. Рекммендую глянуть в сторону TDD

Проверить, что все тесты работают можно командой:

$ go test
PASS
ok      _/Users/myuser/projects/access-log-filter    0.009s

2. Преобразуем словарь в строку логов

Эта операция обратна предыдущей. Нужна она чтобы, при изменении каких-то данных(анонимизировали ip адрес), можно сформировать правильную строку лога.

В файл main.go добавим функцию:

func ConvertMapToLogLine(parsedLine map[string]string) string {
	remote_addr := parsedLine["remote_addr"]
	time_local := parsedLine["time_local"]
	request := parsedLine["request"]
	status := parsedLine["status"]
	body_bytes_sent := parsedLine["body_bytes_sent"]
	http_referer := parsedLine["http_referer"]
	http_user_agent := parsedLine["http_user_agent"]
	return fmt.Sprintf(`%s - - [%s] "%s" %s %s "%s" "%s"`, remote_addr,
		time_local, request, status, body_bytes_sent, http_referer,
		http_user_agent)
}

В секцию import нужно дописать модуль “fmt”.

Допишем тесты для этой функции в main_test.go:

func TestConvertMapToLogLine(t *testing.T) {
	t.Run("Parsing normal map entry", func(t *testing.T) {
		expectedLogLine := `52.87.65.11 - - [02/Nov/2018:06:55:13 +0000] "GET /feed.xml HTTP/1.1" 200 9810 "-" "curl"`
		parsedMap := map[string]string{
			"remote_addr":     "52.87.65.11",
			"remote_user":     "",
			"time_local":      "02/Nov/2018:06:55:13 +0000",
			"request":         "GET /feed.xml HTTP/1.1",
			"status":          "200",
			"body_bytes_sent": "9810",
			"http_referer":    "-",
			"http_user_agent": "curl",
		}
		generatedLogLine := ConvertMapToLogLine(parsedMap)
		if expectedLogLine != generatedLogLine {
			t.Errorf("Log line did not match!.\nExpected: '%s'\n      Got:'%s'", expectedLogLine, generatedLogLine)
		}
	})
	t.Run("Parsing normal map entry with anonimized ip", func(t *testing.T) {
		expectedLogLine := `190.128.131.6 - - [03/Nov/2018:23:25:08 +0000] "" 400 0 "-" "-"`
		parsedMap := map[string]string{
			"remote_addr":     "190.128.131.6",
			"remote_user":     "",
			"time_local":      "03/Nov/2018:23:25:08 +0000",
			"request":         "",
			"status":          "400",
			"body_bytes_sent": "0",
			"http_referer":    "-",
			"http_user_agent": "-",
		}
		generatedLogLine := ConvertMapToLogLine(parsedMap)
		if expectedLogLine != generatedLogLine {
			t.Errorf("Log line did not match!.\nExpected: '%s'\n      Got:'%s'", expectedLogLine, generatedLogLine)
		}
	})
}

3. Чтение из STDIN

Дописываем в функцию main в файле main.go

func main() {
    scanner := bufio.NewScanner(os.Stdin)
    for scanner.Scan() {
        fmt.Println(scanner.Text())
    }

    if err := scanner.Err(); err != nil {
        fmt.Fprintln(os.Stderr, "error:", err)
        os.Exit(1)
    }
}

А в import:

    "bufio"
    "fmt"
    "os"
    "strings"

Для работы с вводом/выводом будем использовать объект типа Scanner из пакета bufio, у которого есть функция Scan(). В качестве ввода передаём STDIN, в Go берётся из пакета os. Затем построчно читаем всё, что пришло на STDIN.

Чтобы посмотреть в текстовом виде, что пришло на ввод воспользуемся функцией Text.

Если происходит какая-нибудь ошибка, например мы оборвали процесс чтения Ctrl-c, просто выводим эту ошибку и выходим.

Получается программа что читает, то и пишет.

Теперь, убедимся, что программа работает как надо:

$ cat old_access.log |go run main.go |wc -l
6838
$ cat old_access.log |wc -l
6838
$ cat old_access.log |go run main.go |head -n5
18.207.127.0 - - [01/Jan/2019:06:27:09 +0000] "GET /twe-feed.xml HTTP/1.1" 200 16988 "-" "curl"
164.52.24.0 - - [01/Jan/2019:06:39:54 +0000] "GET / HTTP/1.1" 400 280 "-" "Mozilla/5.0 (Windows NT 6.1; WOW64; rv:52.0) Gecko/20100101 Firefox/52.0"
157.55.39.0 - - [01/Jan/2019:07:17:12 +0000] "GET / HTTP/1.1" 200 4402 "-" "Mozilla/5.0 (compatible; bingbot/2.0; +http://www.bing.com/bingbot.htm)"
3.82.126.0 - - [01/Jan/2019:07:57:15 +0000] "GET /twe-feed.xml HTTP/1.1" 200 16988 "-" "curl"
54.157.251.0 - - [01/Jan/2019:08:27:18 +0000] "GET /twe-feed.xml HTTP/1.1" 200 16988 "-" "curl"
$ cat old_access.log |head -n5
18.207.127.0 - - [01/Jan/2019:06:27:09 +0000] "GET /twe-feed.xml HTTP/1.1" 200 16988 "-" "curl"
164.52.24.0 - - [01/Jan/2019:06:39:54 +0000] "GET / HTTP/1.1" 400 280 "-" "Mozilla/5.0 (Windows NT 6.1; WOW64; rv:52.0) Gecko/20100101 Firefox/52.0"
157.55.39.0 - - [01/Jan/2019:07:17:12 +0000] "GET / HTTP/1.1" 200 4402 "-" "Mozilla/5.0 (compatible; bingbot/2.0; +http://www.bing.com/bingbot.htm)"
3.82.126.0 - - [01/Jan/2019:07:57:15 +0000] "GET /twe-feed.xml HTTP/1.1" 200 16988 "-" "curl"
54.157.251.0 - - [01/Jan/2019:08:27:18 +0000] "GET /twe-feed.xml HTTP/1.1" 200 16988 "-" "curl"

Похоже не обманывает. Идём дальше по списку.

4. Фильтруем

Для фильтрации создадим функцию matchAllRequirements, которая принимает на вход словарь и проверяет все наши условия и возвращает true или false. В Go switch case работает несколько иначе, чем в других языках, а именно можно не быть привязанным к одной переменной и проверять разные условия.

func matchAllRequirements(parsedLine map[string]string) bool {
	request := regexp.MustCompile(`GET (.+\.html|\/\d*\/\d*\/\d*\/.*\/|\/\?.*)(\?.*)? HTTP\/1\.[10]`)
	http_user_agent := regexp.MustCompile(`.*([Bb]ot|vkShare|Google-AMPHTML|feedly|[cC]rawler|[Pp]arser|curl|-).*`)
	switch {
	case parsedLine["status"] != "200":
		return false
	case !request.MatchString(parsedLine["request"]):
		return false
	case http_user_agent.MatchString(parsedLine["http_user_agent"]):
		return false
	default:
		return true
	}
}

Вот так легко и лаконично можно проверить по всем параметрам, причём не обязательно использовать регулярные выражения, как мы сделали для проверки статус кода(status)

В функцию main добавим вызов проверочной фунции:

func main() {
	scanner := bufio.NewScanner(os.Stdin)
	for scanner.Scan() {
		parsedLine := ConvertLogLineToMap(scanner.Text())
		if matchAllRequirements(parsedLine) == false {
			continue
		}
		fmt.Println(scanner.Text())
	}
}

Тесты в main_test.go:

func TestLogLineOK(t *testing.T) {
	cases := map[string]bool{
		`159.203.112.40 - - [05/Jan/2019:22:35:12 +0000] "GET / HTTP/1.0" 200 13444 "-" "Mozilla/5.0 (compatible; NetcraftSurveyAgent/1.0; +info@netcraft.com)"`:                                                                                                        false,
		`213.138.93.47 - - [05/Jan/2019:23:36:41 +0000] "GET /2018/08/25/aws-certification-preparation.html HTTP/1.1" 200 7779 "https://www.google.com/" "Mozilla/5.0 (Windows NT 6.1; Win64; x64; rv:64.0) Gecko/20100101 Firefox/64.0"`:                               true,
		`213.138.93.47 - - [05/Jan/2019:23:36:42 +0000] "GET /?facebook HTTP/1.1" 200 4402 "https://makvaz.com/2018/08/25/aws-certification-preparation.html" "Mozilla/5.0 (Windows NT 6.1; Win64; x64; rv:64.0) Gecko/20100101 Firefox/64.0"`:                          true,
		`199.16.157.180 - - [02/Jan/2019:11:54:10 +0000] "GET /2018/09/25/effective-devops.html HTTP/1.1" 200 10399 "-" "Twitterbot/1.0"`:                                                                                                                               false,
		`199.16.157.183 - - [02/Jan/2019:11:54:10 +0000] "GET /assets/img/header-pic.jpeg HTTP/1.1" 200 696591 "-" "Twitterbot/1.0"`:                                                                                                                                    false,
		`54.36.148.130 - - [02/Jan/2019:12:06:17 +0000] "GET /blog/page3/ HTTP/1.1" 200 3586 "-" "Mozilla/5.0 (compatible; AhrefsBot/6.1; +http://ahrefs.com/robot/)"`:                                                                                                  false,
		`125.212.217.215 - - [02/Jan/2019:16:03:08 +0000] "GET /robots.txt HTTP/1.1" 200 40 "-" "-"`:                                                                                                                                                                    false,
		`40.77.167.146 - - [02/Jan/2019:16:03:59 +0000] "GET /about/ HTTP/1.1" 200 3193 "-" "Mozilla/5.0 (compatible; bingbot/2.0; +http://www.bing.com/bingbot.htm)"`:                                                                                                  false,
		`89.64.54.234 - - [25/Feb/2019:19:07:01 +0000] "GET /2019/03/07/ideal-cicd-on-practice1/ HTTP/1.1" 200 11379 "https://makvaz.com/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_14_3) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/72.0.3626.121 Safari/537.36"`: true,
	}
	for testCase, expectedResult := range cases {
		parsedLine := ConvertLogLineToMap(testCase)
		actualResult := matchAllRequirements(parsedLine)
		if actualResult != expectedResult {
			t.Errorf("result for line: '%s'\n returned wrong value: %t, expected: %t", testCase, actualResult, expectedResult)

		}
	}
}

Посмотрим, сколько осталось записей после отсева.

$ cat old_access.log |wc -l
6838
$ cat old_access.log |go run main.go |wc -l
458

Отсеялось больше 90% всего трафика, зато честно и понятно.

5. Добавляем анонимизацию ip адресов.

Чтобы не выдавать настоящие ip адреса посетителей, можно их анонимизировать. Для этого в файле main.go добавим функцию:

func AnonymizeIp(ip string) string {
	return ip[:strings.LastIndex(ip, ".")+1] + "0"
}

Вместо последнего числа(октета) в ip адресе записываем 0.

И куда без тестов в main_test.go:

func TestAnonymizeIp(t *testing.T) {
	cases := map[string]string{
		"5.255.250.183":   "5.255.250.0",
		"141.8.144.9":     "141.8.144.0",
		"178.154.244.157": "178.154.244.0",
		"40.77.167.89":    "40.77.167.0",
		"66.249.69.70":    "66.249.69.0",
	}
	for testCase, expectedResult := range cases {
		actualResult := AnonymizeIp(testCase)
		if actualResult != expectedResult {
			t.Errorf("result for line: '%s'\n returned wrong value: %s, expected: %s", testCase, actualResult, expectedResult)
		}
	}
}

Заключение.

По итогу получился вот такой график:

Подчищенные посещения за месяц

Сегодня мы написали достаточно простую программу по очищению логов. Её можно использовать для генерации отчётов в связке с goaccess на сервере.

Что можно улучшить:

  • добавить фильтрацию по дате/диапазону дат
  • иметь возможность читать файл целиком а не из STDIN
  • Фильтры подгружать из внешнего файла
  • улучшить читаемость тестов
  • Строить графики )

Если вы хотите сами поупражняться, то вот вам мой лог

Полезные ссылки

  1. Документация по Go
  2. Курсы по Go от mail.ru
  3. Интересный ресурс по Go

UPDATE 27.03.2019

После того, как сайт переехал на Hugo, ссылки стали выглядеть иначе, например https://makvaz.com/2019/02/14/golang-in-practice1/ , поэтому проверка запросов несколько поменялась. Смотрите функцию matchAllRequirements, также поправил строки для тестирования.

Полный текст программы

package main
import (
	"bufio"
	"fmt"
	"os"
	"regexp"
	"sort"
	"strings"
)
func ConvertLogLineToMap(logLine string) map[string]string {
	regexPattern := `(?P<remote_addr>\d+\.\d+\.\d+\.\d+) - -` +
		` \[(?P<time_local>[^\]]+)\] \"(?P<request>.*)\" (?P<status>[0-9]+)` +
		` (?P<body_bytes_sent>[0-9]+) \"(?P<http_referer>.*)\" \"` +
		`(?P<http_user_agent>.+)\"`
	re := regexp.MustCompile(regexPattern)
	parsedMap := make(map[string]string)
	match := re.FindStringSubmatch(logLine)
	if match == nil {
		return nil
	}
	for i, name := range re.SubexpNames() {
		if i != 0 {
			parsedMap[name] = match[i]
		}
	}
	return parsedMap
}
func matchAllRequirements(parsedLine map[string]string) bool {
	request := regexp.MustCompile(`GET (.+\.html|\/\d*\/\d*\/\d*\/.*\/|\/\?.*)(\?.*)? HTTP\/1\.[10]`)
	http_user_agent := regexp.MustCompile(`.*([Bb]ot|vkShare|Google-AMPHTML|feedly|[cC]rawler|[Pp]arser|curl|-).*`)
	switch {
	case parsedLine["status"] != "200":
		return false
	case !request.MatchString(parsedLine["request"]):
		return false
	case http_user_agent.MatchString(parsedLine["http_user_agent"]):
		return false
	default:
		return true
	}
}
func sortByPopularity(metric map[string]int) {
	n := map[int][]string{}
	var a []int
	for k, v := range metric {
		n[v] = append(n[v], k)
	}
	for k := range n {
		a = append(a, k)
	}
	sort.Sort(sort.IntSlice(a))
	for _, k := range a {
		for _, s := range n[k] {
			fmt.Printf("%d - %s\n", k, s)
		}
	}
}
func AnonymizeIp(ip string) string {
	return ip[:strings.LastIndex(ip, ".")+1] + "0"
}
func ConvertMapToLogLine(parsedLine map[string]string) string {
	remote_addr := parsedLine["remote_addr"]
	time_local := parsedLine["time_local"]
	request := parsedLine["request"]
	status := parsedLine["status"]
	body_bytes_sent := parsedLine["body_bytes_sent"]
	http_referer := parsedLine["http_referer"]
	http_user_agent := parsedLine["http_user_agent"]
	return fmt.Sprintf(`%s - - [%s] "%s" %s %s "%s" "%s"`, remote_addr,
		time_local, request, status, body_bytes_sent, http_referer,
		http_user_agent)
}
func main() {
	scanner := bufio.NewScanner(os.Stdin)
	for scanner.Scan() {
		parsedLine := ConvertLogLineToMap(scanner.Text())
		parsedLine["remote_addr"] = AnonymizeIp(parsedLine["remote_addr"])
		fmt.Println(ConvertMapToLogLine(parsedLine))
	}
	if err := scanner.Err(); err != nil {
		fmt.Fprintln(os.Stderr, "error:", err)
		os.Exit(1)
	}
}
comments powered by Disqus