public function runProcess(IProcessMessage $message, IProcessDefinition $process, $taskId)
{
$this->_queueDelays[$taskId] = 0;
$class = $process->getProcessClass();
if (class_exists($class)) {
$ruleClass = 'Qubes\\Defero\\Transport\\IMessageProcessor';
/*
* replaced below with faster implementation:
* if(in_array($ruleClass, class_implements($class))))
*/
if (is_subclass_of($class, $ruleClass)) {
$proc = new $class($message);
} else {
$proc = new $class();
}
if ($proc instanceof IConfigurable) {
$proc->configure($process->getConfig());
}
if ($proc instanceof IRule) {
if ($proc->canProcess()) {
if ($proc instanceof IDeliveryRule) {
$this->_queueDelays[$taskId] = (int) $proc->getSendDelay();
Log::debug("Setting queue delay to " . $this->_queueDelays[$taskId]);
}
return true;
}
return false;
} else {
if ($proc instanceof IProcess) {
return $proc->process();
}
}
}
return false;
}
public function log(IEvent $e)
{
$level = $e->getStr('level');
if (Log::logLevelAllowed($level, $this->_logLevel)) {
// "critical", "error", "warning", "info", "debug"
switch ($level) {
case LogLevel::EMERGENCY:
case LogLevel::ALERT:
case LogLevel::CRITICAL:
$level = 'critical';
break;
case LogLevel::ERROR:
$level = 'error';
break;
case LogLevel::WARNING:
$level = 'warning';
break;
case LogLevel::DEBUG:
$level = 'debug';
break;
case LogLevel::NOTICE:
case LogLevel::INFO:
default:
$level = 'info';
break;
}
$data = ['file' => $e->getStr('file'), 'line' => $e->getStr('line'), 'context' => $e->getArr('context')];
if (CUBEX_CLI) {
$data['cli_command'] = implode(' ', $_SERVER['argv']);
}
\Rollbar::report_message($e->getStr('message'), $level, $data);
}
}
public function runBatch()
{
$results = [];
/**
* @var $message IProcessMessage
*/
foreach ($this->_batch as $taskId => $message) {
$cid = $message->getInt('campaignId');
$started = $message->getInt('startedAt');
$lastSent = $message->getInt('lastSent', 0);
$startId = $message->getInt('startId', null);
$endId = $message->getInt('endId', 0);
$additionalData = $message->getRaw('additionalData', null);
$campaign = new Campaign($cid);
$dataSource = $campaign->getDataSource();
if ($startId == null) {
$startId = $dataSource->getLastId($cid, $taskId);
}
try {
$dataSource->process($taskId, $cid, $started, $lastSent, $startId, $endId, $additionalData);
$results[$taskId] = true;
} catch (\Exception $e) {
Log::error('Campaign ' . $cid . ': ' . $e->getMessage());
$results[$taskId] = false;
}
}
$this->_batch = [];
return $results;
}
/**
* @return int
*/
public function execute()
{
$this->_logger->setInstanceName($this->instanceName);
$this->_pidFile = new PidFile("", $this->instanceName);
echo Shell::colourText((new Figlet("speed"))->render("Defero"), Shell::COLOUR_FOREGROUND_GREEN);
echo "\n";
Log::debug("Setting Default Queue Provider to " . $this->queueService);
Queue::setDefaultQueueProvider($this->queueService);
$queue = Queue::getAccessor();
if ($queue instanceof DatabaseQueue) {
$instance = gethostname();
if ($this->instanceName) {
$instance .= ':' . $this->instanceName;
}
$queue->setOwnKey($instance);
}
$priority = (int) $this->priority;
if (in_array($priority, [1, 5, 10, 99])) {
$this->queueName .= $priority;
} else {
throw new \Exception("Invalid priority. Supported values: 1 , 5, 10, 99");
}
Log::info("Starting to consume queue " . $this->queueName);
$queue->consume(new StdQueue($this->queueName), new CampaignConsumer());
Log::info("Exiting Defero Processor");
}
private function _logReport($now, $rangeStartTime, $rangeProcessed, $rangeTotal, $rangeErrors, $totalDuration, $currentRate, $averageRate, $lastKey)
{
// Log the stats
Log::info("CURRENT RANGE: Run time " . DateTimeHelper::secondsToTime($now - $rangeStartTime) . ", Processed " . $rangeProcessed . " of " . $rangeTotal . " items, " . $rangeErrors . " errors");
Log::info("OVERALL: Run time " . DateTimeHelper::secondsToTime($totalDuration) . ", Processed " . $this->processedItems . " of " . $this->totalItems . " items, " . $this->errors . " errors");
Log::info("Current rate: " . $currentRate . " items/second, Average rate: " . $averageRate . " items/second");
Log::info("Last key: " . $lastKey);
}
public function init($initialiser = null)
{
EventManager::listen(EventManager::CUBEX_QUERY, function (IEvent $e) {
if (CUBEX_CLI) {
Log::debug("Query: " . $e->getStr("query"));
} else {
var_dump($e->getStr("query"));
}
});
}
public function execute()
{
$this->_logger->setInstanceName($this->instanceName);
$this->_pidFile = new PidFile("", $this->instanceName);
while (true) {
$startedAt = time();
$startedAt -= $startedAt % 60;
$collection = new RecordCollection(new Campaign());
if (!$collection->hasMappers()) {
Log::warning('No mappers found');
}
foreach ($collection as $campaign) {
/** @var Campaign $campaign */
if ($campaign->isDue($startedAt)) {
try {
Defero::pushCampaign($campaign->id(), $startedAt);
if (CronParser::isValid($campaign->sendAt)) {
// check average sends on scheduled
$avgEndDate = (new \DateTime())->setTimestamp($startedAt);
$avgStartDate = CronParser::prevRun($campaign->sendAt, $avgEndDate);
$avgEndDate->sub($avgStartDate->diff($avgEndDate));
$avgStartDate->setTime($avgStartDate->format('H') - 1, 0, 0);
$latestStats = MailStatistic::getCampaignStats($campaign->id(), $avgStartDate, $avgEndDate);
$diff = $avgStartDate->diff($avgEndDate);
$diffLatest = max(1, intval($diff->format('%i')) + intval($diff->format('%h') * 60) + intval($diff->format('%d') * 3600));
$latestHourly = $latestStats->sent / $diffLatest * 60;
if ($campaign->warnMin && $latestHourly < $campaign->warnMin || $campaign->warnMax && $latestHourly > $campaign->warnMax) {
Log::warning('Sending outside threshold', ['campaign' => $campaign->id(), 'average' => $latestHourly, 'warnMin' => $campaign->warnMin, 'warnMax' => $campaign->warnMax]);
}
}
} catch (\Exception $e) {
Log::error('Campaign ' . $campaign->id() . ': ' . $e->getMessage() . ' (Line: ' . $e->getLine() . ')');
}
} else {
Log::debug('Campaign ' . $campaign->id() . ' not due');
}
}
$endTime = time();
$endTime -= $endTime % 60;
if ($endTime == $startedAt) {
sleep(30);
}
}
}
/**
* @return int
*/
public function execute()
{
$this->_logger->setInstanceName($this->instanceName);
$this->_pidFile = new PidFile("", $this->instanceName);
echo Shell::colourText((new Figlet("speed"))->render("Defero"), Shell::COLOUR_FOREGROUND_GREEN);
echo "\n";
Log::debug("Setting Default Queue Provider to " . $this->queueService);
Queue::setDefaultQueueProvider($this->queueService);
$queue = Queue::getAccessor();
if ($queue instanceof DatabaseQueue) {
$instance = gethostname();
if ($this->instanceName) {
$instance .= ':' . $this->instanceName;
}
$queue->setOwnKey($instance);
}
Log::info("Starting to consume queue " . $this->queueName);
$queue->consume(new StdQueue($this->queueName), new CampaignQueueConsumer());
Log::info("Exiting Defero Processor");
}
public static function requeueRange(BucketRange $range, $rangeStartTime, $errorMsg)
{
self::_updateProcessingTime($range, $rangeStartTime);
if ($range->requeueCount > self::MAX_REQUEUES) {
self::rangeFailed($range, $rangeStartTime, $errorMsg);
}
Log::info('Re-queueing range ' . $range->id());
$range->requeueCount++;
$range->error = $errorMsg;
$range->processing = 0;
$range->processed = 0;
$range->failed = 0;
$range->processingTime = 0;
$range->randomKey = rand(10000, 12000);
$range->saveChanges();
}
private function _recalculateBatchSize()
{
if (count($this->_batchTimes) < $this->_bufferSize || $this->_fixedSize) {
return;
}
while (count($this->_batchTimes) > $this->_bufferSize) {
array_shift($this->_batchTimes);
}
$avgTime = array_sum($this->_batchTimes) / count($this->_batchTimes);
$newBatchSize = $this->_currentBatchSize;
if ($avgTime < $this->_minBatchTime) {
// Batches are processing too fast. Increase the batch size if possible.
$diff = $this->_minBatchTime - $avgTime;
$proportion = $diff / $avgTime;
$batchIncrease = $this->_currentBatchSize * $proportion;
$newBatchSize = round($this->_currentBatchSize + $batchIncrease);
if ($newBatchSize > $this->_maxBatchSize) {
$newBatchSize = $this->_maxBatchSize;
}
} else {
if ($avgTime > $this->_maxBatchTime) {
// Batches are processing too slowly. Reduce the batch size if possible.
$diff = $avgTime - $this->_maxBatchTime;
$proportion = $diff / $avgTime;
$batchDecrease = $this->_currentBatchSize * $proportion;
$newBatchSize = round($this->_currentBatchSize - $batchDecrease);
if ($newBatchSize < $this->_minBatchSize) {
$newBatchSize = $this->_minBatchSize;
}
}
}
if ($newBatchSize != $this->_currentBatchSize) {
Log::info(sprintf('BatchSizeTuner: Average batch time: %d seconds. Changing batch size from %d to %d', $avgTime, $this->_currentBatchSize, $newBatchSize));
$this->_currentBatchSize = $newBatchSize;
$this->reset();
} else {
Log::debug('BatchSizeTuner: Average batch time: ' . $avgTime . ' seconds, batch size=' . $this->_currentBatchSize);
}
}
public function processRange(BucketRange $range)
{
Log::info('Processing range ' . $range->id());
$this->_statsReporter->nextRange($range);
$this->_processor->resetRangeData();
$listOpts = ['Bucket' => $this->_bucketName, 'MaxKeys' => $this->_batchSize, 'Prefix' => $range->prefix];
try {
if ($this->_processor->shouldSaveProgress() && !empty($range->lastObject)) {
$lastObject = $range->lastObject;
Log::info('Continuing from key ' . $lastObject);
} else {
$lastObject = "";
}
$gcs = $this->_getGCS();
$finished = false;
while (!$finished) {
if ($lastObject != "") {
$listOpts['Marker'] = $lastObject;
}
EventManager::trigger(Events::LIST_BUCKET_START);
$objects = $gcs->listObjects($listOpts);
EventManager::trigger(Events::LIST_BUCKET_END);
$numObjects = count($objects['Contents']);
if ($numObjects > 0) {
$items = [];
foreach ($objects['Contents'] as $object) {
$items[] = new ObjectInfo($object['Key'], $object['Size'], $object['ETag'], $object['LastModified']);
}
$batchProcessed = $this->_processor->processBatch($items);
$lastObjectObj = end($items);
$lastObject = $lastObjectObj->objectKey;
$range->lastObject = $lastObject;
$this->_statsReporter->addItems($numObjects, $batchProcessed);
if ($this->_processor->shouldSaveProgress()) {
$range->rangeData = $this->_processor->getRangeData();
$range->saveChanges();
}
} else {
Log::info('Finished processing range ' . $range->prefix . ' (' . $this->_statsReporter->rangeTotalItems . ' total items)');
$finished = true;
}
$this->_statsReporter->displayReport();
}
RangeManager::rangeProcessed($range, $this->_statsReporter->rangeStartTime, $this->_processor->getRangeData());
} catch (\Exception $e) {
$msg = "Code " . $e->getCode();
$exMsg = $e->getMessage();
if ($exMsg != "") {
$msg .= ": " . $exMsg;
}
Log::error('Error processing range: ' . $msg . "\n\nBacktrace:\n" . $e->getTraceAsString());
if ($this->_processor->isFatalException($e)) {
RangeManager::rangeFailed($range, $this->_statsReporter->rangeStartTime, $msg);
} else {
RangeManager::requeueRange($range, $this->_statsReporter->rangeStartTime, $msg);
}
}
}
public function processRange(TokenRange $range)
{
Log::info("Processing range ID " . $range->id() . " from '" . $range->firstKey . "' to '" . $range->lastKey . "'...");
$this->_batchSizeTuner->reset();
$totalItems = 0;
$processedItems = 0;
$errors = 0;
$rangeStartTime = microtime(true);
$this->_processor->resetRangeData();
try {
$cf = $this->_getCF();
$cols = $this->_processor->requiredColumns();
if (is_numeric($cols)) {
$cols = new SlicePredicate(['slice_range' => $cf->makeSlice('', '', false, $cols)]);
}
$lastKey = $range->firstKey ? $range->firstKey : "";
$rangeLastKey = $range->lastKey ? $range->lastKey : "";
$finished = false;
while (!$finished) {
$this->_batchSizeTuner->nextBatch();
$batchSize = $this->_batchSizeTuner->getBatchSize();
$items = $this->_getKeysWithRetry($cf, $lastKey, $rangeLastKey, $batchSize, $cols);
//$items = $cf->getKeys($lastKey, $rangeLastKey, $batchSize, $cols);
if (!$items) {
Log::info("Found no more items in range");
break;
}
// Skip the last item in the range because this will be the
// first item in the next range
if ($rangeLastKey != "" && last_key($items) == $rangeLastKey) {
array_pop($items);
}
if ($this->_processor->supportsBatchProcessing()) {
try {
EventManager::trigger(Events::PROCESS_BATCH_START);
$batchProcessed = $this->_processor->processBatch($items);
EventManager::trigger(Events::PROCESS_BATCH_END);
$processedItems += $batchProcessed;
$totalItems += count($items);
$this->_statsReporter->processedItems += $batchProcessed;
$this->_statsReporter->totalItems += count($items);
} catch (BatchException $e) {
$errors += $e->getErrorCount();
$this->_statsReporter->errors += $e->getErrorCount();
$msg = $e->getMessage();
if ($msg != "") {
$msg = 'Error processing batch: ' . $msg;
}
Log::error($msg);
if ($this->_processor->stopOnErrors()) {
die;
}
}
} else {
foreach ($items as $key => $itemData) {
try {
if ($this->_processor->processItem($key, $itemData)) {
$processedItems++;
$this->_statsReporter->processedItems++;
}
} catch (ItemException $e) {
$errors++;
$this->_statsReporter->errors++;
Log::error('Error processing item ' . $key . ' : ' . $e->getMessage());
if ($this->_processor->stopOnErrors()) {
die;
}
}
$totalItems++;
$this->_statsReporter->totalItems++;
}
}
$lastKey = last_key($items);
if ($this->_processor->shouldSaveProgress()) {
$this->_scriptProgress->save($range->firstKey, $lastKey);
}
if ($lastKey == $rangeLastKey || count($items) < $batchSize) {
$finished = true;
}
$this->_statsReporter->displayReport($finished, $range, $totalItems, $processedItems, $errors, $rangeStartTime, $lastKey);
if ($errors > 0) {
break;
}
}
$rangeData = $this->_processor->getRangeData();
$range->rangeData = $rangeData ? json_encode($rangeData) : '';
$range->failed = 0;
$range->error = "";
} catch (\Exception $e) {
$msg = "Code " . $e->getCode();
$exMsg = $e->getMessage();
if ($exMsg != "") {
$msg .= ": " . $exMsg;
}
Log::error('Error processing range: ' . $msg . "\n\nBacktrace:\n" . $e->getTraceAsString());
$range->error = $msg;
// Check for non-fatal errors (i.e. Cassandra timeouts)
if ($e instanceof CassandraException && ($e->getCode() == 408 || $e->getCode() == 503 || starts_with($e->getMessage(), 'TSocket: timed out'))) {
$errors++;
} else {
$range->failed = 1;
}
}
if ($errors > 0) {
$this->_requeueRange($range);
} else {
$range->processing = 0;
$range->processed = 1;
$range->processingTime = microtime(true) - $rangeStartTime;
$range->totalItems = $totalItems;
$range->processedItems = $processedItems;
$range->errorCount = $errors;
$range->saveChanges();
}
}
public function process()
{
$userData = $this->_message->getArr('data');
$campaignActive = $this->_message->getInt('campaignActive');
$serviceName = $this->_message->getStr('emailService', $campaignActive ? 'email' : 'email_test');
$name = null;
if (isset($userData['firstname'])) {
$name = $userData['firstname'];
if (isset($userData['lastname'])) {
$name .= ' ' . $userData['lastname'];
}
}
$email = $userData['email'];
Log::info("Sending to {$name} <{$email}> using {$serviceName}");
$mailer = Email::getAccessor($serviceName);
$mailer->addRecipient($email, $name);
$mailer->setSubject($this->_message->getStr('subject'));
switch ($this->_message->getStr('sendType')) {
case SendType::PLAIN_TEXT:
$mailer->setTextBody($this->_message->getStr('plainText') ?: null);
break;
case SendType::HTML_ONLY:
$mailer->setHtmlBody($this->_message->getStr('htmlContent') ?: null);
break;
case SendType::HTML_AND_PLAIN:
$mailer->setTextBody($this->_message->getStr('plainText') ?: null);
$mailer->setHtmlBody($this->_message->getStr('htmlContent') ?: null);
break;
}
if ($mailer instanceof \Cubex\Email\Service\Mail) {
$mailer->addHeader("X-Defero-MID", uniqid(class_shortname($mailer), true));
$mailer->addHeader("X-Defero-PID", getmypid());
}
$campaignId = $this->_message->getStr('campaignId');
if ($mailer instanceof DatabaseMailer) {
$mailer->setCampaignId($campaignId);
}
$mailer->setFrom($this->_message->getStr('senderEmail'), $this->_message->getStr('senderName'));
$returnPath = $this->_message->getStr('returnPath');
if ($returnPath) {
$mailer->setSender($returnPath);
}
$replyTo = $this->_message->getStr('replyTo');
if ($replyTo) {
$mailer->setSender($replyTo);
} else {
$mailer->setSender($this->_message->getStr('senderEmail'), $this->_message->getStr('senderName'));
}
try {
$result = $mailer->send();
} catch (\Exception $e) {
Log::debug($e->getMessage());
$result = false;
}
$hour = time();
$hour -= $hour % 3600;
if (isset($userData['statskey'])) {
$brandStatsCf = MailStatisticsByBrand::cf();
$column = $hour . '|failed|' . $userData['statskey'] . '|' . $userData['language'];
if ($result !== false) {
$column = $hour . '|' . ($campaignActive ? 'sent' : 'test');
$column .= '|' . $userData['statskey'] . '|' . $userData['language'];
$brandStatsCf->increment($campaignId, $column);
} else {
$brandStatsCf->increment($campaignId, $column);
}
}
$statsCf = MailStatistic::cf();
$column = $hour . '|failed-' . $userData['language'];
if ($result !== false) {
$column = $hour . '|' . ($campaignActive ? 'sent' : 'test');
$column .= '-' . $userData['language'];
$statsCf->increment($campaignId, $column);
} else {
$statsCf->increment($campaignId, $column);
}
if (!$userData['user_id']) {
$userData['user_id'] = 0;
}
MailerLog::addLogEntry($userData['user_id'], $campaignId);
if ($result !== false) {
if ($campaignActive) {
SentEmailLog::addLogEntry($userData['user_id'], $campaignId);
}
}
return false;
}