diff --git a/addons/payment/models/payment_transaction.py b/addons/payment/models/payment_transaction.py index 73a548eeb85..2f625bb0921 100644 --- a/addons/payment/models/payment_transaction.py +++ b/addons/payment/models/payment_transaction.py @@ -476,8 +476,9 @@ class PaymentTransaction(models.Model): # Complete generic processing values with acquirer-specific values processing_values.update(self._get_specific_processing_values(processing_values)) _logger.info( - "generic and acquirer-specific processing values for transaction with id %s:\n%s", - self.id, pprint.pformat(processing_values) + "generic and acquirer-specific processing values for transaction with reference " + "%(ref)s:\n%(values)s", + {'ref': self.reference, 'values': pprint.pformat(processing_values)}, ) # Render the html form for the redirect flow if available @@ -488,8 +489,9 @@ class PaymentTransaction(models.Model): if redirect_form_view: # Some acquirer don't need a redirect form rendering_values = self._get_specific_rendering_values(processing_values) _logger.info( - "acquirer-specific rendering values for transaction with id %s:\n%s", - self.id, pprint.pformat(rendering_values) + "acquirer-specific rendering values for transaction with reference " + "%(ref)s:\n%(values)s", + {'ref': self.reference, 'values': pprint.pformat(rendering_values)}, ) redirect_form_html = redirect_form_view._render(rendering_values, engine='ir.qweb') processing_values.update(redirect_form_html=redirect_form_html) @@ -735,20 +737,21 @@ class PaymentTransaction(models.Model): txs_to_process, txs_already_processed, txs_wrong_state = _classify_by_state(self) for tx in txs_already_processed: _logger.info( - "tried to write tx state with same value (ref: %s, state: %s)", - tx.reference, tx.state + "tried to write on transaction with reference %s with the same value for the " + "state: %s", + tx.reference, tx.state, ) for tx in txs_wrong_state: - logging_values = { - 'reference': tx.reference, - 'tx_state': tx.state, - 'target_state': target_state, - 'allowed_states': allowed_states, - } _logger.warning( - "tried to write tx state with illegal value (ref: %(reference)s, previous state " - "%(tx_state)s, target state: %(target_state)s, expected previous state to be in: " - "%(allowed_states)s)", logging_values + "tried to write on transaction with reference %(ref)s with illegal value for the " + "state (previous state: %(tx_state)s, target state: %(target_state)s, expected " + "previous state to be in: %(allowed_states)s)", + { + 'ref': tx.reference, + 'tx_state': tx.state, + 'target_state': target_state, + 'allowed_states': allowed_states, + }, ) txs_to_process.write({ 'state': target_state, @@ -781,19 +784,21 @@ class PaymentTransaction(models.Model): valid_callback_hash = self._generate_callback_hash(model_sudo.id, res_id, method) if not consteq(ustr(valid_callback_hash), callback_hash): - _logger.warning("invalid callback signature for transaction with id %s", tx.id) + _logger.warning( + "invalid callback signature for transaction with reference %s", tx.reference + ) continue # Ignore tampered callbacks record = self.env[model_sudo.model].browse(res_id).exists() if not record: - logging_values = { - 'model': model_sudo.model, - 'record_id': res_id, - 'tx_id': tx.id, - } _logger.warning( - "invalid callback record %(model)s.%(record_id)s for transaction with id " - "%(tx_id)s", logging_values + "invalid callback record %(model)s.%(record_id)s for transaction with " + "reference %(ref)s", + { + 'model': model_sudo.model, + 'record_id': res_id, + 'ref': tx.reference, + } ) continue # Ignore invalidated callbacks @@ -838,8 +843,8 @@ class PaymentTransaction(models.Model): 'landing_route': self.landing_route, } _logger.debug( - "post-processing values for acquirer with id %s:\n%s", - self.acquirer_id.id, pprint.pformat(post_processing_values) + "post-processing values of transaction with reference %s for acquirer with id %s:\n%s", + self.reference, self.acquirer_id.id, pprint.pformat(post_processing_values) ) # DEBUG level because this can get spammy with transactions in non-final states return post_processing_values @@ -879,8 +884,8 @@ class PaymentTransaction(models.Model): self.env.cr.rollback() # Rollback and try later except Exception as e: _logger.exception( - "encountered an error while post-processing transaction with id %s:\n%s", - tx.id, e + "encountered an error while post-processing transaction with reference %s:\n%s", + tx.reference, e ) self.env.cr.rollback() diff --git a/addons/payment_adyen/controllers/main.py b/addons/payment_adyen/controllers/main.py index 1dadf17c480..f2b6b63cc49 100644 --- a/addons/payment_adyen/controllers/main.py +++ b/addons/payment_adyen/controllers/main.py @@ -143,7 +143,10 @@ class AdyenController(http.Controller): ) # Handle the payment request response - _logger.info("payment request response:\n%s", pprint.pformat(response_content)) + _logger.info( + "payment request response for transaction with reference %s:\n%s", + reference, pprint.pformat(response_content) + ) request.env['payment.transaction'].sudo()._handle_feedback_data( 'adyen', dict(response_content, merchantReference=reference), # Match the transaction ) @@ -172,7 +175,10 @@ class AdyenController(http.Controller): ) # Handle the payment details request response - _logger.info("payment details request response:\n%s", pprint.pformat(response_content)) + _logger.info( + "payment details request response for transaction with reference %s:\n%s", + reference, pprint.pformat(response_content) + ) request.env['payment.transaction'].sudo()._handle_feedback_data( 'adyen', dict(response_content, merchantReference=reference), # Match the transaction ) @@ -206,7 +212,10 @@ class AdyenController(http.Controller): tx_sudo.operation = 'online_redirect' # Query and process the result of the additional actions that have been performed - _logger.info("handling redirection from Adyen with data:\n%s", pprint.pformat(data)) + _logger.info( + "handling redirection from Adyen for transaction with reference %s with data:\n%s", + tx_sudo.reference, pprint.pformat(data) + ) self.adyen_payment_details( tx_sudo.acquirer_id.id, data['merchantReference'], @@ -238,9 +247,11 @@ class AdyenController(http.Controller): received_signature = notification_data.get('additionalData', {}).get('hmacSignature') PaymentTransaction = request.env['payment.transaction'] try: - acquirer_sudo = PaymentTransaction.sudo()._get_tx_from_feedback_data( + tx_sudo = PaymentTransaction.sudo()._get_tx_from_feedback_data( 'adyen', notification_data - ).acquirer_id # Find the acquirer based on the transaction + ) + acquirer_sudo = tx_sudo.acquirer_id # Find the acquirer based on the transaction + if not self._verify_notification_signature( received_signature, notification_data, acquirer_sudo.adyen_hmac_key ): @@ -248,7 +259,11 @@ class AdyenController(http.Controller): # Check whether the event of the notification succeeded and reshape the notification # data for parsing - _logger.info("notification received:\n%s", pprint.pformat(notification_data)) + _logger.info( + "notification received from Adyen for transaction with reference %s with " + "data:\n%s", + tx_sudo.reference, pprint.pformat(notification_data) + ) success = notification_data['success'] == 'true' event_code = notification_data['eventCode'] if event_code == 'AUTHORISATION' and success: diff --git a/addons/payment_adyen/models/payment_transaction.py b/addons/payment_adyen/models/payment_transaction.py index 5027f6aa212..a3f7e78e55e 100644 --- a/addons/payment_adyen/models/payment_transaction.py +++ b/addons/payment_adyen/models/payment_transaction.py @@ -84,7 +84,10 @@ class PaymentTransaction(models.Model): ) # Handle the payment request response - _logger.info("payment request response:\n%s", pprint.pformat(response_content)) + _logger.info( + "payment request response for transaction with reference %s:\n%s", + self.reference, pprint.pformat(response_content) + ) self._handle_feedback_data('adyen', response_content) def _send_refund_request(self, amount_to_refund=None, create_refund_transaction=True): @@ -127,7 +130,10 @@ class PaymentTransaction(models.Model): payload=data, method='POST' ) - _logger.info("refund request response:\n%s", pprint.pformat(response_content)) + _logger.info( + "refund request response for transaction with reference %s:\n%s", + self.reference, pprint.pformat(response_content) + ) # Handle the refund request response psp_reference = response_content.get('pspReference') @@ -232,21 +238,30 @@ class PaymentTransaction(models.Model): if self.operation == 'refund': self.env.ref('payment.cron_post_process_payment_tx')._trigger() elif payment_state in RESULT_CODES_MAPPING['cancel']: - _logger.warning("The transaction with reference %s was cancelled (reason: %s)", - self.reference, refusal_reason) + _logger.warning( + "the transaction with reference %s was cancelled. reason: %s", + self.reference, refusal_reason + ) self._set_canceled() elif payment_state in RESULT_CODES_MAPPING['error']: - _logger.warning("An error occurred on transaction with reference %s (reason: %s)", - self.reference, refusal_reason) + _logger.warning( + "the transaction with reference %s underwent an error. reason: %s", + self.reference, refusal_reason + ) self._set_error( _("An error occurred during the processing of your payment. Please try again.") ) elif payment_state in RESULT_CODES_MAPPING['refused']: - _logger.warning("The transaction with reference %s was refused (reason: %s)", - self.reference, refusal_reason) + _logger.warning( + "the transaction with reference %s was refused. reason: %s", + self.reference, refusal_reason + ) self._set_error(_("Your payment was refused. Please try again.")) else: # Classify unsupported payment state as `error` tx state - _logger.warning("received data with invalid payment state: %s", payment_state) + _logger.warning( + "received data for transaction with reference %s with invalid payment state: %s", + self.reference, payment_state + ) self._set_error( "Adyen: " + _("Received data with invalid payment state: %s", payment_state) ) @@ -274,5 +289,11 @@ class PaymentTransaction(models.Model): 'tokenize': False, }) _logger.info( - "created token with id %s for partner with id %s", token.id, self.partner_id.id + "created token with id %(token_id)s for partner with id %(partner_id)s from " + "transaction with reference %(ref)s", + { + 'token_id': token.id, + 'partner_id': self.partner_id.id, + 'ref': self.reference, + }, ) diff --git a/addons/payment_alipay/controllers/main.py b/addons/payment_alipay/controllers/main.py index 8bf61970783..63cd0ca47d7 100644 --- a/addons/payment_alipay/controllers/main.py +++ b/addons/payment_alipay/controllers/main.py @@ -19,14 +19,14 @@ class AlipayController(http.Controller): @http.route(_return_url, type='http', auth="public", methods=['GET']) def alipay_return_from_redirect(self, **data): """ Alipay return """ - _logger.info("received Alipay return data:\n%s", pprint.pformat(data)) + _logger.info("handling redirection from Alipay with data:\n%s", pprint.pformat(data)) request.env['payment.transaction'].sudo()._handle_feedback_data('alipay', data) return request.redirect('/payment/status') @http.route(_notify_url, type='http', auth='public', methods=['POST'], csrf=False) def alipay_notify(self, **post): """ Alipay Notify """ - _logger.info("received Alipay notification data:\n%s", pprint.pformat(post)) + _logger.info("notification received from Alipay with data:\n%s", pprint.pformat(post)) self._alipay_validate_notification(**post) request.env['payment.transaction'].sudo()._handle_feedback_data('alipay', post) return 'success' # Return 'success' to stop receiving notifications for this tx diff --git a/addons/payment_alipay/models/payment_transaction.py b/addons/payment_alipay/models/payment_transaction.py index 77b72ec0c69..85742203099 100644 --- a/addons/payment_alipay/models/payment_transaction.py +++ b/addons/payment_alipay/models/payment_transaction.py @@ -126,15 +126,15 @@ class PaymentTransaction(models.Model): if float_compare(float(data.get('total_fee', '0.0')), (self.amount + self.fees), 2) != 0: # mc_gross is amount + fees - logging_values = { - 'amount': data.get('total_fee', '0.0'), - 'total': self.amount, - 'fees': self.fees, - 'reference': self.reference, - } _logger.error( "the paid amount (%(amount)s) does not match the total + fees (%(total)s + " - "%(fees)s) for the transaction with reference %(reference)s", logging_values + "%(fees)s) for transaction with reference %(ref)s", + { + 'amount': data.get('total_fee', '0.0'), + 'total': self.amount, + 'fees': self.fees, + 'ref': self.reference, + } ) raise ValidationError("Alipay: " + _("The amount does not match the total + fees.")) if self.acquirer_id.alipay_payment_method == 'standard_checkout': @@ -147,8 +147,13 @@ class PaymentTransaction(models.Model): ) elif data.get('seller_email') != self.acquirer_id.alipay_seller_email: _logger.error( - "the seller email (%s) does not match the configured Alipay account (%s).", - data.get('seller_email'), self.acquirer_id.alipay_seller_email + "the seller email (%(email)s) does not match the configured Alipay account " + "(%(acc_email)s) for transaction with reference %(ref)s", + { + 'email': data.get('seller_email'), + 'acc_email:': self.acquirer_id.alipay_seller_email, + 'ref': self.reference, + }, ) raise ValidationError( "Alipay: " + _("The seller email does not match the configured Alipay account.") @@ -162,7 +167,7 @@ class PaymentTransaction(models.Model): self._set_canceled() else: _logger.info( - "received invalid transaction status for transaction with reference %s: %s", - self.reference, status + "received data with invalid payment status (%s) for transaction with reference %s", + status, self.reference, ) self._set_error("Alipay: " + _("received invalid transaction status: %s", status)) diff --git a/addons/payment_authorize/controllers/main.py b/addons/payment_authorize/controllers/main.py index 461396e05a5..ffca19deb36 100644 --- a/addons/payment_authorize/controllers/main.py +++ b/addons/payment_authorize/controllers/main.py @@ -52,7 +52,10 @@ class AuthorizeController(http.Controller): response_content = tx_sudo._authorize_create_transaction_request(opaque_data) # Handle the payment request response - _logger.info("make payment response:\n%s", pprint.pformat(response_content)) + _logger.info( + "payment request response for transaction with reference %s:\n%s", + reference, pprint.pformat(response_content) + ) # As the API has no redirection flow, we always know the reference of the transaction. # Still, we prefer to simulate the matching of the transaction by crafting dummy feedback # data in order to go through the centralized `_handle_feedback_data` method. diff --git a/addons/payment_authorize/models/authorize_request.py b/addons/payment_authorize/models/authorize_request.py index 55978d2817f..d09c93ba41e 100644 --- a/addons/payment_authorize/models/authorize_request.py +++ b/addons/payment_authorize/models/authorize_request.py @@ -109,8 +109,12 @@ class AuthorizeAPI: if not response.get('customerProfileId'): _logger.warning( - 'Unable to create customer payment profile, data missing from transaction. Transaction_id: %s - Partner_id: %s', - transaction_id, partner, + "unable to create customer payment profile, data missing from transaction with " + "id %(tx_id)s, partner id: %(partner_id)s", + { + 'tx_id': transaction_id, + 'partner_id': partner, + }, ) return False diff --git a/addons/payment_authorize/models/payment_transaction.py b/addons/payment_authorize/models/payment_transaction.py index f224fef623a..7f68f2bd296 100644 --- a/addons/payment_authorize/models/payment_transaction.py +++ b/addons/payment_authorize/models/payment_transaction.py @@ -68,10 +68,16 @@ class PaymentTransaction(models.Model): authorize_API = AuthorizeAPI(self.acquirer_id) if self.acquirer_id.capture_manually: res_content = authorize_API.authorize(self, token=self.token_id) - _logger.info("authorize request response:\n%s", pprint.pformat(res_content)) + _logger.info( + "authorize request response for transaction with reference %s:\n%s", + self.reference, pprint.pformat(res_content) + ) else: res_content = authorize_API.auth_and_capture(self, token=self.token_id) - _logger.info("auth_and_capture request response:\n%s", pprint.pformat(res_content)) + _logger.info( + "auth_and_capture request response for transaction with reference %s:\n%s", + self.reference, pprint.pformat(res_content) + ) # As the API has no redirection flow, we always know the reference of the transaction. # Still, we prefer to simulate the matching of the transaction by crafting dummy feedback @@ -102,7 +108,10 @@ class PaymentTransaction(models.Model): authorize_API = AuthorizeAPI(self.acquirer_id) rounded_amount = round(self.amount, self.currency_id.decimal_places) res_content = authorize_API.refund(self.acquirer_reference, rounded_amount) - _logger.info("refund request response:\n%s", pprint.pformat(res_content)) + _logger.info( + "refund request response for transaction with reference %s:\n%s", + self.reference, pprint.pformat(res_content) + ) # As the API has no redirection flow, we always know the reference of the transaction. # Still, we prefer to simulate the matching of the transaction by crafting dummy feedback # data in order to go through the centralized `_handle_feedback_data` method. @@ -125,7 +134,10 @@ class PaymentTransaction(models.Model): authorize_API = AuthorizeAPI(self.acquirer_id) rounded_amount = round(self.amount, self.currency_id.decimal_places) res_content = authorize_API.capture(self.acquirer_reference, rounded_amount) - _logger.info("capture request response:\n%s", pprint.pformat(res_content)) + _logger.info( + "capture request response for transaction with reference %s:\n%s", + self.reference, pprint.pformat(res_content) + ) # As the API has no redirection flow, we always know the reference of the transaction. # Still, we prefer to simulate the matching of the transaction by crafting dummy feedback # data in order to go through the centralized `_handle_feedback_data` method. @@ -145,7 +157,10 @@ class PaymentTransaction(models.Model): authorize_API = AuthorizeAPI(self.acquirer_id) res_content = authorize_API.void(self.acquirer_reference) - _logger.info("void request response:\n%s", pprint.pformat(res_content)) + _logger.info( + "void request response for transaction with reference %s:\n%s", + self.reference, pprint.pformat(res_content) + ) # As the API has no redirection flow, we always know the reference of the transaction. # Still, we prefer to simulate the matching of the transaction by crafting dummy feedback # data in order to go through the centralized `_handle_feedback_data` method. @@ -214,8 +229,13 @@ class PaymentTransaction(models.Model): else: # Error / Unknown code error_code = response_content.get('x_response_reason_text') _logger.info( - "received data with invalid status code %s and error code %s", - status_code, error_code + "received data with invalid status (%(status)s) and error code (%(err)s) for " + "transaction with reference %(ref)s", + { + 'status': status_code, + 'err': error_code, + 'ref': self.reference, + }, ) self._set_error( "Authorize.Net: " + _( @@ -237,7 +257,10 @@ class PaymentTransaction(models.Model): cust_profile = authorize_API.create_customer_profile( self.partner_id, self.acquirer_reference ) - _logger.info("create_customer_profile request response:\n%s", pprint.pformat(cust_profile)) + _logger.info( + "create_customer_profile request response for transaction with reference %s:\n%s", + self.reference, pprint.pformat(cust_profile) + ) if cust_profile: token = self.env['payment.token'].create({ 'acquirer_id': self.acquirer_id.id, @@ -253,5 +276,11 @@ class PaymentTransaction(models.Model): 'tokenize': False, }) _logger.info( - "created token with id %s for partner with id %s", token.id, self.partner_id.id + "created token with id %(token_id)s for partner with id %(partner_id)s from " + "transaction with reference %(ref)s", + { + 'token_id': token.id, + 'partner_id': self.partner_id.id, + 'ref': self.reference, + }, ) diff --git a/addons/payment_buckaroo/controllers/main.py b/addons/payment_buckaroo/controllers/main.py index e7074267b59..de30cbb824d 100644 --- a/addons/payment_buckaroo/controllers/main.py +++ b/addons/payment_buckaroo/controllers/main.py @@ -18,6 +18,6 @@ class BuckarooController(http.Controller): :param dict data: The feedback data """ - _logger.info("received notification data:\n%s", pprint.pformat(data)) + _logger.info("handling redirection from Buckaroo with data:\n%s", pprint.pformat(data)) request.env['payment.transaction'].sudo()._handle_feedback_data('buckaroo', data) return request.redirect('/payment/status') diff --git a/addons/payment_buckaroo/models/payment_transaction.py b/addons/payment_buckaroo/models/payment_transaction.py index 56ebbaf8d83..fc782981200 100644 --- a/addons/payment_buckaroo/models/payment_transaction.py +++ b/addons/payment_buckaroo/models/payment_transaction.py @@ -140,5 +140,8 @@ class PaymentTransaction(models.Model): elif status_code in STATUS_CODES_MAPPING['error']: self._set_error(_("An error occurred during processing of your payment (code %s). Please try again.", status_code)) else: - _logger.warning("Buckaroo: received unknown status code: %s", status_code) + _logger.warning( + "received data with invalid payment status (%s) for transaction with reference %s", + status_code, self.reference + ) self._set_error("Buckaroo: " + _("Unknown status code: %s", status_code)) diff --git a/addons/payment_mollie/controllers/main.py b/addons/payment_mollie/controllers/main.py index 124d534415f..30da4183510 100755 --- a/addons/payment_mollie/controllers/main.py +++ b/addons/payment_mollie/controllers/main.py @@ -33,7 +33,7 @@ class MollieController(http.Controller): :param dict data: The feedback data (only `id`) and the transaction reference (`ref`) embedded in the return URL """ - _logger.info("Received Mollie return data:\n%s", pprint.pformat(data)) + _logger.info("handling redirection from Mollie with data:\n%s", pprint.pformat(data)) request.env['payment.transaction'].sudo()._handle_feedback_data('mollie', data) return request.redirect('/payment/status') @@ -46,9 +46,9 @@ class MollieController(http.Controller): :return: An empty string to acknowledge the notification :rtype: str """ - _logger.info("Received Mollie notify data:\n%s", pprint.pformat(data)) + _logger.info("notification received from Mollie with data:\n%s", pprint.pformat(data)) try: request.env['payment.transaction'].sudo()._handle_feedback_data('mollie', data) except ValidationError: # Acknowledge the notification to avoid getting spammed - _logger.exception("unable to handle the notification data; skipping to acknowledge") + _logger.exception("unable to handle the data; skipping to acknowledge the notification") return '' # Acknowledge the notification with an HTTP 200 response diff --git a/addons/payment_mollie/models/payment_acquirer.py b/addons/payment_mollie/models/payment_acquirer.py index 4b88367897c..46192de0318 100755 --- a/addons/payment_mollie/models/payment_acquirer.py +++ b/addons/payment_mollie/models/payment_acquirer.py @@ -75,6 +75,6 @@ class PaymentAcquirer(models.Model): response = requests.request(method, url, json=data, headers=headers, timeout=60) response.raise_for_status() except requests.exceptions.RequestException: - _logger.exception("Unable to communicate with Mollie: %s", url) + _logger.exception("unable to communicate with Mollie: %s", url) raise ValidationError("Mollie: " + _("Could not establish the connection to the API.")) return response.json() diff --git a/addons/payment_mollie/models/payment_transaction.py b/addons/payment_mollie/models/payment_transaction.py index 501b30d6e2e..766bcc1e4da 100644 --- a/addons/payment_mollie/models/payment_transaction.py +++ b/addons/payment_mollie/models/payment_transaction.py @@ -112,7 +112,10 @@ class PaymentTransaction(models.Model): elif payment_status in ['expired', 'canceled', 'failed']: self._set_canceled("Mollie: " + _("Canceled payment with status: %s", payment_status)) else: - _logger.info("Received data with invalid payment status: %s", payment_status) + _logger.info( + "received data with invalid payment status (%s) for transaction with reference %s", + payment_status, self.reference + ) self._set_error( "Mollie: " + _("Received data with invalid payment status: %s", payment_status) ) diff --git a/addons/payment_ogone/controllers/main.py b/addons/payment_ogone/controllers/main.py index c74039c1e68..1d6feb0a525 100644 --- a/addons/payment_ogone/controllers/main.py +++ b/addons/payment_ogone/controllers/main.py @@ -42,7 +42,7 @@ class OgoneController(http.Controller): self._verify_signature(feedback_data, data) # Handle the feedback data - _logger.info("entering _handle_feedback_data with data:\n%s", pprint.pformat(data)) + _logger.info("handling redirection from Ogone with data:\n%s", pprint.pformat(data)) request.env['payment.transaction'].sudo()._handle_feedback_data('ogone', data) return request.redirect('/payment/status') diff --git a/addons/payment_ogone/models/payment_transaction.py b/addons/payment_ogone/models/payment_transaction.py index cce902281fa..604140947db 100644 --- a/addons/payment_ogone/models/payment_transaction.py +++ b/addons/payment_ogone/models/payment_transaction.py @@ -135,8 +135,8 @@ class PaymentTransaction(models.Model): data['SHASIGN'] = self.acquirer_id._ogone_generate_signature(data, incoming=False) _logger.info( - "making payment request:\n%s", - pprint.pformat({k: v for k, v in data.items() if k != 'PSWD'}) + "payment request response for transaction with reference %s:\n%s", + self.reference, pprint.pformat({k: v for k, v in data.items() if k != 'PSWD'}) ) # Log the payment request data without the password response_content = self.acquirer_id._ogone_make_request(data) try: @@ -146,11 +146,14 @@ class PaymentTransaction(models.Model): # Handle the feedback data _logger.info( - "received payment request response as an etree:\n%s", - etree.tostring(tree, pretty_print=True, encoding='utf-8') + "payment request response (as an etree) for transaction with reference %s:\n%s", + self.reference, etree.tostring(tree, pretty_print=True, encoding='utf-8') ) feedback_data = {'ORDERID': tree.get('orderID'), 'tree': tree} - _logger.info("entering _handle_feedback_data with data:\n%s", pprint.pformat(feedback_data)) + _logger.info( + "handling feedback data from Ogone for transaction with reference %s with data:\n%s", + self.reference, pprint.pformat(feedback_data) + ) self._handle_feedback_data('ogone', feedback_data) @api.model @@ -202,7 +205,10 @@ class PaymentTransaction(models.Model): elif payment_status in const.PAYMENT_STATUS_MAPPING['cancel']: self._set_canceled() else: # Classify unknown payment statuses as `error` tx state - _logger.info("received data with invalid payment status: %s", payment_status) + _logger.info( + "received data with invalid payment status (%s) for transaction with reference %s", + payment_status, self.reference + ) self._set_error( "Ogone: " + _("Received data with invalid payment status: %s", payment_status) ) @@ -226,5 +232,11 @@ class PaymentTransaction(models.Model): 'tokenize': False, }) _logger.info( - "created token with id %s for partner with id %s", token.id, self.partner_id.id + "created token with id %(token_id)s for partner with id %(partner_id)s from " + "transaction with reference %(ref)s", + { + 'token_id': token.id, + 'partner_id': self.partner_id.id, + 'ref': self.reference, + }, ) diff --git a/addons/payment_paypal/controllers/main.py b/addons/payment_paypal/controllers/main.py index 3da8c937e58..4d3d623fbbc 100644 --- a/addons/payment_paypal/controllers/main.py +++ b/addons/payment_paypal/controllers/main.py @@ -23,7 +23,7 @@ class PaypalController(http.Controller): The "PDT notification" is actually POST data sent along the user redirection. The route also allows the GET method in case the user clicks on "go back to merchant site". """ - _logger.info("beginning DPN with post data:\n%s", pprint.pformat(data)) + _logger.info("handling redirection from Ogone with data:\n%s", pprint.pformat(data)) try: self._validate_data_authenticity(**data) except ValidationError: @@ -38,12 +38,12 @@ class PaypalController(http.Controller): @http.route(_notify_url, type='http', auth='public', methods=['GET', 'POST'], csrf=False) def paypal_ipn(self, **data): """ Route used by the IPN. """ - _logger.info("beginning IPN with post data:\n%s", pprint.pformat(data)) + _logger.info("notification received from Ogone with data:\n%s", pprint.pformat(data)) try: self._validate_data_authenticity(**data) request.env['payment.transaction'].sudo()._handle_feedback_data('paypal', data) except ValidationError: # Acknowledge the notification to avoid getting spammed - _logger.exception("unable to handle the IPN data; skipping to acknowledge the notif") + _logger.exception("unable to handle the data; skipping to acknowledge the notification") return '' def _validate_data_authenticity(self, **data): diff --git a/addons/payment_paypal/models/payment_transaction.py b/addons/payment_paypal/models/payment_transaction.py index 8146e51ca56..cfb52eb92d9 100644 --- a/addons/payment_paypal/models/payment_transaction.py +++ b/addons/payment_paypal/models/payment_transaction.py @@ -120,7 +120,10 @@ class PaymentTransaction(models.Model): elif payment_status in PAYMENT_STATUS_MAPPING['cancel']: self._set_canceled() else: - _logger.info("received data with invalid payment status: %s", payment_status) + _logger.info( + "received data with invalid payment status (%s) for transaction with reference %s", + payment_status, self.reference + ) self._set_error( "PayPal: " + _("Received data with invalid payment status: %s", payment_status) ) diff --git a/addons/payment_payulatam/controllers/main.py b/addons/payment_payulatam/controllers/main.py index 97dd63a35fd..86e1d2d2be7 100644 --- a/addons/payment_payulatam/controllers/main.py +++ b/addons/payment_payulatam/controllers/main.py @@ -14,6 +14,6 @@ class PayuLatamController(http.Controller): @http.route(_return_url, type='http', auth='public', methods=['GET']) def payulatam_return(self, **data): - _logger.info("entering _handle_feedback_data with data:\n%s", pprint.pformat(data)) + _logger.info("handling redirection from PayU Latam with data:\n%s", pprint.pformat(data)) request.env['payment.transaction'].sudo()._handle_feedback_data('payulatam', data) return request.redirect('/payment/status') diff --git a/addons/payment_payulatam/models/payment_transaction.py b/addons/payment_payulatam/models/payment_transaction.py index 15ea8bb28cd..2f3589191f0 100644 --- a/addons/payment_payulatam/models/payment_transaction.py +++ b/addons/payment_payulatam/models/payment_transaction.py @@ -151,7 +151,7 @@ class PaymentTransaction(models.Model): self._set_canceled(state_message=state_message) else: _logger.warning( - "received unrecognized payment state %s for transaction with reference %s", + "received data with invalid payment status (%s) for transaction with reference %s", status, self.reference ) self._set_error("PayU Latam: " + _("Invalid payment status.")) diff --git a/addons/payment_payumoney/controllers/main.py b/addons/payment_payumoney/controllers/main.py index ef5e1679755..e0673673ddb 100644 --- a/addons/payment_payumoney/controllers/main.py +++ b/addons/payment_payumoney/controllers/main.py @@ -29,6 +29,6 @@ class PayUMoneyController(http.Controller): :param dict data: The feedback data to process """ - _logger.info("entering handle_feedback_data with data:\n%s", pprint.pformat(data)) + _logger.info("handling redirection from PayU money with data:\n%s", pprint.pformat(data)) request.env['payment.transaction'].sudo()._handle_feedback_data('payumoney', data) return request.redirect('/payment/status') diff --git a/addons/payment_sips/controllers/main.py b/addons/payment_sips/controllers/main.py index bf1ac86e98a..8e891cf3a14 100644 --- a/addons/payment_sips/controllers/main.py +++ b/addons/payment_sips/controllers/main.py @@ -31,7 +31,7 @@ class SipsController(http.Controller): :param dict post: The feedback data to process """ - _logger.info("beginning Sips DPN _handle_feedback_data with data %s", pprint.pformat(post)) + _logger.info("handling redirection from SIPS with data:\n%s", pprint.pformat(post)) try: if self._sips_validate_data(post): request.env['payment.transaction'].sudo()._handle_feedback_data('sips', post) @@ -42,12 +42,12 @@ class SipsController(http.Controller): @http.route(_notify_url, type='http', auth='public', methods=['POST'], csrf=False) def sips_ipn(self, **post): """ Sips IPN. """ - _logger.info("beginning Sips IPN _handle_feedback_data with data %s", pprint.pformat(post)) + _logger.info("notification received from SIPS with data:\n%s", pprint.pformat(post)) if not post: # SIPS sometimes sends empty notifications, the reason why is unclear but they tend to # pollute logs and do not provide any meaningful information; log as a warning instead # of a traceback. - _logger.warning("received empty notification; skip.") + _logger.warning("unable to handle the data; skipping to acknowledge the notification") else: try: if self._sips_validate_data(post): @@ -61,8 +61,15 @@ class SipsController(http.Controller): acquirer_sudo = tx_sudo.acquirer_id security = acquirer_sudo._sips_generate_shasign(post['Data']) if security == post['Seal']: - _logger.debug('validated data') + _logger.debug( + "authenticity of notification data verified for transaction with reference %s", + tx_sudo.reference + ) return True else: - _logger.warning('data are tampered') + _logger.warning( + "unable to verify the authenticity of notification data for transaction with " + "reference %s", + tx_sudo.reference, + ) return False diff --git a/addons/payment_sips/models/payment_transaction.py b/addons/payment_sips/models/payment_transaction.py index 139c2e7e1bc..ea0f8435d74 100644 --- a/addons/payment_sips/models/payment_transaction.py +++ b/addons/payment_sips/models/payment_transaction.py @@ -157,7 +157,13 @@ class PaymentTransaction(models.Model): status = "error" self._set_error(_("Unrecognized response received from the payment provider.")) _logger.info( - "ref: %s, got response [%s], set as '%s'.", self.reference, response_code, status + "received data with response %(response)s for transaction with reference %(ref)s, set " + "status as '%(status)s'", + { + 'response': response_code, + 'ref': self.reference, + 'status': status, + }, ) def _sips_data_to_object(self, data): diff --git a/addons/payment_stripe/controllers/main.py b/addons/payment_stripe/controllers/main.py index 152f8e67d8b..41fa1d16c34 100644 --- a/addons/payment_stripe/controllers/main.py +++ b/addons/payment_stripe/controllers/main.py @@ -115,7 +115,7 @@ class StripeController(http.Controller): # Handle the feedback data crafted with Stripe API objects as a regular feedback request.env['payment.transaction'].sudo()._handle_feedback_data('stripe', data) except ValidationError: # Acknowledge the notification to avoid getting spammed - _logger.exception("unable to handle the event data; skipping to acknowledge") + _logger.exception("unable to handle the data; skipping to acknowledge the notification") return '' @staticmethod diff --git a/addons/payment_stripe/models/payment_transaction.py b/addons/payment_stripe/models/payment_transaction.py index 97e0c7356f8..d4a148e2b7d 100644 --- a/addons/payment_stripe/models/payment_transaction.py +++ b/addons/payment_stripe/models/payment_transaction.py @@ -168,7 +168,10 @@ class PaymentTransaction(models.Model): payment_intent = self._stripe_create_payment_intent() feedback_data = {'reference': self.reference} StripeController._include_payment_intent_in_feedback_data(payment_intent, feedback_data) - _logger.info("entering _handle_feedback_data with data:\n%s", pprint.pformat(feedback_data)) + _logger.info( + "payment request response for transaction with reference %s:\n%s", + self.reference, pprint.pformat(feedback_data) + ) self._handle_feedback_data('stripe', feedback_data) def _stripe_create_payment_intent(self): @@ -273,7 +276,10 @@ class PaymentTransaction(models.Model): elif intent_status in INTENT_STATUS_MAPPING['cancel']: self._set_canceled() else: # Classify unknown intent statuses as `error` tx state - _logger.warning("received data with invalid intent status: %s", intent_status) + _logger.warning( + "received invalid payment status (%s) for transaction with reference %s", + intent_status, self.reference + ) self._set_error( "Stripe: " + _("Received data with invalid intent status: %s", intent_status) ) @@ -315,5 +321,11 @@ class PaymentTransaction(models.Model): 'tokenize': False, }) _logger.info( - "created token with id %s for partner with id %s", token.id, self.partner_id.id + "created token with id %(token_id)s for partner with id %(partner_id)s from " + "transaction with reference %(ref)s", + { + 'token_id': token.id, + 'partner_id': self.partner_id.id, + 'ref': self.reference, + }, ) diff --git a/addons/payment_transfer/controllers/main.py b/addons/payment_transfer/controllers/main.py index 01c4c5d270d..da89499d440 100644 --- a/addons/payment_transfer/controllers/main.py +++ b/addons/payment_transfer/controllers/main.py @@ -14,6 +14,6 @@ class TransferController(http.Controller): @http.route(_accept_url, type='http', auth='public', methods=['POST'], csrf=False) def transfer_form_feedback(self, **post): - _logger.info("beginning _handle_feedback_data with post data %s", pprint.pformat(post)) + _logger.info("handling redirection from Transfer with data:\n%s", pprint.pformat(post)) request.env['payment.transaction'].sudo()._handle_feedback_data('transfer', post) return request.redirect('/payment/status') diff --git a/addons/payment_transfer/models/payment_transaction.py b/addons/payment_transfer/models/payment_transaction.py index 470869c59c3..2b90272cf4d 100644 --- a/addons/payment_transfer/models/payment_transaction.py +++ b/addons/payment_transfer/models/payment_transaction.py @@ -66,7 +66,8 @@ class PaymentTransaction(models.Model): return _logger.info( - "validated transfer payment for tx with reference %s: set as pending", self.reference + "validated transfer payment for transaction with reference %s: set as pending", + self.reference ) self._set_pending()