Continuous SSH "Session Failed To Exit" Spam In Log

[Deadmano]

Description

Every minute I get the following in my logs. Is this an issue that needs to be looked into? I am using the internal Gitea SSH server.

2022/07/25 07:10:20 modules/ssh/ssh.go:145:sessionHandler() SSH: Wait: exit status 1
2022/07/25 07:10:20 modules/ssh/ssh.go:149:sessionHandler() Session failed to exit. EOF
2022/07/25 07:11:20 modules/ssh/ssh.go:145:sessionHandler() SSH: Wait: exit status 1
2022/07/25 07:11:20 modules/ssh/ssh.go:149:sessionHandler() Session failed to exit. EOF
2022/07/25 07:12:20 modules/ssh/ssh.go:145:sessionHandler() SSH: Wait: exit status 1
2022/07/25 07:12:20 modules/ssh/ssh.go:149:sessionHandler() Session failed to exit. EOF
2022/07/25 07:13:20 modules/ssh/ssh.go:145:sessionHandler() SSH: Wait: exit status 1
2022/07/25 07:13:20 modules/ssh/ssh.go:149:sessionHandler() Session failed to exit. EOF
2022/07/25 07:14:20 modules/ssh/ssh.go:145:sessionHandler() SSH: Wait: exit status 1
2022/07/25 07:14:20 modules/ssh/ssh.go:149:sessionHandler() Session failed to exit. EOF

Gitea Version

1.17.0

Can you reproduce the bug on the Gitea demo site?

No

Log Gist

No response

Screenshots

No response

Git Version

2.37.1

Operating System

Windows 10

How are you running Gitea?

From the latest Windows x64 binary directly from the Gitea downloads.

Database

No response

[Deadmano]

Tagging @zeripath as I believe they worked on the loggers before?

[zeripath]

hmm...

2022/07/25 07:14:20 modules/ssh/ssh.go:149:sessionHandler() Session failed to exit. EOF

these lines seem pointless as there is no point logging EOFs so those should be dropped.

What is a problem however are:

2022/07/25 07:14:20 modules/ssh/ssh.go:145:sessionHandler() SSH: Wait: exit status 1

The logging here isn't being very helpful but it appears that these SSH commands are always exiting with status 1 - be that pushes or pulls.

The command being called here is equivalent to:

env SSH_ORIGINAL_COMMAND=$SSH_ORIGINAL_COMMAND SKIP_MINWINSVC=1 $PATH_TO_GITEA/gitea serv  key-$KEY_ID --config=$GITEA_CONFIG_FILE 

Now this is always exiting with a status 1. The stderr is being sent to whatever is sshing in.

So the question is... What is happening on the other end? Why are they always exiting with status 1?

It's probable that we should not ever log anything here, it's not helpful for the server as all of the error information is being sent to the client.

[Deadmano]

These happen regardless of if there is any activity on the server. No push/pulls happening, and like clockwork every minute it logs this. I'm happy to dig further if it helps, but mainly I'd like to avoid seeing these "errors" as they very quickly clutter up actual meaningful errors that I can action.

[zeripath]

Someone or something is initiating SSH requests to the server with a valid public key that is matching one of the public keys that Gitea knows about.

That is the only way that this can get logged.

The command gitea serv is then failing for whatever reason. I suspect permissions.

If you want to investigate further you need to provide us with debug logging, as the issue template requests.

See https://docs.gitea.io/en-us/logging-configuration/#debugging-problems

Clearly the current logging is pointless and unhelpful. There are many many ways in which gitea serv can exit with exit status 1 so the attached PR strives to remove it.

[Deadmano]

Thanks for the explanation! I'll try the debug logging and hopefully that sheds some light and report back!

[Deadmano]

So after some testing, @zeripath, I've found that it is GitKraken that is causing the update check on the repository. What I find strange is with the handling of the key, which says it is not a certificate and then authenticates after? Seems to be able to handle what it needs, but then fails at the exit?

This was the entirety of the log, and it just repeats. Does any of it help? And is there anything I can do to stop the spam?

2022/07/29 01:31:39 modules/ssh/ssh.go:155:publicKeyHandler() [D] Handle Public Key: Fingerprint: SHA256:[KEY] from IP:51063
2022/07/29 01:31:39 modules/ssh/ssh.go:237:publicKeyHandler() [D] Handle Public Key: IP:51063 Fingerprint: SHA256:[KEY] is not a certificate
2022/07/29 01:31:39 modules/ssh/ssh.go:254:publicKeyHandler() [D] Successfully authenticated: IP:51063 Public Key Fingerprint: SHA256:[KEY]
2022/07/29 01:31:39 modules/ssh/ssh.go:69:sessionHandler() [T] SSH: Payload: git-upload-pack 'Deadmano/test.git'
2022/07/29 01:31:39 modules/ssh/ssh.go:72:sessionHandler() [T] SSH: Arguments: [serv key-7 --config=X:\gitea\custom\conf\app.ini]
2022/07/29 01:31:42 models/repo/repo.go:314:LoadUnits() [T] repo.Units, ID=23, Types: [TypeCode, TypeIssues, TypePullRequests, TypeReleases, TypeProjects]
2022/07/29 01:31:42 ...s/repo_permission.go:157:func1() [T] Permission Loaded for 16:Deadmano in 23:deadmano/test:
	Permissions: perm_model.AccessMode: 4:owner, 5 Units, 0 UnitsMode(s): [ 
	Units[0]: ID: 76 RepoID: 23 Type: 1:TypeCode Config: {}
	Units[1]: ID: 78 RepoID: 23 Type: 2:TypeIssues Config: {"EnableTimetracker":true,"AllowOnlyContributorsToTrackTime":true,"EnableDependencies":true}
	Units[2]: ID: 79 RepoID: 23 Type: 3:TypePullRequests Config: {"IgnoreWhitespaceConflicts":false,"AllowMerge":true,"AllowRebase":true,"AllowRebaseMerge":true,"AllowSquash":true,"AllowManualMerge":false,"AutodetectManualMerge":false,"AllowRebaseUpdate":true,"DefaultDeleteBranchAfterMerge":false,"DefaultMergeStyle":"rebase"}
	Units[3]: ID: 77 RepoID: 23 Type: 4:TypeReleases Config: {}
	Units[4]: ID: 80 RepoID: 23 Type: 8:TypeProjects Config: {} ]
2022/07/29 01:31:42 ...ters/private/serv.go:412:ServCommand() [D] Serv Results:
	IsWiki: false
	DeployKeyID: 0
	KeyID: 7
	KeyName: deadmano@test.com
	UserName: Deadmano
	UserID: 16
	OwnerName: deadmano
	RepoName: test
	RepoID: 23
2022/07/29 01:31:42 modules/ssh/ssh.go:145:sessionHandler() [E] SSH: Wait: exit status 1
2022/07/29 01:31:42 modules/ssh/ssh.go:149:sessionHandler() [E] Session failed to exit. EOF

[zeripath]

Really we'd need to see what git kraken is actually getting across its stderr/stdout.

There's a PR which will be merged very soon which will stop these messages from being logged so that will stop the spam.