Ruby free invalid pointer

Question

When try to run my Rails application (either by running rake, ./script/console or ./script/server), I get src/tcmalloc.cc:353] Attempt to free invalid pointer or Segmentation fault (depending on if running on REE or MRI). It's been running just fine till yesterday, when with no particular reason (did not install any new gems, did not update any package) it started to happen. I have no clue, what could cause this problem and no idea how to find the root of the problem. GDB output doesn't make much sense to me:

src/tcmalloc.cc:353] Attempt to free invalid pointer: 0x64612d5c6c717379

Program received signal SIGABRT, Aborted.
0x00007ffff6f7ca75 in *__GI_raise (sig=<value optimized out>) at ../nptl/sysdeps/unix/sysv/linux/raise.c:64
64      ../nptl/sysdeps/unix/sysv/linux/raise.c: No such file or directory.
        in ../nptl/sysdeps/unix/sysv/linux/raise.c

backtrace:

#0  0x00007ffff6f7ca75 in *__GI_raise (sig=<value optimized out>) at ../nptl/sysdeps/unix/sysv/linux/raise.c:64
#1  0x00007ffff6f805c0 in *__GI_abort () at abort.c:92
#2  0x00007ffff7ba1729 in TCMalloc_CRASH_internal (dump_stats=false, filename=<value optimized out>, line_number=<value optimized out>, 
    format=0x7ffff7bac498 "Attempt to free invalid pointer: %p\n", ap=0x7fffffff4f90) at src/internal_logging.cc:77
#3  0x00007ffff7ba1865 in TCMalloc_CrashReporter::PrintfAndDie (this=<value optimized out>, format=0xffffffffffffffff <Address 0xffffffffffffffff out of bounds>)
    at src/internal_logging.cc:94
#4  0x00007ffff7b9f230 in InvalidFree (ptr=0x6) at src/tcmalloc.cc:353
#5  0x00007ffff7ba9c88 in do_free_with_callback (ptr=0x64612d5c6c717379) at src/tcmalloc.cc:847
#6  do_free (ptr=0x64612d5c6c717379) at src/tcmalloc.cc:879
#7  tc_free (ptr=0x64612d5c6c717379) at src/tcmalloc.cc:1154
#8  0x00007ffff5fdd747 in syck_free_node (n=0x33ec2a0) at node.c:37
#9  0x00007ffff5fea632 in syck_st_free_nodes (key=<value optimized out>, n=0x6d6d, arg=0x6 <Address 0x6 out of bounds>) at syck.c:203
#10 0x000000000047b0dd in st_foreach (table=0x3400b40, func=0x7ffff5fea620 <syck_st_free_nodes>, arg=0) at st.c:487
#11 0x00007ffff5fea5ce in syck_st_free (p=0x117a820) at syck.c:216
#12 0x00007ffff5feabb8 in syck_free_parser (p=0x117a820) at syck.c:244
#13 0x0000000000432253 in run_final (obj=26178040) at gc.c:2664
#14 0x000000000043227e in finalize_list (p=0x18f71f8) at gc.c:1645
#15 0x0000000000432632 in rb_gc_finalize_deferred () at gc.c:2692
#16 0x00000000004204f0 in rb_thread_schedule () at eval.c:11330
#17 0x0000000000421e75 in eval_check_tick () at eval.c:5755
#18 0x000000000041955e in rb_eval (self=19000480, node=0x1421548) at eval.c:3851
#19 0x0000000000427a0f in eval_call (self=19000480, node=0x14214f8) at eval.c:3376
#20 0x000000000041aaeb in rb_yield_0 (val=18962480, self=19000480, klass=<value optimized out>, flags=<value optimized out>, avalue=0) at eval.c:5239
#21 0x000000000048fd21 in rb_ary_each (ary=19002360) at array.c:1261
#22 0x000000000041c575 in rb_call0 (klass=10283840, recv=19002360, id=4001, oid=<value optimized out>, argc=<value optimized out>, argv=<value optimized out>, body=0x9ce2f8, 
    flags=0) at eval.c:6058
#23 0x000000000041c753 in rb_call (klass=10283840, recv=19002360, mid=4001, argc=0, argv=0x0, scope=0, self=19000480) at eval.c:6308
#24 0x0000000000427a58 in eval_call (self=19000480, node=0x1421a48) at eval.c:3381
#25 0x0000000000426cfb in eval_iter (self=19000480, node=0x1421408) at eval.c:3200
#26 0x000000000041c44b in rb_call0 (klass=19107160, recv=19000480, id=22665, oid=<value optimized out>, argc=0, argv=0x0, body=0x1237d68, flags=0) at eval.c:6211
#27 0x000000000041c753 in rb_call (klass=19107160, recv=19000480, mid=22665, argc=0, argv=0x0, scope=2, self=19000480) at eval.c:6308
#28 0x00000000004196b0 in rb_eval (self=19000480, node=0x1433dd8) at eval.c:4059
#29 0x00000000004195ac in rb_eval (self=19000480, node=0x1433d88) at eval.c:3858
#30 0x000000000041c44b in rb_call0 (klass=19107160, recv=19000480, id=22505, oid=<value optimized out>, argc=0, argv=0x7fffffff6618, body=0x1238718, flags=-39400) at eval.c:6211
#31 0x000000000041c753 in rb_call (klass=19107160, recv=19000480, mid=22505, argc=0, argv=0x7fffffff6618, scope=1, self=6) at eval.c:6308
#32 0x000000000041ce50 in rb_f_send (argc=1, argv=0x7fffffff6610, recv=19000480) at eval.c:6356
#33 0x000000000041c575 in rb_call0 (klass=10348840, recv=19000480, id=4233, oid=<value optimized out>, argc=<value optimized out>, argv=<value optimized out>, body=0x9da300, 
    flags=0) at eval.c:6058
#34 0x000000000041c753 in rb_call (klass=10348840, recv=19000480, mid=4233, argc=1, argv=0x7fffffff6610, scope=0, self=19107160) at eval.c:6308
#35 0x0000000000427a58 in eval_call (self=19107160, node=0x14351d8) at eval.c:3381
#36 0x00000000004195ac in rb_eval (self=19107160, node=0x1435188) at eval.c:3858
#37 0x000000000041c44b in rb_call0 (klass=19106120, recv=19107160, id=5401, oid=<value optimized out>, argc=0, argv=0x0, body=0x12387b8, flags=0) at eval.c:6211
#38 0x000000000041c753 in rb_call (klass=19106120, recv=19107160, mid=5401, argc=0, argv=0x0, scope=0, self=10338960) at eval.c:6308
#39 0x0000000000427a58 in eval_call (self=10338960, node=0x1258c48) at eval.c:3381
#40 0x0000000000426cfb in eval_iter (self=10338960, node=0x1256150) at eval.c:3200
#41 0x00000000004195ac in rb_eval (self=10338960, node=0x1256100) at eval.c:3858
#42 0x000000000042a316 in rb_load (fname=19262960, wrap=<value optimized out>) at eval.c:7199
#43 0x000000000042aaba in rb_require_safe (fname=19262800, safe=<value optimized out>) at eval.c:7573
#44 0x000000000041c575 in rb_call0 (klass=10348880, recv=10338960, id=16705, oid=<value optimized out>, argc=<value optimized out>, argv=<value optimized out>, body=0x9be2e0, 
    flags=0) at eval.c:6058
#45 0x000000000041c753 in rb_call (klass=10348880, recv=10338960, mid=16705, argc=1, argv=0x7fffffff7330, scope=1, self=10338960) at eval.c:6308
#46 0x0000000000427cef in eval_fcall (self=10338960, node=0x9b7c38) at eval.c:3396
#47 0x000000000042712c in eval_rescue (self=10338960, node=0x9b4cb8) at eval.c:3237
#48 0x0000000000419c63 in rb_eval (self=10338960, node=0x9b4cb8) at eval.c:3991
#49 0x000000000041c44b in rb_call0 (klass=10348840, recv=10338960, id=10105, oid=<value optimized out>, argc=0, argv=0x7fffffff8580, body=0x9b3e08, flags=-31360) at eval.c:6211
#50 0x000000000041c753 in rb_call (klass=10348840, recv=10338960, mid=10105, argc=1, argv=0x7fffffff8578, scope=3, self=6) at eval.c:6308

Strace neither:

stat("/home/lotus/development/blip/web/app/serializers/active_support/whiny_nil.rb", 0x7fff80357830) = -1 ENOENT (No such file or directory)
stat("/home/lotus/development/blip/web/app/thrift/gen-rb/active_support/whiny_nil.rb", 0x7fff80357830) = -1 ENOENT (No such file or directory)
stat("/home/lotus/development/blip/web/app/thrift/mappers/active_support/whiny_nil.rb", 0x7fff80357830) = -1 ENOENT (No such file or directory)
stat("/home/lotus/development/blip/web/app/thrift/handlers/active_support/whiny_nil.rb", 0x7fff80357830) = -1 ENOENT (No such file or directory)
stat("/home/lotus/development/blip/web/vendor/rails/railties/active_support/whiny_nil.rb", 0x7fff80357830) = -1 ENOENT (No such file or directory)
stat("/home/lotus/development/blip/web/vendor/rails/railties/lib/active_support/whiny_nil.rb", 0x7fff80357830) = -1 ENOENT (No such file or directory)
stat("/home/lotus/development/blip/web/vendor/rails/activesupport/lib/active_support/whiny_nil.rb", {st_mode=S_IFREG|0644, st_size=2434, ...}) = 0
open("/home/lotus/development/blip/web/vendor/rails/activesupport/lib/active_support/whiny_nil.rb", O_RDONLY) = 4
fstat(4, {st_mode=S_IFREG|0644, st_size=2434, ...}) = 0
close(4)                                = 0
open("/home/lotus/development/blip/web/vendor/rails/activesupport/lib/active_support/whiny_nil.rb", O_RDONLY) = 4
fstat(4, {st_mode=S_IFREG|0644, st_size=2434, ...}) = 0
close(4)                                = 0
open("/home/lotus/development/blip/web/vendor/rails/activesupport/lib/active_support/whiny_nil.rb", O_RDONLY) = 4
close(4)                                = 0
open("/home/lotus/development/blip/web/vendor/rails/activesupport/lib/active_support/whiny_nil.rb", O_RDONLY) = 4
fstat(4, {st_mode=S_IFREG|0644, st_size=2434, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f52cee20000
read(4, "# Extensions to +nil+ which allo"..., 4096) = 2434
read(4, "", 4096)                       = 0
close(4)                                = 0
munmap(0x7f52cee20000, 4096)            = 0
write(2, "src/tcmalloc.cc:353] Attempt to "..., 73src/tcmalloc.cc:353] Attempt to free invalid pointer: 0x64612d5c6c717379
) = 73
rt_sigprocmask(SIG_UNBLOCK, [ABRT], NULL, 8) = 0
tgkill(28023, 28023, SIGABRT)           = 0
--- SIGABRT (Aborted) @ 0 (0) ---
+++ killed by SIGABRT +++

I tried to downgrade gcc and libraries used Ruby native extensions, completely recompiled Ruby, reinstalled Gems, but the problem remains.

Answer 1

This is likely a bug in Ruby (or possibly in YAML::Syck::Node).

Run your program under Valgrind, and send the resulting report to Ruby developers (assuming the bug reproduces with the latest Ruby).

The pointer Ruby tries to free has been stomped on with ASCII: "ysql\-ad"

Answer 2

I encountered this recently with various REE versions on Leopard. Seems to be an issue with the tcmalloc that ships with REE. Recompiling ruby with --no-tcmalloc solved it for me.

If you're using RVM, this means something like:

rvm install ree --ree-options "-c --no-tcmalloc"