From 7034d353b132cac69d5863f8a0806fb62bbb91a9 Mon Sep 17 00:00:00 2001 From: Richard Palethorpe Date: Tue, 22 Sep 2026 08:06:32 +0100 Subject: [PATCH] feat(kimodo): Add observability hooks (#12184) feat(kimodocpp): add API and backend request observability Capture animation requests, phase timings, output metadata, and failures in traces. Record correct API error statuses and cover completed, running, failed, and disabled tracing. Assisted-by: Codex:GPT-6 Signed-off-by: Richard Palethorpe --- core/backend/animation.go | 84 +++++++-- core/http/middleware/trace.go | 10 +- core/http/middleware/trace_live_test.go | 26 +++ core/http/routes/animation_traces_test.go | 197 ++++++++++++++++++++++ core/http/routes/localai.go | 1 + docs/content/features/3d-animation.md | 20 +++ 6 files changed, 323 insertions(+), 15 deletions(-) create mode 100644 core/http/routes/animation_traces_test.go diff --git a/core/backend/animation.go b/core/backend/animation.go index 530a86a85..863cb86ce 100644 --- a/core/backend/animation.go +++ b/core/backend/animation.go @@ -3,7 +3,9 @@ package backend import ( "context" + "encoding/json" "fmt" + "os" "time" "github.com/mudler/LocalAI/core/config" @@ -13,37 +15,93 @@ import ( ) func Model3DAnimation(ctx context.Context, request *proto.Animate3DRequest, loader *model.ModelLoader, modelConfig config.ModelConfig, appConfig *config.ApplicationConfig) (responseMetadata []byte, err error) { + var entry *trace.BackendTrace + if appConfig.EnableTracing { + trace.InitBackendTracingIfEnabled(appConfig.TracingMaxItems, appConfig.TracingMaxBodyBytes) + inputs := map[string]any{} + for name, input := range request.Inputs { + if input == nil { + continue + } + detail := map[string]any{"type": input.Type} + if input.Type == "text" { + detail["text"] = input.Data + } else { + detail["present"] = input.Data != "" + } + inputs[name] = detail + } + params := map[string]any{} + for name, value := range request.Params { + params[name] = value + } + summary := "3d: animate" + if prompt := request.Inputs["prompt"]; prompt != nil && prompt.Type == "text" { + summary += ": " + prompt.Data + } + entry = &trace.BackendTrace{Timestamp: time.Now(), Type: trace.BackendTrace3DAnimation, + ModelName: modelConfig.Name, Backend: modelConfig.Backend, Summary: trace.TruncateString(summary, 200), + Data: map[string]any{"inputs": inputs, "params": params, "model_file": modelConfig.Model, "stage": "loading_model"}} + entry.ID = trace.BeginBackendTrace(*entry) + defer trace.CancelBackendTrace(entry.ID) + defer func() { + entry.Duration = time.Since(entry.Timestamp) + if err != nil { + entry.Error = err.Error() + } + if len(responseMetadata) > 0 { + var metadata map[string]any + if decodeErr := json.Unmarshal(responseMetadata, &metadata); decodeErr != nil { + entry.Data["metadata_error"] = decodeErr.Error() + entry.Data["metadata_raw"] = string(responseMetadata) + } else { + entry.Data["metadata"] = metadata + } + } + trace.RecordBackendTrace(*entry) + }() + } + phaseStart := time.Now() inferenceModel, err := loader.Load(ModelOptions(modelConfig, appConfig)...) + if entry != nil { + entry.Data["load_ms"] = time.Since(phaseStart).Milliseconds() + } if err != nil { recordModelLoadFailure(appConfig, modelConfig.Name, modelConfig.Backend, err, nil) return nil, err } + phaseStart = time.Now() + if entry != nil { + entry.Data["stage"] = "waiting_for_slot" + } release, err := AcquireGlobalBackendSlot() + if entry != nil { + entry.Data["queue_ms"] = time.Since(phaseStart).Milliseconds() + } if err != nil { return nil, err } defer release() - if appConfig.EnableTracing { - trace.InitBackendTracingIfEnabled(appConfig.TracingMaxItems, appConfig.TracingMaxBodyBytes) - start := time.Now() - entry := trace.BackendTrace{Timestamp: start, Type: trace.BackendTrace3DAnimation, ModelName: modelConfig.Name, Backend: modelConfig.Backend, Summary: "3d: animate"} - entry.ID = trace.BeginBackendTrace(entry) - defer trace.CancelBackendTrace(entry.ID) - defer func() { - entry.Duration = time.Since(start) - if err != nil { - entry.Error = err.Error() - } - trace.RecordBackendTrace(entry) - }() + if entry != nil { + entry.Data["stage"] = "inference" } + phaseStart = time.Now() request.ModelIdentity = modelConfig.Model result, err := inferenceModel.Animate3D(ctx, request) + if entry != nil { + entry.Data["inference_ms"] = time.Since(phaseStart).Milliseconds() + } if err != nil { return nil, err } if result == nil || !result.Success { return nil, fmt.Errorf("animation backend failed: %s", result.GetMessage()) } + if entry != nil { + entry.Data["stage"] = "completed" + if info, statErr := os.Stat(request.Dst); statErr == nil { + entry.Data["output_bytes"] = info.Size() + } + } return result.Metadata, nil } diff --git a/core/http/middleware/trace.go b/core/http/middleware/trace.go index 1848fbeee..0fd2a5cec 100644 --- a/core/http/middleware/trace.go +++ b/core/http/middleware/trace.go @@ -3,6 +3,7 @@ package middleware import ( "bufio" "bytes" + "errors" "io" "mime" "net" @@ -310,10 +311,15 @@ func TraceMiddleware(app *application.Application) echo.MiddlewareFunc { // Restore original writer unconditionally c.Response().Writer = mw.ResponseWriter - // Determine response status (use 500 if handler errored and no status was set) + // Echo renders returned errors after middleware unwinds. Its default + // response status is already 200, so use the error while uncommitted. status := c.Response().Status - if status == 0 && handlerErr != nil { + if handlerErr != nil && !c.Response().Committed { status = http.StatusInternalServerError + var httpErr *echo.HTTPError + if errors.As(handlerErr, &httpErr) { + status = httpErr.Code + } } // Create exchange log (always, even on error). Sensitive headers diff --git a/core/http/middleware/trace_live_test.go b/core/http/middleware/trace_live_test.go index ac81f3122..332454c3c 100644 --- a/core/http/middleware/trace_live_test.go +++ b/core/http/middleware/trace_live_test.go @@ -3,6 +3,8 @@ package middleware import ( + "errors" + "fmt" "net/http" "net/http/httptest" "time" @@ -105,4 +107,28 @@ var _ = Describe("live API traces", func() { Expect(GetTraces()).To(BeEmpty()) }) + + DescribeTable("records the status of returned errors", func(handlerErr error, committed bool, expected int) { + app := newApp(GinkgoT().TempDir()) + handler := TraceMiddleware(app)(func(c echo.Context) error { + if committed { + Expect(c.NoContent(http.StatusAccepted)).To(Succeed()) + } + return handlerErr + }) + e := echo.New() + req := httptest.NewRequest(http.MethodPost, "/error", http.NoBody) + req.Header.Set(echo.HeaderContentType, echo.MIMEApplicationJSON) + ctx := e.NewContext(req, httptest.NewRecorder()) + Expect(handler(ctx)).To(Equal(handlerErr)) + Eventually(GetTraces).Should(ConsistOf(And( + HaveField("Response.Status", expected), + HaveField("Error", handlerErr.Error()), + ))) + }, + Entry("ordinary error", errors.New("inference failed"), false, http.StatusInternalServerError), + Entry("HTTP error", echo.NewHTTPError(http.StatusBadRequest, "invalid frames"), false, http.StatusBadRequest), + Entry("wrapped HTTP error", fmt.Errorf("validation: %w", echo.NewHTTPError(http.StatusBadRequest)), false, http.StatusBadRequest), + Entry("already committed response", errors.New("after response"), true, http.StatusAccepted), + ) }) diff --git a/core/http/routes/animation_traces_test.go b/core/http/routes/animation_traces_test.go new file mode 100644 index 000000000..f6f04ca03 --- /dev/null +++ b/core/http/routes/animation_traces_test.go @@ -0,0 +1,197 @@ +// SPDX-License-Identifier: MIT +package routes_test + +import ( + "context" + "encoding/json" + "errors" + "net/http" + "net/http/httptest" + "os" + "path/filepath" + "strings" + "time" + + "github.com/mudler/LocalAI/core/application" + "github.com/mudler/LocalAI/core/config" + corehttp "github.com/mudler/LocalAI/core/http" + "github.com/mudler/LocalAI/core/http/middleware" + "github.com/mudler/LocalAI/core/trace" + grpcpkg "github.com/mudler/LocalAI/pkg/grpc" + pb "github.com/mudler/LocalAI/pkg/grpc/proto" + "github.com/mudler/LocalAI/pkg/model" + "github.com/mudler/LocalAI/pkg/system" + . "github.com/onsi/ginkgo/v2" + . "github.com/onsi/gomega" + ggrpc "google.golang.org/grpc" +) + +const animationTraceMetadata = `{"usage":{"input_units":6,"output_units":60,"accounting_rule":"frame_steps_v1","details":{"output_frames":60,"sampling_steps":1}}}` + +type tracedAnimationBackend struct { + grpcpkg.Backend + err error + started chan struct{} + release chan struct{} +} + +func (*tracedAnimationBackend) HealthCheck(context.Context) (bool, error) { return true, nil } +func (*tracedAnimationBackend) IsBusy() bool { return false } +func (*tracedAnimationBackend) Free(context.Context) error { return nil } +func (b *tracedAnimationBackend) Animate3D(_ context.Context, r *pb.Animate3DRequest, _ ...ggrpc.CallOption) (*pb.Result, error) { + if b.started != nil { + close(b.started) + <-b.release + } + if b.err != nil { + return nil, b.err + } + if err := os.WriteFile(r.Dst, []byte("glTF fixture"), 0600); err != nil { + return nil, err + } + return &pb.Result{Success: true, Metadata: []byte(animationTraceMetadata)}, nil +} + +var _ = Describe("animation request traces", func() { + var app *application.Application + var handler http.Handler + var fixture *tracedAnimationBackend + var loadErr error + before := func() { + root := GinkgoT().TempDir() + var err error + app, err = application.New(config.EnableTracing, config.WithDataPath(root), config.WithGeneratedContentDir(filepath.Join(root, "generated")), config.WithDisableLocalAIAssistant(true), config.WithDisableStats(true), config.WithDisableCSRF(true), config.WithSystemState(&system.SystemState{Model: system.Model{ModelsPath: root}, Backend: system.Backend{BackendsPath: root}})) + Expect(err).NotTo(HaveOccurred()) + DeferCleanup(func() { Expect(app.Shutdown()).To(Succeed()) }) + cfg := config.ModelConfig{Name: "motion", Backend: "kimodocpp"} + cfg.SetDefaults() + cfg.Model = "motion.gguf" + app.ModelConfigLoader().ReplaceModelConfigs([]config.ModelConfig{cfg}) + fixture = &tracedAnimationBackend{} + loadErr = nil + app.ModelLoader().SetModelRouter(func(_ context.Context, id string, _, _, _, _ string, _ *pb.ModelOptions, _ bool) (*model.Model, error) { + if loadErr != nil { + return nil, loadErr + } + return model.NewModelWithClient(id, "test://animation", fixture), nil + }) + e, err := corehttp.API(app) + Expect(err).NotTo(HaveOccurred()) + handler = e + middleware.ClearTraces() + trace.InitBackendTracingIfEnabled(app.ApplicationConfig().TracingMaxItems, app.ApplicationConfig().TracingMaxBodyBytes) + trace.ClearBackendTraces() + } + BeforeEach(before) + request := func(frames string) *http.Request { + body := `{"model":"motion","inputs":{"prompt":{"type":"text","data":"Walk forward"}},"params":{"frames":"` + frames + `","steps":"1","seed":"42"}}` + req := httptest.NewRequest(http.MethodPost, "/3d/animate", strings.NewReader(body)) + req.Header.Set("Content-Type", "application/json") + req.Header.Set("Authorization", "Bearer test-trace-secret") + return req + } + animations := func() []trace.BackendTrace { + var found []trace.BackendTrace + for _, t := range trace.GetBackendTraces() { + if t.Type == trace.BackendTrace3DAnimation { + found = append(found, t) + } + } + return found + } + DescribeTable("captures the request and its outcome", func(mode string, code int) { + frames := "60" + switch mode { + case "invalid": + frames = "1" + case "inference failure": + fixture.err = errors.New("animation inference failed") + case "load failure": + loadErr = errors.New("animation load failed") + } + w := httptest.NewRecorder() + handler.ServeHTTP(w, request(frames)) + Expect(w.Code).To(Equal(code)) + Eventually(middleware.GetTraces).Should(ConsistOf(HaveField("Response.Status", code))) + api := middleware.GetTraces()[0] + Expect(api.Request.Path).To(Equal("/3d/animate")) + Expect(api.Response.Status).To(Equal(code)) + Expect(string(*api.Request.Body)).To(ContainSubstring("Walk forward")) + Expect(api.Request.Headers.Get("Authorization")).NotTo(ContainSubstring("test-trace-secret")) + if mode == "invalid" { + Expect(animations()).To(BeEmpty()) + Expect(api.Error).NotTo(BeEmpty()) + return + } + Eventually(animations).Should(HaveLen(1)) + bt := animations()[0] + Expect(bt.ModelName).To(Equal("motion")) + Expect(bt.Backend).To(Equal("kimodocpp")) + Expect(bt.Summary).To(ContainSubstring("Walk forward")) + Expect(bt.Duration).To(BeNumerically(">", 0)) + Expect(bt.Data["inputs"]).To(Equal(map[string]any{"prompt": map[string]any{"type": "text", "text": "Walk forward"}})) + Expect(bt.Data["params"]).To(Equal(map[string]any{"frames": "60", "steps": "1", "seed": "42"})) + Expect(bt.Data).To(HaveKey("load_ms")) + if mode != "success" { + Expect(bt.Status).To(Equal(trace.BackendTraceFailed)) + Expect(bt.Error).To(ContainSubstring("failed")) + if mode == "load failure" { + Expect(bt.Data["stage"]).To(Equal("loading_model")) + } else { + Expect(bt.Data["stage"]).To(Equal("inference")) + } + return + } + Expect(bt.Status).To(Equal(trace.BackendTraceCompleted)) + Expect(bt.Data["stage"]).To(Equal("completed")) + Expect(bt.Data).To(HaveKey("queue_ms")) + Expect(bt.Data).To(HaveKey("inference_ms")) + Expect(bt.Data["output_bytes"]).To(Equal(int64(len("glTF fixture")))) + encoded, err := json.Marshal(bt.Data["metadata"]) + Expect(err).NotTo(HaveOccurred()) + Expect(encoded).To(MatchJSON(animationTraceMetadata)) + Expect(string(*api.Response.Body)).To(ContainSubstring(`"output_units":60`)) + }, Entry("success", "success", http.StatusOK), Entry("validation failure", "invalid", http.StatusBadRequest), Entry("inference failure", "inference failure", http.StatusInternalServerError), Entry("load failure", "load failure", http.StatusInternalServerError)) + It("shows running requests before inference finishes", func() { + fixture.started = make(chan struct{}) + fixture.release = make(chan struct{}) + DeferCleanup(func() { + select { + case <-fixture.release: + default: + close(fixture.release) + } + }) + done := make(chan struct{}) + go func() { + defer GinkgoRecover() + defer close(done) + handler.ServeHTTP(httptest.NewRecorder(), request("60")) + }() + Eventually(fixture.started).Should(BeClosed()) + Eventually(animations).Should(HaveLen(1)) + running := animations()[0] + Expect(running.Status).To(Equal(trace.BackendTraceRunning)) + Expect(running.Summary).To(ContainSubstring("Walk forward")) + Expect(middleware.GetTraces()).To(HaveLen(1)) + Expect(middleware.GetTraces()[0].Response.Status).To(BeZero()) + close(fixture.release) + Eventually(done).Should(BeClosed()) + Eventually(func() trace.BackendTraceStatus { + ts := animations() + if len(ts) != 1 { + return "" + } + return ts[0].Status + }).Should(Equal(trace.BackendTraceCompleted)) + Expect(animations()[0].ID).To(Equal(running.ID)) + }) + It("records nothing when tracing is disabled", func() { + app.ApplicationConfig().EnableTracing = false + w := httptest.NewRecorder() + handler.ServeHTTP(w, request("60")) + Expect(w.Code).To(Equal(http.StatusOK)) + Consistently(middleware.GetTraces, 100*time.Millisecond, 10*time.Millisecond).Should(BeEmpty()) + Expect(animations()).To(BeEmpty()) + }) +}) diff --git a/core/http/routes/localai.go b/core/http/routes/localai.go index a02da736d..1d3c7adaf 100644 --- a/core/http/routes/localai.go +++ b/core/http/routes/localai.go @@ -233,6 +233,7 @@ func RegisterLocalAIRoutes(router *echo.Echo, localai.Model3DAnimationEndpoint(ml, appConfig), middleware.UsageMiddleware(app.StatsRecorder(), app.FallbackUser()), echomiddleware.BodyLimit("45M"), + middleware.TraceMiddleware(app), requestExtractor.BuildFilteredFirstAvailableDefaultModel(config.BuildUsecaseFilterFn(config.FLAG_3D_ANIMATION)), requestExtractor.SetModelAndConfig(func() schema.LocalAIRequest { return new(schema.Model3DAnimationRequest) })) router.POST("/3d/generations", diff --git a/docs/content/features/3d-animation.md b/docs/content/features/3d-animation.md index bf14df4e6..20e78beb9 100644 --- a/docs/content/features/3d-animation.md +++ b/docs/content/features/3d-animation.md @@ -125,6 +125,26 @@ are 150 frames, 100 sampling steps, and text guidance 2. Parameters are strings; unsupported inputs and parameters are rejected. Multi-prompt transitions and mesh retargeting are not currently exposed by this adapter. +## Request traces + +With [tracing](/features/tracing) enabled, `POST /3d/animate` appears on the +**Traces** page in both API and backend history. API traces include the JSON +request, response, HTTP status, duration, and any returned error. Sensitive +headers are redacted and body capture follows the configured size limit. + +The backend trace includes the model and backend, text prompt, requested +parameters, model-loading time (`load_ms`), slot-waiting time (`queue_ms`), +inference time (`inference_ms`), output file size (`output_bytes`), and returned +`metadata`, including the usage breakdown. Parameters describe request overrides; +`metadata.usage.details` reports the effective frames and sampling steps. +Non-text inputs record their type and presence, without copying asset contents. +Trace strings follow the existing backend trace size limit. + +A running backend entry appears before model loading begins. Completed entries +contain the details above; failures include the error and the stage that failed. +Total backend duration includes loading, waiting, and inference. Requests rejected +by endpoint validation have an API trace but no animation backend trace. + ## Usage accounting Kimodo reports one set of usage measurements through **generic backend metadata**.