Se connecter au serveur par ssh sur le compte charlie, ou maverik:
$ ssh charlie@<IP>
Une demande de code google-authenticator est alors affichée. en y répondant de manière volontairement erronée, on obtient des logs caractéristiques sur le serveur ssh.
Voici un exemple de logs présents dans le fichier /var/log/auth.log. On y voit l’authentification de l’utilisateur charlie, qui échoue dans l’authentification à l’étape de renseignement du code google authenticator:
May 5 21:37:10 debian sshd(pam_google_authenticator)[2183]: Invalid verification code for charlie
May 5 21:37:10 debian sshd[2181]: debug3: mm_request_receive entering
May 5 21:37:10 debian sshd[2181]: debug3: monitor_read: checking request 106
May 5 21:37:10 debian sshd[2181]: debug3: mm_answer_pam_query
May 5 21:37:10 debian sshd[2181]: debug3: PAM: sshpam_query entering
May 5 21:37:10 debian sshd[2181]: debug3: ssh_msg_recv entering
May 5 21:37:10 debian sshd[2183]: debug3: ssh_msg_send: type 7
May 5 21:37:10 debian sshd[2181]: debug3: PAM: Authentication failure
May 5 21:37:10 debian sshd[2181]: error: PAM: Authentication failure for charlie from 192.168.2.222
May 5 21:37:10 debian sshd[2181]: debug3: mm_request_send entering: type 107
May 5 21:37:10 debian sshd[2181]: debug3: mm_sshpam_query: pam_query returned -1 [preauth]
May 5 21:37:10 debian sshd[2181]: debug2: auth2_challenge_start: devices <empty> [preauth]
May 5 21:37:10 debian sshd[2181]: debug3: mm_sshpam_free_ctx [preauth]
May 5 21:37:10 debian sshd[2181]: debug3: mm_request_send entering: type 110 [preauth]
May 5 21:37:10 debian sshd[2181]: debug3: mm_sshpam_free_ctx: waiting for MONITOR_ANS_PAM_FREE_CTX [preauth]
May 5 21:37:10 debian sshd[2181]: debug3: mm_request_receive_expect entering: type 111 [preauth]
May 5 21:37:10 debian sshd[2181]: debug3: mm_request_receive entering [preauth]
May 5 21:37:10 debian sshd[2181]: debug3: mm_request_receive entering
May 5 21:37:10 debian sshd[2181]: debug3: monitor_read: checking request 110
May 5 21:37:10 debian sshd[2181]: debug3: mm_answer_pam_free_ctx
May 5 21:37:10 debian sshd[2181]: debug3: PAM: sshpam_free_ctx entering
May 5 21:37:10 debian sshd[2181]: debug3: PAM: sshpam_thread_cleanup entering
May 5 21:37:10 debian sshd[2181]: debug3: mm_request_send entering: type 111
May 5 21:37:10 debian sshd[2181]: debug2: monitor_read: 110 used once, disabling now
May 5 21:37:10 debian sshd[2181]: Failed keyboard-interactive/pam for charlie from 192.168.2.222 port 38354 ssh2
Les logs contiennent du niveau debug3. C’est le niveau de logs le plus complet, mais celui-ci n’est pas optimal en situation réelle. En effet, la quantité de logs est beaucoup trop importante, elle provoque donc des problèmes de gestion mémoire, mais également des problème dans l’analyse humaine des logs. Les logs importants peuvent ainsi être noyés dans la masse de logs debug3. De plus, ce niveau de logs peut-être considéré comme intrusif pour les utilisateurs du service ssh car il répertorie toutes les interactions du service. En pratique, on préfèrera un niveau “verbose” au maximum.
On remarque sur la première ligne que la vérification de code google-authenticator a échoué:
May 5 21:37:10 debian sshd(pam_google_authenticator)[2183]: Invalid verification code for charlie
L’erreur remonte ensuite jusqu’au module PAM:
May 5 21:37:10 debian sshd[2181]: error: PAM: Authentication failure for charlie from 192.168.2.222
Puis est enfin récupérée par le service sshd:
May 5 21:37:10 debian sshd[2181]: Failed keyboard-interactive/pam for charlie from 192.168.2.222 port 38354 ssh2
Cette suite de logs est caractéristique d’une erreur d’authentification.