Email campaigns no longer send after upgrade from 7.5.3 to 7.6.1

dodexahedron · 5 May 2016 03:08

I upgraded from 7.5.3 to 7.6.1 and now none of my outbound emails get sent, and just stick around in the queue.

In my suitecrm log, I see a bunch of errors similar to this, when I try to force email queue processing:

Wed May  4 22:55:36 2016 [4160][1][FATAL] Error acquiring lock for the emailman entry, skipping email delivery. lock status=-1 Array
(
    [date_entered] => 2016-05-04 06:12:19
    [date_modified] =>
    [user_id] => 1
    [id] => 122
    [campaign_id] => 7b0a91cb-21e5-5d92-4d94-57298d3e8257
    [marketing_id] => 596b5523-0f20-3698-a9e3-5729913a1106
    [list_id] => d768b564-9183-8b81-d630-56c78ad841c0
    [send_date_time] => 2016-05-04 06:00:00
    [modified_user_id] =>
    [in_queue] => 0
    [in_queue_date] => 2016-05-04 07:00:01
    [send_attempts] => 0
    [deleted] => 0
    [related_id] => e8b50737-4441-ddcf-9841-56d7ec8ba90e
    [related_type] => Prospects
)

Email campaigns always worked fine before the upgrade.
What does this error mean and how might I go about resolving it?

Here’s what I’ve done so far:
Quick Repair & Rebuild
Checked the permissions for all folders and ensured they match what is in the install guide.
Manually set the in_queue bit to 0 for all records in the emailman table and then tried again, with the same result.

This install is on an ubuntu server using apache 2.4.18, php 7.0.7, and MySQL 5.7.12.

Any help or pointers on which direction to go would be greatly appreciated.

Thanks!

dodexahedron · 5 May 2016 23:54

Digging into the code, this is the relevant section of code dealing with this:

//acquire a lock.
		//if the database does not support repeatable read isolation by default, we might get data that does not meet
        //the criteria in the original query, and we care most about the in_queue_date and process_date_time,
        //if they are null or in past(older than 24 horus) then we are okay.
		$lock_query="UPDATE emailman SET in_queue=1, in_queue_date=". $db->now()." WHERE id = ".intval($row['id']);
		$lock_query.=" AND (in_queue ='0' OR in_queue IS NULL OR ( in_queue ='1' AND in_queue_date <= " .$db->convert($db->quoted($timedate->fromString("-1 day")->asDb()),"datetime")."))";
 		//if the query fails to execute.. terminate campaign email process.
 		$lock_result=$db->query($lock_query,true,'Error acquiring a lock for emailman entry.');
		$lock_count=$db->getAffectedRowCount($lock_result);
		//do not process the message if unable to acquire lock.
		if ($lock_count!= 1) {
			$GLOBALS['log']->fatal("Error acquiring lock for the emailman entry, skipping email delivery. lock status=$lock_count " . print_r($row,true));
			continue;  //do not process this row we will examine it after 24 hrs. the email address based dupe check is in place too.
		}

That’s in /modules/EmailMan/EmailManDelivery.php

However, the fun part is if I execute that SQL myself for a given record in the table, I get 1 row affected, which is what the code expects.
Any PHP gurus out there know why the "if ($lock_count!= 1) " condition is failing?

dodexahedron · 6 May 2016 00:36

This code is actually fundamentally broken using mysqli, if your table storage engine is InnoDB, from what I can tell.

The mysqli_query function returns a boolean for its result, which indicates success or failure of the query. It does not return a mysqli_result object for update queries.

If we dig into the MysqliManager.php file, we see this as the query() function:

	public function query($sql, $dieOnError = false, $msg = '', $suppress = false, $keepResult = false)
	{
		if(is_array($sql)) {
			return $this->queryArray($sql, $dieOnError, $msg, $suppress);
        }

		static $queryMD5 = array();

		parent::countQuery($sql);
		$GLOBALS['log']->info('Query:' . $sql);
		$this->checkConnection();
		$this->query_time = microtime(true);
		$this->lastsql = $sql;
		[b]$result = $suppress?@mysqli_query($this->database,$sql):mysqli_query($this->database,$sql);[/b]
		$md5 = md5($sql);

		if (empty($queryMD5[$md5]))
			$queryMD5[$md5] = true;

		$this->query_time = microtime(true) - $this->query_time;
		$GLOBALS['log']->info('Query Execution Time:'.$this->query_time);

		// This is some heavy duty debugging, leave commented out unless you need this:
		/*
		$bt = debug_backtrace();
		for ( $i = count($bt) ; $i-- ; $i > 0 ) {
			if ( strpos('MysqliManager.php',$bt[$i]['file']) === false ) {
				$line = $bt[$i];
			}
		}

		$GLOBALS['log']->fatal("${line['file']}:${line['line']} ${line['function']} \nQuery: $sql\n");
		*/


		if($keepResult)
			$this->lastResult = $result;
		$this->checkError($msg.' Query Failed: ' . $sql, $dieOnError);

		[b]return $result;[/b]
	}

(bolding mine, obviously)

That means it can never succeed, because EmailManDelivery.php is then doing this:

$lock_count=$db->getAffectedRowCount($lock_result);

Which is this, in MysqliManager.php:

	public function getAffectedRowCount($result)
	{
		return mysqli_affected_rows($this->getDatabase());
	}

Which means calling mysql_affected_rows on the mysqli database object. All that does is gets affected rows of the last query executed. If the last query executed was a commit (hint: with innodb and autocommit, it was), affected rows is 0.

Proposed solution is to turn autocommit off on the mysqli connections and get the count before committing.

dodexahedron · 6 May 2016 02:05

I have submitted a pull request that addresses this issue here: https://github.com/salesagility/SuiteCRM/pull/1355

till · 7 May 2016 00:24

Hi dodexahedron, I tested your pull request and unfortunately this did not fix the issue for me. And by the way, bugfix pull requests like this are supposed to got to the hotfix branch. I made the same mistake not so long ago…

UPDATE: Actually, it did work. I missed one change! Thank you so much, you saved my weekend…

dodexahedron · 9 May 2016 00:06

Glad it worked for you.

Honestly, though, I really think the original “locking” code needs to go away, anyway, as I really can’t see the point in it.

It looks very hacky.
My solution was to work around it and deal with the difference in storage engines, but I’d like to know what the original “lock” code was even for, in the first place, so I can come up with a better solution or just remove it all together.

StephenGSchultz · 9 May 2016 13:21

hi… any guidance for getting campaigns to work for the non-technical/semi-technical like me? Is this an issue already being addressed and will become available in 7.6.2?

till · 9 May 2016 16:23

You can review the code changes here:

https://github.com/salesagility/SuiteCRM/pull/1355/files

Or even simpler just replace these two files:

https://github.com/dodexahedron/SuiteCRM/blob/9a739a77be05149012afa93c27345fcba1bd3d2b/include/database/MysqliManager.php

https://github.com/dodexahedron/SuiteCRM/blob/9a739a77be05149012afa93c27345fcba1bd3d2b/modules/EmailMan/EmailManDelivery.php

itmnetcom · 12 May 2016 03:34

Hi,

Tried the solution. Thank you. But I am getting this:

PHP Parse error: syntax error, unexpected ‘[’ in /httpdocs/include/database/MysqliManager.php on line 125
PHP Fatal error: Call to a member function setOptions() on a non-object in /httpdocs/include/database/DBManagerFactory. php on line 145

Any suggestions?

amariussi · 12 May 2016 09:06

Probably your code is missing some punctuation (semi colon) or parenthesis, curly bracket, square bracket, quote or double quote somewhere.

itmnetcom · 12 May 2016 12:08

Hi,

I got the code from the github links above.

itmnetcom · 12 May 2016 16:43

Tried uploading again, and same error. I replaced with the original files and I no longer get the error.

Any suggestions?

itmnetcom · 12 May 2016 17:46

I tried the manual method on here and I don’t get the errors:

https://github.com/salesagility/SuiteCRM/pull/1355/files

I still get this when I run cron:

PHP Parse error: syntax error, unexpected ‘[’ in /httpdocs/include/database/MysqliManager.php on line 132
PHP Fatal error: Call to a member function setOptions() on a non-object in /httpdocs/include/database/DBManagerFactory.php on line 145

Error is the same

itmnetcom · 12 May 2016 20:35

Hi,

Could you elaborate on how this was fixed? I am using your same versions as well as tried both approaches to fix with no avail. See my resulting errors at the bottom.

Thanks!

till · 12 May 2016 21:59

From the errors it looks like a copy&paste problem. However, I think you guys can revert your changes now and install the upgrade to 7.6.2 instead which should include a fix for this problem.

itmnetcom · 12 May 2016 22:12

That is what i thought as well.

We did a fresh install of 7.6.1 and the issue persists.

StephenGSchultz · 13 May 2016 12:58

Thanks for fix in 7.6.2 - emails now departing queue!