3 files changed, 116 insertions, 24 deletions

diff --git a/OpenSim/Region/ScriptEngine/Interfaces/IScriptInstance.cs b/OpenSim/Region/ScriptEngine/Interfaces/IScriptInstance.cs
index 0cef550..00a99c3 100644
--- a/OpenSim/Region/ScriptEngine/Interfaces/IScriptInstance.cs
+++ b/OpenSim/Region/ScriptEngine/Interfaces/IScriptInstance.cs
@@ -59,6 +59,18 @@ namespace OpenSim.Region.ScriptEngine.Interfaces
     public interface IScriptInstance
     {
         /// <summary>
+        /// Debug level for this script instance.
+        /// </summary>
+        /// <remarks>
+        /// Level == 0, no extra data is logged.
+        /// Level >= 1, state changes are logged.
+        /// Level >= 2, event firing is logged.
+        /// <value>
+        /// The debug level.
+        /// </value>
+        int DebugLevel { get; set; }
+
+        /// <summary>
         /// Is the script currently running?
         /// </summary>
         bool Running { get; set; }
diff --git a/OpenSim/Region/ScriptEngine/Shared/Instance/ScriptInstance.cs b/OpenSim/Region/ScriptEngine/Shared/Instance/ScriptInstance.cs
index 538cb8b..68f701c 100644
--- a/OpenSim/Region/ScriptEngine/Shared/Instance/ScriptInstance.cs
+++ b/OpenSim/Region/ScriptEngine/Shared/Instance/ScriptInstance.cs
@@ -94,6 +94,8 @@ namespace OpenSim.Region.ScriptEngine.Shared.Instance
         private UUID m_CurrentStateHash;
         private UUID m_RegionID;
 
+        public int DebugLevel { get; set; }
+
         public Dictionary<KeyValuePair<int, int>, KeyValuePair<int, int>> LineMap { get; set; }
 
         private Dictionary<string,IScriptApi> m_Apis = new Dictionary<string,IScriptApi>();
@@ -549,9 +551,9 @@ namespace OpenSim.Region.ScriptEngine.Shared.Instance
             // forcibly abort the work item (this aborts the underlying thread).
             if (!m_InSelfDelete)
             {
-//                m_log.ErrorFormat(
-//                    "[SCRIPT INSTANCE]: Aborting script {0} {1} in prim {2} {3} {4} {5}",
-//                    ScriptName, ItemID, PrimName, ObjectID, m_InSelfDelete, DateTime.Now.Ticks);
+                m_log.DebugFormat(
+                    "[SCRIPT INSTANCE]: Aborting unstopped script {0} {1} in prim {2}, localID {3}, timeout was {4} ms", 
+                    ScriptName, ItemID, PrimName, LocalID, timeout);
 
                 workItem.Abort();
             }
@@ -707,19 +709,41 @@ namespace OpenSim.Region.ScriptEngine.Shared.Instance
             {
                 
 //                m_log.DebugFormat("[XEngine]: Processing event {0} for {1}", data.EventName, this);
+                SceneObjectPart part = Engine.World.GetSceneObjectPart(LocalID);
+
+                if (DebugLevel >= 2)
+                    m_log.DebugFormat(
+                        "[SCRIPT INSTANCE]: Processing event {0} for {1}/{2}({3})/{4}({5}) @ {6}/{7}", 
+                        data.EventName, 
+                        ScriptName, 
+                        part.Name, 
+                        part.LocalId, 
+                        part.ParentGroup.Name, 
+                        part.ParentGroup.UUID, 
+                        part.AbsolutePosition, 
+                        part.ParentGroup.Scene.Name);
 
                 m_DetectParams = data.DetectParams;
 
                 if (data.EventName == "state") // Hardcoded state change
                 {
-    //                m_log.DebugFormat("[Script] Script {0}.{1} state set to {2}",
-    //                        PrimName, ScriptName, data.Params[0].ToString());
                     State = data.Params[0].ToString();
+
+                    if (DebugLevel >= 1)
+                        m_log.DebugFormat(
+                            "[SCRIPT INSTANCE]: Changing state to {0} for {1}/{2}({3})/{4}({5}) @ {6}/{7}", 
+                            State, 
+                            ScriptName, 
+                            part.Name, 
+                            part.LocalId, 
+                            part.ParentGroup.Name, 
+                            part.ParentGroup.UUID, 
+                            part.AbsolutePosition, 
+                            part.ParentGroup.Scene.Name);
+
                     AsyncCommandManager.RemoveScript(Engine,
                         LocalID, ItemID);
 
-                    SceneObjectPart part = Engine.World.GetSceneObjectPart(
-                        LocalID);
                     if (part != null)
                     {
                         part.SetScriptEvents(ItemID,
@@ -731,8 +755,6 @@ namespace OpenSim.Region.ScriptEngine.Shared.Instance
                     if (Engine.World.PipeEventsForScript(LocalID) ||
                         data.EventName == "control") // Don't freeze avies!
                     {
-                        SceneObjectPart part = Engine.World.GetSceneObjectPart(
-                            LocalID);
         //                m_log.DebugFormat("[Script] Delivered event {2} in state {3} to {0}.{1}",
         //                        PrimName, ScriptName, data.EventName, State);
 
diff --git a/OpenSim/Region/ScriptEngine/XEngine/XEngine.cs b/OpenSim/Region/ScriptEngine/XEngine/XEngine.cs
index 05ba890..494e0b6 100644
--- a/OpenSim/Region/ScriptEngine/XEngine/XEngine.cs
+++ b/OpenSim/Region/ScriptEngine/XEngine/XEngine.cs
@@ -108,6 +108,24 @@ namespace OpenSim.Region.ScriptEngine.XEngine
         private IXmlRpcRouter m_XmlRpcRouter;
         private int m_EventLimit;
         private bool m_KillTimedOutScripts;
+
+        /// <summary>
+        /// Number of milliseconds we will wait for a script event to complete on script stop before we forcibly abort
+        /// its thread.
+        /// </summary>
+        /// <remarks>
+        /// It appears that if a script thread is aborted whilst it is holding ReaderWriterLockSlim (possibly the write
+        /// lock) then the lock is not properly released.  This causes mono 2.6, 2.10 and possibly
+        /// later to crash, sometimes with symptoms such as a leap to 100% script usage and a vm thead dump showing
+        /// all threads waiting on release of ReaderWriterLockSlim write thread which none of the threads listed 
+        /// actually hold.
+        /// 
+        /// Pausing for event completion reduces the risk of this happening.  However, it may be that aborting threads
+        /// is not a mono issue per se but rather a risky activity in itself in an AppDomain that is not immediately
+        /// shutting down.
+        /// </remarks>
+        private int m_WaitForEventCompletionOnScriptStop = 1000;
+
         private string m_ScriptEnginesPath = null;
 
         private ExpiringCache<UUID, bool> m_runFlags = new ExpiringCache<UUID, bool>();
@@ -317,6 +335,9 @@ namespace OpenSim.Region.ScriptEngine.XEngine
             m_EventLimit = m_ScriptConfig.GetInt("EventLimit", 30);
             m_KillTimedOutScripts = m_ScriptConfig.GetBoolean("KillTimedOutScripts", false);
             m_SaveTime = m_ScriptConfig.GetInt("SaveInterval", 120) * 1000;
+            m_WaitForEventCompletionOnScriptStop 
+                = m_ScriptConfig.GetInt("WaitForEventCompletionOnScriptStop", m_WaitForEventCompletionOnScriptStop);
+
             m_ScriptEnginesPath = m_ScriptConfig.GetString("ScriptEnginesPath", "ScriptEngines");
 
             m_Prio = ThreadPriority.BelowNormal;
@@ -372,7 +393,7 @@ namespace OpenSim.Region.ScriptEngine.XEngine
 
             MainConsole.Instance.Commands.AddCommand(
                 "Scripts", false, "scripts show", "scripts show [<script-item-uuid>]", "Show script information",
-                "Show information on all scripts known to the script engine."
+                "Show information on all scripts known to the script engine.\n"
                     + "If a <script-item-uuid> is given then only information on that script will be shown.",
                 HandleShowScripts);
 
@@ -391,22 +412,30 @@ namespace OpenSim.Region.ScriptEngine.XEngine
             MainConsole.Instance.Commands.AddCommand(
                 "Scripts", false, "scripts resume", "scripts resume [<script-item-uuid>]", "Resumes all suspended scripts",
                 "Resumes all currently suspended scripts.\n"
-                    + "Resumed scripts will process all events accumulated whilst suspended."
+                    + "Resumed scripts will process all events accumulated whilst suspended.\n"
                     + "If a <script-item-uuid> is given then only that script will be resumed.  Otherwise, all suitable scripts are resumed.",
                 (module, cmdparams) => HandleScriptsAction(cmdparams, HandleResumeScript));
 
             MainConsole.Instance.Commands.AddCommand(
                 "Scripts", false, "scripts stop", "scripts stop [<script-item-uuid>]", "Stops all running scripts",
-                "Stops all running scripts."
+                "Stops all running scripts.\n"
                     + "If a <script-item-uuid> is given then only that script will be stopped.  Otherwise, all suitable scripts are stopped.",
                 (module, cmdparams) => HandleScriptsAction(cmdparams, HandleStopScript));
 
             MainConsole.Instance.Commands.AddCommand(
                 "Scripts", false, "scripts start", "scripts start [<script-item-uuid>]", "Starts all stopped scripts",
-                "Starts all stopped scripts."
+                "Starts all stopped scripts.\n"
                     + "If a <script-item-uuid> is given then only that script will be started.  Otherwise, all suitable scripts are started.",
                 (module, cmdparams) => HandleScriptsAction(cmdparams, HandleStartScript));
 
+            MainConsole.Instance.Commands.AddCommand(
+                "Scripts", false, "debug script log", "debug scripts log <item-id> <log-level>", "Extra debug logging for a script",
+                "Activates or deactivates extra debug logging for the given script.\n"
+                    + "Level == 0, deactivate extra debug logging.\n"
+                    + "Level >= 1, log state changes.\n"
+                    + "Level >= 2, log event invocations.\n",
+                HandleDebugScriptLogCommand);
+
 //            MainConsole.Instance.Commands.AddCommand(
 //                "Debug", false, "debug xengine", "debug xengine [<level>]",
 //                "Turn on detailed xengine debugging.",
@@ -415,6 +444,41 @@ namespace OpenSim.Region.ScriptEngine.XEngine
 //                HandleDebugLevelCommand);
         }
 
+        private void HandleDebugScriptLogCommand(string module, string[] args)
+        {
+            if (!(MainConsole.Instance.ConsoleScene == null || MainConsole.Instance.ConsoleScene == m_Scene))
+                return;
+
+            if (args.Length != 5)
+            {
+                MainConsole.Instance.Output("Usage: debug script log <item-id> <log-level>");
+                return;
+            }
+
+            UUID itemId;
+
+            if (!ConsoleUtil.TryParseConsoleUuid(MainConsole.Instance, args[3], out itemId))
+                return;
+
+            int newLevel;
+
+            if (!ConsoleUtil.TryParseConsoleInt(MainConsole.Instance, args[4], out newLevel))
+                return;
+
+            IScriptInstance si;
+
+            lock (m_Scripts)
+            {
+                // XXX: We can't give the user feedback on a bad item id because this may apply to a different script
+                // engine
+                if (!m_Scripts.TryGetValue(itemId, out si))
+                    return;
+            }
+
+            si.DebugLevel = newLevel;
+            MainConsole.Instance.OutputFormat("Set debug level of {0} {1} to {2}", si.ScriptName, si.ItemID, newLevel);
+        }
+
         /// <summary>
         /// Change debug level
         /// </summary>
@@ -486,7 +550,7 @@ namespace OpenSim.Region.ScriptEngine.XEngine
     
                 if (!UUID.TryParse(rawItemId, out itemId))
                 {
-                    MainConsole.Instance.OutputFormat("Error - {0} is not a valid UUID", rawItemId);
+                    MainConsole.Instance.OutputFormat("ERROR: {0} is not a valid UUID", rawItemId);
                     return;
                 }
     
@@ -610,6 +674,7 @@ namespace OpenSim.Region.ScriptEngine.XEngine
             sb.AppendFormat("Queued events       : {0}\n", instance.EventsQueued);
             sb.AppendFormat("Processed events    : {0}\n", instance.EventsProcessed);
             sb.AppendFormat("Item UUID           : {0}\n", instance.ItemID);
+            sb.AppendFormat("Asset UUID          : {0}\n", instance.AssetID);
             sb.AppendFormat("Containing part name: {0}\n", instance.PrimName);
             sb.AppendFormat("Containing part UUID: {0}\n", instance.ObjectID);
             sb.AppendFormat("Position            : {0}\n", sop.AbsolutePosition);
@@ -1375,9 +1440,7 @@ namespace OpenSim.Region.ScriptEngine.XEngine
             lockScriptsForWrite(false);
             instance.ClearQueue();
 
-            // Give the script some time to finish processing its last event.  Simply aborting the script thread can
-            // cause issues on mono 2.6, 2.10 and possibly later where locks are not released properly on abort.
-            instance.Stop(1000);
+            instance.Stop(m_WaitForEventCompletionOnScriptStop);
 
 //                bool objectRemoved = false;
 
@@ -1735,16 +1798,11 @@ namespace OpenSim.Region.ScriptEngine.XEngine
         public void StopScript(UUID itemID)
         {
             IScriptInstance instance = GetInstance(itemID);
+
             if (instance != null)
-            {
-                // Give the script some time to finish processing its last event.  Simply aborting the script thread can
-                // cause issues on mono 2.6, 2.10 and possibly later where locks are not released properly on abort.
-                instance.Stop(1000);
-            }
+                instance.Stop(m_WaitForEventCompletionOnScriptStop);
             else
-            {
                 m_runFlags.AddOrUpdate(itemID, false, 240);
-            }
         }
 
         public DetectParams GetDetectParams(UUID itemID, int idx)