Proxy doesn't always forward VSAs on access-accept

This is a multi-part message in MIME format.

------=_NextPart_000_0168_01C48AC8.6FC12E00
Content-Type: text/plain;
	charset="US-ASCII"
Content-Transfer-Encoding: 7bit

 
Hello,
 
I have a setup where a NAS sends access-requests to a proxy with usernames
of the form user@realm.  The proxy strips the domain and forwards to another
server.  On the way back the proxy forwards the response to the NAS.  In my
application, the server needs to send back VSAs in an access-accept.
 
I've found that when the proxy doesn't contain the user information in its
own users file, the VSA is dropped.  If the proxy's users file mirrors the
server's, the VSA is not dropped.  It looks as though the proxy may be
modifying the packet on it's way out depending on it's own user database.
 
I've attached a tcpdump snippet of two transactions in vsaStripTcpdump.txt.
The proxy is on 207.  The server is on 203.  The first attempt drops the
VSA.  After mirroring the server's users file on the proxy, the VSA is not
dropped on the second attempt:

I've attached some of the logs from the proxy server as well in
vsaStripProxyLog.txt.

I don't believe a proxy should modify responses other than to pop off proxy
state, fix up the msg id, and recompute the authenticator.  Is my
understanding correct, and this is in fact a bug?
 
Cheers,
Duane

------=_NextPart_000_0168_01C48AC8.6FC12E00
Content-Type: text/plain;
	name="vsaStripTcpdump.txt"
Content-Transfer-Encoding: quoted-printable
Content-Disposition: attachment;
	filename="vsaStripTcpdump.txt"

16:38:17.870784 192.168.1.207.32783 > solace5.radius:  rad-access-req 79 =
[id 132] Attr[  [|radius] (DF)=0A=
16:38:17.921688 solace5.radius > 192.168.1.203.radius:  rad-access-req =
76 [id 130] Attr[  User{user} Pass NAS_ipaddr{192.168.1.207} ] (DF)=0A=
16:38:17.922189 192.168.1.203.radius > solace5.radius:  =
rad-access-accept 60 [id 130] Attr[  Vendor_specific{..C.......} =
Service_type{Login} [|radius] (DF)=0A=
16:38:18.020524 solace5.radius > 192.168.1.207.32783:  rad-access-accept =
26 [id 132] Attr[  Service_type{Login} ] (DF)=0A=
=0A=
16:38:37.627568 192.168.1.207.32783 > solace5.radius:  rad-access-req 79 =
[id 133] Attr[  [|radius] (DF)=0A=
16:38:37.665816 solace5.radius > 192.168.1.203.radius:  rad-access-req =
76 [id 131] Attr[  User{user} Pass NAS_ipaddr{192.168.1.207} ] (DF)=0A=
16:38:37.666334 192.168.1.203.radius > solace5.radius:  =
rad-access-accept 60 [id 131] Attr[  Vendor_specific{..C.......} =
Service_type{Login} [|radius] (DF)=0A=
16:38:37.753603 solace5.radius > 192.168.1.207.32783:  rad-access-accept =
38 [id 133] Attr[  Service_type{Login} Vendor_specific{..C.......} ] (DF)=0A=

------=_NextPart_000_0168_01C48AC8.6FC12E00
Content-Type: text/plain;
	name="vsaStripProxyLog.txt"
Content-Transfer-Encoding: quoted-printable
Content-Disposition: attachment;
	filename="vsaStripProxyLog.txt"

Aug 25 16:38:17 Auth.debug: request.c:196:_request_iterator: deleting =
completed AUTH request=0A=
Aug 25 16:38:17 Auth.debug: request.c:346:request_handle: AUTH request 0 =
added to the list. 1 requests held.=0A=
Aug 25 16:38:17 Auth.debug: request.c:196:_request_iterator: deleting =
completed AUTH request=0A=
Aug 25 16:38:17 Auth.debug: request.c:346:request_handle: AUTH request 0 =
added to the list. 1 requests held.=0A=
Aug 25 16:38:17 Auth.debug: proxy.c:248:proxy_send_request: Update =
id=3D132, proxy_id=3D130, realm=3Dbogus.domain.com, server_no=3D0=0A=
Aug 25 16:38:17 Auth.debug: proxy.c:171:proxy_send_pdu: Proxying id 132 =
to c0a801cb=0A=
Aug 25 16:38:17 Main.debug: request.c:361:request_update: enter, =
pid=3D31691, ptr =3D 0x809ab90=0A=
Aug 25 16:38:17 Main.debug: radius.c:386:radius_req_update: Update =
request 132: proxy_id=3D130, realm=3Dbogus.domain.com, server_no=3D0=0A=
Aug 25 16:38:17 Main.debug: request.c:373:request_update: exit=0A=
Aug 25 16:38:17 Main.debug: request.c:361:request_update: enter, =
pid=3D31691, ptr =3D (nil)=0A=
Aug 25 16:38:17 Main.debug: request.c:373:request_update: exit=0A=
Aug 25 16:38:17 Auth.debug: proxy.c:129:proxy_cmp: state: ipaddr =
c0a801cf, id 132, proxy_id 130, remote_ip c0a801cb=0A=
Aug 25 16:38:17 Auth.debug: proxy.c:138:proxy_cmp: (old=3Ddata) id 132 =
132, ipaddr 0xc0a801cf 0xc0a801cf, proxy_id 130 130, server_addr =
0xc0a801cb 0xc0a801cb=0A=
Aug 25 16:38:17 Auth.debug: proxy.c:144:proxy_cmp: EQUAL!!!=0A=
Aug 25 16:38:17 Auth.debug: request.c:307:request_handle: AUTH proxy =
reply. Process 31691=0A=
Aug 25 16:38:17 Auth.debug: proxy.c:129:proxy_cmp: state: ipaddr =
c0a801cf, id 132, proxy_id 130, remote_ip c0a801cb=0A=
Aug 25 16:38:17 Auth.debug: proxy.c:138:proxy_cmp: (old=3Ddata) id 132 =
132, ipaddr 0xc0a801cf 0xc0a801cf, proxy_id 130 130, server_addr =
0xc0a801cb 0xc0a801cb=0A=
Aug 25 16:38:17 Auth.debug: proxy.c:144:proxy_cmp: EQUAL!!!=0A=
Aug 25 16:38:18 Auth.debug: request.c:301:request_handle: AUTH proxy =
reply. Process 0=0A=
Aug 25 16:38:18 Auth.debug: auth.c:684:rad_authenticate: auth: user=0A=
Aug 25 16:38:18 Auth.debug: auth.c:1175:sfn_ack: ACK: user=0A=
Aug 25 16:38:18 Auth.notice: (Access-Request 192.168.1.207 132 "user"): =
Login OK [user]=0A=
Aug 25 16:38:18 Main.debug: request.c:361:request_update: enter, =
pid=3D31691, ptr =3D (nil)=0A=
Aug 25 16:38:18 Main.debug: request.c:373:request_update: exit=0A=
=0A=
# Restarted server to mirror the server's users file=0A=
#=0A=
Aug 25 16:38:37 Auth.debug: request.c:346:request_handle: AUTH request 0 =
added to the list. 1 requests held.=0A=
Aug 25 16:38:37 Auth.debug: request.c:346:request_handle: AUTH request 0 =
added to the list. 1 requests held.=0A=
Aug 25 16:38:37 Auth.debug: proxy.c:248:proxy_send_request: Update =
id=3D133, proxy_id=3D131, realm=3Dbogus.domain.com, server_no=3D0=0A=
Aug 25 16:38:37 Main.debug: request.c:361:request_update: enter, =
pid=3D31796, ptr =3D 0x8096e50=0A=
Aug 25 16:38:37 Auth.debug: proxy.c:171:proxy_send_pdu: Proxying id 133 =
to c0a801cb=0A=
Aug 25 16:38:37 Main.debug: radius.c:386:radius_req_update: Update =
request 133: proxy_id=3D131, realm=3Dbogus.domain.com, server_no=3D0=0A=
Aug 25 16:38:37 Main.debug: request.c:373:request_update: exit=0A=
Aug 25 16:38:37 Main.debug: request.c:361:request_update: enter, =
pid=3D31796, ptr =3D (nil)=0A=
Aug 25 16:38:37 Main.debug: request.c:373:request_update: exit=0A=
Aug 25 16:38:37 Auth.debug: proxy.c:129:proxy_cmp: state: ipaddr =
c0a801cf, id 133, proxy_id 131, remote_ip c0a801cb=0A=
Aug 25 16:38:37 Auth.debug: proxy.c:138:proxy_cmp: (old=3Ddata) id 133 =
133, ipaddr 0xc0a801cf 0xc0a801cf, proxy_id 131 131, server_addr =
0xc0a801cb 0xc0a801cb=0A=
Aug 25 16:38:37 Auth.debug: proxy.c:144:proxy_cmp: EQUAL!!!=0A=
Aug 25 16:38:37 Auth.debug: request.c:307:request_handle: AUTH proxy =
reply. Process 31796=0A=
Aug 25 16:38:37 Auth.debug: proxy.c:129:proxy_cmp: state: ipaddr =
c0a801cf, id 133, proxy_id 131, remote_ip c0a801cb=0A=
Aug 25 16:38:37 Auth.debug: proxy.c:138:proxy_cmp: (old=3Ddata) id 133 =
133, ipaddr 0xc0a801cf 0xc0a801cf, proxy_id 131 131, server_addr =
0xc0a801cb 0xc0a801cb=0A=
Aug 25 16:38:37 Auth.debug: proxy.c:144:proxy_cmp: EQUAL!!!=0A=
Aug 25 16:38:37 Auth.debug: request.c:301:request_handle: AUTH proxy =
reply. Process 0=0A=
Aug 25 16:38:37 Auth.debug: auth.c:684:rad_authenticate: auth: user=0A=
Aug 25 16:38:37 Auth.debug: auth.c:1175:sfn_ack: ACK: user=0A=
Aug 25 16:38:37 Auth.notice: (Access-Request 192.168.1.207 133 "user"): =
Login OK [user]=0A=
Aug 25 16:38:37 Main.debug: request.c:361:request_update: enter, =
pid=3D31796, ptr =3D (nil)=0A=
Aug 25 16:38:37 Main.debug: request.c:373:request_update: exit=0A=

------=_NextPart_000_0168_01C48AC8.6FC12E00
Content-Type: text/plain; charset="us-ascii"
MIME-Version: 1.0
Content-Transfer-Encoding: 7bit
Content-Disposition: inline

_______________________________________________
Bug-gnu-radius mailing list
[email protected]
http://lists.gnu.org/mailman/listinfo/bug-gnu-radius

------=_NextPart_000_0168_01C48AC8.6FC12E00--