Hello Mr. Alan, Thank you for answering.
Below, you will find a working local authentication, user [EMAIL PROTECTED] (without proxy), where the VSA "ERX-Service-Bundle" is found in radreply (although the debug doesn't says that) and sent back to the B-RAS: rad_recv: Access-Request packet from host 192.168.1.1:50000, id=29, length=238 Mon Jun 11 11:18:18 2007 : Debug: --- Walking the entire request list --- Mon Jun 11 11:18:18 2007 : Debug: Waking up in 31 seconds... Mon Jun 11 11:18:18 2007 : Debug: Thread 2 got semaphore Mon Jun 11 11:18:18 2007 : Debug: Thread 2 handling request 1, (1 handled so far) User-Password = "testing" User-Name = "[EMAIL PROTECTED]" Acct-Session-Id = "erx atm 3/2.42:100.132:0002097381" Service-Type = Framed-User Framed-Protocol = PPP ERX-Pppoe-Description = "pppoe 12:34:56:78:9a:bc" Calling-Station-Id = "#BRAS-03#this is a description#100#132" Connect-Info = "speed:UBR:12000" NAS-Port-Type = xDSL NAS-Port = 845414532 NAS-Port-Id = "atm 3/2.42:100.132" NAS-IP-Address = 192.168.1.1 NAS-Identifier = "BRAS-03" Mon Jun 11 11:18:18 2007 : Debug: Processing the authorize section of radiusd.conf Mon Jun 11 11:18:18 2007 : Debug: modcall: entering group authorize for request 1 Mon Jun 11 11:18:18 2007 : Debug: modsingle[authorize]: calling preprocess (rlm_preprocess) for request 1 Mon Jun 11 11:18:18 2007 : Debug: modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 1 Mon Jun 11 11:18:18 2007 : Debug: modcall[authorize]: module "preprocess" returns ok for request 1 Mon Jun 11 11:18:18 2007 : Debug: modsingle[authorize]: calling auth_log (rlm_detail) for request 1 Mon Jun 11 11:18:18 2007 : Debug: radius_xlat: '/usr/local/var/log/radius/radacct/192.168.1.1/auth-detail-20070611' Mon Jun 11 11:18:18 2007 : Debug: rlm_detail: /usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d expands to /usr/local/var/log/radius/radacct/192.168.1.1/auth-detail-20070611 Mon Jun 11 11:18:18 2007 : Debug: modsingle[authorize]: returned from auth_log (rlm_detail) for request 1 Mon Jun 11 11:18:18 2007 : Debug: modcall[authorize]: module "auth_log" returns ok for request 1 Mon Jun 11 11:18:18 2007 : Debug: modsingle[authorize]: calling chap (rlm_chap) for request 1 Mon Jun 11 11:18:18 2007 : Debug: modsingle[authorize]: returned from chap (rlm_chap) for request 1 Mon Jun 11 11:18:18 2007 : Debug: modcall[authorize]: module "chap" returns noop for request 1 Mon Jun 11 11:18:18 2007 : Debug: modsingle[authorize]: calling suffix (rlm_realm) for request 1 Mon Jun 11 11:18:18 2007 : Debug: rlm_realm: Looking up realm "local.com" for User-Name = "[EMAIL PROTECTED]" Mon Jun 11 11:18:18 2007 : Debug: rlm_realm: No such realm "local.com" Mon Jun 11 11:18:18 2007 : Debug: modsingle[authorize]: returned from suffix (rlm_realm) for request 1 Mon Jun 11 11:18:18 2007 : Debug: modcall[authorize]: module "suffix" returns noop for request 1 Mon Jun 11 11:18:18 2007 : Debug: modsingle[authorize]: calling files (rlm_files) for request 1 Mon Jun 11 11:18:18 2007 : Debug: users: Matched entry DEFAULT at line 171 Mon Jun 11 11:18:18 2007 : Debug: users: Matched entry DEFAULT at line 183 Mon Jun 11 11:18:18 2007 : Debug: modsingle[authorize]: returned from files (rlm_files) for request 1 Mon Jun 11 11:18:18 2007 : Debug: modcall[authorize]: module "files" returns ok for request 1 Mon Jun 11 11:18:18 2007 : Debug: modsingle[authorize]: calling sql (rlm_sql) for request 1 Mon Jun 11 11:18:18 2007 : Debug: radius_xlat: '[EMAIL PROTECTED]' Mon Jun 11 11:18:18 2007 : Debug: rlm_sql (sql): sql_set_user escaped user --> '[EMAIL PROTECTED]' Mon Jun 11 11:18:18 2007 : Debug: radius_xlat: 'SELECT id,UserName,Attribute,Value,op FROM radcheck WHERE Username = '[EMAIL PROTECTED]' ORDER BY id' Mon Jun 11 11:18:18 2007 : Debug: rlm_sql (sql): Reserving sql socket id: 30 Mon Jun 11 11:18:18 2007 : Debug: radius_xlat: 'SELECT radgroupcheck.id,radgroupcheck.GroupName,radgroupcheck.Attribute,radgroupcheck.Value,radgroupcheck.op FROM radgroupcheck,usergroup WHERE usergroup.Username = '[EMAIL PROTECTED]' AND usergroup.GroupName = radgroupcheck.GroupName ORDER BY radgroupcheck.id' Mon Jun 11 11:18:18 2007 : Debug: radius_xlat: 'SELECT id,UserName,Attribute,Value,op FROM radreply WHERE Username = '[EMAIL PROTECTED]' ORDER BY id' Mon Jun 11 11:18:18 2007 : Debug: radius_xlat: 'SELECT radgroupreply.id,radgroupreply.GroupName,radgroupreply.Attribute,radgroupreply.Value,radgroupreply.op FROM radgroupreply,usergroup WHERE usergroup.Username = '[EMAIL PROTECTED]' AND usergroup.GroupName = radgroupreply.GroupName ORDER BY radgroupreply.id' Mon Jun 11 11:18:18 2007 : Debug: rlm_sql (sql): Released sql socket id: 30 Mon Jun 11 11:18:18 2007 : Debug: modsingle[authorize]: returned from sql (rlm_sql) for request 1 Mon Jun 11 11:18:18 2007 : Debug: modcall[authorize]: module "sql" returns ok for request 1 Mon Jun 11 11:18:18 2007 : Debug: modsingle[authorize]: calling pap (rlm_pap) for request 1 Mon Jun 11 11:18:18 2007 : Debug: modsingle[authorize]: returned from pap (rlm_pap) for request 1 Mon Jun 11 11:18:18 2007 : Debug: modcall[authorize]: module "pap" returns updated for request 1 Mon Jun 11 11:18:18 2007 : Debug: modcall: leaving group authorize (returns updated) for request 1 Mon Jun 11 11:18:18 2007 : Debug: rad_check_password: Found Auth-Type pap Mon Jun 11 11:18:18 2007 : Debug: auth: type "PAP" Mon Jun 11 11:18:18 2007 : Debug: Processing the authenticate section of radiusd.conf Mon Jun 11 11:18:18 2007 : Debug: modcall: entering group PAP for request 1 Mon Jun 11 11:18:18 2007 : Debug: modsingle[authenticate]: calling pap (rlm_pap) for request 1 Mon Jun 11 11:18:18 2007 : Debug: rlm_pap: login attempt with password testing Mon Jun 11 11:18:18 2007 : Debug: rlm_pap: Using clear text password. Mon Jun 11 11:18:18 2007 : Debug: rlm_pap: User authenticated succesfully Mon Jun 11 11:18:18 2007 : Debug: modsingle[authenticate]: returned from pap (rlm_pap) for request 1 Mon Jun 11 11:18:18 2007 : Debug: modcall[authenticate]: module "pap" returns ok for request 1 Mon Jun 11 11:18:18 2007 : Debug: modcall: leaving group PAP (returns ok) for request 1 Mon Jun 11 11:18:18 2007 : Auth: Login OK: [EMAIL PROTECTED] (from client ERX-3 port 845414532 cli #BRAS-03#this is a description#100#132) Mon Jun 11 11:18:18 2007 : Debug: Processing the post-auth section of radiusd.conf Mon Jun 11 11:18:18 2007 : Debug: modcall: entering group post-auth for request 1 Mon Jun 11 11:18:18 2007 : Debug: modsingle[post-auth]: calling pool (rlm_sqlippool) for request 0 Mon Jun 11 11:18:18 2007 : Debug: Value Of the Pool-Name is [FIX] and its [3] Chars Mon Jun 11 11:18:18 2007 : Debug: rlm_sql (sql_postgresql): Reserving sql socket id: 30 Mon Jun 11 11:18:18 2007 : Debug: radius_xlat: 'BEGIN' Mon Jun 11 11:18:18 2007 : Debug: rlm_sql_postgresql: Status: PGRES_COMMAND_OK Mon Jun 11 11:18:18 2007 : Debug: rlm_sql_postgresql: affected rows = Mon Jun 11 11:18:18 2007 : Debug: radius_xlat: 'UPDATE radippool SET nasipaddress = '', pool_key = 0, callingstationid = '', expiry_time = 'now'::timestamp(0) - '1 second'::interval WHERE nasipaddress = '192.168.1.1' and pool_key = 'pppoe 12:34:56:78:9a:bc'' Mon Jun 11 11:18:18 2007 : Debug: rlm_sql_postgresql: Status: PGRES_COMMAND_OK Mon Jun 11 11:18:18 2007 : Debug: rlm_sql_postgresql: affected rows = 0 Mon Jun 11 11:18:18 2007 : Debug: radius_xlat: 'select pool('[EMAIL PROTECTED]','FIX','#BRAS-03#this is a description#100#134')' Mon Jun 11 11:18:19 2007 : Debug: rlm_sql_postgresql: Status: PGRES_TUPLES_OK Mon Jun 11 11:18:19 2007 : Debug: rlm_sql_postgresql: affected rows = Mon Jun 11 11:18:19 2007 : Info: rlm_sqlippool: ip=[10.10.10.1] len=14 Mon Jun 11 11:18:19 2007 : Debug: radius_xlat: 'UPDATE radippool SET nasipaddress = '192.168.1.1', pool_key = 'pppoe 12:34:56:78:9a:bc', callingstationid = '#BRAS-03#this is a description#100#134', username = '[EMAIL PROTECTED]', expiry_time = 'now'::timestamp(0) + '3600 second'::interval WHERE framedipaddress = '10.10.10.1'' Mon Jun 11 11:18:19 2007 : Debug: rlm_sql_postgresql: Status: PGRES_COMMAND_OK Mon Jun 11 11:18:19 2007 : Debug: rlm_sql_postgresql: affected rows = 1 Mon Jun 11 11:18:19 2007 : Debug: rlm_sqlippool: Allocated IP 10.10.10.1 [8ec25ec9] Mon Jun 11 11:18:19 2007 : Debug: radius_xlat: 'COMMIT' Mon Jun 11 11:18:19 2007 : Debug: rlm_sql_postgresql: Status: PGRES_COMMAND_OK Mon Jun 11 11:18:19 2007 : Debug: rlm_sql_postgresql: affected rows = Mon Jun 11 11:18:19 2007 : Debug: rlm_sql (sql_postgresql): Released sql socket id: 30 Mon Jun 11 11:18:19 2007 : Debug: modsingle[post-auth]: returned from pool (rlm_sqlippool) for request 0 Mon Jun 11 11:18:19 2007 : Debug: modcall[post-auth]: module "pool" returns ok for request 0 Mon Jun 11 11:18:19 2007 : Debug: modsingle[post-auth]: calling sql_log (rlm_sql_log) for request 0 Mon Jun 11 11:18:19 2007 : Debug: rlm_sql_log (sql_log): Processing sql_log_postauth Mon Jun 11 11:18:19 2007 : Debug: radius_xlat: 'INSERT INTO radpostauth ?? (username, pass, reply, authdate) VALUES ?? ('[EMAIL PROTECTED]', 'testing', ?? 'Access-Accept', TO_DATE('2007-06-11 11:18:18','yyyy-mm-dd hh24:mi:ss'))' Mon Jun 11 11:18:19 2007 : Debug: radius_xlat: '/usr/local/var/log/radius/radacct/sql-relay' Mon Jun 11 11:18:19 2007 : Debug: modsingle[post-auth]: returned from sql_log (rlm_sql_log) for request 0 Mon Jun 11 11:18:19 2007 : Debug: modcall[post-auth]: module "sql_log" returns ok for request 0 Mon Jun 11 11:18:19 2007 : Debug: modcall: leaving group post-auth (returns ok) for request 0 Sending Access-Accept of id 30 to 192.168.1.1 port 50000 X-Ascend-Client-Primary-DNS := 172.16.1.1 X-Ascend-Client-Secondary-DNS := 172.16.1.2 X-Ascend-Client-Assign-DNS := DNS-Assign-Yes ERX-Virtual-Router-Name := "default" ERX-Service-Bundle := "test1" Framed-IP-Address = 10.10.10.1 Mon Jun 11 11:18:19 2007 : Debug: Finished request 0 --------------- Now, [EMAIL PROTECTED] gets authenticated, but in a proxied realm (this user is also in radreply): rad_recv: Access-Request packet from host 192.168.1.1:50000, id=30, length=250 Mon Jun 11 11:02:10 2007 : Debug: --- Walking the entire request list --- Mon Jun 11 11:02:10 2007 : Debug: Thread 1 got semaphore Mon Jun 11 11:02:10 2007 : Debug: Thread 1 handling request 0, (1 handled so far) User-Password = "testing" User-Name = "[EMAIL PROTECTED]" Acct-Session-Id = "erx atm 3/2.42:100.133:0002097382" Service-Type = Framed-User Framed-Protocol = PPP ERX-Pppoe-Description = "pppoe 12:34:56:78:9a:bc" Calling-Station-Id = "#BRAS-03#this is a description#100#133" Connect-Info = "speed:UBR:12000" NAS-Port-Type = xDSL NAS-Port = 845414533 NAS-Port-Id = "atm 3/2.42:100.133" NAS-IP-Address = 192.168.1.1 NAS-Identifier = "BRAS-03" Mon Jun 11 11:02:10 2007 : Debug: Processing the authorize section of radiusd.conf Mon Jun 11 11:02:10 2007 : Debug: Waking up in 31 seconds... Mon Jun 11 11:02:10 2007 : Debug: modcall: entering group authorize for request 0 Mon Jun 11 11:02:10 2007 : Debug: modsingle[authorize]: calling preprocess (rlm_preprocess) for request 0 Mon Jun 11 11:02:10 2007 : Debug: Threads: total/active/spare threads = 5/1/4 Mon Jun 11 11:02:10 2007 : Debug: modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 0 Mon Jun 11 11:02:10 2007 : Debug: modcall[authorize]: module "preprocess" returns ok for request 0 Mon Jun 11 11:02:10 2007 : Debug: modsingle[authorize]: calling auth_log (rlm_detail) for request 0 Mon Jun 11 11:02:10 2007 : Debug: radius_xlat: '/usr/local/var/log/radius/radacct/192.168.1.1/auth-detail-20070611' Mon Jun 11 11:02:10 2007 : Debug: rlm_detail: /usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d expands to /usr/local/var/log/radius/radacct/192.168.1.1/auth-detail-20070611 Mon Jun 11 11:02:10 2007 : Debug: modsingle[authorize]: returned from auth_log (rlm_detail) for request 0 Mon Jun 11 11:02:10 2007 : Debug: modcall[authorize]: module "auth_log" returns ok for request 0 Mon Jun 11 11:02:10 2007 : Debug: modsingle[authorize]: calling chap (rlm_chap) for request 0 Mon Jun 11 11:02:10 2007 : Debug: modsingle[authorize]: returned from chap (rlm_chap) for request 0 Mon Jun 11 11:02:10 2007 : Debug: modcall[authorize]: module "chap" returns noop for request 0 Mon Jun 11 11:02:10 2007 : Debug: modsingle[authorize]: calling suffix (rlm_realm) for request 0 Mon Jun 11 11:02:10 2007 : Debug: rlm_realm: Looking up realm "proxy.com" for User-Name = "[EMAIL PROTECTED]" Mon Jun 11 11:02:10 2007 : Debug: rlm_realm: Found realm "proxy.com" Mon Jun 11 11:02:10 2007 : Debug: rlm_realm: Adding Stripped-User-Name = "steve" Mon Jun 11 11:02:10 2007 : Debug: rlm_realm: Proxying request from user steve to realm proxy.com Mon Jun 11 11:02:10 2007 : Debug: rlm_realm: Adding Realm = "proxy.com" Mon Jun 11 11:02:10 2007 : Debug: rlm_realm: Preparing to proxy authentication request to realm "proxy.com" Mon Jun 11 11:02:10 2007 : Debug: modsingle[authorize]: returned from suffix (rlm_realm) for request 0 Mon Jun 11 11:02:10 2007 : Debug: modcall[authorize]: module "suffix" returns updated for request 0 Mon Jun 11 11:02:10 2007 : Debug: modsingle[authorize]: calling files (rlm_files) for request 0 Mon Jun 11 11:02:10 2007 : Debug: users: Matched entry DEFAULT at line 171 Mon Jun 11 11:02:10 2007 : Debug: users: Matched entry DEFAULT at line 183 Mon Jun 11 11:02:10 2007 : Debug: modsingle[authorize]: returned from files (rlm_files) for request 0 Mon Jun 11 11:02:10 2007 : Debug: modcall[authorize]: module "files" returns ok for request 0 Mon Jun 11 11:02:10 2007 : Debug: modsingle[authorize]: calling sql (rlm_sql) for request 0 Mon Jun 11 11:02:10 2007 : Debug: radius_xlat: '[EMAIL PROTECTED]' Mon Jun 11 11:02:10 2007 : Debug: rlm_sql (sql): sql_set_user escaped user --> '[EMAIL PROTECTED]' ORDER BY id' Mon Jun 11 11:02:10 2007 : Debug: rlm_sql (sql): Reserving sql socket id: 31 Mon Jun 11 11:02:10 2007 : Debug: radius_xlat: 'SELECT radgroupcheck.id,radgroupcheck.GroupName,radgroupcheck.Attribute,radgroupcheck.Value,radgroupcheck.op FROM radgroupcheck,usergroup WHERE usergroup.Username = '[EMAIL PROTECTED]' AND usergroup.GroupName = radgroupcheck.GroupName ORDER BY radgroupcheck.id' Mon Jun 11 11:02:10 2007 : Debug: radius_xlat: 'SELECT id,UserName,Attribute,Value,op FROM radreply WHERE Username = '[EMAIL PROTECTED]' ORDER BY id' Mon Jun 11 11:02:10 2007 : Debug: radius_xlat: 'SELECT radgroupreply.id,radgroupreply.GroupName,radgroupreply.Attribute,radgroupreply.Value,radgroupreply.op FROM radgroupreply,usergroup WHERE usergroup.Username = '[EMAIL PROTECTED]' AND usergroup.GroupName = radgroupreply.GroupName ORDER BY radgroupreply.id' Mon Jun 11 11:02:10 2007 : Debug: rlm_sql (sql): Released sql socket id: 31 Mon Jun 11 11:02:10 2007 : Debug: modsingle[authorize]: returned from sql (rlm_sql) for request 0 Mon Jun 11 11:02:10 2007 : Debug: modcall[authorize]: module "sql" returns ok for request 0 Mon Jun 11 11:02:10 2007 : Debug: modsingle[authorize]: calling pap (rlm_pap) for request 0 Mon Jun 11 11:02:10 2007 : Debug: modsingle[authorize]: returned from pap (rlm_pap) for request 0 Mon Jun 11 11:02:10 2007 : Debug: modcall[authorize]: module "pap" returns noop for request 0 Mon Jun 11 11:02:10 2007 : Debug: modcall: leaving group authorize (returns updated) for request 0 Mon Jun 11 11:02:10 2007 : Debug: proxy: creating fc229bc8:1812 Mon Jun 11 11:02:10 2007 : Debug: proxy: allocating fc229bc8:1812 0 Sending Access-Request of id 0 to 192.168.1.2 port 1812 User-Password = "testing" User-Name = "steve" Acct-Session-Id = "erx atm 3/2.42:100.133:0002097382" Service-Type = Framed-User Framed-Protocol = PPP ERX-Pppoe-Description = "pppoe 12:34:56:78:9a:bc" Calling-Station-Id = "#BRAS-03#this is a description#100#133" Connect-Info = "speed:UBR:12000" NAS-Port-Type = xDSL NAS-Port = 845414533 NAS-Port-Id = "atm 3/2.42:100.133" NAS-IP-Address = 192.168.1.1 NAS-Identifier = "BRAS-03" Proxy-State = 0x3330 Mon Jun 11 11:02:10 2007 : Debug: Thread 1 waiting to be assigned a request rad_recv: Access-Accept packet from host 192.168.1.2:1812, id=0, length=24 Mon Jun 11 11:02:10 2007 : Debug: proxy: de-allocating fc229bc8:1812 0 Mon Jun 11 11:02:10 2007 : Debug: rl_next: returning NULL Mon Jun 11 11:02:10 2007 : Debug: Waking up in 31 seconds... Mon Jun 11 11:02:10 2007 : Debug: Threads: total/active/spare threads = 5/0/5 Mon Jun 11 11:02:10 2007 : Debug: Thread 2 got semaphore Mon Jun 11 11:02:10 2007 : Debug: Thread 2 handling request 0, (1 handled so far) Proxy-State = 0x3330 Mon Jun 11 11:02:10 2007 : Debug: Processing the post-proxy section of radiusd.conf Mon Jun 11 11:02:10 2007 : Debug: modcall: entering group post-proxy for request 0 Mon Jun 11 11:02:10 2007 : Debug: modsingle[post-proxy]: calling attr_filter (rlm_attr_filter) for request 0 Mon Jun 11 11:02:10 2007 : Debug: attr_filter: Matched entry proxy.com at line 84 Mon Jun 11 11:02:10 2007 : Debug: modsingle[post-proxy]: returned from attr_filter (rlm_attr_filter) for request 0 Mon Jun 11 11:02:10 2007 : Debug: modcall[post-proxy]: module "attr_filter" returns updated for request 0 Mon Jun 11 11:02:10 2007 : Debug: modcall: leaving group post-proxy (returns updated) for request 0 Mon Jun 11 11:02:10 2007 : Debug: authorize: Skipping authorize in post-proxy stage Mon Jun 11 11:02:10 2007 : Debug: rad_check_password: Found Auth-Type Mon Jun 11 11:02:10 2007 : Debug: rad_check_password: Auth-Type = Accept, accepting the user Mon Jun 11 11:02:10 2007 : Auth: Login OK: [EMAIL PROTECTED] (from client ERX-3 port 845414533 cli #BRAS-03#this is a description#100#133) Mon Jun 11 11:02:10 2007 : Debug: Processing the post-auth section of radiusd.conf Mon Jun 11 11:02:10 2007 : Debug: modcall: entering group post-auth for request 0 Mon Jun 11 11:02:10 2007 : Debug: modsingle[post-auth]: calling pool (rlm_sqlippool) for request 0 Mon Jun 11 11:02:10 2007 : Debug: Value Of the Pool-Name is [FIX] and its [3] Chars Mon Jun 11 11:02:10 2007 : Debug: rlm_sql (sql_postgresql): Reserving sql socket id: 30 Mon Jun 11 11:02:10 2007 : Debug: radius_xlat: 'BEGIN' Mon Jun 11 11:02:10 2007 : Debug: rlm_sql_postgresql: Status: PGRES_COMMAND_OK Mon Jun 11 11:02:10 2007 : Debug: rlm_sql_postgresql: affected rows = Mon Jun 11 11:02:10 2007 : Debug: radius_xlat: 'UPDATE radippool SET nasipaddress = '', pool_key = 0, callingstationid = '', expiry_time = 'now'::timestamp(0) - '1 second'::interval WHERE nasipaddress = '192.168.1.1' and pool_key = 'pppoe 12:34:56:78:9a:bc'' Mon Jun 11 11:02:10 2007 : Debug: rlm_sql_postgresql: Status: PGRES_COMMAND_OK Mon Jun 11 11:02:10 2007 : Debug: rlm_sql_postgresql: affected rows = 0 Mon Jun 11 11:02:10 2007 : Debug: radius_xlat: 'select pool('[EMAIL PROTECTED]','FIX','#BRAS-03#this is a description#100#133')' Mon Jun 11 11:02:10 2007 : Debug: rlm_sql_postgresql: Status: PGRES_TUPLES_OK Mon Jun 11 11:02:10 2007 : Debug: rlm_sql_postgresql: affected rows = Mon Jun 11 11:02:10 2007 : Info: rlm_sqlippool: ip=[10.10.10.1] len=13 Mon Jun 11 11:02:10 2007 : Debug: radius_xlat: 'UPDATE radippool SET nasipaddress = '192.168.1.1', pool_key = 'pppoe 12:34:56:78:9a:bc', callingstationid = '#BRAS-03#this is a description#100#133', username = '[EMAIL PROTECTED]', expiry_time = 'now'::timestamp(0) + '3600 second'::interval WHERE framedipaddress = '10.10.10.1'' Mon Jun 11 11:02:10 2007 : Debug: rlm_sql_postgresql: Status: PGRES_COMMAND_OK Mon Jun 11 11:02:10 2007 : Debug: rlm_sql_postgresql: affected rows = 1 Mon Jun 11 11:02:10 2007 : Debug: rlm_sqlippool: Allocated IP 10.10.10.1 [97310ebd] Mon Jun 11 11:02:10 2007 : Debug: radius_xlat: 'COMMIT' Mon Jun 11 11:02:10 2007 : Debug: rlm_sql_postgresql: Status: PGRES_COMMAND_OK Mon Jun 11 11:02:10 2007 : Debug: rlm_sql_postgresql: affected rows = Mon Jun 11 11:02:10 2007 : Debug: rlm_sql (sql_postgresql): Released sql socket id: 30 Mon Jun 11 11:02:10 2007 : Debug: modsingle[post-auth]: returned from pool (rlm_sqlippool) for request 0 Mon Jun 11 11:02:10 2007 : Debug: modcall[post-auth]: module "pool" returns ok for request 0 Mon Jun 11 11:02:10 2007 : Debug: modsingle[post-auth]: calling sql_log (rlm_sql_log) for request 0 Mon Jun 11 11:02:10 2007 : Debug: rlm_sql_log (sql_log): Processing sql_log_postauth Mon Jun 11 11:02:10 2007 : Debug: radius_xlat: 'INSERT INTO radpostauth ?? (username, pass, reply, authdate) VALUES ?? ('[EMAIL PROTECTED]', 'testing', ?? 'Access-Accept', TO_DATE('2007-06-11 11:02:10','yyyy-mm-dd hh24:mi:ss'))' Mon Jun 11 11:02:10 2007 : Debug: radius_xlat: '/usr/local/var/log/radius/radacct/sql-relay' Mon Jun 11 11:02:10 2007 : Debug: modsingle[post-auth]: returned from sql_log (rlm_sql_log) for request 0 Mon Jun 11 11:02:10 2007 : Debug: modcall[post-auth]: module "sql_log" returns ok for request 0 Mon Jun 11 11:02:10 2007 : Debug: modcall: leaving group post-auth (returns ok) for request 0 Sending Access-Accept of id 30 to 192.168.1.1 port 50000 X-Ascend-Client-Primary-DNS := 172.16.1.1 X-Ascend-Client-Secondary-DNS := 172.16.1.2 X-Ascend-Client-Assign-DNS := DNS-Assign-Yes ERX-Virtual-Router-Name := "default" Framed-IP-Address = 10.10.10.1 Mon Jun 11 11:02:10 2007 : Debug: Finished request 0 ------------- > The debug logs will still tell you what modules are being executed, > and when. That will give information as to *why* it's not being added. *Sorry, but where is the VSA "ERX-Service-Bundle" here? > This is what the post-auth section is for: adding attributes to > packets after a user has been authenticated. *What config shall I put in post-auth to send this VSA back to the B-RAS? Create a module and call it in post-auth? > This will be better supported in 2.0.0. *Should I install 2.0.0 then? Is it the only way? Thank you very much! Guilherme - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html