pb with realm

6 Feb 2013

      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.

pb with realm

Hocine M