Journal Analyse des logs Ruby on Rails de LinuxFr.org de début novembre 2022

Sommaire

• Mais pourquoi s’infliger ça ?
• Par type
• Analyse des logs FATAL
  • Entrée inexistante (ActiveRecord::RecordNotFound)
  • Erreur de routage (ActionController::RoutingError)
  • Format inconnu (ActionController::UnknownFormat)
  • Erreur de codage (Rack::QueryParser::InvalidParameterError)
  • Autres
•  Conclusion

Mais pourquoi s’infliger ça ?

Je ne vais traiter que le cas de l’auteur de ce journal, ce n’est pas à moi de savoir pourquoi toi personne lectrice tu veux t’infliger ça, tu dois sûrement avoir de bonnes raisons.

Garder un œil sur ses traces ou logs est une bonne pratique, histoire de savoir si tout va bien (fonctionnellement), si des bugs sont présents, combien de pénibles visitent le site, si on a finalement réussi à corriger certains bugs ou non, etc. Idéalement on le fait « tout le temps », mais déjà le faire de temps en temps reste mieux que rien.

C’est aussi un moyen de tâcher de comprendre comment marche Ruby On Rails et le site LinuxFr.org en particulier. Cela oblige à comprendre ce qui se passe, à creuser un peu. Et quand on ne fait pas du Ruby tous les jours, ça aide un peu.

Et finalement analyser des logs aide à mieux déboguer des problèmes, donc à acquérir de l’expérience qui sera peut-être utile si par un hasard fortuit des problèmes devaient arriver un jour.

S'ajoute à cela le fait que j'écris cette analyse, ce qui m'oblige à la finir (forfait Crastination Pro+), m'aide à la formaliser (oui vous avez ici un rôle de canard/coincoin en plastique), à m'en rappeler (pour la prochaine invocation de RoR à la pleine lune enroulé dans une tranche de tofu), et comme « ce que l'on conçoit bien s'énonce clairement », j'essaie de faire comprendre à RoR qu'il pourrait me causer meilleur et surtout plus explicitement.

Bref, donc j’ai jeté un œil à l’ensemble de logs RoR présents à un moment donné, soit du 2 novembre 2022 06:27 (Paris) au 12 novembre 11:39.

Par type

Les logs sont associés à un niveau de gravité, et dans le cas présent, la répartition des occurrences est la suivante :

• INFO 139452616 (139M)
• WARN 796
• FATAL 170942 (soit 0,12%)

Cela fait à la fois peu de logs FATAL, et pourtant un peu trop à mon goût. Mais je ne connais pas assez RoR pour en éviter certains si cela est possible. On va donc se concentrer sur ces logs FATAL.

Analyse des logs FATAL

Les cent septante mille entrées FATAL correspondent en fait à 42730 requêtes (une requête pouvant générer plusieurs lignes FATAL, souvent quatre). Trop bien, on a déjà divisé le travail par quatre.

Entrée inexistante (ActiveRecord::RecordNotFound)

Le navigateur a demandé une entrée qui n’existe pas. Elle a pu exister dans le passé (compte purgé par exemple) ou non. Il peut s’agir d’une faute de frappe, d’une erreur de copier-coller, d’une attaque, d’un bug dans un script requêtant le site, etc. Et ça peut concerner une page statique, un compte, une étiquette, un contenu, un commentaire, etc.

Cela représente 32405 entrées (soit 75% des requêtes ayant conduit à des logs FATAL).

Le navigateur reçoit un code HTTP 404 Not Found.

Par occurrence (en gros un peu de tout) :

14747 (Couldn't find Page) app/controllers/static_controller.rb:4:in `show'
14424 (can't find record with friendly id: "xxx"): app/controllers/users_controller.rb:81:in `find_user'
1174 (can't find record with friendly id: "xxx"): app/controllers/news_controller.rb:71:in `find_news'
467 (Couldn't find Tag): app/controllers/tags_controller.rb:96:in `find_tag'
388 (can't find record with friendly id: "xxx"): app/controllers/diaries_controller.rb:108:in `find_diary'
261 (can't find record with friendly id: "xxx"): app/controllers/diaries_controller.rb:107:in `find_diary'
220 (can't find record with friendly id: "xxx"): app/controllers/posts_controller.rb:78:in `find_post'
171 (can't find record with friendly id: "xxx"): app/controllers/sections_controller.rb:9:in `show'
156 (can't find record with friendly id: "xxx"): app/controllers/bookmarks_controller.rb:84:in `find_bookmark'
84  (can't find record with friendly id: "xxx"): app/controllers/forums_controller.rb:17:in `show'
75 (can't find record with friendly id: "xxx"): app/controllers/trackers_controller.rb:108:in `load_tracker'
71  (can't find record with friendly id: "xxx"): app/controllers/bookmarks_controller.rb:85:in `find_bookmark'
51 (Couldn't find User with an out of range value for 'id'): app/controllers/users_controller.rb:81:in `find_user'
36 (Couldn't find User with 'id'=xxx): app/controllers/users_controller.rb:81:in `find_user'
21 (Couldn't find Node with 'id'=xxx): app/controllers/comments_controller.rb:89:in `find_node'
18 (Couldn't find Post with 'id'=xxx [WHERE `posts`.`forum_id` = ?]): app/controllers/posts_controller.rb:78:in `find_post'
9 (can't find record with friendly id: "xxx"): app/controllers/polls_controller.rb:69:in `find_poll'
7 (can't find record with friendly id: "xxx"): app/controllers/posts_controller.rb:77:in `find_post'
6 (Couldn't find News with 'id'=xxx app/controllers/news_controller.rb:71:in `find_news'
6 (Couldn't find Diary with 'id'=xxx [WHERE `diaries`.`owner_id` = ?]): app/controllers/diaries_controller.rb:108:in `find_diary'
6  (can't find record with friendly id: "xxx"): app/controllers/wiki_pages_controller.rb:119:in `load_wiki_page'
3 (Couldn't find Comment with 'id'=xxx [WHERE `comments`.`node_id` = ?]): app/controllers/comments_controller.rb:93:in `find_comment'
1 (can't find record with friendly id: "xxx"): app/controllers/redaction/news_controller.rb:118:in `load_news'
1 (can't find record with friendly id: "xxx"): app/controllers/posts_controller.rb:36:in `index'
1 (Couldn't find Forum with 'id'=xxx): app/controllers/posts_controller.rb:77:in `find_post'
1 (Couldn't find Forum with 'id'=xxx): app/controllers/forums_controller.rb:17:in `show'

Erreur de routage (ActionController::RoutingError)

Le navigateur a demandé un chemin qui n’existe pas, qui n’est pas géré. Il peut s’agir d’une faute de frappe, d’une erreur de copier-coller, d’une attaque, d’un bug dans un script requêtant le site, etc. Certaines fois il s’agit clairement d’attaques (tentative d’exécuter du Perl, de trouver un Wordpress, de récupérer un secret Let's Encrypt, de piquer notre windows\\win.ini, etc.).

Cela représente 8344 entrées (soit 20% des requêtes ayant conduit à des logs FATAL).

Par occurrence ([xxx] étant une méthode GET/POST/HEAD/… et "XXX" un chemin demandé) :

8344 (No route matches [xxx] "XXX"):

Format inconnu (ActionController::UnknownFormat)

Le navigateur a demandé un type de fichier qui n’existe pas, qui n’est pas géré. Il peut s’agir d’une faute de frappe, d’une erreur de copier-coller, d’une attaque, d’un bug dans un script requêtant le site, etc.

Le navigateur reçoit un code HTTP 406 Not Acceptable.

Exemples :

• GET "/users/prenom.nom" sauf que les identifiants de compte ne contiennent pas de point
• GET "/nodes/124266/comments.atom\"" à cause du " final excédentaire
• GET "/tags/python/public.atom%0A" à cause du retour chariot excédentaire
• GET "/board.php3" car nous n’avons plus de PHP3 depuis un certain temps déjà
• présence de l’en-tête Accept: application/json sur une page qui ne le gère pas

792 ActionController::UnknownFormat (ActionController::UnknownFormat): app/controllers/users_controller.rb:9:in `show'
199  ActionController::UnknownFormat (ActionController::UnknownFormat): app/controllers/tags_controller.rb:76:in `public'
112 ActionController::UnknownFormat (ActionController::UnknownFormat): app/controllers/news_controller.rb:13:in `index'
38 ActionController::UnknownFormat (ActionController::UnknownFormat): app/controllers/comments_controller.rb:9:in `index'
10 ActionController::UnknownFormat (NewsController#show is missing a template for this request format and variant.
2 ActionController::UnknownFormat (HomeController#index is missing a template for this request format and variant.
2 ActionController::UnknownFormat (ActionController::UnknownFormat): app/controllers/diaries_controller.rb:16:in `index'
1 ActionController::UnknownFormat (ActionController::UnknownFormat): app/controllers/sections_controller.rb:16:in `show'
1 ActionController::UnknownFormat (ActionController::UnknownFormat): app/controllers/boards_controller.rb:10:in `show'

Erreur de codage (Rack::QueryParser::InvalidParameterError)

Le navigateur a demandé une adresse mal codée. Il peut s’agir d’une faute de frappe, d’une erreur de copier-coller, d’une attaque, d’un bug dans un script requêtant le site, etc.

Le navigateur reçoit un code HTTP 400 Bad Request.

Exemples :

• GET "/tags/souverainet%E9/public" au lieu de "/tags/souverainet%C3%A9/public"
• GET "/news/python-pour-la-rentree-2019-partie-1%D1"

789 Rack::QueryParser::InvalidParameterError (Invalid encoding for parameter: xxx):
9 Rack::QueryParser::InvalidParameterError (invalid byte sequence in UTF-8):

Autres

• Un bogue déjà connu et que j’avais oublié :

22 ActionView::Template::Error (undefined method `each_char' for nil:NilClass):

Le navigateur reçoit un code HTTP 500 Internal Server Error.

• Un souci de pot de miel pour un spammeur (ça semble être une erreur plus ou moins voulue pour engluer du spammeur, mais ça reste peu explicite côté logs en tout cas) :

2 ActionDispatch::Http::Parameters::ParseError (822: unexpected token at 'xxx'):

Le navigateur reçoit un code HTTP 400 Bad Request.

• Un fichier d’avatar mal nommé en Unicode, qui produit une erreur HTTP 500 (entrée de suivi créée) :

1 URI::InvalidURIError (URI must be ascii only "xxx"):

Le navigateur reçoit un code HTTP 500 Internal Server Error.

 Conclusion

On a redécouvert un peu l’eau chaude par moment, mais aussi deux bugs au minimum. C’est aussi formateur de devoir manipuler des gros fichiers textes pour extraire les infos voulues (toi aussi amuses toi en ligne de commande avec tous nos amis grep / sed / awk / … et aussi un peu de redis et de SQL des fois). Et cela a permis d’avoir un journal de plus.