mediagis/nominatim-docker

Error After Installation - How to troubleshoot

noelstieglitz opened this issue · 11 comments

noelstieglitz commented

Describe the bug
After installing, I receive an error attempting to run

nominatim reverse --lat 48 --lon 22

Error:

Traceback (most recent call last):
  File "/usr/local/bin/nominatim", line 7, in <module>
    from nominatim import cli
  File "/usr/local/lib/nominatim/lib-python/nominatim/cli.py", line 22, in <module>
    from nominatim import clicmd
  File "/usr/local/lib/nominatim/lib-python/nominatim/clicmd/__init__.py", line 14, in <module>
    from nominatim.clicmd.setup import SetupAll as SetupAll
  File "/usr/local/lib/nominatim/lib-python/nominatim/clicmd/setup.py", line 22, in <module>
    from nominatim.clicmd.args import NominatimArgs
  File "/usr/local/lib/nominatim/lib-python/nominatim/clicmd/args.py", line 19, in <module>
    import nominatim.api as napi
  File "/usr/local/lib/nominatim/lib-python/nominatim/api/__init__.py", line 17, in <module>
    from .core import (NominatimAPI as NominatimAPI,
  File "/usr/local/lib/nominatim/lib-python/nominatim/api/core.py", line 17, in <module>
    import sqlalchemy.ext.asyncio as sa_asyncio
ModuleNotFoundError: No module named 'sqlalchemy.ext.asyncio'

I also get this error from within the docker container:

image

Desktop / Server (please complete the following information):

  • OS & Version: Ubuntu 20.04 LTS
  • Docker Version: 25.0.5
  • Nominatim Version: 4.4

Additional context
Please bear with me as this is a new domain for me. My ssh session disconnected while running the docker command:

docker run -it \
  -v nominatim-flatnode:/nominatim/flatnode \
  -e PBF_URL=https://planet.openstreetmap.org/pbf/planet-latest.osm.pbf \
  -p 8080:8080 \
  --name nominatim \
  mediagis/nominatim:4.4

I believe the osm2psql step had completed and I see the flat node files exist. Using top, osm2psql was still using > 60GB of memory for hours after the ssh session died. Flat node file:

image

Also, the postgres db is 565GB
image

Any tips on

  1. How can I troubleshoot this further? For example, log locations in the docker container or perhaps directly in the nominatim db?
  2. Can/should I kick off the install without losing the work that seems to have been successful (ie without recreating the flatnode files)? For example, maybe nominatim import --continue indexing?

Also, please let me know if this should be moved to the "discussion" or some other forum.

leonardehrenfried commented

To me this looks like we are not installing a required package during image build.

But the installation instructions don't mention any package that we don't have in our dockerfile: https://nominatim.org/release-docs/latest/appendix/Install-on-Ubuntu-22/

If you find out what the package name to install is, we could add it. Perhaps ask in upstream nominatim.

noelstieglitz commented

Thanks for the speedy response. I just ran the apt-get update/install. and still receive an error. Maybe I need to restart the container? I just ran a db check and got this error:
image

Also, here is more of the error than in my original description:

$ nominatim reverse --lat 22 --lon 21
2024-03-22 16:32:39: Using project directory: /var/log/postgresql
Traceback (most recent call last):
  File "/usr/lib/python3/dist-packages/sqlalchemy/ext/asyncio/engine.py", line 457, in execute
    result = await greenlet_spawn(
  File "/usr/lib/python3/dist-packages/sqlalchemy/util/_concurrency_py3k.py", line 136, in greenlet_spawn
    result = context.switch(value)
  File "/usr/lib/python3/dist-packages/sqlalchemy/engine/base.py", line 1614, in _execute_20
    return meth(self, args_10style, kwargs_10style, execution_options)
  File "/usr/lib/python3/dist-packages/sqlalchemy/sql/elements.py", line 325, in _execute_on_connection
    return connection._execute_clauseelement(
  File "/usr/lib/python3/dist-packages/sqlalchemy/engine/base.py", line 1481, in _execute_clauseelement
    ret = self._execute_context(
  File "/usr/lib/python3/dist-packages/sqlalchemy/engine/base.py", line 1845, in _execute_context
    self._handle_dbapi_exception(
  File "/usr/lib/python3/dist-packages/sqlalchemy/engine/base.py", line 2030, in _handle_dbapi_exception
    util.raise_(exc_info[1], with_traceback=exc_info[2])
  File "/usr/lib/python3/dist-packages/sqlalchemy/util/compat.py", line 207, in raise_
    raise exception
  File "/usr/lib/python3/dist-packages/sqlalchemy/engine/base.py", line 1802, in _execute_context
    self.dialect.do_execute(
  File "/usr/lib/python3/dist-packages/sqlalchemy/engine/default.py", line 732, in do_execute
    cursor.execute(statement, parameters)
  File "/usr/lib/python3/dist-packages/sqlalchemy/dialects/postgresql/asyncpg.py", line 460, in execute
    self._adapt_connection.await_(
  File "/usr/lib/python3/dist-packages/sqlalchemy/util/_concurrency_py3k.py", line 76, in await_only
    return current.driver.switch(awaitable)
  File "/usr/lib/python3/dist-packages/sqlalchemy/util/_concurrency_py3k.py", line 129, in greenlet_spawn
    value = await result
  File "/usr/lib/python3/dist-packages/sqlalchemy/dialects/postgresql/asyncpg.py", line 423, in _prepare_and_execute
    self._rows = await prepared_stmt.fetch(*parameters)
  File "/usr/lib/python3/dist-packages/asyncpg/prepared_stmt.py", line 176, in fetch
    data = await self.__bind_execute(args, 0, timeout)
  File "/usr/lib/python3/dist-packages/asyncpg/prepared_stmt.py", line 241, in __bind_execute
    data, status, _ = await self.__do_execute(
  File "/usr/lib/python3/dist-packages/asyncpg/prepared_stmt.py", line 230, in __do_execute
    return await executor(protocol)
  File "asyncpg/protocol/protocol.pyx", line 201, in bind_execute
asyncio.exceptions.CancelledError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/lib/python3.10/asyncio/tasks.py", line 456, in wait_for
    return fut.result()
asyncio.exceptions.CancelledError

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/local/bin/nominatim", line 12, in <module>
    exit(cli.nominatim(module_dir='/usr/local/lib/nominatim/module',
  File "/usr/local/lib/nominatim/lib-python/nominatim/cli.py", line 228, in nominatim
    return get_set_parser().run(**kwargs)
  File "/usr/local/lib/nominatim/lib-python/nominatim/cli.py", line 121, in run
    return args.command.run(args)
  File "/usr/local/lib/nominatim/lib-python/nominatim/clicmd/api.py", line 183, in run
    result = api.reverse(napi.Point(args.lon, args.lat),
  File "/usr/local/lib/nominatim/lib-python/nominatim/api/core.py", line 648, in reverse
    return self._loop.run_until_complete(self._async_api.reverse(coord, **params))
  File "/usr/lib/python3.10/asyncio/base_events.py", line 649, in run_until_complete
    return future.result()
  File "/usr/local/lib/nominatim/lib-python/nominatim/api/core.py", line 245, in reverse
    return await geocoder.lookup(coord)
  File "/usr/local/lib/nominatim/lib-python/nominatim/api/reverse.py", line 565, in lookup
    row, tmp_row_func = await self.lookup_street_poi()
  File "/usr/local/lib/nominatim/lib-python/nominatim/api/reverse.py", line 308, in lookup_street_poi
    row = await self._find_closest_street_or_poi(distance)
  File "/usr/local/lib/nominatim/lib-python/nominatim/api/reverse.py", line 215, in _find_closest_street_or_poi
    return (await self.conn.execute(sql, self.bind_params)).one_or_none()
  File "/usr/local/lib/nominatim/lib-python/nominatim/api/connection.py", line 63, in execute
    return await asyncio.wait_for(self.connection.execute(sql, params), self.query_timeout)
  File "/usr/lib/python3.10/asyncio/tasks.py", line 458, in wait_for
    raise exceptions.TimeoutError() from exc
asyncio.exceptions.TimeoutError
noelstieglitz commented

Following up on the last comment, I'm not sure if this is where the nominatim CLI is checking, but this table is empty:

image

mtmail commented

Using project directory /var/log/postgresql

That's not the project directory in the Docker container. The CLI looks for the .env file in that directory to read the database connection settings. You might indeed be connecting to the wrong database.

leonardehrenfried commented

Reading the installation instructions again, I see that you not only need apt-get some packages but also some other python packages with pip.

pip install SQLAlchemy PyICU psycopg[binary] \
              psycopg2-binary python-dotenv PyYAML falcon uvicorn gunicorn

Can you try that and report if that helps?

noelstieglitz commented

Sorry for the delay. I created a VM from scratch and re-ran a similar, though slightly different docker command to start everything fresh. It's still running the "Starting rank". Should I wait for that to finish before troubleshooting further? Here is the last output:
image
...current ranking:
image

@mtmail - The bad db connection would make sense, as the nominatim reverse command does take a few seconds before returning the exception message. Also, it fits with the "are you sure you're connecting to the right db" warning. I found a .env file inside the /nominatim directory in the docker container. Assuming that's the correct .env file, it doesn't contain any database connection string details. Here are the contents:

image

Should I add a line like this?
NOMINATIM_DATABASE_DSN="pgsql:dbname=nominatim;user=my_user;password=my_pass"

Interestingly, the output from nominatim admin --check-database does show that NOMINATIM_DATABASE_DSN is set somewhere.
image

@leonardehrenfried, thanks again for chiming in. I can certainly run pip install.... Would it make sense to validate the db connection is setup correctly first? I'd rather not install any dependencies if not needed.

mtmail commented

Let's wait. Running a reverse query or --check-database only makes sense after the import finished.

I think the culprit is the missing dependencies. The docker image for Nominatim 4.4 is very new and between 4.3 and 4.4 a lot of new Python dependencies got added to Nominatim.

Should I add a line like this?
NOMINATIM_DATABASE_DSN="pgsql:dbname=nominatim;user=my_user;password=my_pass"

The import is using the same .env file so I think the database settings are fine as long as both are started from the same project directory. The Docker image setup uses /nominatim as project directory.
(For any unset config variable you can find the defaults in https://nominatim.org/release-docs/latest/customize/Settings/)

  • 👍1
noelstieglitz commented

The installation stopped running but failed. Here are the docker's container logs. It failed just after printing "Warming database caches". The errors that follow the initial error are from the container restarting (ie sudo docker start [containerId], and it appears attempting to restart the installation, but then fails and terminates the container.

2024-03-26 02:07:29: Starting rank 28 (using batch size 1)
2024-03-26 02:07:29: Done 0/0 in 0 @ 0.000 per second - FINISHED rank 28

2024-03-26 02:07:29: Starting rank 29 (using batch size 1)
2024-03-26 02:07:29: Done 0/0 in 0 @ 0.000 per second - FINISHED rank 29

2024-03-26 02:07:29: Starting rank 30 (using batch size 20)
2024-03-26 02:07:29: Done 0/0 in 0 @ 0.000 per second - FINISHED rank 30

2024-03-26 02:07:29: Starting rank 0 (using batch size 1)
2024-03-26 02:41:03: Done 0/0 in 0 @ 0.000 per second - FINISHED rank 0

2024-03-26 02:41:03: Starting interpolation lines (location_property_osmline) (using batch size 20)
2024-03-26 02:41:12: Done 0/0 in 0 @ 0.000 per second - FINISHED interpolation lines (location_property_osmline)

+ sudo -E -u nominatim nominatim admin --check-database
2024-03-26 02:41:12: Using project directory: /nominatim
2024-03-26 02:41:12: Checking database
Checking database connection ... OK
Checking database_version matches Nominatim software version ... OK
Checking for placex table ... OK
Checking for placex content ... OK
Checking that tokenizer works ... OK
Checking for wikipedia/wikidata data ... WARNING

Wikipedia/Wikidata importance tables missing.
Quality of search results may be degraded. Reverse geocoding is unaffected.
See https://nominatim.org/release-docs/latest/admin/Import/#wikipediawikidata-rankings

Checking indexing status ... OK
Checking that database indexes are complete ... OK
Checking that all database indexes are valid ... OK
Checking TIGER external data table. ... OK
+ '[' https://ftp5.gwdg.de/pub/misc/openstreetmap/planet.openstreetmap.org/replication/day '!=' '' ']'
+ sudo -E -u nominatim nominatim replication --init
2024-03-26 02:41:32: Using project directory: /nominatim
2024-03-26 02:41:32: Initialising replication updates
2024-03-26 02:41:35: Updates initialised at sequence 4204 (2024-03-17 22:00:01+00:00)
2024-03-26 02:41:35: Create functions
+ '[' '' = true ']'
+ export NOMINATIM_QUERY_TIMEOUT=600
+ NOMINATIM_QUERY_TIMEOUT=600
+ export NOMINATIM_REQUEST_TIMEOUT=3600
+ NOMINATIM_REQUEST_TIMEOUT=3600
+ '[' '' = true ']'
+ sudo -H -E -u nominatim nominatim admin --warm
2024-03-26 02:41:36: Using project directory: /nominatim
2024-03-26 02:41:36: Warming database caches
Traceback (most recent call last):
  File "/usr/lib/python3/dist-packages/sqlalchemy/ext/asyncio/engine.py", line 457, in execute
    result = await greenlet_spawn(
  File "/usr/lib/python3/dist-packages/sqlalchemy/util/_concurrency_py3k.py", line 136, in greenlet_spawn
    result = context.switch(value)
  File "/usr/lib/python3/dist-packages/sqlalchemy/engine/base.py", line 1614, in _execute_20
    return meth(self, args_10style, kwargs_10style, execution_options)
  File "/usr/lib/python3/dist-packages/sqlalchemy/sql/elements.py", line 325, in _execute_on_connection
    return connection._execute_clauseelement(
  File "/usr/lib/python3/dist-packages/sqlalchemy/engine/base.py", line 1481, in _execute_clauseelement
    ret = self._execute_context(
  File "/usr/lib/python3/dist-packages/sqlalchemy/engine/base.py", line 1845, in _execute_context
    self._handle_dbapi_exception(
  File "/usr/lib/python3/dist-packages/sqlalchemy/engine/base.py", line 2030, in _handle_dbapi_exception
    util.raise_(exc_info[1], with_traceback=exc_info[2])
  File "/usr/lib/python3/dist-packages/sqlalchemy/util/compat.py", line 207, in raise_
    raise exception
  File "/usr/lib/python3/dist-packages/sqlalchemy/engine/base.py", line 1802, in _execute_context
    self.dialect.do_execute(
  File "/usr/lib/python3/dist-packages/sqlalchemy/engine/default.py", line 732, in do_execute
    cursor.execute(statement, parameters)
  File "/usr/lib/python3/dist-packages/sqlalchemy/dialects/postgresql/asyncpg.py", line 460, in execute
    self._adapt_connection.await_(
  File "/usr/lib/python3/dist-packages/sqlalchemy/util/_concurrency_py3k.py", line 76, in await_only
    return current.driver.switch(awaitable)
  File "/usr/lib/python3/dist-packages/sqlalchemy/util/_concurrency_py3k.py", line 129, in greenlet_spawn
    value = await result
  File "/usr/lib/python3/dist-packages/sqlalchemy/dialects/postgresql/asyncpg.py", line 423, in _prepare_and_execute
    self._rows = await prepared_stmt.fetch(*parameters)
  File "/usr/lib/python3/dist-packages/asyncpg/prepared_stmt.py", line 176, in fetch
    data = await self.__bind_execute(args, 0, timeout)
  File "/usr/lib/python3/dist-packages/asyncpg/prepared_stmt.py", line 241, in __bind_execute
    data, status, _ = await self.__do_execute(
  File "/usr/lib/python3/dist-packages/asyncpg/prepared_stmt.py", line 230, in __do_execute
    return await executor(protocol)
  File "asyncpg/protocol/protocol.pyx", line 201, in bind_execute
asyncio.exceptions.CancelledError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/lib/python3.10/asyncio/tasks.py", line 456, in wait_for
    return fut.result()
asyncio.exceptions.CancelledError

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/local/bin/nominatim", line 12, in <module>
    exit(cli.nominatim(module_dir='/usr/local/lib/nominatim/module',
  File "/usr/local/lib/nominatim/lib-python/nominatim/cli.py", line 228, in nominatim
    return get_set_parser().run(**kwargs)
  File "/usr/local/lib/nominatim/lib-python/nominatim/cli.py", line 121, in run
    return args.command.run(args)
  File "/usr/local/lib/nominatim/lib-python/nominatim/clicmd/admin.py", line 64, in run
    return self._warm(args)
  File "/usr/local/lib/nominatim/lib-python/nominatim/clicmd/admin.py", line 119, in _warm
    api.search(word)
  File "/usr/local/lib/nominatim/lib-python/nominatim/api/core.py", line 747, in search
    return self._loop.run_until_complete(
  File "/usr/lib/python3.10/asyncio/base_events.py", line 649, in run_until_complete
    return future.result()
  File "/usr/local/lib/nominatim/lib-python/nominatim/api/core.py", line 261, in search
    return await geocoder.lookup(phrases)
  File "/usr/local/lib/nominatim/lib-python/nominatim/api/search/geocoder.py", line 214, in lookup
    results = await self.execute_searches(query, searches[:50])
  File "/usr/local/lib/nominatim/lib-python/nominatim/api/search/geocoder.py", line 89, in execute_searches
    lookup_results = await search.lookup(self.conn, self.params)
  File "/usr/local/lib/nominatim/lib-python/nominatim/api/search/db_searches.py", line 782, in lookup
    for row in await conn.execute(sql, _details_to_bind_params(details)):
  File "/usr/local/lib/nominatim/lib-python/nominatim/api/connection.py", line 63, in execute
    return await asyncio.wait_for(self.connection.execute(sql, params), self.query_timeout)
  File "/usr/lib/python3.10/asyncio/tasks.py", line 458, in wait_for
    raise exceptions.TimeoutError() from exc
asyncio.exceptions.TimeoutError
+ tailpid=0
+ replicationpid=0
+ trap stopServices SIGTERM TERM INT
+ /app/config.sh
+ id nominatim
+ echo 'user nominatim already exists'
user nominatim already exists
+ IMPORT_FINISHED=/var/lib/postgresql/14/main/import-finished
+ '[' '!' -f /var/lib/postgresql/14/main/import-finished ']'
+ /app/init.sh
+ OSMFILE=/nominatim/data.osm.pbf
+ CURL=("curl" "-L" "-A" "${USER_AGENT}" "--fail-with-body")
+ SCP='sshpass -p DMg5bmLPY7npHL2Q scp -o StrictHostKeyChecking=no u355874-sub1@u355874-sub1.your-storagebox.de'
+ '[' -z '' ']'
++ nproc
+ THREADS=16
+ '[' '' = true ']'
+ '[' -f '' ']'
+ echo 'Skipping optional Wikipedia importance import'
Skipping optional Wikipedia importance import
+ '[' true = true ']'
+ sshpass -p DMg5bmLPY7npHL2Q scp -o StrictHostKeyChecking=no u355874-sub1@u355874-sub1.your-storagebox.de:gb_postcodes.csv.gz /nominatim/gb_postcodes.csv.gz
+ '[' true = true ']'
+ sshpass -p DMg5bmLPY7npHL2Q scp -o StrictHostKeyChecking=no u355874-sub1@u355874-sub1.your-storagebox.de:us_postcodes.csv.gz /nominatim/us_postcodes.csv.gz
+ '[' true = true ']'
+ sshpass -p DMg5bmLPY7npHL2Q scp -o StrictHostKeyChecking=no u355874-sub1@u355874-sub1.your-storagebox.de:tiger2023-nominatim-preprocessed.csv.tar.gz /nominatim/tiger-nominatim-preprocessed.csv.tar.gz
+ '[' https://planet.openstreetmap.org/pbf/planet-latest.osm.pbf '!=' '' ']'
+ echo Downloading OSM extract from https://planet.openstreetmap.org/pbf/planet-latest.osm.pbf
Downloading OSM extract from https://planet.openstreetmap.org/pbf/planet-latest.osm.pbf
+ curl -L -A mediagis/nominatim-docker:4.4.0 --fail-with-body https://planet.openstreetmap.org/pbf/planet-latest.osm.pbf -C - --create-dirs -o /nominatim/data.osm.pbf
** Resuming transfer from byte position 79548738013
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100   333  100   333    0     0    788      0 --:--:-- --:--:-- --:--:--   789
100   378  100   378    0     0    699      0 --:--:-- --:--:-- --:--:--   699
100   367    0   367    0     0    417      0 --:--:-- --:--:-- --:--:--  4587
curl: (22) The requested URL returned error: 416

Any thoughts on how to start the container and possibly attempt continuing the warming caches? Or any other ideas?

noelstieglitz commented

@mtmail would you recommend installing those python dependencies via pip in the docker container? Or since you mentioned many changes in 4.4, perhaps I should try the previous (4.3) version?

mtmail commented

The output is not clear enough. nominatim admin --warm is known to be slower on the initial queries it runs, that's why the timeouts are set higher in the lines above

+ export NOMINATIM_QUERY_TIMEOUT=600
+ export NOMINATIM_REQUEST_TIMEOUT=3600

The values are in seconds, defaults are 10 and 60.

So it's waiting at least 10 minutes and still timing out? I think we can rule out the webserver (HTTP requests or such) because the command accesses the database directly. If the database was empty or missing data I wouldn't expect a timeout either. Sadly the command doesn't write any logs.

Please try installing the Python dependencies via pip in the docker container.

If that doesn't work or you're looking for a faster solution then Nominatim 4.3. is the better option. It will be solvable but you're installing the whole planet so I wouldn't want you to risk installing it multiple times (taking days to weeks).

  • 👍1
noelstieglitz commented

I tried installing the python dependencies but, when restarting the container, it was going to restart install from loading data in the db. Instead of waiting several days to see if that would succeed, I tried version 4.3 which was successful. Thanks for the help!