Hello, Running Freeradius 1.1.4 on RHEL with an Oracle backend. I'm at a Carrier and every "@bar.com" request is configured to be proxied but I have a problem where a VSA (in radreply table) is not even sent to bar.com. In my database: select * from radcheck; ID USERNAME ATTRIBUTE OP VALUE --- ------------------ --------------------- ---- ----------- 1 foo@bar.com User-Password := temp123 select * from radreply; ID USERNAME ATTRIBUTE OP VALUE --- ------------------ ---------------------------- ---- ----------- 1 foo@bar.com ERX-Service-Bundle := test1 ID USERNAME ATTRIBUTE OP VALUE --- ------------------ ---------------------------- ---- ------------------------ 2 foo@bar.com Framed-IP-Address := 192.168.254.199 Disabling the proxying for this realm works correctly (freeradius auths the user locally and sends the VSA to the router). With proxy configured, the user gets authenticated by bar.com but the VSA is not sent to bar.com (no traces of it in pre_proxy logs nor in radiusd -X debugs). I've already added ERX-Service-Bundle =* ANY in both attrs and attrs.pre-proxy and enabled the filters in radiusd.conf, but still no luck. Question: if that issue gets fixed and the VSA goes to bar.com, is there any way to bar.com return that same VSA untouched (considering that bar.com doesn't knows a thing about that VSA, i.e: it doesn't has any VSA info on it's database)? In fact, I don't need to send that VSA to bar.com, I just need to send it directly to my router(just like in the unproxied realm) but the proxy feature doesn't allow that. Please consider that I can't simply add "ERX-Service-Bundle := test1" in attrs (like I do with DNS VSAs) because the value of that VSA is chained with the user in radreply and each user has it's own different value (test2, test5, etc.). I'm very worried. Can anyone please shed some light on this? Thank you very much!
Guilherme Franco wrote:
With proxy configured, the user gets authenticated by bar.com but the VSA is not sent to bar.com (no traces of it in pre_proxy logs nor in radiusd -X debugs).
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.
Question: if that issue gets fixed and the VSA goes to bar.com, is there any way to bar.com return that same VSA untouched (considering that bar.com doesn't knows a thing about that VSA, i.e: it doesn't has any VSA info on it's database)? In fact, I don't need to send that VSA to bar.com, I just need to send it directly to my router(just like in the unproxied realm) but the proxy feature doesn't allow that.
This is what the post-auth section is for: adding attributes to packets after a user has been authenticated. This will be better supported in 2.0.0. Alan DeKok.
Hello Mr. Alan, Thank you for answering. Below, you will find a working local authentication, user steve@local.com (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 = "steve@local.com" 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 = "steve@local.com" 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: 'steve@local.com' Mon Jun 11 11:18:18 2007 : Debug: rlm_sql (sql): sql_set_user escaped user --> 'steve@local.com' Mon Jun 11 11:18:18 2007 : Debug: radius_xlat: 'SELECT id,UserName,Attribute,Value,op FROM radcheck WHERE Username = 'steve@local.com' 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 = 'steve@local.com' 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 = 'steve@local.com' 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 = 'steve@local.com' 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: [steve@local.com] (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('steve@local.com','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 = 'steve@local.com', 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 ?? ('steve@local.com', '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, steve@proxy.com 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 = "steve@proxy.com" 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 = "steve@proxy.com" 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: 'steve@proxy.com' Mon Jun 11 11:02:10 2007 : Debug: rlm_sql (sql): sql_set_user escaped user --> 'steve@proxy.com' 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 = 'steve@proxy.com' 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 = 'steve@proxy.com' 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 = 'steve@proxy.com' 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: [steve@proxy.com] (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('steve@proxy.com','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 = 'steve@proxy.com', 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 ?? ('steve@proxy.com', '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
Hi, Sorry for bothering you guys. I would like to humbly ask if there's any ideas on this? Thanks. On 6/11/07, Guilherme Franco wrote:
Hello Mr. Alan,
Thank you for answering.
Below, you will find a working local authentication, user steve@local.com (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 = "steve@local.com" 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 = "steve@local.com" 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: 'steve@local.com' Mon Jun 11 11:18:18 2007 : Debug: rlm_sql (sql): sql_set_user escaped user --> 'steve@local.com' Mon Jun 11 11:18:18 2007 : Debug: radius_xlat: 'SELECT id,UserName,Attribute,Value,op FROM radcheck WHERE Username = 'steve@local.com' 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 = 'steve@local.com' 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 = 'steve@local.com' 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 = 'steve@local.com' 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: [steve@local.com] (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('steve@local.com','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 = 'steve@local.com', 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 ?? ('steve@local.com', '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, steve@proxy.com 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 = "steve@proxy.com" 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 = "steve@proxy.com" 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: 'steve@proxy.com' Mon Jun 11 11:02:10 2007 : Debug: rlm_sql (sql): sql_set_user escaped user --> 'steve@proxy.com' 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 = 'steve@proxy.com' 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 = 'steve@proxy.com' 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 = 'steve@proxy.com' 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: [steve@proxy.com] (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('steve@proxy.com','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 = 'steve@proxy.com', 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 ?? ('steve@proxy.com', '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
Guilherme Franco wrote:
Hi,
Sorry for bothering you guys.
I would like to humbly ask if there's any ideas on this?
There's a lot there, and it's not clear what's going on. Look at the differences between the two configurations. Alan DeKok. -- http://deployingradius.com - The web site of the book http://deployingradius.com/blog/ - The blog
Hello, It's the same server with the very same config for both users in radcheck and radreply, except that in proxy.conf, only the "proxy.com" realm is set to be proxied to 192.168.1.2. When the user "steve@local.com" (no proxy) logs in, the VSA ERX-Service-Bundle is sent to the B-RAS, while it's not when the user "steve@proxy.com" (proxy) gets authenticated. Thank you. On 6/13/07, Alan Dekok <aland@deployingradius.com> wrote:
Guilherme Franco wrote:
Hi,
Sorry for bothering you guys.
I would like to humbly ask if there's any ideas on this?
There's a lot there, and it's not clear what's going on.
Look at the differences between the two configurations.
Alan DeKok. -- http://deployingradius.com - The web site of the book http://deployingradius.com/blog/ - The blog - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
participants (2)
-
Alan Dekok -
Guilherme Franco