Re: [squid-users] Service Lost issues using WCCP v2

On Thu, 2007-07-19 at 17:07 +0800, Adrian Chadd wrote:
> On Thu, Jul 19, 2007, Arnaud Loonstra wrote:
>
> > What do you mean drifting. I've just check the clock on the router and
> > the cache:
> >
> > cache: Thu Jul 19 10:48:29 CEST 2007
> > router: *10:39:55.771 CET Thu Jul 19 2007
> >
> > So they are 10 minutes apart.
> > I'll sync the cache clock using ntp which I should anyway. See if it
> > helps?
>
> Well, WCCPv2 has 10 second event intervals, and the dead peer time is
> 3 x the I_SEE_YOU time of 10 seconds; so your proxy must be not responding
> to WCCPv2 for > 30 seconds. Maybe if its in a VM the event scheduling
> is busted, or if the server is heavily loaded, or if somethings filtering/
> dropping the UDP packets.
>
> Its hard for me to diagnose further without having access to the kit.
> Hopefully someone else can help you on the mailing list.
>
>
>
>
> Adrian
>
It seems it's the other way around. A tcpdump reveals that the Cisco is
not responding:

192.168.0.6 is the router.

11:55:26.386400 IP 192.168.0.6.2048 > proxy.2048: UDP, length 92
11:55:36.386101 IP proxy.2048 > 192.168.0.6.2048: UDP, length 144
11:55:36.387536 IP 192.168.0.6.2048 > proxy.2048: UDP, length 140
11:55:46.386740 IP proxy.2048 > 192.168.0.6.2048: UDP, length 144
11:55:46.387618 IP 192.168.0.6.2048 > proxy.2048: UDP, length 140
11:55:51.387101 IP proxy.2048 > 192.168.0.6.2048: UDP, length 336
11:55:56.387430 IP proxy.2048 > 192.168.0.6.2048: UDP, length 144
11:55:56.388326 IP 192.168.0.6.2048 > proxy.2048: UDP, length 140
11:56:06.388078 IP proxy.2048 > 192.168.0.6.2048: UDP, length 144
11:56:06.388889 IP 192.168.0.6.2048 > proxy.2048: UDP, length 140
11:56:16.388763 IP proxy.2048 > 192.168.0.6.2048: UDP, length 144
--- no response??
11:56:16.389566 IP 192.168.0.6.2048 > proxy.2048: UDP, length 140
11:56:26.389433 IP proxy.2048 > 192.168.0.6.2048: UDP, length 144
11:56:36.394120 IP proxy.2048 > 192.168.0.6.2048: UDP, length 144
11:56:46.394736 IP proxy.2048 > 192.168.0.6.2048: UDP, length 144
11:56:56.395398 IP proxy.2048 > 192.168.0.6.2048: UDP, length 144

---
11:56:56.396275 IP 192.168.0.6.2048 > proxy.2048: UDP, length 92
11:57:06.396089 IP proxy.2048 > 192.168.0.6.2048: UDP, length 144
11:57:06.397220 IP 192.168.0.6.2048 > proxy.2048: UDP, length 140
11:57:16.396732 IP proxy.2048 > 192.168.0.6.2048: UDP, length 144
11:57:16.397634 IP 192.168.0.6.2048 > proxy.2048: UDP, length 140
11:57:21.401092 IP proxy.2048 > 192.168.0.6.2048: UDP, length 336
11:57:26.397421 IP proxy.2048 > 192.168.0.6.2048: UDP, length 144
11:57:26.398209 IP 192.168.0.6.2048 > proxy.2048: UDP, length 140
11:57:36.398088 IP proxy.2048 > 192.168.0.6.2048: UDP, length 144
11:57:36.398946 IP 192.168.0.6.2048 > proxy.2048: UDP, length 140
11:57:46.398731 IP proxy.2048 > 192.168.0.6.2048: UDP, length 144
11:57:46.399609 IP 192.168.0.6.2048 > proxy.2048: UDP, length 140
11:57:56.399402 IP proxy.2048 > 192.168.0.6.2048: UDP, length 144
11:57:56.400293 IP 192.168.0.6.2048 > proxy.2048: UDP, length 140
11:58:06.400059 IP proxy.2048 > 192.168.0.6.2048: UDP, length 144
11:58:06.400903 IP 192.168.0.6.2048 > proxy.2048: UDP, length 140
Jul 19 11:56:56.382: %WCCP-1-SERVICELOST: Service web-cache lost on WCCP
client 10.1.250.10
Jul 19 11:57:06.386: %WCCP-5-SERVICEFOUND: Service web-cache acquired on
WCCP client 10.1.250.10
Some more wccp events debugging shows some other stuff as well
Jul 19 12:57:06.809: %WCCP-1-SERVICELOST: Service web-cache lost on WCCP
client 10.1.250.10
Jul 19 12:57:16.813: %WCCP-5-SERVICEFOUND: Service web-cache acquired on
WCCP client 10.1.250.10
Jul 19 12:57:16.813: WCCP-EVNT:S00: Built new router view: 1 routers, 1
usable WCCP clients, change # 000028DC
Jul 19 12:57:31.814: WCCP-EVNT:S00: Built new router view: 1 routers, 1
usable WCCP clients, change # 000028DC
Jul 19 12:58:46.831: WCCP-EVNT:S00: Here_I_Am packet from 192.168.0.1
w/bad rcv_id 00033D1A
Jul 19 12:58:56.832: WCCP-EVNT:S00: Here_I_Am packet from 192.168.0.1
w/bad rcv_id 00033D1A
Jul 19 12:59:06.832: WCCP-EVNT:S00: Built new router view: 0 routers, 1
usable WCCP clients, change # 000028DD
Jul 19 12:59:06.832: WCCP-EVNT:S00: Router 172.31.255.6 removed.
Jul 19 12:59:06.832: WCCP-EVNT:S00: Built new router view: 0 routers, 0
usable WCCP clients, change # 000028DE
Jul 19 12:59:06.832: %WCCP-1-SERVICELOST: Service web-cache lost on WCCP
client 10.1.250.10
Jul 19 12:59:16.832: %WCCP-5-SERVICEFOUND: Service web-cache acquired on
WCCP client 10.1.250.10
I don't know where the 192.168.0.1 comes from. That's a Cisco switch
doing nothing with WCCP. 172.16.255.6 is the OSPF ID of the router.
wccp packet debugging shows:
ul 19 13:04:36.875: WCCP-PKT:S00: Sending I_See_You packet to
10.1.250.10 w/ rcv_id 00033D42
Jul 19 13:04:46.876: WCCP-PKT:S00: Received valid Here_I_Am packet from
10.1.250.10 w/rcv_id 00033D42
Jul 19 13:04:46.876: WCCP-PKT:S00: Sending I_See_You packet to
10.1.250.10 w/ rcv_id 00033D43
Jul 19 13:04:56.876: WCCP-PKT:S00: Received valid Here_I_Am packet from
10.1.250.10 w/rcv_id 00033D43
Jul 19 13:04:56.876: WCCP-PKT:S00: Sending I_See_You packet to
10.1.250.10 w/ rcv_id 00033D44
Jul 19 13:05:06.876: WCCP-PKT:S00: Received valid Here_I_Am packet from
10.1.250.10 w/rcv_id 00033D44
Jul 19 13:05:06.876: WCCP-PKT:S00: Sending I_See_You packet to
10.1.250.10 w/ rcv_id 00033D45
Jul 19 13:05:16.880: WCCP-PKT:S00: Received valid Here_I_Am packet from
192.168.0.1 w/rcv_id 00033D45
Jul 19 13:05:16.880: WCCP-PKT:S00: Sending I_See_You packet to
192.168.0.1 w/ rcv_id 00033D46
Jul 19 13:05:26.881: WCCP-PKT:S00: Sending I_See_You packet to
192.168.0.1 w/ rcv_id 00033D47
Jul 19 13:05:36.885: WCCP-PKT:S00: Sending I_See_You packet to
192.168.0.1 w/ rcv_id 00033D48
Jul 19 13:05:41.881: WCCP-PKT:S00: Sending Removal_Query packet to
192.168.0.1w/ rcv_id 00033D49
Jul 19 13:05:46.881: %WCCP-1-SERVICELOST: Service web-cache lost on WCCP
client 10.1.250.10
Jul 19 13:05:46.885: WCCP-PKT:S00: Sending I_See_You packet to
10.1.250.10 w/ rcv_id 00033D4A
Jul 19 13:05:56.893: %WCCP-5-SERVICEFOUND: Service web-cache acquired on
WCCP client 10.1.250.10
Jul 19 13:05:56.893: WCCP-PKT:S00: Received valid Here_I_Am packet from
10.1.250.10 w/rcv_id 00033D4A
Jul 19 13:05:56.893: WCCP-PKT:S00: Sending I_See_You packet to
10.1.250.10 w/ rcv_id 00033D4B
Jul 19 13:06:06.893: WCCP-PKT:S00: Received valid Here_I_Am packet from
10.1.250.10 w/rcv_id 00033D4B
Now,this is weird the cisco just suddenly starts sending wccp packets to
192.168.0.1???
Arnaud.
Amarantis Onderwijsgroep is de concernorganisatie van ISA-scholen en ROC ASA