BiTel

Всем доброго времени суток. Проблема мультилогинга не нова. Перечитал все темы в этом разделе и не один из способов не помог.
Обнаружил, что при подключении любого пользователя с наса wifi портала его статус сразу suspended и таковым остается до того момента, как не истечет таймер активности соединения, или пользователь сам не отключиться со страницы авторизации портала. Объяснение этому возможно является анализ вывода файла connection.log. Вот к примеру что в нем остается после авторизации через портал пользователя adm.
------------
[root@bgbilling log]# cat connection.log |grep adm
09-18/20:22:14 INFO [radiusListener-p-5-t-46] connections - [ 71; adm; 34136 ] DialUpNASConnection startConnection mode=2
09-18/20:22:14 INFO [radiusListener-p-5-t-46] connections - [ 71; adm; 34136 ] IP address register on collector
-----------
все, больше ничего не приходит. В то время как от пользователей др. насов (cisco, режим update) как и положенно идут обновления
-----------
09-18/19:46:47 INFO [radiusListener-p-5-t-50] connections - [ 10310; bushima; 43679 ] DialUpNASConnection update connection..
09-18/19:47:48 INFO [radiusListener-p-5-t-46] connections - [ 10310; bushima; 43679 ] DialUpNASConnection update connection..
09-18/19:48:45 INFO [radiusListener-p-5-t-45] connections - [ 10310; bushima; 43679 ] DialUpNASConnection update connection..
09-18/19:49:47 INFO [radiusListener-p-5-t-44] connections - [ 10310; bushima; 43679 ] DialUpNASConnection update connection..
09-18/19:50:49 INFO [radiusListener-p-5-t-46] connections - [ 10310; bushima; 43679 ] DialUpNASConnection update connection..
-----------

Я так понимаю сессия в режиме suspended не является активной по определению и поэтому ограничение на кол-во сессий не работает. Мультилоггинг в любых количествах возможен с wifi портала. Подскажите в чем причина и как диагностировать что не работает? Какие пакеты и с какого порта должны ходить с наса портала на радиус, чтоб его статус был working?

NAS WiFi:
----------------------------------------------
nas.port_time.default.*=1
nas.port_traffic.default.*=9:COLLECTOR;2:COLLECTOR;15:COLLECTOR;3:COLLECTOR
card.activate.service=0
callback.support=0
month.break=1
month.break.period=3600
nas.inspector.sleep_time=60
nas.inspector.kill.max_messages=5
dialup.workmode=2
nas.inspector.class=bitel.billing.server.processor.WiFiConnectionInspector
nas.inspector.wifi.host=a.b.c.d
nas.inspector.wifi.port=5555
netflow.receive.from=127.0.0.1

Франмент конфигурации DialUP модуля:
----------------------------------------------
#время в секундах, через которое происходит пересчёт в режиме CHECKER
update.time=60
#время в секундах, через которое проверяется необходимость пересчёта в режиме CHECKER
run.sleep=3
dialup.workmode=1
max.update.timeout=120
#сколько максимально секунд соединение в статусе wait ждёт Start пакета
max.wait.timeout=120
#игнорировать длительность соединения в Acct-Session-Time атрибуте с NASа, вычислять самостоятельно
#ignore.acct.session.time=1
#прерывать сессии с того же Calling-Station-Id, если при авторизации произошла ошибка "Превышен лимит сессий"
check.duplicate.session=1

Фрагмент wifi_agent.properties:
----------------------------------------------
wifi.agent.radius.live.time=120000
wifi.agent.client.live.time=2400000

Установлено:
----------------------------------------------
Сервер: вер. 5.1 сборка 706 от 12.09.2011 20:52:10
os:Linux; java:Sun Microsystems Inc., v.1.6.0_14
dialup вер. 5.1 сборка 184 от 07.09.2011 15:13:58

_________________

Сервер: вер. 5.2 сборка 1442 от 11.03.2013 20:09:04
os: Linux; java: Java HotSpot(TM) Server VM, v.1.6.0_33
card вер. 5.2 сборка 199 от 05.03.2013 15:29:28
dialup вер. 5.2 сборка 375 от 28.02.2013 18:32:25
WiFi агент 5.2_222

На a.b.c.d на порту 5555 висит слушатель , на него радиус шлет запрос .. Проверьте все ли там доступно

Трафик между порталом и радиусом ходит любой. Между нормально работающим насом cisco и радиусом постоянно происходит обмен:
--------------------
13:54:43.117293 IP (ip nas cisco).1646 > (ip dialup radius).1813: RADIUS, Accounting Request (4), id: 0x75 length: 321
13:54:43.122194 IP (ip dialup radius).1813 > (ip nas cisco).1646: RADIUS, Accounting Response (5), id: 0x75 length: 20


Теперь вывод дампа пакетов при авторизации на портале, активной работы под логином в течении пары минут и выход:
--------------------
авторизация .....
13:57:25.217916 IP (ip nas wifi).52776 > (ip dialup radius).1812: RADIUS, Access Request (1), id: 0xed length: 80
13:57:25.217934 IP (ip nas wifi) > (ip dialup radius): udp
13:57:25.217943 IP (ip nas wifi) > (ip dialup radius): udp
13:57:25.252434 IP (ip dialup radius).1812 > (ip nas wifi).52776: RADIUS, Access Accept (2), id: 0xed length: 303
13:57:25.263856 IP (ip nas wifi).41006 > (ip dialup radius).1813: RADIUS, Accounting Request (4), id: 0xee length: 63
13:57:25.263882 IP (ip nas wifi) > (ip dialup radius): udp
13:57:25.263889 IP (ip nas wifi) > (ip dialup radius): udp
13:57:25.264540 IP (ip dialup radius).1813 > (ip nas wifi).41006: RADIUS, Accounting Response (5), id: 0xee length: 20
13:57:25.345607 IP (ip nas wifi).41884 > (ip dialup radius).8080: Flags [S], seq 571315616, win 14600, options [mss 1460,sackOK,TS val 180593126 ecr 0,nop,wscale 6]
13:57:25.345778 IP (ip dialup radius).8080 > (ip nas wifi).41884: Flags [S.], seq 3600241696, ack 571315617, win 5792, options [mss 1460,sackOK,TS val 4201078 ecr 1
13:57:25.345814 IP (ip nas wifi).41884 > (ip dialup radius).8080: Flags [.], ack 1, win 229, options [nop,nop,TS val 180593126 ecr 4201078], length 0
13:57:25.346477 IP (ip nas wifi).41884 > (ip dialup radius).8080: Flags [P.], seq 1:289, ack 1, win 229, options [nop,nop,TS val 180593127 ecr 4201078], length 288
13:57:25.346506 IP (ip nas wifi).41884 > (ip dialup radius).8080: Flags [P.], seq 289:390, ack 1, win 229, options [nop,nop,TS val 180593127 ecr 4201078], length 10
13:57:25.346653 IP (ip dialup radius).8080 > (ip nas wifi).41884: Flags [.], ack 289, win 108, options [nop,nop,TS val 4201079 ecr 180593127], length 0
13:57:25.346670 IP (ip dialup radius).8080 > (ip nas wifi).41884: Flags [.], ack 390, win 108, options [nop,nop,TS val 4201079 ecr 180593127], length 0
13:57:25.370394 IP (ip dialup radius).8080 > (ip nas wifi).41884: Flags [P.], seq 1:396, ack 390, win 108, options [nop,nop,TS val 4201102 ecr 180593127], length 39
13:57:25.370445 IP (ip nas wifi).41884 > (ip dialup radius).8080: Flags [.], ack 396, win 245, options [nop,nop,TS val 180593151 ecr 4201102], length 0
13:57:25.371198 IP (ip dialup radius).8080 > (ip nas wifi).41884: Flags [P.], seq 396:401, ack 390, win 108, options [nop,nop,TS val 4201103 ecr 180593151], length
13:57:25.371250 IP (ip nas wifi).41884 > (ip dialup radius).8080: Flags [.], ack 401, win 245, options [nop,nop,TS val 180593152 ecr 4201103], length 0
13:57:35.372391 IP (ip nas wifi).41884 > (ip dialup radius).8080: Flags [F.], seq 390, ack 401, win 245, options [nop,nop,TS val 180603153 ecr 4201103], length 0
13:57:35.372658 IP (ip dialup radius).8080 > (ip nas wifi).41884: Flags [F.], seq 401, ack 391, win 108, options [nop,nop,TS val 4211105 ecr 180603153], length 0
13:57:35.372691 IP (ip nas wifi).41884 > (ip dialup radius).8080: Flags [.], ack 402, win 245, options [nop,nop,TS val 180603153 ecr 4211105], length 0
....
в это время я активно юзал интернет, но никакой активности между порталом и радиусом нет, ни с той ни с другой стороны
....
выход (нажал кнопочку выход на странице портала)
13:59:50.166335 IP (ip nas wifi).37323 > (ip dialup radius).1813: RADIUS, Accounting Request (4), id: 0xef length: 69
13:59:50.166360 IP (ip nas wifi) > (ip dialup radius): udp
13:59:50.166367 IP (ip nas wifi) > (ip dialup radius): udp
13:59:50.166988 IP (ip dialup radius).1813 > (ip nas wifi).37323: RADIUS, Accounting Response (5), id: 0xef length: 20

Тот же дамп, только на радиус-сервере
--------------------
авторизация...
13:57:25.226516 IP (ip nas wifi).52776 > (ip dialup radius).1812: RADIUS, Access Request (1), id: 0xed length: 80
13:57:25.226533 IP (ip nas wifi) > (ip dialup radius): udp
13:57:25.226538 IP (ip nas wifi) > (ip dialup radius): udp
13:57:25.260843 IP (ip dialup radius).1812 > (ip nas wifi).52776: RADIUS, Access Accept (2), id: 0xed length: 303
13:57:25.272463 IP (ip nas wifi).41006 > (ip dialup radius).1813: RADIUS, Accounting Request (4), id: 0xee length: 63
13:57:25.272474 IP (ip nas wifi) > (ip dialup radius): udp
13:57:25.272479 IP (ip nas wifi) > (ip dialup radius): udp
13:57:25.272963 IP (ip dialup radius).1813 > (ip nas wifi).41006: RADIUS, Accounting Response (5), id: 0xee length: 20
13:57:25.354160 IP (ip nas wifi).41884 > (ip dialup radius).8080: S 571315616:571315616(0) win 14600 <mss 1460,sackOK,timestamp 180593126 0,nop,wscale 6>
13:57:25.354203 IP (ip dialup radius).8080 > (ip nas wifi).41884: S 3600241696:3600241696(0) ack 571315617 win 5792 <mss 1460,sackOK,timestamp 4201078 180593126,nop
13:57:25.354341 IP (ip nas wifi).41884 > (ip dialup radius).8080: . ack 1 win 229 <nop,nop,timestamp 180593126 4201078>
13:57:25.355036 IP (ip nas wifi).41884 > (ip dialup radius).8080: P 1:289(288) ack 1 win 229 <nop,nop,timestamp 180593127 4201078>
13:57:25.355063 IP (ip dialup radius).8080 > (ip nas wifi).41884: . ack 289 win 108 <nop,nop,timestamp 4201079 180593127>
13:57:25.355073 IP (ip nas wifi).41884 > (ip dialup radius).8080: P 289:390(101) ack 1 win 229 <nop,nop,timestamp 180593127 4201078>
13:57:25.355083 IP (ip dialup radius).8080 > (ip nas wifi).41884: . ack 390 win 108 <nop,nop,timestamp 4201079 180593127>
13:57:25.378796 IP (ip dialup radius).8080 > (ip nas wifi).41884: P 1:396(395) ack 390 win 108 <nop,nop,timestamp 4201102 180593127>
13:57:25.378978 IP (ip nas wifi).41884 > (ip dialup radius).8080: . ack 396 win 245 <nop,nop,timestamp 180593151 4201102>
13:57:25.379619 IP (ip dialup radius).8080 > (ip nas wifi).41884: P 396:401(5) ack 390 win 108 <nop,nop,timestamp 4201103 180593151>
13:57:25.379788 IP (ip nas wifi).41884 > (ip dialup radius).8080: . ack 401 win 245 <nop,nop,timestamp 180593152 4201103>
13:57:35.380944 IP (ip nas wifi).41884 > (ip dialup radius).8080: F 390:390(0) ack 401 win 245 <nop,nop,timestamp 180603153 4201103>
13:57:35.381100 IP (ip dialup radius).8080 > (ip nas wifi).41884: F 401:401(0) ack 391 win 108 <nop,nop,timestamp 4211105 180603153>
13:57:35.381234 IP (ip nas wifi).41884 > (ip dialup radius).8080: . ack 402 win 245 <nop,nop,timestamp 180603153 4211105>

работа...

выход...
13:59:50.175011 IP (ip nas wifi).37323 > (ip dialup radius).1813: RADIUS, Accounting Request (4), id: 0xef length: 69
13:59:50.175025 IP (ip nas wifi) > (ip dialup radius): udp
13:59:50.175031 IP (ip nas wifi) > (ip dialup radius): udp
13:59:50.175473 IP (ip dialup radius).1813 > (ip nas wifi).37323: RADIUS, Accounting Response (5), id: 0xef length: 20

Если смотреть на рабочий нас циско, то там постоянно с радиуса идут на нас Accounting Request, а в ответ от наса Accounting Response. Т.е. запрос инициируется радиусом. Смею предположить что не отрабатывает сервер биллинга, не посылая запросы на портал. Или начальная процедура авторизации пользователя не проходит успешно. Старт пакет не приходит от наса или еще что-то. Теряюсь в догадках.

_________________

Сервер: вер. 5.2 сборка 1442 от 11.03.2013 20:09:04
os: Linux; java: Java HotSpot(TM) Server VM, v.1.6.0_33
card вер. 5.2 сборка 199 от 05.03.2013 15:29:28
dialup вер. 5.2 сборка 375 от 28.02.2013 18:32:25
WiFi агент 5.2_222

вы запустите логирование портала в режиме debug и покажите логи .

Выставил в log4j_wifi_agent.properties режим debug. В логах ageny.out ошибки
log4j:WARN No appenders could be found for logger (org.apache.struts.util.PropertyMessageResources).
log4j:WARN Please initialize the log4j system properly.

В portal.log как и было
09-21/18:39:04 INFO [http-9090-2] portal - checking aunthecation...
09-21/18:39:04 INFO [http-9090-2] portal - aunthecation accepted!!

В agent.log
09-21/18:38:58 INFO [main] wifiAgent - starting agent.....
09-21/18:38:58 DEBUG [main] wifiAgent - portal init..
09-21/18:38:58 DEBUG [main] wifiAgent - authHost = a.b.c.d
09-21/18:38:58 DEBUG [main] wifiAgent - accountHost = a.b.c.d
09-21/18:38:58 DEBUG [main] wifiAgent - authPort = 1812
09-21/18:38:58 DEBUG [main] wifiAgent - accountPort = 1813
09-21/18:38:58 DEBUG [main] wifiAgent - secret = *******
09-21/18:38:58 DEBUG [main] wifiAgent - nasId = wifi
09-21/18:38:58 INFO [main] wifiAgent - script command: /usr/local/BGDialupWiFiAgent/init.sh
09-21/18:38:58 DEBUG [Thread-2] wifiAgent - Chain WIFI (1 references)
pkts bytes target prot opt in out source destination.........
Zeroing chain `WIFI'

09-21/18:38:58 DEBUG [Thread-2] wifiAgent - ips:
09-21/18:38:58 INFO [main] wifiAgent - catalinaHome=/usr/local/BGDialupWiFiAgent/portal
09-21/18:38:58 DEBUG [main] wifiAgent - portal init..
09-21/18:38:58 DEBUG [main] wifiAgent - authHost = 194.54.64.28
09-21/18:38:58 DEBUG [main] wifiAgent - accountHost = 194.54.64.28
09-21/18:38:58 DEBUG [main] wifiAgent - authPort = 1812
09-21/18:38:58 DEBUG [main] wifiAgent - accountPort = 1813
09-21/18:38:58 DEBUG [main] wifiAgent - secret = [B@a084f8
09-21/18:38:58 DEBUG [main] wifiAgent - nasId = wifi
09-21/18:38:58 INFO [main] wifiAgent - HTTP port: 9090
09-21/18:38:58 INFO [main] wifiAgent - Starting HTTP connector..
09-21/18:38:58 INFO [main] wifiAgent - HTTPS port: 0
09-21/18:38:59 INFO [main] wifiAgent - Starting listen admin port 5556
09-21/18:39:04 DEBUG [http-9090-2] wifiAgent - /sbin/iptables -I WIFI 1 -t nat -j ACCEPT -s 10.50.2.165
09-21/18:39:04 INFO [http-9090-2] wifiAgent - script command: /usr/local/BGDialupWiFiAgent/login.sh 10.50.2.165 700 700.
09-21/18:39:04 INFO [http-9090-2] wifiAgent - alive check...
09-21/18:39:04 INFO [http-9090-2] wifiAgent - alive: 120
09-21/18:39:04 INFO [http-9090-2] wifiAgent - alive - ok

....................................................

09-21/18:39:28 DEBUG [Thread-2] wifiAgent - ips:
09-21/18:39:28 DEBUG [Thread-2] wifiAgent - 10.50.2.165:8095
09-21/18:39:28 DEBUG [Thread-2] wifiAgent - ip = 10.50.2.165
09-21/18:39:32 INFO [Thread-1] wifiAgent - manager: packet recieved
09-21/18:39:32 INFO [pool-1-thread-3] wifiAgent - trying to kill 10.50.3.52- it doesn't exists!!!
09-21/18:39:32 INFO [pool-1-thread-3] wifiAgent - send :packet start............
type : 5
count : 1
ip : 171049780
date : 1316615973008
login : null
packet end............

09-21/18:39:32 DEBUG [pool-1-thread-3] wifiAgent - registered ips:
09-21/18:39:32 DEBUG [pool-1-thread-3] wifiAgent - 10.50.2.165
09-21/18:39:37 DEBUG [http-9090-1] wifiAgent - /sbin/iptables -I WIFI 1 -t nat -j ACCEPT -s 10.50.3.77
09-21/18:39:37 INFO [http-9090-1] wifiAgent - script command: /usr/local/BGDialupWiFiAgent/login.sh 10.50.3.77 300 300.
09-21/18:39:37 INFO [http-9090-3] wifiAgent - alive check...
09-21/18:39:37 INFO [http-9090-3] wifiAgent - alive: 106
09-21/18:39:37 INFO [http-9090-3] wifiAgent - alive - ok
09-21/18:39:37 INFO [http-9090-3] wifiAgent - alive: true
.............................................................

_________________

Сервер: вер. 5.2 сборка 1442 от 11.03.2013 20:09:04
os: Linux; java: Java HotSpot(TM) Server VM, v.1.6.0_33
card вер. 5.2 сборка 199 от 05.03.2013 15:29:28
dialup вер. 5.2 сборка 375 от 28.02.2013 18:32:25
WiFi агент 5.2_222

еще логи радиуса интересуют , там должно быть что-то типа "ip a.b.c.d is alive " или ""ip a.b.c.d is dead"

Нет, таких записей нет. Все записи касаются наса cisco в режиме update. Поиском по логу не смог найти даже упоминания ip сетей которые крутятся на портале. Все записи такого вида
radius.log
---------------------

09-22/09:17:26 INFO [radiusListener-p-5-t-18] update - RESPONSE:
Packet type: Accounting-Response
Identifier: 221
Authenticator: {F9 FB BB C6 D6 07 EA BF 59 CA 37 24 4D 00 5E BC}
Attributes:

Process time update: 3

09-22/09:17:26 INFO [radiusListener-p-5-t-42] update - REQUEST:
Packet type: Accounting-Request
Identifier: 222
Authenticator: {EF 54 D9 5F D9 2A 65 6D 40 32 25 B0 18 DE 2A 1F}
Attributes:
User-Name=kuzmaaya
NAS-IP-Address=x.y.x.c
NAS-Port=42098
Service-Type=2
Framed-Protocol=1
UNKNOWN[-1-197]={77 35 94 00}
Framed-IP-Address=172.24.103.21
UNKNOWN[-1-196]={00 00 00 3C}
UNKNOWN[-1-198]={00 00 00 00}
UNKNOWN[-1-193]={00 00 00 07}
UNKNOWN[-1-192]={00 00 00 09}
NAS-Port-Id=15/0/1/50
Acct-Input-Octets=583774090
Acct-Output-Octets=219148133
Acct-Status-Type=3
Acct-Delay-Time=0
Acct-Session-Time=35105
Acct-Input-Packets=1198682
Acct-Session-Id=0000A472
Acct-Authentic=1
UNKNOWN[-1-255]={77 35 94 00}
Acct-Output-Packets=1112110
UNKNOWN[-1-190]={00 00 00 CC}
UNKNOWN[-1-191]={00 00 00 6C}
NAS-Port-Type=15
cisco-avpair=client-mac-address=90e6.baf7.7978
cisco-avpair=connect-progress=LAN Ses Up
cisco-avpair=nas-tx-speed=2000000000
cisco-avpair=nas-rx-speed=2000000000

_________________

Сервер: вер. 5.2 сборка 1442 от 11.03.2013 20:09:04
os: Linux; java: Java HotSpot(TM) Server VM, v.1.6.0_33
card вер. 5.2 сборка 199 от 05.03.2013 15:29:28
dialup вер. 5.2 сборка 375 от 28.02.2013 18:32:25
WiFi агент 5.2_222

В логах ничего нет, что вызывало бы вопросы. Я начинаю грешить на Fedora 15, логика работы некоторых утилит поменялась, может в этом проблема и откатить на версию постарше пока не поздно. Подскажите хотябы на основе того что писал, проблема в радиусе или в портале, чтоб локализовать в первом приближении.

_________________

Сервер: вер. 5.2 сборка 1442 от 11.03.2013 20:09:04
os: Linux; java: Java HotSpot(TM) Server VM, v.1.6.0_33
card вер. 5.2 сборка 199 от 05.03.2013 15:29:28
dialup вер. 5.2 сборка 375 от 28.02.2013 18:32:25
WiFi агент 5.2_222

Еще заметил симптом, нет идентификатора сессий на портале

.../radius.sh ps | grep wifi
| wifi | x.y.x.f | UNDEF |10.10.2011 18:53:07 |makarovav | k.j.h.g.f | 00:22:69:8c:cc:ea | 000057-11 |suspended |
| wifi | x.y.x.f | UNDEF |10.10.2011 18:52:25 |akimovaal | j.g.h.k.g | 00:1e:68:ae:d4:2b | 000042-11 |suspended |

Номера всех сессий UNDEF.

_________________

Сервер: вер. 5.2 сборка 1442 от 11.03.2013 20:09:04
os: Linux; java: Java HotSpot(TM) Server VM, v.1.6.0_33
card вер. 5.2 сборка 199 от 05.03.2013 15:29:28
dialup вер. 5.2 сборка 375 от 28.02.2013 18:32:25
WiFi агент 5.2_222