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