Странное поведение биллинга при session ID not found

[o^er]

Если в логах радиуса по какой либо причине после Accounting-Request пакета появляется session ID xxxxxx not found, то биллинг делает такую запись в таблицу:

Код: Выделить всё

DBConnection_mysql&#58; <0x7f35f801aca0> SQL query&#58; INSERT INTO dhs_sessions_log&#40;account_id,slink_id,recv_date,last_update_date,Framed_IP_Address,Framed_IP_Address6,Framed_IP_Ad
dress6_ext,NAS_Port,Acct_Delay_Time,Acct_Session_Id,NAS_Port_Type,User_Name,Service_Type,Framed_Protocol,NAS_IP_Address,NAS_IP_Address_ext,NAS_IP_Address_type,NAS_Id,Acct_Status_Type,Acct_Input_Packets,Acct_
Input_Octets,Acct_Input_Gigawords,Acct_Output_Packets,Acct_Output_Octets,Acct_Output_Gigawords,Acct_Session_Time,Acct_Terminate_Cause,flags,called_station_id,calling_station_id&#41; VALUES&#40;'877','1418','14616931
08','1461693108','0','0','0','33816576','0','0103FFFF68007332-571FAAB4','5','nova79300562239','2','1','-1062718463','0','0','192.168.52.1','1','0','0','0','0','0','0','0','0','0','',''&#41;

то есть считает что сессия поднята с IP адресом = 0.

Это приводит к тому, что реально выданный клиенту IP адрес, начинает выдаваться другим абонентам, а NAS такую сессию отшибает из за занятости IP адреса.

Я не совсем понимаю почему меняет session ID в логах биллинга.

Может кто подскажет, почему сменился session ID?
И всё же если он сменился, то дальнейшее поведение биллинга как минимум не логичное. Зачем он считает что сессия поднята с IP адресом = 0.


Полный лог радиуса:

Код: Выделить всё

Apr 26 20:51:48 ?Debug : dd5c7700 AuthQueue: New request from 192.168.52.1:1812
--- RADIUS Pkt ---
  Code: [1]  ID:   [18]
  Auth: Size 16; Data [0x1252565a9b54c584c608a28eeb712727]
    Attr: [1] Vendor: [0] Size 15; Data [0x6e6f76613739333030353632323339]
        (User-Name=STRING:nova79300562239)
    Attr: [3] Vendor: [0] Size 17; Data [0x01ac2cd62b73e643cf41ec57f95eff6a8e]
        (CHAP-Password=HEX:...)
    Attr: [60] Vendor: [0] Size 16; Data [0x1252565a9b54c584c608a28eeb712727]
        (CHAP-Challenge=HEX:...)
    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: [32] Vendor: [0] Size 7; Data [0x5265646261636b]
        (NAS-Identifier=STRING:Redback)
    Attr: [5] Vendor: [0] Size 4; Data [0x02040000]
        (NAS-Port=INT:33816576)
    Attr: [62] Vendor: [2352] Size 4; Data [0x24bc03e9]
        (Redback:NAS-Real-Port=INT:616301545)
    Attr: [61] Vendor: [0] Size 4; Data [0x00000005]
        (NAS-Port-Type=INT:5)
    Attr: [87] Vendor: [0] Size 32; Data [0x322f3420766c616e2d696420333030383a31303031207070706f652036323937]
        (NAS-Port-Id=STRING:2/4 vlan-id 3008:1001 pppoe 6297)
    Attr: [38] Vendor: [2352] Size 4; Data [0x0000000b]
        (Redback:Medium-Type=INT:11)
    Attr: [145] Vendor: [2352] Size 17; Data [0x36302d65332d32372d64352d61662d3064]
        (Redback:Mac-Addr=STRING:60-e3-27-d5-af-0d)
    Attr: [98] Vendor: [2352] Size 4; Data [0x00000004]
        (Redback:Platform-Type=INT:4)
    Attr: [112] Vendor: [2352] Size 9; Data [0x31322e312e312e3131]
        (Redback:OS-Version=STRING:12.1.1.11)

Apr 26 20:51:48 ?Debug : dd5c7700 AuthQueue: Login 'nova79300562239'
Apr 26 20:51:48 ?Debug : dd5c7700 LoginStorage: Acquire: login 'nova79300562239' used 1 times
Apr 26 20:51:48 ?Debug : dd5c7700 AuthQueue: Login info found, slink_id 1418
Apr 26 20:51:48 ?Debug : dd5c7700 AuthQueue: Using CHAP authentication method
Apr 26 20:51:48 ?Debug : dd5c7700 AuthQueue: CHAP authentication OK
Apr 26 20:51:48  Info  : dd5c7700 AuthQueue: authorization request from 192.168.52.1:1812 succeeded
Apr 26 20:51:48 ?Debug : dd5c7700 AuthQueue: Service ID 15 type 3; account ID 877
Apr 26 20:51:48 ?Debug : dd5c7700 IPPoolManager: IP 10.52.0.111 is leased from NamedPool 'inet_nat'
Apr 26 20:51:48 ?Debug : dd5c7700 CustomAttrs: custom attributes for IPTRAFFIC_SERVICE ID 15 have been added to the reply
Apr 26 20:51:48 ?Debug : dd5c7700 AcctQueue: lookup: session ID 1055947 for login 'nova79300562239'
Apr 26 20:51:48 ?Debug : dd5c7700 AcctQueue: lookup: session ID 1055947 for IP 10.52.0.111
Apr 26 20:51:48 ?Debug : dd5c7700 SessionManager: put: session ID 1055947 timeout scheduled at 1461693138
Apr 26 20:51:48 ?Debug : dd5c7700 SessionManager: put: session ID 1055947 from NAS 2 OK
Apr 26 20:51:48 ?Debug : dd5c7700 AuthQueue: Reply
--- RADIUS Pkt ---
  Code: [2]  ID:   [18]
  Auth: Size 16; Data [0x1252565a9b54c584c608a28eeb712727]
    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 [0x0a34006f]
        (Framed-IP-Address=IP:10.52.0.111)
    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: [104] Vendor: [2352] Size 13; Data [0x5050506f455f70726976617465]
        (Redback:IP-Interface-Name=STRING:PPPoE_private)
    Attr: [105] Vendor: [2352] Size 9; Data [0x4e41545f5050504f45]
        (Redback:NAT-Policy-Name=STRING:NAT_PPPOE)
    Attr: [91] Vendor: [2352] Size 11; Data [0x70726f66696c652d34304d]
        (Redback:Subscriber-Profile-Name=STRING:profile-40M)

Apr 26 20:51:48 ?Debug : dd4c6700 AcctQueue: Request from 192.168.52.1:1812
--- RADIUS Pkt ---
  Code: [4]  ID:   [-4]
  Auth: Size 16; Data [0x54a0f9bd59be36ff54f72c22d5665865]
    Attr: [1] Vendor: [0] Size 15; Data [0x6e6f76613739333030353632323339]
        (User-Name=STRING:nova79300562239)
    Attr: [40] Vendor: [0] Size 4; Data [0x00000001]
        (Acct-Status-Type=INT:1)
    Attr: [44] Vendor: [0] Size 25; Data [0x303130334646464636383030373333322d3537314641414234]
        (Acct-Session-Id=STRING:0103FFFF68007332-571FAAB4)
    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: [144] Vendor: [2352] Size 4; Data [0x00000001]
        (Redback:Acct-Update-Reason=INT:1)
    Attr: [32] Vendor: [0] Size 7; Data [0x5265646261636b]
        (NAS-Identifier=STRING:Redback)
    Attr: [5] Vendor: [0] Size 4; Data [0x02040000]
        (NAS-Port=INT:33816576)
    Attr: [62] Vendor: [2352] Size 4; Data [0x24bc03e9]
        (Redback:NAS-Real-Port=INT:616301545)
    Attr: [61] Vendor: [0] Size 4; Data [0x00000005]
        (NAS-Port-Type=INT:5)
    Attr: [87] Vendor: [0] Size 32; Data [0x322f3420766c616e2d696420333030383a31303031207070706f652036323937]
        (NAS-Port-Id=STRING:2/4 vlan-id 3008:1001 pppoe 6297)
    Attr: [38] Vendor: [2352] Size 4; Data [0x0000000b]
        (Redback:Medium-Type=INT:11)
    Attr: [145] Vendor: [2352] Size 17; Data [0x36302d65332d32372d64352d61662d3064]
        (Redback:Mac-Addr=STRING:60-e3-27-d5-af-0d)
    Attr: [98] Vendor: [2352] Size 4; Data [0x00000004]
        (Redback:Platform-Type=INT:4)
    Attr: [112] Vendor: [2352] Size 9; Data [0x31322e312e312e3131]
        (Redback:OS-Version=STRING:12.1.1.11)
    Attr: [45] Vendor: [0] Size 4; Data [0x00000001]
        (Acct-Authentic=INT:1)
    Attr: [104] Vendor: [2352] Size 13; Data [0x5050506f455f70726976617465]
        (Redback:IP-Interface-Name=STRING:PPPoE_private)
    Attr: [91] Vendor: [2352] Size 11; Data [0x70726f66696c652d34304d]
        (Redback:Subscriber-Profile-Name=STRING:profile-40M)
    Attr: [8] Vendor: [0] Size 4; Data [0x0a34006f]
        (Framed-IP-Address=IP:10.52.0.111)
    Attr: [9] Vendor: [0] Size 4; Data [0xffffffff]
        (Framed-IP-Netmask=IP:255.255.255.255)
    Attr: [1] Vendor: [2352] Size 4; Data [0xd45c8403]
        (Redback:Client-DNS-Pri=IP:212.92.132.3)
    Attr: [27] Vendor: [0] Size 4; Data [0x00015180]
        (Session-Timeout=INT:86400)
    Attr: [105] Vendor: [2352] Size 9; Data [0x4e41545f5050504f45]
        (Redback:NAT-Policy-Name=STRING:NAT_PPPOE)
    Attr: [87] Vendor: [2352] Size 6; Data [0x34304d2d696e]
        (Redback:Qos-Policing-Profile-Name=STRING:40M-in)
    Attr: [88] Vendor: [2352] Size 7; Data [0x34304d2d6f7574]
        (Redback:Qos-Metering-Profile-Name=STRING:40M-out)
    Attr: [92] Vendor: [2352] Size 14; Data [0x696e3a55534552535f5050506f45]
        (Redback:Forward-Policy=STRING:in:USERS_PPPoE)
    Attr: [55] Vendor: [0] Size 4; Data [0x571faab4]
        (Event-Timestamp=DATE:1461693108)

Apr 26 20:51:48  ERROR : dd4c6700 SessionManager: get: session ID 1035857 not found
Apr 26 20:51:48  ERROR : dd4c6700 LogicError: get: session not found
Apr 26 20:51:48 ?Trace : dd4c6700 trace: Obtained 11 stack frames.
Apr 26 20:51:48 ?Trace : dd4c6700 trace: /netup/utm5/bin/utm5_radius(_ZN3UTM15print_backtraceEv+0x40) [0x52a030]
Apr 26 20:51:48 ?Trace : dd4c6700 trace: /netup/utm5/bin/utm5_radius(_ZN3UTM8DBAErrorC2ERKSsS2_bNS_6Logger5LevelE+0x96) [0x446b26]
Apr 26 20:51:48 ?Trace : dd4c6700 trace: /netup/utm5/bin/utm5_radius(_ZN3UTM10LogicErrorC2ERKSsbNS_6Logger5LevelE+0x51) [0x446c11]
Apr 26 20:51:48 ?Trace : dd4c6700 trace: /netup/utm5/bin/utm5_radius(_ZN6RADIUS14SessionManager3getEi+0x53a) [0x47f25a]
Apr 26 20:51:48 ?Trace : dd4c6700 trace: /netup/utm5/bin/utm5_radius(_ZN6RADIUS9AcctQueue11get_sessionEiRKSs+0x36) [0x441b16]
Apr 26 20:51:48 ?Trace : dd4c6700 trace: /netup/utm5/bin/utm5_radius(_ZN6RADIUS9AcctQueue15process_requestERKN3UTM8NAS_InfoERKNS_9RADPacketERS5_+0x25e) [0x44488e]
Apr 26 20:51:48 ?Trace : dd4c6700 trace: /netup/utm5/bin/utm5_radius(_ZN6RADIUS9AcctQueue15packet_receivedEPKcmRKN3UTM6Socket8EndpointE+0x51b) [0x4451eb]
Apr 26 20:51:48 ?Trace : dd4c6700 trace: /netup/utm5/bin/utm5_radius(_ZN6RADIUS9UDPServer3runEv+0x40e) [0x49812e]
Apr 26 20:51:48 ?Trace : dd4c6700 trace: /netup/utm5/bin/utm5_radius(_ZN3UTM6Thread6threadEPv+0x54) [0x52bb44]
Apr 26 20:51:48 ?Trace : dd4c6700 trace: /lib/x86_64-linux-gnu/libpthread.so.0(+0x6b50) [0x7f27e098eb50]
Apr 26 20:51:48 ?Trace : dd4c6700 trace: /lib/x86_64-linux-gnu/libc.so.6(clone+0x6d) [0x7f27def7f95d]
Apr 26 20:51:48 ?Debug : dd4c6700 AcctQueue: session ID 1035857 not found
Apr 26 20:51:48  ERROR : dd4c6700 SessionManager: get: session ID 1035857 not found
Apr 26 20:51:48  ERROR : dd4c6700 LogicError: get: session not found
Apr 26 20:51:48 ?Trace : dd4c6700 trace: Obtained 11 stack frames.
Apr 26 20:51:48 ?Trace : dd4c6700 trace: /netup/utm5/bin/utm5_radius(_ZN3UTM15print_backtraceEv+0x40) [0x52a030]
Apr 26 20:51:48 ?Trace : dd4c6700 trace: /netup/utm5/bin/utm5_radius(_ZN3UTM8DBAErrorC2ERKSsS2_bNS_6Logger5LevelE+0x96) [0x446b26]
Apr 26 20:51:48 ?Trace : dd4c6700 trace: /netup/utm5/bin/utm5_radius(_ZN3UTM10LogicErrorC2ERKSsbNS_6Logger5LevelE+0x51) [0x446c11]
Apr 26 20:51:48 ?Trace : dd4c6700 trace: /netup/utm5/bin/utm5_radius(_ZN6RADIUS14SessionManager3getEi+0x53a) [0x47f25a]
Apr 26 20:51:48 ?Trace : dd4c6700 trace: /netup/utm5/bin/utm5_radius(_ZN6RADIUS9AcctQueue11get_sessionEiRKSs+0x36) [0x441b16]
Apr 26 20:51:48 ?Trace : dd4c6700 trace: /netup/utm5/bin/utm5_radius(_ZN6RADIUS9AcctQueue15process_requestERKN3UTM8NAS_InfoERKNS_9RADPacketERS5_+0x3ad) [0x4449dd]
Apr 26 20:51:48 ?Trace : dd4c6700 trace: /netup/utm5/bin/utm5_radius(_ZN6RADIUS9AcctQueue15packet_receivedEPKcmRKN3UTM6Socket8EndpointE+0x51b) [0x4451eb]
Apr 26 20:51:48 ?Trace : dd4c6700 trace: /netup/utm5/bin/utm5_radius(_ZN6RADIUS9UDPServer3runEv+0x40e) [0x49812e]
Apr 26 20:51:48 ?Trace : dd4c6700 trace: /netup/utm5/bin/utm5_radius(_ZN3UTM6Thread6threadEPv+0x54) [0x52bb44]
Apr 26 20:51:48 ?Trace : dd4c6700 trace: /lib/x86_64-linux-gnu/libpthread.so.0(+0x6b50) [0x7f27e098eb50]
Apr 26 20:51:48 ?Trace : dd4c6700 trace: /lib/x86_64-linux-gnu/libc.so.6(clone+0x6d) [0x7f27def7f95d]
Apr 26 20:51:48 ?Debug : dd4c6700 AcctQueue: session ID 1035857 not found
Apr 26 20:51:48 ?Debug : dd4c6700 AcctQueue: new session ID 1055948 for SID 0103FFFF68007332-571FAAB4
Apr 26 20:51:48 ?Debug : dd4c6700 AcctQueue: sid_insert: session ID 1055948 for SID 0103FFFF68007332-571FAAB4
Apr 26 20:51:48 ?Debug : dd4c6700 LoginStorage: Acquire: login 'nova79300562239' used 2 times
Apr 26 20:51:48 ?Debug : dd4c6700 AcctQueue: slink_id 1418 service_type 3 for login 'nova79300562239'
Apr 26 20:51:48  Info  : dd4c6700 AcctQueue: IPv4 address 10.52.0.111 leased
Apr 26 20:51:48  ERROR : dd4c6700 AcctQueue: IP 10.52.0.111 is busy
Apr 26 20:51:48  Info  : dd4c6700 AcctQueue: Accounting-Start for SID 0103FFFF68007332-571FAAB4 user 'nova79300562239' slink ID 1418 from NAS 192.168.52.1
Apr 26 20:51:48 ?Debug : dd4c6700 Transport: sending traffic/dialup session ID 1055948
Apr 26 20:51:48 ?Debug : dd4c6700 Transport: session ID 1055948 witout IPInfo
Apr 26 20:51:48 ?Debug : dd4c6700 StreamConnection: Sending message ID 0x1107
Apr 26 20:51:48 ?Debug : dd4c6700 SessionManager: put: session ID 1055948 timeout scheduled at 2000000000
Apr 26 20:51:48 ?Debug : dd4c6700 SessionManager: put: session ID 1055948 from NAS 2 OK
Apr 26 20:51:48 ?Debug : dd4c6700 AcctQueue: Reply
--- RADIUS Pkt ---
  Code: [5]  ID:   [-4]
  Auth: Size 16; Data [0x54a0f9bd59be36ff54f72c22d5665865]

[billy]

Не получив вовремя ALIVE-пакеты, радиус закрывает сессию, но на NAS абонент продолжает работать.
Поэтому радиус может пытаться выдавать адреса новым абонентам, в то время, как на NAS этот адрес занят.
Самое интересное, что спустя некоторое время ALIVE-пакеты снова начинают поступать с NAS на радиус сервер. А родная сессия на радиусе уже закрыта. Вот тут и начинаются чудеса с ip-адресами и длительностью сессии
Так что очень важно обеспечить надежную связь между NAS и радиусом. У меня они соединены патч-кордом.

[o^er]

Не получив вовремя ALIVE-пакеты, радиус закрывает сессию, но на NAS абонент продолжает работать.
Поэтому радиус может пытаться выдавать адреса новым абонентам, в то время, как на NAS этот адрес занят.
Самое интересное, что спустя некоторое время ALIVE-пакеты снова начинают поступать с NAS на радиус сервер. А родная сессия на радиусе уже закрыта. Вот тут и начинаются чудеса с ip-адресами и длительностью сессии
Так что очень важно обеспечить надежную связь между NAS и радиусом. У меня они соединены патч-кордом.

У меня они тоже соединены патчкордом, но проблема не в связности, и не в том что радиус закрывает сессию.
В биллинге она (сессия) есть, но с IP адресом 0.0.0.0
Тут вся проблема в том, что биллинг изначально считает сессию поднятой с неверным адресом. Вопрос был именно "почему биллинг это делает?"

[banec]

Версия биллинга?
Возможен баг уже убран - смотрите чендж лог

[o^er]

Версия биллинга?
Возможен баг уже убран - смотрите чендж лог

Версия UTM 5.3-003-update9
Из changelog не совсем понятно об этой проблеме в исправлениях идёт речь, или нет.
Например "4610 Исправлена проблема, в ряде случаев приводившая к выдаче некорректных IP-адресов сервером RADIUS", вот что за некорректные IP адреса выдавались, не понятно.