Merge pull request #891 from mexon/mat/mailstream-logging

Modernise logging in mailstream plugin
This commit is contained in:
Hypolite Petovan 2019-09-28 04:19:21 -04:00 committed by GitHub
commit bf91d64453
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23

View File

@ -96,7 +96,7 @@ function mailstream_generate_id($a, $uri) {
$host = $a->getHostName(); $host = $a->getHostName();
$resource = hash('md5', $uri); $resource = hash('md5', $uri);
$message_id = "<" . $resource . "@" . $host . ">"; $message_id = "<" . $resource . "@" . $host . ">";
Logger::log('mailstream: Generated message ID ' . $message_id . ' for URI ' . $uri, Logger::DEBUG); Logger::debug('mailstream: Generated message ID ' . $message_id . ' for URI ' . $uri);
return $message_id; return $message_id;
} }
@ -125,16 +125,14 @@ function mailstream_post_hook(&$a, &$item) {
intval($item['contact-id']), DBA::escape($item['uri']), DBA::escape($message_id)); intval($item['contact-id']), DBA::escape($item['uri']), DBA::escape($message_id));
$r = q('SELECT * FROM `mailstream_item` WHERE `uid` = %d AND `contact-id` = %d AND `uri` = "%s"', intval($item['uid']), intval($item['contact-id']), DBA::escape($item['uri'])); $r = q('SELECT * FROM `mailstream_item` WHERE `uid` = %d AND `contact-id` = %d AND `uri` = "%s"', intval($item['uid']), intval($item['contact-id']), DBA::escape($item['uri']));
if (count($r) != 1) { if (count($r) != 1) {
Logger::log('mailstream_post_remote_hook: Unexpected number of items returned from mailstream_item', Logger::INFO); Logger::info('mailstream_post_remote_hook: Unexpected number of items returned from mailstream_item');
return; return;
} }
$ms_item = $r[0]; $ms_item = $r[0];
Logger::log('mailstream_post_remote_hook: created mailstream_item ' Logger::debug('mailstream_post_remote_hook: created mailstream_item ' . $ms_item['id'] . ' for item ' . $item['uri'] . ' ' . $item['uid'] . ' ' . $item['contact-id']);
. $ms_item['id'] . ' for item ' . $item['uri'] . ' '
. $item['uid'] . ' ' . $item['contact-id'], Logger::DATA);
$user = mailstream_get_user($item['uid']); $user = mailstream_get_user($item['uid']);
if (!$user) { if (!$user) {
Logger::log('mailstream_post_remote_hook: no user ' . $item['uid'], Logger::INFO); Logger::info('mailstream_post_remote_hook: no user ' . $item['uid']);
return; return;
} }
mailstream_send($a, $ms_item['message-id'], $item, $user); mailstream_send($a, $ms_item['message-id'], $item, $user);
@ -143,7 +141,7 @@ function mailstream_post_hook(&$a, &$item) {
function mailstream_get_user($uid) { function mailstream_get_user($uid) {
$r = q('SELECT * FROM `user` WHERE `uid` = %d', intval($uid)); $r = q('SELECT * FROM `user` WHERE `uid` = %d', intval($uid));
if (count($r) != 1) { if (count($r) != 1) {
Logger::log('mailstream_post_remote_hook: Unexpected number of users returned', Logger::INFO); Logger::info('mailstream_post_remote_hook: Unexpected number of users returned');
return; return;
} }
return $r[0]; return $r[0];
@ -301,11 +299,11 @@ function mailstream_send(\Friendica\App $a, $message_id, $item, $user) {
if (!$mail->Send()) { if (!$mail->Send()) {
throw new Exception($mail->ErrorInfo); throw new Exception($mail->ErrorInfo);
} }
Logger::log('mailstream_send sent message ' . $mail->MessageID . ' ' . $mail->Subject, Logger::DEBUG); Logger::debug('mailstream_send sent message ' . $mail->MessageID . ' ' . $mail->Subject);
} catch (phpmailerException $e) { } catch (phpmailerException $e) {
Logger::log('mailstream_send PHPMailer exception sending message ' . $message_id . ': ' . $e->errorMessage(), Logger::INFO); Logger::debug('mailstream_send PHPMailer exception sending message ' . $message_id . ': ' . $e->errorMessage());
} catch (Exception $e) { } catch (Exception $e) {
Logger::log('mailstream_send exception sending message ' . $message_id . ': ' . $e->getMessage(), Logger::INFO); Logger::debug('mailstream_send exception sending message ' . $message_id . ': ' . $e->getMessage());
} }
// In case of failure, still set the item to completed. Otherwise // In case of failure, still set the item to completed. Otherwise
// we'll just try to send it over and over again and it'll fail // we'll just try to send it over and over again and it'll fail
@ -334,10 +332,10 @@ function mailstream_cron($a, $b) {
// mailstream_post_remote_hook fails for some reason will this get // mailstream_post_remote_hook fails for some reason will this get
// used, and in that case it's worth holding off a bit anyway. // used, and in that case it's worth holding off a bit anyway.
$ms_item_ids = q("SELECT `mailstream_item`.`message-id`, `mailstream_item`.`uri`, `item`.`id` FROM `mailstream_item` JOIN `item` ON (`mailstream_item`.`uid` = `item`.`uid` AND `mailstream_item`.`uri` = `item`.`uri` AND `mailstream_item`.`contact-id` = `item`.`contact-id`) WHERE `mailstream_item`.`completed` IS NULL AND `mailstream_item`.`created` < DATE_SUB(NOW(), INTERVAL 1 HOUR) AND `item`.`visible` = 1 ORDER BY `mailstream_item`.`created` LIMIT 100"); $ms_item_ids = q("SELECT `mailstream_item`.`message-id`, `mailstream_item`.`uri`, `item`.`id` FROM `mailstream_item` JOIN `item` ON (`mailstream_item`.`uid` = `item`.`uid` AND `mailstream_item`.`uri` = `item`.`uri` AND `mailstream_item`.`contact-id` = `item`.`contact-id`) WHERE `mailstream_item`.`completed` IS NULL AND `mailstream_item`.`created` < DATE_SUB(NOW(), INTERVAL 1 HOUR) AND `item`.`visible` = 1 ORDER BY `mailstream_item`.`created` LIMIT 100");
Logger::log('mailstream_cron processing ' . count($ms_item_ids) . ' items', Logger::DEBUG); Logger::debug('mailstream_cron processing ' . count($ms_item_ids) . ' items');
foreach ($ms_item_ids as $ms_item_id) { foreach ($ms_item_ids as $ms_item_id) {
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::log('mailstream_cron: Item ' . $ms_item_id['id'] . ' URI ' . $ms_item_id['uri'] . ' has no message-id', Logger::INFO); Logger::info('mailstream_cron: Item ' . $ms_item_id['id'] . ' URI ' . $ms_item_id['uri'] . ' has no message-id');
} }
$item = Item::selectFirst([], ['id' => $ms_item_id['id']]); $item = Item::selectFirst([], ['id' => $ms_item_id['id']]);
$users = q("SELECT * FROM `user` WHERE `uid` = %d", intval($item['uid'])); $users = q("SELECT * FROM `user` WHERE `uid` = %d", intval($item['uid']));
@ -346,7 +344,7 @@ function mailstream_cron($a, $b) {
mailstream_send($a, $ms_item_id['message-id'], $item, $user); mailstream_send($a, $ms_item_id['message-id'], $item, $user);
} }
else { else {
Logger::log('mailstream_cron: Unable to find item ' . $ms_item_id['id'], Logger::INFO); Logger::info('mailstream_cron: Unable to find item ' . $ms_item_id['id']);
q("UPDATE `mailstream_item` SET `completed` = now() WHERE `message-id` = %d", intval($ms_item['message-id'])); q("UPDATE `mailstream_item` SET `completed` = now() WHERE `message-id` = %d", intval($ms_item['message-id']));
} }
} }
@ -415,5 +413,5 @@ function mailstream_tidy() {
foreach ($r as $rr) { foreach ($r as $rr) {
q('DELETE FROM mailstream_item WHERE id = %d', intval($rr['id'])); q('DELETE FROM mailstream_item WHERE id = %d', intval($rr['id']));
} }
Logger::log('mailstream_tidy: deleted ' . count($r) . ' old items', Logger::DEBUG); Logger::debug('mailstream_tidy: deleted ' . count($r) . ' old items');
} }