help in setting up PEAP in freeRADIUS with winXp

On 6/11/07, freeradius-users-request@lists.freeradius.org < freeradius-users-request@lists.freeradius.org> wrote:

Send Freeradius-Users mailing list submissions to
        freeradius-users@lists.freeradius.org

To subscribe or unsubscribe via the World Wide Web, visit
         http://lists.freeradius.org/mailman/listinfo/freeradius-users
or, via email, send a message with subject or body 'help' to
        freeradius-users-request@lists.freeradius.org

You can reach the person managing the list at
        freeradius-users-owner@lists.freeradius.org

When replying, please edit your Subject line so it is more specific
than "Re: Contents of Freeradius-Users digest..."

Today's Topics:

   1. Re: help in setting up PEAP in freeRADIUS with winXp
      supplicant (Martin Gadbois)
   2. Re: Freeradius as a secondary (Jeff)
   3. Re: Big "VSA + Proxy" problem (Guilherme Franco)

----------------------------------------------------------------------

Message: 1
Date: Mon, 11 Jun 2007 09:28:27 -0400
From: Martin Gadbois < martin.gadbois@colubris.com>
Subject: Re: help in setting up PEAP in freeRADIUS with winXp
        supplicant
To: FreeRadius users mailing list
        < freeradius-users@lists.freeradius.org>
Message-ID: <466D4DFB.1020704@colubris.com">466D4DFB.1020704@colubris.com>
Content-Type: text/plain; charset=UTF-8

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

Apangshu Saha wrote:

>   rad_check_password:  Found Auth-Type EAP
> auth: type "EAP"
>   Processing the authenticate section of radiusd.conf
> modcall: entering group authenticate for request 5
>   rlm_eap: EAP Identity
>  rlm_eap: No such EAP type mschapv2
>   rlm_eap: Failed in EAP select
>   modcall[authenticate]: module "eap" returns invalid for request 5
> modcall: leaving group authenticate (returns invalid) for request 5
> auth: Failed to validate the user.
>   PEAP: Tunneled authentication was rejected.
>   rlm_eap_peap: FAILURE

Do you have mschap enabled in your eap.conf?

        eap {
                default_eap_type = peap
                timer_expire     = 60
                ignore_unknown_eap_types = no
                cisco_accounting_username_bug = no

                md5 {
                }

                tls {
...
                }

                ttls {
...
                }
                 peap {
...
                }
>>>                mschapv2 {
>>>                }
        }

- --
==============         +---------------------------------------------+
Martin Gadbois         | "Please answer by yes or no.                |
Sr. SW Designer        | Uncooperative user waste precious CPU time" |
Colubris Networks Inc. | -- The Andromeda Strain, M. Crichton, 1969  |
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.5 (GNU/Linux)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org

iD8DBQFGbU379Y3/iTTCEDkRAhz+AJkBQD2iH/pJHGSFwVdBnNcFAMdILACgomOf
vZhC4ftJ7IjYZXP+1oTcjQI=
=YvGQ
-----END PGP SIGNATURE-----

------------------------------

Message: 2
Date: Mon, 11 Jun 2007 10:28:37 -0400
From: Jeff <jeffa@jahelpdesk.com>
Subject: Re: Freeradius as a secondary
To: "FreeRadius users mailing list"
        <freeradius-users@lists.freeradius.org>
Message-ID: <20070611142837.c0c38dfd@ns1.jahelpdesk.com">20070611142837.c0c38dfd@ns1.jahelpdesk.com >
Content-Type: text/plain; charset="us-ascii"

Ok new issue thats eluding me
I uninstalled version 1. then installed version 2

anyway. i resetup the configs and made sure my services file is 1645 radius and 1646 for acct as before
anyway
when i do a auth with ntradping all connects aok
when i do anykind of an accouting request, stop start update i get error 10054
which i read may mean check the port which it apperas i am set aok unless i am missing something

NEXT
Nothing is going into the radacct dir for detail file either or is it being created

Also when i do a /etc/init.d/freeradius start or restart everything is aok
when i do a /etc/init.d/freeradius reload I see in the radius log that its saying there is errors in the radius config

Anyway anyone have any ideas?
      _____

  From: Peter Nixon [mailto:listuser@peternixon.net]
To: FreeRadius users mailing list [mailto: freeradius-users@lists.freeradius.org]
Sent: Sun, 10 Jun 2007 19:43:58 -0400
Subject: Re: Freeradius as a secondary

On Sun 10 Jun 2007, Jeff wrote:
> I am using the version installed through software update on opensuse

You may wish to use my updated packages at:
http://software.opensuse.org/download/network:/aaa/

Just add is as a software repository in YaST. (ie.
http://software.opensuse.org/download/network:/aaa/openSUSE_10.2/)

Cheers

--

Peter Nixon
http://www.peternixon.net/
PGP Key: http://www.peternixon.net/public.asc
-
List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html

-------------- next part --------------
An HTML attachment was scrubbed...
URL: https://lists.freeradius.org/pipermail/freeradius-users/attachments/20070611/ba461c21/attachment-0001.html

------------------------------

Message: 3
Date: Mon, 11 Jun 2007 11:50:26 -0300
From: "Guilherme Franco" < guilhermefranco@gmail.com>
Subject: Re: Big "VSA + Proxy" problem
To: "FreeRadius users mailing list"
        < freeradius-users@lists.freeradius.org>
Message-ID:
        <5e239f520706110750me7fca81weab5378ca94d39ea@mail.gmail.com">5e239f520706110750me7fca81weab5378ca94d39ea@mail.gmail.com>
Content-Type: text/plain; charset=ISO-8859-1; format=flowed

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

------------------------------

-
List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html

End of Freeradius-Users Digest, Vol 26, Issue 33
************************************************