php.net |  support |  documentation |  report a bug |  advanced search |  search howto |  statistics |  random bug |  login
Bug #63413 Intermittent warning and fatal error on require() statement
Submitted: 2012-11-01 17:04 UTC Modified: 2012-11-01 21:07 UTC
Votes:12
Avg. Score:4.3 ± 0.9
Reproduced:9 of 11 (81.8%)
Same Version:5 (55.6%)
Same OS:8 (88.9%)
From: ben at indietorrent dot org Assigned:
Status: Open Package: Scripting Engine problem
PHP Version: 5.4.8 OS: Windows 7 x64
Private report: No CVE-ID: None
Have you experienced this issue?
Rate the importance of this bug to you:

 [2012-11-01 17:04 UTC] ben at indietorrent dot org
Description:
------------
I observe erratic behavior relating to require() statements. The files that are being required are static (they are not created or destroyed during script execution), so there should be no reason that they are required successfully the vast majority of the time, but fail to be required some small percentage of the time.

It bears mention that I am also wrapping the calls to require() in calls to file_exists(). It seems that while file_exists() always returns true (the require() statements are always executed), the calls to require() fail intermittently with "PHP Warning: Unknown: failed to open stream: No such file or directory" and then "PHP Fatal error: Unknown: Failed opening required".

The symptoms of this issue are very similar to those described in https://bugs.php.net/bug.php?id=49012 ("Spurious fatal error on require() statement"), but I don't know whether the root cause is the same or not.

I have confirmed that this problem occurs on several different computers, no two of which have the exact same OS or *AMP stack component versions. For this reason, I do not believe this issue to be due to failing hardware, a corrupt operating system, or similar.

I should note also that in PHP 5.2 and 5.3, the offending line number was always zero (0). Unless line number zero has some special meaning in PHP, this seems like a bug in itself. In any case, in PHP 5.4.8, the line number is non-zero *usually* (but not always), and seems to be accurate. (I have not tested with any PHP version before 5.2 or between 5.3 and 5.4.8.)

I have not installed any third-party extensions and am using a pristine 5.4.8 installation. PHP is running via Apache's mod_php module. php.ini is relatively untouched; the only changes I made were to enable some of the modules that are disabled by default (I can list them if it's relevant).

Unfortunately, I am unable to reproduce this issue at will, because it occurs completely sporadically.

That said, the problem occurs quite frequently, so, if a developer is able to provide specific debugging instructions, it should be easy enough for me to capture the relevant information. By "quite frequently", I mean every couple of minutes during normal browsing.

Also, I have used Firefox's handy "Reload Tab Every..." context menu feature to reload an affected page every 1 second for 10 minutes straight and the issue occurred only twice. This seems to indicate that the issue does not necessarily occur some percentage of the time (+/- variance), but rather, it occurs when more complex conditions are met. For whatever reason, the issue occurs most frequently when I make several concurrent requests to the affected URLs/files, and I navigate to various URLs before each page has loaded fully.

Strangely enough, if I let the auto-refresh test run long enough (this run, it took more than 30 minutes of refreshing every second), the specific error messages change (the location of the failed require statements change), but their nature is always the same: failed require() statements due to variations of "file not found".

Also, the issue seems most likely to occur when the Web-server (Apache in this case) has been sitting idle for some period of time (e.g., 10 or more minutes). Oftentimes, if I have been away from the computer and refresh an affected page when I return, the issue occurs. Could this behavior point to memory managment or caching?

The code-base that causes this issue is shared across several different production websites, all of which run on various GNU/Linux distributions. With Ubuntu 10.04 + Apache 2.2.14 + mod_php + PHP 5.3.2, I do not observe the issue at all. On another identically-configured server, the only difference being Fast-CGI (fcgid) instead of mod_php, I do observe the issue, but its manifestation is slightly different than on Windows with mod_php. (I'm happy to provide details regarding the differences.)

I find it particularly strange that the messages and specific points of failure change over time. The first log entry (made only a few seconds after Apache was started) makes no sense; there is no file mentioned, and the line number is zero:

--------------------
[29-Oct-2012 15:30:29 America/New_York] PHP Warning:  Unknown: failed to open stream: No such file or directory in Unknown on line 0
--------------------

At least the related fatal error mentions a file:

--------------------
[29-Oct-2012 15:30:29 America/New_York] PHP Fatal error:  Unknown: Failed opening required 'C:/Users/Ben/Documents/Apache/project/public/auxiliary/css.php' (include_path='.;C:\Program Files\php\includes;C:\Program Files\php\PEAR\pear') in Unknown on line 0
--------------------

The next time the warning/fatal occurs, we have a file AND a line number:

--------------------
[29-Oct-2012 15:31:19 America/New_York] PHP Warning:  require(../include/global.inc.php): failed to open stream: No such file or directory in C:\Users\Ben\Documents\Projects\project Testing\project-svn\trunk\public\auxiliary\css.php on line 5

[29-Oct-2012 15:31:19 America/New_York] PHP Fatal error:  require(): Failed opening required '../include/global.inc.php' (include_path='.;C:\Program Files\php\includes;C:\Program Files\php\PEAR\pear') in C:\Users\Ben\Documents\Projects\project Testing\project-svn\trunk\public\auxiliary\css.php on line 5
--------------------

I mean... what, does PHP need to "warm-up"?

This warning/fatal sequence carries-on for some minutes, and then the error (provided this is indeed the same root-cause) morphs slightly:

--------------------
[29-Oct-2012 15:34:07 America/New_York] PHP Fatal error:  Uncaught exception 'SmartyException' with message 'Unable to load template file 'C:/Users/Ben/Documents/Apache/project/protected/templates\css/global.css'' in C:\Users\Ben\Documents\Projects\project Testing\project-svn\trunk\protected\common\libs\php-classes\external\Smarty-3.1.11\libs\sysplugins\smarty_internal_templatebase.php:127
Stack trace:
#0 C:\Users\Ben\Documents\Projects\project Testing\project-svn\trunk\protected\common\libs\php-classes\external\Smarty-3.1.11\libs\sysplugins\smarty_internal_templatebase.php(374): Smarty_Internal_TemplateBase->fetch('C:/Users/Ben/Do...', NULL, NULL, NULL, true)
#1 C:\Users\Ben\Documents\Projects\project Testing\project-svn\trunk\public\auxiliary\css.php(75): Smarty_Internal_TemplateBase->display('C:/Users/Ben/Do...')
#2 {main}
  thrown in C:\Users\Ben\Documents\Projects\project Testing\project-svn\trunk\protected\common\libs\php-classes\external\Smarty-3.1.11\libs\sysplugins\smarty_internal_templatebase.php on line 127
--------------------

After this point, the errors don't change again.

I have discussed this issue at length on the Smarty forums ( http://www.smarty.net/forums/viewtopic.php?t=23591 ) and the Smarty authors pointed-out that Smarty throws the above exception when a call to filemtime($templateSourceFile) returns FALSE (Smarty does not bother to read the file's contents when filemtime() returns FALSE).

So, we have erroneous failures when require() is called, coupled with erroneous failures when filemtime() is called.

The path from the above log excerpts, "C:/Users/Ben/Documents/Apache/project", is an NFTS junction point that resolves to "C:\Users\Ben\Documents\Projects\project Testing\project-svn\trunk". I'm not sure that this is relevant, because the errors occur regardless of which path I use in the calls to require(), but it deserves mention in light of https://bugs.php.net/bug.php?id=39484 ("intermittent include failure under symlinked virtual hosts").


Patches

Add a Patch

Pull Requests

Add a Pull Request

History

AllCommentsChangesGit/SVN commitsRelated reports
 [2012-11-01 21:07 UTC] ben at indietorrent dot org
It occurred to me to examine Apache's internal error log for entries that correspond to those in PHP's error log when this occurs. I noticed what may be an important clue.

Sample entries in PHP's error log:

-----------------------
[01-Nov-2012 13:29:41 America/New_York] PHP Warning:  require(../include/global.inc.php): failed to open stream: No such file or directory in C:\Users\Ben\Documents\Projects\project Testing\project-svn\trunk\public\auxiliary\css.php on line 5

[01-Nov-2012 13:29:41 America/New_York] PHP Fatal error:  require(): Failed opening required '../include/global.inc.php' (include_path='.;C:\Program Files\php\includes;C:\Program Files\php\PEAR\pear') in C:\Users\Ben\Documents\Projects\project Testing\project-svn\trunk\public\auxiliary\css.php on line 5

[01-Nov-2012 13:29:43 America/New_York] PHP Warning:  require(C:/Users/Ben/Documents/Apache/project/protected/constants.inc.php): failed to open stream: No such file or directory in C:\Users\Ben\Documents\Projects\project Testing\project-svn\trunk\public\include\global.inc.php on line 18

[01-Nov-2012 13:29:43 America/New_York] PHP Fatal error:  require(): Failed opening required 'C:/Users/Ben/Documents/Apache/project/protected/constants.inc.php' (include_path='.;C:\Program Files\php\includes;C:\Program Files\php\PEAR\pear') in C:\Users\Ben\Documents\Projects\project Testing\project-svn\trunk\public\include\global.inc.php on line 18
-----------------------

Roughly-corresponding entries in Apache's error log:

-----------------------
[Thu Nov 01 13:29:21.235844 2012] [core:error] [pid 6780:tid 1136] (OS 32)The process cannot access the file because it is being used by another process.  : [client 10.0.1.57:65162] AH00127: Cannot map GET /project/public/js/jquery.accordion.js HTTP/1.1 to file, referer: https://ben-pc/project/public/company/history/
[Thu Nov 01 13:29:41.141441 2012] [core:error] [pid 6780:tid 1128] (OS 32)The process cannot access the file because it is being used by another process.  : [client 10.0.1.57:65204] AH00127: Cannot map GET /project/public/common/js/libs/modernizr-2.5.3.min.js HTTP/1.1 to file, referer: https://ben-pc/project/public/contact/service-inquiry/
-----------------------

While I don't see any direct correlation between the files cited in PHP's error log and those cited in Apache's error log, the message "(OS 32)The process cannot access the file because it is being used by another process" seems very relevant to the observed behavior in PHP.

This observation inspired me to create a very simple test script which, much to my surprise, enables me to produce this issue at will. I was able to reproduce the issue in Windows' Safe Mode, too, which seems to eliminate virus scanners, filter drivers, and other similar causes.

The key to reproducing this issue is making as many requests per unit of time as possible. In other words, holding-down the browser's refresh key (e.g., Ctrl+R or F5) for some period of time eventually causes require() failures to be logged.

Here's the script:

<?php

$file = 'C:/Users/Ben/Documents/Apache/require-test-include.php';

$counter = 0;

while ($counter < 500) {
	require($file);
	
	flush();
	
	$counter++;
}

?>

The contents of "require-test-include.php" are probably largely irrelevant, but I'm using the following:

<?php

echo '.';

?>

A sample excerpt from PHP's error log contains entries such as the following:

-----------------------
[01-Nov-2012 16:01:53 America/New_York] PHP Warning:  require(C:/Users/Ben/Documents/Apache/require-test-include.php): failed to open stream: No such file or directory in C:\Users\Ben\Documents\Apache\require-test.php on line 8

[01-Nov-2012 16:01:53 America/New_York] PHP Fatal error:  require(): Failed opening required 'C:/Users/Ben/Documents/Apache/require-test-include.php' (include_path='.;C:\Program Files\php\includes;C:\Program Files\php\PEAR\pear') in C:\Users\Ben\Documents\Apache\require-test.php on line 8
-----------------------

Apache's error log fills-up with entries such as the following (I've included six lines to demonstrate the timestamp variances):

-----------------------
[Thu Nov 01 15:59:02.327506 2012] [core:error] [pid 4420:tid 1040] (OS 32)The process cannot access the file because it is being used by another process.  : [client 10.0.1.57:62710] AH00127: Cannot map GET /require-test.php HTTP/1.1 to file
[Thu Nov 01 15:59:02.389509 2012] [core:error] [pid 4420:tid 1040] (OS 32)The process cannot access the file because it is being used by another process.  : [client 10.0.1.57:62710] AH00127: Cannot map GET /require-test.php HTTP/1.1 to file
[Thu Nov 01 15:59:02.954339 2012] [core:error] [pid 4420:tid 748] (OS 32)The process cannot access the file because it is being used by another process.  : [client 10.0.1.57:62740] AH00127: Cannot map GET /require-test.php HTTP/1.1 to file
[Thu Nov 01 15:59:03.093347 2012] [core:error] [pid 4420:tid 748] (OS 32)The process cannot access the file because it is being used by another process.  : [client 10.0.1.57:62747] AH00127: Cannot map GET /require-test.php HTTP/1.1 to file
[Thu Nov 01 15:59:03.491370 2012] [core:error] [pid 4420:tid 948] (OS 32)The process cannot access the file because it is being used by another process.  : [client 10.0.1.57:62768] AH00127: Cannot map GET /require-test.php HTTP/1.1 to file
[Thu Nov 01 15:59:03.758385 2012] [core:error] [pid 4420:tid 1040] (OS 32)The process cannot access the file because it is being used by another process.  : [client 10.0.1.57:62776] AH00127: Cannot map GET /require-test.php HTTP/1.1 to file
-----------------------

It is worth noting that requesting a "normal" page from one of my PHP applications and then switching to this test script immediately thereafter, and hammering on it with F5, dramatically increases the number of failed require() occurrences. Conversely, if I hammer on the above script only (and don't browse to other application URLs on localhost), the frequency of the require() failures is reduced to only a few per several thousand requests.

As a final point of note, when the file that is passed to require() references an NTFS junction point (created with "mklink.exe /J"), require() performance is degraded noticeably (expected, perhaps), which makes this issue easier to reproduce. This observation may be at the root of https://bugs.php.net/bug.php?id=39484 ("intermittent include failure under symlinked virtual hosts").

How can one feel confident in deploying a PHP application that is guaranteed to be under a heavy load when this type of problem exists? Even if "this is not a bug", per se, the fact that this scenario is not handled more gracefully (either in PHP or Apache) is disconcerting, to say the least.
 [2012-11-05 15:45 UTC] ben at indietorrent dot org
Another update.

I began to suspect that this is a thread-safety issue, so I downloaded the latest non-thread-safe version of PHP and configured Apache to serve PHP files via Fast-CGI (mod_fcgid).

To my surprise, this problem still occurs, and it seems to be worse with Fast-CGI than with Mod-PHP.

Also, I tried to reproduce the problem on a Mac with Mac OS 10.8 and a fairly modern MAMP installation that runs PHP via Mod-PHP. No matter how hard I hammered on Apache, these spurious require() failures did not occur.
 [2012-11-16 16:29 UTC] ben at indietorrent dot org
Additional testing indicates that this problem is likely related to a specific piece of software that has been installed on the affected machines, and not PHP or the manner in which it is integrated with Apache.

I tested the steps-to-reproduce with the exact same project/code-base on a LAMP stack (Ubuntu 12.04 + Apache 2.2.22 + MySQL 5.5.24 + PHP 5.3.10) and cannot reproduce the issue, no matter how hard I hammer the server with requests.

As mentioned previously, I am unable to reproduce this issue with a comparable stack on Mac OS 10.8, either.

These facts pointed to a Windows-specific cause, perhaps related to Apache's "winnt" MPM, so I setup a VM with a pristine Windows 7 x86 installation. I installed the same stack components as are installed on the computers on which this issue occurs. Yet, after several hours of hammering the server with constant page-requests, not a single error has been registered in PHP's error log.

If at any point I'm able to determine which software causes this issue, I will post my findings here.
 [2013-02-13 17:34 UTC] giunta dot gaetano at gmail dot com
A behaviour which has been puzzling me and that might (or not) be related: we also have some failing code which assumes that filemtime should not be zero (for an existing file). This is generally happening on Linux servers at customers (php in mode_prefork), at times of high load, for nfs-mounted files
 [2013-02-14 10:11 UTC] giunta dot gaetano at gmail dot com
Btw, did some testing on my rig: win7 64bit, apache 2.4.3/vc10 from Apache Lounge, php 5.3.20/vc9.

Using the test scripts provided above, and "ab" hitting them 100 times in a row with concurrency ranging from 1 to 64.

When no NTFS junctions in use => no sign of errors whatsoever

When an NTFS junction in use => one or two php errors do happen, across the whole test (127k requests).

NB: just accessing the main file over the junction is ok. The problems happen then the "require" call is for a file over in the junction-ed directory
 [2013-02-18 15:51 UTC] ben at indietorrent dot org
@giunta dot gaetano at gmail dot com:

I can't thank you enough; your insightful comments reveal the "missing link": NTFS junction points. I didn't think they were relevant until reading your comments.

In my comment dated [2012-11-16 16:29 UTC], I stated that I setup a virtual machine with the same WAMP stack components that are installed on the "problem" machines, but that I was unable to reproduce the problem. Well, I forgot to configure the site-root as an NTFS junction point in those tests.

As soon as I changed the site-root from a regular directory to an NTFS function point, I was able to reproduce the problem almost immediately.

As stated in my previous comments, concurrency seems to be a factor in how likely the failures are to occur. Unfortunately, this fact may point to a race-condition.

It seems safe to say that include() and require() do not perform reliably across NTFS junction points.

Whether or not the same root cause is behind the NFS problems on Linux remains to be seen.
 [2016-04-29 17:29 UTC] jan dot bouvrie at gmail dot com
I think I bumped into this one too, this time on PHP 5.6.20 running on Windows 8.1 x64. However, in my case I've observed a Windows NTFS Directory Junction on a remote filesystem, mapped over a Samba Share to resolve to the 'wrong' realpath(), potentially mapping a remote file to the local machine's filesystem. This could perhaps be a vulnerability.

Since this case relies heavily on a client-server architecture, I created a .cmd script to reproduce this testcase. Essence of the test is that PHP's realpath() will resolve links to remote filesystem to the equivalent location on the local filesystem instead.

-----------------------
Steps to reproduce:
-----------------------
0. Have seperate Windows Client and Server machines on the same LAN with Samba share enabled.

1. On each PC, Create dir C:\JUNC_test
2. On each PC, Create attached files debug.cmd and debug.php in C:\JUNC_test dir.

3. On PC 1 (server), start elevated commandprompt, CD C:\JUNC_test and run "debug.cmd". These tests will pass as all references point to the local machine.

4. On PC 2 (client), start elevated commandprompt, CD C:\JUNC_test. This time, run "debug.cmd <SERVERNAME>", where <SERVERNAME> is PC1's hostname.

The reason for the debug.cmd and elevated privileges, is that it will create the test environment with symlinks, create share, map drive, and remove it as well. Afterwards, just remove the C:\JUNC_test dir.

-----------------------------
What to look for (on PC2):
-----------------------------

TESTING: NORMAL_DIR will work fine on both PC 2 (both point to their respective local or mapped regular files)
TESTING: DIRSYMLINK will probably not work on PC 2, as Windows by default has remote symlink disabled. Observe however that even though file_exists returns false, file_get_contents of the file _does_ work. The shell 'type' command doesn't yield anything.
TESTING: DIRJUNCTION ON J will conflict on PC 2, its realpath() will instead follow the Junction to PC 2' local filesystem, and open its file instead. Note that opening the dirjunction's file in other Windows applications correctly resolve the remote file as intended behavior.


-----------------------
The testcase files:
-----------------------

###### debug.php START: #######
<?php
foreach (array('C:\\JUNC_test\\','J:\\') as $dir)
if (is_dir($dir))
foreach (scandir($dir)as $entry)
{
	if (!in_array($entry,array('.','..','debug.cmd','debug.php'))&& $entry=$dir.$entry)
	{
		$file=$entry.'\\file.php';
		echo 'TESTING: '.basename($entry).' on '.$dir[0].":\n";

		$result=array(	'path'=>$file,
						'path_file_exists'=>file_exists($file),
						'path_shell_exec'=>exec('type "'.$file.'"'),
						'path_get_contents'=>trim(file_get_contents($file)),
						'realpath'=>realpath($file),
						'realpath_file_exists'=>file_exists(realpath($file)),
						'realpath_shell_exec'=>exec('type "'.realpath($file).'"'),
						'realpath_get_contents'=>trim(file_get_contents(realpath($file))),
			);
		var_dump($result);
		echo 'include '.$file.' result:';
		include($file);
		echo PHP_EOL.PHP_EOL;
	}
}
die();
?>
###### debug.php END. #######


###### debug.cmd START: #######
@echo off
SETLOCAL ENABLEDELAYEDEXPANSION
cls
SET PHP_EXE=PHP.EXE
WHERE php.exe 2>nul 1>&2
if not %errorLevel% == 0 (	SET PHP_EXE=C:\XAMPP\PHP\PHP.EXE
				if not exist !PHP_EXE! goto ERROR
			)
if not exist C:\JUNC_test\debug.php goto ERROR

rem check for admin rights 
net session >nul 2>&1
if not %errorLevel% == 0 goto ERROR
if not exist C:\JUNC_test\NORMAL_DIR MD C:\JUNC_test\NORMAL_DIR
rem 1. prepare filesystem for test in C:\JUNC_test folder
rem Creating linked directory and file.
echo ^<php echo '%COMPUTERNAME% file OK';^>> C:\JUNC_test\NORMAL_DIR\file.php

if not "%1"=="" (
	echo %COMPUTERNAME% connecting as client to server %~1...
	echo Mapping share to J: letter
	@NET USE J: /D 2>NUL 1>&2
	NET USE J: \\%~1\JUNC_test_Share
	call :RUNTEST
	echo Test complete. 

	echo Unmapping J drive on client:
	NET USE J: /D 2>NUL 1>&2
) else (
	echo Using %COMPUTERNAME% as server for the tests...

	echo Creating Directory Junction:
	mklink /J C:\JUNC_test\DIRJUNCTION C:\JUNC_test\NORMAL_DIR
	echo Creating symbolic link:
	mklink /D C:\JUNC_test\DIRSYMLINK C:\JUNC_test\NORMAL_DIR


	rem 2. Share C:\JUNC_test folder on the network and map to J: letter
	rem
	echo Sharing C:\JUNC_test dir:
	NET SHARE JUNC_test_Share=C:\JUNC_test /UNLIMITED

	echo Mapping share to letter J:
	@NET USE J: /D 2>NUL 1>&2
	NET USE J: \\%COMPUTERNAME%\JUNC_test_Share
	echo.
	echo Press any key to start test on this ^(server^) PC...
	@pause>nul
	call :RUNTEST
	echo.
	echo See the results above. All files should be acessible ^(true^) and reference "%COMPUTERNAME%". To finish the testcase, please use a second PC and run the following
	echo command: debug.cmd "%COMPUTERNAME%" 
	echo.
	echo After that, press any key to remove the share and mapped J:...
	@pause
	NET USE J: /DELETE
	NET SHARE JUNC_test_Share /DELETE
	RD C:\JUNC_test\DIRSYMLINK
	RD C:\JUNC_test\DIRJUNCTION
)
goto END

:RUNTEST
	echo Windows host SymlinkEvaluation Settings:
	echo ---------------------------------------
	fsutil behavior query SymlinkEvaluation
	echo.
	echo Show the folders:
	echo -----------------
	DIR C:\JUNC_test /ad
	DIR J:\ /ad
	echo.
	echo Run PHP testcode:
	echo -----------------
        call !PHP_EXE! -v
        call !PHP_EXE! -n debug.php
goto :EOF

:ERROR
	echo ERROR:
	echo This script should be run from commandline, placed alongside debug.php in C:\JUNC_test
	echo Also, you must run this script with admin rights in order to perform the test!
	echo Finally, make sure PHP.exe is installed and in your path, or edit the PHP_EXE variable in debug.cmd
	echo.
	@pause
goto END

:END
if exist C:\JUNC_test\NORMAL_DIR\file.php DEL /F/Q C:\JUNC_test\NORMAL_DIR\file.php
if exist C:\JUNC_test\NORMAL_DIR RD C:\JUNC_test\NORMAL_DIR
ENDLOCAL
###### debug.cmd START: #######
 
PHP Copyright © 2001-2019 The PHP Group
All rights reserved.
Last updated: Sun Jul 21 11:01:25 2019 UTC