Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Posting List should return error on read #4958

Closed
manishrjain opened this issue Mar 18, 2020 · 4 comments · Fixed by #4966
Closed

Posting List should return error on read #4958

manishrjain opened this issue Mar 18, 2020 · 4 comments · Fixed by #4966
Assignees
Labels
kind/bug Something is broken. priority/P0 Critical issue that requires immediate attention. status/accepted We accept to investigate/work on it.

Comments

@manishrjain
Copy link
Contributor

manishrjain commented Mar 18, 2020

What version of Dgraph are you using?

master

Have you tried reproducing the issue with the latest release?

Yes

What is the hardware spec (RAM, OS)?

Thinkpad Linux

Steps to reproduce the issue (command/config used to run Dgraph).

  1. Go into mrjn/incremental branch.
  2. From compose dir, $ go build . && ./compose -a1 -z1 && ./run.sh
  3. Run dgraph increment --alpha localhost:9180 --num=1000
  4. Pick a log about Rolled up Key
alpha1    | I0318 02:13:30.022581      15 mvcc.go:87] Rolled up Key: 00000b636f756e7465722e76616c000000000000000001. Version: 288. Meta: 08

In this case, the key got rolled up at version 288. Any reads below version 288 should return error.

Expected behaviour and actual result.

$ curl "localhost:8180/query?startTs=287" -XPOST -H 'Content-Type: application/graphql+-' -d '{me(func: has(counter.val)) { uid, counter.val }}'

# As per code:
	if readTs < l.minTs {
		return errors.Errorf("readTs: %d less than minTs: %d for key: %q", readTs, l.minTs, l.key)
	}

But, this query does not return an error. Instead, it does not return counter.val. This is a bug.

Running the same query with startTs=288 does return a valid value.

@manishrjain manishrjain added the kind/bug Something is broken. label Mar 18, 2020
@martinmr
Copy link
Contributor

I ran the debug command with the history flag. This is what I get:

ts: 328 {item}{discard}{complete}
 Uid: 18446744073709551615 Op: 1  Type: INT.  String Value: "162"
 Num uids = 1. Size = 22
 Uid = 18446744073709551615

ts: 326 {item}{delta}
 Uid: 18446744073709551615 Op: 1  Type: INT.  String Value: "161"

ts: 324 {item}{delta}
 Uid: 18446744073709551615 Op: 1  Type: INT.  String Value: "160"

ts: 322 {item}{delta}
 Uid: 18446744073709551615 Op: 1  Type: INT.  String Value: "159"

ts: 320 {item}{delta}
 Uid: 18446744073709551615 Op: 1  Type: INT.  String Value: "158"
...

// continues until the first delta entry setting the count to 1

In my case 328 is the timestamp at which the rollup happen. As you can see there's a discard marker so the earlier versions are ignored.

I think there are two options here:

  1. Do not set the discard marker. This will allow reads below the rollup ts to keep working and it does not affect the reads above because ReadPostingList stops when it sees the first complete posting list. I am not sure how this marker is set or if this is a badger option.

  2. Return an error when reading below the rollup timestamp. There are several reasons why I don't think we should do this.

    • Dgraph supports passing a read timestamp to queries so we should honor this whenever possible. The data is there but it's inaccessible because of the discard marker. It's not like we are saving storage right now since all the data is in there anyways.
    • There is no efficient way to know if we are below the latest rolled up list. When querying with a timestamp below it, we would need to scan the whole list from the latest version until we find the complete posting list and compare that with the requested timestamp. I don't think we are keeping track of the rollup timestamps in a way that would let us do this efficiently.

@manishrjain any thoughts?

@martinmr
Copy link
Contributor

Found the place where the discard is set. I'll try changing the code and seeing what happens with the query that's failing right now.

// SetAt writes a key-value pair at the given timestamp.
func (w *TxnWriter) SetAt(key, val []byte, meta byte, ts uint64) error {
	return w.update(ts, func(txn *badger.Txn) error {
		switch meta {
		case BitCompletePosting, BitEmptyPosting:
			err := txn.SetEntry((&badger.Entry{
				Key:      key,
				Value:    val,
				UserMeta: meta,
			}).WithDiscard())
			if err != nil {
				return err
			}
		default:
			err := txn.SetEntry(&badger.Entry{
				Key:      key,
				Value:    val,
				UserMeta: meta,
			})
			if err != nil {
				return err
			}
		}
		return nil
	})
}

Also, I see that we will save space by only saving one version of the complete list. We are still storing the deltas, though. Do those entries ever get cleaned up?

@manishrjain
Copy link
Contributor Author

As per the original post, we do return an error from posting list when the read is lower than the discard bit. See this:

# As per code:
	if readTs < l.minTs {
		return errors.Errorf("readTs: %d less than minTs: %d for key: %q", readTs, l.minTs, l.key)
	}

martinmr added a commit that referenced this issue Mar 18, 2020
The condition in this case was causing most of the errors to be ignored.
Verified that reading below the minTs throws an error now.

Fixes #4958
@martinmr martinmr added priority/P0 Critical issue that requires immediate attention. status/accepted We accept to investigate/work on it. labels Mar 18, 2020
@manishrjain
Copy link
Contributor Author

Looks like this is the commit which introduced the issue: 78026df7f1

martinmr added a commit that referenced this issue Mar 18, 2020
The error was being ignored and an empty response was being written because the
condition in a case statement didn't exclude errors not equal to nil or ErrNoValue.

This caused reads below the rollup Ts to succeed with an empty response when
they should throw an error. The bug was triggered by running Jepsen tests with
incremental rollups enabled.

Fixes #4958
martinmr added a commit that referenced this issue Mar 18, 2020
The error was being ignored and an empty response was being written because the
condition in a case statement didn't exclude errors not equal to nil or ErrNoValue.

This caused reads below the rollup Ts to succeed with an empty response when
they should throw an error. The bug was triggered by running Jepsen tests with
incremental rollups enabled.

Fixes #4958
martinmr added a commit that referenced this issue Mar 18, 2020
The error was being ignored and an empty response was being written because the
condition in a case statement didn't exclude errors not equal to nil or ErrNoValue.

This caused reads below the rollup Ts to succeed with an empty response when
they should throw an error. The bug was triggered by running Jepsen tests with
incremental rollups enabled.

Fixes #4958
martinmr added a commit that referenced this issue Mar 18, 2020
The error was being ignored and an empty response was being written because the
condition in a case statement didn't exclude errors not equal to nil or ErrNoValue.

This caused reads below the rollup Ts to succeed with an empty response when
they should throw an error. The bug was triggered by running Jepsen tests with
incremental rollups enabled.

Fixes #4958
martinmr added a commit that referenced this issue Mar 18, 2020
The error was being ignored and an empty response was being written because the
condition in a case statement didn't exclude errors not equal to nil or ErrNoValue.

This caused reads below the rollup Ts to succeed with an empty response when
they should throw an error. The bug was triggered by running Jepsen tests with
incremental rollups enabled.

Fixes #4958
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
kind/bug Something is broken. priority/P0 Critical issue that requires immediate attention. status/accepted We accept to investigate/work on it.
Development

Successfully merging a pull request may close this issue.

2 participants