lighttpd: PHP Prozesse unter falschem Benutzername

  • Thread starter Thread starter lichtmaschine
  • Start date Start date
Also, inzwischen habe ich das ganze hinbekommen. Allerdings erhalte ich immer mal wieder beim Aufruf einer Seite einen 500er Error ausgegeben.

php5-fpm.log sagt folgendes:

[18-Dec-2011 17:03:55] NOTICE: [pool domain.de] child 32672 started
[18-Dec-2011 19:21:22] WARNING: [pool domain.com] child 19228 exited with code 1 after 20480.683950 seconds from start
[18-Dec-2011 19:21:22] NOTICE: [pool domain.com] child 9455 started
[18-Dec-2011 20:00:51] WARNING: [pool domain.com] child 9455 exited with code 1 after 2368.957515 seconds from start
[18-Dec-2011 20:00:51] NOTICE: [pool domain.com] child 11792 started
[18-Dec-2011 20:19:51] WARNING: [pool domain.de] child 19215 exited with code 1 after 23989.430938 seconds from start
[18-Dec-2011 20:19:51] NOTICE: [pool domain.de] child 13191 started
[18-Dec-2011 21:22:11] WARNING: [pool domain.de] child 22515 exited with code 1 after 24804.315722 seconds from start
[18-Dec-2011 21:22:11] NOTICE: [pool domain.de] child 17071 started
[18-Dec-2011 21:53:50] WARNING: [pool domain.com] child 19229 exited with code 1 after 29627.937997 seconds from start
[18-Dec-2011 21:53:50] NOTICE: [pool domain.com] child 18709 started
Click to expand...

So bald die Prozesse also neugestartet wurden, läuft das ganze eine bestimmte Zeit wieder einwandfrei.
 
Habe jetzt mal das Debug Logging in FPM aktiviert. Aber daraus lese ich auch nichts brauchbares.

Code: 
[20-Dec-2011 15:45:33.348817] NOTICE: pid 12514, fpm_children_make(), line 404: [pool domain1.de] child 18242 started
[20-Dec-2011 16:01:23.937778] DEBUG: pid 12514, fpm_got_signal(), line 76: received SIGCHLD
[20-Dec-2011 16:01:23.937845] WARNING: pid 12514, fpm_children_bury(), line 252: [pool domain1.de] child 18242 exited with code 1 after 950.589038 seconds from s$
[20-Dec-2011 16:01:23.938681] NOTICE: pid 12514, fpm_children_make(), line 404: [pool domain1.de] child 19061 started
[20-Dec-2011 16:12:30.684158] DEBUG: pid 12514, fpm_got_signal(), line 76: received SIGCHLD
[20-Dec-2011 16:12:30.684238] WARNING: pid 12514, fpm_children_bury(), line 252: [pool domain1.de] child 16762 exited with code 1 after 3409.645746 seconds from $
[20-Dec-2011 16:12:30.685013] NOTICE: pid 12514, fpm_children_make(), line 404: [pool domain1.de] child 19743 started
[20-Dec-2011 16:23:35.094351] DEBUG: pid 12514, fpm_got_signal(), line 76: received SIGCHLD
[20-Dec-2011 16:23:35.094414] WARNING: pid 12514, fpm_children_bury(), line 252: [pool domain1.de] child 17712 exited on signal 11 (SIGSEGV) after 2933.476704 se$
[20-Dec-2011 16:23:35.095228] NOTICE: pid 12514, fpm_children_make(), line 404: [pool domain1.de] child 20327 started
[20-Dec-2011 16:45:06.155754] DEBUG: pid 12514, fpm_got_signal(), line 76: received SIGCHLD
[20-Dec-2011 16:45:06.155829] WARNING: pid 12514, fpm_children_bury(), line 252: [pool domain1.de] child 20327 exited with code 1 after 1291.060611 seconds from $
[20-Dec-2011 16:45:06.156636] NOTICE: pid 12514, fpm_children_make(), line 404: [pool domain1.de] child 21359 started
[20-Dec-2011 17:07:56.943912] DEBUG: pid 12514, fpm_got_signal(), line 76: received SIGCHLD
[20-Dec-2011 17:07:56.943992] WARNING: pid 12514, fpm_children_bury(), line 252: [pool domain1.de] child 19743 exited on signal 11 (SIGSEGV) after 3326.258989 se$
[20-Dec-2011 17:07:56.944822] NOTICE: pid 12514, fpm_children_make(), line 404: [pool domain1.de] child 22616 started
[20-Dec-2011 17:11:07.279629] DEBUG: pid 12514, fpm_got_signal(), line 76: received SIGCHLD
[20-Dec-2011 17:11:07.279698] WARNING: pid 12514, fpm_children_bury(), line 252: [pool domain1.de] child 18009 exited with code 1 after 5416.899411 seconds from $
[20-Dec-2011 17:11:07.280241] NOTICE: pid 12514, fpm_children_make(), line 404: [pool domain1.de] child 22814 started
[20-Dec-2011 17:16:45.468862] DEBUG: pid 12514, fpm_got_signal(), line 76: received SIGCHLD
[20-Dec-2011 17:16:45.468934] WARNING: pid 12514, fpm_children_bury(), line 252: [pool domain1.de] child 21359 exited with code 1 after 1899.312308 seconds from $
[20-Dec-2011 17:16:45.469439] NOTICE: pid 12514, fpm_children_make(), line 404: [pool domain1.de] child 23049 started
[20-Dec-2011 17:23:44.457212] DEBUG: pid 12514, fpm_got_signal(), line 76: received SIGCHLD
[20-Dec-2011 17:23:44.457279] WARNING: pid 12514, fpm_children_bury(), line 252: [pool domain1.de] child 22814 exited with code 1 after 757.177049 seconds from s$
[20-Dec-2011 17:23:44.457776] NOTICE: pid 12514, fpm_children_make(), line 404: [pool domain1.de] child 23445 started
[20-Dec-2011 17:30:07.913654] DEBUG: pid 12514, fpm_got_signal(), line 76: received SIGCHLD
[20-Dec-2011 17:30:07.913724] WARNING: pid 12514, fpm_children_bury(), line 252: [pool domain1.de] child 23049 exited on signal 11 (SIGSEGV) after 802.444294 sec$
[20-Dec-2011 17:30:07.914240] NOTICE: pid 12514, fpm_children_make(), line 404: [pool domain1.de] child 23772 started
[20-Dec-2011 18:31:41.348715] DEBUG: pid 12514, fpm_got_signal(), line 76: received SIGCHLD
[20-Dec-2011 18:31:41.348794] WARNING: pid 12514, fpm_children_bury(), line 252: [pool domain1.de] child 19061 exited with code 1 after 9017.410122 seconds from $
[20-Dec-2011 18:31:41.349628] NOTICE: pid 12514, fpm_children_make(), line 404: [pool domain1.de] child 26936 started
[20-Dec-2011 18:35:10.705744] DEBUG: pid 12514, fpm_got_signal(), line 76: received SIGCHLD
[20-Dec-2011 18:35:10.705808] WARNING: pid 12514, fpm_children_bury(), line 252: [pool domain1.de] child 22616 exited with code 1 after 5233.760997 seconds from $
[20-Dec-2011 18:35:10.706535] NOTICE: pid 12514, fpm_children_make(), line 404: [pool domain1.de] child 27121 started
[20-Dec-2011 18:35:45.418159] DEBUG: pid 12514, fpm_got_signal(), line 76: received SIGCHLD
[20-Dec-2011 18:35:45.418241] WARNING: pid 12514, fpm_children_bury(), line 252: [pool domain1.de] child 23445 exited on signal 11 (SIGSEGV) after 4320.960475 se$
[20-Dec-2011 18:35:45.419035] NOTICE: pid 12514, fpm_children_make(), line 404: [pool domain1.de] child 27124 started
 
Merkwürdiges Phänomenen, konnte ich bei mir mit php-fpm aus debian wheezy bisher nicht beobachten.
 
Ich hab mir das jetzt noch einmal genauer angeschaut. Zum Zeitpunkt des 500er wird in der php5-fpm.log nichts geloggt. Dabei steht das Logging sogar auf Debug.

Error Log von lighttpd sagt zu dessen Zeitpunkt ebenfalls nichts. So langsam gehen mir die Ideen aus...
 
Hm? lighttpd wirft 500er aus, aber loggt dazu nix? Kannst du das loglevel beim lighty auch erhöhen?
 
Geloggt wird lediglich die Auslieferung der 500er Seite im Access Log.

Eine Option für ein höheres Log Level habe ich jetzt nicht gefunden, bin nur auf folgende debug Optionen für lighttpd (Core) gestoßen:

http://redmine.lighttpd.net/wiki/1/DebugVariables

Meinst du, die Aktivierung dieser Optionen würde zu etwas nennenswertes führen? Ich denke ja, dies ist mehr ein PHP FPM Problem, wo ich das Logging bereits auf Debug gestellt habe.
 
Last edited by a moderator:
Keine Ahnung, dazu habe ich zuwenig Erfahrung mit lighty. Schreibt er denn auch nix in die errorlog? Müsste er doch eigentlich, irgendeinen Grund wird der 500er ja haben.
 
Ich habe jetzt mal in lighttpd "fastcgi.debug" aktiviert. Folgendes findet sich anschließend gefühlt tausendfach in der Error Datei wieder:

Code: 
2011-12-21 21:02:43: (mod_fastcgi.c.3061) got proc: pid: 0 socket: unix:/var/run/lighttpd/kunde-domain.de-php-fpm.socket load: 1
2011-12-21 21:02:43: (mod_fastcgi.c.1492) released proc: pid: 0 socket: unix:/var/run/lighttpd/kunde-domain.de-php-fpm.socket load: 0
2011-12-21 21:02:43: (mod_fastcgi.c.3061) got proc: pid: 0 socket: unix:/var/run/lighttpd/kunde-domain.de-php-fpm.socket load: 2
2011-12-21 21:02:43: (mod_fastcgi.c.1492) released proc: pid: 0 socket: unix:/var/run/lighttpd/kunde-domain.de-php-fpm.socket load: 1
2011-12-21 21:02:43: (mod_fastcgi.c.1492) released proc: pid: 0 socket: unix:/var/run/lighttpd/kunde-domain.de-php-fpm.socket load: 0
2011-12-21 21:02:44: (mod_fastcgi.c.3061) got proc: pid: 0 socket: unix:/var/run/lighttpd/kunde-domain.de-php-fpm.socket load: 1
2011-12-21 21:02:44: (mod_fastcgi.c.1492) released proc: pid: 0 socket: unix:/var/run/lighttpd/kunde-domain.de-php-fpm.socket load: 0

Ansonsten wird nichts geloggt.
 
Die php.ini bitte so anpassen und PHP-FPM neu starten:

Code: 
error_reporting = E_ALL & ~E_DEPRECATED
display_errors = Off
display_startup_errors = Off
log_errors = On
log_errors_max_len = 1024
ignore_repeated_errors = Off
ignore_repeated_source = Off
report_memleaks = On
track_errors = Off
html_errors = Off
error_log = /var/log/php_errors.log
 
Vor dem Umstieg auf FPM ist der Fehler nie aufgetreten. Von daher gehe ich eigentlich von einem Fehler bei FPM aus, auch wenn es so gesehen eigentlich nicht sein kann.

Hier mal die aktuelle lighttpd Konfiguration:

Code: 
var.basedir  = "/var/www"
var.logdir   = "/var/log/lighttpd"
var.statedir = "/var/lib/lighttpd"

server.modules = (
        "mod_rewrite",
        "mod_redirect",
        "mod_alias",
        "mod_access",
        "mod_auth",
        "mod_fastcgi",
        "mod_cgi",
        "mod_accesslog",
)
#server.max-worker = 4
server.username      = "www-data"
server.groupname     = "www-data"
server.document-root = var.basedir
server.pid-file      = "/var/run/lighttpd.pid"
accesslog.filename   = var.logdir + "/access.log"
server.errorlog      = var.logdir  + "/error.log"

server.indexfiles    = ("index.php", "index.html",
                                                "index.htm", "default.htm")

server.name                      = "HOSTNAME"
server.port          = 80
server.bind          = "IP"
url.access-deny = ("~", ".inc")


#### external configuration files
## mimetype mapping
include_shell "/usr/share/lighttpd/create-mime.assign.pl"
include_shell "cat /etc/lighttpd/conf-enabled/*.conf"
 
You must log in or register to reply here.
Back
Top