Projet

Général

Profil

Actions

Anomalie #4617

fermé

Le nombre d'erreurs HTTP explose de façon exponentielle

Ajouté par Christian P. Momon il y a plus de 4 ans. Mis à jour il y a environ 4 ans.

Statut:
Fermé
Priorité:
Normale
Assigné à:
Début:
01/08/2020
Echéance:
% réalisé:

0%

Temps estimé:

Description

Dans le magnifique rapport d'activité de juillet (#4150), on peut lire :

Nombre total de requêtes http                = 124931
Nombre de vraies requêtes http               = 112030
Nombre de requêtes bot                       = 3934
Nombre de requêtes http en erreur            = 1254529

Rétrospectivement :
  • mars : 2 236
  • avril : 9 531
  • mai : 65 071
  • juin : 125 598
  • juillet : 1 254 529

Demande : analyser d'où vient le phénomène et proposer des actions.


Demandes liées 1 (0 ouverte1 fermée)

Lié à date.chapril.org - Tâche récurrente #4150: Rapport annuel 2020 d'activité de date.chapril.orgFerméDidier Clermonté05/01/2020

Actions

Mis à jour par Christian P. Momon il y a plus de 4 ans

Mis à jour par Christian P. Momon il y a plus de 4 ans

  • Description mis à jour (diff)

Mis à jour par Didier Clermonté il y a environ 4 ans

  • Statut changé de Nouveau à En cours de traitement

Le code de tpl/part/vote_table_date.tpl a été modifié comme suit :
ajouté 2 fois lignes 116 et 179 :


              {if sizeof($vote->choices)==1 && strlen($vote->choices[0])==0}
                    {$choice=' '}
              {else}
                        {$choice=$vote->choices[$k]}

              {/if}

Mis à jour par Didier Clermonté il y a environ 4 ans

L'investigation qui a conduit à la solution mentionnée au-dessus :

1) D'abord, dans le ticket, dire si cette erreur représente la
quasi-totalité des 1254529 erreurs de juillet, fournir la ligne de
commande et sa sortie ;

=(^-^)=root@lamp:/var/log/apache2/date.chapril.org# errorCount=$(zgrep " 
Jul " date.chapril.org-error.log* | wc -l)
=(^-^)=root@lamp:/var/log/apache2/date.chapril.org#
theErrorCount=$(zgrep " Jul " date.chapril.org-error.log* | grep "line
397" | wc -l)
=(^-^)=root@lamp:/var/log/apache2/date.chapril.org# echo
"$theErrorCount/$errorCount => $((theErrorCount*100/errorCount)) %" 
1247380/1255052 => 99 %

2) Ensuite, vérifier si un ticket existe déjà dans le projet officiel.

A priori, y a pas.

3) retrouver la ligne dans la version non compilée du template ;

tpl/part/vote_table_date.ptl, ligne 179

4) retrouver le fichier et la ligne où la version non compilée du
template est appelée et remonter le plus haut ;

studs.php,adminstuds.php -> studs.tpl -> vote_table_date.tpl

5) déterminer quand ce fichier de template est appelé, c'est dans
l'affichage de quelles pages ?

=(^-^)=root@lamp:/var/log/apache2/date.chapril.org# cat
/var/www/date.chapril.org/.htaccess
  RewriteRule ^([a-zA-Z0-9-]+)$ studs.php?poll=$1 [L]
  RewriteRule ^([a-zA-Z0-9-]+)/action/([a-zA-Z_-]+)/(.+)$
studs.php?poll=$1&$2=$3
  RewriteRule ^([a-zA-Z0-9-]+)/vote/([a-zA-Z0-9]{16})$
studs.php?poll=$1&vote=$2
  RewriteRule ^([a-zA-Z0-9-]{24})/admin$ adminstuds.php?poll=$1
  RewriteRule ^([a-zA-Z0-9-]{24})/admin/vote/([a-zA-Z0-9]{16})$
adminstuds.php?poll=$1&vote=$2
  RewriteRule ^([a-zA-Z0-9-]{24})/admin/action/([a-zA-Z_-]+)(/(.+))?$
adminstuds.php?poll=$1&$2=$4

=(^-^)=root@lamp:/var/log/apache2/date.chapril.org# grep --after=1 stud
/var/www/date.chapril.org/doc/TREEVIEW.md
* studs.php
    * La page de présentation de sondage
* adminstuds.php
    * La page d'administration réservée à l'auteur du sondage

6) cette partie du template concerne quelle partie de la page ?

 L'affichage du tableau des votes.

7) est-ce systématiquement reproduisible ? Comment ?

 Non. En fait, pour le reproduire, on peut retrouver un id de sondage
(prendre l'ip dans *error.log et chercher dans *acess.log).

 Moi j'ai trouvé https://date.chapril.org/......

 Et là, c'est systématique, un tail -f affiche 4 x 264 erreur à chaque
fois. Le 264 correspond au 8 horaire x 33 jours du sondage.

8) relire le code à l'endroit où sa bug

{foreach $votes as $vote}
  […]
  {$k=0}
  {foreach $slots as $slot}
    {foreach $slot->moments as $moment}
      {$choice=$vote->choices[$k]}
      […]
      {$k=$k + 1}
    {/foreach}
  {/foreach}

 La log d'erreur dit «  PHP Notice:  Undefined offset: 25 ».

 Donc c'est clair, le tableau choices ne contient pas autant de cases
qu'attendu.

 Alors, c'est quoi ce tableau choices ?

 Dans studs.php, on voit que :

$votes = $pollService->allVotesByPollId($poll_id);

et dans app/classes/Framadate/Repositories/VoteRepository.php :

    function allUserVotesByPollId($poll_id) {
        $prepared = $this->prepare('SELECT * FROM `' .
Utils::table('vote') . '` WHERE poll_id = ? ORDER BY id');
        $prepared->execute([$poll_id]);

        return $prepared->fetchAll();
    }

donc on peut supposer que voices est une colonne directement mis dans la
variables $vote :

MariaDB [date_chapril_org_db]> describe fd_vote;
+---------+------------------+------+-----+---------+----------------+
| Field   | Type             | Null | Key | Default | Extra          |
+---------+------------------+------+-----+---------+----------------+
| id      | int(11) unsigned | NO   | PRI | NULL    | auto_increment |
| uniqId  | char(16)         | NO   | MUL | NULL    |                |
| poll_id | varchar(64)      | NO   | MUL | NULL    |                |
| name    | varchar(64)      | NO   |     | NULL    |                |
| choices | text             | NO   |     | NULL    |                |
+---------+------------------+------+-----+---------+----------------+
5 rows in set (0.002 sec)

MariaDB [date_chapril_org_db]> select name,choices from fd_vote where
poll_id='V...........' order by id limit 4;
+-------------------+---------------------------------+
| name              | choices                         |
+-------------------+---------------------------------+
| A                 |                              […]|
| V  F              |        2       2       2     […]|
| V               S |        2       2       2     […]|
| P B               |                      20   2  […]|

 Donc, la colonne choices est une chaîne de caractères qui contient les
votes !

 Donc la fameuse ligne {$choice=$vote->choices[$k]} extrait le vote en
prenant le nième caractère de la chaîne.

 Je n'ose imaginer ce qu'il se passe en cas d'insertion de date, brrr…

 Mais alors pourquoi une erreur ?

MariaDB [date_chapril_org_db]> select * from fd_vote where
poll_id='Vit' and choices like '' order by id;
+-------+------------------+------------------+------------------+---------+
| id    | uniqId           | poll_id          | name             | choices |
+-------+------------------+------------------+------------------+---------+
| 19830 | zVAh8Y           | V                | A                |         |
| 20580 | KiG5f            | V                | C                |         |
| 21193 | ADQte            | V                | C                |         |
| 21208 | Gv3u             | V                | B                |         |
+-------+------------------+------------------+------------------+---------+
4 rows in set (0.002 sec)

 Parce que parfois, pour une raison qui nous échappe, une personne qui
ne vote pas voit sa ligne choices vide. Du coup, l'extraction plante.
Normal.

9) patcher

 Donc il faut blinder la ligne {$choice=$vote->choices[$k]}

 Pour cela, rajouter un test sur la taille de choices :

https://www.smarty.net/docsv2/en/language.modifier.count.characters.tpl

{$articleTitle|count_characters:true}

 Si le count est inférieur à k alors mettre $choice=' ';

9 bis) patcher ailleurs
=(^-^)=root@lamp:/var/log/apache2/date.chapril.org# grep -n -R
"\{\$choice=\$vote->choices\[\$k\]}" /var/www/date.chapril.org/
/var/www/date.chapril.org/tpl/part/vote_table_date.tpl:116:
           {$choice=$vote->choices[$k]}
/var/www/date.chapril.org/tpl/part/vote_table_date.tpl:179:
           {$choice=$vote->choices[$k]}

 Donc le problème existe aussi à la ligne 116, code qui affiche le
tableau en mode édition…

Mis à jour par Didier Clermonté il y a environ 4 ans

  • Statut changé de En cours de traitement à Résolu

Mis à jour par Didier Clermonté il y a environ 4 ans

Lien vers le ticket déposé dans le projet officiel framadate :
https://framagit.org/framasoft/framadate/framadate/-/issues/516

Mis à jour par Didier Clermonté il y a environ 4 ans

  • Statut changé de Résolu à Fermé

Mis à jour par Christian P. Momon il y a environ 4 ans

  • Version cible changé de Backlog à Sprint 2020 été
Actions

Formats disponibles : Atom PDF