Random Blank Page

[cnxsoft]

I've just upgraded from Quick Cache to Zencache, and noticed the random blank pages bug as referenced @ https://wordpress.org/support/topic/random-blank-pages-2 still exists.

The page are not completely blank, as the "head" is there, but "body" is completely missing. It's probably only happening with nginx, and not apache. It may be hard to reproduce. I have thousand cached page, but only a dozen or so have the problem at any given time.

I've updated my work around script for Zencache: http://pastebin.com/KfMfEDaf, which I run every five minutes as a cron job to delete cached files without body.

[raamdev]

@cnxsoft Thank you for the report!I assume the cache files for the "blank pages" include the ZenCache HTML Notes at the bottom, correct?

This bug was originally related to Quick Cache generating a cache file for a non-2xx or non-404 status code. However, that bug was fixed by only allowing 2xx and 404 status codes to be cached.

@jaswsinc Maybe we should add to the HTML Notes for the cache file the HTTP Status code that's being cached, that way we can see if there's something odd about the blank pages that are getting cached. Thoughts?

[cnxsoft]

@raamdev I forgot to check that. Since my script is running, I don't always have files without body to check. But I don't check in the browser, only directly in zencache directly, so I'm sure it's a cache file generated by Zencache.
Edit: I can confirm ZenCache HTML notes are not part of the generated file.

In Quick Cache, I saved one file with the issue, and after "fixing" the issue.
Without body: http://pastebin.com/v1F8tGmX
After clearing the cache: http://pastebin.com/i0tHQmnm

[raamdev]

@cnxsoft Do you have debugging notes enabled in ZenCache ⥱ Plugin Options ⥱ Enable/Disable? The HTML Notes won't show up unless they're enabled.

If you enable debugging notes and update your cleanup script to move the bad cache files somewhere outside the cache directory (instead of deleting them), then we can save those bad cache files for later inspection.

To help us figure out if this issue is related to an odd HTTP Status Code, can you please modify your copy of ZenCache as follows:

If you're using ZenCache (Lite)

Replace lines 948 and 949 inside wp-content/advanced-cache.php with the following:

                $cache .= "\n".'<!-- '.htmlspecialchars(sprintf(__('%1$s file built for (%2$s) in %3$s seconds, on: %4$s (HTTP Status Code: %5$d).', $this->text_domain),
                                                                $this->name, $this->is_404 ? '404 [error document]' : $this->salt_location, $total_time, date('M jS, Y @ g:i a T'), $this->http_status())).' -->';

If you're using ZenCache Pro

Replace lines 1326 and 1327 inside wp-content/advanced-cache.php with the following:

                $cache .= "\n".'<!-- '.htmlspecialchars(sprintf(__('%1$s file built for (%2$s%3$s) in %4$s seconds, on: %5$s (HTTP Status Code: %6$d).', $this->text_domain),
                                                                $this->name, $this->is_404 ? '404 [error document]' : $this->salt_location, (($this->user_token) ? '; '.sprintf(__('user token: %1$s', $this->text_domain), $this->user_token) : ''), $total_time, date('M jS, Y @ g:i a T'), $this->http_status())).' -->';

IMPORTANT NOTE

If you click the "Restore" button inside ZenCache or if you upgrade ZenCache, these changes will get overwritten.

---

Those changes will tell ZenCache to report the HTTP Status code that generated the cache file:

<!-- ZenCache file built for (http://zcpro.dev/) in 0.22450 seconds, on: Mar 12th, 2015 @ 3:12 am UTC (HTTP Status Code: 200). -->

(Notice the extra HTTP Status Code info on the end of that line.)

The next time ZenCache generates a "blank" cache file, we can check the cache file to see what HTTP Status Code generated the blank page. Note that you are currently deleting these blank cache files with the script you mentioned above, so you'll need to first modify that to move the cache files instead of deleting them so that we can inspect them later.

[cnxsoft]

So I've manage to get a cached file from Zencache for the same page:

• When it lacks body - http://pastebin.com/2KDNgnmn
• When it's been generated properly - http://pastebin.com/NVHk8CWT

HTML notes are enabled, and they work, as the second file ends with:

-- ZenCache file path: /cache/zencache/cache/http/www-cnx-software-com/2015/03/10/tessel-2-javascript-node-js-iot-board-features-atmel-samd21-mcu-and-mediatek-mt7620n-wisoc.html --
-- ZenCache file built for (http://www.cnx-software.com/2015/03/10/tessel-2-javascript-node-js-iot-board-features-atmel-samd21-mcu-and-mediatek-mt7620n-wisoc/) in 0.96153 seconds, on: Mar 12th, 2015 @ 3:00 am UTC.
-- This ZenCache file will auto-expire (and be rebuilt) on: Mar 19th, 2015 @ 3:00 am UTC (based on your configured expiration time). --

I'll add the status code, but I don't think it will show in the cached file.

[jaswrks]

Maybe we should add to the HTML Notes for the cache file the HTTP Status code that's being cached, that way we can see if there's something odd about the blank pages that are getting cached. Thoughts?

Sounds like a good idea to me.

---

When it lacks body - http://pastebin.com/2KDNgnmn

@raamdev So it is quite literally lacking a <body> element. This suggests to me that there is an output buffer in conflict with ZenCache on this installation; i.e., that there is a theme or plugin that is attempting to close all output buffers without regard for others that may exist at a higher level, such as the one for ZenCache. Things to look for are areas in a theme or plugin that run a loop calling while(@ob_end_clean());.

Having a locked output buffer would prevent this sort of issue, but it would also result in other problems. We discussed this before in #97 Instead of using a locked output buffer, we decided to use a shutdown flag. See: https://github.com/websharks/zencache/blob/000000-dev/zencache/includes/advanced-cache.tpl.php#L867

---

@cnxsoft Would it be possible for you to provide us with a list of the other plugins and the theme that you're running? I'd like to see if we can find the conflict that I mentioned above.

[raamdev]

HTML notes are enabled, and they work, as the second file ends with:

@cnxsoft That would further confirm @jaswsinc's theory that this is the result of an output buffer conflict. If you're not even seeing the HTML Notes in the cache file missing the <body> element, then that means ZenCache is being interrupted while it's caching the page and the only way that can happen is if there is an output buffer conflict.

[cnxsoft]

@jaswsinc
I'm using inove. (old but still used by many sites).

Installed plugins (activate have a )
adrotate
backwpup*
bad-behavior*
bwp-recent-comments*
comment-redlist*
contact-form-7*
debug-objects
debug-queries
digg-digg
disqus-comment-system
exclude-pages*
flattr*
google-analytics-for-wordpress
google-sitemap-generator
google-xml-sitemaps-v3-for-qtranslate*
invisible-captcha*
light-social*
maintenance-mode*
nofollow
nofollow-links*
outbrain
p3-profiler
quick-cache
really-simple-captcha*
share-and-follow
si-captcha-for-wordpress*
skimlinks*
smart-youtube
sociable-30
static-random-posts-widget
syntaxhighlighter
tentbloggers-feedburner-rss-redirect-plugin*
tsl-iframe-unfilter*
tweetmeme*
user-registration-aide*
utf-8-db-converter
wordpress-easy-paypal-payment-or-donation-accept-plugin
wp-frame-breaker*
wp-google-analytics*
wp-nofollow-post
wp-optimize*
wp-pagenavi*
wp-table-reloaded
wptouch
wysija-newsletters
yet-another-related-posts-plugin*
zemanta
zencache*

[jaswrks]

@cnxsoft Thank you. What does the * indicate in this list? Anything?

[jaswrks]

I see by your comment that it indicates they are active. Looks like it got cut off, but I get it now. Thanks.

[jaswrks]

@cnxsoft (cc @raamdev) Of these plugins, the only one that I found the potential for an output buffer conflict in is backwpup. This plugin calls while( @ob_end_clean() ); in several places without respect for other output buffers. However, that's not to say that this plugin contains a bug, it is just the most likely suspect here. I didn't have time to go through and debug the plugin, but my suggestion would be to disable it temporarily and see if the problem stops.

If it does, then we could go from there and work to resolve the conflict.

---

TODO: Take a closer look at this plugin: https://wordpress.org/plugins/backwpup/
~ Calling upon while( @ob_end_clean() ); is not necessarily a bad thing, if done correctly. So please understand that I'm not accusing this plugin of having a problem. However, in the context of this issue, is it the most likely (only) suspect at the moment.

[jaswrks]

Referencing: https://cloudup.com/c2TMnh6QP_M
~ This is a ZIP file containing all of the active plugin files listed above.

[cnxsoft]

BackWPUp is not the culprit. I've deactivated, and new "no body" cache file are still generated.

I've done a grep in my plugins directory:
grep ob_end_clean * -R
backwpup/inc/class-destination-folder.php: @ob_end_clean();
backwpup/inc/class-job.php: while( @ob_end_clean() );
debug-objects/inc/PHP-Error-master/src/php_error.php: ob_end_clean();
debug-objects/inc/PHP-Error-master/src/php_error.php: ob_end_clean();
debug-objects/inc/PHP-Error-master/src/php_error.php: ob_end_clean();
debug-objects/inc/class-rewrite_backtrace.php: ob_end_clean();
maintenance-mode/maintenance-mode.php: ob_end_clean();
wordpress-easy-paypal-payment-or-donation-accept-plugin/WP_Accept_Paypal_Payment.php: ob_end_clean();
wp-table-reloaded/classes/helper.class.php: @ob_end_clean();
wptouch/admin/settings/html/redirect.php: ob_end_clean();
wptouch/admin/settings/include/custom-latest-posts.php: ob_end_clean();
wptouch/core/globals.php: ob_end_clean();
wysija-newsletters/views/front/widget_nl.php: ob_end_clean();
wysija-newsletters/core/module/module.php: ob_end_clean();
yet-another-related-posts-plugin/classes/YARPP_Core.php: ob_end_clean();
yet-another-related-posts-plugin/classes/YARPP_Core.php: ob_end_clea ();
yet-another-related-posts-plugin/classes/YARPP_Core.php: ob_end_clean();
yet-another-related-posts-plugin/classes/YARPP_Admin.php: ob_end_clean();
zemanta/zemanta.php: ob_end_clean();

Could Yet-another-related-posts-plugin also conflict with Zencache, although the function does not appear to be called within a while loop?

[jaswrks]

@cnxsoft writes...

Could Yet-another-related-posts-plugin also conflict with Zencache, although the function does not appear to be called within a while loop?

Possible, but I'd say it is unlikely; i.e., from what I reviewed of this codebase it seems to be using ob_ related functions properly.

I did not review wp-touch. I see that listed above, but the indication was that you are not running WP Touch, correct?

@cnxsoft writes...

BackWPUp is not the culprit. I've deactivated, and new "no body" cache file are still generated.

Are you keeping a log of all PHP-related errors on your server? If so, have you seen any errors in your log file recently? These could shed light. Checking Apache error logs for anything related to PHP could help also.

Keep in mind that we are still operating on a best-guess here. I am guessing that this is related to output buffers, but an empty <body> could be caused by something else also. What else it could be (other than an output buffer), I'm not sure.

PHP error logs, or debugging this by stripping the site down to a bare minimum might help. If you have a test installation of WordPress where you can start fresh and then add one or two of these plugins at a time until you find a clue as what might be causing this could help.

[cnxsoft]

@jaswsinc Correct, WPTouch is installed, but not active.

The few last lines of my php5-fpm.log (I'm using nginx + php5-fpm. I believe this issues does not occur with apache2):

[15-Mar-2015 01:46:56] WARNING: [pool www] seems busy (you may need to increase pm.start_servers, or pm.min/max_spare_servers), spawning 8 children, there are 0 idle, and 11 total children
[15-Mar-2015 04:00:35] WARNING: [pool www] seems busy (you may need to increase pm.start_servers, or pm.min/max_spare_servers), spawning 8 children, there are 0 idle, and 11 total children
[15-Mar-2015 04:00:36] WARNING: [pool www] seems busy (you may need to increase pm.start_servers, or pm.min/max_spare_servers), spawning 16 children, there are 1 idle, and 13 total children
[15-Mar-2015 06:00:11] WARNING: [pool www] child 898, script '/srv/www/cnx-software.com/public_html/wp-cron.php' (request: "GET /wp-cron.php") executing too slow (10.281921 sec), logging
[15-Mar-2015 06:00:11] NOTICE: child 898 stopped for tracing
[15-Mar-2015 06:00:11] NOTICE: about to trace 898
[15-Mar-2015 06:00:11] NOTICE: finished trace of 898
[15-Mar-2015 06:04:53] WARNING: [pool www] child 1000 exited on signal 11 (SIGSEGV - core dumped) after 281.443589 seconds from start
[15-Mar-2015 06:04:53] NOTICE: [pool www] child 1020 started
[15-Mar-2015 06:32:55] WARNING: [pool www] child 1525, script '/srv/www/cnx-translation.com/public_html/chinese/news.php' (request: "GET /chinese/news.php") executing too slow (10.968071 sec), logging
[15-Mar-2015 06:32:55] NOTICE: child 1525 stopped for tracing
[15-Mar-2015 06:32:55] NOTICE: about to trace 1525
[15-Mar-2015 06:32:55] NOTICE: finished trace of 1525
[15-Mar-2015 07:15:04] WARNING: [pool www] child 1733 exited with code 1 after 868.897157 seconds from start
[15-Mar-2015 07:15:04] NOTICE: [pool www] child 1832 started
[15-Mar-2015 10:05:15] WARNING: [pool www] child 2877, script '/srv/www/cnx-software.com/public_html/wp-cron.php' (request: "GET /wp-cron.php") executing too slow (12.996919 sec), logging
[15-Mar-2015 10:05:15] NOTICE: child 2877 stopped for tracing
[15-Mar-2015 10:05:15] NOTICE: about to trace 2877
[15-Mar-2015 10:05:15] NOTICE: finished trace of 2877
[15-Mar-2015 10:09:38] WARNING: [pool www] child 2876, script '/srv/www/cnx-software.com/public_html/wp-admin/edit-comments.php' (request: "GET /wp-admin/edit-comments.php") executing too slow (12.082231 sec), logging
[15-Mar-2015 10:09:38] NOTICE: child 2876 stopped for tracing
[15-Mar-2015 10:09:38] NOTICE: about to trace 2876
[15-Mar-2015 10:09:38] NOTICE: finished trace of 2876
[15-Mar-2015 10:10:11] WARNING: [pool www] child 2894, script '/srv/www/cnx-software.com/public_html/wp-cron.php' (request: "GET /wp-cron.php") executing too slow (10.756476 sec), logging
[15-Mar-2015 10:10:11] NOTICE: child 2894 stopped for tracing
[15-Mar-2015 10:10:11] NOTICE: about to trace 2894
[15-Mar-2015 10:10:11] NOTICE: finished trace of 2894
[15-Mar-2015 10:15:57] WARNING: [pool www] seems busy (you may need to increase pm.start_servers, or pm.min/max_spare_servers), spawning 8 children, there are 0 idle, and 11 total children
[15-Mar-2015 14:50:12] WARNING: [pool www] child 4526, script '/srv/www/cnx-software.com/public_html/wp-cron.php' (request: "GET /wp-cron.php") executing too slow (10.068839 sec), logging
[15-Mar-2015 14:50:12] NOTICE: child 4526 stopped for tracing
[15-Mar-2015 14:50:12] NOTICE: about to trace 4526
[15-Mar-2015 14:50:12] NOTICE: finished trace of 4526
[15-Mar-2015 14:52:22] WARNING: [pool www] seems busy (you may need to increase pm.start_servers, or pm.min/max_spare_servers), spawning 8 children, there are 0 idle, and 11 total children
[15-Mar-2015 14:52:23] WARNING: [pool www] seems busy (you may need to increase pm.start_servers, or pm.min/max_spare_servers), spawning 16 children, there are 0 idle, and 13 total children
[15-Mar-2015 14:52:24] WARNING: [pool www] seems busy (you may need to increase pm.start_servers, or pm.min/max_spare_servers), spawning 32 children, there are 1 idle, and 15 total children
[15-Mar-2015 14:52:25] WARNING: [pool www] server reached pm.max_children setting (16), consider raising it
[15-Mar-2015 15:07:42] WARNING: [pool www] child 4960, script '/srv/www/cnx-software.com/public_html/wp-comments-post.php' (request: "POST /wp-comments-post.php") executing too slow (12.994014 sec), logging
[15-Mar-2015 15:07:42] NOTICE: child 4960 stopped for tracing
[15-Mar-2015 15:07:42] NOTICE: about to trace 4960
[15-Mar-2015 15:07:42] NOTICE: finished trace of 4960
[15-Mar-2015 15:11:49] WARNING: [pool www] child 4960, script '/srv/www/cnx-software.com/public_html/wp-comments-post.php' (request: "POST /wp-comments-post.php") executing too slow (10.504036 sec), logging
[15-Mar-2015 15:11:49] NOTICE: child 4960 stopped for tracing
[15-Mar-2015 15:11:49] NOTICE: about to trace 4960
[15-Mar-2015 15:11:49] NOTICE: finished trace of 4960
[15-Mar-2015 15:45:13] WARNING: [pool www] child 5164, script '/srv/www/cnx-software.com/public_html/wp-cron.php' (request: "GET /wp-cron.php") executing too slow (11.654822 sec), logging
[15-Mar-2015 15:45:13] NOTICE: child 5164 stopped for tracing
[15-Mar-2015 15:45:13] NOTICE: about to trace 5164
[15-Mar-2015 15:45:13] NOTICE: finished trace of 5164

The "slow cron job" is probably because of the script I use to go through thousands of cached files and delete the ones without body.

[jaswrks]

Thank you :-)

So it appears that you have request-slowlog-timeout set to a pretty low number. I'm seeing log entries for several processes that are being backtraced by PHP5-FPM after just 10-12 seconds.

It could be PHP5-FPM request-slowlog-timeout causing this odd behavior. Where the script execution is being stopped early, and then a backtrace is performed on what is considered a slow-running process. I can't be sure of that, but I think it is worth experimenting with. I suggest increasing this to 30 (i.e., the default max_execution_time for PHP).

Given the number of NOTICE: about to trace entries in the log file, it might worth looking closer at your php-fpm.log.slow log file also. That way you can see exactly which scripts are running slow. I noticed that you referenced wp-cron.php, but it seems there are others also.

[raamdev]

@cnxsoft Just checking in here to see if you had a chance to try increasing max_execution_time to 30 as @jaswsinc suggested above.

[cnxsoft]

@raamdev. Sorry I forget to update. I increased max_execution_time to 30, and even disabled it (set to 0), but the blank pages are still generated.

[raamdev]

@cnxsoft Are you able to test/reproduce this in a clean WordPress environment on your server, i.e., without any other plugins installed?

The most likely cause for this issue is a plugin conflict, possibly even a conflict created by the combination of two or more plugins resulting in a conflict with ZenCache. That makes it very difficult to troubleshoot.

If you're able to reproduce this in a clean WordPress environment, that would indicate an issue with ZenCache and your server environment, in which case we could start running extensive tests using various server environments similar to your own. However, until we can prove that it's not a WordPress plugin/theme conflict, it doesn't make sense to go that route.

[cnxsoft]

@raamdev. I guess testing a clean installation, and trying plugins one by one is the next step. It may take a while before I find/make time for this though.

[raamdev]

It may take a while before I find/make time for this though.

@cnxsoft No problem. Please let us know when you get around to testing this--if you find there's an issue related to your server configuration and not to your WordPress plugins/theme, we'll gladly take another look at this.

If you don't mind, I will go ahead and close this GitHub Issue and when you come back to update here, I will reopen it if there's something for us to research further.