NAMEX-PAY: "Duplicate payment already processed" message repeatedly appearing in logs

[eve-git]

In the Namex-Pay queue, the message "duplicate payment already processed" repeatedly appears in the logs. The referenced payment IDs are old (e.g., payments made in 2022) and are unrelated to Namex, such as PPR payments.

{"severity": "INFO", "message": "Incoming raw msg: b'{\"deliveryAttempt\":2,\"message\":{\"attributes\":{\"corp_type\":\"NRO\"},\"data\":\"eyJkYXRhIjogeyJpZCI6IDY1OTY5MDcsICJzdGF0dXNDb2RlIjogIkNPTVBMRVRFRCIsICJmaWxpbmdJZGVudGlmaWVyIjogbnVsbCwgImNvcnBUeXBlQ29kZSI6ICJOUk8ifSwgImRhdGFjb250ZW50dHlwZSI6ICJhcHBsaWNhdGlvbi9qc29uIiwgImlkIjogIjZkNWVjODY2LWFjZjktNDI3MS04NzVhLTdkMzE2OTM0NzUxMyIsICJzb3VyY2UiOiAic2JjLXBheS1QQVktQVBJIiwgInNwZWN2ZXJzaW9uIjogIjEuMCIsICJzdWJqZWN0IjogbnVsbCwgInRpbWUiOiAiMjAyNC0xMC0xNlQxODoyNzozMy43MDkxMTQrMDA6MDAiLCAidHlwZSI6ICJiYy5yZWdpc3RyeS5wYXltZW50In0=\",\"messageId\":\"12654719409927905\",\"message_id\":\"12654719409927905\",\"publishTime\":\"2024-10-16T18:27:33.749Z\",\"publish_time\":\"2024-10-16T18:27:33.749Z\"},\"subscription\":\"projects/gtksf3-prod/subscriptions/namex-pay-prod\"}\\n'", "component": "namex_pay.resources.worker.worker"}
{"severity": "INFO", "message": "received ce: SimpleCloudEvent(id='6d5ec866-acf9-4271-875a-7d3169347513', source='sbc-pay-PAY-API', subject=None, time='2024-10-16T18:27:33.709114+00:00', type='bc.registry.payment', data={'id': 6596907, 'statusCode': 'COMPLETED', 'filingIdentifier': None, 'corpTypeCode': 'NRO'})", "component": "namex_pay.resources.worker.worker"}
{"severity": "INFO", "message": "Incoming raw msg: Content-Type: application/json\r\nAuthorization: Bearer eyJhbGciOiJSUzI1NiIsImtpZCI6ImE1MGY2ZTcwZWY0YjU0OGE1ZmQ5MTQyZWVjZDFmYjhmNTRkY2U5ZWUiLCJ0eXAiOiJKV1QifQ.eyJhdWQiOiJodHRwczovL2djcC1uYW1leC1wYXktcHJvZC5hcHBzLnNpbHZlci5kZXZvcHMuZ292LmJjLmNhIiwiYXpwIjoiMTA0MzA5MzMwNzE3OTU2MTY3ODQ4IiwiZW1haWwiOiJzYS1wdWJzdWJAZ3Rrc2YzLXByb2QuaWFtLmdzZXJ2aWNlYWNjb3VudC5jb20iLCJlbWFpbF92ZXJpZmllZCI6dHJ1ZSwiZXhwIjoxNzI5MTA0NTk1LCJpYXQiOjE3MjkxMDA5OTUsImlzcyI6Imh0dHBzOi8vYWNjb3VudHMuZ29vZ2xlLmNvbSIsInN1YiI6IjEwNDMwOTMzMDcxNzk1NjE2Nzg0OCJ9.gNMZxWrh-hjGTPjxivyhAC5reHoZYnD-7T_lxQ0iS1Y2Pu6LiHpZci437ab3a6S1x0QSW167aLrqNRLgvZ4ZpkBdyxHHxiLyJ8O6fCLMEZDuanRxklLRLijb9slAb0YEiRwO339kXMi4dW7REzoZwbaywjtgppwNUNLwdzy9F_V8Z5g9wqpib1xJZXtb_lOVHzdFEPabJ-mgu9Va_7lUJhtcFDXIDgOgWfZWVjhoV1PRKvPgZftK_Epbm-FPGm_WU13XyBrAazEGN2j2rPLX7k-WtDZZ1t2p1gGP0BVISxPfPmnghOcZlATLwuPvCcW2VGXMynhuK5UDarODdBISsg\r\nContent-Length: 732\r\nAccept: application/json\r\nFrom: noreply@google.com\r\nUser-Agent: APIs-Google; (+https://developers.google.com/webmasters/APIs-Google.html)\r\nAccept-Encoding: gzip, deflate, br\r\nHost: gcp-namex-pay-prod.apps.silver.devops.gov.bc.ca\r\nX-Forwarded-Host: gcp-namex-pay-prod.apps.silver.devops.gov.bc.ca\r\nX-Forwarded-Port: 443\r\nX-Forwarded-Proto: https\r\nForwarded: for=66.249.84.228;host=gcp-namex-pay-prod.apps.silver.devops.gov.bc.ca;proto=https\r\nX-Forwarded-For: 66.249.84.228\r\n\r\n", "component": "namex_pay.resources.worker.worker"}
{"severity": "INFO", "message": "process namex payment for pay-id: 6596907", "component": "namex_pay.resources.worker.worker"}
{"severity": "DEBUG", "message": "entering process payment", "component": "namex_pay.resources.worker.process_payment"}
{"severity": "NOTICE", "message": "COMPLETED transaction on queue:PaymentToken(id=6596907, status_code='COMPLETED', filing_identifier=None, corp_type_code='NRO')", "component": "namex_pay.resources.worker.process_payment"}
{"severity": "NOTICE", "message": "Queue Issue: Duplicate, payment already processed for payment.id=504410", "component": "namex_pay.resources.worker.update_payment_record"}
{"severity": "NOTICE", "message": "Queue Issue: Duplicate, already furnished receipt for payment.id=504410", "component": "namex_pay.resources.worker.furnish_receipt_message"}
{"severity": "INFO", "message": "completed ce: SimpleCloudEvent(id='6d5ec866-acf9-4271-875a-7d3169347513', source='sbc-pay-PAY-API', subject=None, time='2024-10-16T18:27:33.709114+00:00', type='bc.registry.payment', data={'id': 6596907, 'statusCode': 'COMPLETED', 'filingIdentifier': None, 'corpTypeCode': 'NRO'})", "component": "namex_pay.resources.worker.worker"}

[eve-git]

It appears that namex.payments.id is being confused or mixed up with namex.payments.payment_id.

-- in namex-db
select * from payments where id = 504410;
--"id"  "payment_id"    "payment_completion_date"   "payment_status_code"   "nr_id" "payment_note"  "payment_action"    "furnished"
--504410    "6596907"   "2024-10-16 18:27:33.83831+00"  "COMPLETED" 2610548     "CREATE"    true
-------
-- in pay-db
-- select id, invoice_status_code, total, invoice_status_code, corp_type_code from invoices where id= 504410;
-- "id" "created_on"    "invoice_status_code"   "total" "invoice_status_code-2" "corp_type_code"
-- 504410   "2022-04-02 21:54:58.767989"    "PAID"  8.50    "PAID"  "PPR"

-- it makes sense using paymant_id in namex.payments table:
select id, created_on, invoice_status_code, total, invoice_status_code, corp_type_code from invoices where id= 6596907;
-- "id" "created_on"    "invoice_status_code"   "total" "invoice_status_code-2" "corp_type_code"
-- 6596907  "2024-10-16 18:27:33.269603"    "PAID"  31.50   "PAID"  "NRO"

[rarmitag]

That would be funny.

[rarmitag]

That shouldn't be too hard to find in code.

[eve-git]

In the message "Queue Issue: Duplicate, payment already processed for payment.id=504410", the payment.id means namex.payments.id instead of invoices.id or namex.payments.payment_id.