Sled: Unsupported SledError when trying to connect to DB

[raayan]

Howdy! We've been using sled for a project, it's been great so far! It's in a library that's being called out to by FFI on a few clients and things work pretty well. We just compiled our library for a new target (x86_64-apple-ios-macabi for MacOS catalyst stuff) and we're running into the error provided below...

1. sled version
   sled 0.31.0 also tried sled 0.30.3
2. rustc version
   rustc 1.45.0-nightly (f05a52404 2020-05-02)
3. operating system
   MacOS 10.15.4
4. minimal code sample that helps to reproduce the issue
   We're calling sled::open(db_path.as_str())? but that's been working on other platforms
5. logs, panic messages, stack traces

Unsupported("blobs directory contains unparsable path (\"/Users/raayanpillai/Documents/lockbook.sled/blobs/\"): invalid digit found in string")

Seems like it's getting thrown from: https://github.com/spacejam/sled/blob/5fb10c944b26283f7aa6f8cbc457fe8086db308c/src/pagecache/blob_io.rs#L111-L112
and from what I can tell we're trying to parse a string into a number.
If it's any help I notice that on the platforms where sled is working a snap.XXXXXX file gets created inside my sled directory, but it doesn't get created in this instance.

Thanks for any help!

[spacejam]

Interesting, thanks for opening this issue!

sled puts large values into their own file, and it puts those in <sled_dir>/blobs/<sequence number>. When we recover the system, we see if there was a crash which may have caused part of the file to be unrecoverable. If we do, we will then try to delete any blob files with a sequence number higher than the recovered contiguous tip of the log to avoid corrupting stable data that was written before any flush() command returned (this guarantees that data will be recovered after a crash, unless disk corruption happens).

The way we try to find these blob files is by trying to calculate the blob directory, and then using https://doc.rust-lang.org/std/fs/fn.read_dir.html to iterate over blobs we find. In your case, this resulted in the blobs directory itself being listed. So, I've opened #1056 which does 2 things:

1. makes the blob directory calculation more direct
2. is permissive of unexpected names that it may find there

I'm going to merge this into master when tests pass. Could you try running it on a fresh system to see if the same issue happens? Don't run master on an existing database, or it could corrupt the data. When I do a release, I bump the version number, and at runtime sled will not allow an earlier db version to be opened, but this check doesn't work on master because I haven't bumped the version number yet.

[raayan]

hey @spacejam just got around to trying this out. Your changes seem to have resolved that issue, thanks for looking into!

It was able to write (inspected db), but it's having trouble reading. Nothings erroring out, db.get just seems to be coming up empty. The problem doesn't seem to be happening on the other targets.

I'll do some more recon and update back

[raayan]

Alright so seems that it thinks the blobs directory is a file

SledError(Unsupported("provided parent directory is a file, not a directory: \"/Users/raayanpillai/Library/Containers/com.raayanpillai.lockbook-client/Data/Documents/lockbook.sled/blobs\""))

The sled dir looks like this on the (non-working) macabi target:

$ ls -AF
blobs/
conf
db

And on the other targets the directory looks like:

$ ls -AF
blobs/
conf
db
snap.0000000000001147

Not sure what the importance of the snap file not being created is, but I'm going to clone down sled and try to get it to work

[spacejam]

@raayan can you confirm whether this code panics or not?

assert!(!Path::new("/Users/raayanpillai/Library/Containers/com.raayanpillai.lockbook-client/Data/Documents/lockbook.sled/blobs").is_file());

Based on what I can tell, it seems like on your system, it seems as though calling Path::is_file is returning true for the blobs directory. This would indicate a bug in the standard library.

[spacejam]

@raayan I have a feeling this may be a game of whack-a-mole with macos file behavior, which has been problematic in the past (generally a lot of operations that are atomic on most major filesystems are not atomic on macos ones, leading to all kinds of bad behavior that makes using files dangerous).

https://github.com/spacejam/sled/pull/1063 may help, so I'd be curious if running your code against it results in another bug or if this fixes things. Unfortunately I am only able to test on the mac configuration provided by github actions at the moment, which doesn't have issues like what you are experiencing.

[spacejam]

@raayan it's possible that this will result in a few bug reports that we can file against the standard library, because your target is Tier 2 and they don't do any automated testing, so it's likely that we may have hit a bug in the std lib.

[raayan]

@spacejam seems that it doesn't panic on that line and it is recognizing the sled db again, however it's not reading anything out. You're right though, this does seem like a mixed bag and likely unrelated to sled itself. I appreciate the help and will continue to look into this, nail down where the issue is stemming from and hopefully file this is a bug in std.

[spacejam]

@raayan Thank you very much for your continued support with this!

I just pushed a branch that uses the polyfill disk IO impl for ios: https://github.com/spacejam/sled/tree/tyler_exclude_ios_from_unix_parallel_io

Would you be able to see if that runs as expected or not on your system? Please run against a copy of any database instead of something that may be sensitive, because it's possible that this buggy impl is deleting things too. If it still hits problems on this branch, could you include the output of using something like env_logger to output the trace log events that sled is emitting?

[raayan]

@spacejam Of course!

With that branch you just pushed still have the "reading from db" issue. Here's the env_logger stuffs

[2020-05-17T16:43:54Z WARN  sled::config] empty/corrupt configuration file found
[2020-05-17T16:43:54Z DEBUG sled::pagecache::snapshot] no previous snapshot found
[2020-05-17T16:43:54Z DEBUG sled::pagecache::iterator] ordering before clearing tears: {}, max_header_stable_lsn: 0
[2020-05-17T16:43:54Z DEBUG sled::pagecache::iterator] in clean_tail_tears, found missing item in tail: None and we'll scan segments [] above lowest lsn 0
[2020-05-17T16:43:54Z DEBUG sled::pagecache::iterator] filtering out segments after detected tear at lsn 0 lid 0
[2020-05-17T16:43:54Z DEBUG sled::pagecache::segment] segment accountant returning offset: 0 on deck: {}
[2020-05-17T16:43:54Z DEBUG sled::pagecache::iobuf] starting log at clean offset 0, recovered lsn 0
[2020-05-17T16:43:54Z DEBUG sled::pagecache::iobuf] storing lsn 0 in beginning of buffer
[2020-05-17T16:43:54Z DEBUG sled::pagecache::blob_io] gc_blobs removing any blob with an lsn above -1
[2020-05-17T16:43:54Z WARN  sled::pagecache::blob_io] blobs directory contains unparsable path ("/Users/raayanpillai/Library/Containers/com.raayanpillai.lockbook-client/Data/Documents/lockbook.sled/blobs/"): invalid digit found in string
[2020-05-17T16:43:54Z WARN  sled::pagecache::blob_io] blobs directory contains unparsable path ("/Users/raayanpillai/Library/Containers/com.raayanpillai.lockbook-client/Data/Documents/lockbook.sled/blobs/"): invalid digit found in string
[2020-05-17T16:43:54Z DEBUG sled::pagecache] load_snapshot loading pages from 0..0
[2020-05-17T16:43:54Z DEBUG sled::meta] allocated pid 3 for root of new_tree [95, 95, 115, 108, 101, 100, 95, 95, 100, 101, 102, 97, 117, 108, 116]
[2020-05-17T16:43:54Z DEBUG sled::pagecache::iobuf] advancing offset within the current segment from 0 to 96
[2020-05-17T16:43:54Z DEBUG sled::pagecache::iobuf] wrote lsns 0-95 to disk at offsets 0-95, maxed false complete_len 96
[2020-05-17T16:43:54Z DEBUG sled::pagecache::iobuf] mark_interval(0, 96)
[2020-05-17T16:43:54Z DEBUG sled::pagecache::iobuf] new highest interval: 0 - 95
[2020-05-17T16:43:54Z DEBUG sled::meta] allocated pid 5 for root of new_tree [97, 99, 99, 111, 117, 110, 116]
Update metadata failed with error: AccountRetrievalError(AccountMissing(NoneError)) (at this point we have a tree.get() returning a None)
[2020-05-17T16:43:54Z DEBUG sled::pagecache::iobuf] advancing offset within the current segment from 96 to 164
[2020-05-17T16:43:54Z DEBUG sled::pagecache::iobuf] wrote lsns 96-163 to disk at offsets 96-163, maxed false complete_len 68
[2020-05-17T16:43:54Z DEBUG sled::pagecache::iobuf] mark_interval(96, 68)
[2020-05-17T16:43:54Z DEBUG sled::pagecache::iobuf] new highest interval: 96 - 163
[2020-05-17T16:43:54Z DEBUG sled::pagecache::logger] IoBufs dropped

I see it's saying there's a corrupt config. This is on a fresh db doing a sled::open(), tree.insert("you") then a failing with a tree.read("you")

$ cat conf
segment_size: 524288
use_compression: false
version: 0.31
3Ì&º

$ cat db
ˇ∫«ˇˇˇˇˇˇˇÄ?–˚q¢∆x

Î!É°Ò"so


ÀÇ∫ç__sled__defaultfiчHdrP    


@˜◊__sled__defaultaccount≥fp

¯oyou¯h{"username":"someone"}

[spacejam]

This particular error should not happen with the next release due to creating all files up-front, I believe.