Столкнулся с проблемой при переводе dialup NAS на 6-ую версию.
Сначала был построен NAS (FreeBSD 7.1, MPD5) для DSL абонентов(PPPoE). В админке прописан IP-адрес и ключевое слово к этому NAS. Сейчас решил объединить c dialup NAS (Cisco 5350). Прописал в админке второй NAS. (Сервер с UTM5 на отдельной от обоих NAS машине.)
Те пользователи, которые используют PPPoE работают нормально, а вот диалапщики, когда прописываешь на кошаке данные нового сервера с RADIUS, очень долго пытаются залогиниться, и потом их отбрасывает. На другом таком же сервере, тоже UTM5 (005) эта цыска работает.
Вот лог коннекта тестового юзера (в услуге взял временной промежуток полный, для теста):
Код: Выделить всё
?Debug : Feb 18 16:28:37 AuthServer: User <test1> connecting
?Debug : Feb 18 16:28:37 AuthServer: Session for sessionid <test1> not found in <10.10.1.101> cache
?Debug : Feb 18 16:28:37 RADIUS DBA: Info for login <test1> found. type <2>
?Debug : Feb 18 16:28:37 RADIUS DBA: login_store iter->second.dialup.session_count:0
?Debug : Feb 18 16:28:37 AuthServer: Auth scheme: PAP
?Debug : Feb 18 16:28:37 AuthServer: PAP: <123456> vs <123456>
?Debug : Feb 18 16:28:37 AuthServer: PAP: Authorized user <test1>
?Debug : Feb 18 16:28:37 AuthServer: Dialup session limit:1 session count:0 for user:test1
Info : Feb 18 16:28:37 UT: calc timeout
Info : Feb 18 16:28:37 UT: t 1234956517, left money 333.000000
Info : Feb 18 16:28:37 UT: tr_id 1, mult 1.000000, next 1234983600
Info : Feb 18 16:28:37 UT: quantity 27083 for borders
Info : Feb 18 16:28:37 UT: after borders q=27083, downloaded=27083, downed_as_prepaid=0 cost_info size <1>
Info : Feb 18 16:28:37 UT: added entire 27083
Info : Feb 18 16:28:37 UT: i==cost_info->end()
Info : Feb 18 16:28:37 UT: session_timeout <27083> session_limit <864000> old_session_timeout <0>
Info : Feb 18 16:28:37 UT: t 1234983600, left money 325.476944
Info : Feb 18 16:28:37 UT: tr_id 1, mult 1.000000, next 1235070000
Info : Feb 18 16:28:37 UT: quantity 86400 for borders
Info : Feb 18 16:28:37 UT: after borders q=86400, downloaded=113483, downed_as_prepaid=0 cost_info size <1>
Info : Feb 18 16:28:37 UT: added entire 86400
Info : Feb 18 16:28:37 UT: i==cost_info->end()
Info : Feb 18 16:28:37 UT: session_timeout <113483> session_limit <864000> old_session_timeout <27083>
Info : Feb 18 16:28:37 UT: t 1235070000, left money 301.476944
Info : Feb 18 16:28:37 UT: tr_id 1, mult 1.000000, next 1235156400
Info : Feb 18 16:28:37 UT: quantity 86400 for borders
Info : Feb 18 16:28:37 UT: after borders q=86400, downloaded=199883, downed_as_prepaid=0 cost_info size <1>
Info : Feb 18 16:28:37 UT: added entire 86400
Info : Feb 18 16:28:37 UT: i==cost_info->end()
Info : Feb 18 16:28:37 UT: session_timeout <199883> session_limit <864000> old_session_timeout <113483>
Info : Feb 18 16:28:37 UT: t 1235156400, left money 277.476944
Info : Feb 18 16:28:37 UT: tr_id 1, mult 1.000000, next 1235242800
Info : Feb 18 16:28:37 UT: quantity 86400 for borders
Info : Feb 18 16:28:37 UT: after borders q=86400, downloaded=286283, downed_as_prepaid=0 cost_info size <1>
Info : Feb 18 16:28:37 UT: added entire 86400
Info : Feb 18 16:28:37 UT: i==cost_info->end()
Info : Feb 18 16:28:37 UT: session_timeout <286283> session_limit <864000> old_session_timeout <199883>
Info : Feb 18 16:28:37 UT: t 1235242800, left money 253.476944
Info : Feb 18 16:28:37 UT: tr_id 1, mult 1.000000, next 1235329200
Info : Feb 18 16:28:37 UT: quantity 86400 for borders
Info : Feb 18 16:28:37 UT: after borders q=86400, downloaded=372683, downed_as_prepaid=0 cost_info size <1>
Info : Feb 18 16:28:37 UT: added entire 86400
Info : Feb 18 16:28:37 UT: i==cost_info->end()
Info : Feb 18 16:28:37 UT: session_timeout <372683> session_limit <864000> old_session_timeout <286283>
Info : Feb 18 16:28:37 UT: t 1235329200, left money 229.476944
Info : Feb 18 16:28:37 UT: tr_id 1, mult 1.000000, next 1235415600
Info : Feb 18 16:28:37 UT: quantity 86400 for borders
Info : Feb 18 16:28:37 UT: after borders q=86400, downloaded=459083, downed_as_prepaid=0 cost_info size <1>
Info : Feb 18 16:28:37 UT: added entire 86400
Info : Feb 18 16:28:37 UT: i==cost_info->end()
Info : Feb 18 16:28:37 UT: session_timeout <459083> session_limit <864000> old_session_timeout <372683>
Info : Feb 18 16:28:37 UT: t 1235415600, left money 205.476944
Info : Feb 18 16:28:37 UT: tr_id 1, mult 1.000000, next 1235502000
Info : Feb 18 16:28:37 UT: quantity 86400 for borders
Info : Feb 18 16:28:37 UT: after borders q=86400, downloaded=545483, downed_as_prepaid=0 cost_info size <1>
Info : Feb 18 16:28:37 UT: added entire 86400
Info : Feb 18 16:28:37 UT: i==cost_info->end()
Info : Feb 18 16:28:37 UT: session_timeout <545483> session_limit <864000> old_session_timeout <459083>
Info : Feb 18 16:28:37 UT: t 1235502000, left money 181.476944
Info : Feb 18 16:28:37 UT: tr_id 1, mult 1.000000, next 1235588400
Info : Feb 18 16:28:37 UT: quantity 86400 for borders
Info : Feb 18 16:28:37 UT: after borders q=86400, downloaded=631883, downed_as_prepaid=0 cost_info size <1>
Info : Feb 18 16:28:37 UT: added entire 86400
Info : Feb 18 16:28:37 UT: i==cost_info->end()
Info : Feb 18 16:28:37 UT: session_timeout <631883> session_limit <864000> old_session_timeout <545483>
Info : Feb 18 16:28:37 UT: t 1235588400, left money 157.476944
Info : Feb 18 16:28:37 UT: tr_id 1, mult 1.000000, next 1235674800
Info : Feb 18 16:28:37 UT: quantity 86400 for borders
Info : Feb 18 16:28:37 UT: after borders q=86400, downloaded=718283, downed_as_prepaid=0 cost_info size <1>
Info : Feb 18 16:28:37 UT: added entire 86400
Info : Feb 18 16:28:37 UT: i==cost_info->end()
Info : Feb 18 16:28:37 UT: session_timeout <718283> session_limit <864000> old_session_timeout <631883>
Info : Feb 18 16:28:37 UT: t 1235674800, left money 133.476944
Info : Feb 18 16:28:37 UT: tr_id 1, mult 1.000000, next 1235761200
Info : Feb 18 16:28:37 UT: quantity 86400 for borders
Info : Feb 18 16:28:37 UT: after borders q=86400, downloaded=804683, downed_as_prepaid=0 cost_info size <1>
Info : Feb 18 16:28:37 UT: added entire 86400
Info : Feb 18 16:28:37 UT: i==cost_info->end()
Info : Feb 18 16:28:37 UT: session_timeout <804683> session_limit <864000> old_session_timeout <718283>
Info : Feb 18 16:28:37 UT: t 1235761200, left money 109.476944
Info : Feb 18 16:28:37 UT: tr_id 1, mult 1.000000, next 1235847600
Info : Feb 18 16:28:37 UT: quantity 86400 for borders
Info : Feb 18 16:28:37 UT: after borders q=86400, downloaded=891083, downed_as_prepaid=0 cost_info size <1>
Info : Feb 18 16:28:37 UT: added entire 86400
Info : Feb 18 16:28:37 UT: i==cost_info->end()
Info : Feb 18 16:28:37 UT: session_timeout <891083> session_limit <864000> old_session_timeout <804683>
Info : Feb 18 16:28:37 UT: session_timeout > session_limit or session_timeout - old_session_timeout too small. Breaking ...
?Debug : Feb 18 16:28:37 AuthServer: Calculated maximum session time: 864000
?Debug : Feb 18 16:28:37 RADIUS DBA: dialup_link_update called for slink:398
?Debug : Feb 18 16:28:37 RADIUS DBA: soft dialup_link_update for slink:398 session_count:0
?Debug : Feb 18 16:28:37 AuthServer: Calling fill radius attributes for service. Attr storage size <0>
?Debug : Feb 18 16:28:37 AuthServer: Calling fill radius attributes for slink. Attr storage size <0>
?Debug : Feb 18 16:28:37 AuthServer: Calling fill radius attributes for NAS. Attr storage size <0>
Notice: Feb 18 16:28:37 AuthServer: Login OK <test1> from NAS <10.10.1.101> CLID <44111> Calling-station <41274>
?Debug : Feb 18 16:28:37 AuthServer: Setting interim update interval from config
?Debug : Feb 18 16:28:37 AuthServer: Auth reply: RPacket:
Code: 2; ID: 219
<Vendor: 0; Attr: 6>[4]: 00000002
<Vendor: 0; Attr: 7>[4]: 00000001
<Vendor: 0; Attr: 27>[4]: 000d2f00
<Vendor: 0; Attr: 85>[4]: 00000040
?Debug : Feb 18 16:28:37 RADIUS Packet: raw data constructed! size <44>
?Debug : Feb 18 16:28:37 RadiusSocket: Moving RADIUS packet into send queue
?Debug : Feb 18 16:28:37 RadiusSocket: RADIUS raw data sent
?Debug : Feb 18 16:28:37 AuthServer: Next...
?Trace : Feb 18 16:28:37 AuthServer: Process loop step
?Debug : Feb 18 16:28:37 RadiusSocket: Waiting for RADIUS raw data
?Debug : Feb 18 16:28:38 RADIUS Stream[plugin]: Account <75> with balance <951052.587>
?Debug : Feb 18 16:28:39 RadiusSocket: RADIUS packet successfully received
?Debug : Feb 18 16:28:39 RadiusSocket: RADIUS raw data obtained
?Debug : Feb 18 16:28:39 RADIUS Packet: Size <279>; HDR.Size <279>
?Debug : Feb 18 16:28:39 AcctServer: Recv...
?Debug : Feb 18 16:28:39 AcctServer: Packet from <10.10.1.103> packet dump: RPacket:
Code: 4; ID: 198
<Vendor: 0; Attr: 1>[7]: 7a7669726b756e
<Vendor: 0; Attr: 4>[4]: 0a0a0165
<Vendor: 0; Attr: 5>[4]: 00000105
<Vendor: 0; Attr: 6>[4]: 00000002
<Vendor: 0; Attr: 7>[4]: 00000001
<Vendor: 0; Attr: 8>[4]: c0a8c40a
<Vendor: 0; Attr: 30>[5]: 3434313131
<Vendor: 0; Attr: 31>[5]: 3437333934
<Vendor: 0; Attr: 40>[4]: 00000003
<Vendor: 0; Attr: 41>[4]: 0000000f
<Vendor: 0; Attr: 42>[4]: 0000a193
<Vendor: 0; Attr: 43>[4]: 0001d7b0
<Vendor: 0; Attr: 44>[8]: 3030303043463432
<Vendor: 0; Attr: 45>[4]: 00000001
<Vendor: 0; Attr: 46>[4]: 00000166
<Vendor: 0; Attr: 47>[4]: 0000015f
<Vendor: 0; Attr: 48>[4]: 00000120
<Vendor: 0; Attr: 61>[4]: 00000000
<Vendor: 0; Attr: 77>[36]: 3331323030205633342b2f5634326269732f4c41504d202833333630302f333132303029
<Vendor: 9; Attr: 1>[27]: 636f6e6e6563742d70726f67726573733d4c414e20536573205570
<Vendor: 9(0); Attr: 1>[18]: 6e61732d74782d73706565643d3331323030
<Vendor: 9(1); Attr: 1>[18]: 6e61732d72782d73706565643d3331323030
<Vendor: 9; Attr: 2>[9]: 4173796e63312f3435
Да, вот ещё заметил, что ответ почему-то уходит другому NAS...не 10.10.1.101, а 10.10.1.103. Но не всегда.
Фаравол открыл полностью для этого NAS - поставил в самый вверх:
Код: Выделить всё
ipfw add allow ip from nas_ip to me
ipfw add allow ip from me to nas_ip
В кабинете скачал ключ новый. Модуль коммутируемых и VPN-соединений - куплен.
Я вот думаю, может не включен модуль коммутируемых соединений в лицензии? Голову ломаю второй день. В общем, так как ничего не придумал, решил написать сюда
