time-outs and connectivity issues

[2mike2]

Hi Guys,
We are running azure deployed cluster 1.0.8 of 3 medium size workers (silos) and 15-25 web role clients, sharing virtual network for almost 3 months. Orleans fits beautifully one of our multiplayer subsystems and we enjoy it very much. Last two days we've started to experience massive timeouts of client calls to silos (client response timeout is 5 sec) as well as many dropped connections within internal silos messaging (silo response timeout 180 sec ). The timeouts are not persistent, occurring periodically each 5-7 minutes and lasting for 1-2 minutes. We haven't found time correlation with any pattern of our load peaks / concurrent users. I am attaching below some example of silo and client log entries I see a lot during the outage occurrences. Are you guys familiar with such symptoms and can recommend on the cure? Thank you.

Silo logs example:

[2015-11-03 17:39:00.562 GMT 37 WARNING 101022 Runtime.Messaging.SiloMessageSender.AppMsgsSender_1/3 10.0.0.6:11111] Exception sending message to S10.0.0.5:11111:184264313. Message: Request S10.0.0.6:11111:184263639_cli/1aba9a90@fa5bc7ae->S10.0.0.5:11111:184264313_grn/22B298E/006565ec@cdd199b4 #18976: Tournaments.Grains.Interfaces.Tournaments.Grains.Interfaces.ITournamentPlayerGrain:UpdateScore(). System.Net.Sockets.SocketException (0x80004005): An existing connection was forcibly closed by the remote host
at Orleans.Messaging.OutgoingMessageSender.Process(Message msg)
Exc level 0: System.Net.Sockets.SocketException: An existing connection was forcibly closed by the remote host
at Orleans.Messaging.OutgoingMessageSender.Process(Message msg)
[2015-11-03 17:39:00.562 GMT 27 WARNING 101022 Runtime.Messaging.SiloMessageSender.SystemSender/2 10.0.0.6:11111] Exception sending message to S10.0.0.5:11111:184264313. Message: Request S10.0.0.6:11111:184263639Catalog@S0000000e->S10.0.0.5:11111:184264313DirectoryService@S0000000a #207423: Orleans.Runtime.Orleans.Runtime.IRemoteGrainDirectory:LookUp(). System.Net.Sockets.SocketException (0x80004005): An existing connection was forcibly closed by the remote host
at Orleans.Messaging.OutgoingMessageSender.Process(Message msg)
Exc level 0: System.Net.Sockets.SocketException: An existing connection was forcibly closed by the remote host
at Orleans.Messaging.OutgoingMessageSender.Process(Message msg)
[2015-11-03 17:39:00.562 GMT 24 WARNING 101529 Dispatcher 10.0.0.6:11111] Dropping an expired message: Transient Rejection (info: Silo S10.0.0.6:11111:184263639 is rejecting message: Request S10.0.0.6:11111:184263639_cli/1aba9a90@fa5bc7ae->S10.0.0.5:11111:184264313_grn/22B298E/006565ec@cdd199b4 #18976: Tournaments.Grains.Interfaces.Tournaments.Grains.Interfaces.ITournamentPlayerGrain:UpdateScore(). Reason = Retry count exceeded. Msg is: Request S10.0.0.6:11111:184263639_cli/1aba9a90@fa5bc7ae->S10.0.0.5:11111:184264313_grn/22B298E/006565ec@cdd199b4 #18976: Tournaments.Grains.Interfaces.Tournaments.Grains.Interfaces.ITournamentPlayerGrain:UpdateScore()) Response S10.0.0.5:11111:184264313_grn/22B298E/006565ec@cdd199b4->S10.0.0.6:11111:184263639_cli/1aba9a90@fa5bc7ae #18976: Tournaments.Grains.Interfaces.Tournaments.Grains.Interfaces.ITournamentPlayerGrain:UpdateScore()
[2015-11-03 17:39:00.562 GMT 125 ERROR 100071 Dispatcher 10.0.0.6:11111] !!!!!!!!!! SelectTarget failed with One or more errors occurred.
Exc level 0: System.AggregateException: One or more errors occurred.
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at Orleans.Runtime.GrainReference.d__01.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task) at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at System.Runtime.CompilerServices.TaskAwaiter1.GetResult()
at Orleans.Runtime.GrainDirectory.LocalGrainDirectory.d__60.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at Orleans.Runtime.Scheduler.SchedulerExtensions.<>c__DisplayClass21.<<QueueTask>b__0>d__4.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task) at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at Orleans.Runtime.Placement.RandomPlacementDirector.<OnSelectActivation>d__3.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task) at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at System.Runtime.CompilerServices.TaskAwaiter1.GetResult()
at Orleans.Runtime.Placement.PlacementDirectorsManager.d__0.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at System.Runtime.CompilerServices.TaskAwaiter1.GetResult() at Orleans.Runtime.Dispatcher.<AddressMessage>d__17.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task) at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at Orleans.Runtime.Dispatcher.<AsyncSendMessage>d__14.MoveNext() Exc level 1: Orleans.Runtime.OrleansException: Silo S10.0.0.6:11111:184263639 is rejecting message: Request S10.0.0.6:11111:184263639Catalog@S0000000e->S10.0.0.5:11111:184264313DirectoryService@S0000000a #207423: Orleans.Runtime.Orleans.Runtime.IRemoteGrainDirectory:LookUp(). Reason = Retry count exceeded. Msg is: Request S10.0.0.6:11111:184263639Catalog@S0000000e->S10.0.0.5:11111:184264313DirectoryService@S0000000a #207423: Orleans.Runtime.Orleans.Runtime.IRemoteGrainDirectory:LookUp() [2015-11-03 17:39:05.843 GMT 72 WARNING 101024 Runtime.Messaging.GatewayAcceptor/1 10.0.0.6:11111] Exception while completing a receive from 10.0.0.25:49380 Exc level 0: System.Net.Sockets.SocketException: A connection attempt failed because the connected party did not properly respond after a period of time, or established connection failed because connected host has failed to respond at Orleans.Runtime.Messaging.IncomingMessageAcceptor.ReceiveCallback(IAsyncResult result) [2015-11-03 17:39:05.843 GMT 72 INFO 101302 Orleans.Messaging.Gateway 10.0.0.6:11111] Recorded closed socket from endpoint 10.0.0.25:49380, client ID *cli/9125368a. [2015-11-03 17:39:21.568 GMT 37 WARNING 101021 Runtime.Messaging.SiloMessageSender.AppMsgsSender_1/3 10.0.0.6:11111] Exception getting a sending socket to endpoint S10.0.0.5:11111:184264313 Exc level 0: System.Net.Sockets.SocketException: A connection attempt failed because the connected party did not properly respond after a period of time, or established connection failed because connected host has failed to respond 10.0.0.5:11111 at System.Net.Sockets.Socket.DoConnect(EndPoint endPointSnapshot, SocketAddress socketAddress) at System.Net.Sockets.Socket.Connect(EndPoint remoteEP) at Orleans.Runtime.SocketManager.SendingSocketCreator(IPEndPoint target) at Orleans.Runtime.LRU2.Get(TKey key)
at Orleans.Runtime.Messaging.SiloMessageSender.GetSendingSocket(Message msg, Socket& socket, SiloAddress& targetSilo, String& error)
[2015-11-03 17:39:21.568 GMT 27 WARNING 101021 Runtime.Messaging.SiloMessageSender.SystemSender/2 10.0.0.6:11111] Exception getting a sending socket to endpoint S10.0.0.5:11111:184264313
Exc level 0: System.Net.Sockets.SocketException: A connection attempt failed because the connected party did not properly respond after a period of time, or established connection failed because connected host has failed to respond 10.0.0.5:11111
at System.Net.Sockets.Socket.DoConnect(EndPoint endPointSnapshot, SocketAddress socketAddress)
at System.Net.Sockets.Socket.Connect(EndPoint remoteEP)
at Orleans.Runtime.SocketManager.SendingSocketCreator(IPEndPoint target)
at Orleans.Runtime.LRU2.Get(TKey key) at Orleans.Runtime.Messaging.SiloMessageSender.GetSendingSocket(Message msg, Socket& socket, SiloAddress& targetSilo, String& error) [2015-11-03 17:39:21.584 GMT 24 ERROR 101317 ClientObserverRegistrar 10.0.0.6:11111] !!!!!!!!!! Directory.RegisterAsync S10.0.0.6:11111:184263639*cli/8f30a19f@8f30a19f failed. Exc level 0: System.AggregateException: One or more errors occurred. at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task) at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at Orleans.Runtime.GrainReference.<InvokeMethodAsync>d__01.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at Orleans.Runtime.GrainDirectory.LocalGrainDirectory.d__49.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at Orleans.OrleansTaskExtentions.d__0.MoveNext()
Exc level 1: Orleans.Runtime.OrleansException: Silo S10.0.0.6:11111:184263639 is rejecting message: Request S10.0.0.6:11111:184263639ClientObserverRegistrar@S0000000d->S10.0.0.5:11111:184264313DirectoryService@S0000000a #208597: Orleans.Runtime.Orleans.Runtime.IRemoteGrainDirectory:Register(). Reason = Recent (00:00:00.0155819 ago, at 2015-11-03 17:39:21.568 GMT) connection failure trying to reach target silo S10.0.0.5:11111:184264313. Going to drop Request msg 208597 without sending. CONNECTION_RETRY_DELAY = 00:00:01.
[2015-11-03 17:39:21.584 GMT 24 ERROR 101317 ClientObserverRegistrar 10.0.0.6:11111] !!!!!!!!!! Directory.RegisterAsync S10.0.0.6:11111:184263639_cli/a5b476ab@a5b476ab failed.
Exc level 0: System.AggregateException: One or more errors occurred.
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at Orleans.Runtime.GrainReference.d__01.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task) at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at Orleans.Runtime.GrainDirectory.LocalGrainDirectory.<RegisterAsync>d__49.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task) at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at Orleans.OrleansTaskExtentions.<LogException>d__0.MoveNext() Exc level 1: Orleans.Runtime.OrleansException: Silo S10.0.0.6:11111:184263639 is rejecting message: Request S10.0.0.6:11111:184263639ClientObserverRegistrar@S0000000d->S10.0.0.5:11111:184264313DirectoryService@S0000000a #208598: Orleans.Runtime.Orleans.Runtime.IRemoteGrainDirectory:Register(). Reason = Recent (00:00:00.0155819 ago, at 2015-11-03 17:39:21.568 GMT) connection failure trying to reach target silo S10.0.0.5:11111:184264313. Going to drop Request msg 208598 without sending. CONNECTION_RETRY_DELAY = 00:00:01. [2015-11-03 17:39:21.584 GMT 24 WARNING 101529 Dispatcher 10.0.0.6:11111] Dropping an expired message: Transient Rejection (info: Silo S10.0.0.6:11111:184263639 is rejecting message: Request S10.0.0.6:11111:184263639_cli/07575093@ef6f0d99->S10.0.0.5:11111:184264313_grn/22B298E/0031f3d4@a3440abf #25491: Tournaments.Grains.Interfaces.Tournaments.Grains.Interfaces.ITournamentPlayerGrain:UpdateScore(). Reason = Exception getting a sending socket to endpoint S10.0.0.5:11111:184264313) Response S10.0.0.5:11111:184264313_grn/22B298E/0031f3d4@a3440abf->S10.0.0.6:11111:184263639_cli/07575093@ef6f0d99 #25491: Tournaments.Grains.Interfaces.Tournaments.Grains.Interfaces.ITournamentPlayerGrain:UpdateScore() [2015-11-03 17:39:21.584 GMT 24 WARNING 100147 Dispatcher 10.0.0.6:11111] Intermediate warning for NonExistentActivation from Catalog.GetOrCreateActivation for message Transient Rejection (info: Silo S10.0.0.6:11111:184263639 is rejecting message: Request S10.0.0.6:11111:184263639_cli/40b1fab8@f3b709aa->S10.0.0.5:11111:184264313_grn/22B298E/0088d0fb@309cd1aa #26898: Tournaments.Grains.Interfaces.Tournaments.Grains.Interfaces.ITournamentPlayerGrain:GetGameZoneTournament(). Reason = Recent (00:00:00 ago, at 2015-11-03 17:39:21.568 GMT) connection failure trying to reach target silo S10.0.0.5:11111:184264313. Going to drop Request msg 26898 without sending. CONNECTION_RETRY_DELAY = 00:00:01.) Response S10.0.0.5:11111:184264313_grn/22B298E/0088d0fb@309cd1aa->S10.0.0.6:11111:184263639_cli/40b1fab8@f3b709aa #26898: Tournaments.Grains.Interfaces.Tournaments.Grains.Interfaces.ITournamentPlayerGrain:GetGameZoneTournament() Exc level 0: Orleans.Runtime.Catalog+NonExistentActivationException: Non-existent activation: [ActivationAddress: S10.0.0.6:11111:184263639_cli/40b1fab8@f3b709aa, Full GrainId: [GrainId: _cli/4541ceac63a668551550501f40b1fab80400000000000000-0x9DD68BE8, IdCategory: Client, BaseTypeCode: 0 (x0), PrimaryKey: 63a66855-ceac-4541-b8fa-b1401f505015 (x{0x63a66855,0xceac,0x4541,{0xb8,0xfa,0xb1,0x40,0x1f,0x50,0x50,0x15}}), UniformHashCode: 2648083432 (0x9DD68BE8)], Full ActivationId: @41cbe5f8dd1ffe39ae4fb5def3b709aa0000000000000000], grain type: . at Orleans.Runtime.Catalog.GetOrCreateActivation(ActivationAddress address, Boolean newPlacement, String grainType, String genericArguments, Task& activatedPromise) at Orleans.Runtime.Dispatcher.ReceiveMessage(Message message) [2015-11-03 17:39:21.584 GMT 24 WARNING 100148 Dispatcher 10.0.0.6:11111] No target activation S10.0.0.6:11111:184263639_cli/40b1fab8@f3b709aa for response message: Transient Rejection (info: Silo S10.0.0.6:11111:184263639 is rejecting message: Request S10.0.0.6:11111:184263639_cli/40b1fab8@f3b709aa->S10.0.0.5:11111:184264313_grn/22B298E/0088d0fb@309cd1aa #26898: Tournaments.Grains.Interfaces.Tournaments.Grains.Interfaces.ITournamentPlayerGrain:GetGameZoneTournament(). Reason = Recent (00:00:00 ago, at 2015-11-03 17:39:21.568 GMT) connection failure trying to reach target silo S10.0.0.5:11111:184264313. Going to drop Request msg 26898 without sending. CONNECTION_RETRY_DELAY = 00:00:01.) Response S10.0.0.5:11111:184264313_grn/22B298E/0088d0fb@309cd1aa->S10.0.0.6:11111:184263639_cli/40b1fab8@f3b709aa #26898: Tournaments.Grains.Interfaces.Tournaments.Grains.Interfaces.ITournamentPlayerGrain:GetGameZoneTournament() [2015-11-03 17:39:21.600 GMT 24 WARNING 100147 Dispatcher 10.0.0.6:11111] Intermediate warning for NonExistentActivation from Catalog.GetOrCreateActivation for message Transient Rejection (info: Silo S10.0.0.6:11111:184263639 is rejecting message: Request S10.0.0.6:11111:184263639_cli/e7a87c96@42f6818b->S10.0.0.5:11111:184264313_grn/22B298E/000e9933@0c2de495 #23243: Tournaments.Grains.Interfaces.Tournaments.Grains.Interfaces.ITournamentPlayerGrain:UpdateScore(). Reason = Recent (00:00:00 ago, at 2015-11-03 17:39:21.568 GMT) connection failure trying to reach target silo S10.0.0.5:11111:184264313. Going to drop Request msg 23243 without sending. CONNECTION_RETRY_DELAY = 00:00:01.) Response S10.0.0.5:11111:184264313_grn/22B298E/000e9933@0c2de495->S10.0.0.6:11111:184263639_cli/e7a87c96@42f6818b #23243: Tournaments.Grains.Interfaces.Tournaments.Grains.Interfaces.ITournamentPlayerGrain:UpdateScore() Exc level 0: Orleans.Runtime.Catalog+NonExistentActivationException: Non-existent activation: [ActivationAddress: S10.0.0.6:11111:184263639_cli/e7a87c96@42f6818b, Full GrainId: [GrainId: *cli/46b19a8ca537d34515cf6653e7a87c960400000000000000-0x77DA701C, IdCategory: Client, BaseTypeCode: 0 (x0), PrimaryKey: a537d345-9a8c-46b1-967c-a8e75366cf15 (x{0xa537d345,0x9a8c,0x46b1,{0x96,0x7c,0xa8,0xe7,0x53,0x66,0xcf,0x15}}), UniformHashCode: 2010804252 (0x77DA701C)], Full ActivationId: @42be5db9e4973cf8a666f86a42f6818b0000000000000000], grain type: . at Orleans.Runtime.Catalog.GetOrCreateActivation(ActivationAddress address, Boolean newPlacement, String grainType, String genericArguments, Task& activatedPromise) at Orleans.Runtime.Dispatcher.ReceiveMessage(Message message) [2015-11-03 17:39:21.600 GMT 24 WARNING 100148 Dispatcher 10.0.0.6:11111] No target activation S10.0.0.6:11111:184263639_cli/e7a87c96@42f6818b for response message: Transient Rejection (info: Silo S10.0.0.6:11111:184263639 is rejecting message: Request S10.0.0.6:11111:184263639_cli/e7a87c96@42f6818b->S10.0.0.5:11111:184264313_grn/22B298E/000e9933@0c2de495 #23243: Tournaments.Grains.Interfaces.Tournaments.Grains.Interfaces.ITournamentPlayerGrain:UpdateScore(). Reason = Recent (00:00:00 ago, at 2015-11-03 17:39:21.568 GMT) connection failure trying to reach target silo S10.0.0.5:11111:184264313. Going to drop Request msg 23243 without sending. CONNECTION_RETRY_DELAY = 00:00:01.) Response S10.0.0.5:11111:184264313_grn/22B298E/000e9933@0c2de495->S10.0.0.6:11111:184263639_cli/e7a87c96@42f6818b #23243: Tournaments.Grains.Interfaces.Tournaments.Grains.Interfaces.ITournamentPlayerGrain:UpdateScore() [2015-11-03 17:39:21.600 GMT 24 WARNING 100147 Dispatcher 10.0.0.6:11111] Intermediate warning for NonExistentActivation from Catalog.GetOrCreateActivation for message Transient Rejection (info: Silo S10.0.0.6:11111:184263639 is rejecting message: Request S10.0.0.6:11111:184263639_cli/40b1fab8@f3b709aa->S10.0.0.5:11111:184264313_grn/22B298E/007cb3e7@2313dcbc #26901: Tournaments.Grains.Interfaces.Tournaments.Grains.Interfaces.ITournamentPlayerGrain:GetGameZoneTournament(). Reason = Recent (00:00:00 ago, at 2015-11-03 17:39:21.568 GMT) connection failure trying to reach target silo S10.0.0.5:11111:184264313. Going to drop Request msg 26901 without sending. CONNECTION_RETRY_DELAY = 00:00:01.) Response S10.0.0.5:11111:184264313_grn/22B298E/007cb3e7@2313dcbc->S10.0.0.6:11111:184263639_cli/40b1fab8@f3b709aa #26901: Tournaments.Grains.Interfaces.Tournaments.Grains.Interfaces.ITournamentPlayerGrain:GetGameZoneTournament() Exc level 0: Orleans.Runtime.Catalog+NonExistentActivationException: Non-existent activation: [ActivationAddress: S10.0.0.6:11111:184263639_cli/40b1fab8@f3b709aa, Full GrainId: [GrainId: *cli/4541ceac63a668551550501f40b1fab80400000000000000-0x9DD68BE8, IdCategory: Client, BaseTypeCode: 0 (x0), PrimaryKey: 63a66855-ceac-4541-b8fa-b1401f505015 (x{0x63a66855,0xceac,0x4541,{0xb8,0xfa,0xb1,0x40,0x1f,0x50,0x50,0x15}}), UniformHashCode: 2648083432 (0x9DD68BE8)], Full ActivationId: @41cbe5f8dd1ffe39ae4fb5def3b709aa0000000000000000], grain type: . at Orleans.Runtime.Catalog.GetOrCreateActivation(ActivationAddress address, Boolean newPlacement, String grainType, String genericArguments, Task& activatedPromise) at Orleans.Runtime.Dispatcher.ReceiveMessage(Message message) [2015-11-03 17:39:21.600 GMT 24 WARNING 100148 Dispatcher 10.0.0.6:11111] No target activation S10.0.0.6:11111:184263639_cli/40b1fab8@f3b709aa for response message: Transient Rejection (info: Silo S10.0.0.6:11111:184263639 is rejecting message: Request S10.0.0.6:11111:184263639_cli/40b1fab8@f3b709aa->S10.0.0.5:11111:184264313_grn/22B298E/007cb3e7@2313dcbc #26901: Tournaments.Grains.Interfaces.Tournaments.Grains.Interfaces.ITournamentPlayerGrain:GetGameZoneTournament(). Reason = Recent (00:00:00 ago, at 2015-11-03 17:39:21.568 GMT) connection failure trying to reach target silo S10.0.0.5:11111:184264313. Going to drop Request msg 26901 without sending. CONNECTION_RETRY_DELAY = 00:00:01.) Response S10.0.0.5:11111:184264313_grn/22B298E/007cb3e7@2313dcbc->S10.0.0.6:11111:184263639_cli/40b1fab8@f3b709aa #26901: Tournaments.Grains.Interfaces.Tournaments.Grains.Interfaces.ITournamentPlayerGrain:GetGameZoneTournament() [2015-11-03 17:39:21.600 GMT 24 WARNING 100147 Dispatcher 10.0.0.6:11111] Intermediate warning for NonExistentActivation from Catalog.GetOrCreateActivation for message Transient Rejection (info: Silo S10.0.0.6:11111:184263639 is rejecting message: Request S10.0.0.6:11111:184263639_cli/e8b7b7bf@6f435abf->S10.0.0.5:11111:184264313_grn/22B298E/0096e768@b75e5e9e #27249: Tournaments.Grains.Interfaces.Tournaments.Grains.Interfaces.ITournamentPlayerGrain:GetGameZoneTournament(). Reason = Recent (00:00:00 ago, at 2015-11-03 17:39:21.568 GMT) connection failure trying to reach target silo S10.0.0.5:11111:184264313. Going to drop Request msg 27249 without sending. CONNECTION_RETRY_DELAY = 00:00:01.) Response S10.0.0.5:11111:184264313_grn/22B298E/0096e768@b75e5e9e->S10.0.0.6:11111:184263639_cli/e8b7b7bf@6f435abf #27249: Tournaments.Grains.Interfaces.Tournaments.Grains.Interfaces.ITournamentPlayerGrain:GetGameZoneTournament() Exc level 0: Orleans.Runtime.Catalog+NonExistentActivationException: Non-existent activation: [ActivationAddress: S10.0.0.6:11111:184263639_cli/e8b7b7bf@6f435abf, Full GrainId: [GrainId: *cli/4e61b4434d3ed3b1614b9929e8b7b7bf0400000000000000-0x1A26ED44, IdCategory: Client, BaseTypeCode: 0 (x0), PrimaryKey: 4d3ed3b1-b443-4e61-bfb7-b7e829994b61 (x{0x4d3ed3b1,0xb443,0x4e61,{0xbf,0xb7,0xb7,0xe8,0x29,0x99,0x4b,0x61}}), UniformHashCode: 438758724 (0x1A26ED44)], Full ActivationId: @4e13f0435c66141cd981fa936f435abf0000000000000000], grain type: . at Orleans.Runtime.Catalog.GetOrCreateActivation(ActivationAddress address, Boolean newPlacement, String grainType, String genericArguments, Task& activatedPromise) at Orleans.Runtime.Dispatcher.ReceiveMessage(Message message) [2015-11-03 17:39:21.600 GMT 24 WARNING 100148 Dispatcher 10.0.0.6:11111] No target activation S10.0.0.6:11111:184263639_cli/e8b7b7bf@6f435abf for response message: Transient Rejection (info: Silo S10.0.0.6:11111:184263639 is rejecting message: Request S10.0.0.6:11111:184263639_cli/e8b7b7bf@6f435abf->S10.0.0.5:11111:184264313_grn/22B298E/0096e768@b75e5e9e #27249: Tournaments.Grains.Interfaces.Tournaments.Grains.Interfaces.ITournamentPlayerGrain:GetGameZoneTournament(). Reason = Recent (00:00:00 ago, at 2015-11-03 17:39:21.568 GMT) connection failure trying to reach target silo S10.0.0.5:11111:184264313. Going to drop Request msg 27249 without sending. CONNECTION_RETRY_DELAY = 00:00:01.) Response S10.0.0.5:11111:184264313_grn/22B298E/0096e768@b75e5e9e->S10.0.0.6:11111:184263639_cli/e8b7b7bf@6f435abf #27249: Tournaments.Grains.Interfaces.Tournaments.Grains.Interfaces.ITournamentPlayerGrain:GetGameZoneTournament() [2015-11-03 17:39:21.600 GMT 24 WARNING 100147 Dispatcher 10.0.0.6:11111] Intermediate warning for NonExistentActivation from Catalog.GetOrCreateActivation for message Transient Rejection (info: Silo S10.0.0.6:11111:184263639 is rejecting message: Request S10.0.0.6:11111:184263639_cli/2edbd1bb@4d3394bd->S10.0.0.5:11111:184264313_grn/22B298E/00ae89f8@f56bcc87 #25546: Tournaments.Grains.Interfaces.Tournaments.Grains.Interfaces.ITournamentPlayerGrain:UpdateScore(). Reason = Recent (00:00:00 ago, at 2015-11-03 17:39:21.568 GMT) connection failure trying to reach target silo S10.0.0.5:11111:184264313. Going to drop Request msg 25546 without sending. CONNECTION_RETRY_DELAY = 00:00:01.) Response S10.0.0.5:11111:184264313_grn/22B298E/00ae89f8@f56bcc87->S10.0.0.6:11111:184263639_cli/2edbd1bb@4d3394bd #25546: Tournaments.Grains.Interfaces.Tournaments.Grains.Interfaces.ITournamentPlayerGrain:UpdateScore() Exc level 0: Orleans.Runtime.Catalog+NonExistentActivationException: Non-existent activation: [ActivationAddress: S10.0.0.6:11111:184263639_cli/2edbd1bb@4d3394bd, Full GrainId: [GrainId: *cli/41f9dd0226501812101aebcb2edbd1bb0400000000000000-0xB5C17331, IdCategory: Client, BaseTypeCode: 0 (x0), PrimaryKey: 26501812-dd02-41f9-bbd1-db2ecbeb1a10 (x{0x26501812,0xdd02,0x41f9,{0xbb,0xd1,0xdb,0x2e,0xcb,0xeb,0x1a,0x10}}), UniformHashCode: 3049354033 (0xB5C17331)], Full ActivationId: @42fb04f3acfb4ae82bd63c7d4d3394bd0000000000000000], grain type: . at Orleans.Runtime.Catalog.GetOrCreateActivation(ActivationAddress address, Boolean newPlacement, String grainType, String genericArguments, Task& activatedPromise) at Orleans.Runtime.Dispatcher.ReceiveMessage(Message message) [2015-11-03 17:39:21.600 GMT 24 WARNING 100148 Dispatcher 10.0.0.6:11111] No target activation S10.0.0.6:11111:184263639_cli/2edbd1bb@4d3394bd for response message: Transient Rejection (info: Silo S10.0.0.6:11111:184263639 is rejecting message: Request S10.0.0.6:11111:184263639_cli/2edbd1bb@4d3394bd->S10.0.0.5:11111:184264313_grn/22B298E/00ae89f8@f56bcc87 #25546: Tournaments.Grains.Interfaces.Tournaments.Grains.Interfaces.ITournamentPlayerGrain:UpdateScore(). Reason = Recent (00:00:00 ago, at 2015-11-03 17:39:21.568 GMT) connection failure trying to reach target silo S10.0.0.5:11111:184264313. Going to drop Request msg 25546 without sending. CONNECTION_RETRY_DELAY = 00:00:01.) Response S10.0.0.5:11111:184264313_grn/22B298E/00ae89f8@f56bcc87->S10.0.0.6:11111:184263639_cli/2edbd1bb@4d3394bd #25546: Tournaments.Grains.Interfaces.Tournaments.Grains.Interfaces.ITournamentPlayerGrain:UpdateScore() [2015-11-03 17:39:21.615 GMT 58 ERROR 100071 Dispatcher 10.0.0.6:11111] !!!!!!!!!! SelectTarget failed with One or more errors occurred. Exc level 0: System.AggregateException: One or more errors occurred. at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task) at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at Orleans.Runtime.GrainReference.<InvokeMethodAsync>d__01.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at System.Runtime.CompilerServices.TaskAwaiter1.GetResult() at Orleans.Runtime.GrainDirectory.LocalGrainDirectory.<FullLookup>d__60.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task) at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at Orleans.Runtime.Scheduler.SchedulerExtensions.<>c__DisplayClass21.<b__0>d__4.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at Orleans.Runtime.Placement.RandomPlacementDirector.d__3.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at System.Runtime.CompilerServices.TaskAwaiter1.GetResult() at Orleans.Runtime.Placement.PlacementDirectorsManager.<SelectOrAddActivation>d__0.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task) at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at System.Runtime.CompilerServices.TaskAwaiter1.GetResult()
at Orleans.Runtime.Dispatcher.d__17.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at Orleans.Runtime.Dispatcher.d__14.MoveNext()
Exc level 1: Orleans.Runtime.OrleansException: Silo S10.0.0.6:11111:184263639 is rejecting message: Request S10.0.0.6:11111:184263639Catalog@S0000000e->S10.0.0.5:11111:184264313DirectoryService@S0000000a #207436: Orleans.Runtime.Orleans.Runtime.IRemoteGrainDirectory:LookUp(). Reason = Recent (00:00:00 ago, at 2015-11-03 17:39:21.568 GMT) connection failure trying to reach target silo S10.0.0.5:11111:184264313. Going to drop Request msg 207436 without sending. CONNECTION_RETRY_DELAY = 00:00:01.
[2015-11-03 17:39:21.615 GMT 125 ERROR 100071 Dispatcher 10.0.0.6:11111] !!!!!!!!!! SelectTarget failed with One or more errors occurred.
Exc level 0: System.AggregateException: One or more errors occurred.
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at Orleans.Runtime.GrainReference.d__01.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task) at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at System.Runtime.CompilerServices.TaskAwaiter1.GetResult()
at Orleans.Runtime.GrainDirectory.LocalGrainDirectory.d__60.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at Orleans.Runtime.Scheduler.SchedulerExtensions.<>c__DisplayClass21.<<QueueTask>b__0>d__4.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task) at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at Orleans.Runtime.Placement.RandomPlacementDirector.<OnSelectActivation>d__3.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task) at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at System.Runtime.CompilerServices.TaskAwaiter1.GetResult()
at Orleans.Runtime.Placement.PlacementDirectorsManager.d__0.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at System.Runtime.CompilerServices.TaskAwaiter1.GetResult() at Orleans.Runtime.Dispatcher.<AddressMessage>d__17.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task) at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at Orleans.Runtime.Dispatcher.<AsyncSendMessage>d__14.MoveNext() Exc level 1: Orleans.Runtime.OrleansException: Silo S10.0.0.6:11111:184263639 is rejecting message: Request S10.0.0.6:11111:184263639Catalog@S0000000e->S10.0.0.5:11111:184264313DirectoryService@S0000000a #207518: Orleans.Runtime.Orleans.Runtime.IRemoteGrainDirectory:LookUp(). Reason = Recent (00:00:00 ago, at 2015-11-03 17:39:21.568 GMT) connection failure trying to reach target silo S10.0.0.5:11111:184264313. Going to drop Request msg 207518 without sending. CONNECTION_RETRY_DELAY = 00:00:01. [2015-11-03 17:39:21.615 GMT 125 ERROR 100071 Dispatcher 10.0.0.6:11111] !!!!!!!!!! SelectTarget failed with One or more errors occurred. Exc level 0: System.AggregateException: One or more errors occurred. at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task) at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at Orleans.Runtime.GrainReference.<InvokeMethodAsync>d__01.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at System.Runtime.CompilerServices.TaskAwaiter1.GetResult() at Orleans.Runtime.GrainDirectory.LocalGrainDirectory.<FullLookup>d__60.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task) at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at Orleans.Runtime.Scheduler.SchedulerExtensions.<>c__DisplayClass21.<b__0>d__4.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at Orleans.Runtime.Placement.RandomPlacementDirector.d__3.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at System.Runtime.CompilerServices.TaskAwaiter1.GetResult() at Orleans.Runtime.Placement.PlacementDirectorsManager.<SelectOrAddActivation>d__0.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task) at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at System.Runtime.CompilerServices.TaskAwaiter1.GetResult()
at Orleans.Runtime.Dispatcher.d__17.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at Orleans.Runtime.Dispatcher.d__14.MoveNext()
Exc level 1: Orleans.Runtime.OrleansException: Silo S10.0.0.6:11111:184263639 is rejecting message: Request S10.0.0.6:11111:184263639Catalog@S0000000e->S10.0.0.5:11111:184264313DirectoryService@S0000000a #207554: Orleans.Runtime.Orleans.Runtime.IRemoteGrainDirectory:LookUp(). Reason = Recent (00:00:00 ago, at 2015-11-03 17:39:21.568 GMT) connection failure trying to reach target silo S10.0.0.5:11111:184264313. Going to drop Request msg 207554 without sending. CONNECTION_RETRY_DELAY = 00:00:01.
[2015-11-03 17:39:21.631 GMT 125 ERROR 100071 Dispatcher 10.0.0.6:11111] !!!!!!!!!! SelectTarget failed with One or more errors occurred.
Exc level 0: System.AggregateException: One or more errors occurred.
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at Orleans.Runtime.GrainReference.d__01.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task) at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at System.Runtime.CompilerServices.TaskAwaiter1.GetResult()
at Orleans.Runtime.GrainDirectory.LocalGrainDirectory.d__60.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at Orleans.Runtime.Scheduler.SchedulerExtensions.<>c__DisplayClass21.<<QueueTask>b__0>d__4.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task) at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at Orleans.Runtime.Placement.RandomPlacementDirector.<OnSelectActivation>d__3.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task) at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at System.Runtime.CompilerServices.TaskAwaiter1.GetResult()
at Orleans.Runtime.Placement.PlacementDirectorsManager.d__0.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at System.Runtime.CompilerServices.TaskAwaiter1.GetResult() at Orleans.Runtime.Dispatcher.<AddressMessage>d__17.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task) at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at Orleans.Runtime.Dispatcher.<AsyncSendMessage>d__14.MoveNext() Exc level 1: Orleans.Runtime.OrleansException: Silo S10.0.0.6:11111:184263639 is rejecting message: Request S10.0.0.6:11111:184263639Catalog@S0000000e->S10.0.0.5:11111:184264313DirectoryService@S0000000a #207562: Orleans.Runtime.Orleans.Runtime.IRemoteGrainDirectory:LookUp(). Reason = Recent (00:00:00 ago, at 2015-11-03 17:39:21.568 GMT) connection failure trying to reach target silo S10.0.0.5:11111:184264313. Going to drop Request msg 207562 without sending. CONNECTION_RETRY_DELAY = 00:00:01. [2015-11-03 17:39:21.631 GMT 24 INFO 100520 Catalog 10.0.0.6:11111] Tried to create a duplicate activation S10.0.0.6:11111:184263639_grn/22B298E/008955ee@59d882bf, but we'll use S10.0.0.4:11111:184263445_grn/22B298E/008955ee@b4cce79e instead. GrainInstanceType is Tournaments.Grains.TournamentPlayerGrain. Primary Directory partition for this grain is S10.0.0.4:11111:184263445, full activation address is [ActivationAddress: S10.0.0.6:11111:184263639_grn/22B298E/008955ee@59d882bf, Full GrainId: [GrainId: *grn/22B298E/000000000000000000000000008955ee03000000022b298e-0x85D29B99, IdCategory: Grain, BaseTypeCode: 36383118 (x22B298E), PrimaryKey: 9000430 (x8955EE), UniformHashCode: 2245172121 (0x85D29B99)], Full ActivationId: @41c6384418de35e5e4d5b9ba59d882bf0000000000000000]. We have 1 messages to forward. [2015-11-03 17:39:21.631 GMT 24 INFO 101033 Dispatcher 10.0.0.6:11111] Forwarding 1 requests to old address S10.0.0.6:11111:184263639_grn/22B298E/008955ee@59d882bf after Duplicate activation. [2015-11-03 17:39:21.631 GMT 24 INFO 101031 Dispatcher 10.0.0.6:11111] Trying to forward after Duplicate activation, ForwardCount = 0. Message NewPlacement Request S10.0.0.4:11111:184263445_cli/5b8708aa@b2140998->S10.0.0.6:11111:184263639_grn/22B298E/008955ee@59d882bf #29243: Tournaments.Grains.Interfaces.Tournaments.Grains.Interfaces.ITournamentPlayerGrain:GetLobbyTournaments(). [2015-11-03 17:39:21.646 GMT 24 ERROR 101319 ClientObserverRegistrar 10.0.0.6:11111] !!!!!!!!!! OnClientRefreshTimer has thrown 1 inner exceptions. Printing the first exception: Exc level 0: Orleans.Runtime.OrleansException: Silo S10.0.0.6:11111:184263639 is rejecting message: Request S10.0.0.6:11111:184263639ClientObserverRegistrar@S0000000d->S10.0.0.5:11111:184264313DirectoryService@S0000000a #208597: Orleans.Runtime.Orleans.Runtime.IRemoteGrainDirectory:Register(). Reason = Recent (00:00:00.0155819 ago, at 2015-11-03 17:39:21.568 GMT) connection failure trying to reach target silo S10.0.0.5:11111:184264313. Going to drop Request msg 208597 without sending. CONNECTION_RETRY_DELAY = 00:00:01. [2015-11-03 17:39:21.992 GMT 20 WARNING 101215 Scheduler.WorkItemGroup 10.0.0.6:11111] Task [Id=24, Status=RanToCompletion] in WorkGroup [Activation: S10.0.0.6:11111:184263639_grn/22B298E/00ae8ac7@f53d1997 #GrainType=Tournaments.Grains.TournamentPlayerGrain State=Valid] took elapsed time 0:00:00.2747398 for execution, which is longer than 00:00:00.2000000. Running on thread <Runtime.Scheduler.WorkerPoolThread/1, ManagedThreadId=20, Executing Task Id=24 Status=RanToCompletion for 00:00:00.2832977> [2015-11-03 17:39:21.992 GMT 22 WARNING 101215 Scheduler.WorkItemGroup 10.0.0.6:11111] Task [Id=25, Status=RanToCompletion] in WorkGroup [Activation: S10.0.0.6:11111:184263639_grn/22B298E/00ab944b@5af9a48f #GrainType=Tournaments.Grains.TournamentPlayerGrain State=Valid] took elapsed time 0:00:00.2556948 for execution, which is longer than 00:00:00.2000000. Running on thread <Runtime.Scheduler.WorkerPoolThread/3, ManagedThreadId=22, Executing Task Id=25 Status=RanToCompletion for 00:00:00.2520876> [2015-11-03 17:39:21.992 GMT 23 WARNING 101215 Scheduler.WorkItemGroup 10.0.0.6:11111] Task [Id=26, Status=RanToCompletion] in WorkGroup [Activation: S10.0.0.6:11111:184263639_grn/22B298E/00ae5504@37ad4f95 #GrainType=Tournaments.Grains.TournamentPlayerGrain State=Valid] took elapsed time 0:00:00.2768 for execution, which is longer than 00:00:00.2000000. Running on thread <Runtime.Scheduler.WorkerPoolThread/4, ManagedThreadId=23, Executing Task Id=26 Status=RanToCompletion for 00:00:00.2832977> [2015-11-03 17:39:21.992 GMT 21 WARNING 101215 Scheduler.WorkItemGroup 10.0.0.6:11111] Task [Id=27, Status=RanToCompletion] in WorkGroup [Activation: S10.0.0.6:11111:184263639_grn/22B298E/00ae8a42@5d828286 #GrainType=Tournaments.Grains.TournamentPlayerGrain State=Valid] took elapsed time 0:00:00.2627282 for execution, which is longer than 00:00:00.2000000. Running on thread <Runtime.Scheduler.WorkerPoolThread/2, ManagedThreadId=21, Executing Task Id=27 Status=RanToCompletion for 00:00:00.2677123> [2015-11-03 17:39:23.621 GMT 26 WARNING 101021 Runtime.Messaging.SiloMessageSender.PingSender/1 10.0.0.6:11111] Exception getting a sending socket to endpoint S10.0.0.5:11111:184264313 Exc level 0: System.Net.Sockets.SocketException: A connection attempt failed because the connected party did not properly respond after a period of time, or established connection failed because connected host has failed to respond 10.0.0.5:11111 at System.Net.Sockets.Socket.DoConnect(EndPoint endPointSnapshot, SocketAddress socketAddress) at System.Net.Sockets.Socket.Connect(EndPoint remoteEP) at Orleans.Runtime.SocketManager.SendingSocketCreator(IPEndPoint target) at Orleans.Runtime.LRU2.Get(TKey key)
at Orleans.Runtime.Messaging.SiloMessageSender.GetSendingSocket(Message msg, Socket& socket, SiloAddress& targetSilo, String& error)
[2015-11-03 17:39:23.621 GMT 24 WARNING 100613 MembershipOracle 10.0.0.6:11111] -Did not get ping response for ping #1035 from S10.0.0.5:11111:184264313. Reason = Original Exc Type: Orleans.Runtime.OrleansException Message:Silo S10.0.0.6:11111:184263639 is rejecting message: Request S10.0.0.6:11111:184263639MembershipOracle@S0000000f->S10.0.0.5:11111:184264313MembershipOracle@S0000000f #207819: Orleans.Runtime.Orleans.Runtime.IMembershipService:Ping(). Reason = Exception getting a sending socket to endpoint S10.0.0.5:11111:184264313
[2015-11-03 17:39:23.621 GMT 24 WARNING 100613 MembershipOracle 10.0.0.6:11111] -Did not get ping response for ping #1037 from S10.0.0.5:11111:184264313. Reason = Original Exc Type: Orleans.Runtime.OrleansException Message:Silo S10.0.0.6:11111:184263639 is rejecting message: Request S10.0.0.6:11111:184263639MembershipOracle@S0000000f->S10.0.0.5:11111:184264313MembershipOracle@S0000000f #208303: Orleans.Runtime.Orleans.Runtime.IMembershipService:Ping(). Reason = Recent (00:00:00 ago, at 2015-11-03 17:39:23.621 GMT) connection failure trying to reach target silo S10.0.0.5:11111:184264313. Going to drop Request msg 208303 without sending. CONNECTION_RETRY_DELAY = 00:00:01.
[2015-11-03 17:39:23.621 GMT 24 WARNING 100613 MembershipOracle 10.0.0.6:11111] -Did not get ping response for ping #1039 from S10.0.0.5:11111:184264313. Reason = Original Exc Type: Orleans.Runtime.OrleansException Message:Silo S10.0.0.6:11111:184263639 is rejecting message: Request S10.0.0.6:11111:184263639MembershipOracle@S0000000f->S10.0.0.5:11111:184264313MembershipOracle@S0000000f #208825: Orleans.Runtime.Orleans.Runtime.IMembershipService:Ping(). Reason = Recent (00:00:00 ago, at 2015-11-03 17:39:23.621 GMT) connection failure trying to reach target silo S10.0.0.5:11111:184264313. Going to drop Request msg 208825 without sending. CONNECTION_RETRY_DELAY = 00:00:01.
[2015-11-03 17:39:23.621 GMT 24 INFO 100610 MembershipOracle 10.0.0.6:11111] -Putting my vote to mark silo S10.0.0.5:11111:184264313 as DEAD #2. Previous suspect list is [], trying to update to [<S10.0.0.6:11111:184263639, 2015-11-03 17:39:23.621 GMT>], eTag=W/"datetime'2015-11-03T17%3A37%3A03.6724342Z'", freshVotes is []
[2015-11-03 17:39:43.638 GMT 37 WARNING 101021 Runtime.Messaging.SiloMessageSender.AppMsgsSender_1/3 10.0.0.6:11111] Exception getting a sending socket to endpoint S10.0.0.5:11111:184264313
Exc level 0: System.Net.Sockets.SocketException: A connection attempt failed because the connected party did not properly respond after a period of time, or established connection failed because connected host has failed to respond 10.0.0.5:11111
at System.Net.Sockets.Socket.DoConnect(EndPoint endPointSnapshot, SocketAddress socketAddress)
at System.Net.Sockets.Socket.Connect(EndPoint remoteEP)
at Orleans.Runtime.SocketManager.SendingSocketCreator(IPEndPoint target)
at Orleans.Runtime.LRU2.Get(TKey key) at Orleans.Runtime.Messaging.SiloMessageSender.GetSendingSocket(Message msg, Socket& socket, SiloAddress& targetSilo, String& error) [2015-11-03 17:39:44.373 GMT 27 WARNING 101021 Runtime.Messaging.SiloMessageSender.SystemSender/2 10.0.0.6:11111] Exception getting a sending socket to endpoint S10.0.0.5:11111:184264313 Exc level 0: System.Net.Sockets.SocketException: A connection attempt failed because the connected party did not properly respond after a period of time, or established connection failed because connected host has failed to respond 10.0.0.5:11111 at System.Net.Sockets.Socket.DoConnect(EndPoint endPointSnapshot, SocketAddress socketAddress) at System.Net.Sockets.Socket.Connect(EndPoint remoteEP) at Orleans.Runtime.SocketManager.SendingSocketCreator(IPEndPoint target) at Orleans.Runtime.LRU2.Get(TKey key)
at Orleans.Runtime.Messaging.SiloMessageSender.GetSendingSocket(Message msg, Socket& socket, SiloAddress& targetSilo, String& error)
[2015-11-03 17:39:45.298 GMT 24 INFO 100507 Catalog 10.0.0.6:11111] Before collection#80: memory=62MB, #activations=3600, collector=<#Activations=3599, #Buckets=43, buckets=[1h:18m:14s.701ms->3 items, 1h:19m:14s.701ms->0 items, 1h:20m:14s.701ms->0 items, 1h:21m:14s.701ms->0 items, 1h:22m:14s.701ms->0 items, 1h:23m:14s.701ms->0 items, 1h:24m:14s.701ms->0 items, 1h:25m:14s.701ms->20 items, 1h:26m:14s.701ms->72 items, 1h:27m:14s.701ms->87 items, 1h:28m:14s.701ms->96 items, 1h:29m:14s.701ms->81 items, 1h:30m:14s.701ms->80 items, 1h:31m:14s.701ms->58 items, 1h:32m:14s.701ms->74 items, 1h:33m:14s.701ms->79 items, 1h:34m:14s.701ms->81 items, 1h:35m:14s.701ms->92 items, 1h:36m:14s.701ms->79 items, 1h:37m:14s.701ms->78 items, 1h:38m:14s.701ms->81 items, 1h:39m:14s.701ms->71 items, 1h:40m:14s.701ms->70 items, 1h:41m:14s.701ms->89 items, 1h:42m:14s.701ms->89 items, 1h:43m:14s.701ms->81 items, 1h:44m:14s.701ms->83 items, 1h:45m:14s.701ms->79 items, 1h:46m:14s.701ms->79 items, 1h:47m:14s.701ms->94 items, 1h:48m:14s.701ms->82 items, 1h:49m:14s.701ms->90 items, 1h:50m:14s.701ms->86 items, 1h:51m:14s.701ms->70 items, 1h:52m:14s.701ms->82 items, 1h:53m:14s.701ms->98 items, 1h:54m:14s.701ms->80 items, 1h:55m:14s.701ms->74 items, 1h:56m:14s.701ms->117 items, 1h:57m:14s.701ms->81 items, 1h:58m:14s.701ms->97 items, 1h:59m:14s.701ms->288 items, 2h:0m:14s.701ms->558 items]>.
[2015-11-03 17:39:45.298 GMT 24 INFO 100508 Catalog 10.0.0.6:11111] After collection#80: memory=63MB, #activations=3600, collected 0 activations, collector=<#Activations=3599, #Buckets=43, buckets=[1h:18m:14s.701ms->3 items, 1h:19m:14s.701ms->0 items, 1h:20m:14s.701ms->0 items, 1h:21m:14s.701ms->0 items, 1h:22m:14s.701ms->0 items, 1h:23m:14s.701ms->0 items, 1h:24m:14s.701ms->0 items, 1h:25m:14s.701ms->20 items, 1h:26m:14s.701ms->72 items, 1h:27m:14s.701ms->87 items, 1h:28m:14s.701ms->96 items, 1h:29m:14s.701ms->81 items, 1h:30m:14s.701ms->80 items, 1h:31m:14s.701ms->58 items, 1h:32m:14s.701ms->74 items, 1h:33m:14s.701ms->79 items, 1h:34m:14s.701ms->81 items, 1h:35m:14s.701ms->92 items, 1h:36m:14s.701ms->79 items, 1h:37m:14s.701ms->78 items, 1h:38m:14s.701ms->81 items, 1h:39m:14s.701ms->71 items, 1h:40m:14s.701ms->70 items, 1h:41m:14s.701ms->89 items, 1h:42m:14s.701ms->89 items, 1h:43m:14s.701ms->81 items, 1h:44m:14s.701ms->83 items, 1h:45m:14s.701ms->79 items, 1h:46m:14s.701ms->79 items, 1h:47m:14s.701ms->94 items, 1h:48m:14s.701ms->82 items, 1h:49m:14s.701ms->90 items, 1h:50m:14s.701ms->86 items, 1h:51m:14s.701ms->70 items, 1h:52m:14s.701ms->82 items, 1h:53m:14s.701ms->98 items, 1h:54m:14s.701ms->80 items, 1h:55m:14s.701ms->74 items, 1h:56m:14s.701ms->117 items, 1h:57m:14s.701ms->81 items, 1h:58m:14s.701ms->97 items, 1h:59m:14s.701ms->288 items, 2h:0m:14s.701ms->558 items]>, collection time=00:00:00.0045516.
[2015-11-03 17:39:53.606 GMT 26 WARNING 101021 Runtime.Messaging.SiloMessageSender.PingSender/1 10.0.0.6:11111] Exception getting a sending socket to endpoint S10.0.0.5:11111:184264313
Exc level 0: System.Net.Sockets.SocketException: A connection attempt failed because the connected party did not properly respond after a period of time, or established connection failed because connected host has failed to respond 10.0.0.5:11111
at System.Net.Sockets.Socket.DoConnect(EndPoint endPointSnapshot, SocketAddress socketAddress)
at System.Net.Sockets.Socket.Connect(EndPoint remoteEP)
at Orleans.Runtime.SocketManager.SendingSocketCreator(IPEndPoint target)
at Orleans.Runtime.LRU2.Get(TKey key) at Orleans.Runtime.Messaging.SiloMessageSender.GetSendingSocket(Message msg, Socket& socket, SiloAddress& targetSilo, String& error) [2015-11-03 17:39:53.606 GMT 24 WARNING 100613 MembershipOracle 10.0.0.6:11111] -Did not get ping response for ping #1041 from S10.0.0.5:11111:184264313. Reason = Original Exc Type: Orleans.Runtime.OrleansException Message:Silo S10.0.0.6:11111:184263639 is rejecting message: Request S10.0.0.6:11111:184263639MembershipOracle@S0000000f->S10.0.0.5:11111:184264313MembershipOracle@S0000000f #209337: Orleans.Runtime.Orleans.Runtime.IMembershipService:Ping(). Reason = Exception getting a sending socket to endpoint S10.0.0.5:11111:184264313 [2015-11-03 17:39:53.606 GMT 24 WARNING 100613 MembershipOracle 10.0.0.6:11111] -Did not get ping response for ping #1043 from S10.0.0.5:11111:184264313. Reason = Original Exc Type: Orleans.Runtime.OrleansException Message:Silo S10.0.0.6:11111:184263639 is rejecting message: Request S10.0.0.6:11111:184263639MembershipOracle@S0000000f->S10.0.0.5:11111:184264313MembershipOracle@S0000000f #209884: Orleans.Runtime.Orleans.Runtime.IMembershipService:Ping(). Reason = Recent (00:00:00 ago, at 2015-11-03 17:39:53.606 GMT) connection failure trying to reach target silo S10.0.0.5:11111:184264313. Going to drop Request msg 209884 without sending. CONNECTION_RETRY_DELAY = 00:00:01. [2015-11-03 17:39:53.668 GMT 24 INFO 100610 MembershipOracle 10.0.0.6:11111] -Putting my vote to mark silo S10.0.0.5:11111:184264313 as DEAD #2. Previous suspect list is [<S10.0.0.6:11111:184263639, 2015-11-03 17:39:23.621 GMT>], trying to update to [<S10.0.0.6:11111:184263639, 2015-11-03 17:39:53.668 GMT>], eTag=W/"datetime'2015-11-03T17%3A39%3A23.3715896Z'", freshVotes is [<S10.0.0.6:11111:184263639, 2015-11-03 17:39:23.621 GMT>] [2015-11-03 17:39:53.668 GMT 24 INFO 100610 MembershipOracle 10.0.0.6:11111] -Putting my vote to mark silo S10.0.0.5:11111:184264313 as DEAD #2. Previous suspect list is [<S10.0.0.6:11111:184263639, 2015-11-03 17:39:23.621 GMT>], trying to update to [<S10.0.0.6:11111:184263639, 2015-11-03 17:39:53.668 GMT>], eTag=W/"datetime'2015-11-03T17%3A39%3A23.3715896Z'", freshVotes is [<S10.0.0.6:11111:184263639, 2015-11-03 17:39:23.621 GMT>] [2015-11-03 17:39:53.668 GMT 24 INFO 100610 MembershipOracle 10.0.0.6:11111] -Putting my vote to mark silo S10.0.0.5:11111:184264313 as DEAD #2. Previous suspect list is [<S10.0.0.6:11111:184263639, 2015-11-03 17:39:23.621 GMT>], trying to update to [<S10.0.0.6:11111:184263639, 2015-11-03 17:39:53.668 GMT>], eTag=W/"datetime'2015-11-03T17%3A39%3A23.3715896Z'", freshVotes is [<S10.0.0.6:11111:184263639, 2015-11-03 17:39:23.621 GMT>] [2015-11-03 17:39:53.825 GMT 24 WARNING 100824 AzureSiloMembershipTable 10.0.0.6:11111] Update failed due to contention on the table. Will retry. Entry SiloAddress=S10.0.0.5:11111:184264313 Status=Active, eTag W/"datetime'2015-11-03T17%3A39%3A23.3715896Z'", table version = <143, W/"datetime'2015-11-03T17%3A39%3A30.6704421Z'"> [2015-11-03 17:39:53.825 GMT 24 WARNING 100824 AzureSiloMembershipTable 10.0.0.6:11111] Update failed due to contention on the table. Will retry. Entry SiloAddress=S10.0.0.5:11111:184264313 Status=Active, eTag W/"datetime'2015-11-03T17%3A39%3A23.3715896Z'", table version = <143, W/"datetime'2015-11-03T17%3A39%3A30.6704421Z'"> [2015-11-03 17:39:54.201 GMT 24 INFO 100610 MembershipOracle 10.0.0.6:11111] -Putting my vote to mark silo S10.0.0.5:11111:184264313 as DEAD #2. Previous suspect list is [<S10.0.0.6:11111:184263639, 2015-11-03 17:39:53.668 GMT>], trying to update to [<S10.0.0.6:11111:184263639, 2015-11-03 17:39:54.201 GMT>], eTag=W/"datetime'2015-11-03T17%3A39%3A53.4067893Z'", freshVotes is [<S10.0.0.6:11111:184263639, 2015-11-03 17:39:53.668 GMT>] [2015-11-03 17:39:54.232 GMT 20 WARNING 100824 AzureSiloMembershipTable 10.0.0.6:11111] Update failed due to contention on the table. Will retry. Entry SiloAddress=S10.0.0.5:11111:184264313 Status=Active, eTag W/"datetime'2015-11-03T17%3A39%3A53.4067893Z'", table version = <144, W/"datetime'2015-11-03T17%3A39%3A53.4067893Z'"> [2015-11-03 17:40:05.687 GMT 37 WARNING 101021 Runtime.Messaging.SiloMessageSender.AppMsgsSender_1/3 10.0.0.6:11111] Exception getting a sending socket to endpoint S10.0.0.5:11111:184264313 Exc level 0: System.Net.Sockets.SocketException: A connection attempt failed because the connected party did not properly respond after a period of time, or established connection failed because connected host has failed to respond 10.0.0.5:11111 at System.Net.Sockets.Socket.DoConnect(EndPoint endPointSnapshot, SocketAddress socketAddress) at System.Net.Sockets.Socket.Connect(EndPoint remoteEP) at Orleans.Runtime.SocketManager.SendingSocketCreator(IPEndPoint target) at Orleans.Runtime.LRU2.Get(TKey key)
at Orleans.Runtime.Messaging.SiloMessageSender.GetSendingSocket(Message msg, Socket& socket, SiloAddress& targetSilo, String& error)

Client logs example:

[2015-11-03 17:38:52.954 GMT 14 INFO 101309 Messaging.GatewayManager 10.0.0.30:0] Refreshed the live GateWay list. Found 3 gateways from Gateway listProvider: [gwy.tcp://10.0.0.4:30000/184263445, gwy.tcp://10.0.0.5:30000/184264313, gwy.tcp://10.0.0.6:30000/184263639]. Picked only known live out of them. Now has 3 live Gateways: [gwy.tcp://10.0.0.4:30000/184263445, gwy.tcp://10.0.0.5:30000/184264313, gwy.tcp://10.0.0.6:30000/184263639]. Previous refresh time was = 11/3/2015 5:37:52 PM
[2015-11-03 17:38:55.338 GMT 12 INFO 600157 CallbackData 10.0.0.30:0] Log code 100157 occurred 151 additional times in the previous 00:20:57.5667215
[2015-11-03 17:38:55.338 GMT 12 WARNING 100157 CallbackData 10.0.0.30:0] Response did not arrive on time in 00:00:05 for message: Request _cli/1aba9a90@fa5bc7ae->S10.0.0.5:30000:184264313_grn/22B298E/007cb3e7 #18931: Tournaments.Grains.Interfaces.Tournaments.Grains.Interfaces.ITournamentPlayerGrain:GetGameZoneTournament(). Target History is: S10.0.0.5:30000:184264313:*grn/22B298E/007cb3e7:. About to break its promise.
[2015-11-03 17:38:55.400 GMT 12 WARNING 100157 CallbackData 10.0.0.30:0] Response did not arrive on time in 00:00:05 for message: Request _cli/1aba9a90@fa5bc7ae->S10.0.0.4:30000:184263445_grn/22B298E/00446f1a #18932: Tournaments.Grains.Interfaces.Tournaments.Grains.Interfaces.ITournamentPlayerGrain:UpdateScore(). Target History is: S10.0.0.4:30000:184263445:*grn/22B298E/00446f1a:. About to break its promise.
[2015-11-03 17:38:55.416 GMT 12 WARNING 100157 CallbackData 10.0.0.30:0] Response did not arrive on time in 00:00:05 for message: Request _cli/1aba9a90@fa5bc7ae->S10.0.0.6:30000:184263639_grn/22B298E/00ae17ca #18933: Tournaments.Grains.Interfaces.Tournaments.Grains.Interfaces.ITournamentPlayerGrain:UpdateScore(). Target History is: S10.0.0.6:30000:184263639:*grn/22B298E/00ae17ca:. About to break its promise.
[2015-11-03 17:38:56.072 GMT 12 WARNING 100157 CallbackData 10.0.0.30:0] Response did not arrive on time in 00:00:05 for message: Request _cli/1aba9a90@fa5bc7ae->S10.0.0.5:30000:184264313_grn/22B298E/0055f0e1 #18937: Tournaments.Grains.Interfaces.Tournaments.Grains.Interfaces.ITournamentPlayerGrain:GetLobbyTournaments(). Target History is: S10.0.0.5:30000:184264313:*grn/22B298E/0055f0e1:. About to break its promise.
[2015-11-03 17:38:56.213 GMT 12 WARNING 100157 CallbackData 10.0.0.30:0] Response did not arrive on time in 00:00:05 for message: Request _cli/1aba9a90@fa5bc7ae->S10.0.0.5:30000:184264313_grn/22B298E/00ad4568 #18939: Tournaments.Grains.Interfaces.Tournaments.Grains.Interfaces.ITournamentPlayerGrain:UpdateScore(). Target History is: S10.0.0.5:30000:184264313:*grn/22B298E/00ad4568:. About to break its promise.
[2015-11-03 17:39:00.594 GMT 54 WARNING 100158 Messaging.GatewayClientReceiver/5 10.0.0.30:0] Exception receiving from gateway gwy.tcp://10.0.0.5:30000/184264313
[2015-11-03 17:39:00.594 GMT 54 WARNING 100913 Messaging.GatewayConnection.GatewayClientSender_gwy.tcp://10.0.0.5:30000/184264313/5 10.0.0.30:0] Marking gateway at address gwy.tcp://10.0.0.5:30000/184264313 as Disconnected
[2015-11-03 17:39:00.594 GMT 12 INFO 100277 OrleansSiloInstanceManager 10.0.0.30:0] Searching for active gateway silos for deployment LFG1.0 ...
[2015-11-03 17:39:00.641 GMT 12 INFO 100278 OrleansSiloInstanceManager 10.0.0.30:0] Found 3 active Gateway Silos.
[2015-11-03 17:39:00.641 GMT 12 INFO 101309 Messaging.GatewayManager 10.0.0.30:0] Refreshed the live GateWay list. Found 3 gateways from Gateway listProvider: [gwy.tcp://10.0.0.4:30000/184263445, gwy.tcp://10.0.0.5:30000/184264313, gwy.tcp://10.0.0.6:30000/184263639]. Picked only known live out of them. Now has 3 live Gateways: [gwy.tcp://10.0.0.4:30000/184263445, gwy.tcp://10.0.0.5:30000/184264313, gwy.tcp://10.0.0.6:30000/184263639]. Previous refresh time was = 11/3/2015 5:38:52 PM
[2015-11-03 17:39:21.597 GMT 54 WARNING 100178 Messaging.GatewayConnection.GatewayClientSender_gwy.tcp://10.0.0.5:30000/184264313/5 10.0.0.30:0] Unable to connect to gateway at address gwy.tcp://10.0.0.5:30000/184264313 on trial 0.
[2015-11-03 17:39:21.597 GMT 54 WARNING 100913 Messaging.GatewayConnection.GatewayClientSender_gwy.tcp://10.0.0.5:30000/184264313/5 10.0.0.30:0] Marking gateway at address gwy.tcp://10.0.0.5:30000/184264313 as Disconnected
[2015-11-03 17:39:21.597 GMT 48 INFO 100277 OrleansSiloInstanceManager 10.0.0.30:0] Searching for active gateway silos for deployment LFG1.0 ...
[2015-11-03 17:39:21.660 GMT 48 INFO 100278 OrleansSiloInstanceManager 10.0.0.30:0] Found 3 active Gateway Silos.
[2015-11-03 17:39:21.660 GMT 48 INFO 101309 Messaging.GatewayManager 10.0.0.30:0] Refreshed the live GateWay list. Found 3 gateways from Gateway listProvider: [gwy.tcp://10.0.0.4:30000/184263445, gwy.tcp://10.0.0.5:30000/184264313, gwy.tcp://10.0.0.6:30000/184263639]. Picked only known live out of them. Now has 3 live Gateways: [gwy.tcp://10.0.0.4:30000/184263445, gwy.tcp://10.0.0.5:30000/184264313, gwy.tcp://10.0.0.6:30000/184263639]. Previous refresh time was = 11/3/2015 5:39:00 PM
[2015-11-03 17:39:42.611 GMT 54 WARNING 100178 Messaging.GatewayConnection.GatewayClientSender_gwy.tcp://10.0.0.5:30000/184264313/5 10.0.0.30:0] Unable to connect to gateway at address gwy.tcp://10.0.0.5:30000/184264313 on trial 1.
[2015-11-03 17:39:42.611 GMT 54 WARNING 100913 Messaging.GatewayConnection.GatewayClientSender_gwy.tcp://10.0.0.5:30000/184264313/5 10.0.0.30:0] Marking gateway at address gwy.tcp://10.0.0.5:30000/184264313 as Disconnected
[2015-11-03 17:39:42.611 GMT 8 INFO 100277 OrleansSiloInstanceManager 10.0.0.30:0] Searching for active gateway silos for deployment LFG1.0 ...
[2015-11-03 17:39:42.611 GMT 54 WARNING 100912 Messaging.GatewayConnection.GatewayClientSender_gwy.tcp://10.0.0.5:30000/184264313/5 10.0.0.30:0] Marking gateway at address gwy.tcp://10.0.0.5:30000/184264313 as Dead in my client local gateway list.
[2015-11-03 17:39:42.611 GMT 54 INFO 100328 Messaging.GatewayClientReceiver/5 10.0.0.30:0] Stopping AsyncAgent Messaging.GatewayClientReceiver/5 that runs on managed thread 54
[2015-11-03 17:39:42.627 GMT 8 INFO 100278 OrleansSiloInstanceManager 10.0.0.30:0] Found 3 active Gateway Silos.
[2015-11-03 17:39:42.627 GMT 8 INFO 101309 Messaging.GatewayManager 10.0.0.30:0] Refreshed the live GateWay list. Found 3 gateways from Gateway listProvider: [gwy.tcp://10.0.0.4:30000/184263445, gwy.tcp://10.0.0.5:30000/184264313, gwy.tcp://10.0.0.6:30000/184263639]. Picked only known live out of them. Now has 2 live Gateways: [gwy.tcp://10.0.0.4:30000/184263445, gwy.tcp://10.0.0.6:30000/184263639]. Previous refresh time was = 11/3/2015 5:39:21 PM
[2015-11-03 17:39:52.967 GMT 8 INFO 100277 OrleansSiloInstanceManager 10.0.0.30:0] Searching for active gateway silos for deployment LFG1.0 ...
[2015-11-03 17:39:53.078 GMT 8 INFO 100278 OrleansSiloInstanceManager 10.0.0.30:0] Found 3 active Gateway Silos.
[2015-11-03 17:39:53.078 GMT 8 INFO 101309 Messaging.GatewayManager 10.0.0.30:0] Refreshed the live GateWay list. Found 3 gateways from Gateway listProvider: [gwy.tcp://10.0.0.4:30000/184263445, gwy.tcp://10.0.0.5:30000/184264313, gwy.tcp://10.0.0.6:30000/184263639]. Picked only known live out of them. Now has 2 live Gateways: [gwy.tcp://10.0.0.4:30000/184263445, gwy.tcp://10.0.0.6:30000/184263639]. Previous refresh time was = 11/3/2015 5:39:42 PM
[2015-11-03 17:39:55.785 GMT 8 INFO 600157 CallbackData 10.0.0.30:0] Log code 100157 occurred 297 additional times in the previous 00:01:00.4476120
[2015-11-03 17:39:55.785 GMT 8 WARNING 100157 CallbackData 10.0.0.30:0] Response did not arrive on time in 00:00:05 for message: Request _cli/1aba9a90@fa5bc7ae->S10.0.0.6:30000:184263639_grn/22B298E/00ac33ff #19516: Tournaments.Grains.Interfaces.Tournaments.Grains.Interfaces.ITournamentPlayerGrain:GetGameZoneTournament(). Target History is: S10.0.0.6:30000:184263639:*grn/22B298E/00ac33ff:. About to break its promise.
[2015-11-03 17:39:56.098 GMT 23 WARNING 100157 CallbackData 10.0.0.30:0] Response did not arrive on time in 00:00:05 for message: Request _cli/1aba9a90@fa5bc7ae->S10.0.0.4:30000:184263445_grn/22B298E/00ae8a98 #19517: Tournaments.Grains.Interfaces.Tournaments.Grains.Interfaces.ITournamentPlayerGrain:UpdateScore(). Target History is: S10.0.0.4:30000:184263445:*grn/22B298E/00ae8a98:. About to break its promise.
[2015-11-03 17:39:56.410 GMT 23 WARNING 100157 CallbackData 10.0.0.30:0] Response did not arrive on time in 00:00:05 for message: Request _cli/1aba9a90@fa5bc7ae->S10.0.0.4:30000:184263445_grn/22B298E/007731e5 #19520: Tournaments.Grains.Interfaces.Tournaments.Grains.Interfaces.ITournamentPlayerGrain:UpdateScore(). Target History is: S10.0.0.4:30000:184263445:*grn/22B298E/007731e5:. About to break its promise.
[2015-11-03 17:39:56.582 GMT 55 WARNING 100157 CallbackData 10.0.0.30:0] Response did not arrive on time in 00:00:05 for message: Request _cli/1aba9a90@fa5bc7ae->S10.0.0.6:30000:184263639_grn/22B298E/00a4cc85 #19521: Tournaments.Grains.Interfaces.Tournaments.Grains.Interfaces.ITournamentPlayerGrain:GetLobbyTournaments(). Target History is: S10.0.0.6:30000:184263639:*grn/22B298E/00a4cc85:. About to break its promise.
[2015-11-03 17:39:57.160 GMT 23 WARNING 100157 CallbackData 10.0.0.30:0] Response did not arrive on time in 00:00:05 for message: Request _cli/1aba9a90@fa5bc7ae->S10.0.0.6:30000:184263639_grn/22B298E/001bff99 #19525: Tournaments.Grains.Interfaces.Tournaments.Grains.Interfaces.ITournamentPlayerGrain:UpdateScore(). Target History is: S10.0.0.6:30000:184263639:*grn/22B298E/001bff99:. About to break its promise.
[2015-11-03 17:40:03.629 GMT 53 WARNING 100178 Messaging.GatewayConnection.GatewayClientSender_gwy.tcp://10.0.0.5:30000/184264313/6 10.0.0.30:0] Unable to connect to gateway at address gwy.tcp://10.0.0.5:30000/184264313 on trial 0.
[2015-11-03 17:40:03.629 GMT 53 WARNING 100913 Messaging.GatewayConnection.GatewayClientSender_gwy.tcp://10.0.0.5:30000/184264313/6 10.0.0.30:0] Marking gateway at address gwy.tcp://10.0.0.5:30000/184264313 as Disconnected
[2015-11-03 17:40:03.629 GMT 17 INFO 100277 OrleansSiloInstanceManager 10.0.0.30:0] Searching for active gateway silos for deployment LFG1.0 ...
[2015-11-03 17:40:03.676 GMT 17 INFO 100278 OrleansSiloInstanceManager 10.0.0.30:0] Found 3 active Gateway Silos.
[2015-11-03 17:40:03.676 GMT 17 INFO 101309 Messaging.GatewayManager 10.0.0.30:0] Refreshed the live GateWay list. Found 3 gateways from Gateway listProvider: [gwy.tcp://10.0.0.4:30000/184263445, gwy.tcp://10.0.0.5:30000/184264313, gwy.tcp://10.0.0.6:30000/184263639]. Picked only known live out of them. Now has 2 live Gateways: [gwy.tcp://10.0.0.4:30000/184263445, gwy.tcp://10.0.0.6:30000/184263639]. Previous refresh time was = 11/3/2015 5:39:53 PM
[2015-11-03 17:40:12.632 GMT 53 INFO 100908 Messaging.GatewayConnection.GatewayClientSender_gwy.tcp://10.0.0.5:30000/184264313/6 10.0.0.30:0] Connected to gateway at address gwy.tcp://10.0.0.5:30000/184264313 on trial 1.
[2015-11-03 17:40:12.647 GMT 28 INFO 100000 Messaging.GatewayClientReceiver/6 10.0.0.30:0] Starting AsyncAgent Messaging.GatewayClientReceiver/6 on managed thread 28
[2015-11-03 17:40:12.647 GMT 53 INFO 100328 Messaging.GatewayConnection.GatewayClientSender_gwy.tcp://10.0.0.5:30000/184264313/5 10.0.0.30:0] Stopping AsyncAgent Messaging.GatewayConnection.GatewayClientSender_gwy.tcp://10.0.0.5:30000/184264313/5 that runs on managed thread 53
[2015-11-03 17:40:12.647 GMT 25 INFO 100000 Messaging.GatewayConnection.GatewayClientSender_gwy.tcp://10.0.0.5:30000/184264313/6 10.0.0.30:0] Starting AsyncAgent Messaging.GatewayConnection.GatewayClientSender_gwy.tcp://10.0.0.5:30000/184264313/6 on managed thread 25
[2015-11-03 17:40:53.092 GMT 14 INFO 100277 OrleansSiloInstanceManager 10.0.0.30:0] Searching for active gateway silos for deployment LFG1.0 ...
[2015-11-03 17:40:53.108 GMT 14 INFO 100278 OrleansSiloInstanceManager 10.0.0.30:0] Found 3 active Gateway Silos.
[2015-11-03 17:40:53.108 GMT 14 INFO 101309 Messaging.GatewayManager 10.0.0.30:0] Refreshed the live GateWay list. Found 3 gateways from Gateway listProvider: [gwy.tcp://10.0.0.4:30000/184263445, gwy.tcp://10.0.0.5:30000/184264313, gwy.tcp://10.0.0.6:30000/184263639]. Picked only known live out of them. Now has 3 live Gateways: [gwy.tcp://10.0.0.4:30000/184263445, gwy.tcp://10.0.0.5:30000/184264313, gwy.tcp://10.0.0.6:30000/184263639]. Previous refresh time was = 11/3/2015 5:40:03 PM

[jason-bragg]

What version of Orleans are you using?

[2mike2]

1.0.8

[sergeybykov]

At a first glance, looks like a network connectivity issue. We've seen similar issues in production recently - some worker role instances were getting partitioned from the rest of the role temporarily.

If you look at the OrleansSiloInstance table, you should see the whole history of the cluster state - which silo suspected/voted which dead. That should help determine if there was a problem with a particular VM or a set of VMs.

[sergeybykov]

As per http://dotnet.github.io/orleans/Advanced-Concepts/Silo-Error-Code-Monitoring, look for error/warning codes in the 100600 - 100699 range in the logs.

[2mike2]

Hi Sergey, thanks for getting back. I see lots of "WARNING 100613 MembershipOracle 10.0.0.6:11111] -Did not get ping response for ping" errors in silos logs during the outages. Azure support don't see any networking problems behind the silo VMs / web VMs.
You've said you ran into similar issues and some worker role instances were getting partitioned from the rest of the roles temporarily. How was it resolved ?

[sergeybykov]

Beside 100613, there are numerous socket errors in the log snippet you posted. Did you look at the OrleansSiloInstance table? It should provide a reasonable picture of which instances lost connectivity with each other.

[2mike2]

Silo instances table has the three original silo rows active since their upload. I don't see any of them rolled dead. They have the original start time. On two of them I see suspecting time pretty close to now.

[2mike2]

Actually, I see today that one of the silos does periodically commit suicide and is rolled from active to dead in OrleansSiloInstance. In log I see:

[2015-11-04 21:53:20.932 GMT 20 WARNING 100613 MembershipOracle 10.0.0.19:11111] -Did not get ping response for ping #226 from S10.0.0.20:11111:184367724. Reason = Original Exc Type: Orleans.Runtime.OrleansException Message:Silo S10.0.0.19:11111:184368841 is rejecting message: Request S10.0.0.19:11111:184368841MembershipOracle@S0000000f->S10.0.0.20:11111:184367724MembershipOracle@S0000000f #3500: Orleans.Runtime.Orleans.Runtime.IMembershipService:Ping(). Reason = Exception getting a sending socket to endpoint S10.0.0.20:11111:184367724
[2015-11-04 21:53:38.542 GMT 24 WARNING 100618 MembershipOracle 10.0.0.19:11111] I should be Dead according to membership table (in CleanupTableEntries): entry = SiloAddress=S10.0.0.19:11111:184368841 Status=Dead.
[2015-11-04 21:53:38.542 GMT 24 ERROR 100627 MembershipOracle 10.0.0.19:11111] !!!!!!!!!! I have been told I am dead, so this silo will commit suicide! I should be Dead according to membership table (in CleanupTableEntries): entry = SiloAddress=S10.0.0.19:11111:184368841 Status=Dead.
[2015-11-04 21:53:38.557 GMT 24 ERROR 100627 MembershipOracle 10.0.0.19:11111] !!!!!!!!!! INTERNAL FAILURE! About to crash! Fail message is: I have been told I am dead, so this silo will commit suicide! I should be Dead according to membership table (in CleanupTableEntries): entry = SiloAddress=S10.0.0.19:11111:184368841 Status=Dead.

During his reborn, we have lots of timeouts from clients. Sergey, you've said you've seen similar issues on azure workers, how was it mitigated?

[2mike2]

You said it was temporary, how temporary was it?

[sergeybykov]

Silo instances table has the three original silo rows active since their upload. I don't see any of them rolled dead. They have the original start time. On two of them I see suspecting time pretty close to now.

Are those suspicions from the third instance?

In the log snippet above 10.0.0.19 is unable to communicate (ping) with 10.0.0.20. Then 10.0.0.19 discovers that it already got marked dead by the other silos (their IP addresses should be in the corresponding row in the OrleansSiloMembership table. This picture is consistent with 10.0.0.19 getting network partitioned from other instances of the role.

During his reborn, we have lots of timeouts from clients.

Until 10.0.0.19 is declared dead, the other silos keep trying to send messages to grains on it and to the grain directory partition it is responsible for. During that time you will see timeouts. Once it is declared dead, timeouts should stop. You can reduce the detection period by changing parameters of the membership protocol. However, that will increase the risk of false positives.

Sergey, you've said you've seen similar issues on azure workers, how was it mitigated?

In a couple of cases the connectivity healed after a while and everything continued fine. In another case we VIP-swapped to another deployment. That was a rather large deployment, and the shift engineers didn't have time to figure things out in the middle of the night.

If network partition is persistent, the silo will reboot, and will be unable to join the cluster until it can successfully ping the other silos. So it will keep rebooting every few minutes until the network partition heals.

The more problematic case is when the connectivity is inconsistent - some messages go through fine while some don't. We saw one such case. The periodic losses of connectivity weren't long enough to declare the silo dead. We redeployed that one.

We also found a bug #955 that made it possible for some grains to become unavailable after a failure to unregister them from grain directory. The fix is in 1.1.0-beta1.

[gabikliot]

The more problematic case is when the connectivity is inconsistent - some messages go through fine while some don't. We saw one such case.

@sergeybykov , was the root cause found? Was it an infrastructure problem?

[sergeybykov]

We were asked to run netmon on the VMs next time it happens. :-)

[gabikliot]

👍