> -----Original Message-----
> From: Jeff Trawick [mailto:[EMAIL PROTECTED]
> Sent: Tuesday, March 16, 2004 5:30 PM
> To: [EMAIL PROTECTED]
> Subject: Re: [PATCH] 1.3.29 MPE port update, piped logs, and strdup
> 
> 
> Bixby, Mark (TCSD-MISL-Cupertino) wrote:

...snip...

> > 2) The piped logs process was never terminating on MPE because the
>  > pipe wasn't being closed after the maintenance restart SIGTERM
>  >signal was sent.  My patch closes the pipe here (note -- I did
>  >not make this MPE-specific since another SIGTERM case does
>  >close the pipe for all platforms).  See below or in the attachment.
> 
> can you describe the scenario?  surely there are some close() 
> calls that will 
> now fail (or close the wrong thing) on non-MPE?

After instrumenting (fprintf(stderr,...)) the piped log functions in http_log.c and 
the "other child" functions in http_main.c, here is what I see in an error_log from 
unmodified 1.3.29 configured with access_log piped via rotatelogs:

Server startup.  A pipe for the log process is created, and a log process is spawned:

MPE ap_open_piped_log entry
MPE ap_open_piped_log pipe fds[0]=11, fds[1]=12
MPE piped_log_magic pid=-1, fds[0]=11, fds[1]=12
MPE piped_log_spawn entry
MPE piped_log_spawn pid=78839893
MPE ap_register_other_child entry pid=78839893, write_fd=12
MPE ap_register_other_child exit
MPE piped_log_spawn exit
MPE ap_open_piped_log exit

The log process is immediately cleaned up and unregistered.  Note that 
pipe_log_cleanup() is invoked to close the pipe:

MPE piped_log_cleanup entry pid=78839893
MPE piped_log_cleanup SIGTERM
MPE ap_unregister_other_child entry
MPE piped_log_maintenance entry pid=78839893
MPE piped_log_maintenance entry OC_REASON_UNREGISTER
MPE piped_log_maintenance exit
MPE ap_unregister_other_child exit
MPE piped_log_cleanup close fds[0]=11, fds[1]=12
MPE piped_log_cleanup exit

The real log process is created, just like we did before:

MPE ap_open_piped_log entry
MPE ap_open_piped_log pipe fds[0]=12, fds[1]=13
MPE piped_log_magic pid=-1, fds[0]=12, fds[1]=13
MPE piped_log_spawn entry
MPE piped_log_spawn pid=74317928
MPE ap_register_other_child entry pid=74317928, write_fd=13
MPE ap_register_other_child exit
MPE piped_log_spawn exit
MPE ap_open_piped_log exit

The pipe child closes the original pipe fds (after the read fd has been dup()ed to 
stdin) in preparation for exec()-ing the shell:

MPE piped_log_cleanup_for_exec entry pid=-1
MPE piped_log_cleanup_for_exec close fds[0]=12, fds[1]=13
MPE piped_log_cleanup_for_exec exit
[Wed Mar 17 16:47:17 2004] [notice] Apache/1.3.29 (HP MPE/iX WebWise A.04.00) co
nfigured -- resuming normal operations
[Wed Mar 17 16:47:17 2004] [notice] Accept mutex: fcntl (Default: fcntl)
MPE reap_other_child entry pid=78839893
MPE reap_other_child exit

The first log process is finally reaped.  The server has now finished starting up and 
is waiting for requests.

I then web-browse around to generate a bunch of requests and I see that my piped 
access_log is being created properly according to the rotatelogs parameters.

But now I shut down the server with kill `cat httpd.pid`:

MPE reclaim_child_processes other pid=74317928
MPE piped_log_maintenance entry pid=74317928
MPE piped_log_maintenance entry OC_REASON_RESTART
MPE pipe_log_maintenance SIGTERM
MPE piped_log_maintenance exit

We try to reclaim the log process by sending a SIGTERM.  Unfortunately on MPE signals 
won't be delivered promptly under certain pending I/O conditions, apparently including 
reading from an open pipe.  So the reclamation codes tries again and again and again, 
but the log process doesn't terminate.

MPE reclaim_child_processes other pid=74317928
MPE piped_log_maintenance entry pid=74317928
MPE piped_log_maintenance entry OC_REASON_RESTART
MPE pipe_log_maintenance SIGTERM
MPE piped_log_maintenance exit
...etc...
MPE reclaim_child_processes other pid=74317928
MPE piped_log_maintenance entry pid=74317928
MPE piped_log_maintenance entry OC_REASON_RESTART
MPE pipe_log_maintenance SIGTERM
MPE piped_log_maintenance exit

Eventually the server will give up and just exit instead of continuing to wait for the 
log process to terminate.  At this point all of the regular server children have 
terminated, and the only child processes left are the log process shell and then 
rotatelogs as a child of that shell.

If I had attempted a server restart (kill -HUP) instead of a shutdown, the results are 
the same.  All regular child processes terminated, the server waiting for the log 
process to terminate, and obviously no HTTP requests being processed.

Now curiously piped logs worked just fine on 1.3.22 which was the previous release I 
ported to MPE.  I've diffed http_log.c between the two versions, and there aren't any 
major differences.

Since pipe_log_cleanup() has the sole parental responsibility for closing this pipe 
and it is not being called in the shutdown/restart case, then perhaps the root cause 
lies somewhere in the generic pool cleanup code?  I.e. the fix may really just be to 
make sure that pipe_log_clean() gets invoked rather than adding the new additional 
close() statements in my patch.

There's nothing MPE-specific in the current 1.3.29 piped logging code, so these pipes 
are not being closed on other platforms as well, resulting in a minor fd leak.

> > 3) MPE lacks ftruncate() as expected by rotatelogs, 
> 
> no comment here; I'd rather avoid thinking about the 
> copyright issue ;)

The author of the longpointer.h code (not me) is very flexible about what 
copyright/licensing/etc verbiage is at the top of that file.  Let me know how you want 
to see it worded and I should be able to make it happen.

- Mark B.

Reply via email to