From owner-freebsd-apache@FreeBSD.ORG Wed May 25 07:25:54 2011 Return-Path: Delivered-To: freebsd-apache@freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:4f8:fff6::34]) by hub.freebsd.org (Postfix) with ESMTP id D2BDB1065674 for ; Wed, 25 May 2011 07:25:54 +0000 (UTC) (envelope-from jdc@koitsu.dyndns.org) Received: from qmta03.emeryville.ca.mail.comcast.net (qmta03.emeryville.ca.mail.comcast.net [76.96.30.32]) by mx1.freebsd.org (Postfix) with ESMTP id BADB18FC1A for ; Wed, 25 May 2011 07:25:54 +0000 (UTC) Received: from omta12.emeryville.ca.mail.comcast.net ([76.96.30.44]) by qmta03.emeryville.ca.mail.comcast.net with comcast id njRB1g0020x6nqcA3jRtb3; Wed, 25 May 2011 07:25:53 +0000 Received: from koitsu.dyndns.org ([67.180.84.87]) by omta12.emeryville.ca.mail.comcast.net with comcast id njRs1g0031t3BNj8YjRszT; Wed, 25 May 2011 07:25:53 +0000 Received: by icarus.home.lan (Postfix, from userid 1000) id EDA5F102C19; Wed, 25 May 2011 00:25:52 -0700 (PDT) Date: Wed, 25 May 2011 00:25:52 -0700 From: Jeremy Chadwick To: Doug Barton Message-ID: <20110525072552.GA31990@icarus.home.lan> References: <4DDC9B15.2090703@FreeBSD.org> MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: <4DDC9B15.2090703@FreeBSD.org> User-Agent: Mutt/1.5.21 (2010-09-15) Cc: freebsd-apache@FreeBSD.org, alfred@freebsd.org Subject: Re: Interesting apache 2.2 + accept filter problem X-BeenThere: freebsd-apache@freebsd.org X-Mailman-Version: 2.1.5 Precedence: list List-Id: Support of apache-related ports List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Wed, 25 May 2011 07:25:54 -0000 On Tue, May 24, 2011 at 11:00:53PM -0700, Doug Barton wrote: > I have an odd one here, and I'm hoping to get some insight. I'm > using apache 2.2 (latest ports version) along with the accf_http > kernel module (which is loaded). If I start it the "normal" way, > everything works just fine. However if I start it with -D FOREGROUND > then I get the following error in httpd-error.log: > > (22)Invalid argument: Failed to enable the 'httpready' Accept Filter > > So I reduced everything down to a test case, and I can easily > reproduce it with nothing but a clean ports install (minus SSL, > which doesn't make a difference in the outcome, but simplified the > ktrace). > > I've run 'ktrace httpd' and 'ktrace httpd -D FOREGROUND' numerous > times, and there is one very clear difference. The first, which > works, looks like this: > > 48226 initial thread CALL > setsockopt(0x3,SOL_SOCKET,SO_REUSEADDR,0x7fffffffe80c,0x4) > 48226 initial thread RET setsockopt 0 > 48226 initial thread CALL > setsockopt(0x3,SOL_SOCKET,SO_KEEPALIVE,0x7fffffffe80c,0x4) > 48226 initial thread RET setsockopt 0 > 48226 initial thread CALL setsockopt(0x3,0x6,0x1,0x7fffffffe7ec,0x4) > 48226 initial thread RET setsockopt 0 > 48226 initial thread CALL > setsockopt(0x3,SOL_SOCKET,SO_ACCEPTFILTER,0x7fffffffe6e0,0x100) > 48226 initial thread RET setsockopt 0 > > The weird thing is that the second one, which produces the error, is > exactly the same, except that there is one extra call at the end, > which is the one that fails: > > 48208 initial thread CALL > setsockopt(0x3,SOL_SOCKET,SO_REUSEADDR,0x7fffffffe7ec,0x4) > 48208 initial thread RET setsockopt 0 > 48208 initial thread CALL > setsockopt(0x3,SOL_SOCKET,SO_KEEPALIVE,0x7fffffffe7ec,0x4) > 48208 initial thread RET setsockopt 0 > 48208 initial thread CALL setsockopt(0x3,0x6,0x1,0x7fffffffe7cc,0x4) > 48208 initial thread RET setsockopt 0 > 48208 initial thread CALL > setsockopt(0x3,SOL_SOCKET,SO_ACCEPTFILTER,0x7fffffffe6c0,0x100) > 48208 initial thread RET setsockopt 0 > 48208 initial thread CALL > setsockopt(0x3,SOL_SOCKET,SO_ACCEPTFILTER,0x7fffffffe6c0,0x100) > 48208 initial thread RET setsockopt -1 errno 22 Invalid argument > > I cannot figure out what it is about running in the foreground that > is causing that last call, and I've run out of things to test or > try, so I'm asking for help. Any ideas? > > BTW, not sure it matters but the the reason that I want to add -D > FOREGROUND is for use with daemontools. However I've managed to > isolate the error to just 'httpd -D FOREGROUND' on the command line > without anything else involved. For what it's worth, I've seen this exact error for many years now (since 2.0 at least, possibly earlier). I always assumed it had something to do with the apache22 rc.d script auto-loading http_accf, followed by Apache itself trying to load the same module thus throwing the error. I imagine on SIGUSR1 it also tries to re-load the module and thusly fails. We use the following in rc.conf: apache22_enable="yes" apache22_http_accept_enable="yesA Proof of my statement, re: log rotation and SIGUSR1 showing the same problem, and also re: we don't use -D FOREGROUND: $ grep httpready /var/log/httpd-error* /var/log/httpd-error.log.0:[Wed May 25 00:00:01 2011] [warn] (22)Invalid argument: Failed to enable the 'httpready' Accept Filter /var/log/httpd-error.log.1:[Tue May 24 00:00:01 2011] [warn] (22)Invalid argument: Failed to enable the 'httpready' Accept Filter /var/log/httpd-error.log.10:[Sun May 15 00:00:01 2011] [warn] (22)Invalid argument: Failed to enable the 'httpready' Accept Filter /var/log/httpd-error.log.11:[Sat May 14 00:00:01 2011] [warn] (22)Invalid argument: Failed to enable the 'httpready' Accept Filter /var/log/httpd-error.log.12:[Fri May 13 00:00:01 2011] [warn] (22)Invalid argument: Failed to enable the 'httpready' Accept Filter /var/log/httpd-error.log.13:[Thu May 12 00:00:01 2011] [warn] (22)Invalid argument: Failed to enable the 'httpready' Accept Filter /var/log/httpd-error.log.2:[Mon May 23 00:00:01 2011] [warn] (22)Invalid argument: Failed to enable the 'httpready' Accept Filter /var/log/httpd-error.log.3:[Sun May 22 00:00:01 2011] [warn] (22)Invalid argument: Failed to enable the 'httpready' Accept Filter /var/log/httpd-error.log.4:[Sat May 21 00:00:01 2011] [warn] (22)Invalid argument: Failed to enable the 'httpready' Accept Filter /var/log/httpd-error.log.5:[Fri May 20 00:00:01 2011] [warn] (22)Invalid argument: Failed to enable the 'httpready' Accept Filter /var/log/httpd-error.log.6:[Thu May 19 00:00:01 2011] [warn] (22)Invalid argument: Failed to enable the 'httpready' Accept Filter /var/log/httpd-error.log.7:[Wed May 18 00:00:01 2011] [warn] (22)Invalid argument: Failed to enable the 'httpready' Accept Filter /var/log/httpd-error.log.8:[Tue May 17 00:00:01 2011] [warn] (22)Invalid argument: Failed to enable the 'httpready' Accept Filter /var/log/httpd-error.log.9:[Mon May 16 00:00:01 2011] [warn] (22)Invalid argument: Failed to enable the 'httpready' Accept Filter It doesn't seem to harm anything from what I can tell. The setsockopt(2) man page might shed some light on what's going on, but I'd really have to look at the Apache source + kernel source again to see if I could figure out what was going on. errno 22 is EINVAL, thus: [EINVAL] Installing an accept_filter(9) on a non-listening socket was attempted. Alfred was involved in making this module, so I'm CC'ing him here. I doubt we'd be able to reach David Filo at this point in time. ;-) -- | Jeremy Chadwick jdc@parodius.com | | Parodius Networking http://www.parodius.com/ | | UNIX Systems Administrator Mountain View, CA, USA | | Making life hard for others since 1977. PGP 4BD6C0CB |