forum.bitel.ru
http://forum.bitel.ru/

Новая проблема с радиусом (bgbilling 4.2)
http://forum.bitel.ru/viewtopic.php?f=5&t=498		 Страница 1 из 1
Автор:  vadim s. sabinich [ 01 ноя 2007, 08:05 ]
Заголовок сообщения:  Новая проблема с радиусом (bgbilling 4.2)
Столкнулись с новым сюрпризом, который никак не получается отловить.
Радиус просто не ведет некоторые сессии. Т.е соединение есть, интернет есть, а обсчет услуги не ведется абсолютно. Нередко даже в логах радиуса ничего не отображается. Лечится или перезагрузкой радиуса, или рестартом pppoe-сервера на оборудовании.
Такое встретилось как на рапире, так и на микротике. Буквально на этой неделе началось.
По миру ж пойдем, если все клиенты начнут так "баловаться". 8((

В чем может быть проблема? Какие настройки показать? На что обратить внимание? Я теряюсь в догадках.
Автор:  Администратор [ 01 ноя 2007, 11:14 ]
Заголовок сообщения: 
Обратите внимание приходит ли START пакет по этим сессиям, потом сделайте radius_ps.sh - есть ли в списке коннектов потерянные сессии? Какой у них статус?
Автор:  vadim s. sabinich [ 01 ноя 2007, 12:28 ]
Заголовок сообщения: 
А можно прокомментировать вот такое (взято из 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
Автор:  Администратор [ 01 ноя 2007, 17:05 ]
Заголовок сообщения: 
Цитата:
|r15.nas.ip| x.x.x.x | UNDEF | |user-login | x.x.x.x | mac-addr | 054 - 06 | wait

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

Цитата:
|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

авторизована, старт пришел но проверка по SNMP либо по Update пакетам не прошла, обсчет не идет.
Цитата:
|r15.nas.ip| x.x.x.x | 386D4E1D033B |01.11.2007 13:38:19 |oxranagel | x.x.x.x | mac-addr | 054 - 06 | active

нормальная сессия, считается.
Автор:  vadim s. sabinich [ 01 ноя 2007, 19:35 ]
Заголовок сообщения: 
Отследил проблему.
В 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:
Автор:  Администратор [ 02 ноя 2007, 17:35 ]
Заголовок сообщения: 
Похоже старт пакет не всегда приходит. На днях выложим апдейт чтобы поднимал сессию по Update пакету тоже.. Если не было старта.
Автор:  vadim s. sabinich [ 01 дек 2007, 20:13 ]
Заголовок сообщения: 
После обновления на v4.3 проблема решилась, боюсь, только частично.
Половина сессий поднялась нормально, половина - нет. С маршрутизаторов на РоутерОС и СтарОС. (микротик, рапира). Т.е сессии поднимаются 50\50.

s: на неподхваченной сессии наработка составляет:
Acct-Input-Octets=79929616
Acct-Output-Octets=588851368
Это пролетело мимо, получается?
Автор:  iONE [ 23 дек 2007, 22:54 ]
Заголовок сообщения: 
По выходным, когда наблюдается пиковая активность пользователей, появляются сессии со статусом 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
Автор:  iONE [ 24 дек 2007, 01:47 ]
Заголовок сообщения: 
Вот дебаг 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
Автор:  Администратор [ 24 дек 2007, 02:01 ]
Заголовок сообщения: 
В radius.out ошибок нет?
Можете вытащить полный лог данного соединения из connection.log?
Автор:  iONE [ 24 дек 2007, 11:48 ]
Заголовок сообщения: 
В 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
Проблемма возникает при бОльшем количестве подключений.
Автор:  Администратор [ 24 дек 2007, 11:55 ]
Заголовок сообщения: 
Можно временно увеличить его размер в конфиге log4j_radius.properties.
Автор:  iONE [ 24 дек 2007, 20:31 ]
Заголовок сообщения: 
Вышеописанная проблемма наблюдается с любой сессией. Увеличил размер и количество файлов лога, мониторил весь день. Если в логе появлялось сообщение SNMP check request, то и снифером оно наблюдалось (т.е. запрос по сети отправлялся), к вечеру, когда активность возросла, то сообщение лога не подтверждалось сниффером (т.е. реально запрос отправлялся очень редко), не важно какая сессия, даже со статусом active.
Тут дебаг 3х произвольно взятых сессий:
http://www.lentel.ru/debug.tar.bz2
Автор:  Администратор [ 25 дек 2007, 12:35 ]
Заголовок сообщения: 
Попробуйте перевести радиус в UPDATE режим, UPDATE пакеты ведь идут?
Автор:  iONE [ 25 дек 2007, 13:12 ]
Заголовок сообщения: 
Я же говорю, что UPDATE пакеты специально отключил, да они мне и не нужны т.к. трафик мы учитываем при помощи netflow, да и причём тут UPDATE если Ваш SNMP не шлёт запросы, хотя в логах пишет что шлёт. Решите пожалуйста эту проблему.
Автор:  iONE [ 25 дек 2007, 18:31 ]
Заголовок сообщения: 
Вопрос всё ещё актуален. Можно надеятся на его решение ???
Автор:  Администратор [ 25 дек 2007, 20:30 ]
Заголовок сообщения: 
В процессе.
Автор:  Администратор [ 26 дек 2007, 02:51 ]
Заголовок сообщения: 
Нужен ССШ доступ к радиус серверу, бросьте пожалуйста в личку. И заодно вашу аську. Проверял код, отправка SNMP запроса буквально на соседней строчке с выводом записи в лог..
Автор:  iONE [ 28 дек 2007, 12:11 ]
Заголовок сообщения: 
Спасибо, обновление решило проблему.
Страница 1 из 1 Часовой пояс: UTC + 5 часов [ Летнее время ]
Powered by phpBB® Forum Software © phpBB Group
http://www.phpbb.com/