16.08.2012
Kategorie: Linux, CentOS, PHP

Debug php mit strace und mod_fcgid


Speziell bei timeout Problemen kann es vorkommen dass der php Prozess einfach nach 30 sec. austimed und bei der Webseite ein HTTP ERROR 500 ausgegeben wird. Jetzt ist es oft schwierig den Fehler zu erkennen man ja den Programmcode nicht kennt.

Die Fehlermeldung dazu im Apache Log sieht oft wie folgt aus:

[info] mod_fcgid: process /etc/apache2/phpconf/xxxxx/php-fcgi-starter(12813) exit(communication error), terminated by calling exit(), return code: 0
www.webseite.at.at 195.230.xxx.xxx - - [16/Aug/2012:11:38:36 +0200] "GET / HTTP/1.1" 500 534 "-" "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.1 (KHTML, like Gecko) Chrome/21.0.1180.75 Safari/537.1"

Ein nützliches tool ist hierbei strace, da es alle Systemaufrufe aufzeichnet die der php Prozess ausführt. Hierbei erkennt man zB wenn ein file nicht gelesen werden kann, oder eine tcp Verbindung steht aber keine connection zustande kommt.

Bei php mittels fcgi hat man aber das Problem dass der php Prozess meist erst gestartet wird mit einer neuen pid und bis man diese weis, ist auch schon der interessante Teil vorbei. Abhilfe schafft hier wenn schon beim starten des php Prozesses den strace mitstarten. Eintragen kann man dies am besten im php-fcgi-starter script. 

#!/bin/sh
PHPRC="/etc/apache2/phpconf/xxx/"
export PHPRC
export TMPDIR=/tmp
# Set desired PHP_FCGI_* environment variables.
# Example:
# PHP FastCGI processes exit after 500 requests by default.
PHP_FCGI_MAX_REQUESTS=500
export PHP_FCGI_MAX_REQUESTS
FcgidMaxRequestsPerProcess=500
export FcgidMaxRequestsPerProcess
FcgidProcessLifeTime=600
export FcgidProcessLifeTime
PHP_FCGI_CHILDREN=0
export PHP_FCGI_CHILDREN
#### PHP Prozess mit strace
exec strace -o /tmp/strace.out /opt/php5/php5standard
#exec /opt/php5/php5standard

wie wir schön sehen landet der output nun im /tmp Verzeichnis. So sieht das ganze dann zB aus wenn ein Zugriff auf einen externen Webserver ein timeout verursacht.

socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 6
fcntl(6, F_GETFL) = 0x2 (flags O_RDWR)
fcntl(6, F_SETFL, O_RDWR|O_NONBLOCK) = 0
connect(6, {sa_family=AF_INET, sin_port=htons(1080), sin_addr=inet_addr("195.202.xxx.xxx")}, 16) = -1 EINPROGRESS (Operation now in progress)
poll([{fd=6, events=POLLIN|POLLOUT|POLLERR|POLLHUP}], 1, 5000) = 1 ([{fd=6, revents=POLLOUT}])
getsockopt(6, SOL_SOCKET, SO_ERROR, [0], [4]) = 0
fcntl(6, F_SETFL, O_RDWR) = 0
sendto(6, "GET 69.171.xxx.xxx/feeds/p"..., 82, MSG_DONTWAIT, NULL, 0) = 82
sendto(6, "Host: 69.171.xxx.xxx\r\n", 21, MSG_DONTWAIT, NULL, 0) = 21
sendto(6, "User-Agent: Mozilla/5.0 (Windows"..., 104, MSG_DONTWAIT, NULL, 0) = 104
sendto(6, "\r\n", 2, MSG_DONTWAIT, NULL, 0) = 2
poll([{fd=6, events=POLLIN|POLLPRI|POLLERR|POLLHUP}], 1, 0) = 0 (Timeout)
poll([{fd=6, events=POLLIN|POLLERR|POLLHUP}], 1, 5000) = 0 (Timeout)
poll([{fd=6, events=POLLIN|POLLPRI|POLLERR|POLLHUP}], 1, 0) = 0 (Timeout)
poll([{fd=6, events=POLLIN|POLLERR|POLLHUP}], 1, 5000) = 0 (Timeout)
close(6) = 0

Nachdem man nun festgestellt hat dass der Zugriff auf 69.171.xxx.xxx anscheinend ein Timeout Problem hat muss man diesen Code Teil nur noch ausfindig machen und fixen ;)


 
Telefon:
E-Mail:
Fax:
Web:

+43 2682 24080
office(at)epb.at
+43 2682 205 7700 9963
zum Kontaktformular