Sorry figured it out -
Need to call
EventStore.Common.Log.LogManager.Init(“Eventstore”, PATH, “.”);
Myself and include a log.config file that it can read.
Once thats done you can also use setLogFactory to plug messages into a different system (log4net, etc)
I am having one hell of a time trying to get embedded event stores to gossip with each other. I’ve set all the options the correct way and dug through the source but I would really like some help if someone has a moment.
I am configuring 3 embedded nodes with the following
var ip = System.Net.Dns.GetHostEntry(Environment.MachineName).AddressList.Where(i => i.AddressFamily == System.Net.Sockets.AddressFamily.InterNetwork).FirstOrDefault();
var builder = EmbeddedVNodeBuilder
.AsClusterMember(3)
.WithWorkerThreads(Environment.ProcessorCount)
.WithInternalTcpOn(new IPEndPoint(IPAddress.Loopback, 3113))
.WithExternalTcpOn(new IPEndPoint(ip, 3112))
.WithInternalHttpOn(new IPEndPoint(IPAddress.Loopback, 3110 ))
.WithExternalHttpOn(new IPEndPoint(ip, 3111))
.WithGossipSeeds(new IPEndPoint(IPAddress.Loopback, 3120), new IPEndPoint(IPAddress.Loopback, 3130))
``
I’ve tried numerous different little tweaks, using IpAddress.Any, Loopback, I look up the machine’s IP because I saw some post a while ago saying HTTP couldn’t listen on 0.0.0.0. I was getting errors:
“Failed to start async http on http://0.0.0.0:3110”
I’ve tried adding the http prefix in there “http://*:3100”
Running EventStore.ClusterNode.exe like below works
start EventStore.ClusterNode.exe --mem-db --log .\logs\log1 --int-ip 127.0.0.1 --ext-ip 192.168.1.247 --int-tcp-port=3113 --ext-tcp-port=3112 --int-http-port=3110 --ext-http-port=3111 --cluster-size=3 --discover-via-dns=false --gossip-seed=127.0.0.1:3120,127.0.0.1:3130
start EventStore.ClusterNode.exe --mem-db --log .\logs\log2 --int-ip 127.0.0.1 --ext-ip 192.168.1.247 --int-tcp-port=3123 --ext-tcp-port=3122 --int-http-port=3120 --ext-http-port=3121 --cluster-size=3 --discover-via-dns=false --gossip-seed=127.0.0.1:3110,127.0.0.1:3130
start EventStore.ClusterNode.exe --mem-db --log .\logs\log3 --int-ip 127.0.0.1 --ext-ip 192.168.1.247 --int-tcp-port=3133 --ext-tcp-port=3132 --int-http-port=3130 --ext-http-port=3131 --cluster-size=3 --discover-via-dns=false --gossip-seed=127.0.0.1:3110,127.0.0.1:3120
``
So I added a new log message into the ES client code to print out the cluster settings before building.
2016-03-08 17:51:58,141 [1] DEBUG EmbeddedVNodeBuilder [(null)] - Embedded builder options:
InstanceId: e01e6dbb-5276-426a-85ab-cfa5e32cbd9e
InternalTcp: 127.0.0.1:3113
InternalSecureTcp:
ExternalTcp: 192.168.1.247:3112
ExternalSecureTcp:
InternalHttp: 127.0.0.1:3110
ExternalHttp: 192.168.1.247:3111
IntHttpPrefixes: http://*:3110/
ExtHttpPrefixes: http://*:3111/
EnableTrustedAuth: False
Certificate: n/a
LogHttpRequests: False
WorkerThreads: 8
DiscoverViaDns: False
ClusterDns: fake.dns
GossipSeeds: 127.0.0.1:3120,127.0.0.1:3130
ClusterNodeCount: 3
MinFlushDelay: 00:00:00.0020000
PrepareAckCount: 1
CommitAckCount: 1
PrepareTimeout: 00:00:02
CommitTimeout: 00:00:02
UseSsl: False
SslTargetHost: n/a
SslValidateServer: True
StatsPeriod: 00:00:30
StatsStorage: Stream
AuthenticationProviderFactory Type: EventStore.Core.Authentication.InternalAuthenticationProviderFactory
NodePriority: 0GossipInterval: 00:00:01
GossipAllowedTimeDifference: 00:01:00
GossipTimeout: 00:00:00.5000000
HistogramEnabled: False
HTTPCachingDisabled: False
IndexPath:
ScavengeHistoryMaxAge: 30
``
And the log from ES:
2016-03-08 17:51:59,077 [1] DEBUG MessageHierarchy [(null)] - MessageHierarchy initialization took 00:00:00.8992600.
2016-03-08 17:51:59,334 [1] INFO MiniWeb [(null)] - Starting MiniWeb for /web ==> C:\Users\charl\Projects\Pulse.Api\Domain\Domain\bin\clusternode-web
2016-03-08 17:51:59,342 [1] DEBUG MiniWeb [(null)] - Binding MiniWeb to /web/{*remaining_path}
2016-03-08 17:51:59,350 [1] INFO MiniWeb [(null)] - Starting MiniWeb for /web ==> C:\Users\charl\Projects\Pulse.Api\Domain\Domain\bin\clusternode-web
2016-03-08 17:51:59,360 [1] DEBUG MiniWeb [(null)] - Binding MiniWeb to /web/{*remaining_path}
2016-03-08 17:51:59,368 [MainQueue] INFO ClusterVNodeController [(null)] - ========== [127.0.0.1:3110] SYSTEM INIT…
2016-03-08 17:51:59,410 [MainQueue] INFO TcpServerListener [(null)] - Starting Normal TCP listening on TCP endpoint: 192.168.1.247:3112.
2016-03-08 17:51:59,413 [Storage Chaser] INFO IndexCommitter [(null)] - TableIndex initialization…
2016-03-08 17:51:59,427 [Storage Chaser] INFO IndexCommitter [(null)] - ReadIndex building…
2016-03-08 17:51:59,435 [Storage Chaser] DEBUG IndexCommitter [(null)] - ReadIndex rebuilding done: total processed 0 records, time elapsed: 00:00:00.0080213.
2016-03-08 17:51:59,427 [MainQueue] INFO TcpServerListener [(null)] - Starting Normal TCP listening on TCP endpoint: 127.0.0.1:3113.
2016-03-08 17:51:59,451 [MainQueue] INFO HttpAsyncServer [(null)] - Starting HTTP server on [http://*:3111/]…
2016-03-08 17:51:59,473 [MainQueue] INFO HttpAsyncServer [(null)] - HTTP server is up and listening on [http://*:3111/]
2016-03-08 17:51:59,480 [MainQueue] INFO HttpAsyncServer [(null)] - Starting HTTP server on [http://*:3110/]…
2016-03-08 17:51:59,601 [MainQueue] INFO HttpAsyncServer [(null)] - Attempting to add permissions for http://:3110/ using netsh http add urlacl url=http://:3110/ user=“4KCOMET\charl”
2016-03-08 17:51:59,847 [6] DEBUG QueuedHandlerThreadPool [(null)] - SLOW QUEUE MSG [MonitoringQueue]: SystemInit - 438ms. Q: 0/0.
2016-03-08 17:52:02,013 [MainQueue] INFO HttpAsyncServer [(null)] - Retrying HTTP server on [http://*:3110/]…
2016-03-08 17:52:02,018 [MainQueue] INFO HttpAsyncServer [(null)] - HTTP server is up and listening on [http://*:3110/]
2016-03-08 17:52:02,024 [MainQueue] DEBUG InMemoryBus [(null)] - SLOW BUS MSG [MainBus]: SystemInit - 2543ms. Handler: HttpService.
2016-03-08 17:52:02,043 [MainQueue] DEBUG QueuedHandlerMRES [(null)] - SLOW QUEUE MSG [MainQueue]: SystemInit - 2677ms. Q: 0/8.
2016-03-08 17:52:02,050 [MainQueue] INFO ClusterVNodeController [(null)] - ========== [127.0.0.1:3110] Service ‘StorageReader’ initialized.
2016-03-08 17:52:02,062 [MainQueue] INFO ClusterVNodeController [(null)] - ========== [127.0.0.1:3110] Service ‘StorageWriter’ initialized.
2016-03-08 17:52:02,069 [MainQueue] INFO ClusterVNodeController [(null)] - ========== [127.0.0.1:3110] Service ‘StorageChaser’ initialized.
2016-03-08 17:52:02,086 [MainQueue] DEBUG GossipServiceBase [(null)] - CLUSTER HAS CHANGED
2016-03-08 17:52:02,094 [MainQueue] DEBUG GossipServiceBase [(null)] - Old:
2016-03-08 17:52:02,105 [MainQueue] DEBUG GossipServiceBase [(null)] -VND {e01e6dbb-5276-426a-85ab-cfa5e32cbd9e} [Unknown, 127.0.0.1:3113, n/a, 192.168.1.247:3112, n/a, 127.0.0.1:3110, 192.168.1.247:3111] -1/0/0/E-1@-1:{00000000-0000-0000-0000-000000000000} | 2016-03-08 23:52:02.035{}</log4net.Error>
2016-03-08 17:52:02,227 [MainQueue] DEBUG GossipServiceBase [(null)] - New:
2016-03-08 17:52:02,232 [MainQueue] DEBUG GossipServiceBase [(null)] - MAN {00000000-0000-0000-0000-000000000000} [Manager, 127.0.0.1:3130, 127.0.0.1:3130] | 2016-03-08 23:52:02.077{}</log4net.Error>
2016-03-08 17:52:02,371 [MainQueue] DEBUG GossipServiceBase [(null)] - MAN {00000000-0000-0000-0000-000000000000} [Manager, 127.0.0.1:3120, 127.0.0.1:3120] | 2016-03-08 23:52:02.077{}</log4net.Error>
2016-03-08 17:52:02,489 [MainQueue] DEBUG GossipServiceBase [(null)] -VND {e01e6dbb-5276-426a-85ab-cfa5e32cbd9e} [Unknown, 127.0.0.1:3113, n/a, 192.168.1.247:3112, n/a, 127.0.0.1:3110, 192.168.1.247:3111] -1/0/0/E-1@-1:{00000000-0000-0000-0000-000000000000} | 2016-03-08 23:52:02.035{}</log4net.Error>
2016-03-08 17:52:02,672 [MainQueue] DEBUG GossipServiceBase [(null)] - --------------------------------------------------------------------------------
2016-03-08 17:52:02,687 [MainQueue] DEBUG InMemoryBus [(null)] - SLOW BUS MSG [MainBus]: GotGossipSeedSources - 610ms. Handler: NodeGossipService.
2016-03-08 17:52:02,693 [MainQueue] DEBUG QueuedHandlerMRES [(null)] - SLOW QUEUE MSG [MainQueue]: GotGossipSeedSources - 616ms. Q: 1/3.
2016-03-08 17:52:02,699 [MainQueue] INFO ClusterVNodeController [(null)] - ========== [127.0.0.1:3110] SYSTEM START…
2016-03-08 17:52:02,719 [MainQueue] INFO ClusterVNodeController [(null)] - ========== [127.0.0.1:3110] IS UNKNOWN…
2016-03-08 17:52:02,728 [MainQueue] INFO Pulse.Domain.EndpointConfig [(null)] - EventStore status changed: Unknown
2016-03-08 17:52:02,736 [6] DEBUG PersistentSubscriptionService [(null)] - Subscriptions received state change to Unknown stopping listening.
2016-03-08 17:52:02,748 [MainQueue] DEBUG ElectionsService [(null)] - ELECTIONS: STARTING ELECTIONS.
2016-03-08 17:52:02,758 [MainQueue] DEBUG ElectionsService [(null)] - ELECTIONS: (V=0) SHIFT TO LEADER ELECTION.
2016-03-08 17:52:02,766 [MainQueue] DEBUG ElectionsService [(null)] - ELECTIONS: (V=0) VIEWCHANGE FROM [127.0.0.1:3110, {e01e6dbb-5276-426a-85ab-cfa5e32cbd9e}].
2016-03-08 17:52:03,002 [13] DEBUG InMemoryBus [(null)] - SLOW BUS MSG [Worker #1 Bus]: SendOverHttp - 263ms. Handler: HttpSendService.
2016-03-08 17:52:03,011 [13] DEBUG QueuedHandlerThreadPool [(null)] - SLOW QUEUE MSG [Worker #1]: SendOverHttp - 272ms. Q: 0/0.
2016-03-08 17:52:03,614 [MainQueue] DEBUG GossipServiceBase [(null)] - Looks like node [127.0.0.1:3130] is DEAD (Gossip send failed).
2016-03-08 17:52:03,809 [6] DEBUG InMemoryBus [(null)] - SLOW BUS MSG [Worker #3 Bus]: SendOverHttp - 258ms. Handler: HttpSendService.
2016-03-08 17:52:03,812 [MainQueue] DEBUG GossipServiceBase [(null)] - CLUSTER HAS CHANGED (gossip send failed to [127.0.0.1:3130])
2016-03-08 17:52:04,037 [6] DEBUG QueuedHandlerThreadPool [(null)] - SLOW QUEUE MSG [Worker #3]: SendOverHttp - 486ms. Q: 0/0.
2016-03-08 17:52:04,062 [MainQueue] DEBUG GossipServiceBase [(null)] - Old:
2016-03-08 17:52:04,301 [MainQueue] DEBUG GossipServiceBase [(null)] - MAN {00000000-0000-0000-0000-000000000000} [Manager, 127.0.0.1:3130, 127.0.0.1:3130] | 2016-03-08 23:52:02.077{}</log4net.Error>
2016-03-08 17:52:04,500 [MainQueue] DEBUG GossipServiceBase [(null)] - MAN {00000000-0000-0000-0000-000000000000} [Manager, 127.0.0.1:3120, 127.0.0.1:3120] | 2016-03-08 23:52:02.077{}</log4net.Error>
2016-03-08 17:52:04,690 [MainQueue] DEBUG GossipServiceBase [(null)] -VND {e01e6dbb-5276-426a-85ab-cfa5e32cbd9e} [Unknown, 127.0.0.1:3113, n/a, 192.168.1.247:3112, n/a, 127.0.0.1:3110, 192.168.1.247:3111] -1/0/0/E-1@-1:{00000000-0000-0000-0000-000000000000} | 2016-03-08 23:52:03.551{}</log4net.Error>
2016-03-08 17:52:04,818 [MainQueue] DEBUG GossipServiceBase [(null)] - New:
2016-03-08 17:52:04,828 [MainQueue] DEBUG GossipServiceBase [(null)] - MAN {00000000-0000-0000-0000-000000000000} [Manager, 127.0.0.1:3130, 127.0.0.1:3130] | 2016-03-08 23:52:03.811{}</log4net.Error>
2016-03-08 17:52:04,966 [MainQueue] DEBUG GossipServiceBase [(null)] - MAN {00000000-0000-0000-0000-000000000000} [Manager, 127.0.0.1:3120, 127.0.0.1:3120] | 2016-03-08 23:52:02.077{}</log4net.Error>
2016-03-08 17:52:05,123 [MainQueue] DEBUG GossipServiceBase [(null)] -VND {e01e6dbb-5276-426a-85ab-cfa5e32cbd9e} [Unknown, 127.0.0.1:3113, n/a, 192.168.1.247:3112, n/a, 127.0.0.1:3110, 192.168.1.247:3111] -1/0/0/E-1@-1:{00000000-0000-0000-0000-000000000000} | 2016-03-08 23:52:03.551{}</log4net.Error>
2016-03-08 17:52:05,282 [MainQueue] DEBUG GossipServiceBase [(null)] - --------------------------------------------------------------------------------
2016-03-08 17:52:05,300 [MainQueue] DEBUG InMemoryBus [(null)] - SLOW BUS MSG [MainBus]: GossipSendFailed - 1689ms. Handler: NodeGossipService.
2016-03-08 17:52:05,307 [MainQueue] DEBUG QueuedHandlerMRES [(null)] - SLOW QUEUE MSG [MainQueue]: GossipSendFailed - 1696ms. Q: 0/19.
2016-03-08 17:52:05,315 [MainQueue] DEBUG GossipServiceBase [(null)] - Looks like node [127.0.0.1:3120] is DEAD (Gossip send failed).
2016-03-08 17:52:05,319 [MainQueue] DEBUG GossipServiceBase [(null)] - CLUSTER HAS CHANGED (gossip send failed to [127.0.0.1:3120])
2016-03-08 17:52:05,326 [MainQueue] DEBUG GossipServiceBase [(null)] - Old:
2016-03-08 17:52:05,333 [MainQueue] DEBUG GossipServiceBase [(null)] - MAN {00000000-0000-0000-0000-000000000000} [Manager, 127.0.0.1:3130, 127.0.0.1:3130] | 2016-03-08 23:52:03.811{}</log4net.Error>
2016-03-08 17:52:05,467 [MainQueue] DEBUG GossipServiceBase [(null)] - MAN {00000000-0000-0000-0000-000000000000} [Manager, 127.0.0.1:3120, 127.0.0.1:3120] | 2016-03-08 23:52:02.077{}</log4net.Error>
2016-03-08 17:52:05,621 [MainQueue] DEBUG GossipServiceBase [(null)] -VND {e01e6dbb-5276-426a-85ab-cfa5e32cbd9e} [Unknown, 127.0.0.1:3113, n/a, 192.168.1.247:3112, n/a, 127.0.0.1:3110, 192.168.1.247:3111] -1/0/0/E-1@-1:{00000000-0000-0000-0000-000000000000} | 2016-03-08 23:52:05.313{}</log4net.Error>
2016-03-08 17:52:05,758 [MainQueue] DEBUG GossipServiceBase [(null)] - New:
2016-03-08 17:52:05,772 [MainQueue] DEBUG GossipServiceBase [(null)] - MAN {00000000-0000-0000-0000-000000000000} [Manager, 127.0.0.1:3130, 127.0.0.1:3130] | 2016-03-08 23:52:03.811{}</log4net.Error>
2016-03-08 17:52:05,901 [MainQueue] DEBUG GossipServiceBase [(null)] - MAN {00000000-0000-0000-0000-000000000000} [Manager, 127.0.0.1:3120, 127.0.0.1:3120] | 2016-03-08 23:52:05.319{}</log4net.Error>
2016-03-08 17:52:06,081 [MainQueue] DEBUG GossipServiceBase [(null)] -VND {e01e6dbb-5276-426a-85ab-cfa5e32cbd9e} [Unknown, 127.0.0.1:3113, n/a, 192.168.1.247:3112, n/a, 127.0.0.1:3110, 192.168.1.247:3111] -1/0/0/E-1@-1:{00000000-0000-0000-0000-000000000000} | 2016-03-08 23:52:05.313{}</log4net.Error>
2016-03-08 17:52:06,249 [MainQueue] DEBUG GossipServiceBase [(null)] - --------------------------------------------------------------------------------
2016-03-08 17:52:06,260 [MainQueue] DEBUG InMemoryBus [(null)] - SLOW BUS MSG [MainBus]: GossipSendFailed - 945ms. Handler: NodeGossipService.
2016-03-08 17:52:06,267 [MainQueue] DEBUG QueuedHandlerMRES [(null)] - SLOW QUEUE MSG [MainQueue]: GossipSendFailed - 951ms. Q: 18/20.
2016-03-08 17:52:06,273 [MainQueue] DEBUG ElectionsService [(null)] - ELECTIONS: (V=0) TIMED OUT! (S=ElectingLeader, M=).
2016-03-08 17:52:06,286 [MainQueue] DEBUG ElectionsService [(null)] - ELECTIONS: (V=1) SHIFT TO LEADER ELECTION.
2016-03-08 17:52:06,296 [MainQueue] DEBUG ElectionsService [(null)] - ELECTIONS: (V=1) VIEWCHANGE FROM [127.0.0.1:3110, {e01e6dbb-5276-426a-85ab-cfa5e32cbd9e}].
``
It seems that they are just unable to gossip with each other for some reason when they are embedded. (and I do run as admin)
Can you access them via curl? 127.0.0.1:3110/gossip external:extport/gossip
Another thing that may help is LogHttpRequests=true (not sure if its
in builder, it was just added in 3.5.0) it will print out to log any
http traffic.
I just tried curl to 127.0.0.1:3110/gossip - I get 408 Request Timeout which is interesting
Also I tried starting 2 EventStore.Cluster instances alongside my embedded store, and that works oddly. The embedded store seems to join up with the other 2 real stores
does it give errors on gossip to the other nodes?
if you can't talk to gossip via curl etc, that is the issue building a cluster.
I merged in the PR and ran my code but it produces a lot of output I’ll have to get back to you after dinner
setting a higher gossip interval will make it produce less.
Well I really have no idea why, but after running that test where my embedded store connected to the real stores things seem to be working. Maybe some internal firewall thing was going on or something… I hate leaving it at such a big wtf but I tried backing out the PR and switching back to the nuget packages and its still working. Maybe theres some temperamental issue with my deployment over here.
Thanks for helping me look
the PR was just allowing a field to be set on vnodebuilder 