Logster 2.1.0 causes segfault running unicorn in discourse_dev docker image

Dev
1

Since https://github.com/discourse/discourse/commit/1c00e8a7550936ec7e17aa6bc91b1ef46df982e6, attempting to run unicorn in the discourse_dev docker image results in a segfault:

discourse_dev > unicorn                                                                                                                                                                                                                                                                                                                                                                                                                                                        leo@leo-business 15:44:53
I, [2019-02-15T15:44:56.912215 #221]  INFO -- : Refreshing Gem list
Starting CSS change watcher
I, [2019-02-15T15:44:58.388824 #221]  INFO -- : listening on addr=0.0.0.0:3000 fd=13
Starting up 1 supervised sidekiqs
Loading Sidekiq in process id 328
/usr/local/lib/ruby/gems/2.5.0/gems/logster-2.1.0/lib/logster/scheduler.rb:12: [BUG] Segmentation fault at 0x0000564a00000051
ruby 2.5.2p104 (2018-10-18 revision 65133) [x86_64-linux]

-- Control frame information -----------------------------------------------
c:0061 p:---- s:0392 e:000391 CFUNC  :push
c:0060 p:0028 s:0387 e:000386 METHOD /usr/local/lib/ruby/gems/2.5.0/gems/logster-2.1.0/lib/logster/scheduler.rb:12
c:0059 p:0042 s:0382 E:0002d0 METHOD /usr/local/lib/ruby/gems/2.5.0/gems/logster-2.1.0/lib/logster/defer_logger.rb:9
c:0058 p:0219 s:0374 e:000373 METHOD /usr/local/lib/ruby/gems/2.5.0/gems/logster-2.1.0/lib/logster/logger.rb:101
c:0057 p:0011 s:0363 e:000362 METHOD /usr/local/lib/ruby/gems/2.5.0/gems/logster-2.1.0/lib/logster/logger.rb:52
c:0056 p:0020 s:0357 e:000356 METHOD /usr/local/lib/ruby/2.5.0/logger.rb:493
c:0055 p:0021 s:0351 e:000350 METHOD /usr/local/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2/lib/active_support/log_subscriber.rb:96
c:0054 p:0011 s:0345 e:000344 METHOD /usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2/lib/active_record/log_subscriber.rb:95
c:0053 p:0276 s:0339 e:000338 METHOD /usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2/lib/active_record/log_subscriber.rb:43
c:0052 p:0054 s:0329 e:000328 METHOD /usr/local/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2/lib/active_support/subscriber.rb:101
c:0051 p:0018 s:0319 e:000318 METHOD /usr/local/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2/lib/active_support/log_subscriber.rb:84
c:0050 p:0012 s:0311 e:000310 METHOD /usr/local/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2/lib/active_support/notifications/fanout.rb:104
c:0049 p:0012 s:0304 e:000303 BLOCK  /usr/local/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2/lib/active_support/notifications/fanout.rb:48 [FINISH]
c:0048 p:---- s:0300 e:000299 CFUNC  :each
c:0047 p:0014 s:0296 e:000295 METHOD /usr/local/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2/lib/active_support/notifications/fanout.rb:48
c:0046 p:0015 s:0288 e:000287 METHOD /usr/local/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2/lib/active_support/notifications/instrumenter.rb:44
c:0045 p:0029 s:0281 e:000279 METHOD /usr/local/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2/lib/active_support/notifications/instrumenter.rb:29
c:0044 p:0038 s:0272 e:000271 METHOD /usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2/lib/active_record/connection_adapters/abstract_adapter.rb:569
c:0043 p:0021 s:0263 e:000262 METHOD /usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2/lib/active_record/connection_adapters/postgresql_adapter.rb:609
c:0042 p:0018 s:0255 e:000254 METHOD /usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2/lib/active_record/connection_adapters/postgresql_adapter.rb:596
c:0041 p:0021 s:0244 e:000243 METHOD /usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2/lib/active_record/connection_adapters/postgresql/database_statements.rb:
c:0040 p:0019 s:0235 e:000234 METHOD /usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2/lib/active_record/connection_adapters/abstract/database_statements.rb:47
c:0039 p:0138 s:0228 e:000227 METHOD /usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2/lib/active_record/connection_adapters/abstract/database_statements.rb:62
c:0038 p:0081 s:0218 e:000217 METHOD /usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2/lib/active_record/connection_adapters/abstract/query_cache.rb:101
c:0037 p:0040 s:0208 e:000207 METHOD /usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2/lib/active_record/querying.rb:41
c:0036 p:0028 s:0194 e:000193 BLOCK  /usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2/lib/active_record/relation.rb:560
c:0035 p:0014 s:0189 e:000188 METHOD /usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2/lib/active_record/relation.rb:584
c:0034 p:0005 s:0185 e:000184 METHOD /usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2/lib/active_record/relation.rb:547
c:0033 p:0013 s:0180 e:000179 METHOD /usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2/lib/active_record/relation.rb:422
c:0032 p:0004 s:0175 e:000174 METHOD /usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2/lib/active_record/relation.rb:200
c:0031 p:0004 s:0171 e:000170 METHOD /usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2/lib/active_record/relation.rb:195
c:0030 p:0092 s:0167 e:000166 METHOD /usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2/lib/active_record/relation/finder_methods.rb:528
c:0029 p:0029 s:0160 e:000156 METHOD /usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2/lib/active_record/relation/finder_methods.rb:513
c:0028 p:0020 s:0152 e:000151 METHOD /usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2/lib/active_record/relation/finder_methods.rb:125
c:0027 p:0018 s:0147 e:000146 METHOD /usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2/lib/active_record/querying.rb:5
c:0026 p:0012 s:0139 e:000138 BLOCK  /src/config/initializers/100-sidekiq.rb:55 [FINISH]
c:0025 p:---- s:0135 e:000134 CFUNC  :each
c:0024 p:0027 s:0131 E:000d80 BLOCK  /src/config/initializers/100-sidekiq.rb:54
c:0023 p:0011 s:0128 E:000f90 BLOCK  /src/config/initializers/004-rails_multisite.rb:8 [FINISH]
c:0022 p:0051 s:0123 E:000bd0 METHOD /usr/local/lib/ruby/gems/2.5.0/gems/rails_multisite-2.0.6/lib/rails_multisite/connection_management.rb:63
c:0021 p:0027 s:0115 E:0005b0 METHOD /usr/local/lib/ruby/gems/2.5.0/gems/rails_multisite-2.0.6/lib/rails_multisite/connection_management.rb:73
c:0020 p:0005 s:0109 E:000820 METHOD /src/config/initializers/004-rails_multisite.rb:6
c:0019 p:0091 s:0105 E:0006d0 TOP    /src/config/initializers/100-sidekiq.rb:53 [FINISH]
c:0018 p:---- s:0102 e:000101 CFUNC  :load
c:0017 p:0034 s:0096 E:002540 METHOD /usr/local/lib/ruby/gems/2.5.0/gems/bootsnap-1.3.2/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:50
c:0016 p:0011 s:0088 E:0006f0 BLOCK  /usr/local/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2/lib/active_support/dependencies.rb:285
c:0015 p:0067 s:0085 E:001cb8 METHOD /usr/local/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2/lib/active_support/dependencies.rb:257
c:0014 p:0015 s:0078 E:0009f8 METHOD /usr/local/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2/lib/active_support/dependencies.rb:285
c:0013 p:0192 s:0071 E:000e58 METHOD /src/lib/demon/sidekiq.rb:51
c:0012 p:0031 s:0064 E:001ce0 METHOD /src/lib/demon/base.rb:138
c:0011 p:0071 s:0060 E:0014f8 METHOD /src/lib/demon/base.rb:127
c:0010 p:0065 s:0055 E:002238 BLOCK  /src/lib/demon/base.rb:13 [FINISH]
c:0009 p:---- s:0051 e:000050 CFUNC  :times
c:0008 p:0030 s:0047 E:000d48 METHOD /src/lib/demon/base.rb:12
c:0007 p:0331 s:0040 E:001878 BLOCK  /src/config/unicorn.conf.rb:132 [FINISH]
c:0006 p:0091 s:0032 E:0004f0 METHOD /usr/local/lib/ruby/gems/2.5.0/gems/unicorn-5.4.1/lib/unicorn/http_server.rb:543
c:0005 p:0094 s:0024 E:001700 METHOD /usr/local/lib/ruby/gems/2.5.0/gems/unicorn-5.4.1/lib/unicorn/http_server.rb:142
c:0004 p:0187 s:0020 E:000960 TOP    /usr/local/lib/ruby/gems/2.5.0/gems/unicorn-5.4.1/bin/unicorn:126 [FINISH]
c:0003 p:---- s:0013 e:000012 CFUNC  :load
c:0002 p:0475 s:0008 E:001170 EVAL   bin/unicorn:48 [FINISH]
c:0001 p:0000 s:0003 E:000250 (none) [FINISH]

-- Ruby level backtrace information ----------------------------------------
bin/unicorn:48:in `<main>'
bin/unicorn:48:in `load'
/usr/local/lib/ruby/gems/2.5.0/gems/unicorn-5.4.1/bin/unicorn:126:in `<top (required)>'
/usr/local/lib/ruby/gems/2.5.0/gems/unicorn-5.4.1/lib/unicorn/http_server.rb:142:in `start'
/usr/local/lib/ruby/gems/2.5.0/gems/unicorn-5.4.1/lib/unicorn/http_server.rb:543:in `spawn_missing_workers'
/src/config/unicorn.conf.rb:132:in `block in reload'
/src/lib/demon/base.rb:12:in `start'
/src/lib/demon/base.rb:12:in `times'
/src/lib/demon/base.rb:13:in `block in start'
/src/lib/demon/base.rb:127:in `start'
/src/lib/demon/base.rb:138:in `run'
/src/lib/demon/sidekiq.rb:51:in `after_fork'
/usr/local/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2/lib/active_support/dependencies.rb:285:in `load'
/usr/local/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2/lib/active_support/dependencies.rb:257:in `load_dependency'
/usr/local/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2/lib/active_support/dependencies.rb:285:in `block in load'
/usr/local/lib/ruby/gems/2.5.0/gems/bootsnap-1.3.2/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:50:in `load'
/usr/local/lib/ruby/gems/2.5.0/gems/bootsnap-1.3.2/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:50:in `load'
/src/config/initializers/100-sidekiq.rb:53:in `<main>'
/src/config/initializers/004-rails_multisite.rb:6:in `safe_each_connection'
/usr/local/lib/ruby/gems/2.5.0/gems/rails_multisite-2.0.6/lib/rails_multisite/connection_management.rb:73:in `each_connection'
/usr/local/lib/ruby/gems/2.5.0/gems/rails_multisite-2.0.6/lib/rails_multisite/connection_management.rb:63:in `with_connection'
/src/config/initializers/004-rails_multisite.rb:8:in `block in safe_each_connection'
/src/config/initializers/100-sidekiq.rb:54:in `block in <main>'
/src/config/initializers/100-sidekiq.rb:54:in `each'
/src/config/initializers/100-sidekiq.rb:55:in `block (2 levels) in <main>'
/usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2/lib/active_record/querying.rb:5:in `first'
/usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2/lib/active_record/relation/finder_methods.rb:125:in `first'
/usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2/lib/active_record/relation/finder_methods.rb:513:in `find_nth'
/usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2/lib/active_record/relation/finder_methods.rb:528:in `find_nth_with_limit'
/usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2/lib/active_record/relation.rb:195:in `to_ary'
/usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2/lib/active_record/relation.rb:200:in `records'
/usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2/lib/active_record/relation.rb:422:in `load'
/usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2/lib/active_record/relation.rb:547:in `exec_queries'
/usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2/lib/active_record/relation.rb:584:in `skip_query_cache_if_necessary'
/usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2/lib/active_record/relation.rb:560:in `block in exec_queries'
/usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2/lib/active_record/querying.rb:41:in `find_by_sql'
/usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2/lib/active_record/connection_adapters/abstract/query_cache.rb:101:in `select_all'
/usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2/lib/active_record/connection_adapters/abstract/database_statements.rb:62:in `select_all'
/usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2/lib/active_record/connection_adapters/abstract/database_statements.rb:470:in `select'
/usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2/lib/active_record/connection_adapters/postgresql/database_statements.rb:81:in `exec_query'
/usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2/lib/active_record/connection_adapters/postgresql_adapter.rb:596:in `execute_and_clear'
/usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2/lib/active_record/connection_adapters/postgresql_adapter.rb:609:in `exec_no_cache'
/usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2/lib/active_record/connection_adapters/abstract_adapter.rb:569:in `log'
/usr/local/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2/lib/active_support/notifications/instrumenter.rb:29:in `instrument'
/usr/local/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2/lib/active_support/notifications/instrumenter.rb:44:in `finish_with_state'
/usr/local/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2/lib/active_support/notifications/fanout.rb:48:in `finish'
/usr/local/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2/lib/active_support/notifications/fanout.rb:48:in `each'
/usr/local/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2/lib/active_support/notifications/fanout.rb:48:in `block in finish'
/usr/local/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2/lib/active_support/notifications/fanout.rb:104:in `finish'
/usr/local/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2/lib/active_support/log_subscriber.rb:84:in `finish'
/usr/local/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2/lib/active_support/subscriber.rb:101:in `finish'
/usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2/lib/active_record/log_subscriber.rb:43:in `sql'
/usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2/lib/active_record/log_subscriber.rb:95:in `debug'
/usr/local/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2/lib/active_support/log_subscriber.rb:96:in `debug'
/usr/local/lib/ruby/2.5.0/logger.rb:493:in `debug'
/usr/local/lib/ruby/gems/2.5.0/gems/logster-2.1.0/lib/logster/logger.rb:52:in `add'
/usr/local/lib/ruby/gems/2.5.0/gems/logster-2.1.0/lib/logster/logger.rb:101:in `add_with_opts'
/usr/local/lib/ruby/gems/2.5.0/gems/logster-2.1.0/lib/logster/defer_logger.rb:9:in `report_to_store'
/usr/local/lib/ruby/gems/2.5.0/gems/logster-2.1.0/lib/logster/scheduler.rb:12:in `schedule'
/usr/local/lib/ruby/gems/2.5.0/gems/logster-2.1.0/lib/logster/scheduler.rb:12:in `push'

This happens across my desktop and laptop, so I don’t think it’s a result of the host machine being configured in a weird way.

6 Likes
2

Well that is weird cc @Osama

1 Like
3

This is a ruby bug in the Queue class it seems, my first gut reaction here is to upgrade our dev image to 2.6.1

Can you report the full backtrace to the ruby issue tracker and link here?

Btw this code does not run in production so there is nothing mega urgent here

Maybe this?

https://bugs.ruby-lang.org/issues/14634

@LeoMcA can you do a quick version check on your ruby in the image? What is it?

6 Likes
5

Since I have a repro, my plan is:

Got to bump our base image to 2.6.1 cause 2.5.4 is not released yet and we might as well just go on 2.6.1 for the fix, I prefer that to yanking in a complex patch for now.

New image should be ready in 2 hours or so.

5 Likes
7

New dev image is in the oven and working!

git pull
docker rm -f discourse_dev
bin/docker/boot_dev
bin/docker/unicorn

And you should be good to go :confetti_ball: thanks heaps for reporting this !

4 Likes
8

If a newer ruby is required, we should update our README saying so, and perhaps raise a better error if it’s not met? I just started segfaulting locally and had no idea why.

10

I am mixed here, this is fixed in 2.5.4 which is almost released, let me first try to nag my Ruby friends

11

Right now it’s quite traumatic though. I had to bump my tmux scrollback to even see the beginning of the segfault to realize it was logster.

Maybe logster should be rolled back if we are waiting for a new Ruby.

12

We can skip the feature on that speeds up dev on 2.5.3, but I don’t want to roll back all of logster

13

Ok @eviltrout this is sorted now per:

https://github.com/discourse/discourse/commit/8745f78277f80250032352343bde59f7bba12bec


sam@ubuntu discourse % ruby --version
ruby 2.5.3p105 (2018-10-18 revision 65156) [x86_64-linux]
sam@ubuntu discourse % bin/unicorn
I, [2019-02-21T17:21:45.013068 #12680]  INFO -- : Refreshing Gem list
Starting CSS change watcher

WARNING: Discourse development environment runs slower on Ruby 2.5.3 or below
We recommend you upgrade to Ruby 2.6.1 for the optimal development performance

I, [2019-02-21T17:21:46.552725 #12680]  INFO -- : listening on addr=0.0.0.0:9292 fd=11
Starting up 1 supervised sidekiqs
Loading Sidekiq in process id 12802
I, [2019-02-21T17:21:50.802457 #12829]  INFO -- : worker=0 ready
I, [2019-02-21T17:21:51.082014 #12680]  INFO -- : master process ready
I, [2019-02-21T17:21:51.861961 #12906]  INFO -- : worker=1 ready
I, [2019-02-21T17:21:52.744207 #13036]  INFO -- : worker=2 ready

If you want your dev instance to be performant I recommend upgrading to Ruby 2.6.1.

4 Likes
14

Perfect, working for me now, thanks!

Apologies, I missed this last week. Is this still necessary? Sounds like the bug’s been identified. I was running ruby 2.5.2p104 (2018-10-18 revision 65133) [x86_64-linux].

2 Likes
15

Yeah no need to report anything more, we are all good, hopefully 2.5.4 is released very soon

4 Likes
16

This topic was automatically closed after 7 days. New replies are no longer allowed.