AcctSessionTime missing in Interims-Update / calculated by FR
Hi, FR: 2.1.12 on Debian I have a probably easy and stupid problem: The Cisco ASA (5525-X, 9.4.4) doesn't send AcctSessionTime in "Interim-Update" so I want FR to just calculate it to be able to purge stale sessions (by a sep. cronjob) The f* ASA also doesn't send updates more than once an hour, so debugging is very time-consuming.. I have changed in /etc/freeradius/sql_log: --- cut --- Interim-Update = "UPDATE ${acct_table} \ SET AcctSessionTime = unix_timestamp(now()) - unix_timestamp(acctstarttime), \ AcctInputOctets = '%{Acct-Input-Octets}', \ AcctOutputOctets = '%{Acct-Output-Octets}' \ WHERE AcctSessionId = '%{Acct-Session-Id}' \ AND UserName = '%{User-Name}';" --- cut --- but it doesn't work, AcctSesssionTime in DB stays at 0 - though the remainder works still fine and logs to MySQL.. Any hints? Michael
what does the debug output show when this is hit? in the default sql_log there are similar recipes already present IIRC ..and if you are on 2.x you really should be on 2.2.10 alan
On Mar 23, 2018, at 3:17 PM, Michael Markstaller via Freeradius-Users <freeradius-users@lists.freeradius.org> wrote:
FR: 2.1.12 on Debian
Upgrade to 2.2.10. It's config compatible, and much better.
I have a probably easy and stupid problem:
The Cisco ASA (5525-X, 9.4.4) doesn't send AcctSessionTime in "Interim-Update" so I want FR to just calculate it to be able to purge stale sessions (by a sep. cronjob)
So... in preacct {...} section, do: if (!Acct-Session-Time && Acct-Start-Time) { update request { Acct-Session-Time := "%{expr:%l - %{Acct-Start-Time}}" } } That creates the Acct-Session-Time if it doesn't already exist. Alan DeKok.
Am 24.03.2018 um 13:23 schrieb Alan DeKok:
On Mar 23, 2018, at 3:17 PM, Michael Markstaller via Freeradius-Users <freeradius-users@lists.freeradius.org> wrote:
FR: 2.1.12 on Debian
Upgrade to 2.2.10. It's config compatible, and much better.
Got it, I'll just spawn up a new VM and do a clean install (I came to this probably messed up installation and unknown config like a virgin to a child.. well as it goes..) I'll report when things are well on Monday, as it's a pretty locked-in environment. P.S.: Good to see Alan still on top of the board, I haven't dealt with FR for ~8 yrs (as I just did other business, never ever another *perfect* RADIUS-server :) but fun: found most of the points in my own posts, partially 14yrs ago :-) Keep up the good work, Michael
Hi, now on FR 2.2.8 Ubuntu 16.04 LTS (do I really need 2.2.10?): 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 Acct-Session-Time: Unknown value 1522081 - for attribute Acct-Session-Time +++} # update request = fail ++} # if (!Acct-Session-Time && Acct-Start-Time) = fail +} # group preacct = fail --- Debug --- Any other ideas besides saving the timestamp %l in another field and calculated by crontab-SQL? Michael Am 24.03.2018 um 13:23 schrieb Alan DeKok:
On Mar 23, 2018, at 3:17 PM, Michael Markstaller via Freeradius-Users <freeradius-users@lists.freeradius.org> wrote:
FR: 2.1.12 on Debian
Upgrade to 2.2.10. It's config compatible, and much better.
I have a probably easy and stupid problem:
The Cisco ASA (5525-X, 9.4.4) doesn't send AcctSessionTime in "Interim-Update" so I want FR to just calculate it to be able to purge stale sessions (by a sep. cronjob)
So... in preacct {...} section, do:
if (!Acct-Session-Time && Acct-Start-Time) { update request { Acct-Session-Time := "%{expr:%l - %{Acct-Start-Time}}" } }
That creates the Acct-Session-Time if it doesn't already exist.
Alan DeKok.
On Mar 26, 2018, at 2:00 PM, Michael Markstaller via Freeradius-Users <freeradius-users@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.
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}}" } } Use that, and it will work.
Acct-Session-Time: Unknown value 1522081 - for attribute Acct-Session-Time
Because "1522081 -" isn't a valid integer.
Any other ideas besides saving the timestamp %l in another field and calculated by crontab-SQL?
Follow instructions? Don't make random changes without understanding *what* those changes are. Alan DeKok.
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@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
On Mar 26, 2018, at 10:08 PM, Michael Markstaller via Freeradius-Users <freeradius-users@lists.freeradius.org> wrote;
thanks again for your help!
It's what I do... I'm not *always* cranky.
It got me times factor 1000 too high: so I fiddled around wrong with the formula and parenthesis wrong - my fault - sorry ;)
Why was it 1000 times too high? %l is seconds. Acct-Start-Time is seconds.
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.
It doesn't. It has to look 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
That's a bit easier to fix: if ((Acct-Status-Type == Start) && !Acct-Start-Time) { update request { Acct-Start-Time := "%l" } }
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
And no Acct-Start-Time. Lovely.
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.
Not really. You should do: if ((Acct-Status-Type == Interim-Update) && Acct-Start-Time && !Acct-Session-Time) { update request { Acct-Session-Time := ... } }
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.
It's better to fix it in FR, and then write the correct information to the DB.
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..
Yeah. I've seen vendors who spend ~10M a year on Cisco get blown off for bug reports.
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.
Sure. Alan DeKok.
participants (3)
-
Alan Buxey -
Alan DeKok -
Michael Markstaller