From d9604016688e168c8754fd2fb671afcc15e598e3 Mon Sep 17 00:00:00 2001 From: Tanjin Xu Date: Thu, 31 Oct 2024 14:52:00 -0700 Subject: [PATCH 1/3] add debugging messages --- go/vt/discovery/healthcheck.go | 1 + go/vt/vtgate/engine/set.go | 1 + go/vt/vtgate/plan_execute.go | 2 ++ go/vt/vtgate/scatter_conn.go | 1 + go/vt/vtgate/semantics/derived_table.go | 2 ++ go/vt/vtgate/tabletgateway.go | 3 ++- go/vt/vtgate/vindexes/vschema.go | 13 +++++++++++++ 7 files changed, 22 insertions(+), 1 deletion(-) diff --git a/go/vt/discovery/healthcheck.go b/go/vt/discovery/healthcheck.go index d37b7419fd6..21b402f2a3e 100644 --- a/go/vt/discovery/healthcheck.go +++ b/go/vt/discovery/healthcheck.go @@ -855,6 +855,7 @@ func (hc *HealthCheckImpl) TabletConnection(alias *topodata.TabletAlias, target hc.mu.Unlock() if thc == nil || thc.Conn == nil { // TODO: test that throws this error + log.Warning("NOT_FOUND: tablet: %v is either down or nonexistent", alias) return nil, vterrors.Errorf(vtrpc.Code_NOT_FOUND, "tablet: %v is either down or nonexistent", alias) } return thc.Connection(hc), nil diff --git a/go/vt/vtgate/engine/set.go b/go/vt/vtgate/engine/set.go index 9d370b6ec36..1173538438d 100644 --- a/go/vt/vtgate/engine/set.go +++ b/go/vt/vtgate/engine/set.go @@ -540,6 +540,7 @@ func (svss *SysVarSetAware) Execute(ctx context.Context, vcursor VCursor, env *e return vterrors.NewErrorf(vtrpcpb.Code_INVALID_ARGUMENT, vterrors.WrongValueForVar, "variable 'session_track_gtids' can't be set to the value of '%s'", str) } default: + log.Warning("NOT_FOUOND: unknown system variable '%s'", svss.Name) return vterrors.NewErrorf(vtrpcpb.Code_NOT_FOUND, vterrors.UnknownSystemVariable, "unknown system variable '%s'", svss.Name) } diff --git a/go/vt/vtgate/plan_execute.go b/go/vt/vtgate/plan_execute.go index 4e2c3bfea4c..11c853cc4ac 100644 --- a/go/vt/vtgate/plan_execute.go +++ b/go/vt/vtgate/plan_execute.go @@ -201,12 +201,14 @@ func (e *Executor) handleTransactions( case sqlparser.StmtSRollback: qr, err := e.handleSavepoint(ctx, safeSession, plan.Original, "Rollback Savepoint", logStats, func(query string) (*sqltypes.Result, error) { // Error as there is no transaction, so there is no savepoint that exists. + log.Warning("NOT_FOUND: SAVEPOINT does not exist: %s", query) return nil, vterrors.NewErrorf(vtrpcpb.Code_NOT_FOUND, vterrors.SPDoesNotExist, "SAVEPOINT does not exist: %s", query) }, vcursor.ignoreMaxMemoryRows) return qr, err case sqlparser.StmtRelease: qr, err := e.handleSavepoint(ctx, safeSession, plan.Original, "Release Savepoint", logStats, func(query string) (*sqltypes.Result, error) { // Error as there is no transaction, so there is no savepoint that exists. + log.Warning("NOT_FOUND: SAVEPOINT does not exist: %s", query) return nil, vterrors.NewErrorf(vtrpcpb.Code_NOT_FOUND, vterrors.SPDoesNotExist, "SAVEPOINT does not exist: %s", query) }, vcursor.ignoreMaxMemoryRows) return qr, err diff --git a/go/vt/vtgate/scatter_conn.go b/go/vt/vtgate/scatter_conn.go index ede88e2d9b8..2032af07a4d 100644 --- a/go/vt/vtgate/scatter_conn.go +++ b/go/vt/vtgate/scatter_conn.go @@ -831,6 +831,7 @@ func lockInfo(target *querypb.Target, session *SafeSession, lockFuncType sqlpars info := &shardActionInfo{actionNeeded: nothing} if session.LockSession != nil { if !proto.Equal(target, session.LockSession.Target) { + log.Warning("NOT_FOUND: target does match the existing lock session target: (%v, %v)", target, session.LockSession.Target) return nil, vterrors.Errorf(vtrpcpb.Code_NOT_FOUND, "target does match the existing lock session target: (%v, %v)", target, session.LockSession.Target) } info.reservedID = session.LockSession.ReservedId diff --git a/go/vt/vtgate/semantics/derived_table.go b/go/vt/vtgate/semantics/derived_table.go index 0425d78ed93..3bdbb116702 100644 --- a/go/vt/vtgate/semantics/derived_table.go +++ b/go/vt/vtgate/semantics/derived_table.go @@ -19,6 +19,7 @@ package semantics import ( "strings" + "vitess.io/vitess/go/vt/log" vtrpcpb "vitess.io/vitess/go/vt/proto/vtrpc" "vitess.io/vitess/go/vt/sqlparser" "vitess.io/vitess/go/vt/vterrors" @@ -183,6 +184,7 @@ func (dt *DerivedTable) getExprFor(s string) (sqlparser.Expr, error) { return dt.cols[i], nil } } + log.Warning("NOT_FOUND: Unknown column '%s' in 'field list'", s) return nil, vterrors.NewErrorf(vtrpcpb.Code_NOT_FOUND, vterrors.BadFieldError, "Unknown column '%s' in 'field list'", s) } diff --git a/go/vt/vtgate/tabletgateway.go b/go/vt/vtgate/tabletgateway.go index 4c67f5672e1..5b1945f2eaa 100644 --- a/go/vt/vtgate/tabletgateway.go +++ b/go/vt/vtgate/tabletgateway.go @@ -494,7 +494,8 @@ func (gw *TabletGateway) updateDefaultConnCollation(tablet *topodatapb.Tablet) { return } if gw.defaultConnCollation.Load() != tablet.DefaultConnCollation { - log.Warning("this Vitess cluster has tablets with different default connection collations") + log.Warning("this Vitess cluster has tablets with different default connection collations: gw: %v, tablet:%v, host:%v", + gw.defaultConnCollation.Load(), tablet.DefaultConnCollation, tablet.Hostname) } } diff --git a/go/vt/vtgate/vindexes/vschema.go b/go/vt/vtgate/vindexes/vschema.go index 8559cabc447..49e20c887d6 100644 --- a/go/vt/vtgate/vindexes/vschema.go +++ b/go/vt/vtgate/vindexes/vschema.go @@ -29,6 +29,7 @@ import ( "vitess.io/vitess/go/mysql/collations" "vitess.io/vitess/go/sqlescape" "vitess.io/vitess/go/sqltypes" + "vitess.io/vitess/go/vt/log" querypb "vitess.io/vitess/go/vt/proto/query" topodatapb "vitess.io/vitess/go/vt/proto/topodata" vschemapb "vitess.io/vitess/go/vt/proto/vschema" @@ -493,6 +494,9 @@ func buildKeyspaceReferences(vschema *VSchema, ksvschema *KeyspaceSchema) error if vterrors.Code(err) != vtrpcpb.Code_NOT_FOUND || vterrors.ErrState(err) != vterrors.BadDb { return err } + log.Warning("NOT_FOUND: source %q references a non-existent keyspace %q", + source, + sourceKsname) return vterrors.Errorf( vtrpcpb.Code_NOT_FOUND, "source %q references a non-existent keyspace %q", @@ -501,6 +505,10 @@ func buildKeyspaceReferences(vschema *VSchema, ksvschema *KeyspaceSchema) error ) } if sourceT == nil { + log.Warning("NOT_FOUND: source %q references a table %q that is not present in the VSchema of keyspace %q", + source, + sourceTname, + sourceKsname) return vterrors.Errorf( vtrpcpb.Code_NOT_FOUND, "source %q references a table %q that is not present in the VSchema of keyspace %q", @@ -606,6 +614,8 @@ func buildTables(ks *vschemapb.Keyspace, vschema *VSchema, ksvschema *KeyspaceSc } t.Type = table.Type default: + log.Warning("NOT_FOUND: unidentified table type %s", + table.Type) return vterrors.Errorf( vtrpcpb.Code_NOT_FOUND, "unidentified table type %s", @@ -828,6 +838,9 @@ func resolveAutoIncrement(source *vschemapb.SrvVSchema, vschema *VSchema, parser // Better to remove the table than to leave it partially initialized. delete(ksvschema.Tables, tname) delete(vschema.globalTables, tname) + log.Warning("NOT_FOUND: cannot resolve sequence %s: %s", + table.AutoIncrement.Sequence, + err.Error()) ksvschema.Error = vterrors.Errorf( vtrpcpb.Code_NOT_FOUND, "cannot resolve sequence %s: %s", From 6dbb66c19c877e77f6db1fd0aaa4aba9280634f3 Mon Sep 17 00:00:00 2001 From: Tanjin Xu Date: Thu, 31 Oct 2024 15:14:44 -0700 Subject: [PATCH 2/3] fix typos --- go/vt/discovery/healthcheck.go | 2 +- go/vt/vtgate/engine/set.go | 2 +- go/vt/vtgate/plan_execute.go | 4 ++-- go/vt/vtgate/scatter_conn.go | 2 +- go/vt/vtgate/semantics/derived_table.go | 2 +- go/vt/vtgate/tabletgateway.go | 2 +- go/vt/vtgate/vindexes/vschema.go | 8 ++++---- 7 files changed, 11 insertions(+), 11 deletions(-) diff --git a/go/vt/discovery/healthcheck.go b/go/vt/discovery/healthcheck.go index 21b402f2a3e..3498b144e03 100644 --- a/go/vt/discovery/healthcheck.go +++ b/go/vt/discovery/healthcheck.go @@ -855,7 +855,7 @@ func (hc *HealthCheckImpl) TabletConnection(alias *topodata.TabletAlias, target hc.mu.Unlock() if thc == nil || thc.Conn == nil { // TODO: test that throws this error - log.Warning("NOT_FOUND: tablet: %v is either down or nonexistent", alias) + log.Warningf("NOT_FOUND: tablet: %v is either down or nonexistent", alias) return nil, vterrors.Errorf(vtrpc.Code_NOT_FOUND, "tablet: %v is either down or nonexistent", alias) } return thc.Connection(hc), nil diff --git a/go/vt/vtgate/engine/set.go b/go/vt/vtgate/engine/set.go index 1173538438d..a4181d64863 100644 --- a/go/vt/vtgate/engine/set.go +++ b/go/vt/vtgate/engine/set.go @@ -540,7 +540,7 @@ func (svss *SysVarSetAware) Execute(ctx context.Context, vcursor VCursor, env *e return vterrors.NewErrorf(vtrpcpb.Code_INVALID_ARGUMENT, vterrors.WrongValueForVar, "variable 'session_track_gtids' can't be set to the value of '%s'", str) } default: - log.Warning("NOT_FOUOND: unknown system variable '%s'", svss.Name) + log.Warningf("NOT_FOUOND: unknown system variable '%s'", svss.Name) return vterrors.NewErrorf(vtrpcpb.Code_NOT_FOUND, vterrors.UnknownSystemVariable, "unknown system variable '%s'", svss.Name) } diff --git a/go/vt/vtgate/plan_execute.go b/go/vt/vtgate/plan_execute.go index 11c853cc4ac..c704a8747fe 100644 --- a/go/vt/vtgate/plan_execute.go +++ b/go/vt/vtgate/plan_execute.go @@ -201,14 +201,14 @@ func (e *Executor) handleTransactions( case sqlparser.StmtSRollback: qr, err := e.handleSavepoint(ctx, safeSession, plan.Original, "Rollback Savepoint", logStats, func(query string) (*sqltypes.Result, error) { // Error as there is no transaction, so there is no savepoint that exists. - log.Warning("NOT_FOUND: SAVEPOINT does not exist: %s", query) + log.Warningf("NOT_FOUND: SAVEPOINT does not exist: %s", query) return nil, vterrors.NewErrorf(vtrpcpb.Code_NOT_FOUND, vterrors.SPDoesNotExist, "SAVEPOINT does not exist: %s", query) }, vcursor.ignoreMaxMemoryRows) return qr, err case sqlparser.StmtRelease: qr, err := e.handleSavepoint(ctx, safeSession, plan.Original, "Release Savepoint", logStats, func(query string) (*sqltypes.Result, error) { // Error as there is no transaction, so there is no savepoint that exists. - log.Warning("NOT_FOUND: SAVEPOINT does not exist: %s", query) + log.Warningf("NOT_FOUND: SAVEPOINT does not exist: %s", query) return nil, vterrors.NewErrorf(vtrpcpb.Code_NOT_FOUND, vterrors.SPDoesNotExist, "SAVEPOINT does not exist: %s", query) }, vcursor.ignoreMaxMemoryRows) return qr, err diff --git a/go/vt/vtgate/scatter_conn.go b/go/vt/vtgate/scatter_conn.go index 2032af07a4d..c5a0868d060 100644 --- a/go/vt/vtgate/scatter_conn.go +++ b/go/vt/vtgate/scatter_conn.go @@ -831,7 +831,7 @@ func lockInfo(target *querypb.Target, session *SafeSession, lockFuncType sqlpars info := &shardActionInfo{actionNeeded: nothing} if session.LockSession != nil { if !proto.Equal(target, session.LockSession.Target) { - log.Warning("NOT_FOUND: target does match the existing lock session target: (%v, %v)", target, session.LockSession.Target) + log.Warningf("NOT_FOUND: target does match the existing lock session target: (%v, %v)", target, session.LockSession.Target) return nil, vterrors.Errorf(vtrpcpb.Code_NOT_FOUND, "target does match the existing lock session target: (%v, %v)", target, session.LockSession.Target) } info.reservedID = session.LockSession.ReservedId diff --git a/go/vt/vtgate/semantics/derived_table.go b/go/vt/vtgate/semantics/derived_table.go index 3bdbb116702..c1d3ced4f32 100644 --- a/go/vt/vtgate/semantics/derived_table.go +++ b/go/vt/vtgate/semantics/derived_table.go @@ -184,7 +184,7 @@ func (dt *DerivedTable) getExprFor(s string) (sqlparser.Expr, error) { return dt.cols[i], nil } } - log.Warning("NOT_FOUND: Unknown column '%s' in 'field list'", s) + log.Warningf("NOT_FOUND: Unknown column '%s' in 'field list'", s) return nil, vterrors.NewErrorf(vtrpcpb.Code_NOT_FOUND, vterrors.BadFieldError, "Unknown column '%s' in 'field list'", s) } diff --git a/go/vt/vtgate/tabletgateway.go b/go/vt/vtgate/tabletgateway.go index 5b1945f2eaa..2a72c937b17 100644 --- a/go/vt/vtgate/tabletgateway.go +++ b/go/vt/vtgate/tabletgateway.go @@ -494,7 +494,7 @@ func (gw *TabletGateway) updateDefaultConnCollation(tablet *topodatapb.Tablet) { return } if gw.defaultConnCollation.Load() != tablet.DefaultConnCollation { - log.Warning("this Vitess cluster has tablets with different default connection collations: gw: %v, tablet:%v, host:%v", + log.Warningf("this Vitess cluster has tablets with different default connection collations: gw: %v, tablet:%v, host:%v", gw.defaultConnCollation.Load(), tablet.DefaultConnCollation, tablet.Hostname) } } diff --git a/go/vt/vtgate/vindexes/vschema.go b/go/vt/vtgate/vindexes/vschema.go index 49e20c887d6..52d48cd1bf9 100644 --- a/go/vt/vtgate/vindexes/vschema.go +++ b/go/vt/vtgate/vindexes/vschema.go @@ -494,7 +494,7 @@ func buildKeyspaceReferences(vschema *VSchema, ksvschema *KeyspaceSchema) error if vterrors.Code(err) != vtrpcpb.Code_NOT_FOUND || vterrors.ErrState(err) != vterrors.BadDb { return err } - log.Warning("NOT_FOUND: source %q references a non-existent keyspace %q", + log.Warningf("NOT_FOUND: source %q references a non-existent keyspace %q", source, sourceKsname) return vterrors.Errorf( @@ -505,7 +505,7 @@ func buildKeyspaceReferences(vschema *VSchema, ksvschema *KeyspaceSchema) error ) } if sourceT == nil { - log.Warning("NOT_FOUND: source %q references a table %q that is not present in the VSchema of keyspace %q", + log.Warningf("NOT_FOUND: source %q references a table %q that is not present in the VSchema of keyspace %q", source, sourceTname, sourceKsname) @@ -614,7 +614,7 @@ func buildTables(ks *vschemapb.Keyspace, vschema *VSchema, ksvschema *KeyspaceSc } t.Type = table.Type default: - log.Warning("NOT_FOUND: unidentified table type %s", + log.Warningf("NOT_FOUND: unidentified table type %s", table.Type) return vterrors.Errorf( vtrpcpb.Code_NOT_FOUND, @@ -838,7 +838,7 @@ func resolveAutoIncrement(source *vschemapb.SrvVSchema, vschema *VSchema, parser // Better to remove the table than to leave it partially initialized. delete(ksvschema.Tables, tname) delete(vschema.globalTables, tname) - log.Warning("NOT_FOUND: cannot resolve sequence %s: %s", + log.Warningf("NOT_FOUND: cannot resolve sequence %s: %s", table.AutoIncrement.Sequence, err.Error()) ksvschema.Error = vterrors.Errorf( From 48a811ad3bcaed66b74e9871d6dc17bd34310372 Mon Sep 17 00:00:00 2001 From: Tanjin Xu Date: Fri, 1 Nov 2024 09:00:17 -0700 Subject: [PATCH 3/3] add debug msg --- go/vt/vtgate/tabletgateway.go | 3 +++ 1 file changed, 3 insertions(+) diff --git a/go/vt/vtgate/tabletgateway.go b/go/vt/vtgate/tabletgateway.go index 2a72c937b17..337b7f05bc6 100644 --- a/go/vt/vtgate/tabletgateway.go +++ b/go/vt/vtgate/tabletgateway.go @@ -490,6 +490,9 @@ func (gw *TabletGateway) TabletsHealthyStatus() discovery.TabletsCacheStatusList } func (gw *TabletGateway) updateDefaultConnCollation(tablet *topodatapb.Tablet) { + if tablet.DefaultConnCollation == 45 { + log.Warningf("slack: unexpected collation on tablet host: %s", tablet.Hostname) + } if gw.defaultConnCollation.CompareAndSwap(0, tablet.DefaultConnCollation) { return }