Edit report at https://bugs.php.net/bug.php?id=54612&edit=1
ID: 54612
Updated by: f...@php.net
Reported by: erno dot kovacs at freemail dot hu
Summary: FPM+chroot: random Error 404
-Status: Feedback
+Status: Assigned
Type: Bug
Package: FPM related
Operating System: Linux
PHP Version: 5.3.6
Assigned To: fat
Block user comment: N
Private report: N
Previous Comments:
------------------------------------------------------------------------
[2011-09-07 16:28:41] erno dot kovacs at freemail dot hu
php_resolve_path is being called with the correct filename, which is
/web/web/xxxxxx/index.php this time, and at the tsrm_realpath() call and then
it fails somewhere in virtual_file_ex, where it failes at this block:
add_slash = (use_realpath != CWD_REALPATH) && path_length > 0 &&
IS_SLASH(resolved_path[path_length-1]);
t = CWDG(realpath_cache_ttl) ? 0 : -1;
path_length = tsrm_realpath_r(resolved_path, start, path_length, &ll,
&t, use_realpath, 0, NULL TSRMLS_CC);
if (path_length < 0) {
errno = ENOENT;
mydebug("VFEX FAILURE #444");
return 1;
}
i dont want to dig any deeper, please give me some hints.
------------------------------------------------------------------------
[2011-09-07 15:47:50] erno dot kovacs at freemail dot hu
Added a few lines of dummy debug info into fopen_wrappers's
php_fopen_primary_script, and when it fails, it fails at
zend_resolve_path(), which returns NULL.
------------------------------------------------------------------------
[2011-09-07 15:13:24] erno dot kovacs at freemail dot hu
got the same issue on another box (debian lenny this time, not squeeze) with
php 5.3.8, here are the logs:
when its ok:
# strace -s 1024 -p 27057
Process 27057 attached - interrupt to quit
accept(0, {sa_family=AF_INET, sin_port=htons(47532),
sin_addr=inet_addr("127.0.0.1")}, [16]) = 4
clock_gettime(CLOCK_MONOTONIC, {67474521, 156597098}) = 0
time(NULL) = 1315407924
times({tms_utime=37, tms_stime=14, tms_cutime=0, tms_cstime=0}) = -123996470
poll([{fd=4, events=POLLIN}], 1, 5000) = 1 ([{fd=4, revents=POLLIN}])
read(4, "\1\1\0\1\0\10\0\0"..., 8) = 8
read(4, "\0\1\0\0\0\0\0\0"..., 8) = 8
read(4, "\1\4\0\1\3\2\0\0"..., 8) = 8
read(4,
"\17\17SERVER_SOFTWARElighttpd/1.4.29\v\nSERVER_NAMExxxxxx.com\21\7GATEWAY_INTERFACECGI/1.1\v\5SERVER_PORT50001\v\fSERVER_ADDR217.13.99.87\v\5REMOTE_PORT51194\v\fREMOTE_ADDR80.98.95.222\v\nSCRIPT_NAME/index.php\t\0PATH_INFO\17\31SCRIPT_FILENAME/web/web/xxxxxx/index.php\r\20DOCUMENT_ROOT/web/web/xxxxxx/\v\1REQUEST_URI/\f\0QUERY_STRING\16\3REQUEST_METHODGET\17\3REDIRECT_STATUS200\17\10SERVER_PROTOCOLHTTP/1.1\t\20HTTP_HOSTxxxxxx.com:50001\17JHTTP_USER_AGENTMozilla/5.0
(Windows NT 6.1; WOW64; rv:6.0.1) Gecko/20100101
Firefox/6.0.1\v?HTTP_ACCEPTtext/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8\24#HTTP_ACCEPT_LANGUAGEhu-hu,hu;q=0.8,en-us;q=0.5,en;q=0.3\24\rHTTP_ACCEPT_ENCODINGgzip,
deflate\23\36HTTP_ACCEPT_CHARSETISO-8859-2,utf-8;q=0.7,*;q=0.7\10\1HTTP_DNT1\17\nHTTP_CONNECTIONkeep-alive\22\tHTTP_CACHE_CONTROLmax-age=0"...,
770) = 770
read(4, "\1\4\0\1\0\0\0\0"..., 8) = 8
clock_gettime(CLOCK_MONOTONIC, {67474521, 161587774}) = 0
time(NULL) = 1315407924
setitimer(ITIMER_PROF, {it_interval={0, 0}, it_value={60, 0}}, NULL) = 0
rt_sigaction(SIGPROF, {0x8229650, [PROF], SA_RESTART}, {0x8229650, [PROF],
SA_RESTART}, 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [PROF], NULL, 8) = 0
time(NULL) = 1315407924
lstat64("/web/web/xxxxxx/index.php", {st_mode=S_IFREG|0644, st_size=7076, ...})
= 0
lstat64("/web/web/xxxxxx", {st_mode=S_IFDIR|0755, st_size=108, ...}) = 0
lstat64("/web/web", {st_mode=S_IFLNK|0777, st_size=1, ...}) = 0
readlink("/web/web", "/"..., 4096) = 1
open("/xxxxxx/index.php", O_RDONLY) = 5
fstat64(5, {st_mode=S_IFREG|0644, st_size=7076, ...}) = 0
clock_gettime(CLOCK_MONOTONIC, {67474521, 168395023}) = 0
getcwd("/"..., 4095) = 2
chdir("/web/web/xxxxxx") = 0
setitimer(ITIMER_PROF, {it_interval={0, 0}, it_value={120, 0}}, NULL) = 0
ioctl(5, SNDCTL_TMR_TIMEBASE or TCGETS, 0xbfa293b8) = -1 ENOTTY (Inappropriate
ioctl for device)
fstat64(5, {st_mode=S_IFREG|0644, st_size=7076, ...}) = 0
mmap2(NULL, 7108, PROT_READ, MAP_PRIVATE, 5, 0) = 0xb5168000
fstat64(5, {st_mode=S_IFREG|0644, st_size=7076, ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) =
0xb5167000
_llseek(5, 0, [0], SEEK_CUR) = 0
munmap(0xb5168000, 7076) = 0
close(5) = 0
munmap(0xb5167000, 4096) = 0
chdir("/") = 0
clock_gettime(CLOCK_MONOTONIC, {67474521, 176554306}) = 0
times({tms_utime=38, tms_stime=14, tms_cutime=0, tms_cstime=0}) = -123996468
write(4, "\1\6\0\1\0229\7\0Content-type: text/html\r\n\r\n<!DOCTYPE html PUBLIC
\"-//W3C//DTD XHTML 1.0 Transitional//EN\"
\"http://www.w3.org/TR/xhtml1/DTD/xhtml1-transitional.dtd\";>\r\n<html
xmlns=\"http://www.w3.org/1999/xhtml\";>\r\n<head>\r\n<meta
http-equiv=\"Content-Type\" content=\"text/html; charset=iso-8859-2\"
/>\r\n<title>xxxxxx.com</title>\r\n<style
type=\"text/css\">\r\n<!--\r\nbody,td,th {\r\n\tfont-family: Arial, Helvetica,
sans-serif;\r\n\tfont-size: 12px;\r\n\tcolor: #000000;\r\n}\r\nbody
{\r\n\tbackground-color: #FFFFFF;\r\n\tcolor: #000000;\r\n\tmargin-left:
0px;\r\n\tmargin-top: 0px;\r\n\tmargin-right: 0px;\r\n\tmargin-bottom:
0px;\r\n}\r\na:link {\r\n\tcolor: #000000;\r\n}\r\na:visited {\r\n\tcolor:
#000000;\r\n}\r\na:hover {\r\n\tcolor: #000000;\r\n}\r\na:active {\r\n\tcolor:
#000000;\r\n}\r\na {\r\n\tfont-family: Arial, Helvetica,
sans-serif;\r\n\tfont-size: 12px;\r\n}\r\ndiv.title
{\r\n\tbackground-color:#1543A5;\r\n\theight:109px;\r\n}\r\n\r\ndiv.content
{\r\n\tmargin-left:50px;\r\n\tmargin-right:50px;\r\n}\r\n\r\ndiv.message
{\r\n\ttext-align:center;\r\n\theight:50px;\r\n}\r\n\r\ndiv.form
{\r\n\twidth:400px;\r\n\tmargin:auto;\r\n\ttext-align:center"..., 4696) = 4696
shutdown(4, 1 /* send */) = 0
recv(4, "\1\5\0\1\0\0\0\0"..., 8, 0) = 8
recv(4, ""..., 8, 0) = 0
close(4) = 0
clock_gettime(CLOCK_MONOTONIC, {67474521, 181188404}) = 0
setitimer(ITIMER_PROF, {it_interval={0, 0}, it_value={0, 0}}, NULL) = 0
clock_gettime(CLOCK_MONOTONIC, {67474521, 182245449}) = 0
when its 404:
accept(0, {sa_family=AF_INET, sin_port=htons(47694),
sin_addr=inet_addr("127.0.0.1")}, [16]) = 4
clock_gettime(CLOCK_MONOTONIC, {67474603, 177424184}) = 0
time(NULL) = 1315408006
times({tms_utime=3, tms_stime=2, tms_cutime=0, tms_cstime=0}) = -123988268
poll([{fd=4, events=POLLIN}], 1, 5000) = 1 ([{fd=4, revents=POLLIN}])
read(4, "\1\1\0\1\0\10\0\0"..., 8) = 8
read(4, "\0\1\0\0\0\0\0\0"..., 8) = 8
read(4, "\1\4\0\1\0037\0\0"..., 8) = 8
read(4,
"\17\17SERVER_SOFTWARElighttpd/1.4.29\v\tSERVER_NAMExxxxxx.com\21\7GATEWAY_INTERFACECGI/1.1\v\5SERVER_PORT50001\v\fSERVER_ADDR217.13.99.88\v\5REMOTE_PORT51234\v\fREMOTE_ADDR80.98.95.222\v\nSCRIPT_NAME/index.php\t\0PATH_INFO\17\31SCRIPT_FILENAME/web/web/xxxxxx/index.php\r\20DOCUMENT_ROOT/web/web/xxxxxx/\v\1REQUEST_URI/\f\0QUERY_STRING\16\3REQUEST_METHODGET\17\3REDIRECT_STATUS200\17\10SERVER_PROTOCOLHTTP/1.1\t\17HTTP_HOSTxxxxxx.com:50001\17JHTTP_USER_AGENTMozilla/5.0
(Windows NT 6.1; WOW64; rv:6.0.1) Gecko/20100101
Firefox/6.0.1\v?HTTP_ACCEPTtext/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8\24#HTTP_ACCEPT_LANGUAGEhu-hu,hu;q=0.8,en-us;q=0.5,en;q=0.3\24\rHTTP_ACCEPT_ENCODINGgzip,
deflate\23\36HTTP_ACCEPT_CHARSETISO-8859-2,utf-8;q=0.7,*;q=0.7\v*HTTP_COOKIEPHPSESSID=4c227cf6957666996f470742c77ef6df\10\1HTTP_DNT1\17\nHTTP_CONNECTIONkeep-alive\22\tHTTP_CACHE_CONTROLmax-age=0"...,
823) = 823
read(4, "\1\4\0\1\0\0\0\0"..., 8) = 8
clock_gettime(CLOCK_MONOTONIC, {67474603, 182194605}) = 0
time(NULL) = 1315408006
setitimer(ITIMER_PROF, {it_interval={0, 0}, it_value={60, 0}}, NULL) = 0
rt_sigaction(SIGPROF, {0x8229650, [PROF], SA_RESTART}, {0x8229650, [PROF],
SA_RESTART}, 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [PROF], NULL, 8) = 0
time(NULL) = 1315408006
lstat64("/web/web/xxxxxx/index.php", {st_mode=S_IFREG|0644, st_size=210, ...})
= 0
lstat64("/web/web/xxxxxx", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
clock_gettime(CLOCK_MONOTONIC, {67474603, 186697702}) = 0
times({tms_utime=3, tms_stime=2, tms_cutime=0, tms_cstime=0}) = -123988267
write(4, "\1\6\0\1\0K\5\0Status: 404 Not Found\r\nContent-type:
text/html\r\n\r\nNo input file
specified.\n\0\0\0\0\0\1\3\0\1\0\10\0\0\0\0\0\0\0tp:"..., 104) = 104
shutdown(4, 1 /* send */) = 0
recv(4, "\1\5\0\1\0\0\0\0"..., 8, 0) = 8
recv(4, ""..., 8, 0) = 0
close(4) = 0
clock_gettime(CLOCK_MONOTONIC, {67474603, 191688504}) = 0
setitimer(ITIMER_PROF, {it_interval={0, 0}, it_value={0, 0}}, NULL) = 0
clock_gettime(CLOCK_MONOTONIC, {67474603, 192740671}) = 0
strangely, cgi.fix_pathinfo = 0 doesnt affect the behaviour this time.
------------------------------------------------------------------------
[2011-07-05 17:30:51] f...@php.net
Not enough information was provided for us to be able
to handle this bug. Please re-read the instructions at
http://bugs.php.net/how-to-report.php
If you can provide more information, feel free to add it
to this bug and change the status back to "Open".
Thank you for your interest in PHP.
can you please catch the content of the request made from your webserver
(lighthttpd or nginx) to FPM.
You can use the strace command you used but just add -s 1024 or something big
in
order to ensure to see what FPM reads from the socket.
You can also use tcpdump
tcpdump -i any -s 0 -X dst port 9001
IMO the tcpdump option is the easier to implement.
------------------------------------------------------------------------
[2011-04-29 10:01:38] erno dot kovacs at freemail dot hu
Workarounds:
cgi.fix_pathinfo = 0
OR
using nginx and sending "correct" SCRIPT_FILENAME parameter
------------------------------------------------------------------------
The remainder of the comments for this report are too long. To view
the rest of the comments, please view the bug report online at
https://bugs.php.net/bug.php?id=54612
--
Edit this bug report at https://bugs.php.net/bug.php?id=54612&edit=1
