Merge pull request #455 from Cyberboss/FixLockup

Deadlock investigation

TGS.Interface/Components/Interop.cs

@@ -12,7 +12,7 @@ namespace TGS.Interface.Components
 		/// Called from /world/ExportService(command)
 		/// </summary>
 		/// <param name="command">The command to run</param>
-		/// <returns><see langword="true"/> on success, <see langword="false"/> on failure</returns>
+		/// <returns><see langword="true"/></returns>
 		[OperationContract]
 		bool InteropMessage(string command);
 	}

TGS.Server/CallLogger.cs

@@ -0,0 +1,61 @@
+using System;
+using System.Collections.Generic;
+using System.ServiceModel.Channels;
+using System.ServiceModel.Description;
+using System.ServiceModel.Dispatcher;
+
+namespace TGS.Server
+{
+	sealed class AddCallLoggerBehavior : IOperationBehavior
+	{
+		public void AddBindingParameters(OperationDescription operationDescription, BindingParameterCollection bindingParameters)
+		{
+		}
+
+		public void ApplyClientBehavior(OperationDescription operationDescription, ClientOperation clientOperation)
+		{
+			clientOperation.ClientParameterInspectors.Add(new CallLogger());
+		}
+
+		public void ApplyDispatchBehavior(OperationDescription operationDescription, DispatchOperation dispatchOperation)
+		{
+			dispatchOperation.ParameterInspectors.Add(new CallLogger());
+		}
+
+		public void Validate(OperationDescription operationDescription)
+		{
+		}
+	}
+	sealed class CallLogger : IParameterInspector
+	{
+		static readonly IDictionary<string, int> ActiveCalls = new Dictionary<string, int>();
+
+		public void AfterCall(string operationName, object[] outputs, object returnValue, object correlationState)
+		{
+			lock (ActiveCalls)
+				--ActiveCalls[operationName];
+		}
+
+		public object BeforeCall(string operationName, object[] inputs)
+		{
+			lock (ActiveCalls)
+			{
+				string res = String.Empty;
+				foreach (var I in ActiveCalls)
+				{
+					if (I.Value > 0)
+						res += Environment.NewLine + I.Key + ": " + I.Value;
+				}
+				if (res != String.Empty)
+				{
+					res = String.Format("Starting call {0}. Warning: other calls in progress!{1}", operationName, res);
+					Server.Logger.WriteInfo(res, EventID.CallTracking, 0);
+				}
+				if (!ActiveCalls.ContainsKey(operationName))
+					ActiveCalls.Add(operationName, 0);
+				++ActiveCalls[operationName];
+				return null;
+			}
+		}
+	}
+}

TGS.Server/EventID.cs

@@ -331,5 +331,9 @@ namespace TGS.Server
 		/// Warning: When a testmerge commit failed to be published
 		/// </summary>
 		ReferencePush = 7700,
+		/// <summary>
+		/// Info: When a call starts and another call hasn't completed
+		/// </summary>
+		CallTracking = 7800,
 	}
 }

TGS.Server/Instance/Instance.cs

@@ -1,7 +1,7 @@
 using System;
-using System.Diagnostics;
 using System.IO;
 using System.ServiceModel;
+using System.Threading;
 using TGS.Interface.Components;
 
 namespace TGS.Server
@@ -104,6 +104,23 @@ namespace TGS.Server
 			return Path.Combine(Config.Directory, path);
 		}
 
+		/// <summary>
+		/// Dumps the status of all locks in the <see cref="Instance"/>
+		/// </summary>
+		public void DumpLocks()
+		{
+			var res = Monitor.TryEnter(RepoLock);
+			string rb;
+			if (res)
+			{
+				rb = RepoBusy.ToString();
+				Monitor.Exit(RepoLock);
+			}
+			else
+				rb = "UNKNOWN";
+			Server.Logger.WriteWarning(String.Format("Started HandleCommand with others running! Active locks: Repo: {0}, Byond: {1}, Compiler: {2}, Topic: {3}, Config: {4}, Watchdog: {5}, Chat: {6}, this: {7}, restartLock: {8}, autoUpdateLock: {9}, RepoBusy: {10}", !res, CheckLocked(ByondLock), CheckLocked(CompilerLock), CheckLocked(topicLock), CheckLocked(configLock), CheckLocked(watchdogLock), CheckLocked(ChatLock), CheckLocked(this), CheckLocked(restartLock), CheckLocked(autoUpdateTimer), rb), EventID.CallTracking, LoggingID);
+		}
+
 		/// <inheritdoc />
 		public string Version()
 		{

TGS.Server/Instance/Interop.cs

@@ -6,6 +6,7 @@ using System.Net;
 using System.Net.Sockets;
 using System.Text;
 using System.Threading;
+using System.Threading.Tasks;
 using System.Web.Security;
 using TGS.Server.ChatCommands;
 using TGS.Interface;
@@ -16,7 +17,6 @@ namespace TGS.Server
 	//handles talking between the world and us
 	sealed partial class Instance : ITGInterop
 	{
-
 		object topicLock = new object();
 		const int CommsKeyLen = 64;
 		string serviceCommsKey; //regenerated every DD restart
@@ -65,6 +65,8 @@ namespace TGS.Server
 
 		List<Command> ServerChatCommands;
 
+		int RunningCommandHandlers = 0;
+
 		void LoadServerChatCommands()
 		{
 			if (DaemonStatus() != DreamDaemonStatus.Online)
@@ -88,71 +90,91 @@ namespace TGS.Server
 			catch { }
 		}
 
-		//raw command string sent here via world.ExportService
-		void HandleCommand(string cmd)
+		static bool CheckLocked(object o)
 		{
-			var splits = new List<string>(cmd.Split(' '));
-			cmd = splits[0];
-			splits.RemoveAt(0);
+			var res = Monitor.TryEnter(o);
+			if (res)
+				Monitor.Exit(o);
+			return !res;
+		}
 
-			bool APIValid;
-			lock (topicLock)
+		//raw command string sent here via world.ExportService
+		Task HandleCommand(string cmd)
+		{
+			return Task.Run(() =>
 			{
-				APIValid = CheckAPIVersionConstraints();
-			}
+				if (Interlocked.Increment(ref RunningCommandHandlers) > 1)
+					DumpLocks();
+				try
+				{
+					var splits = new List<string>(cmd.Split(' '));
+					cmd = splits[0];
+					splits.RemoveAt(0);
 
-			if (!APIValid && cmd != SRAPIVersion)
-				return;	//SPEAK THE LANGUAGE!!!
-
-			switch (cmd)
-			{
-				case SRIRCBroadcast:
-					SendMessage("GAME: " + String.Join(" ", splits), MessageType.GameInfo);
-					break;
-				case SRKillProcess:
-					KillMe();
-					break;
-				case SRIRCAdminChannelMessage:
-					SendMessage("RELAY: " + String.Join(" ", splits), MessageType.AdminInfo);
-					break;
-				case SRWorldReboot:
-					WriteInfo("World Rebooted", EventID.WorldReboot);
-					WriteCurrentDDLog("World rebooted");
-					ServerChatCommands = null;
-					ChatConnectivityCheck();
-					lock (CompilerLock)
-					{
-						if (UpdateStaged)
-						{
-							UpdateStaged = false;
-							lock (topicLock)
-							{
-								GameAPIVersion = null;  //needs updating
-							}
-							WriteInfo("Staged update applied", EventID.ServerUpdateApplied);
-						}
-					}
-					break;
-				case SRAPIVersion:
+					bool APIValid;
 					lock (topicLock)
 					{
-						try
-						{
-							GameAPIVersion = new Version(splits[0]);
-							if (!CheckAPIVersionConstraints())
-								throw new Exception();
-						}
-						catch
-						{
-							WriteWarning(String.Format("API version of the game ({0}) is incompatible with the current supported API versions (3.{2}.x.x). Interop disabled.", splits.Count > 1 ? splits[1] : "NULL", AllowedMajorAPIVersion), EventID.APIVersionMismatch);
-							GameAPIVersion = null;
-							break;
-						}
+						APIValid = CheckAPIVersionConstraints();
 					}
-					//This needs to be done asyncronously otherwise DD won't be able to process it, because it's waiting for THIS THREAD to return
-					ThreadPool.QueueUserWorkItem(_ => SendCommand(SCAPICompat));
-					break;
-			}
+
+					if (!APIValid && cmd != SRAPIVersion)
+						return; //SPEAK THE LANGUAGE!!!
+
+					switch (cmd)
+					{
+						case SRIRCBroadcast:
+							SendMessage("GAME: " + String.Join(" ", splits), MessageType.GameInfo);
+							break;
+						case SRKillProcess:
+							KillMe();
+							break;
+						case SRIRCAdminChannelMessage:
+							SendMessage("RELAY: " + String.Join(" ", splits), MessageType.AdminInfo);
+							break;
+						case SRWorldReboot:
+							WriteInfo("World Rebooted", EventID.WorldReboot);
+							WriteCurrentDDLog("World rebooted");
+							ServerChatCommands = null;
+							ChatConnectivityCheck();
+							lock (CompilerLock)
+							{
+								if (UpdateStaged)
+								{
+									UpdateStaged = false;
+									lock (topicLock)
+									{
+										GameAPIVersion = null;  //needs updating
+									}
+									WriteInfo("Staged update applied", EventID.ServerUpdateApplied);
+								}
+							}
+							break;
+						case SRAPIVersion:
+							lock (topicLock)
+							{
+								try
+								{
+									GameAPIVersion = new Version(splits[0]);
+									if (!CheckAPIVersionConstraints())
+										throw new Exception();
+								}
+								catch
+								{
+									WriteWarning(String.Format("API version of the game ({0}) is incompatible with the current supported API versions (3.{2}.x.x). Interop disabled.", splits.Count > 1 ? splits[1] : "NULL", AllowedMajorAPIVersion), EventID.APIVersionMismatch);
+									GameAPIVersion = null;
+									break;
+								}
+							}
+							//This needs to be done asyncronously otherwise DD won't be able to process it, because it's waiting for THIS THREAD to return
+							ThreadPool.QueueUserWorkItem(_ => SendCommand(SCAPICompat));
+							break;
+					}
+				}
+				finally
+				{
+					Interlocked.Decrement(ref RunningCommandHandlers);
+				}
+			});
 		}
 
 		public string SendCommand(string cmd)
@@ -261,16 +283,11 @@ namespace TGS.Server
 		/// <inheritdoc />
 		public bool InteropMessage(string command)
 		{
-			try
+			HandleCommand(command).ContinueWith((t) =>
 			{
-				HandleCommand(command);
-				return true;
-			}
-			catch(Exception e)
-			{
-				WriteWarning(String.Format("Handle command for \"{0}\" failed: {1}", command, e.ToString()), EventID.InteropCallException);
-				return false;
-			}
+				WriteWarning(String.Format("Handle command for \"{0}\" failed: {1}", command, t.Exception.ToString()), EventID.InteropCallException);
+			}, TaskContinuationOptions.OnlyOnFaulted);
+			return true;
 		}
 	}
 }

TGS.Server/Server.cs

@@ -4,6 +4,7 @@ using System.IO;
 using System.Reflection;
 using System.Security.Principal;
 using System.ServiceModel;
+using System.ServiceModel.Description;
 using TGS.Interface;
 using TGS.Interface.Components;
 using TGS.Server.Security;
@@ -342,7 +343,9 @@ namespace TGS.Server
 		void AddEndpoint(ServiceHost host, Type typetype)
 		{
 			var bindingName = typetype.Name;
-			host.AddServiceEndpoint(typetype, new NetNamedPipeBinding() { SendTimeout = new TimeSpan(0, 0, 30), MaxReceivedMessageSize = Definitions.TransferLimitLocal }, bindingName);
+			var endpint = host.AddServiceEndpoint(typetype, new NetNamedPipeBinding() { SendTimeout = new TimeSpan(0, 0, 30), MaxReceivedMessageSize = Definitions.TransferLimitLocal }, bindingName);
+			foreach (OperationDescription od in endpint.Contract.Operations)
+				od.OperationBehaviors.Add(new AddCallLoggerBehavior());
 			var httpsBinding = new BasicHttpsBinding()
 			{
 				SendTimeout = new TimeSpan(0, 0, 40),

TGS.Server/TGS.Server.csproj

@@ -81,6 +81,7 @@
     <Reference Include="System.Web" />
   </ItemGroup>
   <ItemGroup>
+    <Compile Include="CallLogger.cs" />
     <Compile Include="Security\AuthenticationHeaderDecoder.cs" />
     <Compile Include="ChatCommands\ByondCommand.cs" />
     <Compile Include="ChatCommands\CommandInfo.cs" />