The Inner Workings of Jetpack
I have multiple sites using Jetpack services at various levels from the Free through the Premium service. Some sites are playing nicely with the Jetpack services at WordPress.com but not all sites. This post is my notes repository for debugging this issue.
Jetpack issues
Various sites on my server are working poorly with Jetpack. Some have few issues. Others are not running MOST of the Jetpack services. There is definitely an underlying problem that impacts some sites more than others.
Cannot enable Google Analytics or other Professional Plan options
On the WordPress.StoreLocatorPlus.com site I cannot get Jetpack to talk to my server for the Professional services. I cannot enable the Google Analytics or other Professional options. Jetpack can see their API talking to my server but it is not completing all requests. I can see the requests coming into my server and nothing is coming up in the debug logs (enabling WP_DEBUG).
“Jetpack Premium plan is powering up”
On this site (Lance.Bio) I always see that the Premium plan is powering up. I click on the monetize your site with ads or enable Premium video player links and always get a generic “Error updating settings” message.
Spam protection “flickers”
On the Lance.bio site the Spam Protection box under security constantly checks that spam protection is in place, reports that it is and immediately checks again causing a status “flicker”.
Testing Jetpack communication
The public API at WordPress.com will give you some meta about a site and what is accessible. This API URL is the “glue” that hooks Jetpack up to your website and moves meta data back-and-forth between the Jetpack plugin and the WordPress.com engine.
https://public-api.wordpress.com/rest/v1/sites/<your-wordpress-hostname>
Your server access logs will also give you some insight into the Jetpack communication stack:
POST /xmlrpc.php?for=jetpack&token=pYsxxxxxxWdFJqAt%2AE3yFBn%5E%21ntzhqa%28%402%3A1%3A3×tamp=1514905569&nonce=CQZziCijFx&body-hash=FWuSCJUJ8KH37G0MwJrX0uii2pc%3D&signature=vbzFfISXiYXP8OtdexxxxxxOqdos%3D HTTP/1.1" 200 31551 "https://wordpress.storelocatorplus.com/xmlrpc.php?for=jetpack&token=pYsxxxxxxWdFJqAt%2AE3yFBn%5E%21ntzhqa%28%402%3A1%3A3×tamp=1514905569&nonce=CQZziCijFx&body-hash=FWuSCJUJ8KH37G0MwJrX0uii2pc%3D&signature=vbzFfISXiYXP8OtdexxxxxxOqdos%3D" "Jetpack by WordPress.com"
Jetpack uses XML RPC which means all communication must be performed via a POST transaction through the web server.
Proxy services – allowing XML-RPC
You will need to make sure your proxy service does not block xmlrpc.php calls. Services that are WordPress-aware, such as Sucuri, will have specific settings for allowing calls to xmlrpc.php.
This is not the issue with my servers as I can see in the access logs that Jetpack is talking to my server on xmlrpc.php.
Turning on WordPress debugging
Time to see if one of the plugins or other pieces of PHP code is breaking the site. I go to my site’s wp-config.php and turn on the WP_DEBUG log.
I execute the public API call against my site and check the debug.log file in my wp-content directory. I’m not seeing a debug.log file in that directory which means nothing is breaking on either the WPSLP site or Lance.bio site. I can test this by adding a piece of broken PHP code to either site in one of the plugins or the main theme functions.php and see the file is created; I know the logging is working and therefore can assume that the PHP code is fine. The problem is elsewhere.
Checking server log files
I run nginx on my server as I do not need the excess overhead provided by Apache or other web servers. Since I am the system admin for the entire server I can find my log files in the nginx configured path, typically /var/log/nginx/<sitename>_error.log and <sitename>_access.log.
I can see the requests coming in to the access log. Everything looks normal.
However the error log file shows something interesting.
2018/01/03 11:07:23 [error] 19069#19069: *5375915 FastCGI sent in stderr: "PHP message: Error checking in buffer: The buffer you checked in was not checked out" while reading upstream, client: 192.0.87.45, server: lance.bio, request: " POST /xmlrpc.php? for=jetpack &token=aA... ×tamp=1514995642 &nonce=oU... &body-hash=pdst%2B%... &signature=l%2B... HTTP/1.1 ", upstream: "fastcgi://unix:/run/php/php7.0-fpm.sock:", host: "lance.bio", referrer: " https://lancecleveland.com/xmlrpc.php ?for=jetpack &token=a... ×tamp=1514995642 &nonce=oU3... &body-hash=pds... &signature=l%2B... "
Investigating FastCGI The buffer you checked in was not checked out
The first article that seems to have some useful tech info was found on a GitHub Gist.
Let’s check our maximum and average request sizes on the lance.bio site.
sudo awk '($9 ~ /200/ && $7 ~ /\.php/) {i++; sum+=$10; max=$10>max?$10:max;} END {printf("MAX: %d\nAVG: %d\n", max, i?sum/i:0);}' lance_access.log
Maximum: 64156
Average: 1056
# getconf PAGESIZE
4096
This tells me that the average server response is 1,056 bytes with a maximum response of 65,156 bytes.
My server is configured to use a default page size of 4k (4,096) bytes.
Nginx defaults for FastCGI is to have eight (8) 4k buffers for 32k total of FastCGI buffering.
My average response is 1,056 bytes so it will use 1 of the 8 buffers available, no problem. But what happens with a larger response and are those larger responses images (likely) or actual FastCGI responses?
The above awk command reads the ENTIRE access log and adds up the response size for anything with .php in the request that returned a 200 status code (field 9 = the status code, field 7 = the URL , field 10 = size of request).
That exercise was great for checking to make sure my configured buffers are large enough, which they are. If they were not I’d be seeing “upstream response is buffered to a temporary file” warnings in my error log for the site and I’m not.
All of this checks out.
Jetpack synce-queue
Turns out the error message is coming directly from the Jetpack plugin. The Jetpack Jetpack_Sync_Queue class it barfing because something is out of sync.
Turns out this error message is coming directly from Jetpack:
class Jetpack_Sync_Queue {
...
private function validate_checkout( $buffer ) {
...
if ( $checkout_id != $buffer->id ) {
return new WP_Error( 'buffer_mismatch',
'The buffer you checked in was not checked out' );
}
...
}
...
The validate_checkout() method is only called from the Jetpack_Sync_Queue class in two places:
- the checking() method
- the close() method
One of the call stacks that triggers the error:
PHP message: PHP 1. {main}() /var/www/lance/index.php:0
PHP message: PHP 2. require() /var/www/lance/index.php:17
PHP message: PHP 3. wp() /var/www/lance/wp-blog-header.php:16
PHP message: PHP 4. WP->main() /var/www/lance/wp-includes/functions.php:960
PHP message: PHP 5. WP->parse_request() /var/www/lance/wp-includes/class-wp.php:713
PHP message: PHP 6. do_action_ref_array() /var/www/lance/wp-includes/class-wp.php:373
PHP message: PHP 7. WP_Hook->do_action() /var/www/lance/wp-includes/plugin.php:515
PHP message: PHP 8. WP_Hook->apply_filters() /var/www/lance/wp-includes/class-wp-hook.php:310
PHP message: PHP 9. rest_api_loaded() /var/www/lance/wp-includes/class-wp-hook.php:286
PHP message: PHP 10. shutdown_action_hook() /var/www/lance/wp-includes/load.php:0
PHP message: PHP 11. do_action() /var/www/lance/wp-includes/load.php:679
PHP message: PHP 12. WP_Hook->do_action() /var/www/lance/wp-includes/plugin.php:453
PHP message: PHP 13. WP_Hook->apply_filters() /var/www/lance/wp-includes/class-wp-hook.php:310
PHP message: PHP 14. Jetpack_Sync_Sender->do_full_sync() /var/www/lance/wp-includes/class-wp-hook.php:286
PHP message: PHP 15. Jetpack_Sync_Sender->do_sync_and_set_delays() /var/www/lance/wp-content/plugins/jetpack/sync/class.jetpack-sync-sender.php:65
PHP message: PHP 16. Jetpack_Sync_Sender->do_sync_for_queue() /var/www/lance/wp-content/plugins/jetpack/sync/class.jetpack-sync-sender.php:101
PHP message: PHP 17. Jetpack_Sync_Queue->close() /var/www/lance/wp-content/plugins/jetpack/sync/class.jetpack-sync-sender.php:246" while reading upstream, client: 69.1.24.134, server: lance.bio, request: "GET /wp-json/jetpack/v4/plugins?_cacheBuster=1515008596547 HTTP/1.1", upstream: "fastcgi
Looks like the folks at Jetpack are going to have to help uncover this issue.
I wonder if you ever managed to figure out what caused this issue…