Segfault when exception renderer raises on non-internal errors in SFR

[macournoyer]

I don't think it's an urgent issue, because it only happens when an exception is raised from inside the exception renderer, and only the exception is raised from inside this else branch. Raising from anywhere else in the method does not cause a segfault.

So, as long as LiquidExceptionRenderer#track_liquid_unreported_exception does not raise, no segfault should happen.

The issue seems to be that ip is null. But why is it null, and only on that else branch? I don't know.

* thread #1, queue = 'com.apple.main-thread', stop reason = EXC_BAD_ACCESS (code=1, address=0x0)
    frame #0: 0x00000001384a6010 liquid_c.bundle`vm_render_until_error(uncast_args=140732920747216) at vm.c:275:17
   272      args->ip = NULL; // used by vm_render_rescue, NULL to indicate that it isn't in a rescue block
   273
   274      while (true) {
-> 275          switch (*ip++) {
   276              case OP_LEAVE:
   277                  return false;
   278
Target 0: (ruby) stopped.
(lldb) p args->ip
(const uint8_t *) $5 = 0x0000000000000000
(lldb) p args->node_line_number
(const uint8_t *) $6 = 0x0000000000000000
(lldb) p ip
(const uint8_t *) $7 = 0x0000000000000001 ""
(lldb) bt
* thread #1, queue = 'com.apple.main-thread', stop reason = EXC_BAD_ACCESS (code=1, address=0x0)
  * frame #0: 0x00000001391a6010 liquid_c.bundle`vm_render_until_error(uncast_args=140732920747216) at vm.c:275:17
    frame #1: 0x00000001000a71c4 ruby`rb_vrescue2 + 276
    frame #2: 0x00000001000a708b ruby`rb_rescue2 + 123
    frame #3: 0x00000001391a683f liquid_c.bundle`liquid_vm_render(body=0x0000000159375d40, context=4392055680, output=4392745200) at vm.c:544:12
    frame #4: 0x000000013919e197 liquid_c.bundle`block_body_render_to_output_buffer(self=4392639680, context=4392055680, output=4392745200) at block.c:253:5
    frame #5: 0x000000010025b410 ruby`vm_call_cfunc + 368
    frame #6: 0x00000001002410f0 ruby`vm_exec_core + 15104
    frame #7: 0x000000010025624a ruby`rb_vm_exec + 2842
    frame #8: 0x0000000100253b71 ruby`rb_vm_invoke_bmethod + 1985
    frame #9: 0x000000010025bdcc ruby`vm_call_bmethod + 172
    frame #10: 0x000000010025c244 ruby`vm_call_opt_send + 756
    frame #11: 0x00000001002410f0 ruby`vm_exec_core + 15104
    frame #12: 0x000000010025624a ruby`rb_vm_exec + 2842
    frame #13: 0x000000010024ee97 ruby`rb_yield + 167
    frame #14: 0x00000001000038d9 ruby`rb_ary_each + 57
    frame #15: 0x000000010025b410 ruby`vm_call_cfunc + 368
    frame #16: 0x0000000100240f7d ruby`vm_exec_core + 14733
    frame #17: 0x000000010025624a ruby`rb_vm_exec + 2842
    frame #18: 0x000000010024ee97 ruby`rb_yield + 167
    frame #19: 0x0000000100009c72 ruby`rb_ary_collect + 242
    frame #20: 0x000000010025b410 ruby`vm_call_cfunc + 368
    frame #21: 0x0000000100240f7d ruby`vm_exec_core + 14733
    frame #22: 0x000000010025624a ruby`rb_vm_exec + 2842
    frame #23: 0x000000010016e1ef ruby`rb_proc_call + 159
    frame #24: 0x00000001000a9682 ruby`rb_ec_exec_end_proc + 370
    frame #25: 0x00000001000a615f ruby`rb_ec_teardown + 175
    frame #26: 0x00000001000a635e ruby`rb_ec_cleanup + 382
    frame #27: 0x00000001000a665f ruby`ruby_run_node + 95
    frame #28: 0x0000000100000abd ruby`main + 93
    frame #29: 0x00007fff6d915cc9 libdyld.dylib`start + 1
(lldb) expr (void)rb_backtrace()
    from /opt/rubies/2.7.1/lib/ruby/gems/2.7.0/gems/minitest-5.14.2/lib/minitest.rb:68:in `block in autorun'
    from /opt/rubies/2.7.1/lib/ruby/gems/2.7.0/gems/minitest-5.14.2/lib/minitest.rb:141:in `run'
    from /opt/rubies/2.7.1/lib/ruby/gems/2.7.0/gems/minitest-5.14.2/lib/minitest.rb:164:in `__run'
    from /opt/rubies/2.7.1/lib/ruby/gems/2.7.0/gems/minitest-5.14.2/lib/minitest.rb:164:in `map'
    from /opt/rubies/2.7.1/lib/ruby/gems/2.7.0/gems/minitest-5.14.2/lib/minitest.rb:164:in `block in __run'
    from /opt/rubies/2.7.1/lib/ruby/gems/2.7.0/gems/minitest-5.14.2/lib/minitest.rb:326:in `run'
    from /opt/rubies/2.7.1/lib/ruby/gems/2.7.0/gems/minitest-5.14.2/lib/minitest.rb:354:in `with_info_handler'
    from /opt/rubies/2.7.1/lib/ruby/gems/2.7.0/gems/minitest-5.14.2/lib/minitest.rb:367:in `on_signal'
    from /opt/rubies/2.7.1/lib/ruby/gems/2.7.0/gems/minitest-5.14.2/lib/minitest.rb:327:in `block in run'
    from /opt/rubies/2.7.1/lib/ruby/gems/2.7.0/gems/minitest-5.14.2/lib/minitest.rb:327:in `each'
    from /opt/rubies/2.7.1/lib/ruby/gems/2.7.0/gems/minitest-5.14.2/lib/minitest.rb:328:in `block (2 levels) in run'
    from /opt/rubies/2.7.1/lib/ruby/gems/2.7.0/gems/minitest-5.14.2/lib/minitest.rb:341:in `run_one_method'
    from /opt/rubies/2.7.1/lib/ruby/gems/2.7.0/gems/minitest-5.14.2/lib/minitest.rb:1029:in `run_one_method'
    from /Users/ma/.gem/ruby/2.7.1/gems/minitest-reporters-1.4.2/lib/minitest/reporters.rb:48:in `run_with_hooks'
    from /opt/rubies/2.7.1/lib/ruby/gems/2.7.0/gems/minitest-5.14.2/lib/minitest/test.rb:93:in `run'
    from /opt/rubies/2.7.1/lib/ruby/gems/2.7.0/gems/minitest-5.14.2/lib/minitest/test.rb:211:in `with_info_handler'
    from /opt/rubies/2.7.1/lib/ruby/gems/2.7.0/gems/minitest-5.14.2/lib/minitest.rb:367:in `on_signal'
    from /opt/rubies/2.7.1/lib/ruby/gems/2.7.0/gems/minitest-5.14.2/lib/minitest/test.rb:94:in `block in run'
    from /opt/rubies/2.7.1/lib/ruby/gems/2.7.0/gems/minitest-5.14.2/lib/minitest.rb:272:in `time_it'
    from /opt/rubies/2.7.1/lib/ruby/gems/2.7.0/gems/minitest-5.14.2/lib/minitest/test.rb:95:in `block (2 levels) in run'
    from /opt/rubies/2.7.1/lib/ruby/gems/2.7.0/gems/minitest-5.14.2/lib/minitest/test.rb:195:in `capture_exceptions'
    from /opt/rubies/2.7.1/lib/ruby/gems/2.7.0/gems/minitest-5.14.2/lib/minitest/test.rb:98:in `block (3 levels) in run'
    from test/liquid/liquid_renderer_test.rb:191:in `block in <class:LiquidRendererTest>'
    from /Users/ma/src/github.com/Shopify/storefront-renderer/app/liquid/liquid_renderer.rb:99:in `render'
    from /Users/ma/src/github.com/Shopify/storefront-renderer/app/liquid/liquid_renderer.rb:163:in `render_liquid_template'
    from /Users/ma/src/github.com/Shopify/storefront-renderer/app/liquid/liquid_renderer.rb:189:in `instrument'
    from /Users/ma/.gem/ruby/2.7.1/gems/shopify-tracing-0.9.2/lib/shopify/tracing.rb:96:in `trace'
    from /Users/ma/src/github.com/Shopify/storefront-renderer/app/liquid/liquid_renderer.rb:190:in `block in instrument'
    from /opt/rubies/2.7.1/lib/ruby/2.7.0/forwardable.rb:235:in `distribution'
    from /Users/ma/.gem/ruby/2.7.1/gems/statsd-instrument-2.9.2/lib/statsd/instrument/legacy_client.rb:195:in `distribution'
    from /Users/ma/.gem/ruby/2.7.1/gems/statsd-instrument-2.9.2/lib/statsd/instrument/legacy_client.rb:281:in `measure_latency'
    from /Users/ma/src/github.com/Shopify/storefront-renderer/app/liquid/liquid_renderer.rb:191:in `block (2 levels) in instrument'
    from /Users/ma/src/github.com/Shopify/storefront-renderer/app/liquid/liquid_renderer.rb:166:in `block in render_liquid_template'
    from /Users/ma/src/github.com/Shopify/storefront-renderer/app/liquid/liquid_renderer.rb:205:in `render_template'
    from /Users/ma/src/github.com/Shopify/storefront-renderer/app/liquid/null_profiling_strategy.rb:11:in `track_template_render'
    from /Users/ma/src/github.com/Shopify/storefront-renderer/app/liquid/liquid_renderer.rb:207:in `block in render_template'
    from /opt/rubies/2.7.1/lib/ruby/2.7.0/delegate.rb:83:in `method_missing'
    from /Users/ma/.gem/ruby/2.7.1/bundler/gems/liquid-7754d5aef571/lib/liquid/template.rb:194:in `render'
    from /Users/ma/.gem/ruby/2.7.1/bundler/gems/liquid-7754d5aef571/lib/liquid/template.rb:232:in `with_profiling'
    from /Users/ma/.gem/ruby/2.7.1/bundler/gems/liquid-7754d5aef571/lib/liquid/template.rb:195:in `block in render'
    from /Users/ma/.gem/ruby/2.7.1/bundler/gems/liquid-7754d5aef571/lib/liquid/document.rb:41:in `render_to_output_buffer'
    from /Users/ma/.gem/ruby/2.7.1/bundler/gems/liquid-7754d5aef571/lib/liquid/document.rb:41:in `render_to_output_buffer'

I tried reproducing with a test in Liquid-C, but haven't been able to yet, so I'm documenting this issue in case I forget.

[dylanahsmith]

The issue seems to be that ip is null. But why is it null

After an exception is handled, the render_args->ip is used to specify where it should resume from. This is set to NULL outside of rendering a variable compiled into a block body.

Tags aren't yet compiled into the block body VM code, so they are handled by the OP_WRITE_NODE instruction which delegates to Liquid::BlockBody.render_node, which has its own exception handling. Normally the exception will either be handled and rendered by render_node or get re-raised by both render_node and vm_render_rescue. So it looks like this problem is with there being an exception that is (re)raised by render_node but handled by vm_render_rescue.

There is a bug in vm_render_rescue in this unexpected case, where it should re-raise the exception if ip is NULL, rather than relying on Liquid::BlockBody.rescue_render_node to handle this case.

[macournoyer]

Ah so to reproduce, we need to raise from inside a tag body I suppose.

I tried updating my test case to do this, but still can't repro, for ref:

  def test_exception_in_exception_renderer_propagate
    old_exception_renderer = Liquid::Template.default_exception_renderer
    Liquid::Template.default_exception_renderer = ->(e) {
      raise StandardError
    }
    template = Liquid::Template.parse('This is a runtime error: {% if true %}{{ errors.runtime_error }}{% endif %}')

    assert_raises StandardError do
      template.render('errors' => ErrorDrop.new)
    end
  ensure
    Liquid::Template.default_exception_renderer = old_exception_renderer if old_exception_renderer
  end

[dylanahsmith]

To reproduce it, you need the exception renderer to not just raise an exception the first time it is called, but to also render the exception when it is called the second time with the exception raised from the first call to it. I've pushed a regression test to https://github.com/Shopify/liquid-c/pull/116 which reproduces the crash with the corresponding fix reverted.