Segmentation fault in Formatters::Base for async appender

Antsiscool commented 1 year ago

I have been attempting to upgrade a Rails application from Ruby 2.6.10 to 2.7.7 and am receiving a segmentation fault when running cucumber tests on a CI server. The issue does not occur when the same tests are run locally.

Environment

Ruby 2.7.7 (Same issue exists on Ruby 2.7.6)
Semantic Logger Version: 4.12.0 (Same issue exists with 4.11.0)
Rails Semantic Logger: A fork off the latest GitHub commit that removes the Monkey Patch for rails_semantic_logger/extensions/action_dispatch/debug_exceptions
Rails 5.2.8.1
Concurrent-ruby: 1.1.10
Knapsack: 4.0.0
Cucumber: 8.0.0

/var/lib/buildkite-agent/builds/build-server-2022-12-s056-1/myfoodlink-pty-ltd/myfoodlink/vendor/bundle/ruby/2.7.0/gems/semantic_logger-4.12.0/lib/semantic_logger/formatters/base.rb:85: [BUG] Segmentation fault at 0x0000000000000008

ruby 2.7.7p221 (2022-11-24 revision 168ec2b1e5) [x86_64-linux]

-- Control frame information -----------------------------------------------

c:0014 p:---- s:0069 e:000068 CFUNC  :==

c:0013 p:---- s:0066 e:000065 CFUNC  :===

c:0012 p:0052 s:0063 e:000059 METHOD /var/lib/buildkite-agent/builds/build-server-2022-12-s056-1/myfoodlink-pty-ltd/myfoodlink/vendor/bundle/ruby/2.7.0/gems/semanti

c:0011 p:0013 s:0055 e:000054 METHOD /var/lib/buildkite-agent/builds/build-server-2022-12-s056-1/myfoodlink-pty-ltd/myfoodlink/vendor/bundle/ruby/2.7.0/gems/semanti

c:0010 p:0015 s:0051 e:000050 METHOD /var/lib/buildkite-agent/builds/build-server-2022-12-s056-1/myfoodlink-pty-ltd/myfoodlink/vendor/bundle/ruby/2.7.0/gems/semanti

c:0009 p:0021 s:0045 e:000044 METHOD /var/lib/buildkite-agent/builds/build-server-2022-12-s056-1/myfoodlink-pty-ltd/myfoodlink/vendor/bundle/ruby/2.7.0/gems/semanti

c:0008 p:0020 s:0039 e:000038 METHOD /var/lib/buildkite-agent/builds/build-server-2022-12-s056-1/myfoodlink-pty-ltd/myfoodlink/vendor/bundle/ruby/2.7.0/gems/semanti

c:0007 p:0015 s:0031 e:000030 BLOCK  /var/lib/buildkite-agent/builds/build-server-2022-12-s056-1/myfoodlink-pty-ltd/myfoodlink/vendor/bundle/ruby/2.7.0/gems/semanti [FINISH]

c:0006 p:---- s:0026 e:000025 CFUNC  :each

c:0005 p:0004 s:0022 e:000021 METHOD /var/lib/buildkite-agent/builds/build-server-2022-12-s056-1/myfoodlink-pty-ltd/myfoodlink/vendor/bundle/ruby/2.7.0/gems/semanti

c:0004 p:0031 s:0017 e:000016 METHOD /var/lib/buildkite-agent/builds/build-server-2022-12-s056-1/myfoodlink-pty-ltd/myfoodlink/vendor/bundle/ruby/2.7.0/gems/semanti

c:0003 p:0030 s:0011 e:000010 METHOD /var/lib/buildkite-agent/builds/build-server-2022-12-s056-1/myfoodlink-pty-ltd/myfoodlink/vendor/bundle/ruby/2.7.0/gems/semanti

c:0002 p:0004 s:0006 e:000005 BLOCK  /var/lib/buildkite-agent/builds/build-server-2022-12-s056-1/myfoodlink-pty-ltd/myfoodlink/vendor/bundle/ruby/2.7.0/gems/semanti [FINISH]

c:0001 p:---- s:0003 e:000002 (none) [FINISH]

-- Ruby level backtrace information ----------------------------------------

/var/lib/buildkite-agent/builds/build-server-2022-12-s056-1/myfoodlink-pty-ltd/myfoodlink/vendor/bundle/ruby/2.7.0/gems/semantic_logger-4.12.0/lib/semantic_logger/appender/async.rb:63:in `block in reopen'

/var/lib/buildkite-agent/builds/build-server-2022-12-s056-1/myfoodlink-pty-ltd/myfoodlink/vendor/bundle/ruby/2.7.0/gems/semantic_logger-4.12.0/lib/semantic_logger/appender/async.rb:121:in `process'

/var/lib/buildkite-agent/builds/build-server-2022-12-s056-1/myfoodlink-pty-ltd/myfoodlink/vendor/bundle/ruby/2.7.0/gems/semantic_logger-4.12.0/lib/semantic_logger/appender/async.rb:152:in `process_messages'

/var/lib/buildkite-agent/builds/build-server-2022-12-s056-1/myfoodlink-pty-ltd/myfoodlink/vendor/bundle/ruby/2.7.0/gems/semantic_logger-4.12.0/lib/semantic_logger/appenders.rb:30:in `log'

/var/lib/buildkite-agent/builds/build-server-2022-12-s056-1/myfoodlink-pty-ltd/myfoodlink/vendor/bundle/ruby/2.7.0/gems/semantic_logger-4.12.0/lib/semantic_logger/appenders.rb:30:in `each'

/var/lib/buildkite-agent/builds/build-server-2022-12-s056-1/myfoodlink-pty-ltd/myfoodlink/vendor/bundle/ruby/2.7.0/gems/semantic_logger-4.12.0/lib/semantic_logger/appenders.rb:31:in `block in log'

/var/lib/buildkite-agent/builds/build-server-2022-12-s056-1/myfoodlink-pty-ltd/myfoodlink/vendor/bundle/ruby/2.7.0/gems/semantic_logger-4.12.0/lib/semantic_logger/appender/file.rb:188:in `log'

/var/lib/buildkite-agent/builds/build-server-2022-12-s056-1/myfoodlink-pty-ltd/myfoodlink/vendor/bundle/ruby/2.7.0/gems/semantic_logger-4.12.0/lib/semantic_logger/formatters/color.rb:131:in `call'

/var/lib/buildkite-agent/builds/build-server-2022-12-s056-1/myfoodlink-pty-ltd/myfoodlink/vendor/bundle/ruby/2.7.0/gems/semantic_logger-4.12.0/lib/semantic_logger/formatters/default.rb:83:in `call'

/var/lib/buildkite-agent/builds/build-server-2022-12-s056-1/myfoodlink-pty-ltd/myfoodlink/vendor/bundle/ruby/2.7.0/gems/semantic_logger-4.12.0/lib/semantic_logger/formatters/base.rb:61:in `time'

/var/lib/buildkite-agent/builds/build-server-2022-12-s056-1/myfoodlink-pty-ltd/myfoodlink/vendor/bundle/ruby/2.7.0/gems/semantic_logger-4.12.0/lib/semantic_logger/formatters/base.rb:85:in `format_time'

/var/lib/buildkite-agent/builds/build-server-2022-12-s056-1/myfoodlink-pty-ltd/myfoodlink/vendor/bundle/ruby/2.7.0/gems/semantic_logger-4.12.0/lib/semantic_logger/formatters/base.rb:85:in `==='

/var/lib/buildkite-agent/builds/build-server-2022-12-s056-1/myfoodlink-pty-ltd/myfoodlink/vendor/bundle/ruby/2.7.0/gems/semantic_logger-4.12.0/lib/semantic_logger/formatters/base.rb:85:in `=='

-- Machine register context ------------------------------------------------

 RIP: 0x00005625a6ba2aed RBP: 0x0000000000000008 RSP: 0x00007f62639eb3f0

 RAX: 0x0000000000554065 RBX: 0x00005625ae793cc0 RCX: 0x00005625a6ba2a90

 RDX: 0x0000000000000005 RDI: 0x0000000000000008 RSI: 0x00005625ae793cc0

  R8: 0x0000000000000000  R9: 0x0000000000000001 R10: 0x0000000000000000

 R11: 0x0000000000000206 R12: 0x00005625a82d3448 R13: 0x00005625a831f5c0

 R14: 0x0000000000000008 R15: 0x00007f62639eb520 EFL: 0x0000000000010246

-- C level backtrace information -------------------------------------------

/opt/rubies/ruby-2.7.7/bin/ruby(rb_print_backtrace+0x15) [0x5625a6bfb7d5] vm_dump.c:755

/opt/rubies/ruby-2.7.7/bin/ruby(rb_vm_bugreport+0x21b) [0x5625a6bfba0b] vm_dump.c:941

/opt/rubies/ruby-2.7.7/bin/ruby(rb_bug_for_fatal_signal+0xe4) [0x5625a6c79074] error.c:660

/opt/rubies/ruby-2.7.7/bin/ruby(sigsegv+0x4b) [0x5625a6b8085b] signal.c:946

/lib/x86_64-linux-gnu/libpthread.so.0(__restore_rt+0x0) [0x7f626f635390]

/opt/rubies/ruby-2.7.7/bin/ruby(rb_str_equal+0x5d) [0x5625a6ba2aed] string.c:3270

/opt/rubies/ruby-2.7.7/bin/ruby(vm_call0_body+0x24a) [0x5625a6be949a] vm_eval.c:91

/opt/rubies/ruby-2.7.7/bin/ruby(rb_funcallv_with_cc+0xce) [0x5625a6becb0e] vm_eval.c:1013

/opt/rubies/ruby-2.7.7/bin/ruby(rb_equal+0x70) [0x5625a6b0deb0] object.c:139

/opt/rubies/ruby-2.7.7/bin/ruby(vm_call0_body+0x24a) [0x5625a6be949a] vm_eval.c:91

/opt/rubies/ruby-2.7.7/bin/ruby(rb_vm_call0+0xe8) [0x5625a6be9af8] vm_eval.c:52

/opt/rubies/ruby-2.7.7/bin/ruby(check_match+0xcb) [0x5625a6becc7b] vm_insnhelper.c:1807

/opt/rubies/ruby-2.7.7/bin/ruby(vm_exec_core+0x3d7d) [0x5625a6bf1b1d] vm_insnhelper.c:3704

/opt/rubies/ruby-2.7.7/bin/ruby(rb_vm_exec+0xb0) [0x5625a6be5740] vm.c:1929

/opt/rubies/ruby-2.7.7/bin/ruby(rb_yield+0x241) [0x5625a6bf57a1] vm.c:1044

/opt/rubies/ruby-2.7.7/bin/ruby(rb_array_len+0x0) [0x5625a6c056ed] array.c:2135

/opt/rubies/ruby-2.7.7/bin/ruby(rb_ary_each) array.c:2134

/opt/rubies/ruby-2.7.7/bin/ruby(vm_call_cfunc+0x12a) [0x5625a6bdc8da] vm_insnhelper.c:2514

/opt/rubies/ruby-2.7.7/bin/ruby(vm_sendish+0x70) [0x5625a6bd9450] vm_insnhelper.c:4023

/opt/rubies/ruby-2.7.7/bin/ruby(vm_exec_core+0xb30) [0x5625a6bee8d0] insns.def:782

/opt/rubies/ruby-2.7.7/bin/ruby(rb_vm_exec+0xb0) [0x5625a6be5740] vm.c:1929

/opt/rubies/ruby-2.7.7/bin/ruby(rb_vm_invoke_proc+0x271) [0x5625a6be9131] vm.c:1044

/opt/rubies/ruby-2.7.7/bin/ruby(thread_do_start+0x19f) [0x5625a6bb394f] thread.c:692

/opt/rubies/ruby-2.7.7/bin/ruby(thread_start_func_2+0x1fe) [0x5625a6bb3e7e] thread.c:740

/opt/rubies/ruby-2.7.7/bin/ruby(thread_start_func_1+0xa9) [0x5625a6bb4ed9] thread_pthread.c:969

/lib/x86_64-linux-gnu/libpthread.so.0(0x76ba) [0x7f626f62b6ba]

/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d) [0x7f626ea1451d]

Expected Behavior

No seg-fault

Actual Behavior

Cucumber tests always fail. Rspec tests have no issue.

The stack trace always shows it on the comparison with nil in the case statement.

We run our tests with knapsack over multiple CI servers. Different sets of tests fail on different runs of the same commit.

keithrbennett commented 1 year ago

I don't have a reason for the problem, but it looks like the error occurs during the comparison of the appender's log formatter's time formatter object (time_format) with nil. Could you maybe set a time formatter and see if the problem remains? (See the format_time method in ...formatters/base.rb for options.)

Antsiscool commented 1 year ago

I just configured a default formatter with a time format in application.rb. (time_format: :iso_8601). And now all of the cucumber tests have passed.

I may retry the commit a couple of times to see that it continues working.

It seems weird this would fix it, as the default value for time_format is not nil, but a formatting string.

reidmorrison / semantic_logger