// At first check the maximum load. We shouldn't continue with a high load
if (DI::system()->isMaxLoadReached()) {
- Logger::notice('Pre check: maximum load reached, quitting.');
+ DI::logger()->notice('Pre check: maximum load reached, quitting.');
return;
}
foreach ($r as $entry) {
// The work will be done
if (!self::execute($entry)) {
- Logger::warning('Process execution failed, quitting.', ['entry' => $entry]);
+ DI::logger()->warning('Process execution failed, quitting.', ['entry' => $entry]);
return;
}
if (DI::lock()->acquire(self::LOCK_WORKER, 0)) {
// Count active workers and compare them with a maximum value that depends on the load
if (self::tooMuchWorkers()) {
- Logger::info('Active worker limit reached, quitting.');
+ DI::logger()->info('Active worker limit reached, quitting.');
DI::lock()->release(self::LOCK_WORKER);
return;
}
// Check free memory
if (DI::system()->isMinMemoryReached()) {
- Logger::warning('Memory limit reached, quitting.');
+ DI::logger()->warning('Memory limit reached, quitting.');
DI::lock()->release(self::LOCK_WORKER);
return;
}
// Quit the worker once every cron interval
if (time() > ($starttime + (DI::config()->get('system', 'cron_interval') * 60)) && !self::systemLimitReached()) {
- Logger::info('Process lifetime reached, respawning.');
+ DI::logger()->info('Process lifetime reached, respawning.');
self::unclaimProcess($process);
if (Worker\Daemon::isMode()) {
Worker\IPC::SetJobState(true);
if (Worker\Daemon::isMode()) {
Worker\IPC::SetJobState(false);
}
- Logger::info("Couldn't select a workerqueue entry, quitting process", ['pid' => getmypid()]);
+ DI::logger()->info("Couldn't select a workerqueue entry, quitting process", ['pid' => getmypid()]);
}
/**
{
// Count active workers and compare them with a maximum value that depends on the load
if (self::tooMuchWorkers()) {
- Logger::info('Active worker limit reached, quitting.');
+ DI::logger()->info('Active worker limit reached, quitting.');
return false;
}
// Do we have too few memory?
if (DI::system()->isMinMemoryReached()) {
- Logger::warning('Memory limit reached, quitting.');
+ DI::logger()->warning('Memory limit reached, quitting.');
return false;
}
// Possibly there are too much database connections
if (self::maxConnectionsReached()) {
- Logger::warning('Maximum connections reached, quitting.');
+ DI::logger()->warning('Maximum connections reached, quitting.');
return false;
}
// Possibly there are too much database processes that block the system
if (DI::system()->isMaxProcessesReached()) {
- Logger::warning('Maximum processes reached, quitting.');
+ DI::logger()->warning('Maximum processes reached, quitting.');
return false;
}
// Quit when in maintenance
if (DI::config()->get('system', 'maintenance', false)) {
- Logger::notice('Maintenance mode - quit process', ['pid' => $mypid]);
+ DI::logger()->notice('Maintenance mode - quit process', ['pid' => $mypid]);
return false;
}
// Constantly check the number of parallel database processes
if (DI::system()->isMaxProcessesReached()) {
- Logger::warning('Max processes reached for process', ['pid' => $mypid]);
+ DI::logger()->warning('Max processes reached for process', ['pid' => $mypid]);
return false;
}
// Constantly check the number of available database connections to let the frontend be accessible at any time
if (self::maxConnectionsReached()) {
- Logger::warning('Max connection reached for process', ['pid' => $mypid]);
+ DI::logger()->warning('Max connection reached for process', ['pid' => $mypid]);
return false;
}
}
if (empty($argv)) {
- Logger::warning('Parameter is empty', ['queue' => $queue]);
+ DI::logger()->warning('Parameter is empty', ['queue' => $queue]);
return false;
}
}
if (!self::validateInclude($include)) {
- Logger::warning('Include file is not valid', ['file' => $argv[0]]);
+ DI::logger()->warning('Include file is not valid', ['file' => $argv[0]]);
$stamp = (float)microtime(true);
DBA::delete('workerqueue', ['id' => $queue['id']]);
self::$db_duration = (microtime(true) - $stamp);
self::$db_duration = (microtime(true) - $stamp);
self::$db_duration_write += (microtime(true) - $stamp);
} else {
- Logger::warning('Function does not exist', ['function' => $funcname]);
+ DI::logger()->warning('Function does not exist', ['function' => $funcname]);
$stamp = (float)microtime(true);
DBA::delete('workerqueue', ['id' => $queue['id']]);
self::$db_duration = (microtime(true) - $stamp);
{
$cooldown = DI::config()->get('system', 'worker_cooldown', 0);
if ($cooldown > 0) {
- Logger::debug('Wait for cooldown.', ['cooldown' => $cooldown]);
+ DI::logger()->debug('Wait for cooldown.', ['cooldown' => $cooldown]);
if ($cooldown < 1) {
usleep($cooldown * 1000000);
} else {
while ($load = System::getLoadAvg($processes_cooldown != 0)) {
if (($load_cooldown > 0) && ($load['average1'] > $load_cooldown)) {
if (!$sleeping) {
- Logger::info('Load induced pre execution cooldown.', ['max' => $load_cooldown, 'load' => $load, 'called-by' => System::callstack(1)]);
+ DI::logger()->info('Load induced pre execution cooldown.', ['max' => $load_cooldown, 'load' => $load, 'called-by' => System::callstack(1)]);
$sleeping = true;
}
sleep(1);
}
if (($processes_cooldown > 0) && ($load['scheduled'] > $processes_cooldown)) {
if (!$sleeping) {
- Logger::info('Process induced pre execution cooldown.', ['max' => $processes_cooldown, 'load' => $load, 'called-by' => System::callstack(1)]);
+ DI::logger()->info('Process induced pre execution cooldown.', ['max' => $processes_cooldown, 'load' => $load, 'called-by' => System::callstack(1)]);
$sleeping = true;
}
sleep(1);
}
if ($sleeping) {
- Logger::info('Cooldown ended.', ['max-load' => $load_cooldown, 'max-processes' => $processes_cooldown, 'load' => $load, 'called-by' => System::callstack(1)]);
+ DI::logger()->info('Cooldown ended.', ['max-load' => $load_cooldown, 'max-processes' => $processes_cooldown, 'load' => $load, 'called-by' => System::callstack(1)]);
}
}
// If $max is set we will use the processlist to determine the current number of connections
// The processlist only shows entries of the current user
if ($max != 0) {
- Logger::info('Connection usage (user values)', ['working' => $used, 'sleeping' => $sleep, 'max' => $max]);
+ DI::logger()->info('Connection usage (user values)', ['working' => $used, 'sleeping' => $sleep, 'max' => $max]);
$level = ($used / $max) * 100;
if ($level >= $maxlevel) {
- Logger::warning('Maximum level (' . $maxlevel . '%) of user connections reached: ' . $used .'/' . $max);
+ DI::logger()->warning('Maximum level (' . $maxlevel . '%) of user connections reached: ' . $used .'/' . $max);
return true;
}
}
if ($used == 0) {
return false;
}
- Logger::info('Connection usage (system values)', ['working' => $used, 'sleeping' => $sleep, 'max' => $max]);
+ DI::logger()->info('Connection usage (system values)', ['working' => $used, 'sleeping' => $sleep, 'max' => $max]);
$level = $used / $max * 100;
if ($level < $maxlevel) {
return false;
}
- Logger::warning('Maximum level (' . $level . '%) of system connections reached: ' . $used . '/' . $max);
+ DI::logger()->warning('Maximum level (' . $level . '%) of system connections reached: ' . $used . '/' . $max);
return true;
}
$high_running = self::processWithPriorityActive($top_priority);
if (!$high_running && ($top_priority > self::PRIORITY_UNDEFINED) && ($top_priority < self::PRIORITY_NEGLIGIBLE)) {
- Logger::info('Jobs with a higher priority are waiting but none is executed. Open a fastlane.', ['priority' => $top_priority]);
+ DI::logger()->info('Jobs with a higher priority are waiting but none is executed. Open a fastlane.', ['priority' => $top_priority]);
$queues = $active + 1;
}
}
- Logger::info('Load: ' . $load . '/' . $maxsysload . ' - processes: ' . $deferred . '/' . $active . '/' . $waiting_processes . $processlist . ' - maximum: ' . $queues . '/' . $maxqueues);
+ DI::logger()->info('Load: ' . $load . '/' . $maxsysload . ' - processes: ' . $deferred . '/' . $active . '/' . $waiting_processes . $processlist . ' - maximum: ' . $queues . '/' . $maxqueues);
// Are there fewer workers running as possible? Then fork a new one.
if (!DI::config()->get('system', 'worker_dont_fork', false) && ($queues > ($active + 1)) && self::entriesExists() && !self::systemLimitReached()) {
- Logger::info('There are fewer workers as possible, fork a new worker.', ['active' => $active, 'queues' => $queues]);
+ DI::logger()->info('There are fewer workers as possible, fork a new worker.', ['active' => $active, 'queues' => $queues]);
if (Worker\Daemon::isMode()) {
Worker\IPC::SetJobState(true);
} else {
&& !DBA::exists('workerqueue', ["`done` AND `executed` > ?", DateTimeFormat::utc('now - ' . $max_idletime . ' second')])
) {
DI::cache()->set(self::LAST_CHECK, time(), Duration::HOUR);
- Logger::info('The last worker execution had been too long ago.', ['last' => $last_check, 'last-check' => $last_date, 'seconds' => $max_idletime, 'load' => $load, 'max_load' => $maxsysload, 'active_worker' => $active, 'max_worker' => $maxqueues]);
+ DI::logger()->info('The last worker execution had been too long ago.', ['last' => $last_check, 'last-check' => $last_date, 'seconds' => $max_idletime, 'load' => $load, 'max_load' => $maxsysload, 'active_worker' => $active, 'max_worker' => $maxqueues]);
return false;
} elseif ($max_idletime > 0) {
- Logger::debug('Maximum idletime not reached.', ['last' => $last_check, 'last-check' => $last_date, 'seconds' => $max_idletime, 'load' => $load, 'max_load' => $maxsysload, 'active_worker' => $active, 'max_worker' => $maxqueues]);
+ DI::logger()->debug('Maximum idletime not reached.', ['last' => $last_check, 'last-check' => $last_date, 'seconds' => $max_idletime, 'load' => $load, 'max_load' => $maxsysload, 'active_worker' => $active, 'max_worker' => $maxqueues]);
}
}
}
{
$priority = self::nextPriority();
if (empty($priority)) {
- Logger::info('No tasks found');
+ DI::logger()->info('No tasks found');
return [];
}
}
DBA::close($tasks);
- Logger::info('Found:', ['priority' => $priority, 'id' => $ids]);
+ DI::logger()->info('Found:', ['priority' => $priority, 'id' => $ids]);
return $ids;
}
foreach ($priorities as $priority) {
if (!empty($waiting[$priority]) && empty($running[$priority])) {
- Logger::info('No running worker found with priority {priority} - assigning it.', ['priority' => $priority]);
+ DI::logger()->info('No running worker found with priority {priority} - assigning it.', ['priority' => $priority]);
return $priority;
}
}
$i = 0;
foreach ($running as $priority => $workers) {
if ($workers < $limit[$i++]) {
- Logger::info('Priority {priority} has got {workers} workers out of a limit of {limit}', ['priority' => $priority, 'workers' => $workers, 'limit' => $limit[$i - 1]]);
+ DI::logger()->info('Priority {priority} has got {workers} workers out of a limit of {limit}', ['priority' => $priority, 'workers' => $workers, 'limit' => $limit[$i - 1]]);
return $priority;
}
}
if (!empty($waiting)) {
$priority = array_keys($waiting)[0];
- Logger::info('No underassigned priority found, now taking the highest priority.', ['priority' => $priority]);
+ DI::logger()->info('No underassigned priority found, now taking the highest priority.', ['priority' => $priority]);
return $priority;
}
$stamp = (float)microtime(true);
foreach ($worker as $worker_pid => $worker_ids) {
- Logger::info('Set queue entry', ['pid' => $worker_pid, 'ids' => $worker_ids]);
+ DI::logger()->info('Set queue entry', ['pid' => $worker_pid, 'ids' => $worker_ids]);
DBA::update(
'workerqueue',
['executed' => DateTimeFormat::utcNow(), 'pid' => $worker_pid],
private static function forkProcess(bool $do_cron)
{
if (DI::system()->isMinMemoryReached()) {
- Logger::warning('Memory limit reached - quitting');
+ DI::logger()->warning('Memory limit reached - quitting');
return;
}
$pid = pcntl_fork();
if ($pid == -1) {
DBA::connect();
- Logger::warning('Could not spawn worker');
+ DI::logger()->warning('Could not spawn worker');
return;
} elseif ($pid) {
// The parent process continues here
DBA::connect();
Worker\IPC::SetJobState(true, $pid);
- Logger::info('Spawned new worker', ['pid' => $pid]);
+ DI::logger()->info('Spawned new worker', ['pid' => $pid]);
$cycles = 0;
while (Worker\IPC::JobsExists($pid) && (++$cycles < 100)) {
usleep(10000);
}
- Logger::info('Spawned worker is ready', ['pid' => $pid, 'wait_cycles' => $cycles]);
+ DI::logger()->info('Spawned worker is ready', ['pid' => $pid, 'wait_cycles' => $cycles]);
return;
}
usleep(10000);
}
- Logger::info('Worker spawned', ['pid' => $process->pid, 'wait_cycles' => $cycles]);
+ DI::logger()->info('Worker spawned', ['pid' => $process->pid, 'wait_cycles' => $cycles]);
self::processQueue($do_cron, $process);
Worker\IPC::SetJobState(false, $process->pid);
DI::process()->delete($process);
- Logger::info('Worker ended', ['pid' => $process->pid]);
+ DI::logger()->info('Worker ended', ['pid' => $process->pid]);
exit();
}
$added = 0;
if (!is_int($priority) || !in_array($priority, self::PRIORITIES)) {
- Logger::warning('Invalid priority', ['priority' => $priority, 'command' => $command]);
+ DI::logger()->warning('Invalid priority', ['priority' => $priority, 'command' => $command]);
$priority = self::PRIORITY_MEDIUM;
}
$new_retrial = $retrial;
}
}
- Logger::notice('New retrial for task', ['id' => $queue['id'], 'created' => $queue['created'], 'old' => $queue['retrial'], 'new' => $new_retrial]);
+ DI::logger()->notice('New retrial for task', ['id' => $queue['id'], 'created' => $queue['created'], 'old' => $queue['retrial'], 'new' => $new_retrial]);
return $new_retrial;
}
$new_retrial = self::getNextRetrial($queue, $max_level);
if ($new_retrial > $max_level) {
- Logger::notice('The task exceeded the maximum retry count', ['id' => $id, 'created' => $queue['created'], 'old_prio' => $queue['priority'], 'old_retrial' => $queue['retrial'], 'max_level' => $max_level, 'retrial' => $new_retrial]);
+ DI::logger()->notice('The task exceeded the maximum retry count', ['id' => $id, 'created' => $queue['created'], 'old_prio' => $queue['priority'], 'old_retrial' => $queue['retrial'], 'max_level' => $max_level, 'retrial' => $new_retrial]);
return false;
}
$priority = self::PRIORITY_NEGLIGIBLE;
}
- Logger::info('Deferred task', ['id' => $id, 'retrial' => $new_retrial, 'created' => $queue['created'], 'next_execution' => $next, 'old_prio' => $queue['priority'], 'new_prio' => $priority]);
+ DI::logger()->info('Deferred task', ['id' => $id, 'retrial' => $new_retrial, 'created' => $queue['created'], 'next_execution' => $next, 'old_prio' => $queue['priority'], 'new_prio' => $priority]);
$stamp = (float)microtime(true);
$fields = ['retrial' => $new_retrial, 'next_try' => $next, 'executed' => DBA::NULL_DATETIME, 'pid' => 0, 'priority' => $priority];
$start = strtotime(DI::config()->get('system', 'maintenance_start')) % 86400;
$end = strtotime(DI::config()->get('system', 'maintenance_end')) % 86400;
- Logger::info('Maintenance window', ['start' => date('H:i:s', $start), 'end' => date('H:i:s', $end)]);
+ DI::logger()->info('Maintenance window', ['start' => date('H:i:s', $start), 'end' => date('H:i:s', $end)]);
if ($check_last_execution) {
// Calculate the window duration
// Quit when the last cron execution had been after the previous window
$last_cron = DI::keyValue()->get('last_cron_daily');
if ($last_cron + $duration > time()) {
- Logger::info('The Daily cron had been executed recently', ['last' => date(DateTimeFormat::MYSQL, $last_cron), 'start' => date('H:i:s', $start), 'end' => date('H:i:s', $end)]);
+ DI::logger()->info('The Daily cron had been executed recently', ['last' => date(DateTimeFormat::MYSQL, $last_cron), 'start' => date('H:i:s', $start), 'end' => date('H:i:s', $end)]);
return false;
}
}
}
if ($execute) {
- Logger::info('We are inside the maintenance window', ['current' => date('H:i:s', $current), 'start' => date('H:i:s', $start), 'end' => date('H:i:s', $end)]);
+ DI::logger()->info('We are inside the maintenance window', ['current' => date('H:i:s', $current), 'start' => date('H:i:s', $start), 'end' => date('H:i:s', $end)]);
} else {
- Logger::info('We are outside the maintenance window', ['current' => date('H:i:s', $current), 'start' => date('H:i:s', $start), 'end' => date('H:i:s', $end)]);
+ DI::logger()->info('We are outside the maintenance window', ['current' => date('H:i:s', $current), 'start' => date('H:i:s', $start), 'end' => date('H:i:s', $end)]);
}
return $execute;
namespace Friendica\Core\Worker;
-use Friendica\Core\Logger;
use Friendica\Core\Worker;
use Friendica\Database\DBA;
use Friendica\DI;
*/
public static function run()
{
- Logger::info('Add cron entries');
+ DI::logger()->info('Add cron entries');
// Check for spooled items
Worker::add(['priority' => Worker::PRIORITY_HIGH, 'force_priority' => true], 'SpoolPost');
// How long is the process already running?
$duration = (time() - strtotime($entry["executed"])) / 60;
if ($duration > $max_duration) {
- Logger::warning('Worker process took too much time - killed', ['duration' => number_format($duration, 3), 'max' => $max_duration, 'id' => $entry["id"], 'pid' => $entry["pid"], 'command' => $command]);
+ DI::logger()->warning('Worker process took too much time - killed', ['duration' => number_format($duration, 3), 'max' => $max_duration, 'id' => $entry["id"], 'pid' => $entry["pid"], 'command' => $command]);
posix_kill($entry["pid"], SIGTERM);
// We killed the stale process.
DBA::update('workerqueue', ['executed' => DBA::NULL_DATETIME, 'created' => DateTimeFormat::utcNow(), 'priority' => $new_priority, 'pid' => 0], ['id' => $entry["id"]]
);
} else {
- Logger::info('Process runtime is okay', ['duration' => number_format($duration, 3), 'max' => $max_duration, 'id' => $entry["id"], 'pid' => $entry["pid"], 'command' => $command]);
+ DI::logger()->info('Process runtime is okay', ['duration' => number_format($duration, 3), 'max' => $max_duration, 'id' => $entry["id"], 'pid' => $entry["pid"], 'command' => $command]);
}
}
}
$deliveries = DBA::p("SELECT `item-uri`.`uri` AS `inbox`, MAX(`gsid`) AS `gsid`, MAX(`shared`) AS `shared`, MAX(`failed`) AS `failed` FROM `post-delivery` INNER JOIN `item-uri` ON `item-uri`.`id` = `post-delivery`.`inbox-id` LEFT JOIN `inbox-status` ON `inbox-status`.`url` = `item-uri`.`uri` GROUP BY `inbox` ORDER BY RAND()");
while ($delivery = DBA::fetch($deliveries)) {
if ($delivery['failed'] > 0) {
- Logger::info('Removing failed deliveries', ['inbox' => $delivery['inbox'], 'failed' => $delivery['failed']]);
+ DI::logger()->info('Removing failed deliveries', ['inbox' => $delivery['inbox'], 'failed' => $delivery['failed']]);
Post\Delivery::removeFailed($delivery['inbox']);
}
if (($delivery['failed'] == 0) && $delivery['shared'] && !empty($delivery['gsid']) && GServer::isReachableById($delivery['gsid'])) {
$result = ActivityPub\Delivery::deliver($delivery['inbox']);
- Logger::info('Directly deliver inbox', ['inbox' => $delivery['inbox'], 'result' => $result['success']]);
+ DI::logger()->info('Directly deliver inbox', ['inbox' => $delivery['inbox'], 'result' => $result['success']]);
continue;
} elseif ($delivery['failed'] < 3) {
$priority = Worker::PRIORITY_HIGH;
}
if (Worker::add(['priority' => $priority, 'force_priority' => true], 'APDelivery', '', 0, $delivery['inbox'], 0)) {
- Logger::info('Priority for APDelivery worker adjusted', ['inbox' => $delivery['inbox'], 'failed' => $delivery['failed'], 'priority' => $priority]);
+ DI::logger()->info('Priority for APDelivery worker adjusted', ['inbox' => $delivery['inbox'], 'failed' => $delivery['failed'], 'priority' => $priority]);
}
}
// Optimizing this table only last seconds
if (DI::config()->get('system', 'optimize_tables')) {
- Logger::info('Optimize start');
+ DI::logger()->info('Optimize start');
DBA::optimizeTable('post-delivery');
- Logger::info('Optimize end');
+ DI::logger()->info('Optimize end');
}
}
{
foreach(DI::deliveryQueueItemRepo()->selectAggregateByServerId() as $delivery) {
if ($delivery->failed > 0) {
- Logger::info('Removing failed deliveries', ['gsid' => $delivery->targetServerId, 'failed' => $delivery->failed]);
+ DI::logger()->info('Removing failed deliveries', ['gsid' => $delivery->targetServerId, 'failed' => $delivery->failed]);
DI::deliveryQueueItemRepo()->removeFailedByServerId($delivery->targetServerId, DI::config()->get('system', 'worker_defer_limit'));
}
}
if (Worker::add(['priority' => $priority, 'force_priority' => true], 'BulkDelivery', $delivery->targetServerId)) {
- Logger::info('Priority for BulkDelivery worker adjusted', ['gsid' => $delivery->targetServerId, 'failed' => $delivery->failed, 'priority' => $priority]);
+ DI::logger()->info('Priority for BulkDelivery worker adjusted', ['gsid' => $delivery->targetServerId, 'failed' => $delivery->failed, 'priority' => $priority]);
}
}
// Optimizing this table only last seconds
if (DI::config()->get('system', 'optimize_tables')) {
- Logger::info('Optimize start');
+ DI::logger()->info('Optimize start');
DI::deliveryQueueItemRepo()->optimizeStorage();
- Logger::info('Optimize end');
+ DI::logger()->info('Optimize end');
}
}
'datetime' => $contact['created'],
'hash' => Strings::getRandomHex()
];
- Logger::notice('Adding missing intro', ['fields' => $fields]);
+ DI::logger()->notice('Adding missing intro', ['fields' => $fields]);
DBA::insert('intro', $fields);
}
}