I have a deadlock problem on a WCF service and I cannot understand why since every calls are synchronized on the same lock. Here is my client / service configuration.
binding="netTcpBinding"
Service Config : ServiceBehavior(InstanceContextMode = InstanceContextMode.PerSession, ConcurrencyMode = ConcurrencyMode.Reentrant, UseSynchronizationContext = false)
Callback Config : CallbackBehavior(ConcurrencyMode = ConcurrencyMode.Reentrant, UseSynchronizationContext = false)
The code ( I 've simplified class and method names for clarification ):
interface ICallBack{
void OnDoAction(string info);
}
interface IMyService{
Report DoAction( string param);
}
public class MyClient:ICallBack{
void OnDoAction(string info){
Task.Factory.StartNew(() => {Console.WriteLine("Received info=["+info+"]"); });
}
Main(){
MyClient client = new MyClient();
InstanceContext context = new InstanceContext(client);
DuplexChannelFactory<IMyService> duplexChannelFactory = new DuplexChannelFactory<IMyService>(context, "MyService");
IMyService service = duplexChannelFactory.CreateChannel();
Report report = service.DoAction("Param1");
}
}
public class MyService:IMyService{
ICallback callback;
public MyService(){
callback = OperationContext.Current.GetCallbackChannel<ICallBack>();
}
public Report DoAction(){
lock(callback){
try{
Report r = null;
try{
Log("Do action");
r = executeAction();
}catch(Exception e){
r = new Report("Error in DoAction");
}
Log("Do action done");
return report;
}finally{
Log("Do action has returned");
}
}
}
public void CallbackAfterDoAction(string info){
lock(callback){
callback.OnDoAction(info);
}
}
}
The call back is called in a separate thread in asynchronous way.
When I call DoAction() method from my client, there is a deadlock and I have a TimeoutException:
2015-01-16 10:42:17,463 [8] ERROR - (OrderManagerViewModel.cs:311) - CancelOrder : System.TimeoutException: Cette op곡tion de demande envoyꥠet.tcp://localhost:8002/NetsOrderManagerServiceRemote/ n'a pas re赠de r걯nse dans le dꭡi imparti (00:00:05). Le temps allou顠 cette op곡tion fait peut-뵲e partie d'un dꭡi d'attente plus long. Ceci peut 뵲e d fait que le service est toujours en cours de traitement de l'op곡tion ou qu'il n'a pas pu envoyer un message de r걯nse. Envisagez d'augmenter le dꭡi d'attente de l'op곡tion (en diffusant le canal/proxy vers IContextChannel et en dꧩnissant la propri굩 OperationTimeout) et v곩fiez que le service peut se connecter au client.
Server stack trace:
ࡓystem.ServiceModel.Dispatcher.DuplexChannelBinder.SyncDuplexRequest.WaitForReply(TimeSpan timeout)
ࡓystem.ServiceModel.Dispatcher.DuplexChannelBinder.Request(Message message, TimeSpan timeout)
ࡓystem.ServiceModel.Channels.ServiceChannel.Call(String action, Boolean oneway, ProxyOperationRuntime operation, Object[] ins, Object[] outs, TimeSpan timeout)
ࡓystem.ServiceModel.Channels.ServiceChannel.Call(String action, Boolean oneway, ProxyOperationRuntime operation, Object[] ins, Object[] outs)
ࡓystem.ServiceModel.Channels.ServiceChannelProxy.InvokeService(IMethodCallMessage methodCall, ProxyOperationRuntime operation)
ࡓystem.ServiceModel.Channels.ServiceChannelProxy.Invoke(IMessage message)Exception rethrown at [0]:
ࡓystem.Runtime.Remoting.Proxies.RealProxy.HandleReturnMessage(IMessage reqMsg, IMessage retMsg)
ࡓystem.Runtime.Remoting.Proxies.RealProxy.PrivateInvoke(MessageData& msgData, Int32 type)
ࡎets.Core.API.OrderManager.Service.IOrderManager.CancelOrder(ICancelOrderRequest cancelRequest)
ࡎets.Core.Client.Wcf.OrderServiceWcfClient.RemoteOrderManagerServiceProxy.CancelOrder(ICancelOrderRequest cancelRequest) dans c:\dev\GitProjects\NetsCoreLibProject\NetsCoreLib\Nets.Core.Client.Wcf.OrderServiceWcfClient\RemoteOrderManagerServiceProxy.cs:ligne 340
ࡎets.Core.Prototype.Client.ViewModels.OrderManagerViewModels.OrderManagerViewModel.CancelOrder(Object parameter) dans c:\dev\GitProjects\NetsCoreLibProject\NetsCoreLib\Nets.Core.Prototype.Client\ViewModels\OrderManagerViewModels\OrderManagerViewModel.cs:ligne 302
The server log below show that DoAction() return before Callback execution.
Do action call log:
2015-01-16 11:13:57,342 [27] INFO - (RemoteOrderManagerService.cs:195) - CancelOrder : RemoteOrderService : CancelOrder action called by server 2015-01-16 11:13:57,342 [27] INFO - (RemoteOrderManagerService.cs:203) - CancelOrder : RemoteOrderService : CancelOrder action return report=[CancelOrder report netsd2dce|Failed to validate filter Order Consistency Check 2015-01-16 11:13:57,342 [27] INFO - (RemoteOrderManagerService.cs:208) - CancelOrder : RemoteOrderService : CancelOrder action return done
CallbackAfterDoAction call log:
2015-01-16 11:13:57,342 [EventQueue-ThreadDispatcher-HighPriorityEventQueue-2] INFO - (OrderManagerService.cs:451) - DispatchErrorOnOrder : Dispatch error on order NetsOrderId[netsd2dce] 2015-01-16 11:13:57,342 [EventQueue-ThreadDispatcher-HighPriorityEventQueue-2] INFO - (Order.cs:760) - OnCancelAck : OnCancelAck[[Order #ob_,ba3 (netsd2dce) BUY 1 [TOTF.PA] @ 47]|Owner=[]]: Cannot execute request=[CANCEL] cause Order=[[Order #ob_,ba3 (netsd2dce) BUY 1 [TOTF.PA] @ 47]|Owner=[]] is in final state=[CANCELLED] 2015-01-16 11:13:57,343 [EventQueue-ThreadDispatcher-HighPriorityEventQueue-2] INFO - (Order.cs:765) - OnCancelAck : OnCancelAck[[Order #ob_,ba3 (netsd2dce) BUY 1 [TOTF.PA] @ 47]|Owner=[]]: Call from Nets.Core.Service.Remote.RemoteOrderManagerService
BUT: When I comment the callback call on the service, the DoAction() method execute properly. It acts as if callback was called before DoAction method return when deadlock occures. I don't understand what happen since every method called are synchronized on the same lock.
PS: if I add a sleep before callback calling :
public void CallbackAfterDoAction(){
lock(callback){
Thread.Sleep(3);
callback.OnDoAction();
}
}
The deadlock never occures until Sleep(3) but for value < 3 ms the deadlock occures. ==> So the question is why the callback is processed before the return statement of the DoAction() method while the logs say the opposite?
