Accounting question
David Peterson
davidp at wirelessconnections.net
Tue Dec 15 19:10:20 CET 2009
What I am not understanding at this point is how the authentication works with the username "hashed" or using "hex stuff" but the accounting doesn't. You can see on this debug that the username looks the same when its authenticated as it does when it's used for accounting yet the username in the database is clear text.
rad_recv: Access-Request packet from host 172.16.4.2 port 1812, id=152, length=192
User-Name = "{am=1}1F48C19B43C8C33846FAA9CFC58990F4 at test.com"
EAP-Message = 0x020800061500
Message-Authenticator = 0xdf8d44589c8c07b9f6ca5d31ce4e23e6
NAS-Identifier = "WC_LAB"
NAS-IP-Address = 172.16.4.2
Calling-Station-Id = "00-12-CF-C3-FB-8C"
WiMAX-BS-Id = 0x000002030209
NAS-Port-Type = 27
Framed-MTU = 2000
Service-Type = Framed-User
WiMAX-GMT-Timezone-offset = 0
State = 0x7b727fb77d7a6afd64224fae48c09695
Tue Dec 15 12:03:56 2009 : Info: +- entering group authorize {...} Tue Dec 15 12:03:56 2009 : Info: ++[preprocess] returns ok Tue Dec 15 12:03:56 2009 : Info: ++[chap] returns noop Tue Dec 15 12:03:56 2009 : Info: ++[mschap] returns noop Tue Dec 15 12:03:56 2009 : Info: ++[wimax] returns ok Tue Dec 15 12:03:56 2009 : Info: [suffix] Looking up realm "test.com" for User-Name = "{am=1}1F48C19B43C8C33846FAA9CFC58990F4 at test.com"
Tue Dec 15 12:03:56 2009 : Info: [suffix] Found realm "test.com"
Tue Dec 15 12:03:56 2009 : Info: [suffix] Adding Stripped-User-Name = "{am=1}1F48C19B43C8C33846FAA9CFC58990F4"
Tue Dec 15 12:03:56 2009 : Info: [suffix] Adding Realm = "test.com"
Tue Dec 15 12:03:56 2009 : Info: [suffix] Authentication realm is LOCAL.
Tue Dec 15 12:03:56 2009 : Info: ++[suffix] returns ok Tue Dec 15 12:03:56 2009 : Info: [eap] EAP packet type response id 8 length 6 Tue Dec 15 12:03:56 2009 : Info: [eap] Continuing tunnel setup.
Tue Dec 15 12:03:56 2009 : Info: ++[eap] returns ok Tue Dec 15 12:03:56 2009 : Info: Found Auth-Type = EAP Tue Dec 15 12:03:56 2009 : Info: +- entering group authenticate {...} Tue Dec 15 12:03:56 2009 : Info: [eap] Request found, released from the list Tue Dec 15 12:03:56 2009 : Info: [eap] EAP/ttls Tue Dec 15 12:03:56 2009 : Info: [eap] processing type ttls Tue Dec 15 12:03:56 2009 : Info: [ttls] Authenticate Tue Dec 15 12:03:56 2009 : Info: [ttls] processing EAP-TLS Tue Dec 15 12:03:56 2009 : Info: [ttls] Received TLS ACK Tue Dec 15 12:03:56 2009 : Info: [ttls] ACK handshake is finished Tue Dec 15 12:03:56 2009 : Info: [ttls] eaptls_verify returned 3 Tue Dec 15 12:03:56 2009 : Info: [ttls] eaptls_process returned 3 Tue Dec 15 12:03:56 2009 : Info: [eap] Freeing handler Tue Dec 15 12:03:56 2009 : Info: ++[eap] returns ok Tue Dec 15 12:03:56 2009 : Info: +- entering group post-auth {...} Tue Dec 15 12:03:56 2009 : Info: [sql] expand: %{User-Name} -> {am=1}1F48C19B43C8C33846FAA9CFC58990F4 at test.com
Tue Dec 15 12:03:56 2009 : Info: [sql] sql_set_user escaped user --> '{am=1}1F48C19B43C8C33846FAA9CFC58990F4 at test.com'
Tue Dec 15 12:03:56 2009 : Info: [sql] expand: %{User-Password} -> Tue Dec 15 12:03:56 2009 : Info: [sql] expand: %{Chap-Password} ->
Tue Dec 15 12:03:56 2009 : Info: [sql] expand: INSERT INTO radpostauth (user, pass, reply, date) VALUES ( '%{User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S') -> INSERT INTO radpostauth (user, pass, reply, date) VALUES ( '=7Bam=3D1=7D1F48C19B43C8C33846FAA9CFC58990F4 at test.com', '', 'Access-Accept', '2009-12-15 12:03:56')
Tue Dec 15 12:03:56 2009 : Debug: rlm_sql (sql) in sql_postauth: query is INSERT INTO radpostauth (user, pass, reply, date) VALUES ( '=7Bam=3D1=7D1F48C19B43C8C33846FAA9CFC58990F4 at test.com', '', 'Access-Accept', '2009-12-15 12:03:56')
Tue Dec 15 12:03:56 2009 : Debug: rlm_sql (sql): Reserving sql socket id: 4 Tue Dec 15 12:03:56 2009 : Debug: rlm_sql (sql): Released sql socket id: 4 Tue Dec 15 12:03:56 2009 : Info: ++[sql] returns ok Tue Dec 15 12:03:56 2009 : Info: [wimax] MIP-RK = 0x8bbaf6bac41676e1fea6f3a75b5ee6ef94a178d9f52f48068c9b23ccc461aa02a10b5d2bd04a0166461374ec608a81eb4969e526897ae8062732a09112962ef5
Tue Dec 15 12:03:56 2009 : Info: [wimax] MIP-SPI = e5cf883a Tue Dec 15 12:03:56 2009 : Info: [wimax] WARNING: WiMAX-MN-NAI was not found in the request or in the reply.
Tue Dec 15 12:03:56 2009 : Info: [wimax] WARNING: We cannot calculate MN-HA keys.
Tue Dec 15 12:03:56 2009 : Info: [wimax] WARNING: WiMAX-IP-Technology not found in reply.
Tue Dec 15 12:03:56 2009 : Info: [wimax] WARNING: Not calculating MN-HA keys Tue Dec 15 12:03:56 2009 : Info: ++[wimax] returns updated Sending Access-Accept of id 152 to 172.16.4.2 port 1812
User-Name = "test at test.com"
Framed-Filter-Id := "Silver"
EAP-Message = 0x03080004
Message-Authenticator = 0x00000000000000000000000000000000
WiMAX-MSK = 0x737de83d5678db5bd59d21f5f254922b253974cc3aad05dd5bed123a33ba4158dfac34faae6808255f5fe931271c7590a6aef9bdda4e7d55ad1fb807d1ade735
Tue Dec 15 12:03:56 2009 : Info: Finished request 7.
Tue Dec 15 12:03:56 2009 : Debug: Going to the next request Tue Dec 15 12:03:56 2009 : Debug: Waking up in 2.0 seconds.
Tue Dec 15 12:03:58 2009 : Info: Cleaning up request 0 ID 145 with timestamp +63 Tue Dec 15 12:03:58 2009 : Debug: Waking up in 0.1 seconds.
Tue Dec 15 12:03:58 2009 : Info: Cleaning up request 1 ID 146 with timestamp +63 Tue Dec 15 12:03:58 2009 : Debug: Waking up in 0.2 seconds.
Tue Dec 15 12:03:59 2009 : Info: Cleaning up request 2 ID 147 with timestamp +63 Tue Dec 15 12:03:59 2009 : Debug: Waking up in 0.4 seconds.
Tue Dec 15 12:03:59 2009 : Info: Cleaning up request 3 ID 148 with timestamp +64 Tue Dec 15 12:03:59 2009 : Debug: Waking up in 0.4 seconds.
Tue Dec 15 12:03:59 2009 : Info: Cleaning up request 4 ID 149 with timestamp +64 Tue Dec 15 12:03:59 2009 : Debug: Waking up in 0.8 seconds.
Tue Dec 15 12:04:00 2009 : Info: Cleaning up request 5 ID 150 with timestamp +65 Tue Dec 15 12:04:00 2009 : Debug: Waking up in 0.6 seconds.
rad_recv: Accounting-Request packet from host 172.16.4.2 port 1813, id=13, length=239
Acct-Status-Type = Start
WiMAX-Beginning-Of-Session = 1
WiMAX-IP-Technology = Reserved-0
Acct-Session-Id = "00-12-cf-c3-fb-8c7\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000"
Framed-IP-Address = 64.186.195.5
User-Name = "{am=1}1F48C19B43C8C33846FAA9CFC58990F4 at test.com"
Calling-Station-Id = "00-12-cf-c3-fb-8c"
NAS-Identifier = "WC_LAB"
NAS-IP-Address = 172.16.4.2
WiMAX-BS-Id = 0x000002030209
Framed-Pool = "alias"
Event-Timestamp = "Dec 15 2009 12:03:50 CST"
WiMAX-GMT-Timezone-offset = 21600
Acct-Authentic = RADIUS
Tue Dec 15 12:04:00 2009 : Info: +- entering group preacct {...} Tue Dec 15 12:04:00 2009 : Info: ++[preprocess] returns ok Tue Dec 15 12:04:00 2009 : Info: [acct_unique] WARNING: Attribute NAS-Port was not found in request, unique ID MAY be inconsistent Tue Dec 15 12:04:00 2009 : Info: [acct_unique] Hashing ',Client-IP-Address = 172.16.4.2,NAS-IP-Address = 172.16.4.2,Acct-Session-Id = "00-12-cf-c3-fb-8c7\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000",User-Name = "{am=1}1F48C19B43C8C33846FAA9CFC58990F4 at test.com"'
Tue Dec 15 12:04:00 2009 : Info: [acct_unique] Acct-Unique-Session-ID = "a4c0011657ec8b3b".
Tue Dec 15 12:04:00 2009 : Info: ++[acct_unique] returns ok Tue Dec 15 12:04:00 2009 : Info: [suffix] Looking up realm "test.com" for User-Name = "{am=1}1F48C19B43C8C33846FAA9CFC58990F4 at test.com"
Tue Dec 15 12:04:00 2009 : Info: [suffix] Found realm "test.com"
Tue Dec 15 12:04:00 2009 : Info: [suffix] Adding Stripped-User-Name = "{am=1}1F48C19B43C8C33846FAA9CFC58990F4"
Tue Dec 15 12:04:00 2009 : Info: [suffix] Adding Realm = "test.com"
Tue Dec 15 12:04:00 2009 : Info: [suffix] Accounting realm is LOCAL.
Tue Dec 15 12:04:00 2009 : Info: ++[suffix] returns ok Tue Dec 15 12:04:00 2009 : Info: [files] acct_users: Matched entry DEFAULT at line 22 Tue Dec 15 12:04:00 2009 : Info: [files] WARNING: Deprecated conditional expansion ":-". See "man unlang" for details
Tue Dec 15 12:04:00 2009 : Info: [files] expand: %{Stripped-User-Name:-%{User-Name}} -> {am=1}1F48C19B43C8C33846FAA9CFC58990F4
Tue Dec 15 12:04:00 2009 : Info: ++[files] returns ok Tue Dec 15 12:04:00 2009 : Info: +- entering group accounting {...}
Tue Dec 15 12:04:00 2009 : Info: [detail] expand: /var/log/freeradius/radacct/%{Client-IP-Address}/detail-%Y%m%d -> /var/log/freeradius/radacct/172.16.4.2/detail-20091215
Tue Dec 15 12:04:00 2009 : Info: [detail] /var/log/freeradius/radacct/%{Client-IP-Address}/detail-%Y%m%d expands to /var/log/freeradius/radacct/172.16.4.2/detail-20091215
Tue Dec 15 12:04:00 2009 : Info: [detail] expand: %t -> Tue Dec 15 12:04:00 2009
Tue Dec 15 12:04:00 2009 : Info: ++[detail] returns ok
Tue Dec 15 12:04:00 2009 : Info: [radutmp] expand: /var/log/freeradius/radutmp -> /var/log/freeradius/radutmp
Tue Dec 15 12:04:00 2009 : Info: [radutmp] expand: %{User-Name} -> {am=1}1F48C19B43C8C33846FAA9CFC58990F4 at test.com
Tue Dec 15 12:04:00 2009 : Debug: rlm_radutmp: No NAS-Port seen. Cannot do anything.
Tue Dec 15 12:04:00 2009 : Debug: rlm_radumtp: WARNING: checkrad will probably not work!
Tue Dec 15 12:04:00 2009 : Info: ++[radutmp] returns noop Tue Dec 15 12:04:00 2009 : Info: [sql] expand: %{User-Name} -> {am=1}1F48C19B43C8C33846FAA9CFC58990F4 at test.com
Tue Dec 15 12:04:00 2009 : Info: [sql] sql_set_user escaped user --> '{am=1}1F48C19B43C8C33846FAA9CFC58990F4 at test.com'
Tue Dec 15 12:04:00 2009 : Info: [sql] expand: %{Acct-Delay-Time} ->
Tue Dec 15 12:04:00 2009 : Info: [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}',
Tue Dec 15 12:04:00 2009 : Debug: rlm_sql (sql): Reserving sql socket id: 3 Tue Dec 15 12:04:00 2009 : Debug: rlm_sql_mysql: MYSQL check_error: 1048 received Tue Dec 15 12:04:00 2009 : Error: [sql] Couldn't insert SQL accounting START record - Column 'AcctStopTime' cannot be null Tue Dec 15 12:04:00 2009 : Info: [sql] expand: %{Acct-Delay-Time} ->
Tue Dec 15 12:04:00 2009 : Info: [sql] expand: UPDATE radacct SET acctstarttime = '%S', acctstartdelay = '%{%{Acct-Delay-Time}:-0}', connectinfo_start = '%{Connect-Info}' WHERE acctsessionid = '%{Acct-Session-Id}' AND username = '%{SQL-User-Name}' AND nasipaddress = '%{NAS-IP-Address}' -> UPDATE radacct SET acctstarttime = '2009-12-15 12:04:00', acctstartdelay = '0', connectinfo_start = '' WHERE acctsessionid = '00-12-cf-c3-fb-8c7' AND username = '=7Bam=3D1=7D1F48C19B43C8C33846FAA9CFC58990F4 at test.com' AND nasipaddress = '172.16.4.2'
Tue Dec 15 12:04:00 2009 : Debug: rlm_sql (sql): Released sql socket id: 3 Tue Dec 15 12:04:00 2009 : Info: ++[sql] returns ok
Tue Dec 15 12:04:00 2009 : Info: [attr_filter.accounting_response] expand: %{User-Name} -> {am=1}1F48C19B43C8C33846FAA9CFC58990F4 at test.com
-----Original Message-----
From: Arran Cudbard-Bell [mailto:A.Cudbard-Bell at sussex.ac.uk]
Sent: Tuesday, December 15, 2009 10:56 AM
To: David Peterson-WirelessConnections; FreeRadius users mailing list
Subject: Re: Accounting question
David Peterson wrote:
> Here is the accounting packet information I am getting:
> rad_recv: Accounting-Request packet from host 172.16.4.2 port 1813, id=5,
> length=239
> Acct-Status-Type = Start
> WiMAX-Beginning-Of-Session = 1
> WiMAX-IP-Technology = Reserved-0
> Acct-Session-Id =
> "00-12-cf-c3-fb-8c3\000\000\000\000\000\000\000\000\000\000\000\000\000\000\
> 000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000"
> Framed-IP-Address = 64.186.195.5
> User-Name = "{am=1}33AC5579CE57217426E7434FA60E4E65 at test.com"
> Calling-Station-Id = "00-12-cf-c3-fb-8c"
> NAS-Identifier = "WC_LAB"
> NAS-IP-Address = 172.16.4.2
> WiMAX-BS-Id = 0x000002030209
> Framed-Pool = "alias"
> Event-Timestamp = "Dec 15 2009 09:04:15 CST"
> WiMAX-GMT-Timezone-offset = 21600
> Acct-Authentic = RADIUS
>
> What I don't get is why the authentication works with clear text and the
> accounting has the "hex stuff". Is this pretty much controlled by the NAS?
The "hex stuff" is the NAS appending 31 null chars to the session id.
FreeRADIUS is converting the unprintable characters into escape codes so that they're visible.
The RFC recommendation is that:
"The Acct-Session-Id SHOULD contain UTF-8 encoded 10646 [7] characters."
Which SHOULD limit it to printable chars.
Really this is something your NAS vendor should fix, as it's a bug in their code.
...Though if you really want you can trim off the superfluous nulls with:
if(Acct-Session-ID =~ /(.*)/){
update request {
Acct-Session-ID := "%{1}"
}
}
-Arran
>
> David
>
> -----Original Message-----
> From: Alan DeKok [mailto:aland at deployingradius.com]
> Sent: Tuesday, December 15, 2009 9:44 AM
> To: David Peterson-WirelessConnections; FreeRadius users mailing list
> Subject: Re: Accounting question
>
> David Peterson wrote:
>> From what I can determine, the username is encrypted even though the
>> authentication is done in clear text during the EAP authentication.
>
> It's not "encrypted". My guess is that you are using WiMAX.
>
> As always, run the server in debugging mode to see what's going on.
>
> But if the NAS refuses to send a usable User-Name in an accounting
> packet, your only solution is to somehow write the *real* User-Name &&
> the hex stuff into an SQL table. Then, correlated them later when you
> receive the accounting packet.
>
> Alan DeKok.
>
> -
> List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
More information about the Freeradius-Users
mailing list