From c10a43069ec1e71b6608574a81fb29c76919e132 Mon Sep 17 00:00:00 2001 From: Andrew Dolgov Date: Fri, 30 Nov 2018 08:34:29 +0300 Subject: [PATCH] debug logging system rework: * support various logging levels per-message * remove hacks like debug_suppress, DAEMON_EXTENDED_DEBUG, etc * _debug() is kept as a compatibility shim for plugins --- classes/article.php | 26 +-- classes/dbupdater.php | 4 +- classes/debug.php | 85 ++++++++ classes/digest.php | 16 +- classes/feeds.php | 3 + classes/pluginhost.php | 9 - classes/pref/feeds.php | 13 +- classes/rssutils.php | 230 ++++++++++----------- include/functions.php | 71 +------ plugins/af_comics/filters/af_comics_pa.php | 7 - plugins/af_psql_trgm/init.php | 4 +- plugins/af_redditimgur/init.php | 38 ++-- plugins/cache_starred_images/init.php | 6 +- plugins/import_export/init.php | 4 +- update.php | 74 ++++--- update_daemon2.php | 47 +++-- 16 files changed, 326 insertions(+), 311 deletions(-) create mode 100644 classes/debug.php diff --git a/classes/article.php b/classes/article.php index 075da194..e769a3e9 100755 --- a/classes/article.php +++ b/classes/article.php @@ -936,24 +936,24 @@ class Article extends Handler_Protected { return $rv; } - static function purge_orphans($do_output = false) { + static function purge_orphans() { - // purge orphaned posts in main content table + // purge orphaned posts in main content table - if (DB_TYPE == "mysql") - $limit_qpart = "LIMIT 5000"; - else - $limit_qpart = ""; + if (DB_TYPE == "mysql") + $limit_qpart = "LIMIT 5000"; + else + $limit_qpart = ""; - $pdo = Db::pdo(); - $res = $pdo->query("DELETE FROM ttrss_entries WHERE + $pdo = Db::pdo(); + $res = $pdo->query("DELETE FROM ttrss_entries WHERE NOT EXISTS (SELECT ref_id FROM ttrss_user_entries WHERE ref_id = id) $limit_qpart"); - if ($do_output) { - $rows = $res->rowCount(); - _debug("Purged $rows orphaned posts."); - } - } + if (Debug::enabled()) { + $rows = $res->rowCount(); + Debug::log("Purged $rows orphaned posts."); + } + } static function catchupArticlesById($ids, $cmode, $owner_uid = false) { diff --git a/classes/dbupdater.php b/classes/dbupdater.php index 1014fa5a..c32afede 100644 --- a/classes/dbupdater.php +++ b/classes/dbupdater.php @@ -47,8 +47,8 @@ class DbUpdater { print_notice("Query: $line"); print_error("Error: " . implode(", ", $this->pdo->errorInfo())); } else { - _debug("Query: $line"); - _debug("Error: " . implode(", ", $this->pdo->errorInfo())); + Debug::log("Query: $line"); + Debug::log("Error: " . implode(", ", $this->pdo->errorInfo())); } return false; diff --git a/classes/debug.php b/classes/debug.php new file mode 100644 index 00000000..21b823c5 --- /dev/null +++ b/classes/debug.php @@ -0,0 +1,85 @@ + $digest_text, "message_html" => $digest]); - //if (!$rc && $debug) _debug("ERROR: " . $mailer->lastError()); + //if (!$rc && $debug) Debug::log("ERROR: " . $mailer->lastError()); - if ($debug) _debug("RC=$rc"); + Debug::log("RC=$rc"); if ($rc && $do_catchup) { - if ($debug) _debug("Marking affected articles as read..."); + Debug::log("Marking affected articles as read..."); Article::catchupArticlesById($affected_ids, 0, $line["id"]); } } else { - if ($debug) _debug("No headlines"); + Debug::log("No headlines"); } $sth = $pdo->prepare("UPDATE ttrss_users SET last_digest_sent = NOW() @@ -84,7 +84,7 @@ class Digest } } - if ($debug) _debug("All done."); + Debug::log("All done."); } diff --git a/classes/feeds.php b/classes/feeds.php index 7e48efd6..cf9ca64c 100755 --- a/classes/feeds.php +++ b/classes/feeds.php @@ -1134,6 +1134,9 @@ class Feeds extends Handler_Protected { function update_debugger() { header("Content-type: text/html"); + Debug::set_enabled(true); + Debug::set_loglevel($_REQUEST["xdebug"]); + $feed_id = (int)$_REQUEST["feed_id"]; @$do_update = $_REQUEST["action"] == "do_update"; $csrf_token = $_REQUEST["csrf_token"]; diff --git a/classes/pluginhost.php b/classes/pluginhost.php index f40705dd..7e3fb08a 100755 --- a/classes/pluginhost.php +++ b/classes/pluginhost.php @@ -10,7 +10,6 @@ class PluginHost { private $api_methods = array(); private $plugin_actions = array(); private $owner_uid; - private $debug; private $last_registered; private static $instance; @@ -400,14 +399,6 @@ class PluginHost { } } - function set_debug($debug) { - $this->debug = $debug; - } - - function get_debug() { - return $this->debug; - } - // Plugin feed functions are *EXPERIMENTAL*! // cat_id: only -1 is supported (Special) diff --git a/classes/pref/feeds.php b/classes/pref/feeds.php index 5127b19c..2d68f66b 100755 --- a/classes/pref/feeds.php +++ b/classes/pref/feeds.php @@ -328,13 +328,12 @@ class Pref_Feeds extends Handler_Protected { } private function process_category_order(&$data_map, $item_id, $parent_id = false, $nest_level = 0) { - $debug = isset($_REQUEST["debug"]); $prefix = ""; for ($i = 0; $i < $nest_level; $i++) $prefix .= " "; - if ($debug) _debug("$prefix C: $item_id P: $parent_id"); + Debug::log("$prefix C: $item_id P: $parent_id"); $bare_item_id = substr($item_id, strpos($item_id, ':')+1); @@ -361,7 +360,7 @@ class Pref_Feeds extends Handler_Protected { $id = $item['_reference']; $bare_id = substr($id, strpos($id, ':')+1); - if ($debug) _debug("$prefix [$order_id] $id/$bare_id"); + Debug::log("$prefix [$order_id] $id/$bare_id"); if ($item['_reference']) { @@ -1545,12 +1544,10 @@ class Pref_Feeds extends Handler_Protected { } static function remove_feed($id, $owner_uid) { - $debug = isset($_REQUEST["debug"]); - foreach (PluginHost::getInstance()->get_hooks(PluginHost::HOOK_UNSUBSCRIBE_FEED) as $p) { - if( ! $p->hook_unsubscribe_feed($id, $owner_uid)){ - if($debug) _debug("Feed not removed due to Error in Plugin. (HOOK_UNSUBSCRIBE_FEED)"); - return; + if (! $p->hook_unsubscribe_feed($id, $owner_uid)) { + user_error("Feed $id (owner: $owner_uid) not removed due to plugin error (HOOK_UNSUBSCRIBE_FEED).", E_USER_WARNING); + return; } } diff --git a/classes/rssutils.php b/classes/rssutils.php index e76dd3e7..2dfcbb6d 100755 --- a/classes/rssutils.php +++ b/classes/rssutils.php @@ -7,8 +7,6 @@ class RSSUtils { if ($k != "feed" && isset($v)) { $x = strip_tags(is_array($v) ? implode(",", $v) : $v); - //_debug("$k:" . sha1($x) . ":" . htmlspecialchars($x), true); - $tmp .= sha1("$k:" . sha1($x)); } } @@ -68,7 +66,7 @@ class RSSUtils { } - static function update_daemon_common($limit = DAEMON_FEED_LIMIT, $debug = true) { + static function update_daemon_common($limit = DAEMON_FEED_LIMIT) { $schema_version = get_schema_version(); if ($schema_version != SCHEMA_VERSION) { @@ -145,7 +143,7 @@ class RSSUtils { array_push($feeds_to_update, $line['feed_url']); } - if ($debug) _debug(sprintf("Scheduled %d feeds to update...", count($feeds_to_update))); + Debug::log(sprintf("Scheduled %d feeds to update...", count($feeds_to_update))); // Update last_update_started before actually starting the batch // in order to minimize collision risk for parallel daemon tasks @@ -175,13 +173,13 @@ class RSSUtils { ORDER BY ttrss_feeds.id $query_limit"); foreach ($feeds_to_update as $feed) { - if($debug) _debug("Base feed: $feed"); + Debug::log("Base feed: $feed"); $usth->execute([$feed]); //update_rss_feed($line["id"], true); if ($tline = $usth->fetch()) { - if ($debug) _debug(" => " . $tline["last_updated"] . ", " . $tline["id"] . " " . $tline["owner_uid"]); + Debug::log(" => " . $tline["last_updated"] . ", " . $tline["id"] . " " . $tline["owner_uid"]); if (array_search($tline["owner_uid"], $batch_owners) === FALSE) array_push($batch_owners, $tline["owner_uid"]); @@ -200,27 +198,26 @@ class RSSUtils { // thrown outside of an active transaction during feed update } } - _debug_suppress(false); - _debug(sprintf(" %.4f (sec)", microtime(true) - $fstarted)); + Debug::log(sprintf(" %.4f (sec)", microtime(true) - $fstarted)); ++$nf; } } if ($nf > 0) { - _debug(sprintf("Processed %d feeds in %.4f (sec), %.4f (sec/feed avg)", $nf, + Debug::log(sprintf("Processed %d feeds in %.4f (sec), %.4f (sec/feed avg)", $nf, microtime(true) - $bstarted, (microtime(true) - $bstarted) / $nf)); } foreach ($batch_owners as $owner_uid) { - _debug("Running housekeeping tasks for user $owner_uid..."); + Debug::log("Running housekeeping tasks for user $owner_uid..."); RSSUtils::housekeeping_user($owner_uid); } // Send feed digests by email if needed. - Digest::send_headlines_digests($debug); + Digest::send_headlines_digests(); return $nf; } @@ -312,10 +309,7 @@ class RSSUtils { */ static function update_rss_feed($feed, $no_cache = false) { - $debug_enabled = defined('DAEMON_EXTENDED_DEBUG') || clean($_REQUEST['xdebug']); - - _debug_suppress(!$debug_enabled); - _debug("start", $debug_enabled); + Debug::log("start", Debug::$LOG_VERBOSE); $pdo = Db::pdo(); @@ -323,7 +317,7 @@ class RSSUtils { $sth->execute([$feed]); if (!$row = $sth->fetch()) { - _debug("feed $feed NOT FOUND/SKIPPED", $debug_enabled); + Debug::log("feed $feed not found, skipping."); user_error("Attempt to update unknown/invalid feed $feed", E_USER_WARNING); return false; } @@ -333,7 +327,7 @@ class RSSUtils { // feed was batch-subscribed or something, we need to get basic info // this is not optimal currently as it fetches stuff separately TODO: optimize if ($title == "[Unknown]") { - _debug("setting basic feed info for $feed..."); + Debug::log("setting basic feed info for $feed..."); RSSUtils::set_basic_feed_info($feed); } @@ -374,7 +368,6 @@ class RSSUtils { $cache_filename = CACHE_DIR . "/feeds/" . sha1($fetch_url) . ".xml"; $pluginhost = new PluginHost(); - $pluginhost->set_debug($debug_enabled); $user_plugins = get_pref("_ENABLED_PLUGINS", $owner_uid); $pluginhost->load(PLUGINS, PluginHost::KIND_ALL); @@ -397,7 +390,7 @@ class RSSUtils { !$auth_login && !$auth_pass && filemtime($cache_filename) > time() - 30) { - _debug("using local cache [$cache_filename].", $debug_enabled); + Debug::log("using local cache [$cache_filename].", Debug::$LOG_VERBOSE); @$feed_data = file_get_contents($cache_filename); @@ -406,28 +399,28 @@ class RSSUtils { } } else { - _debug("local cache will not be used for this feed", $debug_enabled); + Debug::log("local cache will not be used for this feed", Debug::$LOG_VERBOSE); } global $fetch_last_modified; // fetch feed from source if (!$feed_data) { - _debug("last unconditional update request: $last_unconditional"); + Debug::log("last unconditional update request: $last_unconditional", Debug::$LOG_VERBOSE); if (ini_get("open_basedir") && function_exists("curl_init")) { - _debug("not using CURL due to open_basedir restrictions"); + Debug::log("not using CURL due to open_basedir restrictions", Debug::$LOG_VERBOSE); } if (time() - strtotime($last_unconditional) > MAX_CONDITIONAL_INTERVAL) { - _debug("maximum allowed interval for conditional requests exceeded, forcing refetch"); + Debug::log("maximum allowed interval for conditional requests exceeded, forcing refetch", Debug::$LOG_VERBOSE); $force_refetch = true; } else { - _debug("stored last modified for conditional request: $stored_last_modified", $debug_enabled); + Debug::log("stored last modified for conditional request: $stored_last_modified", Debug::$LOG_VERBOSE); } - _debug("fetching [$fetch_url] (force_refetch: $force_refetch)...", $debug_enabled); + Debug::log("fetching [$fetch_url] (force_refetch: $force_refetch)...", Debug::$LOG_VERBOSE); $feed_data = fetch_file_contents([ "url" => $fetch_url, @@ -447,8 +440,8 @@ class RSSUtils { $feed_data = trim($feed_data); - _debug("fetch done.", $debug_enabled); - _debug("source last modified: " . $fetch_last_modified, $debug_enabled); + Debug::log("fetch done.", Debug::$LOG_VERBOSE); + Debug::log("source last modified: " . $fetch_last_modified, Debug::$LOG_VERBOSE); if ($feed_data && $fetch_last_modified != $stored_last_modified) { $sth = $pdo->prepare("UPDATE ttrss_feeds SET last_modified = ? WHERE id = ?"); @@ -460,7 +453,7 @@ class RSSUtils { $new_rss_hash = sha1($feed_data); if ($new_rss_hash != $rss_hash) { - _debug("saving $cache_filename", $debug_enabled); + Debug::log("saving $cache_filename", Debug::$LOG_VERBOSE); @file_put_contents($cache_filename, $feed_data); } } @@ -470,13 +463,13 @@ class RSSUtils { global $fetch_last_error; global $fetch_last_error_code; - _debug("unable to fetch: $fetch_last_error [$fetch_last_error_code]", $debug_enabled); + Debug::log("unable to fetch: $fetch_last_error [$fetch_last_error_code]", Debug::$LOG_VERBOSE); // If-Modified-Since if ($fetch_last_error_code != 304) { $error_message = $fetch_last_error; } else { - _debug("source claims data not modified, nothing to do.", $debug_enabled); + Debug::log("source claims data not modified, nothing to do.", Debug::$LOG_VERBOSE); $error_message = ""; } @@ -499,8 +492,8 @@ class RSSUtils { // We use local pluginhost here because we need to load different per-user feed plugins $pluginhost->run_hooks(PluginHost::HOOK_FEED_PARSED, "hook_feed_parsed", $rss); - _debug("language: $feed_language", $debug_enabled); - _debug("processing feed data...", $debug_enabled); + Debug::log("language: $feed_language", Debug::$LOG_VERBOSE); + Debug::log("processing feed data...", Debug::$LOG_VERBOSE); if (DB_TYPE == "pgsql") { $favicon_interval_qpart = "favicon_last_checked < NOW() - INTERVAL '12 hour'"; @@ -524,8 +517,8 @@ class RSSUtils { $site_url = mb_substr(rewrite_relative_url($fetch_url, $rss->get_link()), 0, 245); - _debug("site_url: $site_url", $debug_enabled); - _debug("feed_title: " . $rss->get_title(), $debug_enabled); + Debug::log("site_url: $site_url", Debug::$LOG_VERBOSE); + Debug::log("feed_title: " . $rss->get_title(), Debug::$LOG_VERBOSE); if ($favicon_needs_check || $force_refetch) { @@ -535,7 +528,7 @@ class RSSUtils { $favicon_file = ICONS_DIR . "/$feed.ico"; $favicon_modified = @filemtime($favicon_file); - _debug("checking favicon...", $debug_enabled); + Debug::log("checking favicon...", Debug::$LOG_VERBOSE); RSSUtils::check_feed_favicon($site_url, $feed); $favicon_modified_new = @filemtime($favicon_file); @@ -556,7 +549,7 @@ class RSSUtils { $favicon_colorstring = ",favicon_avg_color = " . $pdo->quote($favicon_color); } else if ($favicon_avg_color == 'fail') { - _debug("floicon failed on this file, not trying to recalculate avg color", $debug_enabled); + Debug::log("floicon failed on this file, not trying to recalculate avg color", Debug::$LOG_VERBOSE); } $sth = $pdo->prepare("UPDATE ttrss_feeds SET favicon_last_checked = NOW() @@ -564,20 +557,20 @@ class RSSUtils { $sth->execute([$feed]); } - _debug("loading filters & labels...", $debug_enabled); + Debug::log("loading filters & labels...", Debug::$LOG_VERBOSE); $filters = load_filters($feed, $owner_uid); - if ($debug_enabled) { + if (Debug::get_loglevel() >= Debug::$LOG_EXTENDED) { print_r($filters); } - _debug("" . count($filters) . " filters loaded.", $debug_enabled); + Debug::log("" . count($filters) . " filters loaded.", Debug::$LOG_VERBOSE); $items = $rss->get_items(); if (!is_array($items)) { - _debug("no articles found.", $debug_enabled); + Debug::log("no articles found.", Debug::$LOG_VERBOSE); $sth = $pdo->prepare("UPDATE ttrss_feeds SET last_updated = NOW(), last_unconditional = NOW(), last_error = '' WHERE id = ?"); @@ -586,19 +579,19 @@ class RSSUtils { return true; // no articles } - _debug("processing articles...", $debug_enabled); + Debug::log("processing articles...", Debug::$LOG_VERBOSE); $tstart = time(); foreach ($items as $item) { $pdo->beginTransaction(); - if (clean($_REQUEST['xdebug']) == 3) { + if (Debug::get_loglevel() >= 3) { print_r($item); } if (ini_get("max_execution_time") > 0 && time() - $tstart >= ini_get("max_execution_time") * 0.7) { - _debug("looks like there's too many articles to process at once, breaking out", $debug_enabled); + Debug::log("looks like there's too many articles to process at once, breaking out", Debug::$LOG_VERBOSE); $pdo->commit(); break; } @@ -616,11 +609,11 @@ class RSSUtils { $entry_guid_hashed = 'SHA1:' . sha1($entry_guid); - _debug("guid $entry_guid / $entry_guid_hashed", $debug_enabled); + Debug::log("guid $entry_guid / $entry_guid_hashed", Debug::$LOG_VERBOSE); $entry_timestamp = strip_tags($item->get_date()); - _debug("orig date: " . $item->get_date(), $debug_enabled); + Debug::log("orig date: " . $item->get_date(), Debug::$LOG_VERBOSE); if ($entry_timestamp == -1 || !$entry_timestamp || $entry_timestamp > time()) { $entry_timestamp = time(); @@ -628,7 +621,7 @@ class RSSUtils { $entry_timestamp_fmt = strftime("%Y/%m/%d %H:%M:%S", $entry_timestamp); - _debug("date $entry_timestamp [$entry_timestamp_fmt]", $debug_enabled); + Debug::log("date $entry_timestamp [$entry_timestamp_fmt]", Debug::$LOG_VERBOSE); $entry_title = strip_tags($item->get_title()); @@ -636,16 +629,16 @@ class RSSUtils { $entry_language = mb_substr(trim($item->get_language()), 0, 2); - _debug("title $entry_title", $debug_enabled); - _debug("link $entry_link", $debug_enabled); - _debug("language $entry_language", $debug_enabled); + Debug::log("title $entry_title", Debug::$LOG_VERBOSE); + Debug::log("link $entry_link", Debug::$LOG_VERBOSE); + Debug::log("language $entry_language", Debug::$LOG_VERBOSE); if (!$entry_title) $entry_title = date("Y-m-d H:i:s", $entry_timestamp);; $entry_content = $item->get_content(); if (!$entry_content) $entry_content = $item->get_description(); - if (clean($_REQUEST["xdebug"]) == 2) { + if (Debug::get_loglevel() >= 3) { print "content: "; print htmlspecialchars($entry_content); print "\n"; @@ -657,9 +650,9 @@ class RSSUtils { $entry_author = strip_tags($item->get_author()); $entry_guid = mb_substr($entry_guid, 0, 245); - _debug("author $entry_author", $debug_enabled); - _debug("num_comments: $num_comments", $debug_enabled); - _debug("looking for tags...", $debug_enabled); + Debug::log("author $entry_author", Debug::$LOG_VERBOSE); + Debug::log("num_comments: $num_comments", Debug::$LOG_VERBOSE); + Debug::log("looking for tags...", Debug::$LOG_VERBOSE); // parse entries into tags @@ -682,9 +675,9 @@ class RSSUtils { if (is_numeric($entry_tags[$i])) $entry_tags[$i] = 't:' . $entry_tags[$i]; } - _debug("tags found: " . join(",", $entry_tags), $debug_enabled); + Debug::log("tags found: " . join(",", $entry_tags), Debug::$LOG_VERBOSE); - _debug("done collecting data.", $debug_enabled); + Debug::log("done collecting data.", Debug::$LOG_VERBOSE); $sth = $pdo->prepare("SELECT id, content_hash, lang FROM ttrss_entries WHERE guid = ? OR guid = ?"); @@ -725,10 +718,10 @@ class RSSUtils { $entry_plugin_data = ""; $entry_current_hash = RSSUtils::calculate_article_hash($article, $pluginhost); - _debug("article hash: $entry_current_hash [stored=$entry_stored_hash]", $debug_enabled); + Debug::log("article hash: $entry_current_hash [stored=$entry_stored_hash]", Debug::$LOG_VERBOSE); if ($entry_current_hash == $entry_stored_hash && !isset($_REQUEST["force_rehash"])) { - _debug("stored article seems up to date [IID: $base_entry_id], updating timestamp only", $debug_enabled); + Debug::log("stored article seems up to date [IID: $base_entry_id], updating timestamp only", Debug::$LOG_VERBOSE); // we keep encountering the entry in feeds, so we need to // update date_updated column so that we don't get horrible @@ -743,26 +736,26 @@ class RSSUtils { continue; } - _debug("hash differs, applying plugin filters:", $debug_enabled); + Debug::log("hash differs, applying plugin filters:", Debug::$LOG_VERBOSE); foreach ($pluginhost->get_hooks(PluginHost::HOOK_ARTICLE_FILTER) as $plugin) { - _debug("... " . get_class($plugin), $debug_enabled); + Debug::log("... " . get_class($plugin), Debug::$LOG_VERBOSE); $start = microtime(true); $article = $plugin->hook_article_filter($article); - _debug("=== " . sprintf("%.4f (sec)", microtime(true) - $start), $debug_enabled); + Debug::log(sprintf("=== %.4f (sec)"), Debug::$LOG_VERBOSE); $entry_plugin_data .= mb_strtolower(get_class($plugin)) . ","; } - if (clean($_REQUEST["xdebug"]) == 2) { + if (Debug::get_loglevel() >= 3) { print "processed content: "; print htmlspecialchars($article["content"]); print "\n"; } - _debug("plugin data: $entry_plugin_data", $debug_enabled); + Debug::log("plugin data: $entry_plugin_data", Debug::$LOG_VERBOSE); // Workaround: 4-byte unicode requires utf8mb4 in MySQL. See https://tt-rss.org/forum/viewtopic.php?f=1&t=3377&p=20077#p20077 if (DB_TYPE == "mysql" && MYSQL_CHARSET != "UTF8MB4") { @@ -782,14 +775,14 @@ class RSSUtils { $article["content"], $article["link"], $article["author"], $article["tags"], $matched_rules); - if ($debug_enabled) { - _debug("matched filter rules: ", $debug_enabled); + if (Debug::get_loglevel() >= Debug::$LOG_EXTENDED) { + Debug::log("matched filter rules: ", Debug::$LOG_VERBOSE); if (count($matched_rules) != 0) { print_r($matched_rules); } - _debug("filter actions: ", $debug_enabled); + Debug::log("filter actions: ", Debug::$LOG_VERBOSE); if (count($article_filters) != 0) { print_r($article_filters); @@ -800,7 +793,7 @@ class RSSUtils { $plugin_filter_actions = $pluginhost->get_filter_actions(); if (count($plugin_filter_names) > 0) { - _debug("applying plugin filter actions...", $debug_enabled); + Debug::log("applying plugin filter actions...", Debug::$LOG_VERBOSE); foreach ($plugin_filter_names as $pfn) { list($pfclass,$pfaction) = explode(":", $pfn["param"]); @@ -808,18 +801,18 @@ class RSSUtils { if (isset($plugin_filter_actions[$pfclass])) { $plugin = $pluginhost->get_plugin($pfclass); - _debug("... $pfclass: $pfaction", $debug_enabled); + Debug::log("... $pfclass: $pfaction", Debug::$LOG_VERBOSE); if ($plugin) { $start = microtime(true); $article = $plugin->hook_article_filter_action($article, $pfaction); - _debug("=== " . sprintf("%.4f (sec)", microtime(true) - $start), $debug_enabled); + Debug::log(sprintf("=== %.4f (sec)"), Debug::$LOG_VERBOSE); } else { - _debug("??? $pfclass: plugin object not found."); + Debug::log("??? $pfclass: plugin object not found.", Debug::$LOG_VERBOSE); } } else { - _debug("??? $pfclass: filter plugin not registered."); + Debug::log("??? $pfclass: filter plugin not registered.", Debug::$LOG_VERBOSE); } } } @@ -834,18 +827,18 @@ class RSSUtils { $entry_score_modifier = (int) $article["score_modifier"]; $entry_language = $article["language"]; - if ($debug_enabled) { - _debug("article labels:", $debug_enabled); + if (Debug::get_loglevel() >= Debug::$LOG_EXTENDED) { + Debug::log("article labels:", Debug::$LOG_VERBOSE); if (count($article_labels) != 0) { print_r($article_labels); } } - _debug("force catchup: $entry_force_catchup"); + Debug::log("force catchup: $entry_force_catchup", Debug::$LOG_VERBOSE); if ($cache_images && is_writable(CACHE_DIR . '/images')) - RSSUtils::cache_media($entry_content, $site_url, $debug_enabled); + RSSUtils::cache_media($entry_content, $site_url); $csth = $pdo->prepare("SELECT id FROM ttrss_entries WHERE guid = ? OR guid = ?"); @@ -853,7 +846,7 @@ class RSSUtils { if (!$row = $csth->fetch()) { - _debug("base guid [$entry_guid or $entry_guid_hashed] not found, creating...", $debug_enabled); + Debug::log("base guid [$entry_guid or $entry_guid_hashed] not found, creating...", Debug::$LOG_VERBOSE); // base post entry does not exist, create it @@ -901,7 +894,7 @@ class RSSUtils { if ($row = $csth->fetch()) { - _debug("base guid found, checking for user record", $debug_enabled); + Debug::log("base guid found, checking for user record", Debug::$LOG_VERBOSE); $ref_id = $row['id']; $entry_ref_id = $ref_id; @@ -913,7 +906,7 @@ class RSSUtils { $score = RSSUtils::calculate_article_score($article_filters) + $entry_score_modifier; - _debug("initial score: $score [including plugin modifier: $entry_score_modifier]", $debug_enabled); + Debug::log("initial score: $score [including plugin modifier: $entry_score_modifier]", Debug::$LOG_VERBOSE); // check for user post link to main table @@ -926,10 +919,10 @@ class RSSUtils { $entry_ref_id = $row["ref_id"]; $entry_int_id = $row["int_id"]; - _debug("user record FOUND: RID: $entry_ref_id, IID: $entry_int_id", $debug_enabled); + Debug::log("user record FOUND: RID: $entry_ref_id, IID: $entry_int_id", Debug::$LOG_VERBOSE); } else { - _debug("user record not found, creating...", $debug_enabled); + Debug::log("user record not found, creating...", Debug::$LOG_VERBOSE); if ($score >= -500 && !RSSUtils::find_article_filter($article_filters, 'catchup') && !$entry_force_catchup) { $unread = 1; @@ -974,7 +967,7 @@ class RSSUtils { $entry_int_id = $row['int_id']; } - _debug("resulting RID: $entry_ref_id, IID: $entry_int_id", $debug_enabled); + Debug::log("resulting RID: $entry_ref_id, IID: $entry_int_id", Debug::$LOG_VERBOSE); if (DB_TYPE == "pgsql") $tsvector_qpart = "tsvector_combined = to_tsvector(:ts_lang, :ts_content),"; @@ -1017,7 +1010,7 @@ class RSSUtils { $sth->execute([$score, $ref_id]); if ($mark_unread_on_update) { - _debug("article updated, marking unread as requested.", $debug_enabled); + Debug::log("article updated, marking unread as requested.", Debug::$LOG_VERBOSE); $sth = $pdo->prepare("UPDATE ttrss_user_entries SET last_read = null, unread = true WHERE ref_id = ?"); @@ -1025,18 +1018,18 @@ class RSSUtils { } } - _debug("assigning labels [other]...", $debug_enabled); + Debug::log("assigning labels [other]...", Debug::$LOG_VERBOSE); foreach ($article_labels as $label) { Labels::add_article($entry_ref_id, $label[1], $owner_uid); } - _debug("assigning labels [filters]...", $debug_enabled); + Debug::log("assigning labels [filters]...", Debug::$LOG_VERBOSE); RSSUtils::assign_article_to_label_filters($entry_ref_id, $article_filters, $owner_uid, $article_labels); - _debug("looking for enclosures...", $debug_enabled); + Debug::log("looking for enclosures...", Debug::$LOG_VERBOSE); // enclosures @@ -1064,10 +1057,10 @@ class RSSUtils { } if ($cache_images && is_writable(CACHE_DIR . '/images')) - RSSUtils::cache_enclosures($enclosures, $site_url, $debug_enabled); + RSSUtils::cache_enclosures($enclosures, $site_url); - if ($debug_enabled) { - _debug("article enclosures:", $debug_enabled); + if (Debug::get_loglevel() >= Debug::$LOG_EXTENDED) { + Debug::log("article enclosures:", Debug::$LOG_VERBOSE); print_r($enclosures); } @@ -1126,8 +1119,8 @@ class RSSUtils { $filtered_tags = array_unique($filtered_tags); - if ($debug_enabled) { - _debug("filtered article tags:", $debug_enabled); + if (Debug::get_loglevel() >= Debug::$LOG_EXTENDED) { + Debug::log("filtered article tags:", Debug::$LOG_VERBOSE); print_r($filtered_tags); } @@ -1170,14 +1163,14 @@ class RSSUtils { $tsth->execute([$tags_str, $entry_ref_id, $owner_uid]); } - _debug("article processed", $debug_enabled); + Debug::log("article processed", Debug::$LOG_VERBOSE); $pdo->commit(); } - _debug("purging feed...", $debug_enabled); + Debug::log("purging feed...", Debug::$LOG_VERBOSE); - purge_feed($feed, 0, $debug_enabled); + purge_feed($feed, 0); $sth = $pdo->prepare("UPDATE ttrss_feeds SET last_updated = NOW(), last_unconditional = NOW(), last_error = '' WHERE id = ?"); @@ -1187,11 +1180,11 @@ class RSSUtils { $error_msg = mb_substr($rss->error(), 0, 245); - _debug("fetch error: $error_msg", $debug_enabled); + Debug::log("fetch error: $error_msg", Debug::$LOG_VERBOSE); if (count($rss->errors()) > 1) { foreach ($rss->errors() as $error) { - _debug("+ $error"); + Debug::log("+ $error", Debug::$LOG_VERBOSE); } } @@ -1203,12 +1196,12 @@ class RSSUtils { return false; } - _debug("done", $debug_enabled); + Debug::log("done", Debug::$LOG_VERBOSE); return true; } - static function cache_enclosures($enclosures, $site_url, $debug) { + static function cache_enclosures($enclosures, $site_url) { foreach ($enclosures as $enc) { if (preg_match("/(image|audio|video)/", $enc[1])) { @@ -1217,7 +1210,7 @@ class RSSUtils { $local_filename = CACHE_DIR . "/images/" . sha1($src); - if ($debug) _debug("cache_enclosures: downloading: $src to $local_filename"); + Debug::log("cache_enclosures: downloading: $src to $local_filename", Debug::$LOG_VERBOSE); if (!file_exists($local_filename)) { $file_content = fetch_file_contents($src); @@ -1232,7 +1225,7 @@ class RSSUtils { } } - static function cache_media($html, $site_url, $debug) { + static function cache_media($html, $site_url) { libxml_use_internal_errors(true); $charset_hack = ' @@ -1251,10 +1244,10 @@ class RSSUtils { $local_filename = CACHE_DIR . "/images/" . sha1($src); - if ($debug) _debug("cache_media: checking $src"); + Debug::log("cache_media: checking $src", Debug::$LOG_VERBOSE); if (!file_exists($local_filename)) { - if ($debug) _debug("cache_media: downloading: $src to $local_filename"); + Debug::log("cache_media: downloading: $src to $local_filename", Debug::$LOG_VERBOSE); $file_content = fetch_file_contents($src); @@ -1268,8 +1261,8 @@ class RSSUtils { } } - static function expire_error_log($debug) { - if ($debug) _debug("Removing old error log entries..."); + static function expire_error_log() { + Debug::log("Removing old error log entries..."); $pdo = Db::pdo(); @@ -1282,8 +1275,8 @@ class RSSUtils { } } - static function expire_lock_files($debug) { - //if ($debug) _debug("Removing old lock files..."); + static function expire_lock_files() { + Debug::log("Removing old lock files...", Debug::$LOG_VERBOSE); $num_deleted = 0; @@ -1300,14 +1293,14 @@ class RSSUtils { } } - if ($debug) _debug("Removed $num_deleted old lock files."); + Debug::log("Removed $num_deleted old lock files."); } - static function expire_cached_files($debug) { + static function expire_cached_files() { foreach (array("feeds", "images", "export", "upload") as $dir) { $cache_dir = CACHE_DIR . "/$dir"; -// if ($debug) _debug("Expiring $cache_dir"); + Debug::log("Expiring $cache_dir", Debug::$LOG_VERBOSE); $num_deleted = 0; @@ -1325,7 +1318,7 @@ class RSSUtils { } } - if ($debug) _debug("$cache_dir: removed $num_deleted files."); + Debug::log("$cache_dir: removed $num_deleted files."); } } @@ -1485,7 +1478,7 @@ class RSSUtils { mb_strtolower(strip_tags($title), 'utf-8')); } - static function cleanup_counters_cache($debug) { + static function cleanup_counters_cache() { $pdo = Db::pdo(); $res = $pdo->query("DELETE FROM ttrss_counters_cache @@ -1504,7 +1497,7 @@ class RSSUtils { $crows = $res->rowCount(); - if ($debug) _debug("Removed $frows (feeds) $crows (cats) orphaned counter cache entries."); + Debug::log("Removed $frows (feeds) $crows (cats) orphaned counter cache entries."); } static function housekeeping_user($owner_uid) { @@ -1515,19 +1508,16 @@ class RSSUtils { $tmph->run_hooks(PluginHost::HOOK_HOUSE_KEEPING, "hook_house_keeping", ""); } - static function housekeeping_common($debug) { - RSSUtils::expire_cached_files($debug); - RSSUtils::expire_lock_files($debug); - RSSUtils::expire_error_log($debug); + static function housekeeping_common() { + RSSUtils::expire_cached_files(); + RSSUtils::expire_lock_files(); + RSSUtils::expire_error_log(); $count = RSSUtils::update_feedbrowser_cache(); - _debug("Feedbrowser updated, $count feeds processed."); - - Article::purge_orphans( true); - RSSUtils::cleanup_counters_cache($debug); + Debug::log("Feedbrowser updated, $count feeds processed."); - //$rc = cleanup_tags( 14, 50000); - //_debug("Cleaned $rc cached tags."); + Article::purge_orphans(); + RSSUtils::cleanup_counters_cache(); PluginHost::getInstance()->run_hooks(PluginHost::HOOK_HOUSE_KEEPING, "hook_house_keeping", ""); } diff --git a/include/functions.php b/include/functions.php index b2908983..424f87e9 100755 --- a/include/functions.php +++ b/include/functions.php @@ -13,7 +13,6 @@ $fetch_last_error_content = false; // curl only for the time being $fetch_effective_url = false; $fetch_curl_used = false; - $suppress_debugging = false; libxml_disable_entity_loader(true); @@ -156,67 +155,11 @@ $schema_version = false; - function _debug_suppress($suppress) { - global $suppress_debugging; - - $suppress_debugging = $suppress; + // TODO: compat wrapper, remove at some point + function _debug($msg) { + Debug::log($msg); } - /** - * Print a timestamped debug message. - * - * @param string $msg The debug message. - * @return void - */ - function _debug($msg, $show = true) { - global $suppress_debugging; - - //echo "[$suppress_debugging] $msg $show\n"; - - if ($suppress_debugging) return false; - - $ts = strftime("%H:%M:%S", time()); - if (function_exists('posix_getpid')) { - $ts = "$ts/" . posix_getpid(); - } - - if ($show && !(defined('QUIET') && QUIET)) { - print "[$ts] $msg\n"; - } - - if (defined('LOGFILE')) { - $fp = fopen(LOGFILE, 'a+'); - - if ($fp) { - $locked = false; - - if (function_exists("flock")) { - $tries = 0; - - // try to lock logfile for writing - while ($tries < 5 && !$locked = flock($fp, LOCK_EX | LOCK_NB)) { - sleep(1); - ++$tries; - } - - if (!$locked) { - fclose($fp); - return; - } - } - - fputs($fp, "[$ts] $msg\n"); - - if (function_exists("flock")) { - flock($fp, LOCK_UN); - } - - fclose($fp); - } - } - - } // function _debug - /** * Purge a feed old posts. * @@ -227,7 +170,7 @@ * @access public * @return void */ - function purge_feed($feed_id, $purge_interval, $debug = false) { + function purge_feed($feed_id, $purge_interval) { if (!$purge_interval) $purge_interval = feed_purge_interval($feed_id); @@ -292,9 +235,7 @@ CCache::update($feed_id, $owner_uid); - if ($debug) { - _debug("Purged feed $feed_id ($purge_interval): deleted $rows articles"); - } + Debug::log("Purged feed $feed_id ($purge_interval): deleted $rows articles"); return $rows; } // function purge_feed @@ -421,7 +362,7 @@ // holy shit closures in php // download & upload are *expected* sizes respectively, could be zero curl_setopt($ch, CURLOPT_PROGRESSFUNCTION, function($curl_handle, $download_size, $downloaded, $upload_size, $uploaded) use( &$max_size) { - //_debug("[curl progressfunction] $downloaded $max_size"); + Debug::log("[curl progressfunction] $downloaded $max_size", Debug::$LOG_EXTENDED); return ($downloaded > $max_size) ? 1 : 0; // if max size is set, abort when exceeding it }); diff --git a/plugins/af_comics/filters/af_comics_pa.php b/plugins/af_comics/filters/af_comics_pa.php index e6558d8d..7a60feab 100644 --- a/plugins/af_comics/filters/af_comics_pa.php +++ b/plugins/af_comics/filters/af_comics_pa.php @@ -8,10 +8,6 @@ class Af_Comics_Pa extends Af_ComicFilter { function process(&$article) { if (strpos($article["link"], "penny-arcade.com") !== FALSE && strpos($article["title"], "Comic:") !== FALSE) { - /*if ($debug_enabled) { - _debug("af_pennyarcade: Processing comic"); - }*/ - $doc = new DOMDocument(); if ($doc->loadHTML(fetch_file_contents($article["link"]))) { @@ -27,9 +23,6 @@ class Af_Comics_Pa extends Af_ComicFilter { } if (strpos($article["link"], "penny-arcade.com") !== FALSE && strpos($article["title"], "News Post:") !== FALSE) { - /*if ($debug_enabled) { - _debug("af_pennyarcade: Processing news post"); - }*/ $doc = new DOMDocument(); if ($doc->loadHTML(fetch_file_contents($article["link"]))) { diff --git a/plugins/af_psql_trgm/init.php b/plugins/af_psql_trgm/init.php index 19653c0f..fe5b1a95 100644 --- a/plugins/af_psql_trgm/init.php +++ b/plugins/af_psql_trgm/init.php @@ -287,7 +287,7 @@ class Af_Psql_Trgm extends Plugin { $row = $sth->fetch(); $nequal = $row['nequal']; - _debug("af_psql_trgm: num equals: $nequal"); + Debug::log("af_psql_trgm: num equals: $nequal", Debug::$LOG_EXTENDED); if ($nequal != 0) { $article["force_catchup"] = true; @@ -304,7 +304,7 @@ class Af_Psql_Trgm extends Plugin { $row = $sth->fetch(); $similarity_result = $row['ms']; - _debug("af_psql_trgm: similarity result: $similarity_result"); + Debug::log("af_psql_trgm: similarity result: $similarity_result", Debug::$LOG_EXTENDED); if ($similarity_result >= $similarity) { $article["force_catchup"] = true; diff --git a/plugins/af_redditimgur/init.php b/plugins/af_redditimgur/init.php index be3a5108..2b8415dd 100755 --- a/plugins/af_redditimgur/init.php +++ b/plugins/af_redditimgur/init.php @@ -82,7 +82,7 @@ class Af_RedditImgur extends Plugin { /** * @SuppressWarnings(PHPMD.UnusedFormalParameter) */ - private function inline_stuff($article, &$doc, $xpath, $debug = false) { + private function inline_stuff($article, &$doc, $xpath) { $entries = $xpath->query('(//a[@href]|//img[@src])'); $img_entries = $xpath->query("(//img[@src])"); @@ -93,12 +93,12 @@ class Af_RedditImgur extends Plugin { foreach ($entries as $entry) { if ($entry->hasAttribute("href") && strpos($entry->getAttribute("href"), "reddit.com") === FALSE) { - _debug("processing href: " . $entry->getAttribute("href"), $debug); + Debug::log("processing href: " . $entry->getAttribute("href"), Debug::$LOG_VERBOSE); $matches = array(); if (!$found && preg_match("/^https?:\/\/twitter.com\/(.*?)\/status\/(.*)/", $entry->getAttribute("href"), $matches)) { - _debug("handling as twitter: " . $matches[1] . " " . $matches[2], $debug); + Debug::log("handling as twitter: " . $matches[1] . " " . $matches[2], Debug::$LOG_VERBOSE); $oembed_result = fetch_file_contents("https://publish.twitter.com/oembed?url=" . urlencode($entry->getAttribute("href"))); @@ -130,7 +130,7 @@ class Af_RedditImgur extends Plugin { if (!$found && preg_match("/https?:\/\/(www\.)?gfycat.com\/([a-z]+)$/i", $entry->getAttribute("href"), $matches)) { - _debug("Handling as Gfycat", $debug); + Debug::log("Handling as Gfycat", Debug::$LOG_VERBOSE); $source_stream = 'https://giant.gfycat.com/' . $matches[2] . '.mp4'; $poster_url = 'https://thumbs.gfycat.com/' . $matches[2] . '-mobile.jpg'; @@ -145,7 +145,7 @@ class Af_RedditImgur extends Plugin { if (!$found && preg_match("/https?:\/\/v\.redd\.it\/(.*)$/i", $entry->getAttribute("href"), $matches)) { - _debug("Handling as reddit inline video", $debug); + Debug::log("Handling as reddit inline video", Debug::$LOG_VERBOSE); $img = $img_entries->item(0); @@ -157,7 +157,7 @@ class Af_RedditImgur extends Plugin { // Get original article URL from v.redd.it redirects $source_article_url = $this->get_location($matches[0]); - _debug("Resolved ".$matches[0]." to ".$source_article_url, $debug); + Debug::log("Resolved ".$matches[0]." to ".$source_article_url, Debug::$LOG_VERBOSE); $source_stream = false; @@ -190,7 +190,7 @@ class Af_RedditImgur extends Plugin { if (!$found && preg_match("/https?:\/\/(www\.)?streamable.com\//i", $entry->getAttribute("href"))) { - _debug("Handling as Streamable", $debug); + Debug::log("Handling as Streamable", Debug::$LOG_VERBOSE); $tmp = fetch_file_contents($entry->getAttribute("href")); @@ -216,21 +216,21 @@ class Af_RedditImgur extends Plugin { // imgur .gif -> .gifv if (!$found && preg_match("/i\.imgur\.com\/(.*?)\.gif$/i", $entry->getAttribute("href"))) { - _debug("Handling as imgur gif (->gifv)", $debug); + Debug::log("Handling as imgur gif (->gifv)", Debug::$LOG_VERBOSE); $entry->setAttribute("href", str_replace(".gif", ".gifv", $entry->getAttribute("href"))); } if (!$found && preg_match("/\.(gifv|mp4)$/i", $entry->getAttribute("href"))) { - _debug("Handling as imgur gifv", $debug); + Debug::log("Handling as imgur gifv", Debug::$LOG_VERBOSE); $source_stream = str_replace(".gifv", ".mp4", $entry->getAttribute("href")); if (strpos($source_stream, "imgur.com") !== FALSE) $poster_url = str_replace(".mp4", "h.jpg", $source_stream); - $this->handle_as_video($doc, $entry, $source_stream, $poster_url, $debug); + $this->handle_as_video($doc, $entry, $source_stream, $poster_url); $found = true; } @@ -243,7 +243,7 @@ class Af_RedditImgur extends Plugin { $vid_id = $matches[1]; - _debug("Handling as youtube: $vid_id", $debug); + Debug::log("Handling as youtube: $vid_id", Debug::$LOG_VERBOSE); $iframe = $doc->createElement("iframe"); $iframe->setAttribute("class", "youtube-player"); @@ -265,7 +265,7 @@ class Af_RedditImgur extends Plugin { mb_strpos($entry->getAttribute("href"), "i.reddituploads.com") !== FALSE || mb_strpos($this->get_content_type($entry->getAttribute("href")), "image/") !== FALSE) { - _debug("Handling as a picture", $debug); + Debug::log("Handling as a picture", Debug::$LOG_VERBOSE); $img = $doc->createElement('img'); $img->setAttribute("src", $entry->getAttribute("href")); @@ -281,7 +281,7 @@ class Af_RedditImgur extends Plugin { if (!$found && preg_match("/^https?:\/\/gyazo\.com\/([^\.\/]+$)/", $entry->getAttribute("href"), $matches)) { $img_id = $matches[1]; - _debug("handling as gyazo: $img_id", $debug); + Debug::log("handling as gyazo: $img_id", Debug::$LOG_VERBOSE); $img = $doc->createElement('img'); $img->setAttribute("src", "https://i.gyazo.com/$img_id.jpg"); @@ -295,7 +295,7 @@ class Af_RedditImgur extends Plugin { // let's try meta properties if (!$found) { - _debug("looking for meta og:image", $debug); + Debug::log("looking for meta og:image", Debug::$LOG_VERBOSE); $content = fetch_file_contents(["url" => $entry->getAttribute("href"), "http_accept" => "text/*"]); @@ -415,9 +415,9 @@ class Af_RedditImgur extends Plugin { return 2; } - private function handle_as_video($doc, $entry, $source_stream, $poster_url = false, $debug = false) { + private function handle_as_video($doc, $entry, $source_stream, $poster_url = false) { - _debug("handle_as_video: $source_stream", $debug); + Debug::log("handle_as_video: $source_stream", Debug::$LOG_VERBOSE); $video = $doc->createElement('video'); $video->setAttribute("autoplay", "1"); @@ -454,14 +454,14 @@ class Af_RedditImgur extends Plugin { @$doc->loadHTML("[link]"); $xpath = new DOMXPath($doc); - $found = $this->inline_stuff([], $doc, $xpath, true); + $found = $this->inline_stuff([], $doc, $xpath); print "Inline result: $found\n"; if (!$found) { print "\nReadability result:\n"; - $article = $this->readability([], $url, $doc, $xpath, true); + $article = $this->readability([], $url, $doc, $xpath); print_r($article); } else { @@ -523,7 +523,7 @@ class Af_RedditImgur extends Plugin { "useragent" => $useragent_compat, "http_accept" => "text/html"]); - if ($debug) _debug("tmplen: " . mb_strlen($tmp)); + Debug::log("tmplen: " . mb_strlen($tmp), Debug::$LOG_VERBOSE); if ($tmp && mb_strlen($tmp) < 1024 * 500) { diff --git a/plugins/cache_starred_images/init.php b/plugins/cache_starred_images/init.php index ae0eaf56..a1916e22 100755 --- a/plugins/cache_starred_images/init.php +++ b/plugins/cache_starred_images/init.php @@ -170,7 +170,7 @@ class Cache_Starred_Images extends Plugin implements IHandler { $status_filename = $this->cache_dir . $article_id . "-" . sha1($site_url) . ".status"; - //_debug("status: $status_filename"); return; + Debug::log("status: $status_filename", Debug::$LOG_EXTENDED); if (file_exists($status_filename)) $status = json_decode(file_get_contents($status_filename), true); @@ -181,7 +181,7 @@ class Cache_Starred_Images extends Plugin implements IHandler { // only allow several download attempts for article if ($status["attempt"] > $this->max_cache_attempts) { - _debug("too many attempts for $site_url"); + Debug::log("too many attempts for $site_url", Debug::$LOG_VERBOSE); return; } @@ -214,7 +214,7 @@ class Cache_Starred_Images extends Plugin implements IHandler { $local_filename = $this->cache_dir . $article_id . "-" . sha1($src) . $extension; - //_debug("cache_images: downloading: $src to $local_filename"); + Debug::log("cache_images: downloading: $src to $local_filename", Debug::$LOG_VERBOSE); if (!file_exists($local_filename)) { $file_content = fetch_file_contents(["url" => $src, "max_size" => MAX_CACHE_FILE_SIZE]); diff --git a/plugins/import_export/init.php b/plugins/import_export/init.php index a3413f30..ef1e2db6 100755 --- a/plugins/import_export/init.php +++ b/plugins/import_export/init.php @@ -24,11 +24,11 @@ class Import_Export extends Plugin implements IHandler { return; } - _debug("please enter your username:"); + Debug::log("please enter your username:"); $username = trim(read_stdin()); - _debug("importing $filename for user $username...\n"); + Debug::log("importing $filename for user $username...\n"); $sth = $this->pdo->prepare("SELECT id FROM ttrss_users WHERE login = ?"); $sth->execute($username); diff --git a/update.php b/update.php index 8f268cd3..17eafe12 100755 --- a/update.php +++ b/update.php @@ -29,6 +29,7 @@ "cleanup-tags", "quiet", "log:", + "log-level:", "indexes", "pidlock:", "update-schema", @@ -82,6 +83,7 @@ print " --cleanup-tags - perform tags table maintenance\n"; print " --quiet - don't output messages to stdout\n"; print " --log FILE - log messages to FILE\n"; + print " --log-level N - log verbosity level\n"; print " --indexes - recreate missing schema indexes\n"; print " --update-schema - update database schema\n"; print " --gen-search-idx - generate basic PostgreSQL fulltext search index\n"; @@ -114,12 +116,17 @@ } } - define('QUIET', isset($options['quiet'])); + Debug::set_enabled(true); + Debug::set_quiet(isset($options['quiet'])); + + if (isset($options["log-level"])) { + Debug::set_loglevel((int)$options["log-level"]); + } if (isset($options["log"])) { - _debug("Logging to " . $options["log"]); - define('LOGFILE', $options["log"]); - } + Debug::set_logfile($options["log"]); + Debug::log("Logging to " . $options["log"]); + } if (!isset($options["daemon"])) { $lock_filename = "update.lock"; @@ -128,7 +135,7 @@ } if (isset($options["task"])) { - _debug("Using task id " . $options["task"]); + Debug::log("Using task id " . $options["task"]); $lock_filename = $lock_filename . "-task_" . $options["task"]; } @@ -138,14 +145,14 @@ } - _debug("Lock: $lock_filename"); + Debug::log("Lock: $lock_filename"); $lock_handle = make_lockfile($lock_filename); $must_exit = false; if (isset($options["task"]) && isset($options["pidlock"])) { $waits = $options["task"] * 5; - _debug("Waiting before update ($waits)"); + Debug::log("Waiting before update ($waits)"); sleep($waits); } @@ -156,7 +163,7 @@ } if (isset($options["force-update"])) { - _debug("marking all feeds as needing update..."); + Debug::log("marking all feeds as needing update..."); $pdo->query( "UPDATE ttrss_feeds SET last_update_started = '1970-01-01', last_updated = '1970-01-01'"); @@ -177,21 +184,22 @@ if (isset($options["daemon"])) { while (true) { $quiet = (isset($options["quiet"])) ? "--quiet" : ""; - $log = isset($options['log']) ? '--log '.$options['log'] : ''; + $log = isset($options['log']) ? '--log '.$options['log'] : ''; + $log_level = isset($options['log-level']) ? '--log-level '.$options['log-level'] : ''; - passthru(PHP_EXECUTABLE . " " . $argv[0] ." --daemon-loop $quiet $log"); + passthru(PHP_EXECUTABLE . " " . $argv[0] ." --daemon-loop $quiet $log $log_level"); // let's enforce a minimum spawn interval as to not forkbomb the host $spawn_interval = max(60, DAEMON_SLEEP_INTERVAL); - _debug("Sleeping for $spawn_interval seconds..."); + Debug::log("Sleeping for $spawn_interval seconds..."); sleep($spawn_interval); } } if (isset($options["daemon-loop"])) { if (!make_stampfile('update_daemon.stamp')) { - _debug("warning: unable to create stampfile\n"); + Debug::log("warning: unable to create stampfile\n"); } RSSUtils::update_daemon_common(isset($options["pidlock"]) ? 50 : DAEMON_FEED_LIMIT); @@ -204,17 +212,17 @@ if (isset($options["cleanup-tags"])) { $rc = cleanup_tags( 14, 50000); - _debug("$rc tags deleted.\n"); + Debug::log("$rc tags deleted.\n"); } if (isset($options["indexes"])) { - _debug("PLEASE BACKUP YOUR DATABASE BEFORE PROCEEDING!"); - _debug("Type 'yes' to continue."); + Debug::log("PLEASE BACKUP YOUR DATABASE BEFORE PROCEEDING!"); + Debug::log("Type 'yes' to continue."); if (read_stdin() != 'yes') exit; - _debug("clearing existing indexes..."); + Debug::log("clearing existing indexes..."); if (DB_TYPE == "pgsql") { $sth = $pdo->query( "SELECT relname FROM @@ -229,16 +237,16 @@ while ($line = $sth->fetch()) { if (DB_TYPE == "pgsql") { $statement = "DROP INDEX " . $line["relname"]; - _debug($statement); + Debug::log($statement); } else { $statement = "ALTER TABLE ". $line['table_name']." DROP INDEX ".$line['index_name']; - _debug($statement); + Debug::log($statement); } $pdo->query($statement); } - _debug("reading indexes from schema for: " . DB_TYPE); + Debug::log("reading indexes from schema for: " . DB_TYPE); $fp = fopen("schema/ttrss_schema_" . DB_TYPE . ".sql", "r"); if ($fp) { @@ -251,25 +259,25 @@ $statement = "CREATE INDEX $index ON $table"; - _debug($statement); + Debug::log($statement); $pdo->query($statement); } } fclose($fp); } else { - _debug("unable to open schema file."); + Debug::log("unable to open schema file."); } - _debug("all done."); + Debug::log("all done."); } if (isset($options["convert-filters"])) { - _debug("WARNING: this will remove all existing type2 filters."); - _debug("Type 'yes' to continue."); + Debug::log("WARNING: this will remove all existing type2 filters."); + Debug::log("Type 'yes' to continue."); if (read_stdin() != 'yes') exit; - _debug("converting filters..."); + Debug::log("converting filters..."); $pdo->query("DELETE FROM ttrss_filters2"); @@ -314,30 +322,30 @@ } if (isset($options["update-schema"])) { - _debug("checking for updates (" . DB_TYPE . ")..."); + Debug::log("checking for updates (" . DB_TYPE . ")..."); $updater = new DbUpdater(Db::pdo(), DB_TYPE, SCHEMA_VERSION); if ($updater->isUpdateRequired()) { - _debug("schema update required, version " . $updater->getSchemaVersion() . " to " . SCHEMA_VERSION); - _debug("WARNING: please backup your database before continuing."); - _debug("Type 'yes' to continue."); + Debug::log("schema update required, version " . $updater->getSchemaVersion() . " to " . SCHEMA_VERSION); + Debug::log("WARNING: please backup your database before continuing."); + Debug::log("Type 'yes' to continue."); if (read_stdin() != 'yes') exit; for ($i = $updater->getSchemaVersion() + 1; $i <= SCHEMA_VERSION; $i++) { - _debug("performing update up to version $i..."); + Debug::log("performing update up to version $i..."); $result = $updater->performUpdateTo($i, false); - _debug($result ? "OK!" : "FAILED!"); + Debug::log($result ? "OK!" : "FAILED!"); if (!$result) return; } } else { - _debug("update not required."); + Debug::log("update not required."); } } @@ -408,7 +416,7 @@ if (isset($options["force-refetch"])) $_REQUEST["force_refetch"] = true; if (isset($options["force-rehash"])) $_REQUEST["force_rehash"] = true; - $_REQUEST['xdebug'] = 1; + Debug::set_loglevel(Debug::$LOG_EXTENDED); $rc = RSSUtils::update_rss_feed($feed) != false ? 0 : 1; diff --git a/update_daemon2.php b/update_daemon2.php index af29ac18..007d6286 100755 --- a/update_daemon2.php +++ b/update_daemon2.php @@ -59,12 +59,12 @@ if (file_is_locked("update_daemon-$pid.lock")) { array_push($tmp, $pid); } else { - _debug("[reap_children] child $pid seems active but lockfile is unlocked."); + Debug::log("[reap_children] child $pid seems active but lockfile is unlocked."); unset($ctimes[$pid]); } } else { - _debug("[reap_children] child $pid reaped."); + Debug::log("[reap_children] child $pid reaped."); unset($ctimes[$pid]); } } @@ -81,7 +81,7 @@ $started = $ctimes[$pid]; if (time() - $started > MAX_CHILD_RUNTIME) { - _debug("[MASTER] child process $pid seems to be stuck, aborting..."); + Debug::log("[MASTER] child process $pid seems to be stuck, aborting..."); posix_kill($pid, SIGKILL); } } @@ -93,7 +93,7 @@ function sigchld_handler($signal) { $running_jobs = reap_children(); - _debug("[SIGCHLD] jobs left: $running_jobs"); + Debug::log("[SIGCHLD] jobs left: $running_jobs"); pcntl_waitpid(-1, $status, WNOHANG); } @@ -101,7 +101,7 @@ function shutdown($caller_pid) { if ($caller_pid == posix_getpid()) { if (file_exists(LOCK_DIRECTORY . "/update_daemon.lock")) { - _debug("removing lockfile (master)..."); + Debug::log("removing lockfile (master)..."); unlink(LOCK_DIRECTORY . "/update_daemon.lock"); } } @@ -111,19 +111,19 @@ $pid = posix_getpid(); if (file_exists(LOCK_DIRECTORY . "/update_daemon-$pid.lock")) { - _debug("removing lockfile ($pid)..."); + Debug::log("removing lockfile ($pid)..."); unlink(LOCK_DIRECTORY . "/update_daemon-$pid.lock"); } } function sigint_handler() { - _debug("[MASTER] SIG_INT received.\n"); + Debug::log("[MASTER] SIG_INT received.\n"); shutdown(posix_getpid()); die; } function task_sigint_handler() { - _debug("[TASK] SIG_INT received.\n"); + Debug::log("[TASK] SIG_INT received.\n"); task_shutdown(); die; } @@ -131,6 +131,7 @@ pcntl_signal(SIGCHLD, 'sigchld_handler'); $longopts = array("log:", + "log-level:", "tasks:", "interval:", "quiet", @@ -142,6 +143,7 @@ print "Tiny Tiny RSS update daemon.\n\n"; print "Options:\n"; print " --log FILE - log messages to FILE\n"; + print " --log-level N - log verbosity level\n"; print " --tasks N - amount of update tasks to spawn\n"; print " default: " . MAX_JOBS . "\n"; print " --interval N - task spawn interval\n"; @@ -150,17 +152,27 @@ return; } - define('QUIET', isset($options['quiet'])); + Debug::set_enabled(true); + Debug::set_quiet(isset($options['quiet'])); + + if (isset($options["log-level"])) { + Debug::set_loglevel((int)$options["log-level"]); + } + + if (isset($options["log"])) { + Debug::set_logfile($options["log"]); + Debug::log("Logging to " . $options["log"]); + } if (isset($options["tasks"])) { - _debug("Set to spawn " . $options["tasks"] . " children."); + Debug::log("Set to spawn " . $options["tasks"] . " children."); $max_jobs = $options["tasks"]; } else { $max_jobs = MAX_JOBS; } if (isset($options["interval"])) { - _debug("Spawn interval: " . $options["interval"] . " seconds."); + Debug::log("Spawn interval: " . $options["interval"] . " seconds."); $spawn_interval = $options["interval"]; } else { $spawn_interval = SPAWN_INTERVAL; @@ -168,12 +180,7 @@ // let's enforce a minimum spawn interval as to not forkbomb the host $spawn_interval = max(60, $spawn_interval); - _debug("Spawn interval: $spawn_interval sec"); - - if (isset($options["log"])) { - _debug("Logging to " . $options["log"]); - define('LOGFILE', $options["log"]); - } + Debug::log("Spawn interval: $spawn_interval sec"); if (file_is_locked("update_daemon.lock")) { die("error: Can't create lockfile. ". @@ -205,7 +212,7 @@ if ($next_spawn % 60 == 0) { $running_jobs = count($children); - _debug("[MASTER] active jobs: $running_jobs, next spawn at $next_spawn sec."); + Debug::log("[MASTER] active jobs: $running_jobs, next spawn at $next_spawn sec."); } if ($last_checkpoint + $spawn_interval < time()) { @@ -219,14 +226,14 @@ } else if ($pid) { if (!$master_handlers_installed) { - _debug("[MASTER] installing shutdown handlers"); + Debug::log("[MASTER] installing shutdown handlers"); pcntl_signal(SIGINT, 'sigint_handler'); pcntl_signal(SIGTERM, 'sigint_handler'); register_shutdown_function('shutdown', posix_getpid()); $master_handlers_installed = true; } - _debug("[MASTER] spawned client $j [PID:$pid]..."); + Debug::log("[MASTER] spawned client $j [PID:$pid]..."); array_push($children, $pid); $ctimes[$pid] = time(); } else { -- 2.39.5