Occasional Proxy Errors

This is a multi-part message in MIME format.

------=_NextPart_000_016E_01C48ACA.A8BFDE70
Content-Type: text/plain;
	charset="US-ASCII"
Content-Transfer-Encoding: 7bit

Hello,
 
I've found on occasion that a proxy server can enter a state where it
doesn't recognize responses for requests it has sent out.  This causes my
client to give up and retry, but it seems that usually when it enters this
state, it will remain in this state for a while.  But I have seen a spurious
timeout here and there.
 
I've attached a log file that shows a successful access-accept forward
followed by three unsuccessful forwards.  Many more continue to happen as
the client retries.  For some reason, I've found this happens more
frequently when the proxy server forwards to localhost, stripping the realm.
This is when I first encountered this problem and I suspected this is
probably not a common usage scenario, so I set two servers up on different
machines.  The problem went away for a while, but it does still happen.

Is there any other information I could provide to try to track this down?

Cheers,
Duane

------=_NextPart_000_016E_01C48ACA.A8BFDE70
Content-Type: text/plain;
	name="proxyErrorLog.txt"
Content-Transfer-Encoding: quoted-printable
Content-Disposition: attachment;
	filename="proxyErrorLog.txt"

Aug 25 15:00:31 Auth.debug: request.c:196:_request_iterator: deleting =
completed AUTH request=0A=
Aug 25 15:00:31 Auth.debug: request.c:346:request_handle: AUTH request 0 =
added to the list. 1 requests held.=0A=
Aug 25 15:00:31 Auth.debug: request.c:196:_request_iterator: deleting =
completed AUTH request=0A=
Aug 25 15:00:31 Auth.debug: request.c:346:request_handle: AUTH request 0 =
added to the list. 1 requests held.=0A=
Aug 25 15:00:31 Auth.debug: proxy.c:248:proxy_send_request: Update =
id=3D42, proxy_id=3D20, realm=3Dbogus.domain.com, server_no=3D0=0A=
Aug 25 15:00:31 Auth.debug: proxy.c:171:proxy_send_pdu: Proxying id 42 =
to c0a801cb=0A=
Aug 25 15:00:31 Main.debug: request.c:361:request_update: enter, =
pid=3D18029, ptr =3D 0x8095b90=0A=
Aug 25 15:00:31 Main.debug: radius.c:386:radius_req_update: Update =
request 42: proxy_id=3D20, realm=3Dbogus.domain.com, server_no=3D0=0A=
Aug 25 15:00:31 Main.debug: request.c:373:request_update: exit=0A=
Aug 25 15:00:31 Main.debug: request.c:361:request_update: enter, =
pid=3D18029, ptr =3D (nil)=0A=
Aug 25 15:00:31 Main.debug: request.c:373:request_update: exit=0A=
Aug 25 15:00:32 Auth.debug: proxy.c:129:proxy_cmp: state: ipaddr =
c0a801cf, id 42, proxy_id 20, remote_ip c0a801cb=0A=
Aug 25 15:00:32 Auth.debug: proxy.c:138:proxy_cmp: (old=3Ddata) id 42 =
42, ipaddr 0xc0a801cf 0xc0a801cf, proxy_id 20 20, server_addr 0xc0a801cb =
0xc0a801cb=0A=
Aug 25 15:00:32 Auth.debug: proxy.c:144:proxy_cmp: EQUAL!!!=0A=
Aug 25 15:00:32 Auth.debug: request.c:307:request_handle: AUTH proxy =
reply. Process 18029=0A=
Aug 25 15:00:32 Auth.debug: proxy.c:129:proxy_cmp: state: ipaddr =
c0a801cf, id 42, proxy_id 20, remote_ip c0a801cb=0A=
Aug 25 15:00:32 Auth.debug: proxy.c:138:proxy_cmp: (old=3Ddata) id 42 =
42, ipaddr 0xc0a801cf 0xc0a801cf, proxy_id 20 20, server_addr 0xc0a801cb =
0xc0a801cb=0A=
Aug 25 15:00:32 Auth.debug: proxy.c:144:proxy_cmp: EQUAL!!!=0A=
Aug 25 15:00:32 Auth.debug: request.c:301:request_handle: AUTH proxy =
reply. Process 0=0A=
Aug 25 15:00:32 Auth.debug: auth.c:684:rad_authenticate: auth: user1=0A=
Aug 25 15:00:32 Auth.debug: auth.c:1175:sfn_ack: ACK: user1=0A=
Aug 25 15:00:33 Auth.debug: request.c:196:_request_iterator: deleting =
completed AUTH request=0A=
Aug 25 15:00:33 Auth.debug: request.c:346:request_handle: AUTH request 0 =
added to the list. 1 requests held.=0A=
Aug 25 15:00:33 Auth.notice: (Access-Request 192.168.1.207 42 "user1"): =
Login OK [user1]=0A=
Aug 25 15:00:33 Auth.debug: request.c:196:_request_iterator: deleting =
completed AUTH request=0A=
Aug 25 15:00:33 Main.debug: request.c:361:request_update: enter, =
pid=3D18029, ptr =3D (nil)=0A=
Aug 25 15:00:33 Auth.debug: request.c:346:request_handle: AUTH request 0 =
added to the list. 1 requests held.=0A=
Aug 25 15:00:33 Main.debug: request.c:373:request_update: exit=0A=
Aug 25 15:00:34 Auth.debug: proxy.c:248:proxy_send_request: Update =
id=3D43, proxy_id=3D21, realm=3Dbogus.domain.com, server_no=3D0=0A=
Aug 25 15:00:34 Auth.debug: proxy.c:171:proxy_send_pdu: Proxying id 43 =
to c0a801cb=0A=
Aug 25 15:00:34 Main.debug: request.c:361:request_update: enter, =
pid=3D19201, ptr =3D 0x8095b90=0A=
Aug 25 15:00:34 Main.debug: radius.c:386:radius_req_update: Update =
request 43: proxy_id=3D21, realm=3Dbogus.domain.com, server_no=3D0=0A=
Aug 25 15:00:34 Main.debug: request.c:373:request_update: exit=0A=
Aug 25 15:00:34 Main.debug: request.c:361:request_update: enter, =
pid=3D19201, ptr =3D (nil)=0A=
Aug 25 15:00:34 Main.debug: request.c:373:request_update: exit=0A=
Aug 25 15:00:34 Auth.debug: proxy.c:129:proxy_cmp: state: ipaddr =
c0a801cf, id 43, proxy_id 21, remote_ip c0a801cb=0A=
Aug 25 15:00:34 Auth.debug: proxy.c:138:proxy_cmp: (old=3Ddata) id 43 =
43, ipaddr 0xc0a801cf 0xc0a801cf, proxy_id 21 21, server_addr 0xc0a801cb =
0xc0a801cb=0A=
Aug 25 15:00:35 Auth.debug: proxy.c:144:proxy_cmp: EQUAL!!!=0A=
Aug 25 15:00:35 Auth.debug: request.c:307:request_handle: AUTH proxy =
reply. Process 19201=0A=
Aug 25 15:00:35 Auth.debug: request.c:196:_request_iterator: deleting =
completed AUTH request=0A=
Aug 25 15:00:35 Auth.debug: request.c:346:request_handle: AUTH request 0 =
added to the list. 1 requests held.=0A=
Aug 25 15:00:35 Proxy.error: (Access-Accept 192.168.1.203 21 ""): =
Unrecognized proxy reply from server 192.168.1.203, proxy ID 21=0A=
Aug 25 15:00:35 Main.debug: request.c:361:request_update: enter, =
pid=3D19201, ptr =3D (nil)=0A=
Aug 25 15:00:36 Main.debug: request.c:373:request_update: exit=0A=
Aug 25 15:00:38 Auth.debug: request.c:196:_request_iterator: deleting =
completed AUTH request=0A=
Aug 25 15:00:38 Auth.debug: request.c:346:request_handle: AUTH request 0 =
added to the list. 1 requests held.=0A=
Aug 25 15:00:38 Auth.debug: request.c:196:_request_iterator: deleting =
completed AUTH request=0A=
Aug 25 15:00:39 Auth.debug: request.c:346:request_handle: AUTH request 0 =
added to the list. 1 requests held.=0A=
Aug 25 15:00:39 Auth.debug: proxy.c:248:proxy_send_request: Update =
id=3D43, proxy_id=3D22, realm=3Dbogus.domain.com, server_no=3D0=0A=
Aug 25 15:00:39 Auth.debug: proxy.c:171:proxy_send_pdu: Proxying id 43 =
to c0a801cb=0A=
Aug 25 15:00:39 Main.debug: request.c:361:request_update: enter, =
pid=3D18029, ptr =3D 0x8095b90=0A=
Aug 25 15:00:39 Main.debug: radius.c:386:radius_req_update: Update =
request 43: proxy_id=3D22, realm=3Dbogus.domain.com, server_no=3D0=0A=
Aug 25 15:00:40 Main.debug: request.c:373:request_update: exit=0A=
Aug 25 15:00:40 Main.debug: request.c:361:request_update: enter, =
pid=3D18029, ptr =3D (nil)=0A=
Aug 25 15:00:40 Main.debug: request.c:373:request_update: exit=0A=
Aug 25 15:00:40 Auth.debug: request.c:196:_request_iterator: deleting =
completed AUTH request=0A=
Aug 25 15:00:40 Auth.debug: request.c:346:request_handle: AUTH request 0 =
added to the list. 1 requests held.=0A=
Aug 25 15:00:40 Auth.debug: request.c:196:_request_iterator: deleting =
completed AUTH request=0A=
Aug 25 15:00:40 Auth.debug: request.c:346:request_handle: AUTH request 0 =
added to the list. 1 requests held.=0A=
Aug 25 15:00:41 Proxy.error: (Access-Accept 192.168.1.203 22 ""): =
Unrecognized proxy reply from server 192.168.1.203, proxy ID 22=0A=
Aug 25 15:00:41 Main.debug: request.c:361:request_update: enter, =
pid=3D18029, ptr =3D (nil)=0A=
Aug 25 15:00:41 Main.debug: request.c:373:request_update: exit=0A=
Aug 25 15:00:43 Auth.debug: request.c:196:_request_iterator: deleting =
completed AUTH request=0A=
Aug 25 15:00:43 Auth.debug: request.c:346:request_handle: AUTH request 0 =
added to the list. 1 requests held.=0A=
Aug 25 15:00:43 Auth.debug: request.c:346:request_handle: AUTH request 0 =
added to the list. 1 requests held.=0A=
Aug 25 15:00:44 Auth.debug: proxy.c:248:proxy_send_request: Update =
id=3D43, proxy_id=3D23, realm=3Dbogus.domain.com, server_no=3D0=0A=
Aug 25 15:00:44 Auth.debug: proxy.c:171:proxy_send_pdu: Proxying id 43 =
to c0a801cb=0A=
Aug 25 15:00:44 Main.debug: request.c:361:request_update: enter, =
pid=3D18029, ptr =3D 0x8095b90=0A=
Aug 25 15:00:44 Main.debug: radius.c:386:radius_req_update: Update =
request 43: proxy_id=3D23, realm=3Dbogus.domain.com, server_no=3D0=0A=
Aug 25 15:00:44 Main.debug: request.c:373:request_update: exit=0A=
Aug 25 15:00:44 Main.debug: request.c:361:request_update: enter, =
pid=3D18029, ptr =3D (nil)=0A=
Aug 25 15:00:44 Main.debug: request.c:373:request_update: exit=0A=
Aug 25 15:00:44 Auth.debug: proxy.c:129:proxy_cmp: state: ipaddr =
c0a801cf, id 43, proxy_id 23, remote_ip c0a801cb=0A=
Aug 25 15:00:44 Auth.debug: proxy.c:138:proxy_cmp: (old=3Ddata) id 43 =
43, ipaddr 0xc0a801cf 0xc0a801cf, proxy_id 23 23, server_addr 0xc0a801cb =
0xc0a801cb=0A=
Aug 25 15:00:45 Auth.debug: proxy.c:144:proxy_cmp: EQUAL!!!=0A=
Aug 25 15:00:45 Auth.debug: request.c:307:request_handle: AUTH proxy =
reply. Process 18029=0A=
Aug 25 15:00:45 Auth.debug: request.c:196:_request_iterator: deleting =
completed AUTH request=0A=
Aug 25 15:00:45 Auth.debug: request.c:346:request_handle: AUTH request 0 =
added to the list. 1 requests held.=0A=
Aug 25 15:00:46 Proxy.error: (Access-Accept 192.168.1.203 23 ""): =
Unrecognized proxy reply from server 192.168.1.203, proxy ID 23=0A=
Aug 25 15:00:46 Main.debug: request.c:361:request_update: enter, =
pid=3D18029, ptr =3D (nil)=0A=
Aug 25 15:00:46 Main.debug: request.c:373:request_update: exit=0A=

------=_NextPart_000_016E_01C48ACA.A8BFDE70
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_016E_01C48ACA.A8BFDE70--