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

Panics not formatted as JSON when LOG_JSON is true #1587

Closed
alec-brooks opened this issue May 28, 2024 · 0 comments · Fixed by #1602
Closed

Panics not formatted as JSON when LOG_JSON is true #1587

alec-brooks opened this issue May 28, 2024 · 0 comments · Fixed by #1602
Assignees
Labels
bug Something isn't working good first issue Good for newcomers

Comments

@alec-brooks
Copy link
Contributor

When an FTL controller panics, it seems to print the stack trace to stdout even when LOG_JSON is true. This makes it difficult to read the stack traces in a log aggregator.

See below for a block logs that I recently pulled from an FTL controller, as you can see there is JSON logged normally followed by a panic. A seperate issue will be filed for the actual panic.

{"level":"trace","attributes":{"scope":"reconcileRunners"},"message":"Running scheduled task","time":"2024-05-28T05:48:43.725419134Z"}
{"level":"trace","message":"/xyz.block.ftl.v1.VerbService/GetModuleContext (unary)","time":"2024-05-28T05:48:43.730843304Z"}
2024/05/28 05:48:43 http2: panic serving 127.0.0.6:43935: no configuration manager in context
goroutine 712469 [running]:
golang.org/x/net/http2.(*serverConn).runHandler.func1()
	/root/go/pkg/mod/golang.org/x/net@v0.25.0/http2/server.go:2363 +0x145
panic({0xf74a80?, 0x1501420?})
	/root/.cache/hermit/pkg/go-1.22.3/src/runtime/panic.go:770 +0x132
go.opentelemetry.io/otel/sdk/trace.(*recordingSpan).End.deferwrap1()
	/root/go/pkg/mod/go.opentelemetry.io/otel/sdk@v1.27.0/trace/span.go:381 +0x25
go.opentelemetry.io/otel/sdk/trace.(*recordingSpan).End(0xc00001ea80, {0x0, 0x0, 0xc00094f500?})
	/root/go/pkg/mod/go.opentelemetry.io/otel/sdk@v1.27.0/trace/span.go:419 +0xa82
panic({0xf74a80?, 0x1501420?})
	/root/.cache/hermit/pkg/go-1.22.3/src/runtime/panic.go:770 +0x132
github.com/TBD54566975/ftl/common/configuration.ConfigFromContext(...)
	/src/common/configuration/context.go:34
github.com/TBD54566975/ftl/backend/controller.(*Service).GetModuleContext(0x1?, {0x15165d8, 0xc00190c720}, 0x1?)
	/src/backend/controller/controller.go:662 +0xb1a
connectrpc.com/connect.NewUnaryHandler[...].func1({0x151f990, 0xc0014baa80})
	/root/go/pkg/mod/connectrpc.com/connect@v1.16.1/handler.go:52 +0x14f
github.com/TBD54566975/ftl/internal/rpc.(*versionInterceptor).WrapUnary.versionInterceptor.WrapUnary.func1({0x15165d8, 0xc00190c720}, {0x151f990, 0xc0014baa80})
	/src/internal/rpc/context.go:232 +0x43
connectrpc.com/otelconnect.(*Interceptor).WrapUnary.func1({0x15165d8, 0xc00190c6f0}, {0x151f990, 0xc0014baa80})
	/root/go/pkg/mod/connectrpc.com/otelconnect@v0.7.0/interceptor.go:152 +0x1454
github.com/TBD54566975/ftl/internal/rpc.(*metadataInterceptor).WrapUnary.func1({0x1518250, 0xc00200c6a0}, {0x151f990, 0xc0014baa80})
	/src/internal/rpc/context.go:159 +0x24b
connectrpc.com/connect.NewUnaryHandler[...].func2({0x7f8f2b28fe78, 0xc00200c6e0})
	/root/go/pkg/mod/connectrpc.com/connect@v1.16.1/handler.go:70 +0xa2
connectrpc.com/connect.(*Handler).ServeHTTP(0xc0000200e0, {0x1515220, 0xc000474000}, 0xc00090c360)
	/root/go/pkg/mod/connectrpc.com/connect@v1.16.1/handler.go:238 +0x94f
github.com/TBD54566975/ftl/backend/protos/xyz/block/ftl/v1/ftlv1connect.NewVerbServiceHandler.func1({0x1515220, 0xc000474000}, 0xc00090c360)
	/src/backend/protos/xyz/block/ftl/v1/ftlv1connect/ftl.connect.go:247 +0xb1
net/http.HandlerFunc.ServeHTTP(0xc000380270?, {0x1515220?, 0xc000474000?}, 0x76d94f?)
	/root/.cache/hermit/pkg/go-1.22.3/src/net/http/server.go:2166 +0x29
net/http.(*ServeMux).ServeHTTP(0xc000ac59e0?, {0x1515220, 0xc000474000}, 0xc00090c360)
	/root/.cache/hermit/pkg/go-1.22.3/src/net/http/server.go:2683 +0x1ad
github.com/TBD54566975/ftl/internal/rpc.NewServer.ContextValuesMiddleware.func3({0x1515220, 0xc000474000}, 0xc000ac59e0)
	/src/internal/rpc/rpc.go:91 +0xce
net/http.HandlerFunc.ServeHTTP(0xc001eef560?, {0x1515220?, 0xc000474000?}, 0xc001d3bda0?)
	/root/.cache/hermit/pkg/go-1.22.3/src/net/http/server.go:2166 +0x29
golang.org/x/net/http2.(*serverConn).runHandler(0x44723d?, 0x0?, 0xc001a84240?, 0x0?)
	/root/go/pkg/mod/golang.org/x/net@v0.25.0/http2/server.go:2370 +0xbb
created by golang.org/x/net/http2.(*serverConn).scheduleHandler in goroutine 314
	/root/go/pkg/mod/golang.org/x/net@v0.25.0/http2/server.go:2305 +0x21d
{"level":"debug","message":"Unary RPC failed: canceled: failed to spawn plugin: plugin process died: context canceled: /xyz.block.ftl.v1.RunnerService/Deploy","time":"2024-05-28T05:48:43.773299485Z"}```
@github-actions github-actions bot added the triage Issue needs triaging label May 28, 2024
@ftl-robot ftl-robot mentioned this issue May 28, 2024
@wesbillman wesbillman added bug Something isn't working good first issue Good for newcomers next Work that will be be picked up next and removed triage Issue needs triaging labels May 28, 2024
@safeer safeer self-assigned this May 29, 2024
@github-actions github-actions bot removed the next Work that will be be picked up next label May 29, 2024
wesbillman pushed a commit that referenced this issue May 31, 2024
Fixes #1587 by creating a new grpc Interceptor to log panics in each
wrap handler, then re-panic.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working good first issue Good for newcomers
Projects
None yet
Development

Successfully merging a pull request may close this issue.

3 participants