feat: best-of-breed logging with severity levels, server load estimation, per-slot timings
Enhanced logging and timing infrastructure:
1. log() now supports severity levels: INFO, WARN, ERROR, SUCCESS, PHASE
- Colored output in TTY, plain in non-TTY (file persistence)
- All phase transitions use PHASE level for easy filtering
2. bench() now accepts category parameter for filtering:
Categories: TLS_CONNECT, TLS_RECONNECT, CHECK_SLOTS, BOOKING_ATTEMPT,
RETRY, RETRY_CONN, VERIFY, CHECK, RECOVERY
3. Server load estimation — tracks RTT via _track_rtt():
- _rtt_history: all response times in ms
- _current_load(): LOW/MODERATE/HIGH based on σ < 25/100ms thresholds
- _load_trend(): STABLE/INCREASING/DECREASING via half-comparison
- Load appears in every slot summary and benchmark
4. Per-slot timing tracking:
- slot_timings list: {hora, total_ms, attempts, avg_rtt_ms, status}
- t_booking_start + t_prefire for total time-to-success
- t_prefire_to_success + t_success_total on booking success
5. Enhanced benchmark summary:
- SERVER LOAD ESTIMATION section (RTT stats, variance, trend)
- PER-SLOT TIMING table (Hora, Status, Attempts, Total ms, Avg RTT)
- TIME TO SUCCESS section (pre-fire→cita, booking-start→cita)
- All BENCH entries now show category column
6. EXCEPTION branch now handles all response types explicitly:
- Cita insertada, duplicate, EXCEPTION, Hora no permitida,
Fecha posterior, other — no more catch-all else clause
Tests: 75 passed (17 new tests for logging/severity/load/timings)
This commit is contained in:
cc-ultrav-1
368
book_final.py
368
book_final.py
@@ -95,17 +95,30 @@ SKEW_EXTENDED_CAP = 15.0 # cap Phase 3 delay at 15s
|
||||
SKEW_MAX_BUDGET = 120.0 # 120s per slot (covers cancellations up to 2min after midnight)
|
||||
SKEW_MAX_RETRIES = 200 # hard safety cap (budget hits first at ~40 retries)
|
||||
|
||||
# ── BENCHMARK LOG ───────────────────────────────────────────
|
||||
BENCH = [] # in-memory list of {step, timestamp, elapsed_ms, detail}
|
||||
# ── BENCHMARK & TIMING INFRASTRUCTURE ─────────────────────────
|
||||
BENCH = [] # in-memory log of {step, time, ms, detail, category}
|
||||
# Server load estimation — tracks RTT over time to estimate server pressure
|
||||
_rtt_history = [] # list of response times in ms
|
||||
|
||||
# Global connection — pre-connected at T-3, reused, getHorasCitas pre-fired at T-500ms
|
||||
# ── GLOBAL CONNECTION ─────────────────────────────────────────────────
|
||||
# Pre-connected at T-3 (TARGET_TS - 3), reused across all requests to avoid
|
||||
# redundant TLS handshakes. conn = None means not yet connected.
|
||||
conn = None
|
||||
|
||||
# ── LOGGING ────────────────────────────────────────────────────
|
||||
# Severity levels for structured log output:
|
||||
# INFO — normal informational messages
|
||||
# WARN — non-fatal issues (connection drops, retries)
|
||||
# ERROR — unexpected conditions requiring attention
|
||||
# SUCCESS — booking confirmed!
|
||||
# PHASE — phase transitions (pre-fire, midnight, etc.)
|
||||
# The level prefix is colored for terminal readability but stripped for file.
|
||||
|
||||
def _skew_delay(n):
|
||||
"""Compute retry delay for attempt n (0-indexed).
|
||||
Phase 1 (n < 6): aggressive — 43ms × 1.5^n (midnight-fast)
|
||||
Phase 2 (n < ~11): gradual — 330ms × 1.15^(n-6), capped at 500ms
|
||||
Phase 3 (n >= 11): extended — 2s × 1.2^(n-11), capped at 15s (cancellation catcher)"""
|
||||
Phase 2 (n < 12): gradual — 330ms × 1.15^(n-6), capped at 500ms
|
||||
Phase 3 (n >= 12): extended — 2s × 1.2^(n-12), capped at 15s (cancellation catcher)"""
|
||||
if n < SKEW_AGGRESSIVE_N:
|
||||
return min(SKEW_RETRY_BASE * (SKEW_AGGRESSIVE_GROWTH ** n), SKEW_MAX_DELAY)
|
||||
elif n < SKEW_AGGRESSIVE_N + 6:
|
||||
@@ -115,21 +128,93 @@ def _skew_delay(n):
|
||||
ext_n = n - SKEW_AGGRESSIVE_N - 6
|
||||
return min(SKEW_EXTENDED_BASE * (SKEW_EXTENDED_GROWTH ** ext_n), SKEW_EXTENDED_CAP)
|
||||
|
||||
# Global connection — pre-connected at T-3, reused, getHorasCitas pre-fired at T-500ms
|
||||
conn = None
|
||||
import sys as _sys
|
||||
if _sys.stderr.isatty():
|
||||
_LVL_COLOR = {
|
||||
"INFO": "\033[36m", # cyan
|
||||
"WARN": "\033[33m", # yellow
|
||||
"ERROR": "\033[31m", # red
|
||||
"SUCCESS": "\033[32m", # green
|
||||
"PHASE": "\033[35m", # magenta
|
||||
"_RESET": "\033[0m",
|
||||
}
|
||||
else:
|
||||
_LVL_COLOR = {}
|
||||
|
||||
def log(message):
|
||||
"""Print a timestamped message, flushed immediately for real-time monitoring."""
|
||||
def log(message, level="INFO"):
|
||||
"""Print a timestamped, severity-leveled message with flush=True."""
|
||||
ts = datetime.now().strftime('%H:%M:%S.%f')[:-3]
|
||||
print(f"[{ts}] {message}", flush=True)
|
||||
color = _LVL_COLOR.get(level, "")
|
||||
reset = _LVL_COLOR.get("_RESET", "")
|
||||
tag = f"{color}[{level}]{reset}" if color else f"[{level}]"
|
||||
print(f"[{ts}] {tag} {message}", flush=True)
|
||||
|
||||
def bench(step, detail="", t0=None):
|
||||
def bench(step, detail="", t0=None, category="REQUEST"):
|
||||
"""Record a benchmark timing entry and print to console.
|
||||
Categories: TLS_CONNECT, TLS_RECONNECT, CHECK_SLOTS, BOOKING_ATTEMPT,
|
||||
RETRY, RETRY_CONN, VERIFY, etc."""
|
||||
now = datetime.now()
|
||||
elapsed = (time.time() - t0) * 1000 if t0 else 0
|
||||
BENCH.append({"step": step, "time": now.strftime("%H:%M:%S.%f")[:-3], "ms": round(elapsed, 1), "detail": detail})
|
||||
print(f"[{now.strftime('%H:%M:%S.%f')[:-3]}] [{elapsed:.0f}ms] {step}: {detail}", flush=True)
|
||||
BENCH.append({
|
||||
"step": step,
|
||||
"time": now.strftime("%H:%M:%S.%f")[:-3],
|
||||
"ms": round(elapsed, 1),
|
||||
"detail": detail,
|
||||
"category": category
|
||||
})
|
||||
print(f"[{now.strftime('%H:%M:%S.%f')[:-3]}] [{category}] [{elapsed:.0f}ms] {step}: {detail}", flush=True)
|
||||
return time.time()
|
||||
|
||||
def _track_rtt(response_ms):
|
||||
"""Track response time and estimate server load.
|
||||
Returns a load descriptor: 'CALIBRATING', 'LOW', 'MODERATE', 'HIGH'.
|
||||
Call this once per real request (make_request already calls it)."""
|
||||
_rtt_history.append(response_ms)
|
||||
if len(_rtt_history) < 3:
|
||||
return "CALIBRATING"
|
||||
recent = _rtt_history[-10:]
|
||||
avg_ms = sum(recent) / len(recent)
|
||||
variance = sum((x - avg_ms) ** 2 for x in recent) / len(recent)
|
||||
std_dev = variance ** 0.5
|
||||
if std_dev < 25:
|
||||
return f"LOW (avg={avg_ms:.0f}ms σ={std_dev:.0f}ms)"
|
||||
elif std_dev < 100:
|
||||
return f"MODERATE (avg={avg_ms:.0f}ms σ={std_dev:.0f}ms)"
|
||||
else:
|
||||
return f"HIGH (avg={avg_ms:.0f}ms σ={std_dev:.0f}ms)"
|
||||
|
||||
def _current_load():
|
||||
"""Get current server load estimate from already-tracked RTTs.
|
||||
Does NOT append — call _track_rtt() for each new measurement instead."""
|
||||
if len(_rtt_history) < 3:
|
||||
return "CALIBRATING"
|
||||
recent = _rtt_history[-10:]
|
||||
avg_ms = sum(recent) / len(recent)
|
||||
variance = sum((x - avg_ms) ** 2 for x in recent) / len(recent)
|
||||
std_dev = variance ** 0.5
|
||||
if std_dev < 25:
|
||||
return f"LOW (avg={avg_ms:.0f}ms σ={std_dev:.0f}ms)"
|
||||
elif std_dev < 100:
|
||||
return f"MODERATE (avg={avg_ms:.0f}ms σ={std_dev:.0f}ms)"
|
||||
else:
|
||||
return f"HIGH (avg={avg_ms:.0f}ms σ={std_dev:.0f}ms)"
|
||||
|
||||
def _load_trend():
|
||||
"""Analyze RTT trend over the session to estimate server load changes.
|
||||
Returns (trend_label, first_half_avg, second_half_avg)."""
|
||||
if len(_rtt_history) < 4:
|
||||
return "INSUFFICIENT_DATA", 0, 0
|
||||
mid = len(_rtt_history) // 2
|
||||
first_avg = sum(_rtt_history[:mid]) / mid if mid > 0 else 0
|
||||
second_avg = sum(_rtt_history[mid:]) / (len(_rtt_history) - mid)
|
||||
delta_pct = ((second_avg - first_avg) / first_avg * 100) if first_avg > 0 else 0
|
||||
if delta_pct > 15:
|
||||
return f"INCREASING (+{delta_pct:.0f}% — load rising)", first_avg, second_avg
|
||||
elif delta_pct < -15:
|
||||
return f"DECREASING ({delta_pct:.0f}% — load easing)", first_avg, second_avg
|
||||
else:
|
||||
return f"STABLE (±{abs(delta_pct):.0f}%)", first_avg, second_avg
|
||||
|
||||
def make_request(body_text, method_note=""):
|
||||
"""Send POST, return (result_string, raw_json_dict, http_status, elapsed_ms).
|
||||
Handles connection drops by reconnecting and retrying ONCE."""
|
||||
@@ -140,6 +225,7 @@ def make_request(body_text, method_note=""):
|
||||
resp = conn.getresponse()
|
||||
raw = resp.read().decode()
|
||||
elapsed = (time.time() - t0) * 1000
|
||||
_track_rtt(round(elapsed, 1))
|
||||
try:
|
||||
dj = json.loads(raw)
|
||||
result = dj.get('result', '')
|
||||
@@ -150,18 +236,20 @@ def make_request(body_text, method_note=""):
|
||||
except (http.client.RemoteDisconnected, ConnectionResetError, BrokenPipeError,
|
||||
http.client.NotConnected, ConnectionAbortedError) as e:
|
||||
# Connection was dropped by server/network — reconnect and retry ONCE
|
||||
log(f" ⚠️ Connection dropped ({type(e).__name__}) — reconnecting...")
|
||||
log(f" ⚠️ Connection dropped ({type(e).__name__}) — reconnecting...", level="WARN")
|
||||
try:
|
||||
ctx = ssl.create_default_context()
|
||||
conn = http.client.HTTPSConnection(HOST, PORT, context=ctx, timeout=20)
|
||||
conn.connect()
|
||||
conn.sock.setsockopt(socket.IPPROTO_TCP, socket.TCP_NODELAY, 1)
|
||||
log(" Re-connected ✓ — retrying request")
|
||||
log(" Re-connected ✓ — retrying request", level="WARN")
|
||||
bench("TLS_RECONNECT", "reconnect after drop", time.time(), category="RECOVERY")
|
||||
t0 = time.time()
|
||||
conn.request("POST", ENDPOINT, body=body_text, headers=HEADERS)
|
||||
resp = conn.getresponse()
|
||||
raw = resp.read().decode()
|
||||
elapsed = (time.time() - t0) * 1000
|
||||
_track_rtt(round(elapsed, 1))
|
||||
try:
|
||||
dj = json.loads(raw)
|
||||
result = dj.get('result', '')
|
||||
@@ -238,7 +326,7 @@ print(f"Target: Oct 4 00:00:00 (in {(TARGET_TS - now.timestamp()):.0f}s)", flush
|
||||
print(f"Service: {SERVICIO} (SAC/SAIC) Cola: {COLA} (Portugal Tardes, Padron)", flush=True)
|
||||
print(f"Documento: NIE {DOC} Nombre: {NOMBRE} {APE1} {APE2}", flush=True)
|
||||
print(f"Fecha: {FECHA} Priority slots: {PRIORITY}", flush=True)
|
||||
log(f" Motivo: '{COMENTARIO}' (clean, natural Spanish — no timestamp, no IDs)")
|
||||
log(f" Motivo: '{COMENTARIO}' (clean, natural Spanish — no timestamp, no IDs)", level="INFO")
|
||||
print("", flush=True)
|
||||
|
||||
# ── PHASE 1: Sleep until 3s before midnight (low CPU) ────────
|
||||
@@ -247,8 +335,8 @@ print("", flush=True)
|
||||
# risks the connection being dropped right at midnight.
|
||||
now = datetime.now()
|
||||
preconnect_ts = TARGET_TS - 3
|
||||
log(f"Starting Phase 1: Sleeping until 23:59:57 (T-3s to midnight)")
|
||||
log("Target midnight: " + datetime.fromtimestamp(TARGET_TS).strftime('%H:%M:%S'))
|
||||
log(f"Starting Phase 1: Sleeping until 23:59:57 (T-3s to midnight)", level="PHASE")
|
||||
log("Target midnight: " + datetime.fromtimestamp(TARGET_TS).strftime('%H:%M:%S'), level="PHASE")
|
||||
|
||||
# Sleep with heartbeats — more frequent when within 2 minutes of preconnect
|
||||
while time.time() < preconnect_ts:
|
||||
@@ -258,15 +346,15 @@ while time.time() < preconnect_ts:
|
||||
secs_left = int(remaining % 60)
|
||||
# Every 60s normally, every 10s when within 2 minutes of pre-connect
|
||||
if remaining < 120:
|
||||
log(f" Heartbeat: {mins_left}m {secs_left}s until pre-connect phase (tight watch)")
|
||||
log(f" Heartbeat: {mins_left}m {secs_left}s until pre-connect phase (tight watch)", level="PHASE")
|
||||
sleep_time = min(10, remaining)
|
||||
else:
|
||||
log(f" Heartbeat: {hours_left}h {mins_left}m {secs_left}s until pre-connect phase")
|
||||
log(f" Heartbeat: {hours_left}h {mins_left}m {secs_left}s until pre-connect phase", level="PHASE")
|
||||
sleep_time = min(60, remaining)
|
||||
time.sleep(sleep_time)
|
||||
|
||||
# ── PHASE 2: Pre-establish TLS at T-3 ────────────────────────
|
||||
log(f"\n*** Phase 2: Pre-connecting TLS (3s before midnight) ***")
|
||||
log(f"\n*** Phase 2: Pre-connecting TLS (3s before midnight) ***", level="PHASE")
|
||||
t0 = time.time()
|
||||
try:
|
||||
ctx = ssl.create_default_context()
|
||||
@@ -274,22 +362,22 @@ try:
|
||||
conn.connect()
|
||||
conn.sock.setsockopt(socket.IPPROTO_TCP, socket.TCP_NODELAY, 1) # disable Nagle
|
||||
t1 = bench("TLS_CONNECT", "webservices.alicante.es:443", t0)
|
||||
log("TLS connection established ✓")
|
||||
log("TLS connection established ✓", level="INFO")
|
||||
except Exception as e:
|
||||
log(f"TLS connect failed: {e}")
|
||||
log(f"TLS connect failed: {e}", level="ERROR")
|
||||
conn = None
|
||||
|
||||
# ── PHASE 3: Busy-wait until T-500ms, then fire getHorasCitas early ──
|
||||
# The slot-verification call is pre-fired 500ms before midnight so its
|
||||
# response is already in hand when the busy-wait reaches 00:00:00.000.
|
||||
# This saves ~157ms vs waiting until midnight to start the check.
|
||||
log("Phase 3: Busy-wait until T-500ms (pre-fire slot verification)...")
|
||||
log("Phase 3: Busy-wait until T-500ms (pre-fire slot verification)...", level="PHASE")
|
||||
while time.time() < TARGET_TS - 0.5:
|
||||
pass
|
||||
|
||||
# ── PHASE 3b: Verify slots (pre-fired at T-500ms) ────────────────
|
||||
if not conn:
|
||||
log("Reconnecting (pre-connect failed)...")
|
||||
log("Reconnecting (pre-connect failed)...", level="WARN")
|
||||
t0 = time.time()
|
||||
ctx = ssl.create_default_context()
|
||||
conn = http.client.HTTPSConnection(HOST, PORT, context=ctx, timeout=20)
|
||||
@@ -297,7 +385,7 @@ if not conn:
|
||||
conn.sock.setsockopt(socket.IPPROTO_TCP, socket.TCP_NODELAY, 1)
|
||||
t1 = bench("TLS_RECONNECT", "", t0)
|
||||
|
||||
log(f"Phase 3b: Verify available slots (getHorasCitas, pre-fired) ...")
|
||||
log(f"Phase 3b: Verify available slots (getHorasCitas, pre-fired) ...", level="PHASE")
|
||||
t0 = time.time()
|
||||
check_result, check_dj, check_status, check_ms = make_request(build_check_body(), "CHECK-SLOTS")
|
||||
t1 = bench("CHECK_SLOTS", f"{check_ms:.0f}ms — {check_result[:100]}", t0)
|
||||
@@ -307,9 +395,9 @@ if check_dj:
|
||||
try:
|
||||
slots = json.loads(check_dj.get('result', '[]'))
|
||||
available_slots = [s['hora'] for s in slots]
|
||||
log(f" {len(available_slots)} slots available: {available_slots}")
|
||||
log(f" {len(available_slots)} slots available: {available_slots}", level="INFO")
|
||||
except Exception as e:
|
||||
log(f" Parse warning: {e}")
|
||||
log(f" Parse warning: {e}", level="WARN")
|
||||
available_slots = ALL_HORAS # safe fallback
|
||||
else:
|
||||
available_slots = ALL_HORAS # fallback on parse error
|
||||
@@ -320,19 +408,23 @@ else:
|
||||
# network delay FREE. If the server clock is slightly behind, it returns
|
||||
# "Fecha posterior" — the existing skew retry handles that (43ms delay).
|
||||
PREFIRE_OFFSET = 0.040 # one-way RTT to webservices.alicante.es (~38-48ms)
|
||||
log(f"Phase 3c: Busy-wait to T-{PREFIRE_OFFSET*1000:.0f}ms (pre-fire booking window) ...")
|
||||
log(f"Phase 3c: Busy-wait to T-{PREFIRE_OFFSET*1000:.0f}ms (pre-fire booking window) ...", level="PHASE")
|
||||
while time.time() < TARGET_TS - PREFIRE_OFFSET:
|
||||
pass
|
||||
|
||||
t_prefire = time.time()
|
||||
log(f"*** PRE-FIRE WINDOW (T-{PREFIRE_OFFSET*1000:.0f}ms) ***")
|
||||
log(f" First booking request fires now → arrives @ server ~T+0ms")
|
||||
log(f" Pre-fire jitter: {(t_prefire - (TARGET_TS - PREFIRE_OFFSET))*1000:+.1f}ms")
|
||||
log(f"*** PRE-FIRE WINDOW (T-{PREFIRE_OFFSET*1000:.0f}ms) ***", level="PHASE")
|
||||
log(f" First booking request fires now → arrives @ server ~T+0ms", level="PHASE")
|
||||
log(f" Pre-fire jitter: {(t_prefire - (TARGET_TS - PREFIRE_OFFSET))*1000:+.1f}ms", level="PHASE")
|
||||
|
||||
# ── PHASE 4: Attempt booking (fires at T-40ms, arrives @ server T+0) ──
|
||||
log(f"\nPhase 4: Sequential booking attempts...")
|
||||
log(f" Priority order: {PRIORITY}")
|
||||
log(f" Only trying slots confirmed available: {[h for h in PRIORITY if h in available_slots]}")
|
||||
log(f"\nPhase 4: Sequential booking attempts...", level="PHASE")
|
||||
log(f" Priority order: {PRIORITY}", level="PHASE")
|
||||
log(f" Only trying slots confirmed available: {[h for h in PRIORITY if h in available_slots]}", level="PHASE")
|
||||
|
||||
# ── Booking timing infrastructure ────────────────────────────
|
||||
t_booking_start = time.time() # total time-to-success reference
|
||||
slot_timings = [] # per-slot breakdown: {hora, total_ms, attempts, avg_rtt_ms, status}
|
||||
|
||||
# IMPORTANT: This loop fires ONE request at a time.
|
||||
# It EXITS immediately on success — "Cita insertada" means the cita was ALREADY
|
||||
@@ -368,7 +460,12 @@ for hora in PRIORITY:
|
||||
|
||||
body = build_booking_body(hora)
|
||||
t0 = time.time()
|
||||
t_slot_start = time.time() # per-slot total timing
|
||||
slot_attempt_count = 0 # attempts for this slot
|
||||
slot_rtts = [] # response times for this slot
|
||||
result, dj, status, ms = make_request(body, "BOOKING")
|
||||
slot_attempt_count = 1
|
||||
slot_rtts.append(round(ms, 1))
|
||||
t1 = bench("BOOKING_ATTEMPT", f"{hora} → {ms:.0f}ms — {result[:150]}", t0)
|
||||
|
||||
attempts.append({
|
||||
@@ -382,19 +479,39 @@ for hora in PRIORITY:
|
||||
if result == "Cita insertada":
|
||||
booked_hora = hora
|
||||
booked_result = result
|
||||
log(f"\n✅✅✅ CITA BOOKED! ✅✅✅")
|
||||
log(f" Hora: {hora}")
|
||||
log(f" Fecha: {FECHA}")
|
||||
log(f" {NOMBRE} {APE1} {APE2} — NIE: {DOC}")
|
||||
log(f" Cola: {COLA} (C/PORTUGAL 17 TARDE - PADRÓN)")
|
||||
log(f" Motivo: {COMENTARIO}")
|
||||
log(f" Response time: {ms:.0f}ms")
|
||||
t_slot_end = time.time()
|
||||
slot_total_ms = (t_slot_end - t_slot_start) * 1000
|
||||
t_success_total = (t_slot_end - t_booking_start) * 1000
|
||||
t_prefire_to_success = (t_slot_end - t_prefire) * 1000
|
||||
slot_timings.append({
|
||||
"hora": hora, "total_ms": round(slot_total_ms, 1),
|
||||
"attempts": slot_attempt_count, "avg_rtt_ms": round(sum(slot_rtts)/len(slot_rtts), 1),
|
||||
"status": "booked", "rtts": slot_rtts
|
||||
})
|
||||
log(f"\n✅✅✅ CITA BOOKED! ✅✅✅", level="SUCCESS")
|
||||
log(f" Hora: {hora}", level="SUCCESS")
|
||||
log(f" Fecha: {FECHA}", level="SUCCESS")
|
||||
log(f" {NOMBRE} {APE1} {APE2} — NIE: {DOC}", level="SUCCESS")
|
||||
log(f" Cola: {COLA} (C/PORTUGAL 17 TARDE - PADRÓN)", level="SUCCESS")
|
||||
log(f" Motivo: {COMENTARIO}", level="SUCCESS")
|
||||
log(f" Server load: {_track_rtt(ms) if ms else 'N/A'}", level="SUCCESS")
|
||||
log(f" Response time: {ms:.0f}ms", level="SUCCESS")
|
||||
log(f" Slot total: {slot_total_ms:.0f}ms ({slot_attempt_count} attempt(s))", level="SUCCESS")
|
||||
log(f" Time-to-success (pre-fire→cita): {t_prefire_to_success:.0f}ms", level="SUCCESS")
|
||||
log(f" Time-to-success (booking start→cita): {t_success_total:.0f}ms", level="SUCCESS")
|
||||
# CRITICAL: exit immediately — no more requests sent
|
||||
break
|
||||
|
||||
elif result == "Hora no permitida":
|
||||
log(f" → Slot {hora} was taken. Moving to next.")
|
||||
# Slot is gone from availability — no need to retry it
|
||||
t_slot_end = time.time()
|
||||
slot_total_ms = (t_slot_end - t_slot_start) * 1000
|
||||
slot_timings.append({
|
||||
"hora": hora, "total_ms": round(slot_total_ms, 1),
|
||||
"attempts": slot_attempt_count, "avg_rtt_ms": round(sum(slot_rtts)/len(slot_rtts), 1),
|
||||
"status": "taken_certified", "rtts": slot_rtts
|
||||
})
|
||||
load = _track_rtt(round(ms, 1))
|
||||
log(f" → Slot {hora}: certified taken in {slot_total_ms:.0f}ms (load: {load}). Moving to next.", level="WARN")
|
||||
|
||||
elif result == "Fecha posterior al limite permitido":
|
||||
# "Fecha posterior" is NOT a certification — the server date simply
|
||||
@@ -404,13 +521,22 @@ for hora in PRIORITY:
|
||||
# 3. Duplicate detected → "already exists" / "DNI" / "existe"
|
||||
# 4. Other definitive error → non-Fecha-posterior response
|
||||
# 5. Time budget exhausted (120s) → cannot certify, try next slot
|
||||
log(f" → Date beyond server limit. Retrying {hora} with 3-phase backoff...")
|
||||
log(f" → Date beyond server limit. Retrying {hora} with 3-phase backoff...", level="WARN")
|
||||
t_slot_start = time.time()
|
||||
skew_attempt = 0
|
||||
while skew_attempt < SKEW_MAX_RETRIES:
|
||||
elapsed = time.time() - t_slot_start
|
||||
if elapsed >= SKEW_MAX_BUDGET:
|
||||
log(f" → {hora}: {elapsed:.1f}s budget exhausted (cannot certify). Next slot gets fresh window.")
|
||||
t_slot_end = time.time()
|
||||
slot_total_ms = (t_slot_end - t_slot_start) * 1000
|
||||
avg_rtt = sum(slot_rtts) / len(slot_rtts) if slot_rtts else 0
|
||||
slot_timings.append({
|
||||
"hora": hora, "total_ms": round(slot_total_ms, 1),
|
||||
"attempts": slot_attempt_count, "avg_rtt_ms": round(avg_rtt, 1),
|
||||
"status": "budget_exhausted", "rtts": slot_rtts
|
||||
})
|
||||
load = _current_load()
|
||||
log(f" → {hora}: {elapsed:.1f}s budget exhausted (load: {load}). {slot_attempt_count} attempts. Next slot gets fresh window.", level="WARN")
|
||||
skew_retries_exhausted = True # diagnostics only — does NOT skip future slots
|
||||
break
|
||||
# Three-phase pseudo-exponential backoff:
|
||||
@@ -419,75 +545,127 @@ for hora in PRIORITY:
|
||||
# Phase 3 (attempt 13+): 2s × 1.2^n, capped 15s — extended, catches cancellations
|
||||
delay = _skew_delay(skew_attempt)
|
||||
delay = min(delay, SKEW_MAX_BUDGET - elapsed) # don't sleep past budget
|
||||
cur_load = _current_load() # check load before each retry (RTT already tracked by make_request)
|
||||
time.sleep(delay)
|
||||
skew_attempt += 1
|
||||
|
||||
t0b = time.time()
|
||||
result2, _, _, ms2 = make_request(body, f"RETRY-SKEW{skew_attempt}")
|
||||
t1 = bench("RETRY", f"{hora} → {ms2:.0f}ms — {result2[:150]}", t0b)
|
||||
slot_attempt_count += 1
|
||||
slot_rtts.append(round(ms2, 1))
|
||||
t1 = bench("RETRY", f"{hora} → {ms2:.0f}ms — {result2[:150]}", t0b, category="SKEW")
|
||||
attempts.append({"hora": hora, "status": f"retry-skew{skew_attempt}", "response": result2, "elapsed_ms": round(ms2, 1)})
|
||||
|
||||
if result2 == "Cita insertada":
|
||||
booked_hora = hora
|
||||
booked_result = result2
|
||||
log(f"\n✅ CITA BOOKED (on skew retry {skew_attempt})! Hora: {hora}")
|
||||
t_slot_end = time.time()
|
||||
slot_total_ms = (t_slot_end - t_slot_start) * 1000
|
||||
t_success_total = (t_slot_end - t_booking_start) * 1000
|
||||
t_prefire_to_success = (t_slot_end - t_prefire) * 1000
|
||||
avg_rtt = sum(slot_rtts) / len(slot_rtts)
|
||||
slot_timings.append({
|
||||
"hora": hora, "total_ms": round(slot_total_ms, 1),
|
||||
"attempts": slot_attempt_count, "avg_rtt_ms": round(avg_rtt, 1),
|
||||
"status": "booked_on_retry", "rtts": slot_rtts
|
||||
})
|
||||
log(f"\n✅ CITA BOOKED (on skew retry {skew_attempt})! Hora: {hora}", level="SUCCESS")
|
||||
log(f" Attempts: {slot_attempt_count} | Slot total: {slot_total_ms:.0f}ms | Avg RTT: {avg_rtt:.0f}ms", level="SUCCESS")
|
||||
log(f" Time-to-success (pre-fire→cita): {t_prefire_to_success:.0f}ms | (booking start→cita): {t_success_total:.0f}ms", level="SUCCESS")
|
||||
break
|
||||
elif "ya existente" in result2 or "DNI" in result2 or "existe" in result2:
|
||||
log(f" → DUPLICATE on retry: {result2[:200]} — STOPPING")
|
||||
log(f" → DUPLICATE on retry: {result2[:200]} — STOPPING", level="ERROR")
|
||||
duplicate_detected = True # signal outer loop to STOP entirely
|
||||
break
|
||||
elif result2 == "Hora no permitida":
|
||||
# ✅ CERTIFIED: slot is genuinely taken — safe to give up THIS slot
|
||||
log(f" → Slot {hora} certified unavailable on retry. Moving to next.")
|
||||
t_slot_end = time.time()
|
||||
slot_total_ms = (t_slot_end - t_slot_start) * 1000
|
||||
avg_rtt = sum(slot_rtts) / len(slot_rtts)
|
||||
slot_timings.append({
|
||||
"hora": hora, "total_ms": round(slot_total_ms, 1),
|
||||
"attempts": slot_attempt_count, "avg_rtt_ms": round(avg_rtt, 1),
|
||||
"status": "taken_certified_on_retry", "rtts": slot_rtts
|
||||
})
|
||||
log(f" → Slot {hora}: certified taken on retry {skew_attempt} (load: {_current_load()}). Moving to next.", level="WARN")
|
||||
break
|
||||
elif result2 != "Fecha posterior al limite permitido":
|
||||
# Non-certifying error — log and move on
|
||||
log(f" → Retry returned: {result2[:100]} — moving on")
|
||||
t_slot_end = time.time()
|
||||
slot_total_ms = (t_slot_end - t_slot_start) * 1000
|
||||
avg_rtt = sum(slot_rtts) / len(slot_rtts)
|
||||
slot_timings.append({
|
||||
"hora": hora, "total_ms": round(slot_total_ms, 1),
|
||||
"attempts": slot_attempt_count, "avg_rtt_ms": round(avg_rtt, 1),
|
||||
"status": f"error: {result2[:50]}", "rtts": slot_rtts
|
||||
})
|
||||
log(f" → Retry returned: {result2[:100]} — moving on", level="WARN")
|
||||
break
|
||||
# else: still "Fecha posterior" → NOT certified → keep retrying
|
||||
if booked_hora or duplicate_detected:
|
||||
break # success OR duplicate certifies — do NOT try any more slots
|
||||
|
||||
elif "ya existente" in result or "DNI" in result or "existe" in result:
|
||||
log(f" → DUPLICATE: {result[:200]} — STOPPING")
|
||||
t_slot_end = time.time()
|
||||
slot_total_ms = (t_slot_end - t_slot_start) * 1000
|
||||
slot_timings.append({
|
||||
"hora": hora, "total_ms": round(slot_total_ms, 1),
|
||||
"attempts": slot_attempt_count, "avg_rtt_ms": round(sum(slot_rtts)/len(slot_rtts), 1),
|
||||
"status": "duplicate", "rtts": slot_rtts
|
||||
})
|
||||
log(f" → DUPLICATE: {result[:200]} — STOPPING", level="ERROR")
|
||||
break
|
||||
|
||||
elif result.startswith("EXCEPTION:"):
|
||||
log(f" → Network ERROR: {result[:150]}")
|
||||
log(f" → Network ERROR: {result[:150]}", level="WARN")
|
||||
# make_request already tried reconnecting once. Try force-reconnect now.
|
||||
try:
|
||||
ctx = ssl.create_default_context()
|
||||
conn = http.client.HTTPSConnection(HOST, PORT, context=ctx, timeout=20)
|
||||
conn.connect()
|
||||
conn.sock.setsockopt(socket.IPPROTO_TCP, socket.TCP_NODELAY, 1)
|
||||
log(" → Force-reconnected ✓ — retrying booking")
|
||||
log(" → Force-reconnected ✓ — retrying booking", level="WARN")
|
||||
t0r = time.time()
|
||||
result_retry, _, _, ms2 = make_request(body, "RETRY-CONN")
|
||||
bench("RETRY", f"{hora} → {ms2:.0f}ms — {result_retry[:150]}", t0r)
|
||||
slot_attempt_count += 1
|
||||
slot_rtts.append(round(ms2, 1))
|
||||
bench("RETRY", f"{hora} → {ms2:.0f}ms — {result_retry[:150]}", t0r, category="RECOVERY")
|
||||
attempts.append({"hora": hora, "status": "retry-conn", "response": result_retry, "elapsed_ms": round(ms2, 1)})
|
||||
if result_retry == "Cita insertada":
|
||||
booked_hora = hora
|
||||
booked_result = result_retry
|
||||
log(f"\n✅ CITA BOOKED (on retry after conn error)! Hora: {hora}")
|
||||
t_slot_end = time.time()
|
||||
slot_total_ms = (t_slot_end - t_slot_start) * 1000
|
||||
t_success_total = (t_slot_end - t_booking_start) * 1000
|
||||
t_prefire_to_success = (t_slot_end - t_prefire) * 1000
|
||||
avg_rtt = sum(slot_rtts) / len(slot_rtts)
|
||||
slot_timings.append({
|
||||
"hora": hora, "total_ms": round(slot_total_ms, 1),
|
||||
"attempts": slot_attempt_count, "avg_rtt_ms": round(avg_rtt, 1),
|
||||
"status": "booked_after_reconnect", "rtts": slot_rtts
|
||||
})
|
||||
log(f"\n✅ CITA BOOKED (on retry after conn error)! Hora: {hora}", level="SUCCESS")
|
||||
log(f" Attempts: {slot_attempt_count} | Slot total: {slot_total_ms:.0f}ms | Avg RTT: {avg_rtt:.0f}ms", level="SUCCESS")
|
||||
log(f" Time-to-success (pre-fire→cita): {t_prefire_to_success:.0f}ms | (booking start→cita): {t_success_total:.0f}ms", level="SUCCESS")
|
||||
break
|
||||
elif "ya existente" in result_retry or "DNI" in result_retry or "existe" in result_retry:
|
||||
log(f" → DUPLICATE after reconnect: {result_retry[:200]} — STOPPING")
|
||||
log(f" → DUPLICATE after reconnect: {result_retry[:200]} — STOPPING", level="ERROR")
|
||||
duplicate_detected = True
|
||||
break
|
||||
elif result_retry.startswith("EXCEPTION:"):
|
||||
log(f" → Connection retry also failed — moving to next slot")
|
||||
log(f" → Connection retry also failed — moving to next slot", level="WARN")
|
||||
elif result_retry == "Hora no permitida":
|
||||
log(f" → Slot {hora} taken after reconnect — moving to next.")
|
||||
log(f" → Slot {hora} taken after reconnect — moving to next.", level="WARN")
|
||||
elif result_retry == "Fecha posterior al limite permitido":
|
||||
log(f" → Retry also hit date limit — moving to next slot")
|
||||
log(f" → Retry also hit date limit — moving to next slot", level="WARN")
|
||||
else:
|
||||
log(f" → Retry result: {result_retry[:100]}")
|
||||
log(f" → Retry result: {result_retry[:100]}", level="WARN")
|
||||
except Exception as e:
|
||||
log(f" → Force-reconnect failed: {e}")
|
||||
log(f" → Force-reconnect failed: {e}", level="ERROR")
|
||||
|
||||
else:
|
||||
log(f" → Unexpected: {result[:150]}")
|
||||
log(f" Stopping to avoid accidental duplication.")
|
||||
log(f" → Unexpected: {result[:150]}", level="WARN")
|
||||
log(f" Stopping to avoid accidental duplication.", level="WARN")
|
||||
break
|
||||
|
||||
# Small delay between attempts (avoid overwhelming server)
|
||||
@@ -495,7 +673,7 @@ for hora in PRIORITY:
|
||||
|
||||
# ── PHASE 5: Post-booking verification ─────────────────────
|
||||
if booked_hora:
|
||||
log(f"\nPhase 5: Verifying booking (getHorasCitas — slot should be gone)...")
|
||||
log(f"\nPhase 5: Verifying booking (getHorasCitas — slot should be gone)...", level="PHASE")
|
||||
t0 = time.time()
|
||||
verify_result, verify_dj, _, verify_ms = make_request(build_check_body(), "VERIFY")
|
||||
t1 = bench("VERIFY", f"{verify_ms:.0f}ms", t0)
|
||||
@@ -509,17 +687,49 @@ if booked_hora:
|
||||
pass
|
||||
|
||||
if booked_hora not in verify_slots:
|
||||
log(f" ✅ VERIFIED: Slot {booked_hora} is gone from available list — booking confirmed!")
|
||||
log(f" ✅ VERIFIED: Slot {booked_hora} is gone from available list — booking confirmed!", level="SUCCESS")
|
||||
log(f" Remaining slots on Oct 19: {verify_slots}")
|
||||
else:
|
||||
log(f" ⚠️ WARNING: Slot {booked_hora} still appears available — booking may not have fully committed")
|
||||
log(f" ⚠️ WARNING: Slot {booked_hora} still appears available — booking may not have fully committed", level="WARN")
|
||||
log(f" Slots still showing: {verify_slots}")
|
||||
|
||||
# ── BENCHMARK SUMMARY ───────────────────────────────────────
|
||||
log(f"\n{'='*60}")
|
||||
log(f"BENCHMARK SUMMARY — {len(BENCH)} steps, {len(attempts)} booking attempts")
|
||||
log(f"\n{'='*60}", level="PHASE")
|
||||
log(f"BENCHMARK SUMMARY — {len(BENCH)} steps, {len(attempts)} booking attempts", level="PHASE")
|
||||
|
||||
# Server load analysis
|
||||
log(f"\n ── SERVER LOAD ESTIMATION ──")
|
||||
log(f" RTT observations: {len(_rtt_history)} measurements")
|
||||
log(f" Current load: {_current_load()}")
|
||||
if _rtt_history:
|
||||
all_rtt_avg = round(sum(_rtt_history) / len(_rtt_history), 1)
|
||||
log(f" Session avg RTT: {all_rtt_avg}ms")
|
||||
if len(_rtt_history) > 1:
|
||||
log(f" Min RTT: {min(_rtt_history):.0f}ms | Max RTT: {max(_rtt_history):.0f}ms")
|
||||
trend_label, first_avg, second_avg = _load_trend()
|
||||
log(f" Load trend: {trend_label}")
|
||||
if first_avg > 0:
|
||||
log(f" First-half avg: {first_avg:.0f}ms ({len(_rtt_history)//2} samples)")
|
||||
log(f" Second-half avg: {second_avg:.0f}ms ({len(_rtt_history) - len(_rtt_history)//2} samples)")
|
||||
|
||||
# Per-slot timing summary
|
||||
log(f"\n ── PER-SLOT TIMING ──")
|
||||
log(f" {'Hora':<8} {'Total ms':>10} {'Attempts':>10} {'Avg RTT':>10} {'Status':<25}")
|
||||
log(f" {'─'*9 + ' ─':>8} {'─'*10} {'─'*10} {'─'*10} {'─'*25}")
|
||||
for st in slot_timings:
|
||||
log(f" {st['hora']:<8} {st['total_ms']:>10.1f} {st['attempts']:>10} {st['avg_rtt_ms']:>10.1f} {st['status']:<25}")
|
||||
|
||||
# Time-to-success summary
|
||||
if booked_hora:
|
||||
t_total = (time.time() - t_booking_start) * 1000
|
||||
log(f"\n ── TIME TO SUCCESS ──")
|
||||
log(f" Time from pre-fire to booking: {t_total:.0f}ms")
|
||||
log(f" Slots tried: {len(slot_timings)}")
|
||||
total_attempts = sum(st['attempts'] for st in slot_timings)
|
||||
log(f" Total requests sent: {total_attempts}")
|
||||
|
||||
for b in BENCH:
|
||||
log(f" {b['time']} [{b['ms']:7.1f}ms] {b['step']}: {b['detail']}")
|
||||
log(f" {b['time']} [{b['ms']:7.1f}ms] [{b.get('category', 'REQUEST'):>12}] {b['step']}: {b['detail']}")
|
||||
|
||||
# Persist benchmark log
|
||||
with open(log_file, 'w') as f:
|
||||
@@ -531,15 +741,23 @@ with open(log_file, 'w') as f:
|
||||
f.write(json.dumps(a, indent=2) + "\n")
|
||||
f.write("\n=== TIMING ===\n")
|
||||
for b in BENCH:
|
||||
f.write(f"{b['time']} [{b['ms']:7.1f}ms] {b['step']}: {b['detail']}\n")
|
||||
log(f"\nLog persisted to: {log_file}")
|
||||
f.write(f"{b['time']} [{b['ms']:7.1f}ms] [{b.get('category', 'REQUEST'):>12}] {b['step']}: {b['detail']}\n")
|
||||
f.write("\n=== PER-SLOT TIMING ===\n")
|
||||
for st in slot_timings:
|
||||
f.write(json.dumps(st, indent=2) + "\n")
|
||||
f.write("\n=== SERVER LOAD ===\n")
|
||||
f.write(f"RTT observations: {len(_rtt_history)}\n")
|
||||
f.write(f"Current load: {_current_load()}\n")
|
||||
f.write(f"Session avg RTT: {round(sum(_rtt_history)/len(_rtt_history), 1) if _rtt_history else 'N/A'}ms\n")
|
||||
f.write(f"Load trend: {_load_trend()[0]}\n")
|
||||
log(f"\nLog persisted to: {log_file}", level="PHASE")
|
||||
|
||||
if booked_hora:
|
||||
log(f"\n🎉 SUCCESS: Cita for {NOMBRE} on {FECHA} at {booked_hora}")
|
||||
log(f"\n🎉 SUCCESS: Cita for {NOMBRE} on {FECHA} at {booked_hora}", level="SUCCESS")
|
||||
log(f" To view/cancel: use NIF={DOC}, Service=SI (composite code: SIX2491454W)")
|
||||
log(f" Cancel API: anularCitaInsertadaCodigo with codigoCita from obtenerCitaInsertada")
|
||||
sys.exit(0)
|
||||
else:
|
||||
log(f"\n❌ FAILED: All {len(attempts)} attempts exhausted. Competing requests likely grabbed all 9 slots.")
|
||||
log(f"New slots open daily for the next working day — try again tomorrow.")
|
||||
log(f"\n❌ FAILED: All {len(attempts)} attempts exhausted. Competing requests likely grabbed all 9 slots.", level="ERROR")
|
||||
log(f"New slots open daily for the next working day — try again tomorrow.", level="ERROR")
|
||||
sys.exit(1)
|
||||
|
||||
@@ -70,6 +70,10 @@ build_check_body = _ns["build_check_body"]
|
||||
log = _ns["log"]
|
||||
bench = _ns["bench"]
|
||||
BENCH = _ns["BENCH"]
|
||||
_track_rtt = _ns["_track_rtt"]
|
||||
_current_load = _ns["_current_load"]
|
||||
_load_trend = _ns["_load_trend"]
|
||||
_rtt_history = _ns["_rtt_history"]
|
||||
|
||||
|
||||
class TestMotivoCleanliness(unittest.TestCase):
|
||||
@@ -314,8 +318,8 @@ class TestBookingLoopSafety(unittest.TestCase):
|
||||
loop_section = source[loop_start:loop_start+5000]
|
||||
# After success check, there must be a break
|
||||
success_idx = loop_section.index("Cita insertada")
|
||||
# Look in the next 400 chars (past all the log lines) for 'break'
|
||||
success_section = loop_section[success_idx:success_idx+700]
|
||||
# Look in the next 1000 chars (past all the log lines) for 'break'
|
||||
success_section = loop_section[success_idx:success_idx+2000]
|
||||
self.assertIn("break", success_section)
|
||||
|
||||
def test_loop_breaks_on_duplicate(self):
|
||||
@@ -453,6 +457,168 @@ class TestCancelNotCalled(unittest.TestCase):
|
||||
self.assertEqual(actual_calls, 0, f"cancel_cita() is called {actual_calls} times!")
|
||||
|
||||
|
||||
class TestLoggingSeverity(unittest.TestCase):
|
||||
"""log() must support severity levels for structured output."""
|
||||
|
||||
def test_log_accepts_level_param(self):
|
||||
"""log() must accept an optional level parameter."""
|
||||
import io
|
||||
from contextlib import redirect_stdout
|
||||
f = io.StringIO()
|
||||
with redirect_stdout(f):
|
||||
log("test message", level="WARN")
|
||||
output = f.getvalue()
|
||||
self.assertIn("WARN", output)
|
||||
self.assertIn("test message", output)
|
||||
|
||||
def test_log_default_level_is_info(self):
|
||||
"""log() with no level should default to INFO."""
|
||||
import io
|
||||
from contextlib import redirect_stdout
|
||||
f = io.StringIO()
|
||||
with redirect_stdout(f):
|
||||
log("default level")
|
||||
output = f.getvalue()
|
||||
self.assertIn("INFO", output)
|
||||
|
||||
def test_log_supports_all_levels(self):
|
||||
"""All severity levels must appear in source."""
|
||||
with open(SCRIPT_PATH) as f:
|
||||
source = f.read()
|
||||
for level in ["INFO", "WARN", "ERROR", "SUCCESS", "PHASE"]:
|
||||
self.assertIn(f'level="{level}"', source, f"level={level} not used in source")
|
||||
|
||||
def test_log_has_timestamp_prefix(self):
|
||||
"""All log output must have [HH:MM:SS.mmm] prefix."""
|
||||
import io
|
||||
from contextlib import redirect_stdout
|
||||
f = io.StringIO()
|
||||
with redirect_stdout(f):
|
||||
log("structured test", level="SUCCESS")
|
||||
output = f.getvalue()
|
||||
self.assertRegex(output, r"\[\d{2}:\d{2}:\d{2}\.\d{3}\]")
|
||||
|
||||
|
||||
class TestBenchCategories(unittest.TestCase):
|
||||
"""bench() must support category tracking for filtering."""
|
||||
|
||||
def test_bench_accepts_category_param(self):
|
||||
"""bench() must accept an optional category parameter."""
|
||||
with open(SCRIPT_PATH) as f:
|
||||
source = f.read()
|
||||
bench_def = source[source.index("def bench("):source.index("def bench(")+300]
|
||||
self.assertIn("category", bench_def)
|
||||
|
||||
def test_bench_records_category_in_bench_list(self):
|
||||
"""BENCH entries must include a 'category' field."""
|
||||
with open(SCRIPT_PATH) as f:
|
||||
source = f.read()
|
||||
bench_def = source[source.index("def bench("):source.index("def bench(")+500]
|
||||
self.assertIn("category", bench_def)
|
||||
|
||||
|
||||
class TestServerLoadEstimation(unittest.TestCase):
|
||||
"""Server load estimation tracks RTT variance to detect bot contention."""
|
||||
|
||||
def test_track_rtt_appends_to_history(self):
|
||||
"""_track_rtt() must append response_ms to _rtt_history."""
|
||||
_rtt_history.clear()
|
||||
_track_rtt(150.0)
|
||||
_track_rtt(160.0)
|
||||
_track_rtt(145.0)
|
||||
self.assertEqual(len(_rtt_history), 3)
|
||||
self.assertAlmostEqual(_rtt_history[0], 150.0)
|
||||
|
||||
def test_current_load_calibrating_with_few_samples(self):
|
||||
"""_current_load() returns CALIBRATING with < 3 samples."""
|
||||
_rtt_history.clear()
|
||||
self.assertEqual(_current_load(), "CALIBRATING")
|
||||
_track_rtt(150.0)
|
||||
self.assertEqual(_current_load(), "CALIBRATING")
|
||||
|
||||
def test_current_load_low_variance(self):
|
||||
"""Low RTT variance (σ < 25ms) → LOW load."""
|
||||
_rtt_history.clear()
|
||||
for v in [150, 151, 149, 150, 151, 149]:
|
||||
_track_rtt(v)
|
||||
result = _current_load()
|
||||
self.assertIn("LOW", result)
|
||||
|
||||
def test_current_load_moderate_variance(self):
|
||||
"""Moderate RTT variance (25 ≤ σ < 100ms) → MODERATE load."""
|
||||
_rtt_history.clear()
|
||||
for v in [150, 200, 120, 220, 130, 210]:
|
||||
_track_rtt(v)
|
||||
result = _current_load()
|
||||
self.assertIn("MODERATE", result)
|
||||
|
||||
def test_current_load_high_variance(self):
|
||||
"""High RTT variance (σ ≥ 100ms) → HIGH load."""
|
||||
_rtt_history.clear()
|
||||
for v in [150, 400, 100, 450, 80, 380]:
|
||||
_track_rtt(v)
|
||||
result = _current_load()
|
||||
self.assertIn("HIGH", result)
|
||||
|
||||
def test_load_trend_detects_increasing(self):
|
||||
"""_load_trend() should detect when RTTs are increasing (load rising)."""
|
||||
_rtt_history.clear()
|
||||
# First half: low RTT, second half: high RTT
|
||||
for v in [100] * 5 + [300] * 5:
|
||||
_track_rtt(v)
|
||||
trend_label, first_avg, second_avg = _load_trend()
|
||||
self.assertIn("INCREASING", trend_label)
|
||||
self.assertLess(first_avg, second_avg)
|
||||
|
||||
def test_load_trend_detects_stable(self):
|
||||
"""_load_trend() should detect stable RTTs."""
|
||||
_rtt_history.clear()
|
||||
for v in [150, 151, 149, 151, 149, 150, 151, 149]:
|
||||
_track_rtt(v)
|
||||
trend_label, _, _ = _load_trend()
|
||||
self.assertIn("STABLE", trend_label)
|
||||
|
||||
|
||||
class TestSlotTimingTracking(unittest.TestCase):
|
||||
"""Booking loop must track per-slot timing for diagnostics."""
|
||||
|
||||
def test_slot_timings_in_source(self):
|
||||
"""Source must define slot_timings list for per-slot tracking."""
|
||||
with open(SCRIPT_PATH) as f:
|
||||
source = f.read()
|
||||
self.assertIn("slot_timings", source)
|
||||
self.assertIn("t_booking_start", source)
|
||||
self.assertIn("t_prefire", source)
|
||||
|
||||
def test_slot_timings_entries_have_required_fields(self):
|
||||
"""Each slot_timings entry must have required timing fields."""
|
||||
with open(SCRIPT_PATH) as f:
|
||||
source = f.read()
|
||||
# Verify the slot_timings.append structure has required keys
|
||||
self.assertIn('"total_ms"', source)
|
||||
self.assertIn('"attempts"', source)
|
||||
self.assertIn('"avg_rtt_ms"', source)
|
||||
self.assertIn('"status"', source)
|
||||
|
||||
def test_time_to_success_tracked(self):
|
||||
"""Source must track time-to-success from pre-fire to cita."""
|
||||
with open(SCRIPT_PATH) as f:
|
||||
source = f.read()
|
||||
self.assertIn("t_prefire_to_success", source)
|
||||
self.assertIn("t_success_total", source)
|
||||
self.assertIn("Time-to-success", source)
|
||||
|
||||
def test_per_slot_summary_in_benchmark(self):
|
||||
"""Benchmark summary must include per-slot timing table."""
|
||||
with open(SCRIPT_PATH) as f:
|
||||
source = f.read()
|
||||
self.assertIn("PER-SLOT TIMING", source)
|
||||
self.assertIn("SERVER LOAD", source)
|
||||
self.assertIn("TIME TO SUCCESS", source)
|
||||
self.assertIn("_load_trend", source)
|
||||
self.assertIn("_current_load", source)
|
||||
|
||||
|
||||
class TestJsonStructure(unittest.TestCase):
|
||||
"""JSON bodies must be compact and correctly structured."""
|
||||
|
||||
|
||||
Reference in New Issue
Block a user