Edit report at https://bugs.php.net/bug.php?id=54612&edit=1
ID: 54612
Comment by: erno dot kovacs at freemail dot hu
Reported by: erno dot kovacs at freemail dot hu
Summary: FPM+chroot: random Error 404
Status: Feedback
Type: Bug
Package: FPM related
Operating System: Linux
PHP Version: 5.3.6
Assigned To: fat
Block user comment: N
Private report: N
New Comment:
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.
Previous Comments:
------------------------------------------------------------------------
[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
------------------------------------------------------------------------
[2011-04-27 16:37:36] erno dot kovacs at freemail dot hu
Description:
------------
Debian squeze:
# uname -a
Linux xxx 2.6.32-5-amd64 #1 SMP Mon Mar 7 21:35:22 UTC 2011 x86_64 GNU/Linux
Lighty 1.4.28 with fastcgi config lines:
fastcgi.server = ( ".php" =>
(
(
"host" => "127.0.0.1",
"port" => 9001
)
)
)
# ls -l /web/web/host/web/web/host
lrwxrwxrwx 1 root root 1 Apr 26 15:10 /web/web/host/web/web/host -> /
Docroot is:
/web/web/host/teszdomain.hu/pages
If I turn on chroot to /web/web/host in the fpm config, PHP starts dropping
error 404 randomly:
Process 26491 attached - interrupt to quit
accept(0, {sa_family=AF_INET, sin_port=htons(57968),
sin_addr=inet_addr("127.0.0.1")}, [16]) = 3
poll([{fd=3, events=POLLIN}], 1, 5000) = 1 ([{fd=3, revents=POLLIN}])
read(3, "\1\1\0\1\0\10\0\0", 8) = 8
read(3, "\0\1\0\0\0\0\0\0", 8) = 8
read(3, "\1\4\0\1\3`\0\0", 8) = 8
read(3, "\17\17SERVER_SOFTWARElighttpd/1.4.28"..., 864) = 864
read(3, "\1\4\0\1\0\0\0\0", 8) = 8
lstat("/web/web/host/tesztdomain.hu/pages/x.php", {st_mode=S_IFREG|0644,
st_size=102, ...}) = 0
lstat("/web/web/host/tesztdomain.hu/pages", {st_mode=S_IFDIR|0755,
st_size=4096, ...}) = 0
lstat("/web/web/host/tesztdomain.hu", {st_mode=S_IFDIR|0755, st_size=29, ...})
= 0
stat("/web/web/host/tesztdomain.hu/pages", {st_mode=S_IFDIR|0755, st_size=4096,
...}) = 0
stat("/web/web/host/tesztdomain.hu", {st_mode=S_IFDIR|0755, st_size=29, ...}) = 0
stat("/web/web/host", {st_mode=S_IFDIR|0111, st_size=4096, ...}) = 0
stat("/web/web", {st_mode=S_IFDIR|0755, st_size=17, ...}) = 0
stat("/web", {st_mode=S_IFDIR|0755, st_size=16, ...}) = 0
stat("", 0x7fffc3463110) = -1 ENOENT (No such file or directory)
setitimer(ITIMER_PROF, {it_interval={0, 0}, it_value={60, 0}}, NULL) = 0
rt_sigaction(SIGPROF, {0x664e20, [PROF], SA_RESTORER|SA_RESTART,
0x7f04f9d7e1e0}, {0x664e20, [PROF], SA_RESTORER|SA_RESTART, 0x7f04f9d7e1e0}, 8)
= 0
rt_sigprocmask(SIG_UNBLOCK, [PROF], NULL, 8) = 0
write(3, "\1\6\0\1\0002\6\0Status: 404 Not Found\r\nC"..., 80) = 80
shutdown(3, 1 /* send */) = 0
recvfrom(3, "\1\5\0\1\0\0\0\0", 8, 0, NULL, NULL) = 8
recvfrom(3, "", 8, 0, NULL, NULL) = 0
close(3) = 0
setitimer(ITIMER_PROF, {it_interval={0, 0}, it_value={0, 0}}, NULL) = 0
accept(0, ^C <unfinished ...>
Process 26491 detached
And sometimes it works just fine:
Process 26491 attached - interrupt to quit
accept(0, {sa_family=AF_INET, sin_port=htons(59088),
sin_addr=inet_addr("127.0.0.1")}, [16]) = 3
poll([{fd=3, events=POLLIN}], 1, 5000) = 1 ([{fd=3, revents=POLLIN}])
read(3, "\1\1\0\1\0\10\0\0", 8) = 8
read(3, "\0\1\0\0\0\0\0\0", 8) = 8
read(3, "\1\4\0\1\3`\0\0", 8) = 8
read(3, "\17\17SERVER_SOFTWARElighttpd/1.4.28"..., 864) = 864
read(3, "\1\4\0\1\0\0\0\0", 8) = 8
lstat("/web/web/host/tesztdomain.hu/pages/x.php", {st_mode=S_IFREG|0644,
st_size=102, ...}) = 0
lstat("/web/web/host/tesztdomain.hu/pages", {st_mode=S_IFDIR|0755,
st_size=4096, ...}) = 0
lstat("/web/web/host/tesztdomain.hu", {st_mode=S_IFDIR|0755, st_size=29, ...})
= 0
lstat("/web/web/host", {st_mode=S_IFLNK|0777, st_size=1, ...}) = 0
readlink("/web/web/host", "/"..., 4096) = 1
stat("/web/web/host/tesztdomain.hu/pages/.user.ini", 0x7fffc3460aa0) = -1
ENOENT (No such file or directory)
setitimer(ITIMER_PROF, {it_interval={0, 0}, it_value={60, 0}}, NULL) = 0
rt_sigaction(SIGPROF, {0x664e20, [PROF], SA_RESTORER|SA_RESTART,
0x7f04f9d7e1e0}, {0x664e20, [PROF], SA_RESTORER|SA_RESTART, 0x7f04f9d7e1e0}, 8)
= 0
rt_sigprocmask(SIG_UNBLOCK, [PROF], NULL, 8) = 0
open("/tesztdomain.hu/pages/x.php", O_RDONLY) = 4
fstat(4, {st_mode=S_IFREG|0644, st_size=102, ...}) = 0
getcwd("/", 4095) = 2
chdir("/web/web/host/tesztdomain.hu/pages") = 0
setitimer(ITIMER_PROF, {it_interval={0, 0}, it_value={120, 0}}, NULL) = 0
ioctl(4, SNDCTL_TMR_TIMEBASE or TCGETS, 0x7fffc345e850) = -1 ENOTTY
(Inappropriate ioctl for device)
fstat(4, {st_mode=S_IFREG|0644, st_size=102, ...}) = 0
mmap(NULL, 134, PROT_READ, MAP_PRIVATE, 4, 0) = 0x7f04fd5cf000
fstat(4, {st_mode=S_IFREG|0644, st_size=102, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) =
0x7f04fd5ce000
lseek(4, 0, SEEK_CUR) = 0
munmap(0x7f04fd5cf000, 102) = 0
close(4) = 0
munmap(0x7f04fd5ce000, 4096) = 0
uname({sys="Linux", node="xxx", ...}) = 0
write(3, "\1\6\0\1\37\370\0\0Content-type: text/html\r"..., 8192) = 8192
write(3, "\1\6\0\1\37\370\0\0=\"v\">Off</td></tr>\n<tr><"..., 8192) = 8192
write(3, "\1\6\0\1\37\370\0\0<td class=\"e\">y2k_compli"..., 8192) = 8192
write(3, "\1\6\0\1\37\370\0\0 cellpadding=\"3\" width=\""..., 8192) = 8192
write(3, "\1\6\0\1\37\370\0\0d><td class=\"v\">100</td>"..., 8192) = 8192
chdir("/") = 0
write(3, "\1\6\0\1\30\353\5\0s=\"e\">_REQUEST[\"PHPSESSI"..., 6408) = 6408
shutdown(3, 1 /* send */) = 0
recvfrom(3, "\1\5\0\1\0\0\0\0", 8, 0, NULL, NULL) = 8
recvfrom(3, "", 8, 0, NULL, NULL) = 0
close(3) = 0
setitimer(ITIMER_PROF, {it_interval={0, 0}, it_value={0, 0}}, NULL) = 0
accept(0, ^C <unfinished ...>
Note, I run PHP-FPM with the same chroot+symlink trick on other box and it
works fine all the time.
------------------------------------------------------------------------
--
Edit this bug report at https://bugs.php.net/bug.php?id=54612&edit=1
