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.
bullet-2.82
Justin Clark-Casey (justincc) 2014-05-19 22:45:17 +01:00
parent 3a6f312484
commit b46be88db6
3 changed files with 111 additions and 26 deletions

View File

@ -56,8 +56,8 @@ namespace OpenSim.Groups
private IGroupsServicesConnector m_groupData = null; private IGroupsServicesConnector m_groupData = null;
// Config Options // Config Options
private bool m_groupMessagingEnabled = false; private bool m_groupMessagingEnabled;
private bool m_debugEnabled = true; private bool m_debugEnabled;
/// <summary> /// <summary>
/// If enabled, module only tries to send group IMs to online users by querying cached presence information. /// 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; return;
} }
m_debugEnabled = groupsConfig.GetBoolean("DebugEnabled", true); m_debugEnabled = groupsConfig.GetBoolean("MessagingDebugEnabled", m_debugEnabled);
m_log.InfoFormat( m_log.InfoFormat(
"[Groups.Messaging]: GroupsMessagingModule enabled with MessageOnlineOnly = {0}, DebugEnabled = {1}", "[Groups.Messaging]: GroupsMessagingModule enabled with MessageOnlineOnly = {0}, DebugEnabled = {1}",
@ -140,6 +140,14 @@ namespace OpenSim.Groups
scene.EventManager.OnMakeChildAgent += OnMakeChildAgent; scene.EventManager.OnMakeChildAgent += OnMakeChildAgent;
scene.EventManager.OnIncomingInstantMessage += OnGridInstantMessage; scene.EventManager.OnIncomingInstantMessage += OnGridInstantMessage;
scene.EventManager.OnClientLogin += OnClientLogin; scene.EventManager.OnClientLogin += OnClientLogin;
scene.AddCommand(
"Debug",
this,
"debug groups messaging verbose",
"debug groups messaging verbose <true|false>",
"This setting turns on very verbose groups messaging debugging",
HandleDebugGroupsMessagingVerbose);
} }
public void RegionLoaded(Scene scene) public void RegionLoaded(Scene scene)
@ -227,6 +235,26 @@ namespace OpenSim.Groups
#endregion #endregion
private void HandleDebugGroupsMessagingVerbose(object modules, string[] args)
{
if (args.Length < 5)
{
MainConsole.Instance.Output("Usage: debug groups messaging verbose <true|false>");
return;
}
bool verbose = false;
if (!bool.TryParse(args[4], out verbose))
{
MainConsole.Instance.Output("Usage: debug groups messaging verbose <true|false>");
return;
}
m_debugEnabled = verbose;
MainConsole.Instance.OutputFormat("{0} verbose logging set to {1}", Name, m_debugEnabled);
}
/// <summary> /// <summary>
/// Not really needed, but does confirm that the group exists. /// Not really needed, but does confirm that the group exists.
/// </summary> /// </summary>

View File

@ -55,8 +55,8 @@ namespace OpenSim.Region.OptionalModules.Avatar.XmlRpcGroups
private IGroupsServicesConnector m_groupData = null; private IGroupsServicesConnector m_groupData = null;
// Config Options // Config Options
private bool m_groupMessagingEnabled = false; private bool m_groupMessagingEnabled;
private bool m_debugEnabled = true; private bool m_debugEnabled;
/// <summary> /// <summary>
/// If enabled, module only tries to send group IMs to online users by querying cached presence information. /// 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) if (m_messageOnlineAgentsOnly)
m_usersOnlineCache = new ExpiringCache<UUID, PresenceInfo[]>(); m_usersOnlineCache = new ExpiringCache<UUID, PresenceInfo[]>();
m_debugEnabled = groupsConfig.GetBoolean("DebugEnabled", true); m_debugEnabled = groupsConfig.GetBoolean("MessagingDebugEnabled", m_debugEnabled);
} }
m_log.InfoFormat( m_log.InfoFormat(
@ -127,6 +127,14 @@ namespace OpenSim.Region.OptionalModules.Avatar.XmlRpcGroups
return; return;
scene.RegisterModuleInterface<IGroupsMessagingModule>(this); scene.RegisterModuleInterface<IGroupsMessagingModule>(this);
scene.AddCommand(
"Debug",
this,
"debug groups messaging verbose",
"debug groups messaging verbose <true|false>",
"This setting turns on very verbose groups messaging debugging",
HandleDebugGroupsMessagingVerbose);
} }
public void RegionLoaded(Scene scene) public void RegionLoaded(Scene scene)
@ -218,6 +226,26 @@ namespace OpenSim.Region.OptionalModules.Avatar.XmlRpcGroups
#endregion #endregion
private void HandleDebugGroupsMessagingVerbose(object modules, string[] args)
{
if (args.Length < 5)
{
MainConsole.Instance.Output("Usage: debug groups messaging verbose <true|false>");
return;
}
bool verbose = false;
if (!bool.TryParse(args[4], out verbose))
{
MainConsole.Instance.Output("Usage: debug groups messaging verbose <true|false>");
return;
}
m_debugEnabled = verbose;
MainConsole.Instance.OutputFormat("{0} verbose logging set to {1}", Name, m_debugEnabled);
}
/// <summary> /// <summary>
/// Not really needed, but does confirm that the group exists. /// Not really needed, but does confirm that the group exists.
/// </summary> /// </summary>
@ -336,27 +364,45 @@ namespace OpenSim.Region.OptionalModules.Avatar.XmlRpcGroups
IClientAPI client = GetActiveClient(member.AgentID); IClientAPI client = GetActiveClient(member.AgentID);
if (client == null) if (client == null)
{ {
int startTick = Environment.TickCount;
// If they're not local, forward across the grid // 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) { }); 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 else
{ {
// Deliver locally, directly int startTick = Environment.TickCount;
if (m_debugEnabled) m_log.DebugFormat("[GROUPS-MESSAGING]: Passing to ProcessMessageFromGroupSession to deliver to {0} locally", client.Name);
ProcessMessageFromGroupSession(msg, client); 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 else
{ {
int startTick = Environment.TickCount;
m_msgTransferModule.HandleUndeliverableMessage(msg, delegate(bool success) { }); 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_debugEnabled)
if (m_messageOnlineAgentsOnly)
m_log.DebugFormat( 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); groupID, groupMembersCount, attemptDeliveryUuidSet.Count(), Environment.TickCount - requestStartTick);
} }
@ -591,15 +637,15 @@ namespace OpenSim.Region.OptionalModules.Avatar.XmlRpcGroups
// Don't log any normal IMs (privacy!) // Don't log any normal IMs (privacy!)
if (m_debugEnabled && im.dialog != (byte)InstantMessageDialog.MessageFromAgent) if (m_debugEnabled && im.dialog != (byte)InstantMessageDialog.MessageFromAgent)
{ {
m_log.WarnFormat("[GROUPS-MESSAGING]: IM: fromGroup({0})", im.fromGroup ? "True" : "False"); m_log.DebugFormat("[GROUPS-MESSAGING]: IM: fromGroup({0})", im.fromGroup ? "True" : "False");
m_log.WarnFormat("[GROUPS-MESSAGING]: IM: Dialog({0})", (InstantMessageDialog)im.dialog); m_log.DebugFormat("[GROUPS-MESSAGING]: IM: Dialog({0})", (InstantMessageDialog)im.dialog);
m_log.WarnFormat("[GROUPS-MESSAGING]: IM: fromAgentID({0})", im.fromAgentID); m_log.DebugFormat("[GROUPS-MESSAGING]: IM: fromAgentID({0})", im.fromAgentID);
m_log.WarnFormat("[GROUPS-MESSAGING]: IM: fromAgentName({0})", im.fromAgentName); m_log.DebugFormat("[GROUPS-MESSAGING]: IM: fromAgentName({0})", im.fromAgentName);
m_log.WarnFormat("[GROUPS-MESSAGING]: IM: imSessionID({0})", im.imSessionID); m_log.DebugFormat("[GROUPS-MESSAGING]: IM: imSessionID({0})", im.imSessionID);
m_log.WarnFormat("[GROUPS-MESSAGING]: IM: message({0})", im.message); m_log.DebugFormat("[GROUPS-MESSAGING]: IM: message({0})", im.message);
m_log.WarnFormat("[GROUPS-MESSAGING]: IM: offline({0})", im.offline); m_log.DebugFormat("[GROUPS-MESSAGING]: IM: offline({0})", im.offline);
m_log.WarnFormat("[GROUPS-MESSAGING]: IM: toAgentID({0})", im.toAgentID); m_log.DebugFormat("[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: binaryBucket({0})", OpenMetaverse.Utils.BytesToHexString(im.binaryBucket, "BinaryBucket"));
} }
} }
@ -610,7 +656,8 @@ namespace OpenSim.Region.OptionalModules.Avatar.XmlRpcGroups
/// </summary> /// </summary>
private IClientAPI GetActiveClient(UUID agentID) 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; IClientAPI child = null;
@ -622,12 +669,16 @@ namespace OpenSim.Region.OptionalModules.Avatar.XmlRpcGroups
{ {
if (!sp.IsChildAgent) 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; return sp.ControllingClient;
} }
else 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; 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 we didn't find a root, then just return whichever child we found, or null if none
if (child == null) 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 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; return child;
} }

View File

@ -1664,6 +1664,9 @@
; This makes the Groups modules very chatty on the console. ; This makes the Groups modules very chatty on the console.
DebugEnabled = false 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 ; 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. ; Set to 0 to disable the cache.
; Default is 30 seconds ; Default is 30 seconds