Server Error 500 debuggen

  • Hi,


    weiß jemand wie ich am besten einen Server-Fehler 500 debuggen kann. Ich habe per ssh in den Log-Files keinen Eintrag gefunden. Ich würde erwarten, dass der Server Probleme in den error_log schreibt. Muss ich evtl. irgendetwas aktivieren um diese Logs zu bekommen, oder soll ich im Dunkeln tappen?

  • Also eigentlich sollte der Fehler entweder in /var/log/apache2/error.log oder in einem der Error-Logs der jeweiligen Seiten protokolliert sein.
    Es kann sein dass es overkill ist, aber du kannst auch alle Apache-Child Prozesse mit 'ps' auflisten, und dann alle Prozesse gleichzeitig mit 'strace' überwachen.


    Hier ein Beispiel bei mir: ps -efl | grep apache

    Code
    5 S root  	2900 	1  0  80   0 - 74235 poll_s Aug09 ?    	00:01:08 /usr/sbin/apache2 -k start5 S www-data 17335  2900  0  80   0 - 74291 lock_f 06:25 ?    	00:00:00 /usr/sbin/apache2 -k start5 S www-data 17336  2900  0  80   0 - 74289 lock_f 06:25 ?    	00:00:00 /usr/sbin/apache2 -k start5 S www-data 17338  2900  0  80   0 - 74289 lock_f 06:25 ?    	00:00:00 /usr/sbin/apache2 -k start5 S www-data 17339  2900  0  80   0 - 74289 lock_f 06:25 ?    	00:00:00 /usr/sbin/apache2 -k start5 S www-data 17340  2900  0  80   0 - 74253 ep_pol 06:25 ?    	00:00:00 /usr/sbin/apache2 -k start5 S www-data 18480  2900  0  80   0 - 74289 lock_f 08:56 ?    	00:00:00 /usr/sbin/apache2 -k start0 S root 	19487 19436  0  80   0 -  3938 pipe_w 11:28 pts/0	00:00:00 grep --color=auto apache


    Die PIDs aller Childs überwache ich nun mit strace:

    Code
    strace -p 17335 -p 17336 -p 17338 -p 17339 -p 17340 -p 18480


    Das ist (auf meinem Testsystem) sehr ruhig, weil die nicht viel mehr machen als auf einen Connect warten:

    Code
    [pid 17336] fcntl(9, F_SETLKW, {l_type=F_WRLCK, l_whence=SEEK_SET, l_start=0, l_len=0} <unfinished ...>[pid 18480] fcntl(9, F_SETLKW, {l_type=F_WRLCK, l_whence=SEEK_SET, l_start=0, l_len=0} <unfinished ...>[pid 17340] epoll_wait(15,  <unfinished ...>[pid 17339] fcntl(9, F_SETLKW, {l_type=F_WRLCK, l_whence=SEEK_SET, l_start=0, l_len=0} <unfinished ...>[pid 17335] fcntl(9, F_SETLKW, {l_type=F_WRLCK, l_whence=SEEK_SET, l_start=0, l_len=0} <unfinished ...>[pid 17338] fcntl(9, F_SETLKW, {l_type=F_WRLCK, l_whence=SEEK_SET, l_start=0, l_len=0} <unfinished ...>[pid 17340] <... epoll_wait resumed> [], 2, 10000) = 0[pid 17340] epoll_wait(15, [], 2, 10000) = 0[pid 17340] epoll_wait(15,


    Wenn ich jetzt aber meine Seite aufrufe sieht man dass was passiert, so sollte das normale ausliefern einer html-Seite aussehen:

    Code
    [pid 17340] accept4(4, {sa_family=AF_INET6, sin6_port=htons(35581), inet_pton(AF_INET6, "::ffff:xx.xxx.xxx.xxxx", &sin6_addr), sin6_flowinfo=0, sin6_scope_id=0}, [28], SOCK_CLOEXEC) = 16[pid 17340] fcntl(9, F_SETLKW, {l_type=F_UNLCK, l_whence=SEEK_SET, l_start=0, l_len=0}) = 0[pid 17336] <... fcntl resumed> )   	= 0[pid 17336] epoll_wait(15,  <unfinished ...>[pid 17340] getsockname(16, {sa_family=AF_INET6, sin6_port=htons(80), inet_pton(AF_INET6, "::ffff:xxx.xx.xx.xxx", &sin6_addr), sin6_flowinfo=0, sin6_scope_id=0}, [28]) = 0[pid 17340] fcntl(16, F_GETFL)      	= 0x2 (flags O_RDWR)[pid 17340] fcntl(16, F_SETFL, O_RDWR|O_NONBLOCK) = 0[pid 17340] read(16, "GET / HTTP/1.0\r\nHost: domain.de\r\n"..., 8000) = 432[pid 17340] stat("/var/www/html/", {st_mode=S_IFDIR|0777, st_size=4096, ...}) = 0[pid 17340] lstat("/var", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0[pid 17340] lstat("/var/www", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0[pid 17340] lstat("/var/www/html", {st_mode=S_IFDIR|0777, st_size=4096, ...}) = 0[pid 17340] stat("/var/www/html/index.html", {st_mode=S_IFREG|0777, st_size=7, ...}) = 0[pid 17340] lstat("/var/www/html/index.html", {st_mode=S_IFREG|0777, st_size=7, ...}) = 0[pid 17340] open("/var/www/html/index.html", O_RDONLY|O_CLOEXEC) = 17[pid 17340] close(17)               	= 0[pid 17340] writev(16, [{"HTTP/1.1 304 Not Modified\r\nDate:"..., 142}], 1) = 142[pid 17340] write(12, "xx.xxx.xxx.xxx- - [17/Aug/2016:"..., 152) = 152[pid 17340] times({tms_utime=0, tms_stime=0, tms_cutime=0, tms_cstime=0}) = 1784522822[pid 17340] shutdown(16, SHUT_WR)   	= 0[pid 17340] poll([{fd=16, events=POLLIN}], 1, 2000) = 1 ([{fd=16, revents=POLLIN|POLLHUP}])[pid 17340] read(16, "", 512)       	= 0[pid 17340] close(16)               	= 0[pid 17340] read(7, 0x7ffd931e364f, 1)  = -1 EAGAIN (Resource temporarily unavailable)[pid 17340] fcntl(9, F_SETLKW, {l_type=F_WRLCK, l_whence=SEEK_SET, l_start=0, l_len=0}


    Schön zu sehen auch dass der Indianer hier einen "Not Modified" Header als Antwort schickt.
    Mag sein dass es Overkill ist, aber wenn man im error log wirklich garnix findet, findet sich hier vielleicht ein Hinweis.


    Thomas


  • Hmmm, installier dir mal das Tool 'fatrace', starte es, und ruf deine Seite auf.
    Es sollte dir ausgeben welche Dateien zugegriffen werden und von welchem Prozess.
    Sieht bei mir so aus:

    Code
    apache2(17340): O /var/www/html/index.html
    apache2(17340): W /var/log/apache2/access.log
    apache2(17340): C /var/www/html/index.html


    (Ich halte das für bedeutend schneller als eventuell verstreute Apache-Configs zu durchwühlen, auch wenn 'apachectl -S' hier wohl schon etwas helfen würde!)

  • PS: Ich hab gerade nochmal geschaut warum fatrace nur folgendes loggt:

    Code
    1. Öffnen der html-Datei.
    2. Schreiben des Access-Logs.
    3. Schließen der html-Datei.


    Eigentlich hätte er ja das Lesen der html-Datei auch loggen müssen.
    Dummerweise liest der Apache die Datei nicht mit einem normalen READ, sondern er mappt sie sich in den Memory:
    (strace output)

    Code
    open("/var/www/html/index.html", O_RDONLY|O_CLOEXEC) = 17
    mmap(NULL, 8, PROT_READ, MAP_SHARED, 17, 0) = 0x7f4aec5b7000
    close(17)


    Und da fatrace auf inotify aufbaut, und dort in der Manpage steht:

    Code
    The inotify API does not report file accesses and modifications that may occur because of mmap(2), msync(2), and munmap(2).


    Jetzt ist meine Welt wieder heil :)


    Thomas