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 <io@richiejp.com>

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
 }

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

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),
+	)
 })

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())
+	})
+})

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",

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