(RADIATOR) FreeBSD PPPOE and radiator
Hugh Irvine
hugh at open.com.au
Wed Dec 8 16:09:03 CST 2004
Hello Tim -
Thanks for sending the debugs.
As far as I can see, Radiator is correctly processing the radius access
request and returning an access accept, however the PPPOE debug shows
that the reply is not getting back to the PPPOE server and it simply
retries unsuccessfully.
I suspect you will need to check filters and/or firewall rules to find
out where the radius reply is being blocked.
A good packet sniffer (ethereal, tcpdump, ...) is generally a really
useful tool for this sort of work.
regards
Hugh
On 8 Dec 2004, at 15:58, Tim McCullagh wrote:
> 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.
>
>
NB:
Have you read the reference manual ("doc/ref.html")?
Have you searched the mailing list archive
(www.open.com.au/archives/radiator)?
Have you had a quick look on Google (www.google.com)?
Have you included a copy of your configuration file (no secrets),
together with a trace 4 debug showing what is happening?
--
Radiator: the most portable, flexible and configurable RADIUS server
anywhere. Available on *NIX, *BSD, Windows, MacOS X.
-
Nets: internetwork inventory and management - graphical, extensible,
flexible with hardware, software, platform and database independence.
-
CATool: Private Certificate Authority for Unix and Unix-like systems.
--
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