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

… 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.

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.

absurdfarce added 3 commits June 25, 2024 00:00

Fix root cause of the issue

20f0008

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

c9f749c

… 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

415052d

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

Open

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

Adding test per code review comments

0dec0bc

joao-r-reis reviewed Jun 25, 2024

View reviewed changes

Clean up logging

c51a80f

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

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

Are you sure you want to change the base?

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

mpenick commented Jul 2, 2024 •

edited

Loading