cockroachdb / cockroach

CockroachDB — the cloud native, distributed SQL database designed for high availability, effortless scale, and control over data placement.
https://www.cockroachlabs.com
Other
30.16k stars 3.82k forks source link

crosscluster/physical: prepared statement evaluation fails in read from standby workload #135829

Open msbutler opened 1 day ago

msbutler commented 1 day ago

If I attempt to start a workload on a read only standby cluster, the workload logs return log messages which suggest prepared statement evaluation failed:

W241120 14:45:36.803837 230 workload/pgx_helpers.go:235  [-] 6  error preparing statement. name=kv-2 sql=SELECT k, v FROM kv AS OF SYSTEM TIME follower_read_timestamp() WHERE k IN ($1) ERROR: relation "kv" does not exist (SQLSTATE 42P01)
W241120 14:45:36.803837 187 workload/pgx_helpers.go:235  [-] 7  error preparing statement. name=kv-2 sql=SELECT k, v FROM kv AS OF SYSTEM TIME follower_read_timestamp() WHERE k IN ($1) ERROR: relation "kv" does not exist (SQLSTATE 42P01)
W241120 14:45:36.806227 228 workload/pgx_helpers.go:235  [-] 8  error preparing statement. name=kv-2 sql=SELECT k, v FROM kv AS OF SYSTEM TIME follower_read_timestamp() WHERE k IN ($1) ERROR: relation "kv" does not exist (SQLSTATE 42P01)
W241120 14:45:36.810050 188 workload/pgx_helpers.go:235  [-] 9  error preparing statement. name=kv-5 sql=DELETE FROM kv WHERE k IN ($1) ERROR: cannot mutate materialized view "kv" (SQLSTATE 42809)
W241120 14:45:36.810135 226 workload/pgx_helpers.go:235  [-] 10  error preparing statement. name=kv-5 sql=DELETE FROM kv WHERE k IN ($1) ERROR: cannot mutate materialized view "kv" (SQLSTATE 42809)
W241120 14:45:36.811199 190 workload/pgx_helpers.go:235  [-] 11  error preparing statement. name=kv-3 sql=UPSERT INTO kv (k, v) VALUES ($1, $2) ERROR: cannot mutate materialized view "kv" (SQLSTATE 42809)
W241120 14:45:36.811606 228 workload/pgx_helpers.go:235  [-] 12  error preparing statement. name=kv-5 sql=DELETE FROM kv WHERE k IN ($1) ERROR: cannot mutate materialized view "kv" (SQLSTATE 42809)
W241120 14:45:36.812236 193 workload/pgx_helpers.go:235  [-] 13  error preparing statement. name=kv-5 sql=DELETE FROM kv WHERE k IN ($1) ERROR: cannot mutate materialized view "kv" (SQLSTATE 42809)

In addition, the cockroach log stacks below suggest the sql authentication checks are failing on the standby workload. It's unclear if these checks are firing during prepared statement evaluation.

The stack below suggests that GetUserSessionInitInfo is hitting this assertion failure https://github.com/msbutler/cockroach/blob/butler-public-disk-full/pkg/sql/catalog/descs/leased_descriptors.go#L154

Which implies that this GetUserSessionInitInfo func has a connExecutor not using a historical queries, as enforced by [this PR](https://github.com/cockroachdb/cockroach/commit/6c361b9a9a526bd9bacb9a7cc41b2bbb92e51899#diff-e10255c339480f882118842fb00bc6a10857be5bf2aa1bf09a1fd5f8ace7bd44).

I can also see in the stack trace that the a cache is being used to retrieve session data, so perhaps this cache was hydrated without historical queries.

Other notes:

W241120 14:46:22.527772 107414 sql/pgwire/auth.go:161 ⋮ [T4,Vdestination-tenant-readonly,n3,client=10.142.0.177:48093,hostssl,user=‹roachprod›] 340  user retrieval failed for user=‹"roachprod"›: internal error while retrieving user account memberships: internal error while retrieving user account: get auth info error: PCR reader timestamp has moved forward, existing descriptor ‹role_options›(33) and timestamp: 1732113915.000000000,0 new descritpor ‹users›(4) and timestamp: 1732113960.000000000,0
W241120 14:46:22.527772 107414 sql/pgwire/auth.go:161 ⋮ [T4,Vdestination-tenant-readonly,n3,client=10.142.0.177:48093,hostssl,user=‹roachprod›] 340 +(1) attached stack trace
W241120 14:46:22.527772 107414 sql/pgwire/auth.go:161 ⋮ [T4,Vdestination-tenant-readonly,n3,client=10.142.0.177:48093,hostssl,user=‹roachprod›] 340 +  -- stack trace:
W241120 14:46:22.527772 107414 sql/pgwire/auth.go:161 ⋮ [T4,Vdestination-tenant-readonly,n3,client=10.142.0.177:48093,hostssl,user=‹roachprod›] 340 +  | github.com/cockroachdb/cockroach/pkg/sql.GetUserSessionInitInfo
W241120 14:46:22.527772 107414 sql/pgwire/auth.go:161 ⋮ [T4,Vdestination-tenant-readonly,n3,client=10.142.0.177:48093,hostssl,user=‹roachprod›] 340 +  |        pkg/sql/user.go:197
W241120 14:46:22.527772 107414 sql/pgwire/auth.go:161 ⋮ [T4,Vdestination-tenant-readonly,n3,client=10.142.0.177:48093,hostssl,user=‹roachprod›] 340 +  | github.com/cockroachdb/cockroach/pkg/sql/pgwire.(*conn).handleAuthentication
W241120 14:46:22.527772 107414 sql/pgwire/auth.go:161 ⋮ [T4,Vdestination-tenant-readonly,n3,client=10.142.0.177:48093,hostssl,user=‹roachprod›] 340 +  |        pkg/sql/pgwire/auth.go:154
W241120 14:46:22.527772 107414 sql/pgwire/auth.go:161 ⋮ [T4,Vdestination-tenant-readonly,n3,client=10.142.0.177:48093,hostssl,user=‹roachprod›] 340 +  | github.com/cockroachdb/cockroach/pkg/sql/pgwire.(*conn).processCommands
W241120 14:46:22.527772 107414 sql/pgwire/auth.go:161 ⋮ [T4,Vdestination-tenant-readonly,n3,client=10.142.0.177:48093,hostssl,user=‹roachprod›] 340 +  |        pkg/sql/pgwire/conn.go:203
W241120 14:46:22.527772 107414 sql/pgwire/auth.go:161 ⋮ [T4,Vdestination-tenant-readonly,n3,client=10.142.0.177:48093,hostssl,user=‹roachprod›] 340 +  | github.com/cockroachdb/cockroach/pkg/sql/pgwire.(*Server).serveImpl.func4
W241120 14:46:22.527772 107414 sql/pgwire/auth.go:161 ⋮ [T4,Vdestination-tenant-readonly,n3,client=10.142.0.177:48093,hostssl,user=‹roachprod›] 340 +  |        pkg/sql/pgwire/server.go:1196
W241120 14:46:22.527772 107414 sql/pgwire/auth.go:161 ⋮ [T4,Vdestination-tenant-readonly,n3,client=10.142.0.177:48093,hostssl,user=‹roachprod›] 340 +  | runtime.goexit
W241120 14:46:22.527772 107414 sql/pgwire/auth.go:161 ⋮ [T4,Vdestination-tenant-readonly,n3,client=10.142.0.177:48093,hostssl,user=‹roachprod›] 340 +  |        src/runtime/asm_amd64.s:1695
W241120 14:46:22.527772 107414 sql/pgwire/auth.go:161 ⋮ [T4,Vdestination-tenant-readonly,n3,client=10.142.0.177:48093,hostssl,user=‹roachprod›] 340 +Wraps: (2) internal error while retrieving user account memberships
W241120 14:46:22.527772 107414 sql/pgwire/auth.go:161 ⋮ [T4,Vdestination-tenant-readonly,n3,client=10.142.0.177:48093,hostssl,user=‹roachprod›] 340 +Wraps: (3) internal error while retrieving user account: get auth info error: PCR reader timestamp has moved forward, existing descriptor ‹role_options›(33) and timestamp: 1732113915.000000000,0 new descritpor ‹users›(4) and timestamp: 1732113960.000000000,0
W241120 14:46:22.527772 107414 sql/pgwire/auth.go:161 ⋮ [T4,Vdestination-tenant-readonly,n3,client=10.142.0.177:48093,hostssl,user=‹roachprod›] 340 +  | -- cause hidden behind barrier
W241120 14:46:22.527772 107414 sql/pgwire/auth.go:161 ⋮ [T4,Vdestination-tenant-readonly,n3,client=10.142.0.177:48093,hostssl,user=‹roachprod›] 340 +  | internal error while retrieving user account: get auth info error: PCR reader timestamp has moved forward, existing descriptor ‹role_options›(33) and timestamp: 1732113915.000000000,0 new descritpor ‹users›(4) and timestamp: 1732113960.000000000,0
W241120 14:46:22.527772 107414 sql/pgwire/auth.go:161 ⋮ [T4,Vdestination-tenant-readonly,n3,client=10.142.0.177:48093,hostssl,user=‹roachprod›] 340 +  | (1) attached stack trace
W241120 14:46:22.527772 107414 sql/pgwire/auth.go:161 ⋮ [T4,Vdestination-tenant-readonly,n3,client=10.142.0.177:48093,hostssl,user=‹roachprod›] 340 +  |   -- stack trace:
search hit TOP, continuing at BOTTOM
W241120 16:01:37.762964 754710 sql/pgwire/auth.go:161 ⋮ [T4,Vdestination-tenant-readonly,n3,client=10.142.0.177:47312,hostssl,user=‹roachprod›] 5950 +  | github.com/cockroachdb/cockroach/pkg/sql/pgwire.(*Server).serveImpl.func4
W241120 16:01:37.762964 754710 sql/pgwire/auth.go:161 ⋮ [T4,Vdestination-tenant-readonly,n3,client=10.142.0.177:47312,hostssl,user=‹roachprod›] 5950 +  |       pkg/sql/pgwire/server.go:1196
W241120 16:01:37.762964 754710 sql/pgwire/auth.go:161 ⋮ [T4,Vdestination-tenant-readonly,n3,client=10.142.0.177:47312,hostssl,user=‹roachprod›] 5950 +Wraps: (2) internal error while retrieving user account memberships
W241120 16:01:37.762964 754710 sql/pgwire/auth.go:161 ⋮ [T4,Vdestination-tenant-readonly,n3,client=10.142.0.177:47312,hostssl,user=‹roachprod›] 5950 +  | (1) attached stack trace
W241120 16:01:37.762964 754710 sql/pgwire/auth.go:161 ⋮ [T4,Vdestination-tenant-readonly,n3,client=10.142.0.177:47312,hostssl,user=‹roachprod›] 5950 +  |   |   pkg/sql/user.go:278
W241120 16:01:37.762964 754710 sql/pgwire/auth.go:161 ⋮ [T4,Vdestination-tenant-readonly,n3,client=10.142.0.177:47312,hostssl,user=‹roachprod›] 5950 +  |   | github.com/cockroachdb/cockroach/pkg/sql.GetUserSessionInitInfo.func2
W241120 16:01:37.762964 754710 sql/pgwire/auth.go:161 ⋮ [T4,Vdestination-tenant-readonly,n3,client=10.142.0.177:47312,hostssl,user=‹roachprod›] 5950 +  |   |   pkg/sql/user.go:123
W241120 16:01:37.762964 754710 sql/pgwire/auth.go:161 ⋮ [T4,Vdestination-tenant-readonly,n3,client=10.142.0.177:47312,hostssl,user=‹roachprod›] 5950 +  |   | github.com/cockroachdb/cockroach/pkg/util/timeutil.RunWithTimeout
W241120 16:01:37.762964 754710 sql/pgwire/auth.go:161 ⋮ [T4,Vdestination-tenant-readonly,n3,client=10.142.0.177:47312,hostssl,user=‹roachprod›] 5950 +  |   |   pkg/util/timeutil/timeout.go:28
W241120 16:01:37.762964 754710 sql/pgwire/auth.go:161 ⋮ [T4,Vdestination-tenant-readonly,n3,client=10.142.0.177:47312,hostssl,user=‹roachprod›] 5950 +  |   | github.com/cockroachdb/cockroach/pkg/sql.getUserInfoRunFn.func2
W241120 16:01:37.762964 754710 sql/pgwire/auth.go:161 ⋮ [T4,Vdestination-tenant-readonly,n3,client=10.142.0.177:47312,hostssl,user=‹roachprod›] 5950 +  |   |   pkg/sql/user.go:242
W241120 16:01:37.762964 754710 sql/pgwire/auth.go:161 ⋮ [T4,Vdestination-tenant-readonly,n3,client=10.142.0.177:47312,hostssl,user=‹roachprod›] 5950 +  |   | github.com/cockroachdb/cockroach/pkg/sql.GetUserSessionInitInfo
W241120 16:01:37.762964 754710 sql/pgwire/auth.go:161 ⋮ [T4,Vdestination-tenant-readonly,n3,client=10.142.0.177:47312,hostssl,user=‹roachprod›] 5950 +  |   |   pkg/sql/user.go:120
W241120 16:01:37.762964 754710 sql/pgwire/auth.go:161 ⋮ [T4,Vdestination-tenant-readonly,n3,client=10.142.0.177:47312,hostssl,user=‹roachprod›] 5950 +  |   | github.com/cockroachdb/cockroach/pkg/sql/pgwire.(*conn).handleAuthentication
W241120 16:01:37.762964 754710 sql/pgwire/auth.go:161 ⋮ [T4,Vdestination-tenant-readonly,n3,client=10.142.0.177:47312,hostssl,user=‹roachprod›] 5950 +  |   |   pkg/sql/pgwire/auth.go:154
W241120 16:01:37.762964 754710 sql/pgwire/auth.go:161 ⋮ [T4,Vdestination-tenant-readonly,n3,client=10.142.0.177:47312,hostssl,user=‹roachprod›] 5950 +  |   | github.com/cockroachdb/cockroach/pkg/sql/pgwire.(*conn).processCommands
W241120 16:01:37.762964 754710 sql/pgwire/auth.go:161 ⋮ [T4,Vdestination-tenant-readonly,n3,client=10.142.0.177:47312,hostssl,user=‹roachprod›] 5950 +  |   |   pkg/sql/pgwire/conn.go:203
W241120 16:01:37.762964 754710 sql/pgwire/auth.go:161 ⋮ [T4,Vdestination-tenant-readonly,n3,client=10.142.0.177:47312,hostssl,user=‹roachprod›] 5950 +  |   | github.com/cockroachdb/cockroach/pkg/sql/pgwire.(*Server).serveImpl.func4
W241120 16:01:37.762964 754710 sql/pgwire/auth.go:161 ⋮ [T4,Vdestination-tenant-readonly,n3,client=10.142.0.177:47312,hostssl,user=‹roachprod›] 5950 +  |   |   pkg/sql/pgwire/server.go:1196
W241120 16:01:37.762964 754710 sql/pgwire/auth.go:161 ⋮ [T4,Vdestination-tenant-readonly,n3,client=10.142.0.177:47312,hostssl,user=‹roachprod›] 5950 +  |   | runtime.goexit
W241120 16:01:37.762964 754710 sql/pgwire/auth.go:161 ⋮ [T4,Vdestination-tenant-readonly,n3,client=10.142.0.177:47312,hostssl,user=‹roachprod›] 5950 +  |   |   src/runtime/asm_amd64.s:1695
W241120 16:01:37.762964 754710 sql/pgwire/auth.go:161 ⋮ [T4,Vdestination-tenant-readonly,n3,client=10.142.0.177:47312,hostssl,user=‹roachprod›] 5950 +  | Wraps: (2) internal error while retrieving user account
W241120 16:01:37.762964 754710 sql/pgwire/auth.go:161 ⋮ [T4,Vdestination-tenant-readonly,n3,client=10.142.0.177:47312,hostssl,user=‹roachprod›] 5950 +  | Wraps: (3) get auth info error: PCR reader timestamp has moved forward, existing descriptor ‹role_options›(33) and timestamp: 1732118450.000000000,0 new descritpor ‹users›(4) and timestamp: 1732118465.000000000,0
W241120 16:01:37.762964 754710 sql/pgwire/auth.go:161 ⋮ [T4,Vdestination-tenant-readonly,n3,client=10.142.0.177:47312,hostssl,user=‹roachprod›] 5950 +  |   | -- cause hidden behind barrier
W241120 16:01:37.762964 754710 sql/pgwire/auth.go:161 ⋮ [T4,Vdestination-tenant-readonly,n3,client=10.142.0.177:47312,hostssl,user=‹roachprod›] 5950 +  |   | get auth info error: PCR reader timestamp has moved forward, existing descriptor ‹role_options›(33) and timestamp: 1732118450.000000000,0 new descritpor ‹users›(4) and timestamp: 1732118465.000000000,0
W241120 16:01:37.762964 754710 sql/pgwire/auth.go:161 ⋮ [T4,Vdestination-tenant-readonly,n3,client=10.142.0.177:47312,hostssl,user=‹roachprod›] 5950 +  |   | (1) attached stack trace
W241120 16:01:37.762964 754710 sql/pgwire/auth.go:161 ⋮ [T4,Vdestination-tenant-readonly,n3,client=10.142.0.177:47312,hostssl,user=‹roachprod›] 5950 +  |   |   -- stack trace:
W241120 16:01:37.762964 754710 sql/pgwire/auth.go:161 ⋮ [T4,Vdestination-tenant-readonly,n3,client=10.142.0.177:47312,hostssl,user=‹roachprod›] 5950 +  |   |   | github.com/cockroachdb/cockroach/pkg/sql.retrieveSessionInitInfoWithCache.func1
W241120 16:01:37.762964 754710 sql/pgwire/auth.go:161 ⋮ [T4,Vdestination-tenant-readonly,n3,client=10.142.0.177:47312,hostssl,user=‹roachprod›] 5950 +  |   |   |       pkg/sql/user.go:260
W241120 16:01:37.762964 754710 sql/pgwire/auth.go:161 ⋮ [T4,Vdestination-tenant-readonly,n3,client=10.142.0.177:47312,hostssl,user=‹roachprod›] 5950 +  |   |   | github.com/cockroachdb/cockroach/pkg/sql.retrieveSessionInitInfoWithCache
W241120 16:01:37.762964 754710 sql/pgwire/auth.go:161 ⋮ [T4,Vdestination-tenant-readonly,n3,client=10.142.0.177:47312,hostssl,user=‹roachprod›] 5950 +  |   |   |       pkg/sql/user.go:275
W241120 16:01:37.762964 754710 sql/pgwire/auth.go:161 ⋮ [T4,Vdestination-tenant-readonly,n3,client=10.142.0.177:47312,hostssl,user=‹roachprod›] 5950 +  |   |   | github.com/cockroachdb/cockroach/pkg/sql.GetUserSessionInitInfo.func2
W241120 16:01:37.762964 754710 sql/pgwire/auth.go:161 ⋮ [T4,Vdestination-tenant-readonly,n3,client=10.142.0.177:47312,hostssl,user=‹roachprod›] 5950 +  |   |   |       pkg/sql/user.go:123
W241120 16:01:37.762964 754710 sql/pgwire/auth.go:161 ⋮ [T4,Vdestination-tenant-readonly,n3,client=10.142.0.177:47312,hostssl,user=‹roachprod›] 5950 +  |   |   | github.com/cockroachdb/cockroach/pkg/util/timeutil.RunWithTimeout
W241120 16:01:37.762964 754710 sql/pgwire/auth.go:161 ⋮ [T4,Vdestination-tenant-readonly,n3,client=10.142.0.177:47312,hostssl,user=‹roachprod›] 5950 +  |   |   |       pkg/util/timeutil/timeout.go:28
W241120 16:01:37.762964 754710 sql/pgwire/auth.go:161 ⋮ [T4,Vdestination-tenant-readonly,n3,client=10.142.0.177:47312,hostssl,user=‹roachprod›] 5950 +  |   |   | github.com/cockroachdb/cockroach/pkg/sql.getUserInfoRunFn.func2
W241120 16:01:37.762964 754710 sql/pgwire/auth.go:161 ⋮ [T4,Vdestination-tenant-readonly,n3,client=10.142.0.177:47312,hostssl,user=‹roachprod›] 5950 +  |   |   |       pkg/sql/user.go:242
W241120 16:01:37.762964 754710 sql/pgwire/auth.go:161 ⋮ [T4,Vdestination-tenant-readonly,n3,client=10.142.0.177:47312,hostssl,user=‹roachprod›] 5950 +  |   |   | github.com/cockroachdb/cockroach/pkg/sql.GetUserSessionInitInfo
W241120 16:01:37.762964 754710 sql/pgwire/auth.go:161 ⋮ [T4,Vdestination-tenant-readonly,n3,client=10.142.0.177:47312,hostssl,user=‹roachprod›] 5950 +  |   |   |       pkg/sql/user.go:120
W241120 16:01:37.762964 754710 sql/pgwire/auth.go:161 ⋮ [T4,Vdestination-tenant-readonly,n3,client=10.142.0.177:47312,hostssl,user=‹roachprod›] 5950 +  |   |   | github.com/cockroachdb/cockroach/pkg/sql/pgwire.(*conn).handleAuthentication
W241120 16:01:37.762964 754710 sql/pgwire/auth.go:161 ⋮ [T4,Vdestination-tenant-readonly,n3,client=10.142.0.177:47312,hostssl,user=‹roachprod›] 5950 +  |   |   |       pkg/sql/pgwire/auth.go:154
W241120 16:01:37.762964 754710 sql/pgwire/auth.go:161 ⋮ [T4,Vdestination-tenant-readonly,n3,client=10.142.0.177:47312,hostssl,user=‹roachprod›] 5950 +  |   |   | github.com/cockroachdb/cockroach/pkg/sql/pgwire.(*conn).processCommands
W241120 16:01:37.762964 754710 sql/pgwire/auth.go:161 ⋮ [T4,Vdestination-tenant-readonly,n3,client=10.142.0.177:47312,hostssl,user=‹roachprod›] 5950 +  |   |   |       pkg/sql/pgwire/conn.go:203
W241120 16:01:37.762964 754710 sql/pgwire/auth.go:161 ⋮ [T4,Vdestination-tenant-readonly,n3,client=10.142.0.177:47312,hostssl,user=‹roachprod›] 5950 +  |   |   | github.com/cockroachdb/cockroach/pkg/sql/pgwire.(*Server).serveImpl.func4
W241120 16:01:37.762964 754710 sql/pgwire/auth.go:161 ⋮ [T4,Vdestination-tenant-readonly,n3,client=10.142.0.177:47312,hostssl,user=‹roachprod›] 5950 +  |   |   |       pkg/sql/pgwire/server.go:1196
W241120 16:01:37.762964 754710 sql/pgwire/auth.go:161 ⋮ [T4,Vdestination-tenant-readonly,n3,client=10.142.0.177:47312,hostssl,user=‹roachprod›] 5950 +  |   |   | runtime.goexit
W241120 16:01:37.762964 754710 sql/pgwire/auth.go:161 ⋮ [T4,Vdestination-tenant-readonly,n3,client=10.142.0.177:47312,hostssl,user=‹roachprod›] 5950 +  |   |   |       src/runtime/asm_amd64.s:1695
W241120 16:01:37.762964 754710 sql/pgwire/auth.go:161 ⋮ [T4,Vdestination-tenant-readonly,n3,client=10.142.0.177:47312,hostssl,user=‹roachprod›] 5950 +  |   | Wraps: (2) get auth info error
W241120 16:01:37.762964 754710 sql/pgwire/auth.go:161 ⋮ [T4,Vdestination-tenant-readonly,n3,client=10.142.0.177:47312,hostssl,user=‹roachprod›] 5950 +  |   | Wraps: (3) PCR reader timestamp has moved forward, existing descriptor ‹role_options›(33) and timestamp: 1732118450.000000000,0 new descritpor ‹users›(4) and timestamp: 1732118465.000000000,0

Jira issue: CRDB-44743

Epic CRDB-43310

blathers-crl[bot] commented 1 day ago

cc @cockroachdb/disaster-recovery

blathers-crl[bot] commented 1 day ago

Hi @msbutler, please add branch-* labels to identify which branch(es) this C-bug affects.

:owl: Hoot! I am a Blathers, a bot for CockroachDB. My owner is dev-inf.

blathers-crl[bot] commented 1 day ago

Hi @msbutler, please add branch-* labels to identify which branch(es) this release-blocker affects.

:owl: Hoot! I am a Blathers, a bot for CockroachDB. My owner is dev-inf.