One-stop ƏMAS-import diagnostics in Error Log
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.
This commit is contained in:
parent
98681daf2f
commit
1f32d0b07d
|
|
@ -1 +1 @@
|
|||
__version__ = "0.1.23"
|
||||
__version__ = "0.1.24"
|
||||
|
|
|
|||
|
|
@ -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 "<empty>"
|
||||
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:
|
||||
|
|
|
|||
|
|
@ -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.
|
||||
|
|
|
|||
Loading…
Reference in New Issue