[2017-09-28 08:02:05.238 GMT 1 INFO 100000 Scheduler.OrleansTaskScheduler 127.0.0.1:11111] Starting OrleansTaskScheduler with 8 Max Active application Threads and 1 system thread. [2017-09-28 08:02:05.261 GMT 1 INFO 101010 Runtime.Messaging.IncomingMessageAcceptor 127.0.0.1:11111] Opened a listening socket at address 127.0.0.1:11111 [2017-09-28 08:02:05.272 GMT 1 INFO 101010 Runtime.Messaging.GatewayAcceptor 127.0.0.1:11111] Opened a listening socket at address 127.0.0.1:30000 [2017-09-28 08:02:05.278 GMT 1 VERBOSE 100298 Interner-ActivationId 127.0.0.1:11111] Starting Interner-ActivationId cache cleanup timer with frequency 00:10:00 [2017-09-28 08:02:05.305 GMT 1 VERBOSE 100000 Orleans.Runtime.GrainDirectory.GrainDirectoryHandoffManager 127.0.0.1:11111] Processing silo add event for S127.0.0.1:11111:244281717 [2017-09-28 08:02:05.324 GMT 1 INFO 100000 VirtualBucketsRingProvider 127.0.0.1:11111] Starting VirtualBucketsRingProvider on silo S127.0.0.1:11111:244281717/xFFCB0244. [2017-09-28 08:02:05.359 GMT 1 INFO 103003 VirtualBucketsRingProvider 127.0.0.1:11111] Added Server S127.0.0.1:11111:244281717/xFFCB0244. Current view: [S127.0.0.1:11111:244281717 -> ] [2017-09-28 08:02:05.363 GMT 1 INFO 103005 VirtualBucketsRingProvider 127.0.0.1:11111] -NotifyLocalRangeSubscribers about old <(0 0], Size=x100000000, %Ring=100.000%> new increased? True [2017-09-28 08:02:05.394 GMT 1 INFO 100000 Silo 127.0.0.1:11111] Skip multicluster oracle creation (no multicluster network configured) [2017-09-28 08:02:05.398 GMT 1 INFO 100422 Silo 127.0.0.1:11111] -------------- Started silo S127.0.0.1:11111:244281717, ConsistentHashCode FFCB0244 -------------- [2017-09-28 08:02:05.399 GMT 1 INFO 100288 OrleansSiloHost 127.0.0.1:11111] Successfully initialized Orleans silo 'localhost' as a Primary node. [2017-09-28 08:02:05.403 GMT 1 INFO 100441 OrleansSiloHost 127.0.0.1:11111] Silo shutdown event name: localhost-Shutdown [2017-09-28 08:02:05.405 GMT 1 INFO 100442 OrleansSiloHost 127.0.0.1:11111] Created and set shutdown event localhost-Shutdown [2017-09-28 08:02:05.413 GMT 1 INFO 100401 Silo 127.0.0.1:11111] Silo Start() [2017-09-28 08:02:05.416 GMT 1 INFO 100430 Silo 127.0.0.1:11111] Configured ThreadPool.SetMinThreads() to values: 200,200. Previous values are: 8,8. [2017-09-28 08:02:05.418 GMT 1 INFO 100436 Silo 127.0.0.1:11111] Configured .NET ServicePointManager to Expect100Continue=False, DefaultConnectionLimit=200, UseNagleAlgorithm=False to improve Azure storage performance. [2017-09-28 08:02:05.592 GMT 1 VERBOSE 100000 Runtime.Scheduler.WorkerPoolThread/System.9 127.0.0.1:11111] Started asynch agent Runtime.Scheduler.WorkerPoolThread/System.9 [2017-09-28 08:02:05.595 GMT 1 VERBOSE 100000 Runtime.Scheduler.WorkerPoolThread/0 127.0.0.1:11111] Started asynch agent Runtime.Scheduler.WorkerPoolThread/0 [2017-09-28 08:02:05.597 GMT 19 INFO 100000 Runtime.Scheduler.WorkerPoolThread/0 127.0.0.1:11111] Starting AsyncAgent Runtime.Scheduler.WorkerPoolThread/0 on managed thread 19 [2017-09-28 08:02:05.597 GMT 27 INFO 100000 Runtime.Scheduler.WorkerPoolThread/System.9 127.0.0.1:11111] Starting AsyncAgent Runtime.Scheduler.WorkerPoolThread/System.9 on managed thread 27 [2017-09-28 08:02:05.643 GMT 1 VERBOSE 100000 Runtime.Scheduler.WorkerPoolThread/1 127.0.0.1:11111] Started asynch agent Runtime.Scheduler.WorkerPoolThread/1 [2017-09-28 08:02:05.645 GMT 20 INFO 100000 Runtime.Scheduler.WorkerPoolThread/1 127.0.0.1:11111] Starting AsyncAgent Runtime.Scheduler.WorkerPoolThread/1 on managed thread 20 [2017-09-28 08:02:05.648 GMT 1 VERBOSE 100000 Runtime.Scheduler.WorkerPoolThread/2 127.0.0.1:11111] Started asynch agent Runtime.Scheduler.WorkerPoolThread/2 [2017-09-28 08:02:05.649 GMT 21 INFO 100000 Runtime.Scheduler.WorkerPoolThread/2 127.0.0.1:11111] Starting AsyncAgent Runtime.Scheduler.WorkerPoolThread/2 on managed thread 21 [2017-09-28 08:02:05.693 GMT 1 VERBOSE 100000 Runtime.Scheduler.WorkerPoolThread/3 127.0.0.1:11111] Started asynch agent Runtime.Scheduler.WorkerPoolThread/3 [2017-09-28 08:02:05.694 GMT 22 INFO 100000 Runtime.Scheduler.WorkerPoolThread/3 127.0.0.1:11111] Starting AsyncAgent Runtime.Scheduler.WorkerPoolThread/3 on managed thread 22 [2017-09-28 08:02:05.696 GMT 1 VERBOSE 100000 Runtime.Scheduler.WorkerPoolThread/4 127.0.0.1:11111] Started asynch agent Runtime.Scheduler.WorkerPoolThread/4 [2017-09-28 08:02:05.698 GMT 23 INFO 100000 Runtime.Scheduler.WorkerPoolThread/4 127.0.0.1:11111] Starting AsyncAgent Runtime.Scheduler.WorkerPoolThread/4 on managed thread 23 [2017-09-28 08:02:05.699 GMT 1 VERBOSE 100000 Runtime.Scheduler.WorkerPoolThread/5 127.0.0.1:11111] Started asynch agent Runtime.Scheduler.WorkerPoolThread/5 [2017-09-28 08:02:05.700 GMT 24 INFO 100000 Runtime.Scheduler.WorkerPoolThread/5 127.0.0.1:11111] Starting AsyncAgent Runtime.Scheduler.WorkerPoolThread/5 on managed thread 24 [2017-09-28 08:02:05.702 GMT 1 VERBOSE 100000 Runtime.Scheduler.WorkerPoolThread/6 127.0.0.1:11111] Started asynch agent Runtime.Scheduler.WorkerPoolThread/6 [2017-09-28 08:02:05.703 GMT 25 INFO 100000 Runtime.Scheduler.WorkerPoolThread/6 127.0.0.1:11111] Starting AsyncAgent Runtime.Scheduler.WorkerPoolThread/6 on managed thread 25 [2017-09-28 08:02:05.706 GMT 1 VERBOSE 100000 Runtime.Scheduler.WorkerPoolThread/7 127.0.0.1:11111] Started asynch agent Runtime.Scheduler.WorkerPoolThread/7 [2017-09-28 08:02:05.707 GMT 26 INFO 100000 Runtime.Scheduler.WorkerPoolThread/7 127.0.0.1:11111] Starting AsyncAgent Runtime.Scheduler.WorkerPoolThread/7 on managed thread 26 [2017-09-28 08:02:05.709 GMT 1 VERBOSE 100000 Runtime.Messaging.IncomingMessageAcceptor 127.0.0.1:11111] Started asynch agent Runtime.Messaging.IncomingMessageAcceptor [2017-09-28 08:02:05.710 GMT 28 INFO 100000 Runtime.Messaging.IncomingMessageAcceptor 127.0.0.1:11111] Starting AsyncAgent Runtime.Messaging.IncomingMessageAcceptor on managed thread 28 [2017-09-28 08:02:05.712 GMT 1 VERBOSE 100000 Runtime.Messaging.SiloMessageSender/PingSender 127.0.0.1:11111] Started asynch agent Runtime.Messaging.SiloMessageSender/PingSender [2017-09-28 08:02:05.714 GMT 29 INFO 100000 Runtime.Messaging.SiloMessageSender/PingSender 127.0.0.1:11111] Starting AsyncAgent Runtime.Messaging.SiloMessageSender/PingSender on managed thread 29 [2017-09-28 08:02:05.716 GMT 1 VERBOSE 100000 Runtime.Messaging.SiloMessageSender/SystemSender 127.0.0.1:11111] Started asynch agent Runtime.Messaging.SiloMessageSender/SystemSender [2017-09-28 08:02:05.718 GMT 30 INFO 100000 Runtime.Messaging.SiloMessageSender/SystemSender 127.0.0.1:11111] Starting AsyncAgent Runtime.Messaging.SiloMessageSender/SystemSender on managed thread 30 [2017-09-28 08:02:05.739 GMT 28 INFO 100328 Runtime.Messaging.IncomingMessageAcceptor 127.0.0.1:11111] Stopping AsyncAgent Runtime.Messaging.IncomingMessageAcceptor that runs on managed thread 28 [2017-09-28 08:02:05.764 GMT 1 VERBOSE 100000 Runtime.Messaging.IncomingMessageAgent/Ping 127.0.0.1:11111] Started asynch agent Runtime.Messaging.IncomingMessageAgent/Ping [2017-09-28 08:02:05.767 GMT 36 INFO 100000 Runtime.Messaging.IncomingMessageAgent/Ping 127.0.0.1:11111] Starting AsyncAgent Runtime.Messaging.IncomingMessageAgent/Ping on managed thread 36 [2017-09-28 08:02:05.792 GMT 1 VERBOSE 100000 Runtime.Messaging.IncomingMessageAgent/System 127.0.0.1:11111] Started asynch agent Runtime.Messaging.IncomingMessageAgent/System [2017-09-28 08:02:05.793 GMT 35 INFO 100000 Runtime.Messaging.IncomingMessageAgent/System 127.0.0.1:11111] Starting AsyncAgent Runtime.Messaging.IncomingMessageAgent/System on managed thread 35 [2017-09-28 08:02:05.818 GMT 1 VERBOSE 100000 Runtime.Messaging.IncomingMessageAgent/Application 127.0.0.1:11111] Started asynch agent Runtime.Messaging.IncomingMessageAgent/Application [2017-09-28 08:02:05.842 GMT 37 INFO 100000 Runtime.Messaging.IncomingMessageAgent/Application 127.0.0.1:11111] Starting AsyncAgent Runtime.Messaging.IncomingMessageAgent/Application on managed thread 37 [2017-09-28 08:02:05.849 GMT 1 VERBOSE 100000 Runtime.GrainDirectory.AdaptiveDirectoryCacheMaintainer`1 127.0.0.1:11111] Started asynch agent Runtime.GrainDirectory.AdaptiveDirectoryCacheMaintainer`1 [2017-09-28 08:02:05.851 GMT 33 INFO 100000 Runtime.GrainDirectory.AdaptiveDirectoryCacheMaintainer`1 127.0.0.1:11111] Starting AsyncAgent Runtime.GrainDirectory.AdaptiveDirectoryCacheMaintainer`1 on managed thread 33 [2017-09-28 08:02:05.852 GMT 1 VERBOSE 100000 Runtime.GrainDirectory.GlobalSingleInstanceActivationMaintainer 127.0.0.1:11111] Started asynch agent Runtime.GrainDirectory.GlobalSingleInstanceActivationMaintainer [2017-09-28 08:02:05.853 GMT 34 INFO 100000 Runtime.GrainDirectory.GlobalSingleInstanceActivationMaintainer 127.0.0.1:11111] Starting AsyncAgent Runtime.GrainDirectory.GlobalSingleInstanceActivationMaintainer on managed thread 34 [2017-09-28 08:02:05.882 GMT 34 INFO 100328 Runtime.GrainDirectory.GlobalSingleInstanceActivationMaintainer 127.0.0.1:11111] Stopping AsyncAgent Runtime.GrainDirectory.GlobalSingleInstanceActivationMaintainer that runs on managed thread 34 [2017-09-28 08:02:05.894 GMT 1 VERBOSE 100000 Silo 127.0.0.1:11111] Creating System Targets for this silo. [2017-09-28 08:02:05.897 GMT 1 VERBOSE 100000 Silo 127.0.0.1:11111] Creating SiloControl System Target [2017-09-28 08:02:05.904 GMT 1 VERBOSE 100000 Scheduler.ActivationTaskScheduler 127.0.0.1:11111] Created ActivationTaskScheduler-1:Queued=0 with SchedulingContext=[SystemTarget: S127.0.0.1:11111:244281717SiloControl@S0000000c] [2017-09-28 08:02:05.907 GMT 1 VERBOSE 100000 Silo 127.0.0.1:11111] Creating StreamProviderUpdateAgent System Target [2017-09-28 08:02:05.909 GMT 1 VERBOSE 100000 Scheduler.ActivationTaskScheduler 127.0.0.1:11111] Created ActivationTaskScheduler-2:Queued=0 with SchedulingContext=[SystemTarget: S127.0.0.1:11111:244281717@S00000019] [2017-09-28 08:02:05.912 GMT 1 VERBOSE 100000 Silo 127.0.0.1:11111] Creating ProtocolGateway System Target [2017-09-28 08:02:05.913 GMT 1 VERBOSE 100000 Scheduler.ActivationTaskScheduler 127.0.0.1:11111] Created ActivationTaskScheduler-3:Queued=0 with SchedulingContext=[SystemTarget: S127.0.0.1:11111:244281717ProtocolGateway@S0000001b] [2017-09-28 08:02:05.914 GMT 1 VERBOSE 100000 Silo 127.0.0.1:11111] Creating DeploymentLoadPublisher System Target [2017-09-28 08:02:05.915 GMT 1 VERBOSE 100000 Scheduler.ActivationTaskScheduler 127.0.0.1:11111] Created ActivationTaskScheduler-4:Queued=0 with SchedulingContext=[SystemTarget: S127.0.0.1:11111:244281717DeploymentLoadPublisherSystemTarget@S00000016] [2017-09-28 08:02:05.917 GMT 1 VERBOSE 100000 Silo 127.0.0.1:11111] Creating RemoteGrainDirectory + CacheValidator System Target [2017-09-28 08:02:05.919 GMT 1 VERBOSE 100000 Scheduler.ActivationTaskScheduler 127.0.0.1:11111] Created ActivationTaskScheduler-5:Queued=0 with SchedulingContext=[SystemTarget: S127.0.0.1:11111:244281717DirectoryService@S0000000a] [2017-09-28 08:02:05.922 GMT 1 VERBOSE 100000 Scheduler.ActivationTaskScheduler 127.0.0.1:11111] Created ActivationTaskScheduler-6:Queued=0 with SchedulingContext=[SystemTarget: S127.0.0.1:11111:244281717DirectoryCacheValidator@S0000000b] [2017-09-28 08:02:05.923 GMT 1 VERBOSE 100000 Silo 127.0.0.1:11111] Creating RemoteClusterGrainDirectory System Target [2017-09-28 08:02:05.924 GMT 1 VERBOSE 100000 Scheduler.ActivationTaskScheduler 127.0.0.1:11111] Created ActivationTaskScheduler-7:Queued=0 with SchedulingContext=[SystemTarget: S127.0.0.1:11111:244281717@S00000018] [2017-09-28 08:02:05.926 GMT 1 VERBOSE 100000 Silo 127.0.0.1:11111] Creating ClientObserverRegistrar + TypeManager System Target [2017-09-28 08:02:05.928 GMT 1 VERBOSE 100000 Scheduler.ActivationTaskScheduler 127.0.0.1:11111] Created ActivationTaskScheduler-8:Queued=0 with SchedulingContext=[SystemTarget: S127.0.0.1:11111:244281717ClientObserverRegistrar@S0000000d] [2017-09-28 08:02:05.930 GMT 1 VERBOSE 100000 Scheduler.ActivationTaskScheduler 127.0.0.1:11111] Created ActivationTaskScheduler-9:Queued=0 with SchedulingContext=[SystemTarget: S127.0.0.1:11111:244281717TypeManagerId@S00000011] [2017-09-28 08:02:05.931 GMT 1 VERBOSE 100000 Silo 127.0.0.1:11111] Creating MembershipOracle System Target [2017-09-28 08:02:05.932 GMT 1 VERBOSE 100000 Scheduler.ActivationTaskScheduler 127.0.0.1:11111] Created ActivationTaskScheduler-10:Queued=0 with SchedulingContext=[SystemTarget: S127.0.0.1:11111:244281717MembershipOracle@S0000000f] [2017-09-28 08:02:05.933 GMT 1 VERBOSE 100000 Silo 127.0.0.1:11111] Finished creating System Targets for this silo. [2017-09-28 08:02:05.948 GMT 1 INFO 100000 ReminderFactory 127.0.0.1:11111] Creating reminder grain service for type=Orleans.OrleansCodeGenReminderTableGrainReference [2017-09-28 08:02:05.955 GMT 1 VERBOSE 100000 Scheduler.ActivationTaskScheduler 127.0.0.1:11111] Created ActivationTaskScheduler-11:Queued=0 with SchedulingContext=[LowPrioritySystemTarget: S127.0.0.1:11111:244281717/567A1EA9/00000000@S00000000] [2017-09-28 08:02:05.959 GMT 1 VERBOSE 100000 Scheduler.ActivationTaskScheduler 127.0.0.1:11111] Created ActivationTaskScheduler-12:Queued=0 with SchedulingContext=[SystemTarget: S127.0.0.1:11111:244281717Catalog@S0000000e] [2017-09-28 08:02:05.983 GMT 1 VERBOSE 100000 Scheduler.ActivationTaskScheduler 127.0.0.1:11111] Created ActivationTaskScheduler-13:Queued=0 with SchedulingContext=[SystemTarget: S127.0.0.1:11111:244281717ProviderManagerSystemTarget@S00000013] [2017-09-28 08:02:05.997 GMT 23 INFO 100507 Catalog 127.0.0.1:11111] Before collection#1: memory=26MB, #activations=0, collector=<#Activations=0, #Buckets=0, buckets=[]>. [2017-09-28 08:02:06.002 GMT 27 INFO 103102 ProviderLoader/IStorageProvider 127.0.0.1:11111] Loaded provider of type Orleans.Storage.MemoryStorage Name=Default [2017-09-28 08:02:06.004 GMT 23 INFO 100508 Catalog 127.0.0.1:11111] After collection#1: memory=26MB, #activations=0, collected 0 activations, collector=<#Activations=0, #Buckets=0, buckets=[]>, collection time=00:00:00.0102928. [2017-09-28 08:02:06.025 GMT 27 INFO 103102 ProviderLoader/IStorageProvider 127.0.0.1:11111] Loaded provider of type Orleans.Storage.MemoryStorage Name=PubSubStore [2017-09-28 08:02:06.030 GMT 27 VERBOSE 103114 ProviderLoader/IStorageProvider 127.0.0.1:11111] Provider of type Orleans.Storage.MemoryStorage name Default located ok. [2017-09-28 08:02:06.032 GMT 27 VERBOSE 103114 ProviderLoader/IStorageProvider 127.0.0.1:11111] Provider of type Orleans.Storage.MemoryStorage name PubSubStore located ok. [2017-09-28 08:02:06.039 GMT 27 INFO 0 Storage.MemoryStorage.1 127.0.0.1:11111] Init: Name=Default NumStorageGrains=10 [2017-09-28 08:02:06.042 GMT 27 INFO 0 Storage.MemoryStorage.2 127.0.0.1:11111] Init: Name=PubSubStore NumStorageGrains=10 [2017-09-28 08:02:06.048 GMT 1 VERBOSE 100000 Silo 127.0.0.1:11111] Storage provider manager created successfully. [2017-09-28 08:02:06.051 GMT 1 VERBOSE 100000 Silo 127.0.0.1:11111] Log consistency provider manager created successfully. [2017-09-28 08:02:06.057 GMT 5 INFO 100000 TypeManager 127.0.0.1:11111] OnRefreshClusterMapTimer: refresh start [2017-09-28 08:02:06.060 GMT 27 INFO 103102 ProviderLoader/IStreamProviderImpl 127.0.0.1:11111] Loaded provider of type Orleans.Providers.Streams.SimpleMessageStream.SimpleMessageStreamProvider Name=SMSProvider [2017-09-28 08:02:06.086 GMT 27 VERBOSE 103114 ProviderLoader/IStreamProviderImpl 127.0.0.1:11111] Provider of type Orleans.Providers.Streams.SimpleMessageStream.SimpleMessageStreamProvider name SMSProvider located ok. [2017-09-28 08:02:06.092 GMT 27 INFO 0 SimpleMessageStreamProvider 127.0.0.1:11111] Initialized SimpleMessageStreamProvider with name SMSProvider and with property FireAndForgetDelivery: True, OptimizeForImmutableData: True and PubSubType: ExplicitGrainBasedAndImplicit [2017-09-28 08:02:06.096 GMT 1 VERBOSE 100000 Silo 127.0.0.1:11111] Stream provider manager created successfully. [2017-09-28 08:02:06.103 GMT 26 INFO 100603 MembershipOracle 127.0.0.1:11111] MembershipOracle starting on host = ShlomiWeizmann address = S127.0.0.1:11111:244281717 at 2017-09-28 08:02:05.284 GMT, backOffMax = 00:00:20 [2017-09-28 08:02:06.111 GMT 26 INFO 100635 MembershipTableFactory 127.0.0.1:11111] Creating membership table grain [2017-09-28 08:02:06.118 GMT 26 VERBOSE 100000 Scheduler.ActivationTaskScheduler 127.0.0.1:11111] Created ActivationTaskScheduler-14:Queued=0 with SchedulingContext=[Activation: S127.0.0.1:11111:244281717MembershipTableGrain@43b0c5acSystemPlacement State=Create] [2017-09-28 08:02:06.131 GMT 26 VERBOSE 100000 Catalog 127.0.0.1:11111] CreateGrainInstance MembershipTableGrain@43b0c5ac [2017-09-28 08:02:06.168 GMT 20 VERBOSE 100511 Catalog 127.0.0.1:11111] About to call Orleans.Runtime.MembershipService.GrainBasedMembershipTable grain's OnActivateAsync() method [Activation: S127.0.0.1:11111:244281717MembershipTableGrain@43b0c5ac #GrainType=Orleans.Runtime.MembershipService.GrainBasedMembershipTable Placement=SystemPlacement State=Activating] [2017-09-28 08:02:06.174 GMT 20 INFO 100637 GrainBasedMembershipTable 127.0.0.1:11111] GrainBasedMembershipTable Activated. [2017-09-28 08:02:06.178 GMT 20 VERBOSE 100512 Catalog 127.0.0.1:11111] Returned from calling Orleans.Runtime.MembershipService.GrainBasedMembershipTable grain's OnActivateAsync() method [Activation: S127.0.0.1:11111:244281717MembershipTableGrain@43b0c5ac #GrainType=Orleans.Runtime.MembershipService.GrainBasedMembershipTable Placement=SystemPlacement State=Activating] [2017-09-28 08:02:06.183 GMT 25 VERBOSE 100000 Catalog 127.0.0.1:11111] InitActivation is done: S127.0.0.1:11111:244281717MembershipTableGrain@43b0c5ac [2017-09-28 08:02:06.275 GMT 27 INFO 100631 MembershipTableFactory 127.0.0.1:11111] -Connected to membership table provider. [2017-09-28 08:02:06.319 GMT 24 INFO 100000 GrainBasedMembershipTable 127.0.0.1:11111] InitializeMembershipTable True. [2017-09-28 08:02:07.419 GMT 27 VERBOSE 100000 MembershipOracle 127.0.0.1:11111] -Attempting CleanupTableEntries #0 [2017-09-28 08:02:07.430 GMT 27 INFO 100652 MembershipOracle 127.0.0.1:11111] -CleanupTable called on silo startup. Membership table 0 silos, 0 are Active, 0 are Dead, Version=<0, 0>. All silos: [] [2017-09-28 08:02:07.440 GMT 27 VERBOSE 100000 MembershipOracle 127.0.0.1:11111] -Going to try to TryUpdateMyStatusGlobalOnce #0 [2017-09-28 08:02:07.457 GMT 27 VERBOSE 100000 MembershipOracle 127.0.0.1:11111] -TryUpdateMyStatusGlobalOnce: Read my entry from Membership table 0 silos, 0 are Active, 0 are Dead, Version=<0, 0>. All silos: [] [2017-09-28 08:02:07.472 GMT 23 VERBOSE 100000 GrainBasedMembershipTable 127.0.0.1:11111] InsertRow entry = SiloAddress=S127.0.0.1:11111:244281717 SiloName=localhost Status=Joining, table version = <1, 0> [2017-09-28 08:02:07.480 GMT 27 VERBOSE 100000 MembershipOracle 127.0.0.1:11111] -Silo S127.0.0.1:11111:244281717 Successfully updated my Status in the Membership table to Joining [2017-09-28 08:02:07.496 GMT 27 INFO 100660 MembershipOracle 127.0.0.1:11111] Starting IAmAliveUpdateTimer. [2017-09-28 08:02:07.520 GMT 26 VERBOSE 100000 GrainBasedMembershipTable 127.0.0.1:11111] UpdateIAmAlive entry = SiloAddress=S127.0.0.1:11111:244281717 SiloName= Status=None [2017-09-28 08:02:07.551 GMT 27 VERBOSE 100000 MembershipOracle 127.0.0.1:11111] -ReadAll Membership table 1 silos, 0 are Active, 0 are Dead, 1 are Joining, Version=<1, 2>. All silos: [SiloAddress=S127.0.0.1:11111:244281717 SiloName=localhost Status=Joining] [2017-09-28 08:02:07.554 GMT 1 VERBOSE 100000 Silo 127.0.0.1:11111] Local silo status oracle created successfully. [2017-09-28 08:02:07.558 GMT 20 INFO 100604 MembershipOracle 127.0.0.1:11111] -BecomeActive [2017-09-28 08:02:07.561 GMT 20 VERBOSE 100000 MembershipOracle 127.0.0.1:11111] -Going to try to TryUpdateMyStatusGlobalOnce #0 [2017-09-28 08:02:07.567 GMT 20 VERBOSE 100000 MembershipOracle 127.0.0.1:11111] -TryUpdateMyStatusGlobalOnce: ReadAll Membership table 1 silos, 0 are Active, 0 are Dead, 1 are Joining, Version=<1, 2>. All silos: [SiloAddress=S127.0.0.1:11111:244281717 SiloName=localhost Status=Joining] [2017-09-28 08:02:07.573 GMT 20 INFO 100614 MembershipOracle 127.0.0.1:11111] About to send pings to 0 nodes in order to validate communication in the Joining state. Pinged nodes = [] [2017-09-28 08:02:07.581 GMT 23 VERBOSE 100000 GrainBasedMembershipTable 127.0.0.1:11111] UpdateRow entry = SiloAddress=S127.0.0.1:11111:244281717 SiloName=localhost Status=Active, etag = 3, table version = <2, 2> [2017-09-28 08:02:07.608 GMT 27 VERBOSE 100000 MembershipOracle 127.0.0.1:11111] -Silo S127.0.0.1:11111:244281717 Successfully updated my Status in the Membership table to Active [2017-09-28 08:02:07.616 GMT 27 INFO 100634 MembershipOracle 127.0.0.1:11111] -ReadAll (called from BecomeActive) Membership table 1 silos, 1 are Active, 0 are Dead, Version=<2, 5>. All silos: [SiloAddress=S127.0.0.1:11111:244281717 SiloName=localhost Status=Active] [2017-09-28 08:02:07.623 GMT 27 INFO 100605 MembershipOracle 127.0.0.1:11111] -Finished BecomeActive. [2017-09-28 08:02:07.624 GMT 1 VERBOSE 100000 Silo 127.0.0.1:11111] Local silo status oracle became active successfully. [2017-09-28 08:02:07.648 GMT 1 INFO 100702 WindowsPerfCountersStatistics 127.0.0.1:11111] Starting Windows perf counter stats collection with frequency=00:00:30 [2017-09-28 08:02:07.666 GMT 1 INFO 100714 SiloPerformanceMetrics 127.0.0.1:11111] Starting Silo Table metrics reporter with reportFrequency=00:00:30 [2017-09-28 08:02:07.671 GMT 1 VERBOSE 100000 Silo 127.0.0.1:11111] Silo statistics manager started successfully. [2017-09-28 08:02:07.674 GMT 27 INFO 100000 DeploymentLoadPublisher 127.0.0.1:11111] Starting DeploymentLoadPublisher. [2017-09-28 08:02:07.680 GMT 27 VERBOSE 100000 DeploymentLoadPublisher 127.0.0.1:11111] RefreshStatistics. [2017-09-28 08:02:07.695 GMT 26 VERBOSE 100000 SiloControl 127.0.0.1:11111] GetRuntimeStatistics [2017-09-28 08:02:07.751 GMT 27 INFO 100000 DeploymentLoadPublisher 127.0.0.1:11111] Started DeploymentLoadPublisher. [2017-09-28 08:02:07.753 GMT 1 VERBOSE 100000 Silo 127.0.0.1:11111] Silo deployment load publisher started successfully. [2017-09-28 08:02:07.776 GMT 1 INFO 100000 Watchdog 127.0.0.1:11111] Starting Silo Watchdog. [2017-09-28 08:02:07.779 GMT 1 VERBOSE 100000 Runtime.Watchdog 127.0.0.1:11111] Started asynch agent Runtime.Watchdog [2017-09-28 08:02:07.801 GMT 39 INFO 100000 Runtime.Watchdog 127.0.0.1:11111] Starting AsyncAgent Runtime.Watchdog on managed thread 39 [2017-09-28 08:02:07.825 GMT 1 VERBOSE 100000 Silo 127.0.0.1:11111] Silo platform watchdog started successfully. [2017-09-28 08:02:07.889 GMT 27 VERBOSE 100000 Scheduler.ActivationTaskScheduler 127.0.0.1:11111] Created ActivationTaskScheduler-15:Queued=0 with SchedulingContext=[Activation: S127.0.0.1:11111:244281717*grn/FCB3F509/00003039@a6bf2a8dRandomPlacement State=Create] [2017-09-28 08:02:07.893 GMT 27 VERBOSE 100000 Catalog 127.0.0.1:11111] CreateGrainInstance *grn/FCB3F509/00003039@a6bf2a8d [2017-09-28 08:02:07.904 GMT 25 VERBOSE 100511 Catalog 127.0.0.1:11111] About to call Orleans.Runtime.ReminderService.GrainBasedReminderTable grain's OnActivateAsync() method [Activation: S127.0.0.1:11111:244281717*grn/FCB3F509/00003039@a6bf2a8d #GrainType=Orleans.Runtime.ReminderService.GrainBasedReminderTable Placement=RandomPlacement State=Activating] [2017-09-28 08:02:07.913 GMT 25 VERBOSE 100512 Catalog 127.0.0.1:11111] Returned from calling Orleans.Runtime.ReminderService.GrainBasedReminderTable grain's OnActivateAsync() method [Activation: S127.0.0.1:11111:244281717*grn/FCB3F509/00003039@a6bf2a8d #GrainType=Orleans.Runtime.ReminderService.GrainBasedReminderTable Placement=RandomPlacement State=Activating] [2017-09-28 08:02:07.923 GMT 27 VERBOSE 100000 Catalog 127.0.0.1:11111] InitActivation is done: S127.0.0.1:11111:244281717*grn/FCB3F509/00003039@a6bf2a8d [2017-09-28 08:02:08.336 GMT 22 VERBOSE 100000 MembershipOracle 127.0.0.1:11111] -ReadAll (called from timer) Membership table 1 silos, 1 are Active, 0 are Dead, Version=<2, 5>. All silos: [SiloAddress=S127.0.0.1:11111:244281717 SiloName=localhost Status=Active] [2017-09-28 08:02:09.087 GMT 1 VERBOSE 100000 Silo 127.0.0.1:11111] Reminder service started successfully. [2017-09-28 08:02:09.091 GMT 19 WARNING 101215 Scheduler.WorkItemGroup 127.0.0.1:11111] Task [Id=416, Status=RanToCompletion] in WorkGroup [LowPrioritySystemTarget: S127.0.0.1:11111:244281717/567A1EA9/00000000@S00000000] took elapsed time 0:00:01.137108 for execution, which is longer than 00:00:00.2000000. Running on thread [2017-09-28 08:02:09.098 GMT 27 INFO 103102 ProviderLoader/IBootstrapProvider 127.0.0.1:11111] Loaded provider of type NG.Server.Game.Startup.NGBootstrapProvider Name=NGProvider [2017-09-28 08:02:09.180 GMT 27 VERBOSE 103114 ProviderLoader/IBootstrapProvider 127.0.0.1:11111] Provider of type NG.Server.Game.Startup.NGBootstrapProvider name NGProvider located ok. [2017-09-28 08:02:09.205 GMT 27 INFO 100437 BootstrapProviderManager 127.0.0.1:11111] Calling Init for IBootstrapProvider classes [2017-09-28 08:02:09.239 GMT 24 VERBOSE 100000 Scheduler.ActivationTaskScheduler 127.0.0.1:11111] Created ActivationTaskScheduler-16:Queued=0 with SchedulingContext=[Activation: S127.0.0.1:11111:244281717*grn/D2BA6D64/00000000@155aecbeStatelessWorkerPlacement State=Create] [2017-09-28 08:02:09.265 GMT 24 VERBOSE 100000 Catalog 127.0.0.1:11111] CreateGrainInstance *grn/D2BA6D64/00000000@155aecbe [2017-09-28 08:02:09.270 GMT 26 VERBOSE 100511 Catalog 127.0.0.1:11111] About to call NG.Server.Game.Utils.UtilityGrain grain's OnActivateAsync() method [Activation: S127.0.0.1:11111:244281717*grn/D2BA6D64/00000000@155aecbe #GrainType=NG.Server.Game.Utils.UtilityGrain Placement=StatelessWorkerPlacement State=Activating] [2017-09-28 08:02:09.301 GMT 26 VERBOSE 100512 Catalog 127.0.0.1:11111] Returned from calling NG.Server.Game.Utils.UtilityGrain grain's OnActivateAsync() method [Activation: S127.0.0.1:11111:244281717*grn/D2BA6D64/00000000@155aecbe #GrainType=NG.Server.Game.Utils.UtilityGrain Placement=StatelessWorkerPlacement State=Activating] [2017-09-28 08:02:09.351 GMT 27 VERBOSE 100000 Catalog 127.0.0.1:11111] InitActivation is done: S127.0.0.1:11111:244281717*grn/D2BA6D64/00000000@155aecbe [2017-09-28 08:02:09.377 GMT 26 VERBOSE 100298 Interner-StreamId 127.0.0.1:11111] Starting Interner-StreamId cache cleanup timer with frequency 00:10:00 [2017-09-28 08:02:09.403 GMT 26 VERBOSE 100000 StreamConsumer-Cache-00000000-0000-0000-0000-000000000000-SMSProvider 127.0.0.1:11111] Subscribe Observer=Orleans.Streams.GenericAsyncObserver`1[System.String] Token= [2017-09-28 08:02:09.430 GMT 26 VERBOSE 100000 StreamConsumer-Cache-00000000-0000-0000-0000-000000000000-SMSProvider 127.0.0.1:11111] BindExtensionLazy - Binding local extension to stream runtime=Orleans.Runtime.Providers.SiloProviderRuntime [2017-09-28 08:02:09.459 GMT 26 VERBOSE 100000 StreamConsumer-Cache-00000000-0000-0000-0000-000000000000-SMSProvider 127.0.0.1:11111] BindExtensionLazy - Connected Extension=Orleans.Streams.StreamConsumerExtension GrainRef=GrainReference:*grn/D2BA6D64/00000000 [2017-09-28 08:02:09.462 GMT 26 VERBOSE 100000 StreamConsumer-Cache-00000000-0000-0000-0000-000000000000-SMSProvider 127.0.0.1:11111] Subscribe - Connecting to Rendezvous Orleans.Streams.StreamPubSubImpl My GrainRef=GrainReference:*grn/D2BA6D64/00000000 Token= [2017-09-28 08:02:09.470 GMT 26 VERBOSE 100298 Interner-GuidId 127.0.0.1:11111] Starting Interner-GuidId cache cleanup timer with frequency 00:10:00 [2017-09-28 08:02:09.477 GMT 26 VERBOSE 0 StreamConsumerExtension 127.0.0.1:11111] S127.0.0.1:11111:244281717*grn/D2BA6D64/00000000@155aecbe AddObserver for stream Cache-00000000-0000-0000-0000-000000000000-SMSProvider [2017-09-28 08:02:09.540 GMT 27 VERBOSE 100000 Scheduler.ActivationTaskScheduler 127.0.0.1:11111] Created ActivationTaskScheduler-17:Queued=0 with SchedulingContext=[Activation: S127.0.0.1:11111:244281717*grn/716E8E94/00000000+SMSProvider_Cache@5fd62ab9RandomPlacement State=Create] [2017-09-28 08:02:09.552 GMT 27 VERBOSE 100000 Catalog 127.0.0.1:11111] CreateGrainInstance *grn/716E8E94/00000000+SMSProvider_Cache@5fd62ab9 [2017-09-28 08:02:09.590 GMT 27 VERBOSE 100000 Scheduler.ActivationTaskScheduler 127.0.0.1:11111] Created ActivationTaskScheduler-18:Queued=0 with SchedulingContext=[Activation: S127.0.0.1:11111:244281717*grn/30D642F0/00000000@e160a586RandomPlacement State=Create] [2017-09-28 08:02:09.617 GMT 27 VERBOSE 100000 Catalog 127.0.0.1:11111] CreateGrainInstance *grn/30D642F0/00000000@e160a586 [2017-09-28 08:02:09.620 GMT 23 VERBOSE 100511 Catalog 127.0.0.1:11111] About to call Orleans.Storage.MemoryStorageGrain grain's OnActivateAsync() method [Activation: S127.0.0.1:11111:244281717*grn/30D642F0/00000000@e160a586 #GrainType=Orleans.Storage.MemoryStorageGrain Placement=RandomPlacement State=Activating] [2017-09-28 08:02:09.647 GMT 23 INFO 0 MemoryStorageGrain ] OnActivateAsync [2017-09-28 08:02:09.649 GMT 23 VERBOSE 100512 Catalog 127.0.0.1:11111] Returned from calling Orleans.Storage.MemoryStorageGrain grain's OnActivateAsync() method [Activation: S127.0.0.1:11111:244281717*grn/30D642F0/00000000@e160a586 #GrainType=Orleans.Storage.MemoryStorageGrain Placement=RandomPlacement State=Activating] [2017-09-28 08:02:09.653 GMT 27 VERBOSE 100000 Catalog 127.0.0.1:11111] InitActivation is done: S127.0.0.1:11111:244281717*grn/30D642F0/00000000@e160a586 [2017-09-28 08:02:09.656 GMT 23 VERBOSE 0 MemoryStorageGrain ] ReadStateAsync for MemoryStorage grain: GrainType=Orleans.Streams.PubSubRendezvousGrain+GrainId=GrainReference=0000000000000000000000000000000006000000716e8e94+SMSProvider_Cache [2017-09-28 08:02:09.661 GMT 20 VERBOSE 100511 Catalog 127.0.0.1:11111] About to call Orleans.Streams.PubSubRendezvousGrain grain's OnActivateAsync() method [Activation: S127.0.0.1:11111:244281717*grn/716E8E94/00000000+SMSProvider_Cache@5fd62ab9 #GrainType=Orleans.Streams.PubSubRendezvousGrain Placement=RandomPlacement State=Activating] [2017-09-28 08:02:09.687 GMT 20 INFO 0 PubSubRendezvousGrain-S127.0.0.1:11111:244281717-*grn/716E8E94/0000000000000000000000000000000006000000716e8e94+SMSProvider_Cache-0x83655FEF ] OnActivateAsync. Now have total of 0 producers and 0 consumers. All Consumers = [], All Producers = [] [2017-09-28 08:02:09.691 GMT 20 VERBOSE 100512 Catalog 127.0.0.1:11111] Returned from calling Orleans.Streams.PubSubRendezvousGrain grain's OnActivateAsync() method [Activation: S127.0.0.1:11111:244281717*grn/716E8E94/00000000+SMSProvider_Cache@5fd62ab9 #GrainType=Orleans.Streams.PubSubRendezvousGrain Placement=RandomPlacement State=Activating] [2017-09-28 08:02:09.693 GMT 27 VERBOSE 100000 Catalog 127.0.0.1:11111] InitActivation is done: S127.0.0.1:11111:244281717*grn/716E8E94/00000000+SMSProvider_Cache@5fd62ab9 [2017-09-28 08:02:09.722 GMT 20 INFO 0 PubSubRendezvousGrain-S127.0.0.1:11111:244281717-*grn/716E8E94/0000000000000000000000000000000006000000716e8e94+SMSProvider_Cache-0x83655FEF ] RegisterConsumer GrainReference:*grn/D2BA6D64/00000000. // Orleans Grain register 'Cache' stream Now have total of 0 producers and 1 consumers. All Consumers = [PubSubSubscriptionState:SubscriptionId=d446511b-28c7-4197-8124-858613fba816,StreamId=Cache-00000000-0000-0000-0000-000000000000-SMSProvider, Consumer=GrainReference:*grn/D2BA6D64/00000000.], All Producers = [] [2017-09-28 08:02:09.740 GMT 24 VERBOSE 0 MemoryStorageGrain ] WriteStateAsync for MemoryStorage grain: GrainType=Orleans.Streams.PubSubRendezvousGrain+GrainId=GrainReference=0000000000000000000000000000000006000000716e8e94+SMSProvider_Cache eTag: [2017-09-28 08:02:09.742 GMT 24 VERBOSE 0 MemoryStorageGrain ] Done WriteStateAsync for MemoryStorage grain: GrainType=Orleans.Streams.PubSubRendezvousGrain+GrainId=GrainReference=0000000000000000000000000000000006000000716e8e94+SMSProvider_Cache eTag: a85b4b8bf400496997a2f1e219986ac7 [2017-09-28 08:02:10.276 GMT 20 WARNING 101215 Scheduler.WorkItemGroup 127.0.0.1:11111] Task [Id=866, Status=RanToCompletion] in WorkGroup [Activation: S127.0.0.1:11111:244281717*grn/D2BA6D64/00000000@155aecbe #GrainType=NG.Server.Game.Utils.UtilityGrain Placement=StatelessWorkerPlacement State=Valid] took elapsed time 0:00:00.4845985 for execution, which is longer than 00:00:00.2000000. Running on thread [2017-09-28 08:02:11.675 GMT 1 VERBOSE 100000 Silo 127.0.0.1:11111] App bootstrap calls done successfully. [2017-09-28 08:02:11.677 GMT 1 VERBOSE 100000 Silo 127.0.0.1:11111] Stream providers started successfully. [2017-09-28 08:02:11.705 GMT 1 VERBOSE 100000 Runtime.Messaging.GatewayAcceptor 127.0.0.1:11111] Started asynch agent Runtime.Messaging.GatewayAcceptor [2017-09-28 08:02:11.706 GMT 27 VERBOSE 100000 ClientObserverRegistrar 127.0.0.1:11111] Client registrar service started successfully. [2017-09-28 08:02:11.709 GMT 1 VERBOSE 100000 Runtime.Messaging.GatewayClientCleanupAgent 127.0.0.1:11111] Started asynch agent Runtime.Messaging.GatewayClientCleanupAgent [2017-09-28 08:02:11.709 GMT 31 INFO 100000 Runtime.Messaging.GatewayAcceptor 127.0.0.1:11111] Starting AsyncAgent Runtime.Messaging.GatewayAcceptor on managed thread 31 [2017-09-28 08:02:11.732 GMT 32 INFO 100000 Runtime.Messaging.GatewayClientCleanupAgent 127.0.0.1:11111] Starting AsyncAgent Runtime.Messaging.GatewayClientCleanupAgent on managed thread 32 [2017-09-28 08:02:11.775 GMT 1 VERBOSE 100000 Silo 127.0.0.1:11111] Message gateway service started successfully. [2017-09-28 08:02:11.796 GMT 31 INFO 100328 Runtime.Messaging.GatewayAcceptor 127.0.0.1:11111] Stopping AsyncAgent Runtime.Messaging.GatewayAcceptor that runs on managed thread 31 [2017-09-28 08:02:11.802 GMT 1 VERBOSE 100000 Silo 127.0.0.1:11111] Silo.Start complete: System status = Running [2017-09-28 08:02:11.810 GMT 1 INFO 100424 OrleansSiloHost 127.0.0.1:11111] Silo startup event name: localhost [2017-09-28 08:02:11.818 GMT 1 INFO 100425 OrleansSiloHost 127.0.0.1:11111] Created and set startup event localhost [2017-09-28 08:02:11.823 GMT 1 INFO 100402 OrleansSiloHost 127.0.0.1:11111] Silo localhost started successfully [2017-09-28 08:02:37.655 GMT 12 VERBOSE 100000 OrleansCounterManager 127.0.0.1:11111] Writing counters. [2017-09-28 08:03:06.032 GMT 27 INFO 100507 Catalog 127.0.0.1:11111] Before collection#2: memory=88MB, #activations=5, collector=<#Activations=2, #Buckets=1, buckets=[1h:59m:53s.969ms->2 items]>. [2017-09-28 08:03:06.043 GMT 27 INFO 100508 Catalog 127.0.0.1:11111] After collection#2: memory=88MB, #activations=5, collected 0 activations, collector=<#Activations=2, #Buckets=1, buckets=[1h:59m:53s.956ms->2 items]>, collection time=00:00:00.0131731. [2017-09-28 08:03:06.119 GMT 12 INFO 100000 TypeManager 127.0.0.1:11111] OnRefreshClusterMapTimer: refresh start [2017-09-28 08:03:07.796 GMT 13 VERBOSE 100000 OrleansCounterManager 127.0.0.1:11111] Writing counters. [2017-09-28 08:03:08.335 GMT 27 VERBOSE 100000 MembershipOracle 127.0.0.1:11111] -ReadAll (called from timer) Membership table 1 silos, 1 are Active, 0 are Dead, Version=<2, 5>. All silos: [SiloAddress=S127.0.0.1:11111:244281717 SiloName=localhost Status=Active] [2017-09-28 08:03:37.856 GMT 13 VERBOSE 100000 OrleansCounterManager 127.0.0.1:11111] Writing counters. [2017-09-28 08:03:42.825 GMT 38 VERBOSE 100000 Runtime.Messaging.GatewayAcceptor 127.0.0.1:11111] Received a connection from 127.0.0.1:65505 [2017-09-28 08:03:42.837 GMT 38 INFO 101301 Orleans.Messaging.Gateway 127.0.0.1:11111] Recorded opened socket from endpoint 127.0.0.1:65505, client ID *cli/26a0e3ab. [2017-09-28 08:03:42.874 GMT 47 VERBOSE 100000 Dispatcher 127.0.0.1:11111] Resend Request S127.0.0.1:11111:244281717*cli/26a0e3ab@98001cb1->S127.0.0.1:11111:244281717TypeManagerId@S00000011 #2: global::Orleans.Runtime.IClusterTypeManager:GetClusterTypeCodeMap() [2017-09-28 08:03:42.895 GMT 27 VERBOSE 100000 Runtime.Messaging.GatewaySender/GatewaySiloSender_0 127.0.0.1:11111] Started asynch agent Runtime.Messaging.GatewaySender/GatewaySiloSender_0 [2017-09-28 08:03:42.897 GMT 52 INFO 100000 Runtime.Messaging.GatewaySender/GatewaySiloSender_0 127.0.0.1:11111] Starting AsyncAgent Runtime.Messaging.GatewaySender/GatewaySiloSender_0 on managed thread 52 [2017-09-28 08:03:42.998 GMT 51 VERBOSE 100000 Dispatcher 127.0.0.1:11111] Resend Request S127.0.0.1:11111:244281717*cli/26a0e3ab@98001cb1->S127.0.0.1:11111:244281717TypeManagerId@S00000011 #3: global::Orleans.Runtime.IClusterTypeManager:GetImplicitStreamSubscriberTable() [2017-09-28 08:03:43.092 GMT 51 VERBOSE 100000 Dispatcher 127.0.0.1:11111] Resend Request S127.0.0.1:11111:244281717*cli/26a0e3ab@98001cb1->*grn/716E8E94/00000000+SMSProvider_Cache #4: global::Orleans.Streams.IPubSubRendezvousGrain:RegisterConsumer() [2017-09-28 08:03:43.100 GMT 25 INFO 0 PubSubRendezvousGrain-S127.0.0.1:11111:244281717-*grn/716E8E94/0000000000000000000000000000000006000000716e8e94+SMSProvider_Cache-0x83655FEF ] RegisterConsumer ObserverId:*cli/26a0e3ab/381ebc0c-296f-42b5-bc73-854eaa372bc0. // Client also register 'Cache' stream Now have total of 0 producers and 2 consumers. All Consumers = [PubSubSubscriptionState:SubscriptionId=d446511b-28c7-4197-8124-858613fba816,StreamId=Cache-00000000-0000-0000-0000-000000000000-SMSProvider, Consumer=GrainReference:*grn/D2BA6D64/00000000., PubSubSubscriptionState:SubscriptionId=a979b7d6-2ddd-4dc5-8879-51afd7516447,StreamId=Cache-00000000-0000-0000-0000-000000000000-SMSProvider, Consumer=ObserverId:*cli/26a0e3ab/381ebc0c-296f-42b5-bc73-854eaa372bc0.], All Producers = [] [2017-09-28 08:03:43.110 GMT 21 VERBOSE 0 MemoryStorageGrain ] WriteStateAsync for MemoryStorage grain: GrainType=Orleans.Streams.PubSubRendezvousGrain+GrainId=GrainReference=0000000000000000000000000000000006000000716e8e94+SMSProvider_Cache eTag: a85b4b8bf400496997a2f1e219986ac7 [2017-09-28 08:03:43.116 GMT 21 VERBOSE 0 MemoryStorageGrain ] Done WriteStateAsync for MemoryStorage grain: GrainType=Orleans.Streams.PubSubRendezvousGrain+GrainId=GrainReference=0000000000000000000000000000000006000000716e8e94+SMSProvider_Cache eTag: 5512bf17f02143068d97e7309b6e6abd [2017-09-28 08:03:43.155 GMT 51 VERBOSE 100000 Dispatcher 127.0.0.1:11111] Resend Request S127.0.0.1:11111:244281717*cli/26a0e3ab@98001cb1->*grn/716E8E94/00000000+SMSProvider_Cache #5: global::Orleans.Streams.IPubSubRendezvousGrain:RegisterProducer() [2017-09-28 08:03:43.165 GMT 25 INFO 0 PubSubRendezvousGrain-S127.0.0.1:11111:244281717-*grn/716E8E94/0000000000000000000000000000000006000000716e8e94+SMSProvider_Cache-0x83655FEF ] RegisterProducer ObserverId:*cli/26a0e3ab/f931ed78-6f13-49da-8641-6f2ac0cf3490. // Client publishes event to the 'Cache' stream and becomes a Producer Now have total of 1 producers and 2 consumers. All Consumers = [PubSubSubscriptionState:SubscriptionId=d446511b-28c7-4197-8124-858613fba816,StreamId=Cache-00000000-0000-0000-0000-000000000000-SMSProvider, Consumer=GrainReference:*grn/D2BA6D64/00000000., PubSubSubscriptionState:SubscriptionId=a979b7d6-2ddd-4dc5-8879-51afd7516447,StreamId=Cache-00000000-0000-0000-0000-000000000000-SMSProvider, Consumer=ObserverId:*cli/26a0e3ab/381ebc0c-296f-42b5-bc73-854eaa372bc0.], All Producers = [PubSubPublisherState:StreamId=Cache-00000000-0000-0000-0000-000000000000-SMSProvider, Producer=ObserverId:*cli/26a0e3ab/f931ed78-6f13-49da-8641-6f2ac0cf3490.] [2017-09-28 08:03:43.179 GMT 26 VERBOSE 0 MemoryStorageGrain ] WriteStateAsync for MemoryStorage grain: GrainType=Orleans.Streams.PubSubRendezvousGrain+GrainId=GrainReference=0000000000000000000000000000000006000000716e8e94+SMSProvider_Cache eTag: 5512bf17f02143068d97e7309b6e6abd [2017-09-28 08:03:43.181 GMT 26 VERBOSE 0 MemoryStorageGrain ] Done WriteStateAsync for MemoryStorage grain: GrainType=Orleans.Streams.PubSubRendezvousGrain+GrainId=GrainReference=0000000000000000000000000000000006000000716e8e94+SMSProvider_Cache eTag: 4b2a28f2352b4a618b8a6c2bff54ebad [2017-09-28 08:03:43.204 GMT 51 VERBOSE 100000 Dispatcher 127.0.0.1:11111] Resend Request S127.0.0.1:11111:244281717*cli/26a0e3ab@98001cb1->*cli/26a0e3ab381ebc0c-296f-42b5-bc73-854eaa372bc0 #6: global::Orleans.Streams.IStreamConsumerExtension:DeliverImmutable() [2017-09-28 08:03:43.212 GMT 38 VERBOSE 100000 Dispatcher 127.0.0.1:11111] Resend Request S127.0.0.1:11111:244281717*cli/26a0e3ab@98001cb1->*grn/D2BA6D64/00000000 #7: global::Orleans.Streams.IStreamConsumerExtension:DeliverImmutable() // Somewhere here I've restarted the client, without gracefully shutting it down [2017-09-28 08:03:56.578 GMT 47 VERBOSE 100000 Runtime.Messaging.GatewayAcceptor 127.0.0.1:11111] Closing recieving socket: [2017-09-28 08:03:56.584 GMT 47 INFO 101302 Orleans.Messaging.Gateway 127.0.0.1:11111] Recorded closed socket from endpoint 127.0.0.1:65505, client ID *cli/26a0e3ab. [2017-09-28 08:04:04.281 GMT 19 WARNING 101215 Scheduler.WorkItemGroup 127.0.0.1:11111] Task [Id=3509, Status=RanToCompletion] in WorkGroup [LowPrioritySystemTarget: S127.0.0.1:11111:244281717/567A1EA9/00000000@S00000000] took elapsed time 0:00:00.6408641 for execution, which is longer than 00:00:00.2000000. Running on thread [2017-09-28 08:04:04.893 GMT 47 VERBOSE 100000 Runtime.Messaging.GatewayAcceptor 127.0.0.1:11111] Received a connection from 127.0.0.1:49197 [2017-09-28 08:04:04.900 GMT 47 INFO 101301 Orleans.Messaging.Gateway 127.0.0.1:11111] Recorded opened socket from endpoint 127.0.0.1:49197, client ID *cli/e8fd329c. [2017-09-28 08:04:04.918 GMT 47 VERBOSE 100000 Dispatcher 127.0.0.1:11111] Resend Request S127.0.0.1:11111:244281717*cli/e8fd329c@1adde38e->S127.0.0.1:11111:244281717TypeManagerId@S00000011 #2: global::Orleans.Runtime.IClusterTypeManager:GetClusterTypeCodeMap() [2017-09-28 08:04:04.922 GMT 27 VERBOSE 100000 Runtime.Messaging.GatewaySender/GatewaySiloSender_1 127.0.0.1:11111] Started asynch agent Runtime.Messaging.GatewaySender/GatewaySiloSender_1 [2017-09-28 08:04:04.924 GMT 58 INFO 100000 Runtime.Messaging.GatewaySender/GatewaySiloSender_1 127.0.0.1:11111] Starting AsyncAgent Runtime.Messaging.GatewaySender/GatewaySiloSender_1 on managed thread 58 [2017-09-28 08:04:04.974 GMT 47 VERBOSE 100000 Dispatcher 127.0.0.1:11111] Resend Request S127.0.0.1:11111:244281717*cli/e8fd329c@1adde38e->S127.0.0.1:11111:244281717TypeManagerId@S00000011 #3: global::Orleans.Runtime.IClusterTypeManager:GetImplicitStreamSubscriberTable() [2017-09-28 08:04:05.055 GMT 47 VERBOSE 100000 Dispatcher 127.0.0.1:11111] Resend Request S127.0.0.1:11111:244281717*cli/e8fd329c@1adde38e->*grn/716E8E94/00000000+SMSProvider_Cache #4: global::Orleans.Streams.IPubSubRendezvousGrain:RegisterConsumer() [2017-09-28 08:04:05.060 GMT 26 INFO 0 PubSubRendezvousGrain-S127.0.0.1:11111:244281717-*grn/716E8E94/0000000000000000000000000000000006000000716e8e94+SMSProvider_Cache-0x83655FEF ] RegisterConsumer ObserverId:*cli/e8fd329c/f7e8de56-f78f-448c-bcc0-7b0c0fdf9feb. // (new) Client tries to subscribe to the 'Cache' stream. As you can see - the Producer still exists in the list, though it's dead already. Now have total of 1 producers and 3 consumers. All Consumers = [PubSubSubscriptionState:SubscriptionId=d446511b-28c7-4197-8124-858613fba816,StreamId=Cache-00000000-0000-0000-0000-000000000000-SMSProvider, Consumer=GrainReference:*grn/D2BA6D64/00000000., PubSubSubscriptionState:SubscriptionId=a979b7d6-2ddd-4dc5-8879-51afd7516447,StreamId=Cache-00000000-0000-0000-0000-000000000000-SMSProvider, Consumer=ObserverId:*cli/26a0e3ab/381ebc0c-296f-42b5-bc73-854eaa372bc0., PubSubSubscriptionState:SubscriptionId=9887483b-33ff-4a7d-a30c-a79b15cf2d2e,StreamId=Cache-00000000-0000-0000-0000-000000000000-SMSProvider, Consumer=ObserverId:*cli/e8fd329c/f7e8de56-f78f-448c-bcc0-7b0c0fdf9feb.], All Producers = [PubSubPublisherState:StreamId=Cache-00000000-0000-0000-0000-000000000000-SMSProvider, Producer=ObserverId:*cli/26a0e3ab/f931ed78-6f13-49da-8641-6f2ac0cf3490.] [2017-09-28 08:04:05.090 GMT 24 VERBOSE 0 MemoryStorageGrain ] WriteStateAsync for MemoryStorage grain: GrainType=Orleans.Streams.PubSubRendezvousGrain+GrainId=GrainReference=0000000000000000000000000000000006000000716e8e94+SMSProvider_Cache eTag: 4b2a28f2352b4a618b8a6c2bff54ebad [2017-09-28 08:04:05.097 GMT 24 VERBOSE 0 MemoryStorageGrain ] Done WriteStateAsync for MemoryStorage grain: GrainType=Orleans.Streams.PubSubRendezvousGrain+GrainId=GrainReference=0000000000000000000000000000000006000000716e8e94+SMSProvider_Cache eTag: bdaa9abe0c544748a868de6bddd27e41 [2017-09-28 08:04:05.103 GMT 26 INFO 0 PubSubRendezvousGrain-S127.0.0.1:11111:244281717-*grn/716E8E94/0000000000000000000000000000000006000000716e8e94+SMSProvider_Cache-0x83655FEF ] // PubSubRendezvousGrain grain of the 'Cache' stream tries to Notify the prodcuer about the new consumer (there's no real producer.. it's dead) Notifying 1 existing producer(s) about new consumer ObserverId:*cli/e8fd329c/f7e8de56-f78f-448c-bcc0-7b0c0fdf9feb. Producers=[PubSubPublisherState:StreamId=Cache-00000000-0000-0000-0000-000000000000-SMSProvider,Producer=ObserverId:*cli/26a0e3ab/f931ed78-6f13-49da-8641-6f2ac0cf3490.] // From here it's stuck (probably in the 'Notify'), no more logs from PubSubRendezvousGrain. The client who tried to subscribe to the stream doesn't get answer, and any call tried to the stream, such as GetAllSubscriptions() doesn't get a response. [2017-09-28 08:04:06.061 GMT 27 INFO 100507 Catalog 127.0.0.1:11111] Before collection#3: memory=105MB, #activations=5, collector=<#Activations=2, #Buckets=3, buckets=[1h:58m:53s.938ms->0 items, 1h:59m:53s.938ms->1 items, 2h:0m:53s.938ms->1 items]>. [2017-09-28 08:04:06.069 GMT 27 INFO 100508 Catalog 127.0.0.1:11111] After collection#3: memory=105MB, #activations=5, collected 0 activations, collector=<#Activations=2, #Buckets=3, buckets=[1h:58m:53s.930ms->0 items, 1h:59m:53s.930ms->1 items, 2h:0m:53s.930ms->1 items]>, collection time=00:00:00.0087767. [2017-09-28 08:04:06.135 GMT 12 INFO 100000 TypeManager 127.0.0.1:11111] OnRefreshClusterMapTimer: refresh start [2017-09-28 08:04:07.917 GMT 13 VERBOSE 100000 OrleansCounterManager 127.0.0.1:11111] Writing counters. [2017-09-28 08:04:08.333 GMT 27 VERBOSE 100000 MembershipOracle 127.0.0.1:11111] -ReadAll (called from timer) Membership table 1 silos, 1 are Active, 0 are Dead, Version=<2, 5>. All silos: [SiloAddress=S127.0.0.1:11111:244281717 SiloName=localhost Status=Active] [2017-09-28 08:04:35.132 GMT 47 VERBOSE 100000 Dispatcher 127.0.0.1:11111] Resend Request S127.0.0.1:11111:244281717*cli/e8fd329c@1adde38e->*grn/716E8E94/00000000+SMSProvider_Cache #5: global::Orleans.Streams.IPubSubRendezvousGrain:RegisterProducer() [2017-09-28 08:04:37.981 GMT 14 VERBOSE 100000 OrleansCounterManager 127.0.0.1:11111] Writing counters. [2017-09-28 08:04:45.413 GMT 47 VERBOSE 100000 Runtime.Messaging.GatewayAcceptor 127.0.0.1:11111] Closing recieving socket: [2017-09-28 08:04:45.419 GMT 47 INFO 101302 Orleans.Messaging.Gateway 127.0.0.1:11111] Recorded closed socket from endpoint 127.0.0.1:49197, client ID *cli/e8fd329c.