From d3c1f107c7a7fec4142909dbe944ebedeb8871d8 Mon Sep 17 00:00:00 2001 From: Michael Wu Date: Tue, 22 Sep 2026 02:33:32 +0900 Subject: [PATCH 1/4] Add referral invoice decision logging --- README.md | 30 +++- referral_fee/referral_fee/referral_utils.py | 138 +++++++++++++++- .../referral_fee/test_referral_utils.py | 151 ++++++++++++++++++ 3 files changed, 312 insertions(+), 7 deletions(-) create mode 100644 referral_fee/referral_fee/test_referral_utils.py diff --git a/README.md b/README.md index 7336785..558253d 100644 --- a/README.md +++ b/README.md @@ -172,8 +172,34 @@ Run through these after any install or code change: | **Duplicate guard** | Submit same SI twice (or cancel + resubmit without amending) | Only one PI per referrer | | **Cancel cleanup** | Submit SI → Cancel SI | Draft PI deleted automatically | | **Amend flow** | Submit → Cancel → Amend → Resubmit | New PI created, no duplicates | -| **No project** | Submit SI with no Project set | No PI created, no error | -| **No referrers** | Submit SI against Project with empty Referrers tab | No PI created, no error | +| **No project** | Submit SI with no Project set | No PI created; `missing_project` is logged | +| **No referrers** | Submit SI against Project with empty Referrers tab | No PI created; `no_project_referrers` is logged | + +--- + +## Troubleshooting Missing Referral Invoices + +The automation runs when a **Sales Invoice is submitted**, not when its customer +payment is received. The submitted Sales Invoice must have its header-level +**Project** field set; an invoice with no Project is intentionally skipped because +the app has no Project Referrers table to use. + +Auto-generated Purchase Invoices can be distinguished from manually entered ones +by both of these fields: + +- **Is Referral Fee** is checked. +- **Referral Source Sales Invoice** links to the triggering Sales Invoice. + +Every submission decision is written as structured data to the site-level log: + +```text +sites//logs/referral_fee.log +``` + +Useful events include `referral_invoice.created`, +`referral_invoice.creation_failed`, and `referral_invoice.skipped`. Skip entries +include an explicit reason such as `missing_project`, `no_project_referrers`, or +`duplicate_purchase_invoice`, along with the source Sales Invoice context. --- diff --git a/referral_fee/referral_fee/referral_utils.py b/referral_fee/referral_fee/referral_utils.py index 013a9c3..6ab77f7 100644 --- a/referral_fee/referral_fee/referral_utils.py +++ b/referral_fee/referral_fee/referral_utils.py @@ -1,12 +1,30 @@ import frappe from frappe import _ -from frappe.utils import today, add_years, getdate, flt, add_days +from frappe.utils import add_days, add_years, flt, getdate, today # Item used as the line item in auto-generated referral Purchase Invoices. # "Internal Commission" is the existing item used for manual referral PIs in prod. # Change this if Caleb decides to use a different item. REFERRAL_FEE_ITEM = "Internal Commission" +# Keep a dedicated, site-level audit trail for referral invoice decisions. This is +# intentionally separate from the general web log so a missing invoice can be +# traced without reproducing the original Sales Invoice submission. +logger = frappe.logger("referral_fee", allow_site=True, file_count=20) + + +def _log_sales_invoice_event(level, event, doc, **details): + """Write a structured referral event with the source invoice context.""" + entry = { + "event": event, + "sales_invoice": doc.name, + "customer": doc.customer, + "project": doc.project, + "grand_total": flt(doc.grand_total), + } + entry.update(details) + getattr(logger, level)(entry) + def on_sales_invoice_submit(doc, method): """ @@ -14,16 +32,36 @@ def on_sales_invoice_submit(doc, method): For each referrer defined on the linked Project, creates one Draft Purchase Invoice. Amount = grand_total × referrer_percentage% """ + _log_sales_invoice_event("info", "referral_invoice.processing_started", doc) + if not doc.project: + _log_sales_invoice_event( + "info", + "referral_invoice.skipped", + doc, + reason="missing_project", + ) return try: project = frappe.get_doc("Project", doc.project) except frappe.DoesNotExistError: + _log_sales_invoice_event( + "warning", + "referral_invoice.skipped", + doc, + reason="project_not_found", + ) return referrers = project.get("referrers", []) if not referrers: + _log_sales_invoice_event( + "info", + "referral_invoice.skipped", + doc, + reason="no_project_referrers", + ) return # ── First-year limit ────────────────────────────────────────────────────── @@ -51,7 +89,30 @@ def on_sales_invoice_submit(doc, method): created_pis = [] for row in referrers: - if not row.supplier or not flt(row.percentage): + supplier = row.supplier + percentage = flt(row.percentage) + row_index = row.get("idx") + + if not supplier: + _log_sales_invoice_event( + "warning", + "referral_invoice.referrer_skipped", + doc, + reason="missing_supplier", + referrer_row=row_index, + percentage=percentage, + ) + continue + + if not percentage: + _log_sales_invoice_event( + "info", + "referral_invoice.referrer_skipped", + doc, + reason="zero_percentage", + referrer_row=row_index, + supplier=supplier, + ) continue # Guard: skip if a non-cancelled PI already exists for this SI + supplier. @@ -60,23 +121,74 @@ def on_sales_invoice_submit(doc, method): "Purchase Invoice", { "referral_source_si": doc.name, - "supplier": row.supplier, + "supplier": supplier, "docstatus": ["!=", 2], }, "name", ) if existing: + _log_sales_invoice_event( + "info", + "referral_invoice.referrer_skipped", + doc, + reason="duplicate_purchase_invoice", + referrer_row=row_index, + supplier=supplier, + percentage=percentage, + existing_purchase_invoice=existing, + ) continue # Formula confirmed with Caleb (2026-05-01): grand_total × % # Rounding confirmed with Caleb (2026-05-04): nearest penny, Python standard rounding. # Example: $304.91 × 10% = $30.491 → rounds to $30.49 - amount = round(flt(doc.grand_total) * flt(row.percentage) / 100, 2) + amount = round(flt(doc.grand_total) * percentage / 100, 2) if amount <= 0: + _log_sales_invoice_event( + "warning", + "referral_invoice.referrer_skipped", + doc, + reason="non_positive_amount", + referrer_row=row_index, + supplier=supplier, + percentage=percentage, + amount=amount, + ) continue - pi = _make_purchase_invoice(doc, row.supplier, amount) + try: + pi = _make_purchase_invoice(doc, supplier, amount) + except Exception: + _log_sales_invoice_event( + "exception", + "referral_invoice.creation_failed", + doc, + referrer_row=row_index, + supplier=supplier, + percentage=percentage, + amount=amount, + ) + raise + created_pis.append(pi.name) + _log_sales_invoice_event( + "info", + "referral_invoice.created", + doc, + referrer_row=row_index, + supplier=supplier, + percentage=percentage, + amount=amount, + purchase_invoice=pi.name, + ) + + _log_sales_invoice_event( + "info", + "referral_invoice.processing_completed", + doc, + created_count=len(created_pis), + created_purchase_invoices=created_pis, + ) if created_pis: links = ", ".join( @@ -106,9 +218,25 @@ def on_sales_invoice_cancel(doc, method): pluck="name", ) + _log_sales_invoice_event( + "info", + "referral_invoice.cancel_cleanup_started", + doc, + draft_purchase_invoices=draft_pis, + submitted_purchase_invoices=submitted_pis, + ) + for name in draft_pis: frappe.delete_doc("Purchase Invoice", name, ignore_permissions=True) + _log_sales_invoice_event( + "info", + "referral_invoice.cancel_cleanup_completed", + doc, + deleted_draft_purchase_invoices=draft_pis, + submitted_purchase_invoices_requiring_manual_cancellation=submitted_pis, + ) + if draft_pis: frappe.msgprint( _("Deleted {0} Draft referral Purchase Invoice(s).").format(len(draft_pis)), diff --git a/referral_fee/referral_fee/test_referral_utils.py b/referral_fee/referral_fee/test_referral_utils.py new file mode 100644 index 0000000..b1d2401 --- /dev/null +++ b/referral_fee/referral_fee/test_referral_utils.py @@ -0,0 +1,151 @@ +from unittest import TestCase +from unittest.mock import patch + +import frappe + +from referral_fee.referral_fee import referral_utils + + +class TestReferralInvoiceLogging(TestCase): + def setUp(self): + self.sales_invoice = frappe._dict( + { + "name": "ACC-SINV-TEST-00001", + "customer": "Test Customer", + "project": "PROJ-TEST", + "grand_total": 1000, + "company": "Test Company", + "currency": "USD", + } + ) + + @patch.object(referral_utils.logger, "info") + @patch.object(frappe, "get_doc") + def test_logs_missing_project_skip_reason(self, get_doc, log_info): + self.sales_invoice.project = None + + referral_utils.on_sales_invoice_submit(self.sales_invoice, "on_submit") + + get_doc.assert_not_called() + entries = [call.args[0] for call in log_info.call_args_list] + self.assertEqual(entries[-1]["event"], "referral_invoice.skipped") + self.assertEqual(entries[-1]["reason"], "missing_project") + + @patch.object(referral_utils.logger, "info") + @patch.object(referral_utils, "_make_purchase_invoice") + @patch.object(frappe, "msgprint") + @patch.object(frappe.db, "get_value", return_value=None) + @patch.object(frappe, "get_doc") + def test_logs_created_purchase_invoice( + self, + get_doc, + _get_value, + _msgprint, + make_purchase_invoice, + log_info, + ): + get_doc.return_value = frappe._dict( + { + "referrers": [ + frappe._dict( + { + "idx": 1, + "supplier": "Test Supplier", + "percentage": 10, + } + ) + ] + } + ) + make_purchase_invoice.return_value = frappe._dict( + {"name": "ACC-PINV-TEST-00001"} + ) + + referral_utils.on_sales_invoice_submit(self.sales_invoice, "on_submit") + + make_purchase_invoice.assert_called_once_with( + self.sales_invoice, "Test Supplier", 100.0 + ) + entries = [call.args[0] for call in log_info.call_args_list] + created = next( + entry for entry in entries if entry["event"] == "referral_invoice.created" + ) + self.assertEqual(created["purchase_invoice"], "ACC-PINV-TEST-00001") + self.assertEqual(created["amount"], 100.0) + completed = entries[-1] + self.assertEqual(completed["event"], "referral_invoice.processing_completed") + self.assertEqual(completed["created_count"], 1) + + @patch.object(referral_utils.logger, "info") + @patch.object(referral_utils, "_make_purchase_invoice") + @patch.object(frappe.db, "get_value", return_value="ACC-PINV-TEST-00001") + @patch.object(frappe, "get_doc") + def test_logs_duplicate_skip_reason( + self, get_doc, _get_value, make_purchase_invoice, log_info + ): + get_doc.return_value = frappe._dict( + { + "referrers": [ + frappe._dict( + { + "idx": 1, + "supplier": "Test Supplier", + "percentage": 10, + } + ) + ] + } + ) + + referral_utils.on_sales_invoice_submit(self.sales_invoice, "on_submit") + + make_purchase_invoice.assert_not_called() + entries = [call.args[0] for call in log_info.call_args_list] + skipped = next( + entry + for entry in entries + if entry["event"] == "referral_invoice.referrer_skipped" + ) + self.assertEqual(skipped["reason"], "duplicate_purchase_invoice") + self.assertEqual( + skipped["existing_purchase_invoice"], "ACC-PINV-TEST-00001" + ) + + @patch.object(referral_utils.logger, "exception") + @patch.object(referral_utils.logger, "info") + @patch.object( + referral_utils, + "_make_purchase_invoice", + side_effect=RuntimeError("insert failed"), + ) + @patch.object(frappe.db, "get_value", return_value=None) + @patch.object(frappe, "get_doc") + def test_logs_and_reraises_creation_failure( + self, + get_doc, + _get_value, + _make_purchase_invoice, + _log_info, + log_exception, + ): + get_doc.return_value = frappe._dict( + { + "referrers": [ + frappe._dict( + { + "idx": 1, + "supplier": "Test Supplier", + "percentage": 10, + } + ) + ] + } + ) + + with self.assertRaisesRegex(RuntimeError, "insert failed"): + referral_utils.on_sales_invoice_submit(self.sales_invoice, "on_submit") + + entry = log_exception.call_args.args[0] + self.assertEqual(entry["event"], "referral_invoice.creation_failed") + self.assertEqual(entry["supplier"], "Test Supplier") + self.assertEqual(entry["amount"], 100.0) From 44916249485d9200cbc3459e2bb59624f1761a08 Mon Sep 17 00:00:00 2001 From: Michael Wu Date: Tue, 22 Sep 2026 02:41:43 +0900 Subject: [PATCH 2/4] Defer referral success logs until commit --- README.md | 4 +++- referral_fee/referral_fee/referral_utils.py | 14 ++++++++++++-- .../referral_fee/test_referral_utils.py | 19 ++++++++++++++++++- 3 files changed, 33 insertions(+), 4 deletions(-) diff --git a/README.md b/README.md index 558253d..356f595 100644 --- a/README.md +++ b/README.md @@ -190,7 +190,9 @@ by both of these fields: - **Is Referral Fee** is checked. - **Referral Source Sales Invoice** links to the triggering Sales Invoice. -Every submission decision is written as structured data to the site-level log: +Every submission decision is written as structured data to the site-level log. +Creation and cleanup success events are emitted only after the database transaction +commits, so a later rollback cannot leave a false success record: ```text sites//logs/referral_fee.log diff --git a/referral_fee/referral_fee/referral_utils.py b/referral_fee/referral_fee/referral_utils.py index 6ab77f7..de51b28 100644 --- a/referral_fee/referral_fee/referral_utils.py +++ b/referral_fee/referral_fee/referral_utils.py @@ -13,7 +13,7 @@ logger = frappe.logger("referral_fee", allow_site=True, file_count=20) -def _log_sales_invoice_event(level, event, doc, **details): +def _log_sales_invoice_event(level, event, doc, after_commit=False, **details): """Write a structured referral event with the source invoice context.""" entry = { "event": event, @@ -23,7 +23,14 @@ def _log_sales_invoice_event(level, event, doc, **details): "grand_total": flt(doc.grand_total), } entry.update(details) - getattr(logger, level)(entry) + + def write_log(): + getattr(logger, level)(entry) + + if after_commit: + frappe.db.after_commit.add(write_log) + else: + write_log() def on_sales_invoice_submit(doc, method): @@ -175,6 +182,7 @@ def on_sales_invoice_submit(doc, method): "info", "referral_invoice.created", doc, + after_commit=True, referrer_row=row_index, supplier=supplier, percentage=percentage, @@ -186,6 +194,7 @@ def on_sales_invoice_submit(doc, method): "info", "referral_invoice.processing_completed", doc, + after_commit=True, created_count=len(created_pis), created_purchase_invoices=created_pis, ) @@ -233,6 +242,7 @@ def on_sales_invoice_cancel(doc, method): "info", "referral_invoice.cancel_cleanup_completed", doc, + after_commit=True, deleted_draft_purchase_invoices=draft_pis, submitted_purchase_invoices_requiring_manual_cancellation=submitted_pis, ) diff --git a/referral_fee/referral_fee/test_referral_utils.py b/referral_fee/referral_fee/test_referral_utils.py index b1d2401..c12ed6c 100644 --- a/referral_fee/referral_fee/test_referral_utils.py +++ b/referral_fee/referral_fee/test_referral_utils.py @@ -32,6 +32,7 @@ def test_logs_missing_project_skip_reason(self, get_doc, log_info): self.assertEqual(entries[-1]["reason"], "missing_project") @patch.object(referral_utils.logger, "info") + @patch.object(frappe.db.after_commit, "add") @patch.object(referral_utils, "_make_purchase_invoice") @patch.object(frappe, "msgprint") @patch.object(frappe.db, "get_value", return_value=None) @@ -42,6 +43,7 @@ def test_logs_created_purchase_invoice( _get_value, _msgprint, make_purchase_invoice, + after_commit_add, log_info, ): get_doc.return_value = frappe._dict( @@ -66,6 +68,16 @@ def test_logs_created_purchase_invoice( make_purchase_invoice.assert_called_once_with( self.sales_invoice, "Test Supplier", 100.0 ) + immediate_entries = [call.args[0] for call in log_info.call_args_list] + self.assertNotIn( + "referral_invoice.created", + [entry["event"] for entry in immediate_entries], + ) + + self.assertEqual(after_commit_add.call_count, 2) + for call in after_commit_add.call_args_list: + call.args[0]() + entries = [call.args[0] for call in log_info.call_args_list] created = next( entry for entry in entries if entry["event"] == "referral_invoice.created" @@ -77,11 +89,16 @@ def test_logs_created_purchase_invoice( self.assertEqual(completed["created_count"], 1) @patch.object(referral_utils.logger, "info") + @patch.object( + frappe.db.after_commit, + "add", + side_effect=lambda callback: callback(), + ) @patch.object(referral_utils, "_make_purchase_invoice") @patch.object(frappe.db, "get_value", return_value="ACC-PINV-TEST-00001") @patch.object(frappe, "get_doc") def test_logs_duplicate_skip_reason( - self, get_doc, _get_value, make_purchase_invoice, log_info + self, get_doc, _get_value, make_purchase_invoice, _after_commit_add, log_info ): get_doc.return_value = frappe._dict( { From b9c9b704cdae5800bcc44bbcc1f30545410f318f Mon Sep 17 00:00:00 2001 From: Michael Wu Date: Tue, 22 Sep 2026 02:43:03 +0900 Subject: [PATCH 3/4] Enable referral audit info logs --- referral_fee/referral_fee/referral_utils.py | 3 +++ 1 file changed, 3 insertions(+) diff --git a/referral_fee/referral_fee/referral_utils.py b/referral_fee/referral_fee/referral_utils.py index de51b28..efcaac9 100644 --- a/referral_fee/referral_fee/referral_utils.py +++ b/referral_fee/referral_fee/referral_utils.py @@ -1,3 +1,5 @@ +import logging + import frappe from frappe import _ from frappe.utils import add_days, add_years, flt, getdate, today @@ -11,6 +13,7 @@ # intentionally separate from the general web log so a missing invoice can be # traced without reproducing the original Sales Invoice submission. logger = frappe.logger("referral_fee", allow_site=True, file_count=20) +logger.setLevel(logging.INFO) def _log_sales_invoice_event(level, event, doc, after_commit=False, **details): From 62a307fc7882db71c656de16b071626a7f704b2e Mon Sep 17 00:00:00 2001 From: Michael Wu Date: Fri, 25 Sep 2026 05:17:10 +0900 Subject: [PATCH 4/4] Resolve referral logger per site --- referral_fee/referral_fee/referral_utils.py | 13 ++++--- .../referral_fee/test_referral_utils.py | 37 +++++++++++++------ 2 files changed, 33 insertions(+), 17 deletions(-) diff --git a/referral_fee/referral_fee/referral_utils.py b/referral_fee/referral_fee/referral_utils.py index efcaac9..af93ad7 100644 --- a/referral_fee/referral_fee/referral_utils.py +++ b/referral_fee/referral_fee/referral_utils.py @@ -9,11 +9,12 @@ # Change this if Caleb decides to use a different item. REFERRAL_FEE_ITEM = "Internal Commission" -# Keep a dedicated, site-level audit trail for referral invoice decisions. This is -# intentionally separate from the general web log so a missing invoice can be -# traced without reproducing the original Sales Invoice submission. -logger = frappe.logger("referral_fee", allow_site=True, file_count=20) -logger.setLevel(logging.INFO) + +def _get_referral_logger(): + """Return the dedicated INFO-level audit logger for the current Frappe site.""" + event_logger = frappe.logger("referral_fee", allow_site=True, file_count=20) + event_logger.setLevel(logging.INFO) + return event_logger def _log_sales_invoice_event(level, event, doc, after_commit=False, **details): @@ -28,7 +29,7 @@ def _log_sales_invoice_event(level, event, doc, after_commit=False, **details): entry.update(details) def write_log(): - getattr(logger, level)(entry) + getattr(_get_referral_logger(), level)(entry) if after_commit: frappe.db.after_commit.add(write_log) diff --git a/referral_fee/referral_fee/test_referral_utils.py b/referral_fee/referral_fee/test_referral_utils.py index c12ed6c..83f6249 100644 --- a/referral_fee/referral_fee/test_referral_utils.py +++ b/referral_fee/referral_fee/test_referral_utils.py @@ -1,5 +1,6 @@ +import logging from unittest import TestCase -from unittest.mock import patch +from unittest.mock import call, patch import frappe @@ -19,19 +20,32 @@ def setUp(self): } ) - @patch.object(referral_utils.logger, "info") + @patch.object(frappe, "logger") @patch.object(frappe, "get_doc") - def test_logs_missing_project_skip_reason(self, get_doc, log_info): + def test_logs_missing_project_skip_reason(self, get_doc, get_logger): self.sales_invoice.project = None referral_utils.on_sales_invoice_submit(self.sales_invoice, "on_submit") get_doc.assert_not_called() + event_logger = get_logger.return_value + self.assertEqual( + get_logger.call_args_list, + [ + call("referral_fee", allow_site=True, file_count=20), + call("referral_fee", allow_site=True, file_count=20), + ], + ) + self.assertEqual( + event_logger.setLevel.call_args_list, + [call(logging.INFO), call(logging.INFO)], + ) + log_info = event_logger.info entries = [call.args[0] for call in log_info.call_args_list] self.assertEqual(entries[-1]["event"], "referral_invoice.skipped") self.assertEqual(entries[-1]["reason"], "missing_project") - @patch.object(referral_utils.logger, "info") + @patch.object(frappe, "logger") @patch.object(frappe.db.after_commit, "add") @patch.object(referral_utils, "_make_purchase_invoice") @patch.object(frappe, "msgprint") @@ -44,7 +58,7 @@ def test_logs_created_purchase_invoice( _msgprint, make_purchase_invoice, after_commit_add, - log_info, + get_logger, ): get_doc.return_value = frappe._dict( { @@ -68,6 +82,7 @@ def test_logs_created_purchase_invoice( make_purchase_invoice.assert_called_once_with( self.sales_invoice, "Test Supplier", 100.0 ) + log_info = get_logger.return_value.info immediate_entries = [call.args[0] for call in log_info.call_args_list] self.assertNotIn( "referral_invoice.created", @@ -88,7 +103,7 @@ def test_logs_created_purchase_invoice( self.assertEqual(completed["event"], "referral_invoice.processing_completed") self.assertEqual(completed["created_count"], 1) - @patch.object(referral_utils.logger, "info") + @patch.object(frappe, "logger") @patch.object( frappe.db.after_commit, "add", @@ -98,7 +113,7 @@ def test_logs_created_purchase_invoice( @patch.object(frappe.db, "get_value", return_value="ACC-PINV-TEST-00001") @patch.object(frappe, "get_doc") def test_logs_duplicate_skip_reason( - self, get_doc, _get_value, make_purchase_invoice, _after_commit_add, log_info + self, get_doc, _get_value, make_purchase_invoice, _after_commit_add, get_logger ): get_doc.return_value = frappe._dict( { @@ -117,6 +132,7 @@ def test_logs_duplicate_skip_reason( referral_utils.on_sales_invoice_submit(self.sales_invoice, "on_submit") make_purchase_invoice.assert_not_called() + log_info = get_logger.return_value.info entries = [call.args[0] for call in log_info.call_args_list] skipped = next( entry @@ -128,8 +144,7 @@ def test_logs_duplicate_skip_reason( skipped["existing_purchase_invoice"], "ACC-PINV-TEST-00001" ) - @patch.object(referral_utils.logger, "exception") - @patch.object(referral_utils.logger, "info") + @patch.object(frappe, "logger") @patch.object( referral_utils, "_make_purchase_invoice", @@ -142,8 +157,7 @@ def test_logs_and_reraises_creation_failure( get_doc, _get_value, _make_purchase_invoice, - _log_info, - log_exception, + get_logger, ): get_doc.return_value = frappe._dict( { @@ -162,6 +176,7 @@ def test_logs_and_reraises_creation_failure( with self.assertRaisesRegex(RuntimeError, "insert failed"): referral_utils.on_sales_invoice_submit(self.sales_invoice, "on_submit") + log_exception = get_logger.return_value.exception entry = log_exception.call_args.args[0] self.assertEqual(entry["event"], "referral_invoice.creation_failed") self.assertEqual(entry["supplier"], "Test Supplier")