From 1f32d0b07d7bc3a3fa32a189cd0e3bc2ce175f9f Mon Sep 17 00:00:00 2001 From: Ali <010109ali@gmail.com> Date: Fri, 1 May 2026 16:41:33 +0000 Subject: [PATCH] =?UTF-8?q?One-stop=20=C6=8FMAS-import=20diagnostics=20in?= =?UTF-8?q?=20Error=20Log?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Goal: stop asking the user to run console snippets every time the import looks broken. After finalize the wizard now writes two self-contained Error Log rows that together answer "what did the wizard ask for, and what actually happened": 1. "Jey Wizard trace: amas dispatch" — written immediately when _materialize_amas_employees calls import_bulk_employees. JSON payload covers: how many employees we passed, the result dict from import_bulk_employees, parallel_module_available + bulk_ parallelism (was the worker code refactored?), full Asan Login state with import lock + session/csrf lengths, wizard cache shape (employee count, first-row keys, doc_oid presence, contract_status distribution), recent RQ Job rows for the bulk import worker. 2. "Jey Wizard trace: amas outcome" — enqueued to the long queue right after dispatch. Polls RQ for the bulk import job (up to ~90s) until finished/failed/stopped/cancelled, then writes: final RQ status + truncated exc_info, employee count in DB for the new company, AMAS Employees count, post-run Asan Login state (lock cleared? session still alive?), and the last 10 min of AMAS-tagged Error Log rows excluding our own traces. Together that's enough to localise any of the failure modes I'd otherwise investigate one-by-one (CSRF abort, expired session, stale lock, parallelism module mismatch, all-employees-filtered). The user only needs to grep `Jey Wizard trace: amas*` and paste the two rows back. --- jey_wizard/__init__.py | 2 +- jey_wizard/etaxes.py | 275 ++++++++++++++++++++++++++++-- jey_wizard/public/js/jey_setup.js | 2 +- 3 files changed, 266 insertions(+), 13 deletions(-) diff --git a/jey_wizard/__init__.py b/jey_wizard/__init__.py index 9eb734d..e8438af 100644 --- a/jey_wizard/__init__.py +++ b/jey_wizard/__init__.py @@ -1 +1 @@ -__version__ = "0.1.23" +__version__ = "0.1.24" diff --git a/jey_wizard/etaxes.py b/jey_wizard/etaxes.py index 52d838b..a0ef89b 100644 --- a/jey_wizard/etaxes.py +++ b/jey_wizard/etaxes.py @@ -1062,18 +1062,40 @@ def _materialize_amas_employees(company_name): "Jey Wizard materialize", ) - frappe.log_error( - json.dumps({ - "company": company_name, - "asan_login": asan_login, - "employees": len(employees), - "create_designation": create_designation, - "parallel_module_available": parallel_module_available, - "bulk_parallelism": bulk_parallelism, - "result": result if isinstance(result, dict) else {"raw": str(result)}, - }, ensure_ascii=False, indent=2), - "Jey Wizard trace: amas enqueued", + # Single fat diagnostic — everything we'd otherwise have to chase + # across RQ Job, Error Log, Asan Login and the wizard cache. Lives + # under the dedicated "Jey Wizard trace: amas dispatch" method so + # the user can just grep that one row and hand it back. + _log_amas_dispatch( + company_name=company_name, + asan_login=asan_login, + employees=employees, + create_designation=create_designation, + parallel_module_available=parallel_module_available, + bulk_parallelism=bulk_parallelism, + result=result, ) + + # Follow-up tracer — independent background job in the "long" queue + # that waits for the bulk-import worker to settle, then writes a + # second Error Log entry with the final state (RQ status, employee + # count in DB, recent AMAS errors, post-run lock state). Together + # with "amas dispatch" this gives a single grep target — the user + # never has to open the console for amas diagnostics again. + try: + frappe.enqueue( + "jey_wizard.etaxes._log_amas_outcome", + asan_login=asan_login, + company=company_name, + expected_count=len(employees) if isinstance(employees, list) else 0, + queue="long", + timeout=180, + ) + except Exception as exc: + frappe.log_error( + f"failed to enqueue amas outcome tracer: {exc}", + "Jey Wizard trace: amas dispatch", + ) except Exception as exc: frappe.log_error( f"materialize_after_setup: amas import enqueue failed: {exc}\n{traceback.format_exc()}", @@ -1268,6 +1290,237 @@ def _purge_inactive_etaxes_records(company): ) +def _log_amas_dispatch( + company_name, + asan_login, + employees, + create_designation, + parallel_module_available, + bulk_parallelism, + result, +): + """Single Error Log entry covering everything the user might need to + diagnose 'wizard says employees will import in background, but I see 0 + employees afterwards'. Dumps: + - what we asked import_bulk_employees to do, and what it returned + - whether the worker module exposes the parallel-mode constant + - Asan Login state (auth, AMAS account selection, import lock, + presence of session/csrf — values themselves are sensitive so we + only log lengths) + - shape of the cached selection (count, first-row keys, the set of + contract_status values present) + - the most recent RQ Job rows for the bulk import worker. + Failures are swallowed — diagnostic must never break the actual hook. + """ + try: + blob = { + "company": company_name, + "asan_login": asan_login, + "create_designation": create_designation, + "employees_passed_to_import": len(employees) if isinstance(employees, list) else None, + "parallel_module_available": bool(parallel_module_available), + "bulk_parallelism": bulk_parallelism, + "import_bulk_employees_result": result if isinstance(result, dict) else {"raw": str(result)}, + } + + try: + al = frappe.db.get_value( + "Asan Login", asan_login, + [ + "auth_status", "amas_auth_status", + "amas_account_oid", "amas_account_name", "amas_account_number", + "amas_import_running", "amas_import_cancel_requested", + "amas_session", "amas_csrf_token", "main_token", "mygovid_token", + "amas_last_activity", + ], + as_dict=True, + ) or {} + blob["asan_login_state"] = { + "auth_status": al.get("auth_status"), + "amas_auth_status": al.get("amas_auth_status"), + "amas_account_oid": al.get("amas_account_oid"), + "amas_account_name": al.get("amas_account_name"), + "amas_account_number": al.get("amas_account_number"), + "amas_import_running": bool(al.get("amas_import_running")), + "amas_import_cancel_requested": bool(al.get("amas_import_cancel_requested")), + "amas_session_len": len(al.get("amas_session") or ""), + "amas_csrf_token_len": len(al.get("amas_csrf_token") or ""), + "main_token_present": bool(al.get("main_token")), + "mygovid_token_present": bool(al.get("mygovid_token")), + "amas_last_activity": str(al.get("amas_last_activity") or ""), + } + except Exception as exc: + blob["asan_login_state_error"] = str(exc)[:200] + + try: + cache = frappe.get_single("Jey Wizard Etaxes Cache") + raw = (cache.amas_selected_employees_json or "").strip() + cache_info = {"raw_len": len(raw)} + if raw: + payload = json.loads(raw) + emps = payload.get("employees") or [] + cache_info["employees_in_cache"] = len(emps) + cache_info["create_designation"] = payload.get("create_designation") + if emps: + sample = emps[0] if isinstance(emps[0], dict) else {} + cache_info["first_row_keys"] = sorted(list(sample.keys())) + cache_info["first_row_doc_oid_present"] = bool(sample.get("doc_oid")) + cache_info["first_row_full_name_sample"] = sample.get("full_name", "")[:40] + statuses = {} + for e in emps: + if not isinstance(e, dict): + continue + s = str(e.get("contract_status") or "").strip().lower() or "" + statuses[s] = statuses.get(s, 0) + 1 + cache_info["contract_status_distribution"] = statuses + blob["wizard_cache"] = cache_info + except Exception as exc: + blob["wizard_cache_error"] = str(exc)[:200] + + try: + rq_rows = frappe.get_all( + "RQ Job", + filters={"job_name": ("like", "%bulk_employees%")}, + fields=["job_id", "status", "time_taken", "exc_info"], + order_by="creation desc", + limit_page_length=3, + ) + # Truncate exc_info per row so the JSON stays readable. + for r in rq_rows: + if r.get("exc_info"): + r["exc_info"] = str(r["exc_info"])[:500] + blob["recent_rq_jobs"] = rq_rows + except Exception as exc: + blob["recent_rq_jobs_error"] = str(exc)[:200] + + frappe.log_error( + json.dumps(blob, ensure_ascii=False, indent=2, default=str), + "Jey Wizard trace: amas dispatch", + ) + except Exception as exc: + # Last-ditch fallback so we always leave SOME breadcrumb. + try: + frappe.log_error( + f"_log_amas_dispatch failed: {exc}", + "Jey Wizard trace: amas dispatch", + ) + except Exception: + pass + + +def _log_amas_outcome(asan_login, company, expected_count): + """Background follow-up: poll RQ for the bulk-import job to settle, + then write a single Error Log entry with everything needed to know + whether the import actually delivered employees: + - rq job final status + truncated exc_info + - employees in DB for this company (the question the user actually + asks: "I see 0 employees, where did they go?") + - post-run Asan Login lock state (running flag should be cleared, + cancel flag should be cleared) + - recent ƏMAS-related Error Log rows from the worker (CSRF abort, + session expired, single-employee failures) + + Bounded to ~90s of polling so a stuck job doesn't pin the worker. + """ + import time + + deadline = time.time() + 90 + last_row = None + while time.time() < deadline: + try: + rows = frappe.get_all( + "RQ Job", + filters={"job_name": ("like", "%bulk_employees%")}, + fields=["job_id", "status", "time_taken", "exc_info", "creation"], + order_by="creation desc", + limit_page_length=1, + ) + except Exception as exc: + last_row = {"_query_error": str(exc)[:200]} + break + if rows: + last_row = rows[0] + status = (last_row.get("status") or "").lower() + if "finish" in status or "fail" in status or "stop" in status or "cancel" in status: + break + time.sleep(2) + + blob = { + "company": company, + "asan_login": asan_login, + "expected_employees": expected_count, + } + + if isinstance(last_row, dict): + row_copy = dict(last_row) + if row_copy.get("exc_info"): + row_copy["exc_info"] = str(row_copy["exc_info"])[:1000] + row_copy["creation"] = str(row_copy.get("creation") or "") + blob["rq_job_final"] = row_copy + else: + blob["rq_job_final"] = None + + try: + blob["employees_in_db_for_company"] = frappe.db.count("Employee", {"company": company}) + except Exception as exc: + blob["employees_in_db_for_company_error"] = str(exc)[:200] + + try: + blob["amas_employees_in_db"] = frappe.db.count("Amas Employees") + except Exception as exc: + blob["amas_employees_in_db_error"] = str(exc)[:200] + + try: + al = frappe.db.get_value( + "Asan Login", asan_login, + [ + "amas_auth_status", "amas_import_running", "amas_import_cancel_requested", + "amas_session", "amas_csrf_token", + ], + as_dict=True, + ) or {} + blob["asan_login_state_after"] = { + "amas_auth_status": al.get("amas_auth_status"), + "amas_import_running": bool(al.get("amas_import_running")), + "amas_import_cancel_requested": bool(al.get("amas_import_cancel_requested")), + "amas_session_len": len(al.get("amas_session") or ""), + "amas_csrf_token_len": len(al.get("amas_csrf_token") or ""), + } + except Exception as exc: + blob["asan_login_state_after_error"] = str(exc)[:200] + + try: + recent = frappe.db.sql( + """ + SELECT method, LEFT(error, 1500) AS err, creation + FROM `tabError Log` + WHERE creation > NOW() - INTERVAL 10 MINUTE + AND ( + method LIKE '%MAS%' + OR method LIKE '%mas%' + OR error LIKE '%CSRF%' + OR error LIKE '%aborted%' + OR error LIKE '%employee%' + OR error LIKE '%session expired%' + ) + AND method NOT LIKE 'Jey Wizard trace:%' + ORDER BY creation DESC + LIMIT 12 + """, + as_dict=True, + ) + for r in recent: + r["creation"] = str(r.get("creation") or "") + blob["recent_amas_related_errors"] = recent + except Exception as exc: + blob["recent_amas_related_errors_error"] = str(exc)[:200] + + frappe.log_error( + json.dumps(blob, ensure_ascii=False, indent=2, default=str), + "Jey Wizard trace: amas outcome", + ) + + def _drop_alert_messages(): """Wipe everything in frappe.local.message_log that piled up during the setup_complete request. We need the entire log gone, not just alerts: diff --git a/jey_wizard/public/js/jey_setup.js b/jey_wizard/public/js/jey_setup.js index f0a804a..742cc56 100644 --- a/jey_wizard/public/js/jey_setup.js +++ b/jey_wizard/public/js/jey_setup.js @@ -10,7 +10,7 @@ frappe.provide("jey_wizard"); // Bump this string in every commit that changes wizard code. Displayed in the badge so // we can tell at a glance which version is actually running on a given machine. Kept in // sync with __version__ in jey_wizard/__init__.py. -const JEY_WIZARD_VERSION = "0.1.23"; +const JEY_WIZARD_VERSION = "0.1.24"; // Wipe Frappe + ERPNext default slides so their `before_load`/`after_load` listeners // don't try to mutate a wizard that isn't slide-based anymore.