Trace materialize_after_setup decision points to Error Log

Adds seven 'Jey Wizard trace: ...' breadcrumbs (all using frappe.log_error
so they show up in the same place actual failures already do, with a
distinct title prefix to filter them out from real errors):

- fetch_all_etaxes done — confirms the Asan-step fetch ran, with summary
  and per-endpoint errors
- materialize start — args, Company existence, default Asan Login auth
  state, full cache snapshot
- loaders done — per-loader before/after E-Taxes row counts (or error)
- bank native done — input rows from cache, materialised count, parent
- amas skipped / amas enqueued — which branch ran and why

Used to diagnose 'no doctypes created after setup' on a remote test
machine where I can't reproduce locally.

jey_wizard/__init__.py

@@ -1 +1 @@
-__version__ = "0.1.6"
+__version__ = "0.1.7"

jey_wizard/etaxes.py

@@ -122,6 +122,13 @@ def fetch_all_etaxes():
 	cache.save()
 	frappe.db.commit()
 
+	# Diagnostic breadcrumb so we can confirm from Error Log alone that the Asan-step
+	# fetch ran and what it produced (counts per endpoint, per-endpoint errors).
+	frappe.log_error(
+		json.dumps({"summary": summary, "errors": errors}, ensure_ascii=False, indent=2),
+		"Jey Wizard trace: fetch_all_etaxes done",
+	)
+
 	return {
 		"ok": True,
 		"summary": summary,
@@ -153,6 +160,15 @@ def materialize_after_setup(args):
 	call invoice_az's loaders to persist everything into E-Taxes DocTypes with the
 	real Company link. Best-effort: per-loader failures are logged, not raised.
 	"""
+	# Single trace at entry: confirms the hook fires and dumps every input the rest
+	# of materialize depends on (args, Company existence, Asan auth state, cache
+	# state). Without this we can't tell from logs alone whether materialize even ran.
+	try:
+		_log_materialize_entry(args)
+	except Exception:
+		# Diagnostic must never break the actual hook.
+		pass
+
 	company_name = (args or {}).get("company_name")
 	if not company_name:
 		frappe.log_error(
@@ -198,25 +214,37 @@ def materialize_after_setup(args):
 
 	from invoice_az import company_api
 
+	# (kind, loader, doctype-with-company-link). Doctype is used purely to
+	# count rows before/after each loader as a diagnostic breadcrumb.
 	loaders = [
-		("objects", company_api.load_company_objects),
-		("cash_registers", company_api.load_company_cash_registers),
-		("pos_terminals", company_api.load_company_pos_terminals),
-		("bank_accounts", company_api.load_company_bank_accounts),
-		("obligation_pacts", company_api.load_company_obligation_pacts),
-		("presented_certs", company_api.load_company_presented_certificates),
+		("objects", company_api.load_company_objects, "E-Taxes Object"),
+		("cash_registers", company_api.load_company_cash_registers, "E-Taxes Cash Register"),
+		("pos_terminals", company_api.load_company_pos_terminals, "E-Taxes POS Terminal"),
+		("bank_accounts", company_api.load_company_bank_accounts, "E-Taxes Bank Account"),
+		("obligation_pacts", company_api.load_company_obligation_pacts, "E-Taxes Obligation Pact"),
+		("presented_certs", company_api.load_company_presented_certificates, "E-Taxes Presented Certificate"),
 	]
 
-	for name, loader in loaders:
+	loader_trace = {}
+	for name, loader, doctype in loaders:
+		before = _safe_count(doctype, company_name)
 		try:
 			loader(company_name)
+			after = _safe_count(doctype, company_name)
+			loader_trace[name] = {"before": before, "after": after, "delta": (after - before) if (before is not None and after is not None) else None}
 		except Exception as exc:
+			loader_trace[name] = {"before": before, "error": str(exc)[:200]}
 			frappe.log_error(
 				f"materialize_after_setup: {name} loader failed for {company_name}: {exc}\n"
 				f"{traceback.format_exc()}",
 				"Jey Wizard materialize",
 			)
 
+	frappe.log_error(
+		json.dumps(loader_trace, ensure_ascii=False, indent=2),
+		"Jey Wizard trace: loaders done",
+	)
+
 	# invoice_az's bank loader only populates the E-Taxes Bank Account cache doctype.
 	# For the wizard we also want native ERPNext Bank / Bank Account / GL Account so
 	# the user can post transactions on day one, plus we clear out unused CoA
@@ -290,10 +318,12 @@ def _materialize_native_banks(company):
 
 	_delete_bank_placeholders(company, parent)
 	frappe.db.commit()
-	# Success log is loud on purpose — makes it easy to verify the hook ran end-to-end.
-	frappe.logger().info(
-		f"materialize_native_banks: company={company} materialised={created} "
-		f"skipped_closed={skipped_closed} parent={parent}"
+	# Success breadcrumb in Error Log so we can verify end-to-end run from the same
+	# place where loader/cache traces live.
+	frappe.log_error(
+		f"company={company} materialised={created} skipped_closed={skipped_closed} "
+		f"input_rows={len(accounts)} parent={parent}",
+		"Jey Wizard trace: bank native done",
 	)
 
 
@@ -415,6 +445,10 @@ def _materialize_amas_employees(company_name):
 	cache = frappe.get_single("Jey Wizard Etaxes Cache")
 	raw = (cache.amas_selected_employees_json or "").strip()
 	if not raw:
+		frappe.log_error(
+			f"company={company_name} reason=amas_cache_empty (user skipped AMAS step or fetch never ran)",
+			"Jey Wizard trace: amas skipped",
+		)
 		return
 
 	try:
@@ -428,6 +462,10 @@ def _materialize_amas_employees(company_name):
 
 	employees = payload.get("employees") or []
 	if not employees:
+		frappe.log_error(
+			f"company={company_name} reason=amas_payload_empty employees=0",
+			"Jey Wizard trace: amas skipped",
+		)
 		return
 
 	create_designation = payload.get("create_designation", 0)
@@ -449,6 +487,10 @@ def _materialize_amas_employees(company_name):
 			company=company_name,
 			create_designation=create_designation,
 		)
+		frappe.log_error(
+			f"company={company_name} asan_login={asan_login} employees={len(employees)} create_designation={create_designation}",
+			"Jey Wizard trace: amas enqueued",
+		)
 	except Exception as exc:
 		frappe.log_error(
 			f"materialize_after_setup: amas import enqueue failed: {exc}\n{traceback.format_exc()}",
@@ -525,3 +567,71 @@ def _count_items(data, paginated):
 def _only_admin():
 	if frappe.session.user != "Administrator":
 		frappe.throw(_("Only Administrator may run setup"), frappe.PermissionError)
+
+
+def _safe_count(doctype, company):
+	"""Count rows in `doctype` filtered by company. Returns None on any failure
+	(missing doctype, missing company field, db error) — used purely for trace
+	breadcrumbs, must never throw.
+	"""
+	try:
+		if not frappe.db.exists("DocType", doctype):
+			return None
+		return frappe.db.count(doctype, {"company": company})
+	except Exception:
+		try:
+			return frappe.db.count(doctype)
+		except Exception:
+			return None
+
+
+def _log_materialize_entry(args):
+	"""Dump everything materialize_after_setup decides on at entry: input args,
+	Company existence, default Asan Login auth state, cache freshness/sizes.
+	"""
+	company_name = (args or {}).get("company_name")
+	asan = frappe.db.get_value(
+		"Asan Login",
+		{"is_default": 1},
+		["name", "auth_status", "main_token", "bearer_token"],
+		as_dict=True,
+	)
+	cache_present = frappe.db.exists("DocType", "Jey Wizard Etaxes Cache")
+	cache_info = {}
+	if cache_present:
+		try:
+			c = frappe.get_single("Jey Wizard Etaxes Cache")
+			cache_info = {
+				"fetched_at": str(c.fetched_at) if c.fetched_at else None,
+				"last_summary": c.last_summary,
+				"last_error": c.last_error,
+				"objects_json_len": len(c.objects_json or ""),
+				"cash_registers_json_len": len(c.cash_registers_json or ""),
+				"pos_terminals_json_len": len(c.pos_terminals_json or ""),
+				"bank_accounts_json_len": len(c.bank_accounts_json or ""),
+				"obligation_pacts_json_len": len(c.obligation_pacts_json or ""),
+				"presented_certs_json_len": len(c.presented_certs_json or ""),
+				"amas_selected_employees_json_len": len(c.amas_selected_employees_json or ""),
+			}
+		except Exception as exc:
+			cache_info = {"_load_error": str(exc)[:200]}
+
+	trace = {
+		"args_keys": sorted(list((args or {}).keys())),
+		"company_name": company_name,
+		"company_exists": bool(company_name and frappe.db.exists("Company", company_name)),
+		"valuation_method": (args or {}).get("valuation_method"),
+		"chart_of_accounts": (args or {}).get("chart_of_accounts"),
+		"country": (args or {}).get("country"),
+		"currency": (args or {}).get("currency"),
+		"asan_default_login": asan.name if asan else None,
+		"asan_auth_status": asan.auth_status if asan else None,
+		"asan_has_main_token": bool(asan and asan.main_token),
+		"asan_has_bearer_token": bool(asan and asan.bearer_token),
+		"cache_doctype_exists": bool(cache_present),
+		"cache": cache_info,
+	}
+	frappe.log_error(
+		json.dumps(trace, ensure_ascii=False, indent=2),
+		"Jey Wizard trace: materialize start",
+	)

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.6";
+const JEY_WIZARD_VERSION = "0.1.7";
 
 // 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.