Smarty Forum Index Smarty
The discussions here are for Smarty, a template engine for the PHP programming language.

Intermittent warning and fatal error on require() statement

 
Post new topic   Reply to topic    Smarty Forum Index -> General
View previous topic :: View next topic  
Author Message
cbj4074
Smarty Regular


Joined: 10 Nov 2011
Posts: 49

PostPosted: Mon Oct 29, 2012 9:05 pm    Post subject: Intermittent warning and fatal error on require() statement Reply with quote

Smarty 3.1.11
PHP 5.4.8
Apache 2.4

I don't know whether this is a problem with PHP or with Smarty, but it seems to occur only with sites that leverage Smarty.

The symptoms of this issue are exactly as described in https://bugs.php.net/bug.php?id=49012 , but I don't know whether the root cause is the same or not (several major revisions later and different operating system platform).

I should note also that in PHP 5.2 and 5.3, the offending line number was always zero (0). 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.

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.

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 (different files that are require()d throughout the script -- but always the same parent file), but their nature is always the same: failed require() statements due to "file not found".

I lack hard data to back-up this assertion but 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.

The code-base that causes this issue is shared across several different production websites, all of which run on various GNU/Linux distributions, and I have never observed the problem on any of those servers. I thought that the problem might be Windows-specific, or even specific to my workstation, but bug report https://bugs.php.net/bug.php?id=49012 feels very similar (if not the same).

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) and to install xdebug.

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:

Code:

[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:

Code:

[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:

Code:

[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:

Code:

[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 don't know what else to try or what other information to provide.

Any thoughts here, folks?

Thanks for any help; this has been driving me nuts for about 18 months, across several different Smarty versions, several different PHP versions, and several different Apache versions.
Back to top
View user's profile Send private message
cbj4074
Smarty Regular


Joined: 10 Nov 2011
Posts: 49

PostPosted: Tue Oct 30, 2012 4:10 pm    Post subject: Reply with quote

I've spent even more time with this and everything about this behavior screams, "race condition!"

What is the file that begins with "wrt" that is written to the templates_c directory and then deleted almost immediately?

Cursory examination of the source code indicates that it's a temporary location to which template data is written before the completed file is renamed in a pseudo-atomic way.

This logic (from Smarty_Internal_Write_File::writeFile()) seems like the perfect candidate for a race-condition:

Code:

/*
 * Windows' rename() fails if the destination exists,
 * Linux' rename() properly handles the overwrite.
 * Simply unlink()ing a file might cause other processes
 * currently reading that file to fail, but linux' rename()
 * seems to be smart enough to handle that for us.
 */
if (Smarty::$_IS_WINDOWS) {
   // remove original file
   @unlink($_filepath);
   // rename tmp file
   $success = @rename($_tmp_file, $_filepath);
} else {
   // rename tmp file
   $success = @rename($_tmp_file, $_filepath);
   if (!$success) {
      // remove original file
      @unlink($_filepath);
      // rename tmp file
      $success = @rename($_tmp_file, $_filepath);
   }
}


Smarty is deleting the original file and then moving the new file into its place. The comments even imply that the potential for a race-condition exists on Windows platforms: "Simply unlink()ing a file might cause other processes currently reading that file to fail..." And that's exactly what I'm seeing.

This theory explains why I see the Smarty exceptions most frequently when I hammer on several different pages simultaneously, all of which contain concurrent calls to the CSS wrapper script.

Further research into atomic renaming on Windows indicates that doing so is not possible before Windows Vista or Windows Server 2008: http://stackoverflow.com/questions/167414/is-an-atomic-file-rename-with-overwrite-possible-on-windows .

Disappointing. And alarming, really.

So, are we just #$%&@! until PHP implements atomic renaming for Windows platforms that support it?
Back to top
View user's profile Send private message
U.Tews
Administrator


Joined: 22 Nov 2006
Posts: 5068
Location: Hamburg / Germany

PostPosted: Tue Oct 30, 2012 9:57 pm    Post subject: Reply with quote

All your error messages are not related to the windows rename issue in Smarty_Internal_Write_File::writeFile().

It looks more like a problem with the file system.
Your first error messages indicates the PHP include files could not be read.

The Smarty exception is thrown because the template source global.css could not be accessed.

All of this is really strange.
Back to top
View user's profile Send private message
cbj4074
Smarty Regular


Joined: 10 Nov 2011
Posts: 49

PostPosted: Wed Oct 31, 2012 5:44 pm    Post subject: Reply with quote

Hi, U.Tews, thank you very much for your response. I'm grateful to have your expertise and assistance.

I'm stating the most important part first: I have confirmed that this occurs on different computers. Initially, I noticed this on my work computer, and assumed that it was specific to this workstation. After reading your reply, I decided that no one was likely to help me unless I had evidence to suggest that this is not an isolated, fringe case.

The second computer (my home computer) is a different OS architecture (x86), has different versions of every WAMP stack component, and yet this problem happens there, too! Granted, I setup both computers, so maybe there is something in each environment that causes this problem, but even if that is so, I still feel that this is a "bug", either with Smarty or with PHP. I need to be able to rule-out one or the other, though, so I can report the bug to the appropriate development team.

Additional Background:

Some time ago, I considered that the disk or filesystem may be damaged, but I ruled-out that possibility after performing extensive testing. Windows' built-in disk-check utility does not find anything wrong with the filesystem. I also ran the manufacturer's utility (Western Digital's Data Lifeguard Diagnostics for Windows), which does not find anything wrong. S.M.A.R.T. status is green across the board, and the "Extended Test" yields no errors. Also, I observe no anomalous behavior in any other area of operation on this computer.

I have disabled real-time virus scanning on the relevant portions of the filesystem and the behavior does not change.

I have tried removing the source code from version control (I use TortoiseSVN) to ensure that tsvncache.exe is not interfering in any way, but the behavior persists.

Furthermore, the errors are entirely reproducible. They always follow the same pattern. That is to say, when I restart Apache and begin hammering on the website's homepage (using Firefox's automatic refresh feature), the error messages follow a very specific progression (as outlined in my original post).

Also, this seems to happen only with specific files: the CSS and JS wrapper scripts that I use to send template-driven CSS and JS to the browser.

What's more, I have several sites that use the same code-base and this problem occurs with all of them. The various sites exist in different locations on the filesystem, so it seems unlikely that damage to a specific location on the hard disk or filesystem is the cause.

We're talking about a website with hundreds of PHP files, hundreds of templates, hundreds of PHP classes, etc., yet this problem seems to affect very specific files. As mentioned previously, the content of the Smarty templates (for the CSS files) does not seem to matter, as every site that exhibits this problem has different CSS file content.
Back to top
View user's profile Send private message
U.Tews
Administrator


Joined: 22 Nov 2006
Posts: 5068
Location: Hamburg / Germany

PostPosted: Wed Oct 31, 2012 6:14 pm    Post subject: Reply with quote

Your arror messages for C:/Users/Ben/Documents/Apache/project/public/auxiliary/css.php or require(../include/global.inc.php) are not related to Smarty at all. These are errors while your PHP script file does try to include other PHP files.

The Smarty exception related to ...../templates\css/global.css does indicate that Smarty could not access the template file.

I'm pretty sure that these problems are not related to Smarty and have no idea how I could help you.
Back to top
View user's profile Send private message
cbj4074
Smarty Regular


Joined: 10 Nov 2011
Posts: 49

PostPosted: Wed Oct 31, 2012 7:43 pm    Post subject: Reply with quote

Thanks again for the reply, U.Tews. I understand your position. I don't expect further replies, but I may as well document the issue as thoroughly as possible.

This is one of the most ridiculous phenomenons I've observed in my 15 years of Web development.

So, not only does this occur on a second computer, but the pattern of the PHP error log entries is the same on both computers. More specifically, if Apache has been running for some period of time (e.g., 6+ minutes), the "at line 0" messages disappear, and this message is repeated indefinitely (but the CSS or JS template name ["home-content.js" in this excerpt] varies):

Code:

[31-Oct-2012 18:02:06 UTC] PHP Fatal error:  Uncaught exception 'SmartyException' with message 'Unable to load template file 'D:/My Documents/Apache/sq/protected/templates\js/home-content.js'' in D:\My Documents\Projects\project\trunk\protected\common\libs\php-classes\external\Smarty-3.1.11\libs\sysplugins\smarty_internal_templatebase.php:127
Stack trace:
#0 D:\My Documents\Projects\project\trunk\protected\common\libs\php-classes\external\Smarty-3.1.11\libs\sysplugins\smarty_internal_templatebase.php(374): Smarty_Internal_TemplateBase->fetch('D:/My Documents...', NULL, NULL, NULL, true)
#1 D:\My Documents\Projects\project\trunk\public\auxiliary\js.php(71): Smarty_Internal_TemplateBase->display('D:/My Documents...')
#2 {main}
  thrown in D:\My Documents\Projects\project\trunk\protected\common\libs\php-classes\external\Smarty-3.1.11\libs\sysplugins\smarty_internal_templatebase.php on line 127


Now, it's not as though "home-content.js" doesn't exist on the filesystem. If the file didn't exist, the page wouldn't load without issue the vast majority of the time.

It seems clear that the files intermittently "disappear", as ridiculous as that may sound. And the issue does not seem to be a read-lock or permission issue, because I'm quite sure that PHP includes "permission denied" (or something to similar effect) when the file exists but cannot be read.

The only conclusion to be drawn is that PHP's file_exists() method is failing to return accurate results. Under what circumstances might this happen? Let's see...

This application "stats" the filesystem in several places. (Probably) not coincidentally, I call file_exists() on the CSS (and JS) template files in question shortly before calling $smarty->fetch() or $smarty->display(). I do this because this application is built to include files if they exist and ignore them if not.

The "warm-up" behavior (that is, the error messages changing after about 6 minutes from the time Apache is started), coupled with the completely erratic nature of the error occurrences, leads me to believe that this is related directly to filesystem "statting", and the manner in which PHP performs said statting.

Stat-caching may be a factor, too, although, I don't see how using PHP's clearstatcache() function would be useful here, given that the files mentioned in PHP's error log are not created or deleted during script execution.

The issue seems to boil-down to the following question: Is it possible that some kind of race-condition or dead-locking may occur when two separate PHP execution units (e.g., threads) stat the same file at approximately the same time?

I have a couple more relevant facts to add:

1.) This problem occurs on the production Web-server, too, which runs a completely different OS (Windows on localhost vs. Ubuntu GNU/Linux on the production server). So, it seems not to be Windows-specific. An interesting point of note is that PHP scripts are executed via Apache's mod_php on localhost, but PHP scripts are executed via CGI on the production server. The only difference I observe is that nothing is written to PHP's error log when this occurs with PHP-via-CGI. On the production server, the only indication I have that this occurs is the 500 responses that appear in Apache's access log.

2.) On localhost, PHP thread-safety is enabled, whereas in production, thread-safety is irrelevant (as I understand it) because PHP is running via CGI (phpinfo() reports that thread-safey is disabled, too).

3.) I have ensured that op-code caching (via APC) is disabled everywhere. However, Zend Memory Manager is enabled on both the Windows and Linux servers, if that's relevant.

Perhaps I have run into a very obscure problem relating to Concurreny Models and thread-safety.
Back to top
View user's profile Send private message
U.Tews
Administrator


Joined: 22 Nov 2006
Posts: 5068
Location: Hamburg / Germany

PostPosted: Wed Oct 31, 2012 8:52 pm    Post subject: Reply with quote

First thing I would do for a test is disabling the Zend Memory Manager. (I have myself no knowledge what is does and how it works).

Please note that we do not use file_exists() calls on template source files but make use of the fact that @file_mtime($filepath); does return false when a file is not existing because this has better performance as the two calls of file_exists() and file_mtime(). This so far never created a problem and it does not explain the other errors when including PHP files.
Back to top
View user's profile Send private message
cbj4074
Smarty Regular


Joined: 10 Nov 2011
Posts: 49

PostPosted: Thu Nov 01, 2012 3:20 pm    Post subject: Reply with quote

Thanks for the continued help!

Unfortunately, it seems that disabling the Zend Memory Manager is non-trivial. In fact, I can't even find comprehensive instructions for doing so. I'll work on that.

In the meantime, I have one quick question: given your previous post, do you mean to suggest that when I see

'SmartyException' with message 'Unable to load template file ...'

@filemtime($filepath) is returning false? I have looked at the source code, but the answer is not so easy to discern.

Thanks again, U.Tews!
Back to top
View user's profile Send private message
U.Tews
Administrator


Joined: 22 Nov 2006
Posts: 5068
Location: Hamburg / Germany

PostPosted: Thu Nov 01, 2012 3:51 pm    Post subject: Reply with quote

In smarty_internal_resource_file.php you will find

Code:
if ($source->smarty->compile_check && !isset($source->timestamp)) {
    $source->timestamp = @filemtime($source->filepath);
    $source->exists = !!$source->timestamp;
}


you may give it a try to change it to
Code:
if ($source->smarty->compile_check && !isset($source->timestamp)) {
   if ($source->exists = file_exists($source->filepath)) {
        $source->timestamp = filemtime($source->filepath);
   } else {
        $source->timestamp = false;
   }
}


The error message is created based in the $source->exists status at another place.

But I don't beleave that this will solve your problem.
Back to top
View user's profile Send private message
cbj4074
Smarty Regular


Joined: 10 Nov 2011
Posts: 49

PostPosted: Thu Nov 01, 2012 9:09 pm    Post subject: Reply with quote

You were right, U.Tews. None of those changes solved the problem.

As it turns-out, I have exposed a fundamental limitation with PHP and/or Apache.

In short, too many requests to scripts with calls to require() per a given period of time causes PHP and Apache to behave erratically.

If you are curious as to the details, I have opened a bug report at https://bugs.php.net/bug.php?id=63413 .

Surprising and disconcerting.

Thanks again for all your help with this, knowing full-well that the problem was not with Smarty. Your willingness to assist speaks volumes of your dedication to PHP and to the community of Smarty users. Tip of the hat to you, good sir.
Back to top
View user's profile Send private message
U.Tews
Administrator


Joined: 22 Nov 2006
Posts: 5068
Location: Hamburg / Germany

PostPosted: Fri Nov 02, 2012 2:48 am    Post subject: Reply with quote

Just one last idea. Try to replace require by include.
Back to top
View user's profile Send private message
cbj4074
Smarty Regular


Joined: 10 Nov 2011
Posts: 49

PostPosted: Fri Nov 02, 2012 3:20 pm    Post subject: Reply with quote

No joy, I'm afraid Sad The problem gets worse, actually, because when using include() instead of require(), if the file in which my constants are defined fails to be loaded, execution goes ahead anyway and then the log is full of "Use of undefined constant" notices and additional failures due to incorrect paths (as I define many critical paths using constants).

Here's a new one from Apache (the second message):

Code:

[Fri Nov 02 11:07:25.694983 2012] [core:error] [pid 3268:tid 1120] (OS 32)The process cannot access the file because it is being used by another process.  : [client fe80::1ddc:6806:70b6:8546:57933] AH00127: Cannot map GET /project/public/company/company-overview/ HTTP/1.1 to file, referer: https://ben-pc/project/public/support/
[Fri Nov 02 11:07:25.961017 2012] [core:error] [pid 3268:tid 828] (OS 32)The process cannot access the file because it is being used by another process.  : [client fe80::1ddc:6806:70b6:8546:57952] AH00035: access to /project/public/company/company-overview/ denied (filesystem path 'C:/Users/Ben/Documents/Apache/project/public') because search permissions are missing on a component of the path, referer: https://ben-pc/project/public/support/


Out of curiosity, do you have a project on which you might be able to test this? In other words, do you mind pulling-up any old PHP project and holding down F5 for 5-10 seconds to see if you observe anything similar?

Thanks again!
Back to top
View user's profile Send private message
cbj4074
Smarty Regular


Joined: 10 Nov 2011
Posts: 49

PostPosted: Fri Nov 02, 2012 3:35 pm    Post subject: Reply with quote

I tried to reproduce this problem on a co-workers Mac (Mac OS 10.8 with MAMP stack) and was not able to do so. I used the same exact project source code with which I've been testing on Windows. The MAMP stack is similarly configured in as much as it uses mod_php5 (and not CGI).

I hammered on the site for several minutes with F5 and not a single error in either log file.

So, this problem is shaping-up to be specific to Windows.
Back to top
View user's profile Send private message
U.Tews
Administrator


Joined: 22 Nov 2006
Posts: 5068
Location: Hamburg / Germany

PostPosted: Fri Nov 02, 2012 4:20 pm    Post subject: Reply with quote

I use local a Windows 7 system with WAMP (Apache, PHP 5.3.9). Hammering F5 does not produce any problem.

Sorry I think I can't help any more....
Back to top
View user's profile Send private message
Display posts from previous:   
Post new topic   Reply to topic    Smarty Forum Index -> General All times are GMT
Page 1 of 1

 
Jump to:  
You cannot post new topics in this forum
You cannot reply to topics in this forum
You cannot edit your posts in this forum
You cannot delete your posts in this forum
You cannot vote in polls in this forum


Powered by phpBB © 2001, 2005 phpBB Group
Protected by Anti-Spam ACP