AcctSessionTime missing in Interims-Update / calculated by FR

Michael Markstaller michael at markstaller.de
Tue Mar 27 04:08:24 CEST 2018


Hi Alan,

thanks again for your help!


Am 26.03.2018 um 20:05 schrieb Alan DeKok:
> On Mar 26, 2018, at 2:00 PM, Michael Markstaller via Freeradius-Users <freeradius-users at lists.freeradius.org> wrote:
>> (do I really need 2.2.10?):
> 
>   Yes.
> 
>   Unless Ubuntu has back-ported security fixes from 2.2.10 to 2.2.8.  Which they might not have done.
> 
>   TBH, the fixes between 2.2.8 and 2.2.10 are bug fixes, and only bug fixes.  There's just no reason to run 2.2.8, much less distribute it as part of a "stable" release.
> 

Hmm, ok. I'm really a little bit out of this business maintaining
debian/ubuntu-packages and tracking which fixes were ported back (or
not) but a big friend of NOT using hand-crafted software form git etc.
in a production-environment like 16.04 LTS - as nobody can handle this
during the next update/upgrade..
Anyway, no issue, I'll give it a try..


>> I want a mainly stable and admin-friendly
>> "stock-setup" which is Ubuntu 16.04 here right now..
>> And my needs are also IMHO not very sophisticated, just acct to SQL
>> mitigating somehow what the ASA-developers obviously have missed while
>> reading the RADIUS-RFC :)
>>
>> Anyway, there is also no AcctStartTime in Interim-Update packets, so
>> Alans' suggestion fails
>>
>>
>> --- Debug ---
>> ++if (!Acct-Session-Time && Acct-Start-Time) {
>> +++update request {
>> 	expand: %l / 1000 -> 1522081439 / 1000
>> 	expand: %{expr:%l / 1000} - %{Acct-Start-Time} -> 1522081 -
>> ERROR: Failed parsing value "1522081 - " for attribute
> 
>   Uh... that's *not* what I suggested to do.  Please pay attention.
> 
>   The "expr" module does math.  You can't just put random math into the configuration and expect it to work.
> 
>   The "%l" is the Unix time in seconds.  Which is the same time system as Acct-Start-Time.  There is no need to divide %l by 1000.
> 
>   I said:
> 
> 	if (!Acct-Session-Time && Acct-Start-Time) {
> 		update request {
> 			Acct-Session-Time := "%{expr:%l - %{Acct-Start-Time}}"
> 		}
> 	}

It got me times factor 1000 too high: so I fiddled around wrong with the
formula and parenthesis wrong - my fault - sorry ;)

But as I have no Acct-Start-Time in the Interim-Update packet it still
fails, how should FR know in preacct about Acct-Start-Time without
looking at the database.

--- cut ---
rad_recv: Accounting-Request packet from host 172.x.x.x port 45045,
id=222, length=535
	User-Name = "W0xxxx"
	NAS-Port = 249856
	Service-Type = Framed-User
	Framed-Protocol = PPP
	Called-Station-Id = "1x.x.x.x"
	Calling-Station-Id = "2x.x.x.x"
	Acct-Status-Type = Start
	Acct-Delay-Time = 0
	Acct-Session-Id = "0CC0003D"
	Acct-Authentic = RADIUS
	NAS-Port-Type = Virtual
	Tunnel-Client-Endpoint:0 = "2x.x.x.x"
	Vendor-3076-Attr-146 = 0x45xxx
	Vendor-3076-Attr-150 = 0x00000006
	Vendor-3076-Attr-151 = 0x00000002
	Vendor-3076-Attr-152 = 0x00000003
	Cisco-AVPair = "mdm-tlv=device-platform=win"
	Cisco-AVPair = "mdm-tlv=device-mac=74-xxx"
	Cisco-AVPair = "audit-session-id=ac160a270003d0005ab98eec"
	Cisco-AVPair = "mdm-tlv=device-type=Fxxx"
	Cisco-AVPair = "mdm-tlv=device-platform-version=10.0.16299 "
	Cisco-AVPair = "mdm-tlv=device-uid=Fxxxx"
	NAS-IP-Address = 172.x.x.x
# Executing section preacct from file /etc/freeradius/sites-enabled/default
+group preacct {
++[preprocess] = ok
++? if (!Acct-Session-Time && Acct-Start-Time)
? Evaluating !(Acct-Session-Time ) -> TRUE
? Evaluating (Acct-Start-Time) -> TRUE
++? if (!Acct-Session-Time && Acct-Start-Time) -> TRUE
++if (!Acct-Session-Time && Acct-Start-Time) {
+++update request {
	expand: %l - %{Acct-Start-Time} -> 1522110184 -
	expand: %{expr:%l - %{Acct-Start-Time}} -> 1522110184
+++} # update request = noop
++} # if (!Acct-Session-Time && Acct-Start-Time) = noop
[acct_unique] WARNING: Attribute NAS-Identifier was not found in
request, unique ID MAY be inconsistent
[acct_unique] Hashing 'NAS-Port = 249856,,NAS-IP-Address =
172.x.x.x,Acct-Session-Id = "0CC0003D",User-Name = "W0xxxx"'
[acct_unique] Acct-Unique-Session-ID = "7223639885ceac94".
++[acct_unique] = ok
[suffix] No '@' in User-Name = "W0xxxx", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] = noop
++[files] = noop
+} # group preacct = ok
# Executing section accounting from file
/etc/freeradius/sites-enabled/default
+group accounting {
[detail] 	expand: %{Packet-Src-IP-Address} -> 172.x.x.x
[detail] 	expand:
/var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d
-> /var/log/freeradius/radacct/172.x.x.x/detail-20180327
[detail]
/var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d
expands to /var/log/freeradius/radacct/172.x.x.x/detail-20180327
[detail] 	expand: %t -> Tue Mar 27 02:23:04 2018
++[detail] = ok
[sql] 	expand: %{User-Name} -> W0xxxx
[sql] sql_set_user escaped user --> 'W0xxxx'
[sql] 	expand: %{Acct-Delay-Time} -> 0
[sql] 	expand:            INSERT INTO radacct
(acctsessionid,    acctuniqueid,     username,              realm,
     nasipaddress,     nasportid,              nasporttype,
acctstarttime,    acctstoptime,              acctsessiontime,
acctauthentic,    connectinfo_start,              connectinfo_stop,
acctinputoctets,  acctoutputoctets,              calledstationid,
callingstationid, acctterminatecause,              servicetype,
framedprotocol,   framedipaddress,              acctstartdelay,
acctstopdelay,    xascendsessionsvrkey)           VALUES
('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}',
'%{SQL-User-Name}',              '%{Realm}', '%{NAS-IP-Address}',
'%{NAS-Port}',              '%{NAS-Port-Type}', '%S', NULL,
'0', '%{Acct-Authentic}', '%{Connect-Info}',              '', '0', '0',
            '%{Called-Station-Id}', '%{Calling-Station-Id}', '',
     '%{Service-Type}', '%{Framed-Protocol}', '%{Framed-IP-Address}',
rlm_sql (sql): Reserving sql socket id: 31
rlm_sql (sql): Released sql socket id: 31
++[sql] = ok
++[exec] = noop
[attr_filter.accounting_response] 	expand: %{User-Name} -> W0xxxx
attr_filter: Matched entry DEFAULT at line 12
++[attr_filter.accounting_response] = updated
+} # group accounting = updated
Sending Accounting-Response of id 222 to 172.x.x.x port 45045
Finished request 0.
Cleaning up request 0 ID 222 with timestamp +37
Going to the next request
Ready to process requests.
rad_recv: Accounting-Request packet from host 172.x.x.x port 45045,
id=223, length=565
	User-Name = "W0xxxx"
	NAS-Port = 249856
	Service-Type = Framed-User
	Framed-Protocol = PPP
	Framed-IP-Address = 172.y.x.x
	Called-Station-Id = "1x.x.x.x"
	Calling-Station-Id = "2x.x.x.x"
	Acct-Status-Type = Interim-Update
	Acct-Delay-Time = 0
	Acct-Input-Octets = 0
	Acct-Output-Octets = 0
	Acct-Session-Id = "0CC0003D"
	Acct-Authentic = RADIUS
	Acct-Input-Packets = 0
	Acct-Output-Packets = 0
	NAS-Port-Type = Virtual
	Tunnel-Client-Endpoint:0 = "2x.x.x.x"
	Vendor-3076-Attr-146 = 0x4xxx
	Vendor-3076-Attr-150 = 0x00000006
	Vendor-3076-Attr-151 = 0x00000002
	Vendor-3076-Attr-152 = 0x00000003
	Cisco-AVPair = "mdm-tlv=device-platform=win"
	Cisco-AVPair = "mdm-tlv=device-mac=74-xxx"
	Cisco-AVPair = "audit-session-id=ac160a270003d0005ab98eec"
	Cisco-AVPair = "mdm-tlv=device-type=Fxxx"
	Cisco-AVPair = "mdm-tlv=device-platform-version=10.0.16299 "
	Cisco-AVPair = "mdm-tlv=device-uid=Fxxxx"
	NAS-IP-Address = 172.x.x.x
# Executing section preacct from file /etc/freeradius/sites-enabled/default
+group preacct {
++[preprocess] = ok
++? if (!Acct-Session-Time && Acct-Start-Time)
? Evaluating !(Acct-Session-Time ) -> TRUE
? Evaluating (Acct-Start-Time) -> TRUE
++? if (!Acct-Session-Time && Acct-Start-Time) -> TRUE
++if (!Acct-Session-Time && Acct-Start-Time) {
+++update request {
	expand: %l - %{Acct-Start-Time} -> 1522110184 -
	expand: %{expr:%l - %{Acct-Start-Time}} -> 1522110184
+++} # update request = noop
++} # if (!Acct-Session-Time && Acct-Start-Time) = noop
[acct_unique] WARNING: Attribute NAS-Identifier was not found in
request, unique ID MAY be inconsistent
[acct_unique] Hashing 'NAS-Port = 249856,,NAS-IP-Address =
172.x.x.x,Acct-Session-Id = "0CC0003D",User-Name = "W0xxxx"'
[acct_unique] Acct-Unique-Session-ID = "7223639885ceac94".
++[acct_unique] = ok
[suffix] No '@' in User-Name = "W0xxxx", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] = noop
++[files] = noop
+} # group preacct = ok
# Executing section accounting from file
/etc/freeradius/sites-enabled/default
+group accounting {
[detail] 	expand: %{Packet-Src-IP-Address} -> 172.x.x.x
[detail] 	expand:
/var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d
-> /var/log/freeradius/radacct/172.x.x.x/detail-20180327
[detail]
/var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d
expands to /var/log/freeradius/radacct/172.x.x.x/detail-20180327
[detail] 	expand: %t -> Tue Mar 27 02:23:04 2018
++[detail] = ok
[sql] 	expand: %{User-Name} -> W0xxxx
[sql] sql_set_user escaped user --> 'W0xxxx'
[sql] 	expand: %{Acct-Session-Time} -> 1522110184
[sql] 	expand: %{Acct-Input-Gigawords} ->
[sql] 	... expanding second conditional
[sql] 	expand: %{Acct-Input-Octets} -> 0
[sql] 	expand: %{Acct-Output-Gigawords} ->
[sql] 	... expanding second conditional
[sql] 	expand: %{Acct-Output-Octets} -> 0
[sql] 	expand:            UPDATE radacct           SET
framedipaddress = '%{Framed-IP-Address}',              acctsessiontime
  = '%{%{Acct-Session-Time}:-0}',              acctinputoctets     =
'%{%{Acct-Input-Gigawords}:-0}'  << 32 |
   '%{%{Acct-Input-Octets}:-0}',              acctoutputoctets    =
'%{%{Acct-Output-Gigawords}:-0}' << 32 |
   '%{%{Acct-Output-Octets}:-0}'           WHERE acctsessionid =
'%{Acct-Session-Id}'           AND username        = '%{SQL-User-Name}'
         AND nasipaddress    = '%{NAS-IP-Address}' ->            UPDATE
radacct           SET              framedipaddress = '172.y.x.x',
      acctsessiontime     = '1522110184',              acctinputoctets
  = '0'  << 32 |                                    '0',
acctoutputoctets    = '0' << 32 |                                    '0'
          WHERE acctsessionid = '0CC0003D'           AND username
= 'W0PROD99ADM013.prod.a
rlm_sql (sql): Reserving sql socket id: 30
rlm_sql (sql): Released sql socket id: 30
++[sql] = ok
++[exec] = noop
[attr_filter.accounting_response] 	expand: %{User-Name} -> W0xxxx
attr_filter: Matched entry DEFAULT at line 12
++[attr_filter.accounting_response] = updated
+} # group accounting = updated
Sending Accounting-Response of id 223 to 172.x.x.x port 45045
Finished request 1.
Cleaning up request 1 ID 223 with timestamp +37
Going to the next request
Ready to process requests.
--- cut ---


gives me AcctSessionTime of 1522110184 in DB which is pretty clear as
the substracted AcctStartTime is still 0/NULL in this context.
So my AcctSessionTime is simply the timestamp of the last update.
Good enough.

Good and persistent solution: No!

But still: it gave me an Idea how to get to a result in the reports
anyway: just use the (wrong) AcctSessionTime from the SQL-DB - substract
AcctStartTime from DB, easy, et voila ;-)
Fix it in the display with wrong data in the backend: not neat but working.


P.S.: -> I'm fully aware that the source of the problem is the ASA not
sending AcctSessionTime and AcctStartTime, not FR - but I'm too old and
experienced to open a Bug at Cisco which is usually unfortunately
totally useless..
Though, I think about opening a bug at Cisco: because the 1hrs minimum
Interim-Update interval of the ASA is an absolute No-Go and ridiculous..
Because the base for all of this is: I want to see the status of my
clients/users in nearly realtime to be able to support them at best.

Michael


More information about the Freeradius-Users mailing list