RE: Occasional Proxy Errors
"Duane Pauls" <[email protected]> Fri, 27 Aug 2004 11:50:17 -0400
| Newsgroups | gmane.comp.gnu.radius.bugs |
|---|---|
| Message-ID | <[email protected]> |
This is a multi-part message in MIME format.
------=_NextPart_000_0212_01C48C2C.0D19C9A0
Content-Type: text/plain;
charset="US-ASCII"
Content-Transfer-Encoding: 7bit
>> 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
> It seems that the server 192.168.1.203 does not preserve Proxy-State
> attribute. This attribute must be left intact for the proxying to work.
I observed this problem again, but this time was capturing the RADIUS
traffic with tcpdump (attached in tcpdumpProxyError.txt). It looks like
server 203 is maintaining the proxy-state attribute (the last 0x16 bytes of
each message). The RADIUS packet starts at offset 0x1c into the displayed
data. The first rad-access-req/rad-access-accept pair is the pair that
caused a Proxy.error by the proxy on server 205. The second
rad-access-req/rad-access-accept pair is the pair that succeeded.
I don't notice any difference, other than a longer turnaround time in the
failure case and:
- the ID number
- authenticators
- encrypted passwords (due to different authenticators)
- ID number embedded in proxy state
These are all differences I expect. I don't know if the longer turnaround
time is somehow exposing this problem?
The logs for proxy server (205) are attached in logProxyError.txt.
This problem is intermittent, and sometimes persists for a while. This
time, it was a single error and recovered after a the client retried.
Do you have any suggestions for something else I could look at to further
pinpoint the source of this problem?
Regards,
Duane
------=_NextPart_000_0212_01C48C2C.0D19C9A0
Content-Type: text/plain;
name="tcpdumpProxyError.txt"
Content-Transfer-Encoding: quoted-printable
Content-Disposition: attachment;
filename="tcpdumpProxyError.txt"
11:06:08.387142 192.168.1.205.radius > solace3.radius: rad-access-req =
76 [id 102] Attr[ User{pubuser1} Pass NAS_ipaddr{192.168.1.207} =
Proxy_state{....f...............} ] (DF)=0A=
4500 0068 0000 4000 4011 b59c c0a8 01cd=0A=
c0a8 01cb 0714 0714 0054 f483 0166 004c=0A=
bec8 df66 fd68 aa37 6a5e 4856 ae8e 4977=0A=
010a 7075 6275 7365 7231 0212 2789 2543=0A=
47ad fd0d 6fa4 5c83 490c 743f 0406 c0a8=0A=
01cf 2116 cd01 a8c0 6600 0000 cb01 a8c0=0A=
cf01 a8c0 0000 0000=0A=
11:06:08.388317 solace3.radius > 192.168.1.205.radius: =
rad-access-accept 60 [id 102] Attr[ Vendor_specific{..C.......} =
Service_type{Login} Proxy_state{....f...............} ] (DF)=0A=
4500 0058 0000 4000 4011 b5ac c0a8 01cb=0A=
c0a8 01cd 0714 0714 0044 dbe7 0266 003c=0A=
c5fa 728d 62e6 9cad 700b f27a d065 d592=0A=
1a0c 0000 43b9 0106 0000 0000 0606 0000=0A=
0001 2116 cd01 a8c0 6600 0000 cb01 a8c0=0A=
cf01 a8c0 0000 0000=0A=
11:06:12.549624 192.168.1.205.radius > solace3.radius: rad-access-req =
76 [id 103] Attr[ User{pubuser1} Pass NAS_ipaddr{192.168.1.207} =
Proxy_state{....g...............} ] (DF)=0A=
4500 0068 0000 4000 4011 b59c c0a8 01cd=0A=
c0a8 01cb 0714 0714 0054 2d20 0167 004c=0A=
f109 960b 9ac9 3b62 f746 a21f c7b1 a518=0A=
010a 7075 6275 7365 7231 0212 b3ad 7692=0A=
dfa2 8cce c2bb 07aa e0e2 2c7c 0406 c0a8=0A=
01cf 2116 cd01 a8c0 6700 0000 cb01 a8c0=0A=
cf01 a8c0 0000 0000=0A=
11:06:12.549991 solace3.radius > 192.168.1.205.radius: =
rad-access-accept 60 [id 103] Attr[ Vendor_specific{..C.......} =
Service_type{Login} Proxy_state{....g...............} ] (DF)=0A=
4500 0058 0000 4000 4011 b5ac c0a8 01cb=0A=
c0a8 01cd 0714 0714 0044 f90c 0267 003c=0A=
0f32 f93e 8f31 2284 940e 3603 181e 861e=0A=
1a0c 0000 43b9 0106 0000 0000 0606 0000=0A=
0001 2116 cd01 a8c0 6700 0000 cb01 a8c0=0A=
cf01 a8c0 0000 0000=0A=
------=_NextPart_000_0212_01C48C2C.0D19C9A0
Content-Type: text/plain;
name="logProxyError.txt"
Content-Transfer-Encoding: quoted-printable
Content-Disposition: attachment;
filename="logProxyError.txt"
Aug 27 11:06:07 Auth.debug: request.c:196:_request_iterator: deleting =
completed AUTH request=0A=
Aug 27 11:06:07 Auth.debug: request.c:346:request_handle: AUTH request 0 =
added to the list. 1 requests held.=0A=
Aug 27 11:06:07 Auth.debug: request.c:346:request_handle: AUTH request 0 =
added to the list. 1 requests held.=0A=
Aug 27 11:06:08 Auth.debug: proxy.c:248:proxy_send_request: Update =
id=3D0, proxy_id=3D102, realm=3Dbogus.domain.com, server_no=3D0=0A=
Aug 27 11:06:08 Main.debug: request.c:361:request_update: enter, =
pid=3D2768, ptr =3D 0x8094ee8=0A=
Aug 27 11:06:08 Auth.debug: proxy.c:171:proxy_send_pdu: Proxying id 0 to =
c0a801cb=0A=
Aug 27 11:06:08 Main.debug: radius.c:386:radius_req_update: Update =
request 0: proxy_id=3D102, realm=3Dbogus.domain.com, server_no=3D0=0A=
Aug 27 11:06:08 Main.debug: request.c:373:request_update: exit=0A=
Aug 27 11:06:08 Main.debug: request.c:361:request_update: enter, =
pid=3D2768, ptr =3D (nil)=0A=
Aug 27 11:06:08 Main.debug: request.c:373:request_update: exit=0A=
Aug 27 11:06:08 Auth.debug: proxy.c:129:proxy_cmp: state: ipaddr =
c0a801cf, id 0, proxy_id 102, remote_ip c0a801cb=0A=
Aug 27 11:06:08 Auth.debug: proxy.c:138:proxy_cmp: (old=3Ddata) id 0 0, =
ipaddr 0xc0a801cf 0xc0a801cf, proxy_id 102 102, server_addr 0xc0a801cb =
0xc0a801cb=0A=
Aug 27 11:06:08 Auth.debug: proxy.c:144:proxy_cmp: EQUAL!!!=0A=
Aug 27 11:06:09 Auth.debug: request.c:307:request_handle: AUTH proxy =
reply. Process 2768=0A=
Aug 27 11:06:09 Auth.debug: request.c:196:_request_iterator: deleting =
completed AUTH request=0A=
Aug 27 11:06:09 Auth.debug: request.c:346:request_handle: AUTH request 0 =
added to the list. 1 requests held.=0A=
Aug 27 11:06:09 Proxy.error: (Access-Accept 192.168.1.203 102 ""): =
Unrecognized proxy reply from server 192.168.1.203, proxy ID 102=0A=
Aug 27 11:06:09 Main.debug: request.c:361:request_update: enter, =
pid=3D2768, ptr =3D (nil)=0A=
Aug 27 11:06:09 Main.debug: request.c:373:request_update: exit=0A=
Aug 27 11:06:12 Auth.debug: request.c:196:_request_iterator: deleting =
completed AUTH request=0A=
Aug 27 11:06:12 Auth.debug: request.c:346:request_handle: AUTH request 0 =
added to the list. 1 requests held.=0A=
Aug 27 11:06:12 Auth.debug: request.c:346:request_handle: AUTH request 0 =
added to the list. 1 requests held.=0A=
Aug 27 11:06:12 Auth.debug: proxy.c:248:proxy_send_request: Update =
id=3D0, proxy_id=3D103, realm=3Dbogus.domain.com, server_no=3D0=0A=
Aug 27 11:06:12 Main.debug: request.c:361:request_update: enter, =
pid=3D2768, ptr =3D 0x8094ee8=0A=
Aug 27 11:06:12 Auth.debug: proxy.c:171:proxy_send_pdu: Proxying id 0 to =
c0a801cb=0A=
Aug 27 11:06:12 Main.debug: radius.c:386:radius_req_update: Update =
request 0: proxy_id=3D103, realm=3Dbogus.domain.com, server_no=3D0=0A=
Aug 27 11:06:12 Main.debug: request.c:373:request_update: exit=0A=
Aug 27 11:06:12 Main.debug: request.c:361:request_update: enter, =
pid=3D2768, ptr =3D (nil)=0A=
Aug 27 11:06:12 Main.debug: request.c:373:request_update: exit=0A=
Aug 27 11:06:12 Auth.debug: proxy.c:129:proxy_cmp: state: ipaddr =
c0a801cf, id 0, proxy_id 103, remote_ip c0a801cb=0A=
Aug 27 11:06:12 Auth.debug: proxy.c:138:proxy_cmp: (old=3Ddata) id 0 0, =
ipaddr 0xc0a801cf 0xc0a801cf, proxy_id 103 103, server_addr 0xc0a801cb =
0xc0a801cb=0A=
Aug 27 11:06:12 Auth.debug: proxy.c:144:proxy_cmp: EQUAL!!!=0A=
Aug 27 11:06:12 Auth.debug: request.c:307:request_handle: AUTH proxy =
reply. Process 2768=0A=
Aug 27 11:06:12 Auth.debug: proxy.c:129:proxy_cmp: state: ipaddr =
c0a801cf, id 0, proxy_id 103, remote_ip c0a801cb=0A=
Aug 27 11:06:12 Auth.debug: proxy.c:138:proxy_cmp: (old=3Ddata) id 0 0, =
ipaddr 0xc0a801cf 0xc0a801cf, proxy_id 103 103, server_addr 0xc0a801cb =
0xc0a801cb=0A=
Aug 27 11:06:12 Auth.debug: proxy.c:144:proxy_cmp: EQUAL!!!=0A=
Aug 27 11:06:12 Auth.debug: request.c:301:request_handle: AUTH proxy =
reply. Process 0=0A=
Aug 27 11:06:12 Auth.debug: auth.c:684:rad_authenticate: auth: pubuser1=0A=
Aug 27 11:06:12 Auth.debug: auth.c:1175:sfn_ack: ACK: pubuser1=0A=
Aug 27 11:06:12 Auth.notice: (Access-Request 192.168.1.207 0 =
"pubuser1"): Login OK [pubuser1]=0A=
Aug 27 11:06:12 Main.debug: request.c:361:request_update: enter, =
pid=3D2768, ptr =3D (nil)=0A=
Aug 27 11:06:12 Main.debug: request.c:373:request_update: exit=0A=
------=_NextPart_000_0212_01C48C2C.0D19C9A0
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_0212_01C48C2C.0D19C9A0--