Add option for verbose debugging and logging.

- Fixes #89

config/install/message_subscribe.settings.yml

@@ -1,5 +1,6 @@
 use_queue: false
 notify_own_actions: false
 flag_prefix: subscribe
+debug_mode: false
 default_notifiers:
   - email

config/schema/message_subscribe.schema.yml

@@ -11,6 +11,9 @@ message_subscribe.settings:
     flag_prefix:
       type: string
       label: 'The prefix that will be used to identify subscription flags'
+    debug_mode:
+      type: boolean
+      label: 'Enable debugging mode for verbose logging'
     default_notifiers:
       type: sequence
       label: 'Message notifiers that will be added to every subscription'

message_subscribe.install

@@ -16,3 +16,12 @@ function message_subscribe_uninstall() {
   \Drupal::configFactory()->getEditable('message_subscribe.settings')->clear('use_queue')->save();
   \Drupal::configFactory()->getEditable('message_subscribe.settings')->clear('notify_own_actions')->save();
 }
+
+/**
+ * Set the debugging mode configuration option.
+ */
+function message_subscribe_update_8100() {
+  $config = \Drupal::configFactory()->getEditable('message_subscribe.settings');
+  $config->set('debug_mode', FALSE);
+  $config->save();
+}

message_subscribe.module

@@ -22,6 +22,12 @@ function message_subscribe_message_subscribe_get_subscribers(MessageInterface $m
   // Determine if a range is needed for the query.
   $range = $subscribe_options['range'];
 
+  $debug = \Drupal::config('message_subscribe.settings')->get('debug_mode');
+  $debug && \Drupal::logger('message_subscribe')->debug(
+    'Gathering ALL subscriptions for @context',
+    ['@context' => "\n\n" . print_r($context, TRUE)]
+  );
+
   // Find the users that subscribed to each context.
   foreach ($context as $entity_type => $entity_ids) {
     if (!$entity_ids) {
@@ -33,6 +39,16 @@ function message_subscribe_message_subscribe_get_subscribers(MessageInterface $m
       continue;
     }
 
+    $debug && \Drupal::logger('message_subscribe')->debug(
+      'Using flags @flags for @entity_type @entity_ids for users greater than id @uid',
+      [
+        '@flags' => implode(', ', array_keys($flags)),
+        '@entity_type' => $entity_type,
+        '@entity_ids' => implode(', ', $entity_ids),
+        '@uid' => $subscribe_options['last uid'],
+      ]
+    );
+
     // Query all the entity IDs inside the given flags. We don't use
     // flag_get_content_flags() as we want to get all the flaggings of an
     // entity-type in a single query.
@@ -58,6 +74,10 @@ function message_subscribe_message_subscribe_get_subscribers(MessageInterface $m
 
     foreach ($result as $row) {
 
+      $debug && \Drupal::logger('message_subscribe')->debug(
+        'Subscriber row flag_id: @flag_id user: @uid',
+        ['@flag_id' => $row->flag_id, '@uid' => $row->uid]
+      );
       $uids[$row->uid] = !empty($uids[$row->uid]) ? $uids[$row->uid] : new DeliveryCandidate([], [], $row->uid);
       // Register the flag name.
       $uids[$row->uid]->addFlag($row->flag_id);
@@ -66,11 +86,16 @@ function message_subscribe_message_subscribe_get_subscribers(MessageInterface $m
         --$range;
         if ($range == 0) {
           // We've reach the requested item.
+          \Drupal::logger('message_subscribe')->debug('Exiting hook early as range was reached. Last uid to process @uid', ['@uid' => $row->uid]);
           return $uids;
         }
       }
     }
   }
+  $debug && \Drupal::logger('message_subscribe')->debug(
+    'Found @count recipients.',
+    ['@count' => count($uids)]
+  );
 
   return $uids;
 }

message_subscribe.services.yml

@@ -4,3 +4,7 @@ services:
     arguments: ['@flag', '@config.factory', '@entity_type.manager', '@message_notify.sender', '@module_handler', '@queue']
     calls:
       - [setMembershipManager, ['@?og.membership_manager']]
+      - [setLoggerChannel, ['@logger.channel.message_subscribe']]
+  logger.channel.message_subscribe:
+    parent: logger.channel_base
+    arguments: ['message_subscribe']

message_subscribe_email/message_subscribe_email.module

@@ -53,10 +53,20 @@ function message_subscribe_email_message_subscribe_get_subscribers_alter(array &
     return;
   }
 
+  $debug = \Drupal::config('message_subscribe.settings')->get('debug_mode');
+
   $flag_ids = [];
   foreach ($flags as $flag) {
     $flag_ids[] = $flag->id();
   }
+  $debug && \Drupal::logger('message_subscribe_email')->debug(
+    'Gathering email subscriptions for context: @context',
+    ['@context' => "\n\n" . print_r($values['context'], TRUE)]
+  );
+  $debug && \Drupal::logger('message_subscribe_email')->debug(
+    'Gathering email subscriptions using flags: @flags for users: @uids',
+    ['@flags' => implode(', ', $flag_ids), '@uids' => array_keys($uids)]
+  );
 
   $all_email_subscribers = [];
   foreach ($values['context'] as $entity_type => $entity_ids) {
@@ -78,13 +88,17 @@ function message_subscribe_email_message_subscribe_get_subscribers_alter(array &
     $all_email_subscribers += array_keys($result);
   }
 
+  $debug && \Drupal::logger('message_subscribe_email')->debug('Found email subscribers @subscribers', ['@subscribers' => implode(', ', $all_email_subscribers)]);
+
   /** @var \Drupal\message_subscribe\Subscribers\DeliveryCandidateInterface $delivery_candidate */
   foreach ($uids as $uid => $delivery_candidate) {
     if (!in_array($uid, $all_email_subscribers)) {
+      $debug && \Drupal::logger('message_subscribe_email')->debug('Removing EMAIL notifier for user @uid', ['@uid' => $uid]);
       $delivery_candidate->removeNotifier('email');
     }
     else {
       // Ensure the email notifier is set for email subscribers.
+      $debug && \Drupal::logger('message_subscribe_email')->debug('Adding EMAIL notifier for user @uid', ['@uid' => $uid]);
       $delivery_candidate->addNotifier('email');
     }
   }

src/Form/MessageSubscribeAdminSettings.php

@@ -24,7 +24,7 @@ public function submitForm(array &$form, FormStateInterface $form_state) {
     parent::submitForm($form, $form_state);
     $config = $this->config('message_subscribe.settings');
 
-    foreach (['use_queue', 'notify_own_actions', 'flag_prefix'] as $variable) {
+    foreach (['use_queue', 'notify_own_actions', 'flag_prefix', 'debug_mode'] as $variable) {
       $config->set($variable, $form_state->getValue($variable));
     }
     $config->set('default_notifiers', array_values($form_state->getValue('default_notifiers')));
@@ -84,6 +84,12 @@ public function buildForm(array $form, FormStateInterface $form_state) {
       '#default_value' => $config->get('use_queue'),
     ];
 
+    $form['debug_mode'] = [
+      '#type' => 'checkbox',
+      '#title' => $this->t('Enable debugging mode'),
+      '#description' => $this->t('Enables verbose logging of subscription activities for debugging purposes. <strong>This should not be enabled in a production environment.</strong>'),
+    ];
+
     return parent::buildForm($form, $form_state);
   }
 

src/Subscribers.php

@@ -8,6 +8,7 @@
 use Drupal\Core\Entity\EntityTypeManagerInterface;
 use Drupal\Core\Entity\RevisionLogInterface;
 use Drupal\Core\Extension\ModuleHandlerInterface;
+use Drupal\Core\Logger\LoggerChannelInterface;
 use Drupal\Core\Queue\QueueFactory;
 use Drupal\Core\Session\AccountInterface;
 use Drupal\flag\FlagServiceInterface;
@@ -73,6 +74,20 @@ class Subscribers implements SubscribersInterface {
    */
   protected $queue;
 
+  /**
+   * Logger channel.
+   *
+   * @var \Drupal\Core\Logger\LoggerChannelInterface
+   */
+  protected $logger;
+
+  /**
+   * Debugging enabled.
+   *
+   * @var bool
+   */
+  protected $debug = FALSE;
+
   /**
    * Construct the service.
    *
@@ -96,6 +111,7 @@ public function __construct(FlagServiceInterface $flag_service, ConfigFactoryInt
     $this->messageNotifier = $message_notifier;
     $this->moduleHandler = $module_handler;
     $this->queue = $queue->get('message_subscribe');
+    $this->debug = $this->config->get('debug_mode');
   }
 
   /**
@@ -108,6 +124,18 @@ public function setMembershipManager(MembershipManagerInterface $membership_mana
     $this->membershipManager = $membership_manager;
   }
 
+  /**
+   * Sets the logger channel.
+   *
+   * @param \Drupal\Core\Logger\LoggerChannelInterface $logger
+   *   The message_subscribe logger channel.
+   *
+   * @todo Inject this service in the 2.x version
+   */
+  public function setLoggerChannel(LoggerChannelInterface $logger) {
+    $this->logger = $logger;
+  }
+
   /**
    * {@inheritdoc}
    */
@@ -178,6 +206,7 @@ public function sendMessage(EntityInterface $entity, MessageInterface $message,
       // If we use a queue, it will be deleted.
       return;
     }
+    $this->debug('Preparing to process subscriptions for users: @uids', ['@uids' => implode(', ', array_keys($uids))]);
 
     foreach ($uids as $uid => $delivery_candidate) {
       $last_uid = $uid;
@@ -196,6 +225,13 @@ public function sendMessage(EntityInterface $entity, MessageInterface $message,
       $this->moduleHandler->alter('message_subscribe_message', $cloned_message, $delivery_candidate);
 
       // Send the message using the required notifiers.
+      $this->debug(
+        'Preparing delivery for uid @user with notifiers @notifiers',
+        [
+          '@user' => $uid,
+          '@notifiers' => implode(', ', $delivery_candidate->getNotifiers()),
+        ]
+      );
       foreach ($delivery_candidate->getNotifiers() as $notifier_name) {
         $options = !empty($notify_options[$notifier_name]) ? $notify_options[$notifier_name] : [];
         $options += [
@@ -204,7 +240,8 @@ public function sendMessage(EntityInterface $entity, MessageInterface $message,
           'context' => $context,
         ];
 
-        $this->messageNotifier->send($cloned_message, $options, $notifier_name);
+        $result = $this->messageNotifier->send($cloned_message, $options, $notifier_name);
+        $this->debug($result ? 'Successfully sent message via notifier @notifier to user @uid' : 'Failed to send message via notifier @notifier to user @uid', ['@notifier' => $notifier_name, '@uid' => $uid]);
 
         // Check we didn't timeout.
         if ($use_queue && $subscribe_options['queue']['end time'] && time() < $subscribe_options['queue']['end time']) {
@@ -224,6 +261,7 @@ public function sendMessage(EntityInterface $entity, MessageInterface $message,
       ];
 
       $task['subscribe_options']['last uid'] = $last_uid;
+      $this->debug('Queuing new batch with last uid of @uid', ['@uid' => $last_uid]);
 
       // Create a new queue item, with the last user ID.
       $this->queue->createItem($task);
@@ -244,6 +282,13 @@ public function getSubscribers(EntityInterface $entity, MessageInterface $messag
     foreach ($this->moduleHandler->getImplementations('message_subscribe_get_subscribers') as $module) {
       $function = $module . '_message_subscribe_get_subscribers';
       $result = $function($message, $options, $context);
+      $this->debug(
+        'Found @uids from @function',
+        [
+          '@uids' => implode(', ', array_keys($result)),
+          '@function' => $function,
+        ]
+      );
       $uids += $result;
     }
 
@@ -268,18 +313,22 @@ public function getSubscribers(EntityInterface $entity, MessageInterface $messag
     foreach ($uids as $uid => $values) {
       // See if the author of the entity gets notified.
       if (!$notify_message_owner && $this->isEntityOwner($entity, $uid)) {
+        $this->debug('Removing @uid from recipient list since they are the entity owner.', ['@uid' => $uid]);
         unset($uids[$uid]);
       }
 
       if (!empty($options['entity access'])) {
         $account = $this->entityTypeManager->getStorage('user')->load($uid);
         if (!$entity->access('view', $account)) {
           // User doesn't have access to view the entity.
+          $this->debug('Removing @uid from recipient list since they do not have view access.', ['@uid' => $uid]);
           unset($uids[$uid]);
         }
       }
     }
 
+    $this->debug('Recipients after access filter and entity owner filter: @uids', ['@uids' => implode(', ', array_keys($uids))]);
+
     $values = [
       'context' => $context,
       'entity_type' => $entity->getEntityTypeId(),
@@ -289,9 +338,11 @@ public function getSubscribers(EntityInterface $entity, MessageInterface $messag
     ];
 
     $this->addDefaultNotifiers($uids);
+    $this->debug('Recipient list after default notifiers: @uids', ['@uids' => implode(', ', array_keys($uids))]);
 
     $this->moduleHandler->alter('message_subscribe_get_subscribers', $uids, $values);
     ksort($uids);
+    $this->debug('Recipient list after ksort and alter hook: @uids', ['@uids' => implode(', ', array_keys($uids))]);
 
     return $uids;
 
@@ -436,4 +487,19 @@ protected function addDefaultNotifiers(array &$uids) {
     }
   }
 
+  /**
+   * Wrapper to the logger channel to only log if debugging is enabled.
+   *
+   * @param string $message
+   *   The message to log.
+   * @param array $context
+   *   The replacement patterns.
+   */
+  protected function debug($message, array $context = []) {
+    if (!$this->debug) {
+      return;
+    }
+    $this->logger->debug($message, $context);
+  }
+
 }

src/Tests/Form/MessageSubscribeAdminSettingsTest.php

@@ -44,6 +44,11 @@ public function setUp() {
         '#config_name' => 'message_subscribe.settings',
         '#config_key' => 'flag_prefix',
       ],
+      'debug_mode' => [
+        '#value' => TRUE,
+        '#config_name' => 'message_subscribe.settings',
+        '#config_key' => 'debug_mode',
+      ],
       'default_notifiers' => [
         '#value' => ['email', 'test'],
         '#config_name' => 'message_subscribe.settings',

tests/src/Unit/SubscribersTest.php

@@ -9,6 +9,7 @@
 use Drupal\Core\Entity\EntityTypeManagerInterface;
 use Drupal\Core\Entity\Query\QueryInterface;
 use Drupal\Core\Extension\ModuleHandlerInterface;
+use Drupal\Core\Logger\LoggerChannelInterface;
 use Drupal\Core\Queue\QueueFactory;
 use Drupal\flag\FlagInterface;
 use Drupal\flag\FlagServiceInterface;
@@ -118,6 +119,7 @@ public function testGetFlags() {
     // Override config mock to allow access to the prefix variable.
     $config = $this->prophesize(ImmutableConfig::class);
     $config->get('flag_prefix')->willReturn('blah');
+    $config->get('debug_mode')->willReturn(FALSE);
     $config_factory = $this->prophesize(ConfigFactoryInterface::class);
     $config_factory->get('message_subscribe.settings')->willReturn($config);
     $this->configFactory = $config_factory->reveal();
@@ -158,10 +160,18 @@ public function testGetFlags() {
   public function testSendMessage() {
     // Mock config.
     $config = $this->prophesize(ImmutableConfig::class);
+    $config->get('use_queue')->willReturn(FALSE);
+    $config->get('notify_own_actions')->willReturn(FALSE);
+    $config->get('default_notifiers')->willReturn(FALSE);
+    $config->get('debug_mode')->willReturn(TRUE);
     $config_factory = $this->prophesize(ConfigFactoryInterface::class);
     $config_factory->get('message_subscribe.settings')->willReturn($config);
     $this->configFactory = $config_factory->reveal();
 
+    // Mock logger.
+    $logger = $this->prophesize(LoggerChannelInterface::class);
+    $logger->debug(Argument::any(), Argument::any())->shouldBeCalled();
+
     // Mock module handler.
     $module_handler = $this->prophesize(ModuleHandlerInterface::class);
     $module_handler->getImplementations(Argument::any())->willReturn(['foo']);
@@ -189,6 +199,7 @@ public function testSendMessage() {
     $this->entityTypeManager = $entity_type_manager->reveal();
 
     $subscribers = $this->getSubscriberService();
+    $subscribers->setLoggerChannel($logger->reveal());
 
     $entity = $this->prophesize(EntityInterface::class);
     $entity->access('view', $account)->willReturn(TRUE);