Remove quotes from keyspace names before sending them back in set_keyspace result messages #129

absurdfarce · 2024-06-25T05:06:49Z

As discussed in #128

lukasz-antoniak · 2024-06-25T07:17:52Z

Maybe also change below test accordingly to test USE statement with quoted keyspace:

func TestProxy_UseKeyspace(t *testing.T) {
	ctx, cancel := context.WithCancel(context.Background())
	tester, proxyContactPoint, err := setupProxyTest(ctx, 1, nil)
	defer func() {
		cancel()
		tester.shutdown()
	}()
	require.NoError(t, err)

	cl := connectTestClient(t, ctx, proxyContactPoint)

	tests := []struct {
		name              string
		keyspaceRequested string
		keyspaceExpected  string
	}{
		{"UnquotedKeyspace", "system", "system"},
		{"QuotedKeyspace", "\"system\"", "system"},
	}

	for _, test := range tests {
		t.Run(test.name, func(t *testing.T) {
			resp, err := cl.SendAndReceive(ctx, frame.NewFrame(primitive.ProtocolVersion4, 0, &message.Query{Query: "USE " + test.keyspaceRequested}))
			require.NoError(t, err)

			assert.Equal(t, primitive.OpCodeResult, resp.Header.OpCode)
			res, ok := resp.Body.Message.(*message.SetKeyspaceResult)
			require.True(t, ok, "expected set keyspace result")
			assert.Equal(t, test.keyspaceExpected, res.Keyspace)
		})
	}
}

absurdfarce · 2024-06-25T16:41:15Z

Excellent idea @lukasz-antoniak! I'll add a test in there forthwith!

joao-r-reis · 2024-06-25T19:11:09Z

proxy/proxy.go

 		if err != nil {
 			c.proxy.logger.Error("error parsing query to see if it's handled", zap.Error(err))
 			c.send(raw.Header, &message.Invalid{ErrorMessage: err.Error()})
 		} else {
 			c.interceptSystemQuery(raw.Header, stmt)
 		}
 	} else {
+		c.proxy.logger.Debug("Query is not handled")


Maybe you added these in your testing but I'm not sure if you want to leave them? If you want to leave them then I'd consider adding some context to the log like the query string

So there's actually already logging of the incoming query a few lines above this but it does wind up making things pretty verbose:

$ ./cql-proxy -c 127.0.0.1 --bind ":9142" --debug ... 2024-06-27T17:17:59.330-0500 DEBUG proxy/proxy.go:670 handling query {"query": "SELECT * FROM system.peers_v2", "stream": 3} 2024-06-27T17:17:59.330-0500 DEBUG proxy/proxy.go:675 Query is handled 2024-06-27T17:17:59.330-0500 DEBUG proxy/proxy.go:670 handling query {"query": "SELECT * FROM system.local WHERE key='local'", "stream": 4} 2024-06-27T17:17:59.330-0500 DEBUG proxy/proxy.go:675 Query is handled 2024-06-27T17:17:59.331-0500 DEBUG proxy/proxy.go:670 handling query {"query": "SELECT * FROM system.peers", "stream": 5} 2024-06-27T17:17:59.331-0500 DEBUG proxy/proxy.go:675 Query is handled 2024-06-27T17:17:59.334-0500 DEBUG proxy/proxy.go:670 handling query {"query": "SELECT * FROM system_schema.keyspaces", "stream": 6} 2024-06-27T17:17:59.334-0500 DEBUG proxy/proxy.go:683 Query is not handled 2024-06-27T17:17:59.336-0500 DEBUG proxy/proxy.go:670 handling query {"query": "SELECT * FROM system_schema.tables", "stream": 7} 2024-06-27T17:17:59.336-0500 DEBUG proxy/proxy.go:683 Query is not handled 2024-06-27T17:17:59.336-0500 DEBUG proxy/proxy.go:670 handling query {"query": "SELECT * FROM system_schema.columns", "stream": 8} 2024-06-27T17:17:59.336-0500 DEBUG proxy/proxy.go:683 Query is not handled 2024-06-27T17:17:59.336-0500 DEBUG proxy/proxy.go:670 handling query {"query": "SELECT * FROM system_schema.types", "stream": 9} 2024-06-27T17:17:59.337-0500 DEBUG proxy/proxy.go:683 Query is not handled 2024-06-27T17:17:59.337-0500 DEBUG proxy/proxy.go:670 handling query {"query": "SELECT * FROM system_schema.functions", "stream": 10} 2024-06-27T17:17:59.337-0500 DEBUG proxy/proxy.go:683 Query is not handled 2024-06-27T17:17:59.337-0500 DEBUG proxy/proxy.go:670 handling query {"query": "SELECT * FROM system_schema.aggregates", "stream": 11} 2024-06-27T17:17:59.337-0500 DEBUG proxy/proxy.go:683 Query is not handled ...

Seems like we'd be better off merging all of that logging into a single log statement. I'll work on making that happen.

With the most recent change this now becomes:

$ ./cql-proxy -c 127.0.0.1 --bind ":9142" --debug 2024-06-27T17:26:15.710-0500 DEBUG proxycore/cluster.go:192 connecting to cluster {"connect timeout": "10s"} 2024-06-27T17:26:15.721-0500 INFO proxycore/cluster.go:263 adding host to the cluster {"host": "127.0.0.1:9042"} 2024-06-27T17:26:15.721-0500 DEBUG proxycore/cluster.go:164 control connection connected {"endpoint": "127.0.0.1:9042"} 2024-06-27T17:26:15.721-0500 INFO proxy/proxy.go:376 no local DC configured using DC from the first successful contact point {"dc": "datacenter1"} 2024-06-27T17:26:15.721-0500 DEBUG proxycore/connpool.go:132 creating connection pool {"endpoint": "127.0.0.1:9042", "connect timeout": "10s"} 2024-06-27T17:26:15.722-0500 INFO proxy/run.go:286 proxy is listening {"address": "[::]:9142"} 2024-06-27T17:26:21.134-0500 DEBUG proxy/proxy.go:672 Query handled by proxy {"query": "SELECT * FROM system.peers_v2", "stream": 3} 2024-06-27T17:26:21.134-0500 DEBUG proxy/proxy.go:672 Query handled by proxy {"query": "SELECT * FROM system.local WHERE key='local'", "stream": 4} 2024-06-27T17:26:21.134-0500 DEBUG proxy/proxy.go:672 Query handled by proxy {"query": "SELECT * FROM system.peers", "stream": 5} 2024-06-27T17:26:21.135-0500 DEBUG proxy/proxy.go:680 Query not handled by proxy, forwarding {"query": "SELECT * FROM system_schema.keyspaces", "stream": 6} 2024-06-27T17:26:21.138-0500 DEBUG proxy/proxy.go:680 Query not handled by proxy, forwarding {"query": "SELECT * FROM system_schema.tables", "stream": 7} 2024-06-27T17:26:21.138-0500 DEBUG proxy/proxy.go:680 Query not handled by proxy, forwarding {"query": "SELECT * FROM system_schema.columns", "stream": 8} 2024-06-27T17:26:21.138-0500 DEBUG proxy/proxy.go:680 Query not handled by proxy, forwarding {"query": "SELECT * FROM system_schema.types", "stream": 9} 2024-06-27T17:26:21.138-0500 DEBUG proxy/proxy.go:680 Query not handled by proxy, forwarding {"query": "SELECT * FROM system_schema.functions", "stream": 10} 2024-06-27T17:26:21.138-0500 DEBUG proxy/proxy.go:680 Query not handled by proxy, forwarding {"query": "SELECT * FROM system_schema.aggregates", "stream": 11} 2024-06-27T17:26:21.138-0500 DEBUG proxy/proxy.go:680 Query not handled by proxy, forwarding {"query": "SELECT * FROM system_schema.triggers", "stream": 12} 2024-06-27T17:26:21.138-0500 DEBUG proxy/proxy.go:680 Query not handled by proxy, forwarding {"query": "SELECT * FROM system_schema.indexes", "stream": 13} 2024-06-27T17:26:21.138-0500 DEBUG proxy/proxy.go:680 Query not handled by proxy, forwarding {"query": "SELECT * FROM system_schema.views", "stream": 14} 2024-06-27T17:26:21.138-0500 DEBUG proxy/proxy.go:680 Query not handled by proxy, forwarding {"query": "SELECT * from system_virtual_schema.keyspaces", "stream": 15} 2024-06-27T17:26:21.138-0500 DEBUG proxy/proxy.go:680 Query not handled by proxy, forwarding {"query": "SELECT * from system_virtual_schema.tables", "stream": 16} 2024-06-27T17:26:21.138-0500 DEBUG proxy/proxy.go:680 Query not handled by proxy, forwarding {"query": "SELECT * from system_virtual_schema.columns", "stream": 17} 2024-06-27T17:26:21.158-0500 DEBUG proxy/proxy.go:672 Query handled by proxy {"query": "use \"FOO\"", "stream": 2} 2024-06-27T17:26:21.159-0500 DEBUG proxycore/connpool.go:132 creating connection pool {"endpoint": "127.0.0.1:9042", "connect timeout": "10s"} 2024-06-27T17:26:21.162-0500 DEBUG proxy/proxy.go:672 Query handled by proxy {"query": "USE \"FOO\"", "stream": 3} 2024-06-27T17:26:21.163-0500 DEBUG proxy/proxy.go:680 Query not handled by proxy, forwarding {"query": "select * from bar", "stream": 4}

mpenick · 2024-07-02T14:58:11Z

What's wrong with the original patch? #127. It handles double quoting in the identifier.

proxy/proxy.go

lukasz-antoniak

Not sure now if it is better to handle quoting in the parser. In other places in the code we do parser.IdentifierFromString(keyspace) to unquote keyspace.

Approved too early.

… clear way to tell from logs whether a given query was handled by the proxy or passed on to upstream servers. Added some minimal logging to provide some additional info on this point.

absurdfarce · 2024-07-29T22:25:41Z

proxy/proxy.go

+			switch {
+			case errors.As(err, &cqlError):
+				errMsg := cqlError.Message
+				c.send(hdr, errMsg)


Doesn't this also represent a ServerError? CqlErrors come off of maybeCreateSession() for things like protocol violations: a bad handshake, a destination server complaining about auth, etc. From the perspective of a client connected to cql-proxy don't those also represent ServerErrors?

It does, but then the specific error message is passed to the client like Keyspace XYZ does not exist instead of generic Proxy unable to create new session for keyspace.

All I mean here is that this should be:

c.send(hdr, &message.ServerError{ErrorMessage: errMsg})

That way whatever subsequent processing the proxy applies to ServerErrors is also applied to this response... which seems correct. And IIUC that should result in a meaningful message being delivered to the client as well, right?

This is a relatively minor point and shouldn't hold up a release or anything... I'm just wondering.

absurdfarce · 2024-07-30T16:32:20Z

👍 Looks good... thanks for getting this over the finish line @lukasz-antoniak !

absurdfarce linked an issue Jun 25, 2024 that may be closed by this pull request

cql-proxy is not removing quotes from the keyspace in set_keyspace responses which can confuse some drivers #128

Closed

absurdfarce requested review from lukasz-antoniak and joao-r-reis June 25, 2024 05:07

joao-r-reis reviewed Jun 25, 2024

View reviewed changes

lukasz-antoniak previously approved these changes Jul 26, 2024

View reviewed changes

proxy/proxy.go Show resolved Hide resolved

lukasz-antoniak reviewed Jul 26, 2024

View reviewed changes

lukasz-antoniak self-requested a review July 26, 2024 05:31

absurdfarce and others added 5 commits July 29, 2024 17:54

Drive-by fix while working on this issue. Noted there wasn't really a…

54ceb7e

… clear way to tell from logs whether a given query was handled by the proxy or passed on to upstream servers. Added some minimal logging to provide some additional info on this point.

Added some explanatory comments

5813a9f

Adding test per code review comments

dbdd986

Clean up logging

bd60d74

Return detailed C* error for USE query. More test comments

cd418fe

lukasz-antoniak force-pushed the issue128 branch from c51a80f to cd418fe Compare July 29, 2024 16:45

absurdfarce commented Jul 29, 2024

View reviewed changes

Review comments

68126a8

lukasz-antoniak approved these changes Jul 30, 2024

View reviewed changes

lukasz-antoniak merged commit f856ae1 into main Jul 30, 2024
2 checks passed

lukasz-antoniak deleted the issue128 branch July 30, 2024 16:40

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Remove quotes from keyspace names before sending them back in set_keyspace result messages #129

Remove quotes from keyspace names before sending them back in set_keyspace result messages #129

absurdfarce commented Jun 25, 2024

lukasz-antoniak commented Jun 25, 2024

absurdfarce commented Jun 25, 2024

joao-r-reis Jun 25, 2024

absurdfarce Jun 27, 2024

absurdfarce Jun 27, 2024

mpenick commented Jul 2, 2024 •

edited

Loading

lukasz-antoniak left a comment •

edited

Loading

absurdfarce Jul 29, 2024

lukasz-antoniak Jul 30, 2024

absurdfarce Jul 30, 2024

absurdfarce commented Jul 30, 2024 •

edited

Loading

Remove quotes from keyspace names before sending them back in set_keyspace result messages #129

Remove quotes from keyspace names before sending them back in set_keyspace result messages #129

Conversation

absurdfarce commented Jun 25, 2024

lukasz-antoniak commented Jun 25, 2024

absurdfarce commented Jun 25, 2024

joao-r-reis Jun 25, 2024

Choose a reason for hiding this comment

absurdfarce Jun 27, 2024

Choose a reason for hiding this comment

absurdfarce Jun 27, 2024

Choose a reason for hiding this comment

mpenick commented Jul 2, 2024 • edited Loading

lukasz-antoniak left a comment • edited Loading

Choose a reason for hiding this comment

absurdfarce Jul 29, 2024

Choose a reason for hiding this comment

lukasz-antoniak Jul 30, 2024

Choose a reason for hiding this comment

absurdfarce Jul 30, 2024

Choose a reason for hiding this comment

absurdfarce commented Jul 30, 2024 • edited Loading

mpenick commented Jul 2, 2024 •

edited

Loading

lukasz-antoniak left a comment •

edited

Loading

absurdfarce commented Jul 30, 2024 •

edited

Loading