Bug #52312 [Opn->Bgs]: PHP lstat problem

From: Date: Mon, 12 Jul 2010 11:49:39 +0000
Subject: Bug #52312 [Opn->Bgs]: PHP lstat problem
References: 1  Groups: php.bugs 
Request: Send a blank email to php-bugs+get-152289@lists.php.net to get a copy of this message
Edit report at http://bugs.php.net/bug.php?id=52312&edit=1

 ID:               52312
 Updated by:       rasmus@php.net
 Reported by:      v dot damore at gmail dot com
 Summary:          PHP lstat problem
-Status:           Open
+Status:           Bogus
 Type:             Bug
 Package:          Safe Mode/open_basedir
 Operating System: Linux
 PHP Version:      5.2.13

 New Comment:

There is a realpath cache that gets populated, so you need to warm up
the cache 
and not strace the first request.  You shouldn't care that the first
request to 
the server takes a few more stats.  The real test is whether subsequent
requests 
are slow.  If you are seeing excessive stats with the caches warmed up,
then you 
need to investigate the size of your realpath cache in your php.ini and
possibly 
increase it.  This part has been made more efficient in PHP 5.3.

It would also be a good idea to turn off AllowOverride in your Apache
config to 
get rid of the .htaccess stats if you are concerned about the number of
stat 
calls.

So, do this.  

Start Apache in non-forking mode by running it with -X

Then hit a simple hello_world.php script a few times.  Don't use phpinfo
because 
it does a number of evil things on its own.  After hitting your hello
world 
script a couple of times, attach strace to the Apache process (strace -p
<pid>) 
and then hit the server again once.  At this point you should not see
any extra 
stats.


Previous Comments:
------------------------------------------------------------------------
[2010-07-12 10:03:42] v dot damore at gmail dot com

Description:
------------
PHP lstat full pathname many times (at least 4) before read the file is
looking for.
This behavior appear when in apache httpd configuration is specified
PHP_ADMIN_VALUE open_basedir or safe_mode is On.

Test script:
---------------
To reproduce the problem please create a page phpinfo.php: "<? phpinfo()
?>".

I have httpd.2.2.15, PHP 5.2.13.

[root@svilpar4 ~]# /usr/local/apache2/bin/httpd -V
Server version: Apache/2.2.15 (Unix)
Server built:   Jul  9 2010 17:30:06
Server's Module Magic Number: 20051115:24
Server loaded:  APR 1.2.7, APR-Util 1.2.7
Compiled using: APR 1.2.7, APR-Util 1.2.7
Architecture:   64-bit
Server MPM:     Prefork
  threaded:     no
    forked:     yes (variable process count)
Server compiled with....
 -D APACHE_MPM_DIR="server/mpm/prefork"
 -D APR_HAS_SENDFILE
 -D APR_HAS_MMAP
 -D APR_HAVE_IPV6 (IPv4-mapped addresses enabled)
 -D APR_USE_SYSVSEM_SERIALIZE
 -D APR_USE_PTHREAD_SERIALIZE
 -D SINGLE_LISTEN_UNSERIALIZED_ACCEPT
 -D APR_HAS_OTHER_CHILD
 -D AP_HAVE_RELIABLE_PIPED_LOGS
 -D DYNAMIC_MODULE_LIMIT=128
 -D HTTPD_ROOT="/usr/local/apache2"
 -D SUEXEC_BIN="/usr/local/apache2/bin/suexec"
 -D DEFAULT_PIDLOG="logs/httpd.pid"
 -D DEFAULT_SCOREBOARD="logs/apache_runtime_status"
 -D DEFAULT_LOCKFILE="logs/accept.lock"
 -D DEFAULT_ERRORLOG="logs/error_log"
 -D AP_TYPES_CONFIG_FILE="conf/mime.types"
 -D SERVER_CONFIG_FILE="conf/httpd.conf"

[root@svilpar4 ~]# /usr/local/php5.2.13/bin/php -v
PHP 5.2.13 (cli) (built: Jul  1 2010 16:02:03) 
Copyright (c) 1997-2010 The PHP Group
Zend Engine v2.2.0, Copyright (c) 1998-2010 Zend Technologies

Now we specify PHP_ADMIN_VALUE open_basedir</strong> in Virtual host
configuration:

<Directory "/usr/local/myspace/webspace/httpdocs">
                PHP_ADMIN_VALUE open_basedir
"/usr/local/myspace/webspace"
</Directory>
<VirtualHost *:80>
        ServerName damorealt.xoom.it
        DocumentRoot "/usr/local/myspace/webspace/httpdocs"
    CustomLog   /var/log/httpd/damorealt/access_log   combined
    ErrorLog   /var/log/httpd/damorealt/error_log
</VirtualHost >

Stop & start apache httpd, "strace -f" all httpd instances and then call
page http://damorealt.xoom.it/phpinfo.php, so we
can reproduce behavior


Expected result:
----------------
If PHP_ADMIN_VALUE open_basedir "/usr/local/myspace/webspace" is removed
and safe_mode is Off :

226235 accept(3, {sa_family=AF_INET, sin_port=htons(59366),
sin_addr=inet_addr("212.48.14.186")}, [17179869200]) = 15
26235 getsockname(15, {sa_family=AF_INET, sin_port=htons(80),
sin_addr=inet_addr("151.99.197.198")}, [17179869200]) = 0
26235 fcntl(15, F_GETFL)                = 0x2 (flags O_RDWR)
26235 fcntl(15, F_SETFL, O_RDWR|O_NONBLOCK) = 0
26235 read(15, "GET /phpinfo.php HTTP/1.0\r\nUser-"..., 8000) = 129
26235 gettimeofday({1278696735, 988799}, NULL) = 0
26235 stat("/usr/local/myspace/webspace/httpdocs/phpinfo.php",
{st_mode=S_IFREG|0644, st_size=16, ...}) = 0
26235 open("/usr/local/myspace/.htaccess", O_RDONLY) = -1 ENOENT (No
such file or directory)
26235 open("/usr/local/myspace/webspace/.htaccess", O_RDONLY) = -1
ENOENT (No such file or directory)
26235 open("/usr/local/myspace/webspace/httpdocs/.htaccess", O_RDONLY) =
-1 ENOENT (No such file or directory)
26235 open("/usr/local/myspace/webspace/httpdocs/phpinfo.php/.htaccess",
O_RDONLY) = -1 ENOTDIR (Not a directory)
26235 setitimer(ITIMER_PROF, {it_interval={0, 0}, it_value={20, 0}},
NULL) = 0
26235 rt_sigaction(SIGPROF, {0x2afef587dd80, [PROF],
SA_RESTORER|SA_RESTART, 0x3916e302d0}, {SIG_DFL, [], 0}, 8) = 0
26235 rt_sigprocmask(SIG_UNBLOCK, [PROF], NULL, 8) = 0
26235 getcwd("/"..., 4095)              = 2
26235 chdir("/usr/local/myspace/webspace/httpdocs") = 0

water boiling point

26235 time(NULL)                        = 1278696735
26235 lstat("/usr", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
26235 lstat("/usr/local", {st_mode=S_IFDIR|0755, st_size=4096, ...}) =
0
26235 lstat("/usr/local/myspace", {st_mode=S_IFDIR|0755, st_size=4096,
...}) = 0
26235 lstat("/usr/local/myspace/webspace", {st_mode=S_IFDIR|0755,
st_size=4096, ...}) = 0
26235 lstat("/usr/local/myspace/webspace/httpdocs",
{st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
26235 lstat("/usr/local/myspace/webspace/httpdocs/phpinfo.php",
{st_mode=S_IFREG|0644, st_size=16, ...}) = 0

And read the file.

26235 open("/usr/local/myspace/webspace/httpdocs/phpinfo.php", O_RDONLY)
= 16
26235 fstat(16, {st_mode=S_IFREG|0644, st_size=16, ...}) = 0
26235 read(16, "<? phpinfo() ?>\n", 8192) = 16
26235 read(16, "", 8192)                = 0
26235 read(16, "", 8192)                = 0
26235 close(16)                         = 0
26235 uname({sys="Linux", node="svilpar4", ...}) = 0
26235 time(NULL)                        = 1278696735
26235 writev(15, [{"HTTP/1.1 200 OK\r\nDate: Fri, 09 J"..., 173},
{"<!DOCTYPE html PUBLIC \"-//W3C//D"..., 4109}, {"<table
border=\"0\"
cellpadding=\"3"..., 4101}], 3) = 8383
26235 writev(15, [{"<tr><td class=\"e\">highlight.bg</"...,
4105},
{"sendmail_from</td><td class=\"v\">"..., 4099}], 2) = 8204
26235 time(NULL)                        = 1278696735
26235 writev(15, [{" </td></tr>\n<tr><td
class=\"e\">HT"..., 4108},
{"</td><td class=\"v\">1024</td><td "..., 4098}], 2) = 8206
26235 writev(15, [{"md2 md4 md5 sha1 sha256 sha384 s"..., 4098}, {"
</td></tr>\n</table><br />\n<tabl"..., 4106}], 2) = 8204
26235 writev(15, [{"session.use_cookies</td><td clas"..., 4104}, {"
</td><td class=\"v\">enabled </td"..., 4102}], 2) = 8206
26235 chdir("/")                        = 0
26235 setitimer(ITIMER_PROF, {it_interval={0, 0}, it_value={0, 0}},
NULL) = 0
26235 writev(15, [{"\"]</td><td class=\"v\">Keep-Alive<"...,
4206}], 1)
= 4206
26235 write(10, "212.48.14.186 - - [09/Jul/2010:1"..., 116) = 116
26235 shutdown(15, 1 /* send */)        = 0
26235 poll([{fd=15, events=POLLIN}], 1, 2000) = 1 ([{fd=15,
revents=POLLIN|POLLHUP}])
26235 read(15, "", 512)                 = 0
26235 close(15)                         = 0
26235 read(4, 0x7fff615ff5eb, 1)        = -1 EAGAIN (Resource
temporarily unavailable)
26235 accept(3, 


Actual result:
--------------
If PHP_ADMIN_VALUE open_basedir "/usr/local/myspace/webspace" is set and
safe_mode is On :

25933 accept(3, {sa_family=AF_INET, sin_port=htons(47433),
sin_addr=inet_addr("212.48.14.186")}, [17179869200]) = 15
25933 getsockname(15, {sa_family=AF_INET, sin_port=htons(80),
sin_addr=inet_addr("151.99.197.198")}, [17179869200]) = 0
25933 fcntl(15, F_GETFL)                = 0x2 (flags O_RDWR)
25933 fcntl(15, F_SETFL, O_RDWR|O_NONBLOCK) = 0
25933 read(15, "GET /phpinfo.php HTTP/1.0\r\nUser-"..., 8000) = 129
25933 gettimeofday({1278695388, 52976}, NULL) = 0
25933 stat("/usr/local/myspace/webspace/httpdocs/phpinfo.php",
{st_mode=S_IFREG|0644, st_size=16, ...}) = 0
25933 open("/usr/local/myspace/.htaccess", O_RDONLY) = -1 ENOENT (No
such file or directory)
25933 open("/usr/local/myspace/webspace/.htaccess", O_RDONLY) = -1
ENOENT (No such file or directory)
25933 open("/usr/local/myspace/webspace/httpdocs/.htaccess", O_RDONLY) =
-1 ENOENT (No such file or directory)
25933 open("/usr/local/myspace/webspace/httpdocs/phpinfo.php/.htaccess",
O_RDONLY) = -1 ENOTDIR (Not a directory)
25933 setitimer(ITIMER_PROF, {it_interval={0, 0}, it_value={20, 0}},
NULL) = 0
25933 rt_sigaction(SIGPROF, {0x2b80442fdd80, [PROF],
SA_RESTORER|SA_RESTART, 0x3916e302d0}, {SIG_DFL, [], 0}, 8) = 0
25933 rt_sigprocmask(SIG_UNBLOCK, [PROF], NULL, 8) = 0
25933 getcwd("/"..., 4095)              = 2
25933 chdir("/usr/local/myspace/webspace/httpdocs") = 0

water boiling point

25933 lstat("/usr", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
25933 lstat("/usr/local", {st_mode=S_IFDIR|0755, st_size=4096, ...}) =
0
25933 lstat("/usr/local/myspace", {st_mode=S_IFDIR|0755, st_size=4096,
...}) = 0
25933 lstat("/usr/local/myspace/webspace", {st_mode=S_IFDIR|0755,
st_size=4096, ...}) = 0
25933 lstat("/usr/local/myspace/webspace/httpdocs",
{st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
25933 lstat("/usr/local/myspace/webspace/httpdocs/phpinfo.php",
{st_mode=S_IFREG|0644, st_size=16, ...}) = 0

First check

25933 lstat("/usr", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
25933 lstat("/usr/local", {st_mode=S_IFDIR|0755, st_size=4096, ...}) =
0
25933 lstat("/usr/local/myspace", {st_mode=S_IFDIR|0755, st_size=4096,
...}) = 0
25933 lstat("/usr/local/myspace/webspace", {st_mode=S_IFDIR|0755,
st_size=4096, ...}) = 0
25933 lstat("/usr/local/myspace/webspace/httpdocs",
{st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
25933 lstat("/usr/local/myspace/webspace/httpdocs/phpinfo.php",
{st_mode=S_IFREG|0644, st_size=16, ...}) = 0

Second check

25933 lstat("/usr", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
25933 lstat("/usr/local", {st_mode=S_IFDIR|0755, st_size=4096, ...}) =
0
25933 lstat("/usr/local/myspace", {st_mode=S_IFDIR|0755, st_size=4096,
...}) = 0
25933 lstat("/usr/local/myspace/webspace", {st_mode=S_IFDIR|0755,
st_size=4096, ...}) = 0

Third check (incomplete)

25933 lstat("/usr", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
25933 lstat("/usr/local", {st_mode=S_IFDIR|0755, st_size=4096, ...}) =
0
25933 lstat("/usr/local/myspace", {st_mode=S_IFDIR|0755, st_size=4096,
...}) = 0
25933 lstat("/usr/local/myspace/webspace", {st_mode=S_IFDIR|0755,
st_size=4096, ...}) = 0
25933 lstat("/usr/local/myspace/webspace/httpdocs",
{st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
25933 lstat("/usr/local/myspace/webspace/httpdocs/phpinfo.php",
{st_mode=S_IFREG|0644, st_size=16, ...}) = 0

Final check and then read the file.

25933 open("/usr/local/myspace/webspace/httpdocs/phpinfo.php", O_RDONLY)
= 16
25933 fstat(16, {st_mode=S_IFREG|0644, st_size=16, ...}) = 0
25933 read(16, "<? phpinfo() ?>\n", 8192) = 16
25933 read(16, "", 8192)                = 0
25933 read(16, "", 8192)                = 0
25933 close(16)                         = 0



------------------------------------------------------------------------



-- 
Edit this bug report at http://bugs.php.net/bug.php?id=52312&edit=1


Thread (64 messages)

« previous php.bugs (#152289) next »