Merge pull request #8359 from MrPetovan/bug/7134-local-post-deleted

Add callstack context to cascade deletion debug logging

src/Database/Database.php

@@ -1262,7 +1262,7 @@ class Database
 
 			if ((count($command['conditions']) > 1) || is_int($first_key)) {
 				$sql = "DELETE FROM " . DBA::quoteIdentifier($command['table']) . " " . $condition_string;
-				$this->logger->debug($this->replaceParameters($sql, $conditions));
+				$this->logger->info($this->replaceParameters($sql, $conditions), ['callstack' => System::callstack(6), 'internal_callstack' => $callstack]);
 
 				if (!$this->e($sql, $conditions)) {
 					if ($do_transaction) {
@@ -1292,7 +1292,7 @@ class Database
 					$sql = "DELETE FROM " . DBA::quoteIdentifier($table) . " WHERE " . DBA::quoteIdentifier($field) . " IN (" .
 					       substr(str_repeat("?, ", count($field_values)), 0, -2) . ");";
 
-					$this->logger->debug($this->replaceParameters($sql, $field_values));
+					$this->logger->info($this->replaceParameters($sql, $field_values), ['callstack' => System::callstack(6), 'internal_callstack' => $callstack]);
 
 					if (!$this->e($sql, $field_values)) {
 						if ($do_transaction) {

src/Model/Item.php

@@ -1066,11 +1066,11 @@ class Item
 	 * @param integer $priority  Priority for the notification
 	 * @throws \Friendica\Network\HTTPException\InternalServerErrorException
 	 */
-	public static function delete($condition, $priority = PRIORITY_HIGH)
+	public static function markForDeletion($condition, $priority = PRIORITY_HIGH)
 	{
 		$items = self::select(['id'], $condition);
 		while ($item = self::fetch($items)) {
-			self::deleteById($item['id'], $priority);
+			self::markForDeletionById($item['id'], $priority);
 		}
 		DBA::close($items);
 	}
@@ -1097,7 +1097,7 @@ class Item
 				// Delete notifications
 				DBA::delete('notify', ['iid' => $item['id'], 'uid' => $uid]);
 			} elseif ($item['uid'] == $uid) {
-				self::deleteById($item['id'], PRIORITY_HIGH);
+				self::markForDeletionById($item['id'], PRIORITY_HIGH);
 			} else {
 				Logger::log('Wrong ownership. Not deleting item ' . $item['id']);
 			}
@@ -1106,17 +1106,17 @@ class Item
 	}
 
 	/**
-	 * Delete an item and notify others about it - if it was ours
+	 * Mark an item for deletion, delete related data and notify others about it - if it was ours
 	 *
-	 * @param integer $item_id  Item ID that should be delete
+	 * @param integer $item_id
 	 * @param integer $priority Priority for the notification
 	 *
 	 * @return boolean success
 	 * @throws \Friendica\Network\HTTPException\InternalServerErrorException
 	 */
-	public static function deleteById($item_id, $priority = PRIORITY_HIGH)
+	public static function markForDeletionById($item_id, $priority = PRIORITY_HIGH)
 	{
-		Logger::notice('Delete item by id', ['id' => $item_id, 'callstack' => System::callstack()]);
+		Logger::info('Mark item for deletion by id', ['id' => $item_id, 'callstack' => System::callstack()]);
 		// locate item to be deleted
 		$fields = ['id', 'uri', 'uid', 'parent', 'parent-uri', 'origin',
 			'deleted', 'file', 'resource-id', 'event-id', 'attach',
@@ -1124,12 +1124,12 @@ class Item
 			'icid', 'iaid', 'psid'];
 		$item = self::selectFirst($fields, ['id' => $item_id]);
 		if (!DBA::isResult($item)) {
-			Logger::log('Item with ID ' . $item_id . " hasn't been found.", Logger::DEBUG);
+			Logger::info('Item not found.', ['id' => $item_id]);
 			return false;
 		}
 
 		if ($item['deleted']) {
-			Logger::log('Item with ID ' . $item_id . ' has already been deleted.', Logger::DEBUG);
+			Logger::info('Item has already been marked for deletion.', ['id' => $item_id]);
 			return false;
 		}
 
@@ -1199,7 +1199,7 @@ class Item
 		self::deleteThread($item['id'], $item['parent-uri']);
 
 		if (!self::exists(["`uri` = ? AND `uid` != 0 AND NOT `deleted`", $item['uri']])) {
-			self::delete(['uri' => $item['uri'], 'uid' => 0, 'deleted' => false], $priority);
+			self::markForDeletion(['uri' => $item['uri'], 'uid' => 0, 'deleted' => false], $priority);
 		}
 
 		ItemDeliveryData::delete($item['id']);
@@ -1219,14 +1219,13 @@ class Item
 
 		// If it's the parent of a comment thread, kill all the kids
 		if ($item['id'] == $item['parent']) {
-			self::delete(['parent' => $item['parent'], 'deleted' => false], $priority);
+			self::markForDeletion(['parent' => $item['parent'], 'deleted' => false], $priority);
 		}
 
 		// Is it our comment and/or our thread?
 		if ($item['origin'] || $parent['origin']) {
-
 			// When we delete the original post we will delete all existing copies on the server as well
-			self::delete(['uri' => $item['uri'], 'deleted' => false], $priority);
+			self::markForDeletion(['uri' => $item['uri'], 'deleted' => false], $priority);
 
 			// send the notification upstream/downstream
 			Worker::add(['priority' => $priority, 'dont_fork' => true], "Notifier", Delivery::DELETION, intval($item['id']));
@@ -1239,7 +1238,7 @@ class Item
 			}
 		}
 
-		Logger::log('Item with ID ' . $item_id . " has been deleted.", Logger::DEBUG);
+		Logger::info('Item has been marked for deletion.', ['id' => $item_id]);
 
 		return true;
 	}
@@ -1939,7 +1938,7 @@ class Item
 
 		if ($entries > 1) {
 			// There are duplicates. We delete our just created entry.
-			Logger::notice('Delete duplicated item', ['id' => $current_post, 'uri' => $item['uri'], 'uid' => $item['uid']]);
+			Logger::info('Delete duplicated item', ['id' => $current_post, 'uri' => $item['uri'], 'uid' => $item['uid'], 'guid' => $item['guid']]);
 
 			// Yes, we could do a rollback here - but we are having many users with MyISAM.
 			DBA::delete('item', ['id' => $current_post]);
@@ -2722,7 +2721,7 @@ class Item
 		if (!$mention) {
 			if (($community_page || $prvgroup) &&
 				  !$item['wall'] && !$item['origin'] && ($item['id'] == $item['parent'])) {
-				Logger::notice('Delete private group/communiy top-level item without mention', ['id' => $item_id]);
+				Logger::info('Delete private group/communiy top-level item without mention', ['id' => $item_id, 'guid'=> $item['guid']]);
 				DBA::delete('item', ['id' => $item_id]);
 				return true;
 			}
@@ -3105,7 +3104,7 @@ class Item
 				continue;
 			}
 
-			self::deleteById($item['id'], PRIORITY_LOW);
+			self::markForDeletionById($item['id'], PRIORITY_LOW);
 
 			++$expired;
 		}
@@ -3246,7 +3245,7 @@ class Item
 
 		// If it exists, mark it as deleted
 		if (DBA::isResult($like_item)) {
-			self::deleteById($like_item['id']);
+			self::markForDeletionById($like_item['id']);
 
 			if (!$event_verb_flag || $like_item['verb'] == $activity) {
 				return true;

src/Module/Admin/Item/Delete.php

@@ -48,7 +48,7 @@ class Delete extends BaseAdmin
 			}
 			// Now that we have the GUID, drop those items, which will also delete the
 			// associated threads.
-			Item::delete(['guid' => $guid]);
+			Item::markForDeletion(['guid' => $guid]);
 		}
 
 		info(DI::l10n()->t('Item marked for deletion.') . EOL);

src/Protocol/ActivityPub/Processor.php

@@ -220,7 +220,7 @@ class Processor
 		$owner = Contact::getIdForURL($activity['actor']);
 
 		Logger::log('Deleting item ' . $activity['object_id'] . ' from ' . $owner, Logger::DEBUG);
-		Item::delete(['uri' => $activity['object_id'], 'owner-id' => $owner]);
+		Item::markForDeletion(['uri' => $activity['object_id'], 'owner-id' => $owner]);
 	}
 
 	/**
@@ -873,7 +873,7 @@ class Processor
 			return;
 		}
 
-		Item::delete(['uri' => $activity['object_id'], 'author-id' => $author_id, 'gravity' => GRAVITY_ACTIVITY]);
+		Item::markForDeletion(['uri' => $activity['object_id'], 'author-id' => $author_id, 'gravity' => GRAVITY_ACTIVITY]);
 	}
 
 	/**

src/Protocol/DFRN.php

@@ -2716,7 +2716,7 @@ class DFRN
 
 		Logger::log('deleting item '.$item['id'].' uri='.$uri, Logger::DEBUG);
 
-		Item::delete(['id' => $item['id']]);
+		Item::markForDeletion(['id' => $item['id']]);
 	}
 
 	/**

src/Protocol/Diaspora.php

@@ -2794,7 +2794,7 @@ class Diaspora
 				continue;
 			}
 
-			Item::delete(['id' => $item['id']]);
+			Item::markForDeletion(['id' => $item['id']]);
 
 			Logger::log("Deleted target ".$target_guid." (".$item["id"].") from user ".$item["uid"]." parent: ".$item["parent"], Logger::DEBUG);
 		}

src/Protocol/OStatus.php

@@ -585,7 +585,7 @@ class OStatus
 			return;
 		}
 
-		Item::delete($condition);
+		Item::markForDeletion($condition);
 
 		Logger::log('Deleted item with uri '.$item['uri'].' for user '.$item['uid']);
 	}

src/Worker/DBClean.php

@@ -98,7 +98,7 @@ class DBClean {
 			$last_id = DI::config()->get('system', 'dbclean-last-id-1', 0);
 
 			Logger::log("Deleting old global item entries from item table without user copy. Last ID: ".$last_id);
-			$r = DBA::p("SELECT `id` FROM `item` WHERE `uid` = 0 AND
+			$r = DBA::p("SELECT `id`, `guid` FROM `item` WHERE `uid` = 0 AND
 						NOT EXISTS (SELECT `guid` FROM `item` AS `i` WHERE `item`.`guid` = `i`.`guid` AND `i`.`uid` != 0) AND
 						`received` < UTC_TIMESTAMP() - INTERVAL ? DAY AND `id` >= ?
 					ORDER BY `id` LIMIT ?", $days_unclaimed, $last_id, $limit);
@@ -107,7 +107,7 @@ class DBClean {
 				Logger::log("found global item orphans: ".$count);
 				while ($orphan = DBA::fetch($r)) {
 					$last_id = $orphan["id"];
-					Logger::notice('Delete global orphan item', ['id' => $orphan["id"]]);
+					Logger::info('Delete global orphan item', ['id' => $orphan['id'], 'guid' => $orphan['guid']]);
 					DBA::delete('item', ['id' => $orphan["id"]]);
 				}
 				Worker::add(PRIORITY_MEDIUM, 'DBClean', 1, $last_id);
@@ -122,7 +122,7 @@ class DBClean {
 			$last_id = DI::config()->get('system', 'dbclean-last-id-2', 0);
 
 			Logger::log("Deleting items without parents. Last ID: ".$last_id);
-			$r = DBA::p("SELECT `id` FROM `item`
+			$r = DBA::p("SELECT `id`, `guid` FROM `item`
 					WHERE NOT EXISTS (SELECT `id` FROM `item` AS `i` WHERE `item`.`parent` = `i`.`id`)
 					AND `id` >= ? ORDER BY `id` LIMIT ?", $last_id, $limit);
 			$count = DBA::numRows($r);
@@ -130,7 +130,7 @@ class DBClean {
 				Logger::log("found item orphans without parents: ".$count);
 				while ($orphan = DBA::fetch($r)) {
 					$last_id = $orphan["id"];
-					Logger::notice('Delete orphan item', ['id' => $orphan["id"]]);
+					Logger::info('Delete orphan item', ['id' => $orphan['id'], 'guid' => $orphan['guid']]);
 					DBA::delete('item', ['id' => $orphan["id"]]);
 				}
 				Worker::add(PRIORITY_MEDIUM, 'DBClean', 2, $last_id);
@@ -319,7 +319,7 @@ class DBClean {
 			$till_id = DI::config()->get('system', 'dbclean-last-id-8', 0);
 
 			Logger::log("Deleting old global item entries from expired threads from ID ".$last_id." to ID ".$till_id);
-			$r = DBA::p("SELECT `id` FROM `item` WHERE `uid` = 0 AND
+			$r = DBA::p("SELECT `id`, `guid` FROM `item` WHERE `uid` = 0 AND
 						NOT EXISTS (SELECT `guid` FROM `item` AS `i` WHERE `item`.`guid` = `i`.`guid` AND `i`.`uid` != 0) AND
 						`received` < UTC_TIMESTAMP() - INTERVAL 90 DAY AND `id` >= ? AND `id` <= ?
 					ORDER BY `id` LIMIT ?", $last_id, $till_id, $limit);
@@ -328,7 +328,7 @@ class DBClean {
 				Logger::log("found global item entries from expired threads: ".$count);
 				while ($orphan = DBA::fetch($r)) {
 					$last_id = $orphan["id"];
-					Logger::notice('Delete expired thread item', ['id' => $orphan["id"]]);
+					Logger::info('Delete expired thread item', ['id' => $orphan['id'], 'guid' => $orphan['guid']]);
 					DBA::delete('item', ['id' => $orphan["id"]]);
 				}
 				Worker::add(PRIORITY_MEDIUM, 'DBClean', 9, $last_id);

src/Worker/Expire.php

@@ -43,9 +43,9 @@ class Expire
 			Logger::log('Delete expired items', Logger::DEBUG);
 			// physically remove anything that has been deleted for more than two months
 			$condition = ["`deleted` AND `changed` < UTC_TIMESTAMP() - INTERVAL 60 DAY"];
-			$rows = DBA::select('item', ['id'],  $condition);
+			$rows = DBA::select('item', ['id', 'guid'],  $condition);
 			while ($row = DBA::fetch($rows)) {
-				Logger::notice('Delete expired item', ['id' => $row["id"]]);
+				Logger::info('Delete expired item', ['id' => $row['id'], 'guid' => $row['guid']]);
 				DBA::delete('item', ['id' => $row['id']]);
 			}
 			DBA::close($rows);

src/Worker/RemoveContact.php

@@ -41,9 +41,9 @@ class RemoveContact {
 		// Now we delete the contact and all depending tables
 		$condition = ['uid' => $contact['uid'], 'contact-id' => $id];
 		do {
-			$items = Item::select(['id'], $condition, ['limit' => 100]);
+			$items = Item::select(['id', 'guid'], $condition, ['limit' => 100]);
 			while ($item = Item::fetch($items)) {
-				Logger::notice('Delete removed contact item', ['id' => $item["id"]]);
+				Logger::info('Delete removed contact item', ['id' => $item['id'], 'guid' => $item['guid']]);
 				DBA::delete('item', ['id' => $item['id']]);
 			}
 			DBA::close($items);

src/Worker/RemoveUser.php

@@ -41,7 +41,7 @@ class RemoveUser {
 		do {
 			$items = Item::select(['id'], $condition, ['limit' => 100]);
 			while ($item = Item::fetch($items)) {
-				Item::deleteById($item['id'], PRIORITY_NEGLIGIBLE);
+				Item::markForDeletionById($item['id'], PRIORITY_NEGLIGIBLE);
 			}
 			DBA::close($items);
 		} while (Item::exists($condition));