fix: installer starts the service reliably (retry + verify + installer.log), fails loudly; 1.1.6

Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
2026-09-24 10:54:19 -03:00
parent 7e229f4b84
commit 40a4d835fe
22 changed files with 153 additions and 35 deletions
@@ -43,3 +43,4 @@ scripts/_*
 *.bak
 *.gz
 *.pkl
+.pytmp/
@@ -1,6 +1,6 @@
 [project]
 name = "gti-fiscal-agent"
-version = "1.1.5"
+version = "1.1.6"
 requires-python = ">=3.10"
 dependencies = ["httpx>=0.27,<1"]

@@ -103,7 +103,7 @@ class Config:
        # (A legacy AGENT_JOBS_ENABLED line in an old agent.env is deliberately ignored.)
        self.agent_jobs_enabled = True
        self.poll_interval_seconds = float(env.get("POLL_INTERVAL_SECONDS", "5"))
-        self.agent_version = env.get("AGENT_VERSION", "1.1.5")
+        self.agent_version = env.get("AGENT_VERSION", "1.1.6")
        self.schema_fingerprint = env.get("SCHEMA_FINGERPRINT", REFERENCE_SCHEMA_V1)
        self.state_db = env.get("AGENT_STATE_DB", str(AGENT_ROOT / "agent_state.sqlite"))
        # Pilot write authorization: both must be explicitly set by the installer for
@@ -240,7 +240,7 @@ def execute_job(job, config, executor, state, env):
            "coverage": coverage,
            "operational": operational,
            "fiscal_mode": getattr(config, "fiscal_mode", None),
-            "release_version": env.get("AGENT_VERSION") or "1.1.5",
+            "release_version": env.get("AGENT_VERSION") or "1.1.6",
            "products_total": len(products),
            "products_changed": len(to_process),
            "products_processed": summary["processed"],
@@ -398,7 +398,7 @@ def run(config, env, *, max_iterations=None, stopper=None):
 def enforce_startup_preflight(env):
    """Full read-only preflight at startup (Hub, auth, Firebird, capabilities, company context, guards). Fail closed."""
    from gti_fiscal_agent.preflight import run_preflight
-    report = run_preflight(env, agent_version=env.get("AGENT_VERSION") or "1.1.5")
+    report = run_preflight(env, agent_version=env.get("AGENT_VERSION") or "1.1.6")
    logger.info("startup preflight: %s", json.dumps({k: report[k] for k in ("PREFLIGHT", "blockers", "fiscal_mode", "effective_firebird_writes")}, ensure_ascii=False))
    print(json.dumps({"PREFLIGHT": report["PREFLIGHT"], "blockers": report["blockers"]}, ensure_ascii=False))
    if report["PREFLIGHT"] != "PASS":
@@ -9,7 +9,7 @@ import os
 import sqlite3
 from pathlib import Path

-AGENT_VERSION_DEFAULT = "1.1.5"
+AGENT_VERSION_DEFAULT = "1.1.6"
 REQUIRED_ENV = ("GTI_HUB_URL", "AGENT_TOKEN", "FIREBIRD_DATABASE_PATH", "FB_USER", "FB_PASSWORD")
 REQUIRED_CAPABILITIES = ("supports_ncm", "supports_ipi", "supports_cest")
 FISCAL_MODES = ("DRY_RUN", "AUTO_APPLY")
@@ -4,5 +4,5 @@ kept identical to this) and what an AgentRelease row's `version` column holds
 once published — never a second, independent version number. Fiscal semantics
 are versioned separately (ENGINE_VERSION/DECISION_VERSION in classification.py,
 DECISION_ENGINE_VERSION etc.) and are NOT changed by a release bump."""
-GTI_FISCAL_VERSION = "1.1.5"
+GTI_FISCAL_VERSION = "1.1.6"
 API_COMPAT_MAJOR_MINOR = "1.0"  # an Agent 1.0.x/1.1.x talks to any Hub 1.0.x
@@ -1,6 +1,6 @@
 [project]
 name = "gti-fiscal-hub"
-version = "1.1.5"
+version = "1.1.6"
 requires-python = ">=3.10"
 dependencies = [
  "fastapi>=0.115,<1",
@@ -17,7 +17,7 @@ def test_health_is_unavailable_when_database_is_down():

 def test_version_endpoint_reports_release_and_fiscal_versions():
    body = TestClient(create_app(database_probe=lambda: True)).get("/version").json()
-    assert body["version"] == "1.1.5" and body["api_compat"] == "1.0" and body["engine_version"] and body["decision_version"]
+    assert body["version"] == "1.1.6" and body["api_compat"] == "1.0" and body["engine_version"] and body["decision_version"]


 def test_production_refuses_the_dev_token(monkeypatch):
@@ -19,4 +19,4 @@ FB_PASSWORD=
 FISCAL_MODE=DRY_RUN
 FIREBIRD_WRITES=0
 POLL_INTERVAL_SECONDS=5
-AGENT_VERSION=1.1.5
+AGENT_VERSION=1.1.6
@@ -164,7 +164,7 @@ switch ($Command) {
                "GTI_HUB_URL=$hub", "AGENT_TOKEN=$token", "AGENT_ID=$agentId",
                "COMPANY_CODE=$code", "COMPANY_CNPJ=$cnpj", "COMPANY_CRT_SOURCE=$crtSource",
                "FIREBIRD_DATABASE_PATH=$db", "FB_USER=$fbUser", "FB_PASSWORD=$fbPass",
-                'FISCAL_MODE=DRY_RUN', 'FIREBIRD_WRITES=0', 'POLL_INTERVAL_SECONDS=5', 'AGENT_VERSION=1.1.5'
+                'FISCAL_MODE=DRY_RUN', 'FIREBIRD_WRITES=0', 'POLL_INTERVAL_SECONDS=5', 'AGENT_VERSION=1.1.6'
            )
            Set-Content -Path $EnvFile -Value $lines -Encoding UTF8
        }
@@ -19,4 +19,4 @@ FB_PASSWORD=
 FISCAL_MODE=DRY_RUN
 FIREBIRD_WRITES=0
 POLL_INTERVAL_SECONDS=5
-AGENT_VERSION=1.1.5
+AGENT_VERSION=1.1.6
@@ -19,4 +19,4 @@ FB_PASSWORD=
 FISCAL_MODE=DRY_RUN
 FIREBIRD_WRITES=0
 POLL_INTERVAL_SECONDS=5
-AGENT_VERSION=1.1.5
+AGENT_VERSION=1.1.6
@@ -19,4 +19,4 @@ FB_PASSWORD=
 FISCAL_MODE=DRY_RUN
 FIREBIRD_WRITES=0
 POLL_INTERVAL_SECONDS=5
-AGENT_VERSION=1.1.5
+AGENT_VERSION=1.1.6
@@ -19,4 +19,4 @@ FB_PASSWORD=
 FISCAL_MODE=DRY_RUN
 FIREBIRD_WRITES=0
 POLL_INTERVAL_SECONDS=5
-AGENT_VERSION=1.1.5
+AGENT_VERSION=1.1.6
@@ -1,5 +1,5 @@
 # GTI Fiscal Hub — production environment (copy to .env, never commit .env)
-GTI_FISCAL_VERSION=1.1.5
+GTI_FISCAL_VERSION=1.1.6

 # REQUIRED. URL-safe secret (used inside a connection URL): openssl rand -hex 24
 POSTGRES_PASSWORD=
@@ -36,7 +36,7 @@ services:
    build:
      context: ../..
      dockerfile: central/Dockerfile
-    image: gti-fiscal-hub:${GTI_FISCAL_VERSION:-1.1.5}
+    image: gti-fiscal-hub:${GTI_FISCAL_VERSION:-1.1.6}
    restart: unless-stopped
    depends_on:
      postgres:
@@ -16,7 +16,7 @@ A variável de ambiente `GTI_SSH_PASSWORD`, se existir, tem prioridade. A senha
 ## Deploy
 ```
 powershell -ExecutionPolicy Bypass -File .\scripts\deploy_hub.ps1
-powershell -ExecutionPolicy Bypass -File .\scripts\deploy_hub.ps1 -PublishAgent -Version 1.1.5
+powershell -ExecutionPolicy Bypass -File .\scripts\deploy_hub.ps1 -PublishAgent -Version 1.1.6
 ```
 Parâmetros: `-Version` (padrão `release/VERSION`), `-PublishAgent`, `-SkipTests`, `-DryRun`.

@@ -172,8 +172,26 @@ def wait_for_heartbeat(agent_token: str, hub: str, timeout: float = 120.0) -> bo
    return False


+def log_path() -> Path:
+    return Path(os.environ.get("GTI_LOG_DIR") or os.path.join(os.environ.get("PROGRAMDATA", r"C:\ProgramData"), "GTI", "FiscalAgent")) / "installer.log"
+
+
+def ilog(message: str) -> None:
+    """Append one timestamped line to installer.log (best effort, never raises, never holds a secret)."""
+    try:
+        path = log_path()
+        path.parent.mkdir(parents=True, exist_ok=True)
+        with path.open("a", encoding="utf-8") as fh:
+            fh.write(time.strftime("%Y-%m-%d %H:%M:%S ") + " ".join(message.split()) + chr(10))
+    except Exception:  # noqa: BLE001
+        pass
+
+
 def _sc(args: list[str]) -> subprocess.CompletedProcess[str]:
-    return subprocess.run(["sc.exe", *args], capture_output=True, text=True)
+    result = subprocess.run(["sc.exe", *args], capture_output=True, text=True)
+    text = " ".join((result.stdout + " " + result.stderr).split())
+    ilog(f"sc {' '.join(a for a in args if not a.lower().startswith('binpath'))} -> rc={result.returncode} {text[:300]}")
+    return result


 def install_service(install_dir_path: Path) -> None:
@@ -209,6 +227,57 @@ def start_service() -> None:
    _sc(["start", SERVICE_NAME])


+def service_state() -> str:
+    out = subprocess.run(["sc.exe", "query", SERVICE_NAME], capture_output=True, text=True).stdout
+    for name in ("RUNNING", "START_PENDING", "STOP_PENDING", "STOPPED", "PAUSED"):
+        if name in out:
+            return name
+    return "UNKNOWN"
+
+
+def service_process_alive() -> bool:
+    out = subprocess.run(["sc.exe", "queryex", SERVICE_NAME], capture_output=True, text=True).stdout
+    for line in out.splitlines():
+        if line.strip().upper().startswith("PID"):
+            pid = line.split(":", 1)[1].strip()
+            if pid.isdigit() and int(pid) > 0:
+                tl = subprocess.run(["tasklist", "/FI", f"PID eq {pid}", "/NH"], capture_output=True, text=True).stdout
+                return pid in tl
+    return False
+
+
+def start_and_verify(attempts: int = 4, per_attempt: float = 60.0) -> tuple[bool, str]:
+    """Start the service and prove it: RUNNING for a few seconds AND a live host process.
+    The first start after fresh files often exceeds the SCM's 30 s limit (error 1053: antivirus scans the
+    new onedir), so a failed attempt is diagnosed into installer.log and retried; the second start is fast."""
+    detail = "not started"
+    for attempt in range(1, attempts + 1):
+        ilog(f"start attempt {attempt}/{attempts}; state={service_state()}")
+        if service_state() != "RUNNING":
+            _sc(["start", SERVICE_NAME])
+        deadline = time.time() + per_attempt
+        while time.time() < deadline and service_state() in ("START_PENDING", "STOP_PENDING", "UNKNOWN"):
+            time.sleep(1.5)
+        if service_state() == "RUNNING":
+            time.sleep(6)  # must survive its own startup (preflight) rather than crash right after RUNNING
+            if service_state() == "RUNNING" and service_process_alive():
+                ilog("service RUNNING and host process alive")
+                return True, "RUNNING"
+        state = service_state()
+        query = subprocess.run(["sc.exe", "query", SERVICE_NAME], capture_output=True, text=True).stdout
+        exit_codes = " ".join(line.strip() for line in query.splitlines() if "EXIT_CODE" in line.upper())
+        detail = f"attempt {attempt}: state={state} {exit_codes}".strip()
+        ilog(detail)
+        try:
+            tail = (install_dir() / "logs" / "agent.log").read_text(encoding="utf-8", errors="replace").splitlines()[-3:]
+            ilog("agent.log tail: " + " | ".join(tail)[:400])
+        except Exception:  # noqa: BLE001
+            pass
+        time.sleep(5)
+    ilog(f"service did NOT start: {detail}")
+    return False, detail
+
+
 def stop_service() -> None:
    _sc(["stop", SERVICE_NAME])

@@ -108,14 +108,13 @@ def install_flow(code: str, *, hub: str | None = None, install_dir_path: str | N
    extract_payload(install)

    started = heartbeat = False
+    service_detail = ""
    if register_service:
        common.install_service(install)
        common.write_arp_uninstall(install)
        if chosen:  # without a Firebird database the service would only fail preflight in a loop
            progress("Iniciando o serviço…")
-            if not common.service_running():
-                common.start_service()
-            started = common.wait_service_state("RUNNING", timeout=45)
+            started, service_detail = common.start_and_verify()
            if started and wait_heartbeat:
                progress("Aguardando o primeiro heartbeat…")
                heartbeat = common.wait_for_heartbeat(result["agent_token"], result.get("hub_url") or hub, timeout=120)
@@ -125,7 +124,7 @@ def install_flow(code: str, *, hub: str | None = None, install_dir_path: str | N
    except Exception:  # noqa: BLE001 — best effort
        pass

-    result.update(install_dir=str(install), agent_version=agent_version, firebird_path=chosen["path"] if chosen else None,
+    result.update(service_detail=service_detail, install_dir=str(install), agent_version=agent_version, firebird_path=chosen["path"] if chosen else None,
                  service_running=started, heartbeat=heartbeat, mode="INSTALL")
    return result

@@ -149,8 +148,8 @@ def upgrade_flow(*, install_dir_path: str | None = None, progress: Callable[[str
    common.write_arp_uninstall(install)
    os.environ["AGENT_VERSION"] = version
    progress("Iniciando o serviço…")
-    common.start_service()
-    started = common.wait_service_state("RUNNING", timeout=45)
+    common.ilog(f"upgrade to {version} from {existing.get('agent_id')}")
+    started, service_detail = common.start_and_verify()
    heartbeat = False
    try:
        from gti_fiscal_agent.credential_store import read_credential
@@ -158,7 +157,7 @@ def upgrade_flow(*, install_dir_path: str | None = None, progress: Callable[[str
    except Exception:  # noqa: BLE001
        pass
    return {"agent_id": existing["agent_id"], "installation_id": existing["installation_id"], "install_dir": str(install), "agent_version": version,
-            "service_running": started, "heartbeat": heartbeat, "mode": "UPGRADE", "hub_url": existing["hub_url"]}
+            "service_running": started, "service_detail": service_detail, "heartbeat": heartbeat, "mode": "UPGRADE", "hub_url": existing["hub_url"]}


 def extract_payload(install: Path) -> None:
@@ -195,8 +194,9 @@ def final_message(result: dict) -> str:
    if result.get("service_running"):
        return ("Instalação concluída e serviço em execução, mas o primeiro heartbeat ainda não foi confirmado.\n\n"
                "O serviço continua tentando sozinho; acompanhe pelo painel. Nenhuma edição de arquivo é necessária.")
-    return ("Instalação concluída, mas o serviço não iniciou.\n\nVerifique o log em "
-            f"{result.get('install_dir')}\\logs\\agent.log ou contate o suporte.")
+    return ("ATENÇÃO: o serviço GTI Fiscal Agent NÃO iniciou.\n\n"
+            f"Motivo: {result.get('service_detail') or 'desconhecido'}\n"
+            f"Detalhes em {common.log_path()} e {result.get('install_dir')}\\logs\\agent.log.")


 class SetupWizard:
@@ -343,12 +343,19 @@ def cli() -> int:
    if not args.code:
        result = upgrade_flow(install_dir_path=args.install_dir, progress=print)
        print(f"UPGRADE_OK agent_id={result['agent_id']} service_running={result['service_running']} heartbeat={result['heartbeat']}")
+        if not result["service_running"]:
+            print(f"SERVICE_START_FAILED {result.get('service_detail')} (see {common.log_path()})", file=sys.stderr)
+            return 3
        return 0
    explicit = {"path": args.fdb, "user": args.fb_user, "password": args.fb_password or ""} if args.fdb else None
    result = install_flow(args.code, hub=args.hub, install_dir_path=args.install_dir, register_service=not args.no_service,
                          firebird=explicit, require_firebird=not args.no_firebird, progress=print)
    print(f"INSTALL_OK agent_id={result.get('agent_id')} install_dir={result.get('install_dir')} hub={result.get('hub_url')} "
          f"service_running={result.get('service_running')} heartbeat={result.get('heartbeat')}")
+    if result.get("service_detail") and not result.get("service_running"):  # a start was attempted and failed
+        if True:
+            print(f"SERVICE_START_FAILED {result.get('service_detail')} (see {common.log_path()})", file=sys.stderr)
+            return 3
    return 0


@@ -1,14 +1,14 @@
 {
 "artifact": "RELEASE_MANIFEST",
- "GTI_FISCAL_VERSION": "1.1.5",
- "generated_at": "2026-09-24T12:43:54+00:00",
+ "GTI_FISCAL_VERSION": "1.1.6",
+ "generated_at": "2026-09-24T13:51:44+00:00",
 "hub": {
-  "version": "1.1.5",
+  "version": "1.1.6",
  "api_compat": "1.0",
  "engine_version": "0.3.0",
  "decision_version": "mission-04c-ipi-ex-split"
 },
- "agent_version": "1.1.5",
+ "agent_version": "1.1.6",
 "fiscal_engine": {
  "ENGINE_VERSION": "0.3.0",
  "DECISION_VERSION": "mission-04c-ipi-ex-split",
@@ -1 +1 @@
-1.1.5
+1.1.6
@@ -14,11 +14,11 @@ sys.path.insert(0, str(ROOT))
 def test_versions_are_coherent_across_hub_agent_and_packages():
    from central.app.version import GTI_FISCAL_VERSION
    v = (ROOT / "release" / "VERSION").read_text(encoding="utf-8").strip()
-    assert v == GTI_FISCAL_VERSION == "1.1.5"
+    assert v == GTI_FISCAL_VERSION == "1.1.6"
    pep = v.replace("-rc", "rc")
    for pp in ("central/pyproject.toml", "agent/pyproject.toml"):
        assert f'version = "{pep}"' in (ROOT / pp).read_text(encoding="utf-8")
-    assert '"AGENT_VERSION", "1.1.5"' in (ROOT / "agent" / "scripts" / "run_agent_service.py").read_text(encoding="utf-8")
+    assert '"AGENT_VERSION", "1.1.6"' in (ROOT / "agent" / "scripts" / "run_agent_service.py").read_text(encoding="utf-8")
    manifest = ROOT / "release" / "RELEASE_MANIFEST.json"
    if manifest.exists():
        m = json.loads(manifest.read_text(encoding="utf-8"))
@@ -35,7 +35,7 @@ def world(tmp_path, monkeypatch):
    monkeypatch.setattr(common, "write_arp_uninstall", lambda d: None)
    monkeypatch.setattr(common, "service_running", lambda: False)
    monkeypatch.setattr(common, "service_installed", lambda: True)
-    monkeypatch.setattr(common, "start_service", lambda: calls.append(("start",)))
+    monkeypatch.setattr(common, "start_and_verify", lambda *a, **k: calls.append(("start",)) or (True, "RUNNING"))
    monkeypatch.setattr(common, "ensure_service_stopped", lambda timeout=45.0: calls.append(("stop",)))
    monkeypatch.setattr(common, "wait_service_state", lambda wanted, timeout=45: True)
    monkeypatch.setattr(common, "wait_for_heartbeat", lambda token, hub, timeout=120: calls.append(("heartbeat_wait",)) or True)
@@ -116,3 +116,44 @@ def test_no_write_flags_anywhere_in_zero_touch_installer():
    for name in ("setup_main.py", "firebird_discovery.py"):
        text = (ROOT / "installer" / name).read_text(encoding="utf-8")
        assert "FIREBIRD_WRITES=1" not in text and "AUTO_APPLY" not in text and "UPDATE " not in text.upper().replace("UPDATE_", "")
+
+
+def test_start_and_verify_retries_after_a_failed_first_start_and_logs_the_cause(monkeypatch, tmp_path):
+    """First start after fresh files typically dies with 1053 (SCM 30 s limit); the retry must succeed and installer.log must say why."""
+    monkeypatch.setenv("GTI_LOG_DIR", str(tmp_path))
+    monkeypatch.setenv("GTI_INSTALL_DIR", str(tmp_path / "inst"))
+    state = {"n": 0, "starts": 0}
+
+    def fake_state():
+        return "RUNNING" if state["starts"] >= 2 else "STOPPED"
+
+    def fake_sc(args):
+        if args[0] == "start":
+            state["starts"] += 1
+        import subprocess
+        return subprocess.CompletedProcess(args, 0, "", "")
+
+    class Q:
+        stdout = "WIN32_EXIT_CODE : 1053"
+
+    monkeypatch.setattr(common, "service_state", fake_state)
+    monkeypatch.setattr(common, "_sc", fake_sc)
+    monkeypatch.setattr(common, "service_process_alive", lambda: True)
+    monkeypatch.setattr(common.subprocess, "run", lambda *a, **k: Q())
+    monkeypatch.setattr(common.time, "sleep", lambda s: None)
+    ok, detail = common.start_and_verify(attempts=3, per_attempt=0.01)
+    assert ok and detail == "RUNNING" and state["starts"] == 2
+    log = (tmp_path / "installer.log").read_text(encoding="utf-8")
+    assert "attempt 1" in log and "1053" in log and "host process alive" in log
+
+
+def test_start_and_verify_reports_failure_after_all_attempts(monkeypatch, tmp_path):
+    monkeypatch.setenv("GTI_LOG_DIR", str(tmp_path))
+    monkeypatch.setenv("GTI_INSTALL_DIR", str(tmp_path / "inst"))
+    monkeypatch.setattr(common, "service_state", lambda: "STOPPED")
+    monkeypatch.setattr(common, "_sc", lambda a: None)
+    monkeypatch.setattr(common.subprocess, "run", lambda *a, **k: type("Q", (), {"stdout": "WIN32_EXIT_CODE : 1053"})())
+    monkeypatch.setattr(common.time, "sleep", lambda s: None)
+    ok, detail = common.start_and_verify(attempts=2, per_attempt=0.01)
+    assert not ok and "1053" in detail
+    assert "NÃO iniciou" in setup_main.final_message({"service_running": False, "service_detail": detail, "install_dir": "x"})
@@ -1 +1 @@
 .1.5
 .1.6