Standardise logging of failed authentication attempts in internal SSH (#13962)

Continuing on from #13953 continue to improve and standardise
logging from internal SSH.

Also updates the fail2ban setup

Signed-off-by: Andrew Thornton <art27@cantab.net>

2 files changed, 62 insertions, 8 deletions

diff --git a/docs/content/doc/usage/fail2ban-setup.en-us.md b/docs/content/doc/usage/fail2ban-setup.en-us.md
index 5c5bdb9a28..790d4c020b 100644
--- a/docs/content/doc/usage/fail2ban-setup.en-us.md
+++ b/docs/content/doc/usage/fail2ban-setup.en-us.md
@@ -25,9 +25,27 @@ on a bad authentication from the web or CLI using SSH or HTTP respectively:
 ```log
 2018/04/26 18:15:54 [I] Failed authentication attempt for user from xxx.xxx.xxx.xxx
 ```
+
+```log
+2020/10/15 16:05:09 modules/ssh/ssh.go:143:publicKeyHandler() [W] Failed authentication attempt from xxx.xxx.xxx.xxx
+```
+
+```log
+2020/10/15 16:05:09 modules/ssh/ssh.go:155:publicKeyHandler() [W] Failed authentication attempt from xxx.xxx.xxx.xxx
+```
+
 ```log
-2020/10/15 16:05:09 modules/ssh/ssh.go:188:publicKeyHandler() [E] SearchPublicKeyByContent: public key does not exist [id: 0] Failed authentication attempt from xxx.xxx.xxx.xxx
+2020/10/15 16:05:09 modules/ssh/ssh.go:198:publicKeyHandler() [W] Failed authentication attempt from xxx.xxx.xxx.xxx
 ```
+
+```log
+2020/10/15 16:05:09 modules/ssh/ssh.go:213:publicKeyHandler() [W] Failed authentication attempt from xxx.xxx.xxx.xxx
+```
+
+```log
+2020/10/15 16:05:09 modules/ssh/ssh.go:227:publicKeyHandler() [W] Failed authentication attempt from xxx.xxx.xxx.xxx
+```
+
 ```log
 2020/10/15 16:08:44 ...s/context/context.go:204:HandleText() [E] invalid credentials from xxx.xxx.xxx.xxx
 ```
diff --git a/modules/ssh/ssh.go b/modules/ssh/ssh.go
index e8ed9029ce..4ba52d5653 100644
--- a/modules/ssh/ssh.go
+++ b/modules/ssh/ssh.go
@@ -134,14 +134,25 @@ func sessionHandler(session ssh.Session) {
 }
 
 func publicKeyHandler(ctx ssh.Context, key ssh.PublicKey) bool {
+	if log.IsDebug() { // <- FingerprintSHA256 is kinda expensive so only calculate it if necessary
+		log.Debug("Handle Public Key: Fingerprint: %s from %s", gossh.FingerprintSHA256(key), ctx.RemoteAddr())
+	}
+
 	if ctx.User() != setting.SSH.BuiltinServerUser {
-		log.Warn("Permission Denied: Invalid SSH username %s - must use %s for all git operations via ssh", ctx.User(), setting.SSH.BuiltinServerUser)
+		log.Warn("Invalid SSH username %s - must use %s for all git operations via ssh", ctx.User(), setting.SSH.BuiltinServerUser)
+		log.Warn("Failed authentication attempt from %s", ctx.RemoteAddr())
 		return false
 	}
 
 	// check if we have a certificate
 	if cert, ok := key.(*gossh.Certificate); ok {
+		if log.IsDebug() { // <- FingerprintSHA256 is kinda expensive so only calculate it if necessary
+			log.Debug("Handle Certificate: %s Fingerprint: %s is a certificate", ctx.RemoteAddr(), gossh.FingerprintSHA256(key))
+		}
+
 		if len(setting.SSH.TrustedUserCAKeys) == 0 {
+			log.Warn("Certificate Rejected: No trusted certificate authorities for this server")
+			log.Warn("Failed authentication attempt from %s", ctx.RemoteAddr())
 			return false
 		}
 
@@ -151,7 +162,7 @@ func publicKeyHandler(ctx ssh.Context, key ssh.PublicKey) bool {
 			pkey, err := models.SearchPublicKeyByContentExact(principal)
 			if err != nil {
 				if models.IsErrKeyNotExist(err) {
-					log.Debug("Principal Rejected: Unknown Principal: %s", principal)
+					log.Debug("Principal Rejected: %s Unknown Principal: %s", ctx.RemoteAddr(), principal)
 					continue principalLoop
 				}
 				log.Error("SearchPublicKeyByContentExact: %v", err)
@@ -172,33 +183,58 @@ func publicKeyHandler(ctx ssh.Context, key ssh.PublicKey) bool {
 
 			// check the CA of the cert
 			if !c.IsUserAuthority(cert.SignatureKey) {
-				log.Debug("Principal Rejected: Untrusted Authority Signature Fingerprint %s for Principal: %s", gossh.FingerprintSHA256(cert.SignatureKey), principal)
+				if log.IsDebug() {
+					log.Debug("Principal Rejected: %s Untrusted Authority Signature Fingerprint %s for Principal: %s", ctx.RemoteAddr(), gossh.FingerprintSHA256(cert.SignatureKey), principal)
+				}
 				continue principalLoop
 			}
 
 			// validate the cert for this principal
 			if err := c.CheckCert(principal, cert); err != nil {
-				// User is presenting an invalid cerficate - STOP any further processing
-				log.Error("Permission Denied: Invalid Certificate KeyID %s with Signature Fingerprint %s presented for Principal: %s", cert.KeyId, gossh.FingerprintSHA256(cert.SignatureKey), principal)
+				// User is presenting an invalid certificate - STOP any further processing
+				if log.IsError() {
+					log.Error("Invalid Certificate KeyID %s with Signature Fingerprint %s presented for Principal: %s from %s", cert.KeyId, gossh.FingerprintSHA256(cert.SignatureKey), principal, ctx.RemoteAddr())
+				}
+				log.Warn("Failed authentication attempt from %s", ctx.RemoteAddr())
+
 				return false
 			}
 
+			if log.IsDebug() { // <- FingerprintSHA256 is kinda expensive so only calculate it if necessary
+				log.Debug("Successfully authenticated: %s Certificate Fingerprint: %s Principal: %s", ctx.RemoteAddr(), gossh.FingerprintSHA256(key), principal)
+			}
 			ctx.SetValue(giteaKeyID, pkey.ID)
 
 			return true
 		}
+
+		if log.IsWarn() {
+			log.Warn("From %s Fingerprint: %s is a certificate, but no valid principals found", ctx.RemoteAddr(), gossh.FingerprintSHA256(key))
+			log.Warn("Failed authentication attempt from %s", ctx.RemoteAddr())
+		}
+		return false
+	}
+
+	if log.IsDebug() { // <- FingerprintSHA256 is kinda expensive so only calculate it if necessary
+		log.Debug("Handle Public Key: %s Fingerprint: %s is not a certificate", ctx.RemoteAddr(), gossh.FingerprintSHA256(key))
 	}
 
 	pkey, err := models.SearchPublicKeyByContent(strings.TrimSpace(string(gossh.MarshalAuthorizedKey(key))))
 	if err != nil {
 		if models.IsErrKeyNotExist(err) {
-			log.Warn("Permission Denied: Unknown public key : %s", gossh.FingerprintSHA256(key))
+			if log.IsWarn() {
+				log.Warn("Unknown public key: %s from %s", gossh.FingerprintSHA256(key), ctx.RemoteAddr())
+				log.Warn("Failed authentication attempt from %s", ctx.RemoteAddr())
+			}
 			return false
 		}
-		log.Error("SearchPublicKeyByContent: %v Failed authentication attempt from %s", err, ctx.RemoteAddr())
+		log.Error("SearchPublicKeyByContent: %v", err)
 		return false
 	}
 
+	if log.IsDebug() { // <- FingerprintSHA256 is kinda expensive so only calculate it if necessary
+		log.Debug("Successfully authenticated: %s Public Key Fingerprint: %s", ctx.RemoteAddr(), gossh.FingerprintSHA256(key))
+	}
 	ctx.SetValue(giteaKeyID, pkey.ID)
 
 	return true