unable to start default pelias docker due to "Elasticsearch service did not come up, check configuration" error

[wkulesza]

Describe the bug

Unable to start default pelias docker with default portland-metro project due to "Elasticsearch service did not come up, check configuration" error

Steps to Reproduce

1. on a clear machine, logged as a sudo user i created a sh script taken from https://github.com/pelias/docker documentation
2. git cloned my fork of repo (fork only differs from the original by adding a new region called wlkp - for later tests)
3. edited the path/to/install to /home/{myname}/pelias folder that i created manually
4. chmoded +x that sh script
5. run the ./pelias.sh script
6. during the process, i saw following errors:
   Creating pelias _elasticsearch .. done

• pelias elastic wait
  waiting for elasticsearch service to come up
  ...........................

Elasticsearch service did not come up, check configuration

• pelias elastic create
  Creating pelias_schema_run ... done

---

Create index

Elasticsearch ERROR: 2020-09-15T11:53:21Z
Error: Request error, retrying
GET http://elasticsearch:9200/ => connect ECONNREFUSED 172.19.0.2:9200
[..]

Elasticsearch WARNING: 2020-09-15T11:53:21Z
Unable to revive connection http://elasticsearch:9200/

Elasticsearch WARNING: 2020-09-15T11:53:21Z
No living connections

[...]

unsupported elasticsearch version. try: >=7.4.2

• pelias download all

...
all next log items seem to be ok apart from tests.

Expected behavior
Elasticsearch should load and website api should return correct results?

Environment (please complete the following information):
Ubuntu Ubuntu 20.04 LTS Server 64bit
Docker version 19.03.12, build 48a66213fe
docker-compose version 1.27.2, build 18f557f9

Pastebin/Screenshots
Api works and returns data, but incomplete
[http://prntscr.com/uhnaf4]

References

As requested by @missinglink in issue #180 180 adding this a separate issue.

[missinglink]

Can you please post the output of these commands:

sudo netstat -plnt

docker ps -a | grep pelias

[wkulesza]

Output of netstat:

root@vps671012:/home/wojciech# sudo netstat -plnt
Active Internet connections (only servers)
Proto Recv-Q Send-Q Local Address           Foreign Address         State       PID/Program name
tcp        0      0 127.0.0.53:53           0.0.0.0:*               LISTEN      578/systemd-resolve
tcp        0      0 0.0.0.0:8822            0.0.0.0:*               LISTEN      1545/sshd: /usr/sbi
tcp6       0      0 :::4000                 :::*                    LISTEN      56538/docker-proxy
tcp6       0      0 :::4100                 :::*                    LISTEN      56399/docker-proxy
tcp6       0      0 :::4200                 :::*                    LISTEN      56493/docker-proxy
tcp6       0      0 :::4300                 :::*                    LISTEN      56319/docker-proxy
tcp6       0      0 :::4400                 :::*                    LISTEN      56464/docker-proxy
tcp6       0      0 :::8822                 :::*                    LISTEN      1545/sshd: /usr/sbi

Output of docker ps:

root@vps671012:/home/wojciech# docker ps -a | grep pelias
2aa69951da29        pelias/schema:master          "/bin/bash"              About an hour ago   Exited (0) About an hour ago                             pelias_schema
c764577b5a9c        pelias/polylines:master       "/bin/bash"              About an hour ago   Exited (0) About an hour ago                             pelias_polylines
8e15a3d4af22        pelias/libpostal-service      "./bin/wof-libpostal…"   About an hour ago   Up About an hour                0.0.0.0:4400->4400/tcp   pelias_libpostal
c9c1394b0664        pelias/pip-service:master     "./bin/start"            About an hour ago   Up About an hour                0.0.0.0:4200->4200/tcp   pelias_pip-service
433a77fb2c90        pelias/openstreetmap:master   "/bin/bash"              About an hour ago   Exited (0) About an hour ago                             pelias_openstreetmap
743fda531b72        pelias/fuzzy-tester:master    "./bin/fuzzy-tester …"   About an hour ago   Exited (0) About an hour ago                             pelias_fuzzy_tester
3559566ff397        pelias/transit:master         "/bin/bash"              About an hour ago   Exited (0) About an hour ago                             pelias_transit
ae747c8a14d5        pelias/interpolation:master   "./interpolate serve…"   About an hour ago   Up About an hour                0.0.0.0:4300->4300/tcp   pelias_interpolation
64b4d8352418        pelias/whosonfirst:master     "/bin/bash"              About an hour ago   Exited (0) About an hour ago                             pelias_whosonfirst
dbb7277d9a7e        pelias/openaddresses:master   "/bin/bash"              About an hour ago   Exited (0) About an hour ago                             pelias_openaddresses
697aed3f1cf9        pelias/csv-importer:master    "/bin/bash"              About an hour ago   Exited (0) About an hour ago                             pelias_csv_importer
e5f79125dffc        pelias/placeholder:master     "./cmd/server.sh"        About an hour ago   Up About an hour                0.0.0.0:4100->4100/tcp   pelias_placeholder
f6fd61fdcb92        pelias/api:master             "./bin/start"            About an hour ago   Up About an hour                0.0.0.0:4000->4000/tcp   pelias_api
1b2f7495e50f        pelias/elasticsearch:7.5.1    "/usr/local/bin/dock…"   2 hours ago         Restarting (1) 27 seconds ago                            pelias_elasticsearch

[orangejulius]

Hi @wkulesza,

The output of pelias compose logs elasticsearch will likely provide some hints.

The output can be quite verbose so can you please paste it all here and be sure it's formatted correctly? Your copy/paste above appears to have lost quite a few newlines making it hard to read. For example on my machine, docker ps -a looks like this:

$ docker ps
CONTAINER ID        IMAGE                            COMMAND                  CREATED             STATUS              PORTS                                            NAMES
cd45ae5ee4e5        pelias/elasticsearch:7.5.1       "/usr/local/bin/dock…"   4 days ago          Up 4 days           0.0.0.0:9200->9200/tcp, 0.0.0.0:9300->9300/tcp   pelias_elasticsearch
71e836aaa83e        pelias/api:master                "./bin/start"            4 days ago          Up 4 days           0.0.0.0:4000->4000/tcp                           pelias_api
21b8f752c75b        pelias/libpostal-service         "./bin/wof-libpostal…"   4 days ago          Up 4 days           0.0.0.0:4400->4400/tcp                           pelias_libpostal
853b761bbbbc        pelias/pip-service:master        "./bin/start"            4 days ago          Up 4 days           0.0.0.0:4200->4200/tcp                           pelias_pip-service
cdb2be7d7d9c        pelias/interpolation:master      "./interpolate serve…"   4 days ago          Up 4 days           0.0.0.0:4300->4300/tcp                           pelias_interpolation
e70ce6d0efbe        pelias/placeholder:master        "./cmd/server.sh"        4 days ago          Up 4 days           0.0.0.0:4100->4100/tcp                           pelias_placeholder

[missinglink]

I fixed the formatting above, the trick for markdown is to paste it between a pair of triple backticks

[wkulesza]

Thanks @missinglink for helping with formatting.

Pasting in the elasticsearch log - obviously is very long, but i think this part is repeating towards the end:

Attaching to pelias_elasticsearch
�[36melasticsearch_1  |�[0m OpenJDK 64-Bit Server VM warning: Option UseConcMarkSweepGC was deprecated in version 9.0 and will likely be removed in a future release.
�[36melasticsearch_1  |�[0m {"type": "server", "timestamp": "2020-09-15T11:52:49,011Z", "level": "WARN", "component": "o.e.b.ElasticsearchUncaughtExceptionHandler", "cluster.name": "pelias-dev", "node.name": "1b2f7495e50f", "message": "uncaught exception in thread [main]", 
�[36melasticsearch_1  |�[0m "stacktrace": ["org.elasticsearch.bootstrap.StartupException: ElasticsearchException[failed to bind service]; nested: AccessDeniedException[/usr/share/elasticsearch/data/nodes];",
�[36melasticsearch_1  |�[0m "at org.elasticsearch.bootstrap.Elasticsearch.init(Elasticsearch.java:163) ~[elasticsearch-7.5.1.jar:7.5.1]",
�[36melasticsearch_1  |�[0m "at org.elasticsearch.bootstrap.Elasticsearch.execute(Elasticsearch.java:150) ~[elasticsearch-7.5.1.jar:7.5.1]",
�[36melasticsearch_1  |�[0m "at org.elasticsearch.cli.EnvironmentAwareCommand.execute(EnvironmentAwareCommand.java:86) ~[elasticsearch-7.5.1.jar:7.5.1]",
�[36melasticsearch_1  |�[0m "at org.elasticsearch.cli.Command.mainWithoutErrorHandling(Command.java:125) ~[elasticsearch-cli-7.5.1.jar:7.5.1]",
�[36melasticsearch_1  |�[0m "at org.elasticsearch.cli.Command.main(Command.java:90) ~[elasticsearch-cli-7.5.1.jar:7.5.1]",
�[36melasticsearch_1  |�[0m "at org.elasticsearch.bootstrap.Elasticsearch.main(Elasticsearch.java:115) ~[elasticsearch-7.5.1.jar:7.5.1]",
�[36melasticsearch_1  |�[0m "at org.elasticsearch.bootstrap.Elasticsearch.main(Elasticsearch.java:92) ~[elasticsearch-7.5.1.jar:7.5.1]",
�[36melasticsearch_1  |�[0m "Caused by: org.elasticsearch.ElasticsearchException: failed to bind service",
�[36melasticsearch_1  |�[0m "at org.elasticsearch.node.Node.<init>(Node.java:607) ~[elasticsearch-7.5.1.jar:7.5.1]",
�[36melasticsearch_1  |�[0m "at org.elasticsearch.node.Node.<init>(Node.java:253) ~[elasticsearch-7.5.1.jar:7.5.1]",
�[36melasticsearch_1  |�[0m "at org.elasticsearch.bootstrap.Bootstrap$5.<init>(Bootstrap.java:221) ~[elasticsearch-7.5.1.jar:7.5.1]",
�[36melasticsearch_1  |�[0m "at org.elasticsearch.bootstrap.Bootstrap.setup(Bootstrap.java:221) ~[elasticsearch-7.5.1.jar:7.5.1]",
�[36melasticsearch_1  |�[0m "at org.elasticsearch.bootstrap.Bootstrap.init(Bootstrap.java:349) ~[elasticsearch-7.5.1.jar:7.5.1]",
�[36melasticsearch_1  |�[0m "at org.elasticsearch.bootstrap.Elasticsearch.init(Elasticsearch.java:159) ~[elasticsearch-7.5.1.jar:7.5.1]",
�[36melasticsearch_1  |�[0m "... 6 more",
�[36melasticsearch_1  |�[0m "Caused by: java.nio.file.AccessDeniedException: /usr/share/elasticsearch/data/nodes",
�[36melasticsearch_1  |�[0m "at sun.nio.fs.UnixException.translateToIOException(UnixException.java:90) ~[?:?]",
�[36melasticsearch_1  |�[0m "at sun.nio.fs.UnixException.rethrowAsIOException(UnixException.java:111) ~[?:?]",
�[36melasticsearch_1  |�[0m "at sun.nio.fs.UnixException.rethrowAsIOException(UnixException.java:116) ~[?:?]",
�[36melasticsearch_1  |�[0m "at sun.nio.fs.UnixFileSystemProvider.createDirectory(UnixFileSystemProvider.java:389) ~[?:?]",
�[36melasticsearch_1  |�[0m "at java.nio.file.Files.createDirectory(Files.java:693) ~[?:?]",
�[36melasticsearch_1  |�[0m "at java.nio.file.Files.createAndCheckIsDirectory(Files.java:800) ~[?:?]",
�[36melasticsearch_1  |�[0m "at java.nio.file.Files.createDirectories(Files.java:786) ~[?:?]",
�[36melasticsearch_1  |�[0m "at org.elasticsearch.env.NodeEnvironment.lambda$new$0(NodeEnvironment.java:272) ~[elasticsearch-7.5.1.jar:7.5.1]",
�[36melasticsearch_1  |�[0m "at org.elasticsearch.env.NodeEnvironment$NodeLock.<init>(NodeEnvironment.java:209) ~[elasticsearch-7.5.1.jar:7.5.1]",
�[36melasticsearch_1  |�[0m "at org.elasticsearch.env.NodeEnvironment.<init>(NodeEnvironment.java:269) ~[elasticsearch-7.5.1.jar:7.5.1]",
�[36melasticsearch_1  |�[0m "at org.elasticsearch.node.Node.<init>(Node.java:273) ~[elasticsearch-7.5.1.jar:7.5.1]",
�[36melasticsearch_1  |�[0m "at org.elasticsearch.node.Node.<init>(Node.java:253) ~[elasticsearch-7.5.1.jar:7.5.1]",
�[36melasticsearch_1  |�[0m "at org.elasticsearch.bootstrap.Bootstrap$5.<init>(Bootstrap.java:221) ~[elasticsearch-7.5.1.jar:7.5.1]",
�[36melasticsearch_1  |�[0m "at org.elasticsearch.bootstrap.Bootstrap.setup(Bootstrap.java:221) ~[elasticsearch-7.5.1.jar:7.5.1]",
�[36melasticsearch_1  |�[0m "at org.elasticsearch.bootstrap.Bootstrap.init(Bootstrap.java:349) ~[elasticsearch-7.5.1.jar:7.5.1]",
�[36melasticsearch_1  |�[0m "at org.elasticsearch.bootstrap.Elasticsearch.init(Elasticsearch.java:159) ~[elasticsearch-7.5.1.jar:7.5.1]",
�[36melasticsearch_1  |�[0m "... 6 more"] }

[missinglink]

Caused by: java.nio.file.AccessDeniedException: /usr/share/elasticsearch/data/nodes"

This directory should be available on your host machine at ${DATA_DIR}/elasticsearch
(with the DATA_DIR being defined in the .env file, as per the docs).

Is there anything unusual about that directory? ie. permissions or network mount etc?
Who is the owner of that directory?

[missinglink]

Possibly related:

• Elasticsearch 5 won't start if data directory is owned by root, or not created #33
• Elasticsearch did not come up, check configuration concerning node #118
• https://stackoverflow.com/questions/51201699/elasticsearch-docker-image-with-data-persistence

I suspect the issue is related to user permissions.

[wkulesza]

@missinglink DATA DIR is set in portland-metro to ./data so i understand this directory is /home/wojciech/pelias/docker/projects/portland-metro/data/elasticsearch ? and not usr/share/elasticsearch ?

that elasticsearch in home/wojciech is empty
all folders are root/root, as this is how i run all projects and UID is 1001

[orangejulius]

@wkulesza the ownership of the directory is likely the issue, it can't be owned by root.

This is a common problem, and we were working on some better automatic detection/fixing of this issue in #74, maybe we will pick that up.

For now I happen to have just listed some basic troubleshooting tips in another comment, let me know if any of these work for you: #31 (comment)

[wkulesza]

@orangejulius will work on it, but for the time being, when i try to run it as normal user (without sudo) i get permission errors for creating symbolic link (which is normal, as standard user can't work on /usr/local/bin directory)

wojciech@vps671012:~$ mkdir pelias
wojciech@vps671012:~$
wojciech@vps671012:~$
wojciech@vps671012:~$ ./pelias.sh
+ cd /home/wojciech/pelias
+ git clone https://github.com/wkulesza/docker.git
Cloning into 'docker'...
remote: Enumerating objects: 13, done.
remote: Counting objects: 100% (13/13), done.
remote: Compressing objects: 100% (8/8), done.
remote: Total 1637 (delta 4), reused 11 (delta 4), pack-reused 1624
Receiving objects: 100% (1637/1637), 435.28 KiB | 1.32 MiB/s, done.
Resolving deltas: 100% (1046/1046), done.
+ cd docker
++ pwd
+ ln -s /home/wojciech/pelias/docker/pelias /usr/local/bin/pelias
ln: failed to create symbolic link '/usr/local/bin/pelias': Permission denied
+ cd projects/portland-metro
+ mkdir ./data
+ sed -i /DATA_DIR/d .env
+ echo DATA_DIR=./data
+ sed -i /DOCKER_USER/d .env
++ id -u
+ echo DOCKER_USER=1001
+ pelias compose pull
./pelias.sh: line 30: pelias: command not found
+ pelias elastic start
./pelias.sh: line 31: pelias: command not found
+ pelias elastic wait
./pelias.sh: line 32: pelias: command not found
+ pelias elastic create
./pelias.sh: line 33: pelias: command not found
+ pelias download all
./pelias.sh: line 34: pelias: command not found
+ pelias prepare all
./pelias.sh: line 35: pelias: command not found
+ pelias import all
./pelias.sh: line 36: pelias: command not found
+ pelias compose up
./pelias.sh: line 37: pelias: command not found
+ pelias test run
./pelias.sh: line 40: pelias: command not found

[orangejulius]

Right. Only the ln command should be run with sudo. I've just opened #216 to clarify that in the docs.

[wkulesza]

OK. i made that manually now, added ln command as sudo
then when i try to continue and being in the projects/portland-metro folder i get this:

wojciech@vps671012:~/pelias/docker/projects/portland-metro$ pelias compose pull
pelias: command not found