segmentation fault

[gingerlime]

Just came across a strange error, and am trying to investigate, but not entirely sure what's causing this.

I can see these in the stdout log (this seems normal, we have plenty of those before without any errors)

resque-pool-manager[kenhub][4772]: Reaped resque worker[30308] (status: 0) queues: analytics,fastspring,mailer,social,statsd,tasks
resque-pool-worker[kenhub][30413]: Starting worker gluteus-medius.kenhub.com:30413:*

and then suddenly in the stderr log

/var/local/kenhub/kenhub.d/35/vendor/bundle/ruby/1.9.1/gems/logging-1.8.1/lib/logging/appenders/buffering.rb:58: [BUG] Segmentation fault
ruby 1.9.3p327 (2012-11-10 revision 37606) [x86_64-linux]
-- Control frame information -----------------------------------------------
c:0043 p:0063 s:0137 b:0135 l:000134 d:000134 METHOD /var/local/kenhub/kenhub.d/35/vendor/bundle/ruby/1.9.1/gems/logging-1.8.1/lib/logging/appenders/buffering.rb:58
c:0042 p:0012 s:0131 b:0131 l:000130 d:000130 METHOD /var/local/kenhub/kenhub.d/35/vendor/bundle/ruby/1.9.1/gems/logging-1.8.1/lib/logging/appenders/email.rb:116
c:0041 p:0011 s:0127 b:0127 l:001b90 d:000126 BLOCK  /var/local/kenhub/kenhub.d/35/vendor/bundle/ruby/1.9.1/gems/logging-1.8.1/lib/logging.rb:504
c:0040 p:---- s:0124 b:0124 l:000123 d:000123 FINISH
c:0039 p:---- s:0122 b:0122 l:000121 d:000121 CFUNC  :each
c:0038 p:0021 s:0119 b:0119 l:000118 d:000118 METHOD /var/local/kenhub/kenhub.d/35/vendor/bundle/ruby/1.9.1/gems/logging-1.8.1/lib/logging/appenders.rb:35
c:0037 p:0049 s:0115 b:0115 l:001b90 d:001b90 METHOD /var/local/kenhub/kenhub.d/35/vendor/bundle/ruby/1.9.1/gems/logging-1.8.1/lib/logging.rb:504
c:0036 p:---- s:0111 b:0111 l:000110 d:000110 FINISH
c:0035 p:---- s:0109 b:0109 l:000108 d:000108 CFUNC  :call
c:0034 p:---- s:0107 b:0107 l:000106 d:000106 CFUNC  :fork
c:0033 p:0024 s:0104 b:0104 l:000103 d:000103 METHOD /var/local/kenhub/kenhub.d/35/vendor/bundle/ruby/1.9.1/gems/resque-pool-0.3.0/lib/resque/pool.rb:321
c:0032 p:0012 s:0098 b:0098 l:000089 d:000097 BLOCK  /var/local/kenhub/kenhub.d/35/vendor/bundle/ruby/1.9.1/gems/resque-pool-0.3.0/lib/resque/pool.rb:300
c:0031 p:---- s:0095 b:0095 l:000094 d:000094 FINISH
c:0030 p:---- s:0093 b:0093 l:000092 d:000092 CFUNC  :times
c:0029 p:0019 s:0090 b:0090 l:000089 d:000089 METHOD /var/local/kenhub/kenhub.d/35/vendor/bundle/ruby/1.9.1/gems/resque-pool-0.3.0/lib/resque/pool.rb:299
c:0028 p:0036 s:0086 b:0086 l:000076 d:000085 BLOCK  /var/local/kenhub/kenhub.d/35/vendor/bundle/ruby/1.9.1/gems/resque-pool-0.3.0/lib/resque/pool.rb:285
c:0027 p:---- s:0082 b:0082 l:000081 d:000081 FINISH
c:0026 p:---- s:0080 b:0080 l:000079 d:000079 CFUNC  :each
c:0025 p:0017 s:0077 b:0077 l:000076 d:000076 METHOD /var/local/kenhub/kenhub.d/35/vendor/bundle/ruby/1.9.1/gems/resque-pool-0.3.0/lib/resque/pool.rb:283
c:0024 p:0065 s:0074 b:0074 l:000066 d:000073 BLOCK  /var/local/kenhub/kenhub.d/35/vendor/bundle/ruby/1.9.1/gems/resque-pool-0.3.0/lib/resque/pool.rb:219
c:0023 p:---- s:0072 b:0072 l:000071 d:000071 FINISH
c:0022 p:---- s:0070 b:0070 l:000069 d:000069 CFUNC  :loop
c:0021 p:0011 s:0067 b:0067 l:000066 d:000066 METHOD /var/local/kenhub/kenhub.d/35/vendor/bundle/ruby/1.9.1/gems/resque-pool-0.3.0/lib/resque/pool.rb:214
c:0020 p:0075 s:0064 b:0064 l:000063 d:000063 METHOD /var/local/kenhub/kenhub.d/35/vendor/bundle/ruby/1.9.1/gems/resque-pool-0.3.0/lib/resque/pool.rb:72
c:0019 p:0029 s:0061 b:0061 l:0013f8 d:000060 BLOCK  /var/local/kenhub/kenhub.d/35/vendor/bundle/ruby/1.9.1/gems/resque-pool-0.3.0/lib/resque/pool/tasks.rb:17
c:0018 p:---- s:0059 b:0059 l:000058 d:000058 FINISH
c:0017 p:---- s:0057 b:0057 l:000056 d:000056 CFUNC  :call
c:0016 p:0043 s:0052 b:0052 l:000043 d:000051 BLOCK  /var/local/kenhub/kenhub.d/35/vendor/bundle/ruby/1.9.1/gems/rake-10.0.4/lib/rake/task.rb:246
c:0015 p:---- s:0049 b:0049 l:000048 d:000048 FINISH
c:0014 p:---- s:0047 b:0047 l:000046 d:000046 CFUNC  :each
c:0013 p:0183 s:0044 b:0044 l:000043 d:000043 METHOD /var/local/kenhub/kenhub.d/35/vendor/bundle/ruby/1.9.1/gems/rake-10.0.4/lib/rake/task.rb:241
c:0012 p:0116 s:0040 b:0040 l:000034 d:000039 BLOCK  /var/local/kenhub/kenhub.d/35/vendor/bundle/ruby/1.9.1/gems/rake-10.0.4/lib/rake/task.rb:184
c:0011 p:0019 s:0038 b:0038 l:000037 d:000037 METHOD /usr/local/bin/ruby-1.9.3-p327/lib/ruby/1.9.1/monitor.rb:211
c:0010 p:0033 s:0035 b:0035 l:000034 d:000034 METHOD /var/local/kenhub/kenhub.d/35/vendor/bundle/ruby/1.9.1/gems/rake-10.0.4/lib/rake/task.rb:177
c:0009 p:0048 s:0028 b:0028 l:000027 d:000027 METHOD /var/local/kenhub/kenhub.d/35/vendor/bundle/ruby/1.9.1/gems/rake-10.0.4/lib/rake/task.rb:170
c:0008 p:0095 s:0023 b:0023 l:000022 d:000022 METHOD /var/local/kenhub/kenhub.d/35/vendor/bundle/ruby/1.9.1/gems/resque-pool-0.3.0/lib/resque/pool/cli.rb:114
c:0007 p:0080 s:0020 b:0020 l:000019 d:000019 METHOD /var/local/kenhub/kenhub.d/35/vendor/bundle/ruby/1.9.1/gems/resque-pool-0.3.0/lib/resque/pool/cli.rb:16
c:0006 p:0059 s:0016 b:0016 l:000015 d:000015 TOP    /var/local/kenhub/kenhub.d/35/vendor/bundle/ruby/1.9.1/gems/resque-pool-0.3.0/bin/resque-pool:7
c:0005 p:---- s:0014 b:0014 l:000013 d:000013 FINISH
c:0004 p:---- s:0012 b:0012 l:000011 d:000011 CFUNC  :load
c:0003 p:0167 s:0008 b:0008 l:0022e8 d:0019d8 EVAL   /var/local/kenhub/kenhub.d/35/vendor/bundle/ruby/1.9.1/bin/resque-pool:23
c:0002 p:---- s:0004 b:0004 l:000003 d:000003 FINISH
c:0001 p:0000 s:0002 b:0002 l:0022e8 d:0022e8 TOP
-- Ruby level backtrace information ----------------------------------------
/var/local/kenhub/kenhub.d/35/vendor/bundle/ruby/1.9.1/bin/resque-pool:23:in `<main>'
/var/local/kenhub/kenhub.d/35/vendor/bundle/ruby/1.9.1/bin/resque-pool:23:in `load'
/var/local/kenhub/kenhub.d/35/vendor/bundle/ruby/1.9.1/gems/resque-pool-0.3.0/bin/resque-pool:7:in `<top (required)>'
/var/local/kenhub/kenhub.d/35/vendor/bundle/ruby/1.9.1/gems/resque-pool-0.3.0/lib/resque/pool/cli.rb:16:in `run'
/var/local/kenhub/kenhub.d/35/vendor/bundle/ruby/1.9.1/gems/resque-pool-0.3.0/lib/resque/pool/cli.rb:114:in `start_pool'
/var/local/kenhub/kenhub.d/35/vendor/bundle/ruby/1.9.1/gems/rake-10.0.4/lib/rake/task.rb:170:in `invoke'
/var/local/kenhub/kenhub.d/35/vendor/bundle/ruby/1.9.1/gems/rake-10.0.4/lib/rake/task.rb:177:in `invoke_with_call_chain'
/usr/local/bin/ruby-1.9.3-p327/lib/ruby/1.9.1/monitor.rb:211:in `mon_synchronize'
/var/local/kenhub/kenhub.d/35/vendor/bundle/ruby/1.9.1/gems/rake-10.0.4/lib/rake/task.rb:184:in `block in invoke_with_call_chain'
/var/local/kenhub/kenhub.d/35/vendor/bundle/ruby/1.9.1/gems/rake-10.0.4/lib/rake/task.rb:241:in `execute'
/var/local/kenhub/kenhub.d/35/vendor/bundle/ruby/1.9.1/gems/rake-10.0.4/lib/rake/task.rb:241:in `each'
/var/local/kenhub/kenhub.d/35/vendor/bundle/ruby/1.9.1/gems/rake-10.0.4/lib/rake/task.rb:246:in `block in execute'
/var/local/kenhub/kenhub.d/35/vendor/bundle/ruby/1.9.1/gems/rake-10.0.4/lib/rake/task.rb:246:in `call'
/var/local/kenhub/kenhub.d/35/vendor/bundle/ruby/1.9.1/gems/resque-pool-0.3.0/lib/resque/pool/tasks.rb:17:in `block (2 levels) in <top (required)>'
/var/local/kenhub/kenhub.d/35/vendor/bundle/ruby/1.9.1/gems/resque-pool-0.3.0/lib/resque/pool.rb:72:in `run'
/var/local/kenhub/kenhub.d/35/vendor/bundle/ruby/1.9.1/gems/resque-pool-0.3.0/lib/resque/pool.rb:214:in `join'
/var/local/kenhub/kenhub.d/35/vendor/bundle/ruby/1.9.1/gems/resque-pool-0.3.0/lib/resque/pool.rb:214:in `loop'
/var/local/kenhub/kenhub.d/35/vendor/bundle/ruby/1.9.1/gems/resque-pool-0.3.0/lib/resque/pool.rb:219:in `block in join'
/var/local/kenhub/kenhub.d/35/vendor/bundle/ruby/1.9.1/gems/resque-pool-0.3.0/lib/resque/pool.rb:283:in `maintain_worker_count'
/var/local/kenhub/kenhub.d/35/vendor/bundle/ruby/1.9.1/gems/resque-pool-0.3.0/lib/resque/pool.rb:283:in `each'
/var/local/kenhub/kenhub.d/35/vendor/bundle/ruby/1.9.1/gems/resque-pool-0.3.0/lib/resque/pool.rb:285:in `block in maintain_worker_count'
/var/local/kenhub/kenhub.d/35/vendor/bundle/ruby/1.9.1/gems/resque-pool-0.3.0/lib/resque/pool.rb:299:in `spawn_missing_workers_for'
/var/local/kenhub/kenhub.d/35/vendor/bundle/ruby/1.9.1/gems/resque-pool-0.3.0/lib/resque/pool.rb:299:in `times'
/var/local/kenhub/kenhub.d/35/vendor/bundle/ruby/1.9.1/gems/resque-pool-0.3.0/lib/resque/pool.rb:300:in `block in spawn_missing_workers_for'
/var/local/kenhub/kenhub.d/35/vendor/bundle/ruby/1.9.1/gems/resque-pool-0.3.0/lib/resque/pool.rb:321:in `spawn_worker!'
/var/local/kenhub/kenhub.d/35/vendor/bundle/ruby/1.9.1/gems/resque-pool-0.3.0/lib/resque/pool.rb:321:in `fork'
/var/local/kenhub/kenhub.d/35/vendor/bundle/ruby/1.9.1/gems/resque-pool-0.3.0/lib/resque/pool.rb:321:in `call'
/var/local/kenhub/kenhub.d/35/vendor/bundle/ruby/1.9.1/gems/logging-1.8.1/lib/logging.rb:504:in `shutdown'
/var/local/kenhub/kenhub.d/35/vendor/bundle/ruby/1.9.1/gems/logging-1.8.1/lib/logging/appenders.rb:35:in `each'
/var/local/kenhub/kenhub.d/35/vendor/bundle/ruby/1.9.1/gems/logging-1.8.1/lib/logging/appenders.rb:35:in `each'
/var/local/kenhub/kenhub.d/35/vendor/bundle/ruby/1.9.1/gems/logging-1.8.1/lib/logging.rb:504:in `block in shutdown'
/var/local/kenhub/kenhub.d/35/vendor/bundle/ruby/1.9.1/gems/logging-1.8.1/lib/logging/appenders/email.rb:116:in `close'
/var/local/kenhub/kenhub.d/35/vendor/bundle/ruby/1.9.1/gems/logging-1.8.1/lib/logging/appenders/buffering.rb:58:in `close'
-- C level backtrace information -------------------------------------------
/usr/local/bin/ruby-1.9.3-p327/lib/libruby.so.1.9(+0x17c795) [0x7f6dbf96f795] vm_dump.c:796
...

Any ideas what might go wrong / where to investigate? Happy to paste a more complete segmentation fault error dump if necessary

[gingerlime]

looks like it might be related to logrotate. I see on the readme some note about sending kill -HUP to help with logroate. Any specific tips/examples on what the logrotate config should look like to play nicely with resque-pool??

EDIT: seeing some more errors like this some time after the log rotation took place, so actually not related to logrotate

[gingerlime]

I noticed this TODO comment, and it seems related to the segmenation fault I'm seeing. The Logger file handlers aren't being closed fully perhaps. The logging gem I'm using has a method to shut itself down, which should be helpful here (but not everybody is using the same logging library). I wonder if there's some kind of a more general-purpose solution?

[jjulian]

I think implementation of #75 might make this issue go away for you. Important: do you have the same issue with Resque's log files?

[gingerlime]

Thanks for the tip @jjulian. Not sure I completely follow though. What do you mean by "Resque's log files" exactly? Things generally go to our production.log file via the logging-rails gem. Resque-pool itself pipes output to stdout / stderr from the (bash) init script

resque-pool -d -a ${app_name} -p ${pidfile} -E ${environment} -o ${stdout_log} -e ${stderr_log}

and we're seeing the segmentation fault error in the stderr file. It started recently for no apparent reason, but we're seeing it more and more frequently. I don't really have a clear way of reproducing this behaviour however, so whatever the workaround / fix - it might be tricky to test...

[jjulian]

I'm wondering if you had the same problem when directing Resque's logger to your own. See https://github.com/resque/resque/wiki/Logging

[gingerlime]

Thanks. I'll take a look.

I'm trying something that might solve this actually (will need some time to let it run...)

The Logging gem has a reopen command, especially for those fork situations. So I've added it in the after_fork block. like this:

task "resque:pool:setup" do
  # close any sockets or files in pool manager
  ActiveRecord::Base.connection.disconnect!
  # and re-open them in the resque worker parent
  Resque::Pool.after_prefork do |job|
    ActiveRecord::Base.establish_connection
    Logging.reopen
  end
end

Will report back later. Thanks again for your help Jonathan.

[gingerlime]

I tried playing around with Resque.logger, but am getting an error trying to assign a logger. Perhaps this feature is only available in Resque 2.0 ?

[1] pry(main)> Resque.logger
=> <Logging::Logger:0x3fbce423a128 name="Resque">
[2] pry(main)> Resque.logger = Logging.logger
NoMethodError: undefined method `logger=' for Resque:Module
from (pry):3:in `<top (required)>'

In any case, Looks like adding Logging.reopen in the after_prefork block resolves this issue :)

Thanks again for the help.

[jjulian]

It looks like the logger accessor was added in Resque 1.23.1

On Saturday, August 10, 2013 at 2:40 AM, gingerlime wrote:

I tried playing around with Resque.logger, but am getting an error trying to assign a logger. Perhaps this feature is only available in Resque 2.0 ?
[1] pry(main)> Resque.logger => <Logging::Logger:0x3fbce423a128 name="Resque"> [2] pry(main)> Resque.logger = Logging.logger NoMethodError: undefined method logger=' for Resque:Module from (pry):3:in<top (required)>'
In any case, Looks like adding Logging.reopen in the after_prefork block resolves this issue :)
Thanks again for the help.

—
Reply to this email directly or view it on GitHub (#80 (comment)).

[gingerlime]

Maybe it's time to upgrade our resque gem anyway? Thanks for the tip.