citas-getter/book_final.py

#!/usr/bin/env python3
"""
FINAL hardened booking script — Portugal Tardes (cola I), Oct 19, 2026.

Addresses all concerns:
  - Clean motivo (no tracking ID, natural Spanish reason)
  - Full browser-like headers (Accept, X-Requested-With, Origin, Referer, UA)
  - Realtime in-memory log of every attempt
  - Duplicate prevention (sequential, pre-flight check, post-verify)
  - Benchmark/timing of every step, persisted to /tmp/booking_log.txt
  - Cancel procedure function (for emergency duplicate cleanup)
  - Careful loop review (no accidental re-firing)
  - T-3 pre-connect (not T-5): server closes idle TLS after ~5s; T-3 keeps conn alive
  - Contrarian slot order: post-15h middle slots (15:15-15:45) tried first
  - getHorasCitas pre-fired at T-500ms to overlap with pre-midnight idle — saves ~157ms
  - Booking request pre-fired at T-40ms to absorb one-way RTT — saves ~40ms
  - TCP_NODELAY on all connections to disable Nagle's algorithm
  - Skew retry at 43ms (not 200ms): lift(40ms)+buffer(3ms) — faster stack-up, covers NTP skew up to ~130ms
"""
import http.client, ssl, json, time, sys, socket
from datetime import datetime

# ── USER DATA ───────────────────────────────────────────────
HOST   = "webservices.alicante.es"
PORT   = 443
API    = "/WsCitaPreviaPublic-RESTWebService-context-root/rest/1"
ENDPOINT = API + "/ScCitaVo1"
CT     = "application/vnd.oracle.adf.action+json"  # REQUIRED by ADF REST server

SERVICIO   = "S"
COLA       = "I"
FECHA      = "19-10-2026"
DOC        = "X2491454W"
NOMBRE     = "Humberto"
APE1       = "Normey"
APE2       = "Gomez"
TIPO       = "2"          # NIE
TEL        = "687915599"
EMAIL      = "hj@normey.net"
COMENTARIO = "Solicitud de Alta en el Padrón"  # CLEAN, natural reason

# impuestos is NOT visible on the cita itself — it's an internal API param.
# For service S (not L), the frontend hardcodes resumen.impuestos = 'N'.
# The validation (controllers.js line 611) only blocks service 'L' (Bono).
# The verCita display model ($scope.cita = {...}) does NOT include impuestos.
# City staff see: nombre, apellidos, NIF, fecha, hora, oficina, codigoCita only.
IMPUESTOS  = "N"  # hardcoded by frontend for servicio != 'L' — sent to API but never displayed
IP         = "0.0.0.0"

ALL_HORAS = ["14:30","14:45","15:00","15:15","15:30","15:45","16:00","16:15","16:30"]
# Contrarian strategy: most bots target 16:00 (preferred) or 14:30 (earliest),
# leaving 15:15-15:45 under-contested during the midnight rush.
# Post-15h slots tried first; pre-15h (14:30-15:00) as absolute fallback.
PRIORITY   = ["15:15","15:30","15:45","16:15","16:30","16:00","15:00","14:45","14:30"]

# Browser-like headers (matching what Angular $http + browser would send)
HEADERS = {
    "Content-Type": CT,
    "Accept": "application/json, text/plain, */*",
    "X-Requested-With": "XMLHttpRequest",
    "Origin": "https://citaprevia.alicante.es",
    "Referer": "https://citaprevia.alicante.es/CitaPrevia/",
    "User-Agent": "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/120.0.0.0 Safari/537.36",
}

# ── TIMING TARGET ───────────────────────────────────────────
# Oct 4, 2026 00:00:00 CEST (when the 15-day window slides to include Oct 19)
TARGET_TS = datetime(2026, 10, 4, 0, 0, 0).timestamp()

# ── BENCHMARK LOG ───────────────────────────────────────────
BENCH = []  # in-memory list of {step, timestamp, elapsed_ms, detail}

# Global connection — pre-connected at T-3, reused, getHorasCitas pre-fired at T-500ms
conn = None

def log(message):
    """Print a timestamped message, flushed immediately for real-time monitoring."""
    ts = datetime.now().strftime('%H:%M:%S.%f')[:-3]
    print(f"[{ts}] {message}", flush=True)

def bench(step, detail="", t0=None):
    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)
    return time.time()

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."""
    global conn
    t0 = time.time()
    try:
        conn.request("POST", ENDPOINT, body=body_text, headers=HEADERS)
        resp = conn.getresponse()
        raw = resp.read().decode()
        elapsed = (time.time() - t0) * 1000
        try:
            dj = json.loads(raw)
            result = dj.get('result', '')
        except:
            result = raw[:300] if raw else "(empty)"
            dj = None
        return result, dj, resp.status, elapsed
    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...")
        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")
            t0 = time.time()
            conn.request("POST", ENDPOINT, body=body_text, headers=HEADERS)
            resp = conn.getresponse()
            raw = resp.read().decode()
            elapsed = (time.time() - t0) * 1000
            try:
                dj = json.loads(raw)
                result = dj.get('result', '')
            except:
                result = raw[:300] if raw else "(empty)"
                dj = None
            return result, dj, resp.status, elapsed
        except Exception as e2:
            elapsed = (time.time() - t0) * 1000
            return f"EXCEPTION: {e2}", None, 0, elapsed
    except Exception as e:
        elapsed = (time.time() - t0) * 1000
        return f"EXCEPTION: {e}", None, 0, elapsed

def build_booking_body(hora):
    # Clean motivo: just the natural reason — NO timestamp, NO tracking IDs
    return json.dumps({
        "name": "insertarCitaPrevia",
        "parameters": [
            {"servicio": SERVICIO},
            {"cola": COLA},
            {"fecha": FECHA},
            {"hora": hora},
            {"documento": DOC},
            {"ip": IP},
            {"nombre": NOMBRE},
            {"apellido1": APE1},
            {"apellido2": APE2},
            {"tipo": TIPO},
            {"telefono": TEL},
            {"email": EMAIL},
            {"impuestos": IMPUESTOS},
            {"motivo": COMENTARIO},
            {"procedencia": "NULO"},
        ]
    }, separators=(',', ':'))

def build_check_body():
    return json.dumps({
        "name": "getHorasCitas",
        "parameters": [
            {"servicio": SERVICIO},
            {"cola": COLA},
            {"fecha": FECHA},
        ]
    }, separators=(',', ':'))

def cancel_cita(codigo_cita=None):
    """Emergency cancel procedure.
    Flow: obtenerCitaInsertada (find cita by NIF) → anularCitaInsertadaCodigo (cancel by code)
    """
    print("\n⚠️  CANCEL PROCEDURE (emergency only)", flush=True)
    print("   Step 1: Look up cita via obtenerCitaInsertada...", flush=True)
    body = json.dumps({
        "name": "obtenerCitaInsertada",
        "parameters": [
            {"servicio": SERVICIO},
            {"cola": COLA},
            {"documento": DOC},
        ]
    }, separators=(',', ':'))
    result, dj, status, elapsed = make_request(body, "CANCEL-LOOKUP")
    print(f"   Lookup result: {result[:200]}", flush=True)
    # The response contains cita details — extract codigoCita
    # Then call anularCitaInsertadaCodigo with servicio, cola, documento, codigoCita
    # (Full implementation available if needed — API confirmed in services.js lines 35-46)

# ── INITIAL LOG ─────────────────────────────────────────────
log_file = "/tmp/booking_log.txt"
now = datetime.now()
print(f"=== BOOKING ASSISTANT STARTED ===", flush=True)
print(f"Time: {now.strftime('%Y-%m-%d %H:%M:%S.%f')[:-3]}", flush=True)
print(f"Target: Oct 4 00:00:00 (in {(TARGET_TS - now.timestamp()):.0f}s)", flush=True)
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)")
print("", flush=True)

# ── PHASE 1: Sleep until 3s before midnight (low CPU) ────────
# T-3 (not T-5) to keep the TLS connection alive through midnight —
# the server closes idle TLS connections after ~5s, so a T-5 preconnect
# 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'))

# Sleep with heartbeats — more frequent when within 2 minutes of preconnect
while time.time() < preconnect_ts:
    remaining = preconnect_ts - time.time()
    hours_left = int(remaining / 3600)
    mins_left = int((remaining % 3600) / 60)
    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)")
        sleep_time = min(10, remaining)
    else:
        log(f"  Heartbeat: {hours_left}h {mins_left}m {secs_left}s until pre-connect 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) ***")
t0 = time.time()
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)  # disable Nagle
    t1 = bench("TLS_CONNECT", "webservices.alicante.es:443", t0)
    log("TLS connection established ✓")
except Exception as e:
    log(f"TLS connect failed: {e}")
    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)...")
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)...")
    t0 = time.time()
    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)
    t1 = bench("TLS_RECONNECT", "", t0)

log(f"Phase 3b: Verify available slots (getHorasCitas, pre-fired) ...")
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)

available_slots = []
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}")
    except Exception as e:
        log(f"  Parse warning: {e}")
        available_slots = ALL_HORAS  # safe fallback
else:
    available_slots = ALL_HORAS  # fallback on parse error

# ── PHASE 3c: Busy-wait to T-40ms (pre-fire window for booking) ──
# Fire the first booking request 40ms before OUR midnight. The one-way network
# latency (~40ms) means it arrives at the server AT their midnight, making the
# 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) ...")
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")

# ── 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]}")

# IMPORTANT: This loop fires ONE request at a time.
# It EXITS immediately on success (no more requests after "Cita insertada").
# Each slot is tried ONCE, with retries ONLY for:
#   - "Fecha posterior" (clock skew): up to 5×43ms retry on SAME slot
#   - "EXCEPTION:" (conn drop): force-reconnect + 1 retry on SAME slot
#   - "Hora no permitida": no retry (slot taken — move to next)
# Duplicate detection ("ya existente") → STOP immediately
# This prevents duplicate bookings while tolerating clock/network issues.

attempts = []  # in-memory log of all attempts
booked_hora = None
booked_result = None
skew_retries_exhausted = False  # Set True after first slot exhausts all skew retries

for hora in PRIORITY:
    if hora not in available_slots:
        log(f"  ↷ {hora}: SKIP (not in available list from Phase 3)")
        attempts.append({"hora": hora, "status": "skipped", "response": "not in available list"})
        continue

    body = build_booking_body(hora)
    t0 = time.time()
    result, dj, status, ms = make_request(body, "BOOKING")
    t1 = bench("BOOKING_ATTEMPT", f"{hora} → {ms:.0f}ms — {result[:150]}", t0)

    attempts.append({
        "hora": hora,
        "status": status,
        "response": result,
        "elapsed_ms": round(ms, 1),
        "timestamp": datetime.now().strftime('%H:%M:%S.%f')[:-3]
    })

    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")
        # 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

    elif result == "Fecha posterior al limite permitido":
        if skew_retries_exhausted:
            log(f"   → Date beyond limit (skew confirmed — all retries exhausted). Moving to next slot.")
        else:
            log(f"   → Date beyond server limit (possible clock skew). Retrying {hora} up to 5x...")
            for skew_attempt in range(5):
                # 43ms delay: lift_time(40ms) + buffer(3ms)
                # After pre-fire fails, this allows retry to arrive past server's midnight + lift.
                # 5 × 43ms ≈ 645ms total window — covers NTP skew up to ~130ms.
                # With 200ms this would be ~1000ms — slower recovery for no real safety gain.
                time.sleep(0.043)  # server lift(40ms) + 3ms buffer
                t0b = time.time()
                result2, _, _, ms2 = make_request(body, f"RETRY-SKEW{skew_attempt+1}")
                t1 = bench("RETRY", f"{hora} → {ms2:.0f}ms — {result2[:150]}", t0b)
                attempts.append({"hora": hora, "status": f"retry-skew{skew_attempt+1}", "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+1})!  Hora: {hora}")
                    break
                elif "ya existente" in result2 or "DNI" in result2 or "existe" in result2:
                    log(f"   → POSSIBLE DUPLICATE on retry: {result2[:200]}")
                    log(f"   ⚠️ STOPPING — cita may already exist!")
                    break
                elif result2 != "Fecha posterior al limite permitido":
                    log(f"   → Retry returned: {result2[:100]} — moving on")
                    break
                # else: still "Fecha posterior" → loop continues to next retry
            else:
                # All 5 skew retries exhausted — server clock is ~1s ahead
                log(f"   → Still beyond limit after 5 retries (~215ms elapsed).")
                log(f"   Subsequent slots will skip retry to save time.")
                skew_retries_exhausted = True
            if booked_hora:
                break

    elif "ya existente" in result or "DNI" in result or "existe" in result:
        log(f"   → POSSIBLE DUPLICATE: {result[:200]}")
        log(f"   ⚠️  STOPPING — a cita for this person may already exist!")
        log(f"   Use cancel_cita() to check and clean up if needed.")
        break

    elif result.startswith("EXCEPTION:"):
        log(f"   → Network ERROR: {result[:150]}")
        # 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")
            t0r = time.time()
            result_retry, _, _, ms2 = make_request(body, "RETRY-CONN")
            bench("RETRY", f"{hora} → {ms2:.0f}ms — {result_retry[:150]}", t0r)
            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}")
                break
            elif result_retry.startswith("EXCEPTION:"):
                log(f"   → Connection retry also failed — moving to next slot")
            else:
                log(f"   → Retry result: {result_retry[:100]}")
        except Exception as e:
            log(f"   → Force-reconnect failed: {e}")

    else:
        log(f"   → Unexpected: {result[:150]}")
        log(f"   Stopping to avoid accidental duplication.")
        break

    # Small delay between attempts (avoid overwhelming server)
    time.sleep(0.03)

# ── PHASE 5: Post-booking verification ─────────────────────
if booked_hora:
    log(f"\nPhase 5: Verifying booking (getHorasCitas — slot should be gone)...")
    t0 = time.time()
    verify_result, verify_dj, _, verify_ms = make_request(build_check_body(), "VERIFY")
    t1 = bench("VERIFY", f"{verify_ms:.0f}ms", t0)

    verify_slots = []
    if verify_dj:
        try:
            slots = json.loads(verify_dj.get('result', '[]'))
            verify_slots = [s['hora'] for s in slots]
        except:
            pass

    if booked_hora not in verify_slots:
        log(f"   ✅ VERIFIED: Slot {booked_hora} is gone from available list — booking confirmed!")
        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"   Slots still showing: {verify_slots}")

# ── BENCHMARK SUMMARY ───────────────────────────────────────
log(f"\n{'='*60}")
log(f"BENCHMARK SUMMARY — {len(BENCH)} steps, {len(attempts)} booking attempts")
for b in BENCH:
    log(f"  {b['time']}  [{b['ms']:7.1f}ms]  {b['step']}: {b['detail']}")

# Persist benchmark log
with open(log_file, 'w') as f:
    f.write(f"Booking log — {datetime.now().strftime('%Y-%m-%d %H:%M:%S')}\n")
    f.write(f"NIE: {DOC}  Cola: {COLA}  Fecha: {FECHA}\n")
    f.write(f"Tracking: None (clean motivo)\n\n")
    f.write("=== ATTEMPTS ===\n")
    for a in attempts:
        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}")

if booked_hora:
    log(f"\n🎉 SUCCESS: Cita for {NOMBRE} on {FECHA} at {booked_hora}")
    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.")
    sys.exit(1)