| forum.bitel.ru http://forum.bitel.ru/ |
|
| Проблемы какие-то, навалились прям :) http://forum.bitel.ru/viewtopic.php?f=5&t=683 |
Страница 1 из 1 |
| Автор: | S [ 18 янв 2008, 16:22 ] |
| Заголовок сообщения: | Проблемы какие-то, навалились прям :) |
Версия биллинга 4.3, радиус version 4.3 build 28 from 16.11.2007 09:42:3. Система Gentoo Linux. NAS-сервера - mpd-3.18. 1. Первая проблема, только что заметил просто. В логах радиуса: Код: INFO 18.01.2008 16:56:00 SNMP response [ SNMP1, host=192.168.0.90, msg=uk.co.westhawk.snmp.stack.AgentException cannot be cast to uk.co.westhawk.snmp.stack.varbind, recived object=uk.co.westhawk.snmp.stack.AgentException: Timed out ] SNMP-траффик между хостами идет. Код: 16:57:18.322846 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], length: 73) 192.168.0.110.32780 > 192.168.0.90.snmp: [udp sum ok] { SNMPv2c C=qwerty { GetRequest(30) R=15110424 E:2021.255.19 } } 16:57:20.319071 IP (tos 0x0, ttl 64, id 38178, offset 0, flags [none], length: 83) 192.168.0.90.snmp > 192.168.0.110.32780: { SNMPv2c C=qwerty { GetResponse(39) R=15110289 E:2021.255.3="login" } } 2. Проблема: ровно в 00.00 каждый день людей отключает. По логам радиуса в этот момент ничего существенного: Код: 15 23:52:11 Type=AUTHENTICATION_REQUEST Attributes: User-Name=kosmo1_103 NAS-Identifier=nas NAS-IP-Address=192.168.0.110 NAS-Port=21 Service-Type=2 Framed-Protocol=1 Calling-Station-Id=192.168.6.37 / \u40unknown\u41 / \u40unknown\u41 NAS-Port-Type=5 MS-CHAP2-Response=\u1\u0\u63\u164\u63xT8Yb\u63\u6\u63\u0\u164z\u61\u164\u0\u0\u0\u0\u0\u0\u0\u0_\u28T\u63\u23\u9\u3\u638_P7\u63t\u63C\u63B\u91\u63\u27\u63\u63C MS-CHAP-Challenge=\u187\u30hg\u15\u41IY\u26\u63\u63\T\u7\u25W 15 23:52:11 Type=AUTHENTICATION_ACCEPT Process time:17 Attributes: Acct-Interim-Interval=20 Service-Type=2 Framed-Protocol=1 Framed-IP-Address=62.33.201.35 MS-MPPE-Send-Key=\u63\u0\u63\u63\u23\u63\u63\u94#\u63\u63\u63\u22\u127\u183\u63\u183\u63L\u63\u63\u63\u634\u63\u14\u36\u61\u63l\u63\u174X\u63 MS-MPPE-Recv-Key=\u63\u0\u63\u38\u63\u163\u63\u63\u2\u63\u63T\u63\u63c\u63\u173\u63\u37\u63\u63C\u63l\u18C\u63\u63\u123:n\u5\u63 MS-CHAP2-Success=\u63S\u61172116D39CB321693C409EC6C7E7664D03F61E2D MS-MPPE-Encryption-Types=4 MS-MPPE-Encryption-Policy=1 15 23:52:11 Type=ACCOUNTING_REQUEST Attributes: User-Name=kosmo1_103 NAS-Identifier=nas NAS-IP-Address=192.168.0.110 NAS-Port=21 Service-Type=2 Framed-Protocol=1 Framed-IP-Address=62.33.201.35 Acct-Status-Type=1 Acct-Session-Id=416027-pptp021 Acct-Authentic=1 Acct-Link-Count=1 Acct-Multi-Session-Id=416027-pptp021 NAS-Port-Type=5 Calling-Station-Id=192.168.6.37 / \u40unknown\u41 / \u40unknown\u41 16 00:01:24 Type=ACCOUNTING_REQUEST Attributes: User-Name=kosmo1_103 NAS-Identifier=nas NAS-IP-Address=192.168.0.110 NAS-Port=21 Service-Type=2 Framed-Protocol=1 Acct-Input-Octets=213919 Framed-IP-Address=62.33.201.35 Acct-Output-Octets=698518 Acct-Status-Type=2 Acct-Session-Time=555 Acct-Input-Packets=1351 Acct-Session-Id=416027-pptp021 Acct-Authentic=1 Acct-Link-Count=1 Acct-Multi-Session-Id=416027-pptp021 Acct-Terminate-Cause=10 Acct-Output-Packets=1066 Acct-Output-Gigawords=0 Acct-Input-Gigawords=0 NAS-Port-Type=5 То есть, выглядит все так, как если бы клиент сам отключился. Код: INFO 16.01.2008 00:01:24 [ LS-00115; kosmo1_103; 31521 ] DialUpNASConnection stoppingConnection
INFO 16.01.2008 00:01:24 [ LS-00115; kosmo1_103; 31521 ] DialUpNASConnection has stop Packet => true INFO 16.01.2008 00:01:24 [ LS-00115; kosmo1_103; 31521 ] DialUpNASConnection set STATUS=3 INFO 16.01.2008 00:01:24 [ LS-00115; kosmo1_103; 31521 ] DialUpNASConnection sessionTime => 555 INFO 16.01.2008 00:02:14 [ LS-00115; kosmo1_103; 33956 ] DialUpNASConnection startConnection mode=1 INFO 16.01.2008 00:02:14 [ LS-00115; kosmo1_103; 33956 ] DialUpNASConnection set STATUS=1 INFO 16.01.2008 00:02:53 [ LS-00115; kosmo1_103; 33956 ] DialUpNASConnection update connection.. Но клиент ничего не делает. Но ровно в 00.00, плюс\минус минута\две. Такое началось, когда я обновил радиус. На 4.2 такого не было. Думаю, обновить его еще раз? Настройки собственно тоже никто не менял. Может что с тарифом, но его никто не трогал. Я читал, что у вас есть сброс раз в месяц, но такого не настраивал. 3. Проблема улетания в большой минус Также, на 4.2 было все нормально в принципе, если у клиента не специфичный режим работы, позволяющий уходить в минус, то улетал он максимум в 20 рублей, в ipcad я настроил длительность каждого потока 10 секунд, чтоб много не качалось. А щас улетел в минус. Есть один момент: в NAS слишком много открытых файлов становится в определенный момент и дескрипторов не хватает, периодически приходится ребутать машину, увеличить дескрипторы можно, но суть в том, что это могло повлиять на работу коллектора и он позволил netflow-потоку не останавливаться, пока не скачается файл. Это чисто предположение. 4. Проблема, которую я описывал в соседней ветке. http://bgbilling.ru/forum/viewtopic.php?t=562 Наложение даты сессий входа\выхода абонента. Думаю где-то прикол в настройках NAS, только понять не могу где, т.к. все считает верно, и суммы верно, но только на этом NAS (РРРоЕ), на другом NAS (VPN) все нормально. 5. Некоторые клиенты на NAS (PPPoE) не обсчитываются совсем Как будет лог в радиусе этого соединения, скину. На VPN все нормально. P.S. Пойду проверять настройки. Какие нужны логи могу добавить. Жду помощи. |
|
| Автор: | S [ 18 янв 2008, 17:21 ] |
| Заголовок сообщения: | |
Нашел лог по 5 проблеме: Код: 10 15:57:57
Type=AUTHENTICATION_REQUEST Attributes: User-Name=bakunin2 NAS-Identifier=amber CHAP-Password=\u1\u0\u63_\u36#4\u63\u63\u123\u63\u63\u63\u63\u40\u636 NAS-Port=32 Service-Type=2 Framed-Protocol=1 Calling-Station-Id=0013d3a99d59 NAS-Port-Type=5 CHAP-Challenge=\u187\u30h C?,\u166}???\u4\u27hy??\u29w??sd??x?(L\u3? 10 15:57:57 Type=AUTHENTICATION_ACCEPT Process time:19 Attributes: Acct-Interim-Interval=20 Service-Type=2 Framed-Protocol=1 Framed-IP-Address=83.234.37.166 10 15:57:57 Type=ACCOUNTING_REQUEST Attributes: User-Name=bakunin2 NAS-Identifier=amber NAS-Port=32 Service-Type=2 Framed-Protocol=1 Framed-IP-Address=83.234.37.166 Acct-Status-Type=1 Acct-Session-Id=9955477-pppoe32 Acct-Authentic=1 Acct-Link-Count=1 Acct-Multi-Session-Id=9955477-pppoe32 NAS-Port-Type=5 Calling-Station-Id=0013d3a99d59 10 19:47:01 Type=ACCOUNTING_REQUEST Attributes: User-Name=bakunin2 NAS-Identifier=amber NAS-Port=32 Service-Type=2 Framed-Protocol=1 Acct-Input-Octets=1402091 Framed-IP-Address=83.234.37.166 Acct-Output-Octets=6721344 Acct-Status-Type=2 Acct-Session-Time=21492 Acct-Input-Packets=10189 Acct-Session-Id=9955477-pppoe32 Acct-Authentic=1 Acct-Link-Count=1 Acct-Multi-Session-Id=9955477-pppoe32 Acct-Terminate-Cause=1 Acct-Output-Packets=11008 Acct-Output-Gigawords=0 Acct-Input-Gigawords=0 NAS-Port-Type=5 Calling-Station-Id=0013d3a99d59 У клиента в отчетах все по нулям. |
|
| Автор: | Администратор [ 21 янв 2008, 11:53 ] |
| Заголовок сообщения: | |
1. Последнее обновление RADIUS сервера должно помочь, там была проблема с неравномерным распределением отправляемых SNMP запросов, они терялись. 2. Нужно бы пораньше строки из connection.log по данной сессии. Как определяете что отключает RADIUS? Если есть запросы на сброс - они там логируются. 3. Нужно смотреть приходят ли потоки от ipcad по данному соединению, можете установить лог netflow в режим DEBUG если не очень большие объемы и понаблюдать как приходит статистика по IP сессии. 4. По наложению я отписал вам - нужно RADIUS логи этих 2х сессий, возможно что авторизация второй сессии приходит раньше чем стоп первой. 5. Необходимо connection.log по данному соединению вытащить.. И опять же, проверить что netflow статистика приходит (см. 3). |
|
| Автор: | S [ 25 янв 2008, 10:43 ] |
| Заголовок сообщения: | |
1. Не трогал радиус, само прошло...странно как-то, пока подожду рецидива. Но возникли подозрительные надписи: Код: INFO 24.01.2008 20:46:32 [ LS-00289; kosmo20_56; 6957 ] No close calculate period.. INFO 24.01.2008 20:48:02 [ LS-00791; sov90_26; 80889 ] No close calculate period.. INFO 24.01.2008 21:04:47 [ LS-00227; kalin24_179; 67243 ] No close calculate period.. INFO 24.01.2008 21:23:47 [ LS-00888 ; kalin20_73; 66551 ] No close calculate period.. INFO 24.01.2008 22:09:34 [ LS-00439; orlova30a_3; 13395 ] No close calculate period.. INFO 25.01.2008 00:19:00 [ LS-01033 ; kalin25_15; 80236 ] No close calculate period.. INFO 25.01.2008 00:23:05 [ LS-00125; gork1_25; 64922 ] No close calculate period.. INFO 25.01.2008 07:07:33 [ LS-00169; yubil8_62; 31599 ] No close calculate period.. INFO 25.01.2008 07:12:33 [ LS-00169; yubil8_62; 31599 ] No close calculate period.. INFO 25.01.2008 10:55:38 [ LS-00075 ; sov98_194; 17209 ] No close calculate period.. INFO 25.01.2008 10:55:58 [ LS-00075 ; sov98_194; 17209 ] No close calculate period.. INFO 25.01.2008 10:56:18 [ LS-00075 ; sov98_194; 17209 ] No close calculate period.. INFO 25.01.2008 10:56:38 [ LS-00075 ; sov98_194; 17209 ] No close calculate period.. INFO 25.01.2008 10:56:58 [ LS-00075 ; sov98_194; 17209 ] No close calculate period.. INFO 25.01.2008 10:57:18 [ LS-00075 ; sov98_194; 17209 ] No close calculate period.. INFO 25.01.2008 10:57:38 [ LS-00075 ; sov98_194; 17209 ] No close calculate period.. INFO 25.01.2008 10:57:58 [ LS-00075 ; sov98_194; 17209 ] No close calculate period.. INFO 25.01.2008 10:58:18 [ LS-00075 ; sov98_194; 17209 ] No close calculate period.. INFO 25.01.2008 10:58:38 [ LS-00075 ; sov98_194; 17209 ] No close calculate period.. INFO 25.01.2008 10:58:58 [ LS-00075 ; sov98_194; 17209 ] No close calculate period.. INFO 25.01.2008 10:59:18 [ LS-00075 ; sov98_194; 17209 ] No close calculate period.. INFO 25.01.2008 10:59:38 [ LS-00075 ; sov98_194; 17209 ] No close calculate period.. INFO 25.01.2008 10:59:58 [ LS-00075 ; sov98_194; 17209 ] No close calculate period.. INFO 25.01.2008 11:00:18 [ LS-00075 ; sov98_194; 17209 ] No close calculate period.. А весь лог выглядит как-то странно: Код: INFO 25.01.2008 11:00:08 [ LS-00075 ; sov98_194; 17209 ] sendKillRequest INFO 25.01.2008 11:00:08 [ LS-00075 ; sov98_194; 17209 ] SNMP reset request: set 1.3.6.1.4.1.2021.255.1 i 24 INFO 25.01.2008 11:00:13 [ LS-00075 ; sov98_194; 17209 ] sendKillRequest INFO 25.01.2008 11:00:13 [ LS-00075 ; sov98_194; 17209 ] SNMP reset request: set 1.3.6.1.4.1.2021.255.1 i 24 INFO 25.01.2008 11:00:18 [ LS-00075 ; sov98_194; 17209 ] sendKillRequest INFO 25.01.2008 11:00:18 [ LS-00075 ; sov98_194; 17209 ] Set connection to KILL INFO 25.01.2008 11:00:18 [ LS-00075 ; sov98_194; 17209 ] DialUpNASConnection update connection.. INFO 25.01.2008 11:00:18 [ LS-00075 ; sov98_194; 17209 ] No close calculate period.. INFO 25.01.2008 11:00:18 [ LS-00075 ; sov98_194; 17209 ] Set connection to KILL INFO 25.01.2008 11:00:18 [ LS-00075 ; sov98_194; 17209 ] DialUpNASConnection killing connection after UPDATE INFO 25.01.2008 11:00:18 [ LS-00075 ; sov98_194; 17209 ] DialUpNASConnection set STATUS=1 Попробую обновить радиус и поглядеть. 2. Возьмем другой лог радиуса, т.к. затирается в радиусе старые логи. Код: 24 22:13:24 Type=AUTHENTICATION_REQUEST Attributes: User-Name=yubil8_62 NAS-Identifier=nas.tehset.ru NAS-IP-Address=192.168.0.110 NAS-Port=14 Service-Type=2 Framed-Protocol=1 Calling-Station-Id=192.168.5.56 / \u40unknown\u41 / \u40unknown\u41 NAS-Port-Type=5 MS-CHAP2-Response=\u1\u0p9.\u9e\u12\u63i\u63O\u61\u3\u63\u174\u63s\u0\u0\u0\u0\u0\u0\u0\u0R\u37m\u63d0\u20\u63\u23\u31\u3.\u63\u21I\u63\u63\u63\u63\u63\u63\u91g\u63 MS-CHAP-Challenge=\u187\u30h\u25\u63\u38\u19\u63B\u63\u63A\u18O\u183\u40 24 22:13:24 Type=AUTHENTICATION_ACCEPT Process time:31 Attributes: Acct-Interim-Interval=20 Service-Type=2 Framed-Protocol=1 Framed-IP-Address=62.33.201.112 MS-MPPE-Send-Key=\u63\u0\u40\u37\u63\u63\u17\u63\u24\u63\u59\u63\u63\u63t\u63Yd\u63\u63\u13b\u63\u63\u5\u20\u63\u30\u1714\u63\u63\u36U MS-MPPE-Recv-Key=\u63\u0\u40\u63\u169#\u36\u61\u63\u63\u63\u63\u63\u59\u25I\u41ID\u63 DL\u17X\u6??«??? MS-CHAP2-Success=\u63S\u6102A19F1BF00D8A5756E14FEFF1FB5C6F5DFB36F1 MS-MPPE-Encryption-Types=4 MS-MPPE-Encryption-Policy=1 24 22:13:24 Type=ACCOUNTING_REQUEST Attributes: User-Name=yubil8_62 NAS-Identifier=nas.tehset.ru NAS-IP-Address=192.168.0.110 NAS-Port=14 Service-Type=2 Framed-Protocol=1 Framed-IP-Address=62.33.201.112 Acct-Status-Type=1 Acct-Session-Id=1187623-pptp014 Acct-Authentic=1 Acct-Link-Count=1 Acct-Multi-Session-Id=1187623-pptp014 NAS-Port-Type=5 Calling-Station-Id=192.168.5.56 / \u40unknown\u41 / \u40unknown\u41 25 00:01:27 Type=ACCOUNTING_REQUEST Attributes: User-Name=yubil8_62 NAS-Identifier=nas.tehset.ru NAS-IP-Address=192.168.0.110 NAS-Port=14 Service-Type=2 Framed-Protocol=1 Acct-Input-Octets=734115 Framed-IP-Address=62.33.201.112 Acct-Output-Octets=5729409 Acct-Status-Type=2 Acct-Session-Time=6485 Acct-Input-Packets=5541 Acct-Session-Id=1187623-pptp014 Acct-Authentic=1 Acct-Link-Count=1 Acct-Multi-Session-Id=1187623-pptp014 Acct-Terminate-Cause=10 Acct-Output-Packets=6602 Acct-Output-Gigawords=0 Acct-Input-Gigawords=0 NAS-Port-Type=5 В биллинге выглядит все так, как-будто клиент сам инициировал отключение. Логи NAS по этому соединению: Код: Jan 24 23:58:06 nas mpd: [pptp014] RADIUS: RadiusAddServer Adding 192.168.0.110 Jan 24 23:58:06 nas mpd: [pptp014] RADIUS: RadiusAccount: Sending accounting data (Type: 3) Jan 24 23:58:06 nas mpd: [pptp014] RADIUS: RadiusSendRequest: RAD_ACCOUNTING_RESPONSE for user yubil8_62 Jan 24 23:58:26 nas mpd: [pptp014] RADIUS: RadiusAcctUpdate: Sending Accounting Update Jan 24 23:58:26 nas mpd: [pptp014] RADIUS: RadiusAccount for: yubil8_62 Jan 24 23:58:26 nas mpd: [pptp014] RADIUS: RadiusAddServer Adding 192.168.0.110 Jan 24 23:58:26 nas mpd: [pptp014] RADIUS: RadiusAccount: Sending accounting data (Type: 3) Jan 24 23:58:26 nas mpd: [pptp014] RADIUS: RadiusSendRequest: RAD_ACCOUNTING_RESPONSE for user yubil8_62 Jan 24 23:58:46 nas mpd: [pptp014] RADIUS: RadiusAcctUpdate: Sending Accounting Update Jan 24 23:58:46 nas mpd: [pptp014] RADIUS: RadiusAccount for: yubil8_62 Jan 24 23:58:46 nas mpd: [pptp014] RADIUS: RadiusAddServer Adding 192.168.0.110 Jan 24 23:58:46 nas mpd: [pptp014] RADIUS: RadiusAccount: Sending accounting data (Type: 3) Jan 24 23:58:46 nas mpd: [pptp014] RADIUS: RadiusSendRequest: RAD_ACCOUNTING_RESPONSE for user yubil8_62 Jan 24 23:59:06 nas mpd: [pptp014] RADIUS: RadiusAcctUpdate: Sending Accounting Update Jan 24 23:59:06 nas mpd: [pptp014] RADIUS: RadiusAccount for: yubil8_62 Jan 24 23:59:06 nas mpd: [pptp014] RADIUS: RadiusAddServer Adding 192.168.0.110 Jan 24 23:59:06 nas mpd: [pptp014] RADIUS: RadiusAccount: Sending accounting data (Type: 3) Jan 24 23:59:06 nas mpd: [pptp014] RADIUS: RadiusSendRequest: RAD_ACCOUNTING_RESPONSE for user yubil8_62 Jan 24 23:59:26 nas mpd: [pptp014] RADIUS: RadiusAcctUpdate: Sending Accounting Update Jan 24 23:59:26 nas mpd: [pptp014] RADIUS: RadiusAccount for: yubil8_62 Jan 24 23:59:26 nas mpd: [pptp014] RADIUS: RadiusAddServer Adding 192.168.0.110 Jan 24 23:59:26 nas mpd: [pptp014] RADIUS: RadiusAccount: Sending accounting data (Type: 3) Jan 24 23:59:56 nas mpd: [pptp014] RADIUS: RadiusSendRequest: rad_send_request failed No valid RADIUS responses received А вот дальше, собственно корень проблемы, почему возникла недавно, не могу понять... Код: Jan 25 00:00:57 nas mpd: pptp13: no reply to EchoRequest after 60 sec Jan 25 00:00:57 nas mpd: pptp13: killing connection with 192.168.5.56:2943 Jan 25 00:00:57 nas mpd: pptp13-0: killing channel Jan 25 00:00:57 nas mpd: [pptp014] PPTP call terminated Jan 25 00:00:57 nas mpd: [pptp014] IFACE: Close event Jan 25 00:00:57 nas mpd: [pptp014] exec: /usr/local/etc/rc.d/downiface.sh ng14 inet yubil8_62 Jan 25 00:00:57 nas mpd: [pptp014] exec: /sbin/route delete 83.234.37.8 -iface lo0 Jan 25 00:00:57 nas mpd: [pptp014] exec: command returned 256 Jan 25 00:00:57 nas mpd: [pptp014] exec: /sbin/ifconfig ng14 down delete -link0 Jan 25 00:00:57 nas mpd: [pptp014] IPCP: Close event Jan 25 00:00:57 nas mpd: [pptp014] IPCP: state change Opened --> Closing Jan 25 00:00:57 nas mpd: [pptp014] IPCP: SendTerminateReq #236 Jan 25 00:00:57 nas mpd: [pptp014] error writing len 8 frame to bypass: Network is down Jan 25 00:00:57 nas mpd: [pptp014] IPCP: LayerDown Jan 25 00:00:57 nas mpd: [pptp014] IFACE: Down event Jan 25 00:00:57 nas mpd: [pptp014] IFACE: Close event В общем, попробую увеличить параметр set link keep-alive 10 60, может как-то изменится, но думаю BGRadius тут ни при чем. 4. Логи радиуса: Первая сессия: Код: 05 11:21:59 Type=AUTHENTICATION_REQUEST Attributes: User-Name=stepnoy NAS-Identifier=amber.region19.ru CHAP-Password=\u1\u63\u63\u63EJ\u63K\u167\u174P\u6P_X\u63c NAS-Port=9 Service-Type=2 Framed-Protocol=1 Calling-Station-Id=008048495e5e NAS-Port-Type=5 CHAP-Challenge=\u187\u30h\u63 \u63\u60\u63\u63\u63\u63\u39\u63\u63\u63\u63\u63_\u63X\u9\u63\u125c\u63 05 11:21:59 Type=AUTHENTICATION_ACCEPT Process time:53 Attributes: Acct-Interim-Interval=20 Service-Type=2 Framed-Protocol=1 Framed-IP-Address=83.234.37.196 05 11:21:59 Type=ACCOUNTING_REQUEST Attributes: User-Name=stepnoy NAS-Identifier=amber.region19.ru NAS-Port=9 Service-Type=2 Framed-Protocol=1 Framed-IP-Address=83.234.37.196 Acct-Status-Type=1 Acct-Session-Id=9506919-pppoe9 Acct-Authentic=1 Acct-Link-Count=1 Acct-Multi-Session-Id=9506919-pppoe9 NAS-Port-Type=5 Calling-Station-Id=008048495e5e 05 11:23:20 Type=ACCOUNTING_REQUEST Attributes: User-Name=stepnoy NAS-Identifier=amber.region19.ru NAS-Port=9 Service-Type=2 Framed-Protocol=1 Acct-Input-Octets=314395 Framed-IP-Address=83.234.37.196 Acct-Output-Octets=128160 Acct-Status-Type=2 Acct-Session-Time=369 Acct-Input-Packets=703 Acct-Session-Id=9506919-pppoe9 Acct-Authentic=1 Acct-Link-Count=1 Acct-Multi-Session-Id=9506919-pppoe9 Acct-Terminate-Cause=1 Acct-Output-Packets=813 Acct-Output-Gigawords=0 Acct-Input-Gigawords=0 NAS-Port-Type=5 Calling-Station-Id=008048495e5e Вторая сессия: Код: 05 11:24:44 Type=AUTHENTICATION_REQUEST Attributes: User-Name=stepnoy NAS-Identifier=amber.region19.ru CHAP-Password=\u1\u0\u28\u63mU\u94µ\u61\u63\u63\u63\u9\u63\u63\u63H NAS-Port=12 Service-Type=2 Framed-Protocol=1 Calling-Station-Id=008048495e5e NAS-Port-Type=5 CHAP-Challenge=\u187\u30h\u63\u63\u63\u124g!\u166\u63\u63eY\u63\u634\u173\u1666\u176\u63\u1e\u171\u63\u169\u63w\u63\u63\u63\u63\u22v\u93\u4\u63\u63\u37\u63\u63d\u63\u8U\u127 05 11:24:44 Type=AUTHENTICATION_ACCEPT Process time:34 Attributes: Acct-Interim-Interval=20 Service-Type=2 Framed-Protocol=1 Framed-IP-Address=83.234.37.196 05 11:24:44 Type=ACCOUNTING_REQUEST Attributes: User-Name=stepnoy NAS-Identifier=amber.region19.ru NAS-Port=12 Service-Type=2 Framed-Protocol=1 Framed-IP-Address=83.234.37.196 Acct-Status-Type=1 Acct-Session-Id=9507084-pppoe12 Acct-Authentic=1 Acct-Link-Count=1 Acct-Multi-Session-Id=9507084-pppoe12 NAS-Port-Type=5 Calling-Station-Id=008048495e5e 05 11:57:45 Type=ACCOUNTING_REQUEST Attributes: User-Name=stepnoy NAS-Identifier=amber.region19.ru NAS-Port=12 Service-Type=2 Framed-Protocol=1 Acct-Input-Octets=4293290 Framed-IP-Address=83.234.37.196 Acct-Output-Octets=1952060 Acct-Status-Type=2 Acct-Session-Time=69426 Acct-Input-Packets=6606 Acct-Session-Id=9507084-pppoe12 Acct-Authentic=1 Acct-Link-Count=1 Acct-Multi-Session-Id=9507084-pppoe12 Acct-Terminate-Cause=3 Acct-Output-Packets=9274 Acct-Output-Gigawords=0 Acct-Input-Gigawords=0 NAS-Port-Type=5 Calling-Station-Id=008048495e5e Третья сессия: Код: 05 11:55:39 Type=AUTHENTICATION_REQUEST Attributes: User-Name=stepnoy NAS-Identifier=amber.region19.ru CHAP-Password= ?\u22\u166?F\u3?\u26?A??F?0 NAS-Port=9 Service-Type=2 Framed-Protocol=1 Calling-Station-Id=008048495e5e NAS-Port-Type=5 CHAP-Challenge=\u187\u30hrO\u63\u22\u24\u21w\u63\u63D\u63\u63\u63\u183\u63xU\u63\u63\u63\u59\u37\u63\u63\u63 05 11:55:39 Type=AUTHENTICATION_ACCEPT Process time:42 Attributes: Acct-Interim-Interval=20 Service-Type=2 Framed-Protocol=1 Framed-IP-Address=83.234.37.196 05 11:55:39 Type=ACCOUNTING_REQUEST Attributes: User-Name=stepnoy NAS-Identifier=amber.region19.ru NAS-Port=9 Service-Type=2 Framed-Protocol=1 Framed-IP-Address=83.234.37.196 Acct-Status-Type=1 Acct-Session-Id=9508939-pppoe9 Acct-Authentic=1 Acct-Link-Count=1 Acct-Multi-Session-Id=9508939-pppoe9 NAS-Port-Type=5 Calling-Station-Id=008048495e5e 05 12:38:44 Type=ACCOUNTING_REQUEST Attributes: User-Name=stepnoy NAS-Identifier=amber.region19.ru NAS-Port=9 Service-Type=2 Framed-Protocol=1 Acct-Input-Octets=2528311 Framed-IP-Address=83.234.37.196 Acct-Output-Octets=20813037 Acct-Status-Type=2 Acct-Session-Time=4524 Acct-Input-Packets=21151 Acct-Session-Id=9508939-pppoe9 Acct-Authentic=1 Acct-Link-Count=1 Acct-Multi-Session-Id=9508939-pppoe9 Acct-Terminate-Cause=1 Acct-Output-Packets=26080 Acct-Output-Gigawords=0 Acct-Input-Gigawords=0 NAS-Port-Type=5 Calling-Station-Id=008048495e5e В биллинге выглядит вот так: Код: stepnoy 2579 05.01.2008 11:21:59 05.01.2008 11:28:08 00:06:09 [369] 0.23868 008048495e5e / * 70090 / 104284 / 0 / 0 / 0 / 0 / 0 / 0 stepnoy 2583 05.01.2008 11:24:44 06.01.2008 06:41:50 19:17:06 [69426] 9.78077 008048495e5e / * 1598391 / 4273294 / 0 / 0 / 8892 / 8736 / 0 / 0 stepnoy 2611 05.01.2008 11:55:39 05.01.2008 13:11:03 01:15:24 [4524] 0.54505 008048495e5e / * 179710 / 238140 / 0 / 0 / 3432 / 1872 / 0 / 0 5. Другую сессию\лог возьмем: Код: 24 14:21:10 Type=AUTHENTICATION_REQUEST Attributes: User-Name=stepnoy NAS-Identifier=amber.region19.ru CHAP-Password=\u11 y\u63\u63\u63\u63\u63\u63\u63\u63qbb\u63V NAS-Port=25 Service-Type=2 Framed-Protocol=1 Calling-Station-Id=008048495e5e NAS-Port-Type=5 CHAP-Challenge=\u187\u30h_WI\u63Vj\u63\\u9\u40J\u7n\u63\u173y\u63\u40\u63w.*\u19\u63\u21\u63\u63\u63c\u7\u63\u63\u94\u14\u63\u63y 24 14:21:10 Type=AUTHENTICATION_ACCEPT Process time:185 Attributes: Acct-Interim-Interval=20 Service-Type=2 Framed-Protocol=1 Framed-IP-Address=83.234.37.196 24 14:21:10 Type=ACCOUNTING_REQUEST Attributes: User-Name=stepnoy NAS-Identifier=amber.region19.ru NAS-Port=25 Service-Type=2 Framed-Protocol=1 Framed-IP-Address=83.234.37.196 Acct-Status-Type=1 Acct-Session-Id=1159270-pppoe25 Acct-Authentic=1 Acct-Link-Count=1 Acct-Multi-Session-Id=1159270-pppoe25 NAS-Port-Type=5 Calling-Station-Id=008048495e5e 25 09:12:12 Type=ACCOUNTING_REQUEST Attributes: User-Name=stepnoy NAS-Identifier=amber.region19.ru NAS-Port=25 Service-Type=2 Framed-Protocol=1 Acct-Input-Octets=80738374 Framed-IP-Address=83.234.37.196 Acct-Output-Octets=351797828 Acct-Status-Type=2 Acct-Session-Time=155104 Acct-Input-Packets=329425 Acct-Session-Id=1159270-pppoe25 Acct-Authentic=1 Acct-Link-Count=1 Acct-Multi-Session-Id=1159270-pppoe25 Acct-Terminate-Cause=10 Acct-Output-Packets=389902 Acct-Output-Gigawords=0 Acct-Input-Gigawords=0 NAS-Port-Type=5 Calling-Station-Id=008048495e5e Для него connection.log: Код: INFO 24.01.2008 14:21:10 [ LS-00950; stepnoy; 70820 ] DialUpNASConnection startConnection mode=1 INFO 24.01.2008 14:21:10 [ LS-00950; stepnoy; 70820 ] DialUpNASConnection set STATUS=1 INFO 24.01.2008 14:21:50 [ LS-00950; stepnoy; 70820 ] DialUpNASConnection update connection.. INFO 24.01.2008 14:21:50 [ LS-00950; stepnoy; 70820 ] DialUpNASConnection set STATUS=1 ###### Здесь идут апдейты сессии (чтобы все не писать) ######## INFO 24.01.2008 19:05:31 [ LS-00950; stepnoy; 70820 ] Set status SUSPENDED on UpdateWaitSetter, time after last update: 902 INFO 24.01.2008 19:05:31 [ LS-00950; stepnoy; 70820 ] DialUpNASConnection set STATUS=2 INFO 24.01.2008 20:05:30 [ LS-00950; stepnoy; 70820 ] DialUpNASConnection update connection.. INFO 24.01.2008 20:05:30 [ LS-00950; stepnoy; 70820 ] DialUpNASConnection set STATUS=1 INFO 24.01.2008 20:20:32 [ LS-00950; stepnoy; 70820 ] Set status SUSPENDED on UpdateWaitSetter, time after last update: 901 INFO 24.01.2008 20:20:32 [ LS-00950; stepnoy; 70820 ] DialUpNASConnection set STATUS=2 ###### Здесь идут апдейты сессии (чтобы все не писать) ####### INFO 25.01.2008 00:12:17 [ LS-00950; stepnoy; 70820 ] DialUpNASConnection update connection.. INFO 25.01.2008 00:12:17 [ LS-00950; stepnoy; 70820 ] DialUpNASConnection set STATUS=1 INFO 25.01.2008 00:13:37 [ LS-00950; stepnoy; 70820 ] DialUpNASConnection update connection.. INFO 25.01.2008 00:13:37 [ LS-00950; stepnoy; 70820 ] DialUpNASConnection set STATUS=1 ###### Здесь идут апдейты сессии (чтобы все не писать) ####### INFO 25.01.2008 09:09:33 [ LS-00950; stepnoy; 70820 ] DialUpNASConnection update connection.. INFO 25.01.2008 09:09:33 [ LS-00950; stepnoy; 70820 ] DialUpNASConnection set STATUS=1 INFO 25.01.2008 09:12:09 [ LS-00950; stepnoy; 70820 ] Set connection to KILL INFO 25.01.2008 09:12:12 [ LS-00950; stepnoy; 70820 ] sendKillRequest INFO 25.01.2008 09:12:12 [ LS-00950; stepnoy; 70820 ] SNMP reset request: set 1.3.6.1.4.1.2021.255.1 i 25 INFO 25.01.2008 09:12:12 [ LS-00950; stepnoy; 70820 ] DialUpNASConnection stoppingConnection INFO 25.01.2008 09:12:12 [ LS-00950; stepnoy; 70820 ] DialUpNASConnection has stop Packet => true INFO 25.01.2008 09:12:12 [ LS-00950; stepnoy; 70820 ] DialUpNASConnection set STATUS=3 INFO 25.01.2008 09:12:12 [ LS-00950; stepnoy; 70820 ] DialUpNASConnection sessionTime => 155104 INFO 25.01.2008 09:12:17 [ LS-00950; stepnoy; 70820 ] sendKillRequest INFO 25.01.2008 09:12:17 [ LS-00950; stepnoy; 70820 ] SNMP reset request: set 1.3.6.1.4.1.2021.255.1 i 25 INFO 25.01.2008 09:12:17 [ LS-00950; stepnoy; 37863 ] DialUpNASConnection startConnection mode=1 INFO 25.01.2008 09:12:18 [ LS-00950; stepnoy; 37863 ] DialUpNASConnection set STATUS=1 INFO 25.01.2008 09:12:22 [ LS-00950; stepnoy; 70820 ] sendKillRequest INFO 25.01.2008 09:12:22 [ LS-00950; stepnoy; 70820 ] SNMP reset request: set 1.3.6.1.4.1.2021.255.1 i 25 INFO 25.01.2008 09:12:27 [ LS-00950; stepnoy; 70820 ] sendKillRequest INFO 25.01.2008 09:12:27 [ LS-00950; stepnoy; 70820 ] Set connection to KILL INFO 25.01.2008 09:12:57 [ LS-00950; stepnoy; 37863 ] DialUpNASConnection update connection.. INFO 25.01.2008 09:12:57 [ LS-00950; stepnoy; 37863 ] DialUpNASConnection set STATUS=1 ######## Последняя запись на сегодня ####### INFO 25.01.2008 11:10:21 [ LS-00950; stepnoy; 37863 ] DialUpNASConnection set STATUS=1 INFO 25.01.2008 11:12:21 [ LS-00950; stepnoy; 37863 ] DialUpNASConnection update connection.. INFO 25.01.2008 11:12:21 [ LS-00950; stepnoy; 37863 ] DialUpNASConnection set STATUS=1 В биллинге выглядит вот так: Код: stepnoy 21015 24.01.2008 14:21:10 26.01.2008 09:26:14 43:05:04 [155104] 0.00000 008048495e5e / * 0 / 0 / 0 / 0 / 0 / 0 / 0 / 0
Netflow в дебаг переведу, посмотрю, что получится. Логи наверное из дебага тоже вытащу, чтоб посмотреть. |
|
| Автор: | S [ 25 янв 2008, 14:24 ] |
| Заголовок сообщения: | |
Радиус-лог работающей сессии. Код: 25 13:08:09
Type=AUTHENTICATION_REQUEST Attributes: User-Name=pogrugenie NAS-Identifier=amber.region19.ru CHAP-Password=\u1#9vT\u160I\u63\u61-+\u63\u160j\\u63a NAS-Port=31 Service-Type=2 Framed-Protocol=1 Calling-Station-Id=00804840e314 NAS-Port-Type=5 CHAP-Challenge=\u187\u30h\u40Y\u63a\u63G\u63\u31\u63\u41\u63\u63\u63M\u63\u63\u63\u63\u635\u632\u34@\u34\u31\u63g\u63\u63!\u29V\u6\u1278Mv 25 13:08:10 Type=AUTHENTICATION_ACCEPT Process time:48 Attributes: Acct-Interim-Interval=20 Service-Type=2 Framed-Protocol=1 Framed-IP-Address=83.234.37.193 25 13:08:10 Type=ACCOUNTING_REQUEST Attributes: User-Name=pogrugenie NAS-Identifier=amber.region19.ru NAS-Port=31 Service-Type=2 Framed-Protocol=1 Framed-IP-Address=83.234.37.193 Acct-Status-Type=1 Acct-Session-Id=1241289-pppoe31 Acct-Authentic=1 Acct-Link-Count=1 Acct-Multi-Session-Id=1241289-pppoe31 NAS-Port-Type=5 Calling-Station-Id=00804840e314 IP-адрес работает, по крайней мере пингуется. Netflow в радиусе установлен в дебаге, этот ip не появился. Прикольно конечно, но в чем баг тут...ipcad? У кого такая же проблема была, в чем решение сией проблемы? |
|
| Автор: | S [ 25 янв 2008, 16:32 ] |
| Заголовок сообщения: | |
Обновил BGRadius. До и после обновления появилось: WARN 25.01.2008 17:20:59 Wating for free Thread.. WARN 25.01.2008 17:20:59 Wating for free Thread.. Чего это такое. Ребутал только радиус, сам биллинг не трогал и NAS тоже. Щас переведу радиус в дебаг и погляжу. |
|
| Автор: | Администратор [ 04 фев 2008, 15:00 ] |
| Заголовок сообщения: | |
Сообщение это означает что радиус сервер не успевает ответить на запросы.. Это не гуд. Возможная причина - занята БД. Поставьте последние обновления, в dialup модуле была проблема с очень тяжелым запросом при выборке отчета по сессиям, может это он. По оставшимся проблемам предлагаю схему поочередного разбора, а то тяжело ориентироваться. Обозначьте одну проблему, будем разбираться. |
|
| Автор: | S [ 05 фев 2008, 09:22 ] |
| Заголовок сообщения: | |
Хорошо, модуль обновлю, посмотрим результат. Остается только одна проблема, наложение времени, при отчетах у клиента. Самое интересное, что в RADIUS-логе, время корректное. Куда копать, где проверить, чтоб отчеты корректно выдавались, люди нервничают 
|
|
| Автор: | Администратор [ 05 фев 2008, 12:15 ] |
| Заголовок сообщения: | |
Т.е. Acct-Session-Time имеет верную длительность, но при этом окончание одной сессии выходит за начало последующей? Может Start пакет приходит с задержкой, это бы все объяснило.. |
|
| Автор: | S [ 05 фев 2008, 12:43 ] |
| Заголовок сообщения: | |
Как посмотреть с задержкой или нет прилетает стартовый пакет? connection.log для сесии я выложил, больше нету. |
|
| Автор: | Администратор [ 05 фев 2008, 13:17 ] |
| Заголовок сообщения: | |
Можете вытащить из radius.log пакеты для 2х пересекающихся сессий? |
|
| Автор: | S [ 05 фев 2008, 13:31 ] |
| Заголовок сообщения: | |
Это имеете ввиду? Сессии: Код: stepnoy 7324 10.01.2008 14:16:07 11.01.2008 14:44:12 24:28:05 [88085] 10.27172 008048495e5e / * 4487793 / 617861 / 0 / 0 / 1092 / 1092 / 0 / 0 stepnoy 7331 10.01.2008 14:23:42 10.01.2008 16:28:02 02:04:20 [7460] 165.18436 008048495e5e / * 72170252 / 8191352 / 78 / 0 / 8892 / 8580 / 0 / 0 Вот явное пересечение. Логи RADIUS: Первая сессия: Код: 10 14:16:07 Type=AUTHENTICATION_REQUEST Attributes: User-Name=stepnoy NAS-Identifier=amber.region19.ru CHAP-Password=\u1z\u93\u63\u63\u63\u63\u19/\u63n\u63\u172\u169K\u36 NAS-Port=27 Service-Type=2 Framed-Protocol=1 Calling-Station-Id=008048495e5e NAS-Port-Type=5 CHAP-Challenge=\u187\u30hb\u63\u63\u63Q\u9\u6\u36\u127\u20t\u63\u173 10 14:16:07 Type=AUTHENTICATION_ACCEPT Process time:37 Attributes: Acct-Interim-Interval=20 Service-Type=2 Framed-Protocol=1 Framed-IP-Address=83.234.37.196 10 14:16:07 Type=ACCOUNTING_REQUEST Attributes: User-Name=stepnoy NAS-Identifier=amber.region19.ru NAS-Port=27 Service-Type=2 Framed-Protocol=1 Framed-IP-Address=83.234.37.196 Acct-Status-Type=1 Acct-Session-Id=9949367-pppoe27 Acct-Authentic=1 Acct-Link-Count=1 Acct-Multi-Session-Id=9949367-pppoe27 NAS-Port-Type=5 Calling-Station-Id=008048495e5e 10 14:22:25 Type=ACCOUNTING_REQUEST Attributes: User-Name=stepnoy NAS-Identifier=amber.region19.ru NAS-Port=27 Service-Type=2 Framed-Protocol=1 Acct-Input-Octets=677185 Framed-IP-Address=83.234.37.196 Acct-Output-Octets=4886785 Acct-Status-Type=2 Acct-Session-Time=88085 Acct-Input-Packets=5451 Acct-Session-Id=9949367-pppoe27 Acct-Authentic=1 Acct-Link-Count=1 Acct-Multi-Session-Id=9949367-pppoe27 Acct-Terminate-Cause=1 Acct-Output-Packets=6427 Acct-Output-Gigawords=0 Acct-Input-Gigawords=0 NAS-Port-Type=5 Calling-Station-Id=008048495e5e Вторая сессия: Код: 10 14:23:42
Type=AUTHENTICATION_REQUEST Attributes: User-Name=stepnoy NAS-Identifier=amber.region19.ru CHAP-Password=\u1\u63\u63\u123\u63\u63\u63\u63Kg\u63V\u41Aµ\u63\u63 NAS-Port=5 Service-Type=2 Framed-Protocol=1 Calling-Station-Id=008048495e5e NAS-Port-Type=5 CHAP-Challenge=\u187\u30h\u21\u63\u63V0\u63\u4\u63\u63\u63\u91\u21De\u63µ\u63\u63\u40\u26\u63B\u63\u19yA\u63\u63+\u63\u63A\\u26\u63\u63\u63\u63\u63 10 14:23:42 Type=AUTHENTICATION_ACCEPT Process time:37 Attributes: Acct-Interim-Interval=20 Service-Type=2 Framed-Protocol=1 Framed-IP-Address=83.234.37.196 10 14:23:42 Type=ACCOUNTING_REQUEST Attributes: User-Name=stepnoy NAS-Identifier=amber.region19.ru NAS-Port=5 Service-Type=2 Framed-Protocol=1 Framed-IP-Address=83.234.37.196 Acct-Status-Type=1 Acct-Session-Id=9949822-pppoe5 Acct-Authentic=1 Acct-Link-Count=1 Acct-Multi-Session-Id=9949822-pppoe5 NAS-Port-Type=5 Calling-Station-Id=008048495e5e 10 15:57:53 Type=ACCOUNTING_REQUEST Attributes: User-Name=stepnoy NAS-Identifier=amber.region19.ru NAS-Port=5 Service-Type=2 Framed-Protocol=1 Acct-Input-Octets=8287188 Framed-IP-Address=83.234.37.196 Acct-Output-Octets=72701169 Acct-Status-Type=2 Acct-Session-Time=7460 Acct-Input-Packets=67809 Acct-Session-Id=9949822-pppoe5 Acct-Authentic=1 Acct-Link-Count=1 Acct-Multi-Session-Id=9949822-pppoe5 Acct-Terminate-Cause=1 Acct-Output-Packets=83040 Acct-Output-Gigawords=0 Acct-Input-Gigawords=0 NAS-Port-Type=5 Calling-Station-Id=008048495e5e По RADIUS все четко. Но вот в отображении. |
|
| Автор: | Администратор [ 05 фев 2008, 14:19 ] |
| Заголовок сообщения: | |
Код: 10 14:16:07 Type=ACCOUNTING_REQUEST Attributes: User-Name=stepnoy NAS-Identifier=amber.region19.ru NAS-Port=27 Service-Type=2 Framed-Protocol=1 Framed-IP-Address=83.234.37.196 Acct-Status-Type=1 Acct-Session-Id=9949367-pppoe27 Acct-Authentic=1 Acct-Link-Count=1 Acct-Multi-Session-Id=9949367-pppoe27 NAS-Port-Type=5 Calling-Station-Id=008048495e5e 10 14:22:25 Type=ACCOUNTING_REQUEST Attributes: User-Name=stepnoy NAS-Identifier=amber.region19.ru NAS-Port=27 Service-Type=2 Framed-Protocol=1 Acct-Input-Octets=677185 Framed-IP-Address=83.234.37.196 Acct-Output-Octets=4886785 Acct-Status-Type=2 Acct-Session-Time=88085 Acct-Input-Packets=5451 Acct-Session-Id=9949367-pppoe27 Acct-Authentic=1 Acct-Link-Count=1 Acct-Multi-Session-Id=9949367-pppoe27 Acct-Terminate-Cause=1 Acct-Output-Packets=6427 Acct-Output-Gigawords=0 Acct-Input-Gigawords=0 NAS-Port-Type=5 Calling-Station-Id=008048495e5e Посмотрите по временным меткам Start и Stop пакета получаем длительность сессии (14:22:25 - 14:16:07) = 6 мин. 18 сек. = 378 сек. А в атрибуте идет: Код: Acct-Session-Time=88085 Может вам поставить опцию в конфигурации модуля: Код: ignore.acct.session.time=1 , тогда RADIUS будет игнорировать этот атрибут и сам считать длительность сессии.
|
|
| Автор: | S [ 05 фев 2008, 14:42 ] |
| Заголовок сообщения: | |
Выставил, подождем результатов. |
|
| Автор: | S [ 06 фев 2008, 16:40 ] |
| Заголовок сообщения: | |
Так. Пока отодвинем эту проблему. Возникла другая. NAS - mpd 3.18 Людей откидывает около 00:00. Выглядит со стороны BGRadius как отключение абонента самостоятельно. connection.log смотреть нет смысла. В логах RADIUS для каждой такой сессии есть одна отличительная особенность: Acct-Terminate-Cause=10 По RFC это Код: NAS Request - NAS ended session for a non-error reason not otherwise listed here. Возникает вопрос, что это с NAS. В логах NAS все выглядит подозрительно: Код: Jan 24 23:58:06 nas mpd: [pptp014] RADIUS: RadiusAddServer Adding 192.168.0.110
Jan 24 23:58:06 nas mpd: [pptp014] RADIUS: RadiusAccount: Sending accounting data (Type: 3) Jan 24 23:58:06 nas mpd: [pptp014] RADIUS: RadiusSendRequest: RAD_ACCOUNTING_RESPONSE for user yubil8_62 Jan 24 23:58:26 nas mpd: [pptp014] RADIUS: RadiusAcctUpdate: Sending Accounting Update Jan 24 23:58:26 nas mpd: [pptp014] RADIUS: RadiusAccount for: yubil8_62 Jan 24 23:58:26 nas mpd: [pptp014] RADIUS: RadiusAddServer Adding 192.168.0.110 Jan 24 23:58:26 nas mpd: [pptp014] RADIUS: RadiusAccount: Sending accounting data (Type: 3) Jan 24 23:58:26 nas mpd: [pptp014] RADIUS: RadiusSendRequest: RAD_ACCOUNTING_RESPONSE for user yubil8_62 Jan 24 23:58:46 nas mpd: [pptp014] RADIUS: RadiusAcctUpdate: Sending Accounting Update Jan 24 23:58:46 nas mpd: [pptp014] RADIUS: RadiusAccount for: yubil8_62 Jan 24 23:58:46 nas mpd: [pptp014] RADIUS: RadiusAddServer Adding 192.168.0.110 Jan 24 23:58:46 nas mpd: [pptp014] RADIUS: RadiusAccount: Sending accounting data (Type: 3) Jan 24 23:58:46 nas mpd: [pptp014] RADIUS: RadiusSendRequest: RAD_ACCOUNTING_RESPONSE for user yubil8_62 Jan 24 23:59:06 nas mpd: [pptp014] RADIUS: RadiusAcctUpdate: Sending Accounting Update Jan 24 23:59:06 nas mpd: [pptp014] RADIUS: RadiusAccount for: yubil8_62 Jan 24 23:59:06 nas mpd: [pptp014] RADIUS: RadiusAddServer Adding 192.168.0.110 Jan 24 23:59:06 nas mpd: [pptp014] RADIUS: RadiusAccount: Sending accounting data (Type: 3) Jan 24 23:59:06 nas mpd: [pptp014] RADIUS: RadiusSendRequest: RAD_ACCOUNTING_RESPONSE for user yubil8_62 Jan 24 23:59:26 nas mpd: [pptp014] RADIUS: RadiusAcctUpdate: Sending Accounting Update Jan 24 23:59:26 nas mpd: [pptp014] RADIUS: RadiusAccount for: yubil8_62 Jan 24 23:59:26 nas mpd: [pptp014] RADIUS: RadiusAddServer Adding 192.168.0.110 Jan 24 23:59:26 nas mpd: [pptp014] RADIUS: RadiusAccount: Sending accounting data (Type: 3) Jan 24 23:59:56 nas mpd: [pptp014] RADIUS: RadiusSendRequest: rad_send_request failed No valid RADIUS responses received -------------- Jan 25 00:00:57 nas mpd: pptp13: no reply to EchoRequest after 60 sec Jan 25 00:00:57 nas mpd: pptp13: killing connection with 192.168.5.56:2943 Jan 25 00:00:57 nas mpd: pptp13-0: killing channel Jan 25 00:00:57 nas mpd: [pptp014] PPTP call terminated Jan 25 00:00:57 nas mpd: [pptp014] IFACE: Close event Jan 25 00:00:57 nas mpd: [pptp014] exec: /usr/local/etc/rc.d/downiface.sh ng14 inet yubil8_62 Jan 25 00:00:57 nas mpd: [pptp014] exec: /sbin/route delete 83.234.37.8 -iface lo0 Jan 25 00:00:57 nas mpd: [pptp014] exec: command returned 256 Jan 25 00:00:57 nas mpd: [pptp014] exec: /sbin/ifconfig ng14 down delete -link0 Jan 25 00:00:57 nas mpd: [pptp014] IPCP: Close event Jan 25 00:00:57 nas mpd: [pptp014] IPCP: state change Opened --> Closing Jan 25 00:00:57 nas mpd: [pptp014] IPCP: SendTerminateReq #236 Jan 25 00:00:57 nas mpd: [pptp014] error writing len 8 frame to bypass: Network is down Jan 25 00:00:57 nas mpd: [pptp014] IPCP: LayerDown Jan 25 00:00:57 nas mpd: [pptp014] IFACE: Down event Jan 25 00:00:57 nas mpd: [pptp014] IFACE: Close event Я конечно посмотрю, попытаюсь найти связку к этой проблеме, что может вызывать такую проблему. Но если вы подскажете, то буду просто рад
|
|
| Автор: | Администратор [ 06 фев 2008, 17:41 ] |
| Заголовок сообщения: | |
Код: Jan 25 00:00:57 nas mpd: pptp13: no reply to EchoRequest after 60 sec
Jan 25 00:00:57 nas mpd: pptp13: killing connection with 192.168.5.56:2943 Клиент не ответил на эхо пакет МПД. Возможная причина - у клиента стоит файрвол, который режет все входящие обращения. Ему нужно добавить ВПН сервер в список доверенных адресов. |
|
| Автор: | S [ 07 фев 2008, 08:04 ] |
| Заголовок сообщения: | |
В том и дело, что если бы что-то рубило пакеты, то рубило бы постоянно, т.к. всяко эхо-запросы идут не только в 00:00. Дело в смене времени, точнее, в счене суток. Пока не пойму куда копать, но понять очень хочется. В биллинге нет ничего, что связано со сменой суток, например, обрубание сессий или т.п., возможно какой-то атрибут передается на зпрос к NAS, а тот не отрабатывает или как-то не так отрабатывает. |
|
| Автор: | S [ 07 фев 2008, 12:50 ] |
| Заголовок сообщения: | |
Сегодня было замечено, что дропнуло около 7 клиентов, висящих на этом NAS, однако, не всех. С той же самой причиной. Становится уже интересно. |
|
| Автор: | Администратор [ 08 фев 2008, 12:13 ] |
| Заголовок сообщения: | |
Все запросы на сброс биллинг логирует в connection.log. Для полной достоверности - вы можете запустить tcpdump с мониторингом 161 порта и поизучать запросы, шедшие от биллинга в проблемные моменты. |
|
| Автор: | S [ 18 мар 2008, 16:47 ] |
| Заголовок сообщения: | |
Опять назрело
mp 3.18, BGBilling 4.3. Кстати, имеет смысл ставить mpd4\5? Рекомендуете? Вот мой конф с VPN-сервера: Код: default: load client0 load client1 load client2 load client3 load client4 load client5 load client6 --------------------- client60: new -i ng60 pptp060 pptp060 load client_standard client_standard: set ipcp ranges VPN_SERVER_IP CLIENTS_RANGE set pptp enable incoming set pptp disable originate set iface disable on-demand set iface enable proxy-arp set iface idle 2400 set iface enable tcpmssfix set bundle enable multilink set link no acfcomp protocomp set iface up-script /usr/local/etc/rc.d/upiface.sh set iface down-script /usr/local/etc/rc.d/downiface.sh set link no pap chap set link no chap-msv1 set link enable chap-msv2 set link mtu 1360 set link mru 1360 set link keep-alive 60 180 set ipcp no vjcomp set ipcp dns DNS set bundle no compression set ccp no mppc set ccp no mpp-e40 set ccp no mpp-e128 set ccp no mpp-stateless # RADIUS set radius retries 3 set radius timeout 10 set radius server 192.168.0.110 secret 1812 1813 set radius acct-update 5 set radius me 192.168.0.110 set ipcp enable radius-ip set bundle enable radius-acct set bundle enable radius-auth set radius update-limit-in 100000 set radius update-limit-out 100000 Подскажите, оно верное, что поправить? Я ваш конф глядел, но там для mpd4\5 скорее всего. Требуется помощь, т.к. уже отрубает частенько. И вот эта ошибка прет тоже постоянно: Код: RadiusSendRequest: rad_send_request failed No valid RADIUS responses received
|
|
| Автор: | Администратор [ 18 мар 2008, 16:51 ] |
| Заголовок сообщения: | |
А что назрело? В чем проблема? |
|
| Автор: | S [ 18 мар 2008, 16:59 ] |
| Заголовок сообщения: | |
Отключение абонентов либо в 00:00, либо в 12:00, либо вообще просто по причине в логах радиуса: Код: Acct-Terminate-Cause=10
Настораживает стабильность такого отключения. То есть, может разом скинуть человек 10. У меня два NAS, один РРРоЕ, другой VPN. Стал замечать сперва что в 00:00 (+\- несколько минут) отбрасывает скопом, но не всех, а выборочно. Не могу найти между ними связь, но в логах выдает, что не было ответа радиуса, дропаем значит. По поводу конфа - он не вызывает подозрений? |
|
| Автор: | Администратор [ 19 мар 2008, 13:21 ] |
| Заголовок сообщения: | |
Попробуйте перейти на мпд4. Цитата: RadiusSendRequest: rad_send_request failed No valid RADIUS responses received - эта ошибка не должна сбрасывать, как я понимаю, не был получен ответ авторизации от радиуса вовремя.
Посмотрите connection.log по сброшенным соединениям (можете выбрать с помощью grep), есть ли сигналы на сброс от биллинга. |
|
| Автор: | S [ 24 мар 2008, 12:44 ] |
| Заголовок сообщения: | |
Я конечно же буду пересаживаться на mpd4, но пока что проблемы по отключению продолжаются. Сегодня такая картина (сделал grep "has stop Packet => true"): Код: INFO 24.03.2008 12:13:29 [ LS-00844; evroset; 38123 ] DialUpNASConnection has stop Packet => true INFO 24.03.2008 12:13:29 [ LS-01110; riteil; 49030 ] DialUpNASConnection has stop Packet => true INFO 24.03.2008 12:13:29 [ LS-01004; energosbit_abakan; 24784 ] DialUpNASConnection has stop Packet => true INFO 24.03.2008 12:13:29 [ LS-00912; rgs_sibir_2; 29577 ] DialUpNASConnection has stop Packet => true INFO 24.03.2008 12:13:29 [ LS-00859; energo; 91332 ] DialUpNASConnection has stop Packet => true INFO 24.03.2008 12:13:29 [ LS-00867; mongol; 94783 ] DialUpNASConnection has stop Packet => true INFO 24.03.2008 12:13:29 [ LS-00850; sibnedra; 81853 ] DialUpNASConnection has stop Packet => true INFO 24.03.2008 12:13:29 [ LS-00866; apteka2; 62894 ] DialUpNASConnection has stop Packet => true INFO 24.03.2008 12:13:29 [ LS-00081; chap51_65; 95304 ] DialUpNASConnection has stop Packet => true INFO 24.03.2008 12:13:29 [ LS-01127; htk; 78695 ] DialUpNASConnection has stop Packet => true INFO 24.03.2008 12:13:29 [ LS-00652; sov78_33; 47535 ] DialUpNASConnection has stop Packet => true INFO 24.03.2008 12:13:29 [ LS-00873; stekloplast; 86522 ] DialUpNASConnection has stop Packet => true INFO 24.03.2008 12:13:30 [ LS-00346; kosmo19a_102; 57396 ] DialUpNASConnection has stop Packet => true INFO 24.03.2008 12:13:30 [ LS-00212; gork2_109; 44800 ] DialUpNASConnection has stop Packet => true INFO 24.03.2008 12:13:30 [ LS-00287; sov90_82; 87977 ] DialUpNASConnection has stop Packet => true INFO 24.03.2008 12:13:30 [ CD-06/049/2 ; apteka3; 99133 ] DialUpNASConnection has stop Packet => true INFO 24.03.2008 12:13:30 [ LS-00445; sov98_46; 5324 ] DialUpNASConnection has stop Packet => true INFO 24.03.2008 12:13:30 [ LS-01020 ; sov79_2; 45282 ] DialUpNASConnection has stop Packet => true INFO 24.03.2008 12:13:30 [ LS-00042; haustova; 90406 ] DialUpNASConnection has stop Packet => true INFO 24.03.2008 12:13:30 [ LS-01088 ; kalin28_6; 91772 ] DialUpNASConnection has stop Packet => true INFO 24.03.2008 12:13:30 [ LS-00335; gork1_60; 70644 ] DialUpNASConnection has stop Packet => true INFO 24.03.2008 12:13:30 [ LS-00457; kalin30_57; 73735 ] DialUpNASConnection has stop Packet => true INFO 24.03.2008 12:13:30 [ LS-00233; yubil5_67; 8158 ] DialUpNASConnection has stop Packet => true Не всех выкинуло разом, а только часть, у каждого абонента (специально проверил) причина выглядит так: Код: INFO 24.03.2008 12:13:29 [ LS-00912; rgs_sibir_2; 29577 ] DialUpNASConnection stoppingConnection INFO 24.03.2008 12:13:29 [ LS-00912; rgs_sibir_2; 29577 ] DialUpNASConnection has stop Packet => true INFO 24.03.2008 12:13:29 [ LS-00912; rgs_sibir_2; 29577 ] DialUpNASConnection set STATUS=3 INFO 24.03.2008 12:13:29 [ LS-00912; rgs_sibir_2; 29577 ] DialUpNASConnection sessionTime => 237579 Просто понять не могу, чего происходит. В mpd.stat выглядит тоже массовое отключение: Код: Mon Mar 24 12:15:28 KRAT 2008 kalin30_57 close connection on ng4 Mon Mar 24 12:15:28 KRAT 2008 sov79_2 close connection on ng8 Mon Mar 24 12:15:28 KRAT 2008 sov98_46 close connection on ng15 Mon Mar 24 12:15:28 KRAT 2008 gork2_109 close connection on ng29 Mon Mar 24 12:15:28 KRAT 2008 haustova close connection on ng30 Mon Mar 24 12:15:28 KRAT 2008 gork1_60 close connection on ng20 Mon Mar 24 12:15:29 KRAT 2008 kalin28_6 close connection on ng31 Mon Mar 24 12:15:29 KRAT 2008 energo close connection on ng3 Mon Mar 24 12:15:29 KRAT 2008 htk close connection on ng23 Mon Mar 24 12:15:29 KRAT 2008 kosmo19a_102 close connection on ng27 Mon Mar 24 12:15:29 KRAT 2008 chap51_65 close connection on ng21 Mon Mar 24 12:15:29 KRAT 2008 apteka2 close connection on ng9 Mon Mar 24 12:15:29 KRAT 2008 sibnedra close connection on ng10 Mon Mar 24 12:15:29 KRAT 2008 stekloplast close connection on ng25 Mon Mar 24 12:15:29 KRAT 2008 sov78_33 close connection on ng6 Mon Mar 24 12:15:29 KRAT 2008 sov90_82 close connection on ng14 Mon Mar 24 12:15:29 KRAT 2008 mongol close connection on ng7 Mon Mar 24 12:15:29 KRAT 2008 apteka3 close connection on ng5 Mon Mar 24 12:16:24 KRAT 2008 yubil5_67 close connection on ng16 У всех в NAS одно и тоже: Код: Mar 24 12:15:28 nas mpd: pptp28: no reply to EchoRequest after 60 sec
Mar 24 12:15:28 nas mpd: pptp28: killing connection with 192.168.4.10:1244 Mar 24 12:15:28 nas mpd: pptp28-0: killing channel Mar 24 12:15:28 nas mpd: [pptp030] PPTP call terminated Mar 24 12:15:28 nas mpd: [pptp030] IFACE: Close event Mar 24 12:15:28 nas mpd: [pptp030] exec: /usr/local/etc/rc.d/downiface.sh ng30 inet haustova Mar 24 12:15:28 nas mpd: [pptp030] exec: /sbin/route delete хх.хх.хх.хх -iface lo0 Mar 24 12:15:28 nas mpd: [pptp030] exec: command returned 256 Mar 24 12:15:28 nas mpd: [pptp030] exec: /sbin/ifconfig ng30 down delete -link0 Mar 24 12:15:28 nas mpd: [pptp030] IPCP: Close event Mar 24 12:15:28 nas mpd: [pptp030] IPCP: state change Opened --> Closing Mar 24 12:15:28 nas mpd: [pptp030] IPCP: SendTerminateReq #141 Mar 24 12:15:28 nas mpd: [pptp030] error writing len 8 frame to bypass: Network is down Mar 24 12:15:28 nas mpd: [pptp030] IPCP: LayerDown Mar 24 12:15:28 nas mpd: [pptp030] IFACE: Down event Mar 24 12:15:28 nas mpd: [pptp030] IFACE: Close event Это происходит на двух NAS - оба VPN-сервера. Может что в конфе не так, т.к. я делал второй нас, копируя просто конф. |
|
| Автор: | Администратор [ 24 мар 2008, 12:59 ] |
| Заголовок сообщения: | |
Цитата: Mar 24 12:15:28 nas mpd: pptp28: no reply to EchoRequest after 60 sec По-моему, MPD рвет соединения из-за неответа на эхо-пакет. Биллинг их не сбрасывает.. Цитата: INFO 24.03.2008 12:13:29 [ LS-00844; evroset; 38123 ] DialUpNASConnection has stop Packet => true
Это корректное сообщение, оначает что пришел стоп-пакет и соединение закрывается. Вы лучше выберите grep 38123, например, чтобы получить лог по одному соединению. |
|
| Автор: | S [ 24 мар 2008, 13:05 ] |
| Заголовок сообщения: | |
Вот именно. А почему он их рвет, а другие нет? Посмотрите выше конф, может там чего? Сокеты проверил, вроде нормально. Просто скажите, мож в конфе что не корректно, а так - буду рыть в mpd. |
|
| Автор: | Администратор [ 24 мар 2008, 13:38 ] |
| Заголовок сообщения: | |
У этих клиентов файрволы не стоят? |
|
| Автор: | S [ 24 мар 2008, 13:58 ] |
| Заголовок сообщения: | |
Хороший вопрос. Не думаю, что у всех так. Я попробую сам клиентом выступить, проверить, завтра например. Может быть и такая ситуация. Но почему, допустим, во-первых рубит сразу много и в одно время? В другое время отключение выглядит более-менее плавно, нет таких скачков. Буду дальше наблюдать. |
|
| Страница 1 из 1 | Часовой пояс: UTC + 5 часов [ Летнее время ] |
| Powered by phpBB® Forum Software © phpBB Group http://www.phpbb.com/ |
|