Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Bug Report: FormatBindVariables return invalid JSON string #12872

Open
DeathBorn opened this issue Apr 11, 2023 · 0 comments · May be fixed by #15271
Open

Bug Report: FormatBindVariables return invalid JSON string #12872

DeathBorn opened this issue Apr 11, 2023 · 0 comments · May be fixed by #15271
Labels
Component: Query Serving Type: Bug

Comments

@DeathBorn
Copy link
Contributor

Overview of the Issue

Vtgate query logs are not escaped properly. Parsing becomes impossible.

Reproduction Steps

Provided test is enough to reproduce the issue.

func TestLogStatsFormatHex(t *testing.T) {
	logStats := NewLogStats(
		context.Background(),
		"test",
		"delete from name_lastname_keyspace_id_map where name = :v1 and keyspace_id = :v3",
		"suuid",
		map[string]*querypb.BindVariable{
			"v1": sqltypes.ValueBindVariable(sqltypes.NewVarChar("foo")),
			"v2": sqltypes.BytesBindVariable([]byte("\x16k@\xb4J\xbaK\xd6")),
		},
	)
	logStats.StartTime = time.Date(2017, time.January, 1, 1, 2, 3, 0, time.UTC)
	logStats.EndTime = time.Date(2017, time.January, 1, 1, 2, 4, 1234, time.UTC)
	logStats.Keyspace = "ks"
	logStats.Table = "table"
	logStats.TabletType = "MASTER"

	params := map[string][]string{"full": {}}

	*streamlog.RedactDebugUIQueries = false
	*streamlog.QueryLogFormat = "json"
	got := testFormat(logStats, url.Values(params))

	fmt.Println(fmt.Sprintf("QUERY: %v", logStats))
	fmt.Println(fmt.Sprintf("GOT: %v", got))

	var parsed map[string]interface{}
	err := json.Unmarshal([]byte(got), &parsed)
	if err != nil {
		t.Errorf("logstats format: error unmarshaling json: %v -- got:\n%v", err, got)
	}
	formatted, err := json.MarshalIndent(parsed, "", "    ")
	if err != nil {
		t.Errorf("logstats format: error marshaling json: %v -- got:\n%v", err, got)
	}
	
	want := "{\n    \"BindVars\": {\n        \"v1\": {\n            \"type\": \"VARCHAR\",\n            \"value\": \"foo\"\n        },\n        \"v2\": {\n            \"type\": \"VARBINARY\",\n            \"value\": \"\x16k@\xb4J\xbaK\xd6\"\n        }\n    },\n    \"CommitTime\": 0,\n    \"Effective Caller\": \"\",\n    \"End\": \"2017-01-01 01:02:04.000001\",\n    \"Error\": \"\",\n    \"ExecuteTime\": 0,\n    \"ImmediateCaller\": \"\",\n    \"InTransaction\": false,\n    \"Keyspace\": \"ks\",\n    \"Method\": \"test\",\n    \"PlanTime\": 0,\n    \"RemoteAddr\": \"\",\n    \"RowsAffected\": 0,\n    \"SQL\": \"delete from name_lastname_keyspace_id_map where name = :v1 and keyspace_id = :v3\",\n    \"SessionUUID\": \"suuid\",\n    \"ShardQueries\": 0,\n    \"Start\": \"2017-01-01 01:02:03.000000\",\n    \"StmtType\": \"\",\n    \"Table\": \"table\",\n    \"TabletType\": \"MASTER\",\n    \"TotalTime\": 1.000001,\n    \"Username\": \"\"\n}"
	if string(formatted) != want {
		t.Errorf("logstats format: got:\n%q\nwant:\n%v\n", string(formatted), want)
	}
}

Results are

go test -v -timeout 30s -run ^TestLogStatsFormatHex$ vitess.io/vitess/go/vt/vtgate  -args  -logtostderr true -V 100
ERROR: logging before flag.Parse: I0411 16:08:34.581189   61143 buffer.go:144] vtgate buffer not enabled.
ERROR: logging before flag.Parse: I0411 16:08:34.581403   61143 discoverygateway.go:122] loading tablets for cells:
ERROR: logging before flag.Parse: I0411 16:08:34.581458   61143 gateway.go:103] Gateway waiting for serving tablets of types [] ...
ERROR: logging before flag.Parse: I0411 16:08:34.581493   61143 gateway.go:111] Waiting for tablets completed
ERROR: logging before flag.Parse: I0411 16:08:34.581528   61143 vtgate.go:104] Transaction mode: 'MULTI'
ERROR: logging before flag.Parse: I0411 16:08:34.582318   61143 vschema_manager.go:96] Received vschema update
ERROR: logging before flag.Parse: I0411 16:08:34.582677   61143 streamlog.go:158] Streaming logs from VTGate at /debug/querylog.
=== RUN   TestLogStatsFormatHex
QUERY: &{context.Background test ks MASTER table  delete from name_lastname_keyspace_id_map where name = :v1 and keyspace_id = :v3 map[v1:type:VARCHAR value:"foo" v2:type:VARBINARY value:"\x16k@\xb4J\xbaK\xd6"] 2017-01-01 01:02:03 +0000 UTC 2017-01-01 01:02:04.000001234 +0000 UTC 0 0 0 0s 0s 0s <nil> false suuid}
GOT: {"Method": "test", "RemoteAddr": "", "Username": "", "ImmediateCaller": "", "Effective Caller": "", "Start": "2017-01-01 01:02:03.000000", "End": "2017-01-01 01:02:04.000001", "TotalTime": 1.000001, "PlanTime": 0, "ExecuteTime": 0, "CommitTime": 0, "StmtType": "", "SQL": "delete from name_lastname_keyspace_id_map where name = :v1 and keyspace_id = :v3", "BindVars": {"v1": {"type": "VARCHAR", "value": "foo"}, "v2": {"type": "VARBINARY", "value": "\x16k@\xb4J\xbaK\xd6"}}, "ShardQueries": 0, "RowsAffected": 0, "Error": "", "Keyspace": "ks", "Table": "table", "TabletType": "MASTER", "InTransaction": false, "SessionUUID": "suuid"}

    logstats_test.go:73: logstats format: error unmarshaling json: invalid character 'x' in string escape code -- got:
        {"Method": "test", "RemoteAddr": "", "Username": "", "ImmediateCaller": "", "Effective Caller": "", "Start": "2017-01-01 01:02:03.000000", "End": "2017-01-01 01:02:04.000001", "TotalTime": 1.000001, "PlanTime": 0, "ExecuteTime": 0, "CommitTime": 0, "StmtType": "", "SQL": "delete from name_lastname_keyspace_id_map where name = :v1 and keyspace_id = :v3", "BindVars": {"v1": {"type": "VARCHAR", "value": "foo"}, "v2": {"type": "VARBINARY", "value": "\x16k@\xb4J\xbaK\xd6"}}, "ShardQueries": 0, "RowsAffected": 0, "Error": "", "Keyspace": "ks", "Table": "table", "TabletType": "MASTER", "InTransaction": false, "SessionUUID": "suuid"}
    logstats_test.go:82: logstats format: got:
        "null"
        want:
        {
            "BindVars": {
                "v1": {
                    "type": "VARCHAR",
                    "value": "foo"
                },
                "v2": {
                    "type": "VARBINARY",
                    "value": "k@�J�K�"
                }
            },
            "CommitTime": 0,
            "Effective Caller": "",
            "End": "2017-01-01 01:02:04.000001",
            "Error": "",
            "ExecuteTime": 0,
            "ImmediateCaller": "",
            "InTransaction": false,
            "Keyspace": "ks",
            "Method": "test",
            "PlanTime": 0,
            "RemoteAddr": "",
            "RowsAffected": 0,
            "SQL": "delete from name_lastname_keyspace_id_map where name = :v1 and keyspace_id = :v3",
            "SessionUUID": "suuid",
            "ShardQueries": 0,
            "Start": "2017-01-01 01:02:03.000000",
            "StmtType": "",
            "Table": "table",
            "TabletType": "MASTER",
            "TotalTime": 1.000001,
            "Username": ""
        }
--- FAIL: TestLogStatsFormatHex (0.00s)

Binary Version

v11, but this should be happening in all versions

Operating System and Environment details

Centos 7/8, OSX

Log Fragments

No response
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
Component: Query Serving Type: Bug
Projects
None yet
Milestone
No milestone
2 participants
@DeathBorn @ajm188