Skip to content

Commit ee3a9ab

Browse files
cucaroachcucaroach
committed
sql: add extra information to protocol errors in bind
A user is running into mysterious protocol errors when using prepared statements. Add some extra information to the error message to help guide the investigation. Informs: https://github.com/cockroachlabs/support/issues/2184 Release note: none Epic: none
1 parent c576bae commit ee3a9ab

File tree

8 files changed

+64
-34
lines changed

8 files changed

+64
-34
lines changed

‎pkg/acceptance/testdata/node/base-test.js‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -40,7 +40,7 @@ describe('error cases', () => {
4040
const cases = [{
4141
name: 'not enough params',
4242
query: { text: 'SELECT 3', values: ['foo'] },
43-
msg: "bind message supplies 1 parameters, but prepared statement \"\" requires 0",
43+
msg: "bind message supplies 1 parameters, but requires 0",
4444
code: '08P01',
4545
}, {
4646
name: 'invalid utf8',

‎pkg/sql/conn_executor_prepare.go‎

Lines changed: 21 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -344,14 +344,26 @@ func (ex *connExecutor) populatePrepared(
344344
func (ex *connExecutor) execBind(
345345
ctx context.Context, bindCmd BindStmt,
346346
) (fsm.Event, fsm.EventPayload) {
347+
var ps *PreparedStatement
347348
retErr := func(err error) (fsm.Event, fsm.EventPayload) {
349+
if bindCmd.PreparedStatementName != "" {
350+
err = errors.WithDetailf(err, "statement name %q", bindCmd.PreparedStatementName)
351+
}
352+
if bindCmd.PortalName != "" {
353+
err = errors.WithDetailf(err, "portal name %q", bindCmd.PortalName)
354+
}
355+
if ps != nil && ps.StatementSummary != "" {
356+
err = errors.WithDetailf(err, "statement summary %q", ps.StatementSummary)
357+
}
348358
return eventNonRetriableErr{IsCommit: fsm.False}, eventNonRetriableErrPayload{err: err}
349359
}
350360

351-
ps, ok := ex.extraTxnState.prepStmtsNamespace.prepStmts[bindCmd.PreparedStatementName]
361+
var ok bool
362+
ps, ok = ex.extraTxnState.prepStmtsNamespace.prepStmts[bindCmd.PreparedStatementName]
352363
if !ok {
353364
return retErr(newPreparedStmtDNEError(ex.sessionData(), bindCmd.PreparedStatementName))
354365
}
366+
355367
ex.extraTxnState.prepStmtsNamespace.touchLRUEntry(bindCmd.PreparedStatementName)
356368

357369
// We need to make sure type resolution happens within a transaction.
@@ -437,7 +449,7 @@ func (ex *connExecutor) execBind(
437449
if len(bindCmd.Args) != int(numQArgs) {
438450
return retErr(
439451
pgwirebase.NewProtocolViolationErrorf(
440-
"bind message supplies %d parameters, but prepared statement \"%s\" requires %d", len(bindCmd.Args), bindCmd.PreparedStatementName, numQArgs))
452+
"bind message supplies %d parameters, but requires %d", len(bindCmd.Args), numQArgs))
441453
}
442454

443455
resolve := func(ctx context.Context, txn *kv.Txn) (err error) {
@@ -497,9 +509,14 @@ func (ex *connExecutor) execBind(
497509

498510
numCols := len(ps.Columns)
499511
if (len(bindCmd.OutFormats) > 1) && (len(bindCmd.OutFormats) != numCols) {
500-
return retErr(pgwirebase.NewProtocolViolationErrorf(
512+
err := pgwirebase.NewProtocolViolationErrorf(
501513
"expected 1 or %d for number of format codes, got %d",
502-
numCols, len(bindCmd.OutFormats)))
514+
numCols, len(bindCmd.OutFormats))
515+
// A user is hitting this error unexpectedly and rarely, dump extra info,
516+
// should be okay since this should be a very rare error.
517+
log.Infof(ctx, "%s outformats: %v, AST: %T, prepared statements: %s", err.Error(),
518+
bindCmd.OutFormats, ps.AST, ex.extraTxnState.prepStmtsNamespace.String())
519+
return retErr(err)
503520
}
504521

505522
columnFormatCodes := bindCmd.OutFormats

‎pkg/sql/pgwire/pgwire_test.go‎

Lines changed: 16 additions & 18 deletions
Original file line numberDiff line numberDiff line change
@@ -451,9 +451,9 @@ func TestPGPreparedQuery(t *testing.T) {
451451
{"SELECT $1 > 0", []preparedQueryTest{
452452
baseTest.SetArgs(1).Results(true),
453453
baseTest.SetArgs("1").Results(true),
454-
baseTest.SetArgs(1.1).Error(`pq: error in argument for $1: could not parse "1.1" as type int: strconv.ParseInt: parsing "1.1": invalid syntax`).Results(true),
455-
baseTest.SetArgs("1.0").Error(`pq: error in argument for $1: could not parse "1.0" as type int: strconv.ParseInt: parsing "1.0": invalid syntax`),
456-
baseTest.SetArgs(true).Error(`pq: error in argument for $1: could not parse "true" as type int: strconv.ParseInt: parsing "true": invalid syntax`),
454+
baseTest.SetArgs(1.1).Error(`error in argument for \$1: could not parse "1.1" as type int: strconv.ParseInt: parsing "1.1": invalid syntax`).Results(true),
455+
baseTest.SetArgs("1.0").Error(`error in argument for \$1: could not parse "1.0" as type int: strconv.ParseInt: parsing "1.0": invalid syntax`),
456+
baseTest.SetArgs(true).Error(`error in argument for \$1: could not parse "true" as type int: strconv.ParseInt: parsing "true": invalid syntax`),
457457
}},
458458
{"SELECT ($1) > 0", []preparedQueryTest{
459459
baseTest.SetArgs(1).Results(true),
@@ -467,7 +467,7 @@ func TestPGPreparedQuery(t *testing.T) {
467467
baseTest.SetArgs(true).Results(true),
468468
baseTest.SetArgs(false).Results(false),
469469
baseTest.SetArgs(1).Results(true),
470-
baseTest.SetArgs("").Error(`pq: error in argument for $1: could not parse "" as type bool: strconv.ParseBool: parsing "": invalid syntax`),
470+
baseTest.SetArgs("").Error(`error in argument for \$1: could not parse "" as type bool: strconv.ParseBool: parsing "": invalid syntax`),
471471
// Make sure we can run another after a failure.
472472
baseTest.SetArgs(true).Results(true),
473473
}},
@@ -476,14 +476,12 @@ func TestPGPreparedQuery(t *testing.T) {
476476
baseTest.SetArgs("true").Results(true),
477477
baseTest.SetArgs("false").Results(false),
478478
baseTest.SetArgs("1").Results(true),
479-
baseTest.SetArgs(2).Error(`pq: error in argument for $1: could not parse "2" as type bool: strconv.ParseBool: parsing "2": invalid syntax`),
480-
baseTest.SetArgs(3.1).Error(`pq: error in argument for $1: could not parse "3.1" as type bool: strconv.ParseBool: parsing "3.1": invalid syntax`),
481-
baseTest.SetArgs("").Error(`pq: error in argument for $1: could not parse "" as type bool: strconv.ParseBool: parsing "": invalid syntax`),
479+
baseTest.SetArgs(2).Error(`error in argument for \$1: could not parse "2" as type bool: strconv.ParseBool: parsing "2": invalid syntax`),
480+
baseTest.SetArgs(3.1).Error(`error in argument for \$1: could not parse "3.1" as type bool: strconv.ParseBool: parsing "3.1": invalid syntax`),
481+
baseTest.SetArgs("").Error(`error in argument for \$1: could not parse "" as type bool: strconv.ParseBool: parsing "": invalid syntax`),
482482
}},
483483
{"SELECT CASE 40+2 WHEN 42 THEN 51 ELSE $1::INT END", []preparedQueryTest{
484-
baseTest.Error(
485-
"pq: no value provided for placeholder: $1",
486-
).PreparedError(
484+
baseTest.Error(`no value provided for placeholder: \$1`).PreparedError(
487485
wrongArgCountString(1, 0),
488486
),
489487
}},
@@ -492,14 +490,14 @@ func TestPGPreparedQuery(t *testing.T) {
492490
baseTest.SetArgs("2", 1).Results(true),
493491
baseTest.SetArgs(1, "2").Results(false),
494492
baseTest.SetArgs("2", "1.0").Results(true),
495-
baseTest.SetArgs("2.0", "1").Error(`pq: error in argument for $1: could not parse "2.0" as type int: strconv.ParseInt: parsing "2.0": invalid syntax`),
496-
baseTest.SetArgs(2.1, 1).Error(`pq: error in argument for $1: could not parse "2.1" as type int: strconv.ParseInt: parsing "2.1": invalid syntax`),
493+
baseTest.SetArgs("2.0", "1").Error(`error in argument for \$1: could not parse "2.0" as type int: strconv.ParseInt: parsing "2.0": invalid syntax`),
494+
baseTest.SetArgs(2.1, 1).Error(`error in argument for \$1: could not parse "2.1" as type int: strconv.ParseInt: parsing "2.1": invalid syntax`),
497495
}},
498496
{"SELECT greatest($1, 0, $2), $2", []preparedQueryTest{
499497
baseTest.SetArgs(1, -1).Results(1, -1),
500498
baseTest.SetArgs(-1, 10).Results(10, 10),
501499
baseTest.SetArgs("-2", "-1").Results(0, -1),
502-
baseTest.SetArgs(1, 2.1).Error(`pq: error in argument for $2: could not parse "2.1" as type int: strconv.ParseInt: parsing "2.1": invalid syntax`),
500+
baseTest.SetArgs(1, 2.1).Error(`error in argument for \$2: could not parse "2.1" as type int: strconv.ParseInt: parsing "2.1": invalid syntax`),
503501
}},
504502
{"SELECT $1::int, $1::float", []preparedQueryTest{
505503
baseTest.SetArgs(1).Results(1, 1.0),
@@ -508,7 +506,7 @@ func TestPGPreparedQuery(t *testing.T) {
508506
{"SELECT 3 + $1, $1 + $2", []preparedQueryTest{
509507
baseTest.SetArgs("1", "2").Results(4, 3),
510508
baseTest.SetArgs(3, "4").Results(6, 7),
511-
baseTest.SetArgs(0, "a").Error(`pq: error in argument for $2: could not parse "a" as type int: strconv.ParseInt: parsing "a": invalid syntax`),
509+
baseTest.SetArgs(0, "a").Error(`error in argument for \$2: could not parse "a" as type int: strconv.ParseInt: parsing "a": invalid syntax`),
512510
}},
513511
// Check for name resolution.
514512
{"SELECT count(*)", []preparedQueryTest{
@@ -522,7 +520,7 @@ func TestPGPreparedQuery(t *testing.T) {
522520
{"SELECT CASE 1 WHEN $1 THEN $2 ELSE 2 END", []preparedQueryTest{
523521
baseTest.SetArgs(1, 3).Results(3),
524522
baseTest.SetArgs(2, 3).Results(2),
525-
baseTest.SetArgs(true, 0).Error(`pq: error in argument for $1: could not parse "true" as type int: strconv.ParseInt: parsing "true": invalid syntax`),
523+
baseTest.SetArgs(true, 0).Error(`error in argument for \$1: could not parse "true" as type int: strconv.ParseInt: parsing "true": invalid syntax`),
526524
}},
527525
{"SELECT $1[2] LIKE 'b'", []preparedQueryTest{
528526
baseTest.SetArgs(pq.Array([]string{"a", "b", "c"})).Results(true),
@@ -892,7 +890,7 @@ func TestPGPreparedQuery(t *testing.T) {
892890
if prepared && test.preparedError != "" {
893891
expectedErr = test.preparedError
894892
}
895-
if err.Error() != expectedErr {
893+
if !testutils.IsError(err, expectedErr) {
896894
t.Errorf("%s: %v: expected error: %s, got %s", query, test.qargs, expectedErr, err)
897895
}
898896
}
@@ -1094,7 +1092,7 @@ func TestPGPreparedExec(t *testing.T) {
10941092
"INSERT INTO d.public.t VALUES ($1, $2, $3)",
10951093
[]preparedExecTest{
10961094
baseTest.SetArgs(1, "one", 2).RowsAffected(1),
1097-
baseTest.SetArgs("two", 2, 2).Error(`pq: error in argument for $1: could not parse "two" as type int: strconv.ParseInt: parsing "two": invalid syntax`),
1095+
baseTest.SetArgs("two", 2, 2).Error(`error in argument for \$1: could not parse "two" as type int: strconv.ParseInt: parsing "two": invalid syntax`),
10981096
},
10991097
},
11001098
{
@@ -1294,7 +1292,7 @@ func TestPGPreparedExec(t *testing.T) {
12941292
if result, err := execFunc(test.qargs...); err != nil {
12951293
if test.error == "" {
12961294
t.Errorf("%s: %v: unexpected error: %s", query, test.qargs, err)
1297-
} else if err.Error() != test.error {
1295+
} else if !testutils.IsError(err, test.error) {
12981296
t.Errorf("%s: %v: expected error: %s, got %s", query, test.qargs, test.error, err)
12991297
}
13001298
} else {

‎pkg/sql/pgwire/testdata/pgtest/copy‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1078,7 +1078,7 @@ ErrorResponse
10781078
ReadyForQuery
10791079
----
10801080
{"Type":"ParseComplete"}
1081-
{"Type":"ErrorResponse","Code":"08P01","Message":"bind message supplies 1 parameters, but prepared statement \"\" requires 0"}
1081+
{"Type":"ErrorResponse","Code":"08P01","Message":"bind message supplies 1 parameters, but requires 0","Detail":"statement summary \"COPY (SELECT) TO STDOUT\""}
10821082
{"Type":"ReadyForQuery","TxStatus":"I"}
10831083

10841084
# And it's also an error to _not_ bind a placeholder.

‎pkg/sql/pgwire/testdata/pgtest/errors‎

Lines changed: 15 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -84,3 +84,18 @@ ReadyForQuery
8484
----
8585
{"Type":"ErrorResponse","Code":"23503","ConstraintName":"foo bar"}
8686
{"Type":"ReadyForQuery","TxStatus":"I"}
87+
88+
send
89+
Parse {"Name": "s0", "Query": "select $1,$2,$3", "ParameterOIDs":[1043, 1043, 1043]}
90+
Bind {"DestinationPortal": "p0", "PreparedStatement": "s0", "ParameterFormatCodes": [0], "ResultFormatCodes": [0,1,2,3,4,5], "Parameters": [{"text":"whitebear"}, {"text":"blackbear"}, {"text":"brownbear"}]}
91+
Execute {"Portal": "p0"}
92+
Sync
93+
----
94+
95+
until
96+
ErrorResponse
97+
ReadyForQuery
98+
----
99+
{"Type":"ParseComplete"}
100+
{"Type":"ErrorResponse","Code":"08P01"}
101+
{"Type":"ReadyForQuery","TxStatus":"I"}

‎pkg/sql/pgwire/testdata/pgtest/multiple_active_portals‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -127,7 +127,7 @@ until keepErrMessage
127127
ErrorResponse
128128
----
129129
{"Type":"ParseComplete"}
130-
{"Type":"ErrorResponse","Code":"42P03","Message":"portal \"p2\" already exists"}
130+
{"Type":"ErrorResponse","Code":"42P03","Message":"portal \"p2\" already exists","Detail":"statement name \"q3\"\n--\nportal name \"p2\"\n--\nstatement summary \"SELECT * FROM mytable\""}
131131

132132
send
133133
Query {"String": "COMMIT"}

‎pkg/sql/pgwire/testdata/pgtest/portals‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1363,7 +1363,7 @@ ErrorResponse
13631363
ReadyForQuery
13641364
----
13651365
{"Type":"ParseComplete"}
1366-
{"Type":"ErrorResponse","Code":"42P03","Message":"portal \"sqlcursor\" already exists as cursor"}
1366+
{"Type":"ErrorResponse","Code":"42P03","Message":"portal \"sqlcursor\" already exists as cursor","Detail":"statement name \"blah\"\n--\nportal name \"sqlcursor\"\n--\nstatement summary \"SELECT _\""}
13671367
{"Type":"ReadyForQuery","TxStatus":"E"}
13681368

13691369
send

‎pkg/sql/pgwire/testdata/pgtest/tuple‎

Lines changed: 8 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -89,7 +89,7 @@ ErrorResponse
8989
ReadyForQuery
9090
----
9191
{"Type":"ParseComplete"}
92-
{"Type":"ErrorResponse","Code":"0A000","Message":"error in argument for $1: could not parse \"(1,cat)\" as type tuple: cannot parse anonymous record type"}
92+
{"Type":"ErrorResponse","Code":"0A000","Message":"error in argument for $1: could not parse \"(1,cat)\" as type tuple: cannot parse anonymous record type","Detail":"statement name \"s4\"\n--\nportal name \"p4\"\n--\nstatement summary \"SELECT $1 AS a\""}
9393
{"Type":"ReadyForQuery","TxStatus":"I"}
9494

9595
send
@@ -148,7 +148,7 @@ ErrorResponse
148148
ReadyForQuery
149149
----
150150
{"Type":"ParseComplete"}
151-
{"Type":"ErrorResponse","Code":"42601","Message":"error in argument for $1: tuple requires a 4 byte header for binary format","Detail":"bufferLength=0"}
151+
{"Type":"ErrorResponse","Code":"42601","Message":"error in argument for $1: tuple requires a 4 byte header for binary format","Detail":"bufferLength=0\n--\nstatement name \"s_empty_param\"\n--\nportal name \"p_empty_param\"\n--\nstatement summary \"SELECT $1::r\""}
152152
{"Type":"ReadyForQuery","TxStatus":"I"}
153153

154154
# negative length tuple
@@ -173,7 +173,7 @@ ErrorResponse
173173
ReadyForQuery
174174
----
175175
{"Type":"ParseComplete"}
176-
{"Type":"ErrorResponse","Code":"42601","Message":"error in argument for $1: tuple must have non-negative number of elements","Detail":"numberOfElements=-1"}
176+
{"Type":"ErrorResponse","Code":"42601","Message":"error in argument for $1: tuple must have non-negative number of elements","Detail":"numberOfElements=-1\n--\nstatement name \"s_negative_tuple\"\n--\nportal name \"p_negative_tuple\"\n--\nstatement summary \"SELECT $1::r\""}
177177
{"Type":"ReadyForQuery","TxStatus":"I"}
178178

179179
# not enough bytes for element OID
@@ -198,7 +198,7 @@ ErrorResponse
198198
ReadyForQuery
199199
----
200200
{"Type":"ParseComplete"}
201-
{"Type":"ErrorResponse","Code":"42601","Message":"error in argument for $1: insufficient bytes reading element OID for binary format","Detail":"elementIdx=0 bufferLength=4 bufferStartIdx=4 bufferEndIdx=8"}
201+
{"Type":"ErrorResponse","Code":"42601","Message":"error in argument for $1: insufficient bytes reading element OID for binary format","Detail":"elementIdx=0 bufferLength=4 bufferStartIdx=4 bufferEndIdx=8\n--\nstatement name \"s_element_oid_no_bytes\"\n--\nportal name \"p_element_oid_no_bytes\"\n--\nstatement summary \"SELECT $1::r\""}
202202
{"Type":"ReadyForQuery","TxStatus":"I"}
203203

204204
# element OID not found
@@ -224,7 +224,7 @@ ErrorResponse
224224
ReadyForQuery
225225
----
226226
{"Type":"ParseComplete"}
227-
{"Type":"ErrorResponse","Code":"42601","Message":"error in argument for $1: element type not found for OID 0","Detail":"elementIdx=0 bufferLength=8 bufferStartIdx=4 bufferEndIdx=8"}
227+
{"Type":"ErrorResponse","Code":"42601","Message":"error in argument for $1: element type not found for OID 0","Detail":"elementIdx=0 bufferLength=8 bufferStartIdx=4 bufferEndIdx=8\n--\nstatement name \"s_element_oid_not_found\"\n--\nportal name \"p_element_oid_not_found\"\n--\nstatement summary \"SELECT $1::r\""}
228228
{"Type":"ReadyForQuery","TxStatus":"I"}
229229

230230
# not enough bytes for element size
@@ -250,7 +250,7 @@ ErrorResponse
250250
ReadyForQuery
251251
----
252252
{"Type":"ParseComplete"}
253-
{"Type":"ErrorResponse","Code":"42601","Message":"error in argument for $1: insufficient bytes reading element size for binary format","Detail":"elementIdx=0 bufferLength=8 bufferStartIdx=8 bufferEndIdx=12"}
253+
{"Type":"ErrorResponse","Code":"42601","Message":"error in argument for $1: insufficient bytes reading element size for binary format","Detail":"elementIdx=0 bufferLength=8 bufferStartIdx=8 bufferEndIdx=12\n--\nstatement name \"s_element_size_no_bytes\"\n--\nportal name \"p_element_size_no_bytes\"\n--\nstatement summary \"SELECT $1::r\""}
254254
{"Type":"ReadyForQuery","TxStatus":"I"}
255255

256256
# null element
@@ -297,7 +297,7 @@ ErrorResponse
297297
ReadyForQuery
298298
----
299299
{"Type":"ParseComplete"}
300-
{"Type":"ErrorResponse","Code":"42601","Message":"error in argument for $1: unsupported binary bool: "}
300+
{"Type":"ErrorResponse","Code":"42601","Message":"error in argument for $1: unsupported binary bool: ","Detail":"statement name \"s_element_needs_bytes\"\n--\nportal name \"p_element_needs_bytes\"\n--\nstatement summary \"SELECT $1::r\""}
301301
{"Type":"ReadyForQuery","TxStatus":"I"}
302302

303303
# not enough bytes for element
@@ -324,7 +324,7 @@ ErrorResponse
324324
ReadyForQuery
325325
----
326326
{"Type":"ParseComplete"}
327-
{"Type":"ErrorResponse","Code":"42601","Message":"error in argument for $1: insufficient bytes reading element for binary format","Detail":"elementIdx=0 bufferLength=12 bufferStartIdx=12 bufferEndIdx=13"}
327+
{"Type":"ErrorResponse","Code":"42601","Message":"error in argument for $1: insufficient bytes reading element for binary format","Detail":"elementIdx=0 bufferLength=12 bufferStartIdx=12 bufferEndIdx=13\n--\nstatement name \"s_element_no_bytes\"\n--\nportal name \"p_element_no_bytes\"\n--\nstatement summary \"SELECT $1::r\""}
328328
{"Type":"ReadyForQuery","TxStatus":"I"}
329329

330330
# Test binary encoding of a generic tuple result.

0 commit comments

Comments
 (0)