Connection drops using osm2pgsql-replication on serverless setup (Neon)

[goncalo-oliveira]

Hi,

First, context

Debian 12
Python 3.11.2
OpenSSL 3.0.15 3 Sep 2024 (Library: OpenSSL 3.0.15 3 Sep 2024)

osm2pgsql version 2.0.1
Build: None
Compiled using the following library versions:
Libosmium 2.19.0
Proj 9.1.1
Lua 5.3.6

replication_base_url: https://download.geofabrik.de/europe/united-kingdom-updates

I'm trying to run osm2pgsql-replication update in this machine and I'm getting SSL errors; not with the database, but with the replication source, it seems. Bellow are the logs with -v option.

osm2pgsql-replication update -v 
2024-12-09 11:41:17 [INFO]: Using replication service 'https://download.geofabrik.de/europe/united-kingdom-updates'.
2024-12-09 11:41:17 [DEBUG]: Starting new HTTPS connection (1): download.geofabrik.de:443
2024-12-09 11:41:17 [DEBUG]: https://download.geofabrik.de:443 "GET /europe/united-kingdom-updates/state.txt HTTP/1.1" 200 123
2024-12-09 11:41:17 [DEBUG]: Applying 3 sequence(s) (382 → 379), covering 2 day(s) 23 hour(s) 59 minute(s) 27 second(s) (259167 sec) of changes (2024-12-05T21:21:18Z → 2024-12-08T21:20:45Z)
2024-12-09 11:41:17 [DEBUG]: Calling osm2pgsql with: /usr/bin/osm2pgsql --append --slim --prefix planet_osm /tmp/tmpiveprhuw/osm2pgsql_diff.osc.gz
2024-12-09 11:41:17 [DEBUG]: Importing from sequence 379
2024-12-09 11:41:17 [DEBUG]: Starting new HTTPS connection (1): download.geofabrik.de:443
2024-12-09 11:41:17 [DEBUG]: https://download.geofabrik.de:443 "GET /europe/united-kingdom-updates/state.txt HTTP/1.1" 200 123
2024-12-09 11:41:17 [DEBUG]: Starting new HTTPS connection (1): download.geofabrik.de:443
2024-12-09 11:41:18 [DEBUG]: https://download.geofabrik.de:443 "GET /europe/united-kingdom-updates/000/000/380.osc.gz HTTP/1.1" 200 2547392
2024-12-09 11:41:18 [DEBUG]: Downloaded change 380. (501038 kB available in download buffer)
2024-12-09 11:41:18 [DEBUG]: Starting new HTTPS connection (1): download.geofabrik.de:443
2024-12-09 11:41:18 [DEBUG]: https://download.geofabrik.de:443 "GET /europe/united-kingdom-updates/000/000/381.osc.gz HTTP/1.1" 200 2412863
2024-12-09 11:41:18 [DEBUG]: Downloaded change 381. (490515 kB available in download buffer)
2024-12-09 11:41:18 [DEBUG]: Starting new HTTPS connection (1): download.geofabrik.de:443
2024-12-09 11:41:19 [DEBUG]: https://download.geofabrik.de:443 "GET /europe/united-kingdom-updates/000/000/382.osc.gz HTTP/1.1" 200 2320764
2024-12-09 11:41:19 [DEBUG]: Downloaded change 382. (480543 kB available in download buffer)
2024-12-09 11:41:20  osm2pgsql version 2.0.1
2024-12-09 11:41:20  Database version: 17.2
2024-12-09 11:41:20  PostGIS version: 3.5
2024-12-09 11:41:20  Loading properties from table '"public"."osm2pgsql_properties"'.
2024-12-09 11:41:21  Not using flat node file (same as on import).
2024-12-09 11:41:21  Using output 'flex' (same as on import).
2024-12-09 11:41:21  Using style file '/data/geocoder.lua' (same as on import).
2024-12-09 11:41:21  Storing properties to table '"public"."osm2pgsql_properties"'.
2024-12-09 11:41:22  Storing properties to table '"public"."osm2pgsql_properties"'.
2024-12-09 11:49:31  Reading input files done in 489s (8m 9s).                            
2024-12-09 11:49:31    Processed 234592 nodes in 40s - 6k/s
2024-12-09 11:49:31    Processed 50206 ways in 398s (6m 38s) - 126/s
2024-12-09 11:49:31    Processed 851 relations in 51s - 17/s
2024-12-09 11:49:35  Going over 10276 pending ways (using 4 threads)
Left to process: 0.......
2024-12-09 11:51:35  Processing 10276 pending ways took 119s (1m 59s) at a rate of 86.35/s
2024-12-09 11:51:35  Going over 2639 pending relations (using 4 threads)
Left to process: 0......
2024-12-09 11:53:17  Processing 2639 pending relations took 102s (1m 42s) at a rate of 25.87/s
2024-12-09 11:53:17  Skipping stage 1c for nodes (no marked nodes).
2024-12-09 11:53:17  Skipping stage 1c for ways (no marked ways).
2024-12-09 11:53:17  No marked nodes or ways (Skipping stage 2).
2024-12-09 11:53:17  Done postprocessing on table 'planet_osm_nodes' in 0s
2024-12-09 11:53:17  Done postprocessing on table 'planet_osm_ways' in 0s
2024-12-09 11:53:17  Done postprocessing on table 'planet_osm_rels' in 0s
2024-12-09 11:53:17  All postprocessing on table 'boundaries' done in 0s.
2024-12-09 11:53:17  All postprocessing on table 'roads' done in 0s.
2024-12-09 11:53:17  All postprocessing on table 'addrs' done in 0s.
2024-12-09 11:53:17  Storing properties to table '"public"."osm2pgsql_properties"'.
2024-12-09 11:53:17  osm2pgsql took 717s (11m 57s) overall.
2024-12-09 11:53:17 [DEBUG]: Starting new HTTPS connection (1): download.geofabrik.de:443
2024-12-09 11:53:17 [DEBUG]: https://download.geofabrik.de:443 "GET /europe/united-kingdom-updates/000/000/382.state.txt HTTP/1.1" 200 123
2024-12-09 11:53:17 [CRITICAL]: Exception during execution: SSL connection has been closed unexpectedly

At a certain point, I get the above error, which is awkward, since curling that address (or with wget) works fine on the same machine and it's always at this point.

I tried setting SSL_VERSION=tlsv1.2 and upgrading openssl and libssl-dev but that didn't work out though.

It always happens at this point and not before, giving me the impression that it's not the source, but maybe something with the client?

Does anyone have any hints on what could be happening?

[pnorman]

This doesn't look like it's a TLS issue with the HTTP download, it looks like it's with postgresql.

What happens if you do osm2pgsql-replication status?

[lonvia]

I cannot reproduce this issue on my Debian 12 setup here.

osm2pgsql-replication does keep a connection to postgresql open while osm2pgsql is running and reuses it when it is finished. Still doesn't seem to cause any issues here, even on a long running osm2pgsql. Do you have a special postgresql setup, for example with a proxy?

[goncalo-oliveira]

Thanks for replying...

@pnorman you're right, my view was skewed, didn't see the 200 at the end of the download line.

What happens if you do osm2pgsql-replication status?

It works fine. Currently it's up to date because I did another import.

$ osm2pgsql-replication status
Using replication service 'https://download.geofabrik.de/europe/united-kingdom-updates', which is at sequence 383 ( 2024-12-09T21:20:41Z )
Replication server's most recent data is 12 hour(s) 19 minute(s) 32 second(s) old
Local database is up to date with server
Local database's most recent data is 12 hour(s) 19 minute(s) 32 second(s) old

Do you have a special postgresql setup, for example with a proxy?
@lonvia

I'm using Neon, which does have a peculiar way of doing things and it's possible that the idle connection is being dropped. I'm going to try again using the pooled connection, which should circumvent these idle drops... Will post my findings when possible. Currently, the data is up to date as I did a clean import.

[goncalo-oliveira]

Think I'm running into a different issue now... connecting through the connection pool, I'm getting a prepared statement error.

$ osm2pgsql-replication update --once -v
2024-12-10 11:19:55 [INFO]: Using replication service 'https://download.geofabrik.de/europe/united-kingdom-updates'.
2024-12-10 11:19:55 [DEBUG]: Starting new HTTPS connection (1): download.geofabrik.de:443
2024-12-10 11:19:55 [DEBUG]: https://download.geofabrik.de:443 "GET /europe/united-kingdom-updates/state.txt HTTP/1.1" 200 123
2024-12-10 11:19:55 [DEBUG]: Applying 1 sequence(s) (383 → 382), covering 6 hour(s) 23 minute(s) 20 second(s) (23000 sec) of changes (2024-12-09T14:57:21Z → 2024-12-09T21:20:41Z)
2024-12-10 11:19:55 [DEBUG]: Calling osm2pgsql with: /usr/bin/osm2pgsql --append --slim --prefix planet_osm /tmp/tmpwtpd0we7/osm2pgsql_diff.osc.gz
2024-12-10 11:19:55 [DEBUG]: Importing from sequence 382
2024-12-10 11:19:55 [DEBUG]: Starting new HTTPS connection (1): download.geofabrik.de:443
2024-12-10 11:19:55 [DEBUG]: https://download.geofabrik.de:443 "GET /europe/united-kingdom-updates/state.txt HTTP/1.1" 200 123
2024-12-10 11:19:55 [DEBUG]: Starting new HTTPS connection (1): download.geofabrik.de:443
2024-12-10 11:19:55 [DEBUG]: https://download.geofabrik.de:443 "GET /europe/united-kingdom-updates/000/000/383.osc.gz HTTP/1.1" 200 2905953
2024-12-10 11:19:56 [DEBUG]: Downloaded change 383. (498670 kB available in download buffer)
2024-12-10 11:19:57  osm2pgsql version 2.0.1
2024-12-10 11:19:57  Database version: 17.2
2024-12-10 11:19:57  PostGIS version: 3.5
2024-12-10 11:19:57  Loading properties from table '"public"."osm2pgsql_properties"'.
2024-12-10 11:19:57  Not using flat node file (same as on import).
2024-12-10 11:19:57  Using output 'flex' (same as on import).
2024-12-10 11:19:57  Using style file '/data/geocoder.lua' (same as on import).
2024-12-10 11:19:57  Storing properties to table '"public"."osm2pgsql_properties"'.
2024-12-10 11:19:59  Storing properties to table '"public"."osm2pgsql_properties"'.
2024-12-10 11:19:59  ERROR: Database error: ERROR:  prepared statement "set_property" already exist

2024-12-10 11:19:59 [CRITICAL]: Exception during execution: Command '['/usr/bin/osm2pgsql', '--append', '--slim', '--prefix', 'planet_osm', '/tmp/tmpwtpd0we7/osm2pgsql_diff.osc.gz']' returned non-zero exit status 1.

I tried deleting the "set_property" prepared statement manually, but the problem doesn't go away... Unsure if this could be related to #878.

I'll do further tests and reach out to Neon to see if I can gather more information, as it might not be an osm2pgsql issue.

[joto]

This looks like a problem in your connection pooler. For updates osm2pgsql will create two short-lived connections and they both create a prepared statement set_property. They should not interfere. If they do, it means the proxy is doing something wrong. Either you need to configure it differently or open a bug report there.

[goncalo-oliveira]

Ok, adding more details for whoever comes looking for a similar issue, although it has nothing to do with osm2pgsql directly.

For the first issue related to the SSL connection being closed unexpectedly, this can occur when the application tries to reuse an idle connection after the Neon compute has been suspended due to inactivity. If you plan to leave a connection idle, it would be good to increment the auto-suspend timer to meet the duration needed, or disable it altogether. The default auto-suspend is 5 minutes, and looking at the endpoint activity, it is suspending roughly 5 minutes after opening.

This explains the behaviour... the connection is inactive for more than five minutes and when the application tries to use it again, it was already dropped. To clarify, in this context, we're talking about a direct connection, not through the connection pooler.

To workaround this, one can change the default inactivity timeout to a bigger value (Neon compute settings). Although this has nothing to do with osm2pgsql it would be interesting if it did have options for a health check or keep-alive mechanism to prevent this from happening.

There's something else... which is the timeout for idle transactions. On Neon, that defaults to 5 minutes. Since one can't control the value for the session that osm2pgsql is going to use, the workaround is to change the value at the role value.

ALTER ROLE role_name SET idle_in_transaction_session_timeout='1200s';

I'd like to suggest this to be done at session level by osm2pgsql, but I'll open an issue for that later.

Regarding the issues with the connection pool, I had opened an issue before (which I didn't remember). Neon uses pgbouncer, which doesn't support SQL prepared statements. It does however support protocol level prepared statements and there's already a discussion open requesting for its support.

Hope this helps anyone going through the same issues.