httpd-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Daniel <dferra...@gmail.com>
Subject Re: [users@httpd] Random Internal Server Error 500 after apache and system update
Date Sun, 02 Oct 2016 08:02:37 GMT
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.gervasi70@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.gervasi70@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 <dferradal@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.gervasi70@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]
>>>> 151.25.206.200 - - [www.centrometeo.com/sid#55c3e
>>>> 3673400][rid#7f8c8000e9d0/subreq
>>>> <http://www.centrometeo.com/sid#55c3e3673400][rid%237f8c8000e9d0/subreq>]
>>>> [perdir /home/web/centrometeo.com/] applying pattern '.*' to uri
>>>> 'index.php', referer: http://www.centrometeo.com/mod
>>>> elli-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]
>>>> 151.25.206.200 - - [www.centrometeo.com/sid#55c3e
>>>> 3673400][rid#7f8c8000e9d0/subreq
>>>> <http://www.centrometeo.com/sid#55c3e3673400][rid%237f8c8000e9d0/subreq>]
>>>> [perdir /home/web/centrometeo.com/] pass through /home/web/
>>>> centrometeo.com/index.php, referer: http://www.centrometeo.com/mod
>>>> elli-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]
>>>> Headers from script 'php.fcgi':, referer:
>>>> 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]   *Status:
>>>> 500 Internal Server Error*, referer: http://www.centrometeo.com/mod
>>>> elli-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] *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
>>>> [Fri Sep 30 07:41:39.913162 2016] [core:trace4] [pid 17957:tid
>>>> 140241771534080] util_script.c(568): [client 151.25.206.200:38368]
>>>> X-Powered-By: PHP/5.6.26, referer: http://www.centrometeo.com/mod
>>>> elli-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]
>>>> 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
>>>> [Fri Sep 30 07:41:39.913218 2016] [core:trace4] [pid 17957:tid
>>>> 140241771534080] util_script.c(568): [client 151.25.206.200:38368]
>>>> Content-Encoding: gzip, referer: http://www.centrometeo.com/mod
>>>> elli-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]
>>>> Vary: Accept-Encoding, referer: http://www.centrometeo.com/mod
>>>> elli-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]
>>>> Content-type: text/html; charset=UTF-8, referer:
>>>> 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] *Response
>>>> sent with status 500, headers:*, referer:
>>>> 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]
>>>> X-Powered-By: PHP/5.6.26, referer: http://www.centrometeo.com/mod
>>>> elli-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]
>>>> 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
>>>> [Fri Sep 30 07:41:39.913481 2016] [http:trace4] [pid 17957:tid
>>>> 140241771534080] http_filters.c(835): [client 151.25.206.200:38368]
>>>> Content-Encoding: gzip, referer: http://www.centrometeo.com/mod
>>>> elli-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
>>> linkedin     es.linkedin.com/in/danielferradal
>>>
>>
>>
>


-- 
*Daniel Ferradal*
IT Specialist

email         dferradal at gmail.com
linkedin     es.linkedin.com/in/danielferradal

Mime
View raw message