I would bet on your method of parsing php and the scripts being ran,
in any case to be sure:
Try the strace approach:
strace -o /tmp/outputfile -s 5000 httpd -X or strace -ff -F -s200 -o
/tmp/strace.out -p PID
to try to find out what's really going on.
2016-09-30 20:19 GMT+02:00 Fabio F.Gervasi <fabio.gervas...@gmail.com
<mailto:fabio.gervas...@gmail.com>>:
Hi!
I have additional information:
/var/log/httpd/error_log, at "crash time": [Fri Sep 30
19:09:03.897325 2016] [mpm_event:trace4] [pid 30339:tid
139796798162688] event.c(930): socket reached timeout in
lingering-close state
What do you think?
2016-09-30 14:47 GMT+02:00 Fabio F.Gervasi
<fabio.gervas...@gmail.com <mailto:fabio.gervas...@gmail.com>>:
Hi!
Thank you for your reply. I tried the following tests.
*1) Using a little text file:*
*# ab -k -c 100 -n 2000 localhost/test.txt*
This is ApacheBench, Version 2.3 <$Revision: 1748469 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd,
http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/
Benchmarking localhost (be patient)
Completed 200 requests
Completed 400 requests
Completed 600 requests
Completed 800 requests
Completed 1000 requests
Completed 1200 requests
Completed 1400 requests
Completed 1600 requests
Completed 1800 requests
Completed 2000 requests
Finished 2000 requests
Server Software: Apache/2.4.23
Server Hostname: localhost
Server Port: 80
Document Path: /test.txt
Document Length: 52 bytes
Concurrency Level: 100
Time taken for tests: 2.521 seconds
Complete requests: 2000
*Failed requests: 16*
(Connect: 0, Receive: 0, Length: 16, Exceptions: 0)
Keep-Alive requests: 1984
Total transferred: 950336 bytes
HTML transferred: 103168 bytes
Requests per second: 793.45 [#/sec] (mean)
Time per request: 126.032 [ms] (mean)
Time per request: 1.260 [ms] (mean, across all
concurrent requests)
Transfer rate: 368.18 [Kbytes/sec] received
Connection Times (ms)
min mean[+/-sd] median max
Connect: 0 1 3.8 0 21
Processing: 1 123 126.5 83 772
Waiting: 0 123 126.7 83 772
Total: 1 124 126.6 85 772
Percentage of the requests served within a certain time (ms)
50% 85
66% 154
75% 201
80% 229
90% 303
95% 373
98% 452
99% 547
100% 772 (longest request)
/I obtain 16 failed requests, but if I run more again I obtain
a different number./
*2) Using a big gif file:*
*# ab -k -c 100 -n 2000 localhost/it-vis-animation.gif*
This is ApacheBench, Version 2.3 <$Revision: 1748469 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd,
http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/
Benchmarking localhost (be patient)
Completed 200 requests
Completed 400 requests
Completed 600 requests
Completed 800 requests
Completed 1000 requests
Completed 1200 requests
Completed 1400 requests
Completed 1600 requests
Completed 1800 requests
Completed 2000 requests
Finished 2000 requests
Server Software: Apache/2.4.23
Server Hostname: localhost
Server Port: 80
Document Path: /it-vis-animation.gif
Document Length: 8105309 bytes
Concurrency Level: 100
Time taken for tests: 26.294 seconds
Complete requests: 2000
*Failed requests: 0*
Keep-Alive requests: 2000
Total transferred: 16211484000 bytes
HTML transferred: 16210618000 bytes
Requests per second: 76.06 [#/sec] (mean)
Time per request: 1314.691 [ms] (mean)
Time per request: 13.147 [ms] (mean, across all
concurrent requests)
Transfer rate: 602100.83 [Kbytes/sec] received
Connection Times (ms)
min mean[+/-sd] median max
Connect: 0 1 4.0 0 22
Processing: 404 1309 80.0 1298 1635
Waiting: 5 22 32.4 10 207
Total: 420 1310 80.6 1298 1635
Percentage of the requests served within a certain time (ms)
50% 1298
66% 1315
75% 1342
80% 1360
90% 1397
95% 1440
98% 1513
99% 1530
100% 1635 (longest request)
*
*
/In this case I obtain always 0 failed!/
*3) Using a little png file:*
*# ab -k -c 100 -n 2000 localhost/apple-touch-icon.png*
This is ApacheBench, Version 2.3 <$Revision: 1748469 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd,
http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/
Benchmarking localhost (be patient)
Completed 200 requests
Completed 400 requests
Completed 600 requests
Completed 800 requests
Completed 1000 requests
Completed 1200 requests
Completed 1400 requests
Completed 1600 requests
Completed 1800 requests
Completed 2000 requests
Finished 2000 requests
Server Software: Apache/2.4.23
Server Hostname: localhost
Server Port: 80
Document Path: /apple-touch-icon.png
Document Length: 12364 bytes
Concurrency Level: 100
Time taken for tests: 2.576 seconds
Complete requests: 2000
*Failed requests: 22*
(Connect: 0, Receive: 0, Length: 22, Exceptions: 0)
Keep-Alive requests: 1978
Total transferred: 25304554 bytes
HTML transferred: 24455992 bytes
Requests per second: 776.52 [#/sec] (mean)
Time per request: 128.779 [ms] (mean)
Time per request: 1.288 [ms] (mean, across all concurrent
requests)
Transfer rate: 9594.53 [Kbytes/sec] received
Connection Times (ms)
min mean[+/-sd] median max
Connect: 0 1 3.9 0 20
Processing: 0 125 112.0 101 563
Waiting: 0 125 112.1 101 563
Total: 0 126 112.6 102 563
Percentage of the requests served within a certain time (ms)
50% 102
66% 159
75% 196
80% 220
90% 282
95% 354
98% 401
99% 457
100% 563 (longest request)
/I get 22 failed requests, but if I run more again I obtain a
different number./
What do you thing?
Thank you!
2016-09-30 13:50 GMT+02:00 Daniel <dferra...@gmail.com
<mailto:dferra...@gmail.com>>:
hello,
the fact that all those 500 error reponses go with
"X-Powered-By: PHP/5.6.26" tell me it is php giving those
errors.
If you are still unsure, you could use the ab tool from
Apache HTTPD, and request a specific static file (text,
gif) hundreds of times to see if you get a 500 error from
HTTPD.
2016-09-30 8:59 GMT+02:00 Fabio F.Gervasi
<fabio.gervas...@gmail.com
<mailto:fabio.gervas...@gmail.com>>:
Hi,
I'm not 100% sure that the real source of the problem
is apache (could be php or other), but I'd like start
from here as the only logs that provides me with
information (with trace4 level) is apache log. No
information appears from other logs.
I have:
- Linux 4.7.4-100.fc23.x86_64
- Server version: Apache/2.4.23 (Fedora)
- mysql Ver 15.1 Distrib 10.0.26-MariaDB, for Linux
(x86_64) using readline 5.1
- PHP Version => 5.6.25
The problem: random internal server error 500. Random
because, for example, if a page produces the error and
do "reload" then it works. The same page may not work
as well as work. Sometimes you can use the site for
several minutes with no problems, then suddenly there
is the error.
When error occurs, this is all that I get from the log
file (with loglevel = trace4):
[...]
[Fri Sep 30 07:41:39.151052 2016] [rewrite:trace3]
[pid 17957:tid 140241771534080] mod_rewrite.c(477):
[client 151.25.206.200:38368
<http://151.25.206.200:38368>] 151.25.206.200 - -
[www.centrometeo.com/sid#55c3e3673400][rid#7f8c8000e9d0/subreq
<http://www.centrometeo.com/sid#55c3e3673400][rid%237f8c8000e9d0/subreq>]
[perdir /home/web/centrometeo.com/
<http://centrometeo.com/>] applying pattern '.*' to
uri 'index.php', referer:
http://www.centrometeo.com/modelli-numerici/modello-wrf-nmm/559-wrf-mslp-6hprec-ita
<http://www.centrometeo.com/modelli-numerici/modello-wrf-nmm/559-wrf-mslp-6hprec-ita>
[Fri Sep 30 07:41:39.151092 2016] [rewrite:trace1]
[pid 17957:tid 140241771534080] mod_rewrite.c(477):
[client 151.25.206.200:38368
<http://151.25.206.200:38368>] 151.25.206.200 - -
[www.centrometeo.com/sid#55c3e3673400][rid#7f8c8000e9d0/subreq
<http://www.centrometeo.com/sid#55c3e3673400][rid%237f8c8000e9d0/subreq>]
[perdir /home/web/centrometeo.com/
<http://centrometeo.com/>] pass through
/home/web/centrometeo.com/index.php
<http://centrometeo.com/index.php>, referer:
http://www.centrometeo.com/modelli-numerici/modello-wrf-nmm/559-wrf-mslp-6hprec-ita
<http://www.centrometeo.com/modelli-numerici/modello-wrf-nmm/559-wrf-mslp-6hprec-ita>
[Fri Sep 30 07:41:39.913003 2016] [core:trace4] [pid
17957:tid 140241771534080] util_script.c(567): [client
151.25.206.200:38368 <http://151.25.206.200:38368>]
Headers from script 'php.fcgi':, referer:
http://www.centrometeo.com/modelli-numerici/modello-wrf-nmm/559-wrf-mslp-6hprec-ita
<http://www.centrometeo.com/modelli-numerici/modello-wrf-nmm/559-wrf-mslp-6hprec-ita>
[Fri Sep 30 07:41:39.913097 2016] [core:trace4] [pid
17957:tid 140241771534080] util_script.c(568): [client
151.25.206.200:38368 <http://151.25.206.200:38368>]
*Status: 500 Internal Server Error*, referer:
http://www.centrometeo.com/modelli-numerici/modello-wrf-nmm/559-wrf-mslp-6hprec-ita
<http://www.centrometeo.com/modelli-numerici/modello-wrf-nmm/559-wrf-mslp-6hprec-ita>
[Fri Sep 30 07:41:39.913130 2016] [core:trace1] [pid
17957:tid 140241771534080] util_script.c(649): [client
151.25.206.200:38368 <http://151.25.206.200:38368>]
*Status line from script 'php.fcgi': 500 Internal
Server Error*, referer:
http://www.centrometeo.com/modelli-numerici/modello-wrf-nmm/559-wrf-mslp-6hprec-ita
<http://www.centrometeo.com/modelli-numerici/modello-wrf-nmm/559-wrf-mslp-6hprec-ita>
[Fri Sep 30 07:41:39.913162 2016] [core:trace4] [pid
17957:tid 140241771534080] util_script.c(568): [client
151.25.206.200:38368 <http://151.25.206.200:38368>]
X-Powered-By: PHP/5.6.26, referer:
http://www.centrometeo.com/modelli-numerici/modello-wrf-nmm/559-wrf-mslp-6hprec-ita
<http://www.centrometeo.com/modelli-numerici/modello-wrf-nmm/559-wrf-mslp-6hprec-ita>
[Fri Sep 30 07:41:39.913191 2016] [core:trace4] [pid
17957:tid 140241771534080] util_script.c(568): [client
151.25.206.200:38368 <http://151.25.206.200:38368>]
P3P: CP="NOI ADM DEV PSAi COM NAV OUR OTRo STP IND
DEM", referer:
http://www.centrometeo.com/modelli-numerici/modello-wrf-nmm/559-wrf-mslp-6hprec-ita
<http://www.centrometeo.com/modelli-numerici/modello-wrf-nmm/559-wrf-mslp-6hprec-ita>
[Fri Sep 30 07:41:39.913218 2016] [core:trace4] [pid
17957:tid 140241771534080] util_script.c(568): [client
151.25.206.200:38368 <http://151.25.206.200:38368>]
Content-Encoding: gzip, referer:
http://www.centrometeo.com/modelli-numerici/modello-wrf-nmm/559-wrf-mslp-6hprec-ita
<http://www.centrometeo.com/modelli-numerici/modello-wrf-nmm/559-wrf-mslp-6hprec-ita>
[Fri Sep 30 07:41:39.913246 2016] [core:trace4] [pid
17957:tid 140241771534080] util_script.c(568): [client
151.25.206.200:38368 <http://151.25.206.200:38368>]
Vary: Accept-Encoding, referer:
http://www.centrometeo.com/modelli-numerici/modello-wrf-nmm/559-wrf-mslp-6hprec-ita
<http://www.centrometeo.com/modelli-numerici/modello-wrf-nmm/559-wrf-mslp-6hprec-ita>
[Fri Sep 30 07:41:39.913275 2016] [core:trace4] [pid
17957:tid 140241771534080] util_script.c(568): [client
151.25.206.200:38368 <http://151.25.206.200:38368>]
Content-type: text/html; charset=UTF-8, referer:
http://www.centrometeo.com/modelli-numerici/modello-wrf-nmm/559-wrf-mslp-6hprec-ita
<http://www.centrometeo.com/modelli-numerici/modello-wrf-nmm/559-wrf-mslp-6hprec-ita>
[Fri Sep 30 07:41:39.913395 2016] [http:trace3] [pid
17957:tid 140241771534080] http_filters.c(1006):
[client 151.25.206.200:38368
<http://151.25.206.200:38368>] *Response sent with
status 500, headers:*, referer:
http://www.centrometeo.com/modelli-numerici/modello-wrf-nmm/559-wrf-mslp-6hprec-ita
<http://www.centrometeo.com/modelli-numerici/modello-wrf-nmm/559-wrf-mslp-6hprec-ita>
[Fri Sep 30 07:41:39.913432 2016] [http:trace4] [pid
17957:tid 140241771534080] http_filters.c(835):
[client 151.25.206.200:38368
<http://151.25.206.200:38368>] X-Powered-By:
PHP/5.6.26, referer:
http://www.centrometeo.com/modelli-numerici/modello-wrf-nmm/559-wrf-mslp-6hprec-ita
<http://www.centrometeo.com/modelli-numerici/modello-wrf-nmm/559-wrf-mslp-6hprec-ita>
[Fri Sep 30 07:41:39.913458 2016] [http:trace4] [pid
17957:tid 140241771534080] http_filters.c(835):
[client 151.25.206.200:38368
<http://151.25.206.200:38368>] P3P: CP=\\"NOI ADM
DEV PSAi COM NAV OUR OTRo STP IND DEM\\", referer:
http://www.centrometeo.com/modelli-numerici/modello-wrf-nmm/559-wrf-mslp-6hprec-ita
<http://www.centrometeo.com/modelli-numerici/modello-wrf-nmm/559-wrf-mslp-6hprec-ita>
[Fri Sep 30 07:41:39.913481 2016] [http:trace4] [pid
17957:tid 140241771534080] http_filters.c(835):
[client 151.25.206.200:38368
<http://151.25.206.200:38368>] Content-Encoding: gzip,
referer:
http://www.centrometeo.com/modelli-numerici/modello-wrf-nmm/559-wrf-mslp-6hprec-ita
<http://www.centrometeo.com/modelli-numerici/modello-wrf-nmm/559-wrf-mslp-6hprec-ita>
[...]
Note the use of fcgi. Apache is indeed configured with
event/php-fpm/FastCGI, but the same thing happens with
"normal" prefork / php!
Until a few days ago it did not happen, it started
after updating the system (kernel, apache, php, mariadb).
I do not really know what to do.
Thank you very much.
Fabio.
--
*Daniel Ferradal*
IT Specialist
email dferradal at gmail.com <http://gmail.com>
linkedin es.linkedin.com/in/danielferradal
<http://es.linkedin.com/in/danielferradal>
--
*Daniel Ferradal*
IT Specialist
email dferradal at gmail.com <http://gmail.com>
linkedin es.linkedin.com/in/danielferradal
<http://es.linkedin.com/in/danielferradal>