From 8cb7c19bf4d1ae4133394b881101c09b4574aebe Mon Sep 17 00:00:00 2001 From: zokki Date: Thu, 11 Sep 2025 18:59:24 +0200 Subject: [PATCH] feat(log): better parseable and configurable ssh-logs (#9056) To audit access to our forgejo-instance we currently need to enable debug ssh-logs. It turns out a single log become multiple events in a k8s/container setup. To have our log-collectors properly join these events, we would like to indent them similar to what some stacktraces look like. This PR would change ``` 2025/09/08 07:18:53 ...eb/routing/logger.go:102:func1() [I] Serv Results: IsWiki: %t DeployKeyID: %d KeyID: %d KeyName: %s UserName: %s UserID: %d OwnerName: %s RepoName: %s RepoID: %d ``` to ``` 2025/09/08 07:18:53 ...eb/routing/logger.go:102:func1() [I] Serv Results: IsWiki: %t DeployKeyID: %d KeyID: %d KeyName: %s UserName: %s UserID: %d OwnerName: %s RepoName: %s RepoID: %d ``` Furthermore to standardize user configuration of ssh-logs I have added `LOGGER_SSH_MODE` . It can be configured like router-logger. By doing so we can change the log-LEVEL to debug for ssh without changing other loggers. This would deprecate `ENABLE_SSH_LOG`. ## Checklist The [contributor guide](https://forgejo.org/docs/next/contributor/) contains information that will be helpful to first time contributors. There also are a few [conditions for merging Pull Requests in Forgejo repositories](https://codeberg.org/forgejo/governance/src/branch/main/PullRequestsAgreement.md). You are also welcome to join the [Forgejo development chatroom](https://matrix.to/#/#forgejo-development:matrix.org). ### Documentation - [ ] I created a pull request [to the documentation](https://codeberg.org/forgejo/docs) to explain to Forgejo users how to use this change. - [x] I did not document these changes and I do not expect someone else to do it. ### Release notes - [x] I do not want this change to show in the release notes. - [ ] I want the title to show in the release notes with a link to this pull request. - [ ] I want the content of the `release-notes/.md` to be be used for the release notes instead of the title. ## Release notes - Features - [PR](https://codeberg.org/forgejo/forgejo/pulls/9056): feat(log): better parseable and configurable ssh-logs Reviewed-on: https://codeberg.org/forgejo/forgejo/pulls/9056 Reviewed-by: Lucas Reviewed-by: Gusted Reviewed-by: Earl Warren Co-authored-by: zokki Co-committed-by: zokki --- cmd/serv.go | 13 +++-- custom/conf/app.example.ini | 5 +- modules/log/stack.go | 4 +- modules/private/hook.go | 7 ++- modules/setting/log.go | 15 +++-- modules/setting/log_test.go | 25 ++++++++ modules/ssh/init.go | 2 + modules/ssh/ssh.go | 92 +++++++++++++++--------------- modules/ssh/ssh_graceful.go | 4 +- routers/private/serv.go | 34 +++++------ routers/private/ssh_log.go | 13 +---- tests/integration/git_push_test.go | 8 ++- tests/mysql.ini.tmpl | 2 +- tests/pgsql.ini.tmpl | 2 +- tests/sqlite.ini.tmpl | 2 +- 15 files changed, 132 insertions(+), 96 deletions(-) diff --git a/cmd/serv.go b/cmd/serv.go index b0571a276c..0e0551d297 100644 --- a/cmd/serv.go +++ b/cmd/serv.go @@ -88,6 +88,14 @@ var ( alphaDashDotPattern = regexp.MustCompile(`[^\w-\.]`) ) +func sshLog(ctx context.Context, level log.Level, message string) error { + if testing.Testing() || setting.InternalToken == "" { + return nil + } + + return private.SSHLog(ctx, level, message) +} + // fail prints message to stdout, it's mainly used for git serv and git hook commands. // The output will be passed to git client and shown to user. func fail(ctx context.Context, userMessage, logMsgFmt string, args ...any) error { @@ -112,10 +120,7 @@ func fail(ctx context.Context, userMessage, logMsgFmt string, args ...any) error logMsg = userMessage + ". " + logMsg } } - // Don't send an log if this is done in a test and no InternalToken is set. - if !testing.Testing() || setting.InternalToken != "" { - _ = private.SSHLog(ctx, true, logMsg) - } + _ = sshLog(ctx, log.ERROR, logMsg) } return cli.Exit("", 1) } diff --git a/custom/conf/app.example.ini b/custom/conf/app.example.ini index 267696872d..6c8c85b87c 100644 --- a/custom/conf/app.example.ini +++ b/custom/conf/app.example.ini @@ -598,10 +598,7 @@ LEVEL = Info ;LOGGER_ACCESS_MODE= ;LOGGER_ROUTER_MODE=, ;LOGGER_XORM_MODE=, -;; -;; Collect SSH logs (Creates log from ssh git request) -;; -;ENABLE_SSH_LOG = false +;LOGGER_SSH_MODE= ;; SSH logs from ssh git request ;; ;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;; ;; diff --git a/modules/log/stack.go b/modules/log/stack.go index 9b22e92867..a8d26d1fc3 100644 --- a/modules/log/stack.go +++ b/modules/log/stack.go @@ -32,7 +32,7 @@ func Stack(skip int) string { } // Print equivalent of debug.Stack() - _, _ = fmt.Fprintf(buf, "%s:%d (0x%x)\n", filename, lineNumber, programCounter) + _, _ = fmt.Fprintf(buf, "\t%s:%d (0x%x)\n", filename, lineNumber, programCounter) // Now try to print the offending line if filename != lastFilename { data, err := os.ReadFile(filename) @@ -44,7 +44,7 @@ func Stack(skip int) string { lines = bytes.Split(data, []byte{'\n'}) lastFilename = filename } - _, _ = fmt.Fprintf(buf, "\t%s: %s\n", functionName(programCounter), source(lines, lineNumber)) + _, _ = fmt.Fprintf(buf, "\t\t%s: %s\n", functionName(programCounter), source(lines, lineNumber)) } return buf.String() } diff --git a/modules/private/hook.go b/modules/private/hook.go index 2d64c1dec9..89d44119ea 100644 --- a/modules/private/hook.go +++ b/modules/private/hook.go @@ -11,6 +11,7 @@ import ( "forgejo.org/modules/git" "forgejo.org/modules/git/pushoptions" + "forgejo.org/modules/log" "forgejo.org/modules/repository" "forgejo.org/modules/setting" ) @@ -46,7 +47,7 @@ func (o *HookOptions) GetGitPushOptions() pushoptions.Interface { // SSHLogOption ssh log options type SSHLogOption struct { - IsError bool + Level log.Level Message string } @@ -121,9 +122,9 @@ func SetDefaultBranch(ctx context.Context, ownerName, repoName, branch string) R } // SSHLog sends ssh error log response -func SSHLog(ctx context.Context, isErr bool, msg string) error { +func SSHLog(ctx context.Context, level log.Level, msg string) error { reqURL := setting.LocalURL + "api/internal/ssh/log" - req := newInternalRequest(ctx, reqURL, "POST", &SSHLogOption{IsError: isErr, Message: msg}) + req := newInternalRequest(ctx, reqURL, "POST", &SSHLogOption{Level: level, Message: msg}) _, extra := requestJSONResp(req, &ResponseText{}) return extra.Error } diff --git a/modules/setting/log.go b/modules/setting/log.go index a23662239e..ecc591fd35 100644 --- a/modules/setting/log.go +++ b/modules/setting/log.go @@ -23,8 +23,6 @@ type LogGlobalConfig struct { StacktraceLogLevel log.Level BufferLen int - EnableSSHLog bool - AccessLogTemplate string RequestIDHeaders []string } @@ -47,8 +45,6 @@ func loadLogGlobalFrom(rootCfg ConfigProvider) { } Log.RootPath = util.FilePathJoinAbs(Log.RootPath) - Log.EnableSSHLog = sec.Key("ENABLE_SSH_LOG").MustBool(false) - Log.AccessLogTemplate = sec.Key("ACCESS_LOG_TEMPLATE").MustString(accessLogTemplateDefault) Log.RequestIDHeaders = sec.Key("REQUEST_ID_HEADERS").Strings(",") } @@ -124,6 +120,16 @@ func prepareLoggerConfig(rootCfg ConfigProvider) { if hasNoValue { sec.Key("LOGGER_XORM_MODE").SetValue(",") // use default logger } + + // Priority: `LOGGER_SSH_MODE` -> `ENABLE_SSH_LOG` + deprecatedSettingWarning(rootCfg, "log", "ENABLE_SSH_LOG", "log", "LOGGER_SSH_MODE") + if !sec.HasKey("LOGGER_SSH_MODE") && sec.HasKey("ENABLE_SSH_LOG") { + if sec.Key("ENABLE_SSH_LOG").MustBool() { + sec.Key("LOGGER_SSH_MODE").SetValue(",") // use default logger + } else { + sec.Key("LOGGER_SSH_MODE").SetValue("") // disable ssh logger + } + } } func LogPrepareFilenameForWriter(fileName, defaultFileName string) string { @@ -245,6 +251,7 @@ func initManagedLoggers(manager *log.LoggerManager, cfg ConfigProvider) { initLoggerByName(manager, cfg, "access") initLoggerByName(manager, cfg, "router") initLoggerByName(manager, cfg, "xorm") + initLoggerByName(manager, cfg, "ssh") } func initLoggerByName(manager *log.LoggerManager, rootCfg ConfigProvider, loggerName string) { diff --git a/modules/setting/log_test.go b/modules/setting/log_test.go index a37c8f07a9..1e523d50d7 100644 --- a/modules/setting/log_test.go +++ b/modules/setting/log_test.go @@ -585,6 +585,31 @@ logger.xorm.MODE = console `[log] LOGGER_XORM_MODE = file logger.xorm.MODE = console +`, + "file", + }, + }) + }) + + t.Run("ssh", func(t *testing.T) { + runCases(t, "LOGGER_SSH_MODE", Cases{ + { + "uses default value for ssh logger", + "", + "", + }, + { + "deprecated config can enable logger", + `[log] +ENABLE_SSH_LOG = true +`, + ",", + }, + { + "check priority", + `[log] +LOGGER_SSH_MODE = file +ENABLE_SSH_LOG = true `, "file", }, diff --git a/modules/ssh/init.go b/modules/ssh/init.go index 1ccd95b18b..09b96a7d8a 100644 --- a/modules/ssh/init.go +++ b/modules/ssh/init.go @@ -15,6 +15,8 @@ import ( "forgejo.org/modules/setting" ) +var logger = log.GetManager().GetLogger("ssh") + func Init() error { if setting.SSH.Disabled { builtinUnused() diff --git a/modules/ssh/ssh.go b/modules/ssh/ssh.go index 19cac0b603..502fcd070f 100644 --- a/modules/ssh/ssh.go +++ b/modules/ssh/ssh.go @@ -61,10 +61,10 @@ func sessionHandler(session ssh.Session) { command := session.RawCommand() - log.Trace("SSH: Payload: %v", command) + logger.Trace("SSH: Payload: %v", command) args := []string{"--config=" + setting.CustomConf, "serv", "key-" + keyID} - log.Trace("SSH: Arguments: %v", args) + logger.Trace("SSH: Arguments: %v", args) ctx, cancel := context.WithCancel(session.Context()) defer cancel() @@ -87,21 +87,21 @@ func sessionHandler(session ssh.Session) { stdout, err := cmd.StdoutPipe() if err != nil { - log.Error("SSH: StdoutPipe: %v", err) + logger.Error("SSH: StdoutPipe: %v", err) return } defer stdout.Close() stderr, err := cmd.StderrPipe() if err != nil { - log.Error("SSH: StderrPipe: %v", err) + logger.Error("SSH: StderrPipe: %v", err) return } defer stderr.Close() stdin, err := cmd.StdinPipe() if err != nil { - log.Error("SSH: StdinPipe: %v", err) + logger.Error("SSH: StdinPipe: %v", err) return } defer stdin.Close() @@ -112,14 +112,14 @@ func sessionHandler(session ssh.Session) { wg.Add(2) if err = cmd.Start(); err != nil { - log.Error("SSH: Start: %v", err) + logger.Error("SSH: Start: %v", err) return } go func() { defer stdin.Close() if _, err := io.Copy(stdin, session); err != nil { - log.Error("Failed to write session to stdin. %s", err) + logger.Error("Failed to write session to stdin. %s", err) } }() @@ -127,7 +127,7 @@ func sessionHandler(session ssh.Session) { defer wg.Done() defer stdout.Close() if _, err := io.Copy(session, stdout); err != nil { - log.Error("Failed to write stdout to session. %s", err) + logger.Error("Failed to write stdout to session. %s", err) } }() @@ -135,7 +135,7 @@ func sessionHandler(session ssh.Session) { defer wg.Done() defer stderr.Close() if _, err := io.Copy(session.Stderr(), stderr); err != nil { - log.Error("Failed to write stderr to session. %s", err) + logger.Error("Failed to write stderr to session. %s", err) } }() @@ -149,41 +149,41 @@ func sessionHandler(session ssh.Session) { // Cannot use errors.Is here because ExitError doesn't implement Is // Thus errors.Is will do equality test NOT type comparison if _, ok := err.(*exec.ExitError); !ok { - log.Error("SSH: Wait: %v", err) + logger.Error("SSH: Wait: %v", err) } } if err := session.Exit(getExitStatusFromError(err)); err != nil && !errors.Is(err, io.EOF) { - log.Error("Session failed to exit. %s", err) + logger.Error("Session failed to exit. %s", err) } } 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 logger.LevelEnabled(log.DEBUG) { // <- FingerprintSHA256 is kinda expensive so only calculate it if necessary + logger.Debug("Handle Public Key: Fingerprint: %s from %s", gossh.FingerprintSHA256(key), ctx.RemoteAddr()) } if 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()) + logger.Warn("Invalid SSH username %s - must use %s for all git operations via ssh", ctx.User(), setting.SSH.BuiltinServerUser) + logger.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 logger.LevelEnabled(log.DEBUG) { // <- FingerprintSHA256 is kinda expensive so only calculate it if necessary + logger.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()) + logger.Warn("Certificate Rejected: No trusted certificate authorities for this server") + logger.Warn("Failed authentication attempt from %s", ctx.RemoteAddr()) return false } if cert.CertType != gossh.UserCert { - log.Warn("Certificate Rejected: Not a user certificate") - log.Warn("Failed authentication attempt from %s", ctx.RemoteAddr()) + logger.Warn("Certificate Rejected: Not a user certificate") + logger.Warn("Failed authentication attempt from %s", ctx.RemoteAddr()) return false } @@ -193,10 +193,10 @@ func publicKeyHandler(ctx ssh.Context, key ssh.PublicKey) bool { pkey, err := asymkey_model.SearchPublicKeyByContentExact(ctx, principal) if err != nil { if asymkey_model.IsErrKeyNotExist(err) { - log.Debug("Principal Rejected: %s Unknown Principal: %s", ctx.RemoteAddr(), principal) + logger.Debug("Principal Rejected: %s Unknown Principal: %s", ctx.RemoteAddr(), principal) continue principalLoop } - log.Error("SearchPublicKeyByContentExact: %v", err) + logger.Error("SearchPublicKeyByContentExact: %v", err) return false } @@ -215,8 +215,8 @@ func publicKeyHandler(ctx ssh.Context, key ssh.PublicKey) bool { // check the CA of the cert if !c.IsUserAuthority(cert.SignatureKey) { - if log.IsDebug() { - log.Debug("Principal Rejected: %s Untrusted Authority Signature Fingerprint %s for Principal: %s", ctx.RemoteAddr(), gossh.FingerprintSHA256(cert.SignatureKey), principal) + if logger.LevelEnabled(log.DEBUG) { + logger.Debug("Principal Rejected: %s Untrusted Authority Signature Fingerprint %s for Principal: %s", ctx.RemoteAddr(), gossh.FingerprintSHA256(cert.SignatureKey), principal) } continue principalLoop } @@ -224,14 +224,14 @@ func publicKeyHandler(ctx ssh.Context, key ssh.PublicKey) bool { // validate the cert for this principal if err := c.CheckCert(principal, cert); err != nil { // User is presenting an invalid certificate - STOP any further processing - 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()) + logger.Error("Invalid Certificate KeyID %s with Signature Fingerprint %s presented for Principal: %s from %s", cert.KeyId, gossh.FingerprintSHA256(cert.SignatureKey), principal, ctx.RemoteAddr()) + logger.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) + if logger.LevelEnabled(log.DEBUG) { // <- FingerprintSHA256 is kinda expensive so only calculate it if necessary + logger.Debug("Successfully authenticated: %s Certificate Fingerprint: %s Principal: %s", ctx.RemoteAddr(), gossh.FingerprintSHA256(key), principal) } if ctx.Permissions().Extensions == nil { ctx.Permissions().Extensions = map[string]string{} @@ -241,28 +241,28 @@ func publicKeyHandler(ctx ssh.Context, key ssh.PublicKey) bool { return true } - 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()) + logger.Warn("From %s Fingerprint: %s is a certificate, but no valid principals found", ctx.RemoteAddr(), gossh.FingerprintSHA256(key)) + logger.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)) + if logger.LevelEnabled(log.DEBUG) { // <- FingerprintSHA256 is kinda expensive so only calculate it if necessary + logger.Debug("Handle Public Key: %s Fingerprint: %s is not a certificate", ctx.RemoteAddr(), gossh.FingerprintSHA256(key)) } pkey, err := asymkey_model.SearchPublicKeyByContent(ctx, strings.TrimSpace(string(gossh.MarshalAuthorizedKey(key)))) if err != nil { if asymkey_model.IsErrKeyNotExist(err) { - log.Warn("Unknown public key: %s from %s", gossh.FingerprintSHA256(key), ctx.RemoteAddr()) - log.Warn("Failed authentication attempt from %s", ctx.RemoteAddr()) + logger.Warn("Unknown public key: %s from %s", gossh.FingerprintSHA256(key), ctx.RemoteAddr()) + logger.Warn("Failed authentication attempt from %s", ctx.RemoteAddr()) return false } - log.Error("SearchPublicKeyByContent: %v", err) + logger.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)) + if logger.LevelEnabled(log.DEBUG) { // <- FingerprintSHA256 is kinda expensive so only calculate it if necessary + logger.Debug("Successfully authenticated: %s Public Key Fingerprint: %s", ctx.RemoteAddr(), gossh.FingerprintSHA256(key)) } if ctx.Permissions().Extensions == nil { ctx.Permissions().Extensions = map[string]string{} @@ -276,9 +276,9 @@ func publicKeyHandler(ctx ssh.Context, key ssh.PublicKey) bool { // - this mainly exists to give a nice function name in logging func sshConnectionFailed(conn net.Conn, err error) { // Log the underlying error with a specific message - log.Warn("Failed connection from %s with error: %v", conn.RemoteAddr(), err) + logger.Warn("Failed connection from %s with error: %v", conn.RemoteAddr(), err) // Log with the standard failed authentication from message for simpler fail2ban configuration - log.Warn("Failed authentication attempt from %s", conn.RemoteAddr()) + logger.Warn("Failed authentication attempt from %s", conn.RemoteAddr()) } // Listen starts a SSH server listens on given port. @@ -317,22 +317,22 @@ func Listen(host string, port int, ciphers, keyExchanges, macs []string) { filePath := filepath.Dir(setting.SSH.ServerHostKeys[0]) if err := os.MkdirAll(filePath, os.ModePerm); err != nil { - log.Error("Failed to create dir %s: %v", filePath, err) + logger.Error("Failed to create dir %s: %v", filePath, err) } err := GenKeyPair(setting.SSH.ServerHostKeys[0]) if err != nil { log.Fatal("Failed to generate private key: %v", err) } - log.Trace("New private key is generated: %s", setting.SSH.ServerHostKeys[0]) + logger.Trace("New private key is generated: %s", setting.SSH.ServerHostKeys[0]) keys = append(keys, setting.SSH.ServerHostKeys[0]) } for _, key := range keys { - log.Info("Adding SSH host key: %s", key) + logger.Info("Adding SSH host key: %s", key) err := srv.SetOption(ssh.HostKeyFile(key)) if err != nil { - log.Error("Failed to set Host Key. %s", err) + logger.Error("Failed to set Host Key. %s", err) } } @@ -359,7 +359,7 @@ func GenKeyPair(keyPath string) error { } defer func() { if err = f.Close(); err != nil { - log.Error("Close: %v", err) + logger.Error("Close: %v", err) } }() @@ -380,7 +380,7 @@ func GenKeyPair(keyPath string) error { } defer func() { if err = p.Close(); err != nil { - log.Error("Close: %v", err) + logger.Error("Close: %v", err) } }() _, err = p.Write(public) diff --git a/modules/ssh/ssh_graceful.go b/modules/ssh/ssh_graceful.go index 825313ab1c..98ddc18ae7 100644 --- a/modules/ssh/ssh_graceful.go +++ b/modules/ssh/ssh_graceful.go @@ -20,12 +20,12 @@ func listen(server *ssh.Server) { if err != nil { select { case <-graceful.GetManager().IsShutdown(): - log.Critical("Failed to start SSH server: %v", err) + logger.Critical("Failed to start SSH server: %v", err) default: log.Fatal("Failed to start SSH server: %v", err) } } - log.Info("SSH Listener: %s Closed", server.Addr) + logger.Info("SSH Listener: %s Closed", server.Addr) } // builtinUnused informs our cleanup routine that we will not be using a ssh port diff --git a/routers/private/serv.go b/routers/private/serv.go index 7f08d4ca34..7c4a5b8bb7 100644 --- a/routers/private/serv.go +++ b/routers/private/serv.go @@ -23,6 +23,8 @@ import ( wiki_service "forgejo.org/services/wiki" ) +var sshLogger = log.GetManager().GetLogger("ssh") + func checkTwoFactor(ctx *context.PrivateContext, user *user_model.User) { if !user.MustHaveTwoFactor() { return @@ -30,7 +32,7 @@ func checkTwoFactor(ctx *context.PrivateContext, user *user_model.User) { hasTwoFactor, err := auth.HasTwoFactorByUID(ctx, user.ID) if err != nil { - log.Error("Error getting 2fa: %s", err) + sshLogger.Error("Error getting 2fa: %s", err) ctx.JSON(http.StatusInternalServerError, private.Response{ Err: fmt.Sprintf("Error getting 2fa: %s", err), }) @@ -62,7 +64,7 @@ func ServNoCommand(ctx *context.PrivateContext) { }) return } - log.Error("Unable to get public key: %d Error: %v", keyID, err) + sshLogger.Error("Unable to get public key: %d Error: %v", keyID, err) ctx.JSON(http.StatusInternalServerError, private.Response{ Err: err.Error(), }) @@ -79,7 +81,7 @@ func ServNoCommand(ctx *context.PrivateContext) { }) return } - log.Error("Unable to get owner with id: %d for public key: %d Error: %v", key.OwnerID, keyID, err) + sshLogger.Error("Unable to get owner with id: %d for public key: %d Error: %v", key.OwnerID, keyID, err) ctx.JSON(http.StatusInternalServerError, private.Response{ Err: err.Error(), }) @@ -138,13 +140,13 @@ func ServCommand(ctx *context.PrivateContext) { if err != nil { if user_model.IsErrUserNotExist(err) { // User is fetching/cloning a non-existent repository - log.Warn("Failed authentication attempt (cannot find repository: %s/%s) from %s", results.OwnerName, results.RepoName, ctx.RemoteAddr()) + sshLogger.Warn("Failed authentication attempt (cannot find repository: %s/%s) from %s", results.OwnerName, results.RepoName, ctx.RemoteAddr()) ctx.JSON(http.StatusNotFound, private.Response{ UserMsg: fmt.Sprintf("Cannot find repository: %s/%s", results.OwnerName, results.RepoName), }) return } - log.Error("Unable to get repository owner: %s/%s Error: %v", results.OwnerName, results.RepoName, err) + sshLogger.Error("Unable to get repository owner: %s/%s Error: %v", results.OwnerName, results.RepoName, err) ctx.JSON(http.StatusForbidden, private.Response{ UserMsg: fmt.Sprintf("Unable to get repository owner: %s/%s %v", results.OwnerName, results.RepoName, err), }) @@ -166,7 +168,7 @@ func ServCommand(ctx *context.PrivateContext) { for _, verb := range ctx.FormStrings("verb") { if verb == "git-upload-pack" { // User is fetching/cloning a non-existent repository - log.Warn("Failed authentication attempt (cannot find repository: %s/%s) from %s", results.OwnerName, results.RepoName, ctx.RemoteAddr()) + sshLogger.Warn("Failed authentication attempt (cannot find repository: %s/%s) from %s", results.OwnerName, results.RepoName, ctx.RemoteAddr()) ctx.JSON(http.StatusNotFound, private.Response{ UserMsg: fmt.Sprintf("Cannot find repository: %s/%s", results.OwnerName, results.RepoName), }) @@ -174,7 +176,7 @@ func ServCommand(ctx *context.PrivateContext) { } } } else { - log.Error("Unable to get repository: %s/%s Error: %v", results.OwnerName, results.RepoName, err) + sshLogger.Error("Unable to get repository: %s/%s Error: %v", results.OwnerName, results.RepoName, err) ctx.JSON(http.StatusInternalServerError, private.Response{ Err: fmt.Sprintf("Unable to get repository: %s/%s %v", results.OwnerName, results.RepoName, err), }) @@ -219,7 +221,7 @@ func ServCommand(ctx *context.PrivateContext) { }) return } - log.Error("Unable to get public key: %d Error: %v", keyID, err) + sshLogger.Error("Unable to get public key: %d Error: %v", keyID, err) ctx.JSON(http.StatusInternalServerError, private.Response{ Err: fmt.Sprintf("Unable to get key: %d Error: %v", keyID, err), }) @@ -252,7 +254,7 @@ func ServCommand(ctx *context.PrivateContext) { }) return } - log.Error("Unable to get deploy for public (deploy) key: %d in %-v Error: %v", key.ID, repo, err) + sshLogger.Error("Unable to get deploy for public (deploy) key: %d in %-v Error: %v", key.ID, repo, err) ctx.JSON(http.StatusInternalServerError, private.Response{ Err: fmt.Sprintf("Unable to get Deploy Key for Public Key: %d:%s in %s/%s.", key.ID, key.Name, results.OwnerName, results.RepoName), }) @@ -280,7 +282,7 @@ func ServCommand(ctx *context.PrivateContext) { }) return } - log.Error("Unable to get owner: %d for public key: %d:%s Error: %v", key.OwnerID, key.ID, key.Name, err) + sshLogger.Error("Unable to get owner: %d for public key: %d:%s Error: %v", key.OwnerID, key.ID, key.Name, err) ctx.JSON(http.StatusInternalServerError, private.Response{ Err: fmt.Sprintf("Unable to get Owner: %d for Deploy Key: %d:%s in %s/%s.", key.OwnerID, key.ID, key.Name, ownerName, repoName), }) @@ -341,7 +343,7 @@ func ServCommand(ctx *context.PrivateContext) { perm, err := access_model.GetUserRepoPermission(ctx, repo, user) if err != nil { - log.Error("Unable to get permissions for %-v with key %d in %-v Error: %v", user, key.ID, repo, err) + sshLogger.Error("Unable to get permissions for %-v with key %d in %-v Error: %v", user, key.ID, repo, err) ctx.JSON(http.StatusInternalServerError, private.Response{ Err: fmt.Sprintf("Unable to get permissions for user %d:%s with key %d in %s/%s Error: %v", user.ID, user.Name, key.ID, results.OwnerName, results.RepoName, err), }) @@ -351,7 +353,7 @@ func ServCommand(ctx *context.PrivateContext) { userMode := perm.UnitAccessMode(unitType) if userMode < mode { - log.Warn("Failed authentication attempt for %s with key %s (not authorized to %s %s/%s) from %s", user.Name, key.Name, modeString, ownerName, repoName, ctx.RemoteAddr()) + sshLogger.Warn("Failed authentication attempt for %s with key %s (not authorized to %s %s/%s) from %s", user.Name, key.Name, modeString, ownerName, repoName, ctx.RemoteAddr()) ctx.JSON(http.StatusUnauthorized, private.Response{ UserMsg: fmt.Sprintf("User: %d:%s with Key: %d:%s is not authorized to %s %s/%s.", user.ID, user.Name, key.ID, key.Name, modeString, ownerName, repoName), }) @@ -385,7 +387,7 @@ func ServCommand(ctx *context.PrivateContext) { repo, err = repo_service.PushCreateRepo(ctx, user, owner, results.RepoName) if err != nil { - log.Error("pushCreateRepo: %v", err) + sshLogger.Error("pushCreateRepo: %v", err) ctx.JSON(http.StatusNotFound, private.Response{ UserMsg: fmt.Sprintf("Cannot find repository: %s/%s", results.OwnerName, results.RepoName), }) @@ -403,7 +405,7 @@ func ServCommand(ctx *context.PrivateContext) { }) return } - log.Error("Failed to get the wiki unit in %-v Error: %v", repo, err) + sshLogger.Error("Failed to get the wiki unit in %-v Error: %v", repo, err) ctx.JSON(http.StatusInternalServerError, private.Response{ Err: fmt.Sprintf("Failed to get the wiki unit in %s/%s Error: %v", ownerName, repoName, err), }) @@ -412,14 +414,14 @@ func ServCommand(ctx *context.PrivateContext) { // Finally if we're trying to touch the wiki we should init it if err = wiki_service.InitWiki(ctx, repo); err != nil { - log.Error("Failed to initialize the wiki in %-v Error: %v", repo, err) + sshLogger.Error("Failed to initialize the wiki in %-v Error: %v", repo, err) ctx.JSON(http.StatusInternalServerError, private.Response{ Err: fmt.Sprintf("Failed to initialize the wiki in %s/%s Error: %v", ownerName, repoName, err), }) return } } - log.Debug("Serv Results:\nIsWiki: %t\nDeployKeyID: %d\nKeyID: %d\tKeyName: %s\nUserName: %s\nUserID: %d\nOwnerName: %s\nRepoName: %s\nRepoID: %d", + sshLogger.Info("Serv Results:\n\tIsWiki: %t\n\tDeployKeyID: %d\n\tKeyID: %d\tKeyName: %s\n\tUserName: %s\n\tUserID: %d\n\tOwnerName: %s\n\tRepoName: %s\n\tRepoID: %d", results.IsWiki, results.DeployKeyID, results.KeyID, diff --git a/routers/private/ssh_log.go b/routers/private/ssh_log.go index f6974967c0..1b51c5e7ad 100644 --- a/routers/private/ssh_log.go +++ b/routers/private/ssh_log.go @@ -8,26 +8,19 @@ import ( "forgejo.org/modules/log" "forgejo.org/modules/private" - "forgejo.org/modules/setting" "forgejo.org/modules/web" "forgejo.org/services/context" ) // SSHLog hook to response ssh log func SSHLog(ctx *context.PrivateContext) { - if !setting.Log.EnableSSHLog { + logger := log.GetManager().GetLogger("ssh") + if !logger.IsEnabled() { ctx.Status(http.StatusOK) return } opts := web.GetForm(ctx).(*private.SSHLogOption) - - if opts.IsError { - log.Error("ssh: %v", opts.Message) - ctx.Status(http.StatusOK) - return - } - - log.Debug("ssh: %v", opts.Message) + logger.Log(0, opts.Level, "ssh: %v", opts.Message) ctx.Status(http.StatusOK) } diff --git a/tests/integration/git_push_test.go b/tests/integration/git_push_test.go index 22dd127a4c..977385ff6a 100644 --- a/tests/integration/git_push_test.go +++ b/tests/integration/git_push_test.go @@ -275,7 +275,10 @@ func testOptionsGitPush(t *testing.T, u *url.URL) { t.Run("Collaborator with write access fails to change private & template via push options", func(t *testing.T) { logChecker, cleanup := test.NewLogChecker(log.DEFAULT, log.TRACE) - logChecker.Filter("permission denied for changing repo settings").StopMark("Git push options validation") + logChecker.StopMark("Git push options validation") + defer cleanup() + sshLogChecker, cleanup := test.NewLogChecker("ssh", log.ERROR) + sshLogChecker.Filter("permission denied for changing repo settings") defer cleanup() branchName := "branch4" doGitCreateBranch(gitPath, branchName)(t) @@ -284,7 +287,8 @@ func testOptionsGitPush(t *testing.T, u *url.URL) { require.NoError(t, err) require.False(t, repo.IsPrivate) require.False(t, repo.IsTemplate) - logFiltered, logStopped := logChecker.Check(5 * time.Second) + _, logStopped := logChecker.Check(5 * time.Second) + logFiltered, _ := sshLogChecker.Check(5 * time.Second) assert.True(t, logStopped) assert.True(t, logFiltered[0]) }) diff --git a/tests/mysql.ini.tmpl b/tests/mysql.ini.tmpl index 674884cea5..055cc091c5 100644 --- a/tests/mysql.ini.tmpl +++ b/tests/mysql.ini.tmpl @@ -76,8 +76,8 @@ PROVIDER_CONFIG = tests/{{TEST_TYPE}}/gitea-{{TEST_TYPE}}-mysql/data/sessions [log] MODE = {{TEST_LOGGER}} ROOT_PATH = {{REPO_TEST_DIR}}mysql-log -ENABLE_SSH_LOG = true LOGGER_XORM_MODE = file +LOGGER_SSH_MODE = , [log.test] LEVEL = Info diff --git a/tests/pgsql.ini.tmpl b/tests/pgsql.ini.tmpl index 4af44c3205..0293817c6e 100644 --- a/tests/pgsql.ini.tmpl +++ b/tests/pgsql.ini.tmpl @@ -81,8 +81,8 @@ PROVIDER_CONFIG = tests/{{TEST_TYPE}}/gitea-{{TEST_TYPE}}-pgsql/data/sessions [log] MODE = {{TEST_LOGGER}} ROOT_PATH = {{REPO_TEST_DIR}}pgsql-log -ENABLE_SSH_LOG = true LOGGER_XORM_MODE = file +LOGGER_SSH_MODE = , [log.test] LEVEL = Info diff --git a/tests/sqlite.ini.tmpl b/tests/sqlite.ini.tmpl index b3baa314a2..6a08bce8ea 100644 --- a/tests/sqlite.ini.tmpl +++ b/tests/sqlite.ini.tmpl @@ -78,8 +78,8 @@ PROVIDER_CONFIG = tests/{{TEST_TYPE}}/gitea-{{TEST_TYPE}}-sqlite/data/sessions [log] MODE = {{TEST_LOGGER}} ROOT_PATH = {{REPO_TEST_DIR}}sqlite-log -ENABLE_SSH_LOG = true LOGGER_XORM_MODE = file +LOGGER_SSH_MODE = , [log.test] LEVEL = Info