В продовження теми логів AWS Load Balancer: в попередньому пості Golang: запис логів AWS Loab Balancer до VictoriaLogs зробили збір логів з власним logs collector на Golang, тепер треба з цих логів отримати щось корисне.
Раніше, коли у нас на проекті була Loki, ми з її RecordingRules створювали метрики, з яких потім малювали дашборди в Grafana і мали алерти з Alertmanager.
Тепер треба це перенести до VictoriaMetrics, у якої є власні RecordingRules, з якими VMAlert може виконувати запити до VictoriaLogs.
Колись про це писав у VictoriaLogs: створення Recording Rules з VMAlert, але там більше просто ознайомлення і налаштування – а сьогодні будемо робити конкретну задачу.
Що хочеться бачити в метриках з логів:
- помилки 4хх
- помилки 5хх
- загальна кількість реквестів на ALB
- час відповіді загальна
- час target response time на конкретних ендпоінтах нашого Backend API
Зміст
VictoriaLogs LogsQL ALB logs parsing
ALB access logs має чітко визначений формат полів (який, правда, іноді змінюється), див. документацію Access log entries.
Знаючи ці поля – з LogsQL pipes можемо їх розпарсити і створити потрібні fields, які потім будемо використовувати для обчислень.
extract pipe
Перший pipe, який використаємо – extract, з яким читаємо дані з логу і створюємо поля.
Всі поля нам не потрібні, деякі поля створюються ще на етапі збору логів в Go (описаний у Створення Log parser), тому задаємо <_> на ті поля, які хочемо скіпнути, і тепер маємо таку конструкцію:
{stream="alb"}
| extract "<_> <_> <elb_id> <_> <_> <request_processing_time> <target_processing_time> <response_processing_time> <elb_status_code> <target_status_code> <received_bytes> <sent_bytes> <request_line> <user_agent> <_> <_> <_> <trace_id> <domain_name> <_> <_> <_> <_> <_> <error_reason> <_> <_> <_> <_> <conn_trace_id> <_> <_> <_>"
На початку використовуємо Stream filter, який задається в нашому колекторі логів, а далі описуємо сам патерн полів.
Якщо поля в кінці точно ніколи не будуть потрібні – їх можна прибрати із запиту взагалі, тобто зробити просто так:
{stream="alb"}
| extract "<_> <_> <elb_id> <_> <_> <request_processing_time> <target_processing_time> <response_processing_time> <elb_status_code> <target_status_code> <received_bytes> <sent_bytes> <request_line> <user_agent> <_> <_> <_> <trace_id> <domain_name> <_> <_> <_> <_> <_> <error_reason> <_> <_> <_> <_> <conn_trace_id>"
extract_regexp pipe
Нам потрібно буде робити час відповіді і помилки по конкретним ендпоінтам нашого Backend API, і нам вистачить першої частини URI.
Тобто зі строки “https://staging.api.challenge.example.co:443/roadmap/media/123 HTTP/2.0” треба отримати тільки “/roadmap”.
Сам запит йде в полі request_line:
Тут можемо використати extract_regexp pipe з яким отримуємо першу частину після “/” і зберігаємо результат в regex named capture group з ім’ям uri_path:
{stream="alb"}
| extract "<_> <_> <elb_id> <_> <_> <request_processing_time> <target_processing_time> <response_processing_time> <elb_status_code> <target_status_code> <received_bytes> <sent_bytes> <request_line> <user_agent> <_> <_> <_> <trace_id> <domain_name> <_> <_> <_> <_> <_> <error_reason> <_> <_> <_> <_> <conn_trace_id>"
| extract_regexp `.*:443(?P<uri_path>/[^/?]+).* HTTP` from request_line
Для extract_regexp задаємо поле, яке він буде парсити – from request_line, аби не парсити весь зміст _msg.
Отримуємо такий результат:
filter pipe
Якщо хочемо відфільтрувати дані – використовуємо filter, в який можемо передати регулярку.
Наприклад, аби вибрати тільки деякі домени – робимо filter domain_name :~ "regex". Або без регулярки – з := "example.com", що буде швидше.
Але filter ставимо його перед extract_regexp – аби відсіяти зайве і не виконувати дорогі в плані ресурсів пошуки extract_regexp по зайвим строкам:
{stream="alb"}
| extract "<_> <_> <elb_id> <_> <_> <request_processing_time> <target_processing_time> <response_processing_time> <elb_status_code> <target_status_code> <received_bytes> <sent_bytes> <request_line> <user_agent> <_> <_> <_> <trace_id> <domain_name> <_> <_> <_> <_> <_> <error_reason> <_> <_> <_> <_> <conn_trace_id>"
| filter domain_name :~ ".+challenge.example.co|lightdash.example.co"
| extract_regexp `.*:443(?P<uri_path>/[^/?]+).* HTTP` from request_line
Або можемо прибрати якісь результати, наприклад видалити всі домени, в яких є тире – робимо filter domain_name :!~ "-":
{stream="alb"}
| extract "<_> ... "
| filter domain_name :!~ "-"
| extract_regexp `.*:443(?P<uri_path>/[^/?]+).* HTTP` from request_line
stats pipe та stats pipe functions
І останній крок – отримати безпосередньо результати, які потім будемо використовувати в метриках.
Для цього у нас є stats pipe і її функції, див. всі в документації stats pipe functions.
Наприклад, avg():
{stream="alb"}
| extract "<_> <_> <elb_id> <_> <_> <request_processing_time> <target_processing_time> <response_processing_time> <elb_status_code> <target_status_code> <received_bytes> <sent_bytes> <request_line> <user_agent> <_> <_> <_> <trace_id> <domain_name> <_> <_> <_> <_> <_> <error_reason> <_> <_> <_> <_> <conn_trace_id>"
| filter domain_name :!~ "^-$"
| extract_regexp `.*:443(?P<uri_path>/[^/?]+).* HTTP` from request_line
|stats by (domain_name) avg()
Результат:
Але зараз avg() рахує значення зі всіх numeric log fields:
avg returns the average value over the given numeric log fields .
Тому користі з цього нуль.
Натомість можемо вказати яке саме поле використовувати, вказуємо його аргументом до avg() – avg(target_processing_time):
{stream="alb"}
...
|stats by (domain_name) avg(target_processing_time) as avg_target_processing_time
Результат:
math pipe
Ще хочеться бачити загальний час виконання запитів, але в полях ALB у нас три окремі значення – request_processing_time, target_processing_time та response_processing_time.
Робити три окремі метрики, а потім рахувати в Grafana не хочеться, тому можемо зробити простіше – використати LogsQL math(): спочатку рахуємо суму по всім трьом полям, а потім отриманий результат передаємо до avg():
{stream="alb"}
...
| math (request_processing_time + target_processing_time + response_processing_time) as total_processing_time
|stats by (domain_name) avg(total_processing_time) as avg_total_processing_time
Результат:
Хоча насправді сенсу особо нема, бо в 99.9% випадків 99.9% часу все одно займає target_processing_time.
AWS Athena та AWS ALB logs
“Довіряй – але перевіряй”.
Тому зробимо табличку в AWS Athena, і потім з неї будемо робити запити для перевірки.
Документація – Query Application Load Balancer logs.
Виконуємо запит:
CREATE EXTERNAL TABLE IF NOT EXISTS alb_access_logs (
type string,
time string,
elb string,
client_ip string,
client_port int,
target_ip string,
target_port int,
request_processing_time double,
target_processing_time double,
response_processing_time double,
elb_status_code int,
target_status_code string,
received_bytes bigint,
sent_bytes bigint,
request_verb string,
request_url string,
request_proto string,
user_agent string,
ssl_cipher string,
ssl_protocol string,
target_group_arn string,
trace_id string,
domain_name string,
chosen_cert_arn string,
matched_rule_priority string,
request_creation_time string,
actions_executed string,
redirect_url string,
lambda_error_reason string,
target_port_list string,
target_status_code_list string,
classification string,
classification_reason string,
conn_trace_id string
)
ROW FORMAT SERDE 'org.apache.hadoop.hive.serde2.RegexSerDe'
WITH SERDEPROPERTIES (
'serialization.format' = '1',
'input.regex' =
'([^ ]*) ([^ ]*) ([^ ]*) ([^ ]*):([0-9]*) ([^ ]*)[:-]([0-9]*) ([-.0-9]*) ([-.0-9]*) ([-.0-9]*) (|[-0-9]*) (-|[-0-9]*) ([-0-9]*) ([-0-9]*) \"([^ ]*) (.*) (- |[^ ]*)\" \"([^\"]*)\" ([A-Z0-9-_]+) ([A-Za-z0-9.-]*) ([^ ]*) \"([^\"]*)\" \"([^\"]*)\" \"([^\"]*)\" ([-.0-9]*) ([^ ]*) \"([^\"]*)\" \"([^\"]*)\" \"([^ ]*)\" \"([^\\s]+?)\" \"([^\\s]+)\" \"([^ ]*)\" \"([^ ]*)\" ?([^ ]*)? ?( .*)?'
)
LOCATION 's3://ops-1-33-devops-ingress-ops-alb-loki-logs/AWSLogs/492***148/elasticloadbalancing/us-east-1/';
Тепер маємо таблицю, яка дозволяє виконувати SQL-запити до логів, що зберігаються в S3:
Перевіряємо поля:
SELECT elb_status_code, count(*)
FROM alb_access_logs
WHERE date(from_iso8601_timestamp(time)) = date('2025-12-04')
GROUP BY elb_status_code
ORDER BY elb_status_code;
Результат:
Ну і для додатково користуємось метриками з CloudWatch.
Recording Rules з VictoriaLogs
Розібрались з тим, як нам отримати поля, сформували поля – можна переходити до Recording Rules та метрик.
Документація – Recording rules.
AWS ALB logs 5-minute delay issue
Але перед тим, як почати писати rules – є момент, який треба уточнити:
- у нас логи з S3 збираються раз на 5 хвилин (“ELB publishes a log file for each load balancer node every 5 minutes” – документація Access log files)
- дефолтний Recording Rules evaluation time – 1 хвилина (див. Configuration)
- і якщо момент виконання rule не співпаде з моментом запуску log parser і у VictoriaLogs логів на цей момент не буде – то і наш rule не спрацює, і нічого не створить
Але для таких випадків ми в налаштуваннях Rules group можемо використати eval_delay, наприклад:
apiVersion: operator.victoriametrics.com/v1beta1
kind: VMRule
metadata:
name: vmlogs-alert-rules
spec:
groups:
- name: VM-ALB-logs-Test
type: vlogs
eval_delay: 15m
...
Тоді задача, яка мала запуститись у, наприклад, 12:00:00 – буде запущена в 12:15:00, але вона буде шукати логи в проміжок часу 12:00:00 – 12:01:00.
Ну а в логах, в нашому конкретному випадку, timestamp парситься з самих логів, тому в VictoriaLogs час буде такий, як було збережено самим лоад-балансером.
Планування Recording Rules
Повернемось до початку – що хочеться бачити:
- помилки 4хх – ALB та target
- помилки 5хх – ALB та target
- загальна кількість реквестів на ALB та по конкретних ендпоінтах нашого Backend API
- час відповіді загальна
- час target response time на конкретних ендпоінтах
Тобто задача, фактично, зводиться к трьом показникам – кількість помилок, кількість реквестів, час відповіді.
Як ми це можемо зробити з Recording Rules і метриками:
- 4хх і 5хх помилки по полям
elb_status_code:- з фільтром
filter elb_status_code :~ "40[1-4]|50[0-4]"отримуємо всі логи, в яких єelb_status_codeз 4хх або 5хх - потім зі
statsіrate()рахуємо кількість знайдених log records, в яких були 4хх або 5хх помилки - потім в дашбордах і алертах робимо фільтри по 4хх або 5хх (хоча можна і окремі метрики робити)
- з фільтром
target_status_code– аналогічно- загальна кількість реквестів на секунду по домену:
- кожен запис в логах == окремий HTTP query
- тому можемо просто робити
stats by (elb_id, domain_name) rate()– групуємо поelb_id,domain_name, аби потім мати фільтри в Grafana і алертах
- загальна кількість реквестів на ендпоінт
- аналогічно, тільки додаємо
uri_path–stats by (elb_id, domain_name, uri_path) rate() - в
uri_pathу нас тільки перша частина запиту, їх не так багато різних, тому проблеми з high cardinality у VictoriaLogs не буде
- аналогічно, тільки додаємо
- ALB total response time і на конкретних ендпоінтах – тут є варіанти 🙂 див далі
Пам’ятаємо про high cardinality і в VictoriaMetrics: все, що ми використаємо у stats by () потім буде збережено в labels метрик, а тому робити групування по всяким всякі trace_id не варто – при потребі це можна буде перевіряти в самих логах, а в алертах і Grafana воно нам не треба.
Див. також VictoriaMetrics: Churn Rate, High cardinality, метрики та IndexDB.
Поїхали.
ALB Requests Rate rule
Почнемо з самої простої – просто рахуємо скільки записів було отримано за останній evalution interval, тобто 1 хвилину, потім з rate() отримуємо кількість змін на секунду:
apiVersion: operator.victoriametrics.com/v1beta1
kind: VMRule
metadata:
name: vmlogs-alert-rules
spec:
groups:
- name: VM-ALB-logs
type: vlogs
eval_delay: 15m
interval: 1m
- record: vmlogs:alb:stats:elb_requests_total:rate
debug: true
expr: |
{stream="alb"}
| extract "<_> <_> <elb_id> <_> <_> <request_processing_time> <target_processing_time> <response_processing_time> <elb_status_code> <target_status_code> <received_bytes> <sent_bytes> <request_line> <user_agent> <_> <_> <_> <trace_id> <domain_name> <_> <_> <_> <_> <_> <error_reason> <_> <_> <_> <_> <conn_trace_id> <_> <_> <_>"
| stats by (elb_id, domain_name) rate() as elb_requests_rate
Деплоїмо, чекаємо 5-10 хвилин, перевіряємо в VictoriaMetrics:
О 10:13 маємо значення 4.83.
Перевіряємо в CloudWatch, де з math просто робимо “sum requests in 1 minute /60”:
Ті ж 4.83, правда о 10:12.
Можемо ще перевірити з Athena, яку підготували раніше, і з таким запитом:
SELECT
date_trunc('minute', from_iso8601_timestamp(time)) AS minute,
count(*) / 60.0 AS rps_estimated
FROM alb_access_logs
WHERE from_iso8601_timestamp(time) >= now() - interval '1' hour
GROUP BY 1
ORDER BY 1 DESC;
Ті ж цифри, тільки теж о 10:12:
ALB 4xx/5xx Errors rule
Далі робимо per second rate помилок – та ж сама логіка, тільки додаємо filter elb_status_code :~ "40[1-4]":
- record: vmlogs:alb:stats:elb_errors:4xx:rate
debug: false
expr: |
{stream="alb"}
| extract "<_> <_> <elb_id> <_> <_> <request_processing_time> <target_processing_time> <response_processing_time> <elb_status_code> <target_status_code> <received_bytes> <sent_bytes> <request_line> <user_agent> <_> <_> <_> <trace_id> <domain_name> <_> <_> <_> <_> <_> <error_reason> <_> <_> <_> <_> <conn_trace_id> <_> <_> <_>"
| filter elb_status_code :~ "40[1-4]"
| extract_regexp `.*:443(?P<uri_path>/[^/?]+).* HTTP` from request_line
| stats by (elb_id, elb_status_code, domain_name, uri_path) rate() as elb_4xx_errors_rate
Деплоїмо, чекаємо, перевіряємо у VictoriaMetrics:
Маємо значення 0.91 об 11:07.
В CloudWtach – те саме, тільки знов на 1 хвилину раніше:
ALB Target Processing Time rule
Наступним хочеться отримати те, що в CloudWatch у нас приходить в метриці TargetResponseTime, але мати можливість отримати і загальний час по всьому LoadBalancer – і по окремим URI.
Проблема зі stats by () і avg()
Перше рішення, яке прийшло в голову – це просто взяти середнє по кожному ендпоінту, потім взяти середнє по всім отриманням значенням – і має бути +/- те самий результат, що в CloudWatch Target Response Time з Average.
Але якщо зробити метрику так:
- record: vmlogs:alb:stats:elb_target_processing_time:avg
debug: false
expr: |
{stream="alb"}
...
| stats by (elb_id, domain_name, uri_path) avg(target_processing_time) as avg_target_processing_time
І потім для отримання загального середнього значення у VictoriaMetrics виконувати avg():
avg(vmlogs:alb:stats:elb_target_processing_time:avg)
То дані в VictoriaMetrics і CloudWatch будуть різні.
Наприклад, в 12:52 у VictoriaMetrics маємо значення 0.06:
Але в CloudWatch – Target Response Time і Average за 1 хвилину у 12:21 буде 0.11:
Або 0.15 в 12:52:
Зовсім не схоже на те, що бачимо у VictoriaMetrics.
Окей – тоді, може, просто взяти суму від всіх наших avg(by uri_path)?
sum(vmlogs:alb:stats:elb_target_processing_time:avg)
Але тоді о 12:52 результат буде взагалі 1.23:
Чому так виходить?
Бо у нас в stats() результати рахуються для кожної групи (elb_id, domain_name, uri_path).
Тобто, якщо взяти такі приклади і використати тільки uri_path:
/uri-1: 200 requests по 0.1 секунді:- sum: 200*0.1 == 20 sec
- avg: 200*0.1/200 == 0.1 sec
/uri-2: 10 requests по 2 секунди:- sum: 10*2 == 20 sec
- avg: 10*2/10 == 2 sec
Якщо ми будемо рахувати результат як avg(vmlogs:alb:stats:elb_target_processing_time:avg) – то для отримання avg() ми візьмемо значення з кожної метрики:
vmlogs:alb:stats:elb_target_processing_time:avg{uri_path="/uri-1"}== 0.1 secvmlogs:alb:stats:elb_target_processing_time:avg{uri_path="/uri-2"}== 2 sec
І поділимо на кількість отриманих метрик, тобто на 2, що дасть нам:
- (0.1 sec + 2 sec) / 2 == 1.05 sec
Якщо ж ми будемо рахувати як sum(vmlogs:alb:stats:elb_target_processing_time:avg) – то для тої ж пари:
vmlogs:alb:stats:elb_target_processing_time:avg{uri_path="/uri-1"}== 0.1 secvmlogs:alb:stats:elb_target_processing_time:avg{uri_path="/uri-2"}== 2 sec
Ми отримаємо:
- (0.1 sec + 2 sec) = 2.1 sec
Average values in CloudWatch
А як CloudWatch обчислює Average взагалі, і по TargetResponseTime?
Він бере кількість отриманих метрик, Sample count – о 12:52 це було 143:
Потім бере суму по всім отриманим метрикам, Sum – в 12:52 це було 22:
І ділить суму на кількість – 22/143 == 0.1538:
Або якщо повернутись до нашого прикладу вище – то це сума часу по обом ендпоінтам поділена на загальну кількість запитів: (/uri-1 sum + /uri-2 sum) / (/uri-1 requests + /uri-1 requests):
- (20+20)/210 == 0.19
Тобто реальний середній час відповіді нашого умовного ALB – 0.19 секунди, а не 1.05 у випадку з avg() або тим більш не 2.1 sec у випадку з sum().
Отже, якщо ми хочемо мати і загальний середній час по всьому ALB, і середній час по кожному ендпоінту – то у нас два варіанти:
- або в
stats()треба брати суму, а неavg(), а потім отриманий результат ділити на загальну кількість запитів - або мати окрему метрику на загальний середній час – і окрему на середній час по кожному ендпоінту
При першому варіанті – це може виглядати так:
- record: vmlogs:alb:stats:elb_target_processing_time:sum
debug: false
expr: |
{stream="alb"}
| extract "<_> <_> <elb_id> <_> <_> <request_processing_time> <target_processing_time> <response_processing_time> <elb_status_code> <target_status_code> <received_bytes> <sent_bytes> <request_line> <user_agent> <_> <_> <_> <trace_id> <domain_name> <_> <_> <_> <_> <_> <error_reason> <_> <_> <_> <_> <conn_trace_id> <_> <_> <_>"
| extract_regexp `.*:443(?P<uri_path>/[^/?]+).* HTTP` from request_line
| filter target_processing_time :! "-1"
| stats by (elb_id, domain_name, uri_path) sum(target_processing_time) as sum_target_processing_time
- record: vmlogs:alb:stats:elb_target_processing_time:count
debug: false
expr: |
{stream="alb"}
| extract "<_> <_> <elb_id> <_> <_> <request_processing_time> <target_processing_time> <response_processing_time> <elb_status_code> <target_status_code> <received_bytes> <sent_bytes> <request_line> <user_agent> <_> <_> <_> <trace_id> <domain_name> <_> <_> <_> <_> <_> <error_reason> <_> <_> <_> <_> <conn_trace_id> <_> <_> <_>"
| extract_regexp `.*:443(?P<uri_path>/[^/?]+).* HTTP` from request_line
| filter target_processing_time :! "-1"
| stats by (elb_id, domain_name, uri_path) count() as count_requests
Замість vmlogs:alb:stats:elb_target_processing_time:count можна було б взяти vmlogs:alb:stats:elb_requests_total:count, яку ми робили вище – але в метриках target_processing_time ми прибираємо значення “-1”, яке буває в target_processing_time якщо підключення розірване чи завершилось помилкою, а в vmlogs:alb:stats:elb_requests_total:count у нас всі реквести без виключення.
І з цими двома метриками ми можемо отримати середнє значення часу відповіді по кожному ендпоінту так:
sum( sum(vmlogs:alb:stats:elb_target_processing_time:sum) by (uri_path) / sum(vmlogs:alb:stats:elb_target_processing_time:count) by (uri_path) ) by (uri_path)
Тут у нас в 12:47 ендпоінт /chats відповідав 0.54 секунди.
І те саме значення буде в самому першому варіанті:
- record: vmlogs:alb:stats:elb_target_processing_time:avg
debug: false
expr: |
{stream="alb"}
| extract "<_> <_> <elb_id> <_> <_> <request_processing_time> <target_processing_time> <response_processing_time> <elb_status_code> <target_status_code> <received_bytes> <sent_bytes> <request_line> <user_agent> <_> <_> <_> <trace_id> <domain_name> <_> <_> <_> <_> <_> <error_reason> <_> <_> <_> <_> <conn_trace_id> <_> <_> <_>"
| extract_regexp `.*:443(?P<uri_path>/[^/?]+).* HTTP` from request_line
| filter target_processing_time :! "-1"
| stats by (elb_id, domain_name, uri_path) avg(target_processing_time) as avg_target_processing_time
Маємо о 12:47 ті самі 0.54 на /chats:
А аби отримати середній загальний час відповіді по всьому лоад-балансеру – можемо або використати метрики vmlogs:alb:stats:elb_target_processing_time:sum і vmlogs:alb:stats:elb_target_processing_time:count так:
sum( sum(vmlogs:alb:stats:elb_target_processing_time:sum) / sum(vmlogs:alb:stats:elb_target_processing_time:count) )
Отримаємо 0.22 у 12:58:
Або просто зробити окрему метрику зі stats by (elb_id) avg():
- record: vmlogs:alb:stats:elb_target_processing_time_total:avg
debug: false
expr: |
{stream="alb"}
| extract "<_> <_> <elb_id> <_> <_> <request_processing_time> <target_processing_time> <response_processing_time> <elb_status_code> <target_status_code> <received_bytes> <sent_bytes> <request_line> <user_agent> <_> <_> <_> <trace_id> <domain_name> <_> <_> <_> <_> <_> <error_reason> <_> <_> <_> <_> <conn_trace_id> <_> <_> <_>"
| extract_regexp `.*:443(?P<uri_path>/[^/?]+).* HTTP` from request_line
| filter target_processing_time :! "-1"
| stats by (elb_id) avg(target_processing_time) as avg_target_processing_time
Яка поверне ті самі 0.22 в 12:58:
І те саме значення буде в CloudWatch:
Власне, на цьому і все.
Тепер можна додавати інші метрики, алерти, і тюнити Grafana dashboard.























