From 2e602afd3e1be80dc0e14db98ce0445c58d5231c Mon Sep 17 00:00:00 2001 From: Philipp Holzer Date: Sun, 30 Dec 2018 21:42:56 +0100 Subject: [PATCH] Add Monolog --- bin/auth_ejabberd.php | 5 +- bin/console.php | 6 +- bin/daemon.php | 18 +- bin/worker.php | 5 +- composer.json | 3 +- composer.lock | 127 +++++- include/api.php | 78 ++-- index.php | 6 +- mod/acl.php | 2 +- src/App.php | 33 +- src/BaseObject.php | 5 +- src/Core/Addon.php | 11 +- src/Core/Logger.php | 416 +++++++++++++++----- src/Util/Logger/FriendicaDevelopHandler.php | 50 +++ src/Util/LoggerFactory.php | 116 ++++++ tests/include/ApiTest.php | 8 + tests/src/BaseObjectTest.php | 5 +- update.php | 6 +- 18 files changed, 736 insertions(+), 164 deletions(-) create mode 100644 src/Util/Logger/FriendicaDevelopHandler.php create mode 100644 src/Util/LoggerFactory.php diff --git a/bin/auth_ejabberd.php b/bin/auth_ejabberd.php index e8a7b4963..a6f30d201 100755 --- a/bin/auth_ejabberd.php +++ b/bin/auth_ejabberd.php @@ -34,6 +34,7 @@ use Friendica\App; use Friendica\Util\ExAuth; +use Friendica\Util\LoggerFactory; if (sizeof($_SERVER["argv"]) == 0) { die(); @@ -51,7 +52,9 @@ chdir($directory); require dirname(__DIR__) . '/vendor/autoload.php'; -$a = new App(dirname(__DIR__)); +$logger = LoggerFactory::create('auth_ejabberd'); + +$a = new App(dirname(__DIR__), $logger); if ($a->getMode()->isNormal()) { $oAuth = new ExAuth(); diff --git a/bin/console.php b/bin/console.php index c39df953f..9264e3eee 100755 --- a/bin/console.php +++ b/bin/console.php @@ -3,7 +3,11 @@ require dirname(__DIR__) . '/vendor/autoload.php'; -$a = new Friendica\App(dirname(__DIR__)); +use Friendica\Util\LoggerFactory; + +$logger = LoggerFactory::create('console'); + +$a = new Friendica\App(dirname(__DIR__), $logger); \Friendica\BaseObject::setApp($a); (new Friendica\Core\Console($argv))->execute(); diff --git a/bin/daemon.php b/bin/daemon.php index e60e32b19..c7b321c11 100755 --- a/bin/daemon.php +++ b/bin/daemon.php @@ -9,9 +9,9 @@ use Friendica\App; use Friendica\Core\Config; -use Friendica\Core\Logger; use Friendica\Core\Worker; use Friendica\Database\DBA; +use Friendica\Util\LoggerFactory; // Get options $shortopts = 'f'; @@ -32,7 +32,9 @@ if (!file_exists("boot.php") && (sizeof($_SERVER["argv"]) != 0)) { require dirname(__DIR__) . '/vendor/autoload.php'; -$a = new App(dirname(__DIR__)); +$logger = LoggerFactory::create('daemon'); + +$a = new App(dirname(__DIR__), $logger); if ($a->getMode()->isInstall()) { die("Friendica isn't properly installed yet.\n"); @@ -102,7 +104,7 @@ if ($mode == "stop") { unlink($pidfile); - Logger::log("Worker daemon process $pid was killed.", Logger::DEBUG); + $logger->notice("Worker daemon process was killed", ["pid" => $pid]); Config::set('system', 'worker_daemon_mode', false); die("Worker daemon process $pid was killed.\n"); @@ -112,7 +114,7 @@ if (!empty($pid) && posix_kill($pid, 0)) { die("Daemon process $pid is already running.\n"); } -Logger::log('Starting worker daemon.', Logger::DEBUG); +$logger->notice('Starting worker daemon.', ["pid" => $pid]); if (!$foreground) { echo "Starting worker daemon.\n"; @@ -160,7 +162,7 @@ $last_cron = 0; // Now running as a daemon. while (true) { if (!$do_cron && ($last_cron + $wait_interval) < time()) { - Logger::log('Forcing cron worker call.', Logger::DEBUG); + $logger->info('Forcing cron worker call.', ["pid" => $pid]); $do_cron = true; } @@ -174,7 +176,7 @@ while (true) { $last_cron = time(); } - Logger::log("Sleeping", Logger::DEBUG); + $logger->info("Sleeping", ["pid" => $pid]); $start = time(); do { $seconds = (time() - $start); @@ -191,10 +193,10 @@ while (true) { if ($timeout) { $do_cron = true; - Logger::log("Woke up after $wait_interval seconds.", Logger::DEBUG); + $logger->info("Woke up after $wait_interval seconds.", ["pid" => $pid, 'sleep' => $wait_interval]); } else { $do_cron = false; - Logger::log("Worker jobs are calling to be forked.", Logger::DEBUG); + $logger->info("Worker jobs are calling to be forked.", ["pid" => $pid]); } } diff --git a/bin/worker.php b/bin/worker.php index 78b7a58a0..a64b6a833 100755 --- a/bin/worker.php +++ b/bin/worker.php @@ -8,6 +8,7 @@ use Friendica\App; use Friendica\Core\Config; use Friendica\Core\Worker; use Friendica\Core\Update; +use Friendica\Util\LoggerFactory; // Get options $shortopts = 'sn'; @@ -28,7 +29,9 @@ if (!file_exists("boot.php") && (sizeof($_SERVER["argv"]) != 0)) { require dirname(__DIR__) . '/vendor/autoload.php'; -$a = new App(dirname(__DIR__)); +$logger = LoggerFactory::create('worker'); + +$a = new App(dirname(__DIR__), $logger); // Check the database structure and possibly fixes it Update::check(true); diff --git a/composer.json b/composer.json index 8ac4c3772..2f254877d 100644 --- a/composer.json +++ b/composer.json @@ -42,7 +42,8 @@ "npm-asset/jgrowl": "^1.4", "npm-asset/fullcalendar": "^3.0.1", "npm-asset/cropperjs": "1.2.2", - "npm-asset/imagesloaded": "4.1.4" + "npm-asset/imagesloaded": "4.1.4", + "monolog/monolog": "^1.24" }, "repositories": [ { diff --git a/composer.lock b/composer.lock index 1e87dab8a..9d5728fc2 100644 --- a/composer.lock +++ b/composer.lock @@ -4,7 +4,7 @@ "Read more about it at https://getcomposer.org/doc/01-basic-usage.md#installing-dependencies", "This file is @generated automatically" ], - "content-hash": "51f7b3ab622038d7ef62ed03c06b48d0", + "content-hash": "8cf7268fbcae8a22a518b9e7727eab84", "packages": [ { "name": "asika/simple-console", @@ -809,6 +809,84 @@ ], "time": "2018-09-01T15:05:15+00:00" }, + { + "name": "monolog/monolog", + "version": "1.24.0", + "source": { + "type": "git", + "url": "https://github.com/Seldaek/monolog.git", + "reference": "bfc9ebb28f97e7a24c45bdc3f0ff482e47bb0266" + }, + "dist": { + "type": "zip", + "url": "https://api.github.com/repos/Seldaek/monolog/zipball/bfc9ebb28f97e7a24c45bdc3f0ff482e47bb0266", + "reference": "bfc9ebb28f97e7a24c45bdc3f0ff482e47bb0266", + "shasum": "" + }, + "require": { + "php": ">=5.3.0", + "psr/log": "~1.0" + }, + "provide": { + "psr/log-implementation": "1.0.0" + }, + "require-dev": { + "aws/aws-sdk-php": "^2.4.9 || ^3.0", + "doctrine/couchdb": "~1.0@dev", + "graylog2/gelf-php": "~1.0", + "jakub-onderka/php-parallel-lint": "0.9", + "php-amqplib/php-amqplib": "~2.4", + "php-console/php-console": "^3.1.3", + "phpunit/phpunit": "~4.5", + "phpunit/phpunit-mock-objects": "2.3.0", + "ruflin/elastica": ">=0.90 <3.0", + "sentry/sentry": "^0.13", + "swiftmailer/swiftmailer": "^5.3|^6.0" + }, + "suggest": { + "aws/aws-sdk-php": "Allow sending log messages to AWS services like DynamoDB", + "doctrine/couchdb": "Allow sending log messages to a CouchDB server", + "ext-amqp": "Allow sending log messages to an AMQP server (1.0+ required)", + "ext-mongo": "Allow sending log messages to a MongoDB server", + "graylog2/gelf-php": "Allow sending log messages to a GrayLog2 server", + "mongodb/mongodb": "Allow sending log messages to a MongoDB server via PHP Driver", + "php-amqplib/php-amqplib": "Allow sending log messages to an AMQP server using php-amqplib", + "php-console/php-console": "Allow sending log messages to Google Chrome", + "rollbar/rollbar": "Allow sending log messages to Rollbar", + "ruflin/elastica": "Allow sending log messages to an Elastic Search server", + "sentry/sentry": "Allow sending log messages to a Sentry server" + }, + "type": "library", + "extra": { + "branch-alias": { + "dev-master": "2.0.x-dev" + } + }, + "autoload": { + "psr-4": { + "Monolog\\": "src/Monolog" + } + }, + "notification-url": "https://packagist.org/downloads/", + "license": [ + "MIT" + ], + "authors": [ + { + "name": "Jordi Boggiano", + "email": "j.boggiano@seld.be", + "homepage": "http://seld.be" + } + ], + "description": "Sends your logs to files, sockets, inboxes, databases and various web services", + "homepage": "http://github.com/Seldaek/monolog", + "keywords": [ + "log", + "logging", + "psr-3" + ], + "time": "2018-11-05T09:00:11+00:00" + }, { "name": "npm-asset/cropperjs", "version": "1.2.2", @@ -1810,6 +1888,53 @@ ], "time": "2016-08-06T14:39:51+00:00" }, + { + "name": "psr/log", + "version": "1.1.0", + "source": { + "type": "git", + "url": "https://github.com/php-fig/log.git", + "reference": "6c001f1daafa3a3ac1d8ff69ee4db8e799a654dd" + }, + "dist": { + "type": "zip", + "url": "https://api.github.com/repos/php-fig/log/zipball/6c001f1daafa3a3ac1d8ff69ee4db8e799a654dd", + "reference": "6c001f1daafa3a3ac1d8ff69ee4db8e799a654dd", + "shasum": "" + }, + "require": { + "php": ">=5.3.0" + }, + "type": "library", + "extra": { + "branch-alias": { + "dev-master": "1.0.x-dev" + } + }, + "autoload": { + "psr-4": { + "Psr\\Log\\": "Psr/Log/" + } + }, + "notification-url": "https://packagist.org/downloads/", + "license": [ + "MIT" + ], + "authors": [ + { + "name": "PHP-FIG", + "homepage": "http://www.php-fig.org/" + } + ], + "description": "Common interface for logging libraries", + "homepage": "https://github.com/php-fig/log", + "keywords": [ + "log", + "psr", + "psr-3" + ], + "time": "2018-11-20T15:27:04+00:00" + }, { "name": "seld/cli-prompt", "version": "1.0.3", diff --git a/include/api.php b/include/api.php index f28f18253..57bbd6399 100644 --- a/include/api.php +++ b/include/api.php @@ -55,6 +55,8 @@ define('API_METHOD_GET', 'GET'); define('API_METHOD_POST', 'POST,PUT'); define('API_METHOD_DELETE', 'POST,DELETE'); +define('API_LOG_PREFIX', 'API {action} - '); + $API = []; $called_api = []; @@ -97,9 +99,9 @@ function api_source() return "Twidere"; } - Logger::log("Unrecognized user-agent ".$_SERVER['HTTP_USER_AGENT'], Logger::DEBUG); + Logger::info(API_LOG_PREFIX . 'Unrecognized user-agent', ['module' => 'api', 'action' => 'source', 'http_user_agent' => $_SERVER['HTTP_USER_AGENT']]); } else { - Logger::log("Empty user-agent", Logger::DEBUG); + Logger::info(API_LOG_PREFIX . 'Empty user-agent', ['module' => 'api', 'action' => 'source']); } return "api"; @@ -181,7 +183,7 @@ function api_login(App $a) var_dump($consumer, $token); die(); } catch (Exception $e) { - Logger::log($e); + Logger::warning(API_LOG_PREFIX . 'error', ['module' => 'api', 'action' => 'login', 'exception' => $e->getMessage()]); } // workaround for HTTP-auth in CGI mode @@ -195,7 +197,7 @@ function api_login(App $a) } if (empty($_SERVER['PHP_AUTH_USER'])) { - Logger::log('API_login: ' . print_r($_SERVER, true), Logger::DEBUG); + Logger::debug(API_LOG_PREFIX . 'failed', ['module' => 'api', 'action' => 'login', 'parameters' => $_SERVER]); header('WWW-Authenticate: Basic realm="Friendica"'); throw new UnauthorizedException("This API requires login"); } @@ -236,7 +238,7 @@ function api_login(App $a) } if (!DBA::isResult($record)) { - Logger::log('API_login failure: ' . print_r($_SERVER, true), Logger::DEBUG); + Logger::debug(API_LOG_PREFIX . 'failed', ['module' => 'api', 'action' => 'login', 'parameters' => $_SERVER]); header('WWW-Authenticate: Basic realm="Friendica"'); //header('HTTP/1.0 401 Unauthorized'); //die('This api requires login'); @@ -309,33 +311,35 @@ function api_call(App $a) api_login($a); } - Logger::log('API call for ' . $a->user['username'] . ': ' . $a->query_string); - Logger::log('API parameters: ' . print_r($_REQUEST, true)); + Logger::info(API_LOG_PREFIX . 'username {username}', ['module' => 'api', 'action' => 'call', 'username' => $a->user['username']]); + Logger::debug(API_LOG_PREFIX . 'parameters', ['module' => 'api', 'action' => 'call', 'parameters' => $_REQUEST]); $stamp = microtime(true); $return = call_user_func($info['func'], $type); $duration = (float) (microtime(true) - $stamp); - Logger::log("API call duration: " . round($duration, 2) . "\t" . $a->query_string, Logger::DEBUG); + + Logger::info(API_LOG_PREFIX . 'username {username}', ['module' => 'api', 'action' => 'call', 'username' => $a->user['username'], 'duration' => round($duration, 2)]); if (Config::get("system", "profiler")) { $duration = microtime(true)-$a->performance["start"]; /// @TODO round() really everywhere? - Logger::log( - parse_url($a->query_string, PHP_URL_PATH) . ": " . sprintf( - "Database: %s/%s, Cache %s/%s, Network: %s, I/O: %s, Other: %s, Total: %s", - round($a->performance["database"] - $a->performance["database_write"], 3), - round($a->performance["database_write"], 3), - round($a->performance["cache"], 3), - round($a->performance["cache_write"], 3), - round($a->performance["network"], 2), - round($a->performance["file"], 2), - round($duration - ($a->performance["database"] - + $a->performance["cache"] + $a->performance["cache_write"] - + $a->performance["network"] + $a->performance["file"]), 2), - round($duration, 2) - ), - Logger::DEBUG + Logger::debug( + API_LOG_PREFIX . 'performance', + [ + 'module' => 'api', + 'action' => 'call', + 'database_read' => round($a->performance["database"] - $a->performance["database_write"], 3), + 'database_write' => round($a->performance["database_write"], 3), + 'cache_read' => round($a->performance["cache"], 3), + 'cache_write' => round($a->performance["cache_write"], 3), + 'network_io' => round($a->performance["network"], 2), + 'file_io' => round($a->performance["file"], 2), + 'other_io' => round($duration - ($a->performance["database"] + + $a->performance["cache"] + $a->performance["cache_write"] + + $a->performance["network"] + $a->performance["file"]), 2), + 'total' => round($duration, 2) + ] ); if (Config::get("rendertime", "callstack")) { @@ -376,7 +380,7 @@ function api_call(App $a) $o .= $func . ": " . $time . "\n"; } } - Logger::log($o, Logger::DEBUG); + Logger::debug(API_LOG_PREFIX . $o, ['module' => 'api', 'action' => 'call']); } } @@ -413,7 +417,7 @@ function api_call(App $a) } } - Logger::log('API call not implemented: ' . $a->query_string); + Logger::warning(API_LOG_PREFIX . 'not implemented', ['module' => 'api', 'action' => 'call']); throw new NotImplementedException(); } catch (HTTPException $e) { header("HTTP/1.1 {$e->httpcode} {$e->httpdesc}"); @@ -522,7 +526,7 @@ function api_get_user(App $a, $contact_id = null) $extra_query = ""; $url = ""; - Logger::log("api_get_user: Fetching user data for user ".$contact_id, Logger::DEBUG); + Logger::info(API_LOG_PREFIX . 'Fetching data for user {user}', ['module' => 'api', 'action' => 'get_user', 'user' => $contact_id]); // Searching for contact URL if (!is_null($contact_id) && (intval($contact_id) == 0)) { @@ -606,7 +610,7 @@ function api_get_user(App $a, $contact_id = null) } } - Logger::log("api_get_user: user ".$user, Logger::DEBUG); + Logger::info(API_LOG_PREFIX . 'getting user {user}', ['module' => 'api', 'action' => 'get_user', 'user' => $user]); if (!$user) { if (api_user() === false) { @@ -618,7 +622,7 @@ function api_get_user(App $a, $contact_id = null) } } - Logger::log('api_user: ' . $extra_query . ', user: ' . $user); + Logger::info(API_LOG_PREFIX . 'found user {user}', ['module' => 'api', 'action' => 'get_user', 'user' => $user, 'extra_query' => $extra_query]); // user info $uinfo = q( @@ -1937,7 +1941,7 @@ function api_conversation_show($type) $id = intval(defaults($a->argv, 4, 0)); } - Logger::log('API: api_conversation_show: '.$id); + Logger::info(API_LOG_PREFIX . '{subaction}', ['module' => 'api', 'action' => 'conversation', 'subaction' => 'show', 'id' => $id]); // try to fetch the item for the local user - or the public item, if there is no local one $item = Item::selectFirst(['parent-uri'], ['id' => $id]); @@ -2331,7 +2335,7 @@ function api_favorites($type) // in friendica starred item are private // return favorites only for self - Logger::log('api_favorites: self:' . $user_info['self']); + Logger::info(API_LOG_PREFIX . 'for {self}', ['module' => 'api', 'action' => 'favorites', 'self' => $user_info['self']]); if ($user_info['self'] == 0) { $ret = []; @@ -3694,7 +3698,7 @@ function api_friendships_destroy($type) $contact_id = defaults($_REQUEST, 'user_id'); if (empty($contact_id)) { - Logger::log("No user_id specified", Logger::DEBUG); + Logger::notice(API_LOG_PREFIX . 'No user_id specified', ['module' => 'api', 'action' => 'friendships_destroy']); throw new BadRequestException("no user_id specified"); } @@ -3702,7 +3706,7 @@ function api_friendships_destroy($type) $contact = DBA::selectFirst('contact', ['url'], ['id' => $contact_id, 'uid' => 0, 'self' => false]); if(!DBA::isResult($contact)) { - Logger::log("No contact found for ID" . $contact_id, Logger::DEBUG); + Logger::notice(API_LOG_PREFIX . 'No contact found for ID {contact}', ['module' => 'api', 'action' => 'friendships_destroy', 'contact' => $contact_id]); throw new NotFoundException("no contact found to given ID"); } @@ -3714,12 +3718,12 @@ function api_friendships_destroy($type) $contact = DBA::selectFirst('contact', [], $condition); if (!DBA::isResult($contact)) { - Logger::log("Not following Contact", Logger::DEBUG); + Logger::notice(API_LOG_PREFIX . 'Not following contact', ['module' => 'api', 'action' => 'friendships_destroy']); throw new NotFoundException("Not following Contact"); } if (!in_array($contact['network'], Protocol::NATIVE_SUPPORT)) { - Logger::log("Not supported", Logger::DEBUG); + Logger::notice(API_LOG_PREFIX . 'Not supported for {network}', ['module' => 'api', 'action' => 'friendships_destroy', 'network' => $contact['network']]); throw new ExpectationFailedException("Not supported"); } @@ -3730,7 +3734,7 @@ function api_friendships_destroy($type) Contact::terminateFriendship($owner, $contact, $dissolve); } else { - Logger::log("No owner found", Logger::DEBUG); + Logger::notice(API_LOG_PREFIX . 'No owner {uid} found', ['module' => 'api', 'action' => 'friendships_destroy', 'uid' => $uid]); throw new NotFoundException("Error Processing Request"); } @@ -4837,7 +4841,7 @@ function api_friendica_remoteauth() 'sec' => $sec, 'expire' => time() + 45]; DBA::insert('profile_check', $fields); - Logger::log($contact['name'] . ' ' . $sec, Logger::DEBUG); + Logger::info(API_LOG_PREFIX . 'for contact {contact}', ['module' => 'api', 'action' => 'friendica_remoteauth', 'contact' => $contact['name'], 'hey' => $sec]); $dest = ($url ? '&destination_url=' . $url : ''); System::externalRedirect( @@ -5086,7 +5090,7 @@ function api_in_reply_to($item) // https://github.com/friendica/friendica/issues/1010 // This is a bugfix for that. if (intval($in_reply_to['status_id']) == intval($item['id'])) { - Logger::log('this message should never appear: id: '.$item['id'].' similar to reply-to: '.$in_reply_to['status_id'], Logger::DEBUG); + Logger::warning(API_LOG_PREFIX . 'ID {id} is similar to reply-to {reply-to}', ['module' => 'api', 'action' => 'in_reply_to', 'id' => $item['id'], 'reply-to' => $in_reply_to['status_id']]); $in_reply_to['status_id'] = null; $in_reply_to['user_id'] = null; $in_reply_to['status_id_str'] = null; diff --git a/index.php b/index.php index f2aea6468..c2dd31bcf 100644 --- a/index.php +++ b/index.php @@ -5,6 +5,7 @@ */ use Friendica\App; +use Friendica\Util\LoggerFactory; if (!file_exists(__DIR__ . '/vendor/autoload.php')) { die('Vendor path not found. Please execute "bin/composer.phar --no-dev install" on the command line in the web root.'); @@ -12,9 +13,10 @@ if (!file_exists(__DIR__ . '/vendor/autoload.php')) { require __DIR__ . '/vendor/autoload.php'; +$logger = LoggerFactory::create('index'); + // We assume that the index.php is called by a frontend process // The value is set to "true" by default in App -$a = new App(__DIR__, false); +$a = new App(__DIR__, $logger, false); $a->runFrontend(); - diff --git a/mod/acl.php b/mod/acl.php index fc6755673..03cb1ad63 100644 --- a/mod/acl.php +++ b/mod/acl.php @@ -34,7 +34,7 @@ function acl_content(App $a) $search = $_REQUEST['query']; } - Logger::log("Searching for ".$search." - type ".$type." conversation ".$conv_id, Logger::DEBUG); + Logger::info('ACL {action} - {subaction}', ['module' => 'acl', 'action' => 'content', 'subaction' => 'search', 'search' => $search, 'type' => $type, 'conversation' => $conv_id]); if ($search != '') { $sql_extra = "AND `name` LIKE '%%" . DBA::escape($search) . "%%'"; diff --git a/src/App.php b/src/App.php index df350542a..f5dba13dc 100644 --- a/src/App.php +++ b/src/App.php @@ -8,8 +8,10 @@ use Detection\MobileDetect; use DOMDocument; use DOMXPath; use Exception; +use Friendica\Core\Logger; use Friendica\Database\DBA; use Friendica\Network\HTTPException\InternalServerErrorException; +use Psr\Log\LoggerInterface; /** * @@ -106,6 +108,11 @@ class App */ public $mobileDetect; + /** + * @var LoggerInterface The current logger of this App + */ + private $logger; + /** * Register a stylesheet file path to be included in the tag of every page. * Inclusion is done in App->initHead(). @@ -146,13 +153,16 @@ class App /** * @brief App constructor. * - * @param string $basePath Path to the app base folder - * @param bool $isBackend Whether it is used for backend or frontend (Default true=backend) + * @param string $basePath Path to the app base folder + * @param LoggerInterface $logger Logger of this application + * @param bool $isBackend Whether it is used for backend or frontend (Default true=backend) * * @throws Exception if the Basepath is not usable */ - public function __construct($basePath, $isBackend = true) + public function __construct($basePath, LoggerInterface $logger, $isBackend = true) { + $this->logger = $logger; + if (!static::isDirectoryUsable($basePath, false)) { throw new Exception('Basepath ' . $basePath . ' isn\'t usable.'); } @@ -301,6 +311,21 @@ class App return $this->mode; } + /** + * Returns the Logger of the Application + * + * @return LoggerInterface The Logger + * @throws InternalServerErrorException when the logger isn't created + */ + public function getLogger() + { + if (empty($this->logger)) { + throw new InternalServerErrorException('Logger of the Application is not defined'); + } + + return $this->logger; + } + /** * Reloads the whole app instance */ @@ -328,6 +353,8 @@ class App Core\L10n::init(); $this->process_id = Core\System::processID('log'); + + Core\Logger::setLogger($this->logger); } /** diff --git a/src/BaseObject.php b/src/BaseObject.php index d006c249d..39f98a38f 100644 --- a/src/BaseObject.php +++ b/src/BaseObject.php @@ -6,6 +6,8 @@ namespace Friendica; require_once 'boot.php'; +use Friendica\Util\LoggerFactory; + /** * Basic object * @@ -25,7 +27,8 @@ class BaseObject public static function getApp() { if (empty(self::$app)) { - self::$app = new App(dirname(__DIR__)); + $logger = $logger = LoggerFactory::create('app'); + self::$app = new App(dirname(__DIR__), $logger); } return self::$app; diff --git a/src/Core/Addon.php b/src/Core/Addon.php index a06982820..ee89f4d77 100644 --- a/src/Core/Addon.php +++ b/src/Core/Addon.php @@ -4,9 +4,7 @@ */ namespace Friendica\Core; -use Friendica\App; use Friendica\BaseObject; -use Friendica\Core\Logger; use Friendica\Database\DBA; /** @@ -76,7 +74,7 @@ class Addon extends BaseObject */ public static function uninstall($addon) { - Logger::log("Addons: uninstalling " . $addon); + Logger::notice("Addon {addon}: {action}", ['action' => 'uninstall', 'addon' => $addon]); DBA::delete('addon', ['name' => $addon]); @include_once('addon/' . $addon . '/' . $addon . '.php'); @@ -101,7 +99,7 @@ class Addon extends BaseObject if (!file_exists('addon/' . $addon . '/' . $addon . '.php')) { return false; } - Logger::log("Addons: installing " . $addon); + Logger::notice("Addon {addon}: {action}", ['action' => 'install', 'addon' => $addon]); $t = @filemtime('addon/' . $addon . '/' . $addon . '.php'); @include_once('addon/' . $addon . '/' . $addon . '.php'); if (function_exists($addon . '_install')) { @@ -126,7 +124,7 @@ class Addon extends BaseObject } return true; } else { - Logger::log("Addons: FAILED installing " . $addon); + Logger::error("Addon {addon}: {action} failed", ['action' => 'uninstall', 'addon' => $addon]); return false; } } @@ -156,7 +154,8 @@ class Addon extends BaseObject $t = @filemtime($fname); foreach ($installed as $i) { if (($i['name'] == $addon) && ($i['timestamp'] != $t)) { - Logger::log('Reloading addon: ' . $i['name']); + + Logger::notice("Addon {addon}: {action}", ['action' => 'reload', 'addon' => $i['name']]); @include_once($fname); if (function_exists($addon . '_uninstall')) { diff --git a/src/Core/Logger.php b/src/Core/Logger.php index f9cb8cde0..1aaea665e 100644 --- a/src/Core/Logger.php +++ b/src/Core/Logger.php @@ -5,82 +5,335 @@ namespace Friendica\Core; use Friendica\BaseObject; -use Friendica\Core\Config; -use Friendica\Util\DateTimeFormat; -use ReflectionClass; +use Friendica\Network\HTTPException\InternalServerErrorException; +use Friendica\Util\LoggerFactory; +use Psr\Log\LoggerInterface; +use Psr\Log\LogLevel; /** * @brief Logger functions */ class Logger extends BaseObject { - // Log levels: - const WARNING = 0; - const INFO = 1; - const TRACE = 2; - const DEBUG = 3; - const DATA = 4; - const ALL = 5; + /** + * @see Logger::error() + */ + const WARNING = LogLevel::ERROR; + /** + * @see Logger::warning() + */ + const INFO = LogLevel::WARNING; + /** + * @see Logger::notice() + */ + const TRACE = LogLevel::NOTICE; + /** + * @see Logger::info() + */ + const DEBUG = LogLevel::INFO; + /** + * @see Logger::debug() + */ + const DATA = LogLevel::DEBUG; + /** + * @see Logger::debug() + */ + const ALL = LogLevel::DEBUG; - public static $levels = [ - self::WARNING => 'Warning', - self::INFO => 'Info', - self::TRACE => 'Trace', - self::DEBUG => 'Debug', - self::DATA => 'Data', - self::ALL => 'All', - ]; + /** + * @var array the legacy loglevels + * @deprecated 2019.03 use PSR-3 loglevels + * @see https://github.com/php-fig/fig-standards/blob/master/accepted/PSR-3-logger-interface.md#5-psrlogloglevel + * + */ + public static $levels = [ + self::WARNING => 'Warning', + self::INFO => 'Info', + self::TRACE => 'Trace', + self::DEBUG => 'Debug', + self::DATA => 'Data', + self::ALL => 'All', + ]; + + /** + * @var LoggerInterface A PSR-3 compliant logger instance + */ + private static $logger; + + /** + * @var LoggerInterface A PSR-3 compliant logger instance for developing only + */ + private static $devLogger; + + /** + * Sets the default logging handler for Friendica. + * @todo Can be combined with other handlers too if necessary, could be configurable. + * + * @param LoggerInterface $logger The Logger instance of this Application + * + * @throws InternalServerErrorException if the logger factory is incompatible to this logger + */ + public static function setLogger($logger) + { + $debugging = Config::get('system', 'debugging'); + $logfile = Config::get('system', 'logfile'); + $loglevel = Config::get('system', 'loglevel'); + + if (!$debugging || !$logfile) { + return; + } + + if (is_int($loglevel)) { + $loglevel = self::mapLegacyConfigDebugLevel($loglevel); + } + + LoggerFactory::addStreamHandler($logger, $logfile, $loglevel); + + self::$logger = $logger; + + $logfile = Config::get('system', 'dlogfile'); + + if (!$logfile) { + return; + } + + $developIp = Config::get('system', 'dlogip'); + + self::$devLogger = LoggerFactory::createDev('develop', $developIp); + LoggerFactory::addStreamHandler(self::$devLogger, $logfile, LogLevel::DEBUG); + } + + /** + * Mapping a legacy level to the PSR-3 compliant levels + * @see https://github.com/php-fig/fig-standards/blob/master/accepted/PSR-3-logger-interface.md#5-psrlogloglevel + * + * @param int $level the level to be mapped + * + * @return string the PSR-3 compliant level + */ + private static function mapLegacyConfigDebugLevel($level) + { + switch ($level) { + // legacy WARNING + case 0: + return LogLevel::ERROR; + // legacy INFO + case 1: + return LogLevel::WARNING; + // legacy TRACE + case 2: + return LogLevel::NOTICE; + // legacy DEBUG + case 3: + return LogLevel::INFO; + // legacy DATA + case 4: + return LogLevel::DEBUG; + // legacy ALL + case 5: + return LogLevel::DEBUG; + // default if nothing set + default: + return LogLevel::NOTICE; + } + } + + /** + * System is unusable. + * @see LoggerInterface::emergency() + * + * @param string $message + * @param array $context + * + * @return void + * + */ + public static function emergency($message, $context = []) + { + if (!isset(self::$logger)) { + return; + } + + $stamp1 = microtime(true); + self::$logger->emergency($message, $context); + self::getApp()->saveTimestamp($stamp1, 'file'); + } + + /** + * Action must be taken immediately. + * @see LoggerInterface::alert() + * + * Example: Entire website down, database unavailable, etc. This should + * trigger the SMS alerts and wake you up. + * + * @param string $message + * @param array $context + * + * @return void + * + */ + public static function alert($message, $context = []) + { + if (!isset(self::$logger)) { + return; + } + + $stamp1 = microtime(true); + self::$logger->alert($message, $context); + self::getApp()->saveTimestamp($stamp1, 'file'); + } + + /** + * Critical conditions. + * @see LoggerInterface::critical() + * + * Example: Application component unavailable, unexpected exception. + * + * @param string $message + * @param array $context + * + * @return void + * + */ + public static function critical($message, $context = []) + { + if (!isset(self::$logger)) { + return; + } + + $stamp1 = microtime(true); + self::$logger->critical($message, $context); + self::getApp()->saveTimestamp($stamp1, 'file'); + } + + /** + * Runtime errors that do not require immediate action but should typically + * be logged and monitored. + * @see LoggerInterface::error() + * + * @param string $message + * @param array $context + * + * @return void + * + */ + public static function error($message, $context = []) + { + if (!isset(self::$logger)) { + echo "not set!?\n"; + return; + } + + $stamp1 = microtime(true); + self::$logger->error($message, $context); + self::getApp()->saveTimestamp($stamp1, 'file'); + } + + /** + * Exceptional occurrences that are not errors. + * @see LoggerInterface::warning() + * + * Example: Use of deprecated APIs, poor use of an API, undesirable things + * that are not necessarily wrong. + * + * @param string $message + * @param array $context + * + * @return void + * + */ + public static function warning($message, $context = []) + { + if (!isset(self::$logger)) { + return; + } + + $stamp1 = microtime(true); + self::$logger->warning($message, $context); + self::getApp()->saveTimestamp($stamp1, 'file'); + } + + /** + * Normal but significant events. + * @see LoggerInterface::notice() + * + * @param string $message + * @param array $context + * + * @return void + * + */ + public static function notice($message, $context = []) + { + if (!isset(self::$logger)) { + return; + } + + $stamp1 = microtime(true); + self::$logger->notice($message, $context); + self::getApp()->saveTimestamp($stamp1, 'file'); + } + + /** + * Interesting events. + * @see LoggerInterface::info() + * + * Example: User logs in, SQL logs. + * + * @param string $message + * @param array $context + * + * @return void + * + */ + public static function info($message, $context = []) + { + if (!isset(self::$logger)) { + return; + } + + $stamp1 = microtime(true); + self::$logger->info($message, $context); + self::getApp()->saveTimestamp($stamp1, 'file'); + } + + /** + * Detailed debug information. + * @see LoggerInterface::debug() + * + * @param string $message + * @param array $context + * + * @return void + */ + public static function debug($message, $context = []) + { + if (!isset(self::$logger)) { + return; + } + + $stamp1 = microtime(true); + self::$logger->debug($message, $context); + self::getApp()->saveTimestamp($stamp1, 'file'); + } /** * @brief Logs the given message at the given log level * * @param string $msg * @param int $level + * + * @deprecated since 2019.03 Use Logger::debug() Logger::info() , ... instead */ - public static function log($msg, $level = self::INFO) + public static function log($msg, $level = LogLevel::NOTICE) { - $a = self::getApp(); - - $debugging = Config::get('system', 'debugging'); - $logfile = Config::get('system', 'logfile'); - $loglevel = intval(Config::get('system', 'loglevel')); - - if ( - !$debugging - || !$logfile - || $level > $loglevel - ) { - return; - } - - $processId = session_id(); - - if ($processId == '') - { - $processId = $a->process_id; - } - - $callers = debug_backtrace(); - - if (count($callers) > 1) { - $function = $callers[1]['function']; - } else { - $function = ''; - } - - $logline = sprintf("%s@%s\t[%s]:%s:%s:%s\t%s\n", - DateTimeFormat::utcNow(DateTimeFormat::ATOM), - $processId, - self::$levels[$level], - basename($callers[0]['file']), - $callers[0]['line'], - $function, - $msg - ); + if (!isset(self::$logger)) { + return; + } $stamp1 = microtime(true); - @file_put_contents($logfile, $logline, FILE_APPEND); - $a->saveTimestamp($stamp1, "file"); + self::$logger->log($level, $msg); + self::getApp()->saveTimestamp($stamp1, "file"); } /** @@ -90,47 +343,16 @@ class Logger extends BaseObject * personally without background noise * * @param string $msg + * @param string $level */ - public static function devLog($msg) + public static function devLog($msg, $level = LogLevel::DEBUG) { - $a = self::getApp(); - - $logfile = Config::get('system', 'dlogfile'); - - if (!$logfile) { - return; - } - - $dlogip = Config::get('system', 'dlogip'); - - if (!is_null($dlogip) && $_SERVER['REMOTE_ADDR'] != $dlogip) - { - return; - } - - $processId = session_id(); - - if ($processId == '') - { - $processId = $a->process_id; - } - - if (!is_string($msg)) { - $msg = var_export($msg, true); - } - - $callers = debug_backtrace(); - $logline = sprintf("%s@\t%s:\t%s:\t%s\t%s\t%s\n", - DateTimeFormat::utcNow(), - $processId, - basename($callers[0]['file']), - $callers[0]['line'], - $callers[1]['function'], - $msg - ); + if (!isset(self::$logger)) { + return; + } $stamp1 = microtime(true); - @file_put_contents($logfile, $logline, FILE_APPEND); - $a->saveTimestamp($stamp1, "file"); + self::$devLogger->log($level, $msg); + self::getApp()->saveTimestamp($stamp1, "file"); } } diff --git a/src/Util/Logger/FriendicaDevelopHandler.php b/src/Util/Logger/FriendicaDevelopHandler.php new file mode 100644 index 000000000..908d7052c --- /dev/null +++ b/src/Util/Logger/FriendicaDevelopHandler.php @@ -0,0 +1,50 @@ +developerIp = $developerIp; + } + + /** + * {@inheritdoc} + */ + public function handle(array $record) + { + if (!$this->isHandling($record)) { + return false; + } + + /// Just in case the remote IP is the same as the developer IP log the output + if (!is_null($this->developerIp) && $_SERVER['REMOTE_ADDR'] != $this->developerIp) + { + return false; + } + + return false === $this->bubble; + } +} diff --git a/src/Util/LoggerFactory.php b/src/Util/LoggerFactory.php new file mode 100644 index 000000000..71239edbb --- /dev/null +++ b/src/Util/LoggerFactory.php @@ -0,0 +1,116 @@ +pushProcessor(new Monolog\Processor\PsrLogMessageProcessor()); + $logger->pushProcessor(new Monolog\Processor\ProcessIdProcessor()); + + // Add more information in case of a warning and more + $logger->pushProcessor(new Monolog\Processor\IntrospectionProcessor(LogLevel::WARNING, [], 1)); + + return $logger; + } + + /** + * Creates a new PSR-3 compliant develop logger + * + * If you want to debug only interactions from your IP or the IP of a remote server for federation debug, + * you'll use this logger instance for the duration of your work. + * + * It should never get filled during normal usage of Friendica + * + * @param string $channel The channel of the logger instance + * @param string $developerIp The IP of the developer who wants to use the logger + * + * @return LoggerInterface The PSR-3 compliant logger instance + */ + public static function createDev($channel, $developerIp) + { + $logger = new Monolog\Logger($channel); + $logger->pushProcessor(new Monolog\Processor\PsrLogMessageProcessor()); + $logger->pushProcessor(new Monolog\Processor\ProcessIdProcessor()); + + $logger->pushProcessor(new Monolog\Processor\IntrospectionProcessor(Loglevel::DEBUG, [], 1)); + + $logger->pushHandler(new FriendicaDevelopHandler($developerIp)); + + return $logger; + } + + /** + * Adding a handler to a given logger instance + * + * @param LoggerInterface $logger The logger instance + * @param mixed $stream The stream which handles the logger output + * @param string $level The level, for which this handler at least should handle logging + * + * @return void + * + * @throws InternalServerErrorException if the logger is incompatible to the logger factory + * @throws \Exception in case of general failures + */ + public static function addStreamHandler($logger, $stream, $level = LogLevel::NOTICE) + { + if ($logger instanceof Monolog\Logger) { + $fileHandler = new Monolog\Handler\StreamHandler($stream, Monolog\Logger::toMonologLevel($level)); + + $formatter = new Monolog\Formatter\LineFormatter("%datetime% %channel% [%level_name%]: %message% %context% %extra%\n"); + $fileHandler->setFormatter($formatter); + + $logger->pushHandler($fileHandler); + } else { + throw new InternalServerErrorException('Logger instance incompatible for MonologFactory'); + } + } + + /** + * This method enables the test mode of a given logger + * + * @param LoggerInterface $logger The logger + * + * @return Monolog\Handler\TestHandler the Handling for tests + * + * @throws InternalServerErrorException if the logger is incompatible to the logger factory + */ + public static function enableTest($logger) + { + if ($logger instanceof Monolog\Logger) { + // disable every handler so far + $logger->pushHandler(new Monolog\Handler\NullHandler()); + + // enable the test handler + $fileHandler = new Monolog\Handler\TestHandler(); + $formatter = new Monolog\Formatter\LineFormatter("%datetime% %channel% [%level_name%]: %message% %context% %extra%\n"); + $fileHandler->setFormatter($formatter); + + $logger->pushHandler($fileHandler); + + return $fileHandler; + } else { + throw new InternalServerErrorException('Logger instance incompatible for MonologFactory'); + } + } +} diff --git a/tests/include/ApiTest.php b/tests/include/ApiTest.php index ede84a0eb..cf7571073 100644 --- a/tests/include/ApiTest.php +++ b/tests/include/ApiTest.php @@ -11,6 +11,8 @@ use Friendica\Core\PConfig; use Friendica\Core\Protocol; use Friendica\Core\System; use Friendica\Network\HTTPException; +use Friendica\Util\LoggerFactory; +use Monolog\Handler\TestHandler; require_once __DIR__ . '/../../include/api.php'; @@ -22,6 +24,11 @@ require_once __DIR__ . '/../../include/api.php'; */ class ApiTest extends DatabaseTest { + /** + * @var TestHandler Can handle log-outputs + */ + protected $logOutput; + /** * Create variables used by tests. */ @@ -30,6 +37,7 @@ class ApiTest extends DatabaseTest parent::setUp(); $this->app = BaseObject::getApp(); + $this->logOutput = LoggerFactory::enableTest($this->app->getLogger()); // User data that the test database is populated with $this->selfUser = [ diff --git a/tests/src/BaseObjectTest.php b/tests/src/BaseObjectTest.php index f8542f7b3..7b9ff3aa1 100644 --- a/tests/src/BaseObjectTest.php +++ b/tests/src/BaseObjectTest.php @@ -7,6 +7,7 @@ namespace Friendica\Test; use Friendica\App; use Friendica\BaseObject; +use Friendica\Util\LoggerFactory; use PHPUnit\Framework\TestCase; /** @@ -38,7 +39,9 @@ class BaseObjectTest extends TestCase */ public function testSetApp() { - $app = new App(__DIR__ . '/../../'); + $logger = $logger = LoggerFactory::create('test'); + $app = new App(__DIR__ . '/../../', $logger); + LoggerFactory::enableTest($logger); $this->assertNull($this->baseObject->setApp($app)); $this->assertEquals($app, $this->baseObject->getApp()); } diff --git a/update.php b/update.php index 2663da21f..2ed1a8199 100644 --- a/update.php +++ b/update.php @@ -332,8 +332,8 @@ function update_1298() $fail++; } else { DBA::update('profile', [$translateKey => $key], ['id' => $data['id']]); - logger::log('Updated contact ' . $data['id'] . " to $translateKey " . $key . - ' (was: ' . $data[$translateKey] . ')'); + Logger::notice('Updated contact', ['action' => 'update', 'contact' => $data['id'], "$translateKey" => $key, + 'was' => $data[$translateKey]]); Worker::add(PRIORITY_LOW, 'ProfileUpdate', $data['id']); Contact::updateSelfFromUserID($data['id']); GContact::updateForUser($data['id']); @@ -342,7 +342,7 @@ function update_1298() } } - Logger::log($translateKey . " fix completed. Success: $success. Fail: $fail"); + Logger::notice($translateKey . " fix completed", ['action' => 'update', 'translateKey' => $translateKey, 'Success' => $success, 'Fail' => $fail ]); } return Update::SUCCESS; }