Regular Apache Error

vaibhavs · 06-17-2009, 12:30 AM

Hi,

I have setup a script to email me apache error logs everyday.

Apart from "File does not exist" errors, I see logs of following nature practically every day.

Code:

[Tue Jun 16 02:35:05 2009] [notice] SIGHUP received.  Attempting to restart
[Tue Jun 16 02:36:00 2009] [notice] Apache/2.2.11 (Unix) mod_ssl/2.2.11 OpenSSL/0.9.8e-fips-rhel5 mod_bwlimited/1.4 PHP/5.2.9 configured -- resuming normal operations
[Tue Jun 16 03:35:09 2009] [notice] SIGHUP received.  Attempting to restart
[Tue Jun 16 03:35:56 2009] [notice] Apache/2.2.11 (Unix) mod_ssl/2.2.11 OpenSSL/0.9.8e-fips-rhel5 mod_bwlimited/1.4 PHP/5.2.9 configured -- resuming normal operations
[Tue Jun 16 03:40:03 2009] [notice] SIGHUP received.  Attempting to restart
[Tue Jun 16 03:40:05 2009] [notice] Apache/2.2.11 (Unix) mod_ssl/2.2.11 OpenSSL/0.9.8e-fips-rhel5 mod_bwlimited/1.4 PHP/5.2.9 configured -- resuming normal operations
[Tue Jun 16 04:05:05 2009] [warn] child process 30019 still did not exit, sending a SIGTERM
[Tue Jun 16 04:05:07 2009] [warn] child process 30025 still did not exit, sending a SIGTERM
[Tue Jun 16 04:05:07 2009] [warn] child process 30031 still did not exit, sending a SIGTERM
[Tue Jun 16 04:05:07 2009] [warn] child process 30034 still did not exit, sending a SIGTERM
[Tue Jun 16 04:05:07 2009] [warn] child process 30036 still did not exit, sending a SIGTERM
[Tue Jun 16 04:05:07 2009] [warn] child process 32083 still did not exit, sending a SIGTERM
[Tue Jun 16 04:05:07 2009] [warn] child process 1705 still did not exit, sending a SIGTERM
[Tue Jun 16 04:05:08 2009] [notice] SIGHUP received.  Attempting to restart
[Tue Jun 16 04:05:58 2009] [notice] Apache/2.2.11 (Unix) mod_ssl/2.2.11 OpenSSL/0.9.8e-fips-rhel5 mod_bwlimited/1.4 PHP/5.2.9 configured -- resuming normal operations
[Tue Jun 16 04:11:14 2009] [error] [client 59.182.2.133] File does not exist: /home/ramshyam/public_html/kb, referer: http://www.ramshyam.com/newcc/
[Tue Jun 16 04:15:48 2009] [error] [client 216.129.119.41] script '/home/ramshyam/public_html/links/blog.php' not found or unable to stat
[Tue Jun 16 04:55:20 2009] [warn] child process 22063 still did not exit, sending a SIGTERM
[Tue Jun 16 04:55:26 2009] [notice] SIGHUP received.  Attempting to restart
[Tue Jun 16 04:57:00 2009] [notice] Apache/2.2.11 (Unix) mod_ssl/2.2.11 OpenSSL/0.9.8e-fips-rhel5 mod_bwlimited/1.4 PHP/5.2.9 configured -- resuming normal operations
[Tue Jun 16 05:00:05 2009] [notice] SIGHUP received.  Attempting to restart
[Tue Jun 16 05:00:09 2009] [notice] Apache/2.2.11 (Unix) mod_ssl/2.2.11 OpenSSL/0.9.8e-fips-rhel5 mod_bwlimited/1.4 PHP/5.2.9 configured -- resuming normal operations
[Tue Jun 16 05:05:06 2009] [notice] SIGHUP received.  Attempting to restart
[Tue Jun 16 05:05:08 2009] [notice] Apache/2.2.11 (Unix) mod_ssl/2.2.11 OpenSSL/0.9.8e-fips-rhel5 mod_bwlimited/1.4 PHP/5.2.9 configured -- resuming normal operations
[Tue Jun 16 05:20:06 2009] [warn] child process 20256 still did not exit, sending a SIGTERM
[Tue Jun 16 05:20:07 2009] [warn] child process 20262 still did not exit, sending a SIGTERM
[Tue Jun 16 05:20:07 2009] [warn] child process 20265 still did not exit, sending a SIGTERM
[Tue Jun 16 05:20:07 2009] [warn] child process 20267 still did not exit, sending a SIGTERM
[Tue Jun 16 05:20:07 2009] [warn] child process 20326 still did not exit, sending a SIGTERM
[Tue Jun 16 05:20:09 2009] [notice] SIGHUP received.  Attempting to restart
[Tue Jun 16 05:20:20 2009] [notice] Apache/2.2.11 (Unix) mod_ssl/2.2.11 OpenSSL/0.9.8e-fips-rhel5 mod_bwlimited/1.4 PHP/5.2.9 configured -- resuming normal operations

I have tried googling around, but not much help.

Why are these logs generated, should I be worried ?

Pls advice.

Thx
Vai

anomie · 06-18-2009, 12:59 PM

A quick google turned up some similar problems for mod_python users. Are you using mod_python perchance?

The bottom line is httpd processes aren't dying as quickly as Apache thinks they should be. From your logs, it looks like you're gracefully restarting. And the child processes just aren't dying... (Do you have a high traffic server?)

vaibhavs · 06-18-2009, 01:24 PM

Traffic on the server is very very low.
Just about 100 odd hits in the whole day.

How to check if "using mod_python" is being used ?
I do not have any of my own python scripts.

Thx

anomie · 06-18-2009, 02:39 PM

If you don't know, then you're almost certainly not using it.

You would have explicitly installed it.

On Apache web server 2.2:
# httpd -M

mod_python would show up in that list.

vaibhavs · 06-19-2009, 12:35 AM

This is a Hosted VPS server which are generally pre-configured with the basic requirements.

Tried httpd -M
Did not find mod_python in the list.

Got this error again in today's email of error_logs

Quote:

[Thu Jun 18 03:30:08 2009] [warn] child process 9334 still did not exit, sending a SIGTERM
[Thu Jun 18 03:30:08 2009] [warn] child process 1385 still did not exit, sending a SIGTERM
[Thu Jun 18 03:30:08 2009] [warn] child process 32391 still did not exit, sending a SIGTERM
[Thu Jun 18 03:30:08 2009] [warn] child process 9344 still did not exit, sending a SIGTERM
[Thu Jun 18 03:30:08 2009] [warn] child process 11265 still did not exit, sending a SIGTERM
[Thu Jun 18 03:30:08 2009] [warn] child process 9357 still did not exit, sending a SIGTERM
[Thu Jun 18 03:30:08 2009] [warn] child process 9359 still did not exit, sending a SIGTERM
[Thu Jun 18 03:30:08 2009] [warn] child process 9360 still did not exit, sending a SIGTERM
[Thu Jun 18 03:30:08 2009] [warn] child process 9361 still did not exit, sending a SIGTERM
[Thu Jun 18 03:30:08 2009] [warn] child process 9371 still did not exit, sending a SIGTERM
[Thu Jun 18 03:30:09 2009] [notice] SIGHUP received. Attempting to restart
[Thu Jun 18 03:31:12 2009] [notice] Apache/2.2.11 (Unix) mod_ssl/2.2.11 OpenSSL/0.9.8e-fips-rhel5 mod_bwlimited/1.4 PHP/5.2.9 configured -- resuming normal operations
[Thu Jun 18 03:35:09 2009] [notice] SIGHUP received. Attempting to restart
[Thu Jun 18 03:35:10 2009] [notice] Apache/2.2.11 (Unix) mod_ssl/2.2.11 OpenSSL/0.9.8e-fips-rhel5 mod_bwlimited/1.4 PHP/5.2.9 configured -- resuming normal operations
[Thu Jun 18 03:40:03 2009] [notice] SIGHUP received. Attempting to restart
[Thu Jun 18 03:40:12 2009] [notice] Apache/2.2.11 (Unix) mod_ssl/2.2.11 OpenSSL/0.9.8e-fips-rhel5 mod_bwlimited/1.4 PHP/5.2.9 configured -- resuming normal operations
[Thu Jun 18 04:05:07 2009] [warn] child process 26132 still did not exit, sending a SIGTERM
[Thu Jun 18 04:05:07 2009] [warn] child process 26141 still did not exit, sending a SIGTERM
[Thu Jun 18 04:05:07 2009] [warn] child process 26169 still did not exit, sending a SIGTERM
[Thu Jun 18 04:05:07 2009] [warn] child process 26179 still did not exit, sending a SIGTERM
[Thu Jun 18 04:05:07 2009] [warn] child process 26185 still did not exit, sending a SIGTERM
[Thu Jun 18 04:05:07 2009] [warn] child process 3241 still did not exit, sending a SIGTERM
[Thu Jun 18 04:05:07 2009] [warn] child process 17970 still did not exit, sending a SIGTERM
[Thu Jun 18 04:05:09 2009] [warn] child process 26132 still did not exit, sending a SIGTERM
[Thu Jun 18 04:05:09 2009] [warn] child process 26141 still did not exit, sending a SIGTERM
[Thu Jun 18 04:05:09 2009] [warn] child process 26169 still did not exit, sending a SIGTERM
[Thu Jun 18 04:05:09 2009] [warn] child process 26179 still did not exit, sending a SIGTERM
[Thu Jun 18 04:05:09 2009] [warn] child process 26185 still did not exit, sending a SIGTERM
[Thu Jun 18 04:05:09 2009] [warn] child process 3241 still did not exit, sending a SIGTERM
[Thu Jun 18 04:05:09 2009] [warn] child process 17970 still did not exit, sending a SIGTERM
[Thu Jun 18 04:05:11 2009] [notice] SIGHUP received. Attempting to restart
[Thu Jun 18 04:05:37 2009] [notice] Apache/2.2.11 (Unix) mod_ssl/2.2.11 OpenSSL/0.9.8e-fips-rhel5 mod_bwlimited/1.4 PHP/5.2.9 configured -- resuming normal operations

What else should I check.
Need to get this error corrected.

Pls help!

Thx
Vai

chrism01 · 06-19-2009, 01:57 AM

Look into the Apache access_log and error_log to see what those processes are doing.

vaibhavs · 06-19-2009, 03:45 AM

Error logs is as pasted above.

Checked access log, but could not find anything suspicious.

Below is the access log about the same time as the error log

Quote:

127.0.0.1 - - [18/Jun/2009:03:20:01 -0400] "GET /whm-server-status HTTP/1.0" 200 8854
127.0.0.1 - - [18/Jun/2009:03:22:49 -0400] "GET / HTTP/1.0" 200 3474
127.0.0.1 - - [18/Jun/2009:03:25:05 -0400] "GET /whm-server-status HTTP/1.0" 200 8858
127.0.0.1 - - [18/Jun/2009:03:28:18 -0400] "GET / HTTP/1.0" 200 3474
127.0.0.1 - - [18/Jun/2009:03:30:02 -0400] "GET /whm-server-status HTTP/1.0" 200 8890
127.0.0.1 - - [18/Jun/2009:03:32:56 -0400] "GET / HTTP/1.0" 200 3474
127.0.0.1 - - [18/Jun/2009:03:35:01 -0400] "GET /whm-server-status HTTP/1.0" 200 3476
127.0.0.1 - - [18/Jun/2009:03:37:55 -0400] "GET / HTTP/1.0" 200 3474

anomie · 06-19-2009, 09:52 AM

One approach that might yield results: set the LogLevel debug directive in your Apache config. Then restart httpd and keep an eye on the error_log. (You may be able to get more detailed info about what is going wrong.)

vaibhavs · 06-19-2009, 10:06 AM

Thx @anomie

I have set LogLevel debug.

I will keep an eye on the error log file and update with more details soon.

Thx
Vai

vaibhavs · 06-19-2009, 10:08 AM

HI,

I accessed our website's default home page to ensure everything is smooth and the logs showed up the following

tail -f /etc/httpd/conf/logs/error_log

Quote:

[Fri Jun 19 11:06:23 2009] [debug] proxy_util.c(1801): proxy: grabbed scoreboard slot 0 in child 31870 for worker proxy:reverse
[Fri Jun 19 11:06:23 2009] [debug] proxy_util.c(1820): proxy: worker proxy:reverse already initialized
[Fri Jun 19 11:06:23 2009] [debug] proxy_util.c(1914): proxy: initialized single connection worker 0 in child 31870 for (*)
[Fri Jun 19 11:06:25 2009] [debug] proxy_util.c(1801): proxy: grabbed scoreboard slot 0 in child 32210 for worker proxy:reverse
[Fri Jun 19 11:06:25 2009] [debug] proxy_util.c(1820): proxy: worker proxy:reverse already initialized
[Fri Jun 19 11:06:25 2009] [debug] proxy_util.c(1914): proxy: initialized single connection worker 0 in child 32210 for (*)

All ok ?

Thx
Vai

anomie · 06-19-2009, 10:35 AM

@vaibhavs: Actually, you appear to be running into issues when you try to perform a graceful restart. So keep the debug logging in place, and issue:

# apachectl -k graceful

Then you will need to wait for Apache to get tired of waiting and kill its children processes forcefully. (That takes 25 minutes or so based on the looks of your logs.) Keep an eye out for any potentially useful messages that are appearing around the time the children processes are killed with SIGTERM.

vaibhavs · 06-19-2009, 10:38 AM

Ok. I will try this.

Meanwhile I am seeing a lot of these:

Quote:

[Fri Jun 19 11:32:12 2009] [debug] proxy_util.c(1801): proxy: grabbed scoreboard slot 0 in child 23964 for worker proxy:reverse
[Fri Jun 19 11:32:12 2009] [debug] proxy_util.c(1820): proxy: worker proxy:reverse already initialized
[Fri Jun 19 11:32:12 2009] [debug] proxy_util.c(1914): proxy: initialized single connection worker 0 in child 23964 for (*)
[Fri Jun 19 11:32:13 2009] [debug] proxy_util.c(1801): proxy: grabbed scoreboard slot 0 in child 23975 for worker proxy:reverse
[Fri Jun 19 11:32:13 2009] [debug] proxy_util.c(1820): proxy: worker proxy:reverse already initialized
[Fri Jun 19 11:32:13 2009] [debug] proxy_util.c(1914): proxy: initialized single connection worker 0 in child 23975 for (*)
[Fri Jun 19 11:32:13 2009] [debug] proxy_util.c(1801): proxy: grabbed scoreboard slot 0 in child 23976 for worker proxy:reverse
[Fri Jun 19 11:32:13 2009] [debug] proxy_util.c(1820): proxy: worker proxy:reverse already initialized
[Fri Jun 19 11:32:13 2009] [debug] proxy_util.c(1914): proxy: initialized single connection worker 0 in child 23976 for (*)
[Fri Jun 19 11:32:14 2009] [debug] proxy_util.c(1801): proxy: grabbed scoreboard slot 0 in child 23999 for worker proxy:reverse
[Fri Jun 19 11:32:14 2009] [debug] proxy_util.c(1820): proxy: worker proxy:reverse already initialized
[Fri Jun 19 11:32:14 2009] [debug] proxy_util.c(1914): proxy: initialized single connection worker 0 in child 23999 for (*)
[Fri Jun 19 11:32:14 2009] [debug] proxy_util.c(1801): proxy: grabbed scoreboard slot 0 in child 24000 for worker proxy:reverse
[Fri Jun 19 11:32:14 2009] [debug] proxy_util.c(1820): proxy: worker proxy:reverse already initialized
[Fri Jun 19 11:32:14 2009] [debug] proxy_util.c(1914): proxy: initialized single connection worker 0 in child 24000 for (*)
[Fri Jun 19 11:32:14 2009] [debug] proxy_util.c(1801): proxy: grabbed scoreboard slot 0 in child 24001 for worker proxy:reverse
[Fri Jun 19 11:32:14 2009] [debug] proxy_util.c(1820): proxy: worker proxy:reverse already initialized
[Fri Jun 19 11:32:14 2009] [debug] proxy_util.c(1914): proxy: initialized single connection worker 0 in child 24001 for (*)
[Fri Jun 19 11:32:14 2009] [debug] proxy_util.c(1801): proxy: grabbed scoreboard slot 0 in child 24003 for worker proxy:reverse
[Fri Jun 19 11:32:14 2009] [debug] proxy_util.c(1820): proxy: worker proxy:reverse already initialized
[Fri Jun 19 11:32:14 2009] [debug] proxy_util.c(1914): proxy: initialized single connection worker 0 in child 24003 for (*)

I could not understand them.

All ok ? or anything I should worry about ?

Thx
Vai

anomie · 06-19-2009, 11:53 AM

They appear to be debug level details about mod_proxy. Most likely unrelated to the problem you reported in this thread...

vaibhavs · 06-20-2009, 11:21 PM

HI,

Following lines from the error logs recd this morning.
I have extracted lines which are in the neighbourhood of "Sigterm".
I could not make anything out of it.

Quote:

[Sat Jun 20 03:34:00 2009] [debug] proxy_util.c(1801): proxy: grabbed scoreboard slot 0 in child 22517 for worker proxy:reverse
[Sat Jun 20 03:34:00 2009] [debug] proxy_util.c(1820): proxy: worker proxy:reverse already initialized
[Sat Jun 20 03:34:00 2009] [debug] proxy_util.c(1914): proxy: initialized single connection worker 0 in child 22517 for (*)
[Sat Jun 20 04:33:57 2009] [info] [client 208.122.4.142] (104)Connection reset by peer: core_output_filter: writing data to the network
[Sat Jun 20 04:33:57 2009] [info] [client 208.122.4.142] (32)Broken pipe: core_output_filter: writing data to the network
[Sat Jun 20 04:38:14 2009] [info] [client 112.198.129.179] (104)Connection reset by peer: core_output_filter: writing data to the network
[Sat Jun 20 05:09:15 2009] [debug] proxy_util.c(1801): proxy: grabbed scoreboard slot 0 in child 23753 for worker proxy:reverse
[Sat Jun 20 05:09:15 2009] [debug] proxy_util.c(1820): proxy: worker proxy:reverse already initialized
[Sat Jun 20 05:09:15 2009] [debug] proxy_util.c(1914): proxy: initialized single connection worker 0 in child 23753 for (*)
[Sat Jun 20 05:20:03 2009] [notice] SIGHUP received. Attempting to restart
[Sat Jun 20 05:20:36 2009] [info] Init: Seeding PRNG with 136 bytes of entropy
[Sat Jun 20 05:20:36 2009] [info] Init: Generating temporary RSA private keys (512/1024 bits)
[Sat Jun 20 05:20:36 2009] [info] Init: Generating temporary DH parameters (512/1024 bits)
[Sat Jun 20 05:20:36 2009] [debug] ssl_scache_dbm.c(409): Inter-Process Session Cache (DBM) Expiry: old: 0, new: 0, removed: 0
[Sat Jun 20 05:20:36 2009] [info] Init: Initializing (virtual) servers for SSL
[Sat Jun 20 05:20:36 2009] [info] mod_ssl/2.2.11 compiled against Server: Apache/2.2.11, Library: OpenSSL/0.9.8e-fips-rhel5
[Sat Jun 20 05:20:43 2009] [debug] proxy_util.c(1801): proxy: grabbed scoreboard slot 0 in child 13658 for worker proxy:reverse
[Sat Jun 20 05:20:43 2009] [debug] proxy_util.c(1914): proxy: initialized single connection worker 0 in child 13658 for (*)
[Sat Jun 20 05:20:43 2009] [debug] proxy_util.c(1801): proxy: grabbed scoreboard slot 0 in child 13659 for worker proxy:reverse
[Sat Jun 20 05:20:43 2009] [debug] proxy_util.c(1820): proxy: worker proxy:reverse already initialized
[Sat Jun 20 05:20:43 2009] [debug] proxy_util.c(1914): proxy: initialized single connection worker 0 in child 13659 for (*)
[Sat Jun 20 05:20:43 2009] [debug] proxy_util.c(1801): proxy: grabbed scoreboard slot 0 in child 13663 for worker proxy:reverse
[Sat Jun 20 05:20:43 2009] [debug] proxy_util.c(1820): proxy: worker proxy:reverse already initialized
[Sat Jun 20 05:20:43 2009] [debug] proxy_util.c(1914): proxy: initialized single connection worker 0 in child 13663 for (*)
[Sat Jun 20 05:20:43 2009] [debug] proxy_util.c(1801): proxy: grabbed scoreboard slot 0 in child 13664 for worker proxy:reverse
[Sat Jun 20 05:20:43 2009] [debug] proxy_util.c(1820): proxy: worker proxy:reverse already initialized
[Sat Jun 20 05:20:43 2009] [debug] proxy_util.c(1914): proxy: initialized single connection worker 0 in child 13664 for (*)
[Sat Jun 20 05:20:43 2009] [notice] Apache/2.2.11 (Unix) mod_ssl/2.2.11 OpenSSL/0.9.8e-fips-rhel5 mod_bwlimited/1.4 PHP/5.2.9 configured -- resuming normal operations
[Sat Jun 20 05:20:43 2009] [info] Server built: Jun 9 2009 09:46:20
[Sat Jun 20 05:20:43 2009] [debug] prefork.c(1009): AcceptMutex: sysvsem (default: sysvsem)
[Sat Jun 20 05:20:43 2009] [debug] proxy_util.c(1801): proxy: grabbed scoreboard slot 0 in child 13665 for worker proxy:reverse
[Sat Jun 20 05:20:43 2009] [debug] proxy_util.c(1820): proxy: worker proxy:reverse already initialized

Pls advice if everything seems ok.

Thx
Vai

anomie · 06-20-2009, 11:39 PM

I don't see any warnings this time about children PIDs not dying. Did you cut those out when posting? Or have you made some changes?