Release of the IP after the Acct-Stop (ippool)
Lars Hillebrand
lars.hillebrand at fh-dortmund.de
Mon Oct 29 15:53:28 CET 2018
Hello everyone,
I have a question regarding the release of IP addresses with the module ippool.
We are about to replace our old Feeradius 2.2.8 with a new 3.0.16 installation.
This worked very well, but there is still a problem with the release of the IP pools after the Acct-Stop.
The corresponding "Acct-Status-Type = Stop" packets arrive correctly at the radius, but the evaluation is exited after the first "ippool area" within which no IP is found.
(unabridged debug log in appendix —> debug_1)
(6079) Mon Oct 29 14:40:20 2018: Debug: User-Name = "user1"
(6079) Mon Oct 29 14:40:20 2018: Debug: NAS-Port = 202153984
(6079) Mon Oct 29 14:40:20 2018: Debug: Service-Type = Framed-User
(6079) Mon Oct 29 14:40:20 2018: Debug: Framed-Protocol = PPP
(6079) Mon Oct 29 14:40:20 2018: Debug: Framed-IP-Address = 10.99.157.108
(6079) Mon Oct 29 14:40:20 2018: Debug: Called-Station-Id = "193.25.18.219"
(6079) Mon Oct 29 14:40:20 2018: Debug: Calling-Station-Id = "109.90.177.240"
(6079) Mon Oct 29 14:40:20 2018: Debug: Acct-Status-Type = Stop
(6079) Mon Oct 29 14:40:20 2018: Debug: Acct-Delay-Time = 0
(6079) Mon Oct 29 14:40:20 2018: Debug: Acct-Input-Octets = 5152
(6079) Mon Oct 29 14:40:20 2018: Debug: Acct-Output-Octets = 11550
(6079) Mon Oct 29 14:40:20 2018: Debug: Acct-Session-Id = "6DC02E18"
(6079) Mon Oct 29 14:40:20 2018: Debug: Acct-Authentic = RADIUS
(6079) Mon Oct 29 14:40:20 2018: Debug: Acct-Session-Time = 19
(6079) Mon Oct 29 14:40:20 2018: Debug: Acct-Input-Packets = 79
(6079) Mon Oct 29 14:40:20 2018: Debug: Acct-Output-Packets = 15
(6079) Mon Oct 29 14:40:20 2018: Debug: Acct-Terminate-Cause = User-Request
(6079) Mon Oct 29 14:40:20 2018: Debug: NAS-Port-Type = Virtual
...
(6079) Mon Oct 29 14:40:20 2018: Debug: accounting {
(6079) Mon Oct 29 14:40:20 2018: Debug: detail: EXPAND /var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d
(6079) Mon Oct 29 14:40:20 2018: Debug: detail: --> /var/log/freeradius/radacct/193.25.18.219/detail-20181029
(6079) Mon Oct 29 14:40:20 2018: Debug: detail: /var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d expands to /var/log/freeradius/radacct/193.25.18.219/detail-20181029
(6079) Mon Oct 29 14:40:20 2018: Debug: detail: EXPAND %t
(6079) Mon Oct 29 14:40:20 2018: Debug: detail: --> Mon Oct 29 14:40:20 2018
(6079) Mon Oct 29 14:40:20 2018: Debug: [detail] = ok
(6079) Mon Oct 29 14:40:20 2018: Debug: [unix] = ok
(6079) Mon Oct 29 14:40:20 2018: Debug: FB1-B: EXPAND %{NAS-IP-Address} %{NAS-Port}
(6079) Mon Oct 29 14:40:20 2018: Debug: FB1-B: --> 193.25.18.219 202153984
(6079) Mon Oct 29 14:40:20 2018: Debug: FB1-B: MD5 on 'key' directive maps to: 8c9ebba43c49461c579616773eb1d008
(6079) Mon Oct 29 14:40:20 2018: Debug: FB1-B: Searching for an entry for key: '193.25.18.219 202153984'
(6079) Mon Oct 29 14:40:20 2018: Debug: FB1-B: Entry not found
(6079) Mon Oct 29 14:40:20 2018: Debug: [FB1-B] = notfound
(6079) Mon Oct 29 14:40:20 2018: Debug: } # accounting = notfound
(6079) Mon Oct 29 14:40:20 2018: Debug: Not sending reply to client.
(6079) Mon Oct 29 14:40:20 2018: Debug: Finished request
(6079) Mon Oct 29 14:40:21 2018: Debug: Cleaning up request packet ID 132 with timestamp +76
If we adjust the order of the ippools in the site-availiable configuration so that the used area is in first place, it will be evaluated correctly at the Acct-Stop and the IP address will be released but the evaluation will jump out again after the first pool without an entry.
(unabridged debug log in appendix —> debug_2)
(2931) Mon Oct 29 14:45:52 2018: Debug: Received Accounting-Request Id 149 from 193.25.18.219:38622 to 10.100.16.162:2011 length 213
(2931) Mon Oct 29 14:45:52 2018: Debug: User-Name = "user1"
(2931) Mon Oct 29 14:45:52 2018: Debug: NAS-Port = 202162176
(2931) Mon Oct 29 14:45:52 2018: Debug: Service-Type = Framed-User
(2931) Mon Oct 29 14:45:52 2018: Debug: Framed-Protocol = PPP
(2931) Mon Oct 29 14:45:52 2018: Debug: Framed-IP-Address = 10.99.156.54
(2931) Mon Oct 29 14:45:52 2018: Debug: Called-Station-Id = "193.25.18.219"
(2931) Mon Oct 29 14:45:52 2018: Debug: Framed-IP-Address = 10.99.156.54
(2931) Mon Oct 29 14:45:52 2018: Debug: Called-Station-Id = "193.25.18.219"
(2931) Mon Oct 29 14:45:52 2018: Debug: Calling-Station-Id = "109.90.177.240"
(2931) Mon Oct 29 14:45:52 2018: Debug: Acct-Status-Type = Stop
(2931) Mon Oct 29 14:45:52 2018: Debug: Acct-Delay-Time = 0
(2931) Mon Oct 29 14:45:52 2018: Debug: Acct-Input-Octets = 2747
(2931) Mon Oct 29 14:45:52 2018: Debug: Acct-Output-Octets = 2789
(2931) Mon Oct 29 14:45:52 2018: Debug: Acct-Session-Id = "6DC02E1B"
(2931) Mon Oct 29 14:45:52 2018: Debug: Acct-Authentic = RADIUS
(2931) Mon Oct 29 14:45:52 2018: Debug: Acct-Session-Time = 6
(2931) Mon Oct 29 14:45:52 2018: Debug: Acct-Input-Packets = 43
(2931) Mon Oct 29 14:45:52 2018: Debug: Acct-Output-Packets = 6
(2931) Mon Oct 29 14:45:52 2018: Debug: Acct-Terminate-Cause = User-Request
(2931) Mon Oct 29 14:45:52 2018: Debug: NAS-Port-Type = Virtual
...
(2931) Mon Oct 29 14:45:52 2018: Debug: accounting {
(2931) Mon Oct 29 14:45:52 2018: Debug: detail: EXPAND /var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d
(2931) Mon Oct 29 14:45:52 2018: Debug: detail: --> /var/log/freeradius/radacct/193.25.18.219/detail-20181029
(2931) Mon Oct 29 14:45:52 2018: Debug: detail: /var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d expands to /var/log/freeradius/radacct/193.25.18.219/detail-20181029
(2931) Mon Oct 29 14:45:52 2018: Debug: detail: EXPAND %t
(2931) Mon Oct 29 14:45:52 2018: Debug: detail: --> Mon Oct 29 14:45:52 2018
(2931) Mon Oct 29 14:45:52 2018: Debug: [detail] = ok
(2931) Mon Oct 29 14:45:52 2018: Debug: [unix] = ok
(2931) Mon Oct 29 14:45:52 2018: Debug: DVZ-S: EXPAND %{NAS-IP-Address} %{NAS-Port}
(2931) Mon Oct 29 14:45:52 2018: Debug: DVZ-S: --> 193.25.18.219 202162176
(2931) Mon Oct 29 14:45:52 2018: Debug: DVZ-S: MD5 on 'key' directive maps to: e1441074cac9707ffe85004a796a5062
(2931) Mon Oct 29 14:45:52 2018: Debug: DVZ-S: Searching for an entry for key: '193.25.18.219 202162176'
(2931) Mon Oct 29 14:45:52 2018: Debug: DVZ-S: Deallocated entry for ip: 10.99.156.54
(2931) Mon Oct 29 14:45:52 2018: Debug: DVZ-S: Allocated count now: 0
(2931) Mon Oct 29 14:45:52 2018: Debug: [DVZ-S] = ok
(2931) Mon Oct 29 14:45:52 2018: Debug: Gaeste: EXPAND %{NAS-IP-Address} %{NAS-Port}
(2931) Mon Oct 29 14:45:52 2018: Debug: Gaeste: --> 193.25.18.219 202162176
(2931) Mon Oct 29 14:45:52 2018: Debug: Gaeste: MD5 on 'key' directive maps to: e1441074cac9707ffe85004a796a5062
(2931) Mon Oct 29 14:45:52 2018: Debug: Gaeste: Searching for an entry for key: '193.25.18.219 202162176'
(2931) Mon Oct 29 14:45:52 2018: Debug: Gaeste: Entry not found
(2931) Mon Oct 29 14:45:52 2018: Debug: [Gaeste] = notfound
(2931) Mon Oct 29 14:45:52 2018: Debug: } # accounting = notfound
(2931) Mon Oct 29 14:45:52 2018: Debug: Not sending reply to client.
(2931) Mon Oct 29 14:45:52 2018: Debug: Finished request
(2931) Mon Oct 29 14:45:52 2018: Debug: Cleaning up request packet ID 149 with timestamp +42
Does anyone know a similar behavior and has a tip for us?
The unabridged debug logs and the corresponding sites-available configuration (vpn) can be found in the appendix.
Many thanks in advance!
Yours sincerely
Lars Hillebrand
__
Fachhochschule Dortmund
University of Applied Sciences and Arts
Dipl.-Ing. (FH) Lars Hillebrand
Dez. VI, IT-Basisdienste
Sonnenstraße 100 - 44139 Dortmund
Raum SON D 008
Tel 0231 9112-253
Fax 0231 9112-338
lars.hillebrand at fh-dortmund.de
www.fh-dortmund.de
-------------- next part --------------
A non-text attachment was scrubbed...
Name: smime.p7s
Type: application/pkcs7-signature
Size: 4952 bytes
Desc: not available
URL: <http://lists.freeradius.org/pipermail/freeradius-users/attachments/20181029/487027b8/attachment.bin>
More information about the Freeradius-Users
mailing list