""" E2E test: Standard-vs-Expedited 3-business-day delay system. Tests: 1. business_days_from_now helper (skip weekends + holidays) 2. CRTC handler _maybe_defer_for_standard: - Expedited orders bypass the delay - Standard orders get defer_until set 3 business days out - On second call after delay expires, the defer is cleared and pipeline resumes - On second call before delay expires, returns True (still deferred) 3. Formation _check_standard_delay (same matrix) 4. Idempotency: each checkpoint is independent Usage: python3 -m scripts.tests.e2e_standard_delays """ from __future__ import annotations import logging import os import sys import uuid from datetime import datetime, timedelta, timezone from pathlib import Path from dotenv import load_dotenv env_path = Path(__file__).parent / ".env.test" if env_path.exists(): load_dotenv(env_path) LOG = logging.getLogger("tests.delays") logging.basicConfig( level=logging.INFO, format="%(asctime)s [%(name)s] %(levelname)s %(message)s", stream=sys.stdout, ) DEV_DB_URL = os.environ.get( "DEV_DATABASE_URL", "postgresql://pw:pw_dev_2026@207.174.124.71:5433/performancewest", ) PASS = 0 FAIL = 0 RESULTS: list[dict] = [] def check(label: str, ok: bool, detail: str = ""): global PASS, FAIL if ok: PASS += 1 LOG.info(" PASS: %s", label) else: FAIL += 1 LOG.info(" FAIL: %s — %s", label, detail) RESULTS.append({"label": label, "ok": ok, "detail": detail}) # ────────────────────────────────────────────────────────────────────── # Test 1: business_days_from_now helper # ────────────────────────────────────────────────────────────────────── def test_business_days(): LOG.info("\n=== Test 1: business_days helper ===") from scripts.workers.business_days import business_days_from_now, is_business_day from datetime import datetime as dt, date # Mon → Thu (3 biz days, no weekends) result = business_days_from_now(3, dt(2026, 4, 13)) check("Mon Apr 13 + 3 = Thu Apr 16", result.date() == date(2026, 4, 16), str(result.date())) # Fri → Wed (skips weekend) result = business_days_from_now(3, dt(2026, 4, 17)) check("Fri Apr 17 + 3 = Wed Apr 22", result.date() == date(2026, 4, 22), str(result.date())) # Crossing Memorial Day (Mon May 25) result = business_days_from_now(3, dt(2026, 5, 22)) check("Fri May 22 + 3 skips Memorial Day = Thu May 28", result.date() == date(2026, 5, 28), str(result.date())) # Crossing Christmas + Boxing Day result = business_days_from_now(3, dt(2026, 12, 24)) check("Thu Dec 24 + 3 skips Christmas/Boxing = Wed Dec 30", result.date() == date(2026, 12, 30), str(result.date())) # is_business_day basic checks check("Sat is not business day", not is_business_day(date(2026, 4, 18))) check("Sun is not business day", not is_business_day(date(2026, 4, 19))) check("Mon is business day", is_business_day(date(2026, 4, 13))) check("Christmas is not business day", not is_business_day(date(2026, 12, 25))) # ────────────────────────────────────────────────────────────────────── # Test 2: CRTC _maybe_defer_for_standard # ────────────────────────────────────────────────────────────────────── def _create_test_crtc_order(uid: str) -> str: """Insert a fake CRTC order row for testing.""" import psycopg2 conn = psycopg2.connect(DEV_DB_URL) cur = conn.cursor() order_number = f"CA-TEST-{uid.upper()}" cur.execute( """INSERT INTO canada_crtc_orders ( order_number, customer_name, customer_email, company_type, director_name, director_address, services_description, geographic_coverage, mailbox_address, regulatory_contact_name, regulatory_contact_email, regulatory_contact_phone, service_fee_cents, government_fee_cents, total_cents, status, payment_status, identity_session_id, incorporation_province ) VALUES (%s, 'Test Carrier', %s, 'numbered', 'Test Director', '{"street": "100 Test St"}', 'test services', 'BC', 'test address', 'reg', 'reg@test.com', '+10000000000', 389900, 25000, 414900, 'received', 'paid', NULL, 'BC')""", (order_number, f"delay-test+{uid}@performancewest.net"), ) conn.commit() conn.close() return order_number def _cleanup_test_crtc_order(order_number: str): import psycopg2 conn = psycopg2.connect(DEV_DB_URL) cur = conn.cursor() cur.execute("DELETE FROM canada_crtc_orders WHERE order_number = %s", (order_number,)) conn.commit() conn.close() def _invoke_defer_helper_in_container(order_data: dict, checkpoint: str) -> bool: """Invoke _maybe_defer_for_standard on the dev workers container via docker exec. Pipes Python source via stdin to avoid shell escaping issues. Returns the helper's True/False return value. """ import json import subprocess payload_json_str = json.dumps(order_data) checkpoint_str = json.dumps(checkpoint) py_lines = [ "import sys, json", "sys.path.insert(0, '/app')", "from scripts.workers.services.canada_crtc import CanadaCRTCHandler", "handler = CanadaCRTCHandler()", f"order = json.loads({payload_json_str!r})", f"checkpoint = {checkpoint_str}", "result = handler._maybe_defer_for_standard(order, checkpoint)", "print('DEFER_RESULT:', result)", ] py_code = "\n".join(py_lines) + "\n" cmd = ( "ssh -p 22022 deploy@207.174.124.71 " "'docker exec -i performancewest-dev-workers-1 python3 -'" ) result = subprocess.run( cmd, shell=True, input=py_code, capture_output=True, text=True, timeout=30, ) output = result.stdout + result.stderr for line in output.splitlines(): if line.startswith("DEFER_RESULT:"): val = line.split(":", 1)[1].strip() return val == "True" LOG.warning("Could not parse defer result from output: %s", output[:500]) return False def test_crtc_defer_helper(): LOG.info("\n=== Test 2: CRTC _maybe_defer_for_standard (via dev workers container) ===") uid = uuid.uuid4().hex[:8] order_number = _create_test_crtc_order(uid) try: # Test A: Expedited order should NOT be deferred expedited_order = {"name": order_number, "custom_expedited": True} result = _invoke_defer_helper_in_container(expedited_order, "post_did_pre_incorporation") check("Expedited: returns False (no delay)", result is False) # Test B: Standard order should be deferred (first call) standard_order = {"name": order_number, "custom_expedited": False} result = _invoke_defer_helper_in_container(standard_order, "post_did_pre_incorporation") check("Standard first call: returns True (deferred)", result is True) # Verify defer_until was set in DB import psycopg2 conn = psycopg2.connect(DEV_DB_URL) cur = conn.cursor() cur.execute( "SELECT defer_until, automation_note, automation_status FROM canada_crtc_orders WHERE order_number = %s", (order_number,), ) row = cur.fetchone() defer_until, note, status = row check("DB: defer_until is set", defer_until is not None) check("DB: automation_note matches checkpoint", note == "post_did_pre_incorporation", str(note)) check("DB: automation_status = Deferred", status == "Deferred", str(status)) check("DB: defer_until is in future", defer_until > datetime.now(timezone.utc) if defer_until else False) conn.close() # Test C: Second call (still in defer window) should return True (still deferred) result = _invoke_defer_helper_in_container(standard_order, "post_did_pre_incorporation") check("Standard second call (still pending): returns True", result is True) # Test D: Manually advance defer_until to past, then call again — should clear and return False conn = psycopg2.connect(DEV_DB_URL) cur = conn.cursor() past = datetime.now(timezone.utc) - timedelta(hours=1) cur.execute( "UPDATE canada_crtc_orders SET defer_until = %s WHERE order_number = %s", (past, order_number), ) conn.commit() conn.close() result = _invoke_defer_helper_in_container(standard_order, "post_did_pre_incorporation") check("Standard after defer expired: returns False (resume)", result is False) # Verify defer_until was cleared conn = psycopg2.connect(DEV_DB_URL) cur = conn.cursor() cur.execute( "SELECT defer_until, automation_status FROM canada_crtc_orders WHERE order_number = %s", (order_number,), ) row = cur.fetchone() check("DB: defer_until cleared after resume", row[0] is None) check("DB: automation_status reset to Pending", row[1] == "Pending", str(row[1])) conn.close() # Test E: Different checkpoint = independent defer result = _invoke_defer_helper_in_container(standard_order, "post_email_pre_letter") check("Different checkpoint: independent defer (returns True)", result is True) finally: _cleanup_test_crtc_order(order_number) # ────────────────────────────────────────────────────────────────────── # Test 3: Verify CRTC pipeline source has defer points # ────────────────────────────────────────────────────────────────────── def test_crtc_pipeline_has_defer_points(): LOG.info("\n=== Test 3: CRTC pipeline source verification ===") src = Path(__file__).parent.parent / "workers" / "services" / "canada_crtc.py" text = src.read_text() check("Has _maybe_defer_for_standard method", "def _maybe_defer_for_standard" in text) check("Defer 1: post_did_pre_incorporation", '"post_did_pre_incorporation"' in text) check("Defer 2: post_email_pre_letter", '"post_email_pre_letter"' in text) check("Defer 3: post_delivery_pre_compliance", '"post_delivery_pre_compliance"' in text) check("Step 7 idempotency: binder_already_compiled", "binder_already_compiled" in text) check("Step 8 idempotency: binder_already_uploaded", "binder_already_uploaded" in text) check("Step 9 idempotency: binder_already_emailed", "binder_already_emailed" in text) # ────────────────────────────────────────────────────────────────────── # Test 4: Verify Formation pipeline source has defer points # ────────────────────────────────────────────────────────────────────── def test_formation_pipeline_has_defer_points(): LOG.info("\n=== Test 4: Formation pipeline source verification ===") src = Path(__file__).parent.parent / "workers" / "job_server.py" text = src.read_text() check("Has _check_standard_delay function", "def _check_standard_delay" in text) check("file_entity defer: post_name_pre_filing", '"post_name_pre_filing"' in text) check("obtain_ein defer: post_filing_pre_ein", '"post_filing_pre_ein"' in text) check("generate_docs defer: post_ein_pre_docs", '"post_ein_pre_docs"' in text) check("import business_days_from_now", "from scripts.workers.business_days import business_days_from_now" in text) # ────────────────────────────────────────────────────────────────────── # Test 5: Migration verification # ────────────────────────────────────────────────────────────────────── def test_migration_columns(): LOG.info("\n=== Test 5: Migration 039 columns ===") import psycopg2 conn = psycopg2.connect(DEV_DB_URL) cur = conn.cursor() cur.execute(""" SELECT column_name FROM information_schema.columns WHERE table_name = 'canada_crtc_orders' AND column_name IN ('defer_until', 'automation_note', 'binder_compiled_at', 'binder_uploaded_at', 'binder_emailed_at') ORDER BY column_name """) cols = {r[0] for r in cur.fetchall()} conn.close() check("defer_until column exists", "defer_until" in cols) check("automation_note column exists", "automation_note" in cols) check("binder_compiled_at column exists", "binder_compiled_at" in cols) check("binder_uploaded_at column exists", "binder_uploaded_at" in cols) check("binder_emailed_at column exists", "binder_emailed_at" in cols) # ────────────────────────────────────────────────────────────────────── # Main # ────────────────────────────────────────────────────────────────────── def main(): LOG.info("=" * 60) LOG.info(" STANDARD-VS-EXPEDITED DELAY E2E TEST") LOG.info("=" * 60) test_business_days() test_migration_columns() test_crtc_defer_helper() test_crtc_pipeline_has_defer_points() test_formation_pipeline_has_defer_points() LOG.info("\n" + "=" * 60) LOG.info(" RESULTS: %d passed, %d failed, %d total", PASS, FAIL, PASS + FAIL) LOG.info("=" * 60) if FAIL > 0: LOG.info("\n Failed checks:") for r in RESULTS: if not r["ok"]: LOG.info(" X %s — %s", r["label"], r["detail"]) sys.exit(1 if FAIL > 0 else 0) if __name__ == "__main__": main()