Ajax Activity Update Fails to Post When Akismet Enabled

[SlothLoveChunk]

I originally raised this issue in the support forums here: ​https://buddypress.org/support/topic/buddypress-2-2-activity-updates-ajax-and-askimet-issue/.

When testing BP 2.2 activity updates were not posting via Ajax when I have Akismet enabled. Specifically, the issue seems to be that when Akismet is enabled the spam check prevents an activity update from prepending to the activities list (e.g. <ul id="activity-stream" class="activity-list item-list">). They ARE saving to the DB and Akismet is clearing them. The 'post_update' Ajax listener in buddypress.js is not receiving a "response" back though.

After a bit of debugging I believe I traced the route of the problem to the updated, "bp_filter_metaid_column_name" function in /bp-core/bp-core-filters.php. The updated function includes a new regex:

function bp_filter_metaid_column_name( $q ) {
	/*
	 * Replace quoted content with __QUOTE__ to avoid false positives.
	 * This regular expression will match nested quotes.
	 */
	$quoted_regex = "/'[^'\\\\]*(?:\\\\.[^'\\\\]*)*'/s";
	preg_match_all( $quoted_regex, $q, $quoted_matches );
	$q = preg_replace( $quoted_regex, '__QUOTE__', $q );

	$q = str_replace( 'meta_id', 'id', $q );

	// Put quoted content back into the string.
	if ( ! empty( $quoted_matches[0] ) ) {
		for ( $i = 0; $i < count( $quoted_matches[0] ); $i++ ) {
			$quote_pos = strpos( $q, '__QUOTE__' );
			$q = substr_replace( $q, $quoted_matches[0][ $i ], $quote_pos, 9 );
		}
	}

	return $q;
}

The old function was simply:

function bp_filter_metaid_column_name( $q ) {
	return str_replace( 'meta_id', 'id', $q );
}

If I swap out the updated version of this function for the old one everything works fine. Also, if I comment out the regex portion of 'bp_filter_metaid_column_name' it works fine as well.

I added some logging to this function and the output seems a bit strange to me. It's a bit hard to follow, but here it goes:

[06-Feb-2015 18:40:43 UTC] $q First: SELECT activity_id, meta_key, meta_value FROM wp_bp_activity_meta WHERE activity_id IN (404095) ORDER BY meta_id ASC

[06-Feb-2015 18:40:43 UTC] $q Second: SELECT activity_id, meta_key, meta_value FROM wp_bp_activity_meta WHERE activity_id IN (404095) ORDER BY id ASC

[06-Feb-2015 18:40:43 UTC] $q First: SELECT meta_id FROM wp_bp_activity_meta WHERE meta_key = __QUOTE__ AND activity_id = 404095

[06-Feb-2015 18:40:43 UTC] $q Second: SELECT id FROM wp_bp_activity_meta WHERE meta_key = __QUOTE__ AND activity_id = 404095

[06-Feb-2015 18:40:43 UTC] $q Third: SELECT id FROM wp_bp_activity_meta WHERE meta_key = '_bp_akismet_result' AND activity_id = 404095

[06-Feb-2015 18:40:43 UTC] $q First: INSERT INTO `wp_bp_activity_meta` (`activity_id`,`meta_key`,`meta_value`) VALUES (__QUOTE__,__QUOTE__,__QUOTE__)

[06-Feb-2015 18:40:43 UTC] $q Second: INSERT INTO `wp_bp_activity_meta` (`activity_id`,`meta_key`,`meta_value`) VALUES (__QUOTE__,__QUOTE__,__QUOTE__)

[06-Feb-2015 18:40:43 UTC] $q Third: INSERT INTO `wp_bp_activity_meta` (`activity_id`,`meta_key`,`meta_value`) VALUES ('404095',__QUOTE__,__QUOTE__)

[06-Feb-2015 18:40:43 UTC] $q Third: INSERT INTO `wp_bp_activity_meta` (`activity_id`,`meta_key`,`meta_value`) VALUES ('404095','_bp_akismet_result',__QUOTE__)

[06-Feb-2015 18:40:43 UTC] $q Third: INSERT INTO `wp_bp_activity_meta` (`activity_id`,`meta_key`,`meta_value`) VALUES ('404095','_bp_akismet_result','false')

The SQL statement appended to the '$q Third:' output is logged from inside the '$quoted_matches[0]' for loop (line 744 in /bp-core/bp-core-filters.php).

I get the idea here is for backwards compatibility between 'id' and 'activity_id', but shouldn't it still return the “SELECT" portion of the SQL query?

[boonebgorges]

Thanks for the report and for the debugging you've done so far.

I get the idea here is for backwards compatibility between 'id' and 'activity_id', but shouldn't it still return the “SELECT" portion of the SQL query?

I'm not sure I understand what you mean here. It looks to me like your debug statement is logging three different requests:
(1) one that's priming the meta cache for the activity item (rows 1 and 2),
(2) one that's fetching the specific _bp_akismet_result metavalue (rows 3-5),
(3) one that's inserting a new row into the activitymeta table (rows 6-10)

In other words, the SELECT statement is being returned - twice in fact - and then a separate INSERT is running.

I'll see what I can do about tracking this down.

[boonebgorges]

Hm. I activated Akismet locally and can't reproduce the problem. Activity posts are being properly checked against Akismet, and a success result is returned to the AJAX request.

SlothLoveChunk, could you help with a bit more debugging? Could you enable debug logging (define( 'WP_DEBUG', true ); define( 'WP_DEBUG_DISPLAY', false ); define( 'WP_DEBUG_LOG', true );) and see if anything of note pops up in wp-content/debug.log? If not, could you try digging into buddypress/src/bp-activity/bp-activity-akismet.php to see if you can figure out exactly where execution is getting held up? By the looks of things, I'd say that the failing line is the following in BP_Akismet::update_activity_akismet_meta():

bp_activity_update_meta( $activity->id, '_bp_akismet_result', 'false' );

Is this function returning false? Or true? Or are you getting a fatal error during its execution?

[SlothLoveChunk]

I admit, I am new to this sort of debugging, so let me just show you what I did. Function with logging:

function bp_filter_metaid_column_name( $q ) {
	/*
	 * Replace quoted content with __QUOTE__ to avoid false positives.
	 * This regular expression will match nested quotes.
	 */
	$quoted_regex = "/'[^'\\\\]*(?:\\\\.[^'\\\\]*)*'/s";
	preg_match_all( $quoted_regex, $q, $quoted_matches );
	$q = preg_replace( $quoted_regex, '__QUOTE__', $q );
        
        log_it('$q First: ' . $q);
        
	$q = str_replace( 'meta_id', 'id', $q );
        
        log_it('$q Second: ' . $q);
        
	// Put quoted content back into the string.
	if ( ! empty( $quoted_matches[0] ) ) {
		for ( $i = 0; $i < count( $quoted_matches[0] ); $i++ ) {
			$quote_pos = strpos( $q, '__QUOTE__' );
			$q = substr_replace( $q, $quoted_matches[0][ $i ], $quote_pos, 9 );
                        log_it('$q Third: ' . $q);
		}
	}

	return $q;
}

Note the three calls to the 'log_it' function.

Additionally, after looking in the database and playing around a bit the issue may be related to line 474 of bp-activity-askimet.php:

bp_activity_update_meta( $activity->id, '_bp_akismet_submission', $this->last_activity->akismet_submission );

I noticed that when the post update fails to get a response there is no, "_bp_akismet_submission" entry in the wp_bp_activity_meta table.

[SlothLoveChunk]

@boonebgorges I think we just about replied over each other. Hopefully my last reply is helpful. You're right that issue seems to be in BP_Akismet::update_activity_akismet_meta():, specifically, the last call to bp_activity_update_meta().

[SlothLoveChunk]

Below is the log output for 'bp_filter_metaid_column_name()' that is specific to the call to 'bp_activity_update_meta()' on line 474 ('_bp_akismet_submission').

Interestingly, I don't have a 'wp_bp_activity_meta' entry with ('activity_id = 404100' and 'meta_key = _bp_akismet_submission'), hence why the query doesn't return a result. When you tested and it worked do you see new entries in 'wp_bp_activity_meta' with a meta_key = '_bp_akismet_submission'?

[06-Feb-2015 22:48:16 UTC] $q First: SELECT activity_id, meta_key, meta_value FROM wp_bp_activity_meta WHERE activity_id IN (404100) ORDER BY meta_id ASC

[06-Feb-2015 22:48:16 UTC] $q Second: SELECT activity_id, meta_key, meta_value FROM wp_bp_activity_meta WHERE activity_id IN (404100) ORDER BY id ASC

[06-Feb-2015 22:48:16 UTC] $q First: SELECT meta_id FROM wp_bp_activity_meta WHERE meta_key = __QUOTE__ AND activity_id = 404100

[06-Feb-2015 22:48:16 UTC] $q Second: SELECT id FROM wp_bp_activity_meta WHERE meta_key = __QUOTE__ AND activity_id = 404100

[06-Feb-2015 22:48:16 UTC] $q Third: SELECT id FROM wp_bp_activity_meta WHERE meta_key = '_bp_akismet_submission' AND activity_id = 404100

I'm not sure any of this is helping or not. I don't get why this would affect me, but not you.

[SlothLoveChunk]

One more follow up. I just noticed that all the '_bp_akismet_' entries in the log include a SELECT and INSERT statement; that is, except for '_bp_akismet_submission'. It only has a SELECT, as shown in the log output in my previous comment.

[boonebgorges]

Thanks for the continued debugging. So far I still don't see what's going wrong, but let's keep plugging away :)

Maybe this is something I should've asked earlier, but can you clarify the behavior for me a bit more? If I'm reading the above correctly, it's only the AJAX response (and the corresponding dynamic activity update when looking at the activity stream) that are affected. The new items are being created properly in the db, you note, which I assume means that they appear in the stream when you do a page refresh. Is that correct?

The reason I ask is that I'm not entirely sure how a failure in bp_update_activity_meta() would cause the AJAX failure, unless the meta failure was causing invalid output to be echoed in response. You say "The 'post_update' Ajax listener in buddypress.js is not receiving a "response" back though" - does this mean that the AJAX request times out? or that you get a 500 error? or something else? What does your browser console tell you?

As for the specifics of the failure:

Interestingly, I don't have a 'wp_bp_activity_meta' entry with ('activity_id = 404100' and 'meta_key = _bp_akismet_submission'), hence why the query doesn't return a result. When you tested and it worked do you see new entries in 'wp_bp_activity_meta' with a meta_key = '_bp_akismet_submission'?

Yes, I do have a value, and it's possible that this is part of the issue. It's possible that bp_filter_metaid_column_name() is somehow corrupting the serialized data in the _bp_akismet_submission meta_value field (though even this seems dubious, because we're not seeing an INSERT statement at all).

Have we ascertained that WP_DEBUG is not giving you any warnings? Perhaps it would help to have a closer look at *all* of the SQL queries from the problematic period. Put define( 'SAVEQUERIES', true ); into wp-config, along with a logger like the following:

function bp_6195_showqueries() {
     global $wpdb;

     echo '<pre>';
     print_r( $wpdb->queries );
     echo '</pre>';
}
add_action( 'shutdown', 'bp_6195_showqueries' );

Take note of all the SQL queries, beginning with the first one related to activitymeta. Is anything being improperly filtered?

[SlothLoveChunk]

Sorry for the delay. I was finally able to dig back into this.

You said, "If I'm reading the above correctly, it's only the AJAX response (and the corresponding dynamic activity update when looking at the activity stream) that are affected. The new items are being created properly in the db, you note, which I assume means that they appear in the stream when you do a page refresh. Is that correct?"

That's absolutely right. Other than the dynamic activity update everything works fine. The dynamic update isn't working because the 'post_update' Ajax listener in buddypress.js isn't receiving a response back. The response is not corrupted, so I imagine it's just timing out.

With that said, before wasting anymore time I pushed BP 2.2 up to my production server. The dynamic update seems to work without issue and the '_bp_akismet_submission' entry is being created. That makes me think the actual issue might be with the version of PHP I'm running locally, which is 5.3.10, whereas production is running 5.3.29.

Sorry for wasting valuable time. Next time I run into an issue I will be sure to test on my production server as well.

[boonebgorges]

Sorry for wasting valuable time. Next time I run into an issue I will be sure to test on my production server as well.

Not a waste at all.

There's still clearly something going on here, but I'm glad to hear it's limited to your dev environment. This makes me wonder whether there's some sort of corruption in your local database, or something about your dev environment that is causing AJAX requests to be corrupted in some case.

I'm going to close the ticket as invalid based on the above, but if you manage to reproduce and track down the details any more, please feel free to reopen. Thanks for working with me on this one.