Bug#25495393: GROUP REPLICATION CAN USE SOME VERBOSITY IN THE ERROR LOG

Description:
At present not all scenarios of Group membership changes are logged.
When member join or member leaves, customers cannot identify same by looking
at logs. View changes are not logged. Present logging does not assist DBAs with
corrective measures during network partitions or inform DBAs when member
re-connects.
Also at some places we are logging internal debug messages which cannot be decoded
by DBAs.
Important member related configuration is also not logged.

Resolution:
Logging has been analyzed for:
1. View changes
2. Member join
3. Member leave(graceful and crash)
4. Member unreachable
5. Member re-connect
6. Removal of debug messages
7. Member configuration has been extended with Member_id, member_uuid,
   single_primary_mode, and group_replication_auto_increment_increment
8. Improvements in single-primary mode status reporting and member
   leaving/joining logging
New messages have been added and change to existing messages where required has
been done.

Author: Jaideep Karande

mysql-test/include/mtr_warnings.sql

@@ -280,8 +280,11 @@ INSERT INTO global_suppressions VALUES
  ("\\[GCS\\] Error pushing message into group communication engine."),
  ("\\[GCS\\] Message cannot be sent because the member does not belong to a group."),
  ("Slave SQL for channel 'group_replication_recovery': ... The slave coordinator and worker threads are stopped, possibly leaving data in inconsistent state.*"),
- ("The member lost contact with a majority of the members in the group. Until the network is restored.*"),
- ("The member resumed contact with a majority of the members in the group.*"),
+ ("Member with address .* has become unreachable."),
+ ("This server is not able to reach a majority of members in the group.*"),
+ ("Member with address .* is reachable again."),
+ ("The member has resumed contact with a majority of the members in the group.*"),
+ ("Members removed from the group.*"),
 
  ("THE_LAST_SUPPRESSION")||
 

rapid/plugin/group_replication/include/gcs_event_handlers.h

@@ -267,6 +267,32 @@ class Plugin_gcs_events_handler: public Gcs_communication_event_listener,
   */
   bool was_member_expelled_from_group(const Gcs_view& view) const;
 
+  /**
+    Logs member joining message to error logs from view.
+
+    @param[in]  view        the view delivered by the GCS
+  */
+  void log_members_joining_message(const Gcs_view& new_view) const;
+
+  /**
+    Logs member leaving message to error logs from view.
+
+    @param[in]  view        the view delivered by the GCS
+  */
+  void log_members_leaving_message(const Gcs_view& new_view) const;
+
+  /**
+    This function return all members present in vector of Gcs_member_identifier
+    in HOST:PORT format separated by comma.
+    Function also return PRIMARY member if any in HOST:PORT format.
+
+    @param[in]    joining/leaving members for this view
+    @param[out]   host and port of all members from view
+    @param[out]   primary member hosts and port of all members from view
+  */
+  void get_hosts_from_view(const std::vector<Gcs_member_identifier> &members,
+                           std::string& all_hosts, std::string& primary_host) const;
+
   Applier_module_interface* applier_module;
   Recovery_module* recovery_module;
 

rapid/plugin/group_replication/include/member_info.h

@@ -526,6 +526,14 @@ class Group_member_info_manager_interface
   @return true if majority of the group is unreachable
   */
   virtual bool is_majority_unreachable()= 0;
+
+  /**
+    This method returns all ONLINE and RECOVERING members comma separated
+    host and port in string format.
+
+    @return hosts and port of all ONLINE and RECOVERING members
+  */
+  virtual std::string get_string_current_view_active_hosts() const = 0;
 };
 
 
@@ -578,6 +586,8 @@ class Group_member_info_manager: public Group_member_info_manager_interface
 
   bool is_majority_unreachable();
 
+  std::string get_string_current_view_active_hosts() const;
+
 private:
   void clear_members();
 

rapid/plugin/group_replication/include/plugin_utils.h

@@ -24,6 +24,8 @@
 #include "plugin_psi.h"
 #include <mysql/group_replication_priv.h>
 
+void log_primary_member_details();
+
 class Blocked_transaction_handler
 {
 public:

rapid/plugin/group_replication/src/certifier.cc

@@ -1689,11 +1689,6 @@ void Certifier::enable_conflict_detection()
   conflict_detection_enable= true;
   local_member_info->enable_conflict_detection();
   mysql_mutex_unlock(&LOCK_certification_info);
-
-  log_message(MY_INFORMATION_LEVEL,
-              "A new primary was elected, enabled conflict detection "
-              "until the new primary applies all relay logs");
-
   DBUG_VOID_RETURN;
 }
 

rapid/plugin/group_replication/src/gcs_event_handlers.cc

@@ -290,13 +290,23 @@ Plugin_gcs_events_handler::on_suspicions(const std::vector<Gcs_member_identifier
       uit= std::find(tmp_unreachable.begin(), tmp_unreachable.end(), member);
       if (uit != tmp_unreachable.end())
       {
+        if (!member_info->is_unreachable())
+          log_message(MY_WARNING_LEVEL,
+                      "Member with address %s:%u has become unreachable.",
+                      member_info->get_hostname().c_str(), member_info->get_port());
+
         member_info->set_unreachable();
 
         // remove to not check again against this one
         tmp_unreachable.erase(uit);
       }
       else
       {
+        if (member_info->is_unreachable())
+          log_message(MY_WARNING_LEVEL,
+                      "Member with address %s:%u is reachable again.",
+                      member_info->get_hostname().c_str(), member_info->get_port());
+
         member_info->set_reachable();
       }
     }
@@ -305,19 +315,23 @@ Plugin_gcs_events_handler::on_suspicions(const std::vector<Gcs_member_identifier
   if ((members.size() - unreachable.size()) <= (members.size() / 2))
   {
     if (!group_partition_handler->get_timeout_on_unreachable())
-      log_message(MY_WARNING_LEVEL,
-                  "The member lost contact with a majority of the members in the"
-                  " group. Until the network is restored transactions will block."
-                  " As the value of group_replication_unreachable_majority_timeout"
-                  " is 0 the plugin will wait indefinitely for the network to be"
-                  " restored.");
+      log_message(MY_ERROR_LEVEL,
+                  "This server is not able to reach a majority of members "
+                  "in the group. This server will now block all updates. "
+                  "The server will remain blocked until contact with the "
+                  "majority is restored. "
+                  "It is possible to use group_replication_force_members "
+                  "to force a new group membership.");
     else
-      log_message(MY_WARNING_LEVEL,
-                  "The member lost contact with a majority of the members in the"
-                  " group. Until the network is restored transactions will block."
-                  " The plugin will wait for a network restore or timeout after"
-                  " the period defined on"
-                  " group_replication_unreachable_majority_timeout.");
+      log_message(MY_ERROR_LEVEL,
+                  "This server is not able to reach a majority of members "
+                  "in the group. This server will now block all updates. "
+                  "The server will remain blocked for the next %lu seconds. "
+                  "Unless contact with the majority is restored, after this "
+                  "time the member will error out and leave the group. "
+                  "It is possible to use group_replication_force_members "
+                  "to force a new group membership.",
+                  group_partition_handler->get_timeout_on_unreachable());
 
     if (!group_partition_handler->is_partition_handler_running() &&
         !group_partition_handler->is_partition_handling_terminated())
@@ -342,13 +356,86 @@ Plugin_gcs_events_handler::on_suspicions(const std::vector<Gcs_member_identifier
       {
         /* If it was not running or we canceled it in time */
         log_message(MY_WARNING_LEVEL,
-                    "The member resumed contact with a majority of the members"
-                    " in the group. Regular operation is re-established.");
+                    "The member has resumed contact with a majority of the "
+                    "members in the group. Regular operation is restored and "
+                    "transactions are unblocked.");
       }
     }
   }
 }
 
+void
+Plugin_gcs_events_handler::log_members_leaving_message(const Gcs_view& new_view) const
+{
+  std::string members_leaving;
+  std::string primary_member_host;
+
+  get_hosts_from_view(new_view.get_leaving_members(), members_leaving, primary_member_host);
+
+  log_message(MY_WARNING_LEVEL,
+              "Members removed from the group: %s",
+              members_leaving.c_str());
+
+  if (!primary_member_host.empty())
+    log_message(MY_INFORMATION_LEVEL,
+                "Primary server with address %s left the group. "
+                "Electing new Primary.",
+                primary_member_host.c_str());
+}
+
+void
+Plugin_gcs_events_handler::log_members_joining_message(const Gcs_view& new_view) const
+{
+  std::string members_joining;
+  std::string primary_member_host;
+
+  get_hosts_from_view(new_view.get_joined_members(), members_joining, primary_member_host);
+
+  log_message(MY_INFORMATION_LEVEL,
+              "Members joined the group: %s",
+              members_joining.c_str());
+}
+
+void
+Plugin_gcs_events_handler::get_hosts_from_view(const std::vector<Gcs_member_identifier> &members,
+                         std::string& all_hosts, std::string& primary_host) const
+{
+  std::stringstream hosts_string;
+  std::stringstream primary_string;
+  std::vector<Gcs_member_identifier>::const_iterator all_members_it= members.begin();
+
+  while (all_members_it != members.end())
+  {
+    Group_member_info* member_info= group_member_mgr->
+                                     get_group_member_info_by_member_id((*all_members_it));
+    all_members_it++;
+
+    if (member_info == NULL)
+      continue;
+
+    hosts_string << member_info->get_hostname() << ":" << member_info->get_port();
+
+    /**
+     Check in_primary_mode has been added for safety.
+     Since primary role is in single-primary mode.
+    */
+    if (member_info->in_primary_mode() &&
+        member_info->get_role() == Group_member_info::MEMBER_ROLE_PRIMARY)
+    {
+      if (primary_string.tellp() != 0)
+        primary_string << ", ";
+      primary_string << member_info->get_hostname() << ":" << member_info->get_port();
+    }
+
+    if (all_members_it != members.end())
+    {
+      hosts_string << ", ";
+    }
+  }
+  all_hosts.assign (hosts_string.str());
+  primary_host.assign (primary_string.str());
+}
+
 void
 Plugin_gcs_events_handler::on_view_changed(const Gcs_view& new_view,
                                            const Exchanged_data &exchanged_data)
@@ -393,8 +480,9 @@ Plugin_gcs_events_handler::on_view_changed(const Gcs_view& new_view,
     {
       /* If it was not running or we canceled it in time */
       log_message(MY_WARNING_LEVEL,
-                  "The member resumed contact with a majority of the members"
-                  " in the group. Regular operation is re-established.");
+                  "The member has resumed contact with a majority of the "
+                  "members in the group. Regular operation is restored and "
+                  "transactions are unblocked.");
     }
   }
 
@@ -405,9 +493,15 @@ Plugin_gcs_events_handler::on_view_changed(const Gcs_view& new_view,
   if (!is_leaving && group_partition_handler->is_partition_handling_terminated())
     return;
 
+  if (!is_leaving && new_view.get_leaving_members().size() > 0)
+    log_members_leaving_message(new_view);
+
   //update the Group Manager with all the received states
   this->update_group_info_manager(new_view, exchanged_data, is_leaving);
 
+  if (!is_joining && new_view.get_joined_members().size() > 0)
+    log_members_joining_message(new_view);
+
   //enable conflict detection if someone on group have it enabled
   if (local_member_info->in_primary_mode() &&
       group_member_mgr->is_conflict_detection_enabled())
@@ -439,6 +533,19 @@ Plugin_gcs_events_handler::on_view_changed(const Gcs_view& new_view,
   //Signal that the injected view was delivered
   if (view_change_notifier->is_injected_view_modification())
     view_change_notifier->end_view_modification();
+
+  if (!is_leaving)
+  {
+    log_message(MY_INFORMATION_LEVEL,
+                "Group membership changed to %s on view %s.",
+                group_member_mgr->get_string_current_view_active_hosts().c_str(),
+                gcs_module->get_current_view()->get_view_id().get_representation().c_str());
+  }
+  else
+  {
+    log_message(MY_INFORMATION_LEVEL,
+                "Group membership changed: This member has left the group.");
+  }
 }
 
 bool
@@ -670,12 +777,17 @@ void Plugin_gcs_events_handler::handle_leader_election_if_needed() const
         group_member_mgr->update_member_role(primary_uuid,
                                              Group_member_info::MEMBER_ROLE_PRIMARY);
 
+        log_message(MY_INFORMATION_LEVEL, "A new primary with address %s:%u "
+                    "was elected, enabling conflict detection until the new "
+                    "primary applies all relay logs.",
+                    the_primary->get_hostname().c_str(),
+                    the_primary->get_port());
+
         // Check if the session was established, it can (re)set read only mode.
         if (!skip_set_super_readonly)
         {
           if (is_primary_local)
           {
-            log_message(MY_INFORMATION_LEVEL, "Unsetting super_read_only.");
             if (disable_super_read_only_mode(sql_command_interface))
             {
               log_message(MY_WARNING_LEVEL,
@@ -685,7 +797,6 @@ void Plugin_gcs_events_handler::handle_leader_election_if_needed() const
           }
           else
           {
-            log_message(MY_INFORMATION_LEVEL, "Setting super_read_only.");
             if (enable_super_read_only_mode(sql_command_interface))
             {
               log_message(MY_WARNING_LEVEL,
@@ -694,6 +805,16 @@ void Plugin_gcs_events_handler::handle_leader_election_if_needed() const
             }
           }
         }
+        /* code position limits messaging to primary change */
+        if (is_primary_local)
+          log_message(MY_INFORMATION_LEVEL,
+                      "This server is working as primary member.");
+        else
+          log_message(MY_INFORMATION_LEVEL,
+                      "This server is working as secondary member with primary "
+                      "member address %s:%u.",
+                      the_primary->get_hostname().c_str(),
+                      the_primary->get_port());
       }
     }
     else if (!skip_set_super_readonly)
@@ -812,11 +933,6 @@ void Plugin_gcs_events_handler::handle_joining_members(const Gcs_view& new_view,
                          Group_member_info::MEMBER_IN_RECOVERY,
                          Group_member_info::MEMBER_OFFLINE,
                          Group_member_info::MEMBER_END);
-
-    log_message(MY_INFORMATION_LEVEL,
-                "Starting group replication recovery with view_id %s",
-                new_view.get_view_id().get_representation().c_str());
-
     /**
       Set the read mode if not set during start (auto-start)
     */
@@ -909,10 +1025,6 @@ void Plugin_gcs_events_handler::handle_joining_members(const Gcs_view& new_view,
                          Group_member_info::MEMBER_IN_RECOVERY,
                          Group_member_info::MEMBER_OFFLINE,
                          Group_member_info::MEMBER_END);
-
-    log_message(MY_INFORMATION_LEVEL,
-                "Marking group replication view change with view_id %s",
-                new_view.get_view_id().get_representation().c_str());
     /**
      If not a joining member, all members should record on their own binlogs a
      marking event that identifies the frontier between the data the joining

rapid/plugin/group_replication/src/member_info.cc

@@ -849,6 +849,26 @@ bool Group_member_info_manager::is_majority_unreachable()
   return ret;
 }
 
+std::string
+Group_member_info_manager::get_string_current_view_active_hosts() const
+{
+  std::stringstream hosts_string;
+  map<string, Group_member_info*>::iterator all_members_it= members->begin();
+
+  while (all_members_it != members->end())
+  {
+    Group_member_info* member_info= (*all_members_it).second;
+    if (member_info->get_recovery_status() == Group_member_info::MEMBER_ONLINE ||
+        member_info->get_recovery_status() == Group_member_info::MEMBER_IN_RECOVERY)
+      hosts_string << member_info->get_hostname() << ":" << member_info->get_port();
+    all_members_it++;
+    if (all_members_it != members->end())
+      hosts_string<<", ";
+  }
+
+  return hosts_string.str();
+}
+
 Group_member_info_manager_message::Group_member_info_manager_message()
   : Plugin_gcs_message(CT_MEMBER_INFO_MANAGER_MESSAGE)
 {