search

TBD54566975 / ftl

FTL - Towards a 𝝺-calculus for large-scale systems
https://tbd54566975.github.io/ftl/
Apache License 2.0
21 stars 7 forks source link

One-off controller panic under very high load #1898

Open deniseli opened 3 months ago

deniseli commented 3 months ago

It is possible to panic the controller somehow when hammering ftl dev with a very high rate of verb calls for over a minute. I managed to hit this while sending 1 request every 10 ms and have not yet been able to reproduce it.

error:controller0: panic in RPC: goroutine 96922220 [running]:
runtime/debug.Stack()
    /Users/dli/Library/Caches/hermit/pkg/go-1.22.4/src/runtime/debug/stack.go:24 +0x64
github.com/TBD54566975/ftl/internal/rpc.handlePanic({0x10632c658?, 0x14001ed79e0?})
    /Users/dli/Development/ftl/internal/rpc/context.go:127 +0xdc
panic({0x1060a1580?, 0x106f68930?})
    /Users/dli/Library/Caches/hermit/pkg/go-1.22.4/src/runtime/panic.go:770 +0x124
github.com/TBD54566975/ftl/backend/controller.(*Service).callWithRequest(0x14000502fc0, {0x10632bc38, 0x14002d33bc0}, 0x140010e3300, {{{{0x0, 0x0}, {0x0, 0x0}}, {0x0, 0x0, ...}}, ...}, ...)
    /Users/dli/Development/ftl/backend/controller/controller.go:930 +0x950
github.com/TBD54566975/ftl/backend/controller.(*Service).Call(0x14005ca0988?, {0x10632bc38?, 0x14002d33bc0?}, 0x14005f51590?)
    /Users/dli/Development/ftl/backend/controller/controller.go:745 +0x60
connectrpc.com/connect.NewUnaryHandler[...].func1({0x106336d40, 0x140010e3300})
    /Users/dli/go/pkg/mod/connectrpc.com/connect@v1.16.1/handler.go:52 +0x13c
connectrpc.com/otelconnect.(*Interceptor).WrapUnary.func1({0x10632bc38, 0x14002d33b90}, {0x106336d40, 0x140010e3300})
    /Users/dli/go/pkg/mod/connectrpc.com/otelconnect@v0.7.0/interceptor.go:152 +0x10c0
github.com/TBD54566975/ftl/internal/rpc.(*metadataInterceptor).WrapUnary.func1({0x10632c658, 0x14001ed79e0}, {0x106336d40, 0x140010e3300})
    /Users/dli/Development/ftl/internal/rpc/context.go:204 +0x188
github.com/TBD54566975/ftl/internal/rpc.(*panicInterceptor).WrapUnary.func1({0x10632c658?, 0x14001ed79e0?}, {0x106336d40?, 0x140010e3300?})
    /Users/dli/Development/ftl/internal/rpc/context.go:150 +0x70
connectrpc.com/connect.NewUnaryHandler[...].func2({0x1074f7958, 0x14001ed7a00})
    /Users/dli/go/pkg/mod/connectrpc.com/connect@v1.16.1/handler.go:70 +0x84
connectrpc.com/connect.(*Handler).ServeHTTP(0x140002523f0, {0x106327920, 0x14002e268c0}, 0x1400776fe60)
    /Users/dli/go/pkg/mod/connectrpc.com/connect@v1.16.1/handler.go:238 +0x7f0
github.com/TBD54566975/ftl/backend/protos/xyz/block/ftl/v1/ftlv1connect.NewVerbServiceHandler.func1({0x106327920, 0x14002e268c0}, 0x1400776fe60)
    /Users/dli/Development/ftl/backend/protos/xyz/block/ftl/v1/ftlv1connect/ftl.connect.go:300 +0x180
net/http.HandlerFunc.ServeHTTP(0x140004aa820?, {0x106327920?, 0x14002e268c0?}, 0x105745814?)
    /Users/dli/Library/Caches/hermit/pkg/go-1.22.4/src/net/http/server.go:2166 +0x38
net/http.(*ServeMux).ServeHTTP(0x1400776fb00?, {0x106327920, 0x14002e268c0}, 0x1400776fe60)
    /Users/dli/Library/Caches/hermit/pkg/go-1.22.4/src/net/http/server.go:2683 +0x1a4
github.com/TBD54566975/ftl/internal/rpc.NewServer.ContextValuesMiddleware.func3({0x106327920, 0x14002e268c0}, 0x1400776fb00)
    /Users/dli/Development/ftl/internal/rpc/rpc.go:98 +0xb4
net/http.HandlerFunc.ServeHTTP(0x14002d33ad0?, {0x106327920?, 0x14002e268c0?}, 0x105014448?)
    /Users/dli/Library/Caches/hermit/pkg/go-1.22.4/src/net/http/server.go:2166 +0x38
golang.org/x/net/http2/h2c.h2cHandler.ServeHTTP({{0x106317820?, 0x14000424ae0?}, 0x1400005ae40?}, {0x106327920, 0x14002e268c0}, 0x1400776fb00)
    /Users/dli/go/pkg/mod/golang.org/x/net@v0.26.0/http2/h2c/h2c.go:125 +0x4c8
net/http.serverHandler.ServeHTTP({0x1063228b8?}, {0x106327920?, 0x14002e268c0?}, 0x6?)
    /Users/dli/Library/Caches/hermit/pkg/go-1.22.4/src/net/http/server.go:3137 +0xbc
net/http.(*conn).serve(0x1400660de60, {0x10632bc38, 0x14000424f30})
    /Users/dli/Library/Caches/hermit/pkg/go-1.22.4/src/net/http/server.go:2039 +0x508
created by net/http.(*Server).Serve in goroutine 250
    /Users/dli/Library/Caches/hermit/pkg/go-1.22.4/src/net/http/server.go:3285 +0x3f0
: runtime error: invalid memory address or nil pointer dereference
panic: channel not subscribed

In case the controller code changes significantly from my local version as I hit this, here's a reference to the lines in the above call stack:

ftl/backend/controller/controller.go:745:

func (s *Service) Call(ctx context.Context, req *connect.Request[ftlv1.CallRequest]) (*connect.Response[ftlv1.CallResponse], \
error) {
        return s.callWithRequest(ctx, req, optional.None[model.RequestKey](), "") // this line right here!
}

ftl/backend/controller/controller.go:930:

        response, err := client.verb.Call(ctx, req)
        resp := connect.NewResponse(response.Msg) // this line right here
        var maybeResponse optional.Option[*ftlv1.CallResponse]
        if resp != nil {
                maybeResponse = optional.Some(resp.Msg)
        }
        s.recordCall(ctx, &Call{
stuartwdouglas commented 1 week ago

I think we can close this, as we have not seen it again and that code has changed significantly.