[bug] Uptick of seg faults in Nokogiri v1.14.0

[stanhu]

Please describe the bug

We have a CI job that runs a number of rspec jobs. Since upgrading to Nokogiri v1.14.0, we noticed an uptick of seg faults. In this example, it seems that the seg fault happened at the end of the test run (https://gitlab.com/gitlab-org/gitlab/-/jobs/3697213765):

<snip>
Finished in 32 minutes 18 seconds (files took 1 minute 22.6 seconds to load)
330 examples, 0 failures, 3 pending

Randomized with seed 40485

[TEST PROF INFO] Time spent in factories: 03:25.902 (10.43% of total time)
Failed to write to log, write log/workhorse-test.log: file already closed
[BUG] Segmentation fault at 0x0000000000000440
ruby 3.0.5p211 (2022-11-24 revision ba5cf0f7c5) [x86_64-linux]

-- Machine register context ------------------------------------------------
 RIP: 0x00007f5f4f202b03 RBP: 0x00007f5ec252b410 RSP: 0x00007f5ec252b3f0
 RAX: 0x0000000000000000 RBX: 0x00007f5ed6053358 RCX: 0x0000000000000001
 RDX: 0x00007f5f45cb19e0 RDI: 0x00007f5f1593a6a0 RSI: 0x0000000000000000
  R8: 0x00007f5ec252bca8  R9: 0x00007f5eb126f000 R10: 0x00007f5ea93fdca8
 R11: 0x00007f5ec1229ca8 R12: 0x0000000000000000 R13: 0x00007f5f1593a6a0
 R14: 0x0000000000000004 R15: 0x00007f5ec252cc18 EFL: 0x0000000000010206

-- C level backtrace information -------------------------------------------
/usr/local/lib/libruby.so.3.0(rb_print_backtrace+0x11) [0x7f5f4f3df59e] vm_dump.c:758
/usr/local/lib/libruby.so.3.0(rb_vm_bugreport) vm_dump.c:998
/usr/local/lib/libruby.so.3.0(rb_bug_for_fatal_signal+0xf8) [0x7f5f4f1dfb38] error.c:787
/usr/local/lib/libruby.so.3.0(sigsegv+0x55) [0x7f5f4f332645] signal.c:963
/lib/x86_64-linux-gnu/libpthread.so.0(__restore_rt+0x0) [0x7f5f4f0db140]
/usr/local/lib/libruby.so.3.0(ruby_sized_xfree+0xa) [0x7f5f4f202b03] gc.c:10929
/usr/local/lib/libruby.so.3.0(ruby_sized_xfree) gc.c:10926
/builds/gitlab-org/gitlab/vendor/ruby/3.0.0/gems/nokogiri-1.14.1-x86_64-linux/lib/nokogiri/3.0/nokogiri.so(xmlResetError+0x26) [0x7f5f45c48ad6]
/builds/gitlab-org/gitlab/vendor/ruby/3.0.0/gems/nokogiri-1.14.1-x86_64-linux/lib/nokogiri/3.0/nokogiri.so(0x7f5f45cb19f0) [0x7f5f45cb19f0]
/lib/x86_64-linux-gnu/libpthread.so.0(0x7cd1) [0x7f5f4f0cfcd1]
/lib/x86_64-linux-gnu/libpthread.so.0(0x7eba) [0x7f5f4f0cfeba]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x3f) [0x7f5f4eb68a2f]
<snip>

The backtrace suggests nokogiri or libxml2 is calling xmlResetError(): https://github.com/GNOME/libxml2/blob/f507d167f1755b7eaea09fb1a44d29aab828b6d1/error.c#L873-L891.

The Ruby interpreter (v3.0.5) is patched, but gc.c:10929 line corresponds to the objspace_xfree call in https://github.com/ruby/ruby/blob/ba5cf0f7c52d4d35cc6a173c89eda98ceffa2dcf/gc.c#L10909:

void
ruby_sized_xfree(void *x, size_t size)
{
    if (x) {
	objspace_xfree(&rb_objspace, x, size);
    }
}

This might relate to the changes in #2480. I have to wonder if an error is being allocated with malloc instead of ruby_xmalloc.

Help us reproduce what you're seeing

We're not yet sure how to reproduce the seg fault. We're discussing the issue in https://gitlab.com/gitlab-org/gitlab/-/issues/390313.

Expected behavior

No seg faults.

Environment

• Ruby 3.0.5
• Nokogiri v1.14.1 (x86)

# nokogiri -v
# Nokogiri (1.14.1)
    ---
    warnings: []
    nokogiri:
      version: 1.14.1
      cppflags:
      - "-I/usr/local/lib/ruby/gems/3.0.0/gems/nokogiri-1.14.1-x86_64-linux/ext/nokogiri"
      - "-I/usr/local/lib/ruby/gems/3.0.0/gems/nokogiri-1.14.1-x86_64-linux/ext/nokogiri/include"
      - "-I/usr/local/lib/ruby/gems/3.0.0/gems/nokogiri-1.14.1-x86_64-linux/ext/nokogiri/include/libxml2"
      ldflags: []
    ruby:
      version: 3.0.5
      platform: x86_64-linux
      gem_platform: x86_64-linux
      description: ruby 3.0.5p211 (2022-11-24 revision ba5cf0f7c5) [x86_64-linux]
      engine: ruby
    libxml:
      source: packaged
      precompiled: true
      patches:
      - 0001-Remove-script-macro-support.patch
      - 0002-Update-entities-to-remove-handling-of-ssi.patch
      - 0003-libxml2.la-is-in-top_builddir.patch
      - '0009-allow-wildcard-namespaces.patch'
      libxml2_path: "/usr/local/lib/ruby/gems/3.0.0/gems/nokogiri-1.14.1-x86_64-linux/ext/nokogiri"
      memory_management: ruby
      iconv_enabled: true
      compiled: 2.10.3
      loaded: 2.10.3
    libxslt:
      source: packaged
      precompiled: true
      patches:
      - 0001-update-automake-files-for-arm64.patch
      datetime_enabled: true
      compiled: 1.1.37
      loaded: 1.1.37
    other_libraries:
      zlib: 1.2.13
      libgumbo: 1.0.0-nokogiri

[flavorjones]

Thanks for reporting this, @stanhu! I'll make time to take a look in the next day or two.

[flavorjones]

OK, the likely call stack here is, when the Ruby process is exiting ...

# lldb call stack
  * frame #0: 0x00007ffff35bb610 libxml2.so.2`xmlResetError(err=0x0000555555f29ac8) at error.c:874:1
    frame #1: 0x00007ffff3612962 libxml2.so.2`xmlXPathFreeContext(ctxt=0x0000555555f299e0) at xpath.c:6170:5
    frame #2: 0x00007ffff7c81a5b libruby.so.3.1`finalize_list [inlined] run_final(zombie=140737280155200, objspace=0x000055555555d140) at gc.c:4015:2
    frame #3: 0x00007ffff7c81a4a libruby.so.3.1`finalize_list(objspace=0x000055555555d140, zombie=140737280155200) at gc.c:4034
    frame #4: 0x00007ffff7c86906 libruby.so.3.1`rb_objspace_call_finalizer at gc.c:4198:2
    frame #5: 0x00007ffff7c655b0 libruby.so.3.1`rb_ec_cleanup [inlined] rb_ec_finalize(ec=<unavailable>) at eval.c:164:5
    frame #6: 0x00007ffff7c65586 libruby.so.3.1`rb_ec_cleanup(ec=<unavailable>, ex0=<unavailable>) at eval.c:256
    frame #7: 0x00007ffff7c658f4 libruby.so.3.1`ruby_run_node(n=0x00007ffff3a52710) at eval.c:321:12
    frame #8: 0x000055555555517f ruby`main(argc=<unavailable>, argv=<unavailable>) at main.c:47:9

# gdb call stack
#0  xmlResetError (err=err@entry=0x5555561d0428) at error.c:874
#1  0x00007ffff3612962 in xmlXPathFreeContext (ctxt=0x5555561d0340) at xpath.c:6170
#2  0x00007ffff7c81a5b in run_final (zombie=140737280153880, objspace=0x55555555d140) at gc.c:4015
#3  finalize_list (objspace=objspace@entry=0x55555555d140, zombie=140737280153880) at gc.c:4034
#4  0x00007ffff7c86906 in rb_objspace_call_finalizer (objspace=0x55555555d140) at gc.c:4198
#5  0x00007ffff7c655b0 in rb_ec_finalize (ec=0x55555555d8e0) at vm_core.h:1856
#6  rb_ec_cleanup (ec=ec@entry=0x55555555d8e0, ex0=<optimized out>) at eval.c:256
#7  0x00007ffff7c658f4 in ruby_run_node (n=0x7ffff3a52670) at eval.c:321
#8  0x000055555555517f in main (argc=<optimized out>, argv=<optimized out>) at ./main.c:47

which is essentially a final major GC cycle and XPath query context objects are being swept.

I can't reproduce what you're seeing but it seems like a reasonable guess that it might be the change in #2480? Since I can't reproduce I may need to ask you to do some work here. If you revert that commit (which won't revert cleanly) or alternatively use Nokogiri from, say, 9f080d0, are you able to still see these crashes happening?

(Try bundling with gem 'nokogiri', git: "https://github.com/sparklemotion/nokogiri", ref: "9f080d0d3aaddf3aae439baf259749501860f028")

I'll continue to try to reproduce what you're seeing.

[mttkay]

Thanks @flavorjones ! Another suspicion I had was this commit, which added -O2: ece08bb

This can cause problems with GC when VALUE pointers are optimized away but need to remain on the stack for the GC to see that an object is still alive. These references may now have to be explicitly marked via RB_GC_GUARD: https://docs.ruby-lang.org/en/3.0/extension_rdoc.html#label-Appendix+E.+RB_GC_GUARD+to+protect+from+premature+GC

[flavorjones]

@mttkay Thanks for the suggestion. That is another possibility. Still looking for a repro.

[flavorjones]

@stanhu Can you speak to the nature of the patches you're applying to your version of Ruby? Can you reproduce this with an unpatched version?

[stanhu]

@flavorjones I haven't been able to reproduce the problem myself yet. I'm trying to enable more debug symbols and recompiling Nokogiri to see if we can get more data.

The patches pull in ruby/ruby#3978.

[flavorjones]

@stanhu OK, going to build a Ruby with that patch applied and see if I have better luck reproducing.

[flavorjones]

@stanhu Still unable to reproduce, even when running under valgrind. Could really use some help to pin this down if you're able to do it in your CI environment easily.

[stanhu]

@falvorjones I'm having a hard time reproducing this as well. I'm attempting to add -ggdb3 and -fno-omit-frame-pointer, and the problem hasn't surfaced for me. I'll try dropping these flags to see if that makes a difference. As I recall I've seen some Ruby crashes mysteriously go away with -fno-omit-frame-pointer present, presumably because it might keep the compiler from optimizing away a value on the stack. We might want to consider adding that since it's generally a good flag to have enabled for profiling (https://fedoraproject.org/wiki/Changes/fno-omit-frame-pointer).

[flavorjones]

@stanhu If you can reliably find this in CI, can I ask you to bisect a bit by pinning to commits in your Gemfile? Also, can you confirm that the segfault always happens during process cleanup (and not during runtime)?

[flavorjones]

@stanhu @mttkay were you able to narrow this down at all?