Re: [squid-users] RE: (99) Cannot Assign Requested Address errors

> Here is some usefull information from cache.log:
>
> 2008/09/09 15:10:55| IPInterception.cc(171) NetfilterTransparent: NF
> getsockopt(IP_TRANSPARENT) failed: (92) Protocol not available
> 2008/09/09 15:11:56| commBind: Cannot bind socket FD 35 to
> 10.12.6.198:1974: (98) Address already in use
> 2008/09/09 15:11:56| comm.cc(1002) commResetFD: bind: (98) Address
> already in use
> 2008/09/09 15:11:57| IPInterception.cc(137) NetfilterInterception: NF
> getsockopt(SO_ORIGINAL_DST) failed: (11) Resource temporarily
> unavailable
> 2008/09/09 15:11:57| IPInterception.cc(171) NetfilterTransparent: NF
> getsockopt(IP_TRANSPARENT) failed: (92) Protocol not available
> 2008/09/09 15:12:58| IPInterception.cc(137) NetfilterInterception: NF
> getsockopt(SO_ORIGINAL_DST) failed: (11) Resource temporarily
> unavailable
> 2008/09/09 15:12:58| IPInterception.cc(171) NetfilterTransparent: NF
> getsockopt(IP_TRANSPARENT) failed: (92) Protocol not available
> 2008/09/09 15:13:23| commBind: Cannot bind socket FD 66 to
> 10.12.6.198:2015: (98) Address already in use
> 2008/09/09 15:13:23| comm.cc(1002) commResetFD: bind: (98) Address
> already in use
> 2008/09/09 15:13:26| commBind: Cannot bind socket FD 51 to
> 10.12.6.198:2018: (98) Address already in use
> 2008/09/09 15:13:26| comm.cc(1002) commResetFD: bind: (98) Address
> already in use
> 2008/09/09 15:13:30| commBind: Cannot bind socket FD 86 to
> 10.12.6.198:2018: (98) Address already in use
> 2008/09/09 15:13:30| comm.cc(1002) commResetFD: bind: (98) Address
> already in use
> 2008/09/09 15:13:30| commBind: Cannot bind socket FD 86 to
> 10.12.6.198:2018: (98) Address already in use
> 2008/09/09 15:13:30| comm.cc(1002) commResetFD: bind: (98) Address
> already in use
> 2008/09/09 15:13:31| commBind: Cannot bind socket FD 86 to
> 10.12.6.198:2018: (98) Address already in use
> 2008/09/09 15:13:31| comm.cc(1002) commResetFD: bind: (98) Address
> already in use
> 2008/09/09 15:13:59| IPInterception.cc(137) NetfilterInterception: NF
> getsockopt(SO_ORIGINAL_DST) failed: (11) Resource temporarily
> unavailable
> 2008/09/09 15:13:59| IPInterception.cc(171) NetfilterTransparent: NF
> getsockopt(IP_TRANSPARENT) failed: (92) Protocol not available
> 2008/09/09 15:14:14| commBind: Cannot bind socket FD 94 to
> 10.12.6.198:2035: (98) Address already in use
> 2008/09/09 15:14:14| comm.cc(1002) commResetFD: bind: (98) Address
> already in use
> 2008/09/09 15:15:00| IPInterception.cc(137) NetfilterInterception: NF
> getsockopt(SO_ORIGINAL_DST) failed: (0) Success
> 2008/09/09 15:15:00| IPInterception.cc(171) NetfilterTransparent: NF
> getsockopt(IP_TRANSPARENT) failed: (92) Protocol not available
> 2008/09/09 15:16:02| IPInterception.cc(137) NetfilterInterception: NF
> getsockopt(SO_ORIGINAL_DST) failed: (11) Resource temporarily
> unavailable
>
>
>
> -----Original Message-----
> From: Ritter, Nicholas
> Sent: Tuesday, September 09, 2008 3:03 PM
> To: squid-users_at_squid-cache.org
> Subject: (99) Cannot Assign Requested Address errors
>
> I have deployed a field test of a squid 3HEAD box running TPROXY in a
> WCCP configuration. Under more client load (that could not be simulated
> in my lab) I am noticing that users are getting "(99) Cannot assign
> requested address" errors from the squid box. The odd thing is that some
> web sites cause the error to happen almost all the time when the user
> gets to a certain point through the website. Additonally the same sites
> work fine in Safari on MacOS 10, but not in IE6 on WindowsXP SP2 (and
> SP3). An observation from one enduser noted that if they hit the refresh
> button in the browser enough, the error goes away.
>
> Some sites that are giving problems are:
>
> www.surveymonkey.com
> shl-isp.com
> bestkits.com
> metraonline.com
>
>
> I am using the following software versions:
>
> CentOS 5.2 (x86_64)
> squid/3.HEAD-20080721, with tproxy-onresetfd.patch from Amos Jeffries
> (back on 7/26/08) iptables-1.4.0, with
> tproxy-iptables-20080204-1915.patch
> kernel 2.6.25-11, with tproxy-kernel-2.6.25-20080519-165031-1211208631
>
>
> I am still getting the following entries in my cache.log, but not super
> often since setting] "echo 1 > /proc/sys/net/ipv4/ip_nonlocal_bind" in
> /proc.
>
> 008/09/09 14:55:22| IPInterception.cc(137) NetfilterInterception: NF
> getsockopt(SO_ORIGINAL_DST) failed: (11) Resource temporarily
> unavailable
> 2008/09/09 14:55:22| IPInterception.cc(171) NetfilterTransparent: NF
> getsockopt(IP_TRANSPARENT) failed: (92) Protocol not available
>
> My squid.conf uses this for the http_port setting:
>
> http_port 3128 tproxy intercept disable-pmtu-discovery=always
>
>
> My question is, what can I do to troubleshoot this, or give members of
> this list more information to help isolate the problem? Does anyone have
> suggestions? I can post any information as requestion regarding the
> specific configuration, etc.
>

FWIW, Current HEAD finally has the onresetfd patch applied since 2008-09-03.

I suspect the clutter you are seeing is because of mixing tproxy +
intercept on the same port. The tproxy kernel handling should fail on
intercept requests, and vice versa due to the underlying systems.

If there is any code that should be shared but is not yet, then thats a
bug still in Squid I need to be made aware of and fix.

I suspect we are getting close to the point where only a packet trace will
help troubleshoot further.

Okay, here is a patch to make the debug messages slightly clearer:

=== modified file 'src/IPInterception.cc'
--- src/IPInterception.cc 2008-07-11 20:24:53 +0000
+++ src/IPInterception.cc 2008-09-10 01:29:07 +0000
@@ -168,7 +168,7 @@
      * Try lookup for TPROXY targets. BUT, only if the FD is flagged for
transparent operations. */
     if(getsockopt(fd, SOL_IP, IP_TRANSPARENT, lookup->ai_addr,
&lookup->ai_addrlen) != 0) {
         if(!silent) {
- debugs(89, DBG_IMPORTANT, HERE << " NF
getsockopt(IP_TRANSPARENT) failed: " << xstrerror());
+ debugs(89, DBG_IMPORTANT, HERE << " NF
getsockopt(IP_TRANSPARENT) on FD " << fd << " failed: " << xstrerror());
             last_reported = squid_curtime;
         }
     }
@@ -200,7 +200,7 @@
      * Try lookup for IPFW interception. */
     if( getsockname(fd, lookup->ai_addr, &lookup->ai_addrlen) >= 0 ) {
         if( !silent ) {
- debugs(89, DBG_IMPORTANT, HERE << " IPFW getsockname(...)
failed: " << xstrerror());
+ debugs(89, DBG_IMPORTANT, HERE << " IPFW getsockname(...) on
FD " << fd << " failed: " << xstrerror());
             last_reported = squid_curtime;
         }
     }

There is one bit of code I'm not certain of. It feels right but can't be
backed up logically. Lets see if that makes a difference.

=== modified file 'src/comm.cc'
--- src/comm.cc 2008-09-03 10:39:15 +0000
+++ src/comm.cc 2008-09-10 01:32:35 +0000
@@ -1389,7 +1389,7 @@

     if(fd_table[fd].flags.transparent == 1) {
         /* AYJ: do we actually need to set this again on every accept? */
- //comm_set_transparent(sock);
+ comm_set_transparent(sock);
         F->flags.transparent = 1;
     }

Following that, but in a different test run this may silence a few more of
the unwanted messages:

=== modified file 'src/IPInterception.cc'
--- src/IPInterception.cc 2008-07-11 20:24:53 +0000
+++ src/IPInterception.cc 2008-09-10 01:29:07 +0000
@@ -347,11 +347,11 @@
     if( !me.IsIPv4() ) return -1;
     if( !peer.IsIPv4() ) return -1;

- if(intercept_active) {
+ if(intercept_active && !fd_table[fd].flags.transparent ) {
         if( NetfilterInterception(fd, me, dst, silent) == 0) return 0;
         if( IPFWInterception(fd, me, dst, silent) == 0) return 0;
     }
- if(transparent_active) {
+ if(transparent_active && fd_table[fd].flags.transparent) {
         if( NetfilterTransparent(fd, me, dst, silent) == 0) return 0;
     }

If the above clears the issue up, I'm going to have to work on a better
integrated fix for that.

Amos
Received on Wed Sep 10 2008 - 01:37:54 MDT