Сегодняшний день начался с неожиданного. Один из наших Заказчиков сообщил, что он считает, что RADIUS сервер не справляется с работой, поскольку NAS отсылает большое количество запросов повторно. Так как это достаточно серьезное обвинение, его следовало немедленно проверить. Описанию того как это сделать, посвящена эта статья (материал ориентирован на начинающих разработчиков и системных администраторов).
Первый шаг довольно очевиден. Необходимо получить дамп сетевой активности во время максимальной нагрузки на RADIUS-сервер. Данных 10-15 минутного интервала вполне достаточно для анализа. Для Unix-like систем получить эти данные можно при помощи tcpdump, но поскольку, в нашем случае, RADIUS-сервер работал на Windows-системе, пришлось прибегнуть к помощи Wireshark. Выполнив захват пакетов, Wireshark показал эту замечательную картинку:
Хотя этот интерфейс очень удобен для интерактивной работы, для получения статистики, требуется перевести данные в форму более удобную для автоматизированной обработки. К счастью, Wireshark умеет сохранять данные в текстовый формат:
Результирующий файл выглядит следующим образом:
+---------+---------------+----------+
10:03:59,092,544 ETHER
|0 |ff|ff|ff|ff|ff|ff|00|0c|29|6b|5a|a3|08|00|45|00|00|e5|b6|15|00|00|80|11|04|d4|c0|a8|7d|ce|c0|a8|7f|ff|00|8a|00|8a|00|d1|ee|a9|11|0e|d1|fb|c0|a8|7d|ce|00|8a|00|bb|00|00|20|46|44|46|41|44|44|43|41|43|41|43|41|43|41|43|41|43|41|43|41|43|41|43|41|43|41|43|41|43|41|43|41|00|20|45|4a|45|4f|46|45|45|46|46|43|43|41|43|41|43|41|43|41|43|41|43|41|43|41|43|41|43|41|43|41|42|4e|00|ff|53|4d|42|25|00|00|00|00|00|00|00|00|00|00|00|00|00|00|00|00|00|00|00|00|00|00|00|00|00|00|00|11|00|00|21|00|00|00|00|00|00|00|00|00|e8|03|00|00|00|00|00|00|00|00|21|00|56|00|03|00|01|00|00|00|02|00|32|00|5c|4d|41|49|4c|53|4c|4f|54|5c|42|52|4f|57|53|45|00|01|00|80|fc|0a|00|53|50|33|00|25|03|00|00|00|00|fc|5e|20|03|02|00|05|01|03|12|01|00|0f|01|55|aa|00|
+---------+---------------+----------+
10:03:59,184,049 ETHER
|0 |ff|ff|ff|ff|ff|ff|00|1d|7d|3a|f9|3a|08|06|00|01|08|00|06|04|00|01|00|1d|7d|3a|f9|3a|0a|15|52|44|00|00|00|00|00|00|0a|15|52|41|00|00|00|00|00|00|00|00|00|00|00|00|00|00|00|00|00|00|
...
С этим уже можно работать. Из спецификаций RFC 768, 2865, 2866 нам известны смещения интересующих нас полей (смещения представлены в десятеричной системе счисления, значения — в шестнадцатеричной):
+23 = 11 (UDP)
+36 = 07 14 (RADIUS Destination Port = 1812)
+42 - (01 = Access Request)
+43 - ID
+34 = 07 14 (RADIUS Source Port = 1812)
+42 - (02 = Access Accept; 03 = Access Reject)
+43 - ID
+36 = 07 15 (RADIUS Destination Port = 1813)
+42 - (04 = Accounting Request)
+43 - ID
+34 = 07 14 (RADIUS Source Port = 1812)
+42 - (05 = Accounting Response)
+43 - ID
Обработать данные нам поможет Perl:
use Time::Local;
my $tm;
my $ln;
my %auth;
my %acco;
my %discarded;
my %accepted;
# Обрабатываем все поступающие строки
while (<>) {
# Убираем перевод строки
chomp;
s/|0s+|//;
# Регулярным выражением извлекаем время
if (/^(dd):(dd):(dd),(ddd),ddd/) {
# Приводим значение времени к количеству миллисекунд с начала эпохи
# Поскольку дата нас не интересует, берем 01/01/1970
$tm = timelocal($3, $2, $1, 01, 01, 1970) * 1000 + $4;
}
if (/|/) {
$ln .= $_;
} else {
if ($ln) {
# Разбиваем строку на байты
my @packet = split /|/, $ln;
# Нас интересуют только UDP-пакеты
if ($packet[23] eq '11') {
my $code = $packet[42];
my $id = $packet[43];
# RADIUS Request
if ($packet[36] eq '07' and
($packet[37] eq '14' or $packet[37] eq '15')) {
# Аккаутинг
if ($code eq '04') {
# Повтор ID запроса означает потерю соответствующего ответа
if (exists($acco{%id})) {
$discarded{$code}++;
}
# Сохраняем время получения запроса
$acco{%id} = $tm;
# Авторизация
} else {
if (exists($auth{%id})) {
$discarded{$code}++;
}
$auth{%id} = $tm;
}
}
# RADIUS Response
if ($packet[34] eq '07' and
($packet[35] eq '14' or $packet[35] eq '15')) {
# Аккаутинг
if ($code eq '05') {
if (exists($acco{%id})) {
if ($tm - $acco{%id} > 1000) {
# Если прошло более 1 секунды, считаем пакет отброшенным
$discarded{$code}++;
} else {
# Иначе увеличиваем количество успешно обработанных пакетов
$accepted{$code}++;
}
delete($acco{%id});
}
# Авторизация
} else {
if (exists($auth{%id})) {
if ($tm - $auth{%id} > 1000) {
$discarded{$code}++;
} else {
$accepted{$code}++;
}
delete($auth{%id});
}
}
}
}
$ln = '';
}
}
}
# На всякий случай, учитываем ID, для которых не сформирован ответ
while (($id, $tm) = each(%auth)) {
$discarded{'01'}++;
}
while (($id, $tm) = each(%acco)) {
$discarded{'04'}++;
}
#Выводим результаты обработки
print "Auth Accepted: $accepted{'02'}n";
print "Auth Rejected: $accepted{'03'}n";
print "Acco Responsed: $accepted{'05'}nn";
print "Auth Request Discarded: $discarded{'01'}n";
print "Auth Accept Discarded: $discarded{'02'}n";
print "Auth Reject Discarded: $discarded{'03'}n";
print "Acco Request Discarded: $discarded{'04'}n";
print "Acco Response Discarded: $discarded{'05'}n";
Поскольку мы все еще работаем в Windows, bang-комментарий в исходном коде не обязателен (кстати, Perl для Windows можно взять здесь). Для работы со временем, не забываем подключить Time::Local. Скрипт запускаем на выполнение следующей командой:
perl stat.pl dump.txt > dump
Скрипт работает довольно долго (в основном из-за split-а большого объема данных), но один раз можно и потерпеть. В конечном итоге, формируется следующий результат:
Auth Accepted: 195
Auth Rejected: 907
Acco Responsed: 6058
Auth Request Discarded: 13
Auth Accept Discarded:
Auth Reject Discarded:
Acco Request Discarded: 1476
Acco Response Discarded:
Здесь мы видим, что за 10 минут было успешно обработано 6058 пакетов аккаунтинга и 1102 пакетов авторизации (из них на 907 запросов был сформирован Reject). Все запросы были обработаны сервером не более чем за 1 секунду. По непонятной причине, NAS отослал 13 повторных запросов авторизации и 1476 запросов аккаунтинга. Возможно это связано с потерями UDP-пакетов при передаче их по сети.
Приведенный выше скрипт можно улучшить, для получения более детальной статистики по времени отклика, но в целом задачу можно считать выполненной. RADIUS-сервер работает нормально.
Автор: GlukKazan
