trex/trex-core
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

fix: reconcile ambiguous KIS order submissions

Browse Source
This commit is contained in:
jordan
2026-07-28 11:17:06 +09:00
parent b72bf9f394
commit 24c42d1c92
11 changed files with 1420 additions and 191 deletions
Download Patch File Download Diff File Expand all files Collapse all files
trex_core/application/execution.py
+182 -62
View File
@@ -20,10 +20,11 @@ All slot writes go through SlotService (advisory lock). The broker is touched
only here, never by the domain or the HTTP API. The ledger outbox is the
single producer for ledger work items (NFR-3, single record subject).
"""
from __future__ import annotations
import logging
from dataclasses import dataclass
from dataclasses import dataclass, replace
from datetime import datetime, timezone
from typing import Callable, Optional
@@ -48,7 +49,9 @@ _log = logging.getLogger(__name__)
# _apply_transition_fields). The emitter MUST prefer this hint over
# `slot.strategy_id` so that slot_filled_sell events reach the correct
# per-strategy queue instead of being NO_ROUTEd to the DLQ.
SlotEventEmitter = Callable[[str, object, Optional[str]], None] # (event_type, slot, routing_strategy_id) -> None
SlotEventEmitter = Callable[
[str, object, Optional[str]], None
] # (event_type, slot, routing_strategy_id) -> None
_MAX_DISPATCH_PER_TICK = 64
@@ -58,11 +61,11 @@ class ExecutionResult:
dispatched: int = 0
filled: int = 0
rolled_back: int = 0
ledger_enqueued: int = 0 # REQ-019: ledger work items appended this tick
ledger_skipped: int = 0 # REQ-018 AC-4: fills without portfolio_id
stale_pending: int = 0 # dcy-013 / REQ-014 FR-3: pending orders over threshold
ledger_enqueued: int = 0 # REQ-019: ledger work items appended this tick
ledger_skipped: int = 0 # REQ-018 AC-4: fills without portfolio_id
stale_pending: int = 0 # dcy-013 / REQ-014 FR-3: pending orders over threshold
sell_skipped_no_balance: int = 0 # dcy-020 / REQ-062: broker flat -> sell skipped
timeout_cancelled: int = 0 # dcy-022 / REQ-069: cancel_order sent on timeout
timeout_cancelled: int = 0 # dcy-022 / REQ-069: cancel_order sent on timeout
class ExecutionService:
@@ -139,7 +142,8 @@ class ExecutionService:
_log.warning(
"sell dispatch skipped: slot=%s symbol=%s broker balance is 0 "
"(divergence — no order submitted; operator/reconcile attention)",
slot.slot_id, slot.symbol,
slot.slot_id,
slot.symbol,
)
# dcy-033 / REQ-100: CRITICAL alarm — PENDING_SELL may stick.
if self._alarm_emitter is not None:
@@ -175,7 +179,12 @@ class ExecutionService:
_log.debug(
"slippage applied: slot=%s side=%s base_limit=%s pct=%.4f "
"raw=%.2f effective=%s (tick-snapped)",
slot.slot_id, side, slot.limit_price, slot.slippage_pct, raw, limit,
slot.slot_id,
side,
slot.limit_price,
slot.slippage_pct,
raw,
limit,
)
# REQ-084/085: correlation id (intent→order→fill join key = slot_id)
# so submit/fill/reject logs for one slot share a key.
@@ -193,20 +202,41 @@ class ExecutionService:
if ack.accepted and ack.broker_order_id:
self._repo.mark_dispatched(slot.slot_id, ack.broker_order_id)
r.dispatched += 1
# REQ-085: order-result logging — tailable submit line.
_log.info(
"order submitted event=order_submit side=%s symbol=%s slot_id=%s "
"qty=%s limit_price=%s order_type=%s",
side, slot.symbol, slot.slot_id, qty, limit,
"00" if limit is not None else "01",
)
if ack.reason and ack.reason.startswith("submit_outcome_unknown:"):
_log.warning(
"order submission outcome unknown event=order_submit_unknown "
"side=%s symbol=%s slot_id=%s qty=%s limit_price=%s "
"automatic_retry=blocked reason=%s",
side,
slot.symbol,
slot.slot_id,
qty,
limit,
ack.reason,
)
else:
# REQ-085: order-result logging — tailable submit line.
_log.info(
"order submitted event=order_submit side=%s symbol=%s slot_id=%s "
"qty=%s limit_price=%s order_type=%s",
side,
slot.symbol,
slot.slot_id,
qty,
limit,
"00" if limit is not None else "01",
)
else:
# REQ-085/087: reject is visible (event key) and ERROR level
# (no more silent rollback — issue #28 surfaced too late).
_log.error(
"order rejected event=order_reject side=%s symbol=%s slot_id=%s "
"qty=%s reason=%s",
side, slot.symbol, slot.slot_id, qty, ack.reason or "order_rejected",
side,
slot.symbol,
slot.slot_id,
qty,
ack.reason or "order_rejected",
)
self._rollback(slot, reason=ack.reason or "order_rejected")
r.rolled_back += 1
@@ -217,6 +247,30 @@ class ExecutionService:
side = "buy" if slot.status is SlotState.PENDING_BUY else "sell"
set_correlation_id(str(slot.slot_id)) # REQ-084: same key as submit
fs = self._broker.poll_fill(slot.broker_order_id, side=side, symbol=slot.symbol or "")
resolved_order_id = (
fs.raw.get("resolved_broker_order_id") if isinstance(fs.raw, dict) else None
)
if resolved_order_id and resolved_order_id != slot.broker_order_id:
if not self._repo.replace_dispatch(
slot.slot_id,
str(slot.broker_order_id),
str(resolved_order_id),
):
_log.error(
"resolved broker order id persistence failed "
"event=order_submit_resolution_conflict slot_id=%s symbol=%s",
slot.slot_id,
slot.symbol,
)
continue
slot = replace(slot, broker_order_id=str(resolved_order_id))
_log.info(
"order submission resolved event=order_submit_resolved "
"side=%s symbol=%s slot_id=%s",
side,
slot.symbol,
slot.slot_id,
)
if fs.is_filled:
self._on_filled(slot, fs, side, r)
r.filled += 1
@@ -230,7 +284,10 @@ class ExecutionService:
_log.error(
"order rejected event=order_reject side=%s symbol=%s slot_id=%s "
"reason=order_%s",
side, slot.symbol, slot.slot_id, fs.state,
side,
slot.symbol,
slot.slot_id,
fs.state,
)
self._rollback(slot, reason=f"order_{fs.state}")
r.rolled_back += 1
@@ -270,8 +327,11 @@ class ExecutionService:
_log.warning(
"fill price backfill: slot=%s symbol=%s broker_order_id=%s "
"avg_price=%s backfill_price=%s reason=avg_price_backfill",
slot.slot_id, slot.symbol, slot.broker_order_id,
avg, limit,
slot.slot_id,
slot.symbol,
slot.broker_order_id,
avg,
limit,
)
return float(limit), True
# limit_price also absent/≤0: skip + strong WARN (REQ-095 AC-6 / REQ-096 AC-2)
@@ -280,16 +340,22 @@ class ExecutionService:
"fill price unresolvable: slot=%s symbol=%s broker_order_id=%s "
"avg_price=%s limit_price=%s reason=fill_price_unresolvable "
"(slot stays PENDING — operator attention required)",
slot.slot_id, slot.symbol, slot.broker_order_id,
avg, limit,
slot.slot_id,
slot.symbol,
slot.broker_order_id,
avg,
limit,
)
# dcy-033 / REQ-100: CRITICAL alarm — slot stuck in PENDING.
if self._alarm_emitter is not None:
self._alarm_emitter.publish_alarm(
"fill_price_unresolvable",
f"체결가 미해결: 슬롯 PENDING 고착 위험 (slot={slot.slot_id} symbol={slot.symbol})",
fields={"slot_id": str(slot.slot_id), "symbol": slot.symbol,
"broker_order_id": slot.broker_order_id},
fields={
"slot_id": str(slot.slot_id),
"symbol": slot.symbol,
"broker_order_id": slot.broker_order_id,
},
)
return None, False
@@ -318,12 +384,17 @@ class ExecutionService:
old_avg = float(slot.avg_price) if slot.avg_price else 0.0
new_avg = (
(old_qty * old_avg + filled * fill_price) / new_qty
if new_qty > 0 else fill_price
if new_qty > 0
else fill_price
)
updated = self._svc.transit_slot(
slot.slot_id, SlotState.PENDING_BUY, SlotState.HOLDING,
reason="buy_filled", actor="execution_loop",
avg_price=new_avg, qty=new_qty,
slot.slot_id,
SlotState.PENDING_BUY,
SlotState.HOLDING,
reason="buy_filled",
actor="execution_loop",
avg_price=new_avg,
qty=new_qty,
)
event_type = "slot_filled_buy"
else: # PENDING_SELL — dcy-021/REQ-066: remainder>0 stays holding,
@@ -331,14 +402,20 @@ class ExecutionService:
total = self._balance_map().get(slot.symbol or "", 0)
if total > 0:
updated = self._svc.transit_slot(
slot.slot_id, SlotState.PENDING_SELL, SlotState.HOLDING,
reason="sell_filled_partial", actor="execution_loop",
slot.slot_id,
SlotState.PENDING_SELL,
SlotState.HOLDING,
reason="sell_filled_partial",
actor="execution_loop",
qty=float(total), # avg_price (cost basis) preserved
)
else:
updated = self._svc.transit_slot(
slot.slot_id, SlotState.PENDING_SELL, SlotState.INACTIVE,
reason="sell_filled", actor="execution_loop",
slot.slot_id,
SlotState.PENDING_SELL,
SlotState.INACTIVE,
reason="sell_filled",
actor="execution_loop",
)
event_type = "slot_filled_sell"
except SlotStateMismatchError:
@@ -347,9 +424,13 @@ class ExecutionService:
_log.info(
"order filled event=order_fill side=%s symbol=%s slot_id=%s "
"fill_price=%s filled_qty=%s fee=%s tax=%s",
side, slot.symbol, slot.slot_id,
fs.avg_price, fs.filled_qty,
getattr(fs, "fee", None), getattr(fs, "tax", None),
side,
slot.symbol,
slot.slot_id,
fs.avg_price,
fs.filled_qty,
getattr(fs, "fee", None),
getattr(fs, "tax", None),
)
# REQ-018: enqueue ledger work item AFTER the slot transition is durable.
# Slot transition is the critical path; ledger write is async (REQ-019).
@@ -389,26 +470,37 @@ class ExecutionService:
old_avg = float(slot.avg_price) if slot.avg_price else 0.0
new_avg = (
(old_qty * old_avg + filled * fill_price) / new_qty
if new_qty > 0 else fill_price
if new_qty > 0
else fill_price
)
updated = self._svc.transit_slot(
slot.slot_id, SlotState.PENDING_BUY, SlotState.HOLDING,
reason="buy_partial_cancel", actor="execution_loop",
avg_price=new_avg, qty=new_qty,
slot.slot_id,
SlotState.PENDING_BUY,
SlotState.HOLDING,
reason="buy_partial_cancel",
actor="execution_loop",
avg_price=new_avg,
qty=new_qty,
)
event_type = "slot_filled_buy"
else: # PENDING_SELL: remainder = broker balance, cost basis unchanged.
total = self._balance_map().get(slot.symbol or "", 0)
if total > 0:
updated = self._svc.transit_slot(
slot.slot_id, SlotState.PENDING_SELL, SlotState.HOLDING,
reason="sell_partial_cancel", actor="execution_loop",
slot.slot_id,
SlotState.PENDING_SELL,
SlotState.HOLDING,
reason="sell_partial_cancel",
actor="execution_loop",
qty=float(total),
)
else:
updated = self._svc.transit_slot(
slot.slot_id, SlotState.PENDING_SELL, SlotState.INACTIVE,
reason="sell_partial_cancel", actor="execution_loop",
slot.slot_id,
SlotState.PENDING_SELL,
SlotState.INACTIVE,
reason="sell_partial_cancel",
actor="execution_loop",
)
event_type = "slot_filled_sell"
except SlotStateMismatchError:
@@ -431,13 +523,14 @@ class ExecutionService:
_log.warning(
"pending order stale: slot=%s status=%s broker_order_id=%s "
"age_sec=%.0f threshold_sec=%d (no state change — ops attention)",
slot.slot_id, slot.status.value, slot.broker_order_id,
age, self._stale_threshold_sec,
slot.slot_id,
slot.status.value,
slot.broker_order_id,
age,
self._stale_threshold_sec,
)
def _try_timeout_cancel(
self, slot, now: datetime, side: str, r: ExecutionResult
) -> None:
def _try_timeout_cancel(self, slot, now: datetime, side: str, r: ExecutionResult) -> None:
"""Send cancel_order when the slot-level timeout is exceeded (dcy-022/REQ-069).
Best-effort: a failure only logs a warning — the slot is NOT changed here.
@@ -446,6 +539,8 @@ class ExecutionService:
This design is safe across the cancel-fill race: if the cancel races with a
fill, the next poll sees is_filled and follows the normal fill path (FR-4).
"""
if str(slot.broker_order_id or "").startswith("submission-unknown:"):
return
if slot.timeout_sec is None or slot.updated_at is None:
return
age = (now - slot.updated_at).total_seconds()
@@ -463,14 +558,19 @@ class ExecutionService:
_log.warning(
"timeout cancel sent: slot=%s status=%s broker_order_id=%s "
"age_sec=%.0f timeout_sec=%d broker_accepted=%s",
slot.slot_id, slot.status.value, slot.broker_order_id,
age, slot.timeout_sec, accepted,
slot.slot_id,
slot.status.value,
slot.broker_order_id,
age,
slot.timeout_sec,
accepted,
)
except Exception: # noqa: BLE001 - best-effort; do not block the loop
_log.warning(
"timeout cancel failed (exception): slot=%s broker_order_id=%s "
"(will retry next tick if still pending)",
slot.slot_id, slot.broker_order_id,
slot.slot_id,
slot.broker_order_id,
)
def _emit_event(self, event_type: str, slot, routing_strategy_id: Optional[str] = None) -> None:
@@ -507,7 +607,9 @@ class ExecutionService:
_log.warning(
"ledger skip: slot=%s symbol=%s side=%s reason=missing_portfolio_id "
"(trade NOT recorded to portfolio-hub)",
slot.slot_id, slot.symbol, side,
slot.slot_id,
slot.symbol,
side,
)
return
if fs.execution_id is None:
@@ -516,13 +618,17 @@ class ExecutionService:
_log.warning(
"ledger skip: slot=%s portfolio_id=%s side=%s reason=missing_execution_id "
"(trade NOT recorded to portfolio-hub)",
slot.slot_id, slot.portfolio_id, side,
slot.slot_id,
slot.portfolio_id,
side,
)
return
# REQ-095 KD-3: use pre-resolved price when available; fall back to
# fs.avg_price for any direct callers that do not pass resolved_price.
price = resolved_price if resolved_price is not None else (
float(fs.avg_price) if fs.avg_price is not None else 0.0
price = (
resolved_price
if resolved_price is not None
else (float(fs.avg_price) if fs.avg_price is not None else 0.0)
)
trade = LedgerTrade(
asset_id=str(slot.portfolio_id),
@@ -546,6 +652,7 @@ class ExecutionService:
next poll handles the rollback via the normal is_terminal_reject path.
"""
from uuid import UUID
sid = slot_id if isinstance(slot_id, UUID) else UUID(str(slot_id))
slot = self._repo.fetch_slot(sid)
if slot is None:
@@ -567,12 +674,15 @@ class ExecutionService:
except Exception: # noqa: BLE001 - best-effort
_log.warning(
"operator cancel failed: slot=%s broker_order_id=%s",
slot.slot_id, slot.broker_order_id,
slot.slot_id,
slot.broker_order_id,
)
return "cancel_failed"
_log.warning(
"operator cancel sent: slot=%s status=%s broker_order_id=%s",
slot.slot_id, slot.status.value, slot.broker_order_id,
slot.slot_id,
slot.status.value,
slot.broker_order_id,
)
return "ok"
@@ -584,19 +694,29 @@ class ExecutionService:
# dcy-021: increase rejected — the prior holding is intact
# (broker still holds), so return to holding, not inactive.
self._svc.transit_slot(
slot.slot_id, SlotState.PENDING_BUY, SlotState.HOLDING,
reason=reason, actor="execution_loop", qty=float(total),
slot.slot_id,
SlotState.PENDING_BUY,
SlotState.HOLDING,
reason=reason,
actor="execution_loop",
qty=float(total),
)
self._repo.clear_dispatch(slot.slot_id)
else: # initial buy rejected -> inactive (clears broker_order_id)
self._svc.transit_slot(
slot.slot_id, SlotState.PENDING_BUY, SlotState.INACTIVE,
reason=reason, actor="execution_loop",
slot.slot_id,
SlotState.PENDING_BUY,
SlotState.INACTIVE,
reason=reason,
actor="execution_loop",
)
else: # PENDING_SELL rejected -> back to holding (broker authoritative qty)
self._svc.transit_slot(
slot.slot_id, SlotState.PENDING_SELL, SlotState.HOLDING,
reason=reason, actor="execution_loop",
slot.slot_id,
SlotState.PENDING_SELL,
SlotState.HOLDING,
reason=reason,
actor="execution_loop",
qty=float(total) if total > 0 else None,
)
self._repo.clear_dispatch(slot.slot_id)