500 when adding assets to the phase

[smcalilly]

On staging, I sometimes get a 500 error when adding assets to the phase.

[smcalilly]

this is consistentally happening when we find the intersection of the districts and the asset.

i'm wondering if it's happening whenever we try to add assets that occur across disparate zones?

i can save multiple assets that are nearby each other, but the error happens when the geometries are located far away distance-wise.

ccfp-asset-dashboard-postgres | 2023-05-05 21:24:42.231 UTC [1] LOG:  server process (PID 1736) was terminated by signal 11: Segmentation fault
ccfp-asset-dashboard-postgres | 2023-05-05 21:24:42.231 UTC [1] DETAIL:  Failed process was running: SELECT "asset_dashboard_senatedistrict"."id", "asset_dashboard_senatedistrict"."name", "asset_dashboard_senatedistrict"."boundary"::bytea FROM "asset_dashboard_senatedistrict" WHERE ST_Intersects("asset_dashboard_senatedistrict"."boundary", ST_GeomFromEWKB('\x01070000206b0d00000100000001060000000900000001030000000100000008000000f353e395bdd5304105d578f961b33b410ed7a300a9d53041f52a87966fb33b4162e5d02abcd53041b2f3fd148cb33b41275ebac9d0d53041cf4b37597fb33b41ba7268f9d2d53041a11a2f357eb33b41280681cdcbd53041c1f7536373b33b41711283a8c9d53041dbcef7cb74b33b41f353e395bdd5304105d578f961b33b4101030000000100000005000000b5f1d24d941a314132d9ce57cb153d41e52406a9bc1a3141713d0a9fd4153d41d376be7fc31a3141fb51b8deb6153d4190438b249b1a314124d9ce97ad153d41b5f1d24d941a314132d9ce57cb153d4101030000000100000007000000ebd0222368ec30411d0456363e073c41c8caa1ed63ec304115b29dd740073c415937891146ec3041ba1c5a7c5b073c412a0456de5bec3041c720b0e272073c41290456de7aec304134b6f31556073c41ee2406217cec30411b58393452073c41ebd0222368ec30411d0456363e073c410
ccfp-asset-dashboard-postgres | 2023-05-05 21:24:42.231 UTC [1] LOG:  terminating any other active server processes
ccfp-asset-dashboard-postgres | 2023-05-05 21:24:42.231 UTC [1711] WARNING:  terminating connection because of crash of another server process
ccfp-asset-dashboard-postgres | 2023-05-05 21:24:42.231 UTC [1711] DETAIL:  The postmaster has commanded this server process to roll back the current transaction and exit, because another server process exited abnormally and possibly corrupted shared memory.
ccfp-asset-dashboard-postgres | 2023-05-05 21:24:42.231 UTC [1711] HINT:  In a moment you should be able to reconnect to the database and repeat your command.
ccfp-asset-dashboard-postgres | 2023-05-05 21:24:42.236 UTC [1] LOG:  all server processes terminated; reinitializing
ccfp-asset-dashboard-postgres | 2023-05-05 21:24:42.265 UTC [1745] LOG:  database system was interrupted; last known up at 2023-05-05 21:24:11 UTC
ccfp-asset-dashboard | Internal Server Error: /local-assets/
ccfp-asset-dashboard | Traceback (most recent call last):
ccfp-asset-dashboard |   File "/usr/local/lib/python3.9/site-packages/django/db/backends/utils.py", line 84, in _execute
ccfp-asset-dashboard |     return self.cursor.execute(sql, params)
ccfp-asset-dashboard | psycopg2.OperationalError: server closed the connection unexpectedly
ccfp-asset-dashboard |  This probably means the server terminated abnormally
ccfp-asset-dashboard |  before or while processing the request.
ccfp-asset-dashboard | 
ccfp-asset-dashboard | 
ccfp-asset-dashboard | The above exception was the direct cause of the following exception:
ccfp-asset-dashboard | 
ccfp-asset-dashboard | Traceback (most recent call last):
ccfp-asset-dashboard |   File "/usr/local/lib/python3.9/site-packages/django/core/handlers/exception.py", line 47, in inner
ccfp-asset-dashboard |     response = get_response(request)
ccfp-asset-dashboard |   File "/usr/local/lib/python3.9/site-packages/django/core/handlers/base.py", line 181, in _get_response
ccfp-asset-dashboard |     response = wrapped_callback(request, *callback_args, **callback_kwargs)
ccfp-asset-dashboard |   File "/usr/local/lib/python3.9/site-packages/django/views/decorators/csrf.py", line 54, in wrapped_view
ccfp-asset-dashboard |     return view_func(*args, **kwargs)
ccfp-asset-dashboard |   File "/usr/local/lib/python3.9/site-packages/rest_framework/viewsets.py", line 125, in view
ccfp-asset-dashboard |     return self.dispatch(request, *args, **kwargs)
ccfp-asset-dashboard |   File "/usr/local/lib/python3.9/site-packages/rest_framework/views.py", line 509, in dispatch
ccfp-asset-dashboard |     response = self.handle_exception(exc)
ccfp-asset-dashboard |   File "/usr/local/lib/python3.9/site-packages/rest_framework/views.py", line 469, in handle_exception
ccfp-asset-dashboard |     self.raise_uncaught_exception(exc)
ccfp-asset-dashboard |   File "/usr/local/lib/python3.9/site-packages/rest_framework/views.py", line 480, in raise_uncaught_exception
ccfp-asset-dashboard |     raise exc
ccfp-asset-dashboard |   File "/usr/local/lib/python3.9/site-packages/rest_framework/views.py", line 506, in dispatch
ccfp-asset-dashboard |     response = handler(request, *args, **kwargs)
ccfp-asset-dashboard |   File "/usr/local/lib/python3.9/site-packages/rest_framework/mixins.py", line 19, in create
ccfp-asset-dashboard |     self.perform_create(serializer)
ccfp-asset-dashboard |   File "/usr/local/lib/python3.9/site-packages/rest_framework/mixins.py", line 24, in perform_create
ccfp-asset-dashboard |     serializer.save()
ccfp-asset-dashboard |   File "/usr/local/lib/python3.9/site-packages/rest_framework/serializers.py", line 731, in save
ccfp-asset-dashboard |     self.instance = self.create(validated_data)
ccfp-asset-dashboard |   File "/usr/local/lib/python3.9/site-packages/rest_framework/serializers.py", line 703, in create
ccfp-asset-dashboard |     return [
ccfp-asset-dashboard |   File "/usr/local/lib/python3.9/site-packages/rest_framework/serializers.py", line 704, in <listcomp>
ccfp-asset-dashboard |     self.child.create(attrs) for attrs in validated_data
ccfp-asset-dashboard |   File "/usr/local/lib/python3.9/site-packages/rest_framework/serializers.py", line 962, in create
ccfp-asset-dashboard |     instance = ModelClass._default_manager.create(**validated_data)
ccfp-asset-dashboard |   File "/usr/local/lib/python3.9/site-packages/django/db/models/manager.py", line 85, in manager_method
ccfp-asset-dashboard |     return getattr(self.get_queryset(), name)(*args, **kwargs)
ccfp-asset-dashboard |   File "/usr/local/lib/python3.9/site-packages/django/db/models/query.py", line 453, in create
ccfp-asset-dashboard |     obj.save(force_insert=True, using=self.db)
ccfp-asset-dashboard |   File "/usr/local/lib/python3.9/site-packages/django/db/models/base.py", line 739, in save
ccfp-asset-dashboard |     self.save_base(using=using, force_insert=force_insert,
ccfp-asset-dashboard |   File "/usr/local/lib/python3.9/site-packages/django/db/models/base.py", line 787, in save_base
ccfp-asset-dashboard |     post_save.send(
ccfp-asset-dashboard |   File "/usr/local/lib/python3.9/site-packages/django/dispatch/dispatcher.py", line 180, in send
ccfp-asset-dashboard |     return [
ccfp-asset-dashboard |   File "/usr/local/lib/python3.9/site-packages/django/dispatch/dispatcher.py", line 181, in <listcomp>
ccfp-asset-dashboard |     (receiver, receiver(signal=self, sender=sender, **named))
ccfp-asset-dashboard |   File "/app/asset_dashboard/models.py", line 137, in save_zones_and_districts
ccfp-asset-dashboard |     instance.phase.project.update_project_districts(instance, phase_geoms)
ccfp-asset-dashboard |   File "/app/asset_dashboard/models.py", line 162, in update_project_districts
ccfp-asset-dashboard |     for district in districts:
ccfp-asset-dashboard |   File "/usr/local/lib/python3.9/site-packages/django/db/models/query.py", line 280, in __iter__
ccfp-asset-dashboard |     self._fetch_all()
ccfp-asset-dashboard |   File "/usr/local/lib/python3.9/site-packages/django/db/models/query.py", line 1324, in _fetch_all
ccfp-asset-dashboard |     self._result_cache = list(self._iterable_class(self))
ccfp-asset-dashboard |   File "/usr/local/lib/python3.9/site-packages/django/db/models/query.py", line 51, in __iter__
ccfp-asset-dashboard |     results = compiler.execute_sql(chunked_fetch=self.chunked_fetch, chunk_size=self.chunk_size)
ccfp-asset-dashboard |   File "/usr/local/lib/python3.9/site-packages/django/db/models/sql/compiler.py", line 1175, in execute_sql
ccfp-asset-dashboard |     cursor.execute(sql, params)
ccfp-asset-dashboard |   File "/usr/local/lib/python3.9/site-packages/django/db/backends/utils.py", line 98, in execute
ccfp-asset-dashboard |     return super().execute(sql, params)
ccfp-asset-dashboard |   File "/usr/local/lib/python3.9/site-packages/django/db/backends/utils.py", line 66, in execute
ccfp-asset-dashboard |     return self._execute_with_wrappers(sql, params, many=False, executor=self._execute)
ccfp-asset-dashboard |   File "/usr/local/lib/python3.9/site-packages/django/db/backends/utils.py", line 75, in _execute_with_wrappers
ccfp-asset-dashboard |     return executor(sql, params, many, context)
ccfp-asset-dashboard |   File "/usr/local/lib/python3.9/site-packages/django/db/backends/utils.py", line 84, in _execute
ccfp-asset-dashboard |     return self.cursor.execute(sql, params)
ccfp-asset-dashboard |   File "/usr/local/lib/python3.9/site-packages/django/db/utils.py", line 90, in __exit__
ccfp-asset-dashboard |     raise dj_exc_value.with_traceback(traceback) from exc_value
ccfp-asset-dashboard |   File "/usr/local/lib/python3.9/site-packages/django/db/backends/utils.py", line 84, in _execute
ccfp-asset-dashboard |     return self.cursor.execute(sql, params)
ccfp-asset-dashboard | django.db.utils.OperationalError: server closed the connection unexpectedly
ccfp-asset-dashboard |  This probably means the server terminated abnormally
ccfp-asset-dashboard |  before or while processing the request.
ccfp-asset-dashboard | 
ccfp-asset-dashboard | "POST /local-assets/ HTTP/1.1" 500 21046
ccfp-asset-dashboard-postgres | 2023-05-05 21:24:42.697 UTC [1745] LOG:  database system was not properly shut down; automatic recovery in progress
ccfp-asset-dashboard-postgres | 2023-05-05 21:24:42.700 UTC [1745] LOG:  redo starts at 0/3DB8D90
ccfp-asset-dashboard-postgres | 2023-05-05 21:24:42.701 UTC [1745] LOG:  invalid record length at 0/3DCA4F8: wanted 24, got 0
ccfp-asset-dashboard-postgres | 2023-05-05 21:24:42.701 UTC [1745] LOG:  redo done at 0/3DCA4D0
ccfp-asset-dashboard-postgres | 2023-05-05 21:24:42.732 UTC [1] LOG:  database system is ready to accept connections

[smcalilly]

this issue indicates it might be postgis issue, particularly the geos dependency.

local dev dependency versions:

database=# SELECT PostGIS_full_version();

 POSTGIS="3.0.3 0" [EXTENSION] PGSQL="120" GEOS="3.8.1-CAPI-1.13.3" PROJ="7.0.1" LIBXML="2.9.10" LIBJSON="0.14" LIBPROTOBUF="1.3.3" WAGYU="0.4.3 (Internal)" TOPOLOGY

heroku - staging:

SELECT PostGIS_full_version();

 POSTGIS="3.3.2 4975da8" [EXTENSION] PGSQL="150" GEOS="3.8.0-CAPI-1.13.1 " PROJ="6.3.1" LIBXML="2.9.10" LIBJSON="0.13.1" LIBPROTOBUF="1.3.3" WAGYU="0.5.0 (Internal)"

so it's happening with different versions of postgis and geos.

heroku postgres version:

SELECT version();

PostgreSQL 15.3 (Ubuntu 15.3-1.pgdg20.04+1) on x86_64-pc-linux-gnu, compiled by gcc (Ubuntu 9.4.0-1ubuntu1~20.04.1) 9.4.0, 64-bit

[smcalilly]

i'm going to examine the geo data that we're processing as geodjango data types before saving to the database. maybe see if we're having similar issues to this: https://trac.osgeo.org/postgis/ticket/210

(maybe try this? https://postgis.net/docs/ST_CollectionHomogenize.html)

[smcalilly]

something i found debugging this: there are too many GIS queries happening in a short time span. there are a lot of inefficiencies surrounding this processing of GIS data. we have three django signals that are called upon save/delete of LocalAssets, and the signals run for each single geometry. i'm not sure which time complexity it is but it's not good!

inefficiency 1

all three are calling this method:

phase_geoms = LocalAsset.get_aggregated_assets_by_phase(instance.phase)

which is very redundant. and i'm pretty sure save_social_equity_score is doing the same work but not encapsulated in that method. (gasp! this is my bad btw)

inefficiency 2

additionally, each of the signals do an intersection on the GIS data, which is using the postgres resources and potentially duplicating work.

are the inefficiencies causing the problem?

i'm not sure this is causing the problem, as i'm able to recreate the segmentation fault bug in isolation by running a stripped down version the problematic code path:

>>> from asset_dashboard.models import LocalAsset, Phase, Project, SenateDistrict
>>> phase = Phase.objects.get(id=280)
>>> phase_assets = LocalAsset.get_aggregated_assets_by_phase(phase=phase)
>>> senate_intersection = SenateDistrict.objects.filter(boundary__intersects=phase_assets)
>>> senate_intersection
Traceback (most recent call last):
  File "/usr/local/lib/python3.9/site-packages/django/db/backends/utils.py", line 84, in _execute
    return self.cursor.execute(sql, params)
psycopg2.OperationalError: server closed the connection unexpectedly
        This probably means the server terminated abnormally
        before or while processing the request.

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

Traceback (most recent call last):
  File "<console>", line 1, in <module>
  File "/usr/local/lib/python3.9/site-packages/django/db/models/query.py", line 256, in __repr__
    data = list(self[:REPR_OUTPUT_SIZE + 1])
  File "/usr/local/lib/python3.9/site-packages/django/db/models/query.py", line 262, in __len__
    self._fetch_all()
  File "/usr/local/lib/python3.9/site-packages/django/db/models/query.py", line 1324, in _fetch_all
    self._result_cache = list(self._iterable_class(self))
  File "/usr/local/lib/python3.9/site-packages/django/db/models/query.py", line 51, in __iter__
    results = compiler.execute_sql(chunked_fetch=self.chunked_fetch, chunk_size=self.chunk_size)
  File "/usr/local/lib/python3.9/site-packages/django/db/models/sql/compiler.py", line 1175, in execute_sql
    cursor.execute(sql, params)
  File "/usr/local/lib/python3.9/site-packages/django/db/backends/utils.py", line 98, in execute
    return super().execute(sql, params)
  File "/usr/local/lib/python3.9/site-packages/django/db/backends/utils.py", line 66, in execute
    return self._execute_with_wrappers(sql, params, many=False, executor=self._execute)
  File "/usr/local/lib/python3.9/site-packages/django/db/backends/utils.py", line 75, in _execute_with_wrappers
    return executor(sql, params, many, context)
  File "/usr/local/lib/python3.9/site-packages/django/db/backends/utils.py", line 84, in _execute
    return self.cursor.execute(sql, params)
  File "/usr/local/lib/python3.9/site-packages/django/db/utils.py", line 90, in __exit__
    raise dj_exc_value.with_traceback(traceback) from exc_value
  File "/usr/local/lib/python3.9/site-packages/django/db/backends/utils.py", line 84, in _execute
    return self.cursor.execute(sql, params)
django.db.utils.OperationalError: server closed the connection unexpectedly
        This probably means the server terminated abnormally
        before or while processing the request.

>>> 

[smcalilly]

we can brute force it, but this is inefficient and all of the intersection stuff takes place in python (rather than postgis):

>>> for district in SenateDistrict.objects.all():
...     if district.boundary:
...             intersection = district.boundary.intersection(phase_assets)
...             print(district.id, intersection.area)
...
1 0.0
2 0.0
3 0.0
4 0.0
5 0.0
6 0.0
72 0.0
71 0.0
70 0.0
69 0.0
68 0.0
67 0.0
66 0.0
65 0.0
64 0.0
63 0.0
62 0.0
61 2857.6163876980527
60 0.0
59 0.0
58 0.0
57 0.0
56 0.0
55 0.0
54 0.0
53 0.0
52 3614.4467600054522
51 0.0
49 0.0
48 0.0
47 877.6594017606546
46 0.0
50 0.0

comparing postgis intersection query versus python intersection:

>>> import timeit
>>> from asset_dashboard.models import LocalAsset, Phase, SenateDistrict
>>> phase = Phase.objects.get(id=280)
>>> phase_assets = LocalAsset.get_aggregated_assets_by_phase(phase=phase)
>>> stmt1 = "Zone.objects.filter(boundary__intersects=phase_assets)"
>>> setup1 =
KeyboardInterrupt
>>> from asset_dashboard.models import LocalAsset, Phase, Zone
>>> setup1 = "from asset_dashboard.models import LocalAsset, Phase, Zone; phase = Phase.objects.get(id=280); phase_assets = LocalAsset.get_aggregated_assets_by_phase(phase=phase)"
>>> stmt2 = """\
... for zone in Zone.objects.all():
...     if zone.boundary:
...             intersection = zone.boundary.intersection(phase_assets)
... """
>>> setup2 = "from asset_dashboard.models import LocalAsset, Phase, Zone; phase = Phase.objects.get(id=280); phase_assets = LocalAsset.get_aggregated_assets_by_phase(phase=phase)"
>>> num_repeats = 10
>>> num_iterations = 100
>>> t1 = timeit.Timer(stmt1, setup1).repeat(num_repeats, num_iterations)
>>> t2 = timeit.Timer(stmt2, setup2).repeat(num_repeats, num_iterations)
>>> print("Example 1: Average time taken per query = {:.2f} ms".format((sum(t1) * 1000) / (num_repeats * num_iterations)))
Example 1: Average time taken per query = 0.10 ms
>>> print("Example 2: Average time taken per query = {:.2f} ms".format((sum(t2) * 1000) / (num_repeats * num_iterations)))
Example 2: Average time taken per query = 6.98 ms
>>> t2 = timeit.Timer(stmt2, setup2).repeat(num_repeats, num_iterations)
>>> t1 = timeit.Timer(stmt1, setup1).repeat(num_repeats, num_iterations)
>>> print("Example 1: Average time taken per query = {:.2f} ms".format((sum(t1) * 1000) / (num_repeats * num_iterations)))
Example 1: Average time taken per query = 0.10 ms
>>> print("Example 2: Average time taken per query = {:.2f} ms".format((sum(t2) * 1000) / (num_repeats * num_iterations)))
Example 2: Average time taken per query = 6.32 ms

• postgis = 0.10 ms
• python = 6.32 ms

bad!

[smcalilly]

upgrade geos to 3.8.3 (or 3.10)

[smcalilly]

@fgregg upgrading to geos seemed to fix the problem on my local machine. i've created a ton of assets trying to break it but i haven't been able to.

i'm trying to figure out how to upgrade the dependency on the heroku server. heroku provides a way to upgrade postgres and postgres extensions, but i haven't seen a way to upgrade the lower dependencies used by the database.

some links related to that:

• https://devcenter.heroku.com/categories/heroku-postgres
• https://devcenter.heroku.com/articles/heroku-postgres-extensions-postgis-full-text-search
• possibly? https://github.com/heroku/heroku-geo-buildpack

[fgregg]

https://github.com/heroku/heroku-geo-buildpack looks the most promising.

[smcalilly]

@fgregg Agreed. But should we hold off on that since we'll be focusing on deploying to a new server?

[fgregg]

oh, that's a really good point. yes. let's wait.