Rails ActiveStorage variants writes to PG not working

Questions / Help
,
1

I am running an ordinary Rails app globally, following this blog post Run Ordinary Rails Apps Globally · Fly by @jsierles using the fly-ruby gem. “Normal” writes are working great, Fly-Replay is redirecting writes to the main database.

There is one exception: When I am accessing the website from a secondary (read-only) location and Rails ActiveStorage needs to create new variants of a picture (i.e. they’re not in the database yet), I am getting an error “PG::ReadOnlySqlTransaction” – but no redirection to the writable database is happening.

Has anyone experienced this before and can point me into the right direction?

2

So this would suggest that the middleware that captures this exception is not reached by ActiveStorage requests.We insert the middleware here naively, assuming it will be placed at the bottom of the middleware stack.

Are you sure fly-ruby is running correctly? You’ll see something in the logs as boot time if it’s not.

3

A few things I’d like to see:

Middleware

Could you run rake middleware and paste the contents of the output? That will help us rule out if there’s an issue with the middleware initializing properly.

Exception classes

I don’t think this is it, but let’s do it anyway to rule out the possibility. The middleware needs to have PG::ReadOnlySqlTransaction present to catch the database write exception and trigger a replay. That’s dynamically resolved at runtime at fly-ruby/configuration.rb at main · superfly/fly-ruby · GitHub, so maybe it’s not being picked up for whatever reason?

We can verify this if you paste the output of the following:

Fly.configuration.replayable_exception_classes

Knowing these two things will give us a better idea of where to look, thanks!

4

Error when I upload multiple images in ams (non-primary):


error.message="cannot retry/replay request because request body has been read past what we're willing to buffer" 2022-12-08T16:38:33Z proxy[472ed3b7] ams [error]request.method="POST" request.url="https://myapp.example/activities" request.id="01GKS9MKA4Y709B1GYHV8PB91S-ams" response.status=502

Error when I upload one small image in ams (non-primary):


2022-12-08T16:39:55Z app[472ed3b7] ams [info]I, [2022-12-08T16:39:55.319216 #535] INFO -- : [72daac8f-f339-4cb9-9ae6-6fd22cbfb2bb] Started GET "/rails/active_storage/representations/proxy/eyJfcmFpbHMiOnsibWVzc2FnZSI6IkJBaHBBbVlCIiwiZXhwIjpudWxsLCJwdXIiOiJibG9iX2lkIn19--662b36d4600839c60b4aa4cba33195344c8375d6/eyJfcmFpbHMiOnsibWVzc2FnZSI6IkJBaDdDRG9MWm05eWJXRjBTU0lJYW5CbkJqb0dSVlE2RTNKbGMybDZaVjkwYjE5bWFXeHNXd2RwQXNRQ2FRSlBBam9NWTI5dWRtVnlkRG9KZDJWaWNBPT0iLCJleHAiOm51bGwsInB1ciI6InZhcmlhdGlvbiJ9fQ==--e1bf0351bbf33ddad9f439d265111fc987603159/pk2.jpg" for 149.248.212.195 at 2022-12-08 16:39:55 +0000

2022-12-08T16:39:55Z app[472ed3b7] ams [info]I, [2022-12-08T16:39:55.322873 #535] INFO -- : [72daac8f-f339-4cb9-9ae6-6fd22cbfb2bb] Processing by ActiveStorage::Representations::ProxyController#show as JPEG

2022-12-08T16:39:55Z app[472ed3b7] ams [info]I, [2022-12-08T16:39:55.323114 #535] INFO -- : [72daac8f-f339-4cb9-9ae6-6fd22cbfb2bb] Parameters: {"signed_blob_id"=>"eyJfcmFpbHMiOnsibWVzc2FnZSI6IkJBaHBBbVlCIiwiZXhwIjpudWxsLCJwdXIiOiJibG9iX2lkIn19--662b36d4600839c60b4aa4cba33195344c8375d6", "variation_key"=>"[FILTERED]", "filename"=>"pk2"}

2022-12-08T16:39:55Z app[472ed3b7] ams [info]D, [2022-12-08T16:39:55.327905 #535] DEBUG -- : [72daac8f-f339-4cb9-9ae6-6fd22cbfb2bb] ActiveStorage::Blob Load (1.0ms) SELECT "active_storage_blobs".* FROM "active_storage_blobs" WHERE "active_storage_blobs"."id" = $1 LIMIT $2 [["id", 358], ["LIMIT", 1]]

2022-12-08T16:39:55Z app[472ed3b7] ams [info]D, [2022-12-08T16:39:55.337688 #535] DEBUG -- : [72daac8f-f339-4cb9-9ae6-6fd22cbfb2bb] ActiveStorage::VariantRecord Load (0.8ms) SELECT "active_storage_variant_records".* FROM "active_storage_variant_records" WHERE "active_storage_variant_records"."blob_id" = $1 AND "active_storage_variant_records"."variation_digest" = $2 LIMIT $3 [["blob_id", 358], ["variation_digest", "5xLh1cRAvigeytt41nCwfCjKVNc="], ["LIMIT", 1]]

2022-12-08T16:39:57Z app[472ed3b7] ams [info]D, [2022-12-08T16:39:57.413467 #535] DEBUG -- : [72daac8f-f339-4cb9-9ae6-6fd22cbfb2bb] TRANSACTION (1.3ms) BEGIN

2022-12-08T16:39:57Z app[472ed3b7] ams [info]F, [2022-12-08T16:39:57.439851 #535] FATAL -- : [72daac8f-f339-4cb9-9ae6-6fd22cbfb2bb]

2022-12-08T16:39:57Z app[472ed3b7] ams [info]):

2022-12-08T16:39:57Z app[472ed3b7] ams [info][72daac8f-f339-4cb9-9ae6-6fd22cbfb2bb] activesupport (7.0.4) lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `block in synchronize'

2022-12-08T16:39:57Z app[472ed3b7] ams [info][72daac8f-f339-4cb9-9ae6-6fd22cbfb2bb] activesupport (7.0.4) lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `synchronize'

2022-12-08T16:39:57Z app[472ed3b7] ams [info][72daac8f-f339-4cb9-9ae6-6fd22cbfb2bb] activerecord (7.0.4) lib/active_record/connection_adapters/abstract/database_statements.rb:132:in `exec_insert'

2022-12-08T16:39:57Z app[472ed3b7] ams [info][72daac8f-f339-4cb9-9ae6-6fd22cbfb2bb] activerecord (7.0.4) lib/active_record/persistence.rb:496:in `_insert_record'

2022-12-08T16:39:57Z app[472ed3b7] ams [info][72daac8f-f339-4cb9-9ae6-6fd22cbfb2bb] activerecord (7.0.4) lib/active_record/persistence.rb:1096:in `_create_record'

2022-12-08T16:39:57Z app[472ed3b7] ams [info][72daac8f-f339-4cb9-9ae6-6fd22cbfb2bb] activerecord (7.0.4) lib/active_record/attribute_methods/dirty.rb:222:in `_create_record'

2022-12-08T16:39:57Z app[472ed3b7] ams [info][72daac8f-f339-4cb9-9ae6-6fd22cbfb2bb] activesupport (7.0.4) lib/active_support/callbacks.rb:929:in `_run_create_callbacks'

2022-12-08T16:39:57Z app[472ed3b7] ams [info][72daac8f-f339-4cb9-9ae6-6fd22cbfb2bb] activerecord (7.0.4) lib/active_record/persistence.rb:1067:in `create_or_update'

2022-12-08T16:39:57Z app[472ed3b7] ams [info][72daac8f-f339-4cb9-9ae6-6fd22cbfb2bb] activesupport (7.0.4) lib/active_support/callbacks.rb:929:in `_run_save_callbacks'

2022-12-08T16:39:57Z app[472ed3b7] ams [info][72daac8f-f339-4cb9-9ae6-6fd22cbfb2bb] activerecord (7.0.4) lib/active_record/persistence.rb:648:in `save!'

2022-12-08T16:39:57Z app[472ed3b7] ams [info][72daac8f-f339-4cb9-9ae6-6fd22cbfb2bb] activerecord (7.0.4) lib/active_record/connection_adapters/abstract/database_statements.rb:314:in `transaction'

2022-12-08T16:39:57Z app[472ed3b7] ams [info][72daac8f-f339-4cb9-9ae6-6fd22cbfb2bb] activerecord (7.0.4) lib/active_record/associations/has_many_association.rb:58:in `insert_record'

2022-12-08T16:39:57Z app[472ed3b7] ams [info][72daac8f-f339-4cb9-9ae6-6fd22cbfb2bb] activerecord (7.0.4) lib/active_record/associations/collection_association.rb:351:in `block in _create_record'

2022-12-08T16:39:57Z app[472ed3b7] ams [info][72daac8f-f339-4cb9-9ae6-6fd22cbfb2bb] activerecord (7.0.4) lib/active_record/associations/collection_proxy.rb:364:in `create!'

2022-12-08T16:39:57Z app[472ed3b7] ams [info][72daac8f-f339-4cb9-9ae6-6fd22cbfb2bb] activesupport (7.0.4) lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `handle_interrupt'

2022-12-08T16:39:57Z app[472ed3b7] ams [info][72daac8f-f339-4cb9-9ae6-6fd22cbfb2bb] activerecord (7.0.4) lib/active_record/connection_adapters/abstract/transaction.rb:317:in `within_new_transaction'

2022-12-08T16:39:57Z app[472ed3b7] ams [info][72daac8f-f339-4cb9-9ae6-6fd22cbfb2bb] activerecord (7.0.4) lib/active_record/transactions.rb:209:in `transaction'

2022-12-08T16:39:57Z app[472ed3b7] ams [info][72daac8f-f339-4cb9-9ae6-6fd22cbfb2bb] activerecord (7.0.4) lib/active_record/relation/delegation.rb:108:in `method_missing'

2022-12-08T16:39:57Z app[472ed3b7] ams [info][72daac8f-f339-4cb9-9ae6-6fd22cbfb2bb] activerecord (7.0.4) lib/active_record/connection_handling.rb:156:in `connected_to'

2022-12-08T16:39:57Z app[472ed3b7] ams [info][72daac8f-f339-4cb9-9ae6-6fd22cbfb2bb] activestorage (7.0.4) app/models/active_storage/variation.rb:55:in `transform'

2022-12-08T16:39:57Z app[472ed3b7] ams [info]e6-6fd22cbfb2bb] activesupport (7.0.4)

2022-12-08T16:39:57Z app[472ed3b7] ams [info][72daac8f-f339-4cb9-9ae6-6fd22cbfb2bb] activesupport (7.0.4) lib/active_support/callbacks.rb:116:in `block in run_callbacks'

2022-12-08T16:39:57Z app[472ed3b7] ams [info][72daac8f-f339-4cb9-9ae6-6fd22cbfb2bb] activesupport (7.0.4) lib/active_support/callbacks.rb:138:in `run_callbacks'

2022-12-08T16:39:57Z app[472ed3b7] ams [info][72daac8f-f339-4cb9-9ae6-6fd22cbfb2bb] activesupport (7.0.4) lib/active_support/notifications.rb:206:in `block in instrument'

2022-12-08T16:39:57Z app[472ed3b7] ams [info][72daac8f-f339-4cb9-9ae6-6fd22cbfb2bb] activesupport (7.0.4) lib/active_support/notifications.rb:206:in `instrument'

2022-12-08T16:39:57Z app[472ed3b7] ams [info][72daac8f-f339-4cb9-9ae6-6fd22cbfb2bb] actionpack (7.0.4) lib/abstract_controller/base.rb:151:in `process'

2022-12-08T16:39:57Z app[472ed3b7] ams [info][72daac8f-f339-4cb9-9ae6-6fd22cbfb2bb] activesupport (7.0.4) lib/active_support/concurrency/share_lock.rb:162:in `sharing'

2022-12-08T16:39:57Z app[472ed3b7] ams [info][72daac8f-f339-4cb9-9ae6-6fd22cbfb2bb] activesupport (7.0.4)

2022-12-08T16:39:57Z app[472ed3b7] ams [info]lib/active_support/dependencies/interlock.rb:37:in `running'

2022-12-08T16:39:57Z app[472ed3b7] ams [info][72daac8f-f339-4cb9-9ae6-6fd22cbfb2bb] actionpack (7.0.4) lib/action_controller/metal/live.rb:258:in `block in process'

2022-12-08T16:39:57Z app[472ed3b7] ams [info][72daac8f-f339-4cb9-9ae6-6fd22cbfb2bb] actionpack (7.0.4) lib/action_controller/metal/live.rb:344:in `block in new_controller_thread'

Error when I download the page created in the last step in ams (non-primary):


2022-12-08T16:44:43Z app[472ed3b7] ams [info]I, [2022-12-08T16:44:43.384672 #535] INFO -- : [d20801b2-3670-4a8b-b16e-b8093c864823] Parameters: {"id"=>"2022-12-08_test-for-geo-dist-pg"}

2022-12-08T16:44:43Z app[472ed3b7] ams [info]D, [2022-12-08T16:44:43.389638 #535] DEBUG -- : [d20801b2-3670-4a8b-b16e-b8093c864823] Activity Load (1.2ms) SELECT "activities".* FROM "activities" WHERE (start > '2022-11-08 16:44:43.385255') AND "activities"."slug" = $1 ORDER BY "activities"."start" ASC LIMIT $2 [["slug", "2022-12-08_test-for-geo-dist-pg"], ["LIMIT", 1]]

2022-12-08T16:44:43Z app[472ed3b7] ams [info]D, [2022-12-08T16:44:43.403052 #535] DEBUG -- : [d20801b2-3670-4a8b-b16e-b8093c864823] ActiveStorage::Attachment Load (0.8ms) SELECT "active_storage_attachments".* FROM "active_storage_attachments" WHERE "active_storage_attachments"."record_type" = $1 AND "active_storage_attachments"."name" = $2 AND "active_storage_attachments"."record_id" = $3 [["record_type", "Activity"], ["name", "pictures"], ["record_id", 18]]

2022-12-08T16:44:43Z app[472ed3b7] ams [info]D, [2022-12-08T16:44:43.417848 #535] DEBUG -- : [d20801b2-3670-4a8b-b16e-b8093c864823] Rendering layout layouts/application.html.haml

2022-12-08T16:44:43Z app[472ed3b7] ams [info]D, [2022-12-08T16:44:43.479268 #535] DEBUG -- : [d20801b2-3670-4a8b-b16e-b8093c864823] User Count (1.6ms) SELECT COUNT(*) FROM "users" INNER JOIN "bookings" ON "users"."id" = "bookings"."user_id" WHERE "bookings"."activity_id" = $1 [["activity_id", 18]]

2022-12-08T16:44:43Z app[472ed3b7] ams [info]I, [2022-12-08T16:44:43.491701 #535] INFO -- : [d20801b2-3670-4a8b-b16e-b8093c864823] Rendered activities/show.html.haml within layouts/application (Duration: 73.5ms | Allocations: 37794)

2022-12-08T16:44:43Z app[472ed3b7] ams [info]D, [2022-12-08T16:44:43.499210 #535] DEBUG -- : [d20801b2-3670-4a8b-b16e-b8093c864823] Rendered collection of application/_menu.html.haml [3 times] (Duration: 3.8ms | Allocations: 3261)

2022-12-08T16:44:43Z app[472ed3b7] ams [info]D, [2022-12-08T16:44:43.518230 #535] DEBUG -- : [d20801b2-3670-4a8b-b16e-b8093c864823] ActiveStorage::Blob Load (0.8ms) SELECT "active_storage_blobs".* FROM "active_storage_blobs" WHERE "active_storage_blobs"."id" = $1 LIMIT $2 [["id", 64], ["LIMIT", 1]]

2022-12-08T16:44:43Z app[472ed3b7] ams [info]D, [2022-12-08T16:44:43.521306 #535] DEBUG -- : [d20801b2-3670-4a8b-b16e-b8093c864823] Rendered collection of application/_mobilemenu.html.haml [3 times] (Duration: 0.6ms | Allocations: 254)

2022-12-08T16:44:43Z app[472ed3b7] ams [info]D, [2022-12-08T16:44:43.522573 #535] DEBUG -- : [d20801b2-3670-4a8b-b16e-b8093c864823] Rendered application/_header.html.haml (Duration: 29.0ms | Allocations: 14806)

2022-12-08T16:44:43Z app[472ed3b7] ams [info]D, [2022-12-08T16:44:43.528611 #535] DEBUG -- : [d20801b2-3670-4a8b-b16e-b8093c864823] Rendered application/_footer.html.haml (Duration: 5.6ms | Allocations: 2471)

2022-12-08T16:44:43Z app[472ed3b7] ams [info]I, [2022-12-08T16:44:43.528956 #535] INFO -- : [d20801b2-3670-4a8b-b16e-b8093c864823] Rendered layout layouts/application.html.haml (Duration: 111.0ms | Allocations: 56063)

2022-12-08T16:44:43Z app[472ed3b7] ams [info]I, [2022-12-08T16:44:43.529635 #535] INFO -- : [d20801b2-3670-4a8b-b16e-b8093c864823] Completed 200 OK in 145ms (Views: 101.6ms | ActiveRecord: 17.6ms | Allocations: 62929)

2022-12-08T16:44:44Z app[472ed3b7] ams [info]I, [2022-12-08T16:44:44.954879 #535] INFO -- : [74a688b9-47ba-49ac-a7e0-84c0b89b701a] Started GET "/rails/active_storage/representations/proxy/eyJfcmFpbHMiOnsibWVzc2FnZSI6IkJBaHBBbVlCIiwiZXhwIjpudWxsLCJwdXIiOiJibG9iX2lkIn19--662b36d4600839c60b4aa4cba33195344c8375d6/eyJfcmFpbHMiOnsibWVzc2FnZSI6IkJBaDdDRG9MWm05eWJXRjBTU0lJYW5CbkJqb0dSVlE2RTNKbGMybDZaVjkwYjE5bWFXeHNXd2RwQXNRQ2FRSlBBam9NWTI5dWRtVnlkRG9KZDJWaWNBPT0iLCJleHAiOm51bGwsInB1ciI6InZhcmlhdGlvbiJ9fQ==--e1bf0351bbf33ddad9f439d265111fc987603159/pk2.jpg" for 149.248.212.195 at 2022-12-08 16:44:44 +0000

2022-12-08T16:44:44Z app[472ed3b7] ams [info]I, [2022-12-08T16:44:44.957474 #535] INFO -- : [74a688b9-47ba-49ac-a7e0-84c0b89b701a] Parameters: {"signed_blob_id"=>"eyJfcmFpbHMiOnsibWVzc2FnZSI6IkJBaHBBbVlCIiwiZXhwIjpudWxsLCJwdXIiOiJibG9iX2lkIn19--662b36d4600839c60b4aa4cba33195344c8375d6", "variation_key"=>"[FILTERED]", "filename"=>"pk2"}

2022-12-08T16:44:44Z app[472ed3b7] ams [info]D, [2022-12-08T16:44:44.965539 #535] DEBUG -- : [74a688b9-47ba-49ac-a7e0-84c0b89b701a] ActiveStorage::Blob Load (3.7ms) SELECT "active_storage_blobs".* FROM "active_storage_blobs" WHERE "active_storage_blobs"."id" = $1 LIMIT $2 [["id", 358], ["LIMIT", 1]]

2022-12-08T16:44:44Z app[472ed3b7] ams [info]D, [2022-12-08T16:44:44.974339 #535] DEBUG -- : [74a688b9-47ba-49ac-a7e0-84c0b89b701a] ActiveStorage::VariantRecord Load (2.1ms) SELECT "active_storage_variant_records".* FROM "active_storage_variant_records" WHERE "active_storage_variant_records"."blob_id" = $1 AND "active_storage_variant_records"."variation_digest" = $2 LIMIT $3 [["blob_id", 358], ["variation_digest", "5xLh1cRAvigeytt41nCwfCjKVNc="], ["LIMIT", 1]]

2022-12-08T16:44:46Z app[472ed3b7] ams [info]D, [2022-12-08T16:44:46.809685 #535] DEBUG -- : [74a688b9-47ba-49ac-a7e0-84c0b89b701a] TRANSACTION (1.0ms) BEGIN

2022-12-08T16:44:46Z app[472ed3b7] ams [info][74a688b9-47ba-49ac-a7e0-84c0b89b701a]

2022-12-08T16:44:46Z app[472ed3b7] ams [info][74a688b9-47ba-49ac-a7e0-84c0b89b701a] activerecord (7.0.4) lib/active_record/connection_adapters/postgresql_adapter.rb:767:in `block in exec_no_cache'

2022-12-08T16:44:46Z app[472ed3b7] ams [info][74a688b9-47ba-49ac-a7e0-84c0b89b701a] activerecord (7.0.4) lib/active_record/connection_adapters/abstract_adapter.rb:765:in `block in log'

2022-12-08T16:44:46Z app[472ed3b7] ams [info][74a688b9-47ba-49ac-a7e0-84c0b89b701a] scout_apm (5.3.2) lib/scout_apm/instruments/active_record.rb:257:in `log'

2022-12-08T16:44:46Z app[472ed3b7] ams [info][74a688b9-47ba-49ac-a7e0-84c0b89b701a] activerecord (7.0.4) lib/active_record/connection_adapters/abstract/database_statements.rb:132:in `exec_insert'

2022-12-08T16:44:46Z app[472ed3b7] ams [info][74a688b9-47ba-49ac-a7e0-84c0b89b701a] activerecord (7.0.4) lib/active_record/connection_adapters/abstract/database_statements.rb:167:in `insert'

2022-12-08T16:44:46Z app[472ed3b7] ams [info][74a688b9-47ba-49ac-a7e0-84c0b89b701a] activerecord (7.0.4) lib/active_record/connection_adapters/abstract/query_cache.rb:22:in `insert'

2022-12-08T16:44:46Z app[472ed3b7] ams [info][74a688b9-47ba-49ac-a7e0-84c0b89b701a] activerecord (7.0.4) lib/active_record/persistence.rb:496:in `_insert_record'

2022-12-08T16:44:46Z app[472ed3b7] ams [info]89b701a] activerecord (7.0.4) lib/active_record/associations/collection_proxy.rb:364:in `create!'

[74a688b9-47ba-49

2022-12-08T16:44:46Z app[472ed3b7] ams [info][74a688b9-47ba-49ac-a7e0-84c0b89b701a] activerecord (7.0.4) lib/active_record/callbacks.rb:461:in `_create_record'

2022-12-08T16:44:46Z app[472ed3b7] ams [info][74a688b9-47ba-49ac-a7e0-84c0b89b701a] activerecord (7.0.4) lib/active_record/callbacks.rb:457:in `block in create_or_update'

2022-12-08T16:44:46Z app[472ed3b7] ams [info][74a688b9-47ba-49ac-a7e0-84c0b89b701a] activerecord (7.0.4) lib/active_record/timestamp.rb:126:in `create_or_update'

2022-12-08T16:44:46Z app[472ed3b7] ams [info][74a688b9-47ba-49ac-a7e0-84c0b89b701a] activerecord (7.0.4) lib/active_record/associations/collection_association.rb:365:in `insert_record'

2022-12-08T16:44:46Z app[472ed3b7] ams [info][74a688b9-47ba-49ac-a7e0-84c0b89b701a] activerecord (7.0.4) lib/active_record/associations/collection_association.rb:351:in `block in _create_record'

2022-12-08T16:44:46Z app[472ed3b7] ams [info][74a688b9-47ba-49ac-a7e0-84c0b89b701a] activerecord (7.0.4) lib/active_record/associations/collection_association.rb:308:in `transaction'

2022-12-08T16:44:46Z app[472ed3b7] ams [info][74a688b9-47ba-49ac-a7e0-84c0b89b701a] activerecord (7.0.4) lib/active_record/associations/collection_proxy.rb:364:in `create!'

2022-12-08T16:44:46Z app[472ed3b7] ams [info]c-a7e0-84c0b89b701a] activerecord (7.0.4) lib/active_record/relation.rb:219:in `block in create_or_find_by!'

2022-12-08T16:44:46Z app[472ed3b7] ams [info][74a688b9-47ba-49ac-a7e0-84c0b89b701a] activerecord (7.0.4) lib/active_record/transactions.rb:209:in `transaction'

2022-12-08T16:44:46Z app[472ed3b7] ams [info][74a688b9-47ba-49ac-a7e0-84c0b89b701a] activerecord (7.0.4) lib/active_record/relation.rb:428:in `scoping'

2022-12-08T16:44:46Z app[472ed3b7] ams [info][74a688b9-47ba-49ac-a7e0-84c0b89b701a] activerecord (7.0.4) lib/active_record/relation.rb:219:in `create_or_find_by!'

2022-12-08T16:44:46Z app[472ed3b7] ams [info][74a688b9-47ba-49ac-a7e0-84c0b89b701a] activerecord (7.0.4) lib/active_record/connection_handling.rb:156:in `connected_to'

2022-12-08T16:44:46Z app[472ed3b7] ams [info][74a688b9-47ba-49ac-a7e0-84c0b89b701a] activestorage (7.0.4) app/models/active_storage/variant_with_record.rb:36:in `block (2 levels) in transform_blob'

2022-12-08T16:44:46Z app[472ed3b7] ams [info][74a688b9-47ba-49ac-a7e0-84c0b89b701a] activestorage (7.0.4) app/models/active_storage/variant_with_record.rb:35:in `block in transform_blob'

2022-12-08T16:44:46Z app[472ed3b7] ams [info][74a688b9-47ba-49ac-a7e0-84c0b89b701a] activestorage (7.0.4) lib/active_storage/downloader.rb:15:in `block in open'

2022-12-08T16:44:46Z app[472ed3b7] ams [info][74a688b9-47ba-49ac-a7e0-84c0b89b701a] activestorage (7.0.4) lib/active_storage/downloader.rb:24:in `open_tempfile'

2022-12-08T16:44:46Z app[472ed3b7] ams [info][74a688b9-47ba-49ac-a7e0-84c0b89b701a] activestorage (7.0.4) lib/active_storage/service.rb:90:in `open'

2022-12-08T16:44:46Z app[472ed3b7] ams [info][74a688b9-47ba-49ac-a7e0-84c0b89b701a] actionpack (7.0.4) lib/abstract_controller/callbacks.rb:34:in `block (2 levels) in <module:Callbacks>'

2022-12-08T16:44:46Z app[472ed3b7] ams [info][74a688b9-47ba-49ac-a7e0-84c0b89b701a] activesupport (7.0.4) lib/active_support/callbacks.rb:200:in `block in halting'

2022-12-08T16:44:46Z app[472ed3b7] ams [info][74a688b9-47ba-49ac-a7e0-84c0b89b701a] activesupport (7.0.4) lib/active_support/callbacks.rb:116:in `block in run_callbacks'

2022-12-08T16:44:46Z app[472ed3b7] ams [info][74a688b9-47ba-49ac-a7e0-84c0b89b701a] actiontext (7.0.4) lib/action_text/engine.rb:69:in `block (4 levels) in <class:Engine>'

2022-12-08T16:44:46Z app[472ed3b7] ams [info][74a688b9-47ba-49ac-a7e0-84c0b89b701a] activesupport (7.0.4) lib/active_support/callbacks.rb:127:in `instance_exec'

2022-12-08T16:44:46Z app[472ed3b7] ams [info][74a688b9-47ba-49ac-a7e0-84c0b89b701a] actionpack (7.0.4) lib/action_controller/metal/instrumentation.rb:66:in `process_action'

2022-12-08T16:44:46Z app[472ed3b7] ams [info][74a688b9-47ba-49ac-a7e0-84c0b89b701a] actionpack (7.0.4) lib/action_controller/metal/params_wrapper.rb:259:in `process_action'

2022-12-08T16:44:46Z app[472ed3b7] ams [info][74a688b9-47ba-49ac-a7e0-84c0b89b701a] activerecord (7.0.4) lib/active_record/railties/controller_runtime.rb:27:in `process_action'

2022-12-08T16:44:46Z app[472ed3b7] ams [info][74a688b9-47ba-49ac-a7e0-84c0b89b701a] actionview (7.0.4) lib/action_view/rendering.rb:39:in `process'

2022-12-08T16:44:46Z app[472ed3b7] ams [info][74a688b9-47ba-49ac-a7e0-84c0b89b701a] actionpack (7.0.4) lib/action_controller/metal/live.rb:267:in `block (2 levels) in process'

2022-12-08T16:44:46Z app[472ed3b7] ams [info][74a688b9-47ba-49ac-a7e0-84c0b89b701a] activesupport (7.0.4) lib/active_support/concurrency/share_lock.rb:162:in `sharing'

2022-12-08T16:44:46Z app[472ed3b7] ams [info][74a688b9-47ba-49ac-a7e0-84c0b89b701a] activesupport (7.0.4) lib/active_support/dependencies/interlock.rb:37:in `running'

2022-12-08T16:44:46Z app[472ed3b7] ams [info][74a688b9-47ba-49ac-a7e0-8

2022-12-08T16:44:46Z app[472ed3b7] ams [info]c0b89b701a] actionpack (7.0.4) lib/action_controller/metal/live.rb:258:in `block in process'

2022-12-08T16:44:46Z app[472ed3b7] ams [info][74a688b9-47ba-49ac-a7e0-84c0b89b701a] actionpack (7.0.4) lib/action_controller/metal/live.rb:344:in `block in new_controller_thread'

No error when I download said page from sin:


2022-12-08T16:48:32Z app[af2b3aed] sin [info]I, [2022-12-08T16:48:32.118570 #536] INFO -- : [d2c05028-f91f-4aaf-ad32-b012abcfab72] Started GET "/activities/2022-12-08_test-for-geo-dist-pg" for 149.248.212.195 at 2022-12-08 16:48:32 +0000

2022-12-08T16:48:32Z app[af2b3aed] sin [info]I, [2022-12-08T16:48:32.120708 #536] INFO -- : [d2c05028-f91f-4aaf-ad32-b012abcfab72] Processing by ActivitiesController#show as HTML

2022-12-08T16:48:32Z app[af2b3aed] sin [info]I, [2022-12-08T16:48:32.120779 #536] INFO -- : [d2c05028-f91f-4aaf-ad32-b012abcfab72] Parameters: {"id"=>"2022-12-08_test-for-geo-dist-pg"}

2022-12-08T16:48:32Z app[af2b3aed] sin [info]D, [2022-12-08T16:48:32.155852 #536] DEBUG -- : [d2c05028-f91f-4aaf-ad32-b012abcfab72] Category Load (0.8ms) SELECT "categories".* FROM "categories" WHERE "categories"."id" = $1 [["id", 5]]

2022-12-08T16:48:32Z app[af2b3aed] sin [info]D, [2022-12-08T16:48:32.260264 #536] DEBUG -- : [d2c05028-f91f-4aaf-ad32-b012abcfab72] ActiveStorage::Attachment Load (0.8ms) SELECT "active_storage_attachments".* FROM "active_storage_attachments" WHERE "active_storage_attachments"."record_id" = $1 AND "active_storage_attachments"."record_type" = $2 AND "active_storage_attachments"."name" = $3 LIMIT $4 [["record_id", 56], ["record_type", "User"], ["name", "profile_image"], ["LIMIT", 1]]

2022-12-08T16:48:32Z app[af2b3aed] sin [info]D, [2022-12-08T16:48:32.280636 #536] DEBUG -- : [d2c05028-f91f-4aaf-ad32-b012abcfab72] Rendered application/_favicon.html.haml (Duration: 0.1ms | Allocations: 109)

2022-12-08T16:48:32Z app[af2b3aed] sin [info]D, [2022-12-08T16:48:32.286731 #536] DEBUG -- : [d2c05028-f91f-4aaf-ad32-b012abcfab72] Rendered application/_searchbox.html.haml (Duration: 0.8ms | Allocations: 978)

2022-12-08T16:48:32Z app[af2b3aed] sin [info]D, [2022-12-08T16:48:32.307169 #536] DEBUG -- : [d2c05028-f91f-4aaf-ad32-b012abcfab72] Rendered application/_footer.html.haml (Duration: 3.1ms | Allocations: 2497)

2022-12-08T16:48:32Z app[af2b3aed] sin [info]I, [2022-12-08T16:48:32.307331 #536] INFO -- : [d2c05028-f91f-4aaf-ad32-b012abcfab72] Rendered layout layouts/application.html.haml (Duration: 124.0ms | Allocations: 95637)

2022-12-08T16:48:33Z app[af2b3aed] sin [info]I, [2022-12-08T16:48:33.025595 #536] INFO -- : [cf9060a6-c7a1-41a0-94aa-5952ede94452] Parameters: {"signed_blob_id"=>"eyJfcmFpbHMiOnsibWVzc2FnZSI6IkJBaHBBbVlCIiwiZXhwIjpudWxsLCJwdXIiOiJibG9iX2lkIn19--662b36d4600839c60b4aa4cba33195344c8375d6", "variation_key"=>"[FILTERED]", "filename"=>"pk2"}

2022-12-08T16:48:33Z app[af2b3aed] sin [info]D, [2022-12-08T16:48:33.036630 #536] DEBUG -- : [cf9060a6-c7a1-41a0-94aa-5952ede94452] ActiveStorage::VariantRecord Load (1.0ms) SELECT "active_storage_variant_records".* FROM "active_storage_variant_records" WHERE "active_storage_variant_records"."blob_id" = $1 AND "active_storage_variant_records"."variation_digest" = $2 LIMIT $3 [["blob_id", 358], ["variation_digest", "5xLh1cRAvigeytt41nCwfCjKVNc="], ["LIMIT", 1]]

2022-12-08T16:48:33Z app[af2b3aed] sin [info]I, [2022-12-08T16:48:33.278188 #536] INFO -- : [cf9060a6-c7a1-41a0-94aa-5952ede94452] S3 Storage (240.4ms) Downloaded file from key: 6n8he8zxxhgdhip2yat8o1d3j5n4

2022-12-08T16:48:33Z app[af2b3aed] sin [info]D, [2022-12-08T16:48:33.409504 #536] DEBUG -- : [cf9060a6-c7a1-41a0-94aa-5952ede94452] TRANSACTION (1.2ms) BEGIN

2022-12-08T16:48:33Z app[af2b3aed] sin [info]D, [2022-12-08T16:48:33.424979 #536] DEBUG -- : [cf9060a6-c7a1-41a0-94aa-5952ede94452] ActiveStorage::VariantRecord Create (8.0ms) INSERT INTO "active_storage_variant_records" ("blob_id", "variation_digest") VALUES ($1, $2) RETURNING "id" [["blob_id", 358], ["variation_digest", "5xLh1cRAvigeytt41nCwfCjKVNc="]]

2022-12-08T16:48:33Z app[af2b3aed] sin [info]D, [2022-12-08T16:48:33.429723 #536] DEBUG -- : [cf9060a6-c7a1-41a0-94aa-5952ede94452] ActiveStorage::Blob Load (1.0ms) SELECT "active_storage_blobs".* FROM "active_storage_blobs" INNER JOIN "active_storage_attachments" ON "active_storage_blobs"."id" = "active_storage_attachments"."blob_id" WHERE "active_storage_attachments"."record_id" = $1 AND "active_storage_attachments"."record_type" = $2 AND "active_storage_attachments"."name" = $3 LIMIT $4 [["record_id", 160], ["record_type", "ActiveStorage::VariantRecord"], ["name", "image"], ["LIMIT", 1]]

2022-12-08T16:48:33Z app[af2b3aed] sin [info]D, [2022-12-08T16:48:33.432168 #536] DEBUG -- : [cf9060a6-c7a1-41a0-94aa-5952ede94452] ActiveStorage::Attachment Load (0.9ms) SELECT "active_storage_attachments".* FROM "active_storage_attachments" WHERE "active_storage_attachments"."record_id" = $1 AND "active_storage_attachments"."record_type" = $2 AND "active_storage_attachments"."name" = $3 LIMIT $4 [["record_id", 160], ["record_type", "ActiveStorage::VariantRecord"], ["name", "image"], ["LIMIT", 1]]

2022-12-08T16:48:33Z app[af2b3aed] sin [info]D, [2022-12-08T16:48:33.436260 #536] DEBUG -- : [cf9060a6-c7a1-41a0-94aa-5952ede94452] ActiveStorage::Blob Create (2.0ms) INSERT INTO "active_storage_blobs" ("key", "filename", "content_type", "metadata", "service_name", "byte_size", "checksum", "created_at") VALUES ($1, $2, $3, $4, $5, $6, $7, $8) RETURNING "id" [["key", "soliqsb1tabh5wmunz8cj8tz2w4r"], ["filename", "pk2.jpg"], ["content_type", "image/webp"], ["metadata", "{\"identified\":true}"], ["service_name", "amazon"], ["byte_size", 15174], ["checksum", "xUkCo7fV/tEQNobus9uksw=="], ["created_at", "2022-12-08 16:48:33.433127"]]

2022-12-08T16:48:33Z app[af2b3aed] sin [info]D, [2022-12-08T16:48:33.439816 #536] DEBUG -- : [cf9060a6-c7a1-41a0-94aa-5952ede94452] ActiveStorage::Attachment Create (2.4ms) INSERT INTO "active_storage_attachments" ("name", "record_type", "record_id", "blob_id", "created_at") VALUES ($1, $2, $3, $4, $5) RETURNING "id" [["name", "image"], ["record_type", "ActiveStorage::VariantRecord"], ["record_id", 160], ["blob_id", 359], ["created_at", "2022-12-08 16:48:33.436789"]]

2022-12-08T16:48:33Z app[af2b3aed] sin [info]D, [2022-12-08T16:48:33.442722 #536] DEBUG -- : [cf9060a6-c7a1-41a0-94aa-5952ede94452] TRANSACTION (1.4ms) COMMIT

2022-12-08T16:48:33Z app[af2b3aed] sin [info]I, [2022-12-08T16:48:33.498096 #536] INFO -- : [cf9060a6-c7a1-41a0-94aa-5952ede94452] S3 Storage (54.8ms) Uploaded file to key: soliqsb1tabh5wmunz8cj8tz2w4r (checksum: xUkCo7fV/tEQNobus9uksw==)

2022-12-08T16:48:33Z app[af2b3aed] sin [info]I, [2022-12-08T16:48:33.499817 #536] INFO -- : [cf9060a6-c7a1-41a0-94aa-5952ede94452] [ActiveJob] Enqueued ActiveStorage::AnalyzeJob (Job ID: 7941745a-b4a0-468a-80d5-68ba8717d254) to Async(default) with arguments: #<GlobalID:0x00007f5745cff848 @uri=#<URI::GID gid://myapp/ActiveStorage::Blob/359>>

2022-12-08T16:48:33Z app[af2b3aed] sin [info]D, [2022-12-08T16:48:33.539204 #536] DEBUG -- : [ActiveJob] [ActiveStorage::AnalyzeJob] [7941745a-b4a0-468a-80d5-68ba8717d254] ActiveStorage::Blob Load (1.8ms) SELECT "active_storage_blobs".* FROM "active_storage_blobs" WHERE "active_storage_blobs"."id" = $1 LIMIT $2 [["id", 359], ["LIMIT", 1]]

2022-12-08T16:48:33Z app[af2b3aed] sin [info]I, [2022-12-08T16:48:33.540272 #536] INFO -- : [ActiveJob] [ActiveStorage::AnalyzeJob] [7941745a-b4a0-468a-80d5-68ba8717d254] Performing ActiveStorage::AnalyzeJob (Job ID: 7941745a-b4a0-468a-80d5-68ba8717d254) from Async(default) enqueued at 2022-12-08T16:48:33Z with arguments: #<GlobalID:0x00007f5745cc5418 @uri=#<URI::GID gid://myapp/ActiveStorage::Blob/359>>

2022-12-08T16:48:33Z app[af2b3aed] sin [info]I, [2022-12-08T16:48:33.551233 #536] INFO -- : [cf9060a6-c7a1-41a0-94aa-5952ede94452] S3 Storage (48.1ms) Downloaded file from key: soliqsb1tabh5wmunz8cj8tz2w4r

2022-12-08T16:48:33Z app[af2b3aed] sin [info]I, [2022-12-08T16:48:33.553087 #536] INFO -- : Completed 200 OK in 527ms (ActiveRecord: 23.0ms | Allocations: 127567)

2022-12-08T16:48:33Z app[af2b3aed] sin [info]I, [2022-12-08T16:48:33.614456 #536] INFO -- : [ActiveJob] [ActiveStorage::AnalyzeJob] [7941745a-b4a0-468a-80d5-68ba8717d254] S3 Storage (73.4ms) Downloaded file from key: soliqsb1tabh5wmunz8cj8tz2w4r

2022-12-08T16:48:33Z app[af2b3aed] sin [info]D, [2022-12-08T16:48:33.663666 #536] DEBUG -- : [ActiveJob] [ActiveStorage::AnalyzeJob] [7941745a-b4a0-468a-80d5-68ba8717d254] TRANSACTION (1.0ms) BEGIN

2022-12-08T16:48:33Z app[af2b3aed] sin [info]D, [2022-12-08T16:48:33.665312 #536] DEBUG -- : [ActiveJob] [ActiveStorage::AnalyzeJob] [7941745a-b4a0-468a-80d5-68ba8717d254] ActiveStorage::Blob Update (1.3ms) UPDATE "active_storage_blobs" SET "metadata" = $1 WHERE "active_storage_blobs"."id" = $2 [["metadata", "{\"identified\":true,\"width\":708,\"height\":591,\"analyzed\":true}"], ["id", 359]]

2022-12-08T16:48:33Z app[af2b3aed] sin [info]D, [2022-12-08T16:48:33.667865 #536] DEBUG -- : [ActiveJob] [ActiveStorage::AnalyzeJob] [7941745a-b4a0-468a-80d5-68ba8717d254] TRANSACTION (1.6ms) COMMIT

2022-12-08T16:48:33Z app[af2b3aed] sin [info]I, [2022-12-08T16:48:33.668601 #536] INFO -- : [ActiveJob] [ActiveStorage::AnalyzeJob] [7941745a-b4a0-468a-80d5-68ba8717d254] Performed ActiveStorage::AnalyzeJob (Job ID: 7941745a-b4a0-468a-80d5-68ba8717d254) from Async(default) in 168.31ms

Output of Fly.configuration.replayable_exception_classes:


irb(main):001:0> Fly.configuration.replayable_exception_classes

=> [PG::ReadOnlySqlTransaction]

Output of rake middleware:


root@472ed3b7:/app/bin# rake middleware

(in /app)

use Rack::Cors

use ActionDispatch::HostAuthorization

use ActionDispatch::SSL

use Rack::Sendfile

use ActionDispatch::Static

use Rack::Deflater

use ActionDispatch::Executor

use Fly::Headers

use ActiveSupport::Cache::Strategy::LocalCache::Middleware

use Rack::Runtime

use Rack::MethodOverride

use ActionDispatch::RequestId

use ActionDispatch::RemoteIp

use Rails::Rack::Logger

use ActionDispatch::ShowExceptions

use ActionDispatch::DebugExceptions

use ActionDispatch::Callbacks

use ActionDispatch::Cookies

use ActionDispatch::Session::CookieStore

use ActionDispatch::Flash

use ActionDispatch::ContentSecurityPolicy::Middleware

use ActionDispatch::PermissionsPolicy::Middleware

use Rack::Head

use Rack::ConditionalGet

use Rack::ETag

use Rack::TempfileReaper

use Warden::Manager

use ScoutApm::Middleware

use OmniAuth::Strategies::GoogleOauth2

use OmniAuth::Strategies::Apple

run MyApp::Application.routes
5

Are there any more logs or is there any more debug information or things to try to help you help me?

6

So the upload error is interesting, and a case we thought might cause problems. Rails doesn’t know about the POST request until it’s been fully buffered to Puma by our proxy, which will refuse to replay such a large request.

Without make changes to our proxy to deal with this, here’s what you can try:

  1. If your upload is done over XHR, which is the case if you’re using Turbo in a modern Rails app, you should be able to set an custom HTTP header to send the request directly to the primary: Fly-Prefer-Region: sin. I’m not sure exactly which Turbo event to hook into, but this should technically be possible.

  2. You can use direct S3 uploads to work around the problem, since the request body that reaches Rails only carries metadata about the upload. I recommend this, as it comes with other benefits, including less bandwidth usage and built-in support for upload progress tracking.

For the variant download issue, you’ll want to grab the middleware stack that actually runs in the web process. The rails middleware command will not be accurate since fly-ruby won’t insert middleware in command line runs. Instead, you could add the following somewhere in a web request path, and check logs for the result.

logger.info Rails.application.middleware

7

It looks like turbo:before-fetch-request is the one you want. Example code can be found here: Adding a Custom Request Header Based on the Frame > Symfony UX: Turbo | SymfonyCasts

8

That’s awesome, Joshua. I understood the problem and could make your workaround (2.) work after I figured out how to do the CORS config. Thank you so much!

For the live application the middleware stack looks like this:

#<ActionDispatch::MiddlewareStack:0x00007f480a4b7388
 @middlewares=
  [Rack::Cors,
   ActionDispatch::HostAuthorization,
   ActionDispatch::SSL,
   Rack::Sendfile,
   ActionDispatch::Static,
   Rack::Deflater,
   ActionDispatch::Executor,
   Fly::Headers,
   Fly::RegionalDatabase::ReplayableRequestMiddleware,
   ActiveSupport::Cache::Strategy::LocalCache::Middleware,
   Rack::Runtime,
   Rack::MethodOverride,
   ActionDispatch::RequestId,
   ActionDispatch::RemoteIp,
   Rails::Rack::Logger,
   ActionDispatch::ShowExceptions,
   ActionDispatch::DebugExceptions,
   ActionDispatch::Callbacks,
   ActionDispatch::Cookies,
   ActionDispatch::Session::CookieStore,
   ActionDispatch::Flash,
   ActionDispatch::ContentSecurityPolicy::Middleware,
   ActionDispatch::PermissionsPolicy::Middleware,
   Rack::Head,
   Rack::ConditionalGet,
   Rack::ETag,
   Rack::TempfileReaper,
   Warden::Manager,
   Fly::RegionalDatabase::DbExceptionHandlerMiddleware,
   ScoutApm::Middleware,
   OmniAuth::Strategies::GoogleOauth2,
   OmniAuth::Strategies::Apple]>

The error in my 2nd post only happens in non-primary regions. After I access the website once from the primary region, the variants get generated and then work from everywhere.

9

Great! That middleware shows Fly::RegionalDatabase::DbExceptionHandlerMiddleware low in the stack, which means it should capture the write error. I’m not sure why this happens, but for now, you could look into pre-generating these variants instead of waiting for them to be accessed lazily.

10

Apologies, @jsierles, for only answering now. Pre-generating actually works great and might, in my case, even be the better architecture in general. So problem not solved but averted. Thank you!

I have a follow up question though. On Sidekiq Background Workers · Fly Docs it says:

The [processes] directive currently only works within a single Fly region. Scaling a Rails application to multiple regions requires a different approach to running multiple processes.

I have 2 processes in my fly.toml:

[processes]
  web = "bin/rails fly:server"
  worker = "bundle exec sidekiq"

I set fly scale count web=3 worker=1 --max-per-region=1.

My fly status then looks like this:

Instances
ID      	PROCESS	VERSION	REGION	DESIRED	STATUS 	HEALTH CHECKS	RESTARTS	CREATED
8384exxx	web    	34     	sin   	run    	running	             	0       	2022-12-24T11:04:09Z
9b7d6xxx	web    	34     	fra   	run    	running	             	0       	2022-12-24T11:03:33Z
a1e5dxxx	web    	34     	lax   	run    	running	             	0       	2022-12-24T11:03:33Z
cc109xxx	worker 	34     	sin   	run    	running	             	0       	2022-12-24T11:03:33Z

That seems to be working quite nicely for now. Am I missing something? What is the warning in said blog post about?