Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Card matching query does not exist on Customer.add_card from stripe token from stripe checkout.js #1838

Closed
martinmain93 opened this issue Oct 31, 2022 · 14 comments
Labels

Comments

@martinmain93
Copy link

Describe the bug
I'm running an app which uses stripe checkout in the front end (Source imported from here https://checkout.stripe.com/v2/checkout.js ), in which the user enters their credit card information and then Stripe provides a token which is passed to our API for further processing. On our server we use DJstripe to create a customer and then call add_card with the token from the stripe checkout to add the user's card. Since upgrading to DJstripe 2.6.2 (Previously 2.5.1), we sometimes run into a djstripe.models.payment_methods.Card.DoesNotExist: Card matching query does not exist error when attempting to add the card. Before the upgrade our system has processed thousands of payments with this same set up with no issues. Typically we are seeing this problem in about 1 in 5 payment attempts.

From our server logs, I can see that when the error occurs, a number of webhooks are received and processed between the time that the add_card action is started and when the error trace is printed out. One of the webhooks being processed is started before the error trace, and completes after the error trace, so it really seems like some sort of race condition problem related to the webhooks. In some cases, the webhooks all complete without errors, and in other cases, the webhook handler also raises a similar Card.DoesNotExist error

Full trace:

[2022-10-31T01:49:00.948455283Z] app[web.1]: ERROR 2022-10-30 21:49:00,412 log 302 140720089622336 Internal Server Error: /subscribe/
[2022-10-31T01:49:00.948487892Z] app[web.1]: Traceback (most recent call last):
[2022-10-31T01:49:00.948493567Z] app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/djstripe/models/base.py", line 583, in _create_from_stripe_object
[2022-10-31T01:49:00.948498572Z] app[web.1]:     instance = cls.stripe_objects.get(id=id_)
[2022-10-31T01:49:00.948503185Z] app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/models/manager.py", line 85, in manager_method
[2022-10-31T01:49:00.948507907Z] app[web.1]:     return getattr(self.get_queryset(), name)(*args, **kwargs)
[2022-10-31T01:49:00.948512467Z] app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/models/query.py", line 435, in get
[2022-10-31T01:49:00.948516964Z] app[web.1]:     raise self.model.DoesNotExist(
[2022-10-31T01:49:00.948521326Z] app[web.1]: djstripe.models.payment_methods.Card.DoesNotExist: Card matching query does not exist.
[2022-10-31T01:49:00.948525947Z] app[web.1]: 
[2022-10-31T01:49:00.948530448Z] app[web.1]: During handling of the above exception, another exception occurred:
[2022-10-31T01:49:00.948535195Z] app[web.1]: 
[2022-10-31T01:49:00.948539640Z] app[web.1]: Traceback (most recent call last):
[2022-10-31T01:49:00.948544260Z] app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/backends/utils.py", line 84, in _execute
[2022-10-31T01:49:00.948549387Z] app[web.1]:     return self.cursor.execute(sql, params)
[2022-10-31T01:49:00.948553967Z] app[web.1]: psycopg2.errors.UniqueViolation: duplicate key value violates unique constraint "djstripe_card_stripe_id_1dd55072_uniq"
[2022-10-31T01:49:00.948558639Z] app[web.1]: DETAIL:  Key (id)=(card_1Lyn5mGRvRnAJwTxHV5AQTS7) already exists.
[2022-10-31T01:49:00.948563054Z] app[web.1]: 
[2022-10-31T01:49:00.948567452Z] app[web.1]: 
[2022-10-31T01:49:00.948571724Z] app[web.1]: The above exception was the direct cause of the following exception:
[2022-10-31T01:49:00.948576137Z] app[web.1]: 
[2022-10-31T01:49:00.948580371Z] app[web.1]: Traceback (most recent call last):
[2022-10-31T01:49:00.948584843Z] app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/djstripe/models/base.py", line 704, in _get_or_create_from_stripe_object
[2022-10-31T01:49:00.948589488Z] app[web.1]:     cls._create_from_stripe_object(
[2022-10-31T01:49:00.948594015Z] app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/djstripe/models/base.py", line 596, in _create_from_stripe_object
[2022-10-31T01:49:00.948598603Z] app[web.1]:     instance.save()
[2022-10-31T01:49:00.948603013Z] app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/models/base.py", line 739, in save
[2022-10-31T01:49:00.948607581Z] app[web.1]:     self.save_base(using=using, force_insert=force_insert,
[2022-10-31T01:49:00.948629782Z] app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/models/base.py", line 776, in save_base
[2022-10-31T01:49:00.948635021Z] app[web.1]:     updated = self._save_table(
[2022-10-31T01:49:00.948639363Z] app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/models/base.py", line 881, in _save_table
[2022-10-31T01:49:00.948644971Z] app[web.1]:     results = self._do_insert(cls._base_manager, using, fields, returning_fields, raw)
[2022-10-31T01:49:00.948649643Z] app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/models/base.py", line 919, in _do_insert
[2022-10-31T01:49:00.948654197Z] app[web.1]:     return manager._insert(
[2022-10-31T01:49:00.948658540Z] app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/models/manager.py", line 85, in manager_method
[2022-10-31T01:49:00.948663127Z] app[web.1]:     return getattr(self.get_queryset(), name)(*args, **kwargs)
[2022-10-31T01:49:00.948667512Z] app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/models/query.py", line 1270, in _insert
[2022-10-31T01:49:00.948672061Z] app[web.1]:     return query.get_compiler(using=using).execute_sql(returning_fields)
[2022-10-31T01:49:00.948676482Z] app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/cachalot/monkey_patch.py", line 37, in inner
[2022-10-31T01:49:00.948681022Z] app[web.1]:     return original(compiler, *args, **kwargs)
[2022-10-31T01:49:00.948685392Z] app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/cachalot/monkey_patch.py", line 113, in inner
[2022-10-31T01:49:00.948689919Z] app[web.1]:     return original(write_compiler, *args, **kwargs)
[2022-10-31T01:49:00.948694317Z] app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/models/sql/compiler.py", line 1416, in execute_sql
[2022-10-31T01:49:00.948698989Z] app[web.1]:     cursor.execute(sql, params)
[2022-10-31T01:49:00.948703350Z] app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/raven/contrib/django/client.py", line 127, in execute
[2022-10-31T01:49:00.948707898Z] app[web.1]:     return real_execute(self, sql, params)
[2022-10-31T01:49:00.948712411Z] app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/cachalot/monkey_patch.py", line 137, in inner
[2022-10-31T01:49:00.948717005Z] app[web.1]:     return original(cursor, sql, *args, **kwargs)
[2022-10-31T01:49:00.948721458Z] app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/backends/utils.py", line 66, in execute
[2022-10-31T01:49:00.948725997Z] app[web.1]:     return self._execute_with_wrappers(sql, params, many=False, executor=self._execute)
[2022-10-31T01:49:00.948730549Z] app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/backends/utils.py", line 75, in _execute_with_wrappers
[2022-10-31T01:49:00.948735119Z] app[web.1]:     return executor(sql, params, many, context)
[2022-10-31T01:49:00.948739492Z] app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/backends/utils.py", line 79, in _execute
[2022-10-31T01:49:00.948744007Z] app[web.1]:     with self.db.wrap_database_errors:
[2022-10-31T01:49:00.948748442Z] app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/utils.py", line 90, in __exit__
[2022-10-31T01:49:00.948757510Z] app[web.1]:     raise dj_exc_value.with_traceback(traceback) from exc_value
[2022-10-31T01:49:00.948762415Z] app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/backends/utils.py", line 84, in _execute
[2022-10-31T01:49:00.948893559Z] app[web.1]:     return self.cursor.execute(sql, params)
[2022-10-31T01:49:00.948912659Z] app[web.1]: django.db.utils.IntegrityError: duplicate key value violates unique constraint "djstripe_card_stripe_id_1dd55072_uniq"
[2022-10-31T01:49:00.948918328Z] app[web.1]: DETAIL:  Key (id)=(card_1Lyn5mGRvRnAJwTxHV5AQTS7) already exists.
[2022-10-31T01:49:00.948923122Z] app[web.1]: 
[2022-10-31T01:49:00.948927415Z] app[web.1]: 
[2022-10-31T01:49:00.948931693Z] app[web.1]: During handling of the above exception, another exception occurred:
[2022-10-31T01:49:00.948936130Z] app[web.1]: 
[2022-10-31T01:49:00.948940620Z] app[web.1]: Traceback (most recent call last):
[2022-10-31T01:49:00.948945372Z] app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/core/handlers/exception.py", line 47, in inner
[2022-10-31T01:49:00.948950138Z] app[web.1]:     response = get_response(request)
[2022-10-31T01:49:00.948954602Z] app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/core/handlers/base.py", line 181, in _get_response
[2022-10-31T01:49:00.948959230Z] app[web.1]:     response = wrapped_callback(request, *callback_args, **callback_kwargs)
[2022-10-31T01:49:00.948963812Z] app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/views/generic/base.py", line 70, in view
[2022-10-31T01:49:00.948968417Z] app[web.1]:     return self.dispatch(request, *args, **kwargs)
[2022-10-31T01:49:00.948972788Z] app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/views/generic/base.py", line 98, in dispatch
[2022-10-31T01:49:00.948977427Z] app[web.1]:     return handler(request, *args, **kwargs)
[2022-10-31T01:49:00.948981813Z] app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/views/generic/edit.py", line 142, in post
[2022-10-31T01:49:00.948986376Z] app[web.1]:     return self.form_valid(form)
[2022-10-31T01:49:00.948990764Z] app[web.1]:   File "/app/payment/views.py", line 534, in form_valid
[2022-10-31T01:49:00.948995282Z] app[web.1]:     user = form.create_customer()
[2022-10-31T01:49:00.948999722Z] app[web.1]:   File "/app/payment/forms.py", line 175, in create_customer
[2022-10-31T01:49:00.949004196Z] app[web.1]:     customer.add_card(self.cleaned_data.get('stripe_token'))
[2022-10-31T01:49:00.949008633Z] app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/djstripe/models/core.py", line 1029, in add_card
[2022-10-31T01:49:00.949013292Z] app[web.1]:     new_payment_method = DjstripePaymentMethod.from_stripe_object(
[2022-10-31T01:49:00.949017753Z] app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/djstripe/models/payment_methods.py", line 42, in from_stripe_object
[2022-10-31T01:49:00.949022310Z] app[web.1]:     model.sync_from_stripe_data(data)
[2022-10-31T01:49:00.949026708Z] app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/djstripe/models/base.py", line 946, in sync_from_stripe_data
[2022-10-31T01:49:00.949063242Z] app[web.1]:     instance, created = cls._get_or_create_from_stripe_object(
[2022-10-31T01:49:00.949069927Z] app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/djstripe/models/base.py", line 719, in _get_or_create_from_stripe_object
[2022-10-31T01:49:00.949074588Z] app[web.1]:     return cls.stripe_objects.get(id=id_), False
[2022-10-31T01:49:00.949079763Z] app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/models/manager.py", line 85, in manager_method
[2022-10-31T01:49:00.949084473Z] app[web.1]:     return getattr(self.get_queryset(), name)(*args, **kwargs)
[2022-10-31T01:49:00.949088916Z] app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/models/query.py", line 435, in get
[2022-10-31T01:49:00.949093398Z] app[web.1]:     raise self.model.DoesNotExist(
[2022-10-31T01:49:00.949097784Z] app[web.1]: djstripe.models.payment_methods.Card.DoesNotExist: Card matching query does not exist.

To Reproduce
I have been unable to reliably reproduce

Software versions

  • Dj-Stripe version: 2.6.2
  • Python version: 3.10.6
  • Django version: 3.2.15
  • Stripe API version: 2020-08-27
  • Database type and version: PostgreSQL 10.21
@jleclanche
Copy link
Member

Can you replicate this in 2.7.2?

@martinmain93
Copy link
Author

martinmain93 commented Nov 1, 2022

I'll try this and see if that works. I'll update soon

@martinmain93
Copy link
Author

@jleclanche Just updated to the latest version. I can confirm that the bug is still present. Still appears to be happening when the add card action is executing at the same time as a webhook is being received. The trace was slightly different this time, and appears to also include some webhook exceptions:

2022-11-04T10:14:58.257480928Z app[web.1]: DEBUG 2022-11-04 06:14:58,257 base 298 140276719904576 Sending message of length 17761 to https://sentry.io/api/132754/store/
2022-11-04T10:14:58.727740315Z app[web.1]: ERROR 2022-11-04 06:14:58,281 log 298 140276719904576 Internal Server Error: /subscribe/
2022-11-04T10:14:58.727770176Z app[web.1]: Traceback (most recent call last):
2022-11-04T10:14:58.727775386Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/djstripe/models/base.py", line 618, in _create_from_stripe_object
2022-11-04T10:14:58.727780484Z app[web.1]:     instance = cls.stripe_objects.get(id=id_)
2022-11-04T10:14:58.727785047Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/models/manager.py", line 85, in manager_method
2022-11-04T10:14:58.727789852Z app[web.1]:     return getattr(self.get_queryset(), name)(*args, **kwargs)
2022-11-04T10:14:58.727794412Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/models/query.py", line 435, in get
2022-11-04T10:14:58.727799267Z app[web.1]:     raise self.model.DoesNotExist(
2022-11-04T10:14:58.727803644Z app[web.1]: djstripe.models.payment_methods.Card.DoesNotExist: Card matching query does not exist.
2022-11-04T10:14:58.727808087Z app[web.1]: 
2022-11-04T10:14:58.727812302Z app[web.1]: During handling of the above exception, another exception occurred:
2022-11-04T10:14:58.727816804Z app[web.1]: 
2022-11-04T10:14:58.727821059Z app[web.1]: Traceback (most recent call last):
2022-11-04T10:14:58.727825397Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/backends/utils.py", line 84, in _execute
2022-11-04T10:14:58.727829951Z app[web.1]:     return self.cursor.execute(sql, params)
2022-11-04T10:14:58.727834395Z app[web.1]: psycopg2.errors.UniqueViolation: duplicate key value violates unique constraint "djstripe_card_stripe_id_1dd55072_uniq"
2022-11-04T10:14:58.727838976Z app[web.1]: DETAIL:  Key (id)=(card_1M0MvGGRvRnAJwTxObayP6uq) already exists.
2022-11-04T10:14:58.727843356Z app[web.1]: 
2022-11-04T10:14:58.727847563Z app[web.1]: 
2022-11-04T10:14:58.727851833Z app[web.1]: The above exception was the direct cause of the following exception:
2022-11-04T10:14:58.727856211Z app[web.1]: 
2022-11-04T10:14:58.727860490Z app[web.1]: Traceback (most recent call last):
2022-11-04T10:14:58.727887098Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/djstripe/models/base.py", line 737, in _get_or_create_from_stripe_object
2022-11-04T10:14:58.727891773Z app[web.1]:     cls._create_from_stripe_object(
2022-11-04T10:14:58.727896129Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/djstripe/models/base.py", line 633, in _create_from_stripe_object
2022-11-04T10:14:58.727916177Z app[web.1]:     instance.save()
2022-11-04T10:14:58.727921149Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/models/base.py", line 739, in save
2022-11-04T10:14:58.727925726Z app[web.1]:     self.save_base(using=using, force_insert=force_insert,
2022-11-04T10:14:58.727930094Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/models/base.py", line 776, in save_base
2022-11-04T10:14:58.727934659Z app[web.1]:     updated = self._save_table(
2022-11-04T10:14:58.727939000Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/models/base.py", line 881, in _save_table
2022-11-04T10:14:58.727945123Z app[web.1]:     results = self._do_insert(cls._base_manager, using, fields, returning_fields, raw)
2022-11-04T10:14:58.727949917Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/models/base.py", line 919, in _do_insert
2022-11-04T10:14:58.727954495Z app[web.1]:     return manager._insert(
2022-11-04T10:14:58.727958800Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/models/manager.py", line 85, in manager_method
2022-11-04T10:14:58.727963464Z app[web.1]:     return getattr(self.get_queryset(), name)(*args, **kwargs)
2022-11-04T10:14:58.727967847Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/models/query.py", line 1270, in _insert
2022-11-04T10:14:58.727972360Z app[web.1]:     return query.get_compiler(using=using).execute_sql(returning_fields)
2022-11-04T10:14:58.727976797Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/cachalot/monkey_patch.py", line 37, in inner
2022-11-04T10:14:58.727981439Z app[web.1]:     return original(compiler, *args, **kwargs)
2022-11-04T10:14:58.727985798Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/cachalot/monkey_patch.py", line 113, in inner
2022-11-04T10:14:58.727990302Z app[web.1]:     return original(write_compiler, *args, **kwargs)
2022-11-04T10:14:58.727994679Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/models/sql/compiler.py", line 1416, in execute_sql
2022-11-04T10:14:58.727999377Z app[web.1]:     cursor.execute(sql, params)
2022-11-04T10:14:58.728003691Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/raven/contrib/django/client.py", line 127, in execute
2022-11-04T10:14:58.728008198Z app[web.1]:     return real_execute(self, sql, params)
2022-11-04T10:14:58.728012538Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/cachalot/monkey_patch.py", line 137, in inner
2022-11-04T10:14:58.728017133Z app[web.1]:     return original(cursor, sql, *args, **kwargs)
2022-11-04T10:14:58.728021488Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/backends/utils.py", line 66, in execute
2022-11-04T10:14:58.728026002Z app[web.1]:     return self._execute_with_wrappers(sql, params, many=False, executor=self._execute)
2022-11-04T10:14:58.728049780Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/backends/utils.py", line 75, in _execute_with_wrappers
2022-11-04T10:14:58.728054498Z app[web.1]:     return executor(sql, params, many, context)
2022-11-04T10:14:58.728067173Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/backends/utils.py", line 79, in _execute
2022-11-04T10:14:58.728072090Z app[web.1]:     with self.db.wrap_database_errors:
2022-11-04T10:14:58.728076466Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/utils.py", line 90, in __exit__
2022-11-04T10:14:58.728081056Z app[web.1]:     raise dj_exc_value.with_traceback(traceback) from exc_value
2022-11-04T10:14:58.728085458Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/backends/utils.py", line 84, in _execute
2022-11-04T10:14:58.728505042Z app[web.1]:     return self.cursor.execute(sql, params)
2022-11-04T10:14:58.728521669Z app[web.1]: django.db.utils.IntegrityError: duplicate key value violates unique constraint "djstripe_card_stripe_id_1dd55072_uniq"
2022-11-04T10:14:58.728531764Z app[web.1]: DETAIL:  Key (id)=(card_1M0MvGGRvRnAJwTxObayP6uq) already exists.
2022-11-04T10:14:58.728536310Z app[web.1]: 
2022-11-04T10:14:58.728540535Z app[web.1]: 
2022-11-04T10:14:58.728544772Z app[web.1]: During handling of the above exception, another exception occurred:
2022-11-04T10:14:58.728549224Z app[web.1]: 
2022-11-04T10:14:58.728553390Z app[web.1]: Traceback (most recent call last):
2022-11-04T10:14:58.728571546Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/core/handlers/exception.py", line 47, in inner
2022-11-04T10:14:58.728595599Z app[web.1]:     response = get_response(request)
2022-11-04T10:14:58.728599963Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/core/handlers/base.py", line 181, in _get_response
2022-11-04T10:14:58.728611022Z app[web.1]:     response = wrapped_callback(request, *callback_args, **callback_kwargs)
2022-11-04T10:14:58.728615499Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/views/generic/base.py", line 70, in view
2022-11-04T10:14:58.728619998Z app[web.1]:     return self.dispatch(request, *args, **kwargs)
2022-11-04T10:14:58.728624291Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/views/generic/base.py", line 98, in dispatch
2022-11-04T10:14:58.728628736Z app[web.1]:     return handler(request, *args, **kwargs)
2022-11-04T10:14:58.728633071Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/views/generic/edit.py", line 142, in post
2022-11-04T10:14:58.728637544Z app[web.1]:     return self.form_valid(form)
2022-11-04T10:14:58.728641837Z app[web.1]:   File "/app/payment/views.py", line 535, in form_valid
2022-11-04T10:14:58.728646223Z app[web.1]:     user = form.create_customer()
2022-11-04T10:14:58.728650601Z app[web.1]:   File "/app/payment/forms.py", line 175, in create_customer
2022-11-04T10:14:58.728654973Z app[web.1]:     customer.add_card(self.cleaned_data.get('stripe_token'))
2022-11-04T10:14:58.728659305Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/djstripe/models/core.py", line 1052, in add_card
2022-11-04T10:14:58.728663769Z app[web.1]:     new_payment_method = DjstripePaymentMethod.from_stripe_object(
2022-11-04T10:14:58.728668220Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/djstripe/models/payment_methods.py", line 42, in from_stripe_object
2022-11-04T10:14:58.728681456Z app[web.1]:     model.sync_from_stripe_data(data)
2022-11-04T10:14:58.728686279Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/djstripe/models/base.py", line 1004, in sync_from_stripe_data
2022-11-04T10:14:58.728690849Z app[web.1]:     instance, created = cls._get_or_create_from_stripe_object(
2022-11-04T10:14:58.728695342Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/djstripe/models/base.py", line 753, in _get_or_create_from_stripe_object
2022-11-04T10:14:58.728699862Z app[web.1]:     return cls.stripe_objects.get(id=id_), False
2022-11-04T10:14:58.728704957Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/models/manager.py", line 85, in manager_method
2022-11-04T10:14:58.728709539Z app[web.1]:     return getattr(self.get_queryset(), name)(*args, **kwargs)
2022-11-04T10:14:58.728713959Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/models/query.py", line 435, in get
2022-11-04T10:14:58.728718437Z app[web.1]:     raise self.model.DoesNotExist(
2022-11-04T10:14:58.728722732Z app[web.1]: djstripe.models.payment_methods.Card.DoesNotExist: Card matching query does not exist.
2022-11-04T10:14:58.729243169Z app[web.1]: 172.17.0.1 - - [04/Nov/2022:06:14:58 -0400] "POST /subscribe/ HTTP/1.1" 500 7908 "https://app.studentevaluator.com/subscribe/" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/107.0.0.0 Safari/537.36"
2022-11-04T10:14:58.732323158Z app[web.1]: ERROR 2022-11-04 06:14:58,264 log 303 140276719904576 Internal Server Error: /subscriptions/webhook/
2022-11-04T10:14:58.732339973Z app[web.1]: Traceback (most recent call last):
2022-11-04T10:14:58.732345194Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/djstripe/models/base.py", line 618, in _create_from_stripe_object
2022-11-04T10:14:58.732350131Z app[web.1]:     instance = cls.stripe_objects.get(id=id_)
2022-11-04T10:14:58.732354735Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/models/manager.py", line 85, in manager_method
2022-11-04T10:14:58.732359469Z app[web.1]:     return getattr(self.get_queryset(), name)(*args, **kwargs)
2022-11-04T10:14:58.732363983Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/models/query.py", line 435, in get
2022-11-04T10:14:58.732368569Z app[web.1]:     raise self.model.DoesNotExist(
2022-11-04T10:14:58.732373038Z app[web.1]: djstripe.models.payment_methods.Card.DoesNotExist: Card matching query does not exist.
2022-11-04T10:14:58.732377590Z app[web.1]: 
2022-11-04T10:14:58.732381958Z app[web.1]: During handling of the above exception, another exception occurred:
2022-11-04T10:14:58.732386498Z app[web.1]: 
2022-11-04T10:14:58.732390796Z app[web.1]: Traceback (most recent call last):
2022-11-04T10:14:58.732395165Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/backends/utils.py", line 84, in _execute
2022-11-04T10:14:58.732399727Z app[web.1]:     return self.cursor.execute(sql, params)
2022-11-04T10:14:58.732404250Z app[web.1]: psycopg2.errors.UniqueViolation: duplicate key value violates unique constraint "djstripe_card_stripe_id_1dd55072_uniq"
2022-11-04T10:14:58.732419114Z app[web.1]: DETAIL:  Key (id)=(card_1M0MvGGRvRnAJwTxObayP6uq) already exists.
2022-11-04T10:14:58.732424135Z app[web.1]: 
2022-11-04T10:14:58.732428453Z app[web.1]: 
2022-11-04T10:14:58.732432663Z app[web.1]: The above exception was the direct cause of the following exception:
2022-11-04T10:14:58.732437054Z app[web.1]: 
2022-11-04T10:14:58.732441365Z app[web.1]: Traceback (most recent call last):
2022-11-04T10:14:58.732445779Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/djstripe/models/base.py", line 737, in _get_or_create_from_stripe_object
2022-11-04T10:14:58.732450334Z app[web.1]:     cls._create_from_stripe_object(
2022-11-04T10:14:58.732454674Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/djstripe/models/base.py", line 633, in _create_from_stripe_object
2022-11-04T10:14:58.732459333Z app[web.1]:     instance.save()
2022-11-04T10:14:58.732463646Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/models/base.py", line 739, in save
2022-11-04T10:14:58.732468184Z app[web.1]:     self.save_base(using=using, force_insert=force_insert,
2022-11-04T10:14:58.732472567Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/models/base.py", line 776, in save_base
2022-11-04T10:14:58.732477220Z app[web.1]:     updated = self._save_table(
2022-11-04T10:14:58.732481628Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/models/base.py", line 881, in _save_table
2022-11-04T10:14:58.732487009Z app[web.1]:     results = self._do_insert(cls._base_manager, using, fields, returning_fields, raw)
2022-11-04T10:14:58.732491606Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/models/base.py", line 919, in _do_insert
2022-11-04T10:14:58.732496260Z app[web.1]:     return manager._insert(
2022-11-04T10:14:58.732501027Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/models/manager.py", line 85, in manager_method
2022-11-04T10:14:58.732505935Z app[web.1]:     return getattr(self.get_queryset(), name)(*args, **kwargs)
2022-11-04T10:14:58.732510433Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/models/query.py", line 1270, in _insert
2022-11-04T10:14:58.732515230Z app[web.1]:     return query.get_compiler(using=using).execute_sql(returning_fields)
2022-11-04T10:14:58.732519713Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/cachalot/monkey_patch.py", line 37, in inner
2022-11-04T10:14:58.732524308Z app[web.1]:     return original(compiler, *args, **kwargs)
2022-11-04T10:14:58.732528692Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/cachalot/monkey_patch.py", line 113, in inner
2022-11-04T10:14:58.732533407Z app[web.1]:     return original(write_compiler, *args, **kwargs)
2022-11-04T10:14:58.732537768Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/models/sql/compiler.py", line 1416, in execute_sql
2022-11-04T10:14:58.732542405Z app[web.1]:     cursor.execute(sql, params)
2022-11-04T10:14:58.732546747Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/raven/contrib/django/client.py", line 127, in execute
2022-11-04T10:14:58.732555543Z app[web.1]:     return real_execute(self, sql, params)
2022-11-04T10:14:58.732560142Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/cachalot/monkey_patch.py", line 137, in inner
2022-11-04T10:14:58.732564806Z app[web.1]:     return original(cursor, sql, *args, **kwargs)
2022-11-04T10:14:58.732569180Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/backends/utils.py", line 66, in execute
2022-11-04T10:14:58.732573761Z app[web.1]:     return self._execute_with_wrappers(sql, params, many=False, executor=self._execute)
2022-11-04T10:14:58.732578312Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/backends/utils.py", line 75, in _execute_with_wrappers
2022-11-04T10:14:58.732582881Z app[web.1]:     return executor(sql, params, many, context)
2022-11-04T10:14:58.732587247Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/backends/utils.py", line 79, in _execute
2022-11-04T10:14:58.732591768Z app[web.1]:     with self.db.wrap_database_errors:
2022-11-04T10:14:58.732596157Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/utils.py", line 90, in __exit__
2022-11-04T10:14:58.732600645Z app[web.1]:     raise dj_exc_value.with_traceback(traceback) from exc_value
2022-11-04T10:14:58.732605366Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/backends/utils.py", line 84, in _execute
2022-11-04T10:14:58.732610036Z app[web.1]:     return self.cursor.execute(sql, params)
2022-11-04T10:14:58.732614396Z app[web.1]: django.db.utils.IntegrityError: duplicate key value violates unique constraint "djstripe_card_stripe_id_1dd55072_uniq"
2022-11-04T10:14:58.732618959Z app[web.1]: DETAIL:  Key (id)=(card_1M0MvGGRvRnAJwTxObayP6uq) already exists.
2022-11-04T10:14:58.732623449Z app[web.1]: 
2022-11-04T10:14:58.732627689Z app[web.1]: 
2022-11-04T10:14:58.732631921Z app[web.1]: During handling of the above exception, another exception occurred:
2022-11-04T10:14:58.732636328Z app[web.1]: 
2022-11-04T10:14:58.732640564Z app[web.1]: Traceback (most recent call last):
2022-11-04T10:14:58.732645080Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/core/handlers/exception.py", line 47, in inner
2022-11-04T10:14:58.732649603Z app[web.1]:     response = get_response(request)
2022-11-04T10:14:58.732653921Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/core/handlers/base.py", line 181, in _get_response
2022-11-04T10:14:58.732658467Z app[web.1]:     response = wrapped_callback(request, *callback_args, **callback_kwargs)
2022-11-04T10:14:58.732662858Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/views/generic/base.py", line 70, in view
2022-11-04T10:14:58.732667534Z app[web.1]:     return self.dispatch(request, *args, **kwargs)
2022-11-04T10:14:58.732671897Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/utils/decorators.py", line 43, in _wrapper
2022-11-04T10:14:58.732676543Z app[web.1]:     return bound_method(*args, **kwargs)
2022-11-04T10:14:58.732681083Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/views/decorators/csrf.py", line 54, in wrapped_view
2022-11-04T10:14:58.732689554Z app[web.1]:     return view_func(*args, **kwargs)
2022-11-04T10:14:58.732694136Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/views/generic/base.py", line 98, in dispatch
2022-11-04T10:14:58.732698697Z app[web.1]:     return handler(request, *args, **kwargs)
2022-11-04T10:14:58.732703083Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/djstripe/views.py", line 46, in post
2022-11-04T10:14:58.732707574Z app[web.1]:     trigger = WebhookEventTrigger.from_request(
2022-11-04T10:14:58.732711942Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/djstripe/models/webhooks.py", line 239, in from_request
2022-11-04T10:14:58.732716514Z app[web.1]:     raise e
2022-11-04T10:14:58.732720822Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/djstripe/models/webhooks.py", line 225, in from_request
2022-11-04T10:14:58.732725364Z app[web.1]:     obj.process(save=False, api_key=api_key)
2022-11-04T10:14:58.732729734Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/djstripe/models/webhooks.py", line 331, in process
2022-11-04T10:14:58.732734252Z app[web.1]:     self.event = Event.process(self.json_body, api_key=api_key)
2022-11-04T10:14:58.732738636Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/djstripe/models/core.py", line 1581, in process
2022-11-04T10:14:58.732743167Z app[web.1]:     ret.invoke_webhook_handlers()
2022-11-04T10:14:58.732747942Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/djstripe/models/core.py", line 1593, in invoke_webhook_handlers
2022-11-04T10:14:58.732752591Z app[web.1]:     webhooks.call_handlers(event=self)
2022-11-04T10:14:58.732756977Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/djstripe/webhooks.py", line 98, in call_handlers
2022-11-04T10:14:58.732761521Z app[web.1]:     handler_func(event=event)
2022-11-04T10:14:58.732766001Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/djstripe/event_handlers.py", line 141, in customer_source_webhook_handler
2022-11-04T10:14:58.732770670Z app[web.1]:     _handle_crud_like_event(target_cls=models.Card, event=event)
2022-11-04T10:14:58.732775093Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/djstripe/event_handlers.py", line 416, in _handle_crud_like_event
2022-11-04T10:14:58.732779659Z app[web.1]:     obj = target_cls.sync_from_stripe_data(data, api_key=event.default_api_key)
2022-11-04T10:14:58.732784072Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/djstripe/models/base.py", line 1004, in sync_from_stripe_data
2022-11-04T10:14:58.732788609Z app[web.1]:     instance, created = cls._get_or_create_from_stripe_object(
2022-11-04T10:14:58.732793052Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/djstripe/models/base.py", line 753, in _get_or_create_from_stripe_object
2022-11-04T10:14:58.732797611Z app[web.1]:     return cls.stripe_objects.get(id=id_), False
2022-11-04T10:14:58.732801956Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/models/manager.py", line 85, in manager_method
2022-11-04T10:14:58.732806489Z app[web.1]:     return getattr(self.get_queryset(), name)(*args, **kwargs)
2022-11-04T10:14:58.732814541Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/django/db/models/query.py", line 435, in get
2022-11-04T10:14:58.732819248Z app[web.1]:     raise self.model.DoesNotExist(
2022-11-04T10:14:58.732823685Z app[web.1]: djstripe.models.payment_methods.Card.DoesNotExist: Card matching query does not exist.
2022-11-04T10:14:58.734520252Z app[web.1]: 172.17.0.1 - - [04/Nov/2022:06:14:58 -0400] "POST /subscriptions/webhook/ HTTP/1.1" 500 7908 "-" "Stripe/1.0 (+https://stripe.com/docs/webhooks)"

@arnav13081994
Copy link
Collaborator

@martinmain93 Are you able to reliably reproduce this?

It seems like a race condition to me. In production stripe retries webhooks several times so this usually is not a blocker for most.

@martinmain93
Copy link
Author

@arnav13081994 I am not able to reliably reproduce, but it’s happened on our production site about 50 times over the past month, resulting in lost revenue for our business. The webhooks get errors that we ignore all the time, as is well documented, and usually after one or two retries they come through without issue. The problem here is that the add_card method is failing. I don’t care about the webhooks failing. I am concerned about the add_card method.

@arnav13081994
Copy link
Collaborator

@martinmain93 I will take a look at this issue and see what can be done.

Is this happening when you create a new customer or for returning customers as well? I think what perhaps is causing this is Card and Customer objects getting created at around the same time. This causes the error as the Card needs to be on the Customer (which needs to exist before card can be added).

@martinmain93
Copy link
Author

@arnav13081994 This is only happening with new users. The customer is created immediately before the card is added

@martinmain93
Copy link
Author

@arnav13081994 I've added a simple method to 'retry until success' which will literately attempt the add_card method until it goes through. It seems to be resolving the issue for now. Do you foresee any issues with this? I believe Djstripe uses idempotency keys internally so it shouldn't make any erroneous duplicate actions.

Also, we have noticed similar webhook munging issue in a few other places in our app. Particularly for the 'change_card' action, as well as the 'subscribe' action. The 'retry until success' thing seems to be working for now

@martinmain93
Copy link
Author

For reference:

def keep_trying(func, *args, max_tries=10, **kwargs):
    """
    Utility function to repeatedly attempt a function
    """
    tries = 0
    while True:
        tries += 1
        try:
            return func(
                *args,
                **kwargs
            )
        except Exception as e:
            if tries < max_tries:
                logger.warning(f"{str(func)} attempt failed. Retrying...")
                time.sleep(1)
            else:
                logger.warning(f"{str(func)} attempt failed {max_tries} times. Giving up now..")
                raise e


# Use like:
keep_trying(customer.add_card, stripe_token)

@arnav13081994
Copy link
Collaborator

@martinmain93 I think that's the best you can do at the moment. But please test thoroughly to ensure there are no unwarranted side effects.

@jleclanche Perhaps we can add a default retry mechanism for all methods using idempotency keys?

@martinmain93
Copy link
Author

@arnav13081994 So this has fixed most of our issues. Now, we are occasionally getting the You cannot use a Stripe token more than once: error when we retry the add_card method in some cases...

@arnav13081994
Copy link
Collaborator

@martinmain93 Could you please post some traceback as it's very difficult for me to help without that.

@martinmain93
Copy link
Author

Here's the traceback. In this case, I've added a workaround by detecting if this specific error has been raised, and then trying to detect if the customer has a valid source. If the user has a valid source (after retrying a few times), then we ignore the error.

2022-11-10T16:19:29.027608052Z app[web.1]: Traceback (most recent call last):
2022-11-10T16:19:29.027613702Z app[web.1]:   File "/app/payment/forms.py", line 140, in handle_add_card
2022-11-10T16:19:29.027618648Z app[web.1]:     keep_trying(customer.add_card, self.cleaned_data.get('stripe_token'))
2022-11-10T16:19:29.027623555Z app[web.1]:   File "/app/payment/utils.py", line 201, in keep_trying
2022-11-10T16:19:29.027628293Z app[web.1]:     raise e
2022-11-10T16:19:29.027632781Z app[web.1]:   File "/app/payment/utils.py", line 191, in keep_trying
2022-11-10T16:19:29.027637462Z app[web.1]:     return func(
2022-11-10T16:19:29.027642075Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/djstripe/models/core.py", line 1046, in add_card
2022-11-10T16:19:29.027646922Z app[web.1]:     new_stripe_payment_method = stripe_customer.sources.create(source=source)
2022-11-10T16:19:29.027651690Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/stripe/api_resources/list_object.py", line 32, in create
2022-11-10T16:19:29.027678004Z app[web.1]:     return self._request(
2022-11-10T16:19:29.027683092Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/stripe/stripe_object.py", line 282, in _request
2022-11-10T16:19:29.027687712Z app[web.1]:     response, api_key = requestor.request(method_, url_, params, headers)
2022-11-10T16:19:29.027692248Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/stripe/api_requestor.py", line 122, in request
2022-11-10T16:19:29.027696801Z app[web.1]:     resp = self.interpret_response(rbody, rcode, rheaders)
2022-11-10T16:19:29.027733054Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/stripe/api_requestor.py", line 399, in interpret_response
2022-11-10T16:19:29.027741953Z app[web.1]:     self.handle_error_response(rbody, rcode, resp.data, rheaders)
2022-11-10T16:19:29.027746591Z app[web.1]:   File "/app/.heroku/python/lib/python3.10/site-packages/stripe/api_requestor.py", line 159, in handle_error_response
2022-11-10T16:19:29.027751156Z app[web.1]:     raise err
2022-11-10T16:19:29.027755574Z app[web.1]: stripe.error.InvalidRequestError: Request req_f1KnW7iEfL4nOZ: You cannot use a Stripe token more than once: tok_1M2dSxGRvRnAJwTxwzHQpKas.

There must have been something that changed between Djstripe 2.5 and 2.6. Our system seems to be hacked-together working for now, with lots of error catching and retrying, but our server logs are crammed with Webhook error messages every time anyone does anything stripe related.

@jleclanche
Copy link
Member

add_card is no longer supported by Stripe so I'm closing this.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

No branches or pull requests

3 participants