Hi ,
I have a problem with some user proxied.
In the accounting-request the username is stripped and realm is
NULL.
Why le realm is lost?
here is le debug output.
rad_recv: Access-Request packet from host 192.168.58.5 port 20007,
id=13, length=256
NAS-Port-Id = "AP59/1"
Calling-Station-Id = "98-0C-82-A0-9C-53"
Called-Station-Id = "00-26-3E-70-6F-C0:eduroam"
Service-Type = Framed-User
User-Name = "pierre.dupont@univ-lille1.fr"
NAS-Port = 13815
State = 0xce6b1f07c76006eefba5daa495da75ed
EAP-Message =
0x020b005019001703010020c523a88c2350d93086ec64726de2c365f717579f7b45e134cdc419b070885ab1170301002088cce6caf3b1d263d7731cb2b8c1c6e20b1967450888d652b5dc399cd6c8fe1a
NAS-Port-Type = Wireless-802.11
NAS-IP-Address = 192.168.58.5
NAS-Identifier = "Trapeze"
Message-Authenticator = 0x318ab29add69625365a854e67782de40
Wed Feb 6 10:08:07 2013 : Info: # Executing section authorize
from file /etc/freeradius/sites-enabled/eduroam
Wed Feb 6 10:08:07 2013 : Info: +- entering group authorize {...}
Wed Feb 6 10:08:07 2013 : Info: ++[preprocess] returns ok
Wed Feb 6 10:08:07 2013 : Info: ++? if (User-name !~
/^([^@]*)@(.+)$/)
Wed Feb 6 10:08:07 2013 : Info: ? Evaluating (User-name !~
/^([^@]*)@(.+)$/) -> FALSE
Wed Feb 6 10:08:07 2013 : Info: ++? if (User-name !~
/^([^@]*)@(.+)$/) -> FALSE
Wed Feb 6 10:08:07 2013 : Info: ++- entering else else {...}
Wed Feb 6 10:08:07 2013 : Info: +++[ok] returns ok
Wed Feb 6 10:08:07 2013 : Info: ++- else else returns ok
Wed Feb 6 10:08:07 2013 : Info: ++[mschap] returns noop
Wed Feb 6 10:08:07 2013 : Info: [suffix] Looking up realm
"univ-lille1.fr" for User-Name = "pierre.dupont@univ-lille1.fr"
Wed Feb 6 10:08:07 2013 : Info: [suffix] Found realm "~.+$"
Wed Feb 6 10:08:07 2013 : Info: [suffix] Adding Realm =
"univ-lille1.fr"
Wed Feb 6 10:08:07 2013 : Info: [suffix] Proxying request from
user pierre.dupont to realm ~.+$
Wed Feb 6 10:08:07 2013 : Info: [suffix] Preparing to proxy
authentication request to realm "~.+$"
Wed Feb 6 10:08:07 2013 : Info: ++[suffix] returns updated
Wed Feb 6 10:08:07 2013 : Info: [eap] Request is supposed to be
proxied to Realm ~.+$. Not doing EAP.
Wed Feb 6 10:08:07 2013 : Info: ++[eap] returns noop
Wed Feb 6 10:08:07 2013 : Info: ++[pap] returns noop
Wed Feb 6 10:08:07 2013 : Info: # Executing section pre-proxy
from file /etc/freeradius/sites-enabled/eduroam
Wed Feb 6 10:08:07 2013 : Info: +- entering group pre-proxy {...}
Wed Feb 6 10:08:07 2013 : Info: [pre_proxy_log] expand:
/var/log/freeradius/radacct/%{Client-IP-Address}/pre-proxy-detail-%Y%m%d
->
/var/log/freeradius/radacct/192.168.58.5/pre-proxy-detail-20130206
Wed Feb 6 10:08:07 2013 : Info: [pre_proxy_log]
/var/log/freeradius/radacct/%{Client-IP-Address}/pre-proxy-detail-%Y%m%d
expands to
/var/log/freeradius/radacct/192.168.58.5/pre-proxy-detail-20130206
Wed Feb 6 10:08:07 2013 : Info: [pre_proxy_log] expand: %t
-> Wed Feb 6 10:08:07 2013
Wed Feb 6 10:08:07 2013 : Info: ++[pre_proxy_log] returns ok
Wed Feb 6 10:08:07 2013 : Info: ++? if (Packet-Type !=
Accounting-Request)
Wed Feb 6 10:08:07 2013 : Info: ? Evaluating (Packet-Type !=
Accounting-Request) -> FALSE
Wed Feb 6 10:08:07 2013 : Info: ++? if (Packet-Type !=
Accounting-Request) -> FALSE
Sending Access-Request of id 223 to 193.51.224.109 port 1812
NAS-Port-Id = "AP59/1"
Calling-Station-Id = "98-0C-82-A0-9C-53"
Called-Station-Id = "00-26-3E-70-6F-C0:eduroam"
Service-Type = Framed-User
User-Name = "pierre.dupont@univ-lille1.fr"
NAS-Port = 13815
State = 0xce6b1f07c76006eefba5daa495da75ed
EAP-Message =
0x020b005019001703010020c523a88c2350d93086ec64726de2c365f717579f7b45e134cdc419b070885ab1170301002088cce6caf3b1d263d7731cb2b8c1c6e20b1967450888d652b5dc399cd6c8fe1a
NAS-Port-Type = Wireless-802.11
NAS-IP-Address = 192.168.58.5
NAS-Identifier = "Trapeze"
Message-Authenticator = 0x00000000000000000000000000000000
Proxy-State = 0x3133
Wed Feb 6 10:08:07 2013 : Info: Proxying request 223 to home
server 193.51.224.109 port 1812
Sending Access-Request of id 223 to 193.51.224.109 port 1812
NAS-Port-Id = "AP59/1"
Calling-Station-Id = "98-0C-82-A0-9C-53"
Called-Station-Id = "00-26-3E-70-6F-C0:eduroam"
Service-Type = Framed-User
User-Name = "pierre.dupont@univ-lille1.fr"
NAS-Port = 13815
State = 0xce6b1f07c76006eefba5daa495da75ed
EAP-Message =
0x020b005019001703010020c523a88c2350d93086ec64726de2c365f717579f7b45e134cdc419b070885ab1170301002088cce6caf3b1d263d7731cb2b8c1c6e20b1967450888d652b5dc399cd6c8fe1a
NAS-Port-Type = Wireless-802.11
NAS-IP-Address = 192.168.58.5
NAS-Identifier = "Trapeze"
Message-Authenticator = 0x00000000000000000000000000000000
Proxy-State = 0x3133
Wed Feb 6 10:08:07 2013 : Debug: Going to the next request
Wed Feb 6 10:08:07 2013 : Debug: Waking up in 0.9 seconds.
rad_recv: Access-Accept packet from host 193.51.224.109 port 1812,
id=223, length=182
User-Name = "pierre.dupont\000"
MS-MPPE-Recv-Key =
0x948d791f2da3af530868839e7df666aa1886290c40bfe70643d3cc079f9c24f4
MS-MPPE-Send-Key =
0x0a525d10d48467385a134bf6b1c4bee916e17fd24016a6f6c01b35ef243f07b2
EAP-Message = 0x030b0004
Message-Authenticator = 0xf6f125f6e9767f4dc8f9decb26a31021
Proxy-State = 0x3133
Wed Feb 6 10:08:07 2013 : Info: # Executing section post-proxy
from file /etc/freeradius/sites-enabled/eduroam
Wed Feb 6 10:08:07 2013 : Info: +- entering group post-proxy
{...}
Wed Feb 6 10:08:07 2013 : Info: [post_proxy_log] expand:
/var/log/freeradius/radacct/%{Client-IP-Address}/post-proxy-detail-%Y%m%d
->
/var/log/freeradius/radacct/192.168.58.5/post-proxy-detail-20130206
Wed Feb 6 10:08:07 2013 : Info: [post_proxy_log]
/var/log/freeradius/radacct/%{Client-IP-Address}/post-proxy-detail-%Y%m%d
expands to
/var/log/freeradius/radacct/192.168.58.5/post-proxy-detail-20130206
Wed Feb 6 10:08:07 2013 : Info: [post_proxy_log] expand: %t
-> Wed Feb 6 10:08:07 2013
Wed Feb 6 10:08:07 2013 : Info: ++[post_proxy_log] returns ok
Wed Feb 6 10:08:07 2013 : Info: [eap] No pre-existing handler
found
Wed Feb 6 10:08:07 2013 : Info: ++[eap] returns noop
Wed Feb 6 10:08:07 2013 : Info: Found Auth-Type = Accept
Wed Feb 6 10:08:07 2013 : Info: Auth-Type = Accept, accepting the
user
Wed Feb 6 10:08:07 2013 : Info: # Executing section post-auth
from file /etc/freeradius/sites-enabled/eduroam
Wed Feb 6 10:08:07 2013 : Info: +- entering group post-auth {...}
Wed Feb 6 10:08:07 2013 : Info: [linelog] expand:
%{reply:Packet-Type} -> Access-Accept
Wed Feb 6 10:08:07 2013 : Info: [linelog] expand:
%{%{reply:Packet-Type}:-format} -> Access-Accept
Wed Feb 6 10:08:07 2013 : Info: [linelog] expand:
/var/log/freeradius/linelog.log ->
/var/log/freeradius/linelog.log
Wed Feb 6 10:08:07 2013 : Info: [linelog] expand: %S
%{reply:Packet-Type} %{Packet-Src-IP-Address}
%{NAS-IP-Address} %{Client-Shortname} %{User-Name}
%{Calling-Station-Id} %{Called-Station-Id} -> 2013-02-06
10:08:07 Access-Accept 192.168.58.5 192.168.58.5
MX800R-2 pierre.dupont@univ-lille1.fr 98-0C-82-A0-9C-53
00-26-3E-70-6F-C0:eduroam
Wed Feb 6 10:08:07 2013 : Info: ++[linelog] returns ok
Wed Feb 6 10:08:07 2013 : Info: [f_ticks] expand:
%{reply:Packet-Type} -> Access-Accept
Wed Feb 6 10:08:07 2013 : Info: [f_ticks] expand:
f_ticks.%{%{reply:Packet-Type}:-format} ->
f_ticks.Access-Accept
Wed Feb 6 10:08:07 2013 : Info: [f_ticks] expand:
/var/log/freeradius/f_ticks.log ->
/var/log/freeradius/f_ticks.log
Wed Feb 6 10:08:07 2013 : Info: [f_ticks] expand: %S -
F-TICKS/eduroam/1.0#REALM=%{Realm}#VISCOUNTRY=FR#VISINST=LILLE3#CSI=%{Calling-Station-Id}#RESULT=OK
-> 2013-02-06 10:08:07 -
F-TICKS/eduroam/1.0#REALM=univ-lille1.fr#VISCOUNTRY=FR#VISINST=LILLE3#CSI=98-0C-82-A0-9C-53#RESULT=OK
Wed Feb 6 10:08:07 2013 : Info: ++[f_ticks] returns ok
Wed Feb 6 10:08:07 2013 : Info: expand: %{Realm} ->
univ-lille1.fr
Wed Feb 6 10:08:07 2013 : Info: ++- entering switch %{Realm}
{...}
Wed Feb 6 10:08:07 2013 : Info: +++- switch %{Realm} returns noop
Wed Feb 6 10:08:07 2013 : Info: ++- group post-auth returns noop
Wed Feb 6 10:08:07 2013 : Info: ++? if (("%{Realm}" !~
/^(ext\.|etu\.|)univ-lille3\.fr$/) &&
("%{Called-Station-Id}" =~
/^([0-9A-F]{2}-){5}[0-9A-F]{2}:eduroam$/))
Wed Feb 6 10:08:07 2013 : Info: expand: %{Realm} ->
univ-lille1.fr
Wed Feb 6 10:08:07 2013 : Info: ?? Evaluating ("%{Realm}" !~
/^(ext\.|etu\.|)univ-lille3\.fr$/) -> TRUE
Wed Feb 6 10:08:07 2013 : Info: expand: %{Called-Station-Id}
-> 00-26-3E-70-6F-C0:eduroam
Wed Feb 6 10:08:07 2013 : Info: ?? Evaluating
("%{Called-Station-Id}" =~
/^([0-9A-F]{2}-){5}[0-9A-F]{2}:eduroam$/) -> TRUE
Wed Feb 6 10:08:07 2013 : Info: ++? if (("%{Realm}" !~
/^(ext\.|etu\.|)univ-lille3\.fr$/) &&
("%{Called-Station-Id}" =~
/^([0-9A-F]{2}-){5}[0-9A-F]{2}:eduroam$/)) -> TRUE
Wed Feb 6 10:08:07 2013 : Info: ++- entering if (("%{Realm}" !~
/^(ext\.|etu\.|)univ-lille3\.fr$/) &&
("%{Called-Station-Id}" =~
/^([0-9A-F]{2}-){5}[0-9A-F]{2}:eduroam$/)) {...}
Wed Feb 6 10:08:07 2013 : Info: +++[reply] returns noop
Wed Feb 6 10:08:07 2013 : Info: ++- if (("%{Realm}" !~
/^(ext\.|etu\.|)univ-lille3\.fr$/) &&
("%{Called-Station-Id}" =~
/^([0-9A-F]{2}-){5}[0-9A-F]{2}:eduroam$/)) returns noop
Wed Feb 6 10:08:07 2013 : Info: ++[exec] returns noop
Sending Access-Accept of id 13 to 192.168.58.5 port 20007
User-Name = "pierre.dupont\000"
MS-MPPE-Recv-Key =
0x948d791f2da3af530868839e7df666aa1886290c40bfe70643d3cc079f9c24f4
MS-MPPE-Send-Key =
0x0a525d10d48467385a134bf6b1c4bee916e17fd24016a6f6c01b35ef243f07b2
EAP-Message = 0x030b0004
Message-Authenticator = 0x00000000000000000000000000000000
Tunnel-Type:0 = VLAN
Tunnel-Medium-Type:0 = IEEE-802
Tunnel-Private-Group-Id:0 = "56"
Wed Feb 6 10:08:07 2013 : Info: Finished request 223.
Wed Feb 6 10:08:07 2013 : Debug: Going to the next request
Wed Feb 6 10:08:07 2013 : Debug: Waking up in 1.5 seconds.
rad_recv: Accounting-Request packet from host 192.168.58.5 port
20007, id=14, length=222
Acct-Status-Type = Start
Acct-Authentic = RADIUS
Acct-Multi-Session-Id = "SESS-13815-54b752-141653-ef2"
Acct-Session-Id = "SESS-13815-54b752-141653-ef2"
User-Name = "pierre.dupont"
Event-Timestamp = "Feb 6 2013 10:08:07 CET"
Trapeze-VLAN-Name = "EduExterieurs"
Calling-Station-Id = "98-0C-82-A0-9C-53"
NAS-Port-Id = "AP59/1"
Called-Station-Id = "00-26-3E-70-6F-C0:eduroam"
NAS-Port = 13815
NAS-Port-Type = Wireless-802.11
NAS-IP-Address = 192.168.58.5
NAS-Identifier = "Trapeze"
Acct-Delay-Time = 0
Wed Feb 6 10:08:07 2013 : Info: # Executing section preacct from
file /etc/freeradius/sites-enabled/eduroam
Wed Feb 6 10:08:07 2013 : Info: +- entering group preacct {...}
Wed Feb 6 10:08:07 2013 : Info: ++[preprocess] returns ok
Wed Feb 6 10:08:07 2013 : Info: [linelog] expand:
%{reply:Packet-Type} -> 0
Wed Feb 6 10:08:07 2013 : Info: [linelog] expand:
%{%{reply:Packet-Type}:-format} -> 0
Wed Feb 6 10:08:07 2013 : Debug: WARNING: No such configuration
item .0
Wed Feb 6 10:08:07 2013 : Info: [linelog] No such entry ".0"
Wed Feb 6 10:08:07 2013 : Info: ++[linelog] returns noop
Wed Feb 6 10:08:07 2013 : Info: [acct_unique] Hashing 'NAS-Port =
13815,Client-IP-Address = 192.168.58.5,NAS-IP-Address =
192.168.58.5,Acct-Session-Id =
"SESS-13815-54b752-141653-ef2",User-Name = "pierre.dupont"'
Wed Feb 6 10:08:07 2013 : Info: [acct_unique]
Acct-Unique-Session-ID = "98d6d9a9c729efc3".
Wed Feb 6 10:08:07 2013 : Info: ++[acct_unique] returns ok
Wed Feb 6 10:08:07 2013 : Info: [suffix] No '@' in User-Name =
"pierre.dupont", looking up realm NULL
Wed Feb 6 10:08:07 2013 : Info: [suffix] Found realm "NULL"
Wed Feb 6 10:08:07 2013 : Info: [suffix] Adding
Stripped-User-Name = "pierre.dupont"
Wed Feb 6 10:08:07 2013 : Info: [suffix] Adding Realm = "NULL"
Wed Feb 6 10:08:07 2013 : Info: [suffix] Accounting realm is
LOCAL.
Wed Feb 6 10:08:07 2013 : Info: ++[suffix] returns ok
Wed Feb 6 10:08:07 2013 : Info: # Executing section accounting
from file /etc/freeradius/sites-enabled/eduroam
Wed Feb 6 10:08:07 2013 : Info: +- entering group accounting
{...}
Wed Feb 6 10:08:07 2013 : Info: [detail] expand:
%{Packet-Src-IP-Address} -> 192.168.58.5
Wed Feb 6 10:08:07 2013 : Info: [detail] expand:
/var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d
-> /var/log/freeradius/radacct/192.168.58.5/detail-20130206
Wed Feb 6 10:08:07 2013 : Info: [detail]
/var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d
expands to
/var/log/freeradius/radacct/192.168.58.5/detail-20130206
Wed Feb 6 10:08:07 2013 : Info: [detail] expand: %t -> Wed
Feb 6 10:08:07 2013
Wed Feb 6 10:08:07 2013 : Info: ++[detail] returns ok
Wed Feb 6 10:08:07 2013 : Info: [sql_acct] expand:
%{User-Name} -> pierre.dupont
Wed Feb 6 10:08:07 2013 : Info: [sql_acct] sql_set_user escaped
user --> 'pierre.dupont'
Wed Feb 6 10:08:07 2013 : Info: [sql_acct] expand:
%{Acct-Delay-Time} -> 0
Wed Feb 6 10:08:07 2013 : Info: [sql_acct] 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}',
Wed Feb 6 10:08:07 2013 : Info: [sql_acct] expand:
/var/log/freeradius/sqltrace.sql ->
/var/log/freeradius/sqltrace.sql
Wed Feb 6 10:08:07 2013 : Debug: rlm_sql (sql_acct): Reserving
sql socket id: 5
Wed Feb 6 10:08:07 2013 : Debug: rlm_sql_mysql:
query: 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
('SESS-13815-54b752-141653-ef2', '98d6d9a9c729efc3',
'pierre.dupont', 'NULL', '192.168.58.5',
'13815', 'Wireless-802.11', '2013-02-06 10:08:07',
NULL, '0', 'RADIUS', '', '', '0',
'0', '00-26-3E-70-6F-C0:eduroam',
'98-0C-82-A0-9C-53', '', '', '', '',
'0', '0', '')
Wed Feb 6 10:08:07 2013 : Debug: rlm_sql (sql_acct): Released sql
socket id: 5
Wed Feb 6 10:08:07 2013 : Info: ++[sql_acct] returns ok
Wed Feb 6 10:08:07 2013 : Info: ++[exec] returns noop
Wed Feb 6 10:08:07 2013 : Info: [attr_filter.accounting_response]
expand: %{User-Name} -> pierre.dupont
Wed Feb 6 10:08:07 2013 : Debug: attr_filter: Matched entry
DEFAULT at line 12
Wed Feb 6 10:08:07 2013 : Info:
++[attr_filter.accounting_response] returns updated
Sending Accounting-Response of id 14 to 192.168.58.5 port 20007
Wed Feb 6 10:08:07 2013 : Info: Finished request 224.
Wed Feb 6 10:08:07 2013 : Info: Cleaning up request 224 ID 14
with timestamp +229
Wed Feb 6 10:08:07 2013 : Debug: Going to the next request
Wed Feb 6 10:08:07 2013 : Debug: Waking up in 1.4 seconds.
rad_recv: Accounting-Request packet from host 192.168.58.5 port
20007, id=16, length=258
Acct-Status-Type = Interim-Update
Acct-Authentic = RADIUS
Acct-Multi-Session-Id = "SESS-13815-54b752-141653-ef2"
Acct-Session-Id = "SESS-13815-54b752-141653-ef2"
User-Name = "pierre.dupont"
Event-Timestamp = "Feb 6 2013 10:08:09 CET"
Trapeze-VLAN-Name = "EduExterieurs"
Calling-Station-Id = "98-0C-82-A0-9C-53"
NAS-Port-Id = "AP59/1"
Called-Station-Id = "00-26-3E-70-6F-C0:eduroam"
NAS-Port = 13815
Framed-IP-Address = 10.56.0.149
Acct-Session-Time = 2
Acct-Output-Octets = 9330
Acct-Input-Octets = 1202
Acct-Output-Packets = 38
Acct-Input-Packets = 230
NAS-Port-Type = Wireless-802.11
NAS-IP-Address = 192.168.58.5
NAS-Identifier = "Trapeze"
Acct-Delay-Time = 0
Wed Feb 6 10:08:09 2013 : Info: # Executing section preacct from
file /etc/freeradius/sites-enabled/eduroam
Wed Feb 6 10:08:09 2013 : Info: +- entering group preacct {...}
Wed Feb 6 10:08:09 2013 : Info: ++[preprocess] returns ok
Wed Feb 6 10:08:09 2013 : Info: [linelog] expand:
%{reply:Packet-Type} -> 0
Wed Feb 6 10:08:09 2013 : Info: [linelog] expand:
%{%{reply:Packet-Type}:-format} -> 0
Wed Feb 6 10:08:09 2013 : Debug: WARNING: No such configuration
item .0
Wed Feb 6 10:08:09 2013 : Info: [linelog] No such entry ".0"
Wed Feb 6 10:08:09 2013 : Info: ++[linelog] returns noop
Wed Feb 6 10:08:09 2013 : Info: [acct_unique] Hashing 'NAS-Port =
13815,Client-IP-Address = 192.168.58.5,NAS-IP-Address =
192.168.58.5,Acct-Session-Id =
"SESS-13815-54b752-141653-ef2",User-Name = "pierre.dupont"'
Wed Feb 6 10:08:09 2013 : Info: [acct_unique]
Acct-Unique-Session-ID = "98d6d9a9c729efc3".
Wed Feb 6 10:08:09 2013 : Info: ++[acct_unique] returns ok
Wed Feb 6 10:08:09 2013 : Info: [suffix] No '@' in User-Name =
"pierre.dupont", looking up realm NULL
Wed Feb 6 10:08:09 2013 : Info: [suffix] Found realm "NULL"
Wed Feb 6 10:08:09 2013 : Info: [suffix] Adding
Stripped-User-Name = "pierre.dupont"
Wed Feb 6 10:08:09 2013 : Info: [suffix] Adding Realm = "NULL"
Wed Feb 6 10:08:09 2013 : Info: [suffix] Accounting realm is
LOCAL.
Wed Feb 6 10:08:09 2013 : Info: ++[suffix] returns ok
Wed Feb 6 10:08:09 2013 : Info: # Executing section accounting
from file /etc/freeradius/sites-enabled/eduroam
Wed Feb 6 10:08:09 2013 : Info: +- entering group accounting
{...}
Wed Feb 6 10:08:09 2013 : Info: [detail] expand:
%{Packet-Src-IP-Address} -> 192.168.58.5
Wed Feb 6 10:08:09 2013 : Info: [detail] expand:
/var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d
-> /var/log/freeradius/radacct/192.168.58.5/detail-20130206
Wed Feb 6 10:08:09 2013 : Info: [detail]
/var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d
expands to
/var/log/freeradius/radacct/192.168.58.5/detail-20130206
Wed Feb 6 10:08:09 2013 : Info: [detail] expand: %t -> Wed
Feb 6 10:08:09 2013
Wed Feb 6 10:08:09 2013 : Info: ++[detail] returns ok
Wed Feb 6 10:08:09 2013 : Info: [sql_acct] expand:
%{User-Name} -> pierre.dupont
Wed Feb 6 10:08:09 2013 : Info: [sql_acct] sql_set_user escaped
user --> 'pierre.dupont'
Wed Feb 6 10:08:09 2013 : Info: [sql_acct] expand:
%{Acct-Input-Gigawords} ->
Wed Feb 6 10:08:09 2013 : Info: [sql_acct] ... expanding
second conditional
Wed Feb 6 10:08:09 2013 : Info: [sql_acct] expand:
%{Acct-Input-Octets} -> 1202
Wed Feb 6 10:08:09 2013 : Info: [sql_acct] expand:
%{Acct-Output-Gigawords} ->
Wed Feb 6 10:08:09 2013 : Info: [sql_acct] ... expanding
second conditional
Wed Feb 6 10:08:09 2013 : Info: [sql_acct] expand:
%{Acct-Output-Octets} -> 9330
Wed Feb 6 10:08:09 2013 : Info: [sql_acct] expand:
UPDATE radacct SET framedipaddress =
'%{Framed-IP-Address}', acctsessiontime =
'%{Acct-Session-Time}', 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 = '10.56.0.149',
acctsessiontime = '2', acctinputoctets = '0'
<< 32 |
'1202', acctoutputoctets = '0' << 32
| '9330' WHERE
acctsessionid = 'SESS-13815-54b752-141653-ef2' AND
username = 'yacine
Wed Feb 6 10:08:09 2013 : Info: [sql_acct] expand:
/var/log/freeradius/sqltrace.sql ->
/var/log/freeradius/sqltrace.sql
Wed Feb 6 10:08:09 2013 : Debug: rlm_sql (sql_acct): Reserving
sql socket id: 3
Wed Feb 6 10:08:09 2013 : Debug: rlm_sql_mysql:
query: UPDATE radacct SET
framedipaddress = '10.56.0.149', acctsessiontime
= '2', acctinputoctets = '0' << 32
| '1202',
acctoutputoctets = '0' << 32
| '9330' WHERE
acctsessionid = 'SESS-13815-54b752-141653-ef2' AND
username = 'pierre.dupont' AND nasipaddress =
'192.168.58.5'
Wed Feb 6 10:08:09 2013 : Debug: rlm_sql (sql_acct): Released sql
socket id: 3
Wed Feb 6 10:08:09 2013 : Info: ++[sql_acct] returns ok
Wed Feb 6 10:08:09 2013 : Info: ++[exec] returns noop
Wed Feb 6 10:08:09 2013 : Info: [attr_filter.accounting_response]
expand: %{User-Name} -> pierre.dupont
Wed Feb 6 10:08:09 2013 : Debug: attr_filter: Matched entry
DEFAULT at line 12
Wed Feb 6 10:08:09 2013 : Info:
++[attr_filter.accounting_response] returns updated
Sending Accounting-Response of id 16 to 192.168.58.5 port 20007
Wed Feb 6 10:08:09 2013 : Info: Finished request 226.
Wed Feb 6 10:08:09 2013 : Info: Cleaning up request 226 ID 16
with timestamp +231
Wed Feb 6 10:08:09 2013 : Debug: Going to the next request
Wed Feb 6 10:08:09 2013 : Debug: Waking up in 0.1 seconds.
Wed Feb 6 10:08:09 2013 : Info: Cleaning up request 216 ID 9 with
timestamp +226
Wed Feb 6 10:08:09 2013 : Info: Cleaning up request 217 ID 10
with timestamp +226
Wed Feb 6 10:08:09 2013 : Debug: Waking up in 2.7 seconds.
rad_recv: Accounting-Request packet from host 192.168.58.5 port
20007, id=17, length=258
Acct-Status-Type = Interim-Update
Acct-Authentic = RADIUS
Acct-Multi-Session-Id = "SESS-13815-54b752-141653-ef2"
Acct-Session-Id = "SESS-13815-54b752-141653-ef2"
User-Name = "pierre.dupont"
Event-Timestamp = "Feb 6 2013 10:08:10 CET"
Trapeze-VLAN-Name = "EduExterieurs"
Calling-Station-Id = "98-0C-82-A0-9C-53"
NAS-Port-Id = "AP59/1"
Called-Station-Id = "00-26-3E-70-6F-C0:eduroam"
NAS-Port = 13815
Framed-IP-Address = 10.71.113.16
Acct-Session-Time = 3
Acct-Output-Octets = 9508
Acct-Input-Octets = 1274
Acct-Output-Packets = 40
Acct-Input-Packets = 234
NAS-Port-Type = Wireless-802.11
NAS-IP-Address = 192.168.58.5
NAS-Identifier = "Trapeze"
Acct-Delay-Time = 0
Wed Feb 6 10:08:10 2013 : Info: # Executing section preacct from
file /etc/freeradius/sites-enabled/eduroam
Wed Feb 6 10:08:10 2013 : Info: +- entering group preacct {...}
Wed Feb 6 10:08:10 2013 : Info: ++[preprocess] returns ok
Wed Feb 6 10:08:10 2013 : Info: [linelog] expand:
%{reply:Packet-Type} -> 0
Wed Feb 6 10:08:10 2013 : Info: [linelog] expand:
%{%{reply:Packet-Type}:-format} -> 0
Wed Feb 6 10:08:10 2013 : Debug: WARNING: No such configuration
item .0
Wed Feb 6 10:08:10 2013 : Info: [linelog] No such entry ".0"
Wed Feb 6 10:08:10 2013 : Info: ++[linelog] returns noop
Wed Feb 6 10:08:10 2013 : Info: [acct_unique] Hashing 'NAS-Port =
13815,Client-IP-Address = 192.168.58.5,NAS-IP-Address =
192.168.58.5,Acct-Session-Id =
"SESS-13815-54b752-141653-ef2",User-Name = "pierre.dupont"'
Wed Feb 6 10:08:10 2013 : Info: [acct_unique]
Acct-Unique-Session-ID = "98d6d9a9c729efc3".
Wed Feb 6 10:08:10 2013 : Info: ++[acct_unique] returns ok
Wed Feb 6 10:08:10 2013 : Info: [suffix] No '@' in User-Name =
"pierre.dupont", looking up realm NULL
Wed Feb 6 10:08:10 2013 : Info: [suffix] Found realm "NULL"
Wed Feb 6 10:08:10 2013 : Info: [suffix] Adding
Stripped-User-Name = "pierre.dupont"
Wed Feb 6 10:08:10 2013 : Info: [suffix] Adding Realm = "NULL"
Wed Feb 6 10:08:10 2013 : Info: [suffix] Accounting realm is
LOCAL.
Wed Feb 6 10:08:10 2013 : Info: ++[suffix] returns ok
Wed Feb 6 10:08:10 2013 : Info: # Executing section accounting
from file /etc/freeradius/sites-enabled/eduroam
Wed Feb 6 10:08:10 2013 : Info: +- entering group accounting
{...}
Wed Feb 6 10:08:10 2013 : Info: [detail] expand:
%{Packet-Src-IP-Address} -> 192.168.58.5
Wed Feb 6 10:08:10 2013 : Info: [detail] expand:
/var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d
-> /var/log/freeradius/radacct/192.168.58.5/detail-20130206
Wed Feb 6 10:08:10 2013 : Info: [detail]
/var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d
expands to
/var/log/freeradius/radacct/192.168.58.5/detail-20130206
Wed Feb 6 10:08:10 2013 : Info: [detail] expand: %t -> Wed
Feb 6 10:08:10 2013
Wed Feb 6 10:08:10 2013 : Info: ++[detail] returns ok
Wed Feb 6 10:08:10 2013 : Info: [sql_acct] expand:
%{User-Name} -> pierre.dupont
Wed Feb 6 10:08:10 2013 : Info: [sql_acct] sql_set_user escaped
user --> 'pierre.dupont'
Wed Feb 6 10:08:10 2013 : Info: [sql_acct] expand:
%{Acct-Input-Gigawords} ->
Wed Feb 6 10:08:10 2013 : Info: [sql_acct] ... expanding
second conditional
Wed Feb 6 10:08:10 2013 : Info: [sql_acct] expand:
%{Acct-Input-Octets} -> 1274
Wed Feb 6 10:08:10 2013 : Info: [sql_acct] expand:
%{Acct-Output-Gigawords} ->
Wed Feb 6 10:08:10 2013 : Info: [sql_acct] ... expanding
second conditional
Wed Feb 6 10:08:10 2013 : Info: [sql_acct] expand:
%{Acct-Output-Octets} -> 9508
Wed Feb 6 10:08:10 2013 : Info: [sql_acct] expand:
UPDATE radacct SET framedipaddress =
'%{Framed-IP-Address}', acctsessiontime =
'%{Acct-Session-Time}', 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 = '10.71.113.16',
acctsessiontime = '3', acctinputoctets = '0'
<< 32 |
'1274', acctoutputoctets = '0' << 32
| '9508' WHERE
acctsessionid = 'SESS-13815-54b752-141653-ef2' AND
username = 'yacin
Wed Feb 6 10:08:10 2013 : Info: [sql_acct] expand:
/var/log/freeradius/sqltrace.sql ->
/var/log/freeradius/sqltrace.sql
Wed Feb 6 10:08:10 2013 : Debug: rlm_sql (sql_acct): Reserving
sql socket id: 2
Wed Feb 6 10:08:10 2013 : Debug: rlm_sql_mysql:
query: UPDATE radacct SET
framedipaddress = '10.71.113.16', acctsessiontime
= '3', acctinputoctets = '0' << 32
| '1274',
acctoutputoctets = '0' << 32
| '9508' WHERE
acctsessionid = 'SESS-13815-54b752-141653-ef2' AND
username = 'pierre.dupont' AND nasipaddress =
'192.168.58.5'
Wed Feb 6 10:08:10 2013 : Debug: rlm_sql (sql_acct): Released sql
socket id: 2
Wed Feb 6 10:08:10 2013 : Info: ++[sql_acct] returns ok
Wed Feb 6 10:08:10 2013 : Info: ++[exec] returns noop
Wed Feb 6 10:08:10 2013 : Info: [attr_filter.accounting_response]
expand: %{User-Name} -> pierre.dupont
Wed Feb 6 10:08:10 2013 : Debug: attr_filter: Matched entry
DEFAULT at line 12
Wed Feb 6 10:08:10 2013 : Info:
++[attr_filter.accounting_response] returns updated
Sending Accounting-Response of id 17 to 192.168.58.5 port 20007
Wed Feb 6 10:08:10 2013 : Info: Finished request 227.