You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@httpd.apache.org by "William A. Rowe, Jr." <wr...@rowe-clan.net> on 2007/01/06 00:38:41 UTC
Piped logger nightmares
http://svn.apache.org/viewvc?view=rev&sortby=date&revision=104019
is a complete disaster to Win32 as-a-service. It works fine from the
command line, but the lack of stdout/stderr channels causes cmd.exe
"in a service" appear to cause the CreateProcess of cmd.exe to implode.
As I look at it, the choice to add another indirection between httpd
and the pipe process adds some horrible resource issues to the server,
especially with many, many separate rotated log files. Also, this
extra layer adds more opportunities for kill signals to be mishandled,
possibly leading to some of our orphaned log processes?
The reason given; "some examples use the shell..." wasn't enough to
make this the default behavior against all installations, IMHO.
I'd suggest an alternate syntax; use |$ where a shell command is really
actually demanded. So...
ErrorLog "|bin/rotatelogs someargs"
would go back to invoking rotatelogs, not sh->rotatelogs.
ErrorLog "|$somescriptcommand"
would behave as Jeff desired.
Comments?
Re: mod_log_access [was: Piped logger nightmares]
Posted by "William A. Rowe, Jr." <wr...@rowe-clan.net>.
George Cox wrote:
>
> I'm going to wade in here, and hopefully add something of value. If I
> don't, please flame as hard as you can etc. I've written a module which
> automatically rotates access logs. It's called mod_log_access, and the
> latest version is available at:
>
> http://www.gjvc.com/software/apache/modules/
>
> It only does access logs, not error logs, for reasons people on this list
> will well understand, but if you have any preferences on how it should be
> done, please let me know. I would really like to see this (or something
> like it) added to httpd-trunk/ and would be happy to maintain it.
>
> Please reply off-list -- I don't mean to hijack the discussion.
No hijaak - it's worth answering your plea on-list for others to have the
answers too. The suggestion has come up many times ;-)
The reason for the no-rotate policy was always a combination of issues,
firstly security (need for root to open incremental log files after it's
no longer running as root, or getting replacement pipes to the children
if the parent still root was to open those logs.) This was better handled
by a detached root process, so rotatelogs was born.
The other half of the equation was the general overhead and number of fd's
required. The authors since way-back-when decided it's best not to pollute
the running apache httpd process with heavy lifting duties for the log files.
As an add-in module, I don't necessarily agree with any of the later half
of these objections. A module which solved the first issue, optionally
loaded, would interest me for a future 2.4 or 3.0 release.
Bill
Re: Piped logger nightmares
Posted by George Cox <gj...@gjvc.com>.
* William A. Rowe, Jr. <wr...@rowe-clan.net> [20070105 23:37] wrote:
> http://svn.apache.org/viewvc?view=rev&sortby=date&revision=104019
>
> is a complete disaster to Win32 as-a-service. It works fine from the
> command line, but the lack of stdout/stderr channels causes cmd.exe "in a
> service" appear to cause the CreateProcess of cmd.exe to implode.
>
> As I look at it, the choice to add another indirection between httpd and
> the pipe process adds some horrible resource issues to the server,
> especially with many, many separate rotated log files. Also, this extra
I'm going to wade in here, and hopefully add something of value. If I
don't, please flame as hard as you can etc. I've written a module which
automatically rotates access logs. It's called mod_log_access, and the
latest version is available at:
http://www.gjvc.com/software/apache/modules/
It only does access logs, not error logs, for reasons people on this list
will well understand, but if you have any preferences on how it should be
done, please let me know. I would really like to see this (or something
like it) added to httpd-trunk/ and would be happy to maintain it.
Please reply off-list -- I don't mean to hijack the discussion.
best;
gjvc
Re: Piped logger nightmares
Posted by Ruediger Pluem <rp...@apache.org>.
On 01/09/2007 06:56 PM, Sander Temme wrote:
>
> On Jan 9, 2007, at 9:41 AM, William A. Rowe, Jr. wrote:
>
>> So by changing from the pipe to the shell, we blew up in the service
>> process on some boxes (XP at least). Sander reports it does not die
>> as a service on Windows 2003, but apparently EOS to the cmd.exe process
>> isn't a reliable deathknell.
>
>
> It doesn't die, but on my Production 2k3 server, it's littering about
> 16 rotatelogs.exe and eight cmd.exe in the last hour. The littered
> processes are unconnected to each other and the shells point to a
> nonexistent httpd.exe... which doesn't seem to be crashing (no evidence
> of that in the error log or Application event log, and
> MaxRequestsPerChild is 0).
>
> I'm keeping an eye on it and periodically cleaning out the litter.
>
> This is Steffen's (ApacheLounge) build of 2.2.3, built July 27 2006.
> Yesterday I played with our own (ASF) binary on my home box.
Sorry, might be unrelated noise to this, but have you checked if the patch
to PR40651 which has been backported to 2.2.4 solves this issue?
Regards
Rüdiger
Re: Piped logger nightmares
Posted by Sander Temme <sc...@apache.org>.
On Jan 9, 2007, at 9:41 AM, William A. Rowe, Jr. wrote:
> So by changing from the pipe to the shell, we blew up in the service
> process on some boxes (XP at least). Sander reports it does not die
> as a service on Windows 2003, but apparently EOS to the cmd.exe
> process
> isn't a reliable deathknell.
It doesn't die, but on my Production 2k3 server, it's littering about
16 rotatelogs.exe and eight cmd.exe in the last hour. The littered
processes are unconnected to each other and the shells point to a
nonexistent httpd.exe... which doesn't seem to be crashing (no
evidence of that in the error log or Application event log, and
MaxRequestsPerChild is 0).
I'm keeping an eye on it and periodically cleaning out the litter.
This is Steffen's (ApacheLounge) build of 2.2.3, built July 27 2006.
Yesterday I played with our own (ASF) binary on my home box.
S.
--
sctemme@apache.org http://www.temme.net/sander/
PGP FP: 51B4 8727 466A 0BC3 69F4 B7B8 B2BE BC40 1529 24AF
Re: Piped logger nightmares
Posted by "William A. Rowe, Jr." <wr...@rowe-clan.net>.
Jeff Trawick wrote:
>
> Does anybody know how to tell which flags spawnl() passes to
> CreateProcess[W] when 1.3 starts its piped loggers (something like
> truss/strace I guess)?
Sander and I dug deeper on this, core_spawn in alloc.c we handle the pipes.
We reset the pipes according to the stdin/out/err handles created.
But we don't seem to override if there is no in/out/err handle around.
This means that cmd.exe is not expecting INVALID_FILE_HANDLE, but either
a NULL handle, or a handle to device null. In any case, rotatelogs.exe
and other log handlers had no issue with INVALID_FILE_HANDLE, however,
the cmd.exe shell has a huge issue with it.
So by changing from the pipe to the shell, we blew up in the service
process on some boxes (XP at least). Sander reports it does not die
as a service on Windows 2003, but apparently EOS to the cmd.exe process
isn't a reliable deathknell.
Still working at it.
Re: Piped logger nightmares
Posted by Jeff Trawick <tr...@gmail.com>.
On 1/8/07, Sander Temme <sc...@apache.org> wrote:
> On Jan 8, 2007, at 5:06 PM, Sander Temme wrote:
>
> >> Can you confirm that 1.3 was busted on Windows too?
> >
> > Starting 1.3.37 from the shell (not as a Service):
>
> I'm starting to engage myself in quite the conversation.
>
> Started 2.2.3 from the command line. It does the same thing as the
> service: two cmd.exe + rotatelogs.exe from the parent, two from the
> child. However, it also opens two empty cmd.exe *windows*.
>
> Killing he server by ^C in the cmd.exe that started it gives me two
> orphaned rotatelogs.exe processes, left behind by the child.
This 1.3 code
#elif defined(WIN32)
shellcmd = getenv("COMSPEC");
if (!shellcmd)
shellcmd = SHELL_PATH;
child_pid = spawnl(_P_NOWAIT, shellcmd, shellcmd, "/c", (char *)cmd, NULL);
return(child_pid);
#elif defined(OS2)
has been replaced with a lot of other code.
Does anybody know how to tell which flags spawnl() passes to
CreateProcess[W] when 1.3 starts its piped loggers (something like
truss/strace I guess)?
Re: Piped logger nightmares
Posted by Sander Temme <sc...@apache.org>.
On Jan 8, 2007, at 5:06 PM, Sander Temme wrote:
>> Can you confirm that 1.3 was busted on Windows too?
>
> Starting 1.3.37 from the shell (not as a Service):
I'm starting to engage myself in quite the conversation.
Started 2.2.3 from the command line. It does the same thing as the
service: two cmd.exe + rotatelogs.exe from the parent, two from the
child. However, it also opens two empty cmd.exe *windows*.
Killing he server by ^C in the cmd.exe that started it gives me two
orphaned rotatelogs.exe processes, left behind by the child.
S. (last one for today, I promise)
--
sctemme@apache.org http://www.temme.net/sander/
PGP FP: 51B4 8727 466A 0BC3 69F4 B7B8 B2BE BC40 1529 24AF
Re: Piped logger nightmares
Posted by Sander Temme <sc...@apache.org>.
On Jan 6, 2007, at 6:55 AM, Jeff Trawick wrote:
> Can you confirm that 1.3 was busted on Windows too?
Starting 1.3.37 from the shell (not as a Service):
Parent opens two cmd.exe + rotatelogs.exe with error.log argument,
and one such combination with access.log argument. Child opens one
combination for each log file.
Again, no trouble on the five minute log roll.
Stopping the server by ^C on the command prompt makes everything go
away.
Once again starting as a Service (I didn't have Process Explorer last
time I tried) gives me no problems: two cmd.exe + rotatelogs.exe
started from the child, no surprises when cycling the service.
S.
--
sctemme@apache.org http://www.temme.net/sander/
PGP FP: 51B4 8727 466A 0BC3 69F4 B7B8 B2BE BC40 1529 24AF
Re: Piped logger nightmares
Posted by Sander Temme <sc...@apache.org>.
On Jan 6, 2007, at 6:55 AM, Jeff Trawick wrote:
> Can you confirm that 1.3 was busted on Windows too?
I just loaded up a 1.3.37 binary from archives.apache.org on a fresh
new Win2k3 Server VMWare thingy. I set my error log and access log as
follows:
ErrorLog "| c:/PROGRA~1/APACHE~1/Apache/bin/rotatelogs.exe c:/
PROGRA~1/APACHE~1/Apache/logs/error.log 300 -480"
LogLevel debug
CustomLog "| c:/PROGRA~1/APACHE~1/Apache/bin/rotatelogs.exe c:/
PROGRA~1/APACHE~1/Apache/logs/access.log 300 -480" common
...and I'm seeing two rotatelogs.exe processes. Logfiles are created
and turned over (I'm tickling the server with a slow trickle from
http_load).
Seems non-busted.
S.
--
sctemme@apache.org http://www.temme.net/sander/
PGP FP: 51B4 8727 466A 0BC3 69F4 B7B8 B2BE BC40 1529 24AF
Re: Piped logger nightmares
Posted by Jeff Trawick <tr...@gmail.com>.
On 1/5/07, William A. Rowe, Jr. <wr...@rowe-clan.net> wrote:
> http://svn.apache.org/viewvc?view=rev&sortby=date&revision=104019
Sanity check... 1.3 used /bin/sh in-between httpd and the piped logger.
4513 execve("/bin/sh", ["/bin/sh", "-c",
"/scratch/inst/13/bin/rotatelogs "...], [/* 36 vars */] <unfinished
...>
Why haven't these problems been seen there? Is the problem really
triggered by some minor detail in the 2.x implementation which differs
from 1.3, and not simply by letting the shell assist with the startup?
> The reason given; "some examples use the shell..." wasn't enough to
> make this the default behavior against all installations, IMHO.
That plus the fact that 1.3 had the same behavior (at least at the
high level; maybe some smaller detail is wrong) with nobody
complaining...
Perhaps in pre APR days the 1.3 implementation on Windows differed
more greatly from Unix (e.g., shell wasn't even used on Windows)? Or
perhaps it was busted on Windows there too but nobody cared?
> I'd suggest an alternate syntax; use |$ where a shell command is really
> actually demanded. So...
That works for me, though it is an unexpected migration.
Possible mitigation of the migration issue:
* the '$' should be required in 2.0/2.2 on platform(s) where we know
the shell causes actual problems, and starting with 2.4 it should be
required everywhere
* shell used automatically with 2.0/2.2 if it is obvious that the
shell is needed (no path to the piped logger program, or shell
redirection used)
-/-
Can you confirm that 1.3 was busted on Windows too?
Re: Piped logger nightmares
Posted by Sander Temme <sc...@apache.org>.
On Jan 5, 2007, at 3:38 PM, William A. Rowe, Jr. wrote:
> is a complete disaster to Win32 as-a-service. It works fine from the
> command line, but the lack of stdout/stderr channels causes cmd.exe
> "in a service" appear to cause the CreateProcess of cmd.exe to
> implode.
I am now playing around with Process Explorer and the httpd 2.2.3
binary from our own download, and here's what I'm seeing:
Process PID
httpd.exe 3464 <-- httpd.pid
cmd.exe 3376
rotatelogs.exe 3776
cmd.exe 4040
rotatelogs.exe 2696
httpd.exe 1388
cmd.exe 1584
rotatelogs.exe 3028
cmd.exe 3724
rotatelogs.exe 2548
Note: two rotatelogs is started from the parent, two from the child.
Turning over the log files does not give me orphaned processes, but
every time I restart the service I get four newly unloved
rotatelogs.exe in the list.
Looks like these add up to something too: my production server
stopped logging altogether after the 6th, and once I slapped Process
Explorer onto it I saw it try to timidly spawn a cmd.exe once in a
while, which then went away again real quick. Only when I manually
mucked out the pages and pages of orphans could I successfully
restart the service and make it start logging again.
S.
--
sctemme@apache.org http://www.temme.net/sander/
PGP FP: 51B4 8727 466A 0BC3 69F4 B7B8 B2BE BC40 1529 24AF