PHP :: Bug #54612 :: random Error 404

Bug #54612

random Error 404

Submitted:

2011-04-27 16:37 UTC

Modified:

2014-12-30 10:41 UTC

Votes:	2
Avg. Score:	4.0 ± 1.0
Reproduced:	1 of 1 (100.0%)
Same Version:	0 (0.0%)
Same OS:	1 (100.0%)

From:

erno dot kovacs at freemail dot hu

Assigned:

Status:

No Feedback

Package:

Scripting Engine problem

PHP Version:

5.3.6

OS:

Linux

Private report:

CVE-ID:

None

View Developer Edit

[2011-04-27 16:37 UTC] 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.

Patches

Pull Requests

History

AllCommentsChangesGit/SVN commitsRelated reports

[2011-04-29 10:01 UTC] erno dot kovacs at freemail dot hu

Workarounds:
cgi.fix_pathinfo = 0
OR
using nginx and sending "correct" SCRIPT_FILENAME parameter

[2011-07-02 11:32 UTC] fat@php.net

-Status: Open +Status: Assigned -Assigned To: +Assigned To: fat

[2011-07-05 17:30 UTC] fat@php.net

-Status: Assigned +Status: Feedback

[2011-07-05 17:30 UTC] fat@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-09-07 15:13 UTC] 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-09-07 15:47 UTC] 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 16:28 UTC] 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-10-08 14:31 UTC] fat@php.net

-Status: Feedback +Status: Assigned

[2011-10-08 14:33 UTC] fat@php.net

-Summary: FPM+chroot: random Error 404 +Summary: random Error 404 -Status: Assigned +Status: Open -Package: FPM related +Package: Scripting Engine problem -Assigned To: fat +Assigned To:

[2011-10-08 14:33 UTC] fat@php.net

This is not related to FPM. 

I move this bug to core.

[2013-10-24 08:00 UTC] yohgaki@php.net

-Status: Open +Status: Feedback

[2013-10-24 08:00 UTC] yohgaki@php.net

Do you still have problem with 5.4 or later?

[2014-12-30 10:41 UTC] php-bugs at lists dot php dot net

No feedback was provided. The bug is being suspended because
we assume that you are no longer experiencing the problem.
If this is not the case and you are able to provide the
information that was requested earlier, please do so and
change the status of the bug back to "Re-Opened". Thank you.

	php.net \| support \| documentation \| report a bug \| advanced search \| search howto \| statistics \| random bug \| login
go to bug id or search bugs for


Copyright © 2001-2024 The PHP Group All rights reserved.	Last updated: Sun Dec 22 06:01:30 2024 UTC