[squid-users] WCCP v2 connection dropped intermittently: HERE_I_AM not received by router

Hello,

Anyone ever had problems with Cisco and Squid intermittently dropping
their WCCP link. We have a customer with a Cisco 7602 VXR router
linked to a Squid box (2.6 STABLE17).

They have been reporting a problem where the WCCP link goes down and
has to be renegotiated every hour or two.

When we examine the Squid wccp debug log and the cisco debug log, we
see a particular pattern of events at the time the of the wccp link
going down.

In the period leading to the failure it appears that CISCO either
doesn't receive / handle the HERE_I_AM messages from Squid, or doesn't
send the I_SEE_YOU (rcv_id += 1). eg
 * I_SEE_YOU (371)
 * HERE_I_AM (371)
Tcpdump on the Squid box doesn't show any sign of a response from Cisco.
Meanwhile Squid repeats the previous HERE_I_AM packet
 * HERE_I_AM (371)
25 seconds later Cisco responds with a "Removal_Query packet" as
specifed in "4.14 Querying Cache Time-Out" of the wccpv2 rfc.
Squid appears to receive this, but a quick look at the wccp2.c file
reveals that the REMOVAL_QUERY message is not handled in any way.
Squid continues:
 * HERE_I_AM (371)
Until eventually CISCO gives up and removes Squid from the service group.
Finally the WCCP connection is renegotiated and the system starts working again.

It seems to me that this could be an IOS bug, but we have tried
upgrading the problem router from IOS version 12.3(15)T to 12.4(22)T

We have two test routers at Versions 12.4(17b) and 12.4(11)T neither
of which show this problem with identical Squid configs.

Has anyone seen anything like this before. Debug output is below.

Cisco debug log:
{{{
Dec 18 17:08:16 xxx.xxx.xxx.xxx 468: Dec 18 13:08:41.531:
WCCP-PKT:S00: Sending I_See_You packet to yyy.yyy.yyy.yyy w/ rcv_id
000005DD
Dec 18 17:08:26 xxx.xxx.xxx.xxx 469: Dec 18 13:08:51.531:
WCCP-EVNT:wccp_update_assignment_status: enter
Dec 18 17:08:26 xxx.xxx.xxx.xxx 470: Dec 18 13:08:51.531:
WCCP-EVNT:wccp_update_assignment_status: exit
Dec 18 17:08:26 xxx.xxx.xxx.xxx 471: Dec 18 13:08:51.531:
WCCP-EVNT:wccp_validate_wc_assignments: enter
Dec 18 17:08:26 xxx.xxx.xxx.xxx 472: Dec 18 13:08:51.531:
WCCP-EVNT:wccp_validate_wc_assignments: not mask assignment, exit
Dec 18 17:08:26 xxx.xxx.xxx.xxx 473: Dec 18 13:08:51.531:
WCCP-PKT:S00: Sending I_See_You packet to yyy.yyy.yyy.yyy w/ rcv_id
000005DE
Dec 18 17:08:51 xxx.xxx.xxx.xxx 474: Dec 18 13:09:16.531:
WCCP-PKT:S00: Sending Removal_Query packet to yyy.yyy.yyy.yyyw/ rcv_id
000005DF
Dec 18 17:08:55 xxx.xxx.xxx.xxx 475: Dec 18 13:09:21.531:
WCCP-EVNT:wccp_change_router_view: S00
Dec 18 17:08:55 xxx.xxx.xxx.xxx 476: Dec 18 13:09:21.531:
WCCP-EVNT:wccp_change_router_view: deallocate rtr_view (72 bytes)
Dec 18 17:08:55 xxx.xxx.xxx.xxx 477: Dec 18 13:09:21.531:
WCCP-EVNT:wccp_change_router_view: allocate hash rtr_view (1564 bytes)
Dec 18 17:08:55 xxx.xxx.xxx.xxx 478: Dec 18 13:09:21.531:
WCCP-EVNT:wccp_change_router_view: rtr_view_size set to 68 bytes
Dec 18 17:08:55 xxx.xxx.xxx.xxx 479: Dec 18 13:09:21.531:
WCCP-EVNT:S00: Assignment wait timer started
Dec 18 17:08:55 xxx.xxx.xxx.xxx 480: Dec 18 13:09:21.531:
WCCP-EVNT:S00: Built new router view: 0 routers, 1 usable WCCP
clients, change # 00000009
Dec 18 17:08:55 xxx.xxx.xxx.xxx 481: Dec 18 13:09:21.531:
WCCP-EVNT:S00: Router zzz.zzz.zzz.zzz removed.
}}}

Squid wccp debug log:

{{{
2008/12/18 17:11:06| wccp2HereIam: Called
2008/12/18 17:11:06| wccp2HereIam: sending to service id 0
2008/12/18 17:11:06| wccp2_update_md5_security: called
2008/12/18 17:11:06| Sending HereIam packet size 160
2008/12/18 17:11:06| wccp2HandleUdp: Called.
2008/12/18 17:11:06| Incoming WCCPv2 I_SEE_YOU length 148.
2008/12/18 17:11:06| Complete packet received
2008/12/18 17:11:06| Incoming WCCP2_I_SEE_YOU Received ID old=1500 new=1501.
2008/12/18 17:11:06| Cleaning out cache list
2008/12/18 17:11:06| checking cache list: (12b05ed0:12b05ed0)
2008/12/18 17:11:06| Change not detected (8 = 8)

2008/12/18 17:11:16| wccp2HereIam: Called
2008/12/18 17:11:16| wccp2HereIam: sending to service id 0
2008/12/18 17:11:16| wccp2_update_md5_security: called
2008/12/18 17:11:16| Sending HereIam packet size 160
2008/12/18 17:11:16| wccp2HandleUdp: Called.
2008/12/18 17:11:16| Incoming WCCPv2 I_SEE_YOU length 148.
2008/12/18 17:11:16| Complete packet received
2008/12/18 17:11:16| Incoming WCCP2_I_SEE_YOU Received ID old=1501 new=1502.
2008/12/18 17:11:16| Cleaning out cache list
2008/12/18 17:11:16| checking cache list: (12b05ed0:12b05ed0)
2008/12/18 17:11:16| Change not detected (8 = 8)

2008/12/18 17:11:26| wccp2HereIam: Called
2008/12/18 17:11:26| wccp2HereIam: sending to service id 0
2008/12/18 17:11:26| wccp2_update_md5_security: called
2008/12/18 17:11:26| Sending HereIam packet size 160

2008/12/18 17:11:36| wccp2HereIam: Called
2008/12/18 17:11:36| wccp2HereIam: sending to service id 0
2008/12/18 17:11:36| wccp2_update_md5_security: called
2008/12/18 17:11:36| Sending HereIam packet size 160

2008/12/18 17:11:41| wccp2HandleUdp: Called.

2008/12/18 17:11:46| wccp2HereIam: Called
2008/12/18 17:11:46| wccp2HereIam: sending to service id 0
2008/12/18 17:11:46| wccp2_update_md5_security: called
2008/12/18 17:11:46| Sending HereIam packet size 160

2008/12/18 17:11:56| wccp2HereIam: Called
2008/12/18 17:11:56| wccp2HereIam: sending to service id 0
2008/12/18 17:11:56| wccp2_update_md5_security: called
2008/12/18 17:11:56| Sending HereIam packet size 160

2008/12/18 17:12:06| wccp2HereIam: Called
2008/12/18 17:12:06| wccp2HereIam: sending to service id 0
2008/12/18 17:12:06| wccp2_update_md5_security: called
2008/12/18 17:12:06| Sending HereIam packet size 160

2008/12/18 17:12:16| wccp2HereIam: Called
2008/12/18 17:12:16| wccp2HereIam: sending to service id 0
2008/12/18 17:12:16| wccp2_update_md5_security: called
2008/12/18 17:12:16| Sending HereIam packet size 160

2008/12/18 17:12:26| wccp2HereIam: Called
2008/12/18 17:12:26| wccp2HereIam: sending to service id 0
2008/12/18 17:12:26| wccp2_update_md5_security: called
2008/12/18 17:12:26| Sending HereIam packet size 160

2008/12/18 17:12:36| wccp2HereIam: Called
2008/12/18 17:12:36| wccp2HereIam: sending to service id 0
2008/12/18 17:12:36| wccp2_update_md5_security: called
2008/12/18 17:12:36| Sending HereIam packet size 160
2008/12/18 17:12:36| wccp2HandleUdp: Called.
2008/12/18 17:12:36| Incoming WCCPv2 I_SEE_YOU length 128.
2008/12/18 17:12:36| Complete packet received
2008/12/18 17:12:36| Incoming WCCP2_I_SEE_YOU Received ID old=1502 new=1504.
2008/12/18 17:12:36| Cleaning out cache list
2008/12/18 17:12:36| Adding ourselves as the only cache
2008/12/18 17:12:36| Change detected - queueing up new assignment
}}}

-- 
Richard Wall
ApplianSys Ltd
http://www.appliansys.com