CiviCRM/debugging

This article is a detailed walkthrough of debugging CiviCRM on Drupal (using NetBeans and XDebug). We're specifically debugging the behavior of token replacement and UI representation in the CiviMail component. We've found that if you create 'multi value' custom data that the tokens are not replaced. We're trying to fix that but we're not sure by just reading the code where the problem lies. Hopefully the debugger will provide enough inspection capability to see exactly what's going on; and by extension, what's going wrong.

Call Stacks

The overall process of request routing (Drupal menu system), data retrieval, content creation and output is intricate. It gets even more complex when you look at the internals of CiviCRM.

Since CiviCRM is a Drupal contrib module, a typical request has a call stack like this: index.php

sites/all/modules/contrib/civicrm/CRM/Utils/REST.php.CRM_Utils_REST::ajax:643
sites/all/modules/contrib/civicrm/CRM/Core/Invoke.php.call_user_func:{/var/www/equality-tech.com/www/drupal/sites/all/modules/contrib/civicrm/CRM/Core/Invoke.php:278}:278
sites/all/modules/contrib/civicrm/CRM/Core/Invoke.php.CRM_Core_Invoke::runItem:278
sites/all/modules/contrib/civicrm/CRM/Core/Invoke.php.CRM_Core_Invoke::_invoke:86
sites/all/modules/contrib/civicrm/CRM/Core/Invoke.php.CRM_Core_Invoke::invoke:54
sites/all/modules/contrib/civicrm/drupal/civicrm.module.civicrm_invoke:489
includes/menu.inc.call_user_func_array:{/var/www/equality-tech.com/www/drupal/includes/menu.inc:519}:519
includes/menu.inc.menu_execute_active_handler:519
index.php.{main}:21

Clicking the "Preview as HTML" button from the compose screen of a draft mailing has a call stack like the following. Note that a breakpoint is set at line 536 where $details = CRM_Utils_Token::getTokenDetails($mailingParams, $returnProperties, TRUE, TRUE, NULL, $mailing->getFlattenedTokens());

sites/all/modules/contrib/civicrm/api/v3/Mailing.php.civicrm_api3_mailing_preview:536
sites/all/modules/contrib/civicrm/Civi/API/Provider/MagicFunctionProvider.php.Civi\API\Provider\MagicFunctionProvider->invoke:89
sites/all/modules/contrib/civicrm/Civi/API/Kernel.php.Civi\API\Kernel->run:96
sites/all/modules/contrib/civicrm/Civi/API/Subscriber/ChainSubscriber.php.Civi\API\Subscriber\ChainSubscriber->callNestedApi:196
sites/all/modules/contrib/civicrm/Civi/API/Subscriber/ChainSubscriber.php.Civi\API\Subscriber\ChainSubscriber->onApiRespond:72
sites/all/modules/contrib/civicrm/vendor/symfony/event-dispatcher/Symfony/Component/EventDispatcher/EventDispatcher.php.call_user_func:{/var/www/equality-tech.com/www/drupal/sites/all/modules/contrib/civicrm/vendor/symfony/event-dispatcher/Symfony/Component/EventDispatcher/EventDispatcher.php:164}:164
sites/all/modules/contrib/civicrm/vendor/symfony/event-dispatcher/Symfony/Component/EventDispatcher/EventDispatcher.php.Symfony\Component\EventDispatcher\EventDispatcher->doDispatch:164
sites/all/modules/contrib/civicrm/vendor/symfony/event-dispatcher/Symfony/Component/EventDispatcher/EventDispatcher.php.Symfony\Component\EventDispatcher\EventDispatcher->dispatch:53
sites/all/modules/contrib/civicrm/Civi/API/Kernel.php.Civi\API\Kernel->respond:221
sites/all/modules/contrib/civicrm/Civi/API/Kernel.php.Civi\API\Kernel->run:98
sites/all/modules/contrib/civicrm/api/api.php.civicrm_api:23
sites/all/modules/contrib/civicrm/CRM/Utils/REST.php.CRM_Utils_REST::process:404
sites/all/modules/contrib/civicrm/CRM/Utils/REST.php.CRM_Utils_REST::ajax:640
sites/all/modules/contrib/civicrm/CRM/Core/Invoke.php.call_user_func:{/var/www/equality-tech.com/www/drupal/sites/all/modules/contrib/civicrm/CRM/Core/Invoke.php:278}:278
sites/all/modules/contrib/civicrm/CRM/Core/Invoke.php.CRM_Core_Invoke::runItem:278
sites/all/modules/contrib/civicrm/CRM/Core/Invoke.php.CRM_Core_Invoke::_invoke:86
sites/all/modules/contrib/civicrm/CRM/Core/Invoke.php.CRM_Core_Invoke::invoke:54
sites/all/modules/contrib/civicrm/drupal/civicrm.module.civicrm_invoke:489
includes/menu.inc.call_user_func_array:{/var/www/equality-tech.com/www/drupal/includes/menu.inc:519}:519
includes/menu.inc.menu_execute_active_handler:519

Tokens Tested

tokens tested

token	replaced	$returnProperties	multi
{contact.first_name}	yes	yes	no
{general.wUrl}		no	yes
{custom_40}		yes	yes
{contact.custom_40}		no	yes
{general.custom_40}		no	yes
{general.general.custom_40}		no	yes
{contact.custom_71}		yes*	yes?
{general.articlepath}		no	yes
{general.base}		no	yes
{general.favicon}		no	yes
{general.logo}		no	yes
{general.generator}		no	yes
{stats.activeusers}		no	yes
{stats.admins}		no	yes
{stats.images}		no	yes
{stats.pages}		no	yes
{stats.wUrl}		no	yes
{contact.custom_72}		?	no?
{custom_72}		yes	no?

There is a lot going on with tokens in CiviCRM. There is a whole file CRM/Utils/Token.php to deal with tokens. 45 methods. 2 properties.

It's not just 'getTokens()' that get's called, there is also a function to flattenTokens and getTokenDetails()

on line 524 of civicrm/api/V3/Mailing.php, in civicrm_api3_mailing_preview($params) there is a call to CRM_Mailing_BAO_Mailing::tokenReplace($mailing);

The $mailing is an array with 9 elements, all 'private'

_tableName is "civicrm_mailing"
_fields
_fieldKeys is array[39]

The $body_html is the content of the message and includes token literals

Stepping into that function

loadClass() ends up loading $file CRM/Utils/Token.php (when $class="CRM_Utils_Token")

getTokens($string) is called and returns things like

$tokens['general'][] = "wUrl"

gets passed to _getTokens($prop) and $newTokens is the same as $tokens

eventually tokenReplace() gets called

$details gets populated at line 536 of civicrm/api/V3/Mailing.php and that array has the data, but the keys are like 'custom_40', not general.wUrl

$details[0][2] = array(21) 
[contact_id] "2"
[custom_40] "https://freephile.org/wiki/Main_Page"
[custom_45] "MediaWiki 1.25beta"
[stats.wUrl] "https://freephile.org/wiki/Main_Page"
[stats.articles]
[stats.edits]

$details[1][40][attributes]= array[3] 
'label', 
'data_type', 
'html_type'
$details[1][45][attributes]

echo self::output($result); is called from REST.php

Second pass through

So I ran the debugger again. This time with another "Custom Data Fieldset" and element (Called "Dummy -> Dufus"). The only difference was that this field was 'singular' rather than multi-value.

When I click "Preview as HTML", the value is correctly displayed for the first contact in my "Recipient list". The token is {contact.custom_71}

I used a breakpoint in civicrm/api/V3/Mailing.php at line 536 where $details gets populated from a call to CRM_Utils_Token::getTokenDetails($mailingParams, $returnProperties, TRUE, TRUE, NULL, $mailing->getFlattenedTokens())

$this is a CRM_Mailing_BAO object. $this->tokens is an array[3] with keys html, text, subject

$tokens['html'] is an array[4] with keys contact, general, domain, action
$tokens['html']['contact'] is an array[3] with values 'first_name', 'custom_40' and 'custom_71'
$tokens['html']['general'] is an array[2] with values 'wUrl', 'custom_40'
$tokens['html']['domain'] is an array[1] with values 'address'
$tokens['html']['action'] is an array[1] with values 'optOutUrl'

At this point, $body_html contains the un-evaluated html (meaning the tokens are still present in their literal form).

Interestingly, the $_query is data_select * from $_table civicrm_mailing

$returnProperties is an array[7] with hash, preferred_mail_format, contact_id, display_name, first_name, custom_40, custom_71 all set to (int) 1

Some related constants?

FIELD_BEHAVIOR_NONE 1
FIELD_BEHAVIOR_DEFAULT 2
FIELD_BEHAVIOR_CUSTOM 4
FIELD_LOAD_CURRENT "FIELD_LOAD_CURRENT"
FIELD_LOAD_REVISION "FIELD_LOAD_REVISION"
FIELD_TYPE_NONE "undefined"

The first thing that happens when you step into CRM_Utils_Token::getTokenDetails() is that $mailing->getFlattenedTokens() is called.

There is a $this->tokens, but not a $this->flattenedTokens, so $this->getTokens() on line 873 is a 'no op' (tokens are already defined).

Then we get into a bunch of class autoloader stuff and CRM_Core_Form results in CRM/Core/Form.php being loaded after checking various caches for both class code and interface code. CRM_Core_Form extends HTML_QuickForm_Page

There is a check at line 1218 of Token.php for empty($returnProperties) that would then return all properties, but we do already have defined $returnProperties.

getKeyID is called and for $key "custom_40", it returns "40" since $all is bool 0
getKeyID is called and for $key "custom_71", it returns "71" since $all is bool 0

Those values populate $cfID and in turn $custom[], so that now $custom is array("40", "71") (and also "72" when a singular value custom field is added - indicating that this is the correct place for this info to be found)

We then go through the autoloader mechanism for "CRM_Contact_BAO_Query"

exportableFields() gets called, and the 5th argument in that signature is "$withMultiRecord=FALSE" however I don't think that the callee specifies a value, and so the variable is set to bool(0)

$cacheKeyString ends up being "exportableFields All_1_0_1_2"

and $argString is "exportableFields All_1_0_1_2"

Cache::getItem() is called and Array::value() is called on list which looks small at array(15) but elements like [CRM_PC_CRM_Core_DAO_StateProvince_1_id_name_is_active] is array(3907)

Then we go through the DataObject class methods to create a dsn and connection

some of the queries issued:

SELECT *,  config_backend, locales, locale_custom_strings  FROM civicrm_domain WHERE ( civicrm_domain.id = 1 );
SELECT subtype.*, parent.name as parent, parent.label as parent_label FROM   civicrm_contact_type subtype INNER JOIN civicrm_contact_type parent ON subtype.parent_id = parent.id WHERE  subtype.name IS NOT NULL AND subtype.parent_id IS NOT NULL   AND subtype.is_active = 1 AND parent.is_active = 1 ORDER BY parent.id;
SELECT * FROM civicrm_mailing_group WHERE (  civicrm_mailing_group.id = 511 );
SELECT * FROM civicrm_mailing WHERE ( civicrm_mailing.id = 17 );
SELECT * FROM civicrm_domain WHERE ( civicrm_domain.id = 1 );

As CRM_Core_BAO_Cache::getItem() is called, $data gets set, and cached, by unserializing $dao->data. $data is now array[117]

and includes all the 'custom' fields such as

[custom_40] array[10] 'name', 'title', 'headerPattern', 'import', 'custom_filed_id' => (int) 40, 'text_length', 'data_type'=>"String", 'html_type'=>"Text", 'is_search_range'=>"0"

[custom_71]

That then gets stuffed into $fields array[117]

On line 1605 of CRM/Contact/BAO/Contact.php, $fields gets set as 'exportable'

self::$_exportableFields[$cacheKeyString] = $fields;

but a line later, because $status is false, $fields gets set to the stored value of $_exportableFields[$cacheKeyString]

self::$_exportableFields[$cacheKeyString]; is array[117]

later we get to __construct() in CRM/Contact/BAO/Query.php but $fields is null, so on line 445

$this->_fields = CRM_Contact_BAO_Contact::exportableFields('All', FALSE, TRUE, TRUE);

NOTICE THE 5th parameter ($withMultiRecord) is missing, so the default bool(0) is used. I overrode it and set it to 1

Later, $this->_fields = array_merge($this->_fields, $fields); array[117], array[122] = array[239]

Then on line 455, it says // add any fields provided by hook implementers

but $extFields is array[0] and somehow $this->_fields jumped up to array[255]

The function name / pattern that they are looking for is eqt_civicrm_queryObjects()

Somewhere along the line, around here, Symfony\Component\EventDispatcher::dispatch is called and the $event is an Civi\API\Event\RespondEvent object with several properties including the apiRequest with is an array[9] and apiRequest[fields] is array[123] and apiRequests[fields][custom_40] is an array[21] so this is where the API request and response is happening and dispatch gets called.

Later when runHooks() of Hook.php is called we're looking for a function named "eqt_civicrm_apiWrappers" for the eqt module

At line 1242 of CRM/Utils/Token.php $contactDetails = &$details[0]; and thus

$contactDetails array[1]
$contactDetails[2] array[12]
$contactDetais[2][custom_40] = "https://freephile.org/wiki/Main_Page"
$contactDetais[2][custom_71] = "Not, Never, Well Maybe"

So $details has the data and $contactDetails is a reference to it as well.

On line 1264, there is a foreach loop that runs through $custom and assigns values into $contactDetails[$contactID]["custom_{$cfID}"] but those are ALREADY correct, so is this just a formatter? CustomField::getDisplayValue() is called, which calls self::getDisplayValueCommon(). When CustomField::getDisplayValue($value, $id, &$options, $contactID = NULL, $fieldID = NULL) is called, $value is https://freephile.org/wiki/Main_Page, $id is "40", $options is an array of the custom values we care about with an 'attributes' key and I think $contactID was actually null. In any case, it's clear that these are formatter functions and the 'text' html element is returned as is, unless it's an array in which case it's imploded with commas (line 1309 of CustomField).

We jump back to "api/v3/Mailing.php" line 538 where $mailing->compose() is called. This is defined in CRM/Mailing/BAO/Mailing.php on line 1175. The function has 12 arguments! It does some odd things with "Prepared Templates" ($pTemplates, $pEmails, $pTemplate, $pEmail, $templates all get copied and referenced many times in loops where it's not clear why the data is being manipulated.) The 8th argument of the compose() method is $contactDetails. When compose() is called from line 90 of CRM/Mailing/Page/Preview.php, the $contactDetails are $details[0][$session->get('userID')] But somehow the reference to $contact in all the getTokenData() calls is a lightweight array of 14 elements - not including things like 'general.base' I'm pretty sure those were in $details[0][2]

I then notice that we jumped to MagicFunctionProvider.php where invoke($apiRequest) is called, but only the contact.first_name is replaced correctly in the $result['values']['body_html']

on line 98, kernel.php fills in $apiResponse using $this->respond($apiProvider, $apiRequest, $result); but as just noted, $result doesn't have the custom tokens replaced.

When EventDispatcher::getListeners() is called, $this->listeners has hook_civicrm_post::Activity and hook_civicrm_post::Case so it's not a place where our custom data hooks are involved.

CRM_Utils_Hook_DrupalBase::CRM_Utils_Hook->invoke() is called which builds the module list and runs the hooks.

Then runHooks() in CRM/Utils/Hook.php is called; and it's called with

$civiModules, $fnSuffix, $numParams, &$arg1, &$arg2, &$arg3, &$arg4, &$arg5, &$arg6

where

$civiModules is array[98]
$fnSuffix = civicrm_tokenValues
$numParams = 5
$arg1 is the $contactDetails
$arg2 is array('contact_id' => 2)
$arg3 is null
$arg4 is array[4]
$arg5 is null
$arg6 is null

Note: it also gets called with $fnSuffix = "civicrm_apiWrappers" so the hook function would be hook_civicrm_apiWrappers()

AJAX

The form action is handled by AJAX, and we can see in the $_POST ['entity'] = "Mailing", ['action'] = "create", and ['json'] =

"{"id":"17","domain_id":"1","footer_id":"2","reply_id":"8","unsubscribe_id":"5","resubscribe_id":"6","optout_id":"7","name":"Test of Custom Data","mailing_type":"standalone","from_name":"Greg Rundlett","from_email":"greg@eQuality-tech.com","replyto_email":"greg@eQuality-tech.com","subject":"test","body_html":"<p>Hi {contact.first_name}<br />\nwUrl data is stored as custom 40<br />\nbut the token in the UI is {general.wUrl}<br />\ncustom_40 {custom_40}<br />\ncontact.custom_40 {contact.custom_40}<br />\ngeneral.custom_40 {general.custom_40}<br />\ngeneral.general.custom_40 {general.general.custom_40}</p>\n\n<p>This is the &quot;dufus&quot; {contact.custom_71}</p>\n\n<p>More tests<br />\n{general.articlepath}<br />\n{general.base}<br />\n{general.favicon}<br />\n{general.logo}<br />\n{general.generator}<br />\n{stats.activeusers}<br />\n{stats.admins}<br />\n{stats.images}<br />\n{stats.pages}</p>\n\n<p></p>\n\n<p>And finally, the Bar test of multiple records</p>\n\n<p>\n{contact.custom_72}<br />\n{custom_72}</p>\n","url_tracking":"1","forward_replies":"0","auto_responder":"0","open_tracking":"1","override_verp":"1","created_id":"2","created_date":"2015-10-06 15:49:42","is_archived":"0","visibility":"Public Pages","dedupe_email":"1","hash":"0e95338dfdcbcc5c","email_selection_method":"automatic","is_error":0,"jobs":{},"scheduled_date":null,"groups":{"include":[17],"exclude":[],"base":[]},"mailings":{"include":[],"exclude":[]},"options":{"force_rollback":1},"api.Mailing.preview":{"id":"$value.id"}}"

CRM_Utils_Array

At some point CRM_Utils_Array::value() gets called on $list, which is array[14] with 'contact_id', 'display_name', 'first_name', 'custom_40', 'custom_71', etc. but it does not have a key for 'general.wUrl' so that lookup fails and NULL is returned (the default).

Results

Unfortunately,

Hi {contact.first_name}
wUrl data is stored as custom 40
but the token in the UI is {general.wUrl}
custom_40 {custom_40}
contact.custom_40 {contact.custom_40}
general.custom_40 {general.custom_40}
general.general.custom_40 {general.general.custom_40}

This is the dufus {contact.custom_71}

produces

Hi Greg
wUrl data is stored as custom 40
but the token in the UI is 
custom_40 {custom_40}
contact.custom_40 {contact.custom_40}
general.custom_40 
general.general.custom_40 {general.general.custom_40}

This is the dufus Not, Never, Well Maybe

Resources

1. https://netbeans.org/kb/docs/php/debugging.html#usingAdditionalWatches

HyperText Markup Language = structured text that uses logical links (hyperlinks) between nodes containing text.

Application Programming Interface

Asynchronous JavaScript and XML = A means to exchange data with a server without loading a whole new page.