Manageiq: Segfault when firing the first (two) requests in development

Created on 22 Jan 2021  路  22Comments  路  Source: ManageIQ/manageiq

Since rails 6 I'm sometimes encountering this error when spinning up the development server (rails s) and opening it from chrome that usually fires 2 requests.

bug

All 22 comments

@skateman how often does this happen? Once per day? Once per hour?

Does it always happen on the first requests to puma? Does it ever happen after you've already served up a few pages?

Randomly, always on the first request...chrome sometimes fires two for the favicon/title before even hitting enter, so that's might the problem.

Also, is it always in the loading of a new pg logical client? I wonder if you can't initialize two clients concurrently with rails 6 or if that's always been the case but now rails 6 causes it happen at the same time.

I don't think this is new with Rails 6, we discussed this a while back in the main room but @himdel and I were both hitting this prior to Rails 6 being merged. Of course this could be a totally different error, just seems coincidental that first login would segfault in the pg client for both of us.

Gitter Thread: December 14, 2020 10:27 AM
My gist of the segfault: https://gist.github.com/agrare/212c3aafedf6deded5d7552574f4f21c

My comments from gitter:

https://gitter.im/ManageIQ/manageiq/core?at=600ae3b5ace09d0e8218cf2e

Same exact chain in @agrare 's gist, just instead of a segfault it's a bad file descriptor


@skateman's segfault

c:0111 p:---- s:0775 e:000774 CFUNC  :exec
c:0110 p:0015 s:0770 e:000769 METHOD /home/skateman/.rbenv/versions/2.6.6/lib/ruby/gems/2.6.0/gems/pg-1.2.3/lib/pg/basic_type_mapping.rb:120
c:0109 p:0006 s:0764 e:000763 METHOD /home/skateman/.rbenv/versions/2.6.6/lib/ruby/gems/2.6.0/gems/pg-1.2.3/lib/pg/basic_type_mapping.rb:402 [FINISH]
c:0108 p:---- s:0759 e:000758 CFUNC  :new
c:0107 p:0025 s:0754 e:000749 METHOD /home/skateman/.rbenv/versions/2.6.6/lib/ruby/gems/2.6.0/gems/pg-logical_replication-1.0.0/lib/pg/logical_replication/client.rb
c:0106 p:0009 s:0743 e:000742 METHOD /home/skateman/.rbenv/versions/2.6.6/lib/ruby/gems/2.6.0/gems/pg-logical_replication-1.0.0/lib/pg/logical_replication/client.rb
c:0105 p:0004 s:0737 e:000736 METHOD /home/skateman/.rbenv/versions/2.6.6/lib/ruby/gems/2.6.0/gems/pg-logical_replication-1.0.0/lib/pg/logical_replication/client.rb
c:0104 p:0008 s:0733 e:000732 BLOCK  /home/skateman/Repositories/ManageIQ/manageiq/lib/miq_pglogical.rb:16
c:0103 p:0014 s:0730 e:000729 METHOD /home/skateman/Repositories/ManageIQ/manageiq/lib/miq_pglogical/connection_handling.rb:8
c:0102 p:0008 s:0725 e:000724 METHOD /home/skateman/Repositories/ManageIQ/manageiq/lib/miq_pglogical.rb:16
c:0101 p:0013 s:0721 e:000720 METHOD /home/skateman/Repositories/ManageIQ/manageiq/app/models/miq_region.rb:143
c:0100 p:0004 s:0717 e:000716 METHOD /home/skateman/Repositories/ManageIQ/manageiq/app/models/miq_region.rb:147
c:0099 p:1559 s:0713 e:000712 METHOD /home/skateman/Repositories/ManageIQ/manageiq-ui-classic/app/views/dashboard/login.html.haml:116

@agrare 's bad file descriptor

/home/grare/adam/.gem/gems/pg-1.2.3/lib/pg/basic_type_mapping.rb:120:in `exec'
/home/grare/adam/.gem/gems/pg-1.2.3/lib/pg/basic_type_mapping.rb:120:in `build_coder_maps'
/home/grare/adam/.gem/gems/pg-1.2.3/lib/pg/basic_type_mapping.rb:402:in `initialize'
/home/grare/adam/.gem/gems/pg-logical_replication-1.0.0/lib/pg/logical_replication/client.rb:316:in `new'
/home/grare/adam/.gem/gems/pg-logical_replication-1.0.0/lib/pg/logical_replication/client.rb:316:in `typed_exec'
/home/grare/adam/.gem/gems/pg-logical_replication-1.0.0/lib/pg/logical_replication/client.rb:158:in `subscriptions'
/home/grare/adam/.gem/gems/pg-logical_replication-1.0.0/lib/pg/logical_replication/client.rb:199:in `subscriber?'
/home/grare/adam/src/manageiq/manageiq/lib/miq_pglogical.rb:16:in `block in subscriber?'
/home/grare/adam/src/manageiq/manageiq/lib/miq_pglogical/connection_handling.rb:8:in `with_connection_error_handling'
/home/grare/adam/src/manageiq/manageiq/lib/miq_pglogical.rb:16:in `subscriber?'
/home/grare/adam/src/manageiq/manageiq/app/models/miq_region.rb:143:in `global_replication_type?'
/home/grare/adam/src/manageiq/manageiq/app/models/miq_region.rb:147:in `replication_type'
/home/grare/adam/src/manageiq/manageiq-ui-classic/app/views/dashboard/login.html.haml:116:in `__home_grare_adam_src_manageiq_manageiq_ui_classic_app_views_dashboard_login_html_haml___364608728378130338_770120'

I got similar backtraces as @agrare and a malloc error seen below:

puma 4.3.7 (tcp://localhost:3000) [MIQ: Web Server Worker](65383,0x700000e28000) malloc: double free for ptr 0x7fb4c03c3600
puma 4.3.7 (tcp://localhost:3000) [MIQ: Web Server Worker](65383,0x700000e28000) malloc: *** set a breakpoint in malloc_error_break to debug

Using this script against bin/rails s:

threads = []
url = 'http://admin:[email protected]:3000/'
11.times do
  threads << Thread.new { `curl #{url}` }
end

This doesn't fix it but making this change locally, I cannot recreate either the malloc error or the backtrace with build_coder_maps in the backtrace, so I guess we need a mutex:

diff --git a/lib/miq_pglogical/connection_handling.rb b/lib/miq_pglogical/connection_handling.rb
index 2127a191ab..95062c3df7 100644
--- a/lib/miq_pglogical/connection_handling.rb
+++ b/lib/miq_pglogical/connection_handling.rb
@@ -15,8 +15,7 @@ class MiqPglogical
       end

       def pglogical(refresh = false)
-        @pglogical = nil if refresh
-        @pglogical ||= PG::LogicalReplication::Client.new(pg_connection)
+        PG::LogicalReplication::Client.new(pg_connection)
       end
     end

I guess we can also store the client in a thread local variable to avoid a mutex.

Now I had this one:

=> Booting Puma
=> Rails 6.0.3.4 application starting in development 
=> Run `rails server --help` for more startup options
** ManageIQ master, codename: Lasker
Puma starting in single mode...
* Version 4.3.7 (ruby 2.6.6-p146), codename: Mysterious Traveller
* Min threads: 5, max threads: 5
* Environment: development
* Listening on tcp://0.0.0.0:3000
Use Ctrl-C to stop
[----] I, [2021-01-25T11:19:35.184728 #493253:7d11a6c]  INFO -- : Started GET "/" for 127.0.0.1 at 2021-01-25 11:19:35 +0100
[----] I, [2021-01-25T11:19:36.059045 #493253:7d11a6c]  INFO -- : Processing by DashboardController#login as HTML
[----] D, [2021-01-25T11:19:36.068118 #493253:7d11a6c] DEBUG -- : PostgreSQLAdapter#log_after_checkout, connection_pool: size: 26, connections: 1, in use: 1, waiting_in_queue: 0
[----] D, [2021-01-25T11:19:36.081005 #493253:7d11a6c] DEBUG -- :   Tenant Load (0.7ms)  SELECT "tenants".* FROM "tenants" WHERE "tenants"."id" BETWEEN $1 AND $2 AND "tenants"."ancestry" IS NULL ORDER BY "tenants"."id" ASC LIMIT $3  [["id", 0], ["id", 999999999999], ["LIMIT", 1]]
[----] D, [2021-01-25T11:19:36.108603 #493253:7d11a6c] DEBUG -- :   Tenant Inst Including Associations (26.7ms - 1rows)
[----] D, [2021-01-25T11:19:36.117314 #493253:7d11a6c] DEBUG -- :   MiqServer Load (0.6ms)  SELECT "miq_servers".* FROM "miq_servers" WHERE "miq_servers"."guid" = $1 LIMIT $2  [["guid", "6018179a-b9fd-11e5-8695-02423517de37"], ["LIMIT", 1]]
[----] D, [2021-01-25T11:19:36.118037 #493253:7d11a6c] DEBUG -- :   MiqServer Inst Including Associations (0.2ms - 1rows)
[----] I, [2021-01-25T11:19:36.129107 #493253:7d11a6c]  INFO -- :   Rendering /home/skateman/Repositories/ManageIQ/manageiq-ui-classic/app/views/dashboard/login.html.haml within layouts/login
[----] I, [2021-01-25T11:19:39.200598 #493253:7d11b0c]  INFO -- : Started GET "/" for 127.0.0.1 at 2021-01-25 11:19:39 +0100
[----] I, [2021-01-25T11:19:39.302646 #493253:7d11b0c]  INFO -- : Processing by DashboardController#login as HTML
[----] D, [2021-01-25T11:19:39.310966 #493253:7d11b0c] DEBUG -- : PostgreSQLAdapter#log_after_checkout, connection_pool: size: 26, connections: 2, in use: 2, waiting_in_queue: 0
[----] D, [2021-01-25T11:19:39.312232 #493253:7d11b0c] DEBUG -- :   MiqServer Load (0.5ms)  SELECT "miq_servers".* FROM "miq_servers" WHERE "miq_servers"."guid" = $1 LIMIT $2  [["guid", "6018179a-b9fd-11e5-8695-02423517de37"], ["LIMIT", 1]]
[----] D, [2021-01-25T11:19:39.312755 #493253:7d11b0c] DEBUG -- :   MiqServer Inst Including Associations (0.1ms - 1rows)
[----] I, [2021-01-25T11:19:39.313235 #493253:7d11b0c]  INFO -- :   Rendering /home/skateman/Repositories/ManageIQ/manageiq-ui-classic/app/views/dashboard/login.html.haml within layouts/login
[----] D, [2021-01-25T11:19:43.422047 #493253:7d11a6c] DEBUG -- :   CACHE MiqServer Load (0.0ms)  SELECT "miq_servers".* FROM "miq_servers" WHERE "miq_servers"."guid" = $1 LIMIT $2  [["guid", "6018179a-b9fd-11e5-8695-02423517de37"], ["LIMIT", 1]]
[----] D, [2021-01-25T11:19:43.422249 #493253:7d11a6c] DEBUG -- :   MiqServer Inst Including Associations (0.1ms - 1rows)
[----] I, [2021-01-25T11:19:43.422354 #493253:7d11a6c]  INFO -- :   Rendered /home/skateman/Repositories/ManageIQ/manageiq-ui-classic/app/views/layouts/_spinner.html.haml (Duration: 2.1ms | Allocations: 3652)
[----] I, [2021-01-25T11:19:43.425949 #493253:7d11a6c]  INFO -- :   Rendered /home/skateman/Repositories/ManageIQ/manageiq-ui-classic/app/views/layouts/_flash_msg.html.haml (Duration: 3.2ms | Allocations: 9849)
[----] I, [2021-01-25T11:19:43.428639 #493253:7d11a6c]  INFO -- :   Rendered /home/skateman/Repositories/ManageIQ/manageiq-ui-classic/app/views/dashboard/_login_more.html.haml (Duration: 2.2ms | Allocations: 5658)
[----] D, [2021-01-25T11:19:45.865919 #493253:7d11b0c] DEBUG -- :   CACHE MiqServer Load (0.0ms)  SELECT "miq_servers".* FROM "miq_servers" WHERE "miq_servers"."guid" = $1 LIMIT $2  [["guid", "6018179a-b9fd-11e5-8695-02423517de37"], ["LIMIT", 1]]
[----] D, [2021-01-25T11:19:45.866164 #493253:7d11b0c] DEBUG -- :   MiqServer Inst Including Associations (0.1ms - 1rows)
[----] I, [2021-01-25T11:19:45.866266 #493253:7d11b0c]  INFO -- :   Rendered /home/skateman/Repositories/ManageIQ/manageiq-ui-classic/app/views/layouts/_spinner.html.haml (Duration: 0.6ms | Allocations: 203)
[----] I, [2021-01-25T11:19:45.866449 #493253:7d11b0c]  INFO -- :   Rendered /home/skateman/Repositories/ManageIQ/manageiq-ui-classic/app/views/layouts/_flash_msg.html.haml (Duration: 0.0ms | Allocations: 12)
[----] I, [2021-01-25T11:19:45.866729 #493253:7d11b0c]  INFO -- :   Rendered /home/skateman/Repositories/ManageIQ/manageiq-ui-classic/app/views/dashboard/_login_more.html.haml (Duration: 0.0ms | Allocations: 5)
double free or corruption (!prev)
./run: line 9: 493253 Aborted                 (core dumped) bundle exec rails s -b 0.0.0.0

Can others try the patch above?

Other than wrapping all of the callers of the client code(with_connection_error_handling or pg_logical) with a mutex, it seems like we should really determine if we need to cache at all. In addition, it's pretty gnarly that we initialize the pg logical client with a AR base connection instead of a connection pool. In some testing with thread local variables, there were some connection lost errors that could be related to sharing a connection between threads instead of letting them use the connection pool properly.

While I don't think that this patch above is complete because we still share the connection object among different client objects, I was unable to recreate any of the segfaults or various fatal errors/backtraces reported in this issue.

I'm seeing the The version of PostgreSQL being connected to is incompatible with ManageIQ (10 required) message 12 times during the first few seconds with the patch, intermingled with request log output.

But no segfaults or crashes either :+1: after ~30s all the requests complete (and no new incompatible messages after that, and allocations go down to a tenth of before).

@himdel you need two GET requests from your browser to reproduce this and the first one should not finish before you fire the second.

Now I didn't get a segfault but this:

* Listening on tcp://0.0.0.0:3000
Use Ctrl-C to stop
[----] I, [2021-01-27T11:59:34.643264 #769650:6e925e0]  INFO -- : Started GET "/" for 127.0.0.1 at 2021-01-27 11:59:34 +0100
[----] I, [2021-01-27T11:59:35.488066 #769650:6e925e0]  INFO -- : Processing by DashboardController#login as HTML
[----] D, [2021-01-27T11:59:35.496458 #769650:6e925e0] DEBUG -- : PostgreSQLAdapter#log_after_checkout, connection_pool: size: 26, connections: 1, in use: 1, waiting_in_queue: 0
[----] D, [2021-01-27T11:59:35.508552 #769650:6e925e0] DEBUG -- :   Tenant Load (0.5ms)  SELECT "tenants".* FROM "tenants" WHERE "tenants"."id" BETWEEN $1 AND $2 AND "tenants"."ancestry" IS NULL ORDER BY "tenants"."id" ASC LIMIT $3  [["id", 0], ["id", 999999999999], ["LIMIT", 1]]
[----] D, [2021-01-27T11:59:35.527122 #769650:6e925e0] DEBUG -- :   Tenant Inst Including Associations (18.2ms - 1rows)
[----] D, [2021-01-27T11:59:35.533331 #769650:6e925e0] DEBUG -- :   MiqServer Load (0.5ms)  SELECT "miq_servers".* FROM "miq_servers" WHERE "miq_servers"."guid" = $1 LIMIT $2  [["guid", "6018179a-b9fd-11e5-8695-02423517de37"], ["LIMIT", 1]]
[----] D, [2021-01-27T11:59:35.533773 #769650:6e925e0] DEBUG -- :   MiqServer Inst Including Associations (0.1ms - 1rows)
[----] I, [2021-01-27T11:59:35.539053 #769650:6e925e0]  INFO -- :   Rendering /home/skateman/Repositories/ManageIQ/manageiq-ui-classic/app/views/dashboard/login.html.haml within layouts/login
[----] I, [2021-01-27T11:59:38.646740 #769650:6e92518]  INFO -- : Started GET "/" for 127.0.0.1 at 2021-01-27 11:59:38 +0100
[----] I, [2021-01-27T11:59:38.770965 #769650:6e92518]  INFO -- : Processing by DashboardController#login as HTML
[----] D, [2021-01-27T11:59:38.778971 #769650:6e92518] DEBUG -- : PostgreSQLAdapter#log_after_checkout, connection_pool: size: 26, connections: 2, in use: 2, waiting_in_queue: 0
[----] D, [2021-01-27T11:59:38.780046 #769650:6e92518] DEBUG -- :   MiqServer Load (0.4ms)  SELECT "miq_servers".* FROM "miq_servers" WHERE "miq_servers"."guid" = $1 LIMIT $2  [["guid", "6018179a-b9fd-11e5-8695-02423517de37"], ["LIMIT", 1]]
[----] D, [2021-01-27T11:59:38.780440 #769650:6e92518] DEBUG -- :   MiqServer Inst Including Associations (0.1ms - 1rows)
[----] I, [2021-01-27T11:59:38.780792 #769650:6e92518]  INFO -- :   Rendering /home/skateman/Repositories/ManageIQ/manageiq-ui-classic/app/views/dashboard/login.html.haml within layouts/login
[----] D, [2021-01-27T11:59:45.337165 #769650:6e925e0] DEBUG -- :   CACHE MiqServer Load (0.0ms)  SELECT "miq_servers".* FROM "miq_servers" WHERE "miq_servers"."guid" = $1 LIMIT $2  [["guid", "6018179a-b9fd-11e5-8695-02423517de37"], ["LIMIT", 1]]
[----] D, [2021-01-27T11:59:45.337420 #769650:6e925e0] DEBUG -- :   MiqServer Inst Including Associations (0.1ms - 1rows)
[----] I, [2021-01-27T11:59:45.337525 #769650:6e925e0]  INFO -- :   Rendered /home/skateman/Repositories/ManageIQ/manageiq-ui-classic/app/views/layouts/_spinner.html.haml (Duration: 2.1ms | Allocations: 3659)
[----] I, [2021-01-27T11:59:45.341343 #769650:6e925e0]  INFO -- :   Rendered /home/skateman/Repositories/ManageIQ/manageiq-ui-classic/app/views/layouts/_flash_msg.html.haml (Duration: 3.4ms | Allocations: 10517)
[----] I, [2021-01-27T11:59:45.344378 #769650:6e925e0]  INFO -- :   Rendered /home/skateman/Repositories/ManageIQ/manageiq-ui-classic/app/views/dashboard/_login_more.html.haml (Duration: 2.5ms | Allocations: 5931)
[----] D, [2021-01-27T11:59:46.966800 #769650:6e92518] DEBUG -- :   CACHE MiqServer Load (0.0ms)  SELECT "miq_servers".* FROM "miq_servers" WHERE "miq_servers"."guid" = $1 LIMIT $2  [["guid", "6018179a-b9fd-11e5-8695-02423517de37"], ["LIMIT", 1]]
[----] D, [2021-01-27T11:59:46.967014 #769650:6e92518] DEBUG -- :   MiqServer Inst Including Associations (0.1ms - 1rows)
[----] I, [2021-01-27T11:59:46.967095 #769650:6e92518]  INFO -- :   Rendered /home/skateman/Repositories/ManageIQ/manageiq-ui-classic/app/views/layouts/_spinner.html.haml (Duration: 0.5ms | Allocations: 203)
[----] I, [2021-01-27T11:59:46.967220 #769650:6e92518]  INFO -- :   Rendered /home/skateman/Repositories/ManageIQ/manageiq-ui-classic/app/views/layouts/_flash_msg.html.haml (Duration: 0.0ms | Allocations: 12)
[----] I, [2021-01-27T11:59:46.967439 #769650:6e92518]  INFO -- :   Rendered /home/skateman/Repositories/ManageIQ/manageiq-ui-classic/app/views/dashboard/_login_more.html.haml (Duration: 0.0ms | Allocations: 5)
[----] I, [2021-01-27T11:59:46.978635 #769650:6e92518]  INFO -- :   Rendered /home/skateman/Repositories/ManageIQ/manageiq-ui-classic/app/views/dashboard/login.html.haml within layouts/login (Duration: 8197.7ms | Allocations: 13256427)
[----] I, [2021-01-27T11:59:46.983274 #769650:6e925e0]  INFO -- :   Rendered /home/skateman/Repositories/ManageIQ/manageiq-ui-classic/app/views/dashboard/login.html.haml within layouts/login (Duration: 11444.0ms | Allocations: 17380440)
[----] F, [2021-01-27T11:59:46.983708 #769650:6e92518] FATAL -- : Error caught: [ActionView::Template::Error] no connection to the server

/home/skateman/.rbenv/versions/2.6.6/lib/ruby/gems/2.6.0/gems/pg-1.2.3/lib/pg/basic_type_mapping.rb:120:in `exec'
/home/skateman/.rbenv/versions/2.6.6/lib/ruby/gems/2.6.0/gems/pg-1.2.3/lib/pg/basic_type_mapping.rb:120:in `build_coder_maps'
/home/skateman/.rbenv/versions/2.6.6/lib/ruby/gems/2.6.0/gems/pg-1.2.3/lib/pg/basic_type_mapping.rb:402:in `initialize'
/home/skateman/.rbenv/versions/2.6.6/lib/ruby/gems/2.6.0/gems/pg-logical_replication-1.0.0/lib/pg/logical_replication/client.rb:316:in `new'
/home/skateman/.rbenv/versions/2.6.6/lib/ruby/gems/2.6.0/gems/pg-logical_replication-1.0.0/lib/pg/logical_replication/client.rb:316:in `typed_exec'
/home/skateman/.rbenv/versions/2.6.6/lib/ruby/gems/2.6.0/gems/pg-logical_replication-1.0.0/lib/pg/logical_replication/client.rb:158:in `subscriptions'
/home/skateman/.rbenv/versions/2.6.6/lib/ruby/gems/2.6.0/gems/pg-logical_replication-1.0.0/lib/pg/logical_replication/client.rb:199:in `subscriber?'
/home/skateman/Repositories/ManageIQ/manageiq/lib/miq_pglogical.rb:16:in `block in subscriber?'
/home/skateman/Repositories/ManageIQ/manageiq/lib/miq_pglogical/connection_handling.rb:8:in `with_connection_error_handling'
/home/skateman/Repositories/ManageIQ/manageiq/lib/miq_pglogical.rb:16:in `subscriber?'
/home/skateman/Repositories/ManageIQ/manageiq/app/models/miq_region.rb:143:in `global_replication_type?'
/home/skateman/Repositories/ManageIQ/manageiq/app/models/miq_region.rb:147:in `replication_type'
/home/skateman/Repositories/ManageIQ/manageiq-ui-classic/app/views/dashboard/login.html.haml:116:in `__home_skateman__epositories__anage___manageiq_ui_classic_app_views_dashboard_login_html_haml__3696182104360241195_139132960'

@himdel this should do the thing if your browser doesn't do it automatically:

curl -XGET "http://localhost:3000" &; curl -XGET "http://localhost:3000"

@jrafanie with your patch it seems working for me

@skateman just to confirm, this was WITHOUT the patch that removes the caching, correct?

I'm more and more leaning to just opening a PR with the patch removing the caching and we can determine later if there are some downsides. If others are confirming things still work, the various fatal errors don't happen, and there isn't an obvious performance downside, we can determine at a later time if performance is an issue. Right now, I don't think easily recreated segfaults and fatal errors is something we can tolerate.

FYI, I did look and we're at the latest pg gem but a bit behind on puma.

```

  • puma (newest 5.1.1, installed 4.3.7, requested ~> 4.2) in groups "web_server, manageiq_default"
    ```

FYI, I did look and we're at the latest pg gem but a bit behind on puma.

@jrafanie any issues bringing us up to the latest on master?

I'm more and more leaning to just opening a PR with the patch removing the caching and we can determine later if there are some downsides.

IMHO, that is the right way to move forward.

@jrafanie any issues bringing us up to the latest on master?

I don't know of any problems with upgrading but haven't looked at the changes.

Considering @Fryguy pointed out code caching at the class scope, was shared between threads, had no mutex around access, and removing this caching seemingly removes the fatal errors, I'm thinking we can have some confidence removing the caching can be done now and we can upgrade puma separately.

I'll open a PR and link it here.

Was this page helpful?
0 / 5 - 0 ratings

Related issues

zhitongLBN picture zhitongLBN  路  6Comments

lpichler picture lpichler  路  6Comments

ahrechushkin picture ahrechushkin  路  8Comments

jawatts picture jawatts  路  8Comments

jistefan picture jistefan  路  5Comments