search

TrogloGeek / prestashop-tggatos-module

TggAtos Module for Prestashop (1.4 to 1.7), ATOS SIPS 6xx payment gateway
61 stars 34 forks source link

commandes en double #46

Closed nicolain06 closed 8 years ago

nicolain06 commented 8 years ago

Bonjour, certaines commandes sont doublées après réception du paiement : 2 commandes identiques sont insérées à la même seconde. Avez-vous déjà eu le soucis ? une idée pour le corriger ?

tucoinfo commented 8 years ago

Bonjour, moi aussi, mais depuis quelques jours seulement, et sans avoir touché au site.

OVH mutu - PS 1.6.1.1 - TGGATOS v3.1.0 (Mercanet)

nicolain06 commented 8 years ago

idem, je n'ai rien touché et ça arrive depuis quelques jours également. PS 1.6.1.4 (dernière version) - ça marchait parfaitement avant.

tucoinfo commented 8 years ago

Ca sent le petit changement coté bancaire/ATOS. Perso je n'ai reçu aucun avertissement de leur part (même jamais rien). Je suis certain que TGG va nous tirer ça au clair.

TrogloGeek commented 8 years ago

Hello,

Je suis certain que TGG va nous tirer ça au clair.

Pas si sur, j'ai rejoint la start up française LiveMon en fin d'année dernière et cela me laisse peut de temps pour jouer avec PrestaShop.

@nicolain06 Quelle banque ? Quelle version du module ?

@nicolain06 @tucoinfo Vos doublons sont-ils liés tous deux au même ID panier ou le panier est-il lui aussi dupliqué ?

step 1

Vérifiez les response logs du module pour regarder si les réponses relatives à ces commandes sont présentes en double aussi. Le module vérifie que le panier n'est pas déjà associé à une commande avant de traiter la réponse bancaire, mais comme le reste de PrestaShop ce module n'utilise pas de transactions SQL => une race condition reste possible, dans certains cas de forte charge j'ai pu observer des serveurs SIPS envoyant des séquences de validation de commande incohérentes (souvent une réponse de transaction annulée + une réponse de transaction confirmée).

step 2

Vérifier si ces commandes contenaient un ou plusieurs produits en rupture de stock : cette partie du code de PrestaShop est bien connu pour avoir provoqué de nombreuses anomalies sur les commandes (commandes sans statut, commandes corrompues, commandes avec séquence de statuts incohérente...).

step 3

Pourriez-vous lister tous les deux les modules greffés sur les hooks de validation de commande et de changement de statut de commande voir s'il y a là un point commun suspect ?

tucoinfo commented 8 years ago

Salut Damien,

Vos doublons sont-ils liés tous deux au même ID panier ou le panier est-il lui aussi dupliqué ?

Oui, liés au même ID panier, oui le panier est visiblement dupliqué avec 2 IDs différents.

step 1

Oui, le .log montre des doublons : même transaction_id, même order_id, tout pareil sauf customer_email et customer_ip_address qui sont vides dans le 2ème. Certes, la DB devient lourde pour une mutu, le BO est très lent (bug BO je pense) mais le FO va plutôt bien. Cela dit je dois de toute façon trouver du temps pour migrer sur mon SD.

step 2

Peut pas conclure de mon coté. Une commande avec alerte mail de rupture mais pas encore vraiment le cas (juste en dessous du seuil d'alerte).

step 3

Je ne sais pas si c'est tout ceci mais voici : actionOrderReturn : -- Customer loyalty and rewards -- Mail alerts actionOrderStatusPostUpdate : -- Cross-selling actionOrderStatusUpdate : -- Customer loyalty and rewards displayOrderConfirmation : -- GG Analytics

TrogloGeek commented 8 years ago

Oui, liés au même ID panier, oui le panier est visiblement dupliqué avec 2 IDs différents.

Comment cela ? le doublon ne peut pas à la fois être lié au même ID panier et à l'ID un panier dupliqué.

Oui, le .log montre des doublons : même transaction_id, même order_id, tout pareil sauf customer_email et customer_ip_address qui sont vides dans le 2ème.

Oui, le .log montre des doublons : même transaction_id, même order_id, tout pareil sauf customer_email et customer_ip_address qui sont vides dans le 2ème.

Quid du return_context ? Si l'une des deux réponses est la réponse silencieuse, l'autre le retour utilisateur alors il s'agit d'une cinématique normale.

nicolain06 commented 8 years ago

Banque SMC, version 4.0.0 du module.

J'ai bien les entrées en double dans le log, ainsi que dans la base de données. Le id_cart est le même sur les deux enregistrements (voir PJ des logs & bdd)

Step 2 : aucune commande contenant des produits en rupture

Step 3 : actionOrderReturn : -- Customer loyalty and rewards -- Mail alerts actionOrderStatusPostUpdate -- Meilleures ventes -- Tableau de bord des tendances actionOrderStatusUpdate -- expertise prestashop -- programme de fidélité -- programme parrainage client -- home page top seller tab -- home page top seller carrousel

1 2 3

tucoinfo commented 8 years ago

Comment cela ? le doublon ne peut pas à la fois être lié au même ID panier et à l'ID un panier dupliqué

ID panier A = ID order X ID panier A = ID order Y

Quid du return_context ? Si l'une des deux réponses est la réponse silencieuse, l'autre le retour utilisateur alors il s'agit d'une cinématique normale.

Je ne sais pas trop, mes entrées return_context ont toujours était non renseigné selon le log.

nicolain06 commented 8 years ago

PS : même soucis depuis quelques jours sur un autre prestashop complètement séparé avec le module v3.3.1

tucoinfo commented 8 years ago

PS : même soucis depuis quelques jours sur un autre prestashop complètement séparé avec le module v3.3.1

Oups je vois ça moi aussi sur un autre site PS 1.6.0.14 / TGGATOS 3.4.0 et là il n'y a vraiment aucun souci de puissance (SD optimisé).

84pixels commented 8 years ago

Même problème sur Prestashop 1.6.0.6 et le module TGG 4.0.0 avec Sherlocks LCL.

2016-02-04-a-11 25 17

TrogloGeek commented 8 years ago

Ce ne sont pas des doublons : une response_type user et une silent correspondent au workflow standard.

Le problème semble venir d'une race condition à débusquer dans PaymentModule::validateOrder() entre if (Validate::isLoadedObject($this->context->cart) && $this->context->cart->OrderExists() == false) { et $result = $order->add();

Lorsque plusieurs personnes se mettent subitement à avoir un problème de timing sur des versions différentes, il faut généralement rechercher quel est le webservice commun dont les latences ont récemment augmenté.

TrogloGeek commented 8 years ago

PS: il vaut mieux désactiver temporairement le mode NO_RESPONSE_PAGE qui renforce les risques de déclancher cette race condition en diminuant fortement le délai entre les réponses silencieuses et retour utilisateur.

Je vois une manière de résoudre ce problème de race condition interne à PrestaShop depuis le module via une page de mise en attente avec ping ajax et une table de verrou sur les ID paniers, mais cela représente un temps de développement substantiel dont je ne dispose pas actuellement.

TrogloGeek commented 8 years ago

ERRATUM SIPS doit avoir changé son mode de fonctionnement : auparavant l'utilisateur était mis en attente de la fin de la réponse silencieuse avant soit qu'il soit renvoyé vers la boutique (NO_RESPONSE_PAGE) ou que la banque lui présente la page de confirmation.

La race condition n'était auparavant pas possible grâce à cette mise en attente de la fin de réponse silencieuse, cette mise en attente a du être retirée par SIPS, il faut les contacter à ce sujet (je n'ai personnellement aucun contrat VAD et donc aucun accès support auprès de SIPS ou d'une banque exploitant SIPS).

tucoinfo commented 8 years ago

Je vais les contacter et plus on sera nombreux plus on aura de réponses.

TrogloGeek commented 8 years ago

Un workaround temporaire bien immonde pourra être simplement d'ajouter un sleep() ou usleep() sur le controlleur userreturn donnant un délai suffisant (le délai nécessaire dépendant des performances de la boutique, 200ms devraient suffire pour une boutique rapide, jusqu'à 2s pour les plus lentes) à la réponse silencieuse pour enregistrer la commande en BdD avant que la réponse utilisateur ne commence son traitement. La fiabilité de ce fix ne sera bien évidemment parfaite, on ne corrige jamais une race condition par une attente aveugle via un délai réglé minutieusement au pifomètre, mais cela devrait sérieusement réduire les occurences de cette race condition.

Si quelqu'un a un peu de temps pour coder, il faudrait implémenter une table de verrou sur l'ID panier et mettre l'utilisateur en attente tant que le verrou est en place. Ou implémenter les transactions avec rollback.

TrogloGeek commented 8 years ago

Je vais les contacter et plus on sera nombreux plus on aura de réponses.

Oui, avec SIPS il faut monter au créneau en masse, si un seul utilisateur a un problème, ce n'est pas leur problème.

84pixels commented 8 years ago

Bonjour, Quelles questions doit on leurs poser?

tucoinfo commented 8 years ago

Réponse Mercanet :

Il semble que depuis le début de la semaine, le module Prestashop gère en double les commandes recevant 2 log (réponse automatique et réponses manuelle) provenant de nos serveurs La commande n'est pas doublée sur le compte. Nous vous invitons à prendre contact avec Prestashop afin de leur soumettre les cas : Prestatshop doit effectuer une correction dans leur traitement des log reçus par nos serveurs.

nicolain06 commented 8 years ago

par rapport à l'idée de faire un "quick fix", où verriez-vous le sleep? quel fichier / fonction exactement ?

TrogloGeek commented 8 years ago

@tucoinfo leur a tu bien expliqué que le problème venait du fait qu'ils ne mettent plus le client en attente que la réponse silencieuse soit terminée ?

TrogloGeek commented 8 years ago

@nicolain06 https://github.com/TrogloGeek/prestashop-tggatos-module/blob/RC_4.0.0/controllers/front/userreturn.php#L34 ici par exemple

tucoinfo commented 8 years ago

a tu bien expliqué que le problème venait du fait qu'ils ne mettent plus le client en attente que la réponse silencieuse soit terminée ?

Ca oui mais je suis à 3 A/R déjà pour obtenir la confirmation. J'ai effectivement l'impression de parler à ma banque et non pas ATOS...

tucoinfo commented 8 years ago

Dernière réponse en date :

Si vous êtes parmi les cas suivants, sachez que depuis la semaine dernière, la réponse automatique et la réponse manuelle sont envoyées avec un léger decallage. Prestashop considère ainsi qu'il s'agit de 2 commandes différentes, d'où ses doublons :

  • clic internaute sur "retour boutique"
  • paramétrage du "no respons page"sur votre api.
TrogloGeek commented 8 years ago

Thanks pour l'update

Vous avez pu juguler vos doublons par l'ajout d'un délai ? Je sais c'est très moche comme méthode (il a fallu me faire violence pour la proposer) mais le rapport efficacité coût devrait être redoutable.

nicolain06 commented 8 years ago

J'ai testé avec un sleep(3) sur plusieurs boutiques différentes ayant le soucis, & j'ai toujours la commande en double... bien que décalée de 3 secondes.

TrogloGeek commented 8 years ago

où le sleep a-t-il été ajouté ?

nicolain06 commented 8 years ago

sur userreturn.php (voir PJ)

capture d ecran 2016-02-09 a 09 37 31
TrogloGeek commented 8 years ago

étrange la réponse silencieuse devrait avoir largement le temps de créer la commande durant ces 3 secondes.

Pourriez-vous me donner les heures dans les logs du module pour les deux réponses et les date_add des deux exemplaires de la commande ?

nicolain06 commented 8 years ago

Les voici

capture d ecran 2016-02-09 a 09 50 32 capture d ecran 2016-02-09 a 09 50 01 capture d ecran 2016-02-09 a 09 45 16

TrogloGeek commented 8 years ago

Ok, je pense que le soucis vient du système de cache : https://github.com/PrestaShop/PrestaShop/blob/develop/classes/Cart.php#L1203

le cache a déjà été initialisé au moment du sleep par le init() du FrontController ou autre. exemple : https://github.com/PrestaShop/PrestaShop/blob/develop/classes/controller/FrontController.php#L337

Dans ce cas il faudrait mettre le sleep avant cette ligne : https://github.com/TrogloGeek/prestashop-tggatos-module/blob/RC_4.0.0/autodispatch/userreturn.pub.php#L2 Mettant ainsi en attente toute l'initialisation de PrestaShop dans le contexte de la réponse utilisateur.

TrogloGeek commented 8 years ago

Désolé encore de ne pas pouvoir réellement traiter le problème, les modifications de fonctionnement de SIPS tombent au pire moment pour moi, je n'ai vraiment pas de temps disponible.

nicolain06 commented 8 years ago

Je viens de changer le sleep de place sur 4 boutiques, on va tester !

84pixels commented 8 years ago

Perso j'ai ajouté le sleep après la $response et cela à l'air de fonctionner depuis 2 jours.

TrogloGeek commented 8 years ago

@84pixels ta boutique tourne probablement sans cache ?

84pixels commented 8 years ago

@TrogloGeek, Varnish en front + Nginx + Opcache, j'ai du désactiver memcached. Cache désactivé sur le Back.

84pixels commented 8 years ago

ERRATUM J'ai toujours des commandes en double avec un usleep(500000); sans cache; Je vais tester avec un délais plus élevé.

TrogloGeek commented 8 years ago

Oui 500ms pas forcément suffisant : la réponse de 18:40:41 a généré une commande à 18:40:42. Donc à moins la réponse ne soit arrivée tard dans la 41° seconde il a probablement eu un délai substantiel entre les deux. Pour le POC j'aurais tendance ici à viser les 1.5s, puis à réduire progressivement.

fenaille commented 8 years ago

Bonjour, nous rencontrons également un problème de doublon sur le site d'un de nos clients. Nous avons mis en place la modification suivante depuis ce matin et n'avons pour l'instant plus de doublons (à confirmer avec le temps).

https://github.com/TrogloGeek/prestashop-tggatos-module/blob/RC_4.0.0/controllers/front/userreturn.php#L34 Ajouter le code suivant (valeur du nombre de boucle peut-être à adapter)

            if (!is_null($response)) {
                $loopCounter = 10;
                $cart = new Cart((int)$response->order_id);
                if (Validate::isLoadedObject($cart)) {
                    while ($loopCounter != 0) {
                        if ($this->orderExists($cart->id)) {
                            break;
                        } else {
                            sleep(1);
                            $loopCounter--;
                        }
                    }
                }
            }

Et dans le contrôleur, lui ajouter cette fonction (évite d'utiliser la version cache de PrestaShop)

public function orderExists($id_cart)
{
    $result = (int)Db::getInstance()->getValue('SELECT count(*) FROM `'._DB_PREFIX_.'orders` WHERE `id_cart` = '.(int)$id_cart);
    if ($result == 1)
            return true;

    return false;
}
TrogloGeek commented 8 years ago

Bonne idée, cela permet de réduire la latence lorsque la commande est créée rapidement, plus adaptatif, du coup on peut réduire le sleep(1) à un usleep entre 200ms et 400ms (ne pas trop réduire pour ne pas surcharger la DB) et augmenter le nombre d'itération max en conséquence. (Attention certains serveurs seront en timeout avant la fin des 10s !!)

Par contre remplacer le $result == 1 par $result > 0 pour le cas où il existerait déjà un doublon.

fenaille commented 8 years ago

Bien vu pour le $result :)

On vient tout de même d'avoir un nouveau doublon. J'ai l'impression que le cache du Cart::orderExists_ peut quand même être foireux lorsque le traitement continue dans son $order = $this->module->processResponse($response);. (ce n'est pas contre toi TGG)

Du coup, on vient de rajouter un Cache::clean($cache_id); à chaque itération, $cache_idétant renseigné en amont de la sorte $cache_id = 'Cart::orderExists_'.(int)$cart->id;. A voir si ça arrête les doublons une fois pour toute !!

84pixels commented 8 years ago

@TrogloGeek Allez vous faire un commit du patch?

TrogloGeek commented 8 years ago

@fenaille Bien vu. Pas besoin de faire le clear cache à chaque itération puisque celles-ci le contourne, il suffit de le faire une fois avant le break;

@84pixels Pas dans les prochaines 48h à priori, mon process de RC prend 2 à 3h et je n'ai déjà que quelques heures de sommeil par nuit.

fenaille commented 8 years ago

@TrogloGeek j'ai pas confiance dans le cache PrestaShop (dans les logs, on a déjà reçu plusieurs silent ou user response pour une même commande) nous testons comme ça pour le moment (tant pis pour les performances) et si le problème est vraiment résolu, on affinera

fenaille commented 8 years ago

Pour info, plus de commandes en double depuis 72h avec les modifications suivantes dans le fichier /controllers/front/userreturn.php :

Ajout d'une fonction de vérification si 1 (ou plusieurs) commande existe pour un id de panier :

public function orderExists($id_cart)
{
    $result = (int)Db::getInstance()->getValue('SELECT count(*) FROM `'._DB_PREFIX_.'orders` WHERE `id_cart` = '.(int)$id_cart);
    if ($result > 0)
            return true;

    return false;
}

Modification de la fonction initContent() entre $response = $this->module->uncypherResponse($message, TggAtosModuleResponseObject::TYPE_USER); et $order = $this->module->processResponse($response);

if (!is_null($response)) {
    $loopCounter = 10;

    $cart = new Cart((int)$response->order_id);
    $cache_id = 'Cart::orderExists_'.(int)$cart->id;
    if (Validate::isLoadedObject($cart)) {
        while ($loopCounter != 0) {
            if ($this->orderExists($cart->id)) {
                Cache::clean($cache_id);
                break;
            } else {
                sleep(1);
                $loopCounter--;
            }
        }
    }
}
84pixels commented 8 years ago

Ok je vais tester de mon coté. Merci pour ce quick fix!

mockassin commented 8 years ago

En regardant de plus près, je constate qu'en effet mes commandes en double sont générés l'une par le serveur bancaire et l'autre par l'utilisateur. La solution donc serait uniquement d'enregistrer la commande si la réponse venait uniquement du serveur bancaire (ce qui est plus sécurisant aussi).

mockassin commented 8 years ago

Une analyse plus détaillée m'a fait comprendre que le souci vient du fait qu'à la microseconde près, le retour utilisateur se fait avant celui de la banque... ce qui déclenche le premier enregistrement puis le 2ème. si vous vérifiez vos logs bancaires, dans le cas où il y a un doublon c'est quand le log utilisateur est avant le log réponse silence. Le principe de la solution de @fenaille est pertinente car elle assure que le retour serveur bancaire se fait avant celui de l'utilisateur.

mockassin commented 8 years ago

Juste une réflexion: ce n'est pas normal non plus que le retour utilisateur puisse générer une commande... il faudrait à mon avis pour renforcer la sécurité du module s'assurer que seul le retour du serveur bancaire puisse générer la commande. de mon côté, j'ai filtré en regardant la valeur response->origin.

TrogloGeek commented 8 years ago

@mockassin La réponse silencieuse n'est pas 100% fiable, le traitement de la réponse utilisateur sert de fallback pour les cas où la banque échoue à envoyer la réponse silencieuse (il m'est arrivé d'avoir des journées où 25% des réponses silencieuses étaient en échec sur une boutique dont j'avais la maintenance). Vous pouvez désactiver le traitement de la réponse utilisateur si vous le désirez mais vous risquez de perdre des informations de paiement.