-
Notifications
You must be signed in to change notification settings - Fork 3.9k
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
sql: v20.1.0: read table descriptor without ModificationTime with zero MVCC timestamp #49266
Comments
cc @lucy-zhang |
@ajwerner do you know how this might be possible? This is while fetching a referenced table while migrating the FK representation for a table, though I don't see how that would really matter. |
I have literally no clue how this could happen. It only seems possible if the returned KV pair returned a zero-value hlc timestamp. This code path always uses a transaction. In effect, it seems we called |
Also worth noting that this is a mac. We should probably log.Safe some of these arguments. One other thing of note is that this is the same cluster that hit #48786 - it'd be interesting to know what is going on in terms of the state of that cluster. |
@daylerees @davidsbond @rcrowe any chance you observed a panic around this time? I'd love to understand what happened here as it certainly violates my expectations. |
Also surprising to me is that these seem to be the same clusters but the original issue was using a linux binary and this one seems to be using a macOS binary. |
Hi all, our database cluster that was affected by this is using the standard docker image distribution, not 100% sure how we'd end up with a macOS binary. I'm just checking our DB logs to see if it is our cluster |
Grepping through the logs of the cluster that was affected is returning no results. We also restored that database from backup as was suggested |
Is it possible that while we had the same error the sentry report came from a different cluster to our own? |
We seem to finally have a lead on this bug. The problem is that A potential similar problem occurs with The current thinking is that we should stop reading these descriptors directly and instead always go through a |
In the short term, the fix which we can backport is to not enforce this invariant for tables retrieved just for the purpose of this upgrade. |
Something occurred to me that this came up at some point, esp in reference to the changes to expose MVCC timestamps to sql. While testing the proposed fix I figured it might be worth ensuring that the concerning behavior actually happens. I wrote this test and it does not find this zero-timestamp behavior. I ran it both on master and release-20.1. I think we still need to understand where the zero comes from. // TestGetIntentTimestamp tests that a read against an intent returns the value
// with a non-zero timestamp.
func TestGetIntentTimestamp(t *testing.T) {
defer leaktest.AfterTest(t)()
s, _, db := serverutils.StartServer(t, base.TestServerArgs{Insecure: true})
defer s.Stopper().Stop(context.Background())
ctx := context.Background()
require.NoError(t, db.Txn(ctx, func(ctx context.Context, txn *kv.Txn) error {
const key = "aa"
// Using ptpb.Record as a simple proto message.
ptRec := ptpb.Record{ID: uuid.MakeV4()}
if err := txn.Put(context.Background(), key, &ptRec); err != nil {
t.Fatal(err)
}
// Let's ensure that when we read our intent, we read it at a non-zero
// timestamp.
var read ptpb.Record
ts, err := txn.GetProtoTs(ctx, key, &read)
if err != nil {
return err
}
require.NotZero(t, ts)
require.EqualValues(t, ptRec, read)
return nil
}))
} $ go test ./pkg/kv/ --run TestGetIntentTimestamp
ok github.com/cockroachdb/cockroach/pkg/kv 0.093s It's worth noting that this behavior also is not good. It means we'll populate descriptors with ModificationTime as the provisional commit timestamp rather than the real commit timestamp. In practice this is probably fine because we're not ever handing these descriptors out for leases. |
Here's a contrived way to reproduce a zero timestamp, which still seems not too dissimilar to the Replace the call to
to start reading referenced descriptors in GetMutableDescriptorByID . Then the following usually (but not always) causes a panic due to reading a zero timestamp:
Here's the relevant part of the stack trace:
Starting off with 53 -> t1, 54 -> t2, 55 -> t3, the sequence of writes is:
Then we start trying to determine the dependencies of 55 (t3) so we can determine which ones to also truncate, in During |
Alright, the problem is pretty clear now, when reading an intent we don't get a timestamp. I'll write up a patch to fix it. The problem ends up being that we are reading a key we've already written to so avoiding doing the re-lookup would save us but nevertheless, let's just fix the bug. |
Wait, can you clarify what the the difference is between what you just described and the non-repro from earlier? |
Give me a second to post a PR. It has to do with sequence numbers and intent history. |
Before this commit, we'd return a zero-value MVCC timestamp when reading an intent from the intent history. This was problematic because elsewhere in the code we assume that we will always get a non-zero MVCC timestamp when a read returns a value. This is especially bizarre given that a read of the latest intent will return its write timestamp. The semantics here are such that we'll return the timestamp of the MVCC metadata for the row. I think this is the most reasonable thing to do as that timestamp ought to reflect the timestamp we return when we return the current intent and furthermore is the only timestamp we really have around. We could return the transactions current read or write timestamp but those both seem like worse choices. It's also worth noting that in the case where we need to read a non-zero value, we don't really care what that value is and the fact that we are reading this intent itself is somewhat suspect. That being said, I still think we should make this change in addition to any change made to prevent the code referenced in cockroachdb#49266 from needing it. Fixes cockroachdb#49266. Informs cockroachdb#50102. Release note: None
See #52358. |
Before this commit, we'd return a zero-value MVCC timestamp when reading an intent from the intent history. This was problematic because elsewhere in the code we assume that we will always get a non-zero MVCC timestamp when a read returns a value. This is especially bizarre given that a read of the latest intent will return its write timestamp. The semantics here are such that we'll return the timestamp of the MVCC metadata for the row. I think this is the most reasonable thing to do as that timestamp ought to reflect the timestamp we return when we return the current intent and furthermore is the only timestamp we really have around. We could return the transactions current read or write timestamp but those both seem like worse choices. It's also worth noting that in the case where we need to read a non-zero value, we don't really care what that value is and the fact that we are reading this intent itself is somewhat suspect. That being said, I still think we should make this change in addition to any change made to prevent the code referenced in cockroachdb#49266 from needing it. Fixes cockroachdb#49266. Informs cockroachdb#50102. Release note: None
48842: sql: fix portals after exhausting rows r=yuzefovich a=yuzefovich Previously, we would erroneously restart the execution from the very beginning of empty, unclosed portals after they have been fully exhausted when we should be returning no rows or an error in such scenarios. This is now fixed by tracking whether a portal is exhausted or not and intercepting the calls to `execStmt` when the conn executor state machine is in an open state. Note that the current solution has known deviations from Postgres: - when attempting to execute portals of statements that don't return row sets, on the second and consequent attempt PG returns an error while we are silently doing nothing (meaning we do not run the statement at all and return 0 rows) - we incorrectly populate "command tag" field of pgwire messages of some rows-returning statements after the portal suspension (for example, a suspended UPDATE RETURNING in PG will return the total count of "rows affected" while we will return the count since the last suspension). These deviations are deemed acceptable since this commit fixes a much worse problem - re-executing an exhausted portal (which could be a mutation meaning, previously, we could have executed a mutation multiple times). The reasons for why this commit does not address these deviations are: - Postgres has a concept of "portal strategy" (see https://github.com/postgres/postgres/blob/2f9661311b83dc481fc19f6e3bda015392010a40/src/include/utils/portal.h#L89). - Postgres has a concept of "command" type (these are things like SELECTs, UPDATEs, INSERTs, etc, see https://github.com/postgres/postgres/blob/1aac32df89eb19949050f6f27c268122833ad036/src/include/nodes/nodes.h#L672). CRDB doesn't have these concepts, and without them any attempt to simulate Postgres results in a very error-prone and brittle code. Fixes: #48448. Release note (bug fix): Previously, CockroachDB would erroneously restart the execution of empty, unclosed portals after they have been fully exhausted, and this has been fixed. 52098: sql: better distribute distinct processors r=yuzefovich a=yuzefovich **sql: better distribute distinct processors** The distinct processors are planned in two stages - first, a "local" stage is planned on the same nodes as the previous stage, then, a "global" stage is added. Previously, the global stage would be planned on the gateway, and this commit changes that to make it distributed - by planning "global" distinct processors on the same nodes as the "local" ones and connecting them via a hash router hashing the distinct columns. Release note: None **sql: implement ConstructDistinct in the new factory** Addresses: #47473. Release note: None 52358: engine: set the MVCC timestamp on reads due to historical intents r=ajwerner a=ajwerner Before this commit, we'd return a zero-value MVCC timestamp when reading an intent from the intent history. This was problematic because elsewhere in the code we assume that we will always get a non-zero MVCC timestamp when a read returns a value. This is especially bizarre given that a read of the latest intent will return its write timestamp. The semantics here are such that we'll return the timestamp of the MVCC metadata for the row. I think this is the most reasonable thing to do as that timestamp ought to reflect the timestamp we return when we return the current intent and furthermore is the only timestamp we really have around. We could return the transactions current read or write timestamp but those both seem like worse choices. It's also worth noting that in the case where we need to read a non-zero value, we don't really care what that value is and the fact that we are reading this intent itself is somewhat suspect. That being said, I still think we should make this change in addition to any change made to prevent the code referenced in #49266 from needing it. Fixes #49266. Informs #50102. Release note: None 52384: sql: properly reset extraTxnState in COPY r=ajwerner a=ajwerner Apparently we support some sort of COPY protocol that I know nothing about. We allow operations in that protocol in the open state and in the noTxn state in the connExecutor. In the noTxn state we let the `copyMachine` handle its transaction lifecycle all on its own. In that case, we also hand have the `connExecutor` in a fresh state when calling `execCopyIn()`. During the execution of `COPY`, it seems like sometime we can pick up table descriptor leases. In the noTxn case we'd like to drop those leases and generally leave the executor in the fresh state in which it was handed to us. To deal with that, we call `resetExtraTxnState` before returning in the happy noTxn case. Fixes #52065. Release note (bug fix): Fixed a bug when using the COPY protocol which could prevent schema changes for up to 5 minutes. Co-authored-by: Yahor Yuzefovich <[email protected]> Co-authored-by: Andrew Werner <[email protected]>
Before this commit, we'd return a zero-value MVCC timestamp when reading an intent from the intent history. This was problematic because elsewhere in the code we assume that we will always get a non-zero MVCC timestamp when a read returns a value. This is especially bizarre given that a read of the latest intent will return its write timestamp. The semantics here are such that we'll return the timestamp of the MVCC metadata for the row. I think this is the most reasonable thing to do as that timestamp ought to reflect the timestamp we return when we return the current intent and furthermore is the only timestamp we really have around. We could return the transactions current read or write timestamp but those both seem like worse choices. It's also worth noting that in the case where we need to read a non-zero value, we don't really care what that value is and the fact that we are reading this intent itself is somewhat suspect. That being said, I still think we should make this change in addition to any change made to prevent the code referenced in cockroachdb#49266 from needing it. Fixes cockroachdb#49266. Informs cockroachdb#50102. Release note: None
Before this commit, we'd return a zero-value MVCC timestamp when reading an intent from the intent history. This was problematic because elsewhere in the code we assume that we will always get a non-zero MVCC timestamp when a read returns a value. This is especially bizarre given that a read of the latest intent will return its write timestamp. The semantics here are such that we'll return the timestamp of the MVCC metadata for the row. I think this is the most reasonable thing to do as that timestamp ought to reflect the timestamp we return when we return the current intent and furthermore is the only timestamp we really have around. We could return the transactions current read or write timestamp but those both seem like worse choices. It's also worth noting that in the case where we need to read a non-zero value, we don't really care what that value is and the fact that we are reading this intent itself is somewhat suspect. That being said, I still think we should make this change in addition to any change made to prevent the code referenced in cockroachdb#49266 from needing it. Fixes cockroachdb#49266. Informs cockroachdb#50102. Release note: None
This issue was autofiled by Sentry. It represents a crash or reported error on a live cluster with telemetry enabled.
Sentry link: https://sentry.io/organizations/cockroach-labs/issues/1675228652/?referrer=webhooks_plugin
Panic message:
Stacktrace (expand for inline code snippets):
cockroach/pkg/sql/sqlbase/structured.go
Lines 3477 to 3479 in 9d456b9
cockroach/pkg/sql/sqlbase/structured.go
Lines 407 to 409 in 9d456b9
cockroach/pkg/sql/sqlbase/structured.go
Lines 988 to 990 in 9d456b9
cockroach/pkg/sql/sqlbase/structured.go
Lines 955 to 957 in 9d456b9
cockroach/pkg/sql/sqlbase/structured.go
Lines 892 to 894 in 9d456b9
cockroach/pkg/sql/sqlbase/structured.go
Lines 365 to 367 in 9d456b9
cockroach/pkg/sql/sqlbase/structured.go
Lines 421 to 423 in 9d456b9
cockroach/pkg/sql/table.go
Lines 480 to 482 in 9d456b9
cockroach/pkg/sql/drop_table.go
Lines 489 to 491 in 9d456b9
cockroach/pkg/sql/drop_table.go
Lines 251 to 253 in 9d456b9
cockroach/pkg/sql/drop_database.go
Lines 196 to 198 in 9d456b9
cockroach/pkg/sql/plan.go
Lines 394 to 396 in 9d456b9
cockroach/pkg/sql/walk.go
Lines 143 to 145 in 9d456b9
cockroach/pkg/sql/walk.go
Lines 720 to 722 in 9d456b9
cockroach/pkg/sql/walk.go
Lines 110 to 112 in 9d456b9
cockroach/pkg/sql/walk.go
Lines 74 to 76 in 9d456b9
cockroach/pkg/sql/plan.go
Lines 397 to 399 in 9d456b9
cockroach/pkg/sql/plan_node_to_row_source.go
Lines 116 to 118 in 9d456b9
cockroach/pkg/sql/execinfra/processorsbase.go
Lines 747 to 749 in 9d456b9
cockroach/pkg/sql/flowinfra/flow.go
Lines 369 to 371 in 9d456b9
cockroach/pkg/sql/distsql_running.go
Lines 404 to 406 in 9d456b9
cockroach/pkg/sql/distsql_running.go
Lines 1018 to 1020 in 9d456b9
cockroach/pkg/sql/conn_executor_exec.go
Lines 882 to 884 in 9d456b9
cockroach/pkg/sql/conn_executor_exec.go
Lines 775 to 777 in 9d456b9
cockroach/pkg/sql/conn_executor_exec.go
Lines 480 to 482 in 9d456b9
cockroach/pkg/sql/conn_executor_exec.go
Lines 95 to 97 in 9d456b9
cockroach/pkg/sql/conn_executor.go
Lines 1367 to 1369 in 9d456b9
cockroach/pkg/sql/conn_executor.go
Lines 1296 to 1298 in 9d456b9
cockroach/pkg/sql/conn_executor.go
Lines 475 to 477 in 9d456b9
cockroach/pkg/sql/pgwire/conn.go
Lines 589 to 591 in 9d456b9
v20.1.0
go1.13.9
The text was updated successfully, but these errors were encountered: