Difference between revisions of "CiviCRM/debugging"
(adds intro, Call Stack section, and tokens table) |
|||
| (2 intermediate revisions by the same user not shown) | |||
| Line 1: | Line 1: | ||
| − | + | 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 == | == Call Stacks == | ||
| Line 99: | Line 91: | ||
|} | |} | ||
| − | |||
| − | |||
| − | |||
| − | |||
| − | |||
Revision as of 23:13, 28 October 2015
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.
Contents
Call Stacks[edit | edit source]
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[edit | edit source]
| 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? |
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[edit | edit source]
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[1]
$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[edit | edit source]
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 "dufus" {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[edit | edit source]
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[edit | edit source]
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[edit | edit source]
References[edit source]
- ↑ this expands to include 'stats' when you use one of those tokens in your message
