Mailstream: streamline log lines #1522

Merged
heluecht merged 1 commit from mexon/friendica-addons:mat/mailstream-log into develop 2024-07-14 18:10:10 +02:00

View file

@ -34,7 +34,7 @@ function mailstream_install()
Hook::register('post_remote_end', 'addon/mailstream/mailstream.php', 'mailstream_post_hook'); Hook::register('post_remote_end', 'addon/mailstream/mailstream.php', 'mailstream_post_hook');
Hook::register('mailstream_send_hook', 'addon/mailstream/mailstream.php', 'mailstream_send_hook'); Hook::register('mailstream_send_hook', 'addon/mailstream/mailstream.php', 'mailstream_send_hook');
Logger::info("mailstream: installed"); Logger::info("installed mailstream");
} }
/** /**
@ -44,7 +44,7 @@ function mailstream_check_version()
{ {
if (!is_null(DI::config()->get('mailstream', 'dbversion'))) { if (!is_null(DI::config()->get('mailstream', 'dbversion'))) {
DI::config()->delete('mailstream', 'dbversion'); DI::config()->delete('mailstream', 'dbversion');
Logger::info("mailstream_check_version: old version detected, reinstalling"); Logger::info("old version detected, reinstalling");
mailstream_install(); mailstream_install();
Hook::loadHooks(); Hook::loadHooks();
Hook::add( Hook::add(
@ -105,7 +105,7 @@ function mailstream_generate_id(string $uri): string
$host = DI::baseUrl()->getHost(); $host = DI::baseUrl()->getHost();
$resource = hash('md5', $uri); $resource = hash('md5', $uri);
$message_id = "<" . $resource . "@" . $host . ">"; $message_id = "<" . $resource . "@" . $host . ">";
Logger::debug('mailstream: Generated message ID ' . $message_id . ' for URI ' . $uri); Logger::debug('generated message ID', ['id' => $message_id, 'uri' => $uri]);
return $message_id; return $message_id;
} }
@ -114,20 +114,20 @@ function mailstream_send_hook(array $data)
$criteria = array('uid' => $data['uid'], 'contact-id' => $data['contact-id'], 'uri' => $data['uri']); $criteria = array('uid' => $data['uid'], 'contact-id' => $data['contact-id'], 'uri' => $data['uri']);
$item = Post::selectFirst([], $criteria); $item = Post::selectFirst([], $criteria);
if (empty($item)) { if (empty($item)) {
Logger::error('mailstream_send_hook could not find item'); Logger::error('could not find item');
return; return;
} }
$user = User::getById($item['uid']); $user = User::getById($item['uid']);
if (empty($user)) { if (empty($user)) {
Logger::error('mailstream_send_hook could not fund user', ['uid' => $item['uid']]); Logger::error('could not find user', ['uid' => $item['uid']]);
return; return;
} }
if (!mailstream_send($data['message_id'], $item, $user)) { if (!mailstream_send($data['message_id'], $item, $user)) {
Logger::debug('mailstream_send_hook send failed, will retry', $data); Logger::debug('send failed, will retry', $data);
if (!Worker::defer()) { if (!Worker::defer()) {
Logger::error('mailstream_send_hook failed and could not defer', $data); Logger::error('failed and could not defer', $data);
} }
} }
} }
@ -145,32 +145,32 @@ function mailstream_post_hook(array &$item)
mailstream_check_version(); mailstream_check_version();
if (!DI::pConfig()->get($item['uid'], 'mailstream', 'enabled')) { if (!DI::pConfig()->get($item['uid'], 'mailstream', 'enabled')) {
Logger::debug('mailstream: not enabled.', ['item' => $item['id'], ' uid ' => $item['uid']]); Logger::debug('mailstream not enabled.', ['item' => $item['id'], 'uid' => $item['uid']]);
return; return;
} }
if (!$item['uid']) { if (!$item['uid']) {
Logger::debug('mailstream: no uid for item ' . $item['id']); Logger::debug('no uid', ['item' => $item['id']]);
return; return;
} }
if (!$item['contact-id']) { if (!$item['contact-id']) {
Logger::debug('mailstream: no contact-id for item ' . $item['id']); Logger::debug('no contact-id', ['item' => $item['id']]);
return; return;
} }
if (!$item['uri']) { if (!$item['uri']) {
Logger::debug('mailstream: no uri for item ' . $item['id']); Logger::debug('no uri', ['item' => $item['id']]);
return; return;
} }
if ($item['verb'] == Activity::ANNOUNCE) { if ($item['verb'] == Activity::ANNOUNCE) {
Logger::debug('mailstream: announce item ', ['item' => $item['id']]); Logger::debug('ignoring announce', ['item' => $item['id']]);
return; return;
} }
if (DI::pConfig()->get($item['uid'], 'mailstream', 'nolikes')) { if (DI::pConfig()->get($item['uid'], 'mailstream', 'nolikes')) {
if ($item['verb'] == Activity::LIKE) { if ($item['verb'] == Activity::LIKE) {
Logger::debug('mailstream: like item ' . $item['id']); Logger::debug('ignoring like', ['item' => $item['id']]);
return; return;
} }
if ($item['verb'] == Activity::DISLIKE) { if ($item['verb'] == Activity::DISLIKE) {
Logger::debug('mailstream: dislike item ' . $item['id']); Logger::debug('ignoring dislike', ['item' => $item['id']]);
return; return;
} }
} }
@ -221,7 +221,7 @@ function mailstream_do_images(array &$item, array &$attachments)
try { try {
$curlResult = DI::httpClient()->fetchFull($url, HttpClientAccept::DEFAULT, 0, $cookiejar); $curlResult = DI::httpClient()->fetchFull($url, HttpClientAccept::DEFAULT, 0, $cookiejar);
} catch (InvalidArgumentException $e) { } catch (InvalidArgumentException $e) {
Logger::error('mailstream_do_images exception fetching url', ['url' => $url, 'item_id' => $item['id']]); Logger::error('exception fetching url', ['url' => $url, 'item_id' => $item['id']]);
continue; continue;
} }
$attachments[$url] = [ $attachments[$url] = [
@ -322,13 +322,12 @@ function mailstream_subject(array $item): string
} }
$contact = Contact::selectFirst([], ['id' => $item['contact-id'], 'uid' => $item['uid']]); $contact = Contact::selectFirst([], ['id' => $item['contact-id'], 'uid' => $item['uid']]);
if (!DBA::isResult($contact)) { if (!DBA::isResult($contact)) {
Logger::error( Logger::error('no contact', [
'mailstream_subject no contact for item', 'item' => $item['id'],
['id' => $item['id'],
'plink' => $item['plink'], 'plink' => $item['plink'],
'contact id' => $item['contact-id'], 'contact id' => $item['contact-id'],
'uid' => $item['uid']] 'uid' => $item['uid']
); ]);
return DI::l10n()->t("Friendica post"); return DI::l10n()->t("Friendica post");
} }
if ($contact['network'] === 'dfrn') { if ($contact['network'] === 'dfrn') {
@ -365,17 +364,16 @@ function mailstream_subject(array $item): string
function mailstream_send(string $message_id, array $item, array $user): bool function mailstream_send(string $message_id, array $item, array $user): bool
{ {
if (!is_array($item)) { if (!is_array($item)) {
Logger::error('mailstream_send item is empty', ['message_id' => $message_id]); Logger::error('item is empty', ['message_id' => $message_id]);
return false; return false;
} }
if (!$item['visible']) { if (!$item['visible']) {
Logger::debug('mailstream_send item not yet visible', ['item uri' => $item['uri']]); Logger::debug('item not yet visible', ['item uri' => $item['uri']]);
return false; return false;
} }
if (!$message_id) { if (!$message_id) {
Logger::error('mailstream_send no message ID supplied', ['item uri' => $item['uri'], Logger::error('no message ID supplied', ['item uri' => $item['uri'], 'user email' => $user['email']]);
'user email' => $user['email']]);
return true; return true;
} }
@ -432,13 +430,15 @@ function mailstream_send(string $message_id, array $item, array $user): bool
if (!$mail->Send()) { if (!$mail->Send()) {
throw new Exception($mail->ErrorInfo); throw new Exception($mail->ErrorInfo);
} }
Logger::debug('mailstream_send sent message', ['message ID' => $mail->MessageID, Logger::debug('sent message', [
'message ID' => $mail->MessageID,
'subject' => $mail->Subject, 'subject' => $mail->Subject,
'address' => $address]); 'address' => $address
]);
} catch (phpmailerException $e) { } catch (phpmailerException $e) {
Logger::debug('mailstream_send PHPMailer exception sending message ' . $message_id . ': ' . $e->errorMessage()); Logger::debug('PHPMailer exception sending message', ['id' => $message_id, 'error' => $e->errorMessage()]);
} catch (Exception $e) { } catch (Exception $e) {
Logger::debug('mailstream_send exception sending message ' . $message_id . ': ' . $e->getMessage()); Logger::debug('exception sending message', ['id' => $message_id, 'error' => $e->getMessage()]);
} }
return true; return true;
@ -468,7 +468,7 @@ function mailstream_html_wrap(string &$text)
function mailstream_convert_table_entries() function mailstream_convert_table_entries()
{ {
$ms_item_ids = DBA::selectToArray('mailstream_item', [], ['message-id', 'uri', 'uid', 'contact-id'], ["`mailstream_item`.`completed` IS NULL"]); $ms_item_ids = DBA::selectToArray('mailstream_item', [], ['message-id', 'uri', 'uid', 'contact-id'], ["`mailstream_item`.`completed` IS NULL"]);
Logger::debug('mailstream_convert_table_entries processing ' . count($ms_item_ids) . ' items'); Logger::debug('processing items', ['count' => count($ms_item_ids)]);
foreach ($ms_item_ids as $ms_item_id) { foreach ($ms_item_ids as $ms_item_id) {
$send_hook_data = array('uid' => $ms_item_id['uid'], $send_hook_data = array('uid' => $ms_item_id['uid'],
'contact-id' => $ms_item_id['contact-id'], 'contact-id' => $ms_item_id['contact-id'],
@ -476,10 +476,10 @@ function mailstream_convert_table_entries()
'message_id' => $ms_item_id['message-id'], 'message_id' => $ms_item_id['message-id'],
'tries' => 0); 'tries' => 0);
if (!$ms_item_id['message-id'] || !strlen($ms_item_id['message-id'])) { if (!$ms_item_id['message-id'] || !strlen($ms_item_id['message-id'])) {
Logger::info('mailstream_convert_table_entries: item has no message-id.', ['item' => $ms_item_id['id'], 'uri' => $ms_item_id['uri']]); Logger::info('item has no message-id', ['item' => $ms_item_id['id'], 'uri' => $ms_item_id['uri']]);
continue; continue;
} }
Logger::info('mailstream_convert_table_entries: convert item to workerqueue', $send_hook_data); Logger::info('convert item to workerqueue', $send_hook_data);
Hook::fork(Worker::PRIORITY_LOW, 'mailstream_send_hook', $send_hook_data); Hook::fork(Worker::PRIORITY_LOW, 'mailstream_send_hook', $send_hook_data);
} }
DBA::e('DROP TABLE `mailstream_item`'); DBA::e('DROP TABLE `mailstream_item`');