Smarty template load failures in process-control job logs
Closed, DuplicatePublic
Actions

Assigned To

None

Authored By

	jgleeson
	Dec 30 2022, 10:41 AM

Description

We had three different process-control jobs trigger failmail at different times last night. One resulted in a timeout, and the other two resulted in a bus error. They all contained error log entries relating to smarty template files:

2022-12-30 07:02:26,557 ERROR   include(/srv/org.wikimedia.civicrm-files/civicrm/templates_c/en_US//%%CC/CCD/CCD559CC%%string%3A%7Beval+var%3D%24smartySingleUseString%7Csmarty%3Anodefaults%7D.php):  [warning]
2022-12-30 07:02:26,557 ERROR   failed to open stream: No such file or directory
2022-12-30 07:02:26,557 ERROR   Smarty.class.php:1273
2022-12-30 07:02:26,557 ERROR   include(): Failed opening                                              [warning]
2022-12-30 07:02:26,557 ERROR   '/srv/org.wikimedia.civicrm-files/civicrm/templates_c/en_US//%%CC/CCD/CCD559CC%%string%3A%7Beval+var%3D%24smartySingleUseString%7Csmarty%3Anodefaults%7D.php'

The contents of this file is PHP code which seems to be valid:

<?php /* Smarty version 2.6.31, created on 2022-12-30 02:33:58
         compiled from string:%7Beval+var%3D%24smartySingleUseString%7Csmarty:nodefaults%7D */ ?>
<?php require_once(SMARTY_CORE_DIR . 'core.load_plugins.php');
smarty_core_load_plugins(array('plugins' => array(array('block', 'crmScope', 'string:{eval var=$smartySingleUseString|smarty:nodefaults}', 1, false),array('function', 'eval', 'string:{eval var=$smartySingleUseSt
ring|smarty:nodefaults}', 1, false),)), $this); ?>
<?php $this->_tag_stack[] = array('crmScope', array('extensionKey' => "")); $_block_repeat=true;smarty_block_crmScope($this->_tag_stack[count($this->_tag_stack)-1][1], null, $this, $_block_repeat);while ($_block
_repeat) { ob_start(); ?><?php echo smarty_function_eval(array('var' => $this->_tpl_vars['smartySingleUseString']), $this);?>
<?php $_block_content = ob_get_contents(); ob_end_clean(); $_block_repeat=false;echo smarty_block_crmScope($this->_tag_stack[count($this->_tag_stack)-1][1], $_block_content, $this, $_block_repeat); }  array_pop(
$this->_tag_stack); ?>

Job files:
omnimail_recipient_process_unsubscribes-20221230-090501.log
dedupe_civicrm_contacts-20221230-065001.log
omnimail_groupmember_load-20221230-070001.log

Event Timeline

jgleeson created this task.Dec 30 2022, 10:41 AM

Restricted Application added a subscriber: Aklapper. · View Herald TranscriptDec 30 2022, 10:41 AM

It looks like the failures for the jobs happen regardless of the smarty template file errors, so maybe this is just noise?

So my theory is that when caches get cleared that file disappears between the start of the IF and the include - ie it relies on very specific timing & hence only occurs under load since each process has a very small chance of hitting it.

ob_start();
if ($this->_is_compiled($resource_name, $_smarty_compile_path)
        || $this->_compile_resource($resource_name, $_smarty_compile_path))
{
    include($_smarty_compile_path);
}

I'm not 100% sure what is deleting the file - it would be deleted on a cache clear but is not being constantly deleted - eg as of writing the date is

$ date
Sun 01 Jan 2023 12:32:22 AM UTC

and that file has not been modified for 36 hours I think if I'm reading everything correctly

$ ls -altr
total 12
drwxr-s--x 7 www-data www-data 4096 Nov 19 06:25 ..
-rw-r--r-- 1 www-data www-data 1056 Dec 31 01:18 CCD559CC%%string%3A%7Beval+var%3D%24smartySingleUseString%7Csmarty%3Anodefaults%7D.php
drwxr-s--x 2 www-data www-data 4096 Dec 31 01:18 .
eileen@civi1001:~/org.wikimedia.civicrm/drupal/sites/default/files/civicrm/temp

However, I'm assuming some sort of cache clear co-incided with the 3 fail mails

Note the check is effectively