intermittent errors with the file cache

rkdesantos - April 14, 2008 - 00:24
Project:Advertisement
Version:5.x-1.5-rc2
Component:ad_cache_file module
Category:support request
Priority:normal
Assigned:Unassigned
Status:closed
Description

My host is migrating to PHP5. I ran a test of my site under PHP5 and the Ad modules did not seem to work. So, my questions are:

Have any other users tested or are running the module on a Drupal installation under PHPv5? Are they any know incompatibilities or adjustments that need to be made?

#1

Jeremy@kerneltr... - April 14, 2008 - 00:36
Status:active» active (needs more info)

I develop and use the ad module exclusively under PHP 5. What specifically did not work for you?

#2

rkdesantos - April 17, 2008 - 14:07
Status:active (needs more info)» active

I get the following errors:

Configuration error, failed to lock cache file.

on the banner ad area

and this in the logs:

    * Ad module failed to access cache customfiles/.1.ad.cache. Verify file permissions.
    * Ad module failed to access cache customfiles/.2.ad.cache. Verify file permissions.
    * Ad module failed to access cache customfiles/.3.ad.cache. Verify file permissions.
    * Ad module failed to access cache customfiles/.4.ad.cache. Verify file permissions.
    * Ad module failed to access cache customfiles/.5.ad.cache. Verify file permissions.

#3

Jeremy@kerneltr... - April 17, 2008 - 15:20
Component:ad module» ad_cache_file module
Status:active» active (needs more info)

You are having a file permissions issue. The ad module needs write permissions in the files/ directory. These errors are telling you that it does not have the necessary permissions to lock and write the cache files.

#4

rkdesantos - April 17, 2008 - 23:19

I figured as much Jeremy. The question is what to do to fix it? Do I need to change the ownership of the files? Is there a specific setting for the file permissions required (currently they are 664)?

#5

Jeremy@kerneltr... - April 18, 2008 - 00:17

The files need to be owned by the same user that the web server is running under. That user needs write permission to these files and the directory they are in.

If you're asking about how file permissions work, you may want to start by reading here.

#6

rkdesantos - April 18, 2008 - 00:25

I'll investigate which user owns the files and change it if need be. I understand how file permissions work however PHP5 handles that differently than did PHP4 apparently.

Would it be easier to: 1) turn off file caching for the module. 2) delete the files 3) turn on PHP5 for Drupal 4) turn file caching for the advertisement module back on and let it recreate the files with the ownership it expects?

#7

Jeremy@kerneltr... - April 18, 2008 - 00:31

From what information I have, it should be as simple as chown'ing the files.

Do a "ps -ef | grep apache" or "ps -ef | grep http" to determine what user it's running as. The move to your files/ subdirectory and chown the files to be owned by that user. (They should already be, as they should have been created by the web server process, but perhaps the owner of your web server process was changed during the upgrade.)

#8

rkdesantos - April 18, 2008 - 01:06

Well, the files are owned by "noboby" and that is the owner of the apache and http processes.

-rw-rw-r--   1 nobody nobody    8888 Apr 17 19:57 .1.ad.cache
-rw-rw-r--   1 nobody nobody    8367 Apr 17 19:30 .2.ad.cache
-rw-rw-r--   1 nobody nobody    8367 Apr 17 19:30 .3.ad.cache
-rw-rw-r--   1 nobody nobody    8367 Apr 17 19:30 .4.ad.cache
-rw-rw-r--   1 nobody nobody    8367 Apr 17 19:30 .5.ad.cache

nobody    3598 23804  1 19:42 ?        00:00:17 /usr/local/apache/bin/httpd -DSSL
nobody   11458 23804  1 19:59 ?        00:00:01 /usr/local/apache/bin/httpd -DSSL
nobody   11460 23804  0 19:59 ?        00:00:00 /usr/local/apache/bin/httpd -DSSL
nobody   11461 23804  0 19:59 ?        00:00:01 /usr/local/apache/bin/httpd -DSSL  

nobody    5372 23804  0 19:49 ?        00:00:00 /usr/local/apache/bin/httpd -DSSL
nobody    5376 23804  0 19:49 ?        00:00:00 /usr/local/apache/bin/httpd -DSSL
nobody    5377 23804  0 19:49 ?        00:00:00 /usr/local/apache/bin/httpd -DSSL
nobody    5382 23804  0 19:49 ?        00:00:00 /usr/local/apache/bin/httpd -DSSL
etc.

#9

Jeremy@kerneltr... - April 18, 2008 - 01:14

How about the ownership/permissions of the customfiles/ directory? If you have permissions, the simplest way to debug this is to su to "nobody" and try touching one of those files.

#10

rkdesantos - April 18, 2008 - 02:00

Well that might be an issue except that it doesn't bother any other module:

drwxrwxrwx   8 afana afana   4096 Apr 16 11:32 customfiles/ 

So I'll have to try to see what happen if I change the owner of customfiles to "noboby" or change the owner of the cache files to "afana" and see which one works better.

#11

Jeremy@kerneltr... - April 18, 2008 - 17:58

Looking at your permissions, it seems things should be working, but obviously it's not. I recommend you su to user 'nobody' and try touching the files and see what happens.

You could try and collect more information by reviewing DEBUG.txt, following those instructions with the file cache enabled. Perhaps there will be a clue in that more verbose output.

In any case, one specific error is quite clear due to the error that you've shared:

      if (!$fd = @fopen($cache_file, 'r+')) {
        drupal_set_message(t('Ad module failed to access cache <em>%file</em>.  Verify file permissions.', array('%file' => $cache_file)), 'error');
        continue;
      }

Thus, fopen is failing to obtain 'r+' permissions.

#12

rkdesantos - April 21, 2008 - 22:13
Status:active (needs more info)» fixed

Apparently fixed.... once the cache files were changed to be owned by my site ("afana") and not by "nobody" everything worked as expected.

#13

rkdesantos - April 22, 2008 - 22:59
Status:fixed» active

OK, the ads display correctly but we are getting these intermittent errors logged while running under PHP5:

[22-Apr-2008 17:47:45] PHP Warning:  Invalid argument supplied for foreach() in /home/afana/public_html/drupal5/modules/ad/cache/file/ad_cache_file.inc on line 106
[22-Apr-2008 17:47:45] PHP Warning:  Cannot modify header information - headers already sent by (output started at /home/afana/public_html/drupal5/modules/ad/cache/file/ad_cache_file.inc:106) in /home/afana/public_html/drupal5/modules/ad/adserve.inc on line 202
[22-Apr-2008 17:47:45] PHP Warning:  Cannot modify header information - headers already sent by (output started at /home/afana/public_html/drupal5/modules/ad/cache/file/ad_cache_file.inc:106) in /home/afana/public_html/drupal5/modules/ad/adserve.inc on line 204
[22-Apr-2008 17:47:45] PHP Warning:  Cannot modify header information - headers already sent by (output started at /home/afana/public_html/drupal5/modules/ad/cache/file/ad_cache_file.inc:106) in /home/afana/public_html/drupal5/modules/ad/adserve.inc on line 206
[22-Apr-2008 17:47:45] PHP Warning:  Cannot modify header information - headers already sent by (output started at /home/afana/public_html/drupal5/modules/ad/cache/file/ad_cache_file.inc:106) in /home/afana/public_html/drupal5/modules/ad/adserve.inc on line 207
[22-Apr-2008 17:47:45] PHP Warning:  Cannot modify header information - headers already sent by (output started at /home/afana/public_html/drupal5/modules/ad/cache/file/ad_cache_file.inc:106) in /home/afana/public_html/drupal5/modules/ad/adserve.inc on line 209
[22-Apr-2008 17:47:45] PHP Warning:  Cannot modify header information - headers already sent by (output started at /home/afana/public_html/drupal5/modules/ad/cache/file/ad_cache_file.inc:106) in /home/afana/public_html/drupal5/modules/ad/adserve.inc on line 211

I have temporarily disabled caching for the module.

#14

Jeremy@kerneltr... - April 23, 2008 - 00:52
Title:Compatibility with PHP5» intermittent errors with the file cache
Status:active» active (needs more info)

Updating issue title to reflect actual problems.

Lot's of questions for you, please answer all of them.

How often do you see these errors? Is there any sort of consistency? How often have you configured your file cache to be rebuilt? Does this error show up each time it is rebuilt? (A blind guess, I've no specific ideas what is causing this at this time.)

Can you trigger this error manually, or on a development website? Can you review DEBUG.txt, and trigger this error with &debug=2 enabled?

Offhand, the error doesn't make much sense, as we've already validated that the tids variable is not empty. And as tids is not empty, explode() should always return an array.

#15

rkdesantos - April 23, 2008 - 14:22

How often do you see these errors? Is there any sort of consistency? How often have you configured your file cache to be rebuilt? Does this error show up each time it is rebuilt? (A blind guess, I've no specific ideas what is causing this at this time.)

One to three times per hour; every 30 minutes; doesn't appear to be the case that it is tied to the periodic rebuild but can't rule that out - I would have to monitor the file updates with the cache enabled to determine that.

Can you trigger this error manually, or on a development website? Can you review DEBUG.txt, and trigger this error with &debug=2 enabled?

Don't have a development site at the moment so I am not sure. How would I go about triggering it manually? By causing the cache to be rebuilt? (Which should happen if I turn caching back on).

I can try to run with cache enabled and report on the debug results if you wish. Here are the results with the cache disabled:

ad_dir: '/home/afana/public_html/drupal5/modules/ad'
debug: '2'
cache: 'none'
nids: '787,788,789,794,797,841,843,844,928'
tids: ''
hostid: ''
quantity: '1'
aid: '0'
method: 'javascript'
Root drupal directory detected as '/home/afana/public_html/drupal5'.

/home/afana/public_html/drupal5/modules/ad/serve.php: // $Id: serve.php,v 1.1.2.2 2007/10/19 02:46:40 jeremy Exp $
/home/afana/public_html/drupal5/modules/ad/ad.module: // $Id: ad.module,v 1.2.2.29.2.59 2008/01/11 19:37:33 jeremy Exp $

No cache enabled.
Drupal bootstrap '7'.

Warning: session_start() [function.session-start]: Cannot send session cache limiter - headers already sent (output started at /home/afana/public_html/drupal5/modules/ad/adserve.inc:291) in /home/afana/public_html/drupal5/includes/bootstrap.inc on line 899

Warning: Cannot modify header information - headers already sent by (output started at /home/afana/public_html/drupal5/modules/ad/adserve.inc:291) in /home/afana/public_html/drupal5/includes/bootstrap.inc on line 531

Warning: Cannot modify header information - headers already sent by (output started at /home/afana/public_html/drupal5/modules/ad/adserve.inc:291) in /home/afana/public_html/drupal5/includes/bootstrap.inc on line 532

Warning: Cannot modify header information - headers already sent by (output started at /home/afana/public_html/drupal5/modules/ad/adserve.inc:291) in /home/afana/public_html/drupal5/includes/bootstrap.inc on line 533

Warning: Cannot modify header information - headers already sent by (output started at /home/afana/public_html/drupal5/modules/ad/adserve.inc:291) in /home/afana/public_html/drupal5/includes/bootstrap.inc on line 534
Ads previously served: 0
Searching for ad from nid list: 787,788,789,794,797,841,843,844,928.
Query: "SELECT aid, adtype, redirect, activated, maxviews, maxclicks FROM {ads} WHERE adstatus = 'active' AND (aid = 787 OR aid = 788 OR aid = 789 OR aid = 794 OR aid = 797 OR aid = 841 OR aid = 843 OR aid = 844 OR aid = 928) ORDER BY RAND() LIMIT 1;"
ad:

stdClass Object
(
    [aid] => 794
    [adtype] => image
    [redirect] => http://www.afana.com/drupal5/ad/redirect/794
    [activated] => 1201475627
    [maxviews] => 0
    [maxclicks] => 0
)

Loading module 'modules/ad/image/ad_image.module'.
Ads displayed: 1
document.write('\x3cdiv class=\"image-advertisement\" id=\"ad-794\"\x3e\x3ca href=\"http://www.afana.com/drupal5/ad/redirect/794/\" title=\"Sports Travel with Infohub Sports Travel Specialists\" target=\"_blank\"\x3e\x3cimg src=\"http://www.afana.com/drupal5/customfiles/travel24banner_0.jpg\" width=\"468\" height=\"60\" /\x3e\x3c/a\x3e\x3c/div\x3e');

#16

rkdesantos - April 23, 2008 - 14:31
Status:active (needs more info)» active

Here is the debug output with the cache enabled:

Attempting to include cache include file '/home/afana/public_html/drupal5/modules/ad/cache/file/ad_cache_file.inc'.
ad_dir: '/home/afana/public_html/drupal5/modules/ad'
debug: '2'
cache: 'file'
nids: '787,788,789,794,797,841,843,844,928'
tids: ''
hostid: ''
quantity: '1'
aid: '0'
method: 'javascript'
path: 'customfiles'
files: '5'
Root drupal directory detected as '/home/afana/public_html/drupal5'.

/home/afana/public_html/drupal5/modules/ad/serve.php: // $Id: serve.php,v 1.1.2.2 2007/10/19 02:46:40 jeremy Exp $
/home/afana/public_html/drupal5/modules/ad/ad.module: // $Id: ad.module,v 1.2.2.29.2.59 2008/01/11 19:37:33 jeremy Exp $

Using file cache.
Trying cache_file '/home/afana/public_html/drupal5/customfiles/.1.ad.cache'.
Obtained lock.
File size: 8571
Last sync: 1208960774
Current time: 1208961024
Will rebuild cache in 1550 seconds.
Timestamp: 2008042309
cache_size(9)
Size of $ids: 0
Selecting 1 ad(s) from 9 total ad(s).
Randomly selecting ad: 1 of 1.
Randomly selected ID: 841.
Displaying AID: 841
document.write('\x3cdiv class=\"html-advertisement\" id=\"ad-841\"\x3e\x3cdiv class=\"ad-header\"\x3e\x3c!-- BEGIN STANDARD TAG - 468 x 60 - ROS: Run-of-site - DO NOT MODIFY --\x3e \x3cp\x3e\x3ciframe width=\"468\" scrolling=\"no\" height=\"60\" frameborder=\"0\" marginwidth=\"0\" marginheight=\"0\" src=\"http://ad.z5x.net/st?ad_type=iframe\x26amp;ad_size=468x60\x26amp;section=289050\"\x3e\x3c/iframe\x3e\x3c/p\x3e\x3c!-- END TAG --\x3e\x3c/div\x3e\x3c/div\x3e');

#17

rkdesantos - April 27, 2008 - 03:53
Version:5.x-1.4-1» 5.x-1.5-rc2

Updated to 1.5-rc2 and problem still occurs.

#18

Jeremy@kerneltr... - May 7, 2008 - 13:01
Status:active» active (needs more info)

What line is the error occurring on in 1.5-rc2?

#19

rkdesantos - May 7, 2008 - 15:17
Status:active (needs more info)» active

Here's a recent clip from the error log:

[04-May-2008 07:45:43] PHP Warning:  Cannot modify header information - headers already sent by (output started at /home/afana/public_html/drupal5/modules/ad/cache/file/ad_cache_file.inc:151) in /home/afana/public_html/drupal5/modules/ad/adserve.inc on line 233
[04-May-2008 07:45:43] PHP Warning:  Cannot modify header information - headers already sent by (output started at /home/afana/public_html/drupal5/modules/ad/cache/file/ad_cache_file.inc:151) in /home/afana/public_html/drupal5/modules/ad/adserve.inc on line 235
[04-May-2008 07:45:43] PHP Warning:  Cannot modify header information - headers already sent by (output started at /home/afana/public_html/drupal5/modules/ad/cache/file/ad_cache_file.inc:151) in /home/afana/public_html/drupal5/modules/ad/adserve.inc on line 237
[04-May-2008 07:45:43] PHP Warning:  Cannot modify header information - headers already sent by (output started at /home/afana/public_html/drupal5/modules/ad/cache/file/ad_cache_file.inc:151) in /home/afana/public_html/drupal5/modules/ad/adserve.inc on line 238
[04-May-2008 07:45:43] PHP Warning:  Cannot modify header information - headers already sent by (output started at /home/afana/public_html/drupal5/modules/ad/cache/file/ad_cache_file.inc:151) in /home/afana/public_html/drupal5/modules/ad/adserve.inc on line 240
[04-May-2008 07:45:43] PHP Warning:  Cannot modify header information - headers already sent by (output started at /home/afana/public_html/drupal5/modules/ad/cache/file/ad_cache_file.inc:151) in /home/afana/public_html/drupal5/modules/ad/adserve.inc on line 242

#20

Jeremy@kerneltr... - May 10, 2008 - 17:39
Status:active» fixed

Fix committed to development branch. Added error checking to prevent error from being dumped to screen when no ads are available in cache.

#21

rkdesantos - May 11, 2008 - 02:03

First blush says that fixed the problem. Thanks.

#22

Anonymous (not verified) - May 25, 2008 - 02:12
Status:fixed» closed

Automatically closed -- issue fixed for two weeks with no activity.

 
 

Drupal is a registered trademark of Dries Buytaert.