(RADIATOR) FreeBSD PPPOE and radiator

Tim McCullagh timbo at halenet.com.au
Tue Dec 7 22:58:50 CST 2004 

Hi All,

I am attempting to setup a test FreeBSD server which acts as a PPPOE access
concentrator

The diagram is like this

        |  Public IP
FreeBSD radius server running Radiator
        | Private IP 192.168.x.x
        |
    Switch
        |
        | Private IP    192.168.x.x
Freebsd Gateway PPPOE server
        | Public IP 61.x.x.1
        |
        | Public IP 61.x.x.10 or dynamically assigned
Dlink 704P router
        | Private IP  NAT


The problem I am having is that the Freebsd gateway server is sending radius
requests to the FreeBSD radius server which runs Radiator, the radius server
is processing the
request and logging an Access-Accept however the FreeBSD gateway is
reporting an error  No valid radius reply received.

It would appear as if the problem lies in the format of the reply
attributes.  I have logged all the incoming connections and there is an
incoming radius reply request.

Can anyone tell me how I can see what is being sent from Radiator back to my
pppoe server?

The logs look like this

Radiator Handler config
=================

<Handler NAS-Identifier=joe.xxxxxxxx.com.au>
        # AuthBy for pppoe using dlink 704 P router

        RewriteUsername s/^([^@]+).*/$1/
        AcctLogFileName %L/detail

        <AuthBy SQL>

                DBSource        dbi:mysql:myname:myname.xxxxxxxxx.com.au
                DBUsername      myname
                DBAuth          mysecret

                AuthSelect select _password from svc_acct where username =
'%n'
                AuthColumnDef 0,Encrypted-Password,check

        AcctFailedLogFileName %D/missedaccounting

        AddToReply Framed-Protocol = PPP,\
                Framed-IP-Netmask = 255.255.255.255,\
                Framed-Routing = 1492,\
                Framed-MTU = 1492,\
                NAS-Port-Type = Ethernet
        </AuthBy>
</Handler>


Radiator Server Log
===============

Tue Dec  7 11:15:33 2004: DEBUG: Packet dump:
*** Received from 192.168.xx.xx port 57590 ....
Code:       Access-Request
Identifier: 203
Authentic:  <227><7><243>[P<210><218>(<26>R<178><169><232><181><226>8
Attributes:
        User-Name = "dummy"
        Service-Type = Framed-User
        Framed-Protocol = PPP
        User-Password = "<148>v<30>V}<154>0".pCu<131><195><210><214>"
        NAS-Identifier = "joe.xxxxxxx.com.au"
        Calling-Station-Id = "0:f:3d:16:82:ee"
        NAS-Port-Type = 15
        NAS-Port = 118

Tue Dec  7 11:15:33 2004: DEBUG: Check if Handler
Called-Station-Id=46815000,Service-Type=Framed-User should be used to handle
this request
Tue Dec  7 11:15:33 2004: DEBUG: Check if Handler
Called-Station-Id=12345678,Service-Type=Framed-User should be used to handle
this request
Tue Dec  7 11:15:33 2004: DEBUG: Check if Handler
NAS-Identifier=joe.xxxxxx.com.au should be used to handle this request
Tue Dec  7 11:15:33 2004: DEBUG: Handling request with Handler
'NAS-Identifier=joe.xxxxx.com.au'
Tue Dec  7 11:15:33 2004: DEBUG: Rewrote user name to dummy
Tue Dec  7 11:15:33 2004: DEBUG:  Deleting session for dummy, 192.168.0.230,
118
Tue Dec  7 11:15:33 2004: DEBUG: do query is: delete from RADONLINE where
NASIDENTIFIER='192.168.0.230' and NASPORT=0118

Tue Dec  7 11:15:33 2004: DEBUG: Handling with Radius::AuthSQL
Tue Dec  7 11:15:33 2004: DEBUG: Handling with Radius::AuthSQL
Tue Dec  7 11:15:33 2004: DEBUG: Query is: select _password from svc_acct
where username = 'dummy'

Tue Dec  7 11:15:33 2004: DEBUG: Radius::AuthSQL looks for match with dummy
Tue Dec  7 11:15:34 2004: DEBUG: Radius::AuthSQL ACCEPT:
Tue Dec  7 11:15:34 2004: DEBUG: Access accepted for dummy
Tue Dec  7 11:15:34 2004: DEBUG: Packet dump:
*** Sending to 192.168.0.230 port 57590 ....
Code:       Access-Accept
Identifier: 203
Authentic:  <227><7><243>[P<210><218>(<26>R<178><169><232><181><226>8
Attributes:
        Framed-Protocol = PPP
        Framed-IP-Netmask = 255.255.255.255
        Framed-Routing = 1492
        Framed-MTU = 1492

Tue Dec  7 11:15:34 2004: DEBUG: Packet dump:
*** Received from 192.168.xx.xx port 57590 ....
Code:       Access-Request
Identifier: 203
Authentic:  <227><7><243>[P<210><218>(<26>R<178><169><232><181><226>8
Attributes:
        User-Name = "dummy"
        Service-Type = Framed-User
        Framed-Protocol = PPP
        User-Password = "<148>v<30>V}<154>0".pCu<131><195><210><214>"
        NAS-Identifier = "joe.xxxxxxx.com.au"
        Calling-Station-Id = "0:f:3d:16:82:ee"
        NAS-Port-Type = 15
        NAS-Port = 118

Tue Dec  7 11:15:34 2004: DEBUG: Check if Handler
Called-Station-Id=46815000,Service-Type=Framed-User should be used to handle
this request
Tue Dec  7 11:15:34 2004: DEBUG: Check if Handler
Called-Station-Id=12345678,Service-Type=Framed-User should be used to handle
this request
Tue Dec  7 11:15:34 2004: DEBUG: Check if Handler
NAS-Identifier=joe.xxxxxx.com.au should be used to handle this request
Tue Dec  7 11:15:34 2004: DEBUG: Handling request with Handler
'NAS-Identifier=joe.xxxxxxx.com.au'
Tue Dec  7 11:15:34 2004: DEBUG: Rewrote user name to dummy
Tue Dec  7 11:15:34 2004: DEBUG:  Deleting session for dummy, 192.168.0.230,
118
Tue Dec  7 11:15:34 2004: DEBUG: do query is: delete from RADONLINE where
NASIDENTIFIER='192.168.0.230' and NASPORT=0118

Tue Dec  7 11:15:34 2004: DEBUG: Handling with Radius::AuthSQL
Tue Dec  7 11:15:34 2004: DEBUG: Handling with Radius::AuthSQL
Tue Dec  7 11:15:34 2004: DEBUG: Query is: select _password from svc_acct
where username = 'dummy'

Tue Dec  7 11:15:34 2004: DEBUG: Radius::AuthSQL looks for match with dummy
Tue Dec  7 11:15:35 2004: DEBUG: Radius::AuthSQL ACCEPT:
Tue Dec  7 11:15:35 2004: DEBUG: Access accepted for dummy
Tue Dec  7 11:15:35 2004: DEBUG: Packet dump:
*** Sending to 192.168.xx.xx port 57590 ....
Code:       Access-Accept
Identifier: 203
Authentic:  <227><7><243>[P<210><218>(<26>R<178><169><232><181><226>8
Attributes:
        Framed-Protocol = PPP
        Framed-IP-Netmask = 255.255.255.255
        Framed-Routing = 1492
        Framed-MTU = 1492

Tue Dec  7 11:15:35 2004: DEBUG: Packet dump:
*** Received from 192.168.xx.xx port 57590 ....
Code:       Access-Request
Identifier: 203
Authentic:  <227><7><243>[P<210><218>(<26>R<178><169><232><181><226>8
Attributes:
        User-Name = "dummy"
        Service-Type = Framed-User
        Framed-Protocol = PPP
        User-Password = "<148>v<30>V}<154>0".pCu<131><195><210><214>"
        NAS-Identifier = "joe.xxxxxxx.com.au"
        Calling-Station-Id = "0:f:3d:16:82:ee"
        NAS-Port-Type = 15
        NAS-Port = 118

Tue Dec  7 11:15:35 2004: DEBUG: Check if Handler
Called-Station-Id=46815000,Service-Type=Framed-User should be used to handle
this request
Tue Dec  7 11:15:35 2004: DEBUG: Check if Handler
Called-Station-Id=12345678,Service-Type=Framed-User should be used to handle
this request
Tue Dec  7 11:15:35 2004: DEBUG: Check if Handler
NAS-Identifier=joe.xxxxxxx.com.au should be used to handle this request
Tue Dec  7 11:15:35 2004: DEBUG: Handling request with Handler
'NAS-Identifier=joe.halenet.com.au'
Tue Dec  7 11:15:35 2004: DEBUG: Rewrote user name to dummy
Tue Dec  7 11:15:35 2004: DEBUG:  Deleting session for dummy, 192.168.xx.xx,
118
Tue Dec  7 11:15:35 2004: DEBUG: do query is: delete from RADONLINE where
NASIDENTIFIER='192.168.xx.xx' and NASPORT=0118

Tue Dec  7 11:15:35 2004: DEBUG: Handling with Radius::AuthSQL
Tue Dec  7 11:15:35 2004: DEBUG: Handling with Radius::AuthSQL
Tue Dec  7 11:15:35 2004: DEBUG: Query is: select _password from svc_acct
where username = 'dummy'

Tue Dec  7 11:15:35 2004: DEBUG: Radius::AuthSQL looks for match with dummy
Tue Dec  7 11:15:35 2004: DEBUG: Radius::AuthSQL ACCEPT:
Tue Dec  7 11:15:35 2004: DEBUG: Access accepted for dummy
Tue Dec  7 11:15:35 2004: DEBUG: Packet dump:
*** Sending to 192.168.0.230 port 57590 ....
Code:       Access-Accept
Identifier: 203
Authentic:  <227><7><243>[P<210><218>(<26>R<178><169><232><181><226>8
Attributes:
        Framed-Protocol = PPP
        Framed-IP-Netmask = 255.255.255.255
        Framed-Routing = 1492
        Framed-MTU = 1492





FreeBSD PPPOE server log
====================
Dec  7 14:16:43 joe ppp[6972]: tun0: Radius: Radius(auth): PAP data sent for
dummy
Dec  7 14:16:43 joe ppp[6972]: tun0: Radius: Radius: Request sent
Dec  7 14:16:43 joe ppp[6972]: tun0: Debug: Using radius_Timeout [0x8083998]
Dec  7 14:16:43 joe ppp[6972]: tun0: Timer: timer_Start: Inserting radius
auth timer[0x80ae138] before hdlc timer[0x80bfdb0], delta = 20
Dec  7 14:16:43 joe ppp[6972]: tun0: Timer: Radius: fdset(r) 2
Dec  7 14:16:43 joe ppp[6972]: tun0: Timer: deflink: fdset(r) 0
Dec  7 14:16:43 joe ppp[6972]: tun0: Timer: deflink: fdset(e) 0
Dec  7 14:16:44 joe ppp[6972]: tun0: Timer: Select returns 1
Dec  7 14:16:44 joe ppp[6972]: tun0: Radius: Radius: Request re-sent
Dec  7 14:16:44 joe ppp[6972]: tun0: Timer: timer_Start: Inserting radius
auth timer[0x80ae138] before hdlc timer[0x80bfdb0], delta = 26
Dec  7 14:16:44 joe ppp[6972]: tun0: Timer: Radius: fdset(r) 2
Dec  7 14:16:44 joe ppp[6972]: tun0: Timer: deflink: fdset(r) 0
Dec  7 14:16:44 joe ppp[6972]: tun0: Timer: deflink: fdset(e) 0
Dec  7 14:16:44 joe ppp[6972]: tun0: Timer: Select returns -1
Dec  7 14:16:44 joe ppp[6972]: tun0: Timer: ---- Begin of Timer Service
List---
Dec  7 14:16:44 joe ppp[6972]: tun0: Timer: physical throughput
timer[0x80bd068]: freq = 1.00s, next = 0.00s, state = running
Dec  7 14:16:44 joe ppp[6972]: tun0: Timer: radius auth timer[0x80ae138]:
freq = 3.00s, next = 2.60s, state = running
Dec  7 14:16:44 joe ppp[6972]: tun0: Timer: hdlc timer[0x80bfdb0]: freq =
60.00s, next = 59.00s, state = running
Dec  7 14:16:44 joe ppp[6972]: tun0: Timer: ---- End of Timer Service
List ---
Dec  7 14:16:44 joe ppp[6972]: tun0: Timer: timer_Start: Inserting physical
throughput timer[0x80bd068] before radius auth timer[0x80ae138], delta = 10
Dec  7 14:16:44 joe ppp[6972]: tun0: Timer: Radius: fdset(r) 2
Dec  7 14:16:44 joe ppp[6972]: tun0: Timer: deflink: fdset(r) 0
Dec  7 14:16:44 joe ppp[6972]: tun0: Timer: deflink: fdset(e) 0
Dec  7 14:16:45 joe ppp[6972]: tun0: Timer: Select returns 1
Dec  7 14:16:45 joe ppp[6972]: tun0: Radius: Radius: Request re-sent
Dec  7 14:16:45 joe ppp[6972]: tun0: Timer: timer_Start: Inserting radius
auth timer[0x80ae138] before hdlc timer[0x80bfdb0], delta = 22
Dec  7 14:16:45 joe ppp[6972]: tun0: Timer: Radius: fdset(r) 2
Dec  7 14:16:45 joe ppp[6972]: tun0: Timer: deflink: fdset(r) 0
Dec  7 14:16:45 joe ppp[6972]: tun0: Timer: deflink: fdset(e) 0
Dec  7 14:16:45 joe ppp[6972]: tun0: Timer: Select returns 1
Dec  7 14:16:45 joe ppp[6972]: tun0: Radius: radius(auth): No valid RADIUS
responses received
Dec  7 14:16:45 joe ppp[6972]: tun0: Phase: Pap Output: FAILURE
Dec  7 14:16:45 joe ppp[6972]: tun0: Debug: proto_LayerPush: Using 0xc023
Dec  7 14:16:45 joe ppp[6972]: tun0: Sync: Write
Dec  7 14:16:45 joe ppp[6972]: tun0: Sync:  c0 23 03 2f 00 14 0f 4c 6f 67 69
6e 20 69 6e 63  .#./...Login inc
Dec  7 14:16:45 joe ppp[6972]: tun0: Sync:  6f 72 72 65 63 74
orrect
Dec  7 14:16:45 joe ppp[6972]: tun0: Debug: link_PushPacket: Transmit proto
0xc023
Dec  7 14:16:45 joe ppp[6972]: tun0: Debug: m_enqueue: len = 1
Dec  7 14:16:45 joe ppp[6972]: tun0: LCP: deflink: LayerDown
Dec  7 14:16:45 joe ppp[6972]: tun0: LCP: deflink: SendTerminateReq(3) state
= Opened
Dec  7 14:16:45 joe ppp[6972]: tun0: Debug: fsm_Output
Dec  7 14:16:45 joe ppp[6972]: tun0: Debug:  05 03 00 04
....
Dec  7 14:16:45 joe ppp[6972]: tun0: Debug: proto_LayerPush: Using 0xc021
Dec  7 14:16:45 joe ppp[6972]: tun0: Sync: Write
Dec  7 14:16:45 joe ppp[6972]: tun0: Sync:  c0 21 05 03 00 04
.!....
Dec  7 14:16:45 joe ppp[6972]: tun0: Debug: link_PushPacket: Transmit proto
0xc021
Dec  7 14:16:45 joe ppp[6972]: tun0: Debug: m_enqueue: len = 2
Dec  7 14:16:45 joe ppp[6972]: tun0: Timer: timer_Start: Inserting LCP
restart timer[0x80bd13c]
Dec  7 14:16:45 joe ppp[6972]: tun0: LCP: deflink: State change Opened -->
Closing
Dec  7 14:16:45 joe ppp[6972]: tun0: Timer: deflink: fdset(r) 0
Dec  7 14:16:45 joe ppp[6972]: tun0: Timer: deflink: fdset(e) 0
Dec  7 14:16:45 joe ppp[6972]: tun0: Timer: deflink: fdset(w) 0
Dec  7 14:16:45 joe ppp[6972]: tun0: Timer: Select returns 1
Dec  7 14:16:45 joe ppp[6972]: tun0: Debug: m_dequeue: queue len = 2
Dec  7 14:16:45 joe ppp[6972]: tun0: Debug: link_Dequeue: Dequeued from
queue 1, containing 1 more packets
Dec  7 14:16:45 joe ppp[6972]: tun0: Physical: write
Dec  7 14:16:45 joe ppp[6972]: tun0: Physical:  c0 23 03 2f 00 14 0f 4c 6f
67 69 6e 20 69 6e 63  .#./...Login inc
Dec  7 14:16:45 joe ppp[6972]: tun0: Physical:  6f 72 72 65 63 74
orrect
Dec  7 14:16:45 joe ppp[6972]: tun0: Debug: deflink: DescriptorWrite: wrote
22(22) to 0
Dec  7 14:16:45 joe ppp[6972]: tun0: Timer: deflink: fdset(r) 0
Dec  7 14:16:45 joe ppp[6972]: tun0: Timer: deflink: fdset(e) 0
Dec  7 14:16:45 joe ppp[6972]: tun0: Timer: deflink: fdset(w) 0
Dec  7 14:16:45 joe ppp[6972]: tun0: Timer: Select returns 1
Dec  7 14:16:45 joe ppp[6972]: tun0: Debug: m_dequeue: queue len = 1
Dec  7 14:16:45 joe ppp[6972]: tun0: Debug: link_Dequeue: Dequeued from
queue 1, containing 0 more packets
Dec  7 14:16:45 joe ppp[6972]: tun0: Physical: write
Dec  7 14:16:45 joe ppp[6972]: tun0: Physical:  c0 21 05 03 00 04
.!....
Dec  7 14:16:45 joe ppp[6972]: tun0: Debug: deflink: DescriptorWrite: wrote
6(6) to 0
Dec  7 14:16:45 joe ppp[6972]: tun0: Timer: deflink: fdset(r) 0
Dec  7 14:16:45 joe ppp[6972]: tun0: Timer: deflink: fdset(e) 0
Dec  7 14:16:45 joe ppp[6972]: tun0: Timer: Select returns 1
Dec  7 14:16:45 joe ppp[6972]: tun0: Physical: read
Dec  7 14:16:45 joe ppp[6972]: tun0: Physical:  c0 21 05 32 00 0a 00 00 00
00 00 00              .!.2........
Dec  7 14:16:45 joe ppp[6972]: tun0: Sync: Read
Dec  7 14:16:45 joe ppp[6972]: tun0: ID0: 108 = write(1, data, 108)
Dec  7 14:16:45 joe ppp[6972]: tun0: Debug: wrote 108: cmd = Delete, dst =
61.88.49.201, gateway = <none>
Dec  7 14:16:45 joe ppp[6972]: tun0: Debug: Found ff02:5::/32
fe80:5::202:b3ff:fe99:140a
Dec  7 14:16:45 joe ppp[6972]: tun0: ID0: 1 = socket(17, 3, 0)
Dec  7 14:16:45 joe ppp[6972]: tun0: ID0: 148 = write(1, data, 148)
Dec  7 14:16:45 joe ppp[6972]: tun0: Debug: wrote 148: cmd = Delete, dst =
ff02:5::/32, gateway = <none>
Dec  7 14:16:45 joe ppp[6972]: tun0: ID0: 1 = socket(2, 2, 0)
Dec  7 14:16:45 joe ppp[6972]: tun0: ID0: 0 = ioctl(1, 3223349521,
0xbfbfe140)
Dec  7 14:16:45 joe ppp[6972]: tun0: ID0: 0 = ioctl(1, 2149607696,
0xbfbfe140)
Dec  7 14:16:45 joe ppp[6972]: tun0: Phase: bundle: Dead
Dec  7 14:16:45 joe ppp[6972]: tun0: ID0: 0 = ioctl(6, 2148037723,
0xbfbfeba0)
Dec  7 14:16:45 joe ppp[6972]: tun0: Debug: route_UpdateMTU (5)
Dec  7 14:16:45 joe ppp[6972]: tun0: Debug: DoLoop done.
Dec  7 14:16:45 joe ppp[6972]: tun0: Phase: PPP Terminated (normal).
Dec  7 14:16:45 joe ppp[6972]: tun0: ID0: 1 = socket(2, 2, 0)
Dec  7 14:16:45 joe ppp[6972]: tun0: ID0: 0 = ioctl(1, 2149607705,
0xbfbfeba0)
Dec  7 14:16:45 joe ppp[6972]: tun0: Warning: tun0: DIFADDR 192.168.0.230 ->
61.88.49.201 returns 0
Dec  7 14:16:45 joe ppp[6972]: tun0: ID0: 2 = socket(2, 2, 0)
Dec  7 14:16:45 joe ppp[6972]: tun0: Debug: fxp0 interface is a candidate
for proxy
Dec  7 14:16:45 joe ppp[6972]: tun0: Debug: Check addr 61.xx.xx.xx, mask
255.255.255.0
Dec  7 14:16:45 joe ppp[6972]: tun0: Debug: Found interface fxp0 for
61.xx.xx.xx
Dec  7 14:16:45 joe ppp[6972]: tun0: ID0: 3 = socket(17, 3, 2)
Dec  7 14:16:45 joe ppp[6972]: tun0: ID0: 164 = write(3, data, 164)
Dec  7 14:16:45 joe ppp[6972]: tun0: Debug: route_IfDelete (5)
Dec  7 14:16:45 joe ppp[6972]: tun0: ID0: 1 = socket(2, 2, 0)
Dec  7 14:16:45 joe ppp[6972]: tun0: ID0: 0 = ioctl(1, 3223349521,
0xbfbfebd0)
Dec  7 14:16:45 joe ppp[6972]: tun0: ID0: 0 = ioctl(1, 2149607696,
0xbfbfebd0)
Dec  7 14:16:45 joe ppp[6972]: tun0: Debug: Radius: radius_Destroy
Dec  7 14:16:45 joe ppp[6972]: tun0: ID0: 0 = unlink("/var/run/tun0.pid")

Thanks

Tim

--
Archive at http://www.open.com.au/archives/radiator/
Announcements on radiator-announce at open.com.au
To unsubscribe, email 'majordomo at open.com.au' with
'unsubscribe radiator' in the body of the message.

More information about the radiator mailing list