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**.