RADIUS, задержки и потери инфы о новых ppp сессиях

Технические вопросы по UTM 5.0
Ответить
w0Lf
Сообщения: 13
Зарегистрирован: Пн окт 01, 2012 08:38
Откуда: 127.0.0.1

RADIUS, задержки и потери инфы о новых ppp сессиях

Сообщение w0Lf »

Здравствуйте,

После поднятия абонентом PPPoE сессии, в отчётах по dialup и vpn нет информации о данной сессии.
Информация может появиться в отчёте спустя 5-10 минут.
При этом если длительность сессии менее 2-5 минут информация о ней вовсе не появляется в отчёте, будто бы её и небыло.

В БД так же не появляется запись о данной сессии, либо появляется с большим опозданием(если аптайм сессии более 5-10 минут).

Если перезагрузить utm5_radius, utm5_core, проблема пропадает на 5 минут и затем снова появляется.

Сервер:
10G оперативки, 4 ядра 2.6GHz

Прикладываю лог радиуса, из которого следует что вроде бы как всё в порядке.
Подобное поведение появилось совсем недавно(пару дней назад), до этого такой проблемы небыло, инфа о сессиях всегда появлялась сразу после поднятия сессии.

в ip-трафик связках указаны статические ip-адреса на каждого абонента, вида 11.22.33.44/32.

ошибок, дропов или иных проблем на сетевых интерфейсах нет.
Радиус ходит в отдельном для него влане.

Подскажите, что могло стать причиной такого поведения и как это исправить?

Версия биллинга 5.3-004-update2-debian_jessie_x64
Кол-во сессий в пике: ~4300
NAS: Mikrotik

-----------------------------

Jan 14 11:32:00 ?Debug : 2986c700 AuthQueue: New request from 172.16.200.8:57536
--- RADIUS Pkt ---
Code: [1] ID: [62]
Auth: Size 16; Data [0x3c92adb765a290ccbf26878b104c7f6f]
Attr: [6] Vendor: [0] Size 4; Data [0x00000002]
(Service-Type=INT:2)
Attr: [7] Vendor: [0] Size 4; Data [0x00000001]
(Framed-Protocol=INT:1)
Attr: [5] Vendor: [0] Size 4; Data [0x00f47db8]
(NAS-Port=INT:16022968)
Attr: [61] Vendor: [0] Size 4; Data [0x0000000f]
(NAS-Port-Type=INT:15)
Attr: [1] Vendor: [0] Size 7; Data [0x31303035313031]
(User-Name=STRING:1005101)
Attr: [31] Vendor: [0] Size 17; Data [0x30303a30433a34323a46383a41383a3445]
(Calling-Station-Id=STRING:00:0C:42:F8:A8:4E)
Attr: [30] Vendor: [0] Size 14; Data [0x7070706f655f766c616e5f353230]
(Called-Station-Id=STRING:pppoe_vlan_520)
Attr: [87] Vendor: [0] Size 14; Data [0x7070706f655f766c616e5f353230]
(NAS-Port-Id=STRING:pppoe_vlan_520)
Attr: [60] Vendor: [0] Size 16; Data [0xf4c74f1211854790e1080f502559e4bc]
(CHAP-Challenge=HEX:...)
Attr: [3] Vendor: [0] Size 17; Data [0x018469327aa4558ef574ed68d5153b402f]
(CHAP-Password=HEX:...)
Attr: [32] Vendor: [0] Size 4; Data [0x4d542d38]
(NAS-Identifier=STRING:MT-8)
Attr: [4] Vendor: [0] Size 4; Data [0xac10c808]
(NAS-IP-Address=IP:172.16.200.8)

Jan 14 11:32:00 ?Debug : 2986c700 AuthQueue: Login '1005101'
Jan 14 11:32:00 ?Debug : 2986c700 LoginStorage: Acquire: login '1005101' used 1 times
Jan 14 11:32:00 ?Debug : 2986c700 AuthQueue: Login info found, slink_id 16952
Jan 14 11:32:00 ?Debug : 2986c700 AuthQueue: Using CHAP authentication method
Jan 14 11:32:00 ?Debug : 2986c700 AuthQueue: CHAP authentication OK
Jan 14 11:32:00 Info : 2986c700 AuthQueue: authorization request from 172.16.200.8:57536 succeeded
Jan 14 11:32:00 ?Debug : 2986c700 AuthQueue: Service ID 224 type 3; account ID 1005101
Jan 14 11:32:00 ?Debug : 2986c700 IPPoolManager: IP 100.72.18.143 is leased from LoginPool '1005101'
Jan 14 11:32:00 ?Debug : 2986c700 CustomAttrs: custom attributes for IPTRAFFIC_SERVICE ID 224 have been added to the reply
Jan 14 11:32:00 ?Debug : 2986c700 AcctQueue: lookup: session ID 6007 for login '1005101'
Jan 14 11:32:00 ?Debug : 2986c700 AcctQueue: lookup: session ID 6007 for IP 100.72.18.143
Jan 14 11:32:00 ?Debug : 2986c700 SessionManager: put: session ID 6007 timeout scheduled at 1547454750
Jan 14 11:32:00 ?Debug : 2986c700 SessionManager: put: session ID 6007 from NAS 11 OK
Jan 14 11:32:00 ?Debug : 2986c700 AuthQueue: Reply
--- RADIUS Pkt ---
Code: [2] ID: [62]
Auth: Size 16; Data [0x3c92adb765a290ccbf26878b104c7f6f]
Attr: [6] Vendor: [0] Size 4; Data [0x00000002]
(Service-Type=INT:2)
Attr: [7] Vendor: [0] Size 4; Data [0x00000001]
(Framed-Protocol=INT:1)
Attr: [8] Vendor: [0] Size 4; Data [0x6448128f]
(Framed-IP-Address=IP:100.72.18.143)
Attr: [9] Vendor: [0] Size 4; Data [0xffffffff]
(Framed-IP-Netmask=IP:255.255.255.255)
Attr: [27] Vendor: [0] Size 4; Data [0x00015180]
(Session-Timeout=INT:86400)
Attr: [85] Vendor: [0] Size 4; Data [0x00000046]
(Acct-Interim-Interval=INT:70)
Attr: [8] Vendor: [14988] Size 4; Data [0x3130304d]
(Mikrotik:Mikrotik-Rate-Limit=STRING:100M)

Jan 14 11:32:00 ?Debug : 23fff700 AcctQueue: Request from 172.16.200.8:44037
--- RADIUS Pkt ---
Code: [4] ID: [63]
Auth: Size 16; Data [0xf62a8a1251569e9a09ac3430b318891f]
Attr: [6] Vendor: [0] Size 4; Data [0x00000002]
(Service-Type=INT:2)
Attr: [7] Vendor: [0] Size 4; Data [0x00000001]
(Framed-Protocol=INT:1)
Attr: [5] Vendor: [0] Size 4; Data [0x00f47db8]
(NAS-Port=INT:16022968)
Attr: [61] Vendor: [0] Size 4; Data [0x0000000f]
(NAS-Port-Type=INT:15)
Attr: [1] Vendor: [0] Size 7; Data [0x31303035313031]
(User-Name=STRING:1005101)
Attr: [31] Vendor: [0] Size 17; Data [0x30303a30433a34323a46383a41383a3445]
(Calling-Station-Id=STRING:00:0C:42:F8:A8:4E)
Attr: [30] Vendor: [0] Size 14; Data [0x7070706f655f766c616e5f353230]
(Called-Station-Id=STRING:pppoe_vlan_520)
Attr: [87] Vendor: [0] Size 14; Data [0x7070706f655f766c616e5f353230]
(NAS-Port-Id=STRING:pppoe_vlan_520)
Attr: [44] Vendor: [0] Size 8; Data [0x3831633435643736]
(Acct-Session-Id=STRING:81c45d76)
Attr: [8] Vendor: [0] Size 4; Data [0x6448128f]
(Framed-IP-Address=IP:100.72.18.143)
Attr: [45] Vendor: [0] Size 4; Data [0x00000001]
(Acct-Authentic=INT:1)
Attr: [55] Vendor: [0] Size 4; Data [0x5c3c4900]
(Event-Timestamp=DATE:1547454720)
Attr: [40] Vendor: [0] Size 4; Data [0x00000001]
(Acct-Status-Type=INT:1)
Attr: [32] Vendor: [0] Size 4; Data [0x4d542d38]
(NAS-Identifier=STRING:MT-8)
Attr: [41] Vendor: [0] Size 4; Data [0x00000000]
(Acct-Delay-Time=INT:0)
Attr: [4] Vendor: [0] Size 4; Data [0xac10c808]
(NAS-IP-Address=IP:172.16.200.8)

Jan 14 11:32:00 ?Debug : 23fff700 SessionManager: get: session ID 6007
Jan 14 11:32:00 ?Debug : 23fff700 AcctQueue: found session ID 6007 for IP 100.72.18.143
Jan 14 11:32:00 ?Debug : 23fff700 AcctQueue: sid_insert: session ID 6007 for SID 81c45d76
Jan 14 11:32:00 Info : 23fff700 AcctQueue: IPv4 address 100.72.18.143 leased
Jan 14 11:32:00 Info : 23fff700 AcctQueue: Accounting-Start for SID 81c45d76 user '1005101' slink ID 16952 from NAS 172.16.200.8
Jan 14 11:32:00 ?Debug : 23fff700 Transport: sending traffic/dialup session ID 6007
Jan 14 11:32:00 ?Debug : 23fff700 StreamConnection: Sending message ID 0x1107
Jan 14 11:32:00 ?Debug : 23fff700 SessionManager: put: session ID 6007 timeout scheduled at 2000000000
Jan 14 11:32:00 ?Debug : 23fff700 SessionManager: put: session ID 6007 from NAS 11 OK
Jan 14 11:32:00 ?Debug : 23fff700 AcctQueue: Reply
--- RADIUS Pkt ---
Code: [5] ID: [63]
Auth: Size 16; Data [0xf62a8a1251569e9a09ac3430b318891f]


Jan 14 11:32:21 ?Debug : 23fff700 AcctQueue: Request from 172.16.200.8:35890
--- RADIUS Pkt ---
Code: [4] ID: [-29]
Auth: Size 16; Data [0x4e397fb3bf9c8c081b4830679adc7583]
Attr: [6] Vendor: [0] Size 4; Data [0x00000002]
(Service-Type=INT:2)
Attr: [7] Vendor: [0] Size 4; Data [0x00000001]
(Framed-Protocol=INT:1)
Attr: [5] Vendor: [0] Size 4; Data [0x00f47db8]
(NAS-Port=INT:16022968)
Attr: [61] Vendor: [0] Size 4; Data [0x0000000f]
(NAS-Port-Type=INT:15)
Attr: [1] Vendor: [0] Size 7; Data [0x31303035313031]
(User-Name=STRING:1005101)
Attr: [31] Vendor: [0] Size 17; Data [0x30303a30433a34323a46383a41383a3445]
(Calling-Station-Id=STRING:00:0C:42:F8:A8:4E)
Attr: [30] Vendor: [0] Size 14; Data [0x7070706f655f766c616e5f353230]
(Called-Station-Id=STRING:pppoe_vlan_520)
Attr: [87] Vendor: [0] Size 14; Data [0x7070706f655f766c616e5f353230]
(NAS-Port-Id=STRING:pppoe_vlan_520)
Attr: [44] Vendor: [0] Size 8; Data [0x3831633435643736]
(Acct-Session-Id=STRING:81c45d76)
Attr: [8] Vendor: [0] Size 4; Data [0x6448128f]
(Framed-IP-Address=IP:100.72.18.143)
Attr: [45] Vendor: [0] Size 4; Data [0x00000001]
(Acct-Authentic=INT:1)
Attr: [55] Vendor: [0] Size 4; Data [0x5c3c4915]
(Event-Timestamp=DATE:1547454741)
Attr: [46] Vendor: [0] Size 4; Data [0x00000015]
(Acct-Session-Time=INT:21)
Attr: [28] Vendor: [0] Size 4; Data [0x00000384]
(Idle-Timeout=INT:900)
Attr: [27] Vendor: [0] Size 4; Data [0x00015180]
(Session-Timeout=INT:86400)
Attr: [197] Vendor: [0] Size 4; Data [0x05f5e100]
Attr: [255] Vendor: [529] Size 4; Data [0x05f5e100]
(Ascend:Ascend-Xmit-Rate=INT:100000000)
Attr: [8] Vendor: [14988] Size 4; Data [0x3130304d]
(Mikrotik:Mikrotik-Rate-Limit=STRING:100M)
Attr: [19] Vendor: [14988] Size 15; Data [0x7070706f655f616464725f6c697374]
Attr: [42] Vendor: [0] Size 4; Data [0x00000f84]
(Acct-Input-Octets=INT:3972)
Attr: [52] Vendor: [0] Size 4; Data [0x00000000]
(Acct-Input-Gigawords=INT:0)
Attr: [47] Vendor: [0] Size 4; Data [0x0000004c]
(Acct-Input-Packets=INT:76)
Attr: [43] Vendor: [0] Size 4; Data [0x0000139e]
(Acct-Output-Octets=INT:5022)
Attr: [53] Vendor: [0] Size 4; Data [0x00000000]
(Acct-Output-Gigawords=INT:0)
Attr: [48] Vendor: [0] Size 4; Data [0x0000004b]
(Acct-Output-Packets=INT:75)
Attr: [40] Vendor: [0] Size 4; Data [0x00000002]
(Acct-Status-Type=INT:2)
Attr: [49] Vendor: [0] Size 4; Data [0x00000001]
(Acct-Terminate-Cause=INT:1)
Attr: [32] Vendor: [0] Size 4; Data [0x4d542d38]
(NAS-Identifier=STRING:MT-8)
Attr: [41] Vendor: [0] Size 4; Data [0x00000000]
(Acct-Delay-Time=INT:0)
Attr: [4] Vendor: [0] Size 4; Data [0xac10c808]
(NAS-IP-Address=IP:172.16.200.8)

Jan 14 11:32:21 ?Debug : 23fff700 SessionManager: get: session ID 6007
Jan 14 11:32:21 ?Debug : 23fff700 AcctQueue: found session ID 6007 for SID 81c45d76
Jan 14 11:32:21 Info : 23fff700 AcctQueue: Accouting-Stop for SID 81c45d76 user '1005101' slink ID 16952 from NAS 172.16.200.8
Jan 14 11:32:21 ?Debug : 23fff700 AcctQueue: lookup: session ID 6007 closed
Jan 14 11:32:21 ?Debug : 23fff700 Transport: sending traffic/dialup session ID 6007
Jan 14 11:32:21 ?Debug : 23fff700 StreamConnection: Sending message ID 0x1107
Jan 14 11:32:21 ?Debug : 23fff700 SessionManager: put: sessiond ID 6007 from NAS 11 is closed
Jan 14 11:32:21 ?Debug : 23fff700 IPPoolManager: IP 100.72.18.143 is released
Jan 14 11:32:21 ?Debug : 23fff700 LoginStorage: Release: login '1005101' used 0 times
Jan 14 11:32:21 ?Debug : 23fff700 AcctQueue: Reply
--- RADIUS Pkt ---
Code: [5] ID: [-29]
Auth: Size 16; Data [0x4e397fb3bf9c8c081b4830679adc7583]

Kayfolom
Сообщения: 746
Зарегистрирован: Вс фев 12, 2006 17:15

Re: RADIUS, задержки и потери инфы о новых ppp сессиях

Сообщение Kayfolom »

Подскажите, вы решили проблему? Если да, то как именно?
Заранее благодарю за ответ!

Cramac
Сообщения: 454
Зарегистрирован: Сб июл 01, 2006 17:59

Re: RADIUS, задержки и потери инфы о новых ppp сессиях

Сообщение Cramac »

такая же проблема наблюдается на одном из NAS

Ответить