From bfea07750835ab7b14f56e94bff869505a88ebb4 Mon Sep 17 00:00:00 2001 From: Justin Clarke Casey Date: Fri, 5 Jun 2009 13:48:43 +0000 Subject: [PATCH] * Add oar saving timeout * If an oar save fails to get responses to all asset requests to the asset service then timeout after 60 seconds * Timeout executes abort, since missing assets in an OAR seems bad * This means that oar saves won't permanently hang and instead can be retried if something goes wrong with the asset service * This is not a solution to mantis 3714. Hopefully a fix will be along shortly since I can now consistently reproduce that problem --- .../Servers/BaseGetAssetStreamHandler.cs | 2 +- .../AsynchronousRestObjectRequester.cs | 10 +- OpenSim/Region/Application/OpenSimBase.cs | 1 - .../World/Archiver/AssetsArchiver.cs | 10 +- .../World/Archiver/AssetsRequest.cs | 119 ++++++++++++++++++ 5 files changed, 138 insertions(+), 4 deletions(-) diff --git a/OpenSim/Framework/Servers/BaseGetAssetStreamHandler.cs b/OpenSim/Framework/Servers/BaseGetAssetStreamHandler.cs index 9eacf2469a..83a567635a 100644 --- a/OpenSim/Framework/Servers/BaseGetAssetStreamHandler.cs +++ b/OpenSim/Framework/Servers/BaseGetAssetStreamHandler.cs @@ -61,7 +61,7 @@ namespace OpenSim.Framework.Servers if (p.Length > 0) { UUID assetID; - + if (!UUID.TryParse(p[0], out assetID)) { m_log.InfoFormat( diff --git a/OpenSim/Framework/Servers/HttpServer/AsynchronousRestObjectRequester.cs b/OpenSim/Framework/Servers/HttpServer/AsynchronousRestObjectRequester.cs index 9b44cc1031..76d0b6fe9d 100644 --- a/OpenSim/Framework/Servers/HttpServer/AsynchronousRestObjectRequester.cs +++ b/OpenSim/Framework/Servers/HttpServer/AsynchronousRestObjectRequester.cs @@ -28,18 +28,22 @@ using System; using System.IO; using System.Net; +using System.Reflection; using System.Text; using System.Xml; using System.Xml.Serialization; +using log4net; namespace OpenSim.Framework.Servers.HttpServer { public class AsynchronousRestObjectRequester { + //private static readonly ILog m_log = LogManager.GetLogger(MethodBase.GetCurrentMethod().DeclaringType); + /// /// Perform an asynchronous REST request. /// - /// + /// GET or POST /// /// /// @@ -52,6 +56,8 @@ namespace OpenSim.Framework.Servers.HttpServer public static void MakeRequest(string verb, string requestUrl, TRequest obj, Action action) { + //m_log.DebugFormat("[ASYNC REQUEST]: Starting {0} on {1}", verb, requestUrl); + Type type = typeof (TRequest); WebRequest request = WebRequest.Create(requestUrl); @@ -119,6 +125,8 @@ namespace OpenSim.Framework.Servers.HttpServer { } + // m_log.DebugFormat("[ASYNC REQUEST]: Received {0}", deserial.ToString()); + action(deserial); }, null); } diff --git a/OpenSim/Region/Application/OpenSimBase.cs b/OpenSim/Region/Application/OpenSimBase.cs index 8f3f3e8abc..a1d4b315d6 100644 --- a/OpenSim/Region/Application/OpenSimBase.cs +++ b/OpenSim/Region/Application/OpenSimBase.cs @@ -193,7 +193,6 @@ namespace OpenSim CreatePIDFile(pidFile); userStatsURI = startupConfig.GetString("Stats_URI", String.Empty); - } base.StartupSpecific(); diff --git a/OpenSim/Region/CoreModules/World/Archiver/AssetsArchiver.cs b/OpenSim/Region/CoreModules/World/Archiver/AssetsArchiver.cs index 6972188443..330fa3f019 100644 --- a/OpenSim/Region/CoreModules/World/Archiver/AssetsArchiver.cs +++ b/OpenSim/Region/CoreModules/World/Archiver/AssetsArchiver.cs @@ -147,7 +147,15 @@ namespace OpenSim.Region.CoreModules.World.Archiver //m_log.DebugFormat("[ARCHIVER]: Added asset {0}", m_assetsWritten); if (m_assetsWritten % LOG_ASSET_LOAD_NOTIFICATION_INTERVAL == 0) - m_log.InfoFormat("[ARCHIVER]: Added {0} assets to archive", m_assetsWritten); + m_log.InfoFormat("[ARCHIVER]: Added {0} assets to archive", m_assetsWritten); + } + + /// + /// Only call this if you need to force a close on the underlying writer. + /// + public void ForceClose() + { + m_archiveWriter.Close(); } } } diff --git a/OpenSim/Region/CoreModules/World/Archiver/AssetsRequest.cs b/OpenSim/Region/CoreModules/World/Archiver/AssetsRequest.cs index c459a66122..14804a4e33 100644 --- a/OpenSim/Region/CoreModules/World/Archiver/AssetsRequest.cs +++ b/OpenSim/Region/CoreModules/World/Archiver/AssetsRequest.cs @@ -29,6 +29,7 @@ using System; using System.Collections.Generic; using System.Reflection; using System.Threading; +using System.Timers; using log4net; using OpenMetaverse; using OpenSim.Framework; @@ -44,6 +45,37 @@ namespace OpenSim.Region.CoreModules.World.Archiver { private static readonly ILog m_log = LogManager.GetLogger(MethodBase.GetCurrentMethod().DeclaringType); + enum RequestState + { + Initial, + Running, + Completed, + Aborted + }; + + /// + /// Timeout threshold if we still need assets or missing asset notifications but have stopped receiving them + /// from the asset service + /// + protected const int TIMEOUT = 60 * 1000; + + /// + /// If a timeout does occur, limit the amount of UUID information put to the console. + /// + protected const int MAX_UUID_DISPLAY_ON_TIMEOUT = 3; + + protected System.Timers.Timer m_requestCallbackTimer; + + /// + /// State of this request + /// + private RequestState m_requestState = RequestState.Initial; + + /// + /// Record whether the request has completed. + /// + private bool m_requestCompleted; + /// /// uuids to request /// @@ -85,20 +117,92 @@ namespace OpenSim.Region.CoreModules.World.Archiver m_assetsRequestCallback = assetsRequestCallback; m_assetService = assetService; m_repliesRequired = uuids.Count; + + m_requestCallbackTimer = new System.Timers.Timer(TIMEOUT); + m_requestCallbackTimer.AutoReset = false; + m_requestCallbackTimer.Elapsed += new ElapsedEventHandler(OnRequestCallbackTimeout); } protected internal void Execute() { + m_requestState = RequestState.Running; + m_log.DebugFormat("[ARCHIVER]: AssetsRequest executed looking for {0} assets", m_repliesRequired); // We can stop here if there are no assets to fetch if (m_repliesRequired == 0) + { + m_requestState = RequestState.Completed; PerformAssetsRequestCallback(); + return; + } foreach (UUID uuid in m_uuids) { m_assetService.Get(uuid.ToString(), this, AssetRequestCallback); } + + m_requestCallbackTimer.Enabled = true; + } + + protected void OnRequestCallbackTimeout(object source, ElapsedEventArgs args) + { + try + { + lock (this) + { + // Take care of the possibilty that this thread started but was paused just outside the lock before + // the final request came in (assuming that such a thing is possible) + if (m_requestState == RequestState.Completed) + return; + + m_requestState = RequestState.Aborted; + } + + // Calculate which uuids were not found. This is an expensive way of doing it, but this is a failure + // case anyway. + List uuids = new List(); + foreach (UUID uuid in m_uuids) + { + uuids.Add(uuid); + } + + foreach (UUID uuid in m_foundAssetUuids) + { + uuids.Remove(uuid); + } + + foreach (UUID uuid in m_notFoundAssetUuids) + { + uuids.Remove(uuid); + } + + m_log.ErrorFormat( + "[ARCHIVER]: Asset service failed to return information about {0} requested assets", uuids.Count); + + int i = 0; + foreach (UUID uuid in uuids) + { + m_log.ErrorFormat("[ARCHIVER]: No information about asset {0} received", uuid); + + if (++i >= MAX_UUID_DISPLAY_ON_TIMEOUT) + break; + } + + if (uuids.Count > MAX_UUID_DISPLAY_ON_TIMEOUT) + m_log.ErrorFormat( + "[ARCHIVER]: (... {0} more not shown)", uuids.Count - MAX_UUID_DISPLAY_ON_TIMEOUT); + + m_log.Error("[ARCHIVER]: OAR save aborted."); + } + catch (Exception e) + { + m_log.ErrorFormat("[ARCHIVER]: Timeout handler exception {0}", e); + } + finally + { + m_assetsArchiver.ForceClose(); + } } /// @@ -114,6 +218,15 @@ namespace OpenSim.Region.CoreModules.World.Archiver { //m_log.DebugFormat("[ARCHIVER]: Received callback for asset {0}", id); + m_requestCallbackTimer.Stop(); + + if (m_requestState == RequestState.Aborted) + { + m_log.WarnFormat( + "[ARCHIVER]: Received information about asset {0} after archive save abortion. Ignoring.", + id); + } + if (asset != null) { m_foundAssetUuids.Add(asset.FullID); @@ -126,6 +239,8 @@ namespace OpenSim.Region.CoreModules.World.Archiver if (m_foundAssetUuids.Count + m_notFoundAssetUuids.Count == m_repliesRequired) { + m_requestState = RequestState.Completed; + m_log.DebugFormat( "[ARCHIVER]: Successfully added {0} assets ({1} assets notified missing)", m_foundAssetUuids.Count, m_notFoundAssetUuids.Count); @@ -136,6 +251,10 @@ namespace OpenSim.Region.CoreModules.World.Archiver newThread.Name = "OpenSimulator archiving thread post assets receipt"; newThread.Start(); } + else + { + m_requestCallbackTimer.Start(); + } } } catch (Exception e)