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.

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

sqlite: fix nil deref on missing response #32

Merged
merged 1 commit into from
Oct 11, 2020

Conversation

holiman
Copy link
Contributor

@holiman holiman commented Oct 7, 2020

I tested it out a bit, and immediately hit this error:

020/10/07 13:52:26 [ERROR] Could not store request log: sqlite: could not prepare statement: context canceled
runtime error: invalid memory address or nil pointer dereference

goroutine 102 [running]:
runtime/debug.Stack(0x1, 0x0, 0x0)
	/usr/local/go/src/runtime/debug/stack.go:24 +0x9d
runtime/debug.PrintStack()
	/usr/local/go/src/runtime/debug/stack.go:16 +0x22
github.com/99designs/gqlgen/graphql.DefaultRecover(0x103cb20, 0xc000190360, 0xa327a0, 0x13bd090, 0xc0001a8410, 0x0)
	/home/user/go/pkg/mod/github.com/99designs/gqlgen@v0.11.3/graphql/recovery.go:16 +0xa7
github.com/dstotijn/hetty/pkg/api.(*executionContext)._Query_httpRequestLog.func1(0xc00017c3f0, 0xc00017c530, 0xc0001a9468)
	/home/user/go/src/github.com/dstotijn/hetty/pkg/api/generated.go:930 +0x78
panic(0xa327a0, 0x13bd090)
	/usr/local/go/src/runtime/panic.go:969 +0x166
github.com/dstotijn/hetty/pkg/db/sqlite.(*Client).queryHeaders(0xc0000100e0, 0x103cb20, 0xc000190360, 0xc00054cd00, 0xb, 0x10, 0xc000130280, 0x2, 0x2, 0xc0001302c0, ...)
	/home/user/go/src/github.com/dstotijn/hetty/pkg/db/sqlite/sqlite.go:488 +0x4c6
github.com/dstotijn/hetty/pkg/db/sqlite.(*Client).FindRequestLogByID(0xc0000100e0, 0x103cb20, 0xc000190360, 0x6a, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
	/home/user/go/src/github.com/dstotijn/hetty/pkg/db/sqlite/sqlite.go:208 +0x65c
github.com/dstotijn/hetty/pkg/reqlog.(*Service).FindRequestLogByID(...)
	/home/user/go/src/github.com/dstotijn/hetty/pkg/reqlog/reqlog.go:75
github.com/dstotijn/hetty/pkg/api.(*queryResolver).HTTPRequestLog(0xc0000be078, 0x103cb20, 0xc000190360, 0x6a, 0xc0002e4868, 0xc000600000, 0x7083534e1108)
	/home/user/go/src/github.com/dstotijn/hetty/pkg/api/resolvers.go:41 +0xa9
github.com/dstotijn/hetty/pkg/api.(*executionContext)._Query_httpRequestLog.func2(0x103cb20, 0xc000190360, 0x20, 0xa78e00, 0xc000190301, 0xc0001301e0)
	/home/user/go/src/github.com/dstotijn/hetty/pkg/api/generated.go:951 +0xf2
github.com/99designs/gqlgen/graphql/executor.processExtensions.func3(0x103cb20, 0xc000190360, 0xc0001301e0, 0xc000190390, 0xc0001903c0, 0x0, 0x0)
	/home/user/go/pkg/mod/github.com/99designs/gqlgen@v0.11.3/graphql/executor/extensions.go:62 +0x3a
github.com/dstotijn/hetty/pkg/api.(*executionContext)._Query_httpRequestLog(0xc00017c3f0, 0x103cb20, 0xc000190330, 0xc000165400, 0xc0005ca280, 0x8, 0x8, 0x0, 0x0)
	/home/user/go/src/github.com/dstotijn/hetty/pkg/api/generated.go:949 +0x2af
github.com/dstotijn/hetty/pkg/api.(*executionContext)._Query.func1(0x0, 0x0)
	/home/user/go/src/github.com/dstotijn/hetty/pkg/api/generated.go:2291 +0x9c
github.com/99designs/gqlgen/graphql.(*FieldSet).Dispatch(0xc00016c190)
	/home/user/go/pkg/mod/github.com/99designs/gqlgen@v0.11.3/graphql/fieldset.go:34 +0x1d4
github.com/dstotijn/hetty/pkg/api.(*executionContext)._Query(0xc00017c3f0, 0x103cb20, 0xc000190300, 0xc0001f4b80, 0x1, 0x1, 0x413b56, 0xc000190300)
	/home/user/go/src/github.com/dstotijn/hetty/pkg/api/generated.go:2316 +0x413
github.com/dstotijn/hetty/pkg/api.(*executableSchema).Exec.func1(0x103cb20, 0xc000190300, 0x10)
	/home/user/go/src/github.com/dstotijn/hetty/pkg/api/generated.go:243 +0x7b
github.com/99designs/gqlgen/graphql/executor.(*Executor).DispatchOperation.func1.1.1(0x103cb20, 0xc000190300, 0xc00017c430)
	/home/user/go/pkg/mod/github.com/99designs/gqlgen@v0.11.3/graphql/executor/executor.go:105 +0x43
github.com/99designs/gqlgen/graphql/executor.processExtensions.func2(0x103cb20, 0xc000190300, 0xc00017c430, 0x10241e0)
	/home/user/go/pkg/mod/github.com/99designs/gqlgen@v0.11.3/graphql/executor/extensions.go:59 +0x3a
github.com/99designs/gqlgen/graphql/executor.(*Executor).DispatchOperation.func1.1(0x103cb20, 0xc0001902a0, 0xc000190180)
	/home/user/go/pkg/mod/github.com/99designs/gqlgen@v0.11.3/graphql/executor/executor.go:104 +0x12a
github.com/99designs/gqlgen/graphql/handler/transport.POST.Do(0x103b720, 0xc0001e4e00, 0xc00054c500, 0x103b0a0, 0xc000516000)
	/home/user/go/pkg/mod/github.com/99designs/gqlgen@v0.11.3/graphql/handler/transport/http_post.go:52 +0x353
github.com/99designs/gqlgen/graphql/handler.(*Server).ServeHTTP(0xc00000f9a0, 0x103b720, 0xc0001e4e00, 0xc00054c500)
	/home/user/go/pkg/mod/github.com/99designs/gqlgen@v0.11.3/graphql/handler/server.go:115 +0x1fd
github.com/gorilla/mux.(*Router).ServeHTTP(0xc0003360c0, 0x103b720, 0xc0001e4e00, 0xc00054c200)
	/home/user/go/pkg/mod/github.com/gorilla/mux@v1.7.4/mux.go:210 +0xe2
net/http.serverHandler.ServeHTTP(0xc00032a1c0, 0x103b720, 0xc0001e4e00, 0xc00054c200)
	/usr/local/go/src/net/http/server.go:2807 +0xa3
net/http.(*conn).serve(0xc0000b2c80, 0x103ca60, 0xc000298e40)
	/usr/local/go/src/net/http/server.go:1895 +0x86c
created by net/http.(*Server).Serve
	/usr/local/go/src/net/http/server.go:2933 +0x35c
runtime error: invalid memory address or nil pointer dereference

It seems that if the response either is not saved (or perhaps not yet saved?), the reqLogs[i].Response was nil, causing a crash.
I also rewrote the loops to be more go-idiomatic.

Copy link

@RiRa12621 RiRa12621 left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We probably need some tests in the future to not rely on someone detecting it by hand but that looks fine to me

Copy link
Owner

@dstotijn dstotijn left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks for the PR @holiman, left a question/remark regarding the request logs, but the other changes (response logs) LGTM!

if err != nil {
return fmt.Errorf("could not query request headers: %v", err)
}
reqLogs[i].Request.Header = headers
reqLog.Request.Header = headers
Copy link
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Manually tested this, and the retrieved request headers aren't included in the API response. I believe it's because reqLog.Request is a value and not a pointer, so the original reqLogs that is returned upstream won't be mutated. But because http.Header's underlying type is a map (which holds a reference), we could keep the for _, reqLog (I agree it's more idiomatic) and fill (copy) the found headers like so:

Suggested change
reqLog.Request.Header = headers
for key, value := range headers {
reqLog.Request.Header[key] = value
}

Curious to hear your thoughts @holiman.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Hm, maybe it would be better to change the method signature (and really, in general) to use pointers instead? So you'd use reqLogs []*reqlog.Request. I find that often makes it easier to reason about

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Your proposed variant uses the fact that the copied Request has copied the same pointer to a map, and thus you access the same underlying map. So mutating the original headers-map although the caller passed a copy. It's a bit of a hacky solution to the problem.

Copy link
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This might be a bit personal/subjective, but I typically avoid using/passing around slices of pointers; don't really see the added benefit in this use case. Thinking about this some more IMHO it's actually not that bad to range over the slice and use the index to mutate the values of the slice, e.g. what we now do in master. I'd opt for this PR to be just this change.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I've changed the PR to now be only that change. However, since the egress-object is by-value (only the ingress Response field is a reference), it means that none of the request headers become set. So this PR fixes the nil deref-panic, but doesn't fix the request headers.

Copy link
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

However, since the egress-object is by-value (only the ingress Response field is a reference), it means that none of the request headers become set. So this PR fixes the nil deref-panic, but doesn't fix the request headers.

Are you sure about the request headers not being set? Just tested this manually, and the request headers are getting set. While indeed the Request field on the reqlog.Request struct is a value and not a pointer, because we're using the index when ranging (ref) and setting the headers via reqLogs[i].Request.Header (ref), we're actually mutating the items referenced by the slice.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Are you sure about the request headers not being set? Just tested this manually,

You're right. I tested it too, but apparently I tested against the wrong binary.

@holiman
Copy link
Contributor Author

holiman commented Oct 8, 2020

Unless you change the api to take slices (which I think would be best), I could change my PR to look something like this .. ? That properly closes the statements before doing the next one, instead of deferring both to the end.

func copyHeaders(dst, src http.Header) {
	for k, v := range src {
		dst[k] = v
	}
}

func (c *Client) queryHeaders(
	ctx context.Context,
	query httpRequestLogsQuery,
	reqLogs []reqlog.Request,
) error {

	q := func(cols []string, response bool) error {
		if len(cols) == 0 {
			return nil
		}
		headersQuery, _, err := sq.
			Select(cols...).
			From("http_headers").Where("req_id = ?").
			ToSql()
		if err != nil {
			return fmt.Errorf("could not parse query: %v", err)
		}
		stmt, err := c.db.PrepareContext(ctx, headersQuery)
		if err != nil {
			return fmt.Errorf("could not prepare statement: %v", err)
		}
		defer stmt.Close()
		for _, reqLog := range reqLogs {
			headers, err := findHeaders(ctx, stmt, reqLog.ID)
			if err != nil {
				return fmt.Errorf("could not query request headers: %v", err)
			}
			if !response {
				copyHeaders(reqLog.Request.Header, headers)
			} else {
				copyHeaders(reqLog.Response.Response.Header, headers)
			}
		}
		return nil
	}
	if err := q(query.requestHeaderCols, false); err != nil {
		return err
	}
	if err := q(query.responseHeaderCols, true); err != nil {
		return err
	}
	return nil
}

EDIT: that^ code doesn't work, I made a separate PR instead to solve the root problem too

@holiman holiman mentioned this pull request Oct 9, 2020
@dstotijn dstotijn merged commit 98dacbe into dstotijn:master Oct 11, 2020
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants