sshd.exe eats whole CPU core

[C-Duv]

I have just installed OpenSSH on a Windows 7 Pro 64-bits via Chocolatey openssh package (v0.0.10.0) and Windows process manager shows sshd.exe eating 25% of a 4-core CPU (without any SSH client connected).
I tried setting LogLevel to level DEBUG in the sshd_config but the single log line I have in c:\Program Files\OpenSSH-Win64\Logs\sshd.log is:

11304 11:18:25 501 error: Error retrieving user environment variables. RegOpenKeyExW returned 5

But SSH service works fine: I can connect to it without issue.

[bagajjal]

error code 5 means the "Access denied".

I think the issue is not because of this particular error message because this happens only during the session setup.

Please enable the log level to DEBUG3 and share the sshd.log file.

[bagajjal]

Does it also happen when there are no SSH client connections?

[C-Duv]

Even at DEBUG3 I get nothing in the c:\Program Files\OpenSSH-Win64\Logs\sshd.log (is it really the place I have to look?).
CPU consumption happens the moment I start the service, no matter if there are clients or not.

[bagajjal]

Anyone facing this issue?
Yes its the right place (c:\Program Files\OpenSSH-Win64\Logs\sshd.log).
Not sure what's going wrong because we are not seeing it.
Can you try to install the same version on different machine and see if it still happens?
If yes then please check installing V0.0.9.0, this gives us some information whether it is specific to the latest release or not.

[C-Duv]

I tried the following versions, all have the issue:

• 0.0.10.0
• 0.0.9.20170313
• 0.0.9.20170311
• 0.0.9.0

(v0.0.8.0 does not installs because of DarwinJS/ChocoPackages#26)

I have the same problem on another Windows 7, with the OpenSSH that was packaged with Chocolatey package win32-openssh version 2016.05.30.

But, I tested on a Windows 7 VM that never gets Windows Updates: no issue there (with v0.0.10.0).

[manojampalam]

Since , we are not able to repro this on our side (and there are not logs to give us a clue), we need your help to take this further.

Are you familiar with using VS 2015, if so, please download the express edition, attach to sshd.exe process (symbols can be downloaded from release page) and figure out the busy loop.

[C-Duv]

Not really familiar with it.
I downloaded both symbols and source code (for v0.0.10.0).
I managed to attach to running sshd.exe process and clicked "Break", gave it the location of source file socketio.c (contrib/win32/win32compat/socketio.c on the repo).

VS complains about source file being different than the one used when generating the module, but I get the following stack trace:

sshd.exe!socketio_acceptEx(w32_io * pio) Line 111
sshd.exe!socketio_on_select(w32_io * pio, int rd) Line 908
sshd.exe!w32_io_on_select(w32_io * pio, int rd) Line 177
sshd.exe!w32_select(int fds, w32_fd_set_ * readfds, w32_fd_set_ * writefds, w32_fd_set_ * exceptfds, const timeval * timeout) Line 641
sshd.exe!server_accept_loop(int * sock_in, int * sock_out, int * newsock, int * config_s) Line 1173
sshd.exe!main(int ac, char * * av) Line 1982
sshd.exe!sshd_main(int argc, wchar_t * * wargv) Line 123
sshd.exe!scm_start_service(unsigned long num, wchar_t * * args) Line 145

At sshd.exe!socketio_acceptEx(w32_io * pio) I am in socketio.c at:

/* initiate async acceptEx*/
/* TODO - always return 0, set error in context, accept() will pick it up*/
int
socketio_acceptEx(struct w32_io* pio)
{
	struct acceptEx_context *context;
	debug3("acceptEx - io:%p", pio);
	context = (struct acceptEx_context *)pio->internal.context;
	ResetEvent(pio->read_overlapped.hEvent);

	/* create accepting socket */
	context->accept_socket = socket(AF_UNSPEC, SOCK_STREAM, IPPROTO_TCP);    // THIS IS LINE 111
	if (context->accept_socket == INVALID_SOCKET) {
		errno = errno_from_WSALastError();
		debug("acceptEx - socket() ERROR:%d, io:%p", errno, pio);
		return -1;
	}

	if (TRUE == context->lpfnAcceptEx(pio->sock,
					context->accept_socket,
					context->lpOutputBuf,
					0,
					sizeof(SOCKADDR_STORAGE) + 16,
					sizeof(SOCKADDR_STORAGE) + 16,
					&context->bytes_received,
					&pio->read_overlapped))
	{
		/* we are already connected. Set event so subsequent select will catch */
		SetEvent(pio->read_overlapped.hEvent);
	} else {
		/* if overlapped io is in progress, we are good */
		if (WSAGetLastError() != ERROR_IO_PENDING) {
			errno = errno_from_WSALastError();
			debug("acceptEx - AcceptEx() ERROR:%d, io:%p", errno, pio);
			return -1;
		}
	}

	pio->read_details.pending = TRUE;
	return 0;
}

After a few "Continue" + "Break" I also breaked into:

sshd.exe!wait_for_any_event(void * * events, int num_events, unsigned long milli_seconds) Line 291
sshd.exe!w32_select(int fds, w32_fd_set_ * readfds, w32_fd_set_ * writefds, w32_fd_set_ * exceptfds, const timeval * timeout) Line 667
sshd.exe!server_accept_loop(int * sock_in, int * sock_out, int * newsock, int * config_s) Line 1173
sshd.exe!main(int ac, char * * av) Line 1982
sshd.exe!sshd_main(int argc, wchar_t * * wargv) Line 123
sshd.exe!scm_start_service(unsigned long num, wchar_t * * args) Line 145

also:

sshd.exe!wait_for_any_event(void * * events, int num_events, unsigned long milli_seconds) Line 291
sshd.exe!w32_select(int fds, w32_fd_set_ * readfds, w32_fd_set_ * writefds, w32_fd_set_ * exceptfds, const timeval * timeout) Line 667
sshd.exe!server_accept_loop(int * sock_in, int * sock_out, int * newsock, int * config_s) Line 1173
sshd.exe!main(int ac, char * * av) Line 1982
sshd.exe!sshd_main(int argc, wchar_t * * wargv) Line 123
sshd.exe!scm_start_service(unsigned long num, wchar_t * * args) Line 145

At sshd.exe!wait_for_any_event(void * * events, int num_events, unsigned long milli_seconds) I am in signal.c at:

// [...]
	} else {
		DWORD ret = SleepEx(milli_seconds, TRUE);    // THIS IS LINE 291
		if (ret == WAIT_IO_COMPLETION) {
			/* APC processed due to IO or signal*/
		} else if (ret == 0) {
			/* timed out */
			return 0;
		} else { /* some other error */
			errno = EOTHER;
			debug("ERROR: unxpected SleepEx error: %d", ret);
			return -1;
		}
	}

and:

sshd.exe!socketio_accept(w32_io * pio, sockaddr * addr, int * addrlen) Line 719
sshd.exe!w32_accept(int fd, sockaddr * addr, int * addrlen) Line 239
sshd.exe!server_accept_loop(int * sock_in, int * sock_out, int * newsock, int * config_s) Line 1204
sshd.exe!main(int ac, char * * av) Line 1982
sshd.exe!sshd_main(int argc, wchar_t * * wargv) Line 123
sshd.exe!scm_start_service(unsigned long num, wchar_t * * args) Line 145

At sshd.exe!socketio_accept(w32_io * pio, sockaddr * addr, int * addrlen) I am in socketio.c at:

// [...]
on_error:
	if (context->accept_socket != INVALID_SOCKET) {
		closesocket(context->accept_socket);
		context->accept_socket = INVALID_SOCKET;    // THIS IS LINE 719
	}

	return NULL;
}

I noticed that when a SSH client is getting prompted for the password another sshd.exe process is spawned (as a child of the core-eater one): this one does not seems to abuse CPU (it's at 0%).

[manojampalam]

Based on your stack, looks like you are hitting the same issue as #606. Let's continue further conversation on that thread. I'm actively looking into this issue and we should hopefully fix this for March-End drop.