RE: [squid-users] CISCO + WCCP Stopping forward packets

Yup....looks like an IOS related problem....try a different release of IOS.

-----Original Message-----
From: alexmontoanelli_at_gmail.com on behalf of Alex Montoanelli
Sent: Mon 5/4/2009 4:00 PM
To: squid-users
Subject: Re: [squid-users] CISCO + WCCP Stopping forward packets
 
Hi, after a day works fine, the problem appear.

I see the HereIAm and ISeeYou  packets between Cisco and Squid, above
is the logs of both.

I have 4 Instances of Squid, running on the same machine, I just
shutdown 3 of then, and start again, and every one
go to normal. The fourth instance back to normal without any touch.

The *** mark, is the begin of trouble.

------CISCO--------
May  4 17:21:32 cliente-1-254.unetvale.com.br 240185: 240210: *May  4
21:23:36: WCCP-PKT:S00: Sending I_See_You packet to 200.193.10.140 w/
rcv_id 00091ACD
May  4 17:21:37 cliente-1-254.unetvale.com.br 240188: 240213: *May  4
21:23:41: WCCP-PKT:S00: Received valid Here_I_Am packet from
200.193.10.141 w/rcv_id 00091ACB
May  4 17:21:37 cliente-1-254.unetvale.com.br 240189: 240214: *May  4
21:23:41: WCCP-PKT:S00: Sending I_See_You packet to 200.193.10.141 w/
rcv_id 00091ACF
May  4 17:21:41 cliente-1-254.unetvale.com.br 240190: 240215: *May  4
21:23:44: WCCP-PKT:S00: Received valid Here_I_Am packet from
200.193.10.143 w/rcv_id 00091ACC
May  4 17:21:41 cliente-1-254.unetvale.com.br 240191: 240216: *May  4
21:23:44: WCCP-PKT:S00: Sending I_See_You packet to 200.193.10.143 w/
rcv_id 00091AD0
May  4 17:21:42 cliente-1-254.unetvale.com.br 240192: 240217: *May  4
21:23:46: WCCP-PKT:S00: Received valid Here_I_Am packet from
200.193.10.140 w/rcv_id 00091ACD
May  4 17:21:42 cliente-1-254.unetvale.com.br 240193: 240218: *May  4
21:23:46: WCCP-PKT:S00: Sending I_See_You packet to 200.193.10.140 w/
rcv_id 00091AD1
May  4 17:22:31 cliente-1-254.unetvale.com.br 240244: 240269: *May  4
21:24:35: WCCP-EVNT:S00: Here_I_Am packet from 200.193.10.141 w/bad
rcv_id 00091ACB
May  4 17:22:32 cliente-1-254.unetvale.com.br 240247: 240272: *May  4
21:24:36: WCCP-EVNT:S00: Here_I_Am packet from 200.193.10.140 w/bad
rcv_id 00091AD1
May  4 17:23:27 cliente-1-254.unetvale.com.br 240310: 240335: *May  4
21:25:30: WCCP-PKT:S00: Received valid Here_I_Am packet from
200.193.10.143 w/rcv_id 00091AFE
****May  4 17:23:27 cliente-1-254.unetvale.com.br 240311: 240336: *May
 4 21:25:30: WCCP-EVNT:S00: Assignment wait timer started
May  4 17:23:31 cliente-1-254.unetvale.com.br 240314: 240339: *May  4
21:25:34: WCCP-EVNT:S00: Redirect_Assignment packet from
200.193.10.143 w/bad rcv_id 00091AFE
May  4 17:24:54 cliente-1-254.unetvale.com.br 240378: 240403: *May  4
21:26:58: WCCP-EVNT:S00: Here_I_Am packet from 200.193.10.140 w/bad
rcv_id 00091AD1
May  4 17:24:54 cliente-1-254.unetvale.com.br 240379: 240404: *May  4
21:26:58: WCCP-PKT:S00: Sending I_See_You packet to 200.193.10.140 w/
rcv_id 00091B24
May  4 17:25:34 cliente-1-254.unetvale.com.br 240419: 240444: *May  4
21:27:38: WCCP-PKT:S00: Sending I_See_You packet to 200.193.10.140 w/
rcv_id 00091B39
May  4 17:25:42 cliente-1-254.unetvale.com.br 240429: 240454: *May  4
21:27:46: WCCP-EVNT:S00: Here_I_Am packet from 200.193.10.141 w/bad
rcv_id 00091ACB
May  4 17:25:51 cliente-1-254.unetvale.com.br 240437: 240462: *May  4
21:27:55: WCCP-PKT:S00: Sending I_See_You packet to 200.193.10.143 w/
rcv_id 00091B40
May  4 17:25:53 cliente-1-254.unetvale.com.br 240438: 240463: *May  4
21:27:57: WCCP-EVNT:S00: Here_I_Am packet from 200.193.10.141 w/bad
rcv_id 00091ACB
May  4 17:25:53 cliente-1-254.unetvale.com.br 240439: 240464: *May  4
21:27:57: WCCP-PKT:S00: Sending I_See_You packet to 200.193.10.141 w/
rcv_id 00091B41
May  4 17:25:57 cliente-1-254.unetvale.com.br 240440: 240465: *May  4
21:28:01: WCCP-PKT:S00: Sending Removal_Query packet to
200.193.10.141w/ rcv_id 00091B42
May  4 17:25:58 cliente-1-254.unetvale.com.br 240441: 240466: *May  4
21:28:02: WCCP-EVNT:S00: Here_I_Am packet from 200.193.10.140 w/bad
rcv_id 00091AD1
May  4 17:25:58 cliente-1-254.unetvale.com.br 240442: 240467: *May  4
21:28:02: WCCP-PKT:S00: Sending I_See_You packet to 200.193.10.140 w/
rcv_id 00091B43
May  4 17:25:58 cliente-1-254.unetvale.com.br 240443: 240468: *May  4
21:28:03: WCCP-EVNT:S00: Here_I_Am packet from 200.193.10.142 w/bad
rcv_id 00091B25
May  4 17:25:58 cliente-1-254.unetvale.com.br 240444: 240469: *May  4
21:28:03: WCCP-PKT:S00: Sending I_See_You packet to 200.193.10.142 w/
rcv_id 00091B44
May  4 17:25:58 cliente-1-254.unetvale.com.br 240445: 240470: *May  4
21:28:03: WCCP-PKT:S00: Sending Removal_Query packet to
200.193.10.140w/ rcv_id 00091B45
May  4 17:26:00 cliente-1-254.unetvale.com.br 240446: 240471: *May  4
21:28:04: WCCP-PKT:S00: Sending Removal_Query packet to
200.193.10.142w/ rcv_id 00091B46
May  4 17:26:23 cliente-1-254.unetvale.com.br 240474: 240499: *May  4
21:28:27: WCCP-EVNT:S00: Here_I_Am packet from 200.193.10.141 w/bad
rcv_id 00091B41
May  4 17:26:28 cliente-1-254.unetvale.com.br 240476: 240501: *May  4
21:28:32: WCCP-PKT:S00: Sending Removal_Query packet to
200.193.10.141w/ rcv_id 00091B51
May  4 17:26:28 cliente-1-254.unetvale.com.br 240477: 240502: *May  4
21:28:32: WCCP-EVNT:S00: Here_I_Am packet from 200.193.10.140 w/bad
rcv_id 00091B49
----------

Squid - Cachelog
----------
2009/05/04 17:21:33| ctx: enter level 0:
'http://wm-ttv-mirror01-mia.terra.com/kboing/439755.asf'
2009/05/04 17:21:33| httpProcessReplyHeader: Impossible keep-alive
header from 'http://wm-ttv-mirror01-mia.terra.com/kboing/439755.asf'
2009/05/04 17:21:41| ctx: exit level 0
2009/05/04 17:21:41| wccp2HereIam: sending to service id 0
2009/05/04 17:21:41| Sending HereIam packet size 144
2009/05/04 17:21:41| Incoming WCCPv2 I_SEE_YOU length 264.
2009/05/04 17:21:41| Complete packet received
2009/05/04 17:21:41| Incoming WCCP2_I_SEE_YOU Received ID old=596685 new=596689.
2009/05/04 17:21:41| Cleaning out cache list
2009/05/04 17:21:41| checking cache list: (8c0ac1c8:8c0ac1c8)
2009/05/04 17:21:41| checking cache list: (8d0ac1c8:8c0ac1c8)
2009/05/04 17:21:41| checking cache list: (8e0ac1c8:8c0ac1c8)
2009/05/04 17:21:41| checking cache list: (8f0ac1c8:8c0ac1c8)
2009/05/04 17:21:41| Change not detected (2496 = 2496)
2009/05/04 17:21:44| ctx: enter level 0: 'http://br.msn.com/'
2009/05/04 17:21:44| httpProcessReplyHeader: Impossible keep-alive
header from 'http://br.msn.com/'
2009/05/04 17:21:51| ctx: exit level 0
2009/05/04 17:21:51| wccp2HereIam: sending to service id 0
2009/05/04 17:21:51| Sending HereIam packet size 144
2009/05/04 17:22:01| wccp2HereIam: sending to service id 0
2009/05/04 17:22:01| Sending HereIam packet size 144
2009/05/04 17:22:11| wccp2HereIam: sending to service id 0
2009/05/04 17:22:11| Sending HereIam packet size 144
2009/05/04 17:22:21| wccp2HereIam: sending to service id 0
2009/05/04 17:22:21| Sending HereIam packet size 144
2009/05/04 17:22:25| CACHEMGR: <unknown>@10.100.0.101 requesting 'info'
2009/05/04 17:22:21| wccp2HereIam: sending to service id 0
2009/05/04 17:22:21| Sending HereIam packet size 144
2009/05/04 17:22:25| CACHEMGR: <unknown>@10.100.0.101 requesting 'info'
2009/05/04 17:22:25| CACHEMGR: <unknown>@10.100.0.101 requesting 'info'
2009/05/04 17:22:30| CACHEMGR: <unknown>@10.100.0.101 requesting 'counters'
2009/05/04 17:22:30| CACHEMGR: <unknown>@10.100.0.101 requesting 'info'
2009/05/04 17:22:31| wccp2HereIam: sending to service id 0
2009/05/04 17:22:31| Sending HereIam packet size 144
2009/05/04 17:22:41| wccp2HereIam: sending to service id 0
2009/05/04 17:22:41| Sending HereIam packet size 144
2009/05/04 17:22:51| wccp2HereIam: sending to service id 0
2009/05/04 17:22:51| Sending HereIam packet size 144
2009/05/04 17:23:01| wccp2HereIam: sending to service id 0
2009/05/04 17:23:01| Sending HereIam packet size 144
2009/05/04 17:23:11| wccp2HereIam: sending to service id 0
2009/05/04 17:23:11| Sending HereIam packet size 144
2009/05/04 17:23:26| wccp2HereIam: sending to service id 0
2009/05/04 17:23:26| Sending HereIam packet size 144
2009/05/04 17:24:33| wccp2HereIam: sending to service id 0
2009/05/04 17:24:33| Sending HereIam packet size 144
2009/05/04 17:24:43| wccp2HereIam: sending to service id 0
2009/05/04 17:24:43| Sending HereIam packet size 144
2009/05/04 17:24:53| wccp2HereIam: sending to service id 0
2009/05/04 17:24:53| Sending HereIam packet size 144
2009/05/04 17:25:03| wccp2HereIam: sending to service id 0
2009/05/04 17:25:03| Sending HereIam packet size 144
2009/05/04 17:25:13| wccp2HereIam: sending to service id 0
2009/05/04 17:25:13| Sending HereIam packet size 144
2009/05/04 17:25:23| wccp2HereIam: sending to service id 0
2009/05/04 17:25:23| Sending HereIam packet size 144
2009/05/04 17:25:33| wccp2HereIam: sending to service id 0
2009/05/04 17:25:33| Sending HereIam packet size 144
-------------

Alex Montoanelli
Administração e Gerência de Redes
Unetvale Conectividade
+55 48 3263 8700

On Mon, May 4, 2009 at 11:35 AM, Ritter, Nicholas
<Nicholas.Ritter_at_americantv.com> wrote:
>
> I have not noticed other faqs requiring this, but make sure your iptables is allowing UDP port 2048 on the Ethernet and gre interfaces of the squid box and coming from the IP address listed in the "sh ip wccp" (the router identifier IP.)
>
> Also, update you IOS. The loss of the hello packets is the problem, but the reason behind the packet transmission loss is the mystery. You can try running a packet sniffer on the squid box to make sure it is sending the "Here I am" packets, are increase the debug level of squid to see them.
>
> My experience as been that the problem is on the Cisco side though.
>
> -----Original Message-----
> From: alexmontoanelli_at_gmail.com [mailto:alexmontoanelli_at_gmail.com] On Behalf Of Alex Montoanelli
> Sent: Monday, May 04, 2009 8:57 AM
> To: Ritter, Nicholas
> Subject: Re: [squid-users] CISCO + WCCP Stopping forward packets
>
> Hello Nicholas.
>
> When the service break down, the related fields, are not 0, is equal
> 1/1. ( 1 Client / 1 Router ).
>
> I have setting up a router to log to a syslog server, and when the
> issue occur, the packets/messages are not transmited.
>
> My router, a Cisco 2811 has running a
> 'flash:c2800nm-ipbase-mz.124-21.bin' / 12.4-21 IOS Version.
>
> On Mon, May 4, 2009 at 10:45 AM, Ritter, Nicholas
> <Nicholas.Ritter_at_americantv.com> wrote:
> >
> > Two things you can do:
> >
> > 1) When the wccp service breaks as you describe, do a "sh ip wccp" on
> > the router, make sure that "Number of Service Group Clients" and "Number
> > of Service Group Routers" are both no zero.
> >
> > 2)
> >
> > On the router:
> >
> > Debug ip wccp
> >
> >  - make sure your logging is set to debug level on the router
> >
> > What for the "Here I am" and "I see you" packets, which identifies that
> > the router and the squid box see each other.
> >
> >
> > One important thing, make sure you router is running the most recent
> > version of IOS...different revisions have WCCP problems come and go. I
> > have been running 12.4(15)T8 without problems for months.
> >
> > I was running various sub releases of 12.4 and had problems...but
> > 12.4(15)T8 seems stable.
> >
> > Nick
> >
> >
> > -----Original Message-----
> > From: alexmontoanelli_at_gmail.com [mailto:alexmontoanelli_at_gmail.com] On
> > Behalf Of Alex Montoanelli
> > Sent: Monday, May 04, 2009 7:13 AM
> > To: squid-users
> > Subject: [squid-users] CISCO + WCCP Stopping forward packets
> >
> > Hello all.
> >
> > I have a FreeBSD Box, running Squid Version 2.7.STABLE6-20090306, with
> > WCCP2 features on, with my Cisco Router 2811.
> >
> > It's running fine, but after a few hours, the traffic is not forwarded
> > from Cisco do Squid Box.
> >
> > I don't see any packet on gre0 and a 'show ip wccp' in Cisco, has not
> > increment counters from redirected packets.
> >
> > In my logs (cisco e squid) I could not get nothing;
> >
> > someone has been there?
> >
> > Regards
> >
> > Alex Montoanelli
> >
> >
>
Received on Tue May 05 2009 - 00:08:48 MDT