From b46be88db62bcfa7dcf70c3677a1a1270d177a22 Mon Sep 17 00:00:00 2001 From: "Justin Clark-Casey (justincc)" Date: Mon, 19 May 2014 22:45:17 +0100 Subject: [PATCH] Split verbose groups messaging logging into its own setting separate from that of the groups module. This is to allow us to get useful information on messaging without being overwhelmed by the rest of groups debug. Enabled with [Groups] DebugMessagingEnabled = true in config (default false) Or "debug groups messaging verbose true|false on the console" (similar to existing groups setting). Done for both xmlrpc and V2 groups. --- .../Addons/Groups/GroupsMessagingModule.cs | 34 +++++- .../XmlRpcGroups/GroupsMessagingModule.cs | 100 ++++++++++++++---- bin/OpenSimDefaults.ini | 3 + 3 files changed, 111 insertions(+), 26 deletions(-) diff --git a/OpenSim/Addons/Groups/GroupsMessagingModule.cs b/OpenSim/Addons/Groups/GroupsMessagingModule.cs index bbb5e059d3..bd8db32e71 100644 --- a/OpenSim/Addons/Groups/GroupsMessagingModule.cs +++ b/OpenSim/Addons/Groups/GroupsMessagingModule.cs @@ -56,8 +56,8 @@ namespace OpenSim.Groups private IGroupsServicesConnector m_groupData = null; // Config Options - private bool m_groupMessagingEnabled = false; - private bool m_debugEnabled = true; + private bool m_groupMessagingEnabled; + private bool m_debugEnabled; /// /// If enabled, module only tries to send group IMs to online users by querying cached presence information. @@ -120,7 +120,7 @@ namespace OpenSim.Groups return; } - m_debugEnabled = groupsConfig.GetBoolean("DebugEnabled", true); + m_debugEnabled = groupsConfig.GetBoolean("MessagingDebugEnabled", m_debugEnabled); m_log.InfoFormat( "[Groups.Messaging]: GroupsMessagingModule enabled with MessageOnlineOnly = {0}, DebugEnabled = {1}", @@ -140,6 +140,14 @@ namespace OpenSim.Groups scene.EventManager.OnMakeChildAgent += OnMakeChildAgent; scene.EventManager.OnIncomingInstantMessage += OnGridInstantMessage; scene.EventManager.OnClientLogin += OnClientLogin; + + scene.AddCommand( + "Debug", + this, + "debug groups messaging verbose", + "debug groups messaging verbose ", + "This setting turns on very verbose groups messaging debugging", + HandleDebugGroupsMessagingVerbose); } public void RegionLoaded(Scene scene) @@ -227,6 +235,26 @@ namespace OpenSim.Groups #endregion + private void HandleDebugGroupsMessagingVerbose(object modules, string[] args) + { + if (args.Length < 5) + { + MainConsole.Instance.Output("Usage: debug groups messaging verbose "); + return; + } + + bool verbose = false; + if (!bool.TryParse(args[4], out verbose)) + { + MainConsole.Instance.Output("Usage: debug groups messaging verbose "); + return; + } + + m_debugEnabled = verbose; + + MainConsole.Instance.OutputFormat("{0} verbose logging set to {1}", Name, m_debugEnabled); + } + /// /// Not really needed, but does confirm that the group exists. /// diff --git a/OpenSim/Region/OptionalModules/Avatar/XmlRpcGroups/GroupsMessagingModule.cs b/OpenSim/Region/OptionalModules/Avatar/XmlRpcGroups/GroupsMessagingModule.cs index 3724a2ceaa..09bbec2dba 100644 --- a/OpenSim/Region/OptionalModules/Avatar/XmlRpcGroups/GroupsMessagingModule.cs +++ b/OpenSim/Region/OptionalModules/Avatar/XmlRpcGroups/GroupsMessagingModule.cs @@ -55,8 +55,8 @@ namespace OpenSim.Region.OptionalModules.Avatar.XmlRpcGroups private IGroupsServicesConnector m_groupData = null; // Config Options - private bool m_groupMessagingEnabled = false; - private bool m_debugEnabled = true; + private bool m_groupMessagingEnabled; + private bool m_debugEnabled; /// /// If enabled, module only tries to send group IMs to online users by querying cached presence information. @@ -113,7 +113,7 @@ namespace OpenSim.Region.OptionalModules.Avatar.XmlRpcGroups if (m_messageOnlineAgentsOnly) m_usersOnlineCache = new ExpiringCache(); - m_debugEnabled = groupsConfig.GetBoolean("DebugEnabled", true); + m_debugEnabled = groupsConfig.GetBoolean("MessagingDebugEnabled", m_debugEnabled); } m_log.InfoFormat( @@ -127,6 +127,14 @@ namespace OpenSim.Region.OptionalModules.Avatar.XmlRpcGroups return; scene.RegisterModuleInterface(this); + + scene.AddCommand( + "Debug", + this, + "debug groups messaging verbose", + "debug groups messaging verbose ", + "This setting turns on very verbose groups messaging debugging", + HandleDebugGroupsMessagingVerbose); } public void RegionLoaded(Scene scene) @@ -218,6 +226,26 @@ namespace OpenSim.Region.OptionalModules.Avatar.XmlRpcGroups #endregion + private void HandleDebugGroupsMessagingVerbose(object modules, string[] args) + { + if (args.Length < 5) + { + MainConsole.Instance.Output("Usage: debug groups messaging verbose "); + return; + } + + bool verbose = false; + if (!bool.TryParse(args[4], out verbose)) + { + MainConsole.Instance.Output("Usage: debug groups messaging verbose "); + return; + } + + m_debugEnabled = verbose; + + MainConsole.Instance.OutputFormat("{0} verbose logging set to {1}", Name, m_debugEnabled); + } + /// /// Not really needed, but does confirm that the group exists. /// @@ -336,27 +364,45 @@ namespace OpenSim.Region.OptionalModules.Avatar.XmlRpcGroups IClientAPI client = GetActiveClient(member.AgentID); if (client == null) { + int startTick = Environment.TickCount; + // If they're not local, forward across the grid - if (m_debugEnabled) m_log.DebugFormat("[GROUPS-MESSAGING]: Delivering to {0} via Grid", member.AgentID); m_msgTransferModule.SendInstantMessage(msg, delegate(bool success) { }); + + if (m_debugEnabled) + m_log.DebugFormat( + "[GROUPS-MESSAGING]: Delivering to {0} via grid took {1} ms", + member.AgentID, Environment.TickCount - startTick); } else { - // Deliver locally, directly - if (m_debugEnabled) m_log.DebugFormat("[GROUPS-MESSAGING]: Passing to ProcessMessageFromGroupSession to deliver to {0} locally", client.Name); + int startTick = Environment.TickCount; + ProcessMessageFromGroupSession(msg, client); + + // Deliver locally, directly + if (m_debugEnabled) + m_log.DebugFormat( + "[GROUPS-MESSAGING]: Delivering to {0} locally took {1} ms", + member.AgentID, Environment.TickCount - startTick); } } else { + int startTick = Environment.TickCount; + m_msgTransferModule.HandleUndeliverableMessage(msg, delegate(bool success) { }); + + if (m_debugEnabled) + m_log.DebugFormat( + "[GROUPS-MESSAGING]: Handling undeliverable message for {0} took {1} ms", + member.AgentID, Environment.TickCount - startTick); } } - // Temporary for assessing how long it still takes to send messages to large online groups. - if (m_messageOnlineAgentsOnly) + if (m_debugEnabled) m_log.DebugFormat( - "[GROUPS-MESSAGING]: SendMessageToGroup for group {0} with {1} members, {2} candidates for delivery took {3}ms", + "[GROUPS-MESSAGING]: Total SendMessageToGroup for group {0} with {1} members, {2} candidates for delivery took {3} ms", groupID, groupMembersCount, attemptDeliveryUuidSet.Count(), Environment.TickCount - requestStartTick); } @@ -591,15 +637,15 @@ namespace OpenSim.Region.OptionalModules.Avatar.XmlRpcGroups // Don't log any normal IMs (privacy!) if (m_debugEnabled && im.dialog != (byte)InstantMessageDialog.MessageFromAgent) { - m_log.WarnFormat("[GROUPS-MESSAGING]: IM: fromGroup({0})", im.fromGroup ? "True" : "False"); - m_log.WarnFormat("[GROUPS-MESSAGING]: IM: Dialog({0})", (InstantMessageDialog)im.dialog); - m_log.WarnFormat("[GROUPS-MESSAGING]: IM: fromAgentID({0})", im.fromAgentID); - m_log.WarnFormat("[GROUPS-MESSAGING]: IM: fromAgentName({0})", im.fromAgentName); - m_log.WarnFormat("[GROUPS-MESSAGING]: IM: imSessionID({0})", im.imSessionID); - m_log.WarnFormat("[GROUPS-MESSAGING]: IM: message({0})", im.message); - m_log.WarnFormat("[GROUPS-MESSAGING]: IM: offline({0})", im.offline); - m_log.WarnFormat("[GROUPS-MESSAGING]: IM: toAgentID({0})", im.toAgentID); - m_log.WarnFormat("[GROUPS-MESSAGING]: IM: binaryBucket({0})", OpenMetaverse.Utils.BytesToHexString(im.binaryBucket, "BinaryBucket")); + m_log.DebugFormat("[GROUPS-MESSAGING]: IM: fromGroup({0})", im.fromGroup ? "True" : "False"); + m_log.DebugFormat("[GROUPS-MESSAGING]: IM: Dialog({0})", (InstantMessageDialog)im.dialog); + m_log.DebugFormat("[GROUPS-MESSAGING]: IM: fromAgentID({0})", im.fromAgentID); + m_log.DebugFormat("[GROUPS-MESSAGING]: IM: fromAgentName({0})", im.fromAgentName); + m_log.DebugFormat("[GROUPS-MESSAGING]: IM: imSessionID({0})", im.imSessionID); + m_log.DebugFormat("[GROUPS-MESSAGING]: IM: message({0})", im.message); + m_log.DebugFormat("[GROUPS-MESSAGING]: IM: offline({0})", im.offline); + m_log.DebugFormat("[GROUPS-MESSAGING]: IM: toAgentID({0})", im.toAgentID); + m_log.DebugFormat("[GROUPS-MESSAGING]: IM: binaryBucket({0})", OpenMetaverse.Utils.BytesToHexString(im.binaryBucket, "BinaryBucket")); } } @@ -610,7 +656,8 @@ namespace OpenSim.Region.OptionalModules.Avatar.XmlRpcGroups /// private IClientAPI GetActiveClient(UUID agentID) { - if (m_debugEnabled) m_log.WarnFormat("[GROUPS-MESSAGING]: Looking for local client {0}", agentID); + if (m_debugEnabled) + m_log.DebugFormat("[GROUPS-MESSAGING]: Looking for local client {0}", agentID); IClientAPI child = null; @@ -622,12 +669,16 @@ namespace OpenSim.Region.OptionalModules.Avatar.XmlRpcGroups { if (!sp.IsChildAgent) { - if (m_debugEnabled) m_log.WarnFormat("[GROUPS-MESSAGING]: Found root agent for client : {0}", sp.ControllingClient.Name); + if (m_debugEnabled) + m_log.DebugFormat("[GROUPS-MESSAGING]: Found root agent for client : {0}", sp.ControllingClient.Name); + return sp.ControllingClient; } else { - if (m_debugEnabled) m_log.WarnFormat("[GROUPS-MESSAGING]: Found child agent for client : {0}", sp.ControllingClient.Name); + if (m_debugEnabled) + m_log.DebugFormat("[GROUPS-MESSAGING]: Found child agent for client : {0}", sp.ControllingClient.Name); + child = sp.ControllingClient; } } @@ -636,12 +687,15 @@ namespace OpenSim.Region.OptionalModules.Avatar.XmlRpcGroups // If we didn't find a root, then just return whichever child we found, or null if none if (child == null) { - if (m_debugEnabled) m_log.WarnFormat("[GROUPS-MESSAGING]: Could not find local client for agent : {0}", agentID); + if (m_debugEnabled) + m_log.DebugFormat("[GROUPS-MESSAGING]: Could not find local client for agent : {0}", agentID); } else { - if (m_debugEnabled) m_log.WarnFormat("[GROUPS-MESSAGING]: Returning child agent for client : {0}", child.Name); + if (m_debugEnabled) + m_log.DebugFormat("[GROUPS-MESSAGING]: Returning child agent for client : {0}", child.Name); } + return child; } diff --git a/bin/OpenSimDefaults.ini b/bin/OpenSimDefaults.ini index cae29589fb..3b7a611161 100644 --- a/bin/OpenSimDefaults.ini +++ b/bin/OpenSimDefaults.ini @@ -1664,6 +1664,9 @@ ; This makes the Groups modules very chatty on the console. DebugEnabled = false + ; This makes the Groups Messaging modules very chatty on the console. + DebugMessagingEnabled = false + ; Groups data is cached for this number of seconds before another request is made to the groups service ; Set to 0 to disable the cache. ; Default is 30 seconds