Pgbouncer issues Azure Postgres

[joemillerr]

🐛 Bug Report

Deploying pwpusher with default Azure Postgres DB produces the following error when occasionally when the share link is accessed. I have tried to disable prepared statements and other related pgbounce settings on the Azure DB side but it doesn't appear to make a difference.

ActiveRecord::StatementInvalid (PG::DuplicatePstatement: ERROR:  prepared statement "a1" already exists  

🔬 How To Reproduce

Relatively easy to repro if you refresh the share link page in quick succession.

Environment

Where are you running/using Password Pusher?

• [ ] pwpush.com
• [x] Docker Image
  • [x] pwpush
  • [ ] custom image
• [ ] Heroku
• [ ] Digital Ocean
• [x] Microsoft Azure
• [ ] Google Cloud
• [ ] AWS
• [ ] Source Code
• [ ] Other (please specify)

If applicable, what version of Password Pusher? v1.41.9

📈 Expected behavior

📎 Additional context

[github-actions[bot]]

Hello @joemillerr, thanks for contributing to the Password Pusher community! We will respond as soon as possible.

[pglombardo]

Hi @joemillerr - I haven't ever seen this error myself but a bit of googling shows that it can happen for a couple reasons - none of which have clean/easy answers. :-(

I plan on adding pgbouncer to pwpush.com soon so we'll see...

Can you correlate a Timeout or error in the logs before the prepared statement error?

Could you post the full stack trace?

[pglombardo]

Some links for investigation pickup:

https://stackoverflow.com/questions/64929756/heroku-broken-pg-connection-caused-the-disruption-of-our-rails-app https://github.com/rails/rails/pull/17607 https://github.com/rails/rails/issues/22408 https://github.com/zombocom/rack-timeout/blob/main/doc/risks.md https://github.com/rails/rails/pull/41356

[joemillerr]

Hey @pglombardo thanks for the reply. I've investigated a bit and myself and as far as some sort of temp fix perhaps increasing the rack timeout? I'm pretty unfamiliar with rack so it wasn't clear to me exactly how to do this or if this was even something that would help.

Here are some debug logs when the error repros:

2024-07-02T13:58:46.637049644Z I, [2024-07-02T13:58:46.636973 #44]  INFO -- : [5d84b0be-b8f7-9041-b7b9-bb0b8c3cbc2c] method=GET path=/en/p/lbdtdrkjrvab5g format=html controller=PasswordsController action=show status=200 allocations=4852 duration=16.33 view=2.84 db=6.42 ip=216.200.119.171 forwarded_for=216.200.119.171
2024-07-02T13:58:46.637479644Z D, [2024-07-02T13:58:46.637402 #44] DEBUG -- : source=rack-timeout id=5d84b0be-b8f7-9041-b7b9-bb0b8c3cbc2c timeout=15000ms service=18ms state=completed
2024-07-02T13:58:46.824593843Z D, [2024-07-02T13:58:46.824421 #40] DEBUG -- : source=rack-timeout id=bcb98d1c-f204-917d-8fc1-b80adb64f6e2 timeout=15000ms state=ready
2024-07-02T13:58:46.827472539Z D, [2024-07-02T13:58:46.827348 #40] DEBUG -- : source=rack-timeout id=bcb98d1c-f204-917d-8fc1-b80adb64f6e2 timeout=15000ms service=3ms state=active
2024-07-02T13:58:46.895156630Z I, [2024-07-02T13:58:46.895015 #40]  INFO -- : [bcb98d1c-f204-917d-8fc1-b80adb64f6e2] method=GET path=/en/p/lbdtdrkjrvab5g format=html controller=PasswordsController action=show status=500 allocations=3798 duration=69.25 view=0.00 db=27.02 ip=216.200.119.171 forwarded_for=216.200.119.171
2024-07-02T13:58:46.895797929Z E, [2024-07-02T13:58:46.895722 #40] ERROR -- : [bcb98d1c-f204-917d-8fc1-b80adb64f6e2]   
2024-07-02T13:58:46.895811429Z [bcb98d1c-f204-917d-8fc1-b80adb64f6e2] ActiveRecord::StatementInvalid (PG::DuplicatePstatement: ERROR:  prepared statement "a1" already exists
2024-07-02T13:58:46.895814529Z ):
2024-07-02T13:58:46.895817229Z [bcb98d1c-f204-917d-8fc1-b80adb64f6e2]   
2024-07-02T13:58:46.896282529Z D, [2024-07-02T13:58:46.896207 #40] DEBUG -- : source=rack-timeout id=bcb98d1c-f204-917d-8fc1-b80adb64f6e2 timeout=15000ms service=72ms state=completed
2024-07-02T13:58:47.018399533Z D, [2024-07-02T13:58:47.018276 #40] DEBUG -- : source=rack-timeout id=bcf0c296-1b16-9854-81bc-2745a9032629 timeout=15000ms state=ready
2024-07-02T13:58:47.020525729Z D, [2024-07-02T13:58:47.020369 #40] DEBUG -- : source=rack-timeout id=bcf0c296-1b16-9854-81bc-2745a9032629 timeout=15000ms service=2ms state=active
2024-07-02T13:58:47.022861826Z I, [2024-07-02T13:58:47.022760 #40]  INFO -- : [bcf0c296-1b16-9854-81bc-2745a9032629] method=GET path=/en/p/lbdtdrkjrvab5g format=html controller=PasswordsController action=show status=500 allocations=623 duration=3.14 view=0.00 db=0.00 ip=216.200.119.171 forwarded_for=216.200.119.171
2024-07-02T13:58:47.023200625Z E, [2024-07-02T13:58:47.023123 #40] ERROR -- : [bcf0c296-1b16-9854-81bc-2745a9032629]   
2024-07-02T13:58:47.023220325Z [bcf0c296-1b16-9854-81bc-2745a9032629] ActiveRecord::StatementInvalid (PG::DuplicatePstatement: ERROR:  prepared statement "a2" already exists
2024-07-02T13:58:47.023225625Z ):
2024-07-02T13:58:47.023229825Z [bcf0c296-1b16-9854-81bc-2745a9032629]   

Thanks!

[pglombardo]

You're right - this is the module that does the timeouts. It supports settings via environment variables.

So you should be able to set RACK_TIMEOUT_SERVICE_TIMEOUT to something much bigger (60 or 120 seconds). For example:

RACK_TIMEOUT_SERVICE_TIMEOUT=60

That should (hopefully) reduce the # of occurrences of the prepared statement errors. Give that a try and let me know the results.

[joemillerr]

I believe the timeout adjustment has helped. thank you @pglombardo !

[pglombardo]

I'll close this out @joemillerr but if it comes up again let me know!