1 files changed, 241 insertions, 127 deletions

diff --git a/OpenSim/Region/ScriptEngine/XEngine/XEngine.cs b/OpenSim/Region/ScriptEngine/XEngine/XEngine.cs
index 2a01fc4..cc783aa 100644
--- a/OpenSim/Region/ScriptEngine/XEngine/XEngine.cs
+++ b/OpenSim/Region/ScriptEngine/XEngine/XEngine.cs
@@ -63,6 +63,14 @@ namespace OpenSim.Region.ScriptEngine.XEngine
     {
         private static readonly ILog m_log = LogManager.GetLogger(MethodBase.GetCurrentMethod().DeclaringType);
 
+        /// <summary>
+        /// Control the printing of certain debug messages.
+        /// </summary>
+        /// <remarks>
+        /// If DebugLevel >= 1, then we log every time that a script is started.
+        /// </remarks>
+//        public int DebugLevel { get; set; }
+
         private SmartThreadPool m_ThreadPool;
         private int m_MaxScriptQueue;
         private Scene m_Scene;
@@ -284,9 +292,8 @@ namespace OpenSim.Region.ScriptEngine.XEngine
             AppDomain.CurrentDomain.AssemblyResolve +=
                 OnAssemblyResolve;
 
-            m_log.InfoFormat("[XEngine] Initializing scripts in region {0}",
-                             scene.RegionInfo.RegionName);
             m_Scene = scene;
+            m_log.InfoFormat("[XEngine]: Initializing scripts in region {0}", m_Scene.RegionInfo.RegionName);
 
             m_MinThreads = m_ScriptConfig.GetInt("MinThreads", 2);
             m_MaxThreads = m_ScriptConfig.GetInt("MaxThreads", 100);
@@ -389,9 +396,42 @@ namespace OpenSim.Region.ScriptEngine.XEngine
                 "Starts all stopped scripts."
                     + "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(
+//                "Debug", false, "debug xengine", "debug xengine [<level>]",
+//                "Turn on detailed xengine debugging.",
+//                  "If level <= 0, then no extra logging is done.\n"
+//                + "If level >= 1, then we log every time that a script is started.",
+//                HandleDebugLevelCommand);
         }
 
         /// <summary>
+        /// Change debug level
+        /// </summary>
+        /// <param name="module"></param>
+        /// <param name="args"></param>
+//        private void HandleDebugLevelCommand(string module, string[] args)
+//        {
+//            if (args.Length == 3)
+//            {
+//                int newDebug;
+//                if (int.TryParse(args[2], out newDebug))
+//                {
+//                    DebugLevel = newDebug;
+//                    MainConsole.Instance.OutputFormat("Debug level set to {0}", newDebug);
+//                }
+//            }
+//            else if (args.Length == 2)
+//            {
+//                MainConsole.Instance.OutputFormat("Current debug level is {0}", DebugLevel);
+//            }
+//            else
+//            {
+//                MainConsole.Instance.Output("Usage: debug xengine 0..1");
+//            }
+//        }
+
+        /// <summary>
         /// Parse the raw item id into a script instance from the command params if it's present.
         /// </summary>
         /// <param name="cmdparams"></param>
@@ -799,35 +839,66 @@ namespace OpenSim.Region.ScriptEngine.XEngine
                 int colon = firstline.IndexOf(':');
                 if (firstline.Length > 2 && firstline.Substring(0, 2) == "//" && colon != -1)
                 {
-                    string engineName = firstline.Substring(2, colon-2);
+                    string engineName = firstline.Substring(2, colon - 2);
 
                     if (names.Contains(engineName))
                     {
                         engine = engineName;
-                        script = "//" + script.Substring(script.IndexOf(':')+1);
+                        script = "//" + script.Substring(colon + 1);
                     }
                     else
                     {
                         if (engine == ScriptEngineName)
                         {
-                            SceneObjectPart part =
-                                    m_Scene.GetSceneObjectPart(
-                                    localID);
-                         
-                            TaskInventoryItem item =
-                                    part.Inventory.GetInventoryItem(itemID);
-
-                            ScenePresence presence = 
-                                    m_Scene.GetScenePresence(
-                                    item.OwnerID);
-
-                            if (presence != null)
+                            // If we are falling back on XEngine as the default engine, then only complain to the user
+                            // if a script language has been explicitly set and it's one that we recognize or there are
+                            // no non-whitespace characters after the colon.
+                            //
+                            // If the script is
+                            // explicitly not allowed or the script is not in LSL then the user will be informed by a later compiler message.
+                            //
+                            // If the colon ends the line then we'll risk the false positive as this is more likely
+                            // to signal a real scriptengine line where the user wants to use the default compile language.
+                            //
+                            // This avoids the overwhelming number of false positives where we're in this code because
+                            // there's a colon in a comment in the first line of a script for entirely
+                            // unrelated reasons (e.g. vim settings).
+                            //
+                            // TODO: A better fix would be to deprecate simple : detection and look for some less likely
+                            // string to begin the comment (like #! in unix shell scripts).
+                            bool warnRunningInXEngine = false;
+                            string restOfFirstLine = firstline.Substring(colon + 1);
+
+                            // FIXME: These are hardcoded because they are currently hardcoded in Compiler.cs
+                            if (restOfFirstLine.StartsWith("c#")
+                                || restOfFirstLine.StartsWith("vb")
+                                || restOfFirstLine.StartsWith("lsl")
+                                || restOfFirstLine.StartsWith("js")
+                                || restOfFirstLine.StartsWith("yp")
+                                || restOfFirstLine.Length == 0)
+                                warnRunningInXEngine = true;
+
+                            if (warnRunningInXEngine)
                             {
-                               presence.ControllingClient.SendAgentAlertMessage(
-                                        "Selected engine unavailable. "+
-                                        "Running script on "+
-                                        ScriptEngineName,
-                                        false);
+                                SceneObjectPart part =
+                                        m_Scene.GetSceneObjectPart(
+                                        localID);
+                             
+                                TaskInventoryItem item =
+                                        part.Inventory.GetInventoryItem(itemID);
+    
+                                ScenePresence presence = 
+                                        m_Scene.GetScenePresence(
+                                        item.OwnerID);
+    
+                                if (presence != null)
+                                {
+                                   presence.ControllingClient.SendAgentAlertMessage(
+                                            "Selected engine unavailable. "+
+                                            "Running script on "+
+                                            ScriptEngineName,
+                                            false);
+                                }
                             }
                         }
                     }
@@ -884,20 +955,31 @@ namespace OpenSim.Region.ScriptEngine.XEngine
         {
             if (m_InitialStartup)
             {
-                m_InitialStartup = false;
+                // This delay exists to stop mono problems where script compilation and startup would stop the sim
+                // working properly for the session.
                 System.Threading.Thread.Sleep(15000);
+            }
 
-                if (m_CompileQueue.Count == 0)
+            object[] o;
+
+            int scriptsStarted = 0;
+
+            while (m_CompileQueue.Dequeue(out o))
+            {
+                if (DoOnRezScript(o))
                 {
-                    // No scripts on region, so won't get triggered later
-                    // by the queue becoming empty so we trigger it here
-                    m_Scene.EventManager.TriggerEmptyScriptCompileQueue(0, String.Empty);
+                    scriptsStarted++;
+
+                    if (m_InitialStartup)
+                        if (scriptsStarted % 50 == 0)
+                            m_log.InfoFormat(
+                                "[XEngine]: Started {0} scripts in {1}", scriptsStarted, m_Scene.RegionInfo.RegionName);
                 }
             }
 
-            object[] o;
-            while (m_CompileQueue.Dequeue(out o))
-                DoOnRezScript(o);
+            if (m_InitialStartup)
+                m_log.InfoFormat(
+                    "[XEngine]: Completed starting {0} scripts on {1}", scriptsStarted, m_Scene.RegionInfo.RegionName);
 
             // NOTE: Despite having a lockless queue, this lock is required
             // to make sure there is never no compile thread while there
@@ -905,12 +987,13 @@ namespace OpenSim.Region.ScriptEngine.XEngine
             // due to a race condition
             //
             lock (m_CompileQueue)
-            {
                 m_CurrentCompile = null;
-            }
+
             m_Scene.EventManager.TriggerEmptyScriptCompileQueue(m_ScriptFailCount,
                                                                 m_ScriptErrorMessage);
+
             m_ScriptFailCount = 0;
+            m_InitialStartup = false;
 
             return null;
         }
@@ -1093,11 +1176,18 @@ namespace OpenSim.Region.ScriptEngine.XEngine
 
                         AppDomain sandbox;
                         if (m_AppDomainLoading)
+                        {
                             sandbox = AppDomain.CreateDomain(
                                             m_Scene.RegionInfo.RegionID.ToString(),
                                             evidence, appSetup);
+                            m_AppDomains[appDomain].AssemblyResolve +=
+                                new ResolveEventHandler(
+                                    AssemblyResolver.OnAssemblyResolve);
+                        }
                         else
+                        {
                             sandbox = AppDomain.CurrentDomain;
+                        }
 
                         //PolicyLevel sandboxPolicy = PolicyLevel.CreateAppDomainLevel();
                         //AllMembershipCondition sandboxMembershipCondition = new AllMembershipCondition();
@@ -1109,9 +1199,6 @@ namespace OpenSim.Region.ScriptEngine.XEngine
 
                         m_AppDomains[appDomain] = sandbox;
 
-                        m_AppDomains[appDomain].AssemblyResolve +=
-                            new ResolveEventHandler(
-                                AssemblyResolver.OnAssemblyResolve);
                         m_DomainScripts[appDomain] = new List<UUID>();
                     }
                     catch (Exception e)
@@ -1396,25 +1483,24 @@ namespace OpenSim.Region.ScriptEngine.XEngine
                     return false;
 
                 uuids = m_PrimObjects[localID];
-            
 
-            foreach (UUID itemID in uuids)
-            {
-                IScriptInstance instance = null;
-                try
+                foreach (UUID itemID in uuids)
                 {
-                    if (m_Scripts.ContainsKey(itemID))
-                        instance = m_Scripts[itemID];
-                }
-                catch { /* ignore race conditions */ }
-
-                if (instance != null)
-                {
-                    instance.PostEvent(p);
-                    result = true;
+                    IScriptInstance instance = null;
+                    try
+                    {
+                        if (m_Scripts.ContainsKey(itemID))
+                            instance = m_Scripts[itemID];
+                    }
+                    catch { /* ignore race conditions */ }
+    
+                    if (instance != null)
+                    {
+                        instance.PostEvent(p);
+                        result = true;
+                    }
                 }
             }
-            }
             
             return result;
         }
@@ -1539,6 +1625,13 @@ namespace OpenSim.Region.ScriptEngine.XEngine
             }
         }
 
+        public void SetRunEnable(UUID instanceID, bool enable)
+        {
+            IScriptInstance instance = GetInstance(instanceID);
+            if (instance != null)
+                instance.Run = enable;
+        }
+
         public bool GetScriptState(UUID itemID)
         {
             IScriptInstance instance = GetInstance(itemID);
@@ -1573,7 +1666,11 @@ namespace OpenSim.Region.ScriptEngine.XEngine
         {
             IScriptInstance instance = GetInstance(itemID);
             if (instance != null)
-                instance.Stop(0);
+            {
+                // 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);
+            }
         }
 
         public DetectParams GetDetectParams(UUID itemID, int idx)
@@ -1749,14 +1846,15 @@ namespace OpenSim.Region.ScriptEngine.XEngine
                                 FileMode.Open, FileAccess.Read))
                         {
                             tfs.Read(tdata, 0, tdata.Length);
-                            tfs.Close();
                         }
 
                         assem = new System.Text.ASCIIEncoding().GetString(tdata);
                     }
                     catch (Exception e)
                     {
-                         m_log.DebugFormat("[XEngine]: Unable to open script textfile {0}, reason: {1}", assemName+".text", e.Message);
+                         m_log.ErrorFormat(
+                            "[XEngine]: Unable to open script textfile {0}{1}, reason: {2}",
+                            assemName, ".text", e.Message);
                     }
                 }
             }
@@ -1773,16 +1871,15 @@ namespace OpenSim.Region.ScriptEngine.XEngine
                         using (FileStream fs = File.Open(assemName, FileMode.Open, FileAccess.Read))
                         {
                             fs.Read(data, 0, data.Length);
-                            fs.Close();
                         }
 
                         assem = System.Convert.ToBase64String(data);
                     }
                     catch (Exception e)
                     {
-                        m_log.DebugFormat("[XEngine]: Unable to open script assembly {0}, reason: {1}", assemName, e.Message);
+                        m_log.ErrorFormat(
+                            "[XEngine]: Unable to open script assembly {0}, reason: {1}", assemName, e.Message);
                     }
-
                 }
             }
 
@@ -1795,9 +1892,7 @@ namespace OpenSim.Region.ScriptEngine.XEngine
                     using (StreamReader msr = new StreamReader(mfs))
                     {
                         map = msr.ReadToEnd();
-                        msr.Close();
                     }
-                    mfs.Close();
                 }
             }
 
@@ -1833,6 +1928,8 @@ namespace OpenSim.Region.ScriptEngine.XEngine
 
         public bool SetXMLState(UUID itemID, string xml)
         {
+//            m_log.DebugFormat("[XEngine]: Writing state for script item with ID {0}", itemID);
+
             if (xml == String.Empty)
                 return false;
 
@@ -1893,31 +1990,61 @@ namespace OpenSim.Region.ScriptEngine.XEngine
                     {
                         using (FileStream fs = File.Create(path))
                         {
+//                            m_log.DebugFormat("[XEngine]: Writing assembly file {0}", path);
+
                             fs.Write(filedata, 0, filedata.Length);
-                            fs.Close();
                         }
                     }
                     catch (IOException ex)
                     {
                         // if there already exists a file at that location, it may be locked.
-                        m_log.ErrorFormat("[XEngine]: File {0} already exists! {1}", path, ex.Message);
+                        m_log.ErrorFormat("[XEngine]: Error whilst writing assembly file {0}, {1}", path, ex.Message);
                     }
+
+                    string textpath = path + ".text";
                     try
                     {
-                        using (FileStream fs = File.Create(path + ".text"))
+                        using (FileStream fs = File.Create(textpath))
                         {
                             using (StreamWriter sw = new StreamWriter(fs))
                             {
+//                                m_log.DebugFormat("[XEngine]: Writing .text file {0}", textpath);
+
                                 sw.Write(base64);
-                                sw.Close();
                             }
-                            fs.Close();
                         }
                     }
                     catch (IOException ex)
                     {
                         // if there already exists a file at that location, it may be locked.
-                        m_log.ErrorFormat("[XEngine]: File {0} already exists! {1}", path, ex.Message);
+                        m_log.ErrorFormat("[XEngine]: Error whilst writing .text file {0}, {1}", textpath, ex.Message);
+                    }
+                }
+
+                XmlNodeList mapL = rootE.GetElementsByTagName("LineMap");
+                if (mapL.Count > 0)
+                {
+                    XmlElement mapE = (XmlElement)mapL[0];
+
+                    string mappath = Path.Combine(m_ScriptEnginesPath, World.RegionInfo.RegionID.ToString());
+                    mappath = Path.Combine(mappath, mapE.GetAttribute("Filename"));
+
+                    try
+                    {
+                        using (FileStream mfs = File.Create(mappath))
+                        {
+                            using (StreamWriter msw = new StreamWriter(mfs))
+                            {
+    //                            m_log.DebugFormat("[XEngine]: Writing linemap file {0}", mappath);
+
+                                msw.Write(mapE.InnerText);
+                            }
+                        }
+                    }
+                    catch (IOException ex)
+                    {
+                        // if there already exists a file at that location, it may be locked.
+                        m_log.ErrorFormat("[XEngine]: Linemap file {0} already exists! {1}", mappath, ex.Message);
                     }
                 }
             }
@@ -1931,43 +2058,16 @@ namespace OpenSim.Region.ScriptEngine.XEngine
                 {
                     using (StreamWriter ssw = new StreamWriter(sfs))
                     {
+//                        m_log.DebugFormat("[XEngine]: Writing state file {0}", statepath);
+
                         ssw.Write(stateE.OuterXml);
-                        ssw.Close();
                     }
-                    sfs.Close();
                 }
             }
             catch (IOException ex)
             {
                 // if there already exists a file at that location, it may be locked.
-                m_log.ErrorFormat("[XEngine]: File {0} already exists! {1}", statepath, ex.Message);
-            }
-
-            XmlNodeList mapL = rootE.GetElementsByTagName("LineMap");
-            if (mapL.Count > 0)
-            {
-                XmlElement mapE = (XmlElement)mapL[0];
-
-                string mappath = Path.Combine(m_ScriptEnginesPath, World.RegionInfo.RegionID.ToString());
-                mappath = Path.Combine(mappath, mapE.GetAttribute("Filename"));
-
-                try
-                {
-                    using (FileStream mfs = File.Create(mappath))
-                    {
-                        using (StreamWriter msw = new StreamWriter(mfs))
-                        {
-                            msw.Write(mapE.InnerText);
-                            msw.Close();
-                        }
-                        mfs.Close();
-                    }
-                }
-                catch (IOException ex)
-                {
-                    // if there already exists a file at that location, it may be locked.
-                    m_log.ErrorFormat("[XEngine]: File {0} already exists! {1}", statepath, ex.Message);
-                }
+                m_log.ErrorFormat("[XEngine]: Error whilst writing state file {0}, {1}", statepath, ex.Message);
             }
 
             return true;
@@ -2001,45 +2101,59 @@ namespace OpenSim.Region.ScriptEngine.XEngine
                     if (!topScripts.ContainsKey(si.LocalID))
                         topScripts[si.RootLocalID] = 0;
 
-//                    long ticksElapsed = tickNow - si.MeasurementPeriodTickStart;
-//                    float framesElapsed = ticksElapsed / (18.1818 * TimeSpan.TicksPerMillisecond);
-
-                    // Execution time of the script adjusted by it's measurement period to make scripts started at
-                    // different times comparable.
-//                    float adjustedExecutionTime
-//                        = (float)si.MeasurementPeriodExecutionTime
-//                            / ((float)(tickNow - si.MeasurementPeriodTickStart) / ScriptInstance.MaxMeasurementPeriod)
-//                            / TimeSpan.TicksPerMillisecond;
-
-                    long ticksElapsed = tickNow - si.MeasurementPeriodTickStart;
-
-                    // Avoid divide by zerp
-                    if (ticksElapsed == 0)
-                        ticksElapsed = 1;
+                    topScripts[si.RootLocalID] += CalculateAdjustedExectionTime(si, tickNow);
+                }
+            }
 
-                    // Scale execution time to the ideal 55 fps frame time for these reasons.
-                    //
-                    // 1) XEngine does not execute scripts per frame, unlike other script engines.  Hence, there is no
-                    // 'script execution time per frame', which is the original purpose of this value.
-                    //
-                    // 2) Giving the raw execution times is misleading since scripts start at different times, making
-                    // it impossible to compare scripts.
-                    //
-                    // 3) Scaling the raw execution time to the time that the script has been running is better but
-                    // is still misleading since a script that has just been rezzed may appear to have been running
-                    // for much longer.
-                    //
-                    // 4) Hence, we scale execution time to an idealised frame time (55 fps).  This is also not perfect
-                    // since the figure does not represent actual execution time and very hard running scripts will
-                    // never exceed 18ms (though this is a very high number for script execution so is a warning sign).
-                    float adjustedExecutionTime
-                        = ((float)si.MeasurementPeriodExecutionTime / ticksElapsed) * 18.1818f;
+            return topScripts;
+        }
 
-                    topScripts[si.RootLocalID] += adjustedExecutionTime;
+        public float GetScriptExecutionTime(List<UUID> itemIDs)
+        {
+            if (itemIDs == null|| itemIDs.Count == 0)
+            {
+                return 0.0f;
+            }
+            float time = 0.0f;
+            long tickNow = Util.EnvironmentTickCount();
+            IScriptInstance si;
+            // Calculate the time for all scripts that this engine is executing
+            // Ignore any others
+            foreach (UUID id in itemIDs)
+            {
+                si = GetInstance(id);
+                if (si != null && si.Running)
+                {
+                    time += CalculateAdjustedExectionTime(si, tickNow);
                 }
             }
+            return time;
+        }
 
-            return topScripts;
+        private float CalculateAdjustedExectionTime(IScriptInstance si, long tickNow)
+        {
+            long ticksElapsed = tickNow - si.MeasurementPeriodTickStart;
+
+            // Avoid divide by zero
+            if (ticksElapsed == 0)
+                ticksElapsed = 1;
+
+            // Scale execution time to the ideal 55 fps frame time for these reasons.
+            //
+            // 1) XEngine does not execute scripts per frame, unlike other script engines.  Hence, there is no
+            // 'script execution time per frame', which is the original purpose of this value.
+            //
+            // 2) Giving the raw execution times is misleading since scripts start at different times, making
+            // it impossible to compare scripts.
+            //
+            // 3) Scaling the raw execution time to the time that the script has been running is better but
+            // is still misleading since a script that has just been rezzed may appear to have been running
+            // for much longer.
+            //
+            // 4) Hence, we scale execution time to an idealised frame time (55 fps).  This is also not perfect
+            // since the figure does not represent actual execution time and very hard running scripts will
+            // never exceed 18ms (though this is a very high number for script execution so is a warning sign).
+            return ((float)si.MeasurementPeriodExecutionTime / ticksElapsed) * 18.1818f;
         }
 
         public void SuspendScript(UUID itemID)