search

heroku / heroku-buildpack-pgbouncer

Run pgbouncer in a dyno along with your application
MIT License
338 stars 136 forks source link

Pgbouncer segmentation fault when attempting to connect to postgres #164

Closed mkab closed 2 years ago

mkab commented 2 years ago

I have a very weird error that I have been debugging for the past few days.

I have a Django app deployed on two environments on Heroku - development and staging. There's absolutely no difference between the two environments apart from the Heroku stack. The development environment uses heroku-stack-20 while staging uses heroku-stack-22. They both use the same python runtime environment - 3.10.5

I added the pgbouncer buildpack to both environments. It works on dev without problems but on staging, it fails with a segmentation fault.

Here's the complete stacktrace. It's a bit long.

TL;DR

2022-06-18T08:26:59.209886+00:00 app[web.1]: bin/start-pgbouncer: line 100:    25 Segmentation fault      "$@"

Complete stacktrace:

2022-06-18T08:26:00.445651+00:00 app[api]: Scaled to celery@0:Hobby celerybeat@0:Hobby celeryworker@0:Hobby release@0:Hobby web@1:Hobby by user admin@user.com

2022-06-18T08:26:15.023061+00:00 heroku[web.1]: Starting process with command `bin/start-pgbouncer gunicorn --chdir kilimanjaro kilimanjaro.asgi:application --bind 0.0.0.0:40300 --timeout 120 --workers $WEB_CONCURRENCY -k uvicorn.workers.UvicornWorker`

2022-06-18T08:26:16.246309+00:00 app[web.1]: buildpack=pgbouncer at=pgbouncer-enabled

2022-06-18T08:26:16.246374+00:00 app[web.1]: buildpack=pgbouncer at=config-gen-start

2022-06-18T08:26:16.343361+00:00 app[web.1]: Setting DATABASE_URL_PGBOUNCER config var

2022-06-18T08:26:16.368587+00:00 app[web.1]: buildpack=pgbouncer at=config-gen-end

2022-06-18T08:26:16.368615+00:00 app[web.1]: buildpack=pgbouncer at=config-gen-override DATABASE_URL

2022-06-18T08:26:16.376484+00:00 app[web.1]: buildpack=pgbouncer at=pgbouncer-launched pid=23 signal=SIGINT

2022-06-18T08:26:16.376538+00:00 app[web.1]: buildpack=pgbouncer at=pgbouncer-start

2022-06-18T08:26:16.376789+00:00 app[web.1]: buildpack=pgbouncer at=app-launched pid=24

2022-06-18T08:26:16.376891+00:00 app[web.1]: buildpack=pgbouncer at=app-start

2022-06-18T08:26:16.511046+00:00 app[web.1]: 2022-06-18 08:26:16.510 UTC [25] LOG kernel file descriptor limit: 10000 (hard: 10000); max_client_conn: 100, max expected fd use: 114

2022-06-18T08:26:16.512782+00:00 app[web.1]: 2022-06-18 08:26:16.512 UTC [25] LOG listening on 127.0.0.1:6000

2022-06-18T08:26:16.512836+00:00 app[web.1]: 2022-06-18 08:26:16.512 UTC [25] LOG listening on unix:/tmp/.s.PGSQL.6000

2022-06-18T08:26:16.512853+00:00 app[web.1]: 2022-06-18 08:26:16.512 UTC [25] LOG process up: PgBouncer 1.14.0, libevent 2.1.12-stable (epoll), adns: evdns2, tls: OpenSSL 3.0.2 15 Mar 2022

2022-06-18T08:26:16.741387+00:00 app[web.1]: [2022-06-18 08:26:16 +0000] [27] [INFO] Starting gunicorn 20.1.0

2022-06-18T08:26:16.741729+00:00 app[web.1]: [2022-06-18 08:26:16 +0000] [27] [INFO] Listening at: http://0.0.0.0:40300 (27)

2022-06-18T08:26:16.741776+00:00 app[web.1]: [2022-06-18 08:26:16 +0000] [27] [INFO] Using worker: uvicorn.workers.UvicornWorker

2022-06-18T08:26:16.745349+00:00 app[web.1]: [2022-06-18 08:26:16 +0000] [31] [INFO] Booting worker with pid: 31

2022-06-18T08:26:16.753214+00:00 app[web.1]: [2022-06-18 08:26:16 +0000] [32] [INFO] Booting worker with pid: 32

2022-06-18T08:26:17.273727+00:00 heroku[web.1]: State changed from starting to up

2022-06-18T08:26:18.094750+00:00 app[web.1]: INFO 2022-06-18 08:26:18,094 core 32 /app/.heroku/python/lib/python3.10/site-packages/django_heroku/core.py settings Applying Heroku ALLOWED_HOSTS configuration to Django settings.

2022-06-18T08:26:18.096212+00:00 app[web.1]: INFO 2022-06-18 08:26:18,096 core 32 /app/.heroku/python/lib/python3.10/site-packages/django_heroku/core.py settings Applying Heroku logging configuration to Django settings.

2022-06-18T08:26:18.096352+00:00 app[web.1]: INFO 2022-06-18 08:26:18,096 core 32 /app/.heroku/python/lib/python3.10/site-packages/django_heroku/core.py settings Adding $SECRET_KEY to SECRET_KEY Django setting.

2022-06-18T08:26:18.102411+00:00 app[web.1]: INFO 2022-06-18 08:26:18,102 core 31 /app/.heroku/python/lib/python3.10/site-packages/django_heroku/core.py settings Applying Heroku ALLOWED_HOSTS configuration to Django settings.

2022-06-18T08:26:18.103471+00:00 app[web.1]: INFO 2022-06-18 08:26:18,103 core 31 /app/.heroku/python/lib/python3.10/site-packages/django_heroku/core.py settings Applying Heroku logging configuration to Django settings.

2022-06-18T08:26:18.103562+00:00 app[web.1]: INFO 2022-06-18 08:26:18,103 core 31 /app/.heroku/python/lib/python3.10/site-packages/django_heroku/core.py settings Adding $SECRET_KEY to SECRET_KEY Django setting.

2022-06-18T08:26:19.208891+00:00 app[web.1]: [2022-06-18 08:26:19 +0000] [32] [INFO] Started server process [32]

2022-06-18T08:26:19.209043+00:00 app[web.1]: [2022-06-18 08:26:19 +0000] [32] [INFO] Waiting for application startup.

2022-06-18T08:26:19.209230+00:00 app[web.1]: [2022-06-18 08:26:19 +0000] [32] [INFO] ASGI 'lifespan' protocol appears unsupported.

2022-06-18T08:26:19.209337+00:00 app[web.1]: [2022-06-18 08:26:19 +0000] [32] [INFO] Application startup complete.

2022-06-18T08:26:19.209840+00:00 app[web.1]: [2022-06-18 08:26:19 +0000] [31] [INFO] Started server process [31]

2022-06-18T08:26:19.209840+00:00 app[web.1]: [2022-06-18 08:26:19 +0000] [31] [INFO] Waiting for application startup.

2022-06-18T08:26:19.210032+00:00 app[web.1]: [2022-06-18 08:26:19 +0000] [31] [INFO] ASGI 'lifespan' protocol appears unsupported.

2022-06-18T08:26:19.210161+00:00 app[web.1]: [2022-06-18 08:26:19 +0000] [31] [INFO] Application startup complete.

2022-06-18T08:26:59.407500+00:00 app[web.1]: [2022-06-18 08:26:59 +0000] [32] [INFO] Finished server process [32]

2022-06-18T08:26:59.408522+00:00 app[web.1]: [2022-06-18 08:26:59 +0000] [32] [INFO] Worker exiting (pid: 32)

2022-06-18T08:26:59.323152+00:00 heroku[router]: at=info method=GET path="/admin/" host=staging-web.herokuapp.com request_id=fb3fa9b7-fa63-475a-915d-481e83338e28 fwd="185.248.85.24" dyno=web.1 connect=0ms service=513ms status=500 bytes=203597 protocol=https

2022-06-18T08:26:59.148373+00:00 app[web.1]: 2022-06-18 08:26:59.148 UTC [25] LOG C-0x5635d002ce90: db1/gdvrujishzszsh@127.0.0.1:57004 login attempt: db=db1 user=gdvrujishzszsh tls=no

2022-06-18T08:26:59.175986+00:00 app[web.1]: 2022-06-18 08:26:59.175 UTC [25] LOG S-0x5635d0033c30: db1/gdvrujishzszsh@54.157.16.196:5432 new connection to server (from 172.18.80.26:59898)

2022-06-18T08:26:59.209886+00:00 app[web.1]: bin/start-pgbouncer: line 100:    25 Segmentation fault      "$@"

2022-06-18T08:26:59.210102+00:00 app[web.1]: buildpack=pgbouncer at=pgbouncer-end

2022-06-18T08:26:59.210159+00:00 app[web.1]: buildpack=pgbouncer at=exit process=pgbouncer

2022-06-18T08:26:59.215337+00:00 app[web.1]: buildpack=pgbouncer at=kill-app pid=24

2022-06-18T08:26:59.215407+00:00 app[web.1]: buildpack=pgbouncer at=wait-app pid=24

2022-06-18T08:26:59.215974+00:00 app[web.1]: [2022-06-18 08:26:59 +0000] [27] [INFO] Handling signal: term

2022-06-18T08:26:59.227517+00:00 app[web.1]: [2022-06-18 08:26:59 +0000] [31] [INFO] Shutting down

2022-06-18T08:26:59.227939+00:00 app[web.1]: [2022-06-18 08:26:59 +0000] [31] [INFO] Error while closing socket [Errno 9] Bad file descriptor

2022-06-18T08:26:59.306078+00:00 app[web.1]: [2022-06-18 08:26:59 +0000] [32] [INFO] Shutting down

2022-06-18T08:26:59.306376+00:00 app[web.1]: [2022-06-18 08:26:59 +0000] [32] [INFO] Error while closing socket [Errno 9] Bad file descriptor

2022-06-18T08:26:59.308917+00:00 app[web.1]: ERROR 2022-06-18 08:26:59,305 log 32 /app/.heroku/python/lib/python3.10/site-packages/django/utils/log.py log_response Internal Server Error: /admin/

2022-06-18T08:26:59.308918+00:00 app[web.1]: Traceback (most recent call last):

2022-06-18T08:26:59.308920+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/backends/base/base.py", line 219, in ensure_connection

2022-06-18T08:26:59.308921+00:00 app[web.1]:     self.connect()

2022-06-18T08:26:59.308921+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/sentry_sdk/integrations/django/__init__.py", line 567, in connect

2022-06-18T08:26:59.308922+00:00 app[web.1]:     return real_connect(self)

2022-06-18T08:26:59.308922+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/utils/asyncio.py", line 33, in inner

2022-06-18T08:26:59.308923+00:00 app[web.1]:     return func(*args, **kwargs)

2022-06-18T08:26:59.308923+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/backends/base/base.py", line 200, in connect

2022-06-18T08:26:59.308924+00:00 app[web.1]:     self.connection = self.get_new_connection(conn_params)

2022-06-18T08:26:59.308924+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/utils/asyncio.py", line 33, in inner

2022-06-18T08:26:59.308924+00:00 app[web.1]:     return func(*args, **kwargs)

2022-06-18T08:26:59.308925+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/backends/postgresql/base.py", line 187, in get_new_connection

2022-06-18T08:26:59.308925+00:00 app[web.1]:     connection = Database.connect(**conn_params)

2022-06-18T08:26:59.308926+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/psycopg2/__init__.py", line 122, in connect

2022-06-18T08:26:59.308926+00:00 app[web.1]:     conn = _connect(dsn, connection_factory=connection_factory, **kwasync)

2022-06-18T08:26:59.308927+00:00 app[web.1]: psycopg2.OperationalError: connection to server at "127.0.0.1", port 6000 failed: server closed the connection unexpectedly

2022-06-18T08:26:59.308927+00:00 app[web.1]:    This probably means the server terminated abnormally

2022-06-18T08:26:59.308928+00:00 app[web.1]:    before or while processing the request.

2022-06-18T08:26:59.308929+00:00 app[web.1]: 

2022-06-18T08:26:59.308929+00:00 app[web.1]: 

2022-06-18T08:26:59.308929+00:00 app[web.1]: The above exception was the direct cause of the following exception:

2022-06-18T08:26:59.308930+00:00 app[web.1]: 

2022-06-18T08:26:59.308930+00:00 app[web.1]: Traceback (most recent call last):

2022-06-18T08:26:59.308930+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/core/handlers/exception.py", line 47, in inner

2022-06-18T08:26:59.308931+00:00 app[web.1]:     response = get_response(request)

2022-06-18T08:26:59.308931+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/sentry_sdk/integrations/django/middleware.py", line 175, in __call__

2022-06-18T08:26:59.308932+00:00 app[web.1]:     return f(*args, **kwargs)

2022-06-18T08:26:59.308932+00:00 app[web.1]:   File "/app/kilimanjaro/core/utils/middlewares.py", line 90, in __call__

2022-06-18T08:26:59.308932+00:00 app[web.1]:     response = self.process_response(request)

2022-06-18T08:26:59.308933+00:00 app[web.1]:   File "/app/kilimanjaro/core/utils/middlewares.py", line 106, in process_response

2022-06-18T08:26:59.308934+00:00 app[web.1]:     cache.set("client_api_keys", client_api_list, timeout=CACHE_TTL)

2022-06-18T08:26:59.308934+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django_redis/cache.py", line 31, in _decorator

2022-06-18T08:26:59.308935+00:00 app[web.1]:     return method(self, *args, **kwargs)

2022-06-18T08:26:59.308935+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django_redis/cache.py", line 80, in set

2022-06-18T08:26:59.308935+00:00 app[web.1]:     return self.client.set(*args, **kwargs)

2022-06-18T08:26:59.308936+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django_redis/client/default.py", line 143, in set

2022-06-18T08:26:59.308936+00:00 app[web.1]:     nvalue = self.encode(value)

2022-06-18T08:26:59.308936+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django_redis/client/default.py", line 457, in encode

2022-06-18T08:26:59.308937+00:00 app[web.1]:     value = self._serializer.dumps(value)

2022-06-18T08:26:59.308937+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django_redis/serializers/pickle.py", line 29, in dumps

2022-06-18T08:26:59.308937+00:00 app[web.1]:     return pickle.dumps(value, self._pickle_version)

2022-06-18T08:26:59.308938+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/models/query.py", line 233, in __getstate__

2022-06-18T08:26:59.308938+00:00 app[web.1]:     self._fetch_all()

2022-06-18T08:26:59.308939+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/nplusone/ext/django/patch.py", line 295, in fetch_all

2022-06-18T08:26:59.308939+00:00 app[web.1]:     original_fetch_all(self)

2022-06-18T08:26:59.308939+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/models/query.py", line 1324, in _fetch_all

2022-06-18T08:26:59.308940+00:00 app[web.1]:     self._result_cache = list(self._iterable_class(self))

2022-06-18T08:26:59.308952+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/models/query.py", line 51, in __iter__

2022-06-18T08:26:59.308953+00:00 app[web.1]:     results = compiler.execute_sql(chunked_fetch=self.chunked_fetch, chunk_size=self.chunk_size)

2022-06-18T08:26:59.308953+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/models/sql/compiler.py", line 1173, in execute_sql

2022-06-18T08:26:59.308953+00:00 app[web.1]:     cursor = self.connection.cursor()

2022-06-18T08:26:59.308954+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/utils/asyncio.py", line 33, in inner

2022-06-18T08:26:59.308954+00:00 app[web.1]:     return func(*args, **kwargs)

2022-06-18T08:26:59.308954+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/backends/base/base.py", line 259, in cursor

2022-06-18T08:26:59.308955+00:00 app[web.1]:     return self._cursor()

2022-06-18T08:26:59.308960+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/backends/base/base.py", line 235, in _cursor

2022-06-18T08:26:59.308960+00:00 app[web.1]:     self.ensure_connection()

2022-06-18T08:26:59.308960+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/utils/asyncio.py", line 33, in inner

2022-06-18T08:26:59.308961+00:00 app[web.1]:     return func(*args, **kwargs)

2022-06-18T08:26:59.308961+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/backends/base/base.py", line 218, in ensure_connection

2022-06-18T08:26:59.308961+00:00 app[web.1]:     with self.wrap_database_errors:

2022-06-18T08:26:59.308962+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/utils.py", line 90, in __exit__

2022-06-18T08:26:59.308962+00:00 app[web.1]:     raise dj_exc_value.with_traceback(traceback) from exc_value

2022-06-18T08:26:59.308962+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/backends/base/base.py", line 219, in ensure_connection

2022-06-18T08:26:59.308963+00:00 app[web.1]:     self.connect()

2022-06-18T08:26:59.308963+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/sentry_sdk/integrations/django/__init__.py", line 567, in connect

2022-06-18T08:26:59.308964+00:00 app[web.1]:     return real_connect(self)

2022-06-18T08:26:59.308964+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/utils/asyncio.py", line 33, in inner

2022-06-18T08:26:59.308964+00:00 app[web.1]:     return func(*args, **kwargs)

2022-06-18T08:26:59.308964+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/backends/base/base.py", line 200, in connect

2022-06-18T08:26:59.308965+00:00 app[web.1]:     self.connection = self.get_new_connection(conn_params)

2022-06-18T08:26:59.308965+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/utils/asyncio.py", line 33, in inner

2022-06-18T08:26:59.308965+00:00 app[web.1]:     return func(*args, **kwargs)

2022-06-18T08:26:59.308966+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/backends/postgresql/base.py", line 187, in get_new_connection

2022-06-18T08:26:59.308966+00:00 app[web.1]:     connection = Database.connect(**conn_params)

2022-06-18T08:26:59.308966+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/psycopg2/__init__.py", line 122, in connect

2022-06-18T08:26:59.308967+00:00 app[web.1]:     conn = _connect(dsn, connection_factory=connection_factory, **kwasync)

2022-06-18T08:26:59.308967+00:00 app[web.1]: django.db.utils.OperationalError: connection to server at "127.0.0.1", port 6000 failed: server closed the connection unexpectedly

2022-06-18T08:26:59.308967+00:00 app[web.1]:    This probably means the server terminated abnormally

2022-06-18T08:26:59.308968+00:00 app[web.1]:    before or while processing the request.

2022-06-18T08:26:59.308968+00:00 app[web.1]: 

2022-06-18T08:26:59.316615+00:00 app[web.1]: 185.248.85.24:0 - "GET /admin/ HTTP/1.1" 500

2022-06-18T08:26:59.328308+00:00 app[web.1]: [2022-06-18 08:26:59 +0000] [31] [INFO] Finished server process [31]

2022-06-18T08:26:59.328842+00:00 app[web.1]: [2022-06-18 08:26:59 +0000] [31] [INFO] Worker exiting (pid: 31)

2022-06-18T08:26:59.917215+00:00 app[web.1]: [2022-06-18 08:26:59 +0000] [27] [INFO] Shutting down: Master

2022-06-18T08:26:59.954553+00:00 app[web.1]: buildpack=pgbouncer at=app-end

2022-06-18T08:26:59.954806+00:00 app[web.1]: buildpack=pgbouncer at=kill-aux name=pgbouncer pid=23 signal=SIGINT

2022-06-18T08:26:59.955010+00:00 app[web.1]: bin/start-pgbouncer: line 62: kill: (23) - No such process

2022-06-18T08:27:00.090738+00:00 heroku[web.1]: Process exited with status 1

2022-06-18T08:27:00.222081+00:00 heroku[web.1]: State changed from up to crashed

2022-06-18T08:27:00.234609+00:00 heroku[web.1]: State changed from crashed to starting

2022-06-18T08:27:09.426407+00:00 heroku[web.1]: Starting process with command `bin/start-pgbouncer gunicorn --chdir kilimanjaro kilimanjaro.asgi:application --bind 0.0.0.0:28693 --timeout 120 --workers $WEB_CONCURRENCY -k uvicorn.workers.UvicornWorker`

2022-06-18T08:27:10.483939+00:00 app[web.1]: buildpack=pgbouncer at=pgbouncer-enabled

2022-06-18T08:27:10.484015+00:00 app[web.1]: buildpack=pgbouncer at=config-gen-start

2022-06-18T08:27:10.541586+00:00 app[web.1]: Setting DATABASE_URL_PGBOUNCER config var

2022-06-18T08:27:10.549486+00:00 app[web.1]: buildpack=pgbouncer at=config-gen-end

2022-06-18T08:27:10.549506+00:00 app[web.1]: buildpack=pgbouncer at=config-gen-override DATABASE_URL

2022-06-18T08:27:10.556191+00:00 app[web.1]: buildpack=pgbouncer at=pgbouncer-launched pid=23 signal=SIGINT

2022-06-18T08:27:10.556261+00:00 app[web.1]: buildpack=pgbouncer at=pgbouncer-start

2022-06-18T08:27:10.556437+00:00 app[web.1]: buildpack=pgbouncer at=app-launched pid=24

2022-06-18T08:27:10.556588+00:00 app[web.1]: buildpack=pgbouncer at=app-start

2022-06-18T08:27:10.681111+00:00 app[web.1]: 2022-06-18 08:27:10.681 UTC [25] LOG kernel file descriptor limit: 10000 (hard: 10000); max_client_conn: 100, max expected fd use: 114

2022-06-18T08:27:10.682239+00:00 app[web.1]: 2022-06-18 08:27:10.682 UTC [25] LOG listening on 127.0.0.1:6000

2022-06-18T08:27:10.682281+00:00 app[web.1]: 2022-06-18 08:27:10.682 UTC [25] LOG listening on unix:/tmp/.s.PGSQL.6000

2022-06-18T08:27:10.682296+00:00 app[web.1]: 2022-06-18 08:27:10.682 UTC [25] LOG process up: PgBouncer 1.14.0, libevent 2.1.12-stable (epoll), adns: evdns2, tls: OpenSSL 3.0.2 15 Mar 2022

2022-06-18T08:27:10.934722+00:00 app[web.1]: [2022-06-18 08:27:10 +0000] [27] [INFO] Starting gunicorn 20.1.0

2022-06-18T08:27:10.935094+00:00 app[web.1]: [2022-06-18 08:27:10 +0000] [27] [INFO] Listening at: http://0.0.0.0:28693 (27)

2022-06-18T08:27:10.935137+00:00 app[web.1]: [2022-06-18 08:27:10 +0000] [27] [INFO] Using worker: uvicorn.workers.UvicornWorker

2022-06-18T08:27:10.939008+00:00 app[web.1]: [2022-06-18 08:27:10 +0000] [31] [INFO] Booting worker with pid: 31

2022-06-18T08:27:10.990033+00:00 app[web.1]: [2022-06-18 08:27:10 +0000] [32] [INFO] Booting worker with pid: 32

2022-06-18T08:27:11.093575+00:00 heroku[web.1]: State changed from starting to up

2022-06-18T08:27:12.176369+00:00 app[web.1]: INFO 2022-06-18 08:27:12,176 core 32 /app/.heroku/python/lib/python3.10/site-packages/django_heroku/core.py settings Applying Heroku ALLOWED_HOSTS configuration to Django settings.

2022-06-18T08:27:12.177364+00:00 app[web.1]: INFO 2022-06-18 08:27:12,177 core 32 /app/.heroku/python/lib/python3.10/site-packages/django_heroku/core.py settings Applying Heroku logging configuration to Django settings.

2022-06-18T08:27:12.177461+00:00 app[web.1]: INFO 2022-06-18 08:27:12,177 core 32 /app/.heroku/python/lib/python3.10/site-packages/django_heroku/core.py settings Adding $SECRET_KEY to SECRET_KEY Django setting.

2022-06-18T08:27:12.177532+00:00 app[web.1]: An error occurred while attempting to delete OPTIONS or sslmode. Reason: the key 'OPTIONS' does not exist

2022-06-18T08:27:13.142097+00:00 app[web.1]: [2022-06-18 08:27:13 +0000] [32] [INFO] Started server process [32]

2022-06-18T08:27:13.142233+00:00 app[web.1]: [2022-06-18 08:27:13 +0000] [32] [INFO] Waiting for application startup.

2022-06-18T08:27:13.142373+00:00 app[web.1]: [2022-06-18 08:27:13 +0000] [32] [INFO] ASGI 'lifespan' protocol appears unsupported.

2022-06-18T08:27:13.142447+00:00 app[web.1]: [2022-06-18 08:27:13 +0000] [32] [INFO] Application startup complete.

2022-06-18T08:27:13.363953+00:00 app[web.1]: 2022-06-18 08:27:13.363 UTC [25] LOG C-0x55d703d7de90: db1/gdvrujishzszsh@127.0.0.1:35008 login attempt: db=db1 user=gdvrujishzszsh tls=no

2022-06-18T08:27:13.392721+00:00 app[web.1]: 2022-06-18 08:27:13.392 UTC [25] LOG S-0x55d703d84c30: db1/gdvrujishzszsh@54.157.16.196:5432 new connection to server (from 172.17.133.114:60738)

2022-06-18T08:27:13.567001+00:00 app[web.1]: bin/start-pgbouncer: line 100:    25 Segmentation fault      "$@"

2022-06-18T08:27:13.567127+00:00 app[web.1]: buildpack=pgbouncer at=pgbouncer-end

2022-06-18T08:27:13.567198+00:00 app[web.1]: buildpack=pgbouncer at=exit process=pgbouncer

2022-06-18T08:27:13.569634+00:00 app[web.1]: buildpack=pgbouncer at=kill-app pid=24

2022-06-18T08:27:13.569684+00:00 app[web.1]: buildpack=pgbouncer at=wait-app pid=24

2022-06-18T08:27:13.570210+00:00 app[web.1]: [2022-06-18 08:27:13 +0000] [27] [INFO] Handling signal: term

2022-06-18T08:27:13.574933+00:00 app[web.1]: [2022-06-18 08:27:13 +0000] [27] [WARNING] Worker with pid 31 was terminated due to signal 15

2022-06-18T08:27:13.619017+00:00 app[web.1]: [2022-06-18 08:27:13 +0000] [32] [INFO] Shutting down

2022-06-18T08:27:13.624384+00:00 app[web.1]: [2022-06-18 08:27:13 +0000] [32] [INFO] Error while closing socket [Errno 9] Bad file descriptor

2022-06-18T08:27:13.634420+00:00 app[web.1]: ERROR 2022-06-18 08:27:13,631 log 32 /app/.heroku/python/lib/python3.10/site-packages/django/utils/log.py log_response Internal Server Error: /favicon.ico

2022-06-18T08:27:13.634424+00:00 app[web.1]: Traceback (most recent call last):

2022-06-18T08:27:13.634426+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/backends/base/base.py", line 219, in ensure_connection

2022-06-18T08:27:13.634427+00:00 app[web.1]:     self.connect()

2022-06-18T08:27:13.634427+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/sentry_sdk/integrations/django/__init__.py", line 567, in connect

2022-06-18T08:27:13.634428+00:00 app[web.1]:     return real_connect(self)

2022-06-18T08:27:13.634428+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/utils/asyncio.py", line 33, in inner

2022-06-18T08:27:13.634429+00:00 app[web.1]:     return func(*args, **kwargs)

2022-06-18T08:27:13.634429+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/backends/base/base.py", line 200, in connect

2022-06-18T08:27:13.634430+00:00 app[web.1]:     self.connection = self.get_new_connection(conn_params)

2022-06-18T08:27:13.634430+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/utils/asyncio.py", line 33, in inner

2022-06-18T08:27:13.634430+00:00 app[web.1]:     return func(*args, **kwargs)

2022-06-18T08:27:13.634432+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/backends/postgresql/base.py", line 187, in get_new_connection

2022-06-18T08:27:13.634432+00:00 app[web.1]:     connection = Database.connect(**conn_params)

2022-06-18T08:27:13.634432+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/psycopg2/__init__.py", line 122, in connect

2022-06-18T08:27:13.634433+00:00 app[web.1]:     conn = _connect(dsn, connection_factory=connection_factory, **kwasync)

2022-06-18T08:27:13.634433+00:00 app[web.1]: psycopg2.OperationalError: connection to server at "127.0.0.1", port 6000 failed: server closed the connection unexpectedly

2022-06-18T08:27:13.634434+00:00 app[web.1]:    This probably means the server terminated abnormally

2022-06-18T08:27:13.634434+00:00 app[web.1]:    before or while processing the request.

2022-06-18T08:27:13.634434+00:00 app[web.1]: 

2022-06-18T08:27:13.634435+00:00 app[web.1]: 

2022-06-18T08:27:13.634435+00:00 app[web.1]: The above exception was the direct cause of the following exception:

2022-06-18T08:27:13.634435+00:00 app[web.1]: 

2022-06-18T08:27:13.634435+00:00 app[web.1]: Traceback (most recent call last):

2022-06-18T08:27:13.634436+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/core/handlers/exception.py", line 47, in inner

2022-06-18T08:27:13.634436+00:00 app[web.1]:     response = get_response(request)

2022-06-18T08:27:13.634436+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/sentry_sdk/integrations/django/middleware.py", line 175, in __call__

2022-06-18T08:27:13.634437+00:00 app[web.1]:     return f(*args, **kwargs)

2022-06-18T08:27:13.634437+00:00 app[web.1]:   File "/app/kilimanjaro/core/utils/middlewares.py", line 90, in __call__

2022-06-18T08:27:13.634437+00:00 app[web.1]:     response = self.process_response(request)

2022-06-18T08:27:13.634438+00:00 app[web.1]:   File "/app/kilimanjaro/core/utils/middlewares.py", line 106, in process_response

2022-06-18T08:27:13.634439+00:00 app[web.1]:     cache.set("client_api_keys", client_api_list, timeout=CACHE_TTL)

2022-06-18T08:27:13.634439+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django_redis/cache.py", line 31, in _decorator

2022-06-18T08:27:13.634439+00:00 app[web.1]:     return method(self, *args, **kwargs)

2022-06-18T08:27:13.634439+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django_redis/cache.py", line 80, in set

2022-06-18T08:27:13.634440+00:00 app[web.1]:     return self.client.set(*args, **kwargs)

2022-06-18T08:27:13.634440+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django_redis/client/default.py", line 143, in set

2022-06-18T08:27:13.634440+00:00 app[web.1]:     nvalue = self.encode(value)

2022-06-18T08:27:13.634440+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django_redis/client/default.py", line 457, in encode

2022-06-18T08:27:13.634441+00:00 app[web.1]:     value = self._serializer.dumps(value)

2022-06-18T08:27:13.634441+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django_redis/serializers/pickle.py", line 29, in dumps

2022-06-18T08:27:13.634441+00:00 app[web.1]:     return pickle.dumps(value, self._pickle_version)

2022-06-18T08:27:13.634441+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/models/query.py", line 233, in __getstate__

2022-06-18T08:27:13.634442+00:00 app[web.1]:     self._fetch_all()

2022-06-18T08:27:13.634442+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/nplusone/ext/django/patch.py", line 295, in fetch_all

2022-06-18T08:27:13.634442+00:00 app[web.1]:     original_fetch_all(self)

2022-06-18T08:27:13.634442+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/models/query.py", line 1324, in _fetch_all

2022-06-18T08:27:13.634443+00:00 app[web.1]:     self._result_cache = list(self._iterable_class(self))

2022-06-18T08:27:13.634443+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/models/query.py", line 51, in __iter__

2022-06-18T08:27:13.634443+00:00 app[web.1]:     results = compiler.execute_sql(chunked_fetch=self.chunked_fetch, chunk_size=self.chunk_size)

2022-06-18T08:27:13.634443+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/models/sql/compiler.py", line 1173, in execute_sql

2022-06-18T08:27:13.634444+00:00 app[web.1]:     cursor = self.connection.cursor()

2022-06-18T08:27:13.634444+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/utils/asyncio.py", line 33, in inner

2022-06-18T08:27:13.634444+00:00 app[web.1]:     return func(*args, **kwargs)

2022-06-18T08:27:13.634444+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/backends/base/base.py", line 259, in cursor

2022-06-18T08:27:13.634445+00:00 app[web.1]:     return self._cursor()

2022-06-18T08:27:13.634451+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/backends/base/base.py", line 235, in _cursor

2022-06-18T08:27:13.634451+00:00 app[web.1]:     self.ensure_connection()

2022-06-18T08:27:13.634452+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/utils/asyncio.py", line 33, in inner

2022-06-18T08:27:13.634452+00:00 app[web.1]:     return func(*args, **kwargs)

2022-06-18T08:27:13.634452+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/backends/base/base.py", line 218, in ensure_connection

2022-06-18T08:27:13.634452+00:00 app[web.1]:     with self.wrap_database_errors:

2022-06-18T08:27:13.634453+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/utils.py", line 90, in __exit__

2022-06-18T08:27:13.634453+00:00 app[web.1]:     raise dj_exc_value.with_traceback(traceback) from exc_value

2022-06-18T08:27:13.634453+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/backends/base/base.py", line 219, in ensure_connection

2022-06-18T08:27:13.634453+00:00 app[web.1]:     self.connect()

2022-06-18T08:27:13.634454+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/sentry_sdk/integrations/django/__init__.py", line 567, in connect

2022-06-18T08:27:13.634454+00:00 app[web.1]:     return real_connect(self)

2022-06-18T08:27:13.634454+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/utils/asyncio.py", line 33, in inner

2022-06-18T08:27:13.634454+00:00 app[web.1]:     return func(*args, **kwargs)

2022-06-18T08:27:13.634455+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/backends/base/base.py", line 200, in connect

2022-06-18T08:27:13.634455+00:00 app[web.1]:     self.connection = self.get_new_connection(conn_params)

2022-06-18T08:27:13.634455+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/utils/asyncio.py", line 33, in inner

2022-06-18T08:27:13.634455+00:00 app[web.1]:     return func(*args, **kwargs)

2022-06-18T08:27:13.634456+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/backends/postgresql/base.py", line 187, in get_new_connection

2022-06-18T08:27:13.634456+00:00 app[web.1]:     connection = Database.connect(**conn_params)

2022-06-18T08:27:13.634456+00:00 app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/psycopg2/__init__.py", line 122, in connect

2022-06-18T08:27:13.634457+00:00 app[web.1]:     conn = _connect(dsn, connection_factory=connection_factory, **kwasync)

2022-06-18T08:27:13.634457+00:00 app[web.1]: django.db.utils.OperationalError: connection to server at "127.0.0.1", port 6000 failed: server closed the connection unexpectedly

2022-06-18T08:27:13.634457+00:00 app[web.1]:    This probably means the server terminated abnormally

2022-06-18T08:27:13.634458+00:00 app[web.1]:    before or while processing the request.

2022-06-18T08:27:13.634458+00:00 app[web.1]: 

2022-06-18T08:27:13.635686+00:00 app[web.1]: 185.248.85.24:0 - "GET /favicon.ico HTTP/1.1" 500

2022-06-18T08:27:13.634901+00:00 heroku[router]: sock=client at=warning code=H27 desc="Client Request Interrupted" method=GET path="/favicon.ico" host=staging-web.herokuapp.com request_id=98628e7c-6ebe-4286-824e-16bf185ec76f fwd="185.248.85.24" dyno=web.1 connect=0ms service=1673ms status=499 bytes= protocol=https

2022-06-18T08:27:13.729859+00:00 app[web.1]: [2022-06-18 08:27:13 +0000] [32] [INFO] Finished server process [32]

2022-06-18T08:27:13.730971+00:00 app[web.1]: [2022-06-18 08:27:13 +0000] [32] [INFO] Worker exiting (pid: 32)

2022-06-18T08:27:14.271459+00:00 app[web.1]: [2022-06-18 08:27:14 +0000] [27] [INFO] Shutting down: Master

2022-06-18T08:27:14.317632+00:00 app[web.1]: buildpack=pgbouncer at=app-end

2022-06-18T08:27:14.317928+00:00 app[web.1]: buildpack=pgbouncer at=kill-aux name=pgbouncer pid=23 signal=SIGINT

2022-06-18T08:27:14.318170+00:00 app[web.1]: bin/start-pgbouncer: line 62: kill: (23) - No such process

2022-06-18T08:27:14.594928+00:00 heroku[web.1]: Process exited with status 1

2022-06-18T08:27:14.651940+00:00 heroku[web.1]: State changed from up to crashed

Any ideas why this segmentation fault is happening?

edmorley commented 2 years ago

So I think this may be due to pgbouncer 1.14 (the version currently used by this buildpack) not being fully compatible with OpenSSL 3.

In the release notes for pgbouncer 1.17 there is:

OpenSSL 3 support has been fixed. Previous releases would crash.

It looks like a previous attempt to upgrade the pgbouncer version to something newer (at the time, 1.15), was reverted (#152) due to issues being reported with 1.15 (#150).

However upgrading now seems unavoidable.

Perhaps we should just use 1.17 for Heroku-22 and leave the other stacks on 1.14 until the cause of #150 is understood? (It's also possible those issues have already been fixed in 1.16/1.17 too)

cc @beanieboi

edmorley commented 2 years ago

I've also filed #165 since it's clear the CI for this repo isn't sufficient.

mkab commented 2 years ago

@edmorley thanks a lot for looking into it! What will you say is a viable solution for my case for the time being? Should I downgrade to Heroku-20? I reckon it's going to take some time to upgrade the pgbouncer version to 1.17.

edmorley commented 2 years ago

Yeah I would stick with Heroku-20 for now, if you need to use the pgbouncer buildpack. Note there is now also server-side Postgres connection pooling available as an alternative to pgbouncer on the dyno (which if sufficient for your use-case would mean you can stop using the buildpack): https://devcenter.heroku.com/articles/postgres-connection-pooling

mkab commented 2 years ago

Ok, I will check it out. Thanks

pedrommone commented 2 years ago

Hello! We're getting the same issue,

2022-06-20T14:32:31.583746+00:00 app[worker.1]: buildpack=pgbouncer at=pgbouncer-enabled
2022-06-20T14:32:31.591861+00:00 app[worker.1]: buildpack=pgbouncer at=config-gen-start
2022-06-20T14:32:31.683888+00:00 app[worker.1]: Setting DATABASE_URL_PGBOUNCER config var
2022-06-20T14:32:31.713744+00:00 app[worker.1]: buildpack=pgbouncer at=config-gen-end
2022-06-20T14:32:31.714011+00:00 app[worker.1]: buildpack=pgbouncer at=config-gen-override DATABASE_URL
2022-06-20T14:32:31.732932+00:00 app[worker.1]: buildpack=pgbouncer at=pgbouncer-launched pid=45 signal=SIGINT
2022-06-20T14:32:31.733001+00:00 app[worker.1]: buildpack=pgbouncer at=pgbouncer-start
2022-06-20T14:32:31.733290+00:00 app[worker.1]: buildpack=pgbouncer at=app-launched pid=46
2022-06-20T14:32:31.735803+00:00 app[worker.1]: buildpack=pgbouncer at=app-start
2022-06-20T14:32:31.865047+00:00 app[worker.1]: 2022-06-20 14:32:31.864 UTC [47] LOG kernel file descriptor limit: 10000 (hard: 10000); max_client_conn: 100, max expected fd use: 114
2022-06-20T14:32:31.865837+00:00 app[worker.1]: 2022-06-20 14:32:31.865 UTC [47] LOG listening on 127.0.0.1:6000
2022-06-20T14:32:31.865946+00:00 app[worker.1]: 2022-06-20 14:32:31.865 UTC [47] LOG listening on unix:/tmp/.s.PGSQL.6000
2022-06-20T14:32:31.865987+00:00 app[worker.1]: 2022-06-20 14:32:31.865 UTC [47] LOG process up: PgBouncer 1.14.0, libevent 2.1.12-stable (epoll), adns: evdns2, tls: OpenSSL 3.0.2 15 Mar 2022
2022-06-20T14:32:32.518211+00:00 app[worker.1]: Horizon started successfully.
2022-06-20T14:32:36.138334+00:00 app[worker.1]: 2022-06-20 14:32:36.138 UTC [47] LOG C-0x564763140e80: db1/szulcubzosgfjh@127.0.0.1:47362 login attempt: db=db1 user=szulcubzosgfjh tls=no
2022-06-20T14:32:36.197520+00:00 app[worker.1]: 2022-06-20 14:32:36.197 UTC [47] LOG S-0x564763147c20: db1/szulcubzosgfjh@18.235.4.83:5432 new connection to server (from 172.19.62.2:49206)
2022-06-20T14:32:36.221317+00:00 app[worker.1]: bin/start-pgbouncer: line 100:    47 Segmentation fault      "$@"
2022-06-20T14:32:36.221743+00:00 app[worker.1]: buildpack=pgbouncer at=exit process=pgbouncer
2022-06-20T14:32:36.222275+00:00 app[worker.1]: buildpack=pgbouncer at=pgbouncer-end
2022-06-20T14:32:36.259179+00:00 app[worker.1]: buildpack=pgbouncer at=kill-app pid=46
2022-06-20T14:32:36.260733+00:00 app[worker.1]: buildpack=pgbouncer at=wait-app pid=46
2022-06-20T14:32:36.264278+00:00 app[worker.1]: [2022-06-20 11:32:36][078e6e88-149e-47b9-859d-4fe3188a5f10] Processing: App\Jobs\Redirector\RecountNumberOfClicks
2022-06-20T14:32:36.264279+00:00 app[worker.1]: [2022-06-20 11:32:36][078e6e88-149e-47b9-859d-4fe3188a5f10] Failed:     App\Jobs\Redirector\RecountNumberOfClicks
2022-06-20T14:32:36.320972+00:00 app[worker.1]: buildpack=pgbouncer at=app-end
2022-06-20T14:32:36.321294+00:00 app[worker.1]: buildpack=pgbouncer at=kill-aux name=pgbouncer pid=45 signal=SIGINT
2022-06-20T14:32:36.321354+00:00 app[worker.1]: bin/start-pgbouncer: line 62: kill: (45) - No such process

But it only happens with one of our apps, others are running fine.