Can't start Elasticsearch 7 service on Windows

Elastic Stack Elasticsearch
1

Hi,

I'm trying to set up Elasticsearch on my Windows machine. I've done it before, but now I'm doing it again with version 7.0.0.

I set JAVA_HOME and can run Elasticsearch successfully with elasticsearch.bat (I can confirm that I get a response when browsing localhost:9200).

Next, I install the service by runnng elasticsearch-service.bat install. The installation succeeds, and I can see the service. However, it won't start. When checking Event Viewer, I see the following error:

The Elasticsearch 7.0.0 (elasticsearch-service-x64) service terminated with the following service-specific error:
Incorrect function.

I have no idea what this means.

The path to the executable that the service uses is set to:

C:[...]\elasticsearch-7.0.0\bin\elasticsearch-service-x64.exe //RS//elasticsearch-service-x64

Can anyone help identify what the problem is here, please?

Thanks in advance.

2

Which version of Windows are you on? What version of java are you using?

3

And just to confirm, you said that you previously had installed elasticsearch. Did you remove the service from the old version?

4

Windows 10.

Java: openjdk 12 2019-03-19.

Yes, I had removed the service from the old version. I tried reinstalling the service after the failure but nothing changed.

5

This topic was automatically closed 28 days after the last reply. New replies are no longer allowed.

7

I believe we talked about this briefly at Elasticon, please correct me if I'm wrong. Since this seems to be a very specific issue in your case it would probably make sense to see if there is anything else in the Elasticsearch logs that would point in the right direction.

8

Yes, this was the issue we talked about at Elasticon, and I'm glad you found it. The problem described earlier in this thread was most likely because the service took too long to start (on Windows a service must start within 30 seconds).

I've just downloaded the latest version of Elasticsearch (7.1.1) and given it a try, directly and not as a Windows service. I did this using the bundled JDK, though I had to set JAVA_HOME to it as Elasticsearch claimed to not have found the bundled JDK in the same folder.

Elasticsearch started in around a minute, which is not good enough but faster than I remembered with 7.0. Below is the CLI/logs output when I last tried to start it. I don't see anything obviously critical, though the gaps in time are not a good sign. Take a look, perhaps you may make more sense of it. Let me know if I can provide additional information to clarify the issue further.

OpenJDK 64-Bit Server VM warning: Option UseConcMarkSweepGC was deprecated in version 9.0 and will likely be removed in a future release.
[2019-06-22T17:50:22,826][INFO ][o.e.e.NodeEnvironment    ] [MYMACHINE] using [1] data paths, mounts [[Acer (C:)]], net usable_space [591.8gb], net total_space [912.7gb], types [NTFS]
[2019-06-22T17:50:22,841][INFO ][o.e.e.NodeEnvironment    ] [MYMACHINE] heap size [990.7mb], compressed ordinary object pointers [true]
[2019-06-22T17:50:22,857][INFO ][o.e.n.Node               ] [MYMACHINE] node name [MYMACHINE], node ID [ZgTn_njNTj-J_cc5YFR2Rw], cluster name [elasticsearch]
[2019-06-22T17:50:22,872][INFO ][o.e.n.Node               ] [MYMACHINE] version[7.1.1], pid[10028], build[default/zip/7a013de/2019-05-23T14:04:00.380842Z], OS[Windows 10/10.0/amd64], JVM[Oracle Corporation/OpenJDK 64-Bit Server VM/12.0.1/12.0.1+12]
[2019-06-22T17:50:22,872][INFO ][o.e.n.Node               ] [MYMACHINE] JVM home [C:\tools\elasticsearch-7.1.1\jdk]
[2019-06-22T17:50:22,872][INFO ][o.e.n.Node               ] [MYMACHINE] JVM arguments [-Xms1g, -Xmx1g, -XX:+UseConcMarkSweepGC, -XX:CMSInitiatingOccupancyFraction=75, -XX:+UseCMSInitiatingOccupancyOnly, -Des.networkaddress.cache.ttl=60, -Des.networkaddress.cache.negative.ttl=10, -XX:+AlwaysPreTouch, -Xss1m, -Djava.awt.headless=true, -Dfile.encoding=UTF-8, -Djna.nosys=true, -XX:-OmitStackTraceInFastThrow, -Dio.netty.noUnsafe=true, -Dio.netty.noKeySetOptimization=true, -Dio.netty.recycler.maxCapacityPerThread=0, -Dlog4j.shutdownHookEnabled=false, -Dlog4j2.disable.jmx=true, -Djava.io.tmpdir=C:\Users\Daniel\AppData\Local\Temp\elasticsearch, -XX:+HeapDumpOnOutOfMemoryError, -XX:HeapDumpPath=data, -XX:ErrorFile=logs/hs_err_pid%p.log, -Xlog:gc*,gc+age=trace,safepoint:file=logs/gc.log:utctime,pid,tags:filecount=32,filesize=64m, -Djava.locale.providers=COMPAT, -Dio.netty.allocator.type=unpooled, -Delasticsearch, -Des.path.home=C:\tools\elasticsearch-7.1.1, -Des.path.conf=C:\tools\elasticsearch-7.1.1\config, -Des.distribution.flavor=default, -Des.distribution.type=zip, -Des.bundled_jd=true]
[2019-06-22T17:50:32,107][INFO ][o.e.p.PluginsService     ] [MYMACHINE] loaded module [aggs-matrix-stats]
[2019-06-22T17:50:32,107][INFO ][o.e.p.PluginsService     ] [MYMACHINE] loaded module [analysis-common]
[2019-06-22T17:50:32,111][INFO ][o.e.p.PluginsService     ] [MYMACHINE] loaded module [ingest-common]
[2019-06-22T17:50:32,111][INFO ][o.e.p.PluginsService     ] [MYMACHINE] loaded module [ingest-geoip]
[2019-06-22T17:50:32,111][INFO ][o.e.p.PluginsService     ] [MYMACHINE] loaded module [ingest-user-agent]
[2019-06-22T17:50:32,111][INFO ][o.e.p.PluginsService     ] [MYMACHINE] loaded module [lang-expression]
[2019-06-22T17:50:32,111][INFO ][o.e.p.PluginsService     ] [MYMACHINE] loaded module [lang-mustache]
[2019-06-22T17:50:32,111][INFO ][o.e.p.PluginsService     ] [MYMACHINE] loaded module [lang-painless]
[2019-06-22T17:50:32,115][INFO ][o.e.p.PluginsService     ] [MYMACHINE] loaded module [mapper-extras]
[2019-06-22T17:50:32,115][INFO ][o.e.p.PluginsService     ] [MYMACHINE] loaded module [parent-join]
[2019-06-22T17:50:32,115][INFO ][o.e.p.PluginsService     ] [MYMACHINE] loaded module [percolator]
[2019-06-22T17:50:32,115][INFO ][o.e.p.PluginsService     ] [MYMACHINE] loaded module [rank-eval]
[2019-06-22T17:50:32,115][INFO ][o.e.p.PluginsService     ] [MYMACHINE] loaded module [reindex]
[2019-06-22T17:50:32,115][INFO ][o.e.p.PluginsService     ] [MYMACHINE] loaded module [repository-url]
[2019-06-22T17:50:32,115][INFO ][o.e.p.PluginsService     ] [MYMACHINE] loaded module [transport-netty4]
[2019-06-22T17:50:32,119][INFO ][o.e.p.PluginsService     ] [MYMACHINE] loaded module [x-pack-ccr]
[2019-06-22T17:50:32,119][INFO ][o.e.p.PluginsService     ] [MYMACHINE] loaded module [x-pack-core]
[2019-06-22T17:50:32,119][INFO ][o.e.p.PluginsService     ] [MYMACHINE] loaded module [x-pack-deprecation]
[2019-06-22T17:50:32,119][INFO ][o.e.p.PluginsService     ] [MYMACHINE] loaded module [x-pack-graph]
[2019-06-22T17:50:32,119][INFO ][o.e.p.PluginsService     ] [MYMACHINE] loaded module [x-pack-ilm]
[2019-06-22T17:50:32,119][INFO ][o.e.p.PluginsService     ] [MYMACHINE] loaded module [x-pack-logstash]
[2019-06-22T17:50:32,119][INFO ][o.e.p.PluginsService     ] [MYMACHINE] loaded module [x-pack-ml]
[2019-06-22T17:50:32,123][INFO ][o.e.p.PluginsService     ] [MYMACHINE] loaded module [x-pack-monitoring]
[2019-06-22T17:50:32,127][INFO ][o.e.p.PluginsService     ] [MYMACHINE] loaded module [x-pack-rollup]
[2019-06-22T17:50:32,127][INFO ][o.e.p.PluginsService     ] [MYMACHINE] loaded module [x-pack-security]
[2019-06-22T17:50:32,131][INFO ][o.e.p.PluginsService     ] [MYMACHINE] loaded module [x-pack-sql]
[2019-06-22T17:50:32,131][INFO ][o.e.p.PluginsService     ] [MYMACHINE] loaded module [x-pack-watcher]
[2019-06-22T17:50:32,131][INFO ][o.e.p.PluginsService     ] [MYMACHINE] no plugins loaded

The above is only part of the output. There is a 7,000-character limit to post here, so I'll paste the rest as a followup post.

9

Here are the rest of the logs. I've intentionally repeated three lines here to provide context.

[2019-06-22T17:50:32,131][INFO ][o.e.p.PluginsService     ] [MYMACHINE] loaded module [x-pack-sql]
[2019-06-22T17:50:32,131][INFO ][o.e.p.PluginsService     ] [MYMACHINE] loaded module [x-pack-watcher]
[2019-06-22T17:50:32,131][INFO ][o.e.p.PluginsService     ] [MYMACHINE] no plugins loaded
[2019-06-22T17:50:49,078][INFO ][o.e.x.s.a.s.FileRolesStore] [MYMACHINE] parsed [0] roles from file [C:\tools\elasticsearch-7.1.1\config\roles.yml]
[2019-06-22T17:50:52,410][INFO ][o.e.x.m.p.l.CppLogMessageHandler] [MYMACHINE] [controller/4204] [Main.cc@109] controller (64 bit): Version 7.1.1 (Build fd619a36eb77df) Copyright (c) 2019 Elasticsearch BV
[2019-06-22T17:50:53,753][DEBUG][o.e.a.ActionModule       ] [MYMACHINE] Using REST wrapper from plugin org.elasticsearch.xpack.security.Security
[2019-06-22T17:50:54,863][INFO ][o.e.d.DiscoveryModule    ] [MYMACHINE] using discovery type [zen] and seed hosts providers [settings]
[2019-06-22T17:50:58,543][INFO ][o.e.n.Node               ] [MYMACHINE] initialized
[2019-06-22T17:50:58,559][INFO ][o.e.n.Node               ] [MYMACHINE] starting ...
[2019-06-22T17:51:02,721][INFO ][o.e.t.TransportService   ] [MYMACHINE] publish_address {127.0.0.1:9300}, bound_addresses {127.0.0.1:9300}, {[::1]:9300}
[2019-06-22T17:51:02,973][WARN ][o.e.b.BootstrapChecks    ] [MYMACHINE] the default discovery settings are unsuitable for production use; at least one of [discovery.seed_hosts, discovery.seed_providers, cluster.initial_master_nodes] must be configured
[2019-06-22T17:51:03,013][INFO ][o.e.c.c.Coordinator      ] [MYMACHINE] cluster UUID [T9uSAyQqT6Kak8hACilnaw]
[2019-06-22T17:51:03,077][INFO ][o.e.c.c.ClusterBootstrapService] [MYMACHINE] no discovery configuration found, will perform best-effort cluster bootstrapping after [3s] unless existing master is discovered
[2019-06-22T17:51:04,080][INFO ][o.e.c.s.MasterService    ] [MYMACHINE] elected-as-master ([1] nodes joined)[{MYMACHINE}{ZgTn_njNTj-J_cc5YFR2Rw}{h48kem-6STKGgl9BM1Ewjg}{127.0.0.1}{127.0.0.1:9300}{ml.machine_memory=8509480960, xpack.installed=true, ml.max_open_jobs=20} elect leader, _BECOME_MASTER_TASK_, _FINISH_ELECTION_], term: 2, version: 16, reason: master node changed {previous [], current [{MYMACHINE}{ZgTn_njNTj-J_cc5YFR2Rw}{h48kem-6STKGgl9BM1Ewjg}{127.0.0.1}{127.0.0.1:9300}{ml.machine_memory=8509480960, xpack.installed=true, ml.max_open_jobs=20}]}
[2019-06-22T17:51:05,588][INFO ][o.e.c.s.ClusterApplierService] [MYMACHINE] master node changed {previous [], current [{MYMACHINE}{ZgTn_njNTj-J_cc5YFR2Rw}{h48kem-6STKGgl9BM1Ewjg}{127.0.0.1}{127.0.0.1:9300}{ml.machine_memory=8509480960, xpack.installed=true, ml.max_open_jobs=20}]}, term: 2, version: 16, reason: Publication{term=2, version=16}
[2019-06-22T17:51:07,132][WARN ][o.e.x.s.a.s.m.NativeRoleMappingStore] [MYMACHINE] Failed to clear cache for realms [[]]
[2019-06-22T17:51:07,308][INFO ][o.e.l.LicenseService     ] [MYMACHINE] license [41f2b773-1935-48c3-8faa-00fe83049d0e] mode [basic] - valid
[2019-06-22T17:51:07,375][INFO ][o.e.g.GatewayService     ] [MYMACHINE] recovered [0] indices into cluster_state
[2019-06-22T17:51:08,399][INFO ][o.e.h.AbstractHttpServerTransport] [MYMACHINE] publish_address {127.0.0.1:9200}, bound_addresses {127.0.0.1:9200}, {[::1]:9200}
[2019-06-22T17:51:08,399][INFO ][o.e.n.Node               ] [MYMACHINE] started
10

Thanks. 46sec startup time doesn't look too bad to me but since its above the 30sec mark maybe there is something to get it down, but I wouldn't expect big jumps here.

This looks like a development machine (laptop?), so would you mind sharing some specs (e.g. disk type, memory, what else is running that might use up resources?)

To give you some comparison, ES startup takes around 25sec on my own Laptop (MacBook Pro, 2,9Ghz Intel Core i7, 16GB SSDs). I also have Security and Machine learning disabled which seem to be on in your case (not sure if you need them, you might also try disabling them if not)

I see a gap of about 10sec between the laste Node logline and the PluginService starting to load the modules and later a gap of 17sec before FileRolesStore parsed the "config\roles.yml" file used in security. This doesn't mean that that parsing takes so long (looks like there isn't much in there) but maybe there is something else in betweeen that takes a bit longer than usual. I would try disabling machine learning and/or security if you don't need those plugins locally on your dev machine and see if that improved things a bit.

11

A service needs to respond to the Service Control Manager (SCM) within this time, otherwise Service Control Manager reports an error.

I'm not sure what Apache Commons Procrun does on Windows, which is what is used to run a Windows Service in the zip distribution, but the typical approach is to perform any lengthy processing on a separate thread, and report back to SCM within the timeframe.

12

Thanks for the update. I'm afraid the logs I shared don't give the full picture (so those 46 seconds are optimistic). There is a lot of time wasted with no output (before and after the JDK warning at the beginning), and that's something over a minute on its own.

I did try disabling machine learning and security, and it made a big difference. It drastically reduced the aforementioned initial wait time, and the total time covered by the logs with timestamps is about 32 seconds. Still not good enough, but a big improvement nonetheless.

Admittedly, my home laptop on which I'm having this issue isn't anything powerful.

CPU: Intel Core i3-4005U @ 1.7GHz , 2 Cores, 4 Logical Processors
Memory: 8GB RAM
Hard disk: Toshiba MQ01ABD100 (your typical 5400rpm slow laptop hard disk)

There isn't really anything using up too many resources. While I write this (with Elasticsearch not running), CPU usage is usually between 15-30%, Memory usage is around 40%, Disk usage is around 1-5%.

I tried this also (without disabling anything) on my work laptop (i7) and it took something around 30 seconds.

To be honest, I don't see any reason why anyone who just wants to try the software with a single node and very little data should need to invest in expensive hardware to avoid experiencing such slow startup times, especially when this wasn't a problem before v7. Just like it can scale out really well on large number of nodes, Elasticsearch should work reasonably well on a single one. Otherwise it's making it hard for people to start using the software.

I obviously don't know much about what it's actually doing, so that's just my perspective. If there's any way to enable extra logging to identify where the time is being spent, please let me know.

13

You could always put NSSM in the middle of it, I believe that would resolve the issue. This doesn't resolve the slow startup time but NSSM would report the service up to Windows and keep the OS from killing the "hung" service.