search

frappe / erpnext

Free and Open Source Enterprise Resource Planning (ERP)
https://erpnext.com
GNU General Public License v3.0
21.96k stars 7.36k forks source link

Deadlock Issue in Custom Payment Reconciliation RQ Job for Bulk Transactions #44291

Open dipenf-sigzen opened 9 hours ago

dipenf-sigzen commented 9 hours ago

Information about bug

Description: We have implemented a custom RQ job function for payment reconciliation in ERPNext. The job is derived from the trigger_reconciliation_for_queued_docs function in erpnext/accounts/doctype/process_payment_reconciliation/process_payment_reconciliation.py. In our customization, we made minor modifications by commenting out the queue_size code to process all entries at once. Our goal is to reconcile all customer and supplier payments and invoices in a single run at 2:30 AM daily. While the process handles most of the workload efficiently, we encounter deadlock errors when reconciling high volumes of transactions. This typically occurs for 60–70 transactions, with 4–5 transactions encountering deadlock errors.

Error Details: Error Title: erpnext.accounts.doctype.process_payment_reconciliation.process_payment_reconciliation.fetch_and_allocate Traceback: sql Traceback (most recent call last): File "apps/frappe/frappe/utils/background_jobs.py", line 220, in execute_job retval = method(**kwargs) ... File "apps/frappe/frappe/database/database.py", line 240, in sql raise frappe.QueryDeadlockError(e) from e frappe.exceptions.QueryDeadlockError: (1213, 'Deadlock found when trying to get lock; try restarting transaction')

Relevant Context: We are using 2 workers in a single bench. The issue arises when the job processes entries in bulk, causing some transactions to fail due to deadlocks. The affected function is fetch_and_allocate, which leads to deadlocks while performing database operations (INSERT INTO or UPDATE queries) on tabProcess Payment Reconciliation Log Allocations.

Steps to Reproduce: Implement a custom RQ job similar to trigger_reconciliation_for_queued_docs. Process all Process Payment Reconciliation Doctype entries in a single run. Execute the job during high transaction loads. Observe the deadlock errors in the logs for a subset of transactions.

References: ERPNext Function: trigger_reconciliation_for_queued_docs File Path: erpnext/accounts/doctype/process_payment_reconciliation/process_payment_reconciliation.py

Module

accounts

Version

Environment Details: ERPNext Version: 15.34.0 Frappe Version: 15.39.2 Database: MariaDB Number of Workers: 2 Hosting: Digital Ocean

Installation method

manual install

Relevant log output / Stack trace / Full Error Message.

Traceback with variables (most recent call last):
  File "apps/frappe/frappe/utils/background_jobs.py", line 220, in execute_job
    retval = method(**kwargs)
      site = 'unitycement.sigzencloud.com'
      method = <function fetch_and_allocate at 0x7f819b9cc820>
      event = None
      job_name = 'process_ACC-PPR-74031_fetch_and_allocate'
      kwargs = {'doc': 'ACC-PPR-74031'}
      user = 'Administrator'
      is_async = True
      retry = 0
      retval = None
      method_name = 'erpnext.accounts.doctype.process_payment_reconciliation.process_payment_reconciliation.fetch_and_allocate'
      before_job_task = 'frappe.monitor.start'
  File "apps/erpnext/erpnext/accounts/doctype/process_payment_reconciliation/process_payment_reconciliation.py", line 366, in fetch_and_allocate
    reconcile_log.save()
      doc = 'ACC-PPR-74031'
      log = 'PPR-LOG-74062'
      reconcile_log = <ProcessPaymentReconciliationLog: PPR-LOG-74062>
      pr = <PaymentReconciliation: Payment Reconciliation>
      invoices = [{'name': None, 'owner': None, 'creation': None, 'modified': None, 'modified_by': None, 'docstatus': 0, 'idx': 1, 'invoice_type': 'Sales Invoice', 'invoice_number': 'PMC/24-25/5919', 'invoice_date': datetime.date(2024, 11, 18), 'amount': 128000.0, 'outstanding_amount': 0, 'currency': 'INR', 'exchange_rate': 1.0, 'parent': 'Payment Reconciliation', 'parentfield': 'invoices', 'parenttype': 'Payment Reconciliation', 'doctype': 'Payment Reconciliation Invoice', '__islocal': 1}, {'name': None, 'owner': None, 'creation': None, 'modified': None, 'modified_by': None, 'docstatus': 0, 'idx': 2, 'invoice_type': 'Sales Invoice', 'invoice_number': 'PMC/24-25/5920', 'invoice_date': datetime.date(2024, 11, 18), 'amount': 32000.0, 'outstanding_amount': 0, 'currency': 'INR', 'exchange_rate': 1.0, 'parent': 'Payment Reconciliation', 'parentfield': 'invoices', 'parenttype': 'Payment Reconciliation', 'doctype': 'Payment Reconciliation Invoice', '__islocal': 1}]
      payments = [{'name': None, 'owner': None, 'creation': None, 'modified': None, 'modified_by': None, 'docstatus': 0, 'idx': 1, 'reference_type': 'Payment Entry', 'reference_name': 'REC/24-25/2850', 'posting_date': datetime.date(2024, 11, 20), 'is_advance': None, 'reference_row': None, 'amount': 0.0, 'difference_amount': 0.0, 'remark': None, 'currency': 'INR', 'exchange_rate': 1.0, 'cost_center': None, 'parent': 'Payment Reconciliation', 'parentfield': 'payments', 'parenttype': 'Payment Reconciliation', 'doctype': 'Payment Reconciliation Payment', '__islocal': 1, 'unreconciled_amount': 160000.0}]
      x = <PaymentReconciliationAllocation: unsaved parent=Payment Reconciliation>
  File "apps/frappe/frappe/model/document.py", line 337, in save
    return self._save(*args, **kwargs)
      self = <ProcessPaymentReconciliationLog: PPR-LOG-74062>
      args = ()
      kwargs = {}
  File "apps/frappe/frappe/model/document.py", line 389, in _save
    self.update_children()
      self = <ProcessPaymentReconciliationLog: PPR-LOG-74062>
      ignore_permissions = None
      ignore_version = None
  File "apps/frappe/frappe/model/document.py", line 421, in update_children
    self.update_child_table(df.fieldname, df)
      self = <ProcessPaymentReconciliationLog: PPR-LOG-74062>
      df = <TableDocField: allocations parent=Process Payment Reconciliation Log>
  File "apps/frappe/frappe/model/document.py", line 453, in update_child_table
    d.db_update()
      self = <ProcessPaymentReconciliationLog: PPR-LOG-74062>
      fieldname = 'allocations'
      df = <TableDocField: allocations parent=Process Payment Reconciliation Log>
      all_rows = [<ProcessPaymentReconciliationLogAllocations: u63d2vbkmu parent=PPR-LOG-74062>, <ProcessPaymentReconciliationLogAllocations: u63d5ei5s6 parent=PPR-LOG-74062>]
      existing_row_names = []
      tbl = Table('tabProcess Payment Reconciliation Log Allocations')
      qry = DELETE FROM `tabProcess Payment Reconciliation Log Allocations` WHERE `parent`='PPR-LOG-74062' AND `parenttype`='Process Payment Reconciliation Log' AND `parentfield`='allocations'
      d = <ProcessPaymentReconciliationLogAllocations: u63d2vbkmu parent=PPR-LOG-74062>
  File "apps/frappe/frappe/model/base_document.py", line 590, in db_update
    self.db_insert()
      self = <ProcessPaymentReconciliationLogAllocations: u63d2vbkmu parent=PPR-LOG-74062>
  File "apps/frappe/frappe/model/base_document.py", line 550, in db_insert
    frappe.db.sql(
      self = <ProcessPaymentReconciliationLogAllocations: u63d2vbkmu parent=PPR-LOG-74062>
      ignore_if_duplicate = False
      conflict_handler = ''
      d = {'name': 'u63d2vbkmu', 'owner': 'Administrator', 'creation': '2024-11-21 02:35:57.251328', 'modified': '2024-11-21 02:36:06.095729', 'modified_by': 'Administrator', 'docstatus': 0, 'idx': 1, 'reference_type': 'Payment Entry', 'reference_name': 'REC/24-25/2850', 'reference_row': None, 'invoice_type': 'Sales Invoice', 'invoice_number': 'PMC/24-25/5919', 'allocated_amount': 128000.0, 'unreconciled_amount': 160000.0, 'amount': 160000.0, 'is_advance': None, 'difference_amount': 0.0, 'difference_account': 'Exchange Gain/Loss - PCPL', 'exchange_rate': 1.0, 'currency': 'INR', 'reconciled': 0, 'parent': 'PPR-LOG-74062', 'parentfield': 'allocations', 'parenttype': 'Process Payment Reconciliation Log'}
      columns = ['name', 'owner', 'creation', 'modified', 'modified_by', 'docstatus', 'idx', 'reference_type', 'reference_name', 'reference_row', 'invoice_type', 'invoice_number', 'allocated_amount', 'unreconciled_amount', 'amount', 'is_advance', 'difference_amount', 'difference_account', 'exchange_rate', 'currency', 'reconciled', 'parent', 'parentfield', 'parenttype']
  File "apps/frappe/frappe/database/database.py", line 240, in sql
    raise frappe.QueryDeadlockError(e) from e
      self = <frappe.database.mariadb.database.MariaDBDatabase object at 0x7f81a1b03b20>
      query = 'INSERT INTO `tabProcess Payment Reconciliation Log Allocations` (`name`, `owner`, `creation`, `modified`, `modified_by`, `docstatus`, `idx`, `reference_type`, `reference_name`, `reference_row`, `invoice_type`, `invoice_number`, `allocated_amount`, `unreconciled_amount`, `amount`, `is_advance`, `difference_amount`, `difference_account`, `exchange_rate`, `currency`, `reconciled`, `parent`, `parentfield`, `parenttype`)\n\t\t\t\t\tVALUES (%s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s)'
      values = ['u63d2vbkmu', 'Administrator', '2024-11-21 02:35:57.251328', '2024-11-21 02:36:06.095729', 'Administrator', 0, 1, 'Payment Entry', 'REC/24-25/2850', None, 'Sales Invoice', 'PMC/24-25/5919', 128000.0, 160000.0, 160000.0, None, 0.0, 'Exchange Gain/Loss - PCPL', 1.0, 'INR', 0, 'PPR-LOG-74062', 'allocations', 'Process Payment Reconciliation Log']
      as_dict = 0
      as_list = 0
      debug = False
      ignore_ddl = 0
      auto_commit = 0
      update = None
      explain = False
      run = True
      pluck = False
      as_iterator = False
      trace_id = None
frappe.exceptions.QueryDeadlockError: (1213, 'Deadlock found when trying to get lock; try restarting transaction')