Bug 49798 - [mod_log_config] Piped Log scripts process cause warn
Summary: [mod_log_config] Piped Log scripts process cause warn
Status: REOPENED
Alias: None
Product: Apache httpd-2
Classification: Unclassified
Component: mod_log_config (show other bugs)
Version: 2.2.16
Hardware: PC Linux
: P2 normal (vote)
Target Milestone: ---
Assignee: Apache HTTPD Bugs Mailing List
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2010-08-22 09:11 UTC by Laurent Declercq
Modified: 2010-08-23 01:39 UTC (History)
0 users



Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Laurent Declercq 2010-08-22 09:11:00 UTC
Hello ;

When I do an 'apache2ctl gracefull', I get following warning in my apache error.log:

[Sun Aug 22 14:46:00 2010] [warn] long lost child came home! (pid 10436)

After some avestigations, I found that it's the'mod_log_config' module that cause this issue when we use Piped Log. To show, the problem:


'ps aux' result before do the gracefull:

root      8511  0.1  0.4   6824  4256 ?        Ss   14:18   0:03 /usr/sbin/apache2 -k start
root     10502  0.0  0.0   1748   500 ?        S    14:46   0:00 /bin/sh -c /var/www/ispcp/engine/ispcp-apache-logger
www-data 10503  0.0  0.2   6192  2324 ?        S    14:46   0:00 /usr/sbin/apache2 -k start
root     10504  0.0  0.2   4532  2984 ?        S    14:46   0:00 /usr/bin/perl /var/www/ispcp/engine/ispcp-apache-logger
www-data 10505  0.0  0.2   6824  2188 ?        S    14:46   0:00 /usr/sbin/apache2 -k start
www-data 10506  0.0  0.2 228236  2856 ?        Sl   14:46   0:00 /usr/sbin/apache2 -k start
www-data 10507  0.0  0.2 228236  2860 ?        Sl   14:46   0:00 /usr/sbin/apache2 -k start

Here, you can see my main Piped Log script process (pid 10502) and the second (pid 10504) that is the background process from (pid 10436).

When I do the graceful, I get the following:

[Sun Aug 22 14:52:50 2010] [notice] SIGUSR1 received.  Doing graceful restart
[Sun Aug 22 14:52:51 2010] [notice] Stopping ispCP Apache logger (pid 10504)
[Sun Aug 22 14:52:51 2010] [notice] Apache/2.2.16 (Debian) mod_fcgid/2.3.5 configured -- resuming normal operations
[Sun Aug 22 14:52:51 2010] [warn] long lost child came home! (pid 10502)
[Sun Aug 22 14:52:51 2010] [notice] Starting ispCP Apache logger (pid 10579)

Note: Log lines for the logger come from my logging script (Added to show the problem).

After the gracefull, my 'px aux' result is like this:

root      8511  0.1  0.4   6824  4256 ?        Ss   14:18   0:03 /usr/sbin/apache2 -k start
root     10577  0.0  0.0   1748   500 ?        S    14:52   0:00 /bin/sh -c /var/www/ispcp/engine/ispcp-apache-logger
www-data 10578  0.0  0.2   6192  2324 ?        S    14:52   0:00 /usr/sbin/apache2 -k start
root     10579  0.0  0.2   4532  2984 ?        S    14:52   0:00 /usr/bin/perl /var/www/ispcp/engine/ispcp-apache-logger
www-data 10580  0.0  0.2   6824  2188 ?        S    14:52   0:00 /usr/sbin/apache2 -k start
www-data 10581  0.0  0.2 228236  2856 ?        Sl   14:52   0:00 /usr/sbin/apache2 -k start
www-data 10582  0.0  0.2 228236  2860 ?        Sl   14:52   0:00 /usr/sbin/apache2 -k start

Ok, it's just a warn but I think that should be solved.  I've tried with alternative syntax (Shell not involved at all) and the same problem occurs on the main process.

My system:

root@ispcp:/etc/apache2/sites-available# uname -a
Linux ispcp 2.6.32-5-686 #1 SMP Sat Jul 24 02:27:10 UTC 2010 i686 GNU/Linux

The involved SHELL:
root@ispcp:/etc/apache2/sites-available# ls -la /bin/sh
lrwxrwxrwx 1 root root 4 21 août  07:11 /bin/sh -> dash

The Apache information:
root@ispcp:/etc/apache2/sites-available# apache2ctl -V
Server version: Apache/2.2.16 (Debian)
Server built:   Jul 24 2010 20:24:16
Server's Module Magic Number: 20051115:24
Server loaded:  APR 1.4.2, APR-Util 1.3.9
Compiled using: APR 1.4.2, APR-Util 1.3.9
Architecture:   32-bit
Server MPM:     Worker
  threaded:     yes (fixed thread count)
    forked:     yes (variable process count)
Server compiled with....
 -D APACHE_MPM_DIR="server/mpm/worker"
 -D APR_HAS_SENDFILE
 -D APR_HAS_MMAP
 -D APR_HAVE_IPV6 (IPv4-mapped addresses enabled)
 -D APR_USE_SYSVSEM_SERIALIZE
 -D APR_USE_PTHREAD_SERIALIZE
 -D SINGLE_LISTEN_UNSERIALIZED_ACCEPT
 -D APR_HAS_OTHER_CHILD
 -D AP_HAVE_RELIABLE_PIPED_LOGS
 -D DYNAMIC_MODULE_LIMIT=128
 -D HTTPD_ROOT="/etc/apache2"
 -D SUEXEC_BIN="/usr/lib/apache2/suexec"
 -D DEFAULT_PIDLOG="/var/run/apache2.pid"
 -D DEFAULT_SCOREBOARD="logs/apache_runtime_status"
 -D DEFAULT_ERRORLOG="logs/error_log"
 -D AP_TYPES_CONFIG_FILE="mime.types"
 -D SERVER_CONFIG_FILE="apache2.conf"


Thank a lot if you can solve this problem.

Note: Sorry for my poor English, I'm french.

Note2: not 2.2.16 version is selectable here , why ?
Comment 1 Laurent Declercq 2010-08-22 09:16:32 UTC
I want say graceful, not gracefull (sorry).
Comment 2 Laurent Declercq 2010-08-22 09:34:44 UTC
Forgot the first description and read this:

When I do an 'apache2ctl graceful', I get following warning in my apache
error.log:

[Sun Aug 22 14:46:00 2010] [warn] long lost child came home! (pid 10436)

After some avestigations, I found that it's the'mod_log_config' module that
cause this issue when we use Piped Log. To show, the problem:


'ps aux' result before do the gracefull:

root      8511  0.1  0.4   6824  4256 ?        Ss   14:18   0:03
/usr/sbin/apache2 -k start
root     10502  0.0  0.0   1748   500 ?        S    14:46   0:00 /bin/sh -c
/var/www/ispcp/engine/ispcp-apache-logger
www-data 10503  0.0  0.2   6192  2324 ?        S    14:46   0:00
/usr/sbin/apache2 -k start
root     10504  0.0  0.2   4532  2984 ?        S    14:46   0:00 /usr/bin/perl
/var/www/ispcp/engine/ispcp-apache-logger
www-data 10505  0.0  0.2   6824  2188 ?        S    14:46   0:00
/usr/sbin/apache2 -k start
www-data 10506  0.0  0.2 228236  2856 ?        Sl   14:46   0:00
/usr/sbin/apache2 -k start
www-data 10507  0.0  0.2 228236  2860 ?        Sl   14:46   0:00
/usr/sbin/apache2 -k start

Here, you can see my main Piped Log script process (pid 10502) and the second
(pid 10504) that is the background process from the first (/bin/sh -c ; pid 10502).

When I do the graceful, I get the following:

[Sun Aug 22 14:52:50 2010] [notice] SIGUSR1 received.  Doing graceful restart
[Sun Aug 22 14:52:51 2010] [notice] Stopping ispCP Apache logger (pid 10504)
[Sun Aug 22 14:52:51 2010] [notice] Apache/2.2.16 (Debian) mod_fcgid/2.3.5
configured -- resuming normal operations
[Sun Aug 22 14:52:51 2010] [warn] long lost child came home! (pid 10502)
[Sun Aug 22 14:52:51 2010] [notice] Starting ispCP Apache logger (pid 10579)

Note: Log lines for the logger come from my logging script (Added to show the
problem).

After the gracefull, my 'px aux' result is like this:

root      8511  0.1  0.4   6824  4256 ?        Ss   14:18   0:03
/usr/sbin/apache2 -k start
root     10577  0.0  0.0   1748   500 ?        S    14:52   0:00 /bin/sh -c
/var/www/ispcp/engine/ispcp-apache-logger
www-data 10578  0.0  0.2   6192  2324 ?        S    14:52   0:00
/usr/sbin/apache2 -k start
root     10579  0.0  0.2   4532  2984 ?        S    14:52   0:00 /usr/bin/perl
/var/www/ispcp/engine/ispcp-apache-logger
www-data 10580  0.0  0.2   6824  2188 ?        S    14:52   0:00
/usr/sbin/apache2 -k start
www-data 10581  0.0  0.2 228236  2856 ?        Sl   14:52   0:00
/usr/sbin/apache2 -k start
www-data 10582  0.0  0.2 228236  2860 ?        Sl   14:52   0:00
/usr/sbin/apache2 -k start

Ok, it's just a warn but I think that should be solved.  I've tried with
alternative syntax (Shell not involved at all) and the same problem occurs on
the main process.

My system:

root@ispcp:/etc/apache2/sites-available# uname -a
Linux ispcp 2.6.32-5-686 #1 SMP Sat Jul 24 02:27:10 UTC 2010 i686 GNU/Linux

The involved SHELL:
root@ispcp:/etc/apache2/sites-available# ls -la /bin/sh
lrwxrwxrwx 1 root root 4 21 août  07:11 /bin/sh -> dash

The Apache information:
root@ispcp:/etc/apache2/sites-available# apache2ctl -V
Server version: Apache/2.2.16 (Debian)
Server built:   Jul 24 2010 20:24:16
Server's Module Magic Number: 20051115:24
Server loaded:  APR 1.4.2, APR-Util 1.3.9
Compiled using: APR 1.4.2, APR-Util 1.3.9
Architecture:   32-bit
Server MPM:     Worker
  threaded:     yes (fixed thread count)
    forked:     yes (variable process count)
Server compiled with....
 -D APACHE_MPM_DIR="server/mpm/worker"
 -D APR_HAS_SENDFILE
 -D APR_HAS_MMAP
 -D APR_HAVE_IPV6 (IPv4-mapped addresses enabled)
 -D APR_USE_SYSVSEM_SERIALIZE
 -D APR_USE_PTHREAD_SERIALIZE
 -D SINGLE_LISTEN_UNSERIALIZED_ACCEPT
 -D APR_HAS_OTHER_CHILD
 -D AP_HAVE_RELIABLE_PIPED_LOGS
 -D DYNAMIC_MODULE_LIMIT=128
 -D HTTPD_ROOT="/etc/apache2"
 -D SUEXEC_BIN="/usr/lib/apache2/suexec"
 -D DEFAULT_PIDLOG="/var/run/apache2.pid"
 -D DEFAULT_SCOREBOARD="logs/apache_runtime_status"
 -D DEFAULT_ERRORLOG="logs/error_log"
 -D AP_TYPES_CONFIG_FILE="mime.types"
 -D SERVER_CONFIG_FILE="apache2.conf"


Thank a lot if you can solve this problem.

Note: Sorry for my poor English, I'm french.

Note2: not 2.2.16 version is selectable here , why ?
Comment 3 Rainer Jung 2010-08-22 11:19:46 UTC
Use "||process args" to launch the external logger process without invoking the shell/command interpreter. See the other issue 49768.

*** This bug has been marked as a duplicate of bug 49768 ***
Comment 4 Laurent Declercq 2010-08-22 12:36:49 UTC
Sorry but it's not the same issue. I've already tried to execute without involving the SHELL. I'll try again and show you the logs result...
Comment 5 Laurent Declercq 2010-08-22 12:46:26 UTC
Apache configuration:

CustomLog "|| /var/www/ispcp/engine/ispcp-apache-logger" ispcplog

As you can see, the Shell is not involved here.

ps aux result before do the graceful:

root     15016  0.0  0.2   4532  2984 ?        S    18:39   0:00 /usr/bin/perl /var/www/ispcp/engine/ispcp-apache-logger
www-data 15017  0.0  0.2   6192  2300 ?        S    18:39   0:00 /usr/sbin/apache2 -k start
www-data 15018  0.0  0.2   6824  2164 ?        S    18:39   0:00 /usr/sbin/apache2 -k start
www-data 15019  0.0  0.2 228236  2840 ?        Sl   18:39   0:00 /usr/sbin/apache2 -k start
www-data 15020  0.0  0.2 228236  2844 ?        Sl   18:39   0:00 /usr/sbin/apache2 -k start


ps aux resulter after the graceful:

root     15089  8.0  0.2   4532  2988 ?        S    18:42   0:00 /usr/bin/perl /var/www/ispcp/engine/ispcp-apache-logger
www-data 15090  1.0  0.2   6192  2304 ?        S    18:42   0:00 /usr/sbin/apache2 -k start
www-data 15091  0.0  0.2   6824  2132 ?        S    18:42   0:00 /usr/sbin/apache2 -k start
www-data 15092  2.0  0.2 228236  2844 ?        Sl   18:42   0:00 /usr/sbin/apache2 -k start
www-data 15093  1.0  0.2 228236  2844 ?        Sl   18:42   0:00 /usr/sbin/apache2 -k start

Now, the corresponding error logs:


[Sun Aug 22 18:42:21 2010] [notice] SIGUSR1 received.  Doing graceful restart
[Sun Aug 22 18:42:23 2010] [notice] Apache/2.2.16 (Debian) mod_fcgid/2.3.5 configured -- resuming normal operations
[Sun Aug 22 18:42:23 2010] [warn] long lost child came home! (pid 15016)
[Sun Aug 22 18:42:23 2010] [notice] Starting ispCP Apache logger (pid 15089)


As you can see, the process 15016 (my logger script) that is launch by apache cause the error with graceful.

I hope you understand my sentence now.
Comment 6 Laurent Declercq 2010-08-22 12:50:10 UTC
Updated to 2.2.16
Comment 7 Laurent Declercq 2010-08-23 01:39:30 UTC
Confirmed here: http://publib.boulder.ibm.com/httpserv/ihsdiag/errorlog.html#lostchildhome

I'm not a crasy man...