e837a4ff35
- else (catch-all) branch now appends to slot_timings with 'unexpected' status - Target timestamp display fixed: now uses datetime.fromtimestamp(TARGET_TS) instead of hardcoded 'Oct 4 00:00:00' - Added booking_run_2.log: Oct 20 midnight attempt (blocked by duplicate cita)
1368 lines
69 KiB
Python
1368 lines
69 KiB
Python
#!/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 with three-phase backoff (43ms×1.5^n for 6 aggressive, then 1.15x
|
||
gradual, then 2s×1.2^n gradual to 120s budget — catches cancellations); each
|
||
slot retries independently; only gives up on certified signals: "Hora no permitida"
|
||
= taken, "Cita insertada" = booked, duplicate = STOP)
|
||
"""
|
||
import http.client, ssl, json, time, sys, socket, argparse
|
||
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()
|
||
|
||
# ── SKEW RETRY CONFIG ───────────────────────────────────────
|
||
# Three-phase backoff for "Fecha posterior" responses.
|
||
# Each slot retries independently until CERTIFIED taken or success:
|
||
# Phase 1 (aggressive): 43ms × 1.5^n for first 6 retries — midnight fast
|
||
# Phase 2 (gradual): 330ms × 1.15^n, capped 500ms — less spammy
|
||
# Phase 3 (extended): 2s × 1.2^n, capped 15s — catches post-midnight cancellations
|
||
# Only stops retrying when:
|
||
# - Booking succeeds ("Cita insertada")
|
||
# - Slot certified taken ("Hora no permitida") → give up THIS slot
|
||
# - Duplicate detected ("already exists" / "DNI" / "existe") → STOP entirely
|
||
# - Time budget exhausted (120s) → cannot certify, move to next slot
|
||
# "Fecha posterior" alone is NEVER a give-up reason — server date hasn't rolled.
|
||
# "Hora no permitida" is the ONLY certification that a slot is taken.
|
||
SKEW_RETRY_BASE = 0.043 # 43ms: server lift (~40ms) + 3ms buffer
|
||
SKEW_AGGRESSIVE_N = 6 # first 6 retries at aggressive growth
|
||
SKEW_AGGRESSIVE_GROWTH = 1.5 # 43, 65, 98, 147, 220, 330ms
|
||
SKEW_GRADUAL_GROWTH = 1.15 # Phase 2: 380, 437, 500ms (slower = less bot-spammy)
|
||
SKEW_MAX_DELAY = 0.500 # Phase 1+2 cap: 500ms
|
||
SKEW_PHASE3_START = 2.5 # start Phase 3 after 2.5s
|
||
SKEW_EXTENDED_BASE = 2.0 # 2s base for Phase 3
|
||
SKEW_EXTENDED_GROWTH = 1.2 # 1.2x growth (gentle): 2, 2.4, 2.88, 3.46, ...
|
||
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)
|
||
|
||
# ── DUPLICATE DETECTION ──────────────────────────────────────
|
||
# Strings that indicate the server already has a cita for this NIE + servicio/cola.
|
||
# When ANY of these substrings appear in the result, STOP immediately — do NOT
|
||
# retry, do NOT try other slots. This prevents accidental duplicate bookings.
|
||
DUPLICATE_PATTERNS = (
|
||
"ya existente",
|
||
"DNI",
|
||
"existe",
|
||
"Usted ya tiene cita previa", # ← discovered: server returns this when NIE already has a cita for the servicio/cola
|
||
"cita previa en la gestion", # sub-string match for the above
|
||
)
|
||
|
||
def _is_duplicate(result):
|
||
"""Check if the result string indicates an existing cita for this NIE."""
|
||
rl = result.lower()
|
||
return any(p.lower() in rl for p in DUPLICATE_PATTERNS)
|
||
|
||
# ── CITA TYPES CATALOG ─────────────────────────────────────────
|
||
# Static catalog from live API query (ScServicioFiltrado1 + ScColaVo).
|
||
# Maps (servicio, cola) → metadata dict.
|
||
# motivo_requerido: True when cola.Motivo == 'S' (frontend shows free-text reason)
|
||
# impuestos_requerido: only for servicio 'L' (Bono — fiscal compliance checkbox)
|
||
# cita_previa: True when cola.CitaPrevia == 'S' (bookable online)
|
||
# Catalog auto-refreshable via: --refresh-citas (fetch live from API)
|
||
CITA_TYPES = {
|
||
# ── Servicio S (SAC / SAIC) — 10 gestiones ──
|
||
('S', 'A'): {'nombre': 'Labradores MAÑANA - Altas y modificaciones de Padrón',
|
||
'direccion': 'C/LABRADORES 14', 'horario': 'MAÑANA',
|
||
'motivo_requerido': True, 'max_cita': 21,
|
||
'activa': True, 'cita_previa': True},
|
||
('S', 'B'): {'nombre': 'Labradores MAÑANA - Trámites Municipales',
|
||
'direccion': 'C/LABRADORES 14', 'horario': 'MAÑANA',
|
||
'motivo_requerido': True, 'max_cita': 21,
|
||
'activa': True, 'cita_previa': True},
|
||
('S', 'D'): {'nombre': 'Labradores MAÑANA - Tarjeta Ciudadana',
|
||
'direccion': 'C/LABRADORES 14', 'horario': 'MAÑANA',
|
||
'motivo_requerido': True, 'max_cita': 15,
|
||
'activa': True, 'cita_previa': False},
|
||
('S', 'E'): {'nombre': 'Labradores TARDE - Altas y modificaciones de Padrón',
|
||
'direccion': 'C/LABRADORES 14', 'horario': 'TARDE',
|
||
'motivo_requerido': True, 'max_cita': 21,
|
||
'activa': True, 'cita_previa': True},
|
||
('S', 'F'): {'nombre': 'Labradores TARDE - Trámites Municipales',
|
||
'direccion': 'C/LABRADORES 14', 'horario': 'TARDE',
|
||
'motivo_requerido': True, 'max_cita': 21,
|
||
'activa': True, 'cita_previa': True},
|
||
('S', 'G'): {'nombre': 'Portugal MAÑANA - Altas y modificaciones de Padrón',
|
||
'direccion': 'C/PORTUGAL 17', 'horario': 'MAÑANA',
|
||
'motivo_requerido': True, 'max_cita': 15,
|
||
'activa': True, 'cita_previa': True},
|
||
('S', 'H'): {'nombre': 'Portugal MAÑANA - Trámites Municipales',
|
||
'direccion': 'C/PORTUGAL 17', 'horario': 'MAÑANA',
|
||
'motivo_requerido': True, 'max_cita': 15,
|
||
'activa': True, 'cita_previa': True},
|
||
('S', 'I'): {'nombre': 'Portugal TARDE - Altas y modificaciones de Padrón',
|
||
'direccion': 'C/PORTUGAL 17', 'horario': 'TARDE',
|
||
'motivo_requerido': True, 'max_cita': 15,
|
||
'activa': True, 'cita_previa': True},
|
||
('S', 'J'): {'nombre': 'Portugal TARDE - Trámites Municipales',
|
||
'direccion': 'C/PORTUGAL 17', 'horario': 'TARDE',
|
||
'motivo_requerido': True, 'max_cita': 15,
|
||
'activa': True, 'cita_previa': True},
|
||
('S', 'L'): {'nombre': 'Pino Santo MAÑANA - Trámites Municipales',
|
||
'direccion': 'C/PINO SANTO 1', 'horario': 'MAÑANA',
|
||
'motivo_requerido': True, 'max_cita': 15,
|
||
'activa': True, 'cita_previa': True},
|
||
('S', 'M'): {'nombre': 'Pino Santo TARDE - Trámites Municipales',
|
||
'direccion': 'C/PINO SANTO 1', 'horario': 'TARDE',
|
||
'motivo_requerido': True, 'max_cita': 15,
|
||
'activa': True, 'cita_previa': True},
|
||
|
||
# ── Servicio I (Inmigración) — 10 gestiones (active + cita_previa) ──
|
||
('I', 'C'): {'nombre': 'I- VALORACIÓN ARRAIGO (ENTREVISTA)',
|
||
'direccion': 'SARGENTO VAILLO, 30', 'horario': '',
|
||
'motivo_requerido': False, 'max_cita': 30,
|
||
'activa': True, 'cita_previa': True},
|
||
('I', 'D'): {'nombre': 'II-VALORACIÓN ARRAIGO (ACTUACIONES)',
|
||
'direccion': 'SARGENTO VAILLO, 30', 'horario': '',
|
||
'motivo_requerido': False, 'max_cita': 30,
|
||
'activa': True, 'cita_previa': True},
|
||
('I', 'E'): {'nombre': 'INFORMACIÓN, TRÁMITES Y DOCUMENTOS',
|
||
'direccion': 'SARGENTO VAILLO, 30', 'horario': '',
|
||
'motivo_requerido': False, 'max_cita': 30,
|
||
'activa': True, 'cita_previa': True},
|
||
('I', 'G'): {'nombre': 'ARRAIGO SOCIOFORMATIVO',
|
||
'direccion': 'SARGENTO VAILLO, 30', 'horario': '',
|
||
'motivo_requerido': False, 'max_cita': 30,
|
||
'activa': True, 'cita_previa': True},
|
||
('I', 'H'): {'nombre': 'I- VALORACIÓN ARRAIGO SOCIAL (ENTREVISTA)',
|
||
'direccion': 'PZA.ARGEL, 5-2º', 'horario': '',
|
||
'motivo_requerido': False, 'max_cita': 30,
|
||
'activa': True, 'cita_previa': True},
|
||
('I', 'I'): {'nombre': 'II-VALORACIÓN ARRAIGO SOCIAL (ACTUACIONES)',
|
||
'direccion': 'PZA.ARGEL, 5-2º', 'horario': '',
|
||
'motivo_requerido': False, 'max_cita': 30,
|
||
'activa': True, 'cita_previa': True},
|
||
('I', 'J'): {'nombre': 'INFORMACIÓN TRÁMITES Y DOCUMENTOS (ARRAIGO)',
|
||
'direccion': 'PZA.ARGEL, 5-2º', 'horario': '',
|
||
'motivo_requerido': False, 'max_cita': 30,
|
||
'activa': True, 'cita_previa': True},
|
||
('I', 'L'): {'nombre': 'ARRAIGO SOCIOFORMATIVO',
|
||
'direccion': 'PZA.ARGEL, 5-2º', 'horario': '',
|
||
'motivo_requerido': False, 'max_cita': 30,
|
||
'activa': True, 'cita_previa': True},
|
||
('I', 'U'): {'nombre': 'ESCOLARIZACIÓN Y RETORNO',
|
||
'direccion': 'PZA.ARGEL, 5-2º', 'horario': '',
|
||
'motivo_requerido': False, 'max_cita': 30,
|
||
'activa': True, 'cita_previa': True},
|
||
('I', 'V'): {'nombre': 'ESCOLARIZACIÓN Y RETORNO',
|
||
'direccion': 'SARGENTO VAILLO, 30', 'horario': '',
|
||
'motivo_requerido': False, 'max_cita': 30,
|
||
'activa': True, 'cita_previa': True},
|
||
|
||
# ── Servicio T (Trámites) — 4 gestiones ──
|
||
('T', 'A'): {'nombre': 'APLAZAMIENTOS Y FRACCIONAMIENTOS',
|
||
'motivo_requerido': True, 'max_cita': 15,
|
||
'activa': True, 'cita_previa': True},
|
||
('T', 'B'): {'nombre': 'ALTA DE TERCEROS',
|
||
'motivo_requerido': True, 'max_cita': 15,
|
||
'activa': True, 'cita_previa': True},
|
||
('T', 'C'): {'nombre': 'AVALES Y FIANZAS',
|
||
'motivo_requerido': True, 'max_cita': 15,
|
||
'activa': True, 'cita_previa': True},
|
||
('T', 'D'): {'nombre': 'CERTIFICADOS DE NO DÉBITOS',
|
||
'motivo_requerido': False, 'max_cita': 15,
|
||
'activa': True, 'cita_previa': True},
|
||
|
||
# ── Servicio F (Ayuntamiento) — 3 activas ──
|
||
('F', 'A'): {'nombre': 'SUBVENCIONES Y CONTRATACIÓN',
|
||
'motivo_requerido': True, 'max_cita': 15,
|
||
'activa': True, 'cita_previa': True},
|
||
('F', 'C'): {'nombre': 'CASA DE SAN NICOLÁS',
|
||
'motivo_requerido': False, 'max_cita': 0,
|
||
'activa': True, 'cita_previa': True},
|
||
('F', 'D'): {'nombre': 'CAMPAMENTO CARTEROS REALES',
|
||
'motivo_requerido': False, 'max_cita': 0,
|
||
'activa': True, 'cita_previa': True},
|
||
|
||
# ── Servicio P (Distritos) — 5 activas ──
|
||
('P', 'A'): {'nombre': 'DISTRITO 1 (BARÓN DE FINESTRAT)',
|
||
'telefono_oficina': '965212072', 'motivo_requerido': True,
|
||
'max_cita': 7, 'activa': True, 'cita_previa': True},
|
||
('P', 'B'): {'nombre': 'DISTRITO 2 (PLAZA DE ARGEL)',
|
||
'telefono_oficina': '965128400', 'motivo_requerido': True,
|
||
'max_cita': 7, 'activa': True, 'cita_previa': True},
|
||
('P', 'C'): {'nombre': 'DISTRITO 3 MAÑANA (ALC. LORENZO CARBONELL)',
|
||
'telefono_oficina': '965103947', 'motivo_requerido': True,
|
||
'max_cita': 7, 'activa': True, 'cita_previa': True},
|
||
('P', 'D'): {'nombre': 'DISTRITO 4 MAÑANA (AVDA COSTA BLANCA)',
|
||
'telefono_oficina': '965264057', 'motivo_requerido': True,
|
||
'max_cita': 7, 'activa': True, 'cita_previa': True},
|
||
('P', 'F'): {'nombre': 'DISTRITO 3 TARDE (ALC. LORENZO CARBONELL)',
|
||
'telefono_oficina': '965103947', 'motivo_requerido': True,
|
||
'max_cita': 7, 'activa': True, 'cita_previa': True},
|
||
|
||
# ── Servicio A (Visitas / Eventos) — 1 activa ──
|
||
('A', 'A'): {'nombre': 'VISITA COLEGIOS',
|
||
'motivo_requerido': True, 'max_cita': 270,
|
||
'activa': True, 'cita_previa': True},
|
||
|
||
# ── Servicio B (Bicicletas / Patinetes) — 1 activa ──
|
||
('B', 'A'): {'nombre': 'BICIESCUELA / TALLER PATINETES ELÉCTRICOS',
|
||
'motivo_requerido': True, 'max_cita': 257,
|
||
'activa': True, 'cita_previa': True},
|
||
|
||
# ── Servicio L (Bonos) — 3 gestiones, impuestos REQUERIDO ──
|
||
('L', 'A'): {'nombre': 'BONO COMERCIO',
|
||
'motivo_requerido': False, 'max_cita': 0,
|
||
'activa': False, 'cita_previa': False,
|
||
'impuestos_requerido': True},
|
||
('L', 'B'): {'nombre': 'BONO GASTRONÓMICO',
|
||
'motivo_requerido': False, 'max_cita': 1,
|
||
'activa': False, 'cita_previa': False,
|
||
'impuestos_requerido': True},
|
||
('L', 'C'): {'nombre': 'BONO CULTURAL',
|
||
'motivo_requerido': False, 'max_cita': 0,
|
||
'activa': False, 'cita_previa': False,
|
||
'impuestos_requerido': True},
|
||
|
||
# ── Servicio U (Urbanismo) — 10 gestiones, 6 with cita_previa ──
|
||
('U', 'B'): {'nombre': 'B: INFORMACIÓN GENERAL NO TÉCNICA',
|
||
'motivo_requerido': True, 'max_cita': 10,
|
||
'activa': True, 'cita_previa': True},
|
||
('U', 'F'): {'nombre': 'F: ATENCIÓN TÉCNICA CONSERVACIÓN DE INMUEBLES',
|
||
'motivo_requerido': True, 'max_cita': 0,
|
||
'activa': True, 'cita_previa': True},
|
||
('U', 'G'): {'nombre': 'G: ATENCIÓN TÉCNICA OBRAS Y ACTIVIDADES',
|
||
'motivo_requerido': True, 'max_cita': 15,
|
||
'activa': True, 'cita_previa': True},
|
||
('U', 'H'): {'nombre': 'H: ATENCIÓN TÉCNICA OBRAS Y ACTIVIDADES',
|
||
'motivo_requerido': True, 'max_cita': 15,
|
||
'activa': True, 'cita_previa': True},
|
||
('U', 'I'): {'nombre': 'I: ATENCIÓN TÉCNICA OBRAS Y ACTIVIDADES',
|
||
'motivo_requerido': True, 'max_cita': 15,
|
||
'activa': True, 'cita_previa': True},
|
||
('U', 'J'): {'nombre': 'J: ATENCIÓN TÉCNICA OBRAS Y ACTIVIDADES',
|
||
'motivo_requerido': True, 'max_cita': 15,
|
||
'activa': True, 'cita_previa': True},
|
||
}
|
||
|
||
# Document types from ScTipoDocumentoVo1 (API: tipo → descripción)
|
||
DOC_TYPES = {
|
||
'1': 'DNI',
|
||
'2': 'NIE',
|
||
'3': 'PASS',
|
||
'4': 'CIF',
|
||
}
|
||
|
||
# Fields always required for any booking
|
||
REQUIRED_FIELDS = ['nif', 'tipo', 'nombre', 'ape1', 'fecha', 'tel', 'email']
|
||
|
||
# ── 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 (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 < 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:
|
||
grad_base = min(SKEW_RETRY_BASE * (SKEW_AGGRESSIVE_GROWTH ** (SKEW_AGGRESSIVE_N - 1)), SKEW_MAX_DELAY)
|
||
return min(grad_base * (SKEW_GRADUAL_GROWTH ** (n - SKEW_AGGRESSIVE_N)), SKEW_MAX_DELAY)
|
||
else:
|
||
ext_n = n - SKEW_AGGRESSIVE_N - 6
|
||
return min(SKEW_EXTENDED_BASE * (SKEW_EXTENDED_GROWTH ** ext_n), SKEW_EXTENDED_CAP)
|
||
|
||
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, level="INFO"):
|
||
"""Print a timestamped, severity-leveled message with flush=True."""
|
||
ts = datetime.now().strftime('%H:%M:%S.%f')[:-3]
|
||
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, 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,
|
||
"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 for server load estimation.
|
||
HOT PATH — only appends to history (O(1)). Use _compute_load() to get the
|
||
load descriptor only when logging is needed."""
|
||
_rtt_history.append(response_ms)
|
||
|
||
def _compute_load():
|
||
"""Compute server load descriptor from tracked RTTs.
|
||
Only call when you need to log the load — NOT on every request."""
|
||
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."""
|
||
return _compute_load()
|
||
|
||
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."""
|
||
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
|
||
_track_rtt(elapsed) # HOT PATH: O(1) append only — no computation
|
||
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...", 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", 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(elapsed) # O(1) append — load computed lazily on log
|
||
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)
|
||
|
||
# ── CLI ARGUMENT PARSING ─────────────────────────────────────
|
||
# Defined here so tests can access them. Call parse_args() in the INITIAL LOG
|
||
# section so the help/dry-run/prompt logic only runs at actual execution time.
|
||
|
||
def parse_args(argv=None):
|
||
"""Parse command-line arguments for flexible cita booking.
|
||
|
||
Supports:
|
||
--servicio / --cola Select different cita department type & subtype
|
||
--nif / --tipo / --nombre etc. Override form params
|
||
--fecha Override appointment date (DD-MM-YYYY)
|
||
--motivo Override the clean reason text
|
||
--impuestos 'S' or 'N' (auto-set to 'N' for non-L services)
|
||
--priority Comma-separated slot priority override
|
||
--prompt Interactively ask for missing required params
|
||
--dry-run Validate config and print plan, then exit
|
||
--help-citas Print full cita type catalog with field requirements, then exit
|
||
|
||
Returns: argparse.Namespace with all fields.
|
||
May call sys.exit() for --help-citas or argparse --help.
|
||
"""
|
||
parser = argparse.ArgumentParser(
|
||
prog="book_final.py",
|
||
description="Cita previa booking bot for Alicante (webservices.alicante.es)",
|
||
formatter_class=argparse.RawDescriptionHelpFormatter,
|
||
epilog="""\
|
||
Examples:
|
||
# Default (service S / cola I — Padrón, Portugal Tardes)
|
||
./book_final.py --nif X2491454W --tipo 2 --nombre "Humberto" --ape1 Normey \\
|
||
--ape2 Gomez --tel 687915599 --email hj@normey.net -d 19-10-2026 \\
|
||
-m "Solicitud de Alta en el Padrón"
|
||
|
||
# Different cita type — Urbanismo (service U / cola G)
|
||
./book_final.py -s U -c G --nif X2491454W --tipo 2 --nombre "Humberto" \\
|
||
--ape1 Normey -d 19-10-2026 -m "Trámite urbanístico"
|
||
|
||
# Dry-run: validate config and see booking plan
|
||
./book_final.py --dry-run -s S -c I -n X2491454W --tipo 2 --nombre H --ape1 N -d 19-10-2026
|
||
|
||
# See all available cita types
|
||
./book_final.py --help-citas
|
||
""",
|
||
)
|
||
|
||
# ── Cita type selection ──────────────────────────────────
|
||
parser.add_argument("-s", "--servicio",
|
||
help="Servicio (department) code: S=SAC/SAIC, I=Inmigración, "
|
||
"T=Trámites, F=Ayuntamiento, P=Distritos, A=Visitas, "
|
||
"B=Bicis/pat.Eléc., L=Bonos, U=Urbanismo. Default: S")
|
||
|
||
parser.add_argument("-c", "--cola",
|
||
help="Cola (subtype) code for the selected servicio. "
|
||
"Required if --servicio is given. "
|
||
"See --help-citas for valid combos.")
|
||
|
||
# ── Booking date ─────────────────────────────────────────
|
||
parser.add_argument("-d", "--fecha",
|
||
help="Appointment date in DD-MM-YYYY format. "
|
||
"Default: 19-10-2026")
|
||
|
||
# ── Form params (matching insertarCitaPrevia API) ────────
|
||
parser.add_argument("-n", "--nif",
|
||
help="Document number (NIE/NIF/PASS/CIF)")
|
||
parser.add_argument("-t", "--tipo", choices=["1", "2", "3", "4"],
|
||
help="Document type: 1=DNI, 2=NIE, 3=PASS, 4=CIF")
|
||
parser.add_argument("--nombre",
|
||
help="First name(s)")
|
||
parser.add_argument("--ape1",
|
||
help="Primer apellido / Razón Social (REQUIRED)")
|
||
parser.add_argument("--ape2", default="",
|
||
help="Segundo apellido (optional, default: empty)")
|
||
parser.add_argument("--tel",
|
||
help="Teléfono de contacto (REQUIRED)")
|
||
parser.add_argument("-e", "--email",
|
||
help="Correo electrónico (REQUIRED)")
|
||
parser.add_argument("-m", "--motivo",
|
||
help="Motivo / reason text. REQUIRED when servicio/cola "
|
||
"has motivo='S'")
|
||
parser.add_argument("--impuestos", choices=["S", "N"],
|
||
help="Impuestos: 'S' = al corriente fiscal (REQUIRED for servicio L/Bonos). "
|
||
"Auto-set to 'N' for other services.")
|
||
parser.add_argument("--ip", default="0.0.0.0",
|
||
help="IP address for the booking (default: 0.0.0.0)")
|
||
|
||
# ── Priority slots override ────────────────────────────────
|
||
parser.add_argument("-r", "--priority",
|
||
help="Comma-separated slot priority (e.g. '15:15,15:30,16:00'). "
|
||
"Default: contrarian order for service S.")
|
||
|
||
# ── Mode flags ───────────────────────────────────────────
|
||
parser.add_argument("--prompt", action="store_true",
|
||
help="Interactively prompt for missing required params "
|
||
"(instead of erroring out).")
|
||
parser.add_argument("--dry-run", action="store_true",
|
||
help="Validate config and print booking plan, then exit "
|
||
"(no midnight wait, no booking).")
|
||
parser.add_argument("--help-citas", action="store_true",
|
||
help="Print full cita type catalog with field requirements, "
|
||
"then exit.")
|
||
|
||
return parser.parse_args(argv)
|
||
|
||
|
||
def print_cita_types():
|
||
"""Print the full CITA_TYPES catalog organized by servicio, with field requirements."""
|
||
# Group by servicio
|
||
servicios = {}
|
||
for (svc, cola), meta in sorted(CITA_TYPES.items()):
|
||
servicios.setdefault(svc, []).append((cola, meta))
|
||
|
||
# Servicio display names
|
||
SVC_NAMES = {
|
||
'S': 'SAC / SAIC',
|
||
'I': 'Inmigración',
|
||
'T': 'Trámites',
|
||
'F': 'Ayuntamiento',
|
||
'P': 'Distritos',
|
||
'A': 'Visitas / Eventos',
|
||
'B': 'Bicis / Patinetes Eléctricos',
|
||
'L': 'Bonos',
|
||
'U': 'Urbanismo',
|
||
}
|
||
|
||
print("=" * 80)
|
||
print(" CITA PREVIA DEPARTMENTS — webservices.alicante.es")
|
||
print("=" * 80)
|
||
|
||
total = sum(1 for v in CITA_TYPES.values() if v.get('cita_previa') and v.get('activa'))
|
||
inactive = sum(1 for v in CITA_TYPES.values() if not v.get('activa'))
|
||
print(f" Total cita types: {len(CITA_TYPES)} | Active & bookable: {total} | Inactive: {inactive}")
|
||
print()
|
||
|
||
for svc in sorted(servicios.keys()):
|
||
svc_name = SVC_NAMES.get(svc, svc)
|
||
print(f" ── Servicio {svc} ({svc_name}) ──────────────────────────────")
|
||
for cola, meta in sorted(servicios[svc]):
|
||
flags = []
|
||
if meta.get('motivo_requerido'):
|
||
flags.append("motivo=✓")
|
||
if meta.get('impuestos_requerido'):
|
||
flags.append("impuestos=✓")
|
||
if not meta.get('activa'):
|
||
flags.append("INACTIVA")
|
||
if not meta.get('cita_previa'):
|
||
flags.append("sin_cita_previa")
|
||
|
||
addr = meta.get('direccion', '')
|
||
horario = meta.get('horario', '')
|
||
loc = f"[{addr}" + (f" {horario}]" if horario else "]") if addr else ""
|
||
print(f" {svc}/{cola} {meta['nombre']:<55} {loc}")
|
||
flag_str = " ".join(flags) if flags else "—"
|
||
print(f" max_días={meta['max_cita']:<4} motiv:{meta.get('motivo_requerido','—')} imp:{'S' if meta.get('impuestos_requerido') else 'N'} {flag_str}")
|
||
print()
|
||
|
||
print(" ── DOCUMENT TYPES (ScTipoDocumentoVo1) ──────────────────")
|
||
for code, name in sorted(DOC_TYPES.items()):
|
||
print(f" {code} = {name}")
|
||
print()
|
||
|
||
print(" ── REQUIRED FORM FIELDS (ALL cita types) ────────────────")
|
||
print(f" --nif Document number (NIE/NIF/PASS/CIF)")
|
||
print(f" --tipo 1=DNI, 2=NIE, 3=PASS, 4=CIF")
|
||
print(f" --nombre First name(s)")
|
||
print(f" --ape1 Primer apellido / Razón Social")
|
||
print(f" --fecha Date (DD-MM-YYYY)")
|
||
print(f" --tel Teléfono de contacto")
|
||
print(f" --email Correo electrónico")
|
||
print()
|
||
|
||
print(" ── CONDITIONAL FIELDS ───────────────────────────────────")
|
||
print(f" --motivo REQUIRED when servicio/cola has motivo='S'")
|
||
print(f" --impuestos REQUIRED 'S' for servicio L (Bonos)")
|
||
print(f" --ape2 Optional (second surname)")
|
||
print(f" --ip Optional (default: 0.0.0.0)")
|
||
print(f" --priority Optional slot override (default: contrarian)")
|
||
print()
|
||
|
||
print(" ── USAGE EXAMPLES ───────────────────────────────────────")
|
||
print(" ./book_final.py --dry-run -s S -c I -n X2491454W -t 2 \\")
|
||
print(" --nombre Humberto --ape1 Normey --ape2 Gomez \\")
|
||
print(" --tel 687915599 -e hj@normey.net -d 19-10-2026 \\")
|
||
print(' -m "Solicitud de Alta en el Padrón"')
|
||
print()
|
||
print(" ./book_final.py -s U -c G --help-citas # show Urbanismo types")
|
||
print()
|
||
print("=" * 80)
|
||
|
||
|
||
def validate_config(args):
|
||
"""Validate CLI args against CITA_TYPES. Returns (ok: bool, missing: list, errors: list).
|
||
|
||
Checks:
|
||
1. If --servicio given, --cola must also be given
|
||
2. (servicio, cola) must exist in CITA_TYPES
|
||
3. Service must be active + bookable (cita_previa == True)
|
||
4. All REQUIRED_FIELDS must be provided
|
||
5. --motivo required when cita type has motivo_requerido=True
|
||
6. --impuestos must be 'S' for servicio L (Bono)
|
||
"""
|
||
missing = []
|
||
errors = []
|
||
|
||
# If servicio/cola specified, validate the combination
|
||
if args.servicio is not None:
|
||
if args.cola is None:
|
||
errors.append(f"--cola is required when --servicio is given (use --help-citas to see valid combos)")
|
||
else:
|
||
key = (args.servicio.upper(), args.cola.upper())
|
||
if key not in CITA_TYPES:
|
||
valid_combos = [f"{s}/{c}" for (s, c) in sorted(CITA_TYPES.keys())]
|
||
errors.append(f"Invalid servicio/cola: ({args.servicio}, {args.cola}). "
|
||
f"Valid combos: {', '.join(valid_combos)}")
|
||
else:
|
||
meta = CITA_TYPES[key]
|
||
if not meta.get('activa'):
|
||
errors.append(f"servicio {args.servicio}/cola {args.cola} ({meta['nombre']}) — INACTIVA")
|
||
if not meta.get('cita_previa'):
|
||
errors.append(f"servicio {args.servicio}/cola {args.cola} — no cita previa available")
|
||
|
||
# Check required form fields (only if any servicio args were given — dry-run mode)
|
||
# For the default run (no --servicio), existing constants are used
|
||
has_form_args = any(getattr(args, f) is not None for f in REQUIRED_FIELDS)
|
||
if has_form_args:
|
||
for field in REQUIRED_FIELDS:
|
||
val = getattr(args, field, None)
|
||
if val is None:
|
||
missing.append(f"--{field}")
|
||
elif args.dry_run or args.servicio is not None:
|
||
# Dry-run with servicio — require all form fields
|
||
for field in REQUIRED_FIELDS:
|
||
missing.append(f"--{field}")
|
||
|
||
# Check motivo for cita types that require it
|
||
if args.servicio and args.cola:
|
||
key = (args.servicio.upper(), args.cola.upper())
|
||
if key in CITA_TYPES:
|
||
meta = CITA_TYPES[key]
|
||
if meta.get('motivo_requerido') and not args.motivo:
|
||
missing.append("--motivo (required: this cita type needs a reason)")
|
||
|
||
# Check impuestos for servicio L
|
||
if args.servicio and args.servicio.upper() == 'L':
|
||
if args.impuestos != 'S':
|
||
errors.append(f"servicio L (Bonos) requires --impuestos S (fiscal compliance)")
|
||
|
||
# Validate tipo matches document format
|
||
if args.tipo and args.nif:
|
||
# Quick format check
|
||
if args.tipo == '1': # DNI
|
||
pass # 8 digits + letter
|
||
elif args.tipo == '2': # NIE
|
||
if not args.nif[0].upper() in ('X', 'Y', 'Z'):
|
||
errors.append(f"NIE (tipo=2) must start with X/Y/Z. Got: {args.nif}")
|
||
elif args.tipo == '3': # PASS
|
||
pass # any
|
||
elif args.tipo == '4': # CIF
|
||
if not args.nif[0].upper() in ('A', 'B', 'C', 'D', 'E', 'F', 'G', 'H', 'J', 'N', 'P', 'Q', 'R', 'S', 'U', 'V'):
|
||
errors.append(f"CIF (tipo=4) must start with company letter. Got: {args.nif}")
|
||
|
||
# Validate fecha format
|
||
if args.fecha:
|
||
try:
|
||
datetime.strptime(args.fecha, "%d-%m-%Y")
|
||
except ValueError:
|
||
errors.append(f"--fecha format must be DD-MM-YYYY. Got: {args.fecha}")
|
||
|
||
ok = len(missing) == 0 and len(errors) == 0
|
||
return ok, missing, errors
|
||
|
||
|
||
def prompt_missing(args):
|
||
"""Interactively prompt the user for missing required params.
|
||
Modifies `args` in place."""
|
||
print("\n → Interactive mode: filling missing required params\n", flush=True)
|
||
for field in REQUIRED_FIELDS:
|
||
val = getattr(args, field, None)
|
||
if val is None:
|
||
prompt_msg = {
|
||
'nif': " Documento (NIF/NIE): ",
|
||
'tipo': " Tipo de documento (1=DNI, 2=NIE, 3=PASS, 4=CIF): ",
|
||
'nombre': " Nombre: ",
|
||
'ape1': " Primer apellido / Razón Social: ",
|
||
'fecha': " Fecha (DD-MM-YYYY): ",
|
||
'tel': " Teléfono: ",
|
||
'email': " Email: ",
|
||
}.get(field, f" {field}: ")
|
||
val = input(prompt_msg).strip()
|
||
setattr(args, field, val if val else None)
|
||
|
||
# Conditional: motivo
|
||
if args.servicio and args.cola and not args.motivo:
|
||
key = (args.servicio.upper(), args.cola.upper())
|
||
if key in CITA_TYPES and CITA_TYPES[key].get('motivo_requerido'):
|
||
val = input(" Motivo / razón: ").strip()
|
||
if val:
|
||
args.motivo = val
|
||
|
||
# Conditional: impuestos for servicio L
|
||
if args.servicio and args.servicio.upper() == 'L' and args.impuestos != 'S':
|
||
val = input(" Impuestos (S=al corriente): ").strip().upper()
|
||
if val:
|
||
args.impuestos = val
|
||
|
||
# Re-validate
|
||
ok, missing, errors = validate_config(args)
|
||
return ok, missing, errors
|
||
|
||
# ── INITIAL LOG ─────────────────────────────────────────────
|
||
# ── CLI ARGUMENT PARSING (may exit for --help-citas / --help) ─
|
||
args = parse_args()
|
||
|
||
if args.help_citas:
|
||
print_cita_types()
|
||
sys.exit(0)
|
||
|
||
# Override defaults with CLI args (only if provided)
|
||
if args.servicio: SERVICIO = args.servicio.upper()
|
||
if args.cola: COLA = args.cola.upper()
|
||
if args.fecha: FECHA = args.fecha
|
||
if args.nif: DOC = args.nif.upper()
|
||
if args.tipo: TIPO = args.tipo
|
||
if args.nombre: NOMBRE = args.nombre
|
||
if args.ape1: APE1 = args.ape1
|
||
if args.ape2: APE2 = args.ape2
|
||
if args.tel: TEL = args.tel
|
||
if args.email: EMAIL = args.email
|
||
if args.motivo: COMENTARIO = args.motivo
|
||
if args.ip: IP = args.ip
|
||
if args.priority: PRIORITY = [h.strip() for h in args.priority.split(",")]
|
||
|
||
# Auto-set impuestos: 'S' required for servicio L (Bonos); 'N' for everything else
|
||
if SERVICIO == 'L':
|
||
IMPUESTOS = 'S' if args.impuestos is None else args.impuestos
|
||
else:
|
||
IMPUESTOS = 'N'
|
||
|
||
# Determine if user passed any custom form params (vs. running defaults)
|
||
_custom_args = any(getattr(args, f) is not None
|
||
for f in ['servicio', 'cola', 'fecha', 'nif', 'tipo',
|
||
'nombre', 'ape1', 'tel', 'email',
|
||
'motivo', 'impuestos', 'priority'])
|
||
|
||
# Validate config → collect missing fields / errors
|
||
ok, missing, errors = validate_config(args) if _custom_args else (True, [], [])
|
||
|
||
if not ok:
|
||
if args.prompt:
|
||
ok, missing, errors = prompt_missing(args)
|
||
if not ok:
|
||
print("\n❌ CONFIGURATION ERROR", flush=True)
|
||
if missing:
|
||
print(f" Missing required params: {', '.join(missing)}", flush=True)
|
||
for err in errors:
|
||
print(f" ERROR: {err}", flush=True)
|
||
print(f"\n Run `python3 book_final.py --help-citas` for all cita types & required fields.", flush=True)
|
||
print(f" Add `--prompt` for interactive mode.", flush=True)
|
||
sys.exit(1)
|
||
|
||
# Apply params that prompt_missing may have filled in
|
||
if args.prompt and ok:
|
||
if args.nif: DOC = args.nif.upper()
|
||
if args.tipo: TIPO = args.tipo
|
||
if args.nombre: NOMBRE = args.nombre
|
||
if args.ape1: APE1 = args.ape1
|
||
if args.fecha: FECHA = args.fecha
|
||
if args.tel: TEL = args.tel
|
||
if args.email: EMAIL = args.email
|
||
if args.motivo: COMENTARIO = args.motivo
|
||
|
||
# ── DRY-RUN MODE ───────────────────────────────────────────
|
||
if args.dry_run:
|
||
_cita_meta = CITA_TYPES.get((SERVICIO, COLA), {})
|
||
now = datetime.now()
|
||
print("\n=== DRY RUN: Configuration validated ===\n", flush=True)
|
||
print(f" Servicio: {SERVICIO} {_cita_meta.get('nombre', '?')}", flush=True)
|
||
print(f" Cola: {COLA}", flush=True)
|
||
print(f" Oficina: {_cita_meta.get('direccion', 'N/A')}", flush=True)
|
||
print(f" Fecha: {FECHA} max_días={_cita_meta.get('max_cita', '?')}", flush=True)
|
||
print(f" Documento: {DOC} (tipo {TIPO} = {DOC_TYPES.get(TIPO, '?')})", flush=True)
|
||
print(f" Nombre: {NOMBRE} {APE1} {APE2}", flush=True)
|
||
print(f" Teléfono: {TEL}", flush=True)
|
||
print(f" Email: {EMAIL}", flush=True)
|
||
print(f" Motivo: {COMENTARIO}", flush=True)
|
||
print(f" Impuestos: {IMPUESTOS}", flush=True)
|
||
print(f" IP: {IP}", flush=True)
|
||
print(f" Priority: {PRIORITY}", flush=True)
|
||
print(f" Target TS: {datetime.fromtimestamp(TARGET_TS).strftime('%Y-%m-%d %H:%M:%S')} "
|
||
f"(in {(TARGET_TS - now.timestamp()):.0f}s)", flush=True)
|
||
print(f"\n ✅ Config valid — ready for booking.", flush=True)
|
||
sys.exit(0)
|
||
|
||
# ── STARTUP LOG ─────────────────────────────────────────────
|
||
log_file = "/tmp/booking_log.txt"
|
||
now = datetime.now()
|
||
_cita_meta = CITA_TYPES.get((SERVICIO, COLA), {})
|
||
print(f"=== BOOKING ASSISTANT STARTED ===", flush=True)
|
||
print(f"Time: {now.strftime('%Y-%m-%d %H:%M:%S.%f')[:-3]}", flush=True)
|
||
_target_str = datetime.fromtimestamp(TARGET_TS).strftime('%b %d %H:%M:%S')
|
||
print(f"Target: {_target_str} CEST (in {(TARGET_TS - now.timestamp()):.0f}s)", flush=True)
|
||
print(f"Service: {SERVICIO} ({_cita_meta.get('nombre', 'SAC/SAIC')}) Cola: {COLA}", 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)", level="INFO")
|
||
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)", 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:
|
||
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)", level="PHASE")
|
||
sleep_time = min(10, remaining)
|
||
else:
|
||
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) ***", level="PHASE")
|
||
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 ✓", level="INFO")
|
||
except Exception as 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)...", 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)...", level="WARN")
|
||
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) ...", 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)
|
||
|
||
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}", level="INFO")
|
||
except Exception as e:
|
||
log(f" Parse warning: {e}", level="WARN")
|
||
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) ...", 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) ***", 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...", 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
|
||
# inserted into the database, so no further booking action is needed; we just
|
||
# confirm and stop.
|
||
# Each slot is tried ONCE, with retries ONLY for:
|
||
# - "Fecha posterior" (server date not rolled): EACH slot gets its own independent
|
||
# 3-phase backoff (43ms×1.5^n first 6, 1.15x gradual to 500ms, 2s×1.2^n extended
|
||
# to 120s). WE ARE FIGHTING BOTS — every slot retries until certified taken.
|
||
# - "EXCEPTION:" (conn drop): force-reconnect + retry on SAME slot
|
||
# - "Hora no permitida": DEFINITIVE certification slot is taken → no retry
|
||
# Each slot's retry window is independent — the server date may roll during
|
||
# a later slot's retries even if earlier slots exhausted theirs.
|
||
# Only give up on a slot when: certified taken ("Hora no permitida") or
|
||
# time budget exhausted (can't certify further) or duplicate detected.
|
||
# Duplicate detection ("ya existente"/"DNI"/"existe") at ANY point → STOP immediately.
|
||
# This prevents duplicate bookings while tolerating clock/network issues.
|
||
|
||
attempts = [] # in-memory log of all attempts
|
||
booked_hora = None
|
||
booked_result = None
|
||
# Each slot tracks skew retry exhaustion independently — NO global skip flag.
|
||
# The server date may roll during another slot's retry window, so every
|
||
# slot must get its own full 120s three-phase backoff chance to hit midnight.
|
||
skew_retries_exhausted = False # diagnostics only (per-slot, not global skip)
|
||
duplicate_detected = False # STOP entire booking process if cita already exists
|
||
|
||
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()
|
||
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(ms) # raw RTT, rounding deferred to display
|
||
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
|
||
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: {_current_load()}", 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":
|
||
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 = _current_load() # _track_rtt already called in make_request — no double-track
|
||
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
|
||
# hasn't rolled yet. We must keep retrying until one of these:
|
||
# 1. Booking succeeds → "Cita insertada" (slot available, not taken)
|
||
# 2. Slot certified taken → "Hora no permitida" on retry
|
||
# 3. Duplicate detected → "ya existente" / "DNI" / "existe" / "Usted ya tiene cita previa"
|
||
# 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...", 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:
|
||
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:
|
||
# Phase 1 (attempts 1-6): 43ms × 1.5^n — aggressive, midnight-fast
|
||
# Phase 2 (attempts 7-12): 330ms × 1.15^n, capped 500ms — less spammy
|
||
# 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
|
||
time.sleep(delay)
|
||
skew_attempt += 1
|
||
|
||
t0b = time.time()
|
||
result2, _, _, ms2 = make_request(body, f"RETRY-SKEW{skew_attempt}")
|
||
slot_attempt_count += 1
|
||
slot_rtts.append(ms2) # raw RTT, rounding deferred to display
|
||
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
|
||
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 _is_duplicate(result2): # covers "ya existente", "DNI", "existe", "Usted ya tiene cita previa"
|
||
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
|
||
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
|
||
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 _is_duplicate(result): # covers "ya existente", "DNI", "existe", "Usted ya tiene cita previa"
|
||
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]}", 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", level="WARN")
|
||
t0r = time.time()
|
||
result_retry, _, _, ms2 = make_request(body, "RETRY-CONN")
|
||
slot_attempt_count += 1
|
||
slot_rtts.append(ms2) # raw RTT, rounding deferred to display
|
||
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
|
||
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 _is_duplicate(result_retry): # covers "ya existente", "DNI", "existe", "Usted ya tiene cita previa"
|
||
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", level="WARN")
|
||
elif result_retry == "Hora no permitida":
|
||
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", level="WARN")
|
||
else:
|
||
log(f" → Retry result: {result_retry[:100]}", level="WARN")
|
||
except Exception as e:
|
||
log(f" → Force-reconnect failed: {e}", level="ERROR")
|
||
|
||
else:
|
||
# Catch-all for any other server response — stop to avoid accidental double-booking
|
||
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": f"unexpected: {result[:50]}", "rtts": slot_rtts
|
||
})
|
||
log(f" → Unexpected server response: {result[:150]}", level="WARN")
|
||
log(f" Stopping to avoid accidental duplication. Add to DUPLICATE_PATTERNS if this is a known duplicate signal.", level="WARN")
|
||
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)...", 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)
|
||
|
||
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!", 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", level="WARN")
|
||
log(f" Slots still showing: {verify_slots}")
|
||
|
||
# ── BENCHMARK SUMMARY ───────────────────────────────────────
|
||
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.get('category', 'REQUEST'):>12}] {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.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}", 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.", level="ERROR")
|
||
log(f"New slots open daily for the next working day — try again tomorrow.", level="ERROR")
|
||
sys.exit(1)
|