Deserialization of rdb value failed with error archive_result_t::RANGE_ERROR.

[janih]

I have one node and was inserting data. I don't think it was anything that I havent done many times before. Then I got this:

Version: rethinkdb 1.12.4-0ubuntu1~trusty (GCC 4.8.2)
error: Error in src/rdb_protocol/lazy_json.cc at line 19:
error: Guarantee failed: [res == archive_result_t::SUCCESS] Deserialization of rdb value failed with error archive_result_t::RANGE_ERROR.
error: Backtrace:
addr2line: 'rethinkdb': No such file
error: Sat May 17 02:52:14 2014

       1: backtrace_t::backtrace_t() at 0xf76d30 (rethinkdb)
       2: format_backtrace(bool) at 0xf770c3 (rethinkdb)
       3: report_fatal_error(char const*, int, char const*, ...) at 0xfb0975 (rethinkdb)
       4: get_data(rdb_value_t const*, buf_parent_t) at 0xb7e772 (rethinkdb)
       5: lazy_json_t::get() const at 0xb7e8e4 (rethinkdb)
       6: rget_cb_t::handle_pair(scoped_key_value_t&&, concurrent_traversal_fifo_enforcer_signal_t) at 0xbe0fd5 (rethinkdb)
       7: concurrent_traversal_adapter_t::handle_pair_coro(scoped_key_value_t*, semaphore_acq_t*, fifo_enforcer_write_token_t, auto_drainer_t::lock_t) at 0xc48750 (rethinkdb)
       8: callable_action_instance_t<std::_Bind<std::_Mem_fn<void (concurrent_traversal_adapter_t::*)(scoped_key_value_t*, semaphore_acq_t*, fifo_enforcer_write_token_t, auto_drainer_t::lock_t)> (concurrent_traversal_adapter_t*, scoped_key_value_t*, semaphore_acq_t*, fifo_enforcer_write_token_t, auto_drainer_t::lock_t)> >::run_action() at 0xc48594 (rethinkdb)
       9: coro_t::run() at 0xafb738 (rethinkdb)
error: Exiting.
Trace/breakpoint trap (core dumped)

Runnin on:

3.13.0-24-generic #47-Ubuntu SMP Fri May 2 23:30:00 UTC 2014 x86_64 x86_64 x86_64 GNU/Linux

Lines on dmesg(after a few retries and errors):

[ 1400.697097] traps: rethinkdb[4455] trap int3 ip:b7e785 sp:618bda80 error:0
[ 2156.255800] traps: rethinkdb[6016] trap int3 ip:b7e785 sp:d387a80 error:0
[ 2194.883569] traps: rethinkdb[6995] trap int3 ip:b7e785 sp:61563a80 error:0

I was going to try to dump the database and recreate it but I get a deserialization error while running rethindb dump:

error: Error in src/rdb_protocol/lazy_json.cc at line 19:
error: Guarantee failed: [res == archive_result_t::SUCCESS] Deserialization of rdb value failed with error archive_result_t::SOCK_EOF.
error: Backtrace:
addr2line: 'rethinkdb': No such file
error: Sat May 17 12:40:28 2014

       1: backtrace_t::backtrace_t() at 0xf76d30 (rethinkdb)
       2: format_backtrace(bool) at 0xf770c3 (rethinkdb)
       3: report_fatal_error(char const*, int, char const*, ...) at 0xfb0975 (rethinkdb)
       4: get_data(rdb_value_t const*, buf_parent_t) at 0xb7e772 (rethinkdb)
       5: post_construct_traversal_helper_t::process_a_leaf(buf_lock_t*, btree_key_t const*, btree_key_t const*, signal_t*, int*) at 0xbe55cf (rethinkdb)
       6: process_a_leaf_node(traversal_state_t*, buf_lock_t, int, btree_key_t const*, btree_key_t const*) at 0xc3518b (rethinkdb)
       7: do_a_subtree_traversal_fsm_t::on_node_ready(buf_lock_t) at 0xc3a29e (rethinkdb)
       8: acquire_a_node_fsm_t::you_may_acquire() at 0xc38582 (rethinkdb)
       9: coro_pool_t<acquisition_waiter_callback_t*>::worker_run(acquisition_waiter_callback_t*, auto_drainer_t::lock_t) at 0xc386b8 (rethinkdb)
       10: callable_action_instance_t<std::_Bind<std::_Mem_fn<void (coro_pool_t<acquisition_waiter_callback_t*>::*)(acquisition_waiter_callback_t*, auto_drainer_t::lock_t)> (coro_pool_t<acquisition_waiter_callback_t*>*, acquisition_waiter_callback_t*, auto_drainer_t::lock_t)> >::run_action() at 0xc38932 (rethinkdb)
       11: coro_t::run() at 0xafb738 (rethinkdb)
error: Exiting.
Trace/breakpoint trap (core dumped)

[danielmewes]

Hi @janih, thank you for the issue report.

Do you think you could send us the RethinkDB data directory with the table files for further debugging on our end? If you had important data in the tables, we can also try to recover some of it, though it might not be completely possible.
You can try compressing the data directory and sending it in an email (daniel@rethinkdb.com). If the files are too big, we can arrange an upload page for you.

Another question: Were you running queries using the r.literal() term by any chance? This issue #2399 (comment) has a similar crash message, and could be related (but only if you're using r.literal() in some of your queries).

[janih]

The data directory size is ~375 MB after archiving. Can you provide an upload page?

I haven't used r.literal(), at least not explicitly(I'm using the Java driver). I ran some automated tests against the database and captured the protobuf but didn't notice any use of LITERAL keywords.

[danielmewes]

@mglukhovsky Can you arrange an upload option for @janih ?

[mglukhovsky]

@janih, I'm happy to get that set up for you. Could you email me at mike@rethinkdb.com, so I can prepare a private upload page?

[mglukhovsky]

@danielmewes, the data directory is available on our internal server. Thanks @janih for helping us track this down!

[danielmewes]

@janih I've recovered the faulty table blog_item to a state where it can be read again. If you need the data, I can make a copy available to you.
I wouldn't trust the recovered data though. I found two cases of corruption where 2 and 4 bytes respectively in the table file were overwritten with seemingly random other data. These two were the cases where these corruptions stopped RethinkDB from reading the data. I would expect that some of the actual contents are also corrupted though.

Do you have a chance to run a memory tester on your machine @janih (e.g. Memtest86+ http://www.memtest.org/ )? We will run more tests on our side, because this is obviously a very serious issue. Still I would like to make sure that it wasn't caused by faulty hardware in the first place.

[janih]

Great work, thanks! I would like a copy of the data. I'll run Memtest86+ on the machine, it has 32 GB of ram in four sticks so maybe there is a faulty stick or something.

[janih]

@danielmewes I ran Memtest86+ a couple of times, it didn't find any errors.

[danielmewes]

@janih Thank you for running Memtest. That's very helpful. So we have to assume that this was indeed caused by a bug in RethinkDB.
I would like to reproduce your workload as closely as possible. Since I already have the data, I have only a few remaining questions:

• You said you were inserting data when this happened. Were you inserting one document at a time or using batch inserts?
• Were any other queries running at the same time? If yes, what types of queries? (e.g. something like table().count() ?)

I'll send you an email with information on how to download the recovered data file.

[janih]

@danielmewes I'm inserting documents one at a time to the blog_item table, occasionally update some documents and also do queries like these:

• r.table('blog_item').get('36a4307a-5987-49d6-a2cf-70b486a9bc80')
• r.table('blog_item').getAll('36a4307a-5987-49d6-a2cf-70b486a9bc80', {index: 'feed_id'})
• r.table('blog_item').getAll('cf0c31b6-efe6-4ae3-b383-a94cc5d3feae', {index: "feed_id"}).filter( function(item) {
  return item("link").match("something$")
  })

Here is a couple of other unusual things that I did before this data corruption happened:

• I removed all the leading and trailing whitespace from the text values in blog_item table (= a small piece of code that iterated the table and trimmed and updated documents)
• The previous code had a bug that left a certain field empty after the update. I didn’t have a fresh backup, but I had a backup that was quite new. I didn't just want load the old dump I had so here is what I did:

1. dump the current database to a file
2. drop the database
3. load the old dump and create indices (It is not possible to define the target database name for rethinkdb restore ?)
4. rename the blog_item table to blog_item_old
5. delete the other tables
6. load the dump back that I made in the first step (created indices too)
7. write small piece of code that loads the field from blog_item_old and updates it to the same document in blog_item
8. finally delete blog_item_old table

I hope this is of any help :)

[danielmewes]

@janih Thank you for all the information. It's definitely very helpful!
I will try to replicate that setup and workload.

[janih]

@danielmewes The same error occurred with 1.2.5 version:

Version: rethinkdb 1.12.5-0ubuntu1~trusty (GCC 4.8.2)
error: Error in src/rdb_protocol/lazy_json.cc at line 19:
error: Guarantee failed: [res == archive_result_t::SUCCESS] Deserialization of rdb value failed with error archive_result_t::RANGE_ERROR.
error: Backtrace:
addr2line: 'rethinkdb': No such file
error: Thu May 29 11:19:32 2014

       1: backtrace_t::backtrace_t() at 0xc55360 (rethinkdb)
       2: format_backtrace(bool) at 0xc556f3 (rethinkdb)
       3: report_fatal_error(char const*, int, char const*, ...) at 0xcef315 (rethinkdb)
       4: get_data(rdb_value_t const*, buf_parent_t) at 0xc488b2 (rethinkdb)
       5: lazy_json_t::get() const at 0xc48a24 (rethinkdb)
       6: rget_cb_t::handle_pair(scoped_key_value_t&&, concurrent_traversal_fifo_enforcer_signal_t) at 0xbe8605 (rethinkdb)
       7: concurrent_traversal_adapter_t::handle_pair_coro(scoped_key_value_t*, semaphore_acq_t*, fifo_enforcer_write_token_t, auto_drainer_t::lock_t) at 0xad15d0 (rethinkdb)
       8: callable_action_instance_t<std::_Bind<std::_Mem_fn<void (concurrent_traversal_adapter_t::*)(scoped_key_value_t*, semaphore_acq_t*, fifo_enforcer_write_token_t, auto_drainer_t::lock_t)> (concurrent_traversal_adapter_t*, scoped_key_value_t*, semaphore_acq_t*, fifo_enforcer_write_token_t, auto_drainer_t::lock_t)> >::run_action() at 0xad1414 (rethinkdb)
       9: coro_t::run() at 0xce4d98 (rethinkdb)
error: Exiting.
Trace/breakpoint trap (core dumped)

I was doing the same kind of insert/update queries as I described earlier: #2410 (comment)

[coffeemug]

@janih -- did the second error occur on the same hardware as the first? (I'd like to know for scientific reasons, we're not blaming the bug on the hardware or anything, we're working hard to get to the bottom of it).

[janih]

@coffeemug Yes, same hardware.

[danielmewes]

Thanks for the update @janih. I've had a test case running 24 hours for the past week, with the same RethinkDB binary you are using (and same data), but the bug hasn't shown up yet.
There must be some crucial piece I'm not replicating correctly about your scenario. I will try to improve it and add some more variation.

@janih:
Now that you got the issue again, did you again do any of the special things that you describe here #2410 (comment) (such as importing a complete table, mass-updating a previously empty field)? Or was it just regular inserts, updates and get/getAll/filter queries this time?

Which operating system are you using (Ubuntu 14.04?)?
How many cores does your machine have?
Which file system are the data files on?
Are you using SSDs or rotational hard drives?
Could you also paste the startup log of RethinkDB? Specifically I'm interested in the cache size it's using.
Have you configured any special parameters for RethinkDB?

Thank you so much for sticking with us in debugging this issue @janih!

(Also: Are you on our IRC channel by any chance? (#rethinkdb on Freenode). My name there is "danielmewes". Just in case I have additional questions later...)

[janih]

@danielmewes I made mostly the same things again. But I think I didn't import the complete table this time.

• Operating system is Ubuntu 14.04.
• The machine has 8 cores.
• File system is ext4 on a SSD
• Havent configured any special parameters

Here is the startup log:

info: Running rethinkdb 1.12.5-0ubuntu1~trusty (GCC 4.8.2)...
info: Running on Linux 3.13.0-24-generic x86_64
info: Using cache size of 7568 MB
info: Loading data from directory /home/jani/ohjelmointi/java/rssreader/rethinkdb_data
info: Listening for intracluster connections on port 29015
info: Listening for client driver connections on port 28015
info: Listening for administrative HTTP connections on port 7001
info: Listening on addresses: 127.0.0.1, 127.0.1.1, ::1
info: To fully expose RethinkDB on the network, bind to all addresses
info: by running rethinkdb with the `--bind all` command line option.
info: Server ready
Version: rethinkdb 1.12.5-0ubuntu1~trusty (GCC 4.8.2)
...

I'm not at the IRC chanel, but I'll see if I can join later.

[janih]

@danielmewes I installed RethinkDB on another older machine, restored a dump from a few days back and when the index for blog_item was being built, got this error:

info: Running rethinkdb 1.12.5-0ubuntu1~trusty (GCC 4.8.2)...
info: Running on Linux 3.11.0-12-generic i686
info: Using cache size of 167 MB
info: Loading data from directory /home/jani/ohjelmointi/rssreader/rethinkdb_data
info: Listening for intracluster connections on port 29015
info: Listening for client driver connections on port 28015
info: Listening for administrative HTTP connections on port 7001
info: Listening on addresses: 127.0.0.1, 127.0.1.1, ::1
info: To fully expose RethinkDB on the network, bind to all addresses
info: by running rethinkdb with the `--bind all` command line option.
info: Server ready
Version: rethinkdb 1.12.5-0ubuntu1~trusty (GCC 4.8.2)
error: Error in src/serializer/log/extent_manager.cc at line 24:
error: Guarantee failed: [state_ != state_in_use || extent_use_refcount == 0]
error: Backtrace:
addr2line: 'rethinkdb': No such file
error: Fri May 30 11:33:47 2014

       1: backtrace_t::backtrace_t() at 0x883ea4d (rethinkdb)
       2: format_backtrace(bool) at 0x883edc8 (rethinkdb)
       3: report_fatal_error(char const*, int, char const*, ...) at 0x88f5485 (rethinkdb)
       4: extent_manager_t::gen_extent() at 0x86eb94f (rethinkdb)
       5: data_block_manager_t::gimme_some_new_offsets(std::vector<buf_write_info_t, std::allocator<buf_write_info_t> > const&) at 0x86f6d1b (rethinkdb)
       6: data_block_manager_t::many_writes(std::vector<buf_write_info_t, std::allocator<buf_write_info_t> > const&, file_account_t*, linux_iocallback_t*) at 0x86f73b6 (rethinkdb)
       7: log_serializer_t::block_writes(std::vector<buf_write_info_t, std::allocator<buf_write_info_t> > const&, file_account_t*, linux_iocallback_t*) at 0x870197b (rethinkdb)
       8: merger_serializer_t::block_writes(std::vector<buf_write_info_t, std::allocator<buf_write_info_t> > const&, file_account_t*, linux_iocallback_t*) at 0x86ea481 (rethinkdb)
       9: translator_serializer_t::block_writes(std::vector<buf_write_info_t, std::allocator<buf_write_info_t> > const&, file_account_t*, linux_iocallback_t*) at 0x8705cea (rethinkdb)
       10: alt::page_cache_t::do_flush_changes(alt::page_cache_t*, std::map<unsigned long long, alt::page_cache_t::block_change_t, std::less<unsigned long long>, std::allocator<std::pair<unsigned long long const, alt::page_cache_t::block_change_t> > > const&, fifo_enforcer_write_token_t) at 0x88be2d1 (rethinkdb)
       11: alt::page_cache_t::do_flush_txn_set(alt::page_cache_t*, std::map<unsigned long long, alt::page_cache_t::block_change_t, std::less<unsigned long long>, std::allocator<std::pair<unsigned long long const, alt::page_cache_t::block_change_t> > >*, std::vector<alt::page_txn_t*, std::allocator<alt::page_txn_t*> > const&) at 0x88befd7 (rethinkdb)
       12: callable_action_instance_t<std::_Bind<void (*(alt::page_cache_t*, std::map<unsigned long long, alt::page_cache_t::block_change_t, std::less<unsigned long long>, std::allocator<std::pair<unsigned long long const, alt::page_cache_t::block_change_t> > >*, std::vector<alt::page_txn_t*, std::allocator<alt::page_txn_t*> >))(alt::page_cache_t*, std::map<unsigned long long, alt::page_cache_t::block_change_t, std::less<unsigned long long>, std::allocator<std::pair<unsigned long long const, alt::page_cache_t::block_change_t> > >*, std::vector<alt::page_txn_t*, std::allocator<alt::page_txn_t*> > const&)> >::run_action() at 0x88bf03e (rethinkdb)
       13: coro_t::run() at 0x88ea27d (rethinkdb)
error: Exiting.
Trace/breakpoint trap (core dumped)

I just executed this: irb(main):020:0> r.db('test').table('blog_item').index_create('feed_id').run and left it running (it ran for tens of minutes, the machine is quite slow) and at some point I noticed the error log.

[danielmewes]

@janih First of all thanks for the additional info. The crash on the older machine is interesting. Did you restore the data dump using rethinkdb import?
I know you had already sent us your table files. Is it possible that you can also provide us with the exact data dump that caused the crash on the older machine after importing and creating an index on it?

@mglukhovsky Can you set up another upload page/server for @janih please?

[janih]

@danielmewes I used rethinkdb restore -c localhost:port filename to restore the dump. Sure I can send you the exact same data dump.

[danielmewes]

Thank you @janih for the table dump.
I can reproduce a crash with that. The message I got is error: I/O operation failed. (Unknown error -1536) (offset = 4085604352, count = 45056).

[danielmewes]

Hmm I could get a crash once, but wasn't able to repeat it since then.
This could theoretically be caused by #2500, but that's difficult to test without a reliable way to reproduce the issue.

@janih: If I sent you a modified rethinkdb binary, could you install that and use it instead to see if it works better for you?

[janih]

@danielmewes Yes, I can try the binary. I'm also on #rethinkdb at Freenode, my nick is janih if any additional questions.

[danielmewes]

Sorry, the one crash I got with error: I/O operation failed. (Unknown error -1536) (offset = 4085604352, count = 45056) was actually my VM running out of disk space.

We should really fix #1945 .

[janih]

@danielmewes With the new binary, I got this after running my app for a while:

Version: rethinkdb 1.12.5-16-ge34b8db (GCC 4.8.2)
error: Error in src/rdb_protocol/lazy_json.cc at line 19:
error: Guarantee failed: [res == archive_result_t::SUCCESS] Deserialization of rdb value failed with error archive_result_t::RANGE_ERROR.
error: Backtrace:
error: Thu Jun  5 22:52:36 2014

       1: rethinkdb() [0x48f400] at 0x48f400 ()
       2: rethinkdb() [0x48f793] at 0x48f793 ()
       3: rethinkdb() [0x493b05] at 0x493b05 ()
       4: rethinkdb() [0x882bb2] at 0x882bb2 ()
       5: rethinkdb() [0x882d24] at 0x882d24 ()
       6: rethinkdb() [0x848ea5] at 0x848ea5 ()
       7: rethinkdb() [0x43dfc0] at 0x43dfc0 ()
       8: rethinkdb() [0x43de04] at 0x43de04 ()
       9: rethinkdb() [0x46cf98] at 0x46cf98 ()
error: Exiting.
Trace/breakpoint trap (core dumped)

[danielmewes]

Thanks to @janih 's unit test https://github.com/janih/rethinkdb-junit, I can now reliably reproduce the following two ways of crashing.
The server either crashes with

tcmalloc: large alloc 5060345628524544 bytes == (nil) @ 
rethinkdb: Memory allocation failed. This usually means that we have run out of RAM. Aborting.
Aborted (core dumped)

or with

error: Error in src/serializer/log/data_block_manager.cc at line 1233:
error: Guarantee failed: [gc_state.current_entry == __null] 0x37222c0: 523264 garbage bytes left on the extent, 1024 index-referenced bytes, 0 token-referenced bytes, at offset 524288.

These are reproducible on v1.12.x, but no longer on v1.13.0, and @janih also mentioned that he hadn't seen crashes on 1.13 anymore.

We still have to find out what causes this. I'm currently bisecting between 1.12 and 1.13 to find the change that made this disappear.

[danielmewes]

After further testing, I have to take back the observation that this works on 1.13. I also got the crash on 1.13.
Instead it currently seems like file system mount options are relevant for whether this happens or not...

[danielmewes]

There is a problem that a disk read reads data before it has been written. It's still unclear how that happens in detail.

(edited to remove unreliable work-arounds.)

[janih]

@danielmewes I also got the crash on 1.13.

[danielmewes]

It turns out that on my machine (kernel 3.13.0) ReiserFS, when mounted with the data=journal option, behaves incorrectly.
I could not reproduce the issue on ext4 myself.

I've written a small test program to verify that the file system behaves correctly under direct I/O.
Here is how to run it:

1. Download https://github.com/rethinkdb/rethinkdb/blob/daniel_direct_io_test/test/direct_io_fs_test.cc
2. Compile it: g++ direct_io_fs_test.cc -o direct_io_fs_test
3. Run it: ./direct_io_fs_test <file> where <file> is the path of a test file. <file> is going to be over-written by the program! For example if you want to see if the file system you have mounted in /home behaves correctly, run ./direct_io_fs_test /home/<username>/test_file.tmp. The file will be created automatically. After the program has finished, it can be deleted (it will just contain 32 MB of random data).
4. If the program outputs "Data mismatch", there is a problem with the file system and/or underlying storage hardware. If the program doesn't print anything, there shouldn't be any problem. Note that program execution might take a few minutes.

@janih Can you run that program to see if your server is affected by such a file system / i/o issue?
It also seems that running RethinkDB with --no-direct-io avoids this issue at least on my system.

If you don't have a C++ compiler installed, I can also send you a binary.

[janih]

@danielmewes I was able to compile and run the program. I ran it on my server and two other machines and it didn't output "Data mismatch" on any of them(all have ext4 file systems). I'll try the --no-direct-io switch.

[danielmewes]

I still had no luck in reproducing on any file system other than ReiserFS with data journalling.

Also a late thank you @janih for running the test program. The fact that it passed in your case indicates that there is a different problem than the one that exists on ReiserFS+journalling.
I will send you an email.

How is running with --no-direct-io working out for you so far?

[janih]

I've been using --no-direct-ioswitch for two weeks now and it seems to prevent the error.

[danielmewes]

There's some hope finally: Issue #2840 showed up a corruption issue that was easy to reproduce and for which there is now a fix. See #2840 (comment) onwards.
It is not unlikely that that bug is also behind this issue.

[janih]

Good to hear because I've not been able to reproduce the issue anymore with 1.13.1

[danielmewes]

The fix to #2840 is going to ship with RethinkDB 1.13.4 and 1.14.0.
Closing the issue, since #2840 could well be the same as this and @janih says this isn't happening anymore.

[danielmewes]

Thanks everyone for your patience, and especially @janih for helping a lot with debugging!