Nœuds qui se désynchronisent et usage anormal du CPU

cgeek · 30 September 2017 11:20

Des remontées de @Moul, @elois et @stephane indiquent que les nœuds en version 1.6 manifestent des problèmes de désynchronisation et d’utilisation anormale du CPU (jusqu’à 100%).

Je suis en train d’investiguer, mais n’hésitez pas à le faire vous-mêmes. Je suis très peu disponible ce week-end, je vais faire ce que je peux.

Notez que faire des constats ne suffira pas à corriger le bug : le mieux est de tenter de le reproduire dans un environnement de dev (= cloner Duniter dans sa branche dev, le compiler avec yarn puis utiliser les commandes habituelles pour faire une 1ère synchronisation), et le lancer en mode debug via VSCode, en mettant des points d’arrêts sur les lignes de logs qui vous indiquent un problème.

cgeek · 30 September 2017 11:35

Les 1ers éléments indiquent que c’est le nœud ECTQrRoR qui balance en boucle sa fiche de pair qui provoque le bug. Puis plusieurs bugs en cascade provoquent une boucle sans fin sur cette fiche.

Je regarderai au mieux cet après-midi plus en profondeur, et nous ne pourrons espérer un correctif qu’en fin d’après-midi.

Je ne conseille pas d’action particulière, la blockchain avance tout de même.

cgeek · 30 September 2017 11:43

NB : si le propriétaire du nœud ECTQrRoR se reconnaît, merci de LAISSER son nœud tel quel pour que nous puissions reproduire le bug.

elois · 30 September 2017 15:34

D’après mes log et mes graphes munin le problème lié a la fiche de peer du nœud ECTQrRoR a été observé sur mon noeud g1-monit de vendredi 18h à samedi 3h, puis a repris vers 13h et se poursuit actuellement. C’est donc probablement un nœud diurne dons le problème se reproduit même après redémarrage.

Je précise que le problème ne se produit pas sur mes nœuds en 1.5.x

cgeek · 30 September 2017 16:42

Après analyse du code exécuté, ce que je peux dire :

Il existe un nœud qui envoie sa fiche de pair sous 2 formes différentes :

une avec 1 endpoint WS2P public
une sans aucun endpoint
les 2 fiches portent sur la clé ECTQrRoR

Premier problème

Il y a un bug dans le service PeeringService.ts. D’abord, j’ai introduit en 1.6 la suppression de fiche de pairs de la BDD quand celle-ci ne contenait aucun endpoint. Or, il suffit à l’attaquant (ou au logiciel bugué) de soumettre à nouveau une fiche avec le blockstamp précédent juste ensuite pour recréer l’enregistrement. Puis de renvoyer une fiche vide avec le blockstamp suivant. Puis de supprimer. Puis de récréer. Indéfiniment :

github.com

duniter/duniter/blob/463b86aaf54b8f82253ce45bf73a91caf1a6613e/app/service/PeeringService.ts#L111-L133


      
          if(!found && thePeerDTO.endpoints.length === 0){
            throw 'Peer with zero endpoints that is not already known'
          }
          if(found && thePeerDTO.endpoints.length === 0){
            // This peer is saying "I'm no more joinable"
            // ==> Remove it from the database
            await this.dal.removePeerByPubkey(thePeerDTO.pubkey)
            return thePeerDTO
          }
          else if(found){
            // Already existing peer
            const sp2 = found.block.split('-');
            const previousBlockNumber = parseInt(sp2[0]);
            const interfacesChanged = thePeerDTO.endpointSum() != peerEntityOld.endpointSum()
            const isOutdatedDocument = blockNumber < previousBlockNumber && !eraseIfAlreadyRecorded;
            const isAlreadyKnown = blockNumber == previousBlockNumber && !eraseIfAlreadyRecorded;
            if (isOutdatedDocument){
              const error = _.extend({}, constants.ERRORS.NEWER_PEER_DOCUMENT_AVAILABLE);
              _.extend(error.uerr, { peer: found });
              throw error;

This file has been truncated. show original

La solution débute par le fait de ne pas supprimer les enregistrements de fiches de pair de la BDD. Il faut les conserver, pour avoir trace du dernier blockstamp connu et empêcher cette boucle.

C’est un 1er correctif qui permet ensuite de refuser tout document identique ou avec un blockstamp précédent.

Deuxième problème

Malgré ce correctif, cela n’empêche pas le nœud attaquant/bugué de nous spammer en continu sous WS2P : il nous envoie des documents erronés qui sont refusé certes, mais il continue indéfiniment de le faire.

La solution est similaire à celle utilisée dans BMA : le bannissement. Ainsi, j’ai ajouté une règle dans WS2P qui bannit automatiquement tout nœud qui enverrai 2 fois de suite le même document en erreur, pendant 2 minutes.

La suite

Alors bien sûr, vu que le bug est présent sur tous les nœuds 1.6, il y a de fortes chances que tous les nœuds soient bannis tant qu’il restent dans cette version.

Pire, cette 1.6.6 connaît un autre bug bien connu mais peu gênant : tout bloc ajouté à la blockchain locale est partagé 2 fois de suite avec le même pair. Ça se voit sur Remuniter :

Et donc fatalement, un nœud connecté en WS2P qui aurait ce bug se verrai automatiquement banni par la règle que l’on vient de créer. Ce qui est le cas de tout nœud en version 1.6.0 à 1.6.6.

Ce bug du “double partage” existe depuis la version 1.4 ou 1.5, toutefois il ne nous gêne que dans le cadre de WS2P, donc la 1.6.

Moralité : passer à la 1.6.7.

Cette version est en cours de livraison.

elois · 30 September 2017 17:46

C’est beaucoup mieux je suis a seulement 5% de cpu (hors pow). Toutefois la clé ECTQrRoR ne semble pas être bannie par mon nœud :

2017-09-30T19:37:23+02:00 - warn: Connection to 3AF7bhGQ refused, reason: Peer 3AF7bhGQRt6ymcBZgZTBMoDsEtSwruSarjNG8kDnaueX sending again a wrong document
2017-09-30T19:37:23+02:00 - error: WS2P >>> >>> WS ERROR: REJECTED_PUBKEY_OR_INCORRECT_ASK_SIGNATURE_FROM_REMOTE
2017-09-30T19:37:23+02:00 - warn: Connection to 3AF7bhGQ refused, reason: Peer 3AF7bhGQRt6ymcBZgZTBMoDsEtSwruSarjNG8kDnaueX sending again a wrong document
2017-09-30T19:37:23+02:00 - warn: Connection to 3wdDzBz1 refused, reason: Peer 3wdDzBz18mWupx1UChMnhky2Nut3XVnyn9U7Y662J7yE sending again a wrong document
2017-09-30T19:37:23+02:00 - error: WS2P >>> >>> WS ERROR: REJECTED_PUBKEY_OR_INCORRECT_ASK_SIGNATURE_FROM_REMOTE
2017-09-30T19:37:23+02:00 - info: WS2P D9D2zaJoWYWveii1JRYLVK3J4Z7ZH3QczoKrnQeiM6mx: new incoming connection from 151.80.40.148:54600!
2017-09-30T19:37:23+02:00 - info: WS2P D9D2zaJoWYWveii1JRYLVK3J4Z7ZH3QczoKrnQeiM6mx: new incoming connection from 151.80.40.148:54601!
2017-09-30T19:37:23+02:00 - warn: Connection to 3wdDzBz1 refused, reason: Peer 3wdDzBz18mWupx1UChMnhky2Nut3XVnyn9U7Y662J7yE sending again a wrong document
2017-09-30T19:37:23+02:00 - warn: Connection to 4fHMTFBM refused, reason: Peer 4fHMTFBMo5sTQEc5p1CNWz28S4mnnqdUBmECq1zt4n2m sending again a wrong document
2017-09-30T19:37:23+02:00 - error: WS2P >>> >>> WS ERROR: REJECTED_PUBKEY_OR_INCORRECT_ASK_SIGNATURE_FROM_REMOTE
2017-09-30T19:37:23+02:00 - warn: Connection to 4fHMTFBM refused, reason: Peer 4fHMTFBMo5sTQEc5p1CNWz28S4mnnqdUBmECq1zt4n2m sending again a wrong document
2017-09-30T19:37:23+02:00 - error: WS2P >>> >>> WS ERROR: REJECTED_PUBKEY_OR_INCORRECT_ASK_SIGNATURE_FROM_REMOTE
2017-09-30T19:37:23+02:00 - warn: Connection to 4fHMTFBM refused, reason: Peer 4fHMTFBMo5sTQEc5p1CNWz28S4mnnqdUBmECq1zt4n2m sending again a wrong document
2017-09-30T19:37:23+02:00 - warn: Connection to 4fHMTFBM refused, reason: Peer 4fHMTFBMo5sTQEc5p1CNWz28S4mnnqdUBmECq1zt4n2m sending again a wrong document
2017-09-30T19:37:23+02:00 - info: ⬇ PEER ECTQrRoR
2017-09-30T19:37:23+02:00 - info: ✘ PEER ECTQrRoR
2017-09-30T19:37:23+02:00 - warn:  httpCode=400, ucode=2023, message=Peer document already known
2017-09-30T19:37:23+02:00 - info: ⬇ PEER ECTQrRoR
2017-09-30T19:37:23+02:00 - info: ✘ PEER ECTQrRoR
2017-09-30T19:37:23+02:00 - warn:  httpCode=400, ucode=2023, message=Peer document already known
2017-09-30T19:37:23+02:00 - info: ⬇ PEER ECTQrRoR
2017-09-30T19:37:23+02:00 - info: ✘ PEER ECTQrRoR
2017-09-30T19:37:23+02:00 - warn:  httpCode=400, ucode=2023, message=Peer document already known
2017-09-30T19:37:23+02:00 - info: ⬇ PEER D9D2zaJo
2017-09-30T19:37:23+02:00 - info: ✘ PEER D9D2zaJo
2017-09-30T19:37:23+02:00 - warn:  httpCode=400, ucode=2023, message=Peer document already known
2017-09-30T19:37:23+02:00 - info: ⬇ PEER ECTQrRoR
2017-09-30T19:37:23+02:00 - info: ✘ PEER ECTQrRoR
2017-09-30T19:37:23+02:00 - warn:  httpCode=400, ucode=2023, message=Peer document already known
2017-09-30T19:37:23+02:00 - info: ⬇ PEER ECTQrRoR
2017-09-30T19:37:23+02:00 - info: ✘ PEER ECTQrRoR
2017-09-30T19:37:23+02:00 - warn:  httpCode=400, ucode=2023, message=Peer document already known
2017-09-30T19:37:23+02:00 - info: ⬇ PEER ECTQrRoR
2017-09-30T19:37:23+02:00 - info: ✘ PEER ECTQrRoR
2017-09-30T19:37:23+02:00 - warn:  httpCode=400, ucode=2023, message=Peer document already known
2017-09-30T19:37:24+02:00 - info: ⬇ PEER ECTQrRoR
2017-09-30T19:37:24+02:00 - info: ✘ PEER ECTQrRoR
2017-09-30T19:37:24+02:00 - warn:  httpCode=400, ucode=2023, message=Peer document already known
2017-09-30T19:37:24+02:00 - info: ⬇ PEER ECTQrRoR
2017-09-30T19:37:24+02:00 - info: ✘ PEER ECTQrRoR
2017-09-30T19:37:24+02:00 - warn:  httpCode=400, ucode=2023, message=Peer document already known
2017-09-30T19:37:24+02:00 - info: ⬇ PEER ECTQrRoR
2017-09-30T19:37:24+02:00 - info: ✘ PEER ECTQrRoR
2017-09-30T19:37:24+02:00 - warn:  httpCode=400, ucode=2023, message=Peer document already known
2017-09-30T19:37:24+02:00 - info: ⬇ PEER ECTQrRoR
2017-09-30T19:37:24+02:00 - info: ✘ PEER ECTQrRoR
2017-09-30T19:37:24+02:00 - warn:  httpCode=400, ucode=2023, message=Peer document already known
2017-09-30T19:37:24+02:00 - info: ⬇ PEER ECTQrRoR
2017-09-30T19:37:24+02:00 - info: ✘ PEER ECTQrRoR
2017-09-30T19:37:24+02:00 - warn:  httpCode=400, ucode=2023, message=Peer document already known
2017-09-30T19:37:24+02:00 - info: ⬇ PEER ECTQrRoR
2017-09-30T19:37:24+02:00 - info: ✘ PEER ECTQrRoR
2017-09-30T19:37:24+02:00 - warn:  httpCode=400, ucode=2023, message=Peer document already known
2017-09-30T19:37:24+02:00 - info: ⬇ PEER ECTQrRoR
2017-09-30T19:37:24+02:00 - info: ✘ PEER ECTQrRoR
2017-09-30T19:37:24+02:00 - warn:  httpCode=400, ucode=2023, message=Peer document already known
2017-09-30T19:37:25+02:00 - info: ⬇ PEER ECTQrRoR
2017-09-30T19:37:25+02:00 - info: ✘ PEER ECTQrRoR
2017-09-30T19:37:25+02:00 - warn:  httpCode=400, ucode=2023, message=Peer document already known
2017-09-30T19:37:25+02:00 - info: ⬇ PEER ECTQrRoR
2017-09-30T19:37:25+02:00 - info: ✘ PEER ECTQrRoR
2017-09-30T19:37:25+02:00 - warn:  httpCode=400, ucode=2023, message=Peer document already known
2017-09-30T19:37:25+02:00 - info: ⬇ PEER ECTQrRoR
2017-09-30T19:37:25+02:00 - info: ✘ PEER ECTQrRoR
2017-09-30T19:37:25+02:00 - warn:  httpCode=400, ucode=2023, message=Peer document already known
2017-09-30T19:37:25+02:00 - info: ⬇ PEER ECTQrRoR
2017-09-30T19:37:25+02:00 - info: ✘ PEER ECTQrRoR
2017-09-30T19:37:25+02:00 - warn:  httpCode=400, ucode=2023, message=Peer document already known
2017-09-30T19:37:25+02:00 - info: ⬇ PEER ECTQrRoR
2017-09-30T19:37:25+02:00 - info: ✘ PEER ECTQrRoR
2017-09-30T19:37:25+02:00 - warn:  httpCode=400, ucode=2023, message=Peer document already known
2017-09-30T19:37:25+02:00 - info: ⬇ PEER ECTQrRoR
2017-09-30T19:37:25+02:00 - info: ✘ PEER ECTQrRoR
2017-09-30T19:37:25+02:00 - warn:  httpCode=400, ucode=2023, message=Peer document already known
2017-09-30T19:37:25+02:00 - error: Block already known
2017-09-30T19:37:25+02:00 - error: Block already known
2017-09-30T19:37:25+02:00 - info: WS2P: Could not connect to peer -------- using `WS2P 78.242.14.140 10090: WS2P connection timeout`
2017-09-30T19:37:26+02:00 - info: ⬇ PEER D9D2zaJo
2017-09-30T19:37:26+02:00 - info: ⬇ PEER ECTQrRoR
2017-09-30T19:37:26+02:00 - info: ⬇ PEER ECTQrRoR
2017-09-30T19:37:26+02:00 - info: ⬇ PEER ECTQrRoR
2017-09-30T19:37:26+02:00 - warn:  httpCode=400, ucode=1015, message=Document already under treatment
2017-09-30T19:37:26+02:00 - info: ⬇ PEER ECTQrRoR
2017-09-30T19:37:26+02:00 - warn:  httpCode=400, ucode=1015, message=Document already under treatment
2017-09-30T19:37:26+02:00 - info: ✘ PEER D9D2zaJo
2017-09-30T19:37:26+02:00 - error:  httpCode=400, ucode=2023, message=Peer document already known
2017-09-30T19:37:26+02:00 - info: ⬇ PEER ECTQrRoR
2017-09-30T19:37:26+02:00 - warn:  httpCode=400, ucode=1015, message=Document already under treatment
2017-09-30T19:37:26+02:00 - info: ⬇ PEER ECTQrRoR
2017-09-30T19:37:26+02:00 - warn:  httpCode=400, ucode=1015, message=Document already under treatment
2017-09-30T19:37:26+02:00 - info: ⬇ PEER ECTQrRoR
2017-09-30T19:37:26+02:00 - warn:  httpCode=400, ucode=1015, message=Document already under treatment
2017-09-30T19:37:26+02:00 - info: ✘ PEER ECTQrRoR
2017-09-30T19:37:26+02:00 - warn: Banning connections of 38MEAZN6 for 120s, reason: Peer 38MEAZN68Pz1DTvT3tqgxx4yQP6snJCQhPqEFxbDk4aE sending again a wrong document
2017-09-30T19:37:26+02:00 - warn:  httpCode=400, ucode=2023, message=Peer document already known
2017-09-30T19:37:26+02:00 - info: ⬇ PEER ECTQrRoR
2017-09-30T19:37:26+02:00 - warn:  httpCode=400, ucode=1015, message=Document already under treatment
2017-09-30T19:37:26+02:00 - info: ✘ PEER ECTQrRoR
2017-09-30T19:37:26+02:00 - warn: Banning connections of Hb2TLnB6 for 120s, reason: Peer Hb2TLnB6d3dKiC1VibaUJbZtLhyuHYaDxXNvVd7NqXJe sending again a wrong document
2017-09-30T19:37:26+02:00 - warn:  httpCode=400, ucode=2023, message=Peer document already known

cgeek · 30 September 2017 17:47

Oui c’est ce que je vois aussi, je continue …

elois · 30 September 2017 17:49

De mon coté j’essaye déjà de comprendre ce que tu fais en relisant tes commit, tout ça vas beaucoup trop vite pour moi

cgeek · 30 September 2017 17:56

Pfff … j’ai confondu secondes et millisecondes :

https://github.com/duniter/duniter/blob/07ca679b4b034b79a5f8e7661375ce1d40b4e979/app/modules/ws2p/lib/interface/WS2PServerMessageHandler.ts#L102

Tu peux tester en mettant WS2PConstants.ERROR_RECALL_DURATION_IN_SECONDS * 1000 dans le fichier /opt/duniter/app/modules/ws2p/lib/interface/WS2PServerMessageHandler.js, tu verras que ça fonctionne beaucoup mieux !

Je refais une release … 1.6.8.

cgeek · 1 October 2017 07:24

La 1.6.8 est disponible : Beta-test Duniter 1.6 WS2P

stephane · 1 October 2017 10:19

J’ai un problème avec …/webmin/network/ws2p/info
Il semble, mais j’ai du mal à le mettre en évidence, que le champs connections disparait de temps à autre du json. Cela fait planter mon script python car il ne détecte pas le champ connections

cgeek · 1 October 2017 12:23

Ce champ est toujours renseigné :

https://github.com/duniter/duniter-ui/blob/master/server/controller/webmin.js#L648-L666

stephane · 1 October 2017 13:08

Cependant depuis la dernière mise à jour mon script plante alors qu’avec la version d’avant non.
Je vais donc supprimer la lecture du JSON qui fait planter. Je regarderai plus tard comment contourner le problème, si cela est possible.