|
On Thu, 1 Dec 2005, Graeme Fowler wrote:
On Thu 01 Dec 2005 12:48:28 GMT , John Line <jml4@xxxxxxxxxxxxxx> wrote:
We're not using NAT, but the current SLES9 kernel is 2.6.5-7.201, which
could be enough to include old bugs for which SuSE's not back-ported fixes.
Hrm...
Here's a random idea: if you don't have the lvs debug sysctl in /proc
(/proc/sys/net/ipv4/vs/debug_level) then recompile your kernel - not too
familiar with SLES I'm afraid, so no pointers there :) - and ensure that
IP_VS_DEBUG=y.
Reboot the director with the debug kernel, turn on debugging (start with
'echo "3" >> /proc/sys/net/ipv4/vs/debug_level' and work up or down according
to how much detail you want) and follow the logs.
For what it's worth, here is some sample logging output (using ip_vs*
modules rebuilt from the kernel source for the running kernel, kernel and
other modules as supplied by SuSE) with debug level 12 to get the maximum
detail, for both the web cache (131.111.8.1:8080, works fine) and WPAD
(131.111.8.68:80, almost exclusively ip_rt_bug failures). Two variants are
shown for WPAD, the more common short version and the less frequent longer
one where it shows some signs of considering how the request ought to be
routed. Note that the configuration specifies persistent=600 for cache
requests, which explains some of the differences - but a test some time
ago when I made WPAD persistent made no difference to the problem, already
tried that.
[Client addresses replaced by <clientaddr> here on general privacy grounds.]
With debug level 12, for cache request:
IPVS: lookup/in TCP <clientaddr>:1133->131.111.8.1:8080 not hit
IPVS: lookup service: fwm 0 TCP 131.111.8.1:8080 hit
IPVS: p-schedule: src <clientaddr>:1133 dest 131.111.8.1:8080 mnet <clientaddr>
[p-schedule for persistent connection routing via existing
template if seen before]
IPVS: lookup/in TCP <clientaddr>:0->131.111.8.1:8080 not hit
IPVS: ip_vs_wlc_schedule(): Scheduling...
IPVS: WLC: server 131.111.8.104:8080 activeconns 4 refcnt 10 weight 1 overhead
1025
IPVS: Bind-dest TCP c:<clientaddr>:0 v:131.111.8.1:8080 d:131.111.8.104:8080
fwd:R s:0 flg:183 cnt:1 destcnt:11
IPVS: Bind-dest TCP c:<clientaddr>:1133 v:131.111.8.1:8080 d:131.111.8.104:8080
fwd:R s:0 flg:183 cnt:1 destcnt:12
IPVS: ADDing control for: cp.dst=<clientaddr>:1133 ctl_cp.dst=<clientaddr>:0
IPVS: Incoming packet: TCP <clientaddr>:1133->131.111.8.1:8080
IPVS: TCP input [S...] 131.111.8.104:8080-><clientaddr>:1133 state:
NONE->SYN_RECV cnt:2
Enter: ip_vs_dr_xmit, net/ipv4/ipvs/ip_vs_xmit.c line 451
Leave: ip_vs_dr_xmit, net/ipv4/ipvs/ip_vs_xmit.c line 487
With debug level 12, for WPAD request:
IPVS: lookup/in TCP <clientaddr>:2486->131.111.8.68:80 hit
IPVS: Incoming packet: TCP <clientaddr>:2486->131.111.8.68:80
Enter: ip_vs_dr_xmit, net/ipv4/ipvs/ip_vs_xmit.c line 451
ip_rt_bug: <clientaddr> -> 131.111.8.68, eth1
Leave: ip_vs_dr_xmit, net/ipv4/ipvs/ip_vs_xmit.c line 487
With debug level 12, for WPAD request and showing signs of thinking about
request routing:
IPVS: lookup/in TCP <clientaddr>:41432->131.111.8.68:80 not hit
IPVS: lookup service: fwm 0 TCP 131.111.8.68:80 hit
IPVS: ip_vs_wlc_schedule(): Scheduling...
IPVS: WLC: server 131.111.8.96:80 activeconns 0 refcnt 28 weight 1 overhead 27
IPVS: Bind-dest TCP c:<clientaddr>:41332 v:131.111.8.68:80 d:131.111.8.96:80
fwd:R s:0 flg:183 cnt:1 destcnt:29
IPVS: Schedule fwd:R c:<clientaddr>:41332 v:131.111.8.68:80 d:131.111.8.96:80
flg:1C3 cnt:2
IPVS: Incoming packet: TCP <clientaddr>:41332->131.111.8.68:80
IPVS: TCP input [S...] 131.111.8.96:80-><clientaddr>:41332 state:
NONE->SYN_RECV cnt:2
Enter: ip_vs_dr_xmit, net/ipv4/ipvs/ip_vs_xmit.c line 451
IPVS: new dst 131.111.8.96, refcnt=3, rtos=0
ip_rt_bug: <clientaddr> -> 131.111.8.68, eth1
Leave: ip_vs_dr_xmit, net/ipv4/ipvs/ip_vs_xmit.c line 487
Other observations:
(a) The "short" WPAD log entries are often *not* preceded by "long"
entries for the same client, which seems odd and maybe wrong (since it
suggests they are being passed back to the main IP routing code
when they've never been assigned to a real-server).
(b) After stopping heartbeat/ldirectord (and manually unloading the ip_vs*
modules to avoid continued logging of details about packets that IPVS was
seeing but leaving for normal routing), I was puzzled by the quantity of
IPVS: Unbind-dest TCP c:<clientaddr>:4942 v:131.111.8.68:80 d:131.111.8.96:80
fwd:R s:3 flg:183 cnt:1 destcnt:11
messages being logged. My first thought was that some might be remnants from
earlier tests (since I didn't know whether the state data structures would
survive between tests), but trying another brief test after rebooting the
system showed the same apparent mismatch:
6 ip_rt_bug messages for WPAD
1 Bind-dest message for WPAD
15 Unbind-dest messages for WPAD
Maybe that's expected, but it left me puzzled since it implies state data
exists without having been set up (or at least, without the details being
logged when it was set up).
As ever, any ideas (about the cause of the problem or where to look for
clues) would be welcome.
John
--
John Line - web & news development, University of Cambridge Computing Service
|
