Bug Fix: Prepared Statements Bind Variables Nil Error #5441

PrismaPhonic · 2019-11-15T23:55:37Z

This PR fixes the bind variables nil error first discovered in issue #5255.

The fix involved explicitly setting BindVars to an empty map, rather than looping through and setting each BindVar to nil in the defer function.

I also added a recover to catch any panics that might happen as a result of nil BindVars when using FormatBindVariables in Logf.

… Also added a recover to catch panics that occur inside Logf due to FormatBindVariables call potentially panicking. Signed-off-by: Peter Farr <Peter@PrismaPhonic.com>

Signed-off-by: Peter Farr <Peter@PrismaPhonic.com>

deepthi · 2019-11-17T16:37:26Z

go/mysql/conn.go

-				if prepare.BindVars != nil {
-					for k := range prepare.BindVars {
-						prepare.BindVars[k] = nil
-					}
-				}


Though I agree that this is a cleaner and safer way of resetting PrepareData, I'm concerned that the fix might mask a deeper problem. Is it possible that there is a mismatch between ParamsCount and BindVars? Maybe we are being told to expect a certain number of bind variables (ParamsCount) but receiving a fewer number.

ok, so should we mask and report errors or something? or would rather have things immediately fail?

@deepthi That's a good point. Maybe the problem is that we are reusing stmtID values for different statements?

@PrismaPhonic Were you able to reproduce the problem with the reduced test case?

Also, although this is cleaner and safer than setting everything to nil, there is a performance cost to that. It was probably written this way to avoid allocating a new map on every query. This "fix" will put more load on the GC, which is something we shouldn't do in the hot path unless there's a very good reason.

The assumption written into this optimization seems to be that for a given stmtID, the set of bind var names will never change. Does anyone know of a valid situation in which that assumption is violated? If there is no such situation, then @deepthi is right that there is another bug here that we shouldn't cover up.

@deepthi will as far as I know we set the number of parameters when we check the :v prefix and send it back to the client. Therefore, if there was a mismatch I think the client might catch that.

@enisoc I dont know of a situation that will change the query and number of parameters for a given sstmtID.

OK this finally makes sense. The clue about vtg1 in #5441 (comment) was the key to finding the root cause.

The vtg1 entry in the map is getting added by the normalizer after we pass the map to VTGate.Execute(). The way to reproduce this is to prepare a query that also has some raw values, such as the 'blah' in select foo from bar where name in (?,'blah'). The normalizer will replace the 'blah' with :vtg1 and add vtg1 to the bindvars map with value 'blah'.

After executing, we set all bindvar map values to nil without deleting them, which would have been fine if the normalizer had not mutated our map in-place to add vtg1. Instead, the next time we call VTGate.Execute(), we pass a bindvars map with vtg1 already present (and set to nil). The normalizer sees this and thinks you have a pre-existing bindvar called vtg1 so when it needs to generate a bindvar name for 'blah', it increments to vtg2 to avoid a collision. Now vtg1 remains set in the map with value nil.

The fix for that is what this PR is already doing: make a new map every time. The only suggestion I have then is to add a comment explaining why this is necessary:

// Allocate a new bindvar map every time since VTGate.Execute() mutates it.

Added the comment with 4411cda.

enisoc · 2019-11-18T23:33:17Z

I noticed something weird about the example error message in #5255:

vtg1: bind variable is nil

As far as I can tell, the bind vars generated by the prepared statement code should remain v# (e.g. v1). A bind var called vtg1 should, if I'm reading the code correctly, only be possible if the original query contained a raw value that wasn't passed as a bind var to begin with. Those raw values get converted to vtg# bind vars by the normalizer. However, the normalizer seems to leave existing bind vars with their existing names.

Does anyone have any other example error messages for this case to compare?

enisoc · 2019-11-19T01:04:08Z

go/mysql/conn.go

-						prepare.BindVars[k] = nil
-					}
-				}
+				paramsCount := len(prepare.BindVars)


We should just use prepare.ParamsCount. The value of len(prepare.BindVars) could actually be greater than prepare.ParamsCount when there are raw values in the query, which get converted into additional bindvars by the normalizer.

Good call out. Will adjust after the party tonight. Thanks!

Adjusted with 0da79a8.

Signed-off-by: Peter Farr <Peter@PrismaPhonic.com>

saifalharthi

I took a deeper look on this and it looks good to me!

enisoc · 2019-11-19T17:52:24Z

go/vt/vtgate/logstats.go

@@ -125,6 +127,15 @@ func (stats *LogStats) Logf(w io.Writer, params url.Values) error {
 		return nil
 	}

+	// FormatBindVariables call might panic so we're going to catch it here and print out the stack trace to help us


Doesn't an uncaught panic already print a stack trace? Or is the problem that someone else has been recovering the panic somewhere else in the call stack?

You're right that an uncaught panic already prints a stack trace. @sougou had asked me offline to use recover() to handle the place where the panic was occurring as an extra safety net. I was hoping he would comment here on the PR to clarify the full extent of what he wanted to achieve with the recover(). I've yet to have an opportunity to sync up with him about this part. Perhaps he meant without the explicit panic. @sougou?

I heard that @sougou can be found at the PlanetScale booth at KubeCon. You should try to find him there. :)

Chatted with him. He meant without an explicit panic and deepthi clarified that vtgate by design should never panic. Correcting now

Adjusted c4270d2. PTAL

Signed-off-by: Peter Farr <Peter@PrismaPhonic.com>

enisoc

LGTM

deepthi · 2019-11-23T00:15:03Z

nice work @PrismaPhonic!

PrismaPhonic requested a review from sougou as a code owner November 15, 2019 23:55

Fixed nil bind variables error by resetting bindvars to an empty map.…

e83a02c

… Also added a recover to catch panics that occur inside Logf due to FormatBindVariables call potentially panicking. Signed-off-by: Peter Farr <Peter@PrismaPhonic.com>

PrismaPhonic force-pushed the fix/prepared-statements-bind-vars-nil branch from 3b38e60 to e83a02c Compare November 15, 2019 23:59

Changed import order back. Order was auto-changed by IDE on save

bb7f9fb

Signed-off-by: Peter Farr <Peter@PrismaPhonic.com>

deepthi reviewed Nov 17, 2019

View reviewed changes

enisoc reviewed Nov 19, 2019

View reviewed changes

Using stored ParamsCount for capacity per review suggestion.

0da79a8

Signed-off-by: Peter Farr <Peter@PrismaPhonic.com>

PrismaPhonic force-pushed the fix/prepared-statements-bind-vars-nil branch from af722d8 to 0da79a8 Compare November 19, 2019 09:26

Added explanation comment per review suggestion.

4411cda

Signed-off-by: Peter Farr <Peter@PrismaPhonic.com>

saifalharthi approved these changes Nov 19, 2019

View reviewed changes

enisoc reviewed Nov 19, 2019

View reviewed changes

Removed explicit panic after offline talk with sougou and deepthi

c4270d2

Signed-off-by: Peter Farr <Peter@PrismaPhonic.com>

PrismaPhonic force-pushed the fix/prepared-statements-bind-vars-nil branch from fe7c867 to c4270d2 Compare November 20, 2019 19:57

PrismaPhonic requested review from enisoc and deepthi November 20, 2019 20:00

enisoc approved these changes Nov 20, 2019

View reviewed changes

enisoc merged commit f7205b8 into vitessio:master Nov 22, 2019

enisoc deleted the fix/prepared-statements-bind-vars-nil branch November 22, 2019 23:47

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Bug Fix: Prepared Statements Bind Variables Nil Error #5441

Bug Fix: Prepared Statements Bind Variables Nil Error #5441

PrismaPhonic commented Nov 15, 2019

deepthi Nov 17, 2019

teejae Nov 18, 2019

enisoc Nov 18, 2019

enisoc Nov 18, 2019 •

edited

Loading

saifalharthi Nov 18, 2019

enisoc Nov 19, 2019

PrismaPhonic Nov 19, 2019

enisoc commented Nov 18, 2019

enisoc Nov 19, 2019

PrismaPhonic Nov 19, 2019

PrismaPhonic Nov 19, 2019

saifalharthi left a comment

enisoc Nov 19, 2019

PrismaPhonic Nov 19, 2019 •

edited

Loading

enisoc Nov 19, 2019

PrismaPhonic Nov 20, 2019

PrismaPhonic Nov 20, 2019

enisoc left a comment

deepthi commented Nov 23, 2019

Bug Fix: Prepared Statements Bind Variables Nil Error #5441

Bug Fix: Prepared Statements Bind Variables Nil Error #5441

Conversation

PrismaPhonic commented Nov 15, 2019

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

enisoc Nov 18, 2019 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

enisoc commented Nov 18, 2019

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

saifalharthi left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

PrismaPhonic Nov 19, 2019 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

enisoc left a comment

Choose a reason for hiding this comment

deepthi commented Nov 23, 2019

enisoc Nov 18, 2019 •

edited

Loading

PrismaPhonic Nov 19, 2019 •

edited

Loading