Assertion failure
fabio opened this issue · 9 comments
System Information
- OS: Linux 5.10.0-11-amd64 #1 SMP Debian 5.10.92-2 (2022-02-28) x86_64 GNU/Linux
- Ruby: 3.0.1
- Version: 0.7.48
- OpenSSL: None
Description
Frequently get assertion failure:
iodine -bind 192.168.100.110 -port 4050 -workers 1 -log -public public -maxbd 5 -maxhd 5 -ping 60: fiobj_str.c:259: fiobj_str_write: Assertion `FIOBJ_TYPE_IS(dest, FIOBJ_T_STRING)' failed.
Rack App to Reproduce
Can't reproduce.
Do you have any suggestion about where to try to look for to identify the cause of the failure? I can't find any direct relation with the Ruby app code or some specific user action.
Thanks in advance.
-- fabio
Hi Fabio,
I can't reproduce the issue either, however the assertion would fail if:
-
The
FIOBJpointer tagging was overwritten (the first 3 bits of the pointer address are used to identify the type of the data the pointer points to). This could easily happen if there's a memory overflow bug in any C extension (iodineor another). -
The
fiobj_str_writewas called with a non-StringFIOBJtype (a bug in theiodineextension).
Note that the FIOBJ type system is part of the facil.io library that powers iodine, so it is most likely an iodine issue unless some other extension wrote to an arbitrary memory address.
Kindly,
Bo.
Hi Bo,
Still can't reproduce it locally, but we have now more info about last crash in production. The assertion fail after receiving from a WebSocket client frames with unmasked data, with continuation frame inside.
I see this client error condition (sending unmasked data) is properly checked in websocket_consume() function, even if the function continue processing the frame. Do you think returning here would be appropriate?
diff --git a/ext/iodine/websocket_parser.h b/ext/iodine/websocket_parser.h
index a9a6d0d..56c4f06 100644
--- a/ext/iodine/websocket_parser.h
+++ b/ext/iodine/websocket_parser.h
@@ -453,6 +453,7 @@ static uint64_t websocket_consume(void *buffer, uint64_t len, void *udata,
fprintf(stderr, "ERROR: WebSocket protocol error - unmasked data.\n");
#endif
websocket_on_protocol_error(udata);
+ return 0;
}
/* call callback */
switch (pos[0] & 15) {
Kind regards,
-- fabio
Hi @fabio ,
Vary nice catch!
Yes, adding a return statement there will fix an unexpected code path for the callbacks, but I think it would also be better to fix the callbacks themselves.
There's a chance (untested) that there's another way that lead to the same code path, so it's better to fix the callbacks as well...
I'll have a look at this later tonight.
Cheers,
Bo.
Hi @fabio ,
I committed a possible fix for the issue.
However, I want to be sure that the fix performs as expected before releasing a new version. Would you mind testing it, or is that too much to ask for in production?
Thanks!
Bo.
Sure, I'll give it a try.
Cheers,
-- fabio
The fix has already been in production on some servers for 2 days and will progressively be used by all the others. We may take a few more days to confirm that the fix works well with no side effects.
-- fabio
Hi @fabio ,
Thank you so much for the update!
My main concern is that the code path that allocates a continuation-message buffer wasn't tested when I tested for memory leaks - I don't have a good tool to reproduce a multitude of continuation messages on multiple connections... so that's my main concern.
I don't think the assertion will re-appear, and I am sure the buffer should be freed, but that's all theory and isn't tested.
If you don't see memory leaks than I think we're good to release the fix.
Thanks again!
Bo.
Hi @boazsegev,
Yes, in fact, I confirm that at the moment I am not detecting memory problems.
I'm sure the changes you made are OK.
However I have found another problem in one of the servers with the fix.
It is a core dump already reported in the past (issue #100), so it is not related with this fix. Now I've got:
[BUG] Segmentation fault at 0x0000000000000010
ruby 3.0.1p64 (2021-04-05 revision 0fb782ee38) [x86_64-linux]
-- Machine register context ------------------------------------------------
RIP: 0x00007f8c0da6ab51 RBP: 0x0000000000000ab2 RSP: 0x00007f8befdfde20
RAX: 0x00007f8c519504e0 RBX: 0x00000000000704d0 RCX: 0x00007f8c0daea0fc
RDX: 0x0000000000000000 RDI: 0x00000000000ab206 RSI: 0x0000000000000000
R8: 0x0000000000000000 R9: 0x0000564c1613bfe0 R10: 0x0000000000000003
R11: 0x0000000000000000 R12: 0x000000000007053e R13: 0x00000000000ab206
R14: 0x0000000000000000 R15: 0x00007f8befdfe670 EFL: 0x0000000000010246
-- C level backtrace information -------------------------------------------
/home/amc-prod/.rbenv/versions/3.0.1/lib/libruby.so.3.0(rb_print_backtrace+0x11) [0x7f8c11c16a4f] vm_dump.c:758
/home/amc-prod/.rbenv/versions/3.0.1/lib/libruby.so.3.0(rb_vm_bugreport) vm_dump.c:998
/home/amc-prod/.rbenv/versions/3.0.1/lib/libruby.so.3.0(rb_bug_for_fatal_signal+0xf0) [0x7f8c11a40b80] error.c:786
/home/amc-prod/.rbenv/versions/3.0.1/lib/libruby.so.3.0(sigsegv+0x4b) [0x7f8c11b7d99b] signal.c:960
/lib/x86_64-linux-gnu/libpthread.so.0(__restore_rt+0x0) [0x7f8c1194a730]
/home/amc-prod/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/iodine-0.7.49.pre.beta/lib/iodine/iodine.so(fio_flush+0x261) [0x7f8c0da6ab51] fio.c:3692
/home/amc-prod/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/iodine-0.7.49.pre.beta/lib/iodine/iodine.so(fio_flush) (null):0
/home/amc-prod/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/iodine-0.7.49.pre.beta/lib/iodine/iodine.so(fio_flush_all+0x55) [0x7f8c0da6ac55] fio.c:3752
/home/amc-prod/.rbenv/versions/3.0.1/lib/ruby/gems/3.0.0/gems/iodine-0.7.49.pre.beta/lib/iodine/iodine.so(iodine_io_thread+0x3e) [0x7f8c0dac6b3e] iodine_defer.c:38
/lib/x86_64-linux-gnu/libpthread.so.0(0x7fa3) [0x7f8c1193ffa3]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x3f) [0x7f8c116a2eff]
Apart form Iodine version and line numbers, it is the same backtrace reported here: #100 (comment).
If we could fix that too it would be great. I'm trying to figure out how to reproduce it.
Kid Regards,
-- fabio