Thousands of "WARNING: This entry should have been caught." log messages

[markadev]

What version of Go are you using (go version)?

$ go version
go version go1.12.6 linux/amd64

What version of Badger are you using?

master (badger 2.0 prerelease hash a1ff348)

I also have added a few extra log messages in the GC functionality to try to figure out what's going on, but no other changes to the code.

Does this issue reproduce with the latest master?

Yes

What are the hardware specifications of the machine (RAM, OS, Disk)?

SLES 12 Linux (64 bit) VM, 8 GB RAM

What did you do?

I ran a test program that mimics our application's behavior. The test program is just doing some writes, reads, and value log GC. After 10-24 hours, this warning starts showing up.

main.go.txt

What did you expect to see?

I expected the program to run forever with no warning messages.

What did you see instead?

I saw 10's of thousands of warning messages like:

badger 2019/09/06 20:11:59 WARNING: This entry should have been caught. e={Key:[33 98 97 100 103 101 114 33 109 111 118 101 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 48 51 52 53 48 49 57 255 255 255 255 255 255 242 132] Value:[97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97 97] UserMeta:0 ExpiresAt:0 meta:0 offset:1017934987 skipVlog:false hlen:7}, vp={Fid:5 Len:1823 Offset:847085971}

As far as I can tell, this warning message happens when a value log is GC'd and the entry in the LSM tree points to a value in a vlog file before the one being GC'd, which should be theoretically impossible. In this case, it was rewriting vlog fid 14 but the value pointer in the LSM tree for that timestamp was pointing into vlog fid 5. Vlog fid 5 had already been rewritten a few hours earlier.

[manishrjain]

@jarifibrahim please look into this urgently.

[markadev]

I did a little analysis last week so I'll post what I have so far.

In the 2 reproductions I've dug into so far (1.6.0 and master), I saw that the versions and vlog ptr reported in the log statement were retrieved from an entry down in an L2 table and that L2 table was fairly old. The key was also always a !move key, if that makes any difference.

The LSM compaction code caught my eye and I'm wondering if there's an issue keeping track of the "latest" vlog ptr for a version when an entry at a specific version is rewritten with a new vlog ptr. (Because the same version is written with a new value (pointer), you can kind of lose track of which value pointer is the latest one for a specific version of a key)

My best theory on how to reproduce is:

1. Store 'key'@v1 -> FID1
2. GC vlog FID1: creates '!badger!movekey'@v1 -> FID2
3. Compact '!badger!movekey'@v1 down to an L2 sst
4. GC vlog FID2: creates '!badger!movekey'@v1 -> FID3 in the memtable
5. Flush the memtables out to L0

Right now a 'get' of '!badger!movekey'@v1 will return a pointer to vlog FID3 (from L0). All OK. The LSM tree should contain something like:

• L0: '!badger!movekey'@v1 -> FID3
• L2: '!badger!movekey'@v1 -> FID2

6. Store 'key'@v2 -> FID3
7. GC vlog FID3: creates '!badger!movekey'@v1 -> FID4 and '!badger!movekey@V2' -> FID4
8. Flush memtables out to L0

At this point I think the LSM tree will look like:

• L0: '!badger!movekey'@v1 -> FID4
• L0: '!badger!movekey'@v2 -> FID4
• L2: '!badger!movekey'@v1 -> FID2

A get of '!badger!movekey'@v1 will return a pointer into FID4. Still all OK.

9. Compact L0 into L1

Looking at the compaction code, I think it will discard the '!badger!movekey'@v1 in L0 because there's already a newer version and it only keeps the number of versions set in the options struct. In that case, the SSTs will end up with these entries for the movekey:

• L0: none
• L1: '!badger!movekey'@v2 -> FID4
• L2: '!badger!movekey'@v1 -> FID2 (even though vlog FID4 contains the value for V1)

Then when the FID4 rewrite eventually runs, it only finds the older vlog pointer in the LSM tree.

[connorgorman]

@jarifibrahim Any update on this one? Seems pretty rare, but impactful

[jarifibrahim]

Hey @connorgorman I was able to reproduce this issue using the provided script. Interestingly, if I change any of the DB options in that script, the issue is no longer reproducible.
I also noticed that the warnings automatically disappeared after some time ( > 30 hours). I think we could be leaving away stale move keys which are eventually being cleaned up by the compaction (I can't be sure until we have a test for this). The rewrite function performs the lookup for a specific version of the key. A user would never do that. A user would call txn.Get(..) which would always show the latest version. So this issue shouldn't affect the value a user would see.

I'm working on trying to write a test that can reliably reproduce the issue.

• L0: '!badger!movekey'@v1 -> FID4
• L0: '!badger!movekey'@v2 -> FID4
• L2: '!badger!movekey'@v1 -> FID2

A get of '!badger!movekey'@v1 will return a pointer into FID4. Still all OK.

1. Compact L0 into L1

Looking at the compaction code, I think it will discard the '!badger!movekey'@v1 in L0 because there's already a newer version and it only keeps the number of versions set in the options struct. In that case, the SSTs will end up with these entries for the movekey:

@markadev This wouldn't happen because of

badger/levels.go

Lines 554 to 558 in 86a77bb

	} else if hasOverlap {
	// If this key range has overlap with lower levels, then keep the deletion
	// marker with the latest version, discarding the rest. We have set skipKey,
	// so the following key versions would be skipped.
	} else {

If we find a key has overlap which lower levels, we keep the key. We don't remove it.

Also, if a user was to do txn.Get([]byte("key") they would get the latest value for the key which is key@v2 which points to !badger!move!key@2 which would be stored in Level1.

[markadev]

Thanks @jarifibrahim , you're right about the overlap checking.

I also agree that there's not really any functional impact (no data loss or unavailability in this case for sure). In my application I can't have thousands of spurious warning messages clogging up my logs though. For a temporary workaround I think I will just make a local modification to turn the log message into a counter and log the aggregate count.

[jarifibrahim]

@markadev That makes sense, please make a temporary change in the logs. I'll send a PR to fix this as soon as I am able to build a test for it 💭

Since this isn't a data loss or a crash issue, I've reduced its priority to P1.

[stale]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.