BiTel

Столкнулись с новым сюрпризом, который никак не получается отловить.
Радиус просто не ведет некоторые сессии. Т.е соединение есть, интернет есть, а обсчет услуги не ведется абсолютно. Нередко даже в логах радиуса ничего не отображается. Лечится или перезагрузкой радиуса, или рестартом pppoe-сервера на оборудовании.
Такое встретилось как на рапире, так и на микротике. Буквально на этой неделе началось.
По миру ж пойдем, если все клиенты начнут так "баловаться". 8((

В чем может быть проблема? Какие настройки показать? На что обратить внимание? Я теряюсь в догадках.

Обратите внимание приходит ли START пакет по этим сессиям, потом сделайте radius_ps.sh - есть ли в списке коннектов потерянные сессии? Какой у них статус?

А можно прокомментировать вот такое (взято из list)
|r15.nas.ip| x.x.x.x | UNDEF | |user-login | x.x.x.x | mac-addr | 054 - 06 | wait
|
|r15.nas.ip| x.x.x.x | 386D444404D3 |01.11.2007 11:06:04 |user-login | x.x.x.x | mac-addr | 054 - 06 | sleep
|
|r15.nas.ip| x.x.x.x | 386D4E1D033B |01.11.2007 13:38:19 |oxranagel | x.x.x.x | mac-addr | 054 - 06 | active

эта сессия авторизована, но старт пакет не пришел, следовательно она не считается, просто висит в памяти.
P.S. Планируем сделать чтобы запускались по UPDATE пакету такие сессии тоже.


авторизована, старт пришел но проверка по SNMP либо по Update пакетам не прошла, обсчет не идет.

нормальная сессия, считается.

Отследил проблему.
В radius.log
INFO 01.11.2007 18:01:12,271 ACCOUNT:
Type=ACCOUNTING_REQUEST
Attributes:
User-Name=popa-net
NAS-Identifier=NAS.IP
NAS-IP-Address=x.x.x.x
NAS-Port=7
Service-Type=2
Framed-Protocol=1
Framed-IP-Address=ip-pool-addr
Acct-Input-Octets=86580828
Acct-Output-Octets=197422749
Acct-Status-Type=3
Acct-Delay-Time=0
Acct-Session-Time=273863
Acct-Input-Packets=301179
Acct-Session-Id=81b00000
Acct-Authentic=1
NAS-Port-Id=ether1
Acct-Output-Packets=364830
Acct-Output-Gigawords=0
Acct-Input-Gigawords=0
NAS-Port-Type=15
Calling-Station-Id=mac-addr
Called-Station-Id=service1

INFO 01.11.2007 18:01:12,273 RESPONSE:
Type=ACCOUNTING_RESPONSE
Attributes:

Запустил ./radius_ps.sh, в файле list пользователь отсутствует. Зашел на маршрутизатор - висит, голубчик, активность хорошая.

Прибил пппое-интерфейс. После поднятия соединения радиус нормально отреагировал и в логе появилось следующее:

INFO 01.11.2007 18:37:04,845 AUTH:
Type=AUTHENTICATION_REQUEST
Attributes:
User-Name=popa-net
NAS-Identifier=NAS.IP
NAS-Port-Id=ether1
CHAP-Password=
XXXX
NAS-IP-Address=x.x.x.x
NAS-Port=30
Service-Type=2
Framed-Protocol=1
Calling-Station-Id=mac-addr
NAS-Port-Type=15
CHAP-Challenge=XXX
Called-Station-Id=service1

INFO 01.11.2007 18:37:05,009 RESPONSE:
Type=AUTHENTICATION_ACCEPT
Process time:164
Attributes:
Acct-Interim-Interval=120
Service-Type=2
Framed-Protocol=1
Framed-IP-Address=x.x.x.x
Framed-Pool=pool1

INFO 01.11.2007 18:37:05,029 ACCOUNT:
Type=ACCOUNTING_REQUEST
Attributes:
User-Name=popa-net
NAS-Identifier=NAS.IP
NAS-IP-Address=x.x.x.x
NAS-Port=30
Service-Type=2
Framed-Protocol=1
Framed-IP-Address=x.x.x.x
Acct-Status-Type=1
Acct-Delay-Time=0
Acct-Session-Id=81b00017
Acct-Authentic=1
NAS-Port-Id=ether1
NAS-Port-Type=15
Calling-Station-Id=mac-addr
Called-Station-Id=service1

INFO 01.11.2007 18:37:05,030 RESPONSE:
Type=ACCOUNTING_RESPONSE
Attributes:

Похоже старт пакет не всегда приходит. На днях выложим апдейт чтобы поднимал сессию по Update пакету тоже.. Если не было старта.

После обновления на v4.3 проблема решилась, боюсь, только частично.
Половина сессий поднялась нормально, половина - нет. С маршрутизаторов на РоутерОС и СтарОС. (микротик, рапира). Т.е сессии поднимаются 50\50.

s: на неподхваченной сессии наработка составляет:
Acct-Input-Octets=79929616
Acct-Output-Octets=588851368
Это пролетело мимо, получается?

По выходным, когда наблюдается пиковая активность пользователей, появляются сессии со статусом sleep, и соответственно подсчёт траффика не ведётчся, информация о траффике приходит по netflow, bgradius workmode=2. Промежуточный RADIUS ACCT UPDATE на VPN отключен.
./radius_ps.sh && cat list | grep active | wc -l
218
./radius_ps.sh && cat list | grep sleep | wc -l
251
./radius_ps.sh && cat list | grep wait | wc -l
0
========
23 18:36:03
Type=ACCOUNTING_REQUEST
Attributes:
User-Name=xxxxx
NAS-IP-Address=172.17.1.3
NAS-Port=265
Service-Type=2
Framed-Protocol=1
Framed-IP-Address=10.0.51.173
Acct-Status-Type=1
Acct-Delay-Time=0
NAS-Port-Type=0
Calling-Station-Id=172.17.37.187
Acct-Session-Id=476E806340B300
Acct-Authentic=1
====================
Acct-Session-Id=476E806340B300
От сюда видно что PID PPPD = 16563
Далее на сервере где крутится BGRadiusDialup делаю:
tcpdump -nnvv -i eth1 host 172.17.1.3 and udp port 161| grep '255.16563'
а в ответ тишина.

От сюда вопрос, почему BGRadius не проверяет сессию по SNMP???

модуль dialup вер. 4.3 сборка 19
сервер BGRadiusDialup вер. 4.3 сборка 33
PS: У вас в документации указанно:
#возможные значения 2.4.2 и 2.4.3, для 2.4.4 указывается версия 2.4.2
У меня pppd version 2.4.4 и работает только с указанием в конфиге наса pppd.version=2.4.3

Вот дебаг SNMP проверяльщика по одной из сессий:
tail -n 0 -F connection.log|grep -P 'argus;.*SNMP check'
DEBUG 23.12.2007 22:29:53 [ 11071479; argus; 83236 ] SNMP check request: oid 1.3.6.1.4.1.2021.255.2525
tail: `connection.log' has been replaced; following end of new file
DEBUG 23.12.2007 22:30:48 [ 11071479; argus; 83236 ] SNMP check request: oid 1.3.6.1.4.1.2021.255.2525
DEBUG 23.12.2007 22:31:58 [ 11071479; argus; 83236 ] SNMP check request: oid 1.3.6.1.4.1.2021.255.2525
DEBUG 23.12.2007 22:32:53 [ 11071479; argus; 83236 ] SNMP check request: oid 1.3.6.1.4.1.2021.255.2525
tail: `connection.log' has been replaced; following end of new file
DEBUG 23.12.2007 22:33:48 [ 11071479; argus; 83236 ] SNMP check request: oid 1.3.6.1.4.1.2021.255.2525
DEBUG 23.12.2007 22:34:53 [ 11071479; argus; 83236 ] SNMP check request: oid 1.3.6.1.4.1.2021.255.2525
tail: `connection.log' has been replaced; following end of new file
DEBUG 23.12.2007 22:35:53 [ 11071479; argus; 83236 ] SNMP check request: oid 1.3.6.1.4.1.2021.255.2525
DEBUG 23.12.2007 22:36:58 [ 11071479; argus; 83236 ] SNMP check request: oid 1.3.6.1.4.1.2021.255.2525
tail: `connection.log' has been replaced; following end of new file
DEBUG 23.12.2007 22:37:53 [ 11071479; argus; 83236 ] SNMP check request: oid 1.3.6.1.4.1.2021.255.2525
DEBUG 23.12.2007 22:38:48 [ 11071479; argus; 83236 ] SNMP check request: oid 1.3.6.1.4.1.2021.255.2525
tail: `connection.log' has been replaced; following end of new file
DEBUG 23.12.2007 22:39:53 [ 11071479; argus; 83236 ] SNMP check request: oid 1.3.6.1.4.1.2021.255.2525
DEBUG 23.12.2007 22:40:43 [ 11071479; argus; 83236 ] SNMP check request: oid 1.3.6.1.4.1.2021.255.2525
DEBUG 23.12.2007 22:40:44 [ 11071479; argus; 83236 ] SNMP check response: 2
tail: `connection.log' has been replaced; following end of new file
DEBUG 23.12.2007 22:41:48 [ 11071479; argus; 83236 ] SNMP check request: oid 1.3.6.1.4.1.2021.255.2525
Вот вывод сниффера с той же машины где проверяльщик:
tcpdump -nnvv -i eth1 udp port 161|grep '255.2525'
tcpdump: listening on eth1, link-type EN10MB (Ethernet), capture size 96 bytes
22:40:43.915373 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto: UDP (17), length: 73) 172.17.1.2.32814 > 172.17.1.3.161: { SNMPv2c C=xxxxxx { GetRequest(29) R=16407 .1.3.6.1.4.1.2021.255.2525 } }
22:40:44.356964 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto: UDP (17), length: 74) 172.17.1.3.161 > 172.17.1.2.32814: { SNMPv2c C=xxxxxx { GetResponse(30) R=16407 .1.3.6.1.4.1.2021.255.2525="2" } }
вот вывод сниффера с наса:
root@vpn1:~# tcpdump -nnvv -i eth0 host 172.17.1.2 and udp port 161|grep '255.2525'
tcpdump: listening on eth0, link-type EN10MB (Ethernet), capture size 96 bytes
22:40:43.928375 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto: UDP (17), length: 73) 172.17.1.2.32814 > 172.17.1.3.161: { SNMPv2c C=xxxxxx { GetRequest(29) R=16407 .1.3.6.1.4.1.2021.255.2525 } }
22:40:44.369859 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto: UDP (17), length: 74) 172.17.1.3.161 > 172.17.1.2.32814: { SNMPv2c C=xxxxxx { GetResponse(30) R=16407 .1.3.6.1.4.1.2021.255.2525="2" } }

Из этого всего следует, snmp проверяльщик не делает того что говорит! Из всех попыток послать snmp запрс, реально послал только один запрос в 22:40:43, от сюда и сесси со статусом sleep

В radius.out ошибок нет?
Можете вытащить полный лог данного соединения из connection.log?

В radius.out ошибок нет.
В connection.log валится очень много сообщений в режиме DEBUG, и он перезаписывается каждые 3 мин. Можно уменьшить количество сообщений?
Вот всё что было в логах по этому соединению:
http://www.lentel.ru/argus.txt
Но сейчас активность упала и ситуация нормализовалась:
./radius_ps.sh && cat list | grep wait | wc -l
0
./radius_ps.sh && cat list | grep active | wc -l
104
./radius_ps.sh && cat list | grep sleep | wc -l
0
Проблемма возникает при бОльшем количестве подключений.

Можно временно увеличить его размер в конфиге log4j_radius.properties.

Вышеописанная проблемма наблюдается с любой сессией. Увеличил размер и количество файлов лога, мониторил весь день. Если в логе появлялось сообщение SNMP check request, то и снифером оно наблюдалось (т.е. запрос по сети отправлялся), к вечеру, когда активность возросла, то сообщение лога не подтверждалось сниффером (т.е. реально запрос отправлялся очень редко), не важно какая сессия, даже со статусом active.
Тут дебаг 3х произвольно взятых сессий:
http://www.lentel.ru/debug.tar.bz2

Попробуйте перевести радиус в UPDATE режим, UPDATE пакеты ведь идут?

Я же говорю, что UPDATE пакеты специально отключил, да они мне и не нужны т.к. трафик мы учитываем при помощи netflow, да и причём тут UPDATE если Ваш SNMP не шлёт запросы, хотя в логах пишет что шлёт. Решите пожалуйста эту проблему.

Вопрос всё ещё актуален. Можно надеятся на его решение ???

В процессе.

Нужен ССШ доступ к радиус серверу, бросьте пожалуйста в личку. И заодно вашу аську. Проверял код, отправка SNMP запроса буквально на соседней строчке с выводом записи в лог..

Спасибо, обновление решило проблему.