package dispatcher import ( "context" "encoding/json" "errors" "fmt" "log/slog" "time" "git.ipao.vip/rogee/go-sip/internal/configread" "git.ipao.vip/rogee/go-sip/internal/contract" "git.ipao.vip/rogee/go-sip/internal/store" "google.golang.org/genproto/googleapis/rpc/errdetails" "google.golang.org/grpc/codes" "google.golang.org/grpc/status" ) // CallSpec is a frozen instruction handed to one Agent. Its Snapshot // includes immutable AI parameters and provider credentials; never log it. type CallSpec struct { DispatcherID string EventID string TenantID int64 TaskID string CallerID string Callee string DialedCallee string TrunkID string RingTimeoutMS int64 MaxCallDurationMS int64 Deadline time.Time Snapshot configread.Snapshot } type Originator interface { LoadedTrunks(context.Context) (map[string]int64, error) Originate(context.Context, CallSpec) error } type Publisher interface { Publish(context.Context, string, string, []byte) error } type ExecuteController struct { DispatcherID string Store *store.Store Originator Originator Publisher Publisher Now func() time.Time } func (c *ExecuteController) validate() error { if c == nil || c.DispatcherID == "" || c.Store == nil || c.Originator == nil || c.Publisher == nil || c.Now == nil { return errors.New("current execution requires Dispatcher identity, durable store, originator, publisher, and clock") } return nil } // ProcessExecute persists the inbound identity before the transport ACK. // Its business acknowledgment is a separate durable outbox event, written // only after originate was actually dispatched or an individual number was // definitively rejected. func (c *ExecuteController) ProcessExecute(ctx context.Context, body []byte) error { if err := c.validate(); err != nil { return err } defer c.Store.HoldCallLifecycle()() if err := contract.ValidateCurrent("mq", body); err != nil { return fmt.Errorf("invalid incoming call.execute: %w", err) } var event struct { EventID string `json:"event_id"` EventType string `json:"event_type"` DispatcherID string `json:"dispatcher_id"` TenantID int64 `json:"tenant_id"` IssuedAt string `json:"issued_at"` Payload struct { TaskID string `json:"task_id"` Callee string `json:"callee"` } `json:"payload"` } if err := json.Unmarshal(body, &event); err != nil { return fmt.Errorf("decode call.execute: %w", err) } if event.EventType != "call.execute" || event.Payload.TaskID == "" || event.Payload.Callee == "" || event.DispatcherID != c.DispatcherID { return errors.New("call instruction event type, task, or Dispatcher owner mismatch") } cmd := store.ExecuteCommand{ DispatcherID: event.DispatcherID, EventID: event.EventID, TenantID: event.TenantID, TaskID: event.Payload.TaskID, Callee: event.Payload.Callee, IssuedAt: event.IssuedAt, } logger := slog.With("event_id", cmd.EventID, "task_id", cmd.TaskID, "tenant_id", cmd.TenantID) stored, inserted, err := c.Store.RecordExecute(cmd) if errors.Is(err, store.ErrEventRejected) { logger.Info("Rejected call identity replayed without execution", "stage", "idempotent_rejection") return nil } if errors.Is(err, store.ErrStopped) { logger.Info("Call instruction ignored", "stage", "admission_closed", "reason", "task stopped") // The stopped task never accepted this old queued command. RabbitMQ // may ACK it without creating an execution or a per-call result. return nil } if err != nil { logger.Error("Call instruction persistence failed", "stage", "inbox_save_failed", "error", err) return fmt.Errorf("durable inbound call %q: %w", cmd.EventID, err) } logger.Info("Call instruction saved", "stage", "inbox_saved", "inserted", inserted, "status", stored.Status) if stored.Status != "pending" { logger.Info("Call instruction already handled", "stage", "idempotent_skip", "status", stored.Status) return nil } if !validRawCallee(cmd.Callee) { if err := c.Store.RejectExecute(cmd.DispatcherID, cmd.EventID, ErrCalleeRejected.Error()); err != nil { logger.Error("Callee rejection persistence failed", "stage", "callee_rejection_save_failed", "error", err) return fmt.Errorf("persist rejected call %q: %w", cmd.EventID, err) } logger.Warn("Call instruction rejected", "stage", "callee_rejected", "reason", ErrCalleeRejected) return nil } return c.dispatchPending(ctx, cmd) } // ProcessPending reevaluates only durable, never-originated commands. This is // used after rule/config changes; dispatching and unknown calls are excluded. func (c *ExecuteController) ProcessPending(ctx context.Context) error { if err := c.validate(); err != nil { return err } defer c.Store.HoldCallLifecycle()() commands, err := c.Store.ListPendingExecute(c.DispatcherID) if err != nil { return err } var failures []error for _, cmd := range commands { if err := c.dispatchPending(ctx, cmd); err != nil { failures = append(failures, err) } } return errors.Join(failures...) } func agentProvedCallNotIssued(err error) bool { st, ok := status.FromError(err) if !ok || st.Code() == codes.OK { return false } for _, detail := range st.Details() { if proof, ok := detail.(*errdetails.ErrorInfo); ok && proof.Reason == "GO_SIP_CALL_NOT_ISSUED" && proof.Domain == "agent.go-sip" { return true } } return false } func (c *ExecuteController) dispatchPending(ctx context.Context, cmd store.ExecuteCommand) (dispatchErr error) { logger := slog.With("event_id", cmd.EventID, "task_id", cmd.TaskID, "tenant_id", cmd.TenantID, "dispatcher_id", cmd.DispatcherID) phase := "parse_issued_at" started := time.Now() defer func() { if dispatchErr != nil { logger.Error("Call admission or execution failed", "stage", phase, "error", dispatchErr, "duration_ms", time.Since(started).Milliseconds()) } }() current, err := c.Store.IsCurrentPending(cmd) if err != nil { return fmt.Errorf("recheck pending instruction %q: %w", cmd.EventID, err) } if !current { logger.Info("Buffered call instruction no longer pending", "stage", "pending_batch_skip") return nil } logger.Info("Call admission check", "stage", "select_line") at := c.Now() issued, err := time.Parse(time.RFC3339Nano, cmd.IssuedAt) if err != nil { return fmt.Errorf("persisted command %q has invalid issued_at: %w", cmd.EventID, err) } if issued.After(at) { logger.Info("Call instruction waiting", "stage", "issued_at_wait", "issued_at", cmd.IssuedAt, "checked_at", at) return nil } phase = "load_authorized_snapshot" snapshot, err := c.Store.ReadSnapshot(cmd.DispatcherID, cmd.TenantID, cmd.TaskID) if err != nil { return fmt.Errorf("load authorized task %q: %w", cmd.TaskID, err) } phase = "validate_task_ai" if err := validateAISnapshot(snapshot); err != nil { return errors.Join(err, c.Store.CloseAdmission(c.DispatcherID)) } phase = "read_applied_lines" loaded, err := c.Originator.LoadedTrunks(ctx) if err != nil { return fmt.Errorf("read applied Agent/Asterisk SIP revisions: %w", err) } phase = "read_line_occupancy" occupied, err := c.Store.TrunkOccupancy(c.DispatcherID) if err != nil { return err } phase = "read_task_line_occupancy" taskOccupied, err := c.Store.TaskTrunkOccupancy(c.DispatcherID, cmd.TenantID, cmd.TaskID) if err != nil { return fmt.Errorf("read task trunk occupancy: %w", err) } phase = "select_line" choice, err := SelectTrunk(snapshot, cmd.Callee, at, occupied, taskOccupied, loaded) if errors.Is(err, ErrRuleWait) { logger.Info("Call instruction waiting", "stage", "admission_wait", "reason", err) return nil } if err != nil { return fmt.Errorf("task %q rule validation: %w", cmd.TaskID, err) } phase = "task_config_fingerprint" taskSHA, err := configread.TaskConfigurationSHA256(snapshot.Task) if err != nil { return err } reservation := store.CallReservation{ TrunkID: choice.TrunkID, SIPRevision: snapshot.SIP.Revision, TaskRevision: snapshot.Task.TaskRevision, TaskConfigSHA256: taskSHA, CallerID: choice.CallerID, DialedCallee: choice.DialedCallee, Deadline: choice.Deadline, } phase = "reserve_call" if err := c.Store.ReserveExecute(cmd.DispatcherID, cmd.EventID, reservation, at); err != nil { if errors.Is(err, store.ErrCapacity) || errors.Is(err, store.ErrNotReady) || errors.Is(err, store.ErrAlreadyStarted) { logger.Info("Call reservation not acquired", "stage", "reservation_wait", "reason", err, "trunk_id", choice.TrunkID, "trunk_occupied", occupied[choice.TrunkID], "task_trunk_occupied", taskOccupied[choice.TrunkID]) return nil } return fmt.Errorf("reserve call %q: %w", cmd.EventID, err) } // A reservation is not permission to dial after a clock/window/loaded SIP // change. Recheck the fixed selection immediately before the only RPC. actualAt := c.Now() phase = "recheck_loaded_sip" freshLoaded, err := c.Originator.LoadedTrunks(ctx) if err != nil { logger.Warn("Call reservation cancellation requested", "stage", "reservation_cancel_requested", "reason", err) cancelErr := c.Store.CancelReservationBeforeOrigin(cmd.DispatcherID, cmd.EventID) if cancelErr == nil { logger.Info("Call reservation cancelled", "stage", "reservation_cancelled", "reason", err) } return errors.Join(fmt.Errorf("recheck applied SIP before originate: %w", err), cancelErr) } phase = "recheck_line_and_deadline" fresh, ruleErr := SelectTrunk(snapshot, cmd.Callee, actualAt, occupied, taskOccupied, freshLoaded) if !actualAt.Before(choice.Deadline) || ruleErr != nil || fresh.TrunkID != choice.TrunkID || fresh.CallerID != choice.CallerID { logger.Info("Call reservation cancellation requested", "stage", "reservation_cancel_requested", "deadline_elapsed", !actualAt.Before(choice.Deadline), "rule_error", ruleErr, "line_changed", fresh.TrunkID != choice.TrunkID || fresh.CallerID != choice.CallerID) phase = "cancel_reservation_before_originate" cancelErr := c.Store.CancelReservationBeforeOrigin(cmd.DispatcherID, cmd.EventID) if cancelErr != nil { return fmt.Errorf("cancel expired/changed reservation: %w", cancelErr) } logger.Info("Call reservation cancelled", "stage", "reservation_cancelled", "reason", "pre-dial authorization, line or deadline changed") if ruleErr != nil && !errors.Is(ruleErr, ErrRuleWait) { return fmt.Errorf("pre-dial task %q rule: %w", cmd.TaskID, ruleErr) } return nil } phase = "recheck_task_admission" admitted, err := c.Store.CanAdmit(cmd.DispatcherID, cmd.TenantID, cmd.TaskID) if err != nil || !admitted { logger.Info("Call reservation cancellation requested", "stage", "reservation_cancel_requested", "admitted", admitted, "error", err) cancelErr := c.Store.CancelReservationBeforeOrigin(cmd.DispatcherID, cmd.EventID) if cancelErr == nil { logger.Info("Call reservation cancelled", "stage", "reservation_cancelled", "reason", "task admission closed", "error", err) } if err != nil { return errors.Join(fmt.Errorf("recheck task admission before originate: %w", err), cancelErr) } return cancelErr } spec := CallSpec{ DispatcherID: cmd.DispatcherID, EventID: cmd.EventID, TenantID: cmd.TenantID, TaskID: cmd.TaskID, CallerID: choice.CallerID, Callee: cmd.Callee, DialedCallee: choice.DialedCallee, TrunkID: choice.TrunkID, RingTimeoutMS: snapshot.Task.RingTimeoutMS, MaxCallDurationMS: choice.MaxCallDurationMS, Deadline: choice.Deadline, Snapshot: snapshot, } phase = "read_task_trunk_limits" limits, err := snapshot.Task.TrunkLimits() if err != nil { return errors.Join(fmt.Errorf("read reserved task trunk limit: %w", err), c.Store.CancelReservationBeforeOrigin(cmd.DispatcherID, cmd.EventID)) } logger.Info("Call reservation saved", "stage", "reserved", "task_revision", snapshot.Task.TaskRevision, "trunk_id", choice.TrunkID, "task_trunk_limit", limits[choice.TrunkID], "task_trunk_used_before", taskOccupied[choice.TrunkID]) logger.Info("Call execution request", "direction", "dispatcher->agent", "stage", "originate_requested", "trunk_id", choice.TrunkID) phase = "originate" if err := c.Originator.Originate(ctx, spec); err != nil { if agentProvedCallNotIssued(err) { rejectErr := c.Store.RejectUnissuedExecute(cmd.DispatcherID, cmd.EventID, "Agent refused before outbound call") if rejectErr == nil { logger.Warn("Agent refused before dial", "direction", "agent->dispatcher", "stage", "rejected_before_dial", "agent_code", status.Code(err), "reason", err) } return errors.Join(fmt.Errorf("Agent rejected call %q before dialing: %w", cmd.EventID, err), rejectErr) } logger.Error("Call execution outcome unknown", "stage", "execution_outcome_unknown", "error", err, "occupancy_retained", true) unknownErr := c.Store.MarkExecuteUnknown(cmd.DispatcherID, cmd.EventID) return errors.Join(fmt.Errorf("originator outcome unknown for call %q: %w", cmd.EventID, err), unknownErr) } logger.Info("Agent scheduled call", "direction", "agent->dispatcher", "stage", "originate_scheduled", "trunk_id", choice.TrunkID) phase = "save_scheduled_execution" if err := c.Store.MarkExecuteDispatched(cmd.DispatcherID, cmd.EventID); err != nil { return fmt.Errorf("originated call %q has no durable acknowledgment: %w", cmd.EventID, err) } return nil } // FlushOutbox uses the same event identity/body on every retry. Confirming a // bound queue is not a SaaS application receipt. Completed local data may be // cleaned only after its independent completion conditions are satisfied. func (c *ExecuteController) FlushOutbox(ctx context.Context) error { if err := c.validate(); err != nil { return err } pending, err := c.Store.ListPendingOutbox(c.DispatcherID) if err != nil { return err } var failures []error for _, event := range pending { if err := c.Publisher.Publish(ctx, "agent-call.saas.v1", event.RoutingKey, event.Body); err != nil { failures = append(failures, fmt.Errorf("publish event %q/%q to SaaS queue: %w", event.EventType, event.EventID, err)) continue } if err := c.Store.MarkOutboxConfirmed(c.DispatcherID, event.EventType, event.EventID); err != nil { failures = append(failures, fmt.Errorf("persist queue confirmation for %q/%q: %w", event.EventType, event.EventID, err)) continue } c.cleanupConfirmedFeedback(ctx, event) } return errors.Join(failures...) }