Add more logging for sending debugging [MAILPOET-2084]

lib/Cron/Workers/SendingQueue/SendingQueue.php

@@ -49,6 +49,10 @@ class SendingQueue {
       if (!$queue instanceof SendingTask) continue;
       ScheduledTaskModel::touchAllByIds(array($queue->task_id));
 
+      Logger::getLogger('newsletters')->addInfo(
+        'sending queue processing',
+        ['task_id' => $queue->task_id]
+      );
       $newsletter = $this->newsletter_task->getNewsletterFromQueue($queue);
       if (!$newsletter) {
         continue;
@@ -72,6 +76,10 @@ class SendingQueue {
       // get subscribers
       $subscriber_batches = new BatchIterator($queue->task_id, $this->batch_size);
       foreach ($subscriber_batches as $subscribers_to_process_ids) {
+        Logger::getLogger('newsletters')->addInfo(
+          'subscriber batch processing',
+          ['newsletter_id' => $newsletter->id, 'task_id' => $queue->task_id, 'subscriber_batch_count' => count($subscribers_to_process_ids)]
+        );
         if (!empty($newsletter_segments_ids[0])) {
           // Check that subscribers are in segments
           $finder = new SubscribersFinder();
@@ -98,12 +106,24 @@ class SendingQueue {
             continue;
           }
         }
+        Logger::getLogger('newsletters')->addInfo(
+          'before queue chunk processing',
+          ['newsletter_id' => $newsletter->id, 'task_id' => $queue->task_id, 'found_subscribers_count' => count($found_subscribers)]
+        );
         $queue = $this->processQueue(
           $queue,
           $_newsletter,
           $found_subscribers
         );
+        Logger::getLogger('newsletters')->addInfo(
+          'after queue chunk processing',
+          ['newsletter_id' => $newsletter->id, 'task_id' => $queue->task_id]
+        );
         if ($queue->status === ScheduledTaskModel::STATUS_COMPLETED) {
+          Logger::getLogger('newsletters')->addInfo(
+            'completed newsletter sending',
+            ['newsletter_id' => $newsletter->id, 'task_id' => $queue->task_id]
+          );
           $this->newsletter_task->markNewsletterAsSent($newsletter, $queue);
           $this->stats_notifications_scheduler->schedule($newsletter);
         }

lib/Cron/Workers/SendingQueue/Tasks/Newsletter.php

@@ -5,6 +5,7 @@ namespace MailPoet\Cron\Workers\SendingQueue\Tasks;
 use MailPoet\Cron\Workers\SendingQueue\Tasks\Links as LinksTask;
 use MailPoet\Cron\Workers\SendingQueue\Tasks\Posts as PostsTask;
 use MailPoet\Cron\Workers\SendingQueue\Tasks\Shortcodes as ShortcodesTask;
+use MailPoet\Logging\Logger;
 use MailPoet\Mailer\MailerLog;
 use MailPoet\Models\Newsletter as NewsletterModel;
 use MailPoet\Models\NewsletterSegment as NewsletterSegmentModel;
@@ -75,6 +76,10 @@ class Newsletter {
         $this->stopNewsletterPreProcessing(sprintf('QUEUE-%d-RENDER', $queue->id)) :
         $newsletter;
     }
+    Logger::getLogger('newsletters')->addInfo(
+      'pre-processing newsletter',
+      ['newsletter_id' => $newsletter->id, 'task_id' => $queue->task_id]
+    );
     // if tracking is enabled, do additional processing
     if ($this->tracking_enabled) {
       // hook to the newsletter post-processing filter and add tracking image
@@ -102,6 +107,10 @@ class Newsletter {
       $this->posts_task->getAlcPostsCount($rendered_newsletter, $newsletter) === 0
     ) {
       // delete notification history record since it will never be sent
+      Logger::getLogger('post-notifications')->addInfo(
+        'no posts in post notification, deleting it',
+        ['newsletter_id' => $newsletter->id, 'task_id' => $queue->task_id]
+      );
       $newsletter->delete();
       return false;
     }

lib/Cron/Workers/SendingQueue/Tasks/Posts.php

@@ -1,6 +1,7 @@
 <?php
 namespace MailPoet\Cron\Workers\SendingQueue\Tasks;
 
+use MailPoet\Logging\Logger;
 use MailPoet\Models\Newsletter as NewsletterModel;
 use MailPoet\Models\NewsletterPost;
 
@@ -11,6 +12,10 @@ class Posts {
     if ($newsletter->type !== NewsletterModel::TYPE_NOTIFICATION_HISTORY) {
       return false;
     }
+    Logger::getLogger('post-notifications')->addInfo(
+      'extract and save posts - before',
+      ['newsletter_id' => $newsletter->id]
+    );
     preg_match_all(
       '/data-post-id="(\d+)"/ism',
       $rendered_newsletter['html'],
@@ -26,6 +31,10 @@ class Posts {
       $newsletter_post->post_id = $post_id;
       $newsletter_post->save();
     }
+    Logger::getLogger('post-notifications')->addInfo(
+      'extract and save posts - after',
+      ['newsletter_id' => $newsletter->id, 'matched_posts_ids' => $matched_posts_ids]
+    );
     return true;
   }
 

lib/Services/Bridge/API.php

@@ -2,6 +2,7 @@
 
 namespace MailPoet\Services\Bridge;
 use MailPoet\WP\Functions as WPFunctions;
+use MailPoet\Logging\Logger;
 
 class API {
   const SENDING_STATUS_OK = 'ok';
@@ -76,12 +77,20 @@ class API {
     return array('code' => $code, 'data' => $body);
   }
 
+  function logCurlInformation($headers, $info) {
+    Logger::getLogger('mss')->addInfo(
+      'requests-curl.after_request',
+      ['headers' => $headers, 'curl_info' => $info]
+    );
+  }
 
   function sendMessages($message_body) {
+    add_action('requests-curl.after_request', [$this, 'logCurlInformation'], 10, 2);
     $result = $this->request(
       $this->url_messages,
       $message_body
     );
+    remove_action('requests-curl.after_request', [$this, 'logCurlInformation']);
     if (is_wp_error($result)) {
       return array(
         'status' => self::SENDING_STATUS_CONNECTION_ERROR,

tests/integration/Cron/Workers/SendingQueue/SendingQueueTest.php

@@ -208,7 +208,7 @@ class SendingQueueTest extends \MailPoetTest {
       array(
         'processQueue' => function() {
           // this function returns a queue object
-          return (object)array('status' => null);
+          return (object)array('status' => null, 'task_id' => 0);
         },
         'enforceSendingAndExecutionLimits' => Expected::exactly(2)
       ), $this);

tests/integration/Cron/Workers/SendingQueue/Tasks/NewsletterTest.php

@@ -378,6 +378,7 @@ class NewsletterTest extends \MailPoetTest {
       )
     );
     $queue_mock->id = $queue->id;
+    $queue_mock->task_id = $queue->task_id;
 
     // properly serialized object
     $queue->newsletter_rendered_body = 'a:2:{s:4:"html";s:4:"test";s:4:"text";s:4:"test";}';