fix: per-slot timing for unexpected/else branch + display dynamic target time
- 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)
This commit is contained in:
cc-ultrav-1
@@ -1261,6 +1261,13 @@ for hora in PRIORITY:
|
||||
|
||||
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
|
||||
|
||||
@@ -1,36 +1,25 @@
|
||||
Booking log — 2026-10-04 00:00:03
|
||||
NIE: X2491454W Cola: I Fecha: 19-10-2026
|
||||
Booking log — 2026-10-05 00:00:00
|
||||
NIE: X2491454W Cola: I Fecha: 20-10-2026
|
||||
Tracking: None (clean motivo)
|
||||
|
||||
=== ATTEMPTS ===
|
||||
{
|
||||
"hora": "15:15",
|
||||
"hora": "16:00",
|
||||
"status": 200,
|
||||
"response": "Cita insertada",
|
||||
"elapsed_ms": 3347.3,
|
||||
"timestamp": "00:00:03.307"
|
||||
"response": "Usted ya tiene cita previa en la gestion especificada",
|
||||
"elapsed_ms": 255.0,
|
||||
"timestamp": "00:00:00.215"
|
||||
}
|
||||
|
||||
=== TIMING ===
|
||||
23:59:57.389 [ 389.3ms] [ REQUEST] TLS_CONNECT: webservices.alicante.es:443
|
||||
23:59:59.718 [ 218.1ms] [ REQUEST] CHECK_SLOTS: 218ms — [{"hora":"14:30","dia":"L","horanumero":"1430"},{"hora":"14:45","dia":"L","horanumero":"1445"},{"hor
|
||||
00:00:03.307 [ 3347.3ms] [ REQUEST] BOOKING_ATTEMPT: 15:15 → 3347ms — Cita insertada
|
||||
00:00:03.474 [ 166.8ms] [ REQUEST] VERIFY: 167ms
|
||||
23:59:57.979 [ 979.0ms] [ REQUEST] TLS_CONNECT: webservices.alicante.es:443
|
||||
23:59:59.705 [ 205.5ms] [ REQUEST] CHECK_SLOTS: 205ms — [{"hora":"14:30","dia":"M","horanumero":"1430"},{"hora":"14:45","dia":"M","horanumero":"1445"},{"hor
|
||||
00:00:00.215 [ 255.1ms] [ REQUEST] BOOKING_ATTEMPT: 16:00 → 255ms — Usted ya tiene cita previa en la gestion especificada
|
||||
|
||||
=== PER-SLOT TIMING ===
|
||||
{
|
||||
"hora": "15:15",
|
||||
"total_ms": 3347.3,
|
||||
"attempts": 1,
|
||||
"avg_rtt_ms": 3347.3,
|
||||
"status": "booked",
|
||||
"rtts": [
|
||||
3347.2704887390137
|
||||
]
|
||||
}
|
||||
|
||||
=== SERVER LOAD ===
|
||||
RTT observations: 4
|
||||
Current load: HIGH (avg=1770ms σ=1578ms)
|
||||
Session avg RTT: 1769.8ms
|
||||
Load trend: STABLE (±1%)
|
||||
RTT observations: 2
|
||||
Current load: CALIBRATING
|
||||
Session avg RTT: 230.2ms
|
||||
Load trend: INSUFFICIENT_DATA
|
||||
|
||||
72
booking_run_2.log
Normal file
72
booking_run_2.log
Normal file
@@ -0,0 +1,72 @@
|
||||
=== BOOKING ASSISTANT STARTED ===
|
||||
Time: 2026-10-04 23:48:14.228
|
||||
Target: Oct 4 00:00:00 (in 706s)
|
||||
Service: S (Portugal TARDE - Altas y modificaciones de Padrón) Cola: I
|
||||
Documento: NIE X2491454W Nombre: Humberto Normey Gomez
|
||||
Fecha: 20-10-2026 Priority slots: ['16:00', '15:45', '15:30', '15:15', '16:15', '16:30', '15:00', '14:45', '14:30']
|
||||
[23:48:14.228] [INFO] Motivo: 'Solicitud de Alta en el Padrón' (clean, natural Spanish — no timestamp, no IDs)
|
||||
|
||||
[23:48:14.228] [PHASE] Starting Phase 1: Sleeping until 23:59:57 (T-3s to midnight)
|
||||
[23:48:14.228] [PHASE] Target midnight: 00:00:00
|
||||
[23:48:14.228] [PHASE] Heartbeat: 0h 11m 42s until pre-connect phase
|
||||
[23:49:14.228] [PHASE] Heartbeat: 0h 10m 42s until pre-connect phase
|
||||
[23:50:14.228] [PHASE] Heartbeat: 0h 9m 42s until pre-connect phase
|
||||
[23:51:14.228] [PHASE] Heartbeat: 0h 8m 42s until pre-connect phase
|
||||
[23:52:14.228] [PHASE] Heartbeat: 0h 7m 42s until pre-connect phase
|
||||
[23:53:14.228] [PHASE] Heartbeat: 0h 6m 42s until pre-connect phase
|
||||
[23:54:14.228] [PHASE] Heartbeat: 0h 5m 42s until pre-connect phase
|
||||
[23:55:14.228] [PHASE] Heartbeat: 0h 4m 42s until pre-connect phase
|
||||
[23:56:14.228] [PHASE] Heartbeat: 0h 3m 42s until pre-connect phase
|
||||
[23:57:14.229] [PHASE] Heartbeat: 0h 2m 42s until pre-connect phase
|
||||
[23:58:14.229] [PHASE] Heartbeat: 1m 42s until pre-connect phase (tight watch)
|
||||
[23:58:24.229] [PHASE] Heartbeat: 1m 32s until pre-connect phase (tight watch)
|
||||
[23:58:34.229] [PHASE] Heartbeat: 1m 22s until pre-connect phase (tight watch)
|
||||
[23:58:44.229] [PHASE] Heartbeat: 1m 12s until pre-connect phase (tight watch)
|
||||
[23:58:54.229] [PHASE] Heartbeat: 1m 2s until pre-connect phase (tight watch)
|
||||
[23:59:04.230] [PHASE] Heartbeat: 0m 52s until pre-connect phase (tight watch)
|
||||
[23:59:14.230] [PHASE] Heartbeat: 0m 42s until pre-connect phase (tight watch)
|
||||
[23:59:24.230] [PHASE] Heartbeat: 0m 32s until pre-connect phase (tight watch)
|
||||
[23:59:34.230] [PHASE] Heartbeat: 0m 22s until pre-connect phase (tight watch)
|
||||
[23:59:44.230] [PHASE] Heartbeat: 0m 12s until pre-connect phase (tight watch)
|
||||
[23:59:54.230] [PHASE] Heartbeat: 0m 2s until pre-connect phase (tight watch)
|
||||
[23:59:57.000] [PHASE]
|
||||
*** Phase 2: Pre-connecting TLS (3s before midnight) ***
|
||||
[23:59:57.979] [REQUEST] [979ms] TLS_CONNECT: webservices.alicante.es:443
|
||||
[23:59:57.979] [INFO] TLS connection established ✓
|
||||
[23:59:57.979] [PHASE] Phase 3: Busy-wait until T-500ms (pre-fire slot verification)...
|
||||
[23:59:59.500] [PHASE] Phase 3b: Verify available slots (getHorasCitas, pre-fired) ...
|
||||
[23:59:59.705] [REQUEST] [206ms] CHECK_SLOTS: 205ms — [{"hora":"14:30","dia":"M","horanumero":"1430"},{"hora":"14:45","dia":"M","horanumero":"1445"},{"hor
|
||||
[23:59:59.705] [INFO] 9 slots available: ['14:30', '14:45', '15:00', '15:15', '15:30', '15:45', '16:00', '16:15', '16:30']
|
||||
[23:59:59.705] [PHASE] Phase 3c: Busy-wait to T-40ms (pre-fire booking window) ...
|
||||
[23:59:59.960] [PHASE] *** PRE-FIRE WINDOW (T-40ms) ***
|
||||
[23:59:59.960] [PHASE] First booking request fires now → arrives @ server ~T+0ms
|
||||
[23:59:59.960] [PHASE] Pre-fire jitter: +0.0ms
|
||||
[23:59:59.960] [PHASE]
|
||||
Phase 4: Sequential booking attempts...
|
||||
[23:59:59.960] [PHASE] Priority order: ['16:00', '15:45', '15:30', '15:15', '16:15', '16:30', '15:00', '14:45', '14:30']
|
||||
[23:59:59.960] [PHASE] Only trying slots confirmed available: ['16:00', '15:45', '15:30', '15:15', '16:15', '16:30', '15:00', '14:45', '14:30']
|
||||
[00:00:00.215] [REQUEST] [255ms] BOOKING_ATTEMPT: 16:00 → 255ms — Usted ya tiene cita previa en la gestion especificada
|
||||
[00:00:00.215] [WARN] → Unexpected: Usted ya tiene cita previa en la gestion especificada
|
||||
[00:00:00.215] [WARN] Stopping to avoid accidental duplication.
|
||||
[00:00:00.215] [PHASE]
|
||||
============================================================
|
||||
[00:00:00.215] [PHASE] BENCHMARK SUMMARY — 3 steps, 1 booking attempts
|
||||
[00:00:00.215] [INFO]
|
||||
── SERVER LOAD ESTIMATION ──
|
||||
[00:00:00.215] [INFO] RTT observations: 2 measurements
|
||||
[00:00:00.215] [INFO] Current load: CALIBRATING
|
||||
[00:00:00.215] [INFO] Session avg RTT: 230.2ms
|
||||
[00:00:00.215] [INFO] Min RTT: 205ms | Max RTT: 255ms
|
||||
[00:00:00.215] [INFO] Load trend: INSUFFICIENT_DATA
|
||||
[00:00:00.215] [INFO]
|
||||
── PER-SLOT TIMING ──
|
||||
[00:00:00.215] [INFO] Hora Total ms Attempts Avg RTT Status
|
||||
[00:00:00.215] [INFO] ───────── ─ ────────── ────────── ────────── ─────────────────────────
|
||||
[00:00:00.215] [INFO] 23:59:57.979 [ 979.0ms] [ REQUEST] TLS_CONNECT: webservices.alicante.es:443
|
||||
[00:00:00.215] [INFO] 23:59:59.705 [ 205.5ms] [ REQUEST] CHECK_SLOTS: 205ms — [{"hora":"14:30","dia":"M","horanumero":"1430"},{"hora":"14:45","dia":"M","horanumero":"1445"},{"hor
|
||||
[00:00:00.215] [INFO] 00:00:00.215 [ 255.1ms] [ REQUEST] BOOKING_ATTEMPT: 16:00 → 255ms — Usted ya tiene cita previa en la gestion especificada
|
||||
[00:00:00.215] [PHASE]
|
||||
Log persisted to: /tmp/booking_log.txt
|
||||
[00:00:00.215] [ERROR]
|
||||
❌ FAILED: All 1 attempts exhausted. Competing requests likely grabbed all 9 slots.
|
||||
[00:00:00.215] [ERROR] New slots open daily for the next working day — try again tomorrow.
|
||||
Reference in New Issue
Block a user