FreeRadius не отвечает на стоп аккаунтинга

catalist · August 24, 2020

Добрый день!

Есть фрирадиус версии: 3.0.13

Он получает стоп пакет от наса:

(146) Received Accounting-Request Id 201 from 10.10.1.252:34557 to 10.10.0.80:18013 length 565
(146)   NAS-Identifier = "XXXX"
(146)   Framed-IP-Address = 00.00.13.144
(146)   Calling-Station-Id = "00:00:00:00:96:f4"
(146)   Service-Type = Framed-User
(146)   User-Name = "service_2186"
(146)   Acct-Session-Id = "A1F8AC1E000000E1"
(146)   Acct-Authentic = RADIUS
(146)   Acct-Status-Type = Stop
(146)   Acct-Terminate-Cause = NAS-Request
(146)   Acct-Session-Time = 1798
(146)   Event-Timestamp = "авг 21 2020 13:52:25 +05"
(146)   Acct-Input-Packets = 350
(146)   Acct-Output-Packets = 1
(146)   Acct-Input-Octets = 33757
(146)   Acct-Input-Gigawords = 0
(146)   Acct-Output-Octets = 113
(146)   Acct-Output-Gigawords = 0
(146) # Executing section preacct from file /etc/raddb/sites-enabled/fastdpi-vs
(146) # Executing section accounting from file /etc/raddb/sites-enabled/fastdpi-vs
(146) Not sending reply to client.

И вот в конце пишет (146) Not sending reply to client. и ответ что все ок не посылает, на это сильно ругается NAS.

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

(154) Received Accounting-Request Id 182 from 10.10.1.252:34557 to 10.10.0.80:18013 length 109
(154)   NAS-Identifier = "xxxx"
(154)   Framed-IP-Address = 00.000.13.144
(154)   Calling-Station-Id = "00:00:00:00:96:f4"
(154)   Service-Type = Framed-User
(154)   User-Name = "service_2186"
(154)   Acct-Session-Id = "A1F8AC1E000000E1"
(154)   Acct-Authentic = RADIUS
(154)   Acct-Status-Type = Start
(154)   Event-Timestamp = "авг 21 2020 13:52:30 +05"
(154) # Executing section preacct from file /etc/raddb/sites-enabled/fastdpi-vs
(154) # Executing section accounting from file /etc/raddb/sites-enabled/fastdpi-vs
(154) Sent Accounting-Response Id 182 from 10.10.0.80:18013 to 10.10.1.252:34557 length 0

Подскажите в каком конфиге может быть проблема?

server fastdpi-vs {
listen {

        type = auth
#       ipaddr = 127.0.0.1
        ipaddr = 10.10.0.80
        port = 18012
#       interface = lo
        interface = ens160
#       clients = per_socket_clients
#       limit {
#             max_connections = 16
#             lifetime = 0
#             idle_timeout = 30
#       }
}

listen {
        type = acct
#       ipaddr = 127.0.0.1
        ipaddr = 10.10.0.80
        port = 18013
#       interface = lo
        interface = ens160
}


authorize {

        Autz-Type Status-Server {
                ok
        }

        if (!&NAS-IP-Address) {
           update request {
            &NAS-IP-Address := "%{Packet-Src-IP-Address}"
           }
        }

        detail
        if (&VasExperts-Service-Type == "Auth") {
          perl
        }
        elsif (&VasExperts-Service-Type == "DHCP") {
          perl
        }
        elsif (&VasExperts-Service-Type == "ARP") {
          perl
        } elsif (&VasExperts-Service-Type == "MS_CHAPv2" || &VasExperts-Service-Type == "CHAP") {
          chap
          mschap
          perl
        }
        else {
         update control {
                &Auth-Type := "Reject"
         }
        }

        if (notfound) {
         unknown_pool.post-auth
        }

        if (ok) {
            update control {
                &Auth-Type := Accept
            }
        }

        expiration
        logintime
}


#  Authentication.
authenticate {
        Auth-Type CHAP {
                chap
                if (!ok) {
                update reply {
                         Framed-IP-Address := "0.0.0.0"
                    }
                }
        }
        Auth-Type MS-CHAP {
                mschap
                if (!ok) {
                update reply {
                         Framed-IP-Address := "0.0.0.0"
                    }
                }
        }

}


#
#  Pre-accounting.  Decide which accounting type to use.
#
preacct {
        preprocess
}

#
#  Accounting.  Log the accounting data.
#
accounting {

        Acct-Type Status-Server {

        }

        if (!&NAS-IP-Address) {
           update request {
            &NAS-IP-Address := "%{Packet-Src-IP-Address}"
           }
        }

        perl
        if (&Acct-Status-Type == "Start" || &Acct-Status-Type == "Stop") {
              detail
        }
        unknown_pool
}


session {
}

post-auth {
    Post-Auth-Type Reject {
        if (&request:VasExperts-Service-Type == "MS_CHAPv2" || &request:VasExperts-Service-Type == "CHAP") {
                update reply {
                        reply:Framed-Ip-Address -= &reply:Framed-Ip-Address
                }
        }
    }

   detail
}

pre-proxy {
}

post-proxy {
}

}

DDR · August 24, 2020

Скорей всего, модуль perl на стоп пакеты отвечает fail или noop

catalist · August 24, 2020

Не подскажите как можно подебажить?

DDR · August 24, 2020

radiusd -X

или

raddebug -c '(User-Name == testuser)'

raddebug -c '(Acct-Status-Type == Stop)'

Edited August 24, 2020 by DDR

catalist · August 24, 2020

те логи что я писал выше получены при помощи флага -X, но понимания это не дало почему не шлется ответ

NewUse · August 24, 2020

закомментируйте модуль perl и unknown_pool в секции accounting .

catalist · August 24, 2020

Проблема в том что мне они нужны, там запросы к БД

NewUse · August 24, 2020

у Вас модуль sql вроде бы не используется....

В любом случае следите чтоб модули возвращали правильный код возврата вне зависимости от их внутренней работы.

т.е. при возникновении эксершена его надо перехватывать.

https://wiki.freeradius.org/modules/Rlm_perl

это что касается perl, а вот про модуль unknown_pool что-то ничего не слышал, это самопал?

catalist · August 25, 2020

в перле как раз реализовано обращение к бд, и прочая логика, в конце каждой процедуры стоит:
return RLM_MODULE_OK;

unknow_pool это просто пул айпи адресов для неизвестных абонентов

мы просто радиус не сами настраивали изначально

NewUse · August 25, 2020

19 минут назад, catalist сказал:

unknow_pool это просто пул айпи адресов для неизвестных абонентов

а он точно должен быть в таком виде в этой секции?, хотя если не ругается на конфиг, значит ок.

19 минут назад, catalist сказал:

в перле как раз реализовано обращение к бд, и прочая логика, в конце каждой процедуры стоит:
return RLM_MODULE_OK;

значит происходит эксепшен, отлавливайте его.

catalist · August 25, 2020

так вот вопрос как раз в том как отловить

NewUse · August 25, 2020

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

вообще это вопрос к тому, кто писал Ваш модуль, и если там только sql, то логичный вопрос, почему не использовать модуль sql?

попробуйте запустить с параметром -XXX если не ошибаюсь -- это более высокой уровень дебага.

catalist · August 25, 2020

вопрос не совсем в тему но всеже:

запустили радиус с кучей -xxxx

получили в вот такое:
Tue Aug 25 12:36:26 2020 : ERROR: (409) perl: Failed to create pair - failed to parse time string "авг 25 2020 12:36:25 +05"
Tue Aug 25 12:36:26 2020 : ERROR: (409) perl: &request:Event-Timestamp = $RAD_REQUEST{'Event-Timestamp'} -> 'авг 25 2020 12:36:25 +05'
Кто нить может подсказать почему так? в самом RADIUS пакете время идет в юникс формате (мы это видим вайршарком), а радиус его получается декодирует и сам же ругается.... и такой ругани много

unknow_pool - это ippool файл лежит в mods-avaiable

catalist · August 25, 2020

вот что еще удалось нарыть по теме:
Tue Aug 25 12:36:26 2020 : Debug: Parsed xlat tree:
Tue Aug 25 12:36:26 2020 : Debug: attribute --> Calling-Station-Id
Tue Aug 25 12:36:26 2020 : Debug: literal --> -
Tue Aug 25 12:36:26 2020 : Debug: attribute --> NAS-Port
Tue Aug 25 12:36:26 2020 : Debug: (407) unknown_pool: EXPAND %{Calling-Station-Id}-%{NAS-Port}
Tue Aug 25 12:36:26 2020 : Debug: (407) unknown_pool: --> d4:ca:6d:3c:96:f4-
Tue Aug 25 12:36:26 2020 : Debug: (407) unknown_pool: MD5 on 'key' directive maps to: 105be0687b9e0bd834397957e8310f76
Tue Aug 25 12:36:26 2020 : Debug: (407) unknown_pool: Searching for an entry for key: 'd4:ca:6d:3c:96:f4-'
Tue Aug 25 12:36:26 2020 : Debug: (407) unknown_pool: Entry not found
Tue Aug 25 12:36:26 2020 : Debug: (407) modsingle[accounting]: returned from unknown_pool (rlm_ippool)
Tue Aug 25 12:36:26 2020 : Debug: (407) [unknown_pool] = notfound
Tue Aug 25 12:36:26 2020 : Debug: (407) } # accounting = notfound
Tue Aug 25 12:36:26 2020 : Debug: (407) Not sending reply to client.

понятно что клиент не найден в анноун пуле, но не понятно почему после этого идет Not sending reply to client. ???

NewUse · August 25, 2020

попробуйте поменять местами unknown_pool и perl(чтоб perl позже вызывался).

31 минуту назад, catalist сказал:

perl: Failed to create pair - failed to parse time string "авг 25 2020 12:36:25 +05"
Tue Aug 25 12:36:26 2020 : ERROR: (409)

ну perl не понимает такой формат.

catalist · August 25, 2020

это понятно не понятно как заставить радиус отдавать в исходном формате?

7 минут назад, NewUse сказал:

попробуйте поменять местами unknown_pool и perl(чтоб perl позже вызывался).

хм, попробуем....

NewUse · August 25, 2020

6 минут назад, catalist сказал:

это понятно не понятно как заставить радиус отдавать в исходном формате?

предположу, что никак, надо парсить в перле то, что есть; скорее всего какими нибудь переменными окружения, ти lang* lc* или nls* можно поменять формат, но и модули perl тоже скорее всего умеют национальный формат парсить...

catalist · August 25, 2020

прикол в том что в скрипте перла ваще нет такой переменной как Event-Timestamp

NewUse · August 25, 2020

а вот это похоже баг, она у тебя в REQUEST передаётся, заведи баг с копией лога.

Решается скорее всего запуском из под пользователя с английской локалью.

catalist · August 25, 2020

Да спасибо, поменяли локаль и эта ошибка ушла

NewUse · August 25, 2020

багу заведите, и логи приложите, пусть профиксят.

catalist · August 25, 2020

По ошибке с unknow pool

поправили key, убрав NAS-PORT

и не помогло:
Tue Aug 25 14:36:11 2020 : Debug: (442) unknown_pool: EXPAND %{Calling-Station-Id}
Tue Aug 25 14:36:11 2020 : Debug: (442) unknown_pool: --> d4:ca:6d:3c:96:f4
Tue Aug 25 14:36:11 2020 : Debug: (442) unknown_pool: MD5 on 'key' directive maps to: b67fb80b84b163e2a2755653a7f98037
Tue Aug 25 14:36:11 2020 : Debug: (442) unknown_pool: Searching for an entry for key: 'd4:ca:6d:3c:96:f4'
Tue Aug 25 14:36:11 2020 : Debug: (442) unknown_pool: Entry not found
Tue Aug 25 14:36:11 2020 : Debug: (442) modsingle[accounting]: returned from unknown_pool (rlm_ippool)
Tue Aug 25 14:36:11 2020 : Debug: (442) [unknown_pool] = notfound
Tue Aug 25 14:36:11 2020 : Debug: (442) } # accounting = notfound
Tue Aug 25 14:36:11 2020 : Debug: (442) Not sending reply to client.

^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
Tue Aug 25 14:36:11 2020 : Debug: (442) Finished request
Tue Aug 25 14:36:11 2020 : Debug: (442) Cleaning up request packet ID 87 with timestamp +469

дайте линк где багу сделать?

NewUse · August 25, 2020

поменяли местами вызов perl и unknown_pool?

catalist · August 25, 2020

да, жду когда дебаг вылезет

catalist · August 25, 2020

Странно

ошибка осталась

Tue Aug 25 15:06:12 2020 : Debug: Parsed xlat tree:
Tue Aug 25 15:06:12 2020 : Debug: attribute --> Calling-Station-Id
Tue Aug 25 15:06:12 2020 : Debug: (913) unknown_pool: EXPAND %{Calling-Station-Id}
Tue Aug 25 15:06:12 2020 : Debug: (913) unknown_pool: --> d4:ca:6d:3c:96:f4
Tue Aug 25 15:06:12 2020 : Debug: (913) unknown_pool: MD5 on 'key' directive maps to: b67fb80b84b163e2a2755653a7f98037
Tue Aug 25 15:06:12 2020 : Debug: (913) unknown_pool: Searching for an entry for key: 'd4:ca:6d:3c:96:f4'
Tue Aug 25 15:06:12 2020 : Debug: (913) unknown_pool: Entry not found
Tue Aug 25 15:06:12 2020 : Debug: (913) modsingle[accounting]: returned from unknown_pool (rlm_ippool)
Tue Aug 25 15:06:12 2020 : Debug: (913) [unknown_pool] = notfound
Tue Aug 25 15:06:12 2020 : Debug: (913) } # accounting = notfound
Tue Aug 25 15:06:12 2020 : Debug: (913) Not sending reply to client.
Tue Aug 25 15:06:12 2020 : Debug: (913) Finished request

но теперь в логе у этого пакета нет строчек про перл ваще. (раньше были)

Причем у других типов пакетов (interim-update) есть строчки с перлом, а вот у стопа нет.

значит оно завершается сразу после unknow_pool видя ответ

потому что у interim-update дальше есть обработка

Tue Aug 25 15:06:27 2020 : Debug: (935) unknown_pool: This is not an Accounting-Stop
Tue Aug 25 15:06:27 2020 : Debug: (935) modsingle[accounting]: returned from unknown_pool (rlm_ippool)
Tue Aug 25 15:06:27 2020 : Debug: (935) [unknown_pool] = noop
Tue Aug 25 15:06:27 2020 : Debug: (935) modsingle[accounting]: calling perl (rlm_perl)
Tue Aug 25 15:06:27 2020 : Debug: (935) perl: $RAD_REQUEST{'User-Name'} = &request:User-Name -> 'DL-2-067'
Tue Aug 25 15:06:27 2020 : Debug: (935) perl: $RAD_REQUEST{'NAS-IP-Address'} = &request:NAS-IP-Address -> '10.10.1.252'

Sign In

FreeRadius не отвечает на стоп аккаунтинга

Recommended Posts

catalist

Top Posters In This Topic

Popular Days

Top Posters In This Topic

Popular Days

DDR

catalist

DDR

catalist

NewUse

catalist

NewUse

catalist

NewUse

catalist

NewUse

catalist

catalist

NewUse

catalist

NewUse

catalist

NewUse

catalist

NewUse

catalist

NewUse

catalist

catalist

Join the conversation